niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #182
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestCaseHackSuffix5=== PAUSE TestCaseHackSuffix6=== RUN TestFilterOversizedClosures7=== PAUSE TestFilterOversizedClosures8=== RUN TestPartSizeForNAR9=== PAUSE TestPartSizeForNAR10=== RUN TestUploadMultipart_SupersededByPeer11=== PAUSE TestUploadMultipart_SupersededByPeer12=== RUN TestDumpPathMatchesNix13=== PAUSE TestDumpPathMatchesNix14=== RUN TestDumpPathSingleFile15=== PAUSE TestDumpPathSingleFile16=== RUN TestDumpPathWriterError17=== PAUSE TestDumpPathWriterError18=== RUN TestEncodeNixBase3219=== PAUSE TestEncodeNixBase3220=== RUN TestEncodeNixBase32WithRealHash21=== PAUSE TestEncodeNixBase32WithRealHash22=== RUN TestConvertHashToNix3223=== PAUSE TestConvertHashToNix3224=== RUN TestGetStorePathHash25=== PAUSE TestGetStorePathHash26=== RUN TestPathInfoHashCompatibility27=== PAUSE TestPathInfoHashCompatibility28=== RUN TestParsePathInfoJSON29=== PAUSE TestParsePathInfoJSON30=== RUN TestParsePathInfoJSONMultiplePaths31=== PAUSE TestParsePathInfoJSONMultiplePaths32=== RUN TestPathInfoCACompatibility33=== PAUSE TestPathInfoCACompatibility34=== RUN TestRateLimiterFeedback35=== PAUSE TestRateLimiterFeedback36=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess37=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess38=== RUN TestResolveStorePath39=== PAUSE TestResolveStorePath40=== RUN TestDoWithRetry_BodyReplayedViaGetBody41=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody42=== RUN TestShellSplit43=== PAUSE TestShellSplit44=== RUN TestShellSplitErrors45=== PAUSE TestShellSplitErrors46=== RUN TestSetClientTLS47=== PAUSE TestSetClientTLS48=== RUN TestSetClientTLSDoesNotMutateDefaultTransport49=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport50=== RUN TestSetClientTLSErrors51=== PAUSE TestSetClientTLSErrors52=== RUN TestStaticToken53=== PAUSE TestStaticToken54=== RUN TestFileTokenReadsAndCaches55=== PAUSE TestFileTokenReadsAndCaches56=== RUN TestFileTokenMissing57=== PAUSE TestFileTokenMissing58=== RUN TestFileTokenEmpty59=== PAUSE TestFileTokenEmpty60=== RUN TestScriptTokenNoExpiryRerunsEveryCall61=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall62=== RUN TestScriptTokenCachesUntilRefresh63=== PAUSE TestScriptTokenCachesUntilRefresh64=== RUN TestScriptTokenEmptyToken65=== PAUSE TestScriptTokenEmptyToken66=== RUN TestScriptTokenBadJSON67=== PAUSE TestScriptTokenBadJSON68=== RUN TestScriptTokenScriptFails69=== PAUSE TestScriptTokenScriptFails70=== RUN TestScriptTokenEmptyCommand71=== PAUSE TestScriptTokenEmptyCommand72=== CONT TestDoServerRequestAttachesToken73=== CONT TestPathInfoCACompatibility74=== CONT TestScriptTokenCachesUntilRefresh75=== RUN TestPathInfoCACompatibility/null_ca_field76=== PAUSE TestPathInfoCACompatibility/null_ca_field77=== RUN TestPathInfoCACompatibility/old_string_format_-_text78=== CONT TestScriptTokenScriptFails79=== CONT TestScriptTokenNoExpiryRerunsEveryCall80=== CONT TestScriptTokenBadJSON81=== CONT TestSetClientTLS82=== CONT TestFileTokenReadsAndCaches83=== CONT TestScriptTokenEmptyCommand84--- PASS: TestScriptTokenEmptyCommand (0.00s)85=== CONT TestFileTokenMissing86=== CONT TestDoWithRetry_BodyReplayedViaGetBody87=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text88=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive89=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive90=== RUN TestPathInfoCACompatibility/new_structured_format_-_text91=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text92=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method93=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method94=== CONT TestScriptTokenEmptyToken95--- PASS: TestFileTokenReadsAndCaches (0.00s)96=== CONT TestPathInfoCACompatibility/null_ca_field97=== CONT TestShellSplitErrors98--- PASS: TestShellSplitErrors (0.00s)99=== CONT TestFileTokenEmpty1002026/09/07 19:36:49 WARN Rate limiter enabled after throttle name=server-test rate=51012026/09/07 19:36:49 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57171102--- PASS: TestFileTokenMissing (0.01s)103=== CONT TestShellSplit104--- PASS: TestShellSplit (0.00s)105=== CONT TestPathInfoCACompatibility/new_structured_format_-_text1062026/09/07 19:36:49 WARN Rate limiter backed off name=server-test rate=51072026/09/07 19:36:49 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:57171108=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method109--- PASS: TestDoServerRequestAttachesToken (0.01s)110=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive111=== CONT TestDumpPathWriterError112=== CONT TestParsePathInfoJSONMultiplePaths113=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths114=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths115=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths116=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths117--- PASS: TestFileTokenEmpty (0.00s)118=== CONT TestPathInfoHashCompatibility119=== CONT TestParsePathInfoJSON120=== RUN TestParsePathInfoJSON/Nix_format121=== PAUSE TestParsePathInfoJSON/Nix_format122=== RUN TestParsePathInfoJSON/Lix_format123--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)124=== CONT TestGetStorePathHash125=== PAUSE TestParsePathInfoJSON/Lix_format126=== RUN TestGetStorePathHash/valid_store_path127=== RUN TestParsePathInfoJSON/empty_input128=== PAUSE TestParsePathInfoJSON/empty_input129=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)130=== RUN TestParsePathInfoJSON/whitespace_only131=== PAUSE TestGetStorePathHash/valid_store_path132=== PAUSE TestParsePathInfoJSON/whitespace_only133=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)134=== RUN TestGetStorePathHash/basename_without_hyphen_should_error135=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon136=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon137=== RUN TestParsePathInfoJSON/invalid_JSON138=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI139=== PAUSE TestParsePathInfoJSON/invalid_JSON140=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI141=== CONT TestConvertHashToNix32142=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512143=== RUN TestConvertHashToNix32/SRI_format_to_Nix32144=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512145=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error146=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error147=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error148=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error149=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32150=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error151=== RUN TestConvertHashToNix32/already_Nix32_format152=== CONT TestEncodeNixBase32WithRealHash153--- PASS: TestEncodeNixBase32WithRealHash (0.00s)154=== CONT TestPartSizeForNAR155=== RUN TestPartSizeForNAR/zero_stays_at_minimum156=== CONT TestEncodeNixBase32157=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum158=== PAUSE TestConvertHashToNix32/already_Nix32_format159=== RUN TestEncodeNixBase32/test_string_hash160=== PAUSE TestEncodeNixBase32/test_string_hash161=== RUN TestEncodeNixBase32/empty_input162=== RUN TestConvertHashToNix32/invalid_format163=== PAUSE TestEncodeNixBase32/empty_input164=== RUN TestPartSizeForNAR/small_stays_at_minimum165=== PAUSE TestConvertHashToNix32/invalid_format166=== PAUSE TestPartSizeForNAR/small_stays_at_minimum167=== CONT TestDumpPathSingleFile168=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum169=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum170=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts171=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts172=== RUN TestPartSizeForNAR/1_TiB173=== PAUSE TestPartSizeForNAR/1_TiB174=== RUN TestPartSizeForNAR/5_TiB_S3_max_object175=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object176=== RUN TestPartSizeForNAR/capped_at_5_GiB177=== PAUSE TestPartSizeForNAR/capped_at_5_GiB178=== CONT TestDumpPathMatchesNix179=== CONT TestUploadMultipart_SupersededByPeer180=== RUN TestUploadMultipart_SupersededByPeer/exists181=== PAUSE TestUploadMultipart_SupersededByPeer/exists182=== RUN TestUploadMultipart_SupersededByPeer/missing183=== PAUSE TestUploadMultipart_SupersededByPeer/missing184=== CONT TestSetClientTLSErrors185--- PASS: TestScriptTokenScriptFails (0.01s)186=== CONT TestStaticToken187--- PASS: TestStaticToken (0.00s)188=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1892026/09/07 19:36:49 WARN Rate limiter enabled after throttle name=server-test rate=5190=== RUN TestSetClientTLSErrors/missing_cert_file191=== PAUSE TestSetClientTLSErrors/missing_cert_file192=== RUN TestSetClientTLSErrors/missing_key_file193=== PAUSE TestSetClientTLSErrors/missing_key_file194=== RUN TestSetClientTLSErrors/missing_ca_file195=== PAUSE TestSetClientTLSErrors/missing_ca_file196=== RUN TestSetClientTLSErrors/invalid_ca_file197=== PAUSE TestSetClientTLSErrors/invalid_ca_file198=== CONT TestResolveStorePath199=== RUN TestSetClientTLS/rejects_connection_without_client_cert200=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert201=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA202=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA203=== RUN TestSetClientTLS/preserves_debug_logging_transport204=== PAUSE TestSetClientTLS/preserves_debug_logging_transport205=== CONT TestRateLimiterFeedback206=== RUN TestRateLimiterFeedback/429_enables_limiter207=== PAUSE TestRateLimiterFeedback/429_enables_limiter208=== RUN TestRateLimiterFeedback/503_enables_limiter209=== PAUSE TestRateLimiterFeedback/503_enables_limiter210=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter211=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter212=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter213=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter214=== CONT TestCaseHackSuffix215--- PASS: TestResolveStorePath (0.00s)216=== CONT TestFilterOversizedClosures217=== RUN TestFilterOversizedClosures/no_limit_keeps_everything218=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything219=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped220=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped221=== RUN TestFilterOversizedClosures/all_closures_skipped222=== PAUSE TestFilterOversizedClosures/all_closures_skipped223=== CONT TestPathInfoCACompatibility/old_string_format_-_text224--- PASS: TestPathInfoCACompatibility (0.00s)225 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)226 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)227 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)228 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)229 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)230=== CONT TestSetClientTLSDoesNotMutateDefaultTransport231--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)232=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths233=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths234--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)235 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)236 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)237=== CONT TestParsePathInfoJSON/Nix_format238=== CONT TestParsePathInfoJSON/whitespace_only239=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)240=== CONT TestParsePathInfoJSON/empty_input241=== CONT TestParsePathInfoJSON/Lix_format242=== CONT TestGetStorePathHash/valid_store_path243=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512244=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI245=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon246--- PASS: TestPathInfoHashCompatibility (0.00s)247 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)248 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)249 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)250 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)251=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error252=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error253=== CONT TestGetStorePathHash/basename_without_hyphen_should_error254--- PASS: TestGetStorePathHash (0.00s)255 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)256 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)257 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)258 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)259=== CONT TestParsePathInfoJSON/invalid_JSON260--- PASS: TestParsePathInfoJSON (0.00s)261 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)262 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)263 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)264 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)265 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)266=== CONT TestEncodeNixBase32/test_string_hash267=== CONT TestConvertHashToNix32/SRI_format_to_Nix32268=== CONT TestConvertHashToNix32/invalid_format269=== CONT TestConvertHashToNix32/already_Nix32_format270--- PASS: TestConvertHashToNix32 (0.00s)271 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)272 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)273 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)274=== CONT TestPartSizeForNAR/zero_stays_at_minimum275=== CONT TestEncodeNixBase32/empty_input276--- PASS: TestEncodeNixBase32 (0.00s)277 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)278 --- PASS: TestEncodeNixBase32/empty_input (0.00s)279=== CONT TestPartSizeForNAR/1_TiB280=== CONT TestUploadMultipart_SupersededByPeer/exists281=== CONT TestPartSizeForNAR/capped_at_5_GiB282=== CONT TestPartSizeForNAR/5_TiB_S3_max_object283=== CONT TestUploadMultipart_SupersededByPeer/missing284--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)285 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)286 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)287=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum288=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts289=== CONT TestPartSizeForNAR/small_stays_at_minimum290--- PASS: TestPartSizeForNAR (0.00s)291 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)292 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)293 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)294 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)295 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)296 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)297 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)298=== CONT TestSetClientTLSErrors/missing_cert_file299=== CONT TestSetClientTLSErrors/missing_ca_file300=== CONT TestSetClientTLSErrors/invalid_ca_file301=== CONT TestSetClientTLSErrors/missing_key_file302=== CONT TestSetClientTLS/rejects_connection_without_client_cert303--- PASS: TestScriptTokenEmptyToken (0.02s)304=== CONT TestSetClientTLS/preserves_debug_logging_transport305--- PASS: TestScriptTokenBadJSON (0.02s)306=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA307--- PASS: TestSetClientTLSErrors (0.00s)308 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)309 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)310 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)311 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)312=== CONT TestRateLimiterFeedback/429_enables_limiter313=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3142026/09/07 19:36:49 WARN Rate limiter enabled after throttle name=server-test rate=53152026/09/07 19:36:49 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:571843162026/09/07 19:36:49 WARN Rate limiter backed off name=server-test rate=5317=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter318=== CONT TestRateLimiterFeedback/503_enables_limiter3192026/09/07 19:36:49 WARN Rate limiter enabled after throttle name=server-test rate=5320=== CONT TestFilterOversizedClosures/no_limit_keeps_everything321=== CONT TestFilterOversizedClosures/all_closures_skipped3222026/09/07 19:36:49 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:571883232026/09/07 19:36:49 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50324=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3252026/09/07 19:36:49 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=2000326--- PASS: TestFilterOversizedClosures (0.00s)327 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)328 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)329 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)3302026/09/07 19:36:49 WARN Rate limiter backed off name=server-test rate=5331--- PASS: TestRateLimiterFeedback (0.00s)332 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)333 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)334 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)335 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)3362026/09/07 19:36:49 http: TLS handshake error from 127.0.0.1:57181: remote error: tls: bad certificate337--- PASS: TestSetClientTLS (0.01s)338 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)339 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)340 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)341--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)342--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)343--- PASS: TestDumpPathWriterError (0.04s)344--- PASS: TestDumpPathSingleFile (0.09s)345--- PASS: TestCaseHackSuffix (0.09s)346--- PASS: TestDumpPathMatchesNix (0.10s)347--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)348PASS349Running server tests...350The files belonging to this database system will be owned by user "_nixbld1".351This user must also own the server process.352353The database cluster will be initialized with locale "C".354The default database encoding has accordingly been set to "SQL_ASCII".355The default text search configuration will be set to "english".356357Data page checksums are enabled.358359creating directory /nix/var/nix/builds/nix-35150-957684269/postgres1644062100/data ... ok360creating subdirectories ... ok361selecting dynamic shared memory implementation ... posix362selecting default "max_connections" ... 100363selecting default "shared_buffers" ... 128MB364selecting default time zone ... UTC365creating configuration files ... ok366running bootstrap script ... ok367performing post-bootstrap initialization ... ok368syncing data to disk ... ok369370initdb: warning: enabling "trust" authentication for local connections371initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.372373Success. You can now start the database server using:374375 pg_ctl -D /nix/var/nix/builds/nix-35150-957684269/postgres1644062100/data -l logfile start3763772026-09-07 19:36:51.107 UTC [35185] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit3782026-09-07 19:36:51.107 UTC [35185] LOG: listening on Unix socket "/nix/var/nix/builds/nix-35150-957684269/postgres1644062100/.s.PGSQL.5432"3792026-09-07 19:36:51.109 UTC [35192] LOG: database system was shut down at 2026-09-07 19:36:51 UTC3802026-09-07 19:36:51.109 UTC [35193] FATAL: the database system is starting up381/nix/var/nix/builds/nix-35150-957684269/postgres1644062100:5432 - rejecting connections3822026-09-07 19:36:51.110 UTC [35185] LOG: database system is ready to accept connections383/nix/var/nix/builds/nix-35150-957684269/postgres1644062100: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 TestClaim_BuildWaitComplete403=== PAUSE TestClaim_BuildWaitComplete404=== RUN TestClaim_GCMarkedOutputCountsAsAbsent405=== PAUSE TestClaim_GCMarkedOutputCountsAsAbsent406=== RUN TestClaim_TooManyStreams407=== PAUSE TestClaim_TooManyStreams408=== RUN TestClaim_HolderDisconnectKeepsClaim409=== PAUSE TestClaim_HolderDisconnectKeepsClaim410=== RUN TestClaim_FailWakesWaitersButIsNotRemembered411=== PAUSE TestClaim_FailWakesWaitersButIsNotRemembered412=== RUN TestClaim_FailWithoutKindReleases413=== PAUSE TestClaim_FailWithoutKindReleases414=== RUN TestClaim_StaleHeartbeatStolen415=== PAUSE TestClaim_StaleHeartbeatStolen416=== RUN TestClaim_TwoInstances417=== PAUSE TestClaim_TwoInstances418=== RUN TestClaim_InputsTouched419=== PAUSE TestClaim_InputsTouched420=== RUN TestClaim_StreamsThroughServer421=== PAUSE TestClaim_StreamsThroughServer422=== RUN TestClientCADerivations423=== PAUSE TestClientCADerivations424=== RUN TestClientErrorHandling425=== PAUSE TestClientErrorHandling426=== RUN TestClientIntegration427=== PAUSE TestClientIntegration428=== RUN TestClientMultipleUploads429=== PAUSE TestClientMultipleUploads430=== RUN TestClientWithDependencies431=== PAUSE TestClientWithDependencies432=== RUN TestPinProtectsFromGC433=== PAUSE TestPinProtectsFromGC434=== RUN TestResolveDBConnectionString435=== PAUSE TestResolveDBConnectionString436=== RUN TestGCAdvisoryLockBlocksConcurrentRun4372026-09-07 19:36:51.430 UTC [35202] ERROR: relation "goose_db_version" does not exist at character 364382026-09-07 19:36:51.430 UTC [35202] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4392026/09/07 19:36:51 OK 20241026095416_initial_model.sql (5.13ms)4402026/09/07 19:36:51 OK 20251210153512_drop_unused_gin_index.sql (420.33µs)4412026/09/07 19:36:51 OK 20251218171726_add_pins.sql (886.21µs)4422026/09/07 19:36:51 OK 20260628120000_add_object_size_and_stats.sql (928.29µs)4432026/09/07 19:36:51 OK 20260905000000_add_claims.sql (1.22ms)4442026/09/07 19:36:51 goose: successfully migrated database to version: 202609050000004452026/09/07 19:36:51 OK 1_commit_pending_closure.sql (1.8ms)4462026/09/07 19:36:51 OK 2_object_stats_trigger.sql (215.33µs)4472026/09/07 19:36:51 goose: up to current file version: 2448--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.37s)449=== RUN TestGCBugBareHashReferences450=== PAUSE TestGCBugBareHashReferences451=== RUN TestGCMetrics452=== PAUSE TestGCMetrics453=== RUN TestGCTaskStore_StartNew454=== PAUSE TestGCTaskStore_StartNew455=== RUN TestGCTaskStore_DeduplicateSameParams456=== PAUSE TestGCTaskStore_DeduplicateSameParams457=== RUN TestGCTaskStore_ConflictDifferentParams458=== PAUSE TestGCTaskStore_ConflictDifferentParams459=== RUN TestGCTaskStore_GetEmpty460=== PAUSE TestGCTaskStore_GetEmpty461=== RUN TestGCTaskStore_GetReturnsLatest462=== PAUSE TestGCTaskStore_GetReturnsLatest463=== RUN TestGCTaskStore_CompletedAllowsNewTask464=== PAUSE TestGCTaskStore_CompletedAllowsNewTask465=== RUN TestGCTaskStore_PhaseUpdates466=== PAUSE TestGCTaskStore_PhaseUpdates467=== RUN TestGCTaskStore_Fail468=== PAUSE TestGCTaskStore_Fail469=== RUN TestGracefulShutdownDrainsInflight470=== PAUSE TestGracefulShutdownDrainsInflight471=== RUN TestService_healthCheckHandler472=== PAUSE TestService_healthCheckHandler473=== RUN TestService_readinessHandler474=== PAUSE TestService_readinessHandler475=== RUN TestGenerateLandingPage476=== PAUSE TestGenerateLandingPage477=== RUN TestCacheConfigHandlerMaxNarSize478=== PAUSE TestCacheConfigHandlerMaxNarSize479=== RUN TestCreatePendingClosureRejectsOversizedNAR480=== PAUSE TestCreatePendingClosureRejectsOversizedNAR481=== RUN TestNARDeduplicationMetadataUploadBug482=== PAUSE TestNARDeduplicationMetadataUploadBug483=== RUN TestMetricsInventory484=== PAUSE TestMetricsInventory485=== RUN TestService_NativeMTLS486=== PAUSE TestService_NativeMTLS487=== RUN TestServerTLSConfig488=== PAUSE TestServerTLSConfig489=== RUN TestMultipartCleanup490=== PAUSE TestMultipartCleanup491=== RUN TestObjectStatsTrigger492=== PAUSE TestObjectStatsTrigger493=== RUN TestOrphanedObjectsGC494=== PAUSE TestOrphanedObjectsGC495=== RUN TestOrphanedObjectsGCStressTest496=== PAUSE TestOrphanedObjectsGCStressTest497=== RUN TestResurrectedObjectNotDeleted498=== PAUSE TestResurrectedObjectNotDeleted499=== RUN TestParseSingleRange500=== PAUSE TestParseSingleRange501=== RUN TestIsValidCachePath502=== PAUSE TestIsValidCachePath503=== RUN TestReadProxyNarinfo504=== PAUSE TestReadProxyNarinfo505=== RUN TestReadProxyNarinfoAlreadyDecompressed506=== PAUSE TestReadProxyNarinfoAlreadyDecompressed507=== RUN TestReadProxyNarStreaming508=== PAUSE TestReadProxyNarStreaming509=== RUN TestReadProxy404510=== PAUSE TestReadProxy404511=== RUN TestReadProxyInvalidPath512=== PAUSE TestReadProxyInvalidPath513=== RUN TestReadProxyHead514=== PAUSE TestReadProxyHead515=== RUN TestReadProxyConditionalGet516=== PAUSE TestReadProxyConditionalGet517=== RUN TestReadProxyRootRedirectsToIndexHTML518=== PAUSE TestReadProxyRootRedirectsToIndexHTML519=== RUN TestReadProxyDisabled520=== PAUSE TestReadProxyDisabled521=== RUN TestReadRedirectNar522=== PAUSE TestReadRedirectNar523=== RUN TestReadRedirectKeepsNarinfoProxied524=== PAUSE TestReadRedirectKeepsNarinfoProxied525=== RUN TestReadProxyRangeRequest526=== PAUSE TestReadProxyRangeRequest527=== RUN TestReadRedirectUsesPublicS3URL528=== PAUSE TestReadRedirectUsesPublicS3URL529=== RUN TestRedundantMultipartUpload530=== PAUSE TestRedundantMultipartUpload531=== RUN TestCompleteMultipartUpload_ErrorButObjectExists532=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists533=== RUN TestCompletedNarNotReofferedAcrossClosures534=== PAUSE TestCompletedNarNotReofferedAcrossClosures535=== RUN TestPresignedUploadRegisteredBeforeCommit536=== PAUSE TestPresignedUploadRegisteredBeforeCommit537=== RUN TestService_Rustfstest538=== PAUSE TestService_Rustfstest539=== RUN TestParseSize540=== PAUSE TestParseSize541=== RUN TestSkippedUploadsHandler542=== PAUSE TestSkippedUploadsHandler543=== RUN TestSystemdListenerNotActivated544--- PASS: TestSystemdListenerNotActivated (0.00s)545=== RUN TestWatchdogBeatsWhenHealthy546--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)547=== RUN TestWatchdogSkipsWhenUnhealthy5482026/09/07 19:36:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5492026/09/07 19:36:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5502026/09/07 19:36:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5512026/09/07 19:36:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5522026/09/07 19:36:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5532026/09/07 19:36:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5542026/09/07 19:36:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5552026/09/07 19:36:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5562026/09/07 19:36:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5572026/09/07 19:36:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"558--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)559=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle560=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle561=== RUN TestProxyWriteTimeout562=== PAUSE TestProxyWriteTimeout563=== RUN TestIsValidUploadKey564=== PAUSE TestIsValidUploadKey565=== RUN TestUploadHandlersRejectInvalidKeys566=== PAUSE TestUploadHandlersRejectInvalidKeys567=== RUN TestUploadHandlersRejectOversizedBody568=== PAUSE TestUploadHandlersRejectOversizedBody569=== RUN TestService_cleanupPendingClosuresHandler570=== PAUSE TestService_cleanupPendingClosuresHandler571=== RUN TestService_createPendingClosureHandler572=== PAUSE TestService_createPendingClosureHandler573=== RUN TestService_verifyS3Integrity574=== PAUSE TestService_verifyS3Integrity575=== RUN TestCompleteMultipartUnregistered576=== PAUSE TestCompleteMultipartUnregistered577=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT578=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT579=== CONT TestService_AuthMiddleware580=== CONT TestNARDeduplicationMetadataUploadBug581=== CONT TestService_verifyS3Integrity582=== CONT TestReadProxyNarinfo583=== CONT TestSkippedUploadsHandler584=== CONT TestCompleteMultipartUpload_ErrorButObjectExists585=== CONT TestReadRedirectKeepsNarinfoProxied586=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT587=== CONT TestCreatePendingClosureRejectsOversizedNAR5882026/09/07 19:36:51 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000589=== CONT TestCompleteMultipartUnregistered5902026/09/07 19:36:51 INFO Received uploads request method=POST path=/api/pending_closures591--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)592=== CONT TestCacheConfigHandlerMaxNarSize593--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)594=== CONT TestGenerateLandingPage595--- PASS: TestSkippedUploadsHandler (0.01s)596=== CONT TestService_readinessHandler597--- PASS: TestGenerateLandingPage (0.01s)598=== CONT TestService_healthCheckHandler5992026-09-07 19:36:52.275 UTC [35289] ERROR: relation "goose_db_version" does not exist at character 366002026-09-07 19:36:52.275 UTC [35289] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6012026-09-07 19:36:52.275 UTC [35287] ERROR: relation "goose_db_version" does not exist at character 366022026-09-07 19:36:52.275 UTC [35287] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6032026-09-07 19:36:52.275 UTC [35288] ERROR: relation "goose_db_version" does not exist at character 366042026-09-07 19:36:52.275 UTC [35288] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6052026-09-07 19:36:52.277 UTC [35290] ERROR: relation "goose_db_version" does not exist at character 366062026-09-07 19:36:52.277 UTC [35290] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6072026-09-07 19:36:52.277 UTC [35291] ERROR: relation "goose_db_version" does not exist at character 366082026-09-07 19:36:52.277 UTC [35291] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6092026-09-07 19:36:52.278 UTC [35292] ERROR: relation "goose_db_version" does not exist at character 366102026-09-07 19:36:52.278 UTC [35292] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6112026-09-07 19:36:52.278 UTC [35293] ERROR: relation "goose_db_version" does not exist at character 366122026-09-07 19:36:52.278 UTC [35293] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6132026-09-07 19:36:52.280 UTC [35294] ERROR: relation "goose_db_version" does not exist at character 366142026-09-07 19:36:52.280 UTC [35294] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6152026-09-07 19:36:52.281 UTC [35295] ERROR: relation "goose_db_version" does not exist at character 366162026-09-07 19:36:52.281 UTC [35295] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6172026-09-07 19:36:52.281 UTC [35296] ERROR: relation "goose_db_version" does not exist at character 366182026-09-07 19:36:52.281 UTC [35296] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6192026/09/07 19:36:52 OK 20241026095416_initial_model.sql (7.66ms)6202026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (867.04µs)6212026/09/07 19:36:52 OK 20241026095416_initial_model.sql (8.77ms)6222026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (896.21µs)6232026/09/07 19:36:52 OK 20251218171726_add_pins.sql (2.22ms)6242026/09/07 19:36:52 OK 20241026095416_initial_model.sql (8.8ms)6252026/09/07 19:36:52 OK 20241026095416_initial_model.sql (10.29ms)6262026/09/07 19:36:52 OK 20241026095416_initial_model.sql (8.4ms)6272026/09/07 19:36:52 OK 20251218171726_add_pins.sql (1.73ms)6282026/09/07 19:36:52 OK 20241026095416_initial_model.sql (9.65ms)6292026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (790.92µs)6302026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (1.06ms)6312026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (1.92ms)6322026/09/07 19:36:52 OK 20241026095416_initial_model.sql (9.55ms)6332026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (1.21ms)6342026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (1ms)6352026/09/07 19:36:52 OK 20251218171726_add_pins.sql (1.34ms)6362026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (750.04µs)6372026/09/07 19:36:52 OK 20241026095416_initial_model.sql (7.7ms)6382026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (2.09ms)6392026/09/07 19:36:52 OK 20251218171726_add_pins.sql (1.82ms)6402026/09/07 19:36:52 OK 20241026095416_initial_model.sql (8.16ms)6412026/09/07 19:36:52 OK 20260905000000_add_claims.sql (1.94ms)6422026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000006432026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (739.29µs)6442026/09/07 19:36:52 OK 20241026095416_initial_model.sql (8.73ms)6452026/09/07 19:36:52 OK 20251218171726_add_pins.sql (2.01ms)6462026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (814.33µs)6472026/09/07 19:36:52 OK 20251218171726_add_pins.sql (2.24ms)6482026/09/07 19:36:52 OK 20251218171726_add_pins.sql (1.66ms)6492026/09/07 19:36:52 OK 1_commit_pending_closure.sql (1.17ms)6502026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (688.92µs)6512026/09/07 19:36:52 OK 20260905000000_add_claims.sql (1.8ms)6522026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000006532026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (1.75ms)6542026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (2.54ms)6552026/09/07 19:36:52 OK 2_object_stats_trigger.sql (693.92µs)6562026/09/07 19:36:52 goose: up to current file version: 26572026/09/07 19:36:52 OK 20251218171726_add_pins.sql (1.79ms)6582026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (1.64ms)6592026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (1.79ms)6602026/09/07 19:36:52 OK 20251218171726_add_pins.sql (2.02ms)6612026/09/07 19:36:52 OK 1_commit_pending_closure.sql (1.33ms)6622026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (2.06ms)6632026/09/07 19:36:52 OK 20251218171726_add_pins.sql (1.65ms)6642026/09/07 19:36:52 OK 20260905000000_add_claims.sql (1.55ms)6652026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000006662026/09/07 19:36:52 OK 2_object_stats_trigger.sql (381.92µs)6672026/09/07 19:36:52 goose: up to current file version: 26682026/09/07 19:36:52 OK 20260905000000_add_claims.sql (2.08ms)6692026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000006702026/09/07 19:36:52 OK 20260905000000_add_claims.sql (1.76ms)6712026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000006722026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (1.86ms)6732026/09/07 19:36:52 OK 20260905000000_add_claims.sql (1.97ms)6742026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000006752026/09/07 19:36:52 OK 20260905000000_add_claims.sql (1.53ms)6762026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000006772026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (1.6ms)6782026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (1.89ms)6792026/09/07 19:36:52 OK 1_commit_pending_closure.sql (1.66ms)6802026/09/07 19:36:52 OK 1_commit_pending_closure.sql (1.05ms)6812026/09/07 19:36:52 OK 2_object_stats_trigger.sql (267.67µs)6822026/09/07 19:36:52 goose: up to current file version: 26832026/09/07 19:36:52 OK 2_object_stats_trigger.sql (298.38µs)6842026/09/07 19:36:52 goose: up to current file version: 26852026/09/07 19:36:52 OK 1_commit_pending_closure.sql (1.03ms)6862026/09/07 19:36:52 OK 1_commit_pending_closure.sql (1.12ms)6872026/09/07 19:36:52 OK 20260905000000_add_claims.sql (1.49ms)6882026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000006892026/09/07 19:36:52 OK 20260905000000_add_claims.sql (1.15ms)6902026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000006912026/09/07 19:36:52 OK 1_commit_pending_closure.sql (1.56ms)6922026/09/07 19:36:52 OK 2_object_stats_trigger.sql (390.63µs)6932026/09/07 19:36:52 goose: up to current file version: 26942026/09/07 19:36:52 OK 20260905000000_add_claims.sql (1.34ms)6952026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000006962026/09/07 19:36:52 OK 2_object_stats_trigger.sql (233.67µs)6972026/09/07 19:36:52 goose: up to current file version: 26982026/09/07 19:36:52 OK 2_object_stats_trigger.sql (266.42µs)6992026/09/07 19:36:52 goose: up to current file version: 27002026/09/07 19:36:52 OK 1_commit_pending_closure.sql (645.5µs)7012026/09/07 19:36:52 OK 2_object_stats_trigger.sql (173.21µs)7022026/09/07 19:36:52 goose: up to current file version: 27032026/09/07 19:36:52 OK 1_commit_pending_closure.sql (743.46µs)7042026/09/07 19:36:52 OK 1_commit_pending_closure.sql (937.29µs)7052026/09/07 19:36:52 OK 2_object_stats_trigger.sql (186.29µs)7062026/09/07 19:36:52 goose: up to current file version: 27072026/09/07 19:36:52 OK 2_object_stats_trigger.sql (197.96µs)7082026/09/07 19:36:52 goose: up to current file version: 2709=== NAME TestNARDeduplicationMetadataUploadBug710 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-35150-957684269/TestNARDeduplicationMetadataUploadBug1701483362/001/store/23gbzsifs7p7v4rvr9xyc1l2rhlsx4vz-file1.txt711--- PASS: TestReadRedirectKeepsNarinfoProxied (0.58s)712=== CONT TestGracefulShutdownDrainsInflight7132026/09/07 19:36:52 INFO Starting HTTP server address=127.0.0.1:572127142026/09/07 19:36:52 INFO Shutdown signal received, draining in-flight requests timeout=10s7152026/09/07 19:36:52 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"716--- PASS: TestGracefulShutdownDrainsInflight (0.07s)717=== CONT TestGCTaskStore_Fail718--- PASS: TestGCTaskStore_Fail (0.00s)719=== CONT TestGCTaskStore_PhaseUpdates720--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)721=== CONT TestGCTaskStore_CompletedAllowsNewTask722--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)723=== CONT TestGCTaskStore_GetReturnsLatest724--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)725=== CONT TestGCTaskStore_GetEmpty726--- PASS: TestGCTaskStore_GetEmpty (0.00s)727=== CONT TestGCTaskStore_ConflictDifferentParams728--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)729=== CONT TestGCTaskStore_DeduplicateSameParams730--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)731=== CONT TestGCTaskStore_StartNew732--- PASS: TestGCTaskStore_StartNew (0.00s)733=== CONT TestGCMetrics7342026/09/07 19:36:52 INFO Received uploads request method=POST path=/api/pending_closures7352026/09/07 19:36:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)7362026/09/07 19:36:52 INFO Uploading 23gbzsifs7p7v4rvr9xyc1l2rhlsx4vz-file1.txt (160B)7372026/09/07 19:36:52 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"7382026/09/07 19:36:52 WARN Failed to register uploaded object key=23gbzsifs7p7v4rvr9xyc1l2rhlsx4vz.ls error="server returned 404: 404 page not found\n"7392026/09/07 19:36:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign7402026/09/07 19:36:52 INFO Signed narinfos id=1 count=17412026/09/07 19:36:52 INFO Uploading 1 narinfos7422026/09/07 19:36:52 WARN Failed to register uploaded object key=23gbzsifs7p7v4rvr9xyc1l2rhlsx4vz.narinfo error="server returned 404: 404 page not found\n"7432026/09/07 19:36:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete7442026/09/07 19:36:52 INFO Completed upload id=17452026/09/07 19:36:52 INFO Upload complete. (99ms)746=== NAME TestNARDeduplicationMetadataUploadBug747 metadata_upload_test.go:54: Retrieved narinfo from S3:748 StorePath: /nix/var/nix/builds/nix-35150-957684269/TestNARDeduplicationMetadataUploadBug1701483362/001/store/23gbzsifs7p7v4rvr9xyc1l2rhlsx4vz-file1.txt749 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst750 Compression: zstd751 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf752 NarSize: 160753 References: 754 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf755 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)756 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):757 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}758--- PASS: TestService_healthCheckHandler (0.71s)759=== CONT TestGCBugBareHashReferences760=== NAME TestNARDeduplicationMetadataUploadBug761 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-35150-957684269/TestNARDeduplicationMetadataUploadBug1701483362/001/store/w3qrabpdk8siyw3495k9sydfab2szw2c-file2.txt7622026/09/07 19:36:52 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"7632026/09/07 19:36:52 INFO Received uploads request method=POST path=/api/pending_closures7642026/09/07 19:36:52 INFO Received uploads request method=POST path=/api/pending_closures7652026/09/07 19:36:52 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)766--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.85s)767=== CONT TestResolveDBConnectionString768=== RUN TestResolveDBConnectionString/flag_wins769=== PAUSE TestResolveDBConnectionString/flag_wins770=== RUN TestResolveDBConnectionString/file_when_flag_empty771=== PAUSE TestResolveDBConnectionString/file_when_flag_empty772=== RUN TestResolveDBConnectionString/missing_file_is_an_error773=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error774=== RUN TestResolveDBConnectionString/PGHOST_allows_empty775=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty776=== RUN TestResolveDBConnectionString/nothing_configured777=== PAUSE TestResolveDBConnectionString/nothing_configured778=== CONT TestPinProtectsFromGC7792026/09/07 19:36:52 WARN Failed to register uploaded object key=w3qrabpdk8siyw3495k9sydfab2szw2c.ls error="server returned 404: 404 page not found\n"7802026/09/07 19:36:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign7812026/09/07 19:36:52 INFO Signed narinfos id=2 count=17822026/09/07 19:36:52 INFO Uploading 1 narinfos7832026/09/07 19:36:52 WARN Failed to register uploaded object key=w3qrabpdk8siyw3495k9sydfab2szw2c.narinfo error="server returned 404: 404 page not found\n"7842026/09/07 19:36:52 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete7852026/09/07 19:36:52 INFO Completed upload id=27862026/09/07 19:36:52 INFO Upload complete. (113ms)787=== NAME TestNARDeduplicationMetadataUploadBug788 metadata_upload_test.go:76: Retrieved narinfo from S3:789 StorePath: /nix/var/nix/builds/nix-35150-957684269/TestNARDeduplicationMetadataUploadBug1701483362/001/store/w3qrabpdk8siyw3495k9sydfab2szw2c-file2.txt790 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst791 Compression: zstd792 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf793 NarSize: 160794 References: 795 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf796 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)797 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):798 {"version":1,"root":{"type":"regular","size":44}}799--- PASS: TestNARDeduplicationMetadataUploadBug (0.90s)800=== CONT TestClientWithDependencies8012026-09-07 19:36:52.842 UTC [35321] ERROR: relation "goose_db_version" does not exist at character 368022026-09-07 19:36:52.842 UTC [35321] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8032026/09/07 19:36:52 INFO Received uploads request method=POST path=/api/pending_closures8042026/09/07 19:36:52 OK 20241026095416_initial_model.sql (28.51ms)8052026/09/07 19:36:52 OK 20251210153512_drop_unused_gin_index.sql (8.06ms)8062026/09/07 19:36:52 OK 20251218171726_add_pins.sql (17.01ms)8072026/09/07 19:36:52 OK 20260628120000_add_object_size_and_stats.sql (19.34ms)8082026/09/07 19:36:52 OK 20260905000000_add_claims.sql (12.06ms)8092026/09/07 19:36:52 goose: successfully migrated database to version: 202609050000008102026/09/07 19:36:52 OK 1_commit_pending_closure.sql (1.46ms)8112026/09/07 19:36:52 OK 2_object_stats_trigger.sql (298.92µs)8122026/09/07 19:36:52 goose: up to current file version: 28132026-09-07 19:36:52.970 UTC [35323] ERROR: relation "goose_db_version" does not exist at character 368142026-09-07 19:36:52.970 UTC [35323] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8152026/09/07 19:36:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8162026/09/07 19:36:53 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDZjODFmNzctYjI3My00YTAyLWI5NmYtYTgzOGZkY2MxMDYwLmYzYWZhM2Y2LTc1NjMtNGU3NC1hMzhlLTJmODEwODlkYTljM3gxNzg4ODA5ODEyODg5NTM1MDAw8172026/09/07 19:36:53 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MDZjODFmNzctYjI3My00YTAyLWI5NmYtYTgzOGZkY2MxMDYwLmYzYWZhM2Y2LTc1NjMtNGU3NC1hMzhlLTJmODEwODlkYTljM3gxNzg4ODA5ODEyODg5NTM1MDAw parts=1818--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.12s)819=== CONT TestClientMultipleUploads8202026/09/07 19:36:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8212026/09/07 19:36:53 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst822--- PASS: TestCompleteMultipartUnregistered (1.14s)823=== CONT TestClientIntegration8242026/09/07 19:36:53 OK 20241026095416_initial_model.sql (63.85ms)8252026/09/07 19:36:53 OK 20251210153512_drop_unused_gin_index.sql (5.33ms)8262026/09/07 19:36:53 OK 20251218171726_add_pins.sql (11.26ms)8272026/09/07 19:36:53 OK 20260628120000_add_object_size_and_stats.sql (5.65ms)8282026/09/07 19:36:53 OK 20260905000000_add_claims.sql (14.42ms)8292026/09/07 19:36:53 goose: successfully migrated database to version: 202609050000008302026/09/07 19:36:53 OK 1_commit_pending_closure.sql (1.61ms)8312026/09/07 19:36:53 OK 2_object_stats_trigger.sql (340.92µs)8322026/09/07 19:36:53 goose: up to current file version: 28332026/09/07 19:36:53 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"834--- PASS: TestService_AuthMiddleware (1.26s)835=== CONT TestClientErrorHandling836=== RUN TestClientErrorHandling/InvalidStorePath837=== PAUSE TestClientErrorHandling/InvalidStorePath838=== RUN TestClientErrorHandling/InvalidAuthToken839=== PAUSE TestClientErrorHandling/InvalidAuthToken840=== RUN TestClientErrorHandling/ServerNotAvailable841=== PAUSE TestClientErrorHandling/ServerNotAvailable842=== CONT TestClientCADerivations8432026-09-07 19:36:53.243 UTC [35330] ERROR: relation "goose_db_version" does not exist at character 368442026-09-07 19:36:53.243 UTC [35330] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8452026-09-07 19:36:53.278 UTC [35331] ERROR: relation "goose_db_version" does not exist at character 368462026-09-07 19:36:53.278 UTC [35331] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8472026/09/07 19:36:53 OK 20241026095416_initial_model.sql (71.52ms)8482026/09/07 19:36:53 OK 20251210153512_drop_unused_gin_index.sql (1.85ms)849--- PASS: TestReadProxyNarinfo (1.42s)850=== CONT TestClaim_StreamsThroughServer8512026/09/07 19:36:53 OK 20251218171726_add_pins.sql (15.66ms)8522026/09/07 19:36:53 OK 20260628120000_add_object_size_and_stats.sql (14.72ms)8532026/09/07 19:36:53 OK 20260905000000_add_claims.sql (22.77ms)8542026/09/07 19:36:53 goose: successfully migrated database to version: 202609050000008552026/09/07 19:36:53 OK 20241026095416_initial_model.sql (56.71ms)8562026/09/07 19:36:53 OK 1_commit_pending_closure.sql (1.95ms)8572026/09/07 19:36:53 OK 2_object_stats_trigger.sql (609.08µs)8582026/09/07 19:36:53 goose: up to current file version: 28592026/09/07 19:36:53 OK 20251210153512_drop_unused_gin_index.sql (7.82ms)8602026/09/07 19:36:53 OK 20251218171726_add_pins.sql (6.05ms)8612026/09/07 19:36:53 OK 20260628120000_add_object_size_and_stats.sql (14.47ms)8622026/09/07 19:36:53 OK 20260905000000_add_claims.sql (30.51ms)8632026/09/07 19:36:53 goose: successfully migrated database to version: 202609050000008642026/09/07 19:36:53 OK 1_commit_pending_closure.sql (3.07ms)8652026/09/07 19:36:53 OK 2_object_stats_trigger.sql (609.67µs)8662026/09/07 19:36:53 goose: up to current file version: 28672026/09/07 19:36:53 WARN readiness check failed error="closed pool"868--- PASS: TestService_readinessHandler (1.53s)869=== CONT TestClaim_InputsTouched8702026/09/07 19:36:53 INFO Received uploads request method=POST path=/api/pending_closures8712026-09-07 19:36:53.710 UTC [35336] ERROR: relation "goose_db_version" does not exist at character 368722026-09-07 19:36:53.710 UTC [35336] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8732026-09-07 19:36:53.719 UTC [35337] ERROR: relation "goose_db_version" does not exist at character 368742026-09-07 19:36:53.719 UTC [35337] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8752026/09/07 19:36:53 INFO Aborted multipart uploads count=08762026/09/07 19:36:53 WARN Force mode enabled - objects will be deleted immediately without grace period8772026/09/07 19:36:53 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=08782026/09/07 19:36:53 INFO Vacuumed table table=pending_closures8792026/09/07 19:36:53 INFO Vacuumed table table=pending_objects8802026/09/07 19:36:53 INFO Vacuumed table table=multipart_uploads8812026/09/07 19:36:53 INFO Vacuumed table table=closures8822026/09/07 19:36:53 INFO Vacuumed table table=objects883--- PASS: TestGCMetrics (1.24s)884=== CONT TestClaim_TwoInstances8852026/09/07 19:36:53 OK 20241026095416_initial_model.sql (70.27ms)8862026/09/07 19:36:53 OK 20241026095416_initial_model.sql (86.22ms)8872026/09/07 19:36:53 OK 20251210153512_drop_unused_gin_index.sql (10.21ms)8882026/09/07 19:36:53 OK 20251210153512_drop_unused_gin_index.sql (10.23ms)8892026/09/07 19:36:53 OK 20251218171726_add_pins.sql (20.62ms)8902026/09/07 19:36:53 OK 20251218171726_add_pins.sql (20.87ms)8912026/09/07 19:36:53 OK 20260628120000_add_object_size_and_stats.sql (15.68ms)8922026/09/07 19:36:53 OK 20260628120000_add_object_size_and_stats.sql (16.5ms)8932026/09/07 19:36:53 OK 20260905000000_add_claims.sql (33.16ms)8942026/09/07 19:36:53 goose: successfully migrated database to version: 202609050000008952026/09/07 19:36:53 OK 1_commit_pending_closure.sql (2.32ms)8962026/09/07 19:36:53 OK 2_object_stats_trigger.sql (429.33µs)8972026/09/07 19:36:53 goose: up to current file version: 28982026/09/07 19:36:53 OK 20260905000000_add_claims.sql (41.18ms)8992026/09/07 19:36:53 goose: successfully migrated database to version: 202609050000009002026/09/07 19:36:53 OK 1_commit_pending_closure.sql (7.65ms)9012026/09/07 19:36:53 OK 2_object_stats_trigger.sql (53.23ms)9022026/09/07 19:36:53 goose: up to current file version: 29032026-09-07 19:36:54.148 UTC [35341] ERROR: relation "goose_db_version" does not exist at character 369042026-09-07 19:36:54.148 UTC [35341] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC905--- PASS: TestGCBugBareHashReferences (1.62s)906=== CONT TestClaim_StaleHeartbeatStolen9072026/09/07 19:36:54 OK 20241026095416_initial_model.sql (100.54ms)9082026/09/07 19:36:54 OK 20251210153512_drop_unused_gin_index.sql (8.96ms)9092026/09/07 19:36:54 OK 20251218171726_add_pins.sql (27.81ms)9102026/09/07 19:36:54 OK 20260628120000_add_object_size_and_stats.sql (34.1ms)9112026/09/07 19:36:54 OK 20260905000000_add_claims.sql (45.2ms)9122026/09/07 19:36:54 goose: successfully migrated database to version: 202609050000009132026-09-07 19:36:54.418 UTC [35346] ERROR: relation "goose_db_version" does not exist at character 369142026-09-07 19:36:54.418 UTC [35346] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9152026/09/07 19:36:54 OK 1_commit_pending_closure.sql (2.02ms)9162026/09/07 19:36:54 OK 2_object_stats_trigger.sql (310.54µs)9172026/09/07 19:36:54 goose: up to current file version: 29182026-09-07 19:36:54.498 UTC [35350] ERROR: relation "goose_db_version" does not exist at character 369192026-09-07 19:36:54.498 UTC [35350] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC920=== NAME TestPinProtectsFromGC921 client_integration_test.go:648: Pinned store path: /nix/var/nix/builds/nix-35150-957684269/TestPinProtectsFromGC941329347/001/store/gi0vbnsw31cgawy2r9g8gj0kcms5ih4x-pinned-file.txt922 client_integration_test.go:649: Unpinned store path: /nix/var/nix/builds/nix-35150-957684269/TestPinProtectsFromGC941329347/001/store/lhq12486x8zsw2b8wbfgya9hak8wldwi-unpinned-file.txt9232026/09/07 19:36:54 OK 20241026095416_initial_model.sql (91.05ms)9242026/09/07 19:36:54 OK 20251210153512_drop_unused_gin_index.sql (10.64ms)9252026/09/07 19:36:54 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9262026/09/07 19:36:54 OK 20251218171726_add_pins.sql (20.88ms)9272026/09/07 19:36:54 OK 20260628120000_add_object_size_and_stats.sql (13.29ms)9282026/09/07 19:36:54 OK 20241026095416_initial_model.sql (95.49ms)9292026/09/07 19:36:54 OK 20260905000000_add_claims.sql (42.11ms)9302026/09/07 19:36:54 goose: successfully migrated database to version: 202609050000009312026/09/07 19:36:54 INFO Received uploads request method=POST path=/api/pending_closures9322026/09/07 19:36:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9332026/09/07 19:36:54 OK 1_commit_pending_closure.sql (6.88ms)9342026/09/07 19:36:54 OK 2_object_stats_trigger.sql (248.67µs)9352026/09/07 19:36:54 goose: up to current file version: 29362026/09/07 19:36:54 OK 20251210153512_drop_unused_gin_index.sql (12.27ms)9372026/09/07 19:36:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9382026/09/07 19:36:54 INFO Uploading gi0vbnsw31cgawy2r9g8gj0kcms5ih4x-pinned-file.txt (128B)9392026/09/07 19:36:54 OK 20251218171726_add_pins.sql (29.9ms)9402026/09/07 19:36:54 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"9412026/09/07 19:36:54 WARN Failed to register uploaded object key=gi0vbnsw31cgawy2r9g8gj0kcms5ih4x.ls error="server returned 404: 404 page not found\n"9422026/09/07 19:36:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9432026/09/07 19:36:54 INFO Signed narinfos id=1 count=19442026/09/07 19:36:54 INFO Uploading 1 narinfos9452026/09/07 19:36:54 OK 20260628120000_add_object_size_and_stats.sql (9.32ms)9462026/09/07 19:36:54 WARN Failed to register uploaded object key=gi0vbnsw31cgawy2r9g8gj0kcms5ih4x.narinfo error="server returned 404: 404 page not found\n"9472026/09/07 19:36:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9482026/09/07 19:36:54 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MDZjODFmNzctYjI3My00YTAyLWI5NmYtYTgzOGZkY2MxMDYwLjkxNWRhNjg1LWFmZjEtNDY3Ny04NTRkLTBiZmU5ZDVhYTY0ZXgxNzg4ODA5ODEzNjI0NDEzMDAw parts=109492026/09/07 19:36:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9502026/09/07 19:36:54 OK 20260905000000_add_claims.sql (8.81ms)9512026/09/07 19:36:54 goose: successfully migrated database to version: 202609050000009522026/09/07 19:36:54 INFO Completed upload id=19532026/09/07 19:36:54 INFO Completed upload id=19542026/09/07 19:36:54 INFO Upload complete. (179ms)9552026/09/07 19:36:54 OK 1_commit_pending_closure.sql (7.49ms)9562026/09/07 19:36:54 OK 2_object_stats_trigger.sql (533.83µs)9572026/09/07 19:36:54 goose: up to current file version: 29582026/09/07 19:36:54 INFO Received uploads request method=POST path=/api/pending_closures9592026/09/07 19:36:54 INFO Received uploads request method=POST path=/api/pending_closures9602026/09/07 19:36:54 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9612026/09/07 19:36:54 WARN Found objects in DB but missing from S3, will re-upload count=1962--- PASS: TestService_verifyS3Integrity (2.78s)963=== CONT TestClaim_FailWithoutKindReleases964=== NAME TestClientIntegration965 client_integration_test.go:277: Created store path: /nix/var/nix/builds/nix-35150-957684269/TestClientIntegration4231612918/002/store/4gr2748z9sn7dbdsiq8gccmgvq9sg4xn-test-file.txt9662026/09/07 19:36:54 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"967=== NAME TestClientWithDependencies968 client_integration_test.go:594: Built derivation: /nix/var/nix/builds/nix-35150-957684269/TestClientWithDependencies1177719766/001/store/w9s4ywl9vh981m3zghxi4ck7lracfryv-test-script9692026-09-07 19:36:54.817 UTC [35374] ERROR: relation "goose_db_version" does not exist at character 369702026-09-07 19:36:54.817 UTC [35374] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9712026/09/07 19:36:54 INFO Received uploads request method=POST path=/api/pending_closures9722026/09/07 19:36:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9732026/09/07 19:36:54 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9742026/09/07 19:36:54 INFO Uploading lhq12486x8zsw2b8wbfgya9hak8wldwi-unpinned-file.txt (128B)9752026/09/07 19:36:54 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"9762026/09/07 19:36:54 WARN Failed to register uploaded object key=lhq12486x8zsw2b8wbfgya9hak8wldwi.ls error="server returned 404: 404 page not found\n"9772026/09/07 19:36:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9782026/09/07 19:36:54 INFO Signed narinfos id=2 count=19792026/09/07 19:36:54 INFO Uploading 1 narinfos9802026/09/07 19:36:54 WARN Failed to register uploaded object key=lhq12486x8zsw2b8wbfgya9hak8wldwi.narinfo error="server returned 404: 404 page not found\n"9812026/09/07 19:36:54 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9822026/09/07 19:36:54 INFO Completed upload id=29832026/09/07 19:36:54 INFO Upload complete. (102ms)984 client_integration_test.go:596: Found 1 dependencies (including self)9852026/09/07 19:36:54 OK 20241026095416_initial_model.sql (33.82ms)9862026/09/07 19:36:54 OK 20251210153512_drop_unused_gin_index.sql (646.79µs)9872026/09/07 19:36:54 OK 20251218171726_add_pins.sql (4.32ms)9882026/09/07 19:36:54 INFO Received uploads request method=POST path=/api/pending_closures9892026/09/07 19:36:54 INFO Received create pin request method=POST path=/api/pins/myapp9902026/09/07 19:36:54 OK 20260628120000_add_object_size_and_stats.sql (17.9ms)9912026/09/07 19:36:54 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-35150-957684269/TestPinProtectsFromGC941329347/001/store/gi0vbnsw31cgawy2r9g8gj0kcms5ih4x-pinned-file.txt narinfo_key=gi0vbnsw31cgawy2r9g8gj0kcms5ih4x.narinfo9922026/09/07 19:36:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures9932026/09/07 19:36:54 INFO Garbage collection started9942026/09/07 19:36:54 INFO Aborted multipart uploads count=09952026/09/07 19:36:54 WARN Force mode enabled - objects will be deleted immediately without grace period9962026/09/07 19:36:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9972026/09/07 19:36:54 INFO Uploading 4gr2748z9sn7dbdsiq8gccmgvq9sg4xn-test-file.txt (152B)9982026/09/07 19:36:54 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"9992026/09/07 19:36:54 OK 20260905000000_add_claims.sql (19.61ms)10002026/09/07 19:36:54 goose: successfully migrated database to version: 202609050000001001=== NAME TestClientMultipleUploads1002 client_integration_test.go:339: Created store path 0: /nix/var/nix/builds/nix-35150-957684269/TestClientMultipleUploads772622790/001/store/vjqqp1ba1i2fy99c3v571pr9lw857ajp-test-file-0.txt10032026/09/07 19:36:54 OK 1_commit_pending_closure.sql (1.3ms)10042026/09/07 19:36:54 OK 2_object_stats_trigger.sql (707.5µs)10052026/09/07 19:36:54 goose: up to current file version: 210062026/09/07 19:36:54 WARN Failed to register uploaded object key=4gr2748z9sn7dbdsiq8gccmgvq9sg4xn.ls error="server returned 404: 404 page not found\n"10072026/09/07 19:36:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10082026/09/07 19:36:54 INFO Signed narinfos id=1 count=110092026/09/07 19:36:54 INFO Uploading 1 narinfos10102026/09/07 19:36:54 WARN Failed to register uploaded object key=4gr2748z9sn7dbdsiq8gccmgvq9sg4xn.narinfo error="server returned 404: 404 page not found\n"10112026/09/07 19:36:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10122026/09/07 19:36:54 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10132026/09/07 19:36:54 INFO Received uploads request method=POST path=/api/pending_closures10142026/09/07 19:36:54 INFO Completed upload id=110152026/09/07 19:36:54 INFO Upload complete. (148ms)1016=== NAME TestClientIntegration1017 client_integration_test.go:293: Retrieved narinfo from S3:1018 StorePath: /nix/var/nix/builds/nix-35150-957684269/TestClientIntegration4231612918/002/store/4gr2748z9sn7dbdsiq8gccmgvq9sg4xn-test-file.txt1019 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1020 Compression: zstd1021 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11022 NarSize: 1521023 References: 1024 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk110252026/09/07 19:36:54 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10262026/09/07 19:36:54 INFO Uploading w9s4ywl9vh981m3zghxi4ck7lracfryv-test-script (136B)1027 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1028 client_integration_test.go:294: Decompressed .ls content (64 bytes):1029 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1030 client_integration_test.go:297: Testing garbage collection...10312026/09/07 19:36:54 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"10322026/09/07 19:36:54 WARN Failed to register uploaded object key=log/1w519mb3z7c5jd52x7rzg5damj61kax8-test-script.drv error="server returned 404: 404 page not found\n"10332026/09/07 19:36:54 WARN Failed to register uploaded object key=w9s4ywl9vh981m3zghxi4ck7lracfryv.ls error="server returned 404: 404 page not found\n"10342026/09/07 19:36:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10352026/09/07 19:36:54 INFO Signed narinfos id=1 count=110362026/09/07 19:36:54 INFO Uploading 1 narinfos1037=== NAME TestClientMultipleUploads1038 client_integration_test.go:339: Created store path 1: /nix/var/nix/builds/nix-35150-957684269/TestClientMultipleUploads772622790/001/store/ib9klc74ak0bwxsvdf52rk0zanhnidw4-test-file-1.txt10392026/09/07 19:36:54 WARN Failed to register uploaded object key=w9s4ywl9vh981m3zghxi4ck7lracfryv.narinfo error="server returned 404: 404 page not found\n"10402026/09/07 19:36:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10412026/09/07 19:36:54 INFO Completed upload id=110422026/09/07 19:36:54 INFO Upload complete. (91ms)1043=== NAME TestClientWithDependencies1044 client_integration_test.go:598: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-35150-957684269/TestClientWithDependencies1177719766/001/store) requires matching store prefix10452026/09/07 19:36:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures10462026/09/07 19:36:54 INFO Garbage collection started10472026/09/07 19:36:54 INFO Aborted multipart uploads count=010482026/09/07 19:36:54 WARN Force mode enabled - objects will be deleted immediately without grace period1049--- PASS: TestClientWithDependencies (2.16s)1050=== CONT TestClaim_FailWakesWaitersButIsNotRemembered1051=== NAME TestClientMultipleUploads1052 client_integration_test.go:339: Created store path 2: /nix/var/nix/builds/nix-35150-957684269/TestClientMultipleUploads772622790/001/store/4c4nqcxk5g2yf94zw3jvw73a7kwchrnl-test-file-2.txt10532026-09-07 19:36:55.029 UTC [35402] ERROR: relation "goose_db_version" does not exist at character 3610542026-09-07 19:36:55.029 UTC [35402] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10552026/09/07 19:36:55 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10562026/09/07 19:36:55 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=010572026/09/07 19:36:55 OK 20241026095416_initial_model.sql (63.27ms)10582026/09/07 19:36:55 INFO Vacuumed table table=pending_closures10592026/09/07 19:36:55 OK 20251210153512_drop_unused_gin_index.sql (4.97ms)10602026/09/07 19:36:55 INFO Vacuumed table table=pending_objects10612026/09/07 19:36:55 OK 20251218171726_add_pins.sql (1.92ms)10622026/09/07 19:36:55 INFO Vacuumed table table=multipart_uploads10632026/09/07 19:36:55 INFO Received uploads request method=POST path=/api/pending_closures10642026/09/07 19:36:55 INFO Vacuumed table table=closures10652026/09/07 19:36:55 INFO Vacuumed table table=objects10662026/09/07 19:36:55 INFO Received uploads request method=POST path=/api/pending_closures10672026/09/07 19:36:55 OK 20260628120000_add_object_size_and_stats.sql (16.89ms)10682026/09/07 19:36:55 INFO Received uploads request method=POST path=/api/pending_closures10692026/09/07 19:36:55 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)10702026/09/07 19:36:55 INFO Uploading ib9klc74ak0bwxsvdf52rk0zanhnidw4-test-file-1.txt (160B)10712026/09/07 19:36:55 INFO Uploading 4c4nqcxk5g2yf94zw3jvw73a7kwchrnl-test-file-2.txt (160B)10722026/09/07 19:36:55 INFO Uploading vjqqp1ba1i2fy99c3v571pr9lw857ajp-test-file-0.txt (160B)10732026/09/07 19:36:55 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"10742026/09/07 19:36:55 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"10752026/09/07 19:36:55 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"10762026/09/07 19:36:55 OK 20260905000000_add_claims.sql (8.6ms)10772026/09/07 19:36:55 goose: successfully migrated database to version: 2026090500000010782026/09/07 19:36:55 OK 1_commit_pending_closure.sql (1.5ms)10792026/09/07 19:36:55 OK 2_object_stats_trigger.sql (228.17µs)10802026/09/07 19:36:55 goose: up to current file version: 210812026/09/07 19:36:55 WARN Failed to register uploaded object key=4c4nqcxk5g2yf94zw3jvw73a7kwchrnl.ls error="server returned 404: 404 page not found\n"10822026/09/07 19:36:55 WARN Failed to register uploaded object key=vjqqp1ba1i2fy99c3v571pr9lw857ajp.ls error="server returned 404: 404 page not found\n"10832026/09/07 19:36:55 WARN Failed to register uploaded object key=ib9klc74ak0bwxsvdf52rk0zanhnidw4.ls error="server returned 404: 404 page not found\n"10842026/09/07 19:36:55 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10852026/09/07 19:36:55 INFO Signed narinfos id=2 count=110862026/09/07 19:36:55 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign10872026/09/07 19:36:55 INFO Signed narinfos id=3 count=110882026/09/07 19:36:55 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10892026/09/07 19:36:55 INFO Signed narinfos id=1 count=110902026/09/07 19:36:55 INFO Uploading 3 narinfos10912026/09/07 19:36:55 WARN Failed to register uploaded object key=vjqqp1ba1i2fy99c3v571pr9lw857ajp.narinfo error="server returned 404: 404 page not found\n"10922026/09/07 19:36:55 WARN Failed to register uploaded object key=ib9klc74ak0bwxsvdf52rk0zanhnidw4.narinfo error="server returned 404: 404 page not found\n"10932026/09/07 19:36:55 WARN Failed to register uploaded object key=4c4nqcxk5g2yf94zw3jvw73a7kwchrnl.narinfo error="server returned 404: 404 page not found\n"10942026/09/07 19:36:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10952026/09/07 19:36:55 INFO Completed upload id=110962026/09/07 19:36:55 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10972026/09/07 19:36:55 INFO Completed upload id=210982026/09/07 19:36:55 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete10992026/09/07 19:36:55 INFO Completed upload id=311002026/09/07 19:36:55 INFO Upload complete. (132ms)1101 client_integration_test.go:350: Uploaded 3 paths in 167.368292ms11022026-09-07 19:36:55.200 UTC [35413] ERROR: relation "goose_db_version" does not exist at character 3611032026-09-07 19:36:55.200 UTC [35413] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1104--- PASS: TestClientMultipleUploads (2.16s)1105=== CONT TestClaim_HolderDisconnectKeepsClaim11062026/09/07 19:36:55 INFO Received uploads request method=POST path=/api/pending_closures1107=== NAME TestClientCADerivations1108 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-35150-957684269/TestClientCADerivations2920046538/001/store/30c5bhfq3ndi8qib4ksi62w9b7lsj3s8-ca-test11092026/09/07 19:36:55 OK 20241026095416_initial_model.sql (27.59ms)11102026/09/07 19:36:55 OK 20251210153512_drop_unused_gin_index.sql (10.92ms)11112026/09/07 19:36:55 OK 20251218171726_add_pins.sql (5.13ms)11122026/09/07 19:36:55 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3003 objects-failed-to-delete=011132026/09/07 19:36:55 INFO Vacuumed table table=pending_closures1114 client_ca_test.go:139: Found 1 dependencies (including self)11152026/09/07 19:36:55 OK 20260628120000_add_object_size_and_stats.sql (18.65ms)11162026/09/07 19:36:55 INFO Vacuumed table table=pending_objects11172026/09/07 19:36:55 INFO Vacuumed table table=multipart_uploads11182026/09/07 19:36:55 INFO Vacuumed table table=closures11192026/09/07 19:36:55 OK 20260905000000_add_claims.sql (58.84ms)11202026/09/07 19:36:55 goose: successfully migrated database to version: 2026090500000011212026/09/07 19:36:55 INFO Vacuumed table table=objects11222026/09/07 19:36:55 OK 1_commit_pending_closure.sql (1.02ms)11232026/09/07 19:36:55 OK 2_object_stats_trigger.sql (282.79µs)11242026/09/07 19:36:55 goose: up to current file version: 211252026/09/07 19:36:55 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11262026/09/07 19:36:55 INFO Received uploads request method=POST path=/api/pending_closures11272026/09/07 19:36:55 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11282026/09/07 19:36:55 INFO Uploading 30c5bhfq3ndi8qib4ksi62w9b7lsj3s8-ca-test (144B)11292026/09/07 19:36:55 WARN claim: cannot clear write deadline error="feature not supported"11302026/09/07 19:36:55 WARN claim: cannot clear write deadline error="feature not supported"11312026/09/07 19:36:55 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"11322026/09/07 19:36:55 WARN claim: cannot clear write deadline error="feature not supported"11332026/09/07 19:36:55 INFO Received uploads request method=POST path=/api/pending_closures11342026/09/07 19:36:55 WARN Failed to register uploaded object key=30c5bhfq3ndi8qib4ksi62w9b7lsj3s8.ls error="server returned 404: 404 page not found\n"11352026/09/07 19:36:55 WARN Failed to register uploaded object key=log/krb5ir7zjd305hma7719hs4d14qk0zcp-ca-test.drv error="server returned 404: 404 page not found\n"11362026/09/07 19:36:55 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11372026/09/07 19:36:55 INFO Signed narinfos id=1 count=111382026/09/07 19:36:55 INFO Uploading 1 narinfos11392026/09/07 19:36:55 WARN Failed to register uploaded object key=30c5bhfq3ndi8qib4ksi62w9b7lsj3s8.narinfo error="server returned 404: 404 page not found\n"11402026/09/07 19:36:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11412026/09/07 19:36:55 INFO Completed upload id=111422026/09/07 19:36:55 INFO Upload complete. (143ms)1143 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-35150-957684269/TestClientCADerivations2920046538/001/store/30c5bhfq3ndi8qib4ksi62w9b7lsj3s8-ca-test1144 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1145 Compression: zstd1146 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1147 NarSize: 1441148 References: 1149 Deriver: /nix/var/nix/builds/nix-35150-957684269/TestClientCADerivations2920046538/001/store/krb5ir7zjd305hma7719hs4d14qk0zcp-ca-test.drv1150 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1151 client_ca_test.go:185: Checking for realisation files in S3...1152 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1153 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1154 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket18?endpoint=http://localhost:57192®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-35150-957684269/TestClientCADerivations2920046538/001/store'1155 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11156--- PASS: TestClientCADerivations (2.44s)1157=== CONT TestClaim_TooManyStreams11582026/09/07 19:36:55 WARN claim: cannot clear write deadline error="feature not supported"11592026/09/07 19:36:55 WARN claim: cannot clear write deadline error="feature not supported"1160--- PASS: TestClaim_StaleHeartbeatStolen (1.37s)1161=== CONT TestClaim_GCMarkedOutputCountsAsAbsent11622026-09-07 19:36:55.723 UTC [35435] ERROR: relation "goose_db_version" does not exist at character 3611632026-09-07 19:36:55.723 UTC [35435] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11642026/09/07 19:36:55 WARN claim: cannot clear write deadline error="feature not supported"11652026/09/07 19:36:55 WARN claim: cannot clear write deadline error="feature not supported"1166--- PASS: TestClaim_FailWithoutKindReleases (1.15s)1167=== CONT TestClaim_BuildWaitComplete11682026/09/07 19:36:55 OK 20241026095416_initial_model.sql (125.08ms)11692026/09/07 19:36:55 OK 20251210153512_drop_unused_gin_index.sql (7.41ms)11702026/09/07 19:36:55 OK 20251218171726_add_pins.sql (8.83ms)11712026/09/07 19:36:55 OK 20260628120000_add_object_size_and_stats.sql (11.9ms)11722026/09/07 19:36:55 OK 20260905000000_add_claims.sql (24.6ms)11732026/09/07 19:36:55 goose: successfully migrated database to version: 2026090500000011742026/09/07 19:36:55 OK 1_commit_pending_closure.sql (1.25ms)11752026/09/07 19:36:55 OK 2_object_stats_trigger.sql (255.21µs)11762026/09/07 19:36:55 goose: up to current file version: 211772026-09-07 19:36:56.073 UTC [35439] ERROR: relation "goose_db_version" does not exist at character 3611782026-09-07 19:36:56.073 UTC [35439] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11792026/09/07 19:36:56 WARN claim: cannot clear write deadline error="feature not supported"11802026/09/07 19:36:56 WARN claim: cannot clear write deadline error="feature not supported"11812026/09/07 19:36:56 WARN claim: cannot clear write deadline error="feature not supported"1182--- PASS: TestClaim_FailWakesWaitersButIsNotRemembered (1.18s)1183=== CONT TestCacheStatsHandler11842026/09/07 19:36:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11852026/09/07 19:36:56 OK 20241026095416_initial_model.sql (109.62ms)11862026/09/07 19:36:56 OK 20251210153512_drop_unused_gin_index.sql (1.14ms)11872026/09/07 19:36:56 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001700000000000000000000.nar.zst upload_id=MDZjODFmNzctYjI3My00YTAyLWI5NmYtYTgzOGZkY2MxMDYwLjc1YmJlYmRmLWEyNTQtNDFhMC1iZjRiLTgzYTcxODQ3MjM0N3gxNzg4ODA5ODE1MjQyNjQ2MDAw parts=1011882026/09/07 19:36:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11892026/09/07 19:36:56 OK 20251218171726_add_pins.sql (1.65ms)11902026/09/07 19:36:56 INFO Completed upload id=111912026/09/07 19:36:56 OK 20260628120000_add_object_size_and_stats.sql (5.99ms)11922026/09/07 19:36:56 WARN claim: cannot clear write deadline error="feature not supported"11932026/09/07 19:36:56 INFO Aborted multipart uploads count=011942026/09/07 19:36:56 WARN Force mode enabled - objects will be deleted immediately without grace period11952026/09/07 19:36:56 OK 20260905000000_add_claims.sql (31.15ms)11962026/09/07 19:36:56 goose: successfully migrated database to version: 2026090500000011972026/09/07 19:36:56 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=011982026/09/07 19:36:56 OK 1_commit_pending_closure.sql (6.92ms)11992026/09/07 19:36:56 OK 2_object_stats_trigger.sql (370.33µs)12002026/09/07 19:36:56 goose: up to current file version: 212012026/09/07 19:36:56 INFO Vacuumed table table=pending_closures12022026/09/07 19:36:56 INFO Vacuumed table table=pending_objects12032026/09/07 19:36:56 INFO Vacuumed table table=multipart_uploads12042026/09/07 19:36:56 INFO Vacuumed table table=closures12052026/09/07 19:36:56 INFO Vacuumed table table=objects1206--- PASS: TestClaim_InputsTouched (2.84s)1207=== CONT TestCacheConfigHandler1208=== RUN TestCacheConfigHandler/full_config,_no_issuer1209=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1210=== RUN TestCacheConfigHandler/no_cache_url_configured1211=== PAUSE TestCacheConfigHandler/no_cache_url_configured1212=== RUN TestCacheConfigHandler/no_signing_keys1213=== PAUSE TestCacheConfigHandler/no_signing_keys1214=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1215=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1216=== CONT TestService_ReadScope_PublicByDefault12172026/09/07 19:36:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12182026/09/07 19:36:56 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001600000000000000000000.nar.zst upload_id=MDZjODFmNzctYjI3My00YTAyLWI5NmYtYTgzOGZkY2MxMDYwLmY0ZDdiMDllLTliMzMtNDhhNC1hZDRiLThkMTkzZTg2YzcyNHgxNzg4ODA5ODE1NDMwNDcxMDAw parts=1012192026/09/07 19:36:56 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12202026/09/07 19:36:56 INFO Signed narinfos id=1 count=112212026/09/07 19:36:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12222026/09/07 19:36:56 INFO Completed upload id=11223--- PASS: TestClaim_TwoInstances (2.62s)1224=== CONT TestService_RequireScope_OIDC12252026/09/07 19:36:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57301/oidc12262026/09/07 19:36:56 WARN claim: cannot clear write deadline error="feature not supported"12272026/09/07 19:36:56 WARN claim: cannot clear write deadline error="feature not supported"12282026-09-07 19:36:56.512 UTC [35449] ERROR: relation "goose_db_version" does not exist at character 3612292026-09-07 19:36:56.512 UTC [35449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12302026-09-07 19:36:56.512 UTC [35450] ERROR: relation "goose_db_version" does not exist at character 3612312026-09-07 19:36:56.512 UTC [35450] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12322026/09/07 19:36:56 OK 20241026095416_initial_model.sql (7.51ms)12332026/09/07 19:36:56 OK 20251210153512_drop_unused_gin_index.sql (611.75µs)12342026/09/07 19:36:56 OK 20241026095416_initial_model.sql (9.45ms)12352026/09/07 19:36:56 OK 20251210153512_drop_unused_gin_index.sql (497.63µs)12362026/09/07 19:36:56 OK 20251218171726_add_pins.sql (1.4ms)12372026/09/07 19:36:56 OK 20251218171726_add_pins.sql (910.25µs)12382026/09/07 19:36:56 OK 20260628120000_add_object_size_and_stats.sql (2.81ms)12392026/09/07 19:36:56 OK 20260628120000_add_object_size_and_stats.sql (3.51ms)12402026/09/07 19:36:56 OK 20260905000000_add_claims.sql (1.71ms)12412026/09/07 19:36:56 goose: successfully migrated database to version: 2026090500000012422026/09/07 19:36:56 OK 20260905000000_add_claims.sql (1.75ms)12432026/09/07 19:36:56 goose: successfully migrated database to version: 2026090500000012442026/09/07 19:36:56 OK 1_commit_pending_closure.sql (1.11ms)12452026/09/07 19:36:56 OK 1_commit_pending_closure.sql (1.26ms)12462026/09/07 19:36:56 OK 2_object_stats_trigger.sql (244.67µs)12472026/09/07 19:36:56 goose: up to current file version: 212482026/09/07 19:36:56 OK 2_object_stats_trigger.sql (283.71µs)12492026/09/07 19:36:56 goose: up to current file version: 212502026-09-07 19:36:56.578 UTC [35451] ERROR: relation "goose_db_version" does not exist at character 3612512026-09-07 19:36:56.578 UTC [35451] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1252--- PASS: TestClaim_StreamsThroughServer (3.24s)1253=== CONT TestService_AuthMiddleware_OIDC12542026/09/07 19:36:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57305/oidc12552026/09/07 19:36:56 OK 20241026095416_initial_model.sql (55.01ms)12562026/09/07 19:36:56 OK 20251210153512_drop_unused_gin_index.sql (5.92ms)12572026/09/07 19:36:56 OK 20251218171726_add_pins.sql (12.35ms)12582026/09/07 19:36:56 INFO Received uploads request method=POST path=/api/pending_closures12592026/09/07 19:36:56 OK 20260628120000_add_object_size_and_stats.sql (2.8ms)12602026/09/07 19:36:56 OK 20260905000000_add_claims.sql (35.81ms)12612026/09/07 19:36:56 goose: successfully migrated database to version: 2026090500000012622026/09/07 19:36:56 OK 1_commit_pending_closure.sql (1.9ms)12632026/09/07 19:36:56 OK 2_object_stats_trigger.sql (390.33µs)12642026/09/07 19:36:56 goose: up to current file version: 212652026/09/07 19:36:56 WARN claim: cannot clear write deadline error="feature not supported"1266--- PASS: TestClaim_TooManyStreams (1.22s)1267=== CONT TestService_ReadAuthMiddleware12682026/09/07 19:36:56 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01269=== NAME TestPinProtectsFromGC1270 client_integration_test.go:711: Pin successfully protected closure from garbage collection1271--- PASS: TestPinProtectsFromGC (4.16s)1272=== CONT TestService_AuthMiddleware_MTLSBoundSubjects12732026/09/07 19:36:56 WARN claim: cannot clear write deadline error="feature not supported"12742026/09/07 19:36:56 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3003 objects_failed=01275=== NAME TestClientIntegration1276 client_integration_test.go:304: Objects in database after GC:1277 client_integration_test.go:304: Successfully deleted all objects with GC --force1278--- PASS: TestClientIntegration (3.99s)1279=== CONT TestService_AuthMiddleware_MTLSProxyHeader12802026/09/07 19:36:57 WARN claim: cannot clear write deadline error="feature not supported"12812026/09/07 19:36:57 WARN claim: cannot clear write deadline error="feature not supported"12822026/09/07 19:36:57 WARN claim: cannot clear write deadline error="feature not supported"12832026/09/07 19:36:57 INFO Received uploads request method=POST path=/api/pending_closures12842026-09-07 19:36:57.074 UTC [35463] ERROR: relation "goose_db_version" does not exist at character 3612852026-09-07 19:36:57.074 UTC [35463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12862026-09-07 19:36:57.139 UTC [35464] ERROR: relation "goose_db_version" does not exist at character 3612872026-09-07 19:36:57.139 UTC [35464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12882026/09/07 19:36:57 OK 20241026095416_initial_model.sql (99.98ms)12892026-09-07 19:36:57.240 UTC [35466] ERROR: relation "goose_db_version" does not exist at character 3612902026-09-07 19:36:57.240 UTC [35466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12912026/09/07 19:36:57 OK 20251210153512_drop_unused_gin_index.sql (8.73ms)12922026/09/07 19:36:57 OK 20241026095416_initial_model.sql (92.75ms)12932026/09/07 19:36:57 OK 20251218171726_add_pins.sql (5.16ms)12942026/09/07 19:36:57 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)12952026/09/07 19:36:57 OK 20260628120000_add_object_size_and_stats.sql (4.61ms)12962026/09/07 19:36:57 OK 20251218171726_add_pins.sql (3.2ms)12972026/09/07 19:36:57 OK 20260905000000_add_claims.sql (4.21ms)12982026/09/07 19:36:57 goose: successfully migrated database to version: 2026090500000012992026/09/07 19:36:57 OK 20260628120000_add_object_size_and_stats.sql (4.4ms)13002026/09/07 19:36:57 OK 1_commit_pending_closure.sql (2.77ms)13012026/09/07 19:36:57 OK 2_object_stats_trigger.sql (779.88µs)13022026/09/07 19:36:57 goose: up to current file version: 213032026/09/07 19:36:57 OK 20260905000000_add_claims.sql (3.93ms)13042026/09/07 19:36:57 goose: successfully migrated database to version: 2026090500000013052026/09/07 19:36:57 OK 1_commit_pending_closure.sql (2.15ms)13062026/09/07 19:36:57 OK 2_object_stats_trigger.sql (360.58µs)13072026/09/07 19:36:57 goose: up to current file version: 213082026/09/07 19:36:57 OK 20241026095416_initial_model.sql (23.5ms)13092026/09/07 19:36:57 OK 20251210153512_drop_unused_gin_index.sql (11.49ms)13102026/09/07 19:36:57 OK 20251218171726_add_pins.sql (22.21ms)13112026/09/07 19:36:57 OK 20260628120000_add_object_size_and_stats.sql (23.13ms)13122026/09/07 19:36:57 OK 20260905000000_add_claims.sql (27.29ms)13132026/09/07 19:36:57 goose: successfully migrated database to version: 2026090500000013142026/09/07 19:36:57 OK 1_commit_pending_closure.sql (2.61ms)13152026/09/07 19:36:57 OK 2_object_stats_trigger.sql (512.46µs)13162026/09/07 19:36:57 goose: up to current file version: 21317--- PASS: TestCacheStatsHandler (1.50s)1318=== CONT TestOrphanedObjectsGC1319--- PASS: TestService_ReadScope_PublicByDefault (1.50s)1320=== CONT TestIsValidCachePath1321=== RUN TestIsValidCachePath/narinfo1322=== PAUSE TestIsValidCachePath/narinfo1323=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1324=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1325=== RUN TestIsValidCachePath/nar_zst1326=== PAUSE TestIsValidCachePath/nar_zst1327=== RUN TestIsValidCachePath/nar_xz1328=== PAUSE TestIsValidCachePath/nar_xz1329=== RUN TestIsValidCachePath/nar_bz21330=== PAUSE TestIsValidCachePath/nar_bz21331=== RUN TestIsValidCachePath/nar_uncompressed1332=== PAUSE TestIsValidCachePath/nar_uncompressed1333=== RUN TestIsValidCachePath/ls1334=== PAUSE TestIsValidCachePath/ls1335=== RUN TestIsValidCachePath/log1336=== PAUSE TestIsValidCachePath/log1337=== RUN TestIsValidCachePath/realisation1338=== PAUSE TestIsValidCachePath/realisation1339=== RUN TestIsValidCachePath/nix-cache-info1340=== PAUSE TestIsValidCachePath/nix-cache-info1341=== RUN TestIsValidCachePath/index.html1342=== PAUSE TestIsValidCachePath/index.html1343=== RUN TestIsValidCachePath/traversal_parent1344=== PAUSE TestIsValidCachePath/traversal_parent1345=== RUN TestIsValidCachePath/traversal_in_middle1346=== PAUSE TestIsValidCachePath/traversal_in_middle1347=== RUN TestIsValidCachePath/invalid_char_e1348=== PAUSE TestIsValidCachePath/invalid_char_e1349=== RUN TestIsValidCachePath/invalid_char_u1350=== PAUSE TestIsValidCachePath/invalid_char_u1351=== RUN TestIsValidCachePath/random_path1352=== PAUSE TestIsValidCachePath/random_path1353=== RUN TestIsValidCachePath/empty1354=== PAUSE TestIsValidCachePath/empty1355=== RUN TestIsValidCachePath/leading_slash1356=== PAUSE TestIsValidCachePath/leading_slash1357=== RUN TestIsValidCachePath/wrong_extension1358=== PAUSE TestIsValidCachePath/wrong_extension1359=== RUN TestIsValidCachePath/short_hash1360=== PAUSE TestIsValidCachePath/short_hash1361=== CONT TestParseSingleRange1362=== RUN TestParseSingleRange/none1363=== PAUSE TestParseSingleRange/none1364=== RUN TestParseSingleRange/unknown_unit1365=== PAUSE TestParseSingleRange/unknown_unit1366=== RUN TestParseSingleRange/multi-range_ignored1367=== PAUSE TestParseSingleRange/multi-range_ignored1368=== RUN TestParseSingleRange/malformed_no_dash1369=== PAUSE TestParseSingleRange/malformed_no_dash1370=== RUN TestParseSingleRange/malformed_both_empty1371=== PAUSE TestParseSingleRange/malformed_both_empty1372=== RUN TestParseSingleRange/malformed_end_before_start1373=== PAUSE TestParseSingleRange/malformed_end_before_start1374=== RUN TestParseSingleRange/closed1375=== PAUSE TestParseSingleRange/closed1376=== RUN TestParseSingleRange/open-ended1377=== PAUSE TestParseSingleRange/open-ended1378=== RUN TestParseSingleRange/end_clamped_to_size1379=== PAUSE TestParseSingleRange/end_clamped_to_size1380=== RUN TestParseSingleRange/suffix1381=== PAUSE TestParseSingleRange/suffix1382=== RUN TestParseSingleRange/suffix_exceeds_size1383=== PAUSE TestParseSingleRange/suffix_exceeds_size1384=== RUN TestParseSingleRange/single_byte1385=== PAUSE TestParseSingleRange/single_byte1386=== RUN TestParseSingleRange/start_past_EOF1387=== PAUSE TestParseSingleRange/start_past_EOF1388=== RUN TestParseSingleRange/start_far_past_EOF1389=== PAUSE TestParseSingleRange/start_far_past_EOF1390=== CONT TestResurrectedObjectNotDeleted13912026/09/07 19:36:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13922026/09/07 19:36:57 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001100000000000000000000.nar.zst upload_id=MDZjODFmNzctYjI3My00YTAyLWI5NmYtYTgzOGZkY2MxMDYwLjhkMGEwMGFjLWEyYTAtNGQ5My1iZWU1LWY1NWQzZTlmZWY0ZXgxNzg4ODA5ODE2NzEyMjgzMDAw parts=1013932026/09/07 19:36:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13942026/09/07 19:36:57 INFO Completed upload id=113952026/09/07 19:36:57 WARN claim: cannot clear write deadline error="feature not supported"13962026/09/07 19:36:57 WARN claim: cannot clear write deadline error="feature not supported"1397--- PASS: TestClaim_GCMarkedOutputCountsAsAbsent (2.34s)1398=== CONT TestOrphanedObjectsGCStressTest13992026-09-07 19:36:58.022 UTC [35474] ERROR: relation "goose_db_version" does not exist at character 3614002026-09-07 19:36:58.022 UTC [35474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1401=== RUN TestService_RequireScope_OIDC/builder_may_write1402=== PAUSE TestService_RequireScope_OIDC/builder_may_write1403=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1404=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1405=== RUN TestService_RequireScope_OIDC/ops_may_admin1406=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1407=== RUN TestService_RequireScope_OIDC/ops_may_not_write1408=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1409=== RUN TestService_RequireScope_OIDC/reader_may_not_write1410=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1411=== RUN TestService_RequireScope_OIDC/static_token_may_admin1412=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1413=== RUN TestService_RequireScope_OIDC/static_token_may_write1414=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1415=== RUN TestService_RequireScope_OIDC/reader_may_read1416=== PAUSE TestService_RequireScope_OIDC/reader_may_read1417=== RUN TestService_RequireScope_OIDC/writer_implies_read1418=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1419=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1420=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1421=== CONT TestServerTLSConfig1422=== RUN TestServerTLSConfig/no_client_CA1423=== PAUSE TestServerTLSConfig/no_client_CA1424=== RUN TestServerTLSConfig/missing_CA_file1425=== PAUSE TestServerTLSConfig/missing_CA_file1426=== RUN TestServerTLSConfig/not_a_PEM_file1427=== PAUSE TestServerTLSConfig/not_a_PEM_file1428=== CONT TestObjectStatsTrigger14292026/09/07 19:36:58 OK 20241026095416_initial_model.sql (133.49ms)14302026/09/07 19:36:58 OK 20251210153512_drop_unused_gin_index.sql (5.49ms)14312026/09/07 19:36:58 OK 20251218171726_add_pins.sql (9.1ms)14322026/09/07 19:36:58 OK 20260628120000_add_object_size_and_stats.sql (9.42ms)14332026-09-07 19:36:58.242 UTC [35477] ERROR: relation "goose_db_version" does not exist at character 3614342026-09-07 19:36:58.242 UTC [35477] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14352026/09/07 19:36:58 OK 20260905000000_add_claims.sql (2.79ms)14362026/09/07 19:36:58 goose: successfully migrated database to version: 2026090500000014372026/09/07 19:36:58 OK 1_commit_pending_closure.sql (2.08ms)14382026/09/07 19:36:58 OK 2_object_stats_trigger.sql (892.25µs)14392026/09/07 19:36:58 goose: up to current file version: 214402026-09-07 19:36:58.293 UTC [35478] ERROR: relation "goose_db_version" does not exist at character 3614412026-09-07 19:36:58.293 UTC [35478] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14422026/09/07 19:36:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14432026/09/07 19:36:58 INFO Completed multipart upload object_key=nar/0000000000000000000000000000001000000000000000000000.nar.zst upload_id=MDZjODFmNzctYjI3My00YTAyLWI5NmYtYTgzOGZkY2MxMDYwLmFlYjUzMzIyLTdkZDktNDBlYy1iMzFlLWZkNDYwODFkYTIzY3gxNzg4ODA5ODE3MDkwMzc3MDAw parts=1014442026/09/07 19:36:58 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14452026/09/07 19:36:58 INFO Signed narinfos id=1 count=114462026/09/07 19:36:58 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14472026/09/07 19:36:58 INFO Received uploads request method=POST path=/api/pending_closures14482026/09/07 19:36:58 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14492026/09/07 19:36:58 INFO Signed narinfos id=2 count=114502026/09/07 19:36:58 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14512026/09/07 19:36:58 INFO Completed upload id=214522026/09/07 19:36:58 WARN claim: cannot clear write deadline error="feature not supported"14532026/09/07 19:36:58 OK 20241026095416_initial_model.sql (150.99ms)1454--- PASS: TestClaim_BuildWaitComplete (2.58s)1455=== CONT TestMultipartCleanup14562026/09/07 19:36:58 OK 20251210153512_drop_unused_gin_index.sql (7.41ms)14572026/09/07 19:36:58 OK 20251218171726_add_pins.sql (21.57ms)14582026/09/07 19:36:58 OK 20241026095416_initial_model.sql (110.59ms)14592026/09/07 19:36:58 OK 20251210153512_drop_unused_gin_index.sql (8.19ms)14602026/09/07 19:36:58 OK 20260628120000_add_object_size_and_stats.sql (41.26ms)1461=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1462=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1463=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1464=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1465=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1466=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected14672026/09/07 19:36:58 OK 20251218171726_add_pins.sql (29.18ms)1468=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1469=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1470=== CONT TestUploadHandlersRejectInvalidKeys1471=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1472=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1473=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1474=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1475=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1476=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1477=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1478=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1479=== CONT TestService_createPendingClosureHandler14802026/09/07 19:36:58 OK 20260905000000_add_claims.sql (24.66ms)14812026/09/07 19:36:58 goose: successfully migrated database to version: 2026090500000014822026/09/07 19:36:58 OK 1_commit_pending_closure.sql (3.47ms)14832026/09/07 19:36:58 OK 2_object_stats_trigger.sql (774.13µs)14842026/09/07 19:36:58 goose: up to current file version: 214852026/09/07 19:36:58 OK 20260628120000_add_object_size_and_stats.sql (16.86ms)14862026/09/07 19:36:58 OK 20260905000000_add_claims.sql (121.44ms)14872026/09/07 19:36:58 goose: successfully migrated database to version: 2026090500000014882026/09/07 19:36:58 OK 1_commit_pending_closure.sql (4.14ms)14892026/09/07 19:36:58 OK 2_object_stats_trigger.sql (695.42µs)14902026/09/07 19:36:58 goose: up to current file version: 214912026-09-07 19:36:58.687 UTC [35483] ERROR: relation "goose_db_version" does not exist at character 3614922026-09-07 19:36:58.687 UTC [35483] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1493--- PASS: TestService_ReadAuthMiddleware (1.96s)1494=== CONT TestService_cleanupPendingClosuresHandler14952026/09/07 19:36:58 OK 20241026095416_initial_model.sql (79.63ms)14962026/09/07 19:36:58 OK 20251210153512_drop_unused_gin_index.sql (9.21ms)14972026/09/07 19:36:58 OK 20251218171726_add_pins.sql (8.64ms)14982026/09/07 19:36:58 OK 20260628120000_add_object_size_and_stats.sql (29.73ms)14992026/09/07 19:36:58 OK 20260905000000_add_claims.sql (63.81ms)15002026/09/07 19:36:58 goose: successfully migrated database to version: 2026090500000015012026/09/07 19:36:58 OK 1_commit_pending_closure.sql (10.65ms)15022026/09/07 19:36:58 OK 2_object_stats_trigger.sql (813.88µs)15032026/09/07 19:36:58 goose: up to current file version: 21504--- PASS: TestClaim_HolderDisconnectKeepsClaim (3.77s)1505=== CONT TestUploadHandlersRejectOversizedBody1506=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1507=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1508=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1509=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1510=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1511=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1512=== CONT TestService_Rustfstest15132026/09/07 19:36:59 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15142026/09/07 19:36:59 WARN mTLS auth: bound subjects configured but subject DN unavailable15152026/09/07 19:36:59 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1516--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.10s)1517=== CONT TestParseSize1518--- PASS: TestParseSize (0.00s)1519=== CONT TestReadRedirectUsesPublicS3URL1520--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.28s)1521=== CONT TestRedundantMultipartUpload15222026-09-07 19:36:59.359 UTC [35490] ERROR: relation "goose_db_version" does not exist at character 3615232026-09-07 19:36:59.359 UTC [35490] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15242026-09-07 19:36:59.488 UTC [35493] ERROR: relation "goose_db_version" does not exist at character 3615252026-09-07 19:36:59.488 UTC [35493] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15262026/09/07 19:36:59 OK 20241026095416_initial_model.sql (136.78ms)15272026/09/07 19:36:59 OK 20251210153512_drop_unused_gin_index.sql (12.89ms)15282026/09/07 19:36:59 OK 20251218171726_add_pins.sql (42.81ms)15292026/09/07 19:36:59 OK 20260628120000_add_object_size_and_stats.sql (24.06ms)15302026/09/07 19:36:59 OK 20241026095416_initial_model.sql (146.33ms)15312026/09/07 19:36:59 OK 20251210153512_drop_unused_gin_index.sql (7.99ms)15322026/09/07 19:36:59 OK 20260905000000_add_claims.sql (44.87ms)15332026/09/07 19:36:59 goose: successfully migrated database to version: 2026090500000015342026-09-07 19:36:59.704 UTC [35494] ERROR: relation "goose_db_version" does not exist at character 3615352026-09-07 19:36:59.704 UTC [35494] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15362026/09/07 19:36:59 OK 1_commit_pending_closure.sql (4.85ms)15372026/09/07 19:36:59 OK 2_object_stats_trigger.sql (690.71µs)15382026/09/07 19:36:59 goose: up to current file version: 215392026/09/07 19:36:59 OK 20251218171726_add_pins.sql (19.21ms)15402026/09/07 19:36:59 OK 20260628120000_add_object_size_and_stats.sql (28.51ms)15412026-09-07 19:36:59.767 UTC [35495] ERROR: relation "goose_db_version" does not exist at character 3615422026-09-07 19:36:59.767 UTC [35495] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15432026/09/07 19:36:59 OK 20260905000000_add_claims.sql (20.08ms)15442026/09/07 19:36:59 goose: successfully migrated database to version: 2026090500000015452026/09/07 19:36:59 OK 1_commit_pending_closure.sql (3.41ms)15462026/09/07 19:36:59 OK 2_object_stats_trigger.sql (659.75µs)15472026/09/07 19:36:59 goose: up to current file version: 215482026/09/07 19:36:59 OK 20241026095416_initial_model.sql (58.46ms)15492026/09/07 19:36:59 OK 20251210153512_drop_unused_gin_index.sql (16.2ms)15502026/09/07 19:36:59 OK 20251218171726_add_pins.sql (28.73ms)15512026/09/07 19:36:59 OK 20260628120000_add_object_size_and_stats.sql (38.37ms)15522026/09/07 19:36:59 OK 20260905000000_add_claims.sql (61.92ms)15532026/09/07 19:36:59 goose: successfully migrated database to version: 2026090500000015542026/09/07 19:36:59 OK 1_commit_pending_closure.sql (10.41ms)15552026/09/07 19:36:59 OK 2_object_stats_trigger.sql (1.22ms)15562026/09/07 19:36:59 goose: up to current file version: 215572026/09/07 19:36:59 OK 20241026095416_initial_model.sql (196.18ms)15582026/09/07 19:37:00 OK 20251210153512_drop_unused_gin_index.sql (15.26ms)15592026/09/07 19:37:00 OK 20251218171726_add_pins.sql (22.07ms)15602026/09/07 19:37:00 OK 20260628120000_add_object_size_and_stats.sql (20.05ms)15612026-09-07 19:37:00.157 UTC [35498] ERROR: relation "goose_db_version" does not exist at character 3615622026-09-07 19:37:00.157 UTC [35498] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15632026/09/07 19:37:00 OK 20260905000000_add_claims.sql (121.11ms)15642026/09/07 19:37:00 goose: successfully migrated database to version: 2026090500000015652026/09/07 19:37:00 OK 1_commit_pending_closure.sql (10.08ms)15662026/09/07 19:37:00 OK 2_object_stats_trigger.sql (829.25µs)15672026/09/07 19:37:00 goose: up to current file version: 215682026/09/07 19:37:00 OK 20241026095416_initial_model.sql (261.66ms)15692026/09/07 19:37:00 OK 20251210153512_drop_unused_gin_index.sql (11.04ms)1570--- PASS: TestResurrectedObjectNotDeleted (2.70s)1571=== CONT TestService_NativeMTLS15722026/09/07 19:37:00 OK 20251218171726_add_pins.sql (36.19ms)15732026/09/07 19:37:00 OK 20260628120000_add_object_size_and_stats.sql (40.13ms)15742026-09-07 19:37:00.625 UTC [35500] ERROR: relation "goose_db_version" does not exist at character 3615752026-09-07 19:37:00.625 UTC [35500] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15762026/09/07 19:37:00 OK 20260905000000_add_claims.sql (75.46ms)15772026/09/07 19:37:00 goose: successfully migrated database to version: 2026090500000015782026/09/07 19:37:00 OK 1_commit_pending_closure.sql (4.57ms)15792026/09/07 19:37:00 OK 2_object_stats_trigger.sql (766.42µs)15802026/09/07 19:37:00 goose: up to current file version: 215812026/09/07 19:37:00 OK 20241026095416_initial_model.sql (245.68ms)1582=== NAME TestOrphanedObjectsGC1583 orphaned_objects_gc_test.go:290: GC Test Summary:1584 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1585 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1586 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1587 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1588 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1589--- PASS: TestOrphanedObjectsGC (3.30s)1590=== CONT TestPresignedUploadRegisteredBeforeCommit15912026/09/07 19:37:00 OK 20251210153512_drop_unused_gin_index.sql (15.56ms)15922026/09/07 19:37:01 OK 20251218171726_add_pins.sql (41.55ms)1593--- PASS: TestObjectStatsTrigger (2.93s)1594=== CONT TestMetricsInventory15952026/09/07 19:37:01 OK 20260628120000_add_object_size_and_stats.sql (48.29ms)15962026-09-07 19:37:01.112 UTC [35505] ERROR: relation "goose_db_version" does not exist at character 3615972026-09-07 19:37:01.112 UTC [35505] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15982026/09/07 19:37:01 OK 20260905000000_add_claims.sql (72.18ms)15992026/09/07 19:37:01 goose: successfully migrated database to version: 2026090500000016002026/09/07 19:37:01 OK 1_commit_pending_closure.sql (10.31ms)16012026/09/07 19:37:01 OK 2_object_stats_trigger.sql (729.08µs)16022026/09/07 19:37:01 goose: up to current file version: 216032026-09-07 19:37:01.307 UTC [35508] ERROR: relation "goose_db_version" does not exist at character 3616042026-09-07 19:37:01.307 UTC [35508] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16052026/09/07 19:37:01 INFO Received uploads request method=POST path=/api/pending_closures16062026-09-07 19:37:01.345 UTC [35509] ERROR: relation "goose_db_version" does not exist at character 3616072026-09-07 19:37:01.345 UTC [35509] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16082026/09/07 19:37:01 OK 20241026095416_initial_model.sql (175.12ms)16092026/09/07 19:37:01 OK 20251210153512_drop_unused_gin_index.sql (17.62ms)16102026/09/07 19:37:01 OK 20251218171726_add_pins.sql (55.63ms)16112026/09/07 19:37:01 OK 20260628120000_add_object_size_and_stats.sql (49.81ms)16122026-09-07 19:37:01.491 UTC [35510] ERROR: relation "goose_db_version" does not exist at character 3616132026-09-07 19:37:01.491 UTC [35510] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16142026/09/07 19:37:01 OK 20260905000000_add_claims.sql (30.31ms)16152026/09/07 19:37:01 goose: successfully migrated database to version: 2026090500000016162026/09/07 19:37:01 OK 1_commit_pending_closure.sql (10.03ms)16172026/09/07 19:37:01 OK 2_object_stats_trigger.sql (784.96µs)16182026/09/07 19:37:01 goose: up to current file version: 216192026/09/07 19:37:01 INFO Received cleanup request method=DELETE path=/api/pending_closures16202026/09/07 19:37:01 INFO Aborted multipart uploads count=116212026/09/07 19:37:01 OK 20241026095416_initial_model.sql (134.75ms)16222026/09/07 19:37:01 OK 20241026095416_initial_model.sql (108.84ms)1623--- PASS: TestMultipartCleanup (3.10s)1624=== CONT TestReadProxyRangeRequest16252026/09/07 19:37:01 OK 20251210153512_drop_unused_gin_index.sql (5.65ms)16262026/09/07 19:37:01 OK 20251210153512_drop_unused_gin_index.sql (11.12ms)16272026/09/07 19:37:01 OK 20251218171726_add_pins.sql (25.07ms)16282026/09/07 19:37:01 OK 20251218171726_add_pins.sql (26.59ms)16292026/09/07 19:37:01 OK 20260628120000_add_object_size_and_stats.sql (14.43ms)16302026/09/07 19:37:01 OK 20260628120000_add_object_size_and_stats.sql (19.27ms)16312026/09/07 19:37:01 INFO Received uploads request method=POST path=/api/pending_closures16322026/09/07 19:37:01 INFO Received uploads request method=POST path=/api/pending_closures16332026/09/07 19:37:01 INFO Received uploads request method=POST path=/api/pending_closures16342026/09/07 19:37:01 OK 20260905000000_add_claims.sql (27.96ms)16352026/09/07 19:37:01 goose: successfully migrated database to version: 2026090500000016362026/09/07 19:37:01 OK 1_commit_pending_closure.sql (2.43ms)16372026/09/07 19:37:01 OK 2_object_stats_trigger.sql (437.75µs)16382026/09/07 19:37:01 goose: up to current file version: 216392026/09/07 19:37:01 OK 20260905000000_add_claims.sql (24.68ms)16402026/09/07 19:37:01 goose: successfully migrated database to version: 2026090500000016412026/09/07 19:37:01 OK 1_commit_pending_closure.sql (2.7ms)16422026/09/07 19:37:01 OK 2_object_stats_trigger.sql (484.04µs)16432026/09/07 19:37:01 goose: up to current file version: 216442026/09/07 19:37:01 OK 20241026095416_initial_model.sql (107.22ms)16452026/09/07 19:37:01 OK 20251210153512_drop_unused_gin_index.sql (7.68ms)16462026/09/07 19:37:01 OK 20251218171726_add_pins.sql (15.1ms)16472026/09/07 19:37:01 OK 20260628120000_add_object_size_and_stats.sql (12.7ms)16482026/09/07 19:37:01 OK 20260905000000_add_claims.sql (45.35ms)16492026/09/07 19:37:01 goose: successfully migrated database to version: 2026090500000016502026/09/07 19:37:01 OK 1_commit_pending_closure.sql (6.78ms)16512026/09/07 19:37:01 OK 2_object_stats_trigger.sql (426.96µs)16522026/09/07 19:37:01 goose: up to current file version: 216532026/09/07 19:37:01 INFO Received cleanup request method=DELETE path=/api/pending_closures16542026/09/07 19:37:01 INFO Aborted multipart uploads count=016552026/09/07 19:37:01 INFO Received uploads request method=POST path=/api/pending_closures16562026/09/07 19:37:01 INFO Received cleanup request method=DELETE path=/api/pending_closures16572026/09/07 19:37:01 INFO Aborted multipart uploads count=116582026/09/07 19:37:01 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16592026-09-07 19:37:01.898 UTC [35505] ERROR: Closure does not exist: id=116602026-09-07 19:37:01.898 UTC [35505] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE16612026-09-07 19:37:01.898 UTC [35505] STATEMENT: -- name: CommitPendingClosure :exec1662 SELECT commit_pending_closure($1::bigint)1663 1664--- PASS: TestService_cleanupPendingClosuresHandler (3.10s)1665=== CONT TestReadProxyHead1666--- PASS: TestReadRedirectUsesPublicS3URL (3.08s)1667=== CONT TestReadRedirectNar16682026-09-07 19:37:02.316 UTC [35517] ERROR: relation "goose_db_version" does not exist at character 3616692026-09-07 19:37:02.316 UTC [35517] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1670--- PASS: TestService_Rustfstest (3.35s)1671=== CONT TestReadProxyDisabled16722026/09/07 19:37:02 OK 20241026095416_initial_model.sql (159.1ms)16732026/09/07 19:37:02 OK 20251210153512_drop_unused_gin_index.sql (9.96ms)16742026/09/07 19:37:02 OK 20251218171726_add_pins.sql (34.92ms)16752026-09-07 19:37:02.594 UTC [35520] ERROR: relation "goose_db_version" does not exist at character 3616762026-09-07 19:37:02.594 UTC [35520] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16772026/09/07 19:37:02 OK 20260628120000_add_object_size_and_stats.sql (21.95ms)16782026/09/07 19:37:02 INFO Received uploads request method=POST path=/api/pending_closures16792026/09/07 19:37:02 OK 20260905000000_add_claims.sql (31.22ms)16802026/09/07 19:37:02 goose: successfully migrated database to version: 2026090500000016812026/09/07 19:37:02 OK 1_commit_pending_closure.sql (11.59ms)16822026/09/07 19:37:02 OK 2_object_stats_trigger.sql (849.88µs)16832026/09/07 19:37:02 goose: up to current file version: 216842026/09/07 19:37:02 INFO Received uploads request method=POST path=/api/pending_closures16852026-09-07 19:37:02.712 UTC [35522] ERROR: relation "goose_db_version" does not exist at character 3616862026-09-07 19:37:02.712 UTC [35522] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16872026/09/07 19:37:02 OK 20241026095416_initial_model.sql (188.7ms)16882026/09/07 19:37:02 OK 20251210153512_drop_unused_gin_index.sql (3.13ms)16892026/09/07 19:37:02 OK 20251218171726_add_pins.sql (36.11ms)16902026/09/07 19:37:02 OK 20260628120000_add_object_size_and_stats.sql (46.89ms)16912026/09/07 19:37:02 WARN mTLS auth: subject not in bound subjects subject="CN=reader"16922026/09/07 19:37:02 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1693--- PASS: TestService_NativeMTLS (2.43s)1694=== CONT TestReadProxyRootRedirectsToIndexHTML16952026/09/07 19:37:02 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16962026/09/07 19:37:03 OK 20260905000000_add_claims.sql (98.61ms)16972026/09/07 19:37:03 goose: successfully migrated database to version: 2026090500000016982026/09/07 19:37:03 OK 20241026095416_initial_model.sql (243.21ms)16992026/09/07 19:37:03 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)17002026/09/07 19:37:03 OK 1_commit_pending_closure.sql (3.15ms)17012026/09/07 19:37:03 OK 2_object_stats_trigger.sql (689.79µs)17022026/09/07 19:37:03 goose: up to current file version: 217032026/09/07 19:37:03 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MDZjODFmNzctYjI3My00YTAyLWI5NmYtYTgzOGZkY2MxMDYwLjE3MmYxODM1LTkwNjItNDMwNi04ZTdkLTcwYTVlYjM3ZWExMXgxNzg4ODA5ODIxNjI4MDEyMDAw parts=1017042026/09/07 19:37:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17052026/09/07 19:37:03 OK 20251218171726_add_pins.sql (22.46ms)17062026/09/07 19:37:03 INFO Completed upload id=117072026/09/07 19:37:03 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000017082026/09/07 19:37:03 INFO Received uploads request method=POST path=/api/pending_closures17092026/09/07 19:37:03 INFO Starting cleanup of old closures method=DELETE path=/api/closures17102026/09/07 19:37:03 INFO Aborted multipart uploads count=017112026/09/07 19:37:03 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=017122026/09/07 19:37:03 OK 20260628120000_add_object_size_and_stats.sql (41.15ms)17132026/09/07 19:37:03 INFO Vacuumed table table=pending_closures17142026/09/07 19:37:03 INFO Vacuumed table table=pending_objects17152026/09/07 19:37:03 OK 20260905000000_add_claims.sql (62.32ms)17162026/09/07 19:37:03 goose: successfully migrated database to version: 2026090500000017172026/09/07 19:37:03 INFO Vacuumed table table=multipart_uploads17182026/09/07 19:37:03 OK 1_commit_pending_closure.sql (11.42ms)17192026/09/07 19:37:03 OK 2_object_stats_trigger.sql (1.27ms)17202026/09/07 19:37:03 goose: up to current file version: 217212026/09/07 19:37:03 INFO Vacuumed table table=closures17222026/09/07 19:37:03 INFO Vacuumed table table=objects17232026-09-07 19:37:03.190 UTC [35526] ERROR: relation "goose_db_version" does not exist at character 3617242026-09-07 19:37:03.190 UTC [35526] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17252026/09/07 19:37:03 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001726--- PASS: TestService_createPendingClosureHandler (4.68s)1727=== CONT TestReadProxyConditionalGet17282026/09/07 19:37:03 INFO Received uploads request method=POST path=/api/pending_closures17292026/09/07 19:37:03 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst17302026/09/07 19:37:03 INFO Received uploads request method=POST path=/api/pending_closures1731--- PASS: TestPresignedUploadRegisteredBeforeCommit (2.40s)1732=== CONT TestProxyWriteTimeout1733=== RUN TestProxyWriteTimeout/narinfo1734=== PAUSE TestProxyWriteTimeout/narinfo1735=== RUN TestProxyWriteTimeout/1_GiB_nar1736=== PAUSE TestProxyWriteTimeout/1_GiB_nar1737=== RUN TestProxyWriteTimeout/10_GiB_nar1738=== PAUSE TestProxyWriteTimeout/10_GiB_nar1739=== RUN TestProxyWriteTimeout/unknown_size1740=== PAUSE TestProxyWriteTimeout/unknown_size1741=== CONT TestIsValidUploadKey1742=== RUN TestIsValidUploadKey/narinfo1743=== PAUSE TestIsValidUploadKey/narinfo1744=== RUN TestIsValidUploadKey/nar_zst1745=== PAUSE TestIsValidUploadKey/nar_zst1746=== RUN TestIsValidUploadKey/nar_xz1747=== PAUSE TestIsValidUploadKey/nar_xz1748=== RUN TestIsValidUploadKey/nar_plain1749=== PAUSE TestIsValidUploadKey/nar_plain1750=== RUN TestIsValidUploadKey/listing1751=== PAUSE TestIsValidUploadKey/listing1752=== RUN TestIsValidUploadKey/build_log1753=== PAUSE TestIsValidUploadKey/build_log1754=== RUN TestIsValidUploadKey/build_log_home-manager_file1755=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1756=== RUN TestIsValidUploadKey/build_log_plus_in_name1757=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1758=== RUN TestIsValidUploadKey/build_log_question_mark1759=== PAUSE TestIsValidUploadKey/build_log_question_mark1760=== RUN TestIsValidUploadKey/build_log_equals1761=== PAUSE TestIsValidUploadKey/build_log_equals1762=== RUN TestIsValidUploadKey/realisation1763=== PAUSE TestIsValidUploadKey/realisation1764=== RUN TestIsValidUploadKey/realisation_plus_in_output1765=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1766=== RUN TestIsValidUploadKey/nix-cache-info1767=== PAUSE TestIsValidUploadKey/nix-cache-info1768=== RUN TestIsValidUploadKey/index.html1769=== PAUSE TestIsValidUploadKey/index.html1770=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1771=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1772=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1773=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1774=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1775=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1776=== RUN TestIsValidUploadKey/traversal1777=== PAUSE TestIsValidUploadKey/traversal1778=== RUN TestIsValidUploadKey/traversal_nar1779=== PAUSE TestIsValidUploadKey/traversal_nar1780=== RUN TestIsValidUploadKey/absolute1781=== PAUSE TestIsValidUploadKey/absolute1782=== RUN TestIsValidUploadKey/empty_key1783=== PAUSE TestIsValidUploadKey/empty_key1784=== RUN TestIsValidUploadKey/unknown_type1785=== PAUSE TestIsValidUploadKey/unknown_type1786=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle17872026/09/07 19:37:03 OK 20241026095416_initial_model.sql (146.97ms)17882026/09/07 19:37:03 OK 20251210153512_drop_unused_gin_index.sql (8.47ms)17892026/09/07 19:37:03 OK 20251218171726_add_pins.sql (45.03ms)17902026/09/07 19:37:03 OK 20260628120000_add_object_size_and_stats.sql (34.8ms)17912026/09/07 19:37:03 OK 20260905000000_add_claims.sql (47ms)17922026/09/07 19:37:03 goose: successfully migrated database to version: 2026090500000017932026/09/07 19:37:03 OK 1_commit_pending_closure.sql (3.54ms)17942026/09/07 19:37:03 OK 2_object_stats_trigger.sql (476.17µs)17952026/09/07 19:37:03 goose: up to current file version: 21796--- PASS: TestMetricsInventory (2.55s)1797=== CONT TestReadProxy40417982026-09-07 19:37:03.738 UTC [35533] ERROR: relation "goose_db_version" does not exist at character 3617992026-09-07 19:37:03.738 UTC [35533] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1800--- PASS: TestReadProxyRangeRequest (2.31s)1801=== CONT TestReadProxyInvalidPath18022026-09-07 19:37:03.861 UTC [35534] ERROR: relation "goose_db_version" does not exist at character 3618032026-09-07 19:37:03.861 UTC [35534] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18042026/09/07 19:37:03 OK 20241026095416_initial_model.sql (83.87ms)18052026/09/07 19:37:03 OK 20251210153512_drop_unused_gin_index.sql (856.04µs)18062026/09/07 19:37:03 OK 20251218171726_add_pins.sql (2.69ms)18072026-09-07 19:37:03.877 UTC [35536] ERROR: relation "goose_db_version" does not exist at character 3618082026-09-07 19:37:03.877 UTC [35536] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18092026/09/07 19:37:03 OK 20260628120000_add_object_size_and_stats.sql (36.13ms)18102026/09/07 19:37:03 OK 20260905000000_add_claims.sql (35.99ms)18112026/09/07 19:37:03 goose: successfully migrated database to version: 2026090500000018122026/09/07 19:37:03 OK 1_commit_pending_closure.sql (10.1ms)18132026/09/07 19:37:03 OK 2_object_stats_trigger.sql (1.07ms)18142026/09/07 19:37:03 goose: up to current file version: 218152026/09/07 19:37:03 OK 20241026095416_initial_model.sql (99.73ms)18162026/09/07 19:37:03 OK 20251210153512_drop_unused_gin_index.sql (8.14ms)18172026/09/07 19:37:04 OK 20251218171726_add_pins.sql (25.55ms)18182026/09/07 19:37:04 OK 20241026095416_initial_model.sql (80.6ms)18192026/09/07 19:37:04 OK 20251210153512_drop_unused_gin_index.sql (14.45ms)18202026/09/07 19:37:04 OK 20260628120000_add_object_size_and_stats.sql (33.26ms)18212026/09/07 19:37:04 OK 20251218171726_add_pins.sql (15.04ms)18222026/09/07 19:37:04 OK 20260905000000_add_claims.sql (29.19ms)18232026/09/07 19:37:04 goose: successfully migrated database to version: 2026090500000018242026/09/07 19:37:04 OK 1_commit_pending_closure.sql (2.84ms)18252026/09/07 19:37:04 OK 2_object_stats_trigger.sql (570.5µs)18262026/09/07 19:37:04 goose: up to current file version: 218272026/09/07 19:37:04 OK 20260628120000_add_object_size_and_stats.sql (35.04ms)18282026/09/07 19:37:04 OK 20260905000000_add_claims.sql (54.64ms)18292026/09/07 19:37:04 goose: successfully migrated database to version: 2026090500000018302026/09/07 19:37:04 OK 1_commit_pending_closure.sql (8.67ms)18312026/09/07 19:37:04 OK 2_object_stats_trigger.sql (733.33µs)18322026/09/07 19:37:04 goose: up to current file version: 218332026/09/07 19:37:04 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1834--- PASS: TestReadProxyHead (2.31s)1835=== CONT TestReadProxyNarStreaming18362026/09/07 19:37:04 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MDZjODFmNzctYjI3My00YTAyLWI5NmYtYTgzOGZkY2MxMDYwLmUwOTE3YWZmLThlY2ItNGEwMy1hMmQ2LWMyZDNiMmQ1ZGVmNngxNzg4ODA5ODIyNjQ3OTQzMDAw parts=121837--- PASS: TestRedundantMultipartUpload (4.92s)1838=== CONT TestReadProxyNarinfoAlreadyDecompressed1839--- PASS: TestReadRedirectNar (2.28s)1840=== CONT TestCompletedNarNotReofferedAcrossClosures18412026-09-07 19:37:04.429 UTC [35543] ERROR: relation "goose_db_version" does not exist at character 3618422026-09-07 19:37:04.429 UTC [35543] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18432026/09/07 19:37:04 OK 20241026095416_initial_model.sql (129ms)1844--- PASS: TestReadProxyDisabled (2.25s)1845=== CONT TestResolveDBConnectionString/flag_wins1846=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1847=== CONT TestResolveDBConnectionString/nothing_configured1848=== CONT TestResolveDBConnectionString/missing_file_is_an_error1849=== CONT TestResolveDBConnectionString/file_when_flag_empty1850=== CONT TestClientErrorHandling/InvalidStorePath1851--- PASS: TestResolveDBConnectionString (0.01s)1852 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1853 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1854 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1855 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1856 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)18572026/09/07 19:37:04 OK 20251210153512_drop_unused_gin_index.sql (10.46ms)18582026/09/07 19:37:04 OK 20251218171726_add_pins.sql (7.48ms)18592026-09-07 19:37:04.624 UTC [35546] ERROR: relation "goose_db_version" does not exist at character 3618602026-09-07 19:37:04.624 UTC [35546] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18612026/09/07 19:37:04 OK 20260628120000_add_object_size_and_stats.sql (8.21ms)18622026/09/07 19:37:04 OK 20260905000000_add_claims.sql (4.86ms)18632026/09/07 19:37:04 goose: successfully migrated database to version: 2026090500000018642026/09/07 19:37:04 OK 1_commit_pending_closure.sql (2.44ms)18652026/09/07 19:37:04 OK 2_object_stats_trigger.sql (565.88µs)18662026/09/07 19:37:04 goose: up to current file version: 218672026-09-07 19:37:04.640 UTC [35547] ERROR: relation "goose_db_version" does not exist at character 3618682026-09-07 19:37:04.640 UTC [35547] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18692026/09/07 19:37:04 OK 20241026095416_initial_model.sql (74.52ms)18702026/09/07 19:37:04 OK 20251210153512_drop_unused_gin_index.sql (11.1ms)18712026/09/07 19:37:04 OK 20251218171726_add_pins.sql (13.27ms)18722026/09/07 19:37:04 OK 20260628120000_add_object_size_and_stats.sql (29.75ms)18732026-09-07 19:37:04.789 UTC [35549] ERROR: relation "goose_db_version" does not exist at character 3618742026-09-07 19:37:04.789 UTC [35549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18752026/09/07 19:37:04 OK 20241026095416_initial_model.sql (84.86ms)18762026/09/07 19:37:04 OK 20260905000000_add_claims.sql (36.87ms)18772026/09/07 19:37:04 goose: successfully migrated database to version: 2026090500000018782026/09/07 19:37:04 OK 20251210153512_drop_unused_gin_index.sql (8.36ms)18792026/09/07 19:37:04 OK 1_commit_pending_closure.sql (3.97ms)18802026/09/07 19:37:04 OK 2_object_stats_trigger.sql (610.17µs)18812026/09/07 19:37:04 goose: up to current file version: 218822026/09/07 19:37:04 OK 20251218171726_add_pins.sql (12.1ms)18832026/09/07 19:37:04 OK 20260628120000_add_object_size_and_stats.sql (31.73ms)18842026/09/07 19:37:04 OK 20260905000000_add_claims.sql (44.06ms)18852026/09/07 19:37:04 goose: successfully migrated database to version: 2026090500000018862026/09/07 19:37:04 OK 1_commit_pending_closure.sql (7.03ms)18872026/09/07 19:37:04 OK 2_object_stats_trigger.sql (3.32ms)18882026/09/07 19:37:04 goose: up to current file version: 21889--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.95s)1890=== CONT TestClientErrorHandling/ServerNotAvailable18912026/09/07 19:37:04 OK 20241026095416_initial_model.sql (101.03ms)18922026/09/07 19:37:04 OK 20251210153512_drop_unused_gin_index.sql (8.45ms)18932026/09/07 19:37:04 OK 20251218171726_add_pins.sql (9.9ms)18942026/09/07 19:37:04 OK 20260628120000_add_object_size_and_stats.sql (20.63ms)18952026-09-07 19:37:04.965 UTC [35551] ERROR: relation "goose_db_version" does not exist at character 3618962026-09-07 19:37:04.965 UTC [35551] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18972026/09/07 19:37:04 OK 20260905000000_add_claims.sql (16.84ms)18982026/09/07 19:37:04 goose: successfully migrated database to version: 2026090500000018992026/09/07 19:37:04 OK 1_commit_pending_closure.sql (1.55ms)19002026/09/07 19:37:04 OK 2_object_stats_trigger.sql (1.6ms)19012026/09/07 19:37:04 goose: up to current file version: 219022026/09/07 19:37:05 OK 20241026095416_initial_model.sql (72.66ms)19032026/09/07 19:37:05 OK 20251210153512_drop_unused_gin_index.sql (11.11ms)19042026/09/07 19:37:05 OK 20251218171726_add_pins.sql (7.54ms)1905--- PASS: TestReadProxyConditionalGet (1.88s)1906=== CONT TestClientErrorHandling/InvalidAuthToken19072026/09/07 19:37:05 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-config19082026/09/07 19:37:05 OK 20260628120000_add_object_size_and_stats.sql (22.56ms)1909=== NAME TestOrphanedObjectsGCStressTest1910 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains19112026/09/07 19:37:05 OK 20260905000000_add_claims.sql (23.48ms)19122026/09/07 19:37:05 goose: successfully migrated database to version: 2026090500000019132026/09/07 19:37:05 OK 1_commit_pending_closure.sql (1.47ms)19142026/09/07 19:37:05 OK 2_object_stats_trigger.sql (241.17µs)19152026/09/07 19:37:05 goose: up to current file version: 21916 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion19172026-09-07 19:37:05.177 UTC [35562] ERROR: relation "goose_db_version" does not exist at character 3619182026-09-07 19:37:05.177 UTC [35562] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19192026/09/07 19:37:05 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=201.47121ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19202026-09-07 19:37:05.209 UTC [35563] ERROR: relation "goose_db_version" does not exist at character 3619212026-09-07 19:37:05.209 UTC [35563] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19222026/09/07 19:37:05 OK 20241026095416_initial_model.sql (66.77ms)19232026/09/07 19:37:05 OK 20251210153512_drop_unused_gin_index.sql (13.14ms)19242026/09/07 19:37:05 INFO Received uploads request method=POST path=/api/pending_closures19252026/09/07 19:37:05 OK 20251218171726_add_pins.sql (1.53ms)19262026/09/07 19:37:05 OK 20260628120000_add_object_size_and_stats.sql (20.02ms)19272026/09/07 19:37:05 OK 20241026095416_initial_model.sql (77.36ms)19282026/09/07 19:37:05 OK 20251210153512_drop_unused_gin_index.sql (6.55ms)19292026/09/07 19:37:05 OK 20251218171726_add_pins.sql (21.29ms)19302026/09/07 19:37:05 OK 20260905000000_add_claims.sql (35.93ms)19312026/09/07 19:37:05 goose: successfully migrated database to version: 2026090500000019322026/09/07 19:37:05 OK 1_commit_pending_closure.sql (1.96ms)19332026/09/07 19:37:05 OK 2_object_stats_trigger.sql (344.29µs)19342026/09/07 19:37:05 goose: up to current file version: 219352026/09/07 19:37:05 OK 20260628120000_add_object_size_and_stats.sql (21.07ms)19362026/09/07 19:37:05 OK 20260905000000_add_claims.sql (36.35ms)19372026/09/07 19:37:05 goose: successfully migrated database to version: 2026090500000019382026/09/07 19:37:05 OK 1_commit_pending_closure.sql (6.4ms)19392026/09/07 19:37:05 OK 2_object_stats_trigger.sql (365.42µs)19402026/09/07 19:37:05 goose: up to current file version: 219412026/09/07 19:37:05 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=388.618107ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1942--- PASS: TestReadProxy404 (1.90s)1943=== CONT TestCacheConfigHandler/full_config,_no_issuer1944=== CONT TestCacheConfigHandler/no_signing_keys1945=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1946=== CONT TestCacheConfigHandler/no_cache_url_configured1947--- PASS: TestCacheConfigHandler (0.00s)1948 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1949 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1950 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1951 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1952=== CONT TestIsValidCachePath/narinfo1953=== CONT TestIsValidCachePath/index.html1954=== CONT TestIsValidCachePath/short_hash1955=== CONT TestIsValidCachePath/wrong_extension1956=== CONT TestIsValidCachePath/leading_slash1957=== CONT TestIsValidCachePath/empty1958=== CONT TestIsValidCachePath/random_path1959=== CONT TestIsValidCachePath/invalid_char_u1960=== CONT TestIsValidCachePath/invalid_char_e1961=== CONT TestIsValidCachePath/traversal_in_middle1962=== CONT TestIsValidCachePath/traversal_parent1963=== CONT TestIsValidCachePath/nar_uncompressed1964=== CONT TestIsValidCachePath/nix-cache-info1965=== CONT TestIsValidCachePath/realisation1966=== CONT TestIsValidCachePath/log1967=== CONT TestIsValidCachePath/ls1968=== CONT TestIsValidCachePath/nar_xz1969=== CONT TestIsValidCachePath/nar_bz21970=== CONT TestIsValidCachePath/nar_zst1971=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1972--- PASS: TestIsValidCachePath (0.00s)1973 --- PASS: TestIsValidCachePath/narinfo (0.00s)1974 --- PASS: TestIsValidCachePath/index.html (0.00s)1975 --- PASS: TestIsValidCachePath/short_hash (0.00s)1976 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1977 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1978 --- PASS: TestIsValidCachePath/empty (0.00s)1979 --- PASS: TestIsValidCachePath/random_path (0.00s)1980 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1981 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1982 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1983 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1984 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1985 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1986 --- PASS: TestIsValidCachePath/realisation (0.00s)1987 --- PASS: TestIsValidCachePath/log (0.00s)1988 --- PASS: TestIsValidCachePath/ls (0.00s)1989 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1990 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1991 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1992 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1993=== CONT TestParseSingleRange/none1994=== CONT TestParseSingleRange/end_clamped_to_size1995=== CONT TestParseSingleRange/open-ended1996=== CONT TestParseSingleRange/closed1997=== CONT TestParseSingleRange/malformed_end_before_start1998=== CONT TestParseSingleRange/malformed_both_empty1999=== CONT TestParseSingleRange/malformed_no_dash2000=== CONT TestParseSingleRange/multi-range_ignored2001=== CONT TestParseSingleRange/unknown_unit2002=== CONT TestParseSingleRange/suffix2003=== CONT TestParseSingleRange/start_past_EOF2004=== CONT TestParseSingleRange/start_far_past_EOF2005=== CONT TestParseSingleRange/single_byte2006=== CONT TestParseSingleRange/suffix_exceeds_size2007--- PASS: TestParseSingleRange (0.00s)2008 --- PASS: TestParseSingleRange/none (0.00s)2009 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2010 --- PASS: TestParseSingleRange/open-ended (0.00s)2011 --- PASS: TestParseSingleRange/closed (0.00s)2012 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2013 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2014 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2015 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2016 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2017 --- PASS: TestParseSingleRange/suffix (0.00s)2018 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2019 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2020 --- PASS: TestParseSingleRange/single_byte (0.00s)2021 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2022=== CONT TestService_RequireScope_OIDC/builder_may_write20232026/09/07 19:37:05 INFO OIDC auth successful provider=test scopes=[write]2024=== CONT TestService_RequireScope_OIDC/static_token_may_admin2025=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2026=== CONT TestService_RequireScope_OIDC/writer_implies_read20272026/09/07 19:37:05 INFO OIDC auth successful provider=test scopes=[write]2028=== CONT TestService_RequireScope_OIDC/reader_may_read20292026/09/07 19:37:05 INFO OIDC auth successful provider=test scopes=[read]2030=== CONT TestService_RequireScope_OIDC/static_token_may_write2031=== CONT TestService_RequireScope_OIDC/ops_may_not_write20322026/09/07 19:37:05 INFO OIDC auth successful provider=test scopes=[admin]2033=== CONT TestService_RequireScope_OIDC/reader_may_not_write20342026/09/07 19:37:05 INFO OIDC auth successful provider=test scopes=[read]2035=== CONT TestService_RequireScope_OIDC/ops_may_admin20362026/09/07 19:37:05 INFO OIDC auth successful provider=test scopes=[admin]2037=== CONT TestService_RequireScope_OIDC/builder_may_not_admin20382026/09/07 19:37:05 INFO OIDC auth successful provider=test scopes=[write]2039=== CONT TestServerTLSConfig/no_client_CA2040=== CONT TestServerTLSConfig/not_a_PEM_file2041--- PASS: TestService_RequireScope_OIDC (1.70s)2042 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2043 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2044 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2045 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2046 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2047 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2048 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2049 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2050 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2051 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2052=== CONT TestServerTLSConfig/missing_CA_file2053--- PASS: TestServerTLSConfig (0.00s)2054 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2055 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)2056 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2057=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token20582026/09/07 19:37:05 INFO OIDC auth successful provider=test scopes=[write]2059=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20602026/09/07 19:37:05 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]2061=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2062=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20632026/09/07 19:37:05 WARN Authentication failed token_preview=eyJhbGciOi...5WRpPTOoUQ token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2064=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20652026/09/07 19:37:05 INFO Received uploads request method=POST path=/2066=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20672026/09/07 19:37:05 INFO Received complete multipart upload request method=POST path=/2068=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20692026/09/07 19:37:05 INFO Received request for more parts method=POST path=/2070=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20712026/09/07 19:37:05 INFO Received uploads request method=POST path=/2072--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2073 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2074 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2075 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2076 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2077=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts20782026/09/07 19:37:05 INFO Received request for more parts method=POST path=/2079--- PASS: TestService_AuthMiddleware_OIDC (1.95s)2080 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2081 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2082 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2083 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)20842026/09/07 19:37:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20852026-09-07 19:37:05.558 UTC [35564] ERROR: relation "goose_db_version" does not exist at character 3620862026-09-07 19:37:05.558 UTC [35564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2087=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart20882026/09/07 19:37:05 INFO Received complete multipart upload request method=POST path=/2089=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure20902026/09/07 19:37:05 INFO Received uploads request method=POST path=/20912026/09/07 19:37:05 OK 20241026095416_initial_model.sql (33.99ms)20922026/09/07 19:37:05 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)20932026/09/07 19:37:05 OK 20251218171726_add_pins.sql (2.97ms)20942026-09-07 19:37:05.633 UTC [35565] ERROR: relation "goose_db_version" does not exist at character 3620952026-09-07 19:37:05.633 UTC [35565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20962026/09/07 19:37:05 OK 20260628120000_add_object_size_and_stats.sql (18.68ms)20972026/09/07 19:37:05 OK 20260905000000_add_claims.sql (10.16ms)20982026/09/07 19:37:05 goose: successfully migrated database to version: 2026090500000020992026/09/07 19:37:05 OK 1_commit_pending_closure.sql (5.53ms)21002026/09/07 19:37:05 OK 2_object_stats_trigger.sql (216.21µs)21012026/09/07 19:37:05 goose: up to current file version: 22102--- PASS: TestReadProxyInvalidPath (1.82s)2103=== CONT TestProxyWriteTimeout/narinfo2104=== CONT TestProxyWriteTimeout/10_GiB_nar2105=== CONT TestProxyWriteTimeout/unknown_size2106=== CONT TestProxyWriteTimeout/1_GiB_nar2107--- PASS: TestProxyWriteTimeout (0.00s)2108 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2109 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2110 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2111 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2112=== CONT TestIsValidUploadKey/narinfo2113=== CONT TestIsValidUploadKey/realisation_plus_in_output2114=== CONT TestIsValidUploadKey/unknown_type2115=== CONT TestIsValidUploadKey/empty_key2116=== CONT TestIsValidUploadKey/absolute2117=== CONT TestIsValidUploadKey/traversal_nar2118=== CONT TestIsValidUploadKey/traversal2119=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2120=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2121=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2122=== CONT TestIsValidUploadKey/index.html2123=== CONT TestIsValidUploadKey/nix-cache-info2124=== CONT TestIsValidUploadKey/build_log_home-manager_file2125=== CONT TestIsValidUploadKey/realisation2126=== CONT TestIsValidUploadKey/build_log_equals2127=== CONT TestIsValidUploadKey/build_log_question_mark2128=== CONT TestIsValidUploadKey/build_log_plus_in_name2129=== CONT TestIsValidUploadKey/nar_xz2130=== CONT TestIsValidUploadKey/nar_plain2131=== CONT TestIsValidUploadKey/nar_zst2132=== CONT TestIsValidUploadKey/build_log2133=== CONT TestIsValidUploadKey/listing2134--- PASS: TestIsValidUploadKey (0.00s)2135 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2136 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2137 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2138 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2139 --- PASS: TestIsValidUploadKey/absolute (0.00s)2140 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2141 --- PASS: TestIsValidUploadKey/traversal (0.00s)2142 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2143 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2144 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2145 --- PASS: TestIsValidUploadKey/index.html (0.00s)2146 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2147 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2148 --- PASS: TestIsValidUploadKey/realisation (0.00s)2149 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2150 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2151 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2152 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2153 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2154 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2155 --- PASS: TestIsValidUploadKey/build_log (0.00s)2156 --- PASS: TestIsValidUploadKey/listing (0.00s)21572026/09/07 19:37:05 OK 20241026095416_initial_model.sql (46.94ms)21582026/09/07 19:37:05 OK 20251210153512_drop_unused_gin_index.sql (7.57ms)21592026/09/07 19:37:05 OK 20251218171726_add_pins.sql (8.24ms)21602026/09/07 19:37:05 OK 20260628120000_add_object_size_and_stats.sql (1.15ms)21612026/09/07 19:37:05 OK 20260905000000_add_claims.sql (11.01ms)21622026/09/07 19:37:05 goose: successfully migrated database to version: 2026090500000021632026/09/07 19:37:05 OK 1_commit_pending_closure.sql (5.94ms)21642026/09/07 19:37:05 OK 2_object_stats_trigger.sql (207.58µs)21652026/09/07 19:37:05 goose: up to current file version: 221662026-09-07 19:37:05.788 UTC [35566] ERROR: relation "goose_db_version" does not exist at character 3621672026-09-07 19:37:05.788 UTC [35566] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21682026/09/07 19:37:05 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=752.470086ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2169--- PASS: TestReadProxyNarStreaming (1.62s)21702026/09/07 19:37:05 OK 20241026095416_initial_model.sql (29.14ms)21712026/09/07 19:37:05 OK 20251210153512_drop_unused_gin_index.sql (5.65ms)21722026/09/07 19:37:05 OK 20251218171726_add_pins.sql (5.25ms)21732026/09/07 19:37:05 OK 20260628120000_add_object_size_and_stats.sql (4.51ms)21742026/09/07 19:37:05 OK 20260905000000_add_claims.sql (6.99ms)21752026/09/07 19:37:05 goose: successfully migrated database to version: 202609050000002176--- PASS: TestUploadHandlersRejectOversizedBody (0.04s)2177 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)2178 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2179 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.27s)21802026/09/07 19:37:05 OK 1_commit_pending_closure.sql (5.21ms)21812026/09/07 19:37:05 OK 2_object_stats_trigger.sql (257.13µs)21822026/09/07 19:37:05 goose: up to current file version: 22183--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.70s)21842026/09/07 19:37:06 INFO Received uploads request method=POST path=/api/pending_closures2185=== NAME TestOrphanedObjectsGCStressTest2186 orphaned_objects_gc_test.go:509: Stress test completed successfully:2187 orphaned_objects_gc_test.go:510: - Active objects preserved: 202188 orphaned_objects_gc_test.go:511: - Objects deleted: 2102189 orphaned_objects_gc_test.go:512: - Total GC'd: 2102190--- PASS: TestOrphanedObjectsGCStressTest (8.54s)21912026/09/07 19:37:06 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.540875336s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21922026/09/07 19:37:06 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"21932026/09/07 19:37:06 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21942026/09/07 19:37:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21952026/09/07 19:37:06 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MDZjODFmNzctYjI3My00YTAyLWI5NmYtYTgzOGZkY2MxMDYwLjQ1NjgzYjNjLWQ1MjAtNGI4NS1hOTYwLWFlNjZkOGQ0MTAyY3gxNzg4ODA5ODI2MDg4MDYwMDAw parts=1221962026/09/07 19:37:06 INFO Received uploads request method=POST path=/api/pending_closures2197--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.47s)21982026/09/07 19:37:08 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"21992026/09/07 19:37:08 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_closures22002026/09/07 19:37:08 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=195.862576ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22012026/09/07 19:37:08 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=376.93427ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22022026/09/07 19:37:08 WARN Rate limiter enabled after throttle name=s3-test rate=522032026/09/07 19:37:08 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2204=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2205 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102206 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002207--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.34s)22082026/09/07 19:37:08 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=753.815255ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22092026/09/07 19:37:09 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.702125356s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2210--- PASS: TestClientErrorHandling (0.00s)2211 --- PASS: TestClientErrorHandling/InvalidStorePath (1.70s)2212 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.60s)2213 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.42s)2214PASS2215{"timestamp":"2026-09-07T19:37:11.320803Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:57252","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(2)"}22162026-09-07 19:37:11.423 UTC [35185] LOG: received smart shutdown request22172026-09-07 19:37:11.424 UTC [35185] LOG: background worker "logical replication launcher" (PID 35196) exited with exit code 122182026-09-07 19:37:11.468 UTC [35190] LOG: shutting down22192026-09-07 19:37:11.468 UTC [35190] LOG: checkpoint starting: shutdown immediate22202026-09-07 19:37:12.567 UTC [35190] LOG: checkpoint complete: wrote 13303 buffers (81.2%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 18 recycled; write=0.741 s, sync=0.355 s, total=1.099 s; sync files=21000, longest=0.001 s, average=0.001 s; distance=287764 kB, estimate=287764 kB; lsn=0/13091F80, redo lsn=0/13091F8022212026-09-07 19:37:12.572 UTC [35185] LOG: database system is shut down2222Running OIDC tests...2223=== RUN TestGlobMatch2224=== PAUSE TestGlobMatch2225=== RUN TestAudienceForIssuer2226=== PAUSE TestAudienceForIssuer2227=== RUN TestValidateToken_ValidToken2228=== PAUSE TestValidateToken_ValidToken2229=== RUN TestValidateToken_WrongAudience2230=== PAUSE TestValidateToken_WrongAudience2231=== RUN TestValidateToken_Expired2232=== PAUSE TestValidateToken_Expired2233=== RUN TestValidateToken_BoundClaimsMismatch2234=== PAUSE TestValidateToken_BoundClaimsMismatch2235=== RUN TestValidateToken_BoundSubjectMismatch2236=== PAUSE TestValidateToken_BoundSubjectMismatch2237=== RUN TestValidateToken_MultipleProviders2238=== PAUSE TestValidateToken_MultipleProviders2239=== RUN TestValidateToken_NoMatchingProvider2240=== PAUSE TestValidateToken_NoMatchingProvider2241=== RUN TestValidateToken_KubernetesServiceAccount2242=== PAUSE TestValidateToken_KubernetesServiceAccount2243=== RUN TestNewValidator_KubernetesRequiresCA2244=== PAUSE TestNewValidator_KubernetesRequiresCA2245=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2246=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2247=== RUN TestScopes_LegacyProviderDefaultsToWrite2248=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2249=== RUN TestScopes_Rules2250=== PAUSE TestScopes_Rules2251=== RUN TestScopes_ConfigValidation2252=== PAUSE TestScopes_ConfigValidation2253=== CONT TestGlobMatch2254=== CONT TestScopes_LegacyProviderDefaultsToWrite2255=== RUN TestGlobMatch/foo_foo2256=== PAUSE TestGlobMatch/foo_foo2257=== RUN TestGlobMatch/foo_bar2258=== PAUSE TestGlobMatch/foo_bar2259=== RUN TestGlobMatch/*_2260=== CONT TestValidateToken_NoMatchingProvider2261=== PAUSE TestGlobMatch/*_2262=== RUN TestGlobMatch/*_anything2263=== PAUSE TestGlobMatch/*_anything2264=== RUN TestGlobMatch/foo*_foo2265=== PAUSE TestGlobMatch/foo*_foo2266=== RUN TestGlobMatch/foo*_foobar2267=== PAUSE TestGlobMatch/foo*_foobar2268=== RUN TestGlobMatch/foo*_bar2269=== PAUSE TestGlobMatch/foo*_bar2270=== RUN TestGlobMatch/*bar_bar2271=== PAUSE TestGlobMatch/*bar_bar2272=== RUN TestGlobMatch/*bar_foobar2273=== PAUSE TestGlobMatch/*bar_foobar2274=== RUN TestGlobMatch/*bar_foo2275=== PAUSE TestGlobMatch/*bar_foo2276=== RUN TestGlobMatch/foo*bar_foobar2277=== PAUSE TestGlobMatch/foo*bar_foobar2278=== CONT TestValidateToken_MultipleProviders2279=== RUN TestGlobMatch/foo*bar_foo123bar2280=== PAUSE TestGlobMatch/foo*bar_foo123bar2281=== RUN TestGlobMatch/foo*bar_foobarbaz2282=== PAUSE TestGlobMatch/foo*bar_foobarbaz2283=== RUN TestGlobMatch/*/*_foo/bar2284=== PAUSE TestGlobMatch/*/*_foo/bar2285=== RUN TestGlobMatch/*/*_foo2286=== PAUSE TestGlobMatch/*/*_foo2287=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2288=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2289=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02290=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02291=== RUN TestGlobMatch/refs/*/main_refs/heads/main2292=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2293=== RUN TestGlobMatch/fo?_foo2294=== PAUSE TestGlobMatch/fo?_foo2295=== RUN TestGlobMatch/fo?_fo2296=== PAUSE TestGlobMatch/fo?_fo2297=== RUN TestGlobMatch/fo?_fooo2298=== PAUSE TestGlobMatch/fo?_fooo2299=== CONT TestValidateToken_BoundSubjectMismatch2300=== CONT TestValidateToken_BoundClaimsMismatch2301=== CONT TestValidateToken_Expired2302=== CONT TestValidateToken_WrongAudience2303=== CONT TestValidateToken_ValidToken2304=== CONT TestAudienceForIssuer2305--- PASS: TestAudienceForIssuer (0.00s)2306=== CONT TestScopes_Rules2307=== RUN TestGlobMatch/?oo_foo2308=== PAUSE TestGlobMatch/?oo_foo2309=== RUN TestGlobMatch/?oo_boo2310=== PAUSE TestGlobMatch/?oo_boo2311=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2312=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2313=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2314=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2315=== CONT TestNewValidator_KubernetesRequiresCA23162026/09/07 19:37:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57460/oidc23172026/09/07 19:37:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57463/oidc23182026/09/07 19:37:13 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57465/oidc23192026/09/07 19:37:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57458/oidc23202026/09/07 19:37:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57464/oidc23212026/09/07 19:37:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57462/oidc23222026/09/07 19:37:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57461/oidc23232026/09/07 19:37:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:57459/oidc23242026/09/07 19:37:13 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:57457/oidc23252026/09/07 19:37:13 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:57467/oidc2326--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2327=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2328--- PASS: TestValidateToken_WrongAudience (0.01s)2329=== CONT TestValidateToken_KubernetesServiceAccount2330--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2331=== CONT TestScopes_ConfigValidation2332--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2333=== CONT TestGlobMatch/foo_foo2334=== CONT TestGlobMatch/*/*_foo/bar2335=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2336=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2337=== CONT TestGlobMatch/?oo_boo2338=== CONT TestGlobMatch/?oo_foo2339=== CONT TestGlobMatch/fo?_fooo2340=== CONT TestGlobMatch/fo?_fo2341=== CONT TestGlobMatch/fo?_foo2342=== CONT TestGlobMatch/refs/*/main_refs/heads/main2343=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02344=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2345=== CONT TestGlobMatch/*/*_foo2346=== CONT TestGlobMatch/*bar_bar2347=== CONT TestGlobMatch/foo*bar_foobarbaz2348=== CONT TestGlobMatch/foo*bar_foo123bar2349=== CONT TestGlobMatch/foo*bar_foobar2350=== CONT TestGlobMatch/*bar_foo2351=== CONT TestGlobMatch/*bar_foobar2352=== CONT TestGlobMatch/foo*_foo2353=== CONT TestGlobMatch/foo*_bar2354=== CONT TestGlobMatch/foo*_foobar2355=== CONT TestGlobMatch/*_2356=== CONT TestGlobMatch/foo_bar2357=== CONT TestGlobMatch/*_anything2358--- PASS: TestGlobMatch (0.00s)2359 --- PASS: TestGlobMatch/foo_foo (0.00s)2360 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2361 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2362 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2363 --- PASS: TestGlobMatch/?oo_boo (0.00s)2364 --- PASS: TestGlobMatch/?oo_foo (0.00s)2365 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2366 --- PASS: TestGlobMatch/fo?_fo (0.00s)2367 --- PASS: TestGlobMatch/fo?_foo (0.00s)2368 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2369 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2370 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2371 --- PASS: TestGlobMatch/*/*_foo (0.00s)2372 --- PASS: TestGlobMatch/*bar_bar (0.00s)2373 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2374 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2375 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2376 --- PASS: TestGlobMatch/*bar_foo (0.00s)2377 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2378 --- PASS: TestGlobMatch/foo*_foo (0.00s)2379 --- PASS: TestGlobMatch/foo*_bar (0.00s)2380 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2381 --- PASS: TestGlobMatch/*_ (0.00s)2382 --- PASS: TestGlobMatch/foo_bar (0.00s)2383 --- PASS: TestGlobMatch/*_anything (0.00s)2384--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2385--- PASS: TestValidateToken_Expired (0.01s)2386--- PASS: TestScopes_ConfigValidation (0.00s)2387--- PASS: TestValidateToken_ValidToken (0.01s)2388--- PASS: TestValidateToken_MultipleProviders (0.01s)23892026/09/07 19:37:13 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323902026/09/07 19:37:13 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5748023912026/09/07 19:37:13 http: TLS handshake error from 127.0.0.1:57478: remote error: tls: bad certificate2392--- PASS: TestNewValidator_KubernetesRequiresCA (0.01s)2393--- PASS: TestScopes_Rules (0.01s)2394--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.01s)2395--- PASS: TestValidateToken_KubernetesServiceAccount (0.01s)2396PASS2397Running hook tests...2398=== RUN TestSendPathsEmpty2399=== PAUSE TestSendPathsEmpty2400=== RUN TestQueueEnqueueAndFetch2401=== PAUSE TestQueueEnqueueAndFetch2402=== RUN TestQueueDeduplication2403=== PAUSE TestQueueDeduplication2404=== RUN TestQueueRemove2405=== PAUSE TestQueueRemove2406=== RUN TestQueueFetchBatchLimit2407=== PAUSE TestQueueFetchBatchLimit2408=== RUN TestQueueRetryMovesToBack2409=== PAUSE TestQueueRetryMovesToBack2410=== RUN TestQueueFetchRemoveLifecycle2411=== PAUSE TestQueueFetchRemoveLifecycle2412=== RUN TestQueueConcurrentWriters2413=== PAUSE TestQueueConcurrentWriters2414=== RUN TestQueueRemoveLargeClosure2415=== PAUSE TestQueueRemoveLargeClosure2416=== RUN TestServerClientIntegration2417=== PAUSE TestServerClientIntegration2418=== RUN TestServerQueueError2419=== PAUSE TestServerQueueError2420=== RUN TestGetListenerSocketActivation2421 server_test.go:214: === RUN TestGetListenerSocketActivation2422 --- PASS: TestGetListenerSocketActivation (0.00s)2423 PASS2424 2425--- PASS: TestGetListenerSocketActivation (0.01s)2426=== RUN TestServerWait2427=== PAUSE TestServerWait2428=== RUN TestDrainIsolatesPoisonPath2429=== PAUSE TestDrainIsolatesPoisonPath2430=== RUN TestRunNotBlockedByPoisonHead2431=== PAUSE TestRunNotBlockedByPoisonHead2432=== RUN TestDrainGivesUpWhenServerDown2433=== PAUSE TestDrainGivesUpWhenServerDown2434=== RUN TestFailedPathPrunedByLaterClosure2435=== PAUSE TestFailedPathPrunedByLaterClosure2436=== RUN TestWorkerUploadsAndRemoves2437=== PAUSE TestWorkerUploadsAndRemoves2438=== RUN TestWorkerSkipsGCdPaths2439=== PAUSE TestWorkerSkipsGCdPaths2440=== RUN TestWorkerPrunesClosureDeps2441=== PAUSE TestWorkerPrunesClosureDeps2442=== RUN TestDrainTimeout2443=== PAUSE TestDrainTimeout2444=== CONT TestSendPathsEmpty2445=== CONT TestServerQueueError2446--- PASS: TestSendPathsEmpty (0.00s)2447=== CONT TestServerClientIntegration2448=== CONT TestQueueRemoveLargeClosure2449=== CONT TestQueueConcurrentWriters2450=== CONT TestQueueFetchRemoveLifecycle2451=== CONT TestQueueRetryMovesToBack2452=== CONT TestQueueFetchBatchLimit2453=== CONT TestQueueRemove2454=== CONT TestQueueDeduplication2455=== CONT TestFailedPathPrunedByLaterClosure24562026/09/07 19:37:13 ERROR Hook request failed error="permission denied" wait=false count=12457--- PASS: TestServerClientIntegration (0.00s)2458=== CONT TestQueueEnqueueAndFetch2459--- PASS: TestServerQueueError (0.00s)2460=== CONT TestRunNotBlockedByPoisonHead2461--- PASS: TestQueueFetchBatchLimit (0.01s)2462=== CONT TestDrainGivesUpWhenServerDown24632026/09/07 19:37:13 INFO Upload queue status pending=324642026/09/07 19:37:13 INFO Uploading batch count=124652026/09/07 19:37:13 ERROR Upload failed error="upload failed" count=12466--- PASS: TestQueueDeduplication (0.01s)2467=== CONT TestWorkerPrunesClosureDeps24682026/09/07 19:37:13 INFO Uploading batch count=124692026/09/07 19:37:13 ERROR Upload failed error="upload failed" count=12470--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2471=== CONT TestDrainTimeout2472--- PASS: TestQueueRetryMovesToBack (0.01s)2473=== CONT TestWorkerSkipsGCdPaths24742026/09/07 19:37:13 INFO Uploading batch count=124752026/09/07 19:37:13 INFO Uploading batch count=12476--- PASS: TestQueueEnqueueAndFetch (0.01s)2477=== CONT TestWorkerUploadsAndRemoves2478--- PASS: TestQueueRemove (0.01s)2479=== CONT TestDrainIsolatesPoisonPath24802026/09/07 19:37:13 INFO Upload queue status pending=224812026/09/07 19:37:13 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-35150-957684269/TestWorkerSkipsGCdPaths3933345506/002/nonexistent24822026/09/07 19:37:13 INFO Upload queue status pending=224832026/09/07 19:37:13 INFO Uploading batch count=124842026/09/07 19:37:13 INFO Uploading batch count=12485--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2486=== CONT TestServerWait24872026/09/07 19:37:13 INFO Uploading batch count=224882026/09/07 19:37:13 ERROR Upload failed error="upload failed" count=224892026/09/07 19:37:13 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-35150-957684269/TestDrainGivesUpWhenServerDown2169992417/002/a24902026/09/07 19:37:13 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-35150-957684269/TestDrainGivesUpWhenServerDown2169992417/002/b24912026/09/07 19:37:13 INFO Upload queue status pending=224922026/09/07 19:37:13 INFO Uploading batch count=224932026/09/07 19:37:13 INFO Uploading batch count=224942026/09/07 19:37:13 INFO Uploading batch count=224952026/09/07 19:37:13 ERROR Upload failed error="upload failed" count=224962026/09/07 19:37:13 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-35150-957684269/TestDrainGivesUpWhenServerDown2169992417/002/c2497--- PASS: TestServerWait (0.00s)24982026/09/07 19:37:13 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-35150-957684269/TestDrainGivesUpWhenServerDown2169992417/002/d24992026/09/07 19:37:13 INFO Uploading batch count=425002026/09/07 19:37:13 ERROR Upload failed error="upload failed" count=425012026/09/07 19:37:13 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-35150-957684269/TestDrainIsolatesPoisonPath906365514/002/bbb25022026/09/07 19:37:13 INFO Uploading batch count=225032026/09/07 19:37:13 ERROR Upload failed error="upload failed" count=225042026/09/07 19:37:13 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-35150-957684269/TestDrainGivesUpWhenServerDown2169992417/002/e25052026/09/07 19:37:13 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-35150-957684269/TestDrainGivesUpWhenServerDown2169992417/002/f25062026/09/07 19:37:13 ERROR Drain finished with paths left in queue remaining=1025072026/09/07 19:37:13 INFO Uploading batch count=125082026/09/07 19:37:13 ERROR Upload failed error="upload failed" count=125092026/09/07 19:37:13 INFO Uploading batch count=125102026/09/07 19:37:13 ERROR Upload failed error="upload failed" count=125112026/09/07 19:37:13 INFO Uploading batch count=125122026/09/07 19:37:13 ERROR Upload failed error="upload failed" count=125132026/09/07 19:37:13 ERROR Drain finished with paths left in queue remaining=12514--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2515--- PASS: TestDrainIsolatesPoisonPath (0.01s)2516--- PASS: TestWorkerSkipsGCdPaths (0.02s)2517--- PASS: TestWorkerPrunesClosureDeps (0.03s)2518--- PASS: TestWorkerUploadsAndRemoves (0.02s)2519--- PASS: TestQueueRemoveLargeClosure (0.06s)2520--- PASS: TestQueueConcurrentWriters (0.13s)25212026/09/07 19:37:14 ERROR Upload failed error="context deadline exceeded" count=225222026/09/07 19:37:14 ERROR Drain finished with paths left in queue remaining=42523--- PASS: TestDrainTimeout (0.21s)25242026/09/07 19:37:14 INFO Uploading batch count=125252026/09/07 19:37:14 INFO Uploading batch count=125262026/09/07 19:37:14 INFO Uploading batch count=125272026/09/07 19:37:14 ERROR Upload failed error="upload failed" count=125282026/09/07 19:37:14 INFO Uploading batch count=125292026/09/07 19:37:14 ERROR Upload failed error="upload failed" count=125302026/09/07 19:37:14 INFO Uploading batch count=125312026/09/07 19:37:14 ERROR Upload failed error="upload failed" count=125322026/09/07 19:37:14 INFO Uploading batch count=125332026/09/07 19:37:14 ERROR Upload failed error="upload failed" count=125342026/09/07 19:37:14 ERROR Drain finished with paths left in queue remaining=12535--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2536PASS