niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #170
· raw
1tribuchet: building on eliza2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestCaseHackSuffix6=== PAUSE TestCaseHackSuffix7=== RUN TestFilterOversizedClosures8=== PAUSE TestFilterOversizedClosures9=== RUN TestPartSizeForNAR10=== PAUSE TestPartSizeForNAR11=== RUN TestUploadMultipart_SupersededByPeer12=== PAUSE TestUploadMultipart_SupersededByPeer13=== RUN TestDumpPathMatchesNix14=== PAUSE TestDumpPathMatchesNix15=== RUN TestDumpPathSingleFile16=== PAUSE TestDumpPathSingleFile17=== RUN TestDumpPathWriterError18=== PAUSE TestDumpPathWriterError19=== RUN TestEncodeNixBase3220=== PAUSE TestEncodeNixBase3221=== RUN TestEncodeNixBase32WithRealHash22=== PAUSE TestEncodeNixBase32WithRealHash23=== RUN TestConvertHashToNix3224=== PAUSE TestConvertHashToNix3225=== RUN TestGetStorePathHash26=== PAUSE TestGetStorePathHash27=== RUN TestPathInfoHashCompatibility28=== PAUSE TestPathInfoHashCompatibility29=== RUN TestParsePathInfoJSON30=== PAUSE TestParsePathInfoJSON31=== RUN TestParsePathInfoJSONMultiplePaths32=== PAUSE TestParsePathInfoJSONMultiplePaths33=== RUN TestPathInfoCACompatibility34=== PAUSE TestPathInfoCACompatibility35=== RUN TestRateLimiterFeedback36=== PAUSE TestRateLimiterFeedback37=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess38=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess39=== RUN TestResolveStorePath40=== PAUSE TestResolveStorePath41=== RUN TestDoWithRetry_BodyReplayedViaGetBody42=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody43=== RUN TestShellSplit44=== PAUSE TestShellSplit45=== RUN TestShellSplitErrors46=== PAUSE TestShellSplitErrors47=== RUN TestSetClientTLS48=== PAUSE TestSetClientTLS49=== RUN TestSetClientTLSDoesNotMutateDefaultTransport50=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport51=== RUN TestSetClientTLSErrors52=== PAUSE TestSetClientTLSErrors53=== RUN TestStaticToken54=== PAUSE TestStaticToken55=== RUN TestFileTokenReadsAndCaches56=== PAUSE TestFileTokenReadsAndCaches57=== RUN TestFileTokenMissing58=== PAUSE TestFileTokenMissing59=== RUN TestFileTokenEmpty60=== PAUSE TestFileTokenEmpty61=== RUN TestScriptTokenNoExpiryRerunsEveryCall62=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall63=== RUN TestScriptTokenCachesUntilRefresh64=== PAUSE TestScriptTokenCachesUntilRefresh65=== RUN TestScriptTokenEmptyToken66=== PAUSE TestScriptTokenEmptyToken67=== RUN TestScriptTokenBadJSON68=== PAUSE TestScriptTokenBadJSON69=== RUN TestScriptTokenScriptFails70=== PAUSE TestScriptTokenScriptFails71=== RUN TestScriptTokenEmptyCommand72=== PAUSE TestScriptTokenEmptyCommand73=== CONT TestDoServerRequestAttachesToken74=== CONT TestConvertHashToNix3275=== CONT TestDoWithRetry_BodyReplayedViaGetBody76=== CONT TestEncodeNixBase32WithRealHash77=== RUN TestConvertHashToNix32/SRI_format_to_Nix3278=== CONT TestFileTokenMissing79=== CONT TestParsePathInfoJSON80=== CONT TestResolveStorePath81--- PASS: TestEncodeNixBase32WithRealHash (0.00s)82=== CONT TestRateLimiterFeedback83=== RUN TestRateLimiterFeedback/429_enables_limiter84=== PAUSE TestRateLimiterFeedback/429_enables_limiter85=== RUN TestRateLimiterFeedback/503_enables_limiter86=== CONT TestPathInfoCACompatibility87=== RUN TestPathInfoCACompatibility/null_ca_field88=== PAUSE TestPathInfoCACompatibility/null_ca_field89=== CONT TestParsePathInfoJSONMultiplePaths90=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths91=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths92=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths93=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths94=== CONT TestEncodeNixBase3295--- PASS: TestFileTokenMissing (0.00s)96=== CONT TestDumpPathWriterError97=== RUN TestEncodeNixBase32/test_string_hash98=== CONT TestDumpPathSingleFile99--- PASS: TestResolveStorePath (0.00s)100=== CONT TestUploadMultipart_SupersededByPeer101=== CONT TestScriptTokenEmptyCommand102--- PASS: TestScriptTokenEmptyCommand (0.00s)103=== PAUSE TestEncodeNixBase32/test_string_hash104=== CONT TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestUploadMultipart_SupersededByPeer/exists106=== PAUSE TestUploadMultipart_SupersededByPeer/exists107=== RUN TestUploadMultipart_SupersededByPeer/missing108=== PAUSE TestUploadMultipart_SupersededByPeer/missing109=== CONT TestScriptTokenCachesUntilRefresh110=== CONT TestPartSizeForNAR111=== RUN TestPartSizeForNAR/zero_stays_at_minimum112=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum113=== RUN TestPartSizeForNAR/small_stays_at_minimum114=== PAUSE TestPartSizeForNAR/small_stays_at_minimum115=== CONT TestFilterOversizedClosures116=== RUN TestFilterOversizedClosures/no_limit_keeps_everything117=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything118=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped119=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped120=== RUN TestFilterOversizedClosures/all_closures_skipped121=== PAUSE TestFilterOversizedClosures/all_closures_skipped122=== CONT TestCaseHackSuffix123=== CONT TestFileTokenEmpty124=== CONT TestPathInfoHashCompatibility125=== CONT TestSetClientTLSDoesNotMutateDefaultTransport126=== CONT TestFileTokenReadsAndCaches127=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32128=== CONT TestStaticToken129=== CONT TestSetClientTLSErrors130=== CONT TestScriptTokenEmptyToken131=== RUN TestParsePathInfoJSON/Nix_format132=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess133=== PAUSE TestRateLimiterFeedback/503_enables_limiter134=== RUN TestPathInfoCACompatibility/old_string_format_-_text135=== CONT TestScriptTokenBadJSON136=== CONT TestScriptTokenScriptFails137=== CONT TestDumpPathMatchesNix138=== RUN TestEncodeNixBase32/empty_input139=== PAUSE TestParsePathInfoJSON/Nix_format140=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text1412026/08/29 16:33:31 WARN Rate limiter enabled after throttle name=server-test rate=5142=== RUN TestConvertHashToNix32/already_Nix32_format143=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum144=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum145=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts146=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts147--- PASS: TestStaticToken (0.00s)148=== CONT TestGetStorePathHash149=== PAUSE TestEncodeNixBase32/empty_input150=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter151=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)152=== RUN TestParsePathInfoJSON/Lix_format153=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive154=== PAUSE TestConvertHashToNix32/already_Nix32_format155=== RUN TestConvertHashToNix32/invalid_format156=== PAUSE TestConvertHashToNix32/invalid_format157=== RUN TestGetStorePathHash/valid_store_path158=== PAUSE TestGetStorePathHash/valid_store_path159=== RUN TestGetStorePathHash/basename_without_hyphen_should_error160=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error161=== CONT TestShellSplitErrors162=== RUN TestPartSizeForNAR/1_TiB163--- PASS: TestFileTokenEmpty (0.00s)164--- PASS: TestScriptTokenScriptFails (0.00s)165--- PASS: TestShellSplitErrors (0.00s)166--- PASS: TestFileTokenReadsAndCaches (0.00s)167=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error168=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error169=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error170=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)171=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter172=== PAUSE TestParsePathInfoJSON/Lix_format173=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive174=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths175=== CONT TestShellSplit176=== CONT TestSetClientTLS177=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths1782026/08/29 16:33:31 WARN Rate limiter enabled after throttle name=server-test rate=5179=== CONT TestUploadMultipart_SupersededByPeer/missing1802026/08/29 16:33:31 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:37485181=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error182=== PAUSE TestPartSizeForNAR/1_TiB183=== CONT TestFilterOversizedClosures/no_limit_keeps_everything184=== CONT TestFilterOversizedClosures/all_closures_skipped185=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon186=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter187=== RUN TestParsePathInfoJSON/empty_input188=== RUN TestPathInfoCACompatibility/new_structured_format_-_text189--- PASS: TestShellSplit (0.00s)190=== CONT TestUploadMultipart_SupersededByPeer/exists191=== RUN TestPartSizeForNAR/5_TiB_S3_max_object192--- PASS: TestScriptTokenBadJSON (0.00s)193=== CONT TestConvertHashToNix32/SRI_format_to_Nix32194=== CONT TestEncodeNixBase32/test_string_hash195=== CONT TestConvertHashToNix32/invalid_format196=== CONT TestConvertHashToNix32/already_Nix32_format197--- PASS: TestConvertHashToNix32 (0.01s)198 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)199 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)200 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)201=== CONT TestEncodeNixBase32/empty_input202--- PASS: TestEncodeNixBase32 (0.01s)203 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)204 --- PASS: TestEncodeNixBase32/empty_input (0.00s)205=== CONT TestGetStorePathHash/valid_store_path206=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error207=== CONT TestGetStorePathHash/basename_without_hyphen_should_error208=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error209--- PASS: TestGetStorePathHash (0.00s)210 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)211 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)212 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)213 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)214=== PAUSE TestParsePathInfoJSON/empty_input2152026/08/29 16:33:31 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=50216=== RUN TestParsePathInfoJSON/whitespace_only217=== PAUSE TestParsePathInfoJSON/whitespace_only218=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object219=== RUN TestParsePathInfoJSON/invalid_JSON220=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter221=== RUN TestPartSizeForNAR/capped_at_5_GiB222=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter223=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped224=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter225=== PAUSE TestPartSizeForNAR/capped_at_5_GiB2262026/08/29 16:33:31 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=2000227=== CONT TestRateLimiterFeedback/503_enables_limiter228=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon2292026/08/29 16:33:31 WARN Rate limiter backed off name=server-test rate=5230=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text2312026/08/29 16:33:31 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:37485232=== PAUSE TestParsePathInfoJSON/invalid_JSON233=== CONT TestRateLimiterFeedback/429_enables_limiter234=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts235=== CONT TestParsePathInfoJSON/Nix_format236=== CONT TestParsePathInfoJSON/whitespace_only237=== CONT TestParsePathInfoJSON/invalid_JSON238=== CONT TestParsePathInfoJSON/Lix_format239=== CONT TestPartSizeForNAR/small_stays_at_minimum240=== CONT TestPartSizeForNAR/1_TiB2412026/08/29 16:33:31 WARN Rate limiter enabled after throttle name=server-test rate=5242--- PASS: TestFilterOversizedClosures (0.00s)243 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)244 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)245 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)246--- PASS: TestScriptTokenEmptyToken (0.01s)2472026/08/29 16:33:31 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:37799248=== CONT TestPartSizeForNAR/capped_at_5_GiB249=== CONT TestPartSizeForNAR/zero_stays_at_minimum250=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI251=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method252=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum2532026/08/29 16:33:31 WARN Rate limiter backed off name=server-test rate=5254=== CONT TestPartSizeForNAR/5_TiB_S3_max_object255=== RUN TestSetClientTLSErrors/missing_cert_file256=== CONT TestParsePathInfoJSON/empty_input2572026/08/29 16:33:31 WARN Rate limiter enabled after throttle name=server-test rate=5258=== RUN TestSetClientTLS/rejects_connection_without_client_cert2592026/08/29 16:33:31 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:34341260=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert261--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)262 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)263 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.01s)264--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)265--- PASS: TestDoServerRequestAttachesToken (0.02s)2662026/08/29 16:33:31 WARN Rate limiter backed off name=server-test rate=5267=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI268=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512269--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)270=== PAUSE TestSetClientTLSErrors/missing_cert_file271--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)272=== RUN TestSetClientTLSErrors/missing_key_file273=== PAUSE TestSetClientTLSErrors/missing_key_file274=== RUN TestSetClientTLSErrors/missing_ca_file275=== PAUSE TestSetClientTLSErrors/missing_ca_file276--- PASS: TestPartSizeForNAR (0.01s)277 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)278 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)279 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)280 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)281 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)282 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)283 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)284--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)285 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)286 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)287=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA288=== RUN TestSetClientTLSErrors/invalid_ca_file289=== PAUSE TestSetClientTLSErrors/invalid_ca_file290=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method291=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512292=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)293--- PASS: TestParsePathInfoJSON (0.02s)294 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)295 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)296 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)297 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)298 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)299=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA300=== CONT TestSetClientTLSErrors/missing_cert_file301=== CONT TestSetClientTLSErrors/missing_ca_file302=== CONT TestSetClientTLSErrors/missing_key_file303=== CONT TestSetClientTLSErrors/invalid_ca_file304=== CONT TestPathInfoCACompatibility/null_ca_field305=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive306=== CONT TestPathInfoCACompatibility/new_structured_format_-_text307=== CONT TestPathInfoCACompatibility/old_string_format_-_text308=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method309=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI310=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512311=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon312--- PASS: TestRateLimiterFeedback (0.01s)313 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)314 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)315 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)316 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)317=== RUN TestSetClientTLS/preserves_debug_logging_transport318=== PAUSE TestSetClientTLS/preserves_debug_logging_transport319=== CONT TestSetClientTLS/rejects_connection_without_client_cert320=== CONT TestSetClientTLS/preserves_debug_logging_transport321=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA322--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)323--- PASS: TestPathInfoCACompatibility (0.02s)324 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)325 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)326 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)327 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)328 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)329--- PASS: TestPathInfoHashCompatibility (0.02s)330 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)331 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)332 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)333 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)334--- PASS: TestSetClientTLSErrors (0.02s)335 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)336 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)337 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)338 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)339--- PASS: TestCaseHackSuffix (0.03s)3402026/08/29 16:33:31 http: TLS handshake error from 127.0.0.1:38196: remote error: tls: bad certificate341--- PASS: TestDumpPathSingleFile (0.03s)342--- PASS: TestSetClientTLS (0.01s)343 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)344 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)345 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)346--- PASS: TestDumpPathWriterError (0.04s)347--- PASS: TestDumpPathMatchesNix (0.08s)348--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)349PASS350Running server tests...351The files belonging to this database system will be owned by user "nixbld".352This user must also own the server process.353354The database cluster will be initialized with locale "C".355The default database encoding has accordingly been set to "SQL_ASCII".356The default text search configuration will be set to "english".357358Data page checksums are enabled.359360creating directory /build/postgres1339522463/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/postgres1339522463/data -l logfile start377378/build/postgres1339522463:5432 - no response3792026-08-29 16:33:32.878 UTC [112] LOG: starting PostgreSQL 18.4 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit3802026-08-29 16:33:32.878 UTC [112] LOG: listening on Unix socket "/build/postgres1339522463/.s.PGSQL.5432"3812026-08-29 16:33:32.882 UTC [119] LOG: database system was shut down at 2026-08-29 16:33:32 UTC3822026-08-29 16:33:32.885 UTC [112] LOG: database system is ready to accept connections383/build/postgres1339522463:5432 - accepting connections384=== RUN TestService_AuthMiddleware385=== PAUSE TestService_AuthMiddleware386=== RUN TestService_AuthMiddleware_MTLSProxyHeader387=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader388=== RUN TestService_AuthMiddleware_MTLSBoundSubjects389=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects390=== RUN TestService_ReadAuthMiddleware391=== PAUSE TestService_ReadAuthMiddleware392=== RUN TestService_AuthMiddleware_OIDC393=== PAUSE TestService_AuthMiddleware_OIDC394=== RUN TestService_RequireScope_OIDC395=== PAUSE TestService_RequireScope_OIDC396=== RUN TestService_ReadScope_PublicByDefault397=== PAUSE TestService_ReadScope_PublicByDefault398=== RUN TestCacheConfigHandler399=== PAUSE TestCacheConfigHandler400=== RUN TestCacheStatsHandler401=== PAUSE TestCacheStatsHandler402=== RUN TestClientCADerivations403=== PAUSE TestClientCADerivations404=== RUN TestClientErrorHandling405=== PAUSE TestClientErrorHandling406=== RUN TestClientIntegration407=== PAUSE TestClientIntegration408=== RUN TestClientMultipleUploads409=== PAUSE TestClientMultipleUploads410=== RUN TestClientWithDependencies411=== PAUSE TestClientWithDependencies412=== RUN TestPinProtectsFromGC413=== PAUSE TestPinProtectsFromGC414=== RUN TestResolveDBConnectionString415=== PAUSE TestResolveDBConnectionString416=== RUN TestGCAdvisoryLockBlocksConcurrentRun4172026-08-29 16:33:36.493 UTC [455] ERROR: relation "goose_db_version" does not exist at character 364182026-08-29 16:33:36.493 UTC [455] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4192026/08/29 16:33:36 OK 20241026095416_initial_model.sql (11.59ms)4202026/08/29 16:33:36 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)4212026/08/29 16:33:36 OK 20251218171726_add_pins.sql (3.13ms)4222026/08/29 16:33:36 OK 20260628120000_add_object_size_and_stats.sql (2.94ms)4232026/08/29 16:33:36 goose: successfully migrated database to version: 202606281200004242026/08/29 16:33:36 OK 1_commit_pending_closure.sql (2ms)4252026/08/29 16:33:36 OK 2_object_stats_trigger.sql (843.49µs)4262026/08/29 16:33:36 goose: up to current file version: 2427--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.58s)428=== RUN TestGCBugBareHashReferences429=== PAUSE TestGCBugBareHashReferences430=== RUN TestGCMetrics431=== PAUSE TestGCMetrics432=== RUN TestGCTaskStore_StartNew433=== PAUSE TestGCTaskStore_StartNew434=== RUN TestGCTaskStore_DeduplicateSameParams435=== PAUSE TestGCTaskStore_DeduplicateSameParams436=== RUN TestGCTaskStore_ConflictDifferentParams437=== PAUSE TestGCTaskStore_ConflictDifferentParams438=== RUN TestGCTaskStore_GetEmpty439=== PAUSE TestGCTaskStore_GetEmpty440=== RUN TestGCTaskStore_GetReturnsLatest441=== PAUSE TestGCTaskStore_GetReturnsLatest442=== RUN TestGCTaskStore_CompletedAllowsNewTask443=== PAUSE TestGCTaskStore_CompletedAllowsNewTask444=== RUN TestGCTaskStore_PhaseUpdates445=== PAUSE TestGCTaskStore_PhaseUpdates446=== RUN TestGCTaskStore_Fail447=== PAUSE TestGCTaskStore_Fail448=== RUN TestGracefulShutdownDrainsInflight449=== PAUSE TestGracefulShutdownDrainsInflight450=== RUN TestService_healthCheckHandler451=== PAUSE TestService_healthCheckHandler452=== RUN TestService_readinessHandler453=== PAUSE TestService_readinessHandler454=== RUN TestGenerateLandingPage455=== PAUSE TestGenerateLandingPage456=== RUN TestCacheConfigHandlerMaxNarSize457=== PAUSE TestCacheConfigHandlerMaxNarSize458=== RUN TestCreatePendingClosureRejectsOversizedNAR459=== PAUSE TestCreatePendingClosureRejectsOversizedNAR460=== RUN TestNARDeduplicationMetadataUploadBug461=== PAUSE TestNARDeduplicationMetadataUploadBug462=== RUN TestMetricsInventory463=== PAUSE TestMetricsInventory464=== RUN TestService_NativeMTLS465=== PAUSE TestService_NativeMTLS466=== RUN TestServerTLSConfig467=== PAUSE TestServerTLSConfig468=== RUN TestMultipartCleanup469=== PAUSE TestMultipartCleanup470=== RUN TestObjectStatsTrigger471=== PAUSE TestObjectStatsTrigger472=== RUN TestOrphanedObjectsGC473=== PAUSE TestOrphanedObjectsGC474=== RUN TestOrphanedObjectsGCStressTest475=== PAUSE TestOrphanedObjectsGCStressTest476=== RUN TestResurrectedObjectNotDeleted477=== PAUSE TestResurrectedObjectNotDeleted478=== RUN TestParseSingleRange479=== PAUSE TestParseSingleRange480=== RUN TestIsValidCachePath481=== PAUSE TestIsValidCachePath482=== RUN TestReadProxyNarinfo483=== PAUSE TestReadProxyNarinfo484=== RUN TestReadProxyNarinfoAlreadyDecompressed485=== PAUSE TestReadProxyNarinfoAlreadyDecompressed486=== RUN TestReadProxyNarStreaming487=== PAUSE TestReadProxyNarStreaming488=== RUN TestReadProxy404489=== PAUSE TestReadProxy404490=== RUN TestReadProxyInvalidPath491=== PAUSE TestReadProxyInvalidPath492=== RUN TestReadProxyHead493=== PAUSE TestReadProxyHead494=== RUN TestReadProxyConditionalGet495=== PAUSE TestReadProxyConditionalGet496=== RUN TestReadProxyRootRedirectsToIndexHTML497=== PAUSE TestReadProxyRootRedirectsToIndexHTML498=== RUN TestReadProxyDisabled499=== PAUSE TestReadProxyDisabled500=== RUN TestReadRedirectNar501=== PAUSE TestReadRedirectNar502=== RUN TestReadRedirectKeepsNarinfoProxied503=== PAUSE TestReadRedirectKeepsNarinfoProxied504=== RUN TestReadProxyRangeRequest505=== PAUSE TestReadProxyRangeRequest506=== RUN TestReadRedirectUsesPublicS3URL507=== PAUSE TestReadRedirectUsesPublicS3URL508=== RUN TestRedundantMultipartUpload509=== PAUSE TestRedundantMultipartUpload510=== RUN TestCompleteMultipartUpload_ErrorButObjectExists511=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists512=== RUN TestCompletedNarNotReofferedAcrossClosures513=== PAUSE TestCompletedNarNotReofferedAcrossClosures514=== RUN TestPresignedUploadRegisteredBeforeCommit515=== PAUSE TestPresignedUploadRegisteredBeforeCommit516=== RUN TestService_Rustfstest517=== PAUSE TestService_Rustfstest518=== RUN TestParseSize519=== PAUSE TestParseSize520=== RUN TestSkippedUploadsHandler521=== PAUSE TestSkippedUploadsHandler522=== RUN TestSystemdListenerNotActivated523--- PASS: TestSystemdListenerNotActivated (0.00s)524=== RUN TestWatchdogBeatsWhenHealthy525--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)526=== RUN TestWatchdogSkipsWhenUnhealthy5272026/08/29 16:33:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5282026/08/29 16:33:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5292026/08/29 16:33:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5302026/08/29 16:33:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5312026/08/29 16:33:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5322026/08/29 16:33:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5332026/08/29 16:33:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5342026/08/29 16:33:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5352026/08/29 16:33:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5362026/08/29 16:33:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"537--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)538=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle539=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle540=== RUN TestProxyWriteTimeout541=== PAUSE TestProxyWriteTimeout542=== RUN TestIsValidUploadKey543=== PAUSE TestIsValidUploadKey544=== RUN TestUploadHandlersRejectInvalidKeys545=== PAUSE TestUploadHandlersRejectInvalidKeys546=== RUN TestUploadHandlersRejectOversizedBody547=== PAUSE TestUploadHandlersRejectOversizedBody548=== RUN TestService_cleanupPendingClosuresHandler549=== PAUSE TestService_cleanupPendingClosuresHandler550=== RUN TestService_createPendingClosureHandler551=== PAUSE TestService_createPendingClosureHandler552=== RUN TestService_verifyS3Integrity553=== PAUSE TestService_verifyS3Integrity554=== RUN TestCompleteMultipartUnregistered555=== PAUSE TestCompleteMultipartUnregistered556=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT557=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT558=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT559=== CONT TestMultipartCleanup560=== CONT TestService_AuthMiddleware561=== CONT TestServerTLSConfig562=== RUN TestServerTLSConfig/no_client_CA563=== CONT TestService_NativeMTLS564=== CONT TestMetricsInventory565=== CONT TestNARDeduplicationMetadataUploadBug566=== CONT TestCreatePendingClosureRejectsOversizedNAR567=== CONT TestCacheConfigHandlerMaxNarSize5682026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures569=== CONT TestGenerateLandingPage570=== CONT TestUploadHandlersRejectInvalidKeys571=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info572=== CONT TestService_readinessHandler573=== CONT TestService_healthCheckHandler574=== CONT TestGracefulShutdownDrainsInflight5752026/08/29 16:33:37 INFO Starting HTTP server address=127.0.0.1:35481576=== CONT TestReadProxyRangeRequest577=== CONT TestGCTaskStore_Fail578=== CONT TestGCTaskStore_DeduplicateSameParams579=== CONT TestIsValidUploadKey580=== RUN TestIsValidUploadKey/narinfo581=== CONT TestCompleteMultipartUnregistered582=== CONT TestGCTaskStore_PhaseUpdates583=== CONT TestGCTaskStore_StartNew584=== CONT TestProxyWriteTimeout585=== RUN TestProxyWriteTimeout/narinfo586=== PAUSE TestProxyWriteTimeout/narinfo587=== RUN TestProxyWriteTimeout/1_GiB_nar588=== PAUSE TestProxyWriteTimeout/1_GiB_nar589=== RUN TestProxyWriteTimeout/10_GiB_nar590=== PAUSE TestProxyWriteTimeout/10_GiB_nar591=== RUN TestProxyWriteTimeout/unknown_size592=== PAUSE TestProxyWriteTimeout/unknown_size593=== CONT TestService_verifyS3Integrity594=== CONT TestGCTaskStore_CompletedAllowsNewTask595=== CONT TestService_createPendingClosureHandler596=== CONT TestGCTaskStore_GetReturnsLatest597=== CONT TestService_cleanupPendingClosuresHandler598=== CONT TestGCTaskStore_GetEmpty599=== CONT TestUploadHandlersRejectOversizedBody600=== PAUSE TestServerTLSConfig/no_client_CA601--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)602=== CONT TestGCTaskStore_ConflictDifferentParams603=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info604=== PAUSE TestIsValidUploadKey/narinfo6052026/08/29 16:33:37 INFO Shutdown signal received, draining in-flight requests timeout=10s606=== RUN TestIsValidUploadKey/nar_zst607=== CONT TestCompletedNarNotReofferedAcrossClosures608=== CONT TestGCBugBareHashReferences609=== CONT TestGCMetrics610=== CONT TestCompleteMultipartUpload_ErrorButObjectExists611=== PAUSE TestIsValidUploadKey/nar_zst612=== CONT TestResolveDBConnectionString613--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)614--- PASS: TestGCTaskStore_Fail (0.00s)615--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)616--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)617--- PASS: TestGCTaskStore_StartNew (0.00s)618--- PASS: TestGCTaskStore_GetEmpty (0.00s)619--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)620--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)621--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)622=== RUN TestResolveDBConnectionString/flag_wins623=== PAUSE TestResolveDBConnectionString/flag_wins624=== RUN TestResolveDBConnectionString/file_when_flag_empty625=== PAUSE TestResolveDBConnectionString/file_when_flag_empty626=== RUN TestResolveDBConnectionString/missing_file_is_an_error627=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error628=== RUN TestResolveDBConnectionString/PGHOST_allows_empty629=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty630=== RUN TestResolveDBConnectionString/nothing_configured631=== PAUSE TestResolveDBConnectionString/nothing_configured632=== RUN TestServerTLSConfig/missing_CA_file633=== CONT TestRedundantMultipartUpload634=== PAUSE TestServerTLSConfig/missing_CA_file635=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal636=== RUN TestServerTLSConfig/not_a_PEM_file637=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal638=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key639=== RUN TestIsValidUploadKey/nar_xz640--- PASS: TestGenerateLandingPage (0.01s)641=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key642=== PAUSE TestServerTLSConfig/not_a_PEM_file643=== PAUSE TestIsValidUploadKey/nar_xz644=== RUN TestIsValidUploadKey/nar_plain645=== PAUSE TestIsValidUploadKey/nar_plain646=== RUN TestIsValidUploadKey/listing647=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key648=== CONT TestReadRedirectUsesPublicS3URL649=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key650=== CONT TestClientWithDependencies651=== CONT TestPinProtectsFromGC652=== PAUSE TestIsValidUploadKey/listing653=== RUN TestIsValidUploadKey/build_log654=== PAUSE TestIsValidUploadKey/build_log655=== RUN TestIsValidUploadKey/build_log_home-manager_file656=== PAUSE TestIsValidUploadKey/build_log_home-manager_file657=== RUN TestIsValidUploadKey/build_log_plus_in_name658=== PAUSE TestIsValidUploadKey/build_log_plus_in_name659=== RUN TestIsValidUploadKey/build_log_question_mark660=== PAUSE TestIsValidUploadKey/build_log_question_mark661=== RUN TestIsValidUploadKey/build_log_equals662=== PAUSE TestIsValidUploadKey/build_log_equals663=== RUN TestIsValidUploadKey/realisation664=== PAUSE TestIsValidUploadKey/realisation665=== RUN TestIsValidUploadKey/realisation_plus_in_output666=== PAUSE TestIsValidUploadKey/realisation_plus_in_output667=== RUN TestIsValidUploadKey/nix-cache-info668=== PAUSE TestIsValidUploadKey/nix-cache-info669=== RUN TestIsValidUploadKey/index.html670=== PAUSE TestIsValidUploadKey/index.html671=== RUN TestIsValidUploadKey/narinfo_key,_nar_type672=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type673=== RUN TestIsValidUploadKey/nar_key,_narinfo_type674=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type675=== RUN TestIsValidUploadKey/listing_key,_narinfo_type676=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type677=== RUN TestIsValidUploadKey/traversal678=== PAUSE TestIsValidUploadKey/traversal679=== RUN TestIsValidUploadKey/traversal_nar680=== PAUSE TestIsValidUploadKey/traversal_nar681=== RUN TestIsValidUploadKey/absolute682=== PAUSE TestIsValidUploadKey/absolute683=== RUN TestIsValidUploadKey/empty_key684=== PAUSE TestIsValidUploadKey/empty_key685=== RUN TestIsValidUploadKey/unknown_type686=== PAUSE TestIsValidUploadKey/unknown_type687=== CONT TestService_ReadScope_PublicByDefault688--- PASS: TestGracefulShutdownDrainsInflight (0.07s)689=== CONT TestCacheConfigHandler690=== RUN TestCacheConfigHandler/full_config,_no_issuer691=== PAUSE TestCacheConfigHandler/full_config,_no_issuer692=== RUN TestCacheConfigHandler/no_cache_url_configured693=== PAUSE TestCacheConfigHandler/no_cache_url_configured694=== RUN TestCacheConfigHandler/no_signing_keys695=== PAUSE TestCacheConfigHandler/no_signing_keys696=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator697=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator698=== CONT TestService_RequireScope_OIDC6992026/08/29 16:33:37 INFO OIDC provider initialized name=test7002026-08-29 16:33:37.337 UTC [528] ERROR: relation "goose_db_version" does not exist at character 367012026-08-29 16:33:37.337 UTC [528] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7022026-08-29 16:33:37.338 UTC [529] ERROR: relation "goose_db_version" does not exist at character 367032026-08-29 16:33:37.338 UTC [529] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7042026-08-29 16:33:37.345 UTC [530] ERROR: relation "goose_db_version" does not exist at character 367052026-08-29 16:33:37.345 UTC [530] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC706=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure707=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure7082026-08-29 16:33:37.370 UTC [532] ERROR: relation "goose_db_version" does not exist at character 367092026-08-29 16:33:37.370 UTC [532] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC710=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart711=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart712=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts713=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts714=== CONT TestPresignedUploadRegisteredBeforeCommit7152026-08-29 16:33:37.370 UTC [531] ERROR: relation "goose_db_version" does not exist at character 367162026-08-29 16:33:37.370 UTC [531] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7172026-08-29 16:33:37.407 UTC [537] ERROR: relation "goose_db_version" does not exist at character 367182026-08-29 16:33:37.407 UTC [537] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7192026/08/29 16:33:37 OK 20241026095416_initial_model.sql (60.71ms)7202026/08/29 16:33:37 OK 20241026095416_initial_model.sql (52.13ms)7212026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (5.63ms)7222026/08/29 16:33:37 OK 20241026095416_initial_model.sql (39.56ms)7232026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (6.55ms)7242026/08/29 16:33:37 OK 20241026095416_initial_model.sql (36ms)7252026/08/29 16:33:37 OK 20251218171726_add_pins.sql (9.19ms)7262026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (6.38ms)7272026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (6.49ms)7282026/08/29 16:33:37 OK 20241026095416_initial_model.sql (15.83ms)7292026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (2.86ms)7302026/08/29 16:33:37 OK 20251218171726_add_pins.sql (12.75ms)7312026/08/29 16:33:37 OK 20241026095416_initial_model.sql (42.07ms)7322026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (9.78ms)7332026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200007342026/08/29 16:33:37 OK 20251218171726_add_pins.sql (8.14ms)7352026/08/29 16:33:37 OK 20251218171726_add_pins.sql (6.98ms)7362026-08-29 16:33:37.444 UTC [538] ERROR: relation "goose_db_version" does not exist at character 367372026-08-29 16:33:37.444 UTC [538] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7382026/08/29 16:33:37 OK 20251218171726_add_pins.sql (9.8ms)7392026/08/29 16:33:37 OK 1_commit_pending_closure.sql (9.82ms)7402026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (10.9ms)7412026-08-29 16:33:37.452 UTC [540] ERROR: relation "goose_db_version" does not exist at character 367422026-08-29 16:33:37.452 UTC [540] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7432026-08-29 16:33:37.453 UTC [539] ERROR: relation "goose_db_version" does not exist at character 367442026-08-29 16:33:37.453 UTC [539] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7452026-08-29 16:33:37.453 UTC [541] ERROR: relation "goose_db_version" does not exist at character 367462026-08-29 16:33:37.453 UTC [541] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7472026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (13.68ms)7482026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200007492026/08/29 16:33:37 OK 2_object_stats_trigger.sql (4.87ms)7502026/08/29 16:33:37 goose: up to current file version: 27512026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (8.26ms)7522026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200007532026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (15.17ms)7542026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200007552026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (15.13ms)7562026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200007572026/08/29 16:33:37 OK 1_commit_pending_closure.sql (5.99ms)7582026/08/29 16:33:37 OK 20251218171726_add_pins.sql (8.86ms)7592026/08/29 16:33:37 OK 1_commit_pending_closure.sql (5.35ms)7602026/08/29 16:33:37 OK 1_commit_pending_closure.sql (5.26ms)7612026/08/29 16:33:37 OK 1_commit_pending_closure.sql (7.75ms)7622026/08/29 16:33:37 OK 2_object_stats_trigger.sql (4.54ms)7632026/08/29 16:33:37 goose: up to current file version: 27642026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (6.8ms)7652026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200007662026/08/29 16:33:37 OK 2_object_stats_trigger.sql (4.56ms)7672026/08/29 16:33:37 goose: up to current file version: 27682026/08/29 16:33:37 OK 2_object_stats_trigger.sql (6.36ms)7692026/08/29 16:33:37 goose: up to current file version: 27702026/08/29 16:33:37 OK 2_object_stats_trigger.sql (3.36ms)7712026/08/29 16:33:37 goose: up to current file version: 27722026-08-29 16:33:37.471 UTC [542] ERROR: relation "goose_db_version" does not exist at character 367732026-08-29 16:33:37.471 UTC [542] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7742026/08/29 16:33:37 OK 1_commit_pending_closure.sql (6.35ms)7752026-08-29 16:33:37.480 UTC [543] ERROR: relation "goose_db_version" does not exist at character 367762026-08-29 16:33:37.480 UTC [543] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7772026-08-29 16:33:37.481 UTC [544] ERROR: relation "goose_db_version" does not exist at character 367782026-08-29 16:33:37.481 UTC [544] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7792026/08/29 16:33:37 OK 20241026095416_initial_model.sql (22.4ms)7802026-08-29 16:33:37.484 UTC [545] ERROR: relation "goose_db_version" does not exist at character 367812026-08-29 16:33:37.484 UTC [545] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7822026-08-29 16:33:37.485 UTC [546] ERROR: relation "goose_db_version" does not exist at character 367832026-08-29 16:33:37.485 UTC [546] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7842026/08/29 16:33:37 OK 2_object_stats_trigger.sql (12.73ms)7852026/08/29 16:33:37 goose: up to current file version: 27862026/08/29 16:33:37 OK 20241026095416_initial_model.sql (23.05ms)7872026/08/29 16:33:37 OK 20241026095416_initial_model.sql (22.6ms)7882026/08/29 16:33:37 OK 20241026095416_initial_model.sql (23.87ms)7892026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (6.78ms)7902026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.7ms)7912026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.9ms)7922026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.9ms)7932026/08/29 16:33:37 OK 20251218171726_add_pins.sql (7.7ms)7942026-08-29 16:33:37.499 UTC [548] ERROR: relation "goose_db_version" does not exist at character 367952026-08-29 16:33:37.499 UTC [548] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7962026-08-29 16:33:37.499 UTC [551] ERROR: relation "goose_db_version" does not exist at character 367972026-08-29 16:33:37.499 UTC [551] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7982026/08/29 16:33:37 OK 20251218171726_add_pins.sql (7.58ms)7992026/08/29 16:33:37 OK 20251218171726_add_pins.sql (7.8ms)8002026/08/29 16:33:37 OK 20251218171726_add_pins.sql (7.75ms)8012026/08/29 16:33:37 OK 20241026095416_initial_model.sql (11.8ms)8022026-08-29 16:33:37.501 UTC [550] ERROR: relation "goose_db_version" does not exist at character 368032026-08-29 16:33:37.501 UTC [550] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8042026-08-29 16:33:37.501 UTC [549] ERROR: relation "goose_db_version" does not exist at character 368052026-08-29 16:33:37.501 UTC [549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8062026-08-29 16:33:37.502 UTC [547] ERROR: relation "goose_db_version" does not exist at character 368072026-08-29 16:33:37.502 UTC [547] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8082026-08-29 16:33:37.504 UTC [552] ERROR: relation "goose_db_version" does not exist at character 368092026-08-29 16:33:37.504 UTC [552] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8102026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (7.04ms)8112026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200008122026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.48ms)8132026-08-29 16:33:37.506 UTC [553] ERROR: relation "goose_db_version" does not exist at character 368142026-08-29 16:33:37.506 UTC [553] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8152026-08-29 16:33:37.507 UTC [554] ERROR: relation "goose_db_version" does not exist at character 368162026-08-29 16:33:37.507 UTC [554] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8172026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (6.85ms)8182026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200008192026/08/29 16:33:37 OK 20241026095416_initial_model.sql (12.68ms)8202026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (6.79ms)8212026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200008222026/08/29 16:33:37 OK 20241026095416_initial_model.sql (12.14ms)8232026-08-29 16:33:37.508 UTC [555] ERROR: relation "goose_db_version" does not exist at character 368242026-08-29 16:33:37.508 UTC [555] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8252026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (8.59ms)8262026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200008272026/08/29 16:33:37 OK 20241026095416_initial_model.sql (16.02ms)8282026/08/29 16:33:37 OK 20241026095416_initial_model.sql (16.1ms)8292026/08/29 16:33:37 OK 1_commit_pending_closure.sql (4.4ms)8302026/08/29 16:33:37 OK 20251218171726_add_pins.sql (4.18ms)8312026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (2.87ms)8322026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (2.8ms)8332026/08/29 16:33:37 OK 1_commit_pending_closure.sql (2.53ms)8342026/08/29 16:33:37 OK 1_commit_pending_closure.sql (2.77ms)8352026/08/29 16:33:37 OK 2_object_stats_trigger.sql (3.17ms)8362026/08/29 16:33:37 goose: up to current file version: 28372026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.08ms)8382026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.13ms)8392026/08/29 16:33:37 OK 2_object_stats_trigger.sql (3.84ms)8402026/08/29 16:33:37 goose: up to current file version: 28412026/08/29 16:33:37 OK 2_object_stats_trigger.sql (4.09ms)8422026/08/29 16:33:37 goose: up to current file version: 28432026/08/29 16:33:37 OK 1_commit_pending_closure.sql (5.22ms)8442026/08/29 16:33:37 OK 20251218171726_add_pins.sql (4.23ms)8452026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (6.1ms)8462026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200008472026/08/29 16:33:37 OK 20251218171726_add_pins.sql (5.84ms)8482026/08/29 16:33:37 OK 2_object_stats_trigger.sql (2.92ms)8492026/08/29 16:33:37 goose: up to current file version: 28502026/08/29 16:33:37 OK 20251218171726_add_pins.sql (5.58ms)8512026/08/29 16:33:37 OK 20251218171726_add_pins.sql (5.74ms)8522026/08/29 16:33:37 OK 1_commit_pending_closure.sql (4.58ms)8532026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (5.71ms)8542026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200008552026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (5.99ms)8562026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200008572026/08/29 16:33:37 OK 2_object_stats_trigger.sql (3.49ms)8582026/08/29 16:33:37 goose: up to current file version: 28592026/08/29 16:33:37 OK 20241026095416_initial_model.sql (14.06ms)8602026/08/29 16:33:37 OK 20241026095416_initial_model.sql (16.03ms)8612026/08/29 16:33:37 OK 20241026095416_initial_model.sql (13.91ms)8622026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (7.01ms)8632026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200008642026/08/29 16:33:37 OK 20241026095416_initial_model.sql (18.29ms)8652026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (7.4ms)8662026/08/29 16:33:37 OK 20241026095416_initial_model.sql (13.66ms)8672026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200008682026/08/29 16:33:37 OK 1_commit_pending_closure.sql (4.08ms)8692026/08/29 16:33:37 OK 20241026095416_initial_model.sql (15.14ms)8702026/08/29 16:33:37 OK 20241026095416_initial_model.sql (15.34ms)8712026/08/29 16:33:37 OK 20241026095416_initial_model.sql (10.87ms)8722026/08/29 16:33:37 OK 1_commit_pending_closure.sql (5.38ms)8732026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.46ms)8742026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.37ms)8752026/08/29 16:33:37 OK 1_commit_pending_closure.sql (4.13ms)8762026/08/29 16:33:37 OK 2_object_stats_trigger.sql (4.14ms)8772026/08/29 16:33:37 goose: up to current file version: 28782026/08/29 16:33:37 OK 2_object_stats_trigger.sql (3.98ms)8792026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.34ms)8802026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.65ms)8812026/08/29 16:33:37 goose: up to current file version: 28822026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (5.81ms)8832026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.37ms)8842026/08/29 16:33:37 OK 20241026095416_initial_model.sql (14.9ms)8852026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.51ms)8862026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.33ms)8872026/08/29 16:33:37 OK 1_commit_pending_closure.sql (5.5ms)8882026/08/29 16:33:37 OK 20251218171726_add_pins.sql (3.64ms)8892026/08/29 16:33:37 OK 2_object_stats_trigger.sql (3.69ms)8902026/08/29 16:33:37 goose: up to current file version: 28912026/08/29 16:33:37 OK 2_object_stats_trigger.sql (2.5ms)8922026/08/29 16:33:37 goose: up to current file version: 28932026/08/29 16:33:37 OK 20251218171726_add_pins.sql (5.08ms)8942026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (3.56ms)8952026/08/29 16:33:37 OK 20251218171726_add_pins.sql (3.89ms)8962026/08/29 16:33:37 OK 20251218171726_add_pins.sql (4.16ms)8972026/08/29 16:33:37 OK 20251218171726_add_pins.sql (4.03ms)8982026/08/29 16:33:37 OK 20251218171726_add_pins.sql (5.13ms)8992026/08/29 16:33:37 OK 20251218171726_add_pins.sql (7.35ms)9002026/08/29 16:33:37 OK 20251218171726_add_pins.sql (7.62ms)9012026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (6.44ms)9022026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (4.44ms)9032026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200009042026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200009052026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (4.36ms)9062026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200009072026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (5.04ms)9082026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200009092026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (3.59ms)9102026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200009112026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (4.59ms)9122026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200009132026/08/29 16:33:37 OK 20251218171726_add_pins.sql (4.81ms)9142026/08/29 16:33:37 OK 1_commit_pending_closure.sql (2.97ms)9152026/08/29 16:33:37 OK 1_commit_pending_closure.sql (3.13ms)9162026/08/29 16:33:37 OK 1_commit_pending_closure.sql (3.25ms)9172026/08/29 16:33:37 OK 1_commit_pending_closure.sql (3.14ms)9182026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (4.43ms)9192026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200009202026/08/29 16:33:37 OK 1_commit_pending_closure.sql (3.09ms)9212026/08/29 16:33:37 OK 1_commit_pending_closure.sql (3.35ms)9222026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (4.38ms)9232026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200009242026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (3.59ms)9252026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200009262026/08/29 16:33:37 OK 2_object_stats_trigger.sql (681.71µs)9272026/08/29 16:33:37 goose: up to current file version: 29282026/08/29 16:33:37 OK 2_object_stats_trigger.sql (1.13ms)9292026/08/29 16:33:37 goose: up to current file version: 29302026/08/29 16:33:37 OK 2_object_stats_trigger.sql (804.41µs)9312026/08/29 16:33:37 goose: up to current file version: 29322026/08/29 16:33:37 OK 2_object_stats_trigger.sql (993.65µs)9332026/08/29 16:33:37 goose: up to current file version: 29342026/08/29 16:33:37 OK 2_object_stats_trigger.sql (935.87µs)9352026/08/29 16:33:37 goose: up to current file version: 29362026/08/29 16:33:37 OK 2_object_stats_trigger.sql (948.83µs)9372026/08/29 16:33:37 goose: up to current file version: 29382026/08/29 16:33:37 OK 1_commit_pending_closure.sql (1.89ms)9392026/08/29 16:33:37 OK 1_commit_pending_closure.sql (1.61ms)9402026/08/29 16:33:37 OK 1_commit_pending_closure.sql (2.23ms)9412026/08/29 16:33:37 OK 2_object_stats_trigger.sql (818.39µs)9422026/08/29 16:33:37 goose: up to current file version: 29432026/08/29 16:33:37 OK 2_object_stats_trigger.sql (920.21µs)9442026/08/29 16:33:37 goose: up to current file version: 29452026/08/29 16:33:37 OK 2_object_stats_trigger.sql (850.41µs)9462026/08/29 16:33:37 goose: up to current file version: 29472026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures948--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.37s)949=== CONT TestService_AuthMiddleware_OIDC9502026/08/29 16:33:37 INFO OIDC provider initialized name=test951--- PASS: TestMetricsInventory (0.43s)952=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle953--- PASS: TestReadProxyRangeRequest (0.43s)954=== CONT TestService_ReadAuthMiddleware9552026/08/29 16:33:37 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9562026/08/29 16:33:37 WARN mTLS auth: subject not in bound subjects subject="CN=reader"957--- PASS: TestService_NativeMTLS (0.44s)958=== CONT TestClientMultipleUploads9592026-08-29 16:33:37.666 UTC [565] ERROR: relation "goose_db_version" does not exist at character 369602026-08-29 16:33:37.666 UTC [565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC961--- PASS: TestService_healthCheckHandler (0.45s)962=== CONT TestSkippedUploadsHandler9632026/08/29 16:33:37 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000964--- PASS: TestSkippedUploadsHandler (0.01s)965=== CONT TestService_AuthMiddleware_MTLSBoundSubjects9662026/08/29 16:33:37 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"967--- PASS: TestService_AuthMiddleware (0.47s)968=== CONT TestClientIntegration9692026/08/29 16:33:37 OK 20241026095416_initial_model.sql (18.71ms)9702026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)9712026/08/29 16:33:37 OK 20251218171726_add_pins.sql (4.18ms)9722026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (6.72ms)9732026/08/29 16:33:37 goose: successfully migrated database to version: 202606281200009742026/08/29 16:33:37 OK 1_commit_pending_closure.sql (3.43ms)9752026/08/29 16:33:37 OK 2_object_stats_trigger.sql (2.35ms)9762026/08/29 16:33:37 goose: up to current file version: 29772026-08-29 16:33:37.719 UTC [571] ERROR: relation "goose_db_version" does not exist at character 369782026-08-29 16:33:37.719 UTC [571] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9792026/08/29 16:33:37 INFO Aborted multipart uploads count=09802026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures9812026/08/29 16:33:37 WARN Force mode enabled - objects will be deleted immediately without grace period9822026/08/29 16:33:37 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=09832026/08/29 16:33:37 INFO Vacuumed table table=pending_closures9842026/08/29 16:33:37 INFO Vacuumed table table=pending_objects9852026-08-29 16:33:37.738 UTC [573] ERROR: relation "goose_db_version" does not exist at character 369862026-08-29 16:33:37.738 UTC [573] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9872026/08/29 16:33:37 INFO Vacuumed table table=multipart_uploads9882026/08/29 16:33:37 INFO Vacuumed table table=closures9892026-08-29 16:33:37.738 UTC [574] ERROR: relation "goose_db_version" does not exist at character 369902026-08-29 16:33:37.738 UTC [574] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9912026/08/29 16:33:37 INFO Vacuumed table table=objects9922026/08/29 16:33:37 OK 20241026095416_initial_model.sql (12.86ms)9932026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (2.73ms)994=== NAME TestNARDeduplicationMetadataUploadBug995 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug420811569/001/store/4wg5yrjmzcjb3qimls7wpd7x4i5ibx1r-file1.txt996--- PASS: TestGCMetrics (0.52s)997=== CONT TestParseSize998--- PASS: TestParseSize (0.00s)999=== CONT TestService_AuthMiddleware_MTLSProxyHeader10002026/08/29 16:33:37 WARN readiness check failed error="closed pool"1001--- PASS: TestService_readinessHandler (0.53s)1002=== CONT TestClientErrorHandling1003=== RUN TestClientErrorHandling/InvalidStorePath1004=== PAUSE TestClientErrorHandling/InvalidStorePath1005=== RUN TestClientErrorHandling/InvalidAuthToken1006=== PAUSE TestClientErrorHandling/InvalidAuthToken1007=== RUN TestClientErrorHandling/ServerNotAvailable1008=== PAUSE TestClientErrorHandling/ServerNotAvailable1009=== CONT TestService_Rustfstest10102026/08/29 16:33:37 OK 20251218171726_add_pins.sql (4.15ms)10112026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (5.19ms)10122026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000010132026/08/29 16:33:37 OK 1_commit_pending_closure.sql (3.09ms)10142026/08/29 16:33:37 OK 20241026095416_initial_model.sql (11.48ms)10152026/08/29 16:33:37 OK 20241026095416_initial_model.sql (12.58ms)10162026/08/29 16:33:37 OK 2_object_stats_trigger.sql (1.88ms)10172026/08/29 16:33:37 goose: up to current file version: 210182026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)10192026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)10202026/08/29 16:33:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10212026/08/29 16:33:37 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1022--- PASS: TestCompleteMultipartUnregistered (0.54s)1023=== CONT TestClientCADerivations10242026-08-29 16:33:37.771 UTC [596] ERROR: relation "goose_db_version" does not exist at character 3610252026-08-29 16:33:37.771 UTC [596] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10262026-08-29 16:33:37.772 UTC [597] ERROR: relation "goose_db_version" does not exist at character 3610272026-08-29 16:33:37.772 UTC [597] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10282026/08/29 16:33:37 OK 20251218171726_add_pins.sql (14.19ms)10292026/08/29 16:33:37 OK 20251218171726_add_pins.sql (16.65ms)10302026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (8.08ms)10312026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000010322026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures10332026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (7.01ms)10342026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000010352026/08/29 16:33:37 OK 1_commit_pending_closure.sql (3.48ms)10362026/08/29 16:33:37 OK 1_commit_pending_closure.sql (3.93ms)10372026/08/29 16:33:37 OK 2_object_stats_trigger.sql (3.22ms)10382026/08/29 16:33:37 goose: up to current file version: 210392026/08/29 16:33:37 OK 2_object_stats_trigger.sql (3.33ms)10402026/08/29 16:33:37 goose: up to current file version: 210412026/08/29 16:33:37 OK 20241026095416_initial_model.sql (14.39ms)10422026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (3.57ms)10432026/08/29 16:33:37 OK 20241026095416_initial_model.sql (16.8ms)10442026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (4.37ms)10452026/08/29 16:33:37 OK 20251218171726_add_pins.sql (7.7ms)10462026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures10472026/08/29 16:33:37 OK 20251218171726_add_pins.sql (5.26ms)10482026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (5.5ms)10492026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000010502026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (4.47ms)10512026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000010522026/08/29 16:33:37 OK 1_commit_pending_closure.sql (4.31ms)10532026/08/29 16:33:37 OK 2_object_stats_trigger.sql (2.25ms)10542026/08/29 16:33:37 goose: up to current file version: 210552026/08/29 16:33:37 OK 1_commit_pending_closure.sql (3.35ms)10562026/08/29 16:33:37 OK 2_object_stats_trigger.sql (2.17ms)10572026/08/29 16:33:37 goose: up to current file version: 210582026/08/29 16:33:37 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10592026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures10602026-08-29 16:33:37.825 UTC [635] ERROR: relation "goose_db_version" does not exist at character 3610612026-08-29 16:33:37.825 UTC [635] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10622026-08-29 16:33:37.831 UTC [638] ERROR: relation "goose_db_version" does not exist at character 3610632026-08-29 16:33:37.831 UTC [638] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10642026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures10652026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures10662026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures10672026/08/29 16:33:37 OK 20241026095416_initial_model.sql (14.44ms)10682026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (1.45ms)10692026/08/29 16:33:37 INFO Received cleanup request method=DELETE path=/api/pending_closures10702026/08/29 16:33:37 OK 20251218171726_add_pins.sql (3.68ms)10712026/08/29 16:33:37 OK 20241026095416_initial_model.sql (11.21ms)10722026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (2.12ms)10732026-08-29 16:33:37.853 UTC [639] ERROR: relation "goose_db_version" does not exist at character 3610742026-08-29 16:33:37.853 UTC [639] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10752026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (3.25ms)10762026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000010772026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures10782026/08/29 16:33:37 INFO Aborted multipart uploads count=010792026/08/29 16:33:37 OK 1_commit_pending_closure.sql (2.81ms)10802026/08/29 16:33:37 OK 20251218171726_add_pins.sql (4.02ms)10812026/08/29 16:33:37 OK 2_object_stats_trigger.sql (1.04ms)10822026/08/29 16:33:37 goose: up to current file version: 210832026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures10842026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (3.3ms)10852026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000010862026/08/29 16:33:37 OK 1_commit_pending_closure.sql (2.16ms)10872026/08/29 16:33:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10882026/08/29 16:33:37 INFO Uploading 4wg5yrjmzcjb3qimls7wpd7x4i5ibx1r-file1.txt (160B)10892026/08/29 16:33:37 OK 2_object_stats_trigger.sql (1.06ms)10902026/08/29 16:33:37 goose: up to current file version: 210912026/08/29 16:33:37 INFO Received uploads request method=POST path=/api/pending_closures10922026/08/29 16:33:37 OK 20241026095416_initial_model.sql (9.07ms)10932026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (1.32ms)10942026/08/29 16:33:37 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10952026/08/29 16:33:37 INFO Received cleanup request method=DELETE path=/api/pending_closures10962026/08/29 16:33:37 OK 20251218171726_add_pins.sql (3.87ms)10972026/08/29 16:33:37 INFO Aborted multipart uploads count=110982026/08/29 16:33:37 WARN Failed to register uploaded object key=4wg5yrjmzcjb3qimls7wpd7x4i5ibx1r.ls error="server returned 404: 404 page not found\n"10992026/08/29 16:33:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11002026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (3.53ms)11012026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000011022026/08/29 16:33:37 INFO Signed narinfos id=1 count=111032026/08/29 16:33:37 INFO Uploading 1 narinfos11042026/08/29 16:33:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11052026/08/29 16:33:37 OK 1_commit_pending_closure.sql (2.13ms)11062026-08-29 16:33:37.882 UTC [543] ERROR: Closure does not exist: id=111072026-08-29 16:33:37.882 UTC [543] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE11082026-08-29 16:33:37.882 UTC [543] STATEMENT: -- name: CommitPendingClosure :exec1109 SELECT commit_pending_closure($1::bigint)1110 1111--- PASS: TestService_cleanupPendingClosuresHandler (0.66s)11122026/08/29 16:33:37 OK 2_object_stats_trigger.sql (1.35ms)1113=== CONT TestReadProxyNarStreaming11142026/08/29 16:33:37 goose: up to current file version: 211152026/08/29 16:33:37 WARN Failed to register uploaded object key=4wg5yrjmzcjb3qimls7wpd7x4i5ibx1r.narinfo error="server returned 404: 404 page not found\n"11162026/08/29 16:33:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1117--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.15s)1118=== CONT TestCacheStatsHandler11192026/08/29 16:33:37 INFO Completed upload id=111202026/08/29 16:33:37 INFO Upload complete. (107ms)1121=== NAME TestNARDeduplicationMetadataUploadBug1122 metadata_upload_test.go:54: Retrieved narinfo from S3:1123 StorePath: /build/TestNARDeduplicationMetadataUploadBug420811569/001/store/4wg5yrjmzcjb3qimls7wpd7x4i5ibx1r-file1.txt1124 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1125 Compression: zstd1126 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1127 NarSize: 1601128 References: 1129 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf11302026/08/29 16:33:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1131 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1132 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1133 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11342026/08/29 16:33:37 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NmU5ZTA1ZDQtMTAwNi00MjUzLWExN2MtNmMxOWFlNDBlNGRhLjBmMGVhMjM2LWRlYTctNDRjZi04YWI1LWFjNThmNWRmOWRlMngxNzg4MDIxMjE3ODcyMDAwMDQw11352026/08/29 16:33:37 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NmU5ZTA1ZDQtMTAwNi00MjUzLWExN2MtNmMxOWFlNDBlNGRhLjBmMGVhMjM2LWRlYTctNDRjZi04YWI1LWFjNThmNWRmOWRlMngxNzg4MDIxMjE3ODcyMDAwMDQw parts=11136--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.69s)1137=== CONT TestParseSingleRange1138=== RUN TestParseSingleRange/none1139=== PAUSE TestParseSingleRange/none1140=== RUN TestParseSingleRange/unknown_unit1141=== PAUSE TestParseSingleRange/unknown_unit1142=== RUN TestParseSingleRange/multi-range_ignored1143=== PAUSE TestParseSingleRange/multi-range_ignored1144=== RUN TestParseSingleRange/malformed_no_dash1145=== PAUSE TestParseSingleRange/malformed_no_dash1146=== RUN TestParseSingleRange/malformed_both_empty1147=== PAUSE TestParseSingleRange/malformed_both_empty1148=== RUN TestParseSingleRange/malformed_end_before_start1149=== PAUSE TestParseSingleRange/malformed_end_before_start1150=== RUN TestParseSingleRange/closed1151=== PAUSE TestParseSingleRange/closed1152=== RUN TestParseSingleRange/open-ended1153=== PAUSE TestParseSingleRange/open-ended1154=== RUN TestParseSingleRange/end_clamped_to_size1155=== PAUSE TestParseSingleRange/end_clamped_to_size1156=== RUN TestParseSingleRange/suffix1157=== PAUSE TestParseSingleRange/suffix1158=== RUN TestParseSingleRange/suffix_exceeds_size1159=== PAUSE TestParseSingleRange/suffix_exceeds_size1160=== RUN TestParseSingleRange/single_byte1161=== PAUSE TestParseSingleRange/single_byte1162=== RUN TestParseSingleRange/start_past_EOF1163=== PAUSE TestParseSingleRange/start_past_EOF1164=== RUN TestParseSingleRange/start_far_past_EOF1165=== PAUSE TestParseSingleRange/start_far_past_EOF1166=== CONT TestReadRedirectKeepsNarinfoProxied1167=== NAME TestNARDeduplicationMetadataUploadBug1168 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug420811569/001/store/pyi74nlbp12sw25p437hy2rdgv02wki7-file2.txt11692026-08-29 16:33:37.965 UTC [681] ERROR: relation "goose_db_version" does not exist at character 3611702026-08-29 16:33:37.965 UTC [681] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11712026-08-29 16:33:37.981 UTC [699] ERROR: relation "goose_db_version" does not exist at character 3611722026-08-29 16:33:37.981 UTC [699] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11732026/08/29 16:33:37 OK 20241026095416_initial_model.sql (13.68ms)11742026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (2.92ms)11752026/08/29 16:33:37 OK 20251218171726_add_pins.sql (3.76ms)11762026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (4.24ms)11772026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000011782026/08/29 16:33:38 OK 1_commit_pending_closure.sql (2.42ms)11792026/08/29 16:33:38 OK 20241026095416_initial_model.sql (12.37ms)11802026/08/29 16:33:38 OK 2_object_stats_trigger.sql (1.14ms)11812026/08/29 16:33:38 goose: up to current file version: 211822026-08-29 16:33:38.002 UTC [701] ERROR: relation "goose_db_version" does not exist at character 3611832026-08-29 16:33:38.002 UTC [701] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11842026/08/29 16:33:38 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)11852026/08/29 16:33:38 OK 20251218171726_add_pins.sql (4.44ms)11862026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (5.2ms)11872026/08/29 16:33:38 goose: successfully migrated database to version: 2026062812000011882026/08/29 16:33:38 OK 1_commit_pending_closure.sql (3.48ms)11892026/08/29 16:33:38 OK 2_object_stats_trigger.sql (1.6ms)11902026/08/29 16:33:38 goose: up to current file version: 211912026/08/29 16:33:38 OK 20241026095416_initial_model.sql (9.7ms)11922026/08/29 16:33:38 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)11932026/08/29 16:33:38 OK 20251218171726_add_pins.sql (3.93ms)11942026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (2.64ms)11952026/08/29 16:33:38 goose: successfully migrated database to version: 2026062812000011962026/08/29 16:33:38 OK 1_commit_pending_closure.sql (1.75ms)11972026/08/29 16:33:38 OK 2_object_stats_trigger.sql (862.19µs)11982026/08/29 16:33:38 goose: up to current file version: 211992026/08/29 16:33:38 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12002026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures12012026/08/29 16:33:38 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12022026/08/29 16:33:38 WARN Failed to register uploaded object key=pyi74nlbp12sw25p437hy2rdgv02wki7.ls error="server returned 404: 404 page not found\n"12032026/08/29 16:33:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12042026/08/29 16:33:38 INFO Signed narinfos id=2 count=112052026/08/29 16:33:38 INFO Uploading 1 narinfos12062026/08/29 16:33:38 WARN Failed to register uploaded object key=pyi74nlbp12sw25p437hy2rdgv02wki7.narinfo error="server returned 404: 404 page not found\n"12072026/08/29 16:33:38 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12082026/08/29 16:33:38 INFO Completed upload id=212092026/08/29 16:33:38 INFO Upload complete. (103ms)1210 metadata_upload_test.go:76: Retrieved narinfo from S3:1211 StorePath: /build/TestNARDeduplicationMetadataUploadBug420811569/001/store/pyi74nlbp12sw25p437hy2rdgv02wki7-file2.txt1212 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1213 Compression: zstd1214 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1215 NarSize: 1601216 References: 1217 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1218 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1219 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1220 {"version":1,"root":{"type":"regular","size":44}}1221--- PASS: TestNARDeduplicationMetadataUploadBug (0.87s)1222=== CONT TestOrphanedObjectsGCStressTest12232026-08-29 16:33:38.166 UTC [739] ERROR: relation "goose_db_version" does not exist at character 3612242026-08-29 16:33:38.166 UTC [739] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12252026/08/29 16:33:38 OK 20241026095416_initial_model.sql (9.83ms)12262026/08/29 16:33:38 OK 20251210153512_drop_unused_gin_index.sql (2.18ms)12272026/08/29 16:33:38 OK 20251218171726_add_pins.sql (2.94ms)12282026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (3.11ms)12292026/08/29 16:33:38 goose: successfully migrated database to version: 2026062812000012302026/08/29 16:33:38 OK 1_commit_pending_closure.sql (1.86ms)12312026/08/29 16:33:38 OK 2_object_stats_trigger.sql (811.43µs)12322026/08/29 16:33:38 goose: up to current file version: 212332026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures1234--- PASS: TestService_ReadScope_PublicByDefault (1.31s)1235=== CONT TestReadProxyNarinfoAlreadyDecompressed12362026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures1237=== RUN TestService_RequireScope_OIDC/builder_may_write1238=== PAUSE TestService_RequireScope_OIDC/builder_may_write1239=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1240=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1241=== RUN TestService_RequireScope_OIDC/ops_may_admin1242=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1243=== RUN TestService_RequireScope_OIDC/ops_may_not_write1244=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1245=== RUN TestService_RequireScope_OIDC/reader_may_not_write1246=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1247=== RUN TestService_RequireScope_OIDC/static_token_may_admin1248=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1249=== RUN TestService_RequireScope_OIDC/static_token_may_write1250=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1251=== RUN TestService_RequireScope_OIDC/reader_may_read1252=== PAUSE TestService_RequireScope_OIDC/reader_may_read1253=== RUN TestService_RequireScope_OIDC/writer_implies_read1254=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1255=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1256=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1257=== CONT TestResurrectedObjectNotDeleted12582026/08/29 16:33:38 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12592026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures1260--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.28s)1261=== CONT TestReadRedirectNar12622026-08-29 16:33:38.665 UTC [766] ERROR: relation "goose_db_version" does not exist at character 3612632026-08-29 16:33:38.665 UTC [766] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1264--- PASS: TestReadRedirectUsesPublicS3URL (1.40s)1265=== CONT TestReadProxyNarinfo12662026/08/29 16:33:38 OK 20241026095416_initial_model.sql (15.54ms)12672026/08/29 16:33:38 OK 20251210153512_drop_unused_gin_index.sql (5.67ms)12682026/08/29 16:33:38 INFO Received cleanup request method=DELETE path=/api/pending_closures12692026/08/29 16:33:38 INFO Aborted multipart uploads count=112702026/08/29 16:33:38 OK 20251218171726_add_pins.sql (10.43ms)1271--- PASS: TestMultipartCleanup (1.50s)1272=== CONT TestIsValidCachePath12732026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (5.44ms)1274=== RUN TestIsValidCachePath/narinfo12752026/08/29 16:33:38 goose: successfully migrated database to version: 202606281200001276=== PAUSE TestIsValidCachePath/narinfo1277=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1278=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1279=== RUN TestIsValidCachePath/nar_zst1280=== PAUSE TestIsValidCachePath/nar_zst1281=== RUN TestIsValidCachePath/nar_xz1282=== PAUSE TestIsValidCachePath/nar_xz1283=== RUN TestIsValidCachePath/nar_bz21284=== PAUSE TestIsValidCachePath/nar_bz21285=== RUN TestIsValidCachePath/nar_uncompressed1286=== PAUSE TestIsValidCachePath/nar_uncompressed1287=== RUN TestIsValidCachePath/ls1288=== PAUSE TestIsValidCachePath/ls1289=== RUN TestIsValidCachePath/log1290=== PAUSE TestIsValidCachePath/log1291=== RUN TestIsValidCachePath/realisation1292=== PAUSE TestIsValidCachePath/realisation1293=== RUN TestIsValidCachePath/nix-cache-info1294=== PAUSE TestIsValidCachePath/nix-cache-info1295=== RUN TestIsValidCachePath/index.html1296=== PAUSE TestIsValidCachePath/index.html1297=== RUN TestIsValidCachePath/traversal_parent1298=== PAUSE TestIsValidCachePath/traversal_parent1299=== RUN TestIsValidCachePath/traversal_in_middle1300=== PAUSE TestIsValidCachePath/traversal_in_middle1301=== RUN TestIsValidCachePath/invalid_char_e1302=== PAUSE TestIsValidCachePath/invalid_char_e1303=== RUN TestIsValidCachePath/invalid_char_u1304=== PAUSE TestIsValidCachePath/invalid_char_u1305=== RUN TestIsValidCachePath/random_path1306=== PAUSE TestIsValidCachePath/random_path1307=== RUN TestIsValidCachePath/empty1308=== PAUSE TestIsValidCachePath/empty1309=== RUN TestIsValidCachePath/leading_slash1310=== PAUSE TestIsValidCachePath/leading_slash1311=== RUN TestIsValidCachePath/wrong_extension1312=== PAUSE TestIsValidCachePath/wrong_extension1313=== RUN TestIsValidCachePath/short_hash1314=== PAUSE TestIsValidCachePath/short_hash1315=== CONT TestReadProxyDisabled13162026/08/29 16:33:38 OK 1_commit_pending_closure.sql (3.54ms)13172026/08/29 16:33:38 OK 2_object_stats_trigger.sql (2.64ms)13182026/08/29 16:33:38 goose: up to current file version: 21319=== NAME TestPinProtectsFromGC1320 client_integration_test.go:648: Pinned store path: /build/TestPinProtectsFromGC2017124409/001/store/hasjycvpmpddbvrrhvz2lmnlbb8jn7g2-pinned-file.txt1321 client_integration_test.go:649: Unpinned store path: /build/TestPinProtectsFromGC2017124409/001/store/pwac9rj1cr2yx1a9v7q2lk38q8n00v84-unpinned-file.txt13222026-08-29 16:33:38.735 UTC [791] ERROR: relation "goose_db_version" does not exist at character 3613232026-08-29 16:33:38.735 UTC [791] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1324=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1325=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1326=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1327=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1328=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1329=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1330=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1331=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1332=== CONT TestReadProxyRootRedirectsToIndexHTML13332026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures13342026/08/29 16:33:38 OK 20241026095416_initial_model.sql (15.99ms)13352026/08/29 16:33:38 OK 20251210153512_drop_unused_gin_index.sql (3.33ms)13362026/08/29 16:33:38 OK 20251218171726_add_pins.sql (4.49ms)13372026-08-29 16:33:38.770 UTC [829] ERROR: relation "goose_db_version" does not exist at character 3613382026-08-29 16:33:38.770 UTC [829] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13392026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (4.71ms)13402026/08/29 16:33:38 goose: successfully migrated database to version: 2026062812000013412026/08/29 16:33:38 OK 1_commit_pending_closure.sql (3.38ms)13422026-08-29 16:33:38.778 UTC [830] ERROR: relation "goose_db_version" does not exist at character 3613432026-08-29 16:33:38.778 UTC [830] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13442026/08/29 16:33:38 OK 2_object_stats_trigger.sql (2.33ms)13452026/08/29 16:33:38 goose: up to current file version: 213462026/08/29 16:33:38 OK 20241026095416_initial_model.sql (15.12ms)13472026/08/29 16:33:38 OK 20241026095416_initial_model.sql (10.66ms)13482026-08-29 16:33:38.797 UTC [849] ERROR: relation "goose_db_version" does not exist at character 3613492026-08-29 16:33:38.797 UTC [849] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13502026/08/29 16:33:38 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13512026/08/29 16:33:38 OK 20251210153512_drop_unused_gin_index.sql (4.16ms)13522026/08/29 16:33:38 OK 20251210153512_drop_unused_gin_index.sql (3.13ms)13532026/08/29 16:33:38 OK 20251218171726_add_pins.sql (5.59ms)13542026/08/29 16:33:38 OK 20251218171726_add_pins.sql (8.95ms)13552026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (6.82ms)13562026/08/29 16:33:38 goose: successfully migrated database to version: 2026062812000013572026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (5.78ms)13582026/08/29 16:33:38 goose: successfully migrated database to version: 2026062812000013592026/08/29 16:33:38 OK 20241026095416_initial_model.sql (9.88ms)13602026/08/29 16:33:38 OK 1_commit_pending_closure.sql (1.99ms)13612026/08/29 16:33:38 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)13622026/08/29 16:33:38 OK 1_commit_pending_closure.sql (2.19ms)13632026/08/29 16:33:38 OK 2_object_stats_trigger.sql (2.61ms)13642026/08/29 16:33:38 goose: up to current file version: 213652026/08/29 16:33:38 OK 2_object_stats_trigger.sql (4.25ms)13662026/08/29 16:33:38 goose: up to current file version: 213672026/08/29 16:33:38 OK 20251218171726_add_pins.sql (4.69ms)1368=== NAME TestClientMultipleUploads1369 client_integration_test.go:339: Created store path 0: /build/TestClientMultipleUploads1536183813/001/store/a2ifgqm614kam5qv9b7wwr8yjf77r0mp-test-file-0.txt13702026-08-29 16:33:38.823 UTC [883] ERROR: relation "goose_db_version" does not exist at character 3613712026-08-29 16:33:38.823 UTC [883] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13722026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (8.14ms)13732026/08/29 16:33:38 goose: successfully migrated database to version: 2026062812000013742026/08/29 16:33:38 OK 1_commit_pending_closure.sql (1.78ms)13752026/08/29 16:33:38 OK 2_object_stats_trigger.sql (845.31µs)13762026/08/29 16:33:38 goose: up to current file version: 21377=== NAME TestClientWithDependencies1378 client_integration_test.go:594: Built derivation: /build/TestClientWithDependencies170311472/001/store/vi2x6rriqsdpy4p3ychqqdrhlqblng33-test-script13792026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures13802026/08/29 16:33:38 OK 20241026095416_initial_model.sql (10.15ms)13812026/08/29 16:33:38 OK 20251210153512_drop_unused_gin_index.sql (4.03ms)13822026/08/29 16:33:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13832026/08/29 16:33:38 INFO Uploading hasjycvpmpddbvrrhvz2lmnlbb8jn7g2-pinned-file.txt (128B)13842026/08/29 16:33:38 OK 20251218171726_add_pins.sql (3.73ms)13852026/08/29 16:33:38 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"13862026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (3.58ms)13872026/08/29 16:33:38 goose: successfully migrated database to version: 2026062812000013882026/08/29 16:33:38 WARN Failed to register uploaded object key=hasjycvpmpddbvrrhvz2lmnlbb8jn7g2.ls error="server returned 404: 404 page not found\n"13892026/08/29 16:33:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13902026/08/29 16:33:38 OK 1_commit_pending_closure.sql (1.7ms)13912026/08/29 16:33:38 INFO Signed narinfos id=1 count=113922026/08/29 16:33:38 INFO Uploading 1 narinfos13932026/08/29 16:33:38 OK 2_object_stats_trigger.sql (972.89µs)13942026/08/29 16:33:38 goose: up to current file version: 213952026/08/29 16:33:38 WARN Failed to register uploaded object key=hasjycvpmpddbvrrhvz2lmnlbb8jn7g2.narinfo error="server returned 404: 404 page not found\n"13962026/08/29 16:33:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13972026/08/29 16:33:38 INFO Completed upload id=11398=== NAME TestClientMultipleUploads1399 client_integration_test.go:339: Created store path 1: /build/TestClientMultipleUploads1536183813/001/store/x2wav0b8z0adv2wlkk2difh7inzp4ivz-test-file-1.txt14002026/08/29 16:33:38 INFO Upload complete. (114ms)14012026/08/29 16:33:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1402=== NAME TestClientWithDependencies1403 client_integration_test.go:596: Found 1 dependencies (including self)1404=== NAME TestClientMultipleUploads1405 client_integration_test.go:339: Created store path 2: /build/TestClientMultipleUploads1536183813/001/store/6161x98gn8n9c5kydxbwxxlvlm2daqv0-test-file-2.txt1406--- PASS: TestGCBugBareHashReferences (1.70s)1407=== CONT TestReadProxyHead14082026/08/29 16:33:38 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14092026/08/29 16:33:38 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14102026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures14112026/08/29 16:33:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14122026/08/29 16:33:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14132026/08/29 16:33:38 INFO Uploading vi2x6rriqsdpy4p3ychqqdrhlqblng33-test-script (136B)14142026/08/29 16:33:38 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NmU5ZTA1ZDQtMTAwNi00MjUzLWExN2MtNmMxOWFlNDBlNGRhLmI0ZTI3NzhiLTE5MDktNDQ2ZC04NGYwLTIwNmRkMDI5NmNlYXgxNzg4MDIxMjE3NzQyMzE1NzI1 parts=1014152026/08/29 16:33:38 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14162026/08/29 16:33:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14172026/08/29 16:33:38 WARN Failed to register uploaded object key=log/rz2qxp151hqi4xmzif0d7gn2y1sqdmmn-test-script.drv error="server returned 404: 404 page not found\n"14182026/08/29 16:33:38 WARN Failed to register uploaded object key=vi2x6rriqsdpy4p3ychqqdrhlqblng33.ls error="server returned 404: 404 page not found\n"14192026/08/29 16:33:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14202026/08/29 16:33:38 INFO Signed narinfos id=1 count=114212026/08/29 16:33:38 INFO Uploading 1 narinfos14222026/08/29 16:33:38 INFO Completed upload id=114232026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures14242026/08/29 16:33:38 WARN Failed to register uploaded object key=vi2x6rriqsdpy4p3ychqqdrhlqblng33.narinfo error="server returned 404: 404 page not found\n"14252026/08/29 16:33:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14262026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures14272026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures14282026/08/29 16:33:38 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14292026/08/29 16:33:38 WARN Found objects in DB but missing from S3, will re-upload count=114302026/08/29 16:33:38 INFO Completed upload id=114312026/08/29 16:33:38 INFO Upload complete. (67ms)1432--- PASS: TestService_verifyS3Integrity (1.76s)1433=== CONT TestObjectStatsTrigger14342026/08/29 16:33:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14352026/08/29 16:33:38 INFO Uploading pwac9rj1cr2yx1a9v7q2lk38q8n00v84-unpinned-file.txt (128B)1436=== NAME TestClientWithDependencies1437 client_integration_test.go:598: Skipping nix copy test - isolated store (/build/TestClientWithDependencies170311472/001/store) requires matching store prefix14382026/08/29 16:33:38 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14392026/08/29 16:33:38 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14402026/08/29 16:33:38 WARN Failed to register uploaded object key=pwac9rj1cr2yx1a9v7q2lk38q8n00v84.ls error="server returned 404: 404 page not found\n"1441--- PASS: TestClientWithDependencies (1.71s)1442=== CONT TestReadProxyInvalidPath14432026/08/29 16:33:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14442026/08/29 16:33:38 INFO Signed narinfos id=2 count=114452026/08/29 16:33:38 INFO Uploading 1 narinfos14462026/08/29 16:33:38 WARN Failed to register uploaded object key=pwac9rj1cr2yx1a9v7q2lk38q8n00v84.narinfo error="server returned 404: 404 page not found\n"14472026/08/29 16:33:38 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14482026-08-29 16:33:38.993 UTC [1098] ERROR: relation "goose_db_version" does not exist at character 3614492026-08-29 16:33:38.993 UTC [1098] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14502026/08/29 16:33:38 INFO Completed upload id=214512026/08/29 16:33:38 INFO Upload complete. (98ms)14522026/08/29 16:33:39 INFO Received uploads request method=POST path=/api/pending_closures14532026/08/29 16:33:39 OK 20241026095416_initial_model.sql (20.02ms)14542026/08/29 16:33:39 OK 20251210153512_drop_unused_gin_index.sql (4.16ms)14552026/08/29 16:33:39 OK 20251218171726_add_pins.sql (4.59ms)14562026/08/29 16:33:39 INFO Received create pin request method=POST path=/api/pins/myapp14572026/08/29 16:33:39 INFO Received uploads request method=POST path=/api/pending_closures14582026/08/29 16:33:39 OK 20260628120000_add_object_size_and_stats.sql (4.46ms)14592026/08/29 16:33:39 goose: successfully migrated database to version: 2026062812000014602026/08/29 16:33:39 INFO Received uploads request method=POST path=/api/pending_closures14612026/08/29 16:33:39 OK 1_commit_pending_closure.sql (2.85ms)14622026/08/29 16:33:39 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14632026/08/29 16:33:39 INFO Uploading x2wav0b8z0adv2wlkk2difh7inzp4ivz-test-file-1.txt (160B)14642026/08/29 16:33:39 INFO Uploading a2ifgqm614kam5qv9b7wwr8yjf77r0mp-test-file-0.txt (160B)14652026/08/29 16:33:39 INFO Uploading 6161x98gn8n9c5kydxbwxxlvlm2daqv0-test-file-2.txt (160B)14662026/08/29 16:33:39 OK 2_object_stats_trigger.sql (1.93ms)14672026/08/29 16:33:39 goose: up to current file version: 214682026/08/29 16:33:39 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2017124409/001/store/hasjycvpmpddbvrrhvz2lmnlbb8jn7g2-pinned-file.txt narinfo_key=hasjycvpmpddbvrrhvz2lmnlbb8jn7g2.narinfo14692026/08/29 16:33:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures14702026/08/29 16:33:39 INFO Garbage collection started14712026-08-29 16:33:39.044 UTC [1138] ERROR: relation "goose_db_version" does not exist at character 3614722026-08-29 16:33:39.044 UTC [1138] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14732026/08/29 16:33:39 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"14742026/08/29 16:33:39 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14752026/08/29 16:33:39 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"14762026/08/29 16:33:39 INFO Aborted multipart uploads count=014772026/08/29 16:33:39 WARN Force mode enabled - objects will be deleted immediately without grace period14782026/08/29 16:33:39 OK 20241026095416_initial_model.sql (9.94ms)14792026/08/29 16:33:39 OK 20251210153512_drop_unused_gin_index.sql (1.4ms)14802026/08/29 16:33:39 OK 20251218171726_add_pins.sql (3ms)14812026-08-29 16:33:39.067 UTC [1140] ERROR: relation "goose_db_version" does not exist at character 3614822026-08-29 16:33:39.067 UTC [1140] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14832026/08/29 16:33:39 OK 20260628120000_add_object_size_and_stats.sql (4.69ms)14842026/08/29 16:33:39 goose: successfully migrated database to version: 2026062812000014852026/08/29 16:33:39 OK 1_commit_pending_closure.sql (1.99ms)14862026/08/29 16:33:39 OK 2_object_stats_trigger.sql (796.23µs)14872026/08/29 16:33:39 goose: up to current file version: 214882026/08/29 16:33:39 OK 20241026095416_initial_model.sql (9.68ms)14892026/08/29 16:33:39 OK 20251210153512_drop_unused_gin_index.sql (1.32ms)14902026/08/29 16:33:39 OK 20251218171726_add_pins.sql (3.05ms)14912026/08/29 16:33:39 OK 20260628120000_add_object_size_and_stats.sql (4.1ms)14922026/08/29 16:33:39 goose: successfully migrated database to version: 2026062812000014932026/08/29 16:33:39 OK 1_commit_pending_closure.sql (1.79ms)14942026/08/29 16:33:39 OK 2_object_stats_trigger.sql (776.55µs)14952026/08/29 16:33:39 goose: up to current file version: 214962026/08/29 16:33:39 WARN Failed to register uploaded object key=6161x98gn8n9c5kydxbwxxlvlm2daqv0.ls error="server returned 404: 404 page not found\n"14972026/08/29 16:33:39 WARN Failed to register uploaded object key=x2wav0b8z0adv2wlkk2difh7inzp4ivz.ls error="server returned 404: 404 page not found\n"14982026/08/29 16:33:39 WARN Failed to register uploaded object key=a2ifgqm614kam5qv9b7wwr8yjf77r0mp.ls error="server returned 404: 404 page not found\n"14992026/08/29 16:33:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign15002026/08/29 16:33:39 INFO Signed narinfos id=3 count=115012026/08/29 16:33:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15022026/08/29 16:33:39 INFO Signed narinfos id=1 count=115032026/08/29 16:33:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15042026/08/29 16:33:39 INFO Signed narinfos id=2 count=115052026/08/29 16:33:39 INFO Uploading 3 narinfos15062026/08/29 16:33:39 WARN Failed to register uploaded object key=a2ifgqm614kam5qv9b7wwr8yjf77r0mp.narinfo error="server returned 404: 404 page not found\n"15072026/08/29 16:33:39 WARN Failed to register uploaded object key=x2wav0b8z0adv2wlkk2difh7inzp4ivz.narinfo error="server returned 404: 404 page not found\n"15082026/08/29 16:33:39 WARN Failed to register uploaded object key=6161x98gn8n9c5kydxbwxxlvlm2daqv0.narinfo error="server returned 404: 404 page not found\n"15092026/08/29 16:33:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15102026/08/29 16:33:39 INFO Completed upload id=115112026/08/29 16:33:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15122026/08/29 16:33:39 INFO Completed upload id=215132026/08/29 16:33:39 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete15142026/08/29 16:33:39 INFO Completed upload id=315152026/08/29 16:33:39 INFO Upload complete. (268ms)1516=== NAME TestClientMultipleUploads1517 client_integration_test.go:350: Uploaded 3 paths in 313.889919ms1518--- PASS: TestClientMultipleUploads (1.58s)1519=== CONT TestReadProxyConditionalGet15202026-08-29 16:33:39.314 UTC [1143] ERROR: relation "goose_db_version" does not exist at character 3615212026-08-29 16:33:39.314 UTC [1143] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15222026/08/29 16:33:39 OK 20241026095416_initial_model.sql (12.62ms)15232026/08/29 16:33:39 OK 20251210153512_drop_unused_gin_index.sql (1.66ms)15242026/08/29 16:33:39 OK 20251218171726_add_pins.sql (3.49ms)15252026/08/29 16:33:39 OK 20260628120000_add_object_size_and_stats.sql (3.41ms)15262026/08/29 16:33:39 goose: successfully migrated database to version: 2026062812000015272026/08/29 16:33:39 OK 1_commit_pending_closure.sql (1.81ms)15282026/08/29 16:33:39 OK 2_object_stats_trigger.sql (769.09µs)15292026/08/29 16:33:39 goose: up to current file version: 215302026/08/29 16:33:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15312026/08/29 16:33:39 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NmU5ZTA1ZDQtMTAwNi00MjUzLWExN2MtNmMxOWFlNDBlNGRhLjJmOTA2NmM1LWU3N2ItNDk1MS05NjFkLWFiNDdmN2Y0NTE1NXgxNzg4MDIxMjE3Nzk0ODA5NjM2 parts=1215322026/08/29 16:33:39 INFO Received uploads request method=POST path=/api/pending_closures1533--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.19s)1534=== CONT TestOrphanedObjectsGC15352026-08-29 16:33:39.486 UTC [1147] ERROR: relation "goose_db_version" does not exist at character 3615362026-08-29 16:33:39.486 UTC [1147] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15372026/08/29 16:33:39 OK 20241026095416_initial_model.sql (9.6ms)15382026/08/29 16:33:39 OK 20251210153512_drop_unused_gin_index.sql (1.28ms)15392026/08/29 16:33:39 OK 20251218171726_add_pins.sql (2.99ms)15402026/08/29 16:33:39 OK 20260628120000_add_object_size_and_stats.sql (3.31ms)15412026/08/29 16:33:39 goose: successfully migrated database to version: 2026062812000015422026/08/29 16:33:39 OK 1_commit_pending_closure.sql (1.83ms)15432026/08/29 16:33:39 OK 2_object_stats_trigger.sql (751.23µs)15442026/08/29 16:33:39 goose: up to current file version: 215452026/08/29 16:33:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15462026/08/29 16:33:39 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NmU5ZTA1ZDQtMTAwNi00MjUzLWExN2MtNmMxOWFlNDBlNGRhLjhjZmU4Mjk1LTQyY2UtNDY2ZS1hYjA1LTc2ZGFjNDk3YzlmMHgxNzg4MDIxMjE3ODQ3MjU2MjY3 parts=1015472026/08/29 16:33:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15482026/08/29 16:33:39 INFO Completed upload id=115492026/08/29 16:33:39 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000015502026/08/29 16:33:39 INFO Received uploads request method=POST path=/api/pending_closures15512026/08/29 16:33:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures15522026/08/29 16:33:39 INFO Aborted multipart uploads count=015532026/08/29 16:33:39 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=015542026/08/29 16:33:39 INFO Vacuumed table table=pending_closures15552026/08/29 16:33:39 INFO Vacuumed table table=pending_objects15562026/08/29 16:33:39 INFO Vacuumed table table=multipart_uploads15572026/08/29 16:33:39 INFO Vacuumed table table=closures15582026/08/29 16:33:39 INFO Vacuumed table table=objects15592026/08/29 16:33:39 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001560--- PASS: TestService_createPendingClosureHandler (2.38s)1561=== CONT TestReadProxy40415622026-08-29 16:33:39.668 UTC [1151] ERROR: relation "goose_db_version" does not exist at character 3615632026-08-29 16:33:39.668 UTC [1151] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15642026/08/29 16:33:39 OK 20241026095416_initial_model.sql (10.86ms)15652026/08/29 16:33:39 OK 20251210153512_drop_unused_gin_index.sql (1.37ms)15662026/08/29 16:33:39 OK 20251218171726_add_pins.sql (3.64ms)15672026/08/29 16:33:39 OK 20260628120000_add_object_size_and_stats.sql (3.05ms)15682026/08/29 16:33:39 goose: successfully migrated database to version: 2026062812000015692026/08/29 16:33:39 OK 1_commit_pending_closure.sql (1.78ms)15702026/08/29 16:33:39 OK 2_object_stats_trigger.sql (796.55µs)15712026/08/29 16:33:39 goose: up to current file version: 215722026/08/29 16:33:39 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=015732026/08/29 16:33:39 INFO Vacuumed table table=pending_closures15742026/08/29 16:33:39 INFO Vacuumed table table=pending_objects15752026/08/29 16:33:39 INFO Vacuumed table table=multipart_uploads15762026/08/29 16:33:39 INFO Vacuumed table table=closures15772026/08/29 16:33:39 INFO Vacuumed table table=objects1578--- PASS: TestService_ReadAuthMiddleware (2.27s)1579=== CONT TestProxyWriteTimeout/narinfo1580=== CONT TestProxyWriteTimeout/10_GiB_nar1581=== CONT TestProxyWriteTimeout/unknown_size1582=== CONT TestProxyWriteTimeout/1_GiB_nar1583--- PASS: TestProxyWriteTimeout (0.00s)1584 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1585 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1586 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1587 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1588=== CONT TestResolveDBConnectionString/flag_wins1589=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1590=== CONT TestResolveDBConnectionString/missing_file_is_an_error1591=== CONT TestResolveDBConnectionString/file_when_flag_empty1592=== CONT TestResolveDBConnectionString/nothing_configured1593=== CONT TestServerTLSConfig/no_client_CA1594=== CONT TestServerTLSConfig/missing_CA_file1595=== CONT TestServerTLSConfig/not_a_PEM_file1596--- PASS: TestResolveDBConnectionString (0.00s)1597 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1598 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1599 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1600 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1601 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1602--- PASS: TestServerTLSConfig (0.07s)1603 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1604 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1605 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1606=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16072026/08/29 16:33:39 INFO Received uploads request method=POST path=/1608=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16092026/08/29 16:33:39 INFO Received complete multipart upload request method=POST path=/1610=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16112026/08/29 16:33:39 INFO Received request for more parts method=POST path=/1612=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16132026/08/29 16:33:39 INFO Received uploads request method=POST path=/1614=== CONT TestIsValidUploadKey/narinfo1615=== CONT TestIsValidUploadKey/empty_key1616=== CONT TestIsValidUploadKey/absolute1617=== CONT TestIsValidUploadKey/traversal_nar1618--- PASS: TestUploadHandlersRejectInvalidKeys (0.06s)1619 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1620 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1621 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1622 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1623=== CONT TestIsValidUploadKey/traversal1624=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1625=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1626=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1627=== CONT TestIsValidUploadKey/index.html1628=== CONT TestIsValidUploadKey/unknown_type1629=== CONT TestIsValidUploadKey/nix-cache-info1630=== CONT TestIsValidUploadKey/realisation_plus_in_output1631=== CONT TestIsValidUploadKey/realisation1632=== CONT TestIsValidUploadKey/build_log_equals1633=== CONT TestIsValidUploadKey/build_log_question_mark1634=== CONT TestIsValidUploadKey/build_log_plus_in_name1635=== CONT TestIsValidUploadKey/build_log_home-manager_file1636=== CONT TestIsValidUploadKey/build_log1637=== CONT TestIsValidUploadKey/listing1638=== CONT TestIsValidUploadKey/nar_plain1639=== CONT TestIsValidUploadKey/nar_xz1640=== CONT TestIsValidUploadKey/nar_zst1641=== CONT TestCacheConfigHandler/full_config,_no_issuer1642--- PASS: TestIsValidUploadKey (0.06s)1643 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1644 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1645 --- PASS: TestIsValidUploadKey/absolute (0.00s)1646 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1647 --- PASS: TestIsValidUploadKey/traversal (0.00s)1648 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1649 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1650 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1651 --- PASS: TestIsValidUploadKey/index.html (0.00s)1652 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1653 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1654 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1655 --- PASS: TestIsValidUploadKey/realisation (0.00s)1656 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1657 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1658 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1659 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1660 --- PASS: TestIsValidUploadKey/build_log (0.00s)1661 --- PASS: TestIsValidUploadKey/listing (0.00s)1662 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1663 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1664 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1665=== CONT TestCacheConfigHandler/no_signing_keys1666=== CONT TestCacheConfigHandler/no_cache_url_configured1667=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1668--- PASS: TestCacheConfigHandler (0.00s)1669 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1670 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1671 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1672 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1673=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16742026/08/29 16:33:39 INFO Received uploads request method=POST path=/16752026/08/29 16:33:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16762026/08/29 16:33:39 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16772026/08/29 16:33:39 WARN mTLS auth: bound subjects configured but subject DN unavailable16782026/08/29 16:33:39 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1679--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.26s)1680=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16812026/08/29 16:33:39 INFO Received request for more parts method=POST path=/16822026/08/29 16:33:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NmU5ZTA1ZDQtMTAwNi00MjUzLWExN2MtNmMxOWFlNDBlNGRhLjdlMjlkMjNmLTMxNjEtNDI1Yi1iZjNkLTYyOGUyNGQ1ODNjM3gxNzg4MDIxMjE3ODE3OTg3NDk1 parts=121683--- PASS: TestRedundantMultipartUpload (2.73s)1684=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16852026/08/29 16:33:39 INFO Received complete multipart upload request method=POST path=/1686--- PASS: TestService_Rustfstest (2.21s)1687=== CONT TestClientErrorHandling/InvalidStorePath1688=== NAME TestClientIntegration1689 client_integration_test.go:277: Created store path: /build/TestClientIntegration704597204/002/store/r9v2hkfc2q75hq0v9sd300hnmqpvgbzz-test-file.txt1690--- PASS: TestReadProxyNarStreaming (2.11s)1691=== CONT TestClientErrorHandling/ServerNotAvailable1692--- PASS: TestCacheStatsHandler (2.12s)1693=== CONT TestClientErrorHandling/InvalidAuthToken16942026-08-29 16:33:40.023 UTC [1209] ERROR: relation "goose_db_version" does not exist at character 3616952026-08-29 16:33:40.023 UTC [1209] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1696--- PASS: TestReadRedirectKeepsNarinfoProxied (2.11s)1697=== CONT TestParseSingleRange/none1698=== CONT TestParseSingleRange/start_far_past_EOF1699=== CONT TestParseSingleRange/start_past_EOF1700=== CONT TestParseSingleRange/single_byte1701=== CONT TestParseSingleRange/suffix_exceeds_size1702=== CONT TestParseSingleRange/suffix1703=== CONT TestParseSingleRange/end_clamped_to_size1704=== CONT TestParseSingleRange/open-ended1705=== CONT TestParseSingleRange/closed1706=== CONT TestParseSingleRange/malformed_end_before_start1707=== CONT TestParseSingleRange/malformed_both_empty1708=== CONT TestParseSingleRange/malformed_no_dash1709=== CONT TestParseSingleRange/multi-range_ignored1710=== CONT TestParseSingleRange/unknown_unit1711=== CONT TestService_RequireScope_OIDC/builder_may_write1712--- PASS: TestParseSingleRange (0.00s)1713 --- PASS: TestParseSingleRange/none (0.00s)1714 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1715 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1716 --- PASS: TestParseSingleRange/single_byte (0.00s)1717 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1718 --- PASS: TestParseSingleRange/suffix (0.00s)1719 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1720 --- PASS: TestParseSingleRange/open-ended (0.00s)1721 --- PASS: TestParseSingleRange/closed (0.00s)1722 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1723 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1724 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1725 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1726 --- PASS: TestParseSingleRange/unknown_unit (0.00s)17272026/08/29 16:33:40 INFO OIDC auth successful provider=test scopes=[write]1728=== CONT TestService_RequireScope_OIDC/static_token_may_admin1729=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1730=== CONT TestService_RequireScope_OIDC/writer_implies_read17312026/08/29 16:33:40 INFO OIDC auth successful provider=test scopes=[write]1732=== CONT TestService_RequireScope_OIDC/reader_may_read17332026/08/29 16:33:40 INFO OIDC auth successful provider=test scopes=[read]1734=== CONT TestService_RequireScope_OIDC/static_token_may_write1735=== CONT TestService_RequireScope_OIDC/ops_may_not_write17362026/08/29 16:33:40 INFO OIDC auth successful provider=test scopes=[admin]1737=== CONT TestService_RequireScope_OIDC/reader_may_not_write17382026/08/29 16:33:40 INFO OIDC auth successful provider=test scopes=[read]1739=== CONT TestService_RequireScope_OIDC/ops_may_admin17402026/08/29 16:33:40 INFO OIDC auth successful provider=test scopes=[admin]1741=== CONT TestService_RequireScope_OIDC/builder_may_not_admin17422026/08/29 16:33:40 INFO OIDC auth successful provider=test scopes=[write]1743=== CONT TestIsValidCachePath/narinfo1744=== CONT TestIsValidCachePath/index.html1745=== CONT TestIsValidCachePath/short_hash1746=== CONT TestIsValidCachePath/wrong_extension1747=== CONT TestIsValidCachePath/leading_slash1748=== CONT TestIsValidCachePath/empty1749=== CONT TestIsValidCachePath/random_path1750=== CONT TestIsValidCachePath/invalid_char_u1751=== CONT TestIsValidCachePath/invalid_char_e1752=== CONT TestIsValidCachePath/traversal_in_middle1753=== CONT TestIsValidCachePath/traversal_parent1754=== CONT TestIsValidCachePath/nar_uncompressed1755=== CONT TestIsValidCachePath/nar_xz1756=== CONT TestIsValidCachePath/nix-cache-info1757=== CONT TestIsValidCachePath/nar_bz21758=== CONT TestIsValidCachePath/realisation1759=== CONT TestIsValidCachePath/ls1760=== CONT TestIsValidCachePath/log1761=== CONT TestIsValidCachePath/nar_zst1762=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1763=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1764--- PASS: TestIsValidCachePath (0.00s)1765 --- PASS: TestIsValidCachePath/narinfo (0.00s)1766 --- PASS: TestIsValidCachePath/index.html (0.00s)1767 --- PASS: TestIsValidCachePath/short_hash (0.00s)1768 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1769 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1770 --- PASS: TestIsValidCachePath/empty (0.00s)1771 --- PASS: TestIsValidCachePath/random_path (0.00s)1772 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1773 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1774 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1775 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1776 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1777 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1778 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1779 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1780 --- PASS: TestIsValidCachePath/realisation (0.00s)1781 --- PASS: TestIsValidCachePath/ls (0.00s)1782 --- PASS: TestIsValidCachePath/log (0.00s)1783 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1784 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1785--- PASS: TestService_RequireScope_OIDC (1.36s)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/anonymous_may_not_read (0.00s)1789 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1790 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1791 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1792 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1793 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1794 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1795 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)17962026/08/29 16:33:40 INFO OIDC auth successful provider=test scopes=[write]1797=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected17982026/08/29 16:33:40 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]1799=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1800=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18012026/08/29 16:33:40 OK 20241026095416_initial_model.sql (15.83ms)18022026/08/29 16:33:40 WARN Authentication failed token_preview=eyJhbGciOi...ezgVVeWF1A token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1803--- PASS: TestService_AuthMiddleware_OIDC (1.15s)1804 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)1805 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1806 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1807 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)18082026/08/29 16:33:40 OK 20251210153512_drop_unused_gin_index.sql (3.46ms)18092026/08/29 16:33:40 OK 20251218171726_add_pins.sql (6.36ms)18102026/08/29 16:33:40 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18112026/08/29 16:33:40 OK 20260628120000_add_object_size_and_stats.sql (7.2ms)18122026/08/29 16:33:40 goose: successfully migrated database to version: 2026062812000018132026/08/29 16:33:40 OK 1_commit_pending_closure.sql (3.7ms)1814=== NAME TestClientCADerivations1815 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1910466461/001/store/2j2wghlqma0aax5gk38976pf82gbl1f0-ca-test18162026/08/29 16:33:40 OK 2_object_stats_trigger.sql (2.39ms)18172026/08/29 16:33:40 goose: up to current file version: 218182026-08-29 16:33:40.081 UTC [1283] ERROR: relation "goose_db_version" does not exist at character 3618192026-08-29 16:33:40.081 UTC [1283] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18202026/08/29 16:33:40 OK 20241026095416_initial_model.sql (10.75ms)18212026/08/29 16:33:40 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-config18222026/08/29 16:33:40 OK 20251210153512_drop_unused_gin_index.sql (1.51ms)18232026/08/29 16:33:40 OK 20251218171726_add_pins.sql (4.3ms)18242026/08/29 16:33:40 OK 20260628120000_add_object_size_and_stats.sql (2.65ms)18252026/08/29 16:33:40 goose: successfully migrated database to version: 2026062812000018262026/08/29 16:33:40 OK 1_commit_pending_closure.sql (2.06ms)18272026/08/29 16:33:40 OK 2_object_stats_trigger.sql (882.91µs)18282026/08/29 16:33:40 goose: up to current file version: 21829--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.52s)1830=== NAME TestClientCADerivations1831 client_ca_test.go:139: Found 1 dependencies (including self)18322026/08/29 16:33:40 INFO Received uploads request method=POST path=/api/pending_closures18332026/08/29 16:33:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18342026/08/29 16:33:40 INFO Uploading r9v2hkfc2q75hq0v9sd300hnmqpvgbzz-test-file.txt (152B)18352026/08/29 16:33:40 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"1836--- PASS: TestReadProxyNarinfo (1.46s)18372026/08/29 16:33:40 WARN Failed to register uploaded object key=r9v2hkfc2q75hq0v9sd300hnmqpvgbzz.ls error="server returned 404: 404 page not found\n"18382026/08/29 16:33:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18392026/08/29 16:33:40 INFO Signed narinfos id=1 count=118402026/08/29 16:33:40 INFO Uploading 1 narinfos18412026/08/29 16:33:40 WARN Failed to register uploaded object key=r9v2hkfc2q75hq0v9sd300hnmqpvgbzz.narinfo error="server returned 404: 404 page not found\n"18422026/08/29 16:33:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18432026/08/29 16:33:40 INFO Completed upload id=118442026/08/29 16:33:40 INFO Upload complete. (127ms)1845=== NAME TestClientIntegration1846 client_integration_test.go:293: Retrieved narinfo from S3:1847 StorePath: /build/TestClientIntegration704597204/002/store/r9v2hkfc2q75hq0v9sd300hnmqpvgbzz-test-file.txt1848 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1849 Compression: zstd1850 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11851 NarSize: 1521852 References: 1853 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11854--- PASS: TestReadRedirectNar (1.50s)1855--- PASS: TestResurrectedObjectNotDeleted (1.50s)1856=== NAME TestClientIntegration1857 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1858 client_integration_test.go:294: Decompressed .ls content (64 bytes):1859 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1860 client_integration_test.go:297: Testing garbage collection...1861--- PASS: TestReadProxyDisabled (1.46s)18622026/08/29 16:33:40 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1863--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.45s)18642026/08/29 16:33:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures18652026/08/29 16:33:40 INFO Garbage collection started18662026/08/29 16:33:40 INFO Aborted multipart uploads count=018672026/08/29 16:33:40 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=191.699461ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1868--- PASS: TestReadProxyHead (1.27s)18692026/08/29 16:33:40 WARN Force mode enabled - objects will be deleted immediately without grace period1870--- PASS: TestObjectStatsTrigger (1.24s)18712026/08/29 16:33:40 INFO Received uploads request method=POST path=/api/pending_closures1872--- PASS: TestReadProxyInvalidPath (1.23s)18732026/08/29 16:33:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18742026/08/29 16:33:40 INFO Uploading 2j2wghlqma0aax5gk38976pf82gbl1f0-ca-test (144B)18752026/08/29 16:33:40 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18762026/08/29 16:33:40 WARN Failed to register uploaded object key=log/0y0nd86i0vfszwvlzgf3n7xcdn191s6d-ca-test.drv error="server returned 404: 404 page not found\n"18772026/08/29 16:33:40 WARN Failed to register uploaded object key=2j2wghlqma0aax5gk38976pf82gbl1f0.ls error="server returned 404: 404 page not found\n"18782026/08/29 16:33:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18792026/08/29 16:33:40 INFO Signed narinfos id=1 count=118802026/08/29 16:33:40 INFO Uploading 1 narinfos18812026/08/29 16:33:40 WARN Failed to register uploaded object key=2j2wghlqma0aax5gk38976pf82gbl1f0.narinfo error="server returned 404: 404 page not found\n"18822026/08/29 16:33:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1883--- PASS: TestReadProxyConditionalGet (1.01s)18842026/08/29 16:33:40 INFO Completed upload id=118852026/08/29 16:33:40 INFO Upload complete. (88ms)1886=== NAME TestClientCADerivations1887 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1910466461/001/store/2j2wghlqma0aax5gk38976pf82gbl1f0-ca-test1888 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1889 Compression: zstd1890 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1891 NarSize: 1441892 References: 1893 Deriver: /build/TestClientCADerivations1910466461/001/store/0y0nd86i0vfszwvlzgf3n7xcdn191s6d-ca-test.drv1894 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1895 client_ca_test.go:185: Checking for realisation files in S3...1896 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1897 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1898--- PASS: TestReadProxy404 (0.66s)18992026/08/29 16:33:40 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19002026/08/29 16:33:40 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=365.761304ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1901=== NAME TestClientCADerivations1902 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1903 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1904 error: binary cache 's3://bucket34?endpoint=http://localhost:37727®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1910466461/001/store'1905 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11906--- PASS: TestClientCADerivations (2.63s)19072026/08/29 16:33:40 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"1908=== NAME TestOrphanedObjectsGC1909 orphaned_objects_gc_test.go:290: GC Test Summary:1910 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1911 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1912 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1913 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1914 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1915--- PASS: TestOrphanedObjectsGC (1.11s)19162026/08/29 16:33:40 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=019172026/08/29 16:33:40 INFO Vacuumed table table=pending_closures19182026/08/29 16:33:40 INFO Vacuumed table table=pending_objects19192026/08/29 16:33:40 INFO Vacuumed table table=multipart_uploads19202026/08/29 16:33:40 INFO Vacuumed table table=closures19212026/08/29 16:33:40 INFO Vacuumed table table=objects19222026/08/29 16:33:40 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=792.754303ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1923=== NAME TestOrphanedObjectsGCStressTest1924 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1925 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion19262026/08/29 16:33:41 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01927=== NAME TestPinProtectsFromGC1928 client_integration_test.go:711: Pin successfully protected closure from garbage collection1929--- PASS: TestPinProtectsFromGC (3.77s)1930=== NAME TestOrphanedObjectsGCStressTest1931 orphaned_objects_gc_test.go:509: Stress test completed successfully:1932 orphaned_objects_gc_test.go:510: - Active objects preserved: 201933 orphaned_objects_gc_test.go:511: - Objects deleted: 2101934 orphaned_objects_gc_test.go:512: - Total GC'd: 2101935--- PASS: TestOrphanedObjectsGCStressTest (3.22s)1936--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)1937 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.11s)1938 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.10s)1939 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.41s)19402026/08/29 16:33:41 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.726258791s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19412026/08/29 16:33:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01942=== NAME TestClientIntegration1943 client_integration_test.go:304: Objects in database after GC:1944 client_integration_test.go:304: Successfully deleted all objects with GC --force1945--- PASS: TestClientIntegration (4.51s)19462026/08/29 16:33:43 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"19472026/08/29 16:33:43 WARN Rate limiter enabled after throttle name=s3-test rate=519482026/08/29 16:33:43 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1949=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1950 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101951 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001952--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.66s)19532026/08/29 16:33:43 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_closures19542026/08/29 16:33:43 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=209.865568ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19552026/08/29 16:33:43 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=413.767118ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19562026/08/29 16:33:44 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=793.451239ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19572026/08/29 16:33:44 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.580467349s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1958--- PASS: TestClientErrorHandling (0.00s)1959 --- PASS: TestClientErrorHandling/InvalidStorePath (0.34s)1960 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.39s)1961 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.43s)1962PASS19632026-08-29 16:33:46.695 UTC [112] LOG: received smart shutdown request19642026-08-29 16:33:46.702 UTC [112] LOG: background worker "logical replication launcher" (PID 122) exited with exit code 119652026-08-29 16:33:46.713 UTC [117] LOG: shutting down19662026-08-29 16:33:46.713 UTC [117] LOG: checkpoint starting: shutdown immediate19672026-08-29 16:33:47.225 UTC [117] LOG: checkpoint complete: wrote 11145 buffers (68.0%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 14 recycled; write=0.210 s, sync=0.297 s, total=0.513 s; sync files=17141, longest=0.006 s, average=0.001 s; distance=236073 kB, estimate=236073 kB; lsn=0/FDEE348, redo lsn=0/FDEE34819682026-08-29 16:33:47.309 UTC [112] LOG: database system is shut down1969Running OIDC tests...1970=== RUN TestGlobMatch1971=== PAUSE TestGlobMatch1972=== RUN TestAudienceForIssuer1973=== PAUSE TestAudienceForIssuer1974=== RUN TestValidateToken_ValidToken1975=== PAUSE TestValidateToken_ValidToken1976=== RUN TestValidateToken_WrongAudience1977=== PAUSE TestValidateToken_WrongAudience1978=== RUN TestValidateToken_Expired1979=== PAUSE TestValidateToken_Expired1980=== RUN TestValidateToken_BoundClaimsMismatch1981=== PAUSE TestValidateToken_BoundClaimsMismatch1982=== RUN TestValidateToken_BoundSubjectMismatch1983=== PAUSE TestValidateToken_BoundSubjectMismatch1984=== RUN TestValidateToken_MultipleProviders1985=== PAUSE TestValidateToken_MultipleProviders1986=== RUN TestValidateToken_NoMatchingProvider1987=== PAUSE TestValidateToken_NoMatchingProvider1988=== RUN TestValidateToken_KubernetesServiceAccount1989=== PAUSE TestValidateToken_KubernetesServiceAccount1990=== RUN TestNewValidator_KubernetesRequiresCA1991=== PAUSE TestNewValidator_KubernetesRequiresCA1992=== RUN TestScopes_LegacyProviderDefaultsToWrite1993=== PAUSE TestScopes_LegacyProviderDefaultsToWrite1994=== RUN TestScopes_Rules1995=== PAUSE TestScopes_Rules1996=== RUN TestScopes_ConfigValidation1997=== PAUSE TestScopes_ConfigValidation1998=== CONT TestGlobMatch1999=== CONT TestScopes_LegacyProviderDefaultsToWrite2000=== CONT TestValidateToken_MultipleProviders2001=== CONT TestValidateToken_Expired2002=== RUN TestGlobMatch/foo_foo2003=== PAUSE TestGlobMatch/foo_foo2004=== RUN TestGlobMatch/foo_bar2005=== PAUSE TestGlobMatch/foo_bar2006=== RUN TestGlobMatch/*_2007=== PAUSE TestGlobMatch/*_2008=== RUN TestGlobMatch/*_anything2009=== PAUSE TestGlobMatch/*_anything2010=== RUN TestGlobMatch/foo*_foo2011=== CONT TestValidateToken_WrongAudience2012=== CONT TestValidateToken_ValidToken2013=== CONT TestAudienceForIssuer2014--- PASS: TestAudienceForIssuer (0.00s)2015=== CONT TestScopes_ConfigValidation2016=== CONT TestScopes_Rules2017=== CONT TestValidateToken_KubernetesServiceAccount2018=== CONT TestNewValidator_KubernetesRequiresCA2019=== CONT TestValidateToken_BoundSubjectMismatch2020=== CONT TestValidateToken_NoMatchingProvider2021=== CONT TestValidateToken_BoundClaimsMismatch2022=== PAUSE TestGlobMatch/foo*_foo2023=== RUN TestGlobMatch/foo*_foobar2024=== PAUSE TestGlobMatch/foo*_foobar2025=== RUN TestGlobMatch/foo*_bar2026=== PAUSE TestGlobMatch/foo*_bar2027=== RUN TestGlobMatch/*bar_bar2028=== PAUSE TestGlobMatch/*bar_bar2029=== RUN TestGlobMatch/*bar_foobar2030=== PAUSE TestGlobMatch/*bar_foobar2031=== RUN TestGlobMatch/*bar_foo2032=== PAUSE TestGlobMatch/*bar_foo2033=== RUN TestGlobMatch/foo*bar_foobar2034=== PAUSE TestGlobMatch/foo*bar_foobar2035=== RUN TestGlobMatch/foo*bar_foo123bar2036=== PAUSE TestGlobMatch/foo*bar_foo123bar2037=== RUN TestGlobMatch/foo*bar_foobarbaz2038=== PAUSE TestGlobMatch/foo*bar_foobarbaz2039=== RUN TestGlobMatch/*/*_foo/bar2040=== PAUSE TestGlobMatch/*/*_foo/bar2041=== RUN TestGlobMatch/*/*_foo2042=== PAUSE TestGlobMatch/*/*_foo2043=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2044=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2045=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02046=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02047=== RUN TestGlobMatch/refs/*/main_refs/heads/main2048=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2049=== RUN TestGlobMatch/fo?_foo2050=== PAUSE TestGlobMatch/fo?_foo2051=== RUN TestGlobMatch/fo?_fo2052=== PAUSE TestGlobMatch/fo?_fo2053=== RUN TestGlobMatch/fo?_fooo2054=== PAUSE TestGlobMatch/fo?_fooo2055=== RUN TestGlobMatch/?oo_foo2056=== PAUSE TestGlobMatch/?oo_foo2057=== RUN TestGlobMatch/?oo_boo2058=== PAUSE TestGlobMatch/?oo_boo2059=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2060=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2061=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2062=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2063=== CONT TestGlobMatch/foo_foo2064=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2065=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2066=== CONT TestGlobMatch/?oo_foo2067=== CONT TestGlobMatch/?oo_boo2068=== CONT TestGlobMatch/foo_bar2069=== CONT TestGlobMatch/foo*bar_foobarbaz2070=== CONT TestGlobMatch/fo?_fooo2071=== CONT TestGlobMatch/fo?_fo2072=== CONT TestGlobMatch/fo?_foo2073=== CONT TestGlobMatch/refs/*/main_refs/heads/main2074=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02075=== CONT TestGlobMatch/*/*_foo2076=== CONT TestGlobMatch/*/*_foo/bar2077=== CONT TestGlobMatch/foo*bar_foobar2078=== CONT TestGlobMatch/*bar_foo2079=== CONT TestGlobMatch/*bar_foobar2080=== CONT TestGlobMatch/*bar_bar2081=== CONT TestGlobMatch/foo*_bar2082=== CONT TestGlobMatch/foo*_foobar2083=== CONT TestGlobMatch/foo*_foo2084=== CONT TestGlobMatch/*_anything2085=== CONT TestGlobMatch/*_2086=== CONT TestGlobMatch/foo*bar_foo123bar2087=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2088--- PASS: TestGlobMatch (0.00s)2089 --- PASS: TestGlobMatch/foo_foo (0.00s)2090 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2091 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2092 --- PASS: TestGlobMatch/?oo_foo (0.00s)2093 --- PASS: TestGlobMatch/?oo_boo (0.00s)2094 --- PASS: TestGlobMatch/foo_bar (0.00s)2095 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2096 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2097 --- PASS: TestGlobMatch/fo?_fo (0.00s)2098 --- PASS: TestGlobMatch/fo?_foo (0.00s)2099 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2100 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2101 --- PASS: TestGlobMatch/*/*_foo (0.00s)2102 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2103 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2104 --- PASS: TestGlobMatch/*bar_foo (0.00s)2105 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2106 --- PASS: TestGlobMatch/*bar_bar (0.00s)2107 --- PASS: TestGlobMatch/foo*_bar (0.00s)2108 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2109 --- PASS: TestGlobMatch/foo*_foo (0.00s)2110 --- PASS: TestGlobMatch/*_anything (0.00s)2111 --- PASS: TestGlobMatch/*_ (0.00s)2112 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2113 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2114--- PASS: TestScopes_ConfigValidation (0.00s)21152026/08/29 16:33:48 INFO OIDC provider initialized name=test21162026/08/29 16:33:48 INFO OIDC provider initialized name=test21172026/08/29 16:33:48 INFO OIDC provider initialized name=test21182026/08/29 16:33:48 INFO OIDC provider initialized name=test21192026/08/29 16:33:48 INFO OIDC provider initialized name=test21202026/08/29 16:33:48 INFO OIDC provider initialized name=test21212026/08/29 16:33:48 INFO OIDC provider initialized name=provider121222026/08/29 16:33:48 INFO OIDC provider initialized name=test21232026/08/29 16:33:48 INFO OIDC provider initialized name=provider121242026/08/29 16:33:48 INFO OIDC provider initialized name=provider22125--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2126--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2127--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2128--- PASS: TestValidateToken_ValidToken (0.01s)2129--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2130--- PASS: TestValidateToken_WrongAudience (0.01s)2131--- PASS: TestValidateToken_Expired (0.02s)21322026/08/29 16:33:48 INFO OIDC provider initialized name=kubernetes2133--- PASS: TestValidateToken_MultipleProviders (0.02s)2134--- PASS: TestScopes_Rules (0.02s)2135--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)21362026/08/29 16:33:48 http: TLS handshake error from 127.0.0.1:35940: remote error: tls: bad certificate2137--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2138PASS2139Running hook tests...2140=== RUN TestSendPathsEmpty2141=== PAUSE TestSendPathsEmpty2142=== RUN TestQueueEnqueueAndFetch2143=== PAUSE TestQueueEnqueueAndFetch2144=== RUN TestQueueDeduplication2145=== PAUSE TestQueueDeduplication2146=== RUN TestQueueRemove2147=== PAUSE TestQueueRemove2148=== RUN TestQueueFetchBatchLimit2149=== PAUSE TestQueueFetchBatchLimit2150=== RUN TestQueueRetryMovesToBack2151=== PAUSE TestQueueRetryMovesToBack2152=== RUN TestQueueFetchRemoveLifecycle2153=== PAUSE TestQueueFetchRemoveLifecycle2154=== RUN TestQueueConcurrentWriters2155=== PAUSE TestQueueConcurrentWriters2156=== RUN TestQueueRemoveLargeClosure2157=== PAUSE TestQueueRemoveLargeClosure2158=== RUN TestServerClientIntegration2159=== PAUSE TestServerClientIntegration2160=== RUN TestServerQueueError2161=== PAUSE TestServerQueueError2162=== RUN TestGetListenerSocketActivation2163 server_test.go:210: === RUN TestGetListenerSocketActivation2164 --- PASS: TestGetListenerSocketActivation (0.00s)2165 PASS2166 2167--- PASS: TestGetListenerSocketActivation (0.01s)2168=== RUN TestDrainIsolatesPoisonPath2169=== PAUSE TestDrainIsolatesPoisonPath2170=== RUN TestRunNotBlockedByPoisonHead2171=== PAUSE TestRunNotBlockedByPoisonHead2172=== RUN TestDrainGivesUpWhenServerDown2173=== PAUSE TestDrainGivesUpWhenServerDown2174=== RUN TestFailedPathPrunedByLaterClosure2175=== PAUSE TestFailedPathPrunedByLaterClosure2176=== RUN TestWorkerUploadsAndRemoves2177=== PAUSE TestWorkerUploadsAndRemoves2178=== RUN TestWorkerSkipsGCdPaths2179=== PAUSE TestWorkerSkipsGCdPaths2180=== RUN TestWorkerPrunesClosureDeps2181=== PAUSE TestWorkerPrunesClosureDeps2182=== RUN TestDrainTimeout2183=== PAUSE TestDrainTimeout2184=== CONT TestSendPathsEmpty2185=== CONT TestWorkerUploadsAndRemoves2186=== CONT TestWorkerPrunesClosureDeps2187=== CONT TestDrainTimeout2188--- PASS: TestSendPathsEmpty (0.00s)2189=== CONT TestFailedPathPrunedByLaterClosure2190=== CONT TestDrainGivesUpWhenServerDown2191=== CONT TestRunNotBlockedByPoisonHead2192=== CONT TestDrainIsolatesPoisonPath2193=== CONT TestServerQueueError2194=== CONT TestServerClientIntegration2195=== CONT TestQueueRemoveLargeClosure2196=== CONT TestQueueConcurrentWriters2197=== CONT TestQueueFetchRemoveLifecycle2198=== CONT TestQueueRetryMovesToBack2199=== CONT TestQueueFetchBatchLimit2200=== CONT TestQueueRemove2201=== CONT TestQueueDeduplication2202=== CONT TestQueueEnqueueAndFetch2203=== CONT TestWorkerSkipsGCdPaths22042026/08/29 16:33:48 ERROR Failed to queue paths error="permission denied" count=12205--- PASS: TestServerClientIntegration (0.00s)2206--- PASS: TestServerQueueError (0.00s)22072026/08/29 16:33:48 INFO Uploading batch count=122082026/08/29 16:33:48 ERROR Upload failed error="upload failed" count=122092026/08/29 16:33:48 INFO Uploading batch count=422102026/08/29 16:33:48 ERROR Upload failed error="upload failed" count=422112026/08/29 16:33:48 INFO Uploading batch count=122122026/08/29 16:33:48 INFO Uploading batch count=22213--- PASS: TestQueueEnqueueAndFetch (0.01s)22142026/08/29 16:33:48 INFO Upload queue status pending=322152026/08/29 16:33:48 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1153059216/002/bbb22162026/08/29 16:33:48 INFO Uploading batch count=122172026/08/29 16:33:48 ERROR Upload failed error="upload failed" count=122182026/08/29 16:33:48 INFO Uploading batch count=222192026/08/29 16:33:48 ERROR Upload failed error="upload failed" count=222202026/08/29 16:33:48 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown691550282/002/a2221--- PASS: TestQueueFetchRemoveLifecycle (0.02s)2222--- PASS: TestQueueFetchBatchLimit (0.02s)22232026/08/29 16:33:48 INFO Uploading batch count=12224--- PASS: TestQueueRetryMovesToBack (0.02s)22252026/08/29 16:33:48 INFO Upload queue status pending=222262026/08/29 16:33:48 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown691550282/002/b22272026/08/29 16:33:48 INFO Uploading batch count=22228--- PASS: TestQueueDeduplication (0.02s)22292026/08/29 16:33:48 INFO Upload queue status pending=222302026/08/29 16:33:48 INFO Upload queue status pending=222312026/08/29 16:33:48 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1408781447/002/nonexistent22322026/08/29 16:33:48 INFO Uploading batch count=122332026/08/29 16:33:48 ERROR Upload failed error="upload failed" count=122342026/08/29 16:33:48 INFO Uploading batch count=12235--- PASS: TestQueueRemove (0.02s)22362026/08/29 16:33:48 INFO Uploading batch count=222372026/08/29 16:33:48 INFO Uploading batch count=122382026/08/29 16:33:48 ERROR Upload failed error="upload failed" count=222392026/08/29 16:33:48 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown691550282/002/c22402026/08/29 16:33:48 INFO Uploading batch count=122412026/08/29 16:33:48 ERROR Upload failed error="upload failed" count=12242--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)22432026/08/29 16:33:48 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown691550282/002/d22442026/08/29 16:33:48 INFO Uploading batch count=122452026/08/29 16:33:48 ERROR Upload failed error="upload failed" count=122462026/08/29 16:33:48 INFO Uploading batch count=222472026/08/29 16:33:48 ERROR Upload failed error="upload failed" count=222482026/08/29 16:33:48 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown691550282/002/e22492026/08/29 16:33:48 ERROR Drain finished with paths left in queue remaining=122502026/08/29 16:33:48 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown691550282/002/f22512026/08/29 16:33:48 ERROR Drain finished with paths left in queue remaining=102252--- PASS: TestDrainIsolatesPoisonPath (0.02s)2253--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2254--- PASS: TestWorkerUploadsAndRemoves (0.04s)2255--- PASS: TestWorkerPrunesClosureDeps (0.04s)2256--- PASS: TestWorkerSkipsGCdPaths (0.04s)22572026/08/29 16:33:48 ERROR Upload failed error="context deadline exceeded" count=222582026/08/29 16:33:48 ERROR Drain finished with paths left in queue remaining=42259--- PASS: TestDrainTimeout (0.22s)2260--- PASS: TestQueueConcurrentWriters (0.24s)2261--- PASS: TestQueueRemoveLargeClosure (0.31s)22622026/08/29 16:33:49 INFO Uploading batch count=122632026/08/29 16:33:49 INFO Uploading batch count=122642026/08/29 16:33:49 INFO Uploading batch count=122652026/08/29 16:33:49 ERROR Upload failed error="upload failed" count=122662026/08/29 16:33:49 INFO Uploading batch count=122672026/08/29 16:33:49 ERROR Upload failed error="upload failed" count=122682026/08/29 16:33:49 INFO Uploading batch count=122692026/08/29 16:33:49 ERROR Upload failed error="upload failed" count=122702026/08/29 16:33:49 INFO Uploading batch count=122712026/08/29 16:33:49 ERROR Upload failed error="upload failed" count=122722026/08/29 16:33:49 ERROR Drain finished with paths left in queue remaining=12273--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2274PASS