niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #170
· 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 TestResolveStorePath74=== CONT TestEncodeNixBase32WithRealHash75--- PASS: TestEncodeNixBase32WithRealHash (0.00s)76=== CONT TestScriptTokenBadJSON77=== CONT TestParsePathInfoJSON78=== RUN TestParsePathInfoJSON/Nix_format79=== PAUSE TestParsePathInfoJSON/Nix_format80=== RUN TestParsePathInfoJSON/Lix_format81=== PAUSE TestParsePathInfoJSON/Lix_format82=== RUN TestParsePathInfoJSON/empty_input83=== PAUSE TestParsePathInfoJSON/empty_input84=== RUN TestParsePathInfoJSON/whitespace_only85=== PAUSE TestParsePathInfoJSON/whitespace_only86=== RUN TestParsePathInfoJSON/invalid_JSON87=== PAUSE TestParsePathInfoJSON/invalid_JSON88=== CONT TestScriptTokenEmptyToken89=== CONT TestPathInfoHashCompatibility90=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)91=== CONT TestGetStorePathHash92=== RUN TestGetStorePathHash/valid_store_path93=== PAUSE TestGetStorePathHash/valid_store_path94=== RUN TestGetStorePathHash/basename_without_hyphen_should_error95=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error96=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error97=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error98=== CONT TestFileTokenMissing99=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error100=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error101=== CONT TestScriptTokenEmptyCommand102--- PASS: TestScriptTokenEmptyCommand (0.00s)103=== CONT TestScriptTokenScriptFails104=== CONT TestScriptTokenNoExpiryRerunsEveryCall105=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)106=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon107=== CONT TestConvertHashToNix32108=== RUN TestConvertHashToNix32/SRI_format_to_Nix32109=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32110=== RUN TestConvertHashToNix32/already_Nix32_format111=== PAUSE TestConvertHashToNix32/already_Nix32_format112=== RUN TestConvertHashToNix32/invalid_format113=== PAUSE TestConvertHashToNix32/invalid_format114=== CONT TestFileTokenEmpty115=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon116=== CONT TestScriptTokenCachesUntilRefresh117=== CONT TestRateLimiterFeedback118=== RUN TestRateLimiterFeedback/429_enables_limiter119=== PAUSE TestRateLimiterFeedback/429_enables_limiter120=== RUN TestRateLimiterFeedback/503_enables_limiter121=== PAUSE TestRateLimiterFeedback/503_enables_limiter122=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter123=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter124=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter125=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter126=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess127=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI128--- PASS: TestFileTokenMissing (0.00s)129=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI1302026/08/29 16:33:26 WARN Rate limiter enabled after throttle name=server-test rate=5131=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512132=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512133=== CONT TestDumpPathMatchesNix134--- PASS: TestFileTokenEmpty (0.00s)135=== CONT TestEncodeNixBase32136=== RUN TestEncodeNixBase32/test_string_hash137=== PAUSE TestEncodeNixBase32/test_string_hash138=== RUN TestEncodeNixBase32/empty_input139=== PAUSE TestEncodeNixBase32/empty_input140=== CONT TestDumpPathWriterError141--- PASS: TestResolveStorePath (0.00s)142=== CONT TestDumpPathSingleFile143--- PASS: TestDoServerRequestAttachesToken (0.01s)144=== CONT TestPartSizeForNAR145=== RUN TestPartSizeForNAR/zero_stays_at_minimum146=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum147=== RUN TestPartSizeForNAR/small_stays_at_minimum148=== PAUSE TestPartSizeForNAR/small_stays_at_minimum149=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum150=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum151=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts152=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts153=== RUN TestPartSizeForNAR/1_TiB154=== PAUSE TestPartSizeForNAR/1_TiB155=== RUN TestPartSizeForNAR/5_TiB_S3_max_object156=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object157=== RUN TestPartSizeForNAR/capped_at_5_GiB158=== PAUSE TestPartSizeForNAR/capped_at_5_GiB159=== CONT TestUploadMultipart_SupersededByPeer160=== RUN TestUploadMultipart_SupersededByPeer/exists161=== PAUSE TestUploadMultipart_SupersededByPeer/exists162=== RUN TestUploadMultipart_SupersededByPeer/missing163=== PAUSE TestUploadMultipart_SupersededByPeer/missing164=== CONT TestSetClientTLSDoesNotMutateDefaultTransport165--- PASS: TestScriptTokenScriptFails (0.01s)166=== CONT TestFileTokenReadsAndCaches167--- PASS: TestFileTokenReadsAndCaches (0.00s)168=== CONT TestStaticToken169--- PASS: TestStaticToken (0.00s)170=== CONT TestSetClientTLSErrors171=== RUN TestSetClientTLSErrors/missing_cert_file172=== PAUSE TestSetClientTLSErrors/missing_cert_file173=== RUN TestSetClientTLSErrors/missing_key_file174=== PAUSE TestSetClientTLSErrors/missing_key_file175=== RUN TestSetClientTLSErrors/missing_ca_file176=== PAUSE TestSetClientTLSErrors/missing_ca_file177=== RUN TestSetClientTLSErrors/invalid_ca_file178=== PAUSE TestSetClientTLSErrors/invalid_ca_file179=== CONT TestPathInfoCACompatibility180=== RUN TestPathInfoCACompatibility/null_ca_field181=== PAUSE TestPathInfoCACompatibility/null_ca_field182=== RUN TestPathInfoCACompatibility/old_string_format_-_text183=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text184=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive185=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive186=== RUN TestPathInfoCACompatibility/new_structured_format_-_text187=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text188=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method189=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method190=== CONT TestShellSplitErrors191--- PASS: TestShellSplitErrors (0.00s)192=== CONT TestSetClientTLS193--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)194=== CONT TestFilterOversizedClosures195=== RUN TestFilterOversizedClosures/no_limit_keeps_everything196=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything197=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped198=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped199=== RUN TestFilterOversizedClosures/all_closures_skipped200=== PAUSE TestFilterOversizedClosures/all_closures_skipped201=== CONT TestCaseHackSuffix202=== RUN TestSetClientTLS/rejects_connection_without_client_cert203=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert204=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA205=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA206=== RUN TestSetClientTLS/preserves_debug_logging_transport207=== PAUSE TestSetClientTLS/preserves_debug_logging_transport208=== CONT TestShellSplit209--- PASS: TestShellSplit (0.00s)210=== CONT TestDoWithRetry_BodyReplayedViaGetBody211--- PASS: TestScriptTokenBadJSON (0.01s)212=== CONT TestParsePathInfoJSONMultiplePaths213=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths214=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths215=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths216=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths217=== CONT TestParsePathInfoJSON/Nix_format218=== CONT TestParsePathInfoJSON/invalid_JSON219=== CONT TestParsePathInfoJSON/empty_input220=== CONT TestParsePathInfoJSON/Lix_format221=== CONT TestParsePathInfoJSON/whitespace_only222--- PASS: TestParsePathInfoJSON (0.00s)223 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)224 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)225 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)226 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)227 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)228=== CONT TestGetStorePathHash/valid_store_path229=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error230=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error231=== CONT TestGetStorePathHash/basename_without_hyphen_should_error232--- PASS: TestGetStorePathHash (0.00s)233 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)234 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)235 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)236 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)2372026/08/29 16:33:26 WARN Rate limiter enabled after throttle name=server-test rate=5238=== CONT TestConvertHashToNix32/SRI_format_to_Nix322392026/08/29 16:33:26 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:56410240=== CONT TestConvertHashToNix32/invalid_format241=== CONT TestConvertHashToNix32/already_Nix32_format242--- PASS: TestConvertHashToNix32 (0.00s)243 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)244 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)245 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)246=== CONT TestRateLimiterFeedback/429_enables_limiter247--- PASS: TestScriptTokenEmptyToken (0.01s)248=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2492026/08/29 16:33:26 WARN Rate limiter backed off name=server-test rate=52502026/08/29 16:33:26 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:564102512026/08/29 16:33:26 WARN Rate limiter enabled after throttle name=server-test rate=52522026/08/29 16:33:26 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:56412253--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.00s)254=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter255=== CONT TestRateLimiterFeedback/503_enables_limiter2562026/08/29 16:33:26 WARN Rate limiter backed off name=server-test rate=5257=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)258=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI259=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512260=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon261--- PASS: TestPathInfoHashCompatibility (0.00s)262 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)263 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)264 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)265 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)266=== CONT TestEncodeNixBase32/test_string_hash267=== CONT TestEncodeNixBase32/empty_input268--- PASS: TestEncodeNixBase32 (0.00s)269 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)270 --- PASS: TestEncodeNixBase32/empty_input (0.00s)271=== CONT TestPartSizeForNAR/zero_stays_at_minimum272=== CONT TestPartSizeForNAR/1_TiB273=== CONT TestPartSizeForNAR/capped_at_5_GiB274=== CONT TestPartSizeForNAR/5_TiB_S3_max_object275=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum276=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts277=== CONT TestPartSizeForNAR/small_stays_at_minimum278--- PASS: TestPartSizeForNAR (0.00s)279 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)280 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)281 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)282 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)283 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)284 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)285 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)286=== CONT TestUploadMultipart_SupersededByPeer/exists2872026/08/29 16:33:26 WARN Rate limiter enabled after throttle name=server-test rate=52882026/08/29 16:33:26 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:56417289=== CONT TestUploadMultipart_SupersededByPeer/missing2902026/08/29 16:33:26 WARN Rate limiter backed off name=server-test rate=5291=== CONT TestSetClientTLSErrors/missing_cert_file292=== CONT TestSetClientTLSErrors/missing_ca_file293--- PASS: TestRateLimiterFeedback (0.00s)294 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)295 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)296 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)297 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)298=== CONT TestSetClientTLSErrors/invalid_ca_file299=== CONT TestSetClientTLSErrors/missing_key_file300=== CONT TestPathInfoCACompatibility/null_ca_field301=== CONT TestPathInfoCACompatibility/new_structured_format_-_text302=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method303=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive304--- PASS: TestSetClientTLSErrors (0.00s)305 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)306 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)307 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)308 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)309=== CONT TestPathInfoCACompatibility/old_string_format_-_text310=== CONT TestFilterOversizedClosures/no_limit_keeps_everything311=== CONT TestFilterOversizedClosures/all_closures_skipped312--- PASS: TestPathInfoCACompatibility (0.00s)313 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)314 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)315 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)316 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)317 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)318=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3192026/08/29 16:33:26 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=503202026/08/29 16:33:26 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=2000321=== CONT TestSetClientTLS/rejects_connection_without_client_cert322--- PASS: TestFilterOversizedClosures (0.00s)323 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)324 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)325 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)326=== CONT TestSetClientTLS/preserves_debug_logging_transport327--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)328 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)329 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)330=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA331=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths332=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths333--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)334 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)335 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)3362026/08/29 16:33:26 http: TLS handshake error from 127.0.0.1:56424: read tcp 127.0.0.1:56409->127.0.0.1:56424: use of closed network connection337--- PASS: TestSetClientTLS (0.00s)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: TestScriptTokenCachesUntilRefresh (0.03s)342--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)343--- PASS: TestDumpPathWriterError (0.04s)344--- PASS: TestDumpPathSingleFile (0.04s)345--- PASS: TestCaseHackSuffix (0.04s)346--- PASS: TestDumpPathMatchesNix (0.06s)347--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)348PASS349Running server tests...350The files belonging to this database system will be owned by user "_nixbld10".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-15122-3527464599/postgres2245890322/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-15122-3527464599/postgres2245890322/data -l logfile start376377/nix/var/nix/builds/nix-15122-3527464599/postgres2245890322:5432 - no response3782026-08-29 16:33:27.933 UTC [15176] LOG: starting PostgreSQL 18.4 on aarch64-apple-darwin25.5.0, compiled by clang version 21.1.8, 64-bit3792026-08-29 16:33:27.933 UTC [15176] LOG: listening on Unix socket "/nix/var/nix/builds/nix-15122-3527464599/postgres2245890322/.s.PGSQL.5432"3802026-08-29 16:33:27.935 UTC [15183] LOG: database system was shut down at 2026-08-29 16:33:27 UTC3812026-08-29 16:33:27.936 UTC [15176] LOG: database system is ready to accept connections382/nix/var/nix/builds/nix-15122-3527464599/postgres2245890322:5432 - accepting connections383=== RUN TestService_AuthMiddleware384=== PAUSE TestService_AuthMiddleware385=== RUN TestService_AuthMiddleware_MTLSProxyHeader386=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader387=== RUN TestService_AuthMiddleware_MTLSBoundSubjects388=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects389=== RUN TestService_ReadAuthMiddleware390=== PAUSE TestService_ReadAuthMiddleware391=== RUN TestService_AuthMiddleware_OIDC392=== PAUSE TestService_AuthMiddleware_OIDC393=== RUN TestService_RequireScope_OIDC394=== PAUSE TestService_RequireScope_OIDC395=== RUN TestService_ReadScope_PublicByDefault396=== PAUSE TestService_ReadScope_PublicByDefault397=== RUN TestCacheConfigHandler398=== PAUSE TestCacheConfigHandler399=== RUN TestCacheStatsHandler400=== PAUSE TestCacheStatsHandler401=== RUN TestClientCADerivations402=== PAUSE TestClientCADerivations403=== RUN TestClientErrorHandling404=== PAUSE TestClientErrorHandling405=== RUN TestClientIntegration406=== PAUSE TestClientIntegration407=== RUN TestClientMultipleUploads408=== PAUSE TestClientMultipleUploads409=== RUN TestClientWithDependencies410=== PAUSE TestClientWithDependencies411=== RUN TestPinProtectsFromGC412=== PAUSE TestPinProtectsFromGC413=== RUN TestResolveDBConnectionString414=== PAUSE TestResolveDBConnectionString415=== RUN TestGCAdvisoryLockBlocksConcurrentRun4162026-08-29 16:33:28.344 UTC [15255] ERROR: relation "goose_db_version" does not exist at character 364172026-08-29 16:33:28.344 UTC [15255] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4182026/08/29 16:33:28 OK 20241026095416_initial_model.sql (3.92ms)4192026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (478.83µs)4202026/08/29 16:33:28 OK 20251218171726_add_pins.sql (798.63µs)4212026/08/29 16:33:28 OK 20260628120000_add_object_size_and_stats.sql (839.04µs)4222026/08/29 16:33:28 goose: successfully migrated database to version: 202606281200004232026/08/29 16:33:28 OK 1_commit_pending_closure.sql (885.25µs)4242026/08/29 16:33:28 OK 2_object_stats_trigger.sql (211.79µs)4252026/08/29 16:33:28 goose: up to current file version: 2426--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.25s)427=== RUN TestGCBugBareHashReferences428=== PAUSE TestGCBugBareHashReferences429=== RUN TestGCMetrics430=== PAUSE TestGCMetrics431=== RUN TestGCTaskStore_StartNew432=== PAUSE TestGCTaskStore_StartNew433=== RUN TestGCTaskStore_DeduplicateSameParams434=== PAUSE TestGCTaskStore_DeduplicateSameParams435=== RUN TestGCTaskStore_ConflictDifferentParams436=== PAUSE TestGCTaskStore_ConflictDifferentParams437=== RUN TestGCTaskStore_GetEmpty438=== PAUSE TestGCTaskStore_GetEmpty439=== RUN TestGCTaskStore_GetReturnsLatest440=== PAUSE TestGCTaskStore_GetReturnsLatest441=== RUN TestGCTaskStore_CompletedAllowsNewTask442=== PAUSE TestGCTaskStore_CompletedAllowsNewTask443=== RUN TestGCTaskStore_PhaseUpdates444=== PAUSE TestGCTaskStore_PhaseUpdates445=== RUN TestGCTaskStore_Fail446=== PAUSE TestGCTaskStore_Fail447=== RUN TestGracefulShutdownDrainsInflight448=== PAUSE TestGracefulShutdownDrainsInflight449=== RUN TestService_healthCheckHandler450=== PAUSE TestService_healthCheckHandler451=== RUN TestService_readinessHandler452=== PAUSE TestService_readinessHandler453=== RUN TestGenerateLandingPage454=== PAUSE TestGenerateLandingPage455=== RUN TestCacheConfigHandlerMaxNarSize456=== PAUSE TestCacheConfigHandlerMaxNarSize457=== RUN TestCreatePendingClosureRejectsOversizedNAR458=== PAUSE TestCreatePendingClosureRejectsOversizedNAR459=== RUN TestNARDeduplicationMetadataUploadBug460=== PAUSE TestNARDeduplicationMetadataUploadBug461=== RUN TestMetricsInventory462=== PAUSE TestMetricsInventory463=== RUN TestService_NativeMTLS464=== PAUSE TestService_NativeMTLS465=== RUN TestServerTLSConfig466=== PAUSE TestServerTLSConfig467=== RUN TestMultipartCleanup468=== PAUSE TestMultipartCleanup469=== RUN TestObjectStatsTrigger470=== PAUSE TestObjectStatsTrigger471=== RUN TestOrphanedObjectsGC472=== PAUSE TestOrphanedObjectsGC473=== RUN TestOrphanedObjectsGCStressTest474=== PAUSE TestOrphanedObjectsGCStressTest475=== RUN TestResurrectedObjectNotDeleted476=== PAUSE TestResurrectedObjectNotDeleted477=== RUN TestParseSingleRange478=== PAUSE TestParseSingleRange479=== RUN TestIsValidCachePath480=== PAUSE TestIsValidCachePath481=== RUN TestReadProxyNarinfo482=== PAUSE TestReadProxyNarinfo483=== RUN TestReadProxyNarinfoAlreadyDecompressed484=== PAUSE TestReadProxyNarinfoAlreadyDecompressed485=== RUN TestReadProxyNarStreaming486=== PAUSE TestReadProxyNarStreaming487=== RUN TestReadProxy404488=== PAUSE TestReadProxy404489=== RUN TestReadProxyInvalidPath490=== PAUSE TestReadProxyInvalidPath491=== RUN TestReadProxyHead492=== PAUSE TestReadProxyHead493=== RUN TestReadProxyConditionalGet494=== PAUSE TestReadProxyConditionalGet495=== RUN TestReadProxyRootRedirectsToIndexHTML496=== PAUSE TestReadProxyRootRedirectsToIndexHTML497=== RUN TestReadProxyDisabled498=== PAUSE TestReadProxyDisabled499=== RUN TestReadRedirectNar500=== PAUSE TestReadRedirectNar501=== RUN TestReadRedirectKeepsNarinfoProxied502=== PAUSE TestReadRedirectKeepsNarinfoProxied503=== RUN TestReadProxyRangeRequest504=== PAUSE TestReadProxyRangeRequest505=== RUN TestReadRedirectUsesPublicS3URL506=== PAUSE TestReadRedirectUsesPublicS3URL507=== RUN TestRedundantMultipartUpload508=== PAUSE TestRedundantMultipartUpload509=== RUN TestCompleteMultipartUpload_ErrorButObjectExists510=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists511=== RUN TestCompletedNarNotReofferedAcrossClosures512=== PAUSE TestCompletedNarNotReofferedAcrossClosures513=== RUN TestPresignedUploadRegisteredBeforeCommit514=== PAUSE TestPresignedUploadRegisteredBeforeCommit515=== RUN TestService_Rustfstest516=== PAUSE TestService_Rustfstest517=== RUN TestParseSize518=== PAUSE TestParseSize519=== RUN TestSkippedUploadsHandler520=== PAUSE TestSkippedUploadsHandler521=== RUN TestSystemdListenerNotActivated522--- PASS: TestSystemdListenerNotActivated (0.00s)523=== RUN TestWatchdogBeatsWhenHealthy524--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)525=== RUN TestWatchdogSkipsWhenUnhealthy5262026/08/29 16:33:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5272026/08/29 16:33:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5282026/08/29 16:33:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5292026/08/29 16:33:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5302026/08/29 16:33:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5312026/08/29 16:33:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5322026/08/29 16:33:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5332026/08/29 16:33:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5342026/08/29 16:33:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5352026/08/29 16:33:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"536--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)537=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle538=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle539=== RUN TestProxyWriteTimeout540=== PAUSE TestProxyWriteTimeout541=== RUN TestIsValidUploadKey542=== PAUSE TestIsValidUploadKey543=== RUN TestUploadHandlersRejectInvalidKeys544=== PAUSE TestUploadHandlersRejectInvalidKeys545=== RUN TestUploadHandlersRejectOversizedBody546=== PAUSE TestUploadHandlersRejectOversizedBody547=== RUN TestService_cleanupPendingClosuresHandler548=== PAUSE TestService_cleanupPendingClosuresHandler549=== RUN TestService_createPendingClosureHandler550=== PAUSE TestService_createPendingClosureHandler551=== RUN TestService_verifyS3Integrity552=== PAUSE TestService_verifyS3Integrity553=== RUN TestCompleteMultipartUnregistered554=== PAUSE TestCompleteMultipartUnregistered555=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT556=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT557=== CONT TestReadProxyInvalidPath558=== CONT TestService_Rustfstest559=== CONT TestReadProxy404560=== CONT TestUploadHandlersRejectOversizedBody561=== CONT TestGCTaskStore_GetReturnsLatest562--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)563=== CONT TestProxyWriteTimeout564=== RUN TestProxyWriteTimeout/narinfo565=== CONT TestServerTLSConfig566=== RUN TestServerTLSConfig/no_client_CA567=== CONT TestGCTaskStore_CompletedAllowsNewTask568--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)569=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle570=== CONT TestService_AuthMiddleware571=== CONT TestUploadHandlersRejectInvalidKeys572=== CONT TestIsValidUploadKey573=== PAUSE TestProxyWriteTimeout/narinfo574=== PAUSE TestServerTLSConfig/no_client_CA575=== RUN TestIsValidUploadKey/narinfo576=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info577=== RUN TestServerTLSConfig/missing_CA_file578=== PAUSE TestIsValidUploadKey/narinfo579=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info580=== RUN TestProxyWriteTimeout/1_GiB_nar581=== PAUSE TestProxyWriteTimeout/1_GiB_nar582=== RUN TestProxyWriteTimeout/10_GiB_nar583=== RUN TestIsValidUploadKey/nar_zst584=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal585=== PAUSE TestServerTLSConfig/missing_CA_file586=== PAUSE TestIsValidUploadKey/nar_zst587=== RUN TestIsValidUploadKey/nar_xz588=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal589=== RUN TestServerTLSConfig/not_a_PEM_file590=== PAUSE TestProxyWriteTimeout/10_GiB_nar591=== PAUSE TestServerTLSConfig/not_a_PEM_file592=== RUN TestProxyWriteTimeout/unknown_size593=== CONT TestSkippedUploadsHandler594=== PAUSE TestIsValidUploadKey/nar_xz595=== RUN TestIsValidUploadKey/nar_plain596=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key597=== PAUSE TestIsValidUploadKey/nar_plain598=== RUN TestIsValidUploadKey/listing599=== PAUSE TestIsValidUploadKey/listing600=== RUN TestIsValidUploadKey/build_log601=== PAUSE TestIsValidUploadKey/build_log602=== RUN TestIsValidUploadKey/build_log_home-manager_file603=== PAUSE TestIsValidUploadKey/build_log_home-manager_file604=== PAUSE TestProxyWriteTimeout/unknown_size605=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key606=== RUN TestIsValidUploadKey/build_log_plus_in_name607=== PAUSE TestIsValidUploadKey/build_log_plus_in_name608=== RUN TestIsValidUploadKey/build_log_question_mark609=== PAUSE TestIsValidUploadKey/build_log_question_mark610=== RUN TestIsValidUploadKey/build_log_equals611=== PAUSE TestIsValidUploadKey/build_log_equals612=== RUN TestIsValidUploadKey/realisation613=== PAUSE TestIsValidUploadKey/realisation614=== CONT TestParseSize615--- PASS: TestParseSize (0.00s)616=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key617=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key618=== RUN TestIsValidUploadKey/realisation_plus_in_output619=== PAUSE TestIsValidUploadKey/realisation_plus_in_output620=== CONT TestGenerateLandingPage621=== CONT TestService_NativeMTLS622=== RUN TestIsValidUploadKey/nix-cache-info623=== PAUSE TestIsValidUploadKey/nix-cache-info624=== RUN TestIsValidUploadKey/index.html625=== PAUSE TestIsValidUploadKey/index.html626=== RUN TestIsValidUploadKey/narinfo_key,_nar_type627=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type628=== RUN TestIsValidUploadKey/nar_key,_narinfo_type629=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type630=== RUN TestIsValidUploadKey/listing_key,_narinfo_type631=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type632=== RUN TestIsValidUploadKey/traversal633=== PAUSE TestIsValidUploadKey/traversal634=== RUN TestIsValidUploadKey/traversal_nar635=== PAUSE TestIsValidUploadKey/traversal_nar636=== RUN TestIsValidUploadKey/absolute637=== PAUSE TestIsValidUploadKey/absolute638=== RUN TestIsValidUploadKey/empty_key639=== PAUSE TestIsValidUploadKey/empty_key640=== RUN TestIsValidUploadKey/unknown_type641=== PAUSE TestIsValidUploadKey/unknown_type642=== CONT TestMetricsInventory6432026/08/29 16:33:28 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000644--- PASS: TestSkippedUploadsHandler (0.01s)645=== CONT TestNARDeduplicationMetadataUploadBug646--- PASS: TestGenerateLandingPage (0.01s)647=== CONT TestCreatePendingClosureRejectsOversizedNAR6482026/08/29 16:33:28 INFO Received uploads request method=POST path=/api/pending_closures649--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)650=== CONT TestCacheConfigHandlerMaxNarSize651--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)652=== CONT TestParseSingleRange653=== RUN TestParseSingleRange/none654=== PAUSE TestParseSingleRange/none655=== RUN TestParseSingleRange/unknown_unit656=== PAUSE TestParseSingleRange/unknown_unit657=== RUN TestParseSingleRange/multi-range_ignored658=== PAUSE TestParseSingleRange/multi-range_ignored659=== RUN TestParseSingleRange/malformed_no_dash660=== PAUSE TestParseSingleRange/malformed_no_dash661=== RUN TestParseSingleRange/malformed_both_empty662=== PAUSE TestParseSingleRange/malformed_both_empty663=== RUN TestParseSingleRange/malformed_end_before_start664=== PAUSE TestParseSingleRange/malformed_end_before_start665=== RUN TestParseSingleRange/closed666=== PAUSE TestParseSingleRange/closed667=== RUN TestParseSingleRange/open-ended668=== PAUSE TestParseSingleRange/open-ended669=== RUN TestParseSingleRange/end_clamped_to_size670=== PAUSE TestParseSingleRange/end_clamped_to_size671=== RUN TestParseSingleRange/suffix672=== PAUSE TestParseSingleRange/suffix673=== RUN TestParseSingleRange/suffix_exceeds_size674=== PAUSE TestParseSingleRange/suffix_exceeds_size675=== RUN TestParseSingleRange/single_byte676=== PAUSE TestParseSingleRange/single_byte677=== RUN TestParseSingleRange/start_past_EOF678=== PAUSE TestParseSingleRange/start_past_EOF679=== RUN TestParseSingleRange/start_far_past_EOF680=== PAUSE TestParseSingleRange/start_far_past_EOF681=== CONT TestReadProxyNarStreaming682=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart683=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart684=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts685=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts686=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure687=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure688=== CONT TestReadProxyNarinfoAlreadyDecompressed6892026-08-29 16:33:28.870 UTC [15277] ERROR: relation "goose_db_version" does not exist at character 366902026-08-29 16:33:28.870 UTC [15277] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6912026-08-29 16:33:28.876 UTC [15278] ERROR: relation "goose_db_version" does not exist at character 366922026-08-29 16:33:28.876 UTC [15278] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6932026-08-29 16:33:28.881 UTC [15279] ERROR: relation "goose_db_version" does not exist at character 366942026-08-29 16:33:28.881 UTC [15279] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6952026-08-29 16:33:28.883 UTC [15280] ERROR: relation "goose_db_version" does not exist at character 366962026-08-29 16:33:28.883 UTC [15280] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6972026-08-29 16:33:28.884 UTC [15281] ERROR: relation "goose_db_version" does not exist at character 366982026-08-29 16:33:28.884 UTC [15281] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6992026/08/29 16:33:28 OK 20241026095416_initial_model.sql (11.21ms)7002026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (1.55ms)7012026-08-29 16:33:28.891 UTC [15282] ERROR: relation "goose_db_version" does not exist at character 367022026-08-29 16:33:28.891 UTC [15282] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7032026/08/29 16:33:28 OK 20251218171726_add_pins.sql (1.64ms)7042026/08/29 16:33:28 OK 20241026095416_initial_model.sql (9.51ms)7052026-08-29 16:33:28.892 UTC [15283] ERROR: relation "goose_db_version" does not exist at character 367062026-08-29 16:33:28.892 UTC [15283] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7072026-08-29 16:33:28.892 UTC [15285] ERROR: relation "goose_db_version" does not exist at character 367082026-08-29 16:33:28.892 UTC [15285] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7092026/08/29 16:33:28 OK 20260628120000_add_object_size_and_stats.sql (1.39ms)7102026/08/29 16:33:28 goose: successfully migrated database to version: 202606281200007112026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (682.21µs)7122026-08-29 16:33:28.893 UTC [15286] ERROR: relation "goose_db_version" does not exist at character 367132026-08-29 16:33:28.893 UTC [15286] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7142026-08-29 16:33:28.894 UTC [15284] ERROR: relation "goose_db_version" does not exist at character 367152026-08-29 16:33:28.894 UTC [15284] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7162026/08/29 16:33:28 OK 1_commit_pending_closure.sql (1.47ms)7172026/08/29 16:33:28 OK 2_object_stats_trigger.sql (611µs)7182026/08/29 16:33:28 goose: up to current file version: 27192026/08/29 16:33:28 OK 20251218171726_add_pins.sql (2.17ms)7202026/08/29 16:33:28 OK 20241026095416_initial_model.sql (5.77ms)7212026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (588.17µs)7222026/08/29 16:33:28 OK 20260628120000_add_object_size_and_stats.sql (1.96ms)7232026/08/29 16:33:28 goose: successfully migrated database to version: 202606281200007242026/08/29 16:33:28 OK 20241026095416_initial_model.sql (9.73ms)7252026/08/29 16:33:28 OK 20251218171726_add_pins.sql (1.29ms)7262026/08/29 16:33:28 OK 1_commit_pending_closure.sql (1.07ms)7272026/08/29 16:33:28 OK 2_object_stats_trigger.sql (212.33µs)7282026/08/29 16:33:28 goose: up to current file version: 27292026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (7.47ms)7302026/08/29 16:33:28 OK 20260628120000_add_object_size_and_stats.sql (53.03ms)7312026/08/29 16:33:28 goose: successfully migrated database to version: 202606281200007322026/08/29 16:33:28 OK 20241026095416_initial_model.sql (61.07ms)7332026/08/29 16:33:28 OK 1_commit_pending_closure.sql (1.77ms)7342026/08/29 16:33:28 OK 2_object_stats_trigger.sql (234.75µs)7352026/08/29 16:33:28 goose: up to current file version: 27362026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (8.23ms)7372026/08/29 16:33:28 OK 20251218171726_add_pins.sql (59.91ms)7382026/08/29 16:33:28 OK 20251218171726_add_pins.sql (12.71ms)7392026/08/29 16:33:28 OK 20260628120000_add_object_size_and_stats.sql (7.09ms)7402026/08/29 16:33:28 goose: successfully migrated database to version: 202606281200007412026/08/29 16:33:28 OK 20241026095416_initial_model.sql (76.98ms)7422026/08/29 16:33:28 OK 1_commit_pending_closure.sql (1.26ms)7432026/08/29 16:33:28 OK 20241026095416_initial_model.sql (77.13ms)7442026/08/29 16:33:28 OK 2_object_stats_trigger.sql (427.83µs)7452026/08/29 16:33:28 goose: up to current file version: 27462026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (7.46ms)7472026/08/29 16:33:28 OK 20241026095416_initial_model.sql (84.02ms)7482026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (7.35ms)7492026/08/29 16:33:28 OK 20260628120000_add_object_size_and_stats.sql (9.17ms)7502026/08/29 16:33:28 goose: successfully migrated database to version: 202606281200007512026/08/29 16:33:28 OK 20241026095416_initial_model.sql (84.11ms)7522026/08/29 16:33:28 OK 20241026095416_initial_model.sql (85.23ms)7532026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (4.16ms)7542026/08/29 16:33:28 OK 20251218171726_add_pins.sql (6.85ms)7552026/08/29 16:33:28 OK 1_commit_pending_closure.sql (6.25ms)7562026/08/29 16:33:28 OK 2_object_stats_trigger.sql (203.17µs)7572026/08/29 16:33:28 goose: up to current file version: 27582026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (10.89ms)7592026/08/29 16:33:28 OK 20251210153512_drop_unused_gin_index.sql (11.32ms)7602026/08/29 16:33:28 OK 20251218171726_add_pins.sql (12.17ms)7612026/08/29 16:33:28 OK 20251218171726_add_pins.sql (16.33ms)7622026/08/29 16:33:28 OK 20260628120000_add_object_size_and_stats.sql (10.83ms)7632026/08/29 16:33:28 goose: successfully migrated database to version: 202606281200007642026/08/29 16:33:28 OK 20251218171726_add_pins.sql (5.36ms)7652026/08/29 16:33:28 OK 20251218171726_add_pins.sql (5.99ms)7662026/08/29 16:33:28 OK 20260628120000_add_object_size_and_stats.sql (1.32ms)7672026/08/29 16:33:28 goose: successfully migrated database to version: 202606281200007682026/08/29 16:33:28 OK 20260628120000_add_object_size_and_stats.sql (1.28ms)7692026/08/29 16:33:28 goose: successfully migrated database to version: 202606281200007702026/08/29 16:33:28 OK 1_commit_pending_closure.sql (1.59ms)7712026/08/29 16:33:28 OK 2_object_stats_trigger.sql (226.96µs)7722026/08/29 16:33:28 goose: up to current file version: 27732026/08/29 16:33:28 OK 1_commit_pending_closure.sql (1.31ms)7742026/08/29 16:33:28 OK 1_commit_pending_closure.sql (1.32ms)7752026/08/29 16:33:29 OK 2_object_stats_trigger.sql (218.25µs)7762026/08/29 16:33:29 goose: up to current file version: 27772026/08/29 16:33:29 OK 2_object_stats_trigger.sql (216.13µs)7782026/08/29 16:33:29 goose: up to current file version: 27792026/08/29 16:33:29 OK 20260628120000_add_object_size_and_stats.sql (8.2ms)7802026/08/29 16:33:29 goose: successfully migrated database to version: 202606281200007812026/08/29 16:33:29 OK 20260628120000_add_object_size_and_stats.sql (8.21ms)7822026/08/29 16:33:29 goose: successfully migrated database to version: 202606281200007832026/08/29 16:33:29 OK 1_commit_pending_closure.sql (1.1ms)7842026/08/29 16:33:29 OK 2_object_stats_trigger.sql (193.75µs)7852026/08/29 16:33:29 goose: up to current file version: 27862026/08/29 16:33:29 OK 1_commit_pending_closure.sql (1.14ms)7872026/08/29 16:33:29 OK 2_object_stats_trigger.sql (204.42µs)7882026/08/29 16:33:29 goose: up to current file version: 2789--- PASS: TestReadProxy404 (0.39s)790=== CONT TestReadProxyNarinfo791--- PASS: TestService_Rustfstest (0.47s)792=== CONT TestIsValidCachePath793=== RUN TestIsValidCachePath/narinfo794=== PAUSE TestIsValidCachePath/narinfo795=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars796=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars797=== RUN TestIsValidCachePath/nar_zst798=== PAUSE TestIsValidCachePath/nar_zst799=== RUN TestIsValidCachePath/nar_xz800=== PAUSE TestIsValidCachePath/nar_xz801=== RUN TestIsValidCachePath/nar_bz2802=== PAUSE TestIsValidCachePath/nar_bz2803=== RUN TestIsValidCachePath/nar_uncompressed804=== PAUSE TestIsValidCachePath/nar_uncompressed805=== RUN TestIsValidCachePath/ls806=== PAUSE TestIsValidCachePath/ls807=== RUN TestIsValidCachePath/log808=== PAUSE TestIsValidCachePath/log809=== RUN TestIsValidCachePath/realisation810=== PAUSE TestIsValidCachePath/realisation811=== RUN TestIsValidCachePath/nix-cache-info812=== PAUSE TestIsValidCachePath/nix-cache-info813=== RUN TestIsValidCachePath/index.html814=== PAUSE TestIsValidCachePath/index.html815=== RUN TestIsValidCachePath/traversal_parent816=== PAUSE TestIsValidCachePath/traversal_parent817=== RUN TestIsValidCachePath/traversal_in_middle818=== PAUSE TestIsValidCachePath/traversal_in_middle819=== RUN TestIsValidCachePath/invalid_char_e820=== PAUSE TestIsValidCachePath/invalid_char_e821=== RUN TestIsValidCachePath/invalid_char_u822=== PAUSE TestIsValidCachePath/invalid_char_u823=== RUN TestIsValidCachePath/random_path824=== PAUSE TestIsValidCachePath/random_path825=== RUN TestIsValidCachePath/empty826=== PAUSE TestIsValidCachePath/empty827=== RUN TestIsValidCachePath/leading_slash828=== PAUSE TestIsValidCachePath/leading_slash829=== RUN TestIsValidCachePath/wrong_extension830=== PAUSE TestIsValidCachePath/wrong_extension831=== RUN TestIsValidCachePath/short_hash832=== PAUSE TestIsValidCachePath/short_hash833=== CONT TestOrphanedObjectsGC834--- PASS: TestReadProxyInvalidPath (0.57s)835=== CONT TestResurrectedObjectNotDeleted8362026/08/29 16:33:29 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"837--- PASS: TestService_AuthMiddleware (0.68s)838=== CONT TestOrphanedObjectsGCStressTest8392026/08/29 16:33:29 INFO Received uploads request method=POST path=/api/pending_closures8402026/08/29 16:33:29 WARN mTLS auth: subject not in bound subjects subject="CN=reader"8412026/08/29 16:33:29 WARN mTLS auth: subject not in bound subjects subject="CN=reader"842--- PASS: TestService_NativeMTLS (0.88s)843=== CONT TestService_verifyS3Integrity8442026/08/29 16:33:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete845--- PASS: TestMetricsInventory (1.08s)846=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT847--- PASS: TestReadProxyNarinfoAlreadyDecompressed (1.19s)848=== CONT TestCompleteMultipartUnregistered849--- PASS: TestReadProxyNarStreaming (1.49s)850=== CONT TestReadProxyRangeRequest851=== NAME TestNARDeduplicationMetadataUploadBug852 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-15122-3527464599/TestNARDeduplicationMetadataUploadBug3302923964/001/store/x5nqbn6gqw96pf0195wb4p1wm9myn2rw-file1.txt8532026-08-29 16:33:30.225 UTC [15305] ERROR: relation "goose_db_version" does not exist at character 368542026-08-29 16:33:30.225 UTC [15305] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8552026-08-29 16:33:30.263 UTC [15308] ERROR: relation "goose_db_version" does not exist at character 368562026-08-29 16:33:30.263 UTC [15308] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8572026/08/29 16:33:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8582026/08/29 16:33:30 OK 20241026095416_initial_model.sql (42.43ms)8592026/08/29 16:33:30 OK 20251210153512_drop_unused_gin_index.sql (15.64ms)8602026-08-29 16:33:30.317 UTC [15313] ERROR: relation "goose_db_version" does not exist at character 368612026-08-29 16:33:30.317 UTC [15313] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8622026/08/29 16:33:30 OK 20251218171726_add_pins.sql (18.91ms)8632026/08/29 16:33:30 INFO Received uploads request method=POST path=/api/pending_closures8642026/08/29 16:33:30 OK 20260628120000_add_object_size_and_stats.sql (16.6ms)8652026/08/29 16:33:30 goose: successfully migrated database to version: 202606281200008662026/08/29 16:33:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8672026/08/29 16:33:30 INFO Uploading x5nqbn6gqw96pf0195wb4p1wm9myn2rw-file1.txt (160B)8682026/08/29 16:33:30 OK 1_commit_pending_closure.sql (1.14ms)8692026/08/29 16:33:30 OK 2_object_stats_trigger.sql (223.33µs)8702026/08/29 16:33:30 goose: up to current file version: 28712026/08/29 16:33:30 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"8722026/08/29 16:33:30 WARN Failed to register uploaded object key=x5nqbn6gqw96pf0195wb4p1wm9myn2rw.ls error="server returned 404: 404 page not found\n"8732026/08/29 16:33:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8742026/08/29 16:33:30 INFO Signed narinfos id=1 count=18752026/08/29 16:33:30 INFO Uploading 1 narinfos8762026/08/29 16:33:30 OK 20241026095416_initial_model.sql (127.82ms)8772026/08/29 16:33:30 OK 20251210153512_drop_unused_gin_index.sql (7.96ms)8782026/08/29 16:33:30 WARN Failed to register uploaded object key=x5nqbn6gqw96pf0195wb4p1wm9myn2rw.narinfo error="server returned 404: 404 page not found\n"8792026/08/29 16:33:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8802026/08/29 16:33:30 OK 20251218171726_add_pins.sql (30.92ms)8812026/08/29 16:33:30 INFO Completed upload id=18822026/08/29 16:33:30 INFO Upload complete. (234ms)883 metadata_upload_test.go:54: Retrieved narinfo from S3:884 StorePath: /nix/var/nix/builds/nix-15122-3527464599/TestNARDeduplicationMetadataUploadBug3302923964/001/store/x5nqbn6gqw96pf0195wb4p1wm9myn2rw-file1.txt885 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst886 Compression: zstd887 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf888 NarSize: 160889 References: 890 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf891 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)892 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):893 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}8942026/08/29 16:33:30 OK 20260628120000_add_object_size_and_stats.sql (41.9ms)8952026/08/29 16:33:30 goose: successfully migrated database to version: 202606281200008962026/08/29 16:33:30 OK 20241026095416_initial_model.sql (168.71ms)8972026/08/29 16:33:30 OK 1_commit_pending_closure.sql (5.23ms)8982026/08/29 16:33:30 OK 2_object_stats_trigger.sql (280.42µs)8992026/08/29 16:33:30 goose: up to current file version: 29002026/08/29 16:33:30 OK 20251210153512_drop_unused_gin_index.sql (7.06ms)9012026/08/29 16:33:30 OK 20251218171726_add_pins.sql (38.48ms)902--- PASS: TestReadProxyNarinfo (1.54s)903=== CONT TestPresignedUploadRegisteredBeforeCommit9042026/08/29 16:33:30 OK 20260628120000_add_object_size_and_stats.sql (34.98ms)9052026/08/29 16:33:30 goose: successfully migrated database to version: 202606281200009062026/08/29 16:33:30 OK 1_commit_pending_closure.sql (1.56ms)9072026/08/29 16:33:30 OK 2_object_stats_trigger.sql (257.21µs)9082026/08/29 16:33:30 goose: up to current file version: 2909=== NAME TestNARDeduplicationMetadataUploadBug910 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-15122-3527464599/TestNARDeduplicationMetadataUploadBug3302923964/001/store/a2wfakkxg170x7am82c6xrih5f1qpam0-file2.txt9112026/08/29 16:33:30 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9122026-08-29 16:33:30.698 UTC [15322] ERROR: relation "goose_db_version" does not exist at character 369132026-08-29 16:33:30.698 UTC [15322] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9142026/08/29 16:33:30 INFO Received uploads request method=POST path=/api/pending_closures9152026/08/29 16:33:30 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)9162026/08/29 16:33:30 WARN Failed to register uploaded object key=a2wfakkxg170x7am82c6xrih5f1qpam0.ls error="server returned 404: 404 page not found\n"9172026/08/29 16:33:30 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign9182026/08/29 16:33:30 INFO Signed narinfos id=2 count=19192026/08/29 16:33:30 INFO Uploading 1 narinfos9202026/08/29 16:33:30 WARN Failed to register uploaded object key=a2wfakkxg170x7am82c6xrih5f1qpam0.narinfo error="server returned 404: 404 page not found\n"9212026/08/29 16:33:30 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete9222026/08/29 16:33:30 INFO Completed upload id=29232026/08/29 16:33:30 INFO Upload complete. (184ms)924 metadata_upload_test.go:76: Retrieved narinfo from S3:925 StorePath: /nix/var/nix/builds/nix-15122-3527464599/TestNARDeduplicationMetadataUploadBug3302923964/001/store/a2wfakkxg170x7am82c6xrih5f1qpam0-file2.txt926 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst927 Compression: zstd928 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf929 NarSize: 160930 References: 931 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf932 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)933 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):934 {"version":1,"root":{"type":"regular","size":44}}935--- PASS: TestNARDeduplicationMetadataUploadBug (2.23s)936=== CONT TestCompletedNarNotReofferedAcrossClosures9372026/08/29 16:33:30 OK 20241026095416_initial_model.sql (175.93ms)9382026/08/29 16:33:30 OK 20251210153512_drop_unused_gin_index.sql (2.48ms)939--- PASS: TestResurrectedObjectNotDeleted (1.73s)940=== CONT TestCompleteMultipartUpload_ErrorButObjectExists9412026/08/29 16:33:30 OK 20251218171726_add_pins.sql (20.62ms)9422026/08/29 16:33:30 OK 20260628120000_add_object_size_and_stats.sql (21.05ms)9432026/08/29 16:33:30 goose: successfully migrated database to version: 202606281200009442026-08-29 16:33:30.963 UTC [15333] ERROR: relation "goose_db_version" does not exist at character 369452026-08-29 16:33:30.963 UTC [15333] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9462026/08/29 16:33:30 OK 1_commit_pending_closure.sql (1.98ms)9472026/08/29 16:33:30 OK 2_object_stats_trigger.sql (324.71µs)9482026/08/29 16:33:30 goose: up to current file version: 29492026-08-29 16:33:30.972 UTC [15334] ERROR: relation "goose_db_version" does not exist at character 369502026-08-29 16:33:30.972 UTC [15334] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9512026/08/29 16:33:31 OK 20241026095416_initial_model.sql (229.01ms)9522026/08/29 16:33:31 OK 20241026095416_initial_model.sql (232.15ms)9532026/08/29 16:33:31 OK 20251210153512_drop_unused_gin_index.sql (13.23ms)9542026/08/29 16:33:31 OK 20251210153512_drop_unused_gin_index.sql (16.71ms)9552026/08/29 16:33:31 OK 20251218171726_add_pins.sql (87.36ms)9562026/08/29 16:33:31 OK 20251218171726_add_pins.sql (75.86ms)9572026/08/29 16:33:31 OK 20260628120000_add_object_size_and_stats.sql (50.67ms)9582026/08/29 16:33:31 goose: successfully migrated database to version: 202606281200009592026/08/29 16:33:31 OK 20260628120000_add_object_size_and_stats.sql (58.04ms)9602026/08/29 16:33:31 goose: successfully migrated database to version: 202606281200009612026/08/29 16:33:31 OK 1_commit_pending_closure.sql (9.69ms)9622026/08/29 16:33:31 OK 2_object_stats_trigger.sql (821.5µs)9632026/08/29 16:33:31 goose: up to current file version: 29642026/08/29 16:33:31 OK 1_commit_pending_closure.sql (7.94ms)9652026/08/29 16:33:31 OK 2_object_stats_trigger.sql (638.17µs)9662026/08/29 16:33:31 goose: up to current file version: 29672026/08/29 16:33:31 INFO Received uploads request method=POST path=/api/pending_closures968--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.01s)969=== CONT TestRedundantMultipartUpload970=== NAME TestOrphanedObjectsGC971 orphaned_objects_gc_test.go:290: GC Test Summary:972 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A973 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B974 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)975 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)976 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects977--- PASS: TestOrphanedObjectsGC (2.66s)978=== CONT TestReadRedirectUsesPublicS3URL9792026/08/29 16:33:31 INFO Received uploads request method=POST path=/api/pending_closures9802026-08-29 16:33:31.950 UTC [15339] ERROR: relation "goose_db_version" does not exist at character 369812026-08-29 16:33:31.950 UTC [15339] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9822026/08/29 16:33:32 OK 20241026095416_initial_model.sql (198.26ms)9832026/08/29 16:33:32 OK 20251210153512_drop_unused_gin_index.sql (19.94ms)9842026/08/29 16:33:32 OK 20251218171726_add_pins.sql (35.56ms)9852026/08/29 16:33:32 OK 20260628120000_add_object_size_and_stats.sql (45.96ms)9862026/08/29 16:33:32 goose: successfully migrated database to version: 202606281200009872026/08/29 16:33:32 OK 1_commit_pending_closure.sql (17.25ms)9882026/08/29 16:33:32 OK 2_object_stats_trigger.sql (1.53ms)9892026/08/29 16:33:32 goose: up to current file version: 29902026-08-29 16:33:32.364 UTC [15340] ERROR: relation "goose_db_version" does not exist at character 369912026-08-29 16:33:32.364 UTC [15340] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9922026/08/29 16:33:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9932026/08/29 16:33:32 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst994--- PASS: TestCompleteMultipartUnregistered (2.69s)995=== CONT TestGracefulShutdownDrainsInflight9962026/08/29 16:33:32 INFO Starting HTTP server address=127.0.0.1:564959972026/08/29 16:33:32 INFO Shutdown signal received, draining in-flight requests timeout=10s998--- PASS: TestGracefulShutdownDrainsInflight (0.07s)999=== CONT TestService_readinessHandler10002026/08/29 16:33:32 OK 20241026095416_initial_model.sql (262.28ms)10012026/08/29 16:33:32 OK 20251210153512_drop_unused_gin_index.sql (12.61ms)10022026/08/29 16:33:32 OK 20251218171726_add_pins.sql (29.75ms)10032026/08/29 16:33:32 OK 20260628120000_add_object_size_and_stats.sql (23.36ms)10042026/08/29 16:33:32 goose: successfully migrated database to version: 2026062812000010052026/08/29 16:33:32 OK 1_commit_pending_closure.sql (13.65ms)10062026/08/29 16:33:32 OK 2_object_stats_trigger.sql (658.13µs)10072026/08/29 16:33:32 goose: up to current file version: 21008--- PASS: TestReadProxyRangeRequest (2.91s)1009=== CONT TestService_healthCheckHandler10102026-08-29 16:33:33.225 UTC [15345] ERROR: relation "goose_db_version" does not exist at character 3610112026-08-29 16:33:33.225 UTC [15345] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10122026/08/29 16:33:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10132026-08-29 16:33:33.568 UTC [15349] ERROR: relation "goose_db_version" does not exist at character 3610142026-08-29 16:33:33.568 UTC [15349] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10152026/08/29 16:33:33 OK 20241026095416_initial_model.sql (280.64ms)10162026/08/29 16:33:33 OK 20251210153512_drop_unused_gin_index.sql (24.25ms)10172026/08/29 16:33:33 OK 20251218171726_add_pins.sql (38.69ms)10182026/08/29 16:33:33 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NDdiYWJkNjQtZTQ5Ni00OTIyLWI3NjYtNWExZTc1NmEwYTUxLjAzMWViYmM2LWI0NGEtNGZiMy04M2MxLTExZTIxNGY1NTBmZHgxNzg4MDIxMjExODc2NDk2MDAw parts=1010192026/08/29 16:33:33 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10202026/08/29 16:33:33 OK 20260628120000_add_object_size_and_stats.sql (30.25ms)10212026/08/29 16:33:33 goose: successfully migrated database to version: 2026062812000010222026/08/29 16:33:33 OK 1_commit_pending_closure.sql (6.89ms)10232026/08/29 16:33:33 OK 2_object_stats_trigger.sql (916µs)10242026/08/29 16:33:33 goose: up to current file version: 210252026/08/29 16:33:33 INFO Completed upload id=110262026/08/29 16:33:33 INFO Received uploads request method=POST path=/api/pending_closures10272026/08/29 16:33:33 INFO Received uploads request method=POST path=/api/pending_closures10282026/08/29 16:33:33 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10292026/08/29 16:33:33 WARN Found objects in DB but missing from S3, will re-upload count=11030--- PASS: TestService_verifyS3Integrity (4.16s)1031=== CONT TestClientIntegration10322026-08-29 16:33:33.783 UTC [15350] ERROR: relation "goose_db_version" does not exist at character 3610332026-08-29 16:33:33.783 UTC [15350] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10342026/08/29 16:33:33 OK 20241026095416_initial_model.sql (150.35ms)10352026/08/29 16:33:33 OK 20251210153512_drop_unused_gin_index.sql (7.27ms)10362026/08/29 16:33:33 OK 20251218171726_add_pins.sql (44.8ms)10372026/08/29 16:33:33 INFO Received uploads request method=POST path=/api/pending_closures10382026/08/29 16:33:33 OK 20260628120000_add_object_size_and_stats.sql (30ms)10392026/08/29 16:33:33 goose: successfully migrated database to version: 2026062812000010402026/08/29 16:33:33 OK 1_commit_pending_closure.sql (5.77ms)10412026/08/29 16:33:33 OK 2_object_stats_trigger.sql (909.46µs)10422026/08/29 16:33:33 goose: up to current file version: 210432026/08/29 16:33:33 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10442026/08/29 16:33:33 INFO Received uploads request method=POST path=/api/pending_closures1045--- PASS: TestPresignedUploadRegisteredBeforeCommit (3.38s)1046=== CONT TestGCBugBareHashReferences10472026/08/29 16:33:34 OK 20241026095416_initial_model.sql (218.44ms)10482026/08/29 16:33:34 OK 20251210153512_drop_unused_gin_index.sql (15.83ms)10492026/08/29 16:33:34 INFO Received uploads request method=POST path=/api/pending_closures10502026/08/29 16:33:34 OK 20251218171726_add_pins.sql (38.21ms)10512026/08/29 16:33:34 OK 20260628120000_add_object_size_and_stats.sql (26.32ms)10522026/08/29 16:33:34 goose: successfully migrated database to version: 2026062812000010532026/08/29 16:33:34 OK 1_commit_pending_closure.sql (14.33ms)10542026/08/29 16:33:34 OK 2_object_stats_trigger.sql (1.02ms)10552026/08/29 16:33:34 goose: up to current file version: 210562026/08/29 16:33:34 INFO Received uploads request method=POST path=/api/pending_closures10572026/08/29 16:33:34 WARN Rate limiter enabled after throttle name=s3-test rate=510582026/08/29 16:33:34 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1059=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1060 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101061 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001062--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.89s)1063=== CONT TestResolveDBConnectionString1064=== RUN TestResolveDBConnectionString/flag_wins1065=== PAUSE TestResolveDBConnectionString/flag_wins1066=== RUN TestResolveDBConnectionString/file_when_flag_empty1067=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1068=== RUN TestResolveDBConnectionString/missing_file_is_an_error1069=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1070=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1071=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1072=== RUN TestResolveDBConnectionString/nothing_configured1073=== PAUSE TestResolveDBConnectionString/nothing_configured1074=== CONT TestPinProtectsFromGC10752026-08-29 16:33:34.551 UTC [15355] ERROR: relation "goose_db_version" does not exist at character 3610762026-08-29 16:33:34.551 UTC [15355] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10772026-08-29 16:33:34.675 UTC [15356] ERROR: relation "goose_db_version" does not exist at character 3610782026-08-29 16:33:34.675 UTC [15356] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10792026/08/29 16:33:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10802026/08/29 16:33:34 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDdiYWJkNjQtZTQ5Ni00OTIyLWI3NjYtNWExZTc1NmEwYTUxLjg1ZTljOGZhLWUwMGItNDFkNi05NzdkLThlZGI0NGY3MDI0NHgxNzg4MDIxMjE0MzkyNDEzMDAw10812026/08/29 16:33:34 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NDdiYWJkNjQtZTQ5Ni00OTIyLWI3NjYtNWExZTc1NmEwYTUxLjg1ZTljOGZhLWUwMGItNDFkNi05NzdkLThlZGI0NGY3MDI0NHgxNzg4MDIxMjE0MzkyNDEzMDAw parts=11082--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (3.80s)1083=== CONT TestClientWithDependencies10842026/08/29 16:33:34 OK 20241026095416_initial_model.sql (223.43ms)10852026/08/29 16:33:34 OK 20251210153512_drop_unused_gin_index.sql (10.18ms)10862026/08/29 16:33:34 OK 20251218171726_add_pins.sql (40.8ms)10872026/08/29 16:33:34 OK 20241026095416_initial_model.sql (187.47ms)10882026/08/29 16:33:34 OK 20260628120000_add_object_size_and_stats.sql (44.95ms)10892026/08/29 16:33:34 goose: successfully migrated database to version: 2026062812000010902026/08/29 16:33:34 OK 20251210153512_drop_unused_gin_index.sql (13.53ms)10912026/08/29 16:33:34 OK 1_commit_pending_closure.sql (5.48ms)10922026/08/29 16:33:34 OK 2_object_stats_trigger.sql (833.54µs)10932026/08/29 16:33:34 goose: up to current file version: 210942026/08/29 16:33:35 OK 20251218171726_add_pins.sql (37.8ms)10952026/08/29 16:33:35 OK 20260628120000_add_object_size_and_stats.sql (60.16ms)10962026/08/29 16:33:35 goose: successfully migrated database to version: 2026062812000010972026/08/29 16:33:35 OK 1_commit_pending_closure.sql (17.75ms)10982026/08/29 16:33:35 OK 2_object_stats_trigger.sql (869.04µs)10992026/08/29 16:33:35 goose: up to current file version: 211002026/08/29 16:33:35 INFO Received uploads request method=POST path=/api/pending_closures11012026/08/29 16:33:35 INFO Received uploads request method=POST path=/api/pending_closures1102--- PASS: TestReadRedirectUsesPublicS3URL (3.78s)1103=== CONT TestGCMetrics11042026-08-29 16:33:35.640 UTC [15361] ERROR: relation "goose_db_version" does not exist at character 3611052026-08-29 16:33:35.640 UTC [15361] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11062026/08/29 16:33:35 OK 20241026095416_initial_model.sql (240.74ms)11072026/08/29 16:33:35 OK 20251210153512_drop_unused_gin_index.sql (14.09ms)11082026/08/29 16:33:36 OK 20251218171726_add_pins.sql (53.42ms)11092026/08/29 16:33:36 OK 20260628120000_add_object_size_and_stats.sql (58.48ms)11102026/08/29 16:33:36 goose: successfully migrated database to version: 2026062812000011112026/08/29 16:33:36 OK 1_commit_pending_closure.sql (16.58ms)11122026/08/29 16:33:36 OK 2_object_stats_trigger.sql (1.08ms)11132026/08/29 16:33:36 goose: up to current file version: 211142026-08-29 16:33:36.225 UTC [15367] ERROR: relation "goose_db_version" does not exist at character 3611152026-08-29 16:33:36.225 UTC [15367] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11162026/08/29 16:33:36 WARN readiness check failed error="closed pool"1117--- PASS: TestService_readinessHandler (3.70s)1118=== CONT TestGCTaskStore_GetEmpty1119--- PASS: TestGCTaskStore_GetEmpty (0.00s)1120=== CONT TestGCTaskStore_ConflictDifferentParams1121--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1122=== CONT TestGCTaskStore_DeduplicateSameParams1123--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1124=== CONT TestGCTaskStore_StartNew1125--- PASS: TestGCTaskStore_StartNew (0.00s)1126=== CONT TestClientMultipleUploads11272026/08/29 16:33:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11282026/08/29 16:33:36 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NDdiYWJkNjQtZTQ5Ni00OTIyLWI3NjYtNWExZTc1NmEwYTUxLjk4NjRmZDg3LTk4ODctNGEwMC04MjQyLTcwMmIyN2U1YjhkYngxNzg4MDIxMjE0MTI4NzA3MDAw parts=1211292026/08/29 16:33:36 INFO Received uploads request method=POST path=/api/pending_closures1130--- PASS: TestCompletedNarNotReofferedAcrossClosures (5.59s)1131=== CONT TestReadProxyRootRedirectsToIndexHTML11322026/08/29 16:33:36 OK 20241026095416_initial_model.sql (292.76ms)11332026/08/29 16:33:36 OK 20251210153512_drop_unused_gin_index.sql (22.2ms)11342026/08/29 16:33:36 OK 20251218171726_add_pins.sql (70.74ms)11352026/08/29 16:33:36 OK 20260628120000_add_object_size_and_stats.sql (63.51ms)11362026/08/29 16:33:36 goose: successfully migrated database to version: 2026062812000011372026/08/29 16:33:36 OK 1_commit_pending_closure.sql (22.08ms)11382026/08/29 16:33:36 OK 2_object_stats_trigger.sql (1.04ms)11392026/08/29 16:33:36 goose: up to current file version: 21140--- PASS: TestService_healthCheckHandler (4.00s)1141=== CONT TestReadRedirectKeepsNarinfoProxied11422026-08-29 16:33:37.103 UTC [15372] ERROR: relation "goose_db_version" does not exist at character 3611432026-08-29 16:33:37.103 UTC [15372] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11442026-08-29 16:33:37.205 UTC [15375] ERROR: relation "goose_db_version" does not exist at character 3611452026-08-29 16:33:37.205 UTC [15375] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11462026/08/29 16:33:37 OK 20241026095416_initial_model.sql (188.89ms)11472026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (15.18ms)11482026/08/29 16:33:37 OK 20251218171726_add_pins.sql (13.84ms)11492026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (34.49ms)11502026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000011512026/08/29 16:33:37 OK 1_commit_pending_closure.sql (6.28ms)11522026/08/29 16:33:37 OK 2_object_stats_trigger.sql (957.42µs)11532026/08/29 16:33:37 goose: up to current file version: 211542026/08/29 16:33:37 OK 20241026095416_initial_model.sql (215.46ms)11552026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (14.52ms)11562026/08/29 16:33:37 OK 20251218171726_add_pins.sql (36.36ms)11572026/08/29 16:33:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11582026-08-29 16:33:37.553 UTC [15376] ERROR: relation "goose_db_version" does not exist at character 3611592026-08-29 16:33:37.553 UTC [15376] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11602026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (21.38ms)11612026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000011622026/08/29 16:33:37 OK 1_commit_pending_closure.sql (14.29ms)11632026/08/29 16:33:37 OK 2_object_stats_trigger.sql (735.25µs)11642026/08/29 16:33:37 goose: up to current file version: 211652026/08/29 16:33:37 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NDdiYWJkNjQtZTQ5Ni00OTIyLWI3NjYtNWExZTc1NmEwYTUxLmI4Zjk0YjAwLTAwZDctNDRmNS1iYTIxLTU4YzhmMzk2ZTAzNngxNzg4MDIxMjE1Mjc1Nzg5MDAw parts=121166--- PASS: TestRedundantMultipartUpload (5.94s)1167=== CONT TestReadRedirectNar11682026-08-29 16:33:37.730 UTC [15377] ERROR: relation "goose_db_version" does not exist at character 3611692026-08-29 16:33:37.730 UTC [15377] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11702026/08/29 16:33:37 OK 20241026095416_initial_model.sql (170.55ms)11712026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (7.19ms)11722026/08/29 16:33:37 OK 20251218171726_add_pins.sql (42.66ms)1173=== NAME TestClientIntegration1174 client_integration_test.go:277: Created store path: /nix/var/nix/builds/nix-15122-3527464599/TestClientIntegration1416374218/002/store/jcbcvf2cid453bwh9czs1skqrdw2lfck-test-file.txt11752026/08/29 16:33:37 OK 20260628120000_add_object_size_and_stats.sql (34.19ms)11762026/08/29 16:33:37 goose: successfully migrated database to version: 2026062812000011772026/08/29 16:33:37 OK 1_commit_pending_closure.sql (7.22ms)11782026/08/29 16:33:37 OK 2_object_stats_trigger.sql (275.54µs)11792026/08/29 16:33:37 goose: up to current file version: 211802026/08/29 16:33:37 OK 20241026095416_initial_model.sql (180.8ms)11812026/08/29 16:33:37 OK 20251210153512_drop_unused_gin_index.sql (12.59ms)11822026/08/29 16:33:37 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"11832026/08/29 16:33:38 OK 20251218171726_add_pins.sql (46.87ms)11842026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (32.21ms)11852026/08/29 16:33:38 goose: successfully migrated database to version: 2026062812000011862026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures11872026/08/29 16:33:38 OK 1_commit_pending_closure.sql (1.81ms)11882026/08/29 16:33:38 OK 2_object_stats_trigger.sql (281.79µs)11892026/08/29 16:33:38 goose: up to current file version: 21190--- PASS: TestGCBugBareHashReferences (4.15s)1191=== CONT TestReadProxyDisabled11922026/08/29 16:33:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11932026/08/29 16:33:38 INFO Uploading jcbcvf2cid453bwh9czs1skqrdw2lfck-test-file.txt (152B)11942026/08/29 16:33:38 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"11952026/08/29 16:33:38 WARN Failed to register uploaded object key=jcbcvf2cid453bwh9czs1skqrdw2lfck.ls error="server returned 404: 404 page not found\n"11962026/08/29 16:33:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11972026/08/29 16:33:38 INFO Signed narinfos id=1 count=111982026/08/29 16:33:38 INFO Uploading 1 narinfos11992026/08/29 16:33:38 WARN Failed to register uploaded object key=jcbcvf2cid453bwh9czs1skqrdw2lfck.narinfo error="server returned 404: 404 page not found\n"12002026/08/29 16:33:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12012026-08-29 16:33:38.263 UTC [15390] ERROR: relation "goose_db_version" does not exist at character 3612022026-08-29 16:33:38.263 UTC [15390] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12032026/08/29 16:33:38 INFO Completed upload id=112042026/08/29 16:33:38 INFO Upload complete. (354ms)1205=== NAME TestClientIntegration1206 client_integration_test.go:293: Retrieved narinfo from S3:1207 StorePath: /nix/var/nix/builds/nix-15122-3527464599/TestClientIntegration1416374218/002/store/jcbcvf2cid453bwh9czs1skqrdw2lfck-test-file.txt1208 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1209 Compression: zstd1210 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11211 NarSize: 1521212 References: 1213 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11214 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)1215 client_integration_test.go:294: Decompressed .ls content (64 bytes):1216 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1217 client_integration_test.go:297: Testing garbage collection...12182026/08/29 16:33:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures12192026/08/29 16:33:38 INFO Garbage collection started12202026/08/29 16:33:38 INFO Aborted multipart uploads count=012212026/08/29 16:33:38 WARN Force mode enabled - objects will be deleted immediately without grace period12222026/08/29 16:33:38 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=012232026/08/29 16:33:38 INFO Vacuumed table table=pending_closures12242026/08/29 16:33:38 OK 20241026095416_initial_model.sql (183.71ms)12252026/08/29 16:33:38 OK 20251210153512_drop_unused_gin_index.sql (15.33ms)12262026/08/29 16:33:38 INFO Vacuumed table table=pending_objects12272026/08/29 16:33:38 INFO Vacuumed table table=multipart_uploads12282026/08/29 16:33:38 INFO Vacuumed table table=closures12292026/08/29 16:33:38 OK 20251218171726_add_pins.sql (38.98ms)1230=== NAME TestPinProtectsFromGC1231 client_integration_test.go:648: Pinned store path: /nix/var/nix/builds/nix-15122-3527464599/TestPinProtectsFromGC1618653739/001/store/r0whqc3qfy1sn0y6dbvrcyw2hmrr38y7-pinned-file.txt1232 client_integration_test.go:649: Unpinned store path: /nix/var/nix/builds/nix-15122-3527464599/TestPinProtectsFromGC1618653739/001/store/xgnm3c868a401ab8ki9fwwzznkf63h22-unpinned-file.txt12332026/08/29 16:33:38 INFO Vacuumed table table=objects12342026/08/29 16:33:38 OK 20260628120000_add_object_size_and_stats.sql (33.31ms)12352026/08/29 16:33:38 goose: successfully migrated database to version: 2026062812000012362026/08/29 16:33:38 OK 1_commit_pending_closure.sql (9.3ms)12372026/08/29 16:33:38 OK 2_object_stats_trigger.sql (247.79µs)12382026/08/29 16:33:38 goose: up to current file version: 212392026/08/29 16:33:38 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12402026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures12412026/08/29 16:33:38 INFO Aborted multipart uploads count=012422026/08/29 16:33:38 WARN Force mode enabled - objects will be deleted immediately without grace period12432026/08/29 16:33:38 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=012442026/08/29 16:33:38 INFO Vacuumed table table=pending_closures12452026/08/29 16:33:38 INFO Vacuumed table table=pending_objects12462026/08/29 16:33:38 INFO Vacuumed table table=multipart_uploads12472026/08/29 16:33:38 INFO Vacuumed table table=closures12482026/08/29 16:33:38 INFO Vacuumed table table=objects1249--- PASS: TestGCMetrics (3.23s)1250=== CONT TestGCTaskStore_Fail1251--- PASS: TestGCTaskStore_Fail (0.00s)1252=== CONT TestGCTaskStore_PhaseUpdates1253--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1254=== CONT TestService_RequireScope_OIDC12552026/08/29 16:33:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12562026/08/29 16:33:38 INFO Uploading r0whqc3qfy1sn0y6dbvrcyw2hmrr38y7-pinned-file.txt (128B)12572026/08/29 16:33:38 INFO OIDC provider initialized name=test1258=== NAME TestClientWithDependencies1259 client_integration_test.go:594: Built derivation: /nix/var/nix/builds/nix-15122-3527464599/TestClientWithDependencies1613442086/001/store/s3jl3amq60881sp080fvad1g2hkmbd3c-test-script12602026/08/29 16:33:38 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"1261 client_integration_test.go:596: Found 1 dependencies (including self)12622026/08/29 16:33:38 WARN Failed to register uploaded object key=r0whqc3qfy1sn0y6dbvrcyw2hmrr38y7.ls error="server returned 404: 404 page not found\n"12632026/08/29 16:33:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12642026/08/29 16:33:38 INFO Signed narinfos id=1 count=112652026/08/29 16:33:38 INFO Uploading 1 narinfos12662026/08/29 16:33:38 WARN Failed to register uploaded object key=r0whqc3qfy1sn0y6dbvrcyw2hmrr38y7.narinfo error="server returned 404: 404 page not found\n"12672026/08/29 16:33:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12682026-08-29 16:33:38.920 UTC [15418] ERROR: relation "goose_db_version" does not exist at character 3612692026-08-29 16:33:38.920 UTC [15418] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12702026/08/29 16:33:38 INFO Completed upload id=112712026/08/29 16:33:38 INFO Upload complete. (332ms)12722026/08/29 16:33:38 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12732026/08/29 16:33:38 INFO Received uploads request method=POST path=/api/pending_closures12742026/08/29 16:33:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12752026/08/29 16:33:38 INFO Uploading s3jl3amq60881sp080fvad1g2hkmbd3c-test-script (136B)12762026/08/29 16:33:39 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12772026/08/29 16:33:39 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"12782026/08/29 16:33:39 WARN Failed to register uploaded object key=log/p9mqr3r5ciqky46axag771hi26irq4g7-test-script.drv error="server returned 404: 404 page not found\n"12792026/08/29 16:33:39 INFO Received uploads request method=POST path=/api/pending_closures12802026/08/29 16:33:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12812026/08/29 16:33:39 INFO Uploading xgnm3c868a401ab8ki9fwwzznkf63h22-unpinned-file.txt (128B)12822026/08/29 16:33:39 WARN Failed to register uploaded object key=s3jl3amq60881sp080fvad1g2hkmbd3c.ls error="server returned 404: 404 page not found\n"12832026/08/29 16:33:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12842026/08/29 16:33:39 INFO Signed narinfos id=1 count=112852026/08/29 16:33:39 INFO Uploading 1 narinfos12862026/08/29 16:33:39 WARN Failed to register uploaded object key=s3jl3amq60881sp080fvad1g2hkmbd3c.narinfo error="server returned 404: 404 page not found\n"12872026/08/29 16:33:39 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"12882026/08/29 16:33:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12892026-08-29 16:33:39.127 UTC [15429] ERROR: relation "goose_db_version" does not exist at character 3612902026-08-29 16:33:39.127 UTC [15429] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12912026/08/29 16:33:39 WARN Failed to register uploaded object key=xgnm3c868a401ab8ki9fwwzznkf63h22.ls error="server returned 404: 404 page not found\n"12922026/08/29 16:33:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12932026/08/29 16:33:39 INFO Signed narinfos id=2 count=112942026/08/29 16:33:39 INFO Uploading 1 narinfos12952026/08/29 16:33:39 INFO Completed upload id=112962026/08/29 16:33:39 INFO Upload complete. (258ms)1297 client_integration_test.go:598: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-15122-3527464599/TestClientWithDependencies1613442086/001/store) requires matching store prefix12982026/08/29 16:33:39 WARN Failed to register uploaded object key=xgnm3c868a401ab8ki9fwwzznkf63h22.narinfo error="server returned 404: 404 page not found\n"12992026/08/29 16:33:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13002026/08/29 16:33:39 INFO Completed upload id=213012026/08/29 16:33:39 INFO Upload complete. (235ms)13022026/08/29 16:33:39 OK 20241026095416_initial_model.sql (231.42ms)1303--- PASS: TestClientWithDependencies (4.48s)1304=== CONT TestClientErrorHandling1305=== RUN TestClientErrorHandling/InvalidStorePath1306=== PAUSE TestClientErrorHandling/InvalidStorePath1307=== RUN TestClientErrorHandling/InvalidAuthToken1308=== PAUSE TestClientErrorHandling/InvalidAuthToken1309=== RUN TestClientErrorHandling/ServerNotAvailable1310=== PAUSE TestClientErrorHandling/ServerNotAvailable1311=== CONT TestClientCADerivations13122026/08/29 16:33:39 OK 20251210153512_drop_unused_gin_index.sql (13.27ms)13132026/08/29 16:33:39 INFO Received create pin request method=POST path=/api/pins/myapp13142026/08/29 16:33:39 OK 20251218171726_add_pins.sql (27.44ms)13152026/08/29 16:33:39 OK 20260628120000_add_object_size_and_stats.sql (60.26ms)13162026/08/29 16:33:39 goose: successfully migrated database to version: 2026062812000013172026/08/29 16:33:39 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-15122-3527464599/TestPinProtectsFromGC1618653739/001/store/r0whqc3qfy1sn0y6dbvrcyw2hmrr38y7-pinned-file.txt narinfo_key=r0whqc3qfy1sn0y6dbvrcyw2hmrr38y7.narinfo13182026/08/29 16:33:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures13192026/08/29 16:33:39 INFO Garbage collection started13202026/08/29 16:33:39 INFO Aborted multipart uploads count=013212026/08/29 16:33:39 WARN Force mode enabled - objects will be deleted immediately without grace period13222026/08/29 16:33:39 OK 1_commit_pending_closure.sql (7.14ms)13232026/08/29 16:33:39 OK 2_object_stats_trigger.sql (300.04µs)13242026/08/29 16:33:39 goose: up to current file version: 213252026-08-29 16:33:39.405 UTC [15435] ERROR: relation "goose_db_version" does not exist at character 3613262026-08-29 16:33:39.405 UTC [15435] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13272026/08/29 16:33:39 OK 20241026095416_initial_model.sql (206.99ms)13282026/08/29 16:33:39 OK 20251210153512_drop_unused_gin_index.sql (9.29ms)13292026/08/29 16:33:39 OK 20251218171726_add_pins.sql (20.5ms)13302026/08/29 16:33:39 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=013312026/08/29 16:33:39 OK 20260628120000_add_object_size_and_stats.sql (34.89ms)13322026/08/29 16:33:39 goose: successfully migrated database to version: 2026062812000013332026/08/29 16:33:39 OK 1_commit_pending_closure.sql (5.83ms)13342026/08/29 16:33:39 OK 2_object_stats_trigger.sql (250.67µs)13352026/08/29 16:33:39 goose: up to current file version: 213362026/08/29 16:33:39 INFO Vacuumed table table=pending_closures13372026/08/29 16:33:39 INFO Vacuumed table table=pending_objects13382026/08/29 16:33:39 INFO Vacuumed table table=multipart_uploads13392026/08/29 16:33:39 INFO Vacuumed table table=closures13402026/08/29 16:33:39 INFO Vacuumed table table=objects13412026/08/29 16:33:39 OK 20241026095416_initial_model.sql (218.51ms)13422026/08/29 16:33:39 OK 20251210153512_drop_unused_gin_index.sql (14.2ms)1343--- PASS: TestReadProxyRootRedirectsToIndexHTML (3.24s)1344=== CONT TestCacheStatsHandler13452026/08/29 16:33:39 OK 20251218171726_add_pins.sql (36.81ms)13462026/08/29 16:33:39 OK 20260628120000_add_object_size_and_stats.sql (43.35ms)13472026/08/29 16:33:39 goose: successfully migrated database to version: 2026062812000013482026/08/29 16:33:39 OK 1_commit_pending_closure.sql (12.74ms)13492026/08/29 16:33:39 OK 2_object_stats_trigger.sql (396.33µs)13502026/08/29 16:33:39 goose: up to current file version: 21351=== NAME TestClientMultipleUploads1352 client_integration_test.go:339: Created store path 0: /nix/var/nix/builds/nix-15122-3527464599/TestClientMultipleUploads1506519466/001/store/j9v8wgmaml6x8jp69cxyzh47ws1cns2i-test-file-0.txt1353 client_integration_test.go:339: Created store path 1: /nix/var/nix/builds/nix-15122-3527464599/TestClientMultipleUploads1506519466/001/store/sxnz2s50fbll1xcc12210y408jkc3pim-test-file-1.txt1354--- PASS: TestReadRedirectKeepsNarinfoProxied (2.99s)1355=== CONT TestCacheConfigHandler1356=== RUN TestCacheConfigHandler/full_config,_no_issuer1357=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1358=== RUN TestCacheConfigHandler/no_cache_url_configured1359=== PAUSE TestCacheConfigHandler/no_cache_url_configured1360=== RUN TestCacheConfigHandler/no_signing_keys1361=== PAUSE TestCacheConfigHandler/no_signing_keys1362=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1363=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1364=== CONT TestService_ReadScope_PublicByDefault1365=== NAME TestClientMultipleUploads1366 client_integration_test.go:339: Created store path 2: /nix/var/nix/builds/nix-15122-3527464599/TestClientMultipleUploads1506519466/001/store/pgjwcv2h7kawksa8ymgd6ks1h7qn627q-test-file-2.txt13672026-08-29 16:33:40.129 UTC [15450] ERROR: relation "goose_db_version" does not exist at character 3613682026-08-29 16:33:40.129 UTC [15450] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13692026/08/29 16:33:40 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"13702026/08/29 16:33:40 INFO Received uploads request method=POST path=/api/pending_closures13712026/08/29 16:33:40 INFO Received uploads request method=POST path=/api/pending_closures13722026/08/29 16:33:40 INFO Received uploads request method=POST path=/api/pending_closures13732026/08/29 16:33:40 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)13742026/08/29 16:33:40 INFO Uploading pgjwcv2h7kawksa8ymgd6ks1h7qn627q-test-file-2.txt (160B)13752026/08/29 16:33:40 INFO Uploading j9v8wgmaml6x8jp69cxyzh47ws1cns2i-test-file-0.txt (160B)13762026/08/29 16:33:40 INFO Uploading sxnz2s50fbll1xcc12210y408jkc3pim-test-file-1.txt (160B)13772026/08/29 16:33:40 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01378=== NAME TestClientIntegration1379 client_integration_test.go:304: Objects in database after GC:1380 client_integration_test.go:304: Successfully deleted all objects with GC --force13812026/08/29 16:33:40 OK 20241026095416_initial_model.sql (176.27ms)13822026/08/29 16:33:40 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"13832026/08/29 16:33:40 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"13842026/08/29 16:33:40 OK 20251210153512_drop_unused_gin_index.sql (17.69ms)13852026/08/29 16:33:40 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"13862026/08/29 16:33:40 WARN Failed to register uploaded object key=pgjwcv2h7kawksa8ymgd6ks1h7qn627q.ls error="server returned 404: 404 page not found\n"13872026/08/29 16:33:40 WARN Failed to register uploaded object key=j9v8wgmaml6x8jp69cxyzh47ws1cns2i.ls error="server returned 404: 404 page not found\n"13882026/08/29 16:33:40 WARN Failed to register uploaded object key=sxnz2s50fbll1xcc12210y408jkc3pim.ls error="server returned 404: 404 page not found\n"13892026/08/29 16:33:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13902026/08/29 16:33:40 OK 20251218171726_add_pins.sql (73.34ms)13912026/08/29 16:33:40 INFO Signed narinfos id=1 count=113922026/08/29 16:33:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13932026/08/29 16:33:40 INFO Signed narinfos id=2 count=113942026/08/29 16:33:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign13952026/08/29 16:33:40 INFO Signed narinfos id=3 count=113962026/08/29 16:33:40 INFO Uploading 3 narinfos13972026-08-29 16:33:40.450 UTC [15454] ERROR: relation "goose_db_version" does not exist at character 3613982026-08-29 16:33:40.450 UTC [15454] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1399--- PASS: TestClientIntegration (6.77s)1400=== CONT TestMultipartCleanup14012026/08/29 16:33:40 OK 20260628120000_add_object_size_and_stats.sql (47.13ms)14022026/08/29 16:33:40 goose: successfully migrated database to version: 2026062812000014032026/08/29 16:33:40 WARN Failed to register uploaded object key=pgjwcv2h7kawksa8ymgd6ks1h7qn627q.narinfo error="server returned 404: 404 page not found\n"14042026/08/29 16:33:40 WARN Failed to register uploaded object key=sxnz2s50fbll1xcc12210y408jkc3pim.narinfo error="server returned 404: 404 page not found\n"14052026/08/29 16:33:40 WARN Failed to register uploaded object key=j9v8wgmaml6x8jp69cxyzh47ws1cns2i.narinfo error="server returned 404: 404 page not found\n"14062026/08/29 16:33:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14072026/08/29 16:33:40 OK 1_commit_pending_closure.sql (13.21ms)14082026/08/29 16:33:40 OK 2_object_stats_trigger.sql (531.79µs)14092026/08/29 16:33:40 goose: up to current file version: 214102026/08/29 16:33:40 INFO Completed upload id=114112026/08/29 16:33:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14122026/08/29 16:33:40 INFO Completed upload id=214132026/08/29 16:33:40 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete14142026/08/29 16:33:40 INFO Completed upload id=314152026/08/29 16:33:40 INFO Upload complete. (448ms)1416=== NAME TestClientMultipleUploads1417 client_integration_test.go:350: Uploaded 3 paths in 482.402541ms1418--- PASS: TestClientMultipleUploads (4.39s)1419=== CONT TestReadProxyHead1420--- PASS: TestReadRedirectNar (3.10s)1421=== CONT TestReadProxyConditionalGet14222026/08/29 16:33:40 OK 20241026095416_initial_model.sql (268.12ms)14232026/08/29 16:33:40 OK 20251210153512_drop_unused_gin_index.sql (9.06ms)14242026/08/29 16:33:40 OK 20251218171726_add_pins.sql (41.11ms)14252026/08/29 16:33:40 OK 20260628120000_add_object_size_and_stats.sql (29.98ms)14262026/08/29 16:33:40 goose: successfully migrated database to version: 2026062812000014272026/08/29 16:33:40 OK 1_commit_pending_closure.sql (16.31ms)14282026/08/29 16:33:40 OK 2_object_stats_trigger.sql (930.5µs)14292026/08/29 16:33:40 goose: up to current file version: 21430--- PASS: TestReadProxyDisabled (3.07s)1431=== CONT TestService_createPendingClosureHandler14322026/08/29 16:33:41 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01433=== NAME TestPinProtectsFromGC1434 client_integration_test.go:711: Pin successfully protected closure from garbage collection1435--- PASS: TestPinProtectsFromGC (6.88s)1436=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14372026-08-29 16:33:41.489 UTC [15465] ERROR: relation "goose_db_version" does not exist at character 3614382026-08-29 16:33:41.489 UTC [15465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14392026-08-29 16:33:41.584 UTC [15466] ERROR: relation "goose_db_version" does not exist at character 3614402026-08-29 16:33:41.584 UTC [15466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14412026/08/29 16:33:41 OK 20241026095416_initial_model.sql (196.38ms)14422026/08/29 16:33:41 OK 20251210153512_drop_unused_gin_index.sql (13.81ms)14432026/08/29 16:33:41 OK 20251218171726_add_pins.sql (43.27ms)14442026/08/29 16:33:41 OK 20260628120000_add_object_size_and_stats.sql (51.38ms)14452026/08/29 16:33:41 goose: successfully migrated database to version: 2026062812000014462026/08/29 16:33:41 OK 1_commit_pending_closure.sql (14.59ms)14472026/08/29 16:33:41 OK 2_object_stats_trigger.sql (1.14ms)14482026/08/29 16:33:41 goose: up to current file version: 214492026/08/29 16:33:41 OK 20241026095416_initial_model.sql (262.56ms)14502026/08/29 16:33:41 OK 20251210153512_drop_unused_gin_index.sql (30.54ms)14512026/08/29 16:33:42 OK 20251218171726_add_pins.sql (72.94ms)14522026/08/29 16:33:42 OK 20260628120000_add_object_size_and_stats.sql (97.81ms)14532026/08/29 16:33:42 goose: successfully migrated database to version: 2026062812000014542026/08/29 16:33:42 OK 1_commit_pending_closure.sql (18.98ms)14552026/08/29 16:33:42 OK 2_object_stats_trigger.sql (1.09ms)14562026/08/29 16:33:42 goose: up to current file version: 21457=== RUN TestService_RequireScope_OIDC/builder_may_write1458=== PAUSE TestService_RequireScope_OIDC/builder_may_write1459=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1460=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1461=== RUN TestService_RequireScope_OIDC/ops_may_admin1462=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1463=== RUN TestService_RequireScope_OIDC/ops_may_not_write1464=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1465=== RUN TestService_RequireScope_OIDC/reader_may_not_write1466=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1467=== RUN TestService_RequireScope_OIDC/static_token_may_admin1468=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1469=== RUN TestService_RequireScope_OIDC/static_token_may_write1470=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1471=== RUN TestService_RequireScope_OIDC/reader_may_read1472=== PAUSE TestService_RequireScope_OIDC/reader_may_read1473=== RUN TestService_RequireScope_OIDC/writer_implies_read1474=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1475=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1476=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1477=== CONT TestService_AuthMiddleware_OIDC14782026/08/29 16:33:42 INFO OIDC provider initialized name=test14792026-08-29 16:33:42.596 UTC [15470] ERROR: relation "goose_db_version" does not exist at character 3614802026-08-29 16:33:42.596 UTC [15470] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14812026-08-29 16:33:42.714 UTC [15472] ERROR: relation "goose_db_version" does not exist at character 3614822026-08-29 16:33:42.714 UTC [15472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1483=== NAME TestOrphanedObjectsGCStressTest1484 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains14852026/08/29 16:33:42 OK 20241026095416_initial_model.sql (133.09ms)14862026/08/29 16:33:42 OK 20251210153512_drop_unused_gin_index.sql (538.25µs)14872026/08/29 16:33:42 OK 20251218171726_add_pins.sql (987µs)14882026-08-29 16:33:42.789 UTC [15476] ERROR: relation "goose_db_version" does not exist at character 3614892026-08-29 16:33:42.789 UTC [15476] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14902026/08/29 16:33:42 OK 20260628120000_add_object_size_and_stats.sql (43.43ms)14912026/08/29 16:33:42 goose: successfully migrated database to version: 2026062812000014922026/08/29 16:33:42 OK 1_commit_pending_closure.sql (1.66ms)14932026/08/29 16:33:42 OK 2_object_stats_trigger.sql (224.25µs)14942026/08/29 16:33:42 goose: up to current file version: 214952026/08/29 16:33:42 OK 20241026095416_initial_model.sql (96.28ms)14962026/08/29 16:33:42 OK 20251210153512_drop_unused_gin_index.sql (6.76ms)1497 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion14982026/08/29 16:33:42 OK 20251218171726_add_pins.sql (9.69ms)14992026/08/29 16:33:42 OK 20260628120000_add_object_size_and_stats.sql (20.12ms)15002026/08/29 16:33:42 goose: successfully migrated database to version: 2026062812000015012026/08/29 16:33:42 OK 1_commit_pending_closure.sql (1.13ms)15022026/08/29 16:33:42 OK 2_object_stats_trigger.sql (872.54µs)15032026/08/29 16:33:42 goose: up to current file version: 215042026-08-29 16:33:42.923 UTC [15477] ERROR: relation "goose_db_version" does not exist at character 3615052026-08-29 16:33:42.923 UTC [15477] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15062026/08/29 16:33:42 OK 20241026095416_initial_model.sql (59.66ms)1507=== NAME TestClientCADerivations1508 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-15122-3527464599/TestClientCADerivations2199755701/001/store/m9im60frgwyyjn9xrmvhwwpr38gmszmr-ca-test15092026/08/29 16:33:42 OK 20251210153512_drop_unused_gin_index.sql (8.05ms)15102026/08/29 16:33:42 OK 20251218171726_add_pins.sql (17.32ms)1511 client_ca_test.go:139: Found 1 dependencies (including self)15122026/08/29 16:33:42 OK 20260628120000_add_object_size_and_stats.sql (17.78ms)15132026/08/29 16:33:42 goose: successfully migrated database to version: 2026062812000015142026/08/29 16:33:42 OK 1_commit_pending_closure.sql (1.4ms)15152026/08/29 16:33:42 OK 2_object_stats_trigger.sql (355.04µs)15162026/08/29 16:33:42 goose: up to current file version: 215172026-08-29 16:33:42.985 UTC [15481] ERROR: relation "goose_db_version" does not exist at character 3615182026-08-29 16:33:42.985 UTC [15481] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1519--- PASS: TestCacheStatsHandler (3.27s)1520=== CONT TestService_ReadAuthMiddleware15212026/08/29 16:33:43 OK 20241026095416_initial_model.sql (60.59ms)15222026/08/29 16:33:43 OK 20251210153512_drop_unused_gin_index.sql (1.36ms)15232026/08/29 16:33:43 OK 20251218171726_add_pins.sql (14.37ms)15242026/08/29 16:33:43 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1525--- PASS: TestService_ReadScope_PublicByDefault (3.01s)1526=== CONT TestService_AuthMiddleware_MTLSProxyHeader15272026/08/29 16:33:43 OK 20260628120000_add_object_size_and_stats.sql (20.44ms)15282026/08/29 16:33:43 goose: successfully migrated database to version: 2026062812000015292026/08/29 16:33:43 OK 1_commit_pending_closure.sql (2.01ms)15302026/08/29 16:33:43 OK 2_object_stats_trigger.sql (326.75µs)15312026/08/29 16:33:43 goose: up to current file version: 215322026/08/29 16:33:43 OK 20241026095416_initial_model.sql (64.8ms)15332026/08/29 16:33:43 OK 20251210153512_drop_unused_gin_index.sql (9.14ms)15342026/08/29 16:33:43 INFO Received uploads request method=POST path=/api/pending_closures15352026/08/29 16:33:43 OK 20251218171726_add_pins.sql (19.7ms)15362026/08/29 16:33:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15372026/08/29 16:33:43 INFO Uploading m9im60frgwyyjn9xrmvhwwpr38gmszmr-ca-test (144B)15382026/08/29 16:33:43 OK 20260628120000_add_object_size_and_stats.sql (14.21ms)15392026/08/29 16:33:43 goose: successfully migrated database to version: 2026062812000015402026/08/29 16:33:43 OK 1_commit_pending_closure.sql (1.49ms)15412026/08/29 16:33:43 OK 2_object_stats_trigger.sql (228.83µs)15422026/08/29 16:33:43 goose: up to current file version: 215432026/08/29 16:33:43 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"15442026/08/29 16:33:43 WARN Failed to register uploaded object key=log/f62bc0rpnszw3wh7kb62y0w43pz591w7-ca-test.drv error="server returned 404: 404 page not found\n"15452026-08-29 16:33:43.187 UTC [15491] ERROR: relation "goose_db_version" does not exist at character 3615462026-08-29 16:33:43.187 UTC [15491] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15472026/08/29 16:33:43 WARN Failed to register uploaded object key=m9im60frgwyyjn9xrmvhwwpr38gmszmr.ls error="server returned 404: 404 page not found\n"15482026/08/29 16:33:43 INFO Received uploads request method=POST path=/api/pending_closures15492026/08/29 16:33:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15502026/08/29 16:33:43 INFO Signed narinfos id=1 count=115512026/08/29 16:33:43 INFO Uploading 1 narinfos15522026/08/29 16:33:43 WARN Failed to register uploaded object key=m9im60frgwyyjn9xrmvhwwpr38gmszmr.narinfo error="server returned 404: 404 page not found\n"15532026/08/29 16:33:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15542026/08/29 16:33:43 INFO Completed upload id=115552026/08/29 16:33:43 INFO Upload complete. (255ms)1556=== NAME TestClientCADerivations1557 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-15122-3527464599/TestClientCADerivations2199755701/001/store/m9im60frgwyyjn9xrmvhwwpr38gmszmr-ca-test1558 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1559 Compression: zstd1560 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1561 NarSize: 1441562 References: 1563 Deriver: /nix/var/nix/builds/nix-15122-3527464599/TestClientCADerivations2199755701/001/store/f62bc0rpnszw3wh7kb62y0w43pz591w7-ca-test.drv1564 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1565 client_ca_test.go:185: Checking for realisation files in S3...1566 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1567 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache15682026-08-29 16:33:43.273 UTC [15492] ERROR: relation "goose_db_version" does not exist at character 3615692026-08-29 16:33:43.273 UTC [15492] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15702026/08/29 16:33:43 OK 20241026095416_initial_model.sql (80.13ms)15712026/08/29 16:33:43 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)1572 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket38?endpoint=http://localhost:56427®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-15122-3527464599/TestClientCADerivations2199755701/001/store'1573 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 115742026/08/29 16:33:43 OK 20251218171726_add_pins.sql (27.21ms)1575--- PASS: TestReadProxyHead (2.61s)1576=== CONT TestService_cleanupPendingClosuresHandler15772026/08/29 16:33:43 INFO Received cleanup request method=DELETE path=/api/pending_closures15782026/08/29 16:33:43 OK 20260628120000_add_object_size_and_stats.sql (15.49ms)15792026/08/29 16:33:43 goose: successfully migrated database to version: 2026062812000015802026/08/29 16:33:43 INFO Aborted multipart uploads count=115812026/08/29 16:33:43 OK 1_commit_pending_closure.sql (2.7ms)15822026/08/29 16:33:43 OK 2_object_stats_trigger.sql (220.71µs)15832026/08/29 16:33:43 goose: up to current file version: 21584--- PASS: TestMultipartCleanup (2.90s)1585=== CONT TestObjectStatsTrigger15862026/08/29 16:33:43 OK 20241026095416_initial_model.sql (81.44ms)1587--- PASS: TestClientCADerivations (4.17s)1588=== CONT TestServerTLSConfig/no_client_CA1589=== CONT TestServerTLSConfig/not_a_PEM_file15902026/08/29 16:33:43 OK 20251210153512_drop_unused_gin_index.sql (7.35ms)1591=== CONT TestServerTLSConfig/missing_CA_file1592--- PASS: TestServerTLSConfig (0.03s)1593 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1594 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1595 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1596=== CONT TestProxyWriteTimeout/narinfo1597=== CONT TestProxyWriteTimeout/unknown_size1598=== CONT TestProxyWriteTimeout/10_GiB_nar1599=== CONT TestProxyWriteTimeout/1_GiB_nar1600--- PASS: TestProxyWriteTimeout (0.03s)1601 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1602 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1603 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1604 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1605=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16062026/08/29 16:33:43 INFO Received uploads request method=POST path=/1607=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16082026/08/29 16:33:43 INFO Received request for more parts method=POST path=/1609=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16102026/08/29 16:33:43 INFO Received complete multipart upload request method=POST path=/1611=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16122026/08/29 16:33:43 INFO Received uploads request method=POST path=/1613--- PASS: TestUploadHandlersRejectInvalidKeys (0.03s)1614 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1615 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1616 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1617 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1618=== CONT TestIsValidUploadKey/narinfo1619=== CONT TestIsValidUploadKey/realisation_plus_in_output1620=== CONT TestIsValidUploadKey/unknown_type1621=== CONT TestIsValidUploadKey/empty_key1622=== CONT TestIsValidUploadKey/absolute1623=== CONT TestIsValidUploadKey/traversal_nar1624=== CONT TestIsValidUploadKey/traversal1625=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1626=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1627=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1628=== CONT TestIsValidUploadKey/index.html1629=== CONT TestIsValidUploadKey/nix-cache-info1630=== CONT TestIsValidUploadKey/build_log_home-manager_file1631=== CONT TestIsValidUploadKey/realisation1632=== CONT TestIsValidUploadKey/build_log_equals1633=== CONT TestIsValidUploadKey/build_log_question_mark1634=== CONT TestIsValidUploadKey/build_log_plus_in_name1635=== CONT TestIsValidUploadKey/nar_plain1636=== CONT TestIsValidUploadKey/build_log1637=== CONT TestIsValidUploadKey/listing1638=== CONT TestIsValidUploadKey/nar_xz1639=== CONT TestIsValidUploadKey/nar_zst1640--- PASS: TestIsValidUploadKey (0.03s)1641 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1642 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1643 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1644 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1645 --- PASS: TestIsValidUploadKey/absolute (0.00s)1646 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1647 --- PASS: TestIsValidUploadKey/traversal (0.00s)1648 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1649 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1650 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1651 --- PASS: TestIsValidUploadKey/index.html (0.00s)1652 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1653 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1654 --- PASS: TestIsValidUploadKey/realisation (0.00s)1655 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1656 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1657 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1658 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1659 --- PASS: TestIsValidUploadKey/build_log (0.00s)1660 --- PASS: TestIsValidUploadKey/listing (0.00s)1661 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1662 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1663=== CONT TestParseSingleRange/none16642026/08/29 16:33:43 OK 20251218171726_add_pins.sql (6.18ms)1665=== CONT TestParseSingleRange/open-ended1666=== CONT TestParseSingleRange/start_far_past_EOF1667=== CONT TestParseSingleRange/start_past_EOF1668=== CONT TestParseSingleRange/single_byte1669=== CONT TestParseSingleRange/suffix_exceeds_size1670=== CONT TestParseSingleRange/suffix1671=== CONT TestParseSingleRange/end_clamped_to_size1672=== CONT TestParseSingleRange/malformed_both_empty1673=== CONT TestParseSingleRange/closed1674=== CONT TestParseSingleRange/malformed_end_before_start1675=== CONT TestParseSingleRange/multi-range_ignored1676=== CONT TestParseSingleRange/malformed_no_dash1677=== CONT TestParseSingleRange/unknown_unit1678--- PASS: TestParseSingleRange (0.00s)1679 --- PASS: TestParseSingleRange/none (0.00s)1680 --- PASS: TestParseSingleRange/open-ended (0.00s)1681 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1682 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1683 --- PASS: TestParseSingleRange/single_byte (0.00s)1684 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1685 --- PASS: TestParseSingleRange/suffix (0.00s)1686 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1687 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1688 --- PASS: TestParseSingleRange/closed (0.00s)1689 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1690 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1691 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1692 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1693=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16942026/08/29 16:33:43 INFO Received complete multipart upload request method=POST path=/1695=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16962026/08/29 16:33:43 INFO Received uploads request method=POST path=/16972026/08/29 16:33:43 OK 20260628120000_add_object_size_and_stats.sql (25.77ms)16982026/08/29 16:33:43 goose: successfully migrated database to version: 2026062812000016992026/08/29 16:33:43 OK 1_commit_pending_closure.sql (6.59ms)17002026/08/29 16:33:43 OK 2_object_stats_trigger.sql (495.33µs)17012026/08/29 16:33:43 goose: up to current file version: 21702--- PASS: TestReadProxyConditionalGet (2.67s)1703=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17042026/08/29 16:33:43 INFO Received request for more parts method=POST path=/1705=== CONT TestIsValidCachePath/narinfo1706=== CONT TestIsValidCachePath/index.html1707=== CONT TestIsValidCachePath/short_hash1708=== CONT TestIsValidCachePath/wrong_extension1709=== CONT TestIsValidCachePath/leading_slash1710=== CONT TestIsValidCachePath/empty1711=== CONT TestIsValidCachePath/random_path1712=== CONT TestIsValidCachePath/invalid_char_u1713=== CONT TestIsValidCachePath/invalid_char_e1714=== CONT TestIsValidCachePath/traversal_parent1715=== CONT TestIsValidCachePath/nar_uncompressed1716=== CONT TestIsValidCachePath/nix-cache-info1717=== CONT TestIsValidCachePath/realisation1718=== CONT TestIsValidCachePath/traversal_in_middle1719=== CONT TestIsValidCachePath/log1720=== CONT TestIsValidCachePath/ls1721=== CONT TestIsValidCachePath/nar_xz1722=== CONT TestIsValidCachePath/nar_bz21723=== CONT TestIsValidCachePath/nar_zst1724=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1725--- PASS: TestIsValidCachePath (0.00s)1726 --- PASS: TestIsValidCachePath/narinfo (0.00s)1727 --- PASS: TestIsValidCachePath/index.html (0.00s)1728 --- PASS: TestIsValidCachePath/short_hash (0.00s)1729 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1730 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1731 --- PASS: TestIsValidCachePath/empty (0.00s)1732 --- PASS: TestIsValidCachePath/random_path (0.00s)1733 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1734 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1735 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1736 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1737 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1738 --- PASS: TestIsValidCachePath/realisation (0.00s)1739 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1740 --- PASS: TestIsValidCachePath/log (0.00s)1741 --- PASS: TestIsValidCachePath/ls (0.00s)1742 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1743 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1744 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1745 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1746=== CONT TestResolveDBConnectionString/flag_wins1747=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1748=== CONT TestResolveDBConnectionString/nothing_configured1749=== CONT TestResolveDBConnectionString/missing_file_is_an_error1750=== CONT TestResolveDBConnectionString/file_when_flag_empty1751=== CONT TestClientErrorHandling/InvalidStorePath1752--- PASS: TestResolveDBConnectionString (0.02s)1753 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1754 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1755 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1756 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1757 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)17582026/08/29 16:33:43 INFO Received uploads request method=POST path=/api/pending_closures17592026/08/29 16:33:43 INFO Received uploads request method=POST path=/api/pending_closures17602026/08/29 16:33:43 INFO Received uploads request method=POST path=/api/pending_closures17612026-08-29 16:33:43.521 UTC [15501] ERROR: relation "goose_db_version" does not exist at character 3617622026-08-29 16:33:43.521 UTC [15501] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17632026/08/29 16:33:43 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17642026/08/29 16:33:43 WARN mTLS auth: bound subjects configured but subject DN unavailable17652026/08/29 16:33:43 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1766--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.21s)1767=== CONT TestClientErrorHandling/ServerNotAvailable17682026/08/29 16:33:43 OK 20241026095416_initial_model.sql (77.03ms)17692026/08/29 16:33:43 OK 20251210153512_drop_unused_gin_index.sql (969.71µs)17702026/08/29 16:33:43 OK 20251218171726_add_pins.sql (2.63ms)17712026/08/29 16:33:43 OK 20260628120000_add_object_size_and_stats.sql (2.94ms)17722026/08/29 16:33:43 goose: successfully migrated database to version: 2026062812000017732026/08/29 16:33:43 OK 1_commit_pending_closure.sql (1.17ms)17742026/08/29 16:33:43 OK 2_object_stats_trigger.sql (392.71µs)17752026/08/29 16:33:43 goose: up to current file version: 21776=== CONT TestClientErrorHandling/InvalidAuthToken1777--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)1778 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1779 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1780 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)1781=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1782=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1783=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1784=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1785=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1786=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1787=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1788=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1789=== CONT TestCacheConfigHandler/full_config,_no_issuer1790=== CONT TestCacheConfigHandler/no_signing_keys1791=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1792=== CONT TestCacheConfigHandler/no_cache_url_configured1793--- PASS: TestCacheConfigHandler (0.00s)1794 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1795 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1796 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1797 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1798=== CONT TestService_RequireScope_OIDC/builder_may_write17992026/08/29 16:33:43 INFO OIDC auth successful provider=test scopes=[write]1800=== CONT TestService_RequireScope_OIDC/static_token_may_admin1801=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1802=== CONT TestService_RequireScope_OIDC/writer_implies_read18032026/08/29 16:33:43 INFO OIDC auth successful provider=test scopes=[write]1804=== CONT TestService_RequireScope_OIDC/reader_may_read18052026/08/29 16:33:43 INFO OIDC auth successful provider=test scopes=[read]1806=== CONT TestService_RequireScope_OIDC/static_token_may_write1807=== CONT TestService_RequireScope_OIDC/ops_may_not_write18082026/08/29 16:33:43 INFO OIDC auth successful provider=test scopes=[admin]1809=== CONT TestService_RequireScope_OIDC/reader_may_not_write18102026/08/29 16:33:43 INFO OIDC auth successful provider=test scopes=[read]1811=== CONT TestService_RequireScope_OIDC/ops_may_admin18122026/08/29 16:33:43 INFO OIDC auth successful provider=test scopes=[admin]1813=== CONT TestService_RequireScope_OIDC/builder_may_not_admin18142026/08/29 16:33:43 INFO OIDC auth successful provider=test scopes=[write]1815=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token18162026/08/29 16:33:43 INFO OIDC auth successful provider=test scopes=[write]1817=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18182026/08/29 16:33:43 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]1819=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1820=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18212026/08/29 16:33:43 WARN Authentication failed token_preview=eyJhbGciOi...vUhMSaOGqQ token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1822--- PASS: TestService_RequireScope_OIDC (3.44s)1823 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1824 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1825 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1826 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1827 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1828 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1829 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1830 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1831 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1832 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1833--- PASS: TestService_AuthMiddleware_OIDC (1.62s)1834 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1835 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1836 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1837 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)18382026-08-29 16:33:43.869 UTC [15508] ERROR: relation "goose_db_version" does not exist at character 3618392026-08-29 16:33:43.869 UTC [15508] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18402026/08/29 16:33:43 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-config18412026/08/29 16:33:43 OK 20241026095416_initial_model.sql (33.54ms)18422026-08-29 16:33:43.941 UTC [15511] ERROR: relation "goose_db_version" does not exist at character 3618432026-08-29 16:33:43.941 UTC [15511] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18442026/08/29 16:33:43 OK 20251210153512_drop_unused_gin_index.sql (444.17µs)18452026/08/29 16:33:43 OK 20251218171726_add_pins.sql (1.2ms)18462026/08/29 16:33:43 OK 20260628120000_add_object_size_and_stats.sql (4.64ms)18472026/08/29 16:33:43 goose: successfully migrated database to version: 2026062812000018482026/08/29 16:33:43 OK 1_commit_pending_closure.sql (843.42µs)18492026/08/29 16:33:43 OK 2_object_stats_trigger.sql (226.04µs)18502026/08/29 16:33:43 goose: up to current file version: 218512026/08/29 16:33:44 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=205.031427ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1852--- PASS: TestService_ReadAuthMiddleware (1.07s)18532026/08/29 16:33:44 OK 20241026095416_initial_model.sql (106.94ms)18542026/08/29 16:33:44 OK 20251210153512_drop_unused_gin_index.sql (12.68ms)18552026/08/29 16:33:44 OK 20251218171726_add_pins.sql (17.88ms)18562026/08/29 16:33:44 OK 20260628120000_add_object_size_and_stats.sql (17.56ms)18572026/08/29 16:33:44 goose: successfully migrated database to version: 2026062812000018582026/08/29 16:33:44 OK 1_commit_pending_closure.sql (8.08ms)18592026/08/29 16:33:44 OK 2_object_stats_trigger.sql (308.08µs)18602026/08/29 16:33:44 goose: up to current file version: 218612026/08/29 16:33:44 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=368.005143ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config1862--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.22s)18632026-08-29 16:33:44.493 UTC [15512] ERROR: relation "goose_db_version" does not exist at character 3618642026-08-29 16:33:44.493 UTC [15512] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18652026-08-29 16:33:44.548 UTC [15513] ERROR: relation "goose_db_version" does not exist at character 3618662026-08-29 16:33:44.548 UTC [15513] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18672026-08-29 16:33:44.553 UTC [15514] ERROR: relation "goose_db_version" does not exist at character 3618682026-08-29 16:33:44.553 UTC [15514] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18692026/08/29 16:33:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18702026/08/29 16:33:44 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=871.060423ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config18712026/08/29 16:33:44 OK 20241026095416_initial_model.sql (46.44ms)18722026/08/29 16:33:44 OK 20251210153512_drop_unused_gin_index.sql (15.49ms)18732026/08/29 16:33:44 OK 20251218171726_add_pins.sql (26.63ms)18742026/08/29 16:33:44 OK 20260628120000_add_object_size_and_stats.sql (19.89ms)18752026/08/29 16:33:44 goose: successfully migrated database to version: 2026062812000018762026/08/29 16:33:44 OK 20241026095416_initial_model.sql (93.19ms)18772026/08/29 16:33:44 OK 20241026095416_initial_model.sql (93.33ms)18782026/08/29 16:33:44 OK 1_commit_pending_closure.sql (4.83ms)18792026/08/29 16:33:44 OK 2_object_stats_trigger.sql (1.38ms)18802026/08/29 16:33:44 goose: up to current file version: 218812026/08/29 16:33:44 OK 20251210153512_drop_unused_gin_index.sql (8.8ms)18822026/08/29 16:33:44 OK 20251210153512_drop_unused_gin_index.sql (9.15ms)18832026/08/29 16:33:44 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NDdiYWJkNjQtZTQ5Ni00OTIyLWI3NjYtNWExZTc1NmEwYTUxLjk3MzQwN2UzLTg4YzUtNDMwOC1hYTRkLTk0MDdmOTUyNjA4OXgxNzg4MDIxMjIzNTMxMzgzMDAw parts=1018842026/08/29 16:33:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18852026/08/29 16:33:44 INFO Completed upload id=118862026/08/29 16:33:44 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000018872026/08/29 16:33:44 INFO Received uploads request method=POST path=/api/pending_closures18882026/08/29 16:33:44 INFO Starting cleanup of old closures method=DELETE path=/api/closures18892026/08/29 16:33:44 INFO Aborted multipart uploads count=018902026/08/29 16:33:44 OK 20251218171726_add_pins.sql (34.22ms)18912026/08/29 16:33:44 OK 20251218171726_add_pins.sql (34.22ms)18922026/08/29 16:33:44 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=018932026/08/29 16:33:44 INFO Vacuumed table table=pending_closures18942026/08/29 16:33:44 OK 20260628120000_add_object_size_and_stats.sql (27.63ms)18952026/08/29 16:33:44 goose: successfully migrated database to version: 2026062812000018962026/08/29 16:33:44 OK 20260628120000_add_object_size_and_stats.sql (27.61ms)18972026/08/29 16:33:44 goose: successfully migrated database to version: 2026062812000018982026/08/29 16:33:44 OK 1_commit_pending_closure.sql (10.05ms)18992026/08/29 16:33:44 OK 1_commit_pending_closure.sql (9.99ms)19002026/08/29 16:33:44 OK 2_object_stats_trigger.sql (678.83µs)19012026/08/29 16:33:44 goose: up to current file version: 219022026/08/29 16:33:44 OK 2_object_stats_trigger.sql (685.88µs)19032026/08/29 16:33:44 goose: up to current file version: 219042026/08/29 16:33:44 INFO Vacuumed table table=pending_objects19052026/08/29 16:33:44 INFO Vacuumed table table=multipart_uploads19062026/08/29 16:33:44 INFO Vacuumed table table=closures19072026/08/29 16:33:44 INFO Vacuumed table table=objects19082026/08/29 16:33:44 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001909--- PASS: TestService_createPendingClosureHandler (3.71s)1910--- PASS: TestObjectStatsTrigger (1.55s)19112026-08-29 16:33:45.067 UTC [15516] ERROR: relation "goose_db_version" does not exist at character 3619122026-08-29 16:33:45.067 UTC [15516] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1913=== NAME TestOrphanedObjectsGCStressTest1914 orphaned_objects_gc_test.go:509: Stress test completed successfully:1915 orphaned_objects_gc_test.go:510: - Active objects preserved: 201916 orphaned_objects_gc_test.go:511: - Objects deleted: 2101917 orphaned_objects_gc_test.go:512: - Total GC'd: 2101918--- PASS: TestOrphanedObjectsGCStressTest (15.85s)19192026/08/29 16:33:45 INFO Received cleanup request method=DELETE path=/api/pending_closures19202026/08/29 16:33:45 INFO Aborted multipart uploads count=019212026/08/29 16:33:45 INFO Received uploads request method=POST path=/api/pending_closures19222026/08/29 16:33:45 INFO Received cleanup request method=DELETE path=/api/pending_closures19232026/08/29 16:33:45 OK 20241026095416_initial_model.sql (90.8ms)19242026/08/29 16:33:45 INFO Aborted multipart uploads count=119252026/08/29 16:33:45 OK 20251210153512_drop_unused_gin_index.sql (762.04µs)19262026/08/29 16:33:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19272026-08-29 16:33:45.207 UTC [15514] ERROR: Closure does not exist: id=119282026-08-29 16:33:45.207 UTC [15514] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE19292026-08-29 16:33:45.207 UTC [15514] STATEMENT: -- name: CommitPendingClosure :exec1930 SELECT commit_pending_closure($1::bigint)1931 1932--- PASS: TestService_cleanupPendingClosuresHandler (1.87s)19332026/08/29 16:33:45 OK 20251218171726_add_pins.sql (1.51ms)19342026/08/29 16:33:45 OK 20260628120000_add_object_size_and_stats.sql (1.72ms)19352026/08/29 16:33:45 goose: successfully migrated database to version: 2026062812000019362026/08/29 16:33:45 OK 1_commit_pending_closure.sql (1.79ms)19372026/08/29 16:33:45 OK 2_object_stats_trigger.sql (371.46µs)19382026/08/29 16:33:45 goose: up to current file version: 219392026/08/29 16:33:45 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.719594063s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19402026/08/29 16:33:45 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19412026/08/29 16:33:45 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19422026/08/29 16:33:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"19432026/08/29 16:33:47 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_closures19442026/08/29 16:33:47 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=184.866896ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19452026/08/29 16:33:47 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=372.322287ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19462026/08/29 16:33:47 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=848.990296ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19472026/08/29 16:33:48 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.491127498s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1948--- PASS: TestClientErrorHandling (0.00s)1949 --- PASS: TestClientErrorHandling/InvalidStorePath (1.64s)1950 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.82s)1951 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.67s)1952PASS1953{"timestamp":"2026-08-29T16:33:50.297892Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56506","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1836,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}19542026-08-29 16:33:50.420 UTC [15176] LOG: received smart shutdown request19552026-08-29 16:33:50.421 UTC [15176] LOG: background worker "logical replication launcher" (PID 15186) exited with exit code 119562026-08-29 16:33:50.426 UTC [15181] LOG: shutting down19572026-08-29 16:33:50.426 UTC [15181] LOG: checkpoint starting: shutdown immediate19582026-08-29 16:33:51.492 UTC [15181] LOG: checkpoint complete: wrote 13514 buffers (82.5%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=0.748 s, sync=0.295 s, total=1.066 s; sync files=17141, longest=0.001 s, average=0.001 s; distance=240163 kB, estimate=240163 kB; lsn=0/10213EE0, redo lsn=0/10213EE019592026-08-29 16:33:51.496 UTC [15176] LOG: database system is shut down1960Running OIDC tests...1961=== RUN TestGlobMatch1962=== PAUSE TestGlobMatch1963=== RUN TestAudienceForIssuer1964=== PAUSE TestAudienceForIssuer1965=== RUN TestValidateToken_ValidToken1966=== PAUSE TestValidateToken_ValidToken1967=== RUN TestValidateToken_WrongAudience1968=== PAUSE TestValidateToken_WrongAudience1969=== RUN TestValidateToken_Expired1970=== PAUSE TestValidateToken_Expired1971=== RUN TestValidateToken_BoundClaimsMismatch1972=== PAUSE TestValidateToken_BoundClaimsMismatch1973=== RUN TestValidateToken_BoundSubjectMismatch1974=== PAUSE TestValidateToken_BoundSubjectMismatch1975=== RUN TestValidateToken_MultipleProviders1976=== PAUSE TestValidateToken_MultipleProviders1977=== RUN TestValidateToken_NoMatchingProvider1978=== PAUSE TestValidateToken_NoMatchingProvider1979=== RUN TestValidateToken_KubernetesServiceAccount1980=== PAUSE TestValidateToken_KubernetesServiceAccount1981=== RUN TestNewValidator_KubernetesRequiresCA1982=== PAUSE TestNewValidator_KubernetesRequiresCA1983=== RUN TestScopes_LegacyProviderDefaultsToWrite1984=== PAUSE TestScopes_LegacyProviderDefaultsToWrite1985=== RUN TestScopes_Rules1986=== PAUSE TestScopes_Rules1987=== RUN TestScopes_ConfigValidation1988=== PAUSE TestScopes_ConfigValidation1989=== CONT TestGlobMatch1990=== CONT TestValidateToken_Expired1991=== RUN TestGlobMatch/foo_foo1992=== PAUSE TestGlobMatch/foo_foo1993=== RUN TestGlobMatch/foo_bar1994=== PAUSE TestGlobMatch/foo_bar1995=== RUN TestGlobMatch/*_1996=== PAUSE TestGlobMatch/*_1997=== RUN TestGlobMatch/*_anything1998=== PAUSE TestGlobMatch/*_anything1999=== RUN TestGlobMatch/foo*_foo2000=== PAUSE TestGlobMatch/foo*_foo2001=== RUN TestGlobMatch/foo*_foobar2002=== PAUSE TestGlobMatch/foo*_foobar2003=== RUN TestGlobMatch/foo*_bar2004=== PAUSE TestGlobMatch/foo*_bar2005=== RUN TestGlobMatch/*bar_bar2006=== PAUSE TestGlobMatch/*bar_bar2007=== RUN TestGlobMatch/*bar_foobar2008=== PAUSE TestGlobMatch/*bar_foobar2009=== RUN TestGlobMatch/*bar_foo2010=== PAUSE TestGlobMatch/*bar_foo2011=== CONT TestValidateToken_MultipleProviders2012=== CONT TestScopes_ConfigValidation2013=== CONT TestScopes_Rules2014=== CONT TestScopes_LegacyProviderDefaultsToWrite2015=== CONT TestNewValidator_KubernetesRequiresCA2016=== CONT TestValidateToken_KubernetesServiceAccount2017=== CONT TestValidateToken_NoMatchingProvider2018=== CONT TestValidateToken_BoundClaimsMismatch2019=== RUN TestGlobMatch/foo*bar_foobar2020=== PAUSE TestGlobMatch/foo*bar_foobar2021=== RUN TestGlobMatch/foo*bar_foo123bar2022=== PAUSE TestGlobMatch/foo*bar_foo123bar2023=== RUN TestGlobMatch/foo*bar_foobarbaz2024=== PAUSE TestGlobMatch/foo*bar_foobarbaz2025=== RUN TestGlobMatch/*/*_foo/bar2026=== PAUSE TestGlobMatch/*/*_foo/bar2027=== RUN TestGlobMatch/*/*_foo2028=== PAUSE TestGlobMatch/*/*_foo2029=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2030=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2031=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02032=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02033=== RUN TestGlobMatch/refs/*/main_refs/heads/main2034=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2035=== RUN TestGlobMatch/fo?_foo2036=== PAUSE TestGlobMatch/fo?_foo2037=== RUN TestGlobMatch/fo?_fo2038=== PAUSE TestGlobMatch/fo?_fo2039=== RUN TestGlobMatch/fo?_fooo2040=== PAUSE TestGlobMatch/fo?_fooo2041=== RUN TestGlobMatch/?oo_foo2042=== PAUSE TestGlobMatch/?oo_foo2043=== RUN TestGlobMatch/?oo_boo2044=== PAUSE TestGlobMatch/?oo_boo2045=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2046=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2047=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2048=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2049=== CONT TestValidateToken_ValidToken20502026/08/29 16:33:52 INFO OIDC provider initialized name=test20512026/08/29 16:33:52 INFO OIDC provider initialized name=provider120522026/08/29 16:33:52 INFO OIDC provider initialized name=test20532026/08/29 16:33:52 INFO OIDC provider initialized name=provider12054--- PASS: TestScopes_ConfigValidation (0.01s)2055=== CONT TestValidateToken_WrongAudience20562026/08/29 16:33:52 INFO OIDC provider initialized name=test20572026/08/29 16:33:52 INFO OIDC provider initialized name=test20582026/08/29 16:33:52 INFO OIDC provider initialized name=provider220592026/08/29 16:33:52 INFO OIDC provider initialized name=test20602026/08/29 16:33:52 INFO OIDC provider initialized name=test20612026/08/29 16:33:52 INFO OIDC provider initialized name=kubernetes2062--- PASS: TestValidateToken_Expired (0.01s)2063--- PASS: TestValidateToken_BoundClaimsMismatch (0.01s)2064=== CONT TestAudienceForIssuer2065--- PASS: TestAudienceForIssuer (0.00s)2066=== CONT TestGlobMatch/foo_foo2067=== CONT TestValidateToken_BoundSubjectMismatch2068=== CONT TestGlobMatch/*/*_foo/bar2069=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2070=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2071=== CONT TestGlobMatch/?oo_boo2072=== CONT TestGlobMatch/?oo_foo2073=== CONT TestGlobMatch/fo?_fooo2074=== CONT TestGlobMatch/fo?_fo2075=== CONT TestGlobMatch/fo?_foo2076=== CONT TestGlobMatch/refs/*/main_refs/heads/main2077=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02078=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2079=== CONT TestGlobMatch/*/*_foo2080=== CONT TestGlobMatch/*bar_bar2081=== CONT TestGlobMatch/foo*bar_foobarbaz2082=== CONT TestGlobMatch/foo*bar_foo123bar2083=== CONT TestGlobMatch/*bar_foo2084=== CONT TestGlobMatch/foo*bar_foobar2085=== CONT TestGlobMatch/foo*_foo2086=== CONT TestGlobMatch/foo*_bar2087=== CONT TestGlobMatch/foo*_foobar2088=== CONT TestGlobMatch/*_2089=== CONT TestGlobMatch/*_anything2090=== CONT TestGlobMatch/foo_bar2091=== CONT TestGlobMatch/*bar_foobar2092--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2093--- PASS: TestGlobMatch (0.00s)2094 --- PASS: TestGlobMatch/foo_foo (0.00s)2095 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2096 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2097 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2098 --- PASS: TestGlobMatch/?oo_boo (0.00s)2099 --- PASS: TestGlobMatch/?oo_foo (0.00s)2100 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2101 --- PASS: TestGlobMatch/fo?_fo (0.00s)2102 --- PASS: TestGlobMatch/fo?_foo (0.00s)2103 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2104 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2105 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2106 --- PASS: TestGlobMatch/*/*_foo (0.00s)2107 --- PASS: TestGlobMatch/*bar_bar (0.00s)2108 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2109 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2110 --- PASS: TestGlobMatch/*bar_foo (0.00s)2111 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2112 --- PASS: TestGlobMatch/foo*_foo (0.00s)2113 --- PASS: TestGlobMatch/foo*_bar (0.00s)2114 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2115 --- PASS: TestGlobMatch/*_ (0.00s)2116 --- PASS: TestGlobMatch/*_anything (0.00s)2117 --- PASS: TestGlobMatch/foo_bar (0.00s)2118 --- PASS: TestGlobMatch/*bar_foobar (0.00s)21192026/08/29 16:33:52 INFO OIDC provider initialized name=test2120--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)2121--- PASS: TestValidateToken_ValidToken (0.01s)2122--- PASS: TestValidateToken_MultipleProviders (0.01s)2123--- PASS: TestValidateToken_WrongAudience (0.01s)2124--- PASS: TestValidateToken_BoundSubjectMismatch (0.00s)2125--- PASS: TestValidateToken_KubernetesServiceAccount (0.01s)21262026/08/29 16:33:52 http: TLS handshake error from 127.0.0.1:56672: read tcp 127.0.0.1:56667->127.0.0.1:56672: use of closed network connection2127--- PASS: TestNewValidator_KubernetesRequiresCA (0.01s)2128--- PASS: TestScopes_Rules (0.02s)2129PASS2130Running hook tests...2131=== RUN TestSendPathsEmpty2132=== PAUSE TestSendPathsEmpty2133=== RUN TestQueueEnqueueAndFetch2134=== PAUSE TestQueueEnqueueAndFetch2135=== RUN TestQueueDeduplication2136=== PAUSE TestQueueDeduplication2137=== RUN TestQueueRemove2138=== PAUSE TestQueueRemove2139=== RUN TestQueueFetchBatchLimit2140=== PAUSE TestQueueFetchBatchLimit2141=== RUN TestQueueRetryMovesToBack2142=== PAUSE TestQueueRetryMovesToBack2143=== RUN TestQueueFetchRemoveLifecycle2144=== PAUSE TestQueueFetchRemoveLifecycle2145=== RUN TestQueueConcurrentWriters2146=== PAUSE TestQueueConcurrentWriters2147=== RUN TestQueueRemoveLargeClosure2148=== PAUSE TestQueueRemoveLargeClosure2149=== RUN TestServerClientIntegration2150=== PAUSE TestServerClientIntegration2151=== RUN TestServerQueueError2152=== PAUSE TestServerQueueError2153=== RUN TestGetListenerSocketActivation2154 server_test.go:210: === RUN TestGetListenerSocketActivation2155 --- PASS: TestGetListenerSocketActivation (0.00s)2156 PASS2157 2158--- PASS: TestGetListenerSocketActivation (0.01s)2159=== RUN TestDrainIsolatesPoisonPath2160=== PAUSE TestDrainIsolatesPoisonPath2161=== RUN TestRunNotBlockedByPoisonHead2162=== PAUSE TestRunNotBlockedByPoisonHead2163=== RUN TestDrainGivesUpWhenServerDown2164=== PAUSE TestDrainGivesUpWhenServerDown2165=== RUN TestFailedPathPrunedByLaterClosure2166=== PAUSE TestFailedPathPrunedByLaterClosure2167=== RUN TestWorkerUploadsAndRemoves2168=== PAUSE TestWorkerUploadsAndRemoves2169=== RUN TestWorkerSkipsGCdPaths2170=== PAUSE TestWorkerSkipsGCdPaths2171=== RUN TestWorkerPrunesClosureDeps2172=== PAUSE TestWorkerPrunesClosureDeps2173=== RUN TestDrainTimeout2174=== PAUSE TestDrainTimeout2175=== CONT TestSendPathsEmpty2176--- PASS: TestSendPathsEmpty (0.00s)2177=== CONT TestServerClientIntegration2178=== CONT TestServerQueueError2179=== CONT TestWorkerUploadsAndRemoves2180=== CONT TestDrainTimeout2181=== CONT TestWorkerPrunesClosureDeps2182=== CONT TestWorkerSkipsGCdPaths2183=== CONT TestDrainGivesUpWhenServerDown2184=== CONT TestFailedPathPrunedByLaterClosure2185=== CONT TestRunNotBlockedByPoisonHead2186=== CONT TestDrainIsolatesPoisonPath21872026/08/29 16:33:52 ERROR Failed to queue paths error="permission denied" count=12188--- PASS: TestServerQueueError (0.00s)2189=== CONT TestQueueRetryMovesToBack2190--- PASS: TestServerClientIntegration (0.00s)2191=== CONT TestQueueRemoveLargeClosure21922026/08/29 16:33:52 INFO Uploading batch count=121932026/08/29 16:33:52 INFO Uploading batch count=221942026/08/29 16:33:52 ERROR Upload failed error="upload failed" count=121952026/08/29 16:33:52 INFO Uploading batch count=121962026/08/29 16:33:52 INFO Uploading batch count=421972026/08/29 16:33:52 ERROR Upload failed error="upload failed" count=421982026/08/29 16:33:52 INFO Upload queue status pending=321992026/08/29 16:33:52 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-15122-3527464599/TestDrainIsolatesPoisonPath38255051/002/bbb22002026/08/29 16:33:52 INFO Uploading batch count=122012026/08/29 16:33:52 INFO Upload queue status pending=222022026/08/29 16:33:52 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-15122-3527464599/TestWorkerSkipsGCdPaths1806582777/002/nonexistent22032026/08/29 16:33:52 INFO Uploading batch count=222042026/08/29 16:33:52 ERROR Upload failed error="upload failed" count=222052026/08/29 16:33:52 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-15122-3527464599/TestDrainGivesUpWhenServerDown285433958/002/a2206--- PASS: TestQueueRetryMovesToBack (0.01s)2207=== CONT TestQueueConcurrentWriters22082026/08/29 16:33:52 INFO Uploading batch count=122092026/08/29 16:33:52 ERROR Upload failed error="upload failed" count=122102026/08/29 16:33:52 INFO Upload queue status pending=222112026/08/29 16:33:52 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-15122-3527464599/TestDrainGivesUpWhenServerDown285433958/002/b22122026/08/29 16:33:52 INFO Uploading batch count=222132026/08/29 16:33:52 INFO Upload queue status pending=222142026/08/29 16:33:52 INFO Uploading batch count=122152026/08/29 16:33:52 INFO Uploading batch count=222162026/08/29 16:33:52 ERROR Upload failed error="upload failed" count=222172026/08/29 16:33:52 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-15122-3527464599/TestDrainGivesUpWhenServerDown285433958/002/c22182026/08/29 16:33:52 INFO Uploading batch count=122192026/08/29 16:33:52 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-15122-3527464599/TestDrainGivesUpWhenServerDown285433958/002/d22202026/08/29 16:33:52 INFO Uploading batch count=122212026/08/29 16:33:52 ERROR Upload failed error="upload failed" count=122222026/08/29 16:33:52 INFO Uploading batch count=222232026/08/29 16:33:52 ERROR Upload failed error="upload failed" count=222242026/08/29 16:33:52 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-15122-3527464599/TestDrainGivesUpWhenServerDown285433958/002/e22252026/08/29 16:33:52 INFO Uploading batch count=122262026/08/29 16:33:52 ERROR Upload failed error="upload failed" count=12227--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2228=== CONT TestQueueFetchRemoveLifecycle22292026/08/29 16:33:52 INFO Uploading batch count=122302026/08/29 16:33:52 ERROR Upload failed error="upload failed" count=122312026/08/29 16:33:52 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-15122-3527464599/TestDrainGivesUpWhenServerDown285433958/002/f22322026/08/29 16:33:52 ERROR Drain finished with paths left in queue remaining=122332026/08/29 16:33:52 ERROR Drain finished with paths left in queue remaining=102234--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2235=== CONT TestQueueRemove2236--- PASS: TestDrainIsolatesPoisonPath (0.01s)2237=== CONT TestQueueFetchBatchLimit2238--- PASS: TestQueueFetchRemoveLifecycle (0.00s)2239=== CONT TestQueueDeduplication2240--- PASS: TestQueueFetchBatchLimit (0.00s)2241=== CONT TestQueueEnqueueAndFetch2242--- PASS: TestQueueRemove (0.00s)2243--- PASS: TestQueueDeduplication (0.00s)2244--- PASS: TestQueueEnqueueAndFetch (0.00s)2245--- PASS: TestWorkerSkipsGCdPaths (0.03s)2246--- PASS: TestWorkerPrunesClosureDeps (0.03s)2247--- PASS: TestWorkerUploadsAndRemoves (0.03s)2248--- PASS: TestQueueRemoveLargeClosure (0.06s)2249--- PASS: TestQueueConcurrentWriters (0.15s)22502026/08/29 16:33:52 ERROR Upload failed error="context deadline exceeded" count=222512026/08/29 16:33:52 ERROR Drain finished with paths left in queue remaining=42252--- PASS: TestDrainTimeout (0.21s)22532026/08/29 16:33:53 INFO Uploading batch count=122542026/08/29 16:33:53 INFO Uploading batch count=122552026/08/29 16:33:53 INFO Uploading batch count=122562026/08/29 16:33:53 ERROR Upload failed error="upload failed" count=122572026/08/29 16:33:53 INFO Uploading batch count=122582026/08/29 16:33:53 ERROR Upload failed error="upload failed" count=122592026/08/29 16:33:53 INFO Uploading batch count=122602026/08/29 16:33:53 ERROR Upload failed error="upload failed" count=122612026/08/29 16:33:53 INFO Uploading batch count=122622026/08/29 16:33:53 ERROR Upload failed error="upload failed" count=122632026/08/29 16:33:53 ERROR Drain finished with paths left in queue remaining=12264--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2265PASS