niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #189
· 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 TestResolveStorePath75=== CONT TestEncodeNixBase32WithRealHash76=== CONT TestFileTokenMissing77--- PASS: TestEncodeNixBase32WithRealHash (0.00s)78=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess79=== CONT TestRateLimiterFeedback80=== RUN TestRateLimiterFeedback/429_enables_limiter81=== PAUSE TestRateLimiterFeedback/429_enables_limiter82=== RUN TestRateLimiterFeedback/503_enables_limiter83=== CONT TestScriptTokenEmptyToken84=== PAUSE TestRateLimiterFeedback/503_enables_limiter85=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter86=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter87=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter88=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter89=== CONT TestPathInfoCACompatibility90=== RUN TestPathInfoCACompatibility/null_ca_field91=== PAUSE TestPathInfoCACompatibility/null_ca_field92=== RUN TestPathInfoCACompatibility/old_string_format_-_text93=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text94=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive95=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive96=== RUN TestPathInfoCACompatibility/new_structured_format_-_text97=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text98=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method99=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method100=== CONT TestScriptTokenBadJSON101=== CONT TestParsePathInfoJSONMultiplePaths102--- PASS: TestFileTokenMissing (0.00s)103=== CONT TestFileTokenReadsAndCaches104=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1052026/09/10 09:07:36 WARN Rate limiter enabled after throttle name=server-test rate=5106=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths107=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths108=== CONT TestSetClientTLSDoesNotMutateDefaultTransport109=== CONT TestParsePathInfoJSON110=== RUN TestParsePathInfoJSON/Nix_format111=== PAUSE TestParsePathInfoJSON/Nix_format112=== RUN TestParsePathInfoJSON/Lix_format113=== PAUSE TestParsePathInfoJSON/Lix_format114=== RUN TestParsePathInfoJSON/empty_input115--- PASS: TestResolveStorePath (0.00s)116=== CONT TestConvertHashToNix32117=== RUN TestConvertHashToNix32/SRI_format_to_Nix32118=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32119=== CONT TestScriptTokenScriptFails120=== CONT TestScriptTokenEmptyCommand121=== CONT TestPartSizeForNAR122=== CONT TestUploadMultipart_SupersededByPeer123=== CONT TestScriptTokenNoExpiryRerunsEveryCall124=== CONT TestScriptTokenCachesUntilRefresh125=== CONT TestFilterOversizedClosures126=== CONT TestFileTokenEmpty127=== CONT TestDumpPathWriterError128=== CONT TestEncodeNixBase32129=== CONT TestDumpPathSingleFile130=== CONT TestCaseHackSuffix131=== CONT TestStaticToken132=== CONT TestShellSplitErrors133=== CONT TestSetClientTLS134=== CONT TestShellSplit135=== CONT TestDoWithRetry_BodyReplayedViaGetBody136=== RUN TestFilterOversizedClosures/no_limit_keeps_everything137=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything138=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped139=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped140=== RUN TestFilterOversizedClosures/all_closures_skipped141=== PAUSE TestFilterOversizedClosures/all_closures_skipped142=== CONT TestRateLimiterFeedback/429_enables_limiter143=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths144=== CONT TestPathInfoHashCompatibility145=== PAUSE TestParsePathInfoJSON/empty_input146=== CONT TestGetStorePathHash147--- PASS: TestFileTokenReadsAndCaches (0.00s)148--- PASS: TestStaticToken (0.00s)149--- PASS: TestShellSplitErrors (0.00s)150--- PASS: TestScriptTokenEmptyCommand (0.00s)151=== CONT TestSetClientTLSErrors152=== RUN TestParsePathInfoJSON/whitespace_only153=== RUN TestConvertHashToNix32/already_Nix32_format154=== RUN TestUploadMultipart_SupersededByPeer/exists155=== PAUSE TestUploadMultipart_SupersededByPeer/exists156=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter157=== RUN TestPartSizeForNAR/zero_stays_at_minimum158=== CONT TestDumpPathMatchesNix159--- PASS: TestShellSplit (0.00s)160=== RUN TestEncodeNixBase32/test_string_hash161=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)162=== PAUSE TestParsePathInfoJSON/whitespace_only163=== PAUSE TestConvertHashToNix32/already_Nix32_format164--- PASS: TestFileTokenEmpty (0.00s)165--- PASS: TestScriptTokenScriptFails (0.00s)166=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum167=== RUN TestUploadMultipart_SupersededByPeer/missing168=== RUN TestConvertHashToNix32/invalid_format169=== PAUSE TestEncodeNixBase32/test_string_hash170=== RUN TestEncodeNixBase32/empty_input171=== PAUSE TestEncodeNixBase32/empty_input172=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)173=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon174=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon175=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI176=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI1772026/09/10 09:07:36 WARN Rate limiter enabled after throttle name=server-test rate=5178=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha5121792026/09/10 09:07:36 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:42187180=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512181=== RUN TestPartSizeForNAR/small_stays_at_minimum182=== PAUSE TestPartSizeForNAR/small_stays_at_minimum183=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum184=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum1852026/09/10 09:07:36 WARN Rate limiter backed off name=server-test rate=5186=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts187=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter188=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts189=== PAUSE TestConvertHashToNix32/invalid_format190=== RUN TestGetStorePathHash/valid_store_path191=== RUN TestParsePathInfoJSON/invalid_JSON192=== CONT TestRateLimiterFeedback/503_enables_limiter1932026/09/10 09:07:36 WARN Rate limiter enabled after throttle name=server-test rate=51942026/09/10 09:07:36 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:37369195=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped196=== RUN TestSetClientTLSErrors/missing_cert_file1972026/09/10 09:07:36 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=2000198=== PAUSE TestUploadMultipart_SupersededByPeer/missing199=== CONT TestPathInfoCACompatibility/null_ca_field200--- PASS: TestScriptTokenEmptyToken (0.01s)201--- PASS: TestScriptTokenBadJSON (0.01s)202=== RUN TestPartSizeForNAR/1_TiB2032026/09/10 09:07:36 WARN Rate limiter enabled after throttle name=server-test rate=52042026/09/10 09:07:36 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:40095205=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive206=== CONT TestPathInfoCACompatibility/old_string_format_-_text207=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method2082026/09/10 09:07:36 WARN Rate limiter backed off name=server-test rate=5209=== CONT TestPathInfoCACompatibility/new_structured_format_-_text2102026/09/10 09:07:36 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:37369211=== CONT TestFilterOversizedClosures/no_limit_keeps_everything212=== PAUSE TestGetStorePathHash/valid_store_path213=== PAUSE TestParsePathInfoJSON/invalid_JSON2142026/09/10 09:07:36 WARN Rate limiter backed off name=server-test rate=5215=== CONT TestFilterOversizedClosures/all_closures_skipped216=== PAUSE TestSetClientTLSErrors/missing_cert_file217=== RUN TestSetClientTLS/rejects_connection_without_client_cert218--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)219=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths220--- PASS: TestDoServerRequestAttachesToken (0.01s)2212026/09/10 09:07:36 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50222=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI223=== CONT TestUploadMultipart_SupersededByPeer/exists224=== CONT TestUploadMultipart_SupersededByPeer/missing225=== CONT TestParsePathInfoJSON/Nix_format226=== CONT TestParsePathInfoJSON/empty_input227=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon228=== CONT TestParsePathInfoJSON/whitespace_only229=== PAUSE TestPartSizeForNAR/1_TiB230=== CONT TestEncodeNixBase32/test_string_hash231=== RUN TestGetStorePathHash/basename_without_hyphen_should_error232=== CONT TestEncodeNixBase32/empty_input233=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)234=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512235=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert236=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error237=== CONT TestConvertHashToNix32/SRI_format_to_Nix32238=== RUN TestSetClientTLSErrors/missing_key_file239=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths240=== CONT TestConvertHashToNix32/invalid_format241=== CONT TestConvertHashToNix32/already_Nix32_format242--- PASS: TestFilterOversizedClosures (0.00s)243 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)244 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)245 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)246=== CONT TestParsePathInfoJSON/invalid_JSON247=== CONT TestParsePathInfoJSON/Lix_format248=== RUN TestPartSizeForNAR/5_TiB_S3_max_object249--- PASS: TestPathInfoCACompatibility (0.00s)250 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)251 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)252 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)253 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)254 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)255=== PAUSE TestSetClientTLSErrors/missing_key_file256=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA257=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error258=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object259--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)260=== RUN TestPartSizeForNAR/capped_at_5_GiB261=== RUN TestSetClientTLSErrors/missing_ca_file262=== PAUSE TestSetClientTLSErrors/missing_ca_file263=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA264=== RUN TestSetClientTLS/preserves_debug_logging_transport265--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)266--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)267=== PAUSE TestPartSizeForNAR/capped_at_5_GiB268=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error269=== PAUSE TestSetClientTLS/preserves_debug_logging_transport270=== CONT TestSetClientTLS/rejects_connection_without_client_cert271=== CONT TestSetClientTLS/preserves_debug_logging_transport272=== RUN TestSetClientTLSErrors/invalid_ca_file273=== PAUSE TestSetClientTLSErrors/invalid_ca_file274=== CONT TestSetClientTLSErrors/missing_cert_file275=== CONT TestSetClientTLSErrors/invalid_ca_file276--- PASS: TestRateLimiterFeedback (0.00s)277 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)278 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)279 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)280 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)281=== CONT TestSetClientTLSErrors/missing_key_file282--- PASS: TestEncodeNixBase32 (0.00s)283 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)284 --- PASS: TestEncodeNixBase32/empty_input (0.00s)285--- PASS: TestConvertHashToNix32 (0.01s)286 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)287 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)288 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)289--- PASS: TestPathInfoHashCompatibility (0.00s)290 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)291 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)292 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)293 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)294--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)295 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)296 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)297=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum298=== CONT TestPartSizeForNAR/1_TiB299=== CONT TestPartSizeForNAR/zero_stays_at_minimum300=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts301=== CONT TestPartSizeForNAR/capped_at_5_GiB302=== CONT TestPartSizeForNAR/small_stays_at_minimum303=== CONT TestPartSizeForNAR/5_TiB_S3_max_object304=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error305=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA306=== CONT TestSetClientTLSErrors/missing_ca_file307--- PASS: TestParsePathInfoJSON (0.02s)308 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)309 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)310 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)311 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)312 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)313=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error314=== CONT TestGetStorePathHash/valid_store_path315=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error316=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error317=== CONT TestGetStorePathHash/basename_without_hyphen_should_error318--- PASS: TestPartSizeForNAR (0.02s)319 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)320 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)321 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)322 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)323 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)324 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)325 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)326--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)327 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)328 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)329--- PASS: TestGetStorePathHash (0.02s)330 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)331 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)332 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)333 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (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)3392026/09/10 09:07:36 http: TLS handshake error from 127.0.0.1:54230: remote error: tls: bad certificate340--- PASS: TestSetClientTLS (0.02s)341 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)342 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)343 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)344--- PASS: TestCaseHackSuffix (0.04s)345--- PASS: TestDumpPathSingleFile (0.04s)346--- PASS: TestDumpPathWriterError (0.05s)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/postgres4238492050/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/postgres4238492050/data -l logfile start377378/build/postgres4238492050:5432 - no response3792026-09-10 09:07:38.289 UTC [111] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit3802026-09-10 09:07:38.289 UTC [111] LOG: listening on Unix socket "/build/postgres4238492050/.s.PGSQL.5432"3812026-09-10 09:07:38.294 UTC [118] LOG: database system was shut down at 2026-09-10 09:07:38 UTC3822026-09-10 09:07:38.298 UTC [111] LOG: database system is ready to accept connections383/build/postgres4238492050:5432 - accepting connections384=== RUN TestService_AuthMiddleware385=== PAUSE TestService_AuthMiddleware386=== RUN TestService_AuthMiddleware_MTLSProxyHeader387=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader388=== RUN TestService_AuthMiddleware_MTLSBoundSubjects389=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects390=== RUN TestService_ReadAuthMiddleware391=== PAUSE TestService_ReadAuthMiddleware392=== RUN TestService_AuthMiddleware_OIDC393=== PAUSE TestService_AuthMiddleware_OIDC394=== RUN TestService_RequireScope_OIDC395=== PAUSE TestService_RequireScope_OIDC396=== RUN TestService_ReadScope_PublicByDefault397=== PAUSE TestService_ReadScope_PublicByDefault398=== RUN TestCacheConfigHandler399=== PAUSE TestCacheConfigHandler400=== RUN TestCacheStatsHandler401=== PAUSE TestCacheStatsHandler402=== RUN TestClientCADerivations403=== PAUSE TestClientCADerivations404=== RUN TestClientErrorHandling405=== PAUSE TestClientErrorHandling406=== RUN TestClientIntegration407=== PAUSE TestClientIntegration408=== RUN TestClientMultipleUploads409=== PAUSE TestClientMultipleUploads410=== RUN TestClientWithDependencies411=== PAUSE TestClientWithDependencies412=== RUN TestPinProtectsFromGC413=== PAUSE TestPinProtectsFromGC414=== RUN TestResolveDBConnectionString415=== PAUSE TestResolveDBConnectionString416=== RUN TestGCAdvisoryLockBlocksConcurrentRun4172026-09-10 09:07:41.817 UTC [518] ERROR: relation "goose_db_version" does not exist at character 364182026-09-10 09:07:41.817 UTC [518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4192026/09/10 09:07:41 OK 20241026095416_initial_model.sql (11.91ms)4202026/09/10 09:07:41 OK 20251210153512_drop_unused_gin_index.sql (2.35ms)4212026/09/10 09:07:41 OK 20251218171726_add_pins.sql (3.17ms)4222026/09/10 09:07:41 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)4232026/09/10 09:07:41 goose: successfully migrated database to version: 202606281200004242026/09/10 09:07:41 OK 1_commit_pending_closure.sql (3.94ms)4252026/09/10 09:07:41 OK 2_object_stats_trigger.sql (976.69µs)4262026/09/10 09:07:41 goose: up to current file version: 2427--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.29s)428=== RUN TestOrphanedObjectsGCDeletesEachKeyOnce429=== PAUSE TestOrphanedObjectsGCDeletesEachKeyOnce430=== RUN TestOrphanedObjectsGCFallsBackToSingleDeletes431=== PAUSE TestOrphanedObjectsGCFallsBackToSingleDeletes432=== RUN TestGCBugBareHashReferences433=== PAUSE TestGCBugBareHashReferences434=== RUN TestGCMetrics435=== PAUSE TestGCMetrics436=== RUN TestGCTaskStore_StartNew437=== PAUSE TestGCTaskStore_StartNew438=== RUN TestGCTaskStore_DeduplicateSameParams439=== PAUSE TestGCTaskStore_DeduplicateSameParams440=== RUN TestGCTaskStore_ConflictDifferentParams441=== PAUSE TestGCTaskStore_ConflictDifferentParams442=== RUN TestGCTaskStore_GetEmpty443=== PAUSE TestGCTaskStore_GetEmpty444=== RUN TestGCTaskStore_GetReturnsLatest445=== PAUSE TestGCTaskStore_GetReturnsLatest446=== RUN TestGCTaskStore_CompletedAllowsNewTask447=== PAUSE TestGCTaskStore_CompletedAllowsNewTask448=== RUN TestGCTaskStore_PhaseUpdates449=== PAUSE TestGCTaskStore_PhaseUpdates450=== RUN TestGCTaskStore_Fail451=== PAUSE TestGCTaskStore_Fail452=== RUN TestGracefulShutdownDrainsInflight453=== PAUSE TestGracefulShutdownDrainsInflight454=== RUN TestService_healthCheckHandler455=== PAUSE TestService_healthCheckHandler456=== RUN TestService_readinessHandler457=== PAUSE TestService_readinessHandler458=== RUN TestGenerateLandingPage459=== PAUSE TestGenerateLandingPage460=== RUN TestCacheConfigHandlerMaxNarSize461=== PAUSE TestCacheConfigHandlerMaxNarSize462=== RUN TestCreatePendingClosureRejectsOversizedNAR463=== PAUSE TestCreatePendingClosureRejectsOversizedNAR464=== RUN TestNARDeduplicationMetadataUploadBug465=== PAUSE TestNARDeduplicationMetadataUploadBug466=== RUN TestMetricsInventory467=== PAUSE TestMetricsInventory468=== RUN TestService_NativeMTLS469=== PAUSE TestService_NativeMTLS470=== RUN TestServerTLSConfig471=== PAUSE TestServerTLSConfig472=== RUN TestMultipartCleanup473=== PAUSE TestMultipartCleanup474=== RUN TestObjectStatsTrigger475=== PAUSE TestObjectStatsTrigger476=== RUN TestOrphanedObjectsGC477=== PAUSE TestOrphanedObjectsGC478=== RUN TestOrphanedObjectsGCStressTest479=== PAUSE TestOrphanedObjectsGCStressTest480=== RUN TestResurrectedObjectNotDeleted481=== PAUSE TestResurrectedObjectNotDeleted482=== RUN TestParseSingleRange483=== PAUSE TestParseSingleRange484=== RUN TestIsValidCachePath485=== PAUSE TestIsValidCachePath486=== RUN TestReadProxyNarinfo487=== PAUSE TestReadProxyNarinfo488=== RUN TestReadProxyNarinfoAlreadyDecompressed489=== PAUSE TestReadProxyNarinfoAlreadyDecompressed490=== RUN TestReadProxyNarStreaming491=== PAUSE TestReadProxyNarStreaming492=== RUN TestReadProxy404493=== PAUSE TestReadProxy404494=== RUN TestReadProxyInvalidPath495=== PAUSE TestReadProxyInvalidPath496=== RUN TestReadProxyHead497=== PAUSE TestReadProxyHead498=== RUN TestReadProxyConditionalGet499=== PAUSE TestReadProxyConditionalGet500=== RUN TestReadProxyRootRedirectsToIndexHTML501=== PAUSE TestReadProxyRootRedirectsToIndexHTML502=== RUN TestReadProxyDisabled503=== PAUSE TestReadProxyDisabled504=== RUN TestReadRedirectNar505=== PAUSE TestReadRedirectNar506=== RUN TestReadRedirectKeepsNarinfoProxied507=== PAUSE TestReadRedirectKeepsNarinfoProxied508=== RUN TestReadProxyRangeRequest509=== PAUSE TestReadProxyRangeRequest510=== RUN TestReadRedirectUsesPublicS3URL511=== PAUSE TestReadRedirectUsesPublicS3URL512=== RUN TestRedundantMultipartUpload513=== PAUSE TestRedundantMultipartUpload514=== RUN TestCompleteMultipartUpload_ErrorButObjectExists515=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists516=== RUN TestCompletedNarNotReofferedAcrossClosures517=== PAUSE TestCompletedNarNotReofferedAcrossClosures518=== RUN TestPresignedUploadRegisteredBeforeCommit519=== PAUSE TestPresignedUploadRegisteredBeforeCommit520=== RUN TestService_Rustfstest521=== PAUSE TestService_Rustfstest522=== RUN TestParseSize523=== PAUSE TestParseSize524=== RUN TestSkippedUploadsHandler525=== PAUSE TestSkippedUploadsHandler526=== RUN TestSystemdListenerNotActivated527--- PASS: TestSystemdListenerNotActivated (0.00s)528=== RUN TestWatchdogBeatsWhenHealthy529--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)530=== RUN TestWatchdogSkipsWhenUnhealthy5312026/09/10 09:07:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5322026/09/10 09:07:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5332026/09/10 09:07:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5342026/09/10 09:07:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5352026/09/10 09:07:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5362026/09/10 09:07:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5372026/09/10 09:07:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5382026/09/10 09:07:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5392026/09/10 09:07:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5402026/09/10 09:07:42 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"541--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)542=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle543=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle544=== RUN TestProxyWriteTimeout545=== PAUSE TestProxyWriteTimeout546=== RUN TestIsValidUploadKey547=== PAUSE TestIsValidUploadKey548=== RUN TestUploadHandlersRejectInvalidKeys549=== PAUSE TestUploadHandlersRejectInvalidKeys550=== RUN TestUploadHandlersRejectOversizedBody551=== PAUSE TestUploadHandlersRejectOversizedBody552=== RUN TestService_cleanupPendingClosuresHandler553=== PAUSE TestService_cleanupPendingClosuresHandler554=== RUN TestService_createPendingClosureHandler555=== PAUSE TestService_createPendingClosureHandler556=== RUN TestService_verifyS3Integrity557=== PAUSE TestService_verifyS3Integrity558=== RUN TestCompleteMultipartUnregistered559=== PAUSE TestCompleteMultipartUnregistered560=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT561=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT562=== CONT TestCompleteMultipartUnregistered563=== CONT TestParseSize564=== CONT TestService_AuthMiddleware565=== CONT TestReadProxyConditionalGet566=== CONT TestReadProxyHead567=== CONT TestReadProxyInvalidPath568=== CONT TestReadProxy404569=== CONT TestReadProxyNarStreaming570=== CONT TestReadProxyNarinfoAlreadyDecompressed571=== CONT TestReadProxyNarinfo572=== CONT TestIsValidCachePath573=== RUN TestIsValidCachePath/narinfo574=== PAUSE TestIsValidCachePath/narinfo575=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars576=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars577=== CONT TestParseSingleRange578=== CONT TestResurrectedObjectNotDeleted579=== CONT TestOrphanedObjectsGCStressTest580=== CONT TestOrphanedObjectsGC581=== CONT TestObjectStatsTrigger582=== CONT TestMultipartCleanup583=== CONT TestReadProxyRootRedirectsToIndexHTML584=== CONT TestServerTLSConfig585=== CONT TestService_NativeMTLS586=== CONT TestService_Rustfstest587=== CONT TestMetricsInventory588=== CONT TestPresignedUploadRegisteredBeforeCommit589=== CONT TestNARDeduplicationMetadataUploadBug590--- PASS: TestParseSize (0.00s)591=== CONT TestCompletedNarNotReofferedAcrossClosures592=== RUN TestParseSingleRange/none593=== PAUSE TestParseSingleRange/none594=== RUN TestParseSingleRange/unknown_unit595=== PAUSE TestParseSingleRange/unknown_unit596=== RUN TestParseSingleRange/multi-range_ignored597=== PAUSE TestParseSingleRange/multi-range_ignored598=== RUN TestParseSingleRange/malformed_no_dash599=== PAUSE TestParseSingleRange/malformed_no_dash600=== RUN TestParseSingleRange/malformed_both_empty601=== PAUSE TestParseSingleRange/malformed_both_empty602=== RUN TestParseSingleRange/malformed_end_before_start603=== PAUSE TestParseSingleRange/malformed_end_before_start604=== RUN TestParseSingleRange/closed605=== PAUSE TestParseSingleRange/closed606=== RUN TestParseSingleRange/open-ended607=== PAUSE TestParseSingleRange/open-ended608=== RUN TestParseSingleRange/end_clamped_to_size609=== PAUSE TestParseSingleRange/end_clamped_to_size610=== RUN TestParseSingleRange/suffix611=== PAUSE TestParseSingleRange/suffix612=== RUN TestParseSingleRange/suffix_exceeds_size613=== PAUSE TestParseSingleRange/suffix_exceeds_size614=== RUN TestParseSingleRange/single_byte615=== PAUSE TestParseSingleRange/single_byte616=== RUN TestParseSingleRange/start_past_EOF617=== PAUSE TestParseSingleRange/start_past_EOF618=== RUN TestParseSingleRange/start_far_past_EOF619=== PAUSE TestParseSingleRange/start_far_past_EOF620=== RUN TestIsValidCachePath/nar_zst621=== PAUSE TestIsValidCachePath/nar_zst622=== RUN TestIsValidCachePath/nar_xz623=== PAUSE TestIsValidCachePath/nar_xz624=== RUN TestIsValidCachePath/nar_bz2625=== PAUSE TestIsValidCachePath/nar_bz2626=== RUN TestIsValidCachePath/nar_uncompressed627=== PAUSE TestIsValidCachePath/nar_uncompressed628=== RUN TestIsValidCachePath/ls629=== PAUSE TestIsValidCachePath/ls630=== RUN TestIsValidCachePath/log631=== PAUSE TestIsValidCachePath/log632=== RUN TestIsValidCachePath/realisation633=== PAUSE TestIsValidCachePath/realisation634=== RUN TestIsValidCachePath/nix-cache-info635=== PAUSE TestIsValidCachePath/nix-cache-info636=== RUN TestIsValidCachePath/index.html637=== PAUSE TestIsValidCachePath/index.html638=== RUN TestIsValidCachePath/traversal_parent639=== PAUSE TestIsValidCachePath/traversal_parent640=== RUN TestIsValidCachePath/traversal_in_middle641=== PAUSE TestIsValidCachePath/traversal_in_middle642=== RUN TestIsValidCachePath/invalid_char_e643=== PAUSE TestIsValidCachePath/invalid_char_e644=== RUN TestIsValidCachePath/invalid_char_u645=== PAUSE TestIsValidCachePath/invalid_char_u646=== RUN TestIsValidCachePath/random_path647=== PAUSE TestIsValidCachePath/random_path648=== RUN TestIsValidCachePath/empty649=== PAUSE TestIsValidCachePath/empty650=== RUN TestIsValidCachePath/leading_slash651=== PAUSE TestIsValidCachePath/leading_slash652=== RUN TestIsValidCachePath/wrong_extension653=== PAUSE TestIsValidCachePath/wrong_extension654=== RUN TestIsValidCachePath/short_hash655=== PAUSE TestIsValidCachePath/short_hash656=== CONT TestCreatePendingClosureRejectsOversizedNAR657=== CONT TestCompleteMultipartUpload_ErrorButObjectExists6582026/09/10 09:07:42 INFO Received uploads request method=POST path=/api/pending_closures659=== RUN TestServerTLSConfig/no_client_CA660=== PAUSE TestServerTLSConfig/no_client_CA661=== RUN TestServerTLSConfig/missing_CA_file662=== PAUSE TestServerTLSConfig/missing_CA_file663=== RUN TestServerTLSConfig/not_a_PEM_file664=== PAUSE TestServerTLSConfig/not_a_PEM_file665=== CONT TestCacheConfigHandlerMaxNarSize666--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)667=== CONT TestRedundantMultipartUpload668--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)669=== CONT TestGenerateLandingPage670--- PASS: TestGenerateLandingPage (0.00s)671=== CONT TestReadRedirectUsesPublicS3URL6722026-09-10 09:07:42.339 UTC [593] ERROR: relation "goose_db_version" does not exist at character 366732026-09-10 09:07:42.339 UTC [593] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6742026-09-10 09:07:42.340 UTC [594] ERROR: relation "goose_db_version" does not exist at character 366752026-09-10 09:07:42.340 UTC [594] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6762026-09-10 09:07:42.353 UTC [596] ERROR: relation "goose_db_version" does not exist at character 366772026-09-10 09:07:42.353 UTC [596] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6782026-09-10 09:07:42.357 UTC [595] ERROR: relation "goose_db_version" does not exist at character 366792026-09-10 09:07:42.357 UTC [595] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6802026-09-10 09:07:42.359 UTC [597] ERROR: relation "goose_db_version" does not exist at character 366812026-09-10 09:07:42.359 UTC [597] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6822026-09-10 09:07:42.399 UTC [599] ERROR: relation "goose_db_version" does not exist at character 366832026-09-10 09:07:42.399 UTC [599] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6842026/09/10 09:07:42 OK 20241026095416_initial_model.sql (55.35ms)6852026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (3.46ms)6862026/09/10 09:07:42 OK 20241026095416_initial_model.sql (61.72ms)6872026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (13.88ms)6882026/09/10 09:07:42 OK 20241026095416_initial_model.sql (71.24ms)6892026/09/10 09:07:42 OK 20251218171726_add_pins.sql (20.4ms)6902026/09/10 09:07:42 OK 20251218171726_add_pins.sql (8.63ms)6912026/09/10 09:07:42 OK 20241026095416_initial_model.sql (63.69ms)6922026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (5.11ms)6932026-09-10 09:07:42.447 UTC [600] ERROR: relation "goose_db_version" does not exist at character 366942026-09-10 09:07:42.447 UTC [600] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6952026/09/10 09:07:42 OK 20241026095416_initial_model.sql (61.13ms)6962026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (8.99ms)6972026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200006982026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (5.91ms)6992026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (3.85ms)7002026-09-10 09:07:42.453 UTC [601] ERROR: relation "goose_db_version" does not exist at character 367012026-09-10 09:07:42.453 UTC [601] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7022026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (9.94ms)7032026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200007042026/09/10 09:07:42 OK 20241026095416_initial_model.sql (28.55ms)7052026/09/10 09:07:42 OK 20251218171726_add_pins.sql (9.47ms)7062026-09-10 09:07:42.455 UTC [602] ERROR: relation "goose_db_version" does not exist at character 367072026-09-10 09:07:42.455 UTC [602] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7082026/09/10 09:07:42 OK 1_commit_pending_closure.sql (5.74ms)7092026/09/10 09:07:42 OK 20251218171726_add_pins.sql (7.91ms)7102026/09/10 09:07:42 OK 20251218171726_add_pins.sql (5.92ms)7112026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (3.23ms)7122026/09/10 09:07:42 OK 1_commit_pending_closure.sql (5.07ms)7132026/09/10 09:07:42 OK 2_object_stats_trigger.sql (3.5ms)7142026/09/10 09:07:42 goose: up to current file version: 27152026/09/10 09:07:42 OK 2_object_stats_trigger.sql (2.68ms)7162026/09/10 09:07:42 goose: up to current file version: 27172026-09-10 09:07:42.471 UTC [605] ERROR: relation "goose_db_version" does not exist at character 367182026-09-10 09:07:42.471 UTC [605] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7192026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (12.59ms)7202026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200007212026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (15.91ms)7222026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200007232026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (15ms)7242026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200007252026/09/10 09:07:42 OK 20251218171726_add_pins.sql (14.5ms)7262026/09/10 09:07:42 OK 1_commit_pending_closure.sql (7.01ms)7272026/09/10 09:07:42 OK 1_commit_pending_closure.sql (6.3ms)7282026/09/10 09:07:42 OK 1_commit_pending_closure.sql (8.41ms)7292026/09/10 09:07:42 OK 2_object_stats_trigger.sql (5.19ms)7302026/09/10 09:07:42 goose: up to current file version: 27312026/09/10 09:07:42 OK 2_object_stats_trigger.sql (4.83ms)7322026/09/10 09:07:42 OK 2_object_stats_trigger.sql (4.09ms)7332026/09/10 09:07:42 goose: up to current file version: 27342026/09/10 09:07:42 goose: up to current file version: 27352026/09/10 09:07:42 OK 20241026095416_initial_model.sql (27.5ms)7362026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (11.68ms)7372026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200007382026/09/10 09:07:42 OK 20241026095416_initial_model.sql (30.27ms)7392026/09/10 09:07:42 OK 1_commit_pending_closure.sql (4.64ms)7402026/09/10 09:07:42 OK 20241026095416_initial_model.sql (31.31ms)7412026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (4.06ms)7422026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (6.52ms)7432026/09/10 09:07:42 OK 2_object_stats_trigger.sql (3.84ms)7442026/09/10 09:07:42 goose: up to current file version: 27452026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (4.36ms)7462026/09/10 09:07:42 OK 20251218171726_add_pins.sql (7.43ms)7472026/09/10 09:07:42 OK 20251218171726_add_pins.sql (7.54ms)7482026-09-10 09:07:42.512 UTC [608] ERROR: relation "goose_db_version" does not exist at character 367492026-09-10 09:07:42.512 UTC [608] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7502026/09/10 09:07:42 OK 20241026095416_initial_model.sql (25.02ms)7512026/09/10 09:07:42 OK 20251218171726_add_pins.sql (17.09ms)7522026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (13.89ms)7532026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200007542026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (13.71ms)7552026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200007562026-09-10 09:07:42.518 UTC [609] ERROR: relation "goose_db_version" does not exist at character 367572026-09-10 09:07:42.518 UTC [609] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7582026-09-10 09:07:42.519 UTC [610] ERROR: relation "goose_db_version" does not exist at character 367592026-09-10 09:07:42.519 UTC [610] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7602026-09-10 09:07:42.520 UTC [612] ERROR: relation "goose_db_version" does not exist at character 367612026-09-10 09:07:42.520 UTC [612] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7622026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (6.01ms)7632026-09-10 09:07:42.520 UTC [611] ERROR: relation "goose_db_version" does not exist at character 367642026-09-10 09:07:42.520 UTC [611] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7652026-09-10 09:07:42.522 UTC [615] ERROR: relation "goose_db_version" does not exist at character 367662026-09-10 09:07:42.522 UTC [615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7672026-09-10 09:07:42.522 UTC [613] ERROR: relation "goose_db_version" does not exist at character 367682026-09-10 09:07:42.522 UTC [613] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7692026-09-10 09:07:42.522 UTC [614] ERROR: relation "goose_db_version" does not exist at character 367702026-09-10 09:07:42.522 UTC [614] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7712026/09/10 09:07:42 OK 1_commit_pending_closure.sql (4.9ms)7722026/09/10 09:07:42 OK 1_commit_pending_closure.sql (5.28ms)7732026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (7.02ms)7742026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200007752026/09/10 09:07:42 OK 2_object_stats_trigger.sql (2.98ms)7762026/09/10 09:07:42 goose: up to current file version: 27772026/09/10 09:07:42 OK 20251218171726_add_pins.sql (6.65ms)7782026/09/10 09:07:42 OK 2_object_stats_trigger.sql (5.59ms)7792026/09/10 09:07:42 goose: up to current file version: 27802026/09/10 09:07:42 OK 1_commit_pending_closure.sql (5.86ms)7812026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (6.09ms)7822026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200007832026/09/10 09:07:42 OK 20241026095416_initial_model.sql (14.13ms)7842026-09-10 09:07:42.536 UTC [616] ERROR: relation "goose_db_version" does not exist at character 367852026-09-10 09:07:42.536 UTC [616] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7862026-09-10 09:07:42.538 UTC [617] ERROR: relation "goose_db_version" does not exist at character 367872026-09-10 09:07:42.538 UTC [617] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7882026/09/10 09:07:42 OK 2_object_stats_trigger.sql (6.87ms)7892026/09/10 09:07:42 goose: up to current file version: 27902026/09/10 09:07:42 OK 1_commit_pending_closure.sql (5.13ms)7912026-09-10 09:07:42.540 UTC [618] ERROR: relation "goose_db_version" does not exist at character 367922026-09-10 09:07:42.540 UTC [618] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7932026/09/10 09:07:42 OK 20241026095416_initial_model.sql (14.54ms)7942026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (4.92ms)7952026-09-10 09:07:42.543 UTC [619] ERROR: relation "goose_db_version" does not exist at character 367962026-09-10 09:07:42.543 UTC [619] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7972026/09/10 09:07:42 OK 2_object_stats_trigger.sql (3.47ms)7982026/09/10 09:07:42 goose: up to current file version: 27992026-09-10 09:07:42.545 UTC [620] ERROR: relation "goose_db_version" does not exist at character 368002026-09-10 09:07:42.545 UTC [620] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8012026-09-10 09:07:42.546 UTC [621] ERROR: relation "goose_db_version" does not exist at character 368022026-09-10 09:07:42.546 UTC [621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8032026/09/10 09:07:42 OK 20241026095416_initial_model.sql (14.97ms)8042026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (7.04ms)8052026/09/10 09:07:42 OK 20251218171726_add_pins.sql (8.89ms)8062026/09/10 09:07:42 OK 20241026095416_initial_model.sql (17.24ms)8072026/09/10 09:07:42 OK 20241026095416_initial_model.sql (14.87ms)8082026/09/10 09:07:42 OK 20241026095416_initial_model.sql (19.31ms)8092026/09/10 09:07:42 OK 20241026095416_initial_model.sql (16.65ms)8102026/09/10 09:07:42 OK 20241026095416_initial_model.sql (15.86ms)8112026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (5.38ms)8122026/09/10 09:07:42 OK 20251218171726_add_pins.sql (6.37ms)8132026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (4.57ms)8142026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (4.1ms)8152026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (2.49ms)8162026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (5.64ms)8172026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008182026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (3.09ms)8192026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (3.26ms)8202026/09/10 09:07:42 OK 20241026095416_initial_model.sql (13.98ms)8212026/09/10 09:07:42 OK 1_commit_pending_closure.sql (6.23ms)8222026/09/10 09:07:42 OK 20251218171726_add_pins.sql (6.96ms)8232026/09/10 09:07:42 OK 20251218171726_add_pins.sql (8.46ms)8242026/09/10 09:07:42 OK 20251218171726_add_pins.sql (7.22ms)8252026/09/10 09:07:42 OK 20251218171726_add_pins.sql (6.96ms)8262026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (7.59ms)8272026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008282026/09/10 09:07:42 OK 20251218171726_add_pins.sql (7.01ms)8292026/09/10 09:07:42 OK 20241026095416_initial_model.sql (15.26ms)8302026/09/10 09:07:42 OK 20251218171726_add_pins.sql (7.07ms)8312026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (4.07ms)8322026/09/10 09:07:42 OK 2_object_stats_trigger.sql (3.81ms)8332026/09/10 09:07:42 goose: up to current file version: 28342026/09/10 09:07:42 OK 20241026095416_initial_model.sql (14.98ms)8352026/09/10 09:07:42 OK 1_commit_pending_closure.sql (5.25ms)8362026/09/10 09:07:42 OK 20241026095416_initial_model.sql (13.96ms)8372026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (3.9ms)8382026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (7.45ms)8392026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (7.43ms)8402026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008412026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008422026/09/10 09:07:42 OK 20241026095416_initial_model.sql (15.58ms)8432026/09/10 09:07:42 OK 20251218171726_add_pins.sql (5.36ms)8442026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (7.37ms)8452026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008462026/09/10 09:07:42 OK 20241026095416_initial_model.sql (15.7ms)8472026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (7.47ms)8482026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008492026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (3.76ms)8502026/09/10 09:07:42 OK 2_object_stats_trigger.sql (2.86ms)8512026/09/10 09:07:42 goose: up to current file version: 28522026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (6.51ms)8532026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008542026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (6.59ms)8552026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008562026/09/10 09:07:42 OK 20251218171726_add_pins.sql (2.86ms)8572026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (3.09ms)8582026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)8592026/09/10 09:07:42 OK 1_commit_pending_closure.sql (3.82ms)8602026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (4.07ms)8612026/09/10 09:07:42 OK 1_commit_pending_closure.sql (3.61ms)8622026/09/10 09:07:42 OK 1_commit_pending_closure.sql (3.63ms)8632026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (3.66ms)8642026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008652026/09/10 09:07:42 OK 20251218171726_add_pins.sql (4.32ms)8662026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (4.66ms)8672026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008682026/09/10 09:07:42 OK 20251218171726_add_pins.sql (3.75ms)8692026/09/10 09:07:42 OK 2_object_stats_trigger.sql (1.05ms)8702026/09/10 09:07:42 goose: up to current file version: 28712026/09/10 09:07:42 OK 1_commit_pending_closure.sql (4.27ms)8722026/09/10 09:07:42 OK 1_commit_pending_closure.sql (4.62ms)8732026/09/10 09:07:42 OK 1_commit_pending_closure.sql (4.38ms)8742026/09/10 09:07:42 OK 2_object_stats_trigger.sql (1.01ms)8752026/09/10 09:07:42 goose: up to current file version: 28762026/09/10 09:07:42 OK 20251218171726_add_pins.sql (3.61ms)8772026/09/10 09:07:42 OK 2_object_stats_trigger.sql (1.09ms)8782026/09/10 09:07:42 goose: up to current file version: 28792026/09/10 09:07:42 OK 2_object_stats_trigger.sql (1.29ms)8802026/09/10 09:07:42 goose: up to current file version: 28812026/09/10 09:07:42 OK 2_object_stats_trigger.sql (1.56ms)8822026/09/10 09:07:42 goose: up to current file version: 28832026/09/10 09:07:42 OK 2_object_stats_trigger.sql (2.06ms)8842026/09/10 09:07:42 goose: up to current file version: 28852026/09/10 09:07:42 OK 1_commit_pending_closure.sql (2.24ms)8862026/09/10 09:07:42 OK 1_commit_pending_closure.sql (2.19ms)8872026/09/10 09:07:42 OK 20251218171726_add_pins.sql (4.44ms)8882026/09/10 09:07:42 OK 2_object_stats_trigger.sql (1.8ms)8892026/09/10 09:07:42 goose: up to current file version: 28902026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (4.12ms)8912026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008922026/09/10 09:07:42 OK 2_object_stats_trigger.sql (1.77ms)8932026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (3.98ms)8942026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200008952026/09/10 09:07:42 goose: up to current file version: 28962026/09/10 09:07:42 OK 1_commit_pending_closure.sql (2.41ms)8972026/09/10 09:07:42 OK 1_commit_pending_closure.sql (2.52ms)8982026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (5.79ms)8992026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200009002026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (3.2ms)9012026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200009022026/09/10 09:07:42 OK 2_object_stats_trigger.sql (793.43µs)9032026/09/10 09:07:42 goose: up to current file version: 29042026/09/10 09:07:42 OK 2_object_stats_trigger.sql (1.05ms)9052026/09/10 09:07:42 goose: up to current file version: 29062026/09/10 09:07:42 OK 1_commit_pending_closure.sql (1.42ms)9072026/09/10 09:07:42 OK 1_commit_pending_closure.sql (2.04ms)9082026/09/10 09:07:42 OK 2_object_stats_trigger.sql (787.55µs)9092026/09/10 09:07:42 goose: up to current file version: 29102026/09/10 09:07:42 OK 2_object_stats_trigger.sql (854.53µs)9112026/09/10 09:07:42 goose: up to current file version: 29122026/09/10 09:07:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete913--- PASS: TestReadProxyConditionalGet (0.39s)914=== CONT TestResolveDBConnectionString9152026/09/10 09:07:42 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst916=== RUN TestResolveDBConnectionString/flag_wins917--- PASS: TestCompleteMultipartUnregistered (0.39s)918=== PAUSE TestResolveDBConnectionString/flag_wins919=== CONT TestReadProxyRangeRequest920=== RUN TestResolveDBConnectionString/file_when_flag_empty921=== PAUSE TestResolveDBConnectionString/file_when_flag_empty922=== RUN TestResolveDBConnectionString/missing_file_is_an_error923=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error924=== RUN TestResolveDBConnectionString/PGHOST_allows_empty925=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty926=== RUN TestResolveDBConnectionString/nothing_configured927=== PAUSE TestResolveDBConnectionString/nothing_configured928=== CONT TestPinProtectsFromGC929--- PASS: TestReadProxy404 (0.41s)930=== CONT TestReadRedirectKeepsNarinfoProxied9312026-09-10 09:07:42.734 UTC [630] ERROR: relation "goose_db_version" does not exist at character 369322026-09-10 09:07:42.734 UTC [630] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9332026-09-10 09:07:42.735 UTC [631] ERROR: relation "goose_db_version" does not exist at character 369342026-09-10 09:07:42.735 UTC [631] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9352026/09/10 09:07:42 OK 20241026095416_initial_model.sql (11.29ms)9362026/09/10 09:07:42 OK 20241026095416_initial_model.sql (10.61ms)9372026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)9382026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (1.49ms)9392026-09-10 09:07:42.757 UTC [632] ERROR: relation "goose_db_version" does not exist at character 369402026-09-10 09:07:42.757 UTC [632] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9412026/09/10 09:07:42 OK 20251218171726_add_pins.sql (4.54ms)9422026/09/10 09:07:42 OK 20251218171726_add_pins.sql (4.37ms)9432026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (3.22ms)9442026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200009452026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)9462026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200009472026/09/10 09:07:42 OK 1_commit_pending_closure.sql (1.86ms)9482026/09/10 09:07:42 OK 1_commit_pending_closure.sql (1.95ms)9492026/09/10 09:07:42 OK 2_object_stats_trigger.sql (920.57µs)9502026/09/10 09:07:42 goose: up to current file version: 29512026/09/10 09:07:42 OK 2_object_stats_trigger.sql (875.23µs)9522026/09/10 09:07:42 goose: up to current file version: 29532026/09/10 09:07:42 OK 20241026095416_initial_model.sql (10.44ms)9542026/09/10 09:07:42 OK 20251210153512_drop_unused_gin_index.sql (1.29ms)9552026/09/10 09:07:42 OK 20251218171726_add_pins.sql (3.24ms)9562026/09/10 09:07:42 OK 20260628120000_add_object_size_and_stats.sql (2.65ms)9572026/09/10 09:07:42 goose: successfully migrated database to version: 202606281200009582026/09/10 09:07:42 OK 1_commit_pending_closure.sql (1.86ms)9592026/09/10 09:07:42 OK 2_object_stats_trigger.sql (772.17µs)9602026/09/10 09:07:42 goose: up to current file version: 29612026/09/10 09:07:42 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"962--- PASS: TestService_AuthMiddleware (0.75s)963=== CONT TestClientWithDependencies964--- PASS: TestReadProxyHead (0.79s)965=== CONT TestReadRedirectNar966--- PASS: TestReadProxyNarStreaming (0.80s)967=== CONT TestClientMultipleUploads9682026-09-10 09:07:43.063 UTC [639] ERROR: relation "goose_db_version" does not exist at character 369692026-09-10 09:07:43.063 UTC [639] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC970--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.83s)971=== CONT TestReadProxyDisabled9722026/09/10 09:07:43 OK 20241026095416_initial_model.sql (12.72ms)9732026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (3.03ms)9742026/09/10 09:07:43 OK 20251218171726_add_pins.sql (4.29ms)9752026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (11.4ms)9762026/09/10 09:07:43 goose: successfully migrated database to version: 202606281200009772026-09-10 09:07:43.107 UTC [642] ERROR: relation "goose_db_version" does not exist at character 369782026-09-10 09:07:43.107 UTC [642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9792026/09/10 09:07:43 OK 1_commit_pending_closure.sql (3.17ms)9802026/09/10 09:07:43 OK 2_object_stats_trigger.sql (2.63ms)9812026/09/10 09:07:43 goose: up to current file version: 2982--- PASS: TestMetricsInventory (0.87s)983=== CONT TestClientIntegration9842026-09-10 09:07:43.117 UTC [643] ERROR: relation "goose_db_version" does not exist at character 369852026-09-10 09:07:43.117 UTC [643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC986--- PASS: TestReadProxyInvalidPath (0.88s)987=== CONT TestClientErrorHandling988=== RUN TestClientErrorHandling/InvalidStorePath989=== PAUSE TestClientErrorHandling/InvalidStorePath990=== RUN TestClientErrorHandling/InvalidAuthToken991=== PAUSE TestClientErrorHandling/InvalidAuthToken992=== RUN TestClientErrorHandling/ServerNotAvailable993=== PAUSE TestClientErrorHandling/ServerNotAvailable994=== CONT TestUploadHandlersRejectInvalidKeys995=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info996=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info997=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal998=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal999=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1000=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1001=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1002=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1003=== CONT TestClientCADerivations10042026/09/10 09:07:43 OK 20241026095416_initial_model.sql (11.98ms)10052026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (3.39ms)10062026/09/10 09:07:43 OK 20251218171726_add_pins.sql (3.89ms)10072026/09/10 09:07:43 OK 20241026095416_initial_model.sql (12.5ms)10082026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (5.25ms)10092026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000010102026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (3.26ms)10112026/09/10 09:07:43 OK 1_commit_pending_closure.sql (3.28ms)10122026/09/10 09:07:43 OK 2_object_stats_trigger.sql (2.62ms)10132026/09/10 09:07:43 goose: up to current file version: 210142026/09/10 09:07:43 OK 20251218171726_add_pins.sql (5.06ms)10152026-09-10 09:07:43.147 UTC [648] ERROR: relation "goose_db_version" does not exist at character 3610162026-09-10 09:07:43.147 UTC [648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10172026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (4.24ms)10182026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000010192026/09/10 09:07:43 OK 1_commit_pending_closure.sql (4.18ms)10202026/09/10 09:07:43 OK 2_object_stats_trigger.sql (3.02ms)10212026/09/10 09:07:43 goose: up to current file version: 210222026/09/10 09:07:43 OK 20241026095416_initial_model.sql (11.7ms)10232026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (3.21ms)10242026/09/10 09:07:43 OK 20251218171726_add_pins.sql (4.65ms)10252026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (4.63ms)10262026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000010272026/09/10 09:07:43 INFO Received uploads request method=POST path=/api/pending_closures10282026/09/10 09:07:43 OK 1_commit_pending_closure.sql (2.11ms)10292026/09/10 09:07:43 OK 2_object_stats_trigger.sql (1.04ms)10302026/09/10 09:07:43 goose: up to current file version: 210312026-09-10 09:07:43.186 UTC [649] ERROR: relation "goose_db_version" does not exist at character 3610322026-09-10 09:07:43.186 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10332026-09-10 09:07:43.191 UTC [650] ERROR: relation "goose_db_version" does not exist at character 3610342026-09-10 09:07:43.191 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10352026/09/10 09:07:43 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10362026/09/10 09:07:43 INFO Received uploads request method=POST path=/api/pending_closures10372026/09/10 09:07:43 OK 20241026095416_initial_model.sql (12.45ms)10382026/09/10 09:07:43 OK 20241026095416_initial_model.sql (11.54ms)1039--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.96s)1040=== CONT TestService_verifyS3Integrity10412026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)10422026/09/10 09:07:43 OK 20251218171726_add_pins.sql (3.08ms)10432026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)10442026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)10452026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000010462026/09/10 09:07:43 OK 20251218171726_add_pins.sql (2.81ms)1047--- PASS: TestReadProxyNarinfo (0.98s)1048=== CONT TestCacheStatsHandler10492026/09/10 09:07:43 OK 1_commit_pending_closure.sql (2ms)10502026/09/10 09:07:43 OK 2_object_stats_trigger.sql (921.23µs)10512026/09/10 09:07:43 goose: up to current file version: 210522026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (3.83ms)10532026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000010542026/09/10 09:07:43 OK 1_commit_pending_closure.sql (2.82ms)10552026/09/10 09:07:43 OK 2_object_stats_trigger.sql (2.2ms)10562026/09/10 09:07:43 goose: up to current file version: 210572026/09/10 09:07:43 INFO Received uploads request method=POST path=/api/pending_closures1058--- PASS: TestResurrectedObjectNotDeleted (0.99s)1059=== CONT TestService_createPendingClosureHandler1060--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.02s)1061=== CONT TestOrphanedObjectsGCDeletesEachKeyOnce10622026-09-10 09:07:43.284 UTC [659] ERROR: relation "goose_db_version" does not exist at character 3610632026-09-10 09:07:43.284 UTC [659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10642026-09-10 09:07:43.301 UTC [660] ERROR: relation "goose_db_version" does not exist at character 3610652026-09-10 09:07:43.301 UTC [660] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10662026/09/10 09:07:43 OK 20241026095416_initial_model.sql (11.43ms)10672026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (2.93ms)10682026/09/10 09:07:43 OK 20251218171726_add_pins.sql (3.98ms)10692026/09/10 09:07:43 INFO Received uploads request method=POST path=/api/pending_closures10702026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (4.33ms)10712026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000010722026/09/10 09:07:43 OK 1_commit_pending_closure.sql (3.01ms)10732026/09/10 09:07:43 OK 20241026095416_initial_model.sql (11.9ms)10742026/09/10 09:07:43 OK 2_object_stats_trigger.sql (1.62ms)10752026/09/10 09:07:43 goose: up to current file version: 210762026-09-10 09:07:43.323 UTC [661] ERROR: relation "goose_db_version" does not exist at character 3610772026-09-10 09:07:43.323 UTC [661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10782026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (2.91ms)10792026/09/10 09:07:43 OK 20251218171726_add_pins.sql (3.06ms)10802026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (3.9ms)10812026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000010822026/09/10 09:07:43 OK 1_commit_pending_closure.sql (2.7ms)10832026/09/10 09:07:43 OK 2_object_stats_trigger.sql (933.85µs)10842026/09/10 09:07:43 goose: up to current file version: 210852026/09/10 09:07:43 INFO Received uploads request method=POST path=/api/pending_closures10862026/09/10 09:07:43 OK 20241026095416_initial_model.sql (9.69ms)10872026-09-10 09:07:43.340 UTC [662] ERROR: relation "goose_db_version" does not exist at character 3610882026-09-10 09:07:43.340 UTC [662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10892026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (1.83ms)10902026/09/10 09:07:43 OK 20251218171726_add_pins.sql (3.82ms)10912026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (3.2ms)10922026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000010932026/09/10 09:07:43 OK 1_commit_pending_closure.sql (2.99ms)10942026/09/10 09:07:43 INFO Received uploads request method=POST path=/api/pending_closures10952026/09/10 09:07:43 OK 2_object_stats_trigger.sql (1.85ms)10962026/09/10 09:07:43 goose: up to current file version: 210972026/09/10 09:07:43 OK 20241026095416_initial_model.sql (9.03ms)10982026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (1.57ms)10992026/09/10 09:07:43 OK 20251218171726_add_pins.sql (3.07ms)11002026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (3.03ms)11012026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000011022026/09/10 09:07:43 OK 1_commit_pending_closure.sql (1.91ms)11032026/09/10 09:07:43 OK 2_object_stats_trigger.sql (952.29µs)11042026/09/10 09:07:43 goose: up to current file version: 211052026/09/10 09:07:43 INFO Received uploads request method=POST path=/api/pending_closures1106=== NAME TestNARDeduplicationMetadataUploadBug1107 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug476853411/001/store/6lkhjbmzyl24pzazzsvyqvjcm2cxwd8d-file1.txt1108--- PASS: TestService_Rustfstest (1.18s)1109=== CONT TestCacheConfigHandler1110=== RUN TestCacheConfigHandler/full_config,_no_issuer1111=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1112=== RUN TestCacheConfigHandler/no_cache_url_configured1113=== PAUSE TestCacheConfigHandler/no_cache_url_configured1114=== RUN TestCacheConfigHandler/no_signing_keys1115=== PAUSE TestCacheConfigHandler/no_signing_keys1116=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1117=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1118=== CONT TestService_readinessHandler1119--- PASS: TestReadRedirectUsesPublicS3URL (1.18s)1120=== CONT TestService_ReadScope_PublicByDefault11212026/09/10 09:07:43 INFO Received cleanup request method=DELETE path=/api/pending_closures11222026/09/10 09:07:43 INFO Aborted multipart uploads count=11123--- PASS: TestMultipartCleanup (1.22s)1124=== CONT TestService_RequireScope_OIDC11252026/09/10 09:07:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38983/oidc11262026/09/10 09:07:43 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1127--- PASS: TestObjectStatsTrigger (1.25s)1128=== CONT TestService_AuthMiddleware_OIDC11292026/09/10 09:07:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43029/oidc11302026-09-10 09:07:43.508 UTC [724] ERROR: relation "goose_db_version" does not exist at character 3611312026-09-10 09:07:43.508 UTC [724] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11322026-09-10 09:07:43.512 UTC [726] ERROR: relation "goose_db_version" does not exist at character 3611332026-09-10 09:07:43.512 UTC [726] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11342026/09/10 09:07:43 INFO Received uploads request method=POST path=/api/pending_closures11352026/09/10 09:07:43 OK 20241026095416_initial_model.sql (11.73ms)11362026/09/10 09:07:43 OK 20241026095416_initial_model.sql (18.3ms)11372026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (6.03ms)11382026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (6.2ms)11392026/09/10 09:07:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11402026/09/10 09:07:43 INFO Uploading 6lkhjbmzyl24pzazzsvyqvjcm2cxwd8d-file1.txt (160B)11412026/09/10 09:07:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11422026/09/10 09:07:43 OK 20251218171726_add_pins.sql (5.82ms)11432026/09/10 09:07:43 OK 20251218171726_add_pins.sql (7.11ms)11442026-09-10 09:07:43.554 UTC [744] ERROR: relation "goose_db_version" does not exist at character 3611452026-09-10 09:07:43.554 UTC [744] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11462026/09/10 09:07:43 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11472026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (5.2ms)11482026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000011492026/09/10 09:07:43 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWQ1NDY3Y2ItNjkwNC00OGE4LTk2YTItMzlmZmEyMDFmYjZlLmJmMjZhNTRhLWViOWEtNDRiNy05OWQ4LWI1NjlhMjUzMDgzMXgxNzg5MDMxMjYzMjQ1NzQ4MjU111502026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (5.52ms)11512026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000011522026/09/10 09:07:43 WARN Failed to register uploaded object key=6lkhjbmzyl24pzazzsvyqvjcm2cxwd8d.ls error="server returned 404: 404 page not found\n"11532026/09/10 09:07:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11542026/09/10 09:07:43 OK 1_commit_pending_closure.sql (4.77ms)11552026/09/10 09:07:43 OK 1_commit_pending_closure.sql (6.27ms)11562026/09/10 09:07:43 INFO Signed narinfos id=1 count=111572026/09/10 09:07:43 INFO Uploading 1 narinfos11582026/09/10 09:07:43 OK 2_object_stats_trigger.sql (1.97ms)11592026/09/10 09:07:43 goose: up to current file version: 211602026/09/10 09:07:43 OK 2_object_stats_trigger.sql (2.05ms)11612026/09/10 09:07:43 goose: up to current file version: 211622026/09/10 09:07:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWQ1NDY3Y2ItNjkwNC00OGE4LTk2YTItMzlmZmEyMDFmYjZlLmJmMjZhNTRhLWViOWEtNDRiNy05OWQ4LWI1NjlhMjUzMDgzMXgxNzg5MDMxMjYzMjQ1NzQ4MjU1 parts=11163--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.32s)1164=== CONT TestService_ReadAuthMiddleware11652026/09/10 09:07:43 WARN Failed to register uploaded object key=6lkhjbmzyl24pzazzsvyqvjcm2cxwd8d.narinfo error="server returned 404: 404 page not found\n"11662026/09/10 09:07:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11672026/09/10 09:07:43 OK 20241026095416_initial_model.sql (18.31ms)11682026/09/10 09:07:43 INFO Completed upload id=111692026/09/10 09:07:43 INFO Upload complete. (135ms)11702026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)1171=== NAME TestNARDeduplicationMetadataUploadBug1172 metadata_upload_test.go:54: Retrieved narinfo from S3:1173 StorePath: /build/TestNARDeduplicationMetadataUploadBug476853411/001/store/6lkhjbmzyl24pzazzsvyqvjcm2cxwd8d-file1.txt1174 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1175 Compression: zstd1176 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1177 NarSize: 1601178 References: 1179 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf11802026/09/10 09:07:43 OK 20251218171726_add_pins.sql (4.85ms)1181 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1182 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1183 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11842026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (4.73ms)11852026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000011862026-09-10 09:07:43.595 UTC [747] ERROR: relation "goose_db_version" does not exist at character 3611872026-09-10 09:07:43.595 UTC [747] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11882026/09/10 09:07:43 OK 1_commit_pending_closure.sql (3.69ms)11892026/09/10 09:07:43 OK 2_object_stats_trigger.sql (2.37ms)11902026/09/10 09:07:43 goose: up to current file version: 211912026/09/10 09:07:43 OK 20241026095416_initial_model.sql (11.88ms)11922026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (3.43ms)11932026/09/10 09:07:43 OK 20251218171726_add_pins.sql (5.03ms)11942026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (5.39ms)11952026/09/10 09:07:43 goose: successfully migrated database to version: 202606281200001196 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug476853411/001/store/q18c1zxrl7d8scax9anv5ab2va4p36mk-file2.txt11972026/09/10 09:07:43 OK 1_commit_pending_closure.sql (3.49ms)11982026/09/10 09:07:43 OK 2_object_stats_trigger.sql (1.29ms)11992026/09/10 09:07:43 goose: up to current file version: 212002026-09-10 09:07:43.644 UTC [766] ERROR: relation "goose_db_version" does not exist at character 3612012026-09-10 09:07:43.644 UTC [766] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12022026/09/10 09:07:43 OK 20241026095416_initial_model.sql (10.59ms)12032026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (1.92ms)12042026/09/10 09:07:43 OK 20251218171726_add_pins.sql (3.88ms)12052026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (3.56ms)12062026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000012072026/09/10 09:07:43 OK 1_commit_pending_closure.sql (2.06ms)12082026/09/10 09:07:43 OK 2_object_stats_trigger.sql (1.67ms)12092026/09/10 09:07:43 goose: up to current file version: 212102026/09/10 09:07:43 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12112026/09/10 09:07:43 INFO Received uploads request method=POST path=/api/pending_closures12122026/09/10 09:07:43 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12132026/09/10 09:07:43 WARN Failed to register uploaded object key=q18c1zxrl7d8scax9anv5ab2va4p36mk.ls error="server returned 404: 404 page not found\n"12142026/09/10 09:07:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12152026/09/10 09:07:43 INFO Signed narinfos id=2 count=112162026/09/10 09:07:43 INFO Uploading 1 narinfos12172026/09/10 09:07:43 WARN Failed to register uploaded object key=q18c1zxrl7d8scax9anv5ab2va4p36mk.narinfo error="server returned 404: 404 page not found\n"12182026/09/10 09:07:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12192026/09/10 09:07:43 INFO Completed upload id=212202026/09/10 09:07:43 INFO Upload complete. (93ms)1221 metadata_upload_test.go:76: Retrieved narinfo from S3:1222 StorePath: /build/TestNARDeduplicationMetadataUploadBug476853411/001/store/q18c1zxrl7d8scax9anv5ab2va4p36mk-file2.txt1223 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1224 Compression: zstd1225 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1226 NarSize: 1601227 References: 1228 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1229 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1230 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1231 {"version":1,"root":{"type":"regular","size":44}}1232--- PASS: TestNARDeduplicationMetadataUploadBug (1.52s)1233=== CONT TestService_AuthMiddleware_MTLSBoundSubjects12342026-09-10 09:07:43.840 UTC [822] ERROR: relation "goose_db_version" does not exist at character 3612352026-09-10 09:07:43.840 UTC [822] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12362026/09/10 09:07:43 OK 20241026095416_initial_model.sql (9.8ms)12372026/09/10 09:07:43 OK 20251210153512_drop_unused_gin_index.sql (1.34ms)12382026/09/10 09:07:43 OK 20251218171726_add_pins.sql (3.1ms)12392026/09/10 09:07:43 OK 20260628120000_add_object_size_and_stats.sql (2.83ms)12402026/09/10 09:07:43 goose: successfully migrated database to version: 2026062812000012412026/09/10 09:07:43 OK 1_commit_pending_closure.sql (1.93ms)12422026/09/10 09:07:43 OK 2_object_stats_trigger.sql (811.53µs)12432026/09/10 09:07:43 goose: up to current file version: 212442026/09/10 09:07:44 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12452026/09/10 09:07:44 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1246--- PASS: TestService_NativeMTLS (1.78s)1247=== CONT TestService_healthCheckHandler12482026-09-10 09:07:44.092 UTC [833] ERROR: relation "goose_db_version" does not exist at character 3612492026-09-10 09:07:44.092 UTC [833] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12502026/09/10 09:07:44 OK 20241026095416_initial_model.sql (14.37ms)12512026/09/10 09:07:44 OK 20251210153512_drop_unused_gin_index.sql (1.51ms)1252--- PASS: TestReadRedirectKeepsNarinfoProxied (1.47s)1253=== CONT TestService_AuthMiddleware_MTLSProxyHeader12542026/09/10 09:07:44 OK 20251218171726_add_pins.sql (5.21ms)1255--- PASS: TestReadProxyRangeRequest (1.49s)1256=== CONT TestGracefulShutdownDrainsInflight12572026/09/10 09:07:44 INFO Starting HTTP server address=127.0.0.1:3510512582026/09/10 09:07:44 INFO Shutdown signal received, draining in-flight requests timeout=10s1259=== NAME TestOrphanedObjectsGC1260 orphaned_objects_gc_test.go:290: GC Test Summary:1261 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1262 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1263 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1264 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1265 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1266--- PASS: TestOrphanedObjectsGC (1.88s)1267=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT12682026/09/10 09:07:44 OK 20260628120000_add_object_size_and_stats.sql (4.48ms)12692026/09/10 09:07:44 goose: successfully migrated database to version: 2026062812000012702026/09/10 09:07:44 OK 1_commit_pending_closure.sql (1.99ms)12712026/09/10 09:07:44 OK 2_object_stats_trigger.sql (869.81µs)12722026/09/10 09:07:44 goose: up to current file version: 21273=== NAME TestPinProtectsFromGC1274 client_integration_test.go:648: Pinned store path: /build/TestPinProtectsFromGC1611540468/001/store/dcgrhljjms6dqwdi0rg4ipdk8xbwmsvc-pinned-file.txt1275 client_integration_test.go:649: Unpinned store path: /build/TestPinProtectsFromGC1611540468/001/store/s1i98xa17687dgg8wbw2nanj1z9k3ibz-unpinned-file.txt1276--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1277=== CONT TestService_cleanupPendingClosuresHandler12782026/09/10 09:07:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12792026-09-10 09:07:44.210 UTC [914] ERROR: relation "goose_db_version" does not exist at character 3612802026-09-10 09:07:44.210 UTC [914] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12812026-09-10 09:07:44.214 UTC [916] ERROR: relation "goose_db_version" does not exist at character 3612822026-09-10 09:07:44.214 UTC [916] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12832026/09/10 09:07:44 OK 20241026095416_initial_model.sql (13.35ms)12842026/09/10 09:07:44 OK 20241026095416_initial_model.sql (12.86ms)12852026/09/10 09:07:44 OK 20251210153512_drop_unused_gin_index.sql (2.16ms)12862026/09/10 09:07:44 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)12872026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures12882026/09/10 09:07:44 OK 20251218171726_add_pins.sql (5.21ms)12892026/09/10 09:07:44 OK 20251218171726_add_pins.sql (5.42ms)12902026/09/10 09:07:44 OK 20260628120000_add_object_size_and_stats.sql (4.46ms)12912026/09/10 09:07:44 goose: successfully migrated database to version: 2026062812000012922026/09/10 09:07:44 OK 20260628120000_add_object_size_and_stats.sql (6.77ms)12932026/09/10 09:07:44 goose: successfully migrated database to version: 2026062812000012942026/09/10 09:07:44 OK 1_commit_pending_closure.sql (3.59ms)12952026/09/10 09:07:44 OK 1_commit_pending_closure.sql (2.67ms)12962026/09/10 09:07:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12972026/09/10 09:07:44 INFO Uploading dcgrhljjms6dqwdi0rg4ipdk8xbwmsvc-pinned-file.txt (128B)12982026/09/10 09:07:44 OK 2_object_stats_trigger.sql (1.95ms)12992026/09/10 09:07:44 goose: up to current file version: 213002026/09/10 09:07:44 OK 2_object_stats_trigger.sql (2.46ms)13012026/09/10 09:07:44 goose: up to current file version: 213022026-09-10 09:07:44.265 UTC [934] ERROR: relation "goose_db_version" does not exist at character 3613032026-09-10 09:07:44.265 UTC [934] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13042026/09/10 09:07:44 OK 20241026095416_initial_model.sql (10.9ms)13052026/09/10 09:07:44 OK 20251210153512_drop_unused_gin_index.sql (1.18ms)13062026/09/10 09:07:44 OK 20251218171726_add_pins.sql (3.3ms)13072026/09/10 09:07:44 OK 20260628120000_add_object_size_and_stats.sql (2.59ms)13082026/09/10 09:07:44 goose: successfully migrated database to version: 2026062812000013092026/09/10 09:07:44 OK 1_commit_pending_closure.sql (1.71ms)13102026/09/10 09:07:44 OK 2_object_stats_trigger.sql (763.39µs)13112026/09/10 09:07:44 goose: up to current file version: 213122026/09/10 09:07:44 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"13132026/09/10 09:07:44 WARN Failed to register uploaded object key=dcgrhljjms6dqwdi0rg4ipdk8xbwmsvc.ls error="server returned 404: 404 page not found\n"13142026/09/10 09:07:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13152026/09/10 09:07:44 INFO Signed narinfos id=1 count=113162026/09/10 09:07:44 INFO Uploading 1 narinfos13172026/09/10 09:07:44 WARN Failed to register uploaded object key=dcgrhljjms6dqwdi0rg4ipdk8xbwmsvc.narinfo error="server returned 404: 404 page not found\n"13182026/09/10 09:07:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13192026/09/10 09:07:44 INFO Completed upload id=113202026/09/10 09:07:44 INFO Upload complete. (421ms)1321--- PASS: TestReadRedirectNar (1.59s)1322=== CONT TestGCTaskStore_Fail1323--- PASS: TestGCTaskStore_Fail (0.00s)1324=== CONT TestUploadHandlersRejectOversizedBody1325--- PASS: TestReadProxyDisabled (1.59s)1326=== CONT TestProxyWriteTimeout1327=== RUN TestProxyWriteTimeout/narinfo1328=== PAUSE TestProxyWriteTimeout/narinfo1329=== RUN TestProxyWriteTimeout/1_GiB_nar1330=== PAUSE TestProxyWriteTimeout/1_GiB_nar1331=== RUN TestProxyWriteTimeout/10_GiB_nar1332=== PAUSE TestProxyWriteTimeout/10_GiB_nar1333=== RUN TestProxyWriteTimeout/unknown_size1334=== PAUSE TestProxyWriteTimeout/unknown_size1335=== CONT TestGCTaskStore_PhaseUpdates1336--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1337=== CONT TestIsValidUploadKey1338=== RUN TestIsValidUploadKey/narinfo1339=== PAUSE TestIsValidUploadKey/narinfo1340=== RUN TestIsValidUploadKey/nar_zst1341=== PAUSE TestIsValidUploadKey/nar_zst1342=== RUN TestIsValidUploadKey/nar_xz1343=== PAUSE TestIsValidUploadKey/nar_xz1344=== RUN TestIsValidUploadKey/nar_plain1345=== PAUSE TestIsValidUploadKey/nar_plain1346=== RUN TestIsValidUploadKey/listing1347=== PAUSE TestIsValidUploadKey/listing1348=== RUN TestIsValidUploadKey/build_log1349=== PAUSE TestIsValidUploadKey/build_log1350=== RUN TestIsValidUploadKey/build_log_home-manager_file1351=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1352=== RUN TestIsValidUploadKey/build_log_plus_in_name1353=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1354=== RUN TestIsValidUploadKey/build_log_question_mark1355=== PAUSE TestIsValidUploadKey/build_log_question_mark1356=== RUN TestIsValidUploadKey/build_log_equals1357=== PAUSE TestIsValidUploadKey/build_log_equals1358=== RUN TestIsValidUploadKey/realisation1359=== PAUSE TestIsValidUploadKey/realisation1360=== RUN TestIsValidUploadKey/realisation_plus_in_output1361=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1362=== RUN TestIsValidUploadKey/nix-cache-info1363=== PAUSE TestIsValidUploadKey/nix-cache-info1364=== RUN TestIsValidUploadKey/index.html1365=== PAUSE TestIsValidUploadKey/index.html1366=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1367=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1368=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1369=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1370=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1371=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1372=== RUN TestIsValidUploadKey/traversal1373=== PAUSE TestIsValidUploadKey/traversal1374=== RUN TestIsValidUploadKey/traversal_nar1375=== PAUSE TestIsValidUploadKey/traversal_nar1376=== RUN TestIsValidUploadKey/absolute1377=== PAUSE TestIsValidUploadKey/absolute1378=== RUN TestIsValidUploadKey/empty_key1379=== PAUSE TestIsValidUploadKey/empty_key1380=== RUN TestIsValidUploadKey/unknown_type1381=== PAUSE TestIsValidUploadKey/unknown_type1382=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle13832026/09/10 09:07:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1384=== NAME TestClientMultipleUploads1385 client_integration_test.go:339: Created store path 0: /build/TestClientMultipleUploads1577387490/001/store/nms69mxv0vg9alzi8fx1c5rhljqkiqny-test-file-0.txt1386=== NAME TestClientWithDependencies1387 client_integration_test.go:594: Built derivation: /build/TestClientWithDependencies2648327291/001/store/nzcvmfq3zl4r807jijcx4xyy18s811hj-test-script13882026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures13892026/09/10 09:07:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13902026/09/10 09:07:44 INFO Uploading s1i98xa17687dgg8wbw2nanj1z9k3ibz-unpinned-file.txt (128B)13912026/09/10 09:07:44 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"1392 client_integration_test.go:596: Found 1 dependencies (including self)1393=== NAME TestClientMultipleUploads1394 client_integration_test.go:339: Created store path 1: /build/TestClientMultipleUploads1577387490/001/store/9sij1s23c7chw8lppg132pjh6jbqcl2m-test-file-1.txt13952026/09/10 09:07:44 WARN Failed to register uploaded object key=s1i98xa17687dgg8wbw2nanj1z9k3ibz.ls error="server returned 404: 404 page not found\n"13962026/09/10 09:07:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13972026/09/10 09:07:44 INFO Signed narinfos id=2 count=113982026/09/10 09:07:44 INFO Uploading 1 narinfos13992026/09/10 09:07:44 WARN Failed to register uploaded object key=s1i98xa17687dgg8wbw2nanj1z9k3ibz.narinfo error="server returned 404: 404 page not found\n"14002026/09/10 09:07:44 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14012026/09/10 09:07:44 INFO Completed upload id=214022026/09/10 09:07:44 INFO Upload complete. (106ms)14032026-09-10 09:07:44.736 UTC [1080] ERROR: relation "goose_db_version" does not exist at character 3614042026-09-10 09:07:44.736 UTC [1080] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14052026/09/10 09:07:44 OK 20241026095416_initial_model.sql (13.16ms)14062026/09/10 09:07:44 OK 20251210153512_drop_unused_gin_index.sql (1.5ms)14072026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures1408 client_integration_test.go:339: Created store path 2: /build/TestClientMultipleUploads1577387490/001/store/r2nr4qhhagzdccq5nlx9pmk1np784401-test-file-2.txt14092026/09/10 09:07:44 OK 20251218171726_add_pins.sql (4.11ms)14102026/09/10 09:07:44 OK 20260628120000_add_object_size_and_stats.sql (5.59ms)14112026/09/10 09:07:44 goose: successfully migrated database to version: 2026062812000014122026/09/10 09:07:44 OK 1_commit_pending_closure.sql (2.1ms)14132026/09/10 09:07:44 OK 2_object_stats_trigger.sql (1.33ms)14142026/09/10 09:07:44 goose: up to current file version: 214152026/09/10 09:07:44 INFO Received create pin request method=POST path=/api/pins/myapp1416=== NAME TestClientIntegration1417 client_integration_test.go:277: Created store path: /build/TestClientIntegration3798429366/002/store/fszv532aj0v056z7vz6msmf67xqm23i0-test-file.txt14182026/09/10 09:07:44 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1611540468/001/store/dcgrhljjms6dqwdi0rg4ipdk8xbwmsvc-pinned-file.txt narinfo_key=dcgrhljjms6dqwdi0rg4ipdk8xbwmsvc.narinfo14192026/09/10 09:07:44 INFO Starting cleanup of old closures method=DELETE path=/api/closures14202026/09/10 09:07:44 INFO Garbage collection started14212026/09/10 09:07:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14222026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures14232026/09/10 09:07:44 INFO Aborted multipart uploads count=014242026/09/10 09:07:44 WARN Force mode enabled - objects will be deleted immediately without grace period1425=== NAME TestClientCADerivations1426 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1651512189/001/store/3rv42xc28zck5cni5jl5gqf80jz8jasb-ca-test1427--- PASS: TestCacheStatsHandler (1.58s)1428=== CONT TestGCTaskStore_CompletedAllowsNewTask1429--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1430=== CONT TestGCTaskStore_DeduplicateSameParams1431--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1432=== CONT TestSkippedUploadsHandler14332026/09/10 09:07:44 INFO Client skipped oversized paths paths=3 nar_bytes=500000000014342026/09/10 09:07:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14352026/09/10 09:07:44 INFO Uploading nzcvmfq3zl4r807jijcx4xyy18s811hj-test-script (136B)1436=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1437=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1438=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1439=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1440=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1441=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1442=== CONT TestGCTaskStore_StartNew1443--- PASS: TestGCTaskStore_StartNew (0.00s)1444=== CONT TestGCTaskStore_GetReturnsLatest1445--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1446=== CONT TestGCTaskStore_ConflictDifferentParams1447--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1448=== CONT TestOrphanedObjectsGCFallsBackToSingleDeletes1449--- PASS: TestSkippedUploadsHandler (0.01s)1450=== CONT TestGCBugBareHashReferences14512026/09/10 09:07:44 WARN Failed to register uploaded object key=log/7r92i3gqvf4l9ada8byw0msyslnm019h-test-script.drv error="server returned 404: 404 page not found\n"14522026/09/10 09:07:44 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"14532026/09/10 09:07:44 WARN Failed to register uploaded object key=nzcvmfq3zl4r807jijcx4xyy18s811hj.ls error="server returned 404: 404 page not found\n"14542026/09/10 09:07:44 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=014552026/09/10 09:07:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14562026/09/10 09:07:44 INFO Signed narinfos id=1 count=114572026/09/10 09:07:44 INFO Uploading 1 narinfos14582026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures14592026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures14602026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures14612026/09/10 09:07:44 WARN Failed to register uploaded object key=nzcvmfq3zl4r807jijcx4xyy18s811hj.narinfo error="server returned 404: 404 page not found\n"14622026/09/10 09:07:44 INFO Vacuumed table table=pending_closures14632026/09/10 09:07:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14642026/09/10 09:07:44 INFO Vacuumed table table=pending_objects14652026/09/10 09:07:44 INFO Vacuumed table table=multipart_uploads14662026/09/10 09:07:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14672026/09/10 09:07:44 INFO Vacuumed table table=closures1468=== NAME TestClientCADerivations14692026/09/10 09:07:44 INFO Completed upload id=11470 client_ca_test.go:139: Found 1 dependencies (including self)14712026/09/10 09:07:44 INFO Upload complete. (80ms)14722026/09/10 09:07:44 INFO Vacuumed table table=objects1473=== NAME TestClientWithDependencies1474 client_integration_test.go:598: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2648327291/001/store) requires matching store prefix1475--- PASS: TestClientWithDependencies (1.86s)1476=== CONT TestGCMetrics14772026/09/10 09:07:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14782026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures14792026/09/10 09:07:44 WARN readiness check failed error="closed pool"1480--- PASS: TestService_readinessHandler (1.47s)1481=== CONT TestGCTaskStore_GetEmpty1482--- PASS: TestGCTaskStore_GetEmpty (0.00s)1483=== CONT TestParseSingleRange/none1484=== CONT TestIsValidCachePath/narinfo1485=== CONT TestIsValidCachePath/leading_slash1486=== CONT TestParseSingleRange/start_far_past_EOF1487=== CONT TestParseSingleRange/start_past_EOF1488=== CONT TestParseSingleRange/single_byte1489=== CONT TestParseSingleRange/suffix_exceeds_size1490=== CONT TestParseSingleRange/suffix1491=== CONT TestParseSingleRange/end_clamped_to_size1492=== CONT TestParseSingleRange/open-ended1493=== CONT TestParseSingleRange/closed1494=== CONT TestParseSingleRange/malformed_end_before_start1495=== CONT TestParseSingleRange/malformed_both_empty1496=== CONT TestParseSingleRange/malformed_no_dash1497=== CONT TestParseSingleRange/multi-range_ignored1498=== CONT TestParseSingleRange/unknown_unit1499--- PASS: TestParseSingleRange (0.00s)1500 --- PASS: TestParseSingleRange/none (0.00s)1501 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1502 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1503 --- PASS: TestParseSingleRange/single_byte (0.00s)1504 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1505 --- PASS: TestParseSingleRange/suffix (0.00s)1506 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1507 --- PASS: TestParseSingleRange/open-ended (0.00s)1508 --- PASS: TestParseSingleRange/closed (0.00s)1509 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1510 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1511 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1512 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1513 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1514=== CONT TestIsValidCachePath/wrong_extension1515=== CONT TestIsValidCachePath/short_hash1516=== CONT TestIsValidCachePath/nix-cache-info1517=== CONT TestIsValidCachePath/empty1518=== CONT TestIsValidCachePath/random_path1519=== CONT TestIsValidCachePath/invalid_char_u1520=== CONT TestIsValidCachePath/invalid_char_e1521=== CONT TestIsValidCachePath/traversal_in_middle1522=== CONT TestIsValidCachePath/traversal_parent1523=== CONT TestIsValidCachePath/index.html1524=== CONT TestIsValidCachePath/nar_uncompressed1525=== CONT TestIsValidCachePath/realisation1526=== CONT TestIsValidCachePath/log1527=== CONT TestIsValidCachePath/ls1528=== CONT TestServerTLSConfig/no_client_CA1529=== CONT TestIsValidCachePath/nar_xz1530=== CONT TestIsValidCachePath/nar_bz21531=== CONT TestServerTLSConfig/not_a_PEM_file1532=== CONT TestServerTLSConfig/missing_CA_file1533--- PASS: TestServerTLSConfig (0.00s)1534 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1535 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1536 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1537=== CONT TestIsValidCachePath/nar_zst1538=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1539--- PASS: TestIsValidCachePath (0.00s)1540 --- PASS: TestIsValidCachePath/narinfo (0.00s)1541 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1542 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1543 --- PASS: TestIsValidCachePath/short_hash (0.00s)1544 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1545 --- PASS: TestIsValidCachePath/empty (0.00s)1546 --- PASS: TestIsValidCachePath/random_path (0.00s)1547 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1548 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1549 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1550 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1551 --- PASS: TestIsValidCachePath/index.html (0.00s)1552 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1553 --- PASS: TestIsValidCachePath/realisation (0.00s)1554 --- PASS: TestIsValidCachePath/log (0.00s)1555 --- PASS: TestIsValidCachePath/ls (0.00s)1556 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1557 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1558 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1559 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1560=== CONT TestResolveDBConnectionString/flag_wins1561=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1562=== CONT TestResolveDBConnectionString/missing_file_is_an_error1563=== CONT TestResolveDBConnectionString/file_when_flag_empty1564=== CONT TestResolveDBConnectionString/nothing_configured1565=== CONT TestClientErrorHandling/InvalidStorePath1566--- PASS: TestResolveDBConnectionString (0.00s)1567 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1568 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1569 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1570 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1571 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)15722026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures15732026-09-10 09:07:44.906 UTC [1341] ERROR: relation "goose_db_version" does not exist at character 3615742026-09-10 09:07:44.906 UTC [1341] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15752026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures15762026/09/10 09:07:44 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15772026/09/10 09:07:44 INFO Uploading 9sij1s23c7chw8lppg132pjh6jbqcl2m-test-file-1.txt (160B)15782026/09/10 09:07:44 INFO Uploading r2nr4qhhagzdccq5nlx9pmk1np784401-test-file-2.txt (160B)15792026/09/10 09:07:44 INFO Uploading nms69mxv0vg9alzi8fx1c5rhljqkiqny-test-file-0.txt (160B)15802026-09-10 09:07:44.912 UTC [1342] ERROR: relation "goose_db_version" does not exist at character 3615812026-09-10 09:07:44.912 UTC [1342] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15822026/09/10 09:07:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"15832026/09/10 09:07:44 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15842026/09/10 09:07:44 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15852026/09/10 09:07:44 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15862026/09/10 09:07:44 WARN Failed to register uploaded object key=9sij1s23c7chw8lppg132pjh6jbqcl2m.ls error="server returned 404: 404 page not found\n"15872026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures15882026/09/10 09:07:44 WARN Failed to register uploaded object key=nms69mxv0vg9alzi8fx1c5rhljqkiqny.ls error="server returned 404: 404 page not found\n"15892026/09/10 09:07:44 WARN Failed to register uploaded object key=r2nr4qhhagzdccq5nlx9pmk1np784401.ls error="server returned 404: 404 page not found\n"15902026/09/10 09:07:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15912026/09/10 09:07:44 INFO Signed narinfos id=1 count=115922026/09/10 09:07:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign1593--- PASS: TestService_ReadScope_PublicByDefault (1.50s)1594=== CONT TestClientErrorHandling/InvalidAuthToken15952026/09/10 09:07:44 INFO Signed narinfos id=2 count=115962026/09/10 09:07:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign15972026/09/10 09:07:44 INFO Signed narinfos id=3 count=115982026/09/10 09:07:44 INFO Uploading 3 narinfos15992026/09/10 09:07:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16002026/09/10 09:07:44 INFO Uploading fszv532aj0v056z7vz6msmf67xqm23i0-test-file.txt (152B)16012026/09/10 09:07:44 OK 20241026095416_initial_model.sql (18.58ms)16022026-09-10 09:07:44.937 UTC [1379] ERROR: relation "goose_db_version" does not exist at character 3616032026-09-10 09:07:44.937 UTC [1379] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16042026/09/10 09:07:44 OK 20241026095416_initial_model.sql (15.17ms)16052026/09/10 09:07:44 WARN Failed to register uploaded object key=9sij1s23c7chw8lppg132pjh6jbqcl2m.narinfo error="server returned 404: 404 page not found\n"16062026/09/10 09:07:44 WARN Failed to register uploaded object key=nms69mxv0vg9alzi8fx1c5rhljqkiqny.narinfo error="server returned 404: 404 page not found\n"16072026/09/10 09:07:44 WARN Failed to register uploaded object key=r2nr4qhhagzdccq5nlx9pmk1np784401.narinfo error="server returned 404: 404 page not found\n"16082026/09/10 09:07:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16092026/09/10 09:07:44 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16102026/09/10 09:07:44 OK 20251210153512_drop_unused_gin_index.sql (7.81ms)16112026/09/10 09:07:44 WARN Failed to register uploaded object key=fszv532aj0v056z7vz6msmf67xqm23i0.ls error="server returned 404: 404 page not found\n"16122026/09/10 09:07:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16132026/09/10 09:07:44 OK 20251210153512_drop_unused_gin_index.sql (10.63ms)16142026/09/10 09:07:44 INFO Signed narinfos id=1 count=116152026/09/10 09:07:44 INFO Completed upload id=116162026/09/10 09:07:44 INFO Uploading 1 narinfos16172026/09/10 09:07:44 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16182026/09/10 09:07:44 OK 20251218171726_add_pins.sql (5.03ms)16192026/09/10 09:07:44 INFO Completed upload id=216202026/09/10 09:07:44 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete16212026/09/10 09:07:44 WARN Failed to register uploaded object key=fszv532aj0v056z7vz6msmf67xqm23i0.narinfo error="server returned 404: 404 page not found\n"16222026/09/10 09:07:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16232026/09/10 09:07:44 INFO Received uploads request method=POST path=/api/pending_closures16242026/09/10 09:07:44 OK 20251218171726_add_pins.sql (15.43ms)16252026/09/10 09:07:44 INFO Completed upload id=116262026/09/10 09:07:44 INFO Completed upload id=316272026/09/10 09:07:44 INFO Upload complete. (140ms)16282026/09/10 09:07:44 OK 20241026095416_initial_model.sql (17.78ms)16292026/09/10 09:07:44 OK 20260628120000_add_object_size_and_stats.sql (15.21ms)16302026/09/10 09:07:44 goose: successfully migrated database to version: 2026062812000016312026/09/10 09:07:44 INFO Upload complete. (171ms)1632=== NAME TestClientMultipleUploads1633 client_integration_test.go:350: Uploaded 3 paths in 205.02632ms1634=== NAME TestClientIntegration1635 client_integration_test.go:293: Retrieved narinfo from S3:1636 StorePath: /build/TestClientIntegration3798429366/002/store/fszv532aj0v056z7vz6msmf67xqm23i0-test-file.txt1637 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1638 Compression: zstd1639 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11640 NarSize: 1521641 References: 1642 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk116432026/09/10 09:07:44 OK 20251210153512_drop_unused_gin_index.sql (3.83ms)16442026/09/10 09:07:44 OK 1_commit_pending_closure.sql (4.81ms)16452026/09/10 09:07:44 OK 20260628120000_add_object_size_and_stats.sql (7.97ms)16462026/09/10 09:07:44 goose: successfully migrated database to version: 2026062812000016472026/09/10 09:07:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16482026/09/10 09:07:44 INFO Uploading 3rv42xc28zck5cni5jl5gqf80jz8jasb-ca-test (144B)1649 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1650 client_integration_test.go:294: Decompressed .ls content (64 bytes):1651 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1652 client_integration_test.go:297: Testing garbage collection...16532026/09/10 09:07:44 OK 2_object_stats_trigger.sql (2.99ms)16542026/09/10 09:07:44 goose: up to current file version: 216552026/09/10 09:07:44 OK 20251218171726_add_pins.sql (4.51ms)16562026/09/10 09:07:44 OK 1_commit_pending_closure.sql (3.88ms)16572026/09/10 09:07:44 WARN Failed to register uploaded object key=log/8ky4ihqrxglxs9frpsg6b895ik7y5l4d-ca-test.drv error="server returned 404: 404 page not found\n"16582026/09/10 09:07:44 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16592026/09/10 09:07:44 OK 2_object_stats_trigger.sql (3.14ms)16602026/09/10 09:07:44 goose: up to current file version: 216612026/09/10 09:07:44 OK 20260628120000_add_object_size_and_stats.sql (4.47ms)16622026/09/10 09:07:44 goose: successfully migrated database to version: 202606281200001663--- PASS: TestClientMultipleUploads (1.94s)1664=== CONT TestClientErrorHandling/ServerNotAvailable16652026/09/10 09:07:44 OK 1_commit_pending_closure.sql (2.8ms)16662026/09/10 09:07:44 WARN Failed to register uploaded object key=3rv42xc28zck5cni5jl5gqf80jz8jasb.ls error="server returned 404: 404 page not found\n"16672026/09/10 09:07:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16682026/09/10 09:07:44 OK 2_object_stats_trigger.sql (2.32ms)16692026/09/10 09:07:44 goose: up to current file version: 216702026/09/10 09:07:44 INFO Signed narinfos id=1 count=116712026/09/10 09:07:44 INFO Uploading 1 narinfos16722026-09-10 09:07:44.988 UTC [1399] ERROR: relation "goose_db_version" does not exist at character 3616732026-09-10 09:07:44.988 UTC [1399] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16742026/09/10 09:07:44 WARN Failed to register uploaded object key=3rv42xc28zck5cni5jl5gqf80jz8jasb.narinfo error="server returned 404: 404 page not found\n"16752026/09/10 09:07:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16762026/09/10 09:07:45 INFO Completed upload id=116772026/09/10 09:07:45 INFO Upload complete. (130ms)16782026/09/10 09:07:45 OK 20241026095416_initial_model.sql (11.52ms)16792026/09/10 09:07:45 OK 20251210153512_drop_unused_gin_index.sql (1.62ms)16802026/09/10 09:07:45 INFO Starting cleanup of old closures method=DELETE path=/api/closures16812026/09/10 09:07:45 INFO Garbage collection started16822026/09/10 09:07:45 OK 20251218171726_add_pins.sql (4.83ms)16832026-09-10 09:07:45.016 UTC [1418] ERROR: relation "goose_db_version" does not exist at character 3616842026-09-10 09:07:45.016 UTC [1418] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16852026/09/10 09:07:45 OK 20260628120000_add_object_size_and_stats.sql (3.86ms)16862026/09/10 09:07:45 goose: successfully migrated database to version: 2026062812000016872026/09/10 09:07:45 INFO Aborted multipart uploads count=016882026/09/10 09:07:45 OK 1_commit_pending_closure.sql (2.07ms)16892026/09/10 09:07:45 OK 2_object_stats_trigger.sql (1.38ms)16902026/09/10 09:07:45 goose: up to current file version: 216912026/09/10 09:07:45 WARN Force mode enabled - objects will be deleted immediately without grace period16922026/09/10 09:07:45 OK 20241026095416_initial_model.sql (10.8ms)16932026/09/10 09:07:45 OK 20251210153512_drop_unused_gin_index.sql (1.45ms)16942026/09/10 09:07:45 OK 20251218171726_add_pins.sql (4.46ms)16952026/09/10 09:07:45 OK 20260628120000_add_object_size_and_stats.sql (4.19ms)16962026/09/10 09:07:45 goose: successfully migrated database to version: 2026062812000016972026/09/10 09:07:45 OK 1_commit_pending_closure.sql (2.22ms)16982026/09/10 09:07:45 OK 2_object_stats_trigger.sql (1.02ms)16992026/09/10 09:07:45 goose: up to current file version: 217002026/09/10 09:07:45 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-config17012026/09/10 09:07:45 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=209.222928ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1702=== NAME TestClientCADerivations1703 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1651512189/001/store/3rv42xc28zck5cni5jl5gqf80jz8jasb-ca-test1704 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1705 Compression: zstd1706 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1707 NarSize: 1441708 References: 1709 Deriver: /build/TestClientCADerivations1651512189/001/store/8ky4ihqrxglxs9frpsg6b895ik7y5l4d-ca-test.drv1710 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1711 client_ca_test.go:185: Checking for realisation files in S3...1712 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1713 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache17142026/09/10 09:07:45 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=017152026/09/10 09:07:45 INFO Vacuumed table table=pending_closures17162026/09/10 09:07:45 INFO Vacuumed table table=pending_objects17172026/09/10 09:07:45 INFO Vacuumed table table=multipart_uploads17182026/09/10 09:07:45 INFO Vacuumed table table=closures17192026/09/10 09:07:45 INFO Vacuumed table table=objects17202026/09/10 09:07:45 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=372.186307ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1721=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1722=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1723=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1724=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1725=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1726=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1727=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1728=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1729=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17302026/09/10 09:07:45 INFO Received uploads request method=POST path=/1731=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17322026/09/10 09:07:45 INFO Received complete multipart upload request method=POST path=/1733=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17342026/09/10 09:07:45 INFO Received request for more parts method=POST path=/1735=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17362026/09/10 09:07:45 INFO Received uploads request method=POST path=/1737=== CONT TestCacheConfigHandler/full_config,_no_issuer1738--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1739 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1740 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1741 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1742 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1743=== CONT TestCacheConfigHandler/no_signing_keys1744=== CONT TestCacheConfigHandler/no_cache_url_configured1745=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1746--- PASS: TestCacheConfigHandler (0.00s)1747 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1748 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1749 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1750 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1751=== CONT TestProxyWriteTimeout/narinfo1752=== CONT TestProxyWriteTimeout/10_GiB_nar1753=== CONT TestProxyWriteTimeout/1_GiB_nar1754=== CONT TestProxyWriteTimeout/unknown_size1755--- PASS: TestProxyWriteTimeout (0.00s)1756 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1757 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1758 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1759 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1760=== CONT TestIsValidUploadKey/narinfo1761=== CONT TestIsValidUploadKey/index.html1762=== CONT TestIsValidUploadKey/nix-cache-info1763=== CONT TestIsValidUploadKey/realisation_plus_in_output1764=== CONT TestIsValidUploadKey/realisation1765=== CONT TestIsValidUploadKey/build_log_equals1766=== CONT TestIsValidUploadKey/build_log_question_mark1767=== CONT TestIsValidUploadKey/build_log_plus_in_name1768=== CONT TestIsValidUploadKey/build_log_home-manager_file1769=== CONT TestIsValidUploadKey/build_log1770=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1771=== CONT TestIsValidUploadKey/listing1772=== CONT TestIsValidUploadKey/nar_plain1773=== CONT TestIsValidUploadKey/nar_xz1774=== CONT TestIsValidUploadKey/nar_zst1775=== CONT TestIsValidUploadKey/traversal_nar1776=== CONT TestIsValidUploadKey/absolute1777=== CONT TestIsValidUploadKey/unknown_type1778=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1779=== CONT TestIsValidUploadKey/traversal1780=== CONT TestIsValidUploadKey/empty_key1781=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1782--- PASS: TestIsValidUploadKey (0.00s)1783 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1784 --- PASS: TestIsValidUploadKey/index.html (0.00s)1785 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1786 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1787 --- PASS: TestIsValidUploadKey/realisation (0.00s)1788 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1789 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1790 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1791 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1792 --- PASS: TestIsValidUploadKey/build_log (0.00s)1793 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1794 --- PASS: TestIsValidUploadKey/listing (0.00s)1795 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1796 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1797 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1798 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1799 --- PASS: TestIsValidUploadKey/absolute (0.00s)1800 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1801 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1802 --- PASS: TestIsValidUploadKey/traversal (0.00s)1803 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1804 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1805=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18062026/09/10 09:07:45 INFO Received complete multipart upload request method=POST path=/1807=== RUN TestService_RequireScope_OIDC/builder_may_write1808=== PAUSE TestService_RequireScope_OIDC/builder_may_write1809=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1810=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1811=== RUN TestService_RequireScope_OIDC/ops_may_admin1812=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1813=== RUN TestService_RequireScope_OIDC/ops_may_not_write1814=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1815=== RUN TestService_RequireScope_OIDC/reader_may_not_write1816=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1817=== RUN TestService_RequireScope_OIDC/static_token_may_admin1818=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1819=== RUN TestService_RequireScope_OIDC/static_token_may_write1820=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1821=== RUN TestService_RequireScope_OIDC/reader_may_read1822=== PAUSE TestService_RequireScope_OIDC/reader_may_read1823=== RUN TestService_RequireScope_OIDC/writer_implies_read1824=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1825=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1826=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1827=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18282026/09/10 09:07:45 INFO Received uploads request method=POST path=/1829--- PASS: TestService_ReadAuthMiddleware (1.87s)1830=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18312026/09/10 09:07:45 INFO Received request for more parts method=POST path=/18322026/09/10 09:07:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"18332026/09/10 09:07:45 WARN mTLS auth: bound subjects configured but subject DN unavailable18342026/09/10 09:07:45 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1835--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.69s)1836=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token18372026/09/10 09:07:45 INFO OIDC auth successful provider=test scopes=[write]1838=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18392026/09/10 09:07:45 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]1840=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1841=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18422026/09/10 09:07:45 WARN Authentication failed token_preview=eyJhbGciOi...9TlradVhyQ token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1843=== CONT TestService_RequireScope_OIDC/builder_may_write1844--- PASS: TestService_AuthMiddleware_OIDC (1.92s)1845 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)1846 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1847 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1848 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)18492026/09/10 09:07:45 INFO OIDC auth successful provider=test scopes=[write]1850=== CONT TestService_RequireScope_OIDC/static_token_may_admin1851=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1852=== CONT TestService_RequireScope_OIDC/writer_implies_read18532026/09/10 09:07:45 INFO OIDC auth successful provider=test scopes=[write]1854=== CONT TestService_RequireScope_OIDC/reader_may_read18552026/09/10 09:07:45 INFO OIDC auth successful provider=test scopes=[read]1856=== CONT TestService_RequireScope_OIDC/static_token_may_write1857=== CONT TestService_RequireScope_OIDC/ops_may_not_write18582026/09/10 09:07:45 INFO OIDC auth successful provider=test scopes=[admin]1859=== CONT TestService_RequireScope_OIDC/reader_may_not_write18602026/09/10 09:07:45 INFO OIDC auth successful provider=test scopes=[read]1861=== CONT TestService_RequireScope_OIDC/builder_may_not_admin18622026/09/10 09:07:45 INFO OIDC auth successful provider=test scopes=[write]1863=== CONT TestService_RequireScope_OIDC/ops_may_admin1864--- PASS: TestService_healthCheckHandler (1.46s)18652026/09/10 09:07:45 INFO OIDC auth successful provider=test scopes=[admin]1866--- PASS: TestService_RequireScope_OIDC (1.96s)1867 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1868 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1869 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1870 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1871 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1872 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1873 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1874 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1875 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1876 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)18772026/09/10 09:07:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18782026/09/10 09:07:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18792026/09/10 09:07:45 INFO Received uploads request method=POST path=/api/pending_closures18802026/09/10 09:07:45 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NWQ1NDY3Y2ItNjkwNC00OGE4LTk2YTItMzlmZmEyMDFmYjZlLmU2YWE3MTY3LWExY2ItNDU2Zi05ZmJhLWI2NDZkNWFjZjJiYXgxNzg5MDMxMjYzMzg5MjUxMjgw parts=1218812026/09/10 09:07:45 INFO Received uploads request method=POST path=/api/pending_closures1882--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.27s)1883--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.39s)18842026/09/10 09:07:45 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NWQ1NDY3Y2ItNjkwNC00OGE4LTk2YTItMzlmZmEyMDFmYjZlLmVlOTI3NjNjLTE4NDYtNGIwYS04NWYwLTNkMjJmYmE5Zjk4N3gxNzg5MDMxMjYzMzQ3MDA4NzE0 parts=121885--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.41s)1886--- PASS: TestRedundantMultipartUpload (3.28s)18872026/09/10 09:07:45 INFO Received cleanup request method=DELETE path=/api/pending_closures18882026/09/10 09:07:45 INFO Aborted multipart uploads count=018892026/09/10 09:07:45 INFO Received uploads request method=POST path=/api/pending_closures1890=== NAME TestClientCADerivations1891 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1892 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1893 error: binary cache 's3://bucket33?endpoint=http://localhost:43167®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1651512189/001/store'1894 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11895--- PASS: TestClientCADerivations (2.44s)18962026/09/10 09:07:45 INFO Received cleanup request method=DELETE path=/api/pending_closures18972026/09/10 09:07:45 INFO Aborted multipart uploads count=118982026/09/10 09:07:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18992026-09-10 09:07:45.574 UTC [934] ERROR: Closure does not exist: id=119002026-09-10 09:07:45.574 UTC [934] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE19012026-09-10 09:07:45.574 UTC [934] STATEMENT: -- name: CommitPendingClosure :exec1902 SELECT commit_pending_closure($1::bigint)1903 1904--- PASS: TestService_cleanupPendingClosuresHandler (1.39s)19052026/09/10 09:07:45 INFO Received uploads request method=POST path=/api/pending_closures19062026/09/10 09:07:45 INFO Aborted multipart uploads count=019072026/09/10 09:07:45 WARN Force mode enabled - objects will be deleted immediately without grace period19082026/09/10 09:07:45 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=019092026/09/10 09:07:45 INFO Vacuumed table table=pending_closures19102026/09/10 09:07:45 INFO Vacuumed table table=pending_objects19112026/09/10 09:07:45 INFO Vacuumed table table=multipart_uploads19122026/09/10 09:07:45 INFO Vacuumed table table=closures19132026/09/10 09:07:45 INFO Vacuumed table table=objects1914--- PASS: TestGCMetrics (0.86s)19152026/09/10 09:07:45 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=725.806129ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19162026/09/10 09:07:45 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1917--- PASS: TestGCBugBareHashReferences (1.07s)19182026/09/10 09:07:45 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19192026/09/10 09:07:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19202026/09/10 09:07:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NWQ1NDY3Y2ItNjkwNC00OGE4LTk2YTItMzlmZmEyMDFmYjZlLjVlODViMDhmLTM2ZDMtNDM5Ny1hMDEzLWExMmQyZjAwNTA4MXgxNzg5MDMxMjY0NzcwNjA2MzM3 parts=1019212026/09/10 09:07:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19222026/09/10 09:07:46 INFO Completed upload id=119232026/09/10 09:07:46 INFO Received uploads request method=POST path=/api/pending_closures19242026/09/10 09:07:46 INFO Received uploads request method=POST path=/api/pending_closures19252026/09/10 09:07:46 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo19262026/09/10 09:07:46 WARN Found objects in DB but missing from S3, will re-upload count=11927--- PASS: TestService_verifyS3Integrity (2.83s)19282026/09/10 09:07:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19292026/09/10 09:07:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete19302026/09/10 09:07:46 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NWQ1NDY3Y2ItNjkwNC00OGE4LTk2YTItMzlmZmEyMDFmYjZlLjA2NjdhMGM3LTk5ZWEtNDI0OS1iZjhiLTI3MzBhMmVhZGU1OHgxNzg5MDMxMjY0ODMzNDUyNzYy parts=1019312026/09/10 09:07:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19322026/09/10 09:07:46 INFO Completed upload id=119332026/09/10 09:07:46 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000019342026/09/10 09:07:46 INFO Received uploads request method=POST path=/api/pending_closures19352026/09/10 09:07:46 INFO Starting cleanup of old closures method=DELETE path=/api/closures19362026/09/10 09:07:46 INFO Aborted multipart uploads count=019372026/09/10 09:07:46 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=019382026/09/10 09:07:46 INFO Vacuumed table table=pending_closures19392026/09/10 09:07:46 INFO Vacuumed table table=pending_objects19402026/09/10 09:07:46 INFO Vacuumed table table=multipart_uploads19412026/09/10 09:07:46 INFO Vacuumed table table=closures19422026/09/10 09:07:46 INFO Vacuumed table table=objects19432026/09/10 09:07:46 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001944--- PASS: TestService_createPendingClosureHandler (3.10s)1945=== NAME TestOrphanedObjectsGCStressTest1946 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains19472026/09/10 09:07:46 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.487427581s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1948 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion19492026/09/10 09:07:46 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01950=== NAME TestPinProtectsFromGC1951 client_integration_test.go:711: Pin successfully protected closure from garbage collection1952--- PASS: TestPinProtectsFromGC (4.17s)1953--- PASS: TestUploadHandlersRejectOversizedBody (0.19s)1954 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)1955 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.07s)1956 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.50s)1957=== NAME TestOrphanedObjectsGCStressTest1958 orphaned_objects_gc_test.go:509: Stress test completed successfully:1959 orphaned_objects_gc_test.go:510: - Active objects preserved: 201960 orphaned_objects_gc_test.go:511: - Objects deleted: 2101961 orphaned_objects_gc_test.go:512: - Total GC'd: 2101962--- PASS: TestOrphanedObjectsGCStressTest (4.74s)19632026/09/10 09:07:47 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01964=== NAME TestClientIntegration1965 client_integration_test.go:304: Objects in database after GC:1966 client_integration_test.go:304: Successfully deleted all objects with GC --force1967--- PASS: TestClientIntegration (3.90s)19682026/09/10 09:07:47 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"19692026/09/10 09:07:48 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_closures19702026/09/10 09:07:48 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=187.344206ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19712026/09/10 09:07:48 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=391.348817ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19722026/09/10 09:07:48 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=782.756022ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19732026/09/10 09:07:49 WARN Rate limiter enabled after throttle name=s3-test rate=519742026/09/10 09:07:49 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1975=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1976 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101977 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001978--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.70s)19792026/09/10 09:07:49 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.607997805s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1980--- PASS: TestClientErrorHandling (0.00s)1981 --- PASS: TestClientErrorHandling/InvalidStorePath (0.86s)1982 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.96s)1983 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.13s)19842026/09/10 09:07:52 INFO Aborted multipart uploads count=019852026/09/10 09:07:56 INFO Aborted multipart uploads count=019862026/09/10 09:08:01 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=2500 objects-failed-to-delete=019872026/09/10 09:08:01 INFO Vacuumed table table=pending_closures19882026/09/10 09:08:01 INFO Vacuumed table table=pending_objects19892026/09/10 09:08:01 INFO Vacuumed table table=multipart_uploads19902026/09/10 09:08:01 INFO Vacuumed table table=closures19912026/09/10 09:08:01 INFO Vacuumed table table=objects1992--- PASS: TestOrphanedObjectsGCDeletesEachKeyOnce (18.72s)19932026/09/10 09:08:13 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1500 objects-failed-to-delete=019942026/09/10 09:08:13 INFO Vacuumed table table=pending_closures19952026/09/10 09:08:13 INFO Vacuumed table table=pending_objects19962026/09/10 09:08:13 INFO Vacuumed table table=multipart_uploads19972026/09/10 09:08:13 INFO Vacuumed table table=closures19982026/09/10 09:08:13 INFO Vacuumed table table=objects1999--- PASS: TestOrphanedObjectsGCFallsBackToSingleDeletes (28.21s)2000PASS2001{"timestamp":"2026-09-10T09:08:13.021299074Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53076","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1866,"threadName":"rustfs-worker","threadId":"ThreadId(316)"}20022026-09-10 09:08:14.231 UTC [111] LOG: received smart shutdown request20032026-09-10 09:08:14.238 UTC [111] LOG: background worker "logical replication launcher" (PID 121) exited with exit code 120042026-09-10 09:08:14.256 UTC [116] LOG: shutting down20052026-09-10 09:08:14.257 UTC [116] LOG: checkpoint starting: shutdown immediate20062026-09-10 09:08:15.256 UTC [116] LOG: checkpoint complete: wrote 10601 buffers (64.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=0.215 s, sync=0.775 s, total=1.000 s; sync files=17803, longest=0.002 s, average=0.001 s; distance=246835 kB, estimate=246835 kB; lsn=0/10872930, redo lsn=0/1087293020072026-09-10 09:08:15.362 UTC [111] LOG: database system is shut down2008Running OIDC tests...2009=== RUN TestGlobMatch2010=== PAUSE TestGlobMatch2011=== RUN TestAudienceForIssuer2012=== PAUSE TestAudienceForIssuer2013=== RUN TestValidateToken_ValidToken2014=== PAUSE TestValidateToken_ValidToken2015=== RUN TestValidateToken_WrongAudience2016=== PAUSE TestValidateToken_WrongAudience2017=== RUN TestValidateToken_Expired2018=== PAUSE TestValidateToken_Expired2019=== RUN TestValidateToken_BoundClaimsMismatch2020=== PAUSE TestValidateToken_BoundClaimsMismatch2021=== RUN TestValidateToken_BoundSubjectMismatch2022=== PAUSE TestValidateToken_BoundSubjectMismatch2023=== RUN TestValidateToken_MultipleProviders2024=== PAUSE TestValidateToken_MultipleProviders2025=== RUN TestValidateToken_NoMatchingProvider2026=== PAUSE TestValidateToken_NoMatchingProvider2027=== RUN TestValidateToken_KubernetesServiceAccount2028=== PAUSE TestValidateToken_KubernetesServiceAccount2029=== RUN TestNewValidator_KubernetesRequiresCA2030=== PAUSE TestNewValidator_KubernetesRequiresCA2031=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2032=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2033=== RUN TestScopes_LegacyProviderDefaultsToWrite2034=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2035=== RUN TestScopes_Rules2036=== PAUSE TestScopes_Rules2037=== RUN TestScopes_ConfigValidation2038=== PAUSE TestScopes_ConfigValidation2039=== CONT TestGlobMatch2040=== CONT TestValidateToken_Expired2041=== CONT TestValidateToken_BoundClaimsMismatch2042=== CONT TestValidateToken_NoMatchingProvider2043=== CONT TestScopes_LegacyProviderDefaultsToWrite2044=== RUN TestGlobMatch/foo_foo2045=== CONT TestScopes_Rules2046=== PAUSE TestGlobMatch/foo_foo2047=== RUN TestGlobMatch/foo_bar2048=== PAUSE TestGlobMatch/foo_bar2049=== RUN TestGlobMatch/*_2050=== PAUSE TestGlobMatch/*_2051=== RUN TestGlobMatch/*_anything2052=== PAUSE TestGlobMatch/*_anything2053=== RUN TestGlobMatch/foo*_foo2054=== PAUSE TestGlobMatch/foo*_foo2055=== CONT TestValidateToken_ValidToken2056=== CONT TestAudienceForIssuer2057=== CONT TestValidateToken_BoundSubjectMismatch2058=== CONT TestValidateToken_MultipleProviders2059=== CONT TestScopes_ConfigValidation2060=== CONT TestNewValidator_KubernetesRequiresCA2061=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2062=== CONT TestValidateToken_KubernetesServiceAccount2063=== CONT TestValidateToken_WrongAudience2064=== RUN TestGlobMatch/foo*_foobar2065=== PAUSE TestGlobMatch/foo*_foobar2066=== RUN TestGlobMatch/foo*_bar2067=== PAUSE TestGlobMatch/foo*_bar2068=== RUN TestGlobMatch/*bar_bar2069=== PAUSE TestGlobMatch/*bar_bar2070=== RUN TestGlobMatch/*bar_foobar2071=== PAUSE TestGlobMatch/*bar_foobar2072=== RUN TestGlobMatch/*bar_foo2073--- PASS: TestAudienceForIssuer (0.00s)2074=== PAUSE TestGlobMatch/*bar_foo2075=== RUN TestGlobMatch/foo*bar_foobar2076=== PAUSE TestGlobMatch/foo*bar_foobar2077=== RUN TestGlobMatch/foo*bar_foo123bar2078=== PAUSE TestGlobMatch/foo*bar_foo123bar2079=== RUN TestGlobMatch/foo*bar_foobarbaz2080=== PAUSE TestGlobMatch/foo*bar_foobarbaz2081=== RUN TestGlobMatch/*/*_foo/bar2082=== PAUSE TestGlobMatch/*/*_foo/bar2083=== RUN TestGlobMatch/*/*_foo2084=== PAUSE TestGlobMatch/*/*_foo2085=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2086=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2087=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02088=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02089=== RUN TestGlobMatch/refs/*/main_refs/heads/main2090=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2091=== RUN TestGlobMatch/fo?_foo2092=== PAUSE TestGlobMatch/fo?_foo2093=== RUN TestGlobMatch/fo?_fo2094=== PAUSE TestGlobMatch/fo?_fo2095=== RUN TestGlobMatch/fo?_fooo2096=== PAUSE TestGlobMatch/fo?_fooo2097=== RUN TestGlobMatch/?oo_foo2098=== PAUSE TestGlobMatch/?oo_foo2099=== RUN TestGlobMatch/?oo_boo2100=== PAUSE TestGlobMatch/?oo_boo2101=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2102=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2103=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2104=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2105=== CONT TestGlobMatch/foo_foo2106=== CONT TestGlobMatch/foo*bar_foobarbaz2107=== CONT TestGlobMatch/foo*bar_foo123bar2108=== CONT TestGlobMatch/foo*bar_foobar2109=== CONT TestGlobMatch/*bar_foo2110=== CONT TestGlobMatch/*bar_foobar2111=== CONT TestGlobMatch/*bar_bar2112=== CONT TestGlobMatch/foo*_bar2113=== CONT TestGlobMatch/foo*_foobar2114=== CONT TestGlobMatch/foo*_foo2115=== CONT TestGlobMatch/*_anything2116=== CONT TestGlobMatch/*_2117=== CONT TestGlobMatch/foo_bar2118=== CONT TestGlobMatch/fo?_fo2119=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2120=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2121=== CONT TestGlobMatch/?oo_boo2122=== CONT TestGlobMatch/?oo_foo2123=== CONT TestGlobMatch/fo?_fooo2124=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02125=== CONT TestGlobMatch/fo?_foo2126=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2127=== CONT TestGlobMatch/refs/*/main_refs/heads/main2128=== CONT TestGlobMatch/*/*_foo2129=== CONT TestGlobMatch/*/*_foo/bar2130--- PASS: TestGlobMatch (0.00s)2131 --- PASS: TestGlobMatch/foo_foo (0.00s)2132 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2133 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2134 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2135 --- PASS: TestGlobMatch/*bar_foo (0.00s)2136 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2137 --- PASS: TestGlobMatch/*bar_bar (0.00s)2138 --- PASS: TestGlobMatch/foo*_bar (0.00s)2139 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2140 --- PASS: TestGlobMatch/foo*_foo (0.00s)2141 --- PASS: TestGlobMatch/*_anything (0.00s)2142 --- PASS: TestGlobMatch/*_ (0.00s)2143 --- PASS: TestGlobMatch/foo_bar (0.00s)2144 --- PASS: TestGlobMatch/fo?_fo (0.00s)2145 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2146 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2147 --- PASS: TestGlobMatch/?oo_boo (0.00s)2148 --- PASS: TestGlobMatch/?oo_foo (0.00s)2149 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2150 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2151 --- PASS: TestGlobMatch/fo?_foo (0.00s)2152 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2153 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2154 --- PASS: TestGlobMatch/*/*_foo (0.00s)2155 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2156--- PASS: TestScopes_ConfigValidation (0.00s)21572026/09/10 09:08:16 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:45729/oidc21582026/09/10 09:08:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38953/oidc21592026/09/10 09:08:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39185/oidc21602026/09/10 09:08:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44549/oidc21612026/09/10 09:08:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43487/oidc21622026/09/10 09:08:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46805/oidc21632026/09/10 09:08:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46073/oidc21642026/09/10 09:08:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40555/oidc21652026/09/10 09:08:16 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:46561/oidc21662026/09/10 09:08:16 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36277/oidc21672026/09/10 09:08:16 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232168--- PASS: TestValidateToken_Expired (0.01s)2169--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2170--- PASS: TestValidateToken_WrongAudience (0.01s)2171--- PASS: TestValidateToken_ValidToken (0.01s)2172--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2173--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2174--- PASS: TestValidateToken_NoMatchingProvider (0.01s)21752026/09/10 09:08:16 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:406132176--- PASS: TestValidateToken_MultipleProviders (0.01s)2177--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.02s)21782026/09/10 09:08:16 http: TLS handshake error from 127.0.0.1:38366: remote error: tls: bad certificate2179--- PASS: TestNewValidator_KubernetesRequiresCA (0.02s)2180--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)2181--- PASS: TestScopes_Rules (0.02s)2182PASS2183Running hook tests...2184=== RUN TestSendPathsEmpty2185=== PAUSE TestSendPathsEmpty2186=== RUN TestQueueEnqueueAndFetch2187=== PAUSE TestQueueEnqueueAndFetch2188=== RUN TestQueueDeduplication2189=== PAUSE TestQueueDeduplication2190=== RUN TestQueueRemove2191=== PAUSE TestQueueRemove2192=== RUN TestQueueFetchBatchLimit2193=== PAUSE TestQueueFetchBatchLimit2194=== RUN TestQueueRetryMovesToBack2195=== PAUSE TestQueueRetryMovesToBack2196=== RUN TestQueueFetchRemoveLifecycle2197=== PAUSE TestQueueFetchRemoveLifecycle2198=== RUN TestQueueConcurrentWriters2199=== PAUSE TestQueueConcurrentWriters2200=== RUN TestQueueRemoveLargeClosure2201=== PAUSE TestQueueRemoveLargeClosure2202=== RUN TestServerClientIntegration2203=== PAUSE TestServerClientIntegration2204=== RUN TestServerQueueError2205=== PAUSE TestServerQueueError2206=== RUN TestGetListenerSocketActivation2207 server_test.go:210: === RUN TestGetListenerSocketActivation2208 --- PASS: TestGetListenerSocketActivation (0.00s)2209 PASS2210 2211--- PASS: TestGetListenerSocketActivation (0.01s)2212=== RUN TestDrainIsolatesPoisonPath2213=== PAUSE TestDrainIsolatesPoisonPath2214=== RUN TestRunNotBlockedByPoisonHead2215=== PAUSE TestRunNotBlockedByPoisonHead2216=== RUN TestDrainGivesUpWhenServerDown2217=== PAUSE TestDrainGivesUpWhenServerDown2218=== RUN TestFailedPathPrunedByLaterClosure2219=== PAUSE TestFailedPathPrunedByLaterClosure2220=== RUN TestWorkerUploadsAndRemoves2221=== PAUSE TestWorkerUploadsAndRemoves2222=== RUN TestWorkerSkipsGCdPaths2223=== PAUSE TestWorkerSkipsGCdPaths2224=== RUN TestWorkerPrunesClosureDeps2225=== PAUSE TestWorkerPrunesClosureDeps2226=== RUN TestDrainTimeout2227=== PAUSE TestDrainTimeout2228=== CONT TestSendPathsEmpty2229=== CONT TestRunNotBlockedByPoisonHead2230--- PASS: TestSendPathsEmpty (0.00s)2231=== CONT TestDrainIsolatesPoisonPath2232=== CONT TestServerQueueError2233=== CONT TestServerClientIntegration2234=== CONT TestQueueRemoveLargeClosure2235=== CONT TestQueueConcurrentWriters2236=== CONT TestQueueFetchRemoveLifecycle22372026/09/10 09:08:16 ERROR Failed to queue paths error="permission denied" count=12238=== CONT TestQueueRetryMovesToBack2239=== CONT TestQueueFetchBatchLimit2240=== CONT TestQueueRemove2241=== CONT TestQueueDeduplication2242=== CONT TestQueueEnqueueAndFetch2243=== CONT TestWorkerPrunesClosureDeps2244=== CONT TestFailedPathPrunedByLaterClosure2245=== CONT TestWorkerUploadsAndRemoves2246=== CONT TestDrainTimeout2247=== CONT TestDrainGivesUpWhenServerDown2248=== CONT TestWorkerSkipsGCdPaths2249--- PASS: TestServerQueueError (0.00s)2250--- PASS: TestServerClientIntegration (0.00s)22512026/09/10 09:08:16 INFO Uploading batch count=422522026/09/10 09:08:16 ERROR Upload failed error="upload failed" count=422532026/09/10 09:08:16 INFO Uploading batch count=122542026/09/10 09:08:16 ERROR Upload failed error="upload failed" count=122552026/09/10 09:08:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath880983783/002/bbb22562026/09/10 09:08:16 INFO Upload queue status pending=222572026/09/10 09:08:16 INFO Uploading batch count=122582026/09/10 09:08:16 INFO Uploading batch count=222592026/09/10 09:08:16 INFO Uploading batch count=222602026/09/10 09:08:16 INFO Upload queue status pending=22261--- PASS: TestQueueEnqueueAndFetch (0.02s)22622026/09/10 09:08:16 INFO Uploading batch count=222632026/09/10 09:08:16 ERROR Upload failed error="upload failed" count=222642026/09/10 09:08:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown482454042/002/a22652026/09/10 09:08:16 INFO Upload queue status pending=322662026/09/10 09:08:16 INFO Uploading batch count=122672026/09/10 09:08:16 ERROR Upload failed error="upload failed" count=122682026/09/10 09:08:16 INFO Upload queue status pending=22269--- PASS: TestQueueRemove (0.02s)22702026/09/10 09:08:16 INFO Uploading batch count=122712026/09/10 09:08:16 INFO Uploading batch count=122722026/09/10 09:08:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown482454042/002/b22732026/09/10 09:08:16 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3805239888/002/nonexistent22742026/09/10 09:08:16 INFO Uploading batch count=12275--- PASS: TestQueueFetchBatchLimit (0.02s)22762026/09/10 09:08:16 ERROR Upload failed error="upload failed" count=12277--- PASS: TestQueueRetryMovesToBack (0.02s)22782026/09/10 09:08:16 INFO Uploading batch count=122792026/09/10 09:08:16 INFO Uploading batch count=222802026/09/10 09:08:16 ERROR Upload failed error="upload failed" count=222812026/09/10 09:08:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown482454042/002/c2282--- PASS: TestQueueFetchRemoveLifecycle (0.02s)22832026/09/10 09:08:16 INFO Uploading batch count=122842026/09/10 09:08:16 ERROR Upload failed error="upload failed" count=122852026/09/10 09:08:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown482454042/002/d2286--- PASS: TestQueueDeduplication (0.02s)22872026/09/10 09:08:16 INFO Uploading batch count=122882026/09/10 09:08:16 ERROR Upload failed error="upload failed" count=122892026/09/10 09:08:16 INFO Uploading batch count=222902026/09/10 09:08:16 ERROR Upload failed error="upload failed" count=22291--- PASS: TestFailedPathPrunedByLaterClosure (0.03s)22922026/09/10 09:08:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown482454042/002/e22932026/09/10 09:08:16 ERROR Drain finished with paths left in queue remaining=122942026/09/10 09:08:16 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown482454042/002/f22952026/09/10 09:08:16 ERROR Drain finished with paths left in queue remaining=102296--- PASS: TestDrainIsolatesPoisonPath (0.03s)2297--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2298--- PASS: TestWorkerUploadsAndRemoves (0.04s)2299--- PASS: TestWorkerSkipsGCdPaths (0.04s)2300--- PASS: TestWorkerPrunesClosureDeps (0.04s)23012026/09/10 09:08:16 ERROR Upload failed error="context deadline exceeded" count=223022026/09/10 09:08:16 ERROR Drain finished with paths left in queue remaining=42303--- PASS: TestDrainTimeout (0.22s)2304--- PASS: TestQueueConcurrentWriters (0.22s)2305--- PASS: TestQueueRemoveLargeClosure (0.28s)23062026/09/10 09:08:17 INFO Uploading batch count=123072026/09/10 09:08:17 INFO Uploading batch count=123082026/09/10 09:08:17 INFO Uploading batch count=123092026/09/10 09:08:17 ERROR Upload failed error="upload failed" count=123102026/09/10 09:08:17 INFO Uploading batch count=123112026/09/10 09:08:17 ERROR Upload failed error="upload failed" count=123122026/09/10 09:08:17 INFO Uploading batch count=123132026/09/10 09:08:17 ERROR Upload failed error="upload failed" count=123142026/09/10 09:08:17 INFO Uploading batch count=123152026/09/10 09:08:17 ERROR Upload failed error="upload failed" count=123162026/09/10 09:08:17 ERROR Drain finished with paths left in queue remaining=12317--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2318PASS