niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #333
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestCaseHackSuffix7=== PAUSE TestCaseHackSuffix8=== RUN TestFilterOversizedClosures9=== PAUSE TestFilterOversizedClosures10=== RUN TestUploadMultipart_PartsInParallel11=== PAUSE TestUploadMultipart_PartsInParallel12=== RUN TestPartSizeForNAR13=== PAUSE TestPartSizeForNAR14=== RUN TestUploadMultipart_SupersededByPeer15=== PAUSE TestUploadMultipart_SupersededByPeer16=== RUN TestDumpPathCaseHackMatchesNix17--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestShellSplit96=== CONT TestSetClientTLSErrors97=== CONT TestScriptTokenEmptyCommand98=== CONT TestFileTokenReadsAndCaches99=== CONT TestScriptTokenScriptFails100=== CONT TestScriptTokenBadJSON101=== CONT TestScriptTokenEmptyToken102=== CONT TestScriptTokenCachesUntilRefresh103=== CONT TestScriptTokenNoExpiryRerunsEveryCall104=== CONT TestFileTokenEmpty105=== CONT TestStaticToken106--- PASS: TestShellSplit (0.00s)107--- PASS: TestScriptTokenEmptyCommand (0.00s)108--- PASS: TestFileTokenReadsAndCaches (0.00s)109--- PASS: TestStaticToken (0.00s)110=== CONT TestFileTokenMissing111=== CONT TestStreamPushRequestLine112=== RUN TestSetClientTLSErrors/missing_cert_file113=== PAUSE TestSetClientTLSErrors/missing_cert_file114=== RUN TestSetClientTLSErrors/missing_key_file115=== PAUSE TestSetClientTLSErrors/missing_key_file116=== RUN TestSetClientTLSErrors/missing_ca_file117=== PAUSE TestSetClientTLSErrors/missing_ca_file118=== RUN TestSetClientTLSErrors/invalid_ca_file119=== PAUSE TestSetClientTLSErrors/invalid_ca_file120--- PASS: TestScriptTokenScriptFails (0.00s)121=== CONT TestSetClientTLSDoesNotMutateDefaultTransport122=== CONT TestSetClientTLS123--- PASS: TestFileTokenEmpty (0.00s)124=== CONT TestClientSignaturesByStorePath125--- PASS: TestClientSignaturesByStorePath (0.00s)126=== CONT TestStreamPushReportsSignatures127--- PASS: TestFileTokenMissing (0.00s)1282026/10/01 10:11:40 ERROR Upload failed error=boom count=11292026/10/01 10:11:40 ERROR Upload failed error=boom count=1130=== CONT TestEncodeNixBase32WithRealHash131--- PASS: TestStreamPushReportsSignatures (0.00s)132=== CONT TestDoWithRetry_BodyReplayedViaGetBody133--- PASS: TestEncodeNixBase32WithRealHash (0.00s)134=== CONT TestResolveStorePath135--- PASS: TestDoServerRequestAttachesToken (0.00s)136=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1372026/10/01 10:11:40 WARN Rate limiter enabled after throttle name=server-test rate=51382026/10/01 10:11:40 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:587771392026/10/01 10:11:40 WARN Rate limiter enabled after throttle name=server-test rate=51402026/10/01 10:11:40 WARN Rate limiter backed off name=server-test rate=51412026/10/01 10:11:40 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:58777142--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)143=== CONT TestRateLimiterFeedback144=== RUN TestRateLimiterFeedback/429_enables_limiter145=== PAUSE TestRateLimiterFeedback/429_enables_limiter146=== RUN TestRateLimiterFeedback/503_enables_limiter147=== PAUSE TestRateLimiterFeedback/503_enables_limiter148=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter149=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter150=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter151=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter152=== CONT TestPathInfoCACompatibility153=== RUN TestPathInfoCACompatibility/null_ca_field154=== PAUSE TestPathInfoCACompatibility/null_ca_field155=== RUN TestPathInfoCACompatibility/old_string_format_-_text156=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text157=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive158=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive159=== RUN TestPathInfoCACompatibility/new_structured_format_-_text160=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text161=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method162=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method163=== CONT TestParsePathInfoJSONMultiplePaths164=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths165=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths166=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths167=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths168=== CONT TestParsePathInfoJSON169=== RUN TestParsePathInfoJSON/Nix_format170=== RUN TestSetClientTLS/rejects_connection_without_client_cert171=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert172=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA173=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA174=== RUN TestSetClientTLS/preserves_debug_logging_transport175=== PAUSE TestSetClientTLS/preserves_debug_logging_transport176--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)177--- PASS: TestResolveStorePath (0.00s)178=== CONT TestConvertHashToNix32179=== RUN TestConvertHashToNix32/SRI_format_to_Nix32180=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32181=== RUN TestConvertHashToNix32/already_Nix32_format182=== PAUSE TestConvertHashToNix32/already_Nix32_format183=== RUN TestConvertHashToNix32/invalid_format184=== PAUSE TestConvertHashToNix32/invalid_format185=== CONT TestPathInfoHashCompatibility186=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)187=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)188=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon189=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon190=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI191=== CONT TestStreamPushBatchesUnderLoad192=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI193=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512194=== CONT TestGetStorePathHash195=== RUN TestGetStorePathHash/valid_store_path196=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512197=== PAUSE TestParsePathInfoJSON/Nix_format198=== RUN TestParsePathInfoJSON/Lix_format199=== PAUSE TestParsePathInfoJSON/Lix_format200=== PAUSE TestGetStorePathHash/valid_store_path201=== RUN TestGetStorePathHash/basename_without_hyphen_should_error202=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error203=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error204=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error205=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error206=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error207=== CONT TestStreamPushGivesUpOnDeadServer208=== RUN TestParsePathInfoJSON/empty_input209=== PAUSE TestParsePathInfoJSON/empty_input210=== RUN TestParsePathInfoJSON/whitespace_only211=== CONT TestStreamPushIsolatesFailures212=== PAUSE TestParsePathInfoJSON/whitespace_only213=== RUN TestParsePathInfoJSON/invalid_JSON214=== PAUSE TestParsePathInfoJSON/invalid_JSON215=== CONT TestStreamPushReportsEveryPath2162026/10/01 10:11:40 ERROR Upload failed error="connection refused" count=202172026/10/01 10:11:40 ERROR Server seems unavailable, giving up on batch untried=172182026/10/01 10:11:40 ERROR Upload failed error="bad path" count=3219--- PASS: TestStreamPushReportsEveryPath (0.00s)220=== CONT TestShellSplitErrors221--- PASS: TestShellSplitErrors (0.00s)222--- PASS: TestStreamPushIsolatesFailures (0.00s)223=== CONT TestUploadMultipart_SupersededByPeer224--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)225=== RUN TestUploadMultipart_SupersededByPeer/exists226=== CONT TestEncodeNixBase32227=== RUN TestEncodeNixBase32/test_string_hash228=== PAUSE TestUploadMultipart_SupersededByPeer/exists229=== PAUSE TestEncodeNixBase32/test_string_hash230=== RUN TestEncodeNixBase32/empty_input231=== PAUSE TestEncodeNixBase32/empty_input232=== CONT TestDumpPathWriterError233=== CONT TestDumpPathSingleFile234=== RUN TestUploadMultipart_SupersededByPeer/missing235=== PAUSE TestUploadMultipart_SupersededByPeer/missing236=== CONT TestDumpPathMatchesNix237--- PASS: TestScriptTokenBadJSON (0.01s)238=== CONT TestFilterOversizedClosures239=== RUN TestFilterOversizedClosures/no_limit_keeps_everything240=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything241=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped242=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped243=== RUN TestFilterOversizedClosures/all_closures_skipped244=== PAUSE TestFilterOversizedClosures/all_closures_skipped245=== CONT TestPartSizeForNAR246=== RUN TestPartSizeForNAR/zero_stays_at_minimum247=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum248=== RUN TestPartSizeForNAR/small_stays_at_minimum249=== PAUSE TestPartSizeForNAR/small_stays_at_minimum250=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum251=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum252=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts253=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts254=== RUN TestPartSizeForNAR/1_TiB255=== PAUSE TestPartSizeForNAR/1_TiB256=== RUN TestPartSizeForNAR/5_TiB_S3_max_object257=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object258=== RUN TestPartSizeForNAR/capped_at_5_GiB259=== PAUSE TestPartSizeForNAR/capped_at_5_GiB260=== CONT TestUploadMultipart_PartsInParallel261--- PASS: TestScriptTokenEmptyToken (0.01s)262=== CONT TestCaseHackSuffix263--- PASS: TestStreamPushRequestLine (0.02s)264=== CONT TestRegisterUploadedObjectReusesConnections265--- PASS: TestDumpPathWriterError (0.03s)266=== CONT TestSetClientTLSErrors/missing_cert_file267=== CONT TestSetClientTLSErrors/missing_ca_file268=== CONT TestSetClientTLSErrors/invalid_ca_file269=== CONT TestSetClientTLSErrors/missing_key_file270--- PASS: TestSetClientTLSErrors (0.00s)271 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)272 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)273 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)274 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)275=== CONT TestRateLimiterFeedback/429_enables_limiter2762026/10/01 10:11:40 WARN Rate limiter enabled after throttle name=server-test rate=52772026/10/01 10:11:40 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:588522782026/10/01 10:11:40 WARN Rate limiter backed off name=server-test rate=5279=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter280=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter281--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)282=== CONT TestRateLimiterFeedback/503_enables_limiter283=== CONT TestPathInfoCACompatibility/null_ca_field284=== CONT TestPathInfoCACompatibility/new_structured_format_-_text285=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method286=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive287=== CONT TestPathInfoCACompatibility/old_string_format_-_text288--- PASS: TestPathInfoCACompatibility (0.00s)289 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)290 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)291 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)292 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)293 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)294=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths295=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths296--- PASS: TestParsePa2026/10/01 10:11:40 WARN Rate limiter enabled after throttle name=server-test rate=52972026/10/01 10:11:40 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:588582982026/10/01 10:11:40 WARN Rate limiter backed off name=server-test rate=5299thInfoJSONMultiplePaths (0.00s)300 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)301 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)302=== CONT TestConvertHashToNix32/SRI_format_to_Nix32303=== CONT TestSetClientTLS/preserves_debug_logging_transport304=== CONT TestSetClientTLS/rejects_connection_without_client_cert305--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)306--- PASS: TestRateLimiterFeedback (0.00s)307 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)308 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)309 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)310 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)311=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA312--- PASS: TestRegisterUploadedObjectReusesConnections (0.02s)313=== CONT TestConvertHashToNix32/invalid_format314=== CONT TestConvertHashToNix32/already_Nix32_format315--- PASS: TestConvertHashToNix32 (0.00s)316 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)317 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)318 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)319=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)320=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512321=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon322=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI323--- PASS: TestPathInfoHashCompatibility (0.00s)324 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)325 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)326 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)327 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)328=== CONT TestGetStorePathHash/valid_store_path329=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error330=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error331=== CONT TestGetStorePathHash/basename_without_hyphen_should_error332--- PASS: TestGetStorePathHash (0.00s)333 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)334 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)335 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)336 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)337=== CONT TestParsePathInfoJSON/Nix_format338=== CONT TestParsePathInfoJSON/whitespace_only339=== CONT TestParsePathInfoJSON/invalid_JSON340=== CONT TestParsePathInfoJSON/empty_input341=== CONT TestParsePathInfoJSON/Lix_format342--- PASS: TestParsePathInfoJSON (0.00s)343 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)344 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)345 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)346 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)347 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)348=== CONT TestEncodeNixBase32/test_string_hash349=== CONT TestEncodeNixBase32/empty_input350--- PASS: TestEncodeNixBase32 (0.00s)351 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)352 --- PASS: TestEncodeNixBase32/empty_input (0.00s)353=== CONT TestUploadMultipart_SupersededByPeer/exists354=== CONT TestUploadMultipart_SupersededByPeer/missing355=== CONT TestFilterOversizedClosures/no_limit_keeps_everything356=== CONT TestFilterOversizedClosures/all_closures_skipped3572026/10/01 10:11:40 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=50358=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3592026/10/01 10:11:40 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=2000360--- PASS: TestFilterOversizedClosures (0.00s)361 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)362 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)363 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)364=== CONT TestPartSizeForNAR/zero_stays_at_minimum365=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts366=== CONT TestPartSizeForNAR/small_stays_at_minimum367=== CONT TestPartSizeForNAR/capped_at_5_GiB368=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum369=== CONT TestPartSizeForNAR/5_TiB_S3_max_object370=== CONT TestPartSizeForNAR/1_TiB371--- PASS: TestPartSizeForNAR (0.00s)372 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)373 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)374 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)375 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)376 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)377 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)378 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)379--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)380 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)381 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)3822026/10/01 10:11:40 http: TLS handshake error from 127.0.0.1:58860: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.00s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)385 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)386 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)387--- PASS: TestDumpPathSingleFile (0.05s)388--- PASS: TestCaseHackSuffix (0.05s)389--- PASS: TestDumpPathMatchesNix (0.07s)390--- PASS: TestStreamPushBatchesUnderLoad (0.10s)391--- PASS: TestUploadMultipart_PartsInParallel (0.61s)392--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld10".396This user must also own the server process.397398The database cluster will be initialized with locale "C".399The default database encoding has accordingly been set to "SQL_ASCII".400The default text search configuration will be set to "english".401402Data page checksums are enabled.403404creating directory /nix/var/nix/builds/nix-12646-3956915670/postgres400631832/data ... ok405creating subdirectories ... ok406selecting dynamic shared memory implementation ... posix407selecting default "max_connections" ... 100408selecting default "shared_buffers" ... 128MB409selecting default time zone ... UTC410creating configuration files ... ok411running bootstrap script ... ok412performing post-bootstrap initialization ... ok413syncing data to disk ... ok414415initdb: warning: enabling "trust" authentication for local connections416initdb: 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.417418Success. You can now start the database server using:419420 pg_ctl -D /nix/var/nix/builds/nix-12646-3956915670/postgres400631832/data -l logfile start421422/nix/var/nix/builds/nix-12646-3956915670/postgres400631832:5432 - no response4232026-10-01 10:11:42.192 UTC [12697] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 10:11:42.192 UTC [12697] LOG: listening on Unix socket "/nix/var/nix/builds/nix-12646-3956915670/postgres400631832/.s.PGSQL.5432"4252026-10-01 10:11:42.194 UTC [12704] LOG: database system was shut down at 2026-10-01 10:11:42 UTC4262026-10-01 10:11:42.195 UTC [12697] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-12646-3956915670/postgres400631832:5432 - accepting connections428{"timestamp":"2026-10-01T10:11:42.411047Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"837ac344-97da-4e6d-b5b6-3f8b2aa2298e","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(7)"}429{"timestamp":"2026-10-01T10:11:42.513456Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"b3449b0e-952f-42e0-bf5d-23b47420af2f","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(5)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock468=== RUN TestResolveDBConnectionString469=== PAUSE TestResolveDBConnectionString470=== RUN TestLeadElectsOneAndHandsOver471=== PAUSE TestLeadElectsOneAndHandsOver472=== RUN TestLeadIncumbentWinsAfterRestart4732026-10-01 10:11:42.683 UTC [12734] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 10:11:42.683 UTC [12734] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 10:11:42 OK 20241026095416_initial_model.sql (3.14ms)4762026/10/01 10:11:42 OK 20251210153512_drop_unused_gin_index.sql (441.33µs)4772026/10/01 10:11:42 OK 20251218171726_add_pins.sql (844.42µs)4782026/10/01 10:11:42 OK 20260628120000_add_object_size_and_stats.sql (817.79µs)4792026/10/01 10:11:42 OK 20260905000000_add_claims.sql (890.08µs)4802026/10/01 10:11:42 OK 20260920000000_drop_claims.sql (562µs)4812026/10/01 10:11:42 OK 20260923120000_add_pushes.sql (394.67µs)4822026/10/01 10:11:42 goose: successfully migrated database to version: 202609231200004832026/10/01 10:11:42 OK 1_commit_pending_closure.sql (805.04µs)4842026/10/01 10:11:42 OK 2_object_stats_trigger.sql (210.71µs)4852026/10/01 10:11:42 OK 3_commit_push.sql (209.46µs)4862026/10/01 10:11:42 goose: up to current file version: 34872026/10/01 10:11:42 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 10:11:43 INFO lead: released remote=192.0.2.1:12344892026/10/01 10:11:43 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 10:11:43 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (0.78s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 10:11:43.486 UTC [12738] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 10:11:43.486 UTC [12738] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 10:11:43 OK 20241026095416_initial_model.sql (3.65ms)4982026/10/01 10:11:43 OK 20251210153512_drop_unused_gin_index.sql (402.5µs)4992026/10/01 10:11:43 OK 20251218171726_add_pins.sql (830.88µs)5002026/10/01 10:11:43 OK 20260628120000_add_object_size_and_stats.sql (860.88µs)5012026/10/01 10:11:43 OK 20260905000000_add_claims.sql (1.1ms)5022026/10/01 10:11:43 OK 20260920000000_drop_claims.sql (611.96µs)5032026/10/01 10:11:43 OK 20260923120000_add_pushes.sql (504.33µs)5042026/10/01 10:11:43 goose: successfully migrated database to version: 202609231200005052026/10/01 10:11:43 OK 1_commit_pending_closure.sql (933µs)5062026/10/01 10:11:43 OK 2_object_stats_trigger.sql (222.71µs)5072026/10/01 10:11:43 OK 3_commit_push.sql (180.75µs)5082026/10/01 10:11:43 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.15s)510=== RUN TestGCBugBareHashReferences511=== PAUSE TestGCBugBareHashReferences512=== RUN TestGCMetrics513=== PAUSE TestGCMetrics514=== RUN TestPushDedupSurvivesConcurrentGC515=== PAUSE TestPushDedupSurvivesConcurrentGC516=== RUN TestDeduplicatedObjectsRecordedAsPending517=== PAUSE TestDeduplicatedObjectsRecordedAsPending518=== RUN TestGCSweepSkipsPendingObjects519=== PAUSE TestGCSweepSkipsPendingObjects520=== RUN TestTombstonedObjectOfferedWithoutWaiting521=== PAUSE TestTombstonedObjectOfferedWithoutWaiting522=== RUN TestGCSweepDeliversEachKeyOnce523=== PAUSE TestGCSweepDeliversEachKeyOnce524=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== RUN TestForceGCDuringPushOffersSweptObject527=== PAUSE TestForceGCDuringPushOffersSweptObject528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestSweepRechecksPendingAfterLocking537=== PAUSE TestSweepRechecksPendingAfterLocking538=== RUN TestPushWaitsForSweepHoldingRow539=== PAUSE TestPushWaitsForSweepHoldingRow540=== RUN TestCommitRacingPendingCleanupKeepsObjects541=== PAUSE TestCommitRacingPendingCleanupKeepsObjects542=== RUN TestGCEndsOnShutdown543=== PAUSE TestGCEndsOnShutdown544=== RUN TestGCTaskStore_StartNew545=== PAUSE TestGCTaskStore_StartNew546=== RUN TestGCTaskStore_DeduplicateSameParams547=== PAUSE TestGCTaskStore_DeduplicateSameParams548=== RUN TestGCTaskStore_ConflictDifferentParams549=== PAUSE TestGCTaskStore_ConflictDifferentParams550=== RUN TestGCTaskStore_GetEmpty551=== PAUSE TestGCTaskStore_GetEmpty552=== RUN TestGCTaskStore_GetReturnsLatest553=== PAUSE TestGCTaskStore_GetReturnsLatest554=== RUN TestGCTaskStore_CompletedAllowsNewTask555=== PAUSE TestGCTaskStore_CompletedAllowsNewTask556=== RUN TestGCTaskStore_PhaseUpdates557=== PAUSE TestGCTaskStore_PhaseUpdates558=== RUN TestGCTaskStore_Fail559=== PAUSE TestGCTaskStore_Fail560=== RUN TestGracefulShutdownDrainsInflight561=== PAUSE TestGracefulShutdownDrainsInflight562=== RUN TestService_healthCheckHandler563=== PAUSE TestService_healthCheckHandler564=== RUN TestService_readinessHandler565=== PAUSE TestService_readinessHandler566=== RUN TestGenerateLandingPage567=== PAUSE TestGenerateLandingPage568=== RUN TestCacheConfigHandlerMaxNarSize569=== PAUSE TestCacheConfigHandlerMaxNarSize570=== RUN TestCreatePendingClosureRejectsOversizedNAR571=== PAUSE TestCreatePendingClosureRejectsOversizedNAR572=== RUN TestNARDeduplicationMetadataUploadBug573=== PAUSE TestNARDeduplicationMetadataUploadBug574=== RUN TestMetricsInventory575=== PAUSE TestMetricsInventory576=== RUN TestService_NativeMTLS577=== PAUSE TestService_NativeMTLS578=== RUN TestServerTLSConfig579=== PAUSE TestServerTLSConfig580=== RUN TestMultipartCleanup581=== PAUSE TestMultipartCleanup582=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded584=== RUN TestPendingCleanupUsesOneCutoff585=== PAUSE TestPendingCleanupUsesOneCutoff586=== RUN TestObjectStatsTrigger587=== PAUSE TestObjectStatsTrigger588=== RUN TestOrphanedObjectsGC589=== PAUSE TestOrphanedObjectsGC590=== RUN TestOrphanedObjectsGCStressTest591=== PAUSE TestOrphanedObjectsGCStressTest592=== RUN TestCreatePin_ReservedPins593=== PAUSE TestCreatePin_ReservedPins594=== RUN TestPresentReportsOnlyClosureRoots595=== PAUSE TestPresentReportsOnlyClosureRoots596=== RUN TestPresentNotReportedWhileGCDeletesClosure597=== PAUSE TestPresentNotReportedWhileGCDeletesClosure598=== RUN TestParseSingleRange599=== PAUSE TestParseSingleRange600=== RUN TestProxyHeadersOnlyTrustedOnSocket601=== PAUSE TestProxyHeadersOnlyTrustedOnSocket602=== RUN TestIsValidCachePath603=== PAUSE TestIsValidCachePath604=== RUN TestReadProxyNarinfo605=== PAUSE TestReadProxyNarinfo606=== RUN TestReadProxyNarinfoAlreadyDecompressed607=== PAUSE TestReadProxyNarinfoAlreadyDecompressed608=== RUN TestReadProxyNarStreaming609=== PAUSE TestReadProxyNarStreaming610=== RUN TestReadProxy404611=== PAUSE TestReadProxy404612=== RUN TestReadProxyInvalidPath613=== PAUSE TestReadProxyInvalidPath614=== RUN TestReadProxyHead615=== PAUSE TestReadProxyHead616=== RUN TestReadProxyConditionalGet617=== PAUSE TestReadProxyConditionalGet618=== RUN TestReadProxyRootRedirectsToIndexHTML619=== PAUSE TestReadProxyRootRedirectsToIndexHTML620=== RUN TestReadProxyDisabled621=== PAUSE TestReadProxyDisabled622=== RUN TestReadRedirectNar623=== PAUSE TestReadRedirectNar624=== RUN TestReadRedirectKeepsNarinfoProxied625=== PAUSE TestReadRedirectKeepsNarinfoProxied626=== RUN TestReadProxyRangeRequest627=== PAUSE TestReadProxyRangeRequest628=== RUN TestReadRedirectUsesPublicS3URL629=== PAUSE TestReadRedirectUsesPublicS3URL630=== RUN TestPush_OverlappingRootsStoreOneRowPerKey631=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey632=== RUN TestPush_CompleteCommitsEveryRoot633=== PAUSE TestPush_CompleteCommitsEveryRoot634=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit635=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit636=== RUN TestPush_RejectsBadRequests637=== PAUSE TestPush_RejectsBadRequests638=== RUN TestPush_SignsNarinfosOfItsPendingObjects639=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects640=== RUN TestRedundantMultipartUpload641=== PAUSE TestRedundantMultipartUpload642=== RUN TestCompleteMultipartUpload_ErrorButObjectExists643=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists644=== RUN TestCompletedNarNotReofferedAcrossClosures645=== PAUSE TestCompletedNarNotReofferedAcrossClosures646=== RUN TestPresignedUploadRegisteredBeforeCommit647=== PAUSE TestPresignedUploadRegisteredBeforeCommit648=== RUN TestService_Rustfstest649=== PAUSE TestService_Rustfstest650=== RUN TestParseSize651=== PAUSE TestParseSize652=== RUN TestSkippedUploadsHandler653=== PAUSE TestSkippedUploadsHandler654=== RUN TestSystemdListenerNotActivated655--- PASS: TestSystemdListenerNotActivated (0.00s)656=== RUN TestWatchdogBeatsWhenHealthy657--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)658=== RUN TestWatchdogSkipsWhenUnhealthy6592026/10/01 10:11:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 10:11:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 10:11:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 10:11:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 10:11:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 10:11:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 10:11:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 10:11:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 10:11:43 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"668--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)669=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle670=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle671=== RUN TestProxyWriteTimeout672=== PAUSE TestProxyWriteTimeout673=== RUN TestIsValidUploadKey674=== PAUSE TestIsValidUploadKey675=== RUN TestUploadHandlersRejectInvalidKeys676=== PAUSE TestUploadHandlersRejectInvalidKeys677=== RUN TestUploadHandlersRejectOversizedBody678=== PAUSE TestUploadHandlersRejectOversizedBody679=== RUN TestService_cleanupPendingClosuresHandler680=== PAUSE TestService_cleanupPendingClosuresHandler681=== RUN TestService_createPendingClosureHandler682=== PAUSE TestService_createPendingClosureHandler683=== RUN TestService_verifyS3Integrity684=== PAUSE TestService_verifyS3Integrity685=== RUN TestCompleteMultipartUnregistered686=== PAUSE TestCompleteMultipartUnregistered687=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT688=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT689=== CONT TestPush_OverlappingRootsStoreOneRowPerKey690=== CONT TestCommitRacingPendingCleanupKeepsObjects691=== CONT TestGCTaskStore_StartNew692--- PASS: TestGCTaskStore_StartNew (0.00s)693=== CONT TestReadProxyDisabled694=== CONT TestSkippedUploadsHandler695=== CONT TestService_AuthMiddleware696=== CONT TestReadRedirectUsesPublicS3URL697=== CONT TestReadProxyRangeRequest6982026/10/01 10:11:43 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000699=== CONT TestReadRedirectKeepsNarinfoProxied700=== CONT TestReadRedirectNar701=== CONT TestGCEndsOnShutdown702--- PASS: TestSkippedUploadsHandler (0.01s)703=== CONT TestService_cleanupPendingClosuresHandler7042026-10-01 10:11:44.105 UTC [12762] ERROR: relation "goose_db_version" does not exist at character 367052026-10-01 10:11:44.105 UTC [12762] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7062026-10-01 10:11:44.106 UTC [12761] ERROR: relation "goose_db_version" does not exist at character 367072026-10-01 10:11:44.106 UTC [12761] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7082026-10-01 10:11:44.106 UTC [12760] ERROR: relation "goose_db_version" does not exist at character 367092026-10-01 10:11:44.106 UTC [12760] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7102026-10-01 10:11:44.107 UTC [12763] ERROR: relation "goose_db_version" does not exist at character 367112026-10-01 10:11:44.107 UTC [12763] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7122026-10-01 10:11:44.107 UTC [12764] ERROR: relation "goose_db_version" does not exist at character 367132026-10-01 10:11:44.107 UTC [12764] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7142026-10-01 10:11:44.108 UTC [12766] ERROR: relation "goose_db_version" does not exist at character 367152026-10-01 10:11:44.108 UTC [12766] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7162026-10-01 10:11:44.109 UTC [12765] ERROR: relation "goose_db_version" does not exist at character 367172026-10-01 10:11:44.109 UTC [12765] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7182026-10-01 10:11:44.110 UTC [12767] ERROR: relation "goose_db_version" does not exist at character 367192026-10-01 10:11:44.110 UTC [12767] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7202026-10-01 10:11:44.110 UTC [12769] ERROR: relation "goose_db_version" does not exist at character 367212026-10-01 10:11:44.110 UTC [12769] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7222026-10-01 10:11:44.110 UTC [12768] ERROR: relation "goose_db_version" does not exist at character 367232026-10-01 10:11:44.110 UTC [12768] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7242026/10/01 10:11:44 OK 20241026095416_initial_model.sql (7.67ms)7252026/10/01 10:11:44 OK 20251210153512_drop_unused_gin_index.sql (766.33µs)7262026/10/01 10:11:44 OK 20241026095416_initial_model.sql (8.21ms)7272026/10/01 10:11:44 OK 20251218171726_add_pins.sql (1.6ms)7282026/10/01 10:11:44 OK 20241026095416_initial_model.sql (8.64ms)7292026/10/01 10:11:44 OK 20251210153512_drop_unused_gin_index.sql (719µs)7302026/10/01 10:11:44 OK 20241026095416_initial_model.sql (10.24ms)7312026/10/01 10:11:44 OK 20241026095416_initial_model.sql (7.52ms)7322026/10/01 10:11:44 OK 20241026095416_initial_model.sql (9.67ms)7332026/10/01 10:11:44 OK 20241026095416_initial_model.sql (9.43ms)7342026/10/01 10:11:44 OK 20251210153512_drop_unused_gin_index.sql (828.29µs)7352026/10/01 10:11:44 OK 20251210153512_drop_unused_gin_index.sql (610.71µs)7362026/10/01 10:11:44 OK 20241026095416_initial_model.sql (8.94ms)7372026/10/01 10:11:44 OK 20251210153512_drop_unused_gin_index.sql (629.71µs)7382026/10/01 10:11:44 OK 20251210153512_drop_unused_gin_index.sql (836.5µs)7392026/10/01 10:11:44 OK 20251210153512_drop_unused_gin_index.sql (932.42µs)7402026/10/01 10:11:44 OK 20260628120000_add_object_size_and_stats.sql (1.58ms)7412026/10/01 10:11:44 OK 20251218171726_add_pins.sql (1.53ms)7422026/10/01 10:11:44 OK 20251210153512_drop_unused_gin_index.sql (786.42µs)7432026/10/01 10:11:44 OK 20241026095416_initial_model.sql (8.47ms)7442026/10/01 10:11:44 OK 20241026095416_initial_model.sql (8.43ms)7452026/10/01 10:11:44 OK 20251218171726_add_pins.sql (1.77ms)7462026/10/01 10:11:44 OK 20251218171726_add_pins.sql (2.01ms)7472026/10/01 10:11:44 OK 20251218171726_add_pins.sql (1.61ms)7482026/10/01 10:11:44 OK 20251218171726_add_pins.sql (1.54ms)7492026/10/01 10:11:44 OK 20251218171726_add_pins.sql (1.77ms)7502026/10/01 10:11:44 OK 20260905000000_add_claims.sql (1.74ms)7512026/10/01 10:11:44 OK 20251210153512_drop_unused_gin_index.sql (842.96µs)7522026/10/01 10:11:44 OK 20251210153512_drop_unused_gin_index.sql (883.29µs)7532026/10/01 10:11:44 OK 20260628120000_add_object_size_and_stats.sql (1.83ms)7542026/10/01 10:11:44 OK 20251218171726_add_pins.sql (1.58ms)7552026/10/01 10:11:44 OK 20260920000000_drop_claims.sql (1.25ms)7562026/10/01 10:11:44 OK 20260628120000_add_object_size_and_stats.sql (1.89ms)7572026/10/01 10:11:44 OK 20260628120000_add_object_size_and_stats.sql (1.81ms)7582026/10/01 10:11:44 OK 20260628120000_add_object_size_and_stats.sql (1.63ms)7592026/10/01 10:11:44 OK 20251218171726_add_pins.sql (1.61ms)7602026/10/01 10:11:44 OK 20260628120000_add_object_size_and_stats.sql (2.2ms)7612026/10/01 10:11:44 OK 20260628120000_add_object_size_and_stats.sql (1.48ms)7622026/10/01 10:11:44 OK 20260628120000_add_object_size_and_stats.sql (2.45ms)7632026/10/01 10:11:44 OK 20251218171726_add_pins.sql (2.1ms)7642026/10/01 10:11:44 OK 20260923120000_add_pushes.sql (1.14ms)7652026/10/01 10:11:44 goose: successfully migrated database to version: 202609231200007662026/10/01 10:11:44 OK 20260905000000_add_claims.sql (2.18ms)7672026/10/01 10:11:44 OK 20260628120000_add_object_size_and_stats.sql (1.74ms)7682026/10/01 10:11:44 OK 20260905000000_add_claims.sql (2.36ms)7692026/10/01 10:11:44 OK 20260905000000_add_claims.sql (2.52ms)7702026/10/01 10:11:44 OK 20260905000000_add_claims.sql (2.59ms)7712026/10/01 10:11:44 OK 20260920000000_drop_claims.sql (1.78ms)7722026/10/01 10:11:44 OK 20260905000000_add_claims.sql (2.55ms)7732026/10/01 10:11:44 OK 20260628120000_add_object_size_and_stats.sql (2.38ms)7742026/10/01 10:11:44 OK 20260905000000_add_claims.sql (2.66ms)7752026/10/01 10:11:44 OK 20260905000000_add_claims.sql (2.66ms)7762026/10/01 10:11:44 OK 1_commit_pending_closure.sql (2.12ms)7772026/10/01 10:11:44 OK 20260905000000_add_claims.sql (1.43ms)7782026/10/01 10:11:44 OK 20260923120000_add_pushes.sql (797µs)7792026/10/01 10:11:44 goose: successfully migrated database to version: 202609231200007802026/10/01 10:11:44 OK 20260920000000_drop_claims.sql (1.37ms)7812026/10/01 10:11:44 OK 20260920000000_drop_claims.sql (1.22ms)7822026/10/01 10:11:44 OK 2_object_stats_trigger.sql (759.38µs)7832026/10/01 10:11:44 OK 20260920000000_drop_claims.sql (1.73ms)7842026/10/01 10:11:44 OK 20260920000000_drop_claims.sql (1.29ms)7852026/10/01 10:11:44 OK 20260920000000_drop_claims.sql (1.34ms)7862026/10/01 10:11:44 OK 20260920000000_drop_claims.sql (1.45ms)7872026/10/01 10:11:44 OK 20260920000000_drop_claims.sql (1.26ms)7882026/10/01 10:11:44 OK 20260905000000_add_claims.sql (1.81ms)7892026/10/01 10:11:44 OK 3_commit_push.sql (496.25µs)7902026/10/01 10:11:44 goose: up to current file version: 37912026/10/01 10:11:44 OK 1_commit_pending_closure.sql (1.35ms)7922026/10/01 10:11:44 OK 20260923120000_add_pushes.sql (1.45ms)7932026/10/01 10:11:44 goose: successfully migrated database to version: 202609231200007942026/10/01 10:11:44 OK 20260923120000_add_pushes.sql (538.38µs)7952026/10/01 10:11:44 goose: successfully migrated database to version: 202609231200007962026/10/01 10:11:44 OK 20260923120000_add_pushes.sql (657µs)7972026/10/01 10:11:44 goose: successfully migrated database to version: 202609231200007982026/10/01 10:11:44 OK 2_object_stats_trigger.sql (416.38µs)7992026/10/01 10:11:44 OK 20260923120000_add_pushes.sql (788.63µs)8002026/10/01 10:11:44 goose: successfully migrated database to version: 202609231200008012026/10/01 10:11:44 OK 20260923120000_add_pushes.sql (1.28ms)8022026/10/01 10:11:44 goose: successfully migrated database to version: 202609231200008032026/10/01 10:11:44 OK 20260923120000_add_pushes.sql (925.08µs)8042026/10/01 10:11:44 goose: successfully migrated database to version: 202609231200008052026/10/01 10:11:44 OK 20260923120000_add_pushes.sql (1.48ms)8062026/10/01 10:11:44 goose: successfully migrated database to version: 202609231200008072026/10/01 10:11:44 OK 20260920000000_drop_claims.sql (1.2ms)8082026/10/01 10:11:44 OK 3_commit_push.sql (520.13µs)8092026/10/01 10:11:44 goose: up to current file version: 38102026/10/01 10:11:44 OK 1_commit_pending_closure.sql (945.63µs)8112026/10/01 10:11:44 OK 1_commit_pending_closure.sql (1.3ms)8122026/10/01 10:11:44 OK 2_object_stats_trigger.sql (388.67µs)8132026/10/01 10:11:44 OK 1_commit_pending_closure.sql (1.49ms)8142026/10/01 10:11:44 OK 1_commit_pending_closure.sql (1.16ms)8152026/10/01 10:11:44 OK 20260923120000_add_pushes.sql (861.25µs)8162026/10/01 10:11:44 goose: successfully migrated database to version: 202609231200008172026/10/01 10:11:44 OK 1_commit_pending_closure.sql (931.88µs)8182026/10/01 10:11:44 OK 2_object_stats_trigger.sql (306.42µs)8192026/10/01 10:11:44 OK 3_commit_push.sql (283µs)8202026/10/01 10:11:44 goose: up to current file version: 38212026/10/01 10:11:44 OK 1_commit_pending_closure.sql (1.34ms)8222026/10/01 10:11:44 OK 1_commit_pending_closure.sql (1.51ms)8232026/10/01 10:11:44 OK 2_object_stats_trigger.sql (250.5µs)8242026/10/01 10:11:44 OK 2_object_stats_trigger.sql (357.46µs)8252026/10/01 10:11:44 OK 2_object_stats_trigger.sql (420.79µs)8262026/10/01 10:11:44 OK 3_commit_push.sql (349µs)8272026/10/01 10:11:44 goose: up to current file version: 38282026/10/01 10:11:44 OK 3_commit_push.sql (184.25µs)8292026/10/01 10:11:44 goose: up to current file version: 38302026/10/01 10:11:44 OK 3_commit_push.sql (216.5µs)8312026/10/01 10:11:44 goose: up to current file version: 38322026/10/01 10:11:44 OK 2_object_stats_trigger.sql (338.63µs)8332026/10/01 10:11:44 OK 2_object_stats_trigger.sql (430.96µs)8342026/10/01 10:11:44 OK 3_commit_push.sql (312.17µs)8352026/10/01 10:11:44 goose: up to current file version: 38362026/10/01 10:11:44 OK 3_commit_push.sql (171.58µs)8372026/10/01 10:11:44 goose: up to current file version: 38382026/10/01 10:11:44 OK 3_commit_push.sql (231.92µs)8392026/10/01 10:11:44 goose: up to current file version: 38402026/10/01 10:11:44 OK 1_commit_pending_closure.sql (849.04µs)8412026/10/01 10:11:44 OK 2_object_stats_trigger.sql (171.54µs)8422026/10/01 10:11:44 OK 3_commit_push.sql (158.46µs)8432026/10/01 10:11:44 goose: up to current file version: 3844--- PASS: TestReadRedirectUsesPublicS3URL (0.46s)845=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT846--- PASS: TestReadRedirectNar (0.60s)847=== CONT TestCompleteMultipartUnregistered848--- PASS: TestGCEndsOnShutdown (0.82s)849=== CONT TestService_verifyS3Integrity850--- PASS: TestReadProxyDisabled (0.95s)851=== CONT TestService_createPendingClosureHandler852--- PASS: TestReadRedirectKeepsNarinfoProxied (1.12s)853=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded8542026-10-01 10:11:45.000 UTC [12780] ERROR: relation "goose_db_version" does not exist at character 368552026-10-01 10:11:45.000 UTC [12780] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8562026/10/01 10:11:45 INFO Received cleanup request method=DELETE path=/api/pending_closures8572026/10/01 10:11:45 INFO Aborted multipart uploads count=0 kept=08582026/10/01 10:11:45 INFO Received uploads request method=POST path=/api/pending_closures8592026/10/01 10:11:45 INFO Received cleanup request method=DELETE path=/api/pending_closures8602026-10-01 10:11:45.130 UTC [12781] ERROR: relation "goose_db_version" does not exist at character 368612026-10-01 10:11:45.130 UTC [12781] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8622026/10/01 10:11:45 INFO Aborted multipart uploads count=1 kept=08632026/10/01 10:11:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8642026-10-01 10:11:45.143 UTC [12765] ERROR: Closure does not exist: id=18652026-10-01 10:11:45.143 UTC [12765] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE8662026-10-01 10:11:45.143 UTC [12765] STATEMENT: -- name: CommitPendingClosure :exec867 SELECT commit_pending_closure($1::bigint)868 869--- PASS: TestService_cleanupPendingClosuresHandler (1.35s)870=== CONT TestReadProxyRootRedirectsToIndexHTML8712026/10/01 10:11:45 OK 20241026095416_initial_model.sql (107.98ms)8722026/10/01 10:11:45 OK 20251210153512_drop_unused_gin_index.sql (12.87ms)8732026/10/01 10:11:45 OK 20251218171726_add_pins.sql (57.67ms)8742026/10/01 10:11:45 OK 20260628120000_add_object_size_and_stats.sql (17.97ms)8752026/10/01 10:11:45 OK 20241026095416_initial_model.sql (77.26ms)8762026/10/01 10:11:45 OK 20260905000000_add_claims.sql (22.88ms)8772026/10/01 10:11:45 OK 20251210153512_drop_unused_gin_index.sql (11.46ms)8782026/10/01 10:11:45 OK 20260920000000_drop_claims.sql (19.29ms)8792026/10/01 10:11:45 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"880--- PASS: TestService_AuthMiddleware (1.50s)881=== CONT TestReadProxyConditionalGet8822026-10-01 10:11:45.282 UTC [12784] ERROR: relation "goose_db_version" does not exist at character 368832026-10-01 10:11:45.282 UTC [12784] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8842026/10/01 10:11:45 OK 20251218171726_add_pins.sql (16.21ms)8852026/10/01 10:11:45 OK 20260923120000_add_pushes.sql (4.18ms)8862026/10/01 10:11:45 goose: successfully migrated database to version: 202609231200008872026/10/01 10:11:45 OK 1_commit_pending_closure.sql (2.78ms)8882026/10/01 10:11:45 OK 2_object_stats_trigger.sql (806.38µs)8892026/10/01 10:11:45 OK 3_commit_push.sql (462.33µs)8902026/10/01 10:11:45 goose: up to current file version: 38912026/10/01 10:11:45 OK 20260628120000_add_object_size_and_stats.sql (32.4ms)8922026/10/01 10:11:45 OK 20260905000000_add_claims.sql (21.96ms)8932026/10/01 10:11:45 OK 20260920000000_drop_claims.sql (13.26ms)8942026/10/01 10:11:45 OK 20260923120000_add_pushes.sql (6.66ms)8952026/10/01 10:11:45 goose: successfully migrated database to version: 202609231200008962026/10/01 10:11:45 OK 1_commit_pending_closure.sql (2.42ms)8972026/10/01 10:11:45 OK 2_object_stats_trigger.sql (510.04µs)8982026/10/01 10:11:45 OK 3_commit_push.sql (336.75µs)8992026/10/01 10:11:45 goose: up to current file version: 39002026/10/01 10:11:45 OK 20241026095416_initial_model.sql (58.27ms)9012026/10/01 10:11:45 OK 20251210153512_drop_unused_gin_index.sql (3.52ms)9022026/10/01 10:11:45 OK 20251218171726_add_pins.sql (16.14ms)9032026/10/01 10:11:45 OK 20260628120000_add_object_size_and_stats.sql (18.57ms)9042026/10/01 10:11:45 INFO Received push request method=POST path=/api/pushes9052026/10/01 10:11:45 OK 20260905000000_add_claims.sql (30.33ms)9062026/10/01 10:11:45 OK 20260920000000_drop_claims.sql (26.02ms)9072026/10/01 10:11:45 OK 20260923120000_add_pushes.sql (21.17ms)9082026/10/01 10:11:45 goose: successfully migrated database to version: 202609231200009092026/10/01 10:11:45 OK 1_commit_pending_closure.sql (4.42ms)9102026/10/01 10:11:45 OK 2_object_stats_trigger.sql (887.42µs)9112026/10/01 10:11:45 OK 3_commit_push.sql (553.33µs)9122026/10/01 10:11:45 goose: up to current file version: 3913--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (1.76s)914=== CONT TestReadProxyHead9152026-10-01 10:11:45.552 UTC [12789] ERROR: relation "goose_db_version" does not exist at character 369162026-10-01 10:11:45.552 UTC [12789] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9172026/10/01 10:11:45 OK 20241026095416_initial_model.sql (90.36ms)9182026/10/01 10:11:45 OK 20251210153512_drop_unused_gin_index.sql (9.54ms)9192026/10/01 10:11:45 OK 20251218171726_add_pins.sql (5.28ms)9202026/10/01 10:11:45 INFO Aborted multipart uploads count=0 kept=09212026/10/01 10:11:45 WARN Force mode enabled - objects will be deleted immediately without grace period9222026/10/01 10:11:45 OK 20260628120000_add_object_size_and_stats.sql (25.26ms)9232026/10/01 10:11:45 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=09242026/10/01 10:11:45 INFO Vacuumed table table=pending_closures9252026/10/01 10:11:45 INFO Vacuumed table table=pending_objects9262026/10/01 10:11:45 INFO Vacuumed table table=multipart_uploads9272026/10/01 10:11:45 OK 20260905000000_add_claims.sql (47.85ms)9282026/10/01 10:11:45 INFO Vacuumed table table=closures9292026/10/01 10:11:45 INFO Vacuumed table table=objects930--- PASS: TestCommitRacingPendingCleanupKeepsObjects (1.99s)931=== CONT TestReadProxyInvalidPath9322026/10/01 10:11:45 OK 20260920000000_drop_claims.sql (19.74ms)9332026/10/01 10:11:45 OK 20260923120000_add_pushes.sql (7.41ms)9342026/10/01 10:11:45 goose: successfully migrated database to version: 202609231200009352026/10/01 10:11:45 OK 1_commit_pending_closure.sql (2.04ms)9362026/10/01 10:11:45 OK 2_object_stats_trigger.sql (502.63µs)9372026/10/01 10:11:45 OK 3_commit_push.sql (336.25µs)9382026/10/01 10:11:45 goose: up to current file version: 3939--- PASS: TestReadProxyRangeRequest (2.06s)940=== CONT TestReadProxy4049412026-10-01 10:11:45.886 UTC [12799] ERROR: relation "goose_db_version" does not exist at character 369422026-10-01 10:11:45.886 UTC [12799] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9432026/10/01 10:11:46 INFO Received uploads request method=POST path=/api/pending_closures9442026/10/01 10:11:46 OK 20241026095416_initial_model.sql (118.24ms)9452026/10/01 10:11:46 OK 20251210153512_drop_unused_gin_index.sql (19.57ms)9462026/10/01 10:11:46 OK 20251218171726_add_pins.sql (20.88ms)947--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.83s)948=== CONT TestReadProxyNarStreaming9492026/10/01 10:11:46 OK 20260628120000_add_object_size_and_stats.sql (25.49ms)9502026-10-01 10:11:46.114 UTC [12801] ERROR: relation "goose_db_version" does not exist at character 369512026-10-01 10:11:46.114 UTC [12801] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9522026/10/01 10:11:46 OK 20260905000000_add_claims.sql (19.79ms)9532026/10/01 10:11:46 OK 20260920000000_drop_claims.sql (12.12ms)9542026/10/01 10:11:46 OK 20260923120000_add_pushes.sql (2.85ms)9552026/10/01 10:11:46 goose: successfully migrated database to version: 202609231200009562026/10/01 10:11:46 OK 1_commit_pending_closure.sql (2.86ms)9572026/10/01 10:11:46 OK 2_object_stats_trigger.sql (527.42µs)9582026/10/01 10:11:46 OK 3_commit_push.sql (501.71µs)9592026/10/01 10:11:46 goose: up to current file version: 39602026/10/01 10:11:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9612026/10/01 10:11:46 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst962--- PASS: TestCompleteMultipartUnregistered (1.81s)963=== CONT TestReadProxyNarinfoAlreadyDecompressed9642026/10/01 10:11:46 OK 20241026095416_initial_model.sql (88.33ms)9652026/10/01 10:11:46 OK 20251210153512_drop_unused_gin_index.sql (10.91ms)9662026-10-01 10:11:46.248 UTC [12803] ERROR: relation "goose_db_version" does not exist at character 369672026-10-01 10:11:46.248 UTC [12803] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9682026/10/01 10:11:46 OK 20251218171726_add_pins.sql (11.89ms)9692026/10/01 10:11:46 OK 20260628120000_add_object_size_and_stats.sql (11.14ms)9702026/10/01 10:11:46 OK 20260905000000_add_claims.sql (23.64ms)9712026/10/01 10:11:46 OK 20260920000000_drop_claims.sql (8.75ms)9722026/10/01 10:11:46 OK 20260923120000_add_pushes.sql (5.48ms)9732026/10/01 10:11:46 goose: successfully migrated database to version: 202609231200009742026/10/01 10:11:46 OK 1_commit_pending_closure.sql (2.58ms)9752026/10/01 10:11:46 OK 2_object_stats_trigger.sql (565.21µs)9762026/10/01 10:11:46 OK 3_commit_push.sql (465.08µs)9772026/10/01 10:11:46 goose: up to current file version: 39782026/10/01 10:11:46 OK 20241026095416_initial_model.sql (63.72ms)9792026/10/01 10:11:46 OK 20251210153512_drop_unused_gin_index.sql (12.3ms)9802026/10/01 10:11:46 INFO Received uploads request method=POST path=/api/pending_closures9812026/10/01 10:11:46 OK 20251218171726_add_pins.sql (16.2ms)9822026/10/01 10:11:46 OK 20260628120000_add_object_size_and_stats.sql (40.42ms)9832026/10/01 10:11:46 OK 20260905000000_add_claims.sql (30.33ms)9842026/10/01 10:11:46 OK 20260920000000_drop_claims.sql (14.3ms)9852026/10/01 10:11:46 OK 20260923120000_add_pushes.sql (9.3ms)9862026/10/01 10:11:46 goose: successfully migrated database to version: 202609231200009872026/10/01 10:11:46 OK 1_commit_pending_closure.sql (2.22ms)9882026/10/01 10:11:46 OK 2_object_stats_trigger.sql (476.79µs)9892026/10/01 10:11:46 OK 3_commit_push.sql (389.67µs)9902026/10/01 10:11:46 goose: up to current file version: 39912026/10/01 10:11:46 INFO Received uploads request method=POST path=/api/pending_closures9922026/10/01 10:11:46 INFO Received uploads request method=POST path=/api/pending_closures9932026/10/01 10:11:46 INFO Received uploads request method=POST path=/api/pending_closures9942026-10-01 10:11:46.594 UTC [12806] ERROR: relation "goose_db_version" does not exist at character 369952026-10-01 10:11:46.594 UTC [12806] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9962026/10/01 10:11:46 OK 20241026095416_initial_model.sql (145.84ms)9972026/10/01 10:11:46 OK 20251210153512_drop_unused_gin_index.sql (9.39ms)9982026/10/01 10:11:46 INFO Received uploads request method=POST path=/api/pending_closures9992026/10/01 10:11:46 OK 20251218171726_add_pins.sql (37.99ms)10002026/10/01 10:11:46 OK 20260628120000_add_object_size_and_stats.sql (57.68ms)10012026/10/01 10:11:46 OK 20260905000000_add_claims.sql (46.28ms)1002--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (2.05s)1003=== CONT TestReadProxyNarinfo10042026/10/01 10:11:47 OK 20260920000000_drop_claims.sql (73.03ms)10052026/10/01 10:11:47 OK 20260923120000_add_pushes.sql (16.8ms)10062026/10/01 10:11:47 goose: successfully migrated database to version: 2026092312000010072026/10/01 10:11:47 OK 1_commit_pending_closure.sql (2.95ms)10082026/10/01 10:11:47 OK 2_object_stats_trigger.sql (555.38µs)10092026/10/01 10:11:47 OK 3_commit_push.sql (392.33µs)10102026/10/01 10:11:47 goose: up to current file version: 310112026-10-01 10:11:47.069 UTC [12808] ERROR: relation "goose_db_version" does not exist at character 3610122026-10-01 10:11:47.069 UTC [12808] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1013--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.03s)1014=== CONT TestIsValidCachePath1015=== RUN TestIsValidCachePath/narinfo1016=== PAUSE TestIsValidCachePath/narinfo1017=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1018=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1019=== RUN TestIsValidCachePath/nar_zst1020=== PAUSE TestIsValidCachePath/nar_zst1021=== RUN TestIsValidCachePath/nar_xz1022=== PAUSE TestIsValidCachePath/nar_xz1023=== RUN TestIsValidCachePath/nar_bz21024=== PAUSE TestIsValidCachePath/nar_bz21025=== RUN TestIsValidCachePath/nar_uncompressed1026=== PAUSE TestIsValidCachePath/nar_uncompressed1027=== RUN TestIsValidCachePath/ls1028=== PAUSE TestIsValidCachePath/ls1029=== RUN TestIsValidCachePath/log1030=== PAUSE TestIsValidCachePath/log1031=== RUN TestIsValidCachePath/realisation1032=== PAUSE TestIsValidCachePath/realisation1033=== RUN TestIsValidCachePath/nix-cache-info1034=== PAUSE TestIsValidCachePath/nix-cache-info1035=== RUN TestIsValidCachePath/index.html1036=== PAUSE TestIsValidCachePath/index.html1037=== RUN TestIsValidCachePath/traversal_parent1038=== PAUSE TestIsValidCachePath/traversal_parent1039=== RUN TestIsValidCachePath/traversal_in_middle1040=== PAUSE TestIsValidCachePath/traversal_in_middle1041=== RUN TestIsValidCachePath/invalid_char_e1042=== PAUSE TestIsValidCachePath/invalid_char_e1043=== RUN TestIsValidCachePath/invalid_char_u1044=== PAUSE TestIsValidCachePath/invalid_char_u1045=== RUN TestIsValidCachePath/random_path1046=== PAUSE TestIsValidCachePath/random_path1047=== RUN TestIsValidCachePath/empty1048=== PAUSE TestIsValidCachePath/empty1049=== RUN TestIsValidCachePath/leading_slash1050=== PAUSE TestIsValidCachePath/leading_slash1051=== RUN TestIsValidCachePath/wrong_extension1052=== PAUSE TestIsValidCachePath/wrong_extension1053=== RUN TestIsValidCachePath/short_hash1054=== PAUSE TestIsValidCachePath/short_hash1055=== CONT TestProxyHeadersOnlyTrustedOnSocket10562026-10-01 10:11:47.293 UTC [12812] ERROR: relation "goose_db_version" does not exist at character 3610572026-10-01 10:11:47.293 UTC [12812] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10582026/10/01 10:11:47 OK 20241026095416_initial_model.sql (213.37ms)10592026/10/01 10:11:47 OK 20251210153512_drop_unused_gin_index.sql (18.11ms)10602026/10/01 10:11:47 OK 20251218171726_add_pins.sql (17.61ms)10612026/10/01 10:11:47 OK 20260628120000_add_object_size_and_stats.sql (37ms)1062--- PASS: TestReadProxyConditionalGet (2.17s)1063=== CONT TestParseSingleRange1064=== RUN TestParseSingleRange/none1065=== PAUSE TestParseSingleRange/none1066=== RUN TestParseSingleRange/unknown_unit1067=== PAUSE TestParseSingleRange/unknown_unit1068=== RUN TestParseSingleRange/multi-range_ignored1069=== PAUSE TestParseSingleRange/multi-range_ignored1070=== RUN TestParseSingleRange/malformed_no_dash1071=== PAUSE TestParseSingleRange/malformed_no_dash1072=== RUN TestParseSingleRange/malformed_both_empty1073=== PAUSE TestParseSingleRange/malformed_both_empty1074=== RUN TestParseSingleRange/malformed_end_before_start1075=== PAUSE TestParseSingleRange/malformed_end_before_start1076=== RUN TestParseSingleRange/closed1077=== PAUSE TestParseSingleRange/closed1078=== RUN TestParseSingleRange/open-ended1079=== PAUSE TestParseSingleRange/open-ended1080=== RUN TestParseSingleRange/end_clamped_to_size1081=== PAUSE TestParseSingleRange/end_clamped_to_size1082=== RUN TestParseSingleRange/suffix1083=== PAUSE TestParseSingleRange/suffix1084=== RUN TestParseSingleRange/suffix_exceeds_size1085=== PAUSE TestParseSingleRange/suffix_exceeds_size1086=== RUN TestParseSingleRange/single_byte1087=== PAUSE TestParseSingleRange/single_byte1088=== RUN TestParseSingleRange/start_past_EOF1089=== PAUSE TestParseSingleRange/start_past_EOF1090=== RUN TestParseSingleRange/start_far_past_EOF1091=== PAUSE TestParseSingleRange/start_far_past_EOF1092=== CONT TestPresentNotReportedWhileGCDeletesClosure10932026/10/01 10:11:47 OK 20260905000000_add_claims.sql (101.37ms)10942026/10/01 10:11:47 OK 20260920000000_drop_claims.sql (26.19ms)10952026/10/01 10:11:47 OK 20241026095416_initial_model.sql (191.13ms)10962026/10/01 10:11:47 OK 20260923120000_add_pushes.sql (21.47ms)10972026/10/01 10:11:47 goose: successfully migrated database to version: 2026092312000010982026/10/01 10:11:47 OK 1_commit_pending_closure.sql (1.71ms)10992026/10/01 10:11:47 OK 2_object_stats_trigger.sql (388.17µs)11002026/10/01 10:11:47 OK 3_commit_push.sql (312.29µs)11012026/10/01 10:11:47 goose: up to current file version: 311022026/10/01 10:11:47 OK 20251210153512_drop_unused_gin_index.sql (15.46ms)11032026/10/01 10:11:47 OK 20251218171726_add_pins.sql (35.25ms)11042026-10-01 10:11:47.625 UTC [12815] ERROR: relation "goose_db_version" does not exist at character 3611052026-10-01 10:11:47.625 UTC [12815] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11062026/10/01 10:11:47 OK 20260628120000_add_object_size_and_stats.sql (41.05ms)11072026/10/01 10:11:47 OK 20260905000000_add_claims.sql (31.18ms)11082026/10/01 10:11:47 OK 20260920000000_drop_claims.sql (57.48ms)11092026/10/01 10:11:47 OK 20260923120000_add_pushes.sql (16.7ms)11102026/10/01 10:11:47 goose: successfully migrated database to version: 2026092312000011112026/10/01 10:11:47 OK 1_commit_pending_closure.sql (3.03ms)11122026/10/01 10:11:47 OK 2_object_stats_trigger.sql (649.58µs)11132026/10/01 10:11:47 OK 3_commit_push.sql (403.25µs)11142026/10/01 10:11:47 goose: up to current file version: 311152026/10/01 10:11:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1116--- PASS: TestReadProxyHead (2.22s)1117=== CONT TestPresentReportsOnlyClosureRoots11182026/10/01 10:11:47 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YzYzNGRmM2QtMTAxOS00MWMzLThlNTUtYjFmZTZiNjY4ZGEzLmVlNDY5ZjQ5LTA5YmItNDNmZC1hNzJmLTFmYmNkNmMzMzhmZngxNzkwODQ5NTA2Mzk3Mzc4MDAw parts=1011192026/10/01 10:11:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11202026/10/01 10:11:47 INFO Completed upload id=111212026-10-01 10:11:47.808 UTC [12817] ERROR: relation "goose_db_version" does not exist at character 3611222026-10-01 10:11:47.808 UTC [12817] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11232026/10/01 10:11:47 INFO Received uploads request method=POST path=/api/pending_closures11242026/10/01 10:11:47 INFO Received uploads request method=POST path=/api/pending_closures11252026/10/01 10:11:47 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11262026/10/01 10:11:47 WARN Found objects in DB but missing from S3, will re-upload count=11127--- PASS: TestService_verifyS3Integrity (3.20s)1128=== CONT TestCreatePin_ReservedPins11292026/10/01 10:11:47 OK 20241026095416_initial_model.sql (178.71ms)11302026/10/01 10:11:47 OK 20251210153512_drop_unused_gin_index.sql (20.2ms)11312026/10/01 10:11:47 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58963/oidc11322026/10/01 10:11:47 OK 20251218171726_add_pins.sql (23.79ms)11332026/10/01 10:11:47 OK 20260628120000_add_object_size_and_stats.sql (12.01ms)11342026/10/01 10:11:47 OK 20260905000000_add_claims.sql (22.08ms)11352026/10/01 10:11:47 OK 20260920000000_drop_claims.sql (30.08ms)11362026/10/01 10:11:47 OK 20260923120000_add_pushes.sql (6.11ms)11372026/10/01 10:11:47 goose: successfully migrated database to version: 2026092312000011382026/10/01 10:11:47 OK 1_commit_pending_closure.sql (953.79µs)11392026/10/01 10:11:47 OK 2_object_stats_trigger.sql (224.58µs)11402026/10/01 10:11:47 OK 3_commit_push.sql (195µs)11412026/10/01 10:11:47 goose: up to current file version: 31142--- PASS: TestReadProxyInvalidPath (2.19s)1143=== CONT TestOrphanedObjectsGCStressTest11442026/10/01 10:11:47 OK 20241026095416_initial_model.sql (93.69ms)11452026/10/01 10:11:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11462026/10/01 10:11:48 OK 20251210153512_drop_unused_gin_index.sql (23.04ms)11472026/10/01 10:11:48 OK 20251218171726_add_pins.sql (31.11ms)11482026/10/01 10:11:48 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YzYzNGRmM2QtMTAxOS00MWMzLThlNTUtYjFmZTZiNjY4ZGEzLmI3YjUwYWYxLWNjZjAtNDU2ZC1iNTZjLTkzMzEzYTQwNDRmNngxNzkwODQ5NTA2NjIyOTk0MDAw parts=1011492026/10/01 10:11:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11502026/10/01 10:11:48 OK 20260628120000_add_object_size_and_stats.sql (25.12ms)11512026/10/01 10:11:48 INFO Completed upload id=111522026/10/01 10:11:48 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011532026/10/01 10:11:48 INFO Received uploads request method=POST path=/api/pending_closures11542026/10/01 10:11:48 INFO Starting cleanup of old closures method=DELETE path=/api/closures11552026/10/01 10:11:48 INFO Aborted multipart uploads count=0 kept=011562026/10/01 10:11:48 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011572026/10/01 10:11:48 OK 20260905000000_add_claims.sql (23.13ms)11582026/10/01 10:11:48 INFO Vacuumed table table=pending_closures11592026/10/01 10:11:48 OK 20260920000000_drop_claims.sql (11.15ms)11602026/10/01 10:11:48 INFO Vacuumed table table=pending_objects11612026/10/01 10:11:48 OK 20260923120000_add_pushes.sql (16.8ms)11622026/10/01 10:11:48 goose: successfully migrated database to version: 2026092312000011632026/10/01 10:11:48 OK 1_commit_pending_closure.sql (1.42ms)11642026/10/01 10:11:48 OK 2_object_stats_trigger.sql (322.46µs)11652026/10/01 10:11:48 OK 3_commit_push.sql (257.38µs)11662026/10/01 10:11:48 goose: up to current file version: 311672026/10/01 10:11:48 INFO Vacuumed table table=multipart_uploads11682026/10/01 10:11:48 INFO Vacuumed table table=closures11692026/10/01 10:11:48 INFO Vacuumed table table=objects11702026/10/01 10:11:48 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001171--- PASS: TestService_createPendingClosureHandler (3.49s)1172=== CONT TestOrphanedObjectsGC1173--- PASS: TestReadProxy404 (2.38s)1174=== CONT TestObjectStatsTrigger1175--- PASS: TestReadProxyNarStreaming (2.34s)1176=== CONT TestPendingCleanupUsesOneCutoff11772026-10-01 10:11:48.525 UTC [12831] ERROR: relation "goose_db_version" does not exist at character 3611782026-10-01 10:11:48.525 UTC [12831] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11792026-10-01 10:11:48.596 UTC [12832] ERROR: relation "goose_db_version" does not exist at character 3611802026-10-01 10:11:48.596 UTC [12832] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1181--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.41s)1182=== CONT TestResolveDBConnectionString1183=== RUN TestResolveDBConnectionString/flag_wins1184=== PAUSE TestResolveDBConnectionString/flag_wins1185=== RUN TestResolveDBConnectionString/file_when_flag_empty1186=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1187=== RUN TestResolveDBConnectionString/missing_file_is_an_error1188=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1189=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1190=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1191=== RUN TestResolveDBConnectionString/nothing_configured1192=== PAUSE TestResolveDBConnectionString/nothing_configured1193=== CONT TestTombstonedObjectOfferedWithoutWaiting11942026/10/01 10:11:48 OK 20241026095416_initial_model.sql (88.27ms)11952026/10/01 10:11:48 OK 20251210153512_drop_unused_gin_index.sql (1.13ms)11962026/10/01 10:11:48 OK 20251218171726_add_pins.sql (1.43ms)11972026/10/01 10:11:48 OK 20241026095416_initial_model.sql (28.87ms)11982026/10/01 10:11:48 OK 20251210153512_drop_unused_gin_index.sql (560µs)11992026/10/01 10:11:48 OK 20251218171726_add_pins.sql (1.16ms)12002026-10-01 10:11:48.673 UTC [12835] ERROR: relation "goose_db_version" does not exist at character 3612012026-10-01 10:11:48.673 UTC [12835] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12022026/10/01 10:11:48 OK 20260628120000_add_object_size_and_stats.sql (8.09ms)12032026/10/01 10:11:48 OK 20260905000000_add_claims.sql (7.8ms)12042026/10/01 10:11:48 OK 20260920000000_drop_claims.sql (867.92µs)12052026/10/01 10:11:48 OK 20260923120000_add_pushes.sql (621.54µs)12062026/10/01 10:11:48 goose: successfully migrated database to version: 2026092312000012072026/10/01 10:11:48 OK 20260628120000_add_object_size_and_stats.sql (14.69ms)12082026/10/01 10:11:48 OK 1_commit_pending_closure.sql (2.21ms)12092026/10/01 10:11:48 OK 2_object_stats_trigger.sql (596.21µs)12102026/10/01 10:11:48 OK 3_commit_push.sql (544.33µs)12112026/10/01 10:11:48 goose: up to current file version: 312122026/10/01 10:11:48 OK 20260905000000_add_claims.sql (5.42ms)12132026/10/01 10:11:48 OK 20260920000000_drop_claims.sql (17.74ms)12142026/10/01 10:11:48 OK 20260923120000_add_pushes.sql (6.5ms)12152026/10/01 10:11:48 goose: successfully migrated database to version: 2026092312000012162026/10/01 10:11:48 OK 1_commit_pending_closure.sql (1.8ms)12172026/10/01 10:11:48 OK 2_object_stats_trigger.sql (306.17µs)12182026/10/01 10:11:48 OK 3_commit_push.sql (252.79µs)12192026/10/01 10:11:48 goose: up to current file version: 312202026/10/01 10:11:48 OK 20241026095416_initial_model.sql (57.81ms)12212026/10/01 10:11:48 OK 20251210153512_drop_unused_gin_index.sql (6.29ms)12222026/10/01 10:11:48 OK 20251218171726_add_pins.sql (8.03ms)12232026/10/01 10:11:48 OK 20260628120000_add_object_size_and_stats.sql (19.65ms)12242026/10/01 10:11:48 OK 20260905000000_add_claims.sql (24.64ms)12252026/10/01 10:11:48 OK 20260920000000_drop_claims.sql (22.06ms)12262026/10/01 10:11:48 OK 20260923120000_add_pushes.sql (8.66ms)12272026/10/01 10:11:48 goose: successfully migrated database to version: 2026092312000012282026/10/01 10:11:48 OK 1_commit_pending_closure.sql (2.02ms)12292026/10/01 10:11:48 OK 2_object_stats_trigger.sql (701µs)12302026/10/01 10:11:48 OK 3_commit_push.sql (1.7ms)12312026/10/01 10:11:48 goose: up to current file version: 31232--- PASS: TestReadProxyNarinfo (1.93s)1233=== CONT TestGCSweepSkipsPendingObjects12342026/10/01 10:11:49 INFO Starting HTTP server address=/nix/var/nix/builds/nix-12646-3956915670/TestProxyHeadersOnlyTrustedOnSocket3393439288/001/proxy.sock12352026/10/01 10:11:49 WARN mTLS auth: subject not in bound subjects subject="CN=someone"12362026/10/01 10:11:49 INFO Starting HTTP server address=127.0.0.1:5898512372026/10/01 10:11:49 INFO Shutdown signal received, draining in-flight requests timeout=10s1238--- PASS: TestProxyHeadersOnlyTrustedOnSocket (1.94s)1239=== CONT TestDeduplicatedObjectsRecordedAsPending12402026-10-01 10:11:49.155 UTC [12841] ERROR: relation "goose_db_version" does not exist at character 3612412026-10-01 10:11:49.155 UTC [12841] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12422026-10-01 10:11:49.176 UTC [12844] ERROR: relation "goose_db_version" does not exist at character 3612432026-10-01 10:11:49.176 UTC [12844] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12442026-10-01 10:11:49.214 UTC [12845] ERROR: relation "goose_db_version" does not exist at character 3612452026-10-01 10:11:49.214 UTC [12845] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12462026/10/01 10:11:49 OK 20241026095416_initial_model.sql (86.18ms)12472026/10/01 10:11:49 OK 20251210153512_drop_unused_gin_index.sql (8.7ms)12482026/10/01 10:11:49 OK 20241026095416_initial_model.sql (91.91ms)12492026/10/01 10:11:49 OK 20251210153512_drop_unused_gin_index.sql (8.67ms)12502026/10/01 10:11:49 OK 20251218171726_add_pins.sql (31.74ms)12512026/10/01 10:11:49 OK 20251218171726_add_pins.sql (15.91ms)12522026/10/01 10:11:49 OK 20260628120000_add_object_size_and_stats.sql (23.09ms)12532026/10/01 10:11:49 OK 20260628120000_add_object_size_and_stats.sql (24.59ms)12542026/10/01 10:11:49 OK 20241026095416_initial_model.sql (111.38ms)12552026/10/01 10:11:49 OK 20251210153512_drop_unused_gin_index.sql (9.12ms)12562026/10/01 10:11:49 OK 20260905000000_add_claims.sql (55.03ms)12572026/10/01 10:11:49 OK 20260905000000_add_claims.sql (55.35ms)12582026/10/01 10:11:49 OK 20251218171726_add_pins.sql (22.16ms)12592026/10/01 10:11:49 OK 20260920000000_drop_claims.sql (24.45ms)12602026/10/01 10:11:49 OK 20260920000000_drop_claims.sql (26.51ms)12612026/10/01 10:11:49 OK 20260923120000_add_pushes.sql (18.98ms)12622026/10/01 10:11:49 goose: successfully migrated database to version: 2026092312000012632026/10/01 10:11:49 OK 20260923120000_add_pushes.sql (21.75ms)12642026/10/01 10:11:49 goose: successfully migrated database to version: 2026092312000012652026/10/01 10:11:49 OK 20260628120000_add_object_size_and_stats.sql (36.26ms)12662026/10/01 10:11:49 OK 1_commit_pending_closure.sql (7.03ms)12672026/10/01 10:11:49 OK 1_commit_pending_closure.sql (7.44ms)12682026/10/01 10:11:49 OK 2_object_stats_trigger.sql (2.68ms)12692026/10/01 10:11:49 OK 2_object_stats_trigger.sql (2.9ms)12702026/10/01 10:11:49 OK 3_commit_push.sql (1.04ms)12712026/10/01 10:11:49 goose: up to current file version: 312722026/10/01 10:11:49 OK 3_commit_push.sql (1.11ms)12732026/10/01 10:11:49 goose: up to current file version: 312742026/10/01 10:11:49 OK 20260905000000_add_claims.sql (10.24ms)12752026/10/01 10:11:49 OK 20260920000000_drop_claims.sql (3.34ms)12762026-10-01 10:11:49.467 UTC [12847] ERROR: relation "goose_db_version" does not exist at character 3612772026-10-01 10:11:49.467 UTC [12847] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12782026/10/01 10:11:49 OK 20260923120000_add_pushes.sql (5.43ms)12792026/10/01 10:11:49 goose: successfully migrated database to version: 2026092312000012802026/10/01 10:11:49 OK 1_commit_pending_closure.sql (2.59ms)12812026/10/01 10:11:49 OK 2_object_stats_trigger.sql (2.36ms)12822026/10/01 10:11:49 OK 3_commit_push.sql (457.58µs)12832026/10/01 10:11:49 goose: up to current file version: 312842026-10-01 10:11:49.540 UTC [12848] ERROR: relation "goose_db_version" does not exist at character 3612852026-10-01 10:11:49.540 UTC [12848] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12862026/10/01 10:11:49 OK 20241026095416_initial_model.sql (176.81ms)12872026/10/01 10:11:49 OK 20251210153512_drop_unused_gin_index.sql (11.3ms)12882026/10/01 10:11:49 OK 20251218171726_add_pins.sql (39.9ms)12892026/10/01 10:11:49 OK 20241026095416_initial_model.sql (170.41ms)12902026/10/01 10:11:49 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12912026/10/01 10:11:49 WARN Refused reserved pin name=worker-x86_64-linux12922026/10/01 10:11:49 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12932026/10/01 10:11:49 OK 20251210153512_drop_unused_gin_index.sql (14.52ms)12942026/10/01 10:11:49 INFO Received create pin request method=POST path=/api/pins/my-app12952026/10/01 10:11:49 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12962026-10-01 10:11:49.791 UTC [12849] ERROR: relation "goose_db_version" does not exist at character 3612972026-10-01 10:11:49.791 UTC [12849] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1298--- PASS: TestCreatePin_ReservedPins (1.98s)1299=== CONT TestPushDedupSurvivesConcurrentGC13002026/10/01 10:11:49 OK 20260628120000_add_object_size_and_stats.sql (32.54ms)13012026/10/01 10:11:49 OK 20251218171726_add_pins.sql (42.32ms)1302--- PASS: TestPresentNotReportedWhileGCDeletesClosure (2.39s)1303=== CONT TestGCMetrics13042026/10/01 10:11:49 OK 20260905000000_add_claims.sql (63.6ms)13052026/10/01 10:11:49 OK 20260628120000_add_object_size_and_stats.sql (42.32ms)13062026/10/01 10:11:49 OK 20260920000000_drop_claims.sql (41.03ms)13072026/10/01 10:11:49 OK 20260923120000_add_pushes.sql (11.22ms)13082026/10/01 10:11:49 goose: successfully migrated database to version: 2026092312000013092026/10/01 10:11:49 OK 20260905000000_add_claims.sql (46.35ms)13102026/10/01 10:11:49 OK 1_commit_pending_closure.sql (2.23ms)13112026/10/01 10:11:49 OK 2_object_stats_trigger.sql (457.96µs)13122026/10/01 10:11:49 OK 3_commit_push.sql (388.67µs)13132026/10/01 10:11:49 goose: up to current file version: 313142026/10/01 10:11:49 OK 20260920000000_drop_claims.sql (41.49ms)13152026/10/01 10:11:49 OK 20260923120000_add_pushes.sql (8.95ms)13162026/10/01 10:11:49 goose: successfully migrated database to version: 2026092312000013172026/10/01 10:11:49 OK 1_commit_pending_closure.sql (3.19ms)13182026/10/01 10:11:49 OK 2_object_stats_trigger.sql (624.21µs)13192026/10/01 10:11:49 OK 3_commit_push.sql (395.79µs)13202026/10/01 10:11:49 goose: up to current file version: 313212026/10/01 10:11:50 OK 20241026095416_initial_model.sql (161.21ms)13222026/10/01 10:11:50 OK 20251210153512_drop_unused_gin_index.sql (12.93ms)13232026/10/01 10:11:50 OK 20251218171726_add_pins.sql (41.86ms)1324--- PASS: TestPresentReportsOnlyClosureRoots (2.35s)1325=== CONT TestGCBugBareHashReferences13262026/10/01 10:11:50 OK 20260628120000_add_object_size_and_stats.sql (49.22ms)13272026/10/01 10:11:50 OK 20260905000000_add_claims.sql (86.26ms)13282026/10/01 10:11:50 OK 20260920000000_drop_claims.sql (28.28ms)13292026/10/01 10:11:50 OK 20260923120000_add_pushes.sql (17.88ms)13302026/10/01 10:11:50 goose: successfully migrated database to version: 2026092312000013312026/10/01 10:11:50 OK 1_commit_pending_closure.sql (4.63ms)13322026/10/01 10:11:50 OK 2_object_stats_trigger.sql (819.33µs)13332026/10/01 10:11:50 OK 3_commit_push.sql (586.63µs)13342026/10/01 10:11:50 goose: up to current file version: 313352026-10-01 10:11:50.371 UTC [12856] ERROR: relation "goose_db_version" does not exist at character 3613362026-10-01 10:11:50.371 UTC [12856] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13372026/10/01 10:11:50 OK 20241026095416_initial_model.sql (230.16ms)13382026/10/01 10:11:50 OK 20251210153512_drop_unused_gin_index.sql (28.56ms)13392026/10/01 10:11:50 OK 20251218171726_add_pins.sql (45.12ms)13402026/10/01 10:11:50 OK 20260628120000_add_object_size_and_stats.sql (55.33ms)1341--- PASS: TestObjectStatsTrigger (2.61s)1342=== CONT TestLeadEndsOnShutdown13432026/10/01 10:11:50 OK 20260905000000_add_claims.sql (75.13ms)13442026/10/01 10:11:50 OK 20260920000000_drop_claims.sql (55.47ms)13452026-10-01 10:11:50.959 UTC [12859] ERROR: relation "goose_db_version" does not exist at character 3613462026-10-01 10:11:50.959 UTC [12859] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13472026/10/01 10:11:51 OK 20260923120000_add_pushes.sql (89.45ms)13482026/10/01 10:11:51 goose: successfully migrated database to version: 2026092312000013492026/10/01 10:11:51 OK 1_commit_pending_closure.sql (4.74ms)13502026/10/01 10:11:51 OK 2_object_stats_trigger.sql (964.92µs)13512026/10/01 10:11:51 OK 3_commit_push.sql (578.92µs)13522026/10/01 10:11:51 goose: up to current file version: 313532026/10/01 10:11:51 OK 20241026095416_initial_model.sql (240.19ms)13542026/10/01 10:11:51 OK 20251210153512_drop_unused_gin_index.sql (15.33ms)13552026/10/01 10:11:51 OK 20251218171726_add_pins.sql (67.11ms)13562026-10-01 10:11:51.435 UTC [12860] ERROR: relation "goose_db_version" does not exist at character 3613572026-10-01 10:11:51.435 UTC [12860] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13582026/10/01 10:11:51 OK 20260628120000_add_object_size_and_stats.sql (53.48ms)13592026/10/01 10:11:51 INFO Received uploads request method=POST path=/api/pending_closures13602026/10/01 10:11:51 OK 20260905000000_add_claims.sql (28.68ms)13612026/10/01 10:11:51 OK 20260920000000_drop_claims.sql (25.65ms)13622026/10/01 10:11:51 OK 20260923120000_add_pushes.sql (28.35ms)13632026/10/01 10:11:51 goose: successfully migrated database to version: 2026092312000013642026/10/01 10:11:51 OK 1_commit_pending_closure.sql (4.7ms)13652026/10/01 10:11:51 OK 2_object_stats_trigger.sql (1.01ms)13662026/10/01 10:11:51 OK 3_commit_push.sql (582µs)13672026/10/01 10:11:51 goose: up to current file version: 313682026/10/01 10:11:51 INFO Received uploads request method=POST path=/api/pending_closures13692026/10/01 10:11:51 INFO Received cleanup request method=DELETE path=/api/pending_closures13702026/10/01 10:11:51 OK 20241026095416_initial_model.sql (273.68ms)13712026/10/01 10:11:51 OK 20251210153512_drop_unused_gin_index.sql (17.19ms)13722026/10/01 10:11:51 OK 20251218171726_add_pins.sql (45.1ms)13732026/10/01 10:11:51 INFO Received uploads request method=POST path=/api/pending_closures13742026/10/01 10:11:51 OK 20260628120000_add_object_size_and_stats.sql (53.65ms)1375--- PASS: TestTombstonedObjectOfferedWithoutWaiting (3.28s)1376=== CONT TestLeadElectsOneAndHandsOver13772026/10/01 10:11:51 OK 20260905000000_add_claims.sql (75.17ms)13782026/10/01 10:11:51 OK 20260920000000_drop_claims.sql (35.47ms)1379=== NAME TestOrphanedObjectsGC1380 orphaned_objects_gc_test.go:290: GC Test Summary:1381 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1382 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1383 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1384 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1385 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1386--- PASS: TestOrphanedObjectsGC (3.79s)1387=== CONT TestClientErrorHandling1388=== RUN TestClientErrorHandling/InvalidStorePath1389=== PAUSE TestClientErrorHandling/InvalidStorePath1390=== RUN TestClientErrorHandling/InvalidAuthToken1391=== PAUSE TestClientErrorHandling/InvalidAuthToken1392=== RUN TestClientErrorHandling/ServerNotAvailable1393=== PAUSE TestClientErrorHandling/ServerNotAvailable1394=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13952026/10/01 10:11:52 OK 20260923120000_add_pushes.sql (29.64ms)13962026/10/01 10:11:52 goose: successfully migrated database to version: 2026092312000013972026/10/01 10:11:52 OK 1_commit_pending_closure.sql (2.2ms)13982026/10/01 10:11:52 OK 2_object_stats_trigger.sql (521.17µs)13992026/10/01 10:11:52 OK 3_commit_push.sql (334.96µs)14002026/10/01 10:11:52 goose: up to current file version: 314012026/10/01 10:11:52 INFO Received uploads request method=POST path=/api/pending_closures14022026/10/01 10:11:52 INFO Aborted multipart uploads count=0 kept=014032026/10/01 10:11:52 WARN Force mode enabled - objects will be deleted immediately without grace period14042026/10/01 10:11:52 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=014052026/10/01 10:11:52 INFO Vacuumed table table=pending_closures14062026/10/01 10:11:52 INFO Vacuumed table table=pending_objects14072026/10/01 10:11:52 INFO Vacuumed table table=multipart_uploads14082026/10/01 10:11:52 INFO Vacuumed table table=closures14092026/10/01 10:11:52 INFO Vacuumed table table=objects1410--- PASS: TestGCSweepSkipsPendingObjects (3.61s)1411=== CONT TestClientFallsBackToClosures14122026/10/01 10:11:52 INFO Received uploads request method=POST path=/api/pending_closures1413--- PASS: TestDeduplicatedObjectsRecordedAsPending (3.55s)1414=== CONT TestClientPushesUseOnePush14152026-10-01 10:11:52.745 UTC [12869] ERROR: relation "goose_db_version" does not exist at character 3614162026-10-01 10:11:52.745 UTC [12869] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14172026-10-01 10:11:52.753 UTC [12871] ERROR: relation "goose_db_version" does not exist at character 3614182026-10-01 10:11:52.753 UTC [12871] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14192026-10-01 10:11:52.946 UTC [12872] ERROR: relation "goose_db_version" does not exist at character 3614202026-10-01 10:11:52.946 UTC [12872] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14212026/10/01 10:11:52 OK 20241026095416_initial_model.sql (153.55ms)14222026/10/01 10:11:52 OK 20251210153512_drop_unused_gin_index.sql (10.13ms)14232026/10/01 10:11:52 OK 20241026095416_initial_model.sql (182.75ms)14242026/10/01 10:11:53 OK 20251210153512_drop_unused_gin_index.sql (15.31ms)14252026/10/01 10:11:53 OK 20251218171726_add_pins.sql (43.46ms)14262026/10/01 10:11:53 OK 20251218171726_add_pins.sql (19.21ms)14272026/10/01 10:11:53 OK 20260628120000_add_object_size_and_stats.sql (44.5ms)14282026/10/01 10:11:53 OK 20260628120000_add_object_size_and_stats.sql (42.61ms)14292026/10/01 10:11:53 OK 20260905000000_add_claims.sql (38.72ms)14302026/10/01 10:11:53 OK 20260920000000_drop_claims.sql (19.11ms)14312026/10/01 10:11:53 OK 20260905000000_add_claims.sql (50.5ms)14322026/10/01 10:11:53 OK 20260923120000_add_pushes.sql (7.4ms)14332026/10/01 10:11:53 goose: successfully migrated database to version: 2026092312000014342026/10/01 10:11:53 OK 1_commit_pending_closure.sql (4.46ms)14352026/10/01 10:11:53 OK 2_object_stats_trigger.sql (777.54µs)14362026/10/01 10:11:53 OK 3_commit_push.sql (467.67µs)14372026/10/01 10:11:53 goose: up to current file version: 314382026/10/01 10:11:53 OK 20260920000000_drop_claims.sql (27.17ms)14392026/10/01 10:11:53 OK 20260923120000_add_pushes.sql (32.97ms)14402026/10/01 10:11:53 goose: successfully migrated database to version: 2026092312000014412026/10/01 10:11:53 OK 20241026095416_initial_model.sql (153.56ms)14422026/10/01 10:11:53 OK 1_commit_pending_closure.sql (4.31ms)14432026/10/01 10:11:53 OK 2_object_stats_trigger.sql (675.92µs)14442026/10/01 10:11:53 OK 3_commit_push.sql (515µs)14452026/10/01 10:11:53 goose: up to current file version: 314462026/10/01 10:11:53 OK 20251210153512_drop_unused_gin_index.sql (17.05ms)14472026/10/01 10:11:53 OK 20251218171726_add_pins.sql (27.4ms)14482026/10/01 10:11:53 OK 20260628120000_add_object_size_and_stats.sql (28.84ms)14492026/10/01 10:11:53 OK 20260905000000_add_claims.sql (58.01ms)14502026/10/01 10:11:53 OK 20260920000000_drop_claims.sql (41.37ms)14512026/10/01 10:11:53 OK 20260923120000_add_pushes.sql (10.09ms)14522026/10/01 10:11:53 goose: successfully migrated database to version: 2026092312000014532026/10/01 10:11:53 OK 1_commit_pending_closure.sql (3.1ms)14542026/10/01 10:11:53 OK 2_object_stats_trigger.sql (613.13µs)14552026/10/01 10:11:53 OK 3_commit_push.sql (464µs)14562026/10/01 10:11:53 goose: up to current file version: 314572026-10-01 10:11:53.372 UTC [12873] ERROR: relation "goose_db_version" does not exist at character 3614582026-10-01 10:11:53.372 UTC [12873] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14592026/10/01 10:11:53 INFO Received uploads request method=POST path=/api/pending_closures14602026/10/01 10:11:53 OK 20241026095416_initial_model.sql (144.58ms)14612026/10/01 10:11:53 OK 20251210153512_drop_unused_gin_index.sql (15.84ms)14622026/10/01 10:11:53 OK 20251218171726_add_pins.sql (31.18ms)14632026/10/01 10:11:53 INFO Aborted multipart uploads count=0 kept=014642026/10/01 10:11:53 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014652026/10/01 10:11:53 INFO Vacuumed table table=pending_closures14662026/10/01 10:11:53 OK 20260628120000_add_object_size_and_stats.sql (48.67ms)14672026/10/01 10:11:53 INFO Aborted multipart uploads count=0 kept=014682026/10/01 10:11:53 INFO Vacuumed table table=pending_objects14692026/10/01 10:11:53 WARN Force mode enabled - objects will be deleted immediately without grace period14702026/10/01 10:11:53 INFO Vacuumed table table=multipart_uploads14712026/10/01 10:11:53 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=014722026/10/01 10:11:53 INFO Vacuumed table table=pending_closures14732026/10/01 10:11:53 INFO Vacuumed table table=pending_objects14742026/10/01 10:11:53 INFO Vacuumed table table=multipart_uploads14752026/10/01 10:11:53 INFO Vacuumed table table=closures14762026/10/01 10:11:53 INFO Vacuumed table table=objects1477--- PASS: TestGCMetrics (3.86s)1478=== CONT TestPinProtectsFromGC14792026/10/01 10:11:53 INFO Vacuumed table table=closures14802026/10/01 10:11:53 INFO Vacuumed table table=objects14812026/10/01 10:11:53 OK 20260905000000_add_claims.sql (47.42ms)14822026/10/01 10:11:53 INFO Aborted multipart uploads count=0 kept=014832026/10/01 10:11:53 WARN Force mode enabled - objects will be deleted immediately without grace period14842026/10/01 10:11:53 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=014852026/10/01 10:11:53 INFO Vacuumed table table=pending_closures14862026/10/01 10:11:53 OK 20260920000000_drop_claims.sql (35.44ms)14872026/10/01 10:11:53 INFO Vacuumed table table=pending_objects14882026/10/01 10:11:53 INFO Vacuumed table table=multipart_uploads14892026/10/01 10:11:53 INFO Vacuumed table table=closures14902026/10/01 10:11:53 OK 20260923120000_add_pushes.sql (15.34ms)14912026/10/01 10:11:53 goose: successfully migrated database to version: 2026092312000014922026/10/01 10:11:53 INFO Vacuumed table table=objects14932026/10/01 10:11:53 OK 1_commit_pending_closure.sql (2.7ms)14942026/10/01 10:11:53 OK 2_object_stats_trigger.sql (554.67µs)14952026/10/01 10:11:53 OK 3_commit_push.sql (324.42µs)14962026/10/01 10:11:53 goose: up to current file version: 31497--- PASS: TestPushDedupSurvivesConcurrentGC (3.99s)1498=== CONT TestClientSharedPathCommittedMidPush14992026-10-01 10:11:54.024 UTC [12880] ERROR: relation "goose_db_version" does not exist at character 3615002026-10-01 10:11:54.024 UTC [12880] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1501--- PASS: TestGCBugBareHashReferences (4.15s)1502=== CONT TestClientWithDependencies15032026/10/01 10:11:54 INFO lead: acquired remote=192.0.2.1:123415042026/10/01 10:11:54 INFO lead: released remote=192.0.2.1:12341505--- PASS: TestLeadEndsOnShutdown (3.44s)1506=== CONT TestClientMultipleUploads15072026/10/01 10:11:54 OK 20241026095416_initial_model.sql (186.57ms)15082026/10/01 10:11:54 OK 20251210153512_drop_unused_gin_index.sql (8.85ms)15092026/10/01 10:11:54 OK 20251218171726_add_pins.sql (19.05ms)15102026-10-01 10:11:54.327 UTC [12884] ERROR: relation "goose_db_version" does not exist at character 3615112026-10-01 10:11:54.327 UTC [12884] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15122026/10/01 10:11:54 OK 20260628120000_add_object_size_and_stats.sql (19.8ms)15132026/10/01 10:11:54 OK 20260905000000_add_claims.sql (28.22ms)15142026/10/01 10:11:54 OK 20260920000000_drop_claims.sql (18.66ms)15152026/10/01 10:11:54 OK 20260923120000_add_pushes.sql (10.08ms)15162026/10/01 10:11:54 goose: successfully migrated database to version: 2026092312000015172026-10-01 10:11:54.396 UTC [12886] ERROR: relation "goose_db_version" does not exist at character 3615182026-10-01 10:11:54.396 UTC [12886] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15192026/10/01 10:11:54 OK 1_commit_pending_closure.sql (3.04ms)15202026/10/01 10:11:54 OK 2_object_stats_trigger.sql (574.13µs)15212026/10/01 10:11:54 OK 3_commit_push.sql (411.46µs)15222026/10/01 10:11:54 goose: up to current file version: 315232026-10-01 10:11:54.449 UTC [12887] ERROR: relation "goose_db_version" does not exist at character 3615242026-10-01 10:11:54.449 UTC [12887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15252026/10/01 10:11:54 OK 20241026095416_initial_model.sql (113.07ms)15262026/10/01 10:11:54 OK 20251210153512_drop_unused_gin_index.sql (12.69ms)15272026/10/01 10:11:54 OK 20251218171726_add_pins.sql (14.81ms)15282026/10/01 10:11:54 OK 20241026095416_initial_model.sql (106.55ms)15292026/10/01 10:11:54 OK 20260628120000_add_object_size_and_stats.sql (40.78ms)15302026/10/01 10:11:54 OK 20251210153512_drop_unused_gin_index.sql (22.27ms)15312026/10/01 10:11:54 OK 20251218171726_add_pins.sql (22.06ms)15322026/10/01 10:11:54 OK 20260905000000_add_claims.sql (52.95ms)15332026/10/01 10:11:54 OK 20260920000000_drop_claims.sql (35.11ms)15342026/10/01 10:11:54 OK 20260628120000_add_object_size_and_stats.sql (62.31ms)15352026/10/01 10:11:54 OK 20260923120000_add_pushes.sql (11.6ms)15362026/10/01 10:11:54 goose: successfully migrated database to version: 2026092312000015372026/10/01 10:11:54 OK 1_commit_pending_closure.sql (4.02ms)15382026/10/01 10:11:54 OK 2_object_stats_trigger.sql (774.29µs)15392026/10/01 10:11:54 OK 3_commit_push.sql (540.54µs)15402026/10/01 10:11:54 goose: up to current file version: 315412026/10/01 10:11:54 OK 20260905000000_add_claims.sql (38.06ms)15422026/10/01 10:11:54 OK 20241026095416_initial_model.sql (168.36ms)15432026/10/01 10:11:54 INFO lead: acquired remote=192.0.2.1:123415442026/10/01 10:11:54 OK 20251210153512_drop_unused_gin_index.sql (15.13ms)15452026/10/01 10:11:54 OK 20260920000000_drop_claims.sql (35.54ms)15462026/10/01 10:11:54 OK 20251218171726_add_pins.sql (28.13ms)15472026/10/01 10:11:54 OK 20260923120000_add_pushes.sql (23.59ms)15482026/10/01 10:11:54 goose: successfully migrated database to version: 2026092312000015492026/10/01 10:11:54 OK 1_commit_pending_closure.sql (5.53ms)15502026/10/01 10:11:54 OK 2_object_stats_trigger.sql (905.71µs)15512026/10/01 10:11:54 OK 3_commit_push.sql (533.25µs)15522026/10/01 10:11:54 goose: up to current file version: 315532026/10/01 10:11:54 OK 20260628120000_add_object_size_and_stats.sql (31.43ms)15542026/10/01 10:11:54 OK 20260905000000_add_claims.sql (46.92ms)15552026/10/01 10:11:54 OK 20260920000000_drop_claims.sql (29.28ms)15562026/10/01 10:11:54 INFO lead: released remote=192.0.2.1:123415572026/10/01 10:11:54 OK 20260923120000_add_pushes.sql (19.83ms)15582026/10/01 10:11:54 goose: successfully migrated database to version: 2026092312000015592026/10/01 10:11:54 OK 1_commit_pending_closure.sql (5.23ms)15602026/10/01 10:11:54 OK 2_object_stats_trigger.sql (818.25µs)15612026/10/01 10:11:54 OK 3_commit_push.sql (564.92µs)15622026/10/01 10:11:54 goose: up to current file version: 315632026/10/01 10:11:54 INFO lead: acquired remote=192.0.2.1:123415642026/10/01 10:11:54 INFO lead: released remote=192.0.2.1:12341565--- PASS: TestLeadElectsOneAndHandsOver (2.97s)1566=== CONT TestClientIntegration15672026-10-01 10:11:55.531 UTC [12896] ERROR: relation "goose_db_version" does not exist at character 3615682026-10-01 10:11:55.531 UTC [12896] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15692026-10-01 10:11:55.561 UTC [12899] ERROR: relation "goose_db_version" does not exist at character 3615702026-10-01 10:11:55.561 UTC [12899] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15712026/10/01 10:11:55 OK 20241026095416_initial_model.sql (66.2ms)15722026/10/01 10:11:55 OK 20251210153512_drop_unused_gin_index.sql (7.63ms)15732026/10/01 10:11:55 OK 20241026095416_initial_model.sql (60.28ms)15742026-10-01 10:11:55.664 UTC [12905] ERROR: relation "goose_db_version" does not exist at character 3615752026-10-01 10:11:55.664 UTC [12905] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15762026/10/01 10:11:55 OK 20251210153512_drop_unused_gin_index.sql (2.35ms)15772026/10/01 10:11:55 OK 20251218171726_add_pins.sql (17.77ms)15782026/10/01 10:11:55 OK 20251218171726_add_pins.sql (2.87ms)15792026/10/01 10:11:55 OK 20260628120000_add_object_size_and_stats.sql (15.38ms)15802026-10-01 10:11:55.686 UTC [12907] ERROR: relation "goose_db_version" does not exist at character 3615812026-10-01 10:11:55.686 UTC [12907] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15822026/10/01 10:11:55 OK 20260628120000_add_object_size_and_stats.sql (19.32ms)15832026/10/01 10:11:55 OK 20260905000000_add_claims.sql (12.78ms)15842026/10/01 10:11:55 OK 20260905000000_add_claims.sql (15.03ms)15852026/10/01 10:11:55 OK 20260920000000_drop_claims.sql (16.83ms)15862026/10/01 10:11:55 INFO Received uploads request method=POST path=/api/pending_closures15872026/10/01 10:11:55 OK 20260923120000_add_pushes.sql (8.07ms)15882026/10/01 10:11:55 goose: successfully migrated database to version: 2026092312000015892026/10/01 10:11:55 OK 20260920000000_drop_claims.sql (16.14ms)15902026/10/01 10:11:55 OK 1_commit_pending_closure.sql (1.3ms)15912026/10/01 10:11:55 OK 2_object_stats_trigger.sql (213.17µs)15922026/10/01 10:11:55 OK 3_commit_push.sql (193.79µs)15932026/10/01 10:11:55 goose: up to current file version: 315942026/10/01 10:11:55 OK 20260923120000_add_pushes.sql (8.69ms)15952026/10/01 10:11:55 goose: successfully migrated database to version: 2026092312000015962026/10/01 10:11:55 OK 1_commit_pending_closure.sql (845.58µs)15972026/10/01 10:11:55 OK 2_object_stats_trigger.sql (217.21µs)15982026/10/01 10:11:55 OK 3_commit_push.sql (211.5µs)15992026/10/01 10:11:55 goose: up to current file version: 316002026/10/01 10:11:55 INFO Received uploads request method=POST path=/api/pending_closures16012026/10/01 10:11:55 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16022026/10/01 10:11:55 INFO Uploading ip7r8a0gmz4h122cp8b11jxbvvlylvxr-shared-dep (136B)16032026/10/01 10:11:55 INFO Uploading k8vawwz5lb6737xl2nf31mk3jb5hychg-b (248B)16042026/10/01 10:11:55 WARN Failed to register uploaded object key=26wx8s2iskkg554bpj466jvl0hhwsqzw.ls error="server returned 404: 404 page not found\n"16052026/10/01 10:11:55 WARN Failed to register uploaded object key=nar/16ckcb53inclsk8a7hpqi99fc60gvy7hlr28fy6dhcsrd009aznn.nar.zst error="server returned 404: 404 page not found\n"16062026/10/01 10:11:55 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16072026/10/01 10:11:55 WARN Failed to register uploaded object key=ip7r8a0gmz4h122cp8b11jxbvvlylvxr.ls error="server returned 404: 404 page not found\n"16082026/10/01 10:11:55 WARN Failed to register uploaded object key=k8vawwz5lb6737xl2nf31mk3jb5hychg.ls error="server returned 404: 404 page not found\n"16092026/10/01 10:11:55 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16102026/10/01 10:11:55 INFO Signed narinfos id=1 count=216112026/10/01 10:11:55 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16122026/10/01 10:11:55 INFO Signed narinfos id=2 count=216132026/10/01 10:11:55 INFO Uploading 4 narinfos16142026/10/01 10:11:55 OK 20241026095416_initial_model.sql (94.78ms)16152026/10/01 10:11:55 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)16162026/10/01 10:11:55 WARN Failed to register uploaded object key=26wx8s2iskkg554bpj466jvl0hhwsqzw.narinfo error="server returned 404: 404 page not found\n"16172026/10/01 10:11:55 WARN Failed to register uploaded object key=k8vawwz5lb6737xl2nf31mk3jb5hychg.narinfo error="server returned 404: 404 page not found\n"16182026/10/01 10:11:55 WARN Failed to register uploaded object key=ip7r8a0gmz4h122cp8b11jxbvvlylvxr.narinfo error="server returned 404: 404 page not found\n"16192026/10/01 10:11:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16202026/10/01 10:11:55 WARN Failed to register uploaded object key=ip7r8a0gmz4h122cp8b11jxbvvlylvxr.narinfo error="server returned 404: 404 page not found\n"16212026/10/01 10:11:55 OK 20251218171726_add_pins.sql (22.56ms)16222026/10/01 10:11:55 INFO Completed upload id=116232026/10/01 10:11:55 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16242026/10/01 10:11:55 INFO Completed upload id=216252026/10/01 10:11:55 OK 20260628120000_add_object_size_and_stats.sql (22.36ms)16262026/10/01 10:11:55 INFO Upload complete. (159ms)16272026/10/01 10:11:55 OK 20241026095416_initial_model.sql (107.07ms)1628=== NAME TestClientFallsBackToClosures1629 client_pushes_test.go:112: Retrieved narinfo from S3:1630 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestClientFallsBackToClosures576561269/001/store/ip7r8a0gmz4h122cp8b11jxbvvlylvxr-shared-dep1631 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1632 Compression: zstd1633 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821634 NarSize: 1361635 References: 1636 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n16372026/10/01 10:11:55 INFO Received push request method=POST path=/api/pushes1638 client_pushes_test.go:112: Retrieved narinfo from S3:1639 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestClientFallsBackToClosures576561269/001/store/26wx8s2iskkg554bpj466jvl0hhwsqzw-a1640 URL: nar/16ckcb53inclsk8a7hpqi99fc60gvy7hlr28fy6dhcsrd009aznn.nar.zst1641 Compression: zstd1642 NarHash: sha256:16ckcb53inclsk8a7hpqi99fc60gvy7hlr28fy6dhcsrd009aznn1643 NarSize: 2481644 References: /nix/var/nix/builds/nix-12646-3956915670/TestClientFallsBackToClosures576561269/001/store/ip7r8a0gmz4h122cp8b11jxbvvlylvxr-shared-dep1645 CA: text:sha256:176bbdq8hpx08baqjwyvdp8s4ija8g82zics77qhl1rkbq82i1g31646 client_pushes_test.go:112: Retrieved narinfo from S3:1647 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestClientFallsBackToClosures576561269/001/store/k8vawwz5lb6737xl2nf31mk3jb5hychg-b1648 URL: nar/16ckcb53inclsk8a7hpqi99fc60gvy7hlr28fy6dhcsrd009aznn.nar.zst1649 Compression: zstd1650 NarHash: sha256:16ckcb53inclsk8a7hpqi99fc60gvy7hlr28fy6dhcsrd009aznn1651 NarSize: 2481652 References: /nix/var/nix/builds/nix-12646-3956915670/TestClientFallsBackToClosures576561269/001/store/ip7r8a0gmz4h122cp8b11jxbvvlylvxr-shared-dep1653 CA: text:sha256:176bbdq8hpx08baqjwyvdp8s4ija8g82zics77qhl1rkbq82i1g316542026/10/01 10:11:55 OK 20251210153512_drop_unused_gin_index.sql (4.93ms)16552026/10/01 10:11:55 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16562026/10/01 10:11:55 INFO Uploading jxmqjwdh3cc16w5igpicic9gv5v41s7n-shared-dep (136B)16572026/10/01 10:11:55 INFO Uploading i3jxivvx7l3xagfldglfxyhw14xcid4j-a (248B)16582026/10/01 10:11:55 OK 20251218171726_add_pins.sql (34.75ms)16592026/10/01 10:11:55 WARN Failed to register uploaded object key=nar/0sbryhlq4p4mq08gidjmnqzl5rcfwzivg4jyxmac48a0dhkxpawk.nar.zst error="server returned 404: 404 page not found\n"1660--- PASS: TestClientFallsBackToClosures (3.38s)1661=== CONT TestCompleteMultipartUpload_ErrorButObjectExists16622026/10/01 10:11:55 WARN Failed to register uploaded object key=f900wgi55sacivrh9mpw75fwb0qpjzir.ls error="server returned 404: 404 page not found\n"16632026/10/01 10:11:55 OK 20260905000000_add_claims.sql (47.66ms)16642026/10/01 10:11:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16652026/10/01 10:11:55 WARN Failed to register uploaded object key=jxmqjwdh3cc16w5igpicic9gv5v41s7n.ls error="server returned 404: 404 page not found\n"16662026/10/01 10:11:55 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16672026/10/01 10:11:55 WARN Failed to register uploaded object key=i3jxivvx7l3xagfldglfxyhw14xcid4j.ls error="server returned 404: 404 page not found\n"16682026/10/01 10:11:55 INFO Signed narinfos id=1 count=316692026/10/01 10:11:55 INFO Uploading 3 narinfos16702026/10/01 10:11:55 OK 20260628120000_add_object_size_and_stats.sql (17.88ms)16712026/10/01 10:11:55 WARN Failed to register uploaded object key=f900wgi55sacivrh9mpw75fwb0qpjzir.narinfo error="server returned 404: 404 page not found\n"16722026/10/01 10:11:55 INFO Received complete push request method=POST path=/api/pushes/1/complete16732026/10/01 10:11:55 WARN Failed to register uploaded object key=i3jxivvx7l3xagfldglfxyhw14xcid4j.narinfo error="server returned 404: 404 page not found\n"16742026/10/01 10:11:55 WARN Failed to register uploaded object key=jxmqjwdh3cc16w5igpicic9gv5v41s7n.narinfo error="server returned 404: 404 page not found\n"16752026/10/01 10:11:55 OK 20260920000000_drop_claims.sql (31.7ms)16762026/10/01 10:11:55 INFO Upload complete. (127ms)16772026/10/01 10:11:55 OK 20260905000000_add_claims.sql (28.32ms)1678=== NAME TestClientPushesUseOnePush1679 client_pushes_test.go:97: Retrieved narinfo from S3:1680 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestClientPushesUseOnePush613198566/001/store/jxmqjwdh3cc16w5igpicic9gv5v41s7n-shared-dep1681 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1682 Compression: zstd1683 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821684 NarSize: 1361685 References: 1686 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n16872026/10/01 10:11:55 OK 20260923120000_add_pushes.sql (7.43ms)16882026/10/01 10:11:55 goose: successfully migrated database to version: 202609231200001689 client_pushes_test.go:97: Retrieved narinfo from S3:1690 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestClientPushesUseOnePush613198566/001/store/i3jxivvx7l3xagfldglfxyhw14xcid4j-a1691 URL: nar/0sbryhlq4p4mq08gidjmnqzl5rcfwzivg4jyxmac48a0dhkxpawk.nar.zst1692 Compression: zstd1693 NarHash: sha256:0sbryhlq4p4mq08gidjmnqzl5rcfwzivg4jyxmac48a0dhkxpawk1694 NarSize: 2481695 References: /nix/var/nix/builds/nix-12646-3956915670/TestClientPushesUseOnePush613198566/001/store/jxmqjwdh3cc16w5igpicic9gv5v41s7n-shared-dep1696 CA: text:sha256:0bpzvv4ggqsfdjjhkknq2kgjqdmmd2yp6v983c1m1d6nhibn5x9016972026/10/01 10:11:55 OK 1_commit_pending_closure.sql (1.16ms)16982026/10/01 10:11:55 OK 2_object_stats_trigger.sql (239.08µs)1699 client_pushes_test.go:97: Retrieved narinfo from S3:1700 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestClientPushesUseOnePush613198566/001/store/f900wgi55sacivrh9mpw75fwb0qpjzir-b1701 URL: nar/0sbryhlq4p4mq08gidjmnqzl5rcfwzivg4jyxmac48a0dhkxpawk.nar.zst1702 Compression: zstd1703 NarHash: sha256:0sbryhlq4p4mq08gidjmnqzl5rcfwzivg4jyxmac48a0dhkxpawk1704 NarSize: 2481705 References: /nix/var/nix/builds/nix-12646-3956915670/TestClientPushesUseOnePush613198566/001/store/jxmqjwdh3cc16w5igpicic9gv5v41s7n-shared-dep1706 CA: text:sha256:0bpzvv4ggqsfdjjhkknq2kgjqdmmd2yp6v983c1m1d6nhibn5x9017072026/10/01 10:11:55 OK 3_commit_push.sql (174.46µs)17082026/10/01 10:11:55 goose: up to current file version: 317092026/10/01 10:11:55 OK 20260920000000_drop_claims.sql (24.76ms)17102026/10/01 10:11:55 OK 20260923120000_add_pushes.sql (14.17ms)17112026/10/01 10:11:55 goose: successfully migrated database to version: 2026092312000017122026/10/01 10:11:55 OK 1_commit_pending_closure.sql (946.33µs)17132026/10/01 10:11:55 OK 2_object_stats_trigger.sql (250.04µs)17142026/10/01 10:11:55 OK 3_commit_push.sql (4.93ms)17152026/10/01 10:11:55 goose: up to current file version: 31716--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (3.96s)1717=== CONT TestParseSize1718--- PASS: TestParseSize (0.00s)1719=== CONT TestService_Rustfstest1720--- PASS: TestClientPushesUseOnePush (3.31s)1721=== CONT TestPresignedUploadRegisteredBeforeCommit1722=== NAME TestPinProtectsFromGC1723 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-12646-3956915670/TestPinProtectsFromGC4020395655/001/store/xvzbn8adjzmzgvpx5mzzm67xjjibbn5d-pinned-file.txt1724 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-12646-3956915670/TestPinProtectsFromGC4020395655/001/store/shfgqd0s8zisv536q1wjnq1cynv6jlsb-unpinned-file.txt17252026-10-01 10:11:56.293 UTC [12930] ERROR: relation "goose_db_version" does not exist at character 3617262026-10-01 10:11:56.293 UTC [12930] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1727=== NAME TestOrphanedObjectsGCStressTest1728 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains17292026/10/01 10:11:56 INFO Received push request method=POST path=/api/pushes17302026/10/01 10:11:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17312026/10/01 10:11:56 INFO Uploading xvzbn8adjzmzgvpx5mzzm67xjjibbn5d-pinned-file.txt (128B)17322026/10/01 10:11:56 WARN Failed to register uploaded object key=xvzbn8adjzmzgvpx5mzzm67xjjibbn5d.ls error="server returned 404: 404 page not found\n"17332026/10/01 10:11:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17342026/10/01 10:11:56 INFO Signed narinfos id=1 count=117352026/10/01 10:11:56 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17362026/10/01 10:11:56 INFO Uploading 1 narinfos1737 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion17382026/10/01 10:11:56 INFO Received complete push request method=POST path=/api/pushes/1/complete17392026/10/01 10:11:56 WARN Failed to register uploaded object key=xvzbn8adjzmzgvpx5mzzm67xjjibbn5d.narinfo error="server returned 404: 404 page not found\n"17402026/10/01 10:11:56 INFO Upload complete. (124ms)17412026/10/01 10:11:56 OK 20241026095416_initial_model.sql (129.02ms)17422026/10/01 10:11:56 OK 20251210153512_drop_unused_gin_index.sql (9.29ms)17432026/10/01 10:11:56 INFO Received push request method=POST path=/api/pushes17442026/10/01 10:11:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17452026/10/01 10:11:56 INFO Uploading shfgqd0s8zisv536q1wjnq1cynv6jlsb-unpinned-file.txt (128B)17462026/10/01 10:11:56 OK 20251218171726_add_pins.sql (27.63ms)17472026/10/01 10:11:56 WARN Failed to register uploaded object key=shfgqd0s8zisv536q1wjnq1cynv6jlsb.ls error="server returned 404: 404 page not found\n"17482026/10/01 10:11:56 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17492026/10/01 10:11:56 INFO Signed narinfos id=2 count=117502026/10/01 10:11:56 INFO Uploading 1 narinfos17512026/10/01 10:11:56 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17522026/10/01 10:11:56 INFO Received complete push request method=POST path=/api/pushes/2/complete17532026/10/01 10:11:56 WARN Failed to register uploaded object key=shfgqd0s8zisv536q1wjnq1cynv6jlsb.narinfo error="server returned 404: 404 page not found\n"17542026/10/01 10:11:56 INFO Upload complete. (91ms)17552026/10/01 10:11:56 OK 20260628120000_add_object_size_and_stats.sql (31.38ms)17562026/10/01 10:11:56 INFO Received push request method=POST path=/api/pushes17572026/10/01 10:11:56 INFO Starting cleanup of old closures method=DELETE path=/api/closures17582026/10/01 10:11:56 INFO Garbage collection started17592026/10/01 10:11:56 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17602026/10/01 10:11:56 INFO Uploading zhb63867da78vsha0ak2cv811pqmyqf5-shared-dep (136B)17612026/10/01 10:11:56 INFO Uploading ky5f3qr9sd5fa3bvrfwgp27l9iczfr54-top (256B)17622026/10/01 10:11:56 INFO Aborted multipart uploads count=0 kept=017632026/10/01 10:11:56 WARN Force mode enabled - objects will be deleted immediately without grace period17642026/10/01 10:11:56 WARN Failed to register uploaded object key=zhb63867da78vsha0ak2cv811pqmyqf5.ls error="server returned 404: 404 page not found\n"17652026/10/01 10:11:56 OK 20260905000000_add_claims.sql (55.34ms)17662026/10/01 10:11:56 WARN Failed to register uploaded object key=ky5f3qr9sd5fa3bvrfwgp27l9iczfr54.ls error="server returned 404: 404 page not found\n"17672026/10/01 10:11:56 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17682026/10/01 10:11:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17692026/10/01 10:11:56 WARN Failed to register uploaded object key=nar/1y4l4vfi5ymyq0xdf5d34lpz94xkl0fqbwyymx938qyv4bz4dyhj.nar.zst error="server returned 404: 404 page not found\n"17702026/10/01 10:11:56 INFO Signed narinfos id=1 count=217712026/10/01 10:11:56 INFO Uploading 2 narinfos17722026/10/01 10:11:56 OK 20260920000000_drop_claims.sql (21.4ms)17732026/10/01 10:11:56 INFO Received complete push request method=POST path=/api/pushes/1/complete17742026/10/01 10:11:56 WARN Failed to register uploaded object key=zhb63867da78vsha0ak2cv811pqmyqf5.narinfo error="server returned 404: 404 page not found\n"17752026/10/01 10:11:56 WARN Failed to register uploaded object key=ky5f3qr9sd5fa3bvrfwgp27l9iczfr54.narinfo error="server returned 404: 404 page not found\n"17762026/10/01 10:11:56 OK 20260923120000_add_pushes.sql (11.6ms)17772026/10/01 10:11:56 goose: successfully migrated database to version: 2026092312000017782026/10/01 10:11:56 OK 1_commit_pending_closure.sql (917.83µs)17792026/10/01 10:11:56 OK 2_object_stats_trigger.sql (224.75µs)17802026/10/01 10:11:56 OK 3_commit_push.sql (171.33µs)17812026/10/01 10:11:56 goose: up to current file version: 317822026/10/01 10:11:56 INFO Upload complete. (137ms)1783=== NAME TestClientSharedPathCommittedMidPush1784 client_integration_test.go:680: Retrieved narinfo from S3:1785 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestClientSharedPathCommittedMidPush1871855165/001/store/zhb63867da78vsha0ak2cv811pqmyqf5-shared-dep1786 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1787 Compression: zstd1788 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821789 NarSize: 1361790 References: 1791 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1792 client_integration_test.go:680: Retrieved narinfo from S3:1793 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestClientSharedPathCommittedMidPush1871855165/001/store/ky5f3qr9sd5fa3bvrfwgp27l9iczfr54-top1794 URL: nar/1y4l4vfi5ymyq0xdf5d34lpz94xkl0fqbwyymx938qyv4bz4dyhj.nar.zst1795 Compression: zstd1796 NarHash: sha256:1y4l4vfi5ymyq0xdf5d34lpz94xkl0fqbwyymx938qyv4bz4dyhj1797 NarSize: 2561798 References: /nix/var/nix/builds/nix-12646-3956915670/TestClientSharedPathCommittedMidPush1871855165/001/store/zhb63867da78vsha0ak2cv811pqmyqf5-shared-dep1799 CA: text:sha256:0p2vaq1cls20zzb73z9ii1g2nj2874kni3hbqnw14b2k6prfdw2j18002026/10/01 10:11:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=01801=== NAME TestClientMultipleUploads1802 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-12646-3956915670/TestClientMultipleUploads272397165/001/store/8xqci1y8vyyj7d9yw93w7c9558n929pv-test-file-0.txt18032026/10/01 10:11:56 INFO Vacuumed table table=pending_closures1804--- PASS: TestClientSharedPathCommittedMidPush (2.90s)1805=== CONT TestCompletedNarNotReofferedAcrossClosures18062026/10/01 10:11:56 INFO Vacuumed table table=pending_objects18072026/10/01 10:11:56 INFO Vacuumed table table=multipart_uploads18082026/10/01 10:11:56 INFO Vacuumed table table=closures1809=== NAME TestClientMultipleUploads1810 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-12646-3956915670/TestClientMultipleUploads272397165/001/store/51f9i77rfpfnafm2ckn8pwkxzrvw4qn4-test-file-1.txt18112026/10/01 10:11:56 INFO Vacuumed table table=objects1812 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-12646-3956915670/TestClientMultipleUploads272397165/001/store/kwbyyqzjfqzyzf8cpa9ns67ayika7mvc-test-file-2.txt18132026/10/01 10:11:56 INFO Received push request method=POST path=/api/pushes18142026/10/01 10:11:56 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18152026/10/01 10:11:56 INFO Uploading kwbyyqzjfqzyzf8cpa9ns67ayika7mvc-test-file-2.txt (160B)18162026/10/01 10:11:56 INFO Uploading 51f9i77rfpfnafm2ckn8pwkxzrvw4qn4-test-file-1.txt (160B)18172026/10/01 10:11:56 INFO Uploading 8xqci1y8vyyj7d9yw93w7c9558n929pv-test-file-0.txt (160B)18182026/10/01 10:11:56 WARN Failed to register uploaded object key=8xqci1y8vyyj7d9yw93w7c9558n929pv.ls error="server returned 404: 404 page not found\n"18192026/10/01 10:11:56 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18202026/10/01 10:11:56 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18212026/10/01 10:11:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18222026/10/01 10:11:56 WARN Failed to register uploaded object key=51f9i77rfpfnafm2ckn8pwkxzrvw4qn4.ls error="server returned 404: 404 page not found\n"18232026/10/01 10:11:56 WARN Failed to register uploaded object key=kwbyyqzjfqzyzf8cpa9ns67ayika7mvc.ls error="server returned 404: 404 page not found\n"18242026/10/01 10:11:56 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18252026/10/01 10:11:56 INFO Signed narinfos id=1 count=318262026/10/01 10:11:56 INFO Uploading 3 narinfos18272026/10/01 10:11:56 WARN Failed to register uploaded object key=8xqci1y8vyyj7d9yw93w7c9558n929pv.narinfo error="server returned 404: 404 page not found\n"18282026/10/01 10:11:56 INFO Received complete push request method=POST path=/api/pushes/1/complete18292026/10/01 10:11:56 WARN Failed to register uploaded object key=kwbyyqzjfqzyzf8cpa9ns67ayika7mvc.narinfo error="server returned 404: 404 page not found\n"18302026/10/01 10:11:56 WARN Failed to register uploaded object key=51f9i77rfpfnafm2ckn8pwkxzrvw4qn4.narinfo error="server returned 404: 404 page not found\n"18312026/10/01 10:11:56 INFO Upload complete. (82ms)1832 client_integration_test.go:369: Uploaded 3 paths in 117.307ms1833=== CONT TestService_RequireScope_OIDC1834--- PASS: TestClientMultipleUploads (2.69s)1835=== NAME TestClientIntegration1836 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-12646-3956915670/TestClientIntegration1283115790/002/store/igypz0ihpsb5ry3xs79yi3gy3dnj58b8-test-file.txt1837=== NAME TestClientWithDependencies1838 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-12646-3956915670/TestClientWithDependencies643160747/001/store/arsqxfy3d47m27a32w6h13kf0hbpgw6j-test-script18392026-10-01 10:11:56.974 UTC [12971] ERROR: relation "goose_db_version" does not exist at character 3618402026-10-01 10:11:56.974 UTC [12971] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18412026-10-01 10:11:56.982 UTC [12972] ERROR: relation "goose_db_version" does not exist at character 3618422026-10-01 10:11:56.982 UTC [12972] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18432026-10-01 10:11:56.983 UTC [12973] ERROR: relation "goose_db_version" does not exist at character 3618442026-10-01 10:11:56.983 UTC [12973] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18452026/10/01 10:11:57 OK 20241026095416_initial_model.sql (5.74ms)18462026/10/01 10:11:57 OK 20241026095416_initial_model.sql (6.02ms)18472026/10/01 10:11:57 OK 20241026095416_initial_model.sql (6.56ms)18482026/10/01 10:11:57 OK 20251210153512_drop_unused_gin_index.sql (577.88µs)18492026/10/01 10:11:57 OK 20251210153512_drop_unused_gin_index.sql (851.71µs)18502026/10/01 10:11:57 OK 20251210153512_drop_unused_gin_index.sql (655.29µs)18512026/10/01 10:11:57 OK 20251218171726_add_pins.sql (1.22ms)18522026/10/01 10:11:57 OK 20251218171726_add_pins.sql (964.29µs)18532026/10/01 10:11:57 OK 20251218171726_add_pins.sql (2.24ms)18542026/10/01 10:11:57 OK 20260628120000_add_object_size_and_stats.sql (1.52ms)18552026/10/01 10:11:57 OK 20260628120000_add_object_size_and_stats.sql (2.21ms)18562026/10/01 10:11:57 OK 20260628120000_add_object_size_and_stats.sql (1.72ms)18572026/10/01 10:11:57 OK 20260905000000_add_claims.sql (1.59ms)18582026/10/01 10:11:57 OK 20260920000000_drop_claims.sql (1.25ms)18592026/10/01 10:11:57 OK 20260905000000_add_claims.sql (1.58ms)18602026/10/01 10:11:57 OK 20260920000000_drop_claims.sql (803µs)18612026/10/01 10:11:57 OK 20260923120000_add_pushes.sql (398µs)18622026/10/01 10:11:57 goose: successfully migrated database to version: 2026092312000018632026/10/01 10:11:57 OK 1_commit_pending_closure.sql (853.46µs)18642026/10/01 10:11:57 OK 20260905000000_add_claims.sql (4.41ms)18652026/10/01 10:11:57 OK 2_object_stats_trigger.sql (376.83µs)18662026/10/01 10:11:57 OK 20260923120000_add_pushes.sql (2.69ms)18672026/10/01 10:11:57 goose: successfully migrated database to version: 2026092312000018682026/10/01 10:11:57 OK 3_commit_push.sql (228.33µs)18692026/10/01 10:11:57 goose: up to current file version: 318702026/10/01 10:11:57 OK 20260920000000_drop_claims.sql (1.14ms)18712026/10/01 10:11:57 OK 1_commit_pending_closure.sql (1.13ms)1872 client_integration_test.go:615: Found 1 dependencies (including self)18732026/10/01 10:11:57 OK 2_object_stats_trigger.sql (401.13µs)18742026/10/01 10:11:57 OK 20260923120000_add_pushes.sql (1.39ms)18752026/10/01 10:11:57 goose: successfully migrated database to version: 2026092312000018762026/10/01 10:11:57 OK 3_commit_push.sql (1.09ms)18772026/10/01 10:11:57 goose: up to current file version: 318782026/10/01 10:11:57 OK 1_commit_pending_closure.sql (902.54µs)18792026/10/01 10:11:57 OK 2_object_stats_trigger.sql (409.92µs)18802026/10/01 10:11:57 OK 3_commit_push.sql (284.96µs)18812026/10/01 10:11:57 goose: up to current file version: 318822026/10/01 10:11:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59117/oidc18832026/10/01 10:11:57 INFO Received push request method=POST path=/api/pushes18842026/10/01 10:11:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18852026/10/01 10:11:57 INFO Uploading igypz0ihpsb5ry3xs79yi3gy3dnj58b8-test-file.txt (152B)18862026/10/01 10:11:57 WARN Failed to register uploaded object key=igypz0ihpsb5ry3xs79yi3gy3dnj58b8.ls error="server returned 404: 404 page not found\n"18872026/10/01 10:11:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18882026/10/01 10:11:57 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18892026/10/01 10:11:57 INFO Signed narinfos id=1 count=118902026/10/01 10:11:57 INFO Uploading 1 narinfos18912026/10/01 10:11:57 INFO Received complete push request method=POST path=/api/pushes/1/complete18922026/10/01 10:11:57 WARN Failed to register uploaded object key=igypz0ihpsb5ry3xs79yi3gy3dnj58b8.narinfo error="server returned 404: 404 page not found\n"18932026/10/01 10:11:57 INFO Received push request method=POST path=/api/pushes18942026/10/01 10:11:57 INFO Upload complete. (105ms)18952026/10/01 10:11:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18962026/10/01 10:11:57 INFO Uploading arsqxfy3d47m27a32w6h13kf0hbpgw6j-test-script (136B)18972026/10/01 10:11:57 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18982026/10/01 10:11:57 WARN Failed to register uploaded object key=arsqxfy3d47m27a32w6h13kf0hbpgw6j.ls error="server returned 404: 404 page not found\n"18992026/10/01 10:11:57 INFO All 1 paths already cached1900=== NAME TestClientIntegration1901 client_integration_test.go:312: Retrieved narinfo from S3:1902 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestClientIntegration1283115790/002/store/igypz0ihpsb5ry3xs79yi3gy3dnj58b8-test-file.txt1903 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1904 Compression: zstd1905 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11906 NarSize: 1521907 References: 1908 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11909 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1910 client_integration_test.go:313: Decompressed .ls content (64 bytes):1911 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1912 client_integration_test.go:316: Testing garbage collection...19132026/10/01 10:11:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19142026/10/01 10:11:57 WARN Failed to register uploaded object key=log/0qdzbyihr2l1cnf9i9r1sx0c03k4r820-test-script.drv error="server returned 404: 404 page not found\n"19152026/10/01 10:11:57 INFO Signed narinfos id=1 count=119162026/10/01 10:11:57 INFO Uploading 1 narinfos19172026/10/01 10:11:57 INFO Received complete push request method=POST path=/api/pushes/1/complete19182026/10/01 10:11:57 WARN Failed to register uploaded object key=arsqxfy3d47m27a32w6h13kf0hbpgw6j.narinfo error="server returned 404: 404 page not found\n"19192026/10/01 10:11:57 INFO Upload complete. (133ms)1920=== NAME TestClientWithDependencies1921 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-12646-3956915670/TestClientWithDependencies643160747/001/store) requires matching store prefix19222026/10/01 10:11:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures19232026/10/01 10:11:57 INFO Garbage collection started19242026/10/01 10:11:57 INFO Aborted multipart uploads count=0 kept=019252026/10/01 10:11:57 WARN Force mode enabled - objects will be deleted immediately without grace period1926--- PASS: TestClientWithDependencies (2.98s)1927=== CONT TestClientCADerivations19282026/10/01 10:11:57 INFO Received uploads request method=POST path=/api/pending_closures19292026/10/01 10:11:57 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=019302026/10/01 10:11:57 INFO Vacuumed table table=pending_closures19312026/10/01 10:11:57 INFO Vacuumed table table=pending_objects19322026/10/01 10:11:57 INFO Vacuumed table table=multipart_uploads19332026/10/01 10:11:57 INFO Vacuumed table table=closures19342026/10/01 10:11:57 INFO Vacuumed table table=objects19352026/10/01 10:11:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19362026/10/01 10:11:57 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzYzNGRmM2QtMTAxOS00MWMzLThlNTUtYjFmZTZiNjY4ZGEzLmUwZDYyOGMyLWNkNjMtNGQxOS1iY2U3LTMwMjRlNmI1ZmZjZXgxNzkwODQ5NTE3MjY5ODIzMDAw19372026/10/01 10:11:57 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzYzNGRmM2QtMTAxOS00MWMzLThlNTUtYjFmZTZiNjY4ZGEzLmUwZDYyOGMyLWNkNjMtNGQxOS1iY2U3LTMwMjRlNmI1ZmZjZXgxNzkwODQ5NTE3MjY5ODIzMDAw parts=11938--- PASS: TestService_Rustfstest (1.54s)1939=== CONT TestCacheStatsHandler1940--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.63s)1941=== CONT TestCacheConfigHandler1942=== RUN TestCacheConfigHandler/full_config,_no_issuer1943=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1944=== RUN TestCacheConfigHandler/no_cache_url_configured1945=== PAUSE TestCacheConfigHandler/no_cache_url_configured1946=== RUN TestCacheConfigHandler/no_signing_keys1947=== PAUSE TestCacheConfigHandler/no_signing_keys1948=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1949=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1950=== CONT TestService_ReadScope_PublicByDefault19512026/10/01 10:11:57 INFO Aborted multipart uploads count=1 kept=019522026/10/01 10:11:57 INFO Received cleanup request method=DELETE path=/api/pending_closures19532026/10/01 10:11:57 INFO Aborted multipart uploads count=1 kept=01954--- PASS: TestPendingCleanupUsesOneCutoff (9.28s)1955=== CONT TestPush_RejectsBadRequests19562026/10/01 10:11:57 INFO Received uploads request method=POST path=/api/pending_closures19572026-10-01 10:11:57.779 UTC [12997] ERROR: relation "goose_db_version" does not exist at character 3619582026-10-01 10:11:57.779 UTC [12997] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19592026/10/01 10:11:57 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst19602026/10/01 10:11:57 INFO Received uploads request method=POST path=/api/pending_closures1961--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.84s)1962=== CONT TestRedundantMultipartUpload19632026/10/01 10:11:57 OK 20241026095416_initial_model.sql (49.27ms)19642026/10/01 10:11:57 OK 20251210153512_drop_unused_gin_index.sql (1.02ms)19652026/10/01 10:11:57 OK 20251218171726_add_pins.sql (4.2ms)19662026/10/01 10:11:57 OK 20260628120000_add_object_size_and_stats.sql (8.37ms)19672026/10/01 10:11:57 OK 20260905000000_add_claims.sql (8.23ms)19682026/10/01 10:11:57 OK 20260920000000_drop_claims.sql (1.23ms)19692026/10/01 10:11:57 OK 20260923120000_add_pushes.sql (568.83µs)19702026/10/01 10:11:57 goose: successfully migrated database to version: 2026092312000019712026/10/01 10:11:57 OK 1_commit_pending_closure.sql (1.02ms)19722026/10/01 10:11:57 OK 2_object_stats_trigger.sql (232.92µs)19732026/10/01 10:11:57 OK 3_commit_push.sql (175.33µs)19742026/10/01 10:11:57 goose: up to current file version: 31975=== NAME TestOrphanedObjectsGCStressTest1976 orphaned_objects_gc_test.go:509: Stress test completed successfully:1977 orphaned_objects_gc_test.go:510: - Active objects preserved: 201978 orphaned_objects_gc_test.go:511: - Objects deleted: 2101979 orphaned_objects_gc_test.go:512: - Total GC'd: 2101980--- PASS: TestOrphanedObjectsGCStressTest (9.94s)1981=== CONT TestPush_SignsNarinfosOfItsPendingObjects19822026/10/01 10:11:58 INFO Received uploads request method=POST path=/api/pending_closures19832026-10-01 10:11:58.131 UTC [13002] ERROR: relation "goose_db_version" does not exist at character 3619842026-10-01 10:11:58.131 UTC [13002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19852026/10/01 10:11:58 OK 20241026095416_initial_model.sql (66.34ms)19862026/10/01 10:11:58 OK 20251210153512_drop_unused_gin_index.sql (750.5µs)19872026/10/01 10:11:58 OK 20251218171726_add_pins.sql (1.46ms)19882026-10-01 10:11:58.213 UTC [13003] ERROR: relation "goose_db_version" does not exist at character 3619892026-10-01 10:11:58.213 UTC [13003] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19902026/10/01 10:11:58 OK 20260628120000_add_object_size_and_stats.sql (6.94ms)19912026/10/01 10:11:58 OK 20260905000000_add_claims.sql (2.62ms)19922026/10/01 10:11:58 OK 20260920000000_drop_claims.sql (877.46µs)19932026/10/01 10:11:58 OK 20260923120000_add_pushes.sql (619.38µs)19942026/10/01 10:11:58 goose: successfully migrated database to version: 2026092312000019952026/10/01 10:11:58 OK 1_commit_pending_closure.sql (1.27ms)19962026/10/01 10:11:58 OK 2_object_stats_trigger.sql (271.71µs)19972026/10/01 10:11:58 OK 3_commit_push.sql (234.04µs)19982026/10/01 10:11:58 goose: up to current file version: 319992026/10/01 10:11:58 OK 20241026095416_initial_model.sql (94.29ms)20002026/10/01 10:11:58 OK 20251210153512_drop_unused_gin_index.sql (1.13ms)20012026/10/01 10:11:58 OK 20251218171726_add_pins.sql (27.92ms)20022026/10/01 10:11:58 OK 20260628120000_add_object_size_and_stats.sql (37.07ms)20032026/10/01 10:11:58 OK 20260905000000_add_claims.sql (34.42ms)20042026/10/01 10:11:58 OK 20260920000000_drop_claims.sql (35.47ms)2005=== RUN TestService_RequireScope_OIDC/builder_may_write2006=== PAUSE TestService_RequireScope_OIDC/builder_may_write2007=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2008=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2009=== RUN TestService_RequireScope_OIDC/ops_may_admin2010=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2011=== RUN TestService_RequireScope_OIDC/ops_may_not_write2012=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2013=== RUN TestService_RequireScope_OIDC/reader_may_not_write2014=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2015=== RUN TestService_RequireScope_OIDC/static_token_may_admin2016=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2017=== RUN TestService_RequireScope_OIDC/static_token_may_write2018=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2019=== RUN TestService_RequireScope_OIDC/reader_may_read2020=== PAUSE TestService_RequireScope_OIDC/reader_may_read2021=== RUN TestService_RequireScope_OIDC/writer_implies_read2022=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2023=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2024=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2025=== CONT TestService_readinessHandler20262026/10/01 10:11:58 OK 20260923120000_add_pushes.sql (23.94ms)20272026/10/01 10:11:58 goose: successfully migrated database to version: 2026092312000020282026/10/01 10:11:58 OK 1_commit_pending_closure.sql (1.73ms)20292026/10/01 10:11:58 OK 2_object_stats_trigger.sql (324.46µs)20302026/10/01 10:11:58 OK 3_commit_push.sql (290.33µs)20312026/10/01 10:11:58 goose: up to current file version: 320322026/10/01 10:11:58 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020332026/10/01 10:11:58 INFO Received create pin request method=POST path=/api/pins/myapp20342026/10/01 10:11:58 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-12646-3956915670/TestPinProtectsFromGC4020395655/001/store/xvzbn8adjzmzgvpx5mzzm67xjjibbn5d-pinned-file.txt narinfo_key=xvzbn8adjzmzgvpx5mzzm67xjjibbn5d.narinfo20352026/10/01 10:11:58 INFO Starting cleanup of old closures method=DELETE path=/api/closures20362026/10/01 10:11:58 INFO Garbage collection started20372026/10/01 10:11:58 INFO Aborted multipart uploads count=0 kept=020382026/10/01 10:11:58 WARN Force mode enabled - objects will be deleted immediately without grace period20392026/10/01 10:11:58 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=020402026/10/01 10:11:58 INFO Vacuumed table table=pending_closures20412026/10/01 10:11:58 INFO Vacuumed table table=pending_objects20422026/10/01 10:11:58 INFO Vacuumed table table=multipart_uploads20432026/10/01 10:11:58 INFO Vacuumed table table=closures20442026/10/01 10:11:58 INFO Vacuumed table table=objects20452026-10-01 10:11:58.868 UTC [13007] ERROR: relation "goose_db_version" does not exist at character 3620462026-10-01 10:11:58.868 UTC [13007] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20472026-10-01 10:11:58.874 UTC [13008] ERROR: relation "goose_db_version" does not exist at character 3620482026-10-01 10:11:58.874 UTC [13008] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20492026-10-01 10:11:58.950 UTC [13011] ERROR: relation "goose_db_version" does not exist at character 3620502026-10-01 10:11:58.950 UTC [13011] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20512026/10/01 10:11:58 OK 20241026095416_initial_model.sql (83.66ms)20522026/10/01 10:11:58 OK 20241026095416_initial_model.sql (83.89ms)20532026/10/01 10:11:58 OK 20251210153512_drop_unused_gin_index.sql (6.65ms)20542026/10/01 10:11:58 OK 20251210153512_drop_unused_gin_index.sql (6.62ms)20552026/10/01 10:11:58 OK 20251218171726_add_pins.sql (3.24ms)20562026/10/01 10:11:59 OK 20251218171726_add_pins.sql (10.54ms)20572026/10/01 10:11:59 OK 20260628120000_add_object_size_and_stats.sql (10.43ms)20582026/10/01 10:11:59 OK 20260905000000_add_claims.sql (1.82ms)20592026/10/01 10:11:59 OK 20260628120000_add_object_size_and_stats.sql (5.86ms)20602026/10/01 10:11:59 OK 20260920000000_drop_claims.sql (1.07ms)20612026-10-01 10:11:59.008 UTC [13015] ERROR: relation "goose_db_version" does not exist at character 3620622026-10-01 10:11:59.008 UTC [13015] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20632026-10-01 10:11:59.008 UTC [13014] ERROR: relation "goose_db_version" does not exist at character 3620642026-10-01 10:11:59.008 UTC [13014] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20652026/10/01 10:11:59 OK 20260923120000_add_pushes.sql (1.75ms)20662026/10/01 10:11:59 goose: successfully migrated database to version: 2026092312000020672026/10/01 10:11:59 OK 1_commit_pending_closure.sql (1.14ms)20682026/10/01 10:11:59 OK 2_object_stats_trigger.sql (300.83µs)20692026/10/01 10:11:59 OK 20241026095416_initial_model.sql (20.05ms)20702026/10/01 10:11:59 OK 3_commit_push.sql (855.92µs)20712026/10/01 10:11:59 goose: up to current file version: 320722026/10/01 10:11:59 OK 20260905000000_add_claims.sql (4.35ms)20732026/10/01 10:11:59 OK 20251210153512_drop_unused_gin_index.sql (499.67µs)20742026/10/01 10:11:59 OK 20260920000000_drop_claims.sql (962.33µs)20752026/10/01 10:11:59 OK 20251218171726_add_pins.sql (1.19ms)20762026/10/01 10:11:59 OK 20260923120000_add_pushes.sql (15.73ms)20772026/10/01 10:11:59 goose: successfully migrated database to version: 2026092312000020782026/10/01 10:11:59 OK 1_commit_pending_closure.sql (1.03ms)20792026/10/01 10:11:59 OK 2_object_stats_trigger.sql (196.58µs)20802026/10/01 10:11:59 OK 3_commit_push.sql (174.25µs)20812026/10/01 10:11:59 goose: up to current file version: 320822026/10/01 10:11:59 OK 20260628120000_add_object_size_and_stats.sql (36.98ms)20832026/10/01 10:11:59 OK 20260905000000_add_claims.sql (30.75ms)20842026/10/01 10:11:59 OK 20260920000000_drop_claims.sql (14.24ms)20852026/10/01 10:11:59 OK 20260923120000_add_pushes.sql (4.76ms)20862026/10/01 10:11:59 goose: successfully migrated database to version: 2026092312000020872026/10/01 10:11:59 OK 1_commit_pending_closure.sql (1.26ms)20882026/10/01 10:11:59 OK 2_object_stats_trigger.sql (216.38µs)20892026/10/01 10:11:59 OK 3_commit_push.sql (168.92µs)20902026/10/01 10:11:59 goose: up to current file version: 320912026/10/01 10:11:59 OK 20241026095416_initial_model.sql (95.53ms)2092=== NAME TestClientCADerivations2093 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-12646-3956915670/TestClientCADerivations4245612627/001/store/f4iakpsrnk2s7klsr8fpm14xh9laigsq-ca-test20942026/10/01 10:11:59 OK 20251210153512_drop_unused_gin_index.sql (6.38ms)20952026/10/01 10:11:59 OK 20241026095416_initial_model.sql (101.52ms)20962026/10/01 10:11:59 OK 20251210153512_drop_unused_gin_index.sql (6.92ms)20972026/10/01 10:11:59 OK 20251218171726_add_pins.sql (24.86ms)20982026/10/01 10:11:59 OK 20251218171726_add_pins.sql (17.22ms)2099 client_ca_test.go:139: Found 1 dependencies (including self)21002026/10/01 10:11:59 OK 20260628120000_add_object_size_and_stats.sql (21.08ms)21012026/10/01 10:11:59 OK 20260628120000_add_object_size_and_stats.sql (21.33ms)21022026/10/01 10:11:59 OK 20260905000000_add_claims.sql (22.99ms)21032026/10/01 10:11:59 OK 20260905000000_add_claims.sql (23.34ms)21042026/10/01 10:11:59 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02105=== NAME TestClientIntegration2106 client_integration_test.go:323: Objects in database after GC:2107 client_integration_test.go:323: Successfully deleted all objects with GC --force21082026/10/01 10:11:59 OK 20260920000000_drop_claims.sql (6.37ms)2109--- PASS: TestClientIntegration (4.30s)2110=== CONT TestMultipartCleanup21112026/10/01 10:11:59 OK 20260920000000_drop_claims.sql (14.46ms)21122026/10/01 10:11:59 OK 20260923120000_add_pushes.sql (11.95ms)21132026/10/01 10:11:59 goose: successfully migrated database to version: 2026092312000021142026/10/01 10:11:59 OK 1_commit_pending_closure.sql (849.38µs)21152026/10/01 10:11:59 OK 2_object_stats_trigger.sql (231.38µs)21162026/10/01 10:11:59 OK 3_commit_push.sql (185.17µs)21172026/10/01 10:11:59 goose: up to current file version: 321182026/10/01 10:11:59 OK 20260923120000_add_pushes.sql (9.25ms)21192026/10/01 10:11:59 goose: successfully migrated database to version: 2026092312000021202026/10/01 10:11:59 OK 1_commit_pending_closure.sql (745.67µs)21212026/10/01 10:11:59 OK 2_object_stats_trigger.sql (182.46µs)21222026/10/01 10:11:59 OK 3_commit_push.sql (148.42µs)21232026/10/01 10:11:59 goose: up to current file version: 32124--- PASS: TestCacheStatsHandler (1.76s)2125=== CONT TestServerTLSConfig2126=== RUN TestServerTLSConfig/no_client_CA2127=== PAUSE TestServerTLSConfig/no_client_CA2128=== RUN TestServerTLSConfig/missing_CA_file2129=== PAUSE TestServerTLSConfig/missing_CA_file2130=== RUN TestServerTLSConfig/not_a_PEM_file2131=== PAUSE TestServerTLSConfig/not_a_PEM_file2132=== CONT TestService_NativeMTLS21332026/10/01 10:11:59 INFO Received push request method=POST path=/api/pushes21342026/10/01 10:11:59 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21352026/10/01 10:11:59 INFO Uploading f4iakpsrnk2s7klsr8fpm14xh9laigsq-ca-test (144B)21362026/10/01 10:11:59 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"21372026/10/01 10:11:59 WARN Failed to register uploaded object key=f4iakpsrnk2s7klsr8fpm14xh9laigsq.ls error="server returned 404: 404 page not found\n"21382026/10/01 10:11:59 WARN Failed to register uploaded object key=log/g1ypkn5j2r751w43sb67c33bbjyk8gvq-ca-test.drv error="server returned 404: 404 page not found\n"21392026/10/01 10:11:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21402026/10/01 10:11:59 INFO Signed narinfos id=1 count=121412026/10/01 10:11:59 INFO Uploading 1 narinfos21422026/10/01 10:11:59 INFO Received complete push request method=POST path=/api/pushes/1/complete21432026/10/01 10:11:59 WARN Failed to register uploaded object key=f4iakpsrnk2s7klsr8fpm14xh9laigsq.narinfo error="server returned 404: 404 page not found\n"21442026/10/01 10:11:59 INFO Upload complete. (193ms)2145=== NAME TestClientCADerivations2146 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestClientCADerivations4245612627/001/store/f4iakpsrnk2s7klsr8fpm14xh9laigsq-ca-test2147 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2148 Compression: zstd2149 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2150 NarSize: 1442151 References: 2152 Deriver: /nix/var/nix/builds/nix-12646-3956915670/TestClientCADerivations4245612627/001/store/g1ypkn5j2r751w43sb67c33bbjyk8gvq-ca-test.drv2153 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2154 client_ca_test.go:185: Checking for realisation files in S3...2155 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2156 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache21572026/10/01 10:11:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21582026/10/01 10:11:59 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YzYzNGRmM2QtMTAxOS00MWMzLThlNTUtYjFmZTZiNjY4ZGEzLjljYWI4Nzg2LTU4YzItNDcwMi1iMGE3LWQ1MjMyMzRlNGQwMXgxNzkwODQ5NTE4MTAwMjM1MDAw parts=1221592026/10/01 10:11:59 INFO Received uploads request method=POST path=/api/pending_closures2160--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.77s)2161=== CONT TestMetricsInventory2162=== NAME TestClientCADerivations2163 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket55?endpoint=http://localhost:58869®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-12646-3956915670/TestClientCADerivations4245612627/001/store'2164 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12165--- PASS: TestService_ReadScope_PublicByDefault (1.99s)2166=== CONT TestNARDeduplicationMetadataUploadBug2167--- PASS: TestClientCADerivations (2.32s)2168=== CONT TestCreatePendingClosureRejectsOversizedNAR21692026/10/01 10:11:59 INFO Received uploads request method=POST path=/api/pending_closures2170--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2171=== CONT TestCacheConfigHandlerMaxNarSize2172--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)2173=== CONT TestGenerateLandingPage2174--- PASS: TestGenerateLandingPage (0.00s)2175=== CONT TestGCTaskStore_CompletedAllowsNewTask2176--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)2177=== CONT TestService_healthCheckHandler21782026-10-01 10:11:59.689 UTC [13036] ERROR: relation "goose_db_version" does not exist at character 3621792026-10-01 10:11:59.689 UTC [13036] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2180=== RUN TestPush_RejectsBadRequests/no_roots2181=== PAUSE TestPush_RejectsBadRequests/no_roots2182=== RUN TestPush_RejectsBadRequests/no_objects2183=== PAUSE TestPush_RejectsBadRequests/no_objects2184=== RUN TestPush_RejectsBadRequests/bad_root2185=== PAUSE TestPush_RejectsBadRequests/bad_root2186=== RUN TestPush_RejectsBadRequests/root_not_in_objects2187=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects2188=== CONT TestGracefulShutdownDrainsInflight21892026/10/01 10:11:59 INFO Starting HTTP server address=127.0.0.1:5916521902026/10/01 10:11:59 INFO Shutdown signal received, draining in-flight requests timeout=10s2191--- PASS: TestGracefulShutdownDrainsInflight (0.07s)2192=== CONT TestGCTaskStore_Fail2193--- PASS: TestGCTaskStore_Fail (0.00s)2194=== CONT TestGCTaskStore_PhaseUpdates2195--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)2196=== CONT TestService_ReadAuthMiddleware21972026/10/01 10:11:59 OK 20241026095416_initial_model.sql (49.32ms)21982026/10/01 10:11:59 OK 20251210153512_drop_unused_gin_index.sql (7.05ms)21992026/10/01 10:11:59 OK 20251218171726_add_pins.sql (16.91ms)22002026/10/01 10:11:59 OK 20260628120000_add_object_size_and_stats.sql (25.09ms)22012026/10/01 10:11:59 INFO Received uploads request method=POST path=/api/pending_closures22022026/10/01 10:11:59 OK 20260905000000_add_claims.sql (75.89ms)22032026/10/01 10:11:59 INFO Received uploads request method=POST path=/api/pending_closures22042026/10/01 10:11:59 OK 20260920000000_drop_claims.sql (28.36ms)22052026/10/01 10:11:59 OK 20260923120000_add_pushes.sql (14.67ms)22062026/10/01 10:11:59 goose: successfully migrated database to version: 2026092312000022072026/10/01 10:11:59 OK 1_commit_pending_closure.sql (3.81ms)22082026/10/01 10:11:59 OK 2_object_stats_trigger.sql (686.92µs)22092026/10/01 10:11:59 OK 3_commit_push.sql (510.33µs)22102026/10/01 10:11:59 goose: up to current file version: 322112026/10/01 10:12:00 INFO Received push request method=POST path=/api/pushes22122026/10/01 10:12:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22132026/10/01 10:12:00 INFO Signed narinfos id=1 count=12214--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.26s)2215=== CONT TestService_AuthMiddleware_OIDC22162026/10/01 10:12:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59175/oidc22172026/10/01 10:12:00 WARN readiness check failed error="closed pool"2218--- PASS: TestService_readinessHandler (1.84s)2219=== CONT TestRegisterCompletedObjectNeedsPendingRow22202026-10-01 10:12:00.394 UTC [13046] ERROR: relation "goose_db_version" does not exist at character 3622212026-10-01 10:12:00.394 UTC [13046] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22222026/10/01 10:12:00 OK 20241026095416_initial_model.sql (48.08ms)22232026/10/01 10:12:00 OK 20251210153512_drop_unused_gin_index.sql (600.13µs)22242026/10/01 10:12:00 OK 20251218171726_add_pins.sql (1.05ms)22252026-10-01 10:12:00.469 UTC [13047] ERROR: relation "goose_db_version" does not exist at character 3622262026-10-01 10:12:00.469 UTC [13047] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22272026/10/01 10:12:00 OK 20260628120000_add_object_size_and_stats.sql (5.14ms)22282026/10/01 10:12:00 OK 20260905000000_add_claims.sql (30.1ms)22292026/10/01 10:12:00 OK 20260920000000_drop_claims.sql (17.18ms)22302026/10/01 10:12:00 OK 20260923120000_add_pushes.sql (22.44ms)22312026/10/01 10:12:00 goose: successfully migrated database to version: 2026092312000022322026/10/01 10:12:00 OK 1_commit_pending_closure.sql (1.79ms)22332026/10/01 10:12:00 OK 2_object_stats_trigger.sql (472.25µs)22342026/10/01 10:12:00 OK 3_commit_push.sql (3.35ms)22352026/10/01 10:12:00 goose: up to current file version: 322362026/10/01 10:12:00 OK 20241026095416_initial_model.sql (51.16ms)22372026/10/01 10:12:00 OK 20251210153512_drop_unused_gin_index.sql (492.29µs)22382026/10/01 10:12:00 OK 20251218171726_add_pins.sql (11.96ms)2239=== NAME TestPinProtectsFromGC2240 client_integration_test.go:840: Pin successfully protected closure from garbage collection22412026/10/01 10:12:00 OK 20260628120000_add_object_size_and_stats.sql (57.49ms)22422026/10/01 10:12:00 OK 20260905000000_add_claims.sql (60.66ms)2243--- PASS: TestPinProtectsFromGC (6.98s)2244=== CONT TestPushWaitsForSweepHoldingRow22452026/10/01 10:12:00 OK 20260920000000_drop_claims.sql (4.89ms)22462026/10/01 10:12:00 OK 20260923120000_add_pushes.sql (11.24ms)22472026/10/01 10:12:00 goose: successfully migrated database to version: 2026092312000022482026/10/01 10:12:00 OK 1_commit_pending_closure.sql (1.9ms)22492026/10/01 10:12:00 OK 2_object_stats_trigger.sql (527.13µs)22502026/10/01 10:12:00 OK 3_commit_push.sql (266.71µs)22512026/10/01 10:12:00 goose: up to current file version: 322522026-10-01 10:12:00.771 UTC [13049] ERROR: relation "goose_db_version" does not exist at character 3622532026-10-01 10:12:00.771 UTC [13049] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22542026-10-01 10:12:00.808 UTC [13051] ERROR: relation "goose_db_version" does not exist at character 3622552026-10-01 10:12:00.808 UTC [13051] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22562026/10/01 10:12:00 INFO Received uploads request method=POST path=/api/pending_closures22572026/10/01 10:12:00 OK 20241026095416_initial_model.sql (167.68ms)22582026/10/01 10:12:00 OK 20251210153512_drop_unused_gin_index.sql (3.75ms)22592026/10/01 10:12:01 OK 20241026095416_initial_model.sql (119.72ms)22602026/10/01 10:12:01 OK 20251210153512_drop_unused_gin_index.sql (12.83ms)22612026/10/01 10:12:01 INFO Received cleanup request method=DELETE path=/api/pending_closures22622026/10/01 10:12:01 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket62/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""22632026/10/01 10:12:01 INFO Aborted multipart uploads count=0 kept=122642026/10/01 10:12:01 INFO Received cleanup request method=DELETE path=/api/pending_closures22652026/10/01 10:12:01 OK 20251218171726_add_pins.sql (52.22ms)22662026/10/01 10:12:01 INFO Aborted multipart uploads count=1 kept=022672026/10/01 10:12:01 OK 20251218171726_add_pins.sql (36.86ms)2268--- PASS: TestMultipartCleanup (1.87s)2269=== CONT TestSweepRechecksPendingAfterLocking22702026/10/01 10:12:01 OK 20260628120000_add_object_size_and_stats.sql (36.88ms)22712026-10-01 10:12:01.094 UTC [13052] ERROR: relation "goose_db_version" does not exist at character 3622722026-10-01 10:12:01.094 UTC [13052] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22732026/10/01 10:12:01 OK 20260628120000_add_object_size_and_stats.sql (59.85ms)22742026/10/01 10:12:01 OK 20260905000000_add_claims.sql (50.84ms)22752026/10/01 10:12:01 OK 20260920000000_drop_claims.sql (23.6ms)22762026/10/01 10:12:01 OK 20260905000000_add_claims.sql (38.25ms)22772026/10/01 10:12:01 WARN mTLS auth: subject not in bound subjects subject="CN=reader"22782026/10/01 10:12:01 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2279--- PASS: TestService_NativeMTLS (1.90s)2280=== CONT TestGetExistingObjectsLocksRows22812026/10/01 10:12:01 OK 20260923120000_add_pushes.sql (11.23ms)22822026/10/01 10:12:01 goose: successfully migrated database to version: 2026092312000022832026/10/01 10:12:01 OK 1_commit_pending_closure.sql (1.84ms)22842026/10/01 10:12:01 OK 2_object_stats_trigger.sql (420.67µs)22852026/10/01 10:12:01 OK 3_commit_push.sql (404.38µs)22862026/10/01 10:12:01 goose: up to current file version: 322872026/10/01 10:12:01 OK 20260920000000_drop_claims.sql (46.97ms)22882026/10/01 10:12:01 OK 20260923120000_add_pushes.sql (14.49ms)22892026/10/01 10:12:01 goose: successfully migrated database to version: 2026092312000022902026/10/01 10:12:01 OK 1_commit_pending_closure.sql (1.71ms)22912026/10/01 10:12:01 OK 2_object_stats_trigger.sql (412.13µs)22922026/10/01 10:12:01 OK 3_commit_push.sql (339.5µs)22932026/10/01 10:12:01 goose: up to current file version: 322942026/10/01 10:12:01 OK 20241026095416_initial_model.sql (143.83ms)22952026/10/01 10:12:01 OK 20251210153512_drop_unused_gin_index.sql (7.91ms)22962026/10/01 10:12:01 OK 20251218171726_add_pins.sql (27.53ms)22972026-10-01 10:12:01.357 UTC [13057] ERROR: relation "goose_db_version" does not exist at character 3622982026-10-01 10:12:01.357 UTC [13057] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22992026/10/01 10:12:01 OK 20260628120000_add_object_size_and_stats.sql (34.89ms)23002026/10/01 10:12:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23012026/10/01 10:12:01 OK 20260905000000_add_claims.sql (41.66ms)23022026/10/01 10:12:01 OK 20260920000000_drop_claims.sql (77.39ms)23032026/10/01 10:12:01 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YzYzNGRmM2QtMTAxOS00MWMzLThlNTUtYjFmZTZiNjY4ZGEzLjEwNTBiNmEyLWU5ZDEtNDliZi05OTM3LTgyZDViNmI1NTA1MXgxNzkwODQ5NTE5ODc5MjgwMDAw parts=1223042026/10/01 10:12:01 INFO Received uploads request method=POST path=/api/pending_closures23052026/10/01 10:12:01 OK 20260923120000_add_pushes.sql (38.28ms)23062026/10/01 10:12:01 goose: successfully migrated database to version: 2026092312000023072026/10/01 10:12:01 OK 1_commit_pending_closure.sql (4.28ms)23082026/10/01 10:12:01 OK 2_object_stats_trigger.sql (851.75µs)23092026/10/01 10:12:01 OK 3_commit_push.sql (575.46µs)23102026/10/01 10:12:01 goose: up to current file version: 323112026/10/01 10:12:01 INFO Received uploads request method=POST path=/api/pending_closures2312--- PASS: TestMetricsInventory (2.13s)2313=== CONT TestGCTaskStore_GetEmpty2314--- PASS: TestGCTaskStore_GetEmpty (0.00s)2315=== CONT TestGCTaskStore_GetReturnsLatest2316--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)2317=== CONT TestGCTaskStore_ConflictDifferentParams2318--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)2319=== CONT TestGCTaskStore_DeduplicateSameParams2320--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)2321=== CONT TestIsValidUploadKey2322=== RUN TestIsValidUploadKey/narinfo2323=== PAUSE TestIsValidUploadKey/narinfo2324=== RUN TestIsValidUploadKey/nar_zst2325=== PAUSE TestIsValidUploadKey/nar_zst2326=== RUN TestIsValidUploadKey/nar_xz2327=== PAUSE TestIsValidUploadKey/nar_xz2328=== RUN TestIsValidUploadKey/nar_plain2329=== PAUSE TestIsValidUploadKey/nar_plain2330=== RUN TestIsValidUploadKey/listing2331=== PAUSE TestIsValidUploadKey/listing2332=== RUN TestIsValidUploadKey/build_log2333=== PAUSE TestIsValidUploadKey/build_log2334=== RUN TestIsValidUploadKey/build_log_home-manager_file2335=== PAUSE TestIsValidUploadKey/build_log_home-manager_file2336=== RUN TestIsValidUploadKey/build_log_plus_in_name2337=== PAUSE TestIsValidUploadKey/build_log_plus_in_name2338=== RUN TestIsValidUploadKey/build_log_question_mark2339=== PAUSE TestIsValidUploadKey/build_log_question_mark2340=== RUN TestIsValidUploadKey/build_log_equals2341=== PAUSE TestIsValidUploadKey/build_log_equals2342=== RUN TestIsValidUploadKey/realisation2343=== PAUSE TestIsValidUploadKey/realisation2344=== RUN TestIsValidUploadKey/realisation_plus_in_output2345=== PAUSE TestIsValidUploadKey/realisation_plus_in_output2346=== RUN TestIsValidUploadKey/nix-cache-info2347=== PAUSE TestIsValidUploadKey/nix-cache-info2348=== RUN TestIsValidUploadKey/index.html2349=== PAUSE TestIsValidUploadKey/index.html2350=== RUN TestIsValidUploadKey/narinfo_key,_nar_type2351=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type2352=== RUN TestIsValidUploadKey/nar_key,_narinfo_type2353=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type2354=== RUN TestIsValidUploadKey/listing_key,_narinfo_type2355=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type2356=== RUN TestIsValidUploadKey/traversal2357=== PAUSE TestIsValidUploadKey/traversal2358=== RUN TestIsValidUploadKey/traversal_nar2359=== PAUSE TestIsValidUploadKey/traversal_nar2360=== RUN TestIsValidUploadKey/absolute2361=== PAUSE TestIsValidUploadKey/absolute2362=== RUN TestIsValidUploadKey/empty_key2363=== PAUSE TestIsValidUploadKey/empty_key2364=== RUN TestIsValidUploadKey/unknown_type2365=== PAUSE TestIsValidUploadKey/unknown_type2366=== CONT TestUploadHandlersRejectOversizedBody2367=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart2368=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart2369=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts2370=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts2371=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure2372=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure2373=== CONT TestUploadHandlersRejectInvalidKeys2374=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info2375=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info2376=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal2377=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal2378=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key2379=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key2380=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key2381=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key2382=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit23832026/10/01 10:12:01 OK 20241026095416_initial_model.sql (225.1ms)23842026/10/01 10:12:01 OK 20251210153512_drop_unused_gin_index.sql (3.8ms)23852026/10/01 10:12:01 OK 20251218171726_add_pins.sql (36.08ms)23862026/10/01 10:12:01 OK 20260628120000_add_object_size_and_stats.sql (34.25ms)23872026/10/01 10:12:01 OK 20260905000000_add_claims.sql (49.8ms)23882026/10/01 10:12:01 OK 20260920000000_drop_claims.sql (37.2ms)23892026/10/01 10:12:01 OK 20260923120000_add_pushes.sql (10.26ms)23902026/10/01 10:12:01 goose: successfully migrated database to version: 2026092312000023912026/10/01 10:12:01 OK 1_commit_pending_closure.sql (3.07ms)23922026/10/01 10:12:01 OK 2_object_stats_trigger.sql (491.92µs)23932026/10/01 10:12:01 OK 3_commit_push.sql (403.67µs)23942026/10/01 10:12:01 goose: up to current file version: 323952026-10-01 10:12:01.971 UTC [13061] ERROR: relation "goose_db_version" does not exist at character 3623962026-10-01 10:12:01.971 UTC [13061] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23972026-10-01 10:12:02.000 UTC [13063] ERROR: relation "goose_db_version" does not exist at character 3623982026-10-01 10:12:02.000 UTC [13063] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2399--- PASS: TestService_healthCheckHandler (2.53s)2400=== CONT TestService_AuthMiddleware_MTLSBoundSubjects2401=== NAME TestNARDeduplicationMetadataUploadBug2402 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-12646-3956915670/TestNARDeduplicationMetadataUploadBug3359984896/001/store/74fw90s6vy2irzdzwc66wh8ya9y4wpl2-file1.txt24032026/10/01 10:12:02 INFO Received push request method=POST path=/api/pushes24042026/10/01 10:12:02 OK 20241026095416_initial_model.sql (137.65ms)24052026/10/01 10:12:02 OK 20251210153512_drop_unused_gin_index.sql (8.25ms)24062026/10/01 10:12:02 OK 20241026095416_initial_model.sql (134.81ms)24072026/10/01 10:12:02 OK 20251210153512_drop_unused_gin_index.sql (7.63ms)24082026/10/01 10:12:02 OK 20251218171726_add_pins.sql (15.91ms)24092026/10/01 10:12:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24102026/10/01 10:12:02 INFO Uploading 74fw90s6vy2irzdzwc66wh8ya9y4wpl2-file1.txt (160B)24112026/10/01 10:12:02 WARN Failed to register uploaded object key=74fw90s6vy2irzdzwc66wh8ya9y4wpl2.ls error="server returned 404: 404 page not found\n"24122026/10/01 10:12:02 OK 20251218171726_add_pins.sql (7.81ms)24132026/10/01 10:12:02 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"24142026/10/01 10:12:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24152026/10/01 10:12:02 INFO Signed narinfos id=1 count=124162026/10/01 10:12:02 INFO Uploading 1 narinfos24172026/10/01 10:12:02 OK 20260628120000_add_object_size_and_stats.sql (33.96ms)24182026/10/01 10:12:02 INFO Received complete push request method=POST path=/api/pushes/1/complete24192026/10/01 10:12:02 WARN Failed to register uploaded object key=74fw90s6vy2irzdzwc66wh8ya9y4wpl2.narinfo error="server returned 404: 404 page not found\n"24202026/10/01 10:12:02 OK 20260628120000_add_object_size_and_stats.sql (54.4ms)24212026/10/01 10:12:02 INFO Upload complete. (171ms)2422 metadata_upload_test.go:54: Retrieved narinfo from S3:2423 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestNARDeduplicationMetadataUploadBug3359984896/001/store/74fw90s6vy2irzdzwc66wh8ya9y4wpl2-file1.txt2424 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2425 Compression: zstd2426 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2427 NarSize: 1602428 References: 2429 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2430 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2431 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2432 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}24332026/10/01 10:12:02 OK 20260905000000_add_claims.sql (81.15ms)2434--- PASS: TestService_ReadAuthMiddleware (2.58s)2435=== CONT TestProxyWriteTimeout2436=== RUN TestProxyWriteTimeout/narinfo2437=== PAUSE TestProxyWriteTimeout/narinfo2438=== RUN TestProxyWriteTimeout/1_GiB_nar2439=== PAUSE TestProxyWriteTimeout/1_GiB_nar2440=== RUN TestProxyWriteTimeout/10_GiB_nar2441=== PAUSE TestProxyWriteTimeout/10_GiB_nar2442=== RUN TestProxyWriteTimeout/unknown_size2443=== PAUSE TestProxyWriteTimeout/unknown_size2444=== CONT TestPush_CompleteCommitsEveryRoot24452026/10/01 10:12:02 OK 20260905000000_add_claims.sql (54.62ms)24462026/10/01 10:12:02 OK 20260920000000_drop_claims.sql (17.76ms)24472026/10/01 10:12:02 OK 20260920000000_drop_claims.sql (16.46ms)24482026/10/01 10:12:02 OK 20260923120000_add_pushes.sql (14.21ms)24492026/10/01 10:12:02 goose: successfully migrated database to version: 2026092312000024502026/10/01 10:12:02 OK 1_commit_pending_closure.sql (998.79µs)24512026/10/01 10:12:02 OK 2_object_stats_trigger.sql (253.46µs)24522026/10/01 10:12:02 OK 3_commit_push.sql (225.71µs)24532026/10/01 10:12:02 goose: up to current file version: 324542026/10/01 10:12:02 OK 20260923120000_add_pushes.sql (21.83ms)24552026/10/01 10:12:02 goose: successfully migrated database to version: 2026092312000024562026/10/01 10:12:02 OK 1_commit_pending_closure.sql (773.08µs)24572026/10/01 10:12:02 OK 2_object_stats_trigger.sql (217.58µs)24582026/10/01 10:12:02 OK 3_commit_push.sql (182.71µs)24592026/10/01 10:12:02 goose: up to current file version: 32460=== NAME TestNARDeduplicationMetadataUploadBug2461 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-12646-3956915670/TestNARDeduplicationMetadataUploadBug3359984896/001/store/hapqr0461ky4d1sr02f8pkdvp10k5qhp-file2.txt24622026/10/01 10:12:02 INFO Received push request method=POST path=/api/pushes24632026/10/01 10:12:02 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)24642026/10/01 10:12:02 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign24652026/10/01 10:12:02 INFO Signed narinfos id=2 count=124662026/10/01 10:12:02 INFO Uploading 1 narinfos24672026/10/01 10:12:02 WARN Failed to register uploaded object key=hapqr0461ky4d1sr02f8pkdvp10k5qhp.ls error="server returned 404: 404 page not found\n"24682026/10/01 10:12:02 INFO Received complete push request method=POST path=/api/pushes/2/complete24692026/10/01 10:12:02 WARN Failed to register uploaded object key=hapqr0461ky4d1sr02f8pkdvp10k5qhp.narinfo error="server returned 404: 404 page not found\n"24702026/10/01 10:12:02 INFO Upload complete. (97ms)2471 metadata_upload_test.go:76: Retrieved narinfo from S3:2472 StorePath: /nix/var/nix/builds/nix-12646-3956915670/TestNARDeduplicationMetadataUploadBug3359984896/001/store/hapqr0461ky4d1sr02f8pkdvp10k5qhp-file2.txt2473 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2474 Compression: zstd2475 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2476 NarSize: 1602477 References: 2478 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2479 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2480 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2481 {"version":1,"root":{"type":"regular","size":44}}2482--- PASS: TestNARDeduplicationMetadataUploadBug (3.11s)2483=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle24842026-10-01 10:12:02.628 UTC [13078] ERROR: relation "goose_db_version" does not exist at character 3624852026-10-01 10:12:02.628 UTC [13078] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2486--- PASS: TestRegisterCompletedObjectNeedsPendingRow (2.37s)2487=== CONT TestFailedS3DeleteKeepsTombstone24882026/10/01 10:12:02 OK 20241026095416_initial_model.sql (158.86ms)24892026/10/01 10:12:02 OK 20251210153512_drop_unused_gin_index.sql (12.12ms)24902026/10/01 10:12:02 OK 20251218171726_add_pins.sql (34.92ms)2491=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2492=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2493=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2494=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2495=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2496=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2497=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2498=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2499=== CONT TestSweepSkipsRowsLockedByPush25002026/10/01 10:12:02 OK 20260628120000_add_object_size_and_stats.sql (57.5ms)25012026/10/01 10:12:03 OK 20260905000000_add_claims.sql (57.74ms)25022026/10/01 10:12:03 OK 20260920000000_drop_claims.sql (44.14ms)25032026/10/01 10:12:03 INFO Received complete multipart upload request method=POST path=/api/multipart/complete25042026/10/01 10:12:03 OK 20260923120000_add_pushes.sql (59.2ms)25052026/10/01 10:12:03 goose: successfully migrated database to version: 2026092312000025062026/10/01 10:12:03 OK 1_commit_pending_closure.sql (4.03ms)25072026/10/01 10:12:03 OK 2_object_stats_trigger.sql (1.31ms)25082026/10/01 10:12:03 OK 3_commit_push.sql (446.92µs)25092026/10/01 10:12:03 goose: up to current file version: 325102026/10/01 10:12:03 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YzYzNGRmM2QtMTAxOS00MWMzLThlNTUtYjFmZTZiNjY4ZGEzLjRiMzEyOGNhLTRmNjMtNDMyOS05OGJjLTRhMmE4MTgxYWM2ZHgxNzkwODQ5NTIxNTc2NjM2MDAw error="Get \"http://127.0.0.1:1/bucket59/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"25112026/10/01 10:12:03 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YzYzNGRmM2QtMTAxOS00MWMzLThlNTUtYjFmZTZiNjY4ZGEzLjBmZmVhYWU0LTkwZDUtNGZkNC05YmFjLTViNTEwNjMxZTY5NngxNzkwODQ5NTIxNTI5MjYyMDAw parts=1225122026/10/01 10:12:03 INFO Received cleanup request method=DELETE path=/api/pending_closures25132026/10/01 10:12:03 INFO Aborted multipart uploads count=1 kept=02514--- PASS: TestRedundantMultipartUpload (5.36s)2515=== CONT TestForceGCDuringPushOffersSweptObject2516=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows2517=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows2518=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check2519=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check2520=== CONT TestService_AuthMiddleware_MTLSProxyHeader25212026-10-01 10:12:03.219 UTC [13085] ERROR: relation "goose_db_version" does not exist at character 3625222026-10-01 10:12:03.219 UTC [13085] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25232026/10/01 10:12:03 INFO Received uploads request method=POST path=/api/pending_closures25242026/10/01 10:12:03 OK 20241026095416_initial_model.sql (251.69ms)25252026-10-01 10:12:03.558 UTC [13088] ERROR: relation "goose_db_version" does not exist at character 3625262026-10-01 10:12:03.558 UTC [13088] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25272026/10/01 10:12:03 OK 20251210153512_drop_unused_gin_index.sql (5.54ms)25282026/10/01 10:12:03 OK 20251218171726_add_pins.sql (9.99ms)25292026/10/01 10:12:03 OK 20260628120000_add_object_size_and_stats.sql (28.54ms)25302026/10/01 10:12:03 OK 20260905000000_add_claims.sql (21.36ms)25312026/10/01 10:12:03 OK 20260920000000_drop_claims.sql (33.14ms)25322026/10/01 10:12:03 OK 20260923120000_add_pushes.sql (15.75ms)25332026/10/01 10:12:03 goose: successfully migrated database to version: 2026092312000025342026/10/01 10:12:03 OK 1_commit_pending_closure.sql (7.26ms)25352026/10/01 10:12:03 OK 2_object_stats_trigger.sql (2.18ms)25362026/10/01 10:12:03 OK 3_commit_push.sql (683.92µs)25372026/10/01 10:12:03 goose: up to current file version: 325382026/10/01 10:12:03 OK 20241026095416_initial_model.sql (125.68ms)25392026/10/01 10:12:03 OK 20251210153512_drop_unused_gin_index.sql (7.7ms)25402026/10/01 10:12:03 OK 20251218171726_add_pins.sql (23.51ms)25412026-10-01 10:12:03.763 UTC [13090] ERROR: relation "goose_db_version" does not exist at character 3625422026-10-01 10:12:03.763 UTC [13090] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25432026/10/01 10:12:03 OK 20260628120000_add_object_size_and_stats.sql (43.72ms)25442026/10/01 10:12:03 OK 20260905000000_add_claims.sql (27.38ms)25452026/10/01 10:12:03 OK 20260920000000_drop_claims.sql (21.5ms)25462026/10/01 10:12:03 OK 20260923120000_add_pushes.sql (4.81ms)25472026/10/01 10:12:03 goose: successfully migrated database to version: 2026092312000025482026/10/01 10:12:03 OK 1_commit_pending_closure.sql (4.48ms)25492026/10/01 10:12:03 OK 2_object_stats_trigger.sql (686.63µs)25502026/10/01 10:12:03 OK 3_commit_push.sql (410.04µs)25512026/10/01 10:12:03 goose: up to current file version: 325522026/10/01 10:12:04 OK 20241026095416_initial_model.sql (231.6ms)25532026-10-01 10:12:04.055 UTC [13091] ERROR: relation "goose_db_version" does not exist at character 3625542026-10-01 10:12:04.055 UTC [13091] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2555--- PASS: TestPushWaitsForSweepHoldingRow (3.37s)2556=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection25572026/10/01 10:12:04 OK 20251210153512_drop_unused_gin_index.sql (11.68ms)25582026/10/01 10:12:04 INFO Aborted multipart uploads count=0 kept=025592026/10/01 10:12:04 WARN Force mode enabled - objects will be deleted immediately without grace period25602026/10/01 10:12:04 OK 20251218171726_add_pins.sql (61.84ms)25612026/10/01 10:12:04 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=025622026/10/01 10:12:04 INFO Vacuumed table table=pending_closures25632026/10/01 10:12:04 OK 20260628120000_add_object_size_and_stats.sql (30.03ms)25642026/10/01 10:12:04 INFO Vacuumed table table=pending_objects25652026/10/01 10:12:04 INFO Vacuumed table table=multipart_uploads25662026/10/01 10:12:04 INFO Vacuumed table table=closures25672026/10/01 10:12:04 OK 20260905000000_add_claims.sql (78.2ms)25682026/10/01 10:12:04 INFO Vacuumed table table=objects2569--- PASS: TestSweepRechecksPendingAfterLocking (3.18s)2570=== CONT TestGCSweepDeliversEachKeyOnce25712026/10/01 10:12:04 OK 20260920000000_drop_claims.sql (44.03ms)25722026/10/01 10:12:04 OK 20260923120000_add_pushes.sql (19.02ms)25732026/10/01 10:12:04 goose: successfully migrated database to version: 2026092312000025742026/10/01 10:12:04 OK 1_commit_pending_closure.sql (3.13ms)25752026/10/01 10:12:04 OK 2_object_stats_trigger.sql (635.13µs)25762026/10/01 10:12:04 OK 3_commit_push.sql (421.25µs)25772026/10/01 10:12:04 goose: up to current file version: 32578--- PASS: TestGetExistingObjectsLocksRows (3.17s)2579=== CONT TestIsValidCachePath/narinfo2580=== CONT TestIsValidCachePath/index.html2581=== CONT TestIsValidCachePath/short_hash2582=== CONT TestIsValidCachePath/wrong_extension2583=== CONT TestIsValidCachePath/leading_slash2584=== CONT TestIsValidCachePath/empty2585=== CONT TestIsValidCachePath/random_path2586=== CONT TestIsValidCachePath/invalid_char_u2587=== CONT TestIsValidCachePath/invalid_char_e2588=== CONT TestIsValidCachePath/traversal_in_middle2589=== CONT TestIsValidCachePath/traversal_parent2590=== CONT TestIsValidCachePath/nar_uncompressed2591=== CONT TestIsValidCachePath/nix-cache-info2592=== CONT TestIsValidCachePath/realisation2593=== CONT TestIsValidCachePath/log2594=== CONT TestIsValidCachePath/ls2595=== CONT TestIsValidCachePath/nar_xz2596=== CONT TestIsValidCachePath/nar_bz22597=== CONT TestIsValidCachePath/nar_zst2598=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2599--- PASS: TestIsValidCachePath (0.00s)2600 --- PASS: TestIsValidCachePath/narinfo (0.00s)2601 --- PASS: TestIsValidCachePath/index.html (0.00s)2602 --- PASS: TestIsValidCachePath/short_hash (0.00s)2603 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2604 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2605 --- PASS: TestIsValidCachePath/empty (0.00s)2606 --- PASS: TestIsValidCachePath/random_path (0.00s)2607 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2608 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2609 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2610 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2611 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2612 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2613 --- PASS: TestIsValidCachePath/realisation (0.00s)2614 --- PASS: TestIsValidCachePath/log (0.00s)2615 --- PASS: TestIsValidCachePath/ls (0.00s)2616 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2617 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2618 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2619 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2620=== CONT TestParseSingleRange/none2621=== CONT TestParseSingleRange/open-ended2622=== CONT TestParseSingleRange/start_far_past_EOF2623=== CONT TestParseSingleRange/start_past_EOF2624=== CONT TestParseSingleRange/single_byte2625=== CONT TestParseSingleRange/suffix_exceeds_size2626=== CONT TestParseSingleRange/suffix2627=== CONT TestParseSingleRange/end_clamped_to_size2628=== CONT TestParseSingleRange/malformed_both_empty2629=== CONT TestParseSingleRange/closed2630=== CONT TestParseSingleRange/malformed_end_before_start2631=== CONT TestParseSingleRange/multi-range_ignored2632=== CONT TestParseSingleRange/malformed_no_dash2633=== CONT TestParseSingleRange/unknown_unit2634--- PASS: TestParseSingleRange (0.00s)2635 --- PASS: TestParseSingleRange/none (0.00s)2636 --- PASS: TestParseSingleRange/open-ended (0.00s)2637 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2638 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2639 --- PASS: TestParseSingleRange/single_byte (0.00s)2640 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2641 --- PASS: TestParseSingleRange/suffix (0.00s)2642 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2643 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2644 --- PASS: TestParseSingleRange/closed (0.00s)2645 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2646 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2647 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2648 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2649=== CONT TestResolveDBConnectionString/flag_wins2650=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2651=== CONT TestResolveDBConnectionString/nothing_configured2652=== CONT TestResolveDBConnectionString/missing_file_is_an_error2653=== CONT TestResolveDBConnectionString/file_when_flag_empty2654=== CONT TestClientErrorHandling/InvalidStorePath2655--- PASS: TestResolveDBConnectionString (0.02s)2656 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2657 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2658 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2659 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2660 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)26612026/10/01 10:12:04 OK 20241026095416_initial_model.sql (284.41ms)26622026/10/01 10:12:04 OK 20251210153512_drop_unused_gin_index.sql (7.9ms)26632026/10/01 10:12:04 OK 20251218171726_add_pins.sql (28.95ms)26642026/10/01 10:12:04 OK 20260628120000_add_object_size_and_stats.sql (50.38ms)26652026/10/01 10:12:04 OK 20260905000000_add_claims.sql (112.38ms)26662026/10/01 10:12:04 OK 20260920000000_drop_claims.sql (54.59ms)26672026/10/01 10:12:04 INFO Received push request method=POST path=/api/pushes26682026/10/01 10:12:04 OK 20260923120000_add_pushes.sql (25.46ms)26692026/10/01 10:12:04 goose: successfully migrated database to version: 2026092312000026702026/10/01 10:12:04 OK 1_commit_pending_closure.sql (5.26ms)26712026/10/01 10:12:04 OK 2_object_stats_trigger.sql (818.58µs)26722026/10/01 10:12:04 OK 3_commit_push.sql (569.33µs)26732026/10/01 10:12:04 goose: up to current file version: 326742026/10/01 10:12:04 INFO Received complete push request method=POST path=/api/pushes/1/complete26752026/10/01 10:12:04 INFO Received push request method=POST path=/api/pushes26762026-10-01 10:12:04.833 UTC [13101] ERROR: relation "goose_db_version" does not exist at character 3626772026-10-01 10:12:04.833 UTC [13101] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26782026/10/01 10:12:04 INFO Aborted multipart uploads count=0 kept=026792026/10/01 10:12:04 WARN Force mode enabled - objects will be deleted immediately without grace period26802026/10/01 10:12:04 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2 objects-failed-to-delete=026812026/10/01 10:12:04 INFO Vacuumed table table=pending_closures26822026/10/01 10:12:04 INFO Vacuumed table table=pending_objects26832026/10/01 10:12:05 INFO Vacuumed table table=multipart_uploads26842026/10/01 10:12:05 INFO Vacuumed table table=closures26852026/10/01 10:12:05 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"26862026/10/01 10:12:05 WARN mTLS auth: bound subjects configured but subject DN unavailable26872026/10/01 10:12:05 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2688--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (3.04s)2689=== CONT TestClientErrorHandling/ServerNotAvailable26902026-10-01 10:12:05.121 UTC [13103] ERROR: relation "goose_db_version" does not exist at character 3626912026-10-01 10:12:05.121 UTC [13103] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26922026/10/01 10:12:05 INFO Vacuumed table table=objects26932026-10-01 10:12:05.126 UTC [13104] ERROR: relation "goose_db_version" does not exist at character 3626942026-10-01 10:12:05.126 UTC [13104] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26952026/10/01 10:12:05 INFO Received complete push request method=POST path=/api/pushes/2/complete2696--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (3.51s)2697=== CONT TestClientErrorHandling/InvalidAuthToken26982026/10/01 10:12:05 OK 20241026095416_initial_model.sql (256.77ms)26992026/10/01 10:12:05 OK 20251210153512_drop_unused_gin_index.sql (927.46µs)27002026/10/01 10:12:05 OK 20251218171726_add_pins.sql (18.56ms)27012026/10/01 10:12:05 OK 20260628120000_add_object_size_and_stats.sql (27.98ms)27022026/10/01 10:12:05 OK 20241026095416_initial_model.sql (58.79ms)27032026/10/01 10:12:05 OK 20251210153512_drop_unused_gin_index.sql (9.18ms)27042026-10-01 10:12:05.266 UTC [13109] ERROR: relation "goose_db_version" does not exist at character 3627052026-10-01 10:12:05.266 UTC [13109] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27062026/10/01 10:12:05 OK 20241026095416_initial_model.sql (78.28ms)27072026/10/01 10:12:05 OK 20260905000000_add_claims.sql (31.05ms)27082026/10/01 10:12:05 OK 20251210153512_drop_unused_gin_index.sql (16.32ms)27092026/10/01 10:12:05 OK 20251218171726_add_pins.sql (26.13ms)27102026/10/01 10:12:05 OK 20260920000000_drop_claims.sql (24.54ms)27112026/10/01 10:12:05 OK 20251218171726_add_pins.sql (9.86ms)27122026/10/01 10:12:05 OK 20260923120000_add_pushes.sql (1.89ms)27132026/10/01 10:12:05 goose: successfully migrated database to version: 2026092312000027142026/10/01 10:12:05 OK 20260628120000_add_object_size_and_stats.sql (10.35ms)27152026/10/01 10:12:05 OK 1_commit_pending_closure.sql (3.46ms)27162026/10/01 10:12:05 OK 20260628120000_add_object_size_and_stats.sql (4.26ms)27172026/10/01 10:12:05 OK 20260905000000_add_claims.sql (3.62ms)27182026/10/01 10:12:05 OK 2_object_stats_trigger.sql (662.67µs)27192026/10/01 10:12:05 OK 3_commit_push.sql (483.75µs)27202026/10/01 10:12:05 goose: up to current file version: 327212026-10-01 10:12:05.298 UTC [13110] ERROR: relation "goose_db_version" does not exist at character 3627222026-10-01 10:12:05.298 UTC [13110] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27232026/10/01 10:12:05 OK 20260920000000_drop_claims.sql (1.86ms)27242026/10/01 10:12:05 OK 20260923120000_add_pushes.sql (2.09ms)27252026/10/01 10:12:05 goose: successfully migrated database to version: 2026092312000027262026/10/01 10:12:05 OK 20260905000000_add_claims.sql (4.24ms)27272026/10/01 10:12:05 OK 1_commit_pending_closure.sql (2.03ms)27282026/10/01 10:12:05 OK 2_object_stats_trigger.sql (292.21µs)27292026/10/01 10:12:05 OK 3_commit_push.sql (223.96µs)27302026/10/01 10:12:05 goose: up to current file version: 327312026/10/01 10:12:05 OK 20260920000000_drop_claims.sql (9.68ms)27322026/10/01 10:12:05 OK 20260923120000_add_pushes.sql (12.15ms)27332026/10/01 10:12:05 goose: successfully migrated database to version: 2026092312000027342026/10/01 10:12:05 OK 1_commit_pending_closure.sql (1.22ms)27352026/10/01 10:12:05 OK 2_object_stats_trigger.sql (244.38µs)27362026/10/01 10:12:05 OK 3_commit_push.sql (159.71µs)27372026/10/01 10:12:05 goose: up to current file version: 327382026/10/01 10:12:05 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/present27392026/10/01 10:12:05 OK 20241026095416_initial_model.sql (105.41ms)27402026/10/01 10:12:05 OK 20251210153512_drop_unused_gin_index.sql (10.13ms)27412026/10/01 10:12:05 OK 20251218171726_add_pins.sql (26.12ms)27422026/10/01 10:12:05 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=183.811124ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27432026/10/01 10:12:05 OK 20260628120000_add_object_size_and_stats.sql (21.54ms)27442026/10/01 10:12:05 OK 20241026095416_initial_model.sql (155.39ms)27452026/10/01 10:12:05 OK 20251210153512_drop_unused_gin_index.sql (12.87ms)27462026/10/01 10:12:05 OK 20251218171726_add_pins.sql (25.76ms)27472026/10/01 10:12:05 INFO Received push request method=POST path=/api/pushes27482026/10/01 10:12:05 OK 20260905000000_add_claims.sql (60.6ms)27492026/10/01 10:12:05 OK 20260628120000_add_object_size_and_stats.sql (31.06ms)27502026/10/01 10:12:05 OK 20260920000000_drop_claims.sql (43.96ms)27512026/10/01 10:12:05 OK 20260923120000_add_pushes.sql (21.92ms)27522026/10/01 10:12:05 goose: successfully migrated database to version: 2026092312000027532026/10/01 10:12:05 OK 1_commit_pending_closure.sql (2.72ms)27542026/10/01 10:12:05 OK 2_object_stats_trigger.sql (539.17µs)27552026/10/01 10:12:05 OK 3_commit_push.sql (339.29µs)27562026/10/01 10:12:05 goose: up to current file version: 327572026/10/01 10:12:05 INFO Received complete push request method=POST path=/api/pushes/1/complete27582026/10/01 10:12:05 OK 20260905000000_add_claims.sql (55.39ms)2759--- PASS: TestPush_CompleteCommitsEveryRoot (3.28s)2760=== CONT TestCacheConfigHandler/full_config,_no_issuer2761=== CONT TestCacheConfigHandler/no_signing_keys27622026/10/01 10:12:05 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=439.714399ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2763=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2764=== CONT TestCacheConfigHandler/no_cache_url_configured2765--- PASS: TestCacheConfigHandler (0.00s)2766 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2767 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2768 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2769 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2770=== CONT TestService_RequireScope_OIDC/builder_may_write2771=== CONT TestService_RequireScope_OIDC/static_token_may_admin2772=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2773=== CONT TestService_RequireScope_OIDC/writer_implies_read2774=== CONT TestService_RequireScope_OIDC/reader_may_read2775=== CONT TestService_RequireScope_OIDC/static_token_may_write2776=== CONT TestService_RequireScope_OIDC/ops_may_not_write2777=== CONT TestService_RequireScope_OIDC/reader_may_not_write2778=== CONT TestService_RequireScope_OIDC/ops_may_admin2779=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2780=== CONT TestServerTLSConfig/no_client_CA2781=== CONT TestServerTLSConfig/not_a_PEM_file27822026/10/01 10:12:05 OK 20260920000000_drop_claims.sql (27.33ms)2783--- PASS: TestService_RequireScope_OIDC (1.52s)2784 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2785 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2786 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2787 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2788 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2789 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2790 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2791 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2792 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2793 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)27942026/10/01 10:12:05 OK 20260923120000_add_pushes.sql (19.09ms)27952026/10/01 10:12:05 goose: successfully migrated database to version: 2026092312000027962026/10/01 10:12:05 OK 1_commit_pending_closure.sql (2.52ms)27972026/10/01 10:12:05 OK 2_object_stats_trigger.sql (430.92µs)27982026/10/01 10:12:05 OK 3_commit_push.sql (360.58µs)27992026/10/01 10:12:05 goose: up to current file version: 32800=== CONT TestServerTLSConfig/missing_CA_file2801--- PASS: TestServerTLSConfig (0.00s)2802 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2803 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)2804 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2805=== CONT TestPush_RejectsBadRequests/no_roots28062026/10/01 10:12:05 INFO Received push request method=POST path=/api/pushes2807=== CONT TestPush_RejectsBadRequests/bad_root28082026/10/01 10:12:05 INFO Received push request method=POST path=/api/pushes2809=== CONT TestPush_RejectsBadRequests/root_not_in_objects28102026/10/01 10:12:05 INFO Received push request method=POST path=/api/pushes2811=== CONT TestPush_RejectsBadRequests/no_objects28122026/10/01 10:12:05 INFO Received push request method=POST path=/api/pushes2813=== CONT TestIsValidUploadKey/narinfo2814=== CONT TestIsValidUploadKey/realisation_plus_in_output2815--- PASS: TestPush_RejectsBadRequests (2.00s)2816 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2817 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2818 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2819 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2820=== CONT TestIsValidUploadKey/unknown_type2821=== CONT TestIsValidUploadKey/empty_key2822=== CONT TestIsValidUploadKey/absolute2823=== CONT TestIsValidUploadKey/traversal_nar2824=== CONT TestIsValidUploadKey/traversal2825=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2826=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2827=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2828=== CONT TestIsValidUploadKey/index.html2829=== CONT TestIsValidUploadKey/nix-cache-info2830=== CONT TestIsValidUploadKey/build_log_home-manager_file2831=== CONT TestIsValidUploadKey/realisation2832=== CONT TestIsValidUploadKey/build_log_equals2833=== CONT TestIsValidUploadKey/build_log_question_mark2834=== CONT TestIsValidUploadKey/build_log_plus_in_name2835=== CONT TestIsValidUploadKey/nar_plain2836=== CONT TestIsValidUploadKey/build_log2837=== CONT TestIsValidUploadKey/listing2838=== CONT TestIsValidUploadKey/nar_xz2839=== CONT TestIsValidUploadKey/nar_zst2840--- PASS: TestIsValidUploadKey (0.00s)2841 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2842 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2843 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2844 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2845 --- PASS: TestIsValidUploadKey/absolute (0.00s)2846 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2847 --- PASS: TestIsValidUploadKey/traversal (0.00s)2848 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2849 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2850 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2851 --- PASS: TestIsValidUploadKey/index.html (0.00s)2852 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2853 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2854 --- PASS: TestIsValidUploadKey/realisation (0.00s)2855 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2856 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2857 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2858 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2859 --- PASS: TestIsValidUploadKey/build_log (0.00s)2860 --- PASS: TestIsValidUploadKey/listing (0.00s)2861 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2862 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2863=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart28642026/10/01 10:12:05 INFO Received complete multipart upload request method=POST path=/2865=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure28662026/10/01 10:12:05 INFO Received uploads request method=POST path=/28672026/10/01 10:12:05 INFO Received uploads request method=POST path=/api/pending_closures28682026/10/01 10:12:05 INFO Aborted multipart uploads count=0 kept=028692026/10/01 10:12:05 WARN Force mode enabled - objects will be deleted immediately without grace period28702026/10/01 10:12:05 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."28712026/10/01 10:12:05 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."2872--- PASS: TestFailedS3DeleteKeepsTombstone (3.30s)2873=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts28742026/10/01 10:12:05 INFO Received request for more parts method=POST path=/2875=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info28762026/10/01 10:12:05 INFO Received uploads request method=POST path=/2877=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key28782026/10/01 10:12:05 INFO Received request for more parts method=POST path=/2879=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key28802026/10/01 10:12:05 INFO Received complete multipart upload request method=POST path=/2881=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal28822026/10/01 10:12:05 INFO Received uploads request method=POST path=/2883--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2884 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2885 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2886 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2887 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2888=== CONT TestProxyWriteTimeout/narinfo2889=== CONT TestProxyWriteTimeout/10_GiB_nar2890=== CONT TestProxyWriteTimeout/unknown_size2891=== CONT TestProxyWriteTimeout/1_GiB_nar2892--- PASS: TestProxyWriteTimeout (0.00s)2893 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2894 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2895 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2896 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2897=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2898=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected28992026/10/01 10:12:05 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]2900=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2901=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected29022026/10/01 10:12:05 WARN Authentication failed token_preview=eyJhbGciOi...hfn9V9WC_Q token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2903=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2904--- PASS: TestService_AuthMiddleware_OIDC (2.76s)2905 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2906 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2907 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2908 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2909--- PASS: TestUploadHandlersRejectOversizedBody (0.04s)2910 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)2911 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.27s)2912 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2913=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check29142026/10/01 10:12:06 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=851.534468ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29152026/10/01 10:12:06 INFO Received uploads request method=POST path=/api/pending_closures29162026-10-01 10:12:06.276 UTC [13120] ERROR: relation "goose_db_version" does not exist at character 3629172026-10-01 10:12:06.276 UTC [13120] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29182026/10/01 10:12:06 INFO Aborted multipart uploads count=0 kept=029192026/10/01 10:12:06 WARN Force mode enabled - objects will be deleted immediately without grace period29202026/10/01 10:12:06 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=029212026/10/01 10:12:06 INFO Vacuumed table table=pending_closures29222026/10/01 10:12:06 INFO Vacuumed table table=pending_objects29232026/10/01 10:12:06 INFO Vacuumed table table=multipart_uploads29242026/10/01 10:12:06 INFO Vacuumed table table=closures29252026-10-01 10:12:06.383 UTC [13121] ERROR: relation "goose_db_version" does not exist at character 3629262026-10-01 10:12:06.383 UTC [13121] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29272026/10/01 10:12:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete29282026-10-01 10:12:06.405 UTC [13122] ERROR: relation "goose_db_version" does not exist at character 3629292026-10-01 10:12:06.405 UTC [13122] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29302026/10/01 10:12:06 INFO Vacuumed table table=objects29312026/10/01 10:12:06 INFO Aborted multipart uploads count=0 kept=029322026/10/01 10:12:06 WARN Force mode enabled - objects will be deleted immediately without grace period29332026/10/01 10:12:06 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=029342026/10/01 10:12:06 INFO Vacuumed table table=pending_closures29352026/10/01 10:12:06 INFO Vacuumed table table=pending_objects29362026/10/01 10:12:06 INFO Vacuumed table table=multipart_uploads29372026/10/01 10:12:06 INFO Vacuumed table table=closures29382026/10/01 10:12:06 INFO Vacuumed table table=objects2939--- PASS: TestSweepSkipsRowsLockedByPush (3.56s)29402026/10/01 10:12:06 OK 20241026095416_initial_model.sql (195.37ms)29412026/10/01 10:12:06 OK 20251210153512_drop_unused_gin_index.sql (15.92ms)29422026/10/01 10:12:06 OK 20251218171726_add_pins.sql (27.64ms)29432026/10/01 10:12:06 OK 20260628120000_add_object_size_and_stats.sql (34.73ms)29442026/10/01 10:12:06 OK 20241026095416_initial_model.sql (160.07ms)29452026/10/01 10:12:06 OK 20251210153512_drop_unused_gin_index.sql (17.43ms)2946--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (3.48s)29472026/10/01 10:12:06 OK 20251218171726_add_pins.sql (39.37ms)29482026/10/01 10:12:06 OK 20260905000000_add_claims.sql (80.8ms)29492026/10/01 10:12:06 OK 20241026095416_initial_model.sql (217.6ms)29502026/10/01 10:12:06 OK 20251210153512_drop_unused_gin_index.sql (19.64ms)29512026/10/01 10:12:06 OK 20260628120000_add_object_size_and_stats.sql (56.17ms)29522026/10/01 10:12:06 OK 20260920000000_drop_claims.sql (54.68ms)29532026/10/01 10:12:06 OK 20251218171726_add_pins.sql (26.39ms)29542026/10/01 10:12:06 OK 20260923120000_add_pushes.sql (4.52ms)29552026/10/01 10:12:06 goose: successfully migrated database to version: 2026092312000029562026/10/01 10:12:06 OK 20260905000000_add_claims.sql (15.85ms)29572026/10/01 10:12:06 OK 1_commit_pending_closure.sql (5.32ms)29582026/10/01 10:12:06 OK 2_object_stats_trigger.sql (881.46µs)29592026/10/01 10:12:06 OK 3_commit_push.sql (596.96µs)29602026/10/01 10:12:06 goose: up to current file version: 329612026/10/01 10:12:06 OK 20260920000000_drop_claims.sql (15.57ms)29622026/10/01 10:12:06 OK 20260628120000_add_object_size_and_stats.sql (20.21ms)29632026/10/01 10:12:06 OK 20260923120000_add_pushes.sql (30.09ms)29642026/10/01 10:12:06 goose: successfully migrated database to version: 2026092312000029652026/10/01 10:12:06 OK 1_commit_pending_closure.sql (5.88ms)29662026/10/01 10:12:06 OK 2_object_stats_trigger.sql (1.05ms)29672026/10/01 10:12:06 OK 3_commit_push.sql (569.46µs)29682026/10/01 10:12:06 goose: up to current file version: 329692026/10/01 10:12:06 OK 20260905000000_add_claims.sql (59.21ms)29702026/10/01 10:12:06 OK 20260920000000_drop_claims.sql (38.61ms)29712026/10/01 10:12:06 OK 20260923120000_add_pushes.sql (21.13ms)29722026/10/01 10:12:06 goose: successfully migrated database to version: 2026092312000029732026/10/01 10:12:06 OK 1_commit_pending_closure.sql (4.4ms)29742026/10/01 10:12:06 OK 2_object_stats_trigger.sql (1.25ms)29752026/10/01 10:12:06 OK 3_commit_push.sql (1.17ms)29762026/10/01 10:12:06 goose: up to current file version: 329772026/10/01 10:12:06 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.530361501s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29782026/10/01 10:12:07 INFO Received uploads request method=POST path=/api/pending_closures29792026-10-01 10:12:07.128 UTC [13125] ERROR: relation "goose_db_version" does not exist at character 3629802026-10-01 10:12:07.128 UTC [13125] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2981--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (3.25s)29822026/10/01 10:12:07 INFO Aborted multipart uploads count=0 kept=029832026/10/01 10:12:07 WARN Force mode enabled - objects will be deleted immediately without grace period29842026/10/01 10:12:07 OK 20241026095416_initial_model.sql (239.83ms)29852026/10/01 10:12:07 OK 20251210153512_drop_unused_gin_index.sql (10.95ms)29862026/10/01 10:12:07 OK 20251218171726_add_pins.sql (63.38ms)29872026/10/01 10:12:07 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=029882026/10/01 10:12:07 INFO Vacuumed table table=pending_closures29892026/10/01 10:12:07 INFO Vacuumed table table=pending_objects29902026/10/01 10:12:07 INFO Vacuumed table table=multipart_uploads29912026/10/01 10:12:07 INFO Vacuumed table table=closures29922026/10/01 10:12:07 OK 20260628120000_add_object_size_and_stats.sql (34.86ms)29932026/10/01 10:12:07 INFO Vacuumed table table=objects2994--- PASS: TestGCSweepDeliversEachKeyOnce (3.36s)29952026/10/01 10:12:07 OK 20260905000000_add_claims.sql (91.7ms)29962026/10/01 10:12:07 OK 20260920000000_drop_claims.sql (50.2ms)29972026/10/01 10:12:07 OK 20260923120000_add_pushes.sql (27.32ms)29982026/10/01 10:12:07 goose: successfully migrated database to version: 2026092312000029992026/10/01 10:12:07 OK 1_commit_pending_closure.sql (1.94ms)30002026/10/01 10:12:07 OK 2_object_stats_trigger.sql (423.63µs)30012026/10/01 10:12:07 OK 3_commit_push.sql (333.33µs)30022026/10/01 10:12:07 goose: up to current file version: 330032026-10-01 10:12:08.059 UTC [13129] ERROR: relation "goose_db_version" does not exist at character 3630042026-10-01 10:12:08.059 UTC [13129] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC30052026-10-01 10:12:08.069 UTC [13131] ERROR: relation "goose_db_version" does not exist at character 3630062026-10-01 10:12:08.069 UTC [13131] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC30072026/10/01 10:12:08 OK 20241026095416_initial_model.sql (6.19ms)30082026/10/01 10:12:08 OK 20241026095416_initial_model.sql (6.04ms)30092026/10/01 10:12:08 OK 20251210153512_drop_unused_gin_index.sql (570.79µs)30102026/10/01 10:12:08 OK 20251210153512_drop_unused_gin_index.sql (580.58µs)30112026/10/01 10:12:08 OK 20251218171726_add_pins.sql (1.22ms)30122026/10/01 10:12:08 OK 20251218171726_add_pins.sql (1.25ms)30132026/10/01 10:12:08 OK 20260628120000_add_object_size_and_stats.sql (1.33ms)30142026/10/01 10:12:08 OK 20260628120000_add_object_size_and_stats.sql (1.32ms)30152026/10/01 10:12:08 OK 20260905000000_add_claims.sql (1.59ms)30162026/10/01 10:12:08 OK 20260905000000_add_claims.sql (1.59ms)30172026/10/01 10:12:08 OK 20260920000000_drop_claims.sql (969.17µs)30182026/10/01 10:12:08 OK 20260920000000_drop_claims.sql (984.58µs)30192026/10/01 10:12:08 OK 20260923120000_add_pushes.sql (554.88µs)30202026/10/01 10:12:08 goose: successfully migrated database to version: 2026092312000030212026/10/01 10:12:08 OK 20260923120000_add_pushes.sql (541.58µs)30222026/10/01 10:12:08 goose: successfully migrated database to version: 2026092312000030232026/10/01 10:12:08 OK 1_commit_pending_closure.sql (1.24ms)30242026/10/01 10:12:08 OK 1_commit_pending_closure.sql (1.31ms)30252026/10/01 10:12:08 OK 2_object_stats_trigger.sql (278.33µs)30262026/10/01 10:12:08 OK 2_object_stats_trigger.sql (283.29µs)30272026/10/01 10:12:08 OK 3_commit_push.sql (249.42µs)30282026/10/01 10:12:08 goose: up to current file version: 330292026/10/01 10:12:08 OK 3_commit_push.sql (285.33µs)30302026/10/01 10:12:08 goose: up to current file version: 330312026/10/01 10:12:08 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30322026/10/01 10:12:08 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30332026/10/01 10:12:08 INFO Received uploads request method=POST path=/api/pending_closures30342026/10/01 10:12:08 INFO Aborted multipart uploads count=0 kept=030352026/10/01 10:12:08 WARN Force mode enabled - objects will be deleted immediately without grace period30362026/10/01 10:12:08 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=030372026/10/01 10:12:08 INFO Vacuumed table table=pending_closures30382026/10/01 10:12:08 INFO Vacuumed table table=pending_objects30392026/10/01 10:12:08 INFO Vacuumed table table=multipart_uploads30402026/10/01 10:12:08 INFO Vacuumed table table=closures30412026/10/01 10:12:08 INFO Vacuumed table table=objects30422026/10/01 10:12:08 INFO Received uploads request method=POST path=/api/pending_closures30432026/10/01 10:12:08 INFO Aborted multipart uploads count=0 kept=030442026/10/01 10:12:08 WARN Force mode enabled - objects will be deleted immediately without grace period30452026/10/01 10:12:08 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=030462026/10/01 10:12:08 INFO Vacuumed table table=pending_closures30472026/10/01 10:12:08 INFO Vacuumed table table=pending_objects30482026/10/01 10:12:08 INFO Vacuumed table table=multipart_uploads30492026/10/01 10:12:08 INFO Vacuumed table table=closures30502026/10/01 10:12:08 INFO Vacuumed table table=objects3051--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)3052 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (2.37s)3053 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (2.53s)30542026/10/01 10:12:08 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-config30552026/10/01 10:12:08 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=184.754932ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30562026/10/01 10:12:08 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=431.161508ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30572026/10/01 10:12:09 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=804.402096ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30582026/10/01 10:12:10 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.544746557s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30592026/10/01 10:12:11 WARN Rate limiter enabled after throttle name=s3-test rate=530602026/10/01 10:12:11 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."3061=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle3062 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=103063 throttle_test.go:215: Rate limiter: enabled=true, rate=5.003064--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (8.84s)30652026/10/01 10:12:11 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"30662026/10/01 10:12:11 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-config30672026/10/01 10:12:11 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=191.946017ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30682026/10/01 10:12:11 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=378.658785ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30692026/10/01 10:12:12 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=730.685594ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30702026/10/01 10:12:13 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.68168069s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30712026/10/01 10:12:14 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30722026/10/01 10:12:14 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=209.800547ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30732026/10/01 10:12:15 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=386.016608ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30742026/10/01 10:12:15 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=823.851626ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30752026/10/01 10:12:16 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.690062015s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3076--- PASS: TestClientErrorHandling (0.00s)3077 --- PASS: TestClientErrorHandling/InvalidStorePath (3.45s)3078 --- PASS: TestClientErrorHandling/InvalidAuthToken (3.09s)3079 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.82s)3080PASS3081{"timestamp":"2026-10-01T10:12:17.943403Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:58962","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(8)"}30822026-10-01 10:12:18.083 UTC [12697] LOG: received smart shutdown request30832026-10-01 10:12:18.084 UTC [12697] LOG: background worker "logical replication launcher" (PID 12707) exited with exit code 130842026-10-01 10:12:18.090 UTC [12702] LOG: shutting down30852026-10-01 10:12:18.090 UTC [12702] LOG: checkpoint starting: shutdown immediate30862026-10-01 10:12:19.303 UTC [12702] LOG: checkpoint complete: wrote 12857 buffers (78.5%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 25 recycled; write=0.690 s, sync=0.485 s, total=1.213 s; sync files=28648, longest=0.001 s, average=0.001 s; distance=403223 kB, estimate=403223 kB; lsn=0/1A152C40, redo lsn=0/1A152C4030872026-10-01 10:12:19.308 UTC [12697] LOG: database system is shut down3088Running OIDC tests...3089=== RUN TestAudienceForIssuer3090=== PAUSE TestAudienceForIssuer3091=== RUN TestGlobMatch3092=== PAUSE TestGlobMatch3093=== RUN TestValidateToken_ValidToken3094=== PAUSE TestValidateToken_ValidToken3095=== RUN TestValidateToken_WrongAudience3096=== PAUSE TestValidateToken_WrongAudience3097=== RUN TestValidateToken_Expired3098=== PAUSE TestValidateToken_Expired3099=== RUN TestValidateToken_BoundClaimsMismatch3100=== PAUSE TestValidateToken_BoundClaimsMismatch3101=== RUN TestValidateToken_BoundSubjectMismatch3102=== PAUSE TestValidateToken_BoundSubjectMismatch3103=== RUN TestValidateToken_MultipleProviders3104=== PAUSE TestValidateToken_MultipleProviders3105=== RUN TestValidateToken_NoMatchingProvider3106=== PAUSE TestValidateToken_NoMatchingProvider3107=== RUN TestValidateToken_KubernetesServiceAccount3108=== PAUSE TestValidateToken_KubernetesServiceAccount3109=== RUN TestNewValidator_KubernetesRequiresCA3110=== PAUSE TestNewValidator_KubernetesRequiresCA3111=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3112=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3113=== RUN TestPins_ReservedForMatchingRule3114=== PAUSE TestPins_ReservedForMatchingRule3115=== RUN TestPins_TopLevelShorthand3116=== PAUSE TestPins_TopLevelShorthand3117=== RUN TestPins_ConfigValidation3118=== PAUSE TestPins_ConfigValidation3119=== RUN TestScopes_LegacyProviderDefaultsToWrite3120=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3121=== RUN TestScopes_Rules3122=== PAUSE TestScopes_Rules3123=== RUN TestScopes_ConfigValidation3124=== PAUSE TestScopes_ConfigValidation3125=== CONT TestAudienceForIssuer3126--- PASS: TestAudienceForIssuer (0.00s)3127=== CONT TestValidateToken_NoMatchingProvider3128=== CONT TestPins_ConfigValidation3129=== CONT TestValidateToken_KubernetesServiceAccount3130=== CONT TestPins_ReservedForMatchingRule3131=== CONT TestScopes_ConfigValidation3132=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3133=== CONT TestPins_TopLevelShorthand3134=== CONT TestScopes_Rules3135=== CONT TestScopes_LegacyProviderDefaultsToWrite3136=== CONT TestNewValidator_KubernetesRequiresCA3137--- PASS: TestPins_ConfigValidation (0.01s)3138--- PASS: TestScopes_ConfigValidation (0.01s)3139=== CONT TestValidateToken_Expired3140=== CONT TestValidateToken_BoundSubjectMismatch31412026/10/01 10:12:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59310/oidc3142--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)3143=== CONT TestValidateToken_WrongAudience31442026/10/01 10:12:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59312/oidc3145--- PASS: TestValidateToken_Expired (0.04s)3146=== CONT TestValidateToken_ValidToken31472026/10/01 10:12:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59316/oidc31482026/10/01 10:12:20 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:593143149--- PASS: TestPins_ReservedForMatchingRule (0.05s)3150=== CONT TestGlobMatch3151=== RUN TestGlobMatch/foo_foo3152=== PAUSE TestGlobMatch/foo_foo3153=== RUN TestGlobMatch/foo_bar3154=== PAUSE TestGlobMatch/foo_bar3155=== RUN TestGlobMatch/*_3156=== PAUSE TestGlobMatch/*_3157=== RUN TestGlobMatch/*_anything3158=== PAUSE TestGlobMatch/*_anything3159=== RUN TestGlobMatch/foo*_foo3160=== PAUSE TestGlobMatch/foo*_foo3161=== RUN TestGlobMatch/foo*_foobar3162=== PAUSE TestGlobMatch/foo*_foobar3163=== RUN TestGlobMatch/foo*_bar3164=== PAUSE TestGlobMatch/foo*_bar3165=== RUN TestGlobMatch/*bar_bar3166=== PAUSE TestGlobMatch/*bar_bar3167=== RUN TestGlobMatch/*bar_foobar3168=== PAUSE TestGlobMatch/*bar_foobar3169=== RUN TestGlobMatch/*bar_foo3170=== PAUSE TestGlobMatch/*bar_foo3171=== RUN TestGlobMatch/foo*bar_foobar3172=== PAUSE TestGlobMatch/foo*bar_foobar3173=== RUN TestGlobMatch/foo*bar_foo123bar3174=== PAUSE TestGlobMatch/foo*bar_foo123bar3175=== RUN TestGlobMatch/foo*bar_foobarbaz3176=== PAUSE TestGlobMatch/foo*bar_foobarbaz3177=== RUN TestGlobMatch/*/*_foo/bar3178=== PAUSE TestGlobMatch/*/*_foo/bar3179=== RUN TestGlobMatch/*/*_foo3180=== PAUSE TestGlobMatch/*/*_foo3181=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3182=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3183=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03184=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03185=== RUN TestGlobMatch/refs/*/main_refs/heads/main3186=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3187=== RUN TestGlobMatch/fo?_foo3188=== PAUSE TestGlobMatch/fo?_foo3189=== RUN TestGlobMatch/fo?_fo3190=== PAUSE TestGlobMatch/fo?_fo3191=== RUN TestGlobMatch/fo?_fooo3192=== PAUSE TestGlobMatch/fo?_fooo3193=== RUN TestGlobMatch/?oo_foo3194=== PAUSE TestGlobMatch/?oo_foo3195=== RUN TestGlobMatch/?oo_boo3196=== PAUSE TestGlobMatch/?oo_boo3197=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3198=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3199=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3200=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3201=== CONT TestValidateToken_MultipleProviders3202--- PASS: TestValidateToken_KubernetesServiceAccount (0.05s)3203=== CONT TestValidateToken_BoundClaimsMismatch32042026/10/01 10:12:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59319/oidc32052026/10/01 10:12:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59321/oidc3206--- PASS: TestScopes_Rules (0.09s)3207=== CONT TestGlobMatch/foo_foo3208=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3209=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3210=== CONT TestGlobMatch/?oo_boo3211=== CONT TestGlobMatch/?oo_foo3212=== CONT TestGlobMatch/fo?_fooo3213=== CONT TestGlobMatch/fo?_fo3214=== CONT TestGlobMatch/fo?_foo3215=== CONT TestGlobMatch/refs/*/main_refs/heads/main3216=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03217=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3218=== CONT TestGlobMatch/*/*_foo3219=== CONT TestGlobMatch/*/*_foo/bar3220=== CONT TestGlobMatch/foo*bar_foobarbaz3221=== CONT TestGlobMatch/foo*bar_foo123bar3222=== CONT TestGlobMatch/foo*bar_foobar3223=== CONT TestGlobMatch/*_anything3224=== CONT TestGlobMatch/foo*_foo3225=== CONT TestGlobMatch/*_3226=== CONT TestGlobMatch/*bar_foobar3227=== CONT TestGlobMatch/foo_bar3228=== CONT TestGlobMatch/*bar_foo3229=== CONT TestGlobMatch/foo*_bar3230=== CONT TestGlobMatch/*bar_bar3231=== CONT TestGlobMatch/foo*_foobar3232--- PASS: TestGlobMatch (0.00s)3233 --- PASS: TestGlobMatch/foo_foo (0.00s)3234 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3235 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3236 --- PASS: TestGlobMatch/?oo_boo (0.00s)3237 --- PASS: TestGlobMatch/?oo_foo (0.00s)3238 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3239 --- PASS: TestGlobMatch/fo?_fo (0.00s)3240 --- PASS: TestGlobMatch/fo?_foo (0.00s)3241 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3242 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3243 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3244 --- PASS: TestGlobMatch/*/*_foo (0.00s)3245 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3246 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3247 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3248 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3249 --- PASS: TestGlobMatch/*_anything (0.00s)3250 --- PASS: TestGlobMatch/foo*_foo (0.00s)3251 --- PASS: TestGlobMatch/*_ (0.00s)3252 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3253 --- PASS: TestGlobMatch/foo_bar (0.00s)3254 --- PASS: TestGlobMatch/*bar_foo (0.00s)3255 --- PASS: TestGlobMatch/foo*_bar (0.00s)3256 --- PASS: TestGlobMatch/*bar_bar (0.00s)3257 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3258--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.09s)32592026/10/01 10:12:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59323/oidc32602026/10/01 10:12:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59325/oidc3261--- PASS: TestValidateToken_ValidToken (0.04s)32622026/10/01 10:12:20 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:59318/oidc3263--- PASS: TestPins_TopLevelShorthand (0.09s)32642026/10/01 10:12:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59329/oidc3265--- PASS: TestValidateToken_NoMatchingProvider (0.09s)3266--- PASS: TestValidateToken_BoundClaimsMismatch (0.04s)32672026/10/01 10:12:20 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233268--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.10s)32692026/10/01 10:12:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59333/oidc3270--- PASS: TestValidateToken_WrongAudience (0.08s)32712026/10/01 10:12:20 http: TLS handshake error from 127.0.0.1:59337: read tcp 127.0.0.1:59336->127.0.0.1:59337: use of closed network connection3272--- PASS: TestNewValidator_KubernetesRequiresCA (0.14s)32732026/10/01 10:12:20 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:59335/oidc32742026/10/01 10:12:20 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:59338/oidc3275--- PASS: TestValidateToken_MultipleProviders (0.17s)3276PASS3277Running hook tests...3278=== RUN TestSendPathsEmpty3279=== PAUSE TestSendPathsEmpty3280=== RUN TestQueueEnqueueAndFetch3281=== PAUSE TestQueueEnqueueAndFetch3282=== RUN TestQueueDeduplication3283=== PAUSE TestQueueDeduplication3284=== RUN TestQueueRemove3285=== PAUSE TestQueueRemove3286=== RUN TestQueueFetchBatchLimit3287=== PAUSE TestQueueFetchBatchLimit3288=== RUN TestQueueRetryMovesToBack3289=== PAUSE TestQueueRetryMovesToBack3290=== RUN TestQueueFetchRemoveLifecycle3291=== PAUSE TestQueueFetchRemoveLifecycle3292=== RUN TestQueueConcurrentWriters3293=== PAUSE TestQueueConcurrentWriters3294=== RUN TestQueueRemoveLargeClosure3295=== PAUSE TestQueueRemoveLargeClosure3296=== RUN TestServerClientIntegration3297=== PAUSE TestServerClientIntegration3298=== RUN TestServerQueueError3299=== PAUSE TestServerQueueError3300=== RUN TestGetListenerSocketActivation3301 server_test.go:210: === RUN TestGetListenerSocketActivation3302 --- PASS: TestGetListenerSocketActivation (0.00s)3303 PASS3304 3305--- PASS: TestGetListenerSocketActivation (0.01s)3306=== RUN TestDrainIsolatesPoisonPath3307=== PAUSE TestDrainIsolatesPoisonPath3308=== RUN TestRunNotBlockedByPoisonHead3309=== PAUSE TestRunNotBlockedByPoisonHead3310=== RUN TestDrainGivesUpWhenServerDown3311=== PAUSE TestDrainGivesUpWhenServerDown3312=== RUN TestFailedPathPrunedByLaterClosure3313=== PAUSE TestFailedPathPrunedByLaterClosure3314=== RUN TestWorkerUploadsAndRemoves3315=== PAUSE TestWorkerUploadsAndRemoves3316=== RUN TestWorkerSkipsGCdPaths3317=== PAUSE TestWorkerSkipsGCdPaths3318=== RUN TestWorkerPrunesClosureDeps3319=== PAUSE TestWorkerPrunesClosureDeps3320=== RUN TestDrainTimeout3321=== PAUSE TestDrainTimeout3322=== CONT TestSendPathsEmpty3323=== CONT TestServerQueueError3324--- PASS: TestSendPathsEmpty (0.00s)3325=== CONT TestServerClientIntegration3326=== CONT TestQueueRemoveLargeClosure3327=== CONT TestWorkerUploadsAndRemoves3328=== CONT TestWorkerPrunesClosureDeps3329=== CONT TestWorkerSkipsGCdPaths3330=== CONT TestDrainGivesUpWhenServerDown3331=== CONT TestFailedPathPrunedByLaterClosure3332=== CONT TestRunNotBlockedByPoisonHead3333=== CONT TestQueueFetchBatchLimit33342026/10/01 10:12:21 ERROR Failed to queue paths error="permission denied" count=13335--- PASS: TestServerQueueError (0.00s)3336=== CONT TestQueueConcurrentWriters3337--- PASS: TestServerClientIntegration (0.00s)3338=== CONT TestQueueFetchRemoveLifecycle33392026/10/01 10:12:21 INFO Upload queue status pending=233402026/10/01 10:12:21 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-12646-3956915670/TestWorkerSkipsGCdPaths3634835460/002/nonexistent33412026/10/01 10:12:21 INFO Uploading batch count=133422026/10/01 10:12:21 INFO Upload queue status pending=233432026/10/01 10:12:21 INFO Uploading batch count=133442026/10/01 10:12:21 ERROR Upload failed error="upload failed" count=13345--- PASS: TestQueueFetchBatchLimit (0.01s)3346=== CONT TestQueueRetryMovesToBack33472026/10/01 10:12:21 INFO Upload queue status pending=233482026/10/01 10:12:21 INFO Uploading batch count=133492026/10/01 10:12:21 INFO Uploading batch count=23350--- PASS: TestQueueFetchRemoveLifecycle (0.01s)3351=== CONT TestDrainIsolatesPoisonPath33522026/10/01 10:12:21 INFO Upload queue status pending=333532026/10/01 10:12:21 INFO Uploading batch count=133542026/10/01 10:12:21 INFO Uploading batch count=133552026/10/01 10:12:21 ERROR Upload failed error="upload failed" count=133562026/10/01 10:12:21 INFO Uploading batch count=233572026/10/01 10:12:21 ERROR Upload failed error="upload failed" count=233582026/10/01 10:12:21 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-12646-3956915670/TestDrainGivesUpWhenServerDown173808751/002/a33592026/10/01 10:12:21 INFO Uploading batch count=133602026/10/01 10:12:21 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-12646-3956915670/TestDrainGivesUpWhenServerDown173808751/002/b33612026/10/01 10:12:21 INFO Uploading batch count=233622026/10/01 10:12:21 ERROR Upload failed error="upload failed" count=233632026/10/01 10:12:21 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-12646-3956915670/TestDrainGivesUpWhenServerDown173808751/002/c33642026/10/01 10:12:21 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-12646-3956915670/TestDrainGivesUpWhenServerDown173808751/002/d33652026/10/01 10:12:21 INFO Uploading batch count=233662026/10/01 10:12:21 ERROR Upload failed error="upload failed" count=233672026/10/01 10:12:21 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-12646-3956915670/TestDrainGivesUpWhenServerDown173808751/002/e33682026/10/01 10:12:21 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-12646-3956915670/TestDrainGivesUpWhenServerDown173808751/002/f3369--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)3370=== CONT TestQueueDeduplication33712026/10/01 10:12:21 ERROR Drain finished with paths left in queue remaining=1033722026/10/01 10:12:21 INFO Uploading batch count=433732026/10/01 10:12:21 ERROR Upload failed error="upload failed" count=43374--- PASS: TestQueueRetryMovesToBack (0.00s)3375=== CONT TestQueueRemove33762026/10/01 10:12:21 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-12646-3956915670/TestDrainIsolatesPoisonPath969638664/002/bbb33772026/10/01 10:12:21 INFO Uploading batch count=133782026/10/01 10:12:21 ERROR Upload failed error="upload failed" count=133792026/10/01 10:12:21 INFO Uploading batch count=133802026/10/01 10:12:21 ERROR Upload failed error="upload failed" count=13381--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3382=== CONT TestQueueEnqueueAndFetch33832026/10/01 10:12:21 INFO Uploading batch count=133842026/10/01 10:12:21 ERROR Upload failed error="upload failed" count=133852026/10/01 10:12:21 ERROR Drain finished with paths left in queue remaining=13386--- PASS: TestQueueDeduplication (0.00s)3387=== CONT TestDrainTimeout3388--- PASS: TestQueueRemove (0.00s)3389--- PASS: TestDrainIsolatesPoisonPath (0.01s)3390--- PASS: TestQueueEnqueueAndFetch (0.00s)33912026/10/01 10:12:21 INFO Uploading batch count=23392--- PASS: TestWorkerPrunesClosureDeps (0.03s)3393--- PASS: TestWorkerUploadsAndRemoves (0.03s)3394--- PASS: TestWorkerSkipsGCdPaths (0.03s)3395--- PASS: TestQueueRemoveLargeClosure (0.06s)3396--- PASS: TestQueueConcurrentWriters (0.15s)33972026/10/01 10:12:21 ERROR Upload failed error="context deadline exceeded" count=233982026/10/01 10:12:21 ERROR Drain finished with paths left in queue remaining=43399--- PASS: TestDrainTimeout (0.21s)34002026/10/01 10:12:22 INFO Uploading batch count=134012026/10/01 10:12:22 INFO Uploading batch count=134022026/10/01 10:12:22 INFO Uploading batch count=134032026/10/01 10:12:22 ERROR Upload failed error="upload failed" count=134042026/10/01 10:12:22 INFO Uploading batch count=134052026/10/01 10:12:22 ERROR Upload failed error="upload failed" count=134062026/10/01 10:12:22 INFO Uploading batch count=134072026/10/01 10:12:22 ERROR Upload failed error="upload failed" count=134082026/10/01 10:12:22 INFO Uploading batch count=134092026/10/01 10:12:22 ERROR Upload failed error="upload failed" count=134102026/10/01 10:12:22 ERROR Drain finished with paths left in queue remaining=13411--- PASS: TestRunNotBlockedByPoisonHead (1.04s)3412PASS