niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #158
· raw
1tribuchet: building on eliza2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestCaseHackSuffix6=== PAUSE TestCaseHackSuffix7=== RUN TestFilterOversizedClosures8=== PAUSE TestFilterOversizedClosures9=== RUN TestPartSizeForNAR10=== PAUSE TestPartSizeForNAR11=== RUN TestUploadMultipart_SupersededByPeer12=== PAUSE TestUploadMultipart_SupersededByPeer13=== RUN TestDumpPathMatchesNix14=== PAUSE TestDumpPathMatchesNix15=== RUN TestDumpPathSingleFile16=== PAUSE TestDumpPathSingleFile17=== RUN TestDumpPathWriterError18=== PAUSE TestDumpPathWriterError19=== RUN TestEncodeNixBase3220=== PAUSE TestEncodeNixBase3221=== RUN TestEncodeNixBase32WithRealHash22=== PAUSE TestEncodeNixBase32WithRealHash23=== RUN TestConvertHashToNix3224=== PAUSE TestConvertHashToNix3225=== RUN TestGetStorePathHash26=== PAUSE TestGetStorePathHash27=== RUN TestPathInfoHashCompatibility28=== PAUSE TestPathInfoHashCompatibility29=== RUN TestParsePathInfoJSON30=== PAUSE TestParsePathInfoJSON31=== RUN TestParsePathInfoJSONMultiplePaths32=== PAUSE TestParsePathInfoJSONMultiplePaths33=== RUN TestPathInfoCACompatibility34=== PAUSE TestPathInfoCACompatibility35=== RUN TestRateLimiterFeedback36=== PAUSE TestRateLimiterFeedback37=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess38=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess39=== RUN TestResolveStorePath40=== PAUSE TestResolveStorePath41=== RUN TestDoWithRetry_BodyReplayedViaGetBody42=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody43=== RUN TestShellSplit44=== PAUSE TestShellSplit45=== RUN TestShellSplitErrors46=== PAUSE TestShellSplitErrors47=== RUN TestSetClientTLS48=== PAUSE TestSetClientTLS49=== RUN TestSetClientTLSDoesNotMutateDefaultTransport50=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport51=== RUN TestSetClientTLSErrors52=== PAUSE TestSetClientTLSErrors53=== RUN TestStaticToken54=== PAUSE TestStaticToken55=== RUN TestFileTokenReadsAndCaches56=== PAUSE TestFileTokenReadsAndCaches57=== RUN TestFileTokenMissing58=== PAUSE TestFileTokenMissing59=== RUN TestFileTokenEmpty60=== PAUSE TestFileTokenEmpty61=== RUN TestScriptTokenNoExpiryRerunsEveryCall62=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall63=== RUN TestScriptTokenCachesUntilRefresh64=== PAUSE TestScriptTokenCachesUntilRefresh65=== RUN TestScriptTokenEmptyToken66=== PAUSE TestScriptTokenEmptyToken67=== RUN TestScriptTokenBadJSON68=== PAUSE TestScriptTokenBadJSON69=== RUN TestScriptTokenScriptFails70=== PAUSE TestScriptTokenScriptFails71=== RUN TestScriptTokenEmptyCommand72=== PAUSE TestScriptTokenEmptyCommand73=== CONT TestDoServerRequestAttachesToken74=== CONT TestEncodeNixBase32WithRealHash75--- PASS: TestEncodeNixBase32WithRealHash (0.00s)76=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess77=== CONT TestStaticToken78--- PASS: TestStaticToken (0.00s)79=== CONT TestResolveStorePath80=== CONT TestFileTokenReadsAndCaches81=== CONT TestRateLimiterFeedback82=== RUN TestRateLimiterFeedback/429_enables_limiter83=== PAUSE TestRateLimiterFeedback/429_enables_limiter84=== RUN TestRateLimiterFeedback/503_enables_limiter85=== PAUSE TestRateLimiterFeedback/503_enables_limiter86=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter87=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter88=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter89=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter90=== CONT TestPathInfoCACompatibility91=== RUN TestPathInfoCACompatibility/null_ca_field92=== PAUSE TestPathInfoCACompatibility/null_ca_field93=== RUN TestPathInfoCACompatibility/old_string_format_-_text94=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text95=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive96=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive97=== RUN TestPathInfoCACompatibility/new_structured_format_-_text98=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text99=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method100=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method101=== CONT TestPartSizeForNAR102=== RUN TestPartSizeForNAR/zero_stays_at_minimum103=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum104=== RUN TestPartSizeForNAR/small_stays_at_minimum105=== PAUSE TestPartSizeForNAR/small_stays_at_minimum106=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum107=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum108=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts109=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts110=== RUN TestPartSizeForNAR/1_TiB111=== PAUSE TestPartSizeForNAR/1_TiB112=== RUN TestPartSizeForNAR/5_TiB_S3_max_object113=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object114=== RUN TestPartSizeForNAR/capped_at_5_GiB115=== PAUSE TestPartSizeForNAR/capped_at_5_GiB116=== CONT TestDoWithRetry_BodyReplayedViaGetBody1172026/08/27 11:06:19 WARN Rate limiter enabled after throttle name=server-test rate=5118=== CONT TestUploadMultipart_SupersededByPeer119=== CONT TestParsePathInfoJSONMultiplePaths120=== CONT TestParsePathInfoJSON121=== CONT TestPathInfoHashCompatibility122=== CONT TestGetStorePathHash123=== CONT TestConvertHashToNix32124=== CONT TestScriptTokenEmptyToken125=== CONT TestScriptTokenEmptyCommand126=== CONT TestScriptTokenScriptFails127=== CONT TestScriptTokenBadJSON128=== CONT TestDumpPathMatchesNix129=== CONT TestEncodeNixBase32130=== CONT TestDumpPathWriterError131=== CONT TestDumpPathSingleFile132=== CONT TestSetClientTLS133=== CONT TestSetClientTLSErrors134=== CONT TestSetClientTLSDoesNotMutateDefaultTransport135=== CONT TestShellSplit136=== CONT TestShellSplitErrors137--- PASS: TestFileTokenReadsAndCaches (0.00s)138--- PASS: TestScriptTokenEmptyCommand (0.00s)139--- PASS: TestResolveStorePath (0.00s)140=== CONT TestFileTokenEmpty141=== CONT TestScriptTokenNoExpiryRerunsEveryCall142--- PASS: TestShellSplit (0.00s)143=== CONT TestFilterOversizedClosures144=== RUN TestFilterOversizedClosures/no_limit_keeps_everything145=== RUN TestEncodeNixBase32/test_string_hash146=== PAUSE TestEncodeNixBase32/test_string_hash147=== RUN TestEncodeNixBase32/empty_input148=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything149=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths150=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths151=== RUN TestUploadMultipart_SupersededByPeer/exists152=== RUN TestGetStorePathHash/valid_store_path153=== RUN TestConvertHashToNix32/SRI_format_to_Nix32154=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)155=== RUN TestParsePathInfoJSON/Nix_format156=== PAUSE TestEncodeNixBase32/empty_input157=== CONT TestScriptTokenCachesUntilRefresh158=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped159--- PASS: TestShellSplitErrors (0.00s)160=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped161--- PASS: TestFileTokenEmpty (0.00s)162=== CONT TestCaseHackSuffix163=== RUN TestFilterOversizedClosures/all_closures_skipped164=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths165=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32166=== PAUSE TestUploadMultipart_SupersededByPeer/exists167--- PASS: TestScriptTokenScriptFails (0.00s)168=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)169=== RUN TestUploadMultipart_SupersededByPeer/missing170=== CONT TestFileTokenMissing171=== PAUSE TestFilterOversizedClosures/all_closures_skipped172=== CONT TestPathInfoCACompatibility/null_ca_field173=== PAUSE TestParsePathInfoJSON/Nix_format174=== PAUSE TestGetStorePathHash/valid_store_path175=== RUN TestConvertHashToNix32/already_Nix32_format176=== PAUSE TestConvertHashToNix32/already_Nix32_format1772026/08/27 11:06:19 WARN Rate limiter enabled after throttle name=server-test rate=5178=== RUN TestConvertHashToNix32/invalid_format179=== PAUSE TestConvertHashToNix32/invalid_format1802026/08/27 11:06:19 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:42213181=== RUN TestParsePathInfoJSON/Lix_format182=== PAUSE TestParsePathInfoJSON/Lix_format183=== RUN TestParsePathInfoJSON/empty_input184=== CONT TestRateLimiterFeedback/429_enables_limiter185=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths186=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon187--- PASS: TestDoServerRequestAttachesToken (0.01s)188=== CONT TestPathInfoCACompatibility/old_string_format_-_text189=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive190=== PAUSE TestParsePathInfoJSON/empty_input191=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method192=== CONT TestPartSizeForNAR/zero_stays_at_minimum193=== RUN TestGetStorePathHash/basename_without_hyphen_should_error194--- PASS: TestFileTokenMissing (0.00s)195=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon196=== CONT TestPathInfoCACompatibility/new_structured_format_-_text197=== CONT TestPartSizeForNAR/capped_at_5_GiB198--- PASS: TestScriptTokenBadJSON (0.01s)199=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI200=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI201=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512202=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512203=== CONT TestPartSizeForNAR/small_stays_at_minimum204--- PASS: TestScriptTokenEmptyToken (0.01s)205=== PAUSE TestUploadMultipart_SupersededByPeer/missing206=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error207=== CONT TestFilterOversizedClosures/all_closures_skipped2082026/08/27 11:06:19 WARN Rate limiter backed off name=server-test rate=5209=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2102026/08/27 11:06:19 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:422132112026/08/27 11:06:19 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=50212=== CONT TestFilterOversizedClosures/no_limit_keeps_everything213=== RUN TestParsePathInfoJSON/whitespace_only214=== CONT TestPartSizeForNAR/1_TiB215=== CONT TestEncodeNixBase32/test_string_hash216=== CONT TestConvertHashToNix32/invalid_format217=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum218=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts219=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter220=== CONT TestPartSizeForNAR/5_TiB_S3_max_object221=== CONT TestRateLimiterFeedback/503_enables_limiter222--- PASS: TestPathInfoCACompatibility (0.00s)223 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)224 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)225 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)226 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)227 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)228=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped229--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)230--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)2312026/08/27 11:06:19 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=2000232=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error2332026/08/27 11:06:19 WARN Rate limiter enabled after throttle name=server-test rate=52342026/08/27 11:06:19 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:35747235=== PAUSE TestParsePathInfoJSON/whitespace_only236=== CONT TestEncodeNixBase32/empty_input237=== CONT TestConvertHashToNix32/SRI_format_to_Nix32238=== CONT TestConvertHashToNix32/already_Nix32_format239=== RUN TestSetClientTLSErrors/missing_cert_file240=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths2412026/08/27 11:06:19 WARN Rate limiter backed off name=server-test rate=5242=== RUN TestSetClientTLS/rejects_connection_without_client_cert2432026/08/27 11:06:19 WARN Rate limiter enabled after throttle name=server-test rate=5244=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)2452026/08/27 11:06:19 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:35829246=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI247=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512248=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths249--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)2502026/08/27 11:06:19 WARN Rate limiter backed off name=server-test rate=5251=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon252=== CONT TestUploadMultipart_SupersededByPeer/exists253=== CONT TestUploadMultipart_SupersededByPeer/missing254=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error255=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error256=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error257=== CONT TestGetStorePathHash/valid_store_path258=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error259=== PAUSE TestSetClientTLSErrors/missing_cert_file260=== RUN TestSetClientTLSErrors/missing_key_file261=== PAUSE TestSetClientTLSErrors/missing_key_file262=== RUN TestSetClientTLSErrors/missing_ca_file263=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert264--- PASS: TestPartSizeForNAR (0.00s)265 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)266 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)267 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)268 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)269 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)270 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)271 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)272--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)273=== RUN TestParsePathInfoJSON/invalid_JSON274=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error275=== CONT TestGetStorePathHash/basename_without_hyphen_should_error276=== PAUSE TestSetClientTLSErrors/missing_ca_file277=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA278=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA279--- PASS: TestFilterOversizedClosures (0.00s)280 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)281 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)282 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)283=== PAUSE TestParsePathInfoJSON/invalid_JSON284=== RUN TestSetClientTLSErrors/invalid_ca_file285=== RUN TestSetClientTLS/preserves_debug_logging_transport286=== PAUSE TestSetClientTLSErrors/invalid_ca_file287=== PAUSE TestSetClientTLS/preserves_debug_logging_transport288=== CONT TestSetClientTLS/rejects_connection_without_client_cert289=== CONT TestSetClientTLS/preserves_debug_logging_transport290--- PASS: TestEncodeNixBase32 (0.00s)291 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)292 --- PASS: TestEncodeNixBase32/empty_input (0.00s)293=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA294=== CONT TestSetClientTLSErrors/missing_cert_file295=== CONT TestParsePathInfoJSON/Nix_format296=== CONT TestParsePathInfoJSON/invalid_JSON297=== CONT TestParsePathInfoJSON/whitespace_only298=== CONT TestParsePathInfoJSON/empty_input299=== CONT TestParsePathInfoJSON/Lix_format300=== CONT TestSetClientTLSErrors/invalid_ca_file301=== CONT TestSetClientTLSErrors/missing_ca_file302=== CONT TestSetClientTLSErrors/missing_key_file303--- PASS: TestConvertHashToNix32 (0.01s)304 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)305 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)306 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)307--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)308 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)309 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)310--- PASS: TestPathInfoHashCompatibility (0.01s)311 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)312 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)313 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)314 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)315--- PASS: TestRateLimiterFeedback (0.00s)316 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)317 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)318 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)319 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)320--- PASS: TestGetStorePathHash (0.02s)321 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)322 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)323 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)324 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)325--- PASS: TestParsePathInfoJSON (0.02s)326 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)327 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)328 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)329 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)330 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)331--- PASS: TestSetClientTLSErrors (0.02s)332 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)333 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)334 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)335 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)336--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)337 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)338 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)3392026/08/27 11:06:19 http: TLS handshake error from 127.0.0.1:35224: remote error: tls: bad certificate340--- PASS: TestSetClientTLS (0.02s)341 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)342 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)343 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)344--- PASS: TestDumpPathSingleFile (0.04s)345--- PASS: TestDumpPathWriterError (0.04s)346--- PASS: TestCaseHackSuffix (0.04s)347--- PASS: TestDumpPathMatchesNix (0.08s)348--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)349PASS350Running server tests...351The files belonging to this database system will be owned by user "nixbld".352This user must also own the server process.353354The database cluster will be initialized with locale "C".355The default database encoding has accordingly been set to "SQL_ASCII".356The default text search configuration will be set to "english".357358Data page checksums are enabled.359360creating directory /build/postgres841898840/data ... ok361creating subdirectories ... ok362selecting dynamic shared memory implementation ... posix363selecting default "max_connections" ... 100364selecting default "shared_buffers" ... 128MB365selecting default time zone ... UTC366creating configuration files ... ok367running bootstrap script ... ok368performing post-bootstrap initialization ... ok369syncing data to disk ... ok370371initdb: warning: enabling "trust" authentication for local connections372initdb: 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.373374Success. You can now start the database server using:375376 pg_ctl -D /build/postgres841898840/data -l logfile start377378/build/postgres841898840:5432 - no response3792026-08-27 11:06:20.976 UTC [112] LOG: starting PostgreSQL 18.4 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit3802026-08-27 11:06:20.976 UTC [112] LOG: listening on Unix socket "/build/postgres841898840/.s.PGSQL.5432"3812026-08-27 11:06:20.981 UTC [119] LOG: database system was shut down at 2026-08-27 11:06:20 UTC3822026-08-27 11:06:20.985 UTC [112] LOG: database system is ready to accept connections383/build/postgres841898840:5432 - accepting connections384=== RUN TestService_AuthMiddleware385=== PAUSE TestService_AuthMiddleware386=== RUN TestService_AuthMiddleware_MTLSProxyHeader387=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader388=== RUN TestService_AuthMiddleware_MTLSBoundSubjects389=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects390=== RUN TestService_ReadAuthMiddleware391=== PAUSE TestService_ReadAuthMiddleware392=== RUN TestService_AuthMiddleware_OIDC393=== PAUSE TestService_AuthMiddleware_OIDC394=== RUN TestService_RequireScope_OIDC395=== PAUSE TestService_RequireScope_OIDC396=== RUN TestService_ReadScope_PublicByDefault397=== PAUSE TestService_ReadScope_PublicByDefault398=== RUN TestCacheConfigHandler399=== PAUSE TestCacheConfigHandler400=== RUN TestCacheStatsHandler401=== PAUSE TestCacheStatsHandler402=== RUN TestClientCADerivations403=== PAUSE TestClientCADerivations404=== RUN TestClientErrorHandling405=== PAUSE TestClientErrorHandling406=== RUN TestClientIntegration407=== PAUSE TestClientIntegration408=== RUN TestClientMultipleUploads409=== PAUSE TestClientMultipleUploads410=== RUN TestClientWithDependencies411=== PAUSE TestClientWithDependencies412=== RUN TestPinProtectsFromGC413=== PAUSE TestPinProtectsFromGC414=== RUN TestResolveDBConnectionString415=== PAUSE TestResolveDBConnectionString416=== RUN TestGCAdvisoryLockBlocksConcurrentRun4172026-08-27 11:06:26.108 UTC [519] ERROR: relation "goose_db_version" does not exist at character 364182026-08-27 11:06:26.108 UTC [519] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4192026/08/27 11:06:26 OK 20241026095416_initial_model.sql (11.71ms)4202026/08/27 11:06:26 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)4212026/08/27 11:06:26 OK 20251218171726_add_pins.sql (3.41ms)4222026/08/27 11:06:26 OK 20260628120000_add_object_size_and_stats.sql (3.25ms)4232026/08/27 11:06:26 goose: successfully migrated database to version: 202606281200004242026/08/27 11:06:26 OK 1_commit_pending_closure.sql (1.98ms)4252026/08/27 11:06:26 OK 2_object_stats_trigger.sql (951.57µs)4262026/08/27 11:06:26 goose: up to current file version: 2427--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.68s)428=== RUN TestGCBugBareHashReferences429=== PAUSE TestGCBugBareHashReferences430=== RUN TestGCMetrics431=== PAUSE TestGCMetrics432=== RUN TestGCTaskStore_StartNew433=== PAUSE TestGCTaskStore_StartNew434=== RUN TestGCTaskStore_DeduplicateSameParams435=== PAUSE TestGCTaskStore_DeduplicateSameParams436=== RUN TestGCTaskStore_ConflictDifferentParams437=== PAUSE TestGCTaskStore_ConflictDifferentParams438=== RUN TestGCTaskStore_GetEmpty439=== PAUSE TestGCTaskStore_GetEmpty440=== RUN TestGCTaskStore_GetReturnsLatest441=== PAUSE TestGCTaskStore_GetReturnsLatest442=== RUN TestGCTaskStore_CompletedAllowsNewTask443=== PAUSE TestGCTaskStore_CompletedAllowsNewTask444=== RUN TestGCTaskStore_PhaseUpdates445=== PAUSE TestGCTaskStore_PhaseUpdates446=== RUN TestGCTaskStore_Fail447=== PAUSE TestGCTaskStore_Fail448=== RUN TestGracefulShutdownDrainsInflight449=== PAUSE TestGracefulShutdownDrainsInflight450=== RUN TestService_healthCheckHandler451=== PAUSE TestService_healthCheckHandler452=== RUN TestService_readinessHandler453=== PAUSE TestService_readinessHandler454=== RUN TestGenerateLandingPage455=== PAUSE TestGenerateLandingPage456=== RUN TestCacheConfigHandlerMaxNarSize457=== PAUSE TestCacheConfigHandlerMaxNarSize458=== RUN TestCreatePendingClosureRejectsOversizedNAR459=== PAUSE TestCreatePendingClosureRejectsOversizedNAR460=== RUN TestNARDeduplicationMetadataUploadBug461=== PAUSE TestNARDeduplicationMetadataUploadBug462=== RUN TestMetricsInventory463=== PAUSE TestMetricsInventory464=== RUN TestService_NativeMTLS465=== PAUSE TestService_NativeMTLS466=== RUN TestServerTLSConfig467=== PAUSE TestServerTLSConfig468=== RUN TestMultipartCleanup469=== PAUSE TestMultipartCleanup470=== RUN TestObjectStatsTrigger471=== PAUSE TestObjectStatsTrigger472=== RUN TestOrphanedObjectsGC473=== PAUSE TestOrphanedObjectsGC474=== RUN TestOrphanedObjectsGCStressTest475=== PAUSE TestOrphanedObjectsGCStressTest476=== RUN TestResurrectedObjectNotDeleted477=== PAUSE TestResurrectedObjectNotDeleted478=== RUN TestParseSingleRange479=== PAUSE TestParseSingleRange480=== RUN TestIsValidCachePath481=== PAUSE TestIsValidCachePath482=== RUN TestReadProxyNarinfo483=== PAUSE TestReadProxyNarinfo484=== RUN TestReadProxyNarinfoAlreadyDecompressed485=== PAUSE TestReadProxyNarinfoAlreadyDecompressed486=== RUN TestReadProxyNarStreaming487=== PAUSE TestReadProxyNarStreaming488=== RUN TestReadProxy404489=== PAUSE TestReadProxy404490=== RUN TestReadProxyInvalidPath491=== PAUSE TestReadProxyInvalidPath492=== RUN TestReadProxyHead493=== PAUSE TestReadProxyHead494=== RUN TestReadProxyConditionalGet495=== PAUSE TestReadProxyConditionalGet496=== RUN TestReadProxyRootRedirectsToIndexHTML497=== PAUSE TestReadProxyRootRedirectsToIndexHTML498=== RUN TestReadProxyDisabled499=== PAUSE TestReadProxyDisabled500=== RUN TestReadRedirectNar501=== PAUSE TestReadRedirectNar502=== RUN TestReadRedirectKeepsNarinfoProxied503=== PAUSE TestReadRedirectKeepsNarinfoProxied504=== RUN TestReadProxyRangeRequest505=== PAUSE TestReadProxyRangeRequest506=== 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/27 11:06:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5262026/08/27 11:06:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5272026/08/27 11:06:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5282026/08/27 11:06:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5292026/08/27 11:06:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5302026/08/27 11:06:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5312026/08/27 11:06:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5322026/08/27 11:06:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5332026/08/27 11:06:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5342026/08/27 11:06:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"535--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)536=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle537=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle538=== RUN TestProxyWriteTimeout539=== PAUSE TestProxyWriteTimeout540=== RUN TestIsValidUploadKey541=== PAUSE TestIsValidUploadKey542=== RUN TestUploadHandlersRejectInvalidKeys543=== PAUSE TestUploadHandlersRejectInvalidKeys544=== RUN TestUploadHandlersRejectOversizedBody545=== PAUSE TestUploadHandlersRejectOversizedBody546=== RUN TestService_cleanupPendingClosuresHandler547=== PAUSE TestService_cleanupPendingClosuresHandler548=== RUN TestService_createPendingClosureHandler549=== PAUSE TestService_createPendingClosureHandler550=== RUN TestService_verifyS3Integrity551=== PAUSE TestService_verifyS3Integrity552=== RUN TestCompleteMultipartUnregistered553=== PAUSE TestCompleteMultipartUnregistered554=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT555=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT556=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT557=== CONT TestService_AuthMiddleware558=== CONT TestCompleteMultipartUnregistered559=== CONT TestService_verifyS3Integrity560=== CONT TestService_createPendingClosureHandler561=== CONT TestService_cleanupPendingClosuresHandler562=== CONT TestUploadHandlersRejectOversizedBody563=== CONT TestNARDeduplicationMetadataUploadBug564=== CONT TestCreatePendingClosureRejectsOversizedNAR565=== CONT TestCacheConfigHandlerMaxNarSize566=== CONT TestGenerateLandingPage567--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)568=== CONT TestGCTaskStore_GetEmpty569--- PASS: TestGCTaskStore_GetEmpty (0.00s)570=== CONT TestGCTaskStore_ConflictDifferentParams571--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)572=== CONT TestParseSize5732026/08/27 11:06:26 INFO Received uploads request method=POST path=/api/pending_closures574--- PASS: TestParseSize (0.00s)575=== CONT TestGCTaskStore_DeduplicateSameParams576=== CONT TestService_readinessHandler577=== CONT TestService_healthCheckHandler578=== CONT TestGCTaskStore_StartNew579=== CONT TestPresignedUploadRegisteredBeforeCommit580=== CONT TestMetricsInventory581=== CONT TestGracefulShutdownDrainsInflight582=== CONT TestUploadHandlersRejectInvalidKeys583=== CONT TestGCTaskStore_Fail584=== CONT TestIsValidUploadKey585=== CONT TestGCTaskStore_PhaseUpdates586=== CONT TestProxyWriteTimeout587=== CONT TestGCTaskStore_CompletedAllowsNewTask588=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle589=== CONT TestGCTaskStore_GetReturnsLatest590=== CONT TestSkippedUploadsHandler591--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)592--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)593--- PASS: TestGCTaskStore_StartNew (0.00s)594--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)595=== CONT TestGCMetrics596=== RUN TestProxyWriteTimeout/narinfo597=== PAUSE TestProxyWriteTimeout/narinfo598=== RUN TestProxyWriteTimeout/1_GiB_nar599=== PAUSE TestProxyWriteTimeout/1_GiB_nar600=== RUN TestProxyWriteTimeout/10_GiB_nar601=== PAUSE TestProxyWriteTimeout/10_GiB_nar602=== RUN TestProxyWriteTimeout/unknown_size603=== PAUSE TestProxyWriteTimeout/unknown_size604=== CONT TestCompletedNarNotReofferedAcrossClosures605--- PASS: TestGenerateLandingPage (0.00s)606--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)607=== CONT TestCacheStatsHandler608=== CONT TestService_Rustfstest609=== CONT TestCompleteMultipartUpload_ErrorButObjectExists610=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info611=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info6122026/08/27 11:06:26 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000613--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)614=== CONT TestCacheConfigHandler615=== RUN TestIsValidUploadKey/narinfo616=== PAUSE TestIsValidUploadKey/narinfo617=== RUN TestIsValidUploadKey/nar_zst618=== RUN TestCacheConfigHandler/full_config,_no_issuer6192026/08/27 11:06:27 INFO Starting HTTP server address=127.0.0.1:36239620=== PAUSE TestIsValidUploadKey/nar_zst621=== RUN TestIsValidUploadKey/nar_xz622=== PAUSE TestCacheConfigHandler/full_config,_no_issuer623=== PAUSE TestIsValidUploadKey/nar_xz624=== RUN TestCacheConfigHandler/no_cache_url_configured625=== PAUSE TestCacheConfigHandler/no_cache_url_configured626--- PASS: TestGCTaskStore_Fail (0.00s)627=== RUN TestCacheConfigHandler/no_signing_keys628=== PAUSE TestCacheConfigHandler/no_signing_keys629=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator630=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator631=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal632=== CONT TestRedundantMultipartUpload633=== RUN TestIsValidUploadKey/nar_plain634=== CONT TestService_ReadScope_PublicByDefault635=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal636=== PAUSE TestIsValidUploadKey/nar_plain637=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key638=== RUN TestIsValidUploadKey/listing639=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key640=== PAUSE TestIsValidUploadKey/listing641=== RUN TestIsValidUploadKey/build_log6422026/08/27 11:06:27 INFO Shutdown signal received, draining in-flight requests timeout=10s643=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key644=== PAUSE TestIsValidUploadKey/build_log645=== RUN TestIsValidUploadKey/build_log_home-manager_file646=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key647=== PAUSE TestIsValidUploadKey/build_log_home-manager_file648=== CONT TestReadProxyRangeRequest649=== RUN TestIsValidUploadKey/build_log_plus_in_name650=== PAUSE TestIsValidUploadKey/build_log_plus_in_name651=== RUN TestIsValidUploadKey/build_log_question_mark652=== PAUSE TestIsValidUploadKey/build_log_question_mark653=== RUN TestIsValidUploadKey/build_log_equals654=== PAUSE TestIsValidUploadKey/build_log_equals655=== RUN TestIsValidUploadKey/realisation656=== PAUSE TestIsValidUploadKey/realisation657=== RUN TestIsValidUploadKey/realisation_plus_in_output658=== PAUSE TestIsValidUploadKey/realisation_plus_in_output659=== RUN TestIsValidUploadKey/nix-cache-info660=== PAUSE TestIsValidUploadKey/nix-cache-info661=== RUN TestIsValidUploadKey/index.html662=== PAUSE TestIsValidUploadKey/index.html663=== RUN TestIsValidUploadKey/narinfo_key,_nar_type664=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type665=== RUN TestIsValidUploadKey/nar_key,_narinfo_type666=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type667=== RUN TestIsValidUploadKey/listing_key,_narinfo_type668=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type669=== RUN TestIsValidUploadKey/traversal670=== PAUSE TestIsValidUploadKey/traversal671=== RUN TestIsValidUploadKey/traversal_nar672=== PAUSE TestIsValidUploadKey/traversal_nar673=== RUN TestIsValidUploadKey/absolute674=== PAUSE TestIsValidUploadKey/absolute675=== RUN TestIsValidUploadKey/empty_key676=== PAUSE TestIsValidUploadKey/empty_key677=== RUN TestIsValidUploadKey/unknown_type678=== PAUSE TestIsValidUploadKey/unknown_type679=== CONT TestService_RequireScope_OIDC680--- PASS: TestSkippedUploadsHandler (0.07s)681=== CONT TestReadRedirectKeepsNarinfoProxied6822026/08/27 11:06:27 INFO OIDC provider initialized name=test6832026-08-27 11:06:27.052 UTC [576] ERROR: relation "goose_db_version" does not exist at character 366842026-08-27 11:06:27.052 UTC [576] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6852026-08-27 11:06:27.054 UTC [579] ERROR: relation "goose_db_version" does not exist at character 366862026-08-27 11:06:27.054 UTC [579] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6872026-08-27 11:06:27.055 UTC [580] ERROR: relation "goose_db_version" does not exist at character 366882026-08-27 11:06:27.055 UTC [580] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6892026-08-27 11:06:27.056 UTC [581] ERROR: relation "goose_db_version" does not exist at character 366902026-08-27 11:06:27.056 UTC [581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC691=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts692=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts693=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure694=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure695=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart696=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart697=== CONT TestService_AuthMiddleware_OIDC6982026/08/27 11:06:27 INFO OIDC provider initialized name=test6992026-08-27 11:06:27.181 UTC [594] ERROR: relation "goose_db_version" does not exist at character 367002026-08-27 11:06:27.181 UTC [594] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7012026-08-27 11:06:27.181 UTC [595] ERROR: relation "goose_db_version" does not exist at character 367022026-08-27 11:06:27.181 UTC [595] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7032026-08-27 11:06:27.182 UTC [596] ERROR: relation "goose_db_version" does not exist at character 367042026-08-27 11:06:27.182 UTC [596] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7052026/08/27 11:06:27 OK 20241026095416_initial_model.sql (54.96ms)7062026/08/27 11:06:27 OK 20241026095416_initial_model.sql (25.75ms)7072026/08/27 11:06:27 OK 20241026095416_initial_model.sql (59.13ms)7082026/08/27 11:06:27 OK 20241026095416_initial_model.sql (58.65ms)7092026/08/27 11:06:27 OK 20241026095416_initial_model.sql (58.7ms)7102026-08-27 11:06:27.232 UTC [599] ERROR: relation "goose_db_version" does not exist at character 367112026-08-27 11:06:27.232 UTC [599] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7122026/08/27 11:06:27 OK 20241026095416_initial_model.sql (27.31ms)7132026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (5.34ms)7142026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (5.79ms)7152026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (5.31ms)7162026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (5.41ms)7172026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (5.54ms)7182026-08-27 11:06:27.241 UTC [600] ERROR: relation "goose_db_version" does not exist at character 367192026-08-27 11:06:27.241 UTC [600] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC720--- PASS: TestGracefulShutdownDrainsInflight (0.26s)721=== CONT TestReadRedirectNar7222026/08/27 11:06:27 OK 20241026095416_initial_model.sql (29.81ms)7232026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (4.29ms)7242026/08/27 11:06:27 OK 20251218171726_add_pins.sql (6.61ms)7252026/08/27 11:06:27 OK 20251218171726_add_pins.sql (6.81ms)7262026-08-27 11:06:27.246 UTC [601] ERROR: relation "goose_db_version" does not exist at character 367272026-08-27 11:06:27.246 UTC [601] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7282026-08-27 11:06:27.249 UTC [602] ERROR: relation "goose_db_version" does not exist at character 367292026-08-27 11:06:27.249 UTC [602] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7302026-08-27 11:06:27.249 UTC [604] ERROR: relation "goose_db_version" does not exist at character 367312026-08-27 11:06:27.249 UTC [604] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7322026-08-27 11:06:27.250 UTC [606] ERROR: relation "goose_db_version" does not exist at character 367332026-08-27 11:06:27.250 UTC [606] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7342026-08-27 11:06:27.254 UTC [609] ERROR: relation "goose_db_version" does not exist at character 367352026-08-27 11:06:27.254 UTC [609] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7362026-08-27 11:06:27.254 UTC [605] ERROR: relation "goose_db_version" does not exist at character 367372026-08-27 11:06:27.254 UTC [605] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7382026-08-27 11:06:27.255 UTC [608] ERROR: relation "goose_db_version" does not exist at character 367392026-08-27 11:06:27.255 UTC [608] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7402026/08/27 11:06:27 OK 20251218171726_add_pins.sql (18.91ms)7412026/08/27 11:06:27 OK 20251218171726_add_pins.sql (18.84ms)7422026/08/27 11:06:27 OK 20251218171726_add_pins.sql (19.01ms)7432026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (14.51ms)7442026/08/27 11:06:27 OK 20251218171726_add_pins.sql (15.19ms)7452026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (13.96ms)7462026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200007472026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (14.06ms)7482026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200007492026/08/27 11:06:27 OK 20241026095416_initial_model.sql (17.93ms)7502026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (3.63ms)7512026/08/27 11:06:27 OK 1_commit_pending_closure.sql (4.86ms)7522026/08/27 11:06:27 OK 1_commit_pending_closure.sql (5.92ms)7532026/08/27 11:06:27 OK 2_object_stats_trigger.sql (2.69ms)7542026/08/27 11:06:27 goose: up to current file version: 27552026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (10.11ms)7562026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200007572026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (10.7ms)7582026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200007592026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (11.52ms)7602026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200007612026/08/27 11:06:27 OK 20251218171726_add_pins.sql (12.29ms)7622026/08/27 11:06:27 OK 2_object_stats_trigger.sql (3.83ms)7632026/08/27 11:06:27 goose: up to current file version: 27642026/08/27 11:06:27 OK 20251218171726_add_pins.sql (7.45ms)7652026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (12.2ms)7662026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200007672026/08/27 11:06:27 OK 1_commit_pending_closure.sql (4.1ms)7682026/08/27 11:06:27 OK 1_commit_pending_closure.sql (4.98ms)7692026/08/27 11:06:27 OK 2_object_stats_trigger.sql (3.48ms)7702026/08/27 11:06:27 goose: up to current file version: 27712026/08/27 11:06:27 OK 1_commit_pending_closure.sql (6.41ms)7722026/08/27 11:06:27 OK 1_commit_pending_closure.sql (4.96ms)7732026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.04ms)7742026/08/27 11:06:27 goose: up to current file version: 27752026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (6.51ms)7762026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200007772026/08/27 11:06:27 OK 2_object_stats_trigger.sql (3.79ms)7782026/08/27 11:06:27 goose: up to current file version: 27792026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (9.41ms)7802026/08/27 11:06:27 OK 20241026095416_initial_model.sql (17.93ms)7812026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200007822026/08/27 11:06:27 OK 20241026095416_initial_model.sql (18.05ms)7832026/08/27 11:06:27 OK 20241026095416_initial_model.sql (17.28ms)7842026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.36ms)7852026/08/27 11:06:27 goose: up to current file version: 27862026/08/27 11:06:27 OK 1_commit_pending_closure.sql (4.49ms)7872026/08/27 11:06:27 OK 20241026095416_initial_model.sql (19.74ms)7882026/08/27 11:06:27 OK 20241026095416_initial_model.sql (21.47ms)7892026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (3.37ms)7902026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (3.6ms)7912026/08/27 11:06:27 OK 1_commit_pending_closure.sql (4.52ms)7922026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (4.82ms)7932026/08/27 11:06:27 OK 20241026095416_initial_model.sql (17.19ms)7942026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (2.79ms)7952026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.18ms)7962026/08/27 11:06:27 goose: up to current file version: 27972026/08/27 11:06:27 OK 20241026095416_initial_model.sql (18.11ms)7982026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (4.31ms)7992026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4ms)8002026/08/27 11:06:27 goose: up to current file version: 28012026/08/27 11:06:27 OK 20251218171726_add_pins.sql (5.2ms)8022026/08/27 11:06:27 INFO Received uploads request method=POST path=/api/pending_closures8032026/08/27 11:06:27 OK 20251218171726_add_pins.sql (7.21ms)8042026/08/27 11:06:27 OK 20241026095416_initial_model.sql (22.38ms)8052026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (5.19ms)8062026-08-27 11:06:27.292 UTC [610] ERROR: relation "goose_db_version" does not exist at character 368072026-08-27 11:06:27.292 UTC [610] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8082026-08-27 11:06:27.293 UTC [611] ERROR: relation "goose_db_version" does not exist at character 368092026-08-27 11:06:27.293 UTC [611] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8102026/08/27 11:06:27 OK 20251218171726_add_pins.sql (15.99ms)8112026/08/27 11:06:27 OK 20251218171726_add_pins.sql (17.33ms)8122026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (14.95ms)8132026/08/27 11:06:27 OK 20251218171726_add_pins.sql (17.63ms)8142026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (16.67ms)8152026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200008162026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (14.57ms)8172026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200008182026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (14.8ms)8192026/08/27 11:06:27 OK 20251218171726_add_pins.sql (14.27ms)8202026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (6.85ms)8212026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200008222026/08/27 11:06:27 OK 20251218171726_add_pins.sql (6.67ms)8232026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (6.99ms)8242026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200008252026/08/27 11:06:27 INFO Received cleanup request method=DELETE path=/api/pending_closures8262026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (5.93ms)8272026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200008282026/08/27 11:06:27 OK 1_commit_pending_closure.sql (5.65ms)8292026/08/27 11:06:27 OK 1_commit_pending_closure.sql (5.72ms)8302026/08/27 11:06:27 OK 20251218171726_add_pins.sql (8.79ms)8312026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (8.75ms)8322026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200008332026/08/27 11:06:27 INFO Aborted multipart uploads count=08342026-08-27 11:06:27.315 UTC [612] ERROR: relation "goose_db_version" does not exist at character 368352026-08-27 11:06:27.315 UTC [612] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8362026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.88ms)8372026/08/27 11:06:27 goose: up to current file version: 28382026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.98ms)8392026/08/27 11:06:27 goose: up to current file version: 28402026/08/27 11:06:27 OK 1_commit_pending_closure.sql (7.09ms)8412026/08/27 11:06:27 OK 1_commit_pending_closure.sql (5.13ms)8422026/08/27 11:06:27 OK 1_commit_pending_closure.sql (6.9ms)8432026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (8.38ms)8442026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200008452026/08/27 11:06:27 OK 20241026095416_initial_model.sql (11.71ms)8462026/08/27 11:06:27 INFO Received uploads request method=POST path=/api/pending_closures8472026/08/27 11:06:27 OK 1_commit_pending_closure.sql (4.54ms)8482026-08-27 11:06:27.319 UTC [613] ERROR: relation "goose_db_version" does not exist at character 368492026-08-27 11:06:27.319 UTC [613] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8502026-08-27 11:06:27.319 UTC [614] ERROR: relation "goose_db_version" does not exist at character 368512026-08-27 11:06:27.319 UTC [614] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8522026-08-27 11:06:27.319 UTC [616] ERROR: relation "goose_db_version" does not exist at character 368532026-08-27 11:06:27.319 UTC [616] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8542026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.07ms)8552026/08/27 11:06:27 goose: up to current file version: 28562026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.17ms)8572026/08/27 11:06:27 goose: up to current file version: 28582026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (6.62ms)8592026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200008602026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.3ms)8612026-08-27 11:06:27.320 UTC [615] ERROR: relation "goose_db_version" does not exist at character 368622026-08-27 11:06:27.320 UTC [615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8632026/08/27 11:06:27 goose: up to current file version: 28642026/08/27 11:06:27 OK 20241026095416_initial_model.sql (14.81ms)8652026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (3.21ms)8662026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.16ms)8672026/08/27 11:06:27 goose: up to current file version: 28682026/08/27 11:06:27 OK 1_commit_pending_closure.sql (5.66ms)8692026/08/27 11:06:27 OK 2_object_stats_trigger.sql (1.63ms)8702026/08/27 11:06:27 goose: up to current file version: 28712026/08/27 11:06:27 OK 1_commit_pending_closure.sql (4.24ms)8722026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (3.56ms)8732026/08/27 11:06:27 OK 20251218171726_add_pins.sql (5.73ms)8742026/08/27 11:06:27 OK 2_object_stats_trigger.sql (2.5ms)8752026/08/27 11:06:27 goose: up to current file version: 28762026/08/27 11:06:27 OK 20251218171726_add_pins.sql (5.58ms)8772026/08/27 11:06:27 INFO Received uploads request method=POST path=/api/pending_closures8782026/08/27 11:06:27 INFO Received cleanup request method=DELETE path=/api/pending_closures8792026/08/27 11:06:27 INFO Received uploads request method=POST path=/api/pending_closures8802026/08/27 11:06:27 INFO Received uploads request method=POST path=/api/pending_closures8812026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (5.9ms)8822026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200008832026/08/27 11:06:27 INFO Aborted multipart uploads count=18842026/08/27 11:06:27 OK 20241026095416_initial_model.sql (11.62ms)8852026/08/27 11:06:27 OK 1_commit_pending_closure.sql (5.53ms)8862026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (7.9ms)8872026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200008882026/08/27 11:06:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8892026/08/27 11:06:27 OK 20241026095416_initial_model.sql (10.14ms)8902026-08-27 11:06:27.339 UTC [576] ERROR: Closure does not exist: id=18912026-08-27 11:06:27.339 UTC [576] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE8922026-08-27 11:06:27.339 UTC [576] STATEMENT: -- name: CommitPendingClosure :exec893 SELECT commit_pending_closure($1::bigint)894 8952026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (2.93ms)896--- PASS: TestService_cleanupPendingClosuresHandler (0.43s)897=== CONT TestService_ReadAuthMiddleware8982026-08-27 11:06:27.341 UTC [617] ERROR: relation "goose_db_version" does not exist at character 368992026-08-27 11:06:27.341 UTC [617] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9002026/08/27 11:06:27 OK 2_object_stats_trigger.sql (5.02ms)9012026/08/27 11:06:27 goose: up to current file version: 29022026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (4.43ms)9032026/08/27 11:06:27 OK 1_commit_pending_closure.sql (6.66ms)9042026/08/27 11:06:27 OK 20241026095416_initial_model.sql (16.95ms)9052026/08/27 11:06:27 OK 20251218171726_add_pins.sql (5.43ms)9062026/08/27 11:06:27 OK 20241026095416_initial_model.sql (14ms)9072026/08/27 11:06:27 OK 20241026095416_initial_model.sql (15.03ms)9082026/08/27 11:06:27 OK 2_object_stats_trigger.sql (2.43ms)9092026/08/27 11:06:27 goose: up to current file version: 29102026/08/27 11:06:27 OK 20251218171726_add_pins.sql (4.7ms)9112026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (3.42ms)9122026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (3.53ms)9132026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (3.64ms)9142026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200009152026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (3.7ms)9162026/08/27 11:06:27 INFO Received uploads request method=POST path=/api/pending_closures9172026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (4.83ms)9182026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200009192026/08/27 11:06:27 OK 1_commit_pending_closure.sql (4.18ms)9202026/08/27 11:06:27 OK 20251218171726_add_pins.sql (5.39ms)9212026/08/27 11:06:27 OK 20251218171726_add_pins.sql (5.52ms)9222026/08/27 11:06:27 OK 20251218171726_add_pins.sql (5.21ms)9232026/08/27 11:06:27 OK 2_object_stats_trigger.sql (2.29ms)9242026/08/27 11:06:27 goose: up to current file version: 29252026/08/27 11:06:27 OK 1_commit_pending_closure.sql (5.08ms)9262026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (5.6ms)9272026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200009282026/08/27 11:06:27 OK 20241026095416_initial_model.sql (11.15ms)9292026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (5.99ms)9302026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200009312026/08/27 11:06:27 OK 2_object_stats_trigger.sql (3.59ms)9322026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (7.84ms)9332026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200009342026/08/27 11:06:27 goose: up to current file version: 29352026/08/27 11:06:27 OK 1_commit_pending_closure.sql (6.1ms)9362026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (6.47ms)9372026/08/27 11:06:27 OK 1_commit_pending_closure.sql (5.81ms)9382026/08/27 11:06:27 OK 1_commit_pending_closure.sql (7.86ms)9392026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.76ms)9402026/08/27 11:06:27 goose: up to current file version: 29412026/08/27 11:06:27 OK 20251218171726_add_pins.sql (6.17ms)9422026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.76ms)9432026/08/27 11:06:27 goose: up to current file version: 29442026/08/27 11:06:27 OK 2_object_stats_trigger.sql (4.64ms)9452026/08/27 11:06:27 goose: up to current file version: 2946--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.46s)947=== CONT TestReadProxyDisabled9482026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (5.23ms)9492026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200009502026/08/27 11:06:27 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"951--- PASS: TestService_AuthMiddleware (0.47s)952=== CONT TestService_AuthMiddleware_MTLSBoundSubjects9532026/08/27 11:06:27 OK 1_commit_pending_closure.sql (6.27ms)9542026/08/27 11:06:27 OK 2_object_stats_trigger.sql (1.65ms)9552026/08/27 11:06:27 goose: up to current file version: 29562026-08-27 11:06:27.424 UTC [626] ERROR: relation "goose_db_version" does not exist at character 369572026-08-27 11:06:27.424 UTC [626] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9582026/08/27 11:06:27 OK 20241026095416_initial_model.sql (19.69ms)9592026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (2.86ms)9602026/08/27 11:06:27 OK 20251218171726_add_pins.sql (3.05ms)9612026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (3.9ms)9622026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200009632026-08-27 11:06:27.467 UTC [627] ERROR: relation "goose_db_version" does not exist at character 369642026-08-27 11:06:27.467 UTC [627] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9652026/08/27 11:06:27 OK 1_commit_pending_closure.sql (2.55ms)9662026/08/27 11:06:27 OK 2_object_stats_trigger.sql (1.36ms)9672026/08/27 11:06:27 goose: up to current file version: 29682026-08-27 11:06:27.470 UTC [628] ERROR: relation "goose_db_version" does not exist at character 369692026-08-27 11:06:27.470 UTC [628] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9702026/08/27 11:06:27 OK 20241026095416_initial_model.sql (10.96ms)9712026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (1.35ms)9722026/08/27 11:06:27 OK 20251218171726_add_pins.sql (4.2ms)9732026/08/27 11:06:27 OK 20241026095416_initial_model.sql (13.69ms)9742026/08/27 11:06:27 OK 20251210153512_drop_unused_gin_index.sql (1.51ms)9752026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (3.16ms)9762026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200009772026/08/27 11:06:27 OK 1_commit_pending_closure.sql (1.98ms)9782026/08/27 11:06:27 OK 20251218171726_add_pins.sql (4.04ms)9792026/08/27 11:06:27 OK 2_object_stats_trigger.sql (841.49µs)9802026/08/27 11:06:27 goose: up to current file version: 29812026/08/27 11:06:27 OK 20260628120000_add_object_size_and_stats.sql (4.26ms)9822026/08/27 11:06:27 goose: successfully migrated database to version: 202606281200009832026/08/27 11:06:27 OK 1_commit_pending_closure.sql (2.16ms)9842026/08/27 11:06:27 OK 2_object_stats_trigger.sql (981.55µs)9852026/08/27 11:06:27 goose: up to current file version: 29862026/08/27 11:06:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9872026/08/27 11:06:28 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst988--- PASS: TestCompleteMultipartUnregistered (1.98s)989=== CONT TestReadProxyRootRedirectsToIndexHTML9902026/08/27 11:06:28 INFO Received uploads request method=POST path=/api/pending_closures9912026/08/27 11:06:28 INFO Received uploads request method=POST path=/api/pending_closures9922026/08/27 11:06:28 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9932026/08/27 11:06:28 INFO Received uploads request method=POST path=/api/pending_closures994--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.00s)995=== CONT TestService_AuthMiddleware_MTLSProxyHeader9962026/08/27 11:06:28 INFO Received uploads request method=POST path=/api/pending_closures9972026-08-27 11:06:28.949 UTC [633] ERROR: relation "goose_db_version" does not exist at character 369982026-08-27 11:06:28.949 UTC [633] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9992026/08/27 11:06:28 OK 20241026095416_initial_model.sql (18.41ms)10002026/08/27 11:06:28 OK 20251210153512_drop_unused_gin_index.sql (4.36ms)10012026/08/27 11:06:28 OK 20251218171726_add_pins.sql (5.48ms)10022026/08/27 11:06:28 OK 20260628120000_add_object_size_and_stats.sql (4.3ms)10032026/08/27 11:06:28 goose: successfully migrated database to version: 2026062812000010042026/08/27 11:06:28 OK 1_commit_pending_closure.sql (2.82ms)10052026/08/27 11:06:28 OK 2_object_stats_trigger.sql (901.89µs)10062026/08/27 11:06:28 goose: up to current file version: 210072026/08/27 11:06:29 INFO Aborted multipart uploads count=010082026-08-27 11:06:29.001 UTC [640] ERROR: relation "goose_db_version" does not exist at character 3610092026-08-27 11:06:29.001 UTC [640] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10102026/08/27 11:06:29 WARN Force mode enabled - objects will be deleted immediately without grace period10112026/08/27 11:06:29 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=010122026/08/27 11:06:29 INFO Vacuumed table table=pending_closures10132026/08/27 11:06:29 INFO Vacuumed table table=pending_objects10142026/08/27 11:06:29 INFO Vacuumed table table=multipart_uploads10152026/08/27 11:06:29 INFO Vacuumed table table=closures10162026/08/27 11:06:29 INFO Vacuumed table table=objects1017--- PASS: TestGCMetrics (2.10s)1018=== CONT TestClientCADerivations1019--- PASS: TestCacheStatsHandler (2.10s)1020=== CONT TestClientWithDependencies1021=== NAME TestNARDeduplicationMetadataUploadBug1022 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug835665952/001/store/ix0w395ma2sc5mi5kkax4visjjdywxil-file1.txt10232026/08/27 11:06:29 OK 20241026095416_initial_model.sql (16ms)10242026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)10252026/08/27 11:06:29 OK 20251218171726_add_pins.sql (4.07ms)10262026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (3.44ms)10272026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000010282026/08/27 11:06:29 OK 1_commit_pending_closure.sql (3.15ms)10292026/08/27 11:06:29 OK 2_object_stats_trigger.sql (2.11ms)10302026/08/27 11:06:29 goose: up to current file version: 210312026/08/27 11:06:29 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10322026-08-27 11:06:29.119 UTC [698] ERROR: relation "goose_db_version" does not exist at character 3610332026-08-27 11:06:29.119 UTC [698] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10342026-08-27 11:06:29.119 UTC [699] ERROR: relation "goose_db_version" does not exist at character 3610352026-08-27 11:06:29.119 UTC [699] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10362026/08/27 11:06:29 OK 20241026095416_initial_model.sql (12.8ms)10372026/08/27 11:06:29 OK 20241026095416_initial_model.sql (12.91ms)10382026/08/27 11:06:29 INFO Received uploads request method=POST path=/api/pending_closures10392026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (1.7ms)10402026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (2.6ms)10412026/08/27 11:06:29 OK 20251218171726_add_pins.sql (5.65ms)10422026/08/27 11:06:29 OK 20251218171726_add_pins.sql (5.39ms)10432026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (4.31ms)10442026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000010452026/08/27 11:06:29 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10462026/08/27 11:06:29 INFO Uploading ix0w395ma2sc5mi5kkax4visjjdywxil-file1.txt (160B)10472026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (5.12ms)10482026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000010492026/08/27 11:06:29 OK 1_commit_pending_closure.sql (2.15ms)10502026/08/27 11:06:29 OK 1_commit_pending_closure.sql (2.14ms)10512026/08/27 11:06:29 OK 2_object_stats_trigger.sql (1.46ms)10522026/08/27 11:06:29 goose: up to current file version: 210532026/08/27 11:06:29 OK 2_object_stats_trigger.sql (954.27µs)10542026/08/27 11:06:29 goose: up to current file version: 210552026/08/27 11:06:29 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10562026/08/27 11:06:29 WARN Failed to register uploaded object key=ix0w395ma2sc5mi5kkax4visjjdywxil.ls error="server returned 404: 404 page not found\n"10572026/08/27 11:06:29 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10582026/08/27 11:06:29 INFO Signed narinfos id=1 count=110592026/08/27 11:06:29 INFO Uploading 1 narinfos10602026/08/27 11:06:29 WARN Failed to register uploaded object key=ix0w395ma2sc5mi5kkax4visjjdywxil.narinfo error="server returned 404: 404 page not found\n"10612026/08/27 11:06:29 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1062--- PASS: TestService_healthCheckHandler (2.48s)1063=== CONT TestClientMultipleUploads10642026/08/27 11:06:29 INFO Completed upload id=110652026/08/27 11:06:29 INFO Upload complete. (342ms)1066=== NAME TestNARDeduplicationMetadataUploadBug1067 metadata_upload_test.go:54: Retrieved narinfo from S3:1068 StorePath: /build/TestNARDeduplicationMetadataUploadBug835665952/001/store/ix0w395ma2sc5mi5kkax4visjjdywxil-file1.txt1069 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1070 Compression: zstd1071 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1072 NarSize: 1601073 References: 1074 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1075 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1076 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1077 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1078--- PASS: TestService_Rustfstest (2.50s)1079=== CONT TestGCBugBareHashReferences10802026/08/27 11:06:29 WARN readiness check failed error="closed pool"1081--- PASS: TestService_readinessHandler (2.52s)1082=== CONT TestResolveDBConnectionString10832026/08/27 11:06:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1084=== RUN TestResolveDBConnectionString/flag_wins1085=== PAUSE TestResolveDBConnectionString/flag_wins1086=== RUN TestResolveDBConnectionString/file_when_flag_empty1087=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1088=== RUN TestResolveDBConnectionString/missing_file_is_an_error1089=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1090=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1091=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1092=== RUN TestResolveDBConnectionString/nothing_configured1093=== PAUSE TestResolveDBConnectionString/nothing_configured1094=== CONT TestPinProtectsFromGC1095=== NAME TestNARDeduplicationMetadataUploadBug1096 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug835665952/001/store/52hr0h475nfarx1iyzvjkik462hycji2-file2.txt10972026/08/27 11:06:29 INFO Received uploads request method=POST path=/api/pending_closures10982026/08/27 11:06:29 INFO Received uploads request method=POST path=/api/pending_closures10992026-08-27 11:06:29.487 UTC [741] ERROR: relation "goose_db_version" does not exist at character 3611002026-08-27 11:06:29.487 UTC [741] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11012026/08/27 11:06:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11022026/08/27 11:06:29 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTY0YzJlZjctZGU4OS00YmM4LWJlZjUtNzE4YjUxMGM4YzI1LjI3MzUwZDY4LTk5MzktNDFiMC1hZDJjLTgzOTU1NDQyMDU1M3gxNzg3ODI4Nzg5NDc5NzAzNTIy11032026-08-27 11:06:29.515 UTC [760] ERROR: relation "goose_db_version" does not exist at character 3611042026-08-27 11:06:29.515 UTC [760] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1105=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1106=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1107=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1108=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1109=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1110=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1111=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1112=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1113=== CONT TestParseSingleRange1114=== RUN TestParseSingleRange/none1115=== PAUSE TestParseSingleRange/none1116=== RUN TestParseSingleRange/unknown_unit1117=== PAUSE TestParseSingleRange/unknown_unit1118=== RUN TestParseSingleRange/multi-range_ignored1119=== PAUSE TestParseSingleRange/multi-range_ignored1120=== RUN TestParseSingleRange/malformed_no_dash1121=== PAUSE TestParseSingleRange/malformed_no_dash1122=== RUN TestParseSingleRange/malformed_both_empty1123=== PAUSE TestParseSingleRange/malformed_both_empty1124=== RUN TestParseSingleRange/malformed_end_before_start1125=== PAUSE TestParseSingleRange/malformed_end_before_start1126=== RUN TestParseSingleRange/closed1127=== PAUSE TestParseSingleRange/closed1128=== RUN TestParseSingleRange/open-ended1129=== PAUSE TestParseSingleRange/open-ended1130=== RUN TestParseSingleRange/end_clamped_to_size1131=== PAUSE TestParseSingleRange/end_clamped_to_size1132=== RUN TestParseSingleRange/suffix1133=== PAUSE TestParseSingleRange/suffix1134=== RUN TestParseSingleRange/suffix_exceeds_size1135=== PAUSE TestParseSingleRange/suffix_exceeds_size1136=== RUN TestParseSingleRange/single_byte1137=== PAUSE TestParseSingleRange/single_byte1138=== RUN TestParseSingleRange/start_past_EOF1139=== PAUSE TestParseSingleRange/start_past_EOF1140=== RUN TestParseSingleRange/start_far_past_EOF1141=== PAUSE TestParseSingleRange/start_far_past_EOF1142=== CONT TestReadProxyHead11432026/08/27 11:06:29 INFO Received uploads request method=POST path=/api/pending_closures11442026/08/27 11:06:29 OK 20241026095416_initial_model.sql (19.11ms)11452026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)11462026/08/27 11:06:29 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTY0YzJlZjctZGU4OS00YmM4LWJlZjUtNzE4YjUxMGM4YzI1LjI3MzUwZDY4LTk5MzktNDFiMC1hZDJjLTgzOTU1NDQyMDU1M3gxNzg3ODI4Nzg5NDc5NzAzNTIy parts=11147--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.60s)1148=== CONT TestClientIntegration11492026/08/27 11:06:29 OK 20251218171726_add_pins.sql (5.29ms)1150--- PASS: TestService_ReadScope_PublicByDefault (2.49s)1151=== CONT TestReadProxyInvalidPath1152--- PASS: TestMetricsInventory (2.55s)1153=== CONT TestReadProxy40411542026-08-27 11:06:29.533 UTC [764] ERROR: relation "goose_db_version" does not exist at character 3611552026-08-27 11:06:29.533 UTC [764] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11562026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (7.61ms)11572026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000011582026/08/27 11:06:29 OK 20241026095416_initial_model.sql (14.6ms)11592026/08/27 11:06:29 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11602026/08/27 11:06:29 OK 1_commit_pending_closure.sql (10.54ms)11612026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (9.25ms)11622026/08/27 11:06:29 OK 2_object_stats_trigger.sql (7.27ms)11632026/08/27 11:06:29 goose: up to current file version: 211642026/08/27 11:06:29 OK 20251218171726_add_pins.sql (8.51ms)11652026/08/27 11:06:29 OK 20241026095416_initial_model.sql (13.76ms)11662026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (7.32ms)11672026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000011682026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (4.6ms)11692026/08/27 11:06:29 OK 1_commit_pending_closure.sql (4.88ms)11702026/08/27 11:06:29 OK 20251218171726_add_pins.sql (5.36ms)11712026/08/27 11:06:29 OK 2_object_stats_trigger.sql (6.4ms)11722026/08/27 11:06:29 goose: up to current file version: 211732026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (7.44ms)11742026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000011752026/08/27 11:06:29 INFO Received uploads request method=POST path=/api/pending_closures11762026/08/27 11:06:29 OK 1_commit_pending_closure.sql (7.18ms)11772026/08/27 11:06:29 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11782026/08/27 11:06:29 OK 2_object_stats_trigger.sql (5.54ms)11792026/08/27 11:06:29 goose: up to current file version: 211802026/08/27 11:06:29 WARN Failed to register uploaded object key=52hr0h475nfarx1iyzvjkik462hycji2.ls error="server returned 404: 404 page not found\n"1181=== RUN TestService_RequireScope_OIDC/builder_may_write1182=== PAUSE TestService_RequireScope_OIDC/builder_may_write1183=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1184=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1185=== RUN TestService_RequireScope_OIDC/ops_may_admin1186=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1187=== RUN TestService_RequireScope_OIDC/ops_may_not_write1188=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1189=== RUN TestService_RequireScope_OIDC/reader_may_not_write1190=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1191=== RUN TestService_RequireScope_OIDC/static_token_may_admin1192=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1193=== RUN TestService_RequireScope_OIDC/static_token_may_write1194=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1195=== RUN TestService_RequireScope_OIDC/reader_may_read1196=== PAUSE TestService_RequireScope_OIDC/reader_may_read1197=== RUN TestService_RequireScope_OIDC/writer_implies_read1198=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1199=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1200=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1201=== CONT TestClientErrorHandling1202=== RUN TestClientErrorHandling/InvalidStorePath1203=== PAUSE TestClientErrorHandling/InvalidStorePath1204=== RUN TestClientErrorHandling/InvalidAuthToken1205=== PAUSE TestClientErrorHandling/InvalidAuthToken1206=== RUN TestClientErrorHandling/ServerNotAvailable1207=== PAUSE TestClientErrorHandling/ServerNotAvailable1208=== CONT TestReadProxyNarStreaming12092026/08/27 11:06:29 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12102026/08/27 11:06:29 INFO Signed narinfos id=2 count=112112026/08/27 11:06:29 INFO Uploading 1 narinfos12122026/08/27 11:06:29 WARN Failed to register uploaded object key=52hr0h475nfarx1iyzvjkik462hycji2.narinfo error="server returned 404: 404 page not found\n"12132026/08/27 11:06:29 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1214--- PASS: TestReadRedirectKeepsNarinfoProxied (2.56s)1215=== CONT TestReadProxyConditionalGet12162026/08/27 11:06:29 INFO Completed upload id=212172026/08/27 11:06:29 INFO Upload complete. (120ms)12182026-08-27 11:06:29.621 UTC [806] ERROR: relation "goose_db_version" does not exist at character 3612192026-08-27 11:06:29.621 UTC [806] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1220=== NAME TestNARDeduplicationMetadataUploadBug1221 metadata_upload_test.go:76: Retrieved narinfo from S3:1222 StorePath: /build/TestNARDeduplicationMetadataUploadBug835665952/001/store/52hr0h475nfarx1iyzvjkik462hycji2-file2.txt1223 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1224 Compression: zstd1225 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1226 NarSize: 1601227 References: 1228 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1229 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1230 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1231 {"version":1,"root":{"type":"regular","size":44}}1232--- PASS: TestNARDeduplicationMetadataUploadBug (2.71s)1233=== CONT TestObjectStatsTrigger12342026-08-27 11:06:29.647 UTC [810] ERROR: relation "goose_db_version" does not exist at character 3612352026-08-27 11:06:29.647 UTC [810] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1236--- PASS: TestReadProxyRangeRequest (2.60s)1237=== CONT TestMultipartCleanup12382026/08/27 11:06:29 OK 20241026095416_initial_model.sql (19.64ms)12392026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (7.35ms)12402026/08/27 11:06:29 OK 20251218171726_add_pins.sql (6.98ms)12412026-08-27 11:06:29.671 UTC [815] ERROR: relation "goose_db_version" does not exist at character 3612422026-08-27 11:06:29.671 UTC [815] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12432026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (7.72ms)12442026/08/27 11:06:29 goose: successfully migrated database to version: 202606281200001245--- PASS: TestReadRedirectNar (2.43s)1246=== CONT TestResurrectedObjectNotDeleted12472026/08/27 11:06:29 OK 1_commit_pending_closure.sql (4.39ms)12482026/08/27 11:06:29 OK 20241026095416_initial_model.sql (17.08ms)12492026-08-27 11:06:29.681 UTC [816] ERROR: relation "goose_db_version" does not exist at character 3612502026-08-27 11:06:29.681 UTC [816] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12512026/08/27 11:06:29 OK 2_object_stats_trigger.sql (7.35ms)12522026/08/27 11:06:29 goose: up to current file version: 21253--- PASS: TestService_ReadAuthMiddleware (2.35s)1254=== CONT TestOrphanedObjectsGCStressTest12552026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (21.21ms)12562026/08/27 11:06:29 OK 20241026095416_initial_model.sql (24.05ms)12572026/08/27 11:06:29 OK 20251218171726_add_pins.sql (10.55ms)12582026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (17.03ms)12592026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (11.33ms)12602026/08/27 11:06:29 goose: successfully migrated database to version: 202606281200001261--- PASS: TestReadProxyDisabled (2.35s)1262=== CONT TestReadProxyNarinfoAlreadyDecompressed12632026/08/27 11:06:29 OK 20241026095416_initial_model.sql (22.78ms)12642026-08-27 11:06:29.731 UTC [821] ERROR: relation "goose_db_version" does not exist at character 3612652026-08-27 11:06:29.731 UTC [821] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12662026/08/27 11:06:29 OK 20251218171726_add_pins.sql (8.77ms)12672026/08/27 11:06:29 OK 1_commit_pending_closure.sql (7.05ms)12682026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (4.77ms)12692026/08/27 11:06:29 OK 2_object_stats_trigger.sql (2.58ms)12702026/08/27 11:06:29 goose: up to current file version: 212712026-08-27 11:06:29.736 UTC [823] ERROR: relation "goose_db_version" does not exist at character 3612722026-08-27 11:06:29.736 UTC [823] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12732026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (8.29ms)12742026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000012752026/08/27 11:06:29 OK 20251218171726_add_pins.sql (7.93ms)12762026/08/27 11:06:29 OK 1_commit_pending_closure.sql (5.96ms)12772026/08/27 11:06:29 OK 2_object_stats_trigger.sql (3.16ms)12782026/08/27 11:06:29 goose: up to current file version: 212792026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (7.28ms)12802026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000012812026/08/27 11:06:29 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"12822026/08/27 11:06:29 WARN mTLS auth: bound subjects configured but subject DN unavailable12832026/08/27 11:06:29 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1284--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.37s)1285=== CONT TestOrphanedObjectsGC12862026-08-27 11:06:29.754 UTC [825] ERROR: relation "goose_db_version" does not exist at character 3612872026-08-27 11:06:29.754 UTC [825] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12882026/08/27 11:06:29 OK 20241026095416_initial_model.sql (17.74ms)12892026-08-27 11:06:29.759 UTC [826] ERROR: relation "goose_db_version" does not exist at character 3612902026-08-27 11:06:29.759 UTC [826] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12912026/08/27 11:06:29 OK 1_commit_pending_closure.sql (10.69ms)12922026/08/27 11:06:29 OK 20241026095416_initial_model.sql (16.21ms)12932026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (5.41ms)12942026/08/27 11:06:29 OK 2_object_stats_trigger.sql (4.17ms)12952026/08/27 11:06:29 goose: up to current file version: 212962026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (6.16ms)12972026/08/27 11:06:29 OK 20251218171726_add_pins.sql (6.22ms)12982026/08/27 11:06:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12992026/08/27 11:06:29 OK 20251218171726_add_pins.sql (8.06ms)13002026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (6.93ms)13012026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000013022026/08/27 11:06:29 OK 20241026095416_initial_model.sql (14.57ms)13032026/08/27 11:06:29 OK 20241026095416_initial_model.sql (12.55ms)13042026/08/27 11:06:29 OK 1_commit_pending_closure.sql (4.92ms)13052026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (4.05ms)13062026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (21.55ms)13072026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000013082026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (17.24ms)1309--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.92s)1310=== CONT TestService_NativeMTLS13112026/08/27 11:06:29 OK 2_object_stats_trigger.sql (27.63ms)13122026/08/27 11:06:29 OK 20251218171726_add_pins.sql (27.25ms)13132026/08/27 11:06:29 goose: up to current file version: 213142026/08/27 11:06:29 OK 1_commit_pending_closure.sql (14.32ms)13152026/08/27 11:06:29 OK 20251218171726_add_pins.sql (14.06ms)13162026/08/27 11:06:29 OK 2_object_stats_trigger.sql (3.6ms)13172026/08/27 11:06:29 goose: up to current file version: 213182026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (6.47ms)13192026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000013202026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (6.24ms)13212026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000013222026/08/27 11:06:29 OK 1_commit_pending_closure.sql (4.01ms)13232026/08/27 11:06:29 OK 1_commit_pending_closure.sql (4.21ms)13242026/08/27 11:06:29 OK 2_object_stats_trigger.sql (2.46ms)13252026/08/27 11:06:29 goose: up to current file version: 213262026/08/27 11:06:29 OK 2_object_stats_trigger.sql (2.78ms)13272026/08/27 11:06:29 goose: up to current file version: 213282026-08-27 11:06:29.826 UTC [849] ERROR: relation "goose_db_version" does not exist at character 3613292026-08-27 11:06:29.826 UTC [849] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13302026-08-27 11:06:29.846 UTC [850] ERROR: relation "goose_db_version" does not exist at character 3613312026-08-27 11:06:29.846 UTC [850] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13322026-08-27 11:06:29.849 UTC [851] ERROR: relation "goose_db_version" does not exist at character 3613332026-08-27 11:06:29.849 UTC [851] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13342026/08/27 11:06:29 OK 20241026095416_initial_model.sql (12.22ms)13352026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (2.54ms)13362026/08/27 11:06:29 OK 20251218171726_add_pins.sql (4.23ms)13372026-08-27 11:06:29.861 UTC [852] ERROR: relation "goose_db_version" does not exist at character 3613382026-08-27 11:06:29.861 UTC [852] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13392026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (5.99ms)13402026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000013412026/08/27 11:06:29 OK 20241026095416_initial_model.sql (11.99ms)13422026/08/27 11:06:29 OK 1_commit_pending_closure.sql (3.68ms)13432026/08/27 11:06:29 OK 20241026095416_initial_model.sql (12.05ms)13442026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (3.21ms)13452026/08/27 11:06:29 OK 2_object_stats_trigger.sql (2.66ms)13462026/08/27 11:06:29 goose: up to current file version: 213472026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (3.16ms)13482026/08/27 11:06:29 OK 20251218171726_add_pins.sql (3.74ms)13492026/08/27 11:06:29 OK 20251218171726_add_pins.sql (3.95ms)13502026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (3.25ms)13512026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000013522026/08/27 11:06:29 OK 1_commit_pending_closure.sql (2.83ms)13532026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (3.22ms)13542026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000013552026/08/27 11:06:29 OK 2_object_stats_trigger.sql (986.95µs)13562026/08/27 11:06:29 goose: up to current file version: 213572026/08/27 11:06:29 OK 1_commit_pending_closure.sql (2.13ms)13582026/08/27 11:06:29 OK 20241026095416_initial_model.sql (11.86ms)13592026/08/27 11:06:29 OK 2_object_stats_trigger.sql (1.05ms)13602026/08/27 11:06:29 goose: up to current file version: 213612026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (1.5ms)13622026-08-27 11:06:29.886 UTC [853] ERROR: relation "goose_db_version" does not exist at character 3613632026-08-27 11:06:29.886 UTC [853] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13642026/08/27 11:06:29 OK 20251218171726_add_pins.sql (4.69ms)13652026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (4.95ms)13662026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000013672026/08/27 11:06:29 OK 1_commit_pending_closure.sql (3.33ms)13682026/08/27 11:06:29 OK 2_object_stats_trigger.sql (2.07ms)13692026/08/27 11:06:29 goose: up to current file version: 213702026/08/27 11:06:29 OK 20241026095416_initial_model.sql (8.92ms)13712026/08/27 11:06:29 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)13722026/08/27 11:06:29 OK 20251218171726_add_pins.sql (3.18ms)13732026/08/27 11:06:29 OK 20260628120000_add_object_size_and_stats.sql (2.77ms)13742026/08/27 11:06:29 goose: successfully migrated database to version: 2026062812000013752026/08/27 11:06:29 OK 1_commit_pending_closure.sql (2.02ms)13762026/08/27 11:06:29 OK 2_object_stats_trigger.sql (6.02ms)13772026/08/27 11:06:29 goose: up to current file version: 21378--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.02s)1379=== CONT TestReadProxyNarinfo13802026/08/27 11:06:29 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZTY0YzJlZjctZGU4OS00YmM4LWJlZjUtNzE4YjUxMGM4YzI1LjQwOGFiNjdiLTY1NGItNDI4My05Y2E3LTlkZTA4NmNkMDg0MngxNzg3ODI4Nzg3MzA2NTg5ODAw parts=1013812026/08/27 11:06:29 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13822026/08/27 11:06:29 INFO Completed upload id=113832026/08/27 11:06:29 INFO Received uploads request method=POST path=/api/pending_closures13842026/08/27 11:06:29 INFO Received uploads request method=POST path=/api/pending_closures13852026/08/27 11:06:29 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13862026/08/27 11:06:29 WARN Found objects in DB but missing from S3, will re-upload count=11387--- PASS: TestService_verifyS3Integrity (3.06s)1388=== CONT TestIsValidCachePath1389=== RUN TestIsValidCachePath/narinfo1390=== PAUSE TestIsValidCachePath/narinfo1391=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1392=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1393=== RUN TestIsValidCachePath/nar_zst1394=== PAUSE TestIsValidCachePath/nar_zst1395=== RUN TestIsValidCachePath/nar_xz1396=== PAUSE TestIsValidCachePath/nar_xz1397=== RUN TestIsValidCachePath/nar_bz21398=== PAUSE TestIsValidCachePath/nar_bz21399=== RUN TestIsValidCachePath/nar_uncompressed1400=== PAUSE TestIsValidCachePath/nar_uncompressed1401=== RUN TestIsValidCachePath/ls1402=== PAUSE TestIsValidCachePath/ls1403=== RUN TestIsValidCachePath/log1404=== PAUSE TestIsValidCachePath/log1405=== RUN TestIsValidCachePath/realisation1406=== PAUSE TestIsValidCachePath/realisation1407=== RUN TestIsValidCachePath/nix-cache-info1408=== PAUSE TestIsValidCachePath/nix-cache-info1409=== RUN TestIsValidCachePath/index.html1410=== PAUSE TestIsValidCachePath/index.html1411=== RUN TestIsValidCachePath/traversal_parent1412=== PAUSE TestIsValidCachePath/traversal_parent1413=== RUN TestIsValidCachePath/traversal_in_middle1414=== PAUSE TestIsValidCachePath/traversal_in_middle1415=== RUN TestIsValidCachePath/invalid_char_e1416=== PAUSE TestIsValidCachePath/invalid_char_e1417=== RUN TestIsValidCachePath/invalid_char_u1418=== PAUSE TestIsValidCachePath/invalid_char_u1419=== RUN TestIsValidCachePath/random_path1420=== PAUSE TestIsValidCachePath/random_path1421=== RUN TestIsValidCachePath/empty1422=== PAUSE TestIsValidCachePath/empty1423=== RUN TestIsValidCachePath/leading_slash1424=== PAUSE TestIsValidCachePath/leading_slash1425=== RUN TestIsValidCachePath/wrong_extension1426=== PAUSE TestIsValidCachePath/wrong_extension1427=== RUN TestIsValidCachePath/short_hash1428=== PAUSE TestIsValidCachePath/short_hash1429=== CONT TestServerTLSConfig1430=== RUN TestServerTLSConfig/no_client_CA1431=== PAUSE TestServerTLSConfig/no_client_CA1432=== RUN TestServerTLSConfig/missing_CA_file1433=== PAUSE TestServerTLSConfig/missing_CA_file1434=== RUN TestServerTLSConfig/not_a_PEM_file1435=== PAUSE TestServerTLSConfig/not_a_PEM_file1436=== CONT TestProxyWriteTimeout/narinfo1437=== CONT TestProxyWriteTimeout/1_GiB_nar1438=== CONT TestProxyWriteTimeout/unknown_size1439=== CONT TestProxyWriteTimeout/10_GiB_nar1440--- PASS: TestProxyWriteTimeout (0.00s)1441 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1442 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1443 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1444 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1445=== CONT TestCacheConfigHandler/full_config,_no_issuer1446=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1447=== CONT TestCacheConfigHandler/no_signing_keys1448=== CONT TestCacheConfigHandler/no_cache_url_configured1449--- PASS: TestCacheConfigHandler (0.00s)1450 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1451 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1452 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1453 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1454=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info14552026/08/27 11:06:29 INFO Received uploads request method=POST path=/1456=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key14572026/08/27 11:06:29 INFO Received request for more parts method=POST path=/1458=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key14592026/08/27 11:06:29 INFO Received complete multipart upload request method=POST path=/1460=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal14612026/08/27 11:06:29 INFO Received uploads request method=POST path=/1462=== CONT TestIsValidUploadKey/narinfo1463=== CONT TestIsValidUploadKey/unknown_type1464=== CONT TestIsValidUploadKey/empty_key1465=== CONT TestIsValidUploadKey/absolute1466=== CONT TestIsValidUploadKey/traversal_nar1467=== CONT TestIsValidUploadKey/traversal1468=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1469=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1470=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1471--- PASS: TestUploadHandlersRejectInvalidKeys (0.11s)1472 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1473 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1474 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1475 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1476=== CONT TestIsValidUploadKey/index.html1477=== CONT TestIsValidUploadKey/build_log_home-manager_file1478=== CONT TestIsValidUploadKey/build_log1479=== CONT TestIsValidUploadKey/listing1480=== CONT TestIsValidUploadKey/nar_plain1481=== CONT TestIsValidUploadKey/build_log_plus_in_name1482=== CONT TestIsValidUploadKey/nar_xz1483=== CONT TestIsValidUploadKey/nix-cache-info1484=== CONT TestIsValidUploadKey/nar_zst1485=== CONT TestIsValidUploadKey/realisation_plus_in_output1486=== CONT TestIsValidUploadKey/realisation1487=== CONT TestIsValidUploadKey/build_log_equals1488=== CONT TestIsValidUploadKey/build_log_question_mark1489=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts14902026/08/27 11:06:29 INFO Received request for more parts method=POST path=/1491--- PASS: TestIsValidUploadKey (0.00s)1492 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1493 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1494 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1495 --- PASS: TestIsValidUploadKey/absolute (0.00s)1496 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1497 --- PASS: TestIsValidUploadKey/traversal (0.00s)1498 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1499 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1500 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1501 --- PASS: TestIsValidUploadKey/index.html (0.00s)1502 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1503 --- PASS: TestIsValidUploadKey/build_log (0.00s)1504 --- PASS: TestIsValidUploadKey/listing (0.00s)1505 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1506 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1507 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1508 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1509 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1510 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1511 --- PASS: TestIsValidUploadKey/realisation (0.00s)1512 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1513 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)15142026/08/27 11:06:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15152026/08/27 11:06:30 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZTY0YzJlZjctZGU4OS00YmM4LWJlZjUtNzE4YjUxMGM4YzI1LjA5YWQ2MTk4LTg5ZWUtNDEzZS1iMzk2LTkwNDJlMzhmODRlN3gxNzg3ODI4Nzg4OTI2MDkxODMw parts=1215162026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures15172026-08-27 11:06:30.020 UTC [892] ERROR: relation "goose_db_version" does not exist at character 3615182026-08-27 11:06:30.020 UTC [892] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1519--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.10s)1520=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15212026/08/27 11:06:30 INFO Received complete multipart upload request method=POST path=/15222026/08/27 11:06:30 OK 20241026095416_initial_model.sql (8.53ms)15232026/08/27 11:06:30 OK 20251210153512_drop_unused_gin_index.sql (2.41ms)1524=== NAME TestClientMultipleUploads1525 client_integration_test.go:339: Created store path 0: /build/TestClientMultipleUploads2975107634/001/store/2rls64wiv24ca5nkvq52xm61ncfrs55w-test-file-0.txt15262026/08/27 11:06:30 OK 20251218171726_add_pins.sql (3.96ms)1527--- PASS: TestReadProxyHead (0.53s)1528=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15292026/08/27 11:06:30 INFO Received uploads request method=POST path=/15302026/08/27 11:06:30 OK 20260628120000_add_object_size_and_stats.sql (5.42ms)15312026/08/27 11:06:30 goose: successfully migrated database to version: 2026062812000015322026/08/27 11:06:30 OK 1_commit_pending_closure.sql (2.22ms)15332026/08/27 11:06:30 OK 2_object_stats_trigger.sql (1.02ms)15342026/08/27 11:06:30 goose: up to current file version: 21535=== CONT TestResolveDBConnectionString/flag_wins1536=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1537=== CONT TestResolveDBConnectionString/nothing_configured1538=== CONT TestResolveDBConnectionString/missing_file_is_an_error1539=== CONT TestResolveDBConnectionString/file_when_flag_empty1540=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1541--- PASS: TestResolveDBConnectionString (0.00s)1542 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1543 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1544 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1545 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1546 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)15472026/08/27 11:06:30 INFO OIDC auth successful provider=test scopes=[write]1548=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected15492026/08/27 11:06:30 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]1550=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1551=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1552=== NAME TestClientWithDependencies1553 client_integration_test.go:594: Built derivation: /build/TestClientWithDependencies4080717081/001/store/3h867rqch6k48hr1hdifpnr15d49azh5-test-script15542026/08/27 11:06:30 WARN Authentication failed token_preview=eyJhbGciOi...oOFB9tEmlA token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1555=== CONT TestParseSingleRange/none1556=== CONT TestParseSingleRange/open-ended1557=== CONT TestParseSingleRange/closed1558=== CONT TestParseSingleRange/malformed_end_before_start1559=== CONT TestParseSingleRange/malformed_both_empty1560=== CONT TestParseSingleRange/malformed_no_dash1561=== CONT TestParseSingleRange/multi-range_ignored1562=== CONT TestParseSingleRange/unknown_unit1563=== CONT TestParseSingleRange/start_past_EOF1564=== CONT TestParseSingleRange/end_clamped_to_size1565=== CONT TestParseSingleRange/single_byte1566=== CONT TestParseSingleRange/suffix_exceeds_size1567=== CONT TestParseSingleRange/suffix1568=== CONT TestParseSingleRange/start_far_past_EOF1569--- PASS: TestParseSingleRange (0.00s)1570 --- PASS: TestParseSingleRange/none (0.00s)1571 --- PASS: TestParseSingleRange/open-ended (0.00s)1572 --- PASS: TestParseSingleRange/closed (0.00s)1573 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1574 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1575 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1576 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1577 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1578 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1579 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1580 --- PASS: TestParseSingleRange/single_byte (0.00s)1581 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1582 --- PASS: TestParseSingleRange/suffix (0.00s)1583 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1584=== CONT TestService_RequireScope_OIDC/builder_may_write1585--- PASS: TestService_AuthMiddleware_OIDC (2.34s)1586 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)1587 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1588 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1589 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)1590=== NAME TestClientMultipleUploads1591 client_integration_test.go:339: Created store path 1: /build/TestClientMultipleUploads2975107634/001/store/v2vxx8n52wxkc7g8rs7h72x56p4cq1d0-test-file-1.txt15922026/08/27 11:06:30 INFO OIDC auth successful provider=test scopes=[write]1593=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1594=== CONT TestService_RequireScope_OIDC/writer_implies_read15952026/08/27 11:06:30 INFO OIDC auth successful provider=test scopes=[write]1596=== CONT TestService_RequireScope_OIDC/reader_may_read1597=== NAME TestClientCADerivations1598 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3924477150/001/store/5n228d4d2r9lwc6vzs2vi0j3qhxwwjb4-ca-test15992026/08/27 11:06:30 INFO OIDC auth successful provider=test scopes=[read]1600=== CONT TestService_RequireScope_OIDC/static_token_may_write1601=== CONT TestService_RequireScope_OIDC/static_token_may_admin1602=== CONT TestService_RequireScope_OIDC/reader_may_not_write16032026/08/27 11:06:30 INFO OIDC auth successful provider=test scopes=[read]1604=== CONT TestService_RequireScope_OIDC/ops_may_not_write16052026/08/27 11:06:30 INFO OIDC auth successful provider=test scopes=[admin]1606=== CONT TestService_RequireScope_OIDC/ops_may_admin16072026/08/27 11:06:30 INFO OIDC auth successful provider=test scopes=[admin]1608=== CONT TestService_RequireScope_OIDC/builder_may_not_admin16092026/08/27 11:06:30 INFO OIDC auth successful provider=test scopes=[write]1610=== CONT TestClientErrorHandling/InvalidStorePath1611--- PASS: TestReadProxyInvalidPath (0.55s)1612=== CONT TestClientErrorHandling/InvalidAuthToken1613--- PASS: TestService_RequireScope_OIDC (2.56s)1614 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1615 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1616 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1617 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1618 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1619 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1620 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1621 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1622 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1623 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1624=== NAME TestPinProtectsFromGC1625 client_integration_test.go:647: Pinned store path: /build/TestPinProtectsFromGC2027239026/001/store/lrrw90gfwrlk9yp3iygcjkb789nf1yb9-pinned-file.txt1626 client_integration_test.go:648: Unpinned store path: /build/TestPinProtectsFromGC2027239026/001/store/hcz392kkq20acp6cirb18m860xl426j8-unpinned-file.txt1627--- PASS: TestReadProxy404 (0.56s)1628=== CONT TestClientErrorHandling/ServerNotAvailable1629=== NAME TestClientIntegration1630 client_integration_test.go:277: Created store path: /build/TestClientIntegration3384705406/002/store/rfwxch4809l276m1iv6rqvr3fmsfsr0w-test-file.txt1631=== NAME TestClientWithDependencies1632 client_integration_test.go:596: Found 1 dependencies (including self)1633=== NAME TestClientCADerivations1634 client_ca_test.go:139: Found 1 dependencies (including self)1635=== NAME TestClientMultipleUploads1636 client_integration_test.go:339: Created store path 2: /build/TestClientMultipleUploads2975107634/001/store/9n7479pa45gmmfc37jqqbycbc1yrcnqz-test-file-2.txt1637=== CONT TestIsValidCachePath/narinfo1638=== CONT TestIsValidCachePath/index.html1639=== CONT TestIsValidCachePath/short_hash1640=== CONT TestIsValidCachePath/wrong_extension1641=== CONT TestIsValidCachePath/leading_slash1642=== CONT TestIsValidCachePath/empty1643=== CONT TestIsValidCachePath/random_path1644=== CONT TestIsValidCachePath/invalid_char_u1645=== CONT TestIsValidCachePath/invalid_char_e1646--- PASS: TestReadProxyNarStreaming (0.52s)1647=== CONT TestIsValidCachePath/traversal_parent1648=== CONT TestIsValidCachePath/traversal_in_middle1649=== CONT TestIsValidCachePath/nar_uncompressed1650=== CONT TestIsValidCachePath/realisation1651=== CONT TestIsValidCachePath/nix-cache-info1652=== CONT TestIsValidCachePath/log1653=== CONT TestIsValidCachePath/ls1654=== CONT TestIsValidCachePath/nar_bz21655=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1656=== CONT TestIsValidCachePath/nar_zst1657=== CONT TestIsValidCachePath/nar_xz1658--- PASS: TestIsValidCachePath (0.01s)1659 --- PASS: TestIsValidCachePath/narinfo (0.00s)1660 --- PASS: TestIsValidCachePath/index.html (0.00s)1661 --- PASS: TestIsValidCachePath/short_hash (0.00s)1662 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1663 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1664 --- PASS: TestIsValidCachePath/empty (0.00s)1665 --- PASS: TestIsValidCachePath/random_path (0.00s)1666 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1667 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1668 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1669 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1670 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1671 --- PASS: TestIsValidCachePath/realisation (0.00s)1672 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1673 --- PASS: TestIsValidCachePath/log (0.00s)1674 --- PASS: TestIsValidCachePath/ls (0.00s)1675 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1676 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1677 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1678 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1679=== CONT TestServerTLSConfig/no_client_CA1680=== CONT TestServerTLSConfig/missing_CA_file1681=== CONT TestServerTLSConfig/not_a_PEM_file1682--- PASS: TestServerTLSConfig (0.00s)1683 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1684 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1685 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1686--- PASS: TestReadProxyConditionalGet (0.52s)16872026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures16882026-08-27 11:06:30.166 UTC [1178] ERROR: relation "goose_db_version" does not exist at character 3616892026-08-27 11:06:30.166 UTC [1178] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1690--- PASS: TestObjectStatsTrigger (0.54s)16912026/08/27 11:06:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16922026/08/27 11:06:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16932026/08/27 11:06:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16942026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures16952026-08-27 11:06:30.178 UTC [1219] ERROR: relation "goose_db_version" does not exist at character 3616962026-08-27 11:06:30.178 UTC [1219] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16972026/08/27 11:06:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"16982026/08/27 11:06:30 OK 20241026095416_initial_model.sql (10.7ms)16992026/08/27 11:06:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17002026/08/27 11:06:30 INFO Uploading 3h867rqch6k48hr1hdifpnr15d49azh5-test-script (136B)17012026/08/27 11:06:30 OK 20251210153512_drop_unused_gin_index.sql (5.62ms)17022026/08/27 11:06:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17032026/08/27 11:06:30 OK 20251218171726_add_pins.sql (3.74ms)17042026/08/27 11:06:30 WARN Failed to register uploaded object key=log/z4p0f08vxkyny9gxxg3yp736ilza23p9-test-script.drv error="server returned 404: 404 page not found\n"17052026/08/27 11:06:30 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17062026/08/27 11:06:30 WARN Failed to register uploaded object key=3h867rqch6k48hr1hdifpnr15d49azh5.ls error="server returned 404: 404 page not found\n"17072026/08/27 11:06:30 OK 20260628120000_add_object_size_and_stats.sql (5.17ms)17082026/08/27 11:06:30 goose: successfully migrated database to version: 2026062812000017092026/08/27 11:06:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17102026/08/27 11:06:30 INFO Signed narinfos id=1 count=117112026/08/27 11:06:30 INFO Uploading 1 narinfos17122026/08/27 11:06:30 OK 20241026095416_initial_model.sql (11.26ms)17132026/08/27 11:06:30 OK 1_commit_pending_closure.sql (2.27ms)17142026/08/27 11:06:30 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)17152026/08/27 11:06:30 OK 2_object_stats_trigger.sql (1.06ms)17162026/08/27 11:06:30 goose: up to current file version: 217172026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures17182026/08/27 11:06:30 WARN Failed to register uploaded object key=3h867rqch6k48hr1hdifpnr15d49azh5.narinfo error="server returned 404: 404 page not found\n"17192026/08/27 11:06:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17202026/08/27 11:06:30 OK 20251218171726_add_pins.sql (6.24ms)17212026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures17222026/08/27 11:06:30 OK 20260628120000_add_object_size_and_stats.sql (5.33ms)17232026/08/27 11:06:30 goose: successfully migrated database to version: 2026062812000017242026/08/27 11:06:30 INFO Completed upload id=117252026/08/27 11:06:30 INFO Upload complete. (75ms)17262026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures17272026/08/27 11:06:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17282026/08/27 11:06:30 INFO Uploading lrrw90gfwrlk9yp3iygcjkb789nf1yb9-pinned-file.txt (128B)17292026/08/27 11:06:30 OK 1_commit_pending_closure.sql (2.28ms)1730--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.49s)17312026/08/27 11:06:30 OK 2_object_stats_trigger.sql (1.02ms)17322026/08/27 11:06:30 goose: up to current file version: 21733=== NAME TestClientWithDependencies1734 client_integration_test.go:598: Skipping nix copy test - isolated store (/build/TestClientWithDependencies4080717081/001/store) requires matching store prefix17352026/08/27 11:06:30 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-config17362026/08/27 11:06:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17372026/08/27 11:06:30 INFO Uploading 5n228d4d2r9lwc6vzs2vi0j3qhxwwjb4-ca-test (144B)1738--- PASS: TestClientWithDependencies (1.20s)17392026/08/27 11:06:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17402026/08/27 11:06:30 INFO Uploading rfwxch4809l276m1iv6rqvr3fmsfsr0w-test-file.txt (152B)17412026/08/27 11:06:30 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"17422026/08/27 11:06:30 WARN Failed to register uploaded object key=log/yma3vqaiywmbdbkckm24ybw50gylb85b-ca-test.drv error="server returned 404: 404 page not found\n"17432026/08/27 11:06:30 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"17442026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures17452026/08/27 11:06:30 WARN Failed to register uploaded object key=5n228d4d2r9lwc6vzs2vi0j3qhxwwjb4.ls error="server returned 404: 404 page not found\n"17462026/08/27 11:06:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17472026/08/27 11:06:30 INFO Signed narinfos id=1 count=117482026/08/27 11:06:30 INFO Uploading 1 narinfos17492026/08/27 11:06:30 WARN Failed to register uploaded object key=rfwxch4809l276m1iv6rqvr3fmsfsr0w.ls error="server returned 404: 404 page not found\n"17502026/08/27 11:06:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17512026/08/27 11:06:30 INFO Signed narinfos id=1 count=117522026/08/27 11:06:30 INFO Uploading 1 narinfos17532026/08/27 11:06:30 WARN Failed to register uploaded object key=5n228d4d2r9lwc6vzs2vi0j3qhxwwjb4.narinfo error="server returned 404: 404 page not found\n"1754--- PASS: TestResurrectedObjectNotDeleted (0.56s)17552026/08/27 11:06:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17562026/08/27 11:06:30 WARN Failed to register uploaded object key=rfwxch4809l276m1iv6rqvr3fmsfsr0w.narinfo error="server returned 404: 404 page not found\n"17572026/08/27 11:06:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17582026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures1759--- PASS: TestGCBugBareHashReferences (0.82s)17602026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures17612026/08/27 11:06:30 INFO Completed upload id=117622026/08/27 11:06:30 INFO Upload complete. (105ms)17632026/08/27 11:06:30 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17642026/08/27 11:06:30 INFO Uploading 2rls64wiv24ca5nkvq52xm61ncfrs55w-test-file-0.txt (160B)17652026/08/27 11:06:30 INFO Uploading v2vxx8n52wxkc7g8rs7h72x56p4cq1d0-test-file-1.txt (160B)17662026/08/27 11:06:30 INFO Uploading 9n7479pa45gmmfc37jqqbycbc1yrcnqz-test-file-2.txt (160B)17672026/08/27 11:06:30 INFO Completed upload id=117682026/08/27 11:06:30 INFO Upload complete. (112ms)17692026/08/27 11:06:30 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"1770=== NAME TestClientCADerivations1771 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3924477150/001/store/5n228d4d2r9lwc6vzs2vi0j3qhxwwjb4-ca-test1772 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1773 Compression: zstd1774 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1775 NarSize: 1441776 References: 1777 Deriver: /build/TestClientCADerivations3924477150/001/store/yma3vqaiywmbdbkckm24ybw50gylb85b-ca-test.drv17782026/08/27 11:06:30 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"1779 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1780 client_ca_test.go:185: Checking for realisation files in S3...17812026/08/27 11:06:30 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"1782=== NAME TestClientIntegration1783 client_integration_test.go:293: Retrieved narinfo from S3:1784 StorePath: /build/TestClientIntegration3384705406/002/store/rfwxch4809l276m1iv6rqvr3fmsfsr0w-test-file.txt1785 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1786 Compression: zstd1787 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11788 NarSize: 1521789 References: 1790 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11791=== NAME TestClientCADerivations1792 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations17932026/08/27 11:06:30 WARN Failed to register uploaded object key=v2vxx8n52wxkc7g8rs7h72x56p4cq1d0.ls error="server returned 404: 404 page not found\n"1794 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache17952026/08/27 11:06:30 WARN Failed to register uploaded object key=9n7479pa45gmmfc37jqqbycbc1yrcnqz.ls error="server returned 404: 404 page not found\n"17962026/08/27 11:06:30 WARN Failed to register uploaded object key=2rls64wiv24ca5nkvq52xm61ncfrs55w.ls error="server returned 404: 404 page not found\n"17972026/08/27 11:06:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign1798=== NAME TestClientIntegration1799 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1800 client_integration_test.go:294: Decompressed .ls content (64 bytes):1801 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1802 client_integration_test.go:297: Testing garbage collection...18032026/08/27 11:06:30 INFO Signed narinfos id=1 count=118042026/08/27 11:06:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18052026/08/27 11:06:30 INFO Signed narinfos id=2 count=118062026/08/27 11:06:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign18072026/08/27 11:06:30 INFO Signed narinfos id=3 count=118082026/08/27 11:06:30 INFO Uploading 3 narinfos18092026/08/27 11:06:30 WARN Failed to register uploaded object key=9n7479pa45gmmfc37jqqbycbc1yrcnqz.narinfo error="server returned 404: 404 page not found\n"18102026/08/27 11:06:30 INFO Received cleanup request method=DELETE path=/api/pending_closures18112026/08/27 11:06:30 INFO Aborted multipart uploads count=11812--- PASS: TestMultipartCleanup (0.64s)18132026/08/27 11:06:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures18142026/08/27 11:06:30 INFO Garbage collection started18152026/08/27 11:06:30 INFO Aborted multipart uploads count=018162026/08/27 11:06:30 WARN Force mode enabled - objects will be deleted immediately without grace period18172026/08/27 11:06:30 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=204.956511ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1818=== NAME TestClientCADerivations1819 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1820 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1821 error: binary cache 's3://bucket32?endpoint=http://localhost:35227®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3924477150/001/store'1822 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11823--- PASS: TestClientCADerivations (1.38s)18242026/08/27 11:06:30 WARN Failed to register uploaded object key=2rls64wiv24ca5nkvq52xm61ncfrs55w.narinfo error="server returned 404: 404 page not found\n"18252026/08/27 11:06:30 WARN Failed to register uploaded object key=v2vxx8n52wxkc7g8rs7h72x56p4cq1d0.narinfo error="server returned 404: 404 page not found\n"18262026/08/27 11:06:30 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete18272026/08/27 11:06:30 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"18282026/08/27 11:06:30 WARN Failed to register uploaded object key=lrrw90gfwrlk9yp3iygcjkb789nf1yb9.ls error="server returned 404: 404 page not found\n"18292026/08/27 11:06:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18302026/08/27 11:06:30 INFO Signed narinfos id=1 count=118312026/08/27 11:06:30 INFO Uploading 1 narinfos18322026/08/27 11:06:30 INFO Completed upload id=318332026/08/27 11:06:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18342026/08/27 11:06:30 WARN Failed to register uploaded object key=lrrw90gfwrlk9yp3iygcjkb789nf1yb9.narinfo error="server returned 404: 404 page not found\n"18352026/08/27 11:06:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18362026/08/27 11:06:30 INFO Completed upload id=118372026/08/27 11:06:30 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18382026/08/27 11:06:30 INFO Completed upload id=218392026/08/27 11:06:30 INFO Upload complete. (281ms)1840=== NAME TestClientMultipleUploads1841 client_integration_test.go:350: Uploaded 3 paths in 323.719253ms18422026/08/27 11:06:30 INFO Completed upload id=118432026/08/27 11:06:30 INFO Upload complete. (318ms)1844--- PASS: TestClientMultipleUploads (1.05s)18452026/08/27 11:06:30 WARN mTLS auth: subject not in bound subjects subject="CN=reader"18462026/08/27 11:06:30 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1847--- PASS: TestService_NativeMTLS (0.71s)18482026/08/27 11:06:30 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=409.203437ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1849--- PASS: TestReadProxyNarinfo (0.59s)18502026/08/27 11:06:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18512026/08/27 11:06:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18522026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures18532026/08/27 11:06:30 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZTY0YzJlZjctZGU4OS00YmM4LWJlZjUtNzE4YjUxMGM4YzI1LjYxYjg2OGM1LWYxYzktNGE4ZS1iMTRkLWZjN2Q0MTA2MTFmZngxNzg3ODI4Nzg3MzQxOTU1ODcw parts=1018542026/08/27 11:06:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18552026/08/27 11:06:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18562026/08/27 11:06:30 INFO Uploading hcz392kkq20acp6cirb18m860xl426j8-unpinned-file.txt (128B)18572026/08/27 11:06:30 INFO Completed upload id=118582026/08/27 11:06:30 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000018592026/08/27 11:06:30 INFO Received uploads request method=POST path=/api/pending_closures18602026/08/27 11:06:30 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18612026/08/27 11:06:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures18622026/08/27 11:06:30 WARN Failed to register uploaded object key=hcz392kkq20acp6cirb18m860xl426j8.ls error="server returned 404: 404 page not found\n"18632026/08/27 11:06:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18642026/08/27 11:06:30 INFO Signed narinfos id=2 count=118652026/08/27 11:06:30 INFO Uploading 1 narinfos18662026/08/27 11:06:30 WARN Failed to register uploaded object key=hcz392kkq20acp6cirb18m860xl426j8.narinfo error="server returned 404: 404 page not found\n"18672026/08/27 11:06:30 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18682026/08/27 11:06:30 INFO Completed upload id=218692026/08/27 11:06:30 INFO Upload complete. (109ms)18702026/08/27 11:06:30 INFO Aborted multipart uploads count=018712026/08/27 11:06:30 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=018722026/08/27 11:06:30 INFO Vacuumed table table=pending_closures18732026/08/27 11:06:30 INFO Vacuumed table table=pending_objects18742026/08/27 11:06:30 INFO Vacuumed table table=multipart_uploads18752026/08/27 11:06:30 INFO Vacuumed table table=closures18762026/08/27 11:06:30 INFO Vacuumed table table=objects18772026/08/27 11:06:30 INFO Received create pin request method=POST path=/api/pins/myapp18782026/08/27 11:06:30 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2027239026/001/store/lrrw90gfwrlk9yp3iygcjkb789nf1yb9-pinned-file.txt narinfo_key=lrrw90gfwrlk9yp3iygcjkb789nf1yb9.narinfo18792026/08/27 11:06:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures18802026/08/27 11:06:30 INFO Garbage collection started18812026/08/27 11:06:30 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001882--- PASS: TestService_createPendingClosureHandler (3.72s)18832026/08/27 11:06:30 INFO Aborted multipart uploads count=018842026/08/27 11:06:30 WARN Force mode enabled - objects will be deleted immediately without grace period18852026/08/27 11:06:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18862026/08/27 11:06:30 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"1887=== NAME TestOrphanedObjectsGC1888 orphaned_objects_gc_test.go:290: GC Test Summary:1889 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1890 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1891 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1892 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1893 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1894--- PASS: TestOrphanedObjectsGC (1.04s)18952026/08/27 11:06:30 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=018962026/08/27 11:06:30 INFO Vacuumed table table=pending_closures18972026/08/27 11:06:30 INFO Vacuumed table table=pending_objects18982026/08/27 11:06:30 INFO Vacuumed table table=multipart_uploads18992026/08/27 11:06:30 INFO Vacuumed table table=closures19002026/08/27 11:06:30 INFO Vacuumed table table=objects19012026/08/27 11:06:30 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=877.170661ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19022026/08/27 11:06:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19032026/08/27 11:06:31 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZTY0YzJlZjctZGU4OS00YmM4LWJlZjUtNzE4YjUxMGM4YzI1Ljg0NzAxNWRlLWVhMDAtNDMyYy05YzIwLTQ1YTUwYjA0ZTIyN3gxNzg3ODI4Nzg5NDk5NjU4NjA3 parts=121904--- PASS: TestRedundantMultipartUpload (4.29s)1905=== NAME TestOrphanedObjectsGCStressTest1906 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1907 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion1908--- PASS: TestUploadHandlersRejectOversizedBody (0.26s)1909 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.08s)1910 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.11s)1911 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.61s)1912=== NAME TestOrphanedObjectsGCStressTest1913 orphaned_objects_gc_test.go:509: Stress test completed successfully:1914 orphaned_objects_gc_test.go:510: - Active objects preserved: 201915 orphaned_objects_gc_test.go:511: - Objects deleted: 2101916 orphaned_objects_gc_test.go:512: - Total GC'd: 2101917--- PASS: TestOrphanedObjectsGCStressTest (2.03s)19182026/08/27 11:06:31 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.593077626s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19192026/08/27 11:06:31 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=019202026/08/27 11:06:31 INFO Vacuumed table table=pending_closures19212026/08/27 11:06:31 INFO Vacuumed table table=pending_objects19222026/08/27 11:06:31 INFO Vacuumed table table=multipart_uploads19232026/08/27 11:06:31 INFO Vacuumed table table=closures19242026/08/27 11:06:31 INFO Vacuumed table table=objects19252026/08/27 11:06:32 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01926=== NAME TestClientIntegration1927 client_integration_test.go:304: Objects in database after GC:1928 client_integration_test.go:304: Successfully deleted all objects with GC --force1929--- PASS: TestClientIntegration (2.78s)19302026/08/27 11:06:32 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01931=== NAME TestPinProtectsFromGC1932 client_integration_test.go:710: Pin successfully protected closure from garbage collection1933--- PASS: TestPinProtectsFromGC (3.19s)19342026/08/27 11:06:33 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"19352026/08/27 11:06:33 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_closures19362026/08/27 11:06:33 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=211.764888ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19372026/08/27 11:06:33 WARN Rate limiter enabled after throttle name=s3-test rate=519382026/08/27 11:06:33 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1939=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1940 throttle_test.go:213: Proxy stats: total=15, throttled=10, completeMultipart=101941 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001942--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.83s)19432026/08/27 11:06:33 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=400.679477ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19442026/08/27 11:06:34 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=850.963328ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19452026/08/27 11:06:35 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.509517131s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1946--- PASS: TestClientErrorHandling (0.00s)1947 --- PASS: TestClientErrorHandling/InvalidStorePath (0.52s)1948 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.62s)1949 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.45s)1950PASS19512026-08-27 11:06:36.886 UTC [112] LOG: received smart shutdown request19522026-08-27 11:06:36.891 UTC [112] LOG: background worker "logical replication launcher" (PID 122) exited with exit code 119532026-08-27 11:06:36.903 UTC [117] LOG: shutting down19542026-08-27 11:06:36.903 UTC [117] LOG: checkpoint starting: shutdown immediate19552026-08-27 11:06:38.112 UTC [117] LOG: checkpoint complete: wrote 11750 buffers (71.7%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 14 recycled; write=0.228 s, sync=0.972 s, total=1.210 s; sync files=16812, longest=0.002 s, average=0.001 s; distance=231553 kB, estimate=231553 kB; lsn=0/F9843B0, redo lsn=0/F9843B019562026-08-27 11:06:38.212 UTC [112] LOG: database system is shut down1957Running OIDC tests...1958=== RUN TestGlobMatch1959=== PAUSE TestGlobMatch1960=== RUN TestAudienceForIssuer1961=== PAUSE TestAudienceForIssuer1962=== RUN TestValidateToken_ValidToken1963=== PAUSE TestValidateToken_ValidToken1964=== RUN TestValidateToken_WrongAudience1965=== PAUSE TestValidateToken_WrongAudience1966=== RUN TestValidateToken_Expired1967=== PAUSE TestValidateToken_Expired1968=== RUN TestValidateToken_BoundClaimsMismatch1969=== PAUSE TestValidateToken_BoundClaimsMismatch1970=== RUN TestValidateToken_BoundSubjectMismatch1971=== PAUSE TestValidateToken_BoundSubjectMismatch1972=== RUN TestValidateToken_MultipleProviders1973=== PAUSE TestValidateToken_MultipleProviders1974=== RUN TestValidateToken_NoMatchingProvider1975=== PAUSE TestValidateToken_NoMatchingProvider1976=== RUN TestValidateToken_KubernetesServiceAccount1977=== PAUSE TestValidateToken_KubernetesServiceAccount1978=== RUN TestNewValidator_KubernetesRequiresCA1979=== PAUSE TestNewValidator_KubernetesRequiresCA1980=== RUN TestScopes_LegacyProviderDefaultsToWrite1981=== PAUSE TestScopes_LegacyProviderDefaultsToWrite1982=== RUN TestScopes_Rules1983=== PAUSE TestScopes_Rules1984=== RUN TestScopes_ConfigValidation1985=== PAUSE TestScopes_ConfigValidation1986=== CONT TestGlobMatch1987=== CONT TestScopes_LegacyProviderDefaultsToWrite1988=== CONT TestValidateToken_Expired1989=== RUN TestGlobMatch/foo_foo1990=== PAUSE TestGlobMatch/foo_foo1991=== CONT TestValidateToken_WrongAudience1992=== CONT TestValidateToken_ValidToken1993=== CONT TestAudienceForIssuer1994--- PASS: TestAudienceForIssuer (0.00s)1995=== CONT TestValidateToken_KubernetesServiceAccount1996=== CONT TestNewValidator_KubernetesRequiresCA1997=== CONT TestValidateToken_NoMatchingProvider1998=== CONT TestScopes_ConfigValidation1999=== CONT TestScopes_Rules2000=== CONT TestValidateToken_BoundSubjectMismatch2001=== CONT TestValidateToken_BoundClaimsMismatch2002=== CONT TestValidateToken_MultipleProviders2003=== RUN TestGlobMatch/foo_bar2004=== PAUSE TestGlobMatch/foo_bar2005=== RUN TestGlobMatch/*_2006=== PAUSE TestGlobMatch/*_2007=== RUN TestGlobMatch/*_anything2008=== PAUSE TestGlobMatch/*_anything2009=== RUN TestGlobMatch/foo*_foo2010=== PAUSE TestGlobMatch/foo*_foo2011--- PASS: TestScopes_ConfigValidation (0.00s)2012=== RUN TestGlobMatch/foo*_foobar2013=== PAUSE TestGlobMatch/foo*_foobar2014=== RUN TestGlobMatch/foo*_bar2015=== PAUSE TestGlobMatch/foo*_bar2016=== RUN TestGlobMatch/*bar_bar2017=== PAUSE TestGlobMatch/*bar_bar2018=== RUN TestGlobMatch/*bar_foobar2019=== PAUSE TestGlobMatch/*bar_foobar2020=== RUN TestGlobMatch/*bar_foo2021=== PAUSE TestGlobMatch/*bar_foo2022=== RUN TestGlobMatch/foo*bar_foobar2023=== PAUSE TestGlobMatch/foo*bar_foobar2024=== RUN TestGlobMatch/foo*bar_foo123bar2025=== PAUSE TestGlobMatch/foo*bar_foo123bar2026=== RUN TestGlobMatch/foo*bar_foobarbaz2027=== PAUSE TestGlobMatch/foo*bar_foobarbaz2028=== RUN TestGlobMatch/*/*_foo/bar2029=== PAUSE TestGlobMatch/*/*_foo/bar2030=== RUN TestGlobMatch/*/*_foo2031=== PAUSE TestGlobMatch/*/*_foo2032=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2033=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2034=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02035=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02036=== RUN TestGlobMatch/refs/*/main_refs/heads/main2037=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2038=== RUN TestGlobMatch/fo?_foo2039=== PAUSE TestGlobMatch/fo?_foo2040=== RUN TestGlobMatch/fo?_fo2041=== PAUSE TestGlobMatch/fo?_fo2042=== RUN TestGlobMatch/fo?_fooo2043=== PAUSE TestGlobMatch/fo?_fooo2044=== RUN TestGlobMatch/?oo_foo2045=== PAUSE TestGlobMatch/?oo_foo2046=== RUN TestGlobMatch/?oo_boo2047=== PAUSE TestGlobMatch/?oo_boo2048=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2049=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2050=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2051=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2052=== CONT TestGlobMatch/foo_foo2053=== CONT TestGlobMatch/foo*_bar2054=== CONT TestGlobMatch/*_anything2055=== CONT TestGlobMatch/*bar_foobar2056=== CONT TestGlobMatch/*/*_foo/bar2057=== CONT TestGlobMatch/*_2058=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2059=== CONT TestGlobMatch/fo?_foo20602026/08/27 11:06:39 INFO OIDC provider initialized name=test2061=== CONT TestGlobMatch/refs/heads/*_refs/heads/main20622026/08/27 11:06:39 INFO OIDC provider initialized name=test2063=== CONT TestGlobMatch/foo*_foo20642026/08/27 11:06:39 INFO OIDC provider initialized name=test2065=== CONT TestGlobMatch/foo_bar2066=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2067=== CONT TestGlobMatch/*/*_foo2068=== CONT TestGlobMatch/*bar_bar20692026/08/27 11:06:39 INFO OIDC provider initialized name=test2070=== CONT TestGlobMatch/?oo_boo2071=== CONT TestGlobMatch/foo*bar_foobarbaz2072=== CONT TestGlobMatch/?oo_foo20732026/08/27 11:06:39 INFO OIDC provider initialized name=test2074=== CONT TestGlobMatch/foo*bar_foo123bar2075=== CONT TestGlobMatch/fo?_fooo2076=== CONT TestGlobMatch/foo*bar_foobar2077=== CONT TestGlobMatch/fo?_fo2078=== CONT TestGlobMatch/refs/*/main_refs/heads/main2079=== CONT TestGlobMatch/*bar_foo2080=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.020812026/08/27 11:06:39 INFO OIDC provider initialized name=provider12082=== CONT TestGlobMatch/foo*_foobar2083--- PASS: TestGlobMatch (0.01s)2084 --- PASS: TestGlobMatch/foo_foo (0.00s)2085 --- PASS: TestGlobMatch/foo*_bar (0.00s)2086 --- PASS: TestGlobMatch/*_anything (0.00s)2087 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2088 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2089 --- PASS: TestGlobMatch/*_ (0.00s)2090 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2091 --- PASS: TestGlobMatch/fo?_foo (0.00s)2092 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2093 --- PASS: TestGlobMatch/foo*_foo (0.00s)2094 --- PASS: TestGlobMatch/foo_bar (0.00s)2095 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2096 --- PASS: TestGlobMatch/*/*_foo (0.00s)2097 --- PASS: TestGlobMatch/*bar_bar (0.00s)2098 --- PASS: TestGlobMatch/?oo_boo (0.00s)2099 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2100 --- PASS: TestGlobMatch/?oo_foo (0.00s)2101 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2102 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2103 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2104 --- PASS: TestGlobMatch/fo?_fo (0.00s)2105 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2106 --- PASS: TestGlobMatch/*bar_foo (0.00s)2107 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2108 --- PASS: TestGlobMatch/foo*_foobar (0.00s)21092026/08/27 11:06:39 INFO OIDC provider initialized name=test21102026/08/27 11:06:39 INFO OIDC provider initialized name=test21112026/08/27 11:06:39 INFO OIDC provider initialized name=provider221122026/08/27 11:06:39 INFO OIDC provider initialized name=provider121132026/08/27 11:06:39 INFO OIDC provider initialized name=kubernetes2114--- PASS: TestValidateToken_WrongAudience (0.02s)2115--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2116--- PASS: TestValidateToken_Expired (0.02s)2117--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2118--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.02s)2119--- PASS: TestValidateToken_MultipleProviders (0.01s)2120--- PASS: TestValidateToken_ValidToken (0.02s)2121--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)21222026/08/27 11:06:39 http: TLS handshake error from 127.0.0.1:58468: remote error: tls: bad certificate2123--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2124--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)2125--- PASS: TestScopes_Rules (0.02s)2126PASS2127Running hook tests...2128=== RUN TestSendPathsEmpty2129=== PAUSE TestSendPathsEmpty2130=== RUN TestQueueEnqueueAndFetch2131=== PAUSE TestQueueEnqueueAndFetch2132=== RUN TestQueueDeduplication2133=== PAUSE TestQueueDeduplication2134=== RUN TestQueueRemove2135=== PAUSE TestQueueRemove2136=== RUN TestQueueFetchBatchLimit2137=== PAUSE TestQueueFetchBatchLimit2138=== RUN TestQueueRetryMovesToBack2139=== PAUSE TestQueueRetryMovesToBack2140=== RUN TestQueueFetchRemoveLifecycle2141=== PAUSE TestQueueFetchRemoveLifecycle2142=== RUN TestQueueConcurrentWriters2143=== PAUSE TestQueueConcurrentWriters2144=== RUN TestQueueRemoveLargeClosure2145=== PAUSE TestQueueRemoveLargeClosure2146=== RUN TestServerClientIntegration2147=== PAUSE TestServerClientIntegration2148=== RUN TestServerQueueError2149=== PAUSE TestServerQueueError2150=== RUN TestGetListenerSocketActivation2151 server_test.go:210: === RUN TestGetListenerSocketActivation2152 --- PASS: TestGetListenerSocketActivation (0.00s)2153 PASS2154 2155--- PASS: TestGetListenerSocketActivation (0.01s)2156=== RUN TestDrainIsolatesPoisonPath2157=== PAUSE TestDrainIsolatesPoisonPath2158=== RUN TestRunNotBlockedByPoisonHead2159=== PAUSE TestRunNotBlockedByPoisonHead2160=== RUN TestDrainGivesUpWhenServerDown2161=== PAUSE TestDrainGivesUpWhenServerDown2162=== RUN TestFailedPathPrunedByLaterClosure2163=== PAUSE TestFailedPathPrunedByLaterClosure2164=== RUN TestWorkerUploadsAndRemoves2165=== PAUSE TestWorkerUploadsAndRemoves2166=== RUN TestWorkerSkipsGCdPaths2167=== PAUSE TestWorkerSkipsGCdPaths2168=== RUN TestWorkerPrunesClosureDeps2169=== PAUSE TestWorkerPrunesClosureDeps2170=== RUN TestDrainTimeout2171=== PAUSE TestDrainTimeout2172=== CONT TestSendPathsEmpty2173=== CONT TestFailedPathPrunedByLaterClosure2174=== CONT TestDrainTimeout2175--- PASS: TestSendPathsEmpty (0.00s)2176=== CONT TestQueueFetchRemoveLifecycle2177=== CONT TestQueueRetryMovesToBack2178=== CONT TestQueueFetchBatchLimit2179=== CONT TestQueueRemove2180=== CONT TestQueueDeduplication2181=== CONT TestQueueEnqueueAndFetch2182=== CONT TestQueueConcurrentWriters2183=== CONT TestWorkerPrunesClosureDeps2184=== CONT TestDrainGivesUpWhenServerDown2185=== CONT TestRunNotBlockedByPoisonHead2186=== CONT TestServerQueueError2187=== CONT TestServerClientIntegration2188=== CONT TestDrainIsolatesPoisonPath2189=== CONT TestQueueRemoveLargeClosure2190=== CONT TestWorkerSkipsGCdPaths2191=== CONT TestWorkerUploadsAndRemoves21922026/08/27 11:06:39 ERROR Failed to queue paths error="permission denied" count=12193--- PASS: TestServerQueueError (0.00s)2194--- PASS: TestServerClientIntegration (0.00s)21952026/08/27 11:06:39 INFO Uploading batch count=121962026/08/27 11:06:39 ERROR Upload failed error="upload failed" count=121972026/08/27 11:06:39 INFO Upload queue status pending=221982026/08/27 11:06:39 INFO Uploading batch count=421992026/08/27 11:06:39 ERROR Upload failed error="upload failed" count=422002026/08/27 11:06:39 INFO Uploading batch count=122012026/08/27 11:06:39 INFO Upload queue status pending=222022026/08/27 11:06:39 INFO Uploading batch count=122032026/08/27 11:06:39 INFO Uploading batch count=222042026/08/27 11:06:39 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1269512757/002/bbb22052026/08/27 11:06:39 INFO Uploading batch count=222062026/08/27 11:06:39 INFO Uploading batch count=222072026/08/27 11:06:39 ERROR Upload failed error="upload failed" count=222082026/08/27 11:06:39 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown277249478/002/a22092026/08/27 11:06:39 INFO Upload queue status pending=32210--- PASS: TestQueueEnqueueAndFetch (0.02s)2211--- PASS: TestQueueFetchBatchLimit (0.02s)2212--- PASS: TestQueueFetchRemoveLifecycle (0.02s)22132026/08/27 11:06:39 INFO Uploading batch count=122142026/08/27 11:06:39 INFO Uploading batch count=12215--- PASS: TestQueueRemove (0.02s)22162026/08/27 11:06:39 ERROR Upload failed error="upload failed" count=12217--- PASS: TestQueueDeduplication (0.02s)22182026/08/27 11:06:39 INFO Upload queue status pending=222192026/08/27 11:06:39 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown277249478/002/b22202026/08/27 11:06:39 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1939947066/002/nonexistent2221--- PASS: TestQueueRetryMovesToBack (0.02s)22222026/08/27 11:06:39 INFO Uploading batch count=222232026/08/27 11:06:39 ERROR Upload failed error="upload failed" count=222242026/08/27 11:06:39 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown277249478/002/c22252026/08/27 11:06:39 INFO Uploading batch count=122262026/08/27 11:06:39 ERROR Upload failed error="upload failed" count=122272026/08/27 11:06:39 INFO Uploading batch count=122282026/08/27 11:06:39 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown277249478/002/d22292026/08/27 11:06:39 INFO Uploading batch count=122302026/08/27 11:06:39 ERROR Upload failed error="upload failed" count=12231--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)22322026/08/27 11:06:39 INFO Uploading batch count=122332026/08/27 11:06:39 ERROR Upload failed error="upload failed" count=122342026/08/27 11:06:39 ERROR Drain finished with paths left in queue remaining=122352026/08/27 11:06:39 INFO Uploading batch count=222362026/08/27 11:06:39 ERROR Upload failed error="upload failed" count=222372026/08/27 11:06:39 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown277249478/002/e22382026/08/27 11:06:39 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown277249478/002/f22392026/08/27 11:06:39 ERROR Drain finished with paths left in queue remaining=102240--- PASS: TestDrainIsolatesPoisonPath (0.02s)2241--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2242--- PASS: TestWorkerUploadsAndRemoves (0.03s)2243--- PASS: TestWorkerPrunesClosureDeps (0.04s)2244--- PASS: TestWorkerSkipsGCdPaths (0.04s)22452026/08/27 11:06:39 ERROR Upload failed error="context deadline exceeded" count=222462026/08/27 11:06:39 ERROR Drain finished with paths left in queue remaining=42247--- PASS: TestDrainTimeout (0.22s)2248--- PASS: TestQueueConcurrentWriters (0.23s)2249--- PASS: TestQueueRemoveLargeClosure (0.32s)22502026/08/27 11:06:40 INFO Uploading batch count=122512026/08/27 11:06:40 INFO Uploading batch count=122522026/08/27 11:06:40 INFO Uploading batch count=122532026/08/27 11:06:40 ERROR Upload failed error="upload failed" count=122542026/08/27 11:06:40 INFO Uploading batch count=122552026/08/27 11:06:40 ERROR Upload failed error="upload failed" count=122562026/08/27 11:06:40 INFO Uploading batch count=122572026/08/27 11:06:40 ERROR Upload failed error="upload failed" count=122582026/08/27 11:06:40 INFO Uploading batch count=122592026/08/27 11:06:40 ERROR Upload failed error="upload failed" count=122602026/08/27 11:06:40 ERROR Drain finished with paths left in queue remaining=12261--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2262PASS