niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #189
· raw
1tribuchet: building on jamie2Running 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 TestFileTokenMissing75=== CONT TestResolveStorePath76=== CONT TestEncodeNixBase32WithRealHash77--- PASS: TestEncodeNixBase32WithRealHash (0.00s)78=== CONT TestParsePathInfoJSON79=== RUN TestParsePathInfoJSON/Nix_format80=== PAUSE TestParsePathInfoJSON/Nix_format81=== RUN TestParsePathInfoJSON/Lix_format82=== PAUSE TestParsePathInfoJSON/Lix_format83=== CONT TestPathInfoCACompatibility84--- PASS: TestFileTokenMissing (0.00s)85=== CONT TestDumpPathSingleFile86=== RUN TestPathInfoCACompatibility/null_ca_field87=== PAUSE TestPathInfoCACompatibility/null_ca_field88=== RUN TestPathInfoCACompatibility/old_string_format_-_text89=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text90=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive91=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive92=== RUN TestPathInfoCACompatibility/new_structured_format_-_text93=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text94=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method95=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method96=== CONT TestParsePathInfoJSONMultiplePaths97=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths98=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths99=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess100=== CONT TestSetClientTLS101=== CONT TestRateLimiterFeedback102=== RUN TestRateLimiterFeedback/429_enables_limiter103=== PAUSE TestRateLimiterFeedback/429_enables_limiter104=== RUN TestRateLimiterFeedback/503_enables_limiter105=== PAUSE TestRateLimiterFeedback/503_enables_limiter106=== CONT TestPathInfoHashCompatibility107=== RUN TestParsePathInfoJSON/empty_input108=== CONT TestGetStorePathHash109=== CONT TestConvertHashToNix32110=== CONT TestSetClientTLSDoesNotMutateDefaultTransport111=== CONT TestFileTokenReadsAndCaches112=== CONT TestStaticToken113=== CONT TestSetClientTLSErrors114=== CONT TestScriptTokenEmptyToken115=== CONT TestScriptTokenEmptyCommand116=== CONT TestScriptTokenScriptFails117=== CONT TestScriptTokenBadJSON118=== CONT TestScriptTokenNoExpiryRerunsEveryCall119=== CONT TestScriptTokenCachesUntilRefresh120=== CONT TestDumpPathMatchesNix121=== CONT TestEncodeNixBase32122=== CONT TestDumpPathWriterError123--- PASS: TestResolveStorePath (0.00s)124=== CONT TestShellSplitErrors125=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)126=== RUN TestConvertHashToNix32/SRI_format_to_Nix321272026/09/10 09:07:27 WARN Rate limiter enabled after throttle name=server-test rate=5128=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32129=== RUN TestConvertHashToNix32/already_Nix32_format130=== PAUSE TestConvertHashToNix32/already_Nix32_format131=== RUN TestConvertHashToNix32/invalid_format132=== PAUSE TestConvertHashToNix32/invalid_format133=== CONT TestShellSplit134=== CONT TestUploadMultipart_SupersededByPeer135=== CONT TestPartSizeForNAR136=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)137=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter138=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter139=== PAUSE TestParsePathInfoJSON/empty_input140--- PASS: TestShellSplitErrors (0.00s)141=== RUN TestParsePathInfoJSON/whitespace_only142=== PAUSE TestParsePathInfoJSON/whitespace_only143=== RUN TestPartSizeForNAR/zero_stays_at_minimum144=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum145--- PASS: TestStaticToken (0.00s)146--- PASS: TestFileTokenReadsAndCaches (0.00s)147--- PASS: TestScriptTokenEmptyCommand (0.00s)148=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter149=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter150=== CONT TestCaseHackSuffix151=== CONT TestPathInfoCACompatibility/null_ca_field152--- PASS: TestScriptTokenScriptFails (0.00s)153--- PASS: TestShellSplit (0.00s)154=== RUN TestParsePathInfoJSON/invalid_JSON155=== PAUSE TestParsePathInfoJSON/invalid_JSON156=== RUN TestGetStorePathHash/valid_store_path157=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths158=== CONT TestFilterOversizedClosures159=== CONT TestDoWithRetry_BodyReplayedViaGetBody160=== RUN TestEncodeNixBase32/test_string_hash161=== CONT TestFileTokenEmpty162=== RUN TestUploadMultipart_SupersededByPeer/exists163=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon164=== RUN TestPartSizeForNAR/small_stays_at_minimum165=== PAUSE TestPartSizeForNAR/small_stays_at_minimum166=== PAUSE TestUploadMultipart_SupersededByPeer/exists167=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths168=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive169--- PASS: TestDoServerRequestAttachesToken (0.01s)170=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method171=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon172=== CONT TestPathInfoCACompatibility/new_structured_format_-_text173--- PASS: TestScriptTokenBadJSON (0.01s)174=== CONT TestConvertHashToNix32/invalid_format175=== PAUSE TestEncodeNixBase32/test_string_hash176=== CONT TestPathInfoCACompatibility/old_string_format_-_text177=== PAUSE TestGetStorePathHash/valid_store_path178=== RUN TestFilterOversizedClosures/no_limit_keeps_everything179=== CONT TestConvertHashToNix32/SRI_format_to_Nix32180--- PASS: TestFileTokenEmpty (0.00s)181=== CONT TestConvertHashToNix32/already_Nix32_format182=== RUN TestUploadMultipart_SupersededByPeer/missing183=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum184=== CONT TestRateLimiterFeedback/429_enables_limiter185=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter186=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI187=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI188=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter189=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512190=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512191=== CONT TestParsePathInfoJSON/empty_input192=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything193=== CONT TestParsePathInfoJSON/invalid_JSON194=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped195=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped196=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum197=== PAUSE TestUploadMultipart_SupersededByPeer/missing198=== RUN TestFilterOversizedClosures/all_closures_skipped199=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths200=== CONT TestParsePathInfoJSON/Lix_format201--- PASS: TestPathInfoCACompatibility (0.00s)202 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)203 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)204 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)205 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)206 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)207--- PASS: TestScriptTokenEmptyToken (0.01s)208=== CONT TestParsePathInfoJSON/Nix_format209--- PASS: TestConvertHashToNix32 (0.00s)210 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)211 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)212 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)2132026/09/10 09:07:27 WARN Rate limiter enabled after throttle name=server-test rate=5214=== RUN TestGetStorePathHash/basename_without_hyphen_should_error2152026/09/10 09:07:27 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:36085216=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error2172026/09/10 09:07:27 WARN Rate limiter enabled after throttle name=server-test rate=5218=== RUN TestEncodeNixBase32/empty_input2192026/09/10 09:07:27 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:39583220=== RUN TestSetClientTLS/rejects_connection_without_client_cert221=== PAUSE TestEncodeNixBase32/empty_input222=== CONT TestRateLimiterFeedback/503_enables_limiter2232026/09/10 09:07:27 WARN Rate limiter backed off name=server-test rate=5224=== CONT TestParsePathInfoJSON/whitespace_only225=== CONT TestUploadMultipart_SupersededByPeer/missing226=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts227=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts2282026/09/10 09:07:27 WARN Rate limiter backed off name=server-test rate=5229=== RUN TestPartSizeForNAR/1_TiB2302026/09/10 09:07:27 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:39583231=== PAUSE TestFilterOversizedClosures/all_closures_skipped232=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)233=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI234=== CONT TestFilterOversizedClosures/no_limit_keeps_everything235=== CONT TestEncodeNixBase32/empty_input236=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error237=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped238=== RUN TestSetClientTLSErrors/missing_cert_file239=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert240=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon241=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths242--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)243=== CONT TestUploadMultipart_SupersededByPeer/exists244=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error2452026/09/10 09:07:27 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000246=== PAUSE TestPartSizeForNAR/1_TiB2472026/09/10 09:07:27 WARN Rate limiter enabled after throttle name=server-test rate=5248=== CONT TestEncodeNixBase32/test_string_hash2492026/09/10 09:07:27 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:45523250=== CONT TestFilterOversizedClosures/all_closures_skipped2512026/09/10 09:07:27 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=50252=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512253--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)254=== PAUSE TestSetClientTLSErrors/missing_cert_file255=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA256--- PASS: TestParsePathInfoJSON (0.01s)257 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)258 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)259 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)260 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)261 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)262=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error263=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA264=== RUN TestPartSizeForNAR/5_TiB_S3_max_object265--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)266=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object267--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)268=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error269--- PASS: TestFilterOversizedClosures (0.01s)270 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)271 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)272 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)273=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error274=== RUN TestSetClientTLSErrors/missing_key_file275=== RUN TestSetClientTLS/preserves_debug_logging_transport276=== RUN TestPartSizeForNAR/capped_at_5_GiB277=== CONT TestGetStorePathHash/valid_store_path278--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)279 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)280 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)281--- PASS: TestEncodeNixBase32 (0.01s)282 --- PASS: TestEncodeNixBase32/empty_input (0.00s)283 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)284=== CONT TestGetStorePathHash/basename_without_hyphen_should_error285=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error2862026/09/10 09:07:27 WARN Rate limiter backed off name=server-test rate=5287--- PASS: TestPathInfoHashCompatibility (0.01s)288 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)289 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)290 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)291 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)292=== PAUSE TestPartSizeForNAR/capped_at_5_GiB293=== CONT TestPartSizeForNAR/zero_stays_at_minimum294--- PASS: TestGetStorePathHash (0.02s)295 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)296 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)297 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)298 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)299=== CONT TestPartSizeForNAR/1_TiB300=== CONT TestPartSizeForNAR/5_TiB_S3_max_object301--- PASS: TestRateLimiterFeedback (0.00s)302 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)303 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)304 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)305 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)306=== PAUSE TestSetClientTLSErrors/missing_key_file307=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts308=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum309=== CONT TestPartSizeForNAR/small_stays_at_minimum310=== CONT TestPartSizeForNAR/capped_at_5_GiB311--- PASS: TestPartSizeForNAR (0.02s)312 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)313 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)314 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)315 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)316 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)317 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)318 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)319=== PAUSE TestSetClientTLS/preserves_debug_logging_transport320=== CONT TestSetClientTLS/rejects_connection_without_client_cert321=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA322=== CONT TestSetClientTLS/preserves_debug_logging_transport323=== RUN TestSetClientTLSErrors/missing_ca_file324=== PAUSE TestSetClientTLSErrors/missing_ca_file325=== RUN TestSetClientTLSErrors/invalid_ca_file326=== PAUSE TestSetClientTLSErrors/invalid_ca_file327=== CONT TestSetClientTLSErrors/missing_cert_file328=== CONT TestSetClientTLSErrors/missing_key_file329=== CONT TestSetClientTLSErrors/invalid_ca_file330=== CONT TestSetClientTLSErrors/missing_ca_file331--- PASS: TestSetClientTLSErrors (0.02s)332 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)333 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)334 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)335 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)336--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)337 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)338 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)339--- PASS: TestDumpPathSingleFile (0.03s)3402026/09/10 09:07:27 http: TLS handshake error from 127.0.0.1:39706: remote error: tls: bad certificate341--- PASS: TestSetClientTLS (0.02s)342 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)343 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)344 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)345--- PASS: TestCaseHackSuffix (0.03s)346--- PASS: TestDumpPathWriterError (0.04s)347--- PASS: TestDumpPathMatchesNix (0.07s)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/postgres28583512/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/postgres28583512/data -l logfile start377378/build/postgres28583512:5432 - no response3792026-09-10 09:07:29.789 UTC [112] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit3802026-09-10 09:07:29.789 UTC [112] LOG: listening on Unix socket "/build/postgres28583512/.s.PGSQL.5432"3812026-09-10 09:07:29.795 UTC [119] LOG: database system was shut down at 2026-09-10 09:07:29 UTC3822026-09-10 09:07:29.799 UTC [112] LOG: database system is ready to accept connections383/build/postgres28583512: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-09-10 09:07:30.379 UTC [912] ERROR: relation "goose_db_version" does not exist at character 364182026-09-10 09:07:30.379 UTC [912] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4192026/09/10 09:07:30 OK 20241026095416_initial_model.sql (7.26ms)4202026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)4212026/09/10 09:07:30 OK 20251218171726_add_pins.sql (2.03ms)4222026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (1.72ms)4232026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200004242026/09/10 09:07:30 OK 1_commit_pending_closure.sql (1.39ms)4252026/09/10 09:07:30 OK 2_object_stats_trigger.sql (536.89µs)4262026/09/10 09:07:30 goose: up to current file version: 2427--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.14s)428=== RUN TestOrphanedObjectsGCDeletesEachKeyOnce429=== PAUSE TestOrphanedObjectsGCDeletesEachKeyOnce430=== RUN TestOrphanedObjectsGCFallsBackToSingleDeletes431=== PAUSE TestOrphanedObjectsGCFallsBackToSingleDeletes432=== RUN TestGCBugBareHashReferences433=== PAUSE TestGCBugBareHashReferences434=== RUN TestGCMetrics435=== PAUSE TestGCMetrics436=== RUN TestGCTaskStore_StartNew437=== PAUSE TestGCTaskStore_StartNew438=== RUN TestGCTaskStore_DeduplicateSameParams439=== PAUSE TestGCTaskStore_DeduplicateSameParams440=== RUN TestGCTaskStore_ConflictDifferentParams441=== PAUSE TestGCTaskStore_ConflictDifferentParams442=== RUN TestGCTaskStore_GetEmpty443=== PAUSE TestGCTaskStore_GetEmpty444=== RUN TestGCTaskStore_GetReturnsLatest445=== PAUSE TestGCTaskStore_GetReturnsLatest446=== RUN TestGCTaskStore_CompletedAllowsNewTask447=== PAUSE TestGCTaskStore_CompletedAllowsNewTask448=== RUN TestGCTaskStore_PhaseUpdates449=== PAUSE TestGCTaskStore_PhaseUpdates450=== RUN TestGCTaskStore_Fail451=== PAUSE TestGCTaskStore_Fail452=== RUN TestGracefulShutdownDrainsInflight453=== PAUSE TestGracefulShutdownDrainsInflight454=== RUN TestService_healthCheckHandler455=== PAUSE TestService_healthCheckHandler456=== RUN TestService_readinessHandler457=== PAUSE TestService_readinessHandler458=== RUN TestGenerateLandingPage459=== PAUSE TestGenerateLandingPage460=== RUN TestCacheConfigHandlerMaxNarSize461=== PAUSE TestCacheConfigHandlerMaxNarSize462=== RUN TestCreatePendingClosureRejectsOversizedNAR463=== PAUSE TestCreatePendingClosureRejectsOversizedNAR464=== RUN TestNARDeduplicationMetadataUploadBug465=== PAUSE TestNARDeduplicationMetadataUploadBug466=== RUN TestMetricsInventory467=== PAUSE TestMetricsInventory468=== RUN TestService_NativeMTLS469=== PAUSE TestService_NativeMTLS470=== RUN TestServerTLSConfig471=== PAUSE TestServerTLSConfig472=== RUN TestMultipartCleanup473=== PAUSE TestMultipartCleanup474=== RUN TestObjectStatsTrigger475=== PAUSE TestObjectStatsTrigger476=== RUN TestOrphanedObjectsGC477=== PAUSE TestOrphanedObjectsGC478=== RUN TestOrphanedObjectsGCStressTest479=== PAUSE TestOrphanedObjectsGCStressTest480=== RUN TestResurrectedObjectNotDeleted481=== PAUSE TestResurrectedObjectNotDeleted482=== RUN TestParseSingleRange483=== PAUSE TestParseSingleRange484=== RUN TestIsValidCachePath485=== PAUSE TestIsValidCachePath486=== RUN TestReadProxyNarinfo487=== PAUSE TestReadProxyNarinfo488=== RUN TestReadProxyNarinfoAlreadyDecompressed489=== PAUSE TestReadProxyNarinfoAlreadyDecompressed490=== RUN TestReadProxyNarStreaming491=== PAUSE TestReadProxyNarStreaming492=== RUN TestReadProxy404493=== PAUSE TestReadProxy404494=== RUN TestReadProxyInvalidPath495=== PAUSE TestReadProxyInvalidPath496=== RUN TestReadProxyHead497=== PAUSE TestReadProxyHead498=== RUN TestReadProxyConditionalGet499=== PAUSE TestReadProxyConditionalGet500=== RUN TestReadProxyRootRedirectsToIndexHTML501=== PAUSE TestReadProxyRootRedirectsToIndexHTML502=== RUN TestReadProxyDisabled503=== PAUSE TestReadProxyDisabled504=== RUN TestReadRedirectNar505=== PAUSE TestReadRedirectNar506=== RUN TestReadRedirectKeepsNarinfoProxied507=== PAUSE TestReadRedirectKeepsNarinfoProxied508=== RUN TestReadProxyRangeRequest509=== PAUSE TestReadProxyRangeRequest510=== RUN TestReadRedirectUsesPublicS3URL511=== PAUSE TestReadRedirectUsesPublicS3URL512=== RUN TestRedundantMultipartUpload513=== PAUSE TestRedundantMultipartUpload514=== RUN TestCompleteMultipartUpload_ErrorButObjectExists515=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists516=== RUN TestCompletedNarNotReofferedAcrossClosures517=== PAUSE TestCompletedNarNotReofferedAcrossClosures518=== RUN TestPresignedUploadRegisteredBeforeCommit519=== PAUSE TestPresignedUploadRegisteredBeforeCommit520=== RUN TestService_Rustfstest521=== PAUSE TestService_Rustfstest522=== RUN TestParseSize523=== PAUSE TestParseSize524=== RUN TestSkippedUploadsHandler525=== PAUSE TestSkippedUploadsHandler526=== RUN TestSystemdListenerNotActivated527--- PASS: TestSystemdListenerNotActivated (0.00s)528=== RUN TestWatchdogBeatsWhenHealthy529--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)530=== RUN TestWatchdogSkipsWhenUnhealthy5312026/09/10 09:07:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5322026/09/10 09:07:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5332026/09/10 09:07:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5342026/09/10 09:07:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5352026/09/10 09:07:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5362026/09/10 09:07:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5372026/09/10 09:07:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5382026/09/10 09:07:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5392026/09/10 09:07:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5402026/09/10 09:07:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"541--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)542=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle543=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle544=== RUN TestProxyWriteTimeout545=== PAUSE TestProxyWriteTimeout546=== RUN TestIsValidUploadKey547=== PAUSE TestIsValidUploadKey548=== RUN TestUploadHandlersRejectInvalidKeys549=== PAUSE TestUploadHandlersRejectInvalidKeys550=== RUN TestUploadHandlersRejectOversizedBody551=== PAUSE TestUploadHandlersRejectOversizedBody552=== RUN TestService_cleanupPendingClosuresHandler553=== PAUSE TestService_cleanupPendingClosuresHandler554=== RUN TestService_createPendingClosureHandler555=== PAUSE TestService_createPendingClosureHandler556=== RUN TestService_verifyS3Integrity557=== PAUSE TestService_verifyS3Integrity558=== RUN TestCompleteMultipartUnregistered559=== PAUSE TestCompleteMultipartUnregistered560=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT561=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT562=== CONT TestService_AuthMiddleware563=== CONT TestReadProxyConditionalGet564=== CONT TestGCTaskStore_PhaseUpdates565--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)566=== CONT TestParseSize567=== CONT TestReadProxyHead568=== CONT TestReadProxyInvalidPath569=== CONT TestReadProxy404570=== CONT TestReadProxyNarStreaming571=== CONT TestReadProxyNarinfoAlreadyDecompressed572=== CONT TestReadProxyNarinfo573=== CONT TestIsValidCachePath574=== RUN TestIsValidCachePath/narinfo575=== PAUSE TestIsValidCachePath/narinfo576=== CONT TestParseSingleRange577=== CONT TestResurrectedObjectNotDeleted578=== RUN TestParseSingleRange/none579=== PAUSE TestParseSingleRange/none580=== RUN TestParseSingleRange/unknown_unit581=== CONT TestOrphanedObjectsGCStressTest582=== CONT TestOrphanedObjectsGC583=== CONT TestObjectStatsTrigger584=== CONT TestMultipartCleanup585=== CONT TestServerTLSConfig586=== CONT TestService_NativeMTLS587=== CONT TestMetricsInventory588=== CONT TestNARDeduplicationMetadataUploadBug589=== CONT TestCreatePendingClosureRejectsOversizedNAR590=== CONT TestCacheConfigHandlerMaxNarSize591=== CONT TestGenerateLandingPage592=== CONT TestService_readinessHandler593--- PASS: TestParseSize (0.00s)594=== CONT TestService_healthCheckHandler595=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars596=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars597=== RUN TestIsValidCachePath/nar_zst598=== PAUSE TestIsValidCachePath/nar_zst599=== RUN TestIsValidCachePath/nar_xz600=== PAUSE TestIsValidCachePath/nar_xz601=== RUN TestIsValidCachePath/nar_bz2602=== PAUSE TestIsValidCachePath/nar_bz2603=== RUN TestIsValidCachePath/nar_uncompressed604=== PAUSE TestIsValidCachePath/nar_uncompressed605=== RUN TestIsValidCachePath/ls606=== PAUSE TestIsValidCachePath/ls607=== RUN TestIsValidCachePath/log608=== PAUSE TestIsValidCachePath/log609=== RUN TestIsValidCachePath/realisation610=== PAUSE TestIsValidCachePath/realisation611=== RUN TestIsValidCachePath/nix-cache-info612=== PAUSE TestIsValidCachePath/nix-cache-info613=== RUN TestIsValidCachePath/index.html614=== PAUSE TestIsValidCachePath/index.html615=== RUN TestIsValidCachePath/traversal_parent616=== PAUSE TestIsValidCachePath/traversal_parent617=== RUN TestIsValidCachePath/traversal_in_middle618=== PAUSE TestIsValidCachePath/traversal_in_middle619=== RUN TestIsValidCachePath/invalid_char_e620=== PAUSE TestIsValidCachePath/invalid_char_e621=== RUN TestIsValidCachePath/invalid_char_u622=== PAUSE TestIsValidCachePath/invalid_char_u623=== RUN TestIsValidCachePath/random_path624=== PAUSE TestIsValidCachePath/random_path625=== RUN TestIsValidCachePath/empty626=== PAUSE TestIsValidCachePath/empty627=== RUN TestIsValidCachePath/leading_slash628=== PAUSE TestIsValidCachePath/leading_slash629=== RUN TestIsValidCachePath/wrong_extension630=== PAUSE TestIsValidCachePath/wrong_extension631=== RUN TestIsValidCachePath/short_hash632=== PAUSE TestIsValidCachePath/short_hash633=== CONT TestGracefulShutdownDrainsInflight6342026/09/10 09:07:30 INFO Starting HTTP server address=127.0.0.1:437896352026/09/10 09:07:30 INFO Received uploads request method=POST path=/api/pending_closures636=== CONT TestCompleteMultipartUnregistered637=== CONT TestService_verifyS3Integrity638=== RUN TestServerTLSConfig/no_client_CA639=== PAUSE TestServerTLSConfig/no_client_CA640=== RUN TestServerTLSConfig/missing_CA_file641=== PAUSE TestServerTLSConfig/missing_CA_file642=== RUN TestServerTLSConfig/not_a_PEM_file643=== PAUSE TestServerTLSConfig/not_a_PEM_file6442026/09/10 09:07:30 INFO Shutdown signal received, draining in-flight requests timeout=10s645=== CONT TestGCTaskStore_Fail646=== CONT TestService_createPendingClosureHandler647=== PAUSE TestParseSingleRange/unknown_unit648=== RUN TestParseSingleRange/multi-range_ignored649=== PAUSE TestParseSingleRange/multi-range_ignored650=== RUN TestParseSingleRange/malformed_no_dash651=== PAUSE TestParseSingleRange/malformed_no_dash652=== RUN TestParseSingleRange/malformed_both_empty653--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)654--- PASS: TestGenerateLandingPage (0.01s)655--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)656--- PASS: TestGCTaskStore_Fail (0.00s)657=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT658=== PAUSE TestParseSingleRange/malformed_both_empty659=== RUN TestParseSingleRange/malformed_end_before_start660=== PAUSE TestParseSingleRange/malformed_end_before_start661=== RUN TestParseSingleRange/closed662=== PAUSE TestParseSingleRange/closed663=== RUN TestParseSingleRange/open-ended664=== PAUSE TestParseSingleRange/open-ended665=== RUN TestParseSingleRange/end_clamped_to_size666=== PAUSE TestParseSingleRange/end_clamped_to_size667=== RUN TestParseSingleRange/suffix668=== PAUSE TestParseSingleRange/suffix669=== RUN TestParseSingleRange/suffix_exceeds_size670=== PAUSE TestParseSingleRange/suffix_exceeds_size671=== RUN TestParseSingleRange/single_byte672=== PAUSE TestParseSingleRange/single_byte673=== RUN TestParseSingleRange/start_past_EOF674=== PAUSE TestParseSingleRange/start_past_EOF675=== RUN TestParseSingleRange/start_far_past_EOF676=== PAUSE TestParseSingleRange/start_far_past_EOF677=== CONT TestService_cleanupPendingClosuresHandler678--- PASS: TestGracefulShutdownDrainsInflight (0.07s)679=== CONT TestUploadHandlersRejectOversizedBody6802026-09-10 09:07:30.776 UTC [991] ERROR: relation "goose_db_version" does not exist at character 366812026-09-10 09:07:30.776 UTC [991] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6822026-09-10 09:07:30.782 UTC [990] ERROR: relation "goose_db_version" does not exist at character 366832026-09-10 09:07:30.782 UTC [990] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6842026-09-10 09:07:30.784 UTC [992] ERROR: relation "goose_db_version" does not exist at character 366852026-09-10 09:07:30.784 UTC [992] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6862026-09-10 09:07:30.786 UTC [993] ERROR: relation "goose_db_version" does not exist at character 366872026-09-10 09:07:30.786 UTC [993] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6882026-09-10 09:07:30.786 UTC [994] ERROR: relation "goose_db_version" does not exist at character 366892026-09-10 09:07:30.786 UTC [994] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6902026-09-10 09:07:30.791 UTC [995] ERROR: relation "goose_db_version" does not exist at character 366912026-09-10 09:07:30.791 UTC [995] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6922026-09-10 09:07:30.837 UTC [996] ERROR: relation "goose_db_version" does not exist at character 366932026-09-10 09:07:30.837 UTC [996] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6942026-09-10 09:07:30.837 UTC [997] ERROR: relation "goose_db_version" does not exist at character 366952026-09-10 09:07:30.837 UTC [997] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6962026/09/10 09:07:30 OK 20241026095416_initial_model.sql (49.35ms)6972026/09/10 09:07:30 OK 20241026095416_initial_model.sql (58.35ms)6982026/09/10 09:07:30 OK 20241026095416_initial_model.sql (30.84ms)6992026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (13.53ms)7002026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (7.02ms)7012026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (3.96ms)7022026/09/10 09:07:30 OK 20241026095416_initial_model.sql (69.36ms)7032026/09/10 09:07:30 OK 20241026095416_initial_model.sql (70.96ms)7042026-09-10 09:07:30.902 UTC [998] ERROR: relation "goose_db_version" does not exist at character 367052026-09-10 09:07:30.902 UTC [998] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7062026/09/10 09:07:30 OK 20251218171726_add_pins.sql (10.28ms)7072026/09/10 09:07:30 OK 20241026095416_initial_model.sql (38.22ms)7082026/09/10 09:07:30 OK 20241026095416_initial_model.sql (73.44ms)7092026/09/10 09:07:30 OK 20241026095416_initial_model.sql (73.66ms)7102026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (6.61ms)7112026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (4.85ms)7122026/09/10 09:07:30 OK 20251218171726_add_pins.sql (10.61ms)7132026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (3.98ms)7142026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (3.99ms)7152026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (4.34ms)7162026/09/10 09:07:30 OK 20251218171726_add_pins.sql (13.87ms)717=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure718=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure719=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart720=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart721=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts722=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts723=== CONT TestUploadHandlersRejectInvalidKeys724=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info725=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info726=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal727=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal728=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key729=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key730=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key731=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key732=== CONT TestIsValidUploadKey733=== RUN TestIsValidUploadKey/narinfo734=== PAUSE TestIsValidUploadKey/narinfo735=== RUN TestIsValidUploadKey/nar_zst736=== PAUSE TestIsValidUploadKey/nar_zst737=== RUN TestIsValidUploadKey/nar_xz738=== PAUSE TestIsValidUploadKey/nar_xz739=== RUN TestIsValidUploadKey/nar_plain740=== PAUSE TestIsValidUploadKey/nar_plain741=== RUN TestIsValidUploadKey/listing742=== PAUSE TestIsValidUploadKey/listing743=== RUN TestIsValidUploadKey/build_log744=== PAUSE TestIsValidUploadKey/build_log745=== RUN TestIsValidUploadKey/build_log_home-manager_file746=== PAUSE TestIsValidUploadKey/build_log_home-manager_file747=== RUN TestIsValidUploadKey/build_log_plus_in_name748=== PAUSE TestIsValidUploadKey/build_log_plus_in_name749=== RUN TestIsValidUploadKey/build_log_question_mark750=== PAUSE TestIsValidUploadKey/build_log_question_mark751=== RUN TestIsValidUploadKey/build_log_equals752=== PAUSE TestIsValidUploadKey/build_log_equals753=== RUN TestIsValidUploadKey/realisation754=== PAUSE TestIsValidUploadKey/realisation755=== RUN TestIsValidUploadKey/realisation_plus_in_output756=== PAUSE TestIsValidUploadKey/realisation_plus_in_output757=== RUN TestIsValidUploadKey/nix-cache-info758=== PAUSE TestIsValidUploadKey/nix-cache-info759=== RUN TestIsValidUploadKey/index.html760=== PAUSE TestIsValidUploadKey/index.html761=== RUN TestIsValidUploadKey/narinfo_key,_nar_type762=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type763=== RUN TestIsValidUploadKey/nar_key,_narinfo_type764=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type765=== RUN TestIsValidUploadKey/listing_key,_narinfo_type766=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type767=== RUN TestIsValidUploadKey/traversal768=== PAUSE TestIsValidUploadKey/traversal769=== RUN TestIsValidUploadKey/traversal_nar770=== PAUSE TestIsValidUploadKey/traversal_nar771=== RUN TestIsValidUploadKey/absolute772=== PAUSE TestIsValidUploadKey/absolute773=== RUN TestIsValidUploadKey/empty_key774=== PAUSE TestIsValidUploadKey/empty_key775=== RUN TestIsValidUploadKey/unknown_type776=== PAUSE TestIsValidUploadKey/unknown_type777=== CONT TestProxyWriteTimeout778=== RUN TestProxyWriteTimeout/narinfo779=== PAUSE TestProxyWriteTimeout/narinfo780=== RUN TestProxyWriteTimeout/1_GiB_nar781=== PAUSE TestProxyWriteTimeout/1_GiB_nar782=== RUN TestProxyWriteTimeout/10_GiB_nar783=== PAUSE TestProxyWriteTimeout/10_GiB_nar784=== RUN TestProxyWriteTimeout/unknown_size785=== PAUSE TestProxyWriteTimeout/unknown_size786=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle7872026/09/10 09:07:30 OK 20251218171726_add_pins.sql (14.42ms)7882026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (16.97ms)7892026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200007902026/09/10 09:07:30 OK 20251218171726_add_pins.sql (17.96ms)7912026/09/10 09:07:30 OK 20251218171726_add_pins.sql (16.13ms)7922026/09/10 09:07:30 OK 20251218171726_add_pins.sql (16.11ms)7932026/09/10 09:07:30 OK 20251218171726_add_pins.sql (15.87ms)7942026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (16.3ms)7952026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200007962026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (15.3ms)7972026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200007982026/09/10 09:07:30 OK 1_commit_pending_closure.sql (3.76ms)7992026/09/10 09:07:30 OK 1_commit_pending_closure.sql (5.12ms)8002026/09/10 09:07:30 OK 1_commit_pending_closure.sql (5.59ms)8012026/09/10 09:07:30 OK 2_object_stats_trigger.sql (4.55ms)8022026/09/10 09:07:30 goose: up to current file version: 28032026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (8.49ms)8042026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200008052026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (8.44ms)8062026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200008072026/09/10 09:07:30 OK 20241026095416_initial_model.sql (22.08ms)8082026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (13.96ms)8092026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200008102026/09/10 09:07:30 OK 2_object_stats_trigger.sql (3.92ms)8112026/09/10 09:07:30 goose: up to current file version: 28122026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (10.08ms)8132026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200008142026/09/10 09:07:30 OK 2_object_stats_trigger.sql (4.08ms)8152026/09/10 09:07:30 goose: up to current file version: 28162026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (12.59ms)8172026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200008182026/09/10 09:07:30 OK 1_commit_pending_closure.sql (5.19ms)8192026/09/10 09:07:30 OK 1_commit_pending_closure.sql (5.25ms)8202026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (3.56ms)8212026/09/10 09:07:30 OK 1_commit_pending_closure.sql (5.08ms)8222026/09/10 09:07:30 OK 2_object_stats_trigger.sql (2.46ms)8232026/09/10 09:07:30 OK 2_object_stats_trigger.sql (2.5ms)8242026/09/10 09:07:30 goose: up to current file version: 28252026/09/10 09:07:30 OK 1_commit_pending_closure.sql (3.72ms)8262026/09/10 09:07:30 OK 1_commit_pending_closure.sql (3.84ms)8272026/09/10 09:07:30 goose: up to current file version: 28282026/09/10 09:07:30 OK 2_object_stats_trigger.sql (2.19ms)8292026/09/10 09:07:30 goose: up to current file version: 28302026/09/10 09:07:30 OK 20251218171726_add_pins.sql (3.61ms)8312026/09/10 09:07:30 OK 2_object_stats_trigger.sql (2.02ms)8322026/09/10 09:07:30 goose: up to current file version: 28332026/09/10 09:07:30 OK 2_object_stats_trigger.sql (2.08ms)8342026/09/10 09:07:30 goose: up to current file version: 28352026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (3.64ms)8362026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200008372026/09/10 09:07:30 OK 1_commit_pending_closure.sql (2.83ms)8382026/09/10 09:07:30 OK 2_object_stats_trigger.sql (1.76ms)8392026/09/10 09:07:30 goose: up to current file version: 28402026-09-10 09:07:30.951 UTC [1001] ERROR: relation "goose_db_version" does not exist at character 368412026-09-10 09:07:30.951 UTC [1001] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8422026-09-10 09:07:30.952 UTC [1002] ERROR: relation "goose_db_version" does not exist at character 368432026-09-10 09:07:30.952 UTC [1002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8442026-09-10 09:07:30.952 UTC [1003] ERROR: relation "goose_db_version" does not exist at character 368452026-09-10 09:07:30.952 UTC [1003] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8462026-09-10 09:07:30.953 UTC [1004] ERROR: relation "goose_db_version" does not exist at character 368472026-09-10 09:07:30.953 UTC [1004] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8482026-09-10 09:07:30.955 UTC [1005] ERROR: relation "goose_db_version" does not exist at character 368492026-09-10 09:07:30.955 UTC [1005] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8502026/09/10 09:07:30 INFO Received uploads request method=POST path=/api/pending_closures8512026-09-10 09:07:30.960 UTC [1006] ERROR: relation "goose_db_version" does not exist at character 368522026-09-10 09:07:30.960 UTC [1006] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8532026-09-10 09:07:30.962 UTC [1007] ERROR: relation "goose_db_version" does not exist at character 368542026-09-10 09:07:30.962 UTC [1007] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8552026-09-10 09:07:30.962 UTC [1008] ERROR: relation "goose_db_version" does not exist at character 368562026-09-10 09:07:30.962 UTC [1008] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8572026-09-10 09:07:30.963 UTC [1009] ERROR: relation "goose_db_version" does not exist at character 368582026-09-10 09:07:30.963 UTC [1009] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8592026-09-10 09:07:30.963 UTC [1010] ERROR: relation "goose_db_version" does not exist at character 368602026-09-10 09:07:30.963 UTC [1010] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8612026-09-10 09:07:30.965 UTC [1011] ERROR: relation "goose_db_version" does not exist at character 368622026-09-10 09:07:30.965 UTC [1011] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8632026-09-10 09:07:30.976 UTC [1012] ERROR: relation "goose_db_version" does not exist at character 368642026-09-10 09:07:30.976 UTC [1012] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8652026-09-10 09:07:30.976 UTC [1014] ERROR: relation "goose_db_version" does not exist at character 368662026-09-10 09:07:30.976 UTC [1014] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8672026-09-10 09:07:30.977 UTC [1013] ERROR: relation "goose_db_version" does not exist at character 368682026-09-10 09:07:30.977 UTC [1013] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8692026/09/10 09:07:30 OK 20241026095416_initial_model.sql (11.21ms)8702026/09/10 09:07:30 OK 20241026095416_initial_model.sql (11.33ms)8712026/09/10 09:07:30 OK 20241026095416_initial_model.sql (10.39ms)8722026/09/10 09:07:30 OK 20241026095416_initial_model.sql (12.07ms)8732026/09/10 09:07:30 OK 20241026095416_initial_model.sql (12.88ms)8742026/09/10 09:07:30 OK 20241026095416_initial_model.sql (12.44ms)8752026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.85ms)8762026/09/10 09:07:30 OK 20241026095416_initial_model.sql (13.14ms)8772026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)8782026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.34ms)8792026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (3.15ms)8802026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)8812026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.21ms)8822026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.16ms)8832026/09/10 09:07:30 OK 20241026095416_initial_model.sql (13.22ms)8842026/09/10 09:07:30 OK 20241026095416_initial_model.sql (14.24ms)8852026/09/10 09:07:30 OK 20241026095416_initial_model.sql (14.3ms)8862026/09/10 09:07:30 OK 20251218171726_add_pins.sql (3.87ms)8872026/09/10 09:07:30 OK 20251218171726_add_pins.sql (4.05ms)8882026/09/10 09:07:30 OK 20251218171726_add_pins.sql (3.87ms)8892026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.49ms)8902026/09/10 09:07:30 OK 20241026095416_initial_model.sql (13.66ms)8912026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)8922026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.85ms)8932026/09/10 09:07:30 OK 20251218171726_add_pins.sql (4.21ms)8942026/09/10 09:07:30 OK 20251218171726_add_pins.sql (4.35ms)8952026/09/10 09:07:30 OK 20251218171726_add_pins.sql (4.29ms)8962026/09/10 09:07:30 OK 20251218171726_add_pins.sql (5.34ms)8972026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (4.33ms)8982026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200008992026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.57ms)9002026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (4.5ms)9012026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200009022026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (4.5ms)9032026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200009042026/09/10 09:07:30 OK 20251218171726_add_pins.sql (4.66ms)9052026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (4.13ms)9062026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200009072026/09/10 09:07:30 OK 20251218171726_add_pins.sql (4.59ms)9082026/09/10 09:07:30 OK 20251218171726_add_pins.sql (4.84ms)9092026/09/10 09:07:30 OK 1_commit_pending_closure.sql (3.09ms)9102026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (5.21ms)9112026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200009122026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (5.13ms)9132026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200009142026/09/10 09:07:30 OK 1_commit_pending_closure.sql (3.28ms)9152026/09/10 09:07:30 OK 1_commit_pending_closure.sql (3.22ms)9162026/09/10 09:07:30 OK 20251218171726_add_pins.sql (4.33ms)9172026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (5.38ms)9182026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200009192026/09/10 09:07:30 OK 2_object_stats_trigger.sql (1.9ms)9202026/09/10 09:07:30 OK 2_object_stats_trigger.sql (2.1ms)9212026/09/10 09:07:30 goose: up to current file version: 29222026/09/10 09:07:30 goose: up to current file version: 29232026/09/10 09:07:30 OK 1_commit_pending_closure.sql (2.93ms)9242026/09/10 09:07:30 OK 1_commit_pending_closure.sql (2.53ms)9252026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (3.74ms)9262026/09/10 09:07:30 OK 20241026095416_initial_model.sql (9.34ms)9272026/09/10 09:07:30 OK 2_object_stats_trigger.sql (1.59ms)9282026/09/10 09:07:30 goose: up to current file version: 29292026/09/10 09:07:30 OK 1_commit_pending_closure.sql (2.67ms)9302026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200009312026/09/10 09:07:30 OK 20241026095416_initial_model.sql (9.89ms)9322026/09/10 09:07:30 OK 1_commit_pending_closure.sql (2.05ms)9332026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (4.14ms)9342026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200009352026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (4.18ms)9362026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200009372026/09/10 09:07:30 OK 2_object_stats_trigger.sql (1.9ms)9382026/09/10 09:07:30 goose: up to current file version: 29392026/09/10 09:07:30 OK 2_object_stats_trigger.sql (2.37ms)9402026/09/10 09:07:30 goose: up to current file version: 29412026/09/10 09:07:30 OK 20241026095416_initial_model.sql (11.53ms)9422026/09/10 09:07:30 OK 2_object_stats_trigger.sql (2.46ms)9432026/09/10 09:07:30 goose: up to current file version: 29442026/09/10 09:07:30 OK 20260628120000_add_object_size_and_stats.sql (4.3ms)9452026/09/10 09:07:30 goose: successfully migrated database to version: 202606281200009462026/09/10 09:07:30 OK 2_object_stats_trigger.sql (2.09ms)9472026/09/10 09:07:30 goose: up to current file version: 29482026/09/10 09:07:30 OK 1_commit_pending_closure.sql (2.23ms)9492026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.8ms)9502026/09/10 09:07:30 OK 1_commit_pending_closure.sql (2.38ms)9512026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (2.65ms)9522026/09/10 09:07:30 OK 1_commit_pending_closure.sql (2.31ms)9532026/09/10 09:07:30 OK 20251210153512_drop_unused_gin_index.sql (1.07ms)9542026/09/10 09:07:30 OK 2_object_stats_trigger.sql (767.11µs)9552026/09/10 09:07:30 goose: up to current file version: 29562026/09/10 09:07:30 OK 1_commit_pending_closure.sql (1.34ms)9572026/09/10 09:07:30 OK 2_object_stats_trigger.sql (1.08ms)9582026/09/10 09:07:30 goose: up to current file version: 29592026/09/10 09:07:30 OK 2_object_stats_trigger.sql (1.18ms)9602026/09/10 09:07:30 goose: up to current file version: 29612026/09/10 09:07:31 OK 2_object_stats_trigger.sql (546.41µs)9622026/09/10 09:07:31 goose: up to current file version: 29632026/09/10 09:07:31 OK 20251218171726_add_pins.sql (1.93ms)9642026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.44ms)9652026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.98ms)9662026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (1.98ms)9672026/09/10 09:07:31 goose: successfully migrated database to version: 202606281200009682026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.01ms)9692026/09/10 09:07:31 goose: successfully migrated database to version: 202606281200009702026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (1.92ms)9712026/09/10 09:07:31 goose: successfully migrated database to version: 202606281200009722026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.1ms)9732026/09/10 09:07:31 OK 2_object_stats_trigger.sql (604.46µs)9742026/09/10 09:07:31 goose: up to current file version: 29752026/09/10 09:07:31 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"9762026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.32ms)977--- PASS: TestService_AuthMiddleware (0.33s)978=== CONT TestSkippedUploadsHandler9792026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.25ms)9802026/09/10 09:07:31 INFO Client skipped oversized paths paths=3 nar_bytes=50000000009812026/09/10 09:07:31 OK 2_object_stats_trigger.sql (615.71µs)9822026/09/10 09:07:31 goose: up to current file version: 29832026/09/10 09:07:31 OK 2_object_stats_trigger.sql (676.07µs)9842026/09/10 09:07:31 goose: up to current file version: 29852026-09-10 09:07:31.007 UTC [1015] ERROR: relation "goose_db_version" does not exist at character 369862026-09-10 09:07:31.007 UTC [1015] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC987--- PASS: TestSkippedUploadsHandler (0.00s)988=== CONT TestClientWithDependencies9892026/09/10 09:07:31 OK 20241026095416_initial_model.sql (6.44ms)9902026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (884.78µs)9912026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.49ms)9922026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.02ms)9932026/09/10 09:07:31 goose: successfully migrated database to version: 20260628120000994--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.35s)995=== CONT TestGCTaskStore_StartNew996--- PASS: TestGCTaskStore_StartNew (0.00s)997=== CONT TestGCMetrics9982026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.25ms)9992026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.4ms)10002026/09/10 09:07:31 goose: up to current file version: 21001--- PASS: TestReadProxy404 (0.36s)1002=== CONT TestGCTaskStore_CompletedAllowsNewTask1003--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1004=== CONT TestGCBugBareHashReferences1005--- PASS: TestReadProxyNarStreaming (0.39s)1006=== CONT TestGCTaskStore_GetReturnsLatest1007--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1008=== CONT TestOrphanedObjectsGCFallsBackToSingleDeletes1009--- PASS: TestReadProxyConditionalGet (0.41s)1010=== CONT TestGCTaskStore_GetEmpty1011--- PASS: TestGCTaskStore_GetEmpty (0.00s)1012=== CONT TestOrphanedObjectsGCDeletesEachKeyOnce10132026-09-10 09:07:31.082 UTC [1024] ERROR: relation "goose_db_version" does not exist at character 3610142026-09-10 09:07:31.082 UTC [1024] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10152026/09/10 09:07:31 INFO Received cleanup request method=DELETE path=/api/pending_closures10162026/09/10 09:07:31 INFO Aborted multipart uploads count=11017--- PASS: TestMultipartCleanup (0.43s)1018=== CONT TestGCTaskStore_ConflictDifferentParams1019--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1020=== CONT TestGCTaskStore_DeduplicateSameParams1021--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1022=== CONT TestResolveDBConnectionString1023=== RUN TestResolveDBConnectionString/flag_wins1024=== PAUSE TestResolveDBConnectionString/flag_wins1025=== RUN TestResolveDBConnectionString/file_when_flag_empty1026=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1027=== RUN TestResolveDBConnectionString/missing_file_is_an_error1028=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1029=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1030=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1031=== RUN TestResolveDBConnectionString/nothing_configured1032=== PAUSE TestResolveDBConnectionString/nothing_configured1033=== CONT TestPinProtectsFromGC1034--- PASS: TestReadProxyHead (0.43s)1035=== CONT TestReadRedirectUsesPublicS3URL10362026/09/10 09:07:31 OK 20241026095416_initial_model.sql (10.27ms)10372026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (2.6ms)10382026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.85ms)10392026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.47ms)10402026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000010412026-09-10 09:07:31.116 UTC [1031] ERROR: relation "goose_db_version" does not exist at character 3610422026-09-10 09:07:31.116 UTC [1031] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10432026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.39ms)10442026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.58ms)10452026/09/10 09:07:31 goose: up to current file version: 210462026-09-10 09:07:31.122 UTC [1032] ERROR: relation "goose_db_version" does not exist at character 3610472026-09-10 09:07:31.122 UTC [1032] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1048--- PASS: TestReadProxyNarinfo (0.46s)10492026/09/10 09:07:31 OK 20241026095416_initial_model.sql (9.13ms)1050=== CONT TestCompleteMultipartUpload_ErrorButObjectExists10512026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)10522026/09/10 09:07:31 OK 20251218171726_add_pins.sql (3.51ms)10532026/09/10 09:07:31 OK 20241026095416_initial_model.sql (9.78ms)10542026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.88ms)10552026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.81ms)10562026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000010572026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.44ms)10582026/09/10 09:07:31 OK 20251218171726_add_pins.sql (3.33ms)10592026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.27ms)10602026/09/10 09:07:31 goose: up to current file version: 210612026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.14ms)10622026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000010632026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.03ms)1064--- PASS: TestReadProxyInvalidPath (0.48s)1065=== CONT TestRedundantMultipartUpload10662026/09/10 09:07:31 OK 2_object_stats_trigger.sql (6.45ms)10672026/09/10 09:07:31 goose: up to current file version: 210682026-09-10 09:07:31.158 UTC [1036] ERROR: relation "goose_db_version" does not exist at character 3610692026-09-10 09:07:31.158 UTC [1036] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10702026-09-10 09:07:31.173 UTC [1038] ERROR: relation "goose_db_version" does not exist at character 3610712026-09-10 09:07:31.173 UTC [1038] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10722026/09/10 09:07:31 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10732026/09/10 09:07:31 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1074--- PASS: TestService_NativeMTLS (0.50s)1075=== CONT TestService_Rustfstest10762026/09/10 09:07:31 OK 20241026095416_initial_model.sql (13.2ms)10772026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)10782026/09/10 09:07:31 OK 20251218171726_add_pins.sql (4.19ms)10792026-09-10 09:07:31.187 UTC [1041] ERROR: relation "goose_db_version" does not exist at character 3610802026-09-10 09:07:31.187 UTC [1041] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10812026/09/10 09:07:31 OK 20241026095416_initial_model.sql (8.71ms)10822026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.45ms)10832026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000010842026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)10852026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.58ms)10862026/09/10 09:07:31 OK 20251218171726_add_pins.sql (3.28ms)10872026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.45ms)10882026/09/10 09:07:31 goose: up to current file version: 210892026-09-10 09:07:31.193 UTC [1042] ERROR: relation "goose_db_version" does not exist at character 3610902026-09-10 09:07:31.193 UTC [1042] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10912026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (4.66ms)10922026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000010932026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.06ms)10942026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.83ms)10952026/09/10 09:07:31 goose: up to current file version: 210962026/09/10 09:07:31 OK 20241026095416_initial_model.sql (9.09ms)10972026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)10982026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.93ms)10992026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.11ms)11002026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000011012026/09/10 09:07:31 OK 20241026095416_initial_model.sql (9.51ms)11022026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.04ms)11032026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)11042026-09-10 09:07:31.213 UTC [1043] ERROR: relation "goose_db_version" does not exist at character 3611052026-09-10 09:07:31.213 UTC [1043] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11062026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.64ms)11072026/09/10 09:07:31 goose: up to current file version: 21108--- PASS: TestMetricsInventory (0.54s)1109=== CONT TestCacheConfigHandler1110=== RUN TestCacheConfigHandler/full_config,_no_issuer1111=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1112=== RUN TestCacheConfigHandler/no_cache_url_configured1113=== PAUSE TestCacheConfigHandler/no_cache_url_configured1114=== RUN TestCacheConfigHandler/no_signing_keys1115=== PAUSE TestCacheConfigHandler/no_signing_keys1116=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1117=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1118=== CONT TestClientMultipleUploads11192026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.69ms)11202026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.11ms)11212026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000011222026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.47ms)11232026/09/10 09:07:31 OK 2_object_stats_trigger.sql (954.91µs)11242026/09/10 09:07:31 goose: up to current file version: 211252026/09/10 09:07:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11262026/09/10 09:07:31 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1127--- PASS: TestCompleteMultipartUnregistered (0.54s)1128=== CONT TestClientCADerivations11292026/09/10 09:07:31 OK 20241026095416_initial_model.sql (12.83ms)11302026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (2.23ms)11312026-09-10 09:07:31.232 UTC [1046] ERROR: relation "goose_db_version" does not exist at character 3611322026-09-10 09:07:31.232 UTC [1046] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11332026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.54ms)11342026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.86ms)11352026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000011362026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.67ms)11372026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.71ms)11382026/09/10 09:07:31 goose: up to current file version: 211392026/09/10 09:07:31 OK 20241026095416_initial_model.sql (9.44ms)11402026-09-10 09:07:31.249 UTC [1049] ERROR: relation "goose_db_version" does not exist at character 3611412026-09-10 09:07:31.249 UTC [1049] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11422026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (2.8ms)11432026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.85ms)11442026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.81ms)11452026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000011462026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.06ms)11472026/09/10 09:07:31 OK 2_object_stats_trigger.sql (2.06ms)11482026/09/10 09:07:31 goose: up to current file version: 211492026/09/10 09:07:31 OK 20241026095416_initial_model.sql (8.4ms)11502026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.82ms)1151--- PASS: TestObjectStatsTrigger (0.59s)1152=== CONT TestCacheStatsHandler11532026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.91ms)11542026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures11552026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.13ms)11562026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000011572026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.32ms)11582026/09/10 09:07:31 OK 2_object_stats_trigger.sql (976.4µs)11592026/09/10 09:07:31 goose: up to current file version: 211602026-09-10 09:07:31.289 UTC [1052] ERROR: relation "goose_db_version" does not exist at character 3611612026-09-10 09:07:31.289 UTC [1052] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11622026/09/10 09:07:31 INFO Received cleanup request method=DELETE path=/api/pending_closures11632026-09-10 09:07:31.295 UTC [1053] ERROR: relation "goose_db_version" does not exist at character 3611642026-09-10 09:07:31.295 UTC [1053] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11652026/09/10 09:07:31 INFO Aborted multipart uploads count=011662026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures11672026/09/10 09:07:31 OK 20241026095416_initial_model.sql (8.33ms)11682026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.32ms)11692026/09/10 09:07:31 OK 20241026095416_initial_model.sql (7.88ms)11702026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.81ms)11712026/09/10 09:07:31 INFO Received cleanup request method=DELETE path=/api/pending_closures11722026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)11732026/09/10 09:07:31 INFO Aborted multipart uploads count=111742026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.55ms)11752026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000011762026/09/10 09:07:31 OK 20251218171726_add_pins.sql (3.32ms)11772026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.83ms)11782026/09/10 09:07:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11792026/09/10 09:07:31 OK 2_object_stats_trigger.sql (877.75µs)11802026/09/10 09:07:31 goose: up to current file version: 211812026-09-10 09:07:31.316 UTC [1006] ERROR: Closure does not exist: id=111822026-09-10 09:07:31.316 UTC [1006] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE11832026-09-10 09:07:31.316 UTC [1006] STATEMENT: -- name: CommitPendingClosure :exec1184 SELECT commit_pending_closure($1::bigint)1185 11862026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.66ms)11872026/09/10 09:07:31 goose: successfully migrated database to version: 202606281200001188--- PASS: TestService_cleanupPendingClosuresHandler (0.64s)1189=== CONT TestPresignedUploadRegisteredBeforeCommit11902026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.7ms)11912026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures11922026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures11932026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures11942026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.44ms)11952026/09/10 09:07:31 goose: up to current file version: 211962026-09-10 09:07:31.337 UTC [1056] ERROR: relation "goose_db_version" does not exist at character 3611972026-09-10 09:07:31.337 UTC [1056] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11982026/09/10 09:07:31 OK 20241026095416_initial_model.sql (7.22ms)11992026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)12002026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.54ms)12012026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.52ms)12022026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000012032026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.92ms)12042026/09/10 09:07:31 WARN readiness check failed error="closed pool"1205--- PASS: TestService_readinessHandler (0.69s)1206=== CONT TestClientErrorHandling1207=== RUN TestClientErrorHandling/InvalidStorePath1208=== PAUSE TestClientErrorHandling/InvalidStorePath1209=== RUN TestClientErrorHandling/InvalidAuthToken1210=== PAUSE TestClientErrorHandling/InvalidAuthToken1211=== RUN TestClientErrorHandling/ServerNotAvailable1212=== PAUSE TestClientErrorHandling/ServerNotAvailable1213=== CONT TestService_AuthMiddleware_OIDC12142026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.43ms)12152026/09/10 09:07:31 goose: up to current file version: 212162026/09/10 09:07:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42743/oidc12172026-09-10 09:07:31.382 UTC [1059] ERROR: relation "goose_db_version" does not exist at character 3612182026-09-10 09:07:31.382 UTC [1059] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12192026/09/10 09:07:31 OK 20241026095416_initial_model.sql (11.81ms)12202026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)12212026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.96ms)12222026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.26ms)12232026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000012242026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.02ms)12252026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.26ms)12262026/09/10 09:07:31 goose: up to current file version: 21227=== NAME TestNARDeduplicationMetadataUploadBug1228 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3368227948/001/store/pdbhjcgxhdm66r053lraisnwg6wj7dii-file1.txt12292026-09-10 09:07:31.434 UTC [1077] ERROR: relation "goose_db_version" does not exist at character 3612302026-09-10 09:07:31.434 UTC [1077] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12312026/09/10 09:07:31 OK 20241026095416_initial_model.sql (6.43ms)12322026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (853.29µs)12332026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.06ms)12342026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.07ms)12352026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000012362026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.35ms)12372026/09/10 09:07:31 OK 2_object_stats_trigger.sql (743.64µs)12382026/09/10 09:07:31 goose: up to current file version: 21239--- PASS: TestResurrectedObjectNotDeleted (0.78s)1240=== CONT TestClientIntegration1241--- PASS: TestService_healthCheckHandler (0.78s)1242=== CONT TestService_ReadScope_PublicByDefault12432026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures1244--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.81s)1245=== CONT TestService_RequireScope_OIDC12462026/09/10 09:07:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34545/oidc12472026/09/10 09:07:31 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12482026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures12492026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures12502026-09-10 09:07:31.534 UTC [1138] ERROR: relation "goose_db_version" does not exist at character 3612512026-09-10 09:07:31.534 UTC [1138] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12522026-09-10 09:07:31.534 UTC [1140] ERROR: relation "goose_db_version" does not exist at character 3612532026-09-10 09:07:31.534 UTC [1140] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12542026/09/10 09:07:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12552026/09/10 09:07:31 INFO Uploading pdbhjcgxhdm66r053lraisnwg6wj7dii-file1.txt (160B)12562026/09/10 09:07:31 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12572026/09/10 09:07:31 WARN Failed to register uploaded object key=pdbhjcgxhdm66r053lraisnwg6wj7dii.ls error="server returned 404: 404 page not found\n"12582026/09/10 09:07:31 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12592026/09/10 09:07:31 INFO Signed narinfos id=1 count=112602026/09/10 09:07:31 INFO Uploading 1 narinfos12612026/09/10 09:07:31 OK 20241026095416_initial_model.sql (9.25ms)12622026/09/10 09:07:31 OK 20241026095416_initial_model.sql (9.7ms)12632026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)12642026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (2.57ms)12652026/09/10 09:07:31 OK 20251218171726_add_pins.sql (3.39ms)12662026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.32ms)12672026/09/10 09:07:31 INFO Aborted multipart uploads count=012682026/09/10 09:07:31 WARN Failed to register uploaded object key=pdbhjcgxhdm66r053lraisnwg6wj7dii.narinfo error="server returned 404: 404 page not found\n"12692026/09/10 09:07:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12702026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.22ms)12712026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000012722026/09/10 09:07:31 WARN Force mode enabled - objects will be deleted immediately without grace period12732026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.17ms)12742026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000012752026-09-10 09:07:31.560 UTC [1143] ERROR: relation "goose_db_version" does not exist at character 3612762026-09-10 09:07:31.560 UTC [1143] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12772026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.89ms)12782026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.19ms)12792026/09/10 09:07:31 OK 2_object_stats_trigger.sql (641.68µs)12802026/09/10 09:07:31 goose: up to current file version: 212812026/09/10 09:07:31 OK 2_object_stats_trigger.sql (679.99µs)12822026/09/10 09:07:31 goose: up to current file version: 212832026/09/10 09:07:31 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012842026/09/10 09:07:31 INFO Vacuumed table table=pending_closures12852026/09/10 09:07:31 INFO Vacuumed table table=pending_objects12862026/09/10 09:07:31 INFO Vacuumed table table=multipart_uploads12872026/09/10 09:07:31 INFO Completed upload id=112882026/09/10 09:07:31 INFO Vacuumed table table=closures12892026/09/10 09:07:31 INFO Upload complete. (100ms)12902026/09/10 09:07:31 INFO Vacuumed table table=objects1291=== NAME TestNARDeduplicationMetadataUploadBug1292 metadata_upload_test.go:54: Retrieved narinfo from S3:1293 StorePath: /build/TestNARDeduplicationMetadataUploadBug3368227948/001/store/pdbhjcgxhdm66r053lraisnwg6wj7dii-file1.txt1294 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1295 Compression: zstd1296 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1297 NarSize: 1601298 References: 1299 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1300 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1301 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1302 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1303--- PASS: TestGCMetrics (0.55s)1304=== CONT TestCompletedNarNotReofferedAcrossClosures13052026/09/10 09:07:31 OK 20241026095416_initial_model.sql (7.04ms)13062026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)13072026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.82ms)13082026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.4ms)13092026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000013102026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.25ms)13112026/09/10 09:07:31 OK 2_object_stats_trigger.sql (755.9µs)13122026/09/10 09:07:31 goose: up to current file version: 21313=== NAME TestNARDeduplicationMetadataUploadBug1314 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3368227948/001/store/3ixhjzxdrv5a25shk33xfjdldawkpwkf-file2.txt13152026/09/10 09:07:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1316=== NAME TestClientWithDependencies1317 client_integration_test.go:594: Built derivation: /build/TestClientWithDependencies3305829240/001/store/ldcfyzpd79zs5zwivzyb4xcgkyhh76zj-test-script13182026-09-10 09:07:31.630 UTC [1198] ERROR: relation "goose_db_version" does not exist at character 3613192026-09-10 09:07:31.630 UTC [1198] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13202026/09/10 09:07:31 OK 20241026095416_initial_model.sql (7.19ms)13212026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.4ms)13222026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.42ms)13232026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.64ms)13242026/09/10 09:07:31 goose: successfully migrated database to version: 202606281200001325 client_integration_test.go:596: Found 1 dependencies (including self)13262026/09/10 09:07:31 OK 1_commit_pending_closure.sql (2.73ms)13272026/09/10 09:07:31 OK 2_object_stats_trigger.sql (828.54µs)13282026/09/10 09:07:31 goose: up to current file version: 21329=== NAME TestOrphanedObjectsGC1330 orphaned_objects_gc_test.go:290: GC Test Summary:1331 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1332 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1333 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1334 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1335 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1336--- PASS: TestOrphanedObjectsGC (0.98s)1337=== CONT TestReadRedirectNar1338--- PASS: TestReadRedirectUsesPublicS3URL (0.56s)1339=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13402026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures13412026/09/10 09:07:31 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13422026/09/10 09:07:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13432026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures1344=== NAME TestPinProtectsFromGC1345 client_integration_test.go:648: Pinned store path: /build/TestPinProtectsFromGC3991503199/001/store/xgg53m7qpzpvj321s6cmlx9x9k435a2n-pinned-file.txt1346 client_integration_test.go:649: Unpinned store path: /build/TestPinProtectsFromGC3991503199/001/store/7mpmzgd37h03waq8gaznz6dpqnlrg7j4-unpinned-file.txt13472026/09/10 09:07:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13482026/09/10 09:07:31 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NzExOTRjZjUtMGYxNy00NDFhLTk0NmUtZTRlNWNiOTBlZWEzLjZiMmY2YmNkLTI1ZTMtNGE5My1hZjM2LWJiZmIxMzNkMGE2NngxNzg5MDMxMjUxNjgzOTE1MTc513492026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures13502026/09/10 09:07:31 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13512026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures13522026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures13532026/09/10 09:07:31 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13542026/09/10 09:07:31 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NzExOTRjZjUtMGYxNy00NDFhLTk0NmUtZTRlNWNiOTBlZWEzLjBjNTY4MjJlLTFiZjktNGVkMy04M2E5LTUwYTQ5M2Q3MTkzMngxNzg5MDMxMjUxMjc5ODU2ODg0 parts=1013552026/09/10 09:07:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13562026/09/10 09:07:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13572026/09/10 09:07:31 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13582026/09/10 09:07:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13592026/09/10 09:07:31 INFO Uploading ldcfyzpd79zs5zwivzyb4xcgkyhh76zj-test-script (136B)1360--- PASS: TestGCBugBareHashReferences (0.78s)1361=== CONT TestService_AuthMiddleware_MTLSProxyHeader13622026/09/10 09:07:31 WARN Failed to register uploaded object key=3ixhjzxdrv5a25shk33xfjdldawkpwkf.ls error="server returned 404: 404 page not found\n"13632026/09/10 09:07:31 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13642026/09/10 09:07:31 INFO Signed narinfos id=2 count=113652026/09/10 09:07:31 INFO Uploading 1 narinfos13662026/09/10 09:07:31 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"13672026/09/10 09:07:31 INFO Completed upload id=113682026/09/10 09:07:31 WARN Failed to register uploaded object key=log/8qzbxggmxlf4mz5wf8yqa268s95px6zl-test-script.drv error="server returned 404: 404 page not found\n"13692026-09-10 09:07:31.815 UTC [1407] ERROR: relation "goose_db_version" does not exist at character 3613702026-09-10 09:07:31.815 UTC [1407] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13712026-09-10 09:07:31.816 UTC [1409] ERROR: relation "goose_db_version" does not exist at character 3613722026-09-10 09:07:31.816 UTC [1409] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13732026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures13742026/09/10 09:07:31 WARN Failed to register uploaded object key=3ixhjzxdrv5a25shk33xfjdldawkpwkf.narinfo error="server returned 404: 404 page not found\n"13752026/09/10 09:07:31 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13762026/09/10 09:07:31 WARN Failed to register uploaded object key=ldcfyzpd79zs5zwivzyb4xcgkyhh76zj.ls error="server returned 404: 404 page not found\n"13772026/09/10 09:07:31 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13782026/09/10 09:07:31 INFO Signed narinfos id=1 count=113792026/09/10 09:07:31 INFO Uploading 1 narinfos13802026/09/10 09:07:31 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NzExOTRjZjUtMGYxNy00NDFhLTk0NmUtZTRlNWNiOTBlZWEzLjZiMmY2YmNkLTI1ZTMtNGE5My1hZjM2LWJiZmIxMzNkMGE2NngxNzg5MDMxMjUxNjgzOTE1MTc5 parts=11381--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.69s)1382=== CONT TestService_ReadAuthMiddleware13832026/09/10 09:07:31 WARN Failed to register uploaded object key=ldcfyzpd79zs5zwivzyb4xcgkyhh76zj.narinfo error="server returned 404: 404 page not found\n"13842026/09/10 09:07:31 INFO Completed upload id=213852026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures13862026/09/10 09:07:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13872026/09/10 09:07:31 INFO Upload complete. (169ms)1388=== NAME TestNARDeduplicationMetadataUploadBug1389 metadata_upload_test.go:76: Retrieved narinfo from S3:1390 StorePath: /build/TestNARDeduplicationMetadataUploadBug3368227948/001/store/3ixhjzxdrv5a25shk33xfjdldawkpwkf-file2.txt1391 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1392 Compression: zstd1393 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1394 NarSize: 1601395 References: 1396 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1397--- PASS: TestService_Rustfstest (0.65s)1398=== CONT TestReadProxyRangeRequest13992026/09/10 09:07:31 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14002026/09/10 09:07:31 WARN Found objects in DB but missing from S3, will re-upload count=11401=== NAME TestNARDeduplicationMetadataUploadBug1402 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1403 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1404 {"version":1,"root":{"type":"regular","size":44}}14052026/09/10 09:07:31 INFO Completed upload id=114062026/09/10 09:07:31 INFO Upload complete. (150ms)1407--- PASS: TestService_verifyS3Integrity (1.15s)1408=== CONT TestReadRedirectKeepsNarinfoProxied1409--- PASS: TestNARDeduplicationMetadataUploadBug (1.15s)1410=== CONT TestReadProxyDisabled14112026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures14122026/09/10 09:07:31 OK 20241026095416_initial_model.sql (8.45ms)1413=== NAME TestClientWithDependencies1414 client_integration_test.go:598: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3305829240/001/store) requires matching store prefix14152026/09/10 09:07:31 OK 20241026095416_initial_model.sql (8.09ms)14162026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (2.98ms)14172026/09/10 09:07:31 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NzExOTRjZjUtMGYxNy00NDFhLTk0NmUtZTRlNWNiOTBlZWEzLjk1M2Q4N2FjLTg0ZTgtNDA3OC04ZmM3LTJkNzc4ZWQ5ZjNlNngxNzg5MDMxMjUxMzI3OTQxOTM2 parts=1014182026/09/10 09:07:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14192026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.85ms)14202026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.6ms)1421--- PASS: TestClientWithDependencies (0.83s)1422=== CONT TestReadProxyRootRedirectsToIndexHTML14232026/09/10 09:07:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14242026/09/10 09:07:31 INFO Uploading xgg53m7qpzpvj321s6cmlx9x9k435a2n-pinned-file.txt (128B)14252026/09/10 09:07:31 INFO Completed upload id=114262026/09/10 09:07:31 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014272026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures14282026/09/10 09:07:31 OK 20251218171726_add_pins.sql (4.32ms)14292026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.94ms)14302026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000014312026/09/10 09:07:31 INFO Starting cleanup of old closures method=DELETE path=/api/closures14322026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.54ms)14332026/09/10 09:07:31 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14342026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.85ms)14352026/09/10 09:07:31 goose: up to current file version: 214362026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (4.53ms)14372026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000014382026/09/10 09:07:31 WARN Failed to register uploaded object key=xgg53m7qpzpvj321s6cmlx9x9k435a2n.ls error="server returned 404: 404 page not found\n"14392026/09/10 09:07:31 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14402026/09/10 09:07:31 INFO Signed narinfos id=1 count=114412026/09/10 09:07:31 INFO Uploading 1 narinfos14422026/09/10 09:07:31 OK 1_commit_pending_closure.sql (3.01ms)14432026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.28ms)14442026/09/10 09:07:31 goose: up to current file version: 214452026/09/10 09:07:31 INFO Aborted multipart uploads count=014462026/09/10 09:07:31 WARN Failed to register uploaded object key=xgg53m7qpzpvj321s6cmlx9x9k435a2n.narinfo error="server returned 404: 404 page not found\n"14472026/09/10 09:07:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14482026/09/10 09:07:31 INFO Completed upload id=114492026/09/10 09:07:31 INFO Upload complete. (117ms)14502026/09/10 09:07:31 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=014512026/09/10 09:07:31 INFO Vacuumed table table=pending_closures14522026/09/10 09:07:31 INFO Vacuumed table table=pending_objects14532026/09/10 09:07:31 INFO Vacuumed table table=multipart_uploads14542026/09/10 09:07:31 INFO Vacuumed table table=closures14552026/09/10 09:07:31 INFO Vacuumed table table=objects1456=== NAME TestClientMultipleUploads1457 client_integration_test.go:339: Created store path 0: /build/TestClientMultipleUploads3276222843/001/store/npx1ch7daym8v9d4xffvmqvhym55fxp8-test-file-0.txt14582026/09/10 09:07:31 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001459--- PASS: TestService_createPendingClosureHandler (1.22s)1460=== CONT TestIsValidCachePath/narinfo1461=== CONT TestIsValidCachePath/invalid_char_e1462=== CONT TestIsValidCachePath/short_hash1463=== CONT TestIsValidCachePath/empty1464=== CONT TestIsValidCachePath/wrong_extension1465=== CONT TestIsValidCachePath/leading_slash1466=== CONT TestIsValidCachePath/random_path1467=== CONT TestIsValidCachePath/log1468=== CONT TestIsValidCachePath/traversal_in_middle1469=== CONT TestIsValidCachePath/traversal_parent1470=== CONT TestIsValidCachePath/index.html1471=== CONT TestIsValidCachePath/nix-cache-info1472=== CONT TestIsValidCachePath/realisation1473=== CONT TestIsValidCachePath/nar_bz21474=== CONT TestIsValidCachePath/ls1475=== CONT TestIsValidCachePath/nar_uncompressed1476=== CONT TestServerTLSConfig/no_client_CA1477=== CONT TestServerTLSConfig/not_a_PEM_file1478=== CONT TestIsValidCachePath/invalid_char_u1479=== CONT TestIsValidCachePath/nar_zst1480=== CONT TestIsValidCachePath/nar_xz1481=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1482--- PASS: TestIsValidCachePath (0.00s)1483 --- PASS: TestIsValidCachePath/narinfo (0.00s)1484 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1485 --- PASS: TestIsValidCachePath/short_hash (0.00s)1486 --- PASS: TestIsValidCachePath/empty (0.00s)1487 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1488 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1489 --- PASS: TestIsValidCachePath/random_path (0.00s)1490 --- PASS: TestIsValidCachePath/log (0.00s)1491 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1492 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1493 --- PASS: TestIsValidCachePath/index.html (0.00s)1494 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1495 --- PASS: TestIsValidCachePath/realisation (0.00s)1496 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1497 --- PASS: TestIsValidCachePath/ls (0.00s)1498 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1499 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1500 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1501 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1502 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1503=== CONT TestServerTLSConfig/missing_CA_file1504--- PASS: TestServerTLSConfig (0.01s)1505 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1506 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1507 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1508=== CONT TestParseSingleRange/start_far_past_EOF1509=== CONT TestParseSingleRange/none1510=== CONT TestParseSingleRange/start_past_EOF1511=== CONT TestParseSingleRange/single_byte1512=== CONT TestParseSingleRange/suffix_exceeds_size1513=== CONT TestParseSingleRange/suffix1514=== CONT TestParseSingleRange/end_clamped_to_size1515=== CONT TestParseSingleRange/open-ended1516=== CONT TestParseSingleRange/closed1517=== CONT TestParseSingleRange/malformed_end_before_start1518=== CONT TestParseSingleRange/malformed_both_empty1519=== CONT TestParseSingleRange/malformed_no_dash1520=== CONT TestParseSingleRange/multi-range_ignored1521=== CONT TestParseSingleRange/unknown_unit1522--- PASS: TestParseSingleRange (0.01s)1523 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1524 --- PASS: TestParseSingleRange/none (0.00s)1525 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1526 --- PASS: TestParseSingleRange/single_byte (0.00s)1527 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1528 --- PASS: TestParseSingleRange/suffix (0.00s)1529 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1530 --- PASS: TestParseSingleRange/open-ended (0.00s)1531 --- PASS: TestParseSingleRange/closed (0.00s)1532 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1533 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1534 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1535 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1536 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1537=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15382026/09/10 09:07:31 INFO Received uploads request method=POST path=/15392026/09/10 09:07:31 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1540--- PASS: TestCacheStatsHandler (0.65s)1541=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15422026/09/10 09:07:31 INFO Received complete multipart upload request method=POST path=/15432026-09-10 09:07:31.922 UTC [1494] ERROR: relation "goose_db_version" does not exist at character 3615442026-09-10 09:07:31.922 UTC [1494] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15452026-09-10 09:07:31.927 UTC [1512] ERROR: relation "goose_db_version" does not exist at character 3615462026-09-10 09:07:31.927 UTC [1512] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1547=== NAME TestClientMultipleUploads1548 client_integration_test.go:339: Created store path 1: /build/TestClientMultipleUploads3276222843/001/store/b2h1w9icbwyz58gn35y37bbaf48yx6jk-test-file-1.txt15492026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures15502026-09-10 09:07:31.934 UTC [1514] ERROR: relation "goose_db_version" does not exist at character 3615512026-09-10 09:07:31.934 UTC [1514] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15522026-09-10 09:07:31.934 UTC [1516] ERROR: relation "goose_db_version" does not exist at character 3615532026-09-10 09:07:31.934 UTC [1516] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15542026-09-10 09:07:31.935 UTC [1517] ERROR: relation "goose_db_version" does not exist at character 3615552026-09-10 09:07:31.935 UTC [1517] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15562026-09-10 09:07:31.936 UTC [1518] ERROR: relation "goose_db_version" does not exist at character 3615572026-09-10 09:07:31.936 UTC [1518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15582026/09/10 09:07:31 OK 20241026095416_initial_model.sql (13.28ms)15592026/09/10 09:07:31 OK 20241026095416_initial_model.sql (10.63ms)15602026/09/10 09:07:31 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst15612026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures1562--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.63s)1563=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15642026/09/10 09:07:31 INFO Received request for more parts method=POST path=/15652026/09/10 09:07:31 OK 20241026095416_initial_model.sql (8.61ms)15662026/09/10 09:07:31 OK 20241026095416_initial_model.sql (8.58ms)15672026/09/10 09:07:31 OK 20241026095416_initial_model.sql (9.16ms)15682026/09/10 09:07:31 OK 20241026095416_initial_model.sql (9.28ms)15692026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (2.4ms)15702026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (2.23ms)15712026/09/10 09:07:31 INFO Received uploads request method=POST path=/api/pending_closures15722026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.57ms)15732026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.77ms)15742026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.34ms)15752026/09/10 09:07:31 OK 20251210153512_drop_unused_gin_index.sql (1.65ms)15762026/09/10 09:07:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15772026/09/10 09:07:31 INFO Uploading 7mpmzgd37h03waq8gaznz6dpqnlrg7j4-unpinned-file.txt (128B)1578=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1579=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1580=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1581=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1582=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1583=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1584=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1585=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1586=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15872026/09/10 09:07:31 INFO Received uploads request method=POST path=/1588=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15892026/09/10 09:07:31 INFO Received request for more parts method=POST path=/1590=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15912026/09/10 09:07:31 INFO Received complete multipart upload request method=POST path=/1592=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15932026/09/10 09:07:31 INFO Received uploads request method=POST path=/1594--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1595 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1596 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1597 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1598 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1599=== CONT TestIsValidUploadKey/narinfo1600=== CONT TestIsValidUploadKey/nix-cache-info1601=== CONT TestIsValidUploadKey/realisation_plus_in_output1602=== CONT TestIsValidUploadKey/realisation16032026/09/10 09:07:31 OK 20251218171726_add_pins.sql (3.28ms)1604=== CONT TestIsValidUploadKey/build_log_equals1605=== CONT TestIsValidUploadKey/build_log_question_mark1606=== CONT TestIsValidUploadKey/build_log_plus_in_name1607=== CONT TestIsValidUploadKey/build_log_home-manager_file1608=== CONT TestIsValidUploadKey/build_log1609=== CONT TestIsValidUploadKey/listing1610=== CONT TestIsValidUploadKey/nar_plain1611=== CONT TestIsValidUploadKey/nar_xz1612=== CONT TestIsValidUploadKey/nar_zst1613=== CONT TestIsValidUploadKey/traversal_nar1614=== CONT TestIsValidUploadKey/index.html1615=== CONT TestIsValidUploadKey/traversal1616=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1617=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1618=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1619=== CONT TestIsValidUploadKey/empty_key1620=== CONT TestIsValidUploadKey/unknown_type1621=== CONT TestIsValidUploadKey/absolute1622--- PASS: TestIsValidUploadKey (0.00s)1623 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1624 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1625 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1626 --- PASS: TestIsValidUploadKey/realisation (0.00s)1627 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1628 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1629 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1630 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1631 --- PASS: TestIsValidUploadKey/build_log (0.00s)1632 --- PASS: TestIsValidUploadKey/listing (0.00s)1633 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1634 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1635 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1636 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1637 --- PASS: TestIsValidUploadKey/index.html (0.00s)1638 --- PASS: TestIsValidUploadKey/traversal (0.00s)1639 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1640 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1641 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1642 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1643 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1644 --- PASS: TestIsValidUploadKey/absolute (0.00s)1645=== CONT TestProxyWriteTimeout/narinfo1646=== CONT TestProxyWriteTimeout/10_GiB_nar1647=== CONT TestProxyWriteTimeout/unknown_size1648=== CONT TestProxyWriteTimeout/1_GiB_nar1649--- PASS: TestProxyWriteTimeout (0.00s)1650 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1651 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1652 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1653 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1654=== CONT TestResolveDBConnectionString/flag_wins1655=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1656=== CONT TestResolveDBConnectionString/nothing_configured1657=== CONT TestResolveDBConnectionString/missing_file_is_an_error1658=== CONT TestResolveDBConnectionString/file_when_flag_empty16592026/09/10 09:07:31 OK 20251218171726_add_pins.sql (3.09ms)16602026/09/10 09:07:31 OK 20251218171726_add_pins.sql (3.97ms)1661=== CONT TestCacheConfigHandler/full_config,_no_issuer16622026/09/10 09:07:31 OK 20251218171726_add_pins.sql (3.2ms)16632026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.75ms)1664=== CONT TestCacheConfigHandler/no_signing_keys1665=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator16662026/09/10 09:07:31 OK 20251218171726_add_pins.sql (2.95ms)1667=== CONT TestCacheConfigHandler/no_cache_url_configured1668--- PASS: TestCacheConfigHandler (0.00s)1669 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1670 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1671 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1672 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1673=== CONT TestClientErrorHandling/InvalidStorePath1674--- PASS: TestResolveDBConnectionString (0.00s)1675 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1676 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1677 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1678 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1679 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)16802026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.61ms)16812026/09/10 09:07:31 goose: successfully migrated database to version: 202606281200001682=== NAME TestClientMultipleUploads16832026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.63ms)1684 client_integration_test.go:339: Created store path 2: /build/TestClientMultipleUploads3276222843/001/store/wsa2ynlwh7hbsgd18x6q1x1z4zs8lgay-test-file-2.txt16852026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000016862026/09/10 09:07:31 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16872026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (2.97ms)16882026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000016892026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (4.37ms)16902026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000016912026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.65ms)16922026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000016932026/09/10 09:07:31 OK 20260628120000_add_object_size_and_stats.sql (3.35ms)16942026/09/10 09:07:31 goose: successfully migrated database to version: 2026062812000016952026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.62ms)16962026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.28ms)16972026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.76ms)16982026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.34ms)16992026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.48ms)17002026/09/10 09:07:31 OK 2_object_stats_trigger.sql (939.83µs)17012026/09/10 09:07:31 goose: up to current file version: 217022026/09/10 09:07:31 OK 2_object_stats_trigger.sql (876.54µs)17032026/09/10 09:07:31 goose: up to current file version: 217042026/09/10 09:07:31 OK 1_commit_pending_closure.sql (1.7ms)17052026/09/10 09:07:31 OK 2_object_stats_trigger.sql (872.43µs)17062026/09/10 09:07:31 goose: up to current file version: 217072026/09/10 09:07:31 OK 2_object_stats_trigger.sql (777.07µs)17082026/09/10 09:07:31 goose: up to current file version: 217092026/09/10 09:07:31 WARN Failed to register uploaded object key=7mpmzgd37h03waq8gaznz6dpqnlrg7j4.ls error="server returned 404: 404 page not found\n"17102026/09/10 09:07:31 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17112026/09/10 09:07:31 INFO Signed narinfos id=2 count=117122026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.41ms)17132026/09/10 09:07:31 goose: up to current file version: 217142026/09/10 09:07:31 INFO Uploading 1 narinfos1715=== CONT TestClientErrorHandling/InvalidAuthToken17162026/09/10 09:07:31 OK 2_object_stats_trigger.sql (1.47ms)17172026/09/10 09:07:31 goose: up to current file version: 217182026/09/10 09:07:31 WARN Failed to register uploaded object key=7mpmzgd37h03waq8gaznz6dpqnlrg7j4.narinfo error="server returned 404: 404 page not found\n"17192026/09/10 09:07:31 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17202026/09/10 09:07:31 INFO Completed upload id=217212026/09/10 09:07:31 INFO Upload complete. (79ms)1722=== NAME TestClientCADerivations1723 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2040627672/001/store/x0b5zj4hawkp5fh2kfz7m7lymy1nhc82-ca-test1724--- PASS: TestService_ReadScope_PublicByDefault (0.51s)1725=== CONT TestClientErrorHandling/ServerNotAvailable1726=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token17272026/09/10 09:07:31 INFO OIDC auth successful provider=test scopes=[write]1728=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected17292026/09/10 09:07:31 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]1730=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected17312026/09/10 09:07:31 WARN Authentication failed token_preview=eyJhbGciOi...iFNqlAfM3g token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1732=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1733--- PASS: TestService_AuthMiddleware_OIDC (0.59s)1734 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1735 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1736 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1737 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1738=== NAME TestClientCADerivations1739 client_ca_test.go:139: Found 1 dependencies (including self)17402026/09/10 09:07:32 INFO Received create pin request method=POST path=/api/pins/myapp17412026/09/10 09:07:32 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3991503199/001/store/xgg53m7qpzpvj321s6cmlx9x9k435a2n-pinned-file.txt narinfo_key=xgg53m7qpzpvj321s6cmlx9x9k435a2n.narinfo17422026/09/10 09:07:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures17432026/09/10 09:07:32 INFO Garbage collection started17442026/09/10 09:07:32 INFO Aborted multipart uploads count=017452026/09/10 09:07:32 WARN Force mode enabled - objects will be deleted immediately without grace period17462026/09/10 09:07:32 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1747=== RUN TestService_RequireScope_OIDC/builder_may_write1748=== PAUSE TestService_RequireScope_OIDC/builder_may_write1749=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1750=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1751=== RUN TestService_RequireScope_OIDC/ops_may_admin1752=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1753=== RUN TestService_RequireScope_OIDC/ops_may_not_write1754=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1755=== RUN TestService_RequireScope_OIDC/reader_may_not_write1756=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1757=== RUN TestService_RequireScope_OIDC/static_token_may_admin1758=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1759=== RUN TestService_RequireScope_OIDC/static_token_may_write1760=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1761=== RUN TestService_RequireScope_OIDC/reader_may_read1762=== PAUSE TestService_RequireScope_OIDC/reader_may_read1763=== RUN TestService_RequireScope_OIDC/writer_implies_read1764=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1765=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1766=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1767=== CONT TestService_RequireScope_OIDC/builder_may_write1768=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1769=== CONT TestService_RequireScope_OIDC/ops_may_not_write17702026/09/10 09:07:32 INFO OIDC auth successful provider=test scopes=[write]1771=== CONT TestService_RequireScope_OIDC/static_token_may_admin17722026/09/10 09:07:32 INFO OIDC auth successful provider=test scopes=[admin]1773=== CONT TestService_RequireScope_OIDC/reader_may_not_write1774=== CONT TestService_RequireScope_OIDC/writer_implies_read17752026/09/10 09:07:32 INFO OIDC auth successful provider=test scopes=[read]1776=== CONT TestService_RequireScope_OIDC/static_token_may_write1777=== CONT TestService_RequireScope_OIDC/reader_may_read17782026/09/10 09:07:32 INFO OIDC auth successful provider=test scopes=[write]17792026/09/10 09:07:32 INFO OIDC auth successful provider=test scopes=[read]1780=== CONT TestService_RequireScope_OIDC/ops_may_admin1781=== CONT TestService_RequireScope_OIDC/builder_may_not_admin17822026/09/10 09:07:32 INFO OIDC auth successful provider=test scopes=[admin]17832026/09/10 09:07:32 INFO OIDC auth successful provider=test scopes=[write]1784--- PASS: TestService_RequireScope_OIDC (0.53s)1785 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1786 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1787 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1788 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1789 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1790 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1791 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1792 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1793 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1794 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)17952026/09/10 09:07:32 INFO Received uploads request method=POST path=/api/pending_closures1796=== NAME TestClientIntegration1797 client_integration_test.go:277: Created store path: /build/TestClientIntegration886676067/002/store/1abnz4xhh0cwaz181v6wfc368agfapnf-test-file.txt17982026-09-10 09:07:32.031 UTC [1701] ERROR: relation "goose_db_version" does not exist at character 3617992026-09-10 09:07:32.031 UTC [1701] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18002026/09/10 09:07:32 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=018012026/09/10 09:07:32 INFO Vacuumed table table=pending_closures18022026/09/10 09:07:32 INFO Vacuumed table table=pending_objects18032026/09/10 09:07:32 INFO Vacuumed table table=multipart_uploads18042026/09/10 09:07:32 INFO Vacuumed table table=closures18052026/09/10 09:07:32 INFO Vacuumed table table=objects18062026-09-10 09:07:32.040 UTC [1705] ERROR: relation "goose_db_version" does not exist at character 3618072026-09-10 09:07:32.040 UTC [1705] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18082026/09/10 09:07:32 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"18092026/09/10 09:07:32 WARN mTLS auth: bound subjects configured but subject DN unavailable18102026/09/10 09:07:32 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1811--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.38s)18122026/09/10 09:07:32 OK 20241026095416_initial_model.sql (7.1ms)18132026/09/10 09:07:32 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)18142026/09/10 09:07:32 INFO Received uploads request method=POST path=/api/pending_closures18152026/09/10 09:07:32 OK 20251218171726_add_pins.sql (2.64ms)18162026/09/10 09:07:32 OK 20260628120000_add_object_size_and_stats.sql (3.25ms)18172026/09/10 09:07:32 goose: successfully migrated database to version: 2026062812000018182026/09/10 09:07:32 OK 20241026095416_initial_model.sql (8.6ms)18192026/09/10 09:07:32 INFO Received uploads request method=POST path=/api/pending_closures18202026/09/10 09:07:32 OK 20251210153512_drop_unused_gin_index.sql (1.38ms)18212026/09/10 09:07:32 OK 1_commit_pending_closure.sql (1.52ms)18222026/09/10 09:07:32 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18232026/09/10 09:07:32 INFO Received uploads request method=POST path=/api/pending_closures18242026/09/10 09:07:32 OK 2_object_stats_trigger.sql (848.4µs)18252026/09/10 09:07:32 goose: up to current file version: 218262026/09/10 09:07:32 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18272026/09/10 09:07:32 INFO Uploading npx1ch7daym8v9d4xffvmqvhym55fxp8-test-file-0.txt (160B)18282026/09/10 09:07:32 INFO Uploading b2h1w9icbwyz58gn35y37bbaf48yx6jk-test-file-1.txt (160B)18292026/09/10 09:07:32 INFO Uploading wsa2ynlwh7hbsgd18x6q1x1z4zs8lgay-test-file-2.txt (160B)18302026/09/10 09:07:32 OK 20251218171726_add_pins.sql (2.44ms)18312026/09/10 09:07:32 OK 20260628120000_add_object_size_and_stats.sql (2.03ms)18322026/09/10 09:07:32 goose: successfully migrated database to version: 2026062812000018332026/09/10 09:07:32 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18342026/09/10 09:07:32 OK 1_commit_pending_closure.sql (1.8ms)18352026/09/10 09:07:32 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18362026/09/10 09:07:32 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18372026/09/10 09:07:32 OK 2_object_stats_trigger.sql (873.67µs)18382026/09/10 09:07:32 goose: up to current file version: 218392026/09/10 09:07:32 WARN Failed to register uploaded object key=b2h1w9icbwyz58gn35y37bbaf48yx6jk.ls error="server returned 404: 404 page not found\n"1840--- PASS: TestReadRedirectNar (0.41s)18412026/09/10 09:07:32 WARN Failed to register uploaded object key=wsa2ynlwh7hbsgd18x6q1x1z4zs8lgay.ls error="server returned 404: 404 page not found\n"18422026/09/10 09:07:32 WARN Failed to register uploaded object key=npx1ch7daym8v9d4xffvmqvhym55fxp8.ls error="server returned 404: 404 page not found\n"18432026/09/10 09:07:32 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18442026/09/10 09:07:32 INFO Signed narinfos id=1 count=118452026/09/10 09:07:32 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18462026/09/10 09:07:32 INFO Signed narinfos id=2 count=118472026/09/10 09:07:32 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign18482026/09/10 09:07:32 INFO Signed narinfos id=3 count=118492026/09/10 09:07:32 INFO Uploading 3 narinfos18502026/09/10 09:07:32 WARN Failed to register uploaded object key=npx1ch7daym8v9d4xffvmqvhym55fxp8.narinfo error="server returned 404: 404 page not found\n"18512026/09/10 09:07:32 WARN Failed to register uploaded object key=b2h1w9icbwyz58gn35y37bbaf48yx6jk.narinfo error="server returned 404: 404 page not found\n"18522026/09/10 09:07:32 WARN Failed to register uploaded object key=wsa2ynlwh7hbsgd18x6q1x1z4zs8lgay.narinfo error="server returned 404: 404 page not found\n"18532026/09/10 09:07:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18542026/09/10 09:07:32 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-config18552026/09/10 09:07:32 INFO Completed upload id=118562026/09/10 09:07:32 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18572026/09/10 09:07:32 INFO Completed upload id=218582026/09/10 09:07:32 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete18592026/09/10 09:07:32 INFO Completed upload id=318602026/09/10 09:07:32 INFO Upload complete. (90ms)1861=== NAME TestClientMultipleUploads1862 client_integration_test.go:350: Uploaded 3 paths in 118.875367ms1863--- PASS: TestReadRedirectKeepsNarinfoProxied (0.25s)1864--- PASS: TestClientMultipleUploads (0.87s)18652026/09/10 09:07:32 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18662026/09/10 09:07:32 INFO Received uploads request method=POST path=/api/pending_closures1867--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.25s)18682026/09/10 09:07:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18692026/09/10 09:07:32 INFO Uploading x0b5zj4hawkp5fh2kfz7m7lymy1nhc82-ca-test (144B)18702026/09/10 09:07:32 WARN Failed to register uploaded object key=log/gbiggzvw4x2jrsdhs9cp0bslr3fx0k2l-ca-test.drv error="server returned 404: 404 page not found\n"18712026/09/10 09:07:32 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18722026/09/10 09:07:32 WARN Failed to register uploaded object key=x0b5zj4hawkp5fh2kfz7m7lymy1nhc82.ls error="server returned 404: 404 page not found\n"18732026/09/10 09:07:32 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18742026/09/10 09:07:32 INFO Signed narinfos id=1 count=118752026/09/10 09:07:32 INFO Uploading 1 narinfos18762026/09/10 09:07:32 WARN Failed to register uploaded object key=x0b5zj4hawkp5fh2kfz7m7lymy1nhc82.narinfo error="server returned 404: 404 page not found\n"18772026/09/10 09:07:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18782026/09/10 09:07:32 INFO Completed upload id=118792026/09/10 09:07:32 INFO Upload complete. (79ms)1880--- PASS: TestReadProxyDisabled (0.27s)1881=== NAME TestClientCADerivations1882 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2040627672/001/store/x0b5zj4hawkp5fh2kfz7m7lymy1nhc82-ca-test1883 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1884 Compression: zstd1885 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1886 NarSize: 1441887 References: 1888 Deriver: /build/TestClientCADerivations2040627672/001/store/gbiggzvw4x2jrsdhs9cp0bslr3fx0k2l-ca-test.drv1889 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1890 client_ca_test.go:185: Checking for realisation files in S3...1891 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1892 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache18932026/09/10 09:07:32 INFO Received uploads request method=POST path=/api/pending_closures18942026/09/10 09:07:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18952026/09/10 09:07:32 INFO Uploading 1abnz4xhh0cwaz181v6wfc368agfapnf-test-file.txt (152B)18962026/09/10 09:07:32 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18972026/09/10 09:07:32 WARN Failed to register uploaded object key=1abnz4xhh0cwaz181v6wfc368agfapnf.ls error="server returned 404: 404 page not found\n"18982026/09/10 09:07:32 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18992026/09/10 09:07:32 INFO Signed narinfos id=1 count=119002026/09/10 09:07:32 INFO Uploading 1 narinfos19012026/09/10 09:07:32 WARN Failed to register uploaded object key=1abnz4xhh0cwaz181v6wfc368agfapnf.narinfo error="server returned 404: 404 page not found\n"19022026/09/10 09:07:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1903--- PASS: TestReadProxyRangeRequest (0.30s)19042026/09/10 09:07:32 INFO Completed upload id=119052026/09/10 09:07:32 INFO Upload complete. (75ms)1906=== NAME TestClientIntegration1907 client_integration_test.go:293: Retrieved narinfo from S3:1908 StorePath: /build/TestClientIntegration886676067/002/store/1abnz4xhh0cwaz181v6wfc368agfapnf-test-file.txt1909 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1910 Compression: zstd1911 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11912 NarSize: 1521913 References: 1914 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11915 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1916 client_integration_test.go:294: Decompressed .ls content (64 bytes):1917 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1918 client_integration_test.go:297: Testing garbage collection...1919--- PASS: TestService_ReadAuthMiddleware (0.32s)1920--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.34s)19212026/09/10 09:07:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures19222026/09/10 09:07:32 INFO Garbage collection started19232026/09/10 09:07:32 INFO Aborted multipart uploads count=019242026/09/10 09:07:32 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=196.844775ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19252026/09/10 09:07:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19262026/09/10 09:07:32 WARN Force mode enabled - objects will be deleted immediately without grace period19272026/09/10 09:07:32 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=019282026/09/10 09:07:32 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NzExOTRjZjUtMGYxNy00NDFhLTk0NmUtZTRlNWNiOTBlZWEzLjY3NjQwYzRlLTdmM2YtNDJiMy1iNTliLTY5NmNlOWExMjNiZHgxNzg5MDMxMjUxNzA2MDI1MjYz parts=1219292026/09/10 09:07:32 INFO Vacuumed table table=pending_closures1930--- PASS: TestRedundantMultipartUpload (1.04s)19312026/09/10 09:07:32 INFO Vacuumed table table=pending_objects19322026/09/10 09:07:32 INFO Vacuumed table table=multipart_uploads19332026/09/10 09:07:32 INFO Vacuumed table table=closures19342026/09/10 09:07:32 INFO Vacuumed table table=objects1935=== NAME TestClientCADerivations1936 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1937 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1938 error: binary cache 's3://bucket37?endpoint=http://localhost:40065®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2040627672/001/store'1939 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11940--- PASS: TestClientCADerivations (1.01s)19412026/09/10 09:07:32 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19422026/09/10 09:07:32 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19432026/09/10 09:07:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19442026/09/10 09:07:32 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NzExOTRjZjUtMGYxNy00NDFhLTk0NmUtZTRlNWNiOTBlZWEzLjE2ZDQyN2QwLThlYzMtNDQ5MS1hYmM4LTU5NGM1NmVhZjEyOHgxNzg5MDMxMjUyMDMwMzk1OTY4 parts=1219452026/09/10 09:07:32 INFO Received uploads request method=POST path=/api/pending_closures1946--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.78s)19472026/09/10 09:07:32 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=364.348542ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1948--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)1949 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)1950 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)1951 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.59s)1952=== NAME TestOrphanedObjectsGCStressTest1953 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1954 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion19552026/09/10 09:07:32 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=731.056149ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1956 orphaned_objects_gc_test.go:509: Stress test completed successfully:1957 orphaned_objects_gc_test.go:510: - Active objects preserved: 201958 orphaned_objects_gc_test.go:511: - Objects deleted: 2101959 orphaned_objects_gc_test.go:512: - Total GC'd: 2101960--- PASS: TestOrphanedObjectsGCStressTest (2.35s)19612026/09/10 09:07:33 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.655385765s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19622026/09/10 09:07:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01963=== NAME TestPinProtectsFromGC1964 client_integration_test.go:711: Pin successfully protected closure from garbage collection1965--- PASS: TestPinProtectsFromGC (2.91s)19662026/09/10 09:07:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01967=== NAME TestClientIntegration1968 client_integration_test.go:304: Objects in database after GC:1969 client_integration_test.go:304: Successfully deleted all objects with GC --force1970--- PASS: TestClientIntegration (2.71s)19712026/09/10 09:07:34 WARN Rate limiter enabled after throttle name=s3-test rate=519722026/09/10 09:07:34 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1973=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1974 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101975 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001976--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.95s)19772026/09/10 09:07:35 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"19782026/09/10 09:07:35 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_closures19792026/09/10 09:07:35 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=196.13825ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19802026/09/10 09:07:35 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=430.371522ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19812026/09/10 09:07:35 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=729.85418ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19822026/09/10 09:07:36 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.518852737s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1983--- PASS: TestClientErrorHandling (0.00s)1984 --- PASS: TestClientErrorHandling/InvalidStorePath (0.24s)1985 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.34s)1986 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.17s)19872026/09/10 09:07:38 INFO Aborted multipart uploads count=019882026/09/10 09:07:43 INFO Aborted multipart uploads count=019892026/09/10 09:07:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=2500 objects-failed-to-delete=019902026/09/10 09:07:49 INFO Vacuumed table table=pending_closures19912026/09/10 09:07:49 INFO Vacuumed table table=pending_objects19922026/09/10 09:07:49 INFO Vacuumed table table=multipart_uploads19932026/09/10 09:07:49 INFO Vacuumed table table=closures19942026/09/10 09:07:49 INFO Vacuumed table table=objects1995--- PASS: TestOrphanedObjectsGCDeletesEachKeyOnce (18.11s)19962026/09/10 09:07:59 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1500 objects-failed-to-delete=019972026/09/10 09:07:59 INFO Vacuumed table table=pending_closures19982026/09/10 09:07:59 INFO Vacuumed table table=pending_objects19992026/09/10 09:07:59 INFO Vacuumed table table=multipart_uploads20002026/09/10 09:07:59 INFO Vacuumed table table=closures20012026/09/10 09:07:59 INFO Vacuumed table table=objects2002--- PASS: TestOrphanedObjectsGCFallsBackToSingleDeletes (28.38s)2003PASS2004{"timestamp":"2026-09-10T09:07:59.441476632Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:37316","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1866,"threadName":"rustfs-worker","threadId":"ThreadId(758)"}20052026-09-10 09:08:00.572 UTC [112] LOG: received smart shutdown request20062026-09-10 09:08:00.579 UTC [112] LOG: background worker "logical replication launcher" (PID 122) exited with exit code 120072026-09-10 09:08:00.593 UTC [117] LOG: shutting down20082026-09-10 09:08:00.594 UTC [117] LOG: checkpoint starting: shutdown immediate20092026-09-10 09:08:01.686 UTC [117] LOG: checkpoint complete: wrote 11047 buffers (67.4%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=0.190 s, sync=0.889 s, total=1.093 s; sync files=17803, longest=0.003 s, average=0.001 s; distance=246838 kB, estimate=246838 kB; lsn=0/10873750, redo lsn=0/1087375020102026-09-10 09:08:01.764 UTC [112] LOG: database system is shut down2011Running OIDC tests...2012=== RUN TestGlobMatch2013=== PAUSE TestGlobMatch2014=== RUN TestAudienceForIssuer2015=== PAUSE TestAudienceForIssuer2016=== RUN TestValidateToken_ValidToken2017=== PAUSE TestValidateToken_ValidToken2018=== RUN TestValidateToken_WrongAudience2019=== PAUSE TestValidateToken_WrongAudience2020=== RUN TestValidateToken_Expired2021=== PAUSE TestValidateToken_Expired2022=== RUN TestValidateToken_BoundClaimsMismatch2023=== PAUSE TestValidateToken_BoundClaimsMismatch2024=== RUN TestValidateToken_BoundSubjectMismatch2025=== PAUSE TestValidateToken_BoundSubjectMismatch2026=== RUN TestValidateToken_MultipleProviders2027=== PAUSE TestValidateToken_MultipleProviders2028=== RUN TestValidateToken_NoMatchingProvider2029=== PAUSE TestValidateToken_NoMatchingProvider2030=== RUN TestValidateToken_KubernetesServiceAccount2031=== PAUSE TestValidateToken_KubernetesServiceAccount2032=== RUN TestNewValidator_KubernetesRequiresCA2033=== PAUSE TestNewValidator_KubernetesRequiresCA2034=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2035=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2036=== RUN TestScopes_LegacyProviderDefaultsToWrite2037=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2038=== RUN TestScopes_Rules2039=== PAUSE TestScopes_Rules2040=== RUN TestScopes_ConfigValidation2041=== PAUSE TestScopes_ConfigValidation2042=== CONT TestGlobMatch2043=== RUN TestGlobMatch/foo_foo2044=== PAUSE TestGlobMatch/foo_foo2045=== CONT TestValidateToken_ValidToken2046=== CONT TestValidateToken_BoundSubjectMismatch2047=== RUN TestGlobMatch/foo_bar2048=== PAUSE TestGlobMatch/foo_bar2049=== CONT TestValidateToken_BoundClaimsMismatch2050=== RUN TestGlobMatch/*_2051=== PAUSE TestGlobMatch/*_2052=== RUN TestGlobMatch/*_anything2053=== PAUSE TestGlobMatch/*_anything2054=== RUN TestGlobMatch/foo*_foo2055=== PAUSE TestGlobMatch/foo*_foo2056=== RUN TestGlobMatch/foo*_foobar2057=== PAUSE TestGlobMatch/foo*_foobar2058=== RUN TestGlobMatch/foo*_bar2059=== PAUSE TestGlobMatch/foo*_bar2060=== RUN TestGlobMatch/*bar_bar2061=== PAUSE TestGlobMatch/*bar_bar2062=== RUN TestGlobMatch/*bar_foobar2063=== PAUSE TestGlobMatch/*bar_foobar2064=== RUN TestGlobMatch/*bar_foo2065=== PAUSE TestGlobMatch/*bar_foo2066=== RUN TestGlobMatch/foo*bar_foobar2067=== PAUSE TestGlobMatch/foo*bar_foobar2068=== RUN TestGlobMatch/foo*bar_foo123bar2069=== PAUSE TestGlobMatch/foo*bar_foo123bar2070=== RUN TestGlobMatch/foo*bar_foobarbaz2071=== PAUSE TestGlobMatch/foo*bar_foobarbaz2072=== CONT TestValidateToken_MultipleProviders2073=== CONT TestAudienceForIssuer2074=== CONT TestValidateToken_Expired2075=== CONT TestScopes_LegacyProviderDefaultsToWrite2076=== CONT TestScopes_ConfigValidation2077=== CONT TestScopes_Rules2078=== CONT TestNewValidator_KubernetesRequiresCA2079=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2080=== CONT TestValidateToken_WrongAudience2081=== CONT TestValidateToken_KubernetesServiceAccount2082=== CONT TestValidateToken_NoMatchingProvider2083=== RUN TestGlobMatch/*/*_foo/bar2084=== PAUSE TestGlobMatch/*/*_foo/bar2085--- PASS: TestAudienceForIssuer (0.00s)2086--- PASS: TestScopes_ConfigValidation (0.00s)2087=== RUN TestGlobMatch/*/*_foo2088=== PAUSE TestGlobMatch/*/*_foo2089=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2090=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2091=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02092=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02093=== RUN TestGlobMatch/refs/*/main_refs/heads/main2094=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2095=== RUN TestGlobMatch/fo?_foo2096=== PAUSE TestGlobMatch/fo?_foo2097=== RUN TestGlobMatch/fo?_fo2098=== PAUSE TestGlobMatch/fo?_fo2099=== RUN TestGlobMatch/fo?_fooo2100=== PAUSE TestGlobMatch/fo?_fooo2101=== RUN TestGlobMatch/?oo_foo2102=== PAUSE TestGlobMatch/?oo_foo2103=== RUN TestGlobMatch/?oo_boo2104=== PAUSE TestGlobMatch/?oo_boo2105=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2106=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2107=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2108=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2109=== CONT TestGlobMatch/foo_foo2110=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2111=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2112=== CONT TestGlobMatch/?oo_boo2113=== CONT TestGlobMatch/foo*bar_foo123bar2114=== CONT TestGlobMatch/foo*_foobar2115=== CONT TestGlobMatch/foo*_bar21162026/09/10 09:08:02 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:45003/oidc2117=== CONT TestGlobMatch/?oo_foo21182026/09/10 09:08:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40007/oidc21192026/09/10 09:08:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41729/oidc2120=== CONT TestGlobMatch/foo*_foo21212026/09/10 09:08:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34935/oidc2122=== CONT TestGlobMatch/fo?_foo21232026/09/10 09:08:02 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:46497/oidc2124=== CONT TestGlobMatch/*/*_foo21252026/09/10 09:08:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42729/oidc2126=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2127=== CONT TestGlobMatch/*/*_foo/bar21282026/09/10 09:08:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32867/oidc2129=== CONT TestGlobMatch/foo*bar_foobarbaz2130=== CONT TestGlobMatch/foo*bar_foobar2131=== CONT TestGlobMatch/*_anything21322026/09/10 09:08:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35221/oidc2133=== CONT TestGlobMatch/*bar_foo2134=== CONT TestGlobMatch/*bar_foobar2135=== CONT TestGlobMatch/foo_bar2136=== CONT TestGlobMatch/refs/*/main_refs/heads/main21372026/09/10 09:08:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41623/oidc2138=== CONT TestGlobMatch/*bar_bar2139=== CONT TestGlobMatch/*_2140=== CONT TestGlobMatch/fo?_fooo2141=== CONT TestGlobMatch/fo?_fo2142=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02143--- PASS: TestGlobMatch (0.01s)2144 --- PASS: TestGlobMatch/foo_foo (0.00s)2145 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2146 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2147 --- PASS: TestGlobMatch/?oo_boo (0.00s)2148 --- PASS: TestGlobMatch/foo*_bar (0.00s)2149 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2150 --- PASS: TestGlobMatch/foo*_foo (0.00s)2151 --- PASS: TestGlobMatch/?oo_foo (0.00s)2152 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2153 --- PASS: TestGlobMatch/fo?_foo (0.00s)2154 --- PASS: TestGlobMatch/*/*_foo (0.00s)2155 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2156 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2157 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2158 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2159 --- PASS: TestGlobMatch/*_anything (0.00s)2160 --- PASS: TestGlobMatch/*bar_foo (0.00s)2161 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2162 --- PASS: TestGlobMatch/foo_bar (0.00s)2163 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2164 --- PASS: TestGlobMatch/*bar_bar (0.00s)2165 --- PASS: TestGlobMatch/*_ (0.00s)2166 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2167 --- PASS: TestGlobMatch/fo?_fo (0.00s)2168 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)21692026/09/10 09:08:02 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:34789/oidc21702026/09/10 09:08:02 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232171--- PASS: TestValidateToken_Expired (0.01s)2172--- PASS: TestValidateToken_WrongAudience (0.01s)2173--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2174--- PASS: TestValidateToken_ValidToken (0.02s)2175--- PASS: TestValidateToken_BoundClaimsMismatch (0.02s)21762026/09/10 09:08:02 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:391032177--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2178--- PASS: TestValidateToken_MultipleProviders (0.02s)2179--- PASS: TestValidateToken_BoundSubjectMismatch (0.02s)2180--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.02s)2181--- PASS: TestScopes_Rules (0.02s)2182--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)21832026/09/10 09:08:02 http: TLS handshake error from 127.0.0.1:42998: remote error: tls: bad certificate2184--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2185PASS2186Running hook tests...2187=== RUN TestSendPathsEmpty2188=== PAUSE TestSendPathsEmpty2189=== RUN TestQueueEnqueueAndFetch2190=== PAUSE TestQueueEnqueueAndFetch2191=== RUN TestQueueDeduplication2192=== PAUSE TestQueueDeduplication2193=== RUN TestQueueRemove2194=== PAUSE TestQueueRemove2195=== RUN TestQueueFetchBatchLimit2196=== PAUSE TestQueueFetchBatchLimit2197=== RUN TestQueueRetryMovesToBack2198=== PAUSE TestQueueRetryMovesToBack2199=== RUN TestQueueFetchRemoveLifecycle2200=== PAUSE TestQueueFetchRemoveLifecycle2201=== RUN TestQueueConcurrentWriters2202=== PAUSE TestQueueConcurrentWriters2203=== RUN TestQueueRemoveLargeClosure2204=== PAUSE TestQueueRemoveLargeClosure2205=== RUN TestServerClientIntegration2206=== PAUSE TestServerClientIntegration2207=== RUN TestServerQueueError2208=== PAUSE TestServerQueueError2209=== RUN TestGetListenerSocketActivation2210 server_test.go:210: === RUN TestGetListenerSocketActivation2211 --- PASS: TestGetListenerSocketActivation (0.00s)2212 PASS2213 2214--- PASS: TestGetListenerSocketActivation (0.01s)2215=== RUN TestDrainIsolatesPoisonPath2216=== PAUSE TestDrainIsolatesPoisonPath2217=== RUN TestRunNotBlockedByPoisonHead2218=== PAUSE TestRunNotBlockedByPoisonHead2219=== RUN TestDrainGivesUpWhenServerDown2220=== PAUSE TestDrainGivesUpWhenServerDown2221=== RUN TestFailedPathPrunedByLaterClosure2222=== PAUSE TestFailedPathPrunedByLaterClosure2223=== RUN TestWorkerUploadsAndRemoves2224=== PAUSE TestWorkerUploadsAndRemoves2225=== RUN TestWorkerSkipsGCdPaths2226=== PAUSE TestWorkerSkipsGCdPaths2227=== RUN TestWorkerPrunesClosureDeps2228=== PAUSE TestWorkerPrunesClosureDeps2229=== RUN TestDrainTimeout2230=== PAUSE TestDrainTimeout2231=== CONT TestSendPathsEmpty2232=== CONT TestServerQueueError2233=== CONT TestRunNotBlockedByPoisonHead2234--- PASS: TestSendPathsEmpty (0.00s)2235=== CONT TestQueueFetchBatchLimit2236=== CONT TestQueueRemove2237=== CONT TestQueueDeduplication2238=== CONT TestQueueEnqueueAndFetch2239=== CONT TestQueueRemoveLargeClosure2240=== CONT TestQueueRetryMovesToBack2241=== CONT TestQueueConcurrentWriters2242=== CONT TestServerClientIntegration2243=== CONT TestWorkerUploadsAndRemoves2244=== CONT TestDrainTimeout22452026/09/10 09:08:02 ERROR Failed to queue paths error="permission denied" count=12246=== CONT TestWorkerPrunesClosureDeps2247=== CONT TestQueueFetchRemoveLifecycle2248=== CONT TestWorkerSkipsGCdPaths2249--- PASS: TestServerQueueError (0.00s)2250=== CONT TestFailedPathPrunedByLaterClosure2251=== CONT TestDrainGivesUpWhenServerDown2252=== CONT TestDrainIsolatesPoisonPath2253--- PASS: TestServerClientIntegration (0.00s)22542026/09/10 09:08:02 INFO Upload queue status pending=222552026/09/10 09:08:02 INFO Uploading batch count=12256--- PASS: TestQueueRetryMovesToBack (0.01s)22572026/09/10 09:08:02 INFO Upload queue status pending=22258--- PASS: TestQueueFetchBatchLimit (0.01s)22592026/09/10 09:08:02 INFO Uploading batch count=222602026/09/10 09:08:02 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1066132775/002/nonexistent2261--- PASS: TestQueueEnqueueAndFetch (0.01s)22622026/09/10 09:08:02 INFO Uploading batch count=122632026/09/10 09:08:02 ERROR Upload failed error="upload failed" count=122642026/09/10 09:08:02 INFO Uploading batch count=122652026/09/10 09:08:02 INFO Upload queue status pending=322662026/09/10 09:08:02 INFO Uploading batch count=122672026/09/10 09:08:02 ERROR Upload failed error="upload failed" count=122682026/09/10 09:08:02 INFO Uploading batch count=222692026/09/10 09:08:02 ERROR Upload failed error="upload failed" count=222702026/09/10 09:08:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1064254406/002/a22712026/09/10 09:08:02 INFO Uploading batch count=422722026/09/10 09:08:02 ERROR Upload failed error="upload failed" count=422732026/09/10 09:08:02 INFO Upload queue status pending=22274--- PASS: TestQueueDeduplication (0.02s)2275--- PASS: TestQueueFetchRemoveLifecycle (0.01s)22762026/09/10 09:08:02 INFO Uploading batch count=222772026/09/10 09:08:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1064254406/002/b22782026/09/10 09:08:02 INFO Uploading batch count=122792026/09/10 09:08:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath754740045/002/bbb2280--- PASS: TestQueueRemove (0.02s)22812026/09/10 09:08:02 INFO Uploading batch count=122822026/09/10 09:08:02 INFO Uploading batch count=222832026/09/10 09:08:02 ERROR Upload failed error="upload failed" count=222842026/09/10 09:08:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1064254406/002/c22852026/09/10 09:08:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1064254406/002/d22862026/09/10 09:08:02 INFO Uploading batch count=222872026/09/10 09:08:02 INFO Uploading batch count=122882026/09/10 09:08:02 ERROR Upload failed error="upload failed" count=122892026/09/10 09:08:02 ERROR Upload failed error="upload failed" count=222902026/09/10 09:08:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1064254406/002/e22912026/09/10 09:08:02 INFO Uploading batch count=12292--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)22932026/09/10 09:08:02 ERROR Upload failed error="upload failed" count=122942026/09/10 09:08:02 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1064254406/002/f22952026/09/10 09:08:02 INFO Uploading batch count=122962026/09/10 09:08:02 ERROR Upload failed error="upload failed" count=122972026/09/10 09:08:02 ERROR Drain finished with paths left in queue remaining=1022982026/09/10 09:08:02 ERROR Drain finished with paths left in queue remaining=12299--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2300--- PASS: TestDrainIsolatesPoisonPath (0.02s)2301--- PASS: TestWorkerPrunesClosureDeps (0.03s)2302--- PASS: TestWorkerSkipsGCdPaths (0.03s)2303--- PASS: TestWorkerUploadsAndRemoves (0.03s)2304--- PASS: TestQueueRemoveLargeClosure (0.08s)2305--- PASS: TestQueueConcurrentWriters (0.18s)23062026/09/10 09:08:03 ERROR Upload failed error="context deadline exceeded" count=223072026/09/10 09:08:03 ERROR Drain finished with paths left in queue remaining=42308--- PASS: TestDrainTimeout (0.22s)23092026/09/10 09:08:03 INFO Uploading batch count=123102026/09/10 09:08:03 INFO Uploading batch count=123112026/09/10 09:08:03 INFO Uploading batch count=123122026/09/10 09:08:03 ERROR Upload failed error="upload failed" count=123132026/09/10 09:08:03 INFO Uploading batch count=123142026/09/10 09:08:03 ERROR Upload failed error="upload failed" count=123152026/09/10 09:08:03 INFO Uploading batch count=123162026/09/10 09:08:03 ERROR Upload failed error="upload failed" count=123172026/09/10 09:08:03 INFO Uploading batch count=123182026/09/10 09:08:03 ERROR Upload failed error="upload failed" count=123192026/09/10 09:08:03 ERROR Drain finished with paths left in queue remaining=12320--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2321PASS