niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #256
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestCaseHackSuffix7=== PAUSE TestCaseHackSuffix8=== RUN TestFilterOversizedClosures9=== PAUSE TestFilterOversizedClosures10=== RUN TestUploadMultipart_PartsInParallel11=== PAUSE TestUploadMultipart_PartsInParallel12=== RUN TestPartSizeForNAR13=== PAUSE TestPartSizeForNAR14=== RUN TestUploadMultipart_SupersededByPeer15=== PAUSE TestUploadMultipart_SupersededByPeer16=== RUN TestDumpPathCaseHackMatchesNix17--- PASS: TestDumpPathCaseHackMatchesNix (0.17s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestStreamPushReportsEveryPath96=== CONT TestConvertHashToNix3297=== RUN TestConvertHashToNix32/SRI_format_to_Nix3298=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix3299=== CONT TestShellSplitErrors100--- PASS: TestShellSplitErrors (0.00s)101=== CONT TestParsePathInfoJSONMultiplePaths102=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths103=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths104=== CONT TestShellSplit105=== CONT TestDoWithRetry_BodyReplayedViaGetBody106=== CONT TestResolveStorePath107--- PASS: TestShellSplit (0.00s)108=== CONT TestParsePathInfoJSON109=== RUN TestParsePathInfoJSON/Nix_format110=== PAUSE TestParsePathInfoJSON/Nix_format111=== RUN TestParsePathInfoJSON/Lix_format112=== PAUSE TestParsePathInfoJSON/Lix_format113=== RUN TestParsePathInfoJSON/empty_input114=== PAUSE TestParsePathInfoJSON/empty_input115=== RUN TestParsePathInfoJSON/whitespace_only116=== PAUSE TestParsePathInfoJSON/whitespace_only117=== RUN TestParsePathInfoJSON/invalid_JSON118=== PAUSE TestParsePathInfoJSON/invalid_JSON119=== CONT TestPathInfoHashCompatibility120=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)121=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)122=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon123=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon124=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI125=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI126=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512127=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512128=== CONT TestGetStorePathHash129=== RUN TestGetStorePathHash/valid_store_path130=== PAUSE TestGetStorePathHash/valid_store_path131=== RUN TestGetStorePathHash/basename_without_hyphen_should_error132=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error133=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error134=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error135=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error136=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error137=== CONT TestStaticToken138=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess139--- PASS: TestStaticToken (0.00s)140=== CONT TestScriptTokenEmptyCommand141--- PASS: TestScriptTokenEmptyCommand (0.00s)142=== CONT TestScriptTokenScriptFails143=== CONT TestRateLimiterFeedback1442026/09/23 09:37:23 WARN Rate limiter enabled after throttle name=server-test rate=5145=== CONT TestPathInfoCACompatibility146=== RUN TestRateLimiterFeedback/429_enables_limiter147=== PAUSE TestRateLimiterFeedback/429_enables_limiter148=== RUN TestPathInfoCACompatibility/null_ca_field149=== RUN TestConvertHashToNix32/already_Nix32_format150=== RUN TestRateLimiterFeedback/503_enables_limiter151=== PAUSE TestPathInfoCACompatibility/null_ca_field152--- PASS: TestStreamPushReportsEveryPath (0.00s)153=== CONT TestScriptTokenBadJSON154=== RUN TestPathInfoCACompatibility/old_string_format_-_text155=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text156=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive157=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive158=== RUN TestPathInfoCACompatibility/new_structured_format_-_text159=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text160=== PAUSE TestRateLimiterFeedback/503_enables_limiter161=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths162=== PAUSE TestConvertHashToNix32/already_Nix32_format163=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths164=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method165=== RUN TestConvertHashToNix32/invalid_format166=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method167=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter168=== PAUSE TestConvertHashToNix32/invalid_format169=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter170=== CONT TestScriptTokenCachesUntilRefresh171=== CONT TestScriptTokenEmptyToken172=== CONT TestScriptTokenNoExpiryRerunsEveryCall173=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter174=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter175=== CONT TestFileTokenEmpty1762026/09/23 09:37:23 WARN Rate limiter enabled after throttle name=server-test rate=51772026/09/23 09:37:23 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:543271782026/09/23 09:37:23 WARN Rate limiter backed off name=server-test rate=51792026/09/23 09:37:23 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:54327180--- PASS: TestResolveStorePath (0.00s)181=== CONT TestFileTokenMissing182--- PASS: TestDoServerRequestAttachesToken (0.00s)183=== CONT TestFileTokenReadsAndCaches184--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)185=== CONT TestStreamPushReportsSignatures186--- PASS: TestFileTokenMissing (0.00s)187=== CONT TestSetClientTLSErrors188--- PASS: TestFileTokenEmpty (0.00s)189=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1902026/09/23 09:37:23 ERROR Upload failed error=boom count=1191--- PASS: TestStreamPushReportsSignatures (0.00s)192=== CONT TestSetClientTLS193--- PASS: TestScriptTokenScriptFails (0.01s)194=== CONT TestClientSignaturesByStorePath195--- PASS: TestClientSignaturesByStorePath (0.00s)196=== CONT TestStreamPushGivesUpOnDeadServer1972026/09/23 09:37:23 ERROR Upload failed error="connection refused" count=201982026/09/23 09:37:23 ERROR Server seems unavailable, giving up on batch untried=17199--- PASS: TestFileTokenReadsAndCaches (0.01s)200--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)201=== CONT TestStreamPushRequestLine202=== CONT TestStreamPushIsolatesFailures2032026/09/23 09:37:23 ERROR Upload failed error="bad path" count=3204--- PASS: TestStreamPushIsolatesFailures (0.00s)205=== CONT TestUploadMultipart_SupersededByPeer206=== RUN TestUploadMultipart_SupersededByPeer/exists207=== PAUSE TestUploadMultipart_SupersededByPeer/exists208=== RUN TestUploadMultipart_SupersededByPeer/missing209=== PAUSE TestUploadMultipart_SupersededByPeer/missing210=== CONT TestDumpPathWriterError2112026/09/23 09:37:23 ERROR Upload failed error=boom count=1212=== RUN TestSetClientTLSErrors/missing_cert_file213=== PAUSE TestSetClientTLSErrors/missing_cert_file214=== RUN TestSetClientTLSErrors/missing_key_file215=== PAUSE TestSetClientTLSErrors/missing_key_file216=== RUN TestSetClientTLSErrors/missing_ca_file217=== PAUSE TestSetClientTLSErrors/missing_ca_file218=== RUN TestSetClientTLSErrors/invalid_ca_file219=== PAUSE TestSetClientTLSErrors/invalid_ca_file220=== CONT TestEncodeNixBase32WithRealHash221--- PASS: TestEncodeNixBase32WithRealHash (0.00s)222=== CONT TestDumpPathSingleFile223=== RUN TestSetClientTLS/rejects_connection_without_client_cert224--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)225=== CONT TestEncodeNixBase32226=== RUN TestEncodeNixBase32/test_string_hash227=== PAUSE TestEncodeNixBase32/test_string_hash228=== RUN TestEncodeNixBase32/empty_input229=== PAUSE TestEncodeNixBase32/empty_input230=== CONT TestDumpPathMatchesNix231=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert232=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA233=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA234=== RUN TestSetClientTLS/preserves_debug_logging_transport235=== PAUSE TestSetClientTLS/preserves_debug_logging_transport236=== CONT TestStreamPushBatchesUnderLoad237--- PASS: TestScriptTokenBadJSON (0.01s)238=== CONT TestFilterOversizedClosures239=== RUN TestFilterOversizedClosures/no_limit_keeps_everything240=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything241=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped242=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped243=== RUN TestFilterOversizedClosures/all_closures_skipped244=== PAUSE TestFilterOversizedClosures/all_closures_skipped245=== CONT TestCaseHackSuffix246--- PASS: TestScriptTokenEmptyToken (0.01s)247=== CONT TestPartSizeForNAR248=== RUN TestPartSizeForNAR/zero_stays_at_minimum249=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum250=== RUN TestPartSizeForNAR/small_stays_at_minimum251=== PAUSE TestPartSizeForNAR/small_stays_at_minimum252=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum253=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum254=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts255=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts256=== RUN TestPartSizeForNAR/1_TiB257=== PAUSE TestPartSizeForNAR/1_TiB258=== RUN TestPartSizeForNAR/5_TiB_S3_max_object259=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object260=== RUN TestPartSizeForNAR/capped_at_5_GiB261=== PAUSE TestPartSizeForNAR/capped_at_5_GiB262=== CONT TestUploadMultipart_PartsInParallel263--- PASS: TestStreamPushRequestLine (0.02s)264=== CONT TestRegisterUploadedObjectReusesConnections265--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)266=== CONT TestParsePathInfoJSON/Nix_format267=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)268=== CONT TestParsePathInfoJSON/invalid_JSON269=== CONT TestParsePathInfoJSON/whitespace_only270=== CONT TestParsePathInfoJSON/empty_input271=== CONT TestParsePathInfoJSON/Lix_format272--- PASS: TestParsePathInfoJSON (0.00s)273 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)274 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)275 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)276 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)277 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)278=== CONT TestGetStorePathHash/valid_store_path279=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512280=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI281=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon282--- PASS: TestPathInfoHashCompatibility (0.00s)283 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)284 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)285 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)286 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)287=== CONT TestGetStorePathHash/basename_without_hyphen_should_error288=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error289=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error290--- PASS: TestGetStorePathHash (0.00s)291 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)292 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)293 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)294 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)295=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths296=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths297--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)298 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)299 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)300=== CONT TestPathInfoCACompatibility/null_ca_field301=== CONT TestConvertHashToNix32/SRI_format_to_Nix32302=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method303=== CONT TestPathInfoCACompatibility/new_structured_format_-_text304=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive305=== CONT TestPathInfoCACompatibility/old_string_format_-_text306--- PASS: TestPathInfoCACompatibility (0.00s)307 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)308 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)309 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)310 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)311 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)312=== CONT TestConvertHashToNix32/invalid_format313=== CONT TestConvertHashToNix32/already_Nix32_format314--- PASS: TestConvertHashToNix32 (0.00s)315 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)316 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)317 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)318=== CONT TestRateLimiterFeedback/429_enables_limiter3192026/09/23 09:37:23 WARN Rate limiter enabled after throttle name=server-test rate=53202026/09/23 09:37:23 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:544033212026/09/23 09:37:23 WARN Rate limiter backed off name=server-test rate=5322=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter323=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter324=== CONT TestRateLimiterFeedback/503_enables_limiter3252026/09/23 09:37:23 WARN Rate limiter enabled after throttle name=server-test rate=53262026/09/23 09:37:23 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:54409327--- PASS: TestDumpPathWriterError (0.04s)328=== CONT TestUploadMultipart_SupersededByPeer/exists3292026/09/23 09:37:23 WARN Rate limiter backed off name=server-test rate=5330--- PASS: TestRateLimiterFeedback (0.00s)331 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)332 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)333 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)334 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)335=== CONT TestUploadMultipart_SupersededByPeer/missing336=== CONT TestSetClientTLSErrors/missing_cert_file337--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)338 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)339 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)340=== CONT TestSetClientTLSErrors/missing_ca_file341=== CONT TestSetClientTLSErrors/missing_key_file342=== CONT TestSetClientTLSErrors/invalid_ca_file343=== CONT TestEncodeNixBase32/test_string_hash344=== CONT TestSetClientTLS/rejects_connection_without_client_cert345=== CONT TestSetClientTLS/preserves_debug_logging_transport346--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)347=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA348--- PASS: TestSetClientTLSErrors (0.00s)349 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)350 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)351 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)352 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)353--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)354=== CONT TestEncodeNixBase32/empty_input355--- PASS: TestEncodeNixBase32 (0.00s)356 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)357 --- PASS: TestEncodeNixBase32/empty_input (0.00s)358=== CONT TestFilterOversizedClosures/no_limit_keeps_everything359=== CONT TestFilterOversizedClosures/all_closures_skipped3602026/09/23 09:37:23 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=50361=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3622026/09/23 09:37:23 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=2000363--- PASS: TestFilterOversizedClosures (0.00s)364 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)365 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)366 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)367=== CONT TestPartSizeForNAR/zero_stays_at_minimum368=== CONT TestPartSizeForNAR/1_TiB369=== CONT TestPartSizeForNAR/capped_at_5_GiB370=== CONT TestPartSizeForNAR/5_TiB_S3_max_object371=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts372=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum373=== CONT TestPartSizeForNAR/small_stays_at_minimum374--- PASS: TestPartSizeForNAR (0.00s)375 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)376 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)377 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)378 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)379 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)380 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)381 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)3822026/09/23 09:37:23 http: TLS handshake error from 127.0.0.1:54415: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.01s)384 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)385 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)386 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)387--- PASS: TestDumpPathSingleFile (0.07s)388--- PASS: TestCaseHackSuffix (0.07s)389--- PASS: TestDumpPathMatchesNix (0.10s)390--- PASS: TestStreamPushBatchesUnderLoad (0.10s)391--- PASS: TestUploadMultipart_PartsInParallel (0.62s)392--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld13".396This user must also own the server process.397398The database cluster will be initialized with locale "C".399The default database encoding has accordingly been set to "SQL_ASCII".400The default text search configuration will be set to "english".401402Data page checksums are enabled.403404creating directory /nix/var/nix/builds/nix-26666-911885599/postgres4006209173/data ... ok405creating subdirectories ... ok406selecting dynamic shared memory implementation ... posix407selecting default "max_connections" ... 100408selecting default "shared_buffers" ... 128MB409selecting default time zone ... UTC410creating configuration files ... ok411running bootstrap script ... ok412performing post-bootstrap initialization ... ok413syncing data to disk ... ok414415initdb: warning: enabling "trust" authentication for local connections416initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.417418Success. You can now start the database server using:419420 pg_ctl -D /nix/var/nix/builds/nix-26666-911885599/postgres4006209173/data -l logfile start421422/nix/var/nix/builds/nix-26666-911885599/postgres4006209173:5432 - no response4232026-09-23 09:37:27.032 UTC [27071] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-09-23 09:37:27.032 UTC [27071] LOG: listening on Unix socket "/nix/var/nix/builds/nix-26666-911885599/postgres4006209173/.s.PGSQL.5432"4252026-09-23 09:37:27.038 UTC [27078] LOG: database system was shut down at 2026-09-23 09:37:26 UTC4262026-09-23 09:37:27.040 UTC [27071] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-26666-911885599/postgres4006209173:5432 - accepting connections428{"timestamp":"2026-09-23T09:37:27.285627Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"938d6009-56b2-4124-adcd-ad71c2e1141c","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":7,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":463,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}429{"timestamp":"2026-09-23T09:37:27.403156Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"786be9ef-d73b-4f26-94ec-47dd443e6d52","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":463,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}430{"timestamp":"2026-09-23T09:37:27.50748Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"7aa3000a-cb34-42df-85fa-e18cc6712710","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":463,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}431{"timestamp":"2026-09-23T09:37:27.609357Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"2213b854-795f-4c58-be6d-fcaabf5b7c05","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":463,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}432=== RUN TestService_AuthMiddleware433=== PAUSE TestService_AuthMiddleware434=== RUN TestService_AuthMiddleware_MTLSProxyHeader435=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader436=== RUN TestService_AuthMiddleware_MTLSBoundSubjects437=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects438=== RUN TestService_ReadAuthMiddleware439=== PAUSE TestService_ReadAuthMiddleware440=== RUN TestService_AuthMiddleware_OIDC441=== PAUSE TestService_AuthMiddleware_OIDC442=== RUN TestService_RequireScope_OIDC443=== PAUSE TestService_RequireScope_OIDC444=== RUN TestService_ReadScope_PublicByDefault445=== PAUSE TestService_ReadScope_PublicByDefault446=== RUN TestCacheConfigHandler447=== PAUSE TestCacheConfigHandler448=== RUN TestCacheStatsHandler449=== PAUSE TestCacheStatsHandler450=== RUN TestClientCADerivations451=== PAUSE TestClientCADerivations452=== RUN TestClientErrorHandling453=== PAUSE TestClientErrorHandling454=== RUN TestClientIntegration455=== PAUSE TestClientIntegration456=== RUN TestClientMultipleUploads457=== PAUSE TestClientMultipleUploads458=== RUN TestClientWithDependencies459=== PAUSE TestClientWithDependencies460=== RUN TestClientSharedPathCommittedMidPush461=== PAUSE TestClientSharedPathCommittedMidPush462=== RUN TestPinProtectsFromGC463=== PAUSE TestPinProtectsFromGC464=== RUN TestResolveDBConnectionString465=== PAUSE TestResolveDBConnectionString466=== RUN TestLeadElectsOneAndHandsOver467=== PAUSE TestLeadElectsOneAndHandsOver468=== RUN TestLeadIncumbentWinsAfterRestart4692026-09-23 09:37:27.935 UTC [27124] ERROR: relation "goose_db_version" does not exist at character 364702026-09-23 09:37:27.935 UTC [27124] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4712026/09/23 09:37:27 OK 20241026095416_initial_model.sql (8.29ms)4722026/09/23 09:37:27 OK 20251210153512_drop_unused_gin_index.sql (1.19ms)4732026/09/23 09:37:27 OK 20251218171726_add_pins.sql (2.89ms)4742026/09/23 09:37:27 OK 20260628120000_add_object_size_and_stats.sql (2.59ms)4752026/09/23 09:37:27 OK 20260905000000_add_claims.sql (4.28ms)4762026/09/23 09:37:27 OK 20260920000000_drop_claims.sql (1.65ms)4772026/09/23 09:37:27 goose: successfully migrated database to version: 202609200000004782026/09/23 09:37:27 OK 1_commit_pending_closure.sql (2.92ms)4792026/09/23 09:37:27 OK 2_object_stats_trigger.sql (701.67µs)4802026/09/23 09:37:27 goose: up to current file version: 24812026/09/23 09:37:28 INFO lead: acquired remote=192.0.2.1:12344822026/09/23 09:37:28 INFO lead: released remote=192.0.2.1:12344832026/09/23 09:37:28 INFO lead: acquired remote=192.0.2.1:12344842026/09/23 09:37:28 INFO lead: released remote=192.0.2.1:1234485--- PASS: TestLeadIncumbentWinsAfterRestart (1.04s)486=== RUN TestLeadEndsOnShutdown487=== PAUSE TestLeadEndsOnShutdown488=== RUN TestGCAdvisoryLockBlocksConcurrentRun4892026-09-23 09:37:28.830 UTC [27145] ERROR: relation "goose_db_version" does not exist at character 364902026-09-23 09:37:28.830 UTC [27145] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4912026/09/23 09:37:28 OK 20241026095416_initial_model.sql (7.98ms)4922026/09/23 09:37:28 OK 20251210153512_drop_unused_gin_index.sql (1.17ms)4932026/09/23 09:37:28 OK 20251218171726_add_pins.sql (2.7ms)4942026/09/23 09:37:28 OK 20260628120000_add_object_size_and_stats.sql (2.61ms)4952026/09/23 09:37:28 OK 20260905000000_add_claims.sql (3.34ms)4962026/09/23 09:37:28 OK 20260920000000_drop_claims.sql (1.53ms)4972026/09/23 09:37:28 goose: successfully migrated database to version: 202609200000004982026/09/23 09:37:28 OK 1_commit_pending_closure.sql (2.09ms)4992026/09/23 09:37:28 OK 2_object_stats_trigger.sql (663.42µs)5002026/09/23 09:37:28 goose: up to current file version: 2501--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.27s)502=== RUN TestGCBugBareHashReferences503=== PAUSE TestGCBugBareHashReferences504=== RUN TestGCMetrics505=== PAUSE TestGCMetrics506=== RUN TestGCTaskStore_StartNew507=== PAUSE TestGCTaskStore_StartNew508=== RUN TestGCTaskStore_DeduplicateSameParams509=== PAUSE TestGCTaskStore_DeduplicateSameParams510=== RUN TestGCTaskStore_ConflictDifferentParams511=== PAUSE TestGCTaskStore_ConflictDifferentParams512=== RUN TestGCTaskStore_GetEmpty513=== PAUSE TestGCTaskStore_GetEmpty514=== RUN TestGCTaskStore_GetReturnsLatest515=== PAUSE TestGCTaskStore_GetReturnsLatest516=== RUN TestGCTaskStore_CompletedAllowsNewTask517=== PAUSE TestGCTaskStore_CompletedAllowsNewTask518=== RUN TestGCTaskStore_PhaseUpdates519=== PAUSE TestGCTaskStore_PhaseUpdates520=== RUN TestGCTaskStore_Fail521=== PAUSE TestGCTaskStore_Fail522=== RUN TestGracefulShutdownDrainsInflight523=== PAUSE TestGracefulShutdownDrainsInflight524=== RUN TestService_healthCheckHandler525=== PAUSE TestService_healthCheckHandler526=== RUN TestService_readinessHandler527=== PAUSE TestService_readinessHandler528=== RUN TestGenerateLandingPage529=== PAUSE TestGenerateLandingPage530=== RUN TestCacheConfigHandlerMaxNarSize531=== PAUSE TestCacheConfigHandlerMaxNarSize532=== RUN TestCreatePendingClosureRejectsOversizedNAR533=== PAUSE TestCreatePendingClosureRejectsOversizedNAR534=== RUN TestNARDeduplicationMetadataUploadBug535=== PAUSE TestNARDeduplicationMetadataUploadBug536=== RUN TestMetricsInventory537=== PAUSE TestMetricsInventory538=== RUN TestService_NativeMTLS539=== PAUSE TestService_NativeMTLS540=== RUN TestServerTLSConfig541=== PAUSE TestServerTLSConfig542=== RUN TestMultipartCleanup543=== PAUSE TestMultipartCleanup544=== RUN TestObjectStatsTrigger545=== PAUSE TestObjectStatsTrigger546=== RUN TestOrphanedObjectsGC547=== PAUSE TestOrphanedObjectsGC548=== RUN TestOrphanedObjectsGCStressTest549=== PAUSE TestOrphanedObjectsGCStressTest550=== RUN TestResurrectedObjectNotDeleted551=== PAUSE TestResurrectedObjectNotDeleted552=== RUN TestCreatePin_ReservedPins553=== PAUSE TestCreatePin_ReservedPins554=== RUN TestParseSingleRange555=== PAUSE TestParseSingleRange556=== RUN TestProxyHeadersOnlyTrustedOnSocket557=== PAUSE TestProxyHeadersOnlyTrustedOnSocket558=== RUN TestIsValidCachePath559=== PAUSE TestIsValidCachePath560=== RUN TestReadProxyNarinfo561=== PAUSE TestReadProxyNarinfo562=== RUN TestReadProxyNarinfoAlreadyDecompressed563=== PAUSE TestReadProxyNarinfoAlreadyDecompressed564=== RUN TestReadProxyNarStreaming565=== PAUSE TestReadProxyNarStreaming566=== RUN TestReadProxy404567=== PAUSE TestReadProxy404568=== RUN TestReadProxyInvalidPath569=== PAUSE TestReadProxyInvalidPath570=== RUN TestReadProxyHead571=== PAUSE TestReadProxyHead572=== RUN TestReadProxyConditionalGet573=== PAUSE TestReadProxyConditionalGet574=== RUN TestReadProxyRootRedirectsToIndexHTML575=== PAUSE TestReadProxyRootRedirectsToIndexHTML576=== RUN TestReadProxyDisabled577=== PAUSE TestReadProxyDisabled578=== RUN TestReadRedirectNar579=== PAUSE TestReadRedirectNar580=== RUN TestReadRedirectKeepsNarinfoProxied581=== PAUSE TestReadRedirectKeepsNarinfoProxied582=== RUN TestReadProxyRangeRequest583=== PAUSE TestReadProxyRangeRequest584=== RUN TestReadRedirectUsesPublicS3URL585=== PAUSE TestReadRedirectUsesPublicS3URL586=== RUN TestRedundantMultipartUpload587=== PAUSE TestRedundantMultipartUpload588=== RUN TestCompleteMultipartUpload_ErrorButObjectExists589=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists590=== RUN TestCompletedNarNotReofferedAcrossClosures591=== PAUSE TestCompletedNarNotReofferedAcrossClosures592=== RUN TestPresignedUploadRegisteredBeforeCommit593=== PAUSE TestPresignedUploadRegisteredBeforeCommit594=== RUN TestService_Rustfstest595=== PAUSE TestService_Rustfstest596=== RUN TestParseSize597=== PAUSE TestParseSize598=== RUN TestSkippedUploadsHandler599=== PAUSE TestSkippedUploadsHandler600=== RUN TestSystemdListenerNotActivated601--- PASS: TestSystemdListenerNotActivated (0.00s)602=== RUN TestWatchdogBeatsWhenHealthy603--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)604=== RUN TestWatchdogSkipsWhenUnhealthy6052026/09/23 09:37:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6062026/09/23 09:37:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6072026/09/23 09:37:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6082026/09/23 09:37:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6092026/09/23 09:37:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6102026/09/23 09:37:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6112026/09/23 09:37:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6122026/09/23 09:37:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6132026/09/23 09:37:29 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"614--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)615=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle616=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle617=== RUN TestProxyWriteTimeout618=== PAUSE TestProxyWriteTimeout619=== RUN TestIsValidUploadKey620=== PAUSE TestIsValidUploadKey621=== RUN TestUploadHandlersRejectInvalidKeys622=== PAUSE TestUploadHandlersRejectInvalidKeys623=== RUN TestUploadHandlersRejectOversizedBody624=== PAUSE TestUploadHandlersRejectOversizedBody625=== RUN TestService_cleanupPendingClosuresHandler626=== PAUSE TestService_cleanupPendingClosuresHandler627=== RUN TestService_createPendingClosureHandler628=== PAUSE TestService_createPendingClosureHandler629=== RUN TestService_verifyS3Integrity630=== PAUSE TestService_verifyS3Integrity631=== RUN TestCompleteMultipartUnregistered632=== PAUSE TestCompleteMultipartUnregistered633=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT634=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT635=== CONT TestService_AuthMiddleware636=== CONT TestMultipartCleanup637=== CONT TestReadProxyRangeRequest638=== CONT TestGCMetrics639=== CONT TestProxyWriteTimeout640=== RUN TestProxyWriteTimeout/narinfo641=== PAUSE TestProxyWriteTimeout/narinfo642=== CONT TestClientErrorHandling643=== RUN TestClientErrorHandling/InvalidStorePath644=== RUN TestProxyWriteTimeout/1_GiB_nar645=== PAUSE TestClientErrorHandling/InvalidStorePath646=== RUN TestClientErrorHandling/InvalidAuthToken647=== PAUSE TestProxyWriteTimeout/1_GiB_nar648=== PAUSE TestClientErrorHandling/InvalidAuthToken649=== CONT TestCompleteMultipartUnregistered650=== CONT TestService_verifyS3Integrity651=== CONT TestService_createPendingClosureHandler652=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT653=== RUN TestProxyWriteTimeout/10_GiB_nar654=== PAUSE TestProxyWriteTimeout/10_GiB_nar655=== RUN TestProxyWriteTimeout/unknown_size656=== PAUSE TestProxyWriteTimeout/unknown_size657=== CONT TestService_cleanupPendingClosuresHandler658=== RUN TestClientErrorHandling/ServerNotAvailable659=== PAUSE TestClientErrorHandling/ServerNotAvailable660=== CONT TestUploadHandlersRejectOversizedBody661=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure662=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure663=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart664=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart665=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts666=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts667=== CONT TestUploadHandlersRejectInvalidKeys668=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info669=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info670=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal671=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal672=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key673=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key674=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key675=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key676=== CONT TestIsValidUploadKey677=== RUN TestIsValidUploadKey/narinfo678=== PAUSE TestIsValidUploadKey/narinfo679=== RUN TestIsValidUploadKey/nar_zst680=== PAUSE TestIsValidUploadKey/nar_zst681=== RUN TestIsValidUploadKey/nar_xz682=== PAUSE TestIsValidUploadKey/nar_xz683=== RUN TestIsValidUploadKey/nar_plain684=== PAUSE TestIsValidUploadKey/nar_plain685=== RUN TestIsValidUploadKey/listing686=== PAUSE TestIsValidUploadKey/listing687=== RUN TestIsValidUploadKey/build_log688=== PAUSE TestIsValidUploadKey/build_log689=== RUN TestIsValidUploadKey/build_log_home-manager_file690=== PAUSE TestIsValidUploadKey/build_log_home-manager_file691=== RUN TestIsValidUploadKey/build_log_plus_in_name692=== PAUSE TestIsValidUploadKey/build_log_plus_in_name693=== RUN TestIsValidUploadKey/build_log_question_mark694=== PAUSE TestIsValidUploadKey/build_log_question_mark695=== RUN TestIsValidUploadKey/build_log_equals696=== PAUSE TestIsValidUploadKey/build_log_equals697=== RUN TestIsValidUploadKey/realisation698=== PAUSE TestIsValidUploadKey/realisation699=== RUN TestIsValidUploadKey/realisation_plus_in_output700=== PAUSE TestIsValidUploadKey/realisation_plus_in_output701=== RUN TestIsValidUploadKey/nix-cache-info702=== PAUSE TestIsValidUploadKey/nix-cache-info703=== RUN TestIsValidUploadKey/index.html704=== PAUSE TestIsValidUploadKey/index.html705=== RUN TestIsValidUploadKey/narinfo_key,_nar_type706=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type707=== RUN TestIsValidUploadKey/nar_key,_narinfo_type708=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type709=== RUN TestIsValidUploadKey/listing_key,_narinfo_type710=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type711=== RUN TestIsValidUploadKey/traversal712=== PAUSE TestIsValidUploadKey/traversal713=== RUN TestIsValidUploadKey/traversal_nar714=== PAUSE TestIsValidUploadKey/traversal_nar715=== RUN TestIsValidUploadKey/absolute716=== PAUSE TestIsValidUploadKey/absolute717=== RUN TestIsValidUploadKey/empty_key718=== PAUSE TestIsValidUploadKey/empty_key719=== RUN TestIsValidUploadKey/unknown_type720=== PAUSE TestIsValidUploadKey/unknown_type721=== CONT TestService_RequireScope_OIDC7222026-09-23 09:37:29.533 UTC [27170] ERROR: relation "goose_db_version" does not exist at character 367232026-09-23 09:37:29.533 UTC [27170] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7242026-09-23 09:37:29.553 UTC [27171] ERROR: relation "goose_db_version" does not exist at character 367252026-09-23 09:37:29.553 UTC [27171] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7262026/09/23 09:37:29 OK 20241026095416_initial_model.sql (56.29ms)7272026/09/23 09:37:29 OK 20251210153512_drop_unused_gin_index.sql (3.59ms)7282026/09/23 09:37:29 OK 20241026095416_initial_model.sql (21.91ms)7292026-09-23 09:37:29.612 UTC [27172] ERROR: relation "goose_db_version" does not exist at character 367302026-09-23 09:37:29.612 UTC [27172] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7312026-09-23 09:37:29.612 UTC [27174] ERROR: relation "goose_db_version" does not exist at character 367322026-09-23 09:37:29.612 UTC [27174] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7332026-09-23 09:37:29.614 UTC [27173] ERROR: relation "goose_db_version" does not exist at character 367342026-09-23 09:37:29.614 UTC [27173] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7352026-09-23 09:37:29.615 UTC [27175] ERROR: relation "goose_db_version" does not exist at character 367362026-09-23 09:37:29.615 UTC [27175] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7372026/09/23 09:37:29 OK 20241026095416_initial_model.sql (7.27ms)7382026/09/23 09:37:29 OK 20241026095416_initial_model.sql (9.01ms)7392026/09/23 09:37:29 OK 20251218171726_add_pins.sql (23.07ms)7402026/09/23 09:37:29 OK 20251210153512_drop_unused_gin_index.sql (23.16ms)7412026/09/23 09:37:29 OK 20251210153512_drop_unused_gin_index.sql (806µs)7422026/09/23 09:37:29 OK 20251210153512_drop_unused_gin_index.sql (947.58µs)7432026/09/23 09:37:29 OK 20251218171726_add_pins.sql (3.91ms)7442026/09/23 09:37:29 OK 20251218171726_add_pins.sql (3.6ms)7452026/09/23 09:37:29 OK 20251218171726_add_pins.sql (3.68ms)7462026/09/23 09:37:29 OK 20260628120000_add_object_size_and_stats.sql (4.54ms)7472026-09-23 09:37:29.639 UTC [27177] ERROR: relation "goose_db_version" does not exist at character 367482026-09-23 09:37:29.639 UTC [27177] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7492026/09/23 09:37:29 OK 20260628120000_add_object_size_and_stats.sql (2.64ms)7502026/09/23 09:37:29 OK 20260628120000_add_object_size_and_stats.sql (2.99ms)7512026-09-23 09:37:29.641 UTC [27178] ERROR: relation "goose_db_version" does not exist at character 367522026-09-23 09:37:29.641 UTC [27178] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7532026/09/23 09:37:29 OK 20260628120000_add_object_size_and_stats.sql (2.41ms)7542026/09/23 09:37:29 OK 20260905000000_add_claims.sql (4.52ms)7552026-09-23 09:37:29.644 UTC [27179] ERROR: relation "goose_db_version" does not exist at character 367562026-09-23 09:37:29.644 UTC [27179] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7572026/09/23 09:37:29 OK 20260920000000_drop_claims.sql (1.59ms)7582026/09/23 09:37:29 goose: successfully migrated database to version: 202609200000007592026/09/23 09:37:29 OK 20260905000000_add_claims.sql (3.1ms)7602026/09/23 09:37:29 OK 20260905000000_add_claims.sql (3.75ms)7612026/09/23 09:37:29 OK 20260905000000_add_claims.sql (3.93ms)7622026/09/23 09:37:29 OK 20260920000000_drop_claims.sql (1.45ms)7632026/09/23 09:37:29 goose: successfully migrated database to version: 202609200000007642026/09/23 09:37:29 OK 20260920000000_drop_claims.sql (1.44ms)7652026/09/23 09:37:29 goose: successfully migrated database to version: 202609200000007662026/09/23 09:37:29 OK 1_commit_pending_closure.sql (2.09ms)7672026/09/23 09:37:29 OK 20241026095416_initial_model.sql (12.31ms)7682026/09/23 09:37:29 OK 20241026095416_initial_model.sql (11.39ms)7692026/09/23 09:37:29 OK 20260920000000_drop_claims.sql (1.86ms)7702026/09/23 09:37:29 goose: successfully migrated database to version: 202609200000007712026/09/23 09:37:29 OK 2_object_stats_trigger.sql (756.75µs)7722026/09/23 09:37:29 goose: up to current file version: 27732026/09/23 09:37:29 OK 1_commit_pending_closure.sql (1.85ms)7742026/09/23 09:37:29 OK 1_commit_pending_closure.sql (1.9ms)7752026/09/23 09:37:29 OK 2_object_stats_trigger.sql (652.75µs)7762026/09/23 09:37:29 goose: up to current file version: 27772026/09/23 09:37:29 OK 20251210153512_drop_unused_gin_index.sql (1.18ms)7782026/09/23 09:37:29 OK 2_object_stats_trigger.sql (769.5µs)7792026/09/23 09:37:29 goose: up to current file version: 27802026/09/23 09:37:29 OK 1_commit_pending_closure.sql (1.92ms)7812026/09/23 09:37:29 OK 20251210153512_drop_unused_gin_index.sql (1.2ms)7822026/09/23 09:37:29 OK 2_object_stats_trigger.sql (608.38µs)7832026/09/23 09:37:29 goose: up to current file version: 27842026/09/23 09:37:29 OK 20251218171726_add_pins.sql (13.61ms)7852026/09/23 09:37:29 OK 20251218171726_add_pins.sql (13.32ms)7862026/09/23 09:37:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54435/oidc7872026/09/23 09:37:29 OK 20241026095416_initial_model.sql (32.26ms)7882026/09/23 09:37:29 OK 20241026095416_initial_model.sql (33.31ms)7892026/09/23 09:37:29 OK 20260628120000_add_object_size_and_stats.sql (22.39ms)7902026/09/23 09:37:29 OK 20260628120000_add_object_size_and_stats.sql (22.36ms)7912026/09/23 09:37:29 OK 20251210153512_drop_unused_gin_index.sql (10.18ms)7922026/09/23 09:37:29 OK 20251210153512_drop_unused_gin_index.sql (10.15ms)7932026/09/23 09:37:29 OK 20251218171726_add_pins.sql (7.25ms)7942026/09/23 09:37:29 OK 20251218171726_add_pins.sql (7.31ms)7952026/09/23 09:37:29 OK 20260905000000_add_claims.sql (11.48ms)7962026/09/23 09:37:29 OK 20260905000000_add_claims.sql (11.98ms)7972026/09/23 09:37:29 OK 20260628120000_add_object_size_and_stats.sql (2.68ms)7982026/09/23 09:37:29 OK 20260920000000_drop_claims.sql (9.73ms)7992026/09/23 09:37:29 goose: successfully migrated database to version: 202609200000008002026/09/23 09:37:29 OK 20241026095416_initial_model.sql (57.64ms)8012026/09/23 09:37:29 OK 1_commit_pending_closure.sql (2.04ms)8022026/09/23 09:37:29 OK 2_object_stats_trigger.sql (1.17ms)8032026/09/23 09:37:29 goose: up to current file version: 28042026/09/23 09:37:29 OK 20260920000000_drop_claims.sql (16.95ms)8052026/09/23 09:37:29 OK 20251210153512_drop_unused_gin_index.sql (7.5ms)8062026/09/23 09:37:29 goose: successfully migrated database to version: 202609200000008072026/09/23 09:37:29 OK 20260628120000_add_object_size_and_stats.sql (18.52ms)8082026/09/23 09:37:29 OK 1_commit_pending_closure.sql (2.05ms)8092026/09/23 09:37:29 OK 20260905000000_add_claims.sql (17.57ms)8102026/09/23 09:37:29 OK 2_object_stats_trigger.sql (534.42µs)8112026/09/23 09:37:29 goose: up to current file version: 28122026/09/23 09:37:29 OK 20251218171726_add_pins.sql (16.98ms)8132026/09/23 09:37:29 OK 20260905000000_add_claims.sql (16.52ms)8142026/09/23 09:37:29 OK 20260920000000_drop_claims.sql (14.88ms)8152026/09/23 09:37:29 goose: successfully migrated database to version: 202609200000008162026/09/23 09:37:29 OK 1_commit_pending_closure.sql (2.1ms)8172026/09/23 09:37:29 OK 2_object_stats_trigger.sql (744.96µs)8182026/09/23 09:37:29 goose: up to current file version: 28192026/09/23 09:37:29 OK 20260628120000_add_object_size_and_stats.sql (7.33ms)8202026/09/23 09:37:29 OK 20260920000000_drop_claims.sql (13.79ms)8212026/09/23 09:37:29 goose: successfully migrated database to version: 202609200000008222026/09/23 09:37:29 OK 1_commit_pending_closure.sql (2.13ms)8232026/09/23 09:37:29 OK 2_object_stats_trigger.sql (663.5µs)8242026/09/23 09:37:29 goose: up to current file version: 28252026/09/23 09:37:29 OK 20260905000000_add_claims.sql (22.68ms)8262026/09/23 09:37:29 OK 20260920000000_drop_claims.sql (9.93ms)8272026/09/23 09:37:29 goose: successfully migrated database to version: 202609200000008282026/09/23 09:37:29 OK 1_commit_pending_closure.sql (2.18ms)8292026/09/23 09:37:29 OK 2_object_stats_trigger.sql (667.67µs)8302026/09/23 09:37:29 goose: up to current file version: 28312026/09/23 09:37:29 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"832--- PASS: TestService_AuthMiddleware (0.54s)833=== CONT TestClientCADerivations834--- PASS: TestReadProxyRangeRequest (0.74s)835=== CONT TestCacheStatsHandler8362026/09/23 09:37:30 INFO Received uploads request method=POST path=/api/pending_closures837--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.94s)838=== CONT TestCacheConfigHandler839=== RUN TestCacheConfigHandler/full_config,_no_issuer840=== PAUSE TestCacheConfigHandler/full_config,_no_issuer841=== RUN TestCacheConfigHandler/no_cache_url_configured842=== PAUSE TestCacheConfigHandler/no_cache_url_configured843=== RUN TestCacheConfigHandler/no_signing_keys844=== PAUSE TestCacheConfigHandler/no_signing_keys845=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator846=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator847=== CONT TestService_ReadScope_PublicByDefault8482026/09/23 09:37:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8492026-09-23 09:37:30.337 UTC [27189] ERROR: relation "goose_db_version" does not exist at character 368502026-09-23 09:37:30.337 UTC [27189] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8512026/09/23 09:37:30 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst852--- PASS: TestCompleteMultipartUnregistered (1.09s)853=== CONT TestPresignedUploadRegisteredBeforeCommit8542026/09/23 09:37:30 OK 20241026095416_initial_model.sql (55.82ms)8552026/09/23 09:37:30 OK 20251210153512_drop_unused_gin_index.sql (8.5ms)8562026/09/23 09:37:30 OK 20251218171726_add_pins.sql (15.13ms)8572026/09/23 09:37:30 OK 20260628120000_add_object_size_and_stats.sql (12.92ms)8582026-09-23 09:37:30.501 UTC [27193] ERROR: relation "goose_db_version" does not exist at character 368592026-09-23 09:37:30.501 UTC [27193] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8602026/09/23 09:37:30 INFO Received uploads request method=POST path=/api/pending_closures8612026/09/23 09:37:30 INFO Received uploads request method=POST path=/api/pending_closures8622026/09/23 09:37:30 INFO Received uploads request method=POST path=/api/pending_closures8632026/09/23 09:37:30 OK 20260905000000_add_claims.sql (29.31ms)8642026/09/23 09:37:30 OK 20260920000000_drop_claims.sql (32.54ms)8652026/09/23 09:37:30 goose: successfully migrated database to version: 202609200000008662026/09/23 09:37:30 OK 1_commit_pending_closure.sql (2.2ms)8672026/09/23 09:37:30 OK 2_object_stats_trigger.sql (621.17µs)8682026/09/23 09:37:30 goose: up to current file version: 28692026/09/23 09:37:30 OK 20241026095416_initial_model.sql (86.12ms)8702026/09/23 09:37:30 OK 20251210153512_drop_unused_gin_index.sql (7.35ms)8712026/09/23 09:37:30 OK 20251218171726_add_pins.sql (14.22ms)8722026/09/23 09:37:30 OK 20260628120000_add_object_size_and_stats.sql (16.36ms)8732026/09/23 09:37:30 OK 20260905000000_add_claims.sql (21ms)8742026/09/23 09:37:30 OK 20260920000000_drop_claims.sql (24.52ms)8752026/09/23 09:37:30 goose: successfully migrated database to version: 202609200000008762026/09/23 09:37:30 OK 1_commit_pending_closure.sql (2.06ms)8772026/09/23 09:37:30 OK 2_object_stats_trigger.sql (444.08µs)8782026/09/23 09:37:30 goose: up to current file version: 28792026-09-23 09:37:30.717 UTC [27195] ERROR: relation "goose_db_version" does not exist at character 368802026-09-23 09:37:30.717 UTC [27195] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8812026/09/23 09:37:30 INFO Received uploads request method=POST path=/api/pending_closures8822026-09-23 09:37:30.802 UTC [27196] ERROR: relation "goose_db_version" does not exist at character 368832026-09-23 09:37:30.802 UTC [27196] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8842026/09/23 09:37:30 OK 20241026095416_initial_model.sql (78.36ms)8852026/09/23 09:37:30 OK 20251210153512_drop_unused_gin_index.sql (15.5ms)8862026/09/23 09:37:30 OK 20251218171726_add_pins.sql (21.96ms)8872026/09/23 09:37:30 OK 20260628120000_add_object_size_and_stats.sql (24.21ms)8882026/09/23 09:37:30 INFO Received uploads request method=POST path=/api/pending_closures8892026/09/23 09:37:30 OK 20260905000000_add_claims.sql (75.03ms)8902026/09/23 09:37:31 OK 20260920000000_drop_claims.sql (35.39ms)8912026/09/23 09:37:31 goose: successfully migrated database to version: 202609200000008922026/09/23 09:37:31 OK 20241026095416_initial_model.sql (173.8ms)8932026/09/23 09:37:31 OK 1_commit_pending_closure.sql (2.67ms)8942026/09/23 09:37:31 OK 2_object_stats_trigger.sql (1.66ms)8952026/09/23 09:37:31 goose: up to current file version: 28962026/09/23 09:37:31 OK 20251210153512_drop_unused_gin_index.sql (2.93ms)8972026/09/23 09:37:31 OK 20251218171726_add_pins.sql (5.64ms)8982026/09/23 09:37:31 OK 20260628120000_add_object_size_and_stats.sql (14ms)8992026/09/23 09:37:31 OK 20260905000000_add_claims.sql (46.11ms)9002026/09/23 09:37:31 OK 20260920000000_drop_claims.sql (29.22ms)9012026/09/23 09:37:31 goose: successfully migrated database to version: 202609200000009022026/09/23 09:37:31 OK 1_commit_pending_closure.sql (2.15ms)9032026/09/23 09:37:31 OK 2_object_stats_trigger.sql (489.42µs)9042026/09/23 09:37:31 goose: up to current file version: 29052026/09/23 09:37:31 INFO Received cleanup request method=DELETE path=/api/pending_closures9062026/09/23 09:37:31 INFO Aborted multipart uploads count=1907--- PASS: TestMultipartCleanup (1.90s)908=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9092026-09-23 09:37:31.184 UTC [27198] ERROR: relation "goose_db_version" does not exist at character 369102026-09-23 09:37:31.184 UTC [27198] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9112026/09/23 09:37:31 INFO Received cleanup request method=DELETE path=/api/pending_closures9122026/09/23 09:37:31 INFO Aborted multipart uploads count=09132026/09/23 09:37:31 INFO Received uploads request method=POST path=/api/pending_closures9142026/09/23 09:37:31 INFO Received cleanup request method=DELETE path=/api/pending_closures9152026/09/23 09:37:31 INFO Aborted multipart uploads count=19162026/09/23 09:37:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9172026-09-23 09:37:31.369 UTC [27177] ERROR: Closure does not exist: id=19182026-09-23 09:37:31.369 UTC [27177] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE9192026-09-23 09:37:31.369 UTC [27177] STATEMENT: -- name: CommitPendingClosure :exec920 SELECT commit_pending_closure($1::bigint)921 922--- PASS: TestService_cleanupPendingClosuresHandler (2.12s)923=== CONT TestSkippedUploadsHandler9242026/09/23 09:37:31 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000925--- PASS: TestSkippedUploadsHandler (0.00s)926=== CONT TestParseSize927--- PASS: TestParseSize (0.00s)928=== CONT TestService_Rustfstest9292026/09/23 09:37:31 OK 20241026095416_initial_model.sql (191.15ms)9302026/09/23 09:37:31 OK 20251210153512_drop_unused_gin_index.sql (13.17ms)9312026/09/23 09:37:31 OK 20251218171726_add_pins.sql (34.78ms)9322026/09/23 09:37:31 OK 20260628120000_add_object_size_and_stats.sql (32.23ms)9332026/09/23 09:37:31 OK 20260905000000_add_claims.sql (21.24ms)9342026/09/23 09:37:31 OK 20260920000000_drop_claims.sql (34.04ms)9352026/09/23 09:37:31 goose: successfully migrated database to version: 202609200000009362026/09/23 09:37:31 OK 1_commit_pending_closure.sql (2.25ms)9372026/09/23 09:37:31 OK 2_object_stats_trigger.sql (675.83µs)9382026/09/23 09:37:31 goose: up to current file version: 29392026/09/23 09:37:31 INFO Aborted multipart uploads count=09402026/09/23 09:37:31 WARN Force mode enabled - objects will be deleted immediately without grace period9412026/09/23 09:37:31 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09422026/09/23 09:37:31 INFO Vacuumed table table=pending_closures9432026/09/23 09:37:31 INFO Vacuumed table table=pending_objects9442026/09/23 09:37:31 INFO Vacuumed table table=multipart_uploads9452026/09/23 09:37:31 INFO Vacuumed table table=closures9462026/09/23 09:37:31 INFO Vacuumed table table=objects947--- PASS: TestGCMetrics (2.33s)948=== CONT TestCompleteMultipartUpload_ErrorButObjectExists9492026/09/23 09:37:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9502026/09/23 09:37:31 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZWUxMGUxN2QtYzhmNC00ZjlmLWEyNzktZGRiZmRjM2QwY2I4LmVhNTI5MjVkLTc3NTctNDRlYi04YTQ3LTExOWQzNTBlNDc0NngxNzkwMTU2MjUwNTE3NzI1MDAw parts=109512026/09/23 09:37:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9522026/09/23 09:37:31 INFO Completed upload id=19532026/09/23 09:37:31 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009542026/09/23 09:37:31 INFO Received uploads request method=POST path=/api/pending_closures9552026/09/23 09:37:31 INFO Starting cleanup of old closures method=DELETE path=/api/closures9562026/09/23 09:37:31 INFO Aborted multipart uploads count=0957=== RUN TestService_RequireScope_OIDC/builder_may_write958=== PAUSE TestService_RequireScope_OIDC/builder_may_write959=== RUN TestService_RequireScope_OIDC/builder_may_not_admin960=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin961=== RUN TestService_RequireScope_OIDC/ops_may_admin962=== PAUSE TestService_RequireScope_OIDC/ops_may_admin963=== RUN TestService_RequireScope_OIDC/ops_may_not_write964=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write965=== RUN TestService_RequireScope_OIDC/reader_may_not_write966=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write967=== RUN TestService_RequireScope_OIDC/static_token_may_admin968=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin969=== RUN TestService_RequireScope_OIDC/static_token_may_write970=== PAUSE TestService_RequireScope_OIDC/static_token_may_write971=== RUN TestService_RequireScope_OIDC/reader_may_read972=== PAUSE TestService_RequireScope_OIDC/reader_may_read973=== RUN TestService_RequireScope_OIDC/writer_implies_read974=== PAUSE TestService_RequireScope_OIDC/writer_implies_read975=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read976=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read977=== CONT TestCompletedNarNotReofferedAcrossClosures9782026/09/23 09:37:31 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=09792026/09/23 09:37:31 INFO Vacuumed table table=pending_closures9802026/09/23 09:37:31 INFO Vacuumed table table=pending_objects9812026/09/23 09:37:31 INFO Vacuumed table table=multipart_uploads9822026/09/23 09:37:31 INFO Vacuumed table table=closures9832026/09/23 09:37:31 INFO Vacuumed table table=objects9842026/09/23 09:37:31 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000985--- PASS: TestService_createPendingClosureHandler (2.71s)986=== CONT TestPinProtectsFromGC9872026/09/23 09:37:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9882026/09/23 09:37:32 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZWUxMGUxN2QtYzhmNC00ZjlmLWEyNzktZGRiZmRjM2QwY2I4LmI4ZDJmM2QzLWQzNWMtNGZlMS05OTAxLTYzYjZlZDhiZGRmNngxNzkwMTU2MjUwNzQyODQwMDAw parts=109892026/09/23 09:37:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9902026/09/23 09:37:32 INFO Completed upload id=19912026/09/23 09:37:32 INFO Received uploads request method=POST path=/api/pending_closures9922026/09/23 09:37:32 INFO Received uploads request method=POST path=/api/pending_closures9932026/09/23 09:37:32 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9942026/09/23 09:37:32 WARN Found objects in DB but missing from S3, will re-upload count=1995--- PASS: TestService_verifyS3Integrity (2.81s)996=== CONT TestGCBugBareHashReferences997--- PASS: TestCacheStatsHandler (2.30s)998=== CONT TestLeadEndsOnShutdown999--- PASS: TestService_ReadScope_PublicByDefault (2.24s)1000=== CONT TestLeadElectsOneAndHandsOver10012026-09-23 09:37:32.434 UTC [27246] ERROR: relation "goose_db_version" does not exist at character 3610022026-09-23 09:37:32.434 UTC [27246] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10032026-09-23 09:37:32.481 UTC [27248] ERROR: relation "goose_db_version" does not exist at character 3610042026-09-23 09:37:32.481 UTC [27248] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10052026/09/23 09:37:32 OK 20241026095416_initial_model.sql (75.11ms)10062026/09/23 09:37:32 OK 20241026095416_initial_model.sql (68.97ms)10072026/09/23 09:37:32 OK 20251210153512_drop_unused_gin_index.sql (10.13ms)10082026/09/23 09:37:32 OK 20251210153512_drop_unused_gin_index.sql (2.96ms)10092026/09/23 09:37:32 OK 20251218171726_add_pins.sql (17.46ms)10102026/09/23 09:37:32 OK 20251218171726_add_pins.sql (30.1ms)10112026/09/23 09:37:32 OK 20260628120000_add_object_size_and_stats.sql (31.45ms)10122026/09/23 09:37:32 OK 20260628120000_add_object_size_and_stats.sql (22.92ms)10132026/09/23 09:37:32 INFO Received uploads request method=POST path=/api/pending_closures10142026/09/23 09:37:32 OK 20260905000000_add_claims.sql (15.56ms)10152026/09/23 09:37:32 OK 20260905000000_add_claims.sql (25.33ms)10162026/09/23 09:37:32 OK 20260920000000_drop_claims.sql (19.32ms)10172026/09/23 09:37:32 goose: successfully migrated database to version: 2026092000000010182026/09/23 09:37:32 OK 20260920000000_drop_claims.sql (16.62ms)10192026/09/23 09:37:32 goose: successfully migrated database to version: 2026092000000010202026/09/23 09:37:32 OK 1_commit_pending_closure.sql (2.1ms)10212026/09/23 09:37:32 OK 1_commit_pending_closure.sql (2.45ms)10222026/09/23 09:37:32 OK 2_object_stats_trigger.sql (754.58µs)10232026/09/23 09:37:32 goose: up to current file version: 210242026/09/23 09:37:32 OK 2_object_stats_trigger.sql (1.25ms)10252026/09/23 09:37:32 goose: up to current file version: 210262026/09/23 09:37:32 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10272026/09/23 09:37:32 INFO Received uploads request method=POST path=/api/pending_closures1028--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.37s)1029=== CONT TestResolveDBConnectionString10302026-09-23 09:37:32.714 UTC [27257] ERROR: relation "goose_db_version" does not exist at character 3610312026-09-23 09:37:32.714 UTC [27257] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1032=== RUN TestResolveDBConnectionString/flag_wins1033=== PAUSE TestResolveDBConnectionString/flag_wins1034=== RUN TestResolveDBConnectionString/file_when_flag_empty1035=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1036=== RUN TestResolveDBConnectionString/missing_file_is_an_error1037=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1038=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1039=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1040=== RUN TestResolveDBConnectionString/nothing_configured1041=== PAUSE TestResolveDBConnectionString/nothing_configured1042=== CONT TestReadProxyNarinfoAlreadyDecompressed10432026-09-23 09:37:32.791 UTC [27266] ERROR: relation "goose_db_version" does not exist at character 3610442026-09-23 09:37:32.791 UTC [27266] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1045=== NAME TestClientCADerivations1046 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-26666-911885599/TestClientCADerivations1733164664/001/store/119bamwa6ag0kv9bsli7j1ggq6dxagwj-ca-test10472026/09/23 09:37:32 OK 20241026095416_initial_model.sql (72.26ms)10482026/09/23 09:37:32 OK 20251210153512_drop_unused_gin_index.sql (5.81ms)10492026/09/23 09:37:32 OK 20251218171726_add_pins.sql (23.02ms)10502026/09/23 09:37:32 OK 20260628120000_add_object_size_and_stats.sql (33.74ms)1051 client_ca_test.go:139: Found 1 dependencies (including self)1052--- PASS: TestService_Rustfstest (1.53s)1053=== CONT TestReadRedirectKeepsNarinfoProxied10542026/09/23 09:37:32 OK 20260905000000_add_claims.sql (35.16ms)10552026/09/23 09:37:32 OK 20260920000000_drop_claims.sql (31.84ms)10562026/09/23 09:37:32 goose: successfully migrated database to version: 2026092000000010572026/09/23 09:37:32 OK 1_commit_pending_closure.sql (2.26ms)10582026/09/23 09:37:32 OK 2_object_stats_trigger.sql (653.79µs)10592026/09/23 09:37:32 goose: up to current file version: 210602026/09/23 09:37:32 OK 20241026095416_initial_model.sql (144.22ms)10612026/09/23 09:37:32 OK 20251210153512_drop_unused_gin_index.sql (1.64ms)10622026/09/23 09:37:32 OK 20251218171726_add_pins.sql (21.71ms)10632026-09-23 09:37:33.007 UTC [27278] ERROR: relation "goose_db_version" does not exist at character 3610642026-09-23 09:37:33.007 UTC [27278] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10652026/09/23 09:37:33 OK 20260628120000_add_object_size_and_stats.sql (18.64ms)10662026-09-23 09:37:33.026 UTC [27279] ERROR: relation "goose_db_version" does not exist at character 3610672026-09-23 09:37:33.026 UTC [27279] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10682026/09/23 09:37:33 OK 20260905000000_add_claims.sql (26.9ms)10692026/09/23 09:37:33 OK 20260920000000_drop_claims.sql (7.31ms)10702026/09/23 09:37:33 goose: successfully migrated database to version: 2026092000000010712026/09/23 09:37:33 OK 1_commit_pending_closure.sql (2.33ms)10722026/09/23 09:37:33 OK 2_object_stats_trigger.sql (610.38µs)10732026/09/23 09:37:33 goose: up to current file version: 210742026/09/23 09:37:33 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10752026/09/23 09:37:33 INFO Received uploads request method=POST path=/api/pending_closures10762026/09/23 09:37:33 OK 20241026095416_initial_model.sql (101.97ms)10772026/09/23 09:37:33 INFO Received uploads request method=POST path=/api/pending_closures10782026/09/23 09:37:33 OK 20251210153512_drop_unused_gin_index.sql (7.87ms)10792026/09/23 09:37:33 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10802026/09/23 09:37:33 OK 20241026095416_initial_model.sql (125.8ms)10812026/09/23 09:37:33 INFO Uploading 119bamwa6ag0kv9bsli7j1ggq6dxagwj-ca-test (144B)10822026/09/23 09:37:33 OK 20251218171726_add_pins.sql (28.13ms)10832026/09/23 09:37:33 OK 20251210153512_drop_unused_gin_index.sql (3.31ms)10842026/09/23 09:37:33 OK 20260628120000_add_object_size_and_stats.sql (15.7ms)10852026/09/23 09:37:33 WARN Failed to register uploaded object key=log/rsixnq1fk0886f5zqshnz6rkzm9b1bp5-ca-test.drv error="server returned 404: 404 page not found\n"10862026/09/23 09:37:33 WARN Failed to register uploaded object key=119bamwa6ag0kv9bsli7j1ggq6dxagwj.ls error="server returned 404: 404 page not found\n"10872026/09/23 09:37:33 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"10882026/09/23 09:37:33 OK 20251218171726_add_pins.sql (22.46ms)10892026/09/23 09:37:33 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10902026/09/23 09:37:33 INFO Signed narinfos id=1 count=110912026/09/23 09:37:33 INFO Uploading 1 narinfos10922026/09/23 09:37:33 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10932026/09/23 09:37:33 WARN Failed to register uploaded object key=119bamwa6ag0kv9bsli7j1ggq6dxagwj.narinfo error="server returned 404: 404 page not found\n"10942026/09/23 09:37:33 OK 20260905000000_add_claims.sql (48.25ms)10952026/09/23 09:37:33 OK 20260628120000_add_object_size_and_stats.sql (44.86ms)10962026/09/23 09:37:33 INFO Completed upload id=110972026/09/23 09:37:33 INFO Upload complete. (304ms)1098=== NAME TestClientCADerivations1099 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-26666-911885599/TestClientCADerivations1733164664/001/store/119bamwa6ag0kv9bsli7j1ggq6dxagwj-ca-test1100 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1101 Compression: zstd1102 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1103 NarSize: 1441104 References: 1105 Deriver: /nix/var/nix/builds/nix-26666-911885599/TestClientCADerivations1733164664/001/store/rsixnq1fk0886f5zqshnz6rkzm9b1bp5-ca-test.drv1106 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1107 client_ca_test.go:185: Checking for realisation files in S3...1108 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1109 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache11102026/09/23 09:37:33 OK 20260920000000_drop_claims.sql (50.81ms)11112026/09/23 09:37:33 goose: successfully migrated database to version: 2026092000000011122026/09/23 09:37:33 OK 1_commit_pending_closure.sql (2.39ms)11132026/09/23 09:37:33 OK 2_object_stats_trigger.sql (750.88µs)11142026/09/23 09:37:33 goose: up to current file version: 211152026/09/23 09:37:33 OK 20260905000000_add_claims.sql (71.75ms)11162026/09/23 09:37:33 OK 20260920000000_drop_claims.sql (21.53ms)11172026/09/23 09:37:33 goose: successfully migrated database to version: 2026092000000011182026/09/23 09:37:33 OK 1_commit_pending_closure.sql (2.75ms)11192026/09/23 09:37:33 OK 2_object_stats_trigger.sql (1.33ms)11202026/09/23 09:37:33 goose: up to current file version: 211212026/09/23 09:37:33 INFO Received uploads request method=POST path=/api/pending_closures1122 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket13?endpoint=http://localhost:54420®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-26666-911885599/TestClientCADerivations1733164664/001/store'1123 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 111242026/09/23 09:37:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1125--- PASS: TestClientCADerivations (3.68s)1126=== CONT TestReadRedirectNar11272026-09-23 09:37:33.501 UTC [27301] ERROR: relation "goose_db_version" does not exist at character 3611282026-09-23 09:37:33.501 UTC [27301] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11292026/09/23 09:37:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11302026/09/23 09:37:33 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZWUxMGUxN2QtYzhmNC00ZjlmLWEyNzktZGRiZmRjM2QwY2I4LmQ5NjRiOGQxLTk0NzctNDEwYi1hZThhLTgxYzczZDNkZjQ2NngxNzkwMTU2MjUzNDE4MzgzMDAw11312026/09/23 09:37:33 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZWUxMGUxN2QtYzhmNC00ZjlmLWEyNzktZGRiZmRjM2QwY2I4LmQ5NjRiOGQxLTk0NzctNDEwYi1hZThhLTgxYzczZDNkZjQ2NngxNzkwMTU2MjUzNDE4MzgzMDAw parts=11132--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.04s)1133=== CONT TestReadProxyDisabled11342026-09-23 09:37:33.626 UTC [27311] ERROR: relation "goose_db_version" does not exist at character 3611352026-09-23 09:37:33.626 UTC [27311] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11362026/09/23 09:37:33 OK 20241026095416_initial_model.sql (124.23ms)11372026/09/23 09:37:33 INFO Received uploads request method=POST path=/api/pending_closures11382026/09/23 09:37:33 OK 20251210153512_drop_unused_gin_index.sql (10.79ms)11392026/09/23 09:37:33 OK 20251218171726_add_pins.sql (32.26ms)11402026/09/23 09:37:33 OK 20260628120000_add_object_size_and_stats.sql (26.05ms)11412026/09/23 09:37:33 OK 20260905000000_add_claims.sql (21.22ms)11422026/09/23 09:37:33 OK 20241026095416_initial_model.sql (102ms)11432026/09/23 09:37:33 OK 20251210153512_drop_unused_gin_index.sql (5.73ms)11442026/09/23 09:37:33 OK 20260920000000_drop_claims.sql (27.42ms)11452026/09/23 09:37:33 goose: successfully migrated database to version: 2026092000000011462026/09/23 09:37:33 OK 1_commit_pending_closure.sql (2.29ms)11472026/09/23 09:37:33 OK 2_object_stats_trigger.sql (639.04µs)11482026/09/23 09:37:33 goose: up to current file version: 211492026/09/23 09:37:33 OK 20251218171726_add_pins.sql (43.49ms)11502026/09/23 09:37:33 OK 20260628120000_add_object_size_and_stats.sql (18.68ms)11512026/09/23 09:37:33 OK 20260905000000_add_claims.sql (29.69ms)11522026/09/23 09:37:33 OK 20260920000000_drop_claims.sql (25.04ms)11532026/09/23 09:37:33 goose: successfully migrated database to version: 2026092000000011542026/09/23 09:37:33 OK 1_commit_pending_closure.sql (2.36ms)11552026/09/23 09:37:33 OK 2_object_stats_trigger.sql (664.33µs)11562026/09/23 09:37:33 goose: up to current file version: 211572026-09-23 09:37:33.929 UTC [27339] ERROR: relation "goose_db_version" does not exist at character 3611582026-09-23 09:37:33.929 UTC [27339] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11592026-09-23 09:37:34.090 UTC [27342] ERROR: relation "goose_db_version" does not exist at character 3611602026-09-23 09:37:34.090 UTC [27342] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11612026/09/23 09:37:34 OK 20241026095416_initial_model.sql (98.73ms)11622026/09/23 09:37:34 OK 20251210153512_drop_unused_gin_index.sql (7.37ms)11632026/09/23 09:37:34 OK 20251218171726_add_pins.sql (26.44ms)11642026/09/23 09:37:34 OK 20260628120000_add_object_size_and_stats.sql (20.55ms)11652026/09/23 09:37:34 OK 20260905000000_add_claims.sql (59.69ms)1166--- PASS: TestGCBugBareHashReferences (2.18s)1167=== CONT TestReadProxyRootRedirectsToIndexHTML11682026/09/23 09:37:34 OK 20260920000000_drop_claims.sql (31.44ms)11692026/09/23 09:37:34 goose: successfully migrated database to version: 2026092000000011702026/09/23 09:37:34 OK 1_commit_pending_closure.sql (2.21ms)11712026/09/23 09:37:34 OK 2_object_stats_trigger.sql (313.46µs)11722026/09/23 09:37:34 goose: up to current file version: 211732026/09/23 09:37:34 OK 20241026095416_initial_model.sql (165.15ms)11742026/09/23 09:37:34 OK 20251210153512_drop_unused_gin_index.sql (9.96ms)11752026/09/23 09:37:34 OK 20251218171726_add_pins.sql (24.13ms)11762026/09/23 09:37:34 OK 20260628120000_add_object_size_and_stats.sql (27.37ms)11772026/09/23 09:37:34 INFO lead: acquired remote=192.0.2.1:123411782026/09/23 09:37:34 INFO lead: released remote=192.0.2.1:12341179--- PASS: TestLeadEndsOnShutdown (2.10s)1180=== CONT TestReadProxyConditionalGet11812026/09/23 09:37:34 OK 20260905000000_add_claims.sql (31.36ms)11822026/09/23 09:37:34 OK 20260920000000_drop_claims.sql (35.26ms)11832026/09/23 09:37:34 goose: successfully migrated database to version: 2026092000000011842026/09/23 09:37:34 OK 1_commit_pending_closure.sql (1.86ms)11852026/09/23 09:37:34 OK 2_object_stats_trigger.sql (650.13µs)11862026/09/23 09:37:34 goose: up to current file version: 21187=== NAME TestPinProtectsFromGC1188 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-26666-911885599/TestPinProtectsFromGC2354392500/001/store/q0iikqidzs8lja78qlg2qn2ig37w4c9g-pinned-file.txt1189 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-26666-911885599/TestPinProtectsFromGC2354392500/001/store/pm3djv59b2d7p1s60nif66jg4rr9ddld-unpinned-file.txt11902026/09/23 09:37:34 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11912026/09/23 09:37:34 INFO Received uploads request method=POST path=/api/pending_closures11922026/09/23 09:37:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11932026/09/23 09:37:34 INFO Uploading q0iikqidzs8lja78qlg2qn2ig37w4c9g-pinned-file.txt (128B)11942026/09/23 09:37:34 INFO lead: acquired remote=192.0.2.1:123411952026/09/23 09:37:34 WARN Failed to register uploaded object key=q0iikqidzs8lja78qlg2qn2ig37w4c9g.ls error="server returned 404: 404 page not found\n"11962026/09/23 09:37:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11972026/09/23 09:37:34 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"11982026/09/23 09:37:34 INFO Signed narinfos id=1 count=111992026/09/23 09:37:34 INFO Uploading 1 narinfos12002026/09/23 09:37:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12012026/09/23 09:37:34 WARN Failed to register uploaded object key=q0iikqidzs8lja78qlg2qn2ig37w4c9g.narinfo error="server returned 404: 404 page not found\n"12022026/09/23 09:37:34 INFO Completed upload id=112032026/09/23 09:37:34 INFO Upload complete. (158ms)12042026/09/23 09:37:34 INFO lead: released remote=192.0.2.1:123412052026-09-23 09:37:34.789 UTC [27368] ERROR: relation "goose_db_version" does not exist at character 3612062026-09-23 09:37:34.789 UTC [27368] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12072026/09/23 09:37:34 INFO lead: acquired remote=192.0.2.1:123412082026/09/23 09:37:34 INFO lead: released remote=192.0.2.1:12341209--- PASS: TestLeadElectsOneAndHandsOver (2.40s)1210=== CONT TestReadProxyHead12112026/09/23 09:37:34 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12122026/09/23 09:37:34 INFO Received uploads request method=POST path=/api/pending_closures12132026/09/23 09:37:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12142026/09/23 09:37:34 INFO Uploading pm3djv59b2d7p1s60nif66jg4rr9ddld-unpinned-file.txt (128B)12152026/09/23 09:37:34 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"12162026-09-23 09:37:34.863 UTC [27373] ERROR: relation "goose_db_version" does not exist at character 3612172026-09-23 09:37:34.863 UTC [27373] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12182026/09/23 09:37:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12192026/09/23 09:37:34 INFO Signed narinfos id=2 count=112202026/09/23 09:37:34 INFO Uploading 1 narinfos12212026/09/23 09:37:34 WARN Failed to register uploaded object key=pm3djv59b2d7p1s60nif66jg4rr9ddld.ls error="server returned 404: 404 page not found\n"12222026/09/23 09:37:34 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12232026/09/23 09:37:34 WARN Failed to register uploaded object key=pm3djv59b2d7p1s60nif66jg4rr9ddld.narinfo error="server returned 404: 404 page not found\n"12242026/09/23 09:37:34 INFO Completed upload id=212252026/09/23 09:37:34 INFO Upload complete. (141ms)1226--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.22s)1227=== CONT TestReadProxyInvalidPath12282026/09/23 09:37:34 INFO Received create pin request method=POST path=/api/pins/myapp12292026/09/23 09:37:34 OK 20241026095416_initial_model.sql (151.66ms)12302026/09/23 09:37:34 OK 20251210153512_drop_unused_gin_index.sql (13.41ms)12312026/09/23 09:37:35 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-26666-911885599/TestPinProtectsFromGC2354392500/001/store/q0iikqidzs8lja78qlg2qn2ig37w4c9g-pinned-file.txt narinfo_key=q0iikqidzs8lja78qlg2qn2ig37w4c9g.narinfo12322026/09/23 09:37:35 INFO Starting cleanup of old closures method=DELETE path=/api/closures12332026/09/23 09:37:35 INFO Garbage collection started12342026/09/23 09:37:35 INFO Aborted multipart uploads count=012352026/09/23 09:37:35 WARN Force mode enabled - objects will be deleted immediately without grace period12362026/09/23 09:37:35 OK 20251218171726_add_pins.sql (44.58ms)12372026/09/23 09:37:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12382026/09/23 09:37:35 OK 20260628120000_add_object_size_and_stats.sql (42.22ms)12392026/09/23 09:37:35 OK 20241026095416_initial_model.sql (179.15ms)12402026/09/23 09:37:35 OK 20251210153512_drop_unused_gin_index.sql (7.63ms)12412026/09/23 09:37:35 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZWUxMGUxN2QtYzhmNC00ZjlmLWEyNzktZGRiZmRjM2QwY2I4Ljg4Y2Q3MDgxLTc5M2MtNDhlNS1iYzEzLTEwMmFiZWUyOGY1NngxNzkwMTU2MjUzNzA0MTA4MDAw parts=1212422026/09/23 09:37:35 INFO Received uploads request method=POST path=/api/pending_closures1243--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.29s)1244=== CONT TestReadProxy40412452026/09/23 09:37:35 OK 20260905000000_add_claims.sql (40.23ms)12462026/09/23 09:37:35 OK 20251218171726_add_pins.sql (32.07ms)12472026/09/23 09:37:35 OK 20260920000000_drop_claims.sql (20.9ms)12482026/09/23 09:37:35 goose: successfully migrated database to version: 2026092000000012492026/09/23 09:37:35 OK 1_commit_pending_closure.sql (2.29ms)12502026/09/23 09:37:35 OK 2_object_stats_trigger.sql (751.79µs)12512026/09/23 09:37:35 goose: up to current file version: 212522026/09/23 09:37:35 OK 20260628120000_add_object_size_and_stats.sql (29.47ms)1253--- PASS: TestReadRedirectKeepsNarinfoProxied (2.30s)1254=== CONT TestReadProxyNarStreaming12552026/09/23 09:37:35 OK 20260905000000_add_claims.sql (75.84ms)12562026/09/23 09:37:35 OK 20260920000000_drop_claims.sql (37.67ms)12572026/09/23 09:37:35 goose: successfully migrated database to version: 2026092000000012582026/09/23 09:37:35 OK 1_commit_pending_closure.sql (2.45ms)12592026/09/23 09:37:35 OK 2_object_stats_trigger.sql (741.5µs)12602026/09/23 09:37:35 goose: up to current file version: 212612026/09/23 09:37:35 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=01262--- PASS: TestReadRedirectNar (2.05s)1263=== CONT TestService_healthCheckHandler12642026/09/23 09:37:35 INFO Vacuumed table table=pending_closures12652026/09/23 09:37:35 INFO Vacuumed table table=pending_objects12662026/09/23 09:37:35 INFO Vacuumed table table=multipart_uploads12672026/09/23 09:37:35 INFO Vacuumed table table=closures12682026/09/23 09:37:35 INFO Vacuumed table table=objects12692026-09-23 09:37:35.771 UTC [27400] ERROR: relation "goose_db_version" does not exist at character 3612702026-09-23 09:37:35.771 UTC [27400] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1271--- PASS: TestReadProxyDisabled (2.15s)1272=== CONT TestServerTLSConfig1273=== RUN TestServerTLSConfig/no_client_CA1274=== PAUSE TestServerTLSConfig/no_client_CA1275=== RUN TestServerTLSConfig/missing_CA_file1276=== PAUSE TestServerTLSConfig/missing_CA_file1277=== RUN TestServerTLSConfig/not_a_PEM_file1278=== PAUSE TestServerTLSConfig/not_a_PEM_file1279=== CONT TestService_NativeMTLS12802026-09-23 09:37:35.791 UTC [27402] ERROR: relation "goose_db_version" does not exist at character 3612812026-09-23 09:37:35.791 UTC [27402] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12822026/09/23 09:37:35 OK 20241026095416_initial_model.sql (71.9ms)12832026/09/23 09:37:35 OK 20251210153512_drop_unused_gin_index.sql (6.43ms)12842026/09/23 09:37:35 OK 20241026095416_initial_model.sql (64.23ms)12852026/09/23 09:37:35 OK 20251218171726_add_pins.sql (11.17ms)12862026/09/23 09:37:35 OK 20251210153512_drop_unused_gin_index.sql (2.77ms)12872026/09/23 09:37:35 OK 20251218171726_add_pins.sql (3.05ms)12882026/09/23 09:37:35 OK 20260628120000_add_object_size_and_stats.sql (7.07ms)12892026/09/23 09:37:35 OK 20260628120000_add_object_size_and_stats.sql (17.07ms)12902026/09/23 09:37:35 OK 20260905000000_add_claims.sql (36.31ms)12912026/09/23 09:37:35 OK 20260920000000_drop_claims.sql (10.96ms)12922026/09/23 09:37:35 goose: successfully migrated database to version: 2026092000000012932026/09/23 09:37:35 OK 20260905000000_add_claims.sql (69ms)12942026/09/23 09:37:35 OK 1_commit_pending_closure.sql (38.1ms)12952026/09/23 09:37:35 OK 2_object_stats_trigger.sql (2.55ms)12962026/09/23 09:37:35 goose: up to current file version: 212972026/09/23 09:37:35 OK 20260920000000_drop_claims.sql (3.32ms)12982026/09/23 09:37:35 goose: successfully migrated database to version: 2026092000000012992026/09/23 09:37:35 OK 1_commit_pending_closure.sql (3.07ms)13002026/09/23 09:37:35 OK 2_object_stats_trigger.sql (1.15ms)13012026/09/23 09:37:35 goose: up to current file version: 213022026-09-23 09:37:36.225 UTC [27405] ERROR: relation "goose_db_version" does not exist at character 3613032026-09-23 09:37:36.225 UTC [27405] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1304--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.01s)1305=== CONT TestMetricsInventory13062026/09/23 09:37:36 OK 20241026095416_initial_model.sql (222.32ms)13072026/09/23 09:37:36 OK 20251210153512_drop_unused_gin_index.sql (15.04ms)1308--- PASS: TestReadProxyConditionalGet (2.17s)1309=== CONT TestNARDeduplicationMetadataUploadBug13102026/09/23 09:37:36 OK 20251218171726_add_pins.sql (31.41ms)13112026/09/23 09:37:36 OK 20260628120000_add_object_size_and_stats.sql (36.27ms)13122026/09/23 09:37:36 OK 20260905000000_add_claims.sql (52.03ms)13132026/09/23 09:37:36 OK 20260920000000_drop_claims.sql (10.68ms)13142026/09/23 09:37:36 goose: successfully migrated database to version: 2026092000000013152026/09/23 09:37:36 OK 1_commit_pending_closure.sql (3.59ms)13162026/09/23 09:37:36 OK 2_object_stats_trigger.sql (1.32ms)13172026/09/23 09:37:36 goose: up to current file version: 213182026-09-23 09:37:36.714 UTC [27414] ERROR: relation "goose_db_version" does not exist at character 3613192026-09-23 09:37:36.714 UTC [27414] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13202026-09-23 09:37:36.739 UTC [27413] ERROR: relation "goose_db_version" does not exist at character 3613212026-09-23 09:37:36.739 UTC [27413] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13222026-09-23 09:37:36.781 UTC [27415] ERROR: relation "goose_db_version" does not exist at character 3613232026-09-23 09:37:36.781 UTC [27415] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13242026-09-23 09:37:36.899 UTC [27417] ERROR: relation "goose_db_version" does not exist at character 3613252026-09-23 09:37:36.899 UTC [27417] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13262026/09/23 09:37:36 WARN Rate limiter enabled after throttle name=s3-test rate=513272026/09/23 09:37:36 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1328=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1329 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101330 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001331--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.75s)1332=== CONT TestCreatePendingClosureRejectsOversizedNAR13332026/09/23 09:37:36 INFO Received uploads request method=POST path=/api/pending_closures1334--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1335=== CONT TestCacheConfigHandlerMaxNarSize1336--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1337=== CONT TestGenerateLandingPage1338--- PASS: TestGenerateLandingPage (0.00s)1339=== CONT TestService_readinessHandler13402026/09/23 09:37:36 OK 20241026095416_initial_model.sql (169.95ms)13412026/09/23 09:37:36 OK 20241026095416_initial_model.sql (165.05ms)13422026/09/23 09:37:36 OK 20251210153512_drop_unused_gin_index.sql (11.17ms)13432026/09/23 09:37:36 OK 20251210153512_drop_unused_gin_index.sql (6.18ms)13442026/09/23 09:37:36 OK 20241026095416_initial_model.sql (131.33ms)13452026/09/23 09:37:36 OK 20251218171726_add_pins.sql (23.06ms)13462026/09/23 09:37:36 OK 20251218171726_add_pins.sql (28.86ms)13472026/09/23 09:37:36 OK 20251210153512_drop_unused_gin_index.sql (14.18ms)1348--- PASS: TestReadProxyHead (2.17s)1349=== CONT TestGCTaskStore_GetReturnsLatest1350--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1351=== CONT TestGracefulShutdownDrainsInflight13522026/09/23 09:37:36 INFO Starting HTTP server address=127.0.0.1:5450913532026/09/23 09:37:36 INFO Shutdown signal received, draining in-flight requests timeout=10s13542026/09/23 09:37:37 OK 20251218171726_add_pins.sql (23.38ms)13552026/09/23 09:37:37 OK 20260628120000_add_object_size_and_stats.sql (37.16ms)13562026/09/23 09:37:37 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=013572026/09/23 09:37:37 OK 20260628120000_add_object_size_and_stats.sql (43.4ms)1358=== NAME TestPinProtectsFromGC1359 client_integration_test.go:794: Pin successfully protected closure from garbage collection13602026/09/23 09:37:37 OK 20260628120000_add_object_size_and_stats.sql (38.47ms)13612026/09/23 09:37:37 OK 20260905000000_add_claims.sql (41.91ms)13622026/09/23 09:37:37 OK 20260905000000_add_claims.sql (48.24ms)1363--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1364=== CONT TestGCTaskStore_Fail1365--- PASS: TestGCTaskStore_Fail (0.00s)1366=== CONT TestGCTaskStore_PhaseUpdates1367--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1368=== CONT TestGCTaskStore_CompletedAllowsNewTask1369--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1370=== CONT TestClientWithDependencies13712026/09/23 09:37:37 OK 20260920000000_drop_claims.sql (43.11ms)13722026/09/23 09:37:37 goose: successfully migrated database to version: 202609200000001373--- PASS: TestPinProtectsFromGC (5.14s)1374=== CONT TestClientSharedPathCommittedMidPush13752026/09/23 09:37:37 OK 20260920000000_drop_claims.sql (45.68ms)13762026/09/23 09:37:37 goose: successfully migrated database to version: 2026092000000013772026/09/23 09:37:37 OK 1_commit_pending_closure.sql (3.4ms)13782026/09/23 09:37:37 OK 2_object_stats_trigger.sql (2.28ms)13792026/09/23 09:37:37 goose: up to current file version: 213802026/09/23 09:37:37 OK 1_commit_pending_closure.sql (3.6ms)13812026/09/23 09:37:37 OK 2_object_stats_trigger.sql (856µs)13822026/09/23 09:37:37 goose: up to current file version: 213832026/09/23 09:37:37 OK 20260905000000_add_claims.sql (64.79ms)13842026/09/23 09:37:37 OK 20241026095416_initial_model.sql (165.81ms)13852026/09/23 09:37:37 OK 20251210153512_drop_unused_gin_index.sql (9.36ms)13862026/09/23 09:37:37 OK 20260920000000_drop_claims.sql (19.92ms)13872026/09/23 09:37:37 goose: successfully migrated database to version: 2026092000000013882026/09/23 09:37:37 OK 1_commit_pending_closure.sql (3.01ms)13892026/09/23 09:37:37 OK 20251218171726_add_pins.sql (10.55ms)13902026/09/23 09:37:37 OK 2_object_stats_trigger.sql (609.83µs)13912026/09/23 09:37:37 goose: up to current file version: 213922026/09/23 09:37:37 OK 20260628120000_add_object_size_and_stats.sql (28.52ms)13932026-09-23 09:37:37.172 UTC [27432] ERROR: relation "goose_db_version" does not exist at character 3613942026-09-23 09:37:37.172 UTC [27432] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13952026/09/23 09:37:37 OK 20260905000000_add_claims.sql (88.17ms)13962026/09/23 09:37:37 OK 20260920000000_drop_claims.sql (27.6ms)13972026/09/23 09:37:37 goose: successfully migrated database to version: 2026092000000013982026/09/23 09:37:37 OK 1_commit_pending_closure.sql (2.18ms)13992026/09/23 09:37:37 OK 2_object_stats_trigger.sql (673.17µs)14002026/09/23 09:37:37 goose: up to current file version: 21401--- PASS: TestReadProxy404 (2.23s)1402=== CONT TestService_ReadAuthMiddleware14032026/09/23 09:37:37 OK 20241026095416_initial_model.sql (206.43ms)14042026/09/23 09:37:37 OK 20251210153512_drop_unused_gin_index.sql (2.96ms)14052026/09/23 09:37:37 OK 20251218171726_add_pins.sql (13.11ms)14062026/09/23 09:37:37 OK 20260628120000_add_object_size_and_stats.sql (24.07ms)14072026/09/23 09:37:37 OK 20260905000000_add_claims.sql (35.9ms)14082026/09/23 09:37:37 OK 20260920000000_drop_claims.sql (23.95ms)14092026/09/23 09:37:37 goose: successfully migrated database to version: 2026092000000014102026/09/23 09:37:37 OK 1_commit_pending_closure.sql (2.21ms)14112026/09/23 09:37:37 OK 2_object_stats_trigger.sql (502µs)14122026/09/23 09:37:37 goose: up to current file version: 21413--- PASS: TestReadProxyInvalidPath (2.66s)1414=== CONT TestService_AuthMiddleware_OIDC14152026/09/23 09:37:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54518/oidc1416--- PASS: TestReadProxyNarStreaming (2.65s)1417=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1418--- PASS: TestService_healthCheckHandler (2.62s)1419=== CONT TestClientMultipleUploads14202026-09-23 09:37:38.215 UTC [27449] ERROR: relation "goose_db_version" does not exist at character 3614212026-09-23 09:37:38.215 UTC [27449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14222026-09-23 09:37:38.357 UTC [27453] ERROR: relation "goose_db_version" does not exist at character 3614232026-09-23 09:37:38.357 UTC [27453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14242026/09/23 09:37:38 WARN mTLS auth: subject not in bound subjects subject="CN=reader"14252026/09/23 09:37:38 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1426--- PASS: TestService_NativeMTLS (2.66s)1427=== CONT TestService_AuthMiddleware_MTLSProxyHeader14282026/09/23 09:37:38 OK 20241026095416_initial_model.sql (165.46ms)14292026/09/23 09:37:38 OK 20251210153512_drop_unused_gin_index.sql (8.63ms)14302026/09/23 09:37:38 OK 20251218171726_add_pins.sql (43.12ms)14312026/09/23 09:37:38 OK 20260628120000_add_object_size_and_stats.sql (18.17ms)14322026/09/23 09:37:38 OK 20241026095416_initial_model.sql (111.42ms)14332026/09/23 09:37:38 OK 20251210153512_drop_unused_gin_index.sql (7.11ms)14342026/09/23 09:37:38 OK 20260905000000_add_claims.sql (33.81ms)14352026/09/23 09:37:38 OK 20251218171726_add_pins.sql (11.94ms)14362026/09/23 09:37:38 OK 20260920000000_drop_claims.sql (3.99ms)14372026/09/23 09:37:38 goose: successfully migrated database to version: 2026092000000014382026/09/23 09:37:38 OK 1_commit_pending_closure.sql (2.07ms)14392026/09/23 09:37:38 OK 2_object_stats_trigger.sql (609.17µs)14402026/09/23 09:37:38 goose: up to current file version: 214412026/09/23 09:37:38 OK 20260628120000_add_object_size_and_stats.sql (24.57ms)14422026-09-23 09:37:38.579 UTC [27466] ERROR: relation "goose_db_version" does not exist at character 3614432026-09-23 09:37:38.579 UTC [27466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14442026-09-23 09:37:38.579 UTC [27467] ERROR: relation "goose_db_version" does not exist at character 3614452026-09-23 09:37:38.579 UTC [27467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14462026/09/23 09:37:38 OK 20260905000000_add_claims.sql (35.41ms)14472026/09/23 09:37:38 OK 20260920000000_drop_claims.sql (2.96ms)14482026/09/23 09:37:38 goose: successfully migrated database to version: 2026092000000014492026-09-23 09:37:38.611 UTC [27469] ERROR: relation "goose_db_version" does not exist at character 3614502026-09-23 09:37:38.611 UTC [27469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14512026/09/23 09:37:38 OK 1_commit_pending_closure.sql (3.59ms)14522026/09/23 09:37:38 OK 2_object_stats_trigger.sql (366.54µs)14532026/09/23 09:37:38 goose: up to current file version: 214542026/09/23 09:37:38 OK 20241026095416_initial_model.sql (64.17ms)14552026/09/23 09:37:38 OK 20241026095416_initial_model.sql (73.49ms)14562026/09/23 09:37:38 OK 20251210153512_drop_unused_gin_index.sql (9.05ms)14572026/09/23 09:37:38 OK 20251210153512_drop_unused_gin_index.sql (2.73ms)14582026/09/23 09:37:38 OK 20251218171726_add_pins.sql (15.89ms)14592026/09/23 09:37:38 OK 20251218171726_add_pins.sql (25.09ms)14602026/09/23 09:37:38 OK 20260628120000_add_object_size_and_stats.sql (59.89ms)14612026/09/23 09:37:38 OK 20260628120000_add_object_size_and_stats.sql (67.06ms)14622026/09/23 09:37:38 OK 20241026095416_initial_model.sql (125.25ms)14632026/09/23 09:37:38 OK 20251210153512_drop_unused_gin_index.sql (4.61ms)14642026/09/23 09:37:38 OK 20260905000000_add_claims.sql (39.74ms)14652026/09/23 09:37:38 OK 20251218171726_add_pins.sql (34.6ms)14662026/09/23 09:37:38 OK 20260905000000_add_claims.sql (42.33ms)14672026-09-23 09:37:38.825 UTC [27474] ERROR: relation "goose_db_version" does not exist at character 3614682026-09-23 09:37:38.825 UTC [27474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1469--- PASS: TestMetricsInventory (2.58s)1470=== CONT TestCreatePin_ReservedPins14712026/09/23 09:37:38 OK 20260920000000_drop_claims.sql (22.55ms)14722026/09/23 09:37:38 goose: successfully migrated database to version: 2026092000000014732026/09/23 09:37:38 OK 20260920000000_drop_claims.sql (25.73ms)14742026/09/23 09:37:38 goose: successfully migrated database to version: 2026092000000014752026/09/23 09:37:38 OK 20260628120000_add_object_size_and_stats.sql (26.52ms)14762026/09/23 09:37:38 OK 1_commit_pending_closure.sql (2.33ms)14772026/09/23 09:37:38 OK 1_commit_pending_closure.sql (2.31ms)14782026/09/23 09:37:38 OK 2_object_stats_trigger.sql (960.79µs)14792026/09/23 09:37:38 goose: up to current file version: 214802026/09/23 09:37:38 OK 2_object_stats_trigger.sql (1.06ms)14812026/09/23 09:37:38 goose: up to current file version: 214822026/09/23 09:37:38 OK 20260905000000_add_claims.sql (18.88ms)14832026/09/23 09:37:38 OK 20260920000000_drop_claims.sql (11.2ms)14842026/09/23 09:37:38 goose: successfully migrated database to version: 2026092000000014852026/09/23 09:37:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54526/oidc14862026/09/23 09:37:38 OK 1_commit_pending_closure.sql (2.73ms)14872026/09/23 09:37:38 OK 2_object_stats_trigger.sql (791µs)14882026/09/23 09:37:38 goose: up to current file version: 214892026/09/23 09:37:38 OK 20241026095416_initial_model.sql (84.12ms)14902026/09/23 09:37:38 OK 20251210153512_drop_unused_gin_index.sql (7.89ms)14912026/09/23 09:37:38 OK 20251218171726_add_pins.sql (16.01ms)14922026/09/23 09:37:38 OK 20260628120000_add_object_size_and_stats.sql (27.86ms)14932026/09/23 09:37:39 OK 20260905000000_add_claims.sql (29.75ms)14942026/09/23 09:37:39 OK 20260920000000_drop_claims.sql (16.86ms)14952026/09/23 09:37:39 goose: successfully migrated database to version: 2026092000000014962026/09/23 09:37:39 OK 1_commit_pending_closure.sql (2.3ms)14972026/09/23 09:37:39 OK 2_object_stats_trigger.sql (779.46µs)14982026/09/23 09:37:39 goose: up to current file version: 214992026-09-23 09:37:39.119 UTC [27479] ERROR: relation "goose_db_version" does not exist at character 3615002026-09-23 09:37:39.119 UTC [27479] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1501=== NAME TestNARDeduplicationMetadataUploadBug1502 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-26666-911885599/TestNARDeduplicationMetadataUploadBug2062250773/001/store/v4d5rwyq6fhwjw4s64a3yxk50spvpiaj-file1.txt15032026/09/23 09:37:39 WARN readiness check failed error="closed pool"1504--- PASS: TestService_readinessHandler (2.30s)1505=== CONT TestReadProxyNarinfo15062026-09-23 09:37:39.264 UTC [27484] ERROR: relation "goose_db_version" does not exist at character 3615072026-09-23 09:37:39.264 UTC [27484] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15082026/09/23 09:37:39 OK 20241026095416_initial_model.sql (111.73ms)15092026/09/23 09:37:39 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)15102026/09/23 09:37:39 OK 20251218171726_add_pins.sql (5.35ms)15112026/09/23 09:37:39 OK 20260628120000_add_object_size_and_stats.sql (15.68ms)15122026/09/23 09:37:39 OK 20260905000000_add_claims.sql (19.13ms)15132026/09/23 09:37:39 OK 20260920000000_drop_claims.sql (3.67ms)15142026/09/23 09:37:39 goose: successfully migrated database to version: 2026092000000015152026/09/23 09:37:39 OK 1_commit_pending_closure.sql (2.02ms)15162026/09/23 09:37:39 OK 2_object_stats_trigger.sql (649.63µs)15172026/09/23 09:37:39 goose: up to current file version: 215182026/09/23 09:37:39 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15192026/09/23 09:37:39 INFO Received uploads request method=POST path=/api/pending_closures15202026-09-23 09:37:39.344 UTC [27501] ERROR: relation "goose_db_version" does not exist at character 3615212026-09-23 09:37:39.344 UTC [27501] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15222026/09/23 09:37:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15232026/09/23 09:37:39 INFO Uploading v4d5rwyq6fhwjw4s64a3yxk50spvpiaj-file1.txt (160B)15242026/09/23 09:37:39 OK 20241026095416_initial_model.sql (64.97ms)15252026/09/23 09:37:39 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)15262026/09/23 09:37:39 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"15272026/09/23 09:37:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15282026/09/23 09:37:39 OK 20251218171726_add_pins.sql (30.43ms)15292026/09/23 09:37:39 WARN Failed to register uploaded object key=v4d5rwyq6fhwjw4s64a3yxk50spvpiaj.ls error="server returned 404: 404 page not found\n"15302026/09/23 09:37:39 INFO Signed narinfos id=1 count=115312026/09/23 09:37:39 INFO Uploading 1 narinfos15322026/09/23 09:37:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15332026/09/23 09:37:39 WARN Failed to register uploaded object key=v4d5rwyq6fhwjw4s64a3yxk50spvpiaj.narinfo error="server returned 404: 404 page not found\n"15342026/09/23 09:37:39 OK 20260628120000_add_object_size_and_stats.sql (28.86ms)15352026/09/23 09:37:39 INFO Completed upload id=115362026/09/23 09:37:39 INFO Upload complete. (178ms)1537=== NAME TestNARDeduplicationMetadataUploadBug1538 metadata_upload_test.go:54: Retrieved narinfo from S3:1539 StorePath: /nix/var/nix/builds/nix-26666-911885599/TestNARDeduplicationMetadataUploadBug2062250773/001/store/v4d5rwyq6fhwjw4s64a3yxk50spvpiaj-file1.txt1540 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1541 Compression: zstd1542 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1543 NarSize: 1601544 References: 1545 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1546 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1547 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1548 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}15492026/09/23 09:37:39 OK 20260905000000_add_claims.sql (46.96ms)15502026/09/23 09:37:39 OK 20241026095416_initial_model.sql (81.35ms)15512026/09/23 09:37:39 OK 20251210153512_drop_unused_gin_index.sql (7.19ms)15522026/09/23 09:37:39 OK 20260920000000_drop_claims.sql (16.03ms)15532026/09/23 09:37:39 goose: successfully migrated database to version: 2026092000000015542026/09/23 09:37:39 OK 1_commit_pending_closure.sql (2.33ms)15552026/09/23 09:37:39 OK 2_object_stats_trigger.sql (660.38µs)15562026/09/23 09:37:39 goose: up to current file version: 215572026-09-23 09:37:39.494 UTC [27511] ERROR: relation "goose_db_version" does not exist at character 3615582026-09-23 09:37:39.494 UTC [27511] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15592026/09/23 09:37:39 OK 20251218171726_add_pins.sql (24.4ms)1560 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-26666-911885599/TestNARDeduplicationMetadataUploadBug2062250773/001/store/9wbd7qn4kari52mm8dc18jkx1dbiwkh4-file2.txt15612026/09/23 09:37:39 OK 20260628120000_add_object_size_and_stats.sql (33.16ms)15622026/09/23 09:37:39 OK 20260905000000_add_claims.sql (29.34ms)15632026/09/23 09:37:39 OK 20260920000000_drop_claims.sql (9ms)15642026/09/23 09:37:39 goose: successfully migrated database to version: 2026092000000015652026/09/23 09:37:39 OK 1_commit_pending_closure.sql (3.18ms)15662026/09/23 09:37:39 OK 2_object_stats_trigger.sql (841.63µs)15672026/09/23 09:37:39 goose: up to current file version: 215682026/09/23 09:37:39 OK 20241026095416_initial_model.sql (86.04ms)15692026/09/23 09:37:39 OK 20251210153512_drop_unused_gin_index.sql (7ms)15702026/09/23 09:37:39 OK 20251218171726_add_pins.sql (13.72ms)15712026/09/23 09:37:39 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15722026/09/23 09:37:39 INFO Received uploads request method=POST path=/api/pending_closures15732026/09/23 09:37:39 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15742026/09/23 09:37:39 OK 20260628120000_add_object_size_and_stats.sql (23.06ms)15752026/09/23 09:37:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15762026/09/23 09:37:39 INFO Signed narinfos id=2 count=115772026/09/23 09:37:39 WARN Failed to register uploaded object key=9wbd7qn4kari52mm8dc18jkx1dbiwkh4.ls error="server returned 404: 404 page not found\n"15782026/09/23 09:37:39 INFO Uploading 1 narinfos15792026/09/23 09:37:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15802026/09/23 09:37:39 WARN Failed to register uploaded object key=9wbd7qn4kari52mm8dc18jkx1dbiwkh4.narinfo error="server returned 404: 404 page not found\n"15812026/09/23 09:37:39 INFO Completed upload id=215822026/09/23 09:37:39 INFO Upload complete. (110ms)1583 metadata_upload_test.go:76: Retrieved narinfo from S3:1584 StorePath: /nix/var/nix/builds/nix-26666-911885599/TestNARDeduplicationMetadataUploadBug2062250773/001/store/9wbd7qn4kari52mm8dc18jkx1dbiwkh4-file2.txt1585 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1586 Compression: zstd1587 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1588 NarSize: 1601589 References: 1590 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1591 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1592 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1593 {"version":1,"root":{"type":"regular","size":44}}15942026/09/23 09:37:39 OK 20260905000000_add_claims.sql (42.99ms)15952026/09/23 09:37:39 OK 20260920000000_drop_claims.sql (21.02ms)15962026/09/23 09:37:39 goose: successfully migrated database to version: 2026092000000015972026/09/23 09:37:39 OK 1_commit_pending_closure.sql (2.49ms)15982026/09/23 09:37:39 OK 2_object_stats_trigger.sql (652.33µs)15992026/09/23 09:37:39 goose: up to current file version: 21600--- PASS: TestNARDeduplicationMetadataUploadBug (3.20s)1601=== CONT TestIsValidCachePath1602=== RUN TestIsValidCachePath/narinfo1603=== PAUSE TestIsValidCachePath/narinfo1604=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1605=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1606=== RUN TestIsValidCachePath/nar_zst1607=== PAUSE TestIsValidCachePath/nar_zst1608=== RUN TestIsValidCachePath/nar_xz1609=== PAUSE TestIsValidCachePath/nar_xz1610=== RUN TestIsValidCachePath/nar_bz21611=== PAUSE TestIsValidCachePath/nar_bz21612=== RUN TestIsValidCachePath/nar_uncompressed1613=== PAUSE TestIsValidCachePath/nar_uncompressed1614=== RUN TestIsValidCachePath/ls1615=== PAUSE TestIsValidCachePath/ls1616=== RUN TestIsValidCachePath/log1617=== PAUSE TestIsValidCachePath/log1618=== RUN TestIsValidCachePath/realisation1619=== PAUSE TestIsValidCachePath/realisation1620=== RUN TestIsValidCachePath/nix-cache-info1621=== PAUSE TestIsValidCachePath/nix-cache-info1622=== RUN TestIsValidCachePath/index.html1623=== PAUSE TestIsValidCachePath/index.html1624=== RUN TestIsValidCachePath/traversal_parent1625=== PAUSE TestIsValidCachePath/traversal_parent1626=== RUN TestIsValidCachePath/traversal_in_middle1627=== PAUSE TestIsValidCachePath/traversal_in_middle1628=== RUN TestIsValidCachePath/invalid_char_e1629=== PAUSE TestIsValidCachePath/invalid_char_e1630=== RUN TestIsValidCachePath/invalid_char_u1631=== PAUSE TestIsValidCachePath/invalid_char_u1632=== RUN TestIsValidCachePath/random_path1633=== PAUSE TestIsValidCachePath/random_path1634=== RUN TestIsValidCachePath/empty1635=== PAUSE TestIsValidCachePath/empty1636=== RUN TestIsValidCachePath/leading_slash1637=== PAUSE TestIsValidCachePath/leading_slash1638=== RUN TestIsValidCachePath/wrong_extension1639=== PAUSE TestIsValidCachePath/wrong_extension1640=== RUN TestIsValidCachePath/short_hash1641=== PAUSE TestIsValidCachePath/short_hash1642=== CONT TestProxyHeadersOnlyTrustedOnSocket16432026/09/23 09:37:39 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16442026/09/23 09:37:39 INFO Received uploads request method=POST path=/api/pending_closures1645--- PASS: TestService_ReadAuthMiddleware (2.55s)1646=== CONT TestParseSingleRange1647=== RUN TestParseSingleRange/none1648=== PAUSE TestParseSingleRange/none1649=== RUN TestParseSingleRange/unknown_unit1650=== PAUSE TestParseSingleRange/unknown_unit1651=== RUN TestParseSingleRange/multi-range_ignored1652=== PAUSE TestParseSingleRange/multi-range_ignored1653=== RUN TestParseSingleRange/malformed_no_dash1654=== PAUSE TestParseSingleRange/malformed_no_dash1655=== RUN TestParseSingleRange/malformed_both_empty1656=== PAUSE TestParseSingleRange/malformed_both_empty1657=== RUN TestParseSingleRange/malformed_end_before_start1658=== PAUSE TestParseSingleRange/malformed_end_before_start1659=== RUN TestParseSingleRange/closed1660=== PAUSE TestParseSingleRange/closed1661=== RUN TestParseSingleRange/open-ended1662=== PAUSE TestParseSingleRange/open-ended1663=== RUN TestParseSingleRange/end_clamped_to_size1664=== PAUSE TestParseSingleRange/end_clamped_to_size1665=== RUN TestParseSingleRange/suffix1666=== PAUSE TestParseSingleRange/suffix1667=== RUN TestParseSingleRange/suffix_exceeds_size1668=== PAUSE TestParseSingleRange/suffix_exceeds_size1669=== RUN TestParseSingleRange/single_byte1670=== PAUSE TestParseSingleRange/single_byte1671=== RUN TestParseSingleRange/start_past_EOF1672=== PAUSE TestParseSingleRange/start_past_EOF1673=== RUN TestParseSingleRange/start_far_past_EOF1674=== PAUSE TestParseSingleRange/start_far_past_EOF1675=== CONT TestGCTaskStore_GetEmpty1676--- PASS: TestGCTaskStore_GetEmpty (0.00s)1677=== CONT TestGCTaskStore_ConflictDifferentParams1678--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1679=== CONT TestGCTaskStore_DeduplicateSameParams1680--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1681=== CONT TestGCTaskStore_StartNew1682--- PASS: TestGCTaskStore_StartNew (0.00s)1683=== CONT TestReadRedirectUsesPublicS3URL16842026-09-23 09:37:39.897 UTC [27539] ERROR: relation "goose_db_version" does not exist at character 3616852026-09-23 09:37:39.897 UTC [27539] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16862026/09/23 09:37:40 OK 20241026095416_initial_model.sql (68.23ms)16872026/09/23 09:37:40 OK 20251210153512_drop_unused_gin_index.sql (8.3ms)16882026-09-23 09:37:40.050 UTC [27549] ERROR: relation "goose_db_version" does not exist at character 3616892026-09-23 09:37:40.050 UTC [27549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16902026/09/23 09:37:40 OK 20251218171726_add_pins.sql (17.04ms)16912026/09/23 09:37:40 OK 20260628120000_add_object_size_and_stats.sql (34.32ms)16922026/09/23 09:37:40 OK 20260905000000_add_claims.sql (14.83ms)16932026/09/23 09:37:40 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16942026/09/23 09:37:40 INFO Received uploads request method=POST path=/api/pending_closures16952026/09/23 09:37:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16962026/09/23 09:37:40 INFO Uploading gj6cgay5fpblysbmy9vpmxiv9j6cg9s3-shared-dep (136B)16972026/09/23 09:37:40 OK 20260920000000_drop_claims.sql (22.75ms)16982026/09/23 09:37:40 goose: successfully migrated database to version: 2026092000000016992026/09/23 09:37:40 OK 1_commit_pending_closure.sql (2.09ms)17002026/09/23 09:37:40 OK 2_object_stats_trigger.sql (610.13µs)17012026/09/23 09:37:40 goose: up to current file version: 21702=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1703=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1704=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1705=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1706=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1707=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1708=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1709=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1710=== CONT TestOrphanedObjectsGCStressTest17112026/09/23 09:37:40 WARN Failed to register uploaded object key=gj6cgay5fpblysbmy9vpmxiv9j6cg9s3.ls error="server returned 404: 404 page not found\n"17122026/09/23 09:37:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17132026/09/23 09:37:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17142026/09/23 09:37:40 INFO Signed narinfos id=2 count=117152026/09/23 09:37:40 INFO Uploading 1 narinfos17162026/09/23 09:37:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17172026/09/23 09:37:40 WARN Failed to register uploaded object key=gj6cgay5fpblysbmy9vpmxiv9j6cg9s3.narinfo error="server returned 404: 404 page not found\n"17182026/09/23 09:37:40 INFO Completed upload id=217192026/09/23 09:37:40 INFO Upload complete. (165ms)17202026/09/23 09:37:40 INFO Received uploads request method=POST path=/api/pending_closures17212026/09/23 09:37:40 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17222026/09/23 09:37:40 INFO Uploading nm8b0x7b30nqjc8y4xpgp7cxybldpiq8-top (256B)17232026/09/23 09:37:40 INFO Uploading gj6cgay5fpblysbmy9vpmxiv9j6cg9s3-shared-dep (136B)17242026/09/23 09:37:40 OK 20241026095416_initial_model.sql (128.11ms)17252026/09/23 09:37:40 WARN Failed to register uploaded object key=nar/0hmszlgdlszw63jl03rvbwiz38rn20la5pkg4whpiym94f1pz05b.nar.zst error="server returned 404: 404 page not found\n"17262026/09/23 09:37:40 OK 20251210153512_drop_unused_gin_index.sql (9.17ms)17272026/09/23 09:37:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17282026/09/23 09:37:40 WARN Failed to register uploaded object key=nm8b0x7b30nqjc8y4xpgp7cxybldpiq8.ls error="server returned 404: 404 page not found\n"17292026/09/23 09:37:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign17302026/09/23 09:37:40 WARN Failed to register uploaded object key=gj6cgay5fpblysbmy9vpmxiv9j6cg9s3.ls error="server returned 404: 404 page not found\n"17312026/09/23 09:37:40 INFO Signed narinfos id=3 count=117322026/09/23 09:37:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17332026/09/23 09:37:40 INFO Signed narinfos id=1 count=117342026/09/23 09:37:40 INFO Uploading 2 narinfos17352026/09/23 09:37:40 OK 20251218171726_add_pins.sql (21.33ms)17362026/09/23 09:37:40 WARN Failed to register uploaded object key=nm8b0x7b30nqjc8y4xpgp7cxybldpiq8.narinfo error="server returned 404: 404 page not found\n"17372026/09/23 09:37:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17382026/09/23 09:37:40 WARN Failed to register uploaded object key=gj6cgay5fpblysbmy9vpmxiv9j6cg9s3.narinfo error="server returned 404: 404 page not found\n"17392026/09/23 09:37:40 INFO Completed upload id=117402026/09/23 09:37:40 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete17412026/09/23 09:37:40 INFO Completed upload id=317422026/09/23 09:37:40 INFO Upload complete. (460ms)1743=== NAME TestClientSharedPathCommittedMidPush1744 client_integration_test.go:680: Retrieved narinfo from S3:1745 StorePath: /nix/var/nix/builds/nix-26666-911885599/TestClientSharedPathCommittedMidPush2242769214/001/store/gj6cgay5fpblysbmy9vpmxiv9j6cg9s3-shared-dep1746 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1747 Compression: zstd1748 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821749 NarSize: 1361750 References: 1751 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1752 client_integration_test.go:680: Retrieved narinfo from S3:1753 StorePath: /nix/var/nix/builds/nix-26666-911885599/TestClientSharedPathCommittedMidPush2242769214/001/store/nm8b0x7b30nqjc8y4xpgp7cxybldpiq8-top1754 URL: nar/0hmszlgdlszw63jl03rvbwiz38rn20la5pkg4whpiym94f1pz05b.nar.zst1755 Compression: zstd1756 NarHash: sha256:0hmszlgdlszw63jl03rvbwiz38rn20la5pkg4whpiym94f1pz05b1757 NarSize: 2561758 References: /nix/var/nix/builds/nix-26666-911885599/TestClientSharedPathCommittedMidPush2242769214/001/store/gj6cgay5fpblysbmy9vpmxiv9j6cg9s3-shared-dep1759 CA: text:sha256:1vkjnscgkp6n3rc1m2dccs71dgwfc6bs7d2d901vi0cnmxqa3mis17602026/09/23 09:37:40 OK 20260628120000_add_object_size_and_stats.sql (40.12ms)17612026/09/23 09:37:40 OK 20260905000000_add_claims.sql (47.66ms)1762--- PASS: TestClientSharedPathCommittedMidPush (3.24s)1763=== CONT TestRedundantMultipartUpload17642026/09/23 09:37:40 OK 20260920000000_drop_claims.sql (28.34ms)17652026/09/23 09:37:40 goose: successfully migrated database to version: 2026092000000017662026/09/23 09:37:40 OK 1_commit_pending_closure.sql (2.25ms)17672026/09/23 09:37:40 OK 2_object_stats_trigger.sql (648.96µs)17682026/09/23 09:37:40 goose: up to current file version: 217692026/09/23 09:37:40 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17702026/09/23 09:37:40 WARN mTLS auth: bound subjects configured but subject DN unavailable17712026/09/23 09:37:40 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1772--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.54s)1773=== CONT TestResurrectedObjectNotDeleted1774=== NAME TestClientWithDependencies1775 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-26666-911885599/TestClientWithDependencies3167423967/001/store/1ivfvsi67fbd0g5wd64cjj3zga5ad4x7-test-script1776 client_integration_test.go:615: Found 1 dependencies (including self)17772026-09-23 09:37:40.573 UTC [27575] ERROR: relation "goose_db_version" does not exist at character 3617782026-09-23 09:37:40.573 UTC [27575] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17792026/09/23 09:37:40 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17802026/09/23 09:37:40 INFO Received uploads request method=POST path=/api/pending_closures17812026/09/23 09:37:40 OK 20241026095416_initial_model.sql (99.13ms)17822026/09/23 09:37:40 OK 20251210153512_drop_unused_gin_index.sql (3.54ms)17832026/09/23 09:37:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17842026/09/23 09:37:40 INFO Uploading 1ivfvsi67fbd0g5wd64cjj3zga5ad4x7-test-script (136B)17852026/09/23 09:37:40 OK 20251218171726_add_pins.sql (17.82ms)17862026/09/23 09:37:40 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17872026/09/23 09:37:40 WARN Failed to register uploaded object key=log/kdv5hb275jqdfrzpml6sby457n714rkb-test-script.drv error="server returned 404: 404 page not found\n"17882026/09/23 09:37:40 OK 20260628120000_add_object_size_and_stats.sql (26.26ms)17892026/09/23 09:37:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17902026/09/23 09:37:40 WARN Failed to register uploaded object key=1ivfvsi67fbd0g5wd64cjj3zga5ad4x7.ls error="server returned 404: 404 page not found\n"17912026/09/23 09:37:40 INFO Signed narinfos id=1 count=117922026/09/23 09:37:40 INFO Uploading 1 narinfos17932026/09/23 09:37:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17942026/09/23 09:37:40 WARN Failed to register uploaded object key=1ivfvsi67fbd0g5wd64cjj3zga5ad4x7.narinfo error="server returned 404: 404 page not found\n"1795=== NAME TestClientMultipleUploads1796 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-26666-911885599/TestClientMultipleUploads3155230199/001/store/wjhiayzlybr1kw2gibhmknc6g4y3vcxa-test-file-0.txt17972026/09/23 09:37:40 OK 20260905000000_add_claims.sql (47.83ms)17982026/09/23 09:37:40 INFO Completed upload id=117992026/09/23 09:37:40 INFO Upload complete. (217ms)1800--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.38s)1801=== CONT TestClientIntegration1802=== NAME TestClientWithDependencies1803 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-26666-911885599/TestClientWithDependencies3167423967/001/store) requires matching store prefix18042026/09/23 09:37:40 OK 20260920000000_drop_claims.sql (29.91ms)18052026/09/23 09:37:40 goose: successfully migrated database to version: 2026092000000018062026/09/23 09:37:40 OK 1_commit_pending_closure.sql (2.47ms)18072026/09/23 09:37:40 OK 2_object_stats_trigger.sql (676.71µs)18082026/09/23 09:37:40 goose: up to current file version: 21809--- PASS: TestClientWithDependencies (3.82s)1810=== CONT TestOrphanedObjectsGC1811=== NAME TestClientMultipleUploads1812 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-26666-911885599/TestClientMultipleUploads3155230199/001/store/b24pdrzb88bcwb2p2ci5p4mznz8pv3kc-test-file-1.txt18132026-09-23 09:37:40.949 UTC [27593] ERROR: relation "goose_db_version" does not exist at character 3618142026-09-23 09:37:40.949 UTC [27593] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1815 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-26666-911885599/TestClientMultipleUploads3155230199/001/store/a328sfz737jh3321fi7fagqsyypsss8j-test-file-2.txt18162026/09/23 09:37:41 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18172026/09/23 09:37:41 WARN Refused reserved pin name=worker-x86_64-linux18182026/09/23 09:37:41 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18192026/09/23 09:37:41 INFO Received create pin request method=POST path=/api/pins/my-app18202026/09/23 09:37:41 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1821--- PASS: TestCreatePin_ReservedPins (2.20s)1822=== CONT TestObjectStatsTrigger18232026/09/23 09:37:41 OK 20241026095416_initial_model.sql (99.51ms)18242026/09/23 09:37:41 OK 20251210153512_drop_unused_gin_index.sql (1.35ms)18252026/09/23 09:37:41 OK 20251218171726_add_pins.sql (19.76ms)18262026-09-23 09:37:41.108 UTC [27600] ERROR: relation "goose_db_version" does not exist at character 3618272026-09-23 09:37:41.108 UTC [27600] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18282026/09/23 09:37:41 OK 20260628120000_add_object_size_and_stats.sql (17.3ms)18292026/09/23 09:37:41 OK 20260905000000_add_claims.sql (19.32ms)18302026/09/23 09:37:41 OK 20260920000000_drop_claims.sql (14.66ms)18312026/09/23 09:37:41 goose: successfully migrated database to version: 2026092000000018322026/09/23 09:37:41 OK 1_commit_pending_closure.sql (4.9ms)18332026/09/23 09:37:41 OK 2_object_stats_trigger.sql (2.37ms)18342026/09/23 09:37:41 goose: up to current file version: 218352026-09-23 09:37:41.169 UTC [27602] ERROR: relation "goose_db_version" does not exist at character 3618362026-09-23 09:37:41.169 UTC [27602] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18372026/09/23 09:37:41 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18382026/09/23 09:37:41 INFO Received uploads request method=POST path=/api/pending_closures18392026/09/23 09:37:41 INFO Received uploads request method=POST path=/api/pending_closures18402026/09/23 09:37:41 INFO Received uploads request method=POST path=/api/pending_closures18412026/09/23 09:37:41 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18422026/09/23 09:37:41 INFO Uploading wjhiayzlybr1kw2gibhmknc6g4y3vcxa-test-file-0.txt (160B)18432026/09/23 09:37:41 INFO Uploading b24pdrzb88bcwb2p2ci5p4mznz8pv3kc-test-file-1.txt (160B)18442026/09/23 09:37:41 INFO Uploading a328sfz737jh3321fi7fagqsyypsss8j-test-file-2.txt (160B)18452026/09/23 09:37:41 WARN Failed to register uploaded object key=b24pdrzb88bcwb2p2ci5p4mznz8pv3kc.ls error="server returned 404: 404 page not found\n"18462026/09/23 09:37:41 WARN Failed to register uploaded object key=wjhiayzlybr1kw2gibhmknc6g4y3vcxa.ls error="server returned 404: 404 page not found\n"18472026/09/23 09:37:41 WARN Failed to register uploaded object key=a328sfz737jh3321fi7fagqsyypsss8j.ls error="server returned 404: 404 page not found\n"18482026/09/23 09:37:41 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18492026/09/23 09:37:41 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18502026/09/23 09:37:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18512026/09/23 09:37:41 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18522026/09/23 09:37:41 INFO Signed narinfos id=1 count=118532026/09/23 09:37:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18542026/09/23 09:37:41 INFO Signed narinfos id=2 count=118552026/09/23 09:37:41 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign18562026/09/23 09:37:41 INFO Signed narinfos id=3 count=118572026/09/23 09:37:41 INFO Uploading 3 narinfos1858--- PASS: TestReadProxyNarinfo (2.03s)1859=== CONT TestProxyWriteTimeout/narinfo1860=== CONT TestProxyWriteTimeout/unknown_size1861=== CONT TestProxyWriteTimeout/10_GiB_nar1862=== CONT TestProxyWriteTimeout/1_GiB_nar1863--- PASS: TestProxyWriteTimeout (0.00s)1864 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1865 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1866 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1867 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1868=== CONT TestClientErrorHandling/InvalidStorePath18692026/09/23 09:37:41 WARN Failed to register uploaded object key=b24pdrzb88bcwb2p2ci5p4mznz8pv3kc.narinfo error="server returned 404: 404 page not found\n"18702026/09/23 09:37:41 WARN Failed to register uploaded object key=a328sfz737jh3321fi7fagqsyypsss8j.narinfo error="server returned 404: 404 page not found\n"18712026/09/23 09:37:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18722026/09/23 09:37:41 WARN Failed to register uploaded object key=wjhiayzlybr1kw2gibhmknc6g4y3vcxa.narinfo error="server returned 404: 404 page not found\n"18732026/09/23 09:37:41 OK 20241026095416_initial_model.sql (139.08ms)18742026/09/23 09:37:41 INFO Completed upload id=118752026/09/23 09:37:41 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18762026/09/23 09:37:41 INFO Completed upload id=218772026/09/23 09:37:41 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete18782026/09/23 09:37:41 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)18792026/09/23 09:37:41 INFO Completed upload id=318802026/09/23 09:37:41 INFO Upload complete. (193ms)1881=== NAME TestClientMultipleUploads1882 client_integration_test.go:369: Uploaded 3 paths in 271.30425ms18832026/09/23 09:37:41 OK 20251218171726_add_pins.sql (27.21ms)18842026/09/23 09:37:41 OK 20241026095416_initial_model.sql (139.46ms)18852026/09/23 09:37:41 OK 20260628120000_add_object_size_and_stats.sql (33.95ms)1886--- PASS: TestClientMultipleUploads (3.21s)18872026/09/23 09:37:41 OK 20251210153512_drop_unused_gin_index.sql (1.71ms)1888=== CONT TestClientErrorHandling/ServerNotAvailable18892026/09/23 09:37:41 OK 20251218171726_add_pins.sql (16.58ms)18902026/09/23 09:37:41 OK 20260905000000_add_claims.sql (19.21ms)18912026/09/23 09:37:41 OK 20260920000000_drop_claims.sql (15.79ms)18922026/09/23 09:37:41 goose: successfully migrated database to version: 2026092000000018932026-09-23 09:37:41.381 UTC [27625] ERROR: relation "goose_db_version" does not exist at character 3618942026-09-23 09:37:41.381 UTC [27625] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18952026/09/23 09:37:41 OK 20260628120000_add_object_size_and_stats.sql (20.06ms)18962026/09/23 09:37:41 OK 1_commit_pending_closure.sql (6.1ms)18972026/09/23 09:37:41 OK 2_object_stats_trigger.sql (34.17ms)18982026/09/23 09:37:41 goose: up to current file version: 218992026/09/23 09:37:41 OK 20260905000000_add_claims.sql (43.81ms)19002026/09/23 09:37:41 OK 20260920000000_drop_claims.sql (20.41ms)19012026/09/23 09:37:41 goose: successfully migrated database to version: 2026092000000019022026/09/23 09:37:41 OK 1_commit_pending_closure.sql (1.6ms)19032026/09/23 09:37:41 OK 2_object_stats_trigger.sql (681.58µs)19042026/09/23 09:37:41 goose: up to current file version: 219052026/09/23 09:37:41 INFO Starting HTTP server address=/nix/var/nix/builds/nix-26666-911885599/TestProxyHeadersOnlyTrustedOnSocket1151786772/001/proxy.sock19062026/09/23 09:37:41 INFO Starting HTTP server address=127.0.0.1:5457819072026/09/23 09:37:41 WARN mTLS auth: subject not in bound subjects subject="CN=someone"19082026/09/23 09:37:41 INFO Shutdown signal received, draining in-flight requests timeout=10s1909--- PASS: TestProxyHeadersOnlyTrustedOnSocket (1.70s)1910=== CONT TestClientErrorHandling/InvalidAuthToken19112026/09/23 09:37:41 OK 20241026095416_initial_model.sql (89.46ms)19122026/09/23 09:37:41 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)19132026/09/23 09:37:41 OK 20251218171726_add_pins.sql (14.33ms)19142026/09/23 09:37:41 OK 20260628120000_add_object_size_and_stats.sql (16.74ms)19152026/09/23 09:37:41 OK 20260905000000_add_claims.sql (21.61ms)19162026/09/23 09:37:41 OK 20260920000000_drop_claims.sql (10.19ms)19172026/09/23 09:37:41 goose: successfully migrated database to version: 2026092000000019182026/09/23 09:37:41 OK 1_commit_pending_closure.sql (1.57ms)19192026/09/23 09:37:41 OK 2_object_stats_trigger.sql (657µs)19202026/09/23 09:37:41 goose: up to current file version: 219212026/09/23 09:37:41 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1922--- PASS: TestReadRedirectUsesPublicS3URL (1.78s)1923=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19242026/09/23 09:37:41 INFO Received uploads request method=POST path=/19252026/09/23 09:37:41 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=192.210853ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19262026-09-23 09:37:41.876 UTC [27654] ERROR: relation "goose_db_version" does not exist at character 3619272026-09-23 09:37:41.876 UTC [27654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19282026-09-23 09:37:41.876 UTC [27653] ERROR: relation "goose_db_version" does not exist at character 3619292026-09-23 09:37:41.876 UTC [27653] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19302026/09/23 09:37:41 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=380.287565ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19312026/09/23 09:37:42 OK 20241026095416_initial_model.sql (123.89ms)19322026/09/23 09:37:42 OK 20251210153512_drop_unused_gin_index.sql (10.06ms)19332026/09/23 09:37:42 OK 20241026095416_initial_model.sql (133.97ms)19342026/09/23 09:37:42 OK 20251210153512_drop_unused_gin_index.sql (12.36ms)19352026/09/23 09:37:42 OK 20251218171726_add_pins.sql (34.19ms)19362026/09/23 09:37:42 OK 20251218171726_add_pins.sql (29.84ms)19372026-09-23 09:37:42.106 UTC [27662] ERROR: relation "goose_db_version" does not exist at character 3619382026-09-23 09:37:42.106 UTC [27662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19392026/09/23 09:37:42 OK 20260628120000_add_object_size_and_stats.sql (31.61ms)19402026/09/23 09:37:42 OK 20260628120000_add_object_size_and_stats.sql (28.48ms)19412026/09/23 09:37:42 INFO Received uploads request method=POST path=/api/pending_closures19422026/09/23 09:37:42 OK 20260905000000_add_claims.sql (53.09ms)19432026/09/23 09:37:42 OK 20260905000000_add_claims.sql (55.26ms)19442026/09/23 09:37:42 OK 20260920000000_drop_claims.sql (34.01ms)19452026/09/23 09:37:42 goose: successfully migrated database to version: 2026092000000019462026/09/23 09:37:42 OK 20260920000000_drop_claims.sql (41.24ms)19472026/09/23 09:37:42 goose: successfully migrated database to version: 2026092000000019482026/09/23 09:37:42 OK 1_commit_pending_closure.sql (2.36ms)19492026/09/23 09:37:42 OK 1_commit_pending_closure.sql (2.48ms)19502026/09/23 09:37:42 OK 2_object_stats_trigger.sql (600.5µs)19512026/09/23 09:37:42 goose: up to current file version: 219522026/09/23 09:37:42 OK 2_object_stats_trigger.sql (719.17µs)19532026/09/23 09:37:42 goose: up to current file version: 219542026/09/23 09:37:42 INFO Received uploads request method=POST path=/api/pending_closures19552026/09/23 09:37:42 OK 20241026095416_initial_model.sql (100.43ms)19562026/09/23 09:37:42 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=858.41029ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19572026/09/23 09:37:42 OK 20251210153512_drop_unused_gin_index.sql (9.68ms)19582026/09/23 09:37:42 OK 20251218171726_add_pins.sql (11.36ms)19592026/09/23 09:37:42 OK 20260628120000_add_object_size_and_stats.sql (31.29ms)19602026-09-23 09:37:42.372 UTC [27666] ERROR: relation "goose_db_version" does not exist at character 3619612026-09-23 09:37:42.372 UTC [27666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19622026/09/23 09:37:42 OK 20260905000000_add_claims.sql (45.18ms)19632026/09/23 09:37:42 OK 20260920000000_drop_claims.sql (33.26ms)19642026/09/23 09:37:42 goose: successfully migrated database to version: 2026092000000019652026/09/23 09:37:42 OK 1_commit_pending_closure.sql (2.17ms)19662026/09/23 09:37:42 OK 2_object_stats_trigger.sql (709.38µs)19672026/09/23 09:37:42 goose: up to current file version: 21968--- PASS: TestResurrectedObjectNotDeleted (2.13s)1969=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19702026/09/23 09:37:42 INFO Received request for more parts method=POST path=/1971=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19722026/09/23 09:37:42 INFO Received complete multipart upload request method=POST path=/1973=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19742026/09/23 09:37:42 INFO Received uploads request method=POST path=/1975=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19762026/09/23 09:37:42 INFO Received complete multipart upload request method=POST path=/1977=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19782026/09/23 09:37:42 INFO Received request for more parts method=POST path=/1979=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19802026/09/23 09:37:42 INFO Received uploads request method=POST path=/1981--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1982 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1983 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1984 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1985 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1986=== CONT TestIsValidUploadKey/narinfo1987=== 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=== CONT TestCacheConfigHandler/full_config,_no_issuer2009--- PASS: TestIsValidUploadKey (0.00s)2010 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2011 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2012 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2013 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2014 --- PASS: TestIsValidUploadKey/absolute (0.00s)2015 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2016 --- PASS: TestIsValidUploadKey/traversal (0.00s)2017 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2018 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2019 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2020 --- PASS: TestIsValidUploadKey/index.html (0.00s)2021 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2022 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2023 --- PASS: TestIsValidUploadKey/realisation (0.00s)2024 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2025 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2026 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2027 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2028 --- PASS: TestIsValidUploadKey/build_log (0.00s)2029 --- PASS: TestIsValidUploadKey/listing (0.00s)2030 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2031 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2032=== CONT TestCacheConfigHandler/no_signing_keys2033=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2034=== CONT TestCacheConfigHandler/no_cache_url_configured2035--- PASS: TestCacheConfigHandler (0.00s)2036 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2037 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2038 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2039 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2040=== CONT TestService_RequireScope_OIDC/builder_may_write2041=== CONT TestService_RequireScope_OIDC/static_token_may_admin2042=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2043=== CONT TestService_RequireScope_OIDC/writer_implies_read2044=== CONT TestService_RequireScope_OIDC/reader_may_read2045=== CONT TestService_RequireScope_OIDC/static_token_may_write2046=== CONT TestService_RequireScope_OIDC/ops_may_not_write2047=== CONT TestService_RequireScope_OIDC/ops_may_admin2048=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2049=== CONT TestService_RequireScope_OIDC/reader_may_not_write2050=== CONT TestResolveDBConnectionString/flag_wins2051=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2052=== CONT TestResolveDBConnectionString/nothing_configured2053=== CONT TestResolveDBConnectionString/missing_file_is_an_error2054=== CONT TestResolveDBConnectionString/file_when_flag_empty2055=== CONT TestServerTLSConfig/no_client_CA2056=== CONT TestServerTLSConfig/not_a_PEM_file2057--- PASS: TestResolveDBConnectionString (0.02s)2058 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2059 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2060 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2061 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2062 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2063--- PASS: TestService_RequireScope_OIDC (2.53s)2064 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2065 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2066 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2067 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2068 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2069 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2070 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2071 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2072 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2073 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2074=== CONT TestServerTLSConfig/missing_CA_file2075=== CONT TestIsValidCachePath/narinfo2076--- PASS: TestServerTLSConfig (0.00s)2077 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2078 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)2079 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2080=== CONT TestIsValidCachePath/index.html2081=== CONT TestIsValidCachePath/short_hash2082=== CONT TestIsValidCachePath/wrong_extension2083=== CONT TestIsValidCachePath/leading_slash2084=== CONT TestIsValidCachePath/empty2085=== CONT TestIsValidCachePath/random_path2086=== CONT TestIsValidCachePath/invalid_char_u2087=== CONT TestIsValidCachePath/invalid_char_e2088=== CONT TestIsValidCachePath/traversal_in_middle2089=== CONT TestIsValidCachePath/traversal_parent2090=== CONT TestIsValidCachePath/nar_uncompressed2091=== CONT TestIsValidCachePath/nix-cache-info2092=== CONT TestIsValidCachePath/realisation2093=== CONT TestIsValidCachePath/log2094=== CONT TestIsValidCachePath/ls2095=== CONT TestIsValidCachePath/nar_xz2096=== CONT TestIsValidCachePath/nar_bz22097=== CONT TestIsValidCachePath/nar_zst2098=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2099--- PASS: TestIsValidCachePath (0.00s)2100 --- PASS: TestIsValidCachePath/narinfo (0.00s)2101 --- PASS: TestIsValidCachePath/index.html (0.00s)2102 --- PASS: TestIsValidCachePath/short_hash (0.00s)2103 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2104 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2105 --- PASS: TestIsValidCachePath/empty (0.00s)2106 --- PASS: TestIsValidCachePath/random_path (0.00s)2107 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2108 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2109 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2110 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2111 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2112 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2113 --- PASS: TestIsValidCachePath/realisation (0.00s)2114 --- PASS: TestIsValidCachePath/log (0.00s)2115 --- PASS: TestIsValidCachePath/ls (0.00s)2116 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2117 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2118 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2119 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2120=== CONT TestParseSingleRange/none2121=== CONT TestParseSingleRange/open-ended2122=== CONT TestParseSingleRange/start_far_past_EOF2123=== CONT TestParseSingleRange/start_past_EOF2124=== CONT TestParseSingleRange/single_byte2125=== CONT TestParseSingleRange/suffix_exceeds_size2126=== CONT TestParseSingleRange/suffix2127=== CONT TestParseSingleRange/end_clamped_to_size2128=== CONT TestParseSingleRange/malformed_both_empty2129=== CONT TestParseSingleRange/closed2130=== CONT TestParseSingleRange/malformed_end_before_start2131=== CONT TestParseSingleRange/multi-range_ignored2132=== CONT TestParseSingleRange/malformed_no_dash2133=== CONT TestParseSingleRange/unknown_unit2134--- PASS: TestParseSingleRange (0.00s)2135 --- PASS: TestParseSingleRange/none (0.00s)2136 --- PASS: TestParseSingleRange/open-ended (0.00s)2137 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2138 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2139 --- PASS: TestParseSingleRange/single_byte (0.00s)2140 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2141 --- PASS: TestParseSingleRange/suffix (0.00s)2142 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2143 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2144 --- PASS: TestParseSingleRange/closed (0.00s)2145 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2146 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2147 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2148 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2149=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2150=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21512026/09/23 09:37:42 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]2152=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2153=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21542026/09/23 09:37:42 WARN Authentication failed token_preview=eyJhbGciOi...5VVKHBv_AA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]21552026/09/23 09:37:42 OK 20241026095416_initial_model.sql (205.75ms)2156--- PASS: TestService_AuthMiddleware_OIDC (2.55s)2157 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2158 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2159 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2160 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)21612026/09/23 09:37:42 OK 20251210153512_drop_unused_gin_index.sql (13.17ms)21622026/09/23 09:37:42 OK 20251218171726_add_pins.sql (7.75ms)21632026/09/23 09:37:42 OK 20260628120000_add_object_size_and_stats.sql (26.27ms)21642026/09/23 09:37:42 OK 20260905000000_add_claims.sql (50ms)21652026/09/23 09:37:42 OK 20260920000000_drop_claims.sql (26.11ms)21662026/09/23 09:37:42 goose: successfully migrated database to version: 2026092000000021672026/09/23 09:37:42 OK 1_commit_pending_closure.sql (2.03ms)21682026/09/23 09:37:42 OK 2_object_stats_trigger.sql (864.13µs)21692026/09/23 09:37:42 goose: up to current file version: 221702026-09-23 09:37:42.822 UTC [27668] ERROR: relation "goose_db_version" does not exist at character 3621712026-09-23 09:37:42.822 UTC [27668] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2172--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)2173 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)2174 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)2175 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.29s)21762026/09/23 09:37:43 OK 20241026095416_initial_model.sql (116.61ms)21772026/09/23 09:37:43 OK 20251210153512_drop_unused_gin_index.sql (11.95ms)21782026/09/23 09:37:43 OK 20251218171726_add_pins.sql (33.62ms)21792026/09/23 09:37:43 OK 20260628120000_add_object_size_and_stats.sql (24.51ms)21802026/09/23 09:37:43 OK 20260905000000_add_claims.sql (55.59ms)21812026/09/23 09:37:43 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.53711801s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21822026/09/23 09:37:43 OK 20260920000000_drop_claims.sql (26.95ms)21832026/09/23 09:37:43 goose: successfully migrated database to version: 2026092000000021842026/09/23 09:37:43 OK 1_commit_pending_closure.sql (2.65ms)21852026/09/23 09:37:43 OK 2_object_stats_trigger.sql (668.13µs)21862026/09/23 09:37:43 goose: up to current file version: 22187=== NAME TestClientIntegration2188 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-26666-911885599/TestClientIntegration4275706679/002/store/l3vs330s52c7bv5rxl5v5ghn25sq3l0y-test-file.txt2189--- PASS: TestObjectStatsTrigger (2.33s)2190=== NAME TestOrphanedObjectsGC2191 orphaned_objects_gc_test.go:290: GC Test Summary:2192 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2193 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2194 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2195 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2196 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2197--- PASS: TestOrphanedObjectsGC (2.54s)21982026/09/23 09:37:43 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21992026/09/23 09:37:43 INFO Received uploads request method=POST path=/api/pending_closures22002026/09/23 09:37:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22012026/09/23 09:37:43 INFO Uploading l3vs330s52c7bv5rxl5v5ghn25sq3l0y-test-file.txt (152B)22022026/09/23 09:37:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign22032026/09/23 09:37:43 WARN Failed to register uploaded object key=l3vs330s52c7bv5rxl5v5ghn25sq3l0y.ls error="server returned 404: 404 page not found\n"22042026/09/23 09:37:43 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"22052026/09/23 09:37:43 INFO Signed narinfos id=1 count=122062026/09/23 09:37:43 INFO Uploading 1 narinfos22072026/09/23 09:37:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22082026/09/23 09:37:43 WARN Failed to register uploaded object key=l3vs330s52c7bv5rxl5v5ghn25sq3l0y.narinfo error="server returned 404: 404 page not found\n"22092026/09/23 09:37:43 INFO Completed upload id=122102026/09/23 09:37:43 INFO Upload complete. (172ms)22112026/09/23 09:37:43 INFO All 1 paths already cached2212=== NAME TestClientIntegration2213 client_integration_test.go:312: Retrieved narinfo from S3:2214 StorePath: /nix/var/nix/builds/nix-26666-911885599/TestClientIntegration4275706679/002/store/l3vs330s52c7bv5rxl5v5ghn25sq3l0y-test-file.txt2215 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2216 Compression: zstd2217 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12218 NarSize: 1522219 References: 2220 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12221 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2222 client_integration_test.go:313: Decompressed .ls content (64 bytes):2223 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2224 client_integration_test.go:316: Testing garbage collection...22252026/09/23 09:37:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22262026/09/23 09:37:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures22272026/09/23 09:37:43 INFO Garbage collection started22282026/09/23 09:37:43 INFO Aborted multipart uploads count=022292026/09/23 09:37:43 WARN Force mode enabled - objects will be deleted immediately without grace period22302026/09/23 09:37:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZWUxMGUxN2QtYzhmNC00ZjlmLWEyNzktZGRiZmRjM2QwY2I4LmEwYmE5NTZkLTRkZGEtNDUxNC05NmIwLWY1NzliNjMzMWMwNXgxNzkwMTU2MjYyMTgzNjQxMDAw parts=122231--- PASS: TestRedundantMultipartUpload (3.43s)22322026/09/23 09:37:43 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22332026/09/23 09:37:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22342026/09/23 09:37:44 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22352026/09/23 09:37:44 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=022362026/09/23 09:37:44 INFO Vacuumed table table=pending_closures22372026/09/23 09:37:44 INFO Vacuumed table table=pending_objects22382026/09/23 09:37:44 INFO Vacuumed table table=multipart_uploads22392026/09/23 09:37:44 INFO Vacuumed table table=closures22402026/09/23 09:37:44 INFO Vacuumed table table=objects22412026/09/23 09:37:44 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22422026/09/23 09:37:44 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=200.266818ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2243=== NAME TestOrphanedObjectsGCStressTest2244 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains22452026/09/23 09:37:45 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=420.718814ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2246 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion2247 orphaned_objects_gc_test.go:509: Stress test completed successfully:2248 orphaned_objects_gc_test.go:510: - Active objects preserved: 202249 orphaned_objects_gc_test.go:511: - Objects deleted: 2102250 orphaned_objects_gc_test.go:512: - Total GC'd: 2102251--- PASS: TestOrphanedObjectsGCStressTest (5.26s)22522026/09/23 09:37:45 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=786.784595ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22532026/09/23 09:37:45 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02254=== NAME TestClientIntegration2255 client_integration_test.go:323: Objects in database after GC:2256 client_integration_test.go:323: Successfully deleted all objects with GC --force2257--- PASS: TestClientIntegration (4.92s)22582026/09/23 09:37:46 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.610407015s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22592026/09/23 09:37:47 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 127.0.0.1:19999: connect: connection refused"22602026/09/23 09:37:47 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22612026/09/23 09:37:47 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=190.250733ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22622026/09/23 09:37:48 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=423.921268ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22632026/09/23 09:37:48 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=871.166256ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22642026/09/23 09:37:49 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.682460753s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2265--- PASS: TestClientErrorHandling (0.00s)2266 --- PASS: TestClientErrorHandling/InvalidStorePath (2.40s)2267 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.61s)2268 --- PASS: TestClientErrorHandling/ServerNotAvailable (9.85s)2269PASS22702026-09-23 09:37:51.299 UTC [27071] LOG: received smart shutdown request22712026-09-23 09:37:51.302 UTC [27071] LOG: background worker "logical replication launcher" (PID 27081) exited with exit code 122722026-09-23 09:37:51.317 UTC [27076] LOG: shutting down22732026-09-23 09:37:51.317 UTC [27076] LOG: checkpoint starting: shutdown immediate22742026-09-23 09:37:55.978 UTC [27076] LOG: checkpoint complete: wrote 13417 buffers (81.9%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 16 recycled; write=1.877 s, sync=2.758 s, total=4.662 s; sync files=19406, longest=0.086 s, average=0.001 s; distance=269402 kB, estimate=269402 kB; lsn=0/11EA3808, redo lsn=0/11EA380822752026-09-23 09:37:55.991 UTC [27071] LOG: database system is shut down2276Running OIDC tests...2277=== RUN TestAudienceForIssuer2278=== PAUSE TestAudienceForIssuer2279=== RUN TestGlobMatch2280=== PAUSE TestGlobMatch2281=== RUN TestValidateToken_ValidToken2282=== PAUSE TestValidateToken_ValidToken2283=== RUN TestValidateToken_WrongAudience2284=== PAUSE TestValidateToken_WrongAudience2285=== RUN TestValidateToken_Expired2286=== PAUSE TestValidateToken_Expired2287=== RUN TestValidateToken_BoundClaimsMismatch2288=== PAUSE TestValidateToken_BoundClaimsMismatch2289=== RUN TestValidateToken_BoundSubjectMismatch2290=== PAUSE TestValidateToken_BoundSubjectMismatch2291=== RUN TestValidateToken_MultipleProviders2292=== PAUSE TestValidateToken_MultipleProviders2293=== RUN TestValidateToken_NoMatchingProvider2294=== PAUSE TestValidateToken_NoMatchingProvider2295=== RUN TestValidateToken_KubernetesServiceAccount2296=== PAUSE TestValidateToken_KubernetesServiceAccount2297=== RUN TestNewValidator_KubernetesRequiresCA2298=== PAUSE TestNewValidator_KubernetesRequiresCA2299=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2300=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2301=== RUN TestPins_ReservedForMatchingRule2302=== PAUSE TestPins_ReservedForMatchingRule2303=== RUN TestPins_TopLevelShorthand2304=== PAUSE TestPins_TopLevelShorthand2305=== RUN TestPins_ConfigValidation2306=== PAUSE TestPins_ConfigValidation2307=== RUN TestScopes_LegacyProviderDefaultsToWrite2308=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2309=== RUN TestScopes_Rules2310=== PAUSE TestScopes_Rules2311=== RUN TestScopes_ConfigValidation2312=== PAUSE TestScopes_ConfigValidation2313=== CONT TestAudienceForIssuer2314--- PASS: TestAudienceForIssuer (0.00s)2315=== CONT TestValidateToken_Expired2316=== CONT TestValidateToken_BoundClaimsMismatch2317=== CONT TestValidateToken_KubernetesServiceAccount2318=== CONT TestValidateToken_ValidToken2319=== CONT TestPins_ConfigValidation2320=== CONT TestValidateToken_MultipleProviders2321--- PASS: TestPins_ConfigValidation (0.00s)2322=== CONT TestScopes_ConfigValidation2323--- PASS: TestScopes_ConfigValidation (0.00s)2324=== CONT TestScopes_Rules2325=== CONT TestValidateToken_BoundSubjectMismatch2326=== CONT TestValidateToken_NoMatchingProvider2327=== CONT TestScopes_LegacyProviderDefaultsToWrite2328=== CONT TestValidateToken_WrongAudience23292026/09/23 09:37:59 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:546402330--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)2331=== CONT TestGlobMatch2332=== RUN TestGlobMatch/foo_foo2333=== PAUSE TestGlobMatch/foo_foo2334=== RUN TestGlobMatch/foo_bar2335=== PAUSE TestGlobMatch/foo_bar2336=== RUN TestGlobMatch/*_2337=== PAUSE TestGlobMatch/*_2338=== RUN TestGlobMatch/*_anything2339=== PAUSE TestGlobMatch/*_anything2340=== RUN TestGlobMatch/foo*_foo2341=== PAUSE TestGlobMatch/foo*_foo2342=== RUN TestGlobMatch/foo*_foobar2343=== PAUSE TestGlobMatch/foo*_foobar2344=== RUN TestGlobMatch/foo*_bar2345=== PAUSE TestGlobMatch/foo*_bar2346=== RUN TestGlobMatch/*bar_bar2347=== PAUSE TestGlobMatch/*bar_bar2348=== RUN TestGlobMatch/*bar_foobar2349=== PAUSE TestGlobMatch/*bar_foobar2350=== RUN TestGlobMatch/*bar_foo2351=== PAUSE TestGlobMatch/*bar_foo2352=== RUN TestGlobMatch/foo*bar_foobar2353=== PAUSE TestGlobMatch/foo*bar_foobar2354=== RUN TestGlobMatch/foo*bar_foo123bar2355=== PAUSE TestGlobMatch/foo*bar_foo123bar2356=== RUN TestGlobMatch/foo*bar_foobarbaz2357=== PAUSE TestGlobMatch/foo*bar_foobarbaz2358=== RUN TestGlobMatch/*/*_foo/bar2359=== PAUSE TestGlobMatch/*/*_foo/bar2360=== RUN TestGlobMatch/*/*_foo2361=== PAUSE TestGlobMatch/*/*_foo2362=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2363=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2364=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02365=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02366=== RUN TestGlobMatch/refs/*/main_refs/heads/main2367=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2368=== RUN TestGlobMatch/fo?_foo2369=== PAUSE TestGlobMatch/fo?_foo2370=== RUN TestGlobMatch/fo?_fo2371=== PAUSE TestGlobMatch/fo?_fo2372=== RUN TestGlobMatch/fo?_fooo2373=== PAUSE TestGlobMatch/fo?_fooo2374=== RUN TestGlobMatch/?oo_foo2375=== PAUSE TestGlobMatch/?oo_foo2376=== RUN TestGlobMatch/?oo_boo2377=== PAUSE TestGlobMatch/?oo_boo2378=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2379=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2380=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2381=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2382=== CONT TestPins_TopLevelShorthand23832026/09/23 09:37:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54643/oidc23842026/09/23 09:37:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54642/oidc2385--- PASS: TestValidateToken_ValidToken (0.18s)2386=== CONT TestPins_ReservedForMatchingRule23872026/09/23 09:37:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54646/oidc23882026/09/23 09:37:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54648/oidc2389--- PASS: TestValidateToken_BoundSubjectMismatch (0.19s)2390=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2391--- PASS: TestValidateToken_Expired (0.19s)2392=== CONT TestNewValidator_KubernetesRequiresCA2393--- PASS: TestScopes_Rules (0.19s)2394=== CONT TestGlobMatch/foo_foo2395=== CONT TestGlobMatch/*/*_foo/bar2396=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2397=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2398=== CONT TestGlobMatch/?oo_boo2399=== CONT TestGlobMatch/?oo_foo2400=== CONT TestGlobMatch/fo?_fooo2401=== CONT TestGlobMatch/fo?_fo2402=== CONT TestGlobMatch/fo?_foo2403=== CONT TestGlobMatch/refs/*/main_refs/heads/main2404=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02405=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2406=== CONT TestGlobMatch/*/*_foo2407=== CONT TestGlobMatch/*bar_bar2408=== CONT TestGlobMatch/foo*bar_foobarbaz2409=== CONT TestGlobMatch/foo*bar_foo123bar2410=== CONT TestGlobMatch/foo*bar_foobar2411=== CONT TestGlobMatch/*bar_foo2412=== CONT TestGlobMatch/*bar_foobar2413=== CONT TestGlobMatch/foo*_foo2414=== CONT TestGlobMatch/foo*_bar2415=== CONT TestGlobMatch/foo*_foobar2416=== CONT TestGlobMatch/*_2417=== CONT TestGlobMatch/*_anything2418=== CONT TestGlobMatch/foo_bar2419--- PASS: TestGlobMatch (0.00s)2420 --- PASS: TestGlobMatch/foo_foo (0.00s)2421 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2422 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2423 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2424 --- PASS: TestGlobMatch/?oo_boo (0.00s)2425 --- PASS: TestGlobMatch/?oo_foo (0.00s)2426 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2427 --- PASS: TestGlobMatch/fo?_fo (0.00s)2428 --- PASS: TestGlobMatch/fo?_foo (0.00s)2429 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2430 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2431 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2432 --- PASS: TestGlobMatch/*/*_foo (0.00s)2433 --- PASS: TestGlobMatch/*bar_bar (0.00s)2434 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2435 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2436 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2437 --- PASS: TestGlobMatch/*bar_foo (0.00s)2438 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2439 --- PASS: TestGlobMatch/foo*_foo (0.00s)2440 --- PASS: TestGlobMatch/foo*_bar (0.00s)2441 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2442 --- PASS: TestGlobMatch/*_ (0.00s)2443 --- PASS: TestGlobMatch/*_anything (0.00s)2444 --- PASS: TestGlobMatch/foo_bar (0.00s)24452026/09/23 09:37:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54650/oidc2446--- PASS: TestValidateToken_WrongAudience (0.35s)24472026/09/23 09:38:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54653/oidc2448--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.38s)24492026/09/23 09:38:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54656/oidc2450--- PASS: TestPins_TopLevelShorthand (0.32s)24512026/09/23 09:38:00 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324522026/09/23 09:38:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54658/oidc2453--- PASS: TestValidateToken_BoundClaimsMismatch (0.50s)2454--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.31s)24552026/09/23 09:38:00 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54655/oidc2456--- PASS: TestValidateToken_NoMatchingProvider (0.55s)24572026/09/23 09:38:00 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54652/oidc24582026/09/23 09:38:00 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:54664/oidc24592026/09/23 09:38:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54667/oidc2460--- PASS: TestValidateToken_MultipleProviders (0.66s)2461--- PASS: TestPins_ReservedForMatchingRule (0.48s)24622026/09/23 09:38:00 http: TLS handshake error from 127.0.0.1:54670: remote error: tls: bad certificate2463--- PASS: TestNewValidator_KubernetesRequiresCA (0.82s)2464PASS2465Running hook tests...2466=== RUN TestSendPathsEmpty2467=== PAUSE TestSendPathsEmpty2468=== RUN TestQueueEnqueueAndFetch2469=== PAUSE TestQueueEnqueueAndFetch2470=== RUN TestQueueDeduplication2471=== PAUSE TestQueueDeduplication2472=== RUN TestQueueRemove2473=== PAUSE TestQueueRemove2474=== RUN TestQueueFetchBatchLimit2475=== PAUSE TestQueueFetchBatchLimit2476=== RUN TestQueueRetryMovesToBack2477=== PAUSE TestQueueRetryMovesToBack2478=== RUN TestQueueFetchRemoveLifecycle2479=== PAUSE TestQueueFetchRemoveLifecycle2480=== RUN TestQueueConcurrentWriters2481=== PAUSE TestQueueConcurrentWriters2482=== RUN TestQueueRemoveLargeClosure2483=== PAUSE TestQueueRemoveLargeClosure2484=== RUN TestServerClientIntegration2485=== PAUSE TestServerClientIntegration2486=== RUN TestServerQueueError2487=== PAUSE TestServerQueueError2488=== RUN TestGetListenerSocketActivation2489 server_test.go:210: === RUN TestGetListenerSocketActivation2490 --- PASS: TestGetListenerSocketActivation (0.00s)2491 PASS2492 2493--- PASS: TestGetListenerSocketActivation (0.01s)2494=== RUN TestDrainIsolatesPoisonPath2495=== PAUSE TestDrainIsolatesPoisonPath2496=== RUN TestRunNotBlockedByPoisonHead2497=== PAUSE TestRunNotBlockedByPoisonHead2498=== RUN TestDrainGivesUpWhenServerDown2499=== PAUSE TestDrainGivesUpWhenServerDown2500=== RUN TestFailedPathPrunedByLaterClosure2501=== PAUSE TestFailedPathPrunedByLaterClosure2502=== RUN TestWorkerUploadsAndRemoves2503=== PAUSE TestWorkerUploadsAndRemoves2504=== RUN TestWorkerSkipsGCdPaths2505=== PAUSE TestWorkerSkipsGCdPaths2506=== RUN TestWorkerPrunesClosureDeps2507=== PAUSE TestWorkerPrunesClosureDeps2508=== RUN TestDrainTimeout2509=== PAUSE TestDrainTimeout2510=== CONT TestSendPathsEmpty2511=== CONT TestServerQueueError2512--- PASS: TestSendPathsEmpty (0.00s)2513=== CONT TestWorkerSkipsGCdPaths2514=== CONT TestQueueRetryMovesToBack2515=== CONT TestServerClientIntegration2516=== CONT TestQueueRemoveLargeClosure2517=== CONT TestQueueConcurrentWriters2518=== CONT TestQueueFetchRemoveLifecycle2519=== CONT TestWorkerUploadsAndRemoves25202026/09/23 09:38:01 ERROR Failed to queue paths error="permission denied" count=12521=== CONT TestDrainTimeout2522=== CONT TestWorkerPrunesClosureDeps2523=== CONT TestFailedPathPrunedByLaterClosure2524--- PASS: TestServerClientIntegration (0.00s)2525--- PASS: TestServerQueueError (0.00s)2526=== CONT TestDrainGivesUpWhenServerDown25272026/09/23 09:38:01 INFO Uploading batch count=225282026/09/23 09:38:01 INFO Uploading batch count=125292026/09/23 09:38:01 ERROR Upload failed error="upload failed" count=125302026/09/23 09:38:01 INFO Upload queue status pending=225312026/09/23 09:38:01 INFO Uploading batch count=12532--- PASS: TestQueueRetryMovesToBack (0.01s)2533=== CONT TestQueueRemove25342026/09/23 09:38:01 INFO Upload queue status pending=225352026/09/23 09:38:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-26666-911885599/TestWorkerSkipsGCdPaths2289493002/002/nonexistent25362026/09/23 09:38:01 INFO Uploading batch count=12537--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2538=== CONT TestQueueFetchBatchLimit25392026/09/23 09:38:01 INFO Uploading batch count=125402026/09/23 09:38:01 INFO Uploading batch count=125412026/09/23 09:38:01 INFO Upload queue status pending=225422026/09/23 09:38:01 INFO Uploading batch count=225432026/09/23 09:38:01 INFO Uploading batch count=225442026/09/23 09:38:01 ERROR Upload failed error="upload failed" count=225452026/09/23 09:38:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26666-911885599/TestDrainGivesUpWhenServerDown1480865846/002/a25462026/09/23 09:38:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26666-911885599/TestDrainGivesUpWhenServerDown1480865846/002/b25472026/09/23 09:38:01 INFO Uploading batch count=225482026/09/23 09:38:01 ERROR Upload failed error="upload failed" count=225492026/09/23 09:38:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26666-911885599/TestDrainGivesUpWhenServerDown1480865846/002/c25502026/09/23 09:38:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26666-911885599/TestDrainGivesUpWhenServerDown1480865846/002/d25512026/09/23 09:38:01 INFO Uploading batch count=225522026/09/23 09:38:01 ERROR Upload failed error="upload failed" count=225532026/09/23 09:38:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26666-911885599/TestDrainGivesUpWhenServerDown1480865846/002/e2554--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2555=== CONT TestRunNotBlockedByPoisonHead25562026/09/23 09:38:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26666-911885599/TestDrainGivesUpWhenServerDown1480865846/002/f25572026/09/23 09:38:01 ERROR Drain finished with paths left in queue remaining=102558--- PASS: TestQueueFetchBatchLimit (0.00s)2559=== CONT TestQueueDeduplication2560--- PASS: TestQueueRemove (0.00s)2561=== CONT TestQueueEnqueueAndFetch2562--- PASS: TestDrainGivesUpWhenServerDown (0.01s)25632026/09/23 09:38:01 INFO Upload queue status pending=325642026/09/23 09:38:01 INFO Uploading batch count=125652026/09/23 09:38:01 ERROR Upload failed error="upload failed" count=12566=== CONT TestDrainIsolatesPoisonPath2567--- PASS: TestQueueDeduplication (0.00s)2568--- PASS: TestQueueEnqueueAndFetch (0.00s)25692026/09/23 09:38:01 INFO Uploading batch count=425702026/09/23 09:38:01 ERROR Upload failed error="upload failed" count=425712026/09/23 09:38:01 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26666-911885599/TestDrainIsolatesPoisonPath3904065341/002/bbb25722026/09/23 09:38:01 INFO Uploading batch count=125732026/09/23 09:38:01 ERROR Upload failed error="upload failed" count=125742026/09/23 09:38:01 INFO Uploading batch count=125752026/09/23 09:38:01 ERROR Upload failed error="upload failed" count=125762026/09/23 09:38:01 INFO Uploading batch count=125772026/09/23 09:38:01 ERROR Upload failed error="upload failed" count=125782026/09/23 09:38:01 ERROR Drain finished with paths left in queue remaining=12579--- PASS: TestDrainIsolatesPoisonPath (0.01s)2580--- PASS: TestWorkerPrunesClosureDeps (0.03s)2581--- PASS: TestWorkerSkipsGCdPaths (0.03s)2582--- PASS: TestWorkerUploadsAndRemoves (0.03s)2583--- PASS: TestQueueRemoveLargeClosure (0.07s)2584--- PASS: TestQueueConcurrentWriters (0.13s)25852026/09/23 09:38:01 ERROR Upload failed error="context deadline exceeded" count=225862026/09/23 09:38:01 ERROR Drain finished with paths left in queue remaining=42587--- PASS: TestDrainTimeout (0.21s)25882026/09/23 09:38:02 INFO Uploading batch count=125892026/09/23 09:38:02 INFO Uploading batch count=125902026/09/23 09:38:02 INFO Uploading batch count=125912026/09/23 09:38:02 ERROR Upload failed error="upload failed" count=125922026/09/23 09:38:02 INFO Uploading batch count=125932026/09/23 09:38:02 ERROR Upload failed error="upload failed" count=125942026/09/23 09:38:02 INFO Uploading batch count=125952026/09/23 09:38:02 ERROR Upload failed error="upload failed" count=125962026/09/23 09:38:02 INFO Uploading batch count=125972026/09/23 09:38:02 ERROR Upload failed error="upload failed" count=125982026/09/23 09:38:02 ERROR Drain finished with paths left in queue remaining=12599--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2600PASS