niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #294
· 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 TestScriptTokenEmptyCommand97--- PASS: TestScriptTokenEmptyCommand (0.00s)98=== CONT TestRateLimiterFeedback99=== CONT TestScriptTokenScriptFails100=== CONT TestSetClientTLSDoesNotMutateDefaultTransport101=== CONT TestScriptTokenBadJSON102=== CONT TestScriptTokenEmptyToken103=== CONT TestScriptTokenCachesUntilRefresh104=== CONT TestScriptTokenNoExpiryRerunsEveryCall105=== CONT TestFileTokenEmpty106=== CONT TestFileTokenMissing107=== CONT TestFileTokenReadsAndCaches108=== CONT TestDoWithRetry_BodyReplayedViaGetBody109=== CONT TestStaticToken110=== CONT TestSetClientTLSErrors111=== CONT TestSetClientTLS112=== CONT TestEncodeNixBase32WithRealHash113=== CONT TestStreamPushIsolatesFailures114=== CONT TestStreamPushBatchesUnderLoad115=== CONT TestResolveStorePath116=== CONT TestClientSignaturesByStorePath117=== CONT TestStreamPushReportsEveryPath118=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess119=== CONT TestShellSplitErrors120=== CONT TestStreamPushReportsSignatures121=== RUN TestRateLimiterFeedback/429_enables_limiter122--- PASS: TestScriptTokenScriptFails (0.00s)123=== PAUSE TestRateLimiterFeedback/429_enables_limiter124--- PASS: TestFileTokenMissing (0.00s)125--- PASS: TestFileTokenReadsAndCaches (0.00s)126--- PASS: TestFileTokenEmpty (0.00s)127--- PASS: TestStaticToken (0.00s)128=== CONT TestFilterOversizedClosures129=== CONT TestPathInfoCACompatibility130=== RUN TestFilterOversizedClosures/no_limit_keeps_everything131=== RUN TestPathInfoCACompatibility/null_ca_field132=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything133=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped134=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped135=== RUN TestFilterOversizedClosures/all_closures_skipped136=== PAUSE TestFilterOversizedClosures/all_closures_skipped137--- PASS: TestEncodeNixBase32WithRealHash (0.00s)138=== PAUSE TestPathInfoCACompatibility/null_ca_field139=== RUN TestPathInfoCACompatibility/old_string_format_-_text140=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text141=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive142=== CONT TestShellSplit143=== CONT TestStreamPushGivesUpOnDeadServer144--- PASS: TestScriptTokenBadJSON (0.00s)145=== CONT TestUploadMultipart_PartsInParallel146=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive147=== RUN TestPathInfoCACompatibility/new_structured_format_-_text148=== RUN TestRateLimiterFeedback/503_enables_limiter149=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text150=== CONT TestPartSizeForNAR151=== CONT TestStreamPushRequestLine152=== CONT TestCaseHackSuffix1532026/10/01 07:38:04 ERROR Upload failed error="connection refused" count=201542026/10/01 07:38:04 ERROR Server seems unavailable, giving up on batch untried=17155=== CONT TestPathInfoHashCompatibility1562026/10/01 07:38:04 ERROR Upload failed error="bad path" count=3157--- PASS: TestShellSplitErrors (0.00s)158--- PASS: TestShellSplit (0.00s)159=== CONT TestGetStorePathHash1602026/10/01 07:38:04 WARN Rate limiter enabled after throttle name=server-test rate=5161=== PAUSE TestRateLimiterFeedback/503_enables_limiter162--- PASS: TestClientSignaturesByStorePath (0.00s)163=== CONT TestParsePathInfoJSONMultiplePaths164--- PASS: TestStreamPushIsolatesFailures (0.00s)165=== CONT TestConvertHashToNix32166--- PASS: TestScriptTokenEmptyToken (0.01s)167=== RUN TestPartSizeForNAR/zero_stays_at_minimum168=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum1692026/10/01 07:38:04 WARN Rate limiter enabled after throttle name=server-test rate=51702026/10/01 07:38:04 ERROR Upload failed error=boom count=1171=== CONT TestParsePathInfoJSON172--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)173=== RUN TestParsePathInfoJSON/Nix_format174=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)1752026/10/01 07:38:04 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:36507176=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1772026/10/01 07:38:04 ERROR Upload failed error=boom count=1178=== CONT TestRegisterUploadedObjectReusesConnections179=== RUN TestConvertHashToNix32/SRI_format_to_Nix32180=== CONT TestDumpPathWriterError181=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32182=== PAUSE TestParsePathInfoJSON/Nix_format183=== RUN TestPartSizeForNAR/small_stays_at_minimum184=== RUN TestGetStorePathHash/valid_store_path185--- PASS: TestStreamPushReportsSignatures (0.00s)186=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method187=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter188=== CONT TestEncodeNixBase32189=== RUN TestEncodeNixBase32/test_string_hash190=== PAUSE TestEncodeNixBase32/test_string_hash191=== RUN TestEncodeNixBase32/empty_input192=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter193=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter194=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter195=== PAUSE TestEncodeNixBase32/empty_input196=== CONT TestUploadMultipart_SupersededByPeer197=== RUN TestUploadMultipart_SupersededByPeer/exists198=== PAUSE TestUploadMultipart_SupersededByPeer/exists199--- PASS: TestStreamPushReportsEveryPath (0.00s)200=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method201=== RUN TestSetClientTLSErrors/missing_cert_file202=== RUN TestSetClientTLS/rejects_connection_without_client_cert203=== RUN TestConvertHashToNix32/already_Nix32_format204=== PAUSE TestConvertHashToNix32/already_Nix32_format205=== RUN TestConvertHashToNix32/invalid_format206=== PAUSE TestConvertHashToNix32/invalid_format207=== CONT TestFilterOversizedClosures/no_limit_keeps_everything208=== CONT TestFilterOversizedClosures/all_closures_skipped2092026/10/01 07:38:04 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=50210=== CONT TestRateLimiterFeedback/429_enables_limiter211=== PAUSE TestSetClientTLSErrors/missing_cert_file212=== RUN TestSetClientTLSErrors/missing_key_file213=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2142026/10/01 07:38:04 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=2000215=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter216=== CONT TestDumpPathMatchesNix217=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert218=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA219=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA220=== RUN TestSetClientTLS/preserves_debug_logging_transport221=== PAUSE TestPartSizeForNAR/small_stays_at_minimum222=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum223=== RUN TestUploadMultipart_SupersededByPeer/missing224=== PAUSE TestUploadMultipart_SupersededByPeer/missing225=== PAUSE TestSetClientTLS/preserves_debug_logging_transport2262026/10/01 07:38:04 WARN Rate limiter enabled after throttle name=server-test rate=5227=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2282026/10/01 07:38:04 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:45665229=== CONT TestRateLimiterFeedback/503_enables_limiter230=== CONT TestDumpPathSingleFile2312026/10/01 07:38:04 WARN Rate limiter backed off name=server-test rate=5232=== CONT TestConvertHashToNix32/SRI_format_to_Nix32233=== CONT TestEncodeNixBase32/empty_input234=== CONT TestPathInfoCACompatibility/null_ca_field235=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method236=== CONT TestPathInfoCACompatibility/new_structured_format_-_text2372026/10/01 07:38:04 WARN Rate limiter enabled after throttle name=server-test rate=5238=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2392026/10/01 07:38:04 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:35697240=== CONT TestPathInfoCACompatibility/old_string_format_-_text241=== CONT TestConvertHashToNix32/already_Nix32_format242=== CONT TestUploadMultipart_SupersededByPeer/exists243=== RUN TestParsePathInfoJSON/Lix_format244=== PAUSE TestParsePathInfoJSON/Lix_format2452026/10/01 07:38:04 WARN Rate limiter backed off name=server-test rate=5246=== RUN TestParsePathInfoJSON/empty_input247=== PAUSE TestParsePathInfoJSON/empty_input248=== RUN TestParsePathInfoJSON/whitespace_only249=== PAUSE TestParsePathInfoJSON/whitespace_only250=== RUN TestParsePathInfoJSON/invalid_JSON251=== PAUSE TestParsePathInfoJSON/invalid_JSON252=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths253=== CONT TestUploadMultipart_SupersededByPeer/missing2542026/10/01 07:38:04 WARN Rate limiter backed off name=server-test rate=5255=== CONT TestConvertHashToNix32/invalid_format2562026/10/01 07:38:04 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:36507257=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths258=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths259=== CONT TestParsePathInfoJSON/whitespace_only260=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum261=== CONT TestSetClientTLS/rejects_connection_without_client_cert262=== CONT TestParsePathInfoJSON/empty_input263=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths264=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths265=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts266=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts267=== RUN TestPartSizeForNAR/1_TiB268=== PAUSE TestPartSizeForNAR/1_TiB269=== RUN TestPartSizeForNAR/5_TiB_S3_max_object270=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object271=== RUN TestPartSizeForNAR/capped_at_5_GiB272=== PAUSE TestPartSizeForNAR/capped_at_5_GiB273=== CONT TestPartSizeForNAR/zero_stays_at_minimum274=== PAUSE TestGetStorePathHash/valid_store_path275=== RUN TestGetStorePathHash/basename_without_hyphen_should_error276=== CONT TestPartSizeForNAR/5_TiB_S3_max_object277=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts278=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum279=== CONT TestPartSizeForNAR/small_stays_at_minimum280=== CONT TestParsePathInfoJSON/Lix_format281=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error282=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error283=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error284=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error285=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error286=== CONT TestGetStorePathHash/valid_store_path287=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error288=== CONT TestPartSizeForNAR/1_TiB289=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error290=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA291=== CONT TestParsePathInfoJSON/Nix_format292=== CONT TestSetClientTLS/preserves_debug_logging_transport293=== CONT TestEncodeNixBase32/test_string_hash294=== CONT TestParsePathInfoJSON/invalid_JSON295=== CONT TestPartSizeForNAR/capped_at_5_GiB296--- PASS: TestResolveStorePath (0.00s)297--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)298--- PASS: TestFilterOversizedClosures (0.00s)299 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)300 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)301 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)302=== CONT TestGetStorePathHash/basename_without_hyphen_should_error303--- PASS: TestPathInfoCACompatibility (0.03s)304 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)305 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)306 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)307 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)308 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)309--- PASS: TestRateLimiterFeedback (0.04s)310 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)311 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)312 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)313 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)314--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)315--- PASS: TestConvertHashToNix32 (0.03s)316 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)317 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)318 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)319--- PASS: TestDoServerRequestAttachesToken (0.04s)320--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.04s)321--- PASS: TestParsePathInfoJSONMultiplePaths (0.03s)322 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)323 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)324--- PASS: TestGetStorePathHash (0.03s)325 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)326 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)327 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)328 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)329=== PAUSE TestSetClientTLSErrors/missing_key_file330=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)331--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)332--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)333 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)334 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)335--- PASS: TestParsePathInfoJSON (0.03s)336 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)337 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)338 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)339 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)340 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)341=== RUN TestSetClientTLSErrors/missing_ca_file342=== PAUSE TestSetClientTLSErrors/missing_ca_file343=== RUN TestSetClientTLSErrors/invalid_ca_file344=== PAUSE TestSetClientTLSErrors/invalid_ca_file345=== CONT TestSetClientTLSErrors/missing_cert_file346--- PASS: TestEncodeNixBase32 (0.00s)347 --- PASS: TestEncodeNixBase32/empty_input (0.00s)348 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)349=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon350=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon351=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI352=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI353--- PASS: TestPartSizeForNAR (0.03s)354 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)355 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)356 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)357 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)358 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)359 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)360 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)361=== CONT TestSetClientTLSErrors/invalid_ca_file362=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512363=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512364=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)365=== CONT TestSetClientTLSErrors/missing_key_file366=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512367=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI368=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon369--- PASS: TestPathInfoHashCompatibility (0.04s)370 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)371 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)372 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)373 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)374=== CONT TestSetClientTLSErrors/missing_ca_file375--- PASS: TestSetClientTLSErrors (0.05s)376 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)377 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)378 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)379 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)3802026/10/01 07:38:04 http: TLS handshake error from 127.0.0.1:47772: remote error: tls: bad certificate381--- PASS: TestSetClientTLS (0.03s)382 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)383 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)384 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)385--- PASS: TestRegisterUploadedObjectReusesConnections (0.06s)386--- PASS: TestCaseHackSuffix (0.06s)387--- PASS: TestStreamPushRequestLine (0.06s)388--- PASS: TestDumpPathSingleFile (0.03s)389--- PASS: TestDumpPathWriterError (0.07s)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/postgres3987678366/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/postgres3987678366/data -l logfile start422423/build/postgres3987678366:5432 - no response4242026-10-01 07:38:05.718 UTC [129] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 07:38:05.719 UTC [129] LOG: listening on Unix socket "/build/postgres3987678366/.s.PGSQL.5432"4262026-10-01 07:38:05.723 UTC [136] LOG: database system was shut down at 2026-10-01 07:38:05 UTC4272026-10-01 07:38:05.726 UTC [129] LOG: database system is ready to accept connections428/build/postgres3987678366:5432 - accepting connections429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestClientPushesUseOnePush462=== PAUSE TestClientPushesUseOnePush463=== RUN TestClientFallsBackToClosures464=== PAUSE TestClientFallsBackToClosures465=== RUN TestResolveDBConnectionString466=== PAUSE TestResolveDBConnectionString467=== RUN TestLeadElectsOneAndHandsOver468=== PAUSE TestLeadElectsOneAndHandsOver469=== RUN TestLeadIncumbentWinsAfterRestart4702026-10-01 07:38:06.102 UTC [376] ERROR: relation "goose_db_version" does not exist at character 364712026-10-01 07:38:06.102 UTC [376] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4722026/10/01 07:38:06 OK 20241026095416_initial_model.sql (9.75ms)4732026/10/01 07:38:06 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)4742026/10/01 07:38:06 OK 20251218171726_add_pins.sql (3ms)4752026/10/01 07:38:06 OK 20260628120000_add_object_size_and_stats.sql (2.69ms)4762026/10/01 07:38:06 OK 20260905000000_add_claims.sql (2.55ms)4772026/10/01 07:38:06 OK 20260920000000_drop_claims.sql (1.84ms)4782026/10/01 07:38:06 OK 20260923120000_add_pushes.sql (1.86ms)4792026/10/01 07:38:06 goose: successfully migrated database to version: 202609231200004802026/10/01 07:38:06 OK 1_commit_pending_closure.sql (1.88ms)4812026/10/01 07:38:06 OK 2_object_stats_trigger.sql (800.27µs)4822026/10/01 07:38:06 OK 3_commit_push.sql (775.81µs)4832026/10/01 07:38:06 goose: up to current file version: 34842026/10/01 07:38:06 INFO lead: acquired remote=192.0.2.1:12344852026/10/01 07:38:06 INFO lead: released remote=192.0.2.1:12344862026/10/01 07:38:06 INFO lead: acquired remote=192.0.2.1:12344872026/10/01 07:38:06 INFO lead: released remote=192.0.2.1:1234488--- PASS: TestLeadIncumbentWinsAfterRestart (0.79s)489=== RUN TestLeadEndsOnShutdown490=== PAUSE TestLeadEndsOnShutdown491=== RUN TestGCAdvisoryLockBlocksConcurrentRun4922026-10-01 07:38:06.870 UTC [388] ERROR: relation "goose_db_version" does not exist at character 364932026-10-01 07:38:06.870 UTC [388] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4942026/10/01 07:38:06 OK 20241026095416_initial_model.sql (9.01ms)4952026/10/01 07:38:06 OK 20251210153512_drop_unused_gin_index.sql (1.31ms)4962026/10/01 07:38:06 OK 20251218171726_add_pins.sql (3.49ms)4972026/10/01 07:38:06 OK 20260628120000_add_object_size_and_stats.sql (3.63ms)4982026/10/01 07:38:06 OK 20260905000000_add_claims.sql (2.8ms)4992026/10/01 07:38:06 OK 20260920000000_drop_claims.sql (1.73ms)5002026/10/01 07:38:06 OK 20260923120000_add_pushes.sql (1.34ms)5012026/10/01 07:38:06 goose: successfully migrated database to version: 202609231200005022026/10/01 07:38:06 OK 1_commit_pending_closure.sql (1.73ms)5032026/10/01 07:38:06 OK 2_object_stats_trigger.sql (655.19µs)5042026/10/01 07:38:06 OK 3_commit_push.sql (539.39µs)5052026/10/01 07:38:06 goose: up to current file version: 3506--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.12s)507=== RUN TestGCBugBareHashReferences508=== PAUSE TestGCBugBareHashReferences509=== RUN TestGCMetrics510=== PAUSE TestGCMetrics511=== RUN TestPushDedupSurvivesConcurrentGC512=== PAUSE TestPushDedupSurvivesConcurrentGC513=== RUN TestDeduplicatedObjectsRecordedAsPending514=== PAUSE TestDeduplicatedObjectsRecordedAsPending515=== RUN TestGCSweepSkipsPendingObjects516=== PAUSE TestGCSweepSkipsPendingObjects517=== RUN TestTombstonedObjectOfferedWithoutWaiting518=== PAUSE TestTombstonedObjectOfferedWithoutWaiting519=== RUN TestGCSweepDeliversEachKeyOnce520=== PAUSE TestGCSweepDeliversEachKeyOnce521=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection522=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== RUN TestFailedS3DeleteKeepsTombstone524=== PAUSE TestFailedS3DeleteKeepsTombstone525=== RUN TestSweepSkipsRowsLockedByPush526=== PAUSE TestSweepSkipsRowsLockedByPush527=== RUN TestRegisterCompletedObjectNeedsPendingRow528=== PAUSE TestRegisterCompletedObjectNeedsPendingRow529=== RUN TestGetExistingObjectsLocksRows530=== PAUSE TestGetExistingObjectsLocksRows531=== RUN TestGCTaskStore_StartNew532=== PAUSE TestGCTaskStore_StartNew533=== RUN TestGCTaskStore_DeduplicateSameParams534=== PAUSE TestGCTaskStore_DeduplicateSameParams535=== RUN TestGCTaskStore_ConflictDifferentParams536=== PAUSE TestGCTaskStore_ConflictDifferentParams537=== RUN TestGCTaskStore_GetEmpty538=== PAUSE TestGCTaskStore_GetEmpty539=== RUN TestGCTaskStore_GetReturnsLatest540=== PAUSE TestGCTaskStore_GetReturnsLatest541=== RUN TestGCTaskStore_CompletedAllowsNewTask542=== PAUSE TestGCTaskStore_CompletedAllowsNewTask543=== RUN TestGCTaskStore_PhaseUpdates544=== PAUSE TestGCTaskStore_PhaseUpdates545=== RUN TestGCTaskStore_Fail546=== PAUSE TestGCTaskStore_Fail547=== RUN TestGracefulShutdownDrainsInflight548=== PAUSE TestGracefulShutdownDrainsInflight549=== RUN TestService_healthCheckHandler550=== PAUSE TestService_healthCheckHandler551=== RUN TestService_readinessHandler552=== PAUSE TestService_readinessHandler553=== RUN TestGenerateLandingPage554=== PAUSE TestGenerateLandingPage555=== RUN TestCacheConfigHandlerMaxNarSize556=== PAUSE TestCacheConfigHandlerMaxNarSize557=== RUN TestCreatePendingClosureRejectsOversizedNAR558=== PAUSE TestCreatePendingClosureRejectsOversizedNAR559=== RUN TestNARDeduplicationMetadataUploadBug560=== PAUSE TestNARDeduplicationMetadataUploadBug561=== RUN TestMetricsInventory562=== PAUSE TestMetricsInventory563=== RUN TestService_NativeMTLS564=== PAUSE TestService_NativeMTLS565=== RUN TestServerTLSConfig566=== PAUSE TestServerTLSConfig567=== RUN TestMultipartCleanup568=== PAUSE TestMultipartCleanup569=== RUN TestObjectStatsTrigger570=== PAUSE TestObjectStatsTrigger571=== RUN TestOrphanedObjectsGC572=== PAUSE TestOrphanedObjectsGC573=== RUN TestOrphanedObjectsGCStressTest574=== PAUSE TestOrphanedObjectsGCStressTest575=== RUN TestCreatePin_ReservedPins576=== PAUSE TestCreatePin_ReservedPins577=== RUN TestParseSingleRange578=== PAUSE TestParseSingleRange579=== RUN TestProxyHeadersOnlyTrustedOnSocket580=== PAUSE TestProxyHeadersOnlyTrustedOnSocket581=== RUN TestIsValidCachePath582=== PAUSE TestIsValidCachePath583=== RUN TestReadProxyNarinfo584=== PAUSE TestReadProxyNarinfo585=== RUN TestReadProxyNarinfoAlreadyDecompressed586=== PAUSE TestReadProxyNarinfoAlreadyDecompressed587=== RUN TestReadProxyNarStreaming588=== PAUSE TestReadProxyNarStreaming589=== RUN TestReadProxy404590=== PAUSE TestReadProxy404591=== RUN TestReadProxyInvalidPath592=== PAUSE TestReadProxyInvalidPath593=== RUN TestReadProxyHead594=== PAUSE TestReadProxyHead595=== RUN TestReadProxyConditionalGet596=== PAUSE TestReadProxyConditionalGet597=== RUN TestReadProxyRootRedirectsToIndexHTML598=== PAUSE TestReadProxyRootRedirectsToIndexHTML599=== RUN TestReadProxyDisabled600=== PAUSE TestReadProxyDisabled601=== RUN TestReadRedirectNar602=== PAUSE TestReadRedirectNar603=== RUN TestReadRedirectKeepsNarinfoProxied604=== PAUSE TestReadRedirectKeepsNarinfoProxied605=== RUN TestReadProxyRangeRequest606=== PAUSE TestReadProxyRangeRequest607=== RUN TestReadRedirectUsesPublicS3URL608=== PAUSE TestReadRedirectUsesPublicS3URL609=== RUN TestPush_OverlappingRootsStoreOneRowPerKey610=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey611=== RUN TestPush_CompleteCommitsEveryRoot612=== PAUSE TestPush_CompleteCommitsEveryRoot613=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit614=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit615=== RUN TestPush_RejectsBadRequests616=== PAUSE TestPush_RejectsBadRequests617=== RUN TestPush_SignsNarinfosOfItsPendingObjects618=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects619=== RUN TestRedundantMultipartUpload620=== PAUSE TestRedundantMultipartUpload621=== RUN TestCompleteMultipartUpload_ErrorButObjectExists622=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists623=== RUN TestCompletedNarNotReofferedAcrossClosures624=== PAUSE TestCompletedNarNotReofferedAcrossClosures625=== RUN TestPresignedUploadRegisteredBeforeCommit626=== PAUSE TestPresignedUploadRegisteredBeforeCommit627=== RUN TestService_Rustfstest628=== PAUSE TestService_Rustfstest629=== RUN TestParseSize630=== PAUSE TestParseSize631=== RUN TestSkippedUploadsHandler632=== PAUSE TestSkippedUploadsHandler633=== RUN TestSystemdListenerNotActivated634--- PASS: TestSystemdListenerNotActivated (0.00s)635=== RUN TestWatchdogBeatsWhenHealthy636--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)637=== RUN TestWatchdogSkipsWhenUnhealthy6382026/10/01 07:38:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6392026/10/01 07:38:06 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6402026/10/01 07:38:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6412026/10/01 07:38:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6422026/10/01 07:38:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6432026/10/01 07:38:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6442026/10/01 07:38:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6452026/10/01 07:38:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6462026/10/01 07:38:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6472026/10/01 07:38:07 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"648--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)649=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle650=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle651=== RUN TestProxyWriteTimeout652=== PAUSE TestProxyWriteTimeout653=== RUN TestIsValidUploadKey654=== PAUSE TestIsValidUploadKey655=== RUN TestUploadHandlersRejectInvalidKeys656=== PAUSE TestUploadHandlersRejectInvalidKeys657=== RUN TestUploadHandlersRejectOversizedBody658=== PAUSE TestUploadHandlersRejectOversizedBody659=== RUN TestService_cleanupPendingClosuresHandler660=== PAUSE TestService_cleanupPendingClosuresHandler661=== RUN TestService_createPendingClosureHandler662=== PAUSE TestService_createPendingClosureHandler663=== RUN TestService_verifyS3Integrity664=== PAUSE TestService_verifyS3Integrity665=== RUN TestCompleteMultipartUnregistered666=== PAUSE TestCompleteMultipartUnregistered667=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT668=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT669=== CONT TestProxyWriteTimeout670=== CONT TestParseSize671=== CONT TestService_verifyS3Integrity672=== CONT TestService_createPendingClosureHandler673=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle674=== CONT TestSkippedUploadsHandler675=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT676=== CONT TestCompleteMultipartUnregistered677=== CONT TestGracefulShutdownDrainsInflight6782026/10/01 07:38:07 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000679=== CONT TestService_Rustfstest680=== CONT TestPresignedUploadRegisteredBeforeCommit6812026/10/01 07:38:07 INFO Starting HTTP server address=127.0.0.1:33261682=== CONT TestCompletedNarNotReofferedAcrossClosures683=== RUN TestProxyWriteTimeout/narinfo684=== PAUSE TestProxyWriteTimeout/narinfo685=== CONT TestCompleteMultipartUpload_ErrorButObjectExists686=== CONT TestService_AuthMiddleware687=== CONT TestRedundantMultipartUpload6882026/10/01 07:38:07 INFO Shutdown signal received, draining in-flight requests timeout=10s689--- PASS: TestParseSize (0.00s)690=== CONT TestPush_SignsNarinfosOfItsPendingObjects691=== CONT TestService_cleanupPendingClosuresHandler692=== CONT TestLeadEndsOnShutdown693=== CONT TestPush_RejectsBadRequests694=== CONT TestUploadHandlersRejectOversizedBody695=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit696=== CONT TestUploadHandlersRejectInvalidKeys697=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info698=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info699=== CONT TestPush_CompleteCommitsEveryRoot700=== CONT TestIsValidUploadKey701=== RUN TestIsValidUploadKey/narinfo702=== CONT TestLeadElectsOneAndHandsOver703=== RUN TestProxyWriteTimeout/1_GiB_nar704=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal705=== PAUSE TestIsValidUploadKey/narinfo706=== RUN TestIsValidUploadKey/nar_zst707=== PAUSE TestProxyWriteTimeout/1_GiB_nar708=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal709=== PAUSE TestIsValidUploadKey/nar_zst710=== RUN TestProxyWriteTimeout/10_GiB_nar711=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key712=== PAUSE TestProxyWriteTimeout/10_GiB_nar713=== RUN TestProxyWriteTimeout/unknown_size714=== PAUSE TestProxyWriteTimeout/unknown_size715=== RUN TestIsValidUploadKey/nar_xz716=== PAUSE TestIsValidUploadKey/nar_xz717=== RUN TestIsValidUploadKey/nar_plain718=== PAUSE TestIsValidUploadKey/nar_plain719=== RUN TestIsValidUploadKey/listing720=== PAUSE TestIsValidUploadKey/listing721=== RUN TestIsValidUploadKey/build_log722=== PAUSE TestIsValidUploadKey/build_log723=== RUN TestIsValidUploadKey/build_log_home-manager_file724=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key725=== CONT TestPush_OverlappingRootsStoreOneRowPerKey726=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key727=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key728=== CONT TestParseSingleRange729=== RUN TestParseSingleRange/none730=== PAUSE TestParseSingleRange/none731=== PAUSE TestIsValidUploadKey/build_log_home-manager_file732=== RUN TestParseSingleRange/unknown_unit733=== RUN TestIsValidUploadKey/build_log_plus_in_name734--- PASS: TestSkippedUploadsHandler (0.01s)735=== CONT TestGCBugBareHashReferences736=== PAUSE TestParseSingleRange/unknown_unit737=== PAUSE TestIsValidUploadKey/build_log_plus_in_name738=== RUN TestParseSingleRange/multi-range_ignored739=== RUN TestIsValidUploadKey/build_log_question_mark740=== PAUSE TestIsValidUploadKey/build_log_question_mark741=== PAUSE TestParseSingleRange/multi-range_ignored742=== RUN TestIsValidUploadKey/build_log_equals743=== PAUSE TestIsValidUploadKey/build_log_equals744=== RUN TestParseSingleRange/malformed_no_dash745=== PAUSE TestParseSingleRange/malformed_no_dash746=== RUN TestParseSingleRange/malformed_both_empty747=== PAUSE TestParseSingleRange/malformed_both_empty748=== RUN TestParseSingleRange/malformed_end_before_start749=== PAUSE TestParseSingleRange/malformed_end_before_start750=== RUN TestParseSingleRange/closed751=== RUN TestIsValidUploadKey/realisation752=== PAUSE TestParseSingleRange/closed753=== RUN TestParseSingleRange/open-ended754=== PAUSE TestParseSingleRange/open-ended755=== PAUSE TestIsValidUploadKey/realisation756=== RUN TestParseSingleRange/end_clamped_to_size757=== RUN TestIsValidUploadKey/realisation_plus_in_output758=== PAUSE TestParseSingleRange/end_clamped_to_size759=== PAUSE TestIsValidUploadKey/realisation_plus_in_output760=== RUN TestIsValidUploadKey/nix-cache-info761=== PAUSE TestIsValidUploadKey/nix-cache-info762=== RUN TestIsValidUploadKey/index.html763=== PAUSE TestIsValidUploadKey/index.html764=== RUN TestParseSingleRange/suffix765=== RUN TestIsValidUploadKey/narinfo_key,_nar_type766=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type767=== RUN TestIsValidUploadKey/nar_key,_narinfo_type768=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type769=== RUN TestIsValidUploadKey/listing_key,_narinfo_type770=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type771=== RUN TestIsValidUploadKey/traversal772=== PAUSE TestIsValidUploadKey/traversal773=== RUN TestIsValidUploadKey/traversal_nar774=== PAUSE TestIsValidUploadKey/traversal_nar775=== RUN TestIsValidUploadKey/absolute776=== PAUSE TestIsValidUploadKey/absolute777=== RUN TestIsValidUploadKey/empty_key778=== PAUSE TestIsValidUploadKey/empty_key779=== PAUSE TestParseSingleRange/suffix780=== RUN TestIsValidUploadKey/unknown_type781=== RUN TestParseSingleRange/suffix_exceeds_size782=== PAUSE TestIsValidUploadKey/unknown_type783=== PAUSE TestParseSingleRange/suffix_exceeds_size784=== RUN TestParseSingleRange/single_byte785=== PAUSE TestParseSingleRange/single_byte786=== RUN TestParseSingleRange/start_past_EOF787=== PAUSE TestParseSingleRange/start_past_EOF788=== RUN TestParseSingleRange/start_far_past_EOF789=== PAUSE TestParseSingleRange/start_far_past_EOF790=== CONT TestResolveDBConnectionString791=== CONT TestReadRedirectUsesPublicS3URL792=== RUN TestResolveDBConnectionString/flag_wins793=== PAUSE TestResolveDBConnectionString/flag_wins794=== RUN TestResolveDBConnectionString/file_when_flag_empty795=== PAUSE TestResolveDBConnectionString/file_when_flag_empty796=== RUN TestResolveDBConnectionString/missing_file_is_an_error797=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error798=== RUN TestResolveDBConnectionString/PGHOST_allows_empty799=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty800=== RUN TestResolveDBConnectionString/nothing_configured801=== PAUSE TestResolveDBConnectionString/nothing_configured802=== CONT TestGCTaskStore_Fail803--- PASS: TestGCTaskStore_Fail (0.00s)804=== CONT TestReadProxyRangeRequest805--- PASS: TestGracefulShutdownDrainsInflight (0.14s)806=== CONT TestReadRedirectKeepsNarinfoProxied807=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure808=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure809=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart810=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart811=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts812=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts813=== CONT TestReadRedirectNar8142026-10-01 07:38:07.383 UTC [456] ERROR: relation "goose_db_version" does not exist at character 368152026-10-01 07:38:07.383 UTC [456] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8162026-10-01 07:38:07.385 UTC [457] ERROR: relation "goose_db_version" does not exist at character 368172026-10-01 07:38:07.385 UTC [457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8182026-10-01 07:38:07.385 UTC [458] ERROR: relation "goose_db_version" does not exist at character 368192026-10-01 07:38:07.385 UTC [458] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8202026-10-01 07:38:07.386 UTC [459] ERROR: relation "goose_db_version" does not exist at character 368212026-10-01 07:38:07.386 UTC [459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8222026-10-01 07:38:07.386 UTC [460] ERROR: relation "goose_db_version" does not exist at character 368232026-10-01 07:38:07.386 UTC [460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8242026-10-01 07:38:07.386 UTC [461] ERROR: relation "goose_db_version" does not exist at character 368252026-10-01 07:38:07.386 UTC [461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8262026-10-01 07:38:07.387 UTC [462] ERROR: relation "goose_db_version" does not exist at character 368272026-10-01 07:38:07.387 UTC [462] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8282026-10-01 07:38:07.391 UTC [463] ERROR: relation "goose_db_version" does not exist at character 368292026-10-01 07:38:07.391 UTC [463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8302026-10-01 07:38:07.394 UTC [464] ERROR: relation "goose_db_version" does not exist at character 368312026-10-01 07:38:07.394 UTC [464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8322026-10-01 07:38:07.426 UTC [465] ERROR: relation "goose_db_version" does not exist at character 368332026-10-01 07:38:07.426 UTC [465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8342026-10-01 07:38:07.426 UTC [466] ERROR: relation "goose_db_version" does not exist at character 368352026-10-01 07:38:07.426 UTC [466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8362026-10-01 07:38:07.427 UTC [467] ERROR: relation "goose_db_version" does not exist at character 368372026-10-01 07:38:07.427 UTC [467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8382026-10-01 07:38:07.427 UTC [471] ERROR: relation "goose_db_version" does not exist at character 368392026-10-01 07:38:07.427 UTC [471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8402026-10-01 07:38:07.444 UTC [472] ERROR: relation "goose_db_version" does not exist at character 368412026-10-01 07:38:07.444 UTC [472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8422026-10-01 07:38:07.447 UTC [473] ERROR: relation "goose_db_version" does not exist at character 368432026-10-01 07:38:07.447 UTC [473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8442026-10-01 07:38:07.447 UTC [474] ERROR: relation "goose_db_version" does not exist at character 368452026-10-01 07:38:07.447 UTC [474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8462026/10/01 07:38:07 OK 20241026095416_initial_model.sql (27.64ms)8472026-10-01 07:38:07.448 UTC [475] ERROR: relation "goose_db_version" does not exist at character 368482026-10-01 07:38:07.448 UTC [475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8492026/10/01 07:38:07 OK 20241026095416_initial_model.sql (27.21ms)8502026/10/01 07:38:07 OK 20241026095416_initial_model.sql (27.91ms)8512026/10/01 07:38:07 OK 20241026095416_initial_model.sql (28.37ms)8522026/10/01 07:38:07 OK 20241026095416_initial_model.sql (28.82ms)8532026/10/01 07:38:07 OK 20241026095416_initial_model.sql (27.72ms)8542026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.83ms)8552026/10/01 07:38:07 OK 20241026095416_initial_model.sql (28.17ms)8562026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.96ms)8572026/10/01 07:38:07 OK 20241026095416_initial_model.sql (28.8ms)8582026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.87ms)8592026/10/01 07:38:07 OK 20241026095416_initial_model.sql (29.3ms)8602026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (3.01ms)8612026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (3.03ms)8622026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (3.06ms)8632026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (3.27ms)8642026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.65ms)8652026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (3.4ms)8662026/10/01 07:38:07 OK 20251218171726_add_pins.sql (4.62ms)8672026/10/01 07:38:07 OK 20251218171726_add_pins.sql (5.41ms)8682026/10/01 07:38:07 OK 20251218171726_add_pins.sql (5.51ms)8692026/10/01 07:38:07 OK 20251218171726_add_pins.sql (4.73ms)8702026/10/01 07:38:07 OK 20251218171726_add_pins.sql (4.8ms)8712026/10/01 07:38:07 OK 20251218171726_add_pins.sql (6.47ms)8722026-10-01 07:38:07.461 UTC [476] ERROR: relation "goose_db_version" does not exist at character 368732026-10-01 07:38:07.461 UTC [476] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8742026/10/01 07:38:07 OK 20251218171726_add_pins.sql (5.77ms)8752026-10-01 07:38:07.462 UTC [477] ERROR: relation "goose_db_version" does not exist at character 368762026-10-01 07:38:07.462 UTC [477] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8772026/10/01 07:38:07 OK 20251218171726_add_pins.sql (5.56ms)8782026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (5.41ms)8792026/10/01 07:38:07 OK 20251218171726_add_pins.sql (6.66ms)8802026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (5.54ms)8812026/10/01 07:38:07 OK 20241026095416_initial_model.sql (16.71ms)8822026/10/01 07:38:07 OK 20241026095416_initial_model.sql (15.49ms)8832026/10/01 07:38:07 OK 20241026095416_initial_model.sql (15.93ms)8842026/10/01 07:38:07 OK 20241026095416_initial_model.sql (16.02ms)8852026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (6.6ms)8862026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (6.68ms)8872026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (6.72ms)8882026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.63ms)8892026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (5.89ms)8902026-10-01 07:38:07.466 UTC [478] ERROR: relation "goose_db_version" does not exist at character 368912026-10-01 07:38:07.466 UTC [478] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8922026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.2ms)8932026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.99ms)8942026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (3.62ms)8952026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.95ms)8962026/10/01 07:38:07 OK 20260905000000_add_claims.sql (5.15ms)8972026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (6.39ms)8982026/10/01 07:38:07 OK 20241026095416_initial_model.sql (12.13ms)8992026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (5.63ms)9002026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (5.6ms)9012026/10/01 07:38:07 OK 20260905000000_add_claims.sql (3.6ms)9022026-10-01 07:38:07.469 UTC [479] ERROR: relation "goose_db_version" does not exist at character 369032026-10-01 07:38:07.469 UTC [479] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9042026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.35ms)9052026/10/01 07:38:07 OK 20241026095416_initial_model.sql (12.9ms)9062026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.01ms)9072026/10/01 07:38:07 OK 20260905000000_add_claims.sql (5.04ms)9082026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.52ms)9092026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.62ms)9102026-10-01 07:38:07.470 UTC [480] ERROR: relation "goose_db_version" does not exist at character 369112026-10-01 07:38:07.470 UTC [480] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9122026/10/01 07:38:07 OK 20251218171726_add_pins.sql (5.15ms)9132026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.37ms)9142026/10/01 07:38:07 OK 20251218171726_add_pins.sql (4.44ms)9152026/10/01 07:38:07 OK 20241026095416_initial_model.sql (15.05ms)9162026/10/01 07:38:07 OK 20241026095416_initial_model.sql (12.87ms)9172026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.21ms)9182026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.15ms)9192026/10/01 07:38:07 OK 20260905000000_add_claims.sql (3.98ms)9202026/10/01 07:38:07 OK 20251218171726_add_pins.sql (5.06ms)9212026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (2.75ms)9222026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.26ms)9232026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (2.46ms)9242026/10/01 07:38:07 OK 20251218171726_add_pins.sql (5.57ms)9252026/10/01 07:38:07 OK 20260905000000_add_claims.sql (5.55ms)9262026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.29ms)9272026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (3.33ms)9282026/10/01 07:38:07 goose: successfully migrated database to version: 202609231200009292026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.76ms)9302026/10/01 07:38:07 goose: successfully migrated database to version: 202609231200009312026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)9322026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.21ms)9332026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.55ms)9342026/10/01 07:38:07 goose: successfully migrated database to version: 202609231200009352026/10/01 07:38:07 OK 20251218171726_add_pins.sql (4.09ms)9362026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.28ms)9372026/10/01 07:38:07 goose: successfully migrated database to version: 202609231200009382026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.69ms)9392026/10/01 07:38:07 goose: successfully migrated database to version: 202609231200009402026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)9412026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.56ms)9422026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (3.15ms)9432026/10/01 07:38:07 goose: successfully migrated database to version: 202609231200009442026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (4.54ms)9452026/10/01 07:38:07 OK 20251218171726_add_pins.sql (5.07ms)9462026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (5.26ms)9472026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.92ms)9482026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (5.3ms)9492026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.42ms)9502026/10/01 07:38:07 OK 1_commit_pending_closure.sql (3.66ms)9512026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (4.37ms)9522026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.45ms)9532026/10/01 07:38:07 OK 1_commit_pending_closure.sql (3.6ms)9542026/10/01 07:38:07 OK 20251218171726_add_pins.sql (4.13ms)9552026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (5.44ms)9562026/10/01 07:38:07 OK 20251218171726_add_pins.sql (4.27ms)9572026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (3.11ms)9582026/10/01 07:38:07 OK 20260905000000_add_claims.sql (3.98ms)9592026/10/01 07:38:07 goose: successfully migrated database to version: 202609231200009602026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.81ms)9612026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (4.77ms)9622026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.53ms)9632026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.89ms)9642026/10/01 07:38:07 OK 2_object_stats_trigger.sql (2.71ms)9652026/10/01 07:38:07 OK 2_object_stats_trigger.sql (2.6ms)9662026/10/01 07:38:07 OK 2_object_stats_trigger.sql (2.81ms)9672026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (3.61ms)9682026/10/01 07:38:07 goose: successfully migrated database to version: 202609231200009692026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.87ms)9702026/10/01 07:38:07 goose: successfully migrated database to version: 202609231200009712026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.78ms)9722026/10/01 07:38:07 OK 3_commit_push.sql (1.9ms)9732026/10/01 07:38:07 goose: up to current file version: 39742026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (4.27ms)9752026/10/01 07:38:07 OK 1_commit_pending_closure.sql (3.09ms)9762026/10/01 07:38:07 OK 20260905000000_add_claims.sql (5.41ms)9772026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.1ms)9782026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.84ms)9792026/10/01 07:38:07 OK 20241026095416_initial_model.sql (13.75ms)9802026/10/01 07:38:07 OK 3_commit_push.sql (1.84ms)9812026/10/01 07:38:07 goose: up to current file version: 39822026/10/01 07:38:07 OK 3_commit_push.sql (1.88ms)9832026/10/01 07:38:07 goose: up to current file version: 39842026/10/01 07:38:07 OK 3_commit_push.sql (2.89ms)9852026/10/01 07:38:07 goose: up to current file version: 39862026/10/01 07:38:07 OK 3_commit_push.sql (1.91ms)9872026/10/01 07:38:07 goose: up to current file version: 39882026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (4.04ms)9892026-10-01 07:38:07.484 UTC [481] ERROR: relation "goose_db_version" does not exist at character 369902026-10-01 07:38:07.484 UTC [481] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9912026/10/01 07:38:07 OK 3_commit_push.sql (2.59ms)9922026/10/01 07:38:07 goose: up to current file version: 39932026-10-01 07:38:07.484 UTC [482] ERROR: relation "goose_db_version" does not exist at character 369942026-10-01 07:38:07.484 UTC [482] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9952026/10/01 07:38:07 OK 1_commit_pending_closure.sql (3.35ms)9962026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.52ms)9972026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.04ms)9982026/10/01 07:38:07 OK 2_object_stats_trigger.sql (3.17ms)9992026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (7.22ms)10002026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.22ms)10012026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (7.37ms)10022026/10/01 07:38:07 OK 1_commit_pending_closure.sql (4.99ms)10032026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.46ms)10042026/10/01 07:38:07 OK 20241026095416_initial_model.sql (15.77ms)10052026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.49ms)10062026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (3.12ms)10072026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000010082026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (4.18ms)10092026/10/01 07:38:07 OK 2_object_stats_trigger.sql (3.56ms)10102026/10/01 07:38:07 OK 3_commit_push.sql (2.04ms)10112026/10/01 07:38:07 goose: up to current file version: 310122026/10/01 07:38:07 OK 2_object_stats_trigger.sql (2.13ms)10132026/10/01 07:38:07 OK 20241026095416_initial_model.sql (13.97ms)10142026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.2ms)10152026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000010162026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.85ms)10172026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000010182026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (4.5ms)10192026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.97ms)10202026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000010212026/10/01 07:38:07 OK 20241026095416_initial_model.sql (13.38ms)10222026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.37ms)10232026/10/01 07:38:07 OK 3_commit_push.sql (1.91ms)10242026/10/01 07:38:07 goose: up to current file version: 310252026/10/01 07:38:07 OK 3_commit_push.sql (1.8ms)10262026/10/01 07:38:07 goose: up to current file version: 310272026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (4.14ms)10282026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.15ms)10292026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (3.41ms)10302026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.14ms)10312026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.22ms)10322026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.57ms)10332026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000010342026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.68ms)10352026/10/01 07:38:07 OK 2_object_stats_trigger.sql (2.07ms)10362026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.72ms)10372026/10/01 07:38:07 OK 20241026095416_initial_model.sql (11.94ms)10382026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.34ms)10392026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.34ms)10402026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000010412026/10/01 07:38:07 OK 20251218171726_add_pins.sql (4.51ms)10422026/10/01 07:38:07 OK 1_commit_pending_closure.sql (3.16ms)10432026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (2.92ms)10442026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (2.91ms)10452026/10/01 07:38:07 OK 3_commit_push.sql (1.69ms)10462026/10/01 07:38:07 goose: up to current file version: 310472026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.7ms)10482026/10/01 07:38:07 OK 2_object_stats_trigger.sql (2.36ms)10492026/10/01 07:38:07 OK 20251218171726_add_pins.sql (3.8ms)10502026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.4ms)10512026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)10522026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.02ms)10532026/10/01 07:38:07 OK 20251218171726_add_pins.sql (3.65ms)10542026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.96ms)10552026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.08ms)10562026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000010572026/10/01 07:38:07 OK 20251218171726_add_pins.sql (3.54ms)10582026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.16ms)10592026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000010602026/10/01 07:38:07 OK 3_commit_push.sql (1.75ms)10612026/10/01 07:38:07 goose: up to current file version: 310622026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.99ms)10632026/10/01 07:38:07 OK 3_commit_push.sql (2.03ms)10642026/10/01 07:38:07 goose: up to current file version: 310652026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.9ms)10662026/10/01 07:38:07 OK 3_commit_push.sql (1.81ms)10672026/10/01 07:38:07 goose: up to current file version: 310682026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (3.97ms)10692026/10/01 07:38:07 OK 3_commit_push.sql (1.02ms)10702026/10/01 07:38:07 goose: up to current file version: 310712026/10/01 07:38:07 OK 3_commit_push.sql (1.29ms)10722026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.54ms)10732026/10/01 07:38:07 goose: up to current file version: 310742026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.48ms)10752026/10/01 07:38:07 OK 20251218171726_add_pins.sql (4.39ms)10762026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (4.63ms)10772026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (3.98ms)10782026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.14ms)10792026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (3.74ms)10802026/10/01 07:38:07 OK 20260905000000_add_claims.sql (2.58ms)10812026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.3ms)10822026/10/01 07:38:07 OK 3_commit_push.sql (1.28ms)10832026/10/01 07:38:07 goose: up to current file version: 310842026/10/01 07:38:07 OK 3_commit_push.sql (1.72ms)10852026/10/01 07:38:07 goose: up to current file version: 310862026/10/01 07:38:07 OK 20241026095416_initial_model.sql (10.37ms)10872026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (3.43ms)10882026/10/01 07:38:07 OK 20260905000000_add_claims.sql (3.41ms)10892026/10/01 07:38:07 OK 20241026095416_initial_model.sql (9.63ms)10902026/10/01 07:38:07 OK 20260905000000_add_claims.sql (3.35ms)10912026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (2.93ms)10922026/10/01 07:38:07 OK 20260905000000_add_claims.sql (3.16ms)10932026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (1.31ms)10942026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures10952026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)10962026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.58ms)10972026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000010982026/10/01 07:38:07 OK 20260905000000_add_claims.sql (2.75ms)10992026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.17ms)11002026/10/01 07:38:07 OK 20251218171726_add_pins.sql (2.84ms)11012026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.22ms)11022026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (3.08ms)11032026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (2.4ms)11042026/10/01 07:38:07 OK 20251218171726_add_pins.sql (3.3ms)11052026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.05ms)11062026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000011072026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.79ms)11082026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000011092026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.83ms)11102026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000011112026/10/01 07:38:07 OK 1_commit_pending_closure.sql (3.44ms)11122026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (3.38ms)11132026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (1.71ms)11142026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000011152026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.3ms)11162026/10/01 07:38:07 OK 1_commit_pending_closure.sql (1.58ms)11172026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.59ms)11182026/10/01 07:38:07 OK 1_commit_pending_closure.sql (1.82ms)11192026/10/01 07:38:07 OK 2_object_stats_trigger.sql (694.59µs)11202026/10/01 07:38:07 OK 2_object_stats_trigger.sql (706.97µs)11212026/10/01 07:38:07 OK 3_commit_push.sql (680.19µs)11222026/10/01 07:38:07 goose: up to current file version: 311232026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (3.46ms)11242026/10/01 07:38:07 OK 2_object_stats_trigger.sql (862.47µs)11252026/10/01 07:38:07 OK 1_commit_pending_closure.sql (1.95ms)11262026/10/01 07:38:07 OK 3_commit_push.sql (601.39µs)11272026/10/01 07:38:07 goose: up to current file version: 311282026/10/01 07:38:07 OK 3_commit_push.sql (637.67µs)11292026/10/01 07:38:07 goose: up to current file version: 311302026/10/01 07:38:07 OK 20260905000000_add_claims.sql (2.75ms)11312026/10/01 07:38:07 OK 3_commit_push.sql (596.65µs)11322026/10/01 07:38:07 goose: up to current file version: 311332026/10/01 07:38:07 OK 2_object_stats_trigger.sql (696.77µs)11342026/10/01 07:38:07 OK 3_commit_push.sql (389.28µs)11352026/10/01 07:38:07 goose: up to current file version: 311362026/10/01 07:38:07 OK 20260905000000_add_claims.sql (2.07ms)11372026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (1.5ms)11382026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (1.19ms)11392026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000011402026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (1.44ms)11412026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (1.42ms)11422026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000011432026/10/01 07:38:07 OK 1_commit_pending_closure.sql (1.7ms)11442026/10/01 07:38:07 OK 2_object_stats_trigger.sql (726.49µs)11452026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures11462026/10/01 07:38:07 OK 3_commit_push.sql (553.73µs)11472026/10/01 07:38:07 goose: up to current file version: 311482026/10/01 07:38:07 OK 1_commit_pending_closure.sql (1.65ms)11492026/10/01 07:38:07 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11502026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures11512026/10/01 07:38:07 OK 2_object_stats_trigger.sql (746.97µs)11522026/10/01 07:38:07 OK 3_commit_push.sql (483.26µs)11532026/10/01 07:38:07 goose: up to current file version: 31154--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.37s)1155=== CONT TestReadProxyDisabled11562026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures11572026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures11582026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures1159--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.40s)1160=== CONT TestReadProxyRootRedirectsToIndexHTML11612026/10/01 07:38:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11622026/10/01 07:38:07 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmRkYzhlYWMtZDAxMC00OWYwLTgwNTEtYTk3ZTRiMzQyMzJmLjNhMzhlMjU4LWE5MTYtNGFmYi04OTBiLWFlZTk3MDZhN2YzOHgxNzkwODQwMjg3NTM2NTk1NDUz11632026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures11642026/10/01 07:38:07 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmRkYzhlYWMtZDAxMC00OWYwLTgwNTEtYTk3ZTRiMzQyMzJmLjNhMzhlMjU4LWE5MTYtNGFmYi04OTBiLWFlZTk3MDZhN2YzOHgxNzkwODQwMjg3NTM2NTk1NDUz parts=11165--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.41s)1166=== CONT TestReadProxyConditionalGet11672026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures11682026-10-01 07:38:07.590 UTC [491] ERROR: relation "goose_db_version" does not exist at character 3611692026-10-01 07:38:07.590 UTC [491] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11702026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures11712026/10/01 07:38:07 OK 20241026095416_initial_model.sql (9.26ms)11722026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.24ms)11732026/10/01 07:38:07 OK 20251218171726_add_pins.sql (3.92ms)11742026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (4.36ms)11752026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures11762026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures11772026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures11782026/10/01 07:38:07 OK 20260905000000_add_claims.sql (3.61ms)11792026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (2.58ms)11802026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.83ms)11812026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000011822026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.24ms)11832026/10/01 07:38:07 OK 2_object_stats_trigger.sql (2.01ms)11842026/10/01 07:38:07 OK 3_commit_push.sql (1.38ms)11852026/10/01 07:38:07 goose: up to current file version: 311862026-10-01 07:38:07.634 UTC [492] ERROR: relation "goose_db_version" does not exist at character 3611872026-10-01 07:38:07.634 UTC [492] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11882026/10/01 07:38:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11892026/10/01 07:38:07 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1190--- PASS: TestCompleteMultipartUnregistered (0.49s)1191=== CONT TestReadProxyHead11922026-10-01 07:38:07.646 UTC [493] ERROR: relation "goose_db_version" does not exist at character 3611932026-10-01 07:38:07.646 UTC [493] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11942026/10/01 07:38:07 OK 20241026095416_initial_model.sql (10.39ms)11952026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (1.85ms)11962026/10/01 07:38:07 OK 20251218171726_add_pins.sql (4.07ms)11972026/10/01 07:38:07 OK 20241026095416_initial_model.sql (9.17ms)11982026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (3.4ms)11992026/10/01 07:38:07 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1200--- PASS: TestService_AuthMiddleware (0.51s)1201=== CONT TestReadProxyInvalidPath12022026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (1.82ms)12032026/10/01 07:38:07 OK 20260905000000_add_claims.sql (4.09ms)12042026/10/01 07:38:07 OK 20251218171726_add_pins.sql (3.44ms)12052026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (2.56ms)12062026/10/01 07:38:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12072026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (3.21ms)12082026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.23ms)12092026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000012102026/10/01 07:38:07 OK 20260905000000_add_claims.sql (3.19ms)12112026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.58ms)12122026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.55ms)12132026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (2.29ms)12142026/10/01 07:38:07 OK 3_commit_push.sql (1.17ms)12152026/10/01 07:38:07 goose: up to current file version: 312162026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (1.96ms)12172026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000012182026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.42ms)12192026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.49ms)12202026/10/01 07:38:07 OK 3_commit_push.sql (1.15ms)12212026/10/01 07:38:07 goose: up to current file version: 312222026/10/01 07:38:07 INFO Received push request method=POST path=/api/pushes12232026/10/01 07:38:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12242026/10/01 07:38:07 INFO Signed narinfos id=1 count=11225--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.54s)1226=== CONT TestReadProxy40412272026/10/01 07:38:07 INFO Received cleanup request method=DELETE path=/api/pending_closures12282026/10/01 07:38:07 INFO Aborted multipart uploads count=012292026/10/01 07:38:07 INFO Received uploads request method=POST path=/api/pending_closures12302026-10-01 07:38:07.711 UTC [500] ERROR: relation "goose_db_version" does not exist at character 3612312026-10-01 07:38:07.711 UTC [500] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12322026/10/01 07:38:07 INFO Received cleanup request method=DELETE path=/api/pending_closures1233=== RUN TestPush_RejectsBadRequests/no_roots1234=== PAUSE TestPush_RejectsBadRequests/no_roots1235=== RUN TestPush_RejectsBadRequests/no_objects1236=== PAUSE TestPush_RejectsBadRequests/no_objects1237=== RUN TestPush_RejectsBadRequests/bad_root1238=== PAUSE TestPush_RejectsBadRequests/bad_root1239=== RUN TestPush_RejectsBadRequests/root_not_in_objects1240=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1241=== CONT TestReadProxyNarStreaming12422026/10/01 07:38:07 INFO Aborted multipart uploads count=112432026/10/01 07:38:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12442026/10/01 07:38:07 OK 20241026095416_initial_model.sql (8.52ms)12452026-10-01 07:38:07.727 UTC [467] ERROR: Closure does not exist: id=112462026-10-01 07:38:07.727 UTC [467] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE12472026-10-01 07:38:07.727 UTC [467] STATEMENT: -- name: CommitPendingClosure :exec1248 SELECT commit_pending_closure($1::bigint)1249 1250--- PASS: TestService_cleanupPendingClosuresHandler (0.57s)1251=== CONT TestGCTaskStore_PhaseUpdates1252--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1253=== CONT TestReadProxyNarinfoAlreadyDecompressed12542026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (1.45ms)12552026/10/01 07:38:07 OK 20251218171726_add_pins.sql (3.77ms)12562026-10-01 07:38:07.734 UTC [503] ERROR: relation "goose_db_version" does not exist at character 3612572026-10-01 07:38:07.734 UTC [503] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12582026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)12592026/10/01 07:38:07 OK 20260905000000_add_claims.sql (2.73ms)12602026/10/01 07:38:07 OK 20260920000000_drop_claims.sql (2.88ms)12612026/10/01 07:38:07 OK 20260923120000_add_pushes.sql (2.43ms)12622026/10/01 07:38:07 goose: successfully migrated database to version: 2026092312000012632026/10/01 07:38:07 INFO lead: acquired remote=192.0.2.1:123412642026/10/01 07:38:07 INFO lead: released remote=192.0.2.1:12341265--- PASS: TestLeadEndsOnShutdown (0.59s)1266=== CONT TestGCTaskStore_CompletedAllowsNewTask1267--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1268=== CONT TestReadProxyNarinfo12692026/10/01 07:38:07 OK 1_commit_pending_closure.sql (2.76ms)12702026/10/01 07:38:07 OK 2_object_stats_trigger.sql (1.63ms)12712026/10/01 07:38:07 OK 3_commit_push.sql (1.46ms)12722026/10/01 07:38:07 goose: up to current file version: 312732026/10/01 07:38:07 OK 20241026095416_initial_model.sql (10.96ms)12742026/10/01 07:38:07 OK 20251210153512_drop_unused_gin_index.sql (2.12ms)12752026/10/01 07:38:07 OK 20251218171726_add_pins.sql (3.6ms)12762026/10/01 07:38:07 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)12772026/10/01 07:38:07 OK 20260905000000_add_claims.sql (235.56ms)12782026/10/01 07:38:07 INFO Received push request method=POST path=/api/pushes12792026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (3.85ms)12802026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (3.28ms)12812026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000012822026-10-01 07:38:08.010 UTC [509] ERROR: relation "goose_db_version" does not exist at character 3612832026-10-01 07:38:08.010 UTC [509] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12842026/10/01 07:38:08 OK 1_commit_pending_closure.sql (27.75ms)12852026/10/01 07:38:08 OK 2_object_stats_trigger.sql (2.33ms)12862026/10/01 07:38:08 OK 3_commit_push.sql (2.06ms)12872026/10/01 07:38:08 goose: up to current file version: 31288--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.88s)1289=== CONT TestGCTaskStore_GetReturnsLatest1290--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1291=== CONT TestIsValidCachePath1292=== RUN TestIsValidCachePath/narinfo1293=== PAUSE TestIsValidCachePath/narinfo1294=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1295=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1296=== RUN TestIsValidCachePath/nar_zst1297=== PAUSE TestIsValidCachePath/nar_zst1298=== RUN TestIsValidCachePath/nar_xz1299=== PAUSE TestIsValidCachePath/nar_xz1300=== RUN TestIsValidCachePath/nar_bz21301=== PAUSE TestIsValidCachePath/nar_bz21302=== RUN TestIsValidCachePath/nar_uncompressed1303=== PAUSE TestIsValidCachePath/nar_uncompressed1304=== RUN TestIsValidCachePath/ls1305=== PAUSE TestIsValidCachePath/ls1306=== RUN TestIsValidCachePath/log1307=== PAUSE TestIsValidCachePath/log1308=== RUN TestIsValidCachePath/realisation1309=== PAUSE TestIsValidCachePath/realisation1310=== RUN TestIsValidCachePath/nix-cache-info1311=== PAUSE TestIsValidCachePath/nix-cache-info1312=== RUN TestIsValidCachePath/index.html1313=== PAUSE TestIsValidCachePath/index.html1314=== RUN TestIsValidCachePath/traversal_parent1315=== PAUSE TestIsValidCachePath/traversal_parent1316=== RUN TestIsValidCachePath/traversal_in_middle1317=== PAUSE TestIsValidCachePath/traversal_in_middle1318=== RUN TestIsValidCachePath/invalid_char_e1319=== PAUSE TestIsValidCachePath/invalid_char_e1320=== RUN TestIsValidCachePath/invalid_char_u1321=== PAUSE TestIsValidCachePath/invalid_char_u1322=== RUN TestIsValidCachePath/random_path1323=== PAUSE TestIsValidCachePath/random_path1324=== RUN TestIsValidCachePath/empty1325=== PAUSE TestIsValidCachePath/empty1326=== RUN TestIsValidCachePath/leading_slash1327=== PAUSE TestIsValidCachePath/leading_slash1328=== RUN TestIsValidCachePath/wrong_extension1329=== PAUSE TestIsValidCachePath/wrong_extension1330=== RUN TestIsValidCachePath/short_hash1331=== PAUSE TestIsValidCachePath/short_hash1332=== CONT TestGCTaskStore_GetEmpty13332026/10/01 07:38:08 INFO Received push request method=POST path=/api/pushes1334--- PASS: TestGCTaskStore_GetEmpty (0.00s)1335=== CONT TestMetricsInventory13362026-10-01 07:38:08.043 UTC [512] ERROR: relation "goose_db_version" does not exist at character 3613372026-10-01 07:38:08.043 UTC [512] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13382026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.11ms)13392026-10-01 07:38:08.045 UTC [513] ERROR: relation "goose_db_version" does not exist at character 3613402026-10-01 07:38:08.045 UTC [513] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13412026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.44ms)13422026-10-01 07:38:08.046 UTC [515] ERROR: relation "goose_db_version" does not exist at character 3613432026-10-01 07:38:08.046 UTC [515] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13442026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.05ms)13452026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.82ms)13462026/10/01 07:38:08 INFO Received complete push request method=POST path=/api/pushes/1/complete13472026/10/01 07:38:08 OK 20260905000000_add_claims.sql (4.5ms)13482026/10/01 07:38:08 OK 20241026095416_initial_model.sql (9.86ms)13492026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.91ms)13502026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.01ms)13512026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.54ms)13522026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.89ms)13532026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000013542026/10/01 07:38:08 OK 20241026095416_initial_model.sql (12.64ms)13552026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)1356--- PASS: TestService_Rustfstest (0.91s)1357=== CONT TestGCTaskStore_ConflictDifferentParams1358--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1359=== CONT TestProxyHeadersOnlyTrustedOnSocket13602026/10/01 07:38:08 INFO Received push request method=POST path=/api/pushes13612026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.5ms)13622026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.96ms)13632026/10/01 07:38:08 OK 1_commit_pending_closure.sql (3.21ms)13642026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.77ms)13652026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.97ms)13662026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.37ms)13672026/10/01 07:38:08 OK 3_commit_push.sql (1.19ms)13682026/10/01 07:38:08 goose: up to current file version: 313692026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.75ms)13702026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.55ms)13712026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.81ms)13722026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.75ms)13732026/10/01 07:38:08 OK 20260905000000_add_claims.sql (2.74ms)13742026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (1.9ms)13752026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.55ms)13762026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.2ms)13772026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000013782026/10/01 07:38:08 OK 20260905000000_add_claims.sql (4.01ms)13792026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.4ms)13802026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000013812026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.88ms)13822026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (3.2ms)13832026/10/01 07:38:08 OK 2_object_stats_trigger.sql (2.22ms)13842026/10/01 07:38:08 OK 1_commit_pending_closure.sql (3.8ms)13852026/10/01 07:38:08 OK 3_commit_push.sql (1.69ms)13862026/10/01 07:38:08 goose: up to current file version: 313872026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (3.14ms)13882026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000013892026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.37ms)13902026/10/01 07:38:08 OK 3_commit_push.sql (1.35ms)13912026/10/01 07:38:08 goose: up to current file version: 313922026/10/01 07:38:08 OK 1_commit_pending_closure.sql (4.97ms)13932026/10/01 07:38:08 INFO lead: acquired remote=192.0.2.1:123413942026/10/01 07:38:08 OK 2_object_stats_trigger.sql (2.72ms)13952026/10/01 07:38:08 OK 3_commit_push.sql (1.91ms)13962026/10/01 07:38:08 goose: up to current file version: 313972026/10/01 07:38:08 INFO Received push request method=POST path=/api/pushes13982026-10-01 07:38:08.118 UTC [521] ERROR: relation "goose_db_version" does not exist at character 3613992026-10-01 07:38:08.118 UTC [521] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14002026/10/01 07:38:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14012026/10/01 07:38:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14022026/10/01 07:38:08 INFO Aborted multipart uploads count=014032026/10/01 07:38:08 WARN Force mode enabled - objects will be deleted immediately without grace period14042026/10/01 07:38:08 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MmRkYzhlYWMtZDAxMC00OWYwLTgwNTEtYTk3ZTRiMzQyMzJmLmQxZWU4NDdmLTEzYjUtNDY5Ny05MzIzLWU4MjAyYmYzNzc4OXgxNzkwODQwMjg3NTg2ODY4ODA2 parts=1014052026/10/01 07:38:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14062026/10/01 07:38:08 OK 20241026095416_initial_model.sql (9.4ms)14072026/10/01 07:38:08 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MmRkYzhlYWMtZDAxMC00OWYwLTgwNTEtYTk3ZTRiMzQyMzJmLmQ4ZWQ0OTVkLWIyNTItNDRhMC1hMTFjLWJlMmU4NDQ4ZDk0ZXgxNzkwODQwMjg3NTIzMzA2ODE5 parts=1214082026/10/01 07:38:08 INFO Completed upload id=114092026-10-01 07:38:08.144 UTC [534] ERROR: relation "goose_db_version" does not exist at character 3614102026-10-01 07:38:08.144 UTC [534] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14112026/10/01 07:38:08 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=014122026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.67ms)1413--- PASS: TestRedundantMultipartUpload (0.99s)1414=== CONT TestOrphanedObjectsGCStressTest14152026/10/01 07:38:08 INFO Received complete push request method=POST path=/api/pushes/1/complete14162026/10/01 07:38:08 INFO Received uploads request method=POST path=/api/pending_closures14172026/10/01 07:38:08 INFO Received uploads request method=POST path=/api/pending_closures14182026/10/01 07:38:08 INFO Vacuumed table table=pending_closures14192026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.3ms)14202026/10/01 07:38:08 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14212026/10/01 07:38:08 WARN Found objects in DB but missing from S3, will re-upload count=114222026/10/01 07:38:08 INFO Vacuumed table table=pending_objects14232026/10/01 07:38:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1424--- PASS: TestService_verifyS3Integrity (1.00s)1425=== CONT TestGCTaskStore_DeduplicateSameParams14262026/10/01 07:38:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1427--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1428=== CONT TestOrphanedObjectsGC14292026/10/01 07:38:08 INFO Vacuumed table table=multipart_uploads14302026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.32ms)14312026/10/01 07:38:08 INFO Vacuumed table table=closures14322026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.58ms)14332026/10/01 07:38:08 INFO Vacuumed table table=objects1434--- PASS: TestPush_CompleteCommitsEveryRoot (1.00s)1435=== CONT TestClientFallsBackToClosures14362026/10/01 07:38:08 INFO Received complete push request method=POST path=/api/pushes/2/complete14372026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.83ms)14382026/10/01 07:38:08 OK 20241026095416_initial_model.sql (9.04ms)14392026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (1.87ms)14402026/10/01 07:38:08 goose: successfully migrated database to version: 202609231200001441--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.00s)1442=== CONT TestObjectStatsTrigger14432026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.65ms)1444--- PASS: TestReadRedirectUsesPublicS3URL (0.94s)1445=== CONT TestClientPushesUseOnePush14462026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.39ms)14472026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.58ms)14482026/10/01 07:38:08 OK 2_object_stats_trigger.sql (2.26ms)14492026/10/01 07:38:08 OK 3_commit_push.sql (859.45µs)14502026/10/01 07:38:08 goose: up to current file version: 314512026/10/01 07:38:08 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MmRkYzhlYWMtZDAxMC00OWYwLTgwNTEtYTk3ZTRiMzQyMzJmLmM4NTA3NzQ3LWIxYWUtNDQ1NS1iNzcyLThlM2JlYTIyMWFhZHgxNzkwODQwMjg3NjI0NDA2NjY5 parts=1014522026/10/01 07:38:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14532026/10/01 07:38:08 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MmRkYzhlYWMtZDAxMC00OWYwLTgwNTEtYTk3ZTRiMzQyMzJmLjI0YzI3Yjg4LTA1YmQtNDg4MS1iMzBkLWNmMmM2NTA3YzgwNngxNzkwODQwMjg3NTY3MDExODc1 parts=1214542026/10/01 07:38:08 INFO Received uploads request method=POST path=/api/pending_closures14552026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.33ms)1456--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.02s)1457=== CONT TestMultipartCleanup14582026/10/01 07:38:08 INFO Completed upload id=114592026/10/01 07:38:08 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014602026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.85ms)14612026/10/01 07:38:08 INFO Received uploads request method=POST path=/api/pending_closures14622026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.7ms)14632026/10/01 07:38:08 INFO Starting cleanup of old closures method=DELETE path=/api/closures14642026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (8.38ms)14652026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000014662026/10/01 07:38:08 INFO Aborted multipart uploads count=014672026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.48ms)14682026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.37ms)14692026/10/01 07:38:08 OK 3_commit_push.sql (1.64ms)14702026/10/01 07:38:08 goose: up to current file version: 314712026/10/01 07:38:08 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=014722026/10/01 07:38:08 INFO Vacuumed table table=pending_closures14732026/10/01 07:38:08 INFO Vacuumed table table=pending_objects14742026/10/01 07:38:08 INFO Vacuumed table table=multipart_uploads14752026/10/01 07:38:08 INFO Vacuumed table table=closures1476--- PASS: TestReadProxyRangeRequest (0.98s)1477=== CONT TestGCTaskStore_StartNew1478--- PASS: TestGCTaskStore_StartNew (0.00s)1479=== CONT TestPinProtectsFromGC14802026/10/01 07:38:08 INFO Vacuumed table table=objects1481--- PASS: TestReadRedirectNar (0.90s)1482=== CONT TestServerTLSConfig1483=== RUN TestServerTLSConfig/no_client_CA1484=== PAUSE TestServerTLSConfig/no_client_CA1485=== RUN TestServerTLSConfig/missing_CA_file1486=== PAUSE TestServerTLSConfig/missing_CA_file1487=== RUN TestServerTLSConfig/not_a_PEM_file1488=== PAUSE TestServerTLSConfig/not_a_PEM_file1489=== CONT TestGetExistingObjectsLocksRows14902026/10/01 07:38:08 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001491--- PASS: TestService_createPendingClosureHandler (1.08s)1492=== CONT TestCreatePin_ReservedPins1493--- PASS: TestReadRedirectKeepsNarinfoProxied (0.95s)1494=== CONT TestRegisterCompletedObjectNeedsPendingRow14952026/10/01 07:38:08 INFO lead: released remote=192.0.2.1:123414962026-10-01 07:38:08.244 UTC [572] ERROR: relation "goose_db_version" does not exist at character 3614972026-10-01 07:38:08.244 UTC [572] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14982026-10-01 07:38:08.245 UTC [573] ERROR: relation "goose_db_version" does not exist at character 3614992026-10-01 07:38:08.245 UTC [573] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1500--- PASS: TestReadProxyDisabled (0.73s)1501=== CONT TestService_NativeMTLS15022026-10-01 07:38:08.253 UTC [576] ERROR: relation "goose_db_version" does not exist at character 3615032026-10-01 07:38:08.253 UTC [576] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15042026-10-01 07:38:08.259 UTC [578] ERROR: relation "goose_db_version" does not exist at character 3615052026-10-01 07:38:08.259 UTC [578] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15062026-10-01 07:38:08.260 UTC [579] ERROR: relation "goose_db_version" does not exist at character 3615072026-10-01 07:38:08.260 UTC [579] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15082026/10/01 07:38:08 OK 20241026095416_initial_model.sql (9.98ms)15092026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.3ms)15102026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)15112026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)15122026/10/01 07:38:08 OK 20251218171726_add_pins.sql (4.35ms)15132026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.93ms)15142026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.96ms)15152026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.87ms)15162026/10/01 07:38:08 OK 20241026095416_initial_model.sql (12.34ms)15172026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.96ms)15182026-10-01 07:38:08.274 UTC [581] ERROR: relation "goose_db_version" does not exist at character 3615192026-10-01 07:38:08.274 UTC [581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15202026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.62ms)15212026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.55ms)15222026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.42ms)1523--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.72s)1524=== CONT TestGenerateLandingPage15252026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.77ms)15262026/10/01 07:38:08 OK 20251218171726_add_pins.sql (4.21ms)15272026/10/01 07:38:08 OK 20241026095416_initial_model.sql (12.69ms)1528--- PASS: TestGenerateLandingPage (0.00s)1529=== CONT TestSweepSkipsRowsLockedByPush15302026/10/01 07:38:08 OK 20241026095416_initial_model.sql (17.99ms)15312026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (7.32ms)15322026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000015332026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (8.63ms)15342026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000015352026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (7.32ms)15362026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (7.63ms)15372026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)15382026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.5ms)15392026/10/01 07:38:08 OK 1_commit_pending_closure.sql (3.08ms)15402026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.39ms)15412026/10/01 07:38:08 OK 20251218171726_add_pins.sql (4.56ms)15422026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.93ms)15432026/10/01 07:38:08 OK 20260905000000_add_claims.sql (4.64ms)15442026/10/01 07:38:08 OK 2_object_stats_trigger.sql (2.36ms)15452026/10/01 07:38:08 OK 3_commit_push.sql (1.57ms)15462026/10/01 07:38:08 goose: up to current file version: 315472026/10/01 07:38:08 INFO lead: acquired remote=192.0.2.1:123415482026/10/01 07:38:08 OK 3_commit_push.sql (1.55ms)15492026/10/01 07:38:08 goose: up to current file version: 315502026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (3.03ms)15512026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.57ms)15522026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.3ms)15532026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.27ms)15542026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000015552026/10/01 07:38:08 INFO lead: released remote=192.0.2.1:12341556--- PASS: TestLeadElectsOneAndHandsOver (1.14s)1557=== CONT TestClientSharedPathCommittedMidPush15582026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.28ms)15592026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.33ms)15602026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.89ms)15612026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.81ms)15622026-10-01 07:38:08.300 UTC [585] ERROR: relation "goose_db_version" does not exist at character 3615632026-10-01 07:38:08.300 UTC [585] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15642026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (3.08ms)15652026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.75ms)15662026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.95ms)15672026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (3.47ms)15682026/10/01 07:38:08 OK 3_commit_push.sql (1.23ms)15692026/10/01 07:38:08 goose: up to current file version: 315702026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (1.96ms)15712026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000015722026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.44ms)15732026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000015742026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.55ms)1575--- PASS: TestReadProxyConditionalGet (0.74s)1576=== CONT TestService_readinessHandler15772026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.14ms)15782026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.08ms)15792026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.91ms)15802026/10/01 07:38:08 OK 3_commit_push.sql (1.44ms)15812026/10/01 07:38:08 goose: up to current file version: 315822026/10/01 07:38:08 OK 2_object_stats_trigger.sql (2.25ms)15832026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.43ms)15842026/10/01 07:38:08 OK 3_commit_push.sql (1.39ms)15852026/10/01 07:38:08 goose: up to current file version: 315862026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.69ms)15872026-10-01 07:38:08.314 UTC [588] ERROR: relation "goose_db_version" does not exist at character 3615882026-10-01 07:38:08.314 UTC [588] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15892026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (3.27ms)15902026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.36ms)15912026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.45ms)15922026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000015932026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)15942026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.26ms)15952026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.63ms)15962026/10/01 07:38:08 OK 20251218171726_add_pins.sql (4.06ms)15972026-10-01 07:38:08.325 UTC [591] ERROR: relation "goose_db_version" does not exist at character 3615982026-10-01 07:38:08.325 UTC [591] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15992026/10/01 07:38:08 OK 3_commit_push.sql (1.98ms)16002026/10/01 07:38:08 goose: up to current file version: 316012026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.79ms)1602--- PASS: TestReadProxyHead (0.69s)1603=== CONT TestNARDeduplicationMetadataUploadBug16042026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.59ms)16052026/10/01 07:38:08 OK 20241026095416_initial_model.sql (12.33ms)16062026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.74ms)16072026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)16082026-10-01 07:38:08.337 UTC [593] ERROR: relation "goose_db_version" does not exist at character 3616092026-10-01 07:38:08.337 UTC [593] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16102026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.53ms)16112026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000016122026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.93ms)16132026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.37ms)1614--- PASS: TestReadProxyInvalidPath (0.68s)1615=== CONT TestService_healthCheckHandler16162026/10/01 07:38:08 OK 2_object_stats_trigger.sql (7.57ms)16172026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (10ms)16182026/10/01 07:38:08 OK 20241026095416_initial_model.sql (17.6ms)16192026/10/01 07:38:08 OK 3_commit_push.sql (2.26ms)16202026/10/01 07:38:08 goose: up to current file version: 316212026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.41ms)16222026/10/01 07:38:08 OK 20260905000000_add_claims.sql (4.38ms)16232026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.63ms)16242026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (3.52ms)16252026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)16262026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.98ms)16272026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000016282026-10-01 07:38:08.361 UTC [597] ERROR: relation "goose_db_version" does not exist at character 3616292026-10-01 07:38:08.361 UTC [597] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16302026/10/01 07:38:08 OK 20241026095416_initial_model.sql (12.27ms)16312026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.55ms)16322026/10/01 07:38:08 OK 20260905000000_add_claims.sql (4.27ms)16332026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.69ms)16342026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.76ms)16352026/10/01 07:38:08 OK 3_commit_push.sql (1.77ms)16362026/10/01 07:38:08 goose: up to current file version: 316372026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.77ms)16382026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.54ms)16392026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.5ms)16402026/10/01 07:38:08 goose: successfully migrated database to version: 202609231200001641--- PASS: TestReadProxy404 (0.67s)1642=== CONT TestClientWithDependencies16432026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.41ms)16442026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.48ms)16452026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.76ms)16462026/10/01 07:38:08 OK 3_commit_push.sql (1.43ms)16472026/10/01 07:38:08 goose: up to current file version: 316482026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.47ms)16492026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.08ms)16502026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.61ms)16512026-10-01 07:38:08.379 UTC [599] ERROR: relation "goose_db_version" does not exist at character 3616522026-10-01 07:38:08.379 UTC [599] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16532026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.29ms)16542026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.1ms)16552026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000016562026-10-01 07:38:08.383 UTC [601] ERROR: relation "goose_db_version" does not exist at character 3616572026-10-01 07:38:08.383 UTC [601] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16582026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.2ms)16592026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.96ms)16602026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.03ms)16612026/10/01 07:38:08 OK 3_commit_push.sql (1.39ms)16622026/10/01 07:38:08 goose: up to current file version: 316632026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.28ms)16642026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.54ms)16652026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.82ms)16662026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.3ms)16672026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.12ms)16682026/10/01 07:38:08 goose: successfully migrated database to version: 202609231200001669--- PASS: TestReadProxyNarStreaming (0.68s)1670=== CONT TestCacheConfigHandlerMaxNarSize1671--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1672=== CONT TestClientMultipleUploads16732026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)1674--- PASS: TestGCBugBareHashReferences (1.18s)1675=== CONT TestCreatePendingClosureRejectsOversizedNAR16762026/10/01 07:38:08 INFO Received uploads request method=POST path=/api/pending_closures1677--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1678=== CONT TestClientIntegration16792026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.8ms)16802026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.8ms)16812026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)16822026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.59ms)16832026/10/01 07:38:08 OK 2_object_stats_trigger.sql (2.35ms)16842026-10-01 07:38:08.407 UTC [604] ERROR: relation "goose_db_version" does not exist at character 3616852026-10-01 07:38:08.407 UTC [604] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16862026/10/01 07:38:08 OK 3_commit_push.sql (7.11ms)16872026/10/01 07:38:08 goose: up to current file version: 316882026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (8.16ms)16892026/10/01 07:38:08 OK 20251218171726_add_pins.sql (8.58ms)16902026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.53ms)16912026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.18ms)16922026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.59ms)16932026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.26ms)16942026/10/01 07:38:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45763/oidc16952026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.37ms)16962026/10/01 07:38:08 goose: successfully migrated database to version: 202609231200001697--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.69s)1698=== CONT TestFailedS3DeleteKeepsTombstone16992026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.71ms)17002026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.37ms)17012026-10-01 07:38:08.423 UTC [607] ERROR: relation "goose_db_version" does not exist at character 3617022026-10-01 07:38:08.423 UTC [607] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17032026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.37ms)17042026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.4ms)17052026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.21ms)17062026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000017072026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.94ms)17082026/10/01 07:38:08 OK 3_commit_push.sql (1.94ms)17092026/10/01 07:38:08 goose: up to current file version: 317102026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.59ms)17112026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.42ms)17122026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.24ms)17132026/10/01 07:38:08 OK 3_commit_push.sql (1.05ms)17142026/10/01 07:38:08 goose: up to current file version: 317152026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.02ms)17162026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.34ms)17172026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.23ms)17182026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.32ms)17192026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000017202026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.62ms)17212026/10/01 07:38:08 OK 1_commit_pending_closure.sql (1.79ms)1722--- PASS: TestReadProxyNarinfo (0.70s)1723=== CONT TestClientErrorHandling1724=== RUN TestClientErrorHandling/InvalidStorePath1725=== PAUSE TestClientErrorHandling/InvalidStorePath1726=== RUN TestClientErrorHandling/InvalidAuthToken1727=== PAUSE TestClientErrorHandling/InvalidAuthToken1728=== RUN TestClientErrorHandling/ServerNotAvailable1729=== PAUSE TestClientErrorHandling/ServerNotAvailable1730=== CONT TestDeduplicatedObjectsRecordedAsPending17312026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.94ms)17322026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.27ms)17332026/10/01 07:38:08 OK 3_commit_push.sql (548.28µs)17342026/10/01 07:38:08 goose: up to current file version: 317352026-10-01 07:38:08.445 UTC [612] ERROR: relation "goose_db_version" does not exist at character 3617362026-10-01 07:38:08.445 UTC [612] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17372026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.29ms)17382026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.02ms)17392026/10/01 07:38:08 OK 20260905000000_add_claims.sql (2.86ms)17402026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.28ms)17412026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.01ms)17422026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000017432026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.47ms)17442026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.65ms)17452026/10/01 07:38:08 OK 20241026095416_initial_model.sql (17.34ms)17462026/10/01 07:38:08 OK 3_commit_push.sql (8.56ms)17472026/10/01 07:38:08 goose: up to current file version: 317482026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.49ms)17492026/10/01 07:38:08 INFO Starting HTTP server address=127.0.0.1:342451750--- PASS: TestMetricsInventory (0.44s)17512026/10/01 07:38:08 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket3482300826/001/proxy.sock1752=== CONT TestClientCADerivations17532026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.94ms)17542026/10/01 07:38:08 WARN mTLS auth: subject not in bound subjects subject="CN=someone"17552026/10/01 07:38:08 INFO Shutdown signal received, draining in-flight requests timeout=10s1756--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.41s)1757=== CONT TestGCSweepDeliversEachKeyOnce17582026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.67ms)17592026-10-01 07:38:08.482 UTC [615] ERROR: relation "goose_db_version" does not exist at character 3617602026-10-01 07:38:08.482 UTC [615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17612026-10-01 07:38:08.483 UTC [617] ERROR: relation "goose_db_version" does not exist at character 3617622026-10-01 07:38:08.483 UTC [617] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17632026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.3ms)17642026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.38ms)17652026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (1.76ms)17662026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000017672026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.01ms)17682026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.29ms)17692026/10/01 07:38:08 OK 3_commit_push.sql (936.19µs)17702026/10/01 07:38:08 goose: up to current file version: 317712026/10/01 07:38:08 OK 20241026095416_initial_model.sql (12.2ms)17722026/10/01 07:38:08 OK 20241026095416_initial_model.sql (12.2ms)17732026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)17742026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.21ms)17752026-10-01 07:38:08.503 UTC [621] ERROR: relation "goose_db_version" does not exist at character 3617762026-10-01 07:38:08.503 UTC [621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17772026-10-01 07:38:08.504 UTC [622] ERROR: relation "goose_db_version" does not exist at character 3617782026-10-01 07:38:08.504 UTC [622] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17792026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.77ms)17802026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.86ms)17812026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.89ms)17822026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.63ms)17832026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.29ms)17842026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.36ms)17852026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.34ms)17862026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.41ms)17872026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (1.9ms)17882026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000017892026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (1.63ms)17902026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000017912026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.1ms)17922026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.05ms)17932026/10/01 07:38:08 OK 20241026095416_initial_model.sql (10.75ms)17942026/10/01 07:38:08 OK 20241026095416_initial_model.sql (10.35ms)17952026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.42ms)17962026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.59ms)17972026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.67ms)17982026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)17992026/10/01 07:38:08 OK 3_commit_push.sql (1.23ms)18002026/10/01 07:38:08 goose: up to current file version: 318012026/10/01 07:38:08 OK 3_commit_push.sql (1.71ms)18022026/10/01 07:38:08 goose: up to current file version: 318032026-10-01 07:38:08.524 UTC [623] ERROR: relation "goose_db_version" does not exist at character 3618042026-10-01 07:38:08.524 UTC [623] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18052026/10/01 07:38:08 OK 20251218171726_add_pins.sql (4.21ms)18062026/10/01 07:38:08 OK 20251218171726_add_pins.sql (4.31ms)18072026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (6.88ms)18082026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (6.94ms)18092026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.9ms)18102026/10/01 07:38:08 OK 20260905000000_add_claims.sql (4.43ms)18112026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.49ms)18122026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.54ms)18132026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (1.95ms)18142026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000018152026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.05ms)18162026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000018172026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.38ms)18182026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.06ms)18192026/10/01 07:38:08 OK 20241026095416_initial_model.sql (10.71ms)18202026/10/01 07:38:08 OK 2_object_stats_trigger.sql (898.15µs)18212026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1ms)18222026/10/01 07:38:08 OK 3_commit_push.sql (854.73µs)18232026/10/01 07:38:08 goose: up to current file version: 318242026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.49ms)18252026/10/01 07:38:08 OK 3_commit_push.sql (660.13µs)18262026/10/01 07:38:08 goose: up to current file version: 318272026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.09ms)18282026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.04ms)18292026-10-01 07:38:08.554 UTC [625] ERROR: relation "goose_db_version" does not exist at character 3618302026-10-01 07:38:08.554 UTC [625] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18312026-10-01 07:38:08.554 UTC [626] ERROR: relation "goose_db_version" does not exist at character 3618322026-10-01 07:38:08.554 UTC [626] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18332026/10/01 07:38:08 OK 20260905000000_add_claims.sql (2.78ms)18342026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.4ms)18352026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (1.66ms)18362026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000018372026/10/01 07:38:08 OK 1_commit_pending_closure.sql (1.58ms)1838--- PASS: TestObjectStatsTrigger (0.40s)1839=== CONT TestPushDedupSurvivesConcurrentGC18402026/10/01 07:38:08 OK 2_object_stats_trigger.sql (737.91µs)18412026/10/01 07:38:08 OK 3_commit_push.sql (553.07µs)18422026/10/01 07:38:08 goose: up to current file version: 318432026/10/01 07:38:08 OK 20241026095416_initial_model.sql (9.95ms)18442026/10/01 07:38:08 OK 20241026095416_initial_model.sql (9.78ms)18452026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.37ms)18462026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)18472026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.37ms)18482026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.46ms)18492026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.79ms)18502026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.48ms)18512026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.55ms)18522026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.76ms)18532026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.68ms)18542026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (2.47ms)18552026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.17ms)18562026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000018572026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.3ms)18582026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000018592026/10/01 07:38:08 OK 1_commit_pending_closure.sql (1.94ms)18602026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.06ms)18612026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.65ms)18622026/10/01 07:38:08 OK 2_object_stats_trigger.sql (798.39µs)18632026/10/01 07:38:08 OK 3_commit_push.sql (1.1ms)18642026/10/01 07:38:08 goose: up to current file version: 318652026/10/01 07:38:08 INFO Received uploads request method=POST path=/api/pending_closures18662026/10/01 07:38:08 OK 3_commit_push.sql (1.4ms)18672026/10/01 07:38:08 goose: up to current file version: 318682026-10-01 07:38:08.626 UTC [682] ERROR: relation "goose_db_version" does not exist at character 3618692026-10-01 07:38:08.626 UTC [682] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18702026/10/01 07:38:08 OK 20241026095416_initial_model.sql (9.62ms)18712026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.66ms)1872--- PASS: TestGetExistingObjectsLocksRows (0.42s)1873=== CONT TestCacheStatsHandler18742026/10/01 07:38:08 OK 20251218171726_add_pins.sql (3.32ms)18752026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (3.04ms)18762026/10/01 07:38:08 OK 20260905000000_add_claims.sql (2.63ms)18772026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (1.58ms)1878--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.42s)1879=== CONT TestTombstonedObjectOfferedWithoutWaiting18802026/10/01 07:38:08 INFO Received cleanup request method=DELETE path=/api/pending_closures18812026/10/01 07:38:08 INFO Aborted multipart uploads count=118822026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (271.55ms)18832026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000018842026/10/01 07:38:08 OK 1_commit_pending_closure.sql (4.45ms)1885--- PASS: TestMultipartCleanup (0.76s)1886=== CONT TestGCMetrics18872026/10/01 07:38:08 OK 2_object_stats_trigger.sql (2.32ms)18882026/10/01 07:38:08 OK 3_commit_push.sql (749.53µs)18892026/10/01 07:38:08 goose: up to current file version: 31890=== NAME TestPinProtectsFromGC1891 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC2341479495/001/store/im0nfh0cis06zbwhimkpkfzaa0daswi7-pinned-file.txt1892 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC2341479495/001/store/j4c9dwnga224020h7sbj8c3z303qx2hv-unpinned-file.txt18932026-10-01 07:38:08.943 UTC [792] ERROR: relation "goose_db_version" does not exist at character 3618942026-10-01 07:38:08.943 UTC [792] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18952026/10/01 07:38:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"18962026/10/01 07:38:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1897--- PASS: TestService_NativeMTLS (0.71s)1898=== CONT TestService_AuthMiddleware_OIDC18992026/10/01 07:38:08 OK 20241026095416_initial_model.sql (11.43ms)19002026/10/01 07:38:08 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)19012026/10/01 07:38:08 INFO Received uploads request method=POST path=/api/pending_closures19022026/10/01 07:38:08 OK 20251218171726_add_pins.sql (11.65ms)19032026/10/01 07:38:08 INFO Received uploads request method=POST path=/api/pending_closures19042026/10/01 07:38:08 OK 20260628120000_add_object_size_and_stats.sql (4.41ms)19052026/10/01 07:38:08 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)19062026/10/01 07:38:08 INFO Uploading 00fjwg19pj2rlng6w7h5ksskn7pjr1ab-shared-dep (136B)19072026/10/01 07:38:08 INFO Uploading vhy81ap7gvkgiian2r575g0gd5pfrkml-a (216B)19082026/10/01 07:38:08 OK 20260905000000_add_claims.sql (3.9ms)19092026/10/01 07:38:08 OK 20260920000000_drop_claims.sql (3.12ms)19102026/10/01 07:38:08 WARN Failed to register uploaded object key=14hbiandcbxdyspya1pq0zi3nxdri5kq.ls error="server returned 404: 404 page not found\n"19112026/10/01 07:38:08 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19122026/10/01 07:38:08 WARN Failed to register uploaded object key=nar/18vw18gbwy89hgwsf1az2sqmdsh0hc4yil8n6zdlvq8nacdarfmw.nar.zst error="server returned 404: 404 page not found\n"19132026/10/01 07:38:08 WARN Failed to register uploaded object key=00fjwg19pj2rlng6w7h5ksskn7pjr1ab.ls error="server returned 404: 404 page not found\n"19142026/10/01 07:38:08 WARN Failed to register uploaded object key=vhy81ap7gvkgiian2r575g0gd5pfrkml.ls error="server returned 404: 404 page not found\n"19152026/10/01 07:38:08 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign19162026/10/01 07:38:08 INFO Signed narinfos id=1 count=219172026/10/01 07:38:08 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign19182026/10/01 07:38:08 OK 20260923120000_add_pushes.sql (2.45ms)19192026/10/01 07:38:08 goose: successfully migrated database to version: 2026092312000019202026/10/01 07:38:08 INFO Signed narinfos id=2 count=219212026/10/01 07:38:08 INFO Uploading 4 narinfos19222026/10/01 07:38:08 OK 1_commit_pending_closure.sql (2.12ms)19232026/10/01 07:38:08 OK 2_object_stats_trigger.sql (1.28ms)19242026/10/01 07:38:08 WARN Failed to register uploaded object key=00fjwg19pj2rlng6w7h5ksskn7pjr1ab.narinfo error="server returned 404: 404 page not found\n"19252026/10/01 07:38:08 WARN Failed to register uploaded object key=vhy81ap7gvkgiian2r575g0gd5pfrkml.narinfo error="server returned 404: 404 page not found\n"19262026/10/01 07:38:08 OK 3_commit_push.sql (1.27ms)19272026/10/01 07:38:08 goose: up to current file version: 319282026/10/01 07:38:08 WARN Failed to register uploaded object key=14hbiandcbxdyspya1pq0zi3nxdri5kq.narinfo error="server returned 404: 404 page not found\n"19292026/10/01 07:38:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19302026/10/01 07:38:08 WARN Failed to register uploaded object key=00fjwg19pj2rlng6w7h5ksskn7pjr1ab.narinfo error="server returned 404: 404 page not found\n"19312026-10-01 07:38:09.000 UTC [849] ERROR: relation "goose_db_version" does not exist at character 3619322026-10-01 07:38:09.000 UTC [849] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19332026/10/01 07:38:09 INFO Completed upload id=119342026/10/01 07:38:09 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete19352026/10/01 07:38:09 INFO Completed upload id=219362026/10/01 07:38:09 INFO Upload complete. (67ms)19372026/10/01 07:38:09 INFO Aborted multipart uploads count=01938=== NAME TestClientFallsBackToClosures1939 client_pushes_test.go:112: Retrieved narinfo from S3:1940 StorePath: /build/TestClientFallsBackToClosures4111719261/001/store/00fjwg19pj2rlng6w7h5ksskn7pjr1ab-shared-dep1941 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1942 Compression: zstd1943 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821944 NarSize: 1361945 References: 1946 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n19472026/10/01 07:38:09 WARN Force mode enabled - objects will be deleted immediately without grace period1948 client_pushes_test.go:112: Retrieved narinfo from S3:1949 StorePath: /build/TestClientFallsBackToClosures4111719261/001/store/vhy81ap7gvkgiian2r575g0gd5pfrkml-a1950 URL: nar/18vw18gbwy89hgwsf1az2sqmdsh0hc4yil8n6zdlvq8nacdarfmw.nar.zst1951 Compression: zstd1952 NarHash: sha256:18vw18gbwy89hgwsf1az2sqmdsh0hc4yil8n6zdlvq8nacdarfmw1953 NarSize: 2161954 References: /build/TestClientFallsBackToClosures4111719261/001/store/00fjwg19pj2rlng6w7h5ksskn7pjr1ab-shared-dep1955 CA: text:sha256:0xsz5077an5yw88zixd7px0kqs99l1r3pnc2x19aizg50zy8i5v219562026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes19572026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes19582026/10/01 07:38:09 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=019592026/10/01 07:38:09 INFO Vacuumed table table=pending_closures1960 client_pushes_test.go:112: Retrieved narinfo from S3:19612026/10/01 07:38:09 INFO Vacuumed table table=pending_objects1962 StorePath: /build/TestClientFallsBackToClosures4111719261/001/store/14hbiandcbxdyspya1pq0zi3nxdri5kq-b1963 URL: nar/18vw18gbwy89hgwsf1az2sqmdsh0hc4yil8n6zdlvq8nacdarfmw.nar.zst1964 Compression: zstd1965 NarHash: sha256:18vw18gbwy89hgwsf1az2sqmdsh0hc4yil8n6zdlvq8nacdarfmw1966 NarSize: 2161967 References: /build/TestClientFallsBackToClosures4111719261/001/store/00fjwg19pj2rlng6w7h5ksskn7pjr1ab-shared-dep1968 CA: text:sha256:0xsz5077an5yw88zixd7px0kqs99l1r3pnc2x19aizg50zy8i5v219692026/10/01 07:38:09 INFO Vacuumed table table=multipart_uploads19702026/10/01 07:38:09 INFO Vacuumed table table=closures19712026/10/01 07:38:09 OK 20241026095416_initial_model.sql (7.91ms)19722026/10/01 07:38:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19732026/10/01 07:38:09 INFO Uploading im0nfh0cis06zbwhimkpkfzaa0daswi7-pinned-file.txt (128B)19742026/10/01 07:38:09 INFO Vacuumed table table=objects19752026/10/01 07:38:09 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)19762026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)19772026/10/01 07:38:09 INFO Uploading 4ybzslq7ifr9y2c9qgrxdiz57lf08msv-a (216B)19782026/10/01 07:38:09 INFO Uploading x1hzzdjpwd3zybr0y6z0sncmf4zrpkyi-shared-dep (136B)1979--- PASS: TestClientFallsBackToClosures (0.86s)1980=== CONT TestService_ReadAuthMiddleware19812026/10/01 07:38:09 OK 20251218171726_add_pins.sql (2.48ms)19822026/10/01 07:38:09 INFO Aborted multipart uploads count=019832026/10/01 07:38:09 WARN Failed to register uploaded object key=im0nfh0cis06zbwhimkpkfzaa0daswi7.ls error="server returned 404: 404 page not found\n"19842026/10/01 07:38:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19852026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"19862026/10/01 07:38:09 INFO Signed narinfos id=1 count=119872026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19882026/10/01 07:38:09 INFO Uploading 1 narinfos19892026/10/01 07:38:09 WARN Failed to register uploaded object key=3fyjmr43310mwxw9z461rq6s6qw0fvkx.ls error="server returned 404: 404 page not found\n"19902026/10/01 07:38:09 WARN Force mode enabled - objects will be deleted immediately without grace period19912026-10-01 07:38:09.020 UTC [887] ERROR: relation "goose_db_version" does not exist at character 3619922026-10-01 07:38:09.020 UTC [887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19932026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/0l5k56vnb4cci1pyyb98b2ns8dli8cjhwydcsgnxnwcqa0lsal3g.nar.zst error="server returned 404: 404 page not found\n"19942026/10/01 07:38:09 WARN Failed to register uploaded object key=4ybzslq7ifr9y2c9qgrxdiz57lf08msv.ls error="server returned 404: 404 page not found\n"19952026/10/01 07:38:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19962026/10/01 07:38:09 WARN Failed to register uploaded object key=x1hzzdjpwd3zybr0y6z0sncmf4zrpkyi.ls error="server returned 404: 404 page not found\n"19972026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (3.16ms)19982026/10/01 07:38:09 INFO Signed narinfos id=1 count=319992026/10/01 07:38:09 INFO Uploading 3 narinfos20002026/10/01 07:38:09 OK 20260905000000_add_claims.sql (2.87ms)20012026/10/01 07:38:09 INFO Received complete push request method=POST path=/api/pushes/1/complete20022026/10/01 07:38:09 WARN Failed to register uploaded object key=im0nfh0cis06zbwhimkpkfzaa0daswi7.narinfo error="server returned 404: 404 page not found\n"20032026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (1.59ms)20042026/10/01 07:38:09 WARN Failed to register uploaded object key=3fyjmr43310mwxw9z461rq6s6qw0fvkx.narinfo error="server returned 404: 404 page not found\n"20052026/10/01 07:38:09 WARN Failed to register uploaded object key=x1hzzdjpwd3zybr0y6z0sncmf4zrpkyi.narinfo error="server returned 404: 404 page not found\n"20062026/10/01 07:38:09 WARN readiness check failed error="closed pool"2007--- PASS: TestService_readinessHandler (0.72s)2008=== CONT TestService_RequireScope_OIDC20092026/10/01 07:38:09 INFO Received complete push request method=POST path=/api/pushes/1/complete20102026/10/01 07:38:09 WARN Failed to register uploaded object key=4ybzslq7ifr9y2c9qgrxdiz57lf08msv.narinfo error="server returned 404: 404 page not found\n"20112026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (3.19ms)20122026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000020132026/10/01 07:38:09 INFO Upload complete. (59ms)20142026/10/01 07:38:09 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=020152026/10/01 07:38:09 OK 1_commit_pending_closure.sql (2.18ms)20162026/10/01 07:38:09 INFO Vacuumed table table=pending_closures20172026/10/01 07:38:09 INFO Vacuumed table table=pending_objects20182026/10/01 07:38:09 INFO Vacuumed table table=multipart_uploads20192026/10/01 07:38:09 INFO Vacuumed table table=closures20202026/10/01 07:38:09 OK 2_object_stats_trigger.sql (2.59ms)20212026/10/01 07:38:09 INFO Upload complete. (64ms)20222026/10/01 07:38:09 OK 3_commit_push.sql (802.61µs)20232026/10/01 07:38:09 goose: up to current file version: 320242026/10/01 07:38:09 OK 20241026095416_initial_model.sql (9.89ms)2025=== NAME TestOrphanedObjectsGC20262026/10/01 07:38:09 INFO Vacuumed table table=objects2027 orphaned_objects_gc_test.go:290: GC Test Summary:2028 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2029 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2030 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2031 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2032 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2033--- PASS: TestOrphanedObjectsGC (0.88s)2034=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection2035=== NAME TestClientPushesUseOnePush2036 client_pushes_test.go:97: Retrieved narinfo from S3:2037 StorePath: /build/TestClientPushesUseOnePush3849109425/001/store/x1hzzdjpwd3zybr0y6z0sncmf4zrpkyi-shared-dep2038 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2039 Compression: zstd2040 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822041 NarSize: 1362042 References: 2043 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n20442026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)2045--- PASS: TestSweepSkipsRowsLockedByPush (0.76s)2046=== CONT TestCacheConfigHandler2047=== RUN TestCacheConfigHandler/full_config,_no_issuer2048=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2049=== RUN TestCacheConfigHandler/no_cache_url_configured2050=== PAUSE TestCacheConfigHandler/no_cache_url_configured2051=== RUN TestCacheConfigHandler/no_signing_keys2052=== PAUSE TestCacheConfigHandler/no_signing_keys2053=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2054=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2055=== CONT TestService_AuthMiddleware_MTLSBoundSubjects2056=== NAME TestClientPushesUseOnePush2057 client_pushes_test.go:97: Retrieved narinfo from S3:2058 StorePath: /build/TestClientPushesUseOnePush3849109425/001/store/4ybzslq7ifr9y2c9qgrxdiz57lf08msv-a2059 URL: nar/0l5k56vnb4cci1pyyb98b2ns8dli8cjhwydcsgnxnwcqa0lsal3g.nar.zst2060 Compression: zstd2061 NarHash: sha256:0l5k56vnb4cci1pyyb98b2ns8dli8cjhwydcsgnxnwcqa0lsal3g2062 NarSize: 2162063 References: /build/TestClientPushesUseOnePush3849109425/001/store/x1hzzdjpwd3zybr0y6z0sncmf4zrpkyi-shared-dep2064 CA: text:sha256:1wnjbql48icp82zn54dazrpg5n8awqpfa3safab7knjfa2jlp6ra20652026/10/01 07:38:09 OK 20251218171726_add_pins.sql (3.48ms)2066 client_pushes_test.go:97: Retrieved narinfo from S3:2067 StorePath: /build/TestClientPushesUseOnePush3849109425/001/store/3fyjmr43310mwxw9z461rq6s6qw0fvkx-b2068 URL: nar/0l5k56vnb4cci1pyyb98b2ns8dli8cjhwydcsgnxnwcqa0lsal3g.nar.zst2069 Compression: zstd2070 NarHash: sha256:0l5k56vnb4cci1pyyb98b2ns8dli8cjhwydcsgnxnwcqa0lsal3g2071 NarSize: 2162072 References: /build/TestClientPushesUseOnePush3849109425/001/store/x1hzzdjpwd3zybr0y6z0sncmf4zrpkyi-shared-dep2073 CA: text:sha256:1wnjbql48icp82zn54dazrpg5n8awqpfa3safab7knjfa2jlp6ra20742026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (3.42ms)2075--- PASS: TestClientPushesUseOnePush (0.88s)2076=== CONT TestGCSweepSkipsPendingObjects20772026/10/01 07:38:09 OK 20260905000000_add_claims.sql (3.09ms)20782026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (2.54ms)20792026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (2.19ms)20802026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000020812026/10/01 07:38:09 OK 1_commit_pending_closure.sql (2.29ms)20822026/10/01 07:38:09 OK 2_object_stats_trigger.sql (1.41ms)20832026/10/01 07:38:09 OK 3_commit_push.sql (1.31ms)20842026/10/01 07:38:09 goose: up to current file version: 32085--- PASS: TestService_healthCheckHandler (0.72s)2086=== CONT TestService_AuthMiddleware_MTLSProxyHeader2087=== NAME TestNARDeduplicationMetadataUploadBug2088 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug419953277/001/store/38dscq6mib3prz0xmcazf6lz94dyxyvc-file1.txt20892026-10-01 07:38:09.093 UTC [976] ERROR: relation "goose_db_version" does not exist at character 3620902026-10-01 07:38:09.093 UTC [976] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20912026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes20922026/10/01 07:38:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20932026/10/01 07:38:09 INFO Uploading j4c9dwnga224020h7sbj8c3z303qx2hv-unpinned-file.txt (128B)20942026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"20952026/10/01 07:38:09 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20962026/10/01 07:38:09 WARN Failed to register uploaded object key=j4c9dwnga224020h7sbj8c3z303qx2hv.ls error="server returned 404: 404 page not found\n"20972026/10/01 07:38:09 INFO Signed narinfos id=2 count=120982026/10/01 07:38:09 INFO Uploading 1 narinfos20992026/10/01 07:38:09 INFO Received complete push request method=POST path=/api/pushes/2/complete21002026/10/01 07:38:09 WARN Failed to register uploaded object key=j4c9dwnga224020h7sbj8c3z303qx2hv.narinfo error="server returned 404: 404 page not found\n"21012026/10/01 07:38:09 OK 20241026095416_initial_model.sql (12.11ms)21022026/10/01 07:38:09 INFO Upload complete. (51ms)21032026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.65ms)21042026/10/01 07:38:09 OK 20251218171726_add_pins.sql (3.73ms)21052026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (4.26ms)21062026/10/01 07:38:09 OK 20260905000000_add_claims.sql (3.84ms)21072026-10-01 07:38:09.129 UTC [1048] ERROR: relation "goose_db_version" does not exist at character 3621082026-10-01 07:38:09.129 UTC [1048] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21092026-10-01 07:38:09.129 UTC [1050] ERROR: relation "goose_db_version" does not exist at character 3621102026-10-01 07:38:09.129 UTC [1050] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21112026-10-01 07:38:09.129 UTC [1049] ERROR: relation "goose_db_version" does not exist at character 3621122026-10-01 07:38:09.129 UTC [1049] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21132026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (2.5ms)21142026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (2.07ms)21152026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000021162026/10/01 07:38:09 OK 1_commit_pending_closure.sql (1.82ms)21172026/10/01 07:38:09 OK 2_object_stats_trigger.sql (1.3ms)21182026/10/01 07:38:09 OK 3_commit_push.sql (1.16ms)21192026/10/01 07:38:09 goose: up to current file version: 321202026/10/01 07:38:09 OK 20241026095416_initial_model.sql (9.63ms)21212026/10/01 07:38:09 OK 20241026095416_initial_model.sql (9.44ms)21222026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.06ms)21232026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)21242026/10/01 07:38:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45199/oidc21252026/10/01 07:38:09 OK 20241026095416_initial_model.sql (11.69ms)21262026/10/01 07:38:09 INFO Received create pin request method=POST path=/api/pins/myapp2127=== NAME TestClientMultipleUploads2128 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads97792222/001/store/2bz49ngdp92phdpvdh31b2a7726m3ppn-test-file-0.txt21292026/10/01 07:38:09 OK 20251218171726_add_pins.sql (3.27ms)21302026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)21312026/10/01 07:38:09 OK 20251218171726_add_pins.sql (3.33ms)21322026/10/01 07:38:09 OK 20251218171726_add_pins.sql (3.11ms)21332026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (3.33ms)21342026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (3.51ms)21352026-10-01 07:38:09.154 UTC [1089] ERROR: relation "goose_db_version" does not exist at character 3621362026-10-01 07:38:09.154 UTC [1089] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21372026/10/01 07:38:09 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2341479495/001/store/im0nfh0cis06zbwhimkpkfzaa0daswi7-pinned-file.txt narinfo_key=im0nfh0cis06zbwhimkpkfzaa0daswi7.narinfo21382026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (2.45ms)21392026/10/01 07:38:09 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux21402026/10/01 07:38:09 WARN Refused reserved pin name=worker-x86_64-linux21412026/10/01 07:38:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures21422026/10/01 07:38:09 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux21432026/10/01 07:38:09 OK 20260905000000_add_claims.sql (3.37ms)21442026/10/01 07:38:09 INFO Garbage collection started21452026/10/01 07:38:09 INFO Received create pin request method=POST path=/api/pins/my-app21462026/10/01 07:38:09 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux21472026/10/01 07:38:09 OK 20260905000000_add_claims.sql (3.97ms)2148--- PASS: TestCreatePin_ReservedPins (0.93s)2149=== CONT TestService_ReadScope_PublicByDefault21502026/10/01 07:38:09 OK 20260905000000_add_claims.sql (3.01ms)21512026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (2.67ms)21522026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (2.81ms)21532026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (2.54ms)21542026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes21552026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes21562026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (2.74ms)21572026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000021582026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (2.89ms)21592026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000021602026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (2.26ms)21612026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000021622026/10/01 07:38:09 INFO Aborted multipart uploads count=021632026/10/01 07:38:09 OK 1_commit_pending_closure.sql (2.1ms)21642026/10/01 07:38:09 OK 1_commit_pending_closure.sql (1.74ms)21652026/10/01 07:38:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21662026/10/01 07:38:09 INFO Uploading 38dscq6mib3prz0xmcazf6lz94dyxyvc-file1.txt (160B)21672026/10/01 07:38:09 OK 1_commit_pending_closure.sql (2.36ms)21682026/10/01 07:38:09 OK 2_object_stats_trigger.sql (1.41ms)2169=== NAME TestClientIntegration2170 client_integration_test.go:286: Created store path: /build/TestClientIntegration3068324577/002/store/i5pvv71isv0m53xwcbbf0v2117jd5g5p-test-file.txt21712026/10/01 07:38:09 INFO Received uploads request method=POST path=/api/pending_closures21722026/10/01 07:38:09 WARN Force mode enabled - objects will be deleted immediately without grace period21732026/10/01 07:38:09 OK 2_object_stats_trigger.sql (1.62ms)21742026/10/01 07:38:09 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)21752026/10/01 07:38:09 INFO Uploading 7ilffawlhxy02519ry8zd36kz7hq28cf-top (224B)21762026/10/01 07:38:09 OK 3_commit_push.sql (1.4ms)21772026/10/01 07:38:09 goose: up to current file version: 321782026/10/01 07:38:09 INFO Uploading lgd1njr433syankm7k99y23s72kmqk8i-shared-dep (136B)21792026/10/01 07:38:09 OK 3_commit_push.sql (1.34ms)21802026/10/01 07:38:09 goose: up to current file version: 321812026/10/01 07:38:09 OK 2_object_stats_trigger.sql (2.16ms)21822026/10/01 07:38:09 OK 3_commit_push.sql (1.46ms)21832026/10/01 07:38:09 goose: up to current file version: 321842026/10/01 07:38:09 WARN Failed to register uploaded object key=38dscq6mib3prz0xmcazf6lz94dyxyvc.ls error="server returned 404: 404 page not found\n"21852026/10/01 07:38:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21862026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"21872026/10/01 07:38:09 INFO Signed narinfos id=1 count=121882026/10/01 07:38:09 INFO Uploading 1 narinfos21892026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"21902026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/1z5qgrbi5g9ayyy4gyw9x1cxr4gr6xjrlh7pnmy17hd9bnzm06zm.nar.zst error="server returned 404: 404 page not found\n"21912026/10/01 07:38:09 WARN Failed to register uploaded object key=7ilffawlhxy02519ry8zd36kz7hq28cf.ls error="server returned 404: 404 page not found\n"21922026/10/01 07:38:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21932026/10/01 07:38:09 WARN Failed to register uploaded object key=lgd1njr433syankm7k99y23s72kmqk8i.ls error="server returned 404: 404 page not found\n"21942026/10/01 07:38:09 OK 20241026095416_initial_model.sql (10.85ms)21952026/10/01 07:38:09 INFO Signed narinfos id=1 count=221962026/10/01 07:38:09 INFO Uploading 2 narinfos2197=== NAME TestClientWithDependencies2198 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies3802004989/001/store/7bzfmfvchzm34h6apl1z8ayxpi61jac7-test-script21992026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.98ms)22002026/10/01 07:38:09 INFO Received complete push request method=POST path=/api/pushes/1/complete22012026/10/01 07:38:09 WARN Failed to register uploaded object key=38dscq6mib3prz0xmcazf6lz94dyxyvc.narinfo error="server returned 404: 404 page not found\n"22022026/10/01 07:38:09 WARN Failed to register uploaded object key=lgd1njr433syankm7k99y23s72kmqk8i.narinfo error="server returned 404: 404 page not found\n"22032026/10/01 07:38:09 INFO Received complete push request method=POST path=/api/pushes/1/complete22042026/10/01 07:38:09 WARN Failed to register uploaded object key=7ilffawlhxy02519ry8zd36kz7hq28cf.narinfo error="server returned 404: 404 page not found\n"22052026/10/01 07:38:09 OK 20251218171726_add_pins.sql (4.12ms)22062026/10/01 07:38:09 INFO Upload complete. (59ms)22072026/10/01 07:38:09 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=02208=== NAME TestNARDeduplicationMetadataUploadBug2209 metadata_upload_test.go:54: Retrieved narinfo from S3:2210 StorePath: /build/TestNARDeduplicationMetadataUploadBug419953277/001/store/38dscq6mib3prz0xmcazf6lz94dyxyvc-file1.txt2211 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2212 Compression: zstd2213 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2214 NarSize: 1602215 References: 2216 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf22172026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (4.89ms)22182026/10/01 07:38:09 INFO Upload complete. (58ms)2219=== NAME TestClientSharedPathCommittedMidPush2220 client_integration_test.go:680: Retrieved narinfo from S3:2221 StorePath: /build/TestClientSharedPathCommittedMidPush1594444515/001/store/lgd1njr433syankm7k99y23s72kmqk8i-shared-dep2222 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2223 Compression: zstd2224 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822225 NarSize: 1362226 References: 2227 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n22282026/10/01 07:38:09 INFO Vacuumed table table=pending_closures2229=== NAME TestNARDeduplicationMetadataUploadBug2230 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2231 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2232 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}2233=== NAME TestClientMultipleUploads2234 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads97792222/001/store/nirq4pzn150gicrpbiccpych5kw2bavs-test-file-1.txt22352026/10/01 07:38:09 OK 20260905000000_add_claims.sql (3.43ms)22362026/10/01 07:38:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38761/oidc22372026/10/01 07:38:09 INFO Vacuumed table table=pending_objects2238=== NAME TestClientSharedPathCommittedMidPush2239 client_integration_test.go:680: Retrieved narinfo from S3:2240 StorePath: /build/TestClientSharedPathCommittedMidPush1594444515/001/store/7ilffawlhxy02519ry8zd36kz7hq28cf-top2241 URL: nar/1z5qgrbi5g9ayyy4gyw9x1cxr4gr6xjrlh7pnmy17hd9bnzm06zm.nar.zst2242 Compression: zstd2243 NarHash: sha256:1z5qgrbi5g9ayyy4gyw9x1cxr4gr6xjrlh7pnmy17hd9bnzm06zm2244 NarSize: 2242245 References: /build/TestClientSharedPathCommittedMidPush1594444515/001/store/lgd1njr433syankm7k99y23s72kmqk8i-shared-dep2246 CA: text:sha256:1m3dn75iq4r7zlpryq3dak828psjrv9jpx6zr3scsdy6lzp8azzb22472026/10/01 07:38:09 INFO Vacuumed table table=multipart_uploads22482026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (2.78ms)2249--- PASS: TestClientSharedPathCommittedMidPush (0.89s)2250=== CONT TestProxyWriteTimeout/narinfo2251=== CONT TestProxyWriteTimeout/unknown_size2252=== CONT TestProxyWriteTimeout/10_GiB_nar2253=== CONT TestProxyWriteTimeout/1_GiB_nar2254--- PASS: TestProxyWriteTimeout (0.01s)2255 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2256 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2257 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2258 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2259=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info22602026/10/01 07:38:09 INFO Received uploads request method=POST path=/2261=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key22622026/10/01 07:38:09 INFO Received complete multipart upload request method=POST path=/2263=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key22642026/10/01 07:38:09 INFO Received request for more parts method=POST path=/2265=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal22662026/10/01 07:38:09 INFO Received uploads request method=POST path=/2267--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2268 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2269 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2270 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2271 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2272=== CONT TestIsValidUploadKey/narinfo2273=== CONT TestIsValidUploadKey/index.html2274=== CONT TestIsValidUploadKey/nix-cache-info2275=== CONT TestIsValidUploadKey/realisation_plus_in_output2276=== CONT TestIsValidUploadKey/realisation2277=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2278=== CONT TestIsValidUploadKey/build_log_equals2279=== CONT TestIsValidUploadKey/build_log_question_mark2280=== CONT TestIsValidUploadKey/build_log_plus_in_name2281=== CONT TestIsValidUploadKey/unknown_type2282=== CONT TestIsValidUploadKey/nar_plain2283=== CONT TestIsValidUploadKey/empty_key2284=== CONT TestIsValidUploadKey/nar_xz2285=== CONT TestIsValidUploadKey/absolute2286=== CONT TestIsValidUploadKey/nar_zst2287=== CONT TestIsValidUploadKey/traversal_nar2288=== CONT TestIsValidUploadKey/listing2289=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2290=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2291=== CONT TestIsValidUploadKey/traversal2292=== CONT TestIsValidUploadKey/build_log_home-manager_file2293=== CONT TestIsValidUploadKey/build_log2294=== CONT TestParseSingleRange/none2295=== CONT TestParseSingleRange/open-ended2296=== CONT TestParseSingleRange/closed2297=== CONT TestParseSingleRange/malformed_end_before_start2298=== CONT TestParseSingleRange/malformed_both_empty2299=== CONT TestParseSingleRange/end_clamped_to_size2300=== CONT TestParseSingleRange/malformed_no_dash2301=== CONT TestParseSingleRange/multi-range_ignored2302=== CONT TestParseSingleRange/single_byte2303=== CONT TestParseSingleRange/start_far_past_EOF2304=== CONT TestParseSingleRange/start_past_EOF2305=== CONT TestParseSingleRange/suffix_exceeds_size2306=== CONT TestParseSingleRange/unknown_unit2307=== CONT TestParseSingleRange/suffix2308=== CONT TestResolveDBConnectionString/flag_wins2309=== CONT TestResolveDBConnectionString/nothing_configured2310=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2311=== CONT TestResolveDBConnectionString/missing_file_is_an_error2312--- PASS: TestIsValidUploadKey (0.07s)2313 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2314 --- PASS: TestIsValidUploadKey/index.html (0.00s)2315 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2316 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2317 --- PASS: TestIsValidUploadKey/realisation (0.00s)2318 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2319 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2320 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2321 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2322 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2323 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2324 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2325 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2326 --- PASS: TestIsValidUploadKey/absolute (0.00s)2327 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2328 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2329 --- PASS: TestIsValidUploadKey/listing (0.00s)2330 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2331 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2332 --- PASS: TestIsValidUploadKey/traversal (0.00s)2333 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2334 --- PASS: TestIsValidUploadKey/build_log (0.00s)2335--- PASS: TestParseSingleRange (0.06s)2336 --- PASS: TestParseSingleRange/none (0.00s)2337 --- PASS: TestParseSingleRange/open-ended (0.00s)2338 --- PASS: TestParseSingleRange/closed (0.00s)2339 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2340 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2341 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2342 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2343 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2344 --- PASS: TestParseSingleRange/single_byte (0.00s)2345 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2346 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2347 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2348 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2349 --- PASS: TestParseSingleRange/suffix (0.00s)2350=== CONT TestResolveDBConnectionString/file_when_flag_empty2351=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure23522026/10/01 07:38:09 INFO Received uploads request method=POST path=/2353--- PASS: TestResolveDBConnectionString (0.00s)2354 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2355 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2356 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2357 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2358 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)23592026/10/01 07:38:09 INFO Vacuumed table table=closures23602026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (7.73ms)23612026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000023622026/10/01 07:38:09 INFO Received uploads request method=POST path=/api/pending_closures23632026/10/01 07:38:09 INFO Vacuumed table table=objects23642026/10/01 07:38:09 OK 1_commit_pending_closure.sql (2.66ms)23652026/10/01 07:38:09 OK 2_object_stats_trigger.sql (1.62ms)2366--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.76s)2367=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts23682026/10/01 07:38:09 OK 3_commit_push.sql (1.56ms)23692026/10/01 07:38:09 goose: up to current file version: 323702026/10/01 07:38:09 INFO Received request for more parts method=POST path=/2371=== NAME TestClientWithDependencies2372 client_integration_test.go:615: Found 1 dependencies (including self)2373=== NAME TestNARDeduplicationMetadataUploadBug2374 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug419953277/001/store/4mk5m1pzvfmzdy58ffcdl49vz4wjd4za-file2.txt23752026-10-01 07:38:09.218 UTC [1221] ERROR: relation "goose_db_version" does not exist at character 3623762026-10-01 07:38:09.218 UTC [1221] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2377=== NAME TestClientMultipleUploads2378 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads97792222/001/store/q40wx3dbg6la734w9yi8rs5nnw6jbzh6-test-file-2.txt23792026-10-01 07:38:09.233 UTC [1256] ERROR: relation "goose_db_version" does not exist at character 3623802026-10-01 07:38:09.233 UTC [1256] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23812026/10/01 07:38:09 OK 20241026095416_initial_model.sql (11.6ms)23822026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.83ms)23832026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes23842026/10/01 07:38:09 OK 20251218171726_add_pins.sql (2.63ms)23852026/10/01 07:38:09 INFO Aborted multipart uploads count=023862026/10/01 07:38:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23872026/10/01 07:38:09 INFO Uploading i5pvv71isv0m53xwcbbf0v2117jd5g5p-test-file.txt (152B)23882026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (3.79ms)23892026/10/01 07:38:09 WARN Force mode enabled - objects will be deleted immediately without grace period23902026/10/01 07:38:09 WARN Failed to register uploaded object key=i5pvv71isv0m53xwcbbf0v2117jd5g5p.ls error="server returned 404: 404 page not found\n"23912026/10/01 07:38:09 OK 20260905000000_add_claims.sql (3.75ms)23922026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"23932026/10/01 07:38:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23942026/10/01 07:38:09 INFO Signed narinfos id=1 count=123952026/10/01 07:38:09 INFO Uploading 1 narinfos23962026/10/01 07:38:09 OK 20241026095416_initial_model.sql (11.08ms)23972026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (2.52ms)23982026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.62ms)23992026/10/01 07:38:09 INFO Received complete push request method=POST path=/api/pushes/1/complete24002026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (2.04ms)24012026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000024022026/10/01 07:38:09 WARN Failed to register uploaded object key=i5pvv71isv0m53xwcbbf0v2117jd5g5p.narinfo error="server returned 404: 404 page not found\n"24032026/10/01 07:38:09 OK 1_commit_pending_closure.sql (1.8ms)24042026/10/01 07:38:09 INFO Aborted multipart uploads count=024052026/10/01 07:38:09 OK 20251218171726_add_pins.sql (3.59ms)24062026/10/01 07:38:09 OK 2_object_stats_trigger.sql (1.45ms)24072026/10/01 07:38:09 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."24082026/10/01 07:38:09 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."24092026/10/01 07:38:09 WARN Force mode enabled - objects will be deleted immediately without grace period24102026/10/01 07:38:09 OK 3_commit_push.sql (1.25ms)24112026/10/01 07:38:09 goose: up to current file version: 324122026/10/01 07:38:09 INFO Upload complete. (58ms)2413--- PASS: TestFailedS3DeleteKeepsTombstone (0.84s)2414=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart24152026/10/01 07:38:09 INFO Received complete multipart upload request method=POST path=/24162026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (3.37ms)24172026/10/01 07:38:09 OK 20260905000000_add_claims.sql (3.49ms)24182026-10-01 07:38:09.263 UTC [1345] ERROR: relation "goose_db_version" does not exist at character 3624192026-10-01 07:38:09.263 UTC [1345] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24202026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (2.46ms)2421=== CONT TestPush_RejectsBadRequests/no_roots24222026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes2423=== CONT TestPush_RejectsBadRequests/bad_root24242026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes2425=== CONT TestPush_RejectsBadRequests/no_objects24262026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes2427=== CONT TestPush_RejectsBadRequests/root_not_in_objects24282026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes2429=== CONT TestIsValidCachePath/narinfo2430=== CONT TestIsValidCachePath/wrong_extension2431=== CONT TestIsValidCachePath/leading_slash2432--- PASS: TestPush_RejectsBadRequests (0.57s)2433 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2434 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2435 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2436 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2437=== CONT TestIsValidCachePath/empty2438=== CONT TestIsValidCachePath/random_path2439=== CONT TestIsValidCachePath/invalid_char_u2440=== CONT TestIsValidCachePath/invalid_char_e24412026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (1.8ms)2442=== CONT TestIsValidCachePath/traversal_in_middle24432026/10/01 07:38:09 goose: successfully migrated database to version: 202609231200002444=== CONT TestIsValidCachePath/traversal_parent2445=== CONT TestIsValidCachePath/index.html2446=== CONT TestIsValidCachePath/nix-cache-info2447=== CONT TestIsValidCachePath/short_hash2448=== CONT TestIsValidCachePath/realisation2449=== CONT TestIsValidCachePath/nar_xz2450=== CONT TestIsValidCachePath/nar_zst2451=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2452=== CONT TestIsValidCachePath/ls2453=== CONT TestIsValidCachePath/log2454=== CONT TestIsValidCachePath/nar_uncompressed2455=== CONT TestIsValidCachePath/nar_bz22456--- PASS: TestIsValidCachePath (0.00s)2457 --- PASS: TestIsValidCachePath/narinfo (0.00s)2458 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2459 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2460 --- PASS: TestIsValidCachePath/empty (0.00s)2461 --- PASS: TestIsValidCachePath/random_path (0.00s)2462 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2463 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2464 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2465 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2466 --- PASS: TestIsValidCachePath/index.html (0.00s)2467 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2468 --- PASS: TestIsValidCachePath/short_hash (0.00s)2469 --- PASS: TestIsValidCachePath/realisation (0.00s)2470 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2471 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2472 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2473 --- PASS: TestIsValidCachePath/ls (0.00s)2474 --- PASS: TestIsValidCachePath/log (0.00s)2475 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2476 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2477=== CONT TestServerTLSConfig/no_client_CA2478=== CONT TestServerTLSConfig/missing_CA_file2479=== CONT TestServerTLSConfig/not_a_PEM_file2480--- PASS: TestServerTLSConfig (0.00s)2481 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2482 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2483 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2484=== CONT TestClientErrorHandling/InvalidStorePath24852026/10/01 07:38:09 INFO Received uploads request method=POST path=/api/pending_closures24862026/10/01 07:38:09 OK 1_commit_pending_closure.sql (1.9ms)24872026/10/01 07:38:09 OK 2_object_stats_trigger.sql (1.34ms)24882026/10/01 07:38:09 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=024892026/10/01 07:38:09 OK 3_commit_push.sql (1.05ms)24902026/10/01 07:38:09 goose: up to current file version: 324912026/10/01 07:38:09 INFO Vacuumed table table=pending_closures24922026/10/01 07:38:09 INFO Vacuumed table table=pending_objects24932026/10/01 07:38:09 INFO Vacuumed table table=multipart_uploads24942026/10/01 07:38:09 INFO Vacuumed table table=closures24952026/10/01 07:38:09 INFO Vacuumed table table=objects2496--- PASS: TestGCSweepDeliversEachKeyOnce (0.80s)2497=== CONT TestClientErrorHandling/ServerNotAvailable24982026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes24992026/10/01 07:38:09 OK 20241026095416_initial_model.sql (10.97ms)25002026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.37ms)2501--- PASS: TestCacheStatsHandler (0.64s)2502=== CONT TestClientErrorHandling/InvalidAuthToken25032026/10/01 07:38:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25042026/10/01 07:38:09 INFO Uploading 7bzfmfvchzm34h6apl1z8ayxpi61jac7-test-script (136B)25052026/10/01 07:38:09 OK 20251218171726_add_pins.sql (3.91ms)25062026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"25072026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes25082026/10/01 07:38:09 WARN Failed to register uploaded object key=7bzfmfvchzm34h6apl1z8ayxpi61jac7.ls error="server returned 404: 404 page not found\n"25092026/10/01 07:38:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25102026/10/01 07:38:09 WARN Failed to register uploaded object key=log/02571cdhflyrhk4knnlbp739ibzsawp6-test-script.drv error="server returned 404: 404 page not found\n"25112026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (3.78ms)25122026/10/01 07:38:09 INFO Signed narinfos id=1 count=125132026/10/01 07:38:09 INFO Uploading 1 narinfos25142026/10/01 07:38:09 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)25152026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes25162026/10/01 07:38:09 OK 20260905000000_add_claims.sql (3.54ms)25172026/10/01 07:38:09 INFO Received complete push request method=POST path=/api/pushes/1/complete25182026/10/01 07:38:09 WARN Failed to register uploaded object key=7bzfmfvchzm34h6apl1z8ayxpi61jac7.narinfo error="server returned 404: 404 page not found\n"25192026/10/01 07:38:09 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign25202026/10/01 07:38:09 INFO Signed narinfos id=2 count=125212026/10/01 07:38:09 INFO Uploading 1 narinfos25222026/10/01 07:38:09 WARN Failed to register uploaded object key=4mk5m1pzvfmzdy58ffcdl49vz4wjd4za.ls error="server returned 404: 404 page not found\n"25232026/10/01 07:38:09 INFO All 1 paths already cached25242026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (3.69ms)25252026/10/01 07:38:09 INFO Received uploads request method=POST path=/api/pending_closures2526=== NAME TestClientIntegration2527 client_integration_test.go:312: Retrieved narinfo from S3:2528 StorePath: /build/TestClientIntegration3068324577/002/store/i5pvv71isv0m53xwcbbf0v2117jd5g5p-test-file.txt2529 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2530 Compression: zstd2531 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12532 NarSize: 1522533 References: 2534 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk125352026/10/01 07:38:09 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)25362026/10/01 07:38:09 INFO Uploading nirq4pzn150gicrpbiccpych5kw2bavs-test-file-1.txt (160B)25372026/10/01 07:38:09 INFO Uploading 2bz49ngdp92phdpvdh31b2a7726m3ppn-test-file-0.txt (160B)25382026/10/01 07:38:09 INFO Uploading q40wx3dbg6la734w9yi8rs5nnw6jbzh6-test-file-2.txt (160B)25392026/10/01 07:38:09 INFO Upload complete. (59ms)25402026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (2.57ms)25412026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000025422026/10/01 07:38:09 INFO Received complete push request method=POST path=/api/pushes/2/complete25432026/10/01 07:38:09 WARN Failed to register uploaded object key=4mk5m1pzvfmzdy58ffcdl49vz4wjd4za.narinfo error="server returned 404: 404 page not found\n"2544 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2545 client_integration_test.go:313: Decompressed .ls content (64 bytes):2546 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2547=== NAME TestClientWithDependencies2548 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3802004989/001/store) requires matching store prefix2549=== NAME TestClientIntegration2550 client_integration_test.go:316: Testing garbage collection...25512026/10/01 07:38:09 INFO Upload complete. (49ms)25522026/10/01 07:38:09 OK 1_commit_pending_closure.sql (3.32ms)25532026/10/01 07:38:09 WARN Failed to register uploaded object key=2bz49ngdp92phdpvdh31b2a7726m3ppn.ls error="server returned 404: 404 page not found\n"2554--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.64s)25552026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"2556=== CONT TestCacheConfigHandler/full_config,_no_issuer25572026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"2558=== NAME TestNARDeduplicationMetadataUploadBug2559 metadata_upload_test.go:76: Retrieved narinfo from S3:2560 StorePath: /build/TestNARDeduplicationMetadataUploadBug419953277/001/store/4mk5m1pzvfmzdy58ffcdl49vz4wjd4za-file2.txt2561 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2562 Compression: zstd2563 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2564 NarSize: 1602565 References: 2566 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2567=== CONT TestCacheConfigHandler/no_signing_keys2568=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2569=== CONT TestCacheConfigHandler/no_cache_url_configured2570--- PASS: TestCacheConfigHandler (0.00s)2571 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2572 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2573 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2574 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2575--- PASS: TestClientWithDependencies (0.93s)2576=== NAME TestClientCADerivations2577 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1122025295/001/store/3w5gicljsans62rhymxj0ww1k1i1qpwf-ca-test25782026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"25792026/10/01 07:38:09 WARN Failed to register uploaded object key=q40wx3dbg6la734w9yi8rs5nnw6jbzh6.ls error="server returned 404: 404 page not found\n"25802026/10/01 07:38:09 OK 2_object_stats_trigger.sql (4.05ms)25812026/10/01 07:38:09 WARN Failed to register uploaded object key=nirq4pzn150gicrpbiccpych5kw2bavs.ls error="server returned 404: 404 page not found\n"25822026/10/01 07:38:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign2583=== NAME TestNARDeduplicationMetadataUploadBug2584 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2585 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2586 {"version":1,"root":{"type":"regular","size":44}}25872026/10/01 07:38:09 INFO Signed narinfos id=1 count=325882026/10/01 07:38:09 INFO Uploading 3 narinfos25892026/10/01 07:38:09 OK 3_commit_push.sql (2.25ms)25902026/10/01 07:38:09 goose: up to current file version: 32591--- PASS: TestNARDeduplicationMetadataUploadBug (0.98s)25922026/10/01 07:38:09 WARN Failed to register uploaded object key=2bz49ngdp92phdpvdh31b2a7726m3ppn.narinfo error="server returned 404: 404 page not found\n"25932026/10/01 07:38:09 WARN Failed to register uploaded object key=q40wx3dbg6la734w9yi8rs5nnw6jbzh6.narinfo error="server returned 404: 404 page not found\n"25942026/10/01 07:38:09 INFO Received complete push request method=POST path=/api/pushes/1/complete25952026/10/01 07:38:09 WARN Failed to register uploaded object key=nirq4pzn150gicrpbiccpych5kw2bavs.narinfo error="server returned 404: 404 page not found\n"25962026/10/01 07:38:09 INFO Upload complete. (60ms)2597=== NAME TestClientMultipleUploads2598 client_integration_test.go:369: Uploaded 3 paths in 97.336818ms25992026/10/01 07:38:09 INFO Aborted multipart uploads count=026002026/10/01 07:38:09 WARN Force mode enabled - objects will be deleted immediately without grace period2601--- PASS: TestClientMultipleUploads (0.93s)26022026/10/01 07:38:09 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=026032026/10/01 07:38:09 INFO Vacuumed table table=pending_closures26042026/10/01 07:38:09 INFO Vacuumed table table=pending_objects26052026/10/01 07:38:09 INFO Vacuumed table table=multipart_uploads26062026/10/01 07:38:09 INFO Vacuumed table table=closures26072026/10/01 07:38:09 INFO Vacuumed table table=objects2608--- PASS: TestService_ReadAuthMiddleware (0.32s)2609--- PASS: TestGCMetrics (0.40s)26102026/10/01 07:38:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures26112026/10/01 07:38:09 INFO Garbage collection started26122026/10/01 07:38:09 INFO Aborted multipart uploads count=02613=== NAME TestClientCADerivations2614 client_ca_test.go:139: Found 1 dependencies (including self)26152026/10/01 07:38:09 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=026162026/10/01 07:38:09 INFO Aborted multipart uploads count=026172026/10/01 07:38:09 INFO Vacuumed table table=pending_closures26182026/10/01 07:38:09 WARN Force mode enabled - objects will be deleted immediately without grace period26192026/10/01 07:38:09 INFO Vacuumed table table=pending_objects26202026-10-01 07:38:09.348 UTC [1497] ERROR: relation "goose_db_version" does not exist at character 3626212026-10-01 07:38:09.348 UTC [1497] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26222026/10/01 07:38:09 INFO Vacuumed table table=multipart_uploads26232026/10/01 07:38:09 INFO Vacuumed table table=closures26242026/10/01 07:38:09 INFO Vacuumed table table=objects26252026/10/01 07:38:09 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"26262026/10/01 07:38:09 WARN mTLS auth: bound subjects configured but subject DN unavailable26272026/10/01 07:38:09 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2628--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.32s)26292026/10/01 07:38:09 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/present26302026/10/01 07:38:09 INFO Aborted multipart uploads count=026312026-10-01 07:38:09.356 UTC [1515] ERROR: relation "goose_db_version" does not exist at character 3626322026-10-01 07:38:09.356 UTC [1515] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26332026/10/01 07:38:09 WARN Force mode enabled - objects will be deleted immediately without grace period26342026/10/01 07:38:09 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=026352026/10/01 07:38:09 INFO Vacuumed table table=pending_closures26362026/10/01 07:38:09 INFO Vacuumed table table=pending_objects26372026/10/01 07:38:09 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=026382026/10/01 07:38:09 INFO Vacuumed table table=multipart_uploads26392026/10/01 07:38:09 INFO Vacuumed table table=closures26402026/10/01 07:38:09 INFO Vacuumed table table=objects26412026/10/01 07:38:09 OK 20241026095416_initial_model.sql (9.53ms)26422026/10/01 07:38:09 INFO Vacuumed table table=pending_closures2643--- PASS: TestPushDedupSurvivesConcurrentGC (0.80s)26442026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)26452026/10/01 07:38:09 INFO Vacuumed table table=pending_objects26462026/10/01 07:38:09 INFO Vacuumed table table=multipart_uploads26472026/10/01 07:38:09 INFO Vacuumed table table=closures26482026/10/01 07:38:09 OK 20251218171726_add_pins.sql (2.83ms)26492026/10/01 07:38:09 INFO Vacuumed table table=objects26502026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (3.17ms)26512026/10/01 07:38:09 OK 20241026095416_initial_model.sql (10.46ms)26522026/10/01 07:38:09 OK 20251210153512_drop_unused_gin_index.sql (1.31ms)26532026/10/01 07:38:09 INFO Received uploads request method=POST path=/api/pending_closures26542026/10/01 07:38:09 OK 20260905000000_add_claims.sql (2.41ms)26552026/10/01 07:38:09 OK 20251218171726_add_pins.sql (2.59ms)26562026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (2.35ms)26572026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (1.78ms)26582026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000026592026/10/01 07:38:09 OK 20260628120000_add_object_size_and_stats.sql (2.64ms)26602026/10/01 07:38:09 OK 1_commit_pending_closure.sql (1.96ms)26612026/10/01 07:38:09 OK 20260905000000_add_claims.sql (2.16ms)26622026/10/01 07:38:09 OK 2_object_stats_trigger.sql (694.11µs)26632026/10/01 07:38:09 OK 3_commit_push.sql (608.35µs)26642026/10/01 07:38:09 goose: up to current file version: 326652026/10/01 07:38:09 OK 20260920000000_drop_claims.sql (1.5ms)26662026/10/01 07:38:09 OK 20260923120000_add_pushes.sql (1.22ms)26672026/10/01 07:38:09 goose: successfully migrated database to version: 2026092312000026682026/10/01 07:38:09 OK 1_commit_pending_closure.sql (1.82ms)26692026/10/01 07:38:09 OK 2_object_stats_trigger.sql (760.77µs)26702026/10/01 07:38:09 OK 3_commit_push.sql (592.33µs)26712026/10/01 07:38:09 goose: up to current file version: 326722026/10/01 07:38:09 INFO Received uploads request method=POST path=/api/pending_closures26732026/10/01 07:38:09 INFO Aborted multipart uploads count=02674--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.34s)26752026/10/01 07:38:09 WARN Force mode enabled - objects will be deleted immediately without grace period26762026/10/01 07:38:09 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=026772026/10/01 07:38:09 INFO Vacuumed table table=pending_closures26782026/10/01 07:38:09 INFO Vacuumed table table=pending_objects26792026/10/01 07:38:09 INFO Vacuumed table table=multipart_uploads26802026/10/01 07:38:09 INFO Vacuumed table table=closures26812026/10/01 07:38:09 INFO Vacuumed table table=objects2682--- PASS: TestGCSweepSkipsPendingObjects (0.38s)2683=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2684=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2685=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2686=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2687=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2688=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2689=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2690=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2691=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2692=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected26932026/10/01 07:38:09 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]2694=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2695=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured26962026/10/01 07:38:09 WARN Authentication failed token_preview=eyJhbGciOi...BtOXs-Dw0Q token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2697--- PASS: TestService_AuthMiddleware_OIDC (0.47s)2698 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2699 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2700 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2701 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2702--- PASS: TestService_ReadScope_PublicByDefault (0.28s)27032026/10/01 07:38:09 INFO Received push request method=POST path=/api/pushes27042026/10/01 07:38:09 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=208.497361ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27052026/10/01 07:38:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27062026/10/01 07:38:09 INFO Uploading 3w5gicljsans62rhymxj0ww1k1i1qpwf-ca-test (144B)27072026/10/01 07:38:09 WARN Failed to register uploaded object key=3w5gicljsans62rhymxj0ww1k1i1qpwf.ls error="server returned 404: 404 page not found\n"27082026/10/01 07:38:09 WARN Failed to register uploaded object key=log/d0q6y7x7qbbyblm27ia38xqxmfd1lfa4-ca-test.drv error="server returned 404: 404 page not found\n"27092026/10/01 07:38:09 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"27102026/10/01 07:38:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27112026/10/01 07:38:09 INFO Signed narinfos id=1 count=127122026/10/01 07:38:09 INFO Uploading 1 narinfos27132026/10/01 07:38:09 INFO Received complete push request method=POST path=/api/pushes/1/complete27142026/10/01 07:38:09 WARN Failed to register uploaded object key=3w5gicljsans62rhymxj0ww1k1i1qpwf.narinfo error="server returned 404: 404 page not found\n"27152026/10/01 07:38:09 INFO Upload complete. (95ms)2716=== NAME TestClientCADerivations2717 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1122025295/001/store/3w5gicljsans62rhymxj0ww1k1i1qpwf-ca-test2718 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2719 Compression: zstd2720 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2721 NarSize: 1442722 References: 2723 Deriver: /build/TestClientCADerivations1122025295/001/store/d0q6y7x7qbbyblm27ia38xqxmfd1lfa4-ca-test.drv2724 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2725 client_ca_test.go:185: Checking for realisation files in S3...2726 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2727 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2728=== RUN TestService_RequireScope_OIDC/builder_may_write2729=== PAUSE TestService_RequireScope_OIDC/builder_may_write2730=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2731=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2732=== RUN TestService_RequireScope_OIDC/ops_may_admin2733=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2734=== RUN TestService_RequireScope_OIDC/ops_may_not_write2735=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2736=== RUN TestService_RequireScope_OIDC/reader_may_not_write2737=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2738=== RUN TestService_RequireScope_OIDC/static_token_may_admin2739=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2740=== RUN TestService_RequireScope_OIDC/static_token_may_write2741=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2742=== RUN TestService_RequireScope_OIDC/reader_may_read2743=== PAUSE TestService_RequireScope_OIDC/reader_may_read2744=== RUN TestService_RequireScope_OIDC/writer_implies_read2745=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2746=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2747=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2748=== CONT TestService_RequireScope_OIDC/builder_may_write2749=== CONT TestService_RequireScope_OIDC/ops_may_admin2750=== CONT TestService_RequireScope_OIDC/writer_implies_read2751=== CONT TestService_RequireScope_OIDC/ops_may_not_write2752=== CONT TestService_RequireScope_OIDC/reader_may_not_write2753=== CONT TestService_RequireScope_OIDC/reader_may_read2754=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2755=== CONT TestService_RequireScope_OIDC/static_token_may_write2756=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2757=== CONT TestService_RequireScope_OIDC/static_token_may_admin2758--- PASS: TestService_RequireScope_OIDC (0.45s)2759 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2760 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2761 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2762 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2763 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2764 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2765 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2766 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2767 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2768 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2769=== NAME TestClientCADerivations2770 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2771 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2772 error: binary cache 's3://bucket59?endpoint=http://localhost:33093®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1122025295/001/store'2773 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12774--- PASS: TestClientCADerivations (1.09s)2775--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.54s)27762026/10/01 07:38:09 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"27772026/10/01 07:38:09 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"27782026/10/01 07:38:09 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=412.619751ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2779=== NAME TestOrphanedObjectsGCStressTest2780 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2781 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion27822026/10/01 07:38:10 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=795.612749ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2783--- PASS: TestUploadHandlersRejectOversizedBody (0.16s)2784 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.06s)2785 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.05s)2786 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.92s)2787=== NAME TestOrphanedObjectsGCStressTest2788 orphaned_objects_gc_test.go:509: Stress test completed successfully:2789 orphaned_objects_gc_test.go:510: - Active objects preserved: 202790 orphaned_objects_gc_test.go:511: - Objects deleted: 2102791 orphaned_objects_gc_test.go:512: - Total GC'd: 2102792--- PASS: TestOrphanedObjectsGCStressTest (2.08s)27932026/10/01 07:38:10 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.671183564s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27942026/10/01 07:38:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02795=== NAME TestPinProtectsFromGC2796 client_integration_test.go:794: Pin successfully protected closure from garbage collection2797--- PASS: TestPinProtectsFromGC (2.96s)27982026/10/01 07:38:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02799=== NAME TestClientIntegration2800 client_integration_test.go:323: Objects in database after GC:2801 client_integration_test.go:323: Successfully deleted all objects with GC --force2802--- PASS: TestClientIntegration (2.94s)28032026/10/01 07:38:12 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-config28042026/10/01 07:38:12 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=187.266024ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28052026/10/01 07:38:12 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=390.444097ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28062026/10/01 07:38:12 WARN Rate limiter enabled after throttle name=s3-test rate=528072026/10/01 07:38:12 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2808=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2809 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102810 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002811--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.80s)28122026/10/01 07:38:13 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=727.259039ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28132026/10/01 07:38:13 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.459903118s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28142026/10/01 07:38:15 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"28152026/10/01 07:38:15 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-config28162026/10/01 07:38:15 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=186.382782ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28172026/10/01 07:38:15 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=364.171023ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28182026/10/01 07:38:16 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=841.2035ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28192026/10/01 07:38:16 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.743657066s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28202026/10/01 07:38:18 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_closures28212026/10/01 07:38:18 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.680839ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28222026/10/01 07:38:19 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=417.393088ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28232026/10/01 07:38:19 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=820.341952ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28242026/10/01 07:38:20 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.529384251s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2825--- PASS: TestClientErrorHandling (0.00s)2826 --- PASS: TestClientErrorHandling/InvalidStorePath (0.25s)2827 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.34s)2828 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.50s)2829PASS28302026-10-01 07:38:21.986 UTC [129] LOG: received smart shutdown request28312026-10-01 07:38:21.991 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 128322026-10-01 07:38:22.003 UTC [134] LOG: shutting down28332026-10-01 07:38:22.003 UTC [134] LOG: checkpoint starting: shutdown immediate28342026-10-01 07:38:22.796 UTC [134] LOG: checkpoint complete: wrote 10819 buffers (66.0%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 21 recycled; write=0.186 s, sync=0.582 s, total=0.793 s; sync files=24927, longest=0.002 s, average=0.001 s; distance=339150 kB, estimate=339150 kB; lsn=0/16299620, redo lsn=0/1629962028352026-10-01 07:38:22.873 UTC [129] LOG: database system is shut down2836Running OIDC tests...2837=== RUN TestAudienceForIssuer2838=== PAUSE TestAudienceForIssuer2839=== RUN TestGlobMatch2840=== PAUSE TestGlobMatch2841=== RUN TestValidateToken_ValidToken2842=== PAUSE TestValidateToken_ValidToken2843=== RUN TestValidateToken_WrongAudience2844=== PAUSE TestValidateToken_WrongAudience2845=== RUN TestValidateToken_Expired2846=== PAUSE TestValidateToken_Expired2847=== RUN TestValidateToken_BoundClaimsMismatch2848=== PAUSE TestValidateToken_BoundClaimsMismatch2849=== RUN TestValidateToken_BoundSubjectMismatch2850=== PAUSE TestValidateToken_BoundSubjectMismatch2851=== RUN TestValidateToken_MultipleProviders2852=== PAUSE TestValidateToken_MultipleProviders2853=== RUN TestValidateToken_NoMatchingProvider2854=== PAUSE TestValidateToken_NoMatchingProvider2855=== RUN TestValidateToken_KubernetesServiceAccount2856=== PAUSE TestValidateToken_KubernetesServiceAccount2857=== RUN TestNewValidator_KubernetesRequiresCA2858=== PAUSE TestNewValidator_KubernetesRequiresCA2859=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2860=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2861=== RUN TestPins_ReservedForMatchingRule2862=== PAUSE TestPins_ReservedForMatchingRule2863=== RUN TestPins_TopLevelShorthand2864=== PAUSE TestPins_TopLevelShorthand2865=== RUN TestPins_ConfigValidation2866=== PAUSE TestPins_ConfigValidation2867=== RUN TestScopes_LegacyProviderDefaultsToWrite2868=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2869=== RUN TestScopes_Rules2870=== PAUSE TestScopes_Rules2871=== RUN TestScopes_ConfigValidation2872=== PAUSE TestScopes_ConfigValidation2873=== CONT TestAudienceForIssuer2874=== CONT TestValidateToken_KubernetesServiceAccount2875=== CONT TestValidateToken_WrongAudience2876=== CONT TestValidateToken_NoMatchingProvider2877=== CONT TestPins_ConfigValidation2878=== CONT TestPins_ReservedForMatchingRule2879=== CONT TestPins_TopLevelShorthand2880=== CONT TestValidateToken_MultipleProviders2881=== CONT TestScopes_Rules2882=== CONT TestValidateToken_BoundSubjectMismatch2883=== CONT TestValidateToken_ValidToken2884=== CONT TestGlobMatch2885=== RUN TestGlobMatch/foo_foo2886=== PAUSE TestGlobMatch/foo_foo2887=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2888--- PASS: TestAudienceForIssuer (0.00s)2889=== RUN TestGlobMatch/foo_bar2890=== PAUSE TestGlobMatch/foo_bar2891=== RUN TestGlobMatch/*_2892=== CONT TestNewValidator_KubernetesRequiresCA2893=== CONT TestValidateToken_BoundClaimsMismatch2894--- PASS: TestPins_ConfigValidation (0.00s)2895=== CONT TestScopes_ConfigValidation2896=== CONT TestScopes_LegacyProviderDefaultsToWrite2897=== PAUSE TestGlobMatch/*_2898=== RUN TestGlobMatch/*_anything2899=== PAUSE TestGlobMatch/*_anything2900=== RUN TestGlobMatch/foo*_foo2901=== PAUSE TestGlobMatch/foo*_foo2902=== CONT TestValidateToken_Expired2903=== RUN TestGlobMatch/foo*_foobar2904--- PASS: TestScopes_ConfigValidation (0.00s)2905=== PAUSE TestGlobMatch/foo*_foobar2906=== RUN TestGlobMatch/foo*_bar2907=== PAUSE TestGlobMatch/foo*_bar2908=== RUN TestGlobMatch/*bar_bar2909=== PAUSE TestGlobMatch/*bar_bar2910=== RUN TestGlobMatch/*bar_foobar2911=== PAUSE TestGlobMatch/*bar_foobar2912=== RUN TestGlobMatch/*bar_foo2913=== PAUSE TestGlobMatch/*bar_foo2914=== RUN TestGlobMatch/foo*bar_foobar2915=== PAUSE TestGlobMatch/foo*bar_foobar2916=== RUN TestGlobMatch/foo*bar_foo123bar2917=== PAUSE TestGlobMatch/foo*bar_foo123bar2918=== RUN TestGlobMatch/foo*bar_foobarbaz2919=== PAUSE TestGlobMatch/foo*bar_foobarbaz2920=== RUN TestGlobMatch/*/*_foo/bar2921=== PAUSE TestGlobMatch/*/*_foo/bar2922=== RUN TestGlobMatch/*/*_foo2923=== PAUSE TestGlobMatch/*/*_foo2924=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2925=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2926=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02927=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02928=== RUN TestGlobMatch/refs/*/main_refs/heads/main2929=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2930=== RUN TestGlobMatch/fo?_foo2931=== PAUSE TestGlobMatch/fo?_foo2932=== RUN TestGlobMatch/fo?_fo2933=== PAUSE TestGlobMatch/fo?_fo2934=== RUN TestGlobMatch/fo?_fooo2935=== PAUSE TestGlobMatch/fo?_fooo2936=== RUN TestGlobMatch/?oo_foo2937=== PAUSE TestGlobMatch/?oo_foo2938=== RUN TestGlobMatch/?oo_boo2939=== PAUSE TestGlobMatch/?oo_boo2940=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2941=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2942=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2943=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2944=== CONT TestGlobMatch/foo_foo2945=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2946=== CONT TestGlobMatch/foo*bar_foobar2947=== CONT TestGlobMatch/foo*_foobar2948=== CONT TestGlobMatch/*bar_foobar2949=== CONT TestGlobMatch/?oo_boo2950=== CONT TestGlobMatch/fo?_foo2951=== CONT TestGlobMatch/fo?_fooo2952=== CONT TestGlobMatch/fo?_fo2953=== CONT TestGlobMatch/*bar_bar2954=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2955=== CONT TestGlobMatch/refs/*/main_refs/heads/main2956=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02957=== CONT TestGlobMatch/*/*_foo2958=== CONT TestGlobMatch/*/*_foo/bar2959=== CONT TestGlobMatch/foo*_bar2960=== CONT TestGlobMatch/foo*_foo2961=== CONT TestGlobMatch/*_anything2962=== CONT TestGlobMatch/*_2963=== CONT TestGlobMatch/foo_bar2964=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2965=== CONT TestGlobMatch/*bar_foo2966=== CONT TestGlobMatch/foo*bar_foo123bar2967=== CONT TestGlobMatch/foo*bar_foobarbaz2968=== CONT TestGlobMatch/?oo_foo2969--- PASS: TestGlobMatch (0.00s)2970 --- PASS: TestGlobMatch/foo_foo (0.00s)2971 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2972 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2973 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2974 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2975 --- PASS: TestGlobMatch/?oo_boo (0.00s)2976 --- PASS: TestGlobMatch/fo?_foo (0.00s)2977 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2978 --- PASS: TestGlobMatch/fo?_fo (0.00s)2979 --- PASS: TestGlobMatch/*bar_bar (0.00s)2980 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2981 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2982 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2983 --- PASS: TestGlobMatch/*/*_foo (0.00s)2984 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2985 --- PASS: TestGlobMatch/foo*_bar (0.00s)2986 --- PASS: TestGlobMatch/foo*_foo (0.00s)2987 --- PASS: TestGlobMatch/*_anything (0.00s)2988 --- PASS: TestGlobMatch/*_ (0.00s)2989 --- PASS: TestGlobMatch/foo_bar (0.00s)2990 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2991 --- PASS: TestGlobMatch/*bar_foo (0.00s)2992 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2993 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2994 --- PASS: TestGlobMatch/?oo_foo (0.00s)29952026/10/01 07:38:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45981/oidc2996--- PASS: TestValidateToken_BoundClaimsMismatch (0.05s)29972026/10/01 07:38:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33067/oidc2998--- PASS: TestValidateToken_ValidToken (0.07s)29992026/10/01 07:38:24 http: TLS handshake error from 127.0.0.1:51580: remote error: tls: bad certificate3000--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)30012026/10/01 07:38:24 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:405713002--- PASS: TestValidateToken_KubernetesServiceAccount (0.11s)30032026/10/01 07:38:24 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12330042026/10/01 07:38:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42377/oidc3005--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.12s)3006--- PASS: TestValidateToken_BoundSubjectMismatch (0.12s)30072026/10/01 07:38:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40767/oidc3008--- PASS: TestPins_ReservedForMatchingRule (0.13s)30092026/10/01 07:38:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36939/oidc3010--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.15s)30112026/10/01 07:38:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37813/oidc3012--- PASS: TestValidateToken_WrongAudience (0.17s)30132026/10/01 07:38:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37485/oidc30142026/10/01 07:38:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44621/oidc3015--- PASS: TestPins_TopLevelShorthand (0.24s)30162026/10/01 07:38:24 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40291/oidc3017--- PASS: TestScopes_Rules (0.24s)3018--- PASS: TestValidateToken_Expired (0.24s)30192026/10/01 07:38:24 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36015/oidc3020--- PASS: TestValidateToken_NoMatchingProvider (0.28s)30212026/10/01 07:38:24 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36689/oidc30222026/10/01 07:38:24 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:43885/oidc3023--- PASS: TestValidateToken_MultipleProviders (0.28s)3024PASS3025Running hook tests...3026=== RUN TestSendPathsEmpty3027=== PAUSE TestSendPathsEmpty3028=== RUN TestQueueEnqueueAndFetch3029=== PAUSE TestQueueEnqueueAndFetch3030=== RUN TestQueueDeduplication3031=== PAUSE TestQueueDeduplication3032=== RUN TestQueueRemove3033=== PAUSE TestQueueRemove3034=== RUN TestQueueFetchBatchLimit3035=== PAUSE TestQueueFetchBatchLimit3036=== RUN TestQueueRetryMovesToBack3037=== PAUSE TestQueueRetryMovesToBack3038=== RUN TestQueueFetchRemoveLifecycle3039=== PAUSE TestQueueFetchRemoveLifecycle3040=== RUN TestQueueConcurrentWriters3041=== PAUSE TestQueueConcurrentWriters3042=== RUN TestQueueRemoveLargeClosure3043=== PAUSE TestQueueRemoveLargeClosure3044=== RUN TestServerClientIntegration3045=== PAUSE TestServerClientIntegration3046=== RUN TestServerQueueError3047=== PAUSE TestServerQueueError3048=== RUN TestGetListenerSocketActivation3049 server_test.go:210: === RUN TestGetListenerSocketActivation3050 --- PASS: TestGetListenerSocketActivation (0.00s)3051 PASS3052 3053--- PASS: TestGetListenerSocketActivation (0.01s)3054=== RUN TestDrainIsolatesPoisonPath3055=== PAUSE TestDrainIsolatesPoisonPath3056=== RUN TestRunNotBlockedByPoisonHead3057=== PAUSE TestRunNotBlockedByPoisonHead3058=== RUN TestDrainGivesUpWhenServerDown3059=== PAUSE TestDrainGivesUpWhenServerDown3060=== RUN TestFailedPathPrunedByLaterClosure3061=== PAUSE TestFailedPathPrunedByLaterClosure3062=== RUN TestWorkerUploadsAndRemoves3063=== PAUSE TestWorkerUploadsAndRemoves3064=== RUN TestWorkerSkipsGCdPaths3065=== PAUSE TestWorkerSkipsGCdPaths3066=== RUN TestWorkerPrunesClosureDeps3067=== PAUSE TestWorkerPrunesClosureDeps3068=== RUN TestDrainTimeout3069=== PAUSE TestDrainTimeout3070=== CONT TestSendPathsEmpty3071=== CONT TestRunNotBlockedByPoisonHead3072=== CONT TestFailedPathPrunedByLaterClosure3073--- PASS: TestSendPathsEmpty (0.00s)3074=== CONT TestDrainIsolatesPoisonPath3075=== CONT TestWorkerSkipsGCdPaths3076=== CONT TestServerQueueError3077=== CONT TestDrainTimeout3078=== CONT TestWorkerPrunesClosureDeps3079=== CONT TestServerClientIntegration3080=== CONT TestQueueRemoveLargeClosure3081=== CONT TestWorkerUploadsAndRemoves3082=== CONT TestQueueConcurrentWriters3083=== CONT TestQueueRemove3084=== CONT TestQueueFetchBatchLimit30852026/10/01 07:38:24 ERROR Failed to queue paths error="permission denied" count=13086=== CONT TestQueueDeduplication3087=== CONT TestQueueFetchRemoveLifecycle3088=== CONT TestQueueEnqueueAndFetch3089=== CONT TestQueueRetryMovesToBack3090=== CONT TestDrainGivesUpWhenServerDown3091--- PASS: TestServerClientIntegration (0.00s)3092--- PASS: TestServerQueueError (0.00s)30932026/10/01 07:38:24 INFO Uploading batch count=130942026/10/01 07:38:24 ERROR Upload failed error="upload failed" count=130952026/10/01 07:38:24 INFO Uploading batch count=430962026/10/01 07:38:24 ERROR Upload failed error="upload failed" count=430972026/10/01 07:38:24 INFO Upload queue status pending=23098--- PASS: TestQueueFetchBatchLimit (0.01s)30992026/10/01 07:38:24 INFO Uploading batch count=131002026/10/01 07:38:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3477550374/002/bbb31012026/10/01 07:38:24 INFO Uploading batch count=231022026/10/01 07:38:24 ERROR Upload failed error="upload failed" count=231032026/10/01 07:38:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1843788285/002/a31042026/10/01 07:38:24 INFO Upload queue status pending=231052026/10/01 07:38:24 INFO Uploading batch count=131062026/10/01 07:38:24 INFO Uploading batch count=231072026/10/01 07:38:24 INFO Upload queue status pending=331082026/10/01 07:38:24 INFO Uploading batch count=23109--- PASS: TestQueueEnqueueAndFetch (0.01s)3110--- PASS: TestQueueRemove (0.01s)31112026/10/01 07:38:24 INFO Uploading batch count=13112--- PASS: TestQueueRetryMovesToBack (0.01s)31132026/10/01 07:38:24 ERROR Upload failed error="upload failed" count=131142026/10/01 07:38:24 INFO Uploading batch count=131152026/10/01 07:38:24 ERROR Upload failed error="upload failed" count=131162026/10/01 07:38:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1843788285/002/b3117--- PASS: TestQueueFetchRemoveLifecycle (0.01s)31182026/10/01 07:38:24 INFO Uploading batch count=131192026/10/01 07:38:24 INFO Upload queue status pending=231202026/10/01 07:38:24 INFO Uploading batch count=131212026/10/01 07:38:24 ERROR Upload failed error="upload failed" count=131222026/10/01 07:38:24 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3263838203/002/nonexistent31232026/10/01 07:38:24 INFO Uploading batch count=23124--- PASS: TestQueueDeduplication (0.01s)31252026/10/01 07:38:24 ERROR Upload failed error="upload failed" count=231262026/10/01 07:38:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1843788285/002/c31272026/10/01 07:38:24 INFO Uploading batch count=131282026/10/01 07:38:24 INFO Uploading batch count=131292026/10/01 07:38:24 ERROR Upload failed error="upload failed" count=131302026/10/01 07:38:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1843788285/002/d31312026/10/01 07:38:24 ERROR Drain finished with paths left in queue remaining=13132--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)31332026/10/01 07:38:24 INFO Uploading batch count=231342026/10/01 07:38:24 ERROR Upload failed error="upload failed" count=231352026/10/01 07:38:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1843788285/002/e31362026/10/01 07:38:24 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1843788285/002/f31372026/10/01 07:38:24 ERROR Drain finished with paths left in queue remaining=103138--- PASS: TestDrainIsolatesPoisonPath (0.02s)3139--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3140--- PASS: TestWorkerSkipsGCdPaths (0.03s)3141--- PASS: TestWorkerUploadsAndRemoves (0.03s)3142--- PASS: TestWorkerPrunesClosureDeps (0.03s)3143--- PASS: TestQueueRemoveLargeClosure (0.14s)3144--- PASS: TestQueueConcurrentWriters (0.15s)31452026/10/01 07:38:24 ERROR Upload failed error="context deadline exceeded" count=231462026/10/01 07:38:24 ERROR Drain finished with paths left in queue remaining=43147--- PASS: TestDrainTimeout (0.21s)31482026/10/01 07:38:25 INFO Uploading batch count=131492026/10/01 07:38:25 INFO Uploading batch count=131502026/10/01 07:38:25 INFO Uploading batch count=131512026/10/01 07:38:25 ERROR Upload failed error="upload failed" count=131522026/10/01 07:38:25 INFO Uploading batch count=131532026/10/01 07:38:25 ERROR Upload failed error="upload failed" count=131542026/10/01 07:38:25 INFO Uploading batch count=131552026/10/01 07:38:25 ERROR Upload failed error="upload failed" count=131562026/10/01 07:38:25 INFO Uploading batch count=131572026/10/01 07:38:25 ERROR Upload failed error="upload failed" count=131582026/10/01 07:38:25 ERROR Drain finished with paths left in queue remaining=13159--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3160PASS