niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #311
· raw
1tribuchet: building on eliza2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestCaseHackSuffix8=== PAUSE TestCaseHackSuffix9=== RUN TestFilterOversizedClosures10=== PAUSE TestFilterOversizedClosures11=== RUN TestUploadMultipart_PartsInParallel12=== PAUSE TestUploadMultipart_PartsInParallel13=== RUN TestPartSizeForNAR14=== PAUSE TestPartSizeForNAR15=== RUN TestUploadMultipart_SupersededByPeer16=== PAUSE TestUploadMultipart_SupersededByPeer17=== RUN TestDumpPathCaseHackMatchesNix18--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)19=== RUN TestDumpPathCaseHackCollision20--- PASS: TestDumpPathCaseHackCollision (0.00s)21=== RUN TestDumpPathMatchesNix22=== PAUSE TestDumpPathMatchesNix23=== RUN TestDumpPathSingleFile24=== PAUSE TestDumpPathSingleFile25=== RUN TestDumpPathWriterError26=== PAUSE TestDumpPathWriterError27=== RUN TestEncodeNixBase3228=== PAUSE TestEncodeNixBase3229=== RUN TestEncodeNixBase32WithRealHash30=== PAUSE TestEncodeNixBase32WithRealHash31=== RUN TestConvertHashToNix3232=== PAUSE TestConvertHashToNix3233=== RUN TestGetStorePathHash34=== PAUSE TestGetStorePathHash35=== RUN TestPathInfoHashCompatibility36=== PAUSE TestPathInfoHashCompatibility37=== RUN TestParsePathInfoJSON38=== PAUSE TestParsePathInfoJSON39=== RUN TestParsePathInfoJSONMultiplePaths40=== PAUSE TestParsePathInfoJSONMultiplePaths41=== RUN TestPathInfoCACompatibility42=== PAUSE TestPathInfoCACompatibility43=== RUN TestRateLimiterFeedback44=== PAUSE TestRateLimiterFeedback45=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess47=== RUN TestResolveStorePath48=== PAUSE TestResolveStorePath49=== RUN TestDoWithRetry_BodyReplayedViaGetBody50=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody51=== RUN TestShellSplit52=== PAUSE TestShellSplit53=== RUN TestShellSplitErrors54=== PAUSE TestShellSplitErrors55=== RUN TestStreamPushReportsEveryPath56=== PAUSE TestStreamPushReportsEveryPath57=== RUN TestStreamPushBatchesUnderLoad58=== PAUSE TestStreamPushBatchesUnderLoad59=== RUN TestStreamPushIsolatesFailures60=== PAUSE TestStreamPushIsolatesFailures61=== RUN TestStreamPushGivesUpOnDeadServer62=== PAUSE TestStreamPushGivesUpOnDeadServer63=== RUN TestStreamPushRequestLine64=== PAUSE TestStreamPushRequestLine65=== RUN TestStreamPushReportsSignatures66=== PAUSE TestStreamPushReportsSignatures67=== RUN TestClientSignaturesByStorePath68=== PAUSE TestClientSignaturesByStorePath69=== RUN TestSetClientTLS70=== PAUSE TestSetClientTLS71=== RUN TestSetClientTLSDoesNotMutateDefaultTransport72=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport73=== RUN TestSetClientTLSErrors74=== PAUSE TestSetClientTLSErrors75=== RUN TestStaticToken76=== PAUSE TestStaticToken77=== RUN TestFileTokenReadsAndCaches78=== PAUSE TestFileTokenReadsAndCaches79=== RUN TestFileTokenMissing80=== PAUSE TestFileTokenMissing81=== RUN TestFileTokenEmpty82=== PAUSE TestFileTokenEmpty83=== RUN TestScriptTokenNoExpiryRerunsEveryCall84=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall85=== RUN TestScriptTokenCachesUntilRefresh86=== PAUSE TestScriptTokenCachesUntilRefresh87=== RUN TestScriptTokenEmptyToken88=== PAUSE TestScriptTokenEmptyToken89=== RUN TestScriptTokenBadJSON90=== PAUSE TestScriptTokenBadJSON91=== RUN TestScriptTokenScriptFails92=== PAUSE TestScriptTokenScriptFails93=== RUN TestScriptTokenEmptyCommand94=== PAUSE TestScriptTokenEmptyCommand95=== CONT TestDoServerRequestAttachesToken96=== CONT TestShellSplit97=== CONT TestSetClientTLSErrors98=== CONT TestScriptTokenEmptyCommand99=== CONT TestPathInfoCACompatibility100=== RUN TestPathInfoCACompatibility/null_ca_field101=== CONT TestScriptTokenScriptFails102=== CONT TestScriptTokenBadJSON103=== CONT TestScriptTokenEmptyToken104=== CONT TestScriptTokenCachesUntilRefresh105=== CONT TestScriptTokenNoExpiryRerunsEveryCall106=== CONT TestFileTokenEmpty107=== CONT TestFileTokenMissing108=== CONT TestFileTokenReadsAndCaches109=== CONT TestStaticToken110=== CONT TestSetClientTLS111=== CONT TestSetClientTLSDoesNotMutateDefaultTransport112=== CONT TestStreamPushBatchesUnderLoad113=== CONT TestStreamPushGivesUpOnDeadServer114=== CONT TestStreamPushIsolatesFailures115=== CONT TestClientSignaturesByStorePath116=== CONT TestEncodeNixBase32WithRealHash117=== CONT TestDoWithRetry_BodyReplayedViaGetBody118=== CONT TestResolveStorePath119=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess120=== CONT TestStreamPushRequestLine121--- PASS: TestShellSplit (0.00s)122--- PASS: TestScriptTokenEmptyCommand (0.00s)123=== CONT TestRateLimiterFeedback124=== PAUSE TestPathInfoCACompatibility/null_ca_field125=== CONT TestParsePathInfoJSONMultiplePaths126--- PASS: TestScriptTokenScriptFails (0.00s)127=== RUN TestPathInfoCACompatibility/old_string_format_-_text128--- PASS: TestFileTokenMissing (0.00s)129--- PASS: TestStaticToken (0.00s)130=== CONT TestPathInfoHashCompatibility131=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)132=== CONT TestParsePathInfoJSON133=== RUN TestParsePathInfoJSON/Nix_format134--- PASS: TestFileTokenEmpty (0.00s)135=== CONT TestGetStorePathHash136=== RUN TestGetStorePathHash/valid_store_path137=== PAUSE TestGetStorePathHash/valid_store_path138=== RUN TestGetStorePathHash/basename_without_hyphen_should_error139=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error140=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error141=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error142=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error143=== PAUSE TestParsePathInfoJSON/Nix_format144=== RUN TestParsePathInfoJSON/Lix_format145=== PAUSE TestParsePathInfoJSON/Lix_format146=== RUN TestParsePathInfoJSON/empty_input147=== PAUSE TestParsePathInfoJSON/empty_input148=== CONT TestStreamPushReportsEveryPath1492026/10/01 09:39:08 ERROR Upload failed error="connection refused" count=201502026/10/01 09:39:08 ERROR Server seems unavailable, giving up on batch untried=17151=== CONT TestShellSplitErrors1522026/10/01 09:39:08 ERROR Upload failed error="bad path" count=3153--- PASS: TestClientSignaturesByStorePath (0.00s)154=== RUN TestParsePathInfoJSON/whitespace_only1552026/10/01 09:39:08 WARN Rate limiter enabled after throttle name=server-test rate=5156=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error157=== CONT TestUploadMultipart_PartsInParallel158=== CONT TestConvertHashToNix32159=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)160--- PASS: TestEncodeNixBase32WithRealHash (0.00s)161=== PAUSE TestParsePathInfoJSON/whitespace_only162=== CONT TestStreamPushReportsSignatures1632026/10/01 09:39:08 ERROR Upload failed error=boom count=1164=== CONT TestPartSizeForNAR165=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths166=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text167=== RUN TestRateLimiterFeedback/429_enables_limiter168=== CONT TestFilterOversizedClosures169=== RUN TestFilterOversizedClosures/no_limit_keeps_everything170=== CONT TestDumpPathWriterError1712026/10/01 09:39:08 ERROR Upload failed error=boom count=1172=== RUN TestSetClientTLSErrors/missing_cert_file173=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything174=== CONT TestEncodeNixBase32175=== CONT TestDumpPathSingleFile176=== CONT TestCaseHackSuffix177--- PASS: TestFileTokenReadsAndCaches (0.00s)178=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon179=== RUN TestParsePathInfoJSON/invalid_JSON180=== RUN TestConvertHashToNix32/SRI_format_to_Nix32181=== RUN TestPartSizeForNAR/zero_stays_at_minimum182=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths183=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive184=== CONT TestRegisterUploadedObjectReusesConnections185=== RUN TestSetClientTLS/rejects_connection_without_client_cert186=== CONT TestDumpPathMatchesNix187=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32188=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert189=== RUN TestConvertHashToNix32/already_Nix32_format190=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA191=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths192=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths193=== PAUSE TestParsePathInfoJSON/invalid_JSON194=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon1952026/10/01 09:39:08 WARN Rate limiter enabled after throttle name=server-test rate=5196=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI197=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA1982026/10/01 09:39:08 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:43973199=== RUN TestSetClientTLS/preserves_debug_logging_transport200=== PAUSE TestSetClientTLS/preserves_debug_logging_transport201=== CONT TestGetStorePathHash/valid_store_path202=== CONT TestGetStorePathHash/basename_without_hyphen_should_error203=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths2042026/10/01 09:39:08 WARN Rate limiter backed off name=server-test rate=52052026/10/01 09:39:08 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:43973206=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error207=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths208=== CONT TestParsePathInfoJSON/empty_input209=== CONT TestParsePathInfoJSON/whitespace_only210=== CONT TestParsePathInfoJSON/Lix_format211=== CONT TestParsePathInfoJSON/invalid_JSON212=== CONT TestSetClientTLS/rejects_connection_without_client_cert213=== PAUSE TestConvertHashToNix32/already_Nix32_format214=== CONT TestParsePathInfoJSON/Nix_format215=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum216=== RUN TestPartSizeForNAR/small_stays_at_minimum217=== PAUSE TestPartSizeForNAR/small_stays_at_minimum218=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum219=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum220=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts221=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts222=== RUN TestPartSizeForNAR/1_TiB223=== PAUSE TestPartSizeForNAR/1_TiB224=== RUN TestPartSizeForNAR/5_TiB_S3_max_object225=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object226=== RUN TestPartSizeForNAR/capped_at_5_GiB227=== PAUSE TestPartSizeForNAR/capped_at_5_GiB228=== CONT TestPartSizeForNAR/zero_stays_at_minimum229=== CONT TestSetClientTLS/preserves_debug_logging_transport230=== CONT TestPartSizeForNAR/1_TiB231=== CONT TestPartSizeForNAR/capped_at_5_GiB232=== CONT TestPartSizeForNAR/5_TiB_S3_max_object233=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum234=== CONT TestPartSizeForNAR/small_stays_at_minimum235=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts236=== CONT TestUploadMultipart_SupersededByPeer237=== RUN TestUploadMultipart_SupersededByPeer/exists238=== PAUSE TestUploadMultipart_SupersededByPeer/exists239=== RUN TestUploadMultipart_SupersededByPeer/missing240=== PAUSE TestUploadMultipart_SupersededByPeer/missing241=== CONT TestUploadMultipart_SupersededByPeer/exists242=== PAUSE TestSetClientTLSErrors/missing_cert_file243=== RUN TestSetClientTLSErrors/missing_key_file244=== PAUSE TestSetClientTLSErrors/missing_key_file245=== RUN TestSetClientTLSErrors/missing_ca_file246=== PAUSE TestSetClientTLSErrors/missing_ca_file247=== RUN TestSetClientTLSErrors/invalid_ca_file248=== PAUSE TestSetClientTLSErrors/invalid_ca_file249=== CONT TestSetClientTLSErrors/missing_cert_file250=== CONT TestUploadMultipart_SupersededByPeer/missing251=== RUN TestEncodeNixBase32/test_string_hash252=== CONT TestSetClientTLSErrors/missing_ca_file253=== CONT TestSetClientTLSErrors/missing_key_file254=== CONT TestSetClientTLSErrors/invalid_ca_file255=== PAUSE TestEncodeNixBase32/test_string_hash256=== RUN TestEncodeNixBase32/empty_input257=== PAUSE TestEncodeNixBase32/empty_input258=== CONT TestEncodeNixBase32/test_string_hash259--- PASS: TestShellSplitErrors (0.00s)260--- PASS: TestScriptTokenBadJSON (0.01s)261--- PASS: TestScriptTokenEmptyToken (0.01s)262--- PASS: TestStreamPushIsolatesFailures (0.00s)263--- PASS: TestStreamPushReportsEveryPath (0.00s)264--- PASS: TestDoServerRequestAttachesToken (0.01s)265=== CONT TestEncodeNixBase32/empty_input266=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive267=== RUN TestPathInfoCACompatibility/new_structured_format_-_text268=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text269=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method270=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method271=== CONT TestPathInfoCACompatibility/null_ca_field272--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)273--- PASS: TestResolveStorePath (0.00s)274--- PASS: TestStreamPushReportsSignatures (0.00s)275--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)276=== PAUSE TestRateLimiterFeedback/429_enables_limiter277=== RUN TestRateLimiterFeedback/503_enables_limiter278=== PAUSE TestRateLimiterFeedback/503_enables_limiter279=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter280=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter281=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter282=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter283=== CONT TestRateLimiterFeedback/429_enables_limiter284=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method285=== CONT TestPathInfoCACompatibility/new_structured_format_-_text286=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive287=== CONT TestPathInfoCACompatibility/old_string_format_-_text288=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter289--- PASS: TestPathInfoCACompatibility (0.04s)290 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)291 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)292 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)293 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)294 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)295--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)296 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)297 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)298=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error2992026/10/01 09:39:08 WARN Rate limiter enabled after throttle name=server-test rate=5300=== RUN TestConvertHashToNix32/invalid_format3012026/10/01 09:39:08 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:33225302=== PAUSE TestConvertHashToNix32/invalid_format303=== CONT TestConvertHashToNix32/SRI_format_to_Nix32304=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI305=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512306=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512307=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)308=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3092026/10/01 09:39:08 WARN Rate limiter backed off name=server-test rate=5310=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512311=== CONT TestConvertHashToNix32/already_Nix32_format312=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon313=== CONT TestRateLimiterFeedback/503_enables_limiter314=== CONT TestConvertHashToNix32/invalid_format315=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped316=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped317=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI318=== RUN TestFilterOversizedClosures/all_closures_skipped319=== PAUSE TestFilterOversizedClosures/all_closures_skipped320=== CONT TestFilterOversizedClosures/no_limit_keeps_everything321--- PASS: TestParsePathInfoJSONMultiplePaths (0.03s)322 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)323 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)324--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)325--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)326--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)327=== CONT TestFilterOversizedClosures/all_closures_skipped3282026/10/01 09:39:08 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=50329=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3302026/10/01 09:39:08 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=2000331--- PASS: TestParsePathInfoJSON (0.03s)332 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)333 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)334 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)335 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)336 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)337=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter338--- PASS: TestPathInfoHashCompatibility (0.04s)339 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)340 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)341 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)342 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)3432026/10/01 09:39:08 WARN Rate limiter enabled after throttle name=server-test rate=5344--- PASS: TestFilterOversizedClosures (0.04s)345 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)346 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)347 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)3482026/10/01 09:39:08 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:42873349--- PASS: TestPartSizeForNAR (0.03s)350 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)351 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)352 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)353 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)354 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)355 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)356 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)357--- PASS: TestEncodeNixBase32 (0.00s)358 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)359 --- PASS: TestEncodeNixBase32/empty_input (0.00s)360--- PASS: TestSetClientTLSErrors (0.05s)361 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)362 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)363 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)364 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)365--- PASS: TestGetStorePathHash (0.00s)366 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)367 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)368 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)369 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)370--- PASS: TestConvertHashToNix32 (0.04s)371 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)372 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)373 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)3742026/10/01 09:39:08 WARN Rate limiter backed off name=server-test rate=5375--- PASS: TestRateLimiterFeedback (0.04s)376 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)377 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)378 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)379 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)3802026/10/01 09:39:08 http: TLS handshake error from 127.0.0.1:59754: remote error: tls: bad certificate381--- PASS: TestSetClientTLS (0.04s)382 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)383 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)384 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)385--- PASS: TestStreamPushRequestLine (0.05s)386--- PASS: TestRegisterUploadedObjectReusesConnections (0.02s)387--- PASS: TestCaseHackSuffix (0.03s)388--- PASS: TestDumpPathSingleFile (0.03s)389--- PASS: TestDumpPathWriterError (0.04s)390--- PASS: TestStreamPushBatchesUnderLoad (0.10s)391--- PASS: TestDumpPathMatchesNix (0.08s)392--- PASS: TestUploadMultipart_PartsInParallel (0.65s)393--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)394PASS395Running server tests...396The files belonging to this database system will be owned by user "nixbld".397This user must also own the server process.398399The database cluster will be initialized with locale "C".400The default database encoding has accordingly been set to "SQL_ASCII".401The default text search configuration will be set to "english".402403Data page checksums are enabled.404405creating directory /build/postgres2973129859/data ... ok406creating subdirectories ... ok407selecting dynamic shared memory implementation ... posix408selecting default "max_connections" ... 100409selecting default "shared_buffers" ... 128MB410selecting default time zone ... UTC411creating configuration files ... ok412running bootstrap script ... ok413performing post-bootstrap initialization ... ok414syncing data to disk ... ok415416initdb: warning: enabling "trust" authentication for local connections417initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.418419Success. You can now start the database server using:420421 pg_ctl -D /build/postgres2973129859/data -l logfile start422423/build/postgres2973129859:5432 - no response4242026-10-01 09:39:10.513 UTC [129] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 09:39:10.513 UTC [129] LOG: listening on Unix socket "/build/postgres2973129859/.s.PGSQL.5432"4262026-10-01 09:39:10.517 UTC [136] LOG: database system was shut down at 2026-10-01 09:39:10 UTC4272026-10-01 09:39:10.520 UTC [129] LOG: database system is ready to accept connections428/build/postgres2973129859:5432 - accepting connections429{"timestamp":"2026-10-01T09:39:10.710631591Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"2433ee42-34ef-4ed5-955f-67e9a3f720fa","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(198)"}430{"timestamp":"2026-10-01T09:39:10.812794833Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"bfdf85fc-0599-4df8-950b-2fc535705001","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(198)"}431=== RUN TestService_AuthMiddleware432=== PAUSE TestService_AuthMiddleware433=== RUN TestService_AuthMiddleware_MTLSProxyHeader434=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader435=== RUN TestService_AuthMiddleware_MTLSBoundSubjects436=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects437=== RUN TestService_ReadAuthMiddleware438=== PAUSE TestService_ReadAuthMiddleware439=== RUN TestService_AuthMiddleware_OIDC440=== PAUSE TestService_AuthMiddleware_OIDC441=== RUN TestService_RequireScope_OIDC442=== PAUSE TestService_RequireScope_OIDC443=== RUN TestService_ReadScope_PublicByDefault444=== PAUSE TestService_ReadScope_PublicByDefault445=== RUN TestCacheConfigHandler446=== PAUSE TestCacheConfigHandler447=== RUN TestCacheStatsHandler448=== PAUSE TestCacheStatsHandler449=== RUN TestClientCADerivations450=== PAUSE TestClientCADerivations451=== RUN TestClientErrorHandling452=== PAUSE TestClientErrorHandling453=== RUN TestClientIntegration454=== PAUSE TestClientIntegration455=== RUN TestClientMultipleUploads456=== PAUSE TestClientMultipleUploads457=== RUN TestClientWithDependencies458=== PAUSE TestClientWithDependencies459=== RUN TestClientSharedPathCommittedMidPush460=== PAUSE TestClientSharedPathCommittedMidPush461=== RUN TestPinProtectsFromGC462=== PAUSE TestPinProtectsFromGC463=== RUN TestClientPushesUseOnePush464=== PAUSE TestClientPushesUseOnePush465=== RUN TestClientFallsBackToClosures466=== PAUSE TestClientFallsBackToClosures467=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock468=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock469=== RUN TestResolveDBConnectionString470=== PAUSE TestResolveDBConnectionString471=== RUN TestLeadElectsOneAndHandsOver472=== PAUSE TestLeadElectsOneAndHandsOver473=== RUN TestLeadIncumbentWinsAfterRestart4742026-10-01 09:39:10.990 UTC [373] ERROR: relation "goose_db_version" does not exist at character 364752026-10-01 09:39:10.990 UTC [373] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4762026/10/01 09:39:11 OK 20241026095416_initial_model.sql (10.31ms)4772026/10/01 09:39:11 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)4782026/10/01 09:39:11 OK 20251218171726_add_pins.sql (3.35ms)4792026/10/01 09:39:11 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)4802026/10/01 09:39:11 OK 20260905000000_add_claims.sql (3.13ms)4812026/10/01 09:39:11 OK 20260920000000_drop_claims.sql (1.85ms)4822026/10/01 09:39:11 OK 20260923120000_add_pushes.sql (1.51ms)4832026/10/01 09:39:11 goose: successfully migrated database to version: 202609231200004842026/10/01 09:39:11 OK 1_commit_pending_closure.sql (1.81ms)4852026/10/01 09:39:11 OK 2_object_stats_trigger.sql (834.11µs)4862026/10/01 09:39:11 OK 3_commit_push.sql (614.67µs)4872026/10/01 09:39:11 goose: up to current file version: 34882026/10/01 09:39:11 INFO lead: acquired remote=192.0.2.1:12344892026/10/01 09:39:11 INFO lead: released remote=192.0.2.1:12344902026/10/01 09:39:11 INFO lead: acquired remote=192.0.2.1:12344912026/10/01 09:39:11 INFO lead: released remote=192.0.2.1:1234492--- PASS: TestLeadIncumbentWinsAfterRestart (0.78s)493=== RUN TestLeadEndsOnShutdown494=== PAUSE TestLeadEndsOnShutdown495=== RUN TestGCAdvisoryLockBlocksConcurrentRun4962026-10-01 09:39:11.761 UTC [383] ERROR: relation "goose_db_version" does not exist at character 364972026-10-01 09:39:11.761 UTC [383] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4982026/10/01 09:39:11 OK 20241026095416_initial_model.sql (7.94ms)4992026/10/01 09:39:11 OK 20251210153512_drop_unused_gin_index.sql (2.1ms)5002026/10/01 09:39:11 OK 20251218171726_add_pins.sql (2.92ms)5012026/10/01 09:39:11 OK 20260628120000_add_object_size_and_stats.sql (3.2ms)5022026/10/01 09:39:11 OK 20260905000000_add_claims.sql (3.6ms)5032026/10/01 09:39:11 OK 20260920000000_drop_claims.sql (2.05ms)5042026/10/01 09:39:11 OK 20260923120000_add_pushes.sql (1.96ms)5052026/10/01 09:39:11 goose: successfully migrated database to version: 202609231200005062026/10/01 09:39:11 OK 1_commit_pending_closure.sql (1.75ms)5072026/10/01 09:39:11 OK 2_object_stats_trigger.sql (993.77µs)5082026/10/01 09:39:11 OK 3_commit_push.sql (707.51µs)5092026/10/01 09:39:11 goose: up to current file version: 3510--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.12s)511=== RUN TestGCBugBareHashReferences512=== PAUSE TestGCBugBareHashReferences513=== RUN TestGCMetrics514=== PAUSE TestGCMetrics515=== RUN TestPushDedupSurvivesConcurrentGC516=== PAUSE TestPushDedupSurvivesConcurrentGC517=== RUN TestDeduplicatedObjectsRecordedAsPending518=== PAUSE TestDeduplicatedObjectsRecordedAsPending519=== RUN TestGCSweepSkipsPendingObjects520=== PAUSE TestGCSweepSkipsPendingObjects521=== RUN TestTombstonedObjectOfferedWithoutWaiting522=== PAUSE TestTombstonedObjectOfferedWithoutWaiting523=== RUN TestGCSweepDeliversEachKeyOnce524=== PAUSE TestGCSweepDeliversEachKeyOnce525=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection527=== RUN TestForceGCDuringPushOffersSweptObject528=== PAUSE TestForceGCDuringPushOffersSweptObject529=== RUN TestFailedS3DeleteKeepsTombstone530=== PAUSE TestFailedS3DeleteKeepsTombstone531=== RUN TestSweepSkipsRowsLockedByPush532=== PAUSE TestSweepSkipsRowsLockedByPush533=== RUN TestRegisterCompletedObjectNeedsPendingRow534=== PAUSE TestRegisterCompletedObjectNeedsPendingRow535=== RUN TestGetExistingObjectsLocksRows536=== PAUSE TestGetExistingObjectsLocksRows537=== RUN TestSweepRechecksPendingAfterLocking538=== PAUSE TestSweepRechecksPendingAfterLocking539=== RUN TestPushWaitsForSweepHoldingRow540=== PAUSE TestPushWaitsForSweepHoldingRow541=== RUN TestCommitRacingPendingCleanupKeepsObjects542=== PAUSE TestCommitRacingPendingCleanupKeepsObjects543=== RUN TestGCEndsOnShutdown544=== PAUSE TestGCEndsOnShutdown545=== RUN TestGCTaskStore_StartNew546=== PAUSE TestGCTaskStore_StartNew547=== RUN TestGCTaskStore_DeduplicateSameParams548=== PAUSE TestGCTaskStore_DeduplicateSameParams549=== RUN TestGCTaskStore_ConflictDifferentParams550=== PAUSE TestGCTaskStore_ConflictDifferentParams551=== RUN TestGCTaskStore_GetEmpty552=== PAUSE TestGCTaskStore_GetEmpty553=== RUN TestGCTaskStore_GetReturnsLatest554=== PAUSE TestGCTaskStore_GetReturnsLatest555=== RUN TestGCTaskStore_CompletedAllowsNewTask556=== PAUSE TestGCTaskStore_CompletedAllowsNewTask557=== RUN TestGCTaskStore_PhaseUpdates558=== PAUSE TestGCTaskStore_PhaseUpdates559=== RUN TestGCTaskStore_Fail560=== PAUSE TestGCTaskStore_Fail561=== RUN TestGracefulShutdownDrainsInflight562=== PAUSE TestGracefulShutdownDrainsInflight563=== RUN TestService_healthCheckHandler564=== PAUSE TestService_healthCheckHandler565=== RUN TestService_readinessHandler566=== PAUSE TestService_readinessHandler567=== RUN TestGenerateLandingPage568=== PAUSE TestGenerateLandingPage569=== RUN TestCacheConfigHandlerMaxNarSize570=== PAUSE TestCacheConfigHandlerMaxNarSize571=== RUN TestCreatePendingClosureRejectsOversizedNAR572=== PAUSE TestCreatePendingClosureRejectsOversizedNAR573=== RUN TestNARDeduplicationMetadataUploadBug574=== PAUSE TestNARDeduplicationMetadataUploadBug575=== RUN TestMetricsInventory576=== PAUSE TestMetricsInventory577=== RUN TestService_NativeMTLS578=== PAUSE TestService_NativeMTLS579=== RUN TestServerTLSConfig580=== PAUSE TestServerTLSConfig581=== RUN TestMultipartCleanup582=== PAUSE TestMultipartCleanup583=== RUN TestObjectStatsTrigger584=== PAUSE TestObjectStatsTrigger585=== RUN TestOrphanedObjectsGC586=== PAUSE TestOrphanedObjectsGC587=== RUN TestOrphanedObjectsGCStressTest588=== PAUSE TestOrphanedObjectsGCStressTest589=== RUN TestCreatePin_ReservedPins590=== PAUSE TestCreatePin_ReservedPins591=== RUN TestPresentReportsOnlyClosureRoots592=== PAUSE TestPresentReportsOnlyClosureRoots593=== RUN TestPresentNotReportedWhileGCDeletesClosure594=== PAUSE TestPresentNotReportedWhileGCDeletesClosure595=== RUN TestParseSingleRange596=== PAUSE TestParseSingleRange597=== RUN TestProxyHeadersOnlyTrustedOnSocket598=== PAUSE TestProxyHeadersOnlyTrustedOnSocket599=== RUN TestIsValidCachePath600=== PAUSE TestIsValidCachePath601=== RUN TestReadProxyNarinfo602=== PAUSE TestReadProxyNarinfo603=== RUN TestReadProxyNarinfoAlreadyDecompressed604=== PAUSE TestReadProxyNarinfoAlreadyDecompressed605=== RUN TestReadProxyNarStreaming606=== PAUSE TestReadProxyNarStreaming607=== RUN TestReadProxy404608=== PAUSE TestReadProxy404609=== RUN TestReadProxyInvalidPath610=== PAUSE TestReadProxyInvalidPath611=== RUN TestReadProxyHead612=== PAUSE TestReadProxyHead613=== RUN TestReadProxyConditionalGet614=== PAUSE TestReadProxyConditionalGet615=== RUN TestReadProxyRootRedirectsToIndexHTML616=== PAUSE TestReadProxyRootRedirectsToIndexHTML617=== RUN TestReadProxyDisabled618=== PAUSE TestReadProxyDisabled619=== RUN TestReadRedirectNar620=== PAUSE TestReadRedirectNar621=== RUN TestReadRedirectKeepsNarinfoProxied622=== PAUSE TestReadRedirectKeepsNarinfoProxied623=== RUN TestReadProxyRangeRequest624=== PAUSE TestReadProxyRangeRequest625=== RUN TestReadRedirectUsesPublicS3URL626=== PAUSE TestReadRedirectUsesPublicS3URL627=== RUN TestPush_OverlappingRootsStoreOneRowPerKey628=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey629=== RUN TestPush_CompleteCommitsEveryRoot630=== PAUSE TestPush_CompleteCommitsEveryRoot631=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit632=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit633=== RUN TestPush_RejectsBadRequests634=== PAUSE TestPush_RejectsBadRequests635=== RUN TestPush_SignsNarinfosOfItsPendingObjects636=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects637=== RUN TestRedundantMultipartUpload638=== PAUSE TestRedundantMultipartUpload639=== RUN TestCompleteMultipartUpload_ErrorButObjectExists640=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists641=== RUN TestCompletedNarNotReofferedAcrossClosures642=== PAUSE TestCompletedNarNotReofferedAcrossClosures643=== RUN TestPresignedUploadRegisteredBeforeCommit644=== PAUSE TestPresignedUploadRegisteredBeforeCommit645=== RUN TestService_Rustfstest646=== PAUSE TestService_Rustfstest647=== RUN TestParseSize648=== PAUSE TestParseSize649=== RUN TestSkippedUploadsHandler650=== PAUSE TestSkippedUploadsHandler651=== RUN TestSystemdListenerNotActivated652--- PASS: TestSystemdListenerNotActivated (0.00s)653=== RUN TestWatchdogBeatsWhenHealthy654--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)655=== RUN TestWatchdogSkipsWhenUnhealthy6562026/10/01 09:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6572026/10/01 09:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6582026/10/01 09:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6592026/10/01 09:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:39:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"666--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)667=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle668=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle669=== RUN TestProxyWriteTimeout670=== PAUSE TestProxyWriteTimeout671=== RUN TestIsValidUploadKey672=== PAUSE TestIsValidUploadKey673=== RUN TestUploadHandlersRejectInvalidKeys674=== PAUSE TestUploadHandlersRejectInvalidKeys675=== RUN TestUploadHandlersRejectOversizedBody676=== PAUSE TestUploadHandlersRejectOversizedBody677=== RUN TestService_cleanupPendingClosuresHandler678=== PAUSE TestService_cleanupPendingClosuresHandler679=== RUN TestService_createPendingClosureHandler680=== PAUSE TestService_createPendingClosureHandler681=== RUN TestService_verifyS3Integrity682=== PAUSE TestService_verifyS3Integrity683=== RUN TestCompleteMultipartUnregistered684=== PAUSE TestCompleteMultipartUnregistered685=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT686=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT687=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle688=== CONT TestGCTaskStore_ConflictDifferentParams689=== CONT TestCompleteMultipartUpload_ErrorButObjectExists690=== CONT TestReadRedirectUsesPublicS3URL691=== CONT TestProxyHeadersOnlyTrustedOnSocket692=== CONT TestGCTaskStore_CompletedAllowsNewTask693=== CONT TestSweepRechecksPendingAfterLocking694=== CONT TestSkippedUploadsHandler695=== CONT TestParseSize696=== CONT TestService_Rustfstest6972026/10/01 09:39:12 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000698=== CONT TestPresignedUploadRegisteredBeforeCommit699=== CONT TestGCTaskStore_GetReturnsLatest700=== CONT TestRegisterCompletedObjectNeedsPendingRow701=== CONT TestGCTaskStore_GetEmpty702=== CONT TestSweepSkipsRowsLockedByPush703=== CONT TestCompletedNarNotReofferedAcrossClosures704=== CONT TestRedundantMultipartUpload705=== CONT TestPush_SignsNarinfosOfItsPendingObjects706--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)707--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)708--- PASS: TestParseSize (0.00s)709--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)710--- PASS: TestGCTaskStore_GetEmpty (0.00s)711=== CONT TestPush_RejectsBadRequests712=== CONT TestGCTaskStore_DeduplicateSameParams713--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)714=== CONT TestFailedS3DeleteKeepsTombstone715=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit716=== CONT TestGCTaskStore_StartNew717--- PASS: TestGCTaskStore_StartNew (0.00s)718=== CONT TestPush_CompleteCommitsEveryRoot719=== CONT TestGCEndsOnShutdown720=== CONT TestPush_OverlappingRootsStoreOneRowPerKey721=== CONT TestCommitRacingPendingCleanupKeepsObjects722=== CONT TestPushWaitsForSweepHoldingRow723=== CONT TestService_AuthMiddleware724=== CONT TestGetExistingObjectsLocksRows725=== CONT TestForceGCDuringPushOffersSweptObject726=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows727=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows728=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check729=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check730=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection731--- PASS: TestSkippedUploadsHandler (0.01s)732=== CONT TestGCSweepDeliversEachKeyOnce7332026-10-01 09:39:12.156 UTC [450] ERROR: relation "goose_db_version" does not exist at character 367342026-10-01 09:39:12.156 UTC [450] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7352026-10-01 09:39:12.161 UTC [451] ERROR: relation "goose_db_version" does not exist at character 367362026-10-01 09:39:12.161 UTC [451] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7372026-10-01 09:39:12.174 UTC [452] ERROR: relation "goose_db_version" does not exist at character 367382026-10-01 09:39:12.174 UTC [452] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7392026-10-01 09:39:12.189 UTC [453] ERROR: relation "goose_db_version" does not exist at character 367402026-10-01 09:39:12.189 UTC [453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7412026-10-01 09:39:12.195 UTC [454] ERROR: relation "goose_db_version" does not exist at character 367422026-10-01 09:39:12.195 UTC [454] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7432026/10/01 09:39:12 OK 20241026095416_initial_model.sql (73.16ms)7442026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (6.27ms)7452026/10/01 09:39:12 OK 20241026095416_initial_model.sql (77.55ms)7462026-10-01 09:39:12.266 UTC [455] ERROR: relation "goose_db_version" does not exist at character 367472026-10-01 09:39:12.266 UTC [455] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7482026-10-01 09:39:12.269 UTC [457] ERROR: relation "goose_db_version" does not exist at character 367492026-10-01 09:39:12.269 UTC [457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7502026/10/01 09:39:12 OK 20241026095416_initial_model.sql (113.38ms)7512026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (43.98ms)7522026/10/01 09:39:12 OK 20251218171726_add_pins.sql (49.47ms)7532026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (7.24ms)7542026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (7.99ms)7552026/10/01 09:39:12 OK 20251218171726_add_pins.sql (7.66ms)7562026/10/01 09:39:12 OK 20241026095416_initial_model.sql (80.11ms)7572026-10-01 09:39:12.319 UTC [459] ERROR: relation "goose_db_version" does not exist at character 367582026-10-01 09:39:12.319 UTC [459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7592026/10/01 09:39:12 OK 20251218171726_add_pins.sql (16.95ms)7602026/10/01 09:39:12 OK 20241026095416_initial_model.sql (81.21ms)7612026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.7ms)7622026/10/01 09:39:12 OK 20260905000000_add_claims.sql (6.78ms)7632026-10-01 09:39:12.327 UTC [460] ERROR: relation "goose_db_version" does not exist at character 367642026-10-01 09:39:12.327 UTC [460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7652026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.84ms)7662026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (15.84ms)7672026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (7.89ms)7682026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (10.57ms)7692026-10-01 09:39:12.343 UTC [461] ERROR: relation "goose_db_version" does not exist at character 367702026-10-01 09:39:12.343 UTC [461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7712026-10-01 09:39:12.344 UTC [463] ERROR: relation "goose_db_version" does not exist at character 367722026-10-01 09:39:12.344 UTC [463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7732026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (13.35ms)7742026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200007752026/10/01 09:39:12 OK 20260905000000_add_claims.sql (11.03ms)7762026/10/01 09:39:12 OK 20251218171726_add_pins.sql (11.98ms)7772026/10/01 09:39:12 OK 20251218171726_add_pins.sql (19.81ms)7782026/10/01 09:39:12 OK 20260905000000_add_claims.sql (12.24ms)7792026-10-01 09:39:12.345 UTC [462] ERROR: relation "goose_db_version" does not exist at character 367802026-10-01 09:39:12.345 UTC [462] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7812026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.45ms)7822026/10/01 09:39:12 OK 20241026095416_initial_model.sql (27.06ms)7832026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.89ms)7842026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (4.07ms)7852026/10/01 09:39:12 OK 20241026095416_initial_model.sql (28.59ms)7862026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.14ms)7872026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.88ms)7882026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.39ms)7892026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200007902026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.7ms)7912026-10-01 09:39:12.353 UTC [464] ERROR: relation "goose_db_version" does not exist at character 367922026-10-01 09:39:12.353 UTC [464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7932026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (4.72ms)7942026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200007952026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (9.03ms)7962026/10/01 09:39:12 OK 3_commit_push.sql (3.09ms)7972026/10/01 09:39:12 goose: up to current file version: 37982026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.9ms)7992026/10/01 09:39:12 OK 1_commit_pending_closure.sql (4.31ms)8002026/10/01 09:39:12 OK 20241026095416_initial_model.sql (21.99ms)8012026-10-01 09:39:12.356 UTC [465] ERROR: relation "goose_db_version" does not exist at character 368022026-10-01 09:39:12.356 UTC [465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8032026-10-01 09:39:12.356 UTC [466] ERROR: relation "goose_db_version" does not exist at character 368042026-10-01 09:39:12.356 UTC [466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8052026-10-01 09:39:12.358 UTC [467] ERROR: relation "goose_db_version" does not exist at character 368062026-10-01 09:39:12.358 UTC [467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8072026/10/01 09:39:12 OK 20251218171726_add_pins.sql (6.96ms)8082026/10/01 09:39:12 OK 1_commit_pending_closure.sql (5.29ms)8092026/10/01 09:39:12 OK 20260905000000_add_claims.sql (8.43ms)8102026/10/01 09:39:12 OK 20241026095416_initial_model.sql (14.58ms)8112026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.48ms)8122026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.88ms)8132026/10/01 09:39:12 OK 2_object_stats_trigger.sql (4.53ms)8142026/10/01 09:39:12 OK 20260905000000_add_claims.sql (6.84ms)8152026/10/01 09:39:12 OK 2_object_stats_trigger.sql (3.35ms)8162026-10-01 09:39:12.364 UTC [468] ERROR: relation "goose_db_version" does not exist at character 368172026-10-01 09:39:12.364 UTC [468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8182026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.77ms)8192026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.52ms)8202026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.91ms)8212026/10/01 09:39:12 OK 3_commit_push.sql (2.61ms)8222026/10/01 09:39:12 goose: up to current file version: 38232026-10-01 09:39:12.367 UTC [469] ERROR: relation "goose_db_version" does not exist at character 368242026-10-01 09:39:12.367 UTC [469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8252026-10-01 09:39:12.368 UTC [470] ERROR: relation "goose_db_version" does not exist at character 368262026-10-01 09:39:12.368 UTC [470] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8272026-10-01 09:39:12.368 UTC [471] ERROR: relation "goose_db_version" does not exist at character 368282026-10-01 09:39:12.368 UTC [471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8292026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (4.99ms)8302026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (4.53ms)8312026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200008322026/10/01 09:39:12 OK 3_commit_push.sql (3.59ms)8332026/10/01 09:39:12 goose: up to current file version: 38342026/10/01 09:39:12 OK 20241026095416_initial_model.sql (14.43ms)8352026/10/01 09:39:12 OK 20241026095416_initial_model.sql (13.39ms)8362026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.49ms)8372026/10/01 09:39:12 OK 20241026095416_initial_model.sql (13.14ms)8382026-10-01 09:39:12.372 UTC [472] ERROR: relation "goose_db_version" does not exist at character 368392026-10-01 09:39:12.372 UTC [472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8402026/10/01 09:39:12 OK 20260905000000_add_claims.sql (8ms)8412026/10/01 09:39:12 OK 1_commit_pending_closure.sql (4.8ms)8422026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (5.07ms)8432026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (7.95ms)8442026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (9.76ms)8452026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200008462026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.84ms)8472026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.46ms)8482026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.68ms)8492026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (5.09ms)8502026-10-01 09:39:12.376 UTC [473] ERROR: relation "goose_db_version" does not exist at character 368512026-10-01 09:39:12.376 UTC [473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8522026-10-01 09:39:12.376 UTC [474] ERROR: relation "goose_db_version" does not exist at character 368532026-10-01 09:39:12.376 UTC [474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8542026-10-01 09:39:12.377 UTC [475] ERROR: relation "goose_db_version" does not exist at character 368552026-10-01 09:39:12.377 UTC [475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8562026/10/01 09:39:12 OK 2_object_stats_trigger.sql (3.22ms)8572026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (6.47ms)8582026/10/01 09:39:12 OK 1_commit_pending_closure.sql (5.33ms)8592026/10/01 09:39:12 OK 20260905000000_add_claims.sql (7.05ms)8602026/10/01 09:39:12 OK 20260905000000_add_claims.sql (7.48ms)8612026/10/01 09:39:12 OK 20241026095416_initial_model.sql (14.33ms)8622026/10/01 09:39:12 OK 20251218171726_add_pins.sql (7.14ms)8632026/10/01 09:39:12 OK 20241026095416_initial_model.sql (16.34ms)8642026/10/01 09:39:12 OK 20251218171726_add_pins.sql (7.27ms)8652026/10/01 09:39:12 OK 20251218171726_add_pins.sql (7.06ms)8662026/10/01 09:39:12 OK 20241026095416_initial_model.sql (13.57ms)8672026/10/01 09:39:12 OK 20241026095416_initial_model.sql (14.52ms)8682026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.12ms)8692026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200008702026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (8.33ms)8712026/10/01 09:39:12 OK 3_commit_push.sql (2.92ms)8722026/10/01 09:39:12 goose: up to current file version: 38732026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.87ms)8742026/10/01 09:39:12 OK 3_commit_push.sql (2.23ms)8752026/10/01 09:39:12 goose: up to current file version: 38762026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.85ms)8772026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.5ms)8782026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.24ms)8792026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.39ms)8802026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.4ms)8812026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200008822026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.82ms)8832026/10/01 09:39:12 OK 1_commit_pending_closure.sql (4.54ms)8842026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.78ms)8852026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.8ms)8862026/10/01 09:39:12 OK 20260905000000_add_claims.sql (6.26ms)8872026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (7.26ms)8882026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.87ms)8892026/10/01 09:39:12 OK 20241026095416_initial_model.sql (14.06ms)8902026/10/01 09:39:12 OK 20241026095416_initial_model.sql (15.58ms)8912026/10/01 09:39:12 OK 20241026095416_initial_model.sql (18.12ms)8922026/10/01 09:39:12 OK 20260905000000_add_claims.sql (5.28ms)8932026/10/01 09:39:12 OK 20260905000000_add_claims.sql (5.37ms)8942026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (5.94ms)8952026/10/01 09:39:12 OK 20241026095416_initial_model.sql (17.26ms)8962026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200008972026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.79ms)8982026/10/01 09:39:12 OK 1_commit_pending_closure.sql (6ms)8992026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.98ms)9002026/10/01 09:39:12 OK 20251218171726_add_pins.sql (6.55ms)9012026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.19ms)9022026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.62ms)9032026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.22ms)9042026/10/01 09:39:12 OK 20251218171726_add_pins.sql (7.63ms)9052026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.06ms)9062026/10/01 09:39:12 OK 20241026095416_initial_model.sql (15.35ms)9072026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (4.2ms)9082026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.7ms)9092026/10/01 09:39:12 OK 2_object_stats_trigger.sql (4.11ms)9102026/10/01 09:39:12 OK 20251218171726_add_pins.sql (9.99ms)9112026/10/01 09:39:12 OK 20241026095416_initial_model.sql (14.95ms)9122026/10/01 09:39:12 OK 20260905000000_add_claims.sql (10.39ms)9132026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (5ms)9142026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009152026/10/01 09:39:12 OK 1_commit_pending_closure.sql (5.63ms)9162026/10/01 09:39:12 OK 2_object_stats_trigger.sql (11.09ms)9172026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.54ms)9182026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.01ms)9192026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.62ms)9202026/10/01 09:39:12 OK 20241026095416_initial_model.sql (14.47ms)9212026/10/01 09:39:12 OK 20241026095416_initial_model.sql (15.93ms)9222026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.41ms)9232026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)9242026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.19ms)9252026/10/01 09:39:12 OK 3_commit_push.sql (2.62ms)9262026/10/01 09:39:12 goose: up to current file version: 39272026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (4.49ms)9282026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009292026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.45ms)9302026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.45ms)9312026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009322026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.89ms)9332026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.88ms)9342026/10/01 09:39:12 OK 3_commit_push.sql (2.68ms)9352026/10/01 09:39:12 goose: up to current file version: 39362026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.77ms)9372026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.86ms)9382026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (1.75ms)9392026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.95ms)9402026/10/01 09:39:12 INFO Aborted multipart uploads count=09412026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.6ms)9422026/10/01 09:39:12 OK 3_commit_push.sql (2.2ms)9432026/10/01 09:39:12 goose: up to current file version: 39442026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.11ms)9452026/10/01 09:39:12 OK 2_object_stats_trigger.sql (4.47ms)9462026/10/01 09:39:12 OK 20260905000000_add_claims.sql (6.14ms)9472026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.68ms)9482026/10/01 09:39:12 OK 1_commit_pending_closure.sql (4.73ms)9492026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (7.17ms)9502026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.33ms)9512026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (7.04ms)9522026/10/01 09:39:12 OK 20260905000000_add_claims.sql (6.91ms)9532026/10/01 09:39:12 OK 20251218171726_add_pins.sql (6.19ms)9542026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.3ms)9552026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.99ms)9562026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (9.32ms)9572026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (6.57ms)9582026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.58ms)9592026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009602026/10/01 09:39:12 OK 2_object_stats_trigger.sql (5.11ms)9612026/10/01 09:39:12 OK 3_commit_push.sql (2.97ms)9622026/10/01 09:39:12 goose: up to current file version: 39632026/10/01 09:39:12 OK 20260905000000_add_claims.sql (6.24ms)9642026/10/01 09:39:12 OK 20251218171726_add_pins.sql (8.81ms)9652026/10/01 09:39:12 WARN Force mode enabled - objects will be deleted immediately without grace period9662026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.55ms)9672026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.89ms)9682026/10/01 09:39:12 OK 3_commit_push.sql (2ms)9692026/10/01 09:39:12 goose: up to current file version: 39702026/10/01 09:39:12 OK 3_commit_push.sql (2.65ms)9712026/10/01 09:39:12 goose: up to current file version: 39722026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.72ms)9732026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.6ms)9742026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.36ms)9752026/10/01 09:39:12 OK 20260905000000_add_claims.sql (4.75ms)9762026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.42ms)9772026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.03ms)9782026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.34ms)9792026/10/01 09:39:12 OK 20260905000000_add_claims.sql (5.2ms)9802026/10/01 09:39:12 OK 20260905000000_add_claims.sql (5.14ms)9812026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.85ms)9822026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.95ms)9832026/10/01 09:39:12 OK 20260905000000_add_claims.sql (4.43ms)9842026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.47ms)9852026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.35ms)9862026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009872026/10/01 09:39:12 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=09882026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.23ms)9892026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009902026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.17ms)9912026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009922026/10/01 09:39:12 OK 3_commit_push.sql (2.1ms)9932026/10/01 09:39:12 goose: up to current file version: 39942026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.8ms)9952026/10/01 09:39:12 goose: successfully migrated database to version: 202609231200009962026/10/01 09:39:12 INFO Vacuumed table table=pending_closures9972026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.45ms)9982026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.16ms)9992026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.94ms)10002026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.28ms)10012026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.17ms)10022026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.51ms)10032026/10/01 09:39:12 INFO Vacuumed table table=pending_objects10042026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.4ms)10052026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.8ms)10062026/10/01 09:39:12 OK 20260905000000_add_claims.sql (3.58ms)10072026/10/01 09:39:12 INFO Vacuumed table table=multipart_uploads10082026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (4.08ms)10092026/10/01 09:39:12 INFO Vacuumed table table=closures10102026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.81ms)10112026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.5ms)10122026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.3ms)10132026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.97ms)10142026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.07ms)10152026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010162026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.51ms)10172026/10/01 09:39:12 INFO Vacuumed table table=objects10182026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.45ms)10192026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010202026/10/01 09:39:12 INFO Received uploads request method=POST path=/api/pending_closures10212026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (4.63ms)10222026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010232026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.84ms)10242026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (4.5ms)10252026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010262026/10/01 09:39:12 OK 3_commit_push.sql (4.32ms)10272026/10/01 09:39:12 goose: up to current file version: 310282026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.87ms)10292026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010302026/10/01 09:39:12 OK 2_object_stats_trigger.sql (2.89ms)10312026/10/01 09:39:12 OK 3_commit_push.sql (2.57ms)10322026/10/01 09:39:12 goose: up to current file version: 310332026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.66ms)10342026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.76ms)10352026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (5.54ms)10362026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.26ms)1037--- PASS: TestReadRedirectUsesPublicS3URL (0.38s)1038=== CONT TestTombstonedObjectOfferedWithoutWaiting10392026/10/01 09:39:12 OK 1_commit_pending_closure.sql (1.87ms)10402026/10/01 09:39:12 OK 3_commit_push.sql (1.51ms)10412026/10/01 09:39:12 goose: up to current file version: 310422026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.37ms)10432026/10/01 09:39:12 OK 1_commit_pending_closure.sql (1.96ms)10442026/10/01 09:39:12 OK 3_commit_push.sql (2.05ms)10452026/10/01 09:39:12 goose: up to current file version: 310462026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.11ms)10472026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.27ms)10482026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.88ms)10492026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.13ms)10502026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010512026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.26ms)10522026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010532026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.06ms)10542026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000010552026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.14ms)10562026/10/01 09:39:12 INFO Aborted multipart uploads count=010572026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.18ms)10582026/10/01 09:39:12 OK 3_commit_push.sql (757.47µs)10592026/10/01 09:39:12 goose: up to current file version: 310602026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.16ms)10612026/10/01 09:39:12 OK 3_commit_push.sql (1.24ms)10622026/10/01 09:39:12 goose: up to current file version: 310632026/10/01 09:39:12 OK 3_commit_push.sql (880.91µs)10642026/10/01 09:39:12 goose: up to current file version: 310652026/10/01 09:39:12 OK 1_commit_pending_closure.sql (1.83ms)10662026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.08ms)10672026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.12ms)10682026/10/01 09:39:12 OK 3_commit_push.sql (1.12ms)10692026/10/01 09:39:12 goose: up to current file version: 310702026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.16ms)10712026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.27ms)10722026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.24ms)10732026/10/01 09:39:12 WARN Force mode enabled - objects will be deleted immediately without grace period10742026/10/01 09:39:12 OK 3_commit_push.sql (978.51µs)10752026/10/01 09:39:12 goose: up to current file version: 310762026/10/01 09:39:12 OK 3_commit_push.sql (636.39µs)10772026/10/01 09:39:12 goose: up to current file version: 310782026/10/01 09:39:12 OK 3_commit_push.sql (1.08ms)10792026/10/01 09:39:12 goose: up to current file version: 310802026/10/01 09:39:12 OK 3_commit_push.sql (1.02ms)10812026/10/01 09:39:12 goose: up to current file version: 310822026/10/01 09:39:12 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=010832026/10/01 09:39:12 INFO Vacuumed table table=pending_closures10842026/10/01 09:39:12 INFO Vacuumed table table=pending_objects10852026/10/01 09:39:12 INFO Vacuumed table table=multipart_uploads10862026/10/01 09:39:12 INFO Vacuumed table table=closures10872026/10/01 09:39:12 INFO Received uploads request method=POST path=/api/pending_closures10882026/10/01 09:39:12 INFO Vacuumed table table=objects1089--- PASS: TestSweepSkipsRowsLockedByPush (0.40s)1090=== CONT TestGCSweepSkipsPendingObjects10912026/10/01 09:39:12 INFO Received uploads request method=POST path=/api/pending_closures10922026/10/01 09:39:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10932026/10/01 09:39:12 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDc1MDhiYjgtMjkyYi00MDg5LWEwNjQtYTIzNDg2ZDc1NzM4LmZhMGUxNWFkLWY3OGYtNGM4ZC1iYTI5LTFlODhiMzhlOGJiMHgxNzkwODQ3NTUyNDU2OTk5MTQx10942026/10/01 09:39:12 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10952026/10/01 09:39:12 INFO Received uploads request method=POST path=/api/pending_closures10962026/10/01 09:39:12 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDc1MDhiYjgtMjkyYi00MDg5LWEwNjQtYTIzNDg2ZDc1NzM4LmZhMGUxNWFkLWY3OGYtNGM4ZC1iYTI5LTFlODhiMzhlOGJiMHgxNzkwODQ3NTUyNDU2OTk5MTQx parts=11097--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.45s)1098=== CONT TestDeduplicatedObjectsRecordedAsPending1099--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.46s)1100=== CONT TestPushDedupSurvivesConcurrentGC1101--- PASS: TestService_Rustfstest (0.46s)1102=== CONT TestGCMetrics11032026/10/01 09:39:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11042026-10-01 09:39:12.514 UTC [490] ERROR: relation "goose_db_version" does not exist at character 3611052026-10-01 09:39:12.514 UTC [490] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1106=== RUN TestPush_RejectsBadRequests/no_objects1107=== PAUSE TestPush_RejectsBadRequests/no_objects1108=== RUN TestPush_RejectsBadRequests/bad_root1109=== PAUSE TestPush_RejectsBadRequests/bad_root1110=== RUN TestPush_RejectsBadRequests/root_not_in_objects1111=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1112=== RUN TestPush_RejectsBadRequests/no_roots1113=== PAUSE TestPush_RejectsBadRequests/no_roots1114=== CONT TestGCBugBareHashReferences11152026-10-01 09:39:12.535 UTC [491] ERROR: relation "goose_db_version" does not exist at character 3611162026-10-01 09:39:12.535 UTC [491] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11172026/10/01 09:39:12 OK 20241026095416_initial_model.sql (249.54ms)11182026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (4.69ms)11192026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.15ms)11202026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (6.1ms)11212026/10/01 09:39:12 OK 20241026095416_initial_model.sql (15.02ms)11222026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.5ms)11232026/10/01 09:39:12 OK 20260905000000_add_claims.sql (4.56ms)11242026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (78.76ms)11252026/10/01 09:39:12 INFO Starting HTTP server address=127.0.0.1:4488711262026/10/01 09:39:12 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket1282251003/001/proxy.sock11272026/10/01 09:39:12 WARN mTLS auth: subject not in bound subjects subject="CN=someone"11282026/10/01 09:39:12 INFO Shutdown signal received, draining in-flight requests timeout=10s1129--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.83s)1130=== CONT TestLeadEndsOnShutdown11312026/10/01 09:39:12 OK 20251218171726_add_pins.sql (89.07ms)11322026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (9.53ms)11332026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000011342026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.1ms)11352026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.6ms)11362026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.8ms)11372026/10/01 09:39:12 OK 3_commit_push.sql (1.25ms)11382026/10/01 09:39:12 goose: up to current file version: 311392026/10/01 09:39:12 OK 20260905000000_add_claims.sql (4.94ms)11402026-10-01 09:39:12.891 UTC [498] ERROR: relation "goose_db_version" does not exist at character 3611412026-10-01 09:39:12.891 UTC [498] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11422026-10-01 09:39:12.891 UTC [497] ERROR: relation "goose_db_version" does not exist at character 3611432026-10-01 09:39:12.891 UTC [497] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11442026-10-01 09:39:12.891 UTC [496] ERROR: relation "goose_db_version" does not exist at character 3611452026-10-01 09:39:12.891 UTC [496] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11462026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.94ms)11472026/10/01 09:39:12 INFO Received push request method=POST path=/api/pushes11482026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (4.61ms)11492026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000011502026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.05ms)11512026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.99ms)11522026/10/01 09:39:12 OK 3_commit_push.sql (1.66ms)11532026/10/01 09:39:12 goose: up to current file version: 311542026/10/01 09:39:12 OK 20241026095416_initial_model.sql (11.56ms)11552026/10/01 09:39:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11562026-10-01 09:39:12.911 UTC [499] ERROR: relation "goose_db_version" does not exist at character 3611572026-10-01 09:39:12.911 UTC [499] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11582026/10/01 09:39:12 OK 20241026095416_initial_model.sql (12.99ms)11592026/10/01 09:39:12 INFO Signed narinfos id=1 count=111602026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.98ms)1161--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.87s)1162=== CONT TestLeadElectsOneAndHandsOver11632026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (1.88ms)11642026/10/01 09:39:12 OK 20241026095416_initial_model.sql (14.96ms)11652026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.44ms)11662026/10/01 09:39:12 OK 20251218171726_add_pins.sql (3.98ms)11672026/10/01 09:39:12 OK 20251218171726_add_pins.sql (3.89ms)11682026/10/01 09:39:12 OK 20251218171726_add_pins.sql (5.04ms)11692026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.77ms)11702026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (5.56ms)11712026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.75ms)11722026/10/01 09:39:12 OK 20260905000000_add_claims.sql (4.81ms)11732026/10/01 09:39:12 OK 20260905000000_add_claims.sql (4.71ms)11742026/10/01 09:39:12 OK 20241026095416_initial_model.sql (11.59ms)11752026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.83ms)11762026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.73ms)11772026/10/01 09:39:12 OK 20260905000000_add_claims.sql (4.55ms)11782026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (3.07ms)11792026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.5ms)11802026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000011812026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (3.11ms)11822026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000011832026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (3.04ms)11842026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.57ms)11852026/10/01 09:39:12 INFO Aborted multipart uploads count=011862026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.75ms)11872026/10/01 09:39:12 OK 20251218171726_add_pins.sql (4.7ms)11882026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.91ms)11892026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.92ms)11902026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000011912026/10/01 09:39:12 OK 3_commit_push.sql (1.28ms)11922026/10/01 09:39:12 goose: up to current file version: 311932026/10/01 09:39:12 WARN Force mode enabled - objects will be deleted immediately without grace period11942026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.92ms)11952026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.55ms)11962026/10/01 09:39:12 OK 3_commit_push.sql (1.42ms)11972026/10/01 09:39:12 goose: up to current file version: 311982026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.09ms)11992026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (4.2ms)12002026/10/01 09:39:12 OK 3_commit_push.sql (1.09ms)12012026/10/01 09:39:12 goose: up to current file version: 312022026/10/01 09:39:12 INFO Received push request method=POST path=/api/pushes12032026/10/01 09:39:12 OK 20260905000000_add_claims.sql (4.21ms)12042026-10-01 09:39:12.947 UTC [503] ERROR: relation "goose_db_version" does not exist at character 3612052026-10-01 09:39:12.947 UTC [503] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12062026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (2.44ms)12072026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2.75ms)12082026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000012092026/10/01 09:39:12 OK 1_commit_pending_closure.sql (3.06ms)12102026/10/01 09:39:12 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=012112026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.64ms)12122026/10/01 09:39:12 OK 3_commit_push.sql (1.25ms)12132026/10/01 09:39:12 goose: up to current file version: 312142026/10/01 09:39:12 INFO Vacuumed table table=pending_closures12152026/10/01 09:39:12 INFO Vacuumed table table=pending_objects12162026/10/01 09:39:12 INFO Vacuumed table table=multipart_uploads12172026/10/01 09:39:12 OK 20241026095416_initial_model.sql (10.32ms)12182026/10/01 09:39:12 INFO Vacuumed table table=closures12192026/10/01 09:39:12 INFO Received complete push request method=POST path=/api/pushes/1/complete12202026/10/01 09:39:12 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)12212026/10/01 09:39:12 INFO Vacuumed table table=objects1222--- PASS: TestSweepRechecksPendingAfterLocking (0.92s)1223=== CONT TestResolveDBConnectionString1224=== RUN TestResolveDBConnectionString/flag_wins1225=== PAUSE TestResolveDBConnectionString/flag_wins1226=== RUN TestResolveDBConnectionString/file_when_flag_empty1227=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1228=== RUN TestResolveDBConnectionString/missing_file_is_an_error1229=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1230=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1231=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1232=== RUN TestResolveDBConnectionString/nothing_configured1233=== PAUSE TestResolveDBConnectionString/nothing_configured1234=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12352026/10/01 09:39:12 OK 20251218171726_add_pins.sql (3.05ms)12362026/10/01 09:39:12 OK 20260628120000_add_object_size_and_stats.sql (3.13ms)1237--- PASS: TestPush_CompleteCommitsEveryRoot (0.92s)1238=== CONT TestClientFallsBackToClosures12392026/10/01 09:39:12 OK 20260905000000_add_claims.sql (2.96ms)12402026/10/01 09:39:12 OK 20260920000000_drop_claims.sql (1.64ms)12412026/10/01 09:39:12 OK 20260923120000_add_pushes.sql (2ms)12422026/10/01 09:39:12 goose: successfully migrated database to version: 2026092312000012432026/10/01 09:39:12 OK 1_commit_pending_closure.sql (2.33ms)12442026-10-01 09:39:12.980 UTC [512] ERROR: relation "goose_db_version" does not exist at character 3612452026-10-01 09:39:12.980 UTC [512] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1246--- PASS: TestGetExistingObjectsLocksRows (0.93s)1247=== CONT TestClientPushesUseOnePush12482026/10/01 09:39:12 OK 2_object_stats_trigger.sql (1.61ms)12492026/10/01 09:39:12 OK 3_commit_push.sql (1.69ms)12502026/10/01 09:39:12 goose: up to current file version: 312512026/10/01 09:39:12 INFO Received push request method=POST path=/api/pushes12522026/10/01 09:39:12 OK 20241026095416_initial_model.sql (12.36ms)12532026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.26ms)12542026/10/01 09:39:13 OK 20251218171726_add_pins.sql (5.75ms)12552026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.5ms)12562026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures12572026/10/01 09:39:13 INFO Received complete push request method=POST path=/api/pushes/1/complete12582026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.24ms)12592026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.87ms)12602026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.43ms)12612026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000012622026/10/01 09:39:13 INFO Received push request method=POST path=/api/pushes12632026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.23ms)12642026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures12652026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.3ms)12662026/10/01 09:39:13 OK 3_commit_push.sql (1.1ms)12672026/10/01 09:39:13 goose: up to current file version: 312682026-10-01 09:39:13.035 UTC [517] ERROR: relation "goose_db_version" does not exist at character 3612692026-10-01 09:39:13.035 UTC [517] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12702026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures12712026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.84ms)12722026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.32ms)12732026/10/01 09:39:13 OK 20251218171726_add_pins.sql (2.69ms)12742026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.18ms)12752026/10/01 09:39:13 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1276--- PASS: TestService_AuthMiddleware (1.01s)1277=== CONT TestPinProtectsFromGC12782026-10-01 09:39:13.062 UTC [519] ERROR: relation "goose_db_version" does not exist at character 3612792026-10-01 09:39:13.062 UTC [519] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12802026-10-01 09:39:13.063 UTC [518] ERROR: relation "goose_db_version" does not exist at character 3612812026-10-01 09:39:13.063 UTC [518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12822026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.22ms)12832026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.5ms)12842026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.26ms)12852026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000012862026/10/01 09:39:13 OK 1_commit_pending_closure.sql (1.9ms)12872026/10/01 09:39:13 OK 2_object_stats_trigger.sql (907.23µs)12882026/10/01 09:39:13 OK 3_commit_push.sql (839.93µs)12892026/10/01 09:39:13 goose: up to current file version: 312902026/10/01 09:39:13 OK 20241026095416_initial_model.sql (11.62ms)12912026/10/01 09:39:13 OK 20241026095416_initial_model.sql (12.49ms)12922026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.65ms)12932026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)12942026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.92ms)12952026/10/01 09:39:13 INFO Aborted multipart uploads count=012962026/10/01 09:39:13 OK 20251218171726_add_pins.sql (4.27ms)1297--- PASS: TestRegisterCompletedObjectNeedsPendingRow (1.04s)1298=== CONT TestClientSharedPathCommittedMidPush12992026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period13002026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.76ms)13012026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.73ms)13022026/10/01 09:39:13 OK 20260905000000_add_claims.sql (5.08ms)13032026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.39ms)13042026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.91ms)13052026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.88ms)13062026/10/01 09:39:13 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=013072026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.69ms)13082026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013092026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.9ms)13102026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013112026/10/01 09:39:13 INFO Vacuumed table table=pending_closures13122026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.8ms)13132026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.99ms)13142026/10/01 09:39:13 INFO Vacuumed table table=pending_objects13152026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.66ms)13162026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.62ms)13172026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads13182026/10/01 09:39:13 OK 3_commit_push.sql (9.91ms)13192026/10/01 09:39:13 goose: up to current file version: 313202026/10/01 09:39:13 OK 3_commit_push.sql (10.17ms)13212026/10/01 09:39:13 goose: up to current file version: 313222026/10/01 09:39:13 INFO Vacuumed table table=closures13232026/10/01 09:39:13 INFO Vacuumed table table=objects13242026/10/01 09:39:13 INFO Received complete push request method=POST path=/api/pushes/2/complete1325--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.09s)1326=== CONT TestClientWithDependencies13272026-10-01 09:39:13.142 UTC [524] ERROR: relation "goose_db_version" does not exist at character 3613282026-10-01 09:39:13.142 UTC [524] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13292026/10/01 09:39:13 OK 20241026095416_initial_model.sql (17.06ms)13302026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (4.5ms)13312026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures13322026/10/01 09:39:13 INFO Aborted multipart uploads count=013332026-10-01 09:39:13.178 UTC [528] ERROR: relation "goose_db_version" does not exist at character 3613342026-10-01 09:39:13.178 UTC [528] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13352026/10/01 09:39:13 OK 20251218171726_add_pins.sql (5.03ms)13362026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period13372026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.43ms)13382026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.99ms)13392026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.75ms)13402026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.25ms)13412026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.02ms)13422026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013432026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.1ms)13442026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.55ms)13452026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.35ms)13462026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.12ms)13472026/10/01 09:39:13 OK 3_commit_push.sql (1.33ms)13482026/10/01 09:39:13 goose: up to current file version: 313492026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.41ms)13502026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.53ms)13512026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.09ms)13522026/10/01 09:39:13 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=013532026/10/01 09:39:13 INFO Vacuumed table table=pending_closures13542026/10/01 09:39:13 INFO Vacuumed table table=pending_objects13552026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads13562026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (4.48ms)13572026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013582026/10/01 09:39:13 INFO Vacuumed table table=closures13592026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.73ms)13602026/10/01 09:39:13 INFO Vacuumed table table=objects1361--- PASS: TestGCSweepDeliversEachKeyOnce (1.17s)1362=== CONT TestClientMultipleUploads13632026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.5ms)13642026/10/01 09:39:13 OK 3_commit_push.sql (1.31ms)13652026/10/01 09:39:13 goose: up to current file version: 313662026-10-01 09:39:13.231 UTC [533] ERROR: relation "goose_db_version" does not exist at character 3613672026-10-01 09:39:13.231 UTC [533] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13682026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures13692026/10/01 09:39:13 INFO Aborted multipart uploads count=013702026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period13712026/10/01 09:39:13 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=013722026/10/01 09:39:13 OK 20241026095416_initial_model.sql (10.5ms)13732026/10/01 09:39:13 INFO Vacuumed table table=pending_closures13742026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)13752026/10/01 09:39:13 INFO Vacuumed table table=pending_objects13762026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads13772026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.63ms)13782026/10/01 09:39:13 INFO Vacuumed table table=closures13792026/10/01 09:39:13 INFO Vacuumed table table=objects13802026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.48ms)13812026/10/01 09:39:13 INFO Aborted multipart uploads count=01382--- PASS: TestGCEndsOnShutdown (1.21s)1383=== CONT TestClientIntegration13842026/10/01 09:39:13 OK 20260905000000_add_claims.sql (5.87ms)13852026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period1386--- PASS: TestCommitRacingPendingCleanupKeepsObjects (1.21s)1387=== CONT TestClientErrorHandling1388=== RUN TestClientErrorHandling/InvalidStorePath1389=== PAUSE TestClientErrorHandling/InvalidStorePath1390=== RUN TestClientErrorHandling/InvalidAuthToken1391=== PAUSE TestClientErrorHandling/InvalidAuthToken1392=== RUN TestClientErrorHandling/ServerNotAvailable1393=== PAUSE TestClientErrorHandling/ServerNotAvailable1394=== CONT TestClientCADerivations13952026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.94ms)13962026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.58ms)13972026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000013982026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.9ms)13992026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.84ms)14002026/10/01 09:39:13 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."14012026/10/01 09:39:13 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."14022026/10/01 09:39:13 OK 3_commit_push.sql (1.58ms)14032026/10/01 09:39:13 goose: up to current file version: 31404--- PASS: TestFailedS3DeleteKeepsTombstone (1.23s)1405=== CONT TestCacheStatsHandler14062026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures14072026-10-01 09:39:13.290 UTC [543] ERROR: relation "goose_db_version" does not exist at character 3614082026-10-01 09:39:13.290 UTC [543] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14092026/10/01 09:39:13 INFO Received push request method=POST path=/api/pushes14102026/10/01 09:39:13 OK 20241026095416_initial_model.sql (14.03ms)14112026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.7ms)14122026/10/01 09:39:13 OK 20251218171726_add_pins.sql (4.72ms)14132026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (5.06ms)1414--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (1.37s)1415=== CONT TestCacheConfigHandler1416=== RUN TestCacheConfigHandler/full_config,_no_issuer1417=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1418=== RUN TestCacheConfigHandler/no_cache_url_configured1419=== PAUSE TestCacheConfigHandler/no_cache_url_configured1420=== RUN TestCacheConfigHandler/no_signing_keys1421=== PAUSE TestCacheConfigHandler/no_signing_keys1422=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1423=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1424=== CONT TestService_ReadScope_PublicByDefault14252026-10-01 09:39:13.421 UTC [546] ERROR: relation "goose_db_version" does not exist at character 3614262026-10-01 09:39:13.421 UTC [546] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14272026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.34ms)14282026-10-01 09:39:13.423 UTC [547] ERROR: relation "goose_db_version" does not exist at character 3614292026-10-01 09:39:13.423 UTC [547] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14302026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.37ms)14312026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures14322026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.18ms)14332026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000014342026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.67ms)14352026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.75ms)1436--- PASS: TestTombstonedObjectOfferedWithoutWaiting (1.01s)1437=== CONT TestService_RequireScope_OIDC14382026/10/01 09:39:13 OK 3_commit_push.sql (1.22ms)14392026/10/01 09:39:13 goose: up to current file version: 314402026/10/01 09:39:13 OK 20241026095416_initial_model.sql (12.76ms)14412026/10/01 09:39:13 OK 20241026095416_initial_model.sql (12.59ms)14422026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.22ms)14432026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.24ms)14442026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.55ms)14452026/10/01 09:39:13 OK 20251218171726_add_pins.sql (4.13ms)14462026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.86ms)14472026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.18ms)14482026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.21ms)14492026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures14502026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.75ms)14512026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.67ms)14522026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.04ms)14532026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.65ms)14542026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000014552026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.44ms)14562026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000014572026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.35ms)14582026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.81ms)14592026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.56ms)14602026/10/01 09:39:13 OK 3_commit_push.sql (1.38ms)14612026/10/01 09:39:13 goose: up to current file version: 314622026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.43ms)14632026/10/01 09:39:13 OK 3_commit_push.sql (1.25ms)14642026/10/01 09:39:13 goose: up to current file version: 314652026-10-01 09:39:13.468 UTC [550] ERROR: relation "goose_db_version" does not exist at character 3614662026-10-01 09:39:13.468 UTC [550] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14672026/10/01 09:39:13 INFO Aborted multipart uploads count=014682026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period14692026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures14702026/10/01 09:39:13 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=014712026/10/01 09:39:13 OK 20241026095416_initial_model.sql (16.02ms)14722026/10/01 09:39:13 INFO Vacuumed table table=pending_closures14732026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.61ms)14742026/10/01 09:39:13 INFO Vacuumed table table=pending_objects14752026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads14762026/10/01 09:39:13 INFO Vacuumed table table=closures1477--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.99s)1478=== CONT TestService_AuthMiddleware_OIDC14792026/10/01 09:39:13 INFO Vacuumed table table=objects14802026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.29ms)14812026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.9ms)14822026-10-01 09:39:13.502 UTC [552] ERROR: relation "goose_db_version" does not exist at character 3614832026-10-01 09:39:13.502 UTC [552] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14842026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.29ms)1485--- PASS: TestGCSweepSkipsPendingObjects (1.05s)1486=== CONT TestService_ReadAuthMiddleware14872026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.24ms)14882026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.44ms)14892026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000014902026/10/01 09:39:13 OK 1_commit_pending_closure.sql (1.89ms)14912026/10/01 09:39:13 INFO Aborted multipart uploads count=014922026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.71ms)14932026/10/01 09:39:13 OK 3_commit_push.sql (1.06ms)14942026/10/01 09:39:13 goose: up to current file version: 314952026/10/01 09:39:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14962026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period14972026/10/01 09:39:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40073/oidc14982026/10/01 09:39:13 OK 20241026095416_initial_model.sql (10.11ms)14992026/10/01 09:39:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15002026/10/01 09:39:13 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=015012026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)15022026/10/01 09:39:13 INFO Vacuumed table table=pending_closures15032026/10/01 09:39:13 INFO Vacuumed table table=pending_objects15042026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads15052026/10/01 09:39:13 INFO Vacuumed table table=closures15062026/10/01 09:39:13 INFO Vacuumed table table=objects15072026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.95ms)1508--- PASS: TestGCMetrics (1.02s)1509=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15102026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.71ms)15112026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.07ms)15122026/10/01 09:39:13 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZDc1MDhiYjgtMjkyYi00MDg5LWEwNjQtYTIzNDg2ZDc1NzM4LmMxM2I5YjU0LTBmNzMtNDIxMS1hM2U4LTFjZDRmNzY5N2E3NHgxNzkwODQ3NTUzMDQ2ODk1NTc1 parts=1215132026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures15142026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.2ms)15152026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.09ms)15162026/10/01 09:39:13 goose: successfully migrated database to version: 202609231200001517--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.49s)1518=== CONT TestService_AuthMiddleware_MTLSProxyHeader15192026/10/01 09:39:13 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZDc1MDhiYjgtMjkyYi00MDg5LWEwNjQtYTIzNDg2ZDc1NzM4LmM3OGUxN2IzLWZjYjYtNGIzMi05OGZjLWViNDM0ZjFjZGNjYngxNzkwODQ3NTUzMDIxNTQ2MDQy parts=121520--- PASS: TestRedundantMultipartUpload (1.49s)1521=== CONT TestService_NativeMTLS15222026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.56ms)15232026/10/01 09:39:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41219/oidc1524--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.55s)1525=== CONT TestParseSingleRange1526=== RUN TestParseSingleRange/none1527=== PAUSE TestParseSingleRange/none1528=== RUN TestParseSingleRange/unknown_unit1529=== PAUSE TestParseSingleRange/unknown_unit1530=== RUN TestParseSingleRange/multi-range_ignored1531=== PAUSE TestParseSingleRange/multi-range_ignored1532=== RUN TestParseSingleRange/malformed_no_dash1533=== PAUSE TestParseSingleRange/malformed_no_dash1534=== RUN TestParseSingleRange/malformed_both_empty1535=== PAUSE TestParseSingleRange/malformed_both_empty1536=== RUN TestParseSingleRange/malformed_end_before_start1537=== PAUSE TestParseSingleRange/malformed_end_before_start1538=== RUN TestParseSingleRange/closed1539=== PAUSE TestParseSingleRange/closed1540=== RUN TestParseSingleRange/open-ended1541=== PAUSE TestParseSingleRange/open-ended1542=== RUN TestParseSingleRange/end_clamped_to_size1543=== PAUSE TestParseSingleRange/end_clamped_to_size1544=== RUN TestParseSingleRange/suffix1545=== PAUSE TestParseSingleRange/suffix1546=== RUN TestParseSingleRange/suffix_exceeds_size1547=== PAUSE TestParseSingleRange/suffix_exceeds_size1548=== RUN TestParseSingleRange/single_byte1549=== PAUSE TestParseSingleRange/single_byte1550=== RUN TestParseSingleRange/start_past_EOF1551=== PAUSE TestParseSingleRange/start_past_EOF1552=== RUN TestParseSingleRange/start_far_past_EOF1553=== PAUSE TestParseSingleRange/start_far_past_EOF1554=== CONT TestPresentNotReportedWhileGCDeletesClosure15552026/10/01 09:39:13 OK 2_object_stats_trigger.sql (69.55ms)15562026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures15572026/10/01 09:39:13 OK 3_commit_push.sql (32.24ms)15582026/10/01 09:39:13 goose: up to current file version: 315592026-10-01 09:39:13.658 UTC [589] ERROR: relation "goose_db_version" does not exist at character 3615602026-10-01 09:39:13.658 UTC [589] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15612026-10-01 09:39:13.674 UTC [590] ERROR: relation "goose_db_version" does not exist at character 3615622026-10-01 09:39:13.674 UTC [590] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15632026/10/01 09:39:13 INFO lead: acquired remote=192.0.2.1:123415642026/10/01 09:39:13 INFO lead: released remote=192.0.2.1:12341565--- PASS: TestLeadEndsOnShutdown (0.80s)1566=== CONT TestPresentReportsOnlyClosureRoots15672026/10/01 09:39:13 OK 20241026095416_initial_model.sql (11.35ms)15682026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)15692026-10-01 09:39:13.686 UTC [592] ERROR: relation "goose_db_version" does not exist at character 3615702026-10-01 09:39:13.686 UTC [592] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15712026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.58ms)15722026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.8ms)15732026/10/01 09:39:13 OK 20241026095416_initial_model.sql (13.4ms)15742026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.55ms)15752026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.65ms)15762026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.69ms)15772026/10/01 09:39:13 INFO lead: acquired remote=192.0.2.1:123415782026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.35ms)15792026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.54ms)15802026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000015812026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (6.33ms)15822026/10/01 09:39:13 OK 20241026095416_initial_model.sql (13.47ms)15832026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.91ms)15842026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (6.24ms)15852026/10/01 09:39:13 OK 2_object_stats_trigger.sql (7.77ms)15862026/10/01 09:39:13 OK 20260905000000_add_claims.sql (10.93ms)15872026/10/01 09:39:13 INFO Aborted multipart uploads count=015882026/10/01 09:39:13 OK 20251218171726_add_pins.sql (8.1ms)15892026/10/01 09:39:13 OK 3_commit_push.sql (25.53ms)15902026/10/01 09:39:13 goose: up to current file version: 315912026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (26.32ms)15922026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (24.18ms)1593--- PASS: TestPushWaitsForSweepHoldingRow (1.70s)1594=== CONT TestCreatePin_ReservedPins15952026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.15ms)15962026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000015972026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.64ms)15982026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.19ms)15992026/10/01 09:39:13 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=016002026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.17ms)16012026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.47ms)16022026/10/01 09:39:13 OK 3_commit_push.sql (1.31ms)16032026/10/01 09:39:13 goose: up to current file version: 316042026/10/01 09:39:13 INFO Vacuumed table table=pending_closures16052026-10-01 09:39:13.754 UTC [596] ERROR: relation "goose_db_version" does not exist at character 3616062026-10-01 09:39:13.754 UTC [596] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16072026/10/01 09:39:13 INFO Vacuumed table table=pending_objects16082026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.55ms)16092026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000016102026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads16112026-10-01 09:39:13.756 UTC [597] ERROR: relation "goose_db_version" does not exist at character 3616122026-10-01 09:39:13.756 UTC [597] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16132026-10-01 09:39:13.756 UTC [598] ERROR: relation "goose_db_version" does not exist at character 3616142026-10-01 09:39:13.756 UTC [598] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16152026-10-01 09:39:13.757 UTC [599] ERROR: relation "goose_db_version" does not exist at character 3616162026-10-01 09:39:13.757 UTC [599] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16172026/10/01 09:39:13 OK 1_commit_pending_closure.sql (1.97ms)16182026/10/01 09:39:13 INFO Vacuumed table table=closures16192026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.46ms)16202026/10/01 09:39:13 INFO Vacuumed table table=objects16212026-10-01 09:39:13.759 UTC [600] ERROR: relation "goose_db_version" does not exist at character 3616222026-10-01 09:39:13.759 UTC [600] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16232026/10/01 09:39:13 OK 3_commit_push.sql (1.52ms)16242026/10/01 09:39:13 goose: up to current file version: 316252026/10/01 09:39:13 INFO Aborted multipart uploads count=016262026/10/01 09:39:13 WARN Force mode enabled - objects will be deleted immediately without grace period16272026/10/01 09:39:13 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=016282026/10/01 09:39:13 INFO Vacuumed table table=pending_closures16292026/10/01 09:39:13 OK 20241026095416_initial_model.sql (12.04ms)16302026/10/01 09:39:13 OK 20241026095416_initial_model.sql (12.2ms)16312026/10/01 09:39:13 INFO Vacuumed table table=pending_objects16322026/10/01 09:39:13 OK 20241026095416_initial_model.sql (11.76ms)16332026/10/01 09:39:13 INFO Vacuumed table table=multipart_uploads16342026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)16352026/10/01 09:39:13 OK 20241026095416_initial_model.sql (12.23ms)16362026/10/01 09:39:13 INFO Vacuumed table table=closures16372026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.39ms)16382026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.85ms)16392026/10/01 09:39:13 INFO Vacuumed table table=objects16402026/10/01 09:39:13 OK 20241026095416_initial_model.sql (14.58ms)16412026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (3.95ms)16422026/10/01 09:39:13 OK 20251218171726_add_pins.sql (4.4ms)1643--- PASS: TestPushDedupSurvivesConcurrentGC (1.28s)1644=== CONT TestOrphanedObjectsGCStressTest16452026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.6ms)16462026/10/01 09:39:13 OK 20251218171726_add_pins.sql (7.13ms)16472026/10/01 09:39:13 OK 20251218171726_add_pins.sql (5.69ms)16482026/10/01 09:39:13 OK 20251218171726_add_pins.sql (4.16ms)16492026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.63ms)16502026/10/01 09:39:13 OK 20251218171726_add_pins.sql (5.33ms)16512026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (5.59ms)16522026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (5.58ms)16532026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.21ms)16542026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.76ms)16552026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (4.23ms)16562026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.99ms)16572026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.04ms)16582026/10/01 09:39:13 OK 20260905000000_add_claims.sql (4.4ms)16592026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.23ms)16602026/10/01 09:39:13 OK 20260905000000_add_claims.sql (3.26ms)16612026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.34ms)16622026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000016632026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.57ms)16642026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.85ms)16652026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.65ms)16662026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (3.24ms)16672026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.38ms)16682026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.11ms)16692026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000016702026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.67ms)16712026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000016722026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (3.77ms)16732026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000016742026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.8ms)16752026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.5ms)16762026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.79ms)16772026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000016782026/10/01 09:39:13 OK 1_commit_pending_closure.sql (1.77ms)16792026/10/01 09:39:13 OK 1_commit_pending_closure.sql (2.14ms)16802026/10/01 09:39:13 OK 3_commit_push.sql (1.81ms)16812026/10/01 09:39:13 goose: up to current file version: 316822026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.73ms)16832026/10/01 09:39:13 OK 2_object_stats_trigger.sql (2.54ms)16842026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.55ms)16852026/10/01 09:39:13 OK 2_object_stats_trigger.sql (3.89ms)16862026/10/01 09:39:13 OK 3_commit_push.sql (1.82ms)16872026/10/01 09:39:13 goose: up to current file version: 316882026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.54ms)16892026/10/01 09:39:13 OK 3_commit_push.sql (1.31ms)16902026/10/01 09:39:13 goose: up to current file version: 316912026/10/01 09:39:13 OK 3_commit_push.sql (1.59ms)16922026/10/01 09:39:13 goose: up to current file version: 316932026/10/01 09:39:13 OK 3_commit_push.sql (1.13ms)16942026/10/01 09:39:13 goose: up to current file version: 316952026/10/01 09:39:13 INFO lead: released remote=192.0.2.1:123416962026-10-01 09:39:13.859 UTC [639] ERROR: relation "goose_db_version" does not exist at character 3616972026-10-01 09:39:13.859 UTC [639] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16982026/10/01 09:39:13 OK 20241026095416_initial_model.sql (9.55ms)16992026/10/01 09:39:13 OK 20251210153512_drop_unused_gin_index.sql (2.37ms)17002026/10/01 09:39:13 OK 20251218171726_add_pins.sql (3.13ms)17012026/10/01 09:39:13 OK 20260628120000_add_object_size_and_stats.sql (3.96ms)17022026/10/01 09:39:13 OK 20260905000000_add_claims.sql (5.42ms)1703--- PASS: TestGCBugBareHashReferences (1.36s)1704=== CONT TestOrphanedObjectsGC17052026/10/01 09:39:13 OK 20260920000000_drop_claims.sql (2.31ms)17062026/10/01 09:39:13 OK 20260923120000_add_pushes.sql (2.11ms)17072026/10/01 09:39:13 goose: successfully migrated database to version: 2026092312000017082026/10/01 09:39:13 OK 1_commit_pending_closure.sql (3.65ms)17092026/10/01 09:39:13 OK 2_object_stats_trigger.sql (1.53ms)17102026/10/01 09:39:13 OK 3_commit_push.sql (916.39µs)17112026/10/01 09:39:13 goose: up to current file version: 317122026/10/01 09:39:13 INFO lead: acquired remote=192.0.2.1:123417132026/10/01 09:39:13 INFO lead: released remote=192.0.2.1:12341714--- PASS: TestLeadElectsOneAndHandsOver (0.99s)1715=== CONT TestObjectStatsTrigger1716=== NAME TestPinProtectsFromGC1717 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC2716783079/001/store/nqpc9b201qxgx9xs8mr98ibb39ndwxn0-pinned-file.txt1718 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC2716783079/001/store/8jcdsrgfbmid547sgsf0nlybbba5z91c-unpinned-file.txt1719=== NAME TestClientMultipleUploads1720 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads836299880/001/store/g8sjmgxhl0lx4lkzj1a2xgmzlxlak4l5-test-file-0.txt1721=== NAME TestClientIntegration1722 client_integration_test.go:286: Created store path: /build/TestClientIntegration2968968759/002/store/v88m1cz29m4jwmvps3z2aigk7931ws0z-test-file.txt17232026-10-01 09:39:13.979 UTC [928] ERROR: relation "goose_db_version" does not exist at character 3617242026-10-01 09:39:13.979 UTC [928] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1725=== NAME TestClientWithDependencies1726 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies1152553034/001/store/x31h20vw24s566h0pd2gx9kyhvcv34nj-test-script17272026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures17282026/10/01 09:39:13 INFO Received push request method=POST path=/api/pushes1729=== NAME TestClientMultipleUploads1730 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads836299880/001/store/vj2629n59vfj165bf8dzqj0b3shbqr3w-test-file-1.txt17312026-10-01 09:39:13.991 UTC [999] ERROR: relation "goose_db_version" does not exist at character 3617322026-10-01 09:39:13.991 UTC [999] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17332026/10/01 09:39:13 INFO Received uploads request method=POST path=/api/pending_closures17342026/10/01 09:39:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17352026/10/01 09:39:13 INFO Uploading nqpc9b201qxgx9xs8mr98ibb39ndwxn0-pinned-file.txt (128B)1736--- PASS: TestCacheStatsHandler (0.72s)1737=== CONT TestMultipartCleanup17382026/10/01 09:39:13 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17392026/10/01 09:39:13 INFO Uploading qvzk9b2p4rsa75a23wvpzk7rig2wmpi4-shared-dep (136B)17402026/10/01 09:39:13 INFO Uploading d0aismkiybx2g9r9fcbzq54jzcwq52cd-a (216B)17412026/10/01 09:39:14 WARN Failed to register uploaded object key=nqpc9b201qxgx9xs8mr98ibb39ndwxn0.ls error="server returned 404: 404 page not found\n"17422026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17432026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17442026/10/01 09:39:14 INFO Signed narinfos id=1 count=117452026/10/01 09:39:14 INFO Uploading 1 narinfos17462026/10/01 09:39:14 OK 20241026095416_initial_model.sql (16.85ms)17472026/10/01 09:39:14 WARN Failed to register uploaded object key=qvzk9b2p4rsa75a23wvpzk7rig2wmpi4.ls error="server returned 404: 404 page not found\n"17482026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17492026/10/01 09:39:14 WARN Failed to register uploaded object key=vi8kib0xk3i5pv5g0vlpijpd5f5lrrx1.ls error="server returned 404: 404 page not found\n"17502026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17512026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1d80hkf6jwhrz8fb01kzsg3iy1n3vrmkqp2zglp2hkak865s2r7k.nar.zst error="server returned 404: 404 page not found\n"17522026/10/01 09:39:14 WARN Failed to register uploaded object key=d0aismkiybx2g9r9fcbzq54jzcwq52cd.ls error="server returned 404: 404 page not found\n"17532026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)17542026/10/01 09:39:14 INFO Signed narinfos id=1 count=217552026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17562026/10/01 09:39:14 INFO Signed narinfos id=2 count=217572026/10/01 09:39:14 INFO Uploading 4 narinfos17582026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.84ms)17592026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes17602026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes17612026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete17622026/10/01 09:39:14 WARN Failed to register uploaded object key=nqpc9b201qxgx9xs8mr98ibb39ndwxn0.narinfo error="server returned 404: 404 page not found\n"1763--- PASS: TestService_ReadScope_PublicByDefault (0.59s)1764=== CONT TestServerTLSConfig1765=== RUN TestServerTLSConfig/no_client_CA1766=== PAUSE TestServerTLSConfig/no_client_CA1767=== RUN TestServerTLSConfig/missing_CA_file1768=== PAUSE TestServerTLSConfig/missing_CA_file1769=== RUN TestServerTLSConfig/not_a_PEM_file1770=== PAUSE TestServerTLSConfig/not_a_PEM_file1771=== CONT TestReadProxyHead17722026/10/01 09:39:14 WARN Failed to register uploaded object key=qvzk9b2p4rsa75a23wvpzk7rig2wmpi4.narinfo error="server returned 404: 404 page not found\n"17732026/10/01 09:39:14 WARN Failed to register uploaded object key=vi8kib0xk3i5pv5g0vlpijpd5f5lrrx1.narinfo error="server returned 404: 404 page not found\n"17742026/10/01 09:39:14 WARN Failed to register uploaded object key=d0aismkiybx2g9r9fcbzq54jzcwq52cd.narinfo error="server returned 404: 404 page not found\n"17752026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (5.47ms)1776=== NAME TestClientWithDependencies1777 client_integration_test.go:615: Found 1 dependencies (including self)17782026/10/01 09:39:14 OK 20241026095416_initial_model.sql (13.34ms)17792026/10/01 09:39:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17802026/10/01 09:39:14 WARN Failed to register uploaded object key=qvzk9b2p4rsa75a23wvpzk7rig2wmpi4.narinfo error="server returned 404: 404 page not found\n"17812026/10/01 09:39:14 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17822026/10/01 09:39:14 INFO Uploading dpghjjxg2ypdgsaixbfz785kvn7gig0l-shared-dep (136B)17832026/10/01 09:39:14 INFO Uploading 16z2yifj7bkvw353zyarhbvz49wyr8nq-top (224B)17842026/10/01 09:39:14 INFO Upload complete. (75ms)17852026/10/01 09:39:14 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17862026/10/01 09:39:14 INFO Uploading 712axnhixhggmglmm97a2800krabz7gr-shared-dep (136B)17872026/10/01 09:39:14 INFO Uploading mdjzs9mkkwapk74fhiwvyg0bfnf7crq3-b (216B)17882026/10/01 09:39:14 OK 20260905000000_add_claims.sql (6.52ms)17892026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (5.76ms)17902026/10/01 09:39:14 INFO Completed upload id=117912026/10/01 09:39:14 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17922026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.66ms)17932026/10/01 09:39:14 INFO Completed upload id=217942026/10/01 09:39:14 INFO Upload complete. (84ms)17952026/10/01 09:39:14 WARN Failed to register uploaded object key=fqwa2mmxfi8r2fkyz15smrav9gkd65kp.ls error="server returned 404: 404 page not found\n"17962026/10/01 09:39:14 WARN Failed to register uploaded object key=dpghjjxg2ypdgsaixbfz785kvn7gig0l.ls error="server returned 404: 404 page not found\n"1797=== NAME TestClientMultipleUploads1798 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads836299880/001/store/5c0ym475hq63djf56g9wz9i5i5lmgx9l-test-file-2.txt1799=== NAME TestClientFallsBackToClosures1800 client_pushes_test.go:112: Retrieved narinfo from S3:1801 StorePath: /build/TestClientFallsBackToClosures997086207/001/store/qvzk9b2p4rsa75a23wvpzk7rig2wmpi4-shared-dep1802 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1803 Compression: zstd1804 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821805 NarSize: 1361806 References: 1807 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n18082026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/19836vlkd2clkyi48k89ibf2mbvfq78yrh5fr87nsmv3fl7zjnyw.nar.zst error="server returned 404: 404 page not found\n"18092026/10/01 09:39:14 OK 20251218171726_add_pins.sql (4.8ms)18102026/10/01 09:39:14 WARN Failed to register uploaded object key=712axnhixhggmglmm97a2800krabz7gr.ls error="server returned 404: 404 page not found\n"18112026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/0wwsi4klly5j49zbjaph1d7nq3ha9w33amjp0crn18xsbnc8hvvy.nar.zst error="server returned 404: 404 page not found\n"18122026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18132026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18142026/10/01 09:39:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43565/oidc18152026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.21ms)18162026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000018172026/10/01 09:39:14 WARN Failed to register uploaded object key=16z2yifj7bkvw353zyarhbvz49wyr8nq.ls error="server returned 404: 404 page not found\n"18182026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18192026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18202026/10/01 09:39:14 WARN Failed to register uploaded object key=mdjzs9mkkwapk74fhiwvyg0bfnf7crq3.ls error="server returned 404: 404 page not found\n"18212026/10/01 09:39:14 INFO Signed narinfos id=1 count=218222026/10/01 09:39:14 INFO Uploading 2 narinfos18232026/10/01 09:39:14 INFO Signed narinfos id=1 count=318242026/10/01 09:39:14 INFO Uploading 3 narinfos1825 client_pushes_test.go:112: Retrieved narinfo from S3:1826 StorePath: /build/TestClientFallsBackToClosures997086207/001/store/d0aismkiybx2g9r9fcbzq54jzcwq52cd-a1827 URL: nar/1d80hkf6jwhrz8fb01kzsg3iy1n3vrmkqp2zglp2hkak865s2r7k.nar.zst1828 Compression: zstd18292026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3ms)1830 NarHash: sha256:1d80hkf6jwhrz8fb01kzsg3iy1n3vrmkqp2zglp2hkak865s2r7k1831 NarSize: 2161832 References: /build/TestClientFallsBackToClosures997086207/001/store/qvzk9b2p4rsa75a23wvpzk7rig2wmpi4-shared-dep1833 CA: text:sha256:1d28z85q3lsyfdym5b5ikv1wn8zfs28hjhi9jpnyimmbb9njq1y718342026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.57ms)18352026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.03ms)18362026/10/01 09:39:14 WARN Failed to register uploaded object key=dpghjjxg2ypdgsaixbfz785kvn7gig0l.narinfo error="server returned 404: 404 page not found\n"18372026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete18382026/10/01 09:39:14 WARN Failed to register uploaded object key=16z2yifj7bkvw353zyarhbvz49wyr8nq.narinfo error="server returned 404: 404 page not found\n"18392026/10/01 09:39:14 OK 3_commit_push.sql (2.3ms)18402026/10/01 09:39:14 goose: up to current file version: 31841 client_pushes_test.go:112: Retrieved narinfo from S3:18422026/10/01 09:39:14 WARN Failed to register uploaded object key=mdjzs9mkkwapk74fhiwvyg0bfnf7crq3.narinfo error="server returned 404: 404 page not found\n"1843 StorePath: /build/TestClientFallsBackToClosures997086207/001/store/vi8kib0xk3i5pv5g0vlpijpd5f5lrrx1-b18442026/10/01 09:39:14 WARN Failed to register uploaded object key=fqwa2mmxfi8r2fkyz15smrav9gkd65kp.narinfo error="server returned 404: 404 page not found\n"1845 URL: nar/1d80hkf6jwhrz8fb01kzsg3iy1n3vrmkqp2zglp2hkak865s2r7k.nar.zst1846 Compression: zstd1847 NarHash: sha256:1d80hkf6jwhrz8fb01kzsg3iy1n3vrmkqp2zglp2hkak865s2r7k18482026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete1849 NarSize: 2161850 References: /build/TestClientFallsBackToClosures997086207/001/store/qvzk9b2p4rsa75a23wvpzk7rig2wmpi4-shared-dep1851 CA: text:sha256:1d28z85q3lsyfdym5b5ikv1wn8zfs28hjhi9jpnyimmbb9njq1y718522026/10/01 09:39:14 WARN Failed to register uploaded object key=712axnhixhggmglmm97a2800krabz7gr.narinfo error="server returned 404: 404 page not found\n"18532026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.92ms)18542026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.82ms)1855--- PASS: TestClientFallsBackToClosures (1.07s)1856=== CONT TestReadProxyRangeRequest1857--- PASS: TestService_ReadAuthMiddleware (0.54s)1858=== CONT TestGenerateLandingPage1859--- PASS: TestGenerateLandingPage (0.00s)18602026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (4.76ms)1861=== CONT TestReadRedirectKeepsNarinfoProxied18622026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000018632026/10/01 09:39:14 INFO Upload complete. (75ms)18642026/10/01 09:39:14 INFO Upload complete. (76ms)1865=== NAME TestClientPushesUseOnePush1866 client_pushes_test.go:97: Retrieved narinfo from S3:1867 StorePath: /build/TestClientPushesUseOnePush2656703302/001/store/712axnhixhggmglmm97a2800krabz7gr-shared-dep1868 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1869 Compression: zstd1870 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821871 NarSize: 1361872 References: 18732026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.68ms)1874 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1875=== NAME TestClientSharedPathCommittedMidPush1876 client_integration_test.go:680: Retrieved narinfo from S3:1877 StorePath: /build/TestClientSharedPathCommittedMidPush1159132533/001/store/dpghjjxg2ypdgsaixbfz785kvn7gig0l-shared-dep1878 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1879 Compression: zstd1880 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821881 NarSize: 1361882 References: 1883 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n18842026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.66ms)1885=== NAME TestClientCADerivations1886 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2477090188/001/store/3bjxzcq4l6881yhyy6zbjallw8cjl75g-ca-test18872026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes1888=== NAME TestClientSharedPathCommittedMidPush1889 client_integration_test.go:680: Retrieved narinfo from S3:1890 StorePath: /build/TestClientSharedPathCommittedMidPush1159132533/001/store/16z2yifj7bkvw353zyarhbvz49wyr8nq-top1891 URL: nar/0wwsi4klly5j49zbjaph1d7nq3ha9w33amjp0crn18xsbnc8hvvy.nar.zst1892 Compression: zstd1893 NarHash: sha256:0wwsi4klly5j49zbjaph1d7nq3ha9w33amjp0crn18xsbnc8hvvy1894 NarSize: 2241895 References: /build/TestClientSharedPathCommittedMidPush1159132533/001/store/dpghjjxg2ypdgsaixbfz785kvn7gig0l-shared-dep18962026/10/01 09:39:14 OK 3_commit_push.sql (1.64ms)1897 CA: text:sha256:1wb70q1qrhbfj5m654xn8vfvdx52r27ldzhqi0mq0355a6cmlrdx18982026/10/01 09:39:14 goose: up to current file version: 31899=== NAME TestClientPushesUseOnePush1900 client_pushes_test.go:97: Retrieved narinfo from S3:1901 StorePath: /build/TestClientPushesUseOnePush2656703302/001/store/fqwa2mmxfi8r2fkyz15smrav9gkd65kp-a1902 URL: nar/19836vlkd2clkyi48k89ibf2mbvfq78yrh5fr87nsmv3fl7zjnyw.nar.zst1903 Compression: zstd1904 NarHash: sha256:19836vlkd2clkyi48k89ibf2mbvfq78yrh5fr87nsmv3fl7zjnyw1905 NarSize: 2161906 References: /build/TestClientPushesUseOnePush2656703302/001/store/712axnhixhggmglmm97a2800krabz7gr-shared-dep1907 CA: text:sha256:0mmhnh72lvwqyfzmhvkrrv1i0zy74isnla4gbnam05yvcc92wp0f1908 client_pushes_test.go:97: Retrieved narinfo from S3:1909 StorePath: /build/TestClientPushesUseOnePush2656703302/001/store/mdjzs9mkkwapk74fhiwvyg0bfnf7crq3-b1910 URL: nar/19836vlkd2clkyi48k89ibf2mbvfq78yrh5fr87nsmv3fl7zjnyw.nar.zst1911 Compression: zstd1912 NarHash: sha256:19836vlkd2clkyi48k89ibf2mbvfq78yrh5fr87nsmv3fl7zjnyw1913 NarSize: 2161914 References: /build/TestClientPushesUseOnePush2656703302/001/store/712axnhixhggmglmm97a2800krabz7gr-shared-dep19152026/10/01 09:39:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1916 CA: text:sha256:0mmhnh72lvwqyfzmhvkrrv1i0zy74isnla4gbnam05yvcc92wp0f1917--- PASS: TestClientSharedPathCommittedMidPush (0.97s)19182026/10/01 09:39:14 INFO Uploading v88m1cz29m4jwmvps3z2aigk7931ws0z-test-file.txt (152B)1919=== CONT TestMetricsInventory1920--- PASS: TestClientPushesUseOnePush (1.08s)1921=== CONT TestReadRedirectNar19222026/10/01 09:39:14 WARN Failed to register uploaded object key=v88m1cz29m4jwmvps3z2aigk7931ws0z.ls error="server returned 404: 404 page not found\n"19232026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19242026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19252026/10/01 09:39:14 INFO Signed narinfos id=1 count=119262026/10/01 09:39:14 INFO Uploading 1 narinfos19272026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete19282026/10/01 09:39:14 WARN Failed to register uploaded object key=v88m1cz29m4jwmvps3z2aigk7931ws0z.narinfo error="server returned 404: 404 page not found\n"1929=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1930=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1931=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1932=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1933=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1934=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1935=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1936=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1937=== CONT TestNARDeduplicationMetadataUploadBug19382026-10-01 09:39:14.080 UTC [1201] ERROR: relation "goose_db_version" does not exist at character 3619392026-10-01 09:39:14.080 UTC [1201] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19402026/10/01 09:39:14 INFO Upload complete. (71ms)1941=== NAME TestClientCADerivations1942 client_ca_test.go:139: Found 1 dependencies (including self)19432026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes19442026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes19452026/10/01 09:39:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19462026/10/01 09:39:14 INFO Uploading 8jcdsrgfbmid547sgsf0nlybbba5z91c-unpinned-file.txt (128B)19472026/10/01 09:39:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19482026/10/01 09:39:14 INFO Uploading x31h20vw24s566h0pd2gx9kyhvcv34nj-test-script (136B)19492026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"19502026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19512026/10/01 09:39:14 WARN Failed to register uploaded object key=8jcdsrgfbmid547sgsf0nlybbba5z91c.ls error="server returned 404: 404 page not found\n"19522026/10/01 09:39:14 INFO Signed narinfos id=2 count=119532026/10/01 09:39:14 INFO Uploading 1 narinfos19542026/10/01 09:39:14 WARN Failed to register uploaded object key=x31h20vw24s566h0pd2gx9kyhvcv34nj.ls error="server returned 404: 404 page not found\n"19552026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"19562026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes19572026/10/01 09:39:14 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19582026/10/01 09:39:14 WARN mTLS auth: bound subjects configured but subject DN unavailable19592026/10/01 09:39:14 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1960--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.58s)1961=== CONT TestReadProxyDisabled19622026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19632026/10/01 09:39:14 WARN Failed to register uploaded object key=log/a6ymj00clayakq2zqlwk7wl0wg38jc00-test-script.drv error="server returned 404: 404 page not found\n"19642026/10/01 09:39:14 OK 20241026095416_initial_model.sql (15.63ms)19652026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/2/complete19662026/10/01 09:39:14 INFO Signed narinfos id=1 count=119672026/10/01 09:39:14 WARN Failed to register uploaded object key=8jcdsrgfbmid547sgsf0nlybbba5z91c.narinfo error="server returned 404: 404 page not found\n"19682026/10/01 09:39:14 INFO Uploading 1 narinfos19692026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (3.28ms)19702026/10/01 09:39:14 INFO Upload complete. (55ms)19712026/10/01 09:39:14 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19722026/10/01 09:39:14 INFO Uploading g8sjmgxhl0lx4lkzj1a2xgmzlxlak4l5-test-file-0.txt (160B)19732026/10/01 09:39:14 INFO Uploading vj2629n59vfj165bf8dzqj0b3shbqr3w-test-file-1.txt (160B)19742026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete19752026/10/01 09:39:14 INFO Uploading 5c0ym475hq63djf56g9wz9i5i5lmgx9l-test-file-2.txt (160B)19762026/10/01 09:39:14 WARN Failed to register uploaded object key=x31h20vw24s566h0pd2gx9kyhvcv34nj.narinfo error="server returned 404: 404 page not found\n"19772026-10-01 09:39:14.111 UTC [1276] ERROR: relation "goose_db_version" does not exist at character 3619782026-10-01 09:39:14.111 UTC [1276] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19792026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19802026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19812026/10/01 09:39:14 WARN Failed to register uploaded object key=g8sjmgxhl0lx4lkzj1a2xgmzlxlak4l5.ls error="server returned 404: 404 page not found\n"19822026/10/01 09:39:14 WARN Failed to register uploaded object key=5c0ym475hq63djf56g9wz9i5i5lmgx9l.ls error="server returned 404: 404 page not found\n"19832026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19842026/10/01 09:39:14 WARN Failed to register uploaded object key=vj2629n59vfj165bf8dzqj0b3shbqr3w.ls error="server returned 404: 404 page not found\n"19852026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19862026/10/01 09:39:14 INFO Signed narinfos id=1 count=319872026/10/01 09:39:14 INFO Uploading 3 narinfos19882026/10/01 09:39:14 OK 20251218171726_add_pins.sql (12.56ms)19892026/10/01 09:39:14 WARN Failed to register uploaded object key=5c0ym475hq63djf56g9wz9i5i5lmgx9l.narinfo error="server returned 404: 404 page not found\n"19902026/10/01 09:39:14 WARN Failed to register uploaded object key=g8sjmgxhl0lx4lkzj1a2xgmzlxlak4l5.narinfo error="server returned 404: 404 page not found\n"19912026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete19922026/10/01 09:39:14 WARN Failed to register uploaded object key=vj2629n59vfj165bf8dzqj0b3shbqr3w.narinfo error="server returned 404: 404 page not found\n"19932026/10/01 09:39:14 INFO Upload complete. (72ms)19942026/10/01 09:39:14 INFO All 1 paths already cached1995=== NAME TestClientIntegration1996 client_integration_test.go:312: Retrieved narinfo from S3:1997 StorePath: /build/TestClientIntegration2968968759/002/store/v88m1cz29m4jwmvps3z2aigk7931ws0z-test-file.txt1998 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1999 Compression: zstd2000 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12001 NarSize: 1522002 References: 2003 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk120042026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.68ms)2005=== NAME TestClientWithDependencies2006 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1152553034/001/store) requires matching store prefix2007=== NAME TestClientIntegration2008 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2009 client_integration_test.go:313: Decompressed .ls content (64 bytes):2010 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2011 client_integration_test.go:316: Testing garbage collection...2012--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.59s)2013=== CONT TestCreatePendingClosureRejectsOversizedNAR20142026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures2015--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2016=== CONT TestReadProxyRootRedirectsToIndexHTML2017--- PASS: TestClientWithDependencies (0.99s)2018=== CONT TestCacheConfigHandlerMaxNarSize2019--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)2020=== CONT TestReadProxyConditionalGet20212026-10-01 09:39:14.129 UTC [1313] ERROR: relation "goose_db_version" does not exist at character 3620222026-10-01 09:39:14.129 UTC [1313] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20232026/10/01 09:39:14 INFO Upload complete. (70ms)2024=== NAME TestClientMultipleUploads2025 client_integration_test.go:369: Uploaded 3 paths in 103.647335ms20262026/10/01 09:39:14 OK 20260905000000_add_claims.sql (5.72ms)20272026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.28ms)20282026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.41ms)20292026-10-01 09:39:14.136 UTC [1318] ERROR: relation "goose_db_version" does not exist at character 3620302026-10-01 09:39:14.136 UTC [1318] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20312026-10-01 09:39:14.137 UTC [1319] ERROR: relation "goose_db_version" does not exist at character 3620322026-10-01 09:39:14.137 UTC [1319] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20332026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.9ms)20342026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.52ms)20352026/10/01 09:39:14 goose: successfully migrated database to version: 202609231200002036--- PASS: TestClientMultipleUploads (0.92s)2037=== CONT TestReadProxyNarStreaming20382026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.91ms)20392026/10/01 09:39:14 OK 20251218171726_add_pins.sql (4.67ms)20402026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.06ms)20412026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.44ms)20422026/10/01 09:39:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures20432026/10/01 09:39:14 INFO Garbage collection started20442026/10/01 09:39:14 OK 3_commit_push.sql (3.81ms)20452026/10/01 09:39:14 goose: up to current file version: 320462026/10/01 09:39:14 OK 20241026095416_initial_model.sql (13.29ms)20472026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.37ms)20482026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.98ms)20492026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.69ms)20502026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.6ms)20512026/10/01 09:39:14 OK 20251218171726_add_pins.sql (4.34ms)20522026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.07ms)20532026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000020542026/10/01 09:39:14 OK 20241026095416_initial_model.sql (14.16ms)20552026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.98ms)20562026/10/01 09:39:14 INFO Aborted multipart uploads count=020572026-10-01 09:39:14.160 UTC [1342] ERROR: relation "goose_db_version" does not exist at character 3620582026-10-01 09:39:14.160 UTC [1342] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20592026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)20602026/10/01 09:39:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures20612026/10/01 09:39:14 INFO Garbage collection started20622026-10-01 09:39:14.163 UTC [1378] ERROR: relation "goose_db_version" does not exist at character 3620632026-10-01 09:39:14.163 UTC [1378] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20642026-10-01 09:39:14.164 UTC [1379] ERROR: relation "goose_db_version" does not exist at character 3620652026-10-01 09:39:14.164 UTC [1379] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20662026/10/01 09:39:14 OK 1_commit_pending_closure.sql (10.96ms)20672026/10/01 09:39:14 INFO Aborted multipart uploads count=020682026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period20692026/10/01 09:39:14 OK 20251218171726_add_pins.sql (13.05ms)2070--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.20s)20712026/10/01 09:39:14 OK 20251218171726_add_pins.sql (10.63ms)2072=== CONT TestGCTaskStore_Fail2073--- PASS: TestGCTaskStore_Fail (0.00s)2074=== CONT TestReadProxyInvalidPath20752026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (14.48ms)20762026/10/01 09:39:14 OK 2_object_stats_trigger.sql (3.61ms)20772026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period20782026/10/01 09:39:14 OK 3_commit_push.sql (2.23ms)20792026/10/01 09:39:14 goose: up to current file version: 320802026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.36ms)20812026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (5.39ms)20822026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (5.52ms)20832026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (4.35ms)20842026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.24ms)20852026/10/01 09:39:14 OK 20260905000000_add_claims.sql (5.07ms)20862026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.15ms)20872026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000020882026/10/01 09:39:14 OK 20241026095416_initial_model.sql (12.63ms)20892026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (4.32ms)20902026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.21ms)20912026/10/01 09:39:14 OK 20241026095416_initial_model.sql (13.62ms)20922026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (4.9ms)20932026/10/01 09:39:14 OK 20241026095416_initial_model.sql (15.56ms)20942026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.98ms)20952026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.15ms)20962026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000020972026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.92ms)20982026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.18ms)20992026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.48ms)21002026/10/01 09:39:14 OK 3_commit_push.sql (1.66ms)21012026/10/01 09:39:14 goose: up to current file version: 321022026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.67ms)21032026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000021042026/10/01 09:39:14 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=021052026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.8ms)21062026/10/01 09:39:14 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=021072026/10/01 09:39:14 OK 20251218171726_add_pins.sql (5.45ms)21082026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.32ms)21092026/10/01 09:39:14 OK 20251218171726_add_pins.sql (5ms)21102026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes21112026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.24ms)21122026/10/01 09:39:14 OK 20251218171726_add_pins.sql (5ms)21132026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.68ms)21142026/10/01 09:39:14 OK 3_commit_push.sql (1.91ms)21152026/10/01 09:39:14 goose: up to current file version: 321162026/10/01 09:39:14 INFO Vacuumed table table=pending_closures21172026/10/01 09:39:14 INFO Vacuumed table table=pending_closures21182026-10-01 09:39:14.199 UTC [1402] ERROR: relation "goose_db_version" does not exist at character 3621192026-10-01 09:39:14.199 UTC [1402] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21202026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (5.55ms)21212026/10/01 09:39:14 OK 3_commit_push.sql (3.84ms)21222026/10/01 09:39:14 goose: up to current file version: 321232026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (6.53ms)21242026/10/01 09:39:14 INFO Vacuumed table table=pending_objects21252026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (7.28ms)21262026/10/01 09:39:14 INFO Vacuumed table table=pending_objects21272026/10/01 09:39:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21282026/10/01 09:39:14 INFO Uploading 3bjxzcq4l6881yhyy6zbjallw8cjl75g-ca-test (144B)21292026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads21302026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads2131=== RUN TestService_RequireScope_OIDC/builder_may_write2132=== PAUSE TestService_RequireScope_OIDC/builder_may_write2133=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2134=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2135=== RUN TestService_RequireScope_OIDC/ops_may_admin2136=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2137=== RUN TestService_RequireScope_OIDC/ops_may_not_write2138=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2139=== RUN TestService_RequireScope_OIDC/reader_may_not_write2140=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2141=== RUN TestService_RequireScope_OIDC/static_token_may_admin2142=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2143=== RUN TestService_RequireScope_OIDC/static_token_may_write2144=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2145=== RUN TestService_RequireScope_OIDC/reader_may_read2146=== PAUSE TestService_RequireScope_OIDC/reader_may_read2147=== RUN TestService_RequireScope_OIDC/writer_implies_read2148=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2149=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2150=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2151=== CONT TestGCTaskStore_PhaseUpdates2152--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)2153=== CONT TestReadProxy40421542026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.19ms)21552026/10/01 09:39:14 OK 20260905000000_add_claims.sql (7.03ms)21562026/10/01 09:39:14 INFO Vacuumed table table=closures21572026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.14ms)21582026/10/01 09:39:14 INFO Vacuumed table table=objects21592026/10/01 09:39:14 INFO Vacuumed table table=closures21602026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.29ms)21612026/10/01 09:39:14 WARN Failed to register uploaded object key=log/c9r57sm6bj30p8s00jd79kza4fr2k8gk-ca-test.drv error="server returned 404: 404 page not found\n"21622026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21632026/10/01 09:39:14 WARN Failed to register uploaded object key=3bjxzcq4l6881yhyy6zbjallw8cjl75g.ls error="server returned 404: 404 page not found\n"21642026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"21652026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.91ms)21662026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.54ms)21672026/10/01 09:39:14 INFO Signed narinfos id=1 count=121682026/10/01 09:39:14 INFO Uploading 1 narinfos21692026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.87ms)21702026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000021712026/10/01 09:39:14 INFO Vacuumed table table=objects21722026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.53ms)21732026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000021742026/10/01 09:39:14 WARN mTLS auth: subject not in bound subjects subject="CN=reader"21752026/10/01 09:39:14 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2176--- PASS: TestService_NativeMTLS (0.67s)2177=== CONT TestService_cleanupPendingClosuresHandler21782026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (3.18ms)21792026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000021802026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.82ms)21812026-10-01 09:39:14.214 UTC [1404] ERROR: relation "goose_db_version" does not exist at character 3621822026-10-01 09:39:14.214 UTC [1404] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21832026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete21842026/10/01 09:39:14 WARN Failed to register uploaded object key=3bjxzcq4l6881yhyy6zbjallw8cjl75g.narinfo error="server returned 404: 404 page not found\n"21852026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.31ms)21862026/10/01 09:39:14 OK 1_commit_pending_closure.sql (1.96ms)21872026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.44ms)21882026/10/01 09:39:14 OK 3_commit_push.sql (1.28ms)21892026/10/01 09:39:14 goose: up to current file version: 321902026-10-01 09:39:14.218 UTC [1406] ERROR: relation "goose_db_version" does not exist at character 3621912026-10-01 09:39:14.218 UTC [1406] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21922026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.36ms)21932026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.21ms)21942026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.96ms)21952026/10/01 09:39:14 OK 3_commit_push.sql (1.08ms)21962026/10/01 09:39:14 goose: up to current file version: 321972026/10/01 09:39:14 OK 3_commit_push.sql (8.09ms)21982026/10/01 09:39:14 goose: up to current file version: 321992026-10-01 09:39:14.226 UTC [1409] ERROR: relation "goose_db_version" does not exist at character 3622002026-10-01 09:39:14.226 UTC [1409] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22012026/10/01 09:39:14 INFO Upload complete. (110ms)22022026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (9.64ms)2203=== NAME TestClientCADerivations2204 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2477090188/001/store/3bjxzcq4l6881yhyy6zbjallw8cjl75g-ca-test2205 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2206 Compression: zstd2207 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2208 NarSize: 1442209 References: 2210 Deriver: /build/TestClientCADerivations2477090188/001/store/c9r57sm6bj30p8s00jd79kza4fr2k8gk-ca-test.drv2211 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2212 client_ca_test.go:185: Checking for realisation files in S3...22132026/10/01 09:39:14 OK 20251218171726_add_pins.sql (4.56ms)2214 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2215 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache22162026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.69ms)22172026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.14ms)22182026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.78ms)22192026/10/01 09:39:14 OK 20241026095416_initial_model.sql (13.04ms)22202026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)22212026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.5ms)22222026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.71ms)22232026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (3.85ms)22242026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (5.52ms)22252026/10/01 09:39:14 OK 20251218171726_add_pins.sql (5.15ms)22262026/10/01 09:39:14 OK 20251218171726_add_pins.sql (4.91ms)22272026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.97ms)22282026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000022292026/10/01 09:39:14 OK 20251218171726_add_pins.sql (4.42ms)22302026-10-01 09:39:14.252 UTC [1411] ERROR: relation "goose_db_version" does not exist at character 3622312026-10-01 09:39:14.252 UTC [1411] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22322026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (5.18ms)22332026/10/01 09:39:14 OK 1_commit_pending_closure.sql (4.93ms)2234--- PASS: TestPresentReportsOnlyClosureRoots (0.58s)2235=== CONT TestUploadHandlersRejectInvalidKeys2236=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info2237=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info2238=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal2239=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal2240=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key2241=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key2242=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key2243=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key2244=== CONT TestUploadHandlersRejectOversizedBody22452026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (7.14ms)22462026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.05ms)22472026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (5.86ms)22482026/10/01 09:39:14 OK 20260905000000_add_claims.sql (5.02ms)22492026/10/01 09:39:14 OK 3_commit_push.sql (1.77ms)22502026/10/01 09:39:14 goose: up to current file version: 322512026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.87ms)22522026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.09ms)22532026/10/01 09:39:14 OK 20260905000000_add_claims.sql (6.35ms)22542026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (4.19ms)22552026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000022562026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (5.79ms)22572026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.73ms)22582026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.63ms)22592026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.71ms)22602026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000022612026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.92ms)22622026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.35ms)22632026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.75ms)22642026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000022652026/10/01 09:39:14 OK 3_commit_push.sql (1.44ms)22662026/10/01 09:39:14 goose: up to current file version: 322672026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.79ms)22682026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.4ms)22692026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.43ms)22702026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.62ms)22712026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.37ms)22722026/10/01 09:39:14 OK 3_commit_push.sql (1.19ms)22732026/10/01 09:39:14 goose: up to current file version: 322742026/10/01 09:39:14 OK 3_commit_push.sql (723.19µs)22752026/10/01 09:39:14 goose: up to current file version: 322762026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.95ms)22772026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.57ms)22782026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.55ms)22792026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.04ms)22802026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.45ms)22812026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000022822026-10-01 09:39:14.289 UTC [1430] ERROR: relation "goose_db_version" does not exist at character 3622832026-10-01 09:39:14.289 UTC [1430] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22842026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.29ms)22852026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.21ms)22862026/10/01 09:39:14 OK 3_commit_push.sql (794.09µs)22872026/10/01 09:39:14 goose: up to current file version: 322882026-10-01 09:39:14.303 UTC [1431] ERROR: relation "goose_db_version" does not exist at character 3622892026-10-01 09:39:14.303 UTC [1431] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22902026/10/01 09:39:14 OK 20241026095416_initial_model.sql (9.13ms)22912026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)22922026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.77ms)22932026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (5.65ms)22942026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.63ms)22952026/10/01 09:39:14 OK 20241026095416_initial_model.sql (9.52ms)22962026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.38ms)22972026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.75ms)22982026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.57ms)22992026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000023002026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.89ms)2301=== NAME TestClientCADerivations2302 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2303 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2304 error: binary cache 's3://bucket43?endpoint=http://localhost:46591®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2477090188/001/store'2305 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 123062026/10/01 09:39:14 OK 1_commit_pending_closure.sql (1.79ms)23072026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.06ms)2308--- PASS: TestObjectStatsTrigger (0.42s)2309=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT23102026/10/01 09:39:14 OK 3_commit_push.sql (708.45µs)23112026/10/01 09:39:14 goose: up to current file version: 323122026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.1ms)2313--- PASS: TestClientCADerivations (1.06s)2314=== CONT TestIsValidUploadKey2315=== RUN TestIsValidUploadKey/narinfo2316=== PAUSE TestIsValidUploadKey/narinfo2317=== RUN TestIsValidUploadKey/nar_zst2318=== PAUSE TestIsValidUploadKey/nar_zst2319=== RUN TestIsValidUploadKey/nar_xz2320=== PAUSE TestIsValidUploadKey/nar_xz2321=== RUN TestIsValidUploadKey/nar_plain2322=== PAUSE TestIsValidUploadKey/nar_plain2323=== RUN TestIsValidUploadKey/listing2324=== PAUSE TestIsValidUploadKey/listing2325=== RUN TestIsValidUploadKey/build_log2326=== PAUSE TestIsValidUploadKey/build_log2327=== RUN TestIsValidUploadKey/build_log_home-manager_file2328=== PAUSE TestIsValidUploadKey/build_log_home-manager_file2329=== RUN TestIsValidUploadKey/build_log_plus_in_name2330=== PAUSE TestIsValidUploadKey/build_log_plus_in_name2331=== RUN TestIsValidUploadKey/build_log_question_mark2332=== PAUSE TestIsValidUploadKey/build_log_question_mark2333=== RUN TestIsValidUploadKey/build_log_equals2334=== PAUSE TestIsValidUploadKey/build_log_equals2335=== RUN TestIsValidUploadKey/realisation2336=== PAUSE TestIsValidUploadKey/realisation2337=== RUN TestIsValidUploadKey/realisation_plus_in_output2338=== PAUSE TestIsValidUploadKey/realisation_plus_in_output2339=== RUN TestIsValidUploadKey/nix-cache-info2340=== PAUSE TestIsValidUploadKey/nix-cache-info2341=== RUN TestIsValidUploadKey/index.html2342=== PAUSE TestIsValidUploadKey/index.html2343=== RUN TestIsValidUploadKey/narinfo_key,_nar_type2344=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type2345=== RUN TestIsValidUploadKey/nar_key,_narinfo_type2346=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type2347=== RUN TestIsValidUploadKey/listing_key,_narinfo_type2348=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type2349=== RUN TestIsValidUploadKey/traversal2350=== PAUSE TestIsValidUploadKey/traversal2351=== RUN TestIsValidUploadKey/traversal_nar2352=== PAUSE TestIsValidUploadKey/traversal_nar2353=== RUN TestIsValidUploadKey/absolute2354=== PAUSE TestIsValidUploadKey/absolute2355=== RUN TestIsValidUploadKey/empty_key2356=== PAUSE TestIsValidUploadKey/empty_key2357=== RUN TestIsValidUploadKey/unknown_type2358=== PAUSE TestIsValidUploadKey/unknown_type2359=== CONT TestCompleteMultipartUnregistered23602026/10/01 09:39:14 OK 20260905000000_add_claims.sql (2.8ms)23612026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.03ms)23622026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures23632026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.88ms)23642026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000023652026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.52ms)23662026/10/01 09:39:14 OK 2_object_stats_trigger.sql (4.66ms)23672026/10/01 09:39:14 OK 3_commit_push.sql (982.41µs)23682026/10/01 09:39:14 goose: up to current file version: 32369--- PASS: TestReadProxyHead (0.35s)2370=== CONT TestService_verifyS3Integrity2371=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure2372=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure2373=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart2374=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart2375=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts2376=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts2377=== CONT TestReadProxyNarinfo23782026/10/01 09:39:14 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux23792026/10/01 09:39:14 WARN Refused reserved pin name=worker-x86_64-linux23802026/10/01 09:39:14 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux23812026/10/01 09:39:14 INFO Received create pin request method=POST path=/api/pins/my-app23822026/10/01 09:39:14 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux2383--- PASS: TestCreatePin_ReservedPins (0.65s)2384=== CONT TestService_createPendingClosureHandler2385--- PASS: TestReadRedirectKeepsNarinfoProxied (0.37s)2386=== CONT TestReadProxyNarinfoAlreadyDecompressed23872026-10-01 09:39:14.416 UTC [1539] ERROR: relation "goose_db_version" does not exist at character 3623882026-10-01 09:39:14.416 UTC [1539] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23892026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.87ms)23902026-10-01 09:39:14.438 UTC [1542] ERROR: relation "goose_db_version" does not exist at character 3623912026-10-01 09:39:14.438 UTC [1542] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23922026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.71ms)23932026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.85ms)2394--- PASS: TestReadProxyRangeRequest (0.40s)2395=== CONT TestProxyWriteTimeout2396=== RUN TestProxyWriteTimeout/narinfo2397=== PAUSE TestProxyWriteTimeout/narinfo2398=== RUN TestProxyWriteTimeout/1_GiB_nar2399=== PAUSE TestProxyWriteTimeout/1_GiB_nar2400=== RUN TestProxyWriteTimeout/10_GiB_nar2401=== PAUSE TestProxyWriteTimeout/10_GiB_nar2402=== RUN TestProxyWriteTimeout/unknown_size2403=== PAUSE TestProxyWriteTimeout/unknown_size2404=== CONT TestService_healthCheckHandler24052026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (8.79ms)24062026/10/01 09:39:14 INFO Received cleanup request method=DELETE path=/api/pending_closures24072026/10/01 09:39:14 INFO Aborted multipart uploads count=124082026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.51ms)24092026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.66ms)24102026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.18ms)24112026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.38ms)24122026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000024132026-10-01 09:39:14.462 UTC [1545] ERROR: relation "goose_db_version" does not exist at character 3624142026-10-01 09:39:14.462 UTC [1545] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24152026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (3.56ms)2416--- PASS: TestMultipartCleanup (0.47s)2417=== CONT TestService_readinessHandler24182026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.82ms)24192026-10-01 09:39:14.466 UTC [1546] ERROR: relation "goose_db_version" does not exist at character 3624202026-10-01 09:39:14.466 UTC [1546] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24212026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.95ms)24222026/10/01 09:39:14 OK 3_commit_push.sql (2.74ms)24232026/10/01 09:39:14 goose: up to current file version: 324242026/10/01 09:39:14 OK 20251218171726_add_pins.sql (6.25ms)24252026-10-01 09:39:14.473 UTC [1549] ERROR: relation "goose_db_version" does not exist at character 3624262026-10-01 09:39:14.473 UTC [1549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24272026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.78ms)24282026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.93ms)24292026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.96ms)24302026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (3.55ms)24312026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)24322026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.98ms)24332026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000024342026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.59ms)24352026/10/01 09:39:14 OK 20241026095416_initial_model.sql (14.01ms)24362026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.87ms)24372026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.26ms)2438--- PASS: TestReadRedirectNar (0.43s)2439=== CONT TestGracefulShutdownDrainsInflight24402026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.98ms)24412026/10/01 09:39:14 INFO Starting HTTP server address=127.0.0.1:4202124422026/10/01 09:39:14 INFO Shutdown signal received, draining in-flight requests timeout=10s24432026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.76ms)24442026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.53ms)24452026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.12ms)24462026/10/01 09:39:14 OK 3_commit_push.sql (2.1ms)24472026/10/01 09:39:14 goose: up to current file version: 324482026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.99ms)24492026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.12ms)24502026-10-01 09:39:14.498 UTC [1567] ERROR: relation "goose_db_version" does not exist at character 3624512026-10-01 09:39:14.498 UTC [1567] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24522026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.96ms)24532026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.04ms)24542026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (5.25ms)2455=== NAME TestNARDeduplicationMetadataUploadBug2456 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2066520239/001/store/lh7qpq7jak32l1h1084j64h4769q0nyv-file1.txt24572026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.24ms)24582026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (6.24ms)24592026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.61ms)24602026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000024612026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.47ms)24622026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.25ms)24632026/10/01 09:39:14 OK 20260905000000_add_claims.sql (4.47ms)24642026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (6.37ms)24652026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000024662026/10/01 09:39:14 OK 2_object_stats_trigger.sql (5.39ms)24672026/10/01 09:39:14 OK 3_commit_push.sql (2.86ms)24682026/10/01 09:39:14 goose: up to current file version: 324692026/10/01 09:39:14 OK 1_commit_pending_closure.sql (3.54ms)24702026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (7.72ms)24712026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.85ms)24722026/10/01 09:39:14 OK 20241026095416_initial_model.sql (12.98ms)24732026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.48ms)24742026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000024752026/10/01 09:39:14 OK 3_commit_push.sql (1.35ms)24762026/10/01 09:39:14 goose: up to current file version: 324772026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)24782026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.54ms)24792026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.13ms)24802026/10/01 09:39:14 OK 3_commit_push.sql (1.39ms)24812026/10/01 09:39:14 goose: up to current file version: 324822026/10/01 09:39:14 OK 20251218171726_add_pins.sql (5.19ms)2483--- PASS: TestMetricsInventory (0.47s)2484=== CONT TestIsValidCachePath2485=== RUN TestIsValidCachePath/narinfo2486=== PAUSE TestIsValidCachePath/narinfo2487=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars2488=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars2489=== RUN TestIsValidCachePath/nar_zst2490=== PAUSE TestIsValidCachePath/nar_zst2491=== RUN TestIsValidCachePath/nar_xz2492=== PAUSE TestIsValidCachePath/nar_xz2493=== RUN TestIsValidCachePath/nar_bz22494=== PAUSE TestIsValidCachePath/nar_bz22495=== RUN TestIsValidCachePath/nar_uncompressed2496=== PAUSE TestIsValidCachePath/nar_uncompressed2497=== RUN TestIsValidCachePath/ls2498=== PAUSE TestIsValidCachePath/ls2499=== RUN TestIsValidCachePath/log2500=== PAUSE TestIsValidCachePath/log2501=== RUN TestIsValidCachePath/realisation2502=== PAUSE TestIsValidCachePath/realisation2503=== RUN TestIsValidCachePath/nix-cache-info2504=== PAUSE TestIsValidCachePath/nix-cache-info2505=== RUN TestIsValidCachePath/index.html2506=== PAUSE TestIsValidCachePath/index.html2507=== RUN TestIsValidCachePath/traversal_parent2508=== PAUSE TestIsValidCachePath/traversal_parent2509=== RUN TestIsValidCachePath/traversal_in_middle2510=== PAUSE TestIsValidCachePath/traversal_in_middle2511=== RUN TestIsValidCachePath/invalid_char_e2512=== PAUSE TestIsValidCachePath/invalid_char_e2513=== RUN TestIsValidCachePath/invalid_char_u2514=== PAUSE TestIsValidCachePath/invalid_char_u2515=== RUN TestIsValidCachePath/random_path2516=== PAUSE TestIsValidCachePath/random_path2517=== RUN TestIsValidCachePath/empty2518=== PAUSE TestIsValidCachePath/empty2519=== RUN TestIsValidCachePath/leading_slash2520=== PAUSE TestIsValidCachePath/leading_slash2521=== RUN TestIsValidCachePath/wrong_extension2522=== PAUSE TestIsValidCachePath/wrong_extension2523=== RUN TestIsValidCachePath/short_hash2524=== PAUSE TestIsValidCachePath/short_hash2525=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows25262026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.94ms)25272026-10-01 09:39:14.531 UTC [1569] ERROR: relation "goose_db_version" does not exist at character 3625282026-10-01 09:39:14.531 UTC [1569] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25292026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.65ms)25302026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.66ms)25312026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (2.74ms)25322026/10/01 09:39:14 goose: successfully migrated database to version: 202609231200002533--- PASS: TestReadProxyDisabled (0.44s)2534=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check25352026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.81ms)25362026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.62ms)25372026/10/01 09:39:14 OK 20241026095416_initial_model.sql (8.84ms)25382026/10/01 09:39:14 OK 3_commit_push.sql (1.24ms)25392026/10/01 09:39:14 goose: up to current file version: 325402026-10-01 09:39:14.545 UTC [1589] ERROR: relation "goose_db_version" does not exist at character 3625412026-10-01 09:39:14.545 UTC [1589] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25422026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.98ms)25432026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.88ms)25442026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (11.49ms)25452026/10/01 09:39:14 OK 20241026095416_initial_model.sql (12.55ms)2546--- PASS: TestGracefulShutdownDrainsInflight (0.07s)2547=== CONT TestPush_RejectsBadRequests/no_objects25482026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes2549=== CONT TestPush_RejectsBadRequests/root_not_in_objects25502026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes2551=== CONT TestPush_RejectsBadRequests/bad_root25522026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes2553=== CONT TestPush_RejectsBadRequests/no_roots25542026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes2555=== CONT TestResolveDBConnectionString/flag_wins2556--- PASS: TestPush_RejectsBadRequests (0.48s)2557 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2558 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2559 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2560 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2561=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2562=== CONT TestResolveDBConnectionString/nothing_configured2563=== CONT TestResolveDBConnectionString/missing_file_is_an_error2564=== CONT TestResolveDBConnectionString/file_when_flag_empty2565=== CONT TestClientErrorHandling/InvalidStorePath2566--- PASS: TestResolveDBConnectionString (0.00s)2567 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2568 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2569 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2570 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2571 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)25722026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.75ms)25732026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.44ms)25742026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (5.81ms)25752026/10/01 09:39:14 OK 20251218171726_add_pins.sql (8.42ms)2576--- PASS: TestReadProxyConditionalGet (0.45s)2577=== CONT TestClientErrorHandling/InvalidAuthToken25782026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes25792026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (9.66ms)25802026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000025812026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (12.96ms)25822026/10/01 09:39:14 OK 1_commit_pending_closure.sql (11.28ms)25832026/10/01 09:39:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25842026/10/01 09:39:14 INFO Uploading lh7qpq7jak32l1h1084j64h4769q0nyv-file1.txt (160B)25852026/10/01 09:39:14 OK 20260905000000_add_claims.sql (9.66ms)25862026/10/01 09:39:14 OK 2_object_stats_trigger.sql (8.93ms)25872026/10/01 09:39:14 WARN Failed to register uploaded object key=lh7qpq7jak32l1h1084j64h4769q0nyv.ls error="server returned 404: 404 page not found\n"25882026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25892026/10/01 09:39:14 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"25902026/10/01 09:39:14 INFO Signed narinfos id=1 count=125912026/10/01 09:39:14 INFO Uploading 1 narinfos25922026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (8.53ms)25932026/10/01 09:39:14 OK 3_commit_push.sql (6.97ms)25942026/10/01 09:39:14 goose: up to current file version: 325952026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/1/complete25962026/10/01 09:39:14 WARN Failed to register uploaded object key=lh7qpq7jak32l1h1084j64h4769q0nyv.narinfo error="server returned 404: 404 page not found\n"25972026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (10.34ms)25982026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000025992026/10/01 09:39:14 INFO Upload complete. (87ms)2600=== NAME TestNARDeduplicationMetadataUploadBug2601 metadata_upload_test.go:54: Retrieved narinfo from S3:2602 StorePath: /build/TestNARDeduplicationMetadataUploadBug2066520239/001/store/lh7qpq7jak32l1h1084j64h4769q0nyv-file1.txt2603 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2604 Compression: zstd2605 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2606 NarSize: 1602607 References: 2608 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf26092026/10/01 09:39:14 OK 1_commit_pending_closure.sql (8.8ms)26102026/10/01 09:39:14 OK 2_object_stats_trigger.sql (2.67ms)2611 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2612 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2613 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}26142026/10/01 09:39:14 OK 3_commit_push.sql (2.41ms)26152026/10/01 09:39:14 goose: up to current file version: 326162026-10-01 09:39:14.631 UTC [1614] ERROR: relation "goose_db_version" does not exist at character 3626172026-10-01 09:39:14.631 UTC [1614] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2618--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.51s)2619=== CONT TestClientErrorHandling/ServerNotAvailable26202026-10-01 09:39:14.643 UTC [1616] ERROR: relation "goose_db_version" does not exist at character 3626212026-10-01 09:39:14.643 UTC [1616] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2622=== NAME TestOrphanedObjectsGC2623 orphaned_objects_gc_test.go:290: GC Test Summary:2624 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2625 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2626 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2627 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2628 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2629--- PASS: TestOrphanedObjectsGC (0.76s)2630=== CONT TestCacheConfigHandler/full_config,_no_issuer2631=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2632=== CONT TestCacheConfigHandler/no_signing_keys2633=== CONT TestCacheConfigHandler/no_cache_url_configured2634=== CONT TestParseSingleRange/none2635=== CONT TestParseSingleRange/start_past_EOF2636=== CONT TestParseSingleRange/single_byte2637=== CONT TestParseSingleRange/suffix_exceeds_size2638--- PASS: TestCacheConfigHandler (0.00s)2639 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2640 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2641 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2642 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2643=== CONT TestParseSingleRange/suffix2644=== CONT TestParseSingleRange/end_clamped_to_size2645=== CONT TestParseSingleRange/open-ended2646=== CONT TestParseSingleRange/closed2647=== CONT TestParseSingleRange/start_far_past_EOF2648=== CONT TestParseSingleRange/malformed_end_before_start2649=== CONT TestParseSingleRange/multi-range_ignored2650=== CONT TestParseSingleRange/unknown_unit2651=== CONT TestParseSingleRange/malformed_both_empty2652=== CONT TestParseSingleRange/malformed_no_dash2653--- PASS: TestParseSingleRange (0.00s)2654 --- PASS: TestParseSingleRange/none (0.00s)2655 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2656 --- PASS: TestParseSingleRange/single_byte (0.00s)2657 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2658 --- PASS: TestParseSingleRange/suffix (0.00s)2659 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2660 --- PASS: TestParseSingleRange/open-ended (0.00s)2661 --- PASS: TestParseSingleRange/closed (0.00s)2662 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2663 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2664 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2665 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2666 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2667 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2668=== CONT TestServerTLSConfig/no_client_CA2669=== CONT TestServerTLSConfig/not_a_PEM_file2670=== CONT TestServerTLSConfig/missing_CA_file2671--- PASS: TestServerTLSConfig (0.00s)2672 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2673 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2674 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2675=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token26762026/10/01 09:39:14 OK 20241026095416_initial_model.sql (11.23ms)2677=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected26782026/10/01 09:39:14 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]2679=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2680=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected26812026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.92ms)26822026/10/01 09:39:14 WARN Authentication failed token_preview=eyJhbGciOi...G994t__4WQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2683=== CONT TestService_RequireScope_OIDC/builder_may_write2684--- PASS: TestService_AuthMiddleware_OIDC (0.58s)2685 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2686 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2687 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2688 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2689=== CONT TestService_RequireScope_OIDC/static_token_may_admin2690=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2691=== CONT TestService_RequireScope_OIDC/writer_implies_read2692=== CONT TestService_RequireScope_OIDC/reader_may_read26932026/10/01 09:39:14 OK 20251218171726_add_pins.sql (4.5ms)2694=== CONT TestService_RequireScope_OIDC/static_token_may_write2695=== CONT TestService_RequireScope_OIDC/ops_may_not_write2696=== CONT TestService_RequireScope_OIDC/reader_may_not_write2697=== CONT TestService_RequireScope_OIDC/ops_may_admin2698=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2699=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info27002026/10/01 09:39:14 INFO Received uploads request method=POST path=/2701=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key27022026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/2703=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key27042026/10/01 09:39:14 INFO Received request for more parts method=POST path=/2705=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal27062026/10/01 09:39:14 INFO Received uploads request method=POST path=/2707--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2708 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2709 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2710 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2711 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2712=== CONT TestIsValidUploadKey/narinfo2713=== CONT TestIsValidUploadKey/realisation_plus_in_output2714--- PASS: TestService_RequireScope_OIDC (0.77s)2715 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2716 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2717 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2718 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2719 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2720 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2721 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2722 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2723 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2724 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2725=== CONT TestIsValidUploadKey/unknown_type2726=== CONT TestIsValidUploadKey/empty_key2727=== CONT TestIsValidUploadKey/absolute2728=== CONT TestIsValidUploadKey/traversal_nar2729=== CONT TestIsValidUploadKey/traversal2730=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2731=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2732=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2733=== CONT TestIsValidUploadKey/index.html2734=== CONT TestIsValidUploadKey/build_log_home-manager_file2735=== CONT TestIsValidUploadKey/realisation2736=== CONT TestIsValidUploadKey/build_log_equals2737=== CONT TestIsValidUploadKey/build_log_question_mark2738=== CONT TestIsValidUploadKey/build_log_plus_in_name2739=== CONT TestIsValidUploadKey/build_log2740=== CONT TestIsValidUploadKey/listing2741=== CONT TestIsValidUploadKey/nar_xz2742=== CONT TestIsValidUploadKey/nar_plain2743=== CONT TestIsValidUploadKey/nar_zst2744=== CONT TestIsValidUploadKey/nix-cache-info2745--- PASS: TestIsValidUploadKey (0.00s)2746 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2747 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2748 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2749 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2750 --- PASS: TestIsValidUploadKey/absolute (0.00s)2751 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2752 --- PASS: TestIsValidUploadKey/traversal (0.00s)2753 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2754 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2755 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2756 --- PASS: TestIsValidUploadKey/index.html (0.00s)2757 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2758 --- PASS: TestIsValidUploadKey/realisation (0.00s)2759 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2760 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2761 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2762 --- PASS: TestIsValidUploadKey/build_log (0.00s)2763 --- PASS: TestIsValidUploadKey/listing (0.00s)2764 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2765 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2766 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2767 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2768=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure27692026/10/01 09:39:14 INFO Received uploads request method=POST path=/27702026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.73ms)27712026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (4.8ms)2772=== NAME TestNARDeduplicationMetadataUploadBug2773 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2066520239/001/store/11sn6m7nd82fjbibiyrp2w6rfjgxgxgy-file2.txt27742026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)27752026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.79ms)27762026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.86ms)2777--- PASS: TestReadProxyNarStreaming (0.53s)2778=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts27792026/10/01 09:39:14 INFO Received request for more parts method=POST path=/27802026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.83ms)27812026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (10.17ms)27822026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000027832026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (11.61ms)2784--- PASS: TestPresentNotReportedWhileGCDeletesClosure (1.08s)2785=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart27862026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/27872026-10-01 09:39:14.678 UTC [1635] ERROR: relation "goose_db_version" does not exist at character 3627882026-10-01 09:39:14.678 UTC [1635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27892026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.48ms)27902026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.11ms)27912026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.71ms)27922026/10/01 09:39:14 OK 3_commit_push.sql (947.35µs)27932026/10/01 09:39:14 goose: up to current file version: 327942026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.2ms)27952026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.91ms)27962026/10/01 09:39:14 goose: successfully migrated database to version: 202609231200002797--- PASS: TestReadProxyInvalidPath (0.51s)2798=== CONT TestProxyWriteTimeout/narinfo2799=== CONT TestProxyWriteTimeout/10_GiB_nar2800=== CONT TestProxyWriteTimeout/unknown_size2801=== CONT TestProxyWriteTimeout/1_GiB_nar2802--- PASS: TestProxyWriteTimeout (0.00s)2803 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2804 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2805 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2806 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2807=== CONT TestIsValidCachePath/narinfo2808=== CONT TestIsValidCachePath/index.html2809=== CONT TestIsValidCachePath/short_hash2810=== CONT TestIsValidCachePath/wrong_extension2811=== CONT TestIsValidCachePath/leading_slash2812=== CONT TestIsValidCachePath/empty2813=== CONT TestIsValidCachePath/random_path2814=== CONT TestIsValidCachePath/invalid_char_u2815=== CONT TestIsValidCachePath/invalid_char_e2816=== CONT TestIsValidCachePath/traversal_in_middle2817=== CONT TestIsValidCachePath/traversal_parent2818=== CONT TestIsValidCachePath/nar_uncompressed2819=== CONT TestIsValidCachePath/nix-cache-info2820=== CONT TestIsValidCachePath/realisation2821=== CONT TestIsValidCachePath/ls2822=== CONT TestIsValidCachePath/nar_xz2823=== CONT TestIsValidCachePath/nar_bz22824=== CONT TestIsValidCachePath/nar_zst2825=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2826=== CONT TestIsValidCachePath/log2827--- PASS: TestIsValidCachePath (0.00s)2828 --- PASS: TestIsValidCachePath/narinfo (0.00s)2829 --- PASS: TestIsValidCachePath/index.html (0.00s)2830 --- PASS: TestIsValidCachePath/short_hash (0.00s)2831 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2832 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2833 --- PASS: TestIsValidCachePath/empty (0.00s)2834 --- PASS: TestIsValidCachePath/random_path (0.00s)2835 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2836 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2837 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2838 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2839 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2840 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2841 --- PASS: TestIsValidCachePath/realisation (0.00s)2842 --- PASS: TestIsValidCachePath/ls (0.00s)2843 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2844 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2845 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2846 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2847 --- PASS: TestIsValidCachePath/log (0.00s)28482026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2ms)28492026/10/01 09:39:14 OK 2_object_stats_trigger.sql (1.63ms)28502026/10/01 09:39:14 OK 3_commit_push.sql (931.55µs)28512026/10/01 09:39:14 goose: up to current file version: 328522026-10-01 09:39:14.692 UTC [1652] ERROR: relation "goose_db_version" does not exist at character 3628532026-10-01 09:39:14.692 UTC [1652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28542026/10/01 09:39:14 OK 20241026095416_initial_model.sql (9.79ms)28552026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.28ms)28562026/10/01 09:39:14 OK 20251218171726_add_pins.sql (2.91ms)28572026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.12ms)28582026/10/01 09:39:14 OK 20260905000000_add_claims.sql (3.44ms)28592026/10/01 09:39:14 OK 20241026095416_initial_model.sql (10.63ms)28602026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.13ms)28612026/10/01 09:39:14 OK 20251210153512_drop_unused_gin_index.sql (1.29ms)2862--- PASS: TestReadProxy404 (0.51s)28632026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.81ms)28642026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000028652026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.78ms)28662026/10/01 09:39:14 OK 20251218171726_add_pins.sql (3.95ms)28672026/10/01 09:39:14 OK 2_object_stats_trigger.sql (942.01µs)28682026/10/01 09:39:14 OK 3_commit_push.sql (881.15µs)28692026/10/01 09:39:14 goose: up to current file version: 328702026/10/01 09:39:14 OK 20260628120000_add_object_size_and_stats.sql (3.69ms)28712026/10/01 09:39:14 OK 20260905000000_add_claims.sql (16.64ms)28722026/10/01 09:39:14 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28732026/10/01 09:39:14 INFO Received cleanup request method=DELETE path=/api/pending_closures28742026/10/01 09:39:14 INFO Received push request method=POST path=/api/pushes28752026/10/01 09:39:14 OK 20260920000000_drop_claims.sql (2.38ms)28762026/10/01 09:39:14 INFO Aborted multipart uploads count=028772026/10/01 09:39:14 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)28782026/10/01 09:39:14 OK 20260923120000_add_pushes.sql (1.84ms)28792026/10/01 09:39:14 goose: successfully migrated database to version: 2026092312000028802026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures28812026/10/01 09:39:14 OK 1_commit_pending_closure.sql (2.07ms)28822026/10/01 09:39:14 OK 2_object_stats_trigger.sql (903.13µs)28832026/10/01 09:39:14 WARN Failed to register uploaded object key=11sn6m7nd82fjbibiyrp2w6rfjgxgxgy.ls error="server returned 404: 404 page not found\n"28842026/10/01 09:39:14 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign28852026/10/01 09:39:14 INFO Signed narinfos id=2 count=128862026/10/01 09:39:14 INFO Uploading 1 narinfos28872026/10/01 09:39:14 OK 3_commit_push.sql (3.89ms)28882026/10/01 09:39:14 goose: up to current file version: 328892026/10/01 09:39:14 INFO Received complete push request method=POST path=/api/pushes/2/complete28902026/10/01 09:39:14 WARN Failed to register uploaded object key=11sn6m7nd82fjbibiyrp2w6rfjgxgxgy.narinfo error="server returned 404: 404 page not found\n"28912026/10/01 09:39:14 INFO Received cleanup request method=DELETE path=/api/pending_closures28922026/10/01 09:39:14 INFO Upload complete. (53ms)28932026/10/01 09:39:14 INFO Aborted multipart uploads count=12894=== NAME TestNARDeduplicationMetadataUploadBug2895 metadata_upload_test.go:76: Retrieved narinfo from S3:2896 StorePath: /build/TestNARDeduplicationMetadataUploadBug2066520239/001/store/11sn6m7nd82fjbibiyrp2w6rfjgxgxgy-file2.txt2897 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2898 Compression: zstd2899 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2900 NarSize: 1602901 References: 2902 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf29032026/10/01 09:39:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete29042026-10-01 09:39:14.755 UTC [1431] ERROR: Closure does not exist: id=129052026-10-01 09:39:14.755 UTC [1431] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE29062026-10-01 09:39:14.755 UTC [1431] STATEMENT: -- name: CommitPendingClosure :exec2907 SELECT commit_pending_closure($1::bigint)2908 2909--- PASS: TestService_cleanupPendingClosuresHandler (0.54s)2910=== NAME TestNARDeduplicationMetadataUploadBug2911 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2912 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2913 {"version":1,"root":{"type":"regular","size":44}}2914--- PASS: TestNARDeduplicationMetadataUploadBug (0.68s)29152026/10/01 09:39:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete29162026/10/01 09:39:14 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst2917--- PASS: TestCompleteMultipartUnregistered (0.43s)29182026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures2919--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.46s)29202026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures2921--- PASS: TestReadProxyNarinfo (0.44s)29222026/10/01 09:39:14 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=211.350066ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29232026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures29242026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures29252026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures2926--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.46s)2927--- PASS: TestService_healthCheckHandler (0.45s)29282026/10/01 09:39:14 WARN readiness check failed error="closed pool"2929--- PASS: TestService_readinessHandler (0.45s)29302026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures29312026/10/01 09:39:14 INFO Aborted multipart uploads count=029322026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period29332026/10/01 09:39:14 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=029342026/10/01 09:39:14 INFO Received uploads request method=POST path=/api/pending_closures29352026/10/01 09:39:14 INFO Vacuumed table table=pending_closures29362026/10/01 09:39:14 INFO Vacuumed table table=pending_objects29372026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads29382026/10/01 09:39:14 INFO Vacuumed table table=closures29392026/10/01 09:39:14 INFO Vacuumed table table=objects29402026/10/01 09:39:14 INFO Aborted multipart uploads count=029412026/10/01 09:39:14 WARN Force mode enabled - objects will be deleted immediately without grace period29422026/10/01 09:39:14 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=029432026/10/01 09:39:14 INFO Vacuumed table table=pending_closures29442026/10/01 09:39:14 INFO Vacuumed table table=pending_objects29452026/10/01 09:39:14 INFO Vacuumed table table=multipart_uploads29462026/10/01 09:39:14 INFO Vacuumed table table=closures29472026/10/01 09:39:14 INFO Vacuumed table table=objects2948--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2949 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.46s)2950 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.46s)29512026/10/01 09:39:15 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=377.801062ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29522026/10/01 09:39:15 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29532026/10/01 09:39:15 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29542026/10/01 09:39:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete29552026/10/01 09:39:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZDc1MDhiYjgtMjkyYi00MDg5LWEwNjQtYTIzNDg2ZDc1NzM4LjZjZjgzOTEyLWY2MWQtNGM0NS04MmEyLTM0NzVlZjc2ZmZjOXgxNzkwODQ3NTU0ODA2Nzk2ODI3 parts=1029562026/10/01 09:39:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete29572026/10/01 09:39:15 INFO Completed upload id=129582026/10/01 09:39:15 INFO Received uploads request method=POST path=/api/pending_closures29592026/10/01 09:39:15 INFO Received uploads request method=POST path=/api/pending_closures29602026/10/01 09:39:15 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo29612026/10/01 09:39:15 WARN Found objects in DB but missing from S3, will re-upload count=12962--- PASS: TestService_verifyS3Integrity (0.78s)29632026/10/01 09:39:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete29642026/10/01 09:39:15 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZDc1MDhiYjgtMjkyYi00MDg5LWEwNjQtYTIzNDg2ZDc1NzM4LmE5YWUxMzllLWVjZWItNDViNC04ZmYzLTA3ZWRkM2RkYWZhMngxNzkwODQ3NTU0ODQ4NzY4NTEz parts=1029652026/10/01 09:39:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete29662026/10/01 09:39:15 INFO Completed upload id=129672026/10/01 09:39:15 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000029682026/10/01 09:39:15 INFO Received uploads request method=POST path=/api/pending_closures29692026/10/01 09:39:15 INFO Starting cleanup of old closures method=DELETE path=/api/closures29702026/10/01 09:39:15 INFO Aborted multipart uploads count=029712026/10/01 09:39:15 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=029722026/10/01 09:39:15 INFO Vacuumed table table=pending_closures29732026/10/01 09:39:15 INFO Vacuumed table table=pending_objects29742026/10/01 09:39:15 INFO Vacuumed table table=multipart_uploads29752026/10/01 09:39:15 INFO Vacuumed table table=closures29762026/10/01 09:39:15 INFO Vacuumed table table=objects29772026/10/01 09:39:15 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000002978--- PASS: TestService_createPendingClosureHandler (0.83s)29792026/10/01 09:39:15 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=727.82832ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2980--- PASS: TestUploadHandlersRejectOversizedBody (0.13s)2981 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2982 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.07s)2983 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.93s)2984=== NAME TestOrphanedObjectsGCStressTest2985 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2986 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion2987 orphaned_objects_gc_test.go:509: Stress test completed successfully:2988 orphaned_objects_gc_test.go:510: - Active objects preserved: 202989 orphaned_objects_gc_test.go:511: - Objects deleted: 2102990 orphaned_objects_gc_test.go:512: - Total GC'd: 2102991--- PASS: TestOrphanedObjectsGCStressTest (2.26s)29922026/10/01 09:39:16 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=029932026/10/01 09:39:16 INFO Received create pin request method=POST path=/api/pins/myapp29942026/10/01 09:39:16 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.508960845s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29952026/10/01 09:39:16 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2716783079/001/store/nqpc9b201qxgx9xs8mr98ibb39ndwxn0-pinned-file.txt narinfo_key=nqpc9b201qxgx9xs8mr98ibb39ndwxn0.narinfo29962026/10/01 09:39:16 INFO Starting cleanup of old closures method=DELETE path=/api/closures29972026/10/01 09:39:16 INFO Garbage collection started29982026/10/01 09:39:16 INFO Aborted multipart uploads count=029992026/10/01 09:39:16 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=03000=== NAME TestClientIntegration3001 client_integration_test.go:323: Objects in database after GC:3002 client_integration_test.go:323: Successfully deleted all objects with GC --force30032026/10/01 09:39:16 WARN Force mode enabled - objects will be deleted immediately without grace period30042026/10/01 09:39:16 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=03005--- PASS: TestClientIntegration (2.91s)30062026/10/01 09:39:16 INFO Vacuumed table table=pending_closures30072026/10/01 09:39:16 INFO Vacuumed table table=pending_objects30082026/10/01 09:39:16 INFO Vacuumed table table=multipart_uploads30092026/10/01 09:39:16 INFO Vacuumed table table=closures30102026/10/01 09:39:16 INFO Vacuumed table table=objects30112026/10/01 09:39:17 WARN Rate limiter enabled after throttle name=s3-test rate=530122026/10/01 09:39:17 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."3013=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle3014 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=103015 throttle_test.go:215: Rate limiter: enabled=true, rate=5.003016--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.34s)30172026/10/01 09:39:17 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-config30182026/10/01 09:39:17 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=196.267289ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30192026/10/01 09:39:18 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=427.816264ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config3020=== NAME TestPinProtectsFromGC3021 client_integration_test.go:840: Pin successfully protected closure from garbage collection3022--- PASS: TestPinProtectsFromGC (5.11s)30232026/10/01 09:39:18 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=870.361494ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30242026/10/01 09:39:19 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.550822857s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30252026/10/01 09:39:20 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"30262026/10/01 09:39:20 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-config30272026/10/01 09:39:20 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.373686ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30282026/10/01 09:39:21 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=431.546926ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30292026/10/01 09:39:21 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=793.415026ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30302026/10/01 09:39:22 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.685825859s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30312026/10/01 09:39:24 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_closures30322026/10/01 09:39:24 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=201.025748ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30332026/10/01 09:39:24 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=367.548384ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30342026/10/01 09:39:24 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=777.563231ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30352026/10/01 09:39:25 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.533089365s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3036--- PASS: TestClientErrorHandling (0.00s)3037 --- PASS: TestClientErrorHandling/InvalidStorePath (0.45s)3038 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.54s)3039 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.43s)3040PASS30412026-10-01 09:39:27.303 UTC [129] LOG: received smart shutdown request30422026-10-01 09:39:27.307 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 130432026-10-01 09:39:27.319 UTC [134] LOG: shutting down30442026-10-01 09:39:27.320 UTC [134] LOG: checkpoint starting: shutdown immediate30452026-10-01 09:39:27.824 UTC [134] LOG: checkpoint complete: wrote 11085 buffers (67.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 24 recycled; write=0.198 s, sync=0.285 s, total=0.505 s; sync files=27976, longest=0.003 s, average=0.001 s; distance=387450 kB, estimate=387450 kB; lsn=0/191C4688, redo lsn=0/191C468830462026-10-01 09:39:27.898 UTC [129] LOG: database system is shut down3047Running OIDC tests...3048=== RUN TestAudienceForIssuer3049=== PAUSE TestAudienceForIssuer3050=== RUN TestGlobMatch3051=== PAUSE TestGlobMatch3052=== RUN TestValidateToken_ValidToken3053=== PAUSE TestValidateToken_ValidToken3054=== RUN TestValidateToken_WrongAudience3055=== PAUSE TestValidateToken_WrongAudience3056=== RUN TestValidateToken_Expired3057=== PAUSE TestValidateToken_Expired3058=== RUN TestValidateToken_BoundClaimsMismatch3059=== PAUSE TestValidateToken_BoundClaimsMismatch3060=== RUN TestValidateToken_BoundSubjectMismatch3061=== PAUSE TestValidateToken_BoundSubjectMismatch3062=== RUN TestValidateToken_MultipleProviders3063=== PAUSE TestValidateToken_MultipleProviders3064=== RUN TestValidateToken_NoMatchingProvider3065=== PAUSE TestValidateToken_NoMatchingProvider3066=== RUN TestValidateToken_KubernetesServiceAccount3067=== PAUSE TestValidateToken_KubernetesServiceAccount3068=== RUN TestNewValidator_KubernetesRequiresCA3069=== PAUSE TestNewValidator_KubernetesRequiresCA3070=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3071=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3072=== RUN TestPins_ReservedForMatchingRule3073=== PAUSE TestPins_ReservedForMatchingRule3074=== RUN TestPins_TopLevelShorthand3075=== PAUSE TestPins_TopLevelShorthand3076=== RUN TestPins_ConfigValidation3077=== PAUSE TestPins_ConfigValidation3078=== RUN TestScopes_LegacyProviderDefaultsToWrite3079=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3080=== RUN TestScopes_Rules3081=== PAUSE TestScopes_Rules3082=== RUN TestScopes_ConfigValidation3083=== PAUSE TestScopes_ConfigValidation3084=== CONT TestAudienceForIssuer3085=== CONT TestValidateToken_BoundClaimsMismatch3086--- PASS: TestAudienceForIssuer (0.00s)3087=== CONT TestValidateToken_NoMatchingProvider3088=== CONT TestValidateToken_WrongAudience3089=== CONT TestValidateToken_KubernetesServiceAccount3090=== CONT TestValidateToken_ValidToken3091=== CONT TestScopes_ConfigValidation3092=== CONT TestScopes_Rules3093=== CONT TestScopes_LegacyProviderDefaultsToWrite3094=== CONT TestPins_ConfigValidation3095=== CONT TestPins_TopLevelShorthand3096=== CONT TestPins_ReservedForMatchingRule3097--- PASS: TestScopes_ConfigValidation (0.00s)3098=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3099=== CONT TestNewValidator_KubernetesRequiresCA3100=== CONT TestValidateToken_MultipleProviders3101=== CONT TestGlobMatch3102=== RUN TestGlobMatch/foo_foo3103=== PAUSE TestGlobMatch/foo_foo3104=== RUN TestGlobMatch/foo_bar3105=== PAUSE TestGlobMatch/foo_bar3106=== RUN TestGlobMatch/*_3107=== PAUSE TestGlobMatch/*_3108=== RUN TestGlobMatch/*_anything3109=== PAUSE TestGlobMatch/*_anything3110=== RUN TestGlobMatch/foo*_foo3111=== PAUSE TestGlobMatch/foo*_foo3112=== RUN TestGlobMatch/foo*_foobar3113=== PAUSE TestGlobMatch/foo*_foobar3114=== RUN TestGlobMatch/foo*_bar3115=== PAUSE TestGlobMatch/foo*_bar3116=== RUN TestGlobMatch/*bar_bar3117=== CONT TestValidateToken_Expired3118=== CONT TestValidateToken_BoundSubjectMismatch3119--- PASS: TestPins_ConfigValidation (0.00s)3120=== PAUSE TestGlobMatch/*bar_bar3121=== RUN TestGlobMatch/*bar_foobar3122=== PAUSE TestGlobMatch/*bar_foobar3123=== RUN TestGlobMatch/*bar_foo3124=== PAUSE TestGlobMatch/*bar_foo3125=== RUN TestGlobMatch/foo*bar_foobar3126=== PAUSE TestGlobMatch/foo*bar_foobar3127=== RUN TestGlobMatch/foo*bar_foo123bar3128=== PAUSE TestGlobMatch/foo*bar_foo123bar3129=== RUN TestGlobMatch/foo*bar_foobarbaz3130=== PAUSE TestGlobMatch/foo*bar_foobarbaz3131=== RUN TestGlobMatch/*/*_foo/bar3132=== PAUSE TestGlobMatch/*/*_foo/bar3133=== RUN TestGlobMatch/*/*_foo3134=== PAUSE TestGlobMatch/*/*_foo3135=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3136=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3137=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03138=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03139=== RUN TestGlobMatch/refs/*/main_refs/heads/main3140=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3141=== RUN TestGlobMatch/fo?_foo3142=== PAUSE TestGlobMatch/fo?_foo3143=== RUN TestGlobMatch/fo?_fo3144=== PAUSE TestGlobMatch/fo?_fo3145=== RUN TestGlobMatch/fo?_fooo3146=== PAUSE TestGlobMatch/fo?_fooo3147=== RUN TestGlobMatch/?oo_foo3148=== PAUSE TestGlobMatch/?oo_foo3149=== RUN TestGlobMatch/?oo_boo3150=== PAUSE TestGlobMatch/?oo_boo3151=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3152=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3153=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3154=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3155=== CONT TestGlobMatch/foo_foo3156=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3157=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3158=== CONT TestGlobMatch/?oo_boo3159=== CONT TestGlobMatch/?oo_foo3160=== CONT TestGlobMatch/fo?_fooo3161=== CONT TestGlobMatch/fo?_fo3162=== CONT TestGlobMatch/fo?_foo3163=== CONT TestGlobMatch/refs/*/main_refs/heads/main3164=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03165=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3166=== CONT TestGlobMatch/*/*_foo3167=== CONT TestGlobMatch/*/*_foo/bar3168=== CONT TestGlobMatch/foo*bar_foobarbaz3169=== CONT TestGlobMatch/foo*bar_foo123bar3170=== CONT TestGlobMatch/foo*bar_foobar3171=== CONT TestGlobMatch/*bar_foo3172=== CONT TestGlobMatch/*bar_foobar3173=== CONT TestGlobMatch/*bar_bar3174=== CONT TestGlobMatch/foo*_bar3175=== CONT TestGlobMatch/foo*_foobar3176=== CONT TestGlobMatch/foo*_foo3177=== CONT TestGlobMatch/*_anything3178=== CONT TestGlobMatch/*_3179=== CONT TestGlobMatch/foo_bar3180--- PASS: TestGlobMatch (0.00s)3181 --- PASS: TestGlobMatch/foo_foo (0.00s)3182 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3183 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3184 --- PASS: TestGlobMatch/?oo_boo (0.00s)3185 --- PASS: TestGlobMatch/?oo_foo (0.00s)3186 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3187 --- PASS: TestGlobMatch/fo?_fo (0.00s)3188 --- PASS: TestGlobMatch/fo?_foo (0.00s)3189 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3190 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3191 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3192 --- PASS: TestGlobMatch/*/*_foo (0.00s)3193 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3194 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3195 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3196 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3197 --- PASS: TestGlobMatch/*bar_foo (0.00s)3198 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3199 --- PASS: TestGlobMatch/*bar_bar (0.00s)3200 --- PASS: TestGlobMatch/foo*_bar (0.00s)3201 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3202 --- PASS: TestGlobMatch/foo*_foo (0.00s)3203 --- PASS: TestGlobMatch/*_anything (0.00s)3204 --- PASS: TestGlobMatch/*_ (0.00s)3205 --- PASS: TestGlobMatch/foo_bar (0.00s)32062026/10/01 09:39:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37367/oidc3207--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)32082026/10/01 09:39:29 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:467353209--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)32102026/10/01 09:39:29 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12332112026/10/01 09:39:29 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:42761/oidc3212--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.08s)3213--- PASS: TestValidateToken_NoMatchingProvider (0.08s)32142026/10/01 09:39:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42105/oidc3215--- PASS: TestValidateToken_Expired (0.08s)32162026/10/01 09:39:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34789/oidc3217--- PASS: TestPins_ReservedForMatchingRule (0.09s)32182026/10/01 09:39:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43293/oidc32192026/10/01 09:39:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38479/oidc32202026/10/01 09:39:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40973/oidc3221--- PASS: TestValidateToken_BoundClaimsMismatch (0.13s)3222--- PASS: TestPins_TopLevelShorthand (0.13s)32232026/10/01 09:39:29 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:39857/oidc32242026/10/01 09:39:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34913/oidc32252026/10/01 09:39:29 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:45883/oidc3226--- PASS: TestScopes_Rules (0.13s)3227--- PASS: TestValidateToken_ValidToken (0.14s)3228--- PASS: TestValidateToken_MultipleProviders (0.13s)32292026/10/01 09:39:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35329/oidc3230--- PASS: TestValidateToken_WrongAudience (0.20s)32312026/10/01 09:39:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42917/oidc3232--- PASS: TestValidateToken_BoundSubjectMismatch (0.26s)32332026/10/01 09:39:29 http: TLS handshake error from 127.0.0.1:43026: remote error: tls: bad certificate3234--- PASS: TestNewValidator_KubernetesRequiresCA (0.29s)3235PASS3236Running hook tests...3237=== RUN TestSendPathsEmpty3238=== PAUSE TestSendPathsEmpty3239=== RUN TestQueueEnqueueAndFetch3240=== PAUSE TestQueueEnqueueAndFetch3241=== RUN TestQueueDeduplication3242=== PAUSE TestQueueDeduplication3243=== RUN TestQueueRemove3244=== PAUSE TestQueueRemove3245=== RUN TestQueueFetchBatchLimit3246=== PAUSE TestQueueFetchBatchLimit3247=== RUN TestQueueRetryMovesToBack3248=== PAUSE TestQueueRetryMovesToBack3249=== RUN TestQueueFetchRemoveLifecycle3250=== PAUSE TestQueueFetchRemoveLifecycle3251=== RUN TestQueueConcurrentWriters3252=== PAUSE TestQueueConcurrentWriters3253=== RUN TestQueueRemoveLargeClosure3254=== PAUSE TestQueueRemoveLargeClosure3255=== RUN TestServerClientIntegration3256=== PAUSE TestServerClientIntegration3257=== RUN TestServerQueueError3258=== PAUSE TestServerQueueError3259=== RUN TestGetListenerSocketActivation3260 server_test.go:210: === RUN TestGetListenerSocketActivation3261 --- PASS: TestGetListenerSocketActivation (0.00s)3262 PASS3263 3264--- PASS: TestGetListenerSocketActivation (0.01s)3265=== RUN TestDrainIsolatesPoisonPath3266=== PAUSE TestDrainIsolatesPoisonPath3267=== RUN TestRunNotBlockedByPoisonHead3268=== PAUSE TestRunNotBlockedByPoisonHead3269=== RUN TestDrainGivesUpWhenServerDown3270=== PAUSE TestDrainGivesUpWhenServerDown3271=== RUN TestFailedPathPrunedByLaterClosure3272=== PAUSE TestFailedPathPrunedByLaterClosure3273=== RUN TestWorkerUploadsAndRemoves3274=== PAUSE TestWorkerUploadsAndRemoves3275=== RUN TestWorkerSkipsGCdPaths3276=== PAUSE TestWorkerSkipsGCdPaths3277=== RUN TestWorkerPrunesClosureDeps3278=== PAUSE TestWorkerPrunesClosureDeps3279=== RUN TestDrainTimeout3280=== PAUSE TestDrainTimeout3281=== CONT TestSendPathsEmpty3282=== CONT TestDrainIsolatesPoisonPath3283=== CONT TestQueueRemove3284--- PASS: TestSendPathsEmpty (0.00s)3285=== CONT TestQueueFetchRemoveLifecycle3286=== CONT TestQueueRetryMovesToBack3287=== CONT TestServerQueueError3288=== CONT TestQueueDeduplication3289=== CONT TestServerClientIntegration3290=== CONT TestQueueEnqueueAndFetch3291=== CONT TestQueueRemoveLargeClosure3292=== CONT TestQueueConcurrentWriters3293=== CONT TestWorkerUploadsAndRemoves3294=== CONT TestDrainTimeout32952026/10/01 09:39:29 ERROR Failed to queue paths error="permission denied" count=13296=== CONT TestDrainGivesUpWhenServerDown3297=== CONT TestFailedPathPrunedByLaterClosure3298=== CONT TestWorkerPrunesClosureDeps3299--- PASS: TestServerClientIntegration (0.00s)3300=== CONT TestQueueFetchBatchLimit3301=== CONT TestWorkerSkipsGCdPaths3302=== CONT TestRunNotBlockedByPoisonHead3303--- PASS: TestServerQueueError (0.00s)33042026/10/01 09:39:29 INFO Upload queue status pending=233052026/10/01 09:39:29 INFO Uploading batch count=133062026/10/01 09:39:29 INFO Uploading batch count=133072026/10/01 09:39:29 ERROR Upload failed error="upload failed" count=133082026/10/01 09:39:29 INFO Uploading batch count=433092026/10/01 09:39:29 ERROR Upload failed error="upload failed" count=433102026/10/01 09:39:29 INFO Uploading batch count=233112026/10/01 09:39:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1944326600/002/bbb33122026/10/01 09:39:29 INFO Upload queue status pending=33313--- PASS: TestQueueFetchBatchLimit (0.01s)33142026/10/01 09:39:29 INFO Uploading batch count=133152026/10/01 09:39:29 ERROR Upload failed error="upload failed" count=133162026/10/01 09:39:29 INFO Uploading batch count=13317--- PASS: TestQueueDeduplication (0.02s)3318--- PASS: TestQueueRetryMovesToBack (0.02s)33192026/10/01 09:39:29 INFO Uploading batch count=233202026/10/01 09:39:29 ERROR Upload failed error="upload failed" count=233212026/10/01 09:39:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2500812016/002/a3322--- PASS: TestQueueEnqueueAndFetch (0.02s)33232026/10/01 09:39:29 INFO Uploading batch count=13324--- PASS: TestQueueRemove (0.02s)33252026/10/01 09:39:29 INFO Upload queue status pending=233262026/10/01 09:39:29 INFO Uploading batch count=233272026/10/01 09:39:29 INFO Upload queue status pending=233282026/10/01 09:39:29 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths494499942/002/nonexistent33292026/10/01 09:39:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2500812016/002/b3330--- PASS: TestQueueFetchRemoveLifecycle (0.02s)33312026/10/01 09:39:29 INFO Uploading batch count=133322026/10/01 09:39:29 ERROR Upload failed error="upload failed" count=133332026/10/01 09:39:29 INFO Uploading batch count=233342026/10/01 09:39:29 ERROR Upload failed error="upload failed" count=233352026/10/01 09:39:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2500812016/002/c33362026/10/01 09:39:29 INFO Uploading batch count=133372026/10/01 09:39:29 INFO Uploading batch count=133382026/10/01 09:39:29 ERROR Upload failed error="upload failed" count=133392026/10/01 09:39:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2500812016/002/d3340--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)33412026/10/01 09:39:29 INFO Uploading batch count=133422026/10/01 09:39:29 ERROR Upload failed error="upload failed" count=133432026/10/01 09:39:29 INFO Uploading batch count=233442026/10/01 09:39:29 ERROR Upload failed error="upload failed" count=233452026/10/01 09:39:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2500812016/002/e33462026/10/01 09:39:29 ERROR Drain finished with paths left in queue remaining=133472026/10/01 09:39:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2500812016/002/f33482026/10/01 09:39:29 ERROR Drain finished with paths left in queue remaining=103349--- PASS: TestDrainIsolatesPoisonPath (0.02s)3350--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3351--- PASS: TestWorkerPrunesClosureDeps (0.03s)3352--- PASS: TestWorkerSkipsGCdPaths (0.03s)3353--- PASS: TestWorkerUploadsAndRemoves (0.04s)3354--- PASS: TestQueueRemoveLargeClosure (0.13s)3355--- PASS: TestQueueConcurrentWriters (0.16s)33562026/10/01 09:39:29 ERROR Upload failed error="context deadline exceeded" count=233572026/10/01 09:39:29 ERROR Drain finished with paths left in queue remaining=43358--- PASS: TestDrainTimeout (0.22s)33592026/10/01 09:39:30 INFO Uploading batch count=133602026/10/01 09:39:30 INFO Uploading batch count=133612026/10/01 09:39:30 INFO Uploading batch count=133622026/10/01 09:39:30 ERROR Upload failed error="upload failed" count=133632026/10/01 09:39:30 INFO Uploading batch count=133642026/10/01 09:39:30 ERROR Upload failed error="upload failed" count=133652026/10/01 09:39:30 INFO Uploading batch count=133662026/10/01 09:39:30 ERROR Upload failed error="upload failed" count=133672026/10/01 09:39:30 INFO Uploading batch count=133682026/10/01 09:39:30 ERROR Upload failed error="upload failed" count=133692026/10/01 09:39:30 ERROR Drain finished with paths left in queue remaining=13370--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3371PASS