niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #146
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestFilterOversizedClosures7=== PAUSE TestFilterOversizedClosures8=== RUN TestPartSizeForNAR9=== PAUSE TestPartSizeForNAR10=== RUN TestUploadMultipart_SupersededByPeer11=== PAUSE TestUploadMultipart_SupersededByPeer12=== RUN TestDumpPathMatchesNix13=== PAUSE TestDumpPathMatchesNix14=== RUN TestDumpPathSingleFile15=== PAUSE TestDumpPathSingleFile16=== RUN TestDumpPathWriterError17=== PAUSE TestDumpPathWriterError18=== RUN TestEncodeNixBase3219=== PAUSE TestEncodeNixBase3220=== RUN TestEncodeNixBase32WithRealHash21=== PAUSE TestEncodeNixBase32WithRealHash22=== RUN TestConvertHashToNix3223=== PAUSE TestConvertHashToNix3224=== RUN TestGetStorePathHash25=== PAUSE TestGetStorePathHash26=== RUN TestPathInfoHashCompatibility27=== PAUSE TestPathInfoHashCompatibility28=== RUN TestParsePathInfoJSON29=== PAUSE TestParsePathInfoJSON30=== RUN TestParsePathInfoJSONMultiplePaths31=== PAUSE TestParsePathInfoJSONMultiplePaths32=== RUN TestPathInfoCACompatibility33=== PAUSE TestPathInfoCACompatibility34=== RUN TestRateLimiterFeedback35=== PAUSE TestRateLimiterFeedback36=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess37=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess38=== RUN TestResolveStorePath39=== PAUSE TestResolveStorePath40=== RUN TestDoWithRetry_BodyReplayedViaGetBody41=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody42=== RUN TestShellSplit43=== PAUSE TestShellSplit44=== RUN TestShellSplitErrors45=== PAUSE TestShellSplitErrors46=== RUN TestSetClientTLS47=== PAUSE TestSetClientTLS48=== RUN TestSetClientTLSDoesNotMutateDefaultTransport49=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport50=== RUN TestSetClientTLSErrors51=== PAUSE TestSetClientTLSErrors52=== RUN TestStaticToken53=== PAUSE TestStaticToken54=== RUN TestFileTokenReadsAndCaches55=== PAUSE TestFileTokenReadsAndCaches56=== RUN TestFileTokenMissing57=== PAUSE TestFileTokenMissing58=== RUN TestFileTokenEmpty59=== PAUSE TestFileTokenEmpty60=== RUN TestScriptTokenNoExpiryRerunsEveryCall61=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall62=== RUN TestScriptTokenCachesUntilRefresh63=== PAUSE TestScriptTokenCachesUntilRefresh64=== RUN TestScriptTokenEmptyToken65=== PAUSE TestScriptTokenEmptyToken66=== RUN TestScriptTokenBadJSON67=== PAUSE TestScriptTokenBadJSON68=== RUN TestScriptTokenScriptFails69=== PAUSE TestScriptTokenScriptFails70=== RUN TestScriptTokenEmptyCommand71=== PAUSE TestScriptTokenEmptyCommand72=== CONT TestDoServerRequestAttachesToken73=== CONT TestEncodeNixBase32WithRealHash74=== CONT TestResolveStorePath75--- PASS: TestEncodeNixBase32WithRealHash (0.00s)76=== CONT TestParsePathInfoJSON77=== CONT TestParsePathInfoJSONMultiplePaths78=== RUN TestParsePathInfoJSON/Nix_format79=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths80=== PAUSE TestParsePathInfoJSON/Nix_format81=== CONT TestPathInfoHashCompatibility82=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)83=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths84=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)85=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths86=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon87=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths88=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess89=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon90=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI91=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI92=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha51293=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha51294=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)95=== CONT TestDumpPathMatchesNix962026/08/27 09:41:05 WARN Rate limiter enabled after throttle name=server-test rate=597=== CONT TestPartSizeForNAR98=== RUN TestPartSizeForNAR/zero_stays_at_minimum99=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum100=== RUN TestPartSizeForNAR/small_stays_at_minimum101=== PAUSE TestPartSizeForNAR/small_stays_at_minimum102=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum103=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum104=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts105=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts106=== RUN TestPartSizeForNAR/1_TiB107=== PAUSE TestPartSizeForNAR/1_TiB108=== RUN TestPartSizeForNAR/5_TiB_S3_max_object109=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object110=== RUN TestPartSizeForNAR/capped_at_5_GiB111=== PAUSE TestPartSizeForNAR/capped_at_5_GiB112=== CONT TestPartSizeForNAR/zero_stays_at_minimum113=== CONT TestUploadMultipart_SupersededByPeer114=== CONT TestRateLimiterFeedback115=== CONT TestPathInfoCACompatibility116=== RUN TestUploadMultipart_SupersededByPeer/exists117=== PAUSE TestUploadMultipart_SupersededByPeer/exists118=== RUN TestUploadMultipart_SupersededByPeer/missing119=== PAUSE TestUploadMultipart_SupersededByPeer/missing120=== RUN TestRateLimiterFeedback/429_enables_limiter121=== PAUSE TestRateLimiterFeedback/429_enables_limiter122=== RUN TestRateLimiterFeedback/503_enables_limiter123=== PAUSE TestRateLimiterFeedback/503_enables_limiter124=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter125=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter126=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter127=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter128=== CONT TestFilterOversizedClosures129=== RUN TestFilterOversizedClosures/no_limit_keeps_everything130=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything131=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped132=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped133=== RUN TestFilterOversizedClosures/all_closures_skipped134=== PAUSE TestFilterOversizedClosures/all_closures_skipped135=== RUN TestPathInfoCACompatibility/null_ca_field136=== PAUSE TestPathInfoCACompatibility/null_ca_field137=== RUN TestPathInfoCACompatibility/old_string_format_-_text138=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text139=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive140=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive141=== RUN TestPathInfoCACompatibility/new_structured_format_-_text142=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text143=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method144=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method145=== CONT TestCaseHackSuffix146=== CONT TestPartSizeForNAR/5_TiB_S3_max_object147=== CONT TestPartSizeForNAR/1_TiB148=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts149=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum150=== CONT TestPartSizeForNAR/small_stays_at_minimum151=== CONT TestFileTokenMissing152=== CONT TestUploadMultipart_SupersededByPeer/exists153=== CONT TestPartSizeForNAR/capped_at_5_GiB154=== RUN TestParsePathInfoJSON/Lix_format155=== PAUSE TestParsePathInfoJSON/Lix_format156=== RUN TestParsePathInfoJSON/empty_input157=== CONT TestScriptTokenEmptyCommand158--- PASS: TestScriptTokenEmptyCommand (0.00s)159--- PASS: TestPartSizeForNAR (0.00s)160 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)161 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)162 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)163 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)164 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)165 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)166 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)167=== CONT TestScriptTokenBadJSON168--- PASS: TestResolveStorePath (0.00s)169=== CONT TestScriptTokenEmptyToken170=== CONT TestScriptTokenScriptFails171--- PASS: TestFileTokenMissing (0.00s)172=== CONT TestScriptTokenCachesUntilRefresh173=== CONT TestScriptTokenNoExpiryRerunsEveryCall174=== PAUSE TestParsePathInfoJSON/empty_input175=== RUN TestParsePathInfoJSON/whitespace_only176=== PAUSE TestParsePathInfoJSON/whitespace_only177=== RUN TestParsePathInfoJSON/invalid_JSON178=== PAUSE TestParsePathInfoJSON/invalid_JSON179=== CONT TestFileTokenEmpty180--- PASS: TestDoServerRequestAttachesToken (0.01s)181=== CONT TestRateLimiterFeedback/429_enables_limiter1822026/08/27 09:41:05 WARN Rate limiter enabled after throttle name=server-test rate=51832026/08/27 09:41:05 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:520571842026/08/27 09:41:05 WARN Rate limiter backed off name=server-test rate=5185=== CONT TestFilterOversizedClosures/no_limit_keeps_everything186=== CONT TestUploadMultipart_SupersededByPeer/missing187--- PASS: TestFileTokenEmpty (0.00s)188=== CONT TestSetClientTLSDoesNotMutateDefaultTransport189--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)190=== CONT TestFileTokenReadsAndCaches191--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)192 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)193 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)194=== CONT TestStaticToken195--- PASS: TestStaticToken (0.00s)196=== CONT TestSetClientTLSErrors197--- PASS: TestFileTokenReadsAndCaches (0.00s)198=== CONT TestDumpPathWriterError199--- PASS: TestScriptTokenScriptFails (0.01s)200=== CONT TestEncodeNixBase32201=== RUN TestEncodeNixBase32/test_string_hash202=== PAUSE TestEncodeNixBase32/test_string_hash203=== RUN TestEncodeNixBase32/empty_input204=== PAUSE TestEncodeNixBase32/empty_input205=== CONT TestShellSplitErrors206--- PASS: TestShellSplitErrors (0.00s)207=== CONT TestSetClientTLS208=== RUN TestSetClientTLSErrors/missing_cert_file209=== PAUSE TestSetClientTLSErrors/missing_cert_file210=== RUN TestSetClientTLSErrors/missing_key_file211=== PAUSE TestSetClientTLSErrors/missing_key_file212=== RUN TestSetClientTLSErrors/missing_ca_file213=== PAUSE TestSetClientTLSErrors/missing_ca_file214=== RUN TestSetClientTLSErrors/invalid_ca_file215=== PAUSE TestSetClientTLSErrors/invalid_ca_file216=== CONT TestRateLimiterFeedback/503_enables_limiter217=== RUN TestSetClientTLS/rejects_connection_without_client_cert218=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert219=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA220=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA221=== RUN TestSetClientTLS/preserves_debug_logging_transport222=== PAUSE TestSetClientTLS/preserves_debug_logging_transport223=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2242026/08/27 09:41:05 WARN Rate limiter enabled after throttle name=server-test rate=52252026/08/27 09:41:05 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:52062226=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2272026/08/27 09:41:05 WARN Rate limiter backed off name=server-test rate=5228=== CONT TestDumpPathSingleFile229--- PASS: TestRateLimiterFeedback (0.00s)230 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)231 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)232 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)233 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)234=== CONT TestFilterOversizedClosures/all_closures_skipped2352026/08/27 09:41:05 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=50236=== CONT TestShellSplit237--- PASS: TestShellSplit (0.00s)238=== CONT TestDoWithRetry_BodyReplayedViaGetBody2392026/08/27 09:41:05 WARN Rate limiter enabled after throttle name=server-test rate=52402026/08/27 09:41:05 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:520682412026/08/27 09:41:05 WARN Rate limiter backed off name=server-test rate=52422026/08/27 09:41:05 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:52068243--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)244=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2452026/08/27 09:41:05 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=2000246--- PASS: TestFilterOversizedClosures (0.00s)247 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)248 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)249 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)250=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths251=== CONT TestGetStorePathHash252=== RUN TestGetStorePathHash/valid_store_path253=== PAUSE TestGetStorePathHash/valid_store_path254=== RUN TestGetStorePathHash/basename_without_hyphen_should_error255=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error256=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error257=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error258=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error259=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error260=== CONT TestConvertHashToNix32261=== RUN TestConvertHashToNix32/SRI_format_to_Nix32262=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32263=== RUN TestConvertHashToNix32/already_Nix32_format264=== PAUSE TestConvertHashToNix32/already_Nix32_format265=== RUN TestConvertHashToNix32/invalid_format266=== PAUSE TestConvertHashToNix32/invalid_format267=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths268--- PASS: TestScriptTokenBadJSON (0.01s)269=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI270=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon271--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)272 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)273 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)274=== CONT TestPathInfoCACompatibility/null_ca_field275=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512276=== CONT TestPathInfoCACompatibility/new_structured_format_-_text277=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive278--- PASS: TestPathInfoHashCompatibility (0.00s)279 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)280 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)281 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)282 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)283=== CONT TestPathInfoCACompatibility/old_string_format_-_text284=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method285--- PASS: TestPathInfoCACompatibility (0.00s)286 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)287 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)288 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)289 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)290 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)291=== CONT TestParsePathInfoJSON/Nix_format292=== CONT TestParsePathInfoJSON/whitespace_only293=== CONT TestParsePathInfoJSON/invalid_JSON294=== CONT TestParsePathInfoJSON/empty_input295=== CONT TestEncodeNixBase32/test_string_hash296=== CONT TestParsePathInfoJSON/Lix_format297--- PASS: TestParsePathInfoJSON (0.00s)298 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)299 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)300 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)301 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)302 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)303=== CONT TestEncodeNixBase32/empty_input304--- PASS: TestEncodeNixBase32 (0.00s)305 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)306 --- PASS: TestEncodeNixBase32/empty_input (0.00s)307=== CONT TestSetClientTLSErrors/invalid_ca_file308=== CONT TestSetClientTLSErrors/missing_cert_file309=== CONT TestSetClientTLSErrors/missing_ca_file310=== CONT TestSetClientTLSErrors/missing_key_file311=== CONT TestSetClientTLS/rejects_connection_without_client_cert312=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA313--- PASS: TestSetClientTLSErrors (0.00s)314 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)315 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)316 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)317 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)318=== CONT TestSetClientTLS/preserves_debug_logging_transport319=== CONT TestGetStorePathHash/valid_store_path320=== CONT TestConvertHashToNix32/SRI_format_to_Nix32321=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error322--- PASS: TestScriptTokenEmptyToken (0.02s)323=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error324=== CONT TestGetStorePathHash/basename_without_hyphen_should_error325=== CONT TestConvertHashToNix32/invalid_format326--- PASS: TestGetStorePathHash (0.00s)327 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)328 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)329 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)330 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)331=== CONT TestConvertHashToNix32/already_Nix32_format332--- PASS: TestConvertHashToNix32 (0.00s)333 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)334 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)335 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)3362026/08/27 09:41:05 http: TLS handshake error from 127.0.0.1:52070: remote error: tls: bad certificate337--- PASS: TestSetClientTLS (0.00s)338 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)339 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)340 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)341--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)342--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)343--- PASS: TestDumpPathWriterError (0.07s)344--- PASS: TestCaseHackSuffix (0.21s)345--- PASS: TestDumpPathSingleFile (0.21s)346--- PASS: TestDumpPathMatchesNix (0.27s)347--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)348PASS349Running server tests...350The files belonging to this database system will be owned by user "_nixbld11".351This user must also own the server process.352353The database cluster will be initialized with locale "C".354The default database encoding has accordingly been set to "SQL_ASCII".355The default text search configuration will be set to "english".356357Data page checksums are enabled.358359creating directory /nix/var/nix/builds/nix-42860-2089741757/postgres4241994353/data ... ok360creating subdirectories ... ok361selecting dynamic shared memory implementation ... posix362selecting default "max_connections" ... 100363selecting default "shared_buffers" ... 128MB364selecting default time zone ... UTC365creating configuration files ... ok366running bootstrap script ... ok367performing post-bootstrap initialization ... ok368syncing data to disk ... ok369370initdb: warning: enabling "trust" authentication for local connections371initdb: 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.372373Success. You can now start the database server using:374375 pg_ctl -D /nix/var/nix/builds/nix-42860-2089741757/postgres4241994353/data -l logfile start376377/nix/var/nix/builds/nix-42860-2089741757/postgres4241994353:5432 - no response3782026-08-27 09:41:07.585 UTC [43439] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.5.0, compiled by clang version 21.1.8, 64-bit3792026-08-27 09:41:07.585 UTC [43439] LOG: listening on Unix socket "/nix/var/nix/builds/nix-42860-2089741757/postgres4241994353/.s.PGSQL.5432"3802026-08-27 09:41:07.591 UTC [43446] LOG: database system was shut down at 2026-08-27 09:41:07 UTC3812026-08-27 09:41:07.592 UTC [43439] LOG: database system is ready to accept connections382/nix/var/nix/builds/nix-42860-2089741757/postgres4241994353:5432 - accepting connections383=== RUN TestService_AuthMiddleware384=== PAUSE TestService_AuthMiddleware385=== RUN TestService_AuthMiddleware_MTLSProxyHeader386=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader387=== RUN TestService_AuthMiddleware_MTLSBoundSubjects388=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects389=== RUN TestService_ReadAuthMiddleware390=== PAUSE TestService_ReadAuthMiddleware391=== RUN TestService_AuthMiddleware_OIDC392=== PAUSE TestService_AuthMiddleware_OIDC393=== RUN TestCacheConfigHandler394=== PAUSE TestCacheConfigHandler395=== RUN TestCacheStatsHandler396=== PAUSE TestCacheStatsHandler397=== RUN TestClientCADerivations398=== PAUSE TestClientCADerivations399=== RUN TestClientErrorHandling400=== PAUSE TestClientErrorHandling401=== RUN TestClientIntegration402=== PAUSE TestClientIntegration403=== RUN TestClientMultipleUploads404=== PAUSE TestClientMultipleUploads405=== RUN TestClientWithDependencies406=== PAUSE TestClientWithDependencies407=== RUN TestPinProtectsFromGC408=== PAUSE TestPinProtectsFromGC409=== RUN TestGCAdvisoryLockBlocksConcurrentRun4102026-08-27 09:41:07.994 UTC [43524] ERROR: relation "goose_db_version" does not exist at character 364112026-08-27 09:41:07.994 UTC [43524] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4122026/08/27 09:41:08 OK 20241026095416_initial_model.sql (6.53ms)4132026/08/27 09:41:08 OK 20251210153512_drop_unused_gin_index.sql (914.04µs)4142026/08/27 09:41:08 OK 20251218171726_add_pins.sql (2.26ms)4152026/08/27 09:41:08 OK 20260628120000_add_object_size_and_stats.sql (2.32ms)4162026/08/27 09:41:08 goose: successfully migrated database to version: 202606281200004172026/08/27 09:41:08 OK 1_commit_pending_closure.sql (1.97ms)4182026/08/27 09:41:08 OK 2_object_stats_trigger.sql (806.29µs)4192026/08/27 09:41:08 goose: up to current file version: 2420--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.29s)421=== RUN TestGCBugBareHashReferences422=== PAUSE TestGCBugBareHashReferences423=== RUN TestGCMetrics424=== PAUSE TestGCMetrics425=== RUN TestGCTaskStore_StartNew426=== PAUSE TestGCTaskStore_StartNew427=== RUN TestGCTaskStore_DeduplicateSameParams428=== PAUSE TestGCTaskStore_DeduplicateSameParams429=== RUN TestGCTaskStore_ConflictDifferentParams430=== PAUSE TestGCTaskStore_ConflictDifferentParams431=== RUN TestGCTaskStore_GetEmpty432=== PAUSE TestGCTaskStore_GetEmpty433=== RUN TestGCTaskStore_GetReturnsLatest434=== PAUSE TestGCTaskStore_GetReturnsLatest435=== RUN TestGCTaskStore_CompletedAllowsNewTask436=== PAUSE TestGCTaskStore_CompletedAllowsNewTask437=== RUN TestGCTaskStore_PhaseUpdates438=== PAUSE TestGCTaskStore_PhaseUpdates439=== RUN TestGCTaskStore_Fail440=== PAUSE TestGCTaskStore_Fail441=== RUN TestGracefulShutdownDrainsInflight442=== PAUSE TestGracefulShutdownDrainsInflight443=== RUN TestService_healthCheckHandler444=== PAUSE TestService_healthCheckHandler445=== RUN TestGenerateLandingPage446=== PAUSE TestGenerateLandingPage447=== RUN TestCacheConfigHandlerMaxNarSize448=== PAUSE TestCacheConfigHandlerMaxNarSize449=== RUN TestCreatePendingClosureRejectsOversizedNAR450=== PAUSE TestCreatePendingClosureRejectsOversizedNAR451=== RUN TestNARDeduplicationMetadataUploadBug452=== PAUSE TestNARDeduplicationMetadataUploadBug453=== RUN TestMetricsInventory454=== PAUSE TestMetricsInventory455=== RUN TestService_NativeMTLS456=== PAUSE TestService_NativeMTLS457=== RUN TestServerTLSConfig458=== PAUSE TestServerTLSConfig459=== RUN TestMultipartCleanup460=== PAUSE TestMultipartCleanup461=== RUN TestObjectStatsTrigger462=== PAUSE TestObjectStatsTrigger463=== RUN TestOrphanedObjectsGC464=== PAUSE TestOrphanedObjectsGC465=== RUN TestOrphanedObjectsGCStressTest466=== PAUSE TestOrphanedObjectsGCStressTest467=== RUN TestResurrectedObjectNotDeleted468=== PAUSE TestResurrectedObjectNotDeleted469=== RUN TestParseSingleRange470=== PAUSE TestParseSingleRange471=== RUN TestIsValidCachePath472=== PAUSE TestIsValidCachePath473=== RUN TestReadProxyNarinfo474=== PAUSE TestReadProxyNarinfo475=== RUN TestReadProxyNarinfoAlreadyDecompressed476=== PAUSE TestReadProxyNarinfoAlreadyDecompressed477=== RUN TestReadProxyNarStreaming478=== PAUSE TestReadProxyNarStreaming479=== RUN TestReadProxy404480=== PAUSE TestReadProxy404481=== RUN TestReadProxyInvalidPath482=== PAUSE TestReadProxyInvalidPath483=== RUN TestReadProxyHead484=== PAUSE TestReadProxyHead485=== RUN TestReadProxyConditionalGet486=== PAUSE TestReadProxyConditionalGet487=== RUN TestReadProxyRootRedirectsToIndexHTML488=== PAUSE TestReadProxyRootRedirectsToIndexHTML489=== RUN TestReadProxyDisabled490=== PAUSE TestReadProxyDisabled491=== RUN TestReadProxyRangeRequest492=== PAUSE TestReadProxyRangeRequest493=== RUN TestRedundantMultipartUpload494=== PAUSE TestRedundantMultipartUpload495=== RUN TestCompleteMultipartUpload_ErrorButObjectExists496=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists497=== RUN TestCompletedNarNotReofferedAcrossClosures498=== PAUSE TestCompletedNarNotReofferedAcrossClosures499=== RUN TestPresignedUploadRegisteredBeforeCommit500=== PAUSE TestPresignedUploadRegisteredBeforeCommit501=== RUN TestService_Rustfstest502=== PAUSE TestService_Rustfstest503=== RUN TestParseSize504=== PAUSE TestParseSize505=== RUN TestSkippedUploadsHandler506=== PAUSE TestSkippedUploadsHandler507=== RUN TestSystemdListenerNotActivated508--- PASS: TestSystemdListenerNotActivated (0.00s)509=== RUN TestWatchdogBeatsWhenHealthy510--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)511=== RUN TestWatchdogSkipsWhenUnhealthy5122026/08/27 09:41:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5132026/08/27 09:41:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5142026/08/27 09:41:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5152026/08/27 09:41:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5162026/08/27 09:41:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5172026/08/27 09:41:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5182026/08/27 09:41:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5192026/08/27 09:41:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5202026/08/27 09:41:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5212026/08/27 09:41:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"522--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)523=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle524=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle525=== RUN TestProxyWriteTimeout526=== PAUSE TestProxyWriteTimeout527=== RUN TestIsValidUploadKey528=== PAUSE TestIsValidUploadKey529=== RUN TestUploadHandlersRejectInvalidKeys530=== PAUSE TestUploadHandlersRejectInvalidKeys531=== RUN TestUploadHandlersRejectOversizedBody532=== PAUSE TestUploadHandlersRejectOversizedBody533=== RUN TestService_cleanupPendingClosuresHandler534=== PAUSE TestService_cleanupPendingClosuresHandler535=== RUN TestService_createPendingClosureHandler536=== PAUSE TestService_createPendingClosureHandler537=== RUN TestService_verifyS3Integrity538=== PAUSE TestService_verifyS3Integrity539=== RUN TestCompleteMultipartUnregistered540=== PAUSE TestCompleteMultipartUnregistered541=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT542=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT543=== CONT TestService_AuthMiddleware544=== CONT TestObjectStatsTrigger545=== CONT TestCompleteMultipartUpload_ErrorButObjectExists546=== CONT TestGCTaskStore_ConflictDifferentParams547--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)548=== CONT TestMultipartCleanup549=== CONT TestIsValidUploadKey550=== RUN TestIsValidUploadKey/narinfo551=== CONT TestGCTaskStore_DeduplicateSameParams552--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)553=== CONT TestPinProtectsFromGC554=== CONT TestGCTaskStore_StartNew555--- PASS: TestGCTaskStore_StartNew (0.00s)556=== CONT TestClientWithDependencies557=== CONT TestGCMetrics558=== CONT TestGCBugBareHashReferences559=== CONT TestService_createPendingClosureHandler560=== PAUSE TestIsValidUploadKey/narinfo561=== RUN TestIsValidUploadKey/nar_zst562=== PAUSE TestIsValidUploadKey/nar_zst563=== RUN TestIsValidUploadKey/nar_xz564=== PAUSE TestIsValidUploadKey/nar_xz565=== RUN TestIsValidUploadKey/nar_plain566=== PAUSE TestIsValidUploadKey/nar_plain567=== RUN TestIsValidUploadKey/listing568=== PAUSE TestIsValidUploadKey/listing569=== RUN TestIsValidUploadKey/build_log570=== PAUSE TestIsValidUploadKey/build_log571=== RUN TestIsValidUploadKey/build_log_home-manager_file572=== PAUSE TestIsValidUploadKey/build_log_home-manager_file573=== RUN TestIsValidUploadKey/build_log_plus_in_name574=== PAUSE TestIsValidUploadKey/build_log_plus_in_name575=== RUN TestIsValidUploadKey/build_log_question_mark576=== PAUSE TestIsValidUploadKey/build_log_question_mark577=== RUN TestIsValidUploadKey/build_log_equals578=== PAUSE TestIsValidUploadKey/build_log_equals579=== RUN TestIsValidUploadKey/realisation580=== PAUSE TestIsValidUploadKey/realisation581=== RUN TestIsValidUploadKey/realisation_plus_in_output582=== PAUSE TestIsValidUploadKey/realisation_plus_in_output583=== RUN TestIsValidUploadKey/nix-cache-info584=== PAUSE TestIsValidUploadKey/nix-cache-info585=== RUN TestIsValidUploadKey/index.html586=== PAUSE TestIsValidUploadKey/index.html587=== RUN TestIsValidUploadKey/narinfo_key,_nar_type588=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type589=== RUN TestIsValidUploadKey/nar_key,_narinfo_type590=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type591=== RUN TestIsValidUploadKey/listing_key,_narinfo_type592=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type593=== RUN TestIsValidUploadKey/traversal594=== PAUSE TestIsValidUploadKey/traversal595=== RUN TestIsValidUploadKey/traversal_nar596=== PAUSE TestIsValidUploadKey/traversal_nar597=== RUN TestIsValidUploadKey/absolute598=== PAUSE TestIsValidUploadKey/absolute599=== RUN TestIsValidUploadKey/empty_key600=== PAUSE TestIsValidUploadKey/empty_key601=== RUN TestIsValidUploadKey/unknown_type602=== PAUSE TestIsValidUploadKey/unknown_type603=== CONT TestClientMultipleUploads6042026-08-27 09:41:08.535 UTC [43557] ERROR: relation "goose_db_version" does not exist at character 366052026-08-27 09:41:08.535 UTC [43557] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6062026/08/27 09:41:08 OK 20241026095416_initial_model.sql (37.66ms)6072026/08/27 09:41:08 OK 20251210153512_drop_unused_gin_index.sql (1.44ms)6082026/08/27 09:41:08 OK 20251218171726_add_pins.sql (5.79ms)6092026-08-27 09:41:08.616 UTC [43558] ERROR: relation "goose_db_version" does not exist at character 366102026-08-27 09:41:08.616 UTC [43558] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6112026/08/27 09:41:08 OK 20260628120000_add_object_size_and_stats.sql (3.16ms)6122026/08/27 09:41:08 goose: successfully migrated database to version: 202606281200006132026/08/27 09:41:08 OK 1_commit_pending_closure.sql (3.42ms)6142026/08/27 09:41:08 OK 2_object_stats_trigger.sql (1.13ms)6152026/08/27 09:41:08 goose: up to current file version: 26162026-08-27 09:41:08.690 UTC [43559] ERROR: relation "goose_db_version" does not exist at character 366172026-08-27 09:41:08.690 UTC [43559] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6182026-08-27 09:41:08.694 UTC [43560] ERROR: relation "goose_db_version" does not exist at character 366192026-08-27 09:41:08.694 UTC [43560] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6202026-08-27 09:41:08.698 UTC [43563] ERROR: relation "goose_db_version" does not exist at character 366212026-08-27 09:41:08.698 UTC [43563] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6222026/08/27 09:41:08 OK 20241026095416_initial_model.sql (73.79ms)6232026/08/27 09:41:08 OK 20251210153512_drop_unused_gin_index.sql (11.37ms)6242026/08/27 09:41:08 OK 20251218171726_add_pins.sql (15.79ms)6252026-08-27 09:41:08.734 UTC [43564] ERROR: relation "goose_db_version" does not exist at character 366262026-08-27 09:41:08.734 UTC [43564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6272026-08-27 09:41:08.734 UTC [43566] ERROR: relation "goose_db_version" does not exist at character 366282026-08-27 09:41:08.734 UTC [43566] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6292026-08-27 09:41:08.734 UTC [43565] ERROR: relation "goose_db_version" does not exist at character 366302026-08-27 09:41:08.734 UTC [43565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6312026/08/27 09:41:08 OK 20260628120000_add_object_size_and_stats.sql (11.8ms)6322026/08/27 09:41:08 goose: successfully migrated database to version: 202606281200006332026/08/27 09:41:08 OK 20241026095416_initial_model.sql (36.82ms)6342026/08/27 09:41:08 OK 1_commit_pending_closure.sql (2.17ms)6352026/08/27 09:41:08 OK 2_object_stats_trigger.sql (1.01ms)6362026/08/27 09:41:08 goose: up to current file version: 26372026/08/27 09:41:08 OK 20251210153512_drop_unused_gin_index.sql (5.09ms)6382026/08/27 09:41:08 OK 20251218171726_add_pins.sql (26.9ms)6392026-08-27 09:41:08.773 UTC [43569] ERROR: relation "goose_db_version" does not exist at character 366402026-08-27 09:41:08.773 UTC [43569] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6412026-08-27 09:41:08.778 UTC [43571] ERROR: relation "goose_db_version" does not exist at character 366422026-08-27 09:41:08.778 UTC [43571] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6432026/08/27 09:41:08 INFO Created nix-cache-info in bucket bucket=bucket26442026/08/27 09:41:08 OK 20260628120000_add_object_size_and_stats.sql (35.61ms)6452026/08/27 09:41:08 goose: successfully migrated database to version: 202606281200006462026/08/27 09:41:08 OK 20241026095416_initial_model.sql (94.27ms)6472026/08/27 09:41:08 OK 1_commit_pending_closure.sql (15.37ms)6482026/08/27 09:41:08 OK 2_object_stats_trigger.sql (501.13µs)6492026/08/27 09:41:08 goose: up to current file version: 26502026/08/27 09:41:08 OK 20241026095416_initial_model.sql (103.41ms)6512026/08/27 09:41:08 OK 20251210153512_drop_unused_gin_index.sql (19.38ms)6522026/08/27 09:41:08 OK 20241026095416_initial_model.sql (77.19ms)6532026/08/27 09:41:08 OK 20251210153512_drop_unused_gin_index.sql (12.6ms)6542026/08/27 09:41:08 OK 20251210153512_drop_unused_gin_index.sql (9.52ms)6552026/08/27 09:41:08 OK 20251218171726_add_pins.sql (9.94ms)6562026/08/27 09:41:08 OK 20251218171726_add_pins.sql (37.63ms)6572026/08/27 09:41:08 OK 20251218171726_add_pins.sql (35.86ms)6582026/08/27 09:41:08 OK 20260628120000_add_object_size_and_stats.sql (50.58ms)6592026/08/27 09:41:08 goose: successfully migrated database to version: 202606281200006602026/08/27 09:41:08 OK 20260628120000_add_object_size_and_stats.sql (40.14ms)6612026/08/27 09:41:08 goose: successfully migrated database to version: 202606281200006622026/08/27 09:41:08 OK 20241026095416_initial_model.sql (154.69ms)6632026/08/27 09:41:08 OK 1_commit_pending_closure.sql (15.86ms)6642026/08/27 09:41:08 OK 2_object_stats_trigger.sql (413.25µs)6652026/08/27 09:41:08 goose: up to current file version: 26662026/08/27 09:41:08 OK 1_commit_pending_closure.sql (8.16ms)6672026/08/27 09:41:08 OK 2_object_stats_trigger.sql (549.33µs)6682026/08/27 09:41:08 goose: up to current file version: 26692026/08/27 09:41:08 OK 20251210153512_drop_unused_gin_index.sql (20.69ms)6702026/08/27 09:41:08 OK 20260628120000_add_object_size_and_stats.sql (55.39ms)6712026/08/27 09:41:08 goose: successfully migrated database to version: 202606281200006722026/08/27 09:41:08 OK 20241026095416_initial_model.sql (114.96ms)6732026/08/27 09:41:08 OK 1_commit_pending_closure.sql (4.03ms)6742026/08/27 09:41:08 OK 2_object_stats_trigger.sql (623.96µs)6752026/08/27 09:41:08 goose: up to current file version: 26762026/08/27 09:41:08 INFO Created nix-cache-info in bucket bucket=bucket36772026/08/27 09:41:08 OK 20241026095416_initial_model.sql (189.07ms)6782026/08/27 09:41:08 OK 20251210153512_drop_unused_gin_index.sql (15.25ms)6792026/08/27 09:41:08 OK 20251210153512_drop_unused_gin_index.sql (25.25ms)6802026/08/27 09:41:08 OK 20251218171726_add_pins.sql (43.95ms)6812026/08/27 09:41:09 OK 20251218171726_add_pins.sql (48.16ms)6822026/08/27 09:41:09 OK 20251218171726_add_pins.sql (54.02ms)6832026/08/27 09:41:09 OK 20260628120000_add_object_size_and_stats.sql (40.33ms)6842026/08/27 09:41:09 goose: successfully migrated database to version: 202606281200006852026/08/27 09:41:09 OK 20260628120000_add_object_size_and_stats.sql (7.77ms)6862026/08/27 09:41:09 goose: successfully migrated database to version: 202606281200006872026/08/27 09:41:09 OK 1_commit_pending_closure.sql (10.87ms)6882026/08/27 09:41:09 OK 1_commit_pending_closure.sql (11.52ms)6892026/08/27 09:41:09 OK 2_object_stats_trigger.sql (505.17µs)6902026/08/27 09:41:09 goose: up to current file version: 26912026/08/27 09:41:09 OK 2_object_stats_trigger.sql (543.25µs)6922026/08/27 09:41:09 goose: up to current file version: 26932026/08/27 09:41:09 OK 20260628120000_add_object_size_and_stats.sql (48.95ms)6942026/08/27 09:41:09 goose: successfully migrated database to version: 202606281200006952026/08/27 09:41:09 OK 20241026095416_initial_model.sql (221.34ms)6962026/08/27 09:41:09 OK 1_commit_pending_closure.sql (8.85ms)6972026/08/27 09:41:09 OK 2_object_stats_trigger.sql (568.5µs)6982026/08/27 09:41:09 goose: up to current file version: 26992026/08/27 09:41:09 OK 20251210153512_drop_unused_gin_index.sql (15.16ms)7002026/08/27 09:41:09 INFO Aborted multipart uploads count=0701 client_integration_test.go:338: Created store path 0: /nix/var/nix/builds/nix-42860-2089741757/TestClientMultipleUploads320388571/001/store/b4r3869xz68v69na23bgcx42l4y4a5i2-test-file-0.txt7022026/08/27 09:41:09 WARN Force mode enabled - objects will be deleted immediately without grace period7032026/08/27 09:41:09 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=07042026/08/27 09:41:09 INFO Vacuumed table table=pending_closures7052026/08/27 09:41:09 INFO Vacuumed table table=pending_objects7062026/08/27 09:41:09 INFO Vacuumed table table=multipart_uploads7072026/08/27 09:41:09 INFO Vacuumed table table=closures7082026/08/27 09:41:09 INFO Vacuumed table table=objects709--- PASS: TestGCMetrics (0.77s)710=== CONT TestClientIntegration7112026/08/27 09:41:09 OK 20251218171726_add_pins.sql (41.6ms)7122026/08/27 09:41:09 INFO Received uploads request method=POST path=/api/pending_closures7132026/08/27 09:41:09 OK 20260628120000_add_object_size_and_stats.sql (33.39ms)7142026/08/27 09:41:09 goose: successfully migrated database to version: 202606281200007152026/08/27 09:41:09 OK 1_commit_pending_closure.sql (19.67ms)7162026/08/27 09:41:09 OK 2_object_stats_trigger.sql (600.75µs)7172026/08/27 09:41:09 goose: up to current file version: 2718=== NAME TestClientMultipleUploads719 client_integration_test.go:338: Created store path 1: /nix/var/nix/builds/nix-42860-2089741757/TestClientMultipleUploads320388571/001/store/d8x2wb5xsq1zg5rndg9nhq0rri61qc3c-test-file-1.txt720--- PASS: TestObjectStatsTrigger (1.08s)721=== CONT TestClientErrorHandling722=== RUN TestClientErrorHandling/InvalidStorePath723=== PAUSE TestClientErrorHandling/InvalidStorePath724=== RUN TestClientErrorHandling/InvalidAuthToken725=== PAUSE TestClientErrorHandling/InvalidAuthToken726=== RUN TestClientErrorHandling/ServerNotAvailable727=== PAUSE TestClientErrorHandling/ServerNotAvailable728=== CONT TestClientCADerivations7292026/08/27 09:41:09 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"730--- PASS: TestService_AuthMiddleware (1.11s)731=== CONT TestCacheStatsHandler732=== NAME TestClientMultipleUploads733 client_integration_test.go:338: Created store path 2: /nix/var/nix/builds/nix-42860-2089741757/TestClientMultipleUploads320388571/001/store/0c3l5mj03hi2vir2j8kndgj7r9aca646-test-file-2.txt734--- PASS: TestGCBugBareHashReferences (1.19s)735=== CONT TestCacheConfigHandler736=== RUN TestCacheConfigHandler/full_config,_no_issuer737=== PAUSE TestCacheConfigHandler/full_config,_no_issuer738=== RUN TestCacheConfigHandler/no_cache_url_configured739=== PAUSE TestCacheConfigHandler/no_cache_url_configured740=== RUN TestCacheConfigHandler/no_signing_keys741=== PAUSE TestCacheConfigHandler/no_signing_keys742=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator743=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator744=== CONT TestService_AuthMiddleware_OIDC745=== NAME TestPinProtectsFromGC746 client_integration_test.go:646: Pinned store path: /nix/var/nix/builds/nix-42860-2089741757/TestPinProtectsFromGC3365146693/001/store/mcfkhkhdcjpj5bv9bfmq56v9ghbr0aym-pinned-file.txt747 client_integration_test.go:647: Unpinned store path: /nix/var/nix/builds/nix-42860-2089741757/TestPinProtectsFromGC3365146693/001/store/1w0zpn5rk6xy7dws2nmgfb5p8mw4i1iz-unpinned-file.txt7482026/08/27 09:41:09 INFO Received uploads request method=POST path=/api/pending_closures7492026/08/27 09:41:09 INFO Received uploads request method=POST path=/api/pending_closures7502026/08/27 09:41:09 INFO Received uploads request method=POST path=/api/pending_closures7512026/08/27 09:41:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7522026/08/27 09:41:09 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjNmYmQxYTgtZmNhNC00NDYwLWI0MTctODBlMTUxZDk5NWUyLmYzMDZmNWU4LTk1MzEtNDBiYi05MmRiLTc1YzQ2ODFlZDJjN3gxNzg3ODIzNjY5MjAxODIxMDAw7532026/08/27 09:41:09 INFO OIDC provider initialized name=test7542026/08/27 09:41:09 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjNmYmQxYTgtZmNhNC00NDYwLWI0MTctODBlMTUxZDk5NWUyLmYzMDZmNWU4LTk1MzEtNDBiYi05MmRiLTc1YzQ2ODFlZDJjN3gxNzg3ODIzNjY5MjAxODIxMDAw parts=1755--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.22s)756=== CONT TestService_ReadAuthMiddleware7572026/08/27 09:41:09 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"7582026/08/27 09:41:09 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"7592026/08/27 09:41:09 INFO Created nix-cache-info in bucket bucket=bucket77602026/08/27 09:41:09 INFO Received uploads request method=POST path=/api/pending_closures7612026/08/27 09:41:09 INFO Received uploads request method=POST path=/api/pending_closures7622026/08/27 09:41:09 INFO Received uploads request method=POST path=/api/pending_closures7632026/08/27 09:41:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7642026/08/27 09:41:09 INFO Uploading mcfkhkhdcjpj5bv9bfmq56v9ghbr0aym-pinned-file.txt (128B)7652026/08/27 09:41:09 INFO Received uploads request method=POST path=/api/pending_closures7662026/08/27 09:41:09 INFO Received uploads request method=POST path=/api/pending_closures7672026/08/27 09:41:09 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)7682026/08/27 09:41:09 INFO Uploading b4r3869xz68v69na23bgcx42l4y4a5i2-test-file-0.txt (160B)7692026/08/27 09:41:09 INFO Uploading d8x2wb5xsq1zg5rndg9nhq0rri61qc3c-test-file-1.txt (160B)7702026/08/27 09:41:09 INFO Uploading 0c3l5mj03hi2vir2j8kndgj7r9aca646-test-file-2.txt (160B)7712026/08/27 09:41:09 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"7722026/08/27 09:41:09 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"7732026/08/27 09:41:09 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"7742026/08/27 09:41:09 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"7752026/08/27 09:41:09 WARN Failed to register uploaded object key=mcfkhkhdcjpj5bv9bfmq56v9ghbr0aym.ls error="server returned 404: 404 page not found\n"7762026/08/27 09:41:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign7772026/08/27 09:41:09 INFO Signed narinfos id=1 count=17782026/08/27 09:41:09 INFO Uploading 1 narinfos7792026/08/27 09:41:09 INFO Received cleanup request method=DELETE path=/api/pending_closures7802026/08/27 09:41:09 INFO Aborted multipart uploads count=17812026/08/27 09:41:09 WARN Failed to register uploaded object key=b4r3869xz68v69na23bgcx42l4y4a5i2.ls error="server returned 404: 404 page not found\n"7822026/08/27 09:41:09 WARN Failed to register uploaded object key=0c3l5mj03hi2vir2j8kndgj7r9aca646.ls error="server returned 404: 404 page not found\n"7832026/08/27 09:41:09 WARN Failed to register uploaded object key=d8x2wb5xsq1zg5rndg9nhq0rri61qc3c.ls error="server returned 404: 404 page not found\n"7842026/08/27 09:41:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign7852026/08/27 09:41:09 WARN Failed to register uploaded object key=mcfkhkhdcjpj5bv9bfmq56v9ghbr0aym.narinfo error="server returned 404: 404 page not found\n"7862026/08/27 09:41:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7872026/08/27 09:41:09 INFO Signed narinfos id=3 count=17882026/08/27 09:41:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign7892026/08/27 09:41:09 INFO Signed narinfos id=1 count=17902026/08/27 09:41:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign7912026/08/27 09:41:09 INFO Signed narinfos id=2 count=17922026/08/27 09:41:09 INFO Uploading 3 narinfos793--- PASS: TestMultipartCleanup (1.70s)794=== CONT TestService_AuthMiddleware_MTLSBoundSubjects7952026/08/27 09:41:10 INFO Completed upload id=17962026/08/27 09:41:10 INFO Upload complete. (432ms)7972026/08/27 09:41:10 WARN Failed to register uploaded object key=b4r3869xz68v69na23bgcx42l4y4a5i2.narinfo error="server returned 404: 404 page not found\n"7982026/08/27 09:41:10 WARN Failed to register uploaded object key=0c3l5mj03hi2vir2j8kndgj7r9aca646.narinfo error="server returned 404: 404 page not found\n"7992026/08/27 09:41:10 WARN Failed to register uploaded object key=d8x2wb5xsq1zg5rndg9nhq0rri61qc3c.narinfo error="server returned 404: 404 page not found\n"8002026/08/27 09:41:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8012026/08/27 09:41:10 INFO Completed upload id=18022026/08/27 09:41:10 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete8032026/08/27 09:41:10 INFO Completed upload id=28042026/08/27 09:41:10 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete8052026/08/27 09:41:10 INFO Completed upload id=38062026/08/27 09:41:10 INFO Upload complete. (548ms)807=== NAME TestClientMultipleUploads808 client_integration_test.go:349: Uploaded 3 paths in 619.714542ms8092026/08/27 09:41:10 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"810--- PASS: TestClientMultipleUploads (1.86s)811=== CONT TestService_AuthMiddleware_MTLSProxyHeader8122026/08/27 09:41:10 INFO Received uploads request method=POST path=/api/pending_closures8132026/08/27 09:41:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8142026/08/27 09:41:10 INFO Uploading 1w0zpn5rk6xy7dws2nmgfb5p8mw4i1iz-unpinned-file.txt (128B)8152026/08/27 09:41:10 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"8162026/08/27 09:41:10 WARN Failed to register uploaded object key=1w0zpn5rk6xy7dws2nmgfb5p8mw4i1iz.ls error="server returned 404: 404 page not found\n"8172026/08/27 09:41:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign8182026/08/27 09:41:10 INFO Signed narinfos id=2 count=18192026/08/27 09:41:10 INFO Uploading 1 narinfos8202026/08/27 09:41:10 WARN Failed to register uploaded object key=1w0zpn5rk6xy7dws2nmgfb5p8mw4i1iz.narinfo error="server returned 404: 404 page not found\n"8212026/08/27 09:41:10 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete8222026/08/27 09:41:10 INFO Completed upload id=28232026/08/27 09:41:10 INFO Upload complete. (340ms)824=== NAME TestClientWithDependencies825 client_integration_test.go:593: Built derivation: /nix/var/nix/builds/nix-42860-2089741757/TestClientWithDependencies1536929064/001/store/iwg89fskp0kjr3x9zi7pykwzh7ivj4i8-test-script8262026-08-27 09:41:10.499 UTC [43633] ERROR: relation "goose_db_version" does not exist at character 368272026-08-27 09:41:10.499 UTC [43633] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8282026/08/27 09:41:10 INFO Received create pin request method=POST path=/api/pins/myapp829 client_integration_test.go:595: Found 1 dependencies (including self)8302026/08/27 09:41:10 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-42860-2089741757/TestPinProtectsFromGC3365146693/001/store/mcfkhkhdcjpj5bv9bfmq56v9ghbr0aym-pinned-file.txt narinfo_key=mcfkhkhdcjpj5bv9bfmq56v9ghbr0aym.narinfo8312026/08/27 09:41:10 INFO Starting cleanup of old closures method=DELETE path=/api/closures8322026/08/27 09:41:10 INFO Garbage collection started8332026/08/27 09:41:10 INFO Aborted multipart uploads count=08342026/08/27 09:41:10 WARN Force mode enabled - objects will be deleted immediately without grace period8352026-08-27 09:41:10.675 UTC [43641] ERROR: relation "goose_db_version" does not exist at character 368362026-08-27 09:41:10.675 UTC [43641] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8372026-08-27 09:41:10.676 UTC [43640] ERROR: relation "goose_db_version" does not exist at character 368382026-08-27 09:41:10.676 UTC [43640] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8392026/08/27 09:41:10 OK 20241026095416_initial_model.sql (119.78ms)8402026/08/27 09:41:10 OK 20251210153512_drop_unused_gin_index.sql (11.75ms)8412026/08/27 09:41:10 OK 20251218171726_add_pins.sql (32.47ms)8422026/08/27 09:41:10 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8432026/08/27 09:41:10 INFO Received uploads request method=POST path=/api/pending_closures8442026-08-27 09:41:10.744 UTC [43644] ERROR: relation "goose_db_version" does not exist at character 368452026-08-27 09:41:10.744 UTC [43644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8462026-08-27 09:41:10.750 UTC [43643] ERROR: relation "goose_db_version" does not exist at character 368472026-08-27 09:41:10.750 UTC [43643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8482026/08/27 09:41:10 OK 20260628120000_add_object_size_and_stats.sql (42.34ms)8492026/08/27 09:41:10 goose: successfully migrated database to version: 202606281200008502026/08/27 09:41:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8512026/08/27 09:41:10 INFO Uploading iwg89fskp0kjr3x9zi7pykwzh7ivj4i8-test-script (136B)8522026/08/27 09:41:10 OK 1_commit_pending_closure.sql (7.32ms)8532026/08/27 09:41:10 OK 2_object_stats_trigger.sql (1.2ms)8542026/08/27 09:41:10 goose: up to current file version: 28552026/08/27 09:41:10 WARN Failed to register uploaded object key=log/1gacxz2zc4hpazgl6v9wg43qj5dynk4a-test-script.drv error="server returned 404: 404 page not found\n"8562026/08/27 09:41:10 OK 20241026095416_initial_model.sql (110.56ms)8572026/08/27 09:41:10 OK 20251210153512_drop_unused_gin_index.sql (12.5ms)8582026/08/27 09:41:10 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"8592026/08/27 09:41:10 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=08602026/08/27 09:41:10 INFO Vacuumed table table=pending_closures8612026/08/27 09:41:10 OK 20251218171726_add_pins.sql (44.15ms)8622026/08/27 09:41:10 INFO Vacuumed table table=pending_objects8632026/08/27 09:41:10 INFO Vacuumed table table=multipart_uploads8642026/08/27 09:41:10 OK 20241026095416_initial_model.sql (189.6ms)8652026/08/27 09:41:10 WARN Failed to register uploaded object key=iwg89fskp0kjr3x9zi7pykwzh7ivj4i8.ls error="server returned 404: 404 page not found\n"8662026/08/27 09:41:10 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8672026/08/27 09:41:10 INFO Signed narinfos id=1 count=18682026/08/27 09:41:10 INFO Uploading 1 narinfos8692026/08/27 09:41:10 OK 20251210153512_drop_unused_gin_index.sql (6.8ms)8702026/08/27 09:41:10 INFO Vacuumed table table=closures8712026/08/27 09:41:10 OK 20260628120000_add_object_size_and_stats.sql (40.25ms)8722026/08/27 09:41:10 goose: successfully migrated database to version: 202606281200008732026/08/27 09:41:10 OK 1_commit_pending_closure.sql (18.76ms)8742026/08/27 09:41:10 OK 2_object_stats_trigger.sql (954.67µs)8752026/08/27 09:41:10 goose: up to current file version: 28762026/08/27 09:41:10 INFO Vacuumed table table=objects8772026/08/27 09:41:10 WARN Failed to register uploaded object key=iwg89fskp0kjr3x9zi7pykwzh7ivj4i8.narinfo error="server returned 404: 404 page not found\n"8782026/08/27 09:41:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8792026/08/27 09:41:10 OK 20251218171726_add_pins.sql (54.76ms)8802026/08/27 09:41:11 OK 20241026095416_initial_model.sql (166.25ms)8812026/08/27 09:41:11 INFO Completed upload id=18822026/08/27 09:41:11 OK 20251210153512_drop_unused_gin_index.sql (15.16ms)8832026/08/27 09:41:11 INFO Upload complete. (375ms)884 client_integration_test.go:597: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-42860-2089741757/TestClientWithDependencies1536929064/001/store) requires matching store prefix8852026/08/27 09:41:11 OK 20241026095416_initial_model.sql (200.91ms)8862026/08/27 09:41:11 OK 20260628120000_add_object_size_and_stats.sql (67.28ms)8872026/08/27 09:41:11 goose: successfully migrated database to version: 20260628120000888--- PASS: TestClientWithDependencies (2.71s)889=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT8902026/08/27 09:41:11 OK 1_commit_pending_closure.sql (11.08ms)8912026/08/27 09:41:11 OK 20251218171726_add_pins.sql (36.44ms)8922026/08/27 09:41:11 OK 2_object_stats_trigger.sql (3.63ms)8932026/08/27 09:41:11 goose: up to current file version: 28942026/08/27 09:41:11 OK 20251210153512_drop_unused_gin_index.sql (30.08ms)8952026/08/27 09:41:11 INFO Created nix-cache-info in bucket bucket=bucket128962026/08/27 09:41:11 OK 20260628120000_add_object_size_and_stats.sql (35.81ms)8972026/08/27 09:41:11 goose: successfully migrated database to version: 202606281200008982026/08/27 09:41:11 OK 1_commit_pending_closure.sql (14.79ms)8992026/08/27 09:41:11 OK 20251218171726_add_pins.sql (37.77ms)9002026/08/27 09:41:11 OK 2_object_stats_trigger.sql (1.74ms)9012026/08/27 09:41:11 goose: up to current file version: 29022026/08/27 09:41:11 OK 20260628120000_add_object_size_and_stats.sql (18.45ms)9032026/08/27 09:41:11 goose: successfully migrated database to version: 202606281200009042026/08/27 09:41:11 OK 1_commit_pending_closure.sql (2.58ms)9052026/08/27 09:41:11 OK 2_object_stats_trigger.sql (561.75µs)9062026/08/27 09:41:11 goose: up to current file version: 2907--- PASS: TestCacheStatsHandler (1.79s)908=== CONT TestIsValidCachePath909=== RUN TestIsValidCachePath/narinfo910=== PAUSE TestIsValidCachePath/narinfo911=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars912=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars913=== RUN TestIsValidCachePath/nar_zst914=== PAUSE TestIsValidCachePath/nar_zst915=== RUN TestIsValidCachePath/nar_xz916=== PAUSE TestIsValidCachePath/nar_xz917=== RUN TestIsValidCachePath/nar_bz2918=== PAUSE TestIsValidCachePath/nar_bz2919=== RUN TestIsValidCachePath/nar_uncompressed920=== PAUSE TestIsValidCachePath/nar_uncompressed921=== RUN TestIsValidCachePath/ls922=== PAUSE TestIsValidCachePath/ls923=== RUN TestIsValidCachePath/log924=== PAUSE TestIsValidCachePath/log925=== RUN TestIsValidCachePath/realisation926=== PAUSE TestIsValidCachePath/realisation927=== RUN TestIsValidCachePath/nix-cache-info928=== PAUSE TestIsValidCachePath/nix-cache-info929=== RUN TestIsValidCachePath/index.html930=== PAUSE TestIsValidCachePath/index.html931=== RUN TestIsValidCachePath/traversal_parent932=== PAUSE TestIsValidCachePath/traversal_parent933=== RUN TestIsValidCachePath/traversal_in_middle934=== PAUSE TestIsValidCachePath/traversal_in_middle935=== RUN TestIsValidCachePath/invalid_char_e936=== PAUSE TestIsValidCachePath/invalid_char_e937=== RUN TestIsValidCachePath/invalid_char_u938=== PAUSE TestIsValidCachePath/invalid_char_u939=== RUN TestIsValidCachePath/random_path940=== PAUSE TestIsValidCachePath/random_path941=== RUN TestIsValidCachePath/empty942=== PAUSE TestIsValidCachePath/empty943=== RUN TestIsValidCachePath/leading_slash944=== PAUSE TestIsValidCachePath/leading_slash945=== RUN TestIsValidCachePath/wrong_extension946=== PAUSE TestIsValidCachePath/wrong_extension947=== RUN TestIsValidCachePath/short_hash948=== PAUSE TestIsValidCachePath/short_hash949=== CONT TestCompleteMultipartUnregistered950=== NAME TestClientIntegration951 client_integration_test.go:276: Created store path: /nix/var/nix/builds/nix-42860-2089741757/TestClientIntegration4240365124/002/store/5n66yyyx5x1m3dxypd8bxz35rd2x09ka-test-file.txt952=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token953=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token954=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected955=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected956=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected957=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected958=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured959=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured960=== CONT TestService_verifyS3Integrity9612026/08/27 09:41:11 WARN mTLS auth: subject not in bound subjects subject="CN=writer"962--- PASS: TestService_ReadAuthMiddleware (1.90s)963=== CONT TestReadProxyNarStreaming9642026/08/27 09:41:11 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9652026/08/27 09:41:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9662026/08/27 09:41:11 INFO Created nix-cache-info in bucket bucket=bucket149672026/08/27 09:41:11 INFO Received uploads request method=POST path=/api/pending_closures9682026/08/27 09:41:11 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YjNmYmQxYTgtZmNhNC00NDYwLWI0MTctODBlMTUxZDk5NWUyLjJlNGY4M2QxLTUxZTktNDI2My05MjdkLTM3N2RkZTFlZTFiZXgxNzg3ODIzNjY5NTcwODc0MDAw parts=109692026/08/27 09:41:11 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9702026/08/27 09:41:11 INFO Completed upload id=19712026/08/27 09:41:11 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009722026-08-27 09:41:11.612 UTC [43673] ERROR: relation "goose_db_version" does not exist at character 369732026-08-27 09:41:11.612 UTC [43673] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9742026-08-27 09:41:11.614 UTC [43675] ERROR: relation "goose_db_version" does not exist at character 369752026-08-27 09:41:11.614 UTC [43675] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9762026/08/27 09:41:11 INFO Received uploads request method=POST path=/api/pending_closures9772026/08/27 09:41:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9782026/08/27 09:41:11 INFO Uploading 5n66yyyx5x1m3dxypd8bxz35rd2x09ka-test-file.txt (152B)9792026/08/27 09:41:11 INFO Starting cleanup of old closures method=DELETE path=/api/closures9802026/08/27 09:41:11 INFO Aborted multipart uploads count=09812026/08/27 09:41:11 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=0 objects-failed-to-delete=09822026/08/27 09:41:11 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"9832026/08/27 09:41:11 INFO Vacuumed table table=pending_closures9842026/08/27 09:41:11 WARN Failed to register uploaded object key=5n66yyyx5x1m3dxypd8bxz35rd2x09ka.ls error="server returned 404: 404 page not found\n"9852026/08/27 09:41:11 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9862026/08/27 09:41:11 INFO Signed narinfos id=1 count=19872026/08/27 09:41:11 INFO Uploading 1 narinfos9882026/08/27 09:41:11 INFO Vacuumed table table=pending_objects9892026/08/27 09:41:11 WARN Failed to register uploaded object key=5n66yyyx5x1m3dxypd8bxz35rd2x09ka.narinfo error="server returned 404: 404 page not found\n"9902026/08/27 09:41:11 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9912026/08/27 09:41:11 INFO Vacuumed table table=multipart_uploads9922026/08/27 09:41:11 INFO Completed upload id=19932026/08/27 09:41:11 INFO Upload complete. (397ms)994=== NAME TestClientIntegration995 client_integration_test.go:292: Retrieved narinfo from S3:996 StorePath: /nix/var/nix/builds/nix-42860-2089741757/TestClientIntegration4240365124/002/store/5n66yyyx5x1m3dxypd8bxz35rd2x09ka-test-file.txt997 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst998 Compression: zstd999 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11000 NarSize: 1521001 References: 1002 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11003 client_integration_test.go:293: Retrieved .ls file from S3 (compressed size: 77 bytes)1004 client_integration_test.go:293: Decompressed .ls content (64 bytes):1005 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1006 client_integration_test.go:296: Testing garbage collection...10072026/08/27 09:41:11 INFO Vacuumed table table=closures10082026/08/27 09:41:11 INFO Vacuumed table table=objects10092026/08/27 09:41:11 OK 20241026095416_initial_model.sql (121.76ms)10102026/08/27 09:41:11 OK 20241026095416_initial_model.sql (118.56ms)10112026/08/27 09:41:11 OK 20251210153512_drop_unused_gin_index.sql (5.13ms)10122026/08/27 09:41:11 OK 20251210153512_drop_unused_gin_index.sql (7.29ms)10132026/08/27 09:41:11 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001014--- PASS: TestService_createPendingClosureHandler (3.47s)1015=== CONT TestReadProxyNarinfoAlreadyDecompressed10162026/08/27 09:41:11 OK 20251218171726_add_pins.sql (38.33ms)10172026/08/27 09:41:11 OK 20251218171726_add_pins.sql (44.34ms)10182026/08/27 09:41:11 INFO Starting cleanup of old closures method=DELETE path=/api/closures10192026/08/27 09:41:11 INFO Garbage collection started10202026/08/27 09:41:11 INFO Aborted multipart uploads count=010212026/08/27 09:41:11 WARN Force mode enabled - objects will be deleted immediately without grace period10222026/08/27 09:41:11 OK 20260628120000_add_object_size_and_stats.sql (42.31ms)10232026/08/27 09:41:11 goose: successfully migrated database to version: 2026062812000010242026/08/27 09:41:11 OK 1_commit_pending_closure.sql (19.94ms)10252026/08/27 09:41:11 OK 20260628120000_add_object_size_and_stats.sql (58.57ms)10262026/08/27 09:41:11 goose: successfully migrated database to version: 2026062812000010272026/08/27 09:41:11 OK 2_object_stats_trigger.sql (10.23ms)10282026/08/27 09:41:11 goose: up to current file version: 210292026/08/27 09:41:11 OK 1_commit_pending_closure.sql (21.78ms)10302026/08/27 09:41:11 OK 2_object_stats_trigger.sql (680.96µs)10312026/08/27 09:41:11 goose: up to current file version: 210322026/08/27 09:41:12 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"10332026/08/27 09:41:12 WARN mTLS auth: bound subjects configured but subject DN unavailable10342026/08/27 09:41:12 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1035--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.02s)1036=== CONT TestResurrectedObjectNotDeleted10372026/08/27 09:41:12 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=01038=== NAME TestClientCADerivations1039 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-42860-2089741757/TestClientCADerivations457906247/001/store/i88mymnwb916n5h3sn34bqln20299nh4-ca-test1040--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.93s)1041=== CONT TestReadProxyNarinfo10422026/08/27 09:41:12 INFO Vacuumed table table=pending_closures10432026/08/27 09:41:12 INFO Vacuumed table table=pending_objects10442026/08/27 09:41:12 INFO Vacuumed table table=multipart_uploads10452026/08/27 09:41:12 INFO Vacuumed table table=closures1046=== NAME TestClientCADerivations1047 client_ca_test.go:139: Found 1 dependencies (including self)10482026/08/27 09:41:12 INFO Vacuumed table table=objects10492026/08/27 09:41:12 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10502026-08-27 09:41:12.373 UTC [43719] ERROR: relation "goose_db_version" does not exist at character 3610512026-08-27 09:41:12.373 UTC [43719] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10522026-08-27 09:41:12.378 UTC [43718] ERROR: relation "goose_db_version" does not exist at character 3610532026-08-27 09:41:12.378 UTC [43718] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10542026-08-27 09:41:12.395 UTC [43720] ERROR: relation "goose_db_version" does not exist at character 3610552026-08-27 09:41:12.395 UTC [43720] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10562026-08-27 09:41:12.402 UTC [43721] ERROR: relation "goose_db_version" does not exist at character 3610572026-08-27 09:41:12.402 UTC [43721] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10582026/08/27 09:41:12 INFO Received uploads request method=POST path=/api/pending_closures10592026/08/27 09:41:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10602026/08/27 09:41:12 INFO Uploading i88mymnwb916n5h3sn34bqln20299nh4-ca-test (144B)10612026/08/27 09:41:12 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"10622026/08/27 09:41:12 WARN Failed to register uploaded object key=log/yk1hhh15pv1magb0gcg2y8ffi9kxbf8f-ca-test.drv error="server returned 404: 404 page not found\n"10632026/08/27 09:41:12 WARN Failed to register uploaded object key=i88mymnwb916n5h3sn34bqln20299nh4.ls error="server returned 404: 404 page not found\n"10642026/08/27 09:41:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10652026/08/27 09:41:12 INFO Signed narinfos id=1 count=110662026/08/27 09:41:12 INFO Uploading 1 narinfos10672026/08/27 09:41:12 OK 20241026095416_initial_model.sql (159.65ms)10682026/08/27 09:41:12 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01069=== NAME TestPinProtectsFromGC1070 client_integration_test.go:709: Pin successfully protected closure from garbage collection10712026/08/27 09:41:12 WARN Failed to register uploaded object key=i88mymnwb916n5h3sn34bqln20299nh4.narinfo error="server returned 404: 404 page not found\n"10722026/08/27 09:41:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10732026/08/27 09:41:12 OK 20251210153512_drop_unused_gin_index.sql (28.02ms)10742026/08/27 09:41:12 OK 20241026095416_initial_model.sql (189.65ms)10752026/08/27 09:41:12 OK 20241026095416_initial_model.sql (190.82ms)10762026/08/27 09:41:12 OK 20251210153512_drop_unused_gin_index.sql (11.45ms)10772026/08/27 09:41:12 INFO Completed upload id=110782026/08/27 09:41:12 OK 20241026095416_initial_model.sql (174.66ms)10792026/08/27 09:41:12 OK 20251210153512_drop_unused_gin_index.sql (12.88ms)10802026/08/27 09:41:12 INFO Upload complete. (407ms)1081--- PASS: TestPinProtectsFromGC (4.30s)1082=== CONT TestParseSingleRange1083=== RUN TestParseSingleRange/none1084=== PAUSE TestParseSingleRange/none1085=== RUN TestParseSingleRange/unknown_unit1086=== PAUSE TestParseSingleRange/unknown_unit1087=== RUN TestParseSingleRange/multi-range_ignored1088=== PAUSE TestParseSingleRange/multi-range_ignored1089=== RUN TestParseSingleRange/malformed_no_dash1090=== PAUSE TestParseSingleRange/malformed_no_dash1091=== RUN TestParseSingleRange/malformed_both_empty1092=== PAUSE TestParseSingleRange/malformed_both_empty1093=== RUN TestParseSingleRange/malformed_end_before_start1094=== PAUSE TestParseSingleRange/malformed_end_before_start1095=== RUN TestParseSingleRange/closed1096=== PAUSE TestParseSingleRange/closed1097=== RUN TestParseSingleRange/open-ended1098=== PAUSE TestParseSingleRange/open-ended1099=== RUN TestParseSingleRange/end_clamped_to_size1100=== PAUSE TestParseSingleRange/end_clamped_to_size1101=== RUN TestParseSingleRange/suffix1102=== PAUSE TestParseSing2026/08/27 09:41:12 OK 20251218171726_add_pins.sql (16.8ms)1103leRange/suffix1104=== RUN TestParseSingleRange/suffix_exceeds_size1105=== PAUSE TestParseSingleRange/suffix_exceeds_size1106=== RUN TestParseSingleRange/single_byte1107=== PAUSE TestParseSingleRange/single_byte1108=== RUN TestParseSingleRange/start_past_EOF1109=== PAUSE TestParseSingleRange/start_past_EOF1110=== RUN TestParseSingleRange/start_far_past_EOF1111=== PAUSE TestParseSingleRange/start_far_past_EOF1112=== CONT TestServerTLSConfig1113=== RUN TestServerTLSConfig/no_client_CA1114=== PAUSE TestServerTLSConfig/no_client_CA1115=== RUN TestServerTLSConfig/missing_CA_file1116=== PAUSE TestServerTLSConfig/missing_CA_file1117=== RUN TestServerTLSConfig/not_a_PEM_file1118=== PAUSE TestServerTLSConfig/not_a_PEM_file1119=== CONT TestService_healthCheckHandler11202026/08/27 09:41:12 OK 20251210153512_drop_unused_gin_index.sql (4.65ms)11212026/08/27 09:41:12 OK 20251218171726_add_pins.sql (5.02ms)11222026/08/27 09:41:12 OK 20251218171726_add_pins.sql (6.59ms)1123=== NAME TestClientCADerivations1124 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-42860-2089741757/TestClientCADerivations457906247/001/store/i88mymnwb916n5h3sn34bqln20299nh4-ca-test1125 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1126 Compression: zstd1127 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1128 NarSize: 1441129 References: 1130 Deriver: /nix/var/nix/builds/nix-42860-2089741757/TestClientCADerivations457906247/001/store/yk1hhh15pv1magb0gcg2y8ffi9kxbf8f-ca-test.drv1131 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1132 client_ca_test.go:185: Checking for realisation files in S3...1133 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1134 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache11352026/08/27 09:41:12 OK 20260628120000_add_object_size_and_stats.sql (25.5ms)11362026/08/27 09:41:12 goose: successfully migrated database to version: 2026062812000011372026/08/27 09:41:12 OK 20251218171726_add_pins.sql (25.93ms)11382026/08/27 09:41:12 OK 1_commit_pending_closure.sql (13.26ms)11392026/08/27 09:41:12 OK 20260628120000_add_object_size_and_stats.sql (35.72ms)11402026/08/27 09:41:12 goose: successfully migrated database to version: 2026062812000011412026/08/27 09:41:12 OK 20260628120000_add_object_size_and_stats.sql (35.86ms)11422026/08/27 09:41:12 goose: successfully migrated database to version: 2026062812000011432026/08/27 09:41:12 OK 2_object_stats_trigger.sql (616.08µs)11442026/08/27 09:41:12 goose: up to current file version: 211452026/08/27 09:41:12 OK 1_commit_pending_closure.sql (8.54ms)11462026/08/27 09:41:12 OK 1_commit_pending_closure.sql (8.55ms)11472026/08/27 09:41:12 OK 2_object_stats_trigger.sql (529.13µs)11482026/08/27 09:41:12 goose: up to current file version: 211492026/08/27 09:41:12 OK 2_object_stats_trigger.sql (559.17µs)11502026/08/27 09:41:12 goose: up to current file version: 211512026/08/27 09:41:12 OK 20260628120000_add_object_size_and_stats.sql (50.47ms)11522026/08/27 09:41:12 goose: successfully migrated database to version: 2026062812000011532026/08/27 09:41:12 OK 1_commit_pending_closure.sql (9.39ms)11542026/08/27 09:41:12 OK 2_object_stats_trigger.sql (307.79µs)11552026/08/27 09:41:12 goose: up to current file version: 21156 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket14?endpoint=http://localhost:52075®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-42860-2089741757/TestClientCADerivations457906247/001/store'1157 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11158--- PASS: TestClientCADerivations (3.42s)1159=== CONT TestService_NativeMTLS11602026-08-27 09:41:12.837 UTC [43732] ERROR: relation "goose_db_version" does not exist at character 3611612026-08-27 09:41:12.837 UTC [43732] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11622026/08/27 09:41:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11632026/08/27 09:41:12 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1164--- PASS: TestCompleteMultipartUnregistered (1.62s)1165=== CONT TestReadProxyRootRedirectsToIndexHTML11662026/08/27 09:41:12 INFO Received uploads request method=POST path=/api/pending_closures1167--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.95s)1168=== CONT TestGracefulShutdownDrainsInflight11692026/08/27 09:41:12 INFO Starting HTTP server address=127.0.0.1:5217011702026/08/27 09:41:12 INFO Shutdown signal received, draining in-flight requests timeout=10s1171--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1172=== CONT TestMetricsInventory1173--- PASS: TestReadProxyNarStreaming (1.64s)1174=== CONT TestRedundantMultipartUpload11752026/08/27 09:41:13 OK 20241026095416_initial_model.sql (222.63ms)11762026/08/27 09:41:13 OK 20251210153512_drop_unused_gin_index.sql (11.13ms)11772026/08/27 09:41:13 INFO Received uploads request method=POST path=/api/pending_closures11782026/08/27 09:41:13 OK 20251218171726_add_pins.sql (19.74ms)11792026/08/27 09:41:13 OK 20260628120000_add_object_size_and_stats.sql (35.62ms)11802026/08/27 09:41:13 goose: successfully migrated database to version: 2026062812000011812026/08/27 09:41:13 OK 1_commit_pending_closure.sql (8.18ms)11822026/08/27 09:41:13 OK 2_object_stats_trigger.sql (498.33µs)11832026/08/27 09:41:13 goose: up to current file version: 21184--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.63s)1185=== CONT TestGCTaskStore_Fail1186--- PASS: TestGCTaskStore_Fail (0.00s)1187=== CONT TestNARDeduplicationMetadataUploadBug11882026-08-27 09:41:13.444 UTC [43781] ERROR: relation "goose_db_version" does not exist at character 3611892026-08-27 09:41:13.444 UTC [43781] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11902026-08-27 09:41:13.554 UTC [43796] ERROR: relation "goose_db_version" does not exist at character 3611912026-08-27 09:41:13.554 UTC [43796] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11922026/08/27 09:41:13 OK 20241026095416_initial_model.sql (106.5ms)11932026/08/27 09:41:13 OK 20251210153512_drop_unused_gin_index.sql (12.2ms)11942026/08/27 09:41:13 OK 20251218171726_add_pins.sql (17.92ms)11952026/08/27 09:41:13 OK 20260628120000_add_object_size_and_stats.sql (5.91ms)11962026/08/27 09:41:13 goose: successfully migrated database to version: 2026062812000011972026/08/27 09:41:13 OK 1_commit_pending_closure.sql (3.03ms)11982026/08/27 09:41:13 OK 2_object_stats_trigger.sql (390µs)11992026/08/27 09:41:13 goose: up to current file version: 212002026/08/27 09:41:13 OK 20241026095416_initial_model.sql (97.98ms)12012026/08/27 09:41:13 OK 20251210153512_drop_unused_gin_index.sql (16.11ms)12022026/08/27 09:41:13 OK 20251218171726_add_pins.sql (45.21ms)12032026/08/27 09:41:13 OK 20260628120000_add_object_size_and_stats.sql (51.88ms)12042026/08/27 09:41:13 goose: successfully migrated database to version: 2026062812000012052026/08/27 09:41:13 OK 1_commit_pending_closure.sql (10.63ms)12062026/08/27 09:41:13 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=012072026/08/27 09:41:13 OK 2_object_stats_trigger.sql (1.18ms)12082026/08/27 09:41:13 goose: up to current file version: 21209=== NAME TestClientIntegration1210 client_integration_test.go:303: Objects in database after GC:1211 client_integration_test.go:303: Successfully deleted all objects with GC --force1212--- PASS: TestClientIntegration (4.82s)1213=== CONT TestReadProxyRangeRequest1214--- PASS: TestReadProxyNarinfo (1.81s)1215=== CONT TestGCTaskStore_PhaseUpdates1216--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1217=== CONT TestCreatePendingClosureRejectsOversizedNAR12182026/08/27 09:41:13 INFO Received uploads request method=POST path=/api/pending_closures1219--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1220=== CONT TestReadProxyDisabled1221--- PASS: TestResurrectedObjectNotDeleted (2.22s)1222=== CONT TestGCTaskStore_CompletedAllowsNewTask1223--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1224=== CONT TestCacheConfigHandlerMaxNarSize1225--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1226=== CONT TestOrphanedObjectsGCStressTest12272026-08-27 09:41:14.403 UTC [43939] ERROR: relation "goose_db_version" does not exist at character 3612282026-08-27 09:41:14.403 UTC [43939] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12292026-08-27 09:41:14.445 UTC [43942] ERROR: relation "goose_db_version" does not exist at character 3612302026-08-27 09:41:14.445 UTC [43942] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12312026-08-27 09:41:14.454 UTC [43953] ERROR: relation "goose_db_version" does not exist at character 3612322026-08-27 09:41:14.454 UTC [43953] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12332026-08-27 09:41:14.460 UTC [43956] ERROR: relation "goose_db_version" does not exist at character 3612342026-08-27 09:41:14.460 UTC [43956] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12352026/08/27 09:41:14 OK 20241026095416_initial_model.sql (39.18ms)12362026/08/27 09:41:14 OK 20251210153512_drop_unused_gin_index.sql (27.54ms)12372026-08-27 09:41:14.561 UTC [43965] ERROR: relation "goose_db_version" does not exist at character 3612382026-08-27 09:41:14.561 UTC [43965] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12392026/08/27 09:41:14 OK 20241026095416_initial_model.sql (47.48ms)12402026/08/27 09:41:14 OK 20251218171726_add_pins.sql (46.36ms)12412026/08/27 09:41:14 OK 20251210153512_drop_unused_gin_index.sql (8.66ms)12422026/08/27 09:41:14 OK 20241026095416_initial_model.sql (63.04ms)12432026/08/27 09:41:14 OK 20251210153512_drop_unused_gin_index.sql (12.23ms)12442026/08/27 09:41:14 OK 20251218171726_add_pins.sql (21.38ms)12452026/08/27 09:41:14 OK 20260628120000_add_object_size_and_stats.sql (22.21ms)12462026/08/27 09:41:14 goose: successfully migrated database to version: 2026062812000012472026/08/27 09:41:14 OK 1_commit_pending_closure.sql (13.16ms)12482026/08/27 09:41:14 OK 2_object_stats_trigger.sql (263.21µs)12492026/08/27 09:41:14 goose: up to current file version: 212502026/08/27 09:41:14 OK 20251218171726_add_pins.sql (29.24ms)12512026/08/27 09:41:14 OK 20241026095416_initial_model.sql (113.74ms)12522026/08/27 09:41:14 OK 20260628120000_add_object_size_and_stats.sql (44.57ms)12532026/08/27 09:41:14 goose: successfully migrated database to version: 2026062812000012542026/08/27 09:41:14 OK 20251210153512_drop_unused_gin_index.sql (15.36ms)12552026/08/27 09:41:14 OK 1_commit_pending_closure.sql (15.15ms)12562026/08/27 09:41:14 OK 2_object_stats_trigger.sql (213.21µs)12572026/08/27 09:41:14 goose: up to current file version: 212582026/08/27 09:41:14 OK 20260628120000_add_object_size_and_stats.sql (43.22ms)12592026/08/27 09:41:14 goose: successfully migrated database to version: 2026062812000012602026/08/27 09:41:14 OK 1_commit_pending_closure.sql (9.6ms)12612026/08/27 09:41:14 OK 2_object_stats_trigger.sql (249.83µs)12622026/08/27 09:41:14 goose: up to current file version: 212632026/08/27 09:41:14 OK 20251218171726_add_pins.sql (45.04ms)12642026/08/27 09:41:14 OK 20260628120000_add_object_size_and_stats.sql (58.44ms)12652026/08/27 09:41:14 goose: successfully migrated database to version: 2026062812000012662026/08/27 09:41:14 OK 1_commit_pending_closure.sql (15.02ms)12672026/08/27 09:41:14 OK 2_object_stats_trigger.sql (556.54µs)12682026/08/27 09:41:14 goose: up to current file version: 212692026/08/27 09:41:14 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12702026/08/27 09:41:14 WARN mTLS auth: subject not in bound subjects subject="CN=writer"1271--- PASS: TestService_NativeMTLS (1.95s)1272=== CONT TestGenerateLandingPage1273--- PASS: TestGenerateLandingPage (0.00s)1274=== CONT TestGCTaskStore_GetReturnsLatest1275--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1276=== CONT TestParseSize1277--- PASS: TestParseSize (0.00s)1278=== CONT TestReadProxyHead1279--- PASS: TestService_healthCheckHandler (2.29s)1280=== CONT TestGCTaskStore_GetEmpty1281--- PASS: TestGCTaskStore_GetEmpty (0.00s)1282=== CONT TestProxyWriteTimeout1283=== RUN TestProxyWriteTimeout/narinfo1284=== PAUSE TestProxyWriteTimeout/narinfo1285=== RUN TestProxyWriteTimeout/1_GiB_nar1286=== PAUSE TestProxyWriteTimeout/1_GiB_nar1287=== RUN TestProxyWriteTimeout/10_GiB_nar1288=== PAUSE TestProxyWriteTimeout/10_GiB_nar1289=== RUN TestProxyWriteTimeout/unknown_size1290=== PAUSE TestProxyWriteTimeout/unknown_size1291=== CONT TestReadProxyConditionalGet12922026/08/27 09:41:14 OK 20241026095416_initial_model.sql (306.81ms)12932026/08/27 09:41:14 OK 20251210153512_drop_unused_gin_index.sql (17.56ms)12942026/08/27 09:41:15 OK 20251218171726_add_pins.sql (49.58ms)12952026/08/27 09:41:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12962026/08/27 09:41:15 OK 20260628120000_add_object_size_and_stats.sql (66.62ms)12972026/08/27 09:41:15 goose: successfully migrated database to version: 2026062812000012982026/08/27 09:41:15 OK 1_commit_pending_closure.sql (14.09ms)12992026/08/27 09:41:15 OK 2_object_stats_trigger.sql (549.29µs)13002026/08/27 09:41:15 goose: up to current file version: 21301--- PASS: TestMetricsInventory (2.05s)1302=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle13032026/08/27 09:41:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YjNmYmQxYTgtZmNhNC00NDYwLWI0MTctODBlMTUxZDk5NWUyLmFkNjljYTEyLWExZWQtNGZjZC05N2NmLWZlMjZmNGYyNjJhZXgxNzg3ODIzNjczMTY4MjExMDAw parts=1013042026/08/27 09:41:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13052026/08/27 09:41:15 INFO Completed upload id=113062026/08/27 09:41:15 INFO Received uploads request method=POST path=/api/pending_closures13072026/08/27 09:41:15 INFO Received uploads request method=POST path=/api/pending_closures13082026/08/27 09:41:15 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13092026/08/27 09:41:15 WARN Found objects in DB but missing from S3, will re-upload count=11310--- PASS: TestService_verifyS3Integrity (3.78s)1311=== CONT TestPresignedUploadRegisteredBeforeCommit1312--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.32s)1313=== CONT TestOrphanedObjectsGC13142026/08/27 09:41:15 INFO Received uploads request method=POST path=/api/pending_closures13152026-08-27 09:41:15.315 UTC [44015] ERROR: relation "goose_db_version" does not exist at character 3613162026-08-27 09:41:15.315 UTC [44015] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13172026-08-27 09:41:15.316 UTC [44016] ERROR: relation "goose_db_version" does not exist at character 3613182026-08-27 09:41:15.316 UTC [44016] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13192026/08/27 09:41:15 INFO Received uploads request method=POST path=/api/pending_closures13202026-08-27 09:41:15.397 UTC [44028] ERROR: relation "goose_db_version" does not exist at character 3613212026-08-27 09:41:15.397 UTC [44028] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13222026/08/27 09:41:15 OK 20241026095416_initial_model.sql (95.94ms)13232026/08/27 09:41:15 OK 20251210153512_drop_unused_gin_index.sql (1.74ms)13242026/08/27 09:41:15 OK 20251218171726_add_pins.sql (3.67ms)13252026/08/27 09:41:15 OK 20241026095416_initial_model.sql (46.49ms)13262026/08/27 09:41:15 OK 20251210153512_drop_unused_gin_index.sql (823.63µs)13272026/08/27 09:41:15 OK 20251218171726_add_pins.sql (1.18ms)13282026/08/27 09:41:15 OK 20260628120000_add_object_size_and_stats.sql (3.02ms)13292026/08/27 09:41:15 goose: successfully migrated database to version: 2026062812000013302026/08/27 09:41:15 OK 1_commit_pending_closure.sql (2.66ms)13312026/08/27 09:41:15 OK 20260628120000_add_object_size_and_stats.sql (8.94ms)13322026/08/27 09:41:15 goose: successfully migrated database to version: 2026062812000013332026/08/27 09:41:15 OK 2_object_stats_trigger.sql (1.23ms)13342026/08/27 09:41:15 goose: up to current file version: 213352026/08/27 09:41:15 OK 1_commit_pending_closure.sql (2.18ms)13362026/08/27 09:41:15 OK 20241026095416_initial_model.sql (20.57ms)13372026/08/27 09:41:15 OK 2_object_stats_trigger.sql (738.92µs)13382026/08/27 09:41:15 goose: up to current file version: 213392026/08/27 09:41:15 OK 20251210153512_drop_unused_gin_index.sql (3.82ms)13402026/08/27 09:41:15 OK 20251218171726_add_pins.sql (36.58ms)13412026/08/27 09:41:15 OK 20260628120000_add_object_size_and_stats.sql (43.96ms)13422026/08/27 09:41:15 goose: successfully migrated database to version: 2026062812000013432026/08/27 09:41:15 OK 1_commit_pending_closure.sql (12ms)13442026/08/27 09:41:15 OK 2_object_stats_trigger.sql (562.38µs)13452026/08/27 09:41:15 goose: up to current file version: 213462026/08/27 09:41:15 INFO Created nix-cache-info in bucket bucket=bucket311347--- PASS: TestReadProxyRangeRequest (1.82s)1348=== CONT TestSkippedUploadsHandler13492026/08/27 09:41:15 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001350--- PASS: TestSkippedUploadsHandler (0.00s)1351=== CONT TestService_Rustfstest1352--- PASS: TestReadProxyDisabled (1.83s)1353=== CONT TestUploadHandlersRejectOversizedBody1354=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1355=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1356=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1357=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1358=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1359=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1360=== CONT TestReadProxyInvalidPath1361=== NAME TestNARDeduplicationMetadataUploadBug1362 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-42860-2089741757/TestNARDeduplicationMetadataUploadBug2442918457/001/store/nrfdy8pz01sn6jrhjp1n1wwd11l1gwzy-file1.txt13632026-08-27 09:41:16.020 UTC [44073] ERROR: relation "goose_db_version" does not exist at character 3613642026-08-27 09:41:16.020 UTC [44073] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13652026/08/27 09:41:16 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13662026/08/27 09:41:16 OK 20241026095416_initial_model.sql (90.68ms)13672026/08/27 09:41:16 OK 20251210153512_drop_unused_gin_index.sql (12.35ms)13682026/08/27 09:41:16 OK 20251218171726_add_pins.sql (32.87ms)13692026/08/27 09:41:16 INFO Received uploads request method=POST path=/api/pending_closures13702026/08/27 09:41:16 OK 20260628120000_add_object_size_and_stats.sql (33.44ms)13712026/08/27 09:41:16 goose: successfully migrated database to version: 2026062812000013722026/08/27 09:41:16 OK 1_commit_pending_closure.sql (8.97ms)13732026/08/27 09:41:16 OK 2_object_stats_trigger.sql (534.67µs)13742026/08/27 09:41:16 goose: up to current file version: 213752026/08/27 09:41:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13762026/08/27 09:41:16 INFO Uploading nrfdy8pz01sn6jrhjp1n1wwd11l1gwzy-file1.txt (160B)13772026/08/27 09:41:16 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13782026/08/27 09:41:16 WARN Failed to register uploaded object key=nrfdy8pz01sn6jrhjp1n1wwd11l1gwzy.ls error="server returned 404: 404 page not found\n"13792026/08/27 09:41:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13802026/08/27 09:41:16 INFO Signed narinfos id=1 count=113812026/08/27 09:41:16 INFO Uploading 1 narinfos13822026/08/27 09:41:16 WARN Failed to register uploaded object key=nrfdy8pz01sn6jrhjp1n1wwd11l1gwzy.narinfo error="server returned 404: 404 page not found\n"13832026/08/27 09:41:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13842026/08/27 09:41:16 INFO Completed upload id=113852026/08/27 09:41:16 INFO Upload complete. (400ms)1386 metadata_upload_test.go:54: Retrieved narinfo from S3:1387 StorePath: /nix/var/nix/builds/nix-42860-2089741757/TestNARDeduplicationMetadataUploadBug2442918457/001/store/nrfdy8pz01sn6jrhjp1n1wwd11l1gwzy-file1.txt1388 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1389 Compression: zstd1390 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1391 NarSize: 1601392 References: 1393 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1394 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1395 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1396 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}13972026-08-27 09:41:16.454 UTC [44101] ERROR: relation "goose_db_version" does not exist at character 3613982026-08-27 09:41:16.454 UTC [44101] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13992026-08-27 09:41:16.458 UTC [44102] ERROR: relation "goose_db_version" does not exist at character 3614002026-08-27 09:41:16.458 UTC [44102] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14012026-08-27 09:41:16.561 UTC [44103] ERROR: relation "goose_db_version" does not exist at character 3614022026-08-27 09:41:16.561 UTC [44103] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1403 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-42860-2089741757/TestNARDeduplicationMetadataUploadBug2442918457/001/store/np1nlhx6b2icf0wc8g95798flzwngs8g-file2.txt14042026/08/27 09:41:16 OK 20241026095416_initial_model.sql (71.67ms)14052026/08/27 09:41:16 OK 20251210153512_drop_unused_gin_index.sql (18.9ms)14062026/08/27 09:41:16 OK 20251218171726_add_pins.sql (41.91ms)14072026/08/27 09:41:16 OK 20241026095416_initial_model.sql (140.89ms)14082026/08/27 09:41:16 OK 20251210153512_drop_unused_gin_index.sql (16.87ms)14092026/08/27 09:41:16 OK 20260628120000_add_object_size_and_stats.sql (33.54ms)14102026/08/27 09:41:16 goose: successfully migrated database to version: 2026062812000014112026/08/27 09:41:16 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14122026/08/27 09:41:16 OK 1_commit_pending_closure.sql (17.69ms)14132026/08/27 09:41:16 OK 2_object_stats_trigger.sql (544.67µs)14142026/08/27 09:41:16 goose: up to current file version: 214152026/08/27 09:41:16 OK 20251218171726_add_pins.sql (40.54ms)14162026-08-27 09:41:16.738 UTC [44114] ERROR: relation "goose_db_version" does not exist at character 3614172026-08-27 09:41:16.738 UTC [44114] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14182026/08/27 09:41:16 OK 20260628120000_add_object_size_and_stats.sql (40.63ms)14192026/08/27 09:41:16 goose: successfully migrated database to version: 2026062812000014202026/08/27 09:41:16 INFO Received uploads request method=POST path=/api/pending_closures14212026/08/27 09:41:16 OK 1_commit_pending_closure.sql (9.69ms)14222026/08/27 09:41:16 OK 2_object_stats_trigger.sql (446.04µs)14232026/08/27 09:41:16 goose: up to current file version: 214242026/08/27 09:41:16 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14252026/08/27 09:41:16 WARN Failed to register uploaded object key=np1nlhx6b2icf0wc8g95798flzwngs8g.ls error="server returned 404: 404 page not found\n"14262026/08/27 09:41:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14272026/08/27 09:41:16 INFO Signed narinfos id=2 count=114282026/08/27 09:41:16 INFO Uploading 1 narinfos14292026/08/27 09:41:16 OK 20241026095416_initial_model.sql (278.89ms)14302026/08/27 09:41:16 WARN Failed to register uploaded object key=np1nlhx6b2icf0wc8g95798flzwngs8g.narinfo error="server returned 404: 404 page not found\n"14312026/08/27 09:41:16 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14322026/08/27 09:41:16 INFO Completed upload id=214332026/08/27 09:41:16 INFO Upload complete. (272ms)1434 metadata_upload_test.go:76: Retrieved narinfo from S3:1435 StorePath: /nix/var/nix/builds/nix-42860-2089741757/TestNARDeduplicationMetadataUploadBug2442918457/001/store/np1nlhx6b2icf0wc8g95798flzwngs8g-file2.txt1436 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1437 Compression: zstd1438 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1439 NarSize: 1601440 References: 1441 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1442 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1443 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1444 {"version":1,"root":{"type":"regular","size":44}}14452026/08/27 09:41:16 OK 20251210153512_drop_unused_gin_index.sql (31.02ms)14462026/08/27 09:41:17 OK 20251218171726_add_pins.sql (86.76ms)1447--- PASS: TestReadProxyConditionalGet (2.08s)1448=== CONT TestService_cleanupPendingClosuresHandler14492026/08/27 09:41:17 OK 20260628120000_add_object_size_and_stats.sql (47.41ms)14502026/08/27 09:41:17 goose: successfully migrated database to version: 2026062812000014512026/08/27 09:41:17 OK 1_commit_pending_closure.sql (8.62ms)14522026/08/27 09:41:17 OK 2_object_stats_trigger.sql (338.29µs)14532026/08/27 09:41:17 goose: up to current file version: 21454--- PASS: TestNARDeduplicationMetadataUploadBug (3.66s)1455=== CONT TestUploadHandlersRejectInvalidKeys1456=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1457=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1458=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1459=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1460=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1461=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1462=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1463=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1464=== CONT TestCompletedNarNotReofferedAcrossClosures14652026/08/27 09:41:17 OK 20241026095416_initial_model.sql (333.26ms)14662026/08/27 09:41:17 OK 20251210153512_drop_unused_gin_index.sql (12.14ms)1467--- PASS: TestReadProxyHead (2.39s)1468=== CONT TestReadProxy40414692026/08/27 09:41:17 OK 20251218171726_add_pins.sql (42.09ms)14702026/08/27 09:41:17 INFO Received uploads request method=POST path=/api/pending_closures14712026/08/27 09:41:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14722026/08/27 09:41:17 OK 20260628120000_add_object_size_and_stats.sql (73.56ms)14732026/08/27 09:41:17 goose: successfully migrated database to version: 2026062812000014742026/08/27 09:41:17 OK 1_commit_pending_closure.sql (27.69ms)14752026/08/27 09:41:17 OK 2_object_stats_trigger.sql (296.92µs)14762026/08/27 09:41:17 goose: up to current file version: 214772026/08/27 09:41:17 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjNmYmQxYTgtZmNhNC00NDYwLWI0MTctODBlMTUxZDk5NWUyLjI0NDY3Nzc4LTQ2MTQtNDg3ZS1iMjI2LTQwMmU1YmZmNTZjZXgxNzg3ODIzNjc1MzQxMzYzMDAw parts=121478--- PASS: TestRedundantMultipartUpload (4.38s)1479=== CONT TestIsValidUploadKey/narinfo1480=== CONT TestIsValidUploadKey/realisation_plus_in_output1481=== CONT TestIsValidUploadKey/unknown_type1482=== CONT TestIsValidUploadKey/empty_key1483=== CONT TestIsValidUploadKey/absolute1484=== CONT TestIsValidUploadKey/traversal_nar1485=== CONT TestIsValidUploadKey/traversal1486=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1487=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1488=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1489=== CONT TestIsValidUploadKey/index.html1490=== CONT TestIsValidUploadKey/nix-cache-info1491=== CONT TestIsValidUploadKey/build_log_home-manager_file1492=== CONT TestIsValidUploadKey/realisation1493=== CONT TestIsValidUploadKey/build_log_equals1494=== CONT TestIsValidUploadKey/build_log_question_mark1495=== CONT TestIsValidUploadKey/build_log_plus_in_name1496=== CONT TestIsValidUploadKey/nar_plain1497=== CONT TestIsValidUploadKey/build_log1498=== CONT TestIsValidUploadKey/listing1499=== CONT TestIsValidUploadKey/nar_xz1500=== CONT TestIsValidUploadKey/nar_zst1501--- PASS: TestIsValidUploadKey (0.00s)1502 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1503 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1504 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1505 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1506 --- PASS: TestIsValidUploadKey/absolute (0.00s)1507 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1508 --- PASS: TestIsValidUploadKey/traversal (0.00s)1509 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1510 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1511 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1512 --- PASS: TestIsValidUploadKey/index.html (0.00s)1513 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1514 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1515 --- PASS: TestIsValidUploadKey/realisation (0.00s)1516 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1517 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1518 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1519 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1520 --- PASS: TestIsValidUploadKey/build_log (0.00s)1521 --- PASS: TestIsValidUploadKey/listing (0.00s)1522 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1523 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1524=== CONT TestClientErrorHandling/InvalidStorePath15252026/08/27 09:41:17 INFO Received uploads request method=POST path=/api/pending_closures15262026/08/27 09:41:17 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst15272026/08/27 09:41:17 INFO Received uploads request method=POST path=/api/pending_closures1528--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.57s)1529=== CONT TestClientErrorHandling/ServerNotAvailable15302026/08/27 09:41:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15312026-08-27 09:41:17.880 UTC [44241] ERROR: relation "goose_db_version" does not exist at character 3615322026-08-27 09:41:17.880 UTC [44241] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15332026-08-27 09:41:18.062 UTC [44266] ERROR: relation "goose_db_version" does not exist at character 3615342026-08-27 09:41:18.062 UTC [44266] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15352026/08/27 09:41:18 OK 20241026095416_initial_model.sql (99.86ms)15362026/08/27 09:41:18 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-config15372026/08/27 09:41:18 OK 20251210153512_drop_unused_gin_index.sql (4.08ms)15382026/08/27 09:41:18 OK 20251218171726_add_pins.sql (28.14ms)15392026-08-27 09:41:18.136 UTC [44275] ERROR: relation "goose_db_version" does not exist at character 3615402026-08-27 09:41:18.136 UTC [44275] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15412026/08/27 09:41:18 OK 20260628120000_add_object_size_and_stats.sql (33.51ms)15422026/08/27 09:41:18 goose: successfully migrated database to version: 2026062812000015432026/08/27 09:41:18 OK 1_commit_pending_closure.sql (3.94ms)15442026/08/27 09:41:18 OK 2_object_stats_trigger.sql (703.88µs)15452026/08/27 09:41:18 goose: up to current file version: 215462026/08/27 09:41:18 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=192.887973ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config15472026/08/27 09:41:18 OK 20241026095416_initial_model.sql (211.04ms)15482026/08/27 09:41:18 OK 20251210153512_drop_unused_gin_index.sql (8.38ms)15492026/08/27 09:41:18 OK 20251218171726_add_pins.sql (49.3ms)15502026/08/27 09:41:18 OK 20260628120000_add_object_size_and_stats.sql (21.22ms)15512026/08/27 09:41:18 goose: successfully migrated database to version: 2026062812000015522026/08/27 09:41:18 OK 20241026095416_initial_model.sql (186.5ms)15532026/08/27 09:41:18 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=407.514739ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config15542026/08/27 09:41:18 OK 20251210153512_drop_unused_gin_index.sql (13.34ms)15552026/08/27 09:41:18 OK 1_commit_pending_closure.sql (24.02ms)15562026/08/27 09:41:18 OK 2_object_stats_trigger.sql (5.31ms)15572026/08/27 09:41:18 goose: up to current file version: 215582026/08/27 09:41:18 OK 20251218171726_add_pins.sql (37.43ms)15592026/08/27 09:41:18 OK 20260628120000_add_object_size_and_stats.sql (63.49ms)15602026/08/27 09:41:18 goose: successfully migrated database to version: 2026062812000015612026/08/27 09:41:18 OK 1_commit_pending_closure.sql (8.79ms)15622026/08/27 09:41:18 OK 2_object_stats_trigger.sql (575.33µs)15632026/08/27 09:41:18 goose: up to current file version: 21564--- PASS: TestService_Rustfstest (2.93s)1565=== CONT TestClientErrorHandling/InvalidAuthToken1566--- PASS: TestReadProxyInvalidPath (2.94s)1567=== CONT TestCacheConfigHandler/full_config,_no_issuer1568=== CONT TestCacheConfigHandler/no_signing_keys1569=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1570=== CONT TestCacheConfigHandler/no_cache_url_configured1571--- PASS: TestCacheConfigHandler (0.00s)1572 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1573 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1574 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1575 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1576=== CONT TestIsValidCachePath/narinfo1577=== CONT TestIsValidCachePath/index.html1578=== CONT TestIsValidCachePath/nix-cache-info1579=== CONT TestIsValidCachePath/realisation1580=== CONT TestIsValidCachePath/log1581=== CONT TestIsValidCachePath/ls1582=== CONT TestIsValidCachePath/nar_uncompressed1583=== CONT TestIsValidCachePath/nar_bz21584=== CONT TestIsValidCachePath/nar_xz1585=== CONT TestIsValidCachePath/nar_zst1586=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1587=== CONT TestIsValidCachePath/empty1588=== CONT TestIsValidCachePath/traversal_parent1589=== CONT TestIsValidCachePath/random_path1590=== CONT TestIsValidCachePath/invalid_char_u1591=== CONT TestIsValidCachePath/invalid_char_e1592=== CONT TestIsValidCachePath/traversal_in_middle1593=== CONT TestIsValidCachePath/wrong_extension1594=== CONT TestIsValidCachePath/short_hash1595=== CONT TestIsValidCachePath/leading_slash1596--- PASS: TestIsValidCachePath (0.00s)1597 --- PASS: TestIsValidCachePath/narinfo (0.00s)1598 --- PASS: TestIsValidCachePath/index.html (0.00s)1599 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1600 --- PASS: TestIsValidCachePath/realisation (0.00s)1601 --- PASS: TestIsValidCachePath/log (0.00s)1602 --- PASS: TestIsValidCachePath/ls (0.00s)1603 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1604 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1605 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1606 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1607 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1608 --- PASS: TestIsValidCachePath/empty (0.00s)1609 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1610 --- PASS: TestIsValidCachePath/random_path (0.00s)1611 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1612 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1613 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1614 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1615 --- PASS: TestIsValidCachePath/short_hash (0.00s)1616 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1617=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token16182026/08/27 09:41:18 INFO OIDC auth successful provider=test1619=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected16202026/08/27 09:41:18 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]1621=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1622=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected16232026/08/27 09:41:18 WARN Authentication failed token_preview=eyJhbGciOi...8OQiX_sA1w token_length=702 oidc_error="bound claims validation failed: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1624=== CONT TestParseSingleRange/none1625=== CONT TestServerTLSConfig/no_client_CA1626=== CONT TestParseSingleRange/start_far_past_EOF1627=== CONT TestParseSingleRange/start_past_EOF1628=== CONT TestParseSingleRange/single_byte1629=== CONT TestParseSingleRange/suffix_exceeds_size1630=== CONT TestParseSingleRange/suffix1631=== CONT TestParseSingleRange/end_clamped_to_size1632=== CONT TestParseSingleRange/open-ended1633=== CONT TestParseSingleRange/closed1634=== CONT TestParseSingleRange/malformed_end_before_start1635=== CONT TestParseSingleRange/malformed_both_empty1636=== CONT TestParseSingleRange/malformed_no_dash1637=== CONT TestParseSingleRange/multi-range_ignored1638=== CONT TestParseSingleRange/unknown_unit1639--- PASS: TestParseSingleRange (0.00s)1640 --- PASS: TestParseSingleRange/none (0.00s)1641 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1642 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1643 --- PASS: TestParseSingleRange/single_byte (0.00s)1644 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1645 --- PASS: TestParseSingleRange/suffix (0.00s)1646 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1647 --- PASS: TestParseSingleRange/open-ended (0.00s)1648 --- PASS: TestParseSingleRange/closed (0.00s)1649 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1650 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1651 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1652 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1653 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1654=== CONT TestServerTLSConfig/not_a_PEM_file1655--- PASS: TestService_AuthMiddleware_OIDC (1.86s)1656 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1657 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1658 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1659 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1660=== CONT TestServerTLSConfig/missing_CA_file1661--- PASS: TestServerTLSConfig (0.00s)1662 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1663 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.05s)1664 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1665=== CONT TestProxyWriteTimeout/narinfo1666=== CONT TestProxyWriteTimeout/10_GiB_nar1667=== CONT TestProxyWriteTimeout/unknown_size1668=== CONT TestProxyWriteTimeout/1_GiB_nar1669--- PASS: TestProxyWriteTimeout (0.00s)1670 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1671 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1672 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1673 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1674=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16752026/08/27 09:41:18 INFO Received complete multipart upload request method=POST path=/16762026/08/27 09:41:18 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=757.488707ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1677=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16782026/08/27 09:41:18 INFO Received request for more parts method=POST path=/1679=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16802026/08/27 09:41:18 INFO Received uploads request method=POST path=/1681--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)1682 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1683 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1684 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.46s)1685=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16862026/08/27 09:41:19 INFO Received uploads request method=POST path=/1687=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16882026/08/27 09:41:19 INFO Received complete multipart upload request method=POST path=/1689=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16902026/08/27 09:41:19 INFO Received request for more parts method=POST path=/1691=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16922026/08/27 09:41:19 INFO Received uploads request method=POST path=/1693--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1694 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1695 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1696 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1697 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1698=== NAME TestOrphanedObjectsGC1699 orphaned_objects_gc_test.go:290: GC Test Summary:1700 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1701 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1702 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1703 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1704 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1705--- PASS: TestOrphanedObjectsGC (4.28s)17062026-08-27 09:41:19.560 UTC [44363] ERROR: relation "goose_db_version" does not exist at character 3617072026-08-27 09:41:19.560 UTC [44363] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17082026/08/27 09:41:19 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.72015636s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17092026-08-27 09:41:19.605 UTC [44365] ERROR: relation "goose_db_version" does not exist at character 3617102026-08-27 09:41:19.605 UTC [44365] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17112026-08-27 09:41:19.625 UTC [44367] ERROR: relation "goose_db_version" does not exist at character 3617122026-08-27 09:41:19.625 UTC [44367] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17132026-08-27 09:41:19.689 UTC [44368] ERROR: relation "goose_db_version" does not exist at character 3617142026-08-27 09:41:19.689 UTC [44368] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17152026/08/27 09:41:19 OK 20241026095416_initial_model.sql (110.54ms)17162026/08/27 09:41:19 OK 20251210153512_drop_unused_gin_index.sql (8.72ms)17172026/08/27 09:41:19 OK 20251218171726_add_pins.sql (27.03ms)17182026/08/27 09:41:19 OK 20241026095416_initial_model.sql (139.84ms)17192026/08/27 09:41:19 OK 20251210153512_drop_unused_gin_index.sql (13.92ms)17202026/08/27 09:41:19 OK 20260628120000_add_object_size_and_stats.sql (30.86ms)17212026/08/27 09:41:19 goose: successfully migrated database to version: 2026062812000017222026/08/27 09:41:19 OK 20241026095416_initial_model.sql (109.81ms)17232026/08/27 09:41:19 OK 1_commit_pending_closure.sql (3.25ms)17242026/08/27 09:41:19 OK 2_object_stats_trigger.sql (560.63µs)17252026/08/27 09:41:19 goose: up to current file version: 217262026/08/27 09:41:19 OK 20251210153512_drop_unused_gin_index.sql (9.37ms)17272026/08/27 09:41:19 OK 20251218171726_add_pins.sql (22.9ms)17282026/08/27 09:41:19 OK 20251218171726_add_pins.sql (52.64ms)17292026/08/27 09:41:19 OK 20260628120000_add_object_size_and_stats.sql (48.79ms)17302026/08/27 09:41:19 goose: successfully migrated database to version: 2026062812000017312026/08/27 09:41:19 OK 1_commit_pending_closure.sql (10.71ms)17322026/08/27 09:41:19 OK 2_object_stats_trigger.sql (426.83µs)17332026/08/27 09:41:19 goose: up to current file version: 217342026/08/27 09:41:19 OK 20260628120000_add_object_size_and_stats.sql (23.78ms)17352026/08/27 09:41:19 goose: successfully migrated database to version: 2026062812000017362026/08/27 09:41:19 OK 1_commit_pending_closure.sql (15.47ms)17372026/08/27 09:41:19 OK 2_object_stats_trigger.sql (672.83µs)17382026/08/27 09:41:19 goose: up to current file version: 217392026/08/27 09:41:19 OK 20241026095416_initial_model.sql (182.37ms)17402026/08/27 09:41:19 OK 20251210153512_drop_unused_gin_index.sql (9.76ms)17412026/08/27 09:41:19 OK 20251218171726_add_pins.sql (14.41ms)17422026/08/27 09:41:19 OK 20260628120000_add_object_size_and_stats.sql (45.19ms)17432026/08/27 09:41:19 goose: successfully migrated database to version: 2026062812000017442026/08/27 09:41:19 OK 1_commit_pending_closure.sql (9.37ms)17452026/08/27 09:41:19 OK 2_object_stats_trigger.sql (584.13µs)17462026/08/27 09:41:19 goose: up to current file version: 217472026/08/27 09:41:19 INFO Received uploads request method=POST path=/api/pending_closures17482026/08/27 09:41:20 INFO Received cleanup request method=DELETE path=/api/pending_closures17492026/08/27 09:41:20 INFO Aborted multipart uploads count=017502026/08/27 09:41:20 INFO Received uploads request method=POST path=/api/pending_closures17512026/08/27 09:41:20 INFO Received cleanup request method=DELETE path=/api/pending_closures17522026/08/27 09:41:20 INFO Aborted multipart uploads count=117532026/08/27 09:41:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17542026-08-27 09:41:20.245 UTC [44365] ERROR: Closure does not exist: id=117552026-08-27 09:41:20.245 UTC [44365] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE17562026-08-27 09:41:20.245 UTC [44365] STATEMENT: -- name: CommitPendingClosure :exec1757 SELECT commit_pending_closure($1::bigint)1758 1759--- PASS: TestService_cleanupPendingClosuresHandler (3.24s)1760--- PASS: TestReadProxy404 (3.14s)17612026-08-27 09:41:20.580 UTC [44376] ERROR: relation "goose_db_version" does not exist at character 3617622026-08-27 09:41:20.580 UTC [44376] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17632026/08/27 09:41:20 OK 20241026095416_initial_model.sql (143.97ms)17642026/08/27 09:41:20 OK 20251210153512_drop_unused_gin_index.sql (13.7ms)17652026/08/27 09:41:20 OK 20251218171726_add_pins.sql (14.52ms)17662026/08/27 09:41:20 OK 20260628120000_add_object_size_and_stats.sql (26.01ms)17672026/08/27 09:41:20 goose: successfully migrated database to version: 2026062812000017682026/08/27 09:41:20 OK 1_commit_pending_closure.sql (9.06ms)17692026/08/27 09:41:20 OK 2_object_stats_trigger.sql (226.13µs)17702026/08/27 09:41:20 goose: up to current file version: 217712026/08/27 09:41:21 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"17722026/08/27 09:41:21 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_closures17732026/08/27 09:41:21 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17742026/08/27 09:41:21 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"17752026/08/27 09:41:21 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=216.731514ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17762026/08/27 09:41:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17772026/08/27 09:41:21 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=372.598226ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17782026/08/27 09:41:21 WARN Rate limiter enabled after throttle name=s3-test rate=517792026/08/27 09:41:21 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1780=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1781 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101782 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001783--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.59s)17842026/08/27 09:41:21 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YjNmYmQxYTgtZmNhNC00NDYwLWI0MTctODBlMTUxZDk5NWUyLjYzMDg0YTU2LWY1MDgtNGMyMS05MTI1LTYyYjkxYmI5NGQzNXgxNzg3ODIzNjgwMDI1OTUyMDAw parts=1217852026/08/27 09:41:21 INFO Received uploads request method=POST path=/api/pending_closures1786--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.64s)17872026/08/27 09:41:22 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=744.439168ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures17882026/08/27 09:41:22 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.675127131s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1789--- PASS: TestClientErrorHandling (0.00s)1790 --- PASS: TestClientErrorHandling/InvalidStorePath (2.82s)1791 --- PASS: TestClientErrorHandling/InvalidAuthToken (2.82s)1792 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.82s)1793=== NAME TestOrphanedObjectsGCStressTest1794 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1795 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1796 orphaned_objects_gc_test.go:509: Stress test completed successfully:1797 orphaned_objects_gc_test.go:510: - Active objects preserved: 201798 orphaned_objects_gc_test.go:511: - Objects deleted: 2101799 orphaned_objects_gc_test.go:512: - Total GC'd: 2101800--- PASS: TestOrphanedObjectsGCStressTest (11.33s)1801PASS18022026-08-27 09:41:25.703 UTC [43439] LOG: received smart shutdown request18032026-08-27 09:41:25.703 UTC [43439] LOG: background worker "logical replication launcher" (PID 43449) exited with exit code 118042026-08-27 09:41:25.725 UTC [43444] LOG: shutting down18052026-08-27 09:41:25.725 UTC [43444] LOG: checkpoint starting: shutdown immediate18062026-08-27 09:41:26.945 UTC [43444] LOG: checkpoint complete: wrote 13558 buffers (82.8%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 13 recycled; write=0.803 s, sync=0.415 s, total=1.220 s; sync files=15167, longest=0.008 s, average=0.001 s; distance=212549 kB, estimate=212549 kB; lsn=0/E71C4F8, redo lsn=0/E71C4F818072026-08-27 09:41:26.950 UTC [43439] LOG: database system is shut down1808Running OIDC tests...1809=== RUN TestGlobMatch1810=== PAUSE TestGlobMatch1811=== RUN TestAudienceForIssuer1812=== PAUSE TestAudienceForIssuer1813=== RUN TestValidateToken_ValidToken1814=== PAUSE TestValidateToken_ValidToken1815=== RUN TestValidateToken_WrongAudience1816=== PAUSE TestValidateToken_WrongAudience1817=== RUN TestValidateToken_Expired1818=== PAUSE TestValidateToken_Expired1819=== RUN TestValidateToken_BoundClaimsMismatch1820=== PAUSE TestValidateToken_BoundClaimsMismatch1821=== RUN TestValidateToken_BoundSubjectMismatch1822=== PAUSE TestValidateToken_BoundSubjectMismatch1823=== RUN TestValidateToken_MultipleProviders1824=== PAUSE TestValidateToken_MultipleProviders1825=== RUN TestValidateToken_NoMatchingProvider1826=== PAUSE TestValidateToken_NoMatchingProvider1827=== CONT TestGlobMatch1828=== RUN TestGlobMatch/foo_foo1829=== PAUSE TestGlobMatch/foo_foo1830=== RUN TestGlobMatch/foo_bar1831=== PAUSE TestGlobMatch/foo_bar1832=== RUN TestGlobMatch/*_1833=== PAUSE TestGlobMatch/*_1834=== RUN TestGlobMatch/*_anything1835=== PAUSE TestGlobMatch/*_anything1836=== RUN TestGlobMatch/foo*_foo1837=== PAUSE TestGlobMatch/foo*_foo1838=== RUN TestGlobMatch/foo*_foobar1839=== PAUSE TestGlobMatch/foo*_foobar1840=== RUN TestGlobMatch/foo*_bar1841=== PAUSE TestGlobMatch/foo*_bar1842=== CONT TestValidateToken_BoundClaimsMismatch1843=== CONT TestValidateToken_WrongAudience1844=== RUN TestGlobMatch/*bar_bar1845=== PAUSE TestGlobMatch/*bar_bar1846=== RUN TestGlobMatch/*bar_foobar1847=== PAUSE TestGlobMatch/*bar_foobar1848=== RUN TestGlobMatch/*bar_foo1849=== PAUSE TestGlobMatch/*bar_foo1850=== RUN TestGlobMatch/foo*bar_foobar1851=== PAUSE TestGlobMatch/foo*bar_foobar1852=== RUN TestGlobMatch/foo*bar_foo123bar1853=== PAUSE TestGlobMatch/foo*bar_foo123bar1854=== RUN TestGlobMatch/foo*bar_foobarbaz1855=== PAUSE TestGlobMatch/foo*bar_foobarbaz1856=== RUN TestGlobMatch/*/*_foo/bar1857=== PAUSE TestGlobMatch/*/*_foo/bar1858=== RUN TestGlobMatch/*/*_foo1859=== PAUSE TestGlobMatch/*/*_foo1860=== RUN TestGlobMatch/refs/heads/*_refs/heads/main1861=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main1862=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.01863=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.01864=== RUN TestGlobMatch/refs/*/main_refs/heads/main1865=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main1866=== RUN TestGlobMatch/fo?_foo1867=== PAUSE TestGlobMatch/fo?_foo1868=== RUN TestGlobMatch/fo?_fo1869=== PAUSE TestGlobMatch/fo?_fo1870=== RUN TestGlobMatch/fo?_fooo1871=== PAUSE TestGlobMatch/fo?_fooo1872=== RUN TestGlobMatch/?oo_foo1873=== PAUSE TestGlobMatch/?oo_foo1874=== RUN TestGlobMatch/?oo_boo1875=== CONT TestValidateToken_ValidToken1876=== CONT TestValidateToken_Expired1877=== CONT TestValidateToken_MultipleProviders1878=== CONT TestValidateToken_NoMatchingProvider1879=== CONT TestValidateToken_BoundSubjectMismatch1880=== PAUSE TestGlobMatch/?oo_boo1881=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1882=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1883=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1884=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1885=== CONT TestGlobMatch/foo_foo1886=== CONT TestAudienceForIssuer1887--- PASS: TestAudienceForIssuer (0.00s)1888=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main1889=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main1890=== CONT TestGlobMatch/?oo_boo1891=== CONT TestGlobMatch/?oo_foo1892=== CONT TestGlobMatch/fo?_fooo1893=== CONT TestGlobMatch/fo?_fo1894=== CONT TestGlobMatch/fo?_foo1895=== CONT TestGlobMatch/refs/*/main_refs/heads/main1896=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.01897=== CONT TestGlobMatch/refs/heads/*_refs/heads/main1898=== CONT TestGlobMatch/*/*_foo1899=== CONT TestGlobMatch/*/*_foo/bar1900=== CONT TestGlobMatch/foo*bar_foobarbaz1901=== CONT TestGlobMatch/foo*bar_foo123bar1902=== CONT TestGlobMatch/foo*bar_foobar1903=== CONT TestGlobMatch/*bar_foo1904=== CONT TestGlobMatch/*bar_foobar1905=== CONT TestGlobMatch/*bar_bar1906=== CONT TestGlobMatch/foo*_bar1907=== CONT TestGlobMatch/foo*_foobar1908=== CONT TestGlobMatch/foo*_foo1909=== CONT TestGlobMatch/*_anything1910=== CONT TestGlobMatch/*_1911=== CONT TestGlobMatch/foo_bar1912--- PASS: TestGlobMatch (0.00s)1913 --- PASS: TestGlobMatch/foo_foo (0.00s)1914 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)1915 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)1916 --- PASS: TestGlobMatch/?oo_boo (0.00s)1917 --- PASS: TestGlobMatch/?oo_foo (0.00s)1918 --- PASS: TestGlobMatch/fo?_fooo (0.00s)1919 --- PASS: TestGlobMatch/fo?_fo (0.00s)1920 --- PASS: TestGlobMatch/fo?_foo (0.00s)1921 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)1922 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)1923 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)1924 --- PASS: TestGlobMatch/*/*_foo (0.00s)1925 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)1926 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)1927 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)1928 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)1929 --- PASS: TestGlobMatch/*bar_foo (0.00s)1930 --- PASS: TestGlobMatch/*bar_foobar (0.00s)1931 --- PASS: TestGlobMatch/*bar_bar (0.00s)1932 --- PASS: TestGlobMatch/foo*_bar (0.00s)1933 --- PASS: TestGlobMatch/foo*_foobar (0.00s)1934 --- PASS: TestGlobMatch/foo*_foo (0.00s)1935 --- PASS: TestGlobMatch/*_anything (0.00s)1936 --- PASS: TestGlobMatch/*_ (0.00s)1937 --- PASS: TestGlobMatch/foo_bar (0.00s)19382026/08/27 09:41:27 INFO OIDC provider initialized name=test19392026/08/27 09:41:27 INFO OIDC provider initialized name=test19402026/08/27 09:41:27 INFO OIDC provider initialized name=test19412026/08/27 09:41:27 INFO OIDC provider initialized name=test19422026/08/27 09:41:27 INFO OIDC provider initialized name=provider119432026/08/27 09:41:27 INFO OIDC provider initialized name=test19442026/08/27 09:41:27 INFO OIDC provider initialized name=provider119452026/08/27 09:41:27 INFO OIDC provider initialized name=provider21946--- PASS: TestValidateToken_NoMatchingProvider (0.00s)1947--- PASS: TestValidateToken_Expired (0.00s)1948--- PASS: TestValidateToken_BoundSubjectMismatch (0.00s)1949--- PASS: TestValidateToken_BoundClaimsMismatch (0.00s)1950--- PASS: TestValidateToken_MultipleProviders (0.00s)1951--- PASS: TestValidateToken_WrongAudience (0.00s)1952--- PASS: TestValidateToken_ValidToken (0.00s)1953PASS1954Running hook tests...1955=== RUN TestSendPathsEmpty1956=== PAUSE TestSendPathsEmpty1957=== RUN TestQueueEnqueueAndFetch1958=== PAUSE TestQueueEnqueueAndFetch1959=== RUN TestQueueDeduplication1960=== PAUSE TestQueueDeduplication1961=== RUN TestQueueRemove1962=== PAUSE TestQueueRemove1963=== RUN TestQueueFetchBatchLimit1964=== PAUSE TestQueueFetchBatchLimit1965=== RUN TestQueueRetryMovesToBack1966=== PAUSE TestQueueRetryMovesToBack1967=== RUN TestQueueFetchRemoveLifecycle1968=== PAUSE TestQueueFetchRemoveLifecycle1969=== RUN TestQueueConcurrentWriters1970=== PAUSE TestQueueConcurrentWriters1971=== RUN TestQueueRemoveLargeClosure1972=== PAUSE TestQueueRemoveLargeClosure1973=== RUN TestServerClientIntegration1974=== PAUSE TestServerClientIntegration1975=== RUN TestServerQueueError1976=== PAUSE TestServerQueueError1977=== RUN TestGetListenerSocketActivation1978 server_test.go:210: === RUN TestGetListenerSocketActivation1979 --- PASS: TestGetListenerSocketActivation (0.00s)1980 PASS1981 1982--- PASS: TestGetListenerSocketActivation (0.01s)1983=== RUN TestDrainIsolatesPoisonPath1984=== PAUSE TestDrainIsolatesPoisonPath1985=== RUN TestRunNotBlockedByPoisonHead1986=== PAUSE TestRunNotBlockedByPoisonHead1987=== RUN TestDrainGivesUpWhenServerDown1988=== PAUSE TestDrainGivesUpWhenServerDown1989=== RUN TestFailedPathPrunedByLaterClosure1990=== PAUSE TestFailedPathPrunedByLaterClosure1991=== RUN TestWorkerUploadsAndRemoves1992=== PAUSE TestWorkerUploadsAndRemoves1993=== RUN TestWorkerSkipsGCdPaths1994=== PAUSE TestWorkerSkipsGCdPaths1995=== RUN TestWorkerPrunesClosureDeps1996=== PAUSE TestWorkerPrunesClosureDeps1997=== CONT TestSendPathsEmpty1998=== CONT TestServerClientIntegration1999=== CONT TestQueueEnqueueAndFetch2000=== CONT TestFailedPathPrunedByLaterClosure2001--- PASS: TestSendPathsEmpty (0.00s)2002=== CONT TestQueueRemoveLargeClosure2003=== CONT TestQueueConcurrentWriters2004=== CONT TestQueueFetchRemoveLifecycle2005=== CONT TestQueueRetryMovesToBack2006=== CONT TestQueueFetchBatchLimit2007=== CONT TestQueueRemove2008=== CONT TestQueueDeduplication2009--- PASS: TestServerClientIntegration (0.00s)2010=== CONT TestRunNotBlockedByPoisonHead2011--- PASS: TestQueueFetchBatchLimit (0.01s)2012=== CONT TestDrainGivesUpWhenServerDown20132026/08/27 09:41:28 INFO Uploading batch count=120142026/08/27 09:41:28 ERROR Upload failed error="upload failed" count=120152026/08/27 09:41:28 INFO Upload queue status pending=320162026/08/27 09:41:28 INFO Uploading batch count=120172026/08/27 09:41:28 INFO Uploading batch count=120182026/08/27 09:41:28 ERROR Upload failed error="upload failed" count=120192026/08/27 09:41:28 INFO Uploading batch count=12020--- PASS: TestQueueEnqueueAndFetch (0.01s)2021=== CONT TestWorkerSkipsGCdPaths2022--- PASS: TestQueueDeduplication (0.01s)2023=== CONT TestWorkerPrunesClosureDeps2024--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2025=== CONT TestWorkerUploadsAndRemoves2026=== CONT TestDrainIsolatesPoisonPath2027=== CONT TestServerQueueError2028--- PASS: TestQueueRetryMovesToBack (0.01s)2029--- PASS: TestQueueRemove (0.01s)2030--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)20312026/08/27 09:41:28 ERROR Failed to queue paths error="permission denied" count=120322026/08/27 09:41:28 INFO Upload queue status pending=220332026/08/27 09:41:28 INFO Uploading batch count=120342026/08/27 09:41:28 INFO Upload queue status pending=22035--- PASS: TestServerQueueError (0.00s)20362026/08/27 09:41:28 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-42860-2089741757/TestWorkerSkipsGCdPaths1786005935/002/nonexistent20372026/08/27 09:41:28 INFO Uploading batch count=220382026/08/27 09:41:28 ERROR Upload failed error="upload failed" count=220392026/08/27 09:41:28 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-42860-2089741757/TestDrainGivesUpWhenServerDown4049897593/002/a20402026/08/27 09:41:28 INFO Uploading batch count=120412026/08/27 09:41:28 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-42860-2089741757/TestDrainGivesUpWhenServerDown4049897593/002/b20422026/08/27 09:41:28 INFO Uploading batch count=420432026/08/27 09:41:28 ERROR Upload failed error="upload failed" count=420442026/08/27 09:41:28 INFO Uploading batch count=220452026/08/27 09:41:28 ERROR Upload failed error="upload failed" count=220462026/08/27 09:41:28 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-42860-2089741757/TestDrainGivesUpWhenServerDown4049897593/002/c20472026/08/27 09:41:28 INFO Upload queue status pending=220482026/08/27 09:41:28 INFO Uploading batch count=220492026/08/27 09:41:28 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-42860-2089741757/TestDrainIsolatesPoisonPath511475432/002/bbb20502026/08/27 09:41:28 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-42860-2089741757/TestDrainGivesUpWhenServerDown4049897593/002/d20512026/08/27 09:41:28 INFO Uploading batch count=220522026/08/27 09:41:28 ERROR Upload failed error="upload failed" count=220532026/08/27 09:41:28 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-42860-2089741757/TestDrainGivesUpWhenServerDown4049897593/002/e20542026/08/27 09:41:28 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-42860-2089741757/TestDrainGivesUpWhenServerDown4049897593/002/f20552026/08/27 09:41:28 INFO Uploading batch count=120562026/08/27 09:41:28 ERROR Upload failed error="upload failed" count=120572026/08/27 09:41:28 ERROR Drain finished with paths left in queue remaining=1020582026/08/27 09:41:28 INFO Uploading batch count=120592026/08/27 09:41:28 ERROR Upload failed error="upload failed" count=120602026/08/27 09:41:28 INFO Uploading batch count=120612026/08/27 09:41:28 ERROR Upload failed error="upload failed" count=120622026/08/27 09:41:28 ERROR Drain finished with paths left in queue remaining=12063--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2064--- PASS: TestDrainIsolatesPoisonPath (0.00s)2065--- PASS: TestWorkerSkipsGCdPaths (0.02s)2066--- PASS: TestWorkerPrunesClosureDeps (0.02s)2067--- PASS: TestWorkerUploadsAndRemoves (0.02s)2068--- PASS: TestQueueRemoveLargeClosure (0.05s)2069--- PASS: TestQueueConcurrentWriters (0.12s)20702026/08/27 09:41:29 INFO Uploading batch count=120712026/08/27 09:41:29 INFO Uploading batch count=120722026/08/27 09:41:29 INFO Uploading batch count=120732026/08/27 09:41:29 ERROR Upload failed error="upload failed" count=120742026/08/27 09:41:29 INFO Uploading batch count=120752026/08/27 09:41:29 ERROR Upload failed error="upload failed" count=120762026/08/27 09:41:29 INFO Uploading batch count=120772026/08/27 09:41:29 ERROR Upload failed error="upload failed" count=120782026/08/27 09:41:29 INFO Uploading batch count=120792026/08/27 09:41:29 ERROR Upload failed error="upload failed" count=120802026/08/27 09:41:29 ERROR Drain finished with paths left in queue remaining=12081--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2082PASS