niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #324
· 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.04s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.01s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestShellSplit96=== CONT TestEncodeNixBase32WithRealHash97=== CONT TestSetClientTLSErrors98=== CONT TestPathInfoHashCompatibility99--- PASS: TestEncodeNixBase32WithRealHash (0.00s)100--- PASS: TestShellSplit (0.00s)101=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)102=== CONT TestResolveStorePath103=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)104=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess105=== CONT TestRateLimiterFeedback106=== RUN TestRateLimiterFeedback/429_enables_limiter107=== PAUSE TestRateLimiterFeedback/429_enables_limiter108=== RUN TestRateLimiterFeedback/503_enables_limiter109=== PAUSE TestRateLimiterFeedback/503_enables_limiter110=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter111=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter112=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter113=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter114=== CONT TestPathInfoCACompatibility115=== RUN TestPathInfoCACompatibility/null_ca_field116=== PAUSE TestPathInfoCACompatibility/null_ca_field117=== RUN TestPathInfoCACompatibility/old_string_format_-_text118=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text119=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive120=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive121=== RUN TestPathInfoCACompatibility/new_structured_format_-_text122=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text123=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method124=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method125=== CONT TestParsePathInfoJSONMultiplePaths126=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths127=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths128=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths129=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths130=== CONT TestConvertHashToNix32131=== RUN TestConvertHashToNix32/SRI_format_to_Nix32132=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32133=== RUN TestConvertHashToNix32/already_Nix32_format134=== CONT TestGetStorePathHash135=== PAUSE TestConvertHashToNix32/already_Nix32_format136=== RUN TestConvertHashToNix32/invalid_format137=== PAUSE TestConvertHashToNix32/invalid_format138=== RUN TestGetStorePathHash/valid_store_path139=== PAUSE TestGetStorePathHash/valid_store_path140=== RUN TestGetStorePathHash/basename_without_hyphen_should_error141=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error142=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error143=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error144=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error145=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error146=== CONT TestSetClientTLSDoesNotMutateDefaultTransport147=== CONT TestDoWithRetry_BodyReplayedViaGetBody1482026/10/01 09:53:16 WARN Rate limiter enabled after throttle name=server-test rate=5149=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon150=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon151=== CONT TestStreamPushRequestLine152=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI153=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI154=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512155=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512156=== CONT TestClientSignaturesByStorePath157--- PASS: TestClientSignaturesByStorePath (0.00s)158=== CONT TestStreamPushReportsSignatures159=== CONT TestParsePathInfoJSON160=== CONT TestSetClientTLS161=== RUN TestParsePathInfoJSON/Nix_format162=== PAUSE TestParsePathInfoJSON/Nix_format163=== RUN TestParsePathInfoJSON/Lix_format164=== PAUSE TestParsePathInfoJSON/Lix_format165=== RUN TestParsePathInfoJSON/empty_input166=== PAUSE TestParsePathInfoJSON/empty_input167=== RUN TestParsePathInfoJSON/whitespace_only168=== PAUSE TestParsePathInfoJSON/whitespace_only169=== RUN TestParsePathInfoJSON/invalid_JSON170=== PAUSE TestParsePathInfoJSON/invalid_JSON171=== CONT TestUploadMultipart_SupersededByPeer172=== RUN TestUploadMultipart_SupersededByPeer/exists173=== PAUSE TestUploadMultipart_SupersededByPeer/exists174=== RUN TestUploadMultipart_SupersededByPeer/missing175=== PAUSE TestUploadMultipart_SupersededByPeer/missing176=== CONT TestEncodeNixBase32177=== RUN TestEncodeNixBase32/test_string_hash178=== PAUSE TestEncodeNixBase32/test_string_hash179=== RUN TestEncodeNixBase32/empty_input180=== PAUSE TestEncodeNixBase32/empty_input181=== CONT TestDumpPathWriterError1822026/10/01 09:53:16 ERROR Upload failed error=boom count=1183--- PASS: TestStreamPushReportsSignatures (0.00s)184=== CONT TestDumpPathSingleFile1852026/10/01 09:53:16 ERROR Upload failed error=boom count=11862026/10/01 09:53:16 WARN Rate limiter enabled after throttle name=server-test rate=51872026/10/01 09:53:16 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:56016188--- PASS: TestDoServerRequestAttachesToken (0.00s)189=== CONT TestDumpPathMatchesNix1902026/10/01 09:53:16 WARN Rate limiter backed off name=server-test rate=51912026/10/01 09:53:16 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:56016192--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)193=== CONT TestFileTokenMissing194=== RUN TestSetClientTLSErrors/missing_cert_file195=== PAUSE TestSetClientTLSErrors/missing_cert_file196=== RUN TestSetClientTLSErrors/missing_key_file197=== PAUSE TestSetClientTLSErrors/missing_key_file198=== RUN TestSetClientTLSErrors/missing_ca_file199=== PAUSE TestSetClientTLSErrors/missing_ca_file200=== RUN TestSetClientTLSErrors/invalid_ca_file201=== PAUSE TestSetClientTLSErrors/invalid_ca_file202=== CONT TestScriptTokenNoExpiryRerunsEveryCall203--- PASS: TestStreamPushRequestLine (0.01s)204=== CONT TestFileTokenEmpty205--- PASS: TestFileTokenMissing (0.01s)206=== CONT TestFilterOversizedClosures207=== RUN TestFilterOversizedClosures/no_limit_keeps_everything208=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything209=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped210=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped211=== RUN TestFilterOversizedClosures/all_closures_skipped212=== PAUSE TestFilterOversizedClosures/all_closures_skipped213=== CONT TestPartSizeForNAR214=== RUN TestPartSizeForNAR/zero_stays_at_minimum215=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum216=== RUN TestPartSizeForNAR/small_stays_at_minimum217=== PAUSE TestPartSizeForNAR/small_stays_at_minimum218=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum219=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum220=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts221=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts222=== RUN TestPartSizeForNAR/1_TiB223=== PAUSE TestPartSizeForNAR/1_TiB224=== RUN TestPartSizeForNAR/5_TiB_S3_max_object225=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object226=== RUN TestPartSizeForNAR/capped_at_5_GiB227=== PAUSE TestPartSizeForNAR/capped_at_5_GiB228=== CONT TestUploadMultipart_PartsInParallel229--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)230=== CONT TestScriptTokenScriptFails231=== CONT TestScriptTokenEmptyCommand232--- PASS: TestScriptTokenEmptyCommand (0.00s)233=== CONT TestCaseHackSuffix234--- PASS: TestResolveStorePath (0.01s)235--- PASS: TestScriptTokenScriptFails (0.01s)236=== CONT TestScriptTokenBadJSON237--- PASS: TestFileTokenEmpty (0.01s)238=== CONT TestScriptTokenEmptyToken239=== RUN TestSetClientTLS/rejects_connection_without_client_cert240=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert241=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA242=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA243=== RUN TestSetClientTLS/preserves_debug_logging_transport244=== PAUSE TestSetClientTLS/preserves_debug_logging_transport245=== CONT TestFileTokenReadsAndCaches246--- PASS: TestScriptTokenEmptyToken (0.01s)247=== CONT TestStreamPushBatchesUnderLoad248--- PASS: TestScriptTokenBadJSON (0.01s)249=== CONT TestStreamPushGivesUpOnDeadServer2502026/10/01 09:53:16 ERROR Upload failed error="connection refused" count=202512026/10/01 09:53:16 ERROR Server seems unavailable, giving up on batch untried=17252--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)253=== CONT TestStreamPushIsolatesFailures2542026/10/01 09:53:16 ERROR Upload failed error="bad path" count=3255--- PASS: TestStreamPushIsolatesFailures (0.00s)256=== CONT TestStaticToken257--- PASS: TestStaticToken (0.00s)258=== CONT TestRegisterUploadedObjectReusesConnections259--- PASS: TestFileTokenReadsAndCaches (0.01s)260=== CONT TestStreamPushReportsEveryPath261--- PASS: TestStreamPushReportsEveryPath (0.00s)262=== CONT TestShellSplitErrors263--- PASS: TestShellSplitErrors (0.00s)264=== CONT TestScriptTokenCachesUntilRefresh265--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)266=== CONT TestRateLimiterFeedback/429_enables_limiter2672026/10/01 09:53:16 WARN Rate limiter enabled after throttle name=server-test rate=52682026/10/01 09:53:16 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:56091269--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)270=== CONT TestPathInfoCACompatibility/null_ca_field2712026/10/01 09:53:16 WARN Rate limiter backed off name=server-test rate=5272=== CONT TestRateLimiterFeedback/503_enables_limiter273=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths274=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2752026/10/01 09:53:16 WARN Rate limiter enabled after throttle name=server-test rate=52762026/10/01 09:53:16 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:56093277=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2782026/10/01 09:53:16 WARN Rate limiter backed off name=server-test rate=5279=== CONT TestPathInfoCACompatibility/old_string_format_-_text280=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method281=== CONT TestPathInfoCACompatibility/new_structured_format_-_text282=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive283--- PASS: TestPathInfoCACompatibility (0.00s)284 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)285 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)286 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)287 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)288 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)289=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths290--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)291 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)292 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)293=== CONT TestConvertHashToNix32/SRI_format_to_Nix32294=== CONT TestGetStorePathHash/valid_store_path295=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error296=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error297=== CONT TestGetStorePathHash/basename_without_hyphen_should_error298--- PASS: TestGetStorePathHash (0.00s)299 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)300 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)301 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)302 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)303=== CONT TestConvertHashToNix32/already_Nix32_format304=== CONT TestConvertHashToNix32/invalid_format305--- PASS: TestConvertHashToNix32 (0.00s)306 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)307 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)308 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)309=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)310=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon311=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI312=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512313--- PASS: TestPathInfoHashCompatibility (0.00s)314 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)315 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)316 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)317 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)318=== CONT TestParsePathInfoJSON/Nix_format319=== CONT TestUploadMultipart_SupersededByPeer/exists320--- PASS: TestRateLimiterFeedback (0.00s)321 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)322 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)323 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)324 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)325=== CONT TestParsePathInfoJSON/invalid_JSON326=== CONT TestParsePathInfoJSON/whitespace_only327=== CONT TestParsePathInfoJSON/empty_input328=== CONT TestParsePathInfoJSON/Lix_format329--- PASS: TestParsePathInfoJSON (0.00s)330 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)331 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)332 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)333 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)334 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)335=== CONT TestEncodeNixBase32/test_string_hash336=== CONT TestUploadMultipart_SupersededByPeer/missing337=== CONT TestEncodeNixBase32/empty_input338--- PASS: TestEncodeNixBase32 (0.00s)339 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)340 --- PASS: TestEncodeNixBase32/empty_input (0.00s)341=== CONT TestSetClientTLSErrors/missing_cert_file342=== CONT TestSetClientTLSErrors/missing_ca_file343--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)344 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)345 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)346=== CONT TestSetClientTLSErrors/missing_key_file347=== CONT TestSetClientTLSErrors/invalid_ca_file348=== CONT TestFilterOversizedClosures/no_limit_keeps_everything349=== CONT TestFilterOversizedClosures/all_closures_skipped3502026/10/01 09:53:16 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=50351=== CONT TestPartSizeForNAR/zero_stays_at_minimum352=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3532026/10/01 09:53:16 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=2000354--- PASS: TestFilterOversizedClosures (0.00s)355 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)356 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)357 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)358=== CONT TestPartSizeForNAR/1_TiB359=== CONT TestPartSizeForNAR/capped_at_5_GiB360=== CONT TestPartSizeForNAR/5_TiB_S3_max_object361=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum362=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts363=== CONT TestPartSizeForNAR/small_stays_at_minimum364--- PASS: TestPartSizeForNAR (0.00s)365 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)366 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)367 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)368 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)369 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)370 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)371 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)372=== CONT TestSetClientTLS/rejects_connection_without_client_cert373=== CONT TestSetClientTLS/preserves_debug_logging_transport374--- PASS: TestSetClientTLSErrors (0.01s)375 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)376 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)377 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)378 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)379=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3802026/10/01 09:53:16 http: TLS handshake error from 127.0.0.1:56103: remote error: tls: bad certificate381--- PASS: TestDumpPathSingleFile (0.07s)382--- PASS: TestSetClientTLS (0.02s)383 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)384 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)385 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)386--- PASS: TestCaseHackSuffix (0.06s)387--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)388--- PASS: TestDumpPathWriterError (0.10s)389--- PASS: TestStreamPushBatchesUnderLoad (0.10s)390--- PASS: TestDumpPathMatchesNix (0.13s)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 "_nixbld11".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-91990-792741325/postgres3108812030/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-91990-792741325/postgres3108812030/data -l logfile start421422/nix/var/nix/builds/nix-91990-792741325/postgres3108812030:5432 - no response4232026-10-01 09:53:18.602 UTC [92032] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 09:53:18.602 UTC [92032] LOG: listening on Unix socket "/nix/var/nix/builds/nix-91990-792741325/postgres3108812030/.s.PGSQL.5432"4252026-10-01 09:53:18.610 UTC [92039] LOG: database system was shut down at 2026-10-01 09:53:18 UTC4262026-10-01 09:53:18.612 UTC [92032] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-91990-792741325/postgres3108812030:5432 - accepting connections428{"timestamp":"2026-10-01T09:53:18.812495Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"ecc6396e-1018-4eb8-b0b6-24f24e167b76","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(3)"}429{"timestamp":"2026-10-01T09:53:18.91626Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"21d14680-5cca-4767-818e-5128c5119ee2","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(3)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock468=== RUN TestResolveDBConnectionString469=== PAUSE TestResolveDBConnectionString470=== RUN TestLeadElectsOneAndHandsOver471=== PAUSE TestLeadElectsOneAndHandsOver472=== RUN TestLeadIncumbentWinsAfterRestart4732026-10-01 09:53:19.564 UTC [92071] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 09:53:19.564 UTC [92071] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 09:53:19 OK 20241026095416_initial_model.sql (16.29ms)4762026/10/01 09:53:19 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)4772026/10/01 09:53:19 OK 20251218171726_add_pins.sql (2.43ms)4782026/10/01 09:53:19 OK 20260628120000_add_object_size_and_stats.sql (6.62ms)4792026/10/01 09:53:19 OK 20260905000000_add_claims.sql (16.79ms)4802026/10/01 09:53:19 OK 20260920000000_drop_claims.sql (8.97ms)4812026/10/01 09:53:19 OK 20260923120000_add_pushes.sql (1.07ms)4822026/10/01 09:53:19 goose: successfully migrated database to version: 202609231200004832026/10/01 09:53:19 OK 1_commit_pending_closure.sql (2ms)4842026/10/01 09:53:19 OK 2_object_stats_trigger.sql (443.08µs)4852026/10/01 09:53:19 OK 3_commit_push.sql (370.92µs)4862026/10/01 09:53:19 goose: up to current file version: 34872026/10/01 09:53:19 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 09:53:20 INFO lead: released remote=192.0.2.1:12344892026/10/01 09:53:20 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 09:53:20 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (1.39s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 09:53:20.643 UTC [92079] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 09:53:20.643 UTC [92079] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 09:53:20 OK 20241026095416_initial_model.sql (28.29ms)4982026/10/01 09:53:20 OK 20251210153512_drop_unused_gin_index.sql (1.16ms)4992026/10/01 09:53:20 OK 20251218171726_add_pins.sql (1.98ms)5002026/10/01 09:53:20 OK 20260628120000_add_object_size_and_stats.sql (2.05ms)5012026/10/01 09:53:20 OK 20260905000000_add_claims.sql (2.02ms)5022026/10/01 09:53:20 OK 20260920000000_drop_claims.sql (1.27ms)5032026/10/01 09:53:20 OK 20260923120000_add_pushes.sql (742.96µs)5042026/10/01 09:53:20 goose: successfully migrated database to version: 202609231200005052026/10/01 09:53:20 OK 1_commit_pending_closure.sql (1.87ms)5062026/10/01 09:53:20 OK 2_object_stats_trigger.sql (350.75µs)5072026/10/01 09:53:20 OK 3_commit_push.sql (326.75µs)5082026/10/01 09:53:20 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.42s)510=== RUN TestGCBugBareHashReferences511=== PAUSE TestGCBugBareHashReferences512=== RUN TestGCMetrics513=== PAUSE TestGCMetrics514=== RUN TestPushDedupSurvivesConcurrentGC515=== PAUSE TestPushDedupSurvivesConcurrentGC516=== RUN TestDeduplicatedObjectsRecordedAsPending517=== PAUSE TestDeduplicatedObjectsRecordedAsPending518=== RUN TestGCSweepSkipsPendingObjects519=== PAUSE TestGCSweepSkipsPendingObjects520=== RUN TestTombstonedObjectOfferedWithoutWaiting521=== PAUSE TestTombstonedObjectOfferedWithoutWaiting522=== RUN TestGCSweepDeliversEachKeyOnce523=== PAUSE TestGCSweepDeliversEachKeyOnce524=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== RUN TestForceGCDuringPushOffersSweptObject527=== PAUSE TestForceGCDuringPushOffersSweptObject528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestSweepRechecksPendingAfterLocking537=== PAUSE TestSweepRechecksPendingAfterLocking538=== RUN TestPushWaitsForSweepHoldingRow539=== PAUSE TestPushWaitsForSweepHoldingRow540=== RUN TestCommitRacingPendingCleanupKeepsObjects541=== PAUSE TestCommitRacingPendingCleanupKeepsObjects542=== RUN TestGCEndsOnShutdown543=== PAUSE TestGCEndsOnShutdown544=== RUN TestGCTaskStore_StartNew545=== PAUSE TestGCTaskStore_StartNew546=== RUN TestGCTaskStore_DeduplicateSameParams547=== PAUSE TestGCTaskStore_DeduplicateSameParams548=== RUN TestGCTaskStore_ConflictDifferentParams549=== PAUSE TestGCTaskStore_ConflictDifferentParams550=== RUN TestGCTaskStore_GetEmpty551=== PAUSE TestGCTaskStore_GetEmpty552=== RUN TestGCTaskStore_GetReturnsLatest553=== PAUSE TestGCTaskStore_GetReturnsLatest554=== RUN TestGCTaskStore_CompletedAllowsNewTask555=== PAUSE TestGCTaskStore_CompletedAllowsNewTask556=== RUN TestGCTaskStore_PhaseUpdates557=== PAUSE TestGCTaskStore_PhaseUpdates558=== RUN TestGCTaskStore_Fail559=== PAUSE TestGCTaskStore_Fail560=== RUN TestGracefulShutdownDrainsInflight561=== PAUSE TestGracefulShutdownDrainsInflight562=== RUN TestService_healthCheckHandler563=== PAUSE TestService_healthCheckHandler564=== RUN TestService_readinessHandler565=== PAUSE TestService_readinessHandler566=== RUN TestGenerateLandingPage567=== PAUSE TestGenerateLandingPage568=== RUN TestCacheConfigHandlerMaxNarSize569=== PAUSE TestCacheConfigHandlerMaxNarSize570=== RUN TestCreatePendingClosureRejectsOversizedNAR571=== PAUSE TestCreatePendingClosureRejectsOversizedNAR572=== RUN TestNARDeduplicationMetadataUploadBug573=== PAUSE TestNARDeduplicationMetadataUploadBug574=== RUN TestMetricsInventory575=== PAUSE TestMetricsInventory576=== RUN TestService_NativeMTLS577=== PAUSE TestService_NativeMTLS578=== RUN TestServerTLSConfig579=== PAUSE TestServerTLSConfig580=== RUN TestMultipartCleanup581=== PAUSE TestMultipartCleanup582=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded584=== RUN TestPendingCleanupUsesOneCutoff585=== PAUSE TestPendingCleanupUsesOneCutoff586=== RUN TestObjectStatsTrigger587=== PAUSE TestObjectStatsTrigger588=== RUN TestOrphanedObjectsGC589=== PAUSE TestOrphanedObjectsGC590=== RUN TestOrphanedObjectsGCStressTest591=== PAUSE TestOrphanedObjectsGCStressTest592=== RUN TestCreatePin_ReservedPins593=== PAUSE TestCreatePin_ReservedPins594=== RUN TestPresentReportsOnlyClosureRoots595=== PAUSE TestPresentReportsOnlyClosureRoots596=== RUN TestPresentNotReportedWhileGCDeletesClosure597=== PAUSE TestPresentNotReportedWhileGCDeletesClosure598=== RUN TestParseSingleRange599=== PAUSE TestParseSingleRange600=== RUN TestProxyHeadersOnlyTrustedOnSocket601=== PAUSE TestProxyHeadersOnlyTrustedOnSocket602=== RUN TestIsValidCachePath603=== PAUSE TestIsValidCachePath604=== RUN TestReadProxyNarinfo605=== PAUSE TestReadProxyNarinfo606=== RUN TestReadProxyNarinfoAlreadyDecompressed607=== PAUSE TestReadProxyNarinfoAlreadyDecompressed608=== RUN TestReadProxyNarStreaming609=== PAUSE TestReadProxyNarStreaming610=== RUN TestReadProxy404611=== PAUSE TestReadProxy404612=== RUN TestReadProxyInvalidPath613=== PAUSE TestReadProxyInvalidPath614=== RUN TestReadProxyHead615=== PAUSE TestReadProxyHead616=== RUN TestReadProxyConditionalGet617=== PAUSE TestReadProxyConditionalGet618=== RUN TestReadProxyRootRedirectsToIndexHTML619=== PAUSE TestReadProxyRootRedirectsToIndexHTML620=== RUN TestReadProxyDisabled621=== PAUSE TestReadProxyDisabled622=== RUN TestReadRedirectNar623=== PAUSE TestReadRedirectNar624=== RUN TestReadRedirectKeepsNarinfoProxied625=== PAUSE TestReadRedirectKeepsNarinfoProxied626=== RUN TestReadProxyRangeRequest627=== PAUSE TestReadProxyRangeRequest628=== RUN TestReadRedirectUsesPublicS3URL629=== PAUSE TestReadRedirectUsesPublicS3URL630=== RUN TestPush_OverlappingRootsStoreOneRowPerKey631=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey632=== RUN TestPush_CompleteCommitsEveryRoot633=== PAUSE TestPush_CompleteCommitsEveryRoot634=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit635=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit636=== RUN TestPush_RejectsBadRequests637=== PAUSE TestPush_RejectsBadRequests638=== RUN TestPush_SignsNarinfosOfItsPendingObjects639=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects640=== RUN TestRedundantMultipartUpload641=== PAUSE TestRedundantMultipartUpload642=== RUN TestCompleteMultipartUpload_ErrorButObjectExists643=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists644=== RUN TestCompletedNarNotReofferedAcrossClosures645=== PAUSE TestCompletedNarNotReofferedAcrossClosures646=== RUN TestPresignedUploadRegisteredBeforeCommit647=== PAUSE TestPresignedUploadRegisteredBeforeCommit648=== RUN TestService_Rustfstest649=== PAUSE TestService_Rustfstest650=== RUN TestParseSize651=== PAUSE TestParseSize652=== RUN TestSkippedUploadsHandler653=== PAUSE TestSkippedUploadsHandler654=== RUN TestSystemdListenerNotActivated655--- PASS: TestSystemdListenerNotActivated (0.00s)656=== RUN TestWatchdogBeatsWhenHealthy657--- PASS: TestWatchdogBeatsWhenHealthy (0.04s)658=== RUN TestWatchdogSkipsWhenUnhealthy6592026/10/01 09:53:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:53:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:53:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:53:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:53:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 09:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 09:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6682026/10/01 09:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"669--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)670=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle671=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle672=== RUN TestProxyWriteTimeout673=== PAUSE TestProxyWriteTimeout674=== RUN TestIsValidUploadKey675=== PAUSE TestIsValidUploadKey676=== RUN TestUploadHandlersRejectInvalidKeys677=== PAUSE TestUploadHandlersRejectInvalidKeys678=== RUN TestUploadHandlersRejectOversizedBody679=== PAUSE TestUploadHandlersRejectOversizedBody680=== RUN TestService_cleanupPendingClosuresHandler681=== PAUSE TestService_cleanupPendingClosuresHandler682=== RUN TestService_createPendingClosureHandler683=== PAUSE TestService_createPendingClosureHandler684=== RUN TestService_verifyS3Integrity685=== PAUSE TestService_verifyS3Integrity686=== RUN TestCompleteMultipartUnregistered687=== PAUSE TestCompleteMultipartUnregistered688=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT689=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT690=== CONT TestParseSize691=== CONT TestService_AuthMiddleware692=== CONT TestRedundantMultipartUpload693=== CONT TestUploadHandlersRejectOversizedBody694=== CONT TestUploadHandlersRejectInvalidKeys695=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info696=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info697=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal698=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal699--- PASS: TestParseSize (0.00s)700=== CONT TestService_Rustfstest701=== CONT TestPresignedUploadRegisteredBeforeCommit702=== CONT TestCompletedNarNotReofferedAcrossClosures703=== CONT TestCompleteMultipartUpload_ErrorButObjectExists704=== CONT TestProxyWriteTimeout705=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key706=== CONT TestCacheConfigHandlerMaxNarSize707=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key708=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key709=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key710=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle711=== RUN TestProxyWriteTimeout/narinfo712=== PAUSE TestProxyWriteTimeout/narinfo713--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)714=== CONT TestIsValidUploadKey715=== RUN TestIsValidUploadKey/narinfo716=== RUN TestProxyWriteTimeout/1_GiB_nar717=== PAUSE TestIsValidUploadKey/narinfo718=== RUN TestIsValidUploadKey/nar_zst719=== PAUSE TestProxyWriteTimeout/1_GiB_nar720=== RUN TestProxyWriteTimeout/10_GiB_nar721=== PAUSE TestIsValidUploadKey/nar_zst722=== RUN TestIsValidUploadKey/nar_xz723=== PAUSE TestProxyWriteTimeout/10_GiB_nar724=== RUN TestProxyWriteTimeout/unknown_size725=== PAUSE TestProxyWriteTimeout/unknown_size726=== CONT TestService_verifyS3Integrity727=== PAUSE TestIsValidUploadKey/nar_xz728=== RUN TestIsValidUploadKey/nar_plain729=== PAUSE TestIsValidUploadKey/nar_plain730=== RUN TestIsValidUploadKey/listing731=== PAUSE TestIsValidUploadKey/listing732=== RUN TestIsValidUploadKey/build_log733=== PAUSE TestIsValidUploadKey/build_log734=== RUN TestIsValidUploadKey/build_log_home-manager_file735=== PAUSE TestIsValidUploadKey/build_log_home-manager_file736=== RUN TestIsValidUploadKey/build_log_plus_in_name737=== PAUSE TestIsValidUploadKey/build_log_plus_in_name738=== RUN TestIsValidUploadKey/build_log_question_mark739=== PAUSE TestIsValidUploadKey/build_log_question_mark740=== RUN TestIsValidUploadKey/build_log_equals741=== PAUSE TestIsValidUploadKey/build_log_equals742=== RUN TestIsValidUploadKey/realisation743=== PAUSE TestIsValidUploadKey/realisation744=== RUN TestIsValidUploadKey/realisation_plus_in_output745=== PAUSE TestIsValidUploadKey/realisation_plus_in_output746=== RUN TestIsValidUploadKey/nix-cache-info747=== PAUSE TestIsValidUploadKey/nix-cache-info748=== RUN TestIsValidUploadKey/index.html749=== PAUSE TestIsValidUploadKey/index.html750=== RUN TestIsValidUploadKey/narinfo_key,_nar_type751=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type752=== RUN TestIsValidUploadKey/nar_key,_narinfo_type753=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type754=== RUN TestIsValidUploadKey/listing_key,_narinfo_type755=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type756=== RUN TestIsValidUploadKey/traversal757=== PAUSE TestIsValidUploadKey/traversal758=== RUN TestIsValidUploadKey/traversal_nar759=== PAUSE TestIsValidUploadKey/traversal_nar760=== RUN TestIsValidUploadKey/absolute761=== PAUSE TestIsValidUploadKey/absolute762=== RUN TestIsValidUploadKey/empty_key763=== PAUSE TestIsValidUploadKey/empty_key764=== RUN TestIsValidUploadKey/unknown_type765=== PAUSE TestIsValidUploadKey/unknown_type766=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT767=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure768=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure769=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart770=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart771=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts772=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts773=== CONT TestCompleteMultipartUnregistered7742026-10-01 09:53:22.058 UTC [92106] ERROR: relation "goose_db_version" does not exist at character 367752026-10-01 09:53:22.058 UTC [92106] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7762026-10-01 09:53:22.060 UTC [92107] ERROR: relation "goose_db_version" does not exist at character 367772026-10-01 09:53:22.060 UTC [92107] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7782026-10-01 09:53:22.061 UTC [92108] ERROR: relation "goose_db_version" does not exist at character 367792026-10-01 09:53:22.061 UTC [92108] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7802026-10-01 09:53:22.061 UTC [92109] ERROR: relation "goose_db_version" does not exist at character 367812026-10-01 09:53:22.061 UTC [92109] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7822026-10-01 09:53:22.062 UTC [92110] ERROR: relation "goose_db_version" does not exist at character 367832026-10-01 09:53:22.062 UTC [92110] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7842026-10-01 09:53:22.062 UTC [92112] ERROR: relation "goose_db_version" does not exist at character 367852026-10-01 09:53:22.062 UTC [92112] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7862026-10-01 09:53:22.063 UTC [92111] ERROR: relation "goose_db_version" does not exist at character 367872026-10-01 09:53:22.063 UTC [92111] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7882026-10-01 09:53:22.075 UTC [92114] ERROR: relation "goose_db_version" does not exist at character 367892026-10-01 09:53:22.075 UTC [92114] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7902026-10-01 09:53:22.081 UTC [92115] ERROR: relation "goose_db_version" does not exist at character 367912026-10-01 09:53:22.081 UTC [92115] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7922026-10-01 09:53:22.090 UTC [92113] ERROR: relation "goose_db_version" does not exist at character 367932026-10-01 09:53:22.090 UTC [92113] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7942026/10/01 09:53:22 OK 20241026095416_initial_model.sql (77.88ms)7952026/10/01 09:53:22 OK 20251210153512_drop_unused_gin_index.sql (1.3ms)7962026/10/01 09:53:22 OK 20241026095416_initial_model.sql (62.63ms)7972026/10/01 09:53:22 OK 20241026095416_initial_model.sql (54.74ms)7982026/10/01 09:53:22 OK 20241026095416_initial_model.sql (53.19ms)7992026/10/01 09:53:22 OK 20241026095416_initial_model.sql (42.44ms)8002026/10/01 09:53:22 OK 20241026095416_initial_model.sql (55.15ms)8012026/10/01 09:53:22 OK 20251210153512_drop_unused_gin_index.sql (1.2ms)8022026/10/01 09:53:22 OK 20251218171726_add_pins.sql (2.64ms)8032026/10/01 09:53:22 OK 20251210153512_drop_unused_gin_index.sql (724µs)8042026/10/01 09:53:22 OK 20241026095416_initial_model.sql (53.72ms)8052026/10/01 09:53:22 OK 20241026095416_initial_model.sql (56.23ms)8062026/10/01 09:53:22 OK 20241026095416_initial_model.sql (35.88ms)8072026/10/01 09:53:22 OK 20251210153512_drop_unused_gin_index.sql (776.04µs)8082026/10/01 09:53:22 OK 20251210153512_drop_unused_gin_index.sql (841.17µs)8092026/10/01 09:53:22 OK 20251210153512_drop_unused_gin_index.sql (905.21µs)8102026/10/01 09:53:22 OK 20260628120000_add_object_size_and_stats.sql (2.32ms)8112026/10/01 09:53:22 OK 20251210153512_drop_unused_gin_index.sql (951.92µs)8122026/10/01 09:53:22 OK 20241026095416_initial_model.sql (37.76ms)8132026/10/01 09:53:22 OK 20251210153512_drop_unused_gin_index.sql (1ms)8142026/10/01 09:53:22 OK 20251218171726_add_pins.sql (2.68ms)8152026/10/01 09:53:22 OK 20251210153512_drop_unused_gin_index.sql (883.42µs)8162026/10/01 09:53:22 OK 20251210153512_drop_unused_gin_index.sql (881.63µs)8172026/10/01 09:53:22 OK 20251218171726_add_pins.sql (2.29ms)8182026/10/01 09:53:22 OK 20251218171726_add_pins.sql (2.86ms)8192026/10/01 09:53:22 OK 20251218171726_add_pins.sql (2.21ms)8202026/10/01 09:53:22 OK 20251218171726_add_pins.sql (2.48ms)8212026/10/01 09:53:22 OK 20251218171726_add_pins.sql (2.25ms)8222026/10/01 09:53:22 OK 20260628120000_add_object_size_and_stats.sql (2.02ms)8232026/10/01 09:53:22 OK 20251218171726_add_pins.sql (2.18ms)8242026/10/01 09:53:22 OK 20251218171726_add_pins.sql (2.51ms)8252026/10/01 09:53:22 OK 20260905000000_add_claims.sql (2.96ms)8262026/10/01 09:53:22 OK 20251218171726_add_pins.sql (2.29ms)8272026/10/01 09:53:22 OK 20260920000000_drop_claims.sql (1.3ms)8282026/10/01 09:53:22 OK 20260628120000_add_object_size_and_stats.sql (10.19ms)8292026/10/01 09:53:22 OK 20260628120000_add_object_size_and_stats.sql (9.86ms)8302026/10/01 09:53:22 OK 20260628120000_add_object_size_and_stats.sql (10.17ms)8312026/10/01 09:53:22 OK 20260628120000_add_object_size_and_stats.sql (10.03ms)8322026/10/01 09:53:22 OK 20260628120000_add_object_size_and_stats.sql (9.91ms)8332026/10/01 09:53:22 OK 20260923120000_add_pushes.sql (8.33ms)8342026/10/01 09:53:22 goose: successfully migrated database to version: 202609231200008352026/10/01 09:53:22 OK 20260628120000_add_object_size_and_stats.sql (10.65ms)8362026/10/01 09:53:22 OK 20260628120000_add_object_size_and_stats.sql (9.97ms)8372026/10/01 09:53:22 OK 20260628120000_add_object_size_and_stats.sql (11.77ms)8382026/10/01 09:53:22 OK 20260905000000_add_claims.sql (12.83ms)8392026/10/01 09:53:22 OK 1_commit_pending_closure.sql (2.58ms)8402026/10/01 09:53:22 OK 20260905000000_add_claims.sql (3.78ms)8412026/10/01 09:53:22 OK 2_object_stats_trigger.sql (628.75µs)8422026/10/01 09:53:22 OK 20260905000000_add_claims.sql (4.31ms)8432026/10/01 09:53:22 OK 3_commit_push.sql (608.79µs)8442026/10/01 09:53:22 OK 20260905000000_add_claims.sql (4.45ms)8452026/10/01 09:53:22 goose: up to current file version: 38462026/10/01 09:53:22 OK 20260905000000_add_claims.sql (3.82ms)8472026/10/01 09:53:22 OK 20260905000000_add_claims.sql (4.76ms)8482026/10/01 09:53:22 OK 20260905000000_add_claims.sql (4.83ms)8492026/10/01 09:53:22 OK 20260920000000_drop_claims.sql (1.99ms)8502026/10/01 09:53:22 OK 20260905000000_add_claims.sql (4.11ms)8512026/10/01 09:53:22 OK 20260905000000_add_claims.sql (2.8ms)8522026/10/01 09:53:22 OK 20260920000000_drop_claims.sql (1.68ms)8532026/10/01 09:53:22 OK 20260920000000_drop_claims.sql (1.73ms)8542026/10/01 09:53:22 OK 20260923120000_add_pushes.sql (1.39ms)8552026/10/01 09:53:22 goose: successfully migrated database to version: 202609231200008562026/10/01 09:53:22 OK 20260920000000_drop_claims.sql (1.78ms)8572026/10/01 09:53:22 OK 20260923120000_add_pushes.sql (1.22ms)8582026/10/01 09:53:22 goose: successfully migrated database to version: 202609231200008592026/10/01 09:53:22 OK 20260920000000_drop_claims.sql (2.16ms)8602026/10/01 09:53:22 OK 20260920000000_drop_claims.sql (2.06ms)8612026/10/01 09:53:22 OK 20260920000000_drop_claims.sql (2.18ms)8622026/10/01 09:53:22 OK 20260920000000_drop_claims.sql (1.95ms)8632026/10/01 09:53:22 OK 20260923120000_add_pushes.sql (1.15ms)8642026/10/01 09:53:22 goose: successfully migrated database to version: 202609231200008652026/10/01 09:53:22 OK 20260920000000_drop_claims.sql (1.99ms)8662026/10/01 09:53:22 OK 20260923120000_add_pushes.sql (1.14ms)8672026/10/01 09:53:22 goose: successfully migrated database to version: 202609231200008682026/10/01 09:53:22 OK 20260923120000_add_pushes.sql (1.2ms)8692026/10/01 09:53:22 goose: successfully migrated database to version: 202609231200008702026/10/01 09:53:22 OK 20260923120000_add_pushes.sql (1.01ms)8712026/10/01 09:53:22 goose: successfully migrated database to version: 202609231200008722026/10/01 09:53:22 OK 20260923120000_add_pushes.sql (1.12ms)8732026/10/01 09:53:22 goose: successfully migrated database to version: 202609231200008742026/10/01 09:53:22 OK 20260923120000_add_pushes.sql (1.06ms)8752026/10/01 09:53:22 goose: successfully migrated database to version: 202609231200008762026/10/01 09:53:22 OK 1_commit_pending_closure.sql (1.61ms)8772026/10/01 09:53:22 OK 1_commit_pending_closure.sql (1.85ms)8782026/10/01 09:53:22 OK 20260923120000_add_pushes.sql (1.13ms)8792026/10/01 09:53:22 goose: successfully migrated database to version: 202609231200008802026/10/01 09:53:22 OK 2_object_stats_trigger.sql (453.17µs)8812026/10/01 09:53:22 OK 2_object_stats_trigger.sql (472.71µs)8822026/10/01 09:53:22 OK 1_commit_pending_closure.sql (1.87ms)8832026/10/01 09:53:22 OK 3_commit_push.sql (487.54µs)8842026/10/01 09:53:22 goose: up to current file version: 38852026/10/01 09:53:22 OK 3_commit_push.sql (408.38µs)8862026/10/01 09:53:22 goose: up to current file version: 38872026/10/01 09:53:22 OK 1_commit_pending_closure.sql (1.49ms)8882026/10/01 09:53:22 OK 1_commit_pending_closure.sql (1.62ms)8892026/10/01 09:53:22 OK 1_commit_pending_closure.sql (1.86ms)8902026/10/01 09:53:22 OK 2_object_stats_trigger.sql (498.88µs)8912026/10/01 09:53:22 OK 1_commit_pending_closure.sql (1.48ms)8922026/10/01 09:53:22 OK 2_object_stats_trigger.sql (325.42µs)8932026/10/01 09:53:22 OK 2_object_stats_trigger.sql (423.83µs)8942026/10/01 09:53:22 OK 1_commit_pending_closure.sql (1.8ms)8952026/10/01 09:53:22 OK 1_commit_pending_closure.sql (1.5ms)8962026/10/01 09:53:22 OK 3_commit_push.sql (366.25µs)8972026/10/01 09:53:22 goose: up to current file version: 38982026/10/01 09:53:22 OK 2_object_stats_trigger.sql (376.29µs)8992026/10/01 09:53:22 OK 3_commit_push.sql (301.67µs)9002026/10/01 09:53:22 goose: up to current file version: 39012026/10/01 09:53:22 OK 3_commit_push.sql (310.46µs)9022026/10/01 09:53:22 goose: up to current file version: 39032026/10/01 09:53:22 OK 2_object_stats_trigger.sql (602.46µs)9042026/10/01 09:53:22 OK 2_object_stats_trigger.sql (340.08µs)9052026/10/01 09:53:22 OK 2_object_stats_trigger.sql (289.96µs)9062026/10/01 09:53:22 OK 3_commit_push.sql (286.42µs)9072026/10/01 09:53:22 goose: up to current file version: 39082026/10/01 09:53:22 OK 3_commit_push.sql (207.67µs)9092026/10/01 09:53:22 goose: up to current file version: 39102026/10/01 09:53:22 OK 3_commit_push.sql (226.25µs)9112026/10/01 09:53:22 goose: up to current file version: 39122026/10/01 09:53:22 OK 3_commit_push.sql (280.38µs)9132026/10/01 09:53:22 goose: up to current file version: 39142026/10/01 09:53:22 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"915--- PASS: TestService_AuthMiddleware (1.17s)916=== CONT TestReadProxyNarinfo9172026/10/01 09:53:22 INFO Received uploads request method=POST path=/api/pending_closures9182026/10/01 09:53:22 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9192026/10/01 09:53:22 INFO Received uploads request method=POST path=/api/pending_closures920--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.41s)921=== CONT TestPush_SignsNarinfosOfItsPendingObjects922--- PASS: TestService_Rustfstest (1.56s)923=== CONT TestPush_RejectsBadRequests9242026/10/01 09:53:22 INFO Received uploads request method=POST path=/api/pending_closures9252026/10/01 09:53:23 INFO Received uploads request method=POST path=/api/pending_closures9262026/10/01 09:53:23 INFO Received uploads request method=POST path=/api/pending_closures9272026/10/01 09:53:23 INFO Received uploads request method=POST path=/api/pending_closures9282026/10/01 09:53:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9292026-10-01 09:53:23.616 UTC [92130] ERROR: relation "goose_db_version" does not exist at character 369302026-10-01 09:53:23.616 UTC [92130] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9312026/10/01 09:53:23 INFO Received uploads request method=POST path=/api/pending_closures932--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.61s)933=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9342026/10/01 09:53:23 OK 20241026095416_initial_model.sql (113.55ms)9352026/10/01 09:53:23 OK 20251210153512_drop_unused_gin_index.sql (9.62ms)9362026/10/01 09:53:23 OK 20251218171726_add_pins.sql (31.07ms)9372026/10/01 09:53:23 OK 20260628120000_add_object_size_and_stats.sql (29.61ms)9382026-10-01 09:53:23.859 UTC [92134] ERROR: relation "goose_db_version" does not exist at character 369392026-10-01 09:53:23.859 UTC [92134] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9402026/10/01 09:53:23 OK 20260905000000_add_claims.sql (34.39ms)9412026-10-01 09:53:23.879 UTC [92135] ERROR: relation "goose_db_version" does not exist at character 369422026-10-01 09:53:23.879 UTC [92135] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9432026/10/01 09:53:23 OK 20260920000000_drop_claims.sql (6.83ms)9442026/10/01 09:53:23 OK 20260923120000_add_pushes.sql (10.16ms)9452026/10/01 09:53:23 goose: successfully migrated database to version: 202609231200009462026/10/01 09:53:23 OK 1_commit_pending_closure.sql (1.78ms)9472026/10/01 09:53:23 OK 2_object_stats_trigger.sql (399.33µs)9482026/10/01 09:53:23 OK 3_commit_push.sql (335.42µs)9492026/10/01 09:53:23 goose: up to current file version: 39502026/10/01 09:53:23 INFO Received uploads request method=POST path=/api/pending_closures9512026/10/01 09:53:24 OK 20241026095416_initial_model.sql (172.52ms)9522026/10/01 09:53:24 OK 20251210153512_drop_unused_gin_index.sql (18.09ms)9532026/10/01 09:53:24 OK 20241026095416_initial_model.sql (176.09ms)9542026/10/01 09:53:24 OK 20251210153512_drop_unused_gin_index.sql (11.24ms)9552026/10/01 09:53:24 OK 20251218171726_add_pins.sql (47.27ms)9562026/10/01 09:53:24 OK 20251218171726_add_pins.sql (33.88ms)9572026/10/01 09:53:24 OK 20260628120000_add_object_size_and_stats.sql (20.78ms)9582026/10/01 09:53:24 OK 20260628120000_add_object_size_and_stats.sql (36.92ms)9592026/10/01 09:53:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9602026/10/01 09:53:24 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTE0MDFjNWUtNGVlNi00YjNjLTkxOWItN2VmZDUyMjNkMTc5LjcwMDA3ZjA2LWRlZDItNDFhNC1iOGI5LWU3NDkzMzcwZTMwNngxNzkwODQ4NDAzOTM3MjM2MDAw9612026/10/01 09:53:24 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTE0MDFjNWUtNGVlNi00YjNjLTkxOWItN2VmZDUyMjNkMTc5LjcwMDA3ZjA2LWRlZDItNDFhNC1iOGI5LWU3NDkzMzcwZTMwNngxNzkwODQ4NDAzOTM3MjM2MDAw parts=1962--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (3.08s)963=== CONT TestPush_CompleteCommitsEveryRoot9642026/10/01 09:53:24 INFO Received uploads request method=POST path=/api/pending_closures9652026/10/01 09:53:24 OK 20260905000000_add_claims.sql (64.91ms)9662026/10/01 09:53:24 OK 20260905000000_add_claims.sql (65.06ms)9672026/10/01 09:53:24 OK 20260920000000_drop_claims.sql (56.87ms)9682026/10/01 09:53:24 OK 20260920000000_drop_claims.sql (57.03ms)9692026/10/01 09:53:24 OK 20260923120000_add_pushes.sql (4.35ms)9702026/10/01 09:53:24 goose: successfully migrated database to version: 202609231200009712026/10/01 09:53:24 OK 20260923120000_add_pushes.sql (4.48ms)9722026/10/01 09:53:24 goose: successfully migrated database to version: 202609231200009732026/10/01 09:53:24 OK 1_commit_pending_closure.sql (5.15ms)9742026/10/01 09:53:24 OK 1_commit_pending_closure.sql (5.19ms)9752026/10/01 09:53:24 OK 2_object_stats_trigger.sql (2.4ms)9762026/10/01 09:53:24 OK 2_object_stats_trigger.sql (2.66ms)9772026/10/01 09:53:24 OK 3_commit_push.sql (752.79µs)9782026/10/01 09:53:24 goose: up to current file version: 39792026/10/01 09:53:24 OK 3_commit_push.sql (766.75µs)9802026/10/01 09:53:24 goose: up to current file version: 39812026/10/01 09:53:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9822026/10/01 09:53:24 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst983--- PASS: TestCompleteMultipartUnregistered (3.34s)984=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9852026/10/01 09:53:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9862026/10/01 09:53:24 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YTE0MDFjNWUtNGVlNi00YjNjLTkxOWItN2VmZDUyMjNkMTc5LjBmZmIyYjljLTExNDQtNGUzNy1hMWMyLTQwYmViZjA2ODkyMHgxNzkwODQ4NDAyOTgyMzAwMDAw parts=129872026/10/01 09:53:24 INFO Received uploads request method=POST path=/api/pending_closures988--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.56s)989=== CONT TestReadRedirectUsesPublicS3URL990--- PASS: TestReadProxyNarinfo (2.58s)991=== CONT TestReadProxyRangeRequest9922026/10/01 09:53:25 INFO Received push request method=POST path=/api/pushes9932026/10/01 09:53:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9942026/10/01 09:53:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9952026/10/01 09:53:25 INFO Signed narinfos id=1 count=1996--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.67s)997=== CONT TestReadRedirectKeepsNarinfoProxied9982026/10/01 09:53:25 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YTE0MDFjNWUtNGVlNi00YjNjLTkxOWItN2VmZDUyMjNkMTc5LmM4NWU0NGEyLWY3ZDQtNDQwMC1hMWZhLWQ4MmNmOTk0ZDEwYXgxNzkwODQ4NDAzNDAxNzYyMDAw parts=12999--- PASS: TestRedundantMultipartUpload (4.10s)1000=== CONT TestReadRedirectNar1001=== RUN TestPush_RejectsBadRequests/no_objects1002=== PAUSE TestPush_RejectsBadRequests/no_objects1003=== RUN TestPush_RejectsBadRequests/bad_root1004=== PAUSE TestPush_RejectsBadRequests/bad_root1005=== RUN TestPush_RejectsBadRequests/root_not_in_objects1006=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1007=== RUN TestPush_RejectsBadRequests/no_roots1008=== PAUSE TestPush_RejectsBadRequests/no_roots1009=== CONT TestReadProxyDisabled10102026-10-01 09:53:25.373 UTC [92150] ERROR: relation "goose_db_version" does not exist at character 3610112026-10-01 09:53:25.373 UTC [92150] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10122026/10/01 09:53:25 OK 20241026095416_initial_model.sql (57.27ms)10132026/10/01 09:53:25 OK 20251210153512_drop_unused_gin_index.sql (989.42µs)10142026/10/01 09:53:25 OK 20251218171726_add_pins.sql (3.53ms)10152026/10/01 09:53:25 OK 20260628120000_add_object_size_and_stats.sql (32.54ms)10162026/10/01 09:53:25 OK 20260905000000_add_claims.sql (26.91ms)10172026/10/01 09:53:25 OK 20260920000000_drop_claims.sql (10.19ms)10182026/10/01 09:53:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10192026/10/01 09:53:25 OK 20260923120000_add_pushes.sql (2.81ms)10202026/10/01 09:53:25 goose: successfully migrated database to version: 2026092312000010212026/10/01 09:53:25 OK 1_commit_pending_closure.sql (47.76ms)10222026/10/01 09:53:25 OK 2_object_stats_trigger.sql (495.75µs)10232026/10/01 09:53:25 OK 3_commit_push.sql (242.08µs)10242026/10/01 09:53:25 goose: up to current file version: 310252026/10/01 09:53:25 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YTE0MDFjNWUtNGVlNi00YjNjLTkxOWItN2VmZDUyMjNkMTc5Ljk1YmQwYTgyLTJmMzktNGZmOC1hMTU1LTVmNzMwMjgxODNlNXgxNzkwODQ4NDA0MjE5OTE1MDAw parts=1010262026/10/01 09:53:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10272026/10/01 09:53:25 INFO Completed upload id=110282026/10/01 09:53:25 INFO Received uploads request method=POST path=/api/pending_closures10292026/10/01 09:53:25 INFO Received uploads request method=POST path=/api/pending_closures10302026/10/01 09:53:25 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10312026/10/01 09:53:25 WARN Found objects in DB but missing from S3, will re-upload count=11032--- PASS: TestService_verifyS3Integrity (4.52s)1033=== CONT TestReadProxyRootRedirectsToIndexHTML10342026/10/01 09:53:25 INFO Received push request method=POST path=/api/pushes10352026-10-01 09:53:25.766 UTC [92155] ERROR: relation "goose_db_version" does not exist at character 3610362026-10-01 09:53:25.766 UTC [92155] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10372026/10/01 09:53:25 INFO Received complete push request method=POST path=/api/pushes/1/complete10382026/10/01 09:53:25 INFO Received push request method=POST path=/api/pushes10392026/10/01 09:53:25 OK 20241026095416_initial_model.sql (25.64ms)10402026/10/01 09:53:25 OK 20251210153512_drop_unused_gin_index.sql (6.71ms)10412026/10/01 09:53:25 OK 20251218171726_add_pins.sql (8.65ms)10422026-10-01 09:53:25.870 UTC [92158] ERROR: relation "goose_db_version" does not exist at character 3610432026-10-01 09:53:25.870 UTC [92158] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10442026-10-01 09:53:25.871 UTC [92159] ERROR: relation "goose_db_version" does not exist at character 3610452026-10-01 09:53:25.871 UTC [92159] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10462026/10/01 09:53:25 OK 20260628120000_add_object_size_and_stats.sql (18.33ms)10472026/10/01 09:53:25 OK 20260905000000_add_claims.sql (4.55ms)10482026/10/01 09:53:25 OK 20260920000000_drop_claims.sql (2.58ms)10492026/10/01 09:53:25 OK 20260923120000_add_pushes.sql (1.8ms)10502026/10/01 09:53:25 goose: successfully migrated database to version: 2026092312000010512026/10/01 09:53:25 OK 1_commit_pending_closure.sql (1.66ms)10522026/10/01 09:53:25 OK 2_object_stats_trigger.sql (550.42µs)10532026/10/01 09:53:25 OK 3_commit_push.sql (401.5µs)10542026/10/01 09:53:25 goose: up to current file version: 310552026/10/01 09:53:25 INFO Aborted multipart uploads count=010562026/10/01 09:53:25 WARN Force mode enabled - objects will be deleted immediately without grace period10572026/10/01 09:53:25 OK 20241026095416_initial_model.sql (39.05ms)10582026/10/01 09:53:25 OK 20241026095416_initial_model.sql (39.64ms)10592026/10/01 09:53:25 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=010602026/10/01 09:53:25 OK 20251210153512_drop_unused_gin_index.sql (8.38ms)10612026/10/01 09:53:25 OK 20251210153512_drop_unused_gin_index.sql (8.39ms)10622026/10/01 09:53:25 INFO Vacuumed table table=pending_closures10632026/10/01 09:53:25 OK 20251218171726_add_pins.sql (35.49ms)10642026/10/01 09:53:25 INFO Vacuumed table table=pending_objects10652026/10/01 09:53:25 OK 20251218171726_add_pins.sql (41.27ms)10662026/10/01 09:53:25 INFO Vacuumed table table=multipart_uploads10672026/10/01 09:53:25 OK 20260628120000_add_object_size_and_stats.sql (25.11ms)10682026/10/01 09:53:25 OK 20260628120000_add_object_size_and_stats.sql (22.61ms)10692026/10/01 09:53:26 INFO Vacuumed table table=closures10702026/10/01 09:53:26 OK 20260905000000_add_claims.sql (18.83ms)10712026/10/01 09:53:26 INFO Vacuumed table table=objects10722026/10/01 09:53:26 INFO Received complete push request method=POST path=/api/pushes/2/complete10732026/10/01 09:53:26 OK 20260905000000_add_claims.sql (17.75ms)1074--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.29s)1075=== CONT TestReadProxyConditionalGet10762026/10/01 09:53:26 OK 20260920000000_drop_claims.sql (18.08ms)10772026/10/01 09:53:26 OK 20260920000000_drop_claims.sql (16.51ms)10782026/10/01 09:53:26 OK 20260923120000_add_pushes.sql (9.17ms)10792026/10/01 09:53:26 goose: successfully migrated database to version: 2026092312000010802026/10/01 09:53:26 OK 20260923120000_add_pushes.sql (10.99ms)10812026/10/01 09:53:26 goose: successfully migrated database to version: 2026092312000010822026/10/01 09:53:26 OK 1_commit_pending_closure.sql (1.62ms)10832026/10/01 09:53:26 OK 2_object_stats_trigger.sql (257.04µs)10842026/10/01 09:53:26 OK 3_commit_push.sql (214.54µs)10852026/10/01 09:53:26 goose: up to current file version: 310862026/10/01 09:53:26 OK 1_commit_pending_closure.sql (1.1ms)10872026/10/01 09:53:26 OK 2_object_stats_trigger.sql (261.79µs)10882026/10/01 09:53:26 OK 3_commit_push.sql (205.83µs)10892026/10/01 09:53:26 goose: up to current file version: 310902026/10/01 09:53:26 INFO Received push request method=POST path=/api/pushes10912026/10/01 09:53:26 INFO Received complete push request method=POST path=/api/pushes/1/complete10922026-10-01 09:53:26.225 UTC [92162] ERROR: relation "goose_db_version" does not exist at character 3610932026-10-01 09:53:26.225 UTC [92162] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1094--- PASS: TestPush_CompleteCommitsEveryRoot (2.07s)1095=== CONT TestReadProxyHead10962026/10/01 09:53:26 OK 20241026095416_initial_model.sql (105.37ms)10972026/10/01 09:53:26 OK 20251210153512_drop_unused_gin_index.sql (9.18ms)1098--- PASS: TestReadRedirectUsesPublicS3URL (1.73s)1099=== CONT TestReadProxyInvalidPath11002026/10/01 09:53:26 OK 20251218171726_add_pins.sql (36.81ms)11012026/10/01 09:53:26 OK 20260628120000_add_object_size_and_stats.sql (60.35ms)11022026/10/01 09:53:26 OK 20260905000000_add_claims.sql (21ms)11032026/10/01 09:53:26 OK 20260920000000_drop_claims.sql (16.89ms)11042026/10/01 09:53:26 OK 20260923120000_add_pushes.sql (11.35ms)11052026/10/01 09:53:26 goose: successfully migrated database to version: 2026092312000011062026/10/01 09:53:26 OK 1_commit_pending_closure.sql (3.4ms)11072026/10/01 09:53:26 OK 2_object_stats_trigger.sql (776.33µs)11082026/10/01 09:53:26 OK 3_commit_push.sql (394.54µs)11092026/10/01 09:53:26 goose: up to current file version: 311102026-10-01 09:53:26.587 UTC [92172] ERROR: relation "goose_db_version" does not exist at character 3611112026-10-01 09:53:26.587 UTC [92172] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11122026/10/01 09:53:26 INFO Received push request method=POST path=/api/pushes11132026-10-01 09:53:26.618 UTC [92173] ERROR: relation "goose_db_version" does not exist at character 3611142026-10-01 09:53:26.618 UTC [92173] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11152026-10-01 09:53:26.686 UTC [92174] ERROR: relation "goose_db_version" does not exist at character 3611162026-10-01 09:53:26.686 UTC [92174] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1117--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.23s)1118=== CONT TestReadProxy40411192026/10/01 09:53:26 OK 20241026095416_initial_model.sql (132.23ms)11202026/10/01 09:53:26 OK 20251210153512_drop_unused_gin_index.sql (7.6ms)11212026/10/01 09:53:26 OK 20251218171726_add_pins.sql (18.39ms)11222026/10/01 09:53:26 OK 20260628120000_add_object_size_and_stats.sql (12.71ms)11232026/10/01 09:53:26 OK 20241026095416_initial_model.sql (97.22ms)11242026/10/01 09:53:26 OK 20251210153512_drop_unused_gin_index.sql (8.39ms)11252026/10/01 09:53:26 OK 20251218171726_add_pins.sql (15.35ms)11262026/10/01 09:53:26 OK 20241026095416_initial_model.sql (88.64ms)11272026/10/01 09:53:26 OK 20260905000000_add_claims.sql (31.07ms)11282026/10/01 09:53:26 OK 20251210153512_drop_unused_gin_index.sql (6.66ms)11292026/10/01 09:53:26 OK 20260920000000_drop_claims.sql (18.58ms)11302026/10/01 09:53:26 OK 20260923120000_add_pushes.sql (8.25ms)11312026/10/01 09:53:26 goose: successfully migrated database to version: 2026092312000011322026/10/01 09:53:26 OK 20260628120000_add_object_size_and_stats.sql (27.2ms)11332026/10/01 09:53:26 OK 1_commit_pending_closure.sql (2.53ms)11342026/10/01 09:53:26 OK 2_object_stats_trigger.sql (516.21µs)11352026/10/01 09:53:26 OK 3_commit_push.sql (335.83µs)11362026/10/01 09:53:26 goose: up to current file version: 311372026/10/01 09:53:26 OK 20251218171726_add_pins.sql (27.3ms)11382026-10-01 09:53:26.862 UTC [92179] ERROR: relation "goose_db_version" does not exist at character 3611392026-10-01 09:53:26.862 UTC [92179] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11402026/10/01 09:53:26 OK 20260905000000_add_claims.sql (25.59ms)1141--- PASS: TestReadProxyRangeRequest (2.04s)1142=== CONT TestReadProxyNarStreaming11432026/10/01 09:53:26 OK 20260628120000_add_object_size_and_stats.sql (42.67ms)11442026/10/01 09:53:26 OK 20260920000000_drop_claims.sql (45.28ms)11452026/10/01 09:53:26 OK 20260923120000_add_pushes.sql (13.85ms)11462026/10/01 09:53:26 goose: successfully migrated database to version: 2026092312000011472026/10/01 09:53:26 OK 1_commit_pending_closure.sql (2.14ms)11482026/10/01 09:53:26 OK 2_object_stats_trigger.sql (463.96µs)11492026/10/01 09:53:26 OK 3_commit_push.sql (275.54µs)11502026/10/01 09:53:26 goose: up to current file version: 311512026/10/01 09:53:26 OK 20260905000000_add_claims.sql (51.12ms)11522026/10/01 09:53:26 OK 20260920000000_drop_claims.sql (23.34ms)11532026/10/01 09:53:26 OK 20260923120000_add_pushes.sql (9.25ms)11542026/10/01 09:53:26 goose: successfully migrated database to version: 2026092312000011552026/10/01 09:53:26 OK 1_commit_pending_closure.sql (2.27ms)11562026/10/01 09:53:26 OK 2_object_stats_trigger.sql (398.96µs)11572026/10/01 09:53:26 OK 3_commit_push.sql (344.17µs)11582026/10/01 09:53:26 goose: up to current file version: 311592026/10/01 09:53:27 OK 20241026095416_initial_model.sql (146.71ms)11602026/10/01 09:53:27 OK 20251210153512_drop_unused_gin_index.sql (2.49ms)11612026/10/01 09:53:27 OK 20251218171726_add_pins.sql (33.03ms)11622026/10/01 09:53:27 WARN Rate limiter enabled after throttle name=s3-test rate=511632026/10/01 09:53:27 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1164=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1165 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101166 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001167--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.03s)1168=== CONT TestReadProxyNarinfoAlreadyDecompressed1169--- PASS: TestReadRedirectNar (1.95s)1170=== CONT TestService_createPendingClosureHandler11712026/10/01 09:53:27 OK 20260628120000_add_object_size_and_stats.sql (54.85ms)11722026/10/01 09:53:27 OK 20260905000000_add_claims.sql (52.82ms)11732026/10/01 09:53:27 OK 20260920000000_drop_claims.sql (28.4ms)11742026/10/01 09:53:27 OK 20260923120000_add_pushes.sql (6.02ms)11752026/10/01 09:53:27 goose: successfully migrated database to version: 2026092312000011762026/10/01 09:53:27 OK 1_commit_pending_closure.sql (2.53ms)11772026/10/01 09:53:27 OK 2_object_stats_trigger.sql (1.11ms)11782026/10/01 09:53:27 OK 3_commit_push.sql (589.83µs)11792026/10/01 09:53:27 goose: up to current file version: 31180--- PASS: TestReadProxyDisabled (1.99s)1181=== CONT TestSkippedUploadsHandler11822026/10/01 09:53:27 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001183--- PASS: TestSkippedUploadsHandler (0.00s)1184=== CONT TestGCSweepSkipsPendingObjects11852026-10-01 09:53:27.350 UTC [92186] ERROR: relation "goose_db_version" does not exist at character 3611862026-10-01 09:53:27.350 UTC [92186] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11872026/10/01 09:53:27 OK 20241026095416_initial_model.sql (76.76ms)11882026/10/01 09:53:27 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)11892026/10/01 09:53:27 OK 20251218171726_add_pins.sql (23.34ms)11902026/10/01 09:53:27 OK 20260628120000_add_object_size_and_stats.sql (25.9ms)11912026-10-01 09:53:27.537 UTC [92189] ERROR: relation "goose_db_version" does not exist at character 3611922026-10-01 09:53:27.537 UTC [92189] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1193--- PASS: TestReadRedirectKeepsNarinfoProxied (2.40s)1194=== CONT TestGenerateLandingPage1195--- PASS: TestGenerateLandingPage (0.00s)1196=== CONT TestService_readinessHandler11972026/10/01 09:53:27 OK 20260905000000_add_claims.sql (43.38ms)11982026/10/01 09:53:27 OK 20260920000000_drop_claims.sql (40.98ms)11992026/10/01 09:53:27 OK 20260923120000_add_pushes.sql (16.49ms)12002026/10/01 09:53:27 goose: successfully migrated database to version: 2026092312000012012026/10/01 09:53:27 OK 1_commit_pending_closure.sql (2.33ms)12022026/10/01 09:53:27 OK 2_object_stats_trigger.sql (405.17µs)12032026/10/01 09:53:27 OK 3_commit_push.sql (323.08µs)12042026/10/01 09:53:27 goose: up to current file version: 312052026/10/01 09:53:27 OK 20241026095416_initial_model.sql (95.68ms)12062026/10/01 09:53:27 OK 20251210153512_drop_unused_gin_index.sql (8.01ms)12072026/10/01 09:53:27 OK 20251218171726_add_pins.sql (15.8ms)1208--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.13s)1209=== CONT TestService_healthCheckHandler12102026/10/01 09:53:27 OK 20260628120000_add_object_size_and_stats.sql (70.93ms)12112026/10/01 09:53:27 OK 20260905000000_add_claims.sql (57.31ms)12122026-10-01 09:53:27.878 UTC [92192] ERROR: relation "goose_db_version" does not exist at character 3612132026-10-01 09:53:27.878 UTC [92192] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12142026/10/01 09:53:27 OK 20260920000000_drop_claims.sql (57.64ms)12152026/10/01 09:53:27 OK 20260923120000_add_pushes.sql (23.75ms)12162026/10/01 09:53:27 goose: successfully migrated database to version: 2026092312000012172026/10/01 09:53:27 OK 1_commit_pending_closure.sql (1.81ms)12182026/10/01 09:53:27 OK 2_object_stats_trigger.sql (390.92µs)12192026/10/01 09:53:27 OK 3_commit_push.sql (312.92µs)12202026/10/01 09:53:27 goose: up to current file version: 312212026/10/01 09:53:28 OK 20241026095416_initial_model.sql (146.06ms)12222026/10/01 09:53:28 OK 20251210153512_drop_unused_gin_index.sql (7.96ms)12232026/10/01 09:53:28 OK 20251218171726_add_pins.sql (41.86ms)1224--- PASS: TestReadProxyConditionalGet (2.11s)1225=== CONT TestGracefulShutdownDrainsInflight12262026/10/01 09:53:28 INFO Starting HTTP server address=127.0.0.1:5627512272026/10/01 09:53:28 INFO Shutdown signal received, draining in-flight requests timeout=10s12282026/10/01 09:53:28 OK 20260628120000_add_object_size_and_stats.sql (49.64ms)1229--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1230=== CONT TestGCTaskStore_Fail1231--- PASS: TestGCTaskStore_Fail (0.00s)1232=== CONT TestGCTaskStore_PhaseUpdates1233--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1234=== CONT TestGCTaskStore_CompletedAllowsNewTask1235--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1236=== CONT TestGCTaskStore_GetReturnsLatest1237--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1238=== CONT TestGCTaskStore_GetEmpty1239--- PASS: TestGCTaskStore_GetEmpty (0.00s)1240=== CONT TestGCTaskStore_ConflictDifferentParams1241--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1242=== CONT TestGCTaskStore_DeduplicateSameParams1243--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1244=== CONT TestGCTaskStore_StartNew1245--- PASS: TestGCTaskStore_StartNew (0.00s)1246=== CONT TestGCEndsOnShutdown12472026/10/01 09:53:28 OK 20260905000000_add_claims.sql (113.75ms)12482026/10/01 09:53:28 OK 20260920000000_drop_claims.sql (66.07ms)12492026/10/01 09:53:28 OK 20260923120000_add_pushes.sql (34.6ms)12502026/10/01 09:53:28 goose: successfully migrated database to version: 2026092312000012512026/10/01 09:53:28 OK 1_commit_pending_closure.sql (6.43ms)12522026/10/01 09:53:28 OK 2_object_stats_trigger.sql (1.09ms)12532026/10/01 09:53:28 OK 3_commit_push.sql (561.54µs)12542026/10/01 09:53:28 goose: up to current file version: 31255--- PASS: TestReadProxyHead (2.26s)1256=== CONT TestCommitRacingPendingCleanupKeepsObjects12572026-10-01 09:53:28.648 UTC [92197] ERROR: relation "goose_db_version" does not exist at character 3612582026-10-01 09:53:28.648 UTC [92197] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1259--- PASS: TestReadProxyInvalidPath (2.49s)1260=== CONT TestPushWaitsForSweepHoldingRow12612026-10-01 09:53:28.958 UTC [92202] ERROR: relation "goose_db_version" does not exist at character 3612622026-10-01 09:53:28.958 UTC [92202] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12632026/10/01 09:53:28 OK 20241026095416_initial_model.sql (238.15ms)12642026/10/01 09:53:28 OK 20251210153512_drop_unused_gin_index.sql (16.62ms)12652026/10/01 09:53:29 OK 20251218171726_add_pins.sql (31.81ms)12662026/10/01 09:53:29 OK 20260628120000_add_object_size_and_stats.sql (11.4ms)12672026-10-01 09:53:29.029 UTC [92203] ERROR: relation "goose_db_version" does not exist at character 3612682026-10-01 09:53:29.029 UTC [92203] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12692026/10/01 09:53:29 OK 20260905000000_add_claims.sql (39.87ms)12702026-10-01 09:53:29.087 UTC [92204] ERROR: relation "goose_db_version" does not exist at character 3612712026-10-01 09:53:29.087 UTC [92204] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12722026/10/01 09:53:29 OK 20260920000000_drop_claims.sql (23.13ms)12732026/10/01 09:53:29 OK 20241026095416_initial_model.sql (77.51ms)12742026/10/01 09:53:29 OK 20260923120000_add_pushes.sql (4.75ms)12752026/10/01 09:53:29 goose: successfully migrated database to version: 2026092312000012762026/10/01 09:53:29 OK 1_commit_pending_closure.sql (3.6ms)12772026/10/01 09:53:29 OK 2_object_stats_trigger.sql (628µs)12782026/10/01 09:53:29 OK 3_commit_push.sql (368.58µs)12792026/10/01 09:53:29 goose: up to current file version: 312802026/10/01 09:53:29 OK 20251210153512_drop_unused_gin_index.sql (11.71ms)12812026/10/01 09:53:29 OK 20251218171726_add_pins.sql (39.81ms)12822026/10/01 09:53:29 OK 20260628120000_add_object_size_and_stats.sql (30.62ms)12832026-10-01 09:53:29.208 UTC [92205] ERROR: relation "goose_db_version" does not exist at character 3612842026-10-01 09:53:29.208 UTC [92205] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12852026/10/01 09:53:29 OK 20260905000000_add_claims.sql (88.23ms)12862026/10/01 09:53:29 OK 20241026095416_initial_model.sql (176.89ms)12872026/10/01 09:53:29 OK 20251210153512_drop_unused_gin_index.sql (19.12ms)12882026/10/01 09:53:29 OK 20251218171726_add_pins.sql (28.13ms)12892026/10/01 09:53:29 OK 20260920000000_drop_claims.sql (56.55ms)12902026/10/01 09:53:29 OK 20260923120000_add_pushes.sql (13.16ms)12912026/10/01 09:53:29 goose: successfully migrated database to version: 2026092312000012922026/10/01 09:53:29 OK 1_commit_pending_closure.sql (5.22ms)12932026/10/01 09:53:29 OK 2_object_stats_trigger.sql (2.09ms)12942026/10/01 09:53:29 OK 3_commit_push.sql (643.13µs)12952026/10/01 09:53:29 goose: up to current file version: 312962026/10/01 09:53:29 OK 20260628120000_add_object_size_and_stats.sql (37.55ms)12972026/10/01 09:53:29 OK 20241026095416_initial_model.sql (227.77ms)12982026/10/01 09:53:29 OK 20251210153512_drop_unused_gin_index.sql (9.26ms)12992026/10/01 09:53:29 OK 20260905000000_add_claims.sql (73.44ms)13002026/10/01 09:53:29 OK 20251218171726_add_pins.sql (43.2ms)13012026/10/01 09:53:29 OK 20260920000000_drop_claims.sql (29.4ms)1302--- PASS: TestReadProxy404 (2.75s)1303=== CONT TestSweepRechecksPendingAfterLocking13042026/10/01 09:53:29 OK 20260628120000_add_object_size_and_stats.sql (47.25ms)13052026/10/01 09:53:29 OK 20260923120000_add_pushes.sql (25.24ms)13062026/10/01 09:53:29 goose: successfully migrated database to version: 2026092312000013072026/10/01 09:53:29 OK 1_commit_pending_closure.sql (2.55ms)13082026/10/01 09:53:29 OK 2_object_stats_trigger.sql (574.83µs)13092026/10/01 09:53:29 OK 3_commit_push.sql (427.13µs)13102026/10/01 09:53:29 goose: up to current file version: 313112026/10/01 09:53:29 OK 20241026095416_initial_model.sql (253.4ms)13122026/10/01 09:53:29 OK 20260905000000_add_claims.sql (76.49ms)13132026/10/01 09:53:29 OK 20251210153512_drop_unused_gin_index.sql (4.5ms)13142026/10/01 09:53:29 OK 20260920000000_drop_claims.sql (4.8ms)13152026/10/01 09:53:29 OK 20260923120000_add_pushes.sql (6.31ms)13162026/10/01 09:53:29 goose: successfully migrated database to version: 2026092312000013172026/10/01 09:53:29 OK 20251218171726_add_pins.sql (8.55ms)13182026/10/01 09:53:29 OK 1_commit_pending_closure.sql (2.92ms)13192026/10/01 09:53:29 OK 2_object_stats_trigger.sql (590.33µs)13202026/10/01 09:53:29 OK 3_commit_push.sql (386.42µs)13212026/10/01 09:53:29 goose: up to current file version: 313222026/10/01 09:53:29 OK 20260628120000_add_object_size_and_stats.sql (29.34ms)13232026/10/01 09:53:29 OK 20260905000000_add_claims.sql (17.43ms)13242026/10/01 09:53:29 OK 20260920000000_drop_claims.sql (68.26ms)13252026/10/01 09:53:29 OK 20260923120000_add_pushes.sql (20.01ms)13262026/10/01 09:53:29 goose: successfully migrated database to version: 2026092312000013272026/10/01 09:53:29 OK 1_commit_pending_closure.sql (5.66ms)13282026/10/01 09:53:29 OK 2_object_stats_trigger.sql (1.72ms)13292026/10/01 09:53:29 OK 3_commit_push.sql (811.5µs)13302026/10/01 09:53:29 goose: up to current file version: 313312026-10-01 09:53:29.787 UTC [92208] ERROR: relation "goose_db_version" does not exist at character 3613322026-10-01 09:53:29.787 UTC [92208] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1333--- PASS: TestReadProxyNarStreaming (2.97s)1334=== CONT TestGetExistingObjectsLocksRows13352026/10/01 09:53:30 OK 20241026095416_initial_model.sql (192ms)13362026/10/01 09:53:30 OK 20251210153512_drop_unused_gin_index.sql (6.38ms)13372026/10/01 09:53:30 OK 20251218171726_add_pins.sql (140.41ms)13382026-10-01 09:53:30.247 UTC [92211] ERROR: relation "goose_db_version" does not exist at character 3613392026-10-01 09:53:30.247 UTC [92211] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1340--- PASS: TestReadProxyNarinfoAlreadyDecompressed (3.14s)1341=== CONT TestRegisterCompletedObjectNeedsPendingRow13422026/10/01 09:53:30 OK 20260628120000_add_object_size_and_stats.sql (54.5ms)13432026/10/01 09:53:30 OK 20260905000000_add_claims.sql (78.71ms)13442026/10/01 09:53:30 OK 20260920000000_drop_claims.sql (62.01ms)13452026/10/01 09:53:30 OK 20260923120000_add_pushes.sql (28.27ms)13462026/10/01 09:53:30 goose: successfully migrated database to version: 2026092312000013472026/10/01 09:53:30 OK 1_commit_pending_closure.sql (4.81ms)13482026/10/01 09:53:30 OK 2_object_stats_trigger.sql (835.79µs)13492026/10/01 09:53:30 OK 3_commit_push.sql (560.33µs)13502026/10/01 09:53:30 goose: up to current file version: 313512026/10/01 09:53:30 OK 20241026095416_initial_model.sql (222.2ms)13522026/10/01 09:53:30 OK 20251210153512_drop_unused_gin_index.sql (6.33ms)13532026/10/01 09:53:30 OK 20251218171726_add_pins.sql (32.43ms)13542026/10/01 09:53:30 INFO Received uploads request method=POST path=/api/pending_closures13552026/10/01 09:53:30 INFO Received uploads request method=POST path=/api/pending_closures13562026/10/01 09:53:30 INFO Received uploads request method=POST path=/api/pending_closures13572026/10/01 09:53:30 OK 20260628120000_add_object_size_and_stats.sql (65.18ms)13582026/10/01 09:53:30 OK 20260905000000_add_claims.sql (92.43ms)13592026/10/01 09:53:30 OK 20260920000000_drop_claims.sql (29.89ms)13602026/10/01 09:53:30 OK 20260923120000_add_pushes.sql (9.98ms)13612026/10/01 09:53:30 goose: successfully migrated database to version: 2026092312000013622026/10/01 09:53:30 OK 1_commit_pending_closure.sql (3.14ms)13632026/10/01 09:53:30 OK 2_object_stats_trigger.sql (736.88µs)13642026/10/01 09:53:30 OK 3_commit_push.sql (383.42µs)13652026/10/01 09:53:30 goose: up to current file version: 313662026-10-01 09:53:30.856 UTC [92214] ERROR: relation "goose_db_version" does not exist at character 3613672026-10-01 09:53:30.856 UTC [92214] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13682026/10/01 09:53:31 INFO Received uploads request method=POST path=/api/pending_closures13692026-10-01 09:53:31.107 UTC [92215] ERROR: relation "goose_db_version" does not exist at character 3613702026-10-01 09:53:31.107 UTC [92215] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13712026/10/01 09:53:31 INFO Aborted multipart uploads count=013722026/10/01 09:53:31 WARN Force mode enabled - objects will be deleted immediately without grace period13732026/10/01 09:53:31 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=013742026/10/01 09:53:31 INFO Vacuumed table table=pending_closures13752026/10/01 09:53:31 INFO Vacuumed table table=pending_objects13762026/10/01 09:53:31 INFO Vacuumed table table=multipart_uploads13772026/10/01 09:53:31 INFO Vacuumed table table=closures13782026/10/01 09:53:31 INFO Vacuumed table table=objects13792026/10/01 09:53:31 OK 20241026095416_initial_model.sql (307.49ms)13802026/10/01 09:53:31 OK 20251210153512_drop_unused_gin_index.sql (19.6ms)1381--- PASS: TestGCSweepSkipsPendingObjects (3.92s)1382=== CONT TestSweepSkipsRowsLockedByPush13832026/10/01 09:53:31 OK 20251218171726_add_pins.sql (37.46ms)13842026/10/01 09:53:31 OK 20260628120000_add_object_size_and_stats.sql (35.91ms)13852026/10/01 09:53:31 WARN readiness check failed error="closed pool"1386--- PASS: TestService_readinessHandler (3.80s)1387=== CONT TestFailedS3DeleteKeepsTombstone13882026/10/01 09:53:31 OK 20260905000000_add_claims.sql (112.04ms)13892026/10/01 09:53:31 OK 20260920000000_drop_claims.sql (34.43ms)13902026/10/01 09:53:31 OK 20241026095416_initial_model.sql (249.26ms)13912026/10/01 09:53:31 OK 20260923120000_add_pushes.sql (9.37ms)13922026/10/01 09:53:31 goose: successfully migrated database to version: 2026092312000013932026/10/01 09:53:31 OK 20251210153512_drop_unused_gin_index.sql (9.02ms)13942026/10/01 09:53:31 OK 1_commit_pending_closure.sql (4.05ms)13952026/10/01 09:53:31 OK 2_object_stats_trigger.sql (760.79µs)13962026/10/01 09:53:31 OK 3_commit_push.sql (612.33µs)13972026/10/01 09:53:31 goose: up to current file version: 313982026/10/01 09:53:31 OK 20251218171726_add_pins.sql (50.97ms)13992026/10/01 09:53:31 OK 20260628120000_add_object_size_and_stats.sql (45.64ms)14002026-10-01 09:53:31.612 UTC [92221] ERROR: relation "goose_db_version" does not exist at character 3614012026-10-01 09:53:31.612 UTC [92221] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14022026/10/01 09:53:31 OK 20260905000000_add_claims.sql (35.79ms)14032026/10/01 09:53:31 OK 20260920000000_drop_claims.sql (39.49ms)14042026/10/01 09:53:31 OK 20260923120000_add_pushes.sql (24.66ms)14052026/10/01 09:53:31 goose: successfully migrated database to version: 2026092312000014062026/10/01 09:53:31 OK 1_commit_pending_closure.sql (3.93ms)14072026/10/01 09:53:31 OK 2_object_stats_trigger.sql (863.42µs)14082026/10/01 09:53:31 OK 3_commit_push.sql (559.21µs)14092026/10/01 09:53:31 goose: up to current file version: 31410--- PASS: TestService_healthCheckHandler (4.06s)1411=== CONT TestForceGCDuringPushOffersSweptObject1412=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1413=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1414=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1415=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1416=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection14172026/10/01 09:53:31 OK 20241026095416_initial_model.sql (182.99ms)14182026/10/01 09:53:31 OK 20251210153512_drop_unused_gin_index.sql (6.91ms)14192026/10/01 09:53:31 OK 20251218171726_add_pins.sql (23.4ms)14202026/10/01 09:53:31 OK 20260628120000_add_object_size_and_stats.sql (47.77ms)14212026-10-01 09:53:31.976 UTC [92224] ERROR: relation "goose_db_version" does not exist at character 3614222026-10-01 09:53:31.976 UTC [92224] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14232026/10/01 09:53:31 OK 20260905000000_add_claims.sql (17.1ms)14242026/10/01 09:53:32 OK 20260920000000_drop_claims.sql (37.55ms)14252026/10/01 09:53:32 OK 20260923120000_add_pushes.sql (58.97ms)14262026/10/01 09:53:32 goose: successfully migrated database to version: 2026092312000014272026/10/01 09:53:32 OK 1_commit_pending_closure.sql (6.96ms)14282026/10/01 09:53:32 OK 2_object_stats_trigger.sql (886.29µs)14292026/10/01 09:53:32 OK 3_commit_push.sql (514.21µs)14302026/10/01 09:53:32 goose: up to current file version: 31431--- PASS: TestGCEndsOnShutdown (4.00s)1432=== CONT TestGCSweepDeliversEachKeyOnce14332026/10/01 09:53:32 OK 20241026095416_initial_model.sql (189.82ms)14342026/10/01 09:53:32 OK 20251210153512_drop_unused_gin_index.sql (8.43ms)14352026/10/01 09:53:32 OK 20251218171726_add_pins.sql (57.45ms)14362026/10/01 09:53:32 OK 20260628120000_add_object_size_and_stats.sql (42.1ms)14372026-10-01 09:53:32.381 UTC [92227] ERROR: relation "goose_db_version" does not exist at character 3614382026-10-01 09:53:32.381 UTC [92227] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14392026/10/01 09:53:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14402026/10/01 09:53:32 OK 20260905000000_add_claims.sql (64.62ms)14412026/10/01 09:53:32 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YTE0MDFjNWUtNGVlNi00YjNjLTkxOWItN2VmZDUyMjNkMTc5LjIwYTJiYWMwLTIyYjctNGQzZi1hYzc5LTA5NjI5ZTNjYjRiNHgxNzkwODQ4NDEwNjc2MDg2MDAw parts=1014422026/10/01 09:53:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14432026/10/01 09:53:32 OK 20260920000000_drop_claims.sql (54.06ms)14442026/10/01 09:53:32 INFO Completed upload id=114452026/10/01 09:53:32 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014462026/10/01 09:53:32 INFO Received uploads request method=POST path=/api/pending_closures14472026/10/01 09:53:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures14482026/10/01 09:53:32 OK 20260923120000_add_pushes.sql (13.8ms)14492026/10/01 09:53:32 goose: successfully migrated database to version: 2026092312000014502026/10/01 09:53:32 INFO Aborted multipart uploads count=014512026/10/01 09:53:32 OK 1_commit_pending_closure.sql (2.78ms)14522026/10/01 09:53:32 OK 2_object_stats_trigger.sql (627.42µs)14532026/10/01 09:53:32 OK 3_commit_push.sql (357.42µs)14542026/10/01 09:53:32 goose: up to current file version: 314552026/10/01 09:53:32 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=014562026/10/01 09:53:32 INFO Vacuumed table table=pending_closures14572026/10/01 09:53:32 INFO Vacuumed table table=pending_objects14582026/10/01 09:53:32 INFO Vacuumed table table=multipart_uploads14592026/10/01 09:53:32 INFO Aborted multipart uploads count=014602026/10/01 09:53:32 INFO Vacuumed table table=closures14612026/10/01 09:53:32 WARN Force mode enabled - objects will be deleted immediately without grace period14622026/10/01 09:53:32 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=014632026/10/01 09:53:32 INFO Vacuumed table table=objects14642026/10/01 09:53:32 INFO Vacuumed table table=pending_closures14652026/10/01 09:53:32 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001466--- PASS: TestService_createPendingClosureHandler (5.52s)1467=== CONT TestTombstonedObjectOfferedWithoutWaiting14682026/10/01 09:53:32 INFO Vacuumed table table=pending_objects14692026/10/01 09:53:32 INFO Vacuumed table table=multipart_uploads14702026/10/01 09:53:32 OK 20241026095416_initial_model.sql (234.03ms)14712026/10/01 09:53:32 INFO Vacuumed table table=closures14722026/10/01 09:53:32 OK 20251210153512_drop_unused_gin_index.sql (2.37ms)14732026/10/01 09:53:32 INFO Vacuumed table table=objects1474--- PASS: TestCommitRacingPendingCleanupKeepsObjects (4.20s)1475=== CONT TestClientWithDependencies14762026/10/01 09:53:32 OK 20251218171726_add_pins.sql (21.93ms)14772026/10/01 09:53:32 OK 20260628120000_add_object_size_and_stats.sql (32.22ms)14782026/10/01 09:53:32 OK 20260905000000_add_claims.sql (43.89ms)14792026/10/01 09:53:32 INFO Received uploads request method=POST path=/api/pending_closures14802026/10/01 09:53:32 OK 20260920000000_drop_claims.sql (29.08ms)14812026-10-01 09:53:32.828 UTC [92236] ERROR: relation "goose_db_version" does not exist at character 3614822026-10-01 09:53:32.828 UTC [92236] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14832026/10/01 09:53:32 OK 20260923120000_add_pushes.sql (13.14ms)14842026/10/01 09:53:32 goose: successfully migrated database to version: 2026092312000014852026/10/01 09:53:32 OK 1_commit_pending_closure.sql (3.59ms)14862026/10/01 09:53:32 OK 2_object_stats_trigger.sql (852.42µs)14872026/10/01 09:53:32 OK 3_commit_push.sql (427.25µs)14882026/10/01 09:53:32 goose: up to current file version: 314892026/10/01 09:53:32 OK 20241026095416_initial_model.sql (82.35ms)14902026/10/01 09:53:32 OK 20251210153512_drop_unused_gin_index.sql (11.35ms)14912026/10/01 09:53:32 OK 20251218171726_add_pins.sql (14.92ms)14922026/10/01 09:53:33 OK 20260628120000_add_object_size_and_stats.sql (56.56ms)14932026/10/01 09:53:33 OK 20260905000000_add_claims.sql (60.67ms)14942026/10/01 09:53:33 INFO Aborted multipart uploads count=014952026/10/01 09:53:33 WARN Force mode enabled - objects will be deleted immediately without grace period14962026/10/01 09:53:33 OK 20260920000000_drop_claims.sql (74.65ms)14972026/10/01 09:53:33 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=014982026/10/01 09:53:33 OK 20260923120000_add_pushes.sql (28.81ms)14992026/10/01 09:53:33 goose: successfully migrated database to version: 2026092312000015002026/10/01 09:53:33 INFO Vacuumed table table=pending_closures15012026/10/01 09:53:33 INFO Vacuumed table table=pending_objects15022026/10/01 09:53:33 OK 1_commit_pending_closure.sql (8.17ms)15032026/10/01 09:53:33 OK 2_object_stats_trigger.sql (1.9ms)15042026/10/01 09:53:33 INFO Vacuumed table table=multipart_uploads15052026/10/01 09:53:33 INFO Vacuumed table table=closures15062026/10/01 09:53:33 OK 3_commit_push.sql (921.83µs)15072026/10/01 09:53:33 goose: up to current file version: 315082026/10/01 09:53:33 INFO Vacuumed table table=objects1509--- PASS: TestSweepRechecksPendingAfterLocking (3.77s)1510=== CONT TestDeduplicatedObjectsRecordedAsPending15112026-10-01 09:53:33.242 UTC [92240] ERROR: relation "goose_db_version" does not exist at character 3615122026-10-01 09:53:33.242 UTC [92240] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1513--- PASS: TestPushWaitsForSweepHoldingRow (4.43s)1514=== CONT TestPushDedupSurvivesConcurrentGC15152026-10-01 09:53:33.304 UTC [92243] ERROR: relation "goose_db_version" does not exist at character 3615162026-10-01 09:53:33.304 UTC [92243] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1517--- PASS: TestGetExistingObjectsLocksRows (3.50s)1518=== CONT TestGCMetrics15192026/10/01 09:53:33 OK 20241026095416_initial_model.sql (114.38ms)15202026/10/01 09:53:33 OK 20251210153512_drop_unused_gin_index.sql (8.52ms)15212026/10/01 09:53:33 OK 20251218171726_add_pins.sql (17.71ms)15222026/10/01 09:53:33 OK 20241026095416_initial_model.sql (87.24ms)15232026/10/01 09:53:33 OK 20260628120000_add_object_size_and_stats.sql (19.46ms)15242026/10/01 09:53:33 OK 20251210153512_drop_unused_gin_index.sql (2.48ms)15252026/10/01 09:53:33 OK 20251218171726_add_pins.sql (9.81ms)15262026-10-01 09:53:33.454 UTC [92249] ERROR: relation "goose_db_version" does not exist at character 3615272026-10-01 09:53:33.454 UTC [92249] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15282026/10/01 09:53:33 OK 20260905000000_add_claims.sql (32.79ms)15292026/10/01 09:53:33 OK 20260628120000_add_object_size_and_stats.sql (22.5ms)15302026/10/01 09:53:33 OK 20260920000000_drop_claims.sql (19.94ms)15312026/10/01 09:53:33 OK 20260923120000_add_pushes.sql (21.28ms)15322026/10/01 09:53:33 goose: successfully migrated database to version: 2026092312000015332026/10/01 09:53:33 OK 20260905000000_add_claims.sql (45.01ms)15342026/10/01 09:53:33 OK 1_commit_pending_closure.sql (4.92ms)15352026/10/01 09:53:33 OK 2_object_stats_trigger.sql (1.24ms)15362026/10/01 09:53:33 OK 3_commit_push.sql (429.88µs)15372026/10/01 09:53:33 goose: up to current file version: 315382026/10/01 09:53:33 OK 20260920000000_drop_claims.sql (11.41ms)15392026/10/01 09:53:33 OK 20260923120000_add_pushes.sql (21.9ms)15402026/10/01 09:53:33 goose: successfully migrated database to version: 2026092312000015412026/10/01 09:53:33 OK 1_commit_pending_closure.sql (3.67ms)15422026/10/01 09:53:33 OK 2_object_stats_trigger.sql (671.33µs)15432026/10/01 09:53:33 OK 3_commit_push.sql (391.58µs)15442026/10/01 09:53:33 goose: up to current file version: 31545--- PASS: TestRegisterCompletedObjectNeedsPendingRow (3.31s)1546=== CONT TestGCBugBareHashReferences15472026/10/01 09:53:33 OK 20241026095416_initial_model.sql (97.1ms)15482026/10/01 09:53:33 OK 20251210153512_drop_unused_gin_index.sql (9.32ms)15492026/10/01 09:53:33 OK 20251218171726_add_pins.sql (25.9ms)15502026/10/01 09:53:33 OK 20260628120000_add_object_size_and_stats.sql (26ms)15512026/10/01 09:53:33 OK 20260905000000_add_claims.sql (15.55ms)15522026/10/01 09:53:33 OK 20260920000000_drop_claims.sql (21.06ms)15532026-10-01 09:53:33.699 UTC [92252] ERROR: relation "goose_db_version" does not exist at character 3615542026-10-01 09:53:33.699 UTC [92252] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15552026/10/01 09:53:33 OK 20260923120000_add_pushes.sql (10.21ms)15562026/10/01 09:53:33 goose: successfully migrated database to version: 2026092312000015572026/10/01 09:53:33 OK 1_commit_pending_closure.sql (2.56ms)15582026/10/01 09:53:33 OK 2_object_stats_trigger.sql (552.92µs)15592026/10/01 09:53:33 OK 3_commit_push.sql (458.29µs)15602026/10/01 09:53:33 goose: up to current file version: 315612026/10/01 09:53:33 OK 20241026095416_initial_model.sql (146.82ms)15622026/10/01 09:53:33 INFO Aborted multipart uploads count=015632026/10/01 09:53:33 WARN Force mode enabled - objects will be deleted immediately without grace period15642026/10/01 09:53:33 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=015652026/10/01 09:53:33 INFO Vacuumed table table=pending_closures15662026/10/01 09:53:33 INFO Vacuumed table table=pending_objects15672026/10/01 09:53:33 INFO Vacuumed table table=multipart_uploads15682026/10/01 09:53:33 INFO Vacuumed table table=closures15692026/10/01 09:53:33 OK 20251210153512_drop_unused_gin_index.sql (13.41ms)15702026/10/01 09:53:33 INFO Vacuumed table table=objects15712026/10/01 09:53:33 OK 20251218171726_add_pins.sql (91.41ms)15722026/10/01 09:53:33 INFO Aborted multipart uploads count=015732026/10/01 09:53:34 WARN Force mode enabled - objects will be deleted immediately without grace period15742026/10/01 09:53:34 OK 20260628120000_add_object_size_and_stats.sql (20.5ms)15752026/10/01 09:53:34 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=015762026/10/01 09:53:34 INFO Vacuumed table table=pending_closures15772026/10/01 09:53:34 INFO Vacuumed table table=pending_objects15782026/10/01 09:53:34 INFO Vacuumed table table=multipart_uploads15792026/10/01 09:53:34 INFO Vacuumed table table=closures15802026/10/01 09:53:34 OK 20260905000000_add_claims.sql (38.58ms)15812026/10/01 09:53:34 INFO Vacuumed table table=objects1582--- PASS: TestSweepSkipsRowsLockedByPush (2.78s)1583=== CONT TestLeadEndsOnShutdown15842026/10/01 09:53:34 OK 20260920000000_drop_claims.sql (40.61ms)15852026/10/01 09:53:34 OK 20260923120000_add_pushes.sql (10.62ms)15862026/10/01 09:53:34 goose: successfully migrated database to version: 2026092312000015872026/10/01 09:53:34 OK 1_commit_pending_closure.sql (3.28ms)15882026/10/01 09:53:34 OK 2_object_stats_trigger.sql (537.33µs)15892026/10/01 09:53:34 OK 3_commit_push.sql (386µs)15902026/10/01 09:53:34 goose: up to current file version: 315912026/10/01 09:53:34 INFO Received uploads request method=POST path=/api/pending_closures15922026-10-01 09:53:34.127 UTC [92257] ERROR: relation "goose_db_version" does not exist at character 3615932026-10-01 09:53:34.127 UTC [92257] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15942026-10-01 09:53:34.173 UTC [92258] ERROR: relation "goose_db_version" does not exist at character 3615952026-10-01 09:53:34.173 UTC [92258] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15962026/10/01 09:53:34 INFO Aborted multipart uploads count=015972026/10/01 09:53:34 WARN Force mode enabled - objects will be deleted immediately without grace period15982026/10/01 09:53:34 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."15992026/10/01 09:53:34 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1600--- PASS: TestFailedS3DeleteKeepsTombstone (2.93s)1601=== CONT TestLeadElectsOneAndHandsOver16022026/10/01 09:53:34 OK 20241026095416_initial_model.sql (201.5ms)16032026/10/01 09:53:34 OK 20241026095416_initial_model.sql (145.14ms)16042026/10/01 09:53:34 OK 20251210153512_drop_unused_gin_index.sql (8.59ms)16052026/10/01 09:53:34 OK 20251210153512_drop_unused_gin_index.sql (8.55ms)16062026/10/01 09:53:34 OK 20251218171726_add_pins.sql (26.83ms)16072026/10/01 09:53:34 OK 20251218171726_add_pins.sql (26.89ms)16082026/10/01 09:53:34 INFO Received uploads request method=POST path=/api/pending_closures16092026/10/01 09:53:34 OK 20260628120000_add_object_size_and_stats.sql (33.82ms)16102026/10/01 09:53:34 OK 20260628120000_add_object_size_and_stats.sql (54.14ms)16112026/10/01 09:53:34 OK 20260905000000_add_claims.sql (48.02ms)16122026/10/01 09:53:34 OK 20260905000000_add_claims.sql (31.8ms)16132026/10/01 09:53:34 OK 20260920000000_drop_claims.sql (6.77ms)16142026/10/01 09:53:34 OK 20260920000000_drop_claims.sql (5.73ms)16152026/10/01 09:53:34 OK 20260923120000_add_pushes.sql (8.47ms)16162026/10/01 09:53:34 goose: successfully migrated database to version: 2026092312000016172026/10/01 09:53:34 OK 1_commit_pending_closure.sql (3.28ms)16182026/10/01 09:53:34 OK 2_object_stats_trigger.sql (614.46µs)16192026/10/01 09:53:34 OK 3_commit_push.sql (437.29µs)16202026/10/01 09:53:34 goose: up to current file version: 316212026/10/01 09:53:34 OK 20260923120000_add_pushes.sql (12.57ms)16222026/10/01 09:53:34 goose: successfully migrated database to version: 2026092312000016232026/10/01 09:53:34 OK 1_commit_pending_closure.sql (3.29ms)16242026/10/01 09:53:34 OK 2_object_stats_trigger.sql (589.5µs)16252026/10/01 09:53:34 OK 3_commit_push.sql (417.54µs)16262026/10/01 09:53:34 goose: up to current file version: 31627--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (2.85s)1628=== CONT TestResolveDBConnectionString1629=== RUN TestResolveDBConnectionString/flag_wins1630=== PAUSE TestResolveDBConnectionString/flag_wins1631=== RUN TestResolveDBConnectionString/file_when_flag_empty1632=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1633=== RUN TestResolveDBConnectionString/missing_file_is_an_error1634=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1635=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1636=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1637=== RUN TestResolveDBConnectionString/nothing_configured1638=== PAUSE TestResolveDBConnectionString/nothing_configured1639=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock16402026-10-01 09:53:34.689 UTC [92262] ERROR: relation "goose_db_version" does not exist at character 3616412026-10-01 09:53:34.689 UTC [92262] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16422026-10-01 09:53:34.689 UTC [92263] ERROR: relation "goose_db_version" does not exist at character 3616432026-10-01 09:53:34.689 UTC [92263] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16442026-10-01 09:53:34.818 UTC [92266] ERROR: relation "goose_db_version" does not exist at character 3616452026-10-01 09:53:34.818 UTC [92266] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16462026/10/01 09:53:34 INFO Aborted multipart uploads count=016472026/10/01 09:53:34 WARN Force mode enabled - objects will be deleted immediately without grace period16482026/10/01 09:53:34 OK 20241026095416_initial_model.sql (145.81ms)16492026/10/01 09:53:34 OK 20251210153512_drop_unused_gin_index.sql (71.23ms)16502026/10/01 09:53:34 OK 20241026095416_initial_model.sql (218.59ms)16512026/10/01 09:53:34 OK 20251218171726_add_pins.sql (9.71ms)16522026/10/01 09:53:34 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=016532026/10/01 09:53:34 INFO Vacuumed table table=pending_closures16542026/10/01 09:53:34 OK 20251210153512_drop_unused_gin_index.sql (12.02ms)16552026/10/01 09:53:34 INFO Vacuumed table table=pending_objects16562026/10/01 09:53:34 INFO Vacuumed table table=multipart_uploads16572026/10/01 09:53:34 INFO Vacuumed table table=closures16582026/10/01 09:53:35 INFO Vacuumed table table=objects16592026/10/01 09:53:35 OK 20260628120000_add_object_size_and_stats.sql (58.73ms)1660--- PASS: TestGCSweepDeliversEachKeyOnce (2.82s)1661=== CONT TestPinProtectsFromGC16622026/10/01 09:53:35 OK 20251218171726_add_pins.sql (55.92ms)16632026/10/01 09:53:35 OK 20241026095416_initial_model.sql (176.18ms)16642026/10/01 09:53:35 OK 20260628120000_add_object_size_and_stats.sql (30.92ms)16652026/10/01 09:53:35 OK 20260905000000_add_claims.sql (32.56ms)16662026/10/01 09:53:35 OK 20251210153512_drop_unused_gin_index.sql (14.19ms)16672026/10/01 09:53:35 OK 20260920000000_drop_claims.sql (24.64ms)16682026-10-01 09:53:35.084 UTC [92269] ERROR: relation "goose_db_version" does not exist at character 3616692026-10-01 09:53:35.084 UTC [92269] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16702026/10/01 09:53:35 OK 20251218171726_add_pins.sql (18.25ms)16712026/10/01 09:53:35 OK 20260905000000_add_claims.sql (27.65ms)16722026/10/01 09:53:35 OK 20260923120000_add_pushes.sql (9.56ms)16732026/10/01 09:53:35 goose: successfully migrated database to version: 2026092312000016742026/10/01 09:53:35 OK 1_commit_pending_closure.sql (2.36ms)16752026/10/01 09:53:35 OK 2_object_stats_trigger.sql (466.83µs)16762026/10/01 09:53:35 OK 3_commit_push.sql (408.75µs)16772026/10/01 09:53:35 goose: up to current file version: 316782026/10/01 09:53:35 OK 20260920000000_drop_claims.sql (35.34ms)16792026/10/01 09:53:35 OK 20260628120000_add_object_size_and_stats.sql (37.63ms)16802026/10/01 09:53:35 OK 20260923120000_add_pushes.sql (23.88ms)16812026/10/01 09:53:35 goose: successfully migrated database to version: 2026092312000016822026/10/01 09:53:35 OK 1_commit_pending_closure.sql (1.75ms)16832026/10/01 09:53:35 OK 2_object_stats_trigger.sql (339.79µs)16842026/10/01 09:53:35 OK 3_commit_push.sql (316.46µs)16852026/10/01 09:53:35 goose: up to current file version: 316862026/10/01 09:53:35 OK 20260905000000_add_claims.sql (68.47ms)16872026/10/01 09:53:35 OK 20260920000000_drop_claims.sql (16.35ms)16882026/10/01 09:53:35 OK 20260923120000_add_pushes.sql (2.12ms)16892026/10/01 09:53:35 goose: successfully migrated database to version: 2026092312000016902026/10/01 09:53:35 OK 1_commit_pending_closure.sql (979.08µs)16912026/10/01 09:53:35 OK 2_object_stats_trigger.sql (224.38µs)16922026/10/01 09:53:35 OK 3_commit_push.sql (189.71µs)16932026/10/01 09:53:35 goose: up to current file version: 316942026/10/01 09:53:35 OK 20241026095416_initial_model.sql (109.95ms)16952026/10/01 09:53:35 OK 20251210153512_drop_unused_gin_index.sql (7.32ms)16962026/10/01 09:53:35 OK 20251218171726_add_pins.sql (18.68ms)16972026/10/01 09:53:35 OK 20260628120000_add_object_size_and_stats.sql (2.65ms)16982026/10/01 09:53:35 OK 20260905000000_add_claims.sql (34.74ms)16992026/10/01 09:53:35 INFO Received uploads request method=POST path=/api/pending_closures17002026/10/01 09:53:35 OK 20260920000000_drop_claims.sql (21.8ms)1701--- PASS: TestTombstonedObjectOfferedWithoutWaiting (2.71s)1702=== CONT TestClientSharedPathCommittedMidPush17032026/10/01 09:53:35 OK 20260923120000_add_pushes.sql (22.33ms)17042026/10/01 09:53:35 goose: successfully migrated database to version: 2026092312000017052026/10/01 09:53:35 OK 1_commit_pending_closure.sql (1.8ms)17062026/10/01 09:53:35 OK 2_object_stats_trigger.sql (262.75µs)17072026/10/01 09:53:35 OK 3_commit_push.sql (184.75µs)17082026/10/01 09:53:35 goose: up to current file version: 31709=== NAME TestClientWithDependencies1710 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-91990-792741325/TestClientWithDependencies404194741/001/store/gylkrnld5r3305sjsgj61xpyyqv81skd-test-script17112026-10-01 09:53:35.436 UTC [92278] ERROR: relation "goose_db_version" does not exist at character 3617122026-10-01 09:53:35.436 UTC [92278] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1713 client_integration_test.go:615: Found 1 dependencies (including self)17142026/10/01 09:53:35 INFO Received push request method=POST path=/api/pushes17152026/10/01 09:53:35 INFO Received uploads request method=POST path=/api/pending_closures17162026/10/01 09:53:35 OK 20241026095416_initial_model.sql (88.64ms)17172026/10/01 09:53:35 OK 20251210153512_drop_unused_gin_index.sql (8.56ms)17182026/10/01 09:53:35 OK 20251218171726_add_pins.sql (16.44ms)17192026/10/01 09:53:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17202026/10/01 09:53:35 INFO Uploading gylkrnld5r3305sjsgj61xpyyqv81skd-test-script (136B)1721--- PASS: TestDeduplicatedObjectsRecordedAsPending (2.34s)1722=== CONT TestService_cleanupPendingClosuresHandler17232026/10/01 09:53:35 WARN Failed to register uploaded object key=gylkrnld5r3305sjsgj61xpyyqv81skd.ls error="server returned 404: 404 page not found\n"17242026/10/01 09:53:35 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17252026/10/01 09:53:35 WARN Failed to register uploaded object key=log/l5aizlyy9k64rhr1nzh8kvxik88jp2y9-test-script.drv error="server returned 404: 404 page not found\n"17262026/10/01 09:53:35 OK 20260628120000_add_object_size_and_stats.sql (29.92ms)17272026/10/01 09:53:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17282026/10/01 09:53:35 INFO Signed narinfos id=1 count=117292026/10/01 09:53:35 INFO Uploading 1 narinfos17302026-10-01 09:53:35.620 UTC [92287] ERROR: relation "goose_db_version" does not exist at character 3617312026-10-01 09:53:35.620 UTC [92287] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17322026/10/01 09:53:35 INFO Received complete push request method=POST path=/api/pushes/1/complete17332026/10/01 09:53:35 WARN Failed to register uploaded object key=gylkrnld5r3305sjsgj61xpyyqv81skd.narinfo error="server returned 404: 404 page not found\n"17342026/10/01 09:53:35 OK 20260905000000_add_claims.sql (43.88ms)17352026/10/01 09:53:35 INFO Upload complete. (149ms)1736=== NAME TestClientWithDependencies1737 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-91990-792741325/TestClientWithDependencies404194741/001/store) requires matching store prefix17382026/10/01 09:53:35 OK 20260920000000_drop_claims.sql (40.9ms)17392026/10/01 09:53:35 OK 20260923120000_add_pushes.sql (9.05ms)17402026/10/01 09:53:35 goose: successfully migrated database to version: 2026092312000017412026/10/01 09:53:35 OK 1_commit_pending_closure.sql (1.19ms)17422026/10/01 09:53:35 OK 2_object_stats_trigger.sql (273.83µs)17432026/10/01 09:53:35 OK 3_commit_push.sql (232.29µs)17442026/10/01 09:53:35 goose: up to current file version: 31745--- PASS: TestClientWithDependencies (3.01s)1746=== CONT TestObjectStatsTrigger17472026/10/01 09:53:35 OK 20241026095416_initial_model.sql (108.7ms)17482026/10/01 09:53:35 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)17492026/10/01 09:53:35 OK 20251218171726_add_pins.sql (52.18ms)17502026/10/01 09:53:35 OK 20260628120000_add_object_size_and_stats.sql (27.65ms)17512026/10/01 09:53:35 INFO Received uploads request method=POST path=/api/pending_closures17522026/10/01 09:53:35 OK 20260905000000_add_claims.sql (72.43ms)17532026/10/01 09:53:35 OK 20260920000000_drop_claims.sql (33.09ms)17542026/10/01 09:53:35 OK 20260923120000_add_pushes.sql (11.94ms)17552026/10/01 09:53:35 goose: successfully migrated database to version: 2026092312000017562026/10/01 09:53:35 OK 1_commit_pending_closure.sql (1.27ms)17572026/10/01 09:53:35 OK 2_object_stats_trigger.sql (210.29µs)17582026/10/01 09:53:35 OK 3_commit_push.sql (161µs)17592026/10/01 09:53:35 goose: up to current file version: 317602026/10/01 09:53:36 INFO Aborted multipart uploads count=017612026/10/01 09:53:36 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=017622026/10/01 09:53:36 INFO Vacuumed table table=pending_closures17632026/10/01 09:53:36 INFO Aborted multipart uploads count=017642026/10/01 09:53:36 WARN Force mode enabled - objects will be deleted immediately without grace period17652026/10/01 09:53:36 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=017662026/10/01 09:53:36 INFO Vacuumed table table=pending_closures17672026/10/01 09:53:36 INFO Vacuumed table table=pending_objects17682026/10/01 09:53:36 INFO Vacuumed table table=multipart_uploads17692026/10/01 09:53:36 INFO Vacuumed table table=closures17702026-10-01 09:53:36.087 UTC [92292] ERROR: relation "goose_db_version" does not exist at character 3617712026-10-01 09:53:36.087 UTC [92292] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17722026/10/01 09:53:36 INFO Vacuumed table table=objects1773--- PASS: TestGCMetrics (2.74s)1774=== CONT TestIsValidCachePath1775=== RUN TestIsValidCachePath/narinfo1776=== PAUSE TestIsValidCachePath/narinfo1777=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1778=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1779=== RUN TestIsValidCachePath/nar_zst1780=== PAUSE TestIsValidCachePath/nar_zst1781=== RUN TestIsValidCachePath/nar_xz1782=== PAUSE TestIsValidCachePath/nar_xz1783=== RUN TestIsValidCachePath/nar_bz21784=== PAUSE TestIsValidCachePath/nar_bz21785=== RUN TestIsValidCachePath/nar_uncompressed1786=== PAUSE TestIsValidCachePath/nar_uncompressed1787=== RUN TestIsValidCachePath/ls1788=== PAUSE TestIsValidCachePath/ls1789=== RUN TestIsValidCachePath/log1790=== PAUSE TestIsValidCachePath/log1791=== RUN TestIsValidCachePath/realisation1792=== PAUSE TestIsValidCachePath/realisation1793=== RUN TestIsValidCachePath/nix-cache-info1794=== PAUSE TestIsValidCachePath/nix-cache-info1795=== RUN TestIsValidCachePath/index.html1796=== PAUSE TestIsValidCachePath/index.html1797=== RUN TestIsValidCachePath/traversal_parent1798=== PAUSE TestIsValidCachePath/traversal_parent1799=== RUN TestIsValidCachePath/traversal_in_middle1800=== PAUSE TestIsValidCachePath/traversal_in_middle1801=== RUN TestIsValidCachePath/invalid_char_e1802=== PAUSE TestIsValidCachePath/invalid_char_e1803=== RUN TestIsValidCachePath/invalid_char_u1804=== PAUSE TestIsValidCachePath/invalid_char_u1805=== RUN TestIsValidCachePath/random_path1806=== PAUSE TestIsValidCachePath/random_path1807=== RUN TestIsValidCachePath/empty1808=== PAUSE TestIsValidCachePath/empty1809=== RUN TestIsValidCachePath/leading_slash1810=== PAUSE TestIsValidCachePath/leading_slash1811=== RUN TestIsValidCachePath/wrong_extension1812=== PAUSE TestIsValidCachePath/wrong_extension1813=== RUN TestIsValidCachePath/short_hash1814=== PAUSE TestIsValidCachePath/short_hash1815=== CONT TestProxyHeadersOnlyTrustedOnSocket18162026/10/01 09:53:36 INFO Vacuumed table table=pending_objects18172026/10/01 09:53:36 INFO Vacuumed table table=multipart_uploads18182026/10/01 09:53:36 INFO Vacuumed table table=closures18192026/10/01 09:53:36 INFO Vacuumed table table=objects18202026/10/01 09:53:36 INFO Aborted multipart uploads count=018212026/10/01 09:53:36 WARN Force mode enabled - objects will be deleted immediately without grace period18222026/10/01 09:53:36 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=018232026/10/01 09:53:36 INFO Vacuumed table table=pending_closures18242026/10/01 09:53:36 INFO Vacuumed table table=pending_objects18252026/10/01 09:53:36 INFO Vacuumed table table=multipart_uploads18262026/10/01 09:53:36 INFO Vacuumed table table=closures18272026/10/01 09:53:36 INFO Vacuumed table table=objects1828--- PASS: TestPushDedupSurvivesConcurrentGC (2.87s)1829=== CONT TestParseSingleRange1830=== RUN TestParseSingleRange/none1831=== PAUSE TestParseSingleRange/none1832=== RUN TestParseSingleRange/unknown_unit1833=== PAUSE TestParseSingleRange/unknown_unit1834=== RUN TestParseSingleRange/multi-range_ignored1835=== PAUSE TestParseSingleRange/multi-range_ignored1836=== RUN TestParseSingleRange/malformed_no_dash1837=== PAUSE TestParseSingleRange/malformed_no_dash1838=== RUN TestParseSingleRange/malformed_both_empty1839=== PAUSE TestParseSingleRange/malformed_both_empty1840=== RUN TestParseSingleRange/malformed_end_before_start1841=== PAUSE TestParseSingleRange/malformed_end_before_start1842=== RUN TestParseSingleRange/closed1843=== PAUSE TestParseSingleRange/closed1844=== RUN TestParseSingleRange/open-ended1845=== PAUSE TestParseSingleRange/open-ended1846=== RUN TestParseSingleRange/end_clamped_to_size1847=== PAUSE TestParseSingleRange/end_clamped_to_size1848=== RUN TestParseSingleRange/suffix1849=== PAUSE TestParseSingleRange/suffix1850=== RUN TestParseSingleRange/suffix_exceeds_size1851=== PAUSE TestParseSingleRange/suffix_exceeds_size1852=== RUN TestParseSingleRange/single_byte1853=== PAUSE TestParseSingleRange/single_byte1854=== RUN TestParseSingleRange/start_past_EOF1855=== PAUSE TestParseSingleRange/start_past_EOF1856=== RUN TestParseSingleRange/start_far_past_EOF1857=== PAUSE TestParseSingleRange/start_far_past_EOF1858=== CONT TestPresentNotReportedWhileGCDeletesClosure18592026/10/01 09:53:36 OK 20241026095416_initial_model.sql (49.65ms)18602026/10/01 09:53:36 OK 20251210153512_drop_unused_gin_index.sql (3.84ms)18612026/10/01 09:53:36 OK 20251218171726_add_pins.sql (20.9ms)18622026/10/01 09:53:36 OK 20260628120000_add_object_size_and_stats.sql (14.58ms)18632026/10/01 09:53:36 OK 20260905000000_add_claims.sql (22.9ms)18642026/10/01 09:53:36 OK 20260920000000_drop_claims.sql (26.69ms)18652026/10/01 09:53:36 OK 20260923120000_add_pushes.sql (16.66ms)18662026/10/01 09:53:36 goose: successfully migrated database to version: 2026092312000018672026/10/01 09:53:36 OK 1_commit_pending_closure.sql (980.08µs)18682026/10/01 09:53:36 OK 2_object_stats_trigger.sql (228.96µs)18692026/10/01 09:53:36 OK 3_commit_push.sql (204.83µs)18702026/10/01 09:53:36 goose: up to current file version: 318712026-10-01 09:53:36.306 UTC [92297] ERROR: relation "goose_db_version" does not exist at character 3618722026-10-01 09:53:36.306 UTC [92297] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18732026/10/01 09:53:36 OK 20241026095416_initial_model.sql (49.32ms)18742026/10/01 09:53:36 OK 20251210153512_drop_unused_gin_index.sql (9.41ms)18752026/10/01 09:53:36 OK 20251218171726_add_pins.sql (12.03ms)18762026/10/01 09:53:36 OK 20260628120000_add_object_size_and_stats.sql (14.25ms)18772026/10/01 09:53:36 INFO lead: acquired remote=192.0.2.1:123418782026/10/01 09:53:36 INFO lead: released remote=192.0.2.1:12341879--- PASS: TestLeadEndsOnShutdown (2.39s)1880=== CONT TestPresentReportsOnlyClosureRoots18812026/10/01 09:53:36 OK 20260905000000_add_claims.sql (21.13ms)18822026/10/01 09:53:36 OK 20260920000000_drop_claims.sql (31.5ms)18832026/10/01 09:53:36 OK 20260923120000_add_pushes.sql (18.64ms)18842026/10/01 09:53:36 goose: successfully migrated database to version: 2026092312000018852026/10/01 09:53:36 OK 1_commit_pending_closure.sql (1.31ms)18862026/10/01 09:53:36 OK 2_object_stats_trigger.sql (250.29µs)18872026/10/01 09:53:36 OK 3_commit_push.sql (209.71µs)18882026/10/01 09:53:36 goose: up to current file version: 31889--- PASS: TestGCBugBareHashReferences (2.94s)1890=== CONT TestCreatePin_ReservedPins18912026-10-01 09:53:36.559 UTC [92300] ERROR: relation "goose_db_version" does not exist at character 3618922026-10-01 09:53:36.559 UTC [92300] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18932026/10/01 09:53:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56353/oidc18942026/10/01 09:53:36 INFO lead: acquired remote=192.0.2.1:123418952026/10/01 09:53:36 OK 20241026095416_initial_model.sql (119.87ms)18962026/10/01 09:53:36 OK 20251210153512_drop_unused_gin_index.sql (7.47ms)18972026/10/01 09:53:36 OK 20251218171726_add_pins.sql (10.01ms)18982026/10/01 09:53:36 OK 20260628120000_add_object_size_and_stats.sql (19.64ms)18992026/10/01 09:53:36 OK 20260905000000_add_claims.sql (21.86ms)19002026/10/01 09:53:36 INFO lead: released remote=192.0.2.1:123419012026-10-01 09:53:36.778 UTC [92304] ERROR: relation "goose_db_version" does not exist at character 3619022026-10-01 09:53:36.778 UTC [92304] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19032026/10/01 09:53:36 OK 20260920000000_drop_claims.sql (18.53ms)19042026/10/01 09:53:36 OK 20260923120000_add_pushes.sql (22.74ms)19052026/10/01 09:53:36 goose: successfully migrated database to version: 2026092312000019062026/10/01 09:53:36 OK 1_commit_pending_closure.sql (2.63ms)19072026/10/01 09:53:36 OK 2_object_stats_trigger.sql (810.96µs)19082026/10/01 09:53:36 OK 3_commit_push.sql (409.33µs)19092026/10/01 09:53:36 goose: up to current file version: 319102026/10/01 09:53:36 INFO lead: acquired remote=192.0.2.1:123419112026/10/01 09:53:36 INFO lead: released remote=192.0.2.1:12341912--- PASS: TestLeadElectsOneAndHandsOver (2.53s)1913=== CONT TestOrphanedObjectsGCStressTest19142026/10/01 09:53:36 OK 20241026095416_initial_model.sql (96.81ms)19152026/10/01 09:53:36 OK 20251210153512_drop_unused_gin_index.sql (1.58ms)19162026-10-01 09:53:36.923 UTC [92308] ERROR: relation "goose_db_version" does not exist at character 3619172026-10-01 09:53:36.923 UTC [92308] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19182026/10/01 09:53:36 OK 20251218171726_add_pins.sql (7.57ms)19192026/10/01 09:53:36 OK 20260628120000_add_object_size_and_stats.sql (22.74ms)19202026/10/01 09:53:36 OK 20260905000000_add_claims.sql (34.38ms)19212026/10/01 09:53:36 OK 20260920000000_drop_claims.sql (15.02ms)19222026/10/01 09:53:37 OK 20260923120000_add_pushes.sql (2.79ms)19232026/10/01 09:53:37 goose: successfully migrated database to version: 2026092312000019242026/10/01 09:53:37 OK 1_commit_pending_closure.sql (1.82ms)19252026/10/01 09:53:37 OK 2_object_stats_trigger.sql (409.33µs)19262026/10/01 09:53:37 OK 3_commit_push.sql (316µs)19272026/10/01 09:53:37 goose: up to current file version: 319282026/10/01 09:53:37 OK 20241026095416_initial_model.sql (150.48ms)19292026/10/01 09:53:37 OK 20251210153512_drop_unused_gin_index.sql (13.94ms)19302026/10/01 09:53:37 OK 20251218171726_add_pins.sql (27.32ms)19312026/10/01 09:53:37 OK 20260628120000_add_object_size_and_stats.sql (22.72ms)19322026/10/01 09:53:37 OK 20260905000000_add_claims.sql (32.85ms)19332026/10/01 09:53:37 OK 20260920000000_drop_claims.sql (14.46ms)19342026/10/01 09:53:37 OK 20260923120000_add_pushes.sql (22.15ms)19352026/10/01 09:53:37 goose: successfully migrated database to version: 2026092312000019362026/10/01 09:53:37 OK 1_commit_pending_closure.sql (1.52ms)19372026/10/01 09:53:37 OK 2_object_stats_trigger.sql (295.13µs)19382026/10/01 09:53:37 OK 3_commit_push.sql (234.04µs)19392026/10/01 09:53:37 goose: up to current file version: 319402026-10-01 09:53:37.269 UTC [92311] ERROR: relation "goose_db_version" does not exist at character 3619412026-10-01 09:53:37.269 UTC [92311] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1942=== NAME TestPinProtectsFromGC1943 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-91990-792741325/TestPinProtectsFromGC3157975810/001/store/aw8yaakyfq1kxc4v6i5kimvgzl0vj8l1-pinned-file.txt1944 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-91990-792741325/TestPinProtectsFromGC3157975810/001/store/mwyy8bdbs90zx3shz4wvr3kk9rrwaasv-unpinned-file.txt19452026-10-01 09:53:37.408 UTC [92316] ERROR: relation "goose_db_version" does not exist at character 3619462026-10-01 09:53:37.408 UTC [92316] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19472026/10/01 09:53:37 OK 20241026095416_initial_model.sql (138.59ms)19482026/10/01 09:53:37 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)19492026/10/01 09:53:37 INFO Received push request method=POST path=/api/pushes19502026/10/01 09:53:37 OK 20251218171726_add_pins.sql (15.33ms)19512026/10/01 09:53:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19522026/10/01 09:53:37 INFO Uploading aw8yaakyfq1kxc4v6i5kimvgzl0vj8l1-pinned-file.txt (128B)19532026/10/01 09:53:37 WARN Failed to register uploaded object key=aw8yaakyfq1kxc4v6i5kimvgzl0vj8l1.ls error="server returned 404: 404 page not found\n"19542026/10/01 09:53:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19552026/10/01 09:53:37 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"19562026/10/01 09:53:37 INFO Signed narinfos id=1 count=119572026/10/01 09:53:37 INFO Uploading 1 narinfos19582026/10/01 09:53:37 OK 20260628120000_add_object_size_and_stats.sql (21.7ms)19592026/10/01 09:53:37 INFO Received complete push request method=POST path=/api/pushes/1/complete19602026/10/01 09:53:37 WARN Failed to register uploaded object key=aw8yaakyfq1kxc4v6i5kimvgzl0vj8l1.narinfo error="server returned 404: 404 page not found\n"19612026/10/01 09:53:37 INFO Upload complete. (117ms)19622026/10/01 09:53:37 OK 20260905000000_add_claims.sql (52.6ms)19632026/10/01 09:53:37 OK 20241026095416_initial_model.sql (108.47ms)19642026/10/01 09:53:37 INFO Received cleanup request method=DELETE path=/api/pending_closures19652026/10/01 09:53:37 INFO Aborted multipart uploads count=019662026/10/01 09:53:37 INFO Received uploads request method=POST path=/api/pending_closures19672026/10/01 09:53:37 OK 20251210153512_drop_unused_gin_index.sql (7.47ms)19682026/10/01 09:53:37 OK 20260920000000_drop_claims.sql (42.92ms)19692026/10/01 09:53:37 OK 20251218171726_add_pins.sql (39.13ms)19702026/10/01 09:53:37 OK 20260923120000_add_pushes.sql (21.38ms)19712026/10/01 09:53:37 goose: successfully migrated database to version: 2026092312000019722026/10/01 09:53:37 OK 1_commit_pending_closure.sql (1.37ms)19732026/10/01 09:53:37 OK 2_object_stats_trigger.sql (245.21µs)19742026/10/01 09:53:37 OK 3_commit_push.sql (166.08µs)19752026/10/01 09:53:37 goose: up to current file version: 319762026/10/01 09:53:37 INFO Received push request method=POST path=/api/pushes19772026/10/01 09:53:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19782026/10/01 09:53:37 INFO Uploading mwyy8bdbs90zx3shz4wvr3kk9rrwaasv-unpinned-file.txt (128B)19792026/10/01 09:53:37 INFO Received cleanup request method=DELETE path=/api/pending_closures19802026/10/01 09:53:37 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"19812026/10/01 09:53:37 INFO Aborted multipart uploads count=119822026/10/01 09:53:37 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19832026/10/01 09:53:37 INFO Signed narinfos id=2 count=119842026/10/01 09:53:37 INFO Uploading 1 narinfos19852026/10/01 09:53:37 WARN Failed to register uploaded object key=mwyy8bdbs90zx3shz4wvr3kk9rrwaasv.ls error="server returned 404: 404 page not found\n"19862026/10/01 09:53:37 OK 20260628120000_add_object_size_and_stats.sql (50.19ms)19872026/10/01 09:53:37 INFO Received push request method=POST path=/api/pushes19882026/10/01 09:53:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19892026-10-01 09:53:37.641 UTC [92304] ERROR: Closure does not exist: id=119902026-10-01 09:53:37.641 UTC [92304] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE19912026-10-01 09:53:37.641 UTC [92304] STATEMENT: -- name: CommitPendingClosure :exec1992 SELECT commit_pending_closure($1::bigint)1993 1994--- PASS: TestService_cleanupPendingClosuresHandler (2.07s)1995=== CONT TestOrphanedObjectsGC19962026/10/01 09:53:37 INFO Received complete push request method=POST path=/api/pushes/2/complete19972026/10/01 09:53:37 WARN Failed to register uploaded object key=mwyy8bdbs90zx3shz4wvr3kk9rrwaasv.narinfo error="server returned 404: 404 page not found\n"19982026/10/01 09:53:37 INFO Upload complete. (117ms)19992026/10/01 09:53:37 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)20002026/10/01 09:53:37 INFO Uploading 5aw4zchns2p56071lk65210mj40niq1s-shared-dep (136B)20012026/10/01 09:53:37 INFO Uploading zxkcwnnjg0qvdw0lxlzv8crr9kmhl8kq-top (256B)20022026/10/01 09:53:37 WARN Failed to register uploaded object key=5aw4zchns2p56071lk65210mj40niq1s.ls error="server returned 404: 404 page not found\n"20032026/10/01 09:53:37 WARN Failed to register uploaded object key=zxkcwnnjg0qvdw0lxlzv8crr9kmhl8kq.ls error="server returned 404: 404 page not found\n"20042026/10/01 09:53:37 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20052026/10/01 09:53:37 WARN Failed to register uploaded object key=nar/15vrxcdz6yahllqzfn0wv683yb17fplhh5xj949n14x49vnz354w.nar.zst error="server returned 404: 404 page not found\n"20062026/10/01 09:53:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20072026/10/01 09:53:37 INFO Signed narinfos id=1 count=220082026/10/01 09:53:37 INFO Uploading 2 narinfos20092026/10/01 09:53:37 OK 20260905000000_add_claims.sql (56.75ms)20102026/10/01 09:53:37 INFO Starting cleanup of old closures method=DELETE path=/api/closures20112026/10/01 09:53:37 INFO Garbage collection started20122026/10/01 09:53:37 WARN Failed to register uploaded object key=zxkcwnnjg0qvdw0lxlzv8crr9kmhl8kq.narinfo error="server returned 404: 404 page not found\n"20132026/10/01 09:53:37 INFO Aborted multipart uploads count=020142026/10/01 09:53:37 WARN Force mode enabled - objects will be deleted immediately without grace period20152026/10/01 09:53:37 INFO Received complete push request method=POST path=/api/pushes/1/complete20162026/10/01 09:53:37 WARN Failed to register uploaded object key=5aw4zchns2p56071lk65210mj40niq1s.narinfo error="server returned 404: 404 page not found\n"20172026/10/01 09:53:37 OK 20260920000000_drop_claims.sql (33.66ms)20182026/10/01 09:53:37 INFO Upload complete. (171ms)2019=== NAME TestClientSharedPathCommittedMidPush2020 client_integration_test.go:680: Retrieved narinfo from S3:2021 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestClientSharedPathCommittedMidPush2904506785/001/store/5aw4zchns2p56071lk65210mj40niq1s-shared-dep2022 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2023 Compression: zstd2024 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822025 NarSize: 1362026 References: 2027 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2028 client_integration_test.go:680: Retrieved narinfo from S3:2029 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestClientSharedPathCommittedMidPush2904506785/001/store/zxkcwnnjg0qvdw0lxlzv8crr9kmhl8kq-top2030 URL: nar/15vrxcdz6yahllqzfn0wv683yb17fplhh5xj949n14x49vnz354w.nar.zst2031 Compression: zstd2032 NarHash: sha256:15vrxcdz6yahllqzfn0wv683yb17fplhh5xj949n14x49vnz354w2033 NarSize: 2562034 References: /nix/var/nix/builds/nix-91990-792741325/TestClientSharedPathCommittedMidPush2904506785/001/store/5aw4zchns2p56071lk65210mj40niq1s-shared-dep2035 CA: text:sha256:00px1ygd9mcgxvqab6zalbdvw9rgy4l9qa0jc2zzmmmmj5rvhjly20362026/10/01 09:53:37 OK 20260923120000_add_pushes.sql (19.28ms)20372026/10/01 09:53:37 goose: successfully migrated database to version: 2026092312000020382026/10/01 09:53:37 OK 1_commit_pending_closure.sql (1.11ms)20392026/10/01 09:53:37 OK 2_object_stats_trigger.sql (224.08µs)20402026/10/01 09:53:37 OK 3_commit_push.sql (416.67µs)20412026/10/01 09:53:37 goose: up to current file version: 320422026/10/01 09:53:37 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=02043--- PASS: TestClientSharedPathCommittedMidPush (2.44s)2044=== CONT TestServerTLSConfig2045=== RUN TestServerTLSConfig/no_client_CA2046=== PAUSE TestServerTLSConfig/no_client_CA2047=== RUN TestServerTLSConfig/missing_CA_file2048=== PAUSE TestServerTLSConfig/missing_CA_file2049=== RUN TestServerTLSConfig/not_a_PEM_file2050=== PAUSE TestServerTLSConfig/not_a_PEM_file2051=== CONT TestPendingCleanupUsesOneCutoff20522026/10/01 09:53:37 INFO Vacuumed table table=pending_closures20532026/10/01 09:53:37 INFO Vacuumed table table=pending_objects20542026/10/01 09:53:37 INFO Vacuumed table table=multipart_uploads20552026/10/01 09:53:37 INFO Vacuumed table table=closures20562026-10-01 09:53:37.858 UTC [92341] ERROR: relation "goose_db_version" does not exist at character 3620572026-10-01 09:53:37.858 UTC [92341] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20582026/10/01 09:53:37 INFO Vacuumed table table=objects2059--- PASS: TestObjectStatsTrigger (2.18s)2060=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded2061--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (3.26s)2062=== CONT TestMultipartCleanup20632026-10-01 09:53:37.950 UTC [92346] ERROR: relation "goose_db_version" does not exist at character 3620642026-10-01 09:53:37.950 UTC [92346] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20652026/10/01 09:53:37 OK 20241026095416_initial_model.sql (82.25ms)20662026/10/01 09:53:37 OK 20251210153512_drop_unused_gin_index.sql (7.66ms)20672026/10/01 09:53:38 OK 20251218171726_add_pins.sql (20.95ms)20682026/10/01 09:53:38 OK 20260628120000_add_object_size_and_stats.sql (21.97ms)20692026/10/01 09:53:38 INFO Starting HTTP server address=/nix/var/nix/builds/nix-91990-792741325/TestProxyHeadersOnlyTrustedOnSocket4048658820/001/proxy.sock20702026/10/01 09:53:38 INFO Starting HTTP server address=127.0.0.1:5639420712026/10/01 09:53:38 WARN mTLS auth: subject not in bound subjects subject="CN=someone"20722026/10/01 09:53:38 OK 20260905000000_add_claims.sql (19.5ms)20732026/10/01 09:53:38 INFO Shutdown signal received, draining in-flight requests timeout=10s20742026/10/01 09:53:38 OK 20241026095416_initial_model.sql (92.87ms)2075--- PASS: TestProxyHeadersOnlyTrustedOnSocket (1.97s)2076=== CONT TestMetricsInventory20772026/10/01 09:53:38 OK 20251210153512_drop_unused_gin_index.sql (7.29ms)20782026/10/01 09:53:38 OK 20251218171726_add_pins.sql (18.34ms)20792026/10/01 09:53:38 OK 20260920000000_drop_claims.sql (44.55ms)20802026/10/01 09:53:38 OK 20260923120000_add_pushes.sql (6.4ms)20812026/10/01 09:53:38 goose: successfully migrated database to version: 2026092312000020822026/10/01 09:53:38 OK 20260628120000_add_object_size_and_stats.sql (25.03ms)20832026/10/01 09:53:38 OK 1_commit_pending_closure.sql (2.44ms)20842026/10/01 09:53:38 OK 2_object_stats_trigger.sql (385.04µs)20852026/10/01 09:53:38 OK 3_commit_push.sql (217.5µs)20862026/10/01 09:53:38 goose: up to current file version: 320872026/10/01 09:53:38 OK 20260905000000_add_claims.sql (13.51ms)20882026/10/01 09:53:38 OK 20260920000000_drop_claims.sql (13.87ms)20892026/10/01 09:53:38 OK 20260923120000_add_pushes.sql (6.79ms)20902026/10/01 09:53:38 goose: successfully migrated database to version: 2026092312000020912026-10-01 09:53:38.146 UTC [92350] ERROR: relation "goose_db_version" does not exist at character 3620922026-10-01 09:53:38.146 UTC [92350] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20932026/10/01 09:53:38 OK 1_commit_pending_closure.sql (2.22ms)20942026/10/01 09:53:38 OK 2_object_stats_trigger.sql (302.88µs)20952026/10/01 09:53:38 OK 3_commit_push.sql (219.96µs)20962026/10/01 09:53:38 goose: up to current file version: 320972026/10/01 09:53:38 OK 20241026095416_initial_model.sql (129.95ms)20982026/10/01 09:53:38 OK 20251210153512_drop_unused_gin_index.sql (10.38ms)20992026/10/01 09:53:38 OK 20251218171726_add_pins.sql (9.44ms)21002026/10/01 09:53:38 OK 20260628120000_add_object_size_and_stats.sql (18.83ms)21012026/10/01 09:53:38 OK 20260905000000_add_claims.sql (20.51ms)21022026/10/01 09:53:38 OK 20260920000000_drop_claims.sql (14.79ms)21032026/10/01 09:53:38 OK 20260923120000_add_pushes.sql (9.86ms)21042026/10/01 09:53:38 goose: successfully migrated database to version: 2026092312000021052026/10/01 09:53:38 OK 1_commit_pending_closure.sql (3.26ms)21062026/10/01 09:53:38 OK 2_object_stats_trigger.sql (721.04µs)21072026/10/01 09:53:38 OK 3_commit_push.sql (458.63µs)21082026/10/01 09:53:38 goose: up to current file version: 32109--- PASS: TestPresentReportsOnlyClosureRoots (2.05s)2110=== CONT TestService_NativeMTLS21112026/10/01 09:53:38 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux21122026/10/01 09:53:38 WARN Refused reserved pin name=worker-x86_64-linux21132026/10/01 09:53:38 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux21142026/10/01 09:53:38 INFO Received create pin request method=POST path=/api/pins/my-app21152026/10/01 09:53:38 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux2116--- PASS: TestCreatePin_ReservedPins (2.20s)2117=== CONT TestClientFallsBackToClosures2118--- PASS: TestPresentNotReportedWhileGCDeletesClosure (2.65s)2119=== CONT TestNARDeduplicationMetadataUploadBug21202026-10-01 09:53:38.930 UTC [92358] ERROR: relation "goose_db_version" does not exist at character 3621212026-10-01 09:53:38.930 UTC [92358] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21222026-10-01 09:53:38.975 UTC [92359] ERROR: relation "goose_db_version" does not exist at character 3621232026-10-01 09:53:38.975 UTC [92359] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21242026/10/01 09:53:39 OK 20241026095416_initial_model.sql (98.33ms)21252026/10/01 09:53:39 OK 20251210153512_drop_unused_gin_index.sql (3.81ms)21262026-10-01 09:53:39.083 UTC [92360] ERROR: relation "goose_db_version" does not exist at character 3621272026-10-01 09:53:39.083 UTC [92360] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21282026-10-01 09:53:39.084 UTC [92361] ERROR: relation "goose_db_version" does not exist at character 3621292026-10-01 09:53:39.084 UTC [92361] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21302026/10/01 09:53:39 OK 20251218171726_add_pins.sql (8.95ms)21312026/10/01 09:53:39 OK 20260628120000_add_object_size_and_stats.sql (25.04ms)21322026/10/01 09:53:39 OK 20241026095416_initial_model.sql (86.16ms)21332026/10/01 09:53:39 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)21342026/10/01 09:53:39 OK 20251218171726_add_pins.sql (14.71ms)21352026/10/01 09:53:39 OK 20260905000000_add_claims.sql (25.9ms)21362026/10/01 09:53:39 OK 20260920000000_drop_claims.sql (18.28ms)21372026/10/01 09:53:39 OK 20260628120000_add_object_size_and_stats.sql (20.52ms)21382026/10/01 09:53:39 OK 20260923120000_add_pushes.sql (3.81ms)21392026/10/01 09:53:39 goose: successfully migrated database to version: 2026092312000021402026/10/01 09:53:39 OK 1_commit_pending_closure.sql (2.85ms)21412026/10/01 09:53:39 OK 2_object_stats_trigger.sql (543.58µs)21422026/10/01 09:53:39 OK 3_commit_push.sql (392.92µs)21432026/10/01 09:53:39 goose: up to current file version: 321442026/10/01 09:53:39 OK 20260905000000_add_claims.sql (47.77ms)21452026-10-01 09:53:39.212 UTC [92362] ERROR: relation "goose_db_version" does not exist at character 3621462026-10-01 09:53:39.212 UTC [92362] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21472026/10/01 09:53:39 OK 20241026095416_initial_model.sql (96.66ms)21482026/10/01 09:53:39 OK 20241026095416_initial_model.sql (97.17ms)21492026/10/01 09:53:39 OK 20260920000000_drop_claims.sql (11.73ms)21502026/10/01 09:53:39 OK 20251210153512_drop_unused_gin_index.sql (4.01ms)21512026/10/01 09:53:39 OK 20260923120000_add_pushes.sql (3.21ms)21522026/10/01 09:53:39 goose: successfully migrated database to version: 2026092312000021532026/10/01 09:53:39 OK 20251210153512_drop_unused_gin_index.sql (3.27ms)21542026/10/01 09:53:39 OK 1_commit_pending_closure.sql (3.18ms)21552026/10/01 09:53:39 OK 2_object_stats_trigger.sql (683.42µs)21562026/10/01 09:53:39 OK 3_commit_push.sql (532.83µs)21572026/10/01 09:53:39 goose: up to current file version: 321582026/10/01 09:53:39 OK 20251218171726_add_pins.sql (22.04ms)21592026/10/01 09:53:39 OK 20251218171726_add_pins.sql (21.33ms)21602026/10/01 09:53:39 OK 20260628120000_add_object_size_and_stats.sql (18.29ms)21612026/10/01 09:53:39 OK 20260628120000_add_object_size_and_stats.sql (19.37ms)21622026/10/01 09:53:39 OK 20260905000000_add_claims.sql (24.79ms)21632026/10/01 09:53:39 OK 20260905000000_add_claims.sql (29.59ms)21642026/10/01 09:53:39 OK 20260920000000_drop_claims.sql (14.64ms)21652026/10/01 09:53:39 OK 20260920000000_drop_claims.sql (9.48ms)21662026/10/01 09:53:39 OK 20260923120000_add_pushes.sql (4.49ms)21672026/10/01 09:53:39 goose: successfully migrated database to version: 2026092312000021682026/10/01 09:53:39 OK 1_commit_pending_closure.sql (2.97ms)21692026/10/01 09:53:39 OK 2_object_stats_trigger.sql (513.08µs)21702026/10/01 09:53:39 OK 3_commit_push.sql (351.63µs)21712026/10/01 09:53:39 goose: up to current file version: 321722026/10/01 09:53:39 OK 20260923120000_add_pushes.sql (11ms)21732026/10/01 09:53:39 goose: successfully migrated database to version: 2026092312000021742026/10/01 09:53:39 OK 1_commit_pending_closure.sql (2.54ms)21752026/10/01 09:53:39 OK 2_object_stats_trigger.sql (640.21µs)21762026/10/01 09:53:39 OK 3_commit_push.sql (351.5µs)21772026/10/01 09:53:39 goose: up to current file version: 321782026/10/01 09:53:39 OK 20241026095416_initial_model.sql (92.97ms)21792026/10/01 09:53:39 OK 20251210153512_drop_unused_gin_index.sql (8.82ms)21802026/10/01 09:53:39 OK 20251218171726_add_pins.sql (24.46ms)21812026/10/01 09:53:39 OK 20260628120000_add_object_size_and_stats.sql (41.49ms)21822026/10/01 09:53:39 OK 20260905000000_add_claims.sql (65.96ms)21832026/10/01 09:53:39 OK 20260920000000_drop_claims.sql (45.31ms)21842026/10/01 09:53:39 OK 20260923120000_add_pushes.sql (24.42ms)21852026/10/01 09:53:39 goose: successfully migrated database to version: 2026092312000021862026/10/01 09:53:39 OK 1_commit_pending_closure.sql (5.24ms)21872026/10/01 09:53:39 OK 2_object_stats_trigger.sql (866.63µs)21882026/10/01 09:53:39 OK 3_commit_push.sql (583.42µs)21892026/10/01 09:53:39 goose: up to current file version: 321902026/10/01 09:53:39 INFO Received uploads request method=POST path=/api/pending_closures21912026/10/01 09:53:39 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021922026/10/01 09:53:39 INFO Received create pin request method=POST path=/api/pins/myapp21932026/10/01 09:53:39 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-91990-792741325/TestPinProtectsFromGC3157975810/001/store/aw8yaakyfq1kxc4v6i5kimvgzl0vj8l1-pinned-file.txt narinfo_key=aw8yaakyfq1kxc4v6i5kimvgzl0vj8l1.narinfo21942026/10/01 09:53:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures21952026/10/01 09:53:39 INFO Garbage collection started21962026/10/01 09:53:39 INFO Aborted multipart uploads count=021972026/10/01 09:53:39 WARN Force mode enabled - objects will be deleted immediately without grace period21982026/10/01 09:53:39 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021992026/10/01 09:53:39 INFO Vacuumed table table=pending_closures22002026/10/01 09:53:39 INFO Vacuumed table table=pending_objects22012026/10/01 09:53:39 INFO Vacuumed table table=multipart_uploads22022026/10/01 09:53:39 INFO Vacuumed table table=closures22032026/10/01 09:53:39 INFO Vacuumed table table=objects22042026/10/01 09:53:39 INFO Received uploads request method=POST path=/api/pending_closures22052026/10/01 09:53:39 INFO Received cleanup request method=DELETE path=/api/pending_closures22062026/10/01 09:53:40 INFO Received uploads request method=POST path=/api/pending_closures22072026-10-01 09:53:40.139 UTC [92363] ERROR: relation "goose_db_version" does not exist at character 3622082026-10-01 09:53:40.139 UTC [92363] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2209=== NAME TestOrphanedObjectsGC2210 orphaned_objects_gc_test.go:290: GC Test Summary:2211 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2212 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2213 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2214 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2215 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2216--- PASS: TestOrphanedObjectsGC (2.56s)2217=== CONT TestClientPushesUseOnePush22182026/10/01 09:53:40 INFO Received cleanup request method=DELETE path=/api/pending_closures22192026/10/01 09:53:40 INFO Aborted multipart uploads count=12220--- PASS: TestMultipartCleanup (2.28s)2221=== CONT TestCreatePendingClosureRejectsOversizedNAR22222026/10/01 09:53:40 INFO Received uploads request method=POST path=/api/pending_closures2223--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2224=== CONT TestCacheConfigHandler2225=== RUN TestCacheConfigHandler/full_config,_no_issuer2226=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2227=== RUN TestCacheConfigHandler/no_cache_url_configured2228=== PAUSE TestCacheConfigHandler/no_cache_url_configured2229=== RUN TestCacheConfigHandler/no_signing_keys2230=== PAUSE TestCacheConfigHandler/no_signing_keys2231=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2232=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2233=== CONT TestClientCADerivations22342026/10/01 09:53:40 INFO Received uploads request method=POST path=/api/pending_closures22352026/10/01 09:53:40 OK 20241026095416_initial_model.sql (182.6ms)22362026/10/01 09:53:40 OK 20251210153512_drop_unused_gin_index.sql (9.71ms)22372026/10/01 09:53:40 OK 20251218171726_add_pins.sql (50.9ms)2238--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (2.59s)2239=== CONT TestClientErrorHandling2240=== RUN TestClientErrorHandling/InvalidStorePath2241=== PAUSE TestClientErrorHandling/InvalidStorePath2242=== RUN TestClientErrorHandling/InvalidAuthToken2243=== PAUSE TestClientErrorHandling/InvalidAuthToken2244=== RUN TestClientErrorHandling/ServerNotAvailable2245=== PAUSE TestClientErrorHandling/ServerNotAvailable2246=== CONT TestClientMultipleUploads22472026/10/01 09:53:40 OK 20260628120000_add_object_size_and_stats.sql (46.04ms)22482026/10/01 09:53:40 OK 20260905000000_add_claims.sql (53.45ms)22492026-10-01 09:53:40.554 UTC [92369] ERROR: relation "goose_db_version" does not exist at character 3622502026-10-01 09:53:40.554 UTC [92369] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22512026/10/01 09:53:40 OK 20260920000000_drop_claims.sql (33.79ms)22522026/10/01 09:53:40 OK 20260923120000_add_pushes.sql (18.38ms)22532026/10/01 09:53:40 goose: successfully migrated database to version: 2026092312000022542026/10/01 09:53:40 OK 1_commit_pending_closure.sql (4.14ms)22552026/10/01 09:53:40 OK 2_object_stats_trigger.sql (733.42µs)22562026/10/01 09:53:40 OK 3_commit_push.sql (507.71µs)22572026/10/01 09:53:40 goose: up to current file version: 322582026-10-01 09:53:40.680 UTC [92371] ERROR: relation "goose_db_version" does not exist at character 3622592026-10-01 09:53:40.680 UTC [92371] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22602026/10/01 09:53:40 OK 20241026095416_initial_model.sql (145ms)22612026/10/01 09:53:40 OK 20251210153512_drop_unused_gin_index.sql (9.14ms)2262--- PASS: TestMetricsInventory (2.73s)2263=== CONT TestClientIntegration22642026/10/01 09:53:40 OK 20251218171726_add_pins.sql (40.61ms)22652026/10/01 09:53:40 OK 20260628120000_add_object_size_and_stats.sql (46.78ms)22662026/10/01 09:53:40 OK 20260905000000_add_claims.sql (63.55ms)22672026/10/01 09:53:40 OK 20260920000000_drop_claims.sql (73.79ms)22682026/10/01 09:53:41 OK 20241026095416_initial_model.sql (248.72ms)22692026/10/01 09:53:41 OK 20251210153512_drop_unused_gin_index.sql (14.82ms)22702026/10/01 09:53:41 OK 20260923120000_add_pushes.sql (32.13ms)22712026/10/01 09:53:41 goose: successfully migrated database to version: 2026092312000022722026/10/01 09:53:41 WARN mTLS auth: subject not in bound subjects subject="CN=reader"22732026/10/01 09:53:41 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2274--- PASS: TestService_NativeMTLS (2.54s)2275=== CONT TestCacheStatsHandler22762026/10/01 09:53:41 OK 1_commit_pending_closure.sql (7.69ms)22772026/10/01 09:53:41 OK 2_object_stats_trigger.sql (1.41ms)22782026/10/01 09:53:41 OK 3_commit_push.sql (2.58ms)22792026/10/01 09:53:41 goose: up to current file version: 322802026/10/01 09:53:41 OK 20251218171726_add_pins.sql (25.33ms)22812026/10/01 09:53:41 OK 20260628120000_add_object_size_and_stats.sql (35.9ms)22822026/10/01 09:53:41 OK 20260905000000_add_claims.sql (33.78ms)22832026/10/01 09:53:41 OK 20260920000000_drop_claims.sql (34.96ms)22842026/10/01 09:53:41 OK 20260923120000_add_pushes.sql (30.17ms)22852026/10/01 09:53:41 goose: successfully migrated database to version: 2026092312000022862026/10/01 09:53:41 OK 1_commit_pending_closure.sql (4.4ms)22872026/10/01 09:53:41 OK 2_object_stats_trigger.sql (729.71µs)22882026/10/01 09:53:41 OK 3_commit_push.sql (462.54µs)22892026/10/01 09:53:41 goose: up to current file version: 32290=== NAME TestPinProtectsFromGC2291 client_integration_test.go:840: Pin successfully protected closure from garbage collection2292--- PASS: TestPinProtectsFromGC (6.81s)2293=== CONT TestService_AuthMiddleware_OIDC22942026/10/01 09:53:41 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56429/oidc2295=== NAME TestNARDeduplicationMetadataUploadBug2296 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-91990-792741325/TestNARDeduplicationMetadataUploadBug827782656/001/store/1wpgjwy2h5kq4f4lrb27wlrw12pp6p1v-file1.txt22972026/10/01 09:53:42 INFO Received uploads request method=POST path=/api/pending_closures22982026/10/01 09:53:42 INFO Received push request method=POST path=/api/pushes22992026/10/01 09:53:42 INFO Received uploads request method=POST path=/api/pending_closures23002026/10/01 09:53:42 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)23012026/10/01 09:53:42 INFO Uploading bgj0dxd3kdhlpcd98jybqzcs0yw1w4li-b (248B)23022026/10/01 09:53:42 INFO Uploading dmzk833rp11fb3bdpv7aqgh3kznp10ai-shared-dep (136B)23032026/10/01 09:53:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23042026/10/01 09:53:42 INFO Uploading 1wpgjwy2h5kq4f4lrb27wlrw12pp6p1v-file1.txt (160B)23052026/10/01 09:53:42 WARN Failed to register uploaded object key=dmzk833rp11fb3bdpv7aqgh3kznp10ai.ls error="server returned 404: 404 page not found\n"23062026/10/01 09:53:42 WARN Failed to register uploaded object key=bgj0dxd3kdhlpcd98jybqzcs0yw1w4li.ls error="server returned 404: 404 page not found\n"23072026/10/01 09:53:42 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"23082026/10/01 09:53:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign23092026/10/01 09:53:42 WARN Failed to register uploaded object key=4pkw4s16pm7xrrqkcz3ww8xlq2qybzxw.ls error="server returned 404: 404 page not found\n"23102026/10/01 09:53:42 WARN Failed to register uploaded object key=nar/0xv8i1kfjnmrvxji7a7fqcp40gn064qfnqxsyn0gbrv78njsyaxh.nar.zst error="server returned 404: 404 page not found\n"23112026/10/01 09:53:42 INFO Signed narinfos id=2 count=223122026/10/01 09:53:42 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"23132026/10/01 09:53:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign23142026/10/01 09:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23152026/10/01 09:53:42 INFO Signed narinfos id=1 count=223162026/10/01 09:53:42 WARN Failed to register uploaded object key=1wpgjwy2h5kq4f4lrb27wlrw12pp6p1v.ls error="server returned 404: 404 page not found\n"23172026/10/01 09:53:42 INFO Signed narinfos id=1 count=123182026/10/01 09:53:42 INFO Uploading 4 narinfos23192026/10/01 09:53:42 INFO Uploading 1 narinfos23202026/10/01 09:53:42 INFO Received complete push request method=POST path=/api/pushes/1/complete23212026/10/01 09:53:42 WARN Failed to register uploaded object key=1wpgjwy2h5kq4f4lrb27wlrw12pp6p1v.narinfo error="server returned 404: 404 page not found\n"23222026/10/01 09:53:42 WARN Failed to register uploaded object key=bgj0dxd3kdhlpcd98jybqzcs0yw1w4li.narinfo error="server returned 404: 404 page not found\n"23232026/10/01 09:53:42 WARN Failed to register uploaded object key=dmzk833rp11fb3bdpv7aqgh3kznp10ai.narinfo error="server returned 404: 404 page not found\n"23242026/10/01 09:53:42 WARN Failed to register uploaded object key=4pkw4s16pm7xrrqkcz3ww8xlq2qybzxw.narinfo error="server returned 404: 404 page not found\n"23252026/10/01 09:53:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete23262026/10/01 09:53:42 WARN Failed to register uploaded object key=dmzk833rp11fb3bdpv7aqgh3kznp10ai.narinfo error="server returned 404: 404 page not found\n"23272026/10/01 09:53:42 INFO Upload complete. (158ms)2328 metadata_upload_test.go:54: Retrieved narinfo from S3:2329 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestNARDeduplicationMetadataUploadBug827782656/001/store/1wpgjwy2h5kq4f4lrb27wlrw12pp6p1v-file1.txt2330 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2331 Compression: zstd2332 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2333 NarSize: 1602334 References: 2335 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2336 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2337 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2338 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}23392026/10/01 09:53:42 INFO Completed upload id=123402026/10/01 09:53:42 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete23412026/10/01 09:53:42 INFO Completed upload id=223422026/10/01 09:53:42 INFO Upload complete. (184ms)2343=== NAME TestClientFallsBackToClosures2344 client_pushes_test.go:112: Retrieved narinfo from S3:2345 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestClientFallsBackToClosures2568189638/001/store/dmzk833rp11fb3bdpv7aqgh3kznp10ai-shared-dep2346 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2347 Compression: zstd2348 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822349 NarSize: 1362350 References: 2351 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2352 client_pushes_test.go:112: Retrieved narinfo from S3:2353 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestClientFallsBackToClosures2568189638/001/store/4pkw4s16pm7xrrqkcz3ww8xlq2qybzxw-a2354 URL: nar/0xv8i1kfjnmrvxji7a7fqcp40gn064qfnqxsyn0gbrv78njsyaxh.nar.zst2355 Compression: zstd2356 NarHash: sha256:0xv8i1kfjnmrvxji7a7fqcp40gn064qfnqxsyn0gbrv78njsyaxh2357 NarSize: 2482358 References: /nix/var/nix/builds/nix-91990-792741325/TestClientFallsBackToClosures2568189638/001/store/dmzk833rp11fb3bdpv7aqgh3kznp10ai-shared-dep2359 CA: text:sha256:1q4wakrjsn5fihqksf2qi3jyafa64rharx0rj9dw538vg6wb03bd2360 client_pushes_test.go:112: Retrieved narinfo from S3:2361 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestClientFallsBackToClosures2568189638/001/store/bgj0dxd3kdhlpcd98jybqzcs0yw1w4li-b2362 URL: nar/0xv8i1kfjnmrvxji7a7fqcp40gn064qfnqxsyn0gbrv78njsyaxh.nar.zst2363 Compression: zstd2364 NarHash: sha256:0xv8i1kfjnmrvxji7a7fqcp40gn064qfnqxsyn0gbrv78njsyaxh2365 NarSize: 2482366 References: /nix/var/nix/builds/nix-91990-792741325/TestClientFallsBackToClosures2568189638/001/store/dmzk833rp11fb3bdpv7aqgh3kznp10ai-shared-dep2367 CA: text:sha256:1q4wakrjsn5fihqksf2qi3jyafa64rharx0rj9dw538vg6wb03bd2368--- PASS: TestClientFallsBackToClosures (3.49s)2369=== CONT TestService_ReadScope_PublicByDefault2370=== NAME TestNARDeduplicationMetadataUploadBug2371 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-91990-792741325/TestNARDeduplicationMetadataUploadBug827782656/001/store/rsw64458c49yapy4h3lrdwyf65r689ys-file2.txt23722026/10/01 09:53:42 INFO Received push request method=POST path=/api/pushes23732026/10/01 09:53:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)23742026/10/01 09:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign23752026/10/01 09:53:42 INFO Signed narinfos id=2 count=123762026/10/01 09:53:42 INFO Uploading 1 narinfos23772026/10/01 09:53:42 WARN Failed to register uploaded object key=rsw64458c49yapy4h3lrdwyf65r689ys.ls error="server returned 404: 404 page not found\n"23782026/10/01 09:53:42 INFO Received complete push request method=POST path=/api/pushes/2/complete23792026/10/01 09:53:42 WARN Failed to register uploaded object key=rsw64458c49yapy4h3lrdwyf65r689ys.narinfo error="server returned 404: 404 page not found\n"23802026/10/01 09:53:42 INFO Upload complete. (101ms)2381 metadata_upload_test.go:76: Retrieved narinfo from S3:2382 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestNARDeduplicationMetadataUploadBug827782656/001/store/rsw64458c49yapy4h3lrdwyf65r689ys-file2.txt2383 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2384 Compression: zstd2385 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2386 NarSize: 1602387 References: 2388 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf23892026-10-01 09:53:42.359 UTC [92402] ERROR: relation "goose_db_version" does not exist at character 3623902026-10-01 09:53:42.359 UTC [92402] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23912026-10-01 09:53:42.359 UTC [92401] ERROR: relation "goose_db_version" does not exist at character 3623922026-10-01 09:53:42.359 UTC [92401] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2393 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2394 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2395 {"version":1,"root":{"type":"regular","size":44}}2396--- PASS: TestNARDeduplicationMetadataUploadBug (3.61s)2397=== CONT TestService_RequireScope_OIDC23982026/10/01 09:53:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56455/oidc23992026/10/01 09:53:42 OK 20241026095416_initial_model.sql (138.7ms)24002026/10/01 09:53:42 OK 20241026095416_initial_model.sql (140.66ms)24012026/10/01 09:53:42 OK 20251210153512_drop_unused_gin_index.sql (2.09ms)24022026/10/01 09:53:42 OK 20251210153512_drop_unused_gin_index.sql (8.89ms)24032026/10/01 09:53:42 OK 20251218171726_add_pins.sql (23.54ms)24042026/10/01 09:53:42 OK 20251218171726_add_pins.sql (37.67ms)24052026/10/01 09:53:42 OK 20260628120000_add_object_size_and_stats.sql (45.1ms)24062026/10/01 09:53:42 OK 20260628120000_add_object_size_and_stats.sql (30.03ms)24072026-10-01 09:53:42.663 UTC [92406] ERROR: relation "goose_db_version" does not exist at character 3624082026-10-01 09:53:42.663 UTC [92406] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24092026/10/01 09:53:42 OK 20260905000000_add_claims.sql (50.78ms)24102026/10/01 09:53:42 OK 20260905000000_add_claims.sql (63ms)24112026/10/01 09:53:42 OK 20260920000000_drop_claims.sql (39.95ms)24122026/10/01 09:53:42 OK 20260923120000_add_pushes.sql (16.01ms)24132026/10/01 09:53:42 goose: successfully migrated database to version: 2026092312000024142026/10/01 09:53:42 OK 1_commit_pending_closure.sql (1.68ms)24152026/10/01 09:53:42 OK 2_object_stats_trigger.sql (389.5µs)24162026/10/01 09:53:42 OK 3_commit_push.sql (315.79µs)24172026/10/01 09:53:42 goose: up to current file version: 324182026/10/01 09:53:42 OK 20260920000000_drop_claims.sql (44.37ms)24192026/10/01 09:53:42 OK 20260923120000_add_pushes.sql (23.94ms)24202026/10/01 09:53:42 goose: successfully migrated database to version: 2026092312000024212026/10/01 09:53:42 OK 1_commit_pending_closure.sql (2.66ms)24222026/10/01 09:53:42 OK 2_object_stats_trigger.sql (413.58µs)24232026/10/01 09:53:42 OK 3_commit_push.sql (326.33µs)24242026/10/01 09:53:42 goose: up to current file version: 324252026-10-01 09:53:42.816 UTC [92407] ERROR: relation "goose_db_version" does not exist at character 3624262026-10-01 09:53:42.816 UTC [92407] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24272026/10/01 09:53:43 OK 20241026095416_initial_model.sql (292.61ms)24282026/10/01 09:53:43 OK 20251210153512_drop_unused_gin_index.sql (10.72ms)24292026/10/01 09:53:43 OK 20251218171726_add_pins.sql (47.04ms)24302026/10/01 09:53:43 OK 20260628120000_add_object_size_and_stats.sql (50.99ms)24312026/10/01 09:53:43 OK 20241026095416_initial_model.sql (327.78ms)24322026/10/01 09:53:43 OK 20260905000000_add_claims.sql (109.79ms)24332026/10/01 09:53:43 OK 20251210153512_drop_unused_gin_index.sql (11.64ms)24342026/10/01 09:53:43 OK 20260920000000_drop_claims.sql (52.52ms)24352026/10/01 09:53:43 OK 20251218171726_add_pins.sql (42.3ms)24362026/10/01 09:53:43 OK 20260923120000_add_pushes.sql (22.02ms)24372026/10/01 09:53:43 goose: successfully migrated database to version: 2026092312000024382026-10-01 09:53:43.315 UTC [92408] ERROR: relation "goose_db_version" does not exist at character 3624392026-10-01 09:53:43.315 UTC [92408] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24402026/10/01 09:53:43 OK 1_commit_pending_closure.sql (1.92ms)24412026/10/01 09:53:43 OK 2_object_stats_trigger.sql (381.88µs)24422026/10/01 09:53:43 OK 3_commit_push.sql (213.88µs)24432026/10/01 09:53:43 goose: up to current file version: 324442026/10/01 09:53:43 OK 20260628120000_add_object_size_and_stats.sql (40.21ms)24452026/10/01 09:53:43 OK 20260905000000_add_claims.sql (86.42ms)24462026/10/01 09:53:43 OK 20260920000000_drop_claims.sql (54.9ms)24472026/10/01 09:53:43 OK 20260923120000_add_pushes.sql (23.46ms)24482026/10/01 09:53:43 goose: successfully migrated database to version: 2026092312000024492026/10/01 09:53:43 OK 1_commit_pending_closure.sql (3.05ms)24502026/10/01 09:53:43 OK 2_object_stats_trigger.sql (696.58µs)24512026/10/01 09:53:43 OK 3_commit_push.sql (427.25µs)24522026/10/01 09:53:43 goose: up to current file version: 324532026/10/01 09:53:43 OK 20241026095416_initial_model.sql (260.68ms)24542026/10/01 09:53:43 OK 20251210153512_drop_unused_gin_index.sql (12.44ms)24552026/10/01 09:53:43 OK 20251218171726_add_pins.sql (38.92ms)24562026/10/01 09:53:43 OK 20260628120000_add_object_size_and_stats.sql (31.06ms)24572026/10/01 09:53:43 OK 20260905000000_add_claims.sql (70.35ms)24582026/10/01 09:53:43 OK 20260920000000_drop_claims.sql (42.78ms)24592026/10/01 09:53:43 OK 20260923120000_add_pushes.sql (14.81ms)24602026/10/01 09:53:43 goose: successfully migrated database to version: 2026092312000024612026/10/01 09:53:43 OK 1_commit_pending_closure.sql (1.18ms)24622026/10/01 09:53:43 OK 2_object_stats_trigger.sql (241.42µs)24632026/10/01 09:53:43 OK 3_commit_push.sql (177.25µs)24642026/10/01 09:53:43 goose: up to current file version: 324652026/10/01 09:53:43 INFO Received push request method=POST path=/api/pushes24662026/10/01 09:53:44 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)24672026/10/01 09:53:44 INFO Uploading k535qz4q432yjlhrzn6y2flzdxd4n1a4-a (248B)24682026/10/01 09:53:44 INFO Uploading g0dpfia2xsiswnp1pp2k95yz177drcn0-shared-dep (136B)24692026/10/01 09:53:44 WARN Failed to register uploaded object key=g0dpfia2xsiswnp1pp2k95yz177drcn0.ls error="server returned 404: 404 page not found\n"24702026/10/01 09:53:44 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24712026/10/01 09:53:44 WARN Failed to register uploaded object key=ha687iw71ff0qnhd4yjw20bqcnsxlm87.ls error="server returned 404: 404 page not found\n"24722026/10/01 09:53:44 WARN Failed to register uploaded object key=k535qz4q432yjlhrzn6y2flzdxd4n1a4.ls error="server returned 404: 404 page not found\n"24732026/10/01 09:53:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24742026/10/01 09:53:44 WARN Failed to register uploaded object key=nar/0lixjra6djh3lzq8pagaq129fb40f85z1b6aipgpa9jr4sckyqdh.nar.zst error="server returned 404: 404 page not found\n"24752026/10/01 09:53:44 INFO Signed narinfos id=1 count=324762026/10/01 09:53:44 INFO Uploading 3 narinfos24772026-10-01 09:53:44.067 UTC [92426] ERROR: relation "goose_db_version" does not exist at character 3624782026-10-01 09:53:44.067 UTC [92426] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24792026/10/01 09:53:44 WARN Failed to register uploaded object key=g0dpfia2xsiswnp1pp2k95yz177drcn0.narinfo error="server returned 404: 404 page not found\n"24802026/10/01 09:53:44 WARN Failed to register uploaded object key=k535qz4q432yjlhrzn6y2flzdxd4n1a4.narinfo error="server returned 404: 404 page not found\n"24812026/10/01 09:53:44 INFO Received complete push request method=POST path=/api/pushes/1/complete24822026/10/01 09:53:44 WARN Failed to register uploaded object key=ha687iw71ff0qnhd4yjw20bqcnsxlm87.narinfo error="server returned 404: 404 page not found\n"24832026/10/01 09:53:44 INFO Upload complete. (218ms)2484=== NAME TestClientPushesUseOnePush2485 client_pushes_test.go:97: Retrieved narinfo from S3:2486 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestClientPushesUseOnePush3134957314/001/store/g0dpfia2xsiswnp1pp2k95yz177drcn0-shared-dep2487 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2488 Compression: zstd2489 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822490 NarSize: 1362491 References: 2492 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2493 client_pushes_test.go:97: Retrieved narinfo from S3:2494 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestClientPushesUseOnePush3134957314/001/store/k535qz4q432yjlhrzn6y2flzdxd4n1a4-a2495 URL: nar/0lixjra6djh3lzq8pagaq129fb40f85z1b6aipgpa9jr4sckyqdh.nar.zst2496 Compression: zstd2497 NarHash: sha256:0lixjra6djh3lzq8pagaq129fb40f85z1b6aipgpa9jr4sckyqdh2498 NarSize: 2482499 References: /nix/var/nix/builds/nix-91990-792741325/TestClientPushesUseOnePush3134957314/001/store/g0dpfia2xsiswnp1pp2k95yz177drcn0-shared-dep2500 CA: text:sha256:0x6bpllnwbfs9385vnxap8y34alf9s590w1dphnl8bghcgb2c60r2501 client_pushes_test.go:97: Retrieved narinfo from S3:2502 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestClientPushesUseOnePush3134957314/001/store/ha687iw71ff0qnhd4yjw20bqcnsxlm87-b2503 URL: nar/0lixjra6djh3lzq8pagaq129fb40f85z1b6aipgpa9jr4sckyqdh.nar.zst2504 Compression: zstd2505 NarHash: sha256:0lixjra6djh3lzq8pagaq129fb40f85z1b6aipgpa9jr4sckyqdh2506 NarSize: 2482507 References: /nix/var/nix/builds/nix-91990-792741325/TestClientPushesUseOnePush3134957314/001/store/g0dpfia2xsiswnp1pp2k95yz177drcn0-shared-dep2508 CA: text:sha256:0x6bpllnwbfs9385vnxap8y34alf9s590w1dphnl8bghcgb2c60r2509=== NAME TestClientMultipleUploads2510 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-91990-792741325/TestClientMultipleUploads2040032163/001/store/43ycfk3phday85k70vlqcjcndpwmvz81-test-file-0.txt2511=== NAME TestClientCADerivations2512 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-91990-792741325/TestClientCADerivations2661701718/001/store/v1lchibx3jamqxak7lvlrxvahkllhz0v-ca-test2513 client_ca_test.go:139: Found 1 dependencies (including self)2514--- PASS: TestClientPushesUseOnePush (3.99s)2515=== CONT TestService_AuthMiddleware_MTLSBoundSubjects2516=== NAME TestClientMultipleUploads2517 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-91990-792741325/TestClientMultipleUploads2040032163/001/store/n5syrvrmhmapsf3z7d2wgvm8axkwywrf-test-file-1.txt25182026/10/01 09:53:44 INFO Received push request method=POST path=/api/pushes25192026/10/01 09:53:44 OK 20241026095416_initial_model.sql (223.06ms)25202026/10/01 09:53:44 OK 20251210153512_drop_unused_gin_index.sql (8.79ms)25212026/10/01 09:53:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25222026/10/01 09:53:44 INFO Uploading v1lchibx3jamqxak7lvlrxvahkllhz0v-ca-test (144B)2523 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-91990-792741325/TestClientMultipleUploads2040032163/001/store/1dsi9zym38d0qwz4sr73cqniwb3393s2-test-file-2.txt25242026/10/01 09:53:44 OK 20251218171726_add_pins.sql (26.39ms)25252026/10/01 09:53:44 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"25262026/10/01 09:53:44 WARN Failed to register uploaded object key=v1lchibx3jamqxak7lvlrxvahkllhz0v.ls error="server returned 404: 404 page not found\n"25272026/10/01 09:53:44 WARN Failed to register uploaded object key=log/1405fzq4nws38lwsgk2wrm3a8sx54x4k-ca-test.drv error="server returned 404: 404 page not found\n"25282026/10/01 09:53:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25292026/10/01 09:53:44 INFO Signed narinfos id=1 count=125302026/10/01 09:53:44 INFO Uploading 1 narinfos25312026/10/01 09:53:44 OK 20260628120000_add_object_size_and_stats.sql (48.55ms)25322026/10/01 09:53:44 INFO Received complete push request method=POST path=/api/pushes/1/complete25332026/10/01 09:53:44 WARN Failed to register uploaded object key=v1lchibx3jamqxak7lvlrxvahkllhz0v.narinfo error="server returned 404: 404 page not found\n"25342026/10/01 09:53:44 INFO Received push request method=POST path=/api/pushes25352026/10/01 09:53:44 INFO Upload complete. (242ms)2536=== NAME TestClientIntegration2537 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-91990-792741325/TestClientIntegration3649696705/002/store/yxq48jlhy4rk2hnysr3fxzw5667bn7c0-test-file.txt2538=== NAME TestClientCADerivations2539 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-91990-792741325/TestClientCADerivations2661701718/001/store/v1lchibx3jamqxak7lvlrxvahkllhz0v-ca-test2540 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2541 Compression: zstd2542 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2543 NarSize: 1442544 References: 2545 Deriver: /nix/var/nix/builds/nix-91990-792741325/TestClientCADerivations2661701718/001/store/1405fzq4nws38lwsgk2wrm3a8sx54x4k-ca-test.drv2546 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2547 client_ca_test.go:185: Checking for realisation files in S3...2548 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2549 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache25502026/10/01 09:53:44 OK 20260905000000_add_claims.sql (43.86ms)25512026-10-01 09:53:44.464 UTC [92446] ERROR: relation "goose_db_version" does not exist at character 3625522026-10-01 09:53:44.464 UTC [92446] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25532026/10/01 09:53:44 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)25542026/10/01 09:53:44 INFO Uploading 1dsi9zym38d0qwz4sr73cqniwb3393s2-test-file-2.txt (160B)25552026/10/01 09:53:44 INFO Uploading n5syrvrmhmapsf3z7d2wgvm8axkwywrf-test-file-1.txt (160B)25562026/10/01 09:53:44 INFO Uploading 43ycfk3phday85k70vlqcjcndpwmvz81-test-file-0.txt (160B)25572026/10/01 09:53:44 OK 20260920000000_drop_claims.sql (21.93ms)25582026/10/01 09:53:44 WARN Failed to register uploaded object key=1dsi9zym38d0qwz4sr73cqniwb3393s2.ls error="server returned 404: 404 page not found\n"25592026/10/01 09:53:44 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"25602026/10/01 09:53:44 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"25612026/10/01 09:53:44 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"2562--- PASS: TestCacheStatsHandler (3.45s)2563=== CONT TestService_AuthMiddleware_MTLSProxyHeader25642026/10/01 09:53:44 WARN Failed to register uploaded object key=n5syrvrmhmapsf3z7d2wgvm8axkwywrf.ls error="server returned 404: 404 page not found\n"25652026/10/01 09:53:44 OK 20260923120000_add_pushes.sql (9.31ms)25662026/10/01 09:53:44 goose: successfully migrated database to version: 2026092312000025672026/10/01 09:53:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25682026/10/01 09:53:44 WARN Failed to register uploaded object key=43ycfk3phday85k70vlqcjcndpwmvz81.ls error="server returned 404: 404 page not found\n"25692026/10/01 09:53:44 INFO Signed narinfos id=1 count=325702026/10/01 09:53:44 INFO Uploading 3 narinfos25712026/10/01 09:53:44 OK 1_commit_pending_closure.sql (2.06ms)25722026/10/01 09:53:44 OK 2_object_stats_trigger.sql (302.13µs)25732026/10/01 09:53:44 OK 3_commit_push.sql (201.25µs)25742026/10/01 09:53:44 goose: up to current file version: 325752026/10/01 09:53:44 WARN Failed to register uploaded object key=1dsi9zym38d0qwz4sr73cqniwb3393s2.narinfo error="server returned 404: 404 page not found\n"25762026/10/01 09:53:44 WARN Failed to register uploaded object key=n5syrvrmhmapsf3z7d2wgvm8axkwywrf.narinfo error="server returned 404: 404 page not found\n"25772026/10/01 09:53:44 INFO Received complete push request method=POST path=/api/pushes/1/complete25782026/10/01 09:53:44 WARN Failed to register uploaded object key=43ycfk3phday85k70vlqcjcndpwmvz81.narinfo error="server returned 404: 404 page not found\n"25792026/10/01 09:53:44 INFO Upload complete. (161ms)2580=== NAME TestClientMultipleUploads2581 client_integration_test.go:369: Uploaded 3 paths in 195.664792ms25822026/10/01 09:53:44 INFO Received push request method=POST path=/api/pushes25832026/10/01 09:53:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25842026/10/01 09:53:44 INFO Uploading yxq48jlhy4rk2hnysr3fxzw5667bn7c0-test-file.txt (152B)25852026/10/01 09:53:44 WARN Failed to register uploaded object key=yxq48jlhy4rk2hnysr3fxzw5667bn7c0.ls error="server returned 404: 404 page not found\n"2586=== NAME TestClientCADerivations2587 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket72?endpoint=http://localhost:56118®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-91990-792741325/TestClientCADerivations2661701718/001/store'2588 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 125892026/10/01 09:53:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25902026/10/01 09:53:44 INFO Signed narinfos id=1 count=125912026/10/01 09:53:44 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"25922026/10/01 09:53:44 INFO Uploading 1 narinfos25932026/10/01 09:53:44 INFO Received complete push request method=POST path=/api/pushes/1/complete25942026/10/01 09:53:44 WARN Failed to register uploaded object key=yxq48jlhy4rk2hnysr3fxzw5667bn7c0.narinfo error="server returned 404: 404 page not found\n"2595--- PASS: TestClientMultipleUploads (4.15s)2596=== CONT TestService_ReadAuthMiddleware25972026/10/01 09:53:44 INFO Upload complete. (161ms)25982026/10/01 09:53:44 INFO All 1 paths already cached2599=== NAME TestClientIntegration2600 client_integration_test.go:312: Retrieved narinfo from S3:2601 StorePath: /nix/var/nix/builds/nix-91990-792741325/TestClientIntegration3649696705/002/store/yxq48jlhy4rk2hnysr3fxzw5667bn7c0-test-file.txt2602 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2603 Compression: zstd2604 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12605 NarSize: 1522606 References: 2607 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12608 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2609 client_integration_test.go:313: Decompressed .ls content (64 bytes):2610 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2611 client_integration_test.go:316: Testing garbage collection...2612--- PASS: TestClientCADerivations (4.47s)2613=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info26142026/10/01 09:53:44 INFO Received uploads request method=POST path=/2615=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key26162026/10/01 09:53:44 INFO Received request for more parts method=POST path=/2617=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key26182026/10/01 09:53:44 INFO Received complete multipart upload request method=POST path=/2619=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal26202026/10/01 09:53:44 INFO Received uploads request method=POST path=/2621--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2622 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2623 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2624 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2625 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2626=== CONT TestProxyWriteTimeout/narinfo2627=== CONT TestProxyWriteTimeout/1_GiB_nar2628=== CONT TestProxyWriteTimeout/unknown_size2629=== CONT TestProxyWriteTimeout/10_GiB_nar2630--- PASS: TestProxyWriteTimeout (0.03s)2631 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2632 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2633 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2634 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2635=== CONT TestIsValidUploadKey/narinfo2636=== CONT TestIsValidUploadKey/realisation_plus_in_output2637=== CONT TestIsValidUploadKey/unknown_type2638=== CONT TestIsValidUploadKey/empty_key2639=== CONT TestIsValidUploadKey/absolute2640=== CONT TestIsValidUploadKey/traversal_nar2641=== CONT TestIsValidUploadKey/traversal2642=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2643=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2644=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2645=== CONT TestIsValidUploadKey/index.html2646=== CONT TestIsValidUploadKey/nix-cache-info2647=== CONT TestIsValidUploadKey/nar_plain2648=== CONT TestIsValidUploadKey/build_log_home-manager_file2649=== CONT TestIsValidUploadKey/realisation2650=== CONT TestIsValidUploadKey/build_log_equals2651=== CONT TestIsValidUploadKey/build_log2652=== CONT TestIsValidUploadKey/build_log_question_mark2653=== CONT TestIsValidUploadKey/listing2654=== CONT TestIsValidUploadKey/build_log_plus_in_name2655=== CONT TestIsValidUploadKey/nar_xz2656=== CONT TestIsValidUploadKey/nar_zst2657--- PASS: TestIsValidUploadKey (0.03s)2658 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2659 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2660 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2661 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2662 --- PASS: TestIsValidUploadKey/absolute (0.00s)2663 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2664 --- PASS: TestIsValidUploadKey/traversal (0.00s)2665 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2666 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2667 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2668 --- PASS: TestIsValidUploadKey/index.html (0.00s)2669 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2670 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2671 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2672 --- PASS: TestIsValidUploadKey/realisation (0.00s)2673 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2674 --- PASS: TestIsValidUploadKey/build_log (0.00s)2675 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2676 --- PASS: TestIsValidUploadKey/listing (0.00s)2677 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2678 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2679 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2680=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure26812026/10/01 09:53:44 INFO Received uploads request method=POST path=/26822026/10/01 09:53:44 INFO Starting cleanup of old closures method=DELETE path=/api/closures26832026/10/01 09:53:44 INFO Garbage collection started26842026/10/01 09:53:44 OK 20241026095416_initial_model.sql (216.59ms)26852026/10/01 09:53:44 INFO Aborted multipart uploads count=026862026/10/01 09:53:44 WARN Force mode enabled - objects will be deleted immediately without grace period26872026/10/01 09:53:44 OK 20251210153512_drop_unused_gin_index.sql (9.04ms)26882026/10/01 09:53:44 OK 20251218171726_add_pins.sql (43.15ms)26892026/10/01 09:53:44 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=02690=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2691=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2692=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2693=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2694=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2695=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2696=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2697=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2698=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts26992026/10/01 09:53:44 INFO Received request for more parts method=POST path=/2700=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart27012026/10/01 09:53:44 INFO Received complete multipart upload request method=POST path=/27022026/10/01 09:53:44 OK 20260628120000_add_object_size_and_stats.sql (46.33ms)27032026/10/01 09:53:44 INFO Vacuumed table table=pending_closures2704=== CONT TestPush_RejectsBadRequests/no_objects27052026/10/01 09:53:44 INFO Received push request method=POST path=/api/pushes2706=== CONT TestPush_RejectsBadRequests/root_not_in_objects27072026/10/01 09:53:44 INFO Received push request method=POST path=/api/pushes2708=== CONT TestPush_RejectsBadRequests/no_roots27092026/10/01 09:53:44 INFO Received push request method=POST path=/api/pushes2710=== CONT TestPush_RejectsBadRequests/bad_root27112026/10/01 09:53:44 INFO Received push request method=POST path=/api/pushes2712=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2713--- PASS: TestPush_RejectsBadRequests (2.71s)2714 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2715 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2716 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2717 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)27182026/10/01 09:53:44 INFO Vacuumed table table=pending_objects27192026-10-01 09:53:44.849 UTC [92463] ERROR: relation "goose_db_version" does not exist at character 3627202026-10-01 09:53:44.849 UTC [92463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27212026/10/01 09:53:44 INFO Vacuumed table table=multipart_uploads27222026/10/01 09:53:44 OK 20260905000000_add_claims.sql (50.33ms)27232026/10/01 09:53:44 INFO Vacuumed table table=closures2724=== NAME TestOrphanedObjectsGCStressTest2725 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains27262026/10/01 09:53:44 OK 20260920000000_drop_claims.sql (24.71ms)27272026/10/01 09:53:44 INFO Vacuumed table table=objects27282026/10/01 09:53:44 OK 20260923120000_add_pushes.sql (13.51ms)27292026/10/01 09:53:44 goose: successfully migrated database to version: 2026092312000027302026/10/01 09:53:44 OK 1_commit_pending_closure.sql (934.08µs)27312026/10/01 09:53:44 OK 2_object_stats_trigger.sql (225.58µs)27322026/10/01 09:53:44 OK 3_commit_push.sql (190µs)27332026/10/01 09:53:44 goose: up to current file version: 32734 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion2735--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)2736 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2737 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2738 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)2739=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check27402026/10/01 09:53:45 OK 20241026095416_initial_model.sql (168.06ms)27412026/10/01 09:53:45 OK 20251210153512_drop_unused_gin_index.sql (841.33µs)27422026/10/01 09:53:45 OK 20251218171726_add_pins.sql (25.01ms)27432026/10/01 09:53:45 OK 20260628120000_add_object_size_and_stats.sql (28.86ms)2744--- PASS: TestService_ReadScope_PublicByDefault (2.93s)2745=== CONT TestResolveDBConnectionString/flag_wins2746=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2747=== CONT TestResolveDBConnectionString/nothing_configured2748=== CONT TestResolveDBConnectionString/missing_file_is_an_error2749=== CONT TestResolveDBConnectionString/file_when_flag_empty2750=== CONT TestIsValidCachePath/narinfo2751=== CONT TestIsValidCachePath/traversal_in_middle2752=== CONT TestIsValidCachePath/traversal_parent2753=== CONT TestIsValidCachePath/index.html2754=== CONT TestIsValidCachePath/nix-cache-info2755=== CONT TestIsValidCachePath/realisation2756=== CONT TestIsValidCachePath/log2757=== CONT TestIsValidCachePath/ls2758=== CONT TestIsValidCachePath/nar_uncompressed2759=== CONT TestIsValidCachePath/nar_bz22760=== CONT TestIsValidCachePath/nar_xz2761=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2762=== CONT TestIsValidCachePath/leading_slash2763=== CONT TestIsValidCachePath/short_hash2764=== CONT TestIsValidCachePath/wrong_extension2765=== CONT TestIsValidCachePath/random_path2766=== CONT TestIsValidCachePath/empty2767=== CONT TestIsValidCachePath/nar_zst2768=== CONT TestIsValidCachePath/invalid_char_u2769=== CONT TestIsValidCachePath/invalid_char_e2770=== CONT TestParseSingleRange/none2771=== CONT TestParseSingleRange/open-ended2772=== CONT TestParseSingleRange/start_far_past_EOF2773=== CONT TestParseSingleRange/start_past_EOF2774=== CONT TestParseSingleRange/single_byte2775=== CONT TestParseSingleRange/suffix_exceeds_size2776=== CONT TestParseSingleRange/suffix2777=== CONT TestParseSingleRange/end_clamped_to_size2778--- PASS: TestIsValidCachePath (0.00s)2779 --- PASS: TestIsValidCachePath/narinfo (0.00s)2780 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2781 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2782 --- PASS: TestIsValidCachePath/index.html (0.00s)2783 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2784 --- PASS: TestIsValidCachePath/realisation (0.00s)2785 --- PASS: TestIsValidCachePath/log (0.00s)2786 --- PASS: TestIsValidCachePath/ls (0.00s)2787 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2788 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2789 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2790 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2791 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2792 --- PASS: TestIsValidCachePath/short_hash (0.00s)2793 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2794 --- PASS: TestIsValidCachePath/random_path (0.00s)2795 --- PASS: TestIsValidCachePath/empty (0.00s)2796 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2797 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2798 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2799=== CONT TestParseSingleRange/malformed_both_empty2800=== CONT TestParseSingleRange/closed2801=== CONT TestParseSingleRange/malformed_end_before_start2802=== CONT TestParseSingleRange/multi-range_ignored2803=== CONT TestParseSingleRange/malformed_no_dash2804=== CONT TestParseSingleRange/unknown_unit2805--- PASS: TestParseSingleRange (0.00s)2806 --- PASS: TestParseSingleRange/none (0.00s)2807 --- PASS: TestParseSingleRange/open-ended (0.00s)2808 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2809 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2810 --- PASS: TestParseSingleRange/single_byte (0.00s)2811 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2812 --- PASS: TestParseSingleRange/suffix (0.00s)2813 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2814 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2815 --- PASS: TestParseSingleRange/closed (0.00s)2816 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2817 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2818 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2819 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2820=== CONT TestServerTLSConfig/no_client_CA2821=== CONT TestServerTLSConfig/not_a_PEM_file2822--- PASS: TestResolveDBConnectionString (0.03s)2823 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2824 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2825 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2826 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2827 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2828=== CONT TestServerTLSConfig/missing_CA_file2829--- PASS: TestServerTLSConfig (0.00s)2830 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2831 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)2832 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2833=== CONT TestCacheConfigHandler/full_config,_no_issuer2834=== CONT TestCacheConfigHandler/no_signing_keys2835=== CONT TestCacheConfigHandler/no_cache_url_configured2836=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2837--- PASS: TestCacheConfigHandler (0.00s)2838 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2839 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2840 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2841 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2842=== CONT TestClientErrorHandling/InvalidStorePath28432026/10/01 09:53:45 OK 20260905000000_add_claims.sql (53.81ms)28442026/10/01 09:53:45 OK 20260920000000_drop_claims.sql (12.73ms)28452026/10/01 09:53:45 OK 20260923120000_add_pushes.sql (7.11ms)28462026/10/01 09:53:45 goose: successfully migrated database to version: 2026092312000028472026/10/01 09:53:45 OK 1_commit_pending_closure.sql (1.66ms)28482026/10/01 09:53:45 OK 2_object_stats_trigger.sql (295.29µs)28492026/10/01 09:53:45 OK 3_commit_push.sql (248.33µs)28502026/10/01 09:53:45 goose: up to current file version: 32851=== RUN TestService_RequireScope_OIDC/builder_may_write2852=== PAUSE TestService_RequireScope_OIDC/builder_may_write2853=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2854=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2855=== RUN TestService_RequireScope_OIDC/ops_may_admin2856=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2857=== RUN TestService_RequireScope_OIDC/ops_may_not_write2858=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2859=== RUN TestService_RequireScope_OIDC/reader_may_not_write2860=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2861=== RUN TestService_RequireScope_OIDC/static_token_may_admin2862=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2863=== RUN TestService_RequireScope_OIDC/static_token_may_write2864=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2865=== RUN TestService_RequireScope_OIDC/reader_may_read2866=== PAUSE TestService_RequireScope_OIDC/reader_may_read2867=== RUN TestService_RequireScope_OIDC/writer_implies_read2868=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2869=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2870=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2871=== CONT TestClientErrorHandling/ServerNotAvailable28722026/10/01 09:53: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/present28732026-10-01 09:53:45.658 UTC [92477] ERROR: relation "goose_db_version" does not exist at character 3628742026-10-01 09:53:45.658 UTC [92477] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28752026/10/01 09:53:45 OK 20241026095416_initial_model.sql (10.1ms)28762026/10/01 09:53:45 OK 20251210153512_drop_unused_gin_index.sql (483.79µs)28772026/10/01 09:53:45 OK 20251218171726_add_pins.sql (847.67µs)28782026-10-01 09:53:45.683 UTC [92478] ERROR: relation "goose_db_version" does not exist at character 3628792026-10-01 09:53:45.683 UTC [92478] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28802026/10/01 09:53:45 OK 20260628120000_add_object_size_and_stats.sql (31.9ms)28812026/10/01 09:53:45 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=212.365385ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28822026/10/01 09:53:45 OK 20260905000000_add_claims.sql (54.02ms)28832026/10/01 09:53:45 OK 20260920000000_drop_claims.sql (24.74ms)28842026/10/01 09:53:45 OK 20260923120000_add_pushes.sql (1.22ms)28852026/10/01 09:53:45 goose: successfully migrated database to version: 2026092312000028862026/10/01 09:53:45 OK 1_commit_pending_closure.sql (2.04ms)28872026/10/01 09:53:45 OK 2_object_stats_trigger.sql (583.17µs)28882026/10/01 09:53:45 OK 3_commit_push.sql (424.04µs)28892026/10/01 09:53:45 goose: up to current file version: 328902026/10/01 09:53:45 OK 20241026095416_initial_model.sql (79.25ms)28912026/10/01 09:53:45 OK 20251210153512_drop_unused_gin_index.sql (8.35ms)28922026/10/01 09:53:45 OK 20251218171726_add_pins.sql (27.22ms)28932026/10/01 09:53:45 INFO Aborted multipart uploads count=128942026/10/01 09:53:45 INFO Received cleanup request method=DELETE path=/api/pending_closures28952026/10/01 09:53:45 INFO Aborted multipart uploads count=12896--- PASS: TestPendingCleanupUsesOneCutoff (8.11s)2897=== CONT TestClientErrorHandling/InvalidAuthToken28982026/10/01 09:53:45 OK 20260628120000_add_object_size_and_stats.sql (61.6ms)28992026/10/01 09:53:45 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=414.583469ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29002026/10/01 09:53:45 OK 20260905000000_add_claims.sql (68.89ms)29012026/10/01 09:53:46 OK 20260920000000_drop_claims.sql (36.46ms)29022026/10/01 09:53:46 OK 20260923120000_add_pushes.sql (12.63ms)29032026/10/01 09:53:46 goose: successfully migrated database to version: 2026092312000029042026/10/01 09:53:46 OK 1_commit_pending_closure.sql (3.35ms)29052026/10/01 09:53:46 OK 2_object_stats_trigger.sql (681.38µs)29062026/10/01 09:53:46 OK 3_commit_push.sql (546.38µs)29072026/10/01 09:53:46 goose: up to current file version: 329082026/10/01 09:53:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"29092026/10/01 09:53:46 WARN mTLS auth: bound subjects configured but subject DN unavailable29102026/10/01 09:53:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2911--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.91s)2912=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2913=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected29142026/10/01 09:53:46 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]2915=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2916=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected29172026/10/01 09:53:46 WARN Authentication failed token_preview=eyJhbGciOi...cX37njyGrg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2918=== CONT TestService_RequireScope_OIDC/builder_may_write2919=== CONT TestService_RequireScope_OIDC/static_token_may_admin2920=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2921=== CONT TestService_RequireScope_OIDC/writer_implies_read2922=== CONT TestService_RequireScope_OIDC/reader_may_read2923=== CONT TestService_RequireScope_OIDC/static_token_may_write2924=== CONT TestService_RequireScope_OIDC/ops_may_not_write2925=== CONT TestService_RequireScope_OIDC/reader_may_not_write2926=== CONT TestService_RequireScope_OIDC/ops_may_admin2927=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2928--- PASS: TestService_AuthMiddleware_OIDC (2.98s)2929 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2930 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2931 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2932 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2933--- PASS: TestService_RequireScope_OIDC (3.06s)2934 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2935 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2936 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2937 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2938 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2939 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2940 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2941 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2942 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2943 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)29442026/10/01 09:53:46 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=722.84464ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2945--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.00s)29462026-10-01 09:53:46.657 UTC [92481] ERROR: relation "goose_db_version" does not exist at character 3629472026-10-01 09:53:46.657 UTC [92481] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29482026/10/01 09:53:46 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02949=== NAME TestClientIntegration2950 client_integration_test.go:323: Objects in database after GC:29512026-10-01 09:53:46.733 UTC [92482] ERROR: relation "goose_db_version" does not exist at character 3629522026-10-01 09:53:46.733 UTC [92482] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2953 client_integration_test.go:323: Successfully deleted all objects with GC --force2954--- PASS: TestClientIntegration (5.99s)29552026/10/01 09:53:46 OK 20241026095416_initial_model.sql (121.65ms)29562026/10/01 09:53:46 OK 20251210153512_drop_unused_gin_index.sql (5.05ms)29572026/10/01 09:53:46 OK 20251218171726_add_pins.sql (15.97ms)29582026/10/01 09:53:46 OK 20260628120000_add_object_size_and_stats.sql (24.76ms)29592026/10/01 09:53:46 OK 20241026095416_initial_model.sql (110.61ms)29602026-10-01 09:53:46.896 UTC [92483] ERROR: relation "goose_db_version" does not exist at character 3629612026-10-01 09:53:46.896 UTC [92483] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29622026/10/01 09:53:46 OK 20251210153512_drop_unused_gin_index.sql (4.8ms)29632026/10/01 09:53:46 OK 20260905000000_add_claims.sql (17.2ms)29642026/10/01 09:53:46 OK 20260920000000_drop_claims.sql (6.53ms)29652026/10/01 09:53:46 OK 20251218171726_add_pins.sql (7.07ms)29662026/10/01 09:53:46 OK 20260923120000_add_pushes.sql (4.28ms)29672026/10/01 09:53:46 goose: successfully migrated database to version: 2026092312000029682026/10/01 09:53:46 OK 1_commit_pending_closure.sql (9.37ms)29692026/10/01 09:53:46 OK 20260628120000_add_object_size_and_stats.sql (14.28ms)29702026/10/01 09:53:46 OK 2_object_stats_trigger.sql (3.42ms)29712026-10-01 09:53:46.926 UTC [92484] ERROR: relation "goose_db_version" does not exist at character 3629722026-10-01 09:53:46.926 UTC [92484] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29732026/10/01 09:53:46 OK 3_commit_push.sql (5.72ms)29742026/10/01 09:53:46 goose: up to current file version: 329752026/10/01 09:53:46 OK 20260905000000_add_claims.sql (8.12ms)2976=== NAME TestOrphanedObjectsGCStressTest2977 orphaned_objects_gc_test.go:509: Stress test completed successfully:2978 orphaned_objects_gc_test.go:510: - Active objects preserved: 202979 orphaned_objects_gc_test.go:511: - Objects deleted: 2102980 orphaned_objects_gc_test.go:512: - Total GC'd: 2102981--- PASS: TestOrphanedObjectsGCStressTest (10.12s)29822026/10/01 09:53:46 OK 20260920000000_drop_claims.sql (28.18ms)29832026/10/01 09:53:46 OK 20260923120000_add_pushes.sql (26.6ms)29842026/10/01 09:53:46 goose: successfully migrated database to version: 2026092312000029852026/10/01 09:53:46 OK 1_commit_pending_closure.sql (1.7ms)29862026/10/01 09:53:46 OK 2_object_stats_trigger.sql (384.54µs)29872026/10/01 09:53:46 OK 3_commit_push.sql (331.46µs)29882026/10/01 09:53:46 goose: up to current file version: 329892026/10/01 09:53:47 OK 20241026095416_initial_model.sql (139.95ms)29902026/10/01 09:53:47 OK 20251210153512_drop_unused_gin_index.sql (5.69ms)29912026/10/01 09:53:47 OK 20251218171726_add_pins.sql (8.23ms)29922026/10/01 09:53:47 OK 20260628120000_add_object_size_and_stats.sql (17.79ms)29932026/10/01 09:53:47 OK 20241026095416_initial_model.sql (89.16ms)29942026/10/01 09:53:47 OK 20251210153512_drop_unused_gin_index.sql (3.2ms)29952026/10/01 09:53:47 OK 20260905000000_add_claims.sql (21.26ms)29962026/10/01 09:53:47 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.698247862s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29972026/10/01 09:53:47 OK 20251218171726_add_pins.sql (28.46ms)29982026/10/01 09:53:47 OK 20260920000000_drop_claims.sql (51.79ms)29992026/10/01 09:53:47 OK 20260628120000_add_object_size_and_stats.sql (25.19ms)30002026/10/01 09:53:47 OK 20260923120000_add_pushes.sql (13.5ms)30012026/10/01 09:53:47 goose: successfully migrated database to version: 2026092312000030022026/10/01 09:53:47 OK 1_commit_pending_closure.sql (4.89ms)30032026/10/01 09:53:47 OK 2_object_stats_trigger.sql (955.13µs)30042026/10/01 09:53:47 OK 3_commit_push.sql (1.07ms)30052026/10/01 09:53:47 goose: up to current file version: 33006--- PASS: TestService_ReadAuthMiddleware (2.57s)30072026/10/01 09:53:47 OK 20260905000000_add_claims.sql (57.98ms)30082026/10/01 09:53:47 OK 20260920000000_drop_claims.sql (64.08ms)30092026/10/01 09:53:47 OK 20260923120000_add_pushes.sql (10.8ms)30102026/10/01 09:53:47 goose: successfully migrated database to version: 2026092312000030112026/10/01 09:53:47 OK 1_commit_pending_closure.sql (4.62ms)30122026/10/01 09:53:47 OK 2_object_stats_trigger.sql (948.08µs)30132026/10/01 09:53:47 OK 3_commit_push.sql (737µs)30142026/10/01 09:53:47 goose: up to current file version: 330152026/10/01 09:53:47 INFO Received uploads request method=POST path=/api/pending_closures30162026/10/01 09:53:47 INFO Aborted multipart uploads count=030172026/10/01 09:53:47 WARN Force mode enabled - objects will be deleted immediately without grace period30182026/10/01 09:53:47 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=030192026/10/01 09:53:47 INFO Vacuumed table table=pending_closures30202026/10/01 09:53:47 INFO Vacuumed table table=pending_objects30212026/10/01 09:53:47 INFO Vacuumed table table=multipart_uploads30222026/10/01 09:53:47 INFO Vacuumed table table=closures30232026/10/01 09:53:47 INFO Vacuumed table table=objects30242026/10/01 09:53:47 INFO Received uploads request method=POST path=/api/pending_closures30252026/10/01 09:53:47 INFO Aborted multipart uploads count=030262026-10-01 09:53:47.850 UTC [92486] ERROR: relation "goose_db_version" does not exist at character 3630272026-10-01 09:53:47.850 UTC [92486] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC30282026/10/01 09:53:47 WARN Force mode enabled - objects will be deleted immediately without grace period30292026/10/01 09:53:47 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=030302026/10/01 09:53:47 INFO Vacuumed table table=pending_closures30312026/10/01 09:53:47 INFO Vacuumed table table=pending_objects30322026/10/01 09:53:47 INFO Vacuumed table table=multipart_uploads30332026/10/01 09:53:47 INFO Vacuumed table table=closures30342026/10/01 09:53:47 INFO Vacuumed table table=objects3035--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)3036 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (2.85s)3037 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (2.96s)30382026/10/01 09:53:48 OK 20241026095416_initial_model.sql (130.08ms)30392026/10/01 09:53:48 OK 20251210153512_drop_unused_gin_index.sql (11.49ms)30402026/10/01 09:53:48 OK 20251218171726_add_pins.sql (13.06ms)30412026/10/01 09:53:48 OK 20260628120000_add_object_size_and_stats.sql (9.02ms)30422026/10/01 09:53:48 OK 20260905000000_add_claims.sql (13.76ms)30432026/10/01 09:53:48 OK 20260920000000_drop_claims.sql (2.15ms)30442026/10/01 09:53:48 OK 20260923120000_add_pushes.sql (1.36ms)30452026/10/01 09:53:48 goose: successfully migrated database to version: 2026092312000030462026/10/01 09:53:48 OK 1_commit_pending_closure.sql (2.51ms)30472026/10/01 09:53:48 OK 2_object_stats_trigger.sql (680µs)30482026/10/01 09:53:48 OK 3_commit_push.sql (556.25µs)30492026/10/01 09:53:48 goose: up to current file version: 330502026/10/01 09:53:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30512026/10/01 09:53:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30522026/10/01 09:53:48 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-config30532026/10/01 09:53:48 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=187.196073ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30542026/10/01 09:53:49 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=433.916766ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30552026/10/01 09:53:49 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=843.249078ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30562026/10/01 09:53:50 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.625465923s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30572026/10/01 09:53:52 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"30582026/10/01 09:53:52 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-config30592026/10/01 09:53:52 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=206.177349ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30602026/10/01 09:53:52 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=439.250503ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30612026/10/01 09:53:52 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=837.243932ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30622026/10/01 09:53:53 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.523470189s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30632026/10/01 09:53: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_closures30642026/10/01 09:53:55 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=207.161ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30652026/10/01 09:53:55 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=378.370528ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30662026/10/01 09:53:55 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=786.824124ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30672026/10/01 09:53:56 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.539689456s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3068--- PASS: TestClientErrorHandling (0.00s)3069 --- PASS: TestClientErrorHandling/InvalidStorePath (2.98s)3070 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.62s)3071 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.75s)3072PASS3073{"timestamp":"2026-10-01T09:53:58.218141Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56225","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(11)"}3074{"timestamp":"2026-10-01T09:53:58.218187Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56343","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)"}30752026-10-01 09:53:58.342 UTC [92032] LOG: received smart shutdown request30762026-10-01 09:53:58.343 UTC [92032] LOG: background worker "logical replication launcher" (PID 92042) exited with exit code 130772026-10-01 09:53:58.351 UTC [92037] LOG: shutting down30782026-10-01 09:53:58.351 UTC [92037] LOG: checkpoint starting: shutdown immediate30792026-10-01 09:53:59.616 UTC [92037] LOG: checkpoint complete: wrote 13061 buffers (79.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 25 recycled; write=0.730 s, sync=0.489 s, total=1.266 s; sync files=28648, longest=0.001 s, average=0.001 s; distance=403246 kB, estimate=403246 kB; lsn=0/1A158898, redo lsn=0/1A15889830802026-10-01 09:53:59.622 UTC [92032] LOG: database system is shut down3081Running OIDC tests...3082=== RUN TestAudienceForIssuer3083=== PAUSE TestAudienceForIssuer3084=== RUN TestGlobMatch3085=== PAUSE TestGlobMatch3086=== RUN TestValidateToken_ValidToken3087=== PAUSE TestValidateToken_ValidToken3088=== RUN TestValidateToken_WrongAudience3089=== PAUSE TestValidateToken_WrongAudience3090=== RUN TestValidateToken_Expired3091=== PAUSE TestValidateToken_Expired3092=== RUN TestValidateToken_BoundClaimsMismatch3093=== PAUSE TestValidateToken_BoundClaimsMismatch3094=== RUN TestValidateToken_BoundSubjectMismatch3095=== PAUSE TestValidateToken_BoundSubjectMismatch3096=== RUN TestValidateToken_MultipleProviders3097=== PAUSE TestValidateToken_MultipleProviders3098=== RUN TestValidateToken_NoMatchingProvider3099=== PAUSE TestValidateToken_NoMatchingProvider3100=== RUN TestValidateToken_KubernetesServiceAccount3101=== PAUSE TestValidateToken_KubernetesServiceAccount3102=== RUN TestNewValidator_KubernetesRequiresCA3103=== PAUSE TestNewValidator_KubernetesRequiresCA3104=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3105=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3106=== RUN TestPins_ReservedForMatchingRule3107=== PAUSE TestPins_ReservedForMatchingRule3108=== RUN TestPins_TopLevelShorthand3109=== PAUSE TestPins_TopLevelShorthand3110=== RUN TestPins_ConfigValidation3111=== PAUSE TestPins_ConfigValidation3112=== RUN TestScopes_LegacyProviderDefaultsToWrite3113=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3114=== RUN TestScopes_Rules3115=== PAUSE TestScopes_Rules3116=== RUN TestScopes_ConfigValidation3117=== PAUSE TestScopes_ConfigValidation3118=== CONT TestAudienceForIssuer3119--- PASS: TestAudienceForIssuer (0.00s)3120=== CONT TestValidateToken_BoundClaimsMismatch3121=== CONT TestValidateToken_KubernetesServiceAccount3122=== CONT TestValidateToken_ValidToken3123=== CONT TestGlobMatch3124=== RUN TestGlobMatch/foo_foo3125=== PAUSE TestGlobMatch/foo_foo3126=== RUN TestGlobMatch/foo_bar3127=== CONT TestValidateToken_MultipleProviders3128=== CONT TestValidateToken_NoMatchingProvider3129=== CONT TestValidateToken_BoundSubjectMismatch3130=== CONT TestPins_ConfigValidation3131=== CONT TestScopes_ConfigValidation3132=== CONT TestScopes_Rules3133=== PAUSE TestGlobMatch/foo_bar3134=== RUN TestGlobMatch/*_3135=== PAUSE TestGlobMatch/*_3136=== RUN TestGlobMatch/*_anything3137=== PAUSE TestGlobMatch/*_anything3138=== RUN TestGlobMatch/foo*_foo3139=== PAUSE TestGlobMatch/foo*_foo3140=== RUN TestGlobMatch/foo*_foobar3141=== PAUSE TestGlobMatch/foo*_foobar3142=== RUN TestGlobMatch/foo*_bar3143=== PAUSE TestGlobMatch/foo*_bar3144=== RUN TestGlobMatch/*bar_bar3145=== PAUSE TestGlobMatch/*bar_bar3146=== RUN TestGlobMatch/*bar_foobar3147=== PAUSE TestGlobMatch/*bar_foobar3148=== RUN TestGlobMatch/*bar_foo3149=== PAUSE TestGlobMatch/*bar_foo3150=== RUN TestGlobMatch/foo*bar_foobar3151=== PAUSE TestGlobMatch/foo*bar_foobar3152=== RUN TestGlobMatch/foo*bar_foo123bar3153=== PAUSE TestGlobMatch/foo*bar_foo123bar3154=== RUN TestGlobMatch/foo*bar_foobarbaz3155=== PAUSE TestGlobMatch/foo*bar_foobarbaz3156=== RUN TestGlobMatch/*/*_foo/bar3157=== PAUSE TestGlobMatch/*/*_foo/bar3158=== RUN TestGlobMatch/*/*_foo3159=== PAUSE TestGlobMatch/*/*_foo3160=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3161=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3162=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03163=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03164=== RUN TestGlobMatch/refs/*/main_refs/heads/main3165=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3166=== RUN TestGlobMatch/fo?_foo3167=== PAUSE TestGlobMatch/fo?_foo3168=== RUN TestGlobMatch/fo?_fo3169=== PAUSE TestGlobMatch/fo?_fo3170=== RUN TestGlobMatch/fo?_fooo3171=== PAUSE TestGlobMatch/fo?_fooo3172=== RUN TestGlobMatch/?oo_foo3173=== PAUSE TestGlobMatch/?oo_foo3174=== RUN TestGlobMatch/?oo_boo3175=== PAUSE TestGlobMatch/?oo_boo3176=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3177=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3178=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3179=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3180=== CONT TestScopes_LegacyProviderDefaultsToWrite3181--- PASS: TestPins_ConfigValidation (0.00s)3182--- PASS: TestScopes_ConfigValidation (0.00s)3183=== CONT TestPins_ReservedForMatchingRule3184=== CONT TestPins_TopLevelShorthand31852026/10/01 09:54:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56621/oidc3186--- PASS: TestValidateToken_BoundSubjectMismatch (0.06s)3187=== CONT TestValidateToken_Expired31882026/10/01 09:54:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56623/oidc3189--- PASS: TestPins_ReservedForMatchingRule (0.07s)3190=== CONT TestValidateToken_KubernetesIssuerFromOwnToken31912026/10/01 09:54:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56625/oidc3192--- PASS: TestValidateToken_Expired (0.02s)3193=== CONT TestNewValidator_KubernetesRequiresCA31942026/10/01 09:54:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56627/oidc31952026/10/01 09:54:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56629/oidc3196--- PASS: TestPins_TopLevelShorthand (0.09s)3197=== CONT TestValidateToken_WrongAudience3198--- PASS: TestScopes_Rules (0.09s)3199=== CONT TestGlobMatch/foo_foo3200=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3201=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3202=== CONT TestGlobMatch/?oo_boo3203=== CONT TestGlobMatch/?oo_foo3204=== CONT TestGlobMatch/fo?_fooo3205=== CONT TestGlobMatch/fo?_fo3206=== CONT TestGlobMatch/fo?_foo3207=== CONT TestGlobMatch/refs/*/main_refs/heads/main3208=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03209=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3210=== CONT TestGlobMatch/*/*_foo3211=== CONT TestGlobMatch/*/*_foo/bar3212=== CONT TestGlobMatch/foo*bar_foobarbaz3213=== CONT TestGlobMatch/foo*bar_foo123bar3214=== CONT TestGlobMatch/foo*bar_foobar3215=== CONT TestGlobMatch/*bar_foo3216=== CONT TestGlobMatch/*bar_foobar3217=== CONT TestGlobMatch/*bar_bar3218=== CONT TestGlobMatch/foo*_bar3219=== CONT TestGlobMatch/foo*_foobar3220=== CONT TestGlobMatch/foo*_foo3221=== CONT TestGlobMatch/*_anything3222=== CONT TestGlobMatch/*_3223=== CONT TestGlobMatch/foo_bar3224--- PASS: TestGlobMatch (0.00s)3225 --- PASS: TestGlobMatch/foo_foo (0.00s)3226 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3227 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3228 --- PASS: TestGlobMatch/?oo_boo (0.00s)3229 --- PASS: TestGlobMatch/?oo_foo (0.00s)3230 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3231 --- PASS: TestGlobMatch/fo?_fo (0.00s)3232 --- PASS: TestGlobMatch/fo?_foo (0.00s)3233 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3234 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3235 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3236 --- PASS: TestGlobMatch/*/*_foo (0.00s)3237 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3238 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3239 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3240 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3241 --- PASS: TestGlobMatch/*bar_foo (0.00s)3242 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3243 --- PASS: TestGlobMatch/*bar_bar (0.00s)3244 --- PASS: TestGlobMatch/foo*_bar (0.00s)3245 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3246 --- PASS: TestGlobMatch/foo*_foo (0.00s)3247 --- PASS: TestGlobMatch/*_anything (0.00s)3248 --- PASS: TestGlobMatch/*_ (0.00s)3249 --- PASS: TestGlobMatch/foo_bar (0.00s)32502026/10/01 09:54:00 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:566313251--- PASS: TestValidateToken_KubernetesServiceAccount (0.11s)32522026/10/01 09:54:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56633/oidc3253--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)32542026/10/01 09:54:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56636/oidc3255--- PASS: TestValidateToken_WrongAudience (0.02s)32562026/10/01 09:54:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56638/oidc3257--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.12s)32582026/10/01 09:54:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56640/oidc3259--- PASS: TestValidateToken_ValidToken (0.13s)32602026/10/01 09:54:01 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233261--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)32622026/10/01 09:54:01 http: TLS handshake error from 127.0.0.1:56646: read tcp 127.0.0.1:56645->127.0.0.1:56646: use of closed network connection3263--- PASS: TestNewValidator_KubernetesRequiresCA (0.07s)32642026/10/01 09:54:01 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56635/oidc32652026/10/01 09:54:01 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:56647/oidc3266--- PASS: TestValidateToken_MultipleProviders (0.15s)32672026/10/01 09:54:01 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56642/oidc3268--- PASS: TestValidateToken_NoMatchingProvider (0.18s)3269PASS3270Running hook tests...3271=== RUN TestSendPathsEmpty3272=== PAUSE TestSendPathsEmpty3273=== RUN TestQueueEnqueueAndFetch3274=== PAUSE TestQueueEnqueueAndFetch3275=== RUN TestQueueDeduplication3276=== PAUSE TestQueueDeduplication3277=== RUN TestQueueRemove3278=== PAUSE TestQueueRemove3279=== RUN TestQueueFetchBatchLimit3280=== PAUSE TestQueueFetchBatchLimit3281=== RUN TestQueueRetryMovesToBack3282=== PAUSE TestQueueRetryMovesToBack3283=== RUN TestQueueFetchRemoveLifecycle3284=== PAUSE TestQueueFetchRemoveLifecycle3285=== RUN TestQueueConcurrentWriters3286=== PAUSE TestQueueConcurrentWriters3287=== RUN TestQueueRemoveLargeClosure3288=== PAUSE TestQueueRemoveLargeClosure3289=== RUN TestServerClientIntegration3290=== PAUSE TestServerClientIntegration3291=== RUN TestServerQueueError3292=== PAUSE TestServerQueueError3293=== RUN TestGetListenerSocketActivation3294 server_test.go:210: === RUN TestGetListenerSocketActivation3295 --- PASS: TestGetListenerSocketActivation (0.00s)3296 PASS3297 3298--- PASS: TestGetListenerSocketActivation (0.01s)3299=== RUN TestDrainIsolatesPoisonPath3300=== PAUSE TestDrainIsolatesPoisonPath3301=== RUN TestRunNotBlockedByPoisonHead3302=== PAUSE TestRunNotBlockedByPoisonHead3303=== RUN TestDrainGivesUpWhenServerDown3304=== PAUSE TestDrainGivesUpWhenServerDown3305=== RUN TestFailedPathPrunedByLaterClosure3306=== PAUSE TestFailedPathPrunedByLaterClosure3307=== RUN TestWorkerUploadsAndRemoves3308=== PAUSE TestWorkerUploadsAndRemoves3309=== RUN TestWorkerSkipsGCdPaths3310=== PAUSE TestWorkerSkipsGCdPaths3311=== RUN TestWorkerPrunesClosureDeps3312=== PAUSE TestWorkerPrunesClosureDeps3313=== RUN TestDrainTimeout3314=== PAUSE TestDrainTimeout3315=== CONT TestSendPathsEmpty3316=== CONT TestServerQueueError3317--- PASS: TestSendPathsEmpty (0.00s)3318=== CONT TestQueueFetchBatchLimit3319=== CONT TestQueueRetryMovesToBack3320=== CONT TestWorkerUploadsAndRemoves3321=== CONT TestQueueRemove3322=== CONT TestQueueEnqueueAndFetch3323=== CONT TestDrainGivesUpWhenServerDown3324=== CONT TestWorkerPrunesClosureDeps3325=== CONT TestDrainTimeout3326=== CONT TestQueueDeduplication33272026/10/01 09:54:01 ERROR Failed to queue paths error="permission denied" count=13328=== CONT TestQueueRemoveLargeClosure3329--- PASS: TestServerQueueError (0.00s)33302026/10/01 09:54:01 INFO Upload queue status pending=233312026/10/01 09:54:01 INFO Uploading batch count=133322026/10/01 09:54:01 INFO Uploading batch count=23333--- PASS: TestQueueFetchBatchLimit (0.01s)3334=== CONT TestServerClientIntegration3335--- PASS: TestQueueRemove (0.01s)3336=== CONT TestFailedPathPrunedByLaterClosure3337--- PASS: TestQueueRetryMovesToBack (0.01s)3338=== CONT TestWorkerSkipsGCdPaths33392026/10/01 09:54:01 INFO Upload queue status pending=233402026/10/01 09:54:01 INFO Uploading batch count=233412026/10/01 09:54:01 INFO Uploading batch count=23342--- PASS: TestQueueDeduplication (0.01s)3343--- PASS: TestServerClientIntegration (0.00s)3344=== CONT TestQueueConcurrentWriters33452026/10/01 09:54:01 ERROR Upload failed error="upload failed" count=233462026/10/01 09:54:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91990-792741325/TestDrainGivesUpWhenServerDown937554059/002/a3347=== CONT TestQueueFetchRemoveLifecycle3348=== CONT TestRunNotBlockedByPoisonHead3349--- PASS: TestQueueEnqueueAndFetch (0.01s)33502026/10/01 09:54:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91990-792741325/TestDrainGivesUpWhenServerDown937554059/002/b33512026/10/01 09:54:01 INFO Uploading batch count=233522026/10/01 09:54:01 ERROR Upload failed error="upload failed" count=233532026/10/01 09:54:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91990-792741325/TestDrainGivesUpWhenServerDown937554059/002/c33542026/10/01 09:54:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91990-792741325/TestDrainGivesUpWhenServerDown937554059/002/d33552026/10/01 09:54:01 INFO Uploading batch count=233562026/10/01 09:54:01 ERROR Upload failed error="upload failed" count=233572026/10/01 09:54:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91990-792741325/TestDrainGivesUpWhenServerDown937554059/002/e33582026/10/01 09:54:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91990-792741325/TestDrainGivesUpWhenServerDown937554059/002/f33592026/10/01 09:54:01 INFO Uploading batch count=133602026/10/01 09:54:01 ERROR Upload failed error="upload failed" count=133612026/10/01 09:54:01 INFO Upload queue status pending=233622026/10/01 09:54:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-91990-792741325/TestWorkerSkipsGCdPaths3140350614/002/nonexistent33632026/10/01 09:54:01 ERROR Drain finished with paths left in queue remaining=1033642026/10/01 09:54:01 INFO Uploading batch count=133652026/10/01 09:54:01 INFO Uploading batch count=133662026/10/01 09:54:01 INFO Upload queue status pending=333672026/10/01 09:54:01 INFO Uploading batch count=133682026/10/01 09:54:01 ERROR Upload failed error="upload failed" count=133692026/10/01 09:54:01 INFO Uploading batch count=13370--- PASS: TestQueueFetchRemoveLifecycle (0.00s)3371=== CONT TestDrainIsolatesPoisonPath3372--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3373--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)33742026/10/01 09:54:01 INFO Uploading batch count=433752026/10/01 09:54:01 ERROR Upload failed error="upload failed" count=433762026/10/01 09:54:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-91990-792741325/TestDrainIsolatesPoisonPath3388640242/002/bbb33772026/10/01 09:54:01 INFO Uploading batch count=133782026/10/01 09:54:01 ERROR Upload failed error="upload failed" count=133792026/10/01 09:54:01 INFO Uploading batch count=133802026/10/01 09:54:01 ERROR Upload failed error="upload failed" count=133812026/10/01 09:54:01 INFO Uploading batch count=133822026/10/01 09:54:01 ERROR Upload failed error="upload failed" count=133832026/10/01 09:54:01 ERROR Drain finished with paths left in queue remaining=13384--- PASS: TestDrainIsolatesPoisonPath (0.00s)3385--- PASS: TestWorkerPrunesClosureDeps (0.03s)3386--- PASS: TestWorkerUploadsAndRemoves (0.03s)3387--- PASS: TestWorkerSkipsGCdPaths (0.02s)3388--- PASS: TestQueueRemoveLargeClosure (0.05s)3389--- PASS: TestQueueConcurrentWriters (0.15s)33902026/10/01 09:54:01 ERROR Upload failed error="context deadline exceeded" count=233912026/10/01 09:54:01 ERROR Drain finished with paths left in queue remaining=43392--- PASS: TestDrainTimeout (0.21s)33932026/10/01 09:54:02 INFO Uploading batch count=133942026/10/01 09:54:02 INFO Uploading batch count=133952026/10/01 09:54:02 INFO Uploading batch count=133962026/10/01 09:54:02 ERROR Upload failed error="upload failed" count=133972026/10/01 09:54:02 INFO Uploading batch count=133982026/10/01 09:54:02 ERROR Upload failed error="upload failed" count=133992026/10/01 09:54:02 INFO Uploading batch count=134002026/10/01 09:54:02 ERROR Upload failed error="upload failed" count=134012026/10/01 09:54:02 INFO Uploading batch count=134022026/10/01 09:54:02 ERROR Upload failed error="upload failed" count=134032026/10/01 09:54:02 ERROR Drain finished with paths left in queue remaining=13404--- PASS: TestRunNotBlockedByPoisonHead (1.01s)3405PASS