niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #165
· 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 TestParsePathInfoJSONMultiplePaths75=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths76=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths77=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths78=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths79=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths80=== CONT TestFileTokenMissing81=== CONT TestDumpPathMatchesNix82=== CONT TestPartSizeForNAR83--- PASS: TestResolveStorePath (0.00s)84=== CONT TestEncodeNixBase32WithRealHash85--- PASS: TestFileTokenMissing (0.00s)86=== RUN TestPartSizeForNAR/zero_stays_at_minimum87=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum88=== RUN TestPartSizeForNAR/small_stays_at_minimum89=== PAUSE TestPartSizeForNAR/small_stays_at_minimum90=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum91--- PASS: TestEncodeNixBase32WithRealHash (0.00s)92=== CONT TestScriptTokenEmptyCommand93--- PASS: TestScriptTokenEmptyCommand (0.00s)94=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess95=== CONT TestScriptTokenEmptyToken96=== CONT TestRateLimiterFeedback97=== CONT TestScriptTokenCachesUntilRefresh98=== RUN TestRateLimiterFeedback/429_enables_limiter99=== PAUSE TestRateLimiterFeedback/429_enables_limiter100=== RUN TestRateLimiterFeedback/503_enables_limiter101=== PAUSE TestRateLimiterFeedback/503_enables_limiter102=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter103=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter1042026/08/29 16:25:35 WARN Rate limiter enabled after throttle name=server-test rate=5105=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter106=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter107=== CONT TestPathInfoCACompatibility108=== RUN TestPathInfoCACompatibility/null_ca_field109=== CONT TestScriptTokenBadJSON110=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum111=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts112=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts113=== RUN TestPartSizeForNAR/1_TiB114=== PAUSE TestPartSizeForNAR/1_TiB115=== RUN TestPartSizeForNAR/5_TiB_S3_max_object116=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object117=== RUN TestPartSizeForNAR/capped_at_5_GiB118=== PAUSE TestPartSizeForNAR/capped_at_5_GiB119=== CONT TestFileTokenEmpty120=== PAUSE TestPathInfoCACompatibility/null_ca_field121=== CONT TestScriptTokenScriptFails122=== CONT TestScriptTokenNoExpiryRerunsEveryCall123=== RUN TestPathInfoCACompatibility/old_string_format_-_text124=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text125=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive126=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive127=== RUN TestPathInfoCACompatibility/new_structured_format_-_text128=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text129=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method130=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method131=== CONT TestSetClientTLSDoesNotMutateDefaultTransport132=== CONT TestFileTokenReadsAndCaches133--- PASS: TestDoServerRequestAttachesToken (0.00s)134--- PASS: TestFileTokenEmpty (0.00s)135--- PASS: TestFileTokenReadsAndCaches (0.00s)136=== CONT TestStaticToken137--- PASS: TestStaticToken (0.00s)138=== CONT TestDumpPathWriterError139=== CONT TestSetClientTLSErrors140--- PASS: TestScriptTokenScriptFails (0.00s)141=== CONT TestEncodeNixBase32142=== RUN TestEncodeNixBase32/test_string_hash143=== PAUSE TestEncodeNixBase32/test_string_hash144=== RUN TestEncodeNixBase32/empty_input145=== PAUSE TestEncodeNixBase32/empty_input146=== CONT TestFilterOversizedClosures147=== RUN TestFilterOversizedClosures/no_limit_keeps_everything148=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything149=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped150=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped151=== RUN TestFilterOversizedClosures/all_closures_skipped152=== PAUSE TestFilterOversizedClosures/all_closures_skipped153=== CONT TestDumpPathSingleFile154--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)155=== CONT TestCaseHackSuffix156=== RUN TestSetClientTLSErrors/missing_cert_file157=== PAUSE TestSetClientTLSErrors/missing_cert_file158=== RUN TestSetClientTLSErrors/missing_key_file159=== PAUSE TestSetClientTLSErrors/missing_key_file160=== RUN TestSetClientTLSErrors/missing_ca_file161=== PAUSE TestSetClientTLSErrors/missing_ca_file162=== RUN TestSetClientTLSErrors/invalid_ca_file163=== PAUSE TestSetClientTLSErrors/invalid_ca_file164=== CONT TestShellSplitErrors165--- PASS: TestShellSplitErrors (0.00s)166=== CONT TestSetClientTLS167=== RUN TestSetClientTLS/rejects_connection_without_client_cert168=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert169=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA170=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA171=== RUN TestSetClientTLS/preserves_debug_logging_transport172=== PAUSE TestSetClientTLS/preserves_debug_logging_transport173=== CONT TestGetStorePathHash174=== RUN TestGetStorePathHash/valid_store_path175=== PAUSE TestGetStorePathHash/valid_store_path176=== RUN TestGetStorePathHash/basename_without_hyphen_should_error177=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error178=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error179=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error180=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error181=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error182=== CONT TestParsePathInfoJSON183=== RUN TestParsePathInfoJSON/Nix_format184=== PAUSE TestParsePathInfoJSON/Nix_format185=== RUN TestParsePathInfoJSON/Lix_format186=== PAUSE TestParsePathInfoJSON/Lix_format187=== RUN TestParsePathInfoJSON/empty_input188=== PAUSE TestParsePathInfoJSON/empty_input189=== RUN TestParsePathInfoJSON/whitespace_only190=== PAUSE TestParsePathInfoJSON/whitespace_only191=== RUN TestParsePathInfoJSON/invalid_JSON192=== PAUSE TestParsePathInfoJSON/invalid_JSON193=== CONT TestPathInfoHashCompatibility194=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)195=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)196=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon197=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon198=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI199=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI200=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512201=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512202=== CONT TestShellSplit203--- PASS: TestShellSplit (0.00s)204=== CONT TestDoWithRetry_BodyReplayedViaGetBody205--- PASS: TestScriptTokenEmptyToken (0.01s)206=== CONT TestConvertHashToNix32207--- PASS: TestScriptTokenBadJSON (0.01s)208=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths209=== RUN TestConvertHashToNix32/SRI_format_to_Nix32210=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32211=== RUN TestConvertHashToNix32/already_Nix32_format212=== PAUSE TestConvertHashToNix32/already_Nix32_format213=== RUN TestConvertHashToNix32/invalid_format214--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)215 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)216 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)217=== CONT TestUploadMultipart_SupersededByPeer218=== PAUSE TestConvertHashToNix32/invalid_format219=== RUN TestUploadMultipart_SupersededByPeer/exists220=== PAUSE TestUploadMultipart_SupersededByPeer/exists221=== RUN TestUploadMultipart_SupersededByPeer/missing2222026/08/29 16:25:35 WARN Rate limiter enabled after throttle name=server-test rate=5223=== PAUSE TestUploadMultipart_SupersededByPeer/missing224=== CONT TestRateLimiterFeedback/429_enables_limiter2252026/08/29 16:25:35 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:56052226=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2272026/08/29 16:25:35 WARN Rate limiter backed off name=server-test rate=52282026/08/29 16:25:35 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:56052229=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2302026/08/29 16:25:35 WARN Rate limiter enabled after throttle name=server-test rate=52312026/08/29 16:25:35 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:56055232--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)233=== CONT TestRateLimiterFeedback/503_enables_limiter2342026/08/29 16:25:35 WARN Rate limiter backed off name=server-test rate=5235=== CONT TestPartSizeForNAR/zero_stays_at_minimum236=== CONT TestPartSizeForNAR/1_TiB237=== CONT TestPartSizeForNAR/capped_at_5_GiB238=== CONT TestPartSizeForNAR/5_TiB_S3_max_object239=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum240=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts241=== CONT TestPartSizeForNAR/small_stays_at_minimum242--- PASS: TestPartSizeForNAR (0.00s)243 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)244 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)245 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)246 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)247 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)248 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)249 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)250=== CONT TestPathInfoCACompatibility/null_ca_field251=== CONT TestPathInfoCACompatibility/new_structured_format_-_text252=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method253=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2542026/08/29 16:25:35 WARN Rate limiter enabled after throttle name=server-test rate=5255=== CONT TestPathInfoCACompatibility/old_string_format_-_text2562026/08/29 16:25:35 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:56060257=== CONT TestEncodeNixBase32/test_string_hash258=== CONT TestEncodeNixBase32/empty_input259--- PASS: TestEncodeNixBase32 (0.00s)260 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)261 --- PASS: TestEncodeNixBase32/empty_input (0.00s)262=== CONT TestFilterOversizedClosures/no_limit_keeps_everything263=== CONT TestFilterOversizedClosures/all_closures_skipped2642026/08/29 16:25:35 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=502652026/08/29 16:25:35 WARN Rate limiter backed off name=server-test rate=5266=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2672026/08/29 16:25:35 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=2000268--- PASS: TestFilterOversizedClosures (0.00s)269 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)270 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)271 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)272=== CONT TestSetClientTLSErrors/missing_cert_file273=== CONT TestSetClientTLSErrors/missing_ca_file274--- PASS: TestRateLimiterFeedback (0.00s)275 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)276 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)277 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)278 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)279=== CONT TestSetClientTLSErrors/invalid_ca_file280--- PASS: TestPathInfoCACompatibility (0.00s)281 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)282 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)283 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)284 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)285 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)286=== CONT TestSetClientTLSErrors/missing_key_file287=== CONT TestSetClientTLS/rejects_connection_without_client_cert288=== CONT TestGetStorePathHash/valid_store_path289=== CONT TestSetClientTLS/preserves_debug_logging_transport290=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA291--- PASS: TestSetClientTLSErrors (0.00s)292 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)293 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)294 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)295 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)296=== CONT TestParsePathInfoJSON/Nix_format297=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error298=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error299=== CONT TestGetStorePathHash/basename_without_hyphen_should_error300--- PASS: TestGetStorePathHash (0.00s)301 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)302 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)303 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)304 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)305=== CONT TestParsePathInfoJSON/whitespace_only306=== CONT TestParsePathInfoJSON/invalid_JSON307=== CONT TestParsePathInfoJSON/empty_input308=== CONT TestParsePathInfoJSON/Lix_format309=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)310=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI311=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon312=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512313--- PASS: TestParsePathInfoJSON (0.00s)314 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)315 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)316 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)317 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)318 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)319=== CONT TestConvertHashToNix32/SRI_format_to_Nix32320--- PASS: TestPathInfoHashCompatibility (0.00s)321 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)322 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)323 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)324 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)325=== CONT TestConvertHashToNix32/invalid_format326=== CONT TestUploadMultipart_SupersededByPeer/exists327=== CONT TestConvertHashToNix32/already_Nix32_format328--- PASS: TestConvertHashToNix32 (0.00s)329 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)330 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)331 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)332=== CONT TestUploadMultipart_SupersededByPeer/missing333--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)334 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)335 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)336--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)337--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)3382026/08/29 16:25:35 http: TLS handshake error from 127.0.0.1:56062: remote error: tls: bad certificate339--- PASS: TestSetClientTLS (0.00s)340 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)341 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)342 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)343--- PASS: TestDumpPathWriterError (0.03s)344--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)345--- PASS: TestDumpPathSingleFile (3.43s)346--- PASS: TestCaseHackSuffix (3.43s)347--- PASS: TestDumpPathMatchesNix (3.44s)348PASS349Running server tests...350The files belonging to this database system will be owned by user "_nixbld1".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-9565-1909913857/postgres3623871718/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-9565-1909913857/postgres3623871718/data -l logfile start3763772026-08-29 16:25:42.010 UTC [9753] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.5.0, compiled by clang version 21.1.8, 64-bit3782026-08-29 16:25:42.010 UTC [9753] LOG: listening on Unix socket "/nix/var/nix/builds/nix-9565-1909913857/postgres3623871718/.s.PGSQL.5432"3792026-08-29 16:25:42.013 UTC [9760] LOG: database system was shut down at 2026-08-29 16:25:41 UTC3802026-08-29 16:25:42.013 UTC [9753] LOG: database system is ready to accept connections381/nix/var/nix/builds/nix-9565-1909913857/postgres3623871718: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-08-29 16:25:44.028 UTC [9831] ERROR: relation "goose_db_version" does not exist at character 364162026-08-29 16:25:44.028 UTC [9831] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4172026/08/29 16:25:44 OK 20241026095416_initial_model.sql (4.05ms)4182026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (581.96µs)4192026/08/29 16:25:44 OK 20251218171726_add_pins.sql (817.46µs)4202026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (2.01ms)4212026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200004222026/08/29 16:25:44 OK 1_commit_pending_closure.sql (1.02ms)4232026/08/29 16:25:44 OK 2_object_stats_trigger.sql (225.17µs)4242026/08/29 16:25:44 goose: up to current file version: 2425--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.32s)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.02s)524=== RUN TestWatchdogSkipsWhenUnhealthy5252026/08/29 16:25:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5262026/08/29 16:25:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5272026/08/29 16:25:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5282026/08/29 16:25:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5292026/08/29 16:25:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5302026/08/29 16:25:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5312026/08/29 16:25:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5322026/08/29 16:25:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5332026/08/29 16:25:44 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"534--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)535=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle536=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle537=== RUN TestProxyWriteTimeout538=== PAUSE TestProxyWriteTimeout539=== RUN TestIsValidUploadKey540=== PAUSE TestIsValidUploadKey541=== RUN TestUploadHandlersRejectInvalidKeys542=== PAUSE TestUploadHandlersRejectInvalidKeys543=== RUN TestUploadHandlersRejectOversizedBody544=== PAUSE TestUploadHandlersRejectOversizedBody545=== RUN TestService_cleanupPendingClosuresHandler546=== PAUSE TestService_cleanupPendingClosuresHandler547=== RUN TestService_createPendingClosureHandler548=== PAUSE TestService_createPendingClosureHandler549=== RUN TestService_verifyS3Integrity550=== PAUSE TestService_verifyS3Integrity551=== RUN TestCompleteMultipartUnregistered552=== PAUSE TestCompleteMultipartUnregistered553=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT554=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT555=== CONT TestService_AuthMiddleware556=== CONT TestRedundantMultipartUpload557=== CONT TestReadProxyDisabled558=== CONT TestPinProtectsFromGC559=== CONT TestGCTaskStore_GetEmpty560--- PASS: TestGCTaskStore_GetEmpty (0.00s)561=== CONT TestService_healthCheckHandler562=== CONT TestService_readinessHandler563=== CONT TestReadRedirectUsesPublicS3URL564=== CONT TestReadProxyRangeRequest565=== CONT TestReadRedirectKeepsNarinfoProxied566=== CONT TestReadRedirectNar5672026-08-29 16:25:44.585 UTC [9853] ERROR: relation "goose_db_version" does not exist at character 365682026-08-29 16:25:44.585 UTC [9853] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5692026/08/29 16:25:44 OK 20241026095416_initial_model.sql (31.55ms)5702026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (826.96µs)5712026/08/29 16:25:44 OK 20251218171726_add_pins.sql (5.57ms)5722026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (3.29ms)5732026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200005742026/08/29 16:25:44 OK 1_commit_pending_closure.sql (6.72ms)5752026/08/29 16:25:44 OK 2_object_stats_trigger.sql (594.25µs)5762026/08/29 16:25:44 goose: up to current file version: 25772026-08-29 16:25:44.737 UTC [9857] ERROR: relation "goose_db_version" does not exist at character 365782026-08-29 16:25:44.737 UTC [9857] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5792026-08-29 16:25:44.737 UTC [9856] ERROR: relation "goose_db_version" does not exist at character 365802026-08-29 16:25:44.737 UTC [9856] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5812026-08-29 16:25:44.738 UTC [9858] ERROR: relation "goose_db_version" does not exist at character 365822026-08-29 16:25:44.738 UTC [9858] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5832026-08-29 16:25:44.738 UTC [9855] ERROR: relation "goose_db_version" does not exist at character 365842026-08-29 16:25:44.738 UTC [9855] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5852026-08-29 16:25:44.738 UTC [9854] ERROR: relation "goose_db_version" does not exist at character 365862026-08-29 16:25:44.738 UTC [9854] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5872026/08/29 16:25:44 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"588--- PASS: TestService_AuthMiddleware (0.46s)589=== CONT TestGCTaskStore_StartNew590--- PASS: TestGCTaskStore_StartNew (0.00s)591=== CONT TestGCTaskStore_ConflictDifferentParams592--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)593=== CONT TestGCTaskStore_DeduplicateSameParams594--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)595=== CONT TestResurrectedObjectNotDeleted5962026-08-29 16:25:44.765 UTC [9860] ERROR: relation "goose_db_version" does not exist at character 365972026-08-29 16:25:44.765 UTC [9860] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC5982026-08-29 16:25:44.765 UTC [9861] ERROR: relation "goose_db_version" does not exist at character 365992026-08-29 16:25:44.765 UTC [9861] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6002026-08-29 16:25:44.765 UTC [9859] ERROR: relation "goose_db_version" does not exist at character 366012026-08-29 16:25:44.765 UTC [9859] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6022026-08-29 16:25:44.765 UTC [9862] ERROR: relation "goose_db_version" does not exist at character 366032026-08-29 16:25:44.765 UTC [9862] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6042026/08/29 16:25:44 OK 20241026095416_initial_model.sql (56.74ms)6052026/08/29 16:25:44 OK 20241026095416_initial_model.sql (57.78ms)6062026/08/29 16:25:44 OK 20241026095416_initial_model.sql (57.78ms)6072026/08/29 16:25:44 OK 20241026095416_initial_model.sql (58.07ms)6082026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)6092026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (1.13ms)6102026/08/29 16:25:44 OK 20241026095416_initial_model.sql (58.4ms)6112026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (1.02ms)6122026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)6132026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (1.26ms)6142026/08/29 16:25:44 OK 20251218171726_add_pins.sql (2.85ms)6152026/08/29 16:25:44 OK 20251218171726_add_pins.sql (2.2ms)6162026/08/29 16:25:44 OK 20251218171726_add_pins.sql (2.82ms)6172026/08/29 16:25:44 OK 20251218171726_add_pins.sql (3.53ms)6182026/08/29 16:25:44 OK 20251218171726_add_pins.sql (6.69ms)6192026/08/29 16:25:44 OK 20241026095416_initial_model.sql (55.53ms)6202026/08/29 16:25:44 OK 20241026095416_initial_model.sql (67.86ms)6212026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (9.85ms)6222026/08/29 16:25:44 OK 20241026095416_initial_model.sql (66.58ms)6232026/08/29 16:25:44 OK 20241026095416_initial_model.sql (66.59ms)6242026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (11.24ms)6252026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (23.7ms)6262026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200006272026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (23.71ms)6282026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200006292026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (23.81ms)6302026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200006312026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (22.65ms)6322026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200006332026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (7.16ms)6342026/08/29 16:25:44 OK 20251210153512_drop_unused_gin_index.sql (7.1ms)6352026/08/29 16:25:44 OK 20251218171726_add_pins.sql (8.93ms)6362026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (19.79ms)6372026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200006382026/08/29 16:25:44 OK 1_commit_pending_closure.sql (1.8ms)6392026/08/29 16:25:44 OK 1_commit_pending_closure.sql (1.92ms)6402026/08/29 16:25:44 OK 2_object_stats_trigger.sql (378.71µs)6412026/08/29 16:25:44 goose: up to current file version: 26422026/08/29 16:25:44 OK 1_commit_pending_closure.sql (2.2ms)6432026/08/29 16:25:44 OK 1_commit_pending_closure.sql (2.4ms)6442026/08/29 16:25:44 OK 2_object_stats_trigger.sql (515.83µs)6452026/08/29 16:25:44 goose: up to current file version: 26462026/08/29 16:25:44 OK 2_object_stats_trigger.sql (214.96µs)6472026/08/29 16:25:44 goose: up to current file version: 26482026/08/29 16:25:44 OK 2_object_stats_trigger.sql (241.58µs)6492026/08/29 16:25:44 goose: up to current file version: 26502026/08/29 16:25:44 OK 20251218171726_add_pins.sql (9.21ms)6512026/08/29 16:25:44 OK 1_commit_pending_closure.sql (7.57ms)6522026/08/29 16:25:44 OK 2_object_stats_trigger.sql (163.71µs)6532026/08/29 16:25:44 goose: up to current file version: 26542026/08/29 16:25:44 OK 20251218171726_add_pins.sql (18.05ms)6552026/08/29 16:25:44 OK 20251218171726_add_pins.sql (18.46ms)6562026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (27.52ms)6572026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200006582026/08/29 16:25:44 OK 1_commit_pending_closure.sql (10.42ms)6592026/08/29 16:25:44 OK 2_object_stats_trigger.sql (147.67µs)6602026/08/29 16:25:44 goose: up to current file version: 26612026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (26.48ms)6622026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200006632026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (36.28ms)6642026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200006652026/08/29 16:25:44 OK 20260628120000_add_object_size_and_stats.sql (26.68ms)6662026/08/29 16:25:44 goose: successfully migrated database to version: 202606281200006672026/08/29 16:25:44 OK 1_commit_pending_closure.sql (2.3ms)6682026/08/29 16:25:44 OK 1_commit_pending_closure.sql (2.03ms)6692026/08/29 16:25:44 OK 1_commit_pending_closure.sql (2.05ms)6702026/08/29 16:25:44 OK 2_object_stats_trigger.sql (405µs)6712026/08/29 16:25:44 goose: up to current file version: 26722026/08/29 16:25:44 OK 2_object_stats_trigger.sql (474.5µs)6732026/08/29 16:25:44 goose: up to current file version: 26742026/08/29 16:25:44 OK 2_object_stats_trigger.sql (400.71µs)6752026/08/29 16:25:44 goose: up to current file version: 2676--- PASS: TestReadProxyDisabled (0.66s)677=== CONT TestReadProxyRootRedirectsToIndexHTML6782026/08/29 16:25:45 WARN readiness check failed error="closed pool"679--- PASS: TestService_readinessHandler (0.76s)680=== CONT TestReadProxyConditionalGet681--- PASS: TestReadRedirectUsesPublicS3URL (0.94s)682=== CONT TestReadProxyHead6832026/08/29 16:25:45 INFO Received uploads request method=POST path=/api/pending_closures6842026/08/29 16:25:45 INFO Received uploads request method=POST path=/api/pending_closures685--- PASS: TestReadRedirectKeepsNarinfoProxied (1.31s)686=== CONT TestReadProxyInvalidPath687=== NAME TestPinProtectsFromGC688 client_integration_test.go:648: Pinned store path: /nix/var/nix/builds/nix-9565-1909913857/TestPinProtectsFromGC2696257960/001/store/6l8bgp6vczwscz96b8mq89pmg96hkp75-pinned-file.txt689 client_integration_test.go:649: Unpinned store path: /nix/var/nix/builds/nix-9565-1909913857/TestPinProtectsFromGC2696257960/001/store/zvqsrkk35vhkm5cq4bgi01bb2khqs5cs-unpinned-file.txt690--- PASS: TestReadProxyRangeRequest (1.47s)691=== CONT TestReadProxy4046922026/08/29 16:25:45 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"693--- PASS: TestService_healthCheckHandler (1.61s)694=== CONT TestReadProxyNarStreaming6952026/08/29 16:25:45 INFO Received uploads request method=POST path=/api/pending_closures6962026/08/29 16:25:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)6972026/08/29 16:25:45 INFO Uploading 6l8bgp6vczwscz96b8mq89pmg96hkp75-pinned-file.txt (128B)6982026/08/29 16:25:46 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"6992026/08/29 16:25:46 WARN Failed to register uploaded object key=6l8bgp6vczwscz96b8mq89pmg96hkp75.ls error="server returned 404: 404 page not found\n"7002026/08/29 16:25:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign7012026/08/29 16:25:46 INFO Signed narinfos id=1 count=17022026/08/29 16:25:46 INFO Uploading 1 narinfos7032026/08/29 16:25:46 WARN Failed to register uploaded object key=6l8bgp6vczwscz96b8mq89pmg96hkp75.narinfo error="server returned 404: 404 page not found\n"7042026/08/29 16:25:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7052026/08/29 16:25:46 INFO Completed upload id=17062026/08/29 16:25:46 INFO Upload complete. (303ms)707--- PASS: TestReadRedirectNar (1.85s)708=== CONT TestReadProxyNarinfoAlreadyDecompressed7092026/08/29 16:25:46 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"7102026/08/29 16:25:46 INFO Received uploads request method=POST path=/api/pending_closures7112026/08/29 16:25:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7122026/08/29 16:25:46 INFO Uploading zvqsrkk35vhkm5cq4bgi01bb2khqs5cs-unpinned-file.txt (128B)7132026/08/29 16:25:46 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"7142026-08-29 16:25:46.290 UTC [9898] ERROR: relation "goose_db_version" does not exist at character 367152026-08-29 16:25:46.290 UTC [9898] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7162026/08/29 16:25:46 WARN Failed to register uploaded object key=zvqsrkk35vhkm5cq4bgi01bb2khqs5cs.ls error="server returned 404: 404 page not found\n"7172026/08/29 16:25:46 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign7182026/08/29 16:25:46 INFO Signed narinfos id=2 count=17192026/08/29 16:25:46 INFO Uploading 1 narinfos7202026/08/29 16:25:46 WARN Failed to register uploaded object key=zvqsrkk35vhkm5cq4bgi01bb2khqs5cs.narinfo error="server returned 404: 404 page not found\n"7212026/08/29 16:25:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete7222026/08/29 16:25:46 INFO Completed upload id=27232026/08/29 16:25:46 INFO Upload complete. (205ms)7242026/08/29 16:25:46 INFO Received create pin request method=POST path=/api/pins/myapp7252026/08/29 16:25:46 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-9565-1909913857/TestPinProtectsFromGC2696257960/001/store/6l8bgp6vczwscz96b8mq89pmg96hkp75-pinned-file.txt narinfo_key=6l8bgp6vczwscz96b8mq89pmg96hkp75.narinfo7262026/08/29 16:25:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures7272026/08/29 16:25:46 INFO Garbage collection started7282026/08/29 16:25:46 INFO Aborted multipart uploads count=07292026/08/29 16:25:46 WARN Force mode enabled - objects will be deleted immediately without grace period7302026/08/29 16:25:46 OK 20241026095416_initial_model.sql (157.07ms)7312026/08/29 16:25:46 OK 20251210153512_drop_unused_gin_index.sql (5.59ms)7322026/08/29 16:25:46 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=07332026/08/29 16:25:46 OK 20251218171726_add_pins.sql (46.93ms)7342026/08/29 16:25:46 INFO Vacuumed table table=pending_closures7352026-08-29 16:25:46.599 UTC [9903] ERROR: relation "goose_db_version" does not exist at character 367362026-08-29 16:25:46.599 UTC [9903] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7372026/08/29 16:25:46 OK 20260628120000_add_object_size_and_stats.sql (44.23ms)7382026/08/29 16:25:46 goose: successfully migrated database to version: 202606281200007392026/08/29 16:25:46 INFO Vacuumed table table=pending_objects7402026/08/29 16:25:46 INFO Vacuumed table table=multipart_uploads7412026/08/29 16:25:46 OK 1_commit_pending_closure.sql (9.83ms)7422026/08/29 16:25:46 OK 2_object_stats_trigger.sql (259.5µs)7432026/08/29 16:25:46 goose: up to current file version: 27442026/08/29 16:25:46 INFO Vacuumed table table=closures7452026/08/29 16:25:46 INFO Vacuumed table table=objects7462026/08/29 16:25:46 OK 20241026095416_initial_model.sql (156.31ms)7472026/08/29 16:25:46 OK 20251210153512_drop_unused_gin_index.sql (16.43ms)7482026-08-29 16:25:46.824 UTC [9904] ERROR: relation "goose_db_version" does not exist at character 367492026-08-29 16:25:46.824 UTC [9904] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7502026/08/29 16:25:46 OK 20251218171726_add_pins.sql (23.07ms)7512026/08/29 16:25:46 OK 20260628120000_add_object_size_and_stats.sql (11.58ms)7522026/08/29 16:25:46 goose: successfully migrated database to version: 202606281200007532026/08/29 16:25:46 OK 1_commit_pending_closure.sql (2.23ms)7542026/08/29 16:25:46 OK 2_object_stats_trigger.sql (292.92µs)7552026/08/29 16:25:46 goose: up to current file version: 2756--- PASS: TestResurrectedObjectNotDeleted (2.11s)757=== CONT TestReadProxyNarinfo7582026-08-29 16:25:46.921 UTC [9907] ERROR: relation "goose_db_version" does not exist at character 367592026-08-29 16:25:46.921 UTC [9907] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7602026/08/29 16:25:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7612026/08/29 16:25:47 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZjM0OWNlZmMtMWNjMS00NDFkLTk0OGYtNmFkZTE5MDA3MjM4LmYxMzczMGNiLTdiMzUtNDM3YS05ZjFmLTYyMWQ2OTY4OTM2M3gxNzg4MDIwNzQ1NDgzOTUyMDAw parts=12762--- PASS: TestRedundantMultipartUpload (2.73s)763=== CONT TestIsValidCachePath764=== RUN TestIsValidCachePath/narinfo765=== PAUSE TestIsValidCachePath/narinfo766=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars767=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars768=== RUN TestIsValidCachePath/nar_zst769=== PAUSE TestIsValidCachePath/nar_zst770=== RUN TestIsValidCachePath/nar_xz771=== PAUSE TestIsValidCachePath/nar_xz772=== RUN TestIsValidCachePath/nar_bz2773=== PAUSE TestIsValidCachePath/nar_bz2774=== RUN TestIsValidCachePath/nar_uncompressed775=== PAUSE TestIsValidCachePath/nar_uncompressed776=== RUN TestIsValidCachePath/ls777=== PAUSE TestIsValidCachePath/ls778=== RUN TestIsValidCachePath/log779=== PAUSE TestIsValidCachePath/log780=== RUN TestIsValidCachePath/realisation781=== PAUSE TestIsValidCachePath/realisation782=== RUN TestIsValidCachePath/nix-cache-info783=== PAUSE TestIsValidCachePath/nix-cache-info784=== RUN TestIsValidCachePath/index.html785=== PAUSE TestIsValidCachePath/index.html786=== RUN TestIsValidCachePath/traversal_parent787=== PAUSE TestIsValidCachePath/traversal_parent788=== RUN TestIsValidCachePath/traversal_in_middle789=== PAUSE TestIsValidCachePath/traversal_in_middle790=== RUN TestIsValidCachePath/invalid_char_e791=== PAUSE TestIsValidCachePath/invalid_char_e792=== RUN TestIsValidCachePath/invalid_char_u793=== PAUSE TestIsValidCachePath/invalid_char_u794=== RUN TestIsValidCachePath/random_path795=== PAUSE TestIsValidCachePath/random_path796=== RUN TestIsValidCachePath/empty797=== PAUSE TestIsValidCachePath/empty798=== RUN TestIsValidCachePath/leading_slash799=== PAUSE TestIsValidCachePath/leading_slash800=== RUN TestIsValidCachePath/wrong_extension801=== PAUSE TestIsValidCachePath/wrong_extension802=== RUN TestIsValidCachePath/short_hash803=== PAUSE TestIsValidCachePath/short_hash804=== CONT TestParseSingleRange805=== RUN TestParseSingleRange/none806=== PAUSE TestParseSingleRange/none807=== RUN TestParseSingleRange/unknown_unit808=== PAUSE TestParseSingleRange/unknown_unit809=== RUN TestParseSingleRange/multi-range_ignored810=== PAUSE TestParseSingleRange/multi-range_ignored811=== RUN TestParseSingleRange/malformed_no_dash812=== PAUSE TestParseSingleRange/malformed_no_dash813=== RUN TestParseSingleRange/malformed_both_empty814=== PAUSE TestParseSingleRange/malformed_both_empty815=== RUN TestParseSingleRange/malformed_end_before_start816=== PAUSE TestParseSingleRange/malformed_end_before_start817=== RUN TestParseSingleRange/closed818=== PAUSE TestParseSingleRange/closed819=== RUN TestParseSingleRange/open-ended820=== PAUSE TestParseSingleRange/open-ended821=== RUN TestParseSingleRange/end_clamped_to_size822=== PAUSE TestParseSingleRange/end_clamped_to_size823=== RUN TestParseSingleRange/suffix824=== PAUSE TestParseSingleRange/suffix825=== RUN TestParseSingleRange/suffix_exceeds_size826=== PAUSE TestParseSingleRange/suffix_exceeds_size827=== RUN TestParseSingleRange/single_byte828=== PAUSE TestParseSingleRange/single_byte829=== RUN TestParseSingleRange/start_past_EOF830=== PAUSE TestParseSingleRange/start_past_EOF831=== RUN TestParseSingleRange/start_far_past_EOF832=== PAUSE TestParseSingleRange/start_far_past_EOF833=== CONT TestIsValidUploadKey834=== RUN TestIsValidUploadKey/narinfo835=== PAUSE TestIsValidUploadKey/narinfo836=== RUN TestIsValidUploadKey/nar_zst837=== PAUSE TestIsValidUploadKey/nar_zst838=== RUN TestIsValidUploadKey/nar_xz839=== PAUSE TestIsValidUploadKey/nar_xz840=== RUN TestIsValidUploadKey/nar_plain841=== PAUSE TestIsValidUploadKey/nar_plain842=== RUN TestIsValidUploadKey/listing843=== PAUSE TestIsValidUploadKey/listing844=== RUN TestIsValidUploadKey/build_log845=== PAUSE TestIsValidUploadKey/build_log846=== RUN TestIsValidUploadKey/build_log_home-manager_file847=== PAUSE TestIsValidUploadKey/build_log_home-manager_file848=== RUN TestIsValidUploadKey/build_log_plus_in_name849=== PAUSE TestIsValidUploadKey/build_log_plus_in_name850=== RUN TestIsValidUploadKey/build_log_question_mark851=== PAUSE TestIsValidUploadKey/build_log_question_mark852=== RUN TestIsValidUploadKey/build_log_equals853=== PAUSE TestIsValidUploadKey/build_log_equals854=== RUN TestIsValidUploadKey/realisation855=== PAUSE TestIsValidUploadKey/realisation856=== RUN TestIsValidUploadKey/realisation_plus_in_output857=== PAUSE TestIsValidUploadKey/realisation_plus_in_output858=== RUN TestIsValidUploadKey/nix-cache-info859=== PAUSE TestIsValidUploadKey/nix-cache-info860=== RUN TestIsValidUploadKey/index.html861=== PAUSE TestIsValidUploadKey/index.html862=== RUN TestIsValidUploadKey/narinfo_key,_nar_type863=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type864=== RUN TestIsValidUploadKey/nar_key,_narinfo_type865=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type866=== RUN TestIsValidUploadKey/listing_key,_narinfo_type867=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type868=== RUN TestIsValidUploadKey/traversal869=== PAUSE TestIsValidUploadKey/traversal870=== RUN TestIsValidUploadKey/traversal_nar871=== PAUSE TestIsValidUploadKey/traversal_nar872=== RUN TestIsValidUploadKey/absolute873=== PAUSE TestIsValidUploadKey/absolute874=== RUN TestIsValidUploadKey/empty_key875=== PAUSE TestIsValidUploadKey/empty_key876=== RUN TestIsValidUploadKey/unknown_type877=== PAUSE TestIsValidUploadKey/unknown_type878=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT879--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.10s)880=== CONT TestCompleteMultipartUnregistered8812026/08/29 16:25:47 OK 20241026095416_initial_model.sql (208.69ms)8822026/08/29 16:25:47 OK 20251210153512_drop_unused_gin_index.sql (3.03ms)8832026/08/29 16:25:47 OK 20251218171726_add_pins.sql (10.59ms)8842026/08/29 16:25:47 OK 20241026095416_initial_model.sql (93.55ms)8852026/08/29 16:25:47 OK 20251210153512_drop_unused_gin_index.sql (1.5ms)8862026/08/29 16:25:47 OK 20260628120000_add_object_size_and_stats.sql (30.48ms)8872026/08/29 16:25:47 goose: successfully migrated database to version: 202606281200008882026/08/29 16:25:47 OK 1_commit_pending_closure.sql (10.38ms)8892026/08/29 16:25:47 OK 2_object_stats_trigger.sql (409.83µs)8902026/08/29 16:25:47 goose: up to current file version: 28912026/08/29 16:25:47 OK 20251218171726_add_pins.sql (31.43ms)8922026/08/29 16:25:47 OK 20260628120000_add_object_size_and_stats.sql (49.14ms)8932026/08/29 16:25:47 goose: successfully migrated database to version: 202606281200008942026/08/29 16:25:47 OK 1_commit_pending_closure.sql (9.05ms)8952026/08/29 16:25:47 OK 2_object_stats_trigger.sql (1.87ms)8962026/08/29 16:25:47 goose: up to current file version: 2897--- PASS: TestReadProxyConditionalGet (2.22s)898=== CONT TestService_verifyS3Integrity899--- PASS: TestReadProxyHead (2.18s)900=== CONT TestService_createPendingClosureHandler9012026-08-29 16:25:47.516 UTC [9916] ERROR: relation "goose_db_version" does not exist at character 369022026-08-29 16:25:47.516 UTC [9916] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9032026-08-29 16:25:47.516 UTC [9917] ERROR: relation "goose_db_version" does not exist at character 369042026-08-29 16:25:47.516 UTC [9917] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9052026-08-29 16:25:47.551 UTC [9918] ERROR: relation "goose_db_version" does not exist at character 369062026-08-29 16:25:47.551 UTC [9918] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9072026/08/29 16:25:47 OK 20241026095416_initial_model.sql (14.51ms)9082026/08/29 16:25:47 OK 20241026095416_initial_model.sql (15.2ms)9092026/08/29 16:25:47 OK 20251210153512_drop_unused_gin_index.sql (1.12ms)9102026/08/29 16:25:47 OK 20251210153512_drop_unused_gin_index.sql (1ms)9112026/08/29 16:25:47 OK 20251218171726_add_pins.sql (1.11ms)9122026/08/29 16:25:47 OK 20251218171726_add_pins.sql (2.28ms)9132026/08/29 16:25:47 OK 20260628120000_add_object_size_and_stats.sql (5.89ms)9142026/08/29 16:25:47 goose: successfully migrated database to version: 202606281200009152026/08/29 16:25:47 OK 1_commit_pending_closure.sql (1.07ms)9162026/08/29 16:25:47 OK 2_object_stats_trigger.sql (220.71µs)9172026/08/29 16:25:47 goose: up to current file version: 29182026-08-29 16:25:47.573 UTC [9919] ERROR: relation "goose_db_version" does not exist at character 369192026-08-29 16:25:47.573 UTC [9919] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9202026/08/29 16:25:47 OK 20241026095416_initial_model.sql (45.81ms)9212026/08/29 16:25:47 OK 20260628120000_add_object_size_and_stats.sql (38.39ms)9222026/08/29 16:25:47 goose: successfully migrated database to version: 202606281200009232026/08/29 16:25:47 OK 1_commit_pending_closure.sql (1.6ms)9242026/08/29 16:25:47 OK 2_object_stats_trigger.sql (197.33µs)9252026/08/29 16:25:47 goose: up to current file version: 29262026/08/29 16:25:47 OK 20251210153512_drop_unused_gin_index.sql (6.85ms)9272026/08/29 16:25:47 OK 20251218171726_add_pins.sql (26.64ms)928--- PASS: TestReadProxy404 (1.89s)929=== CONT TestService_cleanupPendingClosuresHandler9302026/08/29 16:25:47 OK 20260628120000_add_object_size_and_stats.sql (36.74ms)9312026/08/29 16:25:47 goose: successfully migrated database to version: 202606281200009322026/08/29 16:25:47 OK 1_commit_pending_closure.sql (5.98ms)9332026/08/29 16:25:47 OK 2_object_stats_trigger.sql (258.96µs)9342026/08/29 16:25:47 goose: up to current file version: 29352026/08/29 16:25:47 OK 20241026095416_initial_model.sql (127.8ms)9362026/08/29 16:25:47 OK 20251210153512_drop_unused_gin_index.sql (13.56ms)9372026/08/29 16:25:47 OK 20251218171726_add_pins.sql (27.61ms)938--- PASS: TestReadProxyInvalidPath (2.18s)939=== CONT TestUploadHandlersRejectOversizedBody9402026/08/29 16:25:47 OK 20260628120000_add_object_size_and_stats.sql (36.45ms)9412026/08/29 16:25:47 goose: successfully migrated database to version: 202606281200009422026/08/29 16:25:47 OK 1_commit_pending_closure.sql (5.34ms)943=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure944=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure945=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart946=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart947=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts948=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts949=== CONT TestUploadHandlersRejectInvalidKeys950=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info951=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info952=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal953=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal954=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key955=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key956=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key957=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key958=== CONT TestService_NativeMTLS9592026/08/29 16:25:47 OK 2_object_stats_trigger.sql (2.18ms)9602026/08/29 16:25:47 goose: up to current file version: 2961--- PASS: TestReadProxyNarStreaming (2.03s)962=== CONT TestOrphanedObjectsGCStressTest963--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.93s)964=== CONT TestOrphanedObjectsGC9652026-08-29 16:25:48.227 UTC [9928] ERROR: relation "goose_db_version" does not exist at character 369662026-08-29 16:25:48.227 UTC [9928] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9672026/08/29 16:25:48 OK 20241026095416_initial_model.sql (19.23ms)9682026/08/29 16:25:48 OK 20251210153512_drop_unused_gin_index.sql (12.27ms)9692026-08-29 16:25:48.270 UTC [9930] ERROR: relation "goose_db_version" does not exist at character 369702026-08-29 16:25:48.270 UTC [9930] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9712026-08-29 16:25:48.270 UTC [9929] ERROR: relation "goose_db_version" does not exist at character 369722026-08-29 16:25:48.270 UTC [9929] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9732026/08/29 16:25:48 OK 20251218171726_add_pins.sql (27.34ms)9742026/08/29 16:25:48 OK 20260628120000_add_object_size_and_stats.sql (10.24ms)9752026/08/29 16:25:48 goose: successfully migrated database to version: 202606281200009762026/08/29 16:25:48 OK 1_commit_pending_closure.sql (8.87ms)9772026/08/29 16:25:48 OK 2_object_stats_trigger.sql (264.17µs)9782026/08/29 16:25:48 goose: up to current file version: 29792026/08/29 16:25:48 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=0980=== NAME TestPinProtectsFromGC981 client_integration_test.go:711: Pin successfully protected closure from garbage collection9822026/08/29 16:25:48 OK 20241026095416_initial_model.sql (143.04ms)9832026/08/29 16:25:48 OK 20241026095416_initial_model.sql (155.07ms)9842026/08/29 16:25:48 OK 20251210153512_drop_unused_gin_index.sql (18.21ms)9852026/08/29 16:25:48 OK 20251210153512_drop_unused_gin_index.sql (5.58ms)9862026/08/29 16:25:48 OK 20251218171726_add_pins.sql (25.48ms)987--- PASS: TestReadProxyNarinfo (1.62s)988=== CONT TestObjectStatsTrigger9892026/08/29 16:25:48 OK 20251218171726_add_pins.sql (33.24ms)990--- PASS: TestPinProtectsFromGC (4.20s)991=== CONT TestMultipartCleanup9922026/08/29 16:25:48 OK 20260628120000_add_object_size_and_stats.sql (31.09ms)9932026/08/29 16:25:48 goose: successfully migrated database to version: 202606281200009942026/08/29 16:25:48 OK 1_commit_pending_closure.sql (3.26ms)9952026/08/29 16:25:48 OK 20260628120000_add_object_size_and_stats.sql (25.55ms)9962026/08/29 16:25:48 goose: successfully migrated database to version: 202606281200009972026/08/29 16:25:48 OK 2_object_stats_trigger.sql (732.21µs)9982026/08/29 16:25:48 goose: up to current file version: 29992026/08/29 16:25:48 OK 1_commit_pending_closure.sql (2.45ms)10002026/08/29 16:25:48 OK 2_object_stats_trigger.sql (557.5µs)10012026/08/29 16:25:48 goose: up to current file version: 210022026/08/29 16:25:48 INFO Received uploads request method=POST path=/api/pending_closures1003--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.71s)1004=== CONT TestServerTLSConfig1005=== RUN TestServerTLSConfig/no_client_CA1006=== PAUSE TestServerTLSConfig/no_client_CA1007=== RUN TestServerTLSConfig/missing_CA_file1008=== PAUSE TestServerTLSConfig/missing_CA_file1009=== RUN TestServerTLSConfig/not_a_PEM_file1010=== PAUSE TestServerTLSConfig/not_a_PEM_file1011=== CONT TestCacheConfigHandler1012=== RUN TestCacheConfigHandler/full_config,_no_issuer1013=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1014=== RUN TestCacheConfigHandler/no_cache_url_configured1015=== PAUSE TestCacheConfigHandler/no_cache_url_configured1016=== RUN TestCacheConfigHandler/no_signing_keys1017=== PAUSE TestCacheConfigHandler/no_signing_keys1018=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1019=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1020=== CONT TestClientWithDependencies10212026/08/29 16:25:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10222026/08/29 16:25:48 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1023--- PASS: TestCompleteMultipartUnregistered (1.76s)1024=== CONT TestClientMultipleUploads10252026-08-29 16:25:48.936 UTC [9939] ERROR: relation "goose_db_version" does not exist at character 3610262026-08-29 16:25:48.936 UTC [9939] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10272026-08-29 16:25:49.017 UTC [9940] ERROR: relation "goose_db_version" does not exist at character 3610282026-08-29 16:25:49.017 UTC [9940] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10292026/08/29 16:25:49 OK 20241026095416_initial_model.sql (91.01ms)10302026/08/29 16:25:49 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)10312026/08/29 16:25:49 OK 20251218171726_add_pins.sql (8.11ms)10322026/08/29 16:25:49 OK 20260628120000_add_object_size_and_stats.sql (33.59ms)10332026/08/29 16:25:49 goose: successfully migrated database to version: 2026062812000010342026/08/29 16:25:49 OK 1_commit_pending_closure.sql (5.83ms)10352026/08/29 16:25:49 OK 2_object_stats_trigger.sql (541.38µs)10362026/08/29 16:25:49 goose: up to current file version: 210372026-08-29 16:25:49.140 UTC [9941] ERROR: relation "goose_db_version" does not exist at character 3610382026-08-29 16:25:49.140 UTC [9941] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10392026/08/29 16:25:49 OK 20241026095416_initial_model.sql (120.29ms)10402026/08/29 16:25:49 OK 20251210153512_drop_unused_gin_index.sql (7.25ms)10412026/08/29 16:25:49 OK 20251218171726_add_pins.sql (43.96ms)10422026-08-29 16:25:49.259 UTC [9942] ERROR: relation "goose_db_version" does not exist at character 3610432026-08-29 16:25:49.259 UTC [9942] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10442026/08/29 16:25:49 OK 20260628120000_add_object_size_and_stats.sql (28.92ms)10452026/08/29 16:25:49 goose: successfully migrated database to version: 2026062812000010462026/08/29 16:25:49 OK 1_commit_pending_closure.sql (16.6ms)10472026/08/29 16:25:49 OK 2_object_stats_trigger.sql (881.04µs)10482026/08/29 16:25:49 goose: up to current file version: 210492026/08/29 16:25:49 INFO Received uploads request method=POST path=/api/pending_closures10502026/08/29 16:25:49 OK 20241026095416_initial_model.sql (221.31ms)10512026/08/29 16:25:49 OK 20251210153512_drop_unused_gin_index.sql (14.43ms)10522026/08/29 16:25:49 OK 20251218171726_add_pins.sql (47.15ms)10532026/08/29 16:25:49 OK 20260628120000_add_object_size_and_stats.sql (40.56ms)10542026/08/29 16:25:49 goose: successfully migrated database to version: 2026062812000010552026/08/29 16:25:49 INFO Received uploads request method=POST path=/api/pending_closures10562026/08/29 16:25:49 INFO Received uploads request method=POST path=/api/pending_closures10572026/08/29 16:25:49 INFO Received uploads request method=POST path=/api/pending_closures10582026/08/29 16:25:49 OK 1_commit_pending_closure.sql (8.04ms)10592026/08/29 16:25:49 OK 2_object_stats_trigger.sql (719µs)10602026/08/29 16:25:49 goose: up to current file version: 210612026/08/29 16:25:49 OK 20241026095416_initial_model.sql (240.01ms)10622026/08/29 16:25:49 OK 20251210153512_drop_unused_gin_index.sql (17.31ms)10632026/08/29 16:25:49 INFO Received cleanup request method=DELETE path=/api/pending_closures10642026/08/29 16:25:49 INFO Aborted multipart uploads count=010652026/08/29 16:25:49 INFO Received uploads request method=POST path=/api/pending_closures10662026/08/29 16:25:49 OK 20251218171726_add_pins.sql (127.3ms)10672026/08/29 16:25:49 OK 20260628120000_add_object_size_and_stats.sql (52.73ms)10682026/08/29 16:25:49 goose: successfully migrated database to version: 2026062812000010692026/08/29 16:25:49 OK 1_commit_pending_closure.sql (18.29ms)10702026/08/29 16:25:49 OK 2_object_stats_trigger.sql (976.25µs)10712026/08/29 16:25:49 goose: up to current file version: 210722026/08/29 16:25:49 INFO Received cleanup request method=DELETE path=/api/pending_closures10732026/08/29 16:25:49 INFO Aborted multipart uploads count=110742026/08/29 16:25:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10752026-08-29 16:25:49.852 UTC [9941] ERROR: Closure does not exist: id=110762026-08-29 16:25:49.852 UTC [9941] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE10772026-08-29 16:25:49.852 UTC [9941] STATEMENT: -- name: CommitPendingClosure :exec1078 SELECT commit_pending_closure($1::bigint)1079 1080--- PASS: TestService_cleanupPendingClosuresHandler (2.19s)1081=== CONT TestClientIntegration10822026/08/29 16:25:50 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10832026/08/29 16:25:50 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1084--- PASS: TestService_NativeMTLS (2.21s)1085=== CONT TestClientErrorHandling1086=== RUN TestClientErrorHandling/InvalidStorePath1087=== PAUSE TestClientErrorHandling/InvalidStorePath1088=== RUN TestClientErrorHandling/InvalidAuthToken1089=== PAUSE TestClientErrorHandling/InvalidAuthToken1090=== RUN TestClientErrorHandling/ServerNotAvailable1091=== PAUSE TestClientErrorHandling/ServerNotAvailable1092=== CONT TestClientCADerivations10932026-08-29 16:25:50.154 UTC [9945] ERROR: relation "goose_db_version" does not exist at character 3610942026-08-29 16:25:50.154 UTC [9945] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10952026/08/29 16:25:50 OK 20241026095416_initial_model.sql (241.09ms)10962026/08/29 16:25:50 OK 20251210153512_drop_unused_gin_index.sql (18.76ms)10972026/08/29 16:25:50 OK 20251218171726_add_pins.sql (11.26ms)10982026/08/29 16:25:50 OK 20260628120000_add_object_size_and_stats.sql (38.98ms)10992026/08/29 16:25:50 goose: successfully migrated database to version: 2026062812000011002026/08/29 16:25:50 OK 1_commit_pending_closure.sql (13.82ms)11012026/08/29 16:25:50 OK 2_object_stats_trigger.sql (520.17µs)11022026/08/29 16:25:50 goose: up to current file version: 211032026-08-29 16:25:50.693 UTC [9949] ERROR: relation "goose_db_version" does not exist at character 3611042026-08-29 16:25:50.693 UTC [9949] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11052026-08-29 16:25:50.901 UTC [9952] ERROR: relation "goose_db_version" does not exist at character 3611062026-08-29 16:25:50.901 UTC [9952] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11072026-08-29 16:25:50.932 UTC [9953] ERROR: relation "goose_db_version" does not exist at character 3611082026-08-29 16:25:50.932 UTC [9953] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11092026/08/29 16:25:51 OK 20241026095416_initial_model.sql (257.39ms)11102026/08/29 16:25:51 OK 20251210153512_drop_unused_gin_index.sql (10.48ms)11112026/08/29 16:25:51 OK 20251218171726_add_pins.sql (41.88ms)11122026/08/29 16:25:51 OK 20260628120000_add_object_size_and_stats.sql (44.58ms)11132026/08/29 16:25:51 goose: successfully migrated database to version: 2026062812000011142026/08/29 16:25:51 OK 1_commit_pending_closure.sql (11.76ms)11152026/08/29 16:25:51 OK 2_object_stats_trigger.sql (677µs)11162026/08/29 16:25:51 goose: up to current file version: 211172026/08/29 16:25:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11182026/08/29 16:25:51 OK 20241026095416_initial_model.sql (286.78ms)11192026-08-29 16:25:51.305 UTC [9954] ERROR: relation "goose_db_version" does not exist at character 3611202026-08-29 16:25:51.305 UTC [9954] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11212026/08/29 16:25:51 OK 20251210153512_drop_unused_gin_index.sql (22.57ms)11222026/08/29 16:25:51 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZjM0OWNlZmMtMWNjMS00NDFkLTk0OGYtNmFkZTE5MDA3MjM4LjkxZmNlZDA3LTJjN2UtNGYyYi1iODFhLTBjZGNjMGEzNWI4ZngxNzg4MDIwNzQ5Mzc2NTc2MDAw parts=1011232026/08/29 16:25:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11242026/08/29 16:25:51 INFO Completed upload id=111252026/08/29 16:25:51 INFO Received uploads request method=POST path=/api/pending_closures11262026/08/29 16:25:51 INFO Received uploads request method=POST path=/api/pending_closures11272026/08/29 16:25:51 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11282026/08/29 16:25:51 WARN Found objects in DB but missing from S3, will re-upload count=11129--- PASS: TestService_verifyS3Integrity (4.05s)1130=== CONT TestCacheStatsHandler11312026/08/29 16:25:51 OK 20251218171726_add_pins.sql (44.65ms)11322026/08/29 16:25:51 OK 20241026095416_initial_model.sql (342.21ms)11332026/08/29 16:25:51 OK 20251210153512_drop_unused_gin_index.sql (20.33ms)11342026/08/29 16:25:51 OK 20260628120000_add_object_size_and_stats.sql (45.94ms)11352026/08/29 16:25:51 goose: successfully migrated database to version: 2026062812000011362026/08/29 16:25:51 OK 1_commit_pending_closure.sql (9.28ms)11372026/08/29 16:25:51 OK 2_object_stats_trigger.sql (609.79µs)11382026/08/29 16:25:51 goose: up to current file version: 211392026/08/29 16:25:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11402026/08/29 16:25:51 OK 20251218171726_add_pins.sql (62.31ms)11412026/08/29 16:25:51 OK 20260628120000_add_object_size_and_stats.sql (57.91ms)11422026/08/29 16:25:51 goose: successfully migrated database to version: 2026062812000011432026/08/29 16:25:51 OK 1_commit_pending_closure.sql (11.3ms)11442026/08/29 16:25:51 OK 2_object_stats_trigger.sql (1.04ms)11452026/08/29 16:25:51 goose: up to current file version: 211462026/08/29 16:25:51 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZjM0OWNlZmMtMWNjMS00NDFkLTk0OGYtNmFkZTE5MDA3MjM4LjM3NzE3MTQ0LWQ4ZDMtNGRiNy04OTYzLTMzNTNlMTFhMjJiZngxNzg4MDIwNzQ5NTY2ODAzMDAw parts=1011472026/08/29 16:25:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11482026/08/29 16:25:51 INFO Completed upload id=111492026/08/29 16:25:51 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011502026/08/29 16:25:51 INFO Received uploads request method=POST path=/api/pending_closures11512026/08/29 16:25:51 INFO Starting cleanup of old closures method=DELETE path=/api/closures11522026/08/29 16:25:51 INFO Aborted multipart uploads count=011532026/08/29 16:25:51 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=011542026/08/29 16:25:51 OK 20241026095416_initial_model.sql (232.24ms)11552026/08/29 16:25:51 INFO Vacuumed table table=pending_closures11562026/08/29 16:25:51 OK 20251210153512_drop_unused_gin_index.sql (14.56ms)11572026/08/29 16:25:51 INFO Vacuumed table table=pending_objects1158--- PASS: TestObjectStatsTrigger (3.19s)1159=== CONT TestGCBugBareHashReferences11602026-08-29 16:25:51.684 UTC [9958] ERROR: relation "goose_db_version" does not exist at character 3611612026-08-29 16:25:51.684 UTC [9958] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11622026/08/29 16:25:51 OK 20251218171726_add_pins.sql (45.53ms)11632026/08/29 16:25:51 INFO Vacuumed table table=multipart_uploads11642026/08/29 16:25:51 OK 20260628120000_add_object_size_and_stats.sql (49.65ms)11652026/08/29 16:25:51 goose: successfully migrated database to version: 2026062812000011662026/08/29 16:25:51 INFO Received uploads request method=POST path=/api/pending_closures11672026/08/29 16:25:51 OK 1_commit_pending_closure.sql (69.74ms)11682026/08/29 16:25:51 INFO Vacuumed table table=closures11692026/08/29 16:25:51 OK 2_object_stats_trigger.sql (1.64ms)11702026/08/29 16:25:51 goose: up to current file version: 211712026/08/29 16:25:51 INFO Vacuumed table table=objects11722026/08/29 16:25:51 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001173--- PASS: TestService_createPendingClosureHandler (4.46s)1174=== CONT TestGCMetrics11752026/08/29 16:25:52 INFO Received cleanup request method=DELETE path=/api/pending_closures11762026/08/29 16:25:52 INFO Aborted multipart uploads count=11177--- PASS: TestMultipartCleanup (3.54s)1178=== CONT TestParseSize1179--- PASS: TestParseSize (0.00s)1180=== CONT TestProxyWriteTimeout1181=== RUN TestProxyWriteTimeout/narinfo1182=== PAUSE TestProxyWriteTimeout/narinfo1183=== RUN TestProxyWriteTimeout/1_GiB_nar1184=== PAUSE TestProxyWriteTimeout/1_GiB_nar1185=== RUN TestProxyWriteTimeout/10_GiB_nar1186=== PAUSE TestProxyWriteTimeout/10_GiB_nar1187=== RUN TestProxyWriteTimeout/unknown_size1188=== PAUSE TestProxyWriteTimeout/unknown_size1189=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle11902026/08/29 16:25:52 OK 20241026095416_initial_model.sql (275.16ms)11912026/08/29 16:25:52 OK 20251210153512_drop_unused_gin_index.sql (12.99ms)11922026/08/29 16:25:52 OK 20251218171726_add_pins.sql (38.14ms)11932026/08/29 16:25:52 OK 20260628120000_add_object_size_and_stats.sql (32.64ms)11942026/08/29 16:25:52 goose: successfully migrated database to version: 2026062812000011952026/08/29 16:25:52 OK 1_commit_pending_closure.sql (15.44ms)11962026/08/29 16:25:52 OK 2_object_stats_trigger.sql (294.13µs)11972026/08/29 16:25:52 goose: up to current file version: 21198=== NAME TestClientMultipleUploads1199 client_integration_test.go:339: Created store path 0: /nix/var/nix/builds/nix-9565-1909913857/TestClientMultipleUploads1525386242/001/store/nb6yfqs3hf2flcpfy7v6j4w61b0zdq9k-test-file-0.txt1200=== NAME TestOrphanedObjectsGC1201 orphaned_objects_gc_test.go:290: GC Test Summary:1202 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1203 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1204 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1205 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1206 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1207--- PASS: TestOrphanedObjectsGC (4.50s)1208=== CONT TestSkippedUploadsHandler12092026/08/29 16:25:52 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001210--- PASS: TestSkippedUploadsHandler (0.00s)1211=== CONT TestResolveDBConnectionString12122026-08-29 16:25:52.587 UTC [9970] ERROR: relation "goose_db_version" does not exist at character 3612132026-08-29 16:25:52.587 UTC [9970] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1214=== RUN TestResolveDBConnectionString/flag_wins1215=== PAUSE TestResolveDBConnectionString/flag_wins1216=== RUN TestResolveDBConnectionString/file_when_flag_empty1217=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1218=== RUN TestResolveDBConnectionString/missing_file_is_an_error1219=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1220=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1221=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1222=== RUN TestResolveDBConnectionString/nothing_configured1223=== PAUSE TestResolveDBConnectionString/nothing_configured1224=== CONT TestCreatePendingClosureRejectsOversizedNAR12252026/08/29 16:25:52 INFO Received uploads request method=POST path=/api/pending_closures1226--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1227=== CONT TestMetricsInventory1228=== NAME TestClientMultipleUploads1229 client_integration_test.go:339: Created store path 1: /nix/var/nix/builds/nix-9565-1909913857/TestClientMultipleUploads1525386242/001/store/glijzj1inrqjmdgmz49xw7iw2wv1yfx3-test-file-1.txt1230 client_integration_test.go:339: Created store path 2: /nix/var/nix/builds/nix-9565-1909913857/TestClientMultipleUploads1525386242/001/store/2m0as8prl2z5hrdmq4zi177k0y3dv433-test-file-2.txt12312026-08-29 16:25:52.748 UTC [9977] ERROR: relation "goose_db_version" does not exist at character 3612322026-08-29 16:25:52.748 UTC [9977] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12332026/08/29 16:25:52 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12342026/08/29 16:25:52 OK 20241026095416_initial_model.sql (125ms)12352026/08/29 16:25:52 OK 20251210153512_drop_unused_gin_index.sql (11.57ms)12362026/08/29 16:25:52 OK 20251218171726_add_pins.sql (15.68ms)12372026/08/29 16:25:52 INFO Received uploads request method=POST path=/api/pending_closures12382026/08/29 16:25:52 OK 20260628120000_add_object_size_and_stats.sql (35.79ms)12392026/08/29 16:25:52 goose: successfully migrated database to version: 2026062812000012402026/08/29 16:25:52 OK 1_commit_pending_closure.sql (5.31ms)12412026/08/29 16:25:52 OK 2_object_stats_trigger.sql (277.04µs)12422026/08/29 16:25:52 goose: up to current file version: 212432026/08/29 16:25:52 INFO Received uploads request method=POST path=/api/pending_closures12442026/08/29 16:25:52 INFO Received uploads request method=POST path=/api/pending_closures12452026/08/29 16:25:52 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)12462026/08/29 16:25:52 INFO Uploading 2m0as8prl2z5hrdmq4zi177k0y3dv433-test-file-2.txt (160B)12472026/08/29 16:25:52 INFO Uploading glijzj1inrqjmdgmz49xw7iw2wv1yfx3-test-file-1.txt (160B)12482026/08/29 16:25:52 INFO Uploading nb6yfqs3hf2flcpfy7v6j4w61b0zdq9k-test-file-0.txt (160B)12492026/08/29 16:25:52 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"12502026/08/29 16:25:52 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"12512026/08/29 16:25:52 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"12522026/08/29 16:25:52 WARN Failed to register uploaded object key=glijzj1inrqjmdgmz49xw7iw2wv1yfx3.ls error="server returned 404: 404 page not found\n"12532026/08/29 16:25:52 WARN Failed to register uploaded object key=nb6yfqs3hf2flcpfy7v6j4w61b0zdq9k.ls error="server returned 404: 404 page not found\n"12542026/08/29 16:25:52 WARN Failed to register uploaded object key=2m0as8prl2z5hrdmq4zi177k0y3dv433.ls error="server returned 404: 404 page not found\n"12552026/08/29 16:25:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12562026/08/29 16:25:52 INFO Signed narinfos id=1 count=112572026/08/29 16:25:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12582026/08/29 16:25:52 INFO Signed narinfos id=2 count=112592026/08/29 16:25:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign12602026/08/29 16:25:52 INFO Signed narinfos id=3 count=112612026/08/29 16:25:52 INFO Uploading 3 narinfos12622026/08/29 16:25:53 OK 20241026095416_initial_model.sql (226.52ms)12632026/08/29 16:25:53 OK 20251210153512_drop_unused_gin_index.sql (19.49ms)12642026/08/29 16:25:53 WARN Failed to register uploaded object key=2m0as8prl2z5hrdmq4zi177k0y3dv433.narinfo error="server returned 404: 404 page not found\n"12652026/08/29 16:25:53 WARN Failed to register uploaded object key=nb6yfqs3hf2flcpfy7v6j4w61b0zdq9k.narinfo error="server returned 404: 404 page not found\n"12662026/08/29 16:25:53 WARN Failed to register uploaded object key=glijzj1inrqjmdgmz49xw7iw2wv1yfx3.narinfo error="server returned 404: 404 page not found\n"12672026/08/29 16:25:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1268=== NAME TestClientWithDependencies1269 client_integration_test.go:594: Built derivation: /nix/var/nix/builds/nix-9565-1909913857/TestClientWithDependencies3419940270/001/store/63ra9slyzg6ka7qppihfj274pqb3iv7c-test-script12702026/08/29 16:25:53 OK 20251218171726_add_pins.sql (38.98ms)12712026/08/29 16:25:53 INFO Completed upload id=112722026/08/29 16:25:53 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12732026/08/29 16:25:53 INFO Completed upload id=212742026/08/29 16:25:53 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete12752026/08/29 16:25:53 INFO Completed upload id=312762026/08/29 16:25:53 INFO Upload complete. (362ms)1277=== NAME TestClientMultipleUploads1278 client_integration_test.go:350: Uploaded 3 paths in 393.142375ms12792026/08/29 16:25:53 OK 20260628120000_add_object_size_and_stats.sql (47.38ms)12802026/08/29 16:25:53 goose: successfully migrated database to version: 202606281200001281=== NAME TestClientWithDependencies1282 client_integration_test.go:596: Found 1 dependencies (including self)12832026/08/29 16:25:53 OK 1_commit_pending_closure.sql (8.22ms)12842026/08/29 16:25:53 OK 2_object_stats_trigger.sql (477.88µs)12852026/08/29 16:25:53 goose: up to current file version: 21286--- PASS: TestClientMultipleUploads (4.37s)1287=== CONT TestNARDeduplicationMetadataUploadBug12882026/08/29 16:25:53 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12892026/08/29 16:25:53 INFO Received uploads request method=POST path=/api/pending_closures12902026/08/29 16:25:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12912026/08/29 16:25:53 INFO Uploading 63ra9slyzg6ka7qppihfj274pqb3iv7c-test-script (136B)12922026/08/29 16:25:53 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"12932026/08/29 16:25:53 WARN Failed to register uploaded object key=log/cr547g5w6ivnq200y351pk04c7llkn9h-test-script.drv error="server returned 404: 404 page not found\n"12942026/08/29 16:25:53 WARN Failed to register uploaded object key=63ra9slyzg6ka7qppihfj274pqb3iv7c.ls error="server returned 404: 404 page not found\n"12952026/08/29 16:25:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12962026/08/29 16:25:53 INFO Signed narinfos id=1 count=112972026/08/29 16:25:53 INFO Uploading 1 narinfos12982026/08/29 16:25:53 WARN Failed to register uploaded object key=63ra9slyzg6ka7qppihfj274pqb3iv7c.narinfo error="server returned 404: 404 page not found\n"12992026/08/29 16:25:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13002026/08/29 16:25:53 INFO Completed upload id=113012026/08/29 16:25:53 INFO Upload complete. (254ms)1302=== NAME TestClientWithDependencies1303 client_integration_test.go:598: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-9565-1909913857/TestClientWithDependencies3419940270/001/store) requires matching store prefix1304=== NAME TestClientIntegration1305 client_integration_test.go:277: Created store path: /nix/var/nix/builds/nix-9565-1909913857/TestClientIntegration777647881/002/store/v0ih19xh5nhyzgr7znxj5xjjyrbj81sd-test-file.txt1306--- PASS: TestClientWithDependencies (4.77s)1307=== CONT TestCacheConfigHandlerMaxNarSize1308--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1309=== CONT TestService_AuthMiddleware_OIDC13102026/08/29 16:25:53 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13112026/08/29 16:25:53 INFO OIDC provider initialized name=test13122026/08/29 16:25:53 INFO Received uploads request method=POST path=/api/pending_closures13132026/08/29 16:25:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13142026/08/29 16:25:53 INFO Uploading v0ih19xh5nhyzgr7znxj5xjjyrbj81sd-test-file.txt (152B)13152026/08/29 16:25:53 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"13162026/08/29 16:25:53 WARN Failed to register uploaded object key=v0ih19xh5nhyzgr7znxj5xjjyrbj81sd.ls error="server returned 404: 404 page not found\n"13172026-08-29 16:25:53.683 UTC [10009] ERROR: relation "goose_db_version" does not exist at character 3613182026-08-29 16:25:53.683 UTC [10009] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13192026/08/29 16:25:53 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13202026/08/29 16:25:53 INFO Signed narinfos id=1 count=113212026/08/29 16:25:53 INFO Uploading 1 narinfos13222026/08/29 16:25:53 WARN Failed to register uploaded object key=v0ih19xh5nhyzgr7znxj5xjjyrbj81sd.narinfo error="server returned 404: 404 page not found\n"13232026/08/29 16:25:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13242026/08/29 16:25:53 INFO Completed upload id=113252026/08/29 16:25:53 INFO Upload complete. (266ms)1326=== NAME TestClientIntegration1327 client_integration_test.go:293: Retrieved narinfo from S3:1328 StorePath: /nix/var/nix/builds/nix-9565-1909913857/TestClientIntegration777647881/002/store/v0ih19xh5nhyzgr7znxj5xjjyrbj81sd-test-file.txt1329 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1330 Compression: zstd1331 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11332 NarSize: 1521333 References: 1334 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11335 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1336 client_integration_test.go:294: Decompressed .ls content (64 bytes):1337 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1338 client_integration_test.go:297: Testing garbage collection...1339=== NAME TestClientCADerivations1340 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-9565-1909913857/TestClientCADerivations3427589753/001/store/b1ljqb5fk3kwqggn6yy9n6qx9a2nsy83-ca-test13412026/08/29 16:25:53 INFO Starting cleanup of old closures method=DELETE path=/api/closures13422026/08/29 16:25:53 INFO Garbage collection started13432026/08/29 16:25:53 INFO Aborted multipart uploads count=013442026/08/29 16:25:53 WARN Force mode enabled - objects will be deleted immediately without grace period13452026-08-29 16:25:53.804 UTC [10012] ERROR: relation "goose_db_version" does not exist at character 3613462026-08-29 16:25:53.804 UTC [10012] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1347 client_ca_test.go:139: Found 1 dependencies (including self)13482026/08/29 16:25:53 OK 20241026095416_initial_model.sql (119.98ms)13492026/08/29 16:25:53 OK 20251210153512_drop_unused_gin_index.sql (2.86ms)13502026/08/29 16:25:53 OK 20251218171726_add_pins.sql (23.23ms)13512026/08/29 16:25:53 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13522026/08/29 16:25:53 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=013532026/08/29 16:25:53 OK 20260628120000_add_object_size_and_stats.sql (32.78ms)13542026/08/29 16:25:53 goose: successfully migrated database to version: 2026062812000013552026/08/29 16:25:53 INFO Vacuumed table table=pending_closures13562026/08/29 16:25:53 OK 1_commit_pending_closure.sql (7.81ms)13572026/08/29 16:25:53 OK 2_object_stats_trigger.sql (257.21µs)13582026/08/29 16:25:53 goose: up to current file version: 213592026/08/29 16:25:53 INFO Received uploads request method=POST path=/api/pending_closures13602026/08/29 16:25:53 INFO Vacuumed table table=pending_objects13612026/08/29 16:25:53 INFO Vacuumed table table=multipart_uploads13622026/08/29 16:25:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13632026/08/29 16:25:53 INFO Uploading b1ljqb5fk3kwqggn6yy9n6qx9a2nsy83-ca-test (144B)13642026/08/29 16:25:53 INFO Vacuumed table table=closures13652026/08/29 16:25:54 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13662026/08/29 16:25:54 OK 20241026095416_initial_model.sql (185.25ms)13672026/08/29 16:25:54 INFO Vacuumed table table=objects13682026/08/29 16:25:54 OK 20251210153512_drop_unused_gin_index.sql (25.59ms)13692026/08/29 16:25:54 WARN Failed to register uploaded object key=log/5kfrzbxhaj4nsa64sqp8qaw3jp0njzmb-ca-test.drv error="server returned 404: 404 page not found\n"13702026/08/29 16:25:54 WARN Failed to register uploaded object key=b1ljqb5fk3kwqggn6yy9n6qx9a2nsy83.ls error="server returned 404: 404 page not found\n"13712026/08/29 16:25:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13722026-08-29 16:25:54.097 UTC [10023] ERROR: relation "goose_db_version" does not exist at character 3613732026-08-29 16:25:54.097 UTC [10023] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13742026/08/29 16:25:54 INFO Signed narinfos id=1 count=113752026/08/29 16:25:54 INFO Uploading 1 narinfos13762026/08/29 16:25:54 OK 20251218171726_add_pins.sql (39ms)13772026/08/29 16:25:54 WARN Failed to register uploaded object key=b1ljqb5fk3kwqggn6yy9n6qx9a2nsy83.narinfo error="server returned 404: 404 page not found\n"13782026/08/29 16:25:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13792026/08/29 16:25:54 OK 20260628120000_add_object_size_and_stats.sql (28.75ms)13802026/08/29 16:25:54 goose: successfully migrated database to version: 2026062812000013812026/08/29 16:25:54 OK 1_commit_pending_closure.sql (12.79ms)13822026/08/29 16:25:54 OK 2_object_stats_trigger.sql (212.33µs)13832026/08/29 16:25:54 goose: up to current file version: 213842026/08/29 16:25:54 INFO Completed upload id=113852026/08/29 16:25:54 INFO Upload complete. (318ms)1386 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-9565-1909913857/TestClientCADerivations3427589753/001/store/b1ljqb5fk3kwqggn6yy9n6qx9a2nsy83-ca-test1387 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1388 Compression: zstd1389 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1390 NarSize: 1441391 References: 1392 Deriver: /nix/var/nix/builds/nix-9565-1909913857/TestClientCADerivations3427589753/001/store/5kfrzbxhaj4nsa64sqp8qaw3jp0njzmb-ca-test.drv1393 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1394 client_ca_test.go:185: Checking for realisation files in S3...1395 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1396 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1397--- PASS: TestCacheStatsHandler (2.87s)1398=== CONT TestService_ReadScope_PublicByDefault1399=== NAME TestClientCADerivations1400 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket34?endpoint=http://localhost:56079®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-9565-1909913857/TestClientCADerivations3427589753/001/store'1401 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11402--- PASS: TestClientCADerivations (4.33s)1403=== CONT TestService_RequireScope_OIDC14042026/08/29 16:25:54 OK 20241026095416_initial_model.sql (216.4ms)14052026/08/29 16:25:54 OK 20251210153512_drop_unused_gin_index.sql (8.89ms)14062026/08/29 16:25:54 INFO OIDC provider initialized name=test14072026/08/29 16:25:54 OK 20251218171726_add_pins.sql (39.49ms)14082026-08-29 16:25:54.443 UTC [10043] ERROR: relation "goose_db_version" does not exist at character 3614092026-08-29 16:25:54.443 UTC [10043] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14102026/08/29 16:25:54 OK 20260628120000_add_object_size_and_stats.sql (40.71ms)14112026/08/29 16:25:54 goose: successfully migrated database to version: 2026062812000014122026/08/29 16:25:54 OK 1_commit_pending_closure.sql (1.21ms)14132026/08/29 16:25:54 OK 2_object_stats_trigger.sql (277.75µs)14142026/08/29 16:25:54 goose: up to current file version: 214152026/08/29 16:25:54 INFO Aborted multipart uploads count=01416--- PASS: TestGCBugBareHashReferences (2.96s)1417=== CONT TestGenerateLandingPage1418--- PASS: TestGenerateLandingPage (0.00s)1419=== CONT TestPresignedUploadRegisteredBeforeCommit14202026/08/29 16:25:54 WARN Force mode enabled - objects will be deleted immediately without grace period14212026/08/29 16:25:54 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=014222026/08/29 16:25:54 INFO Vacuumed table table=pending_closures14232026/08/29 16:25:54 INFO Vacuumed table table=pending_objects14242026/08/29 16:25:54 INFO Vacuumed table table=multipart_uploads14252026/08/29 16:25:54 INFO Vacuumed table table=closures14262026/08/29 16:25:54 INFO Vacuumed table table=objects1427--- PASS: TestGCMetrics (2.77s)1428=== CONT TestService_Rustfstest14292026/08/29 16:25:54 OK 20241026095416_initial_model.sql (229.05ms)14302026/08/29 16:25:54 OK 20251210153512_drop_unused_gin_index.sql (14.65ms)14312026/08/29 16:25:54 OK 20251218171726_add_pins.sql (38.8ms)14322026-08-29 16:25:54.776 UTC [10057] ERROR: relation "goose_db_version" does not exist at character 3614332026-08-29 16:25:54.776 UTC [10057] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14342026/08/29 16:25:54 OK 20260628120000_add_object_size_and_stats.sql (29.69ms)14352026/08/29 16:25:54 goose: successfully migrated database to version: 2026062812000014362026/08/29 16:25:54 OK 1_commit_pending_closure.sql (11.31ms)14372026/08/29 16:25:54 OK 2_object_stats_trigger.sql (663.83µs)14382026/08/29 16:25:54 goose: up to current file version: 214392026/08/29 16:25:54 INFO Received uploads request method=POST path=/api/pending_closures14402026/08/29 16:25:55 OK 20241026095416_initial_model.sql (250.16ms)14412026/08/29 16:25:55 OK 20251210153512_drop_unused_gin_index.sql (4.19ms)14422026/08/29 16:25:55 OK 20251218171726_add_pins.sql (53.14ms)14432026/08/29 16:25:55 OK 20260628120000_add_object_size_and_stats.sql (38.57ms)14442026/08/29 16:25:55 goose: successfully migrated database to version: 2026062812000014452026/08/29 16:25:55 OK 1_commit_pending_closure.sql (9.58ms)14462026/08/29 16:25:55 OK 2_object_stats_trigger.sql (445.33µs)14472026/08/29 16:25:55 goose: up to current file version: 214482026/08/29 16:25:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1449--- PASS: TestMetricsInventory (2.89s)1450=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14512026-08-29 16:25:55.565 UTC [10074] ERROR: relation "goose_db_version" does not exist at character 3614522026-08-29 16:25:55.565 UTC [10074] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14532026-08-29 16:25:55.729 UTC [10083] ERROR: relation "goose_db_version" does not exist at character 3614542026-08-29 16:25:55.729 UTC [10083] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14552026/08/29 16:25:55 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01456=== NAME TestClientIntegration1457 client_integration_test.go:304: Objects in database after GC:1458 client_integration_test.go:304: Successfully deleted all objects with GC --force14592026/08/29 16:25:55 OK 20241026095416_initial_model.sql (199.64ms)14602026/08/29 16:25:55 OK 20251210153512_drop_unused_gin_index.sql (11.78ms)14612026/08/29 16:25:55 OK 20251218171726_add_pins.sql (16.24ms)1462--- PASS: TestClientIntegration (5.99s)1463=== CONT TestService_ReadAuthMiddleware14642026/08/29 16:25:55 OK 20260628120000_add_object_size_and_stats.sql (30.4ms)14652026/08/29 16:25:55 goose: successfully migrated database to version: 2026062812000014662026/08/29 16:25:55 OK 1_commit_pending_closure.sql (1.15ms)14672026/08/29 16:25:55 OK 2_object_stats_trigger.sql (289.79µs)14682026/08/29 16:25:55 goose: up to current file version: 214692026/08/29 16:25:55 OK 20241026095416_initial_model.sql (198.57ms)14702026/08/29 16:25:55 OK 20251210153512_drop_unused_gin_index.sql (11.03ms)14712026/08/29 16:25:56 OK 20251218171726_add_pins.sql (27.69ms)14722026/08/29 16:25:56 OK 20260628120000_add_object_size_and_stats.sql (40.64ms)14732026/08/29 16:25:56 goose: successfully migrated database to version: 2026062812000014742026/08/29 16:25:56 OK 1_commit_pending_closure.sql (11.13ms)14752026/08/29 16:25:56 OK 2_object_stats_trigger.sql (535.38µs)14762026/08/29 16:25:56 goose: up to current file version: 21477=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1478=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1479=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1480=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1481=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1482=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1483=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1484=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1485=== CONT TestGCTaskStore_PhaseUpdates1486--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1487=== CONT TestGracefulShutdownDrainsInflight14882026/08/29 16:25:56 INFO Starting HTTP server address=127.0.0.1:5628214892026/08/29 16:25:56 INFO Shutdown signal received, draining in-flight requests timeout=10s1490--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1491=== CONT TestGCTaskStore_Fail1492--- PASS: TestGCTaskStore_Fail (0.00s)1493=== CONT TestCompletedNarNotReofferedAcrossClosures1494=== NAME TestNARDeduplicationMetadataUploadBug1495 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-9565-1909913857/TestNARDeduplicationMetadataUploadBug1334288288/001/store/m93qwckjjk88hsk9r55fqmglpp2i51lw-file1.txt14962026/08/29 16:25:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14972026/08/29 16:25:56 INFO Received uploads request method=POST path=/api/pending_closures14982026-08-29 16:25:56.504 UTC [10103] ERROR: relation "goose_db_version" does not exist at character 3614992026-08-29 16:25:56.504 UTC [10103] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15002026/08/29 16:25:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15012026/08/29 16:25:56 INFO Uploading m93qwckjjk88hsk9r55fqmglpp2i51lw-file1.txt (160B)15022026-08-29 16:25:56.565 UTC [10104] ERROR: relation "goose_db_version" does not exist at character 3615032026-08-29 16:25:56.565 UTC [10104] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15042026/08/29 16:25:56 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"15052026/08/29 16:25:56 WARN Failed to register uploaded object key=m93qwckjjk88hsk9r55fqmglpp2i51lw.ls error="server returned 404: 404 page not found\n"15062026/08/29 16:25:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15072026/08/29 16:25:56 INFO Signed narinfos id=1 count=115082026/08/29 16:25:56 INFO Uploading 1 narinfos15092026/08/29 16:25:56 WARN Failed to register uploaded object key=m93qwckjjk88hsk9r55fqmglpp2i51lw.narinfo error="server returned 404: 404 page not found\n"15102026/08/29 16:25:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15112026/08/29 16:25:56 INFO Completed upload id=115122026/08/29 16:25:56 INFO Upload complete. (321ms)1513 metadata_upload_test.go:54: Retrieved narinfo from S3:1514 StorePath: /nix/var/nix/builds/nix-9565-1909913857/TestNARDeduplicationMetadataUploadBug1334288288/001/store/m93qwckjjk88hsk9r55fqmglpp2i51lw-file1.txt1515 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1516 Compression: zstd1517 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1518 NarSize: 1601519 References: 1520 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1521 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1522 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1523 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}15242026/08/29 16:25:56 OK 20241026095416_initial_model.sql (161.42ms)15252026/08/29 16:25:56 OK 20251210153512_drop_unused_gin_index.sql (1.82ms)15262026/08/29 16:25:56 OK 20251218171726_add_pins.sql (17.42ms)15272026-08-29 16:25:56.739 UTC [10106] ERROR: relation "goose_db_version" does not exist at character 3615282026-08-29 16:25:56.739 UTC [10106] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15292026-08-29 16:25:56.739 UTC [10107] ERROR: relation "goose_db_version" does not exist at character 3615302026-08-29 16:25:56.739 UTC [10107] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15312026/08/29 16:25:56 OK 20241026095416_initial_model.sql (84.88ms)15322026/08/29 16:25:56 OK 20251210153512_drop_unused_gin_index.sql (7.81ms)15332026/08/29 16:25:56 OK 20260628120000_add_object_size_and_stats.sql (17.76ms)15342026/08/29 16:25:56 goose: successfully migrated database to version: 202606281200001535 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-9565-1909913857/TestNARDeduplicationMetadataUploadBug1334288288/001/store/r17q2ayw2fwbxgcxk65izxg72fjcrf83-file2.txt15362026/08/29 16:25:56 OK 1_commit_pending_closure.sql (7.67ms)15372026/08/29 16:25:56 OK 2_object_stats_trigger.sql (444.08µs)15382026/08/29 16:25:56 goose: up to current file version: 215392026/08/29 16:25:56 OK 20251218171726_add_pins.sql (21.63ms)15402026/08/29 16:25:56 OK 20260628120000_add_object_size_and_stats.sql (33.87ms)15412026/08/29 16:25:56 goose: successfully migrated database to version: 2026062812000015422026/08/29 16:25:56 OK 1_commit_pending_closure.sql (1.7ms)15432026/08/29 16:25:56 OK 2_object_stats_trigger.sql (586.67µs)15442026/08/29 16:25:56 goose: up to current file version: 215452026/08/29 16:25:56 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1546--- PASS: TestService_ReadScope_PublicByDefault (2.67s)1547=== CONT TestCompleteMultipartUpload_ErrorButObjectExists15482026/08/29 16:25:56 INFO Received uploads request method=POST path=/api/pending_closures15492026/08/29 16:25:56 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15502026/08/29 16:25:56 OK 20241026095416_initial_model.sql (132.13ms)15512026/08/29 16:25:56 OK 20251210153512_drop_unused_gin_index.sql (17.74ms)15522026/08/29 16:25:56 WARN Failed to register uploaded object key=r17q2ayw2fwbxgcxk65izxg72fjcrf83.ls error="server returned 404: 404 page not found\n"15532026/08/29 16:25:56 OK 20241026095416_initial_model.sql (141.67ms)15542026/08/29 16:25:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15552026/08/29 16:25:56 INFO Signed narinfos id=2 count=115562026/08/29 16:25:56 INFO Uploading 1 narinfos15572026/08/29 16:25:56 OK 20251210153512_drop_unused_gin_index.sql (12.92ms)15582026/08/29 16:25:56 OK 20251218171726_add_pins.sql (43.13ms)15592026/08/29 16:25:56 WARN Failed to register uploaded object key=r17q2ayw2fwbxgcxk65izxg72fjcrf83.narinfo error="server returned 404: 404 page not found\n"15602026/08/29 16:25:56 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15612026/08/29 16:25:56 INFO Completed upload id=215622026/08/29 16:25:56 INFO Upload complete. (170ms)1563=== NAME TestNARDeduplicationMetadataUploadBug1564 metadata_upload_test.go:76: Retrieved narinfo from S3:1565 StorePath: /nix/var/nix/builds/nix-9565-1909913857/TestNARDeduplicationMetadataUploadBug1334288288/001/store/r17q2ayw2fwbxgcxk65izxg72fjcrf83-file2.txt1566 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1567 Compression: zstd1568 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1569 NarSize: 1601570 References: 1571 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1572 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1573 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1574 {"version":1,"root":{"type":"regular","size":44}}15752026/08/29 16:25:56 OK 20251218171726_add_pins.sql (38.45ms)15762026/08/29 16:25:56 OK 20260628120000_add_object_size_and_stats.sql (28.96ms)15772026/08/29 16:25:56 goose: successfully migrated database to version: 2026062812000015782026/08/29 16:25:56 OK 1_commit_pending_closure.sql (1.46ms)15792026/08/29 16:25:56 OK 2_object_stats_trigger.sql (269.17µs)15802026/08/29 16:25:56 goose: up to current file version: 215812026/08/29 16:25:56 OK 20260628120000_add_object_size_and_stats.sql (16.74ms)15822026/08/29 16:25:56 goose: successfully migrated database to version: 2026062812000015832026/08/29 16:25:57 OK 1_commit_pending_closure.sql (7.81ms)15842026/08/29 16:25:57 OK 2_object_stats_trigger.sql (261.38µs)15852026/08/29 16:25:57 goose: up to current file version: 21586--- PASS: TestNARDeduplicationMetadataUploadBug (3.82s)1587=== CONT TestGCTaskStore_CompletedAllowsNewTask1588--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1589=== CONT TestGCTaskStore_GetReturnsLatest1590--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1591=== CONT TestService_AuthMiddleware_MTLSProxyHeader1592=== RUN TestService_RequireScope_OIDC/builder_may_write1593=== PAUSE TestService_RequireScope_OIDC/builder_may_write1594=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1595=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1596=== RUN TestService_RequireScope_OIDC/ops_may_admin1597=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1598=== RUN TestService_RequireScope_OIDC/ops_may_not_write1599=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1600=== RUN TestService_RequireScope_OIDC/reader_may_not_write1601=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1602=== RUN TestService_RequireScope_OIDC/static_token_may_admin1603=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1604=== RUN TestService_RequireScope_OIDC/static_token_may_write1605=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1606=== RUN TestService_RequireScope_OIDC/reader_may_read1607=== PAUSE TestService_RequireScope_OIDC/reader_may_read1608=== RUN TestService_RequireScope_OIDC/writer_implies_read1609=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1610=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1611=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1612=== CONT TestIsValidCachePath/narinfo1613=== CONT TestIsValidCachePath/index.html1614=== CONT TestIsValidCachePath/short_hash1615=== CONT TestIsValidCachePath/wrong_extension1616=== CONT TestIsValidCachePath/leading_slash1617=== CONT TestIsValidCachePath/empty1618=== CONT TestIsValidCachePath/random_path1619=== CONT TestIsValidCachePath/invalid_char_u1620=== CONT TestIsValidCachePath/invalid_char_e1621=== CONT TestIsValidCachePath/traversal_in_middle1622=== CONT TestIsValidCachePath/traversal_parent1623=== CONT TestIsValidCachePath/nar_uncompressed1624=== CONT TestIsValidCachePath/nix-cache-info1625=== CONT TestIsValidCachePath/realisation1626=== CONT TestIsValidCachePath/log1627=== CONT TestIsValidCachePath/ls1628=== CONT TestIsValidCachePath/nar_xz1629=== CONT TestIsValidCachePath/nar_bz21630=== CONT TestIsValidCachePath/nar_zst1631=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1632--- PASS: TestIsValidCachePath (0.00s)1633 --- PASS: TestIsValidCachePath/narinfo (0.00s)1634 --- PASS: TestIsValidCachePath/index.html (0.00s)1635 --- PASS: TestIsValidCachePath/short_hash (0.00s)1636 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1637 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1638 --- PASS: TestIsValidCachePath/empty (0.00s)1639 --- PASS: TestIsValidCachePath/random_path (0.00s)1640 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1641 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1642 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1643 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1644 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1645 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1646 --- PASS: TestIsValidCachePath/realisation (0.00s)1647 --- PASS: TestIsValidCachePath/log (0.00s)1648 --- PASS: TestIsValidCachePath/ls (0.00s)1649 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1650 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1651 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1652 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1653=== CONT TestParseSingleRange/none1654=== CONT TestParseSingleRange/open-ended1655=== CONT TestParseSingleRange/start_far_past_EOF1656=== CONT TestParseSingleRange/start_past_EOF1657=== CONT TestParseSingleRange/single_byte1658=== CONT TestParseSingleRange/suffix_exceeds_size1659=== CONT TestParseSingleRange/suffix1660=== CONT TestParseSingleRange/end_clamped_to_size1661=== CONT TestParseSingleRange/malformed_both_empty1662=== CONT TestParseSingleRange/closed1663=== CONT TestParseSingleRange/malformed_end_before_start1664=== CONT TestParseSingleRange/multi-range_ignored1665=== CONT TestParseSingleRange/malformed_no_dash1666=== CONT TestParseSingleRange/unknown_unit1667--- PASS: TestParseSingleRange (0.00s)1668 --- PASS: TestParseSingleRange/none (0.00s)1669 --- PASS: TestParseSingleRange/open-ended (0.00s)1670 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1671 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1672 --- PASS: TestParseSingleRange/single_byte (0.00s)1673 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1674 --- PASS: TestParseSingleRange/suffix (0.00s)1675 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1676 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1677 --- PASS: TestParseSingleRange/closed (0.00s)1678 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1679 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1680 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1681 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1682=== CONT TestIsValidUploadKey/narinfo1683=== CONT TestIsValidUploadKey/realisation_plus_in_output1684=== CONT TestIsValidUploadKey/unknown_type1685=== CONT TestIsValidUploadKey/empty_key1686=== CONT TestIsValidUploadKey/absolute1687=== CONT TestIsValidUploadKey/traversal_nar1688=== CONT TestIsValidUploadKey/traversal1689=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1690=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1691=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1692=== CONT TestIsValidUploadKey/index.html1693=== CONT TestIsValidUploadKey/nix-cache-info1694=== CONT TestIsValidUploadKey/build_log_home-manager_file1695=== CONT TestIsValidUploadKey/realisation1696=== CONT TestIsValidUploadKey/build_log_equals1697=== CONT TestIsValidUploadKey/build_log_question_mark1698=== CONT TestIsValidUploadKey/build_log_plus_in_name1699=== CONT TestIsValidUploadKey/nar_plain1700=== CONT TestIsValidUploadKey/build_log1701=== CONT TestIsValidUploadKey/listing1702=== CONT TestIsValidUploadKey/nar_xz1703=== CONT TestIsValidUploadKey/nar_zst1704--- PASS: TestIsValidUploadKey (0.00s)1705 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1706 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1707 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1708 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1709 --- PASS: TestIsValidUploadKey/absolute (0.00s)1710 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1711 --- PASS: TestIsValidUploadKey/traversal (0.00s)1712 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1713 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1714 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1715 --- PASS: TestIsValidUploadKey/index.html (0.00s)1716 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1717 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1718 --- PASS: TestIsValidUploadKey/realisation (0.00s)1719 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1720 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1721 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1722 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1723 --- PASS: TestIsValidUploadKey/build_log (0.00s)1724 --- PASS: TestIsValidUploadKey/listing (0.00s)1725 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1726 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1727=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17282026/08/29 16:25:57 INFO Received uploads request method=POST path=/1729--- PASS: TestService_Rustfstest (2.51s)1730=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17312026/08/29 16:25:57 INFO Received request for more parts method=POST path=/1732=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17332026/08/29 16:25:57 INFO Received complete multipart upload request method=POST path=/1734=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17352026/08/29 16:25:57 INFO Received uploads request method=POST path=/1736=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17372026/08/29 16:25:57 INFO Received complete multipart upload request method=POST path=/1738=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17392026/08/29 16:25:57 INFO Received request for more parts method=POST path=/1740=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17412026/08/29 16:25:57 INFO Received uploads request method=POST path=/1742--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1743 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1744 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1745 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1746 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1747=== CONT TestServerTLSConfig/no_client_CA1748=== CONT TestServerTLSConfig/not_a_PEM_file1749=== CONT TestServerTLSConfig/missing_CA_file1750--- PASS: TestServerTLSConfig (0.00s)1751 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1752 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1753 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1754=== CONT TestCacheConfigHandler/full_config,_no_issuer1755=== CONT TestCacheConfigHandler/no_signing_keys1756=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1757=== CONT TestCacheConfigHandler/no_cache_url_configured1758--- PASS: TestCacheConfigHandler (0.00s)1759 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1760 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1761 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1762 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1763=== CONT TestClientErrorHandling/InvalidStorePath17642026-08-29 16:25:57.284 UTC [10120] ERROR: relation "goose_db_version" does not exist at character 3617652026-08-29 16:25:57.284 UTC [10120] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17662026/08/29 16:25:57 INFO Received uploads request method=POST path=/api/pending_closures1767--- PASS: TestUploadHandlersRejectOversizedBody (0.04s)1768 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1769 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1770 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)1771=== CONT TestClientErrorHandling/ServerNotAvailable17722026-08-29 16:25:57.398 UTC [10123] ERROR: relation "goose_db_version" does not exist at character 3617732026-08-29 16:25:57.398 UTC [10123] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17742026/08/29 16:25:57 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst17752026/08/29 16:25:57 INFO Received uploads request method=POST path=/api/pending_closures1776--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.77s)1777=== CONT TestClientErrorHandling/InvalidAuthToken17782026/08/29 16:25:57 OK 20241026095416_initial_model.sql (167.11ms)17792026/08/29 16:25:57 OK 20251210153512_drop_unused_gin_index.sql (6.84ms)17802026/08/29 16:25:57 OK 20251218171726_add_pins.sql (16.54ms)17812026/08/29 16:25:57 OK 20260628120000_add_object_size_and_stats.sql (20.07ms)17822026/08/29 16:25:57 goose: successfully migrated database to version: 2026062812000017832026/08/29 16:25:57 OK 1_commit_pending_closure.sql (8.38ms)17842026/08/29 16:25:57 OK 2_object_stats_trigger.sql (250.04µs)17852026/08/29 16:25:57 goose: up to current file version: 217862026/08/29 16:25:57 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-config17872026/08/29 16:25:57 OK 20241026095416_initial_model.sql (134.75ms)17882026/08/29 16:25:57 OK 20251210153512_drop_unused_gin_index.sql (12.75ms)17892026/08/29 16:25:57 OK 20251218171726_add_pins.sql (40.37ms)17902026/08/29 16:25:57 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=211.546875ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config17912026/08/29 16:25:57 OK 20260628120000_add_object_size_and_stats.sql (34.92ms)17922026/08/29 16:25:57 goose: successfully migrated database to version: 2026062812000017932026/08/29 16:25:57 OK 1_commit_pending_closure.sql (12.11ms)17942026/08/29 16:25:57 OK 2_object_stats_trigger.sql (311.25µs)17952026/08/29 16:25:57 goose: up to current file version: 217962026/08/29 16:25:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17972026/08/29 16:25:57 WARN mTLS auth: bound subjects configured but subject DN unavailable17982026/08/29 16:25:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1799--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.20s)1800=== CONT TestProxyWriteTimeout/narinfo1801=== CONT TestProxyWriteTimeout/10_GiB_nar1802=== CONT TestProxyWriteTimeout/unknown_size1803=== CONT TestProxyWriteTimeout/1_GiB_nar1804--- PASS: TestProxyWriteTimeout (0.00s)1805 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1806 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1807 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1808 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1809=== CONT TestResolveDBConnectionString/flag_wins1810=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1811=== CONT TestResolveDBConnectionString/nothing_configured1812=== CONT TestResolveDBConnectionString/missing_file_is_an_error1813=== CONT TestResolveDBConnectionString/file_when_flag_empty1814=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1815--- PASS: TestResolveDBConnectionString (0.02s)1816 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1817 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1818 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1819 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1820 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)18212026/08/29 16:25:57 INFO OIDC auth successful provider=test scopes=[write]1822=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18232026/08/29 16:25:57 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]1824=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1825=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18262026/08/29 16:25:57 WARN Authentication failed token_preview=eyJhbGciOi...jGML4lIfbw token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1827=== CONT TestService_RequireScope_OIDC/builder_may_write18282026/08/29 16:25:57 INFO OIDC auth successful provider=test scopes=[write]1829=== CONT TestService_RequireScope_OIDC/static_token_may_admin1830=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1831=== CONT TestService_RequireScope_OIDC/writer_implies_read18322026/08/29 16:25:57 INFO OIDC auth successful provider=test scopes=[write]1833=== CONT TestService_RequireScope_OIDC/reader_may_read18342026/08/29 16:25:57 INFO OIDC auth successful provider=test scopes=[read]1835=== CONT TestService_RequireScope_OIDC/static_token_may_write1836=== CONT TestService_RequireScope_OIDC/ops_may_not_write18372026/08/29 16:25:57 INFO OIDC auth successful provider=test scopes=[admin]1838=== CONT TestService_RequireScope_OIDC/reader_may_not_write18392026/08/29 16:25:57 INFO OIDC auth successful provider=test scopes=[read]1840=== CONT TestService_RequireScope_OIDC/ops_may_admin18412026/08/29 16:25:57 INFO OIDC auth successful provider=test scopes=[admin]1842=== CONT TestService_RequireScope_OIDC/builder_may_not_admin18432026/08/29 16:25:57 INFO OIDC auth successful provider=test scopes=[write]1844--- PASS: TestService_AuthMiddleware_OIDC (2.74s)1845 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1846 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1847 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1848 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1849--- PASS: TestService_RequireScope_OIDC (2.70s)1850 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1851 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1852 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1853 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1854 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1855 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1856 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1857 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1858 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1859 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)18602026/08/29 16:25:57 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=363.337057ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1861--- PASS: TestService_ReadAuthMiddleware (2.09s)18622026-08-29 16:25:58.152 UTC [10131] ERROR: relation "goose_db_version" does not exist at character 3618632026-08-29 16:25:58.152 UTC [10131] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18642026/08/29 16:25:58 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=745.725923ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config18652026/08/29 16:25:58 OK 20241026095416_initial_model.sql (127.49ms)18662026/08/29 16:25:58 OK 20251210153512_drop_unused_gin_index.sql (13.55ms)18672026/08/29 16:25:58 OK 20251218171726_add_pins.sql (36.55ms)18682026/08/29 16:25:58 OK 20260628120000_add_object_size_and_stats.sql (19.11ms)18692026/08/29 16:25:58 goose: successfully migrated database to version: 2026062812000018702026/08/29 16:25:58 OK 1_commit_pending_closure.sql (4.18ms)18712026/08/29 16:25:58 OK 2_object_stats_trigger.sql (1.22ms)18722026/08/29 16:25:58 goose: up to current file version: 218732026/08/29 16:25:58 INFO Received uploads request method=POST path=/api/pending_closures18742026/08/29 16:25:59 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.562117082s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config18752026-08-29 16:25:59.047 UTC [10132] ERROR: relation "goose_db_version" does not exist at character 3618762026-08-29 16:25:59.047 UTC [10132] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18772026-08-29 16:25:59.176 UTC [10133] ERROR: relation "goose_db_version" does not exist at character 3618782026-08-29 16:25:59.176 UTC [10133] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18792026/08/29 16:25:59 OK 20241026095416_initial_model.sql (226.18ms)18802026/08/29 16:25:59 OK 20251210153512_drop_unused_gin_index.sql (13.02ms)18812026/08/29 16:25:59 OK 20251218171726_add_pins.sql (34.11ms)18822026/08/29 16:25:59 OK 20260628120000_add_object_size_and_stats.sql (39.39ms)18832026/08/29 16:25:59 goose: successfully migrated database to version: 2026062812000018842026/08/29 16:25:59 OK 1_commit_pending_closure.sql (7.52ms)18852026/08/29 16:25:59 OK 2_object_stats_trigger.sql (248.17µs)18862026/08/29 16:25:59 goose: up to current file version: 218872026/08/29 16:25:59 OK 20241026095416_initial_model.sql (200.53ms)18882026/08/29 16:25:59 OK 20251210153512_drop_unused_gin_index.sql (11.52ms)18892026/08/29 16:25:59 OK 20251218171726_add_pins.sql (25.97ms)18902026/08/29 16:25:59 OK 20260628120000_add_object_size_and_stats.sql (29.89ms)18912026/08/29 16:25:59 goose: successfully migrated database to version: 2026062812000018922026/08/29 16:25:59 OK 1_commit_pending_closure.sql (1.59ms)18932026/08/29 16:25:59 OK 2_object_stats_trigger.sql (284.83µs)18942026/08/29 16:25:59 goose: up to current file version: 218952026-08-29 16:25:59.586 UTC [10134] ERROR: relation "goose_db_version" does not exist at character 3618962026-08-29 16:25:59.586 UTC [10134] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18972026/08/29 16:25:59 INFO Received uploads request method=POST path=/api/pending_closures1898--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.81s)18992026/08/29 16:25:59 OK 20241026095416_initial_model.sql (226.29ms)19002026/08/29 16:25:59 OK 20251210153512_drop_unused_gin_index.sql (13.13ms)19012026/08/29 16:25:59 OK 20251218171726_add_pins.sql (50.09ms)19022026/08/29 16:25:59 OK 20260628120000_add_object_size_and_stats.sql (30.83ms)19032026/08/29 16:25:59 goose: successfully migrated database to version: 2026062812000019042026-08-29 16:25:59.964 UTC [10135] ERROR: relation "goose_db_version" does not exist at character 3619052026-08-29 16:25:59.964 UTC [10135] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19062026/08/29 16:25:59 OK 1_commit_pending_closure.sql (1.62ms)19072026/08/29 16:25:59 OK 2_object_stats_trigger.sql (312.67µs)19082026/08/29 16:25:59 goose: up to current file version: 219092026/08/29 16:25:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19102026/08/29 16:25:59 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZjM0OWNlZmMtMWNjMS00NDFkLTk0OGYtNmFkZTE5MDA3MjM4LjA5YmVhM2U4LTBlMDEtNGExZi1hYTVkLTkxMDZmNDJhOGIwOXgxNzg4MDIwNzU5NzAxNzc1MDAw19112026/08/29 16:25:59 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZjM0OWNlZmMtMWNjMS00NDFkLTk0OGYtNmFkZTE5MDA3MjM4LjA5YmVhM2U4LTBlMDEtNGExZi1hYTVkLTkxMDZmNDJhOGIwOXgxNzg4MDIwNzU5NzAxNzc1MDAw parts=11912--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (3.12s)19132026/08/29 16:26:00 OK 20241026095416_initial_model.sql (193.8ms)19142026/08/29 16:26:00 OK 20251210153512_drop_unused_gin_index.sql (10.47ms)19152026/08/29 16:26:00 OK 20251218171726_add_pins.sql (19.26ms)19162026/08/29 16:26:00 OK 20260628120000_add_object_size_and_stats.sql (28.68ms)19172026/08/29 16:26:00 goose: successfully migrated database to version: 2026062812000019182026/08/29 16:26:00 OK 1_commit_pending_closure.sql (5.88ms)19192026/08/29 16:26:00 OK 2_object_stats_trigger.sql (344.5µs)19202026/08/29 16:26:00 goose: up to current file version: 219212026/08/29 16:26:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19222026/08/29 16:26:00 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZjM0OWNlZmMtMWNjMS00NDFkLTk0OGYtNmFkZTE5MDA3MjM4LjYzYjFkYzhkLWJjMTctNDhiNi1hN2ZlLThjNGU3YmJmYWZjN3gxNzg4MDIwNzU4NjU2MDExMDAw parts=1219232026/08/29 16:26:00 INFO Received uploads request method=POST path=/api/pending_closures1924--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.24s)19252026/08/29 16:26:00 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"19262026/08/29 16:26:00 WARN Rate limiter enabled after throttle name=s3-test rate=519272026/08/29 16:26:00 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1928=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1929 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101930 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001931--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (8.58s)19322026/08/29 16:26:00 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_closures19332026/08/29 16:26:00 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19342026/08/29 16:26:00 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=189.748078ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19352026/08/29 16:26:00 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"1936=== NAME TestOrphanedObjectsGCStressTest1937 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1938 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion19392026/08/29 16:26:00 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=425.039664ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1940 orphaned_objects_gc_test.go:509: Stress test completed successfully:1941 orphaned_objects_gc_test.go:510: - Active objects preserved: 201942 orphaned_objects_gc_test.go:511: - Objects deleted: 2101943 orphaned_objects_gc_test.go:512: - Total GC'd: 2101944--- PASS: TestOrphanedObjectsGCStressTest (13.37s)19452026/08/29 16:26:01 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=746.993486ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19462026/08/29 16:26:02 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.674563362s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1947--- PASS: TestClientErrorHandling (0.00s)1948 --- PASS: TestClientErrorHandling/InvalidStorePath (3.00s)1949 --- PASS: TestClientErrorHandling/InvalidAuthToken (3.38s)1950 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.47s)1951PASS1952{"timestamp":"2026-08-29T16:26:03.80156Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56216","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1836,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}19532026-08-29 16:26:03.900 UTC [9753] LOG: received smart shutdown request19542026-08-29 16:26:03.901 UTC [9753] LOG: background worker "logical replication launcher" (PID 9763) exited with exit code 119552026-08-29 16:26:03.907 UTC [9758] LOG: shutting down19562026-08-29 16:26:03.907 UTC [9758] LOG: checkpoint starting: shutdown immediate19572026-08-29 16:26:04.951 UTC [9758] LOG: checkpoint complete: wrote 13542 buffers (82.7%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=0.745 s, sync=0.297 s, total=1.044 s; sync files=17141, longest=0.001 s, average=0.001 s; distance=240163 kB, estimate=240163 kB; lsn=0/10213BA0, redo lsn=0/10213BA019582026-08-29 16:26:04.955 UTC [9753] LOG: database system is shut down1959Running OIDC tests...1960=== RUN TestGlobMatch1961=== PAUSE TestGlobMatch1962=== RUN TestAudienceForIssuer1963=== PAUSE TestAudienceForIssuer1964=== RUN TestValidateToken_ValidToken1965=== PAUSE TestValidateToken_ValidToken1966=== RUN TestValidateToken_WrongAudience1967=== PAUSE TestValidateToken_WrongAudience1968=== RUN TestValidateToken_Expired1969=== PAUSE TestValidateToken_Expired1970=== RUN TestValidateToken_BoundClaimsMismatch1971=== PAUSE TestValidateToken_BoundClaimsMismatch1972=== RUN TestValidateToken_BoundSubjectMismatch1973=== PAUSE TestValidateToken_BoundSubjectMismatch1974=== RUN TestValidateToken_MultipleProviders1975=== PAUSE TestValidateToken_MultipleProviders1976=== RUN TestValidateToken_NoMatchingProvider1977=== PAUSE TestValidateToken_NoMatchingProvider1978=== RUN TestValidateToken_KubernetesServiceAccount1979=== PAUSE TestValidateToken_KubernetesServiceAccount1980=== RUN TestNewValidator_KubernetesRequiresCA1981=== PAUSE TestNewValidator_KubernetesRequiresCA1982=== RUN TestScopes_LegacyProviderDefaultsToWrite1983=== PAUSE TestScopes_LegacyProviderDefaultsToWrite1984=== RUN TestScopes_Rules1985=== PAUSE TestScopes_Rules1986=== RUN TestScopes_ConfigValidation1987=== PAUSE TestScopes_ConfigValidation1988=== CONT TestGlobMatch1989=== RUN TestGlobMatch/foo_foo1990=== PAUSE TestGlobMatch/foo_foo1991=== RUN TestGlobMatch/foo_bar1992=== CONT TestScopes_LegacyProviderDefaultsToWrite1993=== PAUSE TestGlobMatch/foo_bar1994=== RUN TestGlobMatch/*_1995=== CONT TestValidateToken_BoundSubjectMismatch1996=== CONT TestValidateToken_MultipleProviders1997=== CONT TestValidateToken_BoundClaimsMismatch1998=== CONT TestValidateToken_Expired1999=== CONT TestNewValidator_KubernetesRequiresCA2000=== CONT TestValidateToken_WrongAudience2001=== CONT TestValidateToken_KubernetesServiceAccount2002=== CONT TestValidateToken_ValidToken2003=== PAUSE TestGlobMatch/*_2004=== RUN TestGlobMatch/*_anything2005=== PAUSE TestGlobMatch/*_anything2006=== RUN TestGlobMatch/foo*_foo2007=== PAUSE TestGlobMatch/foo*_foo2008=== RUN TestGlobMatch/foo*_foobar2009=== PAUSE TestGlobMatch/foo*_foobar2010=== RUN TestGlobMatch/foo*_bar2011=== PAUSE TestGlobMatch/foo*_bar2012=== RUN TestGlobMatch/*bar_bar2013=== PAUSE TestGlobMatch/*bar_bar2014=== RUN TestGlobMatch/*bar_foobar2015=== PAUSE TestGlobMatch/*bar_foobar2016=== RUN TestGlobMatch/*bar_foo2017=== PAUSE TestGlobMatch/*bar_foo2018=== RUN TestGlobMatch/foo*bar_foobar2019=== PAUSE TestGlobMatch/foo*bar_foobar2020=== RUN TestGlobMatch/foo*bar_foo123bar2021=== PAUSE TestGlobMatch/foo*bar_foo123bar2022=== RUN TestGlobMatch/foo*bar_foobarbaz2023=== PAUSE TestGlobMatch/foo*bar_foobarbaz2024=== RUN TestGlobMatch/*/*_foo/bar2025=== PAUSE TestGlobMatch/*/*_foo/bar2026=== RUN TestGlobMatch/*/*_foo2027=== PAUSE TestGlobMatch/*/*_foo2028=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2029=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2030=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02031=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02032=== RUN TestGlobMatch/refs/*/main_refs/heads/main2033=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2034=== RUN TestGlobMatch/fo?_foo2035=== PAUSE TestGlobMatch/fo?_foo2036=== RUN TestGlobMatch/fo?_fo2037=== PAUSE TestGlobMatch/fo?_fo2038=== RUN TestGlobMatch/fo?_fooo2039=== PAUSE TestGlobMatch/fo?_fooo2040=== RUN TestGlobMatch/?oo_foo2041=== PAUSE TestGlobMatch/?oo_foo2042=== RUN TestGlobMatch/?oo_boo2043=== PAUSE TestGlobMatch/?oo_boo2044=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2045=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2046=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2047=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2048=== CONT TestAudienceForIssuer2049--- PASS: TestAudienceForIssuer (0.00s)2050=== CONT TestValidateToken_NoMatchingProvider20512026/08/29 16:26:05 INFO OIDC provider initialized name=test20522026/08/29 16:26:05 INFO OIDC provider initialized name=test20532026/08/29 16:26:05 INFO OIDC provider initialized name=test20542026/08/29 16:26:05 INFO OIDC provider initialized name=test20552026/08/29 16:26:05 INFO OIDC provider initialized name=provider220562026/08/29 16:26:05 INFO OIDC provider initialized name=test20572026/08/29 16:26:05 INFO OIDC provider initialized name=test20582026/08/29 16:26:05 INFO OIDC provider initialized name=provider120592026/08/29 16:26:05 INFO OIDC provider initialized name=provider12060--- PASS: TestValidateToken_BoundClaimsMismatch (0.00s)2061=== CONT TestScopes_Rules2062--- PASS: TestValidateToken_WrongAudience (0.00s)2063=== CONT TestScopes_ConfigValidation2064--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.00s)2065=== CONT TestGlobMatch/foo_foo2066=== CONT TestGlobMatch/*/*_foo/bar2067=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2068=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2069=== CONT TestGlobMatch/?oo_boo2070=== CONT TestGlobMatch/?oo_foo2071=== CONT TestGlobMatch/fo?_fooo2072=== CONT TestGlobMatch/fo?_fo2073=== CONT TestGlobMatch/fo?_foo2074=== CONT TestGlobMatch/refs/*/main_refs/heads/main2075=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02076=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2077=== CONT TestGlobMatch/*/*_foo2078=== CONT TestGlobMatch/*bar_bar2079=== CONT TestGlobMatch/foo*bar_foobarbaz2080=== CONT TestGlobMatch/foo*bar_foo123bar2081=== CONT TestGlobMatch/foo*bar_foobar2082=== CONT TestGlobMatch/*bar_foo2083=== CONT TestGlobMatch/*bar_foobar2084=== CONT TestGlobMatch/foo*_foo2085=== CONT TestGlobMatch/foo*_bar2086=== CONT TestGlobMatch/foo*_foobar2087=== CONT TestGlobMatch/*_2088=== CONT TestGlobMatch/*_anything2089=== CONT TestGlobMatch/foo_bar2090--- PASS: TestGlobMatch (0.00s)2091 --- PASS: TestGlobMatch/foo_foo (0.00s)2092 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2093 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2094 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2095 --- PASS: TestGlobMatch/?oo_boo (0.00s)2096 --- PASS: TestGlobMatch/?oo_foo (0.00s)2097 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2098 --- PASS: TestGlobMatch/fo?_fo (0.00s)2099 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2100 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2101 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2102 --- PASS: TestGlobMatch/*/*_foo (0.00s)2103 --- PASS: TestGlobMatch/*bar_bar (0.00s)2104 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2105 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2106 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2107 --- PASS: TestGlobMatch/*bar_foo (0.00s)2108 --- PASS: TestGlobMatch/fo?_foo (0.00s)2109 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2110 --- PASS: TestGlobMatch/foo*_foo (0.00s)2111 --- PASS: TestGlobMatch/foo*_bar (0.00s)2112 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2113 --- PASS: TestGlobMatch/*_ (0.00s)2114 --- PASS: TestGlobMatch/*_anything (0.00s)2115 --- PASS: TestGlobMatch/foo_bar (0.00s)2116--- PASS: TestValidateToken_Expired (0.01s)21172026/08/29 16:26:05 INFO OIDC provider initialized name=test2118--- PASS: TestValidateToken_NoMatchingProvider (0.00s)2119--- PASS: TestValidateToken_ValidToken (0.00s)21202026/08/29 16:26:05 INFO OIDC provider initialized name=kubernetes2121--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2122--- PASS: TestScopes_ConfigValidation (0.00s)2123--- PASS: TestValidateToken_MultipleProviders (0.01s)2124--- PASS: TestValidateToken_KubernetesServiceAccount (0.01s)2125--- PASS: TestScopes_Rules (0.00s)21262026/08/29 16:26:05 http: TLS handshake error from 127.0.0.1:56353: read tcp 127.0.0.1:56351->127.0.0.1:56353: use of closed network connection2127--- PASS: TestNewValidator_KubernetesRequiresCA (0.01s)2128PASS2129Running hook tests...2130=== RUN TestSendPathsEmpty2131=== PAUSE TestSendPathsEmpty2132=== RUN TestQueueEnqueueAndFetch2133=== PAUSE TestQueueEnqueueAndFetch2134=== RUN TestQueueDeduplication2135=== PAUSE TestQueueDeduplication2136=== RUN TestQueueRemove2137=== PAUSE TestQueueRemove2138=== RUN TestQueueFetchBatchLimit2139=== PAUSE TestQueueFetchBatchLimit2140=== RUN TestQueueRetryMovesToBack2141=== PAUSE TestQueueRetryMovesToBack2142=== RUN TestQueueFetchRemoveLifecycle2143=== PAUSE TestQueueFetchRemoveLifecycle2144=== RUN TestQueueConcurrentWriters2145=== PAUSE TestQueueConcurrentWriters2146=== RUN TestQueueRemoveLargeClosure2147=== PAUSE TestQueueRemoveLargeClosure2148=== RUN TestServerClientIntegration2149=== PAUSE TestServerClientIntegration2150=== RUN TestServerQueueError2151=== PAUSE TestServerQueueError2152=== RUN TestGetListenerSocketActivation2153 server_test.go:210: === RUN TestGetListenerSocketActivation2154 --- PASS: TestGetListenerSocketActivation (0.00s)2155 PASS2156 2157--- PASS: TestGetListenerSocketActivation (0.01s)2158=== RUN TestDrainIsolatesPoisonPath2159=== PAUSE TestDrainIsolatesPoisonPath2160=== RUN TestRunNotBlockedByPoisonHead2161=== PAUSE TestRunNotBlockedByPoisonHead2162=== RUN TestDrainGivesUpWhenServerDown2163=== PAUSE TestDrainGivesUpWhenServerDown2164=== RUN TestFailedPathPrunedByLaterClosure2165=== PAUSE TestFailedPathPrunedByLaterClosure2166=== RUN TestWorkerUploadsAndRemoves2167=== PAUSE TestWorkerUploadsAndRemoves2168=== RUN TestWorkerSkipsGCdPaths2169=== PAUSE TestWorkerSkipsGCdPaths2170=== RUN TestWorkerPrunesClosureDeps2171=== PAUSE TestWorkerPrunesClosureDeps2172=== RUN TestDrainTimeout2173=== PAUSE TestDrainTimeout2174=== CONT TestSendPathsEmpty2175=== CONT TestServerQueueError2176=== CONT TestWorkerUploadsAndRemoves2177=== CONT TestQueueConcurrentWriters2178=== CONT TestQueueRemove2179=== CONT TestQueueDeduplication2180=== CONT TestQueueFetchBatchLimit2181=== CONT TestDrainGivesUpWhenServerDown2182=== CONT TestQueueEnqueueAndFetch2183--- PASS: TestSendPathsEmpty (0.00s)2184=== CONT TestServerClientIntegration2185=== CONT TestQueueRemoveLargeClosure21862026/08/29 16:26:06 ERROR Failed to queue paths error="permission denied" count=12187--- PASS: TestServerQueueError (0.00s)2188=== CONT TestQueueFetchRemoveLifecycle2189--- PASS: TestServerClientIntegration (0.00s)2190=== CONT TestQueueRetryMovesToBack2191--- PASS: TestQueueFetchBatchLimit (0.01s)2192=== CONT TestRunNotBlockedByPoisonHead2193--- PASS: TestQueueDeduplication (0.01s)2194=== CONT TestWorkerSkipsGCdPaths2195--- PASS: TestQueueRemove (0.01s)2196=== CONT TestDrainTimeout21972026/08/29 16:26:06 INFO Uploading batch count=221982026/08/29 16:26:06 ERROR Upload failed error="upload failed" count=221992026/08/29 16:26:06 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-9565-1909913857/TestDrainGivesUpWhenServerDown2147758878/002/a22002026/08/29 16:26:06 INFO Upload queue status pending=22201--- PASS: TestQueueRetryMovesToBack (0.01s)2202=== CONT TestWorkerPrunesClosureDeps22032026/08/29 16:26:06 INFO Uploading batch count=222042026/08/29 16:26:06 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-9565-1909913857/TestDrainGivesUpWhenServerDown2147758878/002/b2205--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2206=== CONT TestDrainIsolatesPoisonPath2207--- PASS: TestQueueEnqueueAndFetch (0.01s)2208=== CONT TestFailedPathPrunedByLaterClosure22092026/08/29 16:26:06 INFO Uploading batch count=222102026/08/29 16:26:06 ERROR Upload failed error="upload failed" count=222112026/08/29 16:26:06 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-9565-1909913857/TestDrainGivesUpWhenServerDown2147758878/002/c22122026/08/29 16:26:06 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-9565-1909913857/TestDrainGivesUpWhenServerDown2147758878/002/d22132026/08/29 16:26:06 INFO Uploading batch count=222142026/08/29 16:26:06 ERROR Upload failed error="upload failed" count=222152026/08/29 16:26:06 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-9565-1909913857/TestDrainGivesUpWhenServerDown2147758878/002/e22162026/08/29 16:26:06 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-9565-1909913857/TestDrainGivesUpWhenServerDown2147758878/002/f22172026/08/29 16:26:06 INFO Upload queue status pending=222182026/08/29 16:26:06 INFO Uploading batch count=122192026/08/29 16:26:06 INFO Upload queue status pending=222202026/08/29 16:26:06 ERROR Drain finished with paths left in queue remaining=1022212026/08/29 16:26:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-9565-1909913857/TestWorkerSkipsGCdPaths3182884143/002/nonexistent22222026/08/29 16:26:06 INFO Upload queue status pending=322232026/08/29 16:26:06 INFO Uploading batch count=122242026/08/29 16:26:06 ERROR Upload failed error="upload failed" count=122252026/08/29 16:26:06 INFO Uploading batch count=122262026/08/29 16:26:06 INFO Uploading batch count=422272026/08/29 16:26:06 ERROR Upload failed error="upload failed" count=422282026/08/29 16:26:06 INFO Uploading batch count=122292026/08/29 16:26:06 ERROR Upload failed error="upload failed" count=122302026/08/29 16:26:06 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-9565-1909913857/TestDrainIsolatesPoisonPath2054120488/002/bbb22312026/08/29 16:26:06 INFO Uploading batch count=222322026/08/29 16:26:06 INFO Uploading batch count=122332026/08/29 16:26:06 INFO Uploading batch count=122342026/08/29 16:26:06 ERROR Upload failed error="upload failed" count=122352026/08/29 16:26:06 INFO Uploading batch count=122362026/08/29 16:26:06 INFO Uploading batch count=122372026/08/29 16:26:06 ERROR Upload failed error="upload failed" count=122382026/08/29 16:26:06 INFO Uploading batch count=122392026/08/29 16:26:06 ERROR Upload failed error="upload failed" count=122402026/08/29 16:26:06 ERROR Drain finished with paths left in queue remaining=12241--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2242--- PASS: TestDrainIsolatesPoisonPath (0.00s)2243--- PASS: TestFailedPathPrunedByLaterClosure (0.00s)2244--- PASS: TestWorkerUploadsAndRemoves (0.03s)2245--- PASS: TestWorkerSkipsGCdPaths (0.02s)2246--- PASS: TestWorkerPrunesClosureDeps (0.02s)2247--- PASS: TestQueueRemoveLargeClosure (0.05s)2248--- PASS: TestQueueConcurrentWriters (0.09s)22492026/08/29 16:26:06 ERROR Upload failed error="context deadline exceeded" count=222502026/08/29 16:26:06 ERROR Drain finished with paths left in queue remaining=42251--- PASS: TestDrainTimeout (0.21s)22522026/08/29 16:26:07 INFO Uploading batch count=122532026/08/29 16:26:07 INFO Uploading batch count=122542026/08/29 16:26:07 INFO Uploading batch count=122552026/08/29 16:26:07 ERROR Upload failed error="upload failed" count=122562026/08/29 16:26:07 INFO Uploading batch count=122572026/08/29 16:26:07 ERROR Upload failed error="upload failed" count=122582026/08/29 16:26:07 INFO Uploading batch count=122592026/08/29 16:26:07 ERROR Upload failed error="upload failed" count=122602026/08/29 16:26:07 INFO Uploading batch count=122612026/08/29 16:26:07 ERROR Upload failed error="upload failed" count=122622026/08/29 16:26:07 ERROR Drain finished with paths left in queue remaining=12263--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2264PASS