niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #292
· 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.06s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestStreamPushReportsEveryPath96=== CONT TestConvertHashToNix3297=== CONT TestUploadMultipart_SupersededByPeer98=== RUN TestConvertHashToNix32/SRI_format_to_Nix3299=== RUN TestUploadMultipart_SupersededByPeer/exists100=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32101=== CONT TestScriptTokenEmptyCommand102=== RUN TestConvertHashToNix32/already_Nix32_format103=== PAUSE TestConvertHashToNix32/already_Nix32_format104--- PASS: TestScriptTokenEmptyCommand (0.00s)105=== CONT TestCaseHackSuffix106=== RUN TestConvertHashToNix32/invalid_format107=== PAUSE TestConvertHashToNix32/invalid_format108=== PAUSE TestUploadMultipart_SupersededByPeer/exists109=== RUN TestUploadMultipart_SupersededByPeer/missing110=== PAUSE TestUploadMultipart_SupersededByPeer/missing111=== CONT TestRateLimiterFeedback112=== RUN TestRateLimiterFeedback/429_enables_limiter113=== PAUSE TestRateLimiterFeedback/429_enables_limiter114=== RUN TestRateLimiterFeedback/503_enables_limiter115=== CONT TestEncodeNixBase32WithRealHash116--- PASS: TestEncodeNixBase32WithRealHash (0.00s)117=== CONT TestShellSplit118--- PASS: TestShellSplit (0.00s)119=== CONT TestDoWithRetry_BodyReplayedViaGetBody120=== CONT TestEncodeNixBase32121=== RUN TestEncodeNixBase32/test_string_hash122=== PAUSE TestEncodeNixBase32/test_string_hash123=== CONT TestDumpPathWriterError124=== RUN TestEncodeNixBase32/empty_input125=== PAUSE TestEncodeNixBase32/empty_input126=== CONT TestResolveStorePath127--- PASS: TestStreamPushReportsEveryPath (0.00s)128=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess129=== CONT TestDumpPathSingleFile130=== CONT TestDumpPathMatchesNix131=== PAUSE TestRateLimiterFeedback/503_enables_limiter132=== CONT TestShellSplitErrors1332026/10/01 07:38:27 WARN Rate limiter enabled after throttle name=server-test rate=5134=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter135--- PASS: TestShellSplitErrors (0.00s)136=== CONT TestRegisterUploadedObjectReusesConnections137=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter138=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter139=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter140=== CONT TestParsePathInfoJSON141=== RUN TestParsePathInfoJSON/Nix_format142=== PAUSE TestParsePathInfoJSON/Nix_format143=== RUN TestParsePathInfoJSON/Lix_format144=== PAUSE TestParsePathInfoJSON/Lix_format145=== RUN TestParsePathInfoJSON/empty_input146=== PAUSE TestParsePathInfoJSON/empty_input147=== RUN TestParsePathInfoJSON/whitespace_only148=== PAUSE TestParsePathInfoJSON/whitespace_only149=== RUN TestParsePathInfoJSON/invalid_JSON150=== PAUSE TestParsePathInfoJSON/invalid_JSON151=== CONT TestPathInfoCACompatibility152=== RUN TestPathInfoCACompatibility/null_ca_field153=== PAUSE TestPathInfoCACompatibility/null_ca_field154=== RUN TestPathInfoCACompatibility/old_string_format_-_text155=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text156=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive157=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive158=== RUN TestPathInfoCACompatibility/new_structured_format_-_text159=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text160=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method161=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method162--- PASS: TestResolveStorePath (0.00s)163=== CONT TestParsePathInfoJSONMultiplePaths164=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths165=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths166=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths167=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths168=== CONT TestSetClientTLSErrors169--- PASS: TestDoServerRequestAttachesToken (0.01s)170=== CONT TestScriptTokenBadJSON1712026/10/01 07:38:27 WARN Rate limiter enabled after throttle name=server-test rate=51722026/10/01 07:38:27 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57029173=== RUN TestSetClientTLSErrors/missing_cert_file174=== PAUSE TestSetClientTLSErrors/missing_cert_file175=== RUN TestSetClientTLSErrors/missing_key_file176=== CONT TestScriptTokenScriptFails177=== PAUSE TestSetClientTLSErrors/missing_key_file178=== RUN TestSetClientTLSErrors/missing_ca_file1792026/10/01 07:38:27 WARN Rate limiter backed off name=server-test rate=51802026/10/01 07:38:27 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57029181=== PAUSE TestSetClientTLSErrors/missing_ca_file182=== RUN TestSetClientTLSErrors/invalid_ca_file183=== PAUSE TestSetClientTLSErrors/invalid_ca_file184--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)185=== CONT TestScriptTokenCachesUntilRefresh186=== CONT TestScriptTokenEmptyToken187--- PASS: TestScriptTokenScriptFails (0.01s)188=== CONT TestScriptTokenNoExpiryRerunsEveryCall189--- PASS: TestScriptTokenBadJSON (0.02s)190=== CONT TestFileTokenEmpty191--- PASS: TestFileTokenEmpty (0.00s)192=== CONT TestFileTokenMissing193--- PASS: TestFileTokenMissing (0.00s)194=== CONT TestFileTokenReadsAndCaches195--- PASS: TestFileTokenReadsAndCaches (0.00s)196=== CONT TestStaticToken197--- PASS: TestStaticToken (0.00s)198=== CONT TestStreamPushRequestLine1992026/10/01 07:38:27 ERROR Upload failed error=boom count=1200--- PASS: TestStreamPushRequestLine (0.02s)201=== CONT TestSetClientTLSDoesNotMutateDefaultTransport202--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)203=== CONT TestSetClientTLS204=== RUN TestSetClientTLS/rejects_connection_without_client_cert205=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert206=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA207=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA208=== RUN TestSetClientTLS/preserves_debug_logging_transport209=== PAUSE TestSetClientTLS/preserves_debug_logging_transport210=== CONT TestClientSignaturesByStorePath211--- PASS: TestClientSignaturesByStorePath (0.00s)212=== CONT TestStreamPushReportsSignatures2132026/10/01 07:38:27 ERROR Upload failed error=boom count=1214--- PASS: TestStreamPushReportsSignatures (0.00s)215=== CONT TestPathInfoHashCompatibility216=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)217=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)218=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon219=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon220=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI221=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI222=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512223=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512224=== CONT TestGetStorePathHash225=== RUN TestGetStorePathHash/valid_store_path226=== PAUSE TestGetStorePathHash/valid_store_path227=== RUN TestGetStorePathHash/basename_without_hyphen_should_error228=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error229=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error230=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error231=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error232=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error233=== CONT TestStreamPushIsolatesFailures2342026/10/01 07:38:27 ERROR Upload failed error="bad path" count=3235--- PASS: TestStreamPushIsolatesFailures (0.00s)236=== CONT TestStreamPushGivesUpOnDeadServer2372026/10/01 07:38:27 ERROR Upload failed error="connection refused" count=202382026/10/01 07:38:27 ERROR Server seems unavailable, giving up on batch untried=17239--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)240=== CONT TestPartSizeForNAR241=== RUN TestPartSizeForNAR/zero_stays_at_minimum242=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum243=== RUN TestPartSizeForNAR/small_stays_at_minimum244=== PAUSE TestPartSizeForNAR/small_stays_at_minimum245=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum246=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum247=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts248=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts249=== RUN TestPartSizeForNAR/1_TiB250=== PAUSE TestPartSizeForNAR/1_TiB251=== RUN TestPartSizeForNAR/5_TiB_S3_max_object252=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object253=== RUN TestPartSizeForNAR/capped_at_5_GiB254=== PAUSE TestPartSizeForNAR/capped_at_5_GiB255=== CONT TestUploadMultipart_PartsInParallel256--- PASS: TestScriptTokenEmptyToken (0.05s)257=== CONT TestStreamPushBatchesUnderLoad258--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.08s)259=== CONT TestConvertHashToNix32/SRI_format_to_Nix32260=== CONT TestUploadMultipart_SupersededByPeer/exists261--- PASS: TestScriptTokenCachesUntilRefresh (0.08s)262=== CONT TestFilterOversizedClosures263=== RUN TestFilterOversizedClosures/no_limit_keeps_everything264=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything265=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped266=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped267=== RUN TestFilterOversizedClosures/all_closures_skipped268=== PAUSE TestFilterOversizedClosures/all_closures_skipped269=== CONT TestUploadMultipart_SupersededByPeer/missing270=== CONT TestConvertHashToNix32/invalid_format271=== CONT TestConvertHashToNix32/already_Nix32_format272--- PASS: TestConvertHashToNix32 (0.00s)273 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)274 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)275 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)276=== CONT TestEncodeNixBase32/test_string_hash277=== CONT TestEncodeNixBase32/empty_input278--- PASS: TestEncodeNixBase32 (0.00s)279 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)280 --- PASS: TestEncodeNixBase32/empty_input (0.00s)281=== CONT TestRateLimiterFeedback/429_enables_limiter282--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)283 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)284 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)285=== CONT TestParsePathInfoJSON/Nix_format286=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2872026/10/01 07:38:27 WARN Rate limiter enabled after throttle name=server-test rate=52882026/10/01 07:38:27 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:571092892026/10/01 07:38:27 WARN Rate limiter backed off name=server-test rate=5290=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter291=== CONT TestRateLimiterFeedback/503_enables_limiter292--- PASS: TestDumpPathWriterError (0.10s)293=== CONT TestPathInfoCACompatibility/null_ca_field294=== CONT TestParsePathInfoJSON/invalid_JSON295=== CONT TestParsePathInfoJSON/whitespace_only296=== CONT TestParsePathInfoJSON/empty_input297=== CONT TestParsePathInfoJSON/Lix_format298--- PASS: TestParsePathInfoJSON (0.00s)299 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)300 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)301 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)302 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)303 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)304=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths305=== CONT TestPathInfoCACompatibility/old_string_format_-_text306=== CONT TestPathInfoCACompatibility/new_structured_format_-_text307=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method308=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive309=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths310--- PASS: TestRegisterUploadedObjectReusesConnections (0.12s)311=== CONT TestSetClientTLSErrors/missing_cert_file312=== CONT TestSetClientTLSErrors/missing_ca_file313=== CONT TestSetClientTLSErrors/invalid_ca_file314--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)315 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)316 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)317=== CONT TestSetClientTLSErrors/missing_key_file318=== CONT TestSetClientTLS/rejects_connection_without_client_cert319=== CONT TestSetClientTLS/preserves_debug_logging_transport320--- PASS: TestSetClientTLSErrors (0.01s)321 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)322 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)323 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)324 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)325--- PASS: TestPathInfoCACompatibility (0.00s)326 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)327 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)328 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)329 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)330 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)331=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)332=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA333=== CONT TestGetStorePathHash/valid_store_path334=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512335=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI3362026/10/01 07:38:27 WARN Rate limiter enabled after throttle name=server-test rate=5337=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon338--- PASS: TestPathInfoHashCompatibility (0.01s)339 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)340 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)341 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)342 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)343=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error344=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error345=== CONT TestGetStorePathHash/basename_without_hyphen_should_error346--- PASS: TestGetStorePathHash (0.00s)347 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)348 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)349 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)350 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)351=== CONT TestPartSizeForNAR/zero_stays_at_minimum352=== CONT TestPartSizeForNAR/capped_at_5_GiB353=== CONT TestPartSizeForNAR/5_TiB_S3_max_object354=== CONT TestPartSizeForNAR/1_TiB355=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts356=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum357=== CONT TestPartSizeForNAR/small_stays_at_minimum358--- PASS: TestPartSizeForNAR (0.00s)359 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)360 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)361 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)362 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)363 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)364 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)365 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)366=== CONT TestFilterOversizedClosures/no_limit_keeps_everything367=== CONT TestFilterOversizedClosures/all_closures_skipped3682026/10/01 07:38:27 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:571153692026/10/01 07:38:27 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=50370=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3712026/10/01 07:38:27 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=2000372--- PASS: TestFilterOversizedClosures (0.00s)373 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)374 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)375 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)3762026/10/01 07:38:27 WARN Rate limiter backed off name=server-test rate=5377--- PASS: TestRateLimiterFeedback (0.00s)378 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)379 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)380 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)381 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.03s)3822026/10/01 07:38:27 http: TLS handshake error from 127.0.0.1:57117: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.00s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)385 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)386 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)387--- PASS: TestStreamPushBatchesUnderLoad (0.10s)388--- PASS: TestCaseHackSuffix (0.18s)389--- PASS: TestDumpPathSingleFile (0.26s)390--- PASS: TestDumpPathMatchesNix (0.28s)391--- PASS: TestUploadMultipart_PartsInParallel (0.64s)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-66626-273570313/postgres2854905702/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-66626-273570313/postgres2854905702/data -l logfile start421422/nix/var/nix/builds/nix-66626-273570313/postgres2854905702:5432 - no response4232026-10-01 07:38:30.541 UTC [67439] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 07:38:30.542 UTC [67439] LOG: listening on Unix socket "/nix/var/nix/builds/nix-66626-273570313/postgres2854905702/.s.PGSQL.5432"4252026-10-01 07:38:30.547 UTC [67449] LOG: database system was shut down at 2026-10-01 07:38:30 UTC4262026-10-01 07:38:30.551 UTC [67439] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-66626-273570313/postgres2854905702:5432 - accepting connections428{"timestamp":"2026-10-01T07:38:30.771185Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"ab36d93e-763a-43da-b9d1-de835299cf3c","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(11)"}429{"timestamp":"2026-10-01T07:38:30.873403Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"52ea4458-e808-4458-92b5-1726a55f0f0a","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(6)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestResolveDBConnectionString467=== PAUSE TestResolveDBConnectionString468=== RUN TestLeadElectsOneAndHandsOver469=== PAUSE TestLeadElectsOneAndHandsOver470=== RUN TestLeadIncumbentWinsAfterRestart4712026-10-01 07:38:31.271 UTC [67555] ERROR: relation "goose_db_version" does not exist at character 364722026-10-01 07:38:31.271 UTC [67555] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4732026/10/01 07:38:31 OK 20241026095416_initial_model.sql (7.6ms)4742026/10/01 07:38:31 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)4752026/10/01 07:38:31 OK 20251218171726_add_pins.sql (2.69ms)4762026/10/01 07:38:31 OK 20260628120000_add_object_size_and_stats.sql (2.58ms)4772026/10/01 07:38:31 OK 20260905000000_add_claims.sql (2.85ms)4782026/10/01 07:38:31 OK 20260920000000_drop_claims.sql (1.43ms)4792026/10/01 07:38:31 OK 20260923120000_add_pushes.sql (666.38µs)4802026/10/01 07:38:31 goose: successfully migrated database to version: 202609231200004812026/10/01 07:38:31 OK 1_commit_pending_closure.sql (2.15ms)4822026/10/01 07:38:31 OK 2_object_stats_trigger.sql (604.25µs)4832026/10/01 07:38:31 OK 3_commit_push.sql (505.96µs)4842026/10/01 07:38:31 goose: up to current file version: 34852026/10/01 07:38:31 INFO lead: acquired remote=192.0.2.1:12344862026/10/01 07:38:32 INFO lead: released remote=192.0.2.1:12344872026/10/01 07:38:32 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 07:38:32 INFO lead: released remote=192.0.2.1:1234489--- PASS: TestLeadIncumbentWinsAfterRestart (1.11s)490=== RUN TestLeadEndsOnShutdown491=== PAUSE TestLeadEndsOnShutdown492=== RUN TestGCAdvisoryLockBlocksConcurrentRun4932026-10-01 07:38:32.134 UTC [67687] ERROR: relation "goose_db_version" does not exist at character 364942026-10-01 07:38:32.134 UTC [67687] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4952026/10/01 07:38:32 OK 20241026095416_initial_model.sql (6.8ms)4962026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (912.79µs)4972026/10/01 07:38:32 OK 20251218171726_add_pins.sql (2.28ms)4982026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (2.29ms)4992026/10/01 07:38:32 OK 20260905000000_add_claims.sql (2.74ms)5002026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (1.22ms)5012026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (1.2ms)5022026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200005032026/10/01 07:38:32 OK 1_commit_pending_closure.sql (1.83ms)5042026/10/01 07:38:32 OK 2_object_stats_trigger.sql (501.54µs)5052026/10/01 07:38:32 OK 3_commit_push.sql (414.38µs)5062026/10/01 07:38:32 goose: up to current file version: 3507--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.17s)508=== RUN TestGCBugBareHashReferences509=== PAUSE TestGCBugBareHashReferences510=== RUN TestGCMetrics511=== PAUSE TestGCMetrics512=== RUN TestPushDedupSurvivesConcurrentGC513=== PAUSE TestPushDedupSurvivesConcurrentGC514=== RUN TestDeduplicatedObjectsRecordedAsPending515=== PAUSE TestDeduplicatedObjectsRecordedAsPending516=== RUN TestGCSweepSkipsPendingObjects517=== PAUSE TestGCSweepSkipsPendingObjects518=== RUN TestTombstonedObjectOfferedWithoutWaiting519=== PAUSE TestTombstonedObjectOfferedWithoutWaiting520=== RUN TestGCSweepDeliversEachKeyOnce521=== PAUSE TestGCSweepDeliversEachKeyOnce522=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection524=== RUN TestFailedS3DeleteKeepsTombstone525=== PAUSE TestFailedS3DeleteKeepsTombstone526=== RUN TestGCTaskStore_StartNew527=== PAUSE TestGCTaskStore_StartNew528=== RUN TestGCTaskStore_DeduplicateSameParams529=== PAUSE TestGCTaskStore_DeduplicateSameParams530=== RUN TestGCTaskStore_ConflictDifferentParams531=== PAUSE TestGCTaskStore_ConflictDifferentParams532=== RUN TestGCTaskStore_GetEmpty533=== PAUSE TestGCTaskStore_GetEmpty534=== RUN TestGCTaskStore_GetReturnsLatest535=== PAUSE TestGCTaskStore_GetReturnsLatest536=== RUN TestGCTaskStore_CompletedAllowsNewTask537=== PAUSE TestGCTaskStore_CompletedAllowsNewTask538=== RUN TestGCTaskStore_PhaseUpdates539=== PAUSE TestGCTaskStore_PhaseUpdates540=== RUN TestGCTaskStore_Fail541=== PAUSE TestGCTaskStore_Fail542=== RUN TestGracefulShutdownDrainsInflight543=== PAUSE TestGracefulShutdownDrainsInflight544=== RUN TestService_healthCheckHandler545=== PAUSE TestService_healthCheckHandler546=== RUN TestService_readinessHandler547=== PAUSE TestService_readinessHandler548=== RUN TestGenerateLandingPage549=== PAUSE TestGenerateLandingPage550=== RUN TestCacheConfigHandlerMaxNarSize551=== PAUSE TestCacheConfigHandlerMaxNarSize552=== RUN TestCreatePendingClosureRejectsOversizedNAR553=== PAUSE TestCreatePendingClosureRejectsOversizedNAR554=== RUN TestNARDeduplicationMetadataUploadBug555=== PAUSE TestNARDeduplicationMetadataUploadBug556=== RUN TestMetricsInventory557=== PAUSE TestMetricsInventory558=== RUN TestService_NativeMTLS559=== PAUSE TestService_NativeMTLS560=== RUN TestServerTLSConfig561=== PAUSE TestServerTLSConfig562=== RUN TestMultipartCleanup563=== PAUSE TestMultipartCleanup564=== RUN TestObjectStatsTrigger565=== PAUSE TestObjectStatsTrigger566=== RUN TestOrphanedObjectsGC567=== PAUSE TestOrphanedObjectsGC568=== RUN TestOrphanedObjectsGCStressTest569=== PAUSE TestOrphanedObjectsGCStressTest570=== RUN TestCreatePin_ReservedPins571=== PAUSE TestCreatePin_ReservedPins572=== RUN TestParseSingleRange573=== PAUSE TestParseSingleRange574=== RUN TestProxyHeadersOnlyTrustedOnSocket575=== PAUSE TestProxyHeadersOnlyTrustedOnSocket576=== RUN TestIsValidCachePath577=== PAUSE TestIsValidCachePath578=== RUN TestReadProxyNarinfo579=== PAUSE TestReadProxyNarinfo580=== RUN TestReadProxyNarinfoAlreadyDecompressed581=== PAUSE TestReadProxyNarinfoAlreadyDecompressed582=== RUN TestReadProxyNarStreaming583=== PAUSE TestReadProxyNarStreaming584=== RUN TestReadProxy404585=== PAUSE TestReadProxy404586=== RUN TestReadProxyInvalidPath587=== PAUSE TestReadProxyInvalidPath588=== RUN TestReadProxyHead589=== PAUSE TestReadProxyHead590=== RUN TestReadProxyConditionalGet591=== PAUSE TestReadProxyConditionalGet592=== RUN TestReadProxyRootRedirectsToIndexHTML593=== PAUSE TestReadProxyRootRedirectsToIndexHTML594=== RUN TestReadProxyDisabled595=== PAUSE TestReadProxyDisabled596=== RUN TestReadRedirectNar597=== PAUSE TestReadRedirectNar598=== RUN TestReadRedirectKeepsNarinfoProxied599=== PAUSE TestReadRedirectKeepsNarinfoProxied600=== RUN TestReadProxyRangeRequest601=== PAUSE TestReadProxyRangeRequest602=== RUN TestReadRedirectUsesPublicS3URL603=== PAUSE TestReadRedirectUsesPublicS3URL604=== RUN TestPush_OverlappingRootsStoreOneRowPerKey605=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey606=== RUN TestPush_CompleteCommitsEveryRoot607=== PAUSE TestPush_CompleteCommitsEveryRoot608=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit609=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit610=== RUN TestPush_RejectsBadRequests611=== PAUSE TestPush_RejectsBadRequests612=== RUN TestPush_SignsNarinfosOfItsPendingObjects613=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects614=== RUN TestRedundantMultipartUpload615=== PAUSE TestRedundantMultipartUpload616=== RUN TestCompleteMultipartUpload_ErrorButObjectExists617=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists618=== RUN TestCompletedNarNotReofferedAcrossClosures619=== PAUSE TestCompletedNarNotReofferedAcrossClosures620=== RUN TestPresignedUploadRegisteredBeforeCommit621=== PAUSE TestPresignedUploadRegisteredBeforeCommit622=== RUN TestService_Rustfstest623=== PAUSE TestService_Rustfstest624=== RUN TestParseSize625=== PAUSE TestParseSize626=== RUN TestSkippedUploadsHandler627=== PAUSE TestSkippedUploadsHandler628=== RUN TestSystemdListenerNotActivated629--- PASS: TestSystemdListenerNotActivated (0.00s)630=== RUN TestWatchdogBeatsWhenHealthy631--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)632=== RUN TestWatchdogSkipsWhenUnhealthy6332026/10/01 07:38:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6342026/10/01 07:38:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6352026/10/01 07:38:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6362026/10/01 07:38:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6372026/10/01 07:38:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6382026/10/01 07:38:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6392026/10/01 07:38:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6402026/10/01 07:38:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6412026/10/01 07:38:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6422026/10/01 07:38:32 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"643--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)644=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle645=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle646=== RUN TestProxyWriteTimeout647=== PAUSE TestProxyWriteTimeout648=== RUN TestIsValidUploadKey649=== PAUSE TestIsValidUploadKey650=== RUN TestUploadHandlersRejectInvalidKeys651=== PAUSE TestUploadHandlersRejectInvalidKeys652=== RUN TestUploadHandlersRejectOversizedBody653=== PAUSE TestUploadHandlersRejectOversizedBody654=== RUN TestService_cleanupPendingClosuresHandler655=== PAUSE TestService_cleanupPendingClosuresHandler656=== RUN TestService_createPendingClosureHandler657=== PAUSE TestService_createPendingClosureHandler658=== RUN TestService_verifyS3Integrity659=== PAUSE TestService_verifyS3Integrity660=== RUN TestCompleteMultipartUnregistered661=== PAUSE TestCompleteMultipartUnregistered662=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT663=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT664=== CONT TestService_AuthMiddleware665=== CONT TestService_NativeMTLS666=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT667=== CONT TestCompleteMultipartUnregistered668=== CONT TestService_verifyS3Integrity669=== CONT TestService_createPendingClosureHandler670=== CONT TestService_cleanupPendingClosuresHandler671=== CONT TestUploadHandlersRejectOversizedBody672=== CONT TestUploadHandlersRejectInvalidKeys673=== CONT TestIsValidUploadKey674=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info675=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info676=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal677=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal678=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key679=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key680=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key681=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key682=== CONT TestProxyWriteTimeout683=== RUN TestProxyWriteTimeout/narinfo684=== PAUSE TestProxyWriteTimeout/narinfo685=== RUN TestProxyWriteTimeout/1_GiB_nar686=== PAUSE TestProxyWriteTimeout/1_GiB_nar687=== RUN TestProxyWriteTimeout/10_GiB_nar688=== PAUSE TestProxyWriteTimeout/10_GiB_nar689=== RUN TestProxyWriteTimeout/unknown_size690=== PAUSE TestProxyWriteTimeout/unknown_size691=== RUN TestIsValidUploadKey/narinfo692=== PAUSE TestIsValidUploadKey/narinfo693=== RUN TestIsValidUploadKey/nar_zst694=== PAUSE TestIsValidUploadKey/nar_zst695=== RUN TestIsValidUploadKey/nar_xz696=== PAUSE TestIsValidUploadKey/nar_xz697=== RUN TestIsValidUploadKey/nar_plain698=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle699=== PAUSE TestIsValidUploadKey/nar_plain700=== RUN TestIsValidUploadKey/listing701=== PAUSE TestIsValidUploadKey/listing702=== RUN TestIsValidUploadKey/build_log703=== PAUSE TestIsValidUploadKey/build_log704=== RUN TestIsValidUploadKey/build_log_home-manager_file705=== PAUSE TestIsValidUploadKey/build_log_home-manager_file706=== RUN TestIsValidUploadKey/build_log_plus_in_name707=== PAUSE TestIsValidUploadKey/build_log_plus_in_name708=== RUN TestIsValidUploadKey/build_log_question_mark709=== PAUSE TestIsValidUploadKey/build_log_question_mark710=== RUN TestIsValidUploadKey/build_log_equals711=== PAUSE TestIsValidUploadKey/build_log_equals712=== RUN TestIsValidUploadKey/realisation713=== PAUSE TestIsValidUploadKey/realisation714=== RUN TestIsValidUploadKey/realisation_plus_in_output715=== PAUSE TestIsValidUploadKey/realisation_plus_in_output716=== RUN TestIsValidUploadKey/nix-cache-info717=== PAUSE TestIsValidUploadKey/nix-cache-info718=== RUN TestIsValidUploadKey/index.html719=== PAUSE TestIsValidUploadKey/index.html720=== RUN TestIsValidUploadKey/narinfo_key,_nar_type721=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type722=== RUN TestIsValidUploadKey/nar_key,_narinfo_type723=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type724=== RUN TestIsValidUploadKey/listing_key,_narinfo_type725=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type726=== RUN TestIsValidUploadKey/traversal727=== PAUSE TestIsValidUploadKey/traversal728=== RUN TestIsValidUploadKey/traversal_nar729=== PAUSE TestIsValidUploadKey/traversal_nar730=== RUN TestIsValidUploadKey/absolute731=== PAUSE TestIsValidUploadKey/absolute732=== RUN TestIsValidUploadKey/empty_key733=== PAUSE TestIsValidUploadKey/empty_key734=== RUN TestIsValidUploadKey/unknown_type735=== PAUSE TestIsValidUploadKey/unknown_type736=== CONT TestSkippedUploadsHandler7372026/10/01 07:38:32 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000738--- PASS: TestSkippedUploadsHandler (0.00s)739=== CONT TestParseSize740--- PASS: TestParseSize (0.00s)741=== CONT TestService_Rustfstest742=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure743=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure744=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart745=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart746=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts747=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts748=== CONT TestPresignedUploadRegisteredBeforeCommit7492026-10-01 07:38:32.685 UTC [67745] ERROR: relation "goose_db_version" does not exist at character 367502026-10-01 07:38:32.685 UTC [67745] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7512026/10/01 07:38:32 OK 20241026095416_initial_model.sql (23.35ms)7522026-10-01 07:38:32.718 UTC [67747] ERROR: relation "goose_db_version" does not exist at character 367532026-10-01 07:38:32.718 UTC [67747] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7542026-10-01 07:38:32.719 UTC [67748] ERROR: relation "goose_db_version" does not exist at character 367552026-10-01 07:38:32.719 UTC [67748] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7562026-10-01 07:38:32.719 UTC [67746] ERROR: relation "goose_db_version" does not exist at character 367572026-10-01 07:38:32.719 UTC [67746] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7582026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (2.57ms)7592026-10-01 07:38:32.725 UTC [67749] ERROR: relation "goose_db_version" does not exist at character 367602026-10-01 07:38:32.725 UTC [67749] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7612026/10/01 07:38:32 OK 20251218171726_add_pins.sql (4.29ms)7622026-10-01 07:38:32.726 UTC [67750] ERROR: relation "goose_db_version" does not exist at character 367632026-10-01 07:38:32.726 UTC [67750] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7642026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (3.96ms)7652026/10/01 07:38:32 OK 20260905000000_add_claims.sql (5.25ms)7662026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (5.24ms)7672026/10/01 07:38:32 OK 20241026095416_initial_model.sql (16.19ms)7682026/10/01 07:38:32 OK 20241026095416_initial_model.sql (16.44ms)7692026/10/01 07:38:32 OK 20241026095416_initial_model.sql (18.35ms)7702026-10-01 07:38:32.745 UTC [67751] ERROR: relation "goose_db_version" does not exist at character 367712026-10-01 07:38:32.745 UTC [67751] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7722026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (4.07ms)7732026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200007742026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (3.98ms)7752026/10/01 07:38:32 OK 20241026095416_initial_model.sql (11.09ms)7762026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (3.24ms)7772026-10-01 07:38:32.747 UTC [67752] ERROR: relation "goose_db_version" does not exist at character 367782026-10-01 07:38:32.747 UTC [67752] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7792026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (3.75ms)7802026/10/01 07:38:32 OK 20241026095416_initial_model.sql (15.16ms)7812026/10/01 07:38:32 OK 1_commit_pending_closure.sql (2.75ms)7822026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)7832026/10/01 07:38:32 OK 2_object_stats_trigger.sql (716.04µs)7842026-10-01 07:38:32.749 UTC [67753] ERROR: relation "goose_db_version" does not exist at character 367852026-10-01 07:38:32.749 UTC [67753] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7862026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (1.28ms)7872026/10/01 07:38:32 OK 20251218171726_add_pins.sql (3.48ms)7882026/10/01 07:38:32 OK 3_commit_push.sql (968.5µs)7892026/10/01 07:38:32 goose: up to current file version: 37902026/10/01 07:38:32 OK 20251218171726_add_pins.sql (1.88ms)7912026/10/01 07:38:32 OK 20251218171726_add_pins.sql (3.56ms)7922026/10/01 07:38:32 OK 20251218171726_add_pins.sql (3.11ms)7932026-10-01 07:38:32.751 UTC [67754] ERROR: relation "goose_db_version" does not exist at character 367942026-10-01 07:38:32.751 UTC [67754] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7952026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (1.56ms)7962026/10/01 07:38:32 OK 20251218171726_add_pins.sql (2.36ms)7972026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (1.42ms)7982026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (2.4ms)7992026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (2.37ms)8002026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (2.26ms)8012026/10/01 07:38:32 OK 20260905000000_add_claims.sql (10.63ms)8022026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (56.62ms)8032026/10/01 07:38:32 OK 20260905000000_add_claims.sql (66.87ms)8042026/10/01 07:38:32 OK 20260905000000_add_claims.sql (66.56ms)8052026/10/01 07:38:32 OK 20260905000000_add_claims.sql (66.39ms)8062026/10/01 07:38:32 OK 20260905000000_add_claims.sql (75.37ms)8072026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (19.23ms)8082026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (19.57ms)8092026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (19.68ms)8102026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (10.16ms)8112026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (21.66ms)8122026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200008132026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (3.72ms)8142026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200008152026/10/01 07:38:32 OK 20241026095416_initial_model.sql (91.78ms)8162026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (4.39ms)8172026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200008182026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (4.6ms)8192026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200008202026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (5.84ms)8212026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200008222026/10/01 07:38:32 OK 1_commit_pending_closure.sql (3.6ms)8232026/10/01 07:38:32 OK 1_commit_pending_closure.sql (3.65ms)8242026/10/01 07:38:32 OK 1_commit_pending_closure.sql (2.72ms)8252026/10/01 07:38:32 OK 2_object_stats_trigger.sql (2.31ms)8262026/10/01 07:38:32 OK 20241026095416_initial_model.sql (94.34ms)8272026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (3.89ms)8282026/10/01 07:38:32 OK 20241026095416_initial_model.sql (96.18ms)8292026/10/01 07:38:32 OK 1_commit_pending_closure.sql (3.31ms)8302026/10/01 07:38:32 OK 1_commit_pending_closure.sql (4.27ms)8312026/10/01 07:38:32 OK 2_object_stats_trigger.sql (2.49ms)8322026/10/01 07:38:32 OK 2_object_stats_trigger.sql (2.89ms)8332026/10/01 07:38:32 OK 3_commit_push.sql (1.77ms)8342026/10/01 07:38:32 goose: up to current file version: 38352026/10/01 07:38:32 OK 2_object_stats_trigger.sql (963.21µs)8362026/10/01 07:38:32 OK 20241026095416_initial_model.sql (30.54ms)8372026/10/01 07:38:32 OK 2_object_stats_trigger.sql (751.96µs)8382026/10/01 07:38:32 OK 3_commit_push.sql (451.46µs)8392026/10/01 07:38:32 goose: up to current file version: 38402026/10/01 07:38:32 OK 3_commit_push.sql (804.42µs)8412026/10/01 07:38:32 goose: up to current file version: 38422026/10/01 07:38:32 OK 3_commit_push.sql (457.17µs)8432026/10/01 07:38:32 goose: up to current file version: 38442026/10/01 07:38:32 OK 3_commit_push.sql (396.33µs)8452026/10/01 07:38:32 goose: up to current file version: 38462026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (4.05ms)8472026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (7.69ms)8482026/10/01 07:38:32 OK 20251210153512_drop_unused_gin_index.sql (6.7ms)8492026/10/01 07:38:32 OK 20251218171726_add_pins.sql (18.41ms)8502026/10/01 07:38:32 OK 20251218171726_add_pins.sql (15.08ms)8512026/10/01 07:38:32 OK 20251218171726_add_pins.sql (10.76ms)8522026/10/01 07:38:32 OK 20251218171726_add_pins.sql (10.47ms)8532026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (17.34ms)8542026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (16.63ms)8552026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (17.69ms)8562026/10/01 07:38:32 OK 20260628120000_add_object_size_and_stats.sql (17.78ms)8572026/10/01 07:38:32 OK 20260905000000_add_claims.sql (16.79ms)8582026/10/01 07:38:32 OK 20260905000000_add_claims.sql (16.85ms)8592026/10/01 07:38:32 OK 20260905000000_add_claims.sql (16.93ms)8602026/10/01 07:38:32 OK 20260905000000_add_claims.sql (17.05ms)8612026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (14.42ms)8622026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (15.56ms)8632026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (20.8ms)8642026/10/01 07:38:32 OK 20260920000000_drop_claims.sql (23.96ms)8652026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (17.24ms)8662026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200008672026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (16.55ms)8682026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200008692026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (11.43ms)8702026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200008712026/10/01 07:38:32 OK 20260923120000_add_pushes.sql (8.21ms)8722026/10/01 07:38:32 goose: successfully migrated database to version: 202609231200008732026/10/01 07:38:32 OK 1_commit_pending_closure.sql (2.68ms)8742026/10/01 07:38:32 OK 1_commit_pending_closure.sql (1.68ms)8752026/10/01 07:38:32 OK 1_commit_pending_closure.sql (2.37ms)8762026/10/01 07:38:32 OK 1_commit_pending_closure.sql (2.02ms)8772026/10/01 07:38:32 OK 2_object_stats_trigger.sql (618.71µs)8782026/10/01 07:38:32 OK 2_object_stats_trigger.sql (562.67µs)8792026/10/01 07:38:32 OK 2_object_stats_trigger.sql (789.29µs)8802026/10/01 07:38:32 OK 2_object_stats_trigger.sql (545.46µs)8812026/10/01 07:38:32 OK 3_commit_push.sql (386µs)8822026/10/01 07:38:32 goose: up to current file version: 38832026/10/01 07:38:32 OK 3_commit_push.sql (388.83µs)8842026/10/01 07:38:32 goose: up to current file version: 38852026/10/01 07:38:32 OK 3_commit_push.sql (431.08µs)8862026/10/01 07:38:32 goose: up to current file version: 38872026/10/01 07:38:32 OK 3_commit_push.sql (343.42µs)8882026/10/01 07:38:32 goose: up to current file version: 38892026/10/01 07:38:32 INFO Received uploads request method=POST path=/api/pending_closures890--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.52s)891=== CONT TestCompletedNarNotReofferedAcrossClosures8922026/10/01 07:38:33 WARN mTLS auth: subject not in bound subjects subject="CN=reader"8932026/10/01 07:38:33 WARN mTLS auth: subject not in bound subjects subject="CN=reader"894--- PASS: TestService_NativeMTLS (0.63s)895=== CONT TestCompleteMultipartUpload_ErrorButObjectExists8962026/10/01 07:38:33 INFO Received uploads request method=POST path=/api/pending_closures8972026/10/01 07:38:33 INFO Received uploads request method=POST path=/api/pending_closures8982026/10/01 07:38:33 INFO Received uploads request method=POST path=/api/pending_closures8992026/10/01 07:38:33 INFO Received uploads request method=POST path=/api/pending_closures9002026-10-01 07:38:33.621 UTC [67831] ERROR: relation "goose_db_version" does not exist at character 369012026-10-01 07:38:33.621 UTC [67831] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9022026/10/01 07:38:33 OK 20241026095416_initial_model.sql (112.91ms)9032026/10/01 07:38:33 OK 20251210153512_drop_unused_gin_index.sql (13.63ms)9042026/10/01 07:38:33 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"905--- PASS: TestService_AuthMiddleware (1.29s)906=== CONT TestRedundantMultipartUpload9072026/10/01 07:38:33 OK 20251218171726_add_pins.sql (38.24ms)9082026/10/01 07:38:33 OK 20260628120000_add_object_size_and_stats.sql (34.8ms)9092026/10/01 07:38:33 OK 20260905000000_add_claims.sql (17.03ms)9102026-10-01 07:38:33.871 UTC [67838] ERROR: relation "goose_db_version" does not exist at character 369112026-10-01 07:38:33.871 UTC [67838] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9122026/10/01 07:38:33 OK 20260920000000_drop_claims.sql (11.86ms)9132026/10/01 07:38:33 OK 20260923120000_add_pushes.sql (21.99ms)9142026/10/01 07:38:33 goose: successfully migrated database to version: 202609231200009152026/10/01 07:38:33 OK 1_commit_pending_closure.sql (1.18ms)9162026/10/01 07:38:33 OK 2_object_stats_trigger.sql (303.71µs)9172026/10/01 07:38:33 OK 3_commit_push.sql (230.88µs)9182026/10/01 07:38:33 goose: up to current file version: 39192026/10/01 07:38:33 OK 20241026095416_initial_model.sql (50.09ms)9202026/10/01 07:38:33 OK 20251210153512_drop_unused_gin_index.sql (13.87ms)9212026/10/01 07:38:34 OK 20251218171726_add_pins.sql (13.75ms)9222026/10/01 07:38:34 OK 20260628120000_add_object_size_and_stats.sql (42.97ms)9232026/10/01 07:38:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9242026/10/01 07:38:34 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst925--- PASS: TestCompleteMultipartUnregistered (1.58s)926=== CONT TestPush_SignsNarinfosOfItsPendingObjects9272026/10/01 07:38:34 OK 20260905000000_add_claims.sql (60.44ms)9282026/10/01 07:38:34 OK 20260920000000_drop_claims.sql (37.12ms)9292026/10/01 07:38:34 OK 20260923120000_add_pushes.sql (24.3ms)9302026/10/01 07:38:34 goose: successfully migrated database to version: 202609231200009312026/10/01 07:38:34 OK 1_commit_pending_closure.sql (2.02ms)9322026/10/01 07:38:34 OK 2_object_stats_trigger.sql (296.79µs)9332026/10/01 07:38:34 OK 3_commit_push.sql (165.13µs)9342026/10/01 07:38:34 goose: up to current file version: 39352026/10/01 07:38:34 INFO Received cleanup request method=DELETE path=/api/pending_closures9362026/10/01 07:38:34 INFO Aborted multipart uploads count=09372026/10/01 07:38:34 INFO Received uploads request method=POST path=/api/pending_closures9382026/10/01 07:38:34 INFO Received cleanup request method=DELETE path=/api/pending_closures9392026/10/01 07:38:34 INFO Aborted multipart uploads count=19402026/10/01 07:38:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9412026-10-01 07:38:34.403 UTC [67752] ERROR: Closure does not exist: id=19422026-10-01 07:38:34.403 UTC [67752] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE9432026-10-01 07:38:34.403 UTC [67752] STATEMENT: -- name: CommitPendingClosure :exec944 SELECT commit_pending_closure($1::bigint)945 946--- PASS: TestService_cleanupPendingClosuresHandler (1.92s)947=== CONT TestPush_RejectsBadRequests9482026/10/01 07:38:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete949--- PASS: TestService_Rustfstest (2.16s)950=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9512026-10-01 07:38:34.686 UTC [67905] ERROR: relation "goose_db_version" does not exist at character 369522026-10-01 07:38:34.686 UTC [67905] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9532026/10/01 07:38:34 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YjZiNjgyMjYtOWM2OC00YzAzLWJkN2EtMmJhMTBiNDlmODMxLjgwY2I0Mjg5LTIyYzgtNGM0Yy05YzFjLTQwZWNmYzNhNjllOHgxNzkwODQwMzEzMzM5ODE0MDAw parts=109542026/10/01 07:38:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9552026/10/01 07:38:34 INFO Completed upload id=19562026/10/01 07:38:34 INFO Received uploads request method=POST path=/api/pending_closures9572026/10/01 07:38:34 INFO Received uploads request method=POST path=/api/pending_closures9582026/10/01 07:38:34 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9592026/10/01 07:38:34 WARN Found objects in DB but missing from S3, will re-upload count=1960--- PASS: TestService_verifyS3Integrity (2.31s)961=== CONT TestPush_CompleteCommitsEveryRoot9622026/10/01 07:38:34 OK 20241026095416_initial_model.sql (130.24ms)9632026/10/01 07:38:34 OK 20251210153512_drop_unused_gin_index.sql (16.05ms)9642026/10/01 07:38:34 OK 20251218171726_add_pins.sql (15.39ms)9652026/10/01 07:38:34 OK 20260628120000_add_object_size_and_stats.sql (28.6ms)9662026/10/01 07:38:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9672026/10/01 07:38:34 INFO Received uploads request method=POST path=/api/pending_closures9682026/10/01 07:38:34 OK 20260905000000_add_claims.sql (32.2ms)9692026/10/01 07:38:34 OK 20260920000000_drop_claims.sql (30.45ms)9702026/10/01 07:38:35 OK 20260923120000_add_pushes.sql (22.42ms)9712026/10/01 07:38:35 goose: successfully migrated database to version: 202609231200009722026/10/01 07:38:35 OK 1_commit_pending_closure.sql (4.37ms)9732026/10/01 07:38:35 OK 2_object_stats_trigger.sql (3.76ms)9742026/10/01 07:38:35 OK 3_commit_push.sql (9.57ms)9752026/10/01 07:38:35 goose: up to current file version: 39762026/10/01 07:38:35 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YjZiNjgyMjYtOWM2OC00YzAzLWJkN2EtMmJhMTBiNDlmODMxLmU2NWMwYzgyLTRkYTItNDgyMy05YzhjLWNiMTU3MDkzZTBmMXgxNzkwODQwMzEzNTQ1MDIwMDAw parts=109772026/10/01 07:38:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9782026/10/01 07:38:35 INFO Completed upload id=19792026/10/01 07:38:35 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009802026/10/01 07:38:35 INFO Received uploads request method=POST path=/api/pending_closures9812026/10/01 07:38:35 INFO Starting cleanup of old closures method=DELETE path=/api/closures9822026/10/01 07:38:35 INFO Aborted multipart uploads count=09832026/10/01 07:38:35 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=09842026/10/01 07:38:35 INFO Vacuumed table table=pending_closures9852026/10/01 07:38:35 INFO Vacuumed table table=pending_objects9862026-10-01 07:38:35.113 UTC [67929] ERROR: relation "goose_db_version" does not exist at character 369872026-10-01 07:38:35.113 UTC [67929] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9882026/10/01 07:38:35 INFO Vacuumed table table=multipart_uploads9892026/10/01 07:38:35 INFO Vacuumed table table=closures9902026/10/01 07:38:35 INFO Vacuumed table table=objects9912026/10/01 07:38:35 INFO Received uploads request method=POST path=/api/pending_closures9922026/10/01 07:38:35 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000993--- PASS: TestService_createPendingClosureHandler (2.74s)994=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9952026/10/01 07:38:35 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9962026/10/01 07:38:35 INFO Received uploads request method=POST path=/api/pending_closures997--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.74s)998=== CONT TestReadRedirectUsesPublicS3URL9992026/10/01 07:38:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10002026/10/01 07:38:35 OK 20241026095416_initial_model.sql (173.83ms)10012026/10/01 07:38:35 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)10022026/10/01 07:38:35 OK 20251218171726_add_pins.sql (14.18ms)10032026/10/01 07:38:35 OK 20260628120000_add_object_size_and_stats.sql (25.78ms)10042026/10/01 07:38:35 OK 20260905000000_add_claims.sql (26.78ms)10052026/10/01 07:38:35 OK 20260920000000_drop_claims.sql (29.21ms)10062026/10/01 07:38:35 INFO Received uploads request method=POST path=/api/pending_closures10072026/10/01 07:38:35 OK 20260923120000_add_pushes.sql (26.7ms)10082026/10/01 07:38:35 goose: successfully migrated database to version: 2026092312000010092026/10/01 07:38:35 OK 1_commit_pending_closure.sql (1.32ms)10102026/10/01 07:38:35 OK 2_object_stats_trigger.sql (255.21µs)10112026/10/01 07:38:35 OK 3_commit_push.sql (181.08µs)10122026/10/01 07:38:35 goose: up to current file version: 310132026/10/01 07:38:35 INFO Received uploads request method=POST path=/api/pending_closures10142026/10/01 07:38:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10152026/10/01 07:38:35 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjZiNjgyMjYtOWM2OC00YzAzLWJkN2EtMmJhMTBiNDlmODMxLjczODY5YzdlLWI2MWMtNGZjOS1hN2Y5LTMwZmQzYjE2OGJkYXgxNzkwODQwMzE1NzA2NjM1MDAw10162026/10/01 07:38:35 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjZiNjgyMjYtOWM2OC00YzAzLWJkN2EtMmJhMTBiNDlmODMxLjczODY5YzdlLWI2MWMtNGZjOS1hN2Y5LTMwZmQzYjE2OGJkYXgxNzkwODQwMzE1NzA2NjM1MDAw parts=11017--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.83s)1018=== CONT TestReadProxyRangeRequest10192026/10/01 07:38:35 INFO Received uploads request method=POST path=/api/pending_closures10202026/10/01 07:38:36 INFO Received uploads request method=POST path=/api/pending_closures10212026/10/01 07:38:36 INFO Received push request method=POST path=/api/pushes10222026/10/01 07:38:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10232026/10/01 07:38:36 INFO Signed narinfos id=1 count=11024--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.42s)1025=== CONT TestReadRedirectKeepsNarinfoProxied10262026-10-01 07:38:36.504 UTC [68058] ERROR: relation "goose_db_version" does not exist at character 3610272026-10-01 07:38:36.504 UTC [68058] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10282026-10-01 07:38:36.541 UTC [68063] ERROR: relation "goose_db_version" does not exist at character 3610292026-10-01 07:38:36.541 UTC [68063] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10302026/10/01 07:38:36 OK 20241026095416_initial_model.sql (124.51ms)10312026/10/01 07:38:36 OK 20251210153512_drop_unused_gin_index.sql (11.74ms)10322026-10-01 07:38:36.703 UTC [68089] ERROR: relation "goose_db_version" does not exist at character 3610332026-10-01 07:38:36.703 UTC [68089] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10342026/10/01 07:38:36 OK 20251218171726_add_pins.sql (26.02ms)10352026/10/01 07:38:36 OK 20241026095416_initial_model.sql (90.96ms)10362026/10/01 07:38:36 OK 20251210153512_drop_unused_gin_index.sql (15.36ms)10372026/10/01 07:38:36 OK 20260628120000_add_object_size_and_stats.sql (41.94ms)10382026/10/01 07:38:36 OK 20251218171726_add_pins.sql (27.45ms)10392026/10/01 07:38:36 OK 20260628120000_add_object_size_and_stats.sql (46.29ms)10402026/10/01 07:38:36 OK 20260905000000_add_claims.sql (98.86ms)10412026/10/01 07:38:36 OK 20260905000000_add_claims.sql (59.29ms)10422026/10/01 07:38:36 OK 20260920000000_drop_claims.sql (26.61ms)10432026/10/01 07:38:36 OK 20260920000000_drop_claims.sql (19.38ms)10442026/10/01 07:38:36 OK 20260923120000_add_pushes.sql (8.42ms)10452026/10/01 07:38:36 goose: successfully migrated database to version: 2026092312000010462026/10/01 07:38:36 OK 20260923120000_add_pushes.sql (7.68ms)10472026/10/01 07:38:36 goose: successfully migrated database to version: 2026092312000010482026/10/01 07:38:36 OK 1_commit_pending_closure.sql (7.24ms)10492026/10/01 07:38:36 OK 1_commit_pending_closure.sql (7.26ms)10502026/10/01 07:38:36 OK 2_object_stats_trigger.sql (7.97ms)10512026/10/01 07:38:36 OK 2_object_stats_trigger.sql (8.07ms)10522026-10-01 07:38:36.904 UTC [68115] ERROR: relation "goose_db_version" does not exist at character 3610532026-10-01 07:38:36.904 UTC [68115] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10542026/10/01 07:38:36 OK 3_commit_push.sql (6.62ms)10552026/10/01 07:38:36 goose: up to current file version: 310562026/10/01 07:38:36 OK 3_commit_push.sql (6.97ms)10572026/10/01 07:38:36 goose: up to current file version: 310582026/10/01 07:38:36 OK 20241026095416_initial_model.sql (208.51ms)10592026/10/01 07:38:37 OK 20251210153512_drop_unused_gin_index.sql (27.34ms)10602026-10-01 07:38:37.037 UTC [68119] ERROR: relation "goose_db_version" does not exist at character 3610612026-10-01 07:38:37.037 UTC [68119] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10622026/10/01 07:38:37 OK 20251218171726_add_pins.sql (36.74ms)10632026/10/01 07:38:37 OK 20260628120000_add_object_size_and_stats.sql (65.56ms)10642026/10/01 07:38:37 OK 20260905000000_add_claims.sql (44.04ms)10652026/10/01 07:38:37 OK 20241026095416_initial_model.sql (185.96ms)10662026/10/01 07:38:37 OK 20260920000000_drop_claims.sql (16.6ms)10672026/10/01 07:38:37 OK 20251210153512_drop_unused_gin_index.sql (17.11ms)10682026/10/01 07:38:37 OK 20251218171726_add_pins.sql (14ms)10692026/10/01 07:38:37 OK 20260923120000_add_pushes.sql (22.05ms)10702026/10/01 07:38:37 goose: successfully migrated database to version: 2026092312000010712026/10/01 07:38:37 OK 20241026095416_initial_model.sql (91.52ms)10722026/10/01 07:38:37 OK 20260628120000_add_object_size_and_stats.sql (15.75ms)10732026/10/01 07:38:37 OK 20251210153512_drop_unused_gin_index.sql (9.14ms)10742026/10/01 07:38:37 OK 20260905000000_add_claims.sql (6.98ms)10752026/10/01 07:38:37 OK 20251218171726_add_pins.sql (6.96ms)10762026/10/01 07:38:37 OK 20260920000000_drop_claims.sql (7.47ms)10772026/10/01 07:38:37 OK 1_commit_pending_closure.sql (37.16ms)10782026/10/01 07:38:37 OK 2_object_stats_trigger.sql (603.71µs)10792026/10/01 07:38:37 OK 3_commit_push.sql (446.58µs)10802026/10/01 07:38:37 goose: up to current file version: 310812026/10/01 07:38:37 OK 20260923120000_add_pushes.sql (13.55ms)10822026/10/01 07:38:37 goose: successfully migrated database to version: 2026092312000010832026/10/01 07:38:37 OK 1_commit_pending_closure.sql (2.15ms)10842026/10/01 07:38:37 OK 2_object_stats_trigger.sql (554µs)10852026/10/01 07:38:37 OK 3_commit_push.sql (370.92µs)10862026/10/01 07:38:37 goose: up to current file version: 310872026/10/01 07:38:37 OK 20260628120000_add_object_size_and_stats.sql (29.23ms)10882026/10/01 07:38:37 OK 20260905000000_add_claims.sql (6.9ms)10892026/10/01 07:38:37 OK 20260920000000_drop_claims.sql (2.47ms)10902026/10/01 07:38:37 OK 20260923120000_add_pushes.sql (11.68ms)10912026/10/01 07:38:37 goose: successfully migrated database to version: 2026092312000010922026/10/01 07:38:37 OK 1_commit_pending_closure.sql (1.08ms)10932026/10/01 07:38:37 OK 2_object_stats_trigger.sql (272.92µs)10942026/10/01 07:38:37 OK 3_commit_push.sql (261.13µs)10952026/10/01 07:38:37 goose: up to current file version: 31096=== RUN TestPush_RejectsBadRequests/no_objects1097=== PAUSE TestPush_RejectsBadRequests/no_objects1098=== RUN TestPush_RejectsBadRequests/bad_root1099=== PAUSE TestPush_RejectsBadRequests/bad_root1100=== RUN TestPush_RejectsBadRequests/root_not_in_objects1101=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1102=== RUN TestPush_RejectsBadRequests/no_roots1103=== PAUSE TestPush_RejectsBadRequests/no_roots1104=== CONT TestReadRedirectNar11052026/10/01 07:38:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11062026/10/01 07:38:37 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YjZiNjgyMjYtOWM2OC00YzAzLWJkN2EtMmJhMTBiNDlmODMxLmM1NTExYjAxLTgzYmUtNGE3MC04ZDhmLTIxYzBhMTg4MmZmN3gxNzkwODQwMzE1NDYxOTY4MDAw parts=1211072026/10/01 07:38:37 INFO Received uploads request method=POST path=/api/pending_closures1108--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.44s)1109=== CONT TestReadProxyDisabled11102026-10-01 07:38:37.569 UTC [68171] ERROR: relation "goose_db_version" does not exist at character 3611112026-10-01 07:38:37.569 UTC [68171] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11122026/10/01 07:38:37 INFO Received push request method=POST path=/api/pushes11132026/10/01 07:38:37 OK 20241026095416_initial_model.sql (145.9ms)11142026/10/01 07:38:37 OK 20251210153512_drop_unused_gin_index.sql (19.41ms)11152026/10/01 07:38:37 INFO Received complete push request method=POST path=/api/pushes/1/complete11162026/10/01 07:38:37 OK 20251218171726_add_pins.sql (13.21ms)11172026/10/01 07:38:37 INFO Received push request method=POST path=/api/pushes11182026/10/01 07:38:37 OK 20260628120000_add_object_size_and_stats.sql (14.71ms)11192026/10/01 07:38:37 OK 20260905000000_add_claims.sql (71.69ms)11202026/10/01 07:38:37 OK 20260920000000_drop_claims.sql (31.33ms)11212026/10/01 07:38:37 INFO Aborted multipart uploads count=011222026/10/01 07:38:37 WARN Force mode enabled - objects will be deleted immediately without grace period11232026/10/01 07:38:37 OK 20260923120000_add_pushes.sql (9.96ms)11242026/10/01 07:38:37 goose: successfully migrated database to version: 2026092312000011252026/10/01 07:38:37 OK 1_commit_pending_closure.sql (1.16ms)11262026/10/01 07:38:37 OK 2_object_stats_trigger.sql (447.04µs)11272026/10/01 07:38:37 OK 3_commit_push.sql (379.33µs)11282026/10/01 07:38:37 goose: up to current file version: 311292026/10/01 07:38:37 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=011302026/10/01 07:38:37 INFO Vacuumed table table=pending_closures11312026/10/01 07:38:37 INFO Vacuumed table table=pending_objects11322026-10-01 07:38:37.978 UTC [68216] ERROR: relation "goose_db_version" does not exist at character 3611332026-10-01 07:38:37.978 UTC [68216] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11342026/10/01 07:38:37 INFO Vacuumed table table=multipart_uploads11352026/10/01 07:38:38 INFO Received push request method=POST path=/api/pushes11362026/10/01 07:38:38 INFO Vacuumed table table=closures11372026/10/01 07:38:38 INFO Vacuumed table table=objects11382026/10/01 07:38:38 INFO Received complete push request method=POST path=/api/pushes/2/complete1139--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (3.35s)1140=== CONT TestReadProxyRootRedirectsToIndexHTML11412026/10/01 07:38:38 INFO Received complete push request method=POST path=/api/pushes/1/complete1142--- PASS: TestPush_CompleteCommitsEveryRoot (3.31s)1143=== CONT TestReadProxyConditionalGet11442026/10/01 07:38:38 OK 20241026095416_initial_model.sql (171.38ms)11452026/10/01 07:38:38 OK 20251210153512_drop_unused_gin_index.sql (10.03ms)11462026/10/01 07:38:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11472026/10/01 07:38:38 OK 20251218171726_add_pins.sql (15.33ms)11482026/10/01 07:38:38 OK 20260628120000_add_object_size_and_stats.sql (60.88ms)11492026/10/01 07:38:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjZiNjgyMjYtOWM2OC00YzAzLWJkN2EtMmJhMTBiNDlmODMxLjIxYzkzYTAxLWE0MWItNDk2Ny1hOWJjLTQyYTAxNjMwOTY4MngxNzkwODQwMzE2MDE4NjkzMDAw parts=121150--- PASS: TestRedundantMultipartUpload (4.55s)1151=== CONT TestReadProxyHead11522026/10/01 07:38:38 INFO Received push request method=POST path=/api/pushes11532026/10/01 07:38:38 OK 20260905000000_add_claims.sql (99.84ms)11542026/10/01 07:38:38 OK 20260920000000_drop_claims.sql (39.65ms)11552026/10/01 07:38:38 OK 20260923120000_add_pushes.sql (45.9ms)11562026/10/01 07:38:38 goose: successfully migrated database to version: 2026092312000011572026/10/01 07:38:38 OK 1_commit_pending_closure.sql (1.39ms)11582026/10/01 07:38:38 OK 2_object_stats_trigger.sql (263.67µs)11592026/10/01 07:38:38 OK 3_commit_push.sql (167.25µs)11602026/10/01 07:38:38 goose: up to current file version: 31161--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (3.29s)1162=== CONT TestReadProxyInvalidPath1163--- PASS: TestReadRedirectUsesPublicS3URL (3.51s)1164=== CONT TestReadProxy40411652026-10-01 07:38:39.028 UTC [68292] ERROR: relation "goose_db_version" does not exist at character 3611662026-10-01 07:38:39.028 UTC [68292] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1167--- PASS: TestReadProxyRangeRequest (3.26s)1168=== CONT TestReadProxyNarStreaming11692026/10/01 07:38:39 OK 20241026095416_initial_model.sql (293.3ms)11702026/10/01 07:38:39 OK 20251210153512_drop_unused_gin_index.sql (35.41ms)11712026/10/01 07:38:39 OK 20251218171726_add_pins.sql (30.58ms)11722026-10-01 07:38:39.505 UTC [68343] ERROR: relation "goose_db_version" does not exist at character 3611732026-10-01 07:38:39.505 UTC [68343] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11742026/10/01 07:38:39 OK 20260628120000_add_object_size_and_stats.sql (47.4ms)1175--- PASS: TestReadRedirectKeepsNarinfoProxied (3.13s)1176=== CONT TestReadProxyNarinfoAlreadyDecompressed11772026/10/01 07:38:39 OK 20260905000000_add_claims.sql (85.99ms)11782026/10/01 07:38:39 OK 20260920000000_drop_claims.sql (38.08ms)11792026/10/01 07:38:39 OK 20260923120000_add_pushes.sql (23.01ms)11802026/10/01 07:38:39 goose: successfully migrated database to version: 2026092312000011812026/10/01 07:38:39 OK 1_commit_pending_closure.sql (950.33µs)11822026/10/01 07:38:39 OK 2_object_stats_trigger.sql (238.17µs)11832026/10/01 07:38:39 OK 3_commit_push.sql (166.25µs)11842026/10/01 07:38:39 goose: up to current file version: 311852026/10/01 07:38:39 OK 20241026095416_initial_model.sql (224.51ms)11862026/10/01 07:38:39 OK 20251210153512_drop_unused_gin_index.sql (8.28ms)11872026/10/01 07:38:39 WARN Rate limiter enabled after throttle name=s3-test rate=511882026/10/01 07:38:39 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1189=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1190 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101191 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001192--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (7.34s)1193=== CONT TestReadProxyNarinfo11942026/10/01 07:38:39 OK 20251218171726_add_pins.sql (60.24ms)11952026/10/01 07:38:39 OK 20260628120000_add_object_size_and_stats.sql (28.68ms)11962026/10/01 07:38:39 OK 20260905000000_add_claims.sql (14.51ms)11972026/10/01 07:38:40 OK 20260920000000_drop_claims.sql (89.15ms)11982026/10/01 07:38:40 OK 20260923120000_add_pushes.sql (20.34ms)11992026/10/01 07:38:40 goose: successfully migrated database to version: 2026092312000012002026/10/01 07:38:40 OK 1_commit_pending_closure.sql (1.29ms)12012026/10/01 07:38:40 OK 2_object_stats_trigger.sql (626.04µs)12022026/10/01 07:38:40 OK 3_commit_push.sql (425.25µs)12032026/10/01 07:38:40 goose: up to current file version: 31204--- PASS: TestReadRedirectNar (2.80s)1205=== CONT TestIsValidCachePath1206=== RUN TestIsValidCachePath/narinfo1207=== PAUSE TestIsValidCachePath/narinfo1208=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1209=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1210=== RUN TestIsValidCachePath/nar_zst1211=== PAUSE TestIsValidCachePath/nar_zst1212=== RUN TestIsValidCachePath/nar_xz1213=== PAUSE TestIsValidCachePath/nar_xz1214=== RUN TestIsValidCachePath/nar_bz21215=== PAUSE TestIsValidCachePath/nar_bz21216=== RUN TestIsValidCachePath/nar_uncompressed1217=== PAUSE TestIsValidCachePath/nar_uncompressed1218=== RUN TestIsValidCachePath/ls1219=== PAUSE TestIsValidCachePath/ls1220=== RUN TestIsValidCachePath/log1221=== PAUSE TestIsValidCachePath/log1222=== RUN TestIsValidCachePath/realisation1223=== PAUSE TestIsValidCachePath/realisation1224=== RUN TestIsValidCachePath/nix-cache-info1225=== PAUSE TestIsValidCachePath/nix-cache-info1226=== RUN TestIsValidCachePath/index.html1227=== PAUSE TestIsValidCachePath/index.html1228=== RUN TestIsValidCachePath/traversal_parent1229=== PAUSE TestIsValidCachePath/traversal_parent1230=== RUN TestIsValidCachePath/traversal_in_middle1231=== PAUSE TestIsValidCachePath/traversal_in_middle1232=== RUN TestIsValidCachePath/invalid_char_e1233=== PAUSE TestIsValidCachePath/invalid_char_e1234=== RUN TestIsValidCachePath/invalid_char_u1235=== PAUSE TestIsValidCachePath/invalid_char_u1236=== RUN TestIsValidCachePath/random_path1237=== PAUSE TestIsValidCachePath/random_path1238=== RUN TestIsValidCachePath/empty1239=== PAUSE TestIsValidCachePath/empty1240=== RUN TestIsValidCachePath/leading_slash1241=== PAUSE TestIsValidCachePath/leading_slash1242=== RUN TestIsValidCachePath/wrong_extension12432026-10-01 07:38:40.117 UTC [68392] ERROR: relation "goose_db_version" does not exist at character 3612442026-10-01 07:38:40.117 UTC [68392] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1245=== PAUSE TestIsValidCachePath/wrong_extension1246=== RUN TestIsValidCachePath/short_hash1247=== PAUSE TestIsValidCachePath/short_hash1248=== CONT TestProxyHeadersOnlyTrustedOnSocket12492026-10-01 07:38:40.263 UTC [68403] ERROR: relation "goose_db_version" does not exist at character 3612502026-10-01 07:38:40.263 UTC [68403] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12512026/10/01 07:38:40 OK 20241026095416_initial_model.sql (236.94ms)12522026/10/01 07:38:40 OK 20251210153512_drop_unused_gin_index.sql (7.38ms)12532026/10/01 07:38:40 OK 20251218171726_add_pins.sql (37.6ms)1254--- PASS: TestReadProxyDisabled (3.04s)1255=== CONT TestParseSingleRange1256=== RUN TestParseSingleRange/none1257=== PAUSE TestParseSingleRange/none1258=== RUN TestParseSingleRange/unknown_unit1259=== PAUSE TestParseSingleRange/unknown_unit1260=== RUN TestParseSingleRange/multi-range_ignored1261=== PAUSE TestParseSingleRange/multi-range_ignored1262=== RUN TestParseSingleRange/malformed_no_dash1263=== PAUSE TestParseSingleRange/malformed_no_dash1264=== RUN TestParseSingleRange/malformed_both_empty1265=== PAUSE TestParseSingleRange/malformed_both_empty1266=== RUN TestParseSingleRange/malformed_end_before_start1267=== PAUSE TestParseSingleRange/malformed_end_before_start1268=== RUN TestParseSingleRange/closed1269=== PAUSE TestParseSingleRange/closed1270=== RUN TestParseSingleRange/open-ended1271=== PAUSE TestParseSingleRange/open-ended1272=== RUN TestParseSingleRange/end_clamped_to_size1273=== PAUSE TestParseSingleRange/end_clamped_to_size1274=== RUN TestParseSingleRange/suffix1275=== PAUSE TestParseSingleRange/suffix1276=== RUN TestParseSingleRange/suffix_exceeds_size1277=== PAUSE TestParseSingleRange/suffix_exceeds_size1278=== RUN TestParseSingleRange/single_byte1279=== PAUSE TestParseSingleRange/single_byte1280=== RUN TestParseSingleRange/start_past_EOF1281=== PAUSE TestParseSingleRange/start_past_EOF1282=== RUN TestParseSingleRange/start_far_past_EOF1283=== PAUSE TestParseSingleRange/start_far_past_EOF1284=== CONT TestCreatePin_ReservedPins12852026-10-01 07:38:40.494 UTC [68414] ERROR: relation "goose_db_version" does not exist at character 3612862026-10-01 07:38:40.494 UTC [68414] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12872026/10/01 07:38:40 OK 20260628120000_add_object_size_and_stats.sql (45.33ms)12882026/10/01 07:38:40 OK 20241026095416_initial_model.sql (213.15ms)12892026-10-01 07:38:40.554 UTC [68421] ERROR: relation "goose_db_version" does not exist at character 3612902026-10-01 07:38:40.554 UTC [68421] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12912026/10/01 07:38:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57363/oidc12922026/10/01 07:38:40 OK 20251210153512_drop_unused_gin_index.sql (15.06ms)12932026/10/01 07:38:40 OK 20260905000000_add_claims.sql (67.6ms)12942026/10/01 07:38:40 OK 20260920000000_drop_claims.sql (27.96ms)12952026/10/01 07:38:40 OK 20251218171726_add_pins.sql (30.21ms)12962026/10/01 07:38:40 OK 20260923120000_add_pushes.sql (6.7ms)12972026/10/01 07:38:40 goose: successfully migrated database to version: 2026092312000012982026/10/01 07:38:40 OK 1_commit_pending_closure.sql (7.18ms)12992026/10/01 07:38:40 OK 2_object_stats_trigger.sql (6.41ms)13002026/10/01 07:38:40 OK 3_commit_push.sql (600.71µs)13012026/10/01 07:38:40 goose: up to current file version: 313022026/10/01 07:38:40 OK 20260628120000_add_object_size_and_stats.sql (24.09ms)13032026/10/01 07:38:40 OK 20241026095416_initial_model.sql (44.52ms)13042026/10/01 07:38:40 OK 20251210153512_drop_unused_gin_index.sql (12.42ms)13052026/10/01 07:38:40 OK 20251218171726_add_pins.sql (46.42ms)13062026/10/01 07:38:40 OK 20260905000000_add_claims.sql (81.14ms)13072026/10/01 07:38:40 OK 20260628120000_add_object_size_and_stats.sql (38.54ms)13082026/10/01 07:38:40 OK 20260920000000_drop_claims.sql (54.81ms)13092026/10/01 07:38:40 OK 20260923120000_add_pushes.sql (21ms)13102026/10/01 07:38:40 goose: successfully migrated database to version: 2026092312000013112026/10/01 07:38:40 OK 1_commit_pending_closure.sql (903.96µs)13122026/10/01 07:38:40 OK 2_object_stats_trigger.sql (235.71µs)13132026/10/01 07:38:40 OK 3_commit_push.sql (161.46µs)13142026/10/01 07:38:40 goose: up to current file version: 313152026/10/01 07:38:40 OK 20260905000000_add_claims.sql (94.73ms)13162026/10/01 07:38:40 OK 20241026095416_initial_model.sql (215.34ms)13172026/10/01 07:38:40 OK 20251210153512_drop_unused_gin_index.sql (12.02ms)13182026/10/01 07:38:40 OK 20260920000000_drop_claims.sql (44.69ms)13192026/10/01 07:38:40 OK 20251218171726_add_pins.sql (30.92ms)13202026/10/01 07:38:40 OK 20260923120000_add_pushes.sql (19.93ms)13212026/10/01 07:38:40 goose: successfully migrated database to version: 2026092312000013222026/10/01 07:38:40 OK 1_commit_pending_closure.sql (3.4ms)13232026/10/01 07:38:40 OK 2_object_stats_trigger.sql (618.25µs)13242026/10/01 07:38:40 OK 3_commit_push.sql (445.63µs)13252026/10/01 07:38:40 goose: up to current file version: 313262026/10/01 07:38:40 OK 20260628120000_add_object_size_and_stats.sql (24.64ms)13272026/10/01 07:38:40 OK 20260905000000_add_claims.sql (68.64ms)13282026-10-01 07:38:40.986 UTC [68449] ERROR: relation "goose_db_version" does not exist at character 3613292026-10-01 07:38:40.986 UTC [68449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13302026/10/01 07:38:41 OK 20260920000000_drop_claims.sql (48.37ms)13312026/10/01 07:38:41 OK 20260923120000_add_pushes.sql (36.19ms)13322026/10/01 07:38:41 goose: successfully migrated database to version: 202609231200001333--- PASS: TestReadProxyRootRedirectsToIndexHTML (3.01s)1334=== CONT TestOrphanedObjectsGCStressTest13352026/10/01 07:38:41 OK 1_commit_pending_closure.sql (2.38ms)13362026/10/01 07:38:41 OK 2_object_stats_trigger.sql (716.54µs)13372026/10/01 07:38:41 OK 3_commit_push.sql (467.29µs)13382026/10/01 07:38:41 goose: up to current file version: 313392026-10-01 07:38:41.183 UTC [68459] ERROR: relation "goose_db_version" does not exist at character 3613402026-10-01 07:38:41.183 UTC [68459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13412026/10/01 07:38:41 OK 20241026095416_initial_model.sql (184.56ms)13422026/10/01 07:38:41 OK 20251210153512_drop_unused_gin_index.sql (19.53ms)13432026/10/01 07:38:41 OK 20251218171726_add_pins.sql (38.43ms)13442026/10/01 07:38:41 OK 20260628120000_add_object_size_and_stats.sql (32.73ms)13452026/10/01 07:38:41 OK 20260905000000_add_claims.sql (36.96ms)13462026/10/01 07:38:41 OK 20260920000000_drop_claims.sql (6.21ms)13472026/10/01 07:38:41 OK 20260923120000_add_pushes.sql (13.35ms)13482026/10/01 07:38:41 goose: successfully migrated database to version: 202609231200001349--- PASS: TestReadProxyConditionalGet (3.28s)1350=== CONT TestOrphanedObjectsGC13512026/10/01 07:38:41 OK 1_commit_pending_closure.sql (1.87ms)13522026/10/01 07:38:41 OK 2_object_stats_trigger.sql (499.17µs)13532026/10/01 07:38:41 OK 3_commit_push.sql (2.02ms)13542026/10/01 07:38:41 goose: up to current file version: 313552026/10/01 07:38:41 OK 20241026095416_initial_model.sql (176.5ms)13562026/10/01 07:38:41 OK 20251210153512_drop_unused_gin_index.sql (17.82ms)13572026/10/01 07:38:41 OK 20251218171726_add_pins.sql (20.59ms)13582026/10/01 07:38:41 OK 20260628120000_add_object_size_and_stats.sql (51.42ms)13592026-10-01 07:38:41.544 UTC [68487] ERROR: relation "goose_db_version" does not exist at character 3613602026-10-01 07:38:41.544 UTC [68487] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13612026/10/01 07:38:41 OK 20260905000000_add_claims.sql (81.18ms)13622026/10/01 07:38:41 OK 20260920000000_drop_claims.sql (30.2ms)13632026/10/01 07:38:41 OK 20260923120000_add_pushes.sql (23.84ms)13642026/10/01 07:38:41 goose: successfully migrated database to version: 2026092312000013652026/10/01 07:38:41 OK 1_commit_pending_closure.sql (1.88ms)13662026/10/01 07:38:41 OK 2_object_stats_trigger.sql (497.75µs)13672026/10/01 07:38:41 OK 3_commit_push.sql (441.04µs)13682026/10/01 07:38:41 goose: up to current file version: 31369--- PASS: TestReadProxyHead (3.44s)1370=== CONT TestObjectStatsTrigger13712026-10-01 07:38:41.841 UTC [68494] ERROR: relation "goose_db_version" does not exist at character 3613722026-10-01 07:38:41.841 UTC [68494] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13732026/10/01 07:38:41 OK 20241026095416_initial_model.sql (238.33ms)13742026/10/01 07:38:41 OK 20251210153512_drop_unused_gin_index.sql (18.65ms)13752026/10/01 07:38:41 OK 20251218171726_add_pins.sql (39.34ms)13762026/10/01 07:38:41 OK 20260628120000_add_object_size_and_stats.sql (36.42ms)13772026/10/01 07:38:42 OK 20260905000000_add_claims.sql (80.78ms)13782026/10/01 07:38:42 OK 20241026095416_initial_model.sql (111.15ms)13792026/10/01 07:38:42 OK 20251210153512_drop_unused_gin_index.sql (17.89ms)1380--- PASS: TestReadProxyInvalidPath (3.57s)1381=== CONT TestMultipartCleanup13822026/10/01 07:38:42 OK 20260920000000_drop_claims.sql (68.44ms)13832026/10/01 07:38:42 OK 20251218171726_add_pins.sql (52.13ms)13842026/10/01 07:38:42 OK 20260923120000_add_pushes.sql (32.86ms)13852026/10/01 07:38:42 goose: successfully migrated database to version: 2026092312000013862026/10/01 07:38:42 OK 1_commit_pending_closure.sql (1.31ms)13872026/10/01 07:38:42 OK 2_object_stats_trigger.sql (580.96µs)13882026/10/01 07:38:42 OK 3_commit_push.sql (452.88µs)13892026/10/01 07:38:42 goose: up to current file version: 313902026/10/01 07:38:42 OK 20260628120000_add_object_size_and_stats.sql (61.1ms)13912026-10-01 07:38:42.189 UTC [68529] ERROR: relation "goose_db_version" does not exist at character 3613922026-10-01 07:38:42.189 UTC [68529] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13932026/10/01 07:38:42 OK 20260905000000_add_claims.sql (37.41ms)13942026/10/01 07:38:42 OK 20260920000000_drop_claims.sql (82.47ms)13952026/10/01 07:38:42 OK 20260923120000_add_pushes.sql (19.74ms)13962026/10/01 07:38:42 goose: successfully migrated database to version: 2026092312000013972026/10/01 07:38:42 OK 1_commit_pending_closure.sql (26.95ms)13982026/10/01 07:38:42 OK 2_object_stats_trigger.sql (16.59ms)13992026/10/01 07:38:42 OK 3_commit_push.sql (1.68ms)14002026/10/01 07:38:42 goose: up to current file version: 314012026-10-01 07:38:42.411 UTC [68542] ERROR: relation "goose_db_version" does not exist at character 3614022026-10-01 07:38:42.411 UTC [68542] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14032026/10/01 07:38:42 OK 20241026095416_initial_model.sql (148.45ms)14042026/10/01 07:38:42 OK 20251210153512_drop_unused_gin_index.sql (15.11ms)14052026/10/01 07:38:42 OK 20251218171726_add_pins.sql (77.37ms)1406--- PASS: TestReadProxy404 (3.77s)1407=== CONT TestServerTLSConfig1408=== RUN TestServerTLSConfig/no_client_CA1409=== PAUSE TestServerTLSConfig/no_client_CA1410=== RUN TestServerTLSConfig/missing_CA_file1411=== PAUSE TestServerTLSConfig/missing_CA_file1412=== RUN TestServerTLSConfig/not_a_PEM_file1413=== PAUSE TestServerTLSConfig/not_a_PEM_file1414=== CONT TestPushDedupSurvivesConcurrentGC14152026/10/01 07:38:42 OK 20260628120000_add_object_size_and_stats.sql (32.45ms)14162026/10/01 07:38:42 OK 20260905000000_add_claims.sql (62.54ms)14172026/10/01 07:38:42 OK 20241026095416_initial_model.sql (84.47ms)14182026/10/01 07:38:42 OK 20260920000000_drop_claims.sql (19.88ms)14192026/10/01 07:38:42 OK 20251210153512_drop_unused_gin_index.sql (17.46ms)14202026-10-01 07:38:42.654 UTC [68551] ERROR: relation "goose_db_version" does not exist at character 3614212026-10-01 07:38:42.654 UTC [68551] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14222026/10/01 07:38:42 OK 20251218171726_add_pins.sql (15.17ms)14232026/10/01 07:38:42 OK 20260923120000_add_pushes.sql (23ms)14242026/10/01 07:38:42 goose: successfully migrated database to version: 2026092312000014252026/10/01 07:38:42 OK 1_commit_pending_closure.sql (5.44ms)14262026/10/01 07:38:42 OK 2_object_stats_trigger.sql (8.99ms)14272026/10/01 07:38:42 OK 3_commit_push.sql (2.74ms)14282026/10/01 07:38:42 goose: up to current file version: 314292026/10/01 07:38:42 OK 20260628120000_add_object_size_and_stats.sql (46.99ms)14302026/10/01 07:38:42 OK 20260905000000_add_claims.sql (52.57ms)14312026/10/01 07:38:42 OK 20260920000000_drop_claims.sql (21.87ms)14322026/10/01 07:38:42 OK 20260923120000_add_pushes.sql (6.01ms)14332026/10/01 07:38:42 goose: successfully migrated database to version: 2026092312000014342026/10/01 07:38:42 OK 1_commit_pending_closure.sql (2.19ms)14352026/10/01 07:38:42 OK 2_object_stats_trigger.sql (261.04µs)14362026/10/01 07:38:42 OK 3_commit_push.sql (176.42µs)14372026/10/01 07:38:42 goose: up to current file version: 314382026/10/01 07:38:42 OK 20241026095416_initial_model.sql (45.76ms)14392026/10/01 07:38:42 OK 20251210153512_drop_unused_gin_index.sql (12.84ms)14402026/10/01 07:38:42 OK 20251218171726_add_pins.sql (23.22ms)14412026/10/01 07:38:42 OK 20260628120000_add_object_size_and_stats.sql (28.16ms)1442--- PASS: TestReadProxyNarStreaming (3.71s)1443=== CONT TestMetricsInventory14442026/10/01 07:38:42 OK 20260905000000_add_claims.sql (65.24ms)14452026/10/01 07:38:42 OK 20260920000000_drop_claims.sql (23.34ms)14462026/10/01 07:38:42 OK 20260923120000_add_pushes.sql (24.69ms)14472026/10/01 07:38:42 goose: successfully migrated database to version: 2026092312000014482026/10/01 07:38:42 OK 1_commit_pending_closure.sql (1.74ms)14492026/10/01 07:38:42 OK 2_object_stats_trigger.sql (724.63µs)14502026/10/01 07:38:42 OK 3_commit_push.sql (345.83µs)14512026/10/01 07:38:42 goose: up to current file version: 314522026-10-01 07:38:43.051 UTC [68572] ERROR: relation "goose_db_version" does not exist at character 3614532026-10-01 07:38:43.051 UTC [68572] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1454--- PASS: TestReadProxyNarinfoAlreadyDecompressed (3.56s)1455=== CONT TestNARDeduplicationMetadataUploadBug14562026/10/01 07:38:43 OK 20241026095416_initial_model.sql (118.83ms)14572026/10/01 07:38:43 OK 20251210153512_drop_unused_gin_index.sql (14.72ms)14582026-10-01 07:38:43.240 UTC [68584] ERROR: relation "goose_db_version" does not exist at character 3614592026-10-01 07:38:43.240 UTC [68584] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14602026/10/01 07:38:43 OK 20251218171726_add_pins.sql (27.22ms)14612026/10/01 07:38:43 OK 20260628120000_add_object_size_and_stats.sql (38.44ms)14622026/10/01 07:38:43 OK 20260905000000_add_claims.sql (24.93ms)14632026/10/01 07:38:43 OK 20260920000000_drop_claims.sql (14.95ms)14642026/10/01 07:38:43 OK 20260923120000_add_pushes.sql (6.3ms)14652026/10/01 07:38:43 goose: successfully migrated database to version: 2026092312000014662026/10/01 07:38:43 OK 1_commit_pending_closure.sql (4.3ms)14672026/10/01 07:38:43 OK 2_object_stats_trigger.sql (1.36ms)14682026/10/01 07:38:43 OK 3_commit_push.sql (1.36ms)14692026/10/01 07:38:43 goose: up to current file version: 314702026/10/01 07:38:43 OK 20241026095416_initial_model.sql (97.73ms)14712026/10/01 07:38:43 OK 20251210153512_drop_unused_gin_index.sql (21.04ms)14722026/10/01 07:38:43 OK 20251218171726_add_pins.sql (13.99ms)1473--- PASS: TestReadProxyNarinfo (3.61s)1474=== CONT TestCreatePendingClosureRejectsOversizedNAR14752026/10/01 07:38:43 INFO Received uploads request method=POST path=/api/pending_closures1476--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1477=== CONT TestCacheConfigHandlerMaxNarSize1478--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1479=== CONT TestGenerateLandingPage1480--- PASS: TestGenerateLandingPage (0.00s)1481=== CONT TestService_readinessHandler14822026/10/01 07:38:43 OK 20260628120000_add_object_size_and_stats.sql (35.97ms)14832026/10/01 07:38:43 OK 20260905000000_add_claims.sql (112.71ms)14842026-10-01 07:38:43.588 UTC [68589] ERROR: relation "goose_db_version" does not exist at character 3614852026-10-01 07:38:43.588 UTC [68589] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14862026/10/01 07:38:43 OK 20260920000000_drop_claims.sql (61.83ms)14872026/10/01 07:38:43 OK 20260923120000_add_pushes.sql (31.7ms)14882026/10/01 07:38:43 goose: successfully migrated database to version: 2026092312000014892026/10/01 07:38:43 OK 1_commit_pending_closure.sql (1.08ms)14902026/10/01 07:38:43 OK 2_object_stats_trigger.sql (235.71µs)14912026/10/01 07:38:43 OK 3_commit_push.sql (188.71µs)14922026/10/01 07:38:43 goose: up to current file version: 314932026/10/01 07:38:43 INFO Starting HTTP server address=127.0.0.1:5740514942026/10/01 07:38:43 INFO Starting HTTP server address=/nix/var/nix/builds/nix-66626-273570313/TestProxyHeadersOnlyTrustedOnSocket3804061379/001/proxy.sock14952026/10/01 07:38:43 WARN mTLS auth: subject not in bound subjects subject="CN=someone"14962026/10/01 07:38:43 INFO Shutdown signal received, draining in-flight requests timeout=10s1497--- PASS: TestProxyHeadersOnlyTrustedOnSocket (3.60s)1498=== CONT TestService_healthCheckHandler14992026/10/01 07:38:43 OK 20241026095416_initial_model.sql (168.81ms)15002026/10/01 07:38:43 OK 20251210153512_drop_unused_gin_index.sql (16.14ms)15012026/10/01 07:38:43 OK 20251218171726_add_pins.sql (42.17ms)15022026-10-01 07:38:43.903 UTC [68606] ERROR: relation "goose_db_version" does not exist at character 3615032026-10-01 07:38:43.903 UTC [68606] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15042026/10/01 07:38:43 OK 20260628120000_add_object_size_and_stats.sql (23.57ms)15052026/10/01 07:38:43 OK 20260905000000_add_claims.sql (48.69ms)15062026/10/01 07:38:43 OK 20260920000000_drop_claims.sql (24.06ms)15072026/10/01 07:38:43 OK 20260923120000_add_pushes.sql (20.49ms)15082026/10/01 07:38:43 goose: successfully migrated database to version: 2026092312000015092026/10/01 07:38:44 OK 1_commit_pending_closure.sql (1.71ms)15102026/10/01 07:38:44 OK 2_object_stats_trigger.sql (549µs)15112026/10/01 07:38:44 OK 3_commit_push.sql (202.46µs)15122026/10/01 07:38:44 goose: up to current file version: 315132026/10/01 07:38:44 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15142026/10/01 07:38:44 WARN Refused reserved pin name=worker-x86_64-linux15152026/10/01 07:38:44 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15162026/10/01 07:38:44 INFO Received create pin request method=POST path=/api/pins/my-app15172026/10/01 07:38:44 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1518--- PASS: TestCreatePin_ReservedPins (3.52s)1519=== CONT TestGracefulShutdownDrainsInflight15202026/10/01 07:38:44 INFO Starting HTTP server address=127.0.0.1:5741415212026/10/01 07:38:44 INFO Shutdown signal received, draining in-flight requests timeout=10s15222026/10/01 07:38:44 OK 20241026095416_initial_model.sql (96.4ms)15232026/10/01 07:38:44 OK 20251210153512_drop_unused_gin_index.sql (23.3ms)1524--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1525=== CONT TestGCTaskStore_Fail1526--- PASS: TestGCTaskStore_Fail (0.00s)1527=== CONT TestGCTaskStore_PhaseUpdates1528--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1529=== CONT TestGCTaskStore_CompletedAllowsNewTask1530--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1531=== CONT TestGCTaskStore_GetReturnsLatest1532--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1533=== CONT TestGCTaskStore_GetEmpty1534--- PASS: TestGCTaskStore_GetEmpty (0.00s)1535=== CONT TestGCTaskStore_ConflictDifferentParams1536--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1537=== CONT TestGCTaskStore_DeduplicateSameParams1538--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1539=== CONT TestGCTaskStore_StartNew1540--- PASS: TestGCTaskStore_StartNew (0.00s)1541=== CONT TestFailedS3DeleteKeepsTombstone15422026/10/01 07:38:44 OK 20251218171726_add_pins.sql (42.47ms)15432026/10/01 07:38:44 OK 20260628120000_add_object_size_and_stats.sql (60.09ms)15442026/10/01 07:38:44 OK 20260905000000_add_claims.sql (63.17ms)15452026/10/01 07:38:44 OK 20260920000000_drop_claims.sql (48.31ms)15462026/10/01 07:38:44 OK 20260923120000_add_pushes.sql (36.31ms)15472026/10/01 07:38:44 goose: successfully migrated database to version: 2026092312000015482026/10/01 07:38:44 OK 1_commit_pending_closure.sql (1.12ms)15492026/10/01 07:38:44 OK 2_object_stats_trigger.sql (279.13µs)15502026/10/01 07:38:44 OK 3_commit_push.sql (186.42µs)15512026/10/01 07:38:44 goose: up to current file version: 31552--- PASS: TestObjectStatsTrigger (3.57s)1553=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection15542026-10-01 07:38:45.443 UTC [68634] ERROR: relation "goose_db_version" does not exist at character 3615552026-10-01 07:38:45.443 UTC [68634] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15562026-10-01 07:38:45.535 UTC [68635] ERROR: relation "goose_db_version" does not exist at character 3615572026-10-01 07:38:45.535 UTC [68635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15582026/10/01 07:38:45 INFO Received uploads request method=POST path=/api/pending_closures15592026-10-01 07:38:45.782 UTC [68637] ERROR: relation "goose_db_version" does not exist at character 3615602026-10-01 07:38:45.782 UTC [68637] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15612026/10/01 07:38:45 OK 20241026095416_initial_model.sql (210.51ms)15622026/10/01 07:38:45 OK 20251210153512_drop_unused_gin_index.sql (17.42ms)15632026/10/01 07:38:45 INFO Received cleanup request method=DELETE path=/api/pending_closures15642026/10/01 07:38:45 OK 20251218171726_add_pins.sql (71.85ms)15652026/10/01 07:38:45 INFO Aborted multipart uploads count=11566--- PASS: TestMultipartCleanup (3.88s)1567=== CONT TestGCSweepDeliversEachKeyOnce15682026/10/01 07:38:46 OK 20260628120000_add_object_size_and_stats.sql (87.12ms)15692026/10/01 07:38:46 OK 20241026095416_initial_model.sql (447.6ms)15702026/10/01 07:38:46 OK 20251210153512_drop_unused_gin_index.sql (10.3ms)15712026/10/01 07:38:46 OK 20260905000000_add_claims.sql (136.62ms)1572=== NAME TestOrphanedObjectsGC1573 orphaned_objects_gc_test.go:290: GC Test Summary:1574 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1575 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1576 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1577 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1578 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1579--- PASS: TestOrphanedObjectsGC (4.76s)1580=== CONT TestTombstonedObjectOfferedWithoutWaiting15812026/10/01 07:38:46 OK 20260920000000_drop_claims.sql (38.89ms)15822026/10/01 07:38:46 OK 20251218171726_add_pins.sql (56.04ms)15832026/10/01 07:38:46 OK 20260923120000_add_pushes.sql (56.21ms)15842026/10/01 07:38:46 goose: successfully migrated database to version: 2026092312000015852026/10/01 07:38:46 OK 1_commit_pending_closure.sql (1.07ms)15862026/10/01 07:38:46 OK 2_object_stats_trigger.sql (256.83µs)15872026/10/01 07:38:46 OK 3_commit_push.sql (186.79µs)15882026/10/01 07:38:46 goose: up to current file version: 315892026/10/01 07:38:46 OK 20241026095416_initial_model.sql (397.8ms)15902026/10/01 07:38:46 OK 20260628120000_add_object_size_and_stats.sql (87.77ms)15912026/10/01 07:38:46 OK 20251210153512_drop_unused_gin_index.sql (25.71ms)15922026/10/01 07:38:46 OK 20251218171726_add_pins.sql (58.33ms)15932026/10/01 07:38:46 OK 20260905000000_add_claims.sql (117.75ms)15942026/10/01 07:38:46 OK 20260628120000_add_object_size_and_stats.sql (76.16ms)15952026/10/01 07:38:46 OK 20260920000000_drop_claims.sql (71.2ms)15962026/10/01 07:38:46 INFO Received uploads request method=POST path=/api/pending_closures15972026/10/01 07:38:46 OK 20260923120000_add_pushes.sql (29.48ms)15982026/10/01 07:38:46 goose: successfully migrated database to version: 2026092312000015992026/10/01 07:38:46 OK 1_commit_pending_closure.sql (930.5µs)16002026/10/01 07:38:46 OK 2_object_stats_trigger.sql (217.75µs)16012026/10/01 07:38:46 OK 3_commit_push.sql (165.67µs)16022026/10/01 07:38:46 goose: up to current file version: 316032026/10/01 07:38:46 OK 20260905000000_add_claims.sql (126.18ms)16042026/10/01 07:38:46 INFO Aborted multipart uploads count=016052026/10/01 07:38:46 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=016062026/10/01 07:38:46 INFO Vacuumed table table=pending_closures16072026/10/01 07:38:46 OK 20260920000000_drop_claims.sql (126.47ms)16082026-10-01 07:38:46.699 UTC [68677] ERROR: relation "goose_db_version" does not exist at character 3616092026-10-01 07:38:46.699 UTC [68677] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16102026/10/01 07:38:46 OK 20260923120000_add_pushes.sql (35.84ms)16112026/10/01 07:38:46 goose: successfully migrated database to version: 2026092312000016122026/10/01 07:38:46 OK 1_commit_pending_closure.sql (970.79µs)16132026/10/01 07:38:46 OK 2_object_stats_trigger.sql (243.54µs)16142026/10/01 07:38:46 OK 3_commit_push.sql (193.71µs)16152026/10/01 07:38:46 goose: up to current file version: 316162026/10/01 07:38:46 INFO Vacuumed table table=pending_objects16172026/10/01 07:38:46 INFO Vacuumed table table=multipart_uploads16182026/10/01 07:38:46 INFO Vacuumed table table=closures16192026/10/01 07:38:46 INFO Vacuumed table table=objects16202026/10/01 07:38:46 INFO Aborted multipart uploads count=016212026/10/01 07:38:46 WARN Force mode enabled - objects will be deleted immediately without grace period16222026/10/01 07:38:46 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016232026/10/01 07:38:46 INFO Vacuumed table table=pending_closures16242026/10/01 07:38:46 INFO Vacuumed table table=pending_objects16252026/10/01 07:38:46 INFO Vacuumed table table=multipart_uploads1626--- PASS: TestMetricsInventory (4.01s)1627=== CONT TestGCSweepSkipsPendingObjects16282026/10/01 07:38:46 INFO Vacuumed table table=closures16292026/10/01 07:38:46 INFO Vacuumed table table=objects1630--- PASS: TestPushDedupSurvivesConcurrentGC (4.38s)1631=== CONT TestDeduplicatedObjectsRecordedAsPending16322026/10/01 07:38:47 OK 20241026095416_initial_model.sql (474.71ms)16332026/10/01 07:38:47 OK 20251210153512_drop_unused_gin_index.sql (37.43ms)16342026/10/01 07:38:47 OK 20251218171726_add_pins.sql (58.78ms)16352026/10/01 07:38:47 OK 20260628120000_add_object_size_and_stats.sql (80.28ms)16362026/10/01 07:38:47 OK 20260905000000_add_claims.sql (135.66ms)16372026/10/01 07:38:47 OK 20260920000000_drop_claims.sql (98.22ms)16382026/10/01 07:38:47 OK 20260923120000_add_pushes.sql (39.43ms)16392026/10/01 07:38:47 goose: successfully migrated database to version: 2026092312000016402026/10/01 07:38:47 OK 1_commit_pending_closure.sql (2.01ms)16412026/10/01 07:38:47 OK 2_object_stats_trigger.sql (450.92µs)16422026/10/01 07:38:47 OK 3_commit_push.sql (397.75µs)16432026/10/01 07:38:47 goose: up to current file version: 316442026/10/01 07:38:47 WARN readiness check failed error="closed pool"1645--- PASS: TestService_readinessHandler (4.42s)1646=== CONT TestClientMultipleUploads1647=== NAME TestNARDeduplicationMetadataUploadBug1648 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-66626-273570313/TestNARDeduplicationMetadataUploadBug366012075/001/store/8ykbv98yzy1pmxarr5mkpnw0ra5bcfgq-file1.txt16492026-10-01 07:38:47.999 UTC [68717] ERROR: relation "goose_db_version" does not exist at character 3616502026-10-01 07:38:47.999 UTC [68717] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16512026/10/01 07:38:48 INFO Received push request method=POST path=/api/pushes16522026/10/01 07:38:48 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16532026/10/01 07:38:48 INFO Uploading 8ykbv98yzy1pmxarr5mkpnw0ra5bcfgq-file1.txt (160B)16542026/10/01 07:38:48 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"16552026/10/01 07:38:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16562026/10/01 07:38:48 WARN Failed to register uploaded object key=8ykbv98yzy1pmxarr5mkpnw0ra5bcfgq.ls error="server returned 404: 404 page not found\n"16572026/10/01 07:38:48 INFO Signed narinfos id=1 count=116582026/10/01 07:38:48 INFO Uploading 1 narinfos16592026/10/01 07:38:48 INFO Received complete push request method=POST path=/api/pushes/1/complete16602026/10/01 07:38:48 WARN Failed to register uploaded object key=8ykbv98yzy1pmxarr5mkpnw0ra5bcfgq.narinfo error="server returned 404: 404 page not found\n"16612026/10/01 07:38:48 OK 20241026095416_initial_model.sql (248.93ms)16622026/10/01 07:38:48 OK 20251210153512_drop_unused_gin_index.sql (27.3ms)16632026/10/01 07:38:48 INFO Upload complete. (338ms)1664 metadata_upload_test.go:54: Retrieved narinfo from S3:1665 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestNARDeduplicationMetadataUploadBug366012075/001/store/8ykbv98yzy1pmxarr5mkpnw0ra5bcfgq-file1.txt1666 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1667 Compression: zstd1668 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1669 NarSize: 1601670 References: 1671 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1672 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1673 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1674 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}16752026/10/01 07:38:48 OK 20251218171726_add_pins.sql (16.4ms)16762026/10/01 07:38:48 OK 20260628120000_add_object_size_and_stats.sql (75.45ms)1677--- PASS: TestService_healthCheckHandler (4.73s)1678=== CONT TestGCMetrics1679=== NAME TestNARDeduplicationMetadataUploadBug1680 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-66626-273570313/TestNARDeduplicationMetadataUploadBug366012075/001/store/zpsqy04b8fxlpawwc4bh22l0g94iw226-file2.txt16812026/10/01 07:38:48 OK 20260905000000_add_claims.sql (75.84ms)16822026/10/01 07:38:48 OK 20260920000000_drop_claims.sql (76.83ms)16832026/10/01 07:38:48 OK 20260923120000_add_pushes.sql (8.16ms)16842026/10/01 07:38:48 goose: successfully migrated database to version: 2026092312000016852026/10/01 07:38:48 OK 1_commit_pending_closure.sql (6.08ms)16862026/10/01 07:38:48 OK 2_object_stats_trigger.sql (2.2ms)16872026/10/01 07:38:48 OK 3_commit_push.sql (964.33µs)16882026/10/01 07:38:48 goose: up to current file version: 316892026/10/01 07:38:48 INFO Received push request method=POST path=/api/pushes16902026/10/01 07:38:48 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16912026/10/01 07:38:48 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16922026-10-01 07:38:48.735 UTC [68733] ERROR: relation "goose_db_version" does not exist at character 3616932026-10-01 07:38:48.735 UTC [68733] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16942026/10/01 07:38:48 INFO Signed narinfos id=2 count=116952026/10/01 07:38:48 WARN Failed to register uploaded object key=zpsqy04b8fxlpawwc4bh22l0g94iw226.ls error="server returned 404: 404 page not found\n"16962026/10/01 07:38:48 INFO Uploading 1 narinfos16972026/10/01 07:38:48 INFO Received complete push request method=POST path=/api/pushes/2/complete16982026/10/01 07:38:48 WARN Failed to register uploaded object key=zpsqy04b8fxlpawwc4bh22l0g94iw226.narinfo error="server returned 404: 404 page not found\n"16992026/10/01 07:38:48 INFO Upload complete. (221ms)1700 metadata_upload_test.go:76: Retrieved narinfo from S3:1701 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestNARDeduplicationMetadataUploadBug366012075/001/store/zpsqy04b8fxlpawwc4bh22l0g94iw226-file2.txt1702 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1703 Compression: zstd1704 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1705 NarSize: 1601706 References: 1707 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1708 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1709 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1710 {"version":1,"root":{"type":"regular","size":44}}1711--- PASS: TestNARDeduplicationMetadataUploadBug (5.81s)1712=== CONT TestGCBugBareHashReferences17132026/10/01 07:38:49 INFO Received uploads request method=POST path=/api/pending_closures17142026/10/01 07:38:49 OK 20241026095416_initial_model.sql (377.15ms)17152026/10/01 07:38:49 OK 20251210153512_drop_unused_gin_index.sql (22.06ms)17162026/10/01 07:38:49 OK 20251218171726_add_pins.sql (61.66ms)17172026/10/01 07:38:49 OK 20260628120000_add_object_size_and_stats.sql (90.91ms)17182026/10/01 07:38:49 INFO Aborted multipart uploads count=017192026/10/01 07:38:49 WARN Force mode enabled - objects will be deleted immediately without grace period17202026/10/01 07:38:49 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."17212026/10/01 07:38:49 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."1722--- PASS: TestFailedS3DeleteKeepsTombstone (5.35s)1723=== CONT TestLeadEndsOnShutdown17242026/10/01 07:38:49 OK 20260905000000_add_claims.sql (114.76ms)17252026/10/01 07:38:49 OK 20260920000000_drop_claims.sql (87.51ms)17262026/10/01 07:38:49 OK 20260923120000_add_pushes.sql (38.18ms)17272026/10/01 07:38:49 goose: successfully migrated database to version: 2026092312000017282026/10/01 07:38:49 OK 1_commit_pending_closure.sql (2.2ms)17292026/10/01 07:38:49 OK 2_object_stats_trigger.sql (308.29µs)17302026/10/01 07:38:49 OK 3_commit_push.sql (180.63µs)17312026/10/01 07:38:49 goose: up to current file version: 317322026-10-01 07:38:49.839 UTC [68745] ERROR: relation "goose_db_version" does not exist at character 3617332026-10-01 07:38:49.839 UTC [68745] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17342026/10/01 07:38:50 INFO Received uploads request method=POST path=/api/pending_closures17352026/10/01 07:38:50 OK 20241026095416_initial_model.sql (360.8ms)17362026/10/01 07:38:50 OK 20251210153512_drop_unused_gin_index.sql (37.23ms)17372026/10/01 07:38:50 OK 20251218171726_add_pins.sql (44.03ms)1738--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (5.14s)1739=== CONT TestLeadElectsOneAndHandsOver17402026/10/01 07:38:50 OK 20260628120000_add_object_size_and_stats.sql (80.3ms)17412026-10-01 07:38:50.676 UTC [68754] ERROR: relation "goose_db_version" does not exist at character 3617422026-10-01 07:38:50.676 UTC [68754] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17432026/10/01 07:38:50 OK 20260905000000_add_claims.sql (151.95ms)17442026/10/01 07:38:50 OK 20260920000000_drop_claims.sql (96.66ms)17452026/10/01 07:38:50 OK 20260923120000_add_pushes.sql (14.59ms)17462026/10/01 07:38:50 goose: successfully migrated database to version: 2026092312000017472026/10/01 07:38:50 OK 1_commit_pending_closure.sql (2.11ms)17482026/10/01 07:38:50 OK 2_object_stats_trigger.sql (542.25µs)17492026/10/01 07:38:50 OK 3_commit_push.sql (409.38µs)17502026/10/01 07:38:50 goose: up to current file version: 317512026-10-01 07:38:50.923 UTC [68758] ERROR: relation "goose_db_version" does not exist at character 3617522026-10-01 07:38:50.923 UTC [68758] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17532026-10-01 07:38:50.936 UTC [68757] ERROR: relation "goose_db_version" does not exist at character 3617542026-10-01 07:38:50.936 UTC [68757] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17552026/10/01 07:38:51 OK 20241026095416_initial_model.sql (337.87ms)17562026/10/01 07:38:51 OK 20251210153512_drop_unused_gin_index.sql (17.2ms)17572026/10/01 07:38:51 OK 20251218171726_add_pins.sql (86.19ms)17582026/10/01 07:38:51 OK 20260628120000_add_object_size_and_stats.sql (49.9ms)17592026/10/01 07:38:51 OK 20241026095416_initial_model.sql (292.5ms)17602026/10/01 07:38:51 OK 20251210153512_drop_unused_gin_index.sql (12.24ms)17612026/10/01 07:38:51 OK 20241026095416_initial_model.sql (390.43ms)17622026/10/01 07:38:51 OK 20260905000000_add_claims.sql (129.5ms)17632026/10/01 07:38:51 OK 20251210153512_drop_unused_gin_index.sql (17.83ms)17642026/10/01 07:38:51 OK 20251218171726_add_pins.sql (87.45ms)17652026/10/01 07:38:51 INFO Aborted multipart uploads count=017662026/10/01 07:38:51 WARN Force mode enabled - objects will be deleted immediately without grace period17672026/10/01 07:38:51 OK 20251218171726_add_pins.sql (72.81ms)17682026/10/01 07:38:51 OK 20260920000000_drop_claims.sql (95.35ms)17692026/10/01 07:38:51 OK 20260923120000_add_pushes.sql (54.77ms)17702026/10/01 07:38:51 goose: successfully migrated database to version: 2026092312000017712026/10/01 07:38:51 OK 1_commit_pending_closure.sql (998.5µs)17722026/10/01 07:38:51 OK 2_object_stats_trigger.sql (240.21µs)17732026/10/01 07:38:51 OK 3_commit_push.sql (175µs)17742026/10/01 07:38:51 goose: up to current file version: 317752026/10/01 07:38:51 OK 20260628120000_add_object_size_and_stats.sql (98.47ms)17762026/10/01 07:38:51 OK 20260628120000_add_object_size_and_stats.sql (118.46ms)17772026/10/01 07:38:51 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=017782026/10/01 07:38:51 INFO Vacuumed table table=pending_closures17792026/10/01 07:38:51 INFO Vacuumed table table=pending_objects17802026/10/01 07:38:51 INFO Vacuumed table table=multipart_uploads17812026/10/01 07:38:51 INFO Vacuumed table table=closures17822026/10/01 07:38:51 OK 20260905000000_add_claims.sql (189.45ms)17832026/10/01 07:38:51 INFO Vacuumed table table=objects1784--- PASS: TestGCSweepDeliversEachKeyOnce (5.88s)1785=== CONT TestResolveDBConnectionString17862026/10/01 07:38:51 OK 20260905000000_add_claims.sql (244.31ms)1787=== RUN TestResolveDBConnectionString/flag_wins1788=== PAUSE TestResolveDBConnectionString/flag_wins1789=== RUN TestResolveDBConnectionString/file_when_flag_empty1790=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1791=== RUN TestResolveDBConnectionString/missing_file_is_an_error1792=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1793=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1794=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1795=== RUN TestResolveDBConnectionString/nothing_configured1796=== PAUSE TestResolveDBConnectionString/nothing_configured1797=== CONT TestClientFallsBackToClosures17982026/10/01 07:38:51 OK 20260920000000_drop_claims.sql (154.17ms)17992026/10/01 07:38:51 OK 20260923120000_add_pushes.sql (35.89ms)18002026/10/01 07:38:51 goose: successfully migrated database to version: 2026092312000018012026/10/01 07:38:51 OK 1_commit_pending_closure.sql (2.39ms)18022026/10/01 07:38:51 OK 2_object_stats_trigger.sql (580.21µs)18032026/10/01 07:38:51 OK 3_commit_push.sql (452.08µs)18042026/10/01 07:38:51 goose: up to current file version: 318052026/10/01 07:38:52 OK 20260920000000_drop_claims.sql (145.28ms)18062026/10/01 07:38:52 OK 20260923120000_add_pushes.sql (63.12ms)18072026/10/01 07:38:52 goose: successfully migrated database to version: 2026092312000018082026/10/01 07:38:52 OK 1_commit_pending_closure.sql (1.98ms)18092026/10/01 07:38:52 OK 2_object_stats_trigger.sql (548.42µs)18102026/10/01 07:38:52 OK 3_commit_push.sql (477.88µs)18112026/10/01 07:38:52 goose: up to current file version: 318122026/10/01 07:38:52 INFO Received uploads request method=POST path=/api/pending_closures18132026-10-01 07:38:52.468 UTC [68768] ERROR: relation "goose_db_version" does not exist at character 3618142026-10-01 07:38:52.468 UTC [68768] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1815--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.34s)1816=== CONT TestClientPushesUseOnePush18172026/10/01 07:38:52 INFO Received uploads request method=POST path=/api/pending_closures1818--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.00s)1819=== CONT TestPinProtectsFromGC18202026/10/01 07:38:53 OK 20241026095416_initial_model.sql (514.86ms)18212026/10/01 07:38:53 OK 20251210153512_drop_unused_gin_index.sql (33.16ms)18222026-10-01 07:38:53.207 UTC [68777] ERROR: relation "goose_db_version" does not exist at character 3618232026-10-01 07:38:53.207 UTC [68777] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18242026/10/01 07:38:53 OK 20251218171726_add_pins.sql (69.95ms)18252026/10/01 07:38:53 OK 20260628120000_add_object_size_and_stats.sql (96.96ms)18262026/10/01 07:38:53 INFO Received uploads request method=POST path=/api/pending_closures18272026/10/01 07:38:53 OK 20260905000000_add_claims.sql (187.72ms)18282026/10/01 07:38:53 INFO Aborted multipart uploads count=018292026/10/01 07:38:53 WARN Force mode enabled - objects will be deleted immediately without grace period18302026/10/01 07:38:53 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018312026/10/01 07:38:53 OK 20260920000000_drop_claims.sql (97.71ms)18322026/10/01 07:38:53 INFO Vacuumed table table=pending_closures18332026/10/01 07:38:53 INFO Vacuumed table table=pending_objects18342026/10/01 07:38:53 OK 20260923120000_add_pushes.sql (70.55ms)18352026/10/01 07:38:53 goose: successfully migrated database to version: 2026092312000018362026/10/01 07:38:53 INFO Vacuumed table table=multipart_uploads18372026/10/01 07:38:53 INFO Vacuumed table table=closures18382026/10/01 07:38:53 OK 1_commit_pending_closure.sql (1.03ms)18392026/10/01 07:38:53 OK 2_object_stats_trigger.sql (283.33µs)18402026/10/01 07:38:53 OK 3_commit_push.sql (176.83µs)18412026/10/01 07:38:53 goose: up to current file version: 318422026/10/01 07:38:53 INFO Vacuumed table table=objects1843--- PASS: TestGCSweepSkipsPendingObjects (6.90s)1844=== CONT TestClientSharedPathCommittedMidPush18452026/10/01 07:38:53 OK 20241026095416_initial_model.sql (516.4ms)18462026/10/01 07:38:53 OK 20251210153512_drop_unused_gin_index.sql (19.12ms)18472026/10/01 07:38:53 OK 20251218171726_add_pins.sql (71.96ms)18482026/10/01 07:38:54 OK 20260628120000_add_object_size_and_stats.sql (94.9ms)18492026-10-01 07:38:54.185 UTC [68828] ERROR: relation "goose_db_version" does not exist at character 3618502026-10-01 07:38:54.185 UTC [68828] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18512026/10/01 07:38:54 OK 20260905000000_add_claims.sql (146.03ms)18522026/10/01 07:38:54 OK 20260920000000_drop_claims.sql (137.77ms)18532026/10/01 07:38:54 OK 20260923120000_add_pushes.sql (33.1ms)18542026/10/01 07:38:54 goose: successfully migrated database to version: 2026092312000018552026/10/01 07:38:54 OK 1_commit_pending_closure.sql (1.97ms)18562026/10/01 07:38:54 OK 2_object_stats_trigger.sql (418.25µs)18572026/10/01 07:38:54 OK 3_commit_push.sql (337.42µs)18582026/10/01 07:38:54 goose: up to current file version: 318592026/10/01 07:38:54 OK 20241026095416_initial_model.sql (392.79ms)18602026/10/01 07:38:54 OK 20251210153512_drop_unused_gin_index.sql (22.27ms)18612026/10/01 07:38:54 OK 20251218171726_add_pins.sql (89.8ms)18622026/10/01 07:38:54 OK 20260628120000_add_object_size_and_stats.sql (77.76ms)18632026/10/01 07:38:54 INFO Aborted multipart uploads count=018642026-10-01 07:38:54.999 UTC [68835] ERROR: relation "goose_db_version" does not exist at character 3618652026-10-01 07:38:54.999 UTC [68835] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1866=== NAME TestClientMultipleUploads1867 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-66626-273570313/TestClientMultipleUploads3603210339/001/store/8x9h4w7zkrcc8fli503jyabmy6fn07yv-test-file-0.txt18682026/10/01 07:38:55 OK 20260905000000_add_claims.sql (120.68ms)18692026/10/01 07:38:55 WARN Force mode enabled - objects will be deleted immediately without grace period18702026/10/01 07:38:55 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=018712026/10/01 07:38:55 INFO Vacuumed table table=pending_closures18722026/10/01 07:38:55 INFO Vacuumed table table=pending_objects18732026/10/01 07:38:55 INFO Vacuumed table table=multipart_uploads18742026/10/01 07:38:55 INFO Vacuumed table table=closures18752026/10/01 07:38:55 INFO Vacuumed table table=objects1876--- PASS: TestGCMetrics (6.60s)1877=== CONT TestClientWithDependencies18782026/10/01 07:38:55 OK 20260920000000_drop_claims.sql (97.51ms)18792026/10/01 07:38:55 OK 20260923120000_add_pushes.sql (22.07ms)18802026/10/01 07:38:55 goose: successfully migrated database to version: 2026092312000018812026/10/01 07:38:55 OK 1_commit_pending_closure.sql (2.71ms)18822026/10/01 07:38:55 OK 2_object_stats_trigger.sql (312.75µs)18832026/10/01 07:38:55 OK 3_commit_push.sql (232.46µs)18842026/10/01 07:38:55 goose: up to current file version: 31885=== NAME TestClientMultipleUploads1886 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-66626-273570313/TestClientMultipleUploads3603210339/001/store/d2lyk96xs3bclsff0lif07wdwi7j5v8z-test-file-1.txt1887 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-66626-273570313/TestClientMultipleUploads3603210339/001/store/kyzzik44v6h31ql9vy164cfvhb90r8i6-test-file-2.txt18882026-10-01 07:38:55.410 UTC [68842] ERROR: relation "goose_db_version" does not exist at character 3618892026-10-01 07:38:55.410 UTC [68842] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18902026/10/01 07:38:55 INFO Received push request method=POST path=/api/pushes18912026/10/01 07:38:55 OK 20241026095416_initial_model.sql (417.57ms)18922026/10/01 07:38:55 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18932026/10/01 07:38:55 INFO Uploading d2lyk96xs3bclsff0lif07wdwi7j5v8z-test-file-1.txt (160B)18942026/10/01 07:38:55 INFO Uploading kyzzik44v6h31ql9vy164cfvhb90r8i6-test-file-2.txt (160B)18952026/10/01 07:38:55 INFO Uploading 8x9h4w7zkrcc8fli503jyabmy6fn07yv-test-file-0.txt (160B)18962026/10/01 07:38:55 OK 20251210153512_drop_unused_gin_index.sql (25.9ms)18972026/10/01 07:38:55 OK 20251218171726_add_pins.sql (28.27ms)18982026/10/01 07:38:55 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18992026/10/01 07:38:55 WARN Failed to register uploaded object key=d2lyk96xs3bclsff0lif07wdwi7j5v8z.ls error="server returned 404: 404 page not found\n"19002026/10/01 07:38:55 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19012026/10/01 07:38:55 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19022026/10/01 07:38:55 WARN Failed to register uploaded object key=kyzzik44v6h31ql9vy164cfvhb90r8i6.ls error="server returned 404: 404 page not found\n"19032026/10/01 07:38:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19042026/10/01 07:38:55 WARN Failed to register uploaded object key=8x9h4w7zkrcc8fli503jyabmy6fn07yv.ls error="server returned 404: 404 page not found\n"19052026/10/01 07:38:55 INFO Signed narinfos id=1 count=319062026/10/01 07:38:55 INFO Uploading 3 narinfos19072026/10/01 07:38:55 WARN Failed to register uploaded object key=8x9h4w7zkrcc8fli503jyabmy6fn07yv.narinfo error="server returned 404: 404 page not found\n"19082026/10/01 07:38:55 INFO Received complete push request method=POST path=/api/pushes/1/complete19092026/10/01 07:38:55 WARN Failed to register uploaded object key=d2lyk96xs3bclsff0lif07wdwi7j5v8z.narinfo error="server returned 404: 404 page not found\n"19102026/10/01 07:38:55 WARN Failed to register uploaded object key=kyzzik44v6h31ql9vy164cfvhb90r8i6.narinfo error="server returned 404: 404 page not found\n"19112026/10/01 07:38:55 OK 20260628120000_add_object_size_and_stats.sql (90.81ms)19122026/10/01 07:38:55 INFO Upload complete. (295ms)1913 client_integration_test.go:369: Uploaded 3 paths in 338.089583ms19142026/10/01 07:38:55 OK 20260905000000_add_claims.sql (246.48ms)19152026/10/01 07:38:55 OK 20241026095416_initial_model.sql (404.45ms)19162026/10/01 07:38:55 OK 20251210153512_drop_unused_gin_index.sql (21.99ms)1917--- PASS: TestClientMultipleUploads (8.08s)1918=== CONT TestService_ReadScope_PublicByDefault19192026/10/01 07:38:56 OK 20260920000000_drop_claims.sql (89.85ms)19202026/10/01 07:38:56 OK 20251218171726_add_pins.sql (75.79ms)1921--- PASS: TestGCBugBareHashReferences (7.03s)1922=== CONT TestClientIntegration19232026/10/01 07:38:56 OK 20260923120000_add_pushes.sql (43.96ms)19242026/10/01 07:38:56 goose: successfully migrated database to version: 2026092312000019252026/10/01 07:38:56 OK 1_commit_pending_closure.sql (1.11ms)19262026/10/01 07:38:56 OK 2_object_stats_trigger.sql (266.96µs)19272026/10/01 07:38:56 OK 3_commit_push.sql (171.17µs)19282026/10/01 07:38:56 goose: up to current file version: 319292026/10/01 07:38:56 OK 20260628120000_add_object_size_and_stats.sql (86.83ms)19302026/10/01 07:38:56 OK 20260905000000_add_claims.sql (152.92ms)19312026/10/01 07:38:56 OK 20260920000000_drop_claims.sql (124.99ms)19322026/10/01 07:38:56 OK 20260923120000_add_pushes.sql (41.32ms)19332026/10/01 07:38:56 goose: successfully migrated database to version: 2026092312000019342026/10/01 07:38:56 OK 1_commit_pending_closure.sql (1.49ms)19352026/10/01 07:38:56 OK 2_object_stats_trigger.sql (373.33µs)19362026/10/01 07:38:56 OK 3_commit_push.sql (306.21µs)19372026/10/01 07:38:56 goose: up to current file version: 319382026/10/01 07:38:56 INFO lead: acquired remote=192.0.2.1:123419392026/10/01 07:38:56 INFO lead: released remote=192.0.2.1:12341940--- PASS: TestLeadEndsOnShutdown (7.24s)1941=== CONT TestClientErrorHandling1942=== RUN TestClientErrorHandling/InvalidStorePath1943=== PAUSE TestClientErrorHandling/InvalidStorePath1944=== RUN TestClientErrorHandling/InvalidAuthToken1945=== PAUSE TestClientErrorHandling/InvalidAuthToken1946=== RUN TestClientErrorHandling/ServerNotAvailable1947=== PAUSE TestClientErrorHandling/ServerNotAvailable1948=== CONT TestClientCADerivations1949=== NAME TestOrphanedObjectsGCStressTest1950 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1951 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion19522026-10-01 07:38:57.005 UTC [68863] ERROR: relation "goose_db_version" does not exist at character 3619532026-10-01 07:38:57.005 UTC [68863] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19542026/10/01 07:38:57 INFO lead: acquired remote=192.0.2.1:123419552026/10/01 07:38:57 INFO lead: released remote=192.0.2.1:123419562026/10/01 07:38:57 INFO lead: acquired remote=192.0.2.1:123419572026/10/01 07:38:57 OK 20241026095416_initial_model.sql (321.26ms)19582026/10/01 07:38:57 INFO lead: released remote=192.0.2.1:12341959--- PASS: TestLeadElectsOneAndHandsOver (7.00s)1960=== CONT TestCacheStatsHandler19612026/10/01 07:38:57 OK 20251210153512_drop_unused_gin_index.sql (22.61ms)19622026/10/01 07:38:57 OK 20251218171726_add_pins.sql (60.85ms)19632026-10-01 07:38:57.550 UTC [68874] ERROR: relation "goose_db_version" does not exist at character 3619642026-10-01 07:38:57.550 UTC [68874] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19652026-10-01 07:38:57.608 UTC [68877] ERROR: relation "goose_db_version" does not exist at character 3619662026-10-01 07:38:57.608 UTC [68877] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19672026/10/01 07:38:57 OK 20260628120000_add_object_size_and_stats.sql (70.15ms)19682026/10/01 07:38:57 OK 20260905000000_add_claims.sql (99.42ms)19692026/10/01 07:38:57 OK 20260920000000_drop_claims.sql (64.15ms)19702026/10/01 07:38:57 OK 20260923120000_add_pushes.sql (13.87ms)19712026/10/01 07:38:57 goose: successfully migrated database to version: 2026092312000019722026/10/01 07:38:57 OK 1_commit_pending_closure.sql (1.75ms)19732026/10/01 07:38:57 OK 2_object_stats_trigger.sql (469.58µs)19742026/10/01 07:38:57 OK 3_commit_push.sql (216.21µs)19752026/10/01 07:38:57 goose: up to current file version: 319762026/10/01 07:38:57 OK 20241026095416_initial_model.sql (224.73ms)19772026/10/01 07:38:57 OK 20251210153512_drop_unused_gin_index.sql (15.72ms)19782026/10/01 07:38:57 OK 20251218171726_add_pins.sql (35.21ms)19792026/10/01 07:38:57 OK 20241026095416_initial_model.sql (226.12ms)19802026/10/01 07:38:57 OK 20251210153512_drop_unused_gin_index.sql (10.86ms)19812026/10/01 07:38:58 OK 20251218171726_add_pins.sql (105.71ms)19822026/10/01 07:38:58 OK 20260628120000_add_object_size_and_stats.sql (139.46ms)19832026-10-01 07:38:58.060 UTC [68889] ERROR: relation "goose_db_version" does not exist at character 3619842026-10-01 07:38:58.060 UTC [68889] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19852026/10/01 07:38:58 OK 20260628120000_add_object_size_and_stats.sql (51.77ms)19862026/10/01 07:38:58 OK 20260905000000_add_claims.sql (94.1ms)19872026/10/01 07:38:58 OK 20260905000000_add_claims.sql (89.06ms)19882026/10/01 07:38:58 OK 20260920000000_drop_claims.sql (62.96ms)19892026/10/01 07:38:58 OK 20260920000000_drop_claims.sql (26.94ms)19902026/10/01 07:38:58 OK 20260923120000_add_pushes.sql (11.28ms)19912026/10/01 07:38:58 goose: successfully migrated database to version: 2026092312000019922026/10/01 07:38:58 OK 1_commit_pending_closure.sql (1.76ms)19932026/10/01 07:38:58 OK 2_object_stats_trigger.sql (228.71µs)19942026/10/01 07:38:58 OK 3_commit_push.sql (172.33µs)19952026/10/01 07:38:58 goose: up to current file version: 319962026/10/01 07:38:58 OK 20260923120000_add_pushes.sql (34.83ms)19972026/10/01 07:38:58 goose: successfully migrated database to version: 2026092312000019982026/10/01 07:38:58 OK 1_commit_pending_closure.sql (1.68ms)19992026/10/01 07:38:58 OK 2_object_stats_trigger.sql (250.33µs)20002026/10/01 07:38:58 OK 3_commit_push.sql (180.5µs)20012026/10/01 07:38:58 goose: up to current file version: 320022026/10/01 07:38:58 OK 20241026095416_initial_model.sql (324.99ms)20032026/10/01 07:38:58 OK 20251210153512_drop_unused_gin_index.sql (10.12ms)20042026/10/01 07:38:58 OK 20251218171726_add_pins.sql (40.93ms)20052026/10/01 07:38:58 OK 20260628120000_add_object_size_and_stats.sql (58.56ms)20062026/10/01 07:38:58 OK 20260905000000_add_claims.sql (150.24ms)20072026/10/01 07:38:58 OK 20260920000000_drop_claims.sql (72.84ms)20082026/10/01 07:38:58 OK 20260923120000_add_pushes.sql (24.21ms)20092026/10/01 07:38:58 goose: successfully migrated database to version: 2026092312000020102026/10/01 07:38:58 OK 1_commit_pending_closure.sql (945.79µs)20112026/10/01 07:38:58 OK 2_object_stats_trigger.sql (238.08µs)20122026/10/01 07:38:58 OK 3_commit_push.sql (201.38µs)20132026/10/01 07:38:58 goose: up to current file version: 320142026/10/01 07:38:59 INFO Received uploads request method=POST path=/api/pending_closures20152026/10/01 07:38:59 INFO Received uploads request method=POST path=/api/pending_closures20162026/10/01 07:38:59 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)20172026/10/01 07:38:59 INFO Uploading ddfhz248ij5bdmpm0mr55f4rwl7rqa4h-shared-dep (136B)20182026/10/01 07:38:59 INFO Uploading src01jkih5h4vvayjnxi2viwd35xqgg1-a (248B)20192026/10/01 07:38:59 WARN Failed to register uploaded object key=4qfjib2x8k2fhh5880wk726cpca55lbd.ls error="server returned 404: 404 page not found\n"20202026/10/01 07:38:59 WARN Failed to register uploaded object key=ddfhz248ij5bdmpm0mr55f4rwl7rqa4h.ls error="server returned 404: 404 page not found\n"20212026/10/01 07:38:59 WARN Failed to register uploaded object key=src01jkih5h4vvayjnxi2viwd35xqgg1.ls error="server returned 404: 404 page not found\n"20222026/10/01 07:38:59 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20232026/10/01 07:38:59 WARN Failed to register uploaded object key=nar/1ghk27c29d217g52s1879wakij5y0s51f863jf291px4bnm4da1r.nar.zst error="server returned 404: 404 page not found\n"20242026/10/01 07:38:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign20252026/10/01 07:38:59 INFO Signed narinfos id=1 count=220262026/10/01 07:38:59 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign20272026/10/01 07:38:59 INFO Signed narinfos id=2 count=220282026/10/01 07:38:59 INFO Uploading 4 narinfos20292026/10/01 07:38:59 WARN Failed to register uploaded object key=ddfhz248ij5bdmpm0mr55f4rwl7rqa4h.narinfo error="server returned 404: 404 page not found\n"20302026/10/01 07:38:59 WARN Failed to register uploaded object key=src01jkih5h4vvayjnxi2viwd35xqgg1.narinfo error="server returned 404: 404 page not found\n"20312026/10/01 07:38:59 WARN Failed to register uploaded object key=4qfjib2x8k2fhh5880wk726cpca55lbd.narinfo error="server returned 404: 404 page not found\n"20322026/10/01 07:38:59 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20332026/10/01 07:38:59 WARN Failed to register uploaded object key=ddfhz248ij5bdmpm0mr55f4rwl7rqa4h.narinfo error="server returned 404: 404 page not found\n"20342026/10/01 07:38:59 INFO Completed upload id=220352026/10/01 07:38:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20362026/10/01 07:38:59 INFO Completed upload id=120372026/10/01 07:38:59 INFO Upload complete. (398ms)2038=== NAME TestClientFallsBackToClosures2039 client_pushes_test.go:112: Retrieved narinfo from S3:2040 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestClientFallsBackToClosures551780909/001/store/ddfhz248ij5bdmpm0mr55f4rwl7rqa4h-shared-dep2041 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2042 Compression: zstd2043 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822044 NarSize: 1362045 References: 2046 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2047 client_pushes_test.go:112: Retrieved narinfo from S3:2048 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestClientFallsBackToClosures551780909/001/store/src01jkih5h4vvayjnxi2viwd35xqgg1-a2049 URL: nar/1ghk27c29d217g52s1879wakij5y0s51f863jf291px4bnm4da1r.nar.zst2050 Compression: zstd2051 NarHash: sha256:1ghk27c29d217g52s1879wakij5y0s51f863jf291px4bnm4da1r2052 NarSize: 2482053 References: /nix/var/nix/builds/nix-66626-273570313/TestClientFallsBackToClosures551780909/001/store/ddfhz248ij5bdmpm0mr55f4rwl7rqa4h-shared-dep2054 CA: text:sha256:0yyzd0sbn66q2180bsp0390jrllrqjzxqpp3gbn0db7106ac9cma2055 client_pushes_test.go:112: Retrieved narinfo from S3:2056 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestClientFallsBackToClosures551780909/001/store/4qfjib2x8k2fhh5880wk726cpca55lbd-b2057 URL: nar/1ghk27c29d217g52s1879wakij5y0s51f863jf291px4bnm4da1r.nar.zst2058 Compression: zstd2059 NarHash: sha256:1ghk27c29d217g52s1879wakij5y0s51f863jf291px4bnm4da1r2060 NarSize: 2482061 References: /nix/var/nix/builds/nix-66626-273570313/TestClientFallsBackToClosures551780909/001/store/ddfhz248ij5bdmpm0mr55f4rwl7rqa4h-shared-dep2062 CA: text:sha256:0yyzd0sbn66q2180bsp0390jrllrqjzxqpp3gbn0db7106ac9cma20632026-10-01 07:38:59.638 UTC [68910] ERROR: relation "goose_db_version" does not exist at character 3620642026-10-01 07:38:59.638 UTC [68910] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2065--- PASS: TestClientFallsBackToClosures (7.81s)2066=== CONT TestCacheConfigHandler2067=== RUN TestCacheConfigHandler/full_config,_no_issuer2068=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2069=== RUN TestCacheConfigHandler/no_cache_url_configured2070=== PAUSE TestCacheConfigHandler/no_cache_url_configured2071=== RUN TestCacheConfigHandler/no_signing_keys2072=== PAUSE TestCacheConfigHandler/no_signing_keys2073=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2074=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2075=== CONT TestService_ReadAuthMiddleware20762026/10/01 07:38:59 INFO Received push request method=POST path=/api/pushes20772026/10/01 07:38:59 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)20782026/10/01 07:38:59 INFO Uploading 2nznf97kak251ihfm48b334rxdf51g2v-b (240B)20792026/10/01 07:38:59 INFO Uploading fx8cr1wal47ww008ksr4yqbyi91db0rl-shared-dep (136B)20802026/10/01 07:38:59 WARN Failed to register uploaded object key=xvnygnvs412lzpi5l3ny0wlfg2m9bziv.ls error="server returned 404: 404 page not found\n"20812026/10/01 07:38:59 WARN Failed to register uploaded object key=2nznf97kak251ihfm48b334rxdf51g2v.ls error="server returned 404: 404 page not found\n"20822026/10/01 07:38:59 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20832026/10/01 07:38:59 WARN Failed to register uploaded object key=nar/1pfargabqpdil3lg5lsqn11c8iy9hayssdk5jp32rskb6v05rr21.nar.zst error="server returned 404: 404 page not found\n"20842026/10/01 07:38:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20852026/10/01 07:38:59 WARN Failed to register uploaded object key=fx8cr1wal47ww008ksr4yqbyi91db0rl.ls error="server returned 404: 404 page not found\n"20862026/10/01 07:38:59 INFO Signed narinfos id=1 count=320872026/10/01 07:38:59 INFO Uploading 3 narinfos20882026/10/01 07:39:00 WARN Failed to register uploaded object key=xvnygnvs412lzpi5l3ny0wlfg2m9bziv.narinfo error="server returned 404: 404 page not found\n"20892026/10/01 07:39:00 WARN Failed to register uploaded object key=2nznf97kak251ihfm48b334rxdf51g2v.narinfo error="server returned 404: 404 page not found\n"20902026/10/01 07:39:00 INFO Received complete push request method=POST path=/api/pushes/1/complete20912026/10/01 07:39:00 WARN Failed to register uploaded object key=fx8cr1wal47ww008ksr4yqbyi91db0rl.narinfo error="server returned 404: 404 page not found\n"2092=== NAME TestPinProtectsFromGC2093 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-66626-273570313/TestPinProtectsFromGC1542284146/001/store/xw90kx0n0i05gqfqpgmykqbif55464ry-pinned-file.txt2094 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-66626-273570313/TestPinProtectsFromGC1542284146/001/store/w96zjya9cjiglgkqjk5b8sch1nyfbndh-unpinned-file.txt20952026/10/01 07:39:00 INFO Upload complete. (342ms)2096=== NAME TestClientPushesUseOnePush2097 client_pushes_test.go:97: Retrieved narinfo from S3:2098 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestClientPushesUseOnePush83803754/001/store/fx8cr1wal47ww008ksr4yqbyi91db0rl-shared-dep2099 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2100 Compression: zstd2101 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822102 NarSize: 1362103 References: 2104 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2105 client_pushes_test.go:97: Retrieved narinfo from S3:2106 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestClientPushesUseOnePush83803754/001/store/xvnygnvs412lzpi5l3ny0wlfg2m9bziv-a2107 URL: nar/1pfargabqpdil3lg5lsqn11c8iy9hayssdk5jp32rskb6v05rr21.nar.zst2108 Compression: zstd2109 NarHash: sha256:1pfargabqpdil3lg5lsqn11c8iy9hayssdk5jp32rskb6v05rr212110 NarSize: 2402111 References: /nix/var/nix/builds/nix-66626-273570313/TestClientPushesUseOnePush83803754/001/store/fx8cr1wal47ww008ksr4yqbyi91db0rl-shared-dep2112 CA: text:sha256:08syz06xmqksgrs9k268d9hifm7vzi6rbinhwvm1js9aj98lbkjj2113 client_pushes_test.go:97: Retrieved narinfo from S3:2114 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestClientPushesUseOnePush83803754/001/store/2nznf97kak251ihfm48b334rxdf51g2v-b2115 URL: nar/1pfargabqpdil3lg5lsqn11c8iy9hayssdk5jp32rskb6v05rr21.nar.zst2116 Compression: zstd2117 NarHash: sha256:1pfargabqpdil3lg5lsqn11c8iy9hayssdk5jp32rskb6v05rr212118 NarSize: 2402119 References: /nix/var/nix/builds/nix-66626-273570313/TestClientPushesUseOnePush83803754/001/store/fx8cr1wal47ww008ksr4yqbyi91db0rl-shared-dep2120 CA: text:sha256:08syz06xmqksgrs9k268d9hifm7vzi6rbinhwvm1js9aj98lbkjj21212026/10/01 07:39:00 INFO Received push request method=POST path=/api/pushes21222026/10/01 07:39:00 OK 20241026095416_initial_model.sql (422.84ms)2123--- PASS: TestClientPushesUseOnePush (7.76s)2124=== CONT TestService_RequireScope_OIDC21252026/10/01 07:39:00 OK 20251210153512_drop_unused_gin_index.sql (35.92ms)21262026/10/01 07:39:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21272026/10/01 07:39:00 INFO Uploading xw90kx0n0i05gqfqpgmykqbif55464ry-pinned-file.txt (128B)21282026/10/01 07:39:00 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"21292026/10/01 07:39:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21302026/10/01 07:39:00 WARN Failed to register uploaded object key=xw90kx0n0i05gqfqpgmykqbif55464ry.ls error="server returned 404: 404 page not found\n"21312026/10/01 07:39:00 INFO Signed narinfos id=1 count=121322026/10/01 07:39:00 INFO Uploading 1 narinfos21332026/10/01 07:39:00 OK 20251218171726_add_pins.sql (40.9ms)21342026/10/01 07:39:00 INFO Received complete push request method=POST path=/api/pushes/1/complete21352026/10/01 07:39:00 WARN Failed to register uploaded object key=xw90kx0n0i05gqfqpgmykqbif55464ry.narinfo error="server returned 404: 404 page not found\n"21362026/10/01 07:39:00 OK 20260628120000_add_object_size_and_stats.sql (69.7ms)21372026/10/01 07:39:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57730/oidc21382026/10/01 07:39:00 INFO Upload complete. (264ms)21392026-10-01 07:39:00.461 UTC [68933] ERROR: relation "goose_db_version" does not exist at character 3621402026-10-01 07:39:00.461 UTC [68933] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21412026/10/01 07:39:00 OK 20260905000000_add_claims.sql (121.16ms)21422026/10/01 07:39:00 INFO Received push request method=POST path=/api/pushes21432026/10/01 07:39:00 OK 20260920000000_drop_claims.sql (6.32ms)21442026-10-01 07:39:00.488 UTC [68944] ERROR: relation "goose_db_version" does not exist at character 3621452026-10-01 07:39:00.488 UTC [68944] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21462026/10/01 07:39:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21472026/10/01 07:39:00 INFO Uploading w96zjya9cjiglgkqjk5b8sch1nyfbndh-unpinned-file.txt (128B)21482026/10/01 07:39:00 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"21492026/10/01 07:39:00 WARN Failed to register uploaded object key=w96zjya9cjiglgkqjk5b8sch1nyfbndh.ls error="server returned 404: 404 page not found\n"21502026/10/01 07:39:00 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign21512026/10/01 07:39:00 INFO Signed narinfos id=2 count=121522026/10/01 07:39:00 INFO Uploading 1 narinfos21532026/10/01 07:39:00 OK 20260923120000_add_pushes.sql (49.62ms)21542026/10/01 07:39:00 goose: successfully migrated database to version: 2026092312000021552026/10/01 07:39:00 OK 1_commit_pending_closure.sql (1.01ms)21562026/10/01 07:39:00 OK 2_object_stats_trigger.sql (237.17µs)21572026/10/01 07:39:00 OK 3_commit_push.sql (196.5µs)21582026/10/01 07:39:00 goose: up to current file version: 321592026/10/01 07:39:00 INFO Received push request method=POST path=/api/pushes21602026/10/01 07:39:00 INFO Received complete push request method=POST path=/api/pushes/2/complete21612026/10/01 07:39:00 WARN Failed to register uploaded object key=w96zjya9cjiglgkqjk5b8sch1nyfbndh.narinfo error="server returned 404: 404 page not found\n"21622026/10/01 07:39:00 INFO Upload complete. (214ms)21632026/10/01 07:39:00 INFO Received create pin request method=POST path=/api/pins/myapp21642026/10/01 07:39:00 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)21652026/10/01 07:39:00 INFO Uploading 73s8pkjqf40b2pyrasgmgpkn8sws9sh3-top (256B)21662026/10/01 07:39:00 INFO Uploading v4d88h8w3imp2vxgjjxj448mzbfzjrq5-shared-dep (136B)21672026-10-01 07:39:00.675 UTC [68946] ERROR: relation "goose_db_version" does not exist at character 3621682026-10-01 07:39:00.675 UTC [68946] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21692026/10/01 07:39:00 WARN Failed to register uploaded object key=73s8pkjqf40b2pyrasgmgpkn8sws9sh3.ls error="server returned 404: 404 page not found\n"21702026/10/01 07:39:00 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"21712026/10/01 07:39:00 WARN Failed to register uploaded object key=nar/0bnlvxhynf2518kv5v3qjpfx1n03qjbal59027am5qvr3z7yw761.nar.zst error="server returned 404: 404 page not found\n"21722026/10/01 07:39:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21732026/10/01 07:39:00 WARN Failed to register uploaded object key=v4d88h8w3imp2vxgjjxj448mzbfzjrq5.ls error="server returned 404: 404 page not found\n"21742026/10/01 07:39:00 INFO Signed narinfos id=1 count=221752026/10/01 07:39:00 INFO Uploading 2 narinfos21762026/10/01 07:39:00 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-66626-273570313/TestPinProtectsFromGC1542284146/001/store/xw90kx0n0i05gqfqpgmykqbif55464ry-pinned-file.txt narinfo_key=xw90kx0n0i05gqfqpgmykqbif55464ry.narinfo21772026/10/01 07:39:00 INFO Starting cleanup of old closures method=DELETE path=/api/closures21782026/10/01 07:39:00 INFO Garbage collection started21792026/10/01 07:39:00 INFO Aborted multipart uploads count=021802026/10/01 07:39:00 WARN Force mode enabled - objects will be deleted immediately without grace period21812026/10/01 07:39:00 WARN Failed to register uploaded object key=73s8pkjqf40b2pyrasgmgpkn8sws9sh3.narinfo error="server returned 404: 404 page not found\n"21822026/10/01 07:39:00 INFO Received complete push request method=POST path=/api/pushes/1/complete21832026/10/01 07:39:00 WARN Failed to register uploaded object key=v4d88h8w3imp2vxgjjxj448mzbfzjrq5.narinfo error="server returned 404: 404 page not found\n"21842026/10/01 07:39:00 INFO Upload complete. (291ms)2185=== NAME TestClientSharedPathCommittedMidPush2186 client_integration_test.go:680: Retrieved narinfo from S3:2187 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestClientSharedPathCommittedMidPush2134355023/001/store/v4d88h8w3imp2vxgjjxj448mzbfzjrq5-shared-dep2188 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2189 Compression: zstd2190 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822191 NarSize: 1362192 References: 2193 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2194 client_integration_test.go:680: Retrieved narinfo from S3:2195 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestClientSharedPathCommittedMidPush2134355023/001/store/73s8pkjqf40b2pyrasgmgpkn8sws9sh3-top2196 URL: nar/0bnlvxhynf2518kv5v3qjpfx1n03qjbal59027am5qvr3z7yw761.nar.zst2197 Compression: zstd2198 NarHash: sha256:0bnlvxhynf2518kv5v3qjpfx1n03qjbal59027am5qvr3z7yw7612199 NarSize: 2562200 References: /nix/var/nix/builds/nix-66626-273570313/TestClientSharedPathCommittedMidPush2134355023/001/store/v4d88h8w3imp2vxgjjxj448mzbfzjrq5-shared-dep2201 CA: text:sha256:0fd9qk61rd9jyxm65fpxdnzmsv7x4vbvl1aw2nd8wsxnld3c6hqz22022026/10/01 07:39:00 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=022032026/10/01 07:39:00 OK 20241026095416_initial_model.sql (386.98ms)22042026/10/01 07:39:00 OK 20251210153512_drop_unused_gin_index.sql (16.37ms)22052026/10/01 07:39:00 INFO Vacuumed table table=pending_closures22062026/10/01 07:39:00 OK 20251218171726_add_pins.sql (62.71ms)2207--- PASS: TestClientSharedPathCommittedMidPush (7.20s)2208=== CONT TestService_AuthMiddleware_OIDC22092026/10/01 07:39:01 INFO Vacuumed table table=pending_objects22102026/10/01 07:39:01 INFO Vacuumed table table=multipart_uploads22112026/10/01 07:39:01 OK 20241026095416_initial_model.sql (406.02ms)22122026/10/01 07:39:01 OK 20260628120000_add_object_size_and_stats.sql (71.27ms)22132026/10/01 07:39:01 INFO Vacuumed table table=closures22142026/10/01 07:39:01 OK 20251210153512_drop_unused_gin_index.sql (27.19ms)22152026/10/01 07:39:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57755/oidc22162026/10/01 07:39:01 INFO Vacuumed table table=objects22172026/10/01 07:39:01 OK 20251218171726_add_pins.sql (67.59ms)22182026/10/01 07:39:01 OK 20260905000000_add_claims.sql (146.05ms)22192026/10/01 07:39:01 OK 20241026095416_initial_model.sql (425.98ms)22202026/10/01 07:39:01 OK 20260628120000_add_object_size_and_stats.sql (80.43ms)22212026/10/01 07:39:01 OK 20251210153512_drop_unused_gin_index.sql (8.1ms)22222026-10-01 07:39:01.235 UTC [68953] ERROR: relation "goose_db_version" does not exist at character 3622232026-10-01 07:39:01.235 UTC [68953] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22242026/10/01 07:39:01 OK 20260920000000_drop_claims.sql (56.13ms)22252026/10/01 07:39:01 OK 20251218171726_add_pins.sql (34.43ms)22262026/10/01 07:39:01 OK 20260923120000_add_pushes.sql (45.86ms)22272026/10/01 07:39:01 goose: successfully migrated database to version: 2026092312000022282026/10/01 07:39:01 OK 1_commit_pending_closure.sql (1.22ms)22292026/10/01 07:39:01 OK 2_object_stats_trigger.sql (204.5µs)22302026/10/01 07:39:01 OK 3_commit_push.sql (185.13µs)22312026/10/01 07:39:01 goose: up to current file version: 322322026/10/01 07:39:01 OK 20260628120000_add_object_size_and_stats.sql (65.72ms)22332026/10/01 07:39:01 OK 20260905000000_add_claims.sql (125.69ms)22342026/10/01 07:39:01 OK 20260920000000_drop_claims.sql (73.04ms)22352026/10/01 07:39:01 OK 20260905000000_add_claims.sql (113.29ms)22362026/10/01 07:39:01 OK 20260923120000_add_pushes.sql (32.81ms)22372026/10/01 07:39:01 goose: successfully migrated database to version: 2026092312000022382026/10/01 07:39:01 OK 1_commit_pending_closure.sql (1.33ms)22392026/10/01 07:39:01 OK 2_object_stats_trigger.sql (296.54µs)22402026/10/01 07:39:01 OK 3_commit_push.sql (236.25µs)22412026/10/01 07:39:01 goose: up to current file version: 322422026/10/01 07:39:01 OK 20260920000000_drop_claims.sql (93.84ms)22432026/10/01 07:39:01 OK 20260923120000_add_pushes.sql (40.74ms)22442026/10/01 07:39:01 goose: successfully migrated database to version: 2026092312000022452026/10/01 07:39:01 OK 1_commit_pending_closure.sql (2.51ms)22462026/10/01 07:39:01 OK 2_object_stats_trigger.sql (938.54µs)22472026/10/01 07:39:01 OK 3_commit_push.sql (2.07ms)22482026/10/01 07:39:01 goose: up to current file version: 322492026/10/01 07:39:01 OK 20241026095416_initial_model.sql (558.6ms)22502026/10/01 07:39:01 OK 20251210153512_drop_unused_gin_index.sql (25.81ms)22512026/10/01 07:39:01 OK 20251218171726_add_pins.sql (86.5ms)22522026/10/01 07:39:02 OK 20260628120000_add_object_size_and_stats.sql (69.14ms)2253=== NAME TestClientWithDependencies2254 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-66626-273570313/TestClientWithDependencies937173943/001/store/gh8pqqlsl45rpfjzkaq39nv2nfh2rgap-test-script22552026/10/01 07:39:02 OK 20260905000000_add_claims.sql (174.72ms)22562026/10/01 07:39:02 OK 20260920000000_drop_claims.sql (75ms)2257 client_integration_test.go:615: Found 1 dependencies (including self)22582026/10/01 07:39:02 OK 20260923120000_add_pushes.sql (27.12ms)22592026/10/01 07:39:02 goose: successfully migrated database to version: 2026092312000022602026/10/01 07:39:02 OK 1_commit_pending_closure.sql (971.75µs)22612026/10/01 07:39:02 OK 2_object_stats_trigger.sql (239µs)22622026/10/01 07:39:02 OK 3_commit_push.sql (201.58µs)22632026/10/01 07:39:02 goose: up to current file version: 322642026/10/01 07:39:02 INFO Received push request method=POST path=/api/pushes2265=== NAME TestClientIntegration2266 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-66626-273570313/TestClientIntegration1873237979/002/store/dsx47r4xbn4bcfb000bd31kk331cgyyf-test-file.txt2267--- PASS: TestService_ReadScope_PublicByDefault (6.49s)2268=== CONT TestService_AuthMiddleware_MTLSBoundSubjects22692026/10/01 07:39:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22702026/10/01 07:39:02 INFO Uploading gh8pqqlsl45rpfjzkaq39nv2nfh2rgap-test-script (136B)22712026/10/01 07:39:02 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"22722026/10/01 07:39:02 WARN Failed to register uploaded object key=gh8pqqlsl45rpfjzkaq39nv2nfh2rgap.ls error="server returned 404: 404 page not found\n"22732026/10/01 07:39:02 WARN Failed to register uploaded object key=log/90m2g0dk2sgi1swq5qlsia10iwls4wff-test-script.drv error="server returned 404: 404 page not found\n"22742026/10/01 07:39:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22752026/10/01 07:39:02 INFO Signed narinfos id=1 count=122762026/10/01 07:39:02 INFO Uploading 1 narinfos22772026/10/01 07:39:02 INFO Received push request method=POST path=/api/pushes22782026/10/01 07:39:02 INFO Received complete push request method=POST path=/api/pushes/1/complete22792026/10/01 07:39:02 WARN Failed to register uploaded object key=gh8pqqlsl45rpfjzkaq39nv2nfh2rgap.narinfo error="server returned 404: 404 page not found\n"22802026/10/01 07:39:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22812026/10/01 07:39:02 INFO Uploading dsx47r4xbn4bcfb000bd31kk331cgyyf-test-file.txt (152B)22822026/10/01 07:39:02 INFO Upload complete. (256ms)2283=== NAME TestClientWithDependencies2284 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-66626-273570313/TestClientWithDependencies937173943/001/store) requires matching store prefix22852026/10/01 07:39:02 WARN Failed to register uploaded object key=dsx47r4xbn4bcfb000bd31kk331cgyyf.ls error="server returned 404: 404 page not found\n"22862026/10/01 07:39:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22872026/10/01 07:39:02 INFO Signed narinfos id=1 count=122882026/10/01 07:39:02 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"22892026/10/01 07:39:02 INFO Uploading 1 narinfos22902026/10/01 07:39:02 INFO Received complete push request method=POST path=/api/pushes/1/complete22912026/10/01 07:39:02 WARN Failed to register uploaded object key=dsx47r4xbn4bcfb000bd31kk331cgyyf.narinfo error="server returned 404: 404 page not found\n"22922026/10/01 07:39:02 INFO Upload complete. (237ms)22932026/10/01 07:39:02 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02294=== NAME TestPinProtectsFromGC2295 client_integration_test.go:794: Pin successfully protected closure from garbage collection22962026/10/01 07:39:02 INFO All 1 paths already cached2297=== NAME TestClientIntegration2298 client_integration_test.go:312: Retrieved narinfo from S3:2299 StorePath: /nix/var/nix/builds/nix-66626-273570313/TestClientIntegration1873237979/002/store/dsx47r4xbn4bcfb000bd31kk331cgyyf-test-file.txt2300 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2301 Compression: zstd2302 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12303 NarSize: 1522304 References: 2305 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12306 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2307 client_integration_test.go:313: Decompressed .ls content (64 bytes):2308 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2309 client_integration_test.go:316: Testing garbage collection...23102026/10/01 07:39:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures23112026/10/01 07:39:02 INFO Garbage collection started23122026/10/01 07:39:02 INFO Aborted multipart uploads count=02313--- PASS: TestClientWithDependencies (7.75s)2314=== CONT TestService_AuthMiddleware_MTLSProxyHeader23152026/10/01 07:39:02 WARN Force mode enabled - objects will be deleted immediately without grace period2316--- PASS: TestPinProtectsFromGC (9.94s)2317=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info23182026/10/01 07:39:02 INFO Received uploads request method=POST path=/2319=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key23202026/10/01 07:39:02 INFO Received complete multipart upload request method=POST path=/2321=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key23222026/10/01 07:39:02 INFO Received request for more parts method=POST path=/2323=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal23242026/10/01 07:39:02 INFO Received uploads request method=POST path=/2325--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2326 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2327 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2328 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2329 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2330=== CONT TestProxyWriteTimeout/narinfo2331=== CONT TestProxyWriteTimeout/unknown_size2332=== CONT TestProxyWriteTimeout/10_GiB_nar2333=== CONT TestProxyWriteTimeout/1_GiB_nar2334--- PASS: TestProxyWriteTimeout (0.00s)2335 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2336 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2337 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2338 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2339=== CONT TestIsValidUploadKey/narinfo2340=== CONT TestIsValidUploadKey/realisation_plus_in_output2341=== CONT TestIsValidUploadKey/unknown_type2342=== CONT TestIsValidUploadKey/empty_key2343=== CONT TestIsValidUploadKey/absolute2344=== CONT TestIsValidUploadKey/traversal_nar2345=== CONT TestIsValidUploadKey/traversal2346=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2347=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2348=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2349=== CONT TestIsValidUploadKey/index.html2350=== CONT TestIsValidUploadKey/nix-cache-info2351=== CONT TestIsValidUploadKey/build_log_home-manager_file2352=== CONT TestIsValidUploadKey/realisation2353=== CONT TestIsValidUploadKey/build_log_equals2354=== CONT TestIsValidUploadKey/build_log_question_mark2355=== CONT TestIsValidUploadKey/build_log_plus_in_name2356=== CONT TestIsValidUploadKey/nar_plain2357=== CONT TestIsValidUploadKey/build_log2358=== CONT TestIsValidUploadKey/listing2359=== CONT TestIsValidUploadKey/nar_xz2360=== CONT TestIsValidUploadKey/nar_zst2361--- PASS: TestIsValidUploadKey (0.03s)2362 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2363 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2364 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2365 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2366 --- PASS: TestIsValidUploadKey/absolute (0.00s)2367 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2368 --- PASS: TestIsValidUploadKey/traversal (0.00s)2369 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2370 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2371 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2372 --- PASS: TestIsValidUploadKey/index.html (0.00s)2373 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2374 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2375 --- PASS: TestIsValidUploadKey/realisation (0.00s)2376 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2377 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2378 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2379 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2380 --- PASS: TestIsValidUploadKey/build_log (0.00s)2381 --- PASS: TestIsValidUploadKey/listing (0.00s)2382 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2383 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2384=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure23852026/10/01 07:39:02 INFO Received uploads request method=POST path=/23862026/10/01 07:39:02 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=023872026/10/01 07:39:02 INFO Vacuumed table table=pending_closures23882026/10/01 07:39:02 INFO Vacuumed table table=pending_objects23892026/10/01 07:39:02 INFO Vacuumed table table=multipart_uploads23902026/10/01 07:39:03 INFO Vacuumed table table=closures23912026/10/01 07:39:03 INFO Vacuumed table table=objects2392=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts23932026/10/01 07:39:03 INFO Received request for more parts method=POST path=/2394=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart23952026/10/01 07:39:03 INFO Received complete multipart upload request method=POST path=/2396--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)2397 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.30s)2398 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2399 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2400=== CONT TestPush_RejectsBadRequests/no_objects24012026/10/01 07:39:03 INFO Received push request method=POST path=/api/pushes2402=== CONT TestPush_RejectsBadRequests/root_not_in_objects24032026/10/01 07:39:03 INFO Received push request method=POST path=/api/pushes2404=== CONT TestPush_RejectsBadRequests/no_roots24052026/10/01 07:39:03 INFO Received push request method=POST path=/api/pushes2406=== CONT TestPush_RejectsBadRequests/bad_root24072026/10/01 07:39:03 INFO Received push request method=POST path=/api/pushes2408=== CONT TestIsValidCachePath/narinfo2409=== CONT TestIsValidCachePath/index.html2410=== CONT TestIsValidCachePath/short_hash2411=== CONT TestIsValidCachePath/wrong_extension2412--- PASS: TestPush_RejectsBadRequests (2.92s)2413 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2414 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2415 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2416 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2417=== CONT TestIsValidCachePath/leading_slash2418=== CONT TestIsValidCachePath/empty2419=== CONT TestIsValidCachePath/random_path2420=== CONT TestIsValidCachePath/invalid_char_u2421=== CONT TestIsValidCachePath/invalid_char_e2422=== CONT TestIsValidCachePath/traversal_in_middle2423=== CONT TestIsValidCachePath/traversal_parent2424=== CONT TestIsValidCachePath/nar_uncompressed2425=== CONT TestIsValidCachePath/nix-cache-info2426=== CONT TestIsValidCachePath/realisation2427=== CONT TestIsValidCachePath/log2428=== CONT TestIsValidCachePath/ls2429=== CONT TestIsValidCachePath/nar_xz2430=== CONT TestIsValidCachePath/nar_bz22431=== CONT TestIsValidCachePath/nar_zst2432=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2433=== CONT TestParseSingleRange/none2434=== CONT TestParseSingleRange/open-ended2435--- PASS: TestIsValidCachePath (0.00s)2436 --- PASS: TestIsValidCachePath/narinfo (0.00s)2437 --- PASS: TestIsValidCachePath/index.html (0.00s)2438 --- PASS: TestIsValidCachePath/short_hash (0.00s)2439 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2440 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2441 --- PASS: TestIsValidCachePath/empty (0.00s)2442 --- PASS: TestIsValidCachePath/random_path (0.00s)2443 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2444 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2445 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2446 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2447 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2448 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2449 --- PASS: TestIsValidCachePath/realisation (0.00s)2450 --- PASS: TestIsValidCachePath/log (0.00s)2451 --- PASS: TestIsValidCachePath/ls (0.00s)2452 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2453 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2454 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2455 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2456=== CONT TestParseSingleRange/start_far_past_EOF2457=== CONT TestParseSingleRange/start_past_EOF2458=== CONT TestParseSingleRange/single_byte2459=== CONT TestParseSingleRange/suffix_exceeds_size2460=== CONT TestParseSingleRange/suffix2461=== CONT TestParseSingleRange/end_clamped_to_size2462=== CONT TestParseSingleRange/malformed_both_empty2463=== CONT TestParseSingleRange/closed2464=== CONT TestParseSingleRange/malformed_end_before_start2465=== CONT TestParseSingleRange/multi-range_ignored2466=== CONT TestParseSingleRange/malformed_no_dash2467=== CONT TestParseSingleRange/unknown_unit2468=== CONT TestServerTLSConfig/no_client_CA2469=== CONT TestServerTLSConfig/not_a_PEM_file2470--- PASS: TestParseSingleRange (0.00s)2471 --- PASS: TestParseSingleRange/none (0.00s)2472 --- PASS: TestParseSingleRange/open-ended (0.00s)2473 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2474 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2475 --- PASS: TestParseSingleRange/single_byte (0.00s)2476 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2477 --- PASS: TestParseSingleRange/suffix (0.00s)2478 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2479 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2480 --- PASS: TestParseSingleRange/closed (0.00s)2481 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2482 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2483 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2484 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2485=== CONT TestServerTLSConfig/missing_CA_file2486--- PASS: TestServerTLSConfig (0.00s)2487 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2488 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.04s)2489 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2490=== CONT TestResolveDBConnectionString/flag_wins2491=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2492=== CONT TestResolveDBConnectionString/nothing_configured2493=== CONT TestResolveDBConnectionString/missing_file_is_an_error2494=== CONT TestResolveDBConnectionString/file_when_flag_empty2495=== CONT TestClientErrorHandling/InvalidStorePath2496--- PASS: TestResolveDBConnectionString (0.05s)2497 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2498 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2499 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2500 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2501 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2502--- PASS: TestCacheStatsHandler (6.00s)2503=== CONT TestClientErrorHandling/ServerNotAvailable2504=== NAME TestClientCADerivations2505 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-66626-273570313/TestClientCADerivations4208669693/001/store/70jcczki2djwbvp20fkima5zmqd46w5c-ca-test25062026/10/01 07:39:03 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/present2507 client_ca_test.go:139: Found 1 dependencies (including self)25082026-10-01 07:39:03.945 UTC [69019] ERROR: relation "goose_db_version" does not exist at character 3625092026-10-01 07:39:03.945 UTC [69019] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25102026/10/01 07:39:03 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=197.780681ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present25112026/10/01 07:39:04 INFO Received push request method=POST path=/api/pushes25122026/10/01 07:39:04 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=364.665878ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present25132026/10/01 07:39:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25142026/10/01 07:39:04 INFO Uploading 70jcczki2djwbvp20fkima5zmqd46w5c-ca-test (144B)25152026/10/01 07:39:04 WARN Failed to register uploaded object key=70jcczki2djwbvp20fkima5zmqd46w5c.ls error="server returned 404: 404 page not found\n"25162026/10/01 07:39:04 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"25172026/10/01 07:39:04 WARN Failed to register uploaded object key=log/1ah6f84pk048nhji45y4dmf2iric2cbw-ca-test.drv error="server returned 404: 404 page not found\n"25182026/10/01 07:39:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25192026/10/01 07:39:04 INFO Signed narinfos id=1 count=125202026/10/01 07:39:04 INFO Uploading 1 narinfos25212026/10/01 07:39:04 INFO Received complete push request method=POST path=/api/pushes/1/complete25222026/10/01 07:39:04 WARN Failed to register uploaded object key=70jcczki2djwbvp20fkima5zmqd46w5c.narinfo error="server returned 404: 404 page not found\n"25232026-10-01 07:39:04.415 UTC [69056] ERROR: relation "goose_db_version" does not exist at character 3625242026-10-01 07:39:04.415 UTC [69056] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25252026/10/01 07:39:04 OK 20241026095416_initial_model.sql (376.86ms)25262026/10/01 07:39:04 OK 20251210153512_drop_unused_gin_index.sql (15.2ms)25272026/10/01 07:39:04 INFO Upload complete. (504ms)2528 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-66626-273570313/TestClientCADerivations4208669693/001/store/70jcczki2djwbvp20fkima5zmqd46w5c-ca-test2529 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2530 Compression: zstd2531 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2532 NarSize: 1442533 References: 2534 Deriver: /nix/var/nix/builds/nix-66626-273570313/TestClientCADerivations4208669693/001/store/1ah6f84pk048nhji45y4dmf2iric2cbw-ca-test.drv2535 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2536 client_ca_test.go:185: Checking for realisation files in S3...2537 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2538 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache25392026/10/01 07:39:04 OK 20251218171726_add_pins.sql (75.29ms)25402026/10/01 07:39:04 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=815.208108ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present25412026/10/01 07:39:04 OK 20260628120000_add_object_size_and_stats.sql (219.37ms)25422026/10/01 07:39:04 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02543=== NAME TestClientIntegration2544 client_integration_test.go:323: Objects in database after GC:2545 client_integration_test.go:323: Successfully deleted all objects with GC --force2546=== NAME TestClientCADerivations2547 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket63?endpoint=http://localhost:57131®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-66626-273570313/TestClientCADerivations4208669693/001/store'2548 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 125492026/10/01 07:39:04 OK 20260905000000_add_claims.sql (138.66ms)2550=== NAME TestOrphanedObjectsGCStressTest2551 orphaned_objects_gc_test.go:509: Stress test completed successfully:2552 orphaned_objects_gc_test.go:510: - Active objects preserved: 202553 orphaned_objects_gc_test.go:511: - Objects deleted: 2102554 orphaned_objects_gc_test.go:512: - Total GC'd: 2102555--- PASS: TestOrphanedObjectsGCStressTest (23.87s)2556=== CONT TestClientErrorHandling/InvalidAuthToken2557--- PASS: TestClientIntegration (8.95s)2558=== CONT TestCacheConfigHandler/full_config,_no_issuer2559=== CONT TestCacheConfigHandler/no_signing_keys2560=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2561=== CONT TestCacheConfigHandler/no_cache_url_configured2562--- PASS: TestCacheConfigHandler (0.00s)2563 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2564 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2565 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2566 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)25672026/10/01 07:39:05 OK 20260920000000_drop_claims.sql (121.82ms)2568--- PASS: TestClientCADerivations (8.32s)25692026/10/01 07:39:05 OK 20241026095416_initial_model.sql (437.34ms)25702026/10/01 07:39:05 OK 20260923120000_add_pushes.sql (5.32ms)25712026/10/01 07:39:05 goose: successfully migrated database to version: 2026092312000025722026/10/01 07:39:05 OK 1_commit_pending_closure.sql (1.83ms)25732026/10/01 07:39:05 OK 2_object_stats_trigger.sql (313.25µs)25742026/10/01 07:39:05 OK 3_commit_push.sql (227.67µs)25752026/10/01 07:39:05 goose: up to current file version: 325762026/10/01 07:39:05 OK 20251210153512_drop_unused_gin_index.sql (15.59ms)25772026/10/01 07:39:05 OK 20251218171726_add_pins.sql (62.91ms)25782026/10/01 07:39:05 OK 20260628120000_add_object_size_and_stats.sql (44.24ms)25792026/10/01 07:39:05 OK 20260905000000_add_claims.sql (99.4ms)25802026/10/01 07:39:05 OK 20260920000000_drop_claims.sql (82.95ms)25812026/10/01 07:39:05 OK 20260923120000_add_pushes.sql (28.86ms)25822026/10/01 07:39:05 goose: successfully migrated database to version: 2026092312000025832026/10/01 07:39:05 OK 1_commit_pending_closure.sql (1.04ms)25842026/10/01 07:39:05 OK 2_object_stats_trigger.sql (232.71µs)25852026/10/01 07:39:05 OK 3_commit_push.sql (195.21µs)25862026/10/01 07:39:05 goose: up to current file version: 325872026-10-01 07:39:05.356 UTC [69108] ERROR: relation "goose_db_version" does not exist at character 3625882026-10-01 07:39:05.356 UTC [69108] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25892026/10/01 07:39:05 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.67024228s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2590--- PASS: TestService_ReadAuthMiddleware (5.73s)25912026/10/01 07:39:05 OK 20241026095416_initial_model.sql (396.42ms)25922026/10/01 07:39:05 OK 20251210153512_drop_unused_gin_index.sql (14.32ms)25932026/10/01 07:39:05 OK 20251218171726_add_pins.sql (54.91ms)2594=== RUN TestService_RequireScope_OIDC/builder_may_write2595=== PAUSE TestService_RequireScope_OIDC/builder_may_write2596=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2597=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2598=== RUN TestService_RequireScope_OIDC/ops_may_admin2599=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2600=== RUN TestService_RequireScope_OIDC/ops_may_not_write2601=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2602=== RUN TestService_RequireScope_OIDC/reader_may_not_write2603=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2604=== RUN TestService_RequireScope_OIDC/static_token_may_admin2605=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2606=== RUN TestService_RequireScope_OIDC/static_token_may_write2607=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2608=== RUN TestService_RequireScope_OIDC/reader_may_read2609=== PAUSE TestService_RequireScope_OIDC/reader_may_read2610=== RUN TestService_RequireScope_OIDC/writer_implies_read2611=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2612=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2613=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2614=== CONT TestService_RequireScope_OIDC/builder_may_write2615=== CONT TestService_RequireScope_OIDC/static_token_may_admin2616=== CONT TestService_RequireScope_OIDC/writer_implies_read2617=== CONT TestService_RequireScope_OIDC/reader_may_read2618=== CONT TestService_RequireScope_OIDC/static_token_may_write2619=== CONT TestService_RequireScope_OIDC/ops_may_not_write2620=== CONT TestService_RequireScope_OIDC/reader_may_not_write2621=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2622=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2623=== CONT TestService_RequireScope_OIDC/ops_may_admin2624--- PASS: TestService_RequireScope_OIDC (5.71s)2625 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2626 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2627 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2628 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2629 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2630 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2631 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2632 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2633 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2634 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)26352026/10/01 07:39:05 OK 20260628120000_add_object_size_and_stats.sql (61.99ms)26362026/10/01 07:39:06 OK 20260905000000_add_claims.sql (74.93ms)26372026/10/01 07:39:06 OK 20260920000000_drop_claims.sql (13.72ms)26382026/10/01 07:39:06 OK 20260923120000_add_pushes.sql (4.74ms)26392026/10/01 07:39:06 goose: successfully migrated database to version: 2026092312000026402026/10/01 07:39:06 OK 1_commit_pending_closure.sql (4.56ms)26412026/10/01 07:39:06 OK 2_object_stats_trigger.sql (1.55ms)26422026/10/01 07:39:06 OK 3_commit_push.sql (1.26ms)26432026/10/01 07:39:06 goose: up to current file version: 326442026-10-01 07:39:06.190 UTC [69127] ERROR: relation "goose_db_version" does not exist at character 3626452026-10-01 07:39:06.190 UTC [69127] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26462026-10-01 07:39:06.488 UTC [69128] ERROR: relation "goose_db_version" does not exist at character 3626472026-10-01 07:39:06.488 UTC [69128] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26482026/10/01 07:39:06 OK 20241026095416_initial_model.sql (247.1ms)26492026/10/01 07:39:06 OK 20251210153512_drop_unused_gin_index.sql (22.4ms)2650=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2651=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2652=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2653=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2654=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2655=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2656=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2657=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2658=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2659=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected26602026/10/01 07:39:06 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]2661=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2662=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected26632026/10/01 07:39:06 WARN Authentication failed token_preview=eyJhbGciOi...S1r6pLF2eQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2664--- PASS: TestService_AuthMiddleware_OIDC (5.57s)2665 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2666 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2667 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2668 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)26692026/10/01 07:39:06 OK 20251218171726_add_pins.sql (68.31ms)26702026/10/01 07:39:06 OK 20260628120000_add_object_size_and_stats.sql (38.56ms)26712026/10/01 07:39:06 OK 20260905000000_add_claims.sql (81.45ms)26722026/10/01 07:39:06 OK 20260920000000_drop_claims.sql (24.93ms)26732026/10/01 07:39:06 OK 20260923120000_add_pushes.sql (32.92ms)26742026/10/01 07:39:06 goose: successfully migrated database to version: 2026092312000026752026/10/01 07:39:06 OK 20241026095416_initial_model.sql (179.5ms)26762026/10/01 07:39:06 OK 1_commit_pending_closure.sql (4.5ms)26772026/10/01 07:39:06 OK 2_object_stats_trigger.sql (4.92ms)26782026/10/01 07:39:06 OK 3_commit_push.sql (3.65ms)26792026/10/01 07:39:06 goose: up to current file version: 326802026/10/01 07:39:06 OK 20251210153512_drop_unused_gin_index.sql (14.73ms)26812026/10/01 07:39:06 OK 20251218171726_add_pins.sql (10.77ms)26822026-10-01 07:39:06.841 UTC [69132] ERROR: relation "goose_db_version" does not exist at character 3626832026-10-01 07:39:06.841 UTC [69132] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26842026/10/01 07:39:06 OK 20260628120000_add_object_size_and_stats.sql (48.22ms)26852026/10/01 07:39:06 OK 20260905000000_add_claims.sql (91.86ms)26862026/10/01 07:39:07 OK 20260920000000_drop_claims.sql (45.12ms)26872026/10/01 07:39:07 OK 20260923120000_add_pushes.sql (7.9ms)26882026/10/01 07:39:07 goose: successfully migrated database to version: 2026092312000026892026/10/01 07:39:07 OK 1_commit_pending_closure.sql (2.68ms)26902026/10/01 07:39:07 OK 2_object_stats_trigger.sql (570µs)26912026/10/01 07:39:07 OK 3_commit_push.sql (433.79µs)26922026/10/01 07:39:07 goose: up to current file version: 326932026/10/01 07:39:07 OK 20241026095416_initial_model.sql (169.11ms)26942026/10/01 07:39:07 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-config26952026/10/01 07:39:07 OK 20251210153512_drop_unused_gin_index.sql (7.35ms)26962026/10/01 07:39:07 OK 20251218171726_add_pins.sql (32.17ms)26972026/10/01 07:39:07 OK 20260628120000_add_object_size_and_stats.sql (54.61ms)26982026/10/01 07:39:07 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=214.327317ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config26992026/10/01 07:39:07 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"27002026/10/01 07:39:07 WARN mTLS auth: bound subjects configured but subject DN unavailable27012026/10/01 07:39:07 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2702--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (4.79s)27032026/10/01 07:39:07 OK 20260905000000_add_claims.sql (117.31ms)27042026/10/01 07:39:07 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=380.848892ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27052026/10/01 07:39:07 OK 20260920000000_drop_claims.sql (118.76ms)27062026/10/01 07:39:07 OK 20260923120000_add_pushes.sql (23.62ms)27072026/10/01 07:39:07 goose: successfully migrated database to version: 2026092312000027082026/10/01 07:39:07 OK 1_commit_pending_closure.sql (4.84ms)27092026/10/01 07:39:07 OK 2_object_stats_trigger.sql (1.02ms)27102026/10/01 07:39:07 OK 3_commit_push.sql (1.26ms)27112026/10/01 07:39:07 goose: up to current file version: 32712--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (4.97s)27132026/10/01 07:39:07 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=747.720554ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27142026-10-01 07:39:08.507 UTC [69148] ERROR: relation "goose_db_version" does not exist at character 3627152026-10-01 07:39:08.507 UTC [69148] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27162026/10/01 07:39:08 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.660759081s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27172026/10/01 07:39:08 OK 20241026095416_initial_model.sql (24.99ms)27182026/10/01 07:39:08 OK 20251210153512_drop_unused_gin_index.sql (1.14ms)27192026/10/01 07:39:08 OK 20251218171726_add_pins.sql (2.01ms)27202026/10/01 07:39:08 OK 20260628120000_add_object_size_and_stats.sql (4.3ms)27212026/10/01 07:39:08 OK 20260905000000_add_claims.sql (35.22ms)27222026/10/01 07:39:08 OK 20260920000000_drop_claims.sql (23.62ms)27232026/10/01 07:39:08 OK 20260923120000_add_pushes.sql (2.25ms)27242026/10/01 07:39:08 goose: successfully migrated database to version: 2026092312000027252026/10/01 07:39:08 OK 1_commit_pending_closure.sql (2.71ms)27262026/10/01 07:39:08 OK 2_object_stats_trigger.sql (243µs)27272026/10/01 07:39:08 OK 3_commit_push.sql (172.96µs)27282026/10/01 07:39:08 goose: up to current file version: 327292026/10/01 07:39:09 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"27302026/10/01 07:39:09 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"27312026/10/01 07:39:10 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"27322026/10/01 07:39:10 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-config27332026/10/01 07:39:10 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=184.455757ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27342026/10/01 07:39:10 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=431.551429ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27352026/10/01 07:39:10 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=750.70957ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27362026/10/01 07:39:11 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.715109775s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27372026/10/01 07:39:13 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_closures27382026/10/01 07:39:13 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=192.971634ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27392026/10/01 07:39:13 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=397.467502ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27402026/10/01 07:39:14 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=805.769536ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27412026/10/01 07:39:14 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.696643448s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2742--- PASS: TestClientErrorHandling (0.00s)2743 --- PASS: TestClientErrorHandling/InvalidStorePath (5.17s)2744 --- PASS: TestClientErrorHandling/InvalidAuthToken (4.65s)2745 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.40s)2746PASS2747{"timestamp":"2026-10-01T07:39:16.858052Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57275","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)"}27482026-10-01 07:39:25.399 UTC [67439] LOG: received smart shutdown request27492026-10-01 07:39:25.407 UTC [67439] LOG: background worker "logical replication launcher" (PID 67456) exited with exit code 127502026-10-01 07:39:25.726 UTC [67446] LOG: shutting down27512026-10-01 07:39:25.731 UTC [67446] LOG: checkpoint starting: shutdown immediate27522026/10/01 07:39:26 ERROR failed to kill rustfs error="no such process"27532026-10-01 07:39:33.261 UTC [67446] LOG: checkpoint complete: wrote 11877 buffers (72.5%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 20 recycled; write=4.721 s, sync=2.488 s, total=7.535 s; sync files=23917, longest=0.016 s, average=0.001 s; distance=330987 kB, estimate=330987 kB; lsn=0/15AC7F08, redo lsn=0/15AC7F0827542026-10-01 07:39:33.331 UTC [67439] LOG: database system is shut down27552026/10/01 07:39:35 ERROR failed to kill rustfs error="no such process"2756Running OIDC tests...2757=== RUN TestAudienceForIssuer2758=== PAUSE TestAudienceForIssuer2759=== RUN TestGlobMatch2760=== PAUSE TestGlobMatch2761=== RUN TestValidateToken_ValidToken2762=== PAUSE TestValidateToken_ValidToken2763=== RUN TestValidateToken_WrongAudience2764=== PAUSE TestValidateToken_WrongAudience2765=== RUN TestValidateToken_Expired2766=== PAUSE TestValidateToken_Expired2767=== RUN TestValidateToken_BoundClaimsMismatch2768=== PAUSE TestValidateToken_BoundClaimsMismatch2769=== RUN TestValidateToken_BoundSubjectMismatch2770=== PAUSE TestValidateToken_BoundSubjectMismatch2771=== RUN TestValidateToken_MultipleProviders2772=== PAUSE TestValidateToken_MultipleProviders2773=== RUN TestValidateToken_NoMatchingProvider2774=== PAUSE TestValidateToken_NoMatchingProvider2775=== RUN TestValidateToken_KubernetesServiceAccount2776=== PAUSE TestValidateToken_KubernetesServiceAccount2777=== RUN TestNewValidator_KubernetesRequiresCA2778=== PAUSE TestNewValidator_KubernetesRequiresCA2779=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2780=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2781=== RUN TestPins_ReservedForMatchingRule2782=== PAUSE TestPins_ReservedForMatchingRule2783=== RUN TestPins_TopLevelShorthand2784=== PAUSE TestPins_TopLevelShorthand2785=== RUN TestPins_ConfigValidation2786=== PAUSE TestPins_ConfigValidation2787=== RUN TestScopes_LegacyProviderDefaultsToWrite2788=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2789=== RUN TestScopes_Rules2790=== PAUSE TestScopes_Rules2791=== RUN TestScopes_ConfigValidation2792=== PAUSE TestScopes_ConfigValidation2793=== CONT TestAudienceForIssuer2794--- PASS: TestAudienceForIssuer (0.00s)2795=== CONT TestScopes_ConfigValidation2796=== CONT TestPins_TopLevelShorthand2797=== CONT TestNewValidator_KubernetesRequiresCA2798=== CONT TestValidateToken_BoundClaimsMismatch2799=== CONT TestValidateToken_WrongAudience2800=== CONT TestValidateToken_Expired2801=== CONT TestGlobMatch2802=== RUN TestGlobMatch/foo_foo2803=== PAUSE TestGlobMatch/foo_foo2804=== RUN TestGlobMatch/foo_bar2805=== PAUSE TestGlobMatch/foo_bar2806=== RUN TestGlobMatch/*_2807=== PAUSE TestGlobMatch/*_2808=== RUN TestGlobMatch/*_anything2809=== PAUSE TestGlobMatch/*_anything2810=== RUN TestGlobMatch/foo*_foo2811=== PAUSE TestGlobMatch/foo*_foo2812=== RUN TestGlobMatch/foo*_foobar2813=== PAUSE TestGlobMatch/foo*_foobar2814=== RUN TestGlobMatch/foo*_bar2815=== PAUSE TestGlobMatch/foo*_bar2816=== RUN TestGlobMatch/*bar_bar2817=== PAUSE TestGlobMatch/*bar_bar2818=== RUN TestGlobMatch/*bar_foobar2819=== PAUSE TestGlobMatch/*bar_foobar2820=== RUN TestGlobMatch/*bar_foo2821=== PAUSE TestGlobMatch/*bar_foo2822=== RUN TestGlobMatch/foo*bar_foobar2823=== PAUSE TestGlobMatch/foo*bar_foobar2824=== RUN TestGlobMatch/foo*bar_foo123bar2825=== CONT TestValidateToken_KubernetesServiceAccount2826=== PAUSE TestGlobMatch/foo*bar_foo123bar2827=== RUN TestGlobMatch/foo*bar_foobarbaz2828=== PAUSE TestGlobMatch/foo*bar_foobarbaz2829=== RUN TestGlobMatch/*/*_foo/bar2830=== PAUSE TestGlobMatch/*/*_foo/bar2831=== RUN TestGlobMatch/*/*_foo2832=== PAUSE TestGlobMatch/*/*_foo2833=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2834=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2835=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02836=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02837=== RUN TestGlobMatch/refs/*/main_refs/heads/main2838=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2839=== RUN TestGlobMatch/fo?_foo2840=== PAUSE TestGlobMatch/fo?_foo2841=== RUN TestGlobMatch/fo?_fo2842=== PAUSE TestGlobMatch/fo?_fo2843=== RUN TestGlobMatch/fo?_fooo2844=== PAUSE TestGlobMatch/fo?_fooo2845=== RUN TestGlobMatch/?oo_foo2846=== PAUSE TestGlobMatch/?oo_foo2847=== RUN TestGlobMatch/?oo_boo2848=== PAUSE TestGlobMatch/?oo_boo2849=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2850=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2851=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2852=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2853=== CONT TestValidateToken_ValidToken2854=== CONT TestPins_ReservedForMatchingRule2855=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2856--- PASS: TestScopes_ConfigValidation (0.01s)2857=== CONT TestValidateToken_MultipleProviders28582026/10/01 07:39:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58513/oidc2859--- PASS: TestValidateToken_Expired (0.03s)2860=== CONT TestValidateToken_NoMatchingProvider28612026/10/01 07:39:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58516/oidc28622026/10/01 07:39:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58518/oidc2863--- PASS: TestPins_TopLevelShorthand (0.04s)2864=== CONT TestScopes_LegacyProviderDefaultsToWrite2865--- PASS: TestPins_ReservedForMatchingRule (0.04s)2866=== CONT TestScopes_Rules28672026/10/01 07:39:44 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5852028682026/10/01 07:39:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58522/oidc2869--- PASS: TestValidateToken_WrongAudience (0.06s)2870=== CONT TestPins_ConfigValidation2871--- PASS: TestPins_ConfigValidation (0.00s)2872=== CONT TestValidateToken_BoundSubjectMismatch2873--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)2874=== CONT TestGlobMatch/foo_foo2875=== CONT TestGlobMatch/*/*_foo/bar2876=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2877=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2878=== CONT TestGlobMatch/?oo_boo2879=== CONT TestGlobMatch/?oo_foo2880=== CONT TestGlobMatch/fo?_fooo2881=== CONT TestGlobMatch/fo?_fo2882=== CONT TestGlobMatch/fo?_foo2883=== CONT TestGlobMatch/refs/*/main_refs/heads/main2884=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02885=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2886=== CONT TestGlobMatch/*/*_foo2887=== CONT TestGlobMatch/*bar_bar2888=== CONT TestGlobMatch/foo*bar_foobarbaz2889=== CONT TestGlobMatch/foo*bar_foo123bar2890=== CONT TestGlobMatch/foo*bar_foobar2891=== CONT TestGlobMatch/*bar_foo2892=== CONT TestGlobMatch/*bar_foobar2893=== CONT TestGlobMatch/foo*_foo2894=== CONT TestGlobMatch/foo*_bar2895=== CONT TestGlobMatch/foo*_foobar2896=== CONT TestGlobMatch/*_2897=== CONT TestGlobMatch/*_anything2898=== CONT TestGlobMatch/foo_bar2899--- PASS: TestGlobMatch (0.00s)2900 --- PASS: TestGlobMatch/foo_foo (0.00s)2901 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2902 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2903 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2904 --- PASS: TestGlobMatch/?oo_boo (0.00s)2905 --- PASS: TestGlobMatch/?oo_foo (0.00s)2906 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2907 --- PASS: TestGlobMatch/fo?_fo (0.00s)2908 --- PASS: TestGlobMatch/fo?_foo (0.00s)2909 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2910 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2911 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2912 --- PASS: TestGlobMatch/*/*_foo (0.00s)2913 --- PASS: TestGlobMatch/*bar_bar (0.00s)2914 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2915 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2916 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2917 --- PASS: TestGlobMatch/*bar_foo (0.00s)2918 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2919 --- PASS: TestGlobMatch/foo*_foo (0.00s)2920 --- PASS: TestGlobMatch/foo*_bar (0.00s)2921 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2922 --- PASS: TestGlobMatch/*_ (0.00s)2923 --- PASS: TestGlobMatch/*_anything (0.00s)2924 --- PASS: TestGlobMatch/foo_bar (0.00s)29252026/10/01 07:39:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:58515/oidc29262026/10/01 07:39:44 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:58524/oidc29272026/10/01 07:39:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58526/oidc2928--- PASS: TestValidateToken_ValidToken (0.07s)2929--- PASS: TestValidateToken_MultipleProviders (0.07s)29302026/10/01 07:39:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58529/oidc29312026/10/01 07:39:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58531/oidc2932--- PASS: TestValidateToken_BoundClaimsMismatch (0.08s)2933--- PASS: TestValidateToken_BoundSubjectMismatch (0.03s)29342026/10/01 07:39:44 http: TLS handshake error from 127.0.0.1:58534: read tcp 127.0.0.1:58533->127.0.0.1:58534: use of closed network connection2935--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)29362026/10/01 07:39:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58535/oidc2937--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)29382026/10/01 07:39:44 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232939--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.11s)29402026/10/01 07:39:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:58539/oidc2941--- PASS: TestValidateToken_NoMatchingProvider (0.10s)29422026/10/01 07:39:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58542/oidc2943--- PASS: TestScopes_Rules (0.14s)2944PASS2945Running hook tests...2946=== RUN TestSendPathsEmpty2947=== PAUSE TestSendPathsEmpty2948=== RUN TestQueueEnqueueAndFetch2949=== PAUSE TestQueueEnqueueAndFetch2950=== RUN TestQueueDeduplication2951=== PAUSE TestQueueDeduplication2952=== RUN TestQueueRemove2953=== PAUSE TestQueueRemove2954=== RUN TestQueueFetchBatchLimit2955=== PAUSE TestQueueFetchBatchLimit2956=== RUN TestQueueRetryMovesToBack2957=== PAUSE TestQueueRetryMovesToBack2958=== RUN TestQueueFetchRemoveLifecycle2959=== PAUSE TestQueueFetchRemoveLifecycle2960=== RUN TestQueueConcurrentWriters2961=== PAUSE TestQueueConcurrentWriters2962=== RUN TestQueueRemoveLargeClosure2963=== PAUSE TestQueueRemoveLargeClosure2964=== RUN TestServerClientIntegration2965=== PAUSE TestServerClientIntegration2966=== RUN TestServerQueueError2967=== PAUSE TestServerQueueError2968=== RUN TestGetListenerSocketActivation2969 server_test.go:210: === RUN TestGetListenerSocketActivation2970 --- PASS: TestGetListenerSocketActivation (0.00s)2971 PASS2972 2973--- PASS: TestGetListenerSocketActivation (0.01s)2974=== RUN TestDrainIsolatesPoisonPath2975=== PAUSE TestDrainIsolatesPoisonPath2976=== RUN TestRunNotBlockedByPoisonHead2977=== PAUSE TestRunNotBlockedByPoisonHead2978=== RUN TestDrainGivesUpWhenServerDown2979=== PAUSE TestDrainGivesUpWhenServerDown2980=== RUN TestFailedPathPrunedByLaterClosure2981=== PAUSE TestFailedPathPrunedByLaterClosure2982=== RUN TestWorkerUploadsAndRemoves2983=== PAUSE TestWorkerUploadsAndRemoves2984=== RUN TestWorkerSkipsGCdPaths2985=== PAUSE TestWorkerSkipsGCdPaths2986=== RUN TestWorkerPrunesClosureDeps2987=== PAUSE TestWorkerPrunesClosureDeps2988=== RUN TestDrainTimeout2989=== PAUSE TestDrainTimeout2990=== CONT TestSendPathsEmpty2991=== CONT TestServerQueueError2992--- PASS: TestSendPathsEmpty (0.00s)2993=== CONT TestServerClientIntegration2994=== CONT TestQueueRemoveLargeClosure2995=== CONT TestQueueFetchBatchLimit2996=== CONT TestWorkerUploadsAndRemoves2997=== CONT TestDrainGivesUpWhenServerDown2998=== CONT TestRunNotBlockedByPoisonHead2999=== CONT TestFailedPathPrunedByLaterClosure3000=== CONT TestDrainIsolatesPoisonPath3001=== CONT TestWorkerPrunesClosureDeps30022026/10/01 07:39:44 ERROR Failed to queue paths error="permission denied" count=13003--- PASS: TestServerQueueError (0.00s)3004=== CONT TestDrainTimeout3005--- PASS: TestServerClientIntegration (0.00s)3006=== CONT TestQueueFetchRemoveLifecycle30072026/10/01 07:39:44 INFO Upload queue status pending=330082026/10/01 07:39:44 INFO Uploading batch count=130092026/10/01 07:39:44 ERROR Upload failed error="upload failed" count=130102026/10/01 07:39:44 INFO Uploading batch count=230112026/10/01 07:39:44 INFO Uploading batch count=130122026/10/01 07:39:44 ERROR Upload failed error="upload failed" count=130132026/10/01 07:39:44 INFO Upload queue status pending=230142026/10/01 07:39:44 INFO Uploading batch count=130152026/10/01 07:39:44 INFO Upload queue status pending=230162026/10/01 07:39:44 INFO Uploading batch count=230172026/10/01 07:39:44 INFO Uploading batch count=430182026/10/01 07:39:44 ERROR Upload failed error="upload failed" count=430192026/10/01 07:39:44 INFO Uploading batch count=13020--- PASS: TestQueueFetchBatchLimit (0.01s)30212026/10/01 07:39:44 INFO Uploading batch count=23022=== CONT TestQueueConcurrentWriters30232026/10/01 07:39:44 ERROR Upload failed error="upload failed" count=230242026/10/01 07:39:44 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-66626-273570313/TestDrainGivesUpWhenServerDown959344054/002/a3025--- PASS: TestQueueFetchRemoveLifecycle (0.01s)3026=== CONT TestQueueRetryMovesToBack30272026/10/01 07:39:44 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-66626-273570313/TestDrainIsolatesPoisonPath1346310206/002/bbb30282026/10/01 07:39:44 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-66626-273570313/TestDrainGivesUpWhenServerDown959344054/002/b30292026/10/01 07:39:44 INFO Uploading batch count=130302026/10/01 07:39:44 INFO Uploading batch count=230312026/10/01 07:39:44 ERROR Upload failed error="upload failed" count=230322026/10/01 07:39:44 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-66626-273570313/TestDrainGivesUpWhenServerDown959344054/002/c30332026/10/01 07:39:44 INFO Uploading batch count=130342026/10/01 07:39:44 ERROR Upload failed error="upload failed" count=130352026/10/01 07:39:44 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-66626-273570313/TestDrainGivesUpWhenServerDown959344054/002/d30362026/10/01 07:39:44 INFO Uploading batch count=130372026/10/01 07:39:44 ERROR Upload failed error="upload failed" count=130382026/10/01 07:39:44 INFO Uploading batch count=230392026/10/01 07:39:44 ERROR Upload failed error="upload failed" count=230402026/10/01 07:39:44 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-66626-273570313/TestDrainGivesUpWhenServerDown959344054/002/e30412026/10/01 07:39:44 INFO Uploading batch count=130422026/10/01 07:39:44 ERROR Upload failed error="upload failed" count=130432026/10/01 07:39:44 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-66626-273570313/TestDrainGivesUpWhenServerDown959344054/002/f30442026/10/01 07:39:44 ERROR Drain finished with paths left in queue remaining=130452026/10/01 07:39:44 ERROR Drain finished with paths left in queue remaining=103046--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)3047=== CONT TestQueueDeduplication3048--- PASS: TestQueueRetryMovesToBack (0.00s)3049=== CONT TestQueueRemove3050--- PASS: TestDrainGivesUpWhenServerDown (0.01s)3051=== CONT TestWorkerSkipsGCdPaths3052--- PASS: TestDrainIsolatesPoisonPath (0.01s)3053=== CONT TestQueueEnqueueAndFetch3054--- PASS: TestQueueDeduplication (0.00s)30552026/10/01 07:39:44 INFO Upload queue status pending=23056--- PASS: TestQueueRemove (0.00s)30572026/10/01 07:39:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-66626-273570313/TestWorkerSkipsGCdPaths3528246018/002/nonexistent30582026/10/01 07:39:44 INFO Uploading batch count=13059--- PASS: TestQueueEnqueueAndFetch (0.00s)3060--- PASS: TestWorkerPrunesClosureDeps (0.03s)3061--- PASS: TestWorkerUploadsAndRemoves (0.03s)3062--- PASS: TestWorkerSkipsGCdPaths (0.02s)3063--- PASS: TestQueueRemoveLargeClosure (0.04s)3064--- PASS: TestQueueConcurrentWriters (0.14s)30652026/10/01 07:39:45 ERROR Upload failed error="context deadline exceeded" count=230662026/10/01 07:39:45 ERROR Drain finished with paths left in queue remaining=43067--- PASS: TestDrainTimeout (0.21s)30682026/10/01 07:39:45 INFO Uploading batch count=130692026/10/01 07:39:45 INFO Uploading batch count=130702026/10/01 07:39:45 INFO Uploading batch count=130712026/10/01 07:39:45 ERROR Upload failed error="upload failed" count=130722026/10/01 07:39:45 INFO Uploading batch count=130732026/10/01 07:39:45 ERROR Upload failed error="upload failed" count=130742026/10/01 07:39:45 INFO Uploading batch count=130752026/10/01 07:39:45 ERROR Upload failed error="upload failed" count=130762026/10/01 07:39:45 INFO Uploading batch count=130772026/10/01 07:39:45 ERROR Upload failed error="upload failed" count=130782026/10/01 07:39:45 ERROR Drain finished with paths left in queue remaining=13079--- PASS: TestRunNotBlockedByPoisonHead (1.04s)3080PASS