niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #294
· 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.14s)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 TestShellSplit96--- PASS: TestShellSplit (0.00s)97=== CONT TestScriptTokenEmptyCommand98--- PASS: TestScriptTokenEmptyCommand (0.00s)99=== CONT TestScriptTokenScriptFails100=== CONT TestDoWithRetry_BodyReplayedViaGetBody101=== CONT TestResolveStorePath102=== CONT TestEncodeNixBase32103=== RUN TestEncodeNixBase32/test_string_hash104=== PAUSE TestEncodeNixBase32/test_string_hash105=== RUN TestEncodeNixBase32/empty_input106=== PAUSE TestEncodeNixBase32/empty_input107=== CONT TestEncodeNixBase32/test_string_hash108=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess109=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1102026/10/01 07:38:45 WARN Rate limiter enabled after throttle name=server-test rate=5111=== CONT TestRateLimiterFeedback112=== RUN TestRateLimiterFeedback/429_enables_limiter113=== PAUSE TestRateLimiterFeedback/429_enables_limiter114=== RUN TestRateLimiterFeedback/503_enables_limiter115=== PAUSE TestRateLimiterFeedback/503_enables_limiter116=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter117=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter118=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter119=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter120=== CONT TestRateLimiterFeedback/429_enables_limiter121=== CONT TestPartSizeForNAR122=== CONT TestPathInfoCACompatibility123=== CONT TestParsePathInfoJSONMultiplePaths124=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths125=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths126=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths127=== RUN TestPartSizeForNAR/zero_stays_at_minimum128=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum129=== RUN TestPartSizeForNAR/small_stays_at_minimum130=== PAUSE TestPartSizeForNAR/small_stays_at_minimum131=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum132=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum133=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts134=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts135=== RUN TestPartSizeForNAR/1_TiB136=== PAUSE TestPartSizeForNAR/1_TiB137=== RUN TestPartSizeForNAR/5_TiB_S3_max_object138=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object139=== RUN TestPartSizeForNAR/capped_at_5_GiB140=== PAUSE TestPartSizeForNAR/capped_at_5_GiB141=== RUN TestPathInfoCACompatibility/null_ca_field142=== PAUSE TestPathInfoCACompatibility/null_ca_field143=== RUN TestPathInfoCACompatibility/old_string_format_-_text144=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text145=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive146=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive147=== RUN TestPathInfoCACompatibility/new_structured_format_-_text148=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text149=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method150=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method151=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths152=== CONT TestParsePathInfoJSON153=== RUN TestParsePathInfoJSON/Nix_format154=== PAUSE TestParsePathInfoJSON/Nix_format155=== RUN TestParsePathInfoJSON/Lix_format156=== CONT TestPathInfoHashCompatibility157=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)158=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)159=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon160=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon161=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI162=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI163=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512164=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512165=== PAUSE TestParsePathInfoJSON/Lix_format166=== RUN TestParsePathInfoJSON/empty_input167=== PAUSE TestParsePathInfoJSON/empty_input168=== RUN TestParsePathInfoJSON/whitespace_only169=== CONT TestGetStorePathHash170=== CONT TestConvertHashToNix32171=== RUN TestGetStorePathHash/valid_store_path172=== PAUSE TestGetStorePathHash/valid_store_path173=== PAUSE TestParsePathInfoJSON/whitespace_only174=== RUN TestParsePathInfoJSON/invalid_JSON175=== RUN TestConvertHashToNix32/SRI_format_to_Nix32176=== RUN TestGetStorePathHash/basename_without_hyphen_should_error177=== PAUSE TestParsePathInfoJSON/invalid_JSON178--- PASS: TestScriptTokenScriptFails (0.00s)179=== CONT TestEncodeNixBase32WithRealHash180=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32181=== RUN TestConvertHashToNix32/already_Nix32_format182=== PAUSE TestConvertHashToNix32/already_Nix32_format183=== RUN TestConvertHashToNix32/invalid_format184=== PAUSE TestConvertHashToNix32/invalid_format185--- PASS: TestEncodeNixBase32WithRealHash (0.00s)186=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error187=== CONT TestUploadMultipart_PartsInParallel188=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error189=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error190=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error1912026/10/01 07:38:45 WARN Rate limiter enabled after throttle name=server-test rate=5192=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error193=== CONT TestEncodeNixBase32/empty_input1942026/10/01 07:38:45 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:57447195=== CONT TestFilterOversizedClosures196--- PASS: TestEncodeNixBase32 (0.00s)197 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)198 --- PASS: TestEncodeNixBase32/empty_input (0.00s)199=== RUN TestFilterOversizedClosures/no_limit_keeps_everything200=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything201=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2022026/10/01 07:38:45 WARN Rate limiter enabled after throttle name=server-test rate=52032026/10/01 07:38:45 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57449204=== CONT TestRegisterUploadedObjectReusesConnections205=== CONT TestCaseHackSuffix206=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped207=== RUN TestFilterOversizedClosures/all_closures_skipped208=== PAUSE TestFilterOversizedClosures/all_closures_skipped2092026/10/01 07:38:45 WARN Rate limiter backed off name=server-test rate=5210=== CONT TestPartSizeForNAR/zero_stays_at_minimum211=== CONT TestDumpPathWriterError212=== CONT TestDumpPathSingleFile213=== CONT TestDumpPathMatchesNix2142026/10/01 07:38:45 WARN Rate limiter backed off name=server-test rate=52152026/10/01 07:38:45 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57449216--- PASS: TestDoServerRequestAttachesToken (0.01s)217--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)218=== CONT TestUploadMultipart_SupersededByPeer219=== RUN TestUploadMultipart_SupersededByPeer/exists220=== PAUSE TestUploadMultipart_SupersededByPeer/exists221=== RUN TestUploadMultipart_SupersededByPeer/missing222=== PAUSE TestUploadMultipart_SupersededByPeer/missing223=== CONT TestScriptTokenEmptyToken224--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)225=== CONT TestScriptTokenBadJSON226--- PASS: TestScriptTokenEmptyToken (0.07s)227=== CONT TestPathInfoCACompatibility/null_ca_field228=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths229=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method230=== CONT TestPathInfoCACompatibility/new_structured_format_-_text231=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive232=== CONT TestPathInfoCACompatibility/old_string_format_-_text233--- PASS: TestPathInfoCACompatibility (0.00s)234 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)235 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)236 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)237 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)238 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)239=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths240--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)241 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)242 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)243=== CONT TestPartSizeForNAR/1_TiB244=== CONT TestPartSizeForNAR/capped_at_5_GiB245=== CONT TestPartSizeForNAR/5_TiB_S3_max_object246=== CONT TestFileTokenReadsAndCaches247--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.09s)248=== CONT TestFileTokenMissing249=== CONT TestSetClientTLS250--- PASS: TestResolveStorePath (0.11s)251--- PASS: TestFileTokenMissing (0.03s)252=== CONT TestClientSignaturesByStorePath253--- PASS: TestClientSignaturesByStorePath (0.00s)254=== CONT TestStreamPushReportsSignatures255--- PASS: TestScriptTokenBadJSON (0.08s)256=== CONT TestStreamPushRequestLine2572026/10/01 07:38:45 ERROR Upload failed error=boom count=1258--- PASS: TestStreamPushReportsSignatures (0.00s)259=== CONT TestStreamPushGivesUpOnDeadServer2602026/10/01 07:38:45 ERROR Upload failed error="connection refused" count=202612026/10/01 07:38:45 ERROR Server seems unavailable, giving up on batch untried=172622026/10/01 07:38:45 ERROR Upload failed error=boom count=1263--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)264=== CONT TestStreamPushIsolatesFailures2652026/10/01 07:38:45 ERROR Upload failed error="bad path" count=3266--- PASS: TestStreamPushIsolatesFailures (0.00s)267=== CONT TestStreamPushBatchesUnderLoad268--- PASS: TestDumpPathSingleFile (0.11s)269=== CONT TestStreamPushReportsEveryPath270--- PASS: TestStreamPushReportsEveryPath (0.00s)271=== CONT TestShellSplitErrors272--- PASS: TestShellSplitErrors (0.00s)273=== CONT TestFileTokenEmpty274--- PASS: TestStreamPushRequestLine (0.01s)275=== CONT TestScriptTokenCachesUntilRefresh276--- PASS: TestFileTokenReadsAndCaches (0.08s)277=== CONT TestScriptTokenNoExpiryRerunsEveryCall278--- PASS: TestCaseHackSuffix (0.17s)279=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum280=== CONT TestStaticToken281--- PASS: TestStaticToken (0.00s)282=== CONT TestSetClientTLSErrors283--- PASS: TestFileTokenEmpty (0.07s)284=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts285=== CONT TestRateLimiterFeedback/503_enables_limiter2862026/10/01 07:38:45 WARN Rate limiter enabled after throttle name=server-test rate=52872026/10/01 07:38:45 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:575292882026/10/01 07:38:45 WARN Rate limiter backed off name=server-test rate=5289=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter290=== RUN TestSetClientTLS/rejects_connection_without_client_cert291=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert292=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA293=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA294=== RUN TestSetClientTLS/preserves_debug_logging_transport295=== PAUSE TestSetClientTLS/preserves_debug_logging_transport296=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter297=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)298=== CONT TestPartSizeForNAR/small_stays_at_minimum299=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512300=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI301=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon302--- PASS: TestRateLimiterFeedback (0.00s)303 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)304 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)305 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)306 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)307--- PASS: TestPartSizeForNAR (0.00s)308 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)309 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)310 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)311 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)312 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)313 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)314 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)315=== CONT TestParsePathInfoJSON/Nix_format316--- PASS: TestPathInfoHashCompatibility (0.00s)317 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)318 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)319 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)320 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)321=== CONT TestParsePathInfoJSON/invalid_JSON322=== CONT TestParsePathInfoJSON/empty_input323=== CONT TestParsePathInfoJSON/Lix_format324=== CONT TestParsePathInfoJSON/whitespace_only325=== CONT TestConvertHashToNix32/SRI_format_to_Nix32326=== CONT TestConvertHashToNix32/invalid_format327=== CONT TestConvertHashToNix32/already_Nix32_format328--- PASS: TestParsePathInfoJSON (0.00s)329 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)330 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)331 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)332 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)333 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)334=== CONT TestGetStorePathHash/valid_store_path335=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error336--- PASS: TestConvertHashToNix32 (0.00s)337 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)338 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)339 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)340=== CONT TestGetStorePathHash/basename_without_hyphen_should_error341=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error342--- PASS: TestGetStorePathHash (0.00s)343 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)344 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)345 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)346 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)347=== CONT TestFilterOversizedClosures/no_limit_keeps_everything348=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3492026/10/01 07:38:45 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=2000350=== CONT TestUploadMultipart_SupersededByPeer/exists351=== CONT TestFilterOversizedClosures/all_closures_skipped3522026/10/01 07:38:45 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=50353--- PASS: TestFilterOversizedClosures (0.00s)354 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)355 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)356 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)357=== CONT TestUploadMultipart_SupersededByPeer/missing358=== CONT TestSetClientTLS/rejects_connection_without_client_cert359--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)360 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)361 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)362=== CONT TestSetClientTLS/preserves_debug_logging_transport363=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3642026/10/01 07:38:45 http: TLS handshake error from 127.0.0.1:57540: remote error: tls: bad certificate365--- PASS: TestStreamPushBatchesUnderLoad (0.10s)366--- PASS: TestScriptTokenCachesUntilRefresh (0.12s)367--- PASS: TestSetClientTLS (0.13s)368 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)369 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)370 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)371=== RUN TestSetClientTLSErrors/missing_cert_file372=== PAUSE TestSetClientTLSErrors/missing_cert_file373=== RUN TestSetClientTLSErrors/missing_key_file374=== PAUSE TestSetClientTLSErrors/missing_key_file375=== RUN TestSetClientTLSErrors/missing_ca_file376=== PAUSE TestSetClientTLSErrors/missing_ca_file377=== RUN TestSetClientTLSErrors/invalid_ca_file378=== PAUSE TestSetClientTLSErrors/invalid_ca_file379=== CONT TestSetClientTLSErrors/missing_cert_file380=== CONT TestSetClientTLSErrors/invalid_ca_file381=== CONT TestSetClientTLSErrors/missing_ca_file382=== CONT TestSetClientTLSErrors/missing_key_file383--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.11s)384--- PASS: TestSetClientTLSErrors (0.11s)385 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)386 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)387 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)388 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)389--- PASS: TestUploadMultipart_PartsInParallel (0.61s)390--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)391--- PASS: TestDumpPathWriterError (1.54s)392--- PASS: TestDumpPathMatchesNix (1.57s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld10".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-68619-1936780597/postgres1820772409/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-68619-1936780597/postgres1820772409/data -l logfile start421422/nix/var/nix/builds/nix-68619-1936780597/postgres1820772409:5432 - no response4232026-10-01 07:39:03.054 UTC [68996] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 07:39:03.074 UTC [68996] LOG: listening on Unix socket "/nix/var/nix/builds/nix-68619-1936780597/postgres1820772409/.s.PGSQL.5432"4252026-10-01 07:39:03.106 UTC [69004] LOG: database system was shut down at 2026-10-01 07:39:02 UTC4262026-10-01 07:39:03.128 UTC [68996] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-68619-1936780597/postgres1820772409:5432 - accepting connections428{"timestamp":"2026-10-01T07:39:03.416092Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"736e5597-5185-4093-b5eb-0402b0178658","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}429{"timestamp":"2026-10-01T07:39:03.519161Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"a6027a59-3790-44d7-be5d-8ab6edccc814","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}430{"timestamp":"2026-10-01T07:39:03.620509Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"c65ea408-b906-4cf8-8917-034c6de44217","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}431{"timestamp":"2026-10-01T07:39:03.723478Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"312f97df-5ff9-414d-93e5-5849eba27798","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}432{"timestamp":"2026-10-01T07:39:03.824335Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"7013dc40-4864-4079-b617-4f926279644e","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}433{"timestamp":"2026-10-01T07:39:03.926249Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"25c193fa-07a5-4c5e-b570-0c9cc260ea60","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}434=== RUN TestService_AuthMiddleware435=== PAUSE TestService_AuthMiddleware436=== RUN TestService_AuthMiddleware_MTLSProxyHeader437=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader438=== RUN TestService_AuthMiddleware_MTLSBoundSubjects439=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects440=== RUN TestService_ReadAuthMiddleware441=== PAUSE TestService_ReadAuthMiddleware442=== RUN TestService_AuthMiddleware_OIDC443=== PAUSE TestService_AuthMiddleware_OIDC444=== RUN TestService_RequireScope_OIDC445=== PAUSE TestService_RequireScope_OIDC446=== RUN TestService_ReadScope_PublicByDefault447=== PAUSE TestService_ReadScope_PublicByDefault448=== RUN TestCacheConfigHandler449=== PAUSE TestCacheConfigHandler450=== RUN TestCacheStatsHandler451=== PAUSE TestCacheStatsHandler452=== RUN TestClientCADerivations453=== PAUSE TestClientCADerivations454=== RUN TestClientErrorHandling455=== PAUSE TestClientErrorHandling456=== RUN TestClientIntegration457=== PAUSE TestClientIntegration458=== RUN TestClientMultipleUploads459=== PAUSE TestClientMultipleUploads460=== RUN TestClientWithDependencies461=== PAUSE TestClientWithDependencies462=== RUN TestClientSharedPathCommittedMidPush463=== PAUSE TestClientSharedPathCommittedMidPush464=== RUN TestPinProtectsFromGC465=== PAUSE TestPinProtectsFromGC466=== RUN TestClientPushesUseOnePush467=== PAUSE TestClientPushesUseOnePush468=== RUN TestClientFallsBackToClosures469=== PAUSE TestClientFallsBackToClosures470=== RUN TestResolveDBConnectionString471=== PAUSE TestResolveDBConnectionString472=== RUN TestLeadElectsOneAndHandsOver473=== PAUSE TestLeadElectsOneAndHandsOver474=== RUN TestLeadIncumbentWinsAfterRestart4752026-10-01 07:39:08.089 UTC [69142] ERROR: relation "goose_db_version" does not exist at character 364762026-10-01 07:39:08.089 UTC [69142] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4772026/10/01 07:39:08 OK 20241026095416_initial_model.sql (284.35ms)4782026/10/01 07:39:08 OK 20251210153512_drop_unused_gin_index.sql (13.91ms)4792026/10/01 07:39:08 OK 20251218171726_add_pins.sql (20.81ms)4802026/10/01 07:39:08 OK 20260628120000_add_object_size_and_stats.sql (41.9ms)4812026/10/01 07:39:08 OK 20260905000000_add_claims.sql (47.55ms)4822026/10/01 07:39:08 OK 20260920000000_drop_claims.sql (6.77ms)4832026/10/01 07:39:08 OK 20260923120000_add_pushes.sql (2.37ms)4842026/10/01 07:39:08 goose: successfully migrated database to version: 202609231200004852026/10/01 07:39:08 OK 1_commit_pending_closure.sql (2.45ms)4862026/10/01 07:39:08 OK 2_object_stats_trigger.sql (910.33µs)4872026/10/01 07:39:08 OK 3_commit_push.sql (567.92µs)4882026/10/01 07:39:08 goose: up to current file version: 34892026/10/01 07:39:08 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 07:39:09 INFO lead: released remote=192.0.2.1:12344912026/10/01 07:39:09 INFO lead: acquired remote=192.0.2.1:12344922026/10/01 07:39:09 INFO lead: released remote=192.0.2.1:1234493--- PASS: TestLeadIncumbentWinsAfterRestart (5.47s)494=== RUN TestLeadEndsOnShutdown495=== PAUSE TestLeadEndsOnShutdown496=== RUN TestGCAdvisoryLockBlocksConcurrentRun4972026-10-01 07:39:10.607 UTC [69206] ERROR: relation "goose_db_version" does not exist at character 364982026-10-01 07:39:10.607 UTC [69206] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4992026/10/01 07:39:10 OK 20241026095416_initial_model.sql (119.55ms)5002026/10/01 07:39:10 OK 20251210153512_drop_unused_gin_index.sql (7.85ms)5012026/10/01 07:39:10 OK 20251218171726_add_pins.sql (8.47ms)5022026/10/01 07:39:10 OK 20260628120000_add_object_size_and_stats.sql (27.93ms)5032026/10/01 07:39:10 OK 20260905000000_add_claims.sql (25.54ms)5042026/10/01 07:39:10 OK 20260920000000_drop_claims.sql (43.07ms)5052026/10/01 07:39:10 OK 20260923120000_add_pushes.sql (16.92ms)5062026/10/01 07:39:10 goose: successfully migrated database to version: 202609231200005072026/10/01 07:39:10 OK 1_commit_pending_closure.sql (2.25ms)5082026/10/01 07:39:10 OK 2_object_stats_trigger.sql (254.21µs)5092026/10/01 07:39:10 OK 3_commit_push.sql (191.13µs)5102026/10/01 07:39:10 goose: up to current file version: 3511--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (1.67s)512=== RUN TestGCBugBareHashReferences513=== PAUSE TestGCBugBareHashReferences514=== RUN TestGCMetrics515=== PAUSE TestGCMetrics516=== RUN TestPushDedupSurvivesConcurrentGC517=== PAUSE TestPushDedupSurvivesConcurrentGC518=== RUN TestDeduplicatedObjectsRecordedAsPending519=== PAUSE TestDeduplicatedObjectsRecordedAsPending520=== RUN TestGCSweepSkipsPendingObjects521=== PAUSE TestGCSweepSkipsPendingObjects522=== RUN TestTombstonedObjectOfferedWithoutWaiting523=== PAUSE TestTombstonedObjectOfferedWithoutWaiting524=== RUN TestGCSweepDeliversEachKeyOnce525=== PAUSE TestGCSweepDeliversEachKeyOnce526=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection527=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestGCTaskStore_StartNew537=== PAUSE TestGCTaskStore_StartNew538=== RUN TestGCTaskStore_DeduplicateSameParams539=== PAUSE TestGCTaskStore_DeduplicateSameParams540=== RUN TestGCTaskStore_ConflictDifferentParams541=== PAUSE TestGCTaskStore_ConflictDifferentParams542=== RUN TestGCTaskStore_GetEmpty543=== PAUSE TestGCTaskStore_GetEmpty544=== RUN TestGCTaskStore_GetReturnsLatest545=== PAUSE TestGCTaskStore_GetReturnsLatest546=== RUN TestGCTaskStore_CompletedAllowsNewTask547=== PAUSE TestGCTaskStore_CompletedAllowsNewTask548=== RUN TestGCTaskStore_PhaseUpdates549=== PAUSE TestGCTaskStore_PhaseUpdates550=== RUN TestGCTaskStore_Fail551=== PAUSE TestGCTaskStore_Fail552=== RUN TestGracefulShutdownDrainsInflight553=== PAUSE TestGracefulShutdownDrainsInflight554=== RUN TestService_healthCheckHandler555=== PAUSE TestService_healthCheckHandler556=== RUN TestService_readinessHandler557=== PAUSE TestService_readinessHandler558=== RUN TestGenerateLandingPage559=== PAUSE TestGenerateLandingPage560=== RUN TestCacheConfigHandlerMaxNarSize561=== PAUSE TestCacheConfigHandlerMaxNarSize562=== RUN TestCreatePendingClosureRejectsOversizedNAR563=== PAUSE TestCreatePendingClosureRejectsOversizedNAR564=== RUN TestNARDeduplicationMetadataUploadBug565=== PAUSE TestNARDeduplicationMetadataUploadBug566=== RUN TestMetricsInventory567=== PAUSE TestMetricsInventory568=== RUN TestService_NativeMTLS569=== PAUSE TestService_NativeMTLS570=== RUN TestServerTLSConfig571=== PAUSE TestServerTLSConfig572=== RUN TestMultipartCleanup573=== PAUSE TestMultipartCleanup574=== RUN TestObjectStatsTrigger575=== PAUSE TestObjectStatsTrigger576=== RUN TestOrphanedObjectsGC577=== PAUSE TestOrphanedObjectsGC578=== RUN TestOrphanedObjectsGCStressTest579=== PAUSE TestOrphanedObjectsGCStressTest580=== RUN TestCreatePin_ReservedPins581=== PAUSE TestCreatePin_ReservedPins582=== RUN TestParseSingleRange583=== PAUSE TestParseSingleRange584=== RUN TestProxyHeadersOnlyTrustedOnSocket585=== PAUSE TestProxyHeadersOnlyTrustedOnSocket586=== RUN TestIsValidCachePath587=== PAUSE TestIsValidCachePath588=== RUN TestReadProxyNarinfo589=== PAUSE TestReadProxyNarinfo590=== RUN TestReadProxyNarinfoAlreadyDecompressed591=== PAUSE TestReadProxyNarinfoAlreadyDecompressed592=== RUN TestReadProxyNarStreaming593=== PAUSE TestReadProxyNarStreaming594=== RUN TestReadProxy404595=== PAUSE TestReadProxy404596=== RUN TestReadProxyInvalidPath597=== PAUSE TestReadProxyInvalidPath598=== RUN TestReadProxyHead599=== PAUSE TestReadProxyHead600=== RUN TestReadProxyConditionalGet601=== PAUSE TestReadProxyConditionalGet602=== RUN TestReadProxyRootRedirectsToIndexHTML603=== PAUSE TestReadProxyRootRedirectsToIndexHTML604=== RUN TestReadProxyDisabled605=== PAUSE TestReadProxyDisabled606=== RUN TestReadRedirectNar607=== PAUSE TestReadRedirectNar608=== RUN TestReadRedirectKeepsNarinfoProxied609=== PAUSE TestReadRedirectKeepsNarinfoProxied610=== RUN TestReadProxyRangeRequest611=== PAUSE TestReadProxyRangeRequest612=== RUN TestReadRedirectUsesPublicS3URL613=== PAUSE TestReadRedirectUsesPublicS3URL614=== RUN TestPush_OverlappingRootsStoreOneRowPerKey615=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey616=== RUN TestPush_CompleteCommitsEveryRoot617=== PAUSE TestPush_CompleteCommitsEveryRoot618=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit619=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit620=== RUN TestPush_RejectsBadRequests621=== PAUSE TestPush_RejectsBadRequests622=== RUN TestPush_SignsNarinfosOfItsPendingObjects623=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects624=== RUN TestRedundantMultipartUpload625=== PAUSE TestRedundantMultipartUpload626=== RUN TestCompleteMultipartUpload_ErrorButObjectExists627=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists628=== RUN TestCompletedNarNotReofferedAcrossClosures629=== PAUSE TestCompletedNarNotReofferedAcrossClosures630=== RUN TestPresignedUploadRegisteredBeforeCommit631=== PAUSE TestPresignedUploadRegisteredBeforeCommit632=== RUN TestService_Rustfstest633=== PAUSE TestService_Rustfstest634=== RUN TestParseSize635=== PAUSE TestParseSize636=== RUN TestSkippedUploadsHandler637=== PAUSE TestSkippedUploadsHandler638=== RUN TestSystemdListenerNotActivated639--- PASS: TestSystemdListenerNotActivated (0.00s)640=== RUN TestWatchdogBeatsWhenHealthy641--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)642=== RUN TestWatchdogSkipsWhenUnhealthy6432026/10/01 07:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6442026/10/01 07:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6452026/10/01 07:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6462026/10/01 07:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6472026/10/01 07:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6482026/10/01 07:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6492026/10/01 07:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6502026/10/01 07:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6512026/10/01 07:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6522026/10/01 07:39:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"653--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)654=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle655=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle656=== RUN TestProxyWriteTimeout657=== PAUSE TestProxyWriteTimeout658=== RUN TestIsValidUploadKey659=== PAUSE TestIsValidUploadKey660=== RUN TestUploadHandlersRejectInvalidKeys661=== PAUSE TestUploadHandlersRejectInvalidKeys662=== RUN TestUploadHandlersRejectOversizedBody663=== PAUSE TestUploadHandlersRejectOversizedBody664=== RUN TestService_cleanupPendingClosuresHandler665=== PAUSE TestService_cleanupPendingClosuresHandler666=== RUN TestService_createPendingClosureHandler667=== PAUSE TestService_createPendingClosureHandler668=== RUN TestService_verifyS3Integrity669=== PAUSE TestService_verifyS3Integrity670=== RUN TestCompleteMultipartUnregistered671=== PAUSE TestCompleteMultipartUnregistered672=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT673=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT674=== CONT TestService_AuthMiddleware675=== CONT TestNARDeduplicationMetadataUploadBug676=== CONT TestReadRedirectUsesPublicS3URL677=== CONT TestDeduplicatedObjectsRecordedAsPending678=== CONT TestReadProxyNarinfo679=== CONT TestParseSize680--- PASS: TestParseSize (0.00s)681=== CONT TestServerTLSConfig682=== CONT TestSkippedUploadsHandler683=== CONT TestUploadHandlersRejectOversizedBody684=== CONT TestUploadHandlersRejectInvalidKeys685=== CONT TestOrphanedObjectsGC686=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info687=== RUN TestServerTLSConfig/no_client_CA688=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info689=== PAUSE TestServerTLSConfig/no_client_CA690=== RUN TestServerTLSConfig/missing_CA_file691=== PAUSE TestServerTLSConfig/missing_CA_file692=== RUN TestServerTLSConfig/not_a_PEM_file693=== PAUSE TestServerTLSConfig/not_a_PEM_file694=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal695=== CONT TestIsValidUploadKey696=== RUN TestIsValidUploadKey/narinfo697=== PAUSE TestIsValidUploadKey/narinfo698=== RUN TestIsValidUploadKey/nar_zst699=== PAUSE TestIsValidUploadKey/nar_zst700=== RUN TestIsValidUploadKey/nar_xz701=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal702=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key703=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key704=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key705=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key706=== CONT TestProxyWriteTimeout707=== RUN TestProxyWriteTimeout/narinfo7082026/10/01 07:39:11 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000709=== PAUSE TestIsValidUploadKey/nar_xz710=== RUN TestIsValidUploadKey/nar_plain711=== PAUSE TestProxyWriteTimeout/narinfo712=== RUN TestProxyWriteTimeout/1_GiB_nar713=== PAUSE TestIsValidUploadKey/nar_plain714=== RUN TestIsValidUploadKey/listing715=== PAUSE TestProxyWriteTimeout/1_GiB_nar716=== RUN TestProxyWriteTimeout/10_GiB_nar717=== PAUSE TestProxyWriteTimeout/10_GiB_nar718=== RUN TestProxyWriteTimeout/unknown_size719=== PAUSE TestProxyWriteTimeout/unknown_size720=== PAUSE TestIsValidUploadKey/listing721=== RUN TestIsValidUploadKey/build_log722=== PAUSE TestIsValidUploadKey/build_log723=== RUN TestIsValidUploadKey/build_log_home-manager_file724=== PAUSE TestIsValidUploadKey/build_log_home-manager_file725=== RUN TestIsValidUploadKey/build_log_plus_in_name726=== PAUSE TestIsValidUploadKey/build_log_plus_in_name727=== RUN TestIsValidUploadKey/build_log_question_mark728=== CONT TestService_Rustfstest729=== PAUSE TestIsValidUploadKey/build_log_question_mark730=== RUN TestIsValidUploadKey/build_log_equals731=== PAUSE TestIsValidUploadKey/build_log_equals732=== RUN TestIsValidUploadKey/realisation733=== PAUSE TestIsValidUploadKey/realisation734=== RUN TestIsValidUploadKey/realisation_plus_in_output735=== PAUSE TestIsValidUploadKey/realisation_plus_in_output736=== RUN TestIsValidUploadKey/nix-cache-info737=== PAUSE TestIsValidUploadKey/nix-cache-info738=== RUN TestIsValidUploadKey/index.html739=== PAUSE TestIsValidUploadKey/index.html740=== RUN TestIsValidUploadKey/narinfo_key,_nar_type741=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type742=== RUN TestIsValidUploadKey/nar_key,_narinfo_type743=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type744=== RUN TestIsValidUploadKey/listing_key,_narinfo_type745=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type746--- PASS: TestSkippedUploadsHandler (0.02s)747=== RUN TestIsValidUploadKey/traversal748=== PAUSE TestIsValidUploadKey/traversal749=== RUN TestIsValidUploadKey/traversal_nar750=== PAUSE TestIsValidUploadKey/traversal_nar751=== RUN TestIsValidUploadKey/absolute752=== PAUSE TestIsValidUploadKey/absolute753=== RUN TestIsValidUploadKey/empty_key754=== PAUSE TestIsValidUploadKey/empty_key755=== RUN TestIsValidUploadKey/unknown_type756=== PAUSE TestIsValidUploadKey/unknown_type757=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle758=== CONT TestPresignedUploadRegisteredBeforeCommit759=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts760=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts761=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure762=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure763=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart764=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart765=== CONT TestCompleteMultipartUnregistered7662026-10-01 07:39:13.607 UTC [69299] ERROR: relation "goose_db_version" does not exist at character 367672026-10-01 07:39:13.607 UTC [69299] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7682026-10-01 07:39:13.628 UTC [69300] ERROR: relation "goose_db_version" does not exist at character 367692026-10-01 07:39:13.628 UTC [69300] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7702026-10-01 07:39:13.628 UTC [69297] ERROR: relation "goose_db_version" does not exist at character 367712026-10-01 07:39:13.628 UTC [69297] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7722026-10-01 07:39:13.630 UTC [69298] ERROR: relation "goose_db_version" does not exist at character 367732026-10-01 07:39:13.630 UTC [69298] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7742026-10-01 07:39:13.643 UTC [69304] ERROR: relation "goose_db_version" does not exist at character 367752026-10-01 07:39:13.643 UTC [69304] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7762026-10-01 07:39:13.652 UTC [69301] ERROR: relation "goose_db_version" does not exist at character 367772026-10-01 07:39:13.652 UTC [69301] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7782026-10-01 07:39:13.659 UTC [69302] ERROR: relation "goose_db_version" does not exist at character 367792026-10-01 07:39:13.659 UTC [69302] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7802026-10-01 07:39:13.680 UTC [69305] ERROR: relation "goose_db_version" does not exist at character 367812026-10-01 07:39:13.680 UTC [69305] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7822026-10-01 07:39:13.699 UTC [69306] ERROR: relation "goose_db_version" does not exist at character 367832026-10-01 07:39:13.699 UTC [69306] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7842026-10-01 07:39:13.709 UTC [69303] ERROR: relation "goose_db_version" does not exist at character 367852026-10-01 07:39:13.709 UTC [69303] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7862026/10/01 07:39:13 OK 20241026095416_initial_model.sql (109.7ms)7872026/10/01 07:39:13 OK 20241026095416_initial_model.sql (131.79ms)7882026/10/01 07:39:13 OK 20251210153512_drop_unused_gin_index.sql (27.03ms)7892026/10/01 07:39:13 OK 20251210153512_drop_unused_gin_index.sql (16.6ms)7902026/10/01 07:39:13 OK 20241026095416_initial_model.sql (190.85ms)7912026/10/01 07:39:13 OK 20241026095416_initial_model.sql (185.96ms)7922026/10/01 07:39:13 OK 20251218171726_add_pins.sql (52.74ms)7932026/10/01 07:39:13 OK 20251218171726_add_pins.sql (61.03ms)7942026/10/01 07:39:13 OK 20251210153512_drop_unused_gin_index.sql (14.24ms)7952026/10/01 07:39:13 OK 20251210153512_drop_unused_gin_index.sql (18.12ms)7962026/10/01 07:39:13 OK 20241026095416_initial_model.sql (204.38ms)7972026/10/01 07:39:13 OK 20251218171726_add_pins.sql (17.51ms)7982026/10/01 07:39:13 OK 20251210153512_drop_unused_gin_index.sql (18.99ms)7992026/10/01 07:39:13 OK 20251218171726_add_pins.sql (31.13ms)8002026/10/01 07:39:13 OK 20260628120000_add_object_size_and_stats.sql (49.31ms)8012026/10/01 07:39:13 OK 20241026095416_initial_model.sql (235.55ms)8022026/10/01 07:39:13 OK 20260628120000_add_object_size_and_stats.sql (39.95ms)8032026/10/01 07:39:13 OK 20251210153512_drop_unused_gin_index.sql (15.9ms)8042026/10/01 07:39:13 OK 20251218171726_add_pins.sql (27.97ms)8052026/10/01 07:39:13 OK 20260628120000_add_object_size_and_stats.sql (33.45ms)8062026/10/01 07:39:13 OK 20241026095416_initial_model.sql (228.76ms)8072026/10/01 07:39:13 OK 20241026095416_initial_model.sql (233.34ms)8082026/10/01 07:39:13 OK 20241026095416_initial_model.sql (243.52ms)8092026/10/01 07:39:13 OK 20251210153512_drop_unused_gin_index.sql (20.84ms)8102026/10/01 07:39:13 OK 20251210153512_drop_unused_gin_index.sql (23.87ms)8112026/10/01 07:39:14 OK 20260628120000_add_object_size_and_stats.sql (59.99ms)8122026/10/01 07:39:14 OK 20251210153512_drop_unused_gin_index.sql (28.3ms)8132026/10/01 07:39:14 OK 20251218171726_add_pins.sql (45.78ms)8142026/10/01 07:39:14 OK 20251218171726_add_pins.sql (52.16ms)8152026/10/01 07:39:14 OK 20260628120000_add_object_size_and_stats.sql (89.91ms)8162026/10/01 07:39:14 OK 20251218171726_add_pins.sql (72.57ms)8172026/10/01 07:39:14 OK 20241026095416_initial_model.sql (322.06ms)8182026/10/01 07:39:14 OK 20260905000000_add_claims.sql (120.16ms)8192026/10/01 07:39:14 OK 20260628120000_add_object_size_and_stats.sql (70.86ms)8202026/10/01 07:39:14 OK 20251210153512_drop_unused_gin_index.sql (30.82ms)8212026/10/01 07:39:14 OK 20251218171726_add_pins.sql (86.59ms)8222026/10/01 07:39:14 OK 20260905000000_add_claims.sql (147.12ms)8232026/10/01 07:39:14 OK 20260905000000_add_claims.sql (130.52ms)8242026/10/01 07:39:14 OK 20260628120000_add_object_size_and_stats.sql (63.52ms)8252026/10/01 07:39:14 OK 20260905000000_add_claims.sql (94.14ms)8262026/10/01 07:39:14 OK 20260628120000_add_object_size_and_stats.sql (50.61ms)8272026/10/01 07:39:14 OK 20260920000000_drop_claims.sql (88.38ms)8282026/10/01 07:39:14 OK 20260628120000_add_object_size_and_stats.sql (64.24ms)8292026/10/01 07:39:14 OK 20260905000000_add_claims.sql (118.19ms)8302026/10/01 07:39:14 OK 20251218171726_add_pins.sql (80.13ms)8312026/10/01 07:39:14 OK 20260923120000_add_pushes.sql (26.45ms)8322026/10/01 07:39:14 goose: successfully migrated database to version: 202609231200008332026/10/01 07:39:14 OK 20260920000000_drop_claims.sql (96.28ms)8342026/10/01 07:39:14 OK 20260920000000_drop_claims.sql (89.46ms)8352026/10/01 07:39:14 OK 20260920000000_drop_claims.sql (96.63ms)8362026/10/01 07:39:14 OK 20260920000000_drop_claims.sql (20.8ms)8372026/10/01 07:39:14 OK 1_commit_pending_closure.sql (12.57ms)8382026/10/01 07:39:14 OK 20260905000000_add_claims.sql (116.81ms)8392026/10/01 07:39:14 OK 20260628120000_add_object_size_and_stats.sql (25.09ms)8402026/10/01 07:39:14 OK 20260905000000_add_claims.sql (96.11ms)8412026/10/01 07:39:14 OK 20260905000000_add_claims.sql (85.69ms)8422026/10/01 07:39:14 OK 2_object_stats_trigger.sql (2.7ms)8432026/10/01 07:39:14 OK 3_commit_push.sql (476.42µs)8442026/10/01 07:39:14 goose: up to current file version: 38452026/10/01 07:39:14 OK 20260923120000_add_pushes.sql (12.63ms)8462026/10/01 07:39:14 goose: successfully migrated database to version: 202609231200008472026/10/01 07:39:14 OK 20260905000000_add_claims.sql (47.38ms)8482026/10/01 07:39:14 OK 20260923120000_add_pushes.sql (14.88ms)8492026/10/01 07:39:14 goose: successfully migrated database to version: 202609231200008502026/10/01 07:39:14 OK 20260923120000_add_pushes.sql (14.67ms)8512026/10/01 07:39:14 goose: successfully migrated database to version: 202609231200008522026/10/01 07:39:14 OK 1_commit_pending_closure.sql (1.87ms)8532026/10/01 07:39:14 OK 1_commit_pending_closure.sql (1.74ms)8542026/10/01 07:39:14 OK 1_commit_pending_closure.sql (1.8ms)8552026/10/01 07:39:14 OK 2_object_stats_trigger.sql (493.67µs)8562026/10/01 07:39:14 OK 2_object_stats_trigger.sql (428µs)8572026/10/01 07:39:14 OK 2_object_stats_trigger.sql (486.04µs)8582026/10/01 07:39:14 OK 3_commit_push.sql (328.58µs)8592026/10/01 07:39:14 goose: up to current file version: 38602026/10/01 07:39:14 OK 3_commit_push.sql (364.25µs)8612026/10/01 07:39:14 goose: up to current file version: 38622026/10/01 07:39:14 OK 3_commit_push.sql (395.88µs)8632026/10/01 07:39:14 goose: up to current file version: 38642026/10/01 07:39:14 OK 20260923120000_add_pushes.sql (24.95ms)8652026/10/01 07:39:14 goose: successfully migrated database to version: 202609231200008662026/10/01 07:39:14 OK 1_commit_pending_closure.sql (2.36ms)8672026/10/01 07:39:14 OK 2_object_stats_trigger.sql (341.21µs)8682026/10/01 07:39:14 OK 3_commit_push.sql (260.38µs)8692026/10/01 07:39:14 goose: up to current file version: 38702026/10/01 07:39:14 OK 20260920000000_drop_claims.sql (84.59ms)8712026/10/01 07:39:14 OK 20260920000000_drop_claims.sql (76.69ms)8722026/10/01 07:39:14 OK 20260920000000_drop_claims.sql (97.95ms)8732026/10/01 07:39:14 OK 20260920000000_drop_claims.sql (99.06ms)8742026/10/01 07:39:14 OK 20260923120000_add_pushes.sql (22.37ms)8752026/10/01 07:39:14 goose: successfully migrated database to version: 202609231200008762026/10/01 07:39:14 OK 1_commit_pending_closure.sql (3.29ms)8772026/10/01 07:39:14 OK 2_object_stats_trigger.sql (755.63µs)8782026/10/01 07:39:14 OK 3_commit_push.sql (482.75µs)8792026/10/01 07:39:14 goose: up to current file version: 38802026/10/01 07:39:14 OK 20260923120000_add_pushes.sql (30.52ms)8812026/10/01 07:39:14 goose: successfully migrated database to version: 202609231200008822026/10/01 07:39:14 OK 1_commit_pending_closure.sql (3.26ms)8832026/10/01 07:39:14 OK 2_object_stats_trigger.sql (748.63µs)8842026/10/01 07:39:14 OK 3_commit_push.sql (437.13µs)8852026/10/01 07:39:14 goose: up to current file version: 38862026/10/01 07:39:14 OK 20260923120000_add_pushes.sql (31.03ms)8872026/10/01 07:39:14 goose: successfully migrated database to version: 202609231200008882026/10/01 07:39:14 OK 1_commit_pending_closure.sql (3.01ms)8892026/10/01 07:39:14 OK 2_object_stats_trigger.sql (644.38µs)8902026/10/01 07:39:14 OK 3_commit_push.sql (427.79µs)8912026/10/01 07:39:14 goose: up to current file version: 38922026/10/01 07:39:14 OK 20260923120000_add_pushes.sql (43.88ms)8932026/10/01 07:39:14 goose: successfully migrated database to version: 202609231200008942026/10/01 07:39:14 OK 20260905000000_add_claims.sql (142.3ms)8952026/10/01 07:39:14 OK 1_commit_pending_closure.sql (2.96ms)8962026/10/01 07:39:14 OK 2_object_stats_trigger.sql (666.83µs)8972026/10/01 07:39:14 OK 3_commit_push.sql (430.25µs)8982026/10/01 07:39:14 goose: up to current file version: 38992026/10/01 07:39:14 OK 20260920000000_drop_claims.sql (45.33ms)9002026/10/01 07:39:14 OK 20260923120000_add_pushes.sql (12.82ms)9012026/10/01 07:39:14 goose: successfully migrated database to version: 202609231200009022026/10/01 07:39:14 OK 1_commit_pending_closure.sql (2.31ms)9032026/10/01 07:39:14 OK 2_object_stats_trigger.sql (426.04µs)9042026/10/01 07:39:14 OK 3_commit_push.sql (390.75µs)9052026/10/01 07:39:14 goose: up to current file version: 3906--- PASS: TestReadProxyNarinfo (3.16s)907=== CONT TestCompletedNarNotReofferedAcrossClosures908--- PASS: TestReadRedirectUsesPublicS3URL (3.51s)909=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT9102026/10/01 07:39:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9112026/10/01 07:39:15 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst912--- PASS: TestCompleteMultipartUnregistered (4.21s)913=== CONT TestService_verifyS3Integrity914=== NAME TestOrphanedObjectsGC915 orphaned_objects_gc_test.go:290: GC Test Summary:916 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A917 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B918 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)919 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)920 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects921--- PASS: TestOrphanedObjectsGC (5.14s)922=== CONT TestService_NativeMTLS9232026/10/01 07:39:16 INFO Received uploads request method=POST path=/api/pending_closures924--- PASS: TestDeduplicatedObjectsRecordedAsPending (5.34s)925=== CONT TestMetricsInventory926=== NAME TestNARDeduplicationMetadataUploadBug927 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-68619-1936780597/TestNARDeduplicationMetadataUploadBug2641078354/001/store/yacq2jmni4kx0v903skkndn4iwr529zn-file1.txt9282026/10/01 07:39:16 INFO Received push request method=POST path=/api/pushes9292026/10/01 07:39:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9302026/10/01 07:39:17 INFO Uploading yacq2jmni4kx0v903skkndn4iwr529zn-file1.txt (160B)9312026/10/01 07:39:17 WARN Failed to register uploaded object key=yacq2jmni4kx0v903skkndn4iwr529zn.ls error="server returned 404: 404 page not found\n"9322026/10/01 07:39:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9332026/10/01 07:39:17 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"9342026/10/01 07:39:17 INFO Signed narinfos id=1 count=19352026/10/01 07:39:17 INFO Uploading 1 narinfos9362026/10/01 07:39:17 INFO Received complete push request method=POST path=/api/pushes/1/complete9372026/10/01 07:39:17 WARN Failed to register uploaded object key=yacq2jmni4kx0v903skkndn4iwr529zn.narinfo error="server returned 404: 404 page not found\n"9382026/10/01 07:39:17 INFO Upload complete. (263ms)939 metadata_upload_test.go:54: Retrieved narinfo from S3:940 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestNARDeduplicationMetadataUploadBug2641078354/001/store/yacq2jmni4kx0v903skkndn4iwr529zn-file1.txt941 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst942 Compression: zstd943 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf944 NarSize: 160945 References: 946 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf947 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)948 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):949 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}9502026/10/01 07:39:17 INFO Received uploads request method=POST path=/api/pending_closures951 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-68619-1936780597/TestNARDeduplicationMetadataUploadBug2641078354/001/store/89abald65iqik8fpf8d66fp0hx3xsxk1-file2.txt9522026/10/01 07:39:17 INFO Received push request method=POST path=/api/pushes9532026/10/01 07:39:17 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)9542026/10/01 07:39:17 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign9552026/10/01 07:39:17 INFO Signed narinfos id=2 count=19562026/10/01 07:39:17 WARN Failed to register uploaded object key=89abald65iqik8fpf8d66fp0hx3xsxk1.ls error="server returned 404: 404 page not found\n"9572026/10/01 07:39:17 INFO Uploading 1 narinfos9582026/10/01 07:39:17 INFO Received complete push request method=POST path=/api/pushes/2/complete9592026/10/01 07:39:17 WARN Failed to register uploaded object key=89abald65iqik8fpf8d66fp0hx3xsxk1.narinfo error="server returned 404: 404 page not found\n"9602026/10/01 07:39:17 INFO Upload complete. (157ms)961 metadata_upload_test.go:76: Retrieved narinfo from S3:962 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestNARDeduplicationMetadataUploadBug2641078354/001/store/89abald65iqik8fpf8d66fp0hx3xsxk1-file2.txt963 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst964 Compression: zstd965 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf966 NarSize: 160967 References: 968 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf969 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)970 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):971 {"version":1,"root":{"type":"regular","size":44}}9722026/10/01 07:39:17 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"973--- PASS: TestService_AuthMiddleware (6.19s)974=== CONT TestParseSingleRange975=== RUN TestParseSingleRange/none976=== PAUSE TestParseSingleRange/none977=== RUN TestParseSingleRange/unknown_unit978=== PAUSE TestParseSingleRange/unknown_unit979=== RUN TestParseSingleRange/multi-range_ignored980=== PAUSE TestParseSingleRange/multi-range_ignored981=== RUN TestParseSingleRange/malformed_no_dash982=== PAUSE TestParseSingleRange/malformed_no_dash983=== RUN TestParseSingleRange/malformed_both_empty984=== PAUSE TestParseSingleRange/malformed_both_empty985=== RUN TestParseSingleRange/malformed_end_before_start986=== PAUSE TestParseSingleRange/malformed_end_before_start987=== RUN TestParseSingleRange/closed988=== PAUSE TestParseSingleRange/closed989=== RUN TestParseSingleRange/open-ended990=== PAUSE TestParseSingleRange/open-ended991=== RUN TestParseSingleRange/end_clamped_to_size992=== PAUSE TestParseSingleRange/end_clamped_to_size993=== RUN TestParseSingleRange/suffix994=== PAUSE TestParseSingleRange/suffix995=== RUN TestParseSingleRange/suffix_exceeds_size996=== PAUSE TestParseSingleRange/suffix_exceeds_size997=== RUN TestParseSingleRange/single_byte998=== PAUSE TestParseSingleRange/single_byte999=== RUN TestParseSingleRange/start_past_EOF1000=== PAUSE TestParseSingleRange/start_past_EOF1001=== RUN TestParseSingleRange/start_far_past_EOF1002=== PAUSE TestParseSingleRange/start_far_past_EOF1003=== CONT TestIsValidCachePath1004=== RUN TestIsValidCachePath/narinfo1005=== PAUSE TestIsValidCachePath/narinfo1006=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1007=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1008=== RUN TestIsValidCachePath/nar_zst1009=== PAUSE TestIsValidCachePath/nar_zst1010=== RUN TestIsValidCachePath/nar_xz1011=== PAUSE TestIsValidCachePath/nar_xz1012=== RUN TestIsValidCachePath/nar_bz21013=== PAUSE TestIsValidCachePath/nar_bz21014=== RUN TestIsValidCachePath/nar_uncompressed1015=== PAUSE TestIsValidCachePath/nar_uncompressed1016=== RUN TestIsValidCachePath/ls1017=== PAUSE TestIsValidCachePath/ls1018=== RUN TestIsValidCachePath/log1019=== PAUSE TestIsValidCachePath/log1020=== RUN TestIsValidCachePath/realisation1021=== PAUSE TestIsValidCachePath/realisation1022=== RUN TestIsValidCachePath/nix-cache-info1023=== PAUSE TestIsValidCachePath/nix-cache-info1024=== RUN TestIsValidCachePath/index.html1025=== PAUSE TestIsValidCachePath/index.html1026=== RUN TestIsValidCachePath/traversal_parent1027=== PAUSE TestIsValidCachePath/traversal_parent1028=== RUN TestIsValidCachePath/traversal_in_middle1029=== PAUSE TestIsValidCachePath/traversal_in_middle1030=== RUN TestIsValidCachePath/invalid_char_e1031=== PAUSE TestIsValidCachePath/invalid_char_e1032=== RUN TestIsValidCachePath/invalid_char_u1033=== PAUSE TestIsValidCachePath/invalid_char_u1034=== RUN TestIsValidCachePath/random_path1035=== PAUSE TestIsValidCachePath/random_path1036=== RUN TestIsValidCachePath/empty1037=== PAUSE TestIsValidCachePath/empty1038=== RUN TestIsValidCachePath/leading_slash1039=== PAUSE TestIsValidCachePath/leading_slash1040=== RUN TestIsValidCachePath/wrong_extension1041=== PAUSE TestIsValidCachePath/wrong_extension1042=== RUN TestIsValidCachePath/short_hash1043=== PAUSE TestIsValidCachePath/short_hash1044=== CONT TestProxyHeadersOnlyTrustedOnSocket10452026/10/01 07:39:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1046--- PASS: TestNARDeduplicationMetadataUploadBug (6.32s)1047=== CONT TestService_healthCheckHandler1048--- PASS: TestService_Rustfstest (6.52s)1049=== CONT TestCreatePendingClosureRejectsOversizedNAR10502026/10/01 07:39:17 INFO Received uploads request method=POST path=/api/pending_closures1051--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1052=== CONT TestCacheConfigHandlerMaxNarSize1053--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1054=== CONT TestGenerateLandingPage1055--- PASS: TestGenerateLandingPage (0.00s)1056=== CONT TestService_readinessHandler10572026-10-01 07:39:18.251 UTC [69355] ERROR: relation "goose_db_version" does not exist at character 3610582026-10-01 07:39:18.251 UTC [69355] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10592026/10/01 07:39:18 INFO Received uploads request method=POST path=/api/pending_closures10602026/10/01 07:39:18 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10612026/10/01 07:39:18 INFO Received uploads request method=POST path=/api/pending_closures1062--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.07s)1063=== CONT TestGCTaskStore_PhaseUpdates1064--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1065=== CONT TestGracefulShutdownDrainsInflight10662026/10/01 07:39:18 INFO Starting HTTP server address=127.0.0.1:5809810672026/10/01 07:39:18 INFO Shutdown signal received, draining in-flight requests timeout=10s10682026-10-01 07:39:18.541 UTC [69362] ERROR: relation "goose_db_version" does not exist at character 3610692026-10-01 07:39:18.541 UTC [69362] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1070--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1071=== CONT TestGCTaskStore_Fail1072--- PASS: TestGCTaskStore_Fail (0.00s)1073=== CONT TestGCTaskStore_GetEmpty1074--- PASS: TestGCTaskStore_GetEmpty (0.00s)1075=== CONT TestService_createPendingClosureHandler10762026/10/01 07:39:18 OK 20241026095416_initial_model.sql (330.97ms)10772026/10/01 07:39:18 OK 20251210153512_drop_unused_gin_index.sql (26.21ms)10782026/10/01 07:39:18 OK 20251218171726_add_pins.sql (36.06ms)10792026/10/01 07:39:18 OK 20260628120000_add_object_size_and_stats.sql (50.42ms)10802026/10/01 07:39:18 OK 20241026095416_initial_model.sql (180.63ms)10812026/10/01 07:39:18 OK 20260905000000_add_claims.sql (50.56ms)10822026/10/01 07:39:18 OK 20251210153512_drop_unused_gin_index.sql (4.9ms)10832026/10/01 07:39:18 OK 20260920000000_drop_claims.sql (40.7ms)10842026/10/01 07:39:18 OK 20251218171726_add_pins.sql (37.66ms)10852026/10/01 07:39:18 OK 20260923120000_add_pushes.sql (29.69ms)10862026/10/01 07:39:18 goose: successfully migrated database to version: 2026092312000010872026/10/01 07:39:18 OK 1_commit_pending_closure.sql (944.04µs)10882026/10/01 07:39:18 OK 2_object_stats_trigger.sql (262.58µs)10892026/10/01 07:39:18 OK 3_commit_push.sql (212.38µs)10902026/10/01 07:39:18 goose: up to current file version: 310912026/10/01 07:39:18 OK 20260628120000_add_object_size_and_stats.sql (66.52ms)10922026/10/01 07:39:19 OK 20260905000000_add_claims.sql (106.46ms)10932026/10/01 07:39:19 OK 20260920000000_drop_claims.sql (74.4ms)10942026-10-01 07:39:19.151 UTC [69386] ERROR: relation "goose_db_version" does not exist at character 3610952026-10-01 07:39:19.151 UTC [69386] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10962026/10/01 07:39:19 OK 20260923120000_add_pushes.sql (46.65ms)10972026/10/01 07:39:19 goose: successfully migrated database to version: 2026092312000010982026/10/01 07:39:19 OK 1_commit_pending_closure.sql (1ms)10992026/10/01 07:39:19 OK 2_object_stats_trigger.sql (258.96µs)11002026/10/01 07:39:19 OK 3_commit_push.sql (190.71µs)11012026/10/01 07:39:19 goose: up to current file version: 311022026/10/01 07:39:19 INFO Received uploads request method=POST path=/api/pending_closures11032026/10/01 07:39:19 OK 20241026095416_initial_model.sql (421.86ms)11042026/10/01 07:39:19 OK 20251210153512_drop_unused_gin_index.sql (25.18ms)11052026/10/01 07:39:19 OK 20251218171726_add_pins.sql (60.23ms)11062026/10/01 07:39:19 INFO Received uploads request method=POST path=/api/pending_closures11072026/10/01 07:39:19 OK 20260628120000_add_object_size_and_stats.sql (221.03ms)1108--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (5.12s)1109=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit11102026/10/01 07:39:20 OK 20260905000000_add_claims.sql (118.21ms)11112026/10/01 07:39:20 OK 20260920000000_drop_claims.sql (62.25ms)11122026/10/01 07:39:20 OK 20260923120000_add_pushes.sql (34.04ms)11132026/10/01 07:39:20 goose: successfully migrated database to version: 2026092312000011142026/10/01 07:39:20 OK 1_commit_pending_closure.sql (1.52ms)11152026/10/01 07:39:20 OK 2_object_stats_trigger.sql (305.08µs)11162026/10/01 07:39:20 OK 3_commit_push.sql (246.46µs)11172026/10/01 07:39:20 goose: up to current file version: 311182026/10/01 07:39:20 WARN Rate limiter enabled after throttle name=s3-test rate=511192026/10/01 07:39:20 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1120=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1121 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101122 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001123--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (8.91s)1124=== CONT TestGCTaskStore_CompletedAllowsNewTask1125--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1126=== CONT TestRedundantMultipartUpload11272026-10-01 07:39:20.402 UTC [69405] ERROR: relation "goose_db_version" does not exist at character 3611282026-10-01 07:39:20.402 UTC [69405] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11292026/10/01 07:39:20 INFO Received uploads request method=POST path=/api/pending_closures11302026-10-01 07:39:20.805 UTC [69411] ERROR: relation "goose_db_version" does not exist at character 3611312026-10-01 07:39:20.805 UTC [69411] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11322026/10/01 07:39:20 OK 20241026095416_initial_model.sql (400.57ms)11332026/10/01 07:39:20 OK 20251210153512_drop_unused_gin_index.sql (14.83ms)11342026/10/01 07:39:20 OK 20251218171726_add_pins.sql (57.36ms)11352026/10/01 07:39:21 OK 20260628120000_add_object_size_and_stats.sql (86.76ms)11362026/10/01 07:39:21 OK 20260905000000_add_claims.sql (72.86ms)11372026/10/01 07:39:21 OK 20260920000000_drop_claims.sql (98.18ms)11382026/10/01 07:39:21 OK 20260923120000_add_pushes.sql (42.84ms)11392026/10/01 07:39:21 goose: successfully migrated database to version: 2026092312000011402026/10/01 07:39:21 OK 1_commit_pending_closure.sql (950.25µs)11412026/10/01 07:39:21 OK 2_object_stats_trigger.sql (236.5µs)11422026/10/01 07:39:21 OK 3_commit_push.sql (201.5µs)11432026/10/01 07:39:21 goose: up to current file version: 311442026/10/01 07:39:21 OK 20241026095416_initial_model.sql (416.81ms)11452026/10/01 07:39:21 OK 20251210153512_drop_unused_gin_index.sql (29.01ms)11462026/10/01 07:39:21 OK 20251218171726_add_pins.sql (77.38ms)11472026/10/01 07:39:21 OK 20260628120000_add_object_size_and_stats.sql (97.22ms)11482026/10/01 07:39:21 OK 20260905000000_add_claims.sql (113.45ms)11492026/10/01 07:39:21 OK 20260920000000_drop_claims.sql (154.4ms)11502026/10/01 07:39:21 OK 20260923120000_add_pushes.sql (38.99ms)11512026/10/01 07:39:21 goose: successfully migrated database to version: 2026092312000011522026/10/01 07:39:21 OK 1_commit_pending_closure.sql (6.11ms)11532026/10/01 07:39:21 OK 2_object_stats_trigger.sql (2.08ms)11542026/10/01 07:39:21 OK 3_commit_push.sql (669.67µs)11552026/10/01 07:39:21 goose: up to current file version: 31156--- PASS: TestMetricsInventory (5.20s)1157=== CONT TestGCTaskStore_GetReturnsLatest1158--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1159=== CONT TestPush_SignsNarinfosOfItsPendingObjects11602026/10/01 07:39:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11612026/10/01 07:39:22 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11622026/10/01 07:39:22 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1163--- PASS: TestService_NativeMTLS (5.88s)1164=== CONT TestPush_RejectsBadRequests11652026/10/01 07:39:22 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NDYxYmZlMGUtZWUzZi00NGExLWJhMDgtYTk1ZDhiMWYxNmZhLjBjYjJlZGU2LTVlZWItNGI3MS1iY2ZiLWNhNGUyMGRjM2UxY3gxNzkwODQwMzU5MzY4OTMyMDAw parts=1211662026/10/01 07:39:22 INFO Received uploads request method=POST path=/api/pending_closures1167--- PASS: TestCompletedNarNotReofferedAcrossClosures (7.89s)1168=== CONT TestPush_OverlappingRootsStoreOneRowPerKey11692026-10-01 07:39:22.538 UTC [69444] ERROR: relation "goose_db_version" does not exist at character 3611702026-10-01 07:39:22.538 UTC [69444] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11712026-10-01 07:39:22.540 UTC [69446] ERROR: relation "goose_db_version" does not exist at character 3611722026-10-01 07:39:22.540 UTC [69446] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11732026-10-01 07:39:22.784 UTC [69451] ERROR: relation "goose_db_version" does not exist at character 3611742026-10-01 07:39:22.784 UTC [69451] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11752026/10/01 07:39:22 OK 20241026095416_initial_model.sql (149.81ms)11762026/10/01 07:39:22 OK 20251210153512_drop_unused_gin_index.sql (15.58ms)11772026-10-01 07:39:22.938 UTC [69452] ERROR: relation "goose_db_version" does not exist at character 3611782026-10-01 07:39:22.938 UTC [69452] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11792026/10/01 07:39:22 OK 20251218171726_add_pins.sql (150.67ms)11802026/10/01 07:39:22 OK 20241026095416_initial_model.sql (318.82ms)11812026/10/01 07:39:22 OK 20251210153512_drop_unused_gin_index.sql (22.78ms)11822026/10/01 07:39:23 OK 20260628120000_add_object_size_and_stats.sql (80.97ms)11832026/10/01 07:39:23 OK 20251218171726_add_pins.sql (61.8ms)11842026/10/01 07:39:23 OK 20260628120000_add_object_size_and_stats.sql (86.06ms)11852026/10/01 07:39:23 OK 20260905000000_add_claims.sql (153.1ms)11862026/10/01 07:39:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11872026/10/01 07:39:23 OK 20260920000000_drop_claims.sql (87.07ms)11882026/10/01 07:39:23 OK 20260905000000_add_claims.sql (178.22ms)11892026/10/01 07:39:23 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NDYxYmZlMGUtZWUzZi00NGExLWJhMDgtYTk1ZDhiMWYxNmZhLjY5OTMwNjE4LTA4MzItNDFhZi05MTcxLWM4ODI2ZDlkZDIzNXgxNzkwODQwMzYwODI4MjgxMDAw parts=1011902026/10/01 07:39:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11912026/10/01 07:39:23 OK 20260923120000_add_pushes.sql (56.26ms)11922026/10/01 07:39:23 goose: successfully migrated database to version: 2026092312000011932026/10/01 07:39:23 OK 1_commit_pending_closure.sql (3.46ms)11942026/10/01 07:39:23 OK 2_object_stats_trigger.sql (2.42ms)11952026/10/01 07:39:23 OK 3_commit_push.sql (972.17µs)11962026/10/01 07:39:23 goose: up to current file version: 311972026/10/01 07:39:23 INFO Completed upload id=111982026/10/01 07:39:23 INFO Received uploads request method=POST path=/api/pending_closures11992026/10/01 07:39:23 INFO Received uploads request method=POST path=/api/pending_closures12002026/10/01 07:39:23 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12012026/10/01 07:39:23 WARN Found objects in DB but missing from S3, will re-upload count=11202--- PASS: TestService_verifyS3Integrity (7.68s)1203=== CONT TestPush_CompleteCommitsEveryRoot12042026/10/01 07:39:23 OK 20241026095416_initial_model.sql (435.16ms)12052026/10/01 07:39:23 OK 20251210153512_drop_unused_gin_index.sql (15.58ms)12062026/10/01 07:39:23 OK 20260920000000_drop_claims.sql (118.02ms)12072026/10/01 07:39:23 OK 20260923120000_add_pushes.sql (33.31ms)12082026/10/01 07:39:23 goose: successfully migrated database to version: 2026092312000012092026/10/01 07:39:23 OK 20241026095416_initial_model.sql (397.26ms)12102026/10/01 07:39:23 OK 1_commit_pending_closure.sql (3.56ms)12112026/10/01 07:39:23 OK 2_object_stats_trigger.sql (667.04µs)12122026/10/01 07:39:23 OK 3_commit_push.sql (415.96µs)12132026/10/01 07:39:23 goose: up to current file version: 312142026/10/01 07:39:23 OK 20251210153512_drop_unused_gin_index.sql (17.27ms)12152026/10/01 07:39:23 OK 20251218171726_add_pins.sql (57.95ms)12162026/10/01 07:39:23 OK 20251218171726_add_pins.sql (43.12ms)12172026/10/01 07:39:23 OK 20260628120000_add_object_size_and_stats.sql (58.28ms)12182026/10/01 07:39:23 OK 20260628120000_add_object_size_and_stats.sql (54.08ms)12192026/10/01 07:39:23 OK 20260905000000_add_claims.sql (115.02ms)12202026/10/01 07:39:23 OK 20260905000000_add_claims.sql (96.93ms)12212026/10/01 07:39:23 OK 20260920000000_drop_claims.sql (60.75ms)12222026/10/01 07:39:23 OK 20260920000000_drop_claims.sql (56.64ms)12232026/10/01 07:39:23 OK 20260923120000_add_pushes.sql (17.63ms)12242026/10/01 07:39:23 goose: successfully migrated database to version: 2026092312000012252026/10/01 07:39:23 OK 1_commit_pending_closure.sql (1.16ms)12262026/10/01 07:39:23 OK 2_object_stats_trigger.sql (288.17µs)12272026/10/01 07:39:23 OK 3_commit_push.sql (216.33µs)12282026/10/01 07:39:23 goose: up to current file version: 312292026/10/01 07:39:23 OK 20260923120000_add_pushes.sql (16.4ms)12302026/10/01 07:39:23 goose: successfully migrated database to version: 2026092312000012312026/10/01 07:39:23 OK 1_commit_pending_closure.sql (1.02ms)12322026/10/01 07:39:23 OK 2_object_stats_trigger.sql (245.5µs)12332026/10/01 07:39:23 OK 3_commit_push.sql (193.71µs)12342026/10/01 07:39:23 goose: up to current file version: 31235--- PASS: TestService_healthCheckHandler (6.10s)1236=== CONT TestObjectStatsTrigger12372026/10/01 07:39:24 INFO Starting HTTP server address=/nix/var/nix/builds/nix-68619-1936780597/TestProxyHeadersOnlyTrustedOnSocket356798073/001/proxy.sock12382026/10/01 07:39:24 INFO Starting HTTP server address=127.0.0.1:5817812392026/10/01 07:39:24 WARN mTLS auth: subject not in bound subjects subject="CN=someone"12402026/10/01 07:39:24 INFO Shutdown signal received, draining in-flight requests timeout=10s1241--- PASS: TestProxyHeadersOnlyTrustedOnSocket (6.53s)1242=== CONT TestMultipartCleanup12432026-10-01 07:39:24.201 UTC [69472] ERROR: relation "goose_db_version" does not exist at character 3612442026-10-01 07:39:24.201 UTC [69472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12452026-10-01 07:39:24.201 UTC [69473] ERROR: relation "goose_db_version" does not exist at character 3612462026-10-01 07:39:24.201 UTC [69473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12472026/10/01 07:39:24 WARN readiness check failed error="closed pool"1248--- PASS: TestService_readinessHandler (6.47s)1249=== CONT TestReadProxyConditionalGet12502026/10/01 07:39:24 OK 20241026095416_initial_model.sql (258.1ms)12512026/10/01 07:39:24 OK 20241026095416_initial_model.sql (264.39ms)12522026/10/01 07:39:24 OK 20251210153512_drop_unused_gin_index.sql (14.85ms)12532026/10/01 07:39:24 OK 20251210153512_drop_unused_gin_index.sql (23.12ms)12542026/10/01 07:39:24 OK 20251218171726_add_pins.sql (41.41ms)12552026/10/01 07:39:24 OK 20251218171726_add_pins.sql (39.21ms)12562026/10/01 07:39:24 OK 20260628120000_add_object_size_and_stats.sql (42.92ms)12572026/10/01 07:39:24 OK 20260628120000_add_object_size_and_stats.sql (44.66ms)12582026/10/01 07:39:24 OK 20260905000000_add_claims.sql (92.92ms)12592026/10/01 07:39:24 OK 20260905000000_add_claims.sql (108.7ms)12602026/10/01 07:39:24 OK 20260920000000_drop_claims.sql (69.46ms)12612026/10/01 07:39:24 OK 20260920000000_drop_claims.sql (39.67ms)12622026/10/01 07:39:24 OK 20260923120000_add_pushes.sql (21.76ms)12632026/10/01 07:39:24 goose: successfully migrated database to version: 2026092312000012642026/10/01 07:39:24 OK 1_commit_pending_closure.sql (4.76ms)12652026/10/01 07:39:24 OK 2_object_stats_trigger.sql (1.1ms)12662026/10/01 07:39:24 OK 3_commit_push.sql (961.33µs)12672026/10/01 07:39:24 goose: up to current file version: 312682026/10/01 07:39:24 OK 20260923120000_add_pushes.sql (44.44ms)12692026/10/01 07:39:24 goose: successfully migrated database to version: 2026092312000012702026/10/01 07:39:24 OK 1_commit_pending_closure.sql (6.58ms)12712026/10/01 07:39:24 OK 2_object_stats_trigger.sql (2.5ms)12722026/10/01 07:39:24 OK 3_commit_push.sql (599.54µs)12732026/10/01 07:39:24 goose: up to current file version: 312742026/10/01 07:39:24 INFO Received uploads request method=POST path=/api/pending_closures12752026/10/01 07:39:24 INFO Received uploads request method=POST path=/api/pending_closures12762026/10/01 07:39:24 INFO Received uploads request method=POST path=/api/pending_closures12772026/10/01 07:39:25 INFO Received uploads request method=POST path=/api/pending_closures12782026/10/01 07:39:25 INFO Received uploads request method=POST path=/api/pending_closures12792026/10/01 07:39:25 INFO Received push request method=POST path=/api/pushes12802026-10-01 07:39:25.719 UTC [69499] ERROR: relation "goose_db_version" does not exist at character 3612812026-10-01 07:39:25.719 UTC [69499] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12822026/10/01 07:39:25 INFO Received complete push request method=POST path=/api/pushes/1/complete12832026-10-01 07:39:25.827 UTC [69505] ERROR: relation "goose_db_version" does not exist at character 3612842026-10-01 07:39:25.827 UTC [69505] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12852026-10-01 07:39:25.830 UTC [69510] ERROR: relation "goose_db_version" does not exist at character 3612862026-10-01 07:39:25.830 UTC [69510] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12872026/10/01 07:39:25 INFO Received push request method=POST path=/api/pushes12882026/10/01 07:39:25 INFO Aborted multipart uploads count=012892026/10/01 07:39:25 WARN Force mode enabled - objects will be deleted immediately without grace period12902026/10/01 07:39:25 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2 objects-failed-to-delete=012912026/10/01 07:39:25 INFO Vacuumed table table=pending_closures12922026/10/01 07:39:26 INFO Vacuumed table table=pending_objects12932026/10/01 07:39:26 INFO Vacuumed table table=multipart_uploads12942026/10/01 07:39:26 OK 20241026095416_initial_model.sql (237.97ms)12952026/10/01 07:39:26 OK 20251210153512_drop_unused_gin_index.sql (3.31ms)12962026/10/01 07:39:26 INFO Vacuumed table table=closures12972026/10/01 07:39:26 INFO Vacuumed table table=objects12982026/10/01 07:39:26 INFO Received complete push request method=POST path=/api/pushes/2/complete1299--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.05s)1300=== CONT TestReadProxyRangeRequest13012026/10/01 07:39:26 OK 20251218171726_add_pins.sql (46.33ms)13022026/10/01 07:39:26 OK 20241026095416_initial_model.sql (247.8ms)13032026/10/01 07:39:26 OK 20260628120000_add_object_size_and_stats.sql (50.28ms)13042026/10/01 07:39:26 OK 20251210153512_drop_unused_gin_index.sql (1.51ms)13052026/10/01 07:39:26 OK 20241026095416_initial_model.sql (273.93ms)13062026/10/01 07:39:26 OK 20251210153512_drop_unused_gin_index.sql (8.18ms)13072026/10/01 07:39:26 OK 20251218171726_add_pins.sql (33.07ms)13082026/10/01 07:39:26 OK 20260905000000_add_claims.sql (43.98ms)13092026/10/01 07:39:26 OK 20260920000000_drop_claims.sql (2.93ms)13102026/10/01 07:39:26 OK 20251218171726_add_pins.sql (25.11ms)13112026/10/01 07:39:26 OK 20260923120000_add_pushes.sql (22.5ms)13122026/10/01 07:39:26 goose: successfully migrated database to version: 2026092312000013132026/10/01 07:39:26 OK 1_commit_pending_closure.sql (1.04ms)13142026/10/01 07:39:26 OK 2_object_stats_trigger.sql (225.21µs)13152026/10/01 07:39:26 OK 3_commit_push.sql (178.63µs)13162026/10/01 07:39:26 goose: up to current file version: 313172026/10/01 07:39:26 OK 20260628120000_add_object_size_and_stats.sql (51.17ms)13182026/10/01 07:39:26 OK 20260628120000_add_object_size_and_stats.sql (65.93ms)13192026/10/01 07:39:26 OK 20260905000000_add_claims.sql (103.08ms)13202026-10-01 07:39:26.353 UTC [69520] ERROR: relation "goose_db_version" does not exist at character 3613212026-10-01 07:39:26.353 UTC [69520] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13222026/10/01 07:39:26 OK 20260905000000_add_claims.sql (76.97ms)13232026/10/01 07:39:26 OK 20260920000000_drop_claims.sql (31.36ms)13242026/10/01 07:39:26 OK 20260920000000_drop_claims.sql (31.88ms)13252026/10/01 07:39:26 OK 20260923120000_add_pushes.sql (28.23ms)13262026/10/01 07:39:26 goose: successfully migrated database to version: 2026092312000013272026/10/01 07:39:26 OK 1_commit_pending_closure.sql (1.39ms)13282026/10/01 07:39:26 OK 2_object_stats_trigger.sql (325.38µs)13292026/10/01 07:39:26 OK 3_commit_push.sql (260.17µs)13302026/10/01 07:39:26 goose: up to current file version: 313312026/10/01 07:39:26 OK 20260923120000_add_pushes.sql (27.06ms)13322026/10/01 07:39:26 goose: successfully migrated database to version: 2026092312000013332026/10/01 07:39:26 OK 1_commit_pending_closure.sql (1.26ms)13342026/10/01 07:39:26 OK 2_object_stats_trigger.sql (270.88µs)13352026/10/01 07:39:26 OK 3_commit_push.sql (229.29µs)13362026/10/01 07:39:26 goose: up to current file version: 313372026/10/01 07:39:26 INFO Received push request method=POST path=/api/pushes13382026-10-01 07:39:26.683 UTC [69525] ERROR: relation "goose_db_version" does not exist at character 3613392026-10-01 07:39:26.683 UTC [69525] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13402026/10/01 07:39:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13412026/10/01 07:39:26 OK 20241026095416_initial_model.sql (303.4ms)13422026/10/01 07:39:26 OK 20251210153512_drop_unused_gin_index.sql (3.7ms)13432026/10/01 07:39:26 OK 20251218171726_add_pins.sql (65.54ms)13442026/10/01 07:39:26 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NDYxYmZlMGUtZWUzZi00NGExLWJhMDgtYTk1ZDhiMWYxNmZhLjYyNmQ5YWUwLThjZTctNDdhOC1hMWViLTUyMjI3M2UxZWI2NngxNzkwODQwMzY0OTM5MzE1MDAw parts=1013452026/10/01 07:39:26 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13462026/10/01 07:39:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13472026/10/01 07:39:26 INFO Signed narinfos id=1 count=11348--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (4.88s)1349=== CONT TestReadRedirectKeepsNarinfoProxied13502026/10/01 07:39:26 INFO Completed upload id=113512026/10/01 07:39:26 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013522026/10/01 07:39:26 INFO Received uploads request method=POST path=/api/pending_closures13532026/10/01 07:39:26 INFO Starting cleanup of old closures method=DELETE path=/api/closures13542026/10/01 07:39:26 INFO Aborted multipart uploads count=013552026/10/01 07:39:26 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013562026/10/01 07:39:26 OK 20260628120000_add_object_size_and_stats.sql (61.9ms)13572026/10/01 07:39:26 INFO Vacuumed table table=pending_closures13582026/10/01 07:39:26 INFO Vacuumed table table=pending_objects13592026/10/01 07:39:26 OK 20260905000000_add_claims.sql (31.4ms)13602026/10/01 07:39:26 INFO Vacuumed table table=multipart_uploads13612026/10/01 07:39:26 INFO Vacuumed table table=closures13622026/10/01 07:39:26 OK 20260920000000_drop_claims.sql (36.78ms)13632026/10/01 07:39:26 INFO Vacuumed table table=objects13642026/10/01 07:39:26 OK 20241026095416_initial_model.sql (173.3ms)13652026/10/01 07:39:26 OK 20251210153512_drop_unused_gin_index.sql (7.69ms)13662026/10/01 07:39:26 OK 20260923120000_add_pushes.sql (15.39ms)13672026/10/01 07:39:26 goose: successfully migrated database to version: 2026092312000013682026/10/01 07:39:26 OK 1_commit_pending_closure.sql (1.25ms)13692026/10/01 07:39:26 OK 2_object_stats_trigger.sql (219.5µs)13702026/10/01 07:39:26 OK 3_commit_push.sql (165.63µs)13712026/10/01 07:39:26 goose: up to current file version: 313722026/10/01 07:39:27 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001373--- PASS: TestService_createPendingClosureHandler (8.43s)1374=== CONT TestReadRedirectNar13752026/10/01 07:39:27 OK 20251218171726_add_pins.sql (28.27ms)1376=== RUN TestPush_RejectsBadRequests/root_not_in_objects1377=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1378=== RUN TestPush_RejectsBadRequests/no_roots1379=== PAUSE TestPush_RejectsBadRequests/no_roots1380=== RUN TestPush_RejectsBadRequests/no_objects1381=== PAUSE TestPush_RejectsBadRequests/no_objects1382=== RUN TestPush_RejectsBadRequests/bad_root1383=== PAUSE TestPush_RejectsBadRequests/bad_root1384=== CONT TestReadProxyDisabled13852026-10-01 07:39:27.024 UTC [69531] ERROR: relation "goose_db_version" does not exist at character 3613862026-10-01 07:39:27.024 UTC [69531] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13872026/10/01 07:39:27 OK 20260628120000_add_object_size_and_stats.sql (26.51ms)13882026/10/01 07:39:27 OK 20260905000000_add_claims.sql (71.5ms)13892026/10/01 07:39:27 OK 20260920000000_drop_claims.sql (39.89ms)13902026/10/01 07:39:27 OK 20260923120000_add_pushes.sql (15.76ms)13912026/10/01 07:39:27 goose: successfully migrated database to version: 2026092312000013922026/10/01 07:39:27 OK 1_commit_pending_closure.sql (985.04µs)13932026/10/01 07:39:27 OK 2_object_stats_trigger.sql (246.58µs)13942026/10/01 07:39:27 OK 3_commit_push.sql (199.08µs)13952026/10/01 07:39:27 goose: up to current file version: 313962026/10/01 07:39:27 OK 20241026095416_initial_model.sql (153.5ms)13972026/10/01 07:39:27 OK 20251210153512_drop_unused_gin_index.sql (7.99ms)13982026/10/01 07:39:27 OK 20251218171726_add_pins.sql (12.86ms)13992026-10-01 07:39:27.266 UTC [69544] ERROR: relation "goose_db_version" does not exist at character 3614002026-10-01 07:39:27.266 UTC [69544] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14012026/10/01 07:39:27 OK 20260628120000_add_object_size_and_stats.sql (33.96ms)14022026/10/01 07:39:27 INFO Received push request method=POST path=/api/pushes14032026/10/01 07:39:27 OK 20260905000000_add_claims.sql (34.78ms)1404--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (4.94s)1405=== CONT TestReadProxyRootRedirectsToIndexHTML14062026/10/01 07:39:27 OK 20260920000000_drop_claims.sql (78.64ms)14072026/10/01 07:39:27 OK 20260923120000_add_pushes.sql (11.87ms)14082026/10/01 07:39:27 goose: successfully migrated database to version: 2026092312000014092026/10/01 07:39:27 OK 1_commit_pending_closure.sql (1.92ms)14102026/10/01 07:39:27 OK 2_object_stats_trigger.sql (438.42µs)14112026/10/01 07:39:27 OK 3_commit_push.sql (368.38µs)14122026/10/01 07:39:27 goose: up to current file version: 314132026/10/01 07:39:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14142026/10/01 07:39:27 OK 20241026095416_initial_model.sql (174.44ms)14152026/10/01 07:39:27 OK 20251210153512_drop_unused_gin_index.sql (27.05ms)14162026/10/01 07:39:27 OK 20251218171726_add_pins.sql (28.61ms)14172026/10/01 07:39:27 OK 20260628120000_add_object_size_and_stats.sql (21.6ms)14182026/10/01 07:39:27 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NDYxYmZlMGUtZWUzZi00NGExLWJhMDgtYTk1ZDhiMWYxNmZhLjFlOGUyYmY3LTBhMWItNDIwMC05MjI3LTdiNTcxMTMzMjNjM3gxNzkwODQwMzY1MzMwNzMyMDAw parts=121419--- PASS: TestRedundantMultipartUpload (7.26s)1420=== CONT TestCompleteMultipartUpload_ErrorButObjectExists14212026/10/01 07:39:27 OK 20260905000000_add_claims.sql (78.59ms)14222026/10/01 07:39:27 INFO Received push request method=POST path=/api/pushes14232026/10/01 07:39:27 OK 20260920000000_drop_claims.sql (40.03ms)14242026/10/01 07:39:27 OK 20260923120000_add_pushes.sql (17.97ms)14252026/10/01 07:39:27 goose: successfully migrated database to version: 2026092312000014262026/10/01 07:39:27 OK 1_commit_pending_closure.sql (3.01ms)14272026/10/01 07:39:27 OK 2_object_stats_trigger.sql (617.63µs)14282026/10/01 07:39:27 OK 3_commit_push.sql (398.96µs)14292026/10/01 07:39:27 goose: up to current file version: 314302026/10/01 07:39:27 INFO Received complete push request method=POST path=/api/pushes/1/complete1431--- PASS: TestPush_CompleteCommitsEveryRoot (4.46s)1432=== CONT TestService_ReadScope_PublicByDefault1433--- PASS: TestObjectStatsTrigger (4.20s)1434=== CONT TestClientIntegration14352026-10-01 07:39:28.090 UTC [69565] ERROR: relation "goose_db_version" does not exist at character 3614362026-10-01 07:39:28.090 UTC [69565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14372026/10/01 07:39:28 INFO Received uploads request method=POST path=/api/pending_closures14382026/10/01 07:39:28 OK 20241026095416_initial_model.sql (141.9ms)14392026/10/01 07:39:28 OK 20251210153512_drop_unused_gin_index.sql (9.83ms)14402026/10/01 07:39:28 OK 20251218171726_add_pins.sql (3.7ms)14412026/10/01 07:39:28 OK 20260628120000_add_object_size_and_stats.sql (29.92ms)14422026/10/01 07:39:28 OK 20260905000000_add_claims.sql (12.93ms)14432026/10/01 07:39:28 OK 20260920000000_drop_claims.sql (15.28ms)14442026/10/01 07:39:28 OK 20260923120000_add_pushes.sql (3.38ms)14452026/10/01 07:39:28 goose: successfully migrated database to version: 2026092312000014462026/10/01 07:39:28 OK 1_commit_pending_closure.sql (907.29µs)14472026/10/01 07:39:28 OK 2_object_stats_trigger.sql (227.79µs)14482026/10/01 07:39:28 OK 3_commit_push.sql (181.63µs)14492026/10/01 07:39:28 goose: up to current file version: 314502026-10-01 07:39:28.367 UTC [69568] ERROR: relation "goose_db_version" does not exist at character 3614512026-10-01 07:39:28.367 UTC [69568] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14522026/10/01 07:39:28 INFO Received cleanup request method=DELETE path=/api/pending_closures14532026/10/01 07:39:28 INFO Aborted multipart uploads count=11454--- PASS: TestMultipartCleanup (4.27s)1455=== CONT TestClientErrorHandling1456=== RUN TestClientErrorHandling/InvalidStorePath1457=== PAUSE TestClientErrorHandling/InvalidStorePath1458=== RUN TestClientErrorHandling/InvalidAuthToken1459=== PAUSE TestClientErrorHandling/InvalidAuthToken1460=== RUN TestClientErrorHandling/ServerNotAvailable1461=== PAUSE TestClientErrorHandling/ServerNotAvailable1462=== CONT TestClientCADerivations1463--- PASS: TestReadProxyConditionalGet (4.06s)1464=== CONT TestCacheStatsHandler14652026/10/01 07:39:28 OK 20241026095416_initial_model.sql (189.93ms)14662026/10/01 07:39:28 OK 20251210153512_drop_unused_gin_index.sql (9.15ms)14672026/10/01 07:39:28 OK 20251218171726_add_pins.sql (35.53ms)14682026/10/01 07:39:28 OK 20260628120000_add_object_size_and_stats.sql (22.31ms)14692026-10-01 07:39:28.670 UTC [69580] ERROR: relation "goose_db_version" does not exist at character 3614702026-10-01 07:39:28.670 UTC [69580] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14712026-10-01 07:39:28.682 UTC [69581] ERROR: relation "goose_db_version" does not exist at character 3614722026-10-01 07:39:28.682 UTC [69581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14732026/10/01 07:39:28 OK 20260905000000_add_claims.sql (37.35ms)14742026/10/01 07:39:28 OK 20260920000000_drop_claims.sql (24.67ms)14752026/10/01 07:39:28 OK 20260923120000_add_pushes.sql (10.55ms)14762026/10/01 07:39:28 goose: successfully migrated database to version: 2026092312000014772026/10/01 07:39:28 OK 1_commit_pending_closure.sql (2.08ms)14782026/10/01 07:39:28 OK 2_object_stats_trigger.sql (457.58µs)14792026/10/01 07:39:28 OK 3_commit_push.sql (354.5µs)14802026/10/01 07:39:28 goose: up to current file version: 31481--- PASS: TestReadProxyRangeRequest (2.69s)1482=== CONT TestCacheConfigHandler1483=== RUN TestCacheConfigHandler/full_config,_no_issuer1484=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1485=== RUN TestCacheConfigHandler/no_cache_url_configured1486=== PAUSE TestCacheConfigHandler/no_cache_url_configured1487=== RUN TestCacheConfigHandler/no_signing_keys1488=== PAUSE TestCacheConfigHandler/no_signing_keys1489=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1490=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1491=== CONT TestSweepSkipsRowsLockedByPush14922026/10/01 07:39:28 OK 20241026095416_initial_model.sql (179.09ms)14932026/10/01 07:39:28 OK 20251210153512_drop_unused_gin_index.sql (4.24ms)14942026/10/01 07:39:28 OK 20241026095416_initial_model.sql (164.18ms)14952026/10/01 07:39:28 OK 20251210153512_drop_unused_gin_index.sql (5.48ms)14962026/10/01 07:39:28 OK 20251218171726_add_pins.sql (26.5ms)14972026/10/01 07:39:28 OK 20251218171726_add_pins.sql (20.09ms)14982026/10/01 07:39:28 OK 20260628120000_add_object_size_and_stats.sql (21.53ms)14992026/10/01 07:39:28 OK 20260628120000_add_object_size_and_stats.sql (21.85ms)15002026/10/01 07:39:28 OK 20260905000000_add_claims.sql (24.88ms)15012026/10/01 07:39:28 OK 20260905000000_add_claims.sql (25.48ms)15022026-10-01 07:39:28.996 UTC [69588] ERROR: relation "goose_db_version" does not exist at character 3615032026-10-01 07:39:28.996 UTC [69588] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15042026/10/01 07:39:28 OK 20260920000000_drop_claims.sql (26.03ms)15052026/10/01 07:39:28 OK 20260920000000_drop_claims.sql (25.76ms)15062026/10/01 07:39:29 OK 20260923120000_add_pushes.sql (7.91ms)15072026/10/01 07:39:29 OK 20260923120000_add_pushes.sql (7.86ms)15082026/10/01 07:39:29 goose: successfully migrated database to version: 2026092312000015092026/10/01 07:39:29 goose: successfully migrated database to version: 2026092312000015102026/10/01 07:39:29 OK 1_commit_pending_closure.sql (2.64ms)15112026/10/01 07:39:29 OK 1_commit_pending_closure.sql (2.74ms)15122026/10/01 07:39:29 OK 2_object_stats_trigger.sql (656.17µs)15132026/10/01 07:39:29 OK 2_object_stats_trigger.sql (697.29µs)15142026/10/01 07:39:29 OK 3_commit_push.sql (420.17µs)15152026/10/01 07:39:29 goose: up to current file version: 315162026/10/01 07:39:29 OK 3_commit_push.sql (389.88µs)15172026/10/01 07:39:29 goose: up to current file version: 31518--- PASS: TestReadRedirectKeepsNarinfoProxied (2.25s)1519=== CONT TestGCTaskStore_ConflictDifferentParams1520--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1521=== CONT TestGCTaskStore_DeduplicateSameParams1522--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1523=== CONT TestGCTaskStore_StartNew1524--- PASS: TestGCTaskStore_StartNew (0.00s)1525=== CONT TestGetExistingObjectsLocksRows15262026-10-01 07:39:29.193 UTC [69594] ERROR: relation "goose_db_version" does not exist at character 3615272026-10-01 07:39:29.193 UTC [69594] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15282026/10/01 07:39:29 OK 20241026095416_initial_model.sql (147.13ms)15292026/10/01 07:39:29 OK 20251210153512_drop_unused_gin_index.sql (9.87ms)15302026/10/01 07:39:29 OK 20251218171726_add_pins.sql (14.79ms)15312026/10/01 07:39:29 OK 20260628120000_add_object_size_and_stats.sql (21.75ms)15322026/10/01 07:39:29 OK 20260905000000_add_claims.sql (47.04ms)15332026-10-01 07:39:29.294 UTC [69597] ERROR: relation "goose_db_version" does not exist at character 3615342026-10-01 07:39:29.294 UTC [69597] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15352026/10/01 07:39:29 OK 20260920000000_drop_claims.sql (12.77ms)15362026/10/01 07:39:29 OK 20260923120000_add_pushes.sql (11.14ms)15372026/10/01 07:39:29 goose: successfully migrated database to version: 2026092312000015382026/10/01 07:39:29 OK 1_commit_pending_closure.sql (3.33ms)15392026/10/01 07:39:29 OK 2_object_stats_trigger.sql (911.75µs)15402026/10/01 07:39:29 OK 3_commit_push.sql (1.21ms)15412026/10/01 07:39:29 goose: up to current file version: 315422026/10/01 07:39:29 OK 20241026095416_initial_model.sql (105.69ms)15432026/10/01 07:39:29 OK 20251210153512_drop_unused_gin_index.sql (7.77ms)1544--- PASS: TestReadRedirectNar (2.36s)1545=== CONT TestRegisterCompletedObjectNeedsPendingRow15462026/10/01 07:39:29 OK 20251218171726_add_pins.sql (38.39ms)15472026/10/01 07:39:29 OK 20260628120000_add_object_size_and_stats.sql (30.72ms)15482026/10/01 07:39:29 OK 20260905000000_add_claims.sql (48.04ms)15492026/10/01 07:39:29 OK 20260920000000_drop_claims.sql (11.17ms)15502026/10/01 07:39:29 OK 20260923120000_add_pushes.sql (24.95ms)15512026/10/01 07:39:29 goose: successfully migrated database to version: 2026092312000015522026/10/01 07:39:29 OK 1_commit_pending_closure.sql (2.21ms)15532026/10/01 07:39:29 OK 2_object_stats_trigger.sql (505.54µs)15542026/10/01 07:39:29 OK 3_commit_push.sql (394.38µs)15552026/10/01 07:39:29 goose: up to current file version: 315562026/10/01 07:39:29 OK 20241026095416_initial_model.sql (174.43ms)15572026/10/01 07:39:29 OK 20251210153512_drop_unused_gin_index.sql (3.06ms)15582026-10-01 07:39:29.527 UTC [69600] ERROR: relation "goose_db_version" does not exist at character 3615592026-10-01 07:39:29.527 UTC [69600] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15602026/10/01 07:39:29 OK 20251218171726_add_pins.sql (10.9ms)15612026/10/01 07:39:29 OK 20260628120000_add_object_size_and_stats.sql (38.76ms)15622026/10/01 07:39:29 OK 20260905000000_add_claims.sql (23.17ms)15632026/10/01 07:39:29 OK 20260920000000_drop_claims.sql (20.5ms)15642026/10/01 07:39:29 OK 20260923120000_add_pushes.sql (7.61ms)15652026/10/01 07:39:29 goose: successfully migrated database to version: 202609231200001566--- PASS: TestReadProxyDisabled (2.60s)1567=== CONT TestCreatePin_ReservedPins15682026/10/01 07:39:29 OK 1_commit_pending_closure.sql (2.84ms)15692026/10/01 07:39:29 OK 2_object_stats_trigger.sql (556.04µs)15702026/10/01 07:39:29 OK 3_commit_push.sql (239.75µs)15712026/10/01 07:39:29 goose: up to current file version: 315722026/10/01 07:39:29 OK 20241026095416_initial_model.sql (107.76ms)15732026/10/01 07:39:29 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)15742026/10/01 07:39:29 OK 20251218171726_add_pins.sql (13.8ms)15752026/10/01 07:39:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58266/oidc15762026/10/01 07:39:29 OK 20260628120000_add_object_size_and_stats.sql (15.1ms)15772026/10/01 07:39:29 OK 20260905000000_add_claims.sql (21.43ms)15782026-10-01 07:39:29.744 UTC [69606] ERROR: relation "goose_db_version" does not exist at character 3615792026-10-01 07:39:29.744 UTC [69606] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15802026/10/01 07:39:29 OK 20260920000000_drop_claims.sql (21.71ms)15812026/10/01 07:39:29 OK 20260923120000_add_pushes.sql (1.76ms)15822026/10/01 07:39:29 goose: successfully migrated database to version: 2026092312000015832026/10/01 07:39:29 OK 1_commit_pending_closure.sql (1.09ms)15842026/10/01 07:39:29 OK 2_object_stats_trigger.sql (908.13µs)15852026/10/01 07:39:29 OK 3_commit_push.sql (211.83µs)15862026/10/01 07:39:29 goose: up to current file version: 31587--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.45s)1588=== CONT TestResolveDBConnectionString1589=== RUN TestResolveDBConnectionString/flag_wins1590=== PAUSE TestResolveDBConnectionString/flag_wins1591=== RUN TestResolveDBConnectionString/file_when_flag_empty1592=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1593=== RUN TestResolveDBConnectionString/missing_file_is_an_error1594=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1595=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1596=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1597=== RUN TestResolveDBConnectionString/nothing_configured1598=== PAUSE TestResolveDBConnectionString/nothing_configured1599=== CONT TestPushDedupSurvivesConcurrentGC16002026/10/01 07:39:29 OK 20241026095416_initial_model.sql (111.18ms)16012026/10/01 07:39:29 OK 20251210153512_drop_unused_gin_index.sql (13.99ms)16022026/10/01 07:39:29 OK 20251218171726_add_pins.sql (20.48ms)16032026-10-01 07:39:29.949 UTC [69614] ERROR: relation "goose_db_version" does not exist at character 3616042026-10-01 07:39:29.949 UTC [69614] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16052026/10/01 07:39:29 OK 20260628120000_add_object_size_and_stats.sql (40.38ms)16062026/10/01 07:39:29 OK 20260905000000_add_claims.sql (27.69ms)16072026/10/01 07:39:30 OK 20260920000000_drop_claims.sql (15.99ms)16082026/10/01 07:39:30 OK 20260923120000_add_pushes.sql (4.09ms)16092026/10/01 07:39:30 goose: successfully migrated database to version: 2026092312000016102026/10/01 07:39:30 OK 1_commit_pending_closure.sql (1ms)16112026/10/01 07:39:30 OK 2_object_stats_trigger.sql (213.83µs)16122026/10/01 07:39:30 OK 3_commit_push.sql (183.33µs)16132026/10/01 07:39:30 goose: up to current file version: 316142026-10-01 07:39:30.048 UTC [69615] ERROR: relation "goose_db_version" does not exist at character 3616152026-10-01 07:39:30.048 UTC [69615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16162026/10/01 07:39:30 OK 20241026095416_initial_model.sql (102.06ms)16172026/10/01 07:39:30 INFO Received uploads request method=POST path=/api/pending_closures16182026/10/01 07:39:30 OK 20251210153512_drop_unused_gin_index.sql (3.72ms)16192026/10/01 07:39:30 OK 20251218171726_add_pins.sql (33.61ms)16202026/10/01 07:39:30 OK 20260628120000_add_object_size_and_stats.sql (35.3ms)16212026/10/01 07:39:30 OK 20260905000000_add_claims.sql (44.38ms)16222026/10/01 07:39:30 OK 20260920000000_drop_claims.sql (21.92ms)16232026/10/01 07:39:30 OK 20260923120000_add_pushes.sql (19.78ms)16242026/10/01 07:39:30 goose: successfully migrated database to version: 2026092312000016252026/10/01 07:39:30 OK 1_commit_pending_closure.sql (909.88µs)16262026/10/01 07:39:30 OK 2_object_stats_trigger.sql (240.17µs)16272026/10/01 07:39:30 OK 3_commit_push.sql (172.33µs)16282026/10/01 07:39:30 goose: up to current file version: 316292026/10/01 07:39:30 OK 20241026095416_initial_model.sql (172.8ms)16302026/10/01 07:39:30 OK 20251210153512_drop_unused_gin_index.sql (12.86ms)16312026/10/01 07:39:30 OK 20251218171726_add_pins.sql (19.87ms)16322026/10/01 07:39:30 OK 20260628120000_add_object_size_and_stats.sql (12.02ms)16332026/10/01 07:39:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16342026/10/01 07:39:30 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDYxYmZlMGUtZWUzZi00NGExLWJhMDgtYTk1ZDhiMWYxNmZhLmMwNmYwMjhmLTllYjktNGNiMS04YjlkLTRhZDVlZWI0OWJhN3gxNzkwODQwMzcwMTI1MTg4MDAw16352026/10/01 07:39:30 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDYxYmZlMGUtZWUzZi00NGExLWJhMDgtYTk1ZDhiMWYxNmZhLmMwNmYwMjhmLTllYjktNGNiMS04YjlkLTRhZDVlZWI0OWJhN3gxNzkwODQwMzcwMTI1MTg4MDAw parts=11636--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.74s)1637=== CONT TestGCMetrics16382026/10/01 07:39:30 OK 20260905000000_add_claims.sql (37.91ms)1639--- PASS: TestService_ReadScope_PublicByDefault (2.55s)1640=== CONT TestGCBugBareHashReferences16412026/10/01 07:39:30 OK 20260920000000_drop_claims.sql (11.16ms)16422026/10/01 07:39:30 OK 20260923120000_add_pushes.sql (2.83ms)16432026/10/01 07:39:30 goose: successfully migrated database to version: 2026092312000016442026/10/01 07:39:30 OK 1_commit_pending_closure.sql (1.16ms)16452026/10/01 07:39:30 OK 2_object_stats_trigger.sql (325.54µs)16462026/10/01 07:39:30 OK 3_commit_push.sql (199.04µs)16472026/10/01 07:39:30 goose: up to current file version: 316482026-10-01 07:39:30.412 UTC [69619] ERROR: relation "goose_db_version" does not exist at character 3616492026-10-01 07:39:30.412 UTC [69619] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16502026/10/01 07:39:30 OK 20241026095416_initial_model.sql (102.24ms)16512026/10/01 07:39:30 OK 20251210153512_drop_unused_gin_index.sql (6.72ms)16522026-10-01 07:39:30.604 UTC [69621] ERROR: relation "goose_db_version" does not exist at character 3616532026-10-01 07:39:30.604 UTC [69621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16542026/10/01 07:39:30 OK 20251218171726_add_pins.sql (18.67ms)16552026/10/01 07:39:30 OK 20260628120000_add_object_size_and_stats.sql (45.47ms)16562026/10/01 07:39:30 OK 20260905000000_add_claims.sql (41.12ms)16572026/10/01 07:39:30 OK 20260920000000_drop_claims.sql (40.11ms)16582026/10/01 07:39:30 OK 20260923120000_add_pushes.sql (9.82ms)16592026/10/01 07:39:30 goose: successfully migrated database to version: 2026092312000016602026/10/01 07:39:30 OK 1_commit_pending_closure.sql (2.32ms)16612026/10/01 07:39:30 OK 2_object_stats_trigger.sql (309.54µs)16622026/10/01 07:39:30 OK 3_commit_push.sql (213.67µs)16632026/10/01 07:39:30 goose: up to current file version: 316642026/10/01 07:39:30 OK 20241026095416_initial_model.sql (100.05ms)16652026/10/01 07:39:30 OK 20251210153512_drop_unused_gin_index.sql (9.62ms)16662026/10/01 07:39:30 OK 20251218171726_add_pins.sql (21.42ms)1667=== NAME TestClientIntegration1668 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-68619-1936780597/TestClientIntegration1677775663/002/store/32nrbx6j1d54nm96qy9n4rw5yh6sdql4-test-file.txt16692026/10/01 07:39:30 OK 20260628120000_add_object_size_and_stats.sql (25.93ms)16702026/10/01 07:39:30 OK 20260905000000_add_claims.sql (18.13ms)16712026/10/01 07:39:30 OK 20260920000000_drop_claims.sql (13.2ms)16722026/10/01 07:39:30 OK 20260923120000_add_pushes.sql (12.99ms)16732026/10/01 07:39:30 goose: successfully migrated database to version: 2026092312000016742026/10/01 07:39:30 OK 1_commit_pending_closure.sql (1.75ms)16752026/10/01 07:39:30 OK 2_object_stats_trigger.sql (269.88µs)16762026/10/01 07:39:30 OK 3_commit_push.sql (193.83µs)16772026/10/01 07:39:30 goose: up to current file version: 316782026/10/01 07:39:30 INFO Received push request method=POST path=/api/pushes16792026/10/01 07:39:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16802026/10/01 07:39:30 INFO Uploading 32nrbx6j1d54nm96qy9n4rw5yh6sdql4-test-file.txt (152B)16812026/10/01 07:39:30 WARN Failed to register uploaded object key=32nrbx6j1d54nm96qy9n4rw5yh6sdql4.ls error="server returned 404: 404 page not found\n"16822026/10/01 07:39:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16832026/10/01 07:39:30 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16842026/10/01 07:39:30 INFO Signed narinfos id=1 count=116852026/10/01 07:39:30 INFO Uploading 1 narinfos16862026/10/01 07:39:30 INFO Received complete push request method=POST path=/api/pushes/1/complete16872026/10/01 07:39:30 WARN Failed to register uploaded object key=32nrbx6j1d54nm96qy9n4rw5yh6sdql4.narinfo error="server returned 404: 404 page not found\n"16882026/10/01 07:39:31 INFO Upload complete. (159ms)16892026/10/01 07:39:31 INFO All 1 paths already cached1690 client_integration_test.go:312: Retrieved narinfo from S3:1691 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestClientIntegration1677775663/002/store/32nrbx6j1d54nm96qy9n4rw5yh6sdql4-test-file.txt1692 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1693 Compression: zstd1694 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11695 NarSize: 1521696 References: 1697 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11698 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1699 client_integration_test.go:313: Decompressed .ls content (64 bytes):1700 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1701 client_integration_test.go:316: Testing garbage collection...17022026/10/01 07:39:31 INFO Starting cleanup of old closures method=DELETE path=/api/closures17032026/10/01 07:39:31 INFO Garbage collection started17042026/10/01 07:39:31 INFO Aborted multipart uploads count=017052026/10/01 07:39:31 WARN Force mode enabled - objects will be deleted immediately without grace period17062026-10-01 07:39:31.080 UTC [69637] ERROR: relation "goose_db_version" does not exist at character 3617072026-10-01 07:39:31.080 UTC [69637] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17082026/10/01 07:39:31 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=017092026/10/01 07:39:31 INFO Vacuumed table table=pending_closures17102026/10/01 07:39:31 INFO Vacuumed table table=pending_objects17112026/10/01 07:39:31 INFO Vacuumed table table=multipart_uploads17122026/10/01 07:39:31 INFO Vacuumed table table=closures1713--- PASS: TestCacheStatsHandler (2.72s)1714=== CONT TestLeadEndsOnShutdown17152026/10/01 07:39:31 INFO Vacuumed table table=objects17162026-10-01 07:39:31.215 UTC [69640] ERROR: relation "goose_db_version" does not exist at character 3617172026-10-01 07:39:31.215 UTC [69640] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17182026/10/01 07:39:31 OK 20241026095416_initial_model.sql (138.91ms)17192026/10/01 07:39:31 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)17202026/10/01 07:39:31 OK 20251218171726_add_pins.sql (18.18ms)1721=== NAME TestClientCADerivations1722 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-68619-1936780597/TestClientCADerivations2762734683/001/store/n3m5zmd0nngci98p97cxz055phhkwk93-ca-test17232026/10/01 07:39:31 OK 20260628120000_add_object_size_and_stats.sql (16.91ms)17242026/10/01 07:39:31 OK 20260905000000_add_claims.sql (31.4ms)1725 client_ca_test.go:139: Found 1 dependencies (including self)17262026/10/01 07:39:31 OK 20260920000000_drop_claims.sql (27.09ms)17272026/10/01 07:39:31 OK 20241026095416_initial_model.sql (100.72ms)17282026/10/01 07:39:31 OK 20260923120000_add_pushes.sql (8.03ms)17292026/10/01 07:39:31 goose: successfully migrated database to version: 2026092312000017302026/10/01 07:39:31 OK 1_commit_pending_closure.sql (1.4ms)17312026/10/01 07:39:31 OK 2_object_stats_trigger.sql (243.75µs)17322026/10/01 07:39:31 OK 3_commit_push.sql (164.08µs)17332026/10/01 07:39:31 goose: up to current file version: 317342026/10/01 07:39:31 OK 20251210153512_drop_unused_gin_index.sql (8.28ms)17352026/10/01 07:39:31 OK 20251218171726_add_pins.sql (33.86ms)17362026/10/01 07:39:31 INFO Aborted multipart uploads count=017372026/10/01 07:39:31 WARN Force mode enabled - objects will be deleted immediately without grace period17382026/10/01 07:39: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=017392026/10/01 07:39:31 INFO Vacuumed table table=pending_closures17402026/10/01 07:39:31 OK 20260628120000_add_object_size_and_stats.sql (24.52ms)17412026/10/01 07:39:31 INFO Vacuumed table table=pending_objects17422026/10/01 07:39:31 INFO Vacuumed table table=multipart_uploads17432026/10/01 07:39:31 INFO Vacuumed table table=closures17442026/10/01 07:39:31 INFO Vacuumed table table=objects17452026/10/01 07:39:31 INFO Aborted multipart uploads count=017462026/10/01 07:39:31 WARN Force mode enabled - objects will be deleted immediately without grace period17472026/10/01 07:39:31 INFO Received push request method=POST path=/api/pushes17482026/10/01 07:39:31 OK 20260905000000_add_claims.sql (51.46ms)17492026/10/01 07:39:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17502026/10/01 07:39:31 INFO Uploading n3m5zmd0nngci98p97cxz055phhkwk93-ca-test (144B)17512026/10/01 07:39:31 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=017522026/10/01 07:39:31 INFO Vacuumed table table=pending_closures17532026/10/01 07:39:31 INFO Vacuumed table table=pending_objects17542026/10/01 07:39:31 INFO Vacuumed table table=multipart_uploads17552026/10/01 07:39:31 INFO Vacuumed table table=closures17562026/10/01 07:39:31 OK 20260920000000_drop_claims.sql (5.56ms)17572026/10/01 07:39:31 INFO Vacuumed table table=objects1758--- PASS: TestSweepSkipsRowsLockedByPush (2.69s)1759=== CONT TestLeadElectsOneAndHandsOver17602026/10/01 07:39:31 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"17612026/10/01 07:39:31 WARN Failed to register uploaded object key=n3m5zmd0nngci98p97cxz055phhkwk93.ls error="server returned 404: 404 page not found\n"17622026/10/01 07:39:31 OK 20260923120000_add_pushes.sql (34.32ms)17632026/10/01 07:39:31 goose: successfully migrated database to version: 2026092312000017642026/10/01 07:39:31 OK 1_commit_pending_closure.sql (911.96µs)17652026/10/01 07:39:31 OK 2_object_stats_trigger.sql (194.83µs)17662026/10/01 07:39:31 OK 3_commit_push.sql (150.71µs)17672026/10/01 07:39:31 goose: up to current file version: 317682026/10/01 07:39:31 WARN Failed to register uploaded object key=log/r4v24rriakvpc97bsh4hbdl9ma18pcmn-ca-test.drv error="server returned 404: 404 page not found\n"17692026/10/01 07:39:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17702026/10/01 07:39:31 INFO Signed narinfos id=1 count=117712026/10/01 07:39:31 INFO Uploading 1 narinfos17722026/10/01 07:39:31 INFO Received complete push request method=POST path=/api/pushes/1/complete17732026/10/01 07:39:31 WARN Failed to register uploaded object key=n3m5zmd0nngci98p97cxz055phhkwk93.narinfo error="server returned 404: 404 page not found\n"17742026/10/01 07:39:31 INFO Upload complete. (215ms)1775=== NAME TestClientCADerivations1776 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestClientCADerivations2762734683/001/store/n3m5zmd0nngci98p97cxz055phhkwk93-ca-test1777 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1778 Compression: zstd1779 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1780 NarSize: 1441781 References: 1782 Deriver: /nix/var/nix/builds/nix-68619-1936780597/TestClientCADerivations2762734683/001/store/r4v24rriakvpc97bsh4hbdl9ma18pcmn-ca-test.drv1783 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1784 client_ca_test.go:185: Checking for realisation files in S3...1785 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1786 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1787--- PASS: TestGetExistingObjectsLocksRows (2.58s)1788=== CONT TestReadProxy4041789=== NAME TestClientCADerivations1790 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket39?endpoint=http://localhost:57792®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-68619-1936780597/TestClientCADerivations2762734683/001/store'1791 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11792--- PASS: TestClientCADerivations (3.33s)1793=== CONT TestReadProxyHead17942026-10-01 07:39:31.766 UTC [69664] ERROR: relation "goose_db_version" does not exist at character 3617952026-10-01 07:39:31.766 UTC [69664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17962026-10-01 07:39:31.768 UTC [69665] ERROR: relation "goose_db_version" does not exist at character 3617972026-10-01 07:39:31.768 UTC [69665] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1798--- PASS: TestRegisterCompletedObjectNeedsPendingRow (2.52s)1799=== CONT TestReadProxyInvalidPath18002026/10/01 07:39:31 OK 20241026095416_initial_model.sql (136.76ms)18012026/10/01 07:39:31 OK 20251210153512_drop_unused_gin_index.sql (8.5ms)18022026/10/01 07:39:31 OK 20241026095416_initial_model.sql (130.4ms)18032026/10/01 07:39:31 OK 20251210153512_drop_unused_gin_index.sql (1.77ms)18042026/10/01 07:39:31 OK 20251218171726_add_pins.sql (5.02ms)18052026/10/01 07:39:31 OK 20251218171726_add_pins.sql (18.13ms)18062026/10/01 07:39:31 OK 20260628120000_add_object_size_and_stats.sql (26.79ms)18072026/10/01 07:39:31 OK 20260628120000_add_object_size_and_stats.sql (20.12ms)18082026/10/01 07:39:32 OK 20260905000000_add_claims.sql (27.08ms)18092026/10/01 07:39:32 OK 20260905000000_add_claims.sql (19.28ms)18102026/10/01 07:39:32 OK 20260920000000_drop_claims.sql (14.33ms)18112026/10/01 07:39:32 OK 20260920000000_drop_claims.sql (13.8ms)18122026/10/01 07:39:32 OK 20260923120000_add_pushes.sql (2.68ms)18132026/10/01 07:39:32 goose: successfully migrated database to version: 2026092312000018142026/10/01 07:39:32 OK 20260923120000_add_pushes.sql (2.68ms)18152026/10/01 07:39:32 goose: successfully migrated database to version: 2026092312000018162026/10/01 07:39:32 OK 1_commit_pending_closure.sql (1.08ms)18172026/10/01 07:39:32 OK 1_commit_pending_closure.sql (1.67ms)18182026/10/01 07:39:32 OK 2_object_stats_trigger.sql (307.83µs)18192026/10/01 07:39:32 OK 2_object_stats_trigger.sql (301.63µs)18202026/10/01 07:39:32 OK 3_commit_push.sql (188.96µs)18212026/10/01 07:39:32 goose: up to current file version: 318222026/10/01 07:39:32 OK 3_commit_push.sql (199.21µs)18232026/10/01 07:39:32 goose: up to current file version: 318242026/10/01 07:39:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18252026/10/01 07:39:32 WARN Refused reserved pin name=worker-x86_64-linux18262026/10/01 07:39:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18272026/10/01 07:39:32 INFO Received create pin request method=POST path=/api/pins/my-app18282026/10/01 07:39:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1829--- PASS: TestCreatePin_ReservedPins (2.52s)1830=== CONT TestPinProtectsFromGC18312026-10-01 07:39:32.395 UTC [69682] ERROR: relation "goose_db_version" does not exist at character 3618322026-10-01 07:39:32.395 UTC [69682] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18332026/10/01 07:39:32 INFO Received uploads request method=POST path=/api/pending_closures18342026/10/01 07:39:32 INFO Aborted multipart uploads count=018352026/10/01 07:39:32 OK 20241026095416_initial_model.sql (171.56ms)18362026/10/01 07:39:32 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)18372026/10/01 07:39:32 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018382026/10/01 07:39:32 INFO Aborted multipart uploads count=018392026/10/01 07:39:32 WARN Force mode enabled - objects will be deleted immediately without grace period18402026/10/01 07:39:32 INFO Vacuumed table table=pending_closures18412026/10/01 07:39:32 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=018422026/10/01 07:39:32 INFO Vacuumed table table=pending_closures18432026/10/01 07:39:32 INFO Vacuumed table table=pending_objects18442026/10/01 07:39:32 INFO Vacuumed table table=multipart_uploads18452026/10/01 07:39:32 INFO Vacuumed table table=closures18462026/10/01 07:39:32 INFO Vacuumed table table=objects1847--- PASS: TestGCMetrics (2.29s)1848=== CONT TestClientMultipleUploads18492026/10/01 07:39:32 OK 20251218171726_add_pins.sql (26.45ms)18502026/10/01 07:39:32 INFO Vacuumed table table=pending_objects18512026/10/01 07:39:32 INFO Vacuumed table table=multipart_uploads18522026/10/01 07:39:32 OK 20260628120000_add_object_size_and_stats.sql (35.57ms)18532026/10/01 07:39:32 INFO Vacuumed table table=closures18542026/10/01 07:39:32 INFO Vacuumed table table=objects18552026/10/01 07:39:32 INFO Aborted multipart uploads count=018562026/10/01 07:39:32 WARN Force mode enabled - objects will be deleted immediately without grace period18572026/10/01 07:39:32 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=018582026/10/01 07:39:32 OK 20260905000000_add_claims.sql (9.52ms)18592026/10/01 07:39:32 INFO Vacuumed table table=pending_closures18602026/10/01 07:39:32 INFO Vacuumed table table=pending_objects18612026/10/01 07:39:32 INFO Vacuumed table table=multipart_uploads18622026/10/01 07:39:32 OK 20260920000000_drop_claims.sql (5.82ms)18632026/10/01 07:39:32 INFO Vacuumed table table=closures18642026/10/01 07:39:32 INFO Vacuumed table table=objects1865--- PASS: TestPushDedupSurvivesConcurrentGC (2.83s)1866=== CONT TestClientSharedPathCommittedMidPush18672026/10/01 07:39:32 OK 20260923120000_add_pushes.sql (9.13ms)18682026/10/01 07:39:32 goose: successfully migrated database to version: 2026092312000018692026/10/01 07:39:32 OK 1_commit_pending_closure.sql (1.32ms)18702026/10/01 07:39:32 OK 2_object_stats_trigger.sql (237.5µs)18712026/10/01 07:39:32 OK 3_commit_push.sql (172.96µs)18722026/10/01 07:39:32 goose: up to current file version: 318732026-10-01 07:39:32.802 UTC [69700] ERROR: relation "goose_db_version" does not exist at character 3618742026-10-01 07:39:32.802 UTC [69700] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18752026-10-01 07:39:32.875 UTC [69704] ERROR: relation "goose_db_version" does not exist at character 3618762026-10-01 07:39:32.875 UTC [69704] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18772026/10/01 07:39:32 OK 20241026095416_initial_model.sql (66.94ms)18782026/10/01 07:39:32 OK 20251210153512_drop_unused_gin_index.sql (7.73ms)18792026-10-01 07:39:32.941 UTC [69705] ERROR: relation "goose_db_version" does not exist at character 3618802026-10-01 07:39:32.941 UTC [69705] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18812026-10-01 07:39:32.941 UTC [69706] ERROR: relation "goose_db_version" does not exist at character 3618822026-10-01 07:39:32.941 UTC [69706] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18832026/10/01 07:39:32 OK 20251218171726_add_pins.sql (9.11ms)18842026/10/01 07:39:32 OK 20260628120000_add_object_size_and_stats.sql (17.42ms)18852026/10/01 07:39:32 OK 20260905000000_add_claims.sql (26.55ms)18862026/10/01 07:39:33 OK 20241026095416_initial_model.sql (86.04ms)18872026/10/01 07:39:33 OK 20260920000000_drop_claims.sql (16.58ms)18882026/10/01 07:39:33 INFO lead: acquired remote=192.0.2.1:123418892026/10/01 07:39:33 INFO lead: released remote=192.0.2.1:12341890--- PASS: TestLeadEndsOnShutdown (1.79s)1891=== CONT TestClientWithDependencies18922026/10/01 07:39:33 OK 20251210153512_drop_unused_gin_index.sql (1.12ms)18932026/10/01 07:39:33 OK 20260923120000_add_pushes.sql (6.95ms)18942026/10/01 07:39:33 goose: successfully migrated database to version: 2026092312000018952026/10/01 07:39:33 OK 1_commit_pending_closure.sql (1.17ms)18962026/10/01 07:39:33 OK 2_object_stats_trigger.sql (208.42µs)18972026/10/01 07:39:33 OK 3_commit_push.sql (172.79µs)18982026/10/01 07:39:33 goose: up to current file version: 318992026/10/01 07:39:33 OK 20251218171726_add_pins.sql (20.85ms)19002026/10/01 07:39:33 OK 20260628120000_add_object_size_and_stats.sql (24.86ms)1901--- PASS: TestGCBugBareHashReferences (2.70s)1902=== CONT TestOrphanedObjectsGCStressTest19032026/10/01 07:39:33 OK 20241026095416_initial_model.sql (83.93ms)19042026/10/01 07:39:33 OK 20241026095416_initial_model.sql (90.59ms)19052026/10/01 07:39:33 OK 20260905000000_add_claims.sql (10.03ms)19062026/10/01 07:39:33 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)19072026/10/01 07:39:33 OK 20251210153512_drop_unused_gin_index.sql (2.48ms)19082026/10/01 07:39:33 OK 20260920000000_drop_claims.sql (7.35ms)19092026/10/01 07:39:33 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01910=== NAME TestClientIntegration1911 client_integration_test.go:323: Objects in database after GC:1912 client_integration_test.go:323: Successfully deleted all objects with GC --force19132026/10/01 07:39:33 OK 20251218171726_add_pins.sql (12.9ms)19142026/10/01 07:39:33 OK 20260923120000_add_pushes.sql (9.32ms)19152026/10/01 07:39:33 goose: successfully migrated database to version: 2026092312000019162026/10/01 07:39:33 OK 1_commit_pending_closure.sql (992.58µs)19172026/10/01 07:39:33 OK 2_object_stats_trigger.sql (214.38µs)19182026/10/01 07:39:33 OK 3_commit_push.sql (172.79µs)19192026/10/01 07:39:33 goose: up to current file version: 319202026/10/01 07:39:33 OK 20251218171726_add_pins.sql (21.65ms)19212026/10/01 07:39:33 OK 20260628120000_add_object_size_and_stats.sql (28.83ms)19222026/10/01 07:39:33 OK 20260628120000_add_object_size_and_stats.sql (21.78ms)1923--- PASS: TestClientIntegration (5.07s)1924=== CONT TestReadProxyNarStreaming19252026/10/01 07:39:33 OK 20260905000000_add_claims.sql (19.06ms)19262026/10/01 07:39:33 OK 20260905000000_add_claims.sql (19.69ms)19272026/10/01 07:39:33 OK 20260920000000_drop_claims.sql (13.07ms)19282026/10/01 07:39:33 OK 20260920000000_drop_claims.sql (17.8ms)19292026/10/01 07:39:33 OK 20260923120000_add_pushes.sql (8.67ms)19302026/10/01 07:39:33 goose: successfully migrated database to version: 2026092312000019312026/10/01 07:39:33 OK 1_commit_pending_closure.sql (1.24ms)19322026/10/01 07:39:33 OK 2_object_stats_trigger.sql (246.67µs)19332026/10/01 07:39:33 OK 3_commit_push.sql (200µs)19342026/10/01 07:39:33 goose: up to current file version: 319352026/10/01 07:39:33 OK 20260923120000_add_pushes.sql (4.48ms)19362026/10/01 07:39:33 goose: successfully migrated database to version: 2026092312000019372026/10/01 07:39:33 OK 1_commit_pending_closure.sql (896.5µs)19382026/10/01 07:39:33 OK 2_object_stats_trigger.sql (201.33µs)19392026/10/01 07:39:33 OK 3_commit_push.sql (171.42µs)19402026/10/01 07:39:33 goose: up to current file version: 319412026/10/01 07:39:33 INFO lead: acquired remote=192.0.2.1:123419422026-10-01 07:39:33.243 UTC [69717] ERROR: relation "goose_db_version" does not exist at character 3619432026-10-01 07:39:33.243 UTC [69717] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19442026/10/01 07:39:33 OK 20241026095416_initial_model.sql (61.28ms)19452026/10/01 07:39:33 OK 20251210153512_drop_unused_gin_index.sql (1.48ms)19462026/10/01 07:39:33 INFO lead: released remote=192.0.2.1:123419472026/10/01 07:39:33 OK 20251218171726_add_pins.sql (17.77ms)1948--- PASS: TestReadProxy404 (1.73s)1949=== CONT TestClientFallsBackToClosures19502026/10/01 07:39:33 OK 20260628120000_add_object_size_and_stats.sql (17.72ms)19512026/10/01 07:39:33 INFO lead: acquired remote=192.0.2.1:123419522026/10/01 07:39:33 INFO lead: released remote=192.0.2.1:12341953--- PASS: TestLeadElectsOneAndHandsOver (1.93s)1954=== CONT TestService_ReadAuthMiddleware19552026/10/01 07:39:33 OK 20260905000000_add_claims.sql (44.2ms)19562026/10/01 07:39:33 OK 20260920000000_drop_claims.sql (9.41ms)19572026/10/01 07:39:33 OK 20260923120000_add_pushes.sql (2.38ms)19582026/10/01 07:39:33 goose: successfully migrated database to version: 2026092312000019592026/10/01 07:39:33 OK 1_commit_pending_closure.sql (952.92µs)19602026/10/01 07:39:33 OK 2_object_stats_trigger.sql (244.96µs)19612026/10/01 07:39:33 OK 3_commit_push.sql (191.42µs)19622026/10/01 07:39:33 goose: up to current file version: 319632026-10-01 07:39:33.545 UTC [69726] ERROR: relation "goose_db_version" does not exist at character 3619642026-10-01 07:39:33.545 UTC [69726] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19652026-10-01 07:39:33.591 UTC [69732] ERROR: relation "goose_db_version" does not exist at character 3619662026-10-01 07:39:33.591 UTC [69732] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1967--- PASS: TestReadProxyInvalidPath (1.70s)1968=== CONT TestService_RequireScope_OIDC19692026/10/01 07:39:33 OK 20241026095416_initial_model.sql (83.69ms)19702026/10/01 07:39:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58346/oidc19712026/10/01 07:39:33 OK 20251210153512_drop_unused_gin_index.sql (4.78ms)19722026/10/01 07:39:33 OK 20251218171726_add_pins.sql (41.86ms)19732026/10/01 07:39:33 OK 20241026095416_initial_model.sql (72.59ms)19742026/10/01 07:39:33 OK 20251210153512_drop_unused_gin_index.sql (1.92ms)19752026/10/01 07:39:33 OK 20260628120000_add_object_size_and_stats.sql (15.29ms)19762026/10/01 07:39:33 OK 20251218171726_add_pins.sql (14.34ms)19772026/10/01 07:39:33 OK 20260628120000_add_object_size_and_stats.sql (18.21ms)19782026/10/01 07:39:33 OK 20260905000000_add_claims.sql (25.93ms)19792026/10/01 07:39:33 OK 20260920000000_drop_claims.sql (14.82ms)19802026/10/01 07:39:33 OK 20260923120000_add_pushes.sql (8.87ms)19812026/10/01 07:39:33 goose: successfully migrated database to version: 2026092312000019822026/10/01 07:39:33 OK 1_commit_pending_closure.sql (1.38ms)19832026/10/01 07:39:33 OK 2_object_stats_trigger.sql (243.96µs)19842026/10/01 07:39:33 OK 3_commit_push.sql (214.42µs)19852026/10/01 07:39:33 goose: up to current file version: 319862026/10/01 07:39:33 OK 20260905000000_add_claims.sql (44.36ms)19872026/10/01 07:39:33 OK 20260920000000_drop_claims.sql (24.27ms)19882026/10/01 07:39:33 OK 20260923120000_add_pushes.sql (24.57ms)19892026/10/01 07:39:33 goose: successfully migrated database to version: 202609231200001990--- PASS: TestReadProxyHead (2.09s)1991=== CONT TestClientPushesUseOnePush19922026/10/01 07:39:33 OK 1_commit_pending_closure.sql (1.74ms)19932026/10/01 07:39:33 OK 2_object_stats_trigger.sql (327.92µs)19942026/10/01 07:39:33 OK 3_commit_push.sql (365.46µs)19952026/10/01 07:39:33 goose: up to current file version: 319962026-10-01 07:39:34.341 UTC [69741] ERROR: relation "goose_db_version" does not exist at character 3619972026-10-01 07:39:34.341 UTC [69741] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1998=== NAME TestPinProtectsFromGC1999 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-68619-1936780597/TestPinProtectsFromGC2270571619/001/store/jb7z0ifnvqbhqhgcyjlc3f7yrc2d2hb6-pinned-file.txt2000 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-68619-1936780597/TestPinProtectsFromGC2270571619/001/store/814hpg7p2fr8bwj098klbilx184i3222-unpinned-file.txt20012026-10-01 07:39:34.498 UTC [69743] ERROR: relation "goose_db_version" does not exist at character 3620022026-10-01 07:39:34.498 UTC [69743] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20032026-10-01 07:39:34.539 UTC [69746] ERROR: relation "goose_db_version" does not exist at character 3620042026-10-01 07:39:34.539 UTC [69746] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20052026/10/01 07:39:34 OK 20241026095416_initial_model.sql (158.02ms)20062026/10/01 07:39:34 OK 20251210153512_drop_unused_gin_index.sql (18.15ms)20072026/10/01 07:39:34 INFO Received push request method=POST path=/api/pushes20082026/10/01 07:39:34 OK 20251218171726_add_pins.sql (31.29ms)20092026/10/01 07:39:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20102026/10/01 07:39:34 INFO Uploading jb7z0ifnvqbhqhgcyjlc3f7yrc2d2hb6-pinned-file.txt (128B)20112026/10/01 07:39:34 OK 20260628120000_add_object_size_and_stats.sql (28.16ms)20122026/10/01 07:39:34 WARN Failed to register uploaded object key=jb7z0ifnvqbhqhgcyjlc3f7yrc2d2hb6.ls error="server returned 404: 404 page not found\n"20132026/10/01 07:39:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20142026/10/01 07:39:34 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"20152026/10/01 07:39:34 INFO Signed narinfos id=1 count=120162026/10/01 07:39:34 INFO Uploading 1 narinfos20172026/10/01 07:39:34 INFO Received complete push request method=POST path=/api/pushes/1/complete20182026/10/01 07:39:34 WARN Failed to register uploaded object key=jb7z0ifnvqbhqhgcyjlc3f7yrc2d2hb6.narinfo error="server returned 404: 404 page not found\n"2019=== NAME TestClientMultipleUploads2020 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-68619-1936780597/TestClientMultipleUploads2444981431/001/store/1qxdphlfk624j0j4lhgn4w0w38zvv8ic-test-file-0.txt20212026/10/01 07:39:34 INFO Upload complete. (161ms)20222026/10/01 07:39:34 OK 20260905000000_add_claims.sql (74.37ms)20232026/10/01 07:39:34 OK 20260920000000_drop_claims.sql (19.91ms)20242026/10/01 07:39:34 OK 20260923120000_add_pushes.sql (7.78ms)20252026/10/01 07:39:34 goose: successfully migrated database to version: 2026092312000020262026/10/01 07:39:34 OK 1_commit_pending_closure.sql (1.88ms)20272026/10/01 07:39:34 OK 2_object_stats_trigger.sql (250.63µs)20282026/10/01 07:39:34 OK 3_commit_push.sql (185.25µs)20292026/10/01 07:39:34 goose: up to current file version: 320302026/10/01 07:39:34 OK 20241026095416_initial_model.sql (163.26ms)20312026/10/01 07:39:34 OK 20251210153512_drop_unused_gin_index.sql (13.8ms)2032 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-68619-1936780597/TestClientMultipleUploads2444981431/001/store/h9iackjykvikzwihhgrqzyjhjqi07891-test-file-1.txt20332026/10/01 07:39:34 INFO Received push request method=POST path=/api/pushes20342026/10/01 07:39:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20352026/10/01 07:39:34 INFO Uploading 814hpg7p2fr8bwj098klbilx184i3222-unpinned-file.txt (128B)20362026/10/01 07:39:34 OK 20251218171726_add_pins.sql (42.88ms)20372026/10/01 07:39:34 WARN Failed to register uploaded object key=814hpg7p2fr8bwj098klbilx184i3222.ls error="server returned 404: 404 page not found\n"20382026/10/01 07:39:34 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20392026/10/01 07:39:34 INFO Signed narinfos id=2 count=120402026/10/01 07:39:34 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"20412026/10/01 07:39:34 INFO Uploading 1 narinfos20422026/10/01 07:39:34 OK 20260628120000_add_object_size_and_stats.sql (29.82ms)20432026/10/01 07:39:34 OK 20241026095416_initial_model.sql (227.46ms)20442026/10/01 07:39:34 INFO Received complete push request method=POST path=/api/pushes/2/complete20452026/10/01 07:39:34 WARN Failed to register uploaded object key=814hpg7p2fr8bwj098klbilx184i3222.narinfo error="server returned 404: 404 page not found\n"20462026/10/01 07:39:34 INFO Upload complete. (128ms)20472026/10/01 07:39:34 OK 20251210153512_drop_unused_gin_index.sql (11.24ms)20482026/10/01 07:39:34 INFO Received create pin request method=POST path=/api/pins/myapp20492026/10/01 07:39:34 OK 20251218171726_add_pins.sql (51.63ms)20502026/10/01 07:39:34 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-68619-1936780597/TestPinProtectsFromGC2270571619/001/store/jb7z0ifnvqbhqhgcyjlc3f7yrc2d2hb6-pinned-file.txt narinfo_key=jb7z0ifnvqbhqhgcyjlc3f7yrc2d2hb6.narinfo20512026/10/01 07:39:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures20522026/10/01 07:39:34 INFO Garbage collection started2053 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-68619-1936780597/TestClientMultipleUploads2444981431/001/store/yk7hf50mmwfmdfg4xwwsv1bacn4snjb0-test-file-2.txt20542026/10/01 07:39:34 INFO Aborted multipart uploads count=020552026/10/01 07:39:34 WARN Force mode enabled - objects will be deleted immediately without grace period20562026/10/01 07:39:34 OK 20260905000000_add_claims.sql (136.49ms)20572026/10/01 07:39:34 OK 20260628120000_add_object_size_and_stats.sql (52.46ms)20582026/10/01 07:39:34 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=020592026/10/01 07:39:35 OK 20260920000000_drop_claims.sql (66.91ms)20602026/10/01 07:39:35 OK 20260923120000_add_pushes.sql (9.61ms)20612026/10/01 07:39:35 goose: successfully migrated database to version: 2026092312000020622026/10/01 07:39:35 OK 1_commit_pending_closure.sql (1ms)20632026/10/01 07:39:35 INFO Received push request method=POST path=/api/pushes20642026/10/01 07:39:35 OK 2_object_stats_trigger.sql (232.38µs)20652026/10/01 07:39:35 OK 3_commit_push.sql (203.54µs)20662026/10/01 07:39:35 goose: up to current file version: 320672026/10/01 07:39:35 OK 20260905000000_add_claims.sql (74.03ms)20682026/10/01 07:39:35 INFO Vacuumed table table=pending_closures20692026/10/01 07:39:35 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)20702026/10/01 07:39:35 INFO Uploading h9iackjykvikzwihhgrqzyjhjqi07891-test-file-1.txt (160B)20712026/10/01 07:39:35 INFO Uploading yk7hf50mmwfmdfg4xwwsv1bacn4snjb0-test-file-2.txt (160B)20722026/10/01 07:39:35 INFO Uploading 1qxdphlfk624j0j4lhgn4w0w38zvv8ic-test-file-0.txt (160B)20732026/10/01 07:39:35 OK 20260920000000_drop_claims.sql (51.43ms)20742026/10/01 07:39:35 WARN Failed to register uploaded object key=1qxdphlfk624j0j4lhgn4w0w38zvv8ic.ls error="server returned 404: 404 page not found\n"20752026/10/01 07:39:35 INFO Vacuumed table table=pending_objects20762026/10/01 07:39:35 INFO Vacuumed table table=multipart_uploads20772026/10/01 07:39:35 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"20782026/10/01 07:39:35 WARN Failed to register uploaded object key=yk7hf50mmwfmdfg4xwwsv1bacn4snjb0.ls error="server returned 404: 404 page not found\n"20792026/10/01 07:39:35 WARN Failed to register uploaded object key=h9iackjykvikzwihhgrqzyjhjqi07891.ls error="server returned 404: 404 page not found\n"20802026/10/01 07:39:35 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"20812026/10/01 07:39:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20822026/10/01 07:39:35 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"20832026/10/01 07:39:35 INFO Signed narinfos id=1 count=320842026/10/01 07:39:35 INFO Uploading 3 narinfos20852026/10/01 07:39:35 OK 20260923120000_add_pushes.sql (25.55ms)20862026/10/01 07:39:35 goose: successfully migrated database to version: 2026092312000020872026/10/01 07:39:35 OK 1_commit_pending_closure.sql (1.54ms)20882026/10/01 07:39:35 OK 2_object_stats_trigger.sql (298.79µs)20892026/10/01 07:39:35 OK 3_commit_push.sql (175.75µs)20902026/10/01 07:39:35 goose: up to current file version: 320912026/10/01 07:39:35 INFO Vacuumed table table=closures20922026/10/01 07:39:35 INFO Received complete push request method=POST path=/api/pushes/1/complete20932026/10/01 07:39:35 WARN Failed to register uploaded object key=yk7hf50mmwfmdfg4xwwsv1bacn4snjb0.narinfo error="server returned 404: 404 page not found\n"20942026/10/01 07:39:35 WARN Failed to register uploaded object key=1qxdphlfk624j0j4lhgn4w0w38zvv8ic.narinfo error="server returned 404: 404 page not found\n"20952026/10/01 07:39:35 WARN Failed to register uploaded object key=h9iackjykvikzwihhgrqzyjhjqi07891.narinfo error="server returned 404: 404 page not found\n"20962026-10-01 07:39:35.188 UTC [69772] ERROR: relation "goose_db_version" does not exist at character 3620972026-10-01 07:39:35.188 UTC [69772] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20982026/10/01 07:39:35 INFO Upload complete. (251ms)20992026/10/01 07:39:35 INFO Vacuumed table table=objects2100 client_integration_test.go:369: Uploaded 3 paths in 285.495667ms2101--- PASS: TestClientMultipleUploads (2.68s)2102=== CONT TestService_AuthMiddleware_OIDC21032026/10/01 07:39:35 INFO Received push request method=POST path=/api/pushes21042026/10/01 07:39:35 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)21052026/10/01 07:39:35 INFO Uploading rk9d93k2f398fwljlmxblk7risi86q22-top (256B)21062026/10/01 07:39:35 INFO Uploading ir2bnqpjdkxkm60znzvqazpgddmbfc7c-shared-dep (136B)21072026/10/01 07:39:35 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"21082026/10/01 07:39:35 WARN Failed to register uploaded object key=rk9d93k2f398fwljlmxblk7risi86q22.ls error="server returned 404: 404 page not found\n"21092026/10/01 07:39:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58402/oidc21102026/10/01 07:39:35 WARN Failed to register uploaded object key=ir2bnqpjdkxkm60znzvqazpgddmbfc7c.ls error="server returned 404: 404 page not found\n"21112026/10/01 07:39:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21122026/10/01 07:39:35 WARN Failed to register uploaded object key=nar/05qd90j8dnm9wc09ayz2zjdwhk5pjj1vv0hh938v6cmm0ws22y6n.nar.zst error="server returned 404: 404 page not found\n"21132026/10/01 07:39:35 INFO Signed narinfos id=1 count=221142026/10/01 07:39:35 INFO Uploading 2 narinfos21152026/10/01 07:39:35 WARN Failed to register uploaded object key=ir2bnqpjdkxkm60znzvqazpgddmbfc7c.narinfo error="server returned 404: 404 page not found\n"21162026/10/01 07:39:35 INFO Received complete push request method=POST path=/api/pushes/1/complete21172026/10/01 07:39:35 WARN Failed to register uploaded object key=rk9d93k2f398fwljlmxblk7risi86q22.narinfo error="server returned 404: 404 page not found\n"21182026/10/01 07:39:35 INFO Upload complete. (174ms)2119=== NAME TestClientSharedPathCommittedMidPush2120 client_integration_test.go:680: Retrieved narinfo from S3:2121 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestClientSharedPathCommittedMidPush353813423/001/store/ir2bnqpjdkxkm60znzvqazpgddmbfc7c-shared-dep2122 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2123 Compression: zstd2124 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822125 NarSize: 1362126 References: 2127 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2128 client_integration_test.go:680: Retrieved narinfo from S3:2129 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestClientSharedPathCommittedMidPush353813423/001/store/rk9d93k2f398fwljlmxblk7risi86q22-top2130 URL: nar/05qd90j8dnm9wc09ayz2zjdwhk5pjj1vv0hh938v6cmm0ws22y6n.nar.zst2131 Compression: zstd2132 NarHash: sha256:05qd90j8dnm9wc09ayz2zjdwhk5pjj1vv0hh938v6cmm0ws22y6n2133 NarSize: 2562134 References: /nix/var/nix/builds/nix-68619-1936780597/TestClientSharedPathCommittedMidPush353813423/001/store/ir2bnqpjdkxkm60znzvqazpgddmbfc7c-shared-dep2135 CA: text:sha256:1xx874ym8bbn0sxp11nsr7srfx4rm616wxhnnkm8ijyjih26ll7y21362026/10/01 07:39:35 OK 20241026095416_initial_model.sql (220.11ms)21372026/10/01 07:39:35 OK 20251210153512_drop_unused_gin_index.sql (10.34ms)21382026-10-01 07:39:35.512 UTC [69784] ERROR: relation "goose_db_version" does not exist at character 3621392026-10-01 07:39:35.512 UTC [69784] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2140--- PASS: TestClientSharedPathCommittedMidPush (2.82s)2141=== CONT TestService_AuthMiddleware_MTLSBoundSubjects21422026/10/01 07:39:35 OK 20251218171726_add_pins.sql (33.49ms)21432026/10/01 07:39:35 OK 20260628120000_add_object_size_and_stats.sql (41.44ms)2144=== NAME TestClientWithDependencies2145 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-68619-1936780597/TestClientWithDependencies3852214815/001/store/75r75aswysbdmjg15l74vidzxq4h50ma-test-script21462026/10/01 07:39:35 OK 20260905000000_add_claims.sql (53.56ms)21472026/10/01 07:39:35 OK 20260920000000_drop_claims.sql (12.8ms)21482026/10/01 07:39:35 OK 20260923120000_add_pushes.sql (8.94ms)21492026/10/01 07:39:35 goose: successfully migrated database to version: 2026092312000021502026/10/01 07:39:35 OK 1_commit_pending_closure.sql (1.47ms)21512026/10/01 07:39:35 OK 2_object_stats_trigger.sql (352µs)21522026/10/01 07:39:35 OK 3_commit_push.sql (202.29µs)21532026/10/01 07:39:35 goose: up to current file version: 32154 client_integration_test.go:615: Found 1 dependencies (including self)21552026/10/01 07:39:35 OK 20241026095416_initial_model.sql (167.84ms)21562026/10/01 07:39:35 OK 20251210153512_drop_unused_gin_index.sql (11.55ms)21572026/10/01 07:39:35 OK 20251218171726_add_pins.sql (16.48ms)21582026/10/01 07:39:35 INFO Received push request method=POST path=/api/pushes2159--- PASS: TestReadProxyNarStreaming (2.70s)2160=== CONT TestService_AuthMiddleware_MTLSProxyHeader21612026/10/01 07:39:35 OK 20260628120000_add_object_size_and_stats.sql (37.1ms)21622026/10/01 07:39:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21632026/10/01 07:39:35 INFO Uploading 75r75aswysbdmjg15l74vidzxq4h50ma-test-script (136B)21642026/10/01 07:39:35 WARN Failed to register uploaded object key=75r75aswysbdmjg15l74vidzxq4h50ma.ls error="server returned 404: 404 page not found\n"21652026/10/01 07:39:35 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"21662026/10/01 07:39:35 WARN Failed to register uploaded object key=log/dfkn3jlldmk86b5g3ziban8hgh6aimx8-test-script.drv error="server returned 404: 404 page not found\n"21672026/10/01 07:39:35 OK 20260905000000_add_claims.sql (31.62ms)21682026/10/01 07:39:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21692026/10/01 07:39:35 INFO Signed narinfos id=1 count=121702026/10/01 07:39:35 INFO Uploading 1 narinfos21712026/10/01 07:39:35 INFO Received complete push request method=POST path=/api/pushes/1/complete21722026/10/01 07:39:35 WARN Failed to register uploaded object key=75r75aswysbdmjg15l74vidzxq4h50ma.narinfo error="server returned 404: 404 page not found\n"21732026/10/01 07:39:35 OK 20260920000000_drop_claims.sql (47.63ms)21742026/10/01 07:39:35 INFO Upload complete. (168ms)2175=== NAME TestClientWithDependencies2176 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-68619-1936780597/TestClientWithDependencies3852214815/001/store) requires matching store prefix21772026/10/01 07:39:35 OK 20260923120000_add_pushes.sql (25.95ms)21782026/10/01 07:39:35 goose: successfully migrated database to version: 2026092312000021792026-10-01 07:39:35.919 UTC [69797] ERROR: relation "goose_db_version" does not exist at character 3621802026-10-01 07:39:35.919 UTC [69797] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21812026/10/01 07:39:35 OK 1_commit_pending_closure.sql (1.65ms)21822026/10/01 07:39:35 OK 2_object_stats_trigger.sql (380.54µs)21832026/10/01 07:39:35 OK 3_commit_push.sql (188.67µs)21842026/10/01 07:39:35 goose: up to current file version: 321852026-10-01 07:39:36.009 UTC [69798] ERROR: relation "goose_db_version" does not exist at character 3621862026-10-01 07:39:36.009 UTC [69798] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2187--- PASS: TestClientWithDependencies (3.01s)2188=== CONT TestReadProxyNarinfoAlreadyDecompressed21892026/10/01 07:39:36 OK 20241026095416_initial_model.sql (206.37ms)21902026/10/01 07:39:36 OK 20251210153512_drop_unused_gin_index.sql (11.05ms)21912026/10/01 07:39:36 OK 20251218171726_add_pins.sql (32.48ms)21922026/10/01 07:39:36 OK 20241026095416_initial_model.sql (203.61ms)21932026/10/01 07:39:36 OK 20251210153512_drop_unused_gin_index.sql (12.21ms)21942026/10/01 07:39:36 OK 20260628120000_add_object_size_and_stats.sql (42.35ms)21952026/10/01 07:39:36 OK 20251218171726_add_pins.sql (21.99ms)21962026/10/01 07:39:36 OK 20260905000000_add_claims.sql (71.25ms)21972026/10/01 07:39:36 OK 20260628120000_add_object_size_and_stats.sql (57.23ms)2198--- PASS: TestService_ReadAuthMiddleware (2.98s)2199=== CONT TestGCSweepDeliversEachKeyOnce22002026/10/01 07:39:36 OK 20260920000000_drop_claims.sql (69.55ms)22012026/10/01 07:39:36 OK 20260923120000_add_pushes.sql (14.32ms)22022026/10/01 07:39:36 goose: successfully migrated database to version: 2026092312000022032026/10/01 07:39:36 OK 20260905000000_add_claims.sql (77.23ms)22042026/10/01 07:39:36 OK 1_commit_pending_closure.sql (1.28ms)22052026/10/01 07:39:36 OK 2_object_stats_trigger.sql (276.17µs)22062026/10/01 07:39:36 OK 3_commit_push.sql (173µs)22072026/10/01 07:39:36 goose: up to current file version: 322082026/10/01 07:39:36 OK 20260920000000_drop_claims.sql (68.13ms)22092026/10/01 07:39:36 OK 20260923120000_add_pushes.sql (14.58ms)22102026/10/01 07:39:36 goose: successfully migrated database to version: 2026092312000022112026/10/01 07:39:36 OK 1_commit_pending_closure.sql (1.56ms)22122026/10/01 07:39:36 OK 2_object_stats_trigger.sql (223.88µs)22132026/10/01 07:39:36 OK 3_commit_push.sql (189.79µs)22142026/10/01 07:39:36 goose: up to current file version: 322152026/10/01 07:39:36 INFO Received uploads request method=POST path=/api/pending_closures22162026/10/01 07:39:36 INFO Received uploads request method=POST path=/api/pending_closures22172026/10/01 07:39:36 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)22182026/10/01 07:39:36 INFO Uploading qxakaxbwb8gh9as2034qf0nn3b1nyh8c-shared-dep (136B)22192026/10/01 07:39:36 INFO Uploading nh7dj5v1xv3ckw8w8dr7s0r4gmzyhvv4-a (248B)2220=== RUN TestService_RequireScope_OIDC/builder_may_write2221=== PAUSE TestService_RequireScope_OIDC/builder_may_write2222=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2223=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2224=== RUN TestService_RequireScope_OIDC/ops_may_admin2225=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2226=== RUN TestService_RequireScope_OIDC/ops_may_not_write2227=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2228=== RUN TestService_RequireScope_OIDC/reader_may_not_write2229=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2230=== RUN TestService_RequireScope_OIDC/static_token_may_admin2231=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2232=== RUN TestService_RequireScope_OIDC/static_token_may_write2233=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2234=== RUN TestService_RequireScope_OIDC/reader_may_read2235=== PAUSE TestService_RequireScope_OIDC/reader_may_read2236=== RUN TestService_RequireScope_OIDC/writer_implies_read2237=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2238=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2239=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2240=== CONT TestFailedS3DeleteKeepsTombstone22412026/10/01 07:39:36 WARN Failed to register uploaded object key=nh7dj5v1xv3ckw8w8dr7s0r4gmzyhvv4.ls error="server returned 404: 404 page not found\n"22422026/10/01 07:39:36 WARN Failed to register uploaded object key=qxakaxbwb8gh9as2034qf0nn3b1nyh8c.ls error="server returned 404: 404 page not found\n"22432026/10/01 07:39:36 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22442026/10/01 07:39:36 WARN Failed to register uploaded object key=nar/1kc5yds0rqbpf7hmf5rckzwzxl97fz646zallsakd7zdvnhy6lhm.nar.zst error="server returned 404: 404 page not found\n"22452026/10/01 07:39:36 WARN Failed to register uploaded object key=1507ycnmii6jw4sqga7vsg915dfshcxp.ls error="server returned 404: 404 page not found\n"22462026/10/01 07:39:36 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign22472026/10/01 07:39:36 INFO Signed narinfos id=1 count=222482026/10/01 07:39:36 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign22492026/10/01 07:39:36 INFO Signed narinfos id=2 count=222502026/10/01 07:39:36 INFO Uploading 4 narinfos22512026/10/01 07:39:36 WARN Failed to register uploaded object key=nh7dj5v1xv3ckw8w8dr7s0r4gmzyhvv4.narinfo error="server returned 404: 404 page not found\n"22522026/10/01 07:39:36 WARN Failed to register uploaded object key=qxakaxbwb8gh9as2034qf0nn3b1nyh8c.narinfo error="server returned 404: 404 page not found\n"22532026/10/01 07:39:36 WARN Failed to register uploaded object key=1507ycnmii6jw4sqga7vsg915dfshcxp.narinfo error="server returned 404: 404 page not found\n"22542026/10/01 07:39:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22552026/10/01 07:39:36 WARN Failed to register uploaded object key=qxakaxbwb8gh9as2034qf0nn3b1nyh8c.narinfo error="server returned 404: 404 page not found\n"22562026/10/01 07:39:36 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02257=== NAME TestPinProtectsFromGC2258 client_integration_test.go:794: Pin successfully protected closure from garbage collection22592026/10/01 07:39:36 INFO Completed upload id=122602026/10/01 07:39:36 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22612026/10/01 07:39:36 INFO Completed upload id=222622026/10/01 07:39:36 INFO Upload complete. (314ms)2263=== NAME TestClientFallsBackToClosures2264 client_pushes_test.go:112: Retrieved narinfo from S3:2265 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestClientFallsBackToClosures2814674880/001/store/qxakaxbwb8gh9as2034qf0nn3b1nyh8c-shared-dep2266 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2267 Compression: zstd2268 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822269 NarSize: 1362270 References: 2271 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2272 client_pushes_test.go:112: Retrieved narinfo from S3:2273 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestClientFallsBackToClosures2814674880/001/store/nh7dj5v1xv3ckw8w8dr7s0r4gmzyhvv4-a2274 URL: nar/1kc5yds0rqbpf7hmf5rckzwzxl97fz646zallsakd7zdvnhy6lhm.nar.zst2275 Compression: zstd2276 NarHash: sha256:1kc5yds0rqbpf7hmf5rckzwzxl97fz646zallsakd7zdvnhy6lhm2277 NarSize: 2482278 References: /nix/var/nix/builds/nix-68619-1936780597/TestClientFallsBackToClosures2814674880/001/store/qxakaxbwb8gh9as2034qf0nn3b1nyh8c-shared-dep2279 CA: text:sha256:083rcj74kdjfw8pfz0jhnacp12fjzlc81spbby2bl6zn1b9h2gxr2280 client_pushes_test.go:112: Retrieved narinfo from S3:2281 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestClientFallsBackToClosures2814674880/001/store/1507ycnmii6jw4sqga7vsg915dfshcxp-b2282 URL: nar/1kc5yds0rqbpf7hmf5rckzwzxl97fz646zallsakd7zdvnhy6lhm.nar.zst2283 Compression: zstd2284 NarHash: sha256:1kc5yds0rqbpf7hmf5rckzwzxl97fz646zallsakd7zdvnhy6lhm2285 NarSize: 2482286 References: /nix/var/nix/builds/nix-68619-1936780597/TestClientFallsBackToClosures2814674880/001/store/qxakaxbwb8gh9as2034qf0nn3b1nyh8c-shared-dep2287 CA: text:sha256:083rcj74kdjfw8pfz0jhnacp12fjzlc81spbby2bl6zn1b9h2gxr2288--- PASS: TestPinProtectsFromGC (4.91s)2289=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection2290--- PASS: TestClientFallsBackToClosures (3.71s)2291=== CONT TestTombstonedObjectOfferedWithoutWaiting22922026-10-01 07:39:37.594 UTC [69828] ERROR: relation "goose_db_version" does not exist at character 3622932026-10-01 07:39:37.594 UTC [69828] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22942026/10/01 07:39:37 INFO Received push request method=POST path=/api/pushes22952026/10/01 07:39:37 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)22962026/10/01 07:39:37 INFO Uploading 5sxadz5lf3gdxvl52mk90166080qciq2-b (248B)22972026/10/01 07:39:37 INFO Uploading 9s73mzw64x7xg82vp6q3laacawfdv8gq-shared-dep (136B)22982026/10/01 07:39:37 WARN Failed to register uploaded object key=9s73mzw64x7xg82vp6q3laacawfdv8gq.ls error="server returned 404: 404 page not found\n"22992026/10/01 07:39:37 WARN Failed to register uploaded object key=5sxadz5lf3gdxvl52mk90166080qciq2.ls error="server returned 404: 404 page not found\n"23002026/10/01 07:39:37 WARN Failed to register uploaded object key=nar/03k8c0zykz5hv16v5bsdi37aw4hgb6x6cv4yvw9jb49qfkcfbnyg.nar.zst error="server returned 404: 404 page not found\n"23012026/10/01 07:39:37 WARN Failed to register uploaded object key=0fmx1im83bcnfrnsksyckmn43m8kra89.ls error="server returned 404: 404 page not found\n"23022026/10/01 07:39:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23032026/10/01 07:39:37 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"23042026/10/01 07:39:37 INFO Signed narinfos id=1 count=323052026/10/01 07:39:37 INFO Uploading 3 narinfos23062026/10/01 07:39:37 WARN Failed to register uploaded object key=5sxadz5lf3gdxvl52mk90166080qciq2.narinfo error="server returned 404: 404 page not found\n"23072026/10/01 07:39:37 WARN Failed to register uploaded object key=9s73mzw64x7xg82vp6q3laacawfdv8gq.narinfo error="server returned 404: 404 page not found\n"23082026/10/01 07:39:37 INFO Received complete push request method=POST path=/api/pushes/1/complete23092026/10/01 07:39:37 WARN Failed to register uploaded object key=0fmx1im83bcnfrnsksyckmn43m8kra89.narinfo error="server returned 404: 404 page not found\n"23102026-10-01 07:39:37.788 UTC [69836] ERROR: relation "goose_db_version" does not exist at character 3623112026-10-01 07:39:37.788 UTC [69836] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23122026/10/01 07:39:37 INFO Upload complete. (167ms)2313=== NAME TestClientPushesUseOnePush2314 client_pushes_test.go:97: Retrieved narinfo from S3:2315 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestClientPushesUseOnePush1993961195/001/store/9s73mzw64x7xg82vp6q3laacawfdv8gq-shared-dep2316 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2317 Compression: zstd2318 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822319 NarSize: 1362320 References: 2321 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2322 client_pushes_test.go:97: Retrieved narinfo from S3:2323 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestClientPushesUseOnePush1993961195/001/store/0fmx1im83bcnfrnsksyckmn43m8kra89-a2324 URL: nar/03k8c0zykz5hv16v5bsdi37aw4hgb6x6cv4yvw9jb49qfkcfbnyg.nar.zst2325 Compression: zstd2326 NarHash: sha256:03k8c0zykz5hv16v5bsdi37aw4hgb6x6cv4yvw9jb49qfkcfbnyg2327 NarSize: 2482328 References: /nix/var/nix/builds/nix-68619-1936780597/TestClientPushesUseOnePush1993961195/001/store/9s73mzw64x7xg82vp6q3laacawfdv8gq-shared-dep2329 CA: text:sha256:05j69n1ps4nfqjjhzmsv7r4ipl4fqn34i6pam0v8h4c32n9isijv2330 client_pushes_test.go:97: Retrieved narinfo from S3:2331 StorePath: /nix/var/nix/builds/nix-68619-1936780597/TestClientPushesUseOnePush1993961195/001/store/5sxadz5lf3gdxvl52mk90166080qciq2-b2332 URL: nar/03k8c0zykz5hv16v5bsdi37aw4hgb6x6cv4yvw9jb49qfkcfbnyg.nar.zst2333 Compression: zstd2334 NarHash: sha256:03k8c0zykz5hv16v5bsdi37aw4hgb6x6cv4yvw9jb49qfkcfbnyg2335 NarSize: 2482336 References: /nix/var/nix/builds/nix-68619-1936780597/TestClientPushesUseOnePush1993961195/001/store/9s73mzw64x7xg82vp6q3laacawfdv8gq-shared-dep2337 CA: text:sha256:05j69n1ps4nfqjjhzmsv7r4ipl4fqn34i6pam0v8h4c32n9isijv23382026/10/01 07:39:37 OK 20241026095416_initial_model.sql (173.66ms)2339--- PASS: TestClientPushesUseOnePush (4.03s)2340=== CONT TestGCSweepSkipsPendingObjects23412026/10/01 07:39:37 OK 20251210153512_drop_unused_gin_index.sql (1.36ms)23422026/10/01 07:39:37 OK 20251218171726_add_pins.sql (15.91ms)23432026/10/01 07:39:37 OK 20260628120000_add_object_size_and_stats.sql (37.07ms)23442026-10-01 07:39:37.949 UTC [69839] ERROR: relation "goose_db_version" does not exist at character 3623452026-10-01 07:39:37.949 UTC [69839] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23462026/10/01 07:39:37 OK 20260905000000_add_claims.sql (49.91ms)23472026/10/01 07:39:37 OK 20260920000000_drop_claims.sql (27.55ms)23482026/10/01 07:39:37 OK 20241026095416_initial_model.sql (167.92ms)23492026/10/01 07:39:37 OK 20260923120000_add_pushes.sql (3.68ms)23502026/10/01 07:39:37 goose: successfully migrated database to version: 2026092312000023512026/10/01 07:39:38 OK 1_commit_pending_closure.sql (1.39ms)23522026/10/01 07:39:38 OK 2_object_stats_trigger.sql (257.25µs)23532026/10/01 07:39:38 OK 3_commit_push.sql (200.08µs)23542026/10/01 07:39:38 goose: up to current file version: 323552026/10/01 07:39:38 OK 20251210153512_drop_unused_gin_index.sql (9.66ms)23562026/10/01 07:39:38 OK 20251218171726_add_pins.sql (106.19ms)23572026/10/01 07:39:38 OK 20260628120000_add_object_size_and_stats.sql (53.14ms)23582026/10/01 07:39:38 OK 20260905000000_add_claims.sql (66.71ms)23592026/10/01 07:39:38 OK 20241026095416_initial_model.sql (283.65ms)23602026/10/01 07:39:38 OK 20260920000000_drop_claims.sql (54.32ms)23612026/10/01 07:39:38 OK 20251210153512_drop_unused_gin_index.sql (18.94ms)2362=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2363=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2364=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2365=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2366=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2367=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2368=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2369=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2370=== CONT TestService_cleanupPendingClosuresHandler23712026/10/01 07:39:38 OK 20260923120000_add_pushes.sql (28.92ms)23722026/10/01 07:39:38 goose: successfully migrated database to version: 2026092312000023732026-10-01 07:39:38.317 UTC [69840] ERROR: relation "goose_db_version" does not exist at character 3623742026-10-01 07:39:38.317 UTC [69840] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23752026/10/01 07:39:38 OK 20251218171726_add_pins.sql (17.31ms)23762026/10/01 07:39:38 OK 1_commit_pending_closure.sql (6.82ms)23772026/10/01 07:39:38 OK 2_object_stats_trigger.sql (908.04µs)23782026/10/01 07:39:38 OK 3_commit_push.sql (542.96µs)23792026/10/01 07:39:38 goose: up to current file version: 323802026/10/01 07:39:38 OK 20260628120000_add_object_size_and_stats.sql (65.82ms)23812026/10/01 07:39:38 OK 20260905000000_add_claims.sql (100.99ms)23822026/10/01 07:39:38 OK 20260920000000_drop_claims.sql (62.01ms)23832026/10/01 07:39:38 OK 20260923120000_add_pushes.sql (36.56ms)23842026/10/01 07:39:38 goose: successfully migrated database to version: 2026092312000023852026/10/01 07:39:38 OK 1_commit_pending_closure.sql (7.25ms)23862026/10/01 07:39:38 OK 2_object_stats_trigger.sql (3.04ms)23872026/10/01 07:39:38 OK 3_commit_push.sql (1.7ms)23882026/10/01 07:39:38 goose: up to current file version: 323892026/10/01 07:39:38 OK 20241026095416_initial_model.sql (294.21ms)23902026/10/01 07:39:38 OK 20251210153512_drop_unused_gin_index.sql (11ms)23912026/10/01 07:39:38 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"23922026/10/01 07:39:38 WARN mTLS auth: bound subjects configured but subject DN unavailable23932026/10/01 07:39:38 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2394--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (3.28s)2395=== CONT TestServerTLSConfig/no_client_CA2396=== CONT TestServerTLSConfig/not_a_PEM_file23972026/10/01 07:39:38 OK 20251218171726_add_pins.sql (75.89ms)2398=== CONT TestServerTLSConfig/missing_CA_file2399--- PASS: TestServerTLSConfig (0.00s)2400 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2401 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)2402 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2403=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info24042026/10/01 07:39:38 INFO Received uploads request method=POST path=/2405=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key24062026/10/01 07:39:38 INFO Received complete multipart upload request method=POST path=/2407=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key24082026/10/01 07:39:38 INFO Received request for more parts method=POST path=/2409=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal24102026/10/01 07:39:38 INFO Received uploads request method=POST path=/2411--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2412 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2413 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2414 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2415 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2416=== CONT TestProxyWriteTimeout/narinfo2417=== CONT TestProxyWriteTimeout/unknown_size2418=== CONT TestProxyWriteTimeout/10_GiB_nar2419=== CONT TestProxyWriteTimeout/1_GiB_nar2420--- PASS: TestProxyWriteTimeout (0.01s)2421 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2422 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2423 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2424 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2425=== CONT TestIsValidUploadKey/narinfo2426=== CONT TestIsValidUploadKey/unknown_type2427=== CONT TestIsValidUploadKey/empty_key2428=== CONT TestIsValidUploadKey/absolute2429=== CONT TestIsValidUploadKey/traversal_nar2430=== CONT TestIsValidUploadKey/traversal2431=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2432=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2433=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2434=== CONT TestIsValidUploadKey/index.html2435=== CONT TestIsValidUploadKey/nix-cache-info2436=== CONT TestIsValidUploadKey/realisation_plus_in_output2437=== CONT TestIsValidUploadKey/realisation2438=== CONT TestIsValidUploadKey/build_log_equals2439=== CONT TestIsValidUploadKey/build_log_question_mark2440=== CONT TestIsValidUploadKey/build_log_plus_in_name2441=== CONT TestIsValidUploadKey/build_log_home-manager_file2442=== CONT TestIsValidUploadKey/build_log2443=== CONT TestIsValidUploadKey/listing2444=== CONT TestIsValidUploadKey/nar_plain2445=== CONT TestIsValidUploadKey/nar_xz2446=== CONT TestIsValidUploadKey/nar_zst2447--- PASS: TestIsValidUploadKey (0.02s)2448 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2449 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2450 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2451 --- PASS: TestIsValidUploadKey/absolute (0.00s)2452 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2453 --- PASS: TestIsValidUploadKey/traversal (0.00s)2454 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2455 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2456 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2457 --- PASS: TestIsValidUploadKey/index.html (0.00s)2458 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2459 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2460 --- PASS: TestIsValidUploadKey/realisation (0.00s)2461 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2462 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2463 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2464 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2465 --- PASS: TestIsValidUploadKey/build_log (0.00s)2466 --- PASS: TestIsValidUploadKey/listing (0.00s)2467 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2468 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2469 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2470=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts24712026/10/01 07:39:38 INFO Received request for more parts method=POST path=/24722026/10/01 07:39:38 OK 20260628120000_add_object_size_and_stats.sql (49.9ms)2473=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure24742026/10/01 07:39:38 INFO Received uploads request method=POST path=/24752026/10/01 07:39:38 OK 20260905000000_add_claims.sql (58.66ms)24762026/10/01 07:39:38 OK 20260920000000_drop_claims.sql (55.82ms)24772026/10/01 07:39:38 OK 20260923120000_add_pushes.sql (15.52ms)24782026/10/01 07:39:38 goose: successfully migrated database to version: 2026092312000024792026/10/01 07:39:38 OK 1_commit_pending_closure.sql (909.17µs)24802026/10/01 07:39:38 OK 2_object_stats_trigger.sql (241.25µs)24812026/10/01 07:39:38 OK 3_commit_push.sql (163.88µs)24822026/10/01 07:39:38 goose: up to current file version: 32483--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (3.33s)2484=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart24852026/10/01 07:39:39 INFO Received complete multipart upload request method=POST path=/2486=== CONT TestParseSingleRange/none2487=== CONT TestParseSingleRange/open-ended2488=== CONT TestParseSingleRange/start_far_past_EOF2489=== CONT TestParseSingleRange/start_past_EOF2490=== CONT TestParseSingleRange/single_byte2491=== CONT TestParseSingleRange/suffix_exceeds_size2492=== CONT TestParseSingleRange/suffix2493=== CONT TestParseSingleRange/end_clamped_to_size2494=== CONT TestParseSingleRange/malformed_both_empty2495=== CONT TestParseSingleRange/closed2496=== CONT TestParseSingleRange/malformed_end_before_start2497=== CONT TestParseSingleRange/multi-range_ignored2498=== CONT TestParseSingleRange/malformed_no_dash2499=== CONT TestParseSingleRange/unknown_unit2500--- PASS: TestParseSingleRange (0.00s)2501 --- PASS: TestParseSingleRange/none (0.00s)2502 --- PASS: TestParseSingleRange/open-ended (0.00s)2503 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2504 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2505 --- PASS: TestParseSingleRange/single_byte (0.00s)2506 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2507 --- PASS: TestParseSingleRange/suffix (0.00s)2508 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2509 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2510 --- PASS: TestParseSingleRange/closed (0.00s)2511 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2512 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2513 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2514 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2515=== CONT TestIsValidCachePath/narinfo2516=== CONT TestIsValidCachePath/index.html2517=== CONT TestIsValidCachePath/short_hash2518=== CONT TestIsValidCachePath/wrong_extension2519=== CONT TestIsValidCachePath/leading_slash2520=== CONT TestIsValidCachePath/empty2521=== CONT TestIsValidCachePath/random_path2522=== CONT TestIsValidCachePath/invalid_char_u2523=== CONT TestIsValidCachePath/invalid_char_e2524=== CONT TestIsValidCachePath/traversal_in_middle2525=== CONT TestIsValidCachePath/traversal_parent2526=== CONT TestIsValidCachePath/nar_uncompressed2527=== CONT TestIsValidCachePath/nix-cache-info2528=== CONT TestIsValidCachePath/realisation2529=== CONT TestIsValidCachePath/log2530=== CONT TestIsValidCachePath/ls2531=== CONT TestIsValidCachePath/nar_xz2532=== CONT TestIsValidCachePath/nar_bz22533=== CONT TestIsValidCachePath/nar_zst2534=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2535--- PASS: TestIsValidCachePath (0.00s)2536 --- PASS: TestIsValidCachePath/narinfo (0.00s)2537 --- PASS: TestIsValidCachePath/index.html (0.00s)2538 --- PASS: TestIsValidCachePath/short_hash (0.00s)2539 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2540 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2541 --- PASS: TestIsValidCachePath/empty (0.00s)2542 --- PASS: TestIsValidCachePath/random_path (0.00s)2543 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2544 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2545 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2546 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2547 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2548 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2549 --- PASS: TestIsValidCachePath/realisation (0.00s)2550 --- PASS: TestIsValidCachePath/log (0.00s)2551 --- PASS: TestIsValidCachePath/ls (0.00s)2552 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2553 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2554 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2555 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2556=== CONT TestPush_RejectsBadRequests/root_not_in_objects25572026/10/01 07:39:39 INFO Received push request method=POST path=/api/pushes2558=== CONT TestPush_RejectsBadRequests/no_objects25592026/10/01 07:39:39 INFO Received push request method=POST path=/api/pushes2560=== CONT TestPush_RejectsBadRequests/bad_root25612026/10/01 07:39:39 INFO Received push request method=POST path=/api/pushes2562=== CONT TestPush_RejectsBadRequests/no_roots25632026/10/01 07:39:39 INFO Received push request method=POST path=/api/pushes2564=== CONT TestClientErrorHandling/InvalidStorePath2565--- PASS: TestPush_RejectsBadRequests (4.58s)2566 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2567 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2568 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2569 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2570--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)2571 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2572 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)2573 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2574=== CONT TestClientErrorHandling/ServerNotAvailable25752026-10-01 07:39:39.241 UTC [69843] ERROR: relation "goose_db_version" does not exist at character 3625762026-10-01 07:39:39.241 UTC [69843] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2577--- PASS: TestReadProxyNarinfoAlreadyDecompressed (3.55s)2578=== CONT TestClientErrorHandling/InvalidAuthToken25792026/10/01 07:39:39 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present25802026/10/01 07:39:39 OK 20241026095416_initial_model.sql (257.65ms)25812026/10/01 07:39:39 OK 20251210153512_drop_unused_gin_index.sql (6.7ms)25822026/10/01 07:39:39 OK 20251218171726_add_pins.sql (23.68ms)25832026-10-01 07:39:39.665 UTC [69851] ERROR: relation "goose_db_version" does not exist at character 3625842026-10-01 07:39:39.665 UTC [69851] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25852026/10/01 07:39:39 OK 20260628120000_add_object_size_and_stats.sql (37.69ms)25862026/10/01 07:39:39 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=188.361103ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present25872026/10/01 07:39:39 OK 20260905000000_add_claims.sql (50.16ms)25882026-10-01 07:39:39.753 UTC [69854] ERROR: relation "goose_db_version" does not exist at character 3625892026-10-01 07:39:39.753 UTC [69854] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25902026/10/01 07:39:39 OK 20260920000000_drop_claims.sql (32.52ms)25912026/10/01 07:39:39 OK 20260923120000_add_pushes.sql (17.3ms)25922026/10/01 07:39:39 goose: successfully migrated database to version: 2026092312000025932026/10/01 07:39:39 OK 1_commit_pending_closure.sql (2.2ms)25942026/10/01 07:39:39 OK 2_object_stats_trigger.sql (512.46µs)25952026/10/01 07:39:39 OK 3_commit_push.sql (407.67µs)25962026/10/01 07:39:39 goose: up to current file version: 325972026/10/01 07:39:39 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=403.377415ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present25982026-10-01 07:39:39.992 UTC [69855] ERROR: relation "goose_db_version" does not exist at character 3625992026-10-01 07:39:39.992 UTC [69855] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26002026/10/01 07:39:40 OK 20241026095416_initial_model.sql (389.4ms)26012026/10/01 07:39:40 OK 20251210153512_drop_unused_gin_index.sql (18.07ms)26022026/10/01 07:39:40 OK 20241026095416_initial_model.sql (284.22ms)26032026/10/01 07:39:40 OK 20251210153512_drop_unused_gin_index.sql (20.73ms)26042026/10/01 07:39:40 OK 20251218171726_add_pins.sql (54.2ms)26052026/10/01 07:39:40 OK 20251218171726_add_pins.sql (58.56ms)26062026/10/01 07:39:40 OK 20260628120000_add_object_size_and_stats.sql (45.75ms)26072026/10/01 07:39:40 OK 20260628120000_add_object_size_and_stats.sql (43.97ms)26082026/10/01 07:39:40 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=841.495446ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present26092026/10/01 07:39:40 OK 20260905000000_add_claims.sql (89.5ms)26102026/10/01 07:39:40 OK 20260905000000_add_claims.sql (73.8ms)26112026/10/01 07:39:40 INFO Aborted multipart uploads count=026122026/10/01 07:39:40 WARN Force mode enabled - objects will be deleted immediately without grace period26132026/10/01 07:39:40 OK 20260920000000_drop_claims.sql (47.77ms)26142026/10/01 07:39:40 OK 20260920000000_drop_claims.sql (39.73ms)26152026/10/01 07:39:40 OK 20260923120000_add_pushes.sql (10.65ms)26162026/10/01 07:39:40 goose: successfully migrated database to version: 2026092312000026172026/10/01 07:39:40 OK 20241026095416_initial_model.sql (249.53ms)26182026/10/01 07:39:40 OK 20260923120000_add_pushes.sql (14.19ms)26192026/10/01 07:39:40 goose: successfully migrated database to version: 2026092312000026202026/10/01 07:39:40 OK 1_commit_pending_closure.sql (4.2ms)26212026/10/01 07:39:40 OK 1_commit_pending_closure.sql (2.46ms)26222026/10/01 07:39:40 OK 2_object_stats_trigger.sql (613.96µs)26232026/10/01 07:39:40 OK 2_object_stats_trigger.sql (536.04µs)26242026/10/01 07:39:40 OK 3_commit_push.sql (381µs)26252026/10/01 07:39:40 goose: up to current file version: 326262026/10/01 07:39:40 OK 3_commit_push.sql (454.38µs)26272026/10/01 07:39:40 goose: up to current file version: 326282026/10/01 07:39:40 OK 20251210153512_drop_unused_gin_index.sql (14.48ms)26292026/10/01 07:39:40 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=026302026/10/01 07:39:40 INFO Vacuumed table table=pending_closures26312026/10/01 07:39:40 INFO Vacuumed table table=pending_objects26322026/10/01 07:39:40 INFO Vacuumed table table=multipart_uploads26332026/10/01 07:39:40 INFO Vacuumed table table=closures26342026/10/01 07:39:40 OK 20251218171726_add_pins.sql (47.8ms)26352026/10/01 07:39:40 INFO Vacuumed table table=objects2636--- PASS: TestGCSweepDeliversEachKeyOnce (4.06s)2637=== CONT TestCacheConfigHandler/full_config,_no_issuer2638=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2639=== CONT TestCacheConfigHandler/no_signing_keys2640=== CONT TestCacheConfigHandler/no_cache_url_configured2641--- PASS: TestCacheConfigHandler (0.00s)2642 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2643 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2644 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2645 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2646=== CONT TestResolveDBConnectionString/flag_wins2647=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2648=== CONT TestResolveDBConnectionString/nothing_configured2649=== CONT TestResolveDBConnectionString/missing_file_is_an_error2650=== CONT TestResolveDBConnectionString/file_when_flag_empty2651=== CONT TestService_RequireScope_OIDC/builder_may_write2652=== CONT TestService_RequireScope_OIDC/static_token_may_admin2653=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2654=== CONT TestService_RequireScope_OIDC/writer_implies_read2655=== CONT TestService_RequireScope_OIDC/reader_may_read2656=== CONT TestService_RequireScope_OIDC/static_token_may_write2657=== CONT TestService_RequireScope_OIDC/ops_may_not_write2658=== CONT TestService_RequireScope_OIDC/reader_may_not_write2659=== CONT TestService_RequireScope_OIDC/ops_may_admin2660=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2661=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2662--- PASS: TestResolveDBConnectionString (0.01s)2663 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2664 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2665 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2666 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2667 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2668=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2669=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected26702026/10/01 07:39:40 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]2671=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected26722026/10/01 07:39:40 WARN Authentication failed token_preview=eyJhbGciOi...Bw1PamO9HQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]26732026/10/01 07:39:40 OK 20260628120000_add_object_size_and_stats.sql (34.16ms)2674--- PASS: TestService_RequireScope_OIDC (3.20s)2675 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2676 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2677 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2678 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2679 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2680 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2681 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2682 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2683 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2684 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2685--- PASS: TestService_AuthMiddleware_OIDC (3.03s)2686 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2687 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2688 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2689 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)26902026/10/01 07:39:40 OK 20260905000000_add_claims.sql (109.45ms)26912026/10/01 07:39:40 OK 20260920000000_drop_claims.sql (77.32ms)26922026/10/01 07:39:40 OK 20260923120000_add_pushes.sql (32.3ms)26932026/10/01 07:39:40 goose: successfully migrated database to version: 2026092312000026942026/10/01 07:39:40 OK 1_commit_pending_closure.sql (5.24ms)26952026/10/01 07:39:40 OK 2_object_stats_trigger.sql (1.73ms)26962026/10/01 07:39:40 OK 3_commit_push.sql (890.21µs)26972026/10/01 07:39:40 goose: up to current file version: 326982026/10/01 07:39:40 INFO Received uploads request method=POST path=/api/pending_closures2699--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (3.95s)27002026/10/01 07:39:41 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.650592692s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27012026/10/01 07:39:41 INFO Received uploads request method=POST path=/api/pending_closures27022026-10-01 07:39:41.224 UTC [69857] ERROR: relation "goose_db_version" does not exist at character 3627032026-10-01 07:39:41.224 UTC [69857] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27042026/10/01 07:39:41 INFO Aborted multipart uploads count=027052026/10/01 07:39:41 WARN Force mode enabled - objects will be deleted immediately without grace period27062026/10/01 07:39:41 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."27072026/10/01 07:39:41 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."2708--- PASS: TestFailedS3DeleteKeepsTombstone (4.60s)27092026/10/01 07:39:41 OK 20241026095416_initial_model.sql (214.17ms)27102026/10/01 07:39:41 INFO Received uploads request method=POST path=/api/pending_closures27112026/10/01 07:39:41 OK 20251210153512_drop_unused_gin_index.sql (11.45ms)27122026-10-01 07:39:41.548 UTC [69859] ERROR: relation "goose_db_version" does not exist at character 3627132026-10-01 07:39:41.548 UTC [69859] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27142026/10/01 07:39:41 OK 20251218171726_add_pins.sql (20.66ms)2715--- PASS: TestTombstonedObjectOfferedWithoutWaiting (4.47s)27162026/10/01 07:39:41 OK 20260628120000_add_object_size_and_stats.sql (18.11ms)27172026/10/01 07:39:41 OK 20260905000000_add_claims.sql (27.5ms)27182026/10/01 07:39:41 OK 20260920000000_drop_claims.sql (24.09ms)27192026/10/01 07:39:41 OK 20260923120000_add_pushes.sql (4.23ms)27202026/10/01 07:39:41 goose: successfully migrated database to version: 2026092312000027212026/10/01 07:39:41 OK 1_commit_pending_closure.sql (3.94ms)27222026/10/01 07:39:41 OK 2_object_stats_trigger.sql (685.83µs)27232026/10/01 07:39:41 OK 3_commit_push.sql (391.67µs)27242026/10/01 07:39:41 goose: up to current file version: 327252026/10/01 07:39:41 OK 20241026095416_initial_model.sql (100.69ms)27262026/10/01 07:39:41 OK 20251210153512_drop_unused_gin_index.sql (8.81ms)27272026/10/01 07:39:41 OK 20251218171726_add_pins.sql (23.71ms)27282026/10/01 07:39:41 OK 20260628120000_add_object_size_and_stats.sql (43.59ms)27292026-10-01 07:39:41.780 UTC [69860] ERROR: relation "goose_db_version" does not exist at character 3627302026-10-01 07:39:41.780 UTC [69860] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27312026/10/01 07:39:41 OK 20260905000000_add_claims.sql (71.41ms)27322026/10/01 07:39:41 OK 20260920000000_drop_claims.sql (29.31ms)27332026/10/01 07:39:41 OK 20260923120000_add_pushes.sql (19.13ms)27342026/10/01 07:39:41 goose: successfully migrated database to version: 2026092312000027352026/10/01 07:39:41 OK 1_commit_pending_closure.sql (4.44ms)27362026/10/01 07:39:41 OK 2_object_stats_trigger.sql (1.06ms)27372026/10/01 07:39:41 OK 3_commit_push.sql (1.71ms)27382026/10/01 07:39:41 goose: up to current file version: 327392026/10/01 07:39:41 INFO Received uploads request method=POST path=/api/pending_closures27402026/10/01 07:39:42 OK 20241026095416_initial_model.sql (194.36ms)27412026/10/01 07:39:42 INFO Aborted multipart uploads count=027422026/10/01 07:39:42 OK 20251210153512_drop_unused_gin_index.sql (11.7ms)27432026/10/01 07:39:42 WARN Force mode enabled - objects will be deleted immediately without grace period27442026/10/01 07:39:42 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=027452026/10/01 07:39:42 INFO Vacuumed table table=pending_closures27462026/10/01 07:39:42 OK 20251218171726_add_pins.sql (22.88ms)27472026/10/01 07:39:42 INFO Vacuumed table table=pending_objects27482026/10/01 07:39:42 INFO Vacuumed table table=multipart_uploads27492026/10/01 07:39:42 INFO Vacuumed table table=closures27502026/10/01 07:39:42 INFO Vacuumed table table=objects27512026/10/01 07:39:42 OK 20260628120000_add_object_size_and_stats.sql (29.55ms)27522026-10-01 07:39:42.115 UTC [69862] ERROR: relation "goose_db_version" does not exist at character 3627532026-10-01 07:39:42.115 UTC [69862] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2754--- PASS: TestGCSweepSkipsPendingObjects (4.26s)2755=== NAME TestOrphanedObjectsGCStressTest2756 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains27572026/10/01 07:39:42 OK 20260905000000_add_claims.sql (70.09ms)2758 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion27592026/10/01 07:39:42 OK 20260920000000_drop_claims.sql (39.47ms)27602026/10/01 07:39:42 OK 20260923120000_add_pushes.sql (10.96ms)27612026/10/01 07:39:42 goose: successfully migrated database to version: 2026092312000027622026/10/01 07:39:42 OK 1_commit_pending_closure.sql (1.9ms)27632026/10/01 07:39:42 OK 2_object_stats_trigger.sql (393.38µs)27642026/10/01 07:39:42 OK 3_commit_push.sql (281.75µs)27652026/10/01 07:39:42 goose: up to current file version: 327662026/10/01 07:39:42 INFO Received cleanup request method=DELETE path=/api/pending_closures27672026/10/01 07:39:42 OK 20241026095416_initial_model.sql (99.96ms)27682026/10/01 07:39:42 INFO Aborted multipart uploads count=027692026/10/01 07:39:42 OK 20251210153512_drop_unused_gin_index.sql (1.94ms)27702026/10/01 07:39:42 INFO Received uploads request method=POST path=/api/pending_closures27712026/10/01 07:39:42 OK 20251218171726_add_pins.sql (27.61ms)27722026/10/01 07:39:42 OK 20260628120000_add_object_size_and_stats.sql (35.97ms)27732026/10/01 07:39:42 INFO Received cleanup request method=DELETE path=/api/pending_closures27742026/10/01 07:39:42 INFO Aborted multipart uploads count=127752026/10/01 07:39:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete27762026-10-01 07:39:42.371 UTC [69859] ERROR: Closure does not exist: id=127772026-10-01 07:39:42.371 UTC [69859] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE27782026-10-01 07:39:42.371 UTC [69859] STATEMENT: -- name: CommitPendingClosure :exec2779 SELECT commit_pending_closure($1::bigint)2780 2781--- PASS: TestService_cleanupPendingClosuresHandler (4.05s)27822026/10/01 07:39:42 OK 20260905000000_add_claims.sql (50.44ms)27832026/10/01 07:39:42 OK 20260920000000_drop_claims.sql (44.86ms)27842026/10/01 07:39:42 OK 20260923120000_add_pushes.sql (4.54ms)27852026/10/01 07:39:42 goose: successfully migrated database to version: 2026092312000027862026/10/01 07:39:42 OK 1_commit_pending_closure.sql (5.04ms)27872026/10/01 07:39:42 OK 2_object_stats_trigger.sql (2.35ms)27882026/10/01 07:39:42 OK 3_commit_push.sql (687.63µs)27892026/10/01 07:39:42 goose: up to current file version: 327902026/10/01 07:39:42 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27912026/10/01 07:39:42 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=219.309327ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27922026/10/01 07:39:42 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"27932026/10/01 07:39:42 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2794=== NAME TestOrphanedObjectsGCStressTest2795 orphaned_objects_gc_test.go:509: Stress test completed successfully:2796 orphaned_objects_gc_test.go:510: - Active objects preserved: 202797 orphaned_objects_gc_test.go:511: - Objects deleted: 2102798 orphaned_objects_gc_test.go:512: - Total GC'd: 2102799--- PASS: TestOrphanedObjectsGCStressTest (9.98s)28002026/10/01 07:39:43 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=383.088098ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28012026/10/01 07:39:43 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=749.32948ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28022026/10/01 07:39:44 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.463220216s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28032026/10/01 07:39:45 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"28042026/10/01 07:39:45 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28052026/10/01 07:39:45 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=215.8769ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28062026/10/01 07:39:46 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=410.292729ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28072026/10/01 07:39:46 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=830.641583ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28082026/10/01 07:39:47 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.502732162s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28092026/10/01 07:39:48 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28102026/10/01 07:39:48 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=189.91853ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28112026/10/01 07:39:49 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=426.930861ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28122026/10/01 07:39:49 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=839.887491ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28132026/10/01 07:39:50 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.735417306s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2814--- PASS: TestClientErrorHandling (0.00s)2815 --- PASS: TestClientErrorHandling/InvalidStorePath (3.53s)2816 --- PASS: TestClientErrorHandling/InvalidAuthToken (3.41s)2817 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.99s)2818PASS28192026-10-01 07:39:52.251 UTC [68996] LOG: received smart shutdown request28202026-10-01 07:39:52.252 UTC [68996] LOG: background worker "logical replication launcher" (PID 69007) exited with exit code 128212026-10-01 07:39:52.258 UTC [69002] LOG: shutting down28222026-10-01 07:39:52.258 UTC [69002] LOG: checkpoint starting: shutdown immediate28232026-10-01 07:39:53.439 UTC [69002] LOG: checkpoint complete: wrote 12819 buffers (78.2%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 21 recycled; write=0.724 s, sync=0.422 s, total=1.182 s; sync files=24926, longest=0.001 s, average=0.001 s; distance=344970 kB, estimate=344970 kB; lsn=0/1686FA58, redo lsn=0/1686FA5828242026-10-01 07:39:53.445 UTC [68996] LOG: database system is shut down2825Running OIDC tests...2826=== RUN TestAudienceForIssuer2827=== PAUSE TestAudienceForIssuer2828=== RUN TestGlobMatch2829=== PAUSE TestGlobMatch2830=== RUN TestValidateToken_ValidToken2831=== PAUSE TestValidateToken_ValidToken2832=== RUN TestValidateToken_WrongAudience2833=== PAUSE TestValidateToken_WrongAudience2834=== RUN TestValidateToken_Expired2835=== PAUSE TestValidateToken_Expired2836=== RUN TestValidateToken_BoundClaimsMismatch2837=== PAUSE TestValidateToken_BoundClaimsMismatch2838=== RUN TestValidateToken_BoundSubjectMismatch2839=== PAUSE TestValidateToken_BoundSubjectMismatch2840=== RUN TestValidateToken_MultipleProviders2841=== PAUSE TestValidateToken_MultipleProviders2842=== RUN TestValidateToken_NoMatchingProvider2843=== PAUSE TestValidateToken_NoMatchingProvider2844=== RUN TestValidateToken_KubernetesServiceAccount2845=== PAUSE TestValidateToken_KubernetesServiceAccount2846=== RUN TestNewValidator_KubernetesRequiresCA2847=== PAUSE TestNewValidator_KubernetesRequiresCA2848=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2849=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2850=== RUN TestPins_ReservedForMatchingRule2851=== PAUSE TestPins_ReservedForMatchingRule2852=== RUN TestPins_TopLevelShorthand2853=== PAUSE TestPins_TopLevelShorthand2854=== RUN TestPins_ConfigValidation2855=== PAUSE TestPins_ConfigValidation2856=== RUN TestScopes_LegacyProviderDefaultsToWrite2857=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2858=== RUN TestScopes_Rules2859=== PAUSE TestScopes_Rules2860=== RUN TestScopes_ConfigValidation2861=== PAUSE TestScopes_ConfigValidation2862=== CONT TestAudienceForIssuer2863--- PASS: TestAudienceForIssuer (0.00s)2864=== CONT TestValidateToken_NoMatchingProvider2865=== CONT TestPins_ConfigValidation2866=== CONT TestScopes_ConfigValidation2867=== CONT TestScopes_Rules2868=== CONT TestScopes_LegacyProviderDefaultsToWrite2869=== CONT TestValidateToken_ValidToken2870=== CONT TestValidateToken_WrongAudience2871--- PASS: TestPins_ConfigValidation (0.00s)2872=== CONT TestGlobMatch2873=== RUN TestGlobMatch/foo_foo2874=== PAUSE TestGlobMatch/foo_foo2875=== RUN TestGlobMatch/foo_bar2876=== PAUSE TestGlobMatch/foo_bar2877=== RUN TestGlobMatch/*_2878=== PAUSE TestGlobMatch/*_2879=== RUN TestGlobMatch/*_anything2880=== PAUSE TestGlobMatch/*_anything2881=== RUN TestGlobMatch/foo*_foo2882=== PAUSE TestGlobMatch/foo*_foo2883=== RUN TestGlobMatch/foo*_foobar2884=== PAUSE TestGlobMatch/foo*_foobar2885=== RUN TestGlobMatch/foo*_bar2886=== PAUSE TestGlobMatch/foo*_bar2887=== RUN TestGlobMatch/*bar_bar2888=== PAUSE TestGlobMatch/*bar_bar2889=== RUN TestGlobMatch/*bar_foobar2890=== PAUSE TestGlobMatch/*bar_foobar2891=== RUN TestGlobMatch/*bar_foo2892=== PAUSE TestGlobMatch/*bar_foo2893=== RUN TestGlobMatch/foo*bar_foobar2894=== PAUSE TestGlobMatch/foo*bar_foobar2895=== RUN TestGlobMatch/foo*bar_foo123bar2896=== PAUSE TestGlobMatch/foo*bar_foo123bar2897=== RUN TestGlobMatch/foo*bar_foobarbaz2898=== PAUSE TestGlobMatch/foo*bar_foobarbaz2899=== RUN TestGlobMatch/*/*_foo/bar2900=== PAUSE TestGlobMatch/*/*_foo/bar2901--- PASS: TestScopes_ConfigValidation (0.00s)2902=== CONT TestPins_TopLevelShorthand2903=== CONT TestValidateToken_KubernetesServiceAccount2904=== CONT TestValidateToken_BoundSubjectMismatch2905=== CONT TestPins_ReservedForMatchingRule2906=== RUN TestGlobMatch/*/*_foo2907=== PAUSE TestGlobMatch/*/*_foo2908=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2909=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2910=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02911=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02912=== RUN TestGlobMatch/refs/*/main_refs/heads/main2913=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2914=== RUN TestGlobMatch/fo?_foo2915=== PAUSE TestGlobMatch/fo?_foo2916=== RUN TestGlobMatch/fo?_fo2917=== PAUSE TestGlobMatch/fo?_fo2918=== RUN TestGlobMatch/fo?_fooo2919=== PAUSE TestGlobMatch/fo?_fooo2920=== RUN TestGlobMatch/?oo_foo2921=== PAUSE TestGlobMatch/?oo_foo2922=== RUN TestGlobMatch/?oo_boo2923=== PAUSE TestGlobMatch/?oo_boo2924=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2925=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2926=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2927=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2928=== CONT TestValidateToken_MultipleProviders29292026/10/01 07:39:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58601/oidc29302026/10/01 07:39:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58603/oidc2931--- PASS: TestPins_TopLevelShorthand (0.03s)2932=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2933--- PASS: TestScopes_Rules (0.04s)2934=== CONT TestValidateToken_BoundClaimsMismatch29352026/10/01 07:39:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58605/oidc2936--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)2937=== CONT TestNewValidator_KubernetesRequiresCA29382026/10/01 07:39:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58608/oidc2939--- PASS: TestValidateToken_BoundSubjectMismatch (0.05s)2940=== CONT TestValidateToken_Expired29412026/10/01 07:39:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58610/oidc2942--- PASS: TestValidateToken_ValidToken (0.07s)2943=== CONT TestGlobMatch/foo_foo2944=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2945=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2946=== CONT TestGlobMatch/?oo_boo2947=== CONT TestGlobMatch/?oo_foo2948=== CONT TestGlobMatch/fo?_fooo2949=== CONT TestGlobMatch/fo?_fo2950=== CONT TestGlobMatch/fo?_foo2951=== CONT TestGlobMatch/refs/*/main_refs/heads/main2952=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02953=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2954=== CONT TestGlobMatch/*/*_foo2955=== CONT TestGlobMatch/*/*_foo/bar2956=== CONT TestGlobMatch/foo*bar_foobarbaz2957=== CONT TestGlobMatch/foo*bar_foo123bar2958=== CONT TestGlobMatch/foo*bar_foobar2959=== CONT TestGlobMatch/*bar_foo2960=== CONT TestGlobMatch/*bar_foobar2961=== CONT TestGlobMatch/*bar_bar2962=== CONT TestGlobMatch/foo*_bar2963=== CONT TestGlobMatch/foo*_foobar2964=== CONT TestGlobMatch/foo*_foo2965=== CONT TestGlobMatch/*_anything2966=== CONT TestGlobMatch/*_2967=== CONT TestGlobMatch/foo_bar2968--- PASS: TestGlobMatch (0.00s)2969 --- PASS: TestGlobMatch/foo_foo (0.00s)2970 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2971 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2972 --- PASS: TestGlobMatch/?oo_boo (0.00s)2973 --- PASS: TestGlobMatch/?oo_foo (0.00s)2974 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2975 --- PASS: TestGlobMatch/fo?_fo (0.00s)2976 --- PASS: TestGlobMatch/fo?_foo (0.00s)2977 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2978 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2979 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2980 --- PASS: TestGlobMatch/*/*_foo (0.00s)2981 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2982 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2983 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2984 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2985 --- PASS: TestGlobMatch/*bar_foo (0.00s)2986 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2987 --- PASS: TestGlobMatch/*bar_bar (0.00s)2988 --- PASS: TestGlobMatch/foo*_bar (0.00s)2989 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2990 --- PASS: TestGlobMatch/foo*_foo (0.00s)2991 --- PASS: TestGlobMatch/*_anything (0.00s)2992 --- PASS: TestGlobMatch/*_ (0.00s)2993 --- PASS: TestGlobMatch/foo_bar (0.00s)29942026/10/01 07:39:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58612/oidc2995--- PASS: TestValidateToken_WrongAudience (0.08s)29962026/10/01 07:39:54 http: TLS handshake error from 127.0.0.1:58615: remote error: tls: bad certificate2997--- PASS: TestNewValidator_KubernetesRequiresCA (0.04s)29982026/10/01 07:39:54 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12329992026/10/01 07:39:54 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:586173000--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)3001--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)30022026/10/01 07:39:54 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:58607/oidc3003--- PASS: TestValidateToken_NoMatchingProvider (0.11s)30042026/10/01 07:39:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58622/oidc3005--- PASS: TestValidateToken_Expired (0.06s)30062026/10/01 07:39:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58624/oidc3007--- PASS: TestPins_ReservedForMatchingRule (0.12s)30082026/10/01 07:39:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58627/oidc3009--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)30102026/10/01 07:39:54 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:58629/oidc30112026/10/01 07:39:54 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:58626/oidc3012--- PASS: TestValidateToken_MultipleProviders (0.15s)3013PASS3014Running hook tests...3015=== RUN TestSendPathsEmpty3016=== PAUSE TestSendPathsEmpty3017=== RUN TestQueueEnqueueAndFetch3018=== PAUSE TestQueueEnqueueAndFetch3019=== RUN TestQueueDeduplication3020=== PAUSE TestQueueDeduplication3021=== RUN TestQueueRemove3022=== PAUSE TestQueueRemove3023=== RUN TestQueueFetchBatchLimit3024=== PAUSE TestQueueFetchBatchLimit3025=== RUN TestQueueRetryMovesToBack3026=== PAUSE TestQueueRetryMovesToBack3027=== RUN TestQueueFetchRemoveLifecycle3028=== PAUSE TestQueueFetchRemoveLifecycle3029=== RUN TestQueueConcurrentWriters3030=== PAUSE TestQueueConcurrentWriters3031=== RUN TestQueueRemoveLargeClosure3032=== PAUSE TestQueueRemoveLargeClosure3033=== RUN TestServerClientIntegration3034=== PAUSE TestServerClientIntegration3035=== RUN TestServerQueueError3036=== PAUSE TestServerQueueError3037=== RUN TestGetListenerSocketActivation3038 server_test.go:210: === RUN TestGetListenerSocketActivation3039 --- PASS: TestGetListenerSocketActivation (0.00s)3040 PASS3041 3042--- PASS: TestGetListenerSocketActivation (0.01s)3043=== RUN TestDrainIsolatesPoisonPath3044=== PAUSE TestDrainIsolatesPoisonPath3045=== RUN TestRunNotBlockedByPoisonHead3046=== PAUSE TestRunNotBlockedByPoisonHead3047=== RUN TestDrainGivesUpWhenServerDown3048=== PAUSE TestDrainGivesUpWhenServerDown3049=== RUN TestFailedPathPrunedByLaterClosure3050=== PAUSE TestFailedPathPrunedByLaterClosure3051=== RUN TestWorkerUploadsAndRemoves3052=== PAUSE TestWorkerUploadsAndRemoves3053=== RUN TestWorkerSkipsGCdPaths3054=== PAUSE TestWorkerSkipsGCdPaths3055=== RUN TestWorkerPrunesClosureDeps3056=== PAUSE TestWorkerPrunesClosureDeps3057=== RUN TestDrainTimeout3058=== PAUSE TestDrainTimeout3059=== CONT TestSendPathsEmpty3060=== CONT TestServerQueueError3061=== CONT TestWorkerUploadsAndRemoves3062=== CONT TestServerClientIntegration3063=== CONT TestQueueRetryMovesToBack3064=== CONT TestQueueConcurrentWriters3065=== CONT TestDrainGivesUpWhenServerDown3066--- PASS: TestSendPathsEmpty (0.00s)3067=== CONT TestWorkerSkipsGCdPaths3068=== CONT TestWorkerPrunesClosureDeps3069=== CONT TestFailedPathPrunedByLaterClosure3070=== CONT TestDrainTimeout30712026/10/01 07:39:54 ERROR Failed to queue paths error="permission denied" count=13072--- PASS: TestServerQueueError (0.00s)3073=== CONT TestRunNotBlockedByPoisonHead3074--- PASS: TestServerClientIntegration (0.00s)3075=== CONT TestQueueDeduplication30762026/10/01 07:39:54 INFO Upload queue status pending=230772026/10/01 07:39:54 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-68619-1936780597/TestWorkerSkipsGCdPaths2442072432/002/nonexistent30782026/10/01 07:39:54 INFO Uploading batch count=130792026/10/01 07:39:54 INFO Upload queue status pending=230802026/10/01 07:39:54 INFO Upload queue status pending=230812026/10/01 07:39:54 INFO Uploading batch count=230822026/10/01 07:39:54 INFO Uploading batch count=130832026/10/01 07:39:54 INFO Uploading batch count=230842026/10/01 07:39:54 INFO Upload queue status pending=330852026/10/01 07:39:54 INFO Uploading batch count=130862026/10/01 07:39:54 ERROR Upload failed error="upload failed" count=130872026/10/01 07:39:54 INFO Uploading batch count=230882026/10/01 07:39:54 ERROR Upload failed error="upload failed" count=230892026/10/01 07:39:54 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-68619-1936780597/TestDrainGivesUpWhenServerDown908800877/002/a30902026/10/01 07:39:54 INFO Uploading batch count=130912026/10/01 07:39:54 ERROR Upload failed error="upload failed" count=130922026/10/01 07:39:54 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-68619-1936780597/TestDrainGivesUpWhenServerDown908800877/002/b3093--- PASS: TestQueueDeduplication (0.01s)3094=== CONT TestQueueRemoveLargeClosure30952026/10/01 07:39:54 INFO Uploading batch count=230962026/10/01 07:39:54 ERROR Upload failed error="upload failed" count=230972026/10/01 07:39:54 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-68619-1936780597/TestDrainGivesUpWhenServerDown908800877/002/c30982026/10/01 07:39:54 INFO Uploading batch count=130992026/10/01 07:39:54 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-68619-1936780597/TestDrainGivesUpWhenServerDown908800877/002/d31002026/10/01 07:39:54 INFO Uploading batch count=13101--- PASS: TestQueueRetryMovesToBack (0.01s)31022026/10/01 07:39:54 INFO Uploading batch count=23103=== CONT TestDrainIsolatesPoisonPath31042026/10/01 07:39:54 ERROR Upload failed error="upload failed" count=231052026/10/01 07:39:54 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-68619-1936780597/TestDrainGivesUpWhenServerDown908800877/002/e31062026/10/01 07:39:54 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-68619-1936780597/TestDrainGivesUpWhenServerDown908800877/002/f31072026/10/01 07:39:54 ERROR Drain finished with paths left in queue remaining=103108--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)3109=== CONT TestQueueEnqueueAndFetch31102026/10/01 07:39:54 INFO Uploading batch count=431112026/10/01 07:39:54 ERROR Upload failed error="upload failed" count=43112--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3113=== CONT TestQueueFetchRemoveLifecycle31142026/10/01 07:39:54 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-68619-1936780597/TestDrainIsolatesPoisonPath1542992448/002/bbb31152026/10/01 07:39:54 INFO Uploading batch count=131162026/10/01 07:39:54 ERROR Upload failed error="upload failed" count=13117--- PASS: TestQueueEnqueueAndFetch (0.00s)3118=== CONT TestQueueFetchBatchLimit31192026/10/01 07:39:54 INFO Uploading batch count=131202026/10/01 07:39:54 ERROR Upload failed error="upload failed" count=131212026/10/01 07:39:54 INFO Uploading batch count=131222026/10/01 07:39:54 ERROR Upload failed error="upload failed" count=131232026/10/01 07:39:54 ERROR Drain finished with paths left in queue remaining=13124--- PASS: TestQueueFetchRemoveLifecycle (0.00s)3125=== CONT TestQueueRemove3126--- PASS: TestDrainIsolatesPoisonPath (0.01s)3127--- PASS: TestQueueFetchBatchLimit (0.00s)3128--- PASS: TestQueueRemove (0.00s)3129--- PASS: TestWorkerUploadsAndRemoves (0.03s)3130--- PASS: TestWorkerSkipsGCdPaths (0.03s)3131--- PASS: TestWorkerPrunesClosureDeps (0.03s)3132--- PASS: TestQueueRemoveLargeClosure (0.04s)3133--- PASS: TestQueueConcurrentWriters (0.13s)31342026/10/01 07:39:55 ERROR Upload failed error="context deadline exceeded" count=231352026/10/01 07:39:55 ERROR Drain finished with paths left in queue remaining=43136--- PASS: TestDrainTimeout (0.21s)31372026/10/01 07:39:55 INFO Uploading batch count=131382026/10/01 07:39:55 INFO Uploading batch count=131392026/10/01 07:39:55 INFO Uploading batch count=131402026/10/01 07:39:55 ERROR Upload failed error="upload failed" count=131412026/10/01 07:39:55 INFO Uploading batch count=131422026/10/01 07:39:55 ERROR Upload failed error="upload failed" count=131432026/10/01 07:39:55 INFO Uploading batch count=131442026/10/01 07:39:55 ERROR Upload failed error="upload failed" count=131452026/10/01 07:39:55 INFO Uploading batch count=131462026/10/01 07:39:55 ERROR Upload failed error="upload failed" count=131472026/10/01 07:39:55 ERROR Drain finished with paths left in queue remaining=13148--- PASS: TestRunNotBlockedByPoisonHead (1.02s)3149PASS