niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #178
· 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 TestResolveStorePath74=== CONT TestEncodeNixBase32WithRealHash75=== CONT TestDumpPathMatchesNix76--- PASS: TestEncodeNixBase32WithRealHash (0.00s)77=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess78=== CONT TestPartSizeForNAR79=== RUN TestPartSizeForNAR/zero_stays_at_minimum80=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum81=== RUN TestPartSizeForNAR/small_stays_at_minimum82=== PAUSE TestPartSizeForNAR/small_stays_at_minimum83=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum84=== CONT TestFilterOversizedClosures85=== RUN TestFilterOversizedClosures/no_limit_keeps_everything86=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything87=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped882026/09/01 08:25:59 WARN Rate limiter enabled after throttle name=server-test rate=589=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped90=== RUN TestFilterOversizedClosures/all_closures_skipped91=== PAUSE TestFilterOversizedClosures/all_closures_skipped92=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum93=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts94=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts95=== RUN TestPartSizeForNAR/1_TiB96=== PAUSE TestPartSizeForNAR/1_TiB97=== RUN TestPartSizeForNAR/5_TiB_S3_max_object98=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object99=== RUN TestPartSizeForNAR/capped_at_5_GiB100=== PAUSE TestPartSizeForNAR/capped_at_5_GiB101=== CONT TestParsePathInfoJSON102=== RUN TestParsePathInfoJSON/Nix_format103=== PAUSE TestParsePathInfoJSON/Nix_format104=== RUN TestParsePathInfoJSON/Lix_format105=== PAUSE TestParsePathInfoJSON/Lix_format106=== RUN TestParsePathInfoJSON/empty_input107=== PAUSE TestParsePathInfoJSON/empty_input108=== RUN TestParsePathInfoJSON/whitespace_only109=== PAUSE TestParsePathInfoJSON/whitespace_only110=== RUN TestParsePathInfoJSON/invalid_JSON111=== PAUSE TestParsePathInfoJSON/invalid_JSON112=== CONT TestPathInfoCACompatibility113=== RUN TestPathInfoCACompatibility/null_ca_field114=== PAUSE TestPathInfoCACompatibility/null_ca_field115=== RUN TestPathInfoCACompatibility/old_string_format_-_text116=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text117=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive118=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive119=== RUN TestPathInfoCACompatibility/new_structured_format_-_text120=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text121=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method122=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method123=== CONT TestParsePathInfoJSONMultiplePaths124=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths125=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths126=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths127=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths128=== CONT TestGetStorePathHash129=== RUN TestGetStorePathHash/valid_store_path130=== PAUSE TestGetStorePathHash/valid_store_path131=== RUN TestGetStorePathHash/basename_without_hyphen_should_error132=== CONT TestUploadMultipart_SupersededByPeer133=== RUN TestUploadMultipart_SupersededByPeer/exists134=== CONT TestEncodeNixBase32135=== PAUSE TestUploadMultipart_SupersededByPeer/exists136=== CONT TestDumpPathSingleFile137=== CONT TestRateLimiterFeedback138=== RUN TestRateLimiterFeedback/429_enables_limiter139=== PAUSE TestRateLimiterFeedback/429_enables_limiter140=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error141=== CONT TestDumpPathWriterError142=== RUN TestRateLimiterFeedback/503_enables_limiter143=== PAUSE TestRateLimiterFeedback/503_enables_limiter144=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter145=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter146=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter147=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter148=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error149=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error150=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error151=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error152=== CONT TestPathInfoHashCompatibility153=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)154=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)155=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon156=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon157=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI158=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI159=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512160=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512161=== CONT TestCaseHackSuffix162=== CONT TestFileTokenMissing163=== RUN TestEncodeNixBase32/test_string_hash164=== PAUSE TestEncodeNixBase32/test_string_hash165=== RUN TestEncodeNixBase32/empty_input166=== PAUSE TestEncodeNixBase32/empty_input167=== RUN TestUploadMultipart_SupersededByPeer/missing168=== PAUSE TestUploadMultipart_SupersededByPeer/missing169=== CONT TestScriptTokenEmptyCommand170--- PASS: TestScriptTokenEmptyCommand (0.00s)171=== CONT TestScriptTokenScriptFails172--- PASS: TestResolveStorePath (0.00s)173=== CONT TestScriptTokenEmptyToken174=== CONT TestScriptTokenBadJSON175--- PASS: TestDoServerRequestAttachesToken (0.00s)176=== CONT TestScriptTokenCachesUntilRefresh177--- PASS: TestFileTokenMissing (0.00s)178=== CONT TestScriptTokenNoExpiryRerunsEveryCall179--- PASS: TestScriptTokenScriptFails (0.01s)180=== CONT TestFileTokenEmpty181--- PASS: TestFileTokenEmpty (0.00s)182=== CONT TestSetClientTLSDoesNotMutateDefaultTransport183--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)184=== CONT TestFileTokenReadsAndCaches185--- PASS: TestFileTokenReadsAndCaches (0.00s)186=== CONT TestStaticToken187--- PASS: TestStaticToken (0.00s)188=== CONT TestSetClientTLSErrors189=== RUN TestSetClientTLSErrors/missing_cert_file190=== PAUSE TestSetClientTLSErrors/missing_cert_file191=== RUN TestSetClientTLSErrors/missing_key_file192=== PAUSE TestSetClientTLSErrors/missing_key_file193=== RUN TestSetClientTLSErrors/missing_ca_file194=== PAUSE TestSetClientTLSErrors/missing_ca_file195=== RUN TestSetClientTLSErrors/invalid_ca_file196=== PAUSE TestSetClientTLSErrors/invalid_ca_file197=== CONT TestShellSplitErrors198--- PASS: TestShellSplitErrors (0.00s)199=== CONT TestSetClientTLS200--- PASS: TestScriptTokenBadJSON (0.01s)201=== CONT TestConvertHashToNix32202=== RUN TestConvertHashToNix32/SRI_format_to_Nix32203=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32204=== RUN TestConvertHashToNix32/already_Nix32_format205=== PAUSE TestConvertHashToNix32/already_Nix32_format206=== RUN TestConvertHashToNix32/invalid_format207=== PAUSE TestConvertHashToNix32/invalid_format208=== CONT TestShellSplit209--- PASS: TestShellSplit (0.00s)210=== CONT TestDoWithRetry_BodyReplayedViaGetBody211=== RUN TestSetClientTLS/rejects_connection_without_client_cert212=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert213=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA214=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA215=== RUN TestSetClientTLS/preserves_debug_logging_transport216=== PAUSE TestSetClientTLS/preserves_debug_logging_transport217=== CONT TestFilterOversizedClosures/no_limit_keeps_everything218=== CONT TestPartSizeForNAR/zero_stays_at_minimum219=== CONT TestParsePathInfoJSON/Nix_format2202026/09/01 08:25:59 WARN Rate limiter enabled after throttle name=server-test rate=52212026/09/01 08:25:59 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:60216222=== CONT TestPartSizeForNAR/5_TiB_S3_max_object223=== CONT TestPartSizeForNAR/1_TiB224=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts225=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum226=== CONT TestPartSizeForNAR/small_stays_at_minimum227=== CONT TestPathInfoCACompatibility/null_ca_field228=== CONT TestParsePathInfoJSON/invalid_JSON229=== CONT TestParsePathInfoJSON/whitespace_only230=== CONT TestParsePathInfoJSON/empty_input231=== CONT TestParsePathInfoJSON/Lix_format232--- PASS: TestParsePathInfoJSON (0.00s)233 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)234 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)235 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)236 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)237 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)238=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths2392026/09/01 08:25:59 WARN Rate limiter backed off name=server-test rate=52402026/09/01 08:25:59 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:60216241=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method242=== CONT TestPathInfoCACompatibility/new_structured_format_-_text243=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive244--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)245=== CONT TestPathInfoCACompatibility/old_string_format_-_text246=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped247--- PASS: TestPathInfoCACompatibility (0.00s)248 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)249 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)250 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)251 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)252 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)253=== CONT TestFilterOversizedClosures/all_closures_skipped2542026/09/01 08:25:59 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=502552026/09/01 08:25:59 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=2000256=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths257--- PASS: TestFilterOversizedClosures (0.00s)258 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)259 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)260 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)261=== CONT TestPartSizeForNAR/capped_at_5_GiB262--- PASS: TestPartSizeForNAR (0.00s)263 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)264 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)265 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)266 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)267 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)268 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)269 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)270--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)271 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)272 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)273=== CONT TestRateLimiterFeedback/429_enables_limiter274=== CONT TestGetStorePathHash/valid_store_path275=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)276--- PASS: TestScriptTokenEmptyToken (0.01s)277=== CONT TestGetStorePathHash/basename_without_hyphen_should_error278=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512279=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon280=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI281=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error282=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error283--- PASS: TestPathInfoHashCompatibility (0.00s)284 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)285 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)286 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)287 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)288=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter289=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2902026/09/01 08:25:59 WARN Rate limiter enabled after throttle name=server-test rate=52912026/09/01 08:25:59 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:60218292--- PASS: TestGetStorePathHash (0.00s)293 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)294 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)295 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)296 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)2972026/09/01 08:25:59 WARN Rate limiter backed off name=server-test rate=5298=== CONT TestUploadMultipart_SupersededByPeer/exists299=== CONT TestRateLimiterFeedback/503_enables_limiter300=== CONT TestEncodeNixBase32/test_string_hash301=== CONT TestEncodeNixBase32/empty_input302=== CONT TestUploadMultipart_SupersededByPeer/missing303--- PASS: TestEncodeNixBase32 (0.00s)304 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)305 --- PASS: TestEncodeNixBase32/empty_input (0.00s)3062026/09/01 08:25:59 WARN Rate limiter enabled after throttle name=server-test rate=53072026/09/01 08:25:59 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:602243082026/09/01 08:25:59 WARN Rate limiter backed off name=server-test rate=5309--- PASS: TestRateLimiterFeedback (0.00s)310 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)311 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)312 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)313 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)314=== CONT TestSetClientTLSErrors/missing_cert_file315=== CONT TestSetClientTLSErrors/missing_ca_file316=== CONT TestSetClientTLSErrors/invalid_ca_file317=== CONT TestSetClientTLSErrors/missing_key_file318=== CONT TestConvertHashToNix32/SRI_format_to_Nix32319=== CONT TestConvertHashToNix32/invalid_format320=== CONT TestSetClientTLS/rejects_connection_without_client_cert321=== CONT TestConvertHashToNix32/already_Nix32_format322--- PASS: TestConvertHashToNix32 (0.00s)323 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)324 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)325 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)326=== CONT TestSetClientTLS/preserves_debug_logging_transport327--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)328 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)329 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)330=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA331--- PASS: TestSetClientTLSErrors (0.00s)332 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)333 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)334 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)335 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)336--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)337--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)338--- PASS: TestDumpPathWriterError (0.03s)3392026/09/01 08:25:59 http: TLS handshake error from 127.0.0.1:60231: remote error: tls: bad certificate340--- PASS: TestSetClientTLS (0.00s)341 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)342 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)343 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)344--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)345--- PASS: TestDumpPathSingleFile (4.54s)346--- PASS: TestCaseHackSuffix (4.54s)347--- PASS: TestDumpPathMatchesNix (4.55s)348PASS349Running server tests...350The files belonging to this database system will be owned by user "_nixbld12".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-84290-1268021945/postgres168305403/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-84290-1268021945/postgres168305403/data -l logfile start3763772026-09-01 08:26:06.913 UTC [96650] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit3782026-09-01 08:26:06.913 UTC [96650] LOG: listening on Unix socket "/nix/var/nix/builds/nix-84290-1268021945/postgres168305403/.s.PGSQL.5432"3792026-09-01 08:26:06.919 UTC [96666] LOG: database system was shut down at 2026-09-01 08:26:06 UTC3802026-09-01 08:26:06.920 UTC [96650] LOG: database system is ready to accept connections381/nix/var/nix/builds/nix-84290-1268021945/postgres168305403:5432 - accepting connections382=== RUN TestService_AuthMiddleware383=== PAUSE TestService_AuthMiddleware384=== RUN TestService_AuthMiddleware_MTLSProxyHeader385=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader386=== RUN TestService_AuthMiddleware_MTLSBoundSubjects387=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects388=== RUN TestService_ReadAuthMiddleware389=== PAUSE TestService_ReadAuthMiddleware390=== RUN TestService_AuthMiddleware_OIDC391=== PAUSE TestService_AuthMiddleware_OIDC392=== RUN TestService_RequireScope_OIDC393=== PAUSE TestService_RequireScope_OIDC394=== RUN TestService_ReadScope_PublicByDefault395=== PAUSE TestService_ReadScope_PublicByDefault396=== RUN TestCacheConfigHandler397=== PAUSE TestCacheConfigHandler398=== RUN TestCacheStatsHandler399=== PAUSE TestCacheStatsHandler400=== RUN TestClientCADerivations401=== PAUSE TestClientCADerivations402=== RUN TestClientErrorHandling403=== PAUSE TestClientErrorHandling404=== RUN TestClientIntegration405=== PAUSE TestClientIntegration406=== RUN TestClientMultipleUploads407=== PAUSE TestClientMultipleUploads408=== RUN TestClientWithDependencies409=== PAUSE TestClientWithDependencies410=== RUN TestPinProtectsFromGC411=== PAUSE TestPinProtectsFromGC412=== RUN TestResolveDBConnectionString413=== PAUSE TestResolveDBConnectionString414=== RUN TestGCAdvisoryLockBlocksConcurrentRun4152026-09-01 08:26:09.414 UTC [97584] ERROR: relation "goose_db_version" does not exist at character 364162026-09-01 08:26:09.414 UTC [97584] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4172026/09/01 08:26:09 OK 20241026095416_initial_model.sql (15.05ms)4182026/09/01 08:26:09 OK 20251210153512_drop_unused_gin_index.sql (5.01ms)4192026/09/01 08:26:09 OK 20251218171726_add_pins.sql (4.83ms)4202026/09/01 08:26:09 OK 20260628120000_add_object_size_and_stats.sql (2.93ms)4212026/09/01 08:26:09 goose: successfully migrated database to version: 202606281200004222026/09/01 08:26:09 OK 1_commit_pending_closure.sql (1.47ms)4232026/09/01 08:26:09 OK 2_object_stats_trigger.sql (1.21ms)4242026/09/01 08:26:09 goose: up to current file version: 2425--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.85s)426=== RUN TestGCBugBareHashReferences427=== PAUSE TestGCBugBareHashReferences428=== RUN TestGCMetrics429=== PAUSE TestGCMetrics430=== RUN TestGCTaskStore_StartNew431=== PAUSE TestGCTaskStore_StartNew432=== RUN TestGCTaskStore_DeduplicateSameParams433=== PAUSE TestGCTaskStore_DeduplicateSameParams434=== RUN TestGCTaskStore_ConflictDifferentParams435=== PAUSE TestGCTaskStore_ConflictDifferentParams436=== RUN TestGCTaskStore_GetEmpty437=== PAUSE TestGCTaskStore_GetEmpty438=== RUN TestGCTaskStore_GetReturnsLatest439=== PAUSE TestGCTaskStore_GetReturnsLatest440=== RUN TestGCTaskStore_CompletedAllowsNewTask441=== PAUSE TestGCTaskStore_CompletedAllowsNewTask442=== RUN TestGCTaskStore_PhaseUpdates443=== PAUSE TestGCTaskStore_PhaseUpdates444=== RUN TestGCTaskStore_Fail445=== PAUSE TestGCTaskStore_Fail446=== RUN TestGracefulShutdownDrainsInflight447=== PAUSE TestGracefulShutdownDrainsInflight448=== RUN TestService_healthCheckHandler449=== PAUSE TestService_healthCheckHandler450=== RUN TestService_readinessHandler451=== PAUSE TestService_readinessHandler452=== RUN TestGenerateLandingPage453=== PAUSE TestGenerateLandingPage454=== RUN TestCacheConfigHandlerMaxNarSize455=== PAUSE TestCacheConfigHandlerMaxNarSize456=== RUN TestCreatePendingClosureRejectsOversizedNAR457=== PAUSE TestCreatePendingClosureRejectsOversizedNAR458=== RUN TestNARDeduplicationMetadataUploadBug459=== PAUSE TestNARDeduplicationMetadataUploadBug460=== RUN TestMetricsInventory461=== PAUSE TestMetricsInventory462=== RUN TestService_NativeMTLS463=== PAUSE TestService_NativeMTLS464=== RUN TestServerTLSConfig465=== PAUSE TestServerTLSConfig466=== RUN TestMultipartCleanup467=== PAUSE TestMultipartCleanup468=== RUN TestObjectStatsTrigger469=== PAUSE TestObjectStatsTrigger470=== RUN TestOrphanedObjectsGC471=== PAUSE TestOrphanedObjectsGC472=== RUN TestOrphanedObjectsGCStressTest473=== PAUSE TestOrphanedObjectsGCStressTest474=== RUN TestResurrectedObjectNotDeleted475=== PAUSE TestResurrectedObjectNotDeleted476=== RUN TestParseSingleRange477=== PAUSE TestParseSingleRange478=== RUN TestIsValidCachePath479=== PAUSE TestIsValidCachePath480=== RUN TestReadProxyNarinfo481=== PAUSE TestReadProxyNarinfo482=== RUN TestReadProxyNarinfoAlreadyDecompressed483=== PAUSE TestReadProxyNarinfoAlreadyDecompressed484=== RUN TestReadProxyNarStreaming485=== PAUSE TestReadProxyNarStreaming486=== RUN TestReadProxy404487=== PAUSE TestReadProxy404488=== RUN TestReadProxyInvalidPath489=== PAUSE TestReadProxyInvalidPath490=== RUN TestReadProxyHead491=== PAUSE TestReadProxyHead492=== RUN TestReadProxyConditionalGet493=== PAUSE TestReadProxyConditionalGet494=== RUN TestReadProxyRootRedirectsToIndexHTML495=== PAUSE TestReadProxyRootRedirectsToIndexHTML496=== RUN TestReadProxyDisabled497=== PAUSE TestReadProxyDisabled498=== RUN TestReadRedirectNar499=== PAUSE TestReadRedirectNar500=== RUN TestReadRedirectKeepsNarinfoProxied501=== PAUSE TestReadRedirectKeepsNarinfoProxied502=== RUN TestReadProxyRangeRequest503=== PAUSE TestReadProxyRangeRequest504=== RUN TestReadRedirectUsesPublicS3URL505=== PAUSE TestReadRedirectUsesPublicS3URL506=== RUN TestRedundantMultipartUpload507=== PAUSE TestRedundantMultipartUpload508=== RUN TestCompleteMultipartUpload_ErrorButObjectExists509=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists510=== RUN TestCompletedNarNotReofferedAcrossClosures511=== PAUSE TestCompletedNarNotReofferedAcrossClosures512=== RUN TestPresignedUploadRegisteredBeforeCommit513=== PAUSE TestPresignedUploadRegisteredBeforeCommit514=== RUN TestService_Rustfstest515=== PAUSE TestService_Rustfstest516=== RUN TestParseSize517=== PAUSE TestParseSize518=== RUN TestSkippedUploadsHandler519=== PAUSE TestSkippedUploadsHandler520=== RUN TestSystemdListenerNotActivated521--- PASS: TestSystemdListenerNotActivated (0.00s)522=== RUN TestWatchdogBeatsWhenHealthy523--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)524=== RUN TestWatchdogSkipsWhenUnhealthy5252026/09/01 08:26:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5262026/09/01 08:26:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5272026/09/01 08:26:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5282026/09/01 08:26:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5292026/09/01 08:26:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5302026/09/01 08:26:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5312026/09/01 08:26:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5322026/09/01 08:26:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5332026/09/01 08:26:09 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5342026/09/01 08:26:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"535--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)536=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle537=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle538=== RUN TestProxyWriteTimeout539=== PAUSE TestProxyWriteTimeout540=== RUN TestIsValidUploadKey541=== PAUSE TestIsValidUploadKey542=== RUN TestUploadHandlersRejectInvalidKeys543=== PAUSE TestUploadHandlersRejectInvalidKeys544=== RUN TestUploadHandlersRejectOversizedBody545=== PAUSE TestUploadHandlersRejectOversizedBody546=== RUN TestService_cleanupPendingClosuresHandler547=== PAUSE TestService_cleanupPendingClosuresHandler548=== RUN TestService_createPendingClosureHandler549=== PAUSE TestService_createPendingClosureHandler550=== RUN TestService_verifyS3Integrity551=== PAUSE TestService_verifyS3Integrity552=== RUN TestCompleteMultipartUnregistered553=== PAUSE TestCompleteMultipartUnregistered554=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT555=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT556=== CONT TestService_AuthMiddleware557=== CONT TestObjectStatsTrigger558=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT559=== CONT TestCompleteMultipartUnregistered560=== CONT TestService_verifyS3Integrity561=== CONT TestService_createPendingClosureHandler562=== CONT TestService_cleanupPendingClosuresHandler563=== CONT TestUploadHandlersRejectOversizedBody564=== CONT TestUploadHandlersRejectInvalidKeys565=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info566=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info567=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal568=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal569=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key570=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key571=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key572=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key573=== CONT TestIsValidUploadKey574=== RUN TestIsValidUploadKey/narinfo575=== PAUSE TestIsValidUploadKey/narinfo576=== RUN TestIsValidUploadKey/nar_zst577=== PAUSE TestIsValidUploadKey/nar_zst578=== RUN TestIsValidUploadKey/nar_xz579=== PAUSE TestIsValidUploadKey/nar_xz580=== RUN TestIsValidUploadKey/nar_plain581=== CONT TestProxyWriteTimeout582=== RUN TestProxyWriteTimeout/narinfo583=== PAUSE TestProxyWriteTimeout/narinfo584=== RUN TestProxyWriteTimeout/1_GiB_nar585=== PAUSE TestProxyWriteTimeout/1_GiB_nar586=== RUN TestProxyWriteTimeout/10_GiB_nar587=== PAUSE TestProxyWriteTimeout/10_GiB_nar588=== RUN TestProxyWriteTimeout/unknown_size589=== PAUSE TestProxyWriteTimeout/unknown_size590=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle591=== PAUSE TestIsValidUploadKey/nar_plain592=== RUN TestIsValidUploadKey/listing593=== PAUSE TestIsValidUploadKey/listing594=== RUN TestIsValidUploadKey/build_log595=== PAUSE TestIsValidUploadKey/build_log596=== RUN TestIsValidUploadKey/build_log_home-manager_file597=== PAUSE TestIsValidUploadKey/build_log_home-manager_file598=== RUN TestIsValidUploadKey/build_log_plus_in_name599=== PAUSE TestIsValidUploadKey/build_log_plus_in_name600=== RUN TestIsValidUploadKey/build_log_question_mark601=== PAUSE TestIsValidUploadKey/build_log_question_mark602=== RUN TestIsValidUploadKey/build_log_equals603=== PAUSE TestIsValidUploadKey/build_log_equals604=== RUN TestIsValidUploadKey/realisation605=== PAUSE TestIsValidUploadKey/realisation606=== RUN TestIsValidUploadKey/realisation_plus_in_output607=== PAUSE TestIsValidUploadKey/realisation_plus_in_output608=== RUN TestIsValidUploadKey/nix-cache-info609=== PAUSE TestIsValidUploadKey/nix-cache-info610=== RUN TestIsValidUploadKey/index.html611=== PAUSE TestIsValidUploadKey/index.html612=== RUN TestIsValidUploadKey/narinfo_key,_nar_type613=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type614=== RUN TestIsValidUploadKey/nar_key,_narinfo_type615=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type616=== RUN TestIsValidUploadKey/listing_key,_narinfo_type617=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type618=== RUN TestIsValidUploadKey/traversal619=== PAUSE TestIsValidUploadKey/traversal620=== RUN TestIsValidUploadKey/traversal_nar621=== PAUSE TestIsValidUploadKey/traversal_nar622=== RUN TestIsValidUploadKey/absolute623=== PAUSE TestIsValidUploadKey/absolute624=== RUN TestIsValidUploadKey/empty_key625=== PAUSE TestIsValidUploadKey/empty_key626=== RUN TestIsValidUploadKey/unknown_type627=== PAUSE TestIsValidUploadKey/unknown_type628=== CONT TestSkippedUploadsHandler6292026/09/01 08:26:10 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000630--- PASS: TestSkippedUploadsHandler (0.00s)631=== CONT TestParseSize632--- PASS: TestParseSize (0.00s)633=== CONT TestService_Rustfstest634=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure635=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure636=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart637=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart638=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts639=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts640=== CONT TestPresignedUploadRegisteredBeforeCommit6412026-09-01 08:26:10.254 UTC [97841] ERROR: relation "goose_db_version" does not exist at character 366422026-09-01 08:26:10.254 UTC [97841] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6432026/09/01 08:26:10 OK 20241026095416_initial_model.sql (10.45ms)6442026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)6452026/09/01 08:26:10 OK 20251218171726_add_pins.sql (1.81ms)6462026-09-01 08:26:10.278 UTC [97849] ERROR: relation "goose_db_version" does not exist at character 366472026-09-01 08:26:10.278 UTC [97849] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6482026-09-01 08:26:10.279 UTC [97847] ERROR: relation "goose_db_version" does not exist at character 366492026-09-01 08:26:10.279 UTC [97847] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6502026-09-01 08:26:10.279 UTC [97848] ERROR: relation "goose_db_version" does not exist at character 366512026-09-01 08:26:10.279 UTC [97848] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6522026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (2.37ms)6532026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200006542026/09/01 08:26:10 OK 1_commit_pending_closure.sql (2.07ms)6552026/09/01 08:26:10 OK 2_object_stats_trigger.sql (613.42µs)6562026/09/01 08:26:10 goose: up to current file version: 26572026/09/01 08:26:10 OK 20241026095416_initial_model.sql (59.05ms)6582026/09/01 08:26:10 OK 20241026095416_initial_model.sql (60.11ms)6592026/09/01 08:26:10 OK 20241026095416_initial_model.sql (59.68ms)6602026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (4.35ms)6612026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (13.29ms)6622026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (13.51ms)6632026/09/01 08:26:10 OK 20251218171726_add_pins.sql (8.82ms)6642026/09/01 08:26:10 OK 20251218171726_add_pins.sql (10.09ms)6652026/09/01 08:26:10 OK 20251218171726_add_pins.sql (28.86ms)6662026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (11.42ms)6672026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200006682026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (25.05ms)6692026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200006702026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (17.66ms)6712026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200006722026/09/01 08:26:10 OK 1_commit_pending_closure.sql (16.02ms)6732026/09/01 08:26:10 OK 1_commit_pending_closure.sql (4.29ms)6742026-09-01 08:26:10.397 UTC [97866] ERROR: relation "goose_db_version" does not exist at character 366752026-09-01 08:26:10.397 UTC [97866] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6762026-09-01 08:26:10.397 UTC [97865] ERROR: relation "goose_db_version" does not exist at character 366772026-09-01 08:26:10.397 UTC [97865] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6782026/09/01 08:26:10 OK 2_object_stats_trigger.sql (3.27ms)6792026/09/01 08:26:10 goose: up to current file version: 26802026/09/01 08:26:10 OK 2_object_stats_trigger.sql (4.25ms)6812026/09/01 08:26:10 goose: up to current file version: 26822026/09/01 08:26:10 OK 1_commit_pending_closure.sql (6.89ms)6832026/09/01 08:26:10 OK 2_object_stats_trigger.sql (2.04ms)6842026/09/01 08:26:10 goose: up to current file version: 26852026-09-01 08:26:10.419 UTC [97867] ERROR: relation "goose_db_version" does not exist at character 366862026-09-01 08:26:10.419 UTC [97867] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6872026-09-01 08:26:10.419 UTC [97868] ERROR: relation "goose_db_version" does not exist at character 366882026-09-01 08:26:10.419 UTC [97868] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6892026-09-01 08:26:10.420 UTC [97872] ERROR: relation "goose_db_version" does not exist at character 366902026-09-01 08:26:10.420 UTC [97872] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6912026/09/01 08:26:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete6922026/09/01 08:26:10 OK 20241026095416_initial_model.sql (72.95ms)6932026/09/01 08:26:10 OK 20241026095416_initial_model.sql (66.75ms)6942026/09/01 08:26:10 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst695--- PASS: TestCompleteMultipartUnregistered (0.46s)696=== CONT TestCompletedNarNotReofferedAcrossClosures6972026/09/01 08:26:10 OK 20241026095416_initial_model.sql (33.54ms)6982026/09/01 08:26:10 OK 20241026095416_initial_model.sql (41.41ms)6992026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (4.7ms)7002026/09/01 08:26:10 OK 20241026095416_initial_model.sql (32.39ms)7012026-09-01 08:26:10.490 UTC [97887] ERROR: relation "goose_db_version" does not exist at character 367022026-09-01 08:26:10.490 UTC [97887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7032026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (5.78ms)7042026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (3.01ms)7052026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (5.36ms)7062026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (5.17ms)7072026/09/01 08:26:10 OK 20251218171726_add_pins.sql (5.56ms)7082026/09/01 08:26:10 OK 20251218171726_add_pins.sql (20.1ms)7092026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (24.25ms)7102026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200007112026/09/01 08:26:10 OK 20251218171726_add_pins.sql (24.75ms)7122026/09/01 08:26:10 OK 20251218171726_add_pins.sql (34.86ms)7132026/09/01 08:26:10 OK 20251218171726_add_pins.sql (32.31ms)7142026/09/01 08:26:10 OK 1_commit_pending_closure.sql (8.53ms)7152026/09/01 08:26:10 OK 2_object_stats_trigger.sql (214.33µs)7162026/09/01 08:26:10 goose: up to current file version: 27172026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (30.66ms)7182026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200007192026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (15.5ms)7202026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200007212026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (23.49ms)7222026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200007232026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (16.41ms)7242026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200007252026/09/01 08:26:10 OK 1_commit_pending_closure.sql (2.61ms)7262026/09/01 08:26:10 OK 1_commit_pending_closure.sql (3.09ms)7272026/09/01 08:26:10 OK 1_commit_pending_closure.sql (2.76ms)7282026/09/01 08:26:10 OK 2_object_stats_trigger.sql (698.42µs)7292026/09/01 08:26:10 goose: up to current file version: 27302026/09/01 08:26:10 OK 2_object_stats_trigger.sql (797.5µs)7312026/09/01 08:26:10 goose: up to current file version: 27322026/09/01 08:26:10 OK 2_object_stats_trigger.sql (486.96µs)7332026/09/01 08:26:10 goose: up to current file version: 27342026/09/01 08:26:10 OK 1_commit_pending_closure.sql (3.1ms)7352026/09/01 08:26:10 OK 2_object_stats_trigger.sql (595.25µs)7362026/09/01 08:26:10 goose: up to current file version: 27372026/09/01 08:26:10 OK 20241026095416_initial_model.sql (97.06ms)7382026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (11.08ms)7392026/09/01 08:26:10 OK 20251218171726_add_pins.sql (11.06ms)7402026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (11.73ms)7412026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200007422026/09/01 08:26:10 OK 1_commit_pending_closure.sql (9.06ms)7432026/09/01 08:26:10 OK 2_object_stats_trigger.sql (593.71µs)7442026/09/01 08:26:10 goose: up to current file version: 27452026/09/01 08:26:10 INFO Received uploads request method=POST path=/api/pending_closures7462026/09/01 08:26:10 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst7472026/09/01 08:26:10 INFO Received uploads request method=POST path=/api/pending_closures748--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.65s)749=== CONT TestCompleteMultipartUpload_ErrorButObjectExists7502026-09-01 08:26:10.876 UTC [97975] ERROR: relation "goose_db_version" does not exist at character 367512026-09-01 08:26:10.876 UTC [97975] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7522026-09-01 08:26:10.893 UTC [97976] ERROR: relation "goose_db_version" does not exist at character 367532026-09-01 08:26:10.893 UTC [97976] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7542026/09/01 08:26:10 OK 20241026095416_initial_model.sql (15.5ms)7552026/09/01 08:26:10 OK 20241026095416_initial_model.sql (16.12ms)7562026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (8.9ms)7572026/09/01 08:26:10 OK 20251210153512_drop_unused_gin_index.sql (8.2ms)7582026/09/01 08:26:10 OK 20251218171726_add_pins.sql (8.56ms)7592026/09/01 08:26:10 OK 20251218171726_add_pins.sql (10.04ms)7602026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (9.65ms)7612026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200007622026/09/01 08:26:10 OK 20260628120000_add_object_size_and_stats.sql (15.56ms)7632026/09/01 08:26:10 goose: successfully migrated database to version: 202606281200007642026/09/01 08:26:10 OK 1_commit_pending_closure.sql (8.04ms)7652026/09/01 08:26:10 OK 2_object_stats_trigger.sql (1.4ms)7662026/09/01 08:26:10 goose: up to current file version: 27672026/09/01 08:26:10 OK 1_commit_pending_closure.sql (7.43ms)7682026/09/01 08:26:10 OK 2_object_stats_trigger.sql (552.96µs)7692026/09/01 08:26:10 goose: up to current file version: 27702026/09/01 08:26:10 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"771--- PASS: TestService_AuthMiddleware (0.96s)772=== CONT TestRedundantMultipartUpload7732026/09/01 08:26:11 INFO Received uploads request method=POST path=/api/pending_closures774--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.15s)775=== CONT TestReadRedirectUsesPublicS3URL7762026-09-01 08:26:11.198 UTC [98066] ERROR: relation "goose_db_version" does not exist at character 367772026-09-01 08:26:11.198 UTC [98066] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7782026/09/01 08:26:11 OK 20241026095416_initial_model.sql (35.65ms)7792026/09/01 08:26:11 OK 20251210153512_drop_unused_gin_index.sql (10.05ms)7802026/09/01 08:26:11 OK 20251218171726_add_pins.sql (11.08ms)7812026/09/01 08:26:11 OK 20260628120000_add_object_size_and_stats.sql (6.92ms)7822026/09/01 08:26:11 goose: successfully migrated database to version: 202606281200007832026/09/01 08:26:11 OK 1_commit_pending_closure.sql (6.93ms)7842026/09/01 08:26:11 OK 2_object_stats_trigger.sql (583.88µs)7852026/09/01 08:26:11 goose: up to current file version: 27862026/09/01 08:26:11 INFO Received uploads request method=POST path=/api/pending_closures7872026-09-01 08:26:11.379 UTC [98096] ERROR: relation "goose_db_version" does not exist at character 367882026-09-01 08:26:11.379 UTC [98096] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7892026/09/01 08:26:11 OK 20241026095416_initial_model.sql (50.35ms)7902026/09/01 08:26:11 OK 20251210153512_drop_unused_gin_index.sql (9.34ms)7912026/09/01 08:26:11 OK 20251218171726_add_pins.sql (4.64ms)7922026/09/01 08:26:11 OK 20260628120000_add_object_size_and_stats.sql (21.25ms)7932026/09/01 08:26:11 goose: successfully migrated database to version: 202606281200007942026/09/01 08:26:11 OK 1_commit_pending_closure.sql (12.52ms)7952026/09/01 08:26:11 OK 2_object_stats_trigger.sql (584.75µs)7962026/09/01 08:26:11 goose: up to current file version: 27972026/09/01 08:26:11 INFO Received uploads request method=POST path=/api/pending_closures7982026/09/01 08:26:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7992026/09/01 08:26:11 INFO Received uploads request method=POST path=/api/pending_closures8002026/09/01 08:26:11 INFO Received uploads request method=POST path=/api/pending_closures8012026/09/01 08:26:11 INFO Received uploads request method=POST path=/api/pending_closures802--- PASS: TestObjectStatsTrigger (2.02s)803=== CONT TestReadProxyRangeRequest8042026/09/01 08:26:12 INFO Received cleanup request method=DELETE path=/api/pending_closures8052026/09/01 08:26:12 INFO Aborted multipart uploads count=08062026/09/01 08:26:12 INFO Received uploads request method=POST path=/api/pending_closures8072026/09/01 08:26:12 INFO Received cleanup request method=DELETE path=/api/pending_closures8082026/09/01 08:26:12 INFO Aborted multipart uploads count=18092026/09/01 08:26:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8102026/09/01 08:26:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8112026-09-01 08:26:12.298 UTC [97868] ERROR: Closure does not exist: id=18122026-09-01 08:26:12.298 UTC [97868] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE8132026-09-01 08:26:12.298 UTC [97868] STATEMENT: -- name: CommitPendingClosure :exec814 SELECT commit_pending_closure($1::bigint)815 816--- PASS: TestService_cleanupPendingClosuresHandler (2.28s)817=== CONT TestReadRedirectKeepsNarinfoProxied8182026/09/01 08:26:12 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=Nzk2OGUyY2EtNThmNS00Nzk5LWJlYWQtY2Q3YTY3MWU4OThlLmM0ODliOTYwLTIyNDAtNDQ5Ni05ODQxLTgxMWNmMTA0ZjNkYXgxNzg4MjUxMTcxMzA3MDk2MDAw parts=108192026/09/01 08:26:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8202026/09/01 08:26:12 INFO Completed upload id=18212026/09/01 08:26:12 INFO Received uploads request method=POST path=/api/pending_closures8222026/09/01 08:26:12 INFO Received uploads request method=POST path=/api/pending_closures8232026/09/01 08:26:12 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo8242026/09/01 08:26:12 WARN Found objects in DB but missing from S3, will re-upload count=1825--- PASS: TestService_verifyS3Integrity (2.34s)826=== CONT TestReadRedirectNar827--- PASS: TestService_Rustfstest (2.43s)828=== CONT TestReadProxyDisabled8292026/09/01 08:26:12 INFO Received uploads request method=POST path=/api/pending_closures8302026/09/01 08:26:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8312026-09-01 08:26:12.967 UTC [98616] ERROR: relation "goose_db_version" does not exist at character 368322026-09-01 08:26:12.967 UTC [98616] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8332026/09/01 08:26:12 OK 20241026095416_initial_model.sql (13.22ms)8342026/09/01 08:26:12 OK 20251210153512_drop_unused_gin_index.sql (3.44ms)8352026/09/01 08:26:13 OK 20251218171726_add_pins.sql (2.78ms)8362026/09/01 08:26:13 OK 20260628120000_add_object_size_and_stats.sql (11.27ms)8372026/09/01 08:26:13 goose: successfully migrated database to version: 202606281200008382026/09/01 08:26:13 OK 1_commit_pending_closure.sql (4.85ms)8392026/09/01 08:26:13 OK 2_object_stats_trigger.sql (915.13µs)8402026/09/01 08:26:13 goose: up to current file version: 28412026/09/01 08:26:13 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=Nzk2OGUyY2EtNThmNS00Nzk5LWJlYWQtY2Q3YTY3MWU4OThlLmE1ODQxZGExLTc5YzEtNGU0MC1hNTYwLWI2Y2Q1YThmMGQ1YXgxNzg4MjUxMTcxODE2NDYwMDAw parts=108422026/09/01 08:26:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8432026/09/01 08:26:13 INFO Completed upload id=18442026/09/01 08:26:13 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000008452026/09/01 08:26:13 INFO Received uploads request method=POST path=/api/pending_closures8462026/09/01 08:26:13 INFO Starting cleanup of old closures method=DELETE path=/api/closures8472026/09/01 08:26:13 INFO Aborted multipart uploads count=08482026/09/01 08:26:13 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=08492026/09/01 08:26:13 INFO Vacuumed table table=pending_closures8502026/09/01 08:26:13 INFO Vacuumed table table=pending_objects8512026/09/01 08:26:13 INFO Received uploads request method=POST path=/api/pending_closures8522026/09/01 08:26:13 INFO Vacuumed table table=multipart_uploads8532026/09/01 08:26:13 INFO Vacuumed table table=closures8542026/09/01 08:26:13 INFO Vacuumed table table=objects8552026/09/01 08:26:13 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000856--- PASS: TestService_createPendingClosureHandler (3.20s)857=== CONT TestReadProxyRootRedirectsToIndexHTML8582026/09/01 08:26:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8592026/09/01 08:26:13 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=Nzk2OGUyY2EtNThmNS00Nzk5LWJlYWQtY2Q3YTY3MWU4OThlLmVhMGQyZGY0LTJjMGYtNDJhOC1iZTkyLWQyYjQ2YTI5Mzk1MHgxNzg4MjUxMTczMjE4MzE4MDAw8602026/09/01 08:26:13 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=Nzk2OGUyY2EtNThmNS00Nzk5LWJlYWQtY2Q3YTY3MWU4OThlLmVhMGQyZGY0LTJjMGYtNDJhOC1iZTkyLWQyYjQ2YTI5Mzk1MHgxNzg4MjUxMTczMjE4MzE4MDAw parts=1861--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.79s)862=== CONT TestReadProxyConditionalGet8632026/09/01 08:26:13 INFO Received uploads request method=POST path=/api/pending_closures8642026-09-01 08:26:13.535 UTC [98801] ERROR: relation "goose_db_version" does not exist at character 368652026-09-01 08:26:13.535 UTC [98801] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8662026-09-01 08:26:13.537 UTC [98791] ERROR: relation "goose_db_version" does not exist at character 368672026-09-01 08:26:13.537 UTC [98791] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8682026-09-01 08:26:13.549 UTC [98814] ERROR: relation "goose_db_version" does not exist at character 368692026-09-01 08:26:13.549 UTC [98814] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8702026/09/01 08:26:13 INFO Received uploads request method=POST path=/api/pending_closures8712026/09/01 08:26:13 OK 20241026095416_initial_model.sql (91.75ms)8722026/09/01 08:26:13 OK 20241026095416_initial_model.sql (87.25ms)8732026/09/01 08:26:13 OK 20251210153512_drop_unused_gin_index.sql (9.36ms)8742026/09/01 08:26:13 OK 20251210153512_drop_unused_gin_index.sql (11.21ms)8752026/09/01 08:26:13 OK 20241026095416_initial_model.sql (69.93ms)8762026/09/01 08:26:13 OK 20251218171726_add_pins.sql (25.64ms)8772026/09/01 08:26:13 OK 20251218171726_add_pins.sql (25.26ms)8782026/09/01 08:26:13 OK 20260628120000_add_object_size_and_stats.sql (27.63ms)8792026/09/01 08:26:13 goose: successfully migrated database to version: 202606281200008802026/09/01 08:26:13 OK 1_commit_pending_closure.sql (6.45ms)8812026/09/01 08:26:13 OK 2_object_stats_trigger.sql (8.47ms)8822026/09/01 08:26:13 goose: up to current file version: 28832026/09/01 08:26:13 OK 20260628120000_add_object_size_and_stats.sql (37.66ms)8842026/09/01 08:26:13 goose: successfully migrated database to version: 202606281200008852026/09/01 08:26:13 OK 20251210153512_drop_unused_gin_index.sql (47.56ms)8862026/09/01 08:26:13 OK 1_commit_pending_closure.sql (8.46ms)8872026/09/01 08:26:13 OK 2_object_stats_trigger.sql (5.89ms)8882026/09/01 08:26:13 goose: up to current file version: 28892026/09/01 08:26:13 OK 20251218171726_add_pins.sql (16.47ms)8902026/09/01 08:26:13 OK 20260628120000_add_object_size_and_stats.sql (30.11ms)8912026/09/01 08:26:13 goose: successfully migrated database to version: 202606281200008922026/09/01 08:26:13 OK 1_commit_pending_closure.sql (19.13ms)8932026/09/01 08:26:13 OK 2_object_stats_trigger.sql (605.96µs)8942026/09/01 08:26:13 goose: up to current file version: 2895--- PASS: TestReadRedirectUsesPublicS3URL (2.88s)896=== CONT TestReadProxyHead8972026-09-01 08:26:14.161 UTC [99007] ERROR: relation "goose_db_version" does not exist at character 368982026-09-01 08:26:14.161 UTC [99007] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8992026-09-01 08:26:14.172 UTC [99012] ERROR: relation "goose_db_version" does not exist at character 369002026-09-01 08:26:14.172 UTC [99012] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9012026/09/01 08:26:14 OK 20241026095416_initial_model.sql (5.07ms)9022026/09/01 08:26:14 OK 20251210153512_drop_unused_gin_index.sql (989.04µs)9032026/09/01 08:26:14 OK 20251218171726_add_pins.sql (1.71ms)9042026/09/01 08:26:14 OK 20241026095416_initial_model.sql (8.79ms)9052026/09/01 08:26:14 OK 20251210153512_drop_unused_gin_index.sql (696.58µs)9062026/09/01 08:26:14 OK 20260628120000_add_object_size_and_stats.sql (2.23ms)9072026/09/01 08:26:14 goose: successfully migrated database to version: 202606281200009082026/09/01 08:26:14 OK 20251218171726_add_pins.sql (1.83ms)9092026/09/01 08:26:14 OK 1_commit_pending_closure.sql (6.74ms)9102026/09/01 08:26:14 OK 20260628120000_add_object_size_and_stats.sql (8.05ms)9112026/09/01 08:26:14 goose: successfully migrated database to version: 202606281200009122026/09/01 08:26:14 OK 2_object_stats_trigger.sql (2.97ms)9132026/09/01 08:26:14 goose: up to current file version: 29142026/09/01 08:26:14 OK 1_commit_pending_closure.sql (2.02ms)9152026/09/01 08:26:14 OK 2_object_stats_trigger.sql (14.69ms)9162026/09/01 08:26:14 goose: up to current file version: 29172026-09-01 08:26:14.318 UTC [99052] ERROR: relation "goose_db_version" does not exist at character 369182026-09-01 08:26:14.318 UTC [99052] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9192026/09/01 08:26:14 OK 20241026095416_initial_model.sql (67.64ms)9202026/09/01 08:26:14 OK 20251210153512_drop_unused_gin_index.sql (3.57ms)9212026/09/01 08:26:14 OK 20251218171726_add_pins.sql (4.36ms)9222026/09/01 08:26:14 OK 20260628120000_add_object_size_and_stats.sql (10.34ms)9232026/09/01 08:26:14 goose: successfully migrated database to version: 202606281200009242026/09/01 08:26:14 OK 1_commit_pending_closure.sql (5.23ms)9252026/09/01 08:26:14 OK 2_object_stats_trigger.sql (639.63µs)9262026/09/01 08:26:14 goose: up to current file version: 2927--- PASS: TestReadProxyRangeRequest (2.48s)928=== CONT TestReadProxyInvalidPath9292026-09-01 08:26:14.877 UTC [99166] ERROR: relation "goose_db_version" does not exist at character 369302026-09-01 08:26:14.877 UTC [99166] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9312026/09/01 08:26:14 OK 20241026095416_initial_model.sql (16.02ms)9322026/09/01 08:26:14 OK 20251210153512_drop_unused_gin_index.sql (10.35ms)9332026/09/01 08:26:14 OK 20251218171726_add_pins.sql (3.62ms)9342026/09/01 08:26:14 OK 20260628120000_add_object_size_and_stats.sql (27.32ms)9352026/09/01 08:26:14 goose: successfully migrated database to version: 20260628120000936--- PASS: TestReadProxyDisabled (2.46s)937=== CONT TestReadProxy4049382026/09/01 08:26:14 OK 1_commit_pending_closure.sql (9.04ms)9392026/09/01 08:26:14 OK 2_object_stats_trigger.sql (565.38µs)9402026/09/01 08:26:14 goose: up to current file version: 29412026/09/01 08:26:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9422026/09/01 08:26:15 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=Nzk2OGUyY2EtNThmNS00Nzk5LWJlYWQtY2Q3YTY3MWU4OThlLmMwNWYxNGE2LTQyNTctNGU0NC1hNjg5LTFlNGVkNzgyNjAyNHgxNzg4MjUxMTcyNzg3MDMwMDAw parts=129432026/09/01 08:26:15 INFO Received uploads request method=POST path=/api/pending_closures944--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.73s)945=== CONT TestReadProxyNarStreaming9462026-09-01 08:26:15.282 UTC [99286] ERROR: relation "goose_db_version" does not exist at character 369472026-09-01 08:26:15.282 UTC [99286] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9482026/09/01 08:26:15 OK 20241026095416_initial_model.sql (40.17ms)949--- PASS: TestReadRedirectNar (3.03s)950=== CONT TestReadProxyNarinfoAlreadyDecompressed9512026/09/01 08:26:15 OK 20251210153512_drop_unused_gin_index.sql (30.49ms)9522026/09/01 08:26:15 OK 20251218171726_add_pins.sql (17.31ms)9532026/09/01 08:26:15 OK 20260628120000_add_object_size_and_stats.sql (23.32ms)9542026/09/01 08:26:15 goose: successfully migrated database to version: 202606281200009552026/09/01 08:26:15 OK 1_commit_pending_closure.sql (10.07ms)9562026/09/01 08:26:15 OK 2_object_stats_trigger.sql (7.03ms)9572026/09/01 08:26:15 goose: up to current file version: 2958--- PASS: TestReadRedirectKeepsNarinfoProxied (3.45s)959=== CONT TestReadProxyNarinfo9602026-09-01 08:26:15.789 UTC [99417] ERROR: relation "goose_db_version" does not exist at character 369612026-09-01 08:26:15.789 UTC [99417] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9622026-09-01 08:26:15.803 UTC [99425] ERROR: relation "goose_db_version" does not exist at character 369632026-09-01 08:26:15.803 UTC [99425] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9642026/09/01 08:26:15 OK 20241026095416_initial_model.sql (93.74ms)9652026/09/01 08:26:15 OK 20241026095416_initial_model.sql (94.61ms)9662026/09/01 08:26:15 OK 20251210153512_drop_unused_gin_index.sql (8.1ms)9672026/09/01 08:26:15 OK 20251210153512_drop_unused_gin_index.sql (21.04ms)9682026/09/01 08:26:15 OK 20251218171726_add_pins.sql (17.3ms)9692026/09/01 08:26:15 OK 20251218171726_add_pins.sql (30.97ms)9702026/09/01 08:26:15 OK 20260628120000_add_object_size_and_stats.sql (43.07ms)9712026/09/01 08:26:15 goose: successfully migrated database to version: 202606281200009722026/09/01 08:26:15 OK 20260628120000_add_object_size_and_stats.sql (16.9ms)9732026/09/01 08:26:15 goose: successfully migrated database to version: 202606281200009742026/09/01 08:26:16 OK 1_commit_pending_closure.sql (3.15ms)9752026/09/01 08:26:16 OK 1_commit_pending_closure.sql (1.63ms)9762026/09/01 08:26:16 OK 2_object_stats_trigger.sql (617.42µs)9772026/09/01 08:26:16 goose: up to current file version: 29782026/09/01 08:26:16 OK 2_object_stats_trigger.sql (735.38µs)9792026/09/01 08:26:16 goose: up to current file version: 2980--- PASS: TestReadProxyConditionalGet (2.61s)981=== CONT TestIsValidCachePath982=== RUN TestIsValidCachePath/narinfo983=== PAUSE TestIsValidCachePath/narinfo984=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars985=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars986=== RUN TestIsValidCachePath/nar_zst987=== PAUSE TestIsValidCachePath/nar_zst988=== RUN TestIsValidCachePath/nar_xz989=== PAUSE TestIsValidCachePath/nar_xz990=== RUN TestIsValidCachePath/nar_bz2991=== PAUSE TestIsValidCachePath/nar_bz2992=== RUN TestIsValidCachePath/nar_uncompressed993=== PAUSE TestIsValidCachePath/nar_uncompressed994=== RUN TestIsValidCachePath/ls995=== PAUSE TestIsValidCachePath/ls996=== RUN TestIsValidCachePath/log997=== PAUSE TestIsValidCachePath/log998=== RUN TestIsValidCachePath/realisation999=== PAUSE TestIsValidCachePath/realisation1000=== RUN TestIsValidCachePath/nix-cache-info1001=== PAUSE TestIsValidCachePath/nix-cache-info1002=== RUN TestIsValidCachePath/index.html1003=== PAUSE TestIsValidCachePath/index.html1004=== RUN TestIsValidCachePath/traversal_parent1005=== PAUSE TestIsValidCachePath/traversal_parent1006=== RUN TestIsValidCachePath/traversal_in_middle1007=== PAUSE TestIsValidCachePath/traversal_in_middle1008=== RUN TestIsValidCachePath/invalid_char_e1009=== PAUSE TestIsValidCachePath/invalid_char_e1010=== RUN TestIsValidCachePath/invalid_char_u1011=== PAUSE TestIsValidCachePath/invalid_char_u1012=== RUN TestIsValidCachePath/random_path1013=== PAUSE TestIsValidCachePath/random_path1014=== RUN TestIsValidCachePath/empty1015=== PAUSE TestIsValidCachePath/empty1016=== RUN TestIsValidCachePath/leading_slash1017=== PAUSE TestIsValidCachePath/leading_slash1018=== RUN TestIsValidCachePath/wrong_extension1019=== PAUSE TestIsValidCachePath/wrong_extension1020=== RUN TestIsValidCachePath/short_hash1021=== PAUSE TestIsValidCachePath/short_hash1022=== CONT TestParseSingleRange1023=== RUN TestParseSingleRange/none1024=== PAUSE TestParseSingleRange/none1025=== RUN TestParseSingleRange/unknown_unit1026=== PAUSE TestParseSingleRange/unknown_unit1027=== RUN TestParseSingleRange/multi-range_ignored1028=== PAUSE TestParseSingleRange/multi-range_ignored1029=== RUN TestParseSingleRange/malformed_no_dash1030=== PAUSE TestParseSingleRange/malformed_no_dash1031=== RUN TestParseSingleRange/malformed_both_empty1032=== PAUSE TestParseSingleRange/malformed_both_empty1033=== RUN TestParseSingleRange/malformed_end_before_start1034=== PAUSE TestParseSingleRange/malformed_end_before_start1035=== RUN TestParseSingleRange/closed1036=== PAUSE TestParseSingleRange/closed1037=== RUN TestParseSingleRange/open-ended1038=== PAUSE TestParseSingleRange/open-ended1039=== RUN TestParseSingleRange/end_clamped_to_size1040=== PAUSE TestParseSingleRange/end_clamped_to_size1041=== RUN TestParseSingleRange/suffix1042=== PAUSE TestParseSingleRange/suffix1043=== RUN TestParseSingleRange/suffix_exceeds_size1044=== PAUSE TestParseSingleRange/suffix_exceeds_size1045=== RUN TestParseSingleRange/single_byte1046=== PAUSE TestParseSingleRange/single_byte1047=== RUN TestParseSingleRange/start_past_EOF1048=== PAUSE TestParseSingleRange/start_past_EOF1049=== RUN TestParseSingleRange/start_far_past_EOF1050=== PAUSE TestParseSingleRange/start_far_past_EOF1051=== CONT TestResurrectedObjectNotDeleted10522026/09/01 08:26:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10532026-09-01 08:26:16.249 UTC [99529] ERROR: relation "goose_db_version" does not exist at character 3610542026-09-01 08:26:16.249 UTC [99529] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10552026/09/01 08:26:16 OK 20241026095416_initial_model.sql (92.84ms)10562026/09/01 08:26:16 OK 20251210153512_drop_unused_gin_index.sql (13.2ms)10572026/09/01 08:26:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=Nzk2OGUyY2EtNThmNS00Nzk5LWJlYWQtY2Q3YTY3MWU4OThlLjQyNWYyZjlkLTczZmMtNGZmMC1hYWI1LTlhZDU3ZDQxZmQ4YngxNzg4MjUxMTczNTczMjYzMDAw parts=1210582026/09/01 08:26:16 OK 20251218171726_add_pins.sql (9.53ms)1059--- PASS: TestRedundantMultipartUpload (5.40s)1060=== CONT TestOrphanedObjectsGCStressTest10612026/09/01 08:26:16 OK 20260628120000_add_object_size_and_stats.sql (49.09ms)10622026/09/01 08:26:16 goose: successfully migrated database to version: 2026062812000010632026/09/01 08:26:16 OK 1_commit_pending_closure.sql (6.59ms)10642026/09/01 08:26:16 OK 2_object_stats_trigger.sql (637µs)10652026/09/01 08:26:16 goose: up to current file version: 21066--- PASS: TestReadProxyRootRedirectsToIndexHTML (3.28s)1067=== CONT TestOrphanedObjectsGC10682026-09-01 08:26:16.848 UTC [99677] ERROR: relation "goose_db_version" does not exist at character 3610692026-09-01 08:26:16.848 UTC [99677] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1070--- PASS: TestReadProxyHead (2.82s)1071=== CONT TestGCTaskStore_DeduplicateSameParams1072--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1073=== CONT TestMultipartCleanup10742026/09/01 08:26:16 OK 20241026095416_initial_model.sql (50.76ms)10752026/09/01 08:26:16 OK 20251210153512_drop_unused_gin_index.sql (8.01ms)10762026/09/01 08:26:16 OK 20251218171726_add_pins.sql (28.09ms)10772026/09/01 08:26:16 OK 20260628120000_add_object_size_and_stats.sql (16.46ms)10782026/09/01 08:26:16 goose: successfully migrated database to version: 2026062812000010792026/09/01 08:26:17 OK 1_commit_pending_closure.sql (11.52ms)10802026/09/01 08:26:17 OK 2_object_stats_trigger.sql (9.36ms)10812026/09/01 08:26:17 goose: up to current file version: 21082--- PASS: TestReadProxyInvalidPath (2.58s)1083=== CONT TestServerTLSConfig1084=== RUN TestServerTLSConfig/no_client_CA1085=== PAUSE TestServerTLSConfig/no_client_CA1086=== RUN TestServerTLSConfig/missing_CA_file1087=== PAUSE TestServerTLSConfig/missing_CA_file1088=== RUN TestServerTLSConfig/not_a_PEM_file1089=== PAUSE TestServerTLSConfig/not_a_PEM_file1090=== CONT TestService_NativeMTLS10912026-09-01 08:26:17.143 UTC [99740] ERROR: relation "goose_db_version" does not exist at character 3610922026-09-01 08:26:17.143 UTC [99740] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10932026/09/01 08:26:17 OK 20241026095416_initial_model.sql (50.73ms)10942026/09/01 08:26:17 OK 20251210153512_drop_unused_gin_index.sql (8.65ms)10952026/09/01 08:26:17 OK 20251218171726_add_pins.sql (3.95ms)10962026-09-01 08:26:17.245 UTC [99753] ERROR: relation "goose_db_version" does not exist at character 3610972026-09-01 08:26:17.245 UTC [99753] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10982026/09/01 08:26:17 OK 20260628120000_add_object_size_and_stats.sql (8.87ms)10992026/09/01 08:26:17 goose: successfully migrated database to version: 2026062812000011002026/09/01 08:26:17 OK 1_commit_pending_closure.sql (3.49ms)11012026/09/01 08:26:17 OK 2_object_stats_trigger.sql (791.21µs)11022026/09/01 08:26:17 goose: up to current file version: 211032026/09/01 08:26:17 OK 20241026095416_initial_model.sql (48.1ms)11042026/09/01 08:26:17 OK 20251210153512_drop_unused_gin_index.sql (5.27ms)11052026/09/01 08:26:17 OK 20251218171726_add_pins.sql (10.11ms)11062026/09/01 08:26:17 OK 20260628120000_add_object_size_and_stats.sql (14.31ms)11072026/09/01 08:26:17 goose: successfully migrated database to version: 2026062812000011082026/09/01 08:26:17 OK 1_commit_pending_closure.sql (6.88ms)11092026/09/01 08:26:17 OK 2_object_stats_trigger.sql (608.25µs)11102026/09/01 08:26:17 goose: up to current file version: 211112026-09-01 08:26:17.382 UTC [99777] ERROR: relation "goose_db_version" does not exist at character 3611122026-09-01 08:26:17.382 UTC [99777] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1113--- PASS: TestReadProxy404 (2.45s)1114=== CONT TestMetricsInventory11152026/09/01 08:26:17 OK 20241026095416_initial_model.sql (115.46ms)11162026/09/01 08:26:17 OK 20251210153512_drop_unused_gin_index.sql (14.66ms)11172026/09/01 08:26:17 OK 20251218171726_add_pins.sql (28.41ms)11182026/09/01 08:26:17 OK 20260628120000_add_object_size_and_stats.sql (25.97ms)11192026/09/01 08:26:17 goose: successfully migrated database to version: 2026062812000011202026/09/01 08:26:17 OK 1_commit_pending_closure.sql (2.31ms)11212026/09/01 08:26:17 OK 2_object_stats_trigger.sql (592.17µs)11222026/09/01 08:26:17 goose: up to current file version: 211232026-09-01 08:26:17.650 UTC [99821] ERROR: relation "goose_db_version" does not exist at character 3611242026-09-01 08:26:17.650 UTC [99821] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11252026/09/01 08:26:17 WARN Rate limiter enabled after throttle name=s3-test rate=511262026/09/01 08:26:17 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1127=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1128 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101129 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001130--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (7.65s)1131=== CONT TestNARDeduplicationMetadataUploadBug1132--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.31s)1133=== CONT TestCreatePendingClosureRejectsOversizedNAR11342026/09/01 08:26:17 INFO Received uploads request method=POST path=/api/pending_closures1135--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1136=== CONT TestCacheConfigHandlerMaxNarSize1137--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1138=== CONT TestGenerateLandingPage1139--- PASS: TestGenerateLandingPage (0.00s)1140=== CONT TestService_readinessHandler11412026/09/01 08:26:17 OK 20241026095416_initial_model.sql (136.08ms)11422026/09/01 08:26:17 OK 20251210153512_drop_unused_gin_index.sql (11.87ms)11432026/09/01 08:26:17 OK 20251218171726_add_pins.sql (17.76ms)11442026/09/01 08:26:17 OK 20260628120000_add_object_size_and_stats.sql (42.02ms)11452026/09/01 08:26:17 goose: successfully migrated database to version: 2026062812000011462026/09/01 08:26:17 OK 1_commit_pending_closure.sql (4.85ms)11472026/09/01 08:26:17 OK 2_object_stats_trigger.sql (1.88ms)11482026/09/01 08:26:17 goose: up to current file version: 21149--- PASS: TestReadProxyNarStreaming (2.82s)1150=== CONT TestService_healthCheckHandler11512026-09-01 08:26:18.206 UTC [99955] ERROR: relation "goose_db_version" does not exist at character 3611522026-09-01 08:26:18.206 UTC [99955] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11532026/09/01 08:26:18 OK 20241026095416_initial_model.sql (29.62ms)11542026/09/01 08:26:18 OK 20251210153512_drop_unused_gin_index.sql (3.9ms)11552026/09/01 08:26:18 OK 20251218171726_add_pins.sql (8.89ms)1156--- PASS: TestReadProxyNarinfo (2.56s)1157=== CONT TestGracefulShutdownDrainsInflight11582026/09/01 08:26:18 INFO Starting HTTP server address=127.0.0.1:6039211592026/09/01 08:26:18 INFO Shutdown signal received, draining in-flight requests timeout=10s11602026/09/01 08:26:18 OK 20260628120000_add_object_size_and_stats.sql (28.51ms)11612026/09/01 08:26:18 goose: successfully migrated database to version: 2026062812000011622026/09/01 08:26:18 OK 1_commit_pending_closure.sql (4.25ms)11632026/09/01 08:26:18 OK 2_object_stats_trigger.sql (612.96µs)11642026/09/01 08:26:18 goose: up to current file version: 211652026-09-01 08:26:18.340 UTC [99998] ERROR: relation "goose_db_version" does not exist at character 3611662026-09-01 08:26:18.340 UTC [99998] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11672026-09-01 08:26:18.379 UTC [110] ERROR: relation "goose_db_version" does not exist at character 3611682026-09-01 08:26:18.379 UTC [110] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1169--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1170=== CONT TestGCTaskStore_Fail1171--- PASS: TestGCTaskStore_Fail (0.00s)1172=== CONT TestGCTaskStore_PhaseUpdates1173--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1174=== CONT TestGCTaskStore_CompletedAllowsNewTask1175--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1176=== CONT TestGCTaskStore_GetReturnsLatest1177--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1178=== CONT TestGCTaskStore_GetEmpty1179--- PASS: TestGCTaskStore_GetEmpty (0.00s)1180=== CONT TestGCTaskStore_ConflictDifferentParams1181--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1182=== CONT TestClientErrorHandling1183=== RUN TestClientErrorHandling/InvalidStorePath1184=== PAUSE TestClientErrorHandling/InvalidStorePath1185=== RUN TestClientErrorHandling/InvalidAuthToken1186=== PAUSE TestClientErrorHandling/InvalidAuthToken1187=== RUN TestClientErrorHandling/ServerNotAvailable1188=== PAUSE TestClientErrorHandling/ServerNotAvailable1189=== CONT TestGCTaskStore_StartNew1190--- PASS: TestGCTaskStore_StartNew (0.00s)1191=== CONT TestGCMetrics11922026/09/01 08:26:18 OK 20241026095416_initial_model.sql (25.13ms)11932026/09/01 08:26:18 OK 20251210153512_drop_unused_gin_index.sql (8.73ms)11942026/09/01 08:26:18 OK 20251218171726_add_pins.sql (9.44ms)11952026/09/01 08:26:18 OK 20260628120000_add_object_size_and_stats.sql (31.16ms)11962026/09/01 08:26:18 goose: successfully migrated database to version: 2026062812000011972026/09/01 08:26:18 OK 20241026095416_initial_model.sql (62.78ms)11982026/09/01 08:26:18 OK 1_commit_pending_closure.sql (3.68ms)11992026/09/01 08:26:18 OK 2_object_stats_trigger.sql (406.13µs)12002026/09/01 08:26:18 goose: up to current file version: 212012026/09/01 08:26:18 OK 20251210153512_drop_unused_gin_index.sql (6.87ms)12022026/09/01 08:26:18 OK 20251218171726_add_pins.sql (8.01ms)12032026/09/01 08:26:18 OK 20260628120000_add_object_size_and_stats.sql (21.9ms)12042026/09/01 08:26:18 goose: successfully migrated database to version: 2026062812000012052026/09/01 08:26:18 OK 1_commit_pending_closure.sql (2.93ms)12062026/09/01 08:26:18 OK 2_object_stats_trigger.sql (847.46µs)12072026/09/01 08:26:18 goose: up to current file version: 212082026-09-01 08:26:18.507 UTC [132] ERROR: relation "goose_db_version" does not exist at character 3612092026-09-01 08:26:18.507 UTC [132] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1210--- PASS: TestResurrectedObjectNotDeleted (2.42s)1211=== CONT TestGCBugBareHashReferences12122026/09/01 08:26:18 OK 20241026095416_initial_model.sql (42.42ms)12132026/09/01 08:26:18 OK 20251210153512_drop_unused_gin_index.sql (7.11ms)12142026/09/01 08:26:18 OK 20251218171726_add_pins.sql (9.46ms)12152026/09/01 08:26:18 OK 20260628120000_add_object_size_and_stats.sql (21.34ms)12162026/09/01 08:26:18 goose: successfully migrated database to version: 2026062812000012172026/09/01 08:26:18 OK 1_commit_pending_closure.sql (2.6ms)12182026/09/01 08:26:18 OK 2_object_stats_trigger.sql (608.58µs)12192026/09/01 08:26:18 goose: up to current file version: 212202026-09-01 08:26:18.887 UTC [207] ERROR: relation "goose_db_version" does not exist at character 3612212026-09-01 08:26:18.887 UTC [207] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12222026/09/01 08:26:18 OK 20241026095416_initial_model.sql (17.67ms)12232026/09/01 08:26:18 OK 20251210153512_drop_unused_gin_index.sql (7.51ms)12242026/09/01 08:26:18 OK 20251218171726_add_pins.sql (3.12ms)12252026/09/01 08:26:18 OK 20260628120000_add_object_size_and_stats.sql (8.03ms)12262026/09/01 08:26:18 goose: successfully migrated database to version: 2026062812000012272026/09/01 08:26:18 OK 1_commit_pending_closure.sql (1.99ms)12282026/09/01 08:26:18 OK 2_object_stats_trigger.sql (552.33µs)12292026/09/01 08:26:18 goose: up to current file version: 212302026-09-01 08:26:18.976 UTC [221] ERROR: relation "goose_db_version" does not exist at character 3612312026-09-01 08:26:18.976 UTC [221] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12322026/09/01 08:26:19 INFO Received uploads request method=POST path=/api/pending_closures12332026/09/01 08:26:19 OK 20241026095416_initial_model.sql (45.23ms)12342026/09/01 08:26:19 OK 20251210153512_drop_unused_gin_index.sql (1.28ms)12352026/09/01 08:26:19 OK 20251218171726_add_pins.sql (7.77ms)12362026/09/01 08:26:19 OK 20260628120000_add_object_size_and_stats.sql (10.59ms)12372026/09/01 08:26:19 goose: successfully migrated database to version: 2026062812000012382026/09/01 08:26:19 OK 1_commit_pending_closure.sql (2.57ms)12392026/09/01 08:26:19 OK 2_object_stats_trigger.sql (454.54µs)12402026/09/01 08:26:19 goose: up to current file version: 212412026/09/01 08:26:19 INFO Received cleanup request method=DELETE path=/api/pending_closures12422026/09/01 08:26:19 INFO Aborted multipart uploads count=11243--- PASS: TestMultipartCleanup (2.30s)1244=== CONT TestResolveDBConnectionString1245=== RUN TestResolveDBConnectionString/flag_wins1246=== PAUSE TestResolveDBConnectionString/flag_wins1247=== RUN TestResolveDBConnectionString/file_when_flag_empty1248=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1249=== RUN TestResolveDBConnectionString/missing_file_is_an_error1250=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1251=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1252=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1253=== RUN TestResolveDBConnectionString/nothing_configured1254=== PAUSE TestResolveDBConnectionString/nothing_configured1255=== CONT TestPinProtectsFromGC12562026/09/01 08:26:19 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12572026/09/01 08:26:19 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1258--- PASS: TestService_NativeMTLS (2.10s)1259=== CONT TestClientWithDependencies1260=== NAME TestOrphanedObjectsGC1261 orphaned_objects_gc_test.go:290: GC Test Summary:1262 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1263 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1264 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1265 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1266 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1267--- PASS: TestOrphanedObjectsGC (2.80s)1268=== CONT TestClientMultipleUploads1269--- PASS: TestMetricsInventory (2.00s)1270=== CONT TestClientIntegration12712026-09-01 08:26:19.518 UTC [518] ERROR: relation "goose_db_version" does not exist at character 3612722026-09-01 08:26:19.518 UTC [518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12732026/09/01 08:26:19 OK 20241026095416_initial_model.sql (39.66ms)12742026/09/01 08:26:19 OK 20251210153512_drop_unused_gin_index.sql (5.49ms)12752026/09/01 08:26:19 WARN readiness check failed error="closed pool"1276--- PASS: TestService_readinessHandler (1.91s)1277=== CONT TestService_RequireScope_OIDC12782026/09/01 08:26:19 OK 20251218171726_add_pins.sql (12.69ms)12792026/09/01 08:26:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60408/oidc12802026/09/01 08:26:19 OK 20260628120000_add_object_size_and_stats.sql (25.57ms)12812026/09/01 08:26:19 goose: successfully migrated database to version: 2026062812000012822026/09/01 08:26:19 OK 1_commit_pending_closure.sql (2.04ms)12832026/09/01 08:26:19 OK 2_object_stats_trigger.sql (795.67µs)12842026/09/01 08:26:19 goose: up to current file version: 212852026-09-01 08:26:19.656 UTC [565] ERROR: relation "goose_db_version" does not exist at character 3612862026-09-01 08:26:19.656 UTC [565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12872026-09-01 08:26:19.708 UTC [581] ERROR: relation "goose_db_version" does not exist at character 3612882026-09-01 08:26:19.708 UTC [581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12892026/09/01 08:26:19 OK 20241026095416_initial_model.sql (30.87ms)12902026/09/01 08:26:19 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)12912026/09/01 08:26:19 OK 20251218171726_add_pins.sql (11.9ms)12922026/09/01 08:26:19 OK 20260628120000_add_object_size_and_stats.sql (10.35ms)12932026/09/01 08:26:19 goose: successfully migrated database to version: 2026062812000012942026/09/01 08:26:19 OK 1_commit_pending_closure.sql (2.55ms)12952026/09/01 08:26:19 OK 2_object_stats_trigger.sql (1.26ms)12962026/09/01 08:26:19 goose: up to current file version: 212972026/09/01 08:26:19 OK 20241026095416_initial_model.sql (51.36ms)12982026/09/01 08:26:19 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)12992026/09/01 08:26:19 OK 20251218171726_add_pins.sql (8.36ms)13002026/09/01 08:26:19 OK 20260628120000_add_object_size_and_stats.sql (18.18ms)13012026/09/01 08:26:19 goose: successfully migrated database to version: 2026062812000013022026/09/01 08:26:19 OK 1_commit_pending_closure.sql (9.82ms)13032026/09/01 08:26:19 OK 2_object_stats_trigger.sql (657.67µs)13042026/09/01 08:26:19 goose: up to current file version: 213052026-09-01 08:26:19.860 UTC [620] ERROR: relation "goose_db_version" does not exist at character 3613062026-09-01 08:26:19.860 UTC [620] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13072026/09/01 08:26:19 OK 20241026095416_initial_model.sql (20.74ms)13082026/09/01 08:26:19 OK 20251210153512_drop_unused_gin_index.sql (6.47ms)13092026/09/01 08:26:19 OK 20251218171726_add_pins.sql (14.6ms)13102026/09/01 08:26:19 OK 20260628120000_add_object_size_and_stats.sql (12.28ms)13112026/09/01 08:26:19 goose: successfully migrated database to version: 2026062812000013122026/09/01 08:26:19 OK 1_commit_pending_closure.sql (2.9ms)13132026/09/01 08:26:19 OK 2_object_stats_trigger.sql (632µs)13142026/09/01 08:26:19 goose: up to current file version: 213152026-09-01 08:26:19.957 UTC [640] ERROR: relation "goose_db_version" does not exist at character 3613162026-09-01 08:26:19.957 UTC [640] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13172026/09/01 08:26:20 OK 20241026095416_initial_model.sql (42.83ms)13182026/09/01 08:26:20 OK 20251210153512_drop_unused_gin_index.sql (5.07ms)13192026/09/01 08:26:20 OK 20251218171726_add_pins.sql (18.85ms)1320=== NAME TestNARDeduplicationMetadataUploadBug1321 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-84290-1268021945/TestNARDeduplicationMetadataUploadBug293096254/001/store/bwymfcazr8m3z6laivw0h1npk092b4q7-file1.txt1322--- PASS: TestService_healthCheckHandler (2.02s)1323=== CONT TestClientCADerivations13242026/09/01 08:26:20 OK 20260628120000_add_object_size_and_stats.sql (22.9ms)13252026/09/01 08:26:20 goose: successfully migrated database to version: 2026062812000013262026/09/01 08:26:20 OK 1_commit_pending_closure.sql (4.32ms)13272026/09/01 08:26:20 OK 2_object_stats_trigger.sql (1.53ms)13282026/09/01 08:26:20 goose: up to current file version: 213292026/09/01 08:26:20 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13302026/09/01 08:26:20 INFO Aborted multipart uploads count=013312026/09/01 08:26:20 WARN Force mode enabled - objects will be deleted immediately without grace period13322026/09/01 08:26:20 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=013332026/09/01 08:26:20 INFO Vacuumed table table=pending_closures13342026/09/01 08:26:20 INFO Vacuumed table table=pending_objects13352026/09/01 08:26:20 INFO Vacuumed table table=multipart_uploads13362026/09/01 08:26:20 INFO Vacuumed table table=closures13372026/09/01 08:26:20 INFO Vacuumed table table=objects1338--- PASS: TestGCMetrics (1.89s)1339=== CONT TestCacheStatsHandler13402026/09/01 08:26:20 INFO Received uploads request method=POST path=/api/pending_closures13412026/09/01 08:26:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13422026/09/01 08:26:20 INFO Uploading bwymfcazr8m3z6laivw0h1npk092b4q7-file1.txt (160B)13432026/09/01 08:26:20 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13442026/09/01 08:26:20 WARN Failed to register uploaded object key=bwymfcazr8m3z6laivw0h1npk092b4q7.ls error="server returned 404: 404 page not found\n"13452026/09/01 08:26:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13462026/09/01 08:26:20 INFO Signed narinfos id=1 count=113472026/09/01 08:26:20 INFO Uploading 1 narinfos13482026-09-01 08:26:20.367 UTC [769] ERROR: relation "goose_db_version" does not exist at character 3613492026-09-01 08:26:20.367 UTC [769] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13502026/09/01 08:26:20 WARN Failed to register uploaded object key=bwymfcazr8m3z6laivw0h1npk092b4q7.narinfo error="server returned 404: 404 page not found\n"13512026/09/01 08:26:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13522026/09/01 08:26:20 INFO Completed upload id=113532026/09/01 08:26:20 INFO Upload complete. (265ms)1354=== NAME TestNARDeduplicationMetadataUploadBug1355 metadata_upload_test.go:54: Retrieved narinfo from S3:1356 StorePath: /nix/var/nix/builds/nix-84290-1268021945/TestNARDeduplicationMetadataUploadBug293096254/001/store/bwymfcazr8m3z6laivw0h1npk092b4q7-file1.txt1357 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1358 Compression: zstd1359 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1360 NarSize: 1601361 References: 1362 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1363 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1364 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1365 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}13662026/09/01 08:26:20 OK 20241026095416_initial_model.sql (14.29ms)13672026/09/01 08:26:20 OK 20251210153512_drop_unused_gin_index.sql (26.53ms)13682026/09/01 08:26:20 OK 20251218171726_add_pins.sql (15.44ms)1369 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-84290-1268021945/TestNARDeduplicationMetadataUploadBug293096254/001/store/x5qa2ac6jxg0xmjlv1d6f1pxg6b9y851-file2.txt13702026/09/01 08:26:20 OK 20260628120000_add_object_size_and_stats.sql (14.98ms)13712026/09/01 08:26:20 goose: successfully migrated database to version: 2026062812000013722026/09/01 08:26:20 OK 1_commit_pending_closure.sql (10.16ms)13732026/09/01 08:26:20 OK 2_object_stats_trigger.sql (1.11ms)13742026/09/01 08:26:20 goose: up to current file version: 213752026-09-01 08:26:20.564 UTC [849] ERROR: relation "goose_db_version" does not exist at character 3613762026-09-01 08:26:20.564 UTC [849] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13772026/09/01 08:26:20 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13782026/09/01 08:26:20 OK 20241026095416_initial_model.sql (20ms)13792026/09/01 08:26:20 OK 20251210153512_drop_unused_gin_index.sql (1.34ms)13802026/09/01 08:26:20 OK 20251218171726_add_pins.sql (2.91ms)13812026/09/01 08:26:20 OK 20260628120000_add_object_size_and_stats.sql (11.67ms)13822026/09/01 08:26:20 goose: successfully migrated database to version: 2026062812000013832026/09/01 08:26:20 OK 1_commit_pending_closure.sql (2.12ms)13842026/09/01 08:26:20 OK 2_object_stats_trigger.sql (560µs)13852026/09/01 08:26:20 goose: up to current file version: 21386--- PASS: TestGCBugBareHashReferences (2.21s)1387=== CONT TestCacheConfigHandler1388=== RUN TestCacheConfigHandler/full_config,_no_issuer1389=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1390=== RUN TestCacheConfigHandler/no_cache_url_configured1391=== PAUSE TestCacheConfigHandler/no_cache_url_configured1392=== RUN TestCacheConfigHandler/no_signing_keys1393=== PAUSE TestCacheConfigHandler/no_signing_keys1394=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1395=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1396=== CONT TestService_ReadScope_PublicByDefault13972026/09/01 08:26:20 INFO Received uploads request method=POST path=/api/pending_closures13982026/09/01 08:26:20 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13992026/09/01 08:26:20 WARN Failed to register uploaded object key=x5qa2ac6jxg0xmjlv1d6f1pxg6b9y851.ls error="server returned 404: 404 page not found\n"14002026/09/01 08:26:20 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14012026/09/01 08:26:20 INFO Signed narinfos id=2 count=114022026/09/01 08:26:20 INFO Uploading 1 narinfos14032026/09/01 08:26:20 WARN Failed to register uploaded object key=x5qa2ac6jxg0xmjlv1d6f1pxg6b9y851.narinfo error="server returned 404: 404 page not found\n"14042026/09/01 08:26:20 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14052026/09/01 08:26:20 INFO Completed upload id=214062026/09/01 08:26:20 INFO Upload complete. (411ms)1407=== NAME TestNARDeduplicationMetadataUploadBug1408 metadata_upload_test.go:76: Retrieved narinfo from S3:1409 StorePath: /nix/var/nix/builds/nix-84290-1268021945/TestNARDeduplicationMetadataUploadBug293096254/001/store/x5qa2ac6jxg0xmjlv1d6f1pxg6b9y851-file2.txt1410 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1411 Compression: zstd1412 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1413 NarSize: 1601414 References: 1415 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1416 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1417 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1418 {"version":1,"root":{"type":"regular","size":44}}1419--- PASS: TestNARDeduplicationMetadataUploadBug (3.25s)1420=== CONT TestService_ReadAuthMiddleware14212026-09-01 08:26:20.994 UTC [987] ERROR: relation "goose_db_version" does not exist at character 3614222026-09-01 08:26:20.994 UTC [987] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14232026/09/01 08:26:21 OK 20241026095416_initial_model.sql (19.04ms)14242026/09/01 08:26:21 OK 20251210153512_drop_unused_gin_index.sql (9.07ms)14252026/09/01 08:26:21 OK 20251218171726_add_pins.sql (27.64ms)14262026/09/01 08:26:21 OK 20260628120000_add_object_size_and_stats.sql (26.31ms)14272026/09/01 08:26:21 goose: successfully migrated database to version: 2026062812000014282026/09/01 08:26:21 OK 1_commit_pending_closure.sql (10.59ms)14292026/09/01 08:26:21 OK 2_object_stats_trigger.sql (403.38µs)14302026/09/01 08:26:21 goose: up to current file version: 214312026-09-01 08:26:21.146 UTC [1046] ERROR: relation "goose_db_version" does not exist at character 3614322026-09-01 08:26:21.146 UTC [1046] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14332026/09/01 08:26:21 OK 20241026095416_initial_model.sql (17.79ms)14342026/09/01 08:26:21 OK 20251210153512_drop_unused_gin_index.sql (5.76ms)14352026/09/01 08:26:21 OK 20251218171726_add_pins.sql (7.84ms)14362026/09/01 08:26:21 OK 20260628120000_add_object_size_and_stats.sql (14.34ms)14372026/09/01 08:26:21 goose: successfully migrated database to version: 2026062812000014382026/09/01 08:26:21 OK 1_commit_pending_closure.sql (6.72ms)14392026/09/01 08:26:21 OK 2_object_stats_trigger.sql (791.08µs)14402026/09/01 08:26:21 goose: up to current file version: 21441=== NAME TestPinProtectsFromGC1442 client_integration_test.go:648: Pinned store path: /nix/var/nix/builds/nix-84290-1268021945/TestPinProtectsFromGC709765507/001/store/kkk6i3lxnw0dan0zbd2fa2bm47a6l82v-pinned-file.txt1443 client_integration_test.go:649: Unpinned store path: /nix/var/nix/builds/nix-84290-1268021945/TestPinProtectsFromGC709765507/001/store/x8872d8r9v4q9zk34wiy0lip2qn94mrn-unpinned-file.txt14442026/09/01 08:26:21 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1445=== NAME TestClientMultipleUploads1446 client_integration_test.go:339: Created store path 0: /nix/var/nix/builds/nix-84290-1268021945/TestClientMultipleUploads1533299470/001/store/xdx2pxjvmyk4l7084j6jqw00vk7zjkiv-test-file-0.txt1447 client_integration_test.go:339: Created store path 1: /nix/var/nix/builds/nix-84290-1268021945/TestClientMultipleUploads1533299470/001/store/qsh2kmvm2cjf7kdrcqbwf1amrshk5cv2-test-file-1.txt1448=== NAME TestClientIntegration1449 client_integration_test.go:277: Created store path: /nix/var/nix/builds/nix-84290-1268021945/TestClientIntegration3019660147/002/store/y5fakqpax5fbhwmdkl14qsvfdb1d5074-test-file.txt14502026/09/01 08:26:21 INFO Received uploads request method=POST path=/api/pending_closures14512026/09/01 08:26:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14522026/09/01 08:26:21 INFO Uploading kkk6i3lxnw0dan0zbd2fa2bm47a6l82v-pinned-file.txt (128B)14532026/09/01 08:26:21 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14542026/09/01 08:26:21 WARN Failed to register uploaded object key=kkk6i3lxnw0dan0zbd2fa2bm47a6l82v.ls error="server returned 404: 404 page not found\n"14552026/09/01 08:26:21 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14562026/09/01 08:26:21 INFO Signed narinfos id=1 count=114572026/09/01 08:26:21 INFO Uploading 1 narinfos14582026/09/01 08:26:21 WARN Failed to register uploaded object key=kkk6i3lxnw0dan0zbd2fa2bm47a6l82v.narinfo error="server returned 404: 404 page not found\n"14592026/09/01 08:26:21 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14602026/09/01 08:26:21 INFO Completed upload id=114612026/09/01 08:26:21 INFO Upload complete. (338ms)1462=== RUN TestService_RequireScope_OIDC/builder_may_write1463=== PAUSE TestService_RequireScope_OIDC/builder_may_write1464=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1465=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1466=== RUN TestService_RequireScope_OIDC/ops_may_admin1467=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1468=== RUN TestService_RequireScope_OIDC/ops_may_not_write1469=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1470=== RUN TestService_RequireScope_OIDC/reader_may_not_write1471=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1472=== RUN TestService_RequireScope_OIDC/static_token_may_admin1473=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1474=== RUN TestService_RequireScope_OIDC/static_token_may_write1475=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1476=== RUN TestService_RequireScope_OIDC/reader_may_read1477=== PAUSE TestService_RequireScope_OIDC/reader_may_read1478=== RUN TestService_RequireScope_OIDC/writer_implies_read1479=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1480=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1481=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1482=== CONT TestService_AuthMiddleware_OIDC14832026/09/01 08:26:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60439/oidc1484=== NAME TestClientMultipleUploads1485 client_integration_test.go:339: Created store path 2: /nix/var/nix/builds/nix-84290-1268021945/TestClientMultipleUploads1533299470/001/store/nna4bkbb3yb4c6n58ndyz7ly9253b2i1-test-file-2.txt14862026/09/01 08:26:21 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14872026/09/01 08:26:21 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14882026/09/01 08:26:21 INFO Received uploads request method=POST path=/api/pending_closures14892026/09/01 08:26:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14902026/09/01 08:26:21 INFO Uploading y5fakqpax5fbhwmdkl14qsvfdb1d5074-test-file.txt (152B)14912026/09/01 08:26:21 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"14922026/09/01 08:26:21 WARN Failed to register uploaded object key=y5fakqpax5fbhwmdkl14qsvfdb1d5074.ls error="server returned 404: 404 page not found\n"14932026/09/01 08:26:21 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14942026/09/01 08:26:21 INFO Signed narinfos id=1 count=114952026/09/01 08:26:21 INFO Uploading 1 narinfos14962026/09/01 08:26:21 WARN Failed to register uploaded object key=y5fakqpax5fbhwmdkl14qsvfdb1d5074.narinfo error="server returned 404: 404 page not found\n"14972026/09/01 08:26:21 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14982026/09/01 08:26:21 INFO Completed upload id=114992026/09/01 08:26:21 INFO Upload complete. (243ms)1500=== NAME TestClientIntegration1501 client_integration_test.go:293: Retrieved narinfo from S3:1502 StorePath: /nix/var/nix/builds/nix-84290-1268021945/TestClientIntegration3019660147/002/store/y5fakqpax5fbhwmdkl14qsvfdb1d5074-test-file.txt1503 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1504 Compression: zstd1505 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11506 NarSize: 1521507 References: 1508 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk115092026/09/01 08:26:21 INFO Received uploads request method=POST path=/api/pending_closures1510 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1511 client_integration_test.go:294: Decompressed .ls content (64 bytes):1512 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1513 client_integration_test.go:297: Testing garbage collection...15142026/09/01 08:26:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15152026/09/01 08:26:21 INFO Uploading x8872d8r9v4q9zk34wiy0lip2qn94mrn-unpinned-file.txt (128B)15162026/09/01 08:26:21 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15172026/09/01 08:26:21 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15182026/09/01 08:26:22 WARN Failed to register uploaded object key=x8872d8r9v4q9zk34wiy0lip2qn94mrn.ls error="server returned 404: 404 page not found\n"15192026/09/01 08:26:22 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15202026/09/01 08:26:22 INFO Signed narinfos id=2 count=115212026/09/01 08:26:22 INFO Uploading 1 narinfos15222026/09/01 08:26:22 WARN Failed to register uploaded object key=x8872d8r9v4q9zk34wiy0lip2qn94mrn.narinfo error="server returned 404: 404 page not found\n"15232026/09/01 08:26:22 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15242026/09/01 08:26:22 INFO Completed upload id=215252026/09/01 08:26:22 INFO Upload complete. (283ms)15262026/09/01 08:26:22 INFO Starting cleanup of old closures method=DELETE path=/api/closures15272026/09/01 08:26:22 INFO Garbage collection started15282026-09-01 08:26:22.136 UTC [1310] ERROR: relation "goose_db_version" does not exist at character 3615292026-09-01 08:26:22.136 UTC [1310] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15302026/09/01 08:26:22 INFO Aborted multipart uploads count=015312026/09/01 08:26:22 WARN Force mode enabled - objects will be deleted immediately without grace period15322026/09/01 08:26:22 OK 20241026095416_initial_model.sql (10.59ms)15332026/09/01 08:26:22 OK 20251210153512_drop_unused_gin_index.sql (1.56ms)15342026/09/01 08:26:22 OK 20251218171726_add_pins.sql (1.5ms)1535--- PASS: TestCacheStatsHandler (1.91s)1536=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15372026/09/01 08:26:22 OK 20260628120000_add_object_size_and_stats.sql (3.39ms)15382026/09/01 08:26:22 goose: successfully migrated database to version: 2026062812000015392026/09/01 08:26:22 OK 1_commit_pending_closure.sql (2.64ms)15402026/09/01 08:26:22 OK 2_object_stats_trigger.sql (626.42µs)15412026/09/01 08:26:22 goose: up to current file version: 21542=== NAME TestOrphanedObjectsGCStressTest1543 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains15442026/09/01 08:26:22 INFO Received uploads request method=POST path=/api/pending_closures15452026/09/01 08:26:22 INFO Received uploads request method=POST path=/api/pending_closures15462026/09/01 08:26:22 INFO Received uploads request method=POST path=/api/pending_closures15472026/09/01 08:26:22 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15482026/09/01 08:26:22 INFO Uploading xdx2pxjvmyk4l7084j6jqw00vk7zjkiv-test-file-0.txt (160B)15492026/09/01 08:26:22 INFO Uploading qsh2kmvm2cjf7kdrcqbwf1amrshk5cv2-test-file-1.txt (160B)15502026/09/01 08:26:22 INFO Uploading nna4bkbb3yb4c6n58ndyz7ly9253b2i1-test-file-2.txt (160B)15512026/09/01 08:26:22 INFO Received create pin request method=POST path=/api/pins/myapp15522026/09/01 08:26:22 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15532026/09/01 08:26:22 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"1554 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion15552026/09/01 08:26:22 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-84290-1268021945/TestPinProtectsFromGC709765507/001/store/kkk6i3lxnw0dan0zbd2fa2bm47a6l82v-pinned-file.txt narinfo_key=kkk6i3lxnw0dan0zbd2fa2bm47a6l82v.narinfo15562026/09/01 08:26:22 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15572026/09/01 08:26:22 INFO Starting cleanup of old closures method=DELETE path=/api/closures15582026/09/01 08:26:22 INFO Garbage collection started15592026/09/01 08:26:22 INFO Aborted multipart uploads count=015602026/09/01 08:26:22 WARN Failed to register uploaded object key=qsh2kmvm2cjf7kdrcqbwf1amrshk5cv2.ls error="server returned 404: 404 page not found\n"15612026/09/01 08:26:22 WARN Force mode enabled - objects will be deleted immediately without grace period15622026/09/01 08:26:22 WARN Failed to register uploaded object key=xdx2pxjvmyk4l7084j6jqw00vk7zjkiv.ls error="server returned 404: 404 page not found\n"15632026/09/01 08:26:22 WARN Failed to register uploaded object key=nna4bkbb3yb4c6n58ndyz7ly9253b2i1.ls error="server returned 404: 404 page not found\n"15642026/09/01 08:26:22 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign15652026/09/01 08:26:22 INFO Signed narinfos id=3 count=115662026/09/01 08:26:22 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15672026/09/01 08:26:22 INFO Signed narinfos id=1 count=115682026/09/01 08:26:22 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15692026/09/01 08:26:22 INFO Signed narinfos id=2 count=115702026/09/01 08:26:22 INFO Uploading 3 narinfos15712026/09/01 08:26:22 WARN Failed to register uploaded object key=nna4bkbb3yb4c6n58ndyz7ly9253b2i1.narinfo error="server returned 404: 404 page not found\n"15722026/09/01 08:26:22 WARN Failed to register uploaded object key=xdx2pxjvmyk4l7084j6jqw00vk7zjkiv.narinfo error="server returned 404: 404 page not found\n"15732026/09/01 08:26:22 WARN Failed to register uploaded object key=qsh2kmvm2cjf7kdrcqbwf1amrshk5cv2.narinfo error="server returned 404: 404 page not found\n"15742026/09/01 08:26:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15752026/09/01 08:26:22 INFO Completed upload id=115762026/09/01 08:26:22 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15772026/09/01 08:26:22 INFO Completed upload id=215782026/09/01 08:26:22 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete15792026/09/01 08:26:22 INFO Completed upload id=315802026/09/01 08:26:22 INFO Upload complete. (450ms)1581=== NAME TestClientMultipleUploads1582 client_integration_test.go:350: Uploaded 3 paths in 533.08075ms1583--- PASS: TestClientMultipleUploads (3.03s)1584=== CONT TestService_AuthMiddleware_MTLSProxyHeader1585--- PASS: TestService_ReadScope_PublicByDefault (1.63s)1586=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15872026/09/01 08:26:22 INFO Received uploads request method=POST path=/1588=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15892026/09/01 08:26:22 INFO Received request for more parts method=POST path=/1590=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15912026/09/01 08:26:22 INFO Received complete multipart upload request method=POST path=/1592=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15932026/09/01 08:26:22 INFO Received uploads request method=POST path=/1594--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1595 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1596 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1597 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1598 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1599=== CONT TestProxyWriteTimeout/narinfo1600=== CONT TestProxyWriteTimeout/10_GiB_nar1601=== CONT TestProxyWriteTimeout/unknown_size1602=== CONT TestProxyWriteTimeout/1_GiB_nar1603=== CONT TestIsValidUploadKey/narinfo1604=== CONT TestIsValidUploadKey/realisation_plus_in_output1605=== CONT TestIsValidUploadKey/unknown_type1606=== CONT TestIsValidUploadKey/empty_key1607=== CONT TestIsValidUploadKey/absolute1608=== CONT TestIsValidUploadKey/traversal_nar1609=== CONT TestIsValidUploadKey/traversal1610=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1611=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1612=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1613=== CONT TestIsValidUploadKey/index.html1614=== CONT TestIsValidUploadKey/nix-cache-info1615=== CONT TestIsValidUploadKey/build_log_home-manager_file1616=== CONT TestIsValidUploadKey/realisation1617=== CONT TestIsValidUploadKey/build_log_equals1618=== CONT TestIsValidUploadKey/build_log_question_mark1619=== CONT TestIsValidUploadKey/build_log_plus_in_name1620=== CONT TestIsValidUploadKey/nar_xz1621=== CONT TestIsValidUploadKey/build_log1622=== CONT TestIsValidUploadKey/listing1623=== CONT TestIsValidUploadKey/nar_plain1624=== CONT TestIsValidUploadKey/nar_zst1625=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure1626--- PASS: TestProxyWriteTimeout (0.00s)1627 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1628 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1629 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1630 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)16312026/09/01 08:26:22 INFO Received uploads request method=POST path=/1632--- PASS: TestIsValidUploadKey (0.03s)1633 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1634 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1635 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1636 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1637 --- PASS: TestIsValidUploadKey/absolute (0.00s)1638 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1639 --- PASS: TestIsValidUploadKey/traversal (0.00s)1640 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1641 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1642 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1643 --- PASS: TestIsValidUploadKey/index.html (0.00s)1644 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1645 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1646 --- PASS: TestIsValidUploadKey/realisation (0.00s)1647 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1648 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1649 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1650 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1651 --- PASS: TestIsValidUploadKey/build_log (0.00s)1652 --- PASS: TestIsValidUploadKey/listing (0.00s)1653 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1654 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)16552026-09-01 08:26:22.428 UTC [1384] ERROR: relation "goose_db_version" does not exist at character 3616562026-09-01 08:26:22.428 UTC [1384] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16572026/09/01 08:26:22 OK 20241026095416_initial_model.sql (37.59ms)16582026/09/01 08:26:22 OK 20251210153512_drop_unused_gin_index.sql (2.15ms)16592026/09/01 08:26:22 OK 20251218171726_add_pins.sql (4.15ms)16602026/09/01 08:26:22 OK 20260628120000_add_object_size_and_stats.sql (3.69ms)16612026/09/01 08:26:22 goose: successfully migrated database to version: 2026062812000016622026/09/01 08:26:22 OK 1_commit_pending_closure.sql (1.97ms)16632026/09/01 08:26:22 OK 2_object_stats_trigger.sql (685.04µs)16642026/09/01 08:26:22 goose: up to current file version: 216652026-09-01 08:26:22.502 UTC [1390] ERROR: relation "goose_db_version" does not exist at character 3616662026-09-01 08:26:22.502 UTC [1390] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16672026/09/01 08:26:22 OK 20241026095416_initial_model.sql (15.77ms)16682026/09/01 08:26:22 OK 20251210153512_drop_unused_gin_index.sql (869.13µs)16692026/09/01 08:26:22 OK 20251218171726_add_pins.sql (2.27ms)16702026/09/01 08:26:22 OK 20260628120000_add_object_size_and_stats.sql (2.15ms)16712026/09/01 08:26:22 goose: successfully migrated database to version: 2026062812000016722026/09/01 08:26:22 OK 1_commit_pending_closure.sql (2.04ms)16732026/09/01 08:26:22 OK 2_object_stats_trigger.sql (555.04µs)16742026/09/01 08:26:22 goose: up to current file version: 21675--- PASS: TestService_ReadAuthMiddleware (1.68s)1676=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16772026/09/01 08:26:22 INFO Received request for more parts method=POST path=/1678=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16792026/09/01 08:26:22 INFO Received complete multipart upload request method=POST path=/1680=== NAME TestClientWithDependencies1681 client_integration_test.go:594: Built derivation: /nix/var/nix/builds/nix-84290-1268021945/TestClientWithDependencies2868218411/001/store/9g0x47mjxbd3qvrfvl8xy9y3v95j7j2x-test-script1682=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1683=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1684=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1685=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1686=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1687=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1688=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1689=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1690=== CONT TestIsValidCachePath/narinfo1691=== CONT TestIsValidCachePath/index.html1692=== CONT TestIsValidCachePath/short_hash1693=== CONT TestIsValidCachePath/wrong_extension1694=== CONT TestIsValidCachePath/leading_slash1695=== CONT TestIsValidCachePath/empty1696=== CONT TestIsValidCachePath/random_path1697=== CONT TestIsValidCachePath/invalid_char_u1698=== CONT TestIsValidCachePath/invalid_char_e1699=== CONT TestIsValidCachePath/traversal_in_middle1700=== CONT TestIsValidCachePath/traversal_parent1701=== CONT TestIsValidCachePath/nar_uncompressed1702=== CONT TestIsValidCachePath/nix-cache-info1703=== CONT TestIsValidCachePath/realisation1704=== CONT TestIsValidCachePath/log1705=== CONT TestIsValidCachePath/ls1706=== CONT TestIsValidCachePath/nar_xz1707=== CONT TestIsValidCachePath/nar_bz21708=== CONT TestIsValidCachePath/nar_zst1709=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1710--- PASS: TestIsValidCachePath (0.00s)1711 --- PASS: TestIsValidCachePath/narinfo (0.00s)1712 --- PASS: TestIsValidCachePath/index.html (0.00s)1713 --- PASS: TestIsValidCachePath/short_hash (0.00s)1714 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1715 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1716 --- PASS: TestIsValidCachePath/empty (0.00s)1717 --- PASS: TestIsValidCachePath/random_path (0.00s)1718 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1719 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1720 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1721 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1722 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1723 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1724 --- PASS: TestIsValidCachePath/realisation (0.00s)1725 --- PASS: TestIsValidCachePath/log (0.00s)1726 --- PASS: TestIsValidCachePath/ls (0.00s)1727 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1728 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1729 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1730 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1731=== CONT TestParseSingleRange/none1732=== CONT TestParseSingleRange/open-ended1733=== CONT TestParseSingleRange/start_far_past_EOF1734=== CONT TestParseSingleRange/start_past_EOF1735=== CONT TestParseSingleRange/single_byte1736=== CONT TestParseSingleRange/suffix_exceeds_size1737=== CONT TestParseSingleRange/suffix1738=== CONT TestParseSingleRange/end_clamped_to_size1739=== CONT TestParseSingleRange/malformed_both_empty1740=== CONT TestParseSingleRange/closed1741=== CONT TestParseSingleRange/malformed_end_before_start1742=== CONT TestParseSingleRange/unknown_unit1743=== CONT TestParseSingleRange/malformed_no_dash1744=== CONT TestParseSingleRange/multi-range_ignored1745--- PASS: TestParseSingleRange (0.00s)1746 --- PASS: TestParseSingleRange/none (0.00s)1747 --- PASS: TestParseSingleRange/open-ended (0.00s)1748 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1749 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1750 --- PASS: TestParseSingleRange/single_byte (0.00s)1751 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1752 --- PASS: TestParseSingleRange/suffix (0.00s)1753 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1754 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1755 --- PASS: TestParseSingleRange/closed (0.00s)1756 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1757 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1758 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1759 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1760=== CONT TestServerTLSConfig/no_client_CA1761=== CONT TestServerTLSConfig/not_a_PEM_file1762=== CONT TestServerTLSConfig/missing_CA_file1763--- PASS: TestServerTLSConfig (0.00s)1764 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1765 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1766 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1767=== CONT TestClientErrorHandling/InvalidStorePath1768=== NAME TestClientWithDependencies1769 client_integration_test.go:596: Found 1 dependencies (including self)1770=== CONT TestClientErrorHandling/ServerNotAvailable17712026-09-01 08:26:23.062 UTC [1499] ERROR: relation "goose_db_version" does not exist at character 3617722026-09-01 08:26:23.062 UTC [1499] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17732026/09/01 08:26:23 OK 20241026095416_initial_model.sql (16.96ms)17742026/09/01 08:26:23 OK 20251210153512_drop_unused_gin_index.sql (887.83µs)17752026/09/01 08:26:23 OK 20251218171726_add_pins.sql (2.54ms)17762026/09/01 08:26:23 OK 20260628120000_add_object_size_and_stats.sql (2.54ms)17772026/09/01 08:26:23 goose: successfully migrated database to version: 2026062812000017782026/09/01 08:26:23 OK 1_commit_pending_closure.sql (1.79ms)17792026/09/01 08:26:23 OK 2_object_stats_trigger.sql (482.79µs)17802026/09/01 08:26:23 goose: up to current file version: 217812026/09/01 08:26:23 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17822026/09/01 08:26:23 WARN mTLS auth: bound subjects configured but subject DN unavailable17832026/09/01 08:26:23 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1784--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.98s)1785=== CONT TestClientErrorHandling/InvalidAuthToken17862026-09-01 08:26:23.345 UTC [1553] ERROR: relation "goose_db_version" does not exist at character 3617872026-09-01 08:26:23.345 UTC [1553] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17882026/09/01 08:26:23 OK 20241026095416_initial_model.sql (32.62ms)17892026/09/01 08:26:23 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)17902026/09/01 08:26:23 OK 20251218171726_add_pins.sql (2.63ms)17912026/09/01 08:26:23 OK 20260628120000_add_object_size_and_stats.sql (2.71ms)17922026/09/01 08:26:23 goose: successfully migrated database to version: 2026062812000017932026/09/01 08:26:23 OK 1_commit_pending_closure.sql (2.18ms)17942026/09/01 08:26:23 OK 2_object_stats_trigger.sql (451.46µs)17952026/09/01 08:26:23 goose: up to current file version: 21796--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.16s)1797=== CONT TestResolveDBConnectionString/flag_wins1798=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1799=== CONT TestResolveDBConnectionString/nothing_configured1800=== CONT TestResolveDBConnectionString/missing_file_is_an_error1801=== CONT TestResolveDBConnectionString/file_when_flag_empty1802=== CONT TestCacheConfigHandler/full_config,_no_issuer1803=== CONT TestCacheConfigHandler/no_signing_keys1804=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1805=== CONT TestCacheConfigHandler/no_cache_url_configured1806--- PASS: TestCacheConfigHandler (0.00s)1807 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1808 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1809 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1810 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1811=== CONT TestService_RequireScope_OIDC/builder_may_write1812--- PASS: TestResolveDBConnectionString (0.01s)1813 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1814 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1815 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1816 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1817 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)18182026/09/01 08:26:23 INFO OIDC auth successful provider=test scopes=[write]1819=== CONT TestService_RequireScope_OIDC/static_token_may_admin1820=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1821=== CONT TestService_RequireScope_OIDC/writer_implies_read18222026/09/01 08:26:23 INFO OIDC auth successful provider=test scopes=[write]1823=== CONT TestService_RequireScope_OIDC/reader_may_read18242026/09/01 08:26:23 INFO OIDC auth successful provider=test scopes=[read]1825=== CONT TestService_RequireScope_OIDC/static_token_may_write1826=== CONT TestService_RequireScope_OIDC/ops_may_not_write18272026/09/01 08:26:23 INFO OIDC auth successful provider=test scopes=[admin]1828=== CONT TestService_RequireScope_OIDC/reader_may_not_write18292026/09/01 08:26:23 INFO OIDC auth successful provider=test scopes=[read]1830=== CONT TestService_RequireScope_OIDC/ops_may_admin18312026/09/01 08:26:23 INFO OIDC auth successful provider=test scopes=[admin]1832=== CONT TestService_RequireScope_OIDC/builder_may_not_admin18332026/09/01 08:26:23 INFO OIDC auth successful provider=test scopes=[write]1834--- PASS: TestService_RequireScope_OIDC (2.10s)1835 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1836 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1837 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1838 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1839 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1840 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1841 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1842 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1843 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1844 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1845=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token18462026/09/01 08:26:23 INFO OIDC auth successful provider=test scopes=[write]1847=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1848=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18492026/09/01 08:26:23 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]1850=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18512026/09/01 08:26:23 WARN Authentication failed token_preview=eyJhbGciOi...beSHs148jg token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1852--- PASS: TestService_AuthMiddleware_OIDC (1.19s)1853 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1854 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1855 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1856 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)18572026/09/01 08:26:23 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18582026/09/01 08:26:23 INFO Received uploads request method=POST path=/api/pending_closures18592026/09/01 08:26:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18602026/09/01 08:26:23 INFO Uploading 9g0x47mjxbd3qvrfvl8xy9y3v95j7j2x-test-script (136B)1861=== NAME TestClientCADerivations1862 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-84290-1268021945/TestClientCADerivations3283104693/001/store/fam0wdn86f2idmgpap2wrbkqnlypdjs7-ca-test18632026/09/01 08:26:23 WARN Failed to register uploaded object key=log/9x9ngvvn74i32bbnazhijc3ssfd6cjjp-test-script.drv error="server returned 404: 404 page not found\n"18642026/09/01 08:26:23 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18652026/09/01 08:26:23 WARN Failed to register uploaded object key=9g0x47mjxbd3qvrfvl8xy9y3v95j7j2x.ls error="server returned 404: 404 page not found\n"18662026/09/01 08:26:23 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18672026/09/01 08:26:23 INFO Signed narinfos id=1 count=118682026/09/01 08:26:23 INFO Uploading 1 narinfos18692026/09/01 08:26:23 WARN Failed to register uploaded object key=9g0x47mjxbd3qvrfvl8xy9y3v95j7j2x.narinfo error="server returned 404: 404 page not found\n"18702026/09/01 08:26:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18712026/09/01 08:26:23 INFO Completed upload id=118722026/09/01 08:26:23 INFO Upload complete. (404ms)1873=== NAME TestClientWithDependencies1874 client_integration_test.go:598: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-84290-1268021945/TestClientWithDependencies2868218411/001/store) requires matching store prefix1875--- PASS: TestClientWithDependencies (4.58s)18762026/09/01 08:26:23 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=018772026/09/01 08:26:23 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=018782026/09/01 08:26:23 INFO Vacuumed table table=pending_closures1879=== NAME TestClientCADerivations1880 client_ca_test.go:139: Found 1 dependencies (including self)18812026/09/01 08:26:23 INFO Vacuumed table table=pending_closures18822026/09/01 08:26:23 INFO Vacuumed table table=pending_objects18832026/09/01 08:26:23 INFO Vacuumed table table=multipart_uploads18842026/09/01 08:26:23 INFO Vacuumed table table=pending_objects18852026/09/01 08:26:23 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-config18862026/09/01 08:26:23 INFO Vacuumed table table=multipart_uploads18872026/09/01 08:26:23 INFO Vacuumed table table=closures18882026/09/01 08:26:23 INFO Vacuumed table table=objects18892026/09/01 08:26:23 INFO Vacuumed table table=closures18902026/09/01 08:26:23 INFO Vacuumed table table=objects18912026/09/01 08:26:23 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=199.472106ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config18922026/09/01 08:26:24 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=412.291494ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config18932026/09/01 08:26:24 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01894=== NAME TestClientIntegration1895 client_integration_test.go:304: Objects in database after GC:1896 client_integration_test.go:304: Successfully deleted all objects with GC --force1897--- PASS: TestClientIntegration (4.76s)18982026/09/01 08:26:24 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01899=== NAME TestPinProtectsFromGC1900 client_integration_test.go:711: Pin successfully protected closure from garbage collection1901--- PASS: TestPinProtectsFromGC (5.09s)19022026/09/01 08:26:24 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1903=== NAME TestOrphanedObjectsGCStressTest1904 orphaned_objects_gc_test.go:509: Stress test completed successfully:1905 orphaned_objects_gc_test.go:510: - Active objects preserved: 201906 orphaned_objects_gc_test.go:511: - Objects deleted: 2101907 orphaned_objects_gc_test.go:512: - Total GC'd: 2101908--- PASS: TestOrphanedObjectsGCStressTest (7.99s)19092026/09/01 08:26:24 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19102026/09/01 08:26:24 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=786.52175ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19112026/09/01 08:26:24 INFO Received uploads request method=POST path=/api/pending_closures19122026/09/01 08:26:24 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19132026/09/01 08:26:24 INFO Uploading fam0wdn86f2idmgpap2wrbkqnlypdjs7-ca-test (144B)19142026/09/01 08:26:24 WARN Failed to register uploaded object key=log/xyfh6misp72cs8dp0fwdmnwpvdw7ypbr-ca-test.drv error="server returned 404: 404 page not found\n"19152026/09/01 08:26:24 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19162026/09/01 08:26:24 WARN Failed to register uploaded object key=fam0wdn86f2idmgpap2wrbkqnlypdjs7.ls error="server returned 404: 404 page not found\n"19172026/09/01 08:26:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign19182026/09/01 08:26:24 INFO Signed narinfos id=1 count=119192026/09/01 08:26:24 INFO Uploading 1 narinfos19202026/09/01 08:26:24 WARN Failed to register uploaded object key=fam0wdn86f2idmgpap2wrbkqnlypdjs7.narinfo error="server returned 404: 404 page not found\n"19212026/09/01 08:26:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19222026/09/01 08:26:24 INFO Completed upload id=119232026/09/01 08:26:24 INFO Upload complete. (573ms)1924=== NAME TestClientCADerivations1925 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-84290-1268021945/TestClientCADerivations3283104693/001/store/fam0wdn86f2idmgpap2wrbkqnlypdjs7-ca-test1926 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1927 Compression: zstd1928 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1929 NarSize: 1441930 References: 1931 Deriver: /nix/var/nix/builds/nix-84290-1268021945/TestClientCADerivations3283104693/001/store/xyfh6misp72cs8dp0fwdmnwpvdw7ypbr-ca-test.drv1932 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1933 client_ca_test.go:185: Checking for realisation files in S3...1934 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1935 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache19362026/09/01 08:26:24 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"1937 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket44?endpoint=http://localhost:60240®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-84290-1268021945/TestClientCADerivations3283104693/001/store'1938 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11939--- PASS: TestClientCADerivations (4.85s)1940--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)1941 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1942 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.35s)1943 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (2.84s)19442026/09/01 08:26:25 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.508123392s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19452026/09/01 08:26:26 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"19462026/09/01 08:26:26 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_closures19472026/09/01 08:26:27 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=196.476137ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19482026/09/01 08:26:27 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=422.807961ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19492026/09/01 08:26:27 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=738.295734ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19502026/09/01 08:26:28 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.66508889s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1951--- PASS: TestClientErrorHandling (0.00s)1952 --- PASS: TestClientErrorHandling/InvalidStorePath (1.16s)1953 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.54s)1954 --- PASS: TestClientErrorHandling/ServerNotAvailable (7.08s)1955PASS19562026-09-01 08:26:30.173 UTC [96650] LOG: received smart shutdown request19572026-09-01 08:26:30.175 UTC [96650] LOG: background worker "logical replication launcher" (PID 96669) exited with exit code 119582026-09-01 08:26:30.192 UTC [96664] LOG: shutting down19592026-09-01 08:26:30.192 UTC [96664] LOG: checkpoint starting: shutdown immediate19602026-09-01 08:26:31.952 UTC [96664] LOG: checkpoint complete: wrote 13219 buffers (80.7%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=1.275 s, sync=0.481 s, total=1.760 s; sync files=17141, longest=0.013 s, average=0.001 s; distance=240172 kB, estimate=240172 kB; lsn=0/10217F78, redo lsn=0/10217F7819612026-09-01 08:26:31.958 UTC [96650] LOG: database system is shut down1962Running OIDC tests...1963=== RUN TestGlobMatch1964=== PAUSE TestGlobMatch1965=== RUN TestAudienceForIssuer1966=== PAUSE TestAudienceForIssuer1967=== RUN TestValidateToken_ValidToken1968=== PAUSE TestValidateToken_ValidToken1969=== RUN TestValidateToken_WrongAudience1970=== PAUSE TestValidateToken_WrongAudience1971=== RUN TestValidateToken_Expired1972=== PAUSE TestValidateToken_Expired1973=== RUN TestValidateToken_BoundClaimsMismatch1974=== PAUSE TestValidateToken_BoundClaimsMismatch1975=== RUN TestValidateToken_BoundSubjectMismatch1976=== PAUSE TestValidateToken_BoundSubjectMismatch1977=== RUN TestValidateToken_MultipleProviders1978=== PAUSE TestValidateToken_MultipleProviders1979=== RUN TestValidateToken_NoMatchingProvider1980=== PAUSE TestValidateToken_NoMatchingProvider1981=== RUN TestValidateToken_KubernetesServiceAccount1982=== PAUSE TestValidateToken_KubernetesServiceAccount1983=== RUN TestNewValidator_KubernetesRequiresCA1984=== PAUSE TestNewValidator_KubernetesRequiresCA1985=== RUN TestValidateToken_KubernetesIssuerFromOwnToken1986=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken1987=== RUN TestScopes_LegacyProviderDefaultsToWrite1988=== PAUSE TestScopes_LegacyProviderDefaultsToWrite1989=== RUN TestScopes_Rules1990=== PAUSE TestScopes_Rules1991=== RUN TestScopes_ConfigValidation1992=== PAUSE TestScopes_ConfigValidation1993=== CONT TestGlobMatch1994=== RUN TestGlobMatch/foo_foo1995=== PAUSE TestGlobMatch/foo_foo1996=== RUN TestGlobMatch/foo_bar1997=== PAUSE TestGlobMatch/foo_bar1998=== RUN TestGlobMatch/*_1999=== PAUSE TestGlobMatch/*_2000=== RUN TestGlobMatch/*_anything2001=== PAUSE TestGlobMatch/*_anything2002=== RUN TestGlobMatch/foo*_foo2003=== PAUSE TestGlobMatch/foo*_foo2004=== RUN TestGlobMatch/foo*_foobar2005=== PAUSE TestGlobMatch/foo*_foobar2006=== RUN TestGlobMatch/foo*_bar2007=== PAUSE TestGlobMatch/foo*_bar2008=== RUN TestGlobMatch/*bar_bar2009=== PAUSE TestGlobMatch/*bar_bar2010=== RUN TestGlobMatch/*bar_foobar2011=== PAUSE TestGlobMatch/*bar_foobar2012=== RUN TestGlobMatch/*bar_foo2013=== PAUSE TestGlobMatch/*bar_foo2014=== RUN TestGlobMatch/foo*bar_foobar2015=== PAUSE TestGlobMatch/foo*bar_foobar2016=== RUN TestGlobMatch/foo*bar_foo123bar2017=== PAUSE TestGlobMatch/foo*bar_foo123bar2018=== RUN TestGlobMatch/foo*bar_foobarbaz2019=== PAUSE TestGlobMatch/foo*bar_foobarbaz2020=== RUN TestGlobMatch/*/*_foo/bar2021=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2022=== CONT TestScopes_LegacyProviderDefaultsToWrite2023=== PAUSE TestGlobMatch/*/*_foo/bar2024=== RUN TestGlobMatch/*/*_foo2025=== PAUSE TestGlobMatch/*/*_foo2026=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2027=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2028=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02029=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02030=== RUN TestGlobMatch/refs/*/main_refs/heads/main2031=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2032=== RUN TestGlobMatch/fo?_foo2033=== PAUSE TestGlobMatch/fo?_foo2034=== RUN TestGlobMatch/fo?_fo2035=== PAUSE TestGlobMatch/fo?_fo2036=== RUN TestGlobMatch/fo?_fooo2037=== PAUSE TestGlobMatch/fo?_fooo2038=== RUN TestGlobMatch/?oo_foo2039=== PAUSE TestGlobMatch/?oo_foo2040=== RUN TestGlobMatch/?oo_boo2041=== PAUSE TestGlobMatch/?oo_boo2042=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2043=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2044=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2045=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2046=== CONT TestGlobMatch/foo_foo2047=== CONT TestValidateToken_WrongAudience2048=== CONT TestValidateToken_Expired2049=== CONT TestValidateToken_ValidToken2050=== CONT TestValidateToken_NoMatchingProvider2051=== CONT TestValidateToken_MultipleProviders2052=== CONT TestValidateToken_BoundSubjectMismatch2053=== CONT TestValidateToken_BoundClaimsMismatch2054=== CONT TestGlobMatch/*/*_foo2055=== CONT TestAudienceForIssuer2056--- PASS: TestAudienceForIssuer (0.00s)2057=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2058=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2059=== CONT TestGlobMatch/?oo_boo2060=== CONT TestGlobMatch/?oo_foo2061=== CONT TestGlobMatch/fo?_fooo2062=== CONT TestGlobMatch/fo?_fo2063=== CONT TestGlobMatch/fo?_foo2064=== CONT TestGlobMatch/refs/*/main_refs/heads/main2065=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02066=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2067=== CONT TestGlobMatch/*bar_bar2068=== CONT TestGlobMatch/*/*_foo/bar2069=== CONT TestGlobMatch/foo*bar_foobarbaz2070=== CONT TestGlobMatch/foo*bar_foo123bar2071=== CONT TestGlobMatch/foo*bar_foobar2072=== CONT TestGlobMatch/*bar_foo2073=== CONT TestGlobMatch/*bar_foobar2074=== CONT TestGlobMatch/foo*_foo2075=== CONT TestGlobMatch/foo*_bar2076=== CONT TestGlobMatch/foo*_foobar2077=== CONT TestNewValidator_KubernetesRequiresCA20782026/09/01 08:26:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60516/oidc20792026/09/01 08:26:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60517/oidc20802026/09/01 08:26:33 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60520/oidc20812026/09/01 08:26:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60526/oidc20822026/09/01 08:26:33 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60515/oidc20832026/09/01 08:26:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60518/oidc20842026/09/01 08:26:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60514/oidc20852026/09/01 08:26:33 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12320862026/09/01 08:26:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60530/oidc2087--- PASS: TestValidateToken_BoundSubjectMismatch (0.00s)2088=== CONT TestGlobMatch/*_2089=== CONT TestGlobMatch/*_anything2090=== CONT TestValidateToken_KubernetesServiceAccount2091--- PASS: TestValidateToken_WrongAudience (0.01s)2092=== CONT TestScopes_Rules2093--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2094=== CONT TestGlobMatch/foo_bar2095--- PASS: TestGlobMatch (0.00s)2096 --- PASS: TestGlobMatch/foo_foo (0.00s)2097 --- PASS: TestGlobMatch/*/*_foo (0.00s)2098 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2099 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2100 --- PASS: TestGlobMatch/?oo_boo (0.00s)2101 --- PASS: TestGlobMatch/?oo_foo (0.00s)2102 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2103 --- PASS: TestGlobMatch/fo?_fo (0.00s)2104 --- PASS: TestGlobMatch/fo?_foo (0.00s)2105 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2106 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2107 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2108 --- PASS: TestGlobMatch/*bar_bar (0.00s)2109 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2110 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2111 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2112 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2113 --- PASS: TestGlobMatch/*bar_foo (0.00s)2114 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2115 --- PASS: TestGlobMatch/foo*_foo (0.00s)2116 --- PASS: TestGlobMatch/foo*_bar (0.00s)2117 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2118 --- PASS: TestGlobMatch/*_ (0.00s)2119 --- PASS: TestGlobMatch/*_anything (0.00s)2120 --- PASS: TestGlobMatch/foo_bar (0.00s)21212026/09/01 08:26:33 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:60519/oidc2122--- PASS: TestValidateToken_ValidToken (0.01s)2123--- PASS: TestValidateToken_Expired (0.01s)2124=== CONT TestScopes_ConfigValidation21252026/09/01 08:26:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60537/oidc2126--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2127--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2128--- PASS: TestScopes_ConfigValidation (0.00s)2129--- PASS: TestValidateToken_MultipleProviders (0.01s)2130--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.01s)21312026/09/01 08:26:33 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:605362132--- PASS: TestScopes_Rules (0.01s)2133--- PASS: TestValidateToken_KubernetesServiceAccount (0.01s)21342026/09/01 08:26:33 http: TLS handshake error from 127.0.0.1:60535: read tcp 127.0.0.1:60532->127.0.0.1:60535: use of closed network connection2135--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2136PASS2137Running hook tests...2138=== RUN TestSendPathsEmpty2139=== PAUSE TestSendPathsEmpty2140=== RUN TestQueueEnqueueAndFetch2141=== PAUSE TestQueueEnqueueAndFetch2142=== RUN TestQueueDeduplication2143=== PAUSE TestQueueDeduplication2144=== RUN TestQueueRemove2145=== PAUSE TestQueueRemove2146=== RUN TestQueueFetchBatchLimit2147=== PAUSE TestQueueFetchBatchLimit2148=== RUN TestQueueRetryMovesToBack2149=== PAUSE TestQueueRetryMovesToBack2150=== RUN TestQueueFetchRemoveLifecycle2151=== PAUSE TestQueueFetchRemoveLifecycle2152=== RUN TestQueueConcurrentWriters2153=== PAUSE TestQueueConcurrentWriters2154=== RUN TestQueueRemoveLargeClosure2155=== PAUSE TestQueueRemoveLargeClosure2156=== RUN TestServerClientIntegration2157=== PAUSE TestServerClientIntegration2158=== RUN TestServerQueueError2159=== PAUSE TestServerQueueError2160=== RUN TestGetListenerSocketActivation2161 server_test.go:210: === RUN TestGetListenerSocketActivation2162 --- PASS: TestGetListenerSocketActivation (0.00s)2163 PASS2164 2165--- PASS: TestGetListenerSocketActivation (0.01s)2166=== RUN TestDrainIsolatesPoisonPath2167=== PAUSE TestDrainIsolatesPoisonPath2168=== RUN TestRunNotBlockedByPoisonHead2169=== PAUSE TestRunNotBlockedByPoisonHead2170=== RUN TestDrainGivesUpWhenServerDown2171=== PAUSE TestDrainGivesUpWhenServerDown2172=== RUN TestFailedPathPrunedByLaterClosure2173=== PAUSE TestFailedPathPrunedByLaterClosure2174=== RUN TestWorkerUploadsAndRemoves2175=== PAUSE TestWorkerUploadsAndRemoves2176=== RUN TestWorkerSkipsGCdPaths2177=== PAUSE TestWorkerSkipsGCdPaths2178=== RUN TestWorkerPrunesClosureDeps2179=== PAUSE TestWorkerPrunesClosureDeps2180=== RUN TestDrainTimeout2181=== PAUSE TestDrainTimeout2182=== CONT TestSendPathsEmpty2183=== CONT TestServerQueueError2184--- PASS: TestSendPathsEmpty (0.00s)2185=== CONT TestQueueFetchBatchLimit2186=== CONT TestQueueRemove2187=== CONT TestQueueDeduplication2188=== CONT TestQueueEnqueueAndFetch2189=== CONT TestQueueRetryMovesToBack2190=== CONT TestQueueRemoveLargeClosure2191=== CONT TestQueueConcurrentWriters2192=== CONT TestServerClientIntegration2193=== CONT TestWorkerUploadsAndRemoves21942026/09/01 08:26:33 ERROR Failed to queue paths error="permission denied" count=12195--- PASS: TestServerQueueError (0.00s)2196=== CONT TestDrainGivesUpWhenServerDown2197--- PASS: TestServerClientIntegration (0.00s)2198=== CONT TestFailedPathPrunedByLaterClosure21992026/09/01 08:26:33 INFO Uploading batch count=122002026/09/01 08:26:33 ERROR Upload failed error="upload failed" count=12201--- PASS: TestQueueEnqueueAndFetch (0.03s)2202=== CONT TestQueueFetchRemoveLifecycle22032026/09/01 08:26:33 INFO Uploading batch count=222042026/09/01 08:26:33 ERROR Upload failed error="upload failed" count=222052026/09/01 08:26:33 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-84290-1268021945/TestDrainGivesUpWhenServerDown4188060847/002/a22062026/09/01 08:26:33 INFO Upload queue status pending=222072026/09/01 08:26:33 INFO Uploading batch count=122082026/09/01 08:26:33 INFO Uploading batch count=22209--- PASS: TestQueueRemove (0.03s)2210=== CONT TestWorkerPrunesClosureDeps22112026/09/01 08:26:33 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-84290-1268021945/TestDrainGivesUpWhenServerDown4188060847/002/b2212--- PASS: TestQueueFetchBatchLimit (0.03s)2213=== CONT TestDrainTimeout22142026/09/01 08:26:33 INFO Uploading batch count=122152026/09/01 08:26:33 INFO Uploading batch count=222162026/09/01 08:26:33 ERROR Upload failed error="upload failed" count=222172026/09/01 08:26:33 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-84290-1268021945/TestDrainGivesUpWhenServerDown4188060847/002/c2218--- PASS: TestQueueRetryMovesToBack (0.03s)2219=== CONT TestWorkerSkipsGCdPaths22202026/09/01 08:26:33 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-84290-1268021945/TestDrainGivesUpWhenServerDown4188060847/002/d2221--- PASS: TestQueueDeduplication (0.03s)2222=== CONT TestRunNotBlockedByPoisonHead22232026/09/01 08:26:33 INFO Uploading batch count=222242026/09/01 08:26:33 ERROR Upload failed error="upload failed" count=222252026/09/01 08:26:33 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-84290-1268021945/TestDrainGivesUpWhenServerDown4188060847/002/e2226--- PASS: TestFailedPathPrunedByLaterClosure (0.03s)2227=== CONT TestDrainIsolatesPoisonPath22282026/09/01 08:26:33 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-84290-1268021945/TestDrainGivesUpWhenServerDown4188060847/002/f22292026/09/01 08:26:33 ERROR Drain finished with paths left in queue remaining=102230--- PASS: TestQueueFetchRemoveLifecycle (0.01s)22312026/09/01 08:26:33 INFO Uploading batch count=222322026/09/01 08:26:33 INFO Upload queue status pending=222332026/09/01 08:26:33 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-84290-1268021945/TestWorkerSkipsGCdPaths2660237523/002/nonexistent22342026/09/01 08:26:33 INFO Upload queue status pending=222352026/09/01 08:26:33 INFO Uploading batch count=122362026/09/01 08:26:33 INFO Uploading batch count=12237--- PASS: TestDrainGivesUpWhenServerDown (0.03s)22382026/09/01 08:26:33 INFO Uploading batch count=422392026/09/01 08:26:33 ERROR Upload failed error="upload failed" count=422402026/09/01 08:26:33 INFO Upload queue status pending=322412026/09/01 08:26:33 INFO Uploading batch count=122422026/09/01 08:26:33 ERROR Upload failed error="upload failed" count=122432026/09/01 08:26:33 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-84290-1268021945/TestDrainIsolatesPoisonPath2299519098/002/bbb22442026/09/01 08:26:33 INFO Uploading batch count=122452026/09/01 08:26:33 ERROR Upload failed error="upload failed" count=122462026/09/01 08:26:33 INFO Uploading batch count=122472026/09/01 08:26:33 ERROR Upload failed error="upload failed" count=122482026/09/01 08:26:33 INFO Uploading batch count=122492026/09/01 08:26:33 ERROR Upload failed error="upload failed" count=122502026/09/01 08:26:33 ERROR Drain finished with paths left in queue remaining=12251--- PASS: TestDrainIsolatesPoisonPath (0.01s)2252--- PASS: TestWorkerUploadsAndRemoves (0.05s)2253--- PASS: TestWorkerPrunesClosureDeps (0.02s)2254--- PASS: TestWorkerSkipsGCdPaths (0.02s)2255--- PASS: TestQueueRemoveLargeClosure (0.09s)2256--- PASS: TestQueueConcurrentWriters (0.17s)22572026/09/01 08:26:34 ERROR Upload failed error="context deadline exceeded" count=222582026/09/01 08:26:34 ERROR Drain finished with paths left in queue remaining=42259--- PASS: TestDrainTimeout (0.21s)22602026/09/01 08:26:34 INFO Uploading batch count=122612026/09/01 08:26:34 INFO Uploading batch count=122622026/09/01 08:26:34 INFO Uploading batch count=122632026/09/01 08:26:34 ERROR Upload failed error="upload failed" count=122642026/09/01 08:26:34 INFO Uploading batch count=122652026/09/01 08:26:34 ERROR Upload failed error="upload failed" count=122662026/09/01 08:26:34 INFO Uploading batch count=122672026/09/01 08:26:34 ERROR Upload failed error="upload failed" count=122682026/09/01 08:26:34 INFO Uploading batch count=122692026/09/01 08:26:34 ERROR Upload failed error="upload failed" count=122702026/09/01 08:26:34 ERROR Drain finished with paths left in queue remaining=12271--- PASS: TestRunNotBlockedByPoisonHead (1.01s)2272PASS