niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #210
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestFilterOversizedClosures7=== PAUSE TestFilterOversizedClosures8=== RUN TestPartSizeForNAR9=== PAUSE TestPartSizeForNAR10=== RUN TestUploadMultipart_SupersededByPeer11=== PAUSE TestUploadMultipart_SupersededByPeer12=== RUN TestDumpPathCaseHackMatchesNix13--- PASS: TestDumpPathCaseHackMatchesNix (0.14s)14=== RUN TestDumpPathCaseHackCollision15--- PASS: TestDumpPathCaseHackCollision (0.00s)16=== RUN TestDumpPathMatchesNix17=== PAUSE TestDumpPathMatchesNix18=== RUN TestDumpPathSingleFile19=== PAUSE TestDumpPathSingleFile20=== RUN TestDumpPathWriterError21=== PAUSE TestDumpPathWriterError22=== RUN TestEncodeNixBase3223=== PAUSE TestEncodeNixBase3224=== RUN TestEncodeNixBase32WithRealHash25=== PAUSE TestEncodeNixBase32WithRealHash26=== RUN TestConvertHashToNix3227=== PAUSE TestConvertHashToNix3228=== RUN TestGetStorePathHash29=== PAUSE TestGetStorePathHash30=== RUN TestPathInfoHashCompatibility31=== PAUSE TestPathInfoHashCompatibility32=== RUN TestParsePathInfoJSON33=== PAUSE TestParsePathInfoJSON34=== RUN TestParsePathInfoJSONMultiplePaths35=== PAUSE TestParsePathInfoJSONMultiplePaths36=== RUN TestPathInfoCACompatibility37=== PAUSE TestPathInfoCACompatibility38=== RUN TestRateLimiterFeedback39=== PAUSE TestRateLimiterFeedback40=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess41=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess42=== RUN TestResolveStorePath43=== PAUSE TestResolveStorePath44=== RUN TestDoWithRetry_BodyReplayedViaGetBody45=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody46=== RUN TestShellSplit47=== PAUSE TestShellSplit48=== RUN TestShellSplitErrors49=== PAUSE TestShellSplitErrors50=== RUN TestStreamPushReportsEveryPath51=== PAUSE TestStreamPushReportsEveryPath52=== RUN TestStreamPushBatchesUnderLoad53=== PAUSE TestStreamPushBatchesUnderLoad54=== RUN TestStreamPushIsolatesFailures55=== PAUSE TestStreamPushIsolatesFailures56=== RUN TestStreamPushGivesUpOnDeadServer57=== PAUSE TestStreamPushGivesUpOnDeadServer58=== RUN TestStreamPushRequestLine59=== PAUSE TestStreamPushRequestLine60=== RUN TestSetClientTLS61=== PAUSE TestSetClientTLS62=== RUN TestSetClientTLSDoesNotMutateDefaultTransport63=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport64=== RUN TestSetClientTLSErrors65=== PAUSE TestSetClientTLSErrors66=== RUN TestStaticToken67=== PAUSE TestStaticToken68=== RUN TestFileTokenReadsAndCaches69=== PAUSE TestFileTokenReadsAndCaches70=== RUN TestFileTokenMissing71=== PAUSE TestFileTokenMissing72=== RUN TestFileTokenEmpty73=== PAUSE TestFileTokenEmpty74=== RUN TestScriptTokenNoExpiryRerunsEveryCall75=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall76=== RUN TestScriptTokenCachesUntilRefresh77=== PAUSE TestScriptTokenCachesUntilRefresh78=== RUN TestScriptTokenEmptyToken79=== PAUSE TestScriptTokenEmptyToken80=== RUN TestScriptTokenBadJSON81=== PAUSE TestScriptTokenBadJSON82=== RUN TestScriptTokenScriptFails83=== PAUSE TestScriptTokenScriptFails84=== RUN TestScriptTokenEmptyCommand85=== PAUSE TestScriptTokenEmptyCommand86=== CONT TestDoServerRequestAttachesToken87=== CONT TestShellSplit88=== CONT TestResolveStorePath89=== CONT TestStaticToken90=== CONT TestParsePathInfoJSONMultiplePaths91=== CONT TestPathInfoCACompatibility92=== CONT TestStreamPushGivesUpOnDeadServer93=== CONT TestSetClientTLSErrors94--- PASS: TestShellSplit (0.00s)95=== CONT TestSetClientTLSDoesNotMutateDefaultTransport96--- PASS: TestStaticToken (0.00s)97=== CONT TestSetClientTLS98=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths99=== CONT TestConvertHashToNix32100=== RUN TestConvertHashToNix32/SRI_format_to_Nix32101=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32102=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths103=== RUN TestConvertHashToNix32/already_Nix32_format104=== PAUSE TestConvertHashToNix32/already_Nix32_format105=== CONT TestDoWithRetry_BodyReplayedViaGetBody106=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths107=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths108=== CONT TestStreamPushRequestLine109=== RUN TestConvertHashToNix32/invalid_format110=== PAUSE TestConvertHashToNix32/invalid_format111=== CONT TestPathInfoHashCompatibility112=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)113=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)114=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon115=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon116=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI117=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI118=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512119=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512120=== RUN TestPathInfoCACompatibility/null_ca_field121=== PAUSE TestPathInfoCACompatibility/null_ca_field122=== RUN TestPathInfoCACompatibility/old_string_format_-_text123=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text124=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive125=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive126=== RUN TestPathInfoCACompatibility/new_structured_format_-_text127=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text128=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method129=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method130=== CONT TestParsePathInfoJSON131=== RUN TestParsePathInfoJSON/Nix_format132=== PAUSE TestParsePathInfoJSON/Nix_format133=== RUN TestParsePathInfoJSON/Lix_format134=== PAUSE TestParsePathInfoJSON/Lix_format135=== RUN TestParsePathInfoJSON/empty_input136=== PAUSE TestParsePathInfoJSON/empty_input137=== RUN TestParsePathInfoJSON/whitespace_only138=== PAUSE TestParsePathInfoJSON/whitespace_only139=== RUN TestParsePathInfoJSON/invalid_JSON140=== PAUSE TestParsePathInfoJSON/invalid_JSON141=== CONT TestDumpPathMatchesNix142=== CONT TestEncodeNixBase32WithRealHash143--- PASS: TestResolveStorePath (0.00s)1442026/09/16 19:09:35 ERROR Upload failed error="connection refused" count=201452026/09/16 19:09:35 ERROR Server seems unavailable, giving up on batch untried=171462026/09/16 19:09:35 ERROR Upload failed error="stale build claim" count=1147=== CONT TestEncodeNixBase32148=== RUN TestEncodeNixBase32/test_string_hash149=== CONT TestScriptTokenCachesUntilRefresh150=== PAUSE TestEncodeNixBase32/test_string_hash151=== RUN TestEncodeNixBase32/empty_input152=== PAUSE TestEncodeNixBase32/empty_input153--- PASS: TestEncodeNixBase32WithRealHash (0.00s)154--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)155--- PASS: TestStreamPushRequestLine (0.00s)156=== CONT TestScriptTokenEmptyCommand157--- PASS: TestScriptTokenEmptyCommand (0.00s)158=== CONT TestScriptTokenScriptFails159=== CONT TestDumpPathWriterError160=== CONT TestDumpPathSingleFile161=== RUN TestSetClientTLSErrors/missing_cert_file162=== PAUSE TestSetClientTLSErrors/missing_cert_file163=== RUN TestSetClientTLSErrors/missing_key_file164=== PAUSE TestSetClientTLSErrors/missing_key_file165=== RUN TestSetClientTLSErrors/missing_ca_file166=== PAUSE TestSetClientTLSErrors/missing_ca_file167=== RUN TestSetClientTLSErrors/invalid_ca_file168=== PAUSE TestSetClientTLSErrors/invalid_ca_file169=== CONT TestScriptTokenBadJSON1702026/09/16 19:09:35 WARN Rate limiter enabled after throttle name=server-test rate=51712026/09/16 19:09:35 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:56980172--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)1732026/09/16 19:09:35 WARN Rate limiter backed off name=server-test rate=51742026/09/16 19:09:35 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:56980175--- PASS: TestDoServerRequestAttachesToken (0.01s)176=== CONT TestScriptTokenEmptyToken177=== CONT TestPartSizeForNAR178=== RUN TestPartSizeForNAR/zero_stays_at_minimum179=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum180=== RUN TestPartSizeForNAR/small_stays_at_minimum181=== PAUSE TestPartSizeForNAR/small_stays_at_minimum182=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum183=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum184=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts185=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts186=== RUN TestPartSizeForNAR/1_TiB187=== PAUSE TestPartSizeForNAR/1_TiB188=== RUN TestPartSizeForNAR/5_TiB_S3_max_object189=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object190=== RUN TestPartSizeForNAR/capped_at_5_GiB191=== PAUSE TestPartSizeForNAR/capped_at_5_GiB192=== CONT TestUploadMultipart_SupersededByPeer193=== RUN TestUploadMultipart_SupersededByPeer/exists194=== PAUSE TestUploadMultipart_SupersededByPeer/exists195=== RUN TestUploadMultipart_SupersededByPeer/missing196=== PAUSE TestUploadMultipart_SupersededByPeer/missing197--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)198--- PASS: TestScriptTokenScriptFails (0.01s)199=== CONT TestGetStorePathHash200=== RUN TestGetStorePathHash/valid_store_path201=== PAUSE TestGetStorePathHash/valid_store_path202=== RUN TestGetStorePathHash/basename_without_hyphen_should_error203=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error204=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error205=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error206=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error207=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error208=== CONT TestStreamPushBatchesUnderLoad209=== CONT TestStreamPushReportsEveryPath210=== CONT TestStreamPushIsolatesFailures2112026/09/16 19:09:35 ERROR Upload failed error="bad path" count=3212--- PASS: TestStreamPushReportsEveryPath (0.00s)213=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess214--- PASS: TestStreamPushIsolatesFailures (0.00s)215=== CONT TestFilterOversizedClosures216=== RUN TestFilterOversizedClosures/no_limit_keeps_everything217=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything218=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped219=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped220=== RUN TestFilterOversizedClosures/all_closures_skipped221=== PAUSE TestFilterOversizedClosures/all_closures_skipped222=== CONT TestShellSplitErrors223--- PASS: TestShellSplitErrors (0.00s)224=== CONT TestFileTokenEmpty225=== RUN TestSetClientTLS/rejects_connection_without_client_cert226=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert227=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA2282026/09/16 19:09:36 WARN Rate limiter enabled after throttle name=server-test rate=5229=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA230=== RUN TestSetClientTLS/preserves_debug_logging_transport231--- PASS: TestFileTokenEmpty (0.00s)232=== CONT TestScriptTokenNoExpiryRerunsEveryCall233=== PAUSE TestSetClientTLS/preserves_debug_logging_transport234=== CONT TestFileTokenMissing235--- PASS: TestFileTokenMissing (0.00s)236=== CONT TestFileTokenReadsAndCaches237--- PASS: TestFileTokenReadsAndCaches (0.00s)238=== CONT TestCaseHackSuffix239--- PASS: TestScriptTokenBadJSON (0.01s)240=== CONT TestRateLimiterFeedback241=== RUN TestRateLimiterFeedback/429_enables_limiter242=== PAUSE TestRateLimiterFeedback/429_enables_limiter243=== RUN TestRateLimiterFeedback/503_enables_limiter244=== PAUSE TestRateLimiterFeedback/503_enables_limiter245=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter246=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter247=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter248=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter249=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths250=== CONT TestConvertHashToNix32/SRI_format_to_Nix32251=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths252--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)253 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)254 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)255=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)256=== CONT TestConvertHashToNix32/already_Nix32_format257=== CONT TestPathInfoCACompatibility/null_ca_field258=== CONT TestConvertHashToNix32/invalid_format259--- PASS: TestConvertHashToNix32 (0.00s)260 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)261 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)262 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)263=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon264=== CONT TestPathInfoCACompatibility/new_structured_format_-_text265=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method266=== CONT TestParsePathInfoJSON/Nix_format267=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive268=== CONT TestPathInfoCACompatibility/old_string_format_-_text269--- PASS: TestPathInfoCACompatibility (0.00s)270 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)271 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)272 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)273 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)274 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)275=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI276=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512277--- PASS: TestPathInfoHashCompatibility (0.00s)278 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)279 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)280 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)281 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)282=== CONT TestParsePathInfoJSON/whitespace_only283=== CONT TestParsePathInfoJSON/invalid_JSON284=== CONT TestParsePathInfoJSON/empty_input285=== CONT TestParsePathInfoJSON/Lix_format286--- PASS: TestParsePathInfoJSON (0.00s)287 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)288 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)289 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)290 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)291 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)292=== CONT TestEncodeNixBase32/test_string_hash293=== CONT TestEncodeNixBase32/empty_input294--- PASS: TestEncodeNixBase32 (0.00s)295 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)296 --- PASS: TestEncodeNixBase32/empty_input (0.00s)297=== CONT TestSetClientTLSErrors/missing_cert_file298=== CONT TestSetClientTLSErrors/missing_ca_file299=== CONT TestSetClientTLSErrors/invalid_ca_file300=== CONT TestSetClientTLSErrors/missing_key_file301=== CONT TestPartSizeForNAR/zero_stays_at_minimum302=== CONT TestPartSizeForNAR/1_TiB303=== CONT TestPartSizeForNAR/capped_at_5_GiB304=== CONT TestPartSizeForNAR/5_TiB_S3_max_object305=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum306=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts307=== CONT TestPartSizeForNAR/small_stays_at_minimum308--- PASS: TestPartSizeForNAR (0.00s)309 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)310 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)311 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)312 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)313 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)314 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)315 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)316=== CONT TestUploadMultipart_SupersededByPeer/exists317--- PASS: TestSetClientTLSErrors (0.01s)318 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)319 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)320 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)321 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)322=== CONT TestGetStorePathHash/valid_store_path323=== CONT TestUploadMultipart_SupersededByPeer/missing324=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error325--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)326 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)327 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)328=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error329=== CONT TestGetStorePathHash/basename_without_hyphen_should_error330--- PASS: TestGetStorePathHash (0.00s)331 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)332 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)333 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)334 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)335=== CONT TestFilterOversizedClosures/no_limit_keeps_everything336=== CONT TestFilterOversizedClosures/all_closures_skipped3372026/09/16 19:09:36 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=50338=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3392026/09/16 19:09:36 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=2000340--- PASS: TestFilterOversizedClosures (0.00s)341 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)342 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)343 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)344=== CONT TestSetClientTLS/rejects_connection_without_client_cert345--- PASS: TestScriptTokenEmptyToken (0.01s)346=== CONT TestSetClientTLS/preserves_debug_logging_transport347=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA348=== CONT TestRateLimiterFeedback/429_enables_limiter3492026/09/16 19:09:36 WARN Rate limiter enabled after throttle name=server-test rate=53502026/09/16 19:09:36 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:569933512026/09/16 19:09:36 WARN Rate limiter backed off name=server-test rate=5352=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter353=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter354=== CONT TestRateLimiterFeedback/503_enables_limiter3552026/09/16 19:09:36 WARN Rate limiter enabled after throttle name=server-test rate=53562026/09/16 19:09:36 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:569993572026/09/16 19:09:36 WARN Rate limiter backed off name=server-test rate=5358--- PASS: TestRateLimiterFeedback (0.00s)359 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)360 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)361 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)362 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)3632026/09/16 19:09:36 http: TLS handshake error from 127.0.0.1:56990: remote error: tls: bad certificate364--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)365--- PASS: TestSetClientTLS (0.01s)366 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)367 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)368 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)369--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)370--- PASS: TestDumpPathWriterError (0.04s)371--- PASS: TestDumpPathSingleFile (0.05s)372--- PASS: TestCaseHackSuffix (0.04s)373--- PASS: TestDumpPathMatchesNix (0.07s)374--- PASS: TestStreamPushBatchesUnderLoad (0.10s)375--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)376PASS377Running server tests...378The files belonging to this database system will be owned by user "_nixbld1".379This user must also own the server process.380381The database cluster will be initialized with locale "C".382The default database encoding has accordingly been set to "SQL_ASCII".383The default text search configuration will be set to "english".384385Data page checksums are enabled.386387creating directory /nix/var/nix/builds/nix-64313-353831061/postgres2081438487/data ... ok388creating subdirectories ... ok389selecting dynamic shared memory implementation ... posix390selecting default "max_connections" ... 100391selecting default "shared_buffers" ... 128MB392selecting default time zone ... UTC393creating configuration files ... ok394running bootstrap script ... ok395performing post-bootstrap initialization ... ok396syncing data to disk ... ok397398initdb: warning: enabling "trust" authentication for local connections399initdb: 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.400401Success. You can now start the database server using:402403 pg_ctl -D /nix/var/nix/builds/nix-64313-353831061/postgres2081438487/data -l logfile start404405/nix/var/nix/builds/nix-64313-353831061/postgres2081438487:5432 - no response4062026-09-16 19:09:37.837 UTC [64351] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4072026-09-16 19:09:37.837 UTC [64351] LOG: listening on Unix socket "/nix/var/nix/builds/nix-64313-353831061/postgres2081438487/.s.PGSQL.5432"4082026-09-16 19:09:37.839 UTC [64358] LOG: database system was shut down at 2026-09-16 19:09:37 UTC4092026-09-16 19:09:37.840 UTC [64351] LOG: database system is ready to accept connections410/nix/var/nix/builds/nix-64313-353831061/postgres2081438487:5432 - accepting connections411=== RUN TestService_AuthMiddleware412=== PAUSE TestService_AuthMiddleware413=== RUN TestService_AuthMiddleware_MTLSProxyHeader414=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader415=== RUN TestService_AuthMiddleware_MTLSBoundSubjects416=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects417=== RUN TestService_ReadAuthMiddleware418=== PAUSE TestService_ReadAuthMiddleware419=== RUN TestService_AuthMiddleware_OIDC420=== PAUSE TestService_AuthMiddleware_OIDC421=== RUN TestService_RequireScope_OIDC422=== PAUSE TestService_RequireScope_OIDC423=== RUN TestService_ReadScope_PublicByDefault424=== PAUSE TestService_ReadScope_PublicByDefault425=== RUN TestCacheConfigHandler426=== PAUSE TestCacheConfigHandler427=== RUN TestCacheStatsHandler428=== PAUSE TestCacheStatsHandler429=== RUN TestClaim_BuildWaitComplete430=== PAUSE TestClaim_BuildWaitComplete431=== RUN TestClaim_GCMarkedOutputCountsAsAbsent432=== PAUSE TestClaim_GCMarkedOutputCountsAsAbsent433=== RUN TestClaim_TooManyStreams434=== PAUSE TestClaim_TooManyStreams435=== RUN TestClaim_HolderDisconnectKeepsClaim436=== PAUSE TestClaim_HolderDisconnectKeepsClaim437=== RUN TestClaim_FailWakesWaitersButIsNotRemembered438=== PAUSE TestClaim_FailWakesWaitersButIsNotRemembered439=== RUN TestClaim_FailWithoutKindReleases440=== PAUSE TestClaim_FailWithoutKindReleases441=== RUN TestClaim_StaleHeartbeatStolen442=== PAUSE TestClaim_StaleHeartbeatStolen443=== RUN TestClaim_TwoInstances444=== PAUSE TestClaim_TwoInstances445=== RUN TestClaim_InputsTouched446=== PAUSE TestClaim_InputsTouched447=== RUN TestClaim_StreamsThroughServer448=== PAUSE TestClaim_StreamsThroughServer449=== RUN TestClientCADerivations450=== PAUSE TestClientCADerivations451=== RUN TestClientErrorHandling452=== PAUSE TestClientErrorHandling453=== RUN TestClientIntegration454=== PAUSE TestClientIntegration455=== RUN TestClientMultipleUploads456=== PAUSE TestClientMultipleUploads457=== RUN TestClientWithDependencies458=== PAUSE TestClientWithDependencies459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestResolveDBConnectionString462=== PAUSE TestResolveDBConnectionString463=== RUN TestGCAdvisoryLockBlocksConcurrentRun4642026-09-16 19:09:38.183 UTC [64367] ERROR: relation "goose_db_version" does not exist at character 364652026-09-16 19:09:38.183 UTC [64367] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4662026/09/16 19:09:38 OK 20241026095416_initial_model.sql (21.8ms)4672026/09/16 19:09:38 OK 20251210153512_drop_unused_gin_index.sql (5.08ms)4682026/09/16 19:09:38 OK 20251218171726_add_pins.sql (7.78ms)4692026/09/16 19:09:38 OK 20260628120000_add_object_size_and_stats.sql (1.2ms)4702026/09/16 19:09:38 OK 20260905000000_add_claims.sql (8.79ms)4712026/09/16 19:09:38 goose: successfully migrated database to version: 202609050000004722026/09/16 19:09:38 OK 1_commit_pending_closure.sql (2.01ms)4732026/09/16 19:09:38 OK 2_object_stats_trigger.sql (307.75µs)4742026/09/16 19:09:38 goose: up to current file version: 2475--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.35s)476=== RUN TestGCBugBareHashReferences477=== PAUSE TestGCBugBareHashReferences478=== RUN TestGCMetrics479=== PAUSE TestGCMetrics480=== RUN TestGCTaskStore_StartNew481=== PAUSE TestGCTaskStore_StartNew482=== RUN TestGCTaskStore_DeduplicateSameParams483=== PAUSE TestGCTaskStore_DeduplicateSameParams484=== RUN TestGCTaskStore_ConflictDifferentParams485=== PAUSE TestGCTaskStore_ConflictDifferentParams486=== RUN TestGCTaskStore_GetEmpty487=== PAUSE TestGCTaskStore_GetEmpty488=== RUN TestGCTaskStore_GetReturnsLatest489=== PAUSE TestGCTaskStore_GetReturnsLatest490=== RUN TestGCTaskStore_CompletedAllowsNewTask491=== PAUSE TestGCTaskStore_CompletedAllowsNewTask492=== RUN TestGCTaskStore_PhaseUpdates493=== PAUSE TestGCTaskStore_PhaseUpdates494=== RUN TestGCTaskStore_Fail495=== PAUSE TestGCTaskStore_Fail496=== RUN TestGracefulShutdownDrainsInflight497=== PAUSE TestGracefulShutdownDrainsInflight498=== RUN TestService_healthCheckHandler499=== PAUSE TestService_healthCheckHandler500=== RUN TestService_readinessHandler501=== PAUSE TestService_readinessHandler502=== RUN TestGenerateLandingPage503=== PAUSE TestGenerateLandingPage504=== RUN TestCacheConfigHandlerMaxNarSize505=== PAUSE TestCacheConfigHandlerMaxNarSize506=== RUN TestCreatePendingClosureRejectsOversizedNAR507=== PAUSE TestCreatePendingClosureRejectsOversizedNAR508=== RUN TestNARDeduplicationMetadataUploadBug509=== PAUSE TestNARDeduplicationMetadataUploadBug510=== RUN TestMetricsInventory511=== PAUSE TestMetricsInventory512=== RUN TestService_NativeMTLS513=== PAUSE TestService_NativeMTLS514=== RUN TestServerTLSConfig515=== PAUSE TestServerTLSConfig516=== RUN TestMultipartCleanup517=== PAUSE TestMultipartCleanup518=== RUN TestObjectStatsTrigger519=== PAUSE TestObjectStatsTrigger520=== RUN TestOrphanedObjectsGC521=== PAUSE TestOrphanedObjectsGC522=== RUN TestOrphanedObjectsGCStressTest523=== PAUSE TestOrphanedObjectsGCStressTest524=== RUN TestResurrectedObjectNotDeleted525=== PAUSE TestResurrectedObjectNotDeleted526=== RUN TestParseSingleRange527=== PAUSE TestParseSingleRange528=== RUN TestIsValidCachePath529=== PAUSE TestIsValidCachePath530=== RUN TestReadProxyNarinfo531=== PAUSE TestReadProxyNarinfo532=== RUN TestReadProxyNarinfoAlreadyDecompressed533=== PAUSE TestReadProxyNarinfoAlreadyDecompressed534=== RUN TestReadProxyNarStreaming535=== PAUSE TestReadProxyNarStreaming536=== RUN TestReadProxy404537=== PAUSE TestReadProxy404538=== RUN TestReadProxyInvalidPath539=== PAUSE TestReadProxyInvalidPath540=== RUN TestReadProxyHead541=== PAUSE TestReadProxyHead542=== RUN TestReadProxyConditionalGet543=== PAUSE TestReadProxyConditionalGet544=== RUN TestReadProxyRootRedirectsToIndexHTML545=== PAUSE TestReadProxyRootRedirectsToIndexHTML546=== RUN TestReadProxyDisabled547=== PAUSE TestReadProxyDisabled548=== RUN TestReadRedirectNar549=== PAUSE TestReadRedirectNar550=== RUN TestReadRedirectKeepsNarinfoProxied551=== PAUSE TestReadRedirectKeepsNarinfoProxied552=== RUN TestReadProxyRangeRequest553=== PAUSE TestReadProxyRangeRequest554=== RUN TestReadRedirectUsesPublicS3URL555=== PAUSE TestReadRedirectUsesPublicS3URL556=== RUN TestRedundantMultipartUpload557=== PAUSE TestRedundantMultipartUpload558=== RUN TestCompleteMultipartUpload_ErrorButObjectExists559=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists560=== RUN TestCompletedNarNotReofferedAcrossClosures561=== PAUSE TestCompletedNarNotReofferedAcrossClosures562=== RUN TestPresignedUploadRegisteredBeforeCommit563=== PAUSE TestPresignedUploadRegisteredBeforeCommit564=== RUN TestService_Rustfstest565=== PAUSE TestService_Rustfstest566=== RUN TestParseSize567=== PAUSE TestParseSize568=== RUN TestSkippedUploadsHandler569=== PAUSE TestSkippedUploadsHandler570=== RUN TestSystemdListenerNotActivated571--- PASS: TestSystemdListenerNotActivated (0.00s)572=== RUN TestWatchdogBeatsWhenHealthy573--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)574=== RUN TestWatchdogSkipsWhenUnhealthy5752026/09/16 19:09:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5762026/09/16 19:09:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5772026/09/16 19:09:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5782026/09/16 19:09:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5792026/09/16 19:09:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5802026/09/16 19:09:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5812026/09/16 19:09:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5822026/09/16 19:09:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5832026/09/16 19:09:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5842026/09/16 19:09:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"585--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)586=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle587=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle588=== RUN TestProxyWriteTimeout589=== PAUSE TestProxyWriteTimeout590=== RUN TestIsValidUploadKey591=== PAUSE TestIsValidUploadKey592=== RUN TestUploadHandlersRejectInvalidKeys593=== PAUSE TestUploadHandlersRejectInvalidKeys594=== RUN TestUploadHandlersRejectOversizedBody595=== PAUSE TestUploadHandlersRejectOversizedBody596=== RUN TestService_cleanupPendingClosuresHandler597=== PAUSE TestService_cleanupPendingClosuresHandler598=== RUN TestService_createPendingClosureHandler599=== PAUSE TestService_createPendingClosureHandler600=== RUN TestService_verifyS3Integrity601=== PAUSE TestService_verifyS3Integrity602=== RUN TestCompleteMultipartUnregistered603=== PAUSE TestCompleteMultipartUnregistered604=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT605=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT606=== CONT TestSkippedUploadsHandler607=== CONT TestService_Rustfstest608=== CONT TestGCTaskStore_Fail609--- PASS: TestGCTaskStore_Fail (0.00s)610=== CONT TestService_cleanupPendingClosuresHandler611=== CONT TestPresignedUploadRegisteredBeforeCommit612=== CONT TestService_AuthMiddleware613=== CONT TestParseSize614--- PASS: TestParseSize (0.00s)615=== CONT TestReadProxyRangeRequest616=== CONT TestCompleteMultipartUpload_ErrorButObjectExists617=== CONT TestRedundantMultipartUpload618=== CONT TestReadRedirectUsesPublicS3URL619=== CONT TestCompletedNarNotReofferedAcrossClosures6202026/09/16 19:09:38 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000621--- PASS: TestSkippedUploadsHandler (0.00s)622=== CONT TestReadRedirectKeepsNarinfoProxied6232026-09-16 19:09:38.941 UTC [64452] ERROR: relation "goose_db_version" does not exist at character 366242026-09-16 19:09:38.941 UTC [64452] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6252026/09/16 19:09:38 OK 20241026095416_initial_model.sql (20.46ms)6262026/09/16 19:09:38 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)6272026/09/16 19:09:38 OK 20251218171726_add_pins.sql (3.09ms)6282026/09/16 19:09:38 OK 20260628120000_add_object_size_and_stats.sql (3.47ms)6292026-09-16 19:09:38.985 UTC [64453] ERROR: relation "goose_db_version" does not exist at character 366302026-09-16 19:09:38.985 UTC [64453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6312026/09/16 19:09:38 OK 20260905000000_add_claims.sql (6.23ms)6322026/09/16 19:09:38 goose: successfully migrated database to version: 202609050000006332026-09-16 19:09:38.989 UTC [64454] ERROR: relation "goose_db_version" does not exist at character 366342026-09-16 19:09:38.989 UTC [64454] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6352026/09/16 19:09:38 OK 1_commit_pending_closure.sql (3.52ms)6362026/09/16 19:09:38 OK 2_object_stats_trigger.sql (450.29µs)6372026/09/16 19:09:38 goose: up to current file version: 26382026-09-16 19:09:38.991 UTC [64455] ERROR: relation "goose_db_version" does not exist at character 366392026-09-16 19:09:38.991 UTC [64455] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6402026-09-16 19:09:38.992 UTC [64457] ERROR: relation "goose_db_version" does not exist at character 366412026-09-16 19:09:38.992 UTC [64457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6422026-09-16 19:09:38.992 UTC [64458] ERROR: relation "goose_db_version" does not exist at character 366432026-09-16 19:09:38.992 UTC [64458] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6442026-09-16 19:09:38.993 UTC [64456] ERROR: relation "goose_db_version" does not exist at character 366452026-09-16 19:09:38.993 UTC [64456] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6462026-09-16 19:09:38.994 UTC [64460] ERROR: relation "goose_db_version" does not exist at character 366472026-09-16 19:09:38.994 UTC [64460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6482026-09-16 19:09:38.994 UTC [64459] ERROR: relation "goose_db_version" does not exist at character 366492026-09-16 19:09:38.994 UTC [64459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6502026-09-16 19:09:38.994 UTC [64461] ERROR: relation "goose_db_version" does not exist at character 366512026-09-16 19:09:38.994 UTC [64461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6522026/09/16 19:09:38 OK 20241026095416_initial_model.sql (7.53ms)6532026/09/16 19:09:38 OK 20251210153512_drop_unused_gin_index.sql (1.02ms)6542026/09/16 19:09:39 OK 20241026095416_initial_model.sql (7.01ms)6552026/09/16 19:09:39 OK 20241026095416_initial_model.sql (6.09ms)6562026/09/16 19:09:39 OK 20241026095416_initial_model.sql (6.5ms)6572026/09/16 19:09:39 OK 20251210153512_drop_unused_gin_index.sql (588.42µs)6582026/09/16 19:09:39 OK 20251218171726_add_pins.sql (1.83ms)6592026/09/16 19:09:39 OK 20251210153512_drop_unused_gin_index.sql (991.21µs)6602026/09/16 19:09:39 OK 20251210153512_drop_unused_gin_index.sql (1.06ms)6612026/09/16 19:09:39 OK 20251218171726_add_pins.sql (1.53ms)6622026/09/16 19:09:39 OK 20251218171726_add_pins.sql (1.19ms)6632026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (2.11ms)6642026/09/16 19:09:39 OK 20241026095416_initial_model.sql (6.78ms)6652026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (1.4ms)6662026/09/16 19:09:39 OK 20251210153512_drop_unused_gin_index.sql (768.79µs)6672026/09/16 19:09:39 OK 20251218171726_add_pins.sql (2.45ms)6682026/09/16 19:09:39 OK 20241026095416_initial_model.sql (8.25ms)6692026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (1.58ms)6702026/09/16 19:09:39 OK 20241026095416_initial_model.sql (8.14ms)6712026/09/16 19:09:39 OK 20251210153512_drop_unused_gin_index.sql (868.46µs)6722026/09/16 19:09:39 OK 20260905000000_add_claims.sql (2.19ms)6732026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000006742026/09/16 19:09:39 OK 20251210153512_drop_unused_gin_index.sql (753.17µs)6752026/09/16 19:09:39 OK 20241026095416_initial_model.sql (7.33ms)6762026/09/16 19:09:39 OK 20251218171726_add_pins.sql (1.69ms)6772026/09/16 19:09:39 OK 20260905000000_add_claims.sql (1.96ms)6782026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000006792026/09/16 19:09:39 OK 20241026095416_initial_model.sql (6.44ms)6802026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (1.64ms)6812026/09/16 19:09:39 OK 20251210153512_drop_unused_gin_index.sql (393.04µs)6822026/09/16 19:09:39 OK 20260905000000_add_claims.sql (1.86ms)6832026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000006842026/09/16 19:09:39 OK 20251210153512_drop_unused_gin_index.sql (745.67µs)6852026/09/16 19:09:39 OK 20251218171726_add_pins.sql (1.54ms)6862026/09/16 19:09:39 OK 1_commit_pending_closure.sql (1.57ms)6872026/09/16 19:09:39 OK 1_commit_pending_closure.sql (1.09ms)6882026/09/16 19:09:39 OK 20251218171726_add_pins.sql (1.64ms)6892026/09/16 19:09:39 OK 2_object_stats_trigger.sql (292.33µs)6902026/09/16 19:09:39 goose: up to current file version: 26912026/09/16 19:09:39 OK 2_object_stats_trigger.sql (506.21µs)6922026/09/16 19:09:39 goose: up to current file version: 26932026/09/16 19:09:39 OK 1_commit_pending_closure.sql (1.14ms)6942026/09/16 19:09:39 OK 20260905000000_add_claims.sql (1.65ms)6952026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000006962026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (2.01ms)6972026/09/16 19:09:39 OK 20251218171726_add_pins.sql (1.47ms)6982026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (1.15ms)6992026/09/16 19:09:39 OK 2_object_stats_trigger.sql (459.04µs)7002026/09/16 19:09:39 goose: up to current file version: 27012026/09/16 19:09:39 OK 20251218171726_add_pins.sql (1.78ms)7022026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (1.42ms)7032026/09/16 19:09:39 OK 1_commit_pending_closure.sql (961.67µs)7042026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (1.08ms)7052026/09/16 19:09:39 OK 2_object_stats_trigger.sql (389.46µs)7062026/09/16 19:09:39 goose: up to current file version: 27072026/09/16 19:09:39 OK 20260905000000_add_claims.sql (1.14ms)7082026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000007092026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (1.15ms)7102026/09/16 19:09:39 OK 20260905000000_add_claims.sql (1.59ms)7112026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000007122026/09/16 19:09:39 OK 20260905000000_add_claims.sql (1.4ms)7132026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000007142026/09/16 19:09:39 OK 20260905000000_add_claims.sql (1.1ms)7152026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000007162026/09/16 19:09:39 OK 20260905000000_add_claims.sql (1.04ms)7172026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000007182026/09/16 19:09:39 OK 1_commit_pending_closure.sql (886.54µs)7192026/09/16 19:09:39 OK 1_commit_pending_closure.sql (1.2ms)7202026/09/16 19:09:39 OK 2_object_stats_trigger.sql (309.88µs)7212026/09/16 19:09:39 goose: up to current file version: 27222026/09/16 19:09:39 OK 1_commit_pending_closure.sql (729.42µs)7232026/09/16 19:09:39 OK 2_object_stats_trigger.sql (303.04µs)7242026/09/16 19:09:39 goose: up to current file version: 27252026/09/16 19:09:39 OK 1_commit_pending_closure.sql (735.42µs)7262026/09/16 19:09:39 OK 1_commit_pending_closure.sql (672.63µs)7272026/09/16 19:09:39 OK 2_object_stats_trigger.sql (221.79µs)7282026/09/16 19:09:39 goose: up to current file version: 27292026/09/16 19:09:39 OK 2_object_stats_trigger.sql (200.42µs)7302026/09/16 19:09:39 goose: up to current file version: 27312026/09/16 19:09:39 OK 2_object_stats_trigger.sql (175.71µs)7322026/09/16 19:09:39 goose: up to current file version: 2733--- PASS: TestService_Rustfstest (0.46s)734=== CONT TestReadRedirectNar735--- PASS: TestReadProxyRangeRequest (0.62s)736=== CONT TestReadProxyDisabled7372026/09/16 19:09:39 INFO Received uploads request method=POST path=/api/pending_closures7382026/09/16 19:09:39 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst7392026/09/16 19:09:39 INFO Received uploads request method=POST path=/api/pending_closures740--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.78s)741=== CONT TestReadProxyRootRedirectsToIndexHTML7422026/09/16 19:09:39 INFO Received uploads request method=POST path=/api/pending_closures7432026/09/16 19:09:39 INFO Received uploads request method=POST path=/api/pending_closures7442026-09-16 19:09:39.621 UTC [64468] ERROR: relation "goose_db_version" does not exist at character 367452026-09-16 19:09:39.621 UTC [64468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7462026/09/16 19:09:39 INFO Received cleanup request method=DELETE path=/api/pending_closures7472026/09/16 19:09:39 INFO Aborted multipart uploads count=07482026/09/16 19:09:39 INFO Received uploads request method=POST path=/api/pending_closures7492026/09/16 19:09:39 OK 20241026095416_initial_model.sql (60.7ms)7502026/09/16 19:09:39 OK 20251210153512_drop_unused_gin_index.sql (12.56ms)7512026-09-16 19:09:39.747 UTC [64469] ERROR: relation "goose_db_version" does not exist at character 367522026-09-16 19:09:39.747 UTC [64469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7532026/09/16 19:09:39 INFO Received cleanup request method=DELETE path=/api/pending_closures7542026/09/16 19:09:39 INFO Aborted multipart uploads count=17552026/09/16 19:09:39 OK 20251218171726_add_pins.sql (33.29ms)7562026/09/16 19:09:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7572026-09-16 19:09:39.763 UTC [64455] ERROR: Closure does not exist: id=17582026-09-16 19:09:39.763 UTC [64455] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE7592026-09-16 19:09:39.763 UTC [64455] STATEMENT: -- name: CommitPendingClosure :exec760 SELECT commit_pending_closure($1::bigint)761 762--- PASS: TestService_cleanupPendingClosuresHandler (1.13s)763=== CONT TestReadProxyConditionalGet7642026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (36.5ms)7652026/09/16 19:09:39 OK 20260905000000_add_claims.sql (21.26ms)7662026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000007672026/09/16 19:09:39 OK 1_commit_pending_closure.sql (2.65ms)7682026/09/16 19:09:39 OK 2_object_stats_trigger.sql (505.04µs)7692026/09/16 19:09:39 goose: up to current file version: 27702026/09/16 19:09:39 OK 20241026095416_initial_model.sql (70.71ms)7712026/09/16 19:09:39 OK 20251210153512_drop_unused_gin_index.sql (11.61ms)7722026/09/16 19:09:39 OK 20251218171726_add_pins.sql (19.19ms)7732026/09/16 19:09:39 OK 20260628120000_add_object_size_and_stats.sql (16.7ms)7742026/09/16 19:09:39 OK 20260905000000_add_claims.sql (6.25ms)7752026/09/16 19:09:39 goose: successfully migrated database to version: 202609050000007762026/09/16 19:09:39 OK 1_commit_pending_closure.sql (5.34ms)7772026/09/16 19:09:39 OK 2_object_stats_trigger.sql (733.67µs)7782026/09/16 19:09:39 goose: up to current file version: 2779--- PASS: TestReadRedirectUsesPublicS3URL (1.30s)780=== CONT TestReadProxyHead7812026-09-16 19:09:39.947 UTC [64472] ERROR: relation "goose_db_version" does not exist at character 367822026-09-16 19:09:39.947 UTC [64472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7832026/09/16 19:09:40 OK 20241026095416_initial_model.sql (32.43ms)7842026/09/16 19:09:40 OK 20251210153512_drop_unused_gin_index.sql (6.34ms)7852026/09/16 19:09:40 OK 20251218171726_add_pins.sql (25.82ms)7862026/09/16 19:09:40 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"787--- PASS: TestService_AuthMiddleware (1.44s)7882026/09/16 19:09:40 OK 20260628120000_add_object_size_and_stats.sql (25.55ms)789=== CONT TestReadProxyInvalidPath7902026/09/16 19:09:40 OK 20260905000000_add_claims.sql (20.41ms)7912026/09/16 19:09:40 goose: successfully migrated database to version: 202609050000007922026/09/16 19:09:40 OK 1_commit_pending_closure.sql (6.3ms)7932026/09/16 19:09:40 OK 2_object_stats_trigger.sql (408.17µs)7942026/09/16 19:09:40 goose: up to current file version: 27952026/09/16 19:09:40 INFO Received uploads request method=POST path=/api/pending_closures796--- PASS: TestReadRedirectKeepsNarinfoProxied (1.83s)797=== CONT TestReadProxy4047982026-09-16 19:09:40.517 UTC [64479] ERROR: relation "goose_db_version" does not exist at character 367992026-09-16 19:09:40.517 UTC [64479] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8002026/09/16 19:09:40 INFO Received uploads request method=POST path=/api/pending_closures8012026/09/16 19:09:40 OK 20241026095416_initial_model.sql (125.34ms)8022026/09/16 19:09:40 OK 20251210153512_drop_unused_gin_index.sql (14.71ms)8032026/09/16 19:09:40 OK 20251218171726_add_pins.sql (31.47ms)8042026/09/16 19:09:40 OK 20260628120000_add_object_size_and_stats.sql (37.58ms)8052026/09/16 19:09:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8062026/09/16 19:09:40 OK 20260905000000_add_claims.sql (67.85ms)8072026/09/16 19:09:40 goose: successfully migrated database to version: 202609050000008082026/09/16 19:09:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MjVmOGRmMzAtNTAxMy00MWM4LTlmYjktMDE0N2Y1NDM2OWUxLmViZTI3NGY0LWI5NWUtNDE5MS1iNTZjLWZlZTUxM2RiMTZkZHgxNzg5NTg1Nzc5NTQ2NDQ5MDAw parts=12809--- PASS: TestRedundantMultipartUpload (2.24s)810=== CONT TestReadProxyNarStreaming8112026/09/16 19:09:40 OK 1_commit_pending_closure.sql (6.58ms)8122026/09/16 19:09:40 OK 2_object_stats_trigger.sql (1.54ms)8132026/09/16 19:09:40 goose: up to current file version: 28142026/09/16 19:09:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8152026/09/16 19:09:40 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjVmOGRmMzAtNTAxMy00MWM4LTlmYjktMDE0N2Y1NDM2OWUxLmE2M2M4NzVkLTdkY2UtNGQ0MC05YzdkLTg4NDIyODgyYzk2MHgxNzg5NTg1NzgwNzI0OTY2MDAw8162026/09/16 19:09:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MjVmOGRmMzAtNTAxMy00MWM4LTlmYjktMDE0N2Y1NDM2OWUxLmE2M2M4NzVkLTdkY2UtNGQ0MC05YzdkLTg4NDIyODgyYzk2MHgxNzg5NTg1NzgwNzI0OTY2MDAw parts=1817--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.32s)818=== CONT TestReadProxyNarinfoAlreadyDecompressed8192026-09-16 19:09:40.971 UTC [64482] ERROR: relation "goose_db_version" does not exist at character 368202026-09-16 19:09:40.971 UTC [64482] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC821--- PASS: TestReadRedirectNar (1.90s)822=== CONT TestReadProxyNarinfo8232026/09/16 19:09:41 OK 20241026095416_initial_model.sql (110.75ms)8242026/09/16 19:09:41 OK 20251210153512_drop_unused_gin_index.sql (12.79ms)825--- PASS: TestReadProxyDisabled (1.89s)826=== CONT TestIsValidCachePath827=== RUN TestIsValidCachePath/narinfo828=== PAUSE TestIsValidCachePath/narinfo829=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars830=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars831=== RUN TestIsValidCachePath/nar_zst832=== PAUSE TestIsValidCachePath/nar_zst833=== RUN TestIsValidCachePath/nar_xz834=== PAUSE TestIsValidCachePath/nar_xz835=== RUN TestIsValidCachePath/nar_bz2836=== PAUSE TestIsValidCachePath/nar_bz2837=== RUN TestIsValidCachePath/nar_uncompressed838=== PAUSE TestIsValidCachePath/nar_uncompressed839=== RUN TestIsValidCachePath/ls840=== PAUSE TestIsValidCachePath/ls841=== RUN TestIsValidCachePath/log842=== PAUSE TestIsValidCachePath/log843=== RUN TestIsValidCachePath/realisation844=== PAUSE TestIsValidCachePath/realisation845=== RUN TestIsValidCachePath/nix-cache-info846=== PAUSE TestIsValidCachePath/nix-cache-info847=== RUN TestIsValidCachePath/index.html848=== PAUSE TestIsValidCachePath/index.html849=== RUN TestIsValidCachePath/traversal_parent850=== PAUSE TestIsValidCachePath/traversal_parent851=== RUN TestIsValidCachePath/traversal_in_middle852=== PAUSE TestIsValidCachePath/traversal_in_middle853=== RUN TestIsValidCachePath/invalid_char_e854=== PAUSE TestIsValidCachePath/invalid_char_e855=== RUN TestIsValidCachePath/invalid_char_u856=== PAUSE TestIsValidCachePath/invalid_char_u857=== RUN TestIsValidCachePath/random_path858=== PAUSE TestIsValidCachePath/random_path859=== RUN TestIsValidCachePath/empty860=== PAUSE TestIsValidCachePath/empty861=== RUN TestIsValidCachePath/leading_slash862=== PAUSE TestIsValidCachePath/leading_slash863=== RUN TestIsValidCachePath/wrong_extension864=== PAUSE TestIsValidCachePath/wrong_extension865=== RUN TestIsValidCachePath/short_hash866=== PAUSE TestIsValidCachePath/short_hash867=== CONT TestParseSingleRange868=== RUN TestParseSingleRange/none869=== PAUSE TestParseSingleRange/none870=== RUN TestParseSingleRange/unknown_unit871=== PAUSE TestParseSingleRange/unknown_unit872=== RUN TestParseSingleRange/multi-range_ignored873=== PAUSE TestParseSingleRange/multi-range_ignored874=== RUN TestParseSingleRange/malformed_no_dash875=== PAUSE TestParseSingleRange/malformed_no_dash876=== RUN TestParseSingleRange/malformed_both_empty877=== PAUSE TestParseSingleRange/malformed_both_empty878=== RUN TestParseSingleRange/malformed_end_before_start879=== PAUSE TestParseSingleRange/malformed_end_before_start880=== RUN TestParseSingleRange/closed881=== PAUSE TestParseSingleRange/closed882=== RUN TestParseSingleRange/open-ended883=== PAUSE TestParseSingleRange/open-ended884=== RUN TestParseSingleRange/end_clamped_to_size885=== PAUSE TestParseSingleRange/end_clamped_to_size886=== RUN TestParseSingleRange/suffix887=== PAUSE TestParseSingleRange/suffix888=== RUN TestParseSingleRange/suffix_exceeds_size889=== PAUSE TestParseSingleRange/suffix_exceeds_size890=== RUN TestParseSingleRange/single_byte891=== PAUSE TestParseSingleRange/single_byte892=== RUN TestParseSingleRange/start_past_EOF893=== PAUSE TestParseSingleRange/start_past_EOF894=== RUN TestParseSingleRange/start_far_past_EOF895=== PAUSE TestParseSingleRange/start_far_past_EOF896=== CONT TestResurrectedObjectNotDeleted8972026/09/16 19:09:41 OK 20251218171726_add_pins.sql (16.82ms)8982026/09/16 19:09:41 OK 20260628120000_add_object_size_and_stats.sql (47.85ms)8992026/09/16 19:09:41 OK 20260905000000_add_claims.sql (15.74ms)9002026/09/16 19:09:41 goose: successfully migrated database to version: 202609050000009012026/09/16 19:09:41 OK 1_commit_pending_closure.sql (2.49ms)9022026/09/16 19:09:41 OK 2_object_stats_trigger.sql (391.29µs)9032026/09/16 19:09:41 goose: up to current file version: 29042026-09-16 19:09:41.315 UTC [64489] ERROR: relation "goose_db_version" does not exist at character 369052026-09-16 19:09:41.315 UTC [64489] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC906--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.95s)907=== CONT TestOrphanedObjectsGCStressTest9082026/09/16 19:09:41 OK 20241026095416_initial_model.sql (102.39ms)9092026/09/16 19:09:41 OK 20251210153512_drop_unused_gin_index.sql (5.85ms)9102026/09/16 19:09:41 OK 20251218171726_add_pins.sql (12.16ms)9112026/09/16 19:09:41 OK 20260628120000_add_object_size_and_stats.sql (36.51ms)9122026/09/16 19:09:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete913--- PASS: TestReadProxyConditionalGet (1.80s)914=== CONT TestOrphanedObjectsGC9152026/09/16 19:09:41 OK 20260905000000_add_claims.sql (85.19ms)9162026/09/16 19:09:41 goose: successfully migrated database to version: 202609050000009172026/09/16 19:09:41 OK 1_commit_pending_closure.sql (6.97ms)9182026/09/16 19:09:41 OK 2_object_stats_trigger.sql (454.88µs)9192026/09/16 19:09:41 goose: up to current file version: 29202026/09/16 19:09:41 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MjVmOGRmMzAtNTAxMy00MWM4LTlmYjktMDE0N2Y1NDM2OWUxLjkwOGQ5ZDg0LTc1NTItNDkyMi04YTk5LWQ3NzhkOTgwNzU3N3gxNzg5NTg1NzgwMjQ4ODQ5MDAw parts=129212026/09/16 19:09:41 INFO Received uploads request method=POST path=/api/pending_closures922--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.00s)923=== CONT TestObjectStatsTrigger924--- PASS: TestReadProxyHead (1.81s)925=== CONT TestMultipartCleanup9262026-09-16 19:09:41.837 UTC [64498] ERROR: relation "goose_db_version" does not exist at character 369272026-09-16 19:09:41.837 UTC [64498] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC928--- PASS: TestReadProxyInvalidPath (1.85s)929=== CONT TestServerTLSConfig930=== RUN TestServerTLSConfig/no_client_CA931=== PAUSE TestServerTLSConfig/no_client_CA932=== RUN TestServerTLSConfig/missing_CA_file933=== PAUSE TestServerTLSConfig/missing_CA_file934=== RUN TestServerTLSConfig/not_a_PEM_file935=== PAUSE TestServerTLSConfig/not_a_PEM_file936=== CONT TestService_NativeMTLS9372026/09/16 19:09:41 OK 20241026095416_initial_model.sql (36.36ms)9382026/09/16 19:09:41 OK 20251210153512_drop_unused_gin_index.sql (796.96µs)9392026/09/16 19:09:41 OK 20251218171726_add_pins.sql (1.48ms)9402026/09/16 19:09:41 OK 20260628120000_add_object_size_and_stats.sql (9.01ms)9412026/09/16 19:09:41 OK 20260905000000_add_claims.sql (3.29ms)9422026/09/16 19:09:41 goose: successfully migrated database to version: 202609050000009432026/09/16 19:09:41 OK 1_commit_pending_closure.sql (1.84ms)9442026-09-16 19:09:41.945 UTC [64501] ERROR: relation "goose_db_version" does not exist at character 369452026-09-16 19:09:41.945 UTC [64501] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9462026/09/16 19:09:41 OK 2_object_stats_trigger.sql (5.43ms)9472026/09/16 19:09:41 goose: up to current file version: 29482026-09-16 19:09:42.024 UTC [64502] ERROR: relation "goose_db_version" does not exist at character 369492026-09-16 19:09:42.024 UTC [64502] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9502026/09/16 19:09:42 OK 20241026095416_initial_model.sql (83.16ms)9512026/09/16 19:09:42 OK 20251210153512_drop_unused_gin_index.sql (7.5ms)9522026/09/16 19:09:42 OK 20251218171726_add_pins.sql (15.81ms)9532026/09/16 19:09:42 OK 20260628120000_add_object_size_and_stats.sql (22.2ms)954--- PASS: TestReadProxy404 (1.66s)955=== CONT TestMetricsInventory9562026/09/16 19:09:42 OK 20241026095416_initial_model.sql (82.29ms)9572026/09/16 19:09:42 OK 20260905000000_add_claims.sql (10.34ms)9582026/09/16 19:09:42 goose: successfully migrated database to version: 202609050000009592026/09/16 19:09:42 OK 20251210153512_drop_unused_gin_index.sql (974.54µs)9602026/09/16 19:09:42 OK 1_commit_pending_closure.sql (2.2ms)9612026/09/16 19:09:42 OK 2_object_stats_trigger.sql (695.08µs)9622026/09/16 19:09:42 goose: up to current file version: 29632026/09/16 19:09:42 OK 20251218171726_add_pins.sql (2.27ms)9642026-09-16 19:09:42.141 UTC [64504] ERROR: relation "goose_db_version" does not exist at character 369652026-09-16 19:09:42.141 UTC [64504] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9662026/09/16 19:09:42 OK 20260628120000_add_object_size_and_stats.sql (16.03ms)9672026/09/16 19:09:42 OK 20260905000000_add_claims.sql (27.3ms)9682026/09/16 19:09:42 goose: successfully migrated database to version: 202609050000009692026/09/16 19:09:42 OK 1_commit_pending_closure.sql (2.92ms)9702026/09/16 19:09:42 OK 2_object_stats_trigger.sql (781.71µs)9712026/09/16 19:09:42 goose: up to current file version: 29722026-09-16 19:09:42.218 UTC [64506] ERROR: relation "goose_db_version" does not exist at character 369732026-09-16 19:09:42.218 UTC [64506] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9742026/09/16 19:09:42 OK 20241026095416_initial_model.sql (69.76ms)9752026/09/16 19:09:42 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)9762026/09/16 19:09:42 OK 20251218171726_add_pins.sql (10.09ms)9772026/09/16 19:09:42 OK 20260628120000_add_object_size_and_stats.sql (27.91ms)9782026/09/16 19:09:42 OK 20260905000000_add_claims.sql (41.59ms)9792026/09/16 19:09:42 goose: successfully migrated database to version: 202609050000009802026/09/16 19:09:42 OK 1_commit_pending_closure.sql (4.86ms)9812026/09/16 19:09:42 OK 20241026095416_initial_model.sql (82.34ms)9822026/09/16 19:09:42 OK 2_object_stats_trigger.sql (2.49ms)9832026/09/16 19:09:42 goose: up to current file version: 29842026/09/16 19:09:42 OK 20251210153512_drop_unused_gin_index.sql (3.77ms)985--- PASS: TestReadProxyNarStreaming (1.47s)986=== CONT TestNARDeduplicationMetadataUploadBug9872026/09/16 19:09:42 OK 20251218171726_add_pins.sql (29.56ms)9882026/09/16 19:09:42 OK 20260628120000_add_object_size_and_stats.sql (20.76ms)9892026/09/16 19:09:42 OK 20260905000000_add_claims.sql (24.74ms)9902026/09/16 19:09:42 goose: successfully migrated database to version: 202609050000009912026/09/16 19:09:42 OK 1_commit_pending_closure.sql (2.46ms)9922026/09/16 19:09:42 OK 2_object_stats_trigger.sql (582.25µs)9932026/09/16 19:09:42 goose: up to current file version: 29942026-09-16 19:09:42.530 UTC [64509] ERROR: relation "goose_db_version" does not exist at character 369952026-09-16 19:09:42.530 UTC [64509] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC996--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.59s)997=== CONT TestCreatePendingClosureRejectsOversizedNAR9982026/09/16 19:09:42 INFO Received uploads request method=POST path=/api/pending_closures999--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1000=== CONT TestCacheConfigHandlerMaxNarSize1001--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1002=== CONT TestGenerateLandingPage1003--- PASS: TestGenerateLandingPage (0.00s)1004=== CONT TestService_readinessHandler10052026-09-16 19:09:42.563 UTC [64510] ERROR: relation "goose_db_version" does not exist at character 3610062026-09-16 19:09:42.563 UTC [64510] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10072026/09/16 19:09:42 OK 20241026095416_initial_model.sql (71.55ms)10082026-09-16 19:09:42.646 UTC [64513] ERROR: relation "goose_db_version" does not exist at character 3610092026-09-16 19:09:42.646 UTC [64513] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10102026/09/16 19:09:42 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)10112026/09/16 19:09:42 OK 20251218171726_add_pins.sql (11.24ms)10122026/09/16 19:09:42 OK 20241026095416_initial_model.sql (79.56ms)10132026/09/16 19:09:42 OK 20251210153512_drop_unused_gin_index.sql (9.74ms)10142026/09/16 19:09:42 OK 20260628120000_add_object_size_and_stats.sql (27.17ms)10152026/09/16 19:09:42 OK 20251218171726_add_pins.sql (11.39ms)10162026/09/16 19:09:42 OK 20260628120000_add_object_size_and_stats.sql (14.09ms)10172026/09/16 19:09:42 OK 20260905000000_add_claims.sql (21.87ms)10182026/09/16 19:09:42 goose: successfully migrated database to version: 2026090500000010192026/09/16 19:09:42 OK 1_commit_pending_closure.sql (9.96ms)10202026/09/16 19:09:42 OK 2_object_stats_trigger.sql (582.58µs)10212026/09/16 19:09:42 goose: up to current file version: 210222026/09/16 19:09:42 OK 20260905000000_add_claims.sql (25.52ms)10232026/09/16 19:09:42 goose: successfully migrated database to version: 2026090500000010242026/09/16 19:09:42 OK 1_commit_pending_closure.sql (4.74ms)10252026/09/16 19:09:42 OK 2_object_stats_trigger.sql (2.56ms)10262026/09/16 19:09:42 goose: up to current file version: 21027--- PASS: TestReadProxyNarinfo (1.75s)1028=== CONT TestService_healthCheckHandler10292026/09/16 19:09:42 OK 20241026095416_initial_model.sql (64.41ms)10302026/09/16 19:09:42 OK 20251210153512_drop_unused_gin_index.sql (6.82ms)10312026-09-16 19:09:42.760 UTC [64514] ERROR: relation "goose_db_version" does not exist at character 3610322026-09-16 19:09:42.760 UTC [64514] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10332026/09/16 19:09:42 OK 20251218171726_add_pins.sql (12.15ms)10342026/09/16 19:09:42 OK 20260628120000_add_object_size_and_stats.sql (10.96ms)10352026/09/16 19:09:42 OK 20260905000000_add_claims.sql (22.99ms)10362026/09/16 19:09:42 goose: successfully migrated database to version: 2026090500000010372026/09/16 19:09:42 OK 1_commit_pending_closure.sql (3.59ms)10382026/09/16 19:09:42 OK 2_object_stats_trigger.sql (485.71µs)10392026/09/16 19:09:42 goose: up to current file version: 210402026/09/16 19:09:42 OK 20241026095416_initial_model.sql (84.6ms)10412026/09/16 19:09:42 OK 20251210153512_drop_unused_gin_index.sql (8.04ms)10422026/09/16 19:09:42 OK 20251218171726_add_pins.sql (25.45ms)10432026/09/16 19:09:42 OK 20260628120000_add_object_size_and_stats.sql (24.55ms)10442026/09/16 19:09:42 OK 20260905000000_add_claims.sql (31.79ms)10452026/09/16 19:09:42 goose: successfully migrated database to version: 2026090500000010462026/09/16 19:09:42 OK 1_commit_pending_closure.sql (4.64ms)10472026/09/16 19:09:42 OK 2_object_stats_trigger.sql (911.25µs)10482026/09/16 19:09:42 goose: up to current file version: 210492026-09-16 19:09:42.986 UTC [64517] ERROR: relation "goose_db_version" does not exist at character 3610502026-09-16 19:09:42.986 UTC [64517] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1051--- PASS: TestResurrectedObjectNotDeleted (1.85s)1052=== CONT TestGracefulShutdownDrainsInflight10532026/09/16 19:09:42 INFO Starting HTTP server address=127.0.0.1:5709710542026/09/16 19:09:42 INFO Shutdown signal received, draining in-flight requests timeout=10s1055--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1056=== CONT TestClaim_StreamsThroughServer10572026/09/16 19:09:43 OK 20241026095416_initial_model.sql (78.71ms)10582026/09/16 19:09:43 OK 20251210153512_drop_unused_gin_index.sql (3.25ms)10592026/09/16 19:09:43 OK 20251218171726_add_pins.sql (5.55ms)10602026-09-16 19:09:43.116 UTC [64520] ERROR: relation "goose_db_version" does not exist at character 3610612026-09-16 19:09:43.116 UTC [64520] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10622026/09/16 19:09:43 OK 20260628120000_add_object_size_and_stats.sql (37.91ms)10632026/09/16 19:09:43 OK 20260905000000_add_claims.sql (34.38ms)10642026/09/16 19:09:43 goose: successfully migrated database to version: 2026090500000010652026/09/16 19:09:43 OK 1_commit_pending_closure.sql (10.21ms)10662026/09/16 19:09:43 OK 2_object_stats_trigger.sql (1.87ms)10672026/09/16 19:09:43 goose: up to current file version: 210682026-09-16 19:09:43.204 UTC [64521] ERROR: relation "goose_db_version" does not exist at character 3610692026-09-16 19:09:43.204 UTC [64521] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10702026/09/16 19:09:43 OK 20241026095416_initial_model.sql (72.06ms)10712026/09/16 19:09:43 OK 20251210153512_drop_unused_gin_index.sql (9.11ms)10722026/09/16 19:09:43 OK 20251218171726_add_pins.sql (33.25ms)10732026/09/16 19:09:43 OK 20260628120000_add_object_size_and_stats.sql (27.36ms)10742026/09/16 19:09:43 OK 20260905000000_add_claims.sql (10.1ms)10752026/09/16 19:09:43 goose: successfully migrated database to version: 2026090500000010762026/09/16 19:09:43 OK 1_commit_pending_closure.sql (3.57ms)10772026/09/16 19:09:43 OK 2_object_stats_trigger.sql (996.75µs)10782026/09/16 19:09:43 goose: up to current file version: 210792026/09/16 19:09:43 OK 20241026095416_initial_model.sql (72.26ms)10802026/09/16 19:09:43 OK 20251210153512_drop_unused_gin_index.sql (7.04ms)10812026/09/16 19:09:43 OK 20251218171726_add_pins.sql (16.62ms)10822026/09/16 19:09:43 OK 20260628120000_add_object_size_and_stats.sql (11.21ms)10832026/09/16 19:09:43 OK 20260905000000_add_claims.sql (19ms)10842026/09/16 19:09:43 goose: successfully migrated database to version: 2026090500000010852026/09/16 19:09:43 OK 1_commit_pending_closure.sql (3.48ms)10862026/09/16 19:09:43 OK 2_object_stats_trigger.sql (1.24ms)10872026/09/16 19:09:43 goose: up to current file version: 210882026-09-16 19:09:43.380 UTC [64522] ERROR: relation "goose_db_version" does not exist at character 3610892026-09-16 19:09:43.380 UTC [64522] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10902026/09/16 19:09:43 OK 20241026095416_initial_model.sql (53.92ms)10912026/09/16 19:09:43 OK 20251210153512_drop_unused_gin_index.sql (9.61ms)1092--- PASS: TestObjectStatsTrigger (1.85s)1093=== CONT TestGCTaskStore_PhaseUpdates1094--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1095=== CONT TestGCTaskStore_CompletedAllowsNewTask1096--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1097=== CONT TestGCTaskStore_GetReturnsLatest1098--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1099=== CONT TestGCTaskStore_GetEmpty1100--- PASS: TestGCTaskStore_GetEmpty (0.00s)1101=== CONT TestGCTaskStore_ConflictDifferentParams1102--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1103=== CONT TestGCTaskStore_DeduplicateSameParams1104--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1105=== CONT TestCompleteMultipartUnregistered11062026/09/16 19:09:43 OK 20251218171726_add_pins.sql (8.33ms)11072026/09/16 19:09:43 OK 20260628120000_add_object_size_and_stats.sql (15.59ms)11082026/09/16 19:09:43 OK 20260905000000_add_claims.sql (16.61ms)11092026/09/16 19:09:43 goose: successfully migrated database to version: 2026090500000011102026/09/16 19:09:43 OK 1_commit_pending_closure.sql (2.73ms)11112026/09/16 19:09:43 OK 2_object_stats_trigger.sql (581.96µs)11122026/09/16 19:09:43 goose: up to current file version: 211132026-09-16 19:09:43.534 UTC [64525] ERROR: relation "goose_db_version" does not exist at character 3611142026-09-16 19:09:43.534 UTC [64525] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11152026/09/16 19:09:43 INFO Received uploads request method=POST path=/api/pending_closures11162026/09/16 19:09:43 OK 20241026095416_initial_model.sql (75.64ms)11172026/09/16 19:09:43 OK 20251210153512_drop_unused_gin_index.sql (2.87ms)11182026/09/16 19:09:43 OK 20251218171726_add_pins.sql (27.74ms)11192026/09/16 19:09:43 OK 20260628120000_add_object_size_and_stats.sql (22.7ms)11202026/09/16 19:09:43 OK 20260905000000_add_claims.sql (28.57ms)11212026/09/16 19:09:43 goose: successfully migrated database to version: 2026090500000011222026/09/16 19:09:43 OK 1_commit_pending_closure.sql (3.44ms)11232026/09/16 19:09:43 OK 2_object_stats_trigger.sql (704.13µs)11242026/09/16 19:09:43 goose: up to current file version: 211252026-09-16 19:09:43.781 UTC [64526] ERROR: relation "goose_db_version" does not exist at character 3611262026-09-16 19:09:43.781 UTC [64526] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1127=== NAME TestOrphanedObjectsGC1128 orphaned_objects_gc_test.go:290: GC Test Summary:1129 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1130 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1131 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1132 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1133 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1134--- PASS: TestOrphanedObjectsGC (2.22s)1135=== CONT TestGCTaskStore_StartNew1136--- PASS: TestGCTaskStore_StartNew (0.00s)1137=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT11382026/09/16 19:09:43 INFO Received cleanup request method=DELETE path=/api/pending_closures11392026/09/16 19:09:43 INFO Aborted multipart uploads count=111402026/09/16 19:09:43 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11412026/09/16 19:09:43 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1142--- PASS: TestService_NativeMTLS (1.91s)1143=== CONT TestIsValidUploadKey1144=== RUN TestIsValidUploadKey/narinfo1145=== PAUSE TestIsValidUploadKey/narinfo1146=== RUN TestIsValidUploadKey/nar_zst1147=== PAUSE TestIsValidUploadKey/nar_zst1148=== RUN TestIsValidUploadKey/nar_xz1149=== PAUSE TestIsValidUploadKey/nar_xz1150=== RUN TestIsValidUploadKey/nar_plain1151=== PAUSE TestIsValidUploadKey/nar_plain1152=== RUN TestIsValidUploadKey/listing1153=== PAUSE TestIsValidUploadKey/listing1154=== RUN TestIsValidUploadKey/build_log1155=== PAUSE TestIsValidUploadKey/build_log1156=== RUN TestIsValidUploadKey/build_log_home-manager_file1157=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1158=== RUN TestIsValidUploadKey/build_log_plus_in_name1159=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1160=== RUN TestIsValidUploadKey/build_log_question_mark1161=== PAUSE TestIsValidUploadKey/build_log_question_mark1162=== RUN TestIsValidUploadKey/build_log_equals1163=== PAUSE TestIsValidUploadKey/build_log_equals1164=== RUN TestIsValidUploadKey/realisation1165=== PAUSE TestIsValidUploadKey/realisation1166=== RUN TestIsValidUploadKey/realisation_plus_in_output1167=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1168=== RUN TestIsValidUploadKey/nix-cache-info1169=== PAUSE TestIsValidUploadKey/nix-cache-info1170=== RUN TestIsValidUploadKey/index.html1171=== PAUSE TestIsValidUploadKey/index.html1172=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1173=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1174=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1175=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1176=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1177=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1178=== RUN TestIsValidUploadKey/traversal1179=== PAUSE TestIsValidUploadKey/traversal1180=== RUN TestIsValidUploadKey/traversal_nar1181=== PAUSE TestIsValidUploadKey/traversal_nar1182=== RUN TestIsValidUploadKey/absolute1183=== PAUSE TestIsValidUploadKey/absolute1184=== RUN TestIsValidUploadKey/empty_key1185=== PAUSE TestIsValidUploadKey/empty_key1186=== RUN TestIsValidUploadKey/unknown_type1187=== PAUSE TestIsValidUploadKey/unknown_type1188=== CONT TestGCMetrics1189--- PASS: TestMultipartCleanup (2.08s)1190=== CONT TestUploadHandlersRejectOversizedBody1191=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1192=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1193=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1194=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1195=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1196=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1197=== CONT TestUploadHandlersRejectInvalidKeys1198=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1199=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1200=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1201=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1202=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1203=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1204=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1205=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1206=== CONT TestProxyWriteTimeout1207=== RUN TestProxyWriteTimeout/narinfo1208=== PAUSE TestProxyWriteTimeout/narinfo1209=== RUN TestProxyWriteTimeout/1_GiB_nar1210=== PAUSE TestProxyWriteTimeout/1_GiB_nar1211=== RUN TestProxyWriteTimeout/10_GiB_nar1212=== PAUSE TestProxyWriteTimeout/10_GiB_nar1213=== RUN TestProxyWriteTimeout/unknown_size1214=== PAUSE TestProxyWriteTimeout/unknown_size1215=== CONT TestGCBugBareHashReferences12162026/09/16 19:09:43 OK 20241026095416_initial_model.sql (44.15ms)12172026/09/16 19:09:43 OK 20251210153512_drop_unused_gin_index.sql (6.97ms)12182026/09/16 19:09:43 OK 20251218171726_add_pins.sql (6.04ms)12192026/09/16 19:09:43 OK 20260628120000_add_object_size_and_stats.sql (20.39ms)12202026/09/16 19:09:43 OK 20260905000000_add_claims.sql (13.04ms)12212026/09/16 19:09:43 goose: successfully migrated database to version: 2026090500000012222026/09/16 19:09:43 OK 1_commit_pending_closure.sql (1.75ms)12232026/09/16 19:09:43 OK 2_object_stats_trigger.sql (301.17µs)12242026/09/16 19:09:43 goose: up to current file version: 21225--- PASS: TestMetricsInventory (1.85s)1226=== CONT TestResolveDBConnectionString1227=== RUN TestResolveDBConnectionString/flag_wins1228=== PAUSE TestResolveDBConnectionString/flag_wins1229=== RUN TestResolveDBConnectionString/file_when_flag_empty1230=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1231=== RUN TestResolveDBConnectionString/missing_file_is_an_error1232=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1233=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1234=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1235=== RUN TestResolveDBConnectionString/nothing_configured1236=== PAUSE TestResolveDBConnectionString/nothing_configured1237=== CONT TestPinProtectsFromGC12382026-09-16 19:09:44.221 UTC [64537] ERROR: relation "goose_db_version" does not exist at character 3612392026-09-16 19:09:44.221 UTC [64537] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12402026/09/16 19:09:44 WARN readiness check failed error="closed pool"1241--- PASS: TestService_readinessHandler (1.76s)1242=== CONT TestClientWithDependencies1243=== NAME TestNARDeduplicationMetadataUploadBug1244 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-64313-353831061/TestNARDeduplicationMetadataUploadBug988028803/001/store/4ff421h5qfl496lfr3dh4ycxpad63p77-file1.txt12452026/09/16 19:09:44 OK 20241026095416_initial_model.sql (64.07ms)12462026/09/16 19:09:44 OK 20251210153512_drop_unused_gin_index.sql (1.15ms)12472026/09/16 19:09:44 OK 20251218171726_add_pins.sql (7.83ms)12482026/09/16 19:09:44 OK 20260628120000_add_object_size_and_stats.sql (18.42ms)12492026/09/16 19:09:44 OK 20260905000000_add_claims.sql (2.68ms)12502026/09/16 19:09:44 goose: successfully migrated database to version: 2026090500000012512026/09/16 19:09:44 OK 1_commit_pending_closure.sql (1.76ms)12522026/09/16 19:09:44 OK 2_object_stats_trigger.sql (368.92µs)12532026/09/16 19:09:44 goose: up to current file version: 212542026/09/16 19:09:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12552026/09/16 19:09:44 INFO Received uploads request method=POST path=/api/pending_closures1256--- PASS: TestService_healthCheckHandler (1.73s)1257=== CONT TestClientMultipleUploads12582026/09/16 19:09:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12592026/09/16 19:09:44 INFO Uploading 4ff421h5qfl496lfr3dh4ycxpad63p77-file1.txt (160B)12602026/09/16 19:09:44 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12612026/09/16 19:09:44 WARN Failed to register uploaded object key=4ff421h5qfl496lfr3dh4ycxpad63p77.ls error="server returned 404: 404 page not found\n"12622026/09/16 19:09:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12632026/09/16 19:09:44 INFO Signed narinfos id=1 count=112642026/09/16 19:09:44 INFO Uploading 1 narinfos12652026/09/16 19:09:44 WARN Failed to register uploaded object key=4ff421h5qfl496lfr3dh4ycxpad63p77.narinfo error="server returned 404: 404 page not found\n"12662026/09/16 19:09:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12672026/09/16 19:09:44 INFO Completed upload id=112682026/09/16 19:09:44 INFO Upload complete. (202ms)1269=== NAME TestNARDeduplicationMetadataUploadBug1270 metadata_upload_test.go:54: Retrieved narinfo from S3:1271 StorePath: /nix/var/nix/builds/nix-64313-353831061/TestNARDeduplicationMetadataUploadBug988028803/001/store/4ff421h5qfl496lfr3dh4ycxpad63p77-file1.txt1272 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1273 Compression: zstd1274 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1275 NarSize: 1601276 References: 1277 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1278 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1279 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1280 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1281 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-64313-353831061/TestNARDeduplicationMetadataUploadBug988028803/001/store/w1msc535jxqcdsfkgxgf3s94d3g1jrd4-file2.txt12822026-09-16 19:09:44.657 UTC [64550] ERROR: relation "goose_db_version" does not exist at character 3612832026-09-16 19:09:44.657 UTC [64550] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12842026/09/16 19:09:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12852026/09/16 19:09:44 INFO Received uploads request method=POST path=/api/pending_closures12862026/09/16 19:09:44 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12872026/09/16 19:09:44 WARN Failed to register uploaded object key=w1msc535jxqcdsfkgxgf3s94d3g1jrd4.ls error="server returned 404: 404 page not found\n"12882026/09/16 19:09:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12892026/09/16 19:09:44 INFO Signed narinfos id=2 count=112902026/09/16 19:09:44 INFO Uploading 1 narinfos12912026/09/16 19:09:44 WARN Failed to register uploaded object key=w1msc535jxqcdsfkgxgf3s94d3g1jrd4.narinfo error="server returned 404: 404 page not found\n"12922026/09/16 19:09:44 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12932026/09/16 19:09:44 INFO Completed upload id=212942026/09/16 19:09:44 INFO Upload complete. (126ms)1295 metadata_upload_test.go:76: Retrieved narinfo from S3:1296 StorePath: /nix/var/nix/builds/nix-64313-353831061/TestNARDeduplicationMetadataUploadBug988028803/001/store/w1msc535jxqcdsfkgxgf3s94d3g1jrd4-file2.txt1297 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1298 Compression: zstd1299 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1300 NarSize: 1601301 References: 1302 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1303 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1304 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1305 {"version":1,"root":{"type":"regular","size":44}}1306--- PASS: TestNARDeduplicationMetadataUploadBug (2.48s)1307=== CONT TestClientIntegration13082026/09/16 19:09:44 OK 20241026095416_initial_model.sql (147.43ms)13092026/09/16 19:09:44 OK 20251210153512_drop_unused_gin_index.sql (6.77ms)13102026/09/16 19:09:44 OK 20251218171726_add_pins.sql (22.04ms)13112026-09-16 19:09:44.890 UTC [64560] ERROR: relation "goose_db_version" does not exist at character 3613122026-09-16 19:09:44.890 UTC [64560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13132026/09/16 19:09:44 OK 20260628120000_add_object_size_and_stats.sql (32.73ms)13142026/09/16 19:09:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13152026/09/16 19:09:44 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1316--- PASS: TestCompleteMultipartUnregistered (1.50s)1317=== CONT TestClaim_BuildWaitComplete13182026/09/16 19:09:44 OK 20260905000000_add_claims.sql (64.13ms)13192026/09/16 19:09:44 goose: successfully migrated database to version: 2026090500000013202026-09-16 19:09:44.986 UTC [64561] ERROR: relation "goose_db_version" does not exist at character 3613212026-09-16 19:09:44.986 UTC [64561] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13222026/09/16 19:09:44 OK 1_commit_pending_closure.sql (1.93ms)13232026/09/16 19:09:44 OK 2_object_stats_trigger.sql (314.58µs)13242026/09/16 19:09:44 goose: up to current file version: 213252026/09/16 19:09:45 OK 20241026095416_initial_model.sql (166.4ms)13262026/09/16 19:09:45 OK 20251210153512_drop_unused_gin_index.sql (9.42ms)13272026/09/16 19:09:45 OK 20251218171726_add_pins.sql (26.31ms)13282026/09/16 19:09:45 OK 20260628120000_add_object_size_and_stats.sql (26.52ms)13292026/09/16 19:09:45 OK 20241026095416_initial_model.sql (164.49ms)13302026/09/16 19:09:45 OK 20251210153512_drop_unused_gin_index.sql (13.52ms)13312026/09/16 19:09:45 OK 20260905000000_add_claims.sql (33.46ms)13322026/09/16 19:09:45 goose: successfully migrated database to version: 2026090500000013332026/09/16 19:09:45 OK 1_commit_pending_closure.sql (10.39ms)13342026/09/16 19:09:45 OK 2_object_stats_trigger.sql (737.83µs)13352026/09/16 19:09:45 goose: up to current file version: 213362026/09/16 19:09:45 INFO Received uploads request method=POST path=/api/pending_closures13372026-09-16 19:09:45.244 UTC [64564] ERROR: relation "goose_db_version" does not exist at character 3613382026-09-16 19:09:45.244 UTC [64564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13392026/09/16 19:09:45 OK 20251218171726_add_pins.sql (32.17ms)13402026/09/16 19:09:45 OK 20260628120000_add_object_size_and_stats.sql (7.45ms)1341--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.53s)1342=== CONT TestClaim_InputsTouched13432026/09/16 19:09:45 OK 20260905000000_add_claims.sql (69.37ms)13442026/09/16 19:09:45 goose: successfully migrated database to version: 2026090500000013452026/09/16 19:09:45 OK 1_commit_pending_closure.sql (9.6ms)13462026/09/16 19:09:45 OK 2_object_stats_trigger.sql (888.83µs)13472026/09/16 19:09:45 goose: up to current file version: 213482026/09/16 19:09:45 OK 20241026095416_initial_model.sql (165.5ms)13492026/09/16 19:09:45 OK 20251210153512_drop_unused_gin_index.sql (12.44ms)13502026/09/16 19:09:45 OK 20251218171726_add_pins.sql (35.59ms)13512026/09/16 19:09:45 OK 20260628120000_add_object_size_and_stats.sql (24.34ms)13522026/09/16 19:09:45 INFO Aborted multipart uploads count=013532026/09/16 19:09:45 WARN Force mode enabled - objects will be deleted immediately without grace period13542026/09/16 19:09:45 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013552026/09/16 19:09:45 INFO Vacuumed table table=pending_closures13562026/09/16 19:09:45 INFO Vacuumed table table=pending_objects13572026/09/16 19:09:45 INFO Vacuumed table table=multipart_uploads13582026/09/16 19:09:45 INFO Vacuumed table table=closures13592026/09/16 19:09:45 INFO Vacuumed table table=objects1360--- PASS: TestGCMetrics (1.72s)1361=== CONT TestClaim_TwoInstances13622026/09/16 19:09:45 OK 20260905000000_add_claims.sql (67.48ms)13632026/09/16 19:09:45 goose: successfully migrated database to version: 2026090500000013642026/09/16 19:09:45 OK 1_commit_pending_closure.sql (3.27ms)13652026/09/16 19:09:45 OK 2_object_stats_trigger.sql (548.38µs)13662026/09/16 19:09:45 goose: up to current file version: 213672026-09-16 19:09:45.871 UTC [64570] ERROR: relation "goose_db_version" does not exist at character 3613682026-09-16 19:09:45.871 UTC [64570] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1369--- PASS: TestGCBugBareHashReferences (2.21s)1370=== CONT TestClientErrorHandling1371=== RUN TestClientErrorHandling/InvalidStorePath1372=== PAUSE TestClientErrorHandling/InvalidStorePath1373=== RUN TestClientErrorHandling/InvalidAuthToken1374=== PAUSE TestClientErrorHandling/InvalidAuthToken1375=== RUN TestClientErrorHandling/ServerNotAvailable1376=== PAUSE TestClientErrorHandling/ServerNotAvailable1377=== CONT TestClientCADerivations13782026/09/16 19:09:46 OK 20241026095416_initial_model.sql (176.61ms)13792026/09/16 19:09:46 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)13802026/09/16 19:09:46 OK 20251218171726_add_pins.sql (3.92ms)13812026-09-16 19:09:46.114 UTC [64574] ERROR: relation "goose_db_version" does not exist at character 3613822026-09-16 19:09:46.114 UTC [64574] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13832026/09/16 19:09:46 OK 20260628120000_add_object_size_and_stats.sql (40.58ms)13842026/09/16 19:09:46 OK 20260905000000_add_claims.sql (31.83ms)13852026/09/16 19:09:46 goose: successfully migrated database to version: 2026090500000013862026/09/16 19:09:46 OK 1_commit_pending_closure.sql (2.15ms)13872026/09/16 19:09:46 OK 2_object_stats_trigger.sql (274µs)13882026/09/16 19:09:46 goose: up to current file version: 21389--- PASS: TestClaim_StreamsThroughServer (3.14s)1390=== CONT TestClaim_StaleHeartbeatStolen13912026-09-16 19:09:46.268 UTC [64578] ERROR: relation "goose_db_version" does not exist at character 3613922026-09-16 19:09:46.268 UTC [64578] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13932026/09/16 19:09:46 OK 20241026095416_initial_model.sql (141.66ms)13942026/09/16 19:09:46 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)13952026/09/16 19:09:46 OK 20251218171726_add_pins.sql (21.8ms)13962026-09-16 19:09:46.350 UTC [64581] ERROR: relation "goose_db_version" does not exist at character 3613972026-09-16 19:09:46.350 UTC [64581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1398=== NAME TestPinProtectsFromGC1399 client_integration_test.go:648: Pinned store path: /nix/var/nix/builds/nix-64313-353831061/TestPinProtectsFromGC615934418/001/store/5fxpqzav0wl24gnyi3wjsrxyc5brcag6-pinned-file.txt1400 client_integration_test.go:649: Unpinned store path: /nix/var/nix/builds/nix-64313-353831061/TestPinProtectsFromGC615934418/001/store/qy58rlr72jiddz4n1jp9jykblkj4s0an-unpinned-file.txt14012026/09/16 19:09:46 OK 20260628120000_add_object_size_and_stats.sql (33.32ms)14022026/09/16 19:09:46 OK 20260905000000_add_claims.sql (29.62ms)14032026/09/16 19:09:46 goose: successfully migrated database to version: 2026090500000014042026/09/16 19:09:46 OK 20241026095416_initial_model.sql (86.84ms)14052026/09/16 19:09:46 OK 1_commit_pending_closure.sql (1.7ms)14062026/09/16 19:09:46 OK 2_object_stats_trigger.sql (223µs)14072026/09/16 19:09:46 goose: up to current file version: 214082026/09/16 19:09:46 OK 20251210153512_drop_unused_gin_index.sql (7.02ms)14092026/09/16 19:09:46 OK 20251218171726_add_pins.sql (15.83ms)14102026/09/16 19:09:46 OK 20260628120000_add_object_size_and_stats.sql (7.57ms)14112026/09/16 19:09:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14122026/09/16 19:09:46 OK 20260905000000_add_claims.sql (17.93ms)14132026/09/16 19:09:46 goose: successfully migrated database to version: 2026090500000014142026/09/16 19:09:46 OK 1_commit_pending_closure.sql (1.58ms)14152026/09/16 19:09:46 OK 2_object_stats_trigger.sql (250µs)14162026/09/16 19:09:46 goose: up to current file version: 214172026/09/16 19:09:46 OK 20241026095416_initial_model.sql (63.31ms)14182026/09/16 19:09:46 OK 20251210153512_drop_unused_gin_index.sql (978.54µs)14192026/09/16 19:09:46 OK 20251218171726_add_pins.sql (30ms)14202026/09/16 19:09:46 INFO Received uploads request method=POST path=/api/pending_closures14212026/09/16 19:09:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14222026/09/16 19:09:46 INFO Uploading 5fxpqzav0wl24gnyi3wjsrxyc5brcag6-pinned-file.txt (128B)14232026/09/16 19:09:46 OK 20260628120000_add_object_size_and_stats.sql (41.75ms)14242026/09/16 19:09:46 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14252026/09/16 19:09:46 WARN Failed to register uploaded object key=5fxpqzav0wl24gnyi3wjsrxyc5brcag6.ls error="server returned 404: 404 page not found\n"14262026/09/16 19:09:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14272026/09/16 19:09:46 INFO Signed narinfos id=1 count=114282026/09/16 19:09:46 INFO Uploading 1 narinfos14292026/09/16 19:09:46 OK 20260905000000_add_claims.sql (49.43ms)14302026/09/16 19:09:46 goose: successfully migrated database to version: 2026090500000014312026/09/16 19:09:46 WARN Failed to register uploaded object key=5fxpqzav0wl24gnyi3wjsrxyc5brcag6.narinfo error="server returned 404: 404 page not found\n"14322026/09/16 19:09:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14332026/09/16 19:09:46 OK 1_commit_pending_closure.sql (6.44ms)14342026/09/16 19:09:46 OK 2_object_stats_trigger.sql (266.79µs)14352026/09/16 19:09:46 goose: up to current file version: 214362026/09/16 19:09:46 INFO Completed upload id=114372026/09/16 19:09:46 INFO Upload complete. (211ms)14382026/09/16 19:09:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14392026/09/16 19:09:46 INFO Received uploads request method=POST path=/api/pending_closures14402026/09/16 19:09:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14412026/09/16 19:09:46 INFO Uploading qy58rlr72jiddz4n1jp9jykblkj4s0an-unpinned-file.txt (128B)14422026/09/16 19:09:46 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14432026/09/16 19:09:46 WARN Failed to register uploaded object key=qy58rlr72jiddz4n1jp9jykblkj4s0an.ls error="server returned 404: 404 page not found\n"14442026/09/16 19:09:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14452026/09/16 19:09:46 INFO Signed narinfos id=2 count=114462026/09/16 19:09:46 INFO Uploading 1 narinfos14472026/09/16 19:09:46 WARN Failed to register uploaded object key=qy58rlr72jiddz4n1jp9jykblkj4s0an.narinfo error="server returned 404: 404 page not found\n"14482026/09/16 19:09:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14492026/09/16 19:09:46 INFO Completed upload id=214502026/09/16 19:09:46 INFO Upload complete. (142ms)14512026/09/16 19:09:46 INFO Received create pin request method=POST path=/api/pins/myapp14522026-09-16 19:09:46.832 UTC [64602] ERROR: relation "goose_db_version" does not exist at character 3614532026-09-16 19:09:46.832 UTC [64602] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14542026/09/16 19:09:46 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-64313-353831061/TestPinProtectsFromGC615934418/001/store/5fxpqzav0wl24gnyi3wjsrxyc5brcag6-pinned-file.txt narinfo_key=5fxpqzav0wl24gnyi3wjsrxyc5brcag6.narinfo14552026/09/16 19:09:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures14562026/09/16 19:09:46 INFO Garbage collection started1457=== NAME TestClientWithDependencies1458 client_integration_test.go:594: Built derivation: /nix/var/nix/builds/nix-64313-353831061/TestClientWithDependencies2975254942/001/store/l7rcxc6ln80i04z80l6b9078w7awm8wr-test-script1459=== NAME TestClientMultipleUploads1460 client_integration_test.go:339: Created store path 0: /nix/var/nix/builds/nix-64313-353831061/TestClientMultipleUploads2362087698/001/store/84nbknsr59bg1b84qqxb0dyv1mig2q2q-test-file-0.txt14612026/09/16 19:09:46 INFO Aborted multipart uploads count=014622026/09/16 19:09:46 WARN Force mode enabled - objects will be deleted immediately without grace period1463=== NAME TestClientWithDependencies1464 client_integration_test.go:596: Found 1 dependencies (including self)1465=== NAME TestOrphanedObjectsGCStressTest1466 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1467=== NAME TestClientMultipleUploads1468 client_integration_test.go:339: Created store path 1: /nix/var/nix/builds/nix-64313-353831061/TestClientMultipleUploads2362087698/001/store/ipgsqphnjap9s7hwml60lf94w8rc82nx-test-file-1.txt14692026-09-16 19:09:46.928 UTC [64613] ERROR: relation "goose_db_version" does not exist at character 3614702026-09-16 19:09:46.928 UTC [64613] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1471=== NAME TestOrphanedObjectsGCStressTest1472 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion14732026/09/16 19:09:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14742026/09/16 19:09:46 OK 20241026095416_initial_model.sql (74.09ms)14752026/09/16 19:09:46 INFO Received uploads request method=POST path=/api/pending_closures1476=== NAME TestClientMultipleUploads1477 client_integration_test.go:339: Created store path 2: /nix/var/nix/builds/nix-64313-353831061/TestClientMultipleUploads2362087698/001/store/2vswhbz6pdhrj0xzw58ya5my9a84082z-test-file-2.txt14782026/09/16 19:09:46 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)14792026/09/16 19:09:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14802026/09/16 19:09:46 INFO Uploading l7rcxc6ln80i04z80l6b9078w7awm8wr-test-script (136B)14812026/09/16 19:09:46 OK 20251218171726_add_pins.sql (14.2ms)14822026/09/16 19:09:46 OK 20260628120000_add_object_size_and_stats.sql (11.59ms)14832026/09/16 19:09:46 WARN Failed to register uploaded object key=log/5g70rkf2f6rdxpghyr9qzvxxx892mj50-test-script.drv error="server returned 404: 404 page not found\n"14842026/09/16 19:09:46 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14852026/09/16 19:09:46 OK 20241026095416_initial_model.sql (33.28ms)14862026/09/16 19:09:46 WARN Failed to register uploaded object key=l7rcxc6ln80i04z80l6b9078w7awm8wr.ls error="server returned 404: 404 page not found\n"14872026/09/16 19:09:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14882026/09/16 19:09:46 INFO Signed narinfos id=1 count=114892026/09/16 19:09:46 INFO Uploading 1 narinfos14902026/09/16 19:09:47 OK 20251210153512_drop_unused_gin_index.sql (10.74ms)14912026/09/16 19:09:47 WARN Failed to register uploaded object key=l7rcxc6ln80i04z80l6b9078w7awm8wr.narinfo error="server returned 404: 404 page not found\n"14922026/09/16 19:09:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14932026/09/16 19:09:47 OK 20260905000000_add_claims.sql (21.83ms)14942026/09/16 19:09:47 goose: successfully migrated database to version: 2026090500000014952026/09/16 19:09:47 OK 1_commit_pending_closure.sql (6.37ms)14962026/09/16 19:09:47 OK 2_object_stats_trigger.sql (323.79µs)14972026/09/16 19:09:47 goose: up to current file version: 214982026/09/16 19:09:47 OK 20251218171726_add_pins.sql (14.33ms)14992026/09/16 19:09:47 INFO Completed upload id=115002026/09/16 19:09:47 INFO Upload complete. (113ms)1501=== NAME TestClientWithDependencies1502 client_integration_test.go:598: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-64313-353831061/TestClientWithDependencies2975254942/001/store) requires matching store prefix15032026/09/16 19:09:47 OK 20260628120000_add_object_size_and_stats.sql (14.32ms)1504=== NAME TestClientIntegration1505 client_integration_test.go:277: Created store path: /nix/var/nix/builds/nix-64313-353831061/TestClientIntegration3827957040/002/store/7j7wvzpiwb8l2f75w03i4wa9pm31xwkb-test-file.txt1506--- PASS: TestClientWithDependencies (2.74s)1507=== CONT TestClaim_FailWithoutKindReleases15082026/09/16 19:09:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15092026/09/16 19:09:47 OK 20260905000000_add_claims.sql (23.13ms)15102026/09/16 19:09:47 goose: successfully migrated database to version: 2026090500000015112026/09/16 19:09:47 OK 1_commit_pending_closure.sql (1.97ms)15122026/09/16 19:09:47 OK 2_object_stats_trigger.sql (293.54µs)15132026/09/16 19:09:47 goose: up to current file version: 215142026/09/16 19:09:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=015152026/09/16 19:09:47 INFO Vacuumed table table=pending_closures15162026/09/16 19:09:47 WARN claim: cannot clear write deadline error="feature not supported"15172026/09/16 19:09:47 INFO Vacuumed table table=pending_objects15182026/09/16 19:09:47 INFO Received uploads request method=POST path=/api/pending_closures15192026/09/16 19:09:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15202026/09/16 19:09:47 INFO Vacuumed table table=multipart_uploads15212026/09/16 19:09:47 WARN claim: cannot clear write deadline error="feature not supported"15222026/09/16 19:09:47 WARN claim: cannot clear write deadline error="feature not supported"15232026/09/16 19:09:47 INFO Received uploads request method=POST path=/api/pending_closures15242026/09/16 19:09:47 INFO Vacuumed table table=closures15252026/09/16 19:09:47 INFO Received uploads request method=POST path=/api/pending_closures15262026/09/16 19:09:47 INFO Received uploads request method=POST path=/api/pending_closures15272026/09/16 19:09:47 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15282026/09/16 19:09:47 INFO Uploading ipgsqphnjap9s7hwml60lf94w8rc82nx-test-file-1.txt (160B)15292026/09/16 19:09:47 INFO Uploading 84nbknsr59bg1b84qqxb0dyv1mig2q2q-test-file-0.txt (160B)15302026/09/16 19:09:47 INFO Uploading 2vswhbz6pdhrj0xzw58ya5my9a84082z-test-file-2.txt (160B)15312026-09-16 19:09:47.136 UTC [64633] ERROR: relation "goose_db_version" does not exist at character 3615322026-09-16 19:09:47.136 UTC [64633] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15332026/09/16 19:09:47 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15342026/09/16 19:09:47 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15352026/09/16 19:09:47 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15362026/09/16 19:09:47 INFO Vacuumed table table=objects15372026/09/16 19:09:47 WARN Failed to register uploaded object key=ipgsqphnjap9s7hwml60lf94w8rc82nx.ls error="server returned 404: 404 page not found\n"15382026/09/16 19:09:47 WARN Failed to register uploaded object key=2vswhbz6pdhrj0xzw58ya5my9a84082z.ls error="server returned 404: 404 page not found\n"15392026/09/16 19:09:47 WARN Failed to register uploaded object key=84nbknsr59bg1b84qqxb0dyv1mig2q2q.ls error="server returned 404: 404 page not found\n"15402026/09/16 19:09:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15412026/09/16 19:09:47 INFO Signed narinfos id=1 count=115422026/09/16 19:09:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15432026/09/16 19:09:47 INFO Signed narinfos id=2 count=115442026/09/16 19:09:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign15452026/09/16 19:09:47 INFO Signed narinfos id=3 count=115462026/09/16 19:09:47 INFO Uploading 3 narinfos15472026/09/16 19:09:47 WARN Failed to register uploaded object key=2vswhbz6pdhrj0xzw58ya5my9a84082z.narinfo error="server returned 404: 404 page not found\n"15482026/09/16 19:09:47 WARN Failed to register uploaded object key=84nbknsr59bg1b84qqxb0dyv1mig2q2q.narinfo error="server returned 404: 404 page not found\n"15492026/09/16 19:09:47 WARN Failed to register uploaded object key=ipgsqphnjap9s7hwml60lf94w8rc82nx.narinfo error="server returned 404: 404 page not found\n"15502026/09/16 19:09:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15512026/09/16 19:09:47 INFO Received uploads request method=POST path=/api/pending_closures15522026/09/16 19:09:47 INFO Completed upload id=115532026/09/16 19:09:47 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15542026/09/16 19:09:47 INFO Completed upload id=215552026/09/16 19:09:47 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete15562026/09/16 19:09:47 INFO Completed upload id=315572026/09/16 19:09:47 INFO Upload complete. (179ms)1558=== NAME TestClientMultipleUploads1559 client_integration_test.go:350: Uploaded 3 paths in 214.909292ms15602026/09/16 19:09:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15612026/09/16 19:09:47 INFO Uploading 7j7wvzpiwb8l2f75w03i4wa9pm31xwkb-test-file.txt (152B)15622026/09/16 19:09:47 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15632026/09/16 19:09:47 WARN Failed to register uploaded object key=7j7wvzpiwb8l2f75w03i4wa9pm31xwkb.ls error="server returned 404: 404 page not found\n"15642026/09/16 19:09:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15652026/09/16 19:09:47 INFO Signed narinfos id=1 count=115662026/09/16 19:09:47 INFO Uploading 1 narinfos15672026-09-16 19:09:47.230 UTC [64635] ERROR: relation "goose_db_version" does not exist at character 3615682026-09-16 19:09:47.230 UTC [64635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15692026/09/16 19:09:47 WARN Failed to register uploaded object key=7j7wvzpiwb8l2f75w03i4wa9pm31xwkb.narinfo error="server returned 404: 404 page not found\n"15702026/09/16 19:09:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1571--- PASS: TestClientMultipleUploads (2.79s)1572=== CONT TestClaim_FailWakesWaitersButIsNotRemembered15732026/09/16 19:09:47 INFO Completed upload id=115742026/09/16 19:09:47 INFO Upload complete. (187ms)1575=== NAME TestClientIntegration1576 client_integration_test.go:293: Retrieved narinfo from S3:1577 StorePath: /nix/var/nix/builds/nix-64313-353831061/TestClientIntegration3827957040/002/store/7j7wvzpiwb8l2f75w03i4wa9pm31xwkb-test-file.txt1578 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1579 Compression: zstd1580 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11581 NarSize: 1521582 References: 1583 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11584 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1585 client_integration_test.go:294: Decompressed .ls content (64 bytes):1586 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1587 client_integration_test.go:297: Testing garbage collection...15882026/09/16 19:09:47 OK 20241026095416_initial_model.sql (108.15ms)15892026/09/16 19:09:47 OK 20251210153512_drop_unused_gin_index.sql (8.48ms)15902026/09/16 19:09:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures15912026/09/16 19:09:47 INFO Garbage collection started15922026/09/16 19:09:47 INFO Aborted multipart uploads count=015932026/09/16 19:09:47 WARN Force mode enabled - objects will be deleted immediately without grace period15942026/09/16 19:09:47 OK 20251218171726_add_pins.sql (26.36ms)15952026/09/16 19:09:47 OK 20260628120000_add_object_size_and_stats.sql (18.5ms)15962026/09/16 19:09:47 INFO Received uploads request method=POST path=/api/pending_closures15972026/09/16 19:09:47 OK 20241026095416_initial_model.sql (77.29ms)15982026/09/16 19:09:47 OK 20251210153512_drop_unused_gin_index.sql (6.24ms)15992026/09/16 19:09:47 OK 20260905000000_add_claims.sql (26.13ms)16002026/09/16 19:09:47 goose: successfully migrated database to version: 2026090500000016012026/09/16 19:09:47 OK 1_commit_pending_closure.sql (1.34ms)16022026/09/16 19:09:47 OK 2_object_stats_trigger.sql (288.83µs)16032026/09/16 19:09:47 goose: up to current file version: 216042026/09/16 19:09:47 OK 20251218171726_add_pins.sql (18.14ms)16052026/09/16 19:09:47 OK 20260628120000_add_object_size_and_stats.sql (15.15ms)16062026/09/16 19:09:47 OK 20260905000000_add_claims.sql (39.11ms)16072026/09/16 19:09:47 goose: successfully migrated database to version: 2026090500000016082026/09/16 19:09:47 OK 1_commit_pending_closure.sql (5.98ms)16092026/09/16 19:09:47 OK 2_object_stats_trigger.sql (230.71µs)16102026/09/16 19:09:47 goose: up to current file version: 216112026/09/16 19:09:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=016122026/09/16 19:09:47 INFO Vacuumed table table=pending_closures16132026/09/16 19:09:47 WARN claim: cannot clear write deadline error="feature not supported"16142026/09/16 19:09:47 INFO Vacuumed table table=pending_objects16152026/09/16 19:09:47 INFO Vacuumed table table=multipart_uploads16162026/09/16 19:09:47 WARN claim: cannot clear write deadline error="feature not supported"16172026/09/16 19:09:47 WARN claim: cannot clear write deadline error="feature not supported"16182026/09/16 19:09:47 INFO Received uploads request method=POST path=/api/pending_closures16192026/09/16 19:09:47 INFO Vacuumed table table=closures16202026/09/16 19:09:47 INFO Vacuumed table table=objects16212026/09/16 19:09:48 WARN claim: cannot clear write deadline error="feature not supported"16222026/09/16 19:09:48 WARN claim: cannot clear write deadline error="feature not supported"1623--- PASS: TestClaim_StaleHeartbeatStolen (1.90s)1624=== CONT TestClaim_HolderDisconnectKeepsClaim16252026/09/16 19:09:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16262026/09/16 19:09:48 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001000000000000000000000.nar.zst upload_id=MjVmOGRmMzAtNTAxMy00MWM4LTlmYjktMDE0N2Y1NDM2OWUxLmY0YjBjYWIwLTE3ZmYtNGVmMC1hYjRiLWZlNmEzZGM4NTc3OHgxNzg5NTg1Nzg3MTM3MTU3MDAw parts=1016272026/09/16 19:09:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16282026/09/16 19:09:48 INFO Signed narinfos id=1 count=116292026/09/16 19:09:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16302026/09/16 19:09:48 INFO Received uploads request method=POST path=/api/pending_closures16312026/09/16 19:09:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16322026/09/16 19:09:48 INFO Signed narinfos id=2 count=116332026/09/16 19:09:48 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16342026/09/16 19:09:48 INFO Completed upload id=216352026/09/16 19:09:48 WARN claim: cannot clear write deadline error="feature not supported"1636--- PASS: TestClaim_BuildWaitComplete (3.39s)1637=== CONT TestClaim_TooManyStreams1638=== NAME TestClientCADerivations1639 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-64313-353831061/TestClientCADerivations3852827849/001/store/7z8zjd0qhv4iaj3jwrrf8naq6dfmflqf-ca-test1640 client_ca_test.go:139: Found 1 dependencies (including self)16412026-09-16 19:09:48.434 UTC [64659] ERROR: relation "goose_db_version" does not exist at character 3616422026-09-16 19:09:48.434 UTC [64659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16432026/09/16 19:09:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16442026/09/16 19:09:48 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16452026/09/16 19:09:48 INFO Received uploads request method=POST path=/api/pending_closures16462026/09/16 19:09:48 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001700000000000000000000.nar.zst upload_id=MjVmOGRmMzAtNTAxMy00MWM4LTlmYjktMDE0N2Y1NDM2OWUxLmE5YWVkNGE2LTZhMjMtNDg4ZS1hMzFkLTA3NWUzMjg0ODNkN3gxNzg5NTg1Nzg3MzUyMzY0MDAw parts=1016472026/09/16 19:09:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16482026/09/16 19:09:48 INFO Completed upload id=116492026/09/16 19:09:48 WARN claim: cannot clear write deadline error="feature not supported"16502026/09/16 19:09:48 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16512026/09/16 19:09:48 INFO Uploading 7z8zjd0qhv4iaj3jwrrf8naq6dfmflqf-ca-test (144B)16522026/09/16 19:09:48 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16532026/09/16 19:09:48 WARN Failed to register uploaded object key=log/kq7mrijxr066jwzan2isrwzpqbsj77s6-ca-test.drv error="server returned 404: 404 page not found\n"16542026/09/16 19:09:48 WARN Failed to register uploaded object key=7z8zjd0qhv4iaj3jwrrf8naq6dfmflqf.ls error="server returned 404: 404 page not found\n"16552026/09/16 19:09:48 INFO Aborted multipart uploads count=016562026/09/16 19:09:48 WARN Force mode enabled - objects will be deleted immediately without grace period16572026/09/16 19:09:48 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=016582026/09/16 19:09:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16592026/09/16 19:09:48 INFO Signed narinfos id=1 count=116602026/09/16 19:09:48 INFO Uploading 1 narinfos16612026/09/16 19:09:48 OK 20241026095416_initial_model.sql (135.77ms)16622026/09/16 19:09:48 WARN Failed to register uploaded object key=7z8zjd0qhv4iaj3jwrrf8naq6dfmflqf.narinfo error="server returned 404: 404 page not found\n"16632026/09/16 19:09:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16642026/09/16 19:09:48 INFO Vacuumed table table=pending_closures16652026/09/16 19:09:48 OK 20251210153512_drop_unused_gin_index.sql (7.46ms)16662026/09/16 19:09:48 INFO Completed upload id=116672026/09/16 19:09:48 INFO Upload complete. (171ms)1668 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-64313-353831061/TestClientCADerivations3852827849/001/store/7z8zjd0qhv4iaj3jwrrf8naq6dfmflqf-ca-test1669 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1670 Compression: zstd1671 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1672 NarSize: 1441673 References: 1674 Deriver: /nix/var/nix/builds/nix-64313-353831061/TestClientCADerivations3852827849/001/store/kq7mrijxr066jwzan2isrwzpqbsj77s6-ca-test.drv1675 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1676 client_ca_test.go:185: Checking for realisation files in S3...1677 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1678 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache16792026/09/16 19:09:48 INFO Vacuumed table table=pending_objects16802026/09/16 19:09:48 OK 20251218171726_add_pins.sql (22.45ms)16812026/09/16 19:09:48 INFO Vacuumed table table=multipart_uploads16822026/09/16 19:09:48 OK 20260628120000_add_object_size_and_stats.sql (36.63ms)16832026/09/16 19:09:48 INFO Vacuumed table table=closures16842026/09/16 19:09:48 INFO Vacuumed table table=objects1685--- PASS: TestClaim_InputsTouched (3.38s)1686=== CONT TestService_RequireScope_OIDC16872026/09/16 19:09:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57186/oidc1688=== NAME TestClientCADerivations1689 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket44?endpoint=http://localhost:57001®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-64313-353831061/TestClientCADerivations3852827849/001/store'1690 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 116912026/09/16 19:09:48 OK 20260905000000_add_claims.sql (50.3ms)16922026/09/16 19:09:48 goose: successfully migrated database to version: 2026090500000016932026/09/16 19:09:48 OK 1_commit_pending_closure.sql (1.52ms)16942026/09/16 19:09:48 OK 2_object_stats_trigger.sql (238.58µs)16952026/09/16 19:09:48 goose: up to current file version: 216962026-09-16 19:09:48.786 UTC [64671] ERROR: relation "goose_db_version" does not exist at character 3616972026-09-16 19:09:48.786 UTC [64671] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1698--- PASS: TestClientCADerivations (2.74s)1699=== CONT TestClaim_GCMarkedOutputCountsAsAbsent17002026/09/16 19:09:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17012026/09/16 19:09:48 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01702=== NAME TestPinProtectsFromGC1703 client_integration_test.go:711: Pin successfully protected closure from garbage collection1704--- PASS: TestPinProtectsFromGC (4.87s)1705=== CONT TestCacheStatsHandler17062026/09/16 19:09:48 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001600000000000000000000.nar.zst upload_id=MjVmOGRmMzAtNTAxMy00MWM4LTlmYjktMDE0N2Y1NDM2OWUxLjg5OWJhMGZlLWRmMWQtNDM5YS1iYTc0LTNhZTExZjJjNzA1MngxNzg5NTg1Nzg3NTg1NjE0MDAw parts=1017072026/09/16 19:09:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17082026/09/16 19:09:48 INFO Signed narinfos id=1 count=117092026/09/16 19:09:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17102026/09/16 19:09:48 INFO Completed upload id=11711--- PASS: TestClaim_TwoInstances (3.35s)1712=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle17132026/09/16 19:09:49 WARN claim: cannot clear write deadline error="feature not supported"17142026/09/16 19:09:49 WARN claim: cannot clear write deadline error="feature not supported"1715--- PASS: TestClaim_FailWithoutKindReleases (1.98s)1716=== CONT TestService_verifyS3Integrity17172026/09/16 19:09:49 OK 20241026095416_initial_model.sql (153.08ms)17182026/09/16 19:09:49 OK 20251210153512_drop_unused_gin_index.sql (5.53ms)17192026/09/16 19:09:49 OK 20251218171726_add_pins.sql (9.14ms)17202026/09/16 19:09:49 OK 20260628120000_add_object_size_and_stats.sql (11.67ms)17212026/09/16 19:09:49 OK 20260905000000_add_claims.sql (22.32ms)17222026/09/16 19:09:49 goose: successfully migrated database to version: 2026090500000017232026/09/16 19:09:49 OK 1_commit_pending_closure.sql (2.2ms)17242026/09/16 19:09:49 OK 2_object_stats_trigger.sql (420.63µs)17252026/09/16 19:09:49 goose: up to current file version: 217262026/09/16 19:09:49 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01727=== NAME TestClientIntegration1728 client_integration_test.go:304: Objects in database after GC:17292026/09/16 19:09:49 WARN claim: cannot clear write deadline error="feature not supported"1730 client_integration_test.go:304: Successfully deleted all objects with GC --force17312026/09/16 19:09:49 WARN claim: cannot clear write deadline error="feature not supported"1732--- PASS: TestClientIntegration (4.49s)1733=== CONT TestCacheConfigHandler1734=== RUN TestCacheConfigHandler/full_config,_no_issuer1735=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1736=== RUN TestCacheConfigHandler/no_cache_url_configured1737=== PAUSE TestCacheConfigHandler/no_cache_url_configured1738=== RUN TestCacheConfigHandler/no_signing_keys1739=== PAUSE TestCacheConfigHandler/no_signing_keys1740=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1741=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1742=== CONT TestService_ReadScope_PublicByDefault17432026/09/16 19:09:49 WARN claim: cannot clear write deadline error="feature not supported"1744--- PASS: TestClaim_FailWakesWaitersButIsNotRemembered (2.07s)1745=== CONT TestService_ReadAuthMiddleware17462026-09-16 19:09:49.356 UTC [64686] ERROR: relation "goose_db_version" does not exist at character 3617472026-09-16 19:09:49.356 UTC [64686] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1748=== NAME TestOrphanedObjectsGCStressTest1749 orphaned_objects_gc_test.go:509: Stress test completed successfully:1750 orphaned_objects_gc_test.go:510: - Active objects preserved: 201751 orphaned_objects_gc_test.go:511: - Objects deleted: 2101752 orphaned_objects_gc_test.go:512: - Total GC'd: 2101753--- PASS: TestOrphanedObjectsGCStressTest (8.04s)1754=== CONT TestService_createPendingClosureHandler17552026/09/16 19:09:49 OK 20241026095416_initial_model.sql (15.02ms)17562026/09/16 19:09:49 OK 20251210153512_drop_unused_gin_index.sql (999.17µs)17572026/09/16 19:09:49 OK 20251218171726_add_pins.sql (1.07ms)17582026/09/16 19:09:49 OK 20260628120000_add_object_size_and_stats.sql (3.43ms)17592026/09/16 19:09:49 OK 20260905000000_add_claims.sql (5.75ms)17602026/09/16 19:09:49 goose: successfully migrated database to version: 2026090500000017612026/09/16 19:09:49 OK 1_commit_pending_closure.sql (1.01ms)17622026/09/16 19:09:49 OK 2_object_stats_trigger.sql (297.13µs)17632026/09/16 19:09:49 goose: up to current file version: 217642026-09-16 19:09:49.418 UTC [64690] ERROR: relation "goose_db_version" does not exist at character 3617652026-09-16 19:09:49.418 UTC [64690] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17662026/09/16 19:09:49 OK 20241026095416_initial_model.sql (51.13ms)17672026/09/16 19:09:49 OK 20251210153512_drop_unused_gin_index.sql (6.4ms)17682026/09/16 19:09:49 OK 20251218171726_add_pins.sql (6.41ms)17692026/09/16 19:09:49 OK 20260628120000_add_object_size_and_stats.sql (26.45ms)17702026/09/16 19:09:49 WARN claim: cannot clear write deadline error="feature not supported"17712026/09/16 19:09:49 OK 20260905000000_add_claims.sql (28.34ms)17722026/09/16 19:09:49 goose: successfully migrated database to version: 2026090500000017732026/09/16 19:09:49 OK 1_commit_pending_closure.sql (1.99ms)17742026/09/16 19:09:49 OK 2_object_stats_trigger.sql (317.38µs)17752026/09/16 19:09:49 goose: up to current file version: 217762026/09/16 19:09:49 WARN claim: cannot clear write deadline error="feature not supported"17772026/09/16 19:09:49 WARN claim: cannot clear write deadline error="feature not supported"1778--- PASS: TestClaim_TooManyStreams (1.41s)1779=== CONT TestService_AuthMiddleware_OIDC17802026/09/16 19:09:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57201/oidc17812026-09-16 19:09:49.773 UTC [64693] ERROR: relation "goose_db_version" does not exist at character 3617822026-09-16 19:09:49.773 UTC [64693] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17832026-09-16 19:09:49.790 UTC [64695] ERROR: relation "goose_db_version" does not exist at character 3617842026-09-16 19:09:49.790 UTC [64695] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17852026-09-16 19:09:49.792 UTC [64696] ERROR: relation "goose_db_version" does not exist at character 3617862026-09-16 19:09:49.792 UTC [64696] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17872026-09-16 19:09:49.793 UTC [64697] ERROR: relation "goose_db_version" does not exist at character 3617882026-09-16 19:09:49.793 UTC [64697] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17892026-09-16 19:09:49.793 UTC [64698] ERROR: relation "goose_db_version" does not exist at character 3617902026-09-16 19:09:49.793 UTC [64698] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17912026/09/16 19:09:49 OK 20241026095416_initial_model.sql (30.48ms)17922026/09/16 19:09:49 OK 20251210153512_drop_unused_gin_index.sql (1.23ms)17932026/09/16 19:09:49 OK 20241026095416_initial_model.sql (10.94ms)17942026/09/16 19:09:49 OK 20251218171726_add_pins.sql (2.42ms)17952026/09/16 19:09:49 OK 20251210153512_drop_unused_gin_index.sql (559.25µs)17962026/09/16 19:09:49 OK 20241026095416_initial_model.sql (10.89ms)17972026/09/16 19:09:49 OK 20251210153512_drop_unused_gin_index.sql (398.63µs)17982026/09/16 19:09:49 OK 20251218171726_add_pins.sql (977.33µs)17992026/09/16 19:09:49 OK 20241026095416_initial_model.sql (11.06ms)18002026/09/16 19:09:49 OK 20251218171726_add_pins.sql (896.92µs)18012026/09/16 19:09:49 OK 20251210153512_drop_unused_gin_index.sql (375.17µs)18022026/09/16 19:09:49 OK 20251218171726_add_pins.sql (3.93ms)18032026/09/16 19:09:49 OK 20260628120000_add_object_size_and_stats.sql (4.64ms)18042026/09/16 19:09:49 OK 20260628120000_add_object_size_and_stats.sql (6.07ms)18052026/09/16 19:09:49 OK 20260628120000_add_object_size_and_stats.sql (4.7ms)18062026/09/16 19:09:49 OK 20241026095416_initial_model.sql (17.89ms)18072026/09/16 19:09:49 OK 20260628120000_add_object_size_and_stats.sql (3.02ms)18082026/09/16 19:09:49 OK 20260905000000_add_claims.sql (2.99ms)18092026/09/16 19:09:49 goose: successfully migrated database to version: 2026090500000018102026/09/16 19:09:49 OK 20260905000000_add_claims.sql (2.77ms)18112026/09/16 19:09:49 goose: successfully migrated database to version: 2026090500000018122026/09/16 19:09:49 OK 20260905000000_add_claims.sql (3.63ms)18132026/09/16 19:09:49 goose: successfully migrated database to version: 2026090500000018142026/09/16 19:09:49 OK 20251210153512_drop_unused_gin_index.sql (819.08µs)18152026/09/16 19:09:49 OK 1_commit_pending_closure.sql (1.86ms)18162026/09/16 19:09:49 OK 1_commit_pending_closure.sql (1.65ms)18172026/09/16 19:09:49 OK 1_commit_pending_closure.sql (2.1ms)18182026/09/16 19:09:49 OK 2_object_stats_trigger.sql (272.75µs)18192026/09/16 19:09:49 goose: up to current file version: 218202026/09/16 19:09:49 OK 20251218171726_add_pins.sql (1.89ms)18212026/09/16 19:09:49 OK 2_object_stats_trigger.sql (443.63µs)18222026/09/16 19:09:49 goose: up to current file version: 218232026/09/16 19:09:49 OK 2_object_stats_trigger.sql (335.83µs)18242026/09/16 19:09:49 goose: up to current file version: 218252026/09/16 19:09:49 OK 20260905000000_add_claims.sql (2.95ms)18262026/09/16 19:09:49 goose: successfully migrated database to version: 2026090500000018272026/09/16 19:09:49 OK 1_commit_pending_closure.sql (897.92µs)18282026/09/16 19:09:49 OK 20260628120000_add_object_size_and_stats.sql (1.33ms)18292026/09/16 19:09:49 OK 2_object_stats_trigger.sql (234.29µs)18302026/09/16 19:09:49 goose: up to current file version: 218312026/09/16 19:09:49 OK 20260905000000_add_claims.sql (19.95ms)18322026/09/16 19:09:49 goose: successfully migrated database to version: 2026090500000018332026/09/16 19:09:49 OK 1_commit_pending_closure.sql (1.28ms)18342026/09/16 19:09:49 OK 2_object_stats_trigger.sql (212.54µs)18352026/09/16 19:09:49 goose: up to current file version: 218362026/09/16 19:09:49 INFO Received uploads request method=POST path=/api/pending_closures18372026/09/16 19:09:50 WARN claim: cannot clear write deadline error="feature not supported"18382026/09/16 19:09:50 INFO Received uploads request method=POST path=/api/pending_closures18392026-09-16 19:09:50.351 UTC [64701] ERROR: relation "goose_db_version" does not exist at character 3618402026-09-16 19:09:50.351 UTC [64701] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1841=== RUN TestService_RequireScope_OIDC/builder_may_write1842=== PAUSE TestService_RequireScope_OIDC/builder_may_write1843=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1844=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1845=== RUN TestService_RequireScope_OIDC/ops_may_admin1846=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1847=== RUN TestService_RequireScope_OIDC/ops_may_not_write1848=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1849=== RUN TestService_RequireScope_OIDC/reader_may_not_write1850=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1851=== RUN TestService_RequireScope_OIDC/static_token_may_admin1852=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1853=== RUN TestService_RequireScope_OIDC/static_token_may_write1854=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1855=== RUN TestService_RequireScope_OIDC/reader_may_read1856=== PAUSE TestService_RequireScope_OIDC/reader_may_read1857=== RUN TestService_RequireScope_OIDC/writer_implies_read1858=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1859=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1860=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1861=== CONT TestService_AuthMiddleware_MTLSBoundSubjects18622026/09/16 19:09:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18632026-09-16 19:09:50.562 UTC [64704] ERROR: relation "goose_db_version" does not exist at character 3618642026-09-16 19:09:50.562 UTC [64704] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18652026-09-16 19:09:50.562 UTC [64705] ERROR: relation "goose_db_version" does not exist at character 3618662026-09-16 19:09:50.562 UTC [64705] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18672026/09/16 19:09:50 OK 20241026095416_initial_model.sql (157.16ms)18682026/09/16 19:09:50 OK 20251210153512_drop_unused_gin_index.sql (6.05ms)18692026/09/16 19:09:50 OK 20251218171726_add_pins.sql (7.82ms)18702026/09/16 19:09:50 OK 20260628120000_add_object_size_and_stats.sql (26.55ms)18712026/09/16 19:09:50 OK 20260905000000_add_claims.sql (44.19ms)18722026/09/16 19:09:50 goose: successfully migrated database to version: 2026090500000018732026/09/16 19:09:50 OK 1_commit_pending_closure.sql (9.07ms)18742026/09/16 19:09:50 OK 2_object_stats_trigger.sql (818.04µs)18752026/09/16 19:09:50 goose: up to current file version: 218762026/09/16 19:09:50 OK 20241026095416_initial_model.sql (119.38ms)18772026/09/16 19:09:50 OK 20241026095416_initial_model.sql (119.51ms)1878--- PASS: TestCacheStatsHandler (1.86s)1879=== CONT TestService_AuthMiddleware_MTLSProxyHeader18802026/09/16 19:09:50 OK 20251210153512_drop_unused_gin_index.sql (12.15ms)18812026/09/16 19:09:50 OK 20251210153512_drop_unused_gin_index.sql (12.46ms)18822026/09/16 19:09:50 OK 20251218171726_add_pins.sql (4.89ms)18832026/09/16 19:09:50 OK 20251218171726_add_pins.sql (4.69ms)18842026/09/16 19:09:50 OK 20260628120000_add_object_size_and_stats.sql (25.19ms)18852026/09/16 19:09:50 OK 20260628120000_add_object_size_and_stats.sql (29.75ms)18862026/09/16 19:09:50 OK 20260905000000_add_claims.sql (41.46ms)18872026/09/16 19:09:50 goose: successfully migrated database to version: 2026090500000018882026/09/16 19:09:50 OK 20260905000000_add_claims.sql (37.27ms)18892026/09/16 19:09:50 goose: successfully migrated database to version: 2026090500000018902026-09-16 19:09:50.812 UTC [64708] ERROR: relation "goose_db_version" does not exist at character 3618912026-09-16 19:09:50.812 UTC [64708] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18922026/09/16 19:09:50 OK 1_commit_pending_closure.sql (30.05ms)18932026/09/16 19:09:50 OK 1_commit_pending_closure.sql (29.33ms)18942026/09/16 19:09:50 OK 2_object_stats_trigger.sql (1.1ms)18952026/09/16 19:09:50 goose: up to current file version: 218962026/09/16 19:09:50 OK 2_object_stats_trigger.sql (1.2ms)18972026/09/16 19:09:50 goose: up to current file version: 218982026/09/16 19:09:50 INFO Received uploads request method=POST path=/api/pending_closures18992026/09/16 19:09:50 OK 20241026095416_initial_model.sql (131.2ms)19002026/09/16 19:09:50 OK 20251210153512_drop_unused_gin_index.sql (10.05ms)19012026/09/16 19:09:51 OK 20251218171726_add_pins.sql (26.14ms)19022026/09/16 19:09:51 OK 20260628120000_add_object_size_and_stats.sql (35.47ms)19032026/09/16 19:09:51 OK 20260905000000_add_claims.sql (37ms)19042026/09/16 19:09:51 goose: successfully migrated database to version: 202609050000001905--- PASS: TestService_ReadScope_PublicByDefault (1.78s)1906=== CONT TestIsValidCachePath/narinfo1907=== CONT TestIsValidCachePath/index.html1908=== CONT TestIsValidCachePath/short_hash1909=== CONT TestIsValidCachePath/wrong_extension1910=== CONT TestIsValidCachePath/leading_slash1911=== CONT TestIsValidCachePath/empty1912=== CONT TestIsValidCachePath/random_path1913=== CONT TestIsValidCachePath/invalid_char_u1914=== CONT TestIsValidCachePath/invalid_char_e1915=== CONT TestIsValidCachePath/traversal_in_middle1916=== CONT TestIsValidCachePath/traversal_parent1917=== CONT TestIsValidCachePath/nar_xz1918=== CONT TestIsValidCachePath/nar_bz21919=== CONT TestIsValidCachePath/realisation1920=== CONT TestIsValidCachePath/nix-cache-info1921=== CONT TestIsValidCachePath/log1922=== CONT TestIsValidCachePath/nar_zst1923=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1924=== CONT TestIsValidCachePath/nar_uncompressed1925=== CONT TestIsValidCachePath/ls1926=== CONT TestParseSingleRange/none1927--- PASS: TestIsValidCachePath (0.00s)1928 --- PASS: TestIsValidCachePath/narinfo (0.00s)1929 --- PASS: TestIsValidCachePath/index.html (0.00s)1930 --- PASS: TestIsValidCachePath/short_hash (0.00s)1931 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1932 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1933 --- PASS: TestIsValidCachePath/empty (0.00s)1934 --- PASS: TestIsValidCachePath/random_path (0.00s)1935 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1936 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1937 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1938 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1939 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1940 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1941 --- PASS: TestIsValidCachePath/realisation (0.00s)1942 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1943 --- PASS: TestIsValidCachePath/log (0.00s)1944 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1945 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1946 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1947 --- PASS: TestIsValidCachePath/ls (0.00s)1948=== CONT TestParseSingleRange/open-ended1949=== CONT TestParseSingleRange/start_far_past_EOF1950=== CONT TestParseSingleRange/start_past_EOF1951=== CONT TestParseSingleRange/single_byte1952=== CONT TestParseSingleRange/suffix_exceeds_size1953=== CONT TestParseSingleRange/suffix1954=== CONT TestParseSingleRange/end_clamped_to_size1955=== CONT TestParseSingleRange/malformed_both_empty1956=== CONT TestParseSingleRange/closed1957=== CONT TestParseSingleRange/malformed_end_before_start1958=== CONT TestParseSingleRange/multi-range_ignored1959=== CONT TestParseSingleRange/malformed_no_dash1960=== CONT TestParseSingleRange/unknown_unit1961--- PASS: TestParseSingleRange (0.00s)1962 --- PASS: TestParseSingleRange/none (0.00s)1963 --- PASS: TestParseSingleRange/open-ended (0.00s)1964 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1965 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1966 --- PASS: TestParseSingleRange/single_byte (0.00s)1967 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1968 --- PASS: TestParseSingleRange/suffix (0.00s)1969 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1970 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1971 --- PASS: TestParseSingleRange/closed (0.00s)1972 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1973 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1974 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1975 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1976=== CONT TestServerTLSConfig/no_client_CA1977=== CONT TestServerTLSConfig/not_a_PEM_file19782026/09/16 19:09:51 OK 1_commit_pending_closure.sql (8.74ms)19792026/09/16 19:09:51 OK 2_object_stats_trigger.sql (652.71µs)19802026/09/16 19:09:51 goose: up to current file version: 21981=== CONT TestServerTLSConfig/missing_CA_file1982=== CONT TestIsValidUploadKey/narinfo1983--- PASS: TestServerTLSConfig (0.00s)1984 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1985 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1986 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1987=== CONT TestIsValidUploadKey/realisation_plus_in_output1988=== CONT TestIsValidUploadKey/unknown_type1989=== CONT TestIsValidUploadKey/empty_key1990=== CONT TestIsValidUploadKey/absolute1991=== CONT TestIsValidUploadKey/traversal_nar1992=== CONT TestIsValidUploadKey/traversal1993=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1994=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1995=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1996=== CONT TestIsValidUploadKey/index.html1997=== CONT TestIsValidUploadKey/nix-cache-info1998=== CONT TestIsValidUploadKey/build_log_home-manager_file1999=== CONT TestIsValidUploadKey/realisation2000=== CONT TestIsValidUploadKey/build_log_equals2001=== CONT TestIsValidUploadKey/build_log_question_mark2002=== CONT TestIsValidUploadKey/build_log_plus_in_name2003=== CONT TestIsValidUploadKey/nar_plain2004=== CONT TestIsValidUploadKey/build_log2005=== CONT TestIsValidUploadKey/listing2006=== CONT TestIsValidUploadKey/nar_xz2007=== CONT TestIsValidUploadKey/nar_zst2008--- PASS: TestIsValidUploadKey (0.00s)2009 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2010 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2011 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2012 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2013 --- PASS: TestIsValidUploadKey/absolute (0.00s)2014 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2015 --- PASS: TestIsValidUploadKey/traversal (0.00s)2016 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2017 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2018 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2019 --- PASS: TestIsValidUploadKey/index.html (0.00s)2020 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2021 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2022 --- PASS: TestIsValidUploadKey/realisation (0.00s)2023 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2024 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2025 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2026 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2027 --- PASS: TestIsValidUploadKey/build_log (0.00s)2028 --- PASS: TestIsValidUploadKey/listing (0.00s)2029 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2030 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2031=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart20322026/09/16 19:09:51 INFO Received complete multipart upload request method=POST path=/20332026/09/16 19:09:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2034=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure20352026/09/16 19:09:51 INFO Received uploads request method=POST path=/20362026/09/16 19:09:51 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MjVmOGRmMzAtNTAxMy00MWM4LTlmYjktMDE0N2Y1NDM2OWUxLjlhM2U3NDRlLTgzNWItNDc4OC1iZjA3LTliZTNhOGQwMzc1OXgxNzg5NTg1Nzg5OTg3MjU0MDAw parts=1020372026/09/16 19:09:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20382026/09/16 19:09:51 INFO Completed upload id=120392026/09/16 19:09:51 INFO Received uploads request method=POST path=/api/pending_closures20402026/09/16 19:09:51 INFO Received uploads request method=POST path=/api/pending_closures20412026/09/16 19:09:51 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo20422026/09/16 19:09:51 WARN Found objects in DB but missing from S3, will re-upload count=12043--- PASS: TestService_verifyS3Integrity (2.14s)2044=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts20452026/09/16 19:09:51 INFO Received request for more parts method=POST path=/2046=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20472026/09/16 19:09:51 INFO Received uploads request method=POST path=/2048=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20492026/09/16 19:09:51 INFO Received complete multipart upload request method=POST path=/2050=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20512026/09/16 19:09:51 INFO Received request for more parts method=POST path=/2052=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20532026/09/16 19:09:51 INFO Received uploads request method=POST path=/2054--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2055 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2056 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2057 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2058 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2059=== CONT TestProxyWriteTimeout/narinfo2060=== CONT TestProxyWriteTimeout/10_GiB_nar2061=== CONT TestProxyWriteTimeout/unknown_size2062=== CONT TestProxyWriteTimeout/1_GiB_nar2063--- PASS: TestProxyWriteTimeout (0.00s)2064 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2065 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2066 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2067 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2068=== CONT TestResolveDBConnectionString/flag_wins2069=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2070=== CONT TestResolveDBConnectionString/nothing_configured2071=== CONT TestResolveDBConnectionString/missing_file_is_an_error2072=== CONT TestResolveDBConnectionString/file_when_flag_empty2073=== CONT TestClientErrorHandling/InvalidStorePath2074--- PASS: TestResolveDBConnectionString (0.01s)2075 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2076 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2077 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2078 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2079 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2080--- PASS: TestService_ReadAuthMiddleware (1.97s)2081=== CONT TestClientErrorHandling/ServerNotAvailable20822026-09-16 19:09:51.435 UTC [64714] ERROR: relation "goose_db_version" does not exist at character 3620832026-09-16 19:09:51.435 UTC [64714] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2084--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)2085 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)2086 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2087 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)2088=== CONT TestClientErrorHandling/InvalidAuthToken20892026/09/16 19:09:51 INFO Received uploads request method=POST path=/api/pending_closures20902026/09/16 19:09:51 INFO Received uploads request method=POST path=/api/pending_closures20912026/09/16 19:09:51 INFO Received uploads request method=POST path=/api/pending_closures20922026/09/16 19:09:51 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20932026/09/16 19:09:51 OK 20241026095416_initial_model.sql (56.78ms)20942026/09/16 19:09:51 OK 20251210153512_drop_unused_gin_index.sql (8.93ms)20952026/09/16 19:09:51 OK 20251218171726_add_pins.sql (26.93ms)20962026/09/16 19:09:51 OK 20260628120000_add_object_size_and_stats.sql (28.91ms)20972026/09/16 19:09:51 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.182125ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20982026/09/16 19:09:51 OK 20260905000000_add_claims.sql (42.33ms)20992026/09/16 19:09:51 goose: successfully migrated database to version: 2026090500000021002026/09/16 19:09:51 OK 1_commit_pending_closure.sql (7.37ms)21012026/09/16 19:09:51 OK 2_object_stats_trigger.sql (339.08µs)21022026/09/16 19:09:51 goose: up to current file version: 22103=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2104=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2105=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2106=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2107=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2108=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2109=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2110=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2111=== CONT TestCacheConfigHandler/full_config,_no_issuer2112=== CONT TestCacheConfigHandler/no_signing_keys2113=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2114=== CONT TestCacheConfigHandler/no_cache_url_configured2115--- PASS: TestCacheConfigHandler (0.00s)2116 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2117 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2118 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2119 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2120=== CONT TestService_RequireScope_OIDC/builder_may_write21212026/09/16 19:09:51 INFO OIDC auth successful provider=test scopes=[write]2122=== CONT TestService_RequireScope_OIDC/static_token_may_admin2123=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2124=== CONT TestService_RequireScope_OIDC/writer_implies_read21252026/09/16 19:09:51 INFO OIDC auth successful provider=test scopes=[write]2126=== CONT TestService_RequireScope_OIDC/reader_may_read21272026/09/16 19:09:51 INFO OIDC auth successful provider=test scopes=[read]2128=== CONT TestService_RequireScope_OIDC/static_token_may_write2129=== CONT TestService_RequireScope_OIDC/ops_may_not_write21302026/09/16 19:09:51 INFO OIDC auth successful provider=test scopes=[admin]2131=== CONT TestService_RequireScope_OIDC/reader_may_not_write21322026/09/16 19:09:51 INFO OIDC auth successful provider=test scopes=[read]2133=== CONT TestService_RequireScope_OIDC/ops_may_admin21342026/09/16 19:09:51 INFO OIDC auth successful provider=test scopes=[admin]2135=== CONT TestService_RequireScope_OIDC/builder_may_not_admin21362026/09/16 19:09:51 INFO OIDC auth successful provider=test scopes=[write]2137=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token21382026/09/16 19:09:51 INFO OIDC auth successful provider=test scopes=[write]2139=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21402026/09/16 19:09:51 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]2141=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21422026/09/16 19:09:51 WARN Authentication failed token_preview=eyJhbGciOi...TRSDP3Uf0w token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2143=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2144--- PASS: TestService_AuthMiddleware_OIDC (1.96s)2145 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2146 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2147 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2148 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2149--- PASS: TestService_RequireScope_OIDC (1.80s)2150 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2151 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2152 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2153 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2154 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2155 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2156 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2157 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2158 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2159 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)21602026/09/16 19:09:51 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=385.781249ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21612026/09/16 19:09:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21622026/09/16 19:09:51 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001100000000000000000000.nar.zst upload_id=MjVmOGRmMzAtNTAxMy00MWM4LTlmYjktMDE0N2Y1NDM2OWUxLjA0ZTJkYjNlLTViNjYtNGY1YS1hOTI3LWU0ZmY3NGUyODZiYngxNzg5NTg1NzkwOTA5NzY4MDAw parts=1021632026/09/16 19:09:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21642026/09/16 19:09:51 INFO Completed upload id=121652026/09/16 19:09:51 WARN claim: cannot clear write deadline error="feature not supported"21662026/09/16 19:09:51 WARN claim: cannot clear write deadline error="feature not supported"21672026/09/16 19:09:51 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"21682026/09/16 19:09:51 WARN mTLS auth: bound subjects configured but subject DN unavailable21692026/09/16 19:09:51 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2170--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.50s)2171--- PASS: TestClaim_GCMarkedOutputCountsAsAbsent (3.17s)21722026-09-16 19:09:51.986 UTC [64721] ERROR: relation "goose_db_version" does not exist at character 3621732026-09-16 19:09:51.986 UTC [64721] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21742026/09/16 19:09:52 OK 20241026095416_initial_model.sql (16.05ms)21752026/09/16 19:09:52 OK 20251210153512_drop_unused_gin_index.sql (1.1ms)21762026/09/16 19:09:52 OK 20251218171726_add_pins.sql (6.26ms)21772026-09-16 19:09:52.037 UTC [64722] ERROR: relation "goose_db_version" does not exist at character 3621782026-09-16 19:09:52.037 UTC [64722] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21792026/09/16 19:09:52 OK 20260628120000_add_object_size_and_stats.sql (12.38ms)21802026/09/16 19:09:52 OK 20260905000000_add_claims.sql (20.28ms)21812026/09/16 19:09:52 goose: successfully migrated database to version: 2026090500000021822026/09/16 19:09:52 OK 1_commit_pending_closure.sql (1.98ms)21832026/09/16 19:09:52 OK 2_object_stats_trigger.sql (400.79µs)21842026/09/16 19:09:52 goose: up to current file version: 22185--- PASS: TestClaim_HolderDisconnectKeepsClaim (3.97s)21862026/09/16 19:09:52 OK 20241026095416_initial_model.sql (80.28ms)21872026/09/16 19:09:52 OK 20251210153512_drop_unused_gin_index.sql (10.87ms)21882026/09/16 19:09:52 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=821.261969ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21892026/09/16 19:09:52 OK 20251218171726_add_pins.sql (35.52ms)21902026/09/16 19:09:52 OK 20260628120000_add_object_size_and_stats.sql (22.9ms)21912026/09/16 19:09:52 OK 20260905000000_add_claims.sql (55.16ms)21922026/09/16 19:09:52 goose: successfully migrated database to version: 202609050000002193--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.56s)21942026/09/16 19:09:52 OK 1_commit_pending_closure.sql (3.86ms)21952026/09/16 19:09:52 OK 2_object_stats_trigger.sql (916.79µs)21962026/09/16 19:09:52 goose: up to current file version: 221972026-09-16 19:09:52.326 UTC [64723] ERROR: relation "goose_db_version" does not exist at character 3621982026-09-16 19:09:52.326 UTC [64723] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21992026/09/16 19:09:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22002026/09/16 19:09:52 OK 20241026095416_initial_model.sql (86.6ms)22012026/09/16 19:09:52 OK 20251210153512_drop_unused_gin_index.sql (11.22ms)22022026/09/16 19:09:52 OK 20251218171726_add_pins.sql (8.96ms)22032026/09/16 19:09:52 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MjVmOGRmMzAtNTAxMy00MWM4LTlmYjktMDE0N2Y1NDM2OWUxLjNkODMxZmU4LThlNTQtNGMyZS1hMzA2LWU2MmNhMjlmZTY4YXgxNzg5NTg1NzkxNDk1MzU4MDAw parts=1022042026/09/16 19:09:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22052026/09/16 19:09:52 INFO Completed upload id=122062026/09/16 19:09:52 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000022072026/09/16 19:09:52 OK 20260628120000_add_object_size_and_stats.sql (5.74ms)22082026/09/16 19:09:52 INFO Received uploads request method=POST path=/api/pending_closures22092026/09/16 19:09:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures22102026/09/16 19:09:52 OK 20260905000000_add_claims.sql (3.99ms)22112026/09/16 19:09:52 goose: successfully migrated database to version: 2026090500000022122026/09/16 19:09:52 OK 1_commit_pending_closure.sql (2.21ms)22132026/09/16 19:09:52 OK 2_object_stats_trigger.sql (626.83µs)22142026/09/16 19:09:52 goose: up to current file version: 222152026/09/16 19:09:52 INFO Aborted multipart uploads count=022162026/09/16 19:09:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=0 objects-failed-to-delete=022172026/09/16 19:09:52 INFO Vacuumed table table=pending_closures22182026/09/16 19:09:52 INFO Vacuumed table table=pending_objects22192026/09/16 19:09:52 INFO Vacuumed table table=multipart_uploads22202026/09/16 19:09:52 INFO Vacuumed table table=closures22212026/09/16 19:09:52 INFO Vacuumed table table=objects22222026/09/16 19:09:52 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000002223--- PASS: TestService_createPendingClosureHandler (3.12s)22242026/09/16 19:09:52 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22252026/09/16 19:09:52 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22262026/09/16 19:09:52 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.711788538s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22272026/09/16 19:09:54 WARN Rate limiter enabled after throttle name=s3-test rate=522282026/09/16 19:09:54 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2229=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2230 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102231 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002232--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.75s)22332026/09/16 19:09:54 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"22342026/09/16 19:09:54 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_closures22352026/09/16 19:09:54 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=208.626992ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22362026/09/16 19:09:55 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=394.4924ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22372026/09/16 19:09:55 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=860.816686ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22382026/09/16 19:09:56 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.511732201s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2239--- PASS: TestClientErrorHandling (0.00s)2240 --- PASS: TestClientErrorHandling/InvalidStorePath (1.34s)2241 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.27s)2242 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.58s)2243PASS2244{"timestamp":"2026-09-16T19:09:57.876591Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57223","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1880,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}22452026-09-16 19:09:57.979 UTC [64351] LOG: received smart shutdown request22462026-09-16 19:09:57.980 UTC [64351] LOG: background worker "logical replication launcher" (PID 64361) exited with exit code 122472026-09-16 19:09:57.997 UTC [64356] LOG: shutting down22482026-09-16 19:09:57.997 UTC [64356] LOG: checkpoint starting: shutdown immediate22492026-09-16 19:09:59.017 UTC [64356] LOG: checkpoint complete: wrote 13385 buffers (81.7%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 18 recycled; write=0.655 s, sync=0.351 s, total=1.020 s; sync files=21000, longest=0.001 s, average=0.001 s; distance=287764 kB, estimate=287764 kB; lsn=0/13092168, redo lsn=0/1309216822502026-09-16 19:09:59.022 UTC [64351] LOG: database system is shut down2251Running OIDC tests...2252=== RUN TestGlobMatch2253=== PAUSE TestGlobMatch2254=== RUN TestAudienceForIssuer2255=== PAUSE TestAudienceForIssuer2256=== RUN TestValidateToken_ValidToken2257=== PAUSE TestValidateToken_ValidToken2258=== RUN TestValidateToken_WrongAudience2259=== PAUSE TestValidateToken_WrongAudience2260=== RUN TestValidateToken_Expired2261=== PAUSE TestValidateToken_Expired2262=== RUN TestValidateToken_BoundClaimsMismatch2263=== PAUSE TestValidateToken_BoundClaimsMismatch2264=== RUN TestValidateToken_BoundSubjectMismatch2265=== PAUSE TestValidateToken_BoundSubjectMismatch2266=== RUN TestValidateToken_MultipleProviders2267=== PAUSE TestValidateToken_MultipleProviders2268=== RUN TestValidateToken_NoMatchingProvider2269=== PAUSE TestValidateToken_NoMatchingProvider2270=== RUN TestValidateToken_KubernetesServiceAccount2271=== PAUSE TestValidateToken_KubernetesServiceAccount2272=== RUN TestNewValidator_KubernetesRequiresCA2273=== PAUSE TestNewValidator_KubernetesRequiresCA2274=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2275=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2276=== RUN TestScopes_LegacyProviderDefaultsToWrite2277=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2278=== RUN TestScopes_Rules2279=== PAUSE TestScopes_Rules2280=== RUN TestScopes_ConfigValidation2281=== PAUSE TestScopes_ConfigValidation2282=== CONT TestGlobMatch2283=== CONT TestNewValidator_KubernetesRequiresCA2284=== RUN TestGlobMatch/foo_foo2285=== PAUSE TestGlobMatch/foo_foo2286=== RUN TestGlobMatch/foo_bar2287=== PAUSE TestGlobMatch/foo_bar2288=== RUN TestGlobMatch/*_2289=== PAUSE TestGlobMatch/*_2290=== CONT TestScopes_Rules2291=== RUN TestGlobMatch/*_anything2292=== PAUSE TestGlobMatch/*_anything2293=== RUN TestGlobMatch/foo*_foo2294=== CONT TestValidateToken_Expired2295=== CONT TestValidateToken_WrongAudience2296=== CONT TestValidateToken_ValidToken2297=== CONT TestAudienceForIssuer2298--- PASS: TestAudienceForIssuer (0.00s)2299=== CONT TestScopes_ConfigValidation2300=== CONT TestScopes_LegacyProviderDefaultsToWrite2301=== CONT TestValidateToken_NoMatchingProvider2302=== CONT TestValidateToken_KubernetesServiceAccount2303=== PAUSE TestGlobMatch/foo*_foo2304=== RUN TestGlobMatch/foo*_foobar2305=== PAUSE TestGlobMatch/foo*_foobar2306=== RUN TestGlobMatch/foo*_bar2307=== PAUSE TestGlobMatch/foo*_bar2308=== RUN TestGlobMatch/*bar_bar2309=== PAUSE TestGlobMatch/*bar_bar2310=== RUN TestGlobMatch/*bar_foobar2311=== PAUSE TestGlobMatch/*bar_foobar2312=== RUN TestGlobMatch/*bar_foo2313=== PAUSE TestGlobMatch/*bar_foo2314=== RUN TestGlobMatch/foo*bar_foobar2315=== PAUSE TestGlobMatch/foo*bar_foobar2316=== RUN TestGlobMatch/foo*bar_foo123bar2317=== PAUSE TestGlobMatch/foo*bar_foo123bar2318=== RUN TestGlobMatch/foo*bar_foobarbaz2319=== PAUSE TestGlobMatch/foo*bar_foobarbaz2320=== RUN TestGlobMatch/*/*_foo/bar2321=== PAUSE TestGlobMatch/*/*_foo/bar2322=== RUN TestGlobMatch/*/*_foo2323=== PAUSE TestGlobMatch/*/*_foo2324=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2325=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2326=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02327=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02328=== RUN TestGlobMatch/refs/*/main_refs/heads/main2329=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2330=== RUN TestGlobMatch/fo?_foo2331=== PAUSE TestGlobMatch/fo?_foo2332=== RUN TestGlobMatch/fo?_fo2333=== PAUSE TestGlobMatch/fo?_fo2334=== RUN TestGlobMatch/fo?_fooo2335=== PAUSE TestGlobMatch/fo?_fooo2336=== RUN TestGlobMatch/?oo_foo2337=== PAUSE TestGlobMatch/?oo_foo2338=== RUN TestGlobMatch/?oo_boo2339=== PAUSE TestGlobMatch/?oo_boo2340=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2341=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2342=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2343=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2344=== CONT TestValidateToken_KubernetesIssuerFromOwnToken23452026/09/16 19:09:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57271/oidc2346--- PASS: TestScopes_ConfigValidation (0.00s)2347=== CONT TestValidateToken_MultipleProviders23482026/09/16 19:09:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57272/oidc23492026/09/16 19:09:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57269/oidc23502026/09/16 19:09:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57267/oidc23512026/09/16 19:09:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57268/oidc23522026/09/16 19:09:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57266/oidc23532026/09/16 19:09:59 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232354--- PASS: TestValidateToken_Expired (0.01s)2355=== CONT TestValidateToken_BoundSubjectMismatch23562026/09/16 19:09:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57283/oidc23572026/09/16 19:09:59 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:572732358--- PASS: TestValidateToken_WrongAudience (0.01s)2359=== CONT TestValidateToken_BoundClaimsMismatch2360--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2361=== CONT TestGlobMatch/foo_foo2362=== CONT TestGlobMatch/*/*_foo/bar2363=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2364=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2365=== CONT TestGlobMatch/?oo_boo2366=== CONT TestGlobMatch/?oo_foo2367=== CONT TestGlobMatch/fo?_fooo2368=== CONT TestGlobMatch/fo?_fo2369=== CONT TestGlobMatch/fo?_foo2370=== CONT TestGlobMatch/refs/*/main_refs/heads/main2371=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02372=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2373=== CONT TestGlobMatch/*/*_foo2374=== CONT TestGlobMatch/*bar_bar2375=== CONT TestGlobMatch/foo*bar_foobarbaz2376=== CONT TestGlobMatch/foo*bar_foo123bar2377=== CONT TestGlobMatch/foo*bar_foobar2378=== CONT TestGlobMatch/*bar_foo2379=== CONT TestGlobMatch/*bar_foobar2380=== CONT TestGlobMatch/foo*_foo2381=== CONT TestGlobMatch/foo*_bar2382=== CONT TestGlobMatch/foo*_foobar2383=== CONT TestGlobMatch/*_2384=== CONT TestGlobMatch/*_anything2385=== CONT TestGlobMatch/foo_bar2386--- PASS: TestGlobMatch (0.00s)2387 --- PASS: TestGlobMatch/foo_foo (0.00s)2388 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2389 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2390 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2391 --- PASS: TestGlobMatch/?oo_boo (0.00s)2392 --- PASS: TestGlobMatch/?oo_foo (0.00s)2393 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2394 --- PASS: TestGlobMatch/fo?_fo (0.00s)2395 --- PASS: TestGlobMatch/fo?_foo (0.00s)2396 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2397 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2398 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2399 --- PASS: TestGlobMatch/*/*_foo (0.00s)2400 --- PASS: TestGlobMatch/*bar_bar (0.00s)2401 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2402 --- PASS: TestGlobMatch/foo*bar_foo2026/09/16 19:09:59 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:57284/oidc2403123bar (0.00s)2404 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2405 --- PASS: TestGlobMatch/*bar_foo (0.00s)2406 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2407 --- PASS: TestGlobMatch/foo*_foo (0.00s)2408 --- PASS: TestGlobMatch/foo*_bar (0.00s)2409 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2410 --- PASS: TestGlobMatch/*_ (0.00s)2411 --- PASS: TestGlobMatch/*_anything (0.00s)2412 --- PASS: TestGlobMatch/foo_bar (0.00s)2413--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)24142026/09/16 19:09:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57287/oidc24152026/09/16 19:09:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57288/oidc2416--- PASS: TestValidateToken_ValidToken (0.01s)2417--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2418--- PASS: TestValidateToken_BoundClaimsMismatch (0.00s)24192026/09/16 19:09:59 http: TLS handshake error from 127.0.0.1:57275: remote error: tls: bad certificate2420--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2421--- PASS: TestValidateToken_MultipleProviders (0.01s)2422--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)2423--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.02s)2424--- PASS: TestScopes_Rules (0.02s)2425PASS2426Running hook tests...2427=== RUN TestSendPathsEmpty2428=== PAUSE TestSendPathsEmpty2429=== RUN TestQueueEnqueueAndFetch2430=== PAUSE TestQueueEnqueueAndFetch2431=== RUN TestQueueDeduplication2432=== PAUSE TestQueueDeduplication2433=== RUN TestQueueRemove2434=== PAUSE TestQueueRemove2435=== RUN TestQueueFetchBatchLimit2436=== PAUSE TestQueueFetchBatchLimit2437=== RUN TestQueueRetryMovesToBack2438=== PAUSE TestQueueRetryMovesToBack2439=== RUN TestQueueFetchRemoveLifecycle2440=== PAUSE TestQueueFetchRemoveLifecycle2441=== RUN TestQueueConcurrentWriters2442=== PAUSE TestQueueConcurrentWriters2443=== RUN TestQueueRemoveLargeClosure2444=== PAUSE TestQueueRemoveLargeClosure2445=== RUN TestServerClientIntegration2446=== PAUSE TestServerClientIntegration2447=== RUN TestServerQueueError2448=== PAUSE TestServerQueueError2449=== RUN TestGetListenerSocketActivation2450 server_test.go:210: === RUN TestGetListenerSocketActivation2451 --- PASS: TestGetListenerSocketActivation (0.00s)2452 PASS2453 2454--- PASS: TestGetListenerSocketActivation (0.01s)2455=== RUN TestDrainIsolatesPoisonPath2456=== PAUSE TestDrainIsolatesPoisonPath2457=== RUN TestRunNotBlockedByPoisonHead2458=== PAUSE TestRunNotBlockedByPoisonHead2459=== RUN TestDrainGivesUpWhenServerDown2460=== PAUSE TestDrainGivesUpWhenServerDown2461=== RUN TestFailedPathPrunedByLaterClosure2462=== PAUSE TestFailedPathPrunedByLaterClosure2463=== RUN TestWorkerUploadsAndRemoves2464=== PAUSE TestWorkerUploadsAndRemoves2465=== RUN TestWorkerSkipsGCdPaths2466=== PAUSE TestWorkerSkipsGCdPaths2467=== RUN TestWorkerPrunesClosureDeps2468=== PAUSE TestWorkerPrunesClosureDeps2469=== RUN TestDrainTimeout2470=== PAUSE TestDrainTimeout2471=== CONT TestSendPathsEmpty2472=== CONT TestServerQueueError2473=== CONT TestQueueRetryMovesToBack2474=== CONT TestQueueEnqueueAndFetch2475=== CONT TestWorkerUploadsAndRemoves2476=== CONT TestQueueDeduplication2477=== CONT TestServerClientIntegration2478--- PASS: TestSendPathsEmpty (0.00s)2479=== CONT TestQueueFetchBatchLimit2480=== CONT TestQueueRemove2481=== CONT TestWorkerPrunesClosureDeps2482=== CONT TestDrainTimeout24832026/09/16 19:10:00 ERROR Failed to queue paths error="permission denied" count=12484--- PASS: TestServerQueueError (0.00s)2485=== CONT TestWorkerSkipsGCdPaths2486--- PASS: TestServerClientIntegration (0.00s)2487=== CONT TestDrainGivesUpWhenServerDown24882026/09/16 19:10:00 INFO Upload queue status pending=224892026/09/16 19:10:00 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-64313-353831061/TestWorkerSkipsGCdPaths1936510130/002/nonexistent24902026/09/16 19:10:00 INFO Uploading batch count=224912026/09/16 19:10:00 INFO Upload queue status pending=224922026/09/16 19:10:00 INFO Uploading batch count=12493--- PASS: TestQueueEnqueueAndFetch (0.01s)2494=== CONT TestFailedPathPrunedByLaterClosure2495--- PASS: TestQueueRetryMovesToBack (0.01s)2496=== CONT TestRunNotBlockedByPoisonHead24972026/09/16 19:10:00 INFO Uploading batch count=124982026/09/16 19:10:00 INFO Uploading batch count=224992026/09/16 19:10:00 ERROR Upload failed error="upload failed" count=225002026/09/16 19:10:00 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-64313-353831061/TestDrainGivesUpWhenServerDown2805386839/002/a25012026/09/16 19:10:00 INFO Upload queue status pending=22502--- PASS: TestQueueDeduplication (0.01s)2503=== CONT TestDrainIsolatesPoisonPath25042026/09/16 19:10:00 INFO Uploading batch count=22505--- PASS: TestQueueFetchBatchLimit (0.01s)2506=== CONT TestQueueFetchRemoveLifecycle25072026/09/16 19:10:00 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-64313-353831061/TestDrainGivesUpWhenServerDown2805386839/002/b2508--- PASS: TestQueueRemove (0.01s)2509=== CONT TestQueueConcurrentWriters25102026/09/16 19:10:00 INFO Uploading batch count=225112026/09/16 19:10:00 ERROR Upload failed error="upload failed" count=225122026/09/16 19:10:00 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-64313-353831061/TestDrainGivesUpWhenServerDown2805386839/002/c25132026/09/16 19:10:00 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-64313-353831061/TestDrainGivesUpWhenServerDown2805386839/002/d25142026/09/16 19:10:00 INFO Uploading batch count=225152026/09/16 19:10:00 ERROR Upload failed error="upload failed" count=225162026/09/16 19:10:00 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-64313-353831061/TestDrainGivesUpWhenServerDown2805386839/002/e25172026/09/16 19:10:00 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-64313-353831061/TestDrainGivesUpWhenServerDown2805386839/002/f25182026/09/16 19:10:00 INFO Upload queue status pending=325192026/09/16 19:10:00 INFO Uploading batch count=125202026/09/16 19:10:00 ERROR Upload failed error="upload failed" count=125212026/09/16 19:10:00 ERROR Drain finished with paths left in queue remaining=1025222026/09/16 19:10:00 INFO Uploading batch count=125232026/09/16 19:10:00 ERROR Upload failed error="upload failed" count=125242026/09/16 19:10:00 INFO Uploading batch count=125252026/09/16 19:10:00 INFO Uploading batch count=425262026/09/16 19:10:00 ERROR Upload failed error="upload failed" count=425272026/09/16 19:10:00 INFO Uploading batch count=125282026/09/16 19:10:00 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-64313-353831061/TestDrainIsolatesPoisonPath3363111381/002/bbb25292026/09/16 19:10:00 INFO Uploading batch count=125302026/09/16 19:10:00 ERROR Upload failed error="upload failed" count=12531--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2532=== CONT TestQueueRemoveLargeClosure25332026/09/16 19:10:00 INFO Uploading batch count=125342026/09/16 19:10:00 ERROR Upload failed error="upload failed" count=12535--- PASS: TestQueueFetchRemoveLifecycle (0.00s)25362026/09/16 19:10:00 INFO Uploading batch count=125372026/09/16 19:10:00 ERROR Upload failed error="upload failed" count=125382026/09/16 19:10:00 ERROR Drain finished with paths left in queue remaining=12539--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2540--- PASS: TestDrainIsolatesPoisonPath (0.01s)2541--- PASS: TestWorkerSkipsGCdPaths (0.03s)2542--- PASS: TestWorkerPrunesClosureDeps (0.03s)2543--- PASS: TestWorkerUploadsAndRemoves (0.03s)2544--- PASS: TestQueueRemoveLargeClosure (0.04s)2545--- PASS: TestQueueConcurrentWriters (0.14s)25462026/09/16 19:10:00 ERROR Upload failed error="context deadline exceeded" count=225472026/09/16 19:10:00 ERROR Drain finished with paths left in queue remaining=42548--- PASS: TestDrainTimeout (0.21s)25492026/09/16 19:10:01 INFO Uploading batch count=125502026/09/16 19:10:01 INFO Uploading batch count=125512026/09/16 19:10:01 INFO Uploading batch count=125522026/09/16 19:10:01 ERROR Upload failed error="upload failed" count=125532026/09/16 19:10:01 INFO Uploading batch count=125542026/09/16 19:10:01 ERROR Upload failed error="upload failed" count=125552026/09/16 19:10:01 INFO Uploading batch count=125562026/09/16 19:10:01 ERROR Upload failed error="upload failed" count=125572026/09/16 19:10:01 INFO Uploading batch count=125582026/09/16 19:10:01 ERROR Upload failed error="upload failed" count=125592026/09/16 19:10:01 ERROR Drain finished with paths left in queue remaining=12560--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2561PASS