niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #309
· 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.05s)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 TestScriptTokenBadJSON96=== CONT TestScriptTokenEmptyCommand97--- PASS: TestScriptTokenEmptyCommand (0.00s)98=== CONT TestParsePathInfoJSON99=== RUN TestParsePathInfoJSON/Nix_format100=== PAUSE TestParsePathInfoJSON/Nix_format101=== RUN TestParsePathInfoJSON/Lix_format102=== PAUSE TestParsePathInfoJSON/Lix_format103=== RUN TestParsePathInfoJSON/empty_input104=== CONT TestScriptTokenScriptFails105=== CONT TestEncodeNixBase32WithRealHash106--- PASS: TestEncodeNixBase32WithRealHash (0.00s)107=== CONT TestPathInfoHashCompatibility108=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)109=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)110=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon111=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon112=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI113=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI114=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512115=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512116=== CONT TestGetStorePathHash117=== RUN TestGetStorePathHash/valid_store_path118=== PAUSE TestGetStorePathHash/valid_store_path119=== RUN TestGetStorePathHash/basename_without_hyphen_should_error120=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error121=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error122=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error123=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error124=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error125=== CONT TestConvertHashToNix32126=== CONT TestResolveStorePath127=== RUN TestConvertHashToNix32/SRI_format_to_Nix32128=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32129=== CONT TestRateLimiterFeedback130=== RUN TestRateLimiterFeedback/429_enables_limiter131=== PAUSE TestRateLimiterFeedback/429_enables_limiter132=== CONT TestPathInfoCACompatibility133=== CONT TestParsePathInfoJSONMultiplePaths134=== RUN TestPathInfoCACompatibility/null_ca_field135=== PAUSE TestPathInfoCACompatibility/null_ca_field136=== PAUSE TestParsePathInfoJSON/empty_input137=== RUN TestParsePathInfoJSON/whitespace_only138=== RUN TestPathInfoCACompatibility/old_string_format_-_text139=== PAUSE TestParsePathInfoJSON/whitespace_only140=== RUN TestParsePathInfoJSON/invalid_JSON141=== PAUSE TestParsePathInfoJSON/invalid_JSON142=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text143=== CONT TestDoWithRetry_BodyReplayedViaGetBody144=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive145=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess146=== RUN TestConvertHashToNix32/already_Nix32_format147=== RUN TestRateLimiterFeedback/503_enables_limiter148=== PAUSE TestConvertHashToNix32/already_Nix32_format149=== RUN TestConvertHashToNix32/invalid_format150=== PAUSE TestRateLimiterFeedback/503_enables_limiter151=== PAUSE TestConvertHashToNix32/invalid_format152=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter153=== CONT TestSetClientTLS154=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter155=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter156=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter157=== CONT TestScriptTokenEmptyToken158=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths159--- PASS: TestResolveStorePath (0.00s)160=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths161=== CONT TestClientSignaturesByStorePath162=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths163--- PASS: TestClientSignaturesByStorePath (0.00s)164=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths165=== CONT TestScriptTokenCachesUntilRefresh166=== CONT TestStreamPushReportsSignatures167=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive1682026/10/01 09:30:21 WARN Rate limiter enabled after throttle name=server-test rate=5169=== RUN TestPathInfoCACompatibility/new_structured_format_-_text170=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text171=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method172=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method173=== CONT TestScriptTokenNoExpiryRerunsEveryCall1742026/10/01 09:30:21 ERROR Upload failed error=boom count=1175--- PASS: TestStreamPushReportsSignatures (0.00s)176=== CONT TestStreamPushRequestLine1772026/10/01 09:30:21 ERROR Upload failed error=boom count=11782026/10/01 09:30:21 WARN Rate limiter enabled after throttle name=server-test rate=51792026/10/01 09:30:21 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:64709180--- PASS: TestScriptTokenScriptFails (0.01s)181=== CONT TestFileTokenEmpty182--- PASS: TestDoServerRequestAttachesToken (0.01s)183=== CONT TestFileTokenMissing1842026/10/01 09:30:21 WARN Rate limiter backed off name=server-test rate=51852026/10/01 09:30:21 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:64709186--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)187=== CONT TestStreamPushGivesUpOnDeadServer1882026/10/01 09:30:21 ERROR Upload failed error="connection refused" count=201892026/10/01 09:30:21 ERROR Server seems unavailable, giving up on batch untried=17190=== RUN TestSetClientTLS/rejects_connection_without_client_cert191--- PASS: TestFileTokenEmpty (0.00s)192=== CONT TestFileTokenReadsAndCaches193=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert194=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA195=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA196=== RUN TestSetClientTLS/preserves_debug_logging_transport197=== PAUSE TestSetClientTLS/preserves_debug_logging_transport198=== CONT TestStreamPushIsolatesFailures199--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)200=== CONT TestStaticToken2012026/10/01 09:30:21 ERROR Upload failed error="bad path" count=3202--- PASS: TestStaticToken (0.00s)203=== CONT TestStreamPushBatchesUnderLoad204--- PASS: TestStreamPushIsolatesFailures (0.00s)205=== CONT TestSetClientTLSErrors206--- PASS: TestFileTokenMissing (0.00s)207=== CONT TestStreamPushReportsEveryPath208--- PASS: TestFileTokenReadsAndCaches (0.00s)209=== CONT TestSetClientTLSDoesNotMutateDefaultTransport210--- PASS: TestStreamPushReportsEveryPath (0.00s)211=== CONT TestShellSplitErrors212--- PASS: TestShellSplitErrors (0.00s)213=== CONT TestShellSplit214--- PASS: TestShellSplit (0.00s)215=== CONT TestUploadMultipart_SupersededByPeer216=== RUN TestUploadMultipart_SupersededByPeer/exists217=== PAUSE TestUploadMultipart_SupersededByPeer/exists218=== RUN TestUploadMultipart_SupersededByPeer/missing219=== PAUSE TestUploadMultipart_SupersededByPeer/missing220=== CONT TestEncodeNixBase32221=== RUN TestEncodeNixBase32/test_string_hash222=== PAUSE TestEncodeNixBase32/test_string_hash223=== RUN TestEncodeNixBase32/empty_input224=== PAUSE TestEncodeNixBase32/empty_input225=== CONT TestDumpPathWriterError226=== RUN TestSetClientTLSErrors/missing_cert_file227=== PAUSE TestSetClientTLSErrors/missing_cert_file228=== RUN TestSetClientTLSErrors/missing_key_file229=== PAUSE TestSetClientTLSErrors/missing_key_file230=== RUN TestSetClientTLSErrors/missing_ca_file231=== PAUSE TestSetClientTLSErrors/missing_ca_file232=== RUN TestSetClientTLSErrors/invalid_ca_file233=== PAUSE TestSetClientTLSErrors/invalid_ca_file234=== CONT TestDumpPathSingleFile235--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)236=== 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 TestCaseHackSuffix246--- PASS: TestScriptTokenEmptyToken (0.01s)247=== CONT TestPartSizeForNAR248=== RUN TestPartSizeForNAR/zero_stays_at_minimum249=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum250=== RUN TestPartSizeForNAR/small_stays_at_minimum251=== PAUSE TestPartSizeForNAR/small_stays_at_minimum252=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum253=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum254=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts255=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts256=== RUN TestPartSizeForNAR/1_TiB257=== PAUSE TestPartSizeForNAR/1_TiB258=== RUN TestPartSizeForNAR/5_TiB_S3_max_object259=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object260=== RUN TestPartSizeForNAR/capped_at_5_GiB261=== PAUSE TestPartSizeForNAR/capped_at_5_GiB262=== CONT TestUploadMultipart_PartsInParallel263--- PASS: TestStreamPushRequestLine (0.02s)264=== CONT TestRegisterUploadedObjectReusesConnections265--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)266=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)267=== CONT TestGetStorePathHash/valid_store_path268=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon269=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI270=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512271--- PASS: TestPathInfoHashCompatibility (0.00s)272 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)273 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)274 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)275 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)276=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error277=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error278=== CONT TestGetStorePathHash/basename_without_hyphen_should_error279--- PASS: TestGetStorePathHash (0.00s)280 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)281 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)282 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)283 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)284=== CONT TestParsePathInfoJSON/invalid_JSON285=== CONT TestParsePathInfoJSON/Nix_format286=== CONT TestParsePathInfoJSON/whitespace_only287=== CONT TestParsePathInfoJSON/empty_input288=== CONT TestParsePathInfoJSON/Lix_format289--- PASS: TestParsePathInfoJSON (0.00s)290 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)291 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)292 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)293 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)294 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)295=== CONT TestConvertHashToNix32/SRI_format_to_Nix32296=== CONT TestRateLimiterFeedback/429_enables_limiter2972026/10/01 09:30:21 WARN Rate limiter enabled after throttle name=server-test rate=52982026/10/01 09:30:21 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:647842992026/10/01 09:30:21 WARN Rate limiter backed off name=server-test rate=5300=== CONT TestConvertHashToNix32/invalid_format301=== CONT TestConvertHashToNix32/already_Nix32_format302--- PASS: TestConvertHashToNix32 (0.00s)303 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)304 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)305 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)306=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter307=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter308=== CONT TestRateLimiterFeedback/503_enables_limiter309--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)310=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths3112026/10/01 09:30:21 WARN Rate limiter enabled after throttle name=server-test rate=53122026/10/01 09:30:21 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:64790313=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths314--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)315 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)316 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)317=== CONT TestPathInfoCACompatibility/null_ca_field318=== CONT TestPathInfoCACompatibility/new_structured_format_-_text319=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method320=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive321=== CONT TestPathInfoCA2026/10/01 09:30:21 WARN Rate limiter backed off name=server-test rate=5322Compatibility/old_string_format_-_text323=== CONT TestSetClientTLS/preserves_debug_logging_transport324--- PASS: TestRateLimiterFeedback (0.00s)325 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)326 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)327 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)328 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)329=== CONT TestSetClientTLS/rejects_connection_without_client_cert330--- PASS: TestPathInfoCACompatibility (0.00s)331 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)332 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)333 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)334 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)335 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)336=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA337--- PASS: TestDumpPathWriterError (0.04s)338=== CONT TestUploadMultipart_SupersededByPeer/exists339=== CONT TestUploadMultipart_SupersededByPeer/missing340=== CONT TestEncodeNixBase32/test_string_hash341=== CONT TestEncodeNixBase32/empty_input342--- PASS: TestEncodeNixBase32 (0.00s)343 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)344 --- PASS: TestEncodeNixBase32/empty_input (0.00s)345=== CONT TestSetClientTLSErrors/missing_cert_file346=== CONT TestSetClientTLSErrors/missing_ca_file347=== CONT TestSetClientTLSErrors/invalid_ca_file348--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)349=== CONT TestSetClientTLSErrors/missing_key_file350--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)351 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)352 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)353=== CONT TestFilterOversizedClosures/no_limit_keeps_everything354=== CONT TestFilterOversizedClosures/all_closures_skipped355=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3562026/10/01 09:30:21 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50357=== CONT TestPartSizeForNAR/zero_stays_at_minimum358=== CONT TestPartSizeForNAR/1_TiB3592026/10/01 09:30:21 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=== CONT TestPartSizeForNAR/capped_at_5_GiB361=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum362=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts363=== CONT TestPartSizeForNAR/small_stays_at_minimum364--- PASS: TestFilterOversizedClosures (0.00s)365 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)366 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)367 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)368=== CONT TestPartSizeForNAR/5_TiB_S3_max_object369--- PASS: TestPartSizeForNAR (0.00s)370 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)371 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)372 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)373 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)374 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)375 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)376 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)377--- PASS: TestSetClientTLSErrors (0.00s)378 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)379 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)380 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)381 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)3822026/10/01 09:30:21 http: TLS handshake error from 127.0.0.1:64792: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.01s)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-36033-363360632/postgres2215487318/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-36033-363360632/postgres2215487318/data -l logfile start421422/nix/var/nix/builds/nix-36033-363360632/postgres2215487318:5432 - no response4232026-10-01 09:30:22.777 UTC [36077] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 09:30:22.777 UTC [36077] LOG: listening on Unix socket "/nix/var/nix/builds/nix-36033-363360632/postgres2215487318/.s.PGSQL.5432"4252026-10-01 09:30:22.779 UTC [36084] LOG: database system was shut down at 2026-10-01 09:30:22 UTC4262026-10-01 09:30:22.780 UTC [36077] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-36033-363360632/postgres2215487318:5432 - accepting connections428{"timestamp":"2026-10-01T09:30:22.995752Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"f44252fe-6565-4739-984b-f482e4ff3d4a","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)"}429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestClientPushesUseOnePush462=== PAUSE TestClientPushesUseOnePush463=== RUN TestClientFallsBackToClosures464=== PAUSE TestClientFallsBackToClosures465=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock466=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== RUN TestResolveDBConnectionString468=== PAUSE TestResolveDBConnectionString469=== RUN TestLeadElectsOneAndHandsOver470=== PAUSE TestLeadElectsOneAndHandsOver471=== RUN TestLeadIncumbentWinsAfterRestart4722026-10-01 09:30:23.229 UTC [36114] ERROR: relation "goose_db_version" does not exist at character 364732026-10-01 09:30:23.229 UTC [36114] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4742026/10/01 09:30:23 OK 20241026095416_initial_model.sql (4.09ms)4752026/10/01 09:30:23 OK 20251210153512_drop_unused_gin_index.sql (428.13µs)4762026/10/01 09:30:23 OK 20251218171726_add_pins.sql (945.79µs)4772026/10/01 09:30:23 OK 20260628120000_add_object_size_and_stats.sql (917.88µs)4782026/10/01 09:30:23 OK 20260905000000_add_claims.sql (1.05ms)4792026/10/01 09:30:23 OK 20260920000000_drop_claims.sql (652.79µs)4802026/10/01 09:30:23 OK 20260923120000_add_pushes.sql (404.83µs)4812026/10/01 09:30:23 goose: successfully migrated database to version: 202609231200004822026/10/01 09:30:23 OK 1_commit_pending_closure.sql (956.54µs)4832026/10/01 09:30:23 OK 2_object_stats_trigger.sql (224.17µs)4842026/10/01 09:30:23 OK 3_commit_push.sql (192.46µs)4852026/10/01 09:30:23 goose: up to current file version: 34862026/10/01 09:30:23 INFO lead: acquired remote=192.0.2.1:12344872026/10/01 09:30:23 INFO lead: released remote=192.0.2.1:12344882026/10/01 09:30:23 INFO lead: acquired remote=192.0.2.1:12344892026/10/01 09:30:23 INFO lead: released remote=192.0.2.1:1234490--- PASS: TestLeadIncumbentWinsAfterRestart (0.85s)491=== RUN TestLeadEndsOnShutdown492=== PAUSE TestLeadEndsOnShutdown493=== RUN TestGCAdvisoryLockBlocksConcurrentRun4942026-10-01 09:30:24.032 UTC [36118] ERROR: relation "goose_db_version" does not exist at character 364952026-10-01 09:30:24.032 UTC [36118] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4962026/10/01 09:30:24 OK 20241026095416_initial_model.sql (3.8ms)4972026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (539.63µs)4982026/10/01 09:30:24 OK 20251218171726_add_pins.sql (892.58µs)4992026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (892.17µs)5002026/10/01 09:30:24 OK 20260905000000_add_claims.sql (1.11ms)5012026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (711.5µs)5022026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (479.42µs)5032026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200005042026/10/01 09:30:24 OK 1_commit_pending_closure.sql (964.04µs)5052026/10/01 09:30:24 OK 2_object_stats_trigger.sql (226.67µs)5062026/10/01 09:30:24 OK 3_commit_push.sql (196.17µs)5072026/10/01 09:30:24 goose: up to current file version: 3508--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.15s)509=== RUN TestGCBugBareHashReferences510=== PAUSE TestGCBugBareHashReferences511=== RUN TestGCMetrics512=== PAUSE TestGCMetrics513=== RUN TestPushDedupSurvivesConcurrentGC514=== PAUSE TestPushDedupSurvivesConcurrentGC515=== RUN TestDeduplicatedObjectsRecordedAsPending516=== PAUSE TestDeduplicatedObjectsRecordedAsPending517=== RUN TestGCSweepSkipsPendingObjects518=== PAUSE TestGCSweepSkipsPendingObjects519=== RUN TestTombstonedObjectOfferedWithoutWaiting520=== PAUSE TestTombstonedObjectOfferedWithoutWaiting521=== RUN TestGCSweepDeliversEachKeyOnce522=== PAUSE TestGCSweepDeliversEachKeyOnce523=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection524=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== RUN TestForceGCDuringPushOffersSweptObject526=== PAUSE TestForceGCDuringPushOffersSweptObject527=== RUN TestFailedS3DeleteKeepsTombstone528=== PAUSE TestFailedS3DeleteKeepsTombstone529=== RUN TestSweepSkipsRowsLockedByPush530=== PAUSE TestSweepSkipsRowsLockedByPush531=== RUN TestRegisterCompletedObjectNeedsPendingRow532=== PAUSE TestRegisterCompletedObjectNeedsPendingRow533=== RUN TestGetExistingObjectsLocksRows534=== PAUSE TestGetExistingObjectsLocksRows535=== RUN TestSweepRechecksPendingAfterLocking536=== PAUSE TestSweepRechecksPendingAfterLocking537=== RUN TestPushWaitsForSweepHoldingRow538=== PAUSE TestPushWaitsForSweepHoldingRow539=== RUN TestCommitRacingPendingCleanupKeepsObjects540=== PAUSE TestCommitRacingPendingCleanupKeepsObjects541=== RUN TestGCTaskStore_StartNew542=== PAUSE TestGCTaskStore_StartNew543=== RUN TestGCTaskStore_DeduplicateSameParams544=== PAUSE TestGCTaskStore_DeduplicateSameParams545=== RUN TestGCTaskStore_ConflictDifferentParams546=== PAUSE TestGCTaskStore_ConflictDifferentParams547=== RUN TestGCTaskStore_GetEmpty548=== PAUSE TestGCTaskStore_GetEmpty549=== RUN TestGCTaskStore_GetReturnsLatest550=== PAUSE TestGCTaskStore_GetReturnsLatest551=== RUN TestGCTaskStore_CompletedAllowsNewTask552=== PAUSE TestGCTaskStore_CompletedAllowsNewTask553=== RUN TestGCTaskStore_PhaseUpdates554=== PAUSE TestGCTaskStore_PhaseUpdates555=== RUN TestGCTaskStore_Fail556=== PAUSE TestGCTaskStore_Fail557=== RUN TestGracefulShutdownDrainsInflight558=== PAUSE TestGracefulShutdownDrainsInflight559=== RUN TestService_healthCheckHandler560=== PAUSE TestService_healthCheckHandler561=== RUN TestService_readinessHandler562=== PAUSE TestService_readinessHandler563=== RUN TestGenerateLandingPage564=== PAUSE TestGenerateLandingPage565=== RUN TestCacheConfigHandlerMaxNarSize566=== PAUSE TestCacheConfigHandlerMaxNarSize567=== RUN TestCreatePendingClosureRejectsOversizedNAR568=== PAUSE TestCreatePendingClosureRejectsOversizedNAR569=== RUN TestNARDeduplicationMetadataUploadBug570=== PAUSE TestNARDeduplicationMetadataUploadBug571=== RUN TestMetricsInventory572=== PAUSE TestMetricsInventory573=== RUN TestService_NativeMTLS574=== PAUSE TestService_NativeMTLS575=== RUN TestServerTLSConfig576=== PAUSE TestServerTLSConfig577=== RUN TestMultipartCleanup578=== PAUSE TestMultipartCleanup579=== RUN TestObjectStatsTrigger580=== PAUSE TestObjectStatsTrigger581=== RUN TestOrphanedObjectsGC582=== PAUSE TestOrphanedObjectsGC583=== RUN TestOrphanedObjectsGCStressTest584=== PAUSE TestOrphanedObjectsGCStressTest585=== RUN TestCreatePin_ReservedPins586=== PAUSE TestCreatePin_ReservedPins587=== RUN TestPresentReportsOnlyClosureRoots588=== PAUSE TestPresentReportsOnlyClosureRoots589=== RUN TestPresentNotReportedWhileGCDeletesClosure590=== PAUSE TestPresentNotReportedWhileGCDeletesClosure591=== RUN TestParseSingleRange592=== PAUSE TestParseSingleRange593=== RUN TestProxyHeadersOnlyTrustedOnSocket594=== PAUSE TestProxyHeadersOnlyTrustedOnSocket595=== RUN TestIsValidCachePath596=== PAUSE TestIsValidCachePath597=== RUN TestReadProxyNarinfo598=== PAUSE TestReadProxyNarinfo599=== RUN TestReadProxyNarinfoAlreadyDecompressed600=== PAUSE TestReadProxyNarinfoAlreadyDecompressed601=== RUN TestReadProxyNarStreaming602=== PAUSE TestReadProxyNarStreaming603=== RUN TestReadProxy404604=== PAUSE TestReadProxy404605=== RUN TestReadProxyInvalidPath606=== PAUSE TestReadProxyInvalidPath607=== RUN TestReadProxyHead608=== PAUSE TestReadProxyHead609=== RUN TestReadProxyConditionalGet610=== PAUSE TestReadProxyConditionalGet611=== RUN TestReadProxyRootRedirectsToIndexHTML612=== PAUSE TestReadProxyRootRedirectsToIndexHTML613=== RUN TestReadProxyDisabled614=== PAUSE TestReadProxyDisabled615=== RUN TestReadRedirectNar616=== PAUSE TestReadRedirectNar617=== RUN TestReadRedirectKeepsNarinfoProxied618=== PAUSE TestReadRedirectKeepsNarinfoProxied619=== RUN TestReadProxyRangeRequest620=== PAUSE TestReadProxyRangeRequest621=== RUN TestReadRedirectUsesPublicS3URL622=== PAUSE TestReadRedirectUsesPublicS3URL623=== RUN TestPush_OverlappingRootsStoreOneRowPerKey624=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey625=== RUN TestPush_CompleteCommitsEveryRoot626=== PAUSE TestPush_CompleteCommitsEveryRoot627=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit628=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit629=== RUN TestPush_RejectsBadRequests630=== PAUSE TestPush_RejectsBadRequests631=== RUN TestPush_SignsNarinfosOfItsPendingObjects632=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects633=== RUN TestRedundantMultipartUpload634=== PAUSE TestRedundantMultipartUpload635=== RUN TestCompleteMultipartUpload_ErrorButObjectExists636=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists637=== RUN TestCompletedNarNotReofferedAcrossClosures638=== PAUSE TestCompletedNarNotReofferedAcrossClosures639=== RUN TestPresignedUploadRegisteredBeforeCommit640=== PAUSE TestPresignedUploadRegisteredBeforeCommit641=== RUN TestService_Rustfstest642=== PAUSE TestService_Rustfstest643=== RUN TestParseSize644=== PAUSE TestParseSize645=== RUN TestSkippedUploadsHandler646=== PAUSE TestSkippedUploadsHandler647=== RUN TestSystemdListenerNotActivated648--- PASS: TestSystemdListenerNotActivated (0.00s)649=== RUN TestWatchdogBeatsWhenHealthy650--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)651=== RUN TestWatchdogSkipsWhenUnhealthy6522026/10/01 09:30:24 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6532026/10/01 09:30:24 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6542026/10/01 09:30:24 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6552026/10/01 09:30:24 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6562026/10/01 09:30:24 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6572026/10/01 09:30:24 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6582026/10/01 09:30:24 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6592026/10/01 09:30:24 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:30:24 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:30:24 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"662--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)663=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle664=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle665=== RUN TestProxyWriteTimeout666=== PAUSE TestProxyWriteTimeout667=== RUN TestIsValidUploadKey668=== PAUSE TestIsValidUploadKey669=== RUN TestUploadHandlersRejectInvalidKeys670=== PAUSE TestUploadHandlersRejectInvalidKeys671=== RUN TestUploadHandlersRejectOversizedBody672=== PAUSE TestUploadHandlersRejectOversizedBody673=== RUN TestService_cleanupPendingClosuresHandler674=== PAUSE TestService_cleanupPendingClosuresHandler675=== RUN TestService_createPendingClosureHandler676=== PAUSE TestService_createPendingClosureHandler677=== RUN TestService_verifyS3Integrity678=== PAUSE TestService_verifyS3Integrity679=== RUN TestCompleteMultipartUnregistered680=== PAUSE TestCompleteMultipartUnregistered681=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT682=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT683=== CONT TestParseSize684=== CONT TestService_AuthMiddleware685=== CONT TestUploadHandlersRejectOversizedBody686=== CONT TestService_verifyS3Integrity687--- PASS: TestParseSize (0.00s)688=== CONT TestUploadHandlersRejectInvalidKeys689=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info690=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info691=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal692=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal693=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key694=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key695=== CONT TestCompleteMultipartUnregistered696=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key697=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key698=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info699=== CONT TestService_cleanupPendingClosuresHandler700=== CONT TestService_createPendingClosureHandler701=== CONT TestGCTaskStore_PhaseUpdates702--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)703=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT704=== CONT TestPresignedUploadRegisteredBeforeCommit7052026/10/01 09:30:24 INFO Received uploads request method=POST path=/706=== CONT TestService_Rustfstest707=== CONT TestCompletedNarNotReofferedAcrossClosures708=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure709=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure710=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart711=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart712=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts713=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts714=== CONT TestCompleteMultipartUpload_ErrorButObjectExists7152026-10-01 09:30:24.649 UTC [36140] ERROR: relation "goose_db_version" does not exist at character 367162026-10-01 09:30:24.649 UTC [36140] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7172026-10-01 09:30:24.649 UTC [36141] ERROR: relation "goose_db_version" does not exist at character 367182026-10-01 09:30:24.649 UTC [36141] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7192026-10-01 09:30:24.651 UTC [36142] ERROR: relation "goose_db_version" does not exist at character 367202026-10-01 09:30:24.651 UTC [36142] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7212026-10-01 09:30:24.652 UTC [36143] ERROR: relation "goose_db_version" does not exist at character 367222026-10-01 09:30:24.652 UTC [36143] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7232026-10-01 09:30:24.653 UTC [36145] ERROR: relation "goose_db_version" does not exist at character 367242026-10-01 09:30:24.653 UTC [36145] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7252026-10-01 09:30:24.654 UTC [36144] ERROR: relation "goose_db_version" does not exist at character 367262026-10-01 09:30:24.654 UTC [36144] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7272026-10-01 09:30:24.654 UTC [36146] ERROR: relation "goose_db_version" does not exist at character 367282026-10-01 09:30:24.654 UTC [36146] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7292026-10-01 09:30:24.654 UTC [36147] ERROR: relation "goose_db_version" does not exist at character 367302026-10-01 09:30:24.654 UTC [36147] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7312026-10-01 09:30:24.655 UTC [36148] ERROR: relation "goose_db_version" does not exist at character 367322026-10-01 09:30:24.655 UTC [36148] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7332026-10-01 09:30:24.657 UTC [36149] ERROR: relation "goose_db_version" does not exist at character 367342026-10-01 09:30:24.657 UTC [36149] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7352026/10/01 09:30:24 OK 20241026095416_initial_model.sql (7.71ms)7362026/10/01 09:30:24 OK 20241026095416_initial_model.sql (8.8ms)7372026/10/01 09:30:24 OK 20241026095416_initial_model.sql (8.47ms)7382026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)7392026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (933.67µs)7402026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (645.33µs)7412026/10/01 09:30:24 OK 20251218171726_add_pins.sql (1.95ms)7422026/10/01 09:30:24 OK 20241026095416_initial_model.sql (8.52ms)7432026/10/01 09:30:24 OK 20251218171726_add_pins.sql (2.08ms)7442026/10/01 09:30:24 OK 20251218171726_add_pins.sql (1.83ms)7452026/10/01 09:30:24 OK 20241026095416_initial_model.sql (8.02ms)7462026/10/01 09:30:24 OK 20241026095416_initial_model.sql (9.9ms)7472026/10/01 09:30:24 OK 20241026095416_initial_model.sql (9.07ms)7482026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (687.96µs)7492026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (740.17µs)7502026/10/01 09:30:24 OK 20241026095416_initial_model.sql (8.67ms)7512026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (1.33ms)7522026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (647.17µs)7532026/10/01 09:30:24 OK 20241026095416_initial_model.sql (9.4ms)7542026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (773.92µs)7552026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (2.12ms)7562026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (820.96µs)7572026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (2.08ms)7582026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (760.21µs)7592026/10/01 09:30:24 OK 20251218171726_add_pins.sql (1.98ms)7602026/10/01 09:30:24 OK 20241026095416_initial_model.sql (8.22ms)7612026/10/01 09:30:24 OK 20251218171726_add_pins.sql (1.87ms)7622026/10/01 09:30:24 OK 20251218171726_add_pins.sql (2.46ms)7632026/10/01 09:30:24 OK 20260905000000_add_claims.sql (2.31ms)7642026/10/01 09:30:24 OK 20251218171726_add_pins.sql (1.86ms)7652026/10/01 09:30:24 OK 20251218171726_add_pins.sql (2.55ms)7662026/10/01 09:30:24 OK 20251210153512_drop_unused_gin_index.sql (579.25µs)7672026/10/01 09:30:24 OK 20260905000000_add_claims.sql (2.32ms)7682026/10/01 09:30:24 OK 20251218171726_add_pins.sql (2.22ms)7692026/10/01 09:30:24 OK 20260905000000_add_claims.sql (2.44ms)7702026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (1.79ms)7712026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (1.31ms)7722026/10/01 09:30:24 OK 20251218171726_add_pins.sql (1.19ms)7732026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (1.42ms)7742026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (1.96ms)7752026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (2.17ms)7762026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (1.35ms)7772026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (2.06ms)7782026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (2.31ms)7792026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (1.86ms)7802026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (948µs)7812026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200007822026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (1.29ms)7832026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200007842026/10/01 09:30:24 OK 20260905000000_add_claims.sql (2.09ms)7852026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (1.12ms)7862026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200007872026/10/01 09:30:24 OK 20260905000000_add_claims.sql (2.69ms)7882026/10/01 09:30:24 OK 20260905000000_add_claims.sql (1.8ms)7892026/10/01 09:30:24 OK 20260628120000_add_object_size_and_stats.sql (2.69ms)7902026/10/01 09:30:24 OK 20260905000000_add_claims.sql (2.3ms)7912026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (1.3ms)7922026/10/01 09:30:24 OK 1_commit_pending_closure.sql (1.72ms)7932026/10/01 09:30:24 OK 20260905000000_add_claims.sql (2.02ms)7942026/10/01 09:30:24 OK 20260905000000_add_claims.sql (2.19ms)7952026/10/01 09:30:24 OK 1_commit_pending_closure.sql (1.6ms)7962026/10/01 09:30:24 OK 1_commit_pending_closure.sql (1.57ms)7972026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (890.54µs)7982026/10/01 09:30:24 OK 2_object_stats_trigger.sql (407.17µs)7992026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (1.41ms)8002026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (1ms)8012026/10/01 09:30:24 OK 2_object_stats_trigger.sql (567.33µs)8022026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (861µs)8032026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200008042026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (593.38µs)8052026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200008062026/10/01 09:30:24 OK 3_commit_push.sql (491.79µs)8072026/10/01 09:30:24 goose: up to current file version: 38082026/10/01 09:30:24 OK 2_object_stats_trigger.sql (718.13µs)8092026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (1.17ms)8102026/10/01 09:30:24 OK 3_commit_push.sql (451µs)8112026/10/01 09:30:24 goose: up to current file version: 38122026/10/01 09:30:24 OK 20260905000000_add_claims.sql (1.6ms)8132026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (796.42µs)8142026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200008152026/10/01 09:30:24 OK 3_commit_push.sql (437.08µs)8162026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (1.36ms)8172026/10/01 09:30:24 goose: up to current file version: 38182026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (719.54µs)8192026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200008202026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (748.79µs)8212026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200008222026/10/01 09:30:24 OK 1_commit_pending_closure.sql (1.01ms)8232026/10/01 09:30:24 OK 1_commit_pending_closure.sql (1.15ms)8242026/10/01 09:30:24 OK 1_commit_pending_closure.sql (905.17µs)8252026/10/01 09:30:24 OK 2_object_stats_trigger.sql (300.63µs)8262026/10/01 09:30:24 OK 20260920000000_drop_claims.sql (961.25µs)8272026/10/01 09:30:24 OK 1_commit_pending_closure.sql (1.01ms)8282026/10/01 09:30:24 OK 2_object_stats_trigger.sql (374.83µs)8292026/10/01 09:30:24 OK 2_object_stats_trigger.sql (594.71µs)8302026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (1.18ms)8312026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200008322026/10/01 09:30:24 OK 3_commit_push.sql (363µs)8332026/10/01 09:30:24 goose: up to current file version: 38342026/10/01 09:30:24 OK 1_commit_pending_closure.sql (831.63µs)8352026/10/01 09:30:24 OK 3_commit_push.sql (217.67µs)8362026/10/01 09:30:24 goose: up to current file version: 38372026/10/01 09:30:24 OK 3_commit_push.sql (242.88µs)8382026/10/01 09:30:24 goose: up to current file version: 38392026/10/01 09:30:24 OK 2_object_stats_trigger.sql (473.96µs)8402026/10/01 09:30:24 OK 2_object_stats_trigger.sql (276.54µs)8412026/10/01 09:30:24 OK 20260923120000_add_pushes.sql (648.5µs)8422026/10/01 09:30:24 goose: successfully migrated database to version: 202609231200008432026/10/01 09:30:24 OK 3_commit_push.sql (176.46µs)8442026/10/01 09:30:24 goose: up to current file version: 38452026/10/01 09:30:24 OK 3_commit_push.sql (302.67µs)8462026/10/01 09:30:24 goose: up to current file version: 38472026/10/01 09:30:24 OK 1_commit_pending_closure.sql (762.58µs)8482026/10/01 09:30:24 OK 2_object_stats_trigger.sql (177.71µs)8492026/10/01 09:30:24 OK 3_commit_push.sql (139.92µs)8502026/10/01 09:30:24 goose: up to current file version: 38512026/10/01 09:30:24 OK 1_commit_pending_closure.sql (722.88µs)8522026/10/01 09:30:24 OK 2_object_stats_trigger.sql (192.63µs)8532026/10/01 09:30:24 OK 3_commit_push.sql (158.88µs)8542026/10/01 09:30:24 goose: up to current file version: 38552026/10/01 09:30:24 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"856--- PASS: TestService_AuthMiddleware (0.41s)857=== CONT TestRedundantMultipartUpload8582026/10/01 09:30:24 INFO Received uploads request method=POST path=/api/pending_closures8592026/10/01 09:30:24 INFO Received uploads request method=POST path=/api/pending_closures8602026/10/01 09:30:24 INFO Received uploads request method=POST path=/api/pending_closures8612026/10/01 09:30:25 INFO Received cleanup request method=DELETE path=/api/pending_closures8622026/10/01 09:30:25 INFO Aborted multipart uploads count=08632026/10/01 09:30:25 INFO Received uploads request method=POST path=/api/pending_closures8642026/10/01 09:30:25 INFO Received cleanup request method=DELETE path=/api/pending_closures8652026/10/01 09:30:25 INFO Aborted multipart uploads count=18662026/10/01 09:30:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8672026-10-01 09:30:25.163 UTC [36140] ERROR: Closure does not exist: id=18682026-10-01 09:30:25.163 UTC [36140] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE8692026-10-01 09:30:25.163 UTC [36140] STATEMENT: -- name: CommitPendingClosure :exec870 SELECT commit_pending_closure($1::bigint)871 872--- PASS: TestService_cleanupPendingClosuresHandler (0.83s)873=== CONT TestPush_SignsNarinfosOfItsPendingObjects8742026/10/01 09:30:25 INFO Received uploads request method=POST path=/api/pending_closures8752026/10/01 09:30:25 INFO Received uploads request method=POST path=/api/pending_closures8762026/10/01 09:30:25 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst8772026/10/01 09:30:25 INFO Received uploads request method=POST path=/api/pending_closures878--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.24s)879=== CONT TestPush_RejectsBadRequests8802026/10/01 09:30:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8812026/10/01 09:30:25 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst882--- PASS: TestCompleteMultipartUnregistered (1.44s)883=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit8842026-10-01 09:30:25.834 UTC [36157] ERROR: relation "goose_db_version" does not exist at character 368852026-10-01 09:30:25.834 UTC [36157] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8862026/10/01 09:30:25 OK 20241026095416_initial_model.sql (103.82ms)8872026/10/01 09:30:25 OK 20251210153512_drop_unused_gin_index.sql (12.36ms)8882026/10/01 09:30:26 INFO Received uploads request method=POST path=/api/pending_closures8892026/10/01 09:30:26 OK 20251218171726_add_pins.sql (15.5ms)8902026/10/01 09:30:26 OK 20260628120000_add_object_size_and_stats.sql (35.64ms)891--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.74s)892=== CONT TestPush_CompleteCommitsEveryRoot8932026/10/01 09:30:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8942026/10/01 09:30:26 OK 20260905000000_add_claims.sql (43.87ms)8952026/10/01 09:30:26 OK 20260920000000_drop_claims.sql (44.61ms)8962026/10/01 09:30:26 OK 20260923120000_add_pushes.sql (6.32ms)8972026/10/01 09:30:26 goose: successfully migrated database to version: 202609231200008982026/10/01 09:30:26 OK 1_commit_pending_closure.sql (1.83ms)8992026/10/01 09:30:26 OK 2_object_stats_trigger.sql (384.08µs)9002026/10/01 09:30:26 OK 3_commit_push.sql (313.25µs)9012026/10/01 09:30:26 goose: up to current file version: 39022026/10/01 09:30:26 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MThhYmI2ZDItYzVjNS00N2Y2LWFkMDYtMTY3ZTY3YzFhOTAyLmM4OTg1MjhiLTg3OTUtNDNiZS1hMmZjLTNkZjM3ZDczZGJmMngxNzkwODQ3MDI0ODk1MjUwMDAw parts=109032026/10/01 09:30:26 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9042026/10/01 09:30:26 INFO Completed upload id=19052026/10/01 09:30:26 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009062026/10/01 09:30:26 INFO Received uploads request method=POST path=/api/pending_closures9072026/10/01 09:30:26 INFO Starting cleanup of old closures method=DELETE path=/api/closures9082026/10/01 09:30:26 INFO Aborted multipart uploads count=09092026/10/01 09:30:26 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=09102026/10/01 09:30:26 INFO Vacuumed table table=pending_closures9112026/10/01 09:30:26 INFO Vacuumed table table=pending_objects9122026-10-01 09:30:26.198 UTC [36163] ERROR: relation "goose_db_version" does not exist at character 369132026-10-01 09:30:26.198 UTC [36163] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9142026/10/01 09:30:26 INFO Vacuumed table table=multipart_uploads9152026/10/01 09:30:26 INFO Vacuumed table table=closures9162026/10/01 09:30:26 INFO Vacuumed table table=objects9172026/10/01 09:30:26 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000918--- PASS: TestService_createPendingClosureHandler (1.92s)919=== CONT TestPush_OverlappingRootsStoreOneRowPerKey920--- PASS: TestService_Rustfstest (1.92s)921=== CONT TestReadRedirectUsesPublicS3URL9222026/10/01 09:30:26 OK 20241026095416_initial_model.sql (145.58ms)9232026/10/01 09:30:26 OK 20251210153512_drop_unused_gin_index.sql (6.86ms)9242026/10/01 09:30:26 OK 20251218171726_add_pins.sql (19.22ms)9252026/10/01 09:30:26 OK 20260628120000_add_object_size_and_stats.sql (26.62ms)9262026/10/01 09:30:26 INFO Received uploads request method=POST path=/api/pending_closures9272026/10/01 09:30:26 OK 20260905000000_add_claims.sql (26.41ms)9282026/10/01 09:30:26 OK 20260920000000_drop_claims.sql (28.31ms)9292026/10/01 09:30:26 OK 20260923120000_add_pushes.sql (24.96ms)9302026/10/01 09:30:26 goose: successfully migrated database to version: 202609231200009312026/10/01 09:30:26 OK 1_commit_pending_closure.sql (3.44ms)9322026/10/01 09:30:26 OK 2_object_stats_trigger.sql (857.67µs)9332026/10/01 09:30:26 OK 3_commit_push.sql (541.92µs)9342026/10/01 09:30:26 goose: up to current file version: 39352026-10-01 09:30:26.668 UTC [36168] ERROR: relation "goose_db_version" does not exist at character 369362026-10-01 09:30:26.668 UTC [36168] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9372026/10/01 09:30:26 INFO Received uploads request method=POST path=/api/pending_closures9382026/10/01 09:30:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9392026/10/01 09:30:26 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MThhYmI2ZDItYzVjNS00N2Y2LWFkMDYtMTY3ZTY3YzFhOTAyLjFiNjc1ODE3LTk1YzUtNDdkYS05NDU2LTFlMGZhZDNkNzk2ZXgxNzkwODQ3MDI1MzcyMTAwMDAw parts=129402026/10/01 09:30:26 INFO Received uploads request method=POST path=/api/pending_closures941--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.51s)942=== CONT TestReadProxyRangeRequest9432026/10/01 09:30:26 OK 20241026095416_initial_model.sql (207.58ms)9442026/10/01 09:30:26 OK 20251210153512_drop_unused_gin_index.sql (8.14ms)9452026/10/01 09:30:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9462026/10/01 09:30:26 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MThhYmI2ZDItYzVjNS00N2Y2LWFkMDYtMTY3ZTY3YzFhOTAyLjg4NzlkZWQxLWE4MWYtNDg0Ni1hMWRiLTFhYjI0ZjRjZTU1ZXgxNzkwODQ3MDI2NzQwNDg0MDAw9472026/10/01 09:30:26 OK 20251218171726_add_pins.sql (27.65ms)9482026/10/01 09:30:26 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MThhYmI2ZDItYzVjNS00N2Y2LWFkMDYtMTY3ZTY3YzFhOTAyLjg4NzlkZWQxLWE4MWYtNDg0Ni1hMWRiLTFhYjI0ZjRjZTU1ZXgxNzkwODQ3MDI2NzQwNDg0MDAw parts=1949--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.60s)950=== CONT TestReadRedirectKeepsNarinfoProxied9512026/10/01 09:30:27 INFO Received uploads request method=POST path=/api/pending_closures9522026/10/01 09:30:27 OK 20260628120000_add_object_size_and_stats.sql (38.24ms)9532026/10/01 09:30:27 OK 20260905000000_add_claims.sql (55.76ms)9542026/10/01 09:30:27 INFO Received uploads request method=POST path=/api/pending_closures9552026/10/01 09:30:27 OK 20260920000000_drop_claims.sql (50.86ms)9562026/10/01 09:30:27 OK 20260923120000_add_pushes.sql (17.92ms)9572026/10/01 09:30:27 goose: successfully migrated database to version: 202609231200009582026/10/01 09:30:27 OK 1_commit_pending_closure.sql (1.56ms)9592026/10/01 09:30:27 OK 2_object_stats_trigger.sql (321.25µs)9602026/10/01 09:30:27 OK 3_commit_push.sql (277.38µs)9612026/10/01 09:30:27 goose: up to current file version: 39622026-10-01 09:30:27.206 UTC [36173] ERROR: relation "goose_db_version" does not exist at character 369632026-10-01 09:30:27.206 UTC [36173] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9642026/10/01 09:30:27 INFO Received push request method=POST path=/api/pushes9652026/10/01 09:30:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9662026/10/01 09:30:27 INFO Signed narinfos id=1 count=1967--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.16s)968=== CONT TestReadRedirectNar9692026/10/01 09:30:27 OK 20241026095416_initial_model.sql (169.75ms)9702026/10/01 09:30:27 OK 20251210153512_drop_unused_gin_index.sql (18.73ms)9712026/10/01 09:30:27 OK 20251218171726_add_pins.sql (32.77ms)972=== RUN TestPush_RejectsBadRequests/no_roots973=== PAUSE TestPush_RejectsBadRequests/no_roots974=== RUN TestPush_RejectsBadRequests/no_objects975=== PAUSE TestPush_RejectsBadRequests/no_objects976=== RUN TestPush_RejectsBadRequests/bad_root977=== PAUSE TestPush_RejectsBadRequests/bad_root978=== RUN TestPush_RejectsBadRequests/root_not_in_objects979=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects980=== CONT TestReadProxyDisabled9812026/10/01 09:30:27 OK 20260628120000_add_object_size_and_stats.sql (70.5ms)9822026/10/01 09:30:27 OK 20260905000000_add_claims.sql (58.9ms)9832026/10/01 09:30:27 OK 20260920000000_drop_claims.sql (8.5ms)9842026/10/01 09:30:27 OK 20260923120000_add_pushes.sql (8.44ms)9852026/10/01 09:30:27 goose: successfully migrated database to version: 202609231200009862026/10/01 09:30:27 OK 1_commit_pending_closure.sql (3.25ms)9872026/10/01 09:30:27 OK 2_object_stats_trigger.sql (519.04µs)9882026/10/01 09:30:27 OK 3_commit_push.sql (296.25µs)9892026/10/01 09:30:27 goose: up to current file version: 39902026/10/01 09:30:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9912026-10-01 09:30:27.770 UTC [36178] ERROR: relation "goose_db_version" does not exist at character 369922026-10-01 09:30:27.770 UTC [36178] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9932026/10/01 09:30:27 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MThhYmI2ZDItYzVjNS00N2Y2LWFkMDYtMTY3ZTY3YzFhOTAyLmJmYWUxYzYxLThhNDYtNGUwMi05OWQ4LWEzMGIzOGZkNGJjY3gxNzkwODQ3MDI2NDkyMjg1MDAw parts=109942026/10/01 09:30:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9952026/10/01 09:30:27 INFO Completed upload id=19962026/10/01 09:30:27 INFO Received uploads request method=POST path=/api/pending_closures9972026/10/01 09:30:27 INFO Received uploads request method=POST path=/api/pending_closures9982026/10/01 09:30:27 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9992026/10/01 09:30:27 WARN Found objects in DB but missing from S3, will re-upload count=11000--- PASS: TestService_verifyS3Integrity (3.54s)1001=== CONT TestReadProxyRootRedirectsToIndexHTML10022026/10/01 09:30:27 INFO Received push request method=POST path=/api/pushes10032026/10/01 09:30:28 INFO Received complete push request method=POST path=/api/pushes/1/complete10042026/10/01 09:30:28 OK 20241026095416_initial_model.sql (181.26ms)10052026/10/01 09:30:28 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)10062026/10/01 09:30:28 OK 20251218171726_add_pins.sql (7.24ms)10072026/10/01 09:30:28 INFO Received push request method=POST path=/api/pushes10082026-10-01 09:30:28.078 UTC [36182] ERROR: relation "goose_db_version" does not exist at character 3610092026-10-01 09:30:28.078 UTC [36182] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10102026/10/01 09:30:28 OK 20260628120000_add_object_size_and_stats.sql (22.13ms)10112026-10-01 09:30:28.087 UTC [36183] ERROR: relation "goose_db_version" does not exist at character 3610122026-10-01 09:30:28.087 UTC [36183] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10132026/10/01 09:30:28 OK 20260905000000_add_claims.sql (34.76ms)10142026/10/01 09:30:28 OK 20260920000000_drop_claims.sql (9.25ms)10152026/10/01 09:30:28 OK 20260923120000_add_pushes.sql (2.52ms)10162026/10/01 09:30:28 goose: successfully migrated database to version: 2026092312000010172026/10/01 09:30:28 OK 1_commit_pending_closure.sql (2.89ms)10182026/10/01 09:30:28 OK 2_object_stats_trigger.sql (655.5µs)10192026/10/01 09:30:28 OK 3_commit_push.sql (592.5µs)10202026/10/01 09:30:28 goose: up to current file version: 310212026/10/01 09:30:28 INFO Aborted multipart uploads count=010222026/10/01 09:30:28 WARN Force mode enabled - objects will be deleted immediately without grace period10232026/10/01 09:30:28 OK 20241026095416_initial_model.sql (19.44ms)10242026/10/01 09:30:28 OK 20251210153512_drop_unused_gin_index.sql (6.69ms)10252026/10/01 09:30:28 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=010262026/10/01 09:30:28 OK 20241026095416_initial_model.sql (36.55ms)10272026/10/01 09:30:28 OK 20251210153512_drop_unused_gin_index.sql (6.46ms)10282026/10/01 09:30:28 INFO Vacuumed table table=pending_closures10292026/10/01 09:30:28 OK 20251218171726_add_pins.sql (43.85ms)10302026/10/01 09:30:28 INFO Vacuumed table table=pending_objects10312026/10/01 09:30:28 OK 20251218171726_add_pins.sql (40.16ms)10322026/10/01 09:30:28 INFO Vacuumed table table=multipart_uploads10332026/10/01 09:30:28 OK 20260628120000_add_object_size_and_stats.sql (41.96ms)10342026/10/01 09:30:28 OK 20260628120000_add_object_size_and_stats.sql (42.88ms)10352026/10/01 09:30:28 INFO Vacuumed table table=closures10362026/10/01 09:30:28 INFO Vacuumed table table=objects10372026/10/01 09:30:28 OK 20260905000000_add_claims.sql (34.62ms)10382026/10/01 09:30:28 OK 20260905000000_add_claims.sql (23.16ms)10392026/10/01 09:30:28 INFO Received complete push request method=POST path=/api/pushes/2/complete1040--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.50s)1041=== CONT TestReadProxyConditionalGet10422026/10/01 09:30:28 OK 20260920000000_drop_claims.sql (19.38ms)10432026/10/01 09:30:28 OK 20260920000000_drop_claims.sql (18.85ms)10442026/10/01 09:30:28 OK 20260923120000_add_pushes.sql (10.04ms)10452026/10/01 09:30:28 goose: successfully migrated database to version: 2026092312000010462026/10/01 09:30:28 OK 20260923120000_add_pushes.sql (11.5ms)10472026/10/01 09:30:28 goose: successfully migrated database to version: 2026092312000010482026/10/01 09:30:28 OK 1_commit_pending_closure.sql (1.91ms)10492026/10/01 09:30:28 OK 1_commit_pending_closure.sql (2.05ms)10502026/10/01 09:30:28 OK 2_object_stats_trigger.sql (395.42µs)10512026/10/01 09:30:28 OK 2_object_stats_trigger.sql (483.33µs)10522026/10/01 09:30:28 OK 3_commit_push.sql (322.92µs)10532026/10/01 09:30:28 goose: up to current file version: 310542026/10/01 09:30:28 OK 3_commit_push.sql (321.67µs)10552026/10/01 09:30:28 goose: up to current file version: 310562026/10/01 09:30:28 INFO Received push request method=POST path=/api/pushes10572026/10/01 09:30:28 INFO Received complete push request method=POST path=/api/pushes/1/complete1058--- PASS: TestPush_CompleteCommitsEveryRoot (2.47s)1059=== CONT TestReadProxyHead10602026/10/01 09:30:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10612026/10/01 09:30:28 INFO Received push request method=POST path=/api/pushes10622026/10/01 09:30:28 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MThhYmI2ZDItYzVjNS00N2Y2LWFkMDYtMTY3ZTY3YzFhOTAyLjRhMzFjODdlLTM5YmYtNGU0OS1hNzljLTQ1ODlmNDAzMjFiNngxNzkwODQ3MDI3MDM5MjMxMDAw parts=121063--- PASS: TestRedundantMultipartUpload (3.98s)1064=== CONT TestReadProxyInvalidPath1065--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.47s)1066=== CONT TestReadProxy40410672026-10-01 09:30:28.738 UTC [36190] ERROR: relation "goose_db_version" does not exist at character 3610682026-10-01 09:30:28.738 UTC [36190] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10692026/10/01 09:30:28 OK 20241026095416_initial_model.sql (121ms)10702026/10/01 09:30:28 OK 20251210153512_drop_unused_gin_index.sql (14.59ms)10712026-10-01 09:30:28.942 UTC [36196] ERROR: relation "goose_db_version" does not exist at character 3610722026-10-01 09:30:28.942 UTC [36196] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1073--- PASS: TestReadRedirectUsesPublicS3URL (2.68s)1074=== CONT TestReadProxyNarStreaming10752026/10/01 09:30:28 OK 20251218171726_add_pins.sql (22.89ms)10762026/10/01 09:30:28 OK 20260628120000_add_object_size_and_stats.sql (23.39ms)10772026-10-01 09:30:28.992 UTC [36199] ERROR: relation "goose_db_version" does not exist at character 3610782026-10-01 09:30:28.992 UTC [36199] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10792026/10/01 09:30:28 OK 20260905000000_add_claims.sql (10.04ms)10802026/10/01 09:30:28 OK 20260920000000_drop_claims.sql (1.46ms)10812026/10/01 09:30:28 OK 20260923120000_add_pushes.sql (804.58µs)10822026/10/01 09:30:28 goose: successfully migrated database to version: 2026092312000010832026/10/01 09:30:28 OK 1_commit_pending_closure.sql (1.46ms)10842026/10/01 09:30:29 OK 2_object_stats_trigger.sql (804µs)10852026/10/01 09:30:29 OK 3_commit_push.sql (337.08µs)10862026/10/01 09:30:29 goose: up to current file version: 310872026-10-01 09:30:29.022 UTC [36200] ERROR: relation "goose_db_version" does not exist at character 3610882026-10-01 09:30:29.022 UTC [36200] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10892026/10/01 09:30:29 OK 20241026095416_initial_model.sql (65.87ms)10902026/10/01 09:30:29 OK 20251210153512_drop_unused_gin_index.sql (6.05ms)10912026/10/01 09:30:29 OK 20251218171726_add_pins.sql (15.33ms)10922026/10/01 09:30:29 OK 20241026095416_initial_model.sql (66.13ms)10932026/10/01 09:30:29 OK 20260628120000_add_object_size_and_stats.sql (13.65ms)10942026/10/01 09:30:29 OK 20251210153512_drop_unused_gin_index.sql (7.84ms)10952026/10/01 09:30:29 OK 20251218171726_add_pins.sql (8.41ms)10962026/10/01 09:30:29 OK 20260905000000_add_claims.sql (32.88ms)10972026/10/01 09:30:29 OK 20260628120000_add_object_size_and_stats.sql (35.92ms)10982026/10/01 09:30:29 OK 20260920000000_drop_claims.sql (20.73ms)10992026/10/01 09:30:29 OK 20260923120000_add_pushes.sql (4.21ms)11002026/10/01 09:30:29 goose: successfully migrated database to version: 2026092312000011012026/10/01 09:30:29 OK 1_commit_pending_closure.sql (2.77ms)11022026/10/01 09:30:29 OK 2_object_stats_trigger.sql (539.96µs)11032026/10/01 09:30:29 OK 3_commit_push.sql (347.25µs)11042026/10/01 09:30:29 goose: up to current file version: 311052026/10/01 09:30:29 OK 20241026095416_initial_model.sql (94.3ms)11062026/10/01 09:30:29 OK 20251210153512_drop_unused_gin_index.sql (13.5ms)11072026/10/01 09:30:29 OK 20260905000000_add_claims.sql (34.59ms)11082026/10/01 09:30:29 OK 20251218171726_add_pins.sql (18.35ms)11092026/10/01 09:30:29 OK 20260920000000_drop_claims.sql (22.39ms)11102026/10/01 09:30:29 OK 20260923120000_add_pushes.sql (15.41ms)11112026/10/01 09:30:29 goose: successfully migrated database to version: 202609231200001112--- PASS: TestReadProxyRangeRequest (2.35s)1113=== CONT TestReadProxyNarinfoAlreadyDecompressed11142026/10/01 09:30:29 OK 1_commit_pending_closure.sql (3.58ms)11152026/10/01 09:30:29 OK 2_object_stats_trigger.sql (3.09ms)11162026/10/01 09:30:29 OK 20260628120000_add_object_size_and_stats.sql (33.45ms)11172026/10/01 09:30:29 OK 3_commit_push.sql (703µs)11182026/10/01 09:30:29 goose: up to current file version: 311192026/10/01 09:30:29 OK 20260905000000_add_claims.sql (79.39ms)11202026/10/01 09:30:29 OK 20260920000000_drop_claims.sql (2.48ms)11212026/10/01 09:30:29 OK 20260923120000_add_pushes.sql (16.03ms)11222026/10/01 09:30:29 goose: successfully migrated database to version: 2026092312000011232026/10/01 09:30:29 OK 1_commit_pending_closure.sql (2.95ms)11242026/10/01 09:30:29 OK 2_object_stats_trigger.sql (532.08µs)11252026/10/01 09:30:29 OK 3_commit_push.sql (348.75µs)11262026/10/01 09:30:29 goose: up to current file version: 311272026-10-01 09:30:29.364 UTC [36203] ERROR: relation "goose_db_version" does not exist at character 3611282026-10-01 09:30:29.364 UTC [36203] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1129--- PASS: TestReadRedirectKeepsNarinfoProxied (2.42s)1130=== CONT TestReadProxyNarinfo11312026/10/01 09:30:29 OK 20241026095416_initial_model.sql (106.39ms)11322026/10/01 09:30:29 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)11332026/10/01 09:30:29 OK 20251218171726_add_pins.sql (30.26ms)11342026/10/01 09:30:29 OK 20260628120000_add_object_size_and_stats.sql (17.25ms)11352026/10/01 09:30:29 OK 20260905000000_add_claims.sql (30ms)1136--- PASS: TestReadRedirectNar (2.30s)1137=== CONT TestIsValidCachePath1138=== RUN TestIsValidCachePath/narinfo1139=== PAUSE TestIsValidCachePath/narinfo1140=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1141=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1142=== RUN TestIsValidCachePath/nar_zst1143=== PAUSE TestIsValidCachePath/nar_zst1144=== RUN TestIsValidCachePath/nar_xz1145=== PAUSE TestIsValidCachePath/nar_xz1146=== RUN TestIsValidCachePath/nar_bz21147=== PAUSE TestIsValidCachePath/nar_bz21148=== RUN TestIsValidCachePath/nar_uncompressed1149=== PAUSE TestIsValidCachePath/nar_uncompressed1150=== RUN TestIsValidCachePath/ls1151=== PAUSE TestIsValidCachePath/ls1152=== RUN TestIsValidCachePath/log1153=== PAUSE TestIsValidCachePath/log1154=== RUN TestIsValidCachePath/realisation1155=== PAUSE TestIsValidCachePath/realisation1156=== RUN TestIsValidCachePath/nix-cache-info1157=== PAUSE TestIsValidCachePath/nix-cache-info1158=== RUN TestIsValidCachePath/index.html1159=== PAUSE TestIsValidCachePath/index.html1160=== RUN TestIsValidCachePath/traversal_parent1161=== PAUSE TestIsValidCachePath/traversal_parent1162=== RUN TestIsValidCachePath/traversal_in_middle1163=== PAUSE TestIsValidCachePath/traversal_in_middle1164=== RUN TestIsValidCachePath/invalid_char_e1165=== PAUSE TestIsValidCachePath/invalid_char_e1166=== RUN TestIsValidCachePath/invalid_char_u1167=== PAUSE TestIsValidCachePath/invalid_char_u1168=== RUN TestIsValidCachePath/random_path1169=== PAUSE TestIsValidCachePath/random_path1170=== RUN TestIsValidCachePath/empty1171=== PAUSE TestIsValidCachePath/empty1172=== RUN TestIsValidCachePath/leading_slash1173=== PAUSE TestIsValidCachePath/leading_slash1174=== RUN TestIsValidCachePath/wrong_extension1175=== PAUSE TestIsValidCachePath/wrong_extension1176=== RUN TestIsValidCachePath/short_hash1177=== PAUSE TestIsValidCachePath/short_hash1178=== CONT TestProxyHeadersOnlyTrustedOnSocket11792026/10/01 09:30:29 OK 20260920000000_drop_claims.sql (36.2ms)11802026/10/01 09:30:29 OK 20260923120000_add_pushes.sql (17.29ms)11812026/10/01 09:30:29 goose: successfully migrated database to version: 2026092312000011822026/10/01 09:30:29 OK 1_commit_pending_closure.sql (2ms)11832026/10/01 09:30:29 OK 2_object_stats_trigger.sql (456.21µs)11842026/10/01 09:30:29 OK 3_commit_push.sql (367.25µs)11852026/10/01 09:30:29 goose: up to current file version: 311862026-10-01 09:30:29.661 UTC [36206] ERROR: relation "goose_db_version" does not exist at character 3611872026-10-01 09:30:29.661 UTC [36206] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11882026/10/01 09:30:29 OK 20241026095416_initial_model.sql (112.58ms)11892026/10/01 09:30:29 OK 20251210153512_drop_unused_gin_index.sql (4.75ms)1190--- PASS: TestReadProxyDisabled (2.31s)1191=== CONT TestParseSingleRange1192=== RUN TestParseSingleRange/none1193=== PAUSE TestParseSingleRange/none1194=== RUN TestParseSingleRange/unknown_unit1195=== PAUSE TestParseSingleRange/unknown_unit1196=== RUN TestParseSingleRange/multi-range_ignored1197=== PAUSE TestParseSingleRange/multi-range_ignored1198=== RUN TestParseSingleRange/malformed_no_dash1199=== PAUSE TestParseSingleRange/malformed_no_dash1200=== RUN TestParseSingleRange/malformed_both_empty1201=== PAUSE TestParseSingleRange/malformed_both_empty1202=== RUN TestParseSingleRange/malformed_end_before_start1203=== PAUSE TestParseSingleRange/malformed_end_before_start1204=== RUN TestParseSingleRange/closed1205=== PAUSE TestParseSingleRange/closed1206=== RUN TestParseSingleRange/open-ended1207=== PAUSE TestParseSingleRange/open-ended1208=== RUN TestParseSingleRange/end_clamped_to_size1209=== PAUSE TestParseSingleRange/end_clamped_to_size1210=== RUN TestParseSingleRange/suffix1211=== PAUSE TestParseSingleRange/suffix1212=== RUN TestParseSingleRange/suffix_exceeds_size1213=== PAUSE TestParseSingleRange/suffix_exceeds_size1214=== RUN TestParseSingleRange/single_byte1215=== PAUSE TestParseSingleRange/single_byte1216=== RUN TestParseSingleRange/start_past_EOF1217=== PAUSE TestParseSingleRange/start_past_EOF1218=== RUN TestParseSingleRange/start_far_past_EOF1219=== PAUSE TestParseSingleRange/start_far_past_EOF1220=== CONT TestPresentNotReportedWhileGCDeletesClosure12212026/10/01 09:30:29 OK 20251218171726_add_pins.sql (42.27ms)12222026-10-01 09:30:29.883 UTC [36210] ERROR: relation "goose_db_version" does not exist at character 3612232026-10-01 09:30:29.883 UTC [36210] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12242026/10/01 09:30:29 OK 20260628120000_add_object_size_and_stats.sql (31.5ms)12252026/10/01 09:30:29 OK 20260905000000_add_claims.sql (32.6ms)12262026/10/01 09:30:29 OK 20260920000000_drop_claims.sql (8.93ms)12272026-10-01 09:30:29.946 UTC [36212] ERROR: relation "goose_db_version" does not exist at character 3612282026-10-01 09:30:29.946 UTC [36212] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12292026/10/01 09:30:29 OK 20260923120000_add_pushes.sql (4.91ms)12302026/10/01 09:30:29 goose: successfully migrated database to version: 2026092312000012312026/10/01 09:30:29 OK 1_commit_pending_closure.sql (3.47ms)12322026/10/01 09:30:29 OK 2_object_stats_trigger.sql (597.79µs)12332026/10/01 09:30:29 OK 3_commit_push.sql (578.38µs)12342026/10/01 09:30:29 goose: up to current file version: 312352026-10-01 09:30:29.986 UTC [36213] ERROR: relation "goose_db_version" does not exist at character 3612362026-10-01 09:30:29.986 UTC [36213] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12372026/10/01 09:30:29 OK 20241026095416_initial_model.sql (58.95ms)12382026/10/01 09:30:29 OK 20251210153512_drop_unused_gin_index.sql (7.81ms)12392026/10/01 09:30:30 OK 20251218171726_add_pins.sql (25.98ms)12402026/10/01 09:30:30 OK 20260628120000_add_object_size_and_stats.sql (30.48ms)12412026/10/01 09:30:30 OK 20260905000000_add_claims.sql (19.42ms)12422026/10/01 09:30:30 OK 20241026095416_initial_model.sql (96.56ms)1243--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.20s)1244=== CONT TestPresentReportsOnlyClosureRoots12452026/10/01 09:30:30 OK 20251210153512_drop_unused_gin_index.sql (19.82ms)12462026/10/01 09:30:30 OK 20260920000000_drop_claims.sql (44.04ms)12472026/10/01 09:30:30 OK 20251218171726_add_pins.sql (20.24ms)12482026/10/01 09:30:30 OK 20260923120000_add_pushes.sql (8.95ms)12492026/10/01 09:30:30 goose: successfully migrated database to version: 2026092312000012502026/10/01 09:30:30 OK 1_commit_pending_closure.sql (2.33ms)12512026/10/01 09:30:30 OK 2_object_stats_trigger.sql (423.21µs)12522026/10/01 09:30:30 OK 3_commit_push.sql (349.17µs)12532026/10/01 09:30:30 goose: up to current file version: 312542026/10/01 09:30:30 OK 20260628120000_add_object_size_and_stats.sql (36.29ms)12552026/10/01 09:30:30 OK 20241026095416_initial_model.sql (131.03ms)12562026/10/01 09:30:30 OK 20251210153512_drop_unused_gin_index.sql (14.34ms)12572026/10/01 09:30:30 OK 20260905000000_add_claims.sql (23.93ms)12582026/10/01 09:30:30 OK 20251218171726_add_pins.sql (9.24ms)12592026/10/01 09:30:30 OK 20260920000000_drop_claims.sql (15.06ms)12602026-10-01 09:30:30.202 UTC [36216] ERROR: relation "goose_db_version" does not exist at character 3612612026-10-01 09:30:30.202 UTC [36216] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12622026/10/01 09:30:30 OK 20260628120000_add_object_size_and_stats.sql (25.19ms)12632026/10/01 09:30:30 OK 20260923120000_add_pushes.sql (11.09ms)12642026/10/01 09:30:30 goose: successfully migrated database to version: 2026092312000012652026/10/01 09:30:30 OK 1_commit_pending_closure.sql (2.51ms)12662026/10/01 09:30:30 OK 2_object_stats_trigger.sql (526.13µs)12672026/10/01 09:30:30 OK 3_commit_push.sql (337.29µs)12682026/10/01 09:30:30 goose: up to current file version: 312692026/10/01 09:30:30 OK 20260905000000_add_claims.sql (17.43ms)12702026/10/01 09:30:30 OK 20260920000000_drop_claims.sql (25.91ms)12712026/10/01 09:30:30 OK 20260923120000_add_pushes.sql (9.99ms)12722026/10/01 09:30:30 goose: successfully migrated database to version: 2026092312000012732026/10/01 09:30:30 OK 1_commit_pending_closure.sql (2.8ms)12742026/10/01 09:30:30 OK 2_object_stats_trigger.sql (537.08µs)12752026/10/01 09:30:30 OK 3_commit_push.sql (336.33µs)12762026/10/01 09:30:30 goose: up to current file version: 31277--- PASS: TestReadProxyConditionalGet (2.02s)1278=== CONT TestCreatePin_ReservedPins12792026/10/01 09:30:30 OK 20241026095416_initial_model.sql (95.24ms)12802026/10/01 09:30:30 OK 20251210153512_drop_unused_gin_index.sql (3.9ms)12812026/10/01 09:30:30 OK 20251218171726_add_pins.sql (23.83ms)12822026/10/01 09:30:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:64899/oidc12832026/10/01 09:30:30 OK 20260628120000_add_object_size_and_stats.sql (41.42ms)12842026/10/01 09:30:30 OK 20260905000000_add_claims.sql (44.54ms)12852026/10/01 09:30:30 OK 20260920000000_drop_claims.sql (39.85ms)12862026/10/01 09:30:30 OK 20260923120000_add_pushes.sql (6.56ms)12872026/10/01 09:30:30 goose: successfully migrated database to version: 2026092312000012882026/10/01 09:30:30 OK 1_commit_pending_closure.sql (1.31ms)12892026/10/01 09:30:30 OK 2_object_stats_trigger.sql (322.04µs)12902026/10/01 09:30:30 OK 3_commit_push.sql (227.92µs)12912026/10/01 09:30:30 goose: up to current file version: 31292--- PASS: TestReadProxyHead (2.01s)1293=== CONT TestOrphanedObjectsGCStressTest12942026-10-01 09:30:30.660 UTC [36222] ERROR: relation "goose_db_version" does not exist at character 3612952026-10-01 09:30:30.660 UTC [36222] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1296--- PASS: TestReadProxyInvalidPath (2.05s)1297=== CONT TestOrphanedObjectsGC12982026/10/01 09:30:30 OK 20241026095416_initial_model.sql (221.78ms)12992026-10-01 09:30:30.958 UTC [36225] ERROR: relation "goose_db_version" does not exist at character 3613002026-10-01 09:30:30.958 UTC [36225] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13012026/10/01 09:30:30 OK 20251210153512_drop_unused_gin_index.sql (16.38ms)13022026/10/01 09:30:30 OK 20251218171726_add_pins.sql (22.28ms)13032026/10/01 09:30:31 OK 20260628120000_add_object_size_and_stats.sql (56.1ms)1304--- PASS: TestReadProxy404 (2.38s)1305=== CONT TestObjectStatsTrigger13062026/10/01 09:30:31 OK 20260905000000_add_claims.sql (78.86ms)13072026/10/01 09:30:31 OK 20260920000000_drop_claims.sql (50ms)13082026/10/01 09:30:31 OK 20260923120000_add_pushes.sql (17.36ms)13092026/10/01 09:30:31 goose: successfully migrated database to version: 2026092312000013102026/10/01 09:30:31 OK 1_commit_pending_closure.sql (3.08ms)13112026/10/01 09:30:31 OK 2_object_stats_trigger.sql (607.71µs)13122026/10/01 09:30:31 OK 3_commit_push.sql (402.21µs)13132026/10/01 09:30:31 goose: up to current file version: 313142026/10/01 09:30:31 OK 20241026095416_initial_model.sql (207.3ms)13152026/10/01 09:30:31 OK 20251210153512_drop_unused_gin_index.sql (22.74ms)13162026/10/01 09:30:31 OK 20251218171726_add_pins.sql (13.6ms)13172026/10/01 09:30:31 OK 20260628120000_add_object_size_and_stats.sql (40.76ms)13182026/10/01 09:30:31 OK 20260905000000_add_claims.sql (75.68ms)13192026/10/01 09:30:31 OK 20260920000000_drop_claims.sql (48.26ms)1320--- PASS: TestReadProxyNarStreaming (2.52s)1321=== CONT TestMultipartCleanup13222026/10/01 09:30:31 OK 20260923120000_add_pushes.sql (29.3ms)13232026/10/01 09:30:31 goose: successfully migrated database to version: 2026092312000013242026/10/01 09:30:31 OK 1_commit_pending_closure.sql (3.26ms)13252026/10/01 09:30:31 OK 2_object_stats_trigger.sql (674.92µs)13262026/10/01 09:30:31 OK 3_commit_push.sql (436.92µs)13272026/10/01 09:30:31 goose: up to current file version: 313282026-10-01 09:30:31.515 UTC [36228] ERROR: relation "goose_db_version" does not exist at character 3613292026-10-01 09:30:31.515 UTC [36228] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13302026-10-01 09:30:31.620 UTC [36231] ERROR: relation "goose_db_version" does not exist at character 3613312026-10-01 09:30:31.620 UTC [36231] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1332--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.54s)1333=== CONT TestServerTLSConfig1334=== RUN TestServerTLSConfig/no_client_CA1335=== PAUSE TestServerTLSConfig/no_client_CA1336=== RUN TestServerTLSConfig/missing_CA_file1337=== PAUSE TestServerTLSConfig/missing_CA_file1338=== RUN TestServerTLSConfig/not_a_PEM_file1339=== PAUSE TestServerTLSConfig/not_a_PEM_file1340=== CONT TestService_NativeMTLS13412026/10/01 09:30:31 OK 20241026095416_initial_model.sql (193.06ms)13422026/10/01 09:30:31 OK 20251210153512_drop_unused_gin_index.sql (15.07ms)13432026/10/01 09:30:31 OK 20251218171726_add_pins.sql (20.06ms)13442026/10/01 09:30:31 OK 20260628120000_add_object_size_and_stats.sql (47.73ms)13452026/10/01 09:30:31 OK 20260905000000_add_claims.sql (100.71ms)13462026/10/01 09:30:31 OK 20241026095416_initial_model.sql (249.03ms)13472026/10/01 09:30:31 OK 20251210153512_drop_unused_gin_index.sql (21.43ms)13482026/10/01 09:30:31 OK 20260920000000_drop_claims.sql (39.05ms)13492026/10/01 09:30:31 OK 20251218171726_add_pins.sql (32.96ms)13502026/10/01 09:30:32 OK 20260923120000_add_pushes.sql (29.77ms)13512026/10/01 09:30:32 goose: successfully migrated database to version: 2026092312000013522026/10/01 09:30:32 OK 1_commit_pending_closure.sql (6.49ms)13532026/10/01 09:30:32 OK 2_object_stats_trigger.sql (1.07ms)13542026/10/01 09:30:32 OK 3_commit_push.sql (845.17µs)13552026/10/01 09:30:32 goose: up to current file version: 313562026/10/01 09:30:32 OK 20260628120000_add_object_size_and_stats.sql (42.66ms)13572026-10-01 09:30:32.054 UTC [36234] ERROR: relation "goose_db_version" does not exist at character 3613582026-10-01 09:30:32.054 UTC [36234] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1359--- PASS: TestReadProxyNarinfo (2.67s)1360=== CONT TestMetricsInventory13612026/10/01 09:30:32 OK 20260905000000_add_claims.sql (53.61ms)13622026/10/01 09:30:32 OK 20260920000000_drop_claims.sql (64.69ms)13632026/10/01 09:30:32 OK 20260923120000_add_pushes.sql (23.31ms)13642026/10/01 09:30:32 goose: successfully migrated database to version: 2026092312000013652026/10/01 09:30:32 OK 1_commit_pending_closure.sql (3.34ms)13662026/10/01 09:30:32 OK 2_object_stats_trigger.sql (681.29µs)13672026/10/01 09:30:32 OK 3_commit_push.sql (467.42µs)13682026/10/01 09:30:32 goose: up to current file version: 313692026/10/01 09:30:32 OK 20241026095416_initial_model.sql (246.61ms)13702026/10/01 09:30:32 INFO Starting HTTP server address=127.0.0.1:6492513712026/10/01 09:30:32 INFO Starting HTTP server address=/nix/var/nix/builds/nix-36033-363360632/TestProxyHeadersOnlyTrustedOnSocket717736336/001/proxy.sock13722026/10/01 09:30:32 WARN mTLS auth: subject not in bound subjects subject="CN=someone"13732026/10/01 09:30:32 INFO Shutdown signal received, draining in-flight requests timeout=10s13742026/10/01 09:30:32 OK 20251210153512_drop_unused_gin_index.sql (15.15ms)1375--- PASS: TestProxyHeadersOnlyTrustedOnSocket (2.79s)1376=== CONT TestNARDeduplicationMetadataUploadBug13772026/10/01 09:30:32 OK 20251218171726_add_pins.sql (41.18ms)13782026/10/01 09:30:32 OK 20260628120000_add_object_size_and_stats.sql (30.34ms)13792026/10/01 09:30:32 OK 20260905000000_add_claims.sql (57.21ms)13802026/10/01 09:30:32 OK 20260920000000_drop_claims.sql (54.99ms)13812026/10/01 09:30:32 OK 20260923120000_add_pushes.sql (10.73ms)13822026/10/01 09:30:32 goose: successfully migrated database to version: 2026092312000013832026/10/01 09:30:32 OK 1_commit_pending_closure.sql (4.8ms)13842026/10/01 09:30:32 OK 2_object_stats_trigger.sql (831.71µs)13852026/10/01 09:30:32 OK 3_commit_push.sql (552.25µs)13862026/10/01 09:30:32 goose: up to current file version: 313872026-10-01 09:30:32.710 UTC [36239] ERROR: relation "goose_db_version" does not exist at character 3613882026-10-01 09:30:32.710 UTC [36239] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13892026-10-01 09:30:32.954 UTC [36243] ERROR: relation "goose_db_version" does not exist at character 3613902026-10-01 09:30:32.954 UTC [36243] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13912026/10/01 09:30:33 OK 20241026095416_initial_model.sql (218.17ms)13922026/10/01 09:30:33 OK 20251210153512_drop_unused_gin_index.sql (18.97ms)13932026/10/01 09:30:33 OK 20251218171726_add_pins.sql (41.01ms)1394--- PASS: TestPresentReportsOnlyClosureRoots (3.01s)1395=== CONT TestCreatePendingClosureRejectsOversizedNAR13962026/10/01 09:30:33 INFO Received uploads request method=POST path=/api/pending_closures1397--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1398=== CONT TestCacheConfigHandlerMaxNarSize1399--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1400=== CONT TestGenerateLandingPage1401--- PASS: TestGenerateLandingPage (0.00s)1402=== CONT TestService_readinessHandler14032026/10/01 09:30:33 OK 20260628120000_add_object_size_and_stats.sql (37.43ms)14042026/10/01 09:30:33 OK 20260905000000_add_claims.sql (25.57ms)14052026/10/01 09:30:33 OK 20260920000000_drop_claims.sql (3.12ms)14062026/10/01 09:30:33 OK 20260923120000_add_pushes.sql (10.74ms)14072026/10/01 09:30:33 goose: successfully migrated database to version: 2026092312000014082026/10/01 09:30:33 OK 1_commit_pending_closure.sql (2.63ms)14092026/10/01 09:30:33 OK 2_object_stats_trigger.sql (473.67µs)14102026/10/01 09:30:33 OK 3_commit_push.sql (374.67µs)14112026/10/01 09:30:33 goose: up to current file version: 314122026-10-01 09:30:33.201 UTC [36247] ERROR: relation "goose_db_version" does not exist at character 3614132026-10-01 09:30:33.201 UTC [36247] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14142026/10/01 09:30:33 OK 20241026095416_initial_model.sql (166.13ms)14152026/10/01 09:30:33 OK 20251210153512_drop_unused_gin_index.sql (13.52ms)14162026/10/01 09:30:33 OK 20251218171726_add_pins.sql (66.74ms)1417--- PASS: TestPresentNotReportedWhileGCDeletesClosure (3.45s)1418=== CONT TestService_healthCheckHandler14192026/10/01 09:30:33 OK 20260628120000_add_object_size_and_stats.sql (46.78ms)14202026-10-01 09:30:33.336 UTC [36248] ERROR: relation "goose_db_version" does not exist at character 3614212026-10-01 09:30:33.336 UTC [36248] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14222026/10/01 09:30:33 OK 20260905000000_add_claims.sql (89.7ms)14232026/10/01 09:30:33 OK 20260920000000_drop_claims.sql (47.75ms)14242026/10/01 09:30:33 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14252026/10/01 09:30:33 WARN Refused reserved pin name=worker-x86_64-linux14262026/10/01 09:30:33 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14272026/10/01 09:30:33 INFO Received create pin request method=POST path=/api/pins/my-app14282026/10/01 09:30:33 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1429--- PASS: TestCreatePin_ReservedPins (3.18s)1430=== CONT TestGracefulShutdownDrainsInflight14312026/10/01 09:30:33 INFO Starting HTTP server address=127.0.0.1:6493414322026/10/01 09:30:33 INFO Shutdown signal received, draining in-flight requests timeout=10s14332026/10/01 09:30:33 OK 20260923120000_add_pushes.sql (14.94ms)14342026/10/01 09:30:33 goose: successfully migrated database to version: 2026092312000014352026/10/01 09:30:33 OK 1_commit_pending_closure.sql (3.23ms)14362026/10/01 09:30:33 OK 2_object_stats_trigger.sql (627.25µs)14372026/10/01 09:30:33 OK 3_commit_push.sql (405.13µs)14382026/10/01 09:30:33 goose: up to current file version: 31439--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1440=== CONT TestGCTaskStore_Fail1441--- PASS: TestGCTaskStore_Fail (0.00s)1442=== CONT TestGCBugBareHashReferences14432026/10/01 09:30:33 OK 20241026095416_initial_model.sql (258.56ms)14442026/10/01 09:30:33 OK 20251210153512_drop_unused_gin_index.sql (9.32ms)14452026/10/01 09:30:33 OK 20251218171726_add_pins.sql (40.78ms)14462026/10/01 09:30:33 OK 20260628120000_add_object_size_and_stats.sql (26.75ms)14472026/10/01 09:30:33 OK 20241026095416_initial_model.sql (218.59ms)14482026/10/01 09:30:33 OK 20251210153512_drop_unused_gin_index.sql (11.42ms)14492026/10/01 09:30:33 OK 20260905000000_add_claims.sql (31.03ms)14502026/10/01 09:30:33 OK 20251218171726_add_pins.sql (20.28ms)14512026/10/01 09:30:33 OK 20260628120000_add_object_size_and_stats.sql (35.89ms)14522026/10/01 09:30:33 OK 20260920000000_drop_claims.sql (58.4ms)14532026/10/01 09:30:33 OK 20260923120000_add_pushes.sql (10.84ms)14542026/10/01 09:30:33 goose: successfully migrated database to version: 2026092312000014552026/10/01 09:30:33 OK 1_commit_pending_closure.sql (4.97ms)14562026/10/01 09:30:33 OK 2_object_stats_trigger.sql (818.54µs)14572026/10/01 09:30:33 OK 3_commit_push.sql (579.79µs)14582026/10/01 09:30:33 goose: up to current file version: 314592026/10/01 09:30:33 OK 20260905000000_add_claims.sql (62.1ms)14602026/10/01 09:30:33 OK 20260920000000_drop_claims.sql (21.11ms)14612026/10/01 09:30:33 OK 20260923120000_add_pushes.sql (14.27ms)14622026/10/01 09:30:33 goose: successfully migrated database to version: 2026092312000014632026/10/01 09:30:33 OK 1_commit_pending_closure.sql (2.73ms)14642026/10/01 09:30:33 OK 2_object_stats_trigger.sql (564.42µs)14652026/10/01 09:30:33 OK 3_commit_push.sql (380.92µs)14662026/10/01 09:30:33 goose: up to current file version: 314672026-10-01 09:30:33.859 UTC [36253] ERROR: relation "goose_db_version" does not exist at character 3614682026-10-01 09:30:33.859 UTC [36253] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14692026/10/01 09:30:34 OK 20241026095416_initial_model.sql (254.46ms)14702026/10/01 09:30:34 OK 20251210153512_drop_unused_gin_index.sql (16.33ms)14712026-10-01 09:30:34.222 UTC [36254] ERROR: relation "goose_db_version" does not exist at character 3614722026-10-01 09:30:34.222 UTC [36254] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14732026/10/01 09:30:34 OK 20251218171726_add_pins.sql (25.06ms)14742026/10/01 09:30:34 OK 20260628120000_add_object_size_and_stats.sql (47.45ms)14752026/10/01 09:30:34 OK 20260905000000_add_claims.sql (49.63ms)14762026/10/01 09:30:34 OK 20260920000000_drop_claims.sql (45.89ms)14772026/10/01 09:30:34 OK 20260923120000_add_pushes.sql (23.53ms)14782026/10/01 09:30:34 goose: successfully migrated database to version: 2026092312000014792026/10/01 09:30:34 OK 1_commit_pending_closure.sql (4.73ms)14802026/10/01 09:30:34 OK 2_object_stats_trigger.sql (830.17µs)14812026/10/01 09:30:34 OK 3_commit_push.sql (571.92µs)14822026/10/01 09:30:34 goose: up to current file version: 314832026/10/01 09:30:34 OK 20241026095416_initial_model.sql (200.72ms)14842026/10/01 09:30:34 OK 20251210153512_drop_unused_gin_index.sql (9.88ms)14852026/10/01 09:30:34 OK 20251218171726_add_pins.sql (22.99ms)1486--- PASS: TestObjectStatsTrigger (3.46s)1487=== CONT TestGCTaskStore_CompletedAllowsNewTask1488--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1489=== CONT TestGCTaskStore_GetReturnsLatest1490--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1491=== CONT TestGCTaskStore_GetEmpty1492--- PASS: TestGCTaskStore_GetEmpty (0.00s)1493=== CONT TestGCTaskStore_ConflictDifferentParams1494--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1495=== CONT TestGCTaskStore_DeduplicateSameParams1496--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1497=== CONT TestGCTaskStore_StartNew1498--- PASS: TestGCTaskStore_StartNew (0.00s)1499=== CONT TestCommitRacingPendingCleanupKeepsObjects15002026/10/01 09:30:34 OK 20260628120000_add_object_size_and_stats.sql (56.15ms)15012026-10-01 09:30:34.647 UTC [36256] ERROR: relation "goose_db_version" does not exist at character 3615022026-10-01 09:30:34.647 UTC [36256] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15032026/10/01 09:30:34 OK 20260905000000_add_claims.sql (86.37ms)15042026/10/01 09:30:34 OK 20260920000000_drop_claims.sql (39.14ms)15052026/10/01 09:30:34 OK 20260923120000_add_pushes.sql (22.46ms)15062026/10/01 09:30:34 goose: successfully migrated database to version: 2026092312000015072026/10/01 09:30:34 OK 1_commit_pending_closure.sql (5.69ms)15082026/10/01 09:30:34 OK 2_object_stats_trigger.sql (811.17µs)15092026/10/01 09:30:34 OK 3_commit_push.sql (550.13µs)15102026/10/01 09:30:34 goose: up to current file version: 315112026/10/01 09:30:34 INFO Received uploads request method=POST path=/api/pending_closures15122026-10-01 09:30:34.847 UTC [36258] ERROR: relation "goose_db_version" does not exist at character 3615132026-10-01 09:30:34.847 UTC [36258] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15142026/10/01 09:30:34 OK 20241026095416_initial_model.sql (202.15ms)15152026/10/01 09:30:34 OK 20251210153512_drop_unused_gin_index.sql (23.7ms)1516=== NAME TestOrphanedObjectsGC1517 orphaned_objects_gc_test.go:290: GC Test Summary:1518 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1519 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1520 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1521 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1522 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1523--- PASS: TestOrphanedObjectsGC (4.19s)1524=== CONT TestPushWaitsForSweepHoldingRow15252026/10/01 09:30:34 OK 20251218171726_add_pins.sql (40.09ms)15262026/10/01 09:30:35 INFO Received cleanup request method=DELETE path=/api/pending_closures15272026/10/01 09:30:35 INFO Aborted multipart uploads count=115282026/10/01 09:30:35 OK 20260628120000_add_object_size_and_stats.sql (44.91ms)1529--- PASS: TestMultipartCleanup (3.57s)1530=== CONT TestSweepRechecksPendingAfterLocking15312026/10/01 09:30:35 OK 20260905000000_add_claims.sql (59.33ms)15322026/10/01 09:30:35 OK 20260920000000_drop_claims.sql (42.05ms)15332026/10/01 09:30:35 WARN mTLS auth: subject not in bound subjects subject="CN=reader"15342026/10/01 09:30:35 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1535--- PASS: TestService_NativeMTLS (3.40s)1536=== CONT TestGetExistingObjectsLocksRows15372026/10/01 09:30:35 OK 20241026095416_initial_model.sql (215.67ms)15382026/10/01 09:30:35 OK 20251210153512_drop_unused_gin_index.sql (16.47ms)15392026/10/01 09:30:35 OK 20260923120000_add_pushes.sql (20.34ms)15402026/10/01 09:30:35 goose: successfully migrated database to version: 2026092312000015412026/10/01 09:30:35 OK 1_commit_pending_closure.sql (3.21ms)15422026/10/01 09:30:35 OK 2_object_stats_trigger.sql (563.25µs)15432026/10/01 09:30:35 OK 3_commit_push.sql (338.92µs)15442026/10/01 09:30:35 goose: up to current file version: 315452026/10/01 09:30:35 OK 20251218171726_add_pins.sql (24.64ms)15462026/10/01 09:30:35 OK 20260628120000_add_object_size_and_stats.sql (39.08ms)15472026/10/01 09:30:35 OK 20260905000000_add_claims.sql (73.39ms)15482026/10/01 09:30:35 OK 20260920000000_drop_claims.sql (47.05ms)15492026/10/01 09:30:35 OK 20260923120000_add_pushes.sql (28.15ms)15502026/10/01 09:30:35 goose: successfully migrated database to version: 2026092312000015512026/10/01 09:30:35 OK 1_commit_pending_closure.sql (5.95ms)15522026/10/01 09:30:35 OK 2_object_stats_trigger.sql (1.02ms)15532026/10/01 09:30:35 OK 3_commit_push.sql (1.83ms)15542026/10/01 09:30:35 goose: up to current file version: 315552026-10-01 09:30:35.383 UTC [36265] ERROR: relation "goose_db_version" does not exist at character 3615562026-10-01 09:30:35.383 UTC [36265] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1557--- PASS: TestMetricsInventory (3.45s)1558=== CONT TestRegisterCompletedObjectNeedsPendingRow15592026-10-01 09:30:35.658 UTC [36268] ERROR: relation "goose_db_version" does not exist at character 3615602026-10-01 09:30:35.658 UTC [36268] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15612026/10/01 09:30:35 OK 20241026095416_initial_model.sql (189.62ms)15622026/10/01 09:30:35 OK 20251210153512_drop_unused_gin_index.sql (13.67ms)15632026/10/01 09:30:35 OK 20251218171726_add_pins.sql (36.58ms)15642026/10/01 09:30:35 OK 20260628120000_add_object_size_and_stats.sql (37.12ms)15652026/10/01 09:30:35 OK 20260905000000_add_claims.sql (62.86ms)15662026/10/01 09:30:35 OK 20260920000000_drop_claims.sql (12.23ms)15672026/10/01 09:30:35 OK 20260923120000_add_pushes.sql (10.53ms)15682026/10/01 09:30:35 goose: successfully migrated database to version: 2026092312000015692026/10/01 09:30:35 OK 1_commit_pending_closure.sql (4.19ms)15702026/10/01 09:30:35 OK 2_object_stats_trigger.sql (975.88µs)15712026/10/01 09:30:35 OK 3_commit_push.sql (528.75µs)15722026/10/01 09:30:35 goose: up to current file version: 315732026/10/01 09:30:35 OK 20241026095416_initial_model.sql (146ms)15742026/10/01 09:30:35 OK 20251210153512_drop_unused_gin_index.sql (7.7ms)15752026/10/01 09:30:35 OK 20251218171726_add_pins.sql (17.34ms)15762026-10-01 09:30:35.948 UTC [36271] ERROR: relation "goose_db_version" does not exist at character 3615772026-10-01 09:30:35.948 UTC [36271] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15782026/10/01 09:30:35 OK 20260628120000_add_object_size_and_stats.sql (44.5ms)15792026/10/01 09:30:36 OK 20260905000000_add_claims.sql (47.93ms)1580=== NAME TestNARDeduplicationMetadataUploadBug1581 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-36033-363360632/TestNARDeduplicationMetadataUploadBug114778356/001/store/rq5a2hwfw6xfhfxa197yvzn3nh00y72g-file1.txt15822026/10/01 09:30:36 OK 20260920000000_drop_claims.sql (56.12ms)15832026/10/01 09:30:36 OK 20260923120000_add_pushes.sql (12.5ms)15842026/10/01 09:30:36 goose: successfully migrated database to version: 2026092312000015852026/10/01 09:30:36 OK 1_commit_pending_closure.sql (985.75µs)15862026/10/01 09:30:36 OK 2_object_stats_trigger.sql (284.17µs)15872026/10/01 09:30:36 OK 3_commit_push.sql (454.83µs)15882026/10/01 09:30:36 goose: up to current file version: 315892026/10/01 09:30:36 WARN readiness check failed error="closed pool"1590--- PASS: TestService_readinessHandler (3.00s)1591=== CONT TestSweepSkipsRowsLockedByPush15922026/10/01 09:30:36 INFO Received push request method=POST path=/api/pushes15932026/10/01 09:30:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15942026/10/01 09:30:36 INFO Uploading rq5a2hwfw6xfhfxa197yvzn3nh00y72g-file1.txt (160B)15952026/10/01 09:30:36 OK 20241026095416_initial_model.sql (148.76ms)15962026/10/01 09:30:36 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"15972026/10/01 09:30:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15982026/10/01 09:30:36 WARN Failed to register uploaded object key=rq5a2hwfw6xfhfxa197yvzn3nh00y72g.ls error="server returned 404: 404 page not found\n"15992026/10/01 09:30:36 INFO Signed narinfos id=1 count=116002026/10/01 09:30:36 INFO Uploading 1 narinfos16012026/10/01 09:30:36 OK 20251210153512_drop_unused_gin_index.sql (12.97ms)16022026/10/01 09:30:36 INFO Received complete push request method=POST path=/api/pushes/1/complete16032026/10/01 09:30:36 WARN Failed to register uploaded object key=rq5a2hwfw6xfhfxa197yvzn3nh00y72g.narinfo error="server returned 404: 404 page not found\n"16042026/10/01 09:30:36 OK 20251218171726_add_pins.sql (26.77ms)16052026/10/01 09:30:36 INFO Upload complete. (129ms)1606=== NAME TestNARDeduplicationMetadataUploadBug1607 metadata_upload_test.go:54: Retrieved narinfo from S3:1608 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestNARDeduplicationMetadataUploadBug114778356/001/store/rq5a2hwfw6xfhfxa197yvzn3nh00y72g-file1.txt1609 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1610 Compression: zstd1611 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1612 NarSize: 1601613 References: 1614 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1615 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1616 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1617 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}16182026/10/01 09:30:36 OK 20260628120000_add_object_size_and_stats.sql (47.22ms)16192026/10/01 09:30:36 OK 20260905000000_add_claims.sql (51.24ms)1620 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-36033-363360632/TestNARDeduplicationMetadataUploadBug114778356/001/store/irgjc6ilbm0gapvm076lz2h1ka8294xb-file2.txt16212026/10/01 09:30:36 OK 20260920000000_drop_claims.sql (22.35ms)16222026/10/01 09:30:36 OK 20260923120000_add_pushes.sql (15.69ms)16232026/10/01 09:30:36 goose: successfully migrated database to version: 2026092312000016242026/10/01 09:30:36 OK 1_commit_pending_closure.sql (883.13µs)16252026/10/01 09:30:36 OK 2_object_stats_trigger.sql (236.29µs)16262026/10/01 09:30:36 OK 3_commit_push.sql (187.58µs)16272026/10/01 09:30:36 goose: up to current file version: 31628--- PASS: TestService_healthCheckHandler (3.05s)1629=== CONT TestFailedS3DeleteKeepsTombstone16302026/10/01 09:30:36 INFO Received push request method=POST path=/api/pushes16312026/10/01 09:30:36 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16322026/10/01 09:30:36 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16332026/10/01 09:30:36 INFO Signed narinfos id=2 count=116342026/10/01 09:30:36 INFO Uploading 1 narinfos16352026/10/01 09:30:36 WARN Failed to register uploaded object key=irgjc6ilbm0gapvm076lz2h1ka8294xb.ls error="server returned 404: 404 page not found\n"16362026/10/01 09:30:36 INFO Received complete push request method=POST path=/api/pushes/2/complete16372026/10/01 09:30:36 WARN Failed to register uploaded object key=irgjc6ilbm0gapvm076lz2h1ka8294xb.narinfo error="server returned 404: 404 page not found\n"16382026/10/01 09:30:36 INFO Upload complete. (89ms)1639=== NAME TestNARDeduplicationMetadataUploadBug1640 metadata_upload_test.go:76: Retrieved narinfo from S3:1641 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestNARDeduplicationMetadataUploadBug114778356/001/store/irgjc6ilbm0gapvm076lz2h1ka8294xb-file2.txt1642 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1643 Compression: zstd1644 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1645 NarSize: 1601646 References: 1647 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1648 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1649 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1650 {"version":1,"root":{"type":"regular","size":44}}1651--- PASS: TestNARDeduplicationMetadataUploadBug (4.09s)1652=== CONT TestForceGCDuringPushOffersSweptObject1653=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1654=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1655=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1656=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1657=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection16582026-10-01 09:30:36.646 UTC [36288] ERROR: relation "goose_db_version" does not exist at character 3616592026-10-01 09:30:36.646 UTC [36288] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16602026-10-01 09:30:36.754 UTC [36289] ERROR: relation "goose_db_version" does not exist at character 3616612026-10-01 09:30:36.754 UTC [36289] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16622026/10/01 09:30:36 OK 20241026095416_initial_model.sql (85.36ms)16632026/10/01 09:30:36 OK 20251210153512_drop_unused_gin_index.sql (6.46ms)16642026/10/01 09:30:36 OK 20251218171726_add_pins.sql (20.94ms)16652026-10-01 09:30:36.829 UTC [36290] ERROR: relation "goose_db_version" does not exist at character 3616662026-10-01 09:30:36.829 UTC [36290] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1667--- PASS: TestGCBugBareHashReferences (3.29s)1668=== CONT TestGCSweepDeliversEachKeyOnce16692026/10/01 09:30:36 OK 20260628120000_add_object_size_and_stats.sql (57.67ms)16702026-10-01 09:30:36.853 UTC [36291] ERROR: relation "goose_db_version" does not exist at character 3616712026-10-01 09:30:36.853 UTC [36291] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16722026/10/01 09:30:36 OK 20241026095416_initial_model.sql (90.88ms)16732026/10/01 09:30:36 OK 20251210153512_drop_unused_gin_index.sql (6.99ms)16742026/10/01 09:30:36 OK 20260905000000_add_claims.sql (27.87ms)16752026/10/01 09:30:36 OK 20251218171726_add_pins.sql (17.72ms)16762026/10/01 09:30:36 OK 20260920000000_drop_claims.sql (9.98ms)16772026/10/01 09:30:36 OK 20260923120000_add_pushes.sql (9.22ms)16782026/10/01 09:30:36 goose: successfully migrated database to version: 2026092312000016792026/10/01 09:30:36 OK 1_commit_pending_closure.sql (1.92ms)16802026/10/01 09:30:36 OK 2_object_stats_trigger.sql (371µs)16812026/10/01 09:30:36 OK 3_commit_push.sql (288µs)16822026/10/01 09:30:36 goose: up to current file version: 316832026/10/01 09:30:36 OK 20260628120000_add_object_size_and_stats.sql (27.48ms)16842026/10/01 09:30:36 OK 20260905000000_add_claims.sql (36.68ms)16852026/10/01 09:30:36 OK 20260920000000_drop_claims.sql (35.91ms)16862026/10/01 09:30:36 OK 20241026095416_initial_model.sql (132.11ms)16872026/10/01 09:30:37 OK 20251210153512_drop_unused_gin_index.sql (9.9ms)16882026/10/01 09:30:37 OK 20260923120000_add_pushes.sql (24.46ms)16892026/10/01 09:30:37 goose: successfully migrated database to version: 2026092312000016902026/10/01 09:30:37 OK 1_commit_pending_closure.sql (2.81ms)16912026/10/01 09:30:37 OK 2_object_stats_trigger.sql (655.5µs)16922026/10/01 09:30:37 OK 3_commit_push.sql (343.21µs)16932026/10/01 09:30:37 goose: up to current file version: 316942026/10/01 09:30:37 OK 20251218171726_add_pins.sql (37.83ms)16952026/10/01 09:30:37 OK 20241026095416_initial_model.sql (170.5ms)16962026/10/01 09:30:37 OK 20251210153512_drop_unused_gin_index.sql (8.1ms)16972026/10/01 09:30:37 OK 20260628120000_add_object_size_and_stats.sql (29.25ms)16982026/10/01 09:30:37 OK 20251218171726_add_pins.sql (30.49ms)16992026-10-01 09:30:37.116 UTC [36294] ERROR: relation "goose_db_version" does not exist at character 3617002026-10-01 09:30:37.116 UTC [36294] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17012026/10/01 09:30:37 OK 20260905000000_add_claims.sql (43.12ms)17022026/10/01 09:30:37 OK 20260628120000_add_object_size_and_stats.sql (34.48ms)17032026/10/01 09:30:37 OK 20260920000000_drop_claims.sql (46.44ms)17042026/10/01 09:30:37 OK 20260923120000_add_pushes.sql (13.24ms)17052026/10/01 09:30:37 goose: successfully migrated database to version: 2026092312000017062026/10/01 09:30:37 OK 1_commit_pending_closure.sql (4.31ms)17072026/10/01 09:30:37 OK 2_object_stats_trigger.sql (771µs)17082026/10/01 09:30:37 OK 3_commit_push.sql (541.92µs)17092026/10/01 09:30:37 goose: up to current file version: 317102026/10/01 09:30:37 OK 20260905000000_add_claims.sql (52.19ms)17112026/10/01 09:30:37 OK 20260920000000_drop_claims.sql (49.23ms)17122026/10/01 09:30:37 OK 20260923120000_add_pushes.sql (26.15ms)17132026/10/01 09:30:37 goose: successfully migrated database to version: 2026092312000017142026/10/01 09:30:37 OK 1_commit_pending_closure.sql (4.6ms)17152026/10/01 09:30:37 OK 2_object_stats_trigger.sql (982.08µs)17162026/10/01 09:30:37 OK 3_commit_push.sql (625.08µs)17172026/10/01 09:30:37 goose: up to current file version: 317182026/10/01 09:30:37 INFO Aborted multipart uploads count=017192026/10/01 09:30:37 WARN Force mode enabled - objects will be deleted immediately without grace period17202026/10/01 09:30:37 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=017212026/10/01 09:30:37 INFO Vacuumed table table=pending_closures17222026/10/01 09:30:37 INFO Vacuumed table table=pending_objects17232026/10/01 09:30:37 INFO Vacuumed table table=multipart_uploads17242026/10/01 09:30:37 INFO Vacuumed table table=closures17252026/10/01 09:30:37 INFO Vacuumed table table=objects17262026/10/01 09:30:37 OK 20241026095416_initial_model.sql (185.04ms)17272026/10/01 09:30:37 OK 20251210153512_drop_unused_gin_index.sql (8.24ms)1728--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.81s)1729=== CONT TestTombstonedObjectOfferedWithoutWaiting17302026/10/01 09:30:37 OK 20251218171726_add_pins.sql (53.45ms)17312026/10/01 09:30:37 OK 20260628120000_add_object_size_and_stats.sql (29.54ms)17322026/10/01 09:30:37 INFO Received uploads request method=POST path=/api/pending_closures17332026/10/01 09:30:37 OK 20260905000000_add_claims.sql (58.67ms)17342026/10/01 09:30:37 OK 20260920000000_drop_claims.sql (20.9ms)17352026/10/01 09:30:37 OK 20260923120000_add_pushes.sql (21.45ms)17362026/10/01 09:30:37 goose: successfully migrated database to version: 2026092312000017372026/10/01 09:30:37 OK 1_commit_pending_closure.sql (4.81ms)17382026/10/01 09:30:37 OK 2_object_stats_trigger.sql (780.29µs)17392026/10/01 09:30:37 OK 3_commit_push.sql (545.04µs)17402026/10/01 09:30:37 goose: up to current file version: 317412026/10/01 09:30:37 INFO Aborted multipart uploads count=017422026/10/01 09:30:37 WARN Force mode enabled - objects will be deleted immediately without grace period17432026/10/01 09:30:37 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=017442026-10-01 09:30:37.944 UTC [36305] ERROR: relation "goose_db_version" does not exist at character 3617452026-10-01 09:30:37.944 UTC [36305] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17462026/10/01 09:30:37 INFO Vacuumed table table=pending_closures17472026/10/01 09:30:37 INFO Vacuumed table table=pending_objects17482026/10/01 09:30:37 INFO Vacuumed table table=multipart_uploads17492026/10/01 09:30:37 INFO Vacuumed table table=closures1750--- PASS: TestPushWaitsForSweepHoldingRow (3.00s)1751=== CONT TestGCSweepSkipsPendingObjects17522026/10/01 09:30:37 INFO Vacuumed table table=objects1753--- PASS: TestSweepRechecksPendingAfterLocking (2.96s)1754=== CONT TestDeduplicatedObjectsRecordedAsPending1755--- PASS: TestGetExistingObjectsLocksRows (2.98s)1756=== CONT TestPushDedupSurvivesConcurrentGC17572026/10/01 09:30:38 OK 20241026095416_initial_model.sql (194.04ms)17582026/10/01 09:30:38 OK 20251210153512_drop_unused_gin_index.sql (12.89ms)17592026-10-01 09:30:38.243 UTC [36314] ERROR: relation "goose_db_version" does not exist at character 3617602026-10-01 09:30:38.243 UTC [36314] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17612026/10/01 09:30:38 OK 20251218171726_add_pins.sql (18.21ms)17622026/10/01 09:30:38 OK 20260628120000_add_object_size_and_stats.sql (40.85ms)17632026-10-01 09:30:38.311 UTC [36315] ERROR: relation "goose_db_version" does not exist at character 3617642026-10-01 09:30:38.311 UTC [36315] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17652026/10/01 09:30:38 OK 20260905000000_add_claims.sql (57.97ms)17662026/10/01 09:30:38 OK 20260920000000_drop_claims.sql (35.29ms)17672026/10/01 09:30:38 OK 20260923120000_add_pushes.sql (5.16ms)17682026/10/01 09:30:38 goose: successfully migrated database to version: 202609231200001769--- PASS: TestRegisterCompletedObjectNeedsPendingRow (2.86s)1770=== CONT TestGCMetrics17712026/10/01 09:30:38 OK 1_commit_pending_closure.sql (5.29ms)17722026/10/01 09:30:38 OK 2_object_stats_trigger.sql (2.08ms)17732026/10/01 09:30:38 OK 3_commit_push.sql (828.25µs)17742026/10/01 09:30:38 goose: up to current file version: 317752026/10/01 09:30:38 OK 20241026095416_initial_model.sql (132.36ms)17762026/10/01 09:30:38 OK 20251210153512_drop_unused_gin_index.sql (12.98ms)17772026/10/01 09:30:38 OK 20251218171726_add_pins.sql (32.26ms)17782026/10/01 09:30:38 OK 20241026095416_initial_model.sql (177.56ms)17792026/10/01 09:30:38 OK 20251210153512_drop_unused_gin_index.sql (3.38ms)17802026/10/01 09:30:38 OK 20260628120000_add_object_size_and_stats.sql (36.84ms)17812026/10/01 09:30:38 OK 20251218171726_add_pins.sql (46.44ms)17822026/10/01 09:30:38 OK 20260628120000_add_object_size_and_stats.sql (37.85ms)17832026/10/01 09:30:38 OK 20260905000000_add_claims.sql (66.07ms)17842026/10/01 09:30:38 OK 20260920000000_drop_claims.sql (46.86ms)17852026/10/01 09:30:38 OK 20260905000000_add_claims.sql (53.04ms)17862026/10/01 09:30:38 OK 20260923120000_add_pushes.sql (8.59ms)17872026/10/01 09:30:38 goose: successfully migrated database to version: 2026092312000017882026/10/01 09:30:38 OK 1_commit_pending_closure.sql (4.38ms)17892026/10/01 09:30:38 OK 2_object_stats_trigger.sql (797.17µs)17902026/10/01 09:30:38 OK 3_commit_push.sql (473.21µs)17912026/10/01 09:30:38 goose: up to current file version: 317922026/10/01 09:30:38 INFO Aborted multipart uploads count=017932026/10/01 09:30:38 OK 20260920000000_drop_claims.sql (27.72ms)17942026/10/01 09:30:38 WARN Force mode enabled - objects will be deleted immediately without grace period17952026/10/01 09:30:38 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=017962026/10/01 09:30:38 INFO Vacuumed table table=pending_closures17972026/10/01 09:30:38 INFO Vacuumed table table=pending_objects17982026/10/01 09:30:38 INFO Vacuumed table table=multipart_uploads17992026/10/01 09:30:38 INFO Vacuumed table table=closures18002026/10/01 09:30:38 OK 20260923120000_add_pushes.sql (18.37ms)18012026/10/01 09:30:38 goose: successfully migrated database to version: 2026092312000018022026/10/01 09:30:38 OK 1_commit_pending_closure.sql (2.52ms)18032026/10/01 09:30:38 OK 2_object_stats_trigger.sql (530.46µs)18042026/10/01 09:30:38 OK 3_commit_push.sql (407.71µs)18052026/10/01 09:30:38 goose: up to current file version: 318062026/10/01 09:30:38 INFO Vacuumed table table=objects18072026/10/01 09:30:38 INFO Aborted multipart uploads count=018082026/10/01 09:30:38 WARN Force mode enabled - objects will be deleted immediately without grace period18092026/10/01 09:30:38 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=018102026/10/01 09:30:38 INFO Vacuumed table table=pending_closures18112026/10/01 09:30:38 INFO Vacuumed table table=pending_objects18122026/10/01 09:30:38 INFO Vacuumed table table=multipart_uploads18132026/10/01 09:30:38 INFO Vacuumed table table=closures18142026/10/01 09:30:38 INFO Vacuumed table table=objects1815--- PASS: TestSweepSkipsRowsLockedByPush (2.73s)1816=== CONT TestClientIntegration18172026-10-01 09:30:38.904 UTC [36322] ERROR: relation "goose_db_version" does not exist at character 3618182026-10-01 09:30:38.904 UTC [36322] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18192026/10/01 09:30:38 INFO Received uploads request method=POST path=/api/pending_closures18202026/10/01 09:30:39 INFO Aborted multipart uploads count=018212026/10/01 09:30:39 WARN Force mode enabled - objects will be deleted immediately without grace period18222026/10/01 09:30:39 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."18232026/10/01 09:30:39 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1824--- PASS: TestFailedS3DeleteKeepsTombstone (2.80s)1825=== CONT TestLeadEndsOnShutdown18262026/10/01 09:30:39 OK 20241026095416_initial_model.sql (166.19ms)18272026/10/01 09:30:39 OK 20251210153512_drop_unused_gin_index.sql (14.86ms)18282026/10/01 09:30:39 OK 20251218171726_add_pins.sql (18.48ms)18292026/10/01 09:30:39 OK 20260628120000_add_object_size_and_stats.sql (73.86ms)18302026/10/01 09:30:39 INFO Received uploads request method=POST path=/api/pending_closures18312026/10/01 09:30:39 OK 20260905000000_add_claims.sql (28.67ms)18322026/10/01 09:30:39 OK 20260920000000_drop_claims.sql (18.11ms)18332026/10/01 09:30:39 OK 20260923120000_add_pushes.sql (12.05ms)18342026/10/01 09:30:39 goose: successfully migrated database to version: 2026092312000018352026/10/01 09:30:39 OK 1_commit_pending_closure.sql (2.75ms)18362026/10/01 09:30:39 OK 2_object_stats_trigger.sql (500.54µs)18372026/10/01 09:30:39 OK 3_commit_push.sql (307µs)18382026/10/01 09:30:39 goose: up to current file version: 318392026-10-01 09:30:39.367 UTC [36326] ERROR: relation "goose_db_version" does not exist at character 3618402026-10-01 09:30:39.367 UTC [36326] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1841--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (2.98s)1842=== CONT TestLeadElectsOneAndHandsOver18432026/10/01 09:30:39 OK 20241026095416_initial_model.sql (176.5ms)18442026/10/01 09:30:39 OK 20251210153512_drop_unused_gin_index.sql (10.69ms)18452026/10/01 09:30:39 OK 20251218171726_add_pins.sql (13.29ms)18462026/10/01 09:30:39 INFO Aborted multipart uploads count=018472026/10/01 09:30:39 WARN Force mode enabled - objects will be deleted immediately without grace period18482026/10/01 09:30:39 OK 20260628120000_add_object_size_and_stats.sql (42.19ms)18492026/10/01 09:30:39 OK 20260905000000_add_claims.sql (25.18ms)18502026/10/01 09:30:39 OK 20260920000000_drop_claims.sql (20.92ms)1851=== NAME TestOrphanedObjectsGCStressTest1852 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains18532026-10-01 09:30:39.716 UTC [36330] ERROR: relation "goose_db_version" does not exist at character 3618542026-10-01 09:30:39.716 UTC [36330] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18552026/10/01 09:30:39 OK 20260923120000_add_pushes.sql (4.64ms)18562026/10/01 09:30:39 goose: successfully migrated database to version: 2026092312000018572026/10/01 09:30:39 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=018582026/10/01 09:30:39 INFO Vacuumed table table=pending_closures18592026/10/01 09:30:39 INFO Vacuumed table table=pending_objects18602026/10/01 09:30:39 OK 1_commit_pending_closure.sql (3.22ms)18612026/10/01 09:30:39 INFO Vacuumed table table=multipart_uploads18622026/10/01 09:30:39 OK 2_object_stats_trigger.sql (594.88µs)18632026/10/01 09:30:39 INFO Vacuumed table table=closures18642026/10/01 09:30:39 OK 3_commit_push.sql (453.21µs)18652026/10/01 09:30:39 goose: up to current file version: 318662026/10/01 09:30:39 INFO Vacuumed table table=objects1867--- PASS: TestGCSweepDeliversEachKeyOnce (2.91s)1868=== CONT TestResolveDBConnectionString18692026-10-01 09:30:39.775 UTC [36331] ERROR: relation "goose_db_version" does not exist at character 3618702026-10-01 09:30:39.775 UTC [36331] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1871=== RUN TestResolveDBConnectionString/flag_wins1872=== PAUSE TestResolveDBConnectionString/flag_wins1873=== RUN TestResolveDBConnectionString/file_when_flag_empty1874=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1875=== RUN TestResolveDBConnectionString/missing_file_is_an_error1876=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1877=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1878=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1879=== RUN TestResolveDBConnectionString/nothing_configured1880=== PAUSE TestResolveDBConnectionString/nothing_configured1881=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1882=== NAME TestOrphanedObjectsGCStressTest1883 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion18842026-10-01 09:30:39.845 UTC [36333] ERROR: relation "goose_db_version" does not exist at character 3618852026-10-01 09:30:39.845 UTC [36333] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18862026/10/01 09:30:39 OK 20241026095416_initial_model.sql (130.45ms)18872026/10/01 09:30:39 OK 20241026095416_initial_model.sql (111.16ms)18882026/10/01 09:30:39 OK 20251210153512_drop_unused_gin_index.sql (10.13ms)18892026/10/01 09:30:39 OK 20251210153512_drop_unused_gin_index.sql (8.58ms)18902026/10/01 09:30:39 OK 20251218171726_add_pins.sql (33.46ms)18912026/10/01 09:30:39 OK 20251218171726_add_pins.sql (33.59ms)18922026/10/01 09:30:39 INFO Received uploads request method=POST path=/api/pending_closures18932026/10/01 09:30:39 OK 20260628120000_add_object_size_and_stats.sql (26.74ms)18942026/10/01 09:30:39 OK 20260628120000_add_object_size_and_stats.sql (28.22ms)1895--- PASS: TestTombstonedObjectOfferedWithoutWaiting (2.61s)1896=== CONT TestClientFallsBackToClosures18972026/10/01 09:30:39 OK 20241026095416_initial_model.sql (121.08ms)18982026/10/01 09:30:40 OK 20251210153512_drop_unused_gin_index.sql (2.9ms)18992026/10/01 09:30:40 OK 20260905000000_add_claims.sql (16.71ms)19002026/10/01 09:30:40 OK 20260905000000_add_claims.sql (16.18ms)19012026/10/01 09:30:40 OK 20251218171726_add_pins.sql (4.32ms)19022026/10/01 09:30:40 OK 20260920000000_drop_claims.sql (2.24ms)19032026/10/01 09:30:40 OK 20260920000000_drop_claims.sql (1.82ms)19042026/10/01 09:30:40 OK 20260923120000_add_pushes.sql (1.04ms)19052026/10/01 09:30:40 goose: successfully migrated database to version: 2026092312000019062026/10/01 09:30:40 OK 20260923120000_add_pushes.sql (1.32ms)19072026/10/01 09:30:40 goose: successfully migrated database to version: 2026092312000019082026/10/01 09:30:40 OK 1_commit_pending_closure.sql (2.48ms)19092026/10/01 09:30:40 OK 1_commit_pending_closure.sql (2.22ms)19102026-10-01 09:30:40.012 UTC [36336] ERROR: relation "goose_db_version" does not exist at character 3619112026-10-01 09:30:40.012 UTC [36336] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19122026/10/01 09:30:40 OK 2_object_stats_trigger.sql (693.54µs)19132026/10/01 09:30:40 OK 20260628120000_add_object_size_and_stats.sql (5.45ms)19142026/10/01 09:30:40 OK 3_commit_push.sql (526.29µs)19152026/10/01 09:30:40 goose: up to current file version: 319162026/10/01 09:30:40 OK 2_object_stats_trigger.sql (698.79µs)19172026/10/01 09:30:40 OK 3_commit_push.sql (440µs)19182026/10/01 09:30:40 goose: up to current file version: 319192026/10/01 09:30:40 OK 20260905000000_add_claims.sql (11.91ms)19202026/10/01 09:30:40 OK 20260920000000_drop_claims.sql (12.22ms)19212026/10/01 09:30:40 OK 20260923120000_add_pushes.sql (8.29ms)19222026/10/01 09:30:40 goose: successfully migrated database to version: 2026092312000019232026/10/01 09:30:40 OK 1_commit_pending_closure.sql (2.09ms)19242026/10/01 09:30:40 OK 2_object_stats_trigger.sql (395.58µs)19252026/10/01 09:30:40 OK 3_commit_push.sql (11.4ms)19262026/10/01 09:30:40 goose: up to current file version: 319272026-10-01 09:30:40.123 UTC [36338] ERROR: relation "goose_db_version" does not exist at character 3619282026-10-01 09:30:40.123 UTC [36338] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19292026/10/01 09:30:40 OK 20241026095416_initial_model.sql (70.81ms)19302026/10/01 09:30:40 OK 20251210153512_drop_unused_gin_index.sql (13.95ms)19312026/10/01 09:30:40 OK 20251218171726_add_pins.sql (13.57ms)19322026/10/01 09:30:40 OK 20260628120000_add_object_size_and_stats.sql (36.49ms)19332026/10/01 09:30:40 OK 20260905000000_add_claims.sql (42.5ms)19342026/10/01 09:30:40 INFO Received uploads request method=POST path=/api/pending_closures1935--- PASS: TestDeduplicatedObjectsRecordedAsPending (2.27s)1936=== CONT TestClientPushesUseOnePush19372026/10/01 09:30:40 OK 20260920000000_drop_claims.sql (42.51ms)19382026/10/01 09:30:40 OK 20260923120000_add_pushes.sql (8.15ms)19392026/10/01 09:30:40 goose: successfully migrated database to version: 2026092312000019402026/10/01 09:30:40 OK 1_commit_pending_closure.sql (2.53ms)19412026/10/01 09:30:40 OK 2_object_stats_trigger.sql (690.42µs)19422026/10/01 09:30:40 OK 3_commit_push.sql (490.13µs)19432026/10/01 09:30:40 goose: up to current file version: 319442026/10/01 09:30:40 OK 20241026095416_initial_model.sql (137.68ms)19452026/10/01 09:30:40 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)19462026/10/01 09:30:40 OK 20251218171726_add_pins.sql (14.76ms)19472026/10/01 09:30:40 OK 20260628120000_add_object_size_and_stats.sql (16.99ms)19482026-10-01 09:30:40.365 UTC [36341] ERROR: relation "goose_db_version" does not exist at character 3619492026-10-01 09:30:40.365 UTC [36341] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19502026/10/01 09:30:40 OK 20260905000000_add_claims.sql (27.27ms)19512026/10/01 09:30:40 OK 20260920000000_drop_claims.sql (20.14ms)19522026/10/01 09:30:40 OK 20260923120000_add_pushes.sql (11.02ms)19532026/10/01 09:30:40 goose: successfully migrated database to version: 2026092312000019542026/10/01 09:30:40 OK 1_commit_pending_closure.sql (3.27ms)19552026/10/01 09:30:40 OK 2_object_stats_trigger.sql (566.42µs)19562026/10/01 09:30:40 OK 3_commit_push.sql (400.46µs)19572026/10/01 09:30:40 goose: up to current file version: 319582026/10/01 09:30:40 INFO Received uploads request method=POST path=/api/pending_closures19592026/10/01 09:30:40 INFO Aborted multipart uploads count=019602026/10/01 09:30:40 WARN Force mode enabled - objects will be deleted immediately without grace period19612026/10/01 09:30:40 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=019622026/10/01 09:30:40 INFO Vacuumed table table=pending_closures19632026/10/01 09:30:40 INFO Vacuumed table table=pending_objects19642026/10/01 09:30:40 INFO Vacuumed table table=multipart_uploads19652026/10/01 09:30:40 INFO Vacuumed table table=closures19662026/10/01 09:30:40 OK 20241026095416_initial_model.sql (149.14ms)19672026/10/01 09:30:40 INFO Vacuumed table table=objects19682026/10/01 09:30:40 OK 20251210153512_drop_unused_gin_index.sql (3.01ms)19692026/10/01 09:30:40 OK 20251218171726_add_pins.sql (21.07ms)1970--- PASS: TestGCSweepSkipsPendingObjects (2.61s)1971=== CONT TestPinProtectsFromGC19722026/10/01 09:30:40 OK 20260628120000_add_object_size_and_stats.sql (25.93ms)19732026/10/01 09:30:40 OK 20260905000000_add_claims.sql (32.55ms)19742026/10/01 09:30:40 OK 20260920000000_drop_claims.sql (26.23ms)19752026/10/01 09:30:40 OK 20260923120000_add_pushes.sql (19.28ms)19762026/10/01 09:30:40 goose: successfully migrated database to version: 2026092312000019772026/10/01 09:30:40 OK 1_commit_pending_closure.sql (3ms)19782026/10/01 09:30:40 OK 2_object_stats_trigger.sql (647.58µs)19792026/10/01 09:30:40 OK 3_commit_push.sql (463.88µs)19802026/10/01 09:30:40 goose: up to current file version: 319812026/10/01 09:30:40 INFO Received uploads request method=POST path=/api/pending_closures19822026-10-01 09:30:40.785 UTC [36345] ERROR: relation "goose_db_version" does not exist at character 3619832026-10-01 09:30:40.785 UTC [36345] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19842026/10/01 09:30:40 INFO Aborted multipart uploads count=019852026/10/01 09:30:40 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019862026/10/01 09:30:40 INFO Vacuumed table table=pending_closures19872026/10/01 09:30:40 INFO Vacuumed table table=pending_objects19882026/10/01 09:30:40 INFO Vacuumed table table=multipart_uploads19892026/10/01 09:30:40 INFO Vacuumed table table=closures19902026/10/01 09:30:40 INFO Aborted multipart uploads count=019912026/10/01 09:30:40 WARN Force mode enabled - objects will be deleted immediately without grace period19922026/10/01 09:30:40 INFO Vacuumed table table=objects19932026/10/01 09:30:40 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=019942026/10/01 09:30:40 INFO Vacuumed table table=pending_closures19952026/10/01 09:30:40 INFO Vacuumed table table=pending_objects19962026/10/01 09:30:40 INFO Vacuumed table table=multipart_uploads19972026/10/01 09:30:40 INFO Vacuumed table table=closures19982026/10/01 09:30:40 INFO Vacuumed table table=objects1999--- PASS: TestGCMetrics (2.61s)2000=== CONT TestClientSharedPathCommittedMidPush20012026/10/01 09:30:41 INFO Aborted multipart uploads count=020022026/10/01 09:30:41 WARN Force mode enabled - objects will be deleted immediately without grace period20032026/10/01 09:30:41 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=020042026/10/01 09:30:41 OK 20241026095416_initial_model.sql (182.94ms)20052026/10/01 09:30:41 INFO Vacuumed table table=pending_closures20062026/10/01 09:30:41 OK 20251210153512_drop_unused_gin_index.sql (9.03ms)20072026/10/01 09:30:41 INFO Vacuumed table table=pending_objects20082026/10/01 09:30:41 INFO Vacuumed table table=multipart_uploads20092026/10/01 09:30:41 INFO Vacuumed table table=closures20102026/10/01 09:30:41 INFO Vacuumed table table=objects20112026/10/01 09:30:41 OK 20251218171726_add_pins.sql (11.96ms)2012--- PASS: TestPushDedupSurvivesConcurrentGC (2.93s)2013=== CONT TestClientWithDependencies20142026/10/01 09:30:41 OK 20260628120000_add_object_size_and_stats.sql (19.72ms)20152026/10/01 09:30:41 OK 20260905000000_add_claims.sql (31.69ms)20162026/10/01 09:30:41 OK 20260920000000_drop_claims.sql (15.7ms)20172026-10-01 09:30:41.152 UTC [36352] ERROR: relation "goose_db_version" does not exist at character 3620182026-10-01 09:30:41.152 UTC [36352] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20192026/10/01 09:30:41 OK 20260923120000_add_pushes.sql (48.65ms)20202026/10/01 09:30:41 goose: successfully migrated database to version: 2026092312000020212026/10/01 09:30:41 OK 1_commit_pending_closure.sql (4.55ms)20222026/10/01 09:30:41 OK 2_object_stats_trigger.sql (783.88µs)20232026/10/01 09:30:41 OK 3_commit_push.sql (410.5µs)20242026/10/01 09:30:41 goose: up to current file version: 320252026/10/01 09:30:41 OK 20241026095416_initial_model.sql (115.48ms)20262026/10/01 09:30:41 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)20272026/10/01 09:30:41 OK 20251218171726_add_pins.sql (8.26ms)20282026-10-01 09:30:41.333 UTC [36355] ERROR: relation "goose_db_version" does not exist at character 3620292026-10-01 09:30:41.333 UTC [36355] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20302026/10/01 09:30:41 OK 20260628120000_add_object_size_and_stats.sql (31.73ms)20312026/10/01 09:30:41 OK 20260905000000_add_claims.sql (39.5ms)2032=== NAME TestClientIntegration2033 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-36033-363360632/TestClientIntegration1006224575/002/store/r74kfkzli11zgpwidsl3jhc3bamq1wff-test-file.txt20342026/10/01 09:30:41 OK 20260920000000_drop_claims.sql (20.77ms)20352026/10/01 09:30:41 OK 20260923120000_add_pushes.sql (12.1ms)20362026/10/01 09:30:41 goose: successfully migrated database to version: 2026092312000020372026/10/01 09:30:41 INFO lead: acquired remote=192.0.2.1:123420382026/10/01 09:30:41 INFO lead: released remote=192.0.2.1:12342039--- PASS: TestLeadEndsOnShutdown (2.30s)2040=== CONT TestClientMultipleUploads20412026/10/01 09:30:41 OK 1_commit_pending_closure.sql (2.11ms)20422026/10/01 09:30:41 OK 2_object_stats_trigger.sql (1.38ms)20432026/10/01 09:30:41 OK 3_commit_push.sql (223.83µs)20442026/10/01 09:30:41 goose: up to current file version: 320452026/10/01 09:30:41 OK 20241026095416_initial_model.sql (92.15ms)20462026/10/01 09:30:41 OK 20251210153512_drop_unused_gin_index.sql (1.21ms)20472026/10/01 09:30:41 OK 20251218171726_add_pins.sql (15ms)20482026/10/01 09:30:41 INFO Received push request method=POST path=/api/pushes20492026-10-01 09:30:41.507 UTC [36362] ERROR: relation "goose_db_version" does not exist at character 3620502026-10-01 09:30:41.507 UTC [36362] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20512026/10/01 09:30:41 OK 20260628120000_add_object_size_and_stats.sql (15.54ms)20522026/10/01 09:30:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20532026/10/01 09:30:41 INFO Uploading r74kfkzli11zgpwidsl3jhc3bamq1wff-test-file.txt (152B)20542026/10/01 09:30:41 WARN Failed to register uploaded object key=r74kfkzli11zgpwidsl3jhc3bamq1wff.ls error="server returned 404: 404 page not found\n"20552026/10/01 09:30:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20562026/10/01 09:30:41 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"20572026/10/01 09:30:41 INFO Signed narinfos id=1 count=120582026/10/01 09:30:41 INFO Uploading 1 narinfos20592026/10/01 09:30:41 INFO Received complete push request method=POST path=/api/pushes/1/complete20602026/10/01 09:30:41 WARN Failed to register uploaded object key=r74kfkzli11zgpwidsl3jhc3bamq1wff.narinfo error="server returned 404: 404 page not found\n"20612026/10/01 09:30:41 OK 20260905000000_add_claims.sql (44.71ms)20622026/10/01 09:30:41 INFO Upload complete. (127ms)20632026/10/01 09:30:41 OK 20260920000000_drop_claims.sql (38.61ms)20642026/10/01 09:30:41 OK 20260923120000_add_pushes.sql (5.89ms)20652026/10/01 09:30:41 goose: successfully migrated database to version: 2026092312000020662026/10/01 09:30:41 OK 1_commit_pending_closure.sql (1.1ms)20672026/10/01 09:30:41 OK 2_object_stats_trigger.sql (206.54µs)20682026/10/01 09:30:41 OK 3_commit_push.sql (195.79µs)20692026/10/01 09:30:41 goose: up to current file version: 320702026/10/01 09:30:41 INFO All 1 paths already cached2071=== NAME TestClientIntegration2072 client_integration_test.go:312: Retrieved narinfo from S3:2073 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestClientIntegration1006224575/002/store/r74kfkzli11zgpwidsl3jhc3bamq1wff-test-file.txt2074 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2075 Compression: zstd2076 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12077 NarSize: 1522078 References: 2079 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12080 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2081 client_integration_test.go:313: Decompressed .ls content (64 bytes):2082 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2083 client_integration_test.go:316: Testing garbage collection...20842026/10/01 09:30:41 INFO lead: acquired remote=192.0.2.1:123420852026/10/01 09:30:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures20862026/10/01 09:30:41 INFO Garbage collection started20872026/10/01 09:30:41 INFO Aborted multipart uploads count=020882026/10/01 09:30:41 WARN Force mode enabled - objects will be deleted immediately without grace period20892026/10/01 09:30:41 OK 20241026095416_initial_model.sql (126.28ms)20902026/10/01 09:30:41 OK 20251210153512_drop_unused_gin_index.sql (1.84ms)20912026/10/01 09:30:41 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=020922026/10/01 09:30:41 OK 20251218171726_add_pins.sql (20.56ms)20932026/10/01 09:30:41 INFO Vacuumed table table=pending_closures20942026/10/01 09:30:41 INFO Vacuumed table table=pending_objects20952026/10/01 09:30:41 INFO Vacuumed table table=multipart_uploads20962026/10/01 09:30:41 OK 20260628120000_add_object_size_and_stats.sql (44.1ms)20972026/10/01 09:30:41 INFO Vacuumed table table=closures20982026/10/01 09:30:41 INFO Vacuumed table table=objects20992026/10/01 09:30:41 OK 20260905000000_add_claims.sql (14.81ms)21002026/10/01 09:30:41 INFO lead: released remote=192.0.2.1:123421012026/10/01 09:30:41 OK 20260920000000_drop_claims.sql (16.66ms)21022026/10/01 09:30:41 OK 20260923120000_add_pushes.sql (3.19ms)21032026/10/01 09:30:41 goose: successfully migrated database to version: 2026092312000021042026/10/01 09:30:41 OK 1_commit_pending_closure.sql (979.5µs)21052026/10/01 09:30:41 OK 2_object_stats_trigger.sql (230.75µs)21062026/10/01 09:30:41 OK 3_commit_push.sql (200.29µs)21072026/10/01 09:30:41 goose: up to current file version: 321082026/10/01 09:30:41 INFO lead: acquired remote=192.0.2.1:123421092026/10/01 09:30:41 INFO lead: released remote=192.0.2.1:12342110--- PASS: TestLeadElectsOneAndHandsOver (2.35s)2111=== CONT TestSkippedUploadsHandler21122026/10/01 09:30:41 INFO Client skipped oversized paths paths=3 nar_bytes=50000000002113--- PASS: TestSkippedUploadsHandler (0.00s)2114=== CONT TestIsValidUploadKey2115=== RUN TestIsValidUploadKey/narinfo2116=== PAUSE TestIsValidUploadKey/narinfo2117=== RUN TestIsValidUploadKey/nar_zst2118=== PAUSE TestIsValidUploadKey/nar_zst2119=== RUN TestIsValidUploadKey/nar_xz2120=== PAUSE TestIsValidUploadKey/nar_xz2121=== RUN TestIsValidUploadKey/nar_plain2122=== PAUSE TestIsValidUploadKey/nar_plain2123=== RUN TestIsValidUploadKey/listing2124=== PAUSE TestIsValidUploadKey/listing2125=== RUN TestIsValidUploadKey/build_log2126=== PAUSE TestIsValidUploadKey/build_log2127=== RUN TestIsValidUploadKey/build_log_home-manager_file2128=== PAUSE TestIsValidUploadKey/build_log_home-manager_file2129=== RUN TestIsValidUploadKey/build_log_plus_in_name2130=== PAUSE TestIsValidUploadKey/build_log_plus_in_name2131=== RUN TestIsValidUploadKey/build_log_question_mark2132=== PAUSE TestIsValidUploadKey/build_log_question_mark2133=== RUN TestIsValidUploadKey/build_log_equals2134=== PAUSE TestIsValidUploadKey/build_log_equals2135=== RUN TestIsValidUploadKey/realisation2136=== PAUSE TestIsValidUploadKey/realisation2137=== RUN TestIsValidUploadKey/realisation_plus_in_output2138=== PAUSE TestIsValidUploadKey/realisation_plus_in_output2139=== RUN TestIsValidUploadKey/nix-cache-info2140=== PAUSE TestIsValidUploadKey/nix-cache-info2141=== RUN TestIsValidUploadKey/index.html2142=== PAUSE TestIsValidUploadKey/index.html2143=== RUN TestIsValidUploadKey/narinfo_key,_nar_type2144=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type2145=== RUN TestIsValidUploadKey/nar_key,_narinfo_type2146=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type2147=== RUN TestIsValidUploadKey/listing_key,_narinfo_type2148=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type2149=== RUN TestIsValidUploadKey/traversal2150=== PAUSE TestIsValidUploadKey/traversal2151=== RUN TestIsValidUploadKey/traversal_nar2152=== PAUSE TestIsValidUploadKey/traversal_nar2153=== RUN TestIsValidUploadKey/absolute2154=== PAUSE TestIsValidUploadKey/absolute2155=== RUN TestIsValidUploadKey/empty_key2156=== PAUSE TestIsValidUploadKey/empty_key2157=== RUN TestIsValidUploadKey/unknown_type2158=== PAUSE TestIsValidUploadKey/unknown_type2159=== CONT TestProxyWriteTimeout2160=== RUN TestProxyWriteTimeout/narinfo2161=== PAUSE TestProxyWriteTimeout/narinfo2162=== RUN TestProxyWriteTimeout/1_GiB_nar2163=== PAUSE TestProxyWriteTimeout/1_GiB_nar2164=== RUN TestProxyWriteTimeout/10_GiB_nar2165=== PAUSE TestProxyWriteTimeout/10_GiB_nar2166=== RUN TestProxyWriteTimeout/unknown_size2167=== PAUSE TestProxyWriteTimeout/unknown_size2168=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle21692026-10-01 09:30:41.971 UTC [36372] ERROR: relation "goose_db_version" does not exist at character 3621702026-10-01 09:30:41.971 UTC [36372] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2171=== NAME TestOrphanedObjectsGCStressTest2172 orphaned_objects_gc_test.go:509: Stress test completed successfully:2173 orphaned_objects_gc_test.go:510: - Active objects preserved: 202174 orphaned_objects_gc_test.go:511: - Objects deleted: 2102175 orphaned_objects_gc_test.go:512: - Total GC'd: 2102176--- PASS: TestOrphanedObjectsGCStressTest (11.53s)2177=== CONT TestService_RequireScope_OIDC21782026/10/01 09:30:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65020/oidc21792026-10-01 09:30:42.212 UTC [36376] ERROR: relation "goose_db_version" does not exist at character 3621802026-10-01 09:30:42.212 UTC [36376] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21812026/10/01 09:30:42 OK 20241026095416_initial_model.sql (139.37ms)21822026/10/01 09:30:42 OK 20251210153512_drop_unused_gin_index.sql (9.91ms)21832026-10-01 09:30:42.229 UTC [36378] ERROR: relation "goose_db_version" does not exist at character 3621842026-10-01 09:30:42.229 UTC [36378] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21852026/10/01 09:30:42 OK 20251218171726_add_pins.sql (6.44ms)21862026/10/01 09:30:42 OK 20260628120000_add_object_size_and_stats.sql (24.06ms)21872026/10/01 09:30:42 OK 20260905000000_add_claims.sql (22.93ms)21882026/10/01 09:30:42 OK 20260920000000_drop_claims.sql (23.03ms)21892026/10/01 09:30:42 OK 20260923120000_add_pushes.sql (6.69ms)21902026/10/01 09:30:42 goose: successfully migrated database to version: 2026092312000021912026/10/01 09:30:42 OK 1_commit_pending_closure.sql (2.03ms)21922026/10/01 09:30:42 OK 2_object_stats_trigger.sql (333.04µs)21932026/10/01 09:30:42 OK 3_commit_push.sql (321µs)21942026/10/01 09:30:42 goose: up to current file version: 321952026/10/01 09:30:42 OK 20241026095416_initial_model.sql (68.88ms)21962026/10/01 09:30:42 OK 20251210153512_drop_unused_gin_index.sql (7.8ms)21972026/10/01 09:30:42 OK 20251218171726_add_pins.sql (33.29ms)21982026/10/01 09:30:42 OK 20241026095416_initial_model.sql (102.45ms)21992026/10/01 09:30:42 OK 20251210153512_drop_unused_gin_index.sql (12.36ms)22002026/10/01 09:30:42 OK 20260628120000_add_object_size_and_stats.sql (29.14ms)22012026/10/01 09:30:42 OK 20251218171726_add_pins.sql (35.43ms)22022026/10/01 09:30:42 OK 20260628120000_add_object_size_and_stats.sql (17.51ms)22032026/10/01 09:30:42 OK 20260905000000_add_claims.sql (42.3ms)22042026/10/01 09:30:42 OK 20260905000000_add_claims.sql (15.57ms)22052026/10/01 09:30:42 OK 20260920000000_drop_claims.sql (23.04ms)22062026/10/01 09:30:42 OK 20260920000000_drop_claims.sql (14.07ms)22072026/10/01 09:30:42 OK 20260923120000_add_pushes.sql (8.33ms)22082026/10/01 09:30:42 goose: successfully migrated database to version: 2026092312000022092026/10/01 09:30:42 OK 20260923120000_add_pushes.sql (8.47ms)22102026/10/01 09:30:42 goose: successfully migrated database to version: 2026092312000022112026/10/01 09:30:42 OK 1_commit_pending_closure.sql (1.03ms)22122026/10/01 09:30:42 OK 1_commit_pending_closure.sql (1.13ms)22132026/10/01 09:30:42 OK 2_object_stats_trigger.sql (249.67µs)22142026/10/01 09:30:42 OK 2_object_stats_trigger.sql (335.88µs)22152026/10/01 09:30:42 OK 3_commit_push.sql (209.17µs)22162026/10/01 09:30:42 goose: up to current file version: 322172026/10/01 09:30:42 OK 3_commit_push.sql (250.04µs)22182026/10/01 09:30:42 goose: up to current file version: 322192026/10/01 09:30:42 INFO Received uploads request method=POST path=/api/pending_closures22202026/10/01 09:30:42 INFO Received uploads request method=POST path=/api/pending_closures22212026/10/01 09:30:42 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)22222026/10/01 09:30:42 INFO Uploading m6l5fggmnhgd94r5da4rz8kvf1xmzcak-b (248B)22232026/10/01 09:30:42 INFO Uploading chvrc9fsl5nc1bbk407gjbq03gxk2xns-shared-dep (136B)22242026/10/01 09:30:42 WARN Failed to register uploaded object key=m6l5fggmnhgd94r5da4rz8kvf1xmzcak.ls error="server returned 404: 404 page not found\n"22252026/10/01 09:30:42 WARN Failed to register uploaded object key=jdsg4rx4bb3mqj3xymdb4jqjnrzrvaf5.ls error="server returned 404: 404 page not found\n"22262026/10/01 09:30:42 WARN Failed to register uploaded object key=chvrc9fsl5nc1bbk407gjbq03gxk2xns.ls error="server returned 404: 404 page not found\n"22272026/10/01 09:30:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign22282026/10/01 09:30:42 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22292026/10/01 09:30:42 WARN Failed to register uploaded object key=nar/0sypba14r6a6mlf2z1hmzbdfgffjqs20ips37q8a4lyrm0c5i7h6.nar.zst error="server returned 404: 404 page not found\n"22302026/10/01 09:30:42 INFO Signed narinfos id=1 count=222312026/10/01 09:30:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign22322026/10/01 09:30:42 INFO Signed narinfos id=2 count=222332026/10/01 09:30:42 INFO Uploading 4 narinfos22342026/10/01 09:30:42 WARN Failed to register uploaded object key=jdsg4rx4bb3mqj3xymdb4jqjnrzrvaf5.narinfo error="server returned 404: 404 page not found\n"22352026/10/01 09:30:42 WARN Failed to register uploaded object key=chvrc9fsl5nc1bbk407gjbq03gxk2xns.narinfo error="server returned 404: 404 page not found\n"22362026/10/01 09:30:42 WARN Failed to register uploaded object key=m6l5fggmnhgd94r5da4rz8kvf1xmzcak.narinfo error="server returned 404: 404 page not found\n"22372026/10/01 09:30:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22382026/10/01 09:30:42 WARN Failed to register uploaded object key=chvrc9fsl5nc1bbk407gjbq03gxk2xns.narinfo error="server returned 404: 404 page not found\n"22392026/10/01 09:30:42 INFO Completed upload id=222402026/10/01 09:30:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22412026/10/01 09:30:42 INFO Completed upload id=122422026/10/01 09:30:42 INFO Upload complete. (165ms)2243=== NAME TestClientFallsBackToClosures2244 client_pushes_test.go:112: Retrieved narinfo from S3:2245 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestClientFallsBackToClosures226904259/001/store/chvrc9fsl5nc1bbk407gjbq03gxk2xns-shared-dep2246 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2247 Compression: zstd2248 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822249 NarSize: 1362250 References: 2251 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2252 client_pushes_test.go:112: Retrieved narinfo from S3:2253 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestClientFallsBackToClosures226904259/001/store/jdsg4rx4bb3mqj3xymdb4jqjnrzrvaf5-a2254 URL: nar/0sypba14r6a6mlf2z1hmzbdfgffjqs20ips37q8a4lyrm0c5i7h6.nar.zst2255 Compression: zstd2256 NarHash: sha256:0sypba14r6a6mlf2z1hmzbdfgffjqs20ips37q8a4lyrm0c5i7h62257 NarSize: 2482258 References: /nix/var/nix/builds/nix-36033-363360632/TestClientFallsBackToClosures226904259/001/store/chvrc9fsl5nc1bbk407gjbq03gxk2xns-shared-dep2259 CA: text:sha256:0xk63wbvkb29dmb9sla362c7g92zym5k1qdwk3lfc70r5abdli0l2260 client_pushes_test.go:112: Retrieved narinfo from S3:2261 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestClientFallsBackToClosures226904259/001/store/m6l5fggmnhgd94r5da4rz8kvf1xmzcak-b2262 URL: nar/0sypba14r6a6mlf2z1hmzbdfgffjqs20ips37q8a4lyrm0c5i7h6.nar.zst2263 Compression: zstd2264 NarHash: sha256:0sypba14r6a6mlf2z1hmzbdfgffjqs20ips37q8a4lyrm0c5i7h62265 NarSize: 2482266 References: /nix/var/nix/builds/nix-36033-363360632/TestClientFallsBackToClosures226904259/001/store/chvrc9fsl5nc1bbk407gjbq03gxk2xns-shared-dep2267 CA: text:sha256:0xk63wbvkb29dmb9sla362c7g92zym5k1qdwk3lfc70r5abdli0l22682026-10-01 09:30:42.633 UTC [36397] ERROR: relation "goose_db_version" does not exist at character 3622692026-10-01 09:30:42.633 UTC [36397] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2270--- PASS: TestClientFallsBackToClosures (2.66s)2271=== CONT TestClientErrorHandling2272=== RUN TestClientErrorHandling/InvalidStorePath2273=== PAUSE TestClientErrorHandling/InvalidStorePath2274=== RUN TestClientErrorHandling/InvalidAuthToken2275=== PAUSE TestClientErrorHandling/InvalidAuthToken2276=== RUN TestClientErrorHandling/ServerNotAvailable2277=== PAUSE TestClientErrorHandling/ServerNotAvailable2278=== CONT TestClientCADerivations22792026/10/01 09:30:42 INFO Received push request method=POST path=/api/pushes22802026/10/01 09:30:42 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)22812026/10/01 09:30:42 INFO Uploading lnrpcvzs16fylki21i0k5kzgw4nyyfwz-shared-dep (136B)22822026/10/01 09:30:42 INFO Uploading 3j9gb2b8gcmzxc88g3aw0442jqkvff45-a (248B)22832026/10/01 09:30:42 WARN Failed to register uploaded object key=nar/0c8a6fiwdx4b90qwc7dvs66rrhhi1ihlyymcqdnd158xhlrxdp0p.nar.zst error="server returned 404: 404 page not found\n"22842026/10/01 09:30:42 WARN Failed to register uploaded object key=lnrpcvzs16fylki21i0k5kzgw4nyyfwz.ls error="server returned 404: 404 page not found\n"22852026/10/01 09:30:42 WARN Failed to register uploaded object key=3j9gb2b8gcmzxc88g3aw0442jqkvff45.ls error="server returned 404: 404 page not found\n"22862026/10/01 09:30:42 WARN Failed to register uploaded object key=2yhcsjyq6mcfcqf9vfv1crjj72bakxpl.ls error="server returned 404: 404 page not found\n"22872026/10/01 09:30:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22882026/10/01 09:30:42 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22892026/10/01 09:30:42 INFO Signed narinfos id=1 count=322902026/10/01 09:30:42 INFO Uploading 3 narinfos22912026/10/01 09:30:42 WARN Failed to register uploaded object key=lnrpcvzs16fylki21i0k5kzgw4nyyfwz.narinfo error="server returned 404: 404 page not found\n"22922026/10/01 09:30:42 WARN Failed to register uploaded object key=2yhcsjyq6mcfcqf9vfv1crjj72bakxpl.narinfo error="server returned 404: 404 page not found\n"22932026/10/01 09:30:42 INFO Received complete push request method=POST path=/api/pushes/1/complete22942026/10/01 09:30:42 WARN Failed to register uploaded object key=3j9gb2b8gcmzxc88g3aw0442jqkvff45.narinfo error="server returned 404: 404 page not found\n"22952026/10/01 09:30:42 INFO Upload complete. (133ms)2296=== NAME TestClientPushesUseOnePush2297 client_pushes_test.go:97: Retrieved narinfo from S3:2298 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestClientPushesUseOnePush2183915749/001/store/lnrpcvzs16fylki21i0k5kzgw4nyyfwz-shared-dep2299 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2300 Compression: zstd2301 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822302 NarSize: 1362303 References: 2304 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2305 client_pushes_test.go:97: Retrieved narinfo from S3:2306 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestClientPushesUseOnePush2183915749/001/store/3j9gb2b8gcmzxc88g3aw0442jqkvff45-a2307 URL: nar/0c8a6fiwdx4b90qwc7dvs66rrhhi1ihlyymcqdnd158xhlrxdp0p.nar.zst2308 Compression: zstd2309 NarHash: sha256:0c8a6fiwdx4b90qwc7dvs66rrhhi1ihlyymcqdnd158xhlrxdp0p2310 NarSize: 2482311 References: /nix/var/nix/builds/nix-36033-363360632/TestClientPushesUseOnePush2183915749/001/store/lnrpcvzs16fylki21i0k5kzgw4nyyfwz-shared-dep2312 CA: text:sha256:01xg2lkrhydhb3m5ybyiddxphg7q3nr60br3d4n4yva0xsdmad192313 client_pushes_test.go:97: Retrieved narinfo from S3:2314 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestClientPushesUseOnePush2183915749/001/store/2yhcsjyq6mcfcqf9vfv1crjj72bakxpl-b2315 URL: nar/0c8a6fiwdx4b90qwc7dvs66rrhhi1ihlyymcqdnd158xhlrxdp0p.nar.zst2316 Compression: zstd2317 NarHash: sha256:0c8a6fiwdx4b90qwc7dvs66rrhhi1ihlyymcqdnd158xhlrxdp0p2318 NarSize: 2482319 References: /nix/var/nix/builds/nix-36033-363360632/TestClientPushesUseOnePush2183915749/001/store/lnrpcvzs16fylki21i0k5kzgw4nyyfwz-shared-dep2320 CA: text:sha256:01xg2lkrhydhb3m5ybyiddxphg7q3nr60br3d4n4yva0xsdmad192321=== NAME TestPinProtectsFromGC2322 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-36033-363360632/TestPinProtectsFromGC3877516726/001/store/byi0knqpm1rx6qi6q81ibpwnanszwq52-pinned-file.txt2323 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-36033-363360632/TestPinProtectsFromGC3877516726/001/store/x2c3fahph7xq0p7ij6x4pk3jmjhw099r-unpinned-file.txt2324--- PASS: TestClientPushesUseOnePush (2.60s)2325=== CONT TestCacheStatsHandler2326--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (3.13s)2327=== CONT TestCacheConfigHandler2328=== RUN TestCacheConfigHandler/full_config,_no_issuer2329=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2330=== RUN TestCacheConfigHandler/no_cache_url_configured2331=== PAUSE TestCacheConfigHandler/no_cache_url_configured2332=== RUN TestCacheConfigHandler/no_signing_keys2333=== PAUSE TestCacheConfigHandler/no_signing_keys2334=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2335=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2336=== CONT TestService_ReadScope_PublicByDefault23372026/10/01 09:30:42 OK 20241026095416_initial_model.sql (209.3ms)23382026/10/01 09:30:42 OK 20251210153512_drop_unused_gin_index.sql (24.61ms)23392026/10/01 09:30:42 INFO Received push request method=POST path=/api/pushes23402026/10/01 09:30:42 OK 20251218171726_add_pins.sql (10.41ms)23412026/10/01 09:30:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23422026/10/01 09:30:42 INFO Uploading byi0knqpm1rx6qi6q81ibpwnanszwq52-pinned-file.txt (128B)23432026/10/01 09:30:42 OK 20260628120000_add_object_size_and_stats.sql (26.39ms)23442026/10/01 09:30:42 WARN Failed to register uploaded object key=byi0knqpm1rx6qi6q81ibpwnanszwq52.ls error="server returned 404: 404 page not found\n"23452026/10/01 09:30:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23462026/10/01 09:30:42 INFO Signed narinfos id=1 count=123472026/10/01 09:30:42 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"23482026/10/01 09:30:42 INFO Uploading 1 narinfos23492026/10/01 09:30:42 INFO Received complete push request method=POST path=/api/pushes/1/complete23502026/10/01 09:30:42 WARN Failed to register uploaded object key=byi0knqpm1rx6qi6q81ibpwnanszwq52.narinfo error="server returned 404: 404 page not found\n"23512026/10/01 09:30:43 INFO Upload complete. (144ms)23522026/10/01 09:30:43 OK 20260905000000_add_claims.sql (52.7ms)23532026/10/01 09:30:43 OK 20260920000000_drop_claims.sql (33.68ms)23542026/10/01 09:30:43 OK 20260923120000_add_pushes.sql (11.24ms)23552026/10/01 09:30:43 goose: successfully migrated database to version: 2026092312000023562026/10/01 09:30:43 OK 1_commit_pending_closure.sql (1.3ms)23572026/10/01 09:30:43 OK 2_object_stats_trigger.sql (238.13µs)23582026/10/01 09:30:43 OK 3_commit_push.sql (187.04µs)23592026/10/01 09:30:43 goose: up to current file version: 323602026/10/01 09:30:43 INFO Received push request method=POST path=/api/pushes23612026/10/01 09:30:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23622026/10/01 09:30:43 INFO Uploading x2c3fahph7xq0p7ij6x4pk3jmjhw099r-unpinned-file.txt (128B)23632026/10/01 09:30:43 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"23642026/10/01 09:30:43 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign23652026/10/01 09:30:43 INFO Signed narinfos id=2 count=123662026/10/01 09:30:43 WARN Failed to register uploaded object key=x2c3fahph7xq0p7ij6x4pk3jmjhw099r.ls error="server returned 404: 404 page not found\n"23672026/10/01 09:30:43 INFO Uploading 1 narinfos23682026/10/01 09:30:43 INFO Received complete push request method=POST path=/api/pushes/2/complete23692026/10/01 09:30:43 WARN Failed to register uploaded object key=x2c3fahph7xq0p7ij6x4pk3jmjhw099r.narinfo error="server returned 404: 404 page not found\n"23702026/10/01 09:30:43 INFO Upload complete. (123ms)23712026/10/01 09:30:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures23722026/10/01 09:30:43 INFO Garbage collection started23732026/10/01 09:30:43 INFO Aborted multipart uploads count=023742026/10/01 09:30:43 WARN Force mode enabled - objects will be deleted immediately without grace period23752026/10/01 09:30:43 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=02376=== NAME TestClientWithDependencies2377 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-36033-363360632/TestClientWithDependencies23084862/001/store/56n7g8b06606mdxbryx426cmxq5i49xf-test-script23782026-10-01 09:30:43.313 UTC [36429] ERROR: relation "goose_db_version" does not exist at character 3623792026-10-01 09:30:43.313 UTC [36429] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23802026/10/01 09:30:43 INFO Vacuumed table table=pending_closures2381 client_integration_test.go:615: Found 1 dependencies (including self)23822026/10/01 09:30:43 INFO Vacuumed table table=pending_objects23832026/10/01 09:30:43 INFO Vacuumed table table=multipart_uploads23842026/10/01 09:30:43 INFO Vacuumed table table=closures23852026/10/01 09:30:43 INFO Vacuumed table table=objects23862026/10/01 09:30:43 INFO Received push request method=POST path=/api/pushes23872026/10/01 09:30:43 OK 20241026095416_initial_model.sql (80.91ms)23882026/10/01 09:30:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23892026/10/01 09:30:43 INFO Uploading 56n7g8b06606mdxbryx426cmxq5i49xf-test-script (136B)23902026/10/01 09:30:43 OK 20251210153512_drop_unused_gin_index.sql (9.7ms)23912026/10/01 09:30:43 WARN Failed to register uploaded object key=56n7g8b06606mdxbryx426cmxq5i49xf.ls error="server returned 404: 404 page not found\n"23922026/10/01 09:30:43 WARN Failed to register uploaded object key=log/zzh5rc69pfqi476hni4b9qyrdr4q0602-test-script.drv error="server returned 404: 404 page not found\n"23932026/10/01 09:30:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23942026/10/01 09:30:43 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"23952026/10/01 09:30:43 OK 20251218171726_add_pins.sql (25.23ms)23962026/10/01 09:30:43 INFO Signed narinfos id=1 count=123972026/10/01 09:30:43 INFO Uploading 1 narinfos23982026/10/01 09:30:43 INFO Received push request method=POST path=/api/pushes23992026/10/01 09:30:43 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)24002026/10/01 09:30:43 INFO Uploading kickm1chbmc3qdj9h1sdv8h6c2slw6lf-shared-dep (136B)24012026/10/01 09:30:43 INFO Uploading nyffabh9bk578zv3wkscrzg4yzcgqrn6-top (256B)24022026/10/01 09:30:43 INFO Received complete push request method=POST path=/api/pushes/1/complete24032026/10/01 09:30:43 WARN Failed to register uploaded object key=56n7g8b06606mdxbryx426cmxq5i49xf.narinfo error="server returned 404: 404 page not found\n"24042026-10-01 09:30:43.520 UTC [36445] ERROR: relation "goose_db_version" does not exist at character 3624052026-10-01 09:30:43.520 UTC [36445] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24062026/10/01 09:30:43 WARN Failed to register uploaded object key=nyffabh9bk578zv3wkscrzg4yzcgqrn6.ls error="server returned 404: 404 page not found\n"24072026/10/01 09:30:43 OK 20260628120000_add_object_size_and_stats.sql (36.8ms)2408=== NAME TestClientMultipleUploads2409 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-36033-363360632/TestClientMultipleUploads1519307228/001/store/3s5qz4r0x74irgapkk2ivr0fyy9ar838-test-file-0.txt24102026/10/01 09:30:43 WARN Failed to register uploaded object key=nar/1r1gcik9vmbxlpmcfy38pxq4innjbn8zp4x61n68b3v3qg7lf14k.nar.zst error="server returned 404: 404 page not found\n"24112026/10/01 09:30:43 WARN Failed to register uploaded object key=kickm1chbmc3qdj9h1sdv8h6c2slw6lf.ls error="server returned 404: 404 page not found\n"24122026/10/01 09:30:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24132026/10/01 09:30:43 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24142026/10/01 09:30:43 INFO Upload complete. (152ms)24152026/10/01 09:30:43 INFO Signed narinfos id=1 count=224162026/10/01 09:30:43 INFO Uploading 2 narinfos2417=== NAME TestClientWithDependencies2418 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-36033-363360632/TestClientWithDependencies23084862/001/store) requires matching store prefix24192026/10/01 09:30:43 INFO Received complete push request method=POST path=/api/pushes/1/complete24202026/10/01 09:30:43 WARN Failed to register uploaded object key=nyffabh9bk578zv3wkscrzg4yzcgqrn6.narinfo error="server returned 404: 404 page not found\n"24212026/10/01 09:30:43 WARN Failed to register uploaded object key=kickm1chbmc3qdj9h1sdv8h6c2slw6lf.narinfo error="server returned 404: 404 page not found\n"24222026/10/01 09:30:43 INFO Upload complete. (138ms)2423=== NAME TestClientSharedPathCommittedMidPush2424 client_integration_test.go:680: Retrieved narinfo from S3:2425 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestClientSharedPathCommittedMidPush264895386/001/store/kickm1chbmc3qdj9h1sdv8h6c2slw6lf-shared-dep2426 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2427 Compression: zstd2428 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822429 NarSize: 1362430 References: 2431 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2432 client_integration_test.go:680: Retrieved narinfo from S3:2433 StorePath: /nix/var/nix/builds/nix-36033-363360632/TestClientSharedPathCommittedMidPush264895386/001/store/nyffabh9bk578zv3wkscrzg4yzcgqrn6-top2434 URL: nar/1r1gcik9vmbxlpmcfy38pxq4innjbn8zp4x61n68b3v3qg7lf14k.nar.zst2435 Compression: zstd2436 NarHash: sha256:1r1gcik9vmbxlpmcfy38pxq4innjbn8zp4x61n68b3v3qg7lf14k2437 NarSize: 2562438 References: /nix/var/nix/builds/nix-36033-363360632/TestClientSharedPathCommittedMidPush264895386/001/store/kickm1chbmc3qdj9h1sdv8h6c2slw6lf-shared-dep2439 CA: text:sha256:18qff0cci175lwn4mk64pjzbknr8nwx1dz21qwiayidgp7520hnp24402026/10/01 09:30:43 OK 20260905000000_add_claims.sql (45.06ms)24412026/10/01 09:30:43 OK 20260920000000_drop_claims.sql (17.91ms)24422026/10/01 09:30:43 OK 20260923120000_add_pushes.sql (11.12ms)24432026/10/01 09:30:43 goose: successfully migrated database to version: 2026092312000024442026/10/01 09:30:43 OK 1_commit_pending_closure.sql (1.04ms)24452026/10/01 09:30:43 OK 2_object_stats_trigger.sql (218.08µs)24462026/10/01 09:30:43 OK 3_commit_push.sql (175.33µs)24472026/10/01 09:30:43 goose: up to current file version: 32448--- PASS: TestClientWithDependencies (2.56s)2449=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key24502026/10/01 09:30:43 INFO Received complete multipart upload request method=POST path=/2451=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key24522026/10/01 09:30:43 INFO Received request for more parts method=POST path=/2453=== CONT TestService_AuthMiddleware_MTLSBoundSubjects2454=== NAME TestClientMultipleUploads2455 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-36033-363360632/TestClientMultipleUploads1519307228/001/store/84bhlqcandmq3fl0zlhsdcc6hcqgnzpl-test-file-1.txt2456--- PASS: TestClientSharedPathCommittedMidPush (2.64s)2457=== CONT TestService_AuthMiddleware_OIDC24582026/10/01 09:30:43 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02459=== NAME TestClientIntegration2460 client_integration_test.go:323: Objects in database after GC:2461 client_integration_test.go:323: Successfully deleted all objects with GC --force24622026/10/01 09:30:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65099/oidc24632026/10/01 09:30:43 OK 20241026095416_initial_model.sql (109.37ms)2464--- PASS: TestClientIntegration (4.86s)2465=== CONT TestService_ReadAuthMiddleware24662026/10/01 09:30:43 OK 20251210153512_drop_unused_gin_index.sql (5.4ms)24672026/10/01 09:30:43 OK 20251218171726_add_pins.sql (2.98ms)2468=== NAME TestClientMultipleUploads2469 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-36033-363360632/TestClientMultipleUploads1519307228/001/store/ghddi2dfh1vfrq4ci9m0zyz9rn789mk4-test-file-2.txt24702026/10/01 09:30:43 OK 20260628120000_add_object_size_and_stats.sql (20.44ms)24712026/10/01 09:30:43 OK 20260905000000_add_claims.sql (49.97ms)24722026/10/01 09:30:43 INFO Received uploads request method=POST path=/api/pending_closures24732026/10/01 09:30:43 INFO Received push request method=POST path=/api/pushes24742026/10/01 09:30:43 OK 20260920000000_drop_claims.sql (37.32ms)24752026/10/01 09:30:43 OK 20260923120000_add_pushes.sql (9.4ms)24762026/10/01 09:30:43 goose: successfully migrated database to version: 2026092312000024772026/10/01 09:30:43 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)24782026/10/01 09:30:43 INFO Uploading 84bhlqcandmq3fl0zlhsdcc6hcqgnzpl-test-file-1.txt (160B)24792026/10/01 09:30:43 INFO Uploading 3s5qz4r0x74irgapkk2ivr0fyy9ar838-test-file-0.txt (160B)24802026/10/01 09:30:43 INFO Uploading ghddi2dfh1vfrq4ci9m0zyz9rn789mk4-test-file-2.txt (160B)24812026/10/01 09:30:43 OK 1_commit_pending_closure.sql (1.16ms)24822026/10/01 09:30:43 OK 2_object_stats_trigger.sql (399.63µs)24832026/10/01 09:30:43 OK 3_commit_push.sql (489.42µs)24842026/10/01 09:30:43 goose: up to current file version: 324852026/10/01 09:30:43 WARN Failed to register uploaded object key=ghddi2dfh1vfrq4ci9m0zyz9rn789mk4.ls error="server returned 404: 404 page not found\n"24862026/10/01 09:30:43 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"24872026/10/01 09:30:43 WARN Failed to register uploaded object key=84bhlqcandmq3fl0zlhsdcc6hcqgnzpl.ls error="server returned 404: 404 page not found\n"24882026/10/01 09:30:43 WARN Failed to register uploaded object key=3s5qz4r0x74irgapkk2ivr0fyy9ar838.ls error="server returned 404: 404 page not found\n"24892026/10/01 09:30:43 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"24902026/10/01 09:30:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24912026/10/01 09:30:43 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"24922026/10/01 09:30:43 INFO Signed narinfos id=1 count=324932026/10/01 09:30:43 INFO Uploading 3 narinfos24942026/10/01 09:30:43 WARN Failed to register uploaded object key=84bhlqcandmq3fl0zlhsdcc6hcqgnzpl.narinfo error="server returned 404: 404 page not found\n"24952026/10/01 09:30:43 WARN Failed to register uploaded object key=3s5qz4r0x74irgapkk2ivr0fyy9ar838.narinfo error="server returned 404: 404 page not found\n"24962026/10/01 09:30:43 INFO Received complete push request method=POST path=/api/pushes/1/complete24972026/10/01 09:30:43 WARN Failed to register uploaded object key=ghddi2dfh1vfrq4ci9m0zyz9rn789mk4.narinfo error="server returned 404: 404 page not found\n"24982026/10/01 09:30:43 INFO Upload complete. (229ms)2499 client_integration_test.go:369: Uploaded 3 paths in 264.603083ms2500--- PASS: TestClientMultipleUploads (2.64s)2501=== CONT TestService_AuthMiddleware_MTLSProxyHeader2502=== RUN TestService_RequireScope_OIDC/builder_may_write2503=== PAUSE TestService_RequireScope_OIDC/builder_may_write2504=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2505=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2506=== RUN TestService_RequireScope_OIDC/ops_may_admin2507=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2508=== RUN TestService_RequireScope_OIDC/ops_may_not_write2509=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2510=== RUN TestService_RequireScope_OIDC/reader_may_not_write2511=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2512=== RUN TestService_RequireScope_OIDC/static_token_may_admin2513=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2514=== RUN TestService_RequireScope_OIDC/static_token_may_write2515=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2516=== RUN TestService_RequireScope_OIDC/reader_may_read2517=== PAUSE TestService_RequireScope_OIDC/reader_may_read2518=== RUN TestService_RequireScope_OIDC/writer_implies_read2519=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2520=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2521=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2522=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal25232026/10/01 09:30:44 INFO Received uploads request method=POST path=/2524--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2525 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.01s)2526 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2527 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2528 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2529=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure25302026/10/01 09:30:44 INFO Received uploads request method=POST path=/25312026/10/01 09:30:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete25322026-10-01 09:30:44.209 UTC [36462] ERROR: relation "goose_db_version" does not exist at character 3625332026-10-01 09:30:44.209 UTC [36462] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25342026-10-01 09:30:44.247 UTC [36463] ERROR: relation "goose_db_version" does not exist at character 3625352026-10-01 09:30:44.247 UTC [36463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25362026-10-01 09:30:44.262 UTC [36464] ERROR: relation "goose_db_version" does not exist at character 3625372026-10-01 09:30:44.262 UTC [36464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25382026/10/01 09:30:44 OK 20241026095416_initial_model.sql (51.67ms)25392026/10/01 09:30:44 OK 20251210153512_drop_unused_gin_index.sql (774.38µs)25402026/10/01 09:30:44 OK 20251218171726_add_pins.sql (11.96ms)25412026/10/01 09:30:44 OK 20260628120000_add_object_size_and_stats.sql (2.35ms)25422026/10/01 09:30:44 OK 20241026095416_initial_model.sql (23.06ms)25432026/10/01 09:30:44 OK 20251210153512_drop_unused_gin_index.sql (667.58µs)25442026/10/01 09:30:44 OK 20260905000000_add_claims.sql (2.16ms)25452026/10/01 09:30:44 OK 20251218171726_add_pins.sql (1.42ms)25462026/10/01 09:30:44 OK 20241026095416_initial_model.sql (18.01ms)25472026/10/01 09:30:44 OK 20260920000000_drop_claims.sql (737.71µs)25482026/10/01 09:30:44 OK 20251210153512_drop_unused_gin_index.sql (309.33µs)25492026/10/01 09:30:44 OK 20260923120000_add_pushes.sql (404.25µs)25502026/10/01 09:30:44 goose: successfully migrated database to version: 2026092312000025512026/10/01 09:30:44 OK 20251218171726_add_pins.sql (697.83µs)25522026/10/01 09:30:44 OK 1_commit_pending_closure.sql (945.58µs)25532026/10/01 09:30:44 OK 2_object_stats_trigger.sql (250.54µs)25542026/10/01 09:30:44 OK 3_commit_push.sql (153.96µs)25552026/10/01 09:30:44 goose: up to current file version: 325562026/10/01 09:30:44 OK 20260628120000_add_object_size_and_stats.sql (13.69ms)25572026/10/01 09:30:44 OK 20260628120000_add_object_size_and_stats.sql (12.65ms)25582026/10/01 09:30:44 OK 20260905000000_add_claims.sql (36.52ms)25592026/10/01 09:30:44 OK 20260905000000_add_claims.sql (42.29ms)25602026/10/01 09:30:44 OK 20260920000000_drop_claims.sql (16.93ms)25612026/10/01 09:30:44 OK 20260920000000_drop_claims.sql (10.69ms)2562=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts25632026/10/01 09:30:44 INFO Received request for more parts method=POST path=/25642026/10/01 09:30:44 OK 20260923120000_add_pushes.sql (12.83ms)25652026/10/01 09:30:44 goose: successfully migrated database to version: 2026092312000025662026/10/01 09:30:44 OK 20260923120000_add_pushes.sql (12.9ms)25672026/10/01 09:30:44 goose: successfully migrated database to version: 2026092312000025682026/10/01 09:30:44 OK 1_commit_pending_closure.sql (1.23ms)25692026/10/01 09:30:44 OK 1_commit_pending_closure.sql (1.25ms)25702026/10/01 09:30:44 OK 2_object_stats_trigger.sql (272.96µs)25712026/10/01 09:30:44 OK 2_object_stats_trigger.sql (228.38µs)25722026/10/01 09:30:44 OK 3_commit_push.sql (172.29µs)25732026/10/01 09:30:44 goose: up to current file version: 325742026/10/01 09:30:44 OK 3_commit_push.sql (163.38µs)25752026/10/01 09:30:44 goose: up to current file version: 32576=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart25772026/10/01 09:30:44 INFO Received complete multipart upload request method=POST path=/2578--- PASS: TestUploadHandlersRejectOversizedBody (0.06s)2579 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)2580 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2581 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2582=== CONT TestPush_RejectsBadRequests/no_roots25832026/10/01 09:30:44 INFO Received push request method=POST path=/api/pushes2584=== CONT TestPush_RejectsBadRequests/bad_root25852026/10/01 09:30:44 INFO Received push request method=POST path=/api/pushes2586=== CONT TestPush_RejectsBadRequests/root_not_in_objects25872026/10/01 09:30:44 INFO Received push request method=POST path=/api/pushes2588=== CONT TestPush_RejectsBadRequests/no_objects25892026/10/01 09:30:44 INFO Received push request method=POST path=/api/pushes2590=== CONT TestIsValidCachePath/narinfo2591=== CONT TestIsValidCachePath/index.html2592=== CONT TestIsValidCachePath/nix-cache-info2593=== CONT TestIsValidCachePath/realisation2594--- PASS: TestPush_RejectsBadRequests (1.94s)2595 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2596 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2597 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2598 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2599=== CONT TestIsValidCachePath/log2600=== CONT TestIsValidCachePath/ls2601=== CONT TestIsValidCachePath/nar_uncompressed2602=== CONT TestIsValidCachePath/nar_bz22603=== CONT TestIsValidCachePath/nar_xz2604=== CONT TestIsValidCachePath/nar_zst2605=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2606=== CONT TestIsValidCachePath/empty2607=== CONT TestIsValidCachePath/invalid_char_u2608=== CONT TestIsValidCachePath/random_path2609=== CONT TestIsValidCachePath/wrong_extension2610=== CONT TestIsValidCachePath/short_hash2611=== CONT TestIsValidCachePath/leading_slash2612=== CONT TestIsValidCachePath/invalid_char_e2613=== CONT TestIsValidCachePath/traversal_in_middle2614=== CONT TestIsValidCachePath/traversal_parent2615--- PASS: TestIsValidCachePath (0.00s)2616 --- PASS: TestIsValidCachePath/narinfo (0.00s)2617 --- PASS: TestIsValidCachePath/index.html (0.00s)2618 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2619 --- PASS: TestIsValidCachePath/realisation (0.00s)2620 --- PASS: TestIsValidCachePath/log (0.00s)2621 --- PASS: TestIsValidCachePath/ls (0.00s)2622 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2623 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2624 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2625 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2626 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2627 --- PASS: TestIsValidCachePath/empty (0.00s)2628 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2629 --- PASS: TestIsValidCachePath/random_path (0.00s)2630 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2631 --- PASS: TestIsValidCachePath/short_hash (0.00s)2632 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2633 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2634 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2635 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2636=== CONT TestParseSingleRange/none2637=== CONT TestParseSingleRange/open-ended2638=== CONT TestParseSingleRange/start_far_past_EOF2639=== CONT TestParseSingleRange/start_past_EOF2640=== CONT TestParseSingleRange/single_byte2641=== CONT TestParseSingleRange/suffix_exceeds_size2642=== CONT TestParseSingleRange/suffix2643=== CONT TestParseSingleRange/end_clamped_to_size2644=== CONT TestParseSingleRange/malformed_both_empty2645=== CONT TestParseSingleRange/closed2646=== CONT TestParseSingleRange/malformed_end_before_start2647=== CONT TestParseSingleRange/multi-range_ignored2648=== CONT TestParseSingleRange/malformed_no_dash2649=== CONT TestParseSingleRange/unknown_unit2650--- PASS: TestParseSingleRange (0.00s)2651 --- PASS: TestParseSingleRange/none (0.00s)2652 --- PASS: TestParseSingleRange/open-ended (0.00s)2653 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2654 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2655 --- PASS: TestParseSingleRange/single_byte (0.00s)2656 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2657 --- PASS: TestParseSingleRange/suffix (0.00s)2658 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2659 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2660 --- PASS: TestParseSingleRange/closed (0.00s)2661 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2662 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2663 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2664 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2665=== CONT TestServerTLSConfig/no_client_CA2666=== CONT TestServerTLSConfig/not_a_PEM_file2667=== CONT TestServerTLSConfig/missing_CA_file2668--- PASS: TestServerTLSConfig (0.00s)2669 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2670 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)2671 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2672=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2673--- PASS: TestCacheStatsHandler (1.93s)2674=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2675=== NAME TestClientCADerivations2676 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-36033-363360632/TestClientCADerivations1359657377/001/store/1pmcx7m4hp4x198x7wgaacf38a5fi5s1-ca-test2677--- PASS: TestService_ReadScope_PublicByDefault (2.07s)2678=== CONT TestResolveDBConnectionString/flag_wins2679=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2680=== CONT TestResolveDBConnectionString/nothing_configured2681=== CONT TestResolveDBConnectionString/missing_file_is_an_error2682=== CONT TestResolveDBConnectionString/file_when_flag_empty2683=== CONT TestIsValidUploadKey/narinfo2684=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2685=== CONT TestIsValidUploadKey/index.html2686=== CONT TestIsValidUploadKey/nix-cache-info2687=== CONT TestIsValidUploadKey/realisation_plus_in_output2688=== CONT TestIsValidUploadKey/realisation2689=== CONT TestIsValidUploadKey/build_log_equals2690=== CONT TestIsValidUploadKey/build_log_question_mark2691=== CONT TestIsValidUploadKey/build_log_plus_in_name2692=== CONT TestIsValidUploadKey/build_log_home-manager_file2693=== CONT TestIsValidUploadKey/build_log2694=== CONT TestIsValidUploadKey/listing2695=== CONT TestIsValidUploadKey/nar_plain2696=== CONT TestIsValidUploadKey/nar_xz2697=== CONT TestIsValidUploadKey/nar_zst2698=== CONT TestIsValidUploadKey/absolute2699=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2700=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2701=== CONT TestIsValidUploadKey/traversal2702=== CONT TestIsValidUploadKey/traversal_nar2703=== CONT TestIsValidUploadKey/unknown_type2704=== CONT TestIsValidUploadKey/empty_key2705=== CONT TestProxyWriteTimeout/narinfo2706=== CONT TestProxyWriteTimeout/10_GiB_nar2707--- PASS: TestIsValidUploadKey (0.00s)2708 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2709 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2710 --- PASS: TestIsValidUploadKey/index.html (0.00s)2711 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2712 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2713 --- PASS: TestIsValidUploadKey/realisation (0.00s)2714 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2715 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2716 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2717 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2718 --- PASS: TestIsValidUploadKey/build_log (0.00s)2719 --- PASS: TestIsValidUploadKey/listing (0.00s)2720 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2721 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2722 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2723 --- PASS: TestIsValidUploadKey/absolute (0.00s)2724 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2725 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2726 --- PASS: TestIsValidUploadKey/traversal (0.00s)2727 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2728 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2729 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2730=== CONT TestProxyWriteTimeout/unknown_size2731=== CONT TestProxyWriteTimeout/1_GiB_nar2732--- PASS: TestProxyWriteTimeout (0.00s)2733 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2734 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2735 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2736 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2737=== CONT TestClientErrorHandling/InvalidStorePath2738--- PASS: TestResolveDBConnectionString (0.03s)2739 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2740 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2741 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2742 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2743 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2744=== NAME TestClientCADerivations2745 client_ca_test.go:139: Found 1 dependencies (including self)27462026-10-01 09:30:45.026 UTC [36475] ERROR: relation "goose_db_version" does not exist at character 3627472026-10-01 09:30:45.026 UTC [36475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27482026-10-01 09:30:45.074 UTC [36482] ERROR: relation "goose_db_version" does not exist at character 3627492026-10-01 09:30:45.074 UTC [36482] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27502026-10-01 09:30:45.091 UTC [36483] ERROR: relation "goose_db_version" does not exist at character 3627512026-10-01 09:30:45.091 UTC [36483] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27522026/10/01 09:30:45 OK 20241026095416_initial_model.sql (38.31ms)27532026/10/01 09:30:45 OK 20251210153512_drop_unused_gin_index.sql (490.96µs)27542026-10-01 09:30:45.098 UTC [36486] ERROR: relation "goose_db_version" does not exist at character 3627552026-10-01 09:30:45.098 UTC [36486] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27562026/10/01 09:30:45 OK 20251218171726_add_pins.sql (4.11ms)27572026/10/01 09:30:45 OK 20260628120000_add_object_size_and_stats.sql (23.68ms)27582026/10/01 09:30:45 INFO Received push request method=POST path=/api/pushes27592026/10/01 09:30:45 OK 20260905000000_add_claims.sql (22.43ms)27602026/10/01 09:30:45 OK 20260920000000_drop_claims.sql (18.47ms)27612026/10/01 09:30:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27622026/10/01 09:30:45 INFO Uploading 1pmcx7m4hp4x198x7wgaacf38a5fi5s1-ca-test (144B)27632026/10/01 09:30:45 OK 20241026095416_initial_model.sql (75.84ms)27642026/10/01 09:30:45 OK 20260923120000_add_pushes.sql (5.72ms)27652026/10/01 09:30:45 goose: successfully migrated database to version: 2026092312000027662026/10/01 09:30:45 WARN Failed to register uploaded object key=1pmcx7m4hp4x198x7wgaacf38a5fi5s1.ls error="server returned 404: 404 page not found\n"27672026/10/01 09:30:45 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"27682026/10/01 09:30:45 OK 1_commit_pending_closure.sql (1.16ms)27692026/10/01 09:30:45 OK 20251210153512_drop_unused_gin_index.sql (1.66ms)27702026/10/01 09:30:45 OK 2_object_stats_trigger.sql (451.67µs)27712026/10/01 09:30:45 OK 3_commit_push.sql (230.54µs)27722026/10/01 09:30:45 goose: up to current file version: 327732026/10/01 09:30:45 OK 20241026095416_initial_model.sql (94.81ms)27742026/10/01 09:30:45 WARN Failed to register uploaded object key=log/3fv37nv46lqclly3bg15dfshky5v9y3f-ca-test.drv error="server returned 404: 404 page not found\n"27752026/10/01 09:30:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27762026/10/01 09:30:45 INFO Signed narinfos id=1 count=127772026/10/01 09:30:45 INFO Uploading 1 narinfos27782026/10/01 09:30:45 OK 20251210153512_drop_unused_gin_index.sql (14.5ms)27792026/10/01 09:30:45 OK 20251218171726_add_pins.sql (48.6ms)27802026/10/01 09:30:45 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=027812026/10/01 09:30:45 INFO Received create pin request method=POST path=/api/pins/myapp27822026/10/01 09:30:45 INFO Received complete push request method=POST path=/api/pushes/1/complete27832026/10/01 09:30:45 WARN Failed to register uploaded object key=1pmcx7m4hp4x198x7wgaacf38a5fi5s1.narinfo error="server returned 404: 404 page not found\n"27842026/10/01 09:30:45 OK 20251218171726_add_pins.sql (31.28ms)27852026/10/01 09:30:45 OK 20260628120000_add_object_size_and_stats.sql (28.9ms)27862026/10/01 09:30:45 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-36033-363360632/TestPinProtectsFromGC3877516726/001/store/byi0knqpm1rx6qi6q81ibpwnanszwq52-pinned-file.txt narinfo_key=byi0knqpm1rx6qi6q81ibpwnanszwq52.narinfo27872026/10/01 09:30:45 INFO Starting cleanup of old closures method=DELETE path=/api/closures27882026/10/01 09:30:45 INFO Garbage collection started27892026/10/01 09:30:45 INFO Upload complete. (216ms)27902026/10/01 09:30:45 INFO Aborted multipart uploads count=02791 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-36033-363360632/TestClientCADerivations1359657377/001/store/1pmcx7m4hp4x198x7wgaacf38a5fi5s1-ca-test2792 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2793 Compression: zstd2794 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2795 NarSize: 1442796 References: 2797 Deriver: /nix/var/nix/builds/nix-36033-363360632/TestClientCADerivations1359657377/001/store/3fv37nv46lqclly3bg15dfshky5v9y3f-ca-test.drv2798 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2799 client_ca_test.go:185: Checking for realisation files in S3...2800 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2801 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache28022026/10/01 09:30:45 WARN Force mode enabled - objects will be deleted immediately without grace period28032026/10/01 09:30: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=028042026/10/01 09:30:45 INFO Vacuumed table table=pending_closures28052026/10/01 09:30:45 INFO Vacuumed table table=pending_objects28062026/10/01 09:30:45 INFO Vacuumed table table=multipart_uploads28072026/10/01 09:30:45 INFO Vacuumed table table=closures28082026/10/01 09:30:45 INFO Vacuumed table table=objects28092026/10/01 09:30:45 OK 20260628120000_add_object_size_and_stats.sql (41.5ms)28102026/10/01 09:30:45 OK 20241026095416_initial_model.sql (144.15ms)28112026/10/01 09:30:45 OK 20251210153512_drop_unused_gin_index.sql (7.64ms)28122026/10/01 09:30:45 OK 20260905000000_add_claims.sql (50.97ms)28132026/10/01 09:30:45 OK 20251218171726_add_pins.sql (40.04ms)28142026/10/01 09:30:45 OK 20260905000000_add_claims.sql (69ms)28152026/10/01 09:30:45 OK 20260920000000_drop_claims.sql (54.79ms)28162026/10/01 09:30:45 OK 20260920000000_drop_claims.sql (16.61ms)28172026/10/01 09:30:45 OK 20260923120000_add_pushes.sql (12.82ms)28182026/10/01 09:30:45 goose: successfully migrated database to version: 2026092312000028192026/10/01 09:30:45 OK 1_commit_pending_closure.sql (1.49ms)28202026/10/01 09:30:45 OK 2_object_stats_trigger.sql (252.54µs)28212026/10/01 09:30:45 OK 3_commit_push.sql (221µs)28222026/10/01 09:30:45 goose: up to current file version: 328232026/10/01 09:30:45 OK 20260628120000_add_object_size_and_stats.sql (45.39ms)28242026/10/01 09:30:45 OK 20260923120000_add_pushes.sql (8.21ms)28252026/10/01 09:30:45 goose: successfully migrated database to version: 2026092312000028262026/10/01 09:30:45 OK 1_commit_pending_closure.sql (1.35ms)28272026/10/01 09:30:45 OK 2_object_stats_trigger.sql (223.58µs)28282026/10/01 09:30:45 OK 3_commit_push.sql (189.83µs)28292026/10/01 09:30:45 goose: up to current file version: 32830 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket72?endpoint=http://localhost:64801®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-36033-363360632/TestClientCADerivations1359657377/001/store'2831 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 128322026/10/01 09:30:45 OK 20260905000000_add_claims.sql (26.24ms)28332026/10/01 09:30:45 OK 20260920000000_drop_claims.sql (33.23ms)28342026/10/01 09:30:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"28352026/10/01 09:30:45 WARN mTLS auth: bound subjects configured but subject DN unavailable28362026/10/01 09:30:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2837--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.83s)2838=== CONT TestClientErrorHandling/ServerNotAvailable28392026/10/01 09:30:45 OK 20260923120000_add_pushes.sql (11.74ms)28402026/10/01 09:30:45 goose: successfully migrated database to version: 2026092312000028412026/10/01 09:30:45 OK 1_commit_pending_closure.sql (1.33ms)28422026/10/01 09:30:45 OK 2_object_stats_trigger.sql (323.88µs)28432026/10/01 09:30:45 OK 3_commit_push.sql (236.63µs)28442026/10/01 09:30:45 goose: up to current file version: 32845--- PASS: TestClientCADerivations (2.81s)2846=== CONT TestClientErrorHandling/InvalidAuthToken28472026/10/01 09:30:45 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/present2848--- PASS: TestService_ReadAuthMiddleware (1.99s)2849=== CONT TestCacheConfigHandler/full_config,_no_issuer2850=== CONT TestCacheConfigHandler/no_signing_keys2851=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2852=== CONT TestCacheConfigHandler/no_cache_url_configured2853--- PASS: TestCacheConfigHandler (0.00s)2854 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2855 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2856 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2857 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2858=== CONT TestService_RequireScope_OIDC/builder_may_write2859=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2860=== CONT TestService_RequireScope_OIDC/writer_implies_read2861=== CONT TestService_RequireScope_OIDC/reader_may_read2862=== CONT TestService_RequireScope_OIDC/static_token_may_write2863=== CONT TestService_RequireScope_OIDC/static_token_may_admin2864=== CONT TestService_RequireScope_OIDC/reader_may_not_write2865=== CONT TestService_RequireScope_OIDC/ops_may_not_write2866=== CONT TestService_RequireScope_OIDC/ops_may_admin2867=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2868--- PASS: TestService_RequireScope_OIDC (2.02s)2869 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2870 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2871 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2872 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2873 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2874 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2875 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2876 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2877 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2878 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)28792026/10/01 09:30:45 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=184.145311ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28802026-10-01 09:30:45.842 UTC [36496] ERROR: relation "goose_db_version" does not exist at character 3628812026-10-01 09:30:45.842 UTC [36496] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2882=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2883=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2884=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2885=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2886=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2887=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2888=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2889=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2890=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2891=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected28922026/10/01 09:30:45 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]2893=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2894=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected28952026/10/01 09:30:45 WARN Authentication failed token_preview=eyJhbGciOi...oR39pjjsMA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2896--- PASS: TestService_AuthMiddleware_OIDC (2.29s)2897 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2898 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2899 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2900 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)29012026/10/01 09:30:45 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=411.852161ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29022026/10/01 09:30:46 OK 20241026095416_initial_model.sql (192.17ms)29032026/10/01 09:30:46 OK 20251210153512_drop_unused_gin_index.sql (11.16ms)29042026/10/01 09:30:46 OK 20251218171726_add_pins.sql (19.17ms)29052026/10/01 09:30:46 OK 20260628120000_add_object_size_and_stats.sql (33.9ms)29062026/10/01 09:30:46 OK 20260905000000_add_claims.sql (45.14ms)2907--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.13s)29082026/10/01 09:30:46 OK 20260920000000_drop_claims.sql (22.3ms)29092026/10/01 09:30:46 OK 20260923120000_add_pushes.sql (12.68ms)29102026/10/01 09:30:46 goose: successfully migrated database to version: 2026092312000029112026/10/01 09:30:46 OK 1_commit_pending_closure.sql (4.82ms)29122026/10/01 09:30:46 OK 2_object_stats_trigger.sql (1.12ms)29132026/10/01 09:30:46 OK 3_commit_push.sql (640.38µs)29142026/10/01 09:30:46 goose: up to current file version: 329152026-10-01 09:30:46.265 UTC [36497] ERROR: relation "goose_db_version" does not exist at character 3629162026-10-01 09:30:46.265 UTC [36497] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29172026/10/01 09:30:46 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=879.958331ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29182026-10-01 09:30:46.420 UTC [36498] ERROR: relation "goose_db_version" does not exist at character 3629192026-10-01 09:30:46.420 UTC [36498] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29202026/10/01 09:30:46 OK 20241026095416_initial_model.sql (157.19ms)29212026/10/01 09:30:46 OK 20251210153512_drop_unused_gin_index.sql (12.14ms)29222026/10/01 09:30:46 INFO Received uploads request method=POST path=/api/pending_closures29232026/10/01 09:30:46 OK 20251218171726_add_pins.sql (27.96ms)29242026/10/01 09:30:46 INFO Aborted multipart uploads count=029252026/10/01 09:30:46 WARN Force mode enabled - objects will be deleted immediately without grace period29262026/10/01 09:30:46 OK 20260628120000_add_object_size_and_stats.sql (32.48ms)29272026/10/01 09:30:46 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=029282026/10/01 09:30:46 INFO Vacuumed table table=pending_closures29292026/10/01 09:30:46 INFO Vacuumed table table=pending_objects29302026/10/01 09:30:46 INFO Vacuumed table table=multipart_uploads29312026/10/01 09:30:46 INFO Vacuumed table table=closures29322026/10/01 09:30:46 INFO Vacuumed table table=objects29332026/10/01 09:30:46 OK 20260905000000_add_claims.sql (40.49ms)29342026/10/01 09:30:46 OK 20260920000000_drop_claims.sql (31.8ms)29352026/10/01 09:30:46 OK 20260923120000_add_pushes.sql (11.38ms)29362026/10/01 09:30:46 goose: successfully migrated database to version: 2026092312000029372026/10/01 09:30:46 OK 1_commit_pending_closure.sql (4.53ms)29382026/10/01 09:30:46 OK 2_object_stats_trigger.sql (754.25µs)29392026/10/01 09:30:46 OK 3_commit_push.sql (571.21µs)29402026/10/01 09:30:46 goose: up to current file version: 329412026/10/01 09:30:46 OK 20241026095416_initial_model.sql (141.81ms)29422026/10/01 09:30:46 OK 20251210153512_drop_unused_gin_index.sql (11.23ms)29432026/10/01 09:30:46 OK 20251218171726_add_pins.sql (27.62ms)29442026/10/01 09:30:46 OK 20260628120000_add_object_size_and_stats.sql (22.35ms)29452026/10/01 09:30:46 OK 20260905000000_add_claims.sql (55.72ms)29462026/10/01 09:30:46 OK 20260920000000_drop_claims.sql (32.67ms)29472026/10/01 09:30:46 OK 20260923120000_add_pushes.sql (13.58ms)29482026/10/01 09:30:46 goose: successfully migrated database to version: 2026092312000029492026/10/01 09:30:46 OK 1_commit_pending_closure.sql (4.66ms)29502026/10/01 09:30:46 OK 2_object_stats_trigger.sql (952.79µs)29512026/10/01 09:30:46 OK 3_commit_push.sql (700.38µs)29522026/10/01 09:30:46 goose: up to current file version: 329532026/10/01 09:30:46 INFO Received uploads request method=POST path=/api/pending_closures29542026/10/01 09:30:46 INFO Aborted multipart uploads count=029552026/10/01 09:30:46 WARN Force mode enabled - objects will be deleted immediately without grace period29562026/10/01 09:30:46 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=029572026/10/01 09:30:46 INFO Vacuumed table table=pending_closures29582026/10/01 09:30:46 INFO Vacuumed table table=pending_objects29592026/10/01 09:30:46 INFO Vacuumed table table=multipart_uploads29602026/10/01 09:30:46 INFO Vacuumed table table=closures29612026/10/01 09:30:46 INFO Vacuumed table table=objects2962--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2963 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (2.20s)2964 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (2.25s)29652026-10-01 09:30:47.111 UTC [36501] ERROR: relation "goose_db_version" does not exist at character 3629662026-10-01 09:30:47.111 UTC [36501] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29672026/10/01 09:30:47 OK 20241026095416_initial_model.sql (60.09ms)29682026/10/01 09:30:47 OK 20251210153512_drop_unused_gin_index.sql (5.62ms)29692026/10/01 09:30:47 OK 20251218171726_add_pins.sql (1.01ms)29702026/10/01 09:30:47 OK 20260628120000_add_object_size_and_stats.sql (1.07ms)29712026/10/01 09:30:47 OK 20260905000000_add_claims.sql (1.29ms)29722026/10/01 09:30:47 OK 20260920000000_drop_claims.sql (6.2ms)29732026/10/01 09:30:47 OK 20260923120000_add_pushes.sql (4.69ms)29742026/10/01 09:30:47 goose: successfully migrated database to version: 2026092312000029752026/10/01 09:30:47 OK 1_commit_pending_closure.sql (1.16ms)29762026/10/01 09:30:47 OK 2_object_stats_trigger.sql (271.83µs)29772026/10/01 09:30:47 OK 3_commit_push.sql (221.71µs)29782026/10/01 09:30:47 goose: up to current file version: 329792026/10/01 09:30:47 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.746162338s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2980=== NAME TestPinProtectsFromGC2981 client_integration_test.go:840: Pin successfully protected closure from garbage collection2982--- PASS: TestPinProtectsFromGC (6.71s)29832026/10/01 09:30:47 WARN Rate limiter enabled after throttle name=s3-test rate=529842026/10/01 09:30:47 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2985=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2986 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102987 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002988--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.63s)29892026/10/01 09:30:47 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29902026/10/01 09:30:47 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29912026/10/01 09:30:49 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-config29922026/10/01 09:30:49 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=187.793533ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29932026/10/01 09:30:49 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=391.65708ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29942026/10/01 09:30:49 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=745.483168ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29952026/10/01 09:30:50 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.456578569s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29962026/10/01 09:30:51 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"29972026/10/01 09:30:51 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-config29982026/10/01 09:30:52 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=197.958728ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29992026/10/01 09:30:52 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=373.456638ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30002026/10/01 09:30:52 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=754.050265ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30012026/10/01 09:30:53 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.747448451s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30022026/10/01 09:30:55 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_closures30032026/10/01 09:30:55 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=201.999194ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30042026/10/01 09:30:55 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=432.398279ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30052026/10/01 09:30:55 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=727.971301ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30062026/10/01 09:30:56 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.489874978s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3007--- PASS: TestClientErrorHandling (0.00s)3008 --- PASS: TestClientErrorHandling/InvalidStorePath (2.23s)3009 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.13s)3010 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.69s)3011PASS3012{"timestamp":"2026-10-01T09:30:58.133961Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:64851","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(10)"}30132026-10-01 09:30:58.333 UTC [36077] LOG: received smart shutdown request30142026-10-01 09:30:58.334 UTC [36077] LOG: background worker "logical replication launcher" (PID 36087) exited with exit code 130152026-10-01 09:30:58.341 UTC [36082] LOG: shutting down30162026-10-01 09:30:58.341 UTC [36082] LOG: checkpoint starting: shutdown immediate30172026-10-01 09:30:59.564 UTC [36082] LOG: checkpoint complete: wrote 12964 buffers (79.1%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 24 recycled; write=0.714 s, sync=0.470 s, total=1.224 s; sync files=27639, longest=0.001 s, average=0.001 s; distance=389278 kB, estimate=389278 kB; lsn=0/193B4968, redo lsn=0/193B496830182026-10-01 09:30:59.570 UTC [36077] LOG: database system is shut down3019Running OIDC tests...3020=== RUN TestAudienceForIssuer3021=== PAUSE TestAudienceForIssuer3022=== RUN TestGlobMatch3023=== PAUSE TestGlobMatch3024=== RUN TestValidateToken_ValidToken3025=== PAUSE TestValidateToken_ValidToken3026=== RUN TestValidateToken_WrongAudience3027=== PAUSE TestValidateToken_WrongAudience3028=== RUN TestValidateToken_Expired3029=== PAUSE TestValidateToken_Expired3030=== RUN TestValidateToken_BoundClaimsMismatch3031=== PAUSE TestValidateToken_BoundClaimsMismatch3032=== RUN TestValidateToken_BoundSubjectMismatch3033=== PAUSE TestValidateToken_BoundSubjectMismatch3034=== RUN TestValidateToken_MultipleProviders3035=== PAUSE TestValidateToken_MultipleProviders3036=== RUN TestValidateToken_NoMatchingProvider3037=== PAUSE TestValidateToken_NoMatchingProvider3038=== RUN TestValidateToken_KubernetesServiceAccount3039=== PAUSE TestValidateToken_KubernetesServiceAccount3040=== RUN TestNewValidator_KubernetesRequiresCA3041=== PAUSE TestNewValidator_KubernetesRequiresCA3042=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3043=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3044=== RUN TestPins_ReservedForMatchingRule3045=== PAUSE TestPins_ReservedForMatchingRule3046=== RUN TestPins_TopLevelShorthand3047=== PAUSE TestPins_TopLevelShorthand3048=== RUN TestPins_ConfigValidation3049=== PAUSE TestPins_ConfigValidation3050=== RUN TestScopes_LegacyProviderDefaultsToWrite3051=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3052=== RUN TestScopes_Rules3053=== PAUSE TestScopes_Rules3054=== RUN TestScopes_ConfigValidation3055=== PAUSE TestScopes_ConfigValidation3056=== CONT TestAudienceForIssuer3057--- PASS: TestAudienceForIssuer (0.00s)3058=== CONT TestValidateToken_Expired3059=== CONT TestValidateToken_BoundClaimsMismatch3060=== CONT TestValidateToken_KubernetesServiceAccount3061=== CONT TestPins_ConfigValidation3062=== CONT TestScopes_Rules3063=== CONT TestValidateToken_ValidToken3064=== CONT TestScopes_LegacyProviderDefaultsToWrite3065=== CONT TestScopes_ConfigValidation3066=== CONT TestPins_ReservedForMatchingRule3067=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3068--- PASS: TestPins_ConfigValidation (0.01s)3069=== CONT TestValidateToken_MultipleProviders3070--- PASS: TestScopes_ConfigValidation (0.01s)3071=== CONT TestPins_TopLevelShorthand30722026/10/01 09:31:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65211/oidc3073--- PASS: TestScopes_Rules (0.04s)3074=== CONT TestGlobMatch3075=== RUN TestGlobMatch/foo_foo3076=== PAUSE TestGlobMatch/foo_foo3077=== RUN TestGlobMatch/foo_bar3078=== PAUSE TestGlobMatch/foo_bar3079=== RUN TestGlobMatch/*_3080=== PAUSE TestGlobMatch/*_3081=== RUN TestGlobMatch/*_anything3082=== PAUSE TestGlobMatch/*_anything3083=== RUN TestGlobMatch/foo*_foo3084=== PAUSE TestGlobMatch/foo*_foo3085=== RUN TestGlobMatch/foo*_foobar3086=== PAUSE TestGlobMatch/foo*_foobar3087=== RUN TestGlobMatch/foo*_bar3088=== PAUSE TestGlobMatch/foo*_bar3089=== RUN TestGlobMatch/*bar_bar3090=== PAUSE TestGlobMatch/*bar_bar3091=== RUN TestGlobMatch/*bar_foobar3092=== PAUSE TestGlobMatch/*bar_foobar3093=== RUN TestGlobMatch/*bar_foo3094=== PAUSE TestGlobMatch/*bar_foo3095=== RUN TestGlobMatch/foo*bar_foobar3096=== PAUSE TestGlobMatch/foo*bar_foobar3097=== RUN TestGlobMatch/foo*bar_foo123bar3098=== PAUSE TestGlobMatch/foo*bar_foo123bar3099=== RUN TestGlobMatch/foo*bar_foobarbaz3100=== PAUSE TestGlobMatch/foo*bar_foobarbaz3101=== RUN TestGlobMatch/*/*_foo/bar3102=== PAUSE TestGlobMatch/*/*_foo/bar3103=== RUN TestGlobMatch/*/*_foo3104=== PAUSE TestGlobMatch/*/*_foo3105=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3106=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3107=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03108=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03109=== RUN TestGlobMatch/refs/*/main_refs/heads/main3110=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3111=== RUN TestGlobMatch/fo?_foo3112=== PAUSE TestGlobMatch/fo?_foo3113=== RUN TestGlobMatch/fo?_fo3114=== PAUSE TestGlobMatch/fo?_fo3115=== RUN TestGlobMatch/fo?_fooo3116=== PAUSE TestGlobMatch/fo?_fooo3117=== RUN TestGlobMatch/?oo_foo3118=== PAUSE TestGlobMatch/?oo_foo3119=== RUN TestGlobMatch/?oo_boo3120=== PAUSE TestGlobMatch/?oo_boo3121=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3122=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3123=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3124=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3125=== CONT TestNewValidator_KubernetesRequiresCA31262026/10/01 09:31:00 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:652133127--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)3128=== CONT TestValidateToken_BoundSubjectMismatch31292026/10/01 09:31:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65216/oidc3130--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.08s)3131=== CONT TestValidateToken_WrongAudience31322026/10/01 09:31:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65218/oidc3133--- PASS: TestPins_ReservedForMatchingRule (0.08s)3134=== CONT TestValidateToken_NoMatchingProvider31352026/10/01 09:31:00 http: TLS handshake error from 127.0.0.1:65221: read tcp 127.0.0.1:65220->127.0.0.1:65221: use of closed network connection3136--- PASS: TestNewValidator_KubernetesRequiresCA (0.07s)3137=== CONT TestGlobMatch/foo_foo3138=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3139=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3140=== CONT TestGlobMatch/?oo_boo3141=== CONT TestGlobMatch/?oo_foo3142=== CONT TestGlobMatch/fo?_fooo3143=== CONT TestGlobMatch/fo?_fo3144=== CONT TestGlobMatch/fo?_foo3145=== CONT TestGlobMatch/refs/*/main_refs/heads/main3146=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03147=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3148=== CONT TestGlobMatch/*/*_foo3149=== CONT TestGlobMatch/*/*_foo/bar3150=== CONT TestGlobMatch/foo*bar_foobarbaz3151=== CONT TestGlobMatch/foo*bar_foo123bar3152=== CONT TestGlobMatch/foo*bar_foobar3153=== CONT TestGlobMatch/*bar_foo3154=== CONT TestGlobMatch/*bar_foobar3155=== CONT TestGlobMatch/*bar_bar3156=== CONT TestGlobMatch/foo*_bar3157=== CONT TestGlobMatch/foo*_foobar3158=== CONT TestGlobMatch/foo*_foo3159=== CONT TestGlobMatch/*_anything3160=== CONT TestGlobMatch/*_3161=== CONT TestGlobMatch/foo_bar3162--- PASS: TestGlobMatch (0.00s)3163 --- PASS: TestGlobMatch/foo_foo (0.00s)3164 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3165 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3166 --- PASS: TestGlobMatch/?oo_boo (0.00s)3167 --- PASS: TestGlobMatch/?oo_foo (0.00s)3168 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3169 --- PASS: TestGlobMatch/fo?_fo (0.00s)3170 --- PASS: TestGlobMatch/fo?_foo (0.00s)3171 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3172 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3173 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3174 --- PASS: TestGlobMatch/*/*_foo (0.00s)3175 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3176 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3177 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3178 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3179 --- PASS: TestGlobMatch/*bar_foo (0.00s)3180 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3181 --- PASS: TestGlobMatch/*bar_bar (0.00s)3182 --- PASS: TestGlobMatch/foo*_bar (0.00s)3183 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3184 --- PASS: TestGlobMatch/foo*_foo (0.00s)3185 --- PASS: TestGlobMatch/*_anything (0.00s)3186 --- PASS: TestGlobMatch/*_ (0.00s)3187 --- PASS: TestGlobMatch/foo_bar (0.00s)31882026/10/01 09:31:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65222/oidc31892026/10/01 09:31:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65224/oidc3190--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)3191--- PASS: TestValidateToken_Expired (0.12s)31922026/10/01 09:31:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65226/oidc3193--- PASS: TestPins_TopLevelShorthand (0.11s)31942026/10/01 09:31:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65228/oidc3195--- PASS: TestValidateToken_ValidToken (0.13s)31962026/10/01 09:31:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65230/oidc3197--- PASS: TestValidateToken_BoundSubjectMismatch (0.07s)31982026/10/01 09:31:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:65232/oidc3199--- PASS: TestValidateToken_WrongAudience (0.06s)32002026/10/01 09:31:00 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:65215/oidc32012026/10/01 09:31:00 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:65235/oidc3202--- PASS: TestValidateToken_MultipleProviders (0.14s)32032026/10/01 09:31:00 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:65234/oidc3204--- PASS: TestValidateToken_NoMatchingProvider (0.10s)32052026/10/01 09:31:00 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233206--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.19s)3207PASS3208Running hook tests...3209=== RUN TestSendPathsEmpty3210=== PAUSE TestSendPathsEmpty3211=== RUN TestQueueEnqueueAndFetch3212=== PAUSE TestQueueEnqueueAndFetch3213=== RUN TestQueueDeduplication3214=== PAUSE TestQueueDeduplication3215=== RUN TestQueueRemove3216=== PAUSE TestQueueRemove3217=== RUN TestQueueFetchBatchLimit3218=== PAUSE TestQueueFetchBatchLimit3219=== RUN TestQueueRetryMovesToBack3220=== PAUSE TestQueueRetryMovesToBack3221=== RUN TestQueueFetchRemoveLifecycle3222=== PAUSE TestQueueFetchRemoveLifecycle3223=== RUN TestQueueConcurrentWriters3224=== PAUSE TestQueueConcurrentWriters3225=== RUN TestQueueRemoveLargeClosure3226=== PAUSE TestQueueRemoveLargeClosure3227=== RUN TestServerClientIntegration3228=== PAUSE TestServerClientIntegration3229=== RUN TestServerQueueError3230=== PAUSE TestServerQueueError3231=== RUN TestGetListenerSocketActivation3232 server_test.go:210: === RUN TestGetListenerSocketActivation3233 --- PASS: TestGetListenerSocketActivation (0.00s)3234 PASS3235 3236--- PASS: TestGetListenerSocketActivation (0.01s)3237=== RUN TestDrainIsolatesPoisonPath3238=== PAUSE TestDrainIsolatesPoisonPath3239=== RUN TestRunNotBlockedByPoisonHead3240=== PAUSE TestRunNotBlockedByPoisonHead3241=== RUN TestDrainGivesUpWhenServerDown3242=== PAUSE TestDrainGivesUpWhenServerDown3243=== RUN TestFailedPathPrunedByLaterClosure3244=== PAUSE TestFailedPathPrunedByLaterClosure3245=== RUN TestWorkerUploadsAndRemoves3246=== PAUSE TestWorkerUploadsAndRemoves3247=== RUN TestWorkerSkipsGCdPaths3248=== PAUSE TestWorkerSkipsGCdPaths3249=== RUN TestWorkerPrunesClosureDeps3250=== PAUSE TestWorkerPrunesClosureDeps3251=== RUN TestDrainTimeout3252=== PAUSE TestDrainTimeout3253=== CONT TestSendPathsEmpty3254=== CONT TestServerQueueError3255=== CONT TestQueueRemoveLargeClosure3256=== CONT TestQueueRetryMovesToBack3257--- PASS: TestSendPathsEmpty (0.00s)3258=== CONT TestServerClientIntegration3259=== CONT TestQueueFetchBatchLimit3260=== CONT TestQueueRemove3261=== CONT TestQueueDeduplication3262=== CONT TestQueueEnqueueAndFetch3263=== CONT TestQueueConcurrentWriters3264=== CONT TestWorkerUploadsAndRemoves32652026/10/01 09:31:01 ERROR Failed to queue paths error="permission denied" count=13266--- PASS: TestServerClientIntegration (0.00s)3267=== CONT TestDrainTimeout3268--- PASS: TestServerQueueError (0.00s)3269=== CONT TestWorkerPrunesClosureDeps32702026/10/01 09:31:01 INFO Upload queue status pending=232712026/10/01 09:31:01 INFO Uploading batch count=232722026/10/01 09:31:01 INFO Upload queue status pending=232732026/10/01 09:31:01 INFO Uploading batch count=13274--- PASS: TestQueueFetchBatchLimit (0.01s)3275=== CONT TestWorkerSkipsGCdPaths3276--- PASS: TestQueueRetryMovesToBack (0.01s)3277=== CONT TestDrainGivesUpWhenServerDown3278--- PASS: TestQueueEnqueueAndFetch (0.01s)3279=== CONT TestFailedPathPrunedByLaterClosure32802026/10/01 09:31:01 INFO Uploading batch count=23281--- PASS: TestQueueDeduplication (0.01s)3282=== CONT TestQueueFetchRemoveLifecycle3283--- PASS: TestQueueRemove (0.01s)3284=== CONT TestRunNotBlockedByPoisonHead32852026/10/01 09:31:01 INFO Upload queue status pending=232862026/10/01 09:31:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-36033-363360632/TestWorkerSkipsGCdPaths400032836/002/nonexistent32872026/10/01 09:31:01 INFO Uploading batch count=132882026/10/01 09:31:01 ERROR Upload failed error="upload failed" count=132892026/10/01 09:31:01 INFO Uploading batch count=132902026/10/01 09:31:01 INFO Uploading batch count=132912026/10/01 09:31:01 INFO Upload queue status pending=332922026/10/01 09:31:01 INFO Uploading batch count=132932026/10/01 09:31:01 ERROR Upload failed error="upload failed" count=132942026/10/01 09:31:01 INFO Uploading batch count=132952026/10/01 09:31:01 INFO Uploading batch count=232962026/10/01 09:31:01 ERROR Upload failed error="upload failed" count=232972026/10/01 09:31:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-36033-363360632/TestDrainGivesUpWhenServerDown2000483010/002/a3298--- PASS: TestQueueFetchRemoveLifecycle (0.00s)3299=== CONT TestDrainIsolatesPoisonPath33002026/10/01 09:31:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-36033-363360632/TestDrainGivesUpWhenServerDown2000483010/002/b33012026/10/01 09:31:01 INFO Uploading batch count=233022026/10/01 09:31:01 ERROR Upload failed error="upload failed" count=233032026/10/01 09:31:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-36033-363360632/TestDrainGivesUpWhenServerDown2000483010/002/c33042026/10/01 09:31:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-36033-363360632/TestDrainGivesUpWhenServerDown2000483010/002/d33052026/10/01 09:31:01 INFO Uploading batch count=233062026/10/01 09:31:01 ERROR Upload failed error="upload failed" count=233072026/10/01 09:31:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-36033-363360632/TestDrainGivesUpWhenServerDown2000483010/002/e33082026/10/01 09:31:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-36033-363360632/TestDrainGivesUpWhenServerDown2000483010/002/f33092026/10/01 09:31:01 ERROR Drain finished with paths left in queue remaining=103310--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)33112026/10/01 09:31:01 INFO Uploading batch count=433122026/10/01 09:31:01 ERROR Upload failed error="upload failed" count=433132026/10/01 09:31:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-36033-363360632/TestDrainIsolatesPoisonPath3544963402/002/bbb33142026/10/01 09:31:01 INFO Uploading batch count=133152026/10/01 09:31:01 ERROR Upload failed error="upload failed" count=133162026/10/01 09:31:01 INFO Uploading batch count=133172026/10/01 09:31:01 ERROR Upload failed error="upload failed" count=133182026/10/01 09:31:01 INFO Uploading batch count=133192026/10/01 09:31:01 ERROR Upload failed error="upload failed" count=13320--- PASS: TestDrainGivesUpWhenServerDown (0.01s)33212026/10/01 09:31:01 ERROR Drain finished with paths left in queue remaining=13322--- PASS: TestDrainIsolatesPoisonPath (0.00s)3323--- PASS: TestWorkerUploadsAndRemoves (0.03s)3324--- PASS: TestWorkerPrunesClosureDeps (0.03s)3325--- PASS: TestWorkerSkipsGCdPaths (0.02s)3326--- PASS: TestQueueRemoveLargeClosure (0.05s)3327--- PASS: TestQueueConcurrentWriters (0.15s)33282026/10/01 09:31:01 ERROR Upload failed error="context deadline exceeded" count=233292026/10/01 09:31:01 ERROR Drain finished with paths left in queue remaining=43330--- PASS: TestDrainTimeout (0.21s)33312026/10/01 09:31:02 INFO Uploading batch count=133322026/10/01 09:31:02 INFO Uploading batch count=133332026/10/01 09:31:02 INFO Uploading batch count=133342026/10/01 09:31:02 ERROR Upload failed error="upload failed" count=133352026/10/01 09:31:02 INFO Uploading batch count=133362026/10/01 09:31:02 ERROR Upload failed error="upload failed" count=133372026/10/01 09:31:02 INFO Uploading batch count=133382026/10/01 09:31:02 ERROR Upload failed error="upload failed" count=133392026/10/01 09:31:02 INFO Uploading batch count=133402026/10/01 09:31:02 ERROR Upload failed error="upload failed" count=133412026/10/01 09:31:02 ERROR Drain finished with paths left in queue remaining=13342--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3343PASS