niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #197
· 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 TestDumpPathCaseHackMatchesNix13--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)14=== RUN TestDumpPathCaseHackCollision15--- PASS: TestDumpPathCaseHackCollision (0.00s)16=== RUN TestDumpPathMatchesNix17=== PAUSE TestDumpPathMatchesNix18=== RUN TestDumpPathSingleFile19=== PAUSE TestDumpPathSingleFile20=== RUN TestDumpPathWriterError21=== PAUSE TestDumpPathWriterError22=== RUN TestEncodeNixBase3223=== PAUSE TestEncodeNixBase3224=== RUN TestEncodeNixBase32WithRealHash25=== PAUSE TestEncodeNixBase32WithRealHash26=== RUN TestConvertHashToNix3227=== PAUSE TestConvertHashToNix3228=== RUN TestGetStorePathHash29=== PAUSE TestGetStorePathHash30=== RUN TestPathInfoHashCompatibility31=== PAUSE TestPathInfoHashCompatibility32=== RUN TestParsePathInfoJSON33=== PAUSE TestParsePathInfoJSON34=== RUN TestParsePathInfoJSONMultiplePaths35=== PAUSE TestParsePathInfoJSONMultiplePaths36=== RUN TestPathInfoCACompatibility37=== PAUSE TestPathInfoCACompatibility38=== RUN TestRateLimiterFeedback39=== PAUSE TestRateLimiterFeedback40=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess41=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess42=== RUN TestResolveStorePath43=== PAUSE TestResolveStorePath44=== RUN TestDoWithRetry_BodyReplayedViaGetBody45=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody46=== RUN TestShellSplit47=== PAUSE TestShellSplit48=== RUN TestShellSplitErrors49=== PAUSE TestShellSplitErrors50=== RUN TestStreamPushReportsEveryPath51=== PAUSE TestStreamPushReportsEveryPath52=== RUN TestStreamPushBatchesUnderLoad53=== PAUSE TestStreamPushBatchesUnderLoad54=== RUN TestStreamPushIsolatesFailures55=== PAUSE TestStreamPushIsolatesFailures56=== RUN TestStreamPushGivesUpOnDeadServer57=== PAUSE TestStreamPushGivesUpOnDeadServer58=== RUN TestSetClientTLS59=== PAUSE TestSetClientTLS60=== RUN TestSetClientTLSDoesNotMutateDefaultTransport61=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport62=== RUN TestSetClientTLSErrors63=== PAUSE TestSetClientTLSErrors64=== RUN TestStaticToken65=== PAUSE TestStaticToken66=== RUN TestFileTokenReadsAndCaches67=== PAUSE TestFileTokenReadsAndCaches68=== RUN TestFileTokenMissing69=== PAUSE TestFileTokenMissing70=== RUN TestFileTokenEmpty71=== PAUSE TestFileTokenEmpty72=== RUN TestScriptTokenNoExpiryRerunsEveryCall73=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall74=== RUN TestScriptTokenCachesUntilRefresh75=== PAUSE TestScriptTokenCachesUntilRefresh76=== RUN TestScriptTokenEmptyToken77=== PAUSE TestScriptTokenEmptyToken78=== RUN TestScriptTokenBadJSON79=== PAUSE TestScriptTokenBadJSON80=== RUN TestScriptTokenScriptFails81=== PAUSE TestScriptTokenScriptFails82=== RUN TestScriptTokenEmptyCommand83=== PAUSE TestScriptTokenEmptyCommand84=== CONT TestDoServerRequestAttachesToken85=== CONT TestShellSplit86=== CONT TestConvertHashToNix3287=== RUN TestConvertHashToNix32/SRI_format_to_Nix3288=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix3289=== RUN TestConvertHashToNix32/already_Nix32_format90=== PAUSE TestConvertHashToNix32/already_Nix32_format91=== RUN TestConvertHashToNix32/invalid_format92=== PAUSE TestConvertHashToNix32/invalid_format93=== CONT TestDoWithRetry_BodyReplayedViaGetBody94=== CONT TestPathInfoHashCompatibility95=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)96=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)97=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon98=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon99=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI100=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI101=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512102=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512103=== CONT TestGetStorePathHash104=== RUN TestGetStorePathHash/valid_store_path105=== PAUSE TestGetStorePathHash/valid_store_path106=== RUN TestGetStorePathHash/basename_without_hyphen_should_error107=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error108=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error109=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error110=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error111=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error112=== CONT TestFileTokenReadsAndCaches113=== CONT TestResolveStorePath114=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess115--- PASS: TestShellSplit (0.00s)116=== CONT TestStreamPushGivesUpOnDeadServer117=== 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 TestScriptTokenEmptyCommand127--- PASS: TestScriptTokenEmptyCommand (0.00s)128=== CONT TestStaticToken129--- PASS: TestStaticToken (0.00s)130=== CONT TestScriptTokenScriptFails131=== CONT TestPathInfoCACompatibility132=== RUN TestPathInfoCACompatibility/null_ca_field133=== CONT TestParsePathInfoJSONMultiplePaths134=== PAUSE TestPathInfoCACompatibility/null_ca_field135=== CONT TestParsePathInfoJSON136=== RUN TestPathInfoCACompatibility/old_string_format_-_text137=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text138=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive139=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive140=== RUN TestPathInfoCACompatibility/new_structured_format_-_text141=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text142=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method143=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method144=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths145=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths146=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths147=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths148=== CONT TestSetClientTLSErrors149=== CONT TestScriptTokenBadJSON150=== RUN TestParsePathInfoJSON/Nix_format151=== PAUSE TestParsePathInfoJSON/Nix_format152=== RUN TestParsePathInfoJSON/Lix_format153=== PAUSE TestParsePathInfoJSON/Lix_format154=== RUN TestParsePathInfoJSON/empty_input155=== PAUSE TestParsePathInfoJSON/empty_input156=== RUN TestParsePathInfoJSON/whitespace_only157--- PASS: TestFileTokenReadsAndCaches (0.00s)158=== CONT TestScriptTokenEmptyToken159--- PASS: TestResolveStorePath (0.00s)160=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1612026/09/10 18:32:37 ERROR Upload failed error="connection refused" count=201622026/09/10 18:32:37 ERROR Server seems unavailable, giving up on batch untried=17163=== PAUSE TestParsePathInfoJSON/whitespace_only164=== RUN TestParsePathInfoJSON/invalid_JSON165=== PAUSE TestParsePathInfoJSON/invalid_JSON166=== CONT TestScriptTokenCachesUntilRefresh167--- PASS: TestScriptTokenScriptFails (0.00s)168=== CONT TestSetClientTLS1692026/09/10 18:32:37 WARN Rate limiter enabled after throttle name=server-test rate=5170--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)171=== CONT TestScriptTokenNoExpiryRerunsEveryCall172=== RUN TestSetClientTLSErrors/missing_cert_file173=== PAUSE TestSetClientTLSErrors/missing_cert_file174=== RUN TestSetClientTLSErrors/missing_key_file175=== PAUSE TestSetClientTLSErrors/missing_key_file176=== RUN TestSetClientTLSErrors/missing_ca_file177=== PAUSE TestSetClientTLSErrors/missing_ca_file178=== RUN TestSetClientTLSErrors/invalid_ca_file179=== PAUSE TestSetClientTLSErrors/invalid_ca_file180=== CONT TestFileTokenEmpty1812026/09/10 18:32:37 WARN Rate limiter enabled after throttle name=server-test rate=51822026/09/10 18:32:37 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:53829183=== RUN TestSetClientTLS/rejects_connection_without_client_cert184--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)185--- PASS: TestFileTokenEmpty (0.00s)186=== CONT TestDumpPathMatchesNix1872026/09/10 18:32:37 WARN Rate limiter backed off name=server-test rate=51882026/09/10 18:32:37 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:53829189=== CONT TestFileTokenMissing190=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert191=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA192--- PASS: TestDoServerRequestAttachesToken (0.01s)193=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA194=== CONT TestEncodeNixBase32WithRealHash195=== RUN TestSetClientTLS/preserves_debug_logging_transport196--- PASS: TestEncodeNixBase32WithRealHash (0.00s)197=== CONT TestDumpPathWriterError198=== PAUSE TestSetClientTLS/preserves_debug_logging_transport199=== CONT TestDumpPathSingleFile200--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)201=== CONT TestEncodeNixBase32202=== RUN TestEncodeNixBase32/test_string_hash203=== PAUSE TestEncodeNixBase32/test_string_hash204=== RUN TestEncodeNixBase32/empty_input205=== PAUSE TestEncodeNixBase32/empty_input206=== CONT TestStreamPushBatchesUnderLoad207--- PASS: TestFileTokenMissing (0.00s)208=== CONT TestStreamPushIsolatesFailures2092026/09/10 18:32:37 ERROR Upload failed error="bad path" count=3210--- PASS: TestStreamPushIsolatesFailures (0.00s)211=== CONT TestStreamPushReportsEveryPath212--- PASS: TestStreamPushReportsEveryPath (0.00s)213=== CONT TestShellSplitErrors214--- PASS: TestShellSplitErrors (0.00s)215=== CONT TestPartSizeForNAR216=== RUN TestPartSizeForNAR/zero_stays_at_minimum217=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum218=== RUN TestPartSizeForNAR/small_stays_at_minimum219=== PAUSE TestPartSizeForNAR/small_stays_at_minimum220=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum221=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum222=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts223=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts224=== RUN TestPartSizeForNAR/1_TiB225=== PAUSE TestPartSizeForNAR/1_TiB226=== RUN TestPartSizeForNAR/5_TiB_S3_max_object227=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object228=== RUN TestPartSizeForNAR/capped_at_5_GiB229=== PAUSE TestPartSizeForNAR/capped_at_5_GiB230=== CONT TestUploadMultipart_SupersededByPeer231=== RUN TestUploadMultipart_SupersededByPeer/exists232=== PAUSE TestUploadMultipart_SupersededByPeer/exists233=== RUN TestUploadMultipart_SupersededByPeer/missing234=== PAUSE TestUploadMultipart_SupersededByPeer/missing235=== CONT TestFilterOversizedClosures236=== RUN TestFilterOversizedClosures/no_limit_keeps_everything237=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything238=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped239=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped240=== RUN TestFilterOversizedClosures/all_closures_skipped241=== PAUSE TestFilterOversizedClosures/all_closures_skipped242=== CONT TestCaseHackSuffix243--- PASS: TestScriptTokenEmptyToken (0.01s)244=== CONT TestConvertHashToNix32/SRI_format_to_Nix32245=== CONT TestConvertHashToNix32/invalid_format246=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)247=== CONT TestConvertHashToNix32/already_Nix32_format248--- PASS: TestConvertHashToNix32 (0.00s)249 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)250 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)251 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)252=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI253=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512254--- PASS: TestScriptTokenBadJSON (0.01s)255=== CONT TestGetStorePathHash/valid_store_path256=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon257=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error258=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error259=== CONT TestGetStorePathHash/basename_without_hyphen_should_error260--- PASS: TestGetStorePathHash (0.00s)261 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)262 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)263 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)264 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)265=== CONT TestRateLimiterFeedback/429_enables_limiter266--- PASS: TestPathInfoHashCompatibility (0.00s)267 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)268 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)269 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)270 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)271=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2722026/09/10 18:32:37 WARN Rate limiter enabled after throttle name=server-test rate=52732026/09/10 18:32:37 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:53835274=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2752026/09/10 18:32:37 WARN Rate limiter backed off name=server-test rate=5276=== CONT TestRateLimiterFeedback/503_enables_limiter277=== CONT TestPathInfoCACompatibility/null_ca_field278=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths2792026/09/10 18:32:37 WARN Rate limiter enabled after throttle name=server-test rate=52802026/09/10 18:32:37 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:53841281=== CONT TestPathInfoCACompatibility/old_string_format_-_text282=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method2832026/09/10 18:32:37 WARN Rate limiter backed off name=server-test rate=5284=== CONT TestPathInfoCACompatibility/new_structured_format_-_text285=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive286=== CONT TestParsePathInfoJSON/Nix_format287=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths288--- PASS: TestPathInfoCACompatibility (0.00s)289 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)290 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)291 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)292 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)293 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)294--- PASS: TestRateLimiterFeedback (0.00s)295 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)296 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)297 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)298 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)299=== CONT TestParsePathInfoJSON/invalid_JSON300=== CONT TestParsePathInfoJSON/whitespace_only301=== CONT TestParsePathInfoJSON/empty_input302=== CONT TestParsePathInfoJSON/Lix_format303--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)304 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)305 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)306=== CONT TestSetClientTLSErrors/missing_cert_file307--- PASS: TestParsePathInfoJSON (0.00s)308 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)309 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)310 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)311 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)312 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)313=== CONT TestSetClientTLSErrors/invalid_ca_file314=== CONT TestSetClientTLSErrors/missing_ca_file315=== CONT TestSetClientTLSErrors/missing_key_file316=== CONT TestSetClientTLS/rejects_connection_without_client_cert317=== CONT TestSetClientTLS/preserves_debug_logging_transport318--- PASS: TestSetClientTLSErrors (0.01s)319 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)320 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)321 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)322 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)323=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA324=== CONT TestEncodeNixBase32/test_string_hash325=== CONT TestEncodeNixBase32/empty_input326--- PASS: TestEncodeNixBase32 (0.00s)327 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)328 --- PASS: TestEncodeNixBase32/empty_input (0.00s)329=== CONT TestPartSizeForNAR/zero_stays_at_minimum330=== CONT TestPartSizeForNAR/capped_at_5_GiB331=== CONT TestPartSizeForNAR/5_TiB_S3_max_object332=== CONT TestPartSizeForNAR/1_TiB333=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts334=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum335=== CONT TestPartSizeForNAR/small_stays_at_minimum336--- PASS: TestPartSizeForNAR (0.00s)337 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)338 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)339 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)340 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)341 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)342 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)343 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)344=== CONT TestUploadMultipart_SupersededByPeer/exists345=== CONT TestUploadMultipart_SupersededByPeer/missing346--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)347 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)348 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)349=== CONT TestFilterOversizedClosures/no_limit_keeps_everything350=== CONT TestFilterOversizedClosures/all_closures_skipped3512026/09/10 18:32:37 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=50352=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3532026/09/10 18:32:37 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=2000354--- PASS: TestFilterOversizedClosures (0.00s)355 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)356 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)357 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)358--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)3592026/09/10 18:32:37 http: TLS handshake error from 127.0.0.1:53843: read tcp 127.0.0.1:53834->127.0.0.1:53843: use of closed network connection360--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)361--- PASS: TestSetClientTLS (0.01s)362 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)363 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)364 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)365--- PASS: TestDumpPathWriterError (0.04s)366--- PASS: TestDumpPathSingleFile (0.04s)367--- PASS: TestCaseHackSuffix (0.04s)368--- PASS: TestDumpPathMatchesNix (0.07s)369--- PASS: TestStreamPushBatchesUnderLoad (0.10s)370--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)371PASS372Running server tests...373The files belonging to this database system will be owned by user "_nixbld10".374This user must also own the server process.375376The database cluster will be initialized with locale "C".377The default database encoding has accordingly been set to "SQL_ASCII".378The default text search configuration will be set to "english".379380Data page checksums are enabled.381382creating directory /nix/var/nix/builds/nix-22629-883778699/postgres3298260441/data ... ok383creating subdirectories ... ok384selecting dynamic shared memory implementation ... posix385selecting default "max_connections" ... 100386selecting default "shared_buffers" ... 128MB387selecting default time zone ... UTC388creating configuration files ... ok389running bootstrap script ... ok390performing post-bootstrap initialization ... ok391syncing data to disk ... ok392393initdb: warning: enabling "trust" authentication for local connections394initdb: 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.395396Success. You can now start the database server using:397398 pg_ctl -D /nix/var/nix/builds/nix-22629-883778699/postgres3298260441/data -l logfile start399400/nix/var/nix/builds/nix-22629-883778699/postgres3298260441:5432 - no response4012026-09-10 18:32:38.936 UTC [22713] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4022026-09-10 18:32:38.936 UTC [22713] LOG: listening on Unix socket "/nix/var/nix/builds/nix-22629-883778699/postgres3298260441/.s.PGSQL.5432"4032026-09-10 18:32:38.938 UTC [22720] LOG: database system was shut down at 2026-09-10 18:32:38 UTC4042026-09-10 18:32:38.939 UTC [22713] LOG: database system is ready to accept connections405/nix/var/nix/builds/nix-22629-883778699/postgres3298260441:5432 - accepting connections406=== RUN TestService_AuthMiddleware407=== PAUSE TestService_AuthMiddleware408=== RUN TestService_AuthMiddleware_MTLSProxyHeader409=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader410=== RUN TestService_AuthMiddleware_MTLSBoundSubjects411=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects412=== RUN TestService_ReadAuthMiddleware413=== PAUSE TestService_ReadAuthMiddleware414=== RUN TestService_AuthMiddleware_OIDC415=== PAUSE TestService_AuthMiddleware_OIDC416=== RUN TestService_RequireScope_OIDC417=== PAUSE TestService_RequireScope_OIDC418=== RUN TestService_ReadScope_PublicByDefault419=== PAUSE TestService_ReadScope_PublicByDefault420=== RUN TestCacheConfigHandler421=== PAUSE TestCacheConfigHandler422=== RUN TestCacheStatsHandler423=== PAUSE TestCacheStatsHandler424=== RUN TestClientCADerivations425=== PAUSE TestClientCADerivations426=== RUN TestClientErrorHandling427=== PAUSE TestClientErrorHandling428=== RUN TestClientIntegration429=== PAUSE TestClientIntegration430=== RUN TestClientMultipleUploads431=== PAUSE TestClientMultipleUploads432=== RUN TestClientWithDependencies433=== PAUSE TestClientWithDependencies434=== RUN TestPinProtectsFromGC435=== PAUSE TestPinProtectsFromGC436=== RUN TestResolveDBConnectionString437=== PAUSE TestResolveDBConnectionString438=== RUN TestGCAdvisoryLockBlocksConcurrentRun4392026-09-10 18:32:40.947 UTC [22793] ERROR: relation "goose_db_version" does not exist at character 364402026-09-10 18:32:40.947 UTC [22793] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4412026/09/10 18:32:40 OK 20241026095416_initial_model.sql (3.25ms)4422026/09/10 18:32:40 OK 20251210153512_drop_unused_gin_index.sql (361.33µs)4432026/09/10 18:32:40 OK 20251218171726_add_pins.sql (846.71µs)4442026/09/10 18:32:40 OK 20260628120000_add_object_size_and_stats.sql (797.46µs)4452026/09/10 18:32:40 goose: successfully migrated database to version: 202606281200004462026/09/10 18:32:40 OK 1_commit_pending_closure.sql (879.38µs)4472026/09/10 18:32:40 OK 2_object_stats_trigger.sql (246.38µs)4482026/09/10 18:32:40 goose: up to current file version: 2449--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.22s)450=== RUN TestGCBugBareHashReferences451=== PAUSE TestGCBugBareHashReferences452=== RUN TestGCMetrics453=== PAUSE TestGCMetrics454=== RUN TestGCTaskStore_StartNew455=== PAUSE TestGCTaskStore_StartNew456=== RUN TestGCTaskStore_DeduplicateSameParams457=== PAUSE TestGCTaskStore_DeduplicateSameParams458=== RUN TestGCTaskStore_ConflictDifferentParams459=== PAUSE TestGCTaskStore_ConflictDifferentParams460=== RUN TestGCTaskStore_GetEmpty461=== PAUSE TestGCTaskStore_GetEmpty462=== RUN TestGCTaskStore_GetReturnsLatest463=== PAUSE TestGCTaskStore_GetReturnsLatest464=== RUN TestGCTaskStore_CompletedAllowsNewTask465=== PAUSE TestGCTaskStore_CompletedAllowsNewTask466=== RUN TestGCTaskStore_PhaseUpdates467=== PAUSE TestGCTaskStore_PhaseUpdates468=== RUN TestGCTaskStore_Fail469=== PAUSE TestGCTaskStore_Fail470=== RUN TestGracefulShutdownDrainsInflight471=== PAUSE TestGracefulShutdownDrainsInflight472=== RUN TestService_healthCheckHandler473=== PAUSE TestService_healthCheckHandler474=== RUN TestService_readinessHandler475=== PAUSE TestService_readinessHandler476=== RUN TestGenerateLandingPage477=== PAUSE TestGenerateLandingPage478=== RUN TestCacheConfigHandlerMaxNarSize479=== PAUSE TestCacheConfigHandlerMaxNarSize480=== RUN TestCreatePendingClosureRejectsOversizedNAR481=== PAUSE TestCreatePendingClosureRejectsOversizedNAR482=== RUN TestNARDeduplicationMetadataUploadBug483=== PAUSE TestNARDeduplicationMetadataUploadBug484=== RUN TestMetricsInventory485=== PAUSE TestMetricsInventory486=== RUN TestService_NativeMTLS487=== PAUSE TestService_NativeMTLS488=== RUN TestServerTLSConfig489=== PAUSE TestServerTLSConfig490=== RUN TestMultipartCleanup491=== PAUSE TestMultipartCleanup492=== RUN TestObjectStatsTrigger493=== PAUSE TestObjectStatsTrigger494=== RUN TestOrphanedObjectsGC495=== PAUSE TestOrphanedObjectsGC496=== RUN TestOrphanedObjectsGCStressTest497=== PAUSE TestOrphanedObjectsGCStressTest498=== RUN TestResurrectedObjectNotDeleted499=== PAUSE TestResurrectedObjectNotDeleted500=== RUN TestParseSingleRange501=== PAUSE TestParseSingleRange502=== RUN TestIsValidCachePath503=== PAUSE TestIsValidCachePath504=== RUN TestReadProxyNarinfo505=== PAUSE TestReadProxyNarinfo506=== RUN TestReadProxyNarinfoAlreadyDecompressed507=== PAUSE TestReadProxyNarinfoAlreadyDecompressed508=== RUN TestReadProxyNarStreaming509=== PAUSE TestReadProxyNarStreaming510=== RUN TestReadProxy404511=== PAUSE TestReadProxy404512=== RUN TestReadProxyInvalidPath513=== PAUSE TestReadProxyInvalidPath514=== RUN TestReadProxyHead515=== PAUSE TestReadProxyHead516=== RUN TestReadProxyConditionalGet517=== PAUSE TestReadProxyConditionalGet518=== RUN TestReadProxyRootRedirectsToIndexHTML519=== PAUSE TestReadProxyRootRedirectsToIndexHTML520=== RUN TestReadProxyDisabled521=== PAUSE TestReadProxyDisabled522=== RUN TestReadRedirectNar523=== PAUSE TestReadRedirectNar524=== RUN TestReadRedirectKeepsNarinfoProxied525=== PAUSE TestReadRedirectKeepsNarinfoProxied526=== RUN TestReadProxyRangeRequest527=== PAUSE TestReadProxyRangeRequest528=== RUN TestReadRedirectUsesPublicS3URL529=== PAUSE TestReadRedirectUsesPublicS3URL530=== RUN TestRedundantMultipartUpload531=== PAUSE TestRedundantMultipartUpload532=== RUN TestCompleteMultipartUpload_ErrorButObjectExists533=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists534=== RUN TestCompletedNarNotReofferedAcrossClosures535=== PAUSE TestCompletedNarNotReofferedAcrossClosures536=== RUN TestPresignedUploadRegisteredBeforeCommit537=== PAUSE TestPresignedUploadRegisteredBeforeCommit538=== RUN TestService_Rustfstest539=== PAUSE TestService_Rustfstest540=== RUN TestParseSize541=== PAUSE TestParseSize542=== RUN TestSkippedUploadsHandler543=== PAUSE TestSkippedUploadsHandler544=== RUN TestSystemdListenerNotActivated545--- PASS: TestSystemdListenerNotActivated (0.00s)546=== RUN TestWatchdogBeatsWhenHealthy547--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)548=== RUN TestWatchdogSkipsWhenUnhealthy5492026/09/10 18:32:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5502026/09/10 18:32:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5512026/09/10 18:32:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5522026/09/10 18:32:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5532026/09/10 18:32:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5542026/09/10 18:32:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5552026/09/10 18:32:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5562026/09/10 18:32:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5572026/09/10 18:32:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5582026/09/10 18:32:41 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"559--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)560=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle561=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle562=== RUN TestProxyWriteTimeout563=== PAUSE TestProxyWriteTimeout564=== RUN TestIsValidUploadKey565=== PAUSE TestIsValidUploadKey566=== RUN TestUploadHandlersRejectInvalidKeys567=== PAUSE TestUploadHandlersRejectInvalidKeys568=== RUN TestUploadHandlersRejectOversizedBody569=== PAUSE TestUploadHandlersRejectOversizedBody570=== RUN TestService_cleanupPendingClosuresHandler571=== PAUSE TestService_cleanupPendingClosuresHandler572=== RUN TestService_createPendingClosureHandler573=== PAUSE TestService_createPendingClosureHandler574=== RUN TestService_verifyS3Integrity575=== PAUSE TestService_verifyS3Integrity576=== RUN TestCompleteMultipartUnregistered577=== PAUSE TestCompleteMultipartUnregistered578=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT579=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT580=== CONT TestService_AuthMiddleware581=== CONT TestIsValidCachePath582=== CONT TestGCTaskStore_GetEmpty583=== RUN TestIsValidCachePath/narinfo584--- PASS: TestGCTaskStore_GetEmpty (0.00s)585=== CONT TestCompleteMultipartUnregistered586=== CONT TestObjectStatsTrigger587=== PAUSE TestIsValidCachePath/narinfo588=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars589=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars590=== RUN TestIsValidCachePath/nar_zst591=== CONT TestCompletedNarNotReofferedAcrossClosures592=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT593=== CONT TestParseSingleRange594=== RUN TestParseSingleRange/none595=== CONT TestResurrectedObjectNotDeleted596=== PAUSE TestParseSingleRange/none597=== RUN TestParseSingleRange/unknown_unit598=== PAUSE TestParseSingleRange/unknown_unit599=== CONT TestOrphanedObjectsGCStressTest600=== CONT TestOrphanedObjectsGC601=== PAUSE TestIsValidCachePath/nar_zst602=== RUN TestParseSingleRange/multi-range_ignored603=== RUN TestIsValidCachePath/nar_xz604=== PAUSE TestIsValidCachePath/nar_xz605=== RUN TestIsValidCachePath/nar_bz2606=== PAUSE TestIsValidCachePath/nar_bz2607=== PAUSE TestParseSingleRange/multi-range_ignored608=== RUN TestIsValidCachePath/nar_uncompressed609=== PAUSE TestIsValidCachePath/nar_uncompressed610=== RUN TestParseSingleRange/malformed_no_dash611=== RUN TestIsValidCachePath/ls612=== PAUSE TestParseSingleRange/malformed_no_dash613=== RUN TestParseSingleRange/malformed_both_empty614=== PAUSE TestParseSingleRange/malformed_both_empty615=== PAUSE TestIsValidCachePath/ls616=== RUN TestIsValidCachePath/log617=== PAUSE TestIsValidCachePath/log618=== RUN TestParseSingleRange/malformed_end_before_start619=== RUN TestIsValidCachePath/realisation620=== PAUSE TestIsValidCachePath/realisation621=== PAUSE TestParseSingleRange/malformed_end_before_start622=== RUN TestIsValidCachePath/nix-cache-info623=== PAUSE TestIsValidCachePath/nix-cache-info624=== RUN TestIsValidCachePath/index.html625=== RUN TestParseSingleRange/closed626=== PAUSE TestIsValidCachePath/index.html627=== PAUSE TestParseSingleRange/closed628=== RUN TestParseSingleRange/open-ended629=== RUN TestIsValidCachePath/traversal_parent630=== PAUSE TestParseSingleRange/open-ended631=== PAUSE TestIsValidCachePath/traversal_parent632=== RUN TestParseSingleRange/end_clamped_to_size633=== PAUSE TestParseSingleRange/end_clamped_to_size634=== RUN TestIsValidCachePath/traversal_in_middle635=== RUN TestParseSingleRange/suffix636=== PAUSE TestIsValidCachePath/traversal_in_middle637=== RUN TestIsValidCachePath/invalid_char_e638=== PAUSE TestIsValidCachePath/invalid_char_e639=== RUN TestIsValidCachePath/invalid_char_u640=== PAUSE TestIsValidCachePath/invalid_char_u641=== RUN TestIsValidCachePath/random_path642=== PAUSE TestParseSingleRange/suffix643=== PAUSE TestIsValidCachePath/random_path644=== RUN TestIsValidCachePath/empty645=== RUN TestParseSingleRange/suffix_exceeds_size646=== PAUSE TestIsValidCachePath/empty647=== PAUSE TestParseSingleRange/suffix_exceeds_size648=== RUN TestIsValidCachePath/leading_slash649=== PAUSE TestIsValidCachePath/leading_slash650=== RUN TestIsValidCachePath/wrong_extension651=== PAUSE TestIsValidCachePath/wrong_extension652=== RUN TestIsValidCachePath/short_hash653=== PAUSE TestIsValidCachePath/short_hash654=== RUN TestParseSingleRange/single_byte655=== PAUSE TestParseSingleRange/single_byte656=== RUN TestParseSingleRange/start_past_EOF657=== PAUSE TestParseSingleRange/start_past_EOF658=== CONT TestClientIntegration659=== RUN TestParseSingleRange/start_far_past_EOF660=== PAUSE TestParseSingleRange/start_far_past_EOF661=== CONT TestGCTaskStore_ConflictDifferentParams662--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)663=== CONT TestGCTaskStore_DeduplicateSameParams664--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)665=== CONT TestGCTaskStore_StartNew666--- PASS: TestGCTaskStore_StartNew (0.00s)667=== CONT TestGCMetrics6682026-09-10 18:32:41.563 UTC [22818] ERROR: relation "goose_db_version" does not exist at character 366692026-09-10 18:32:41.563 UTC [22818] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6702026-09-10 18:32:41.586 UTC [22819] ERROR: relation "goose_db_version" does not exist at character 366712026-09-10 18:32:41.586 UTC [22819] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6722026-09-10 18:32:41.587 UTC [22820] ERROR: relation "goose_db_version" does not exist at character 366732026-09-10 18:32:41.587 UTC [22820] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6742026-09-10 18:32:41.588 UTC [22823] ERROR: relation "goose_db_version" does not exist at character 366752026-09-10 18:32:41.588 UTC [22823] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6762026-09-10 18:32:41.589 UTC [22821] ERROR: relation "goose_db_version" does not exist at character 366772026-09-10 18:32:41.589 UTC [22821] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6782026-09-10 18:32:41.589 UTC [22822] ERROR: relation "goose_db_version" does not exist at character 366792026-09-10 18:32:41.589 UTC [22822] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6802026/09/10 18:32:41 OK 20241026095416_initial_model.sql (19.09ms)6812026/09/10 18:32:41 OK 20251210153512_drop_unused_gin_index.sql (981.5µs)6822026-09-10 18:32:41.594 UTC [22824] ERROR: relation "goose_db_version" does not exist at character 366832026-09-10 18:32:41.594 UTC [22824] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6842026-09-10 18:32:41.594 UTC [22825] ERROR: relation "goose_db_version" does not exist at character 366852026-09-10 18:32:41.594 UTC [22825] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6862026-09-10 18:32:41.594 UTC [22826] ERROR: relation "goose_db_version" does not exist at character 366872026-09-10 18:32:41.594 UTC [22826] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6882026/09/10 18:32:41 OK 20251218171726_add_pins.sql (1.39ms)6892026-09-10 18:32:41.596 UTC [22827] ERROR: relation "goose_db_version" does not exist at character 366902026-09-10 18:32:41.596 UTC [22827] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6912026/09/10 18:32:41 OK 20260628120000_add_object_size_and_stats.sql (2.83ms)6922026/09/10 18:32:41 goose: successfully migrated database to version: 202606281200006932026/09/10 18:32:41 OK 1_commit_pending_closure.sql (2.45ms)6942026/09/10 18:32:41 OK 20241026095416_initial_model.sql (7.58ms)6952026/09/10 18:32:41 OK 20241026095416_initial_model.sql (7.8ms)6962026/09/10 18:32:41 OK 2_object_stats_trigger.sql (693.58µs)6972026/09/10 18:32:41 goose: up to current file version: 26982026/09/10 18:32:41 OK 20241026095416_initial_model.sql (7.93ms)6992026/09/10 18:32:41 OK 20251210153512_drop_unused_gin_index.sql (789.21µs)7002026/09/10 18:32:41 OK 20241026095416_initial_model.sql (7.56ms)7012026/09/10 18:32:41 OK 20241026095416_initial_model.sql (8.81ms)7022026/09/10 18:32:41 OK 20251210153512_drop_unused_gin_index.sql (905.96µs)7032026/09/10 18:32:41 OK 20251210153512_drop_unused_gin_index.sql (692.92µs)7042026/09/10 18:32:41 OK 20251210153512_drop_unused_gin_index.sql (790.88µs)7052026/09/10 18:32:41 OK 20251210153512_drop_unused_gin_index.sql (828.67µs)7062026/09/10 18:32:41 OK 20251218171726_add_pins.sql (1.47ms)7072026/09/10 18:32:41 OK 20251218171726_add_pins.sql (1.64ms)7082026/09/10 18:32:41 OK 20241026095416_initial_model.sql (6.25ms)7092026/09/10 18:32:41 OK 20251218171726_add_pins.sql (1.56ms)7102026/09/10 18:32:41 OK 20251218171726_add_pins.sql (1.81ms)7112026/09/10 18:32:41 OK 20241026095416_initial_model.sql (6.44ms)7122026/09/10 18:32:41 OK 20251210153512_drop_unused_gin_index.sql (474.42µs)7132026/09/10 18:32:41 OK 20241026095416_initial_model.sql (6.4ms)7142026/09/10 18:32:41 OK 20251210153512_drop_unused_gin_index.sql (9.45ms)7152026/09/10 18:32:41 OK 20260628120000_add_object_size_and_stats.sql (10.8ms)7162026/09/10 18:32:41 goose: successfully migrated database to version: 202606281200007172026/09/10 18:32:41 OK 20260628120000_add_object_size_and_stats.sql (11.3ms)7182026/09/10 18:32:41 goose: successfully migrated database to version: 202606281200007192026/09/10 18:32:41 OK 20251218171726_add_pins.sql (11.82ms)7202026/09/10 18:32:41 OK 20251218171726_add_pins.sql (10.09ms)7212026/09/10 18:32:41 OK 1_commit_pending_closure.sql (984.13µs)7222026/09/10 18:32:41 OK 2_object_stats_trigger.sql (220.25µs)7232026/09/10 18:32:41 goose: up to current file version: 27242026/09/10 18:32:41 OK 20251210153512_drop_unused_gin_index.sql (37.91ms)7252026/09/10 18:32:41 OK 20260628120000_add_object_size_and_stats.sql (38.75ms)7262026/09/10 18:32:41 goose: successfully migrated database to version: 202606281200007272026/09/10 18:32:41 OK 20260628120000_add_object_size_and_stats.sql (38.84ms)7282026/09/10 18:32:41 goose: successfully migrated database to version: 202606281200007292026/09/10 18:32:41 OK 1_commit_pending_closure.sql (29.2ms)7302026/09/10 18:32:41 OK 2_object_stats_trigger.sql (381.46µs)7312026/09/10 18:32:41 goose: up to current file version: 27322026/09/10 18:32:41 OK 1_commit_pending_closure.sql (1.75ms)7332026/09/10 18:32:41 OK 1_commit_pending_closure.sql (1.85ms)7342026/09/10 18:32:41 OK 2_object_stats_trigger.sql (210.42µs)7352026/09/10 18:32:41 goose: up to current file version: 27362026/09/10 18:32:41 OK 2_object_stats_trigger.sql (213.17µs)7372026/09/10 18:32:41 goose: up to current file version: 27382026/09/10 18:32:41 OK 20260628120000_add_object_size_and_stats.sql (36.57ms)7392026/09/10 18:32:41 goose: successfully migrated database to version: 202606281200007402026/09/10 18:32:41 OK 20251218171726_add_pins.sql (37.07ms)7412026/09/10 18:32:41 OK 20260628120000_add_object_size_and_stats.sql (36.62ms)7422026/09/10 18:32:41 goose: successfully migrated database to version: 202606281200007432026/09/10 18:32:41 OK 20251218171726_add_pins.sql (8.58ms)7442026/09/10 18:32:41 OK 1_commit_pending_closure.sql (807.88µs)7452026/09/10 18:32:41 OK 2_object_stats_trigger.sql (187.29µs)7462026/09/10 18:32:41 goose: up to current file version: 27472026/09/10 18:32:41 OK 1_commit_pending_closure.sql (1.02ms)7482026/09/10 18:32:41 OK 20260628120000_add_object_size_and_stats.sql (1.59ms)7492026/09/10 18:32:41 goose: successfully migrated database to version: 202606281200007502026/09/10 18:32:41 OK 2_object_stats_trigger.sql (230.17µs)7512026/09/10 18:32:41 goose: up to current file version: 27522026/09/10 18:32:41 OK 1_commit_pending_closure.sql (860.33µs)7532026/09/10 18:32:41 OK 2_object_stats_trigger.sql (174.88µs)7542026/09/10 18:32:41 goose: up to current file version: 27552026/09/10 18:32:41 OK 20260628120000_add_object_size_and_stats.sql (8.33ms)7562026/09/10 18:32:41 goose: successfully migrated database to version: 202606281200007572026/09/10 18:32:41 OK 20241026095416_initial_model.sql (59.49ms)7582026/09/10 18:32:41 OK 20251210153512_drop_unused_gin_index.sql (2.55ms)7592026/09/10 18:32:41 OK 1_commit_pending_closure.sql (3.14ms)7602026/09/10 18:32:41 OK 2_object_stats_trigger.sql (183.75µs)7612026/09/10 18:32:41 goose: up to current file version: 27622026/09/10 18:32:41 OK 20251218171726_add_pins.sql (6.91ms)7632026/09/10 18:32:41 OK 20260628120000_add_object_size_and_stats.sql (1.37ms)7642026/09/10 18:32:41 goose: successfully migrated database to version: 202606281200007652026/09/10 18:32:41 OK 1_commit_pending_closure.sql (863.67µs)7662026/09/10 18:32:41 OK 2_object_stats_trigger.sql (203µs)7672026/09/10 18:32:41 goose: up to current file version: 27682026/09/10 18:32:41 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"769--- PASS: TestService_AuthMiddleware (0.46s)770=== CONT TestGCBugBareHashReferences7712026/09/10 18:32:41 INFO Received uploads request method=POST path=/api/pending_closures772--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.64s)773=== CONT TestResolveDBConnectionString774=== RUN TestResolveDBConnectionString/flag_wins775=== PAUSE TestResolveDBConnectionString/flag_wins776=== RUN TestResolveDBConnectionString/file_when_flag_empty777=== PAUSE TestResolveDBConnectionString/file_when_flag_empty778=== RUN TestResolveDBConnectionString/missing_file_is_an_error779=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error780=== RUN TestResolveDBConnectionString/PGHOST_allows_empty781=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty782=== RUN TestResolveDBConnectionString/nothing_configured783=== PAUSE TestResolveDBConnectionString/nothing_configured784=== CONT TestPinProtectsFromGC785--- PASS: TestResurrectedObjectNotDeleted (0.81s)786=== CONT TestClientWithDependencies7872026-09-10 18:32:42.238 UTC [22836] ERROR: relation "goose_db_version" does not exist at character 367882026-09-10 18:32:42.238 UTC [22836] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC789=== NAME TestClientIntegration790 client_integration_test.go:277: Created store path: /nix/var/nix/builds/nix-22629-883778699/TestClientIntegration1517834758/002/store/v6i5526qpvkijq8pbdadf8gb7svwpfil-test-file.txt7912026/09/10 18:32:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete7922026/09/10 18:32:42 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst793--- PASS: TestCompleteMultipartUnregistered (1.03s)794=== CONT TestClientMultipleUploads7952026/09/10 18:32:42 OK 20241026095416_initial_model.sql (26.44ms)7962026/09/10 18:32:42 OK 20251210153512_drop_unused_gin_index.sql (7.6ms)7972026/09/10 18:32:42 OK 20251218171726_add_pins.sql (1.63ms)7982026/09/10 18:32:42 OK 20260628120000_add_object_size_and_stats.sql (10.64ms)7992026/09/10 18:32:42 goose: successfully migrated database to version: 202606281200008002026-09-10 18:32:42.303 UTC [22842] ERROR: relation "goose_db_version" does not exist at character 368012026-09-10 18:32:42.303 UTC [22842] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8022026/09/10 18:32:42 OK 1_commit_pending_closure.sql (2.04ms)8032026/09/10 18:32:42 OK 2_object_stats_trigger.sql (246.54µs)8042026/09/10 18:32:42 goose: up to current file version: 28052026/09/10 18:32:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8062026/09/10 18:32:42 OK 20241026095416_initial_model.sql (17.57ms)8072026/09/10 18:32:42 OK 20251210153512_drop_unused_gin_index.sql (3.96ms)8082026/09/10 18:32:42 OK 20251218171726_add_pins.sql (6.13ms)8092026/09/10 18:32:42 INFO Received uploads request method=POST path=/api/pending_closures8102026/09/10 18:32:42 OK 20260628120000_add_object_size_and_stats.sql (6.56ms)8112026/09/10 18:32:42 goose: successfully migrated database to version: 202606281200008122026/09/10 18:32:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8132026/09/10 18:32:42 OK 1_commit_pending_closure.sql (999.75µs)8142026/09/10 18:32:42 INFO Uploading v6i5526qpvkijq8pbdadf8gb7svwpfil-test-file.txt (152B)8152026/09/10 18:32:42 OK 2_object_stats_trigger.sql (237.13µs)8162026/09/10 18:32:42 goose: up to current file version: 28172026/09/10 18:32:42 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"8182026/09/10 18:32:42 WARN Failed to register uploaded object key=v6i5526qpvkijq8pbdadf8gb7svwpfil.ls error="server returned 404: 404 page not found\n"8192026/09/10 18:32:42 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8202026-09-10 18:32:42.368 UTC [22846] ERROR: relation "goose_db_version" does not exist at character 368212026-09-10 18:32:42.368 UTC [22846] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8222026/09/10 18:32:42 INFO Signed narinfos id=1 count=18232026/09/10 18:32:42 INFO Uploading 1 narinfos8242026/09/10 18:32:42 WARN Failed to register uploaded object key=v6i5526qpvkijq8pbdadf8gb7svwpfil.narinfo error="server returned 404: 404 page not found\n"8252026/09/10 18:32:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8262026/09/10 18:32:42 INFO Completed upload id=18272026/09/10 18:32:42 INFO Upload complete. (96ms)828=== NAME TestClientIntegration829 client_integration_test.go:293: Retrieved narinfo from S3:830 StorePath: /nix/var/nix/builds/nix-22629-883778699/TestClientIntegration1517834758/002/store/v6i5526qpvkijq8pbdadf8gb7svwpfil-test-file.txt831 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst832 Compression: zstd833 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1834 NarSize: 152835 References: 836 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1837 client_integration_test.go:294: Retrieved .ls file from S3 (compressed size: 77 bytes)838 client_integration_test.go:294: Decompressed .ls content (64 bytes):839 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}840 client_integration_test.go:297: Testing garbage collection...8412026/09/10 18:32:42 INFO Aborted multipart uploads count=08422026/09/10 18:32:42 WARN Force mode enabled - objects will be deleted immediately without grace period8432026/09/10 18:32:42 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=08442026/09/10 18:32:42 INFO Vacuumed table table=pending_closures8452026/09/10 18:32:42 INFO Vacuumed table table=pending_objects8462026/09/10 18:32:42 INFO Vacuumed table table=multipart_uploads8472026/09/10 18:32:42 INFO Vacuumed table table=closures8482026/09/10 18:32:42 INFO Vacuumed table table=objects849--- PASS: TestGCMetrics (1.15s)850=== CONT TestIsValidUploadKey851=== RUN TestIsValidUploadKey/narinfo852=== PAUSE TestIsValidUploadKey/narinfo853=== RUN TestIsValidUploadKey/nar_zst854=== PAUSE TestIsValidUploadKey/nar_zst855=== RUN TestIsValidUploadKey/nar_xz856=== PAUSE TestIsValidUploadKey/nar_xz857=== RUN TestIsValidUploadKey/nar_plain858=== PAUSE TestIsValidUploadKey/nar_plain859=== RUN TestIsValidUploadKey/listing860=== PAUSE TestIsValidUploadKey/listing861=== RUN TestIsValidUploadKey/build_log862=== PAUSE TestIsValidUploadKey/build_log863=== RUN TestIsValidUploadKey/build_log_home-manager_file864=== PAUSE TestIsValidUploadKey/build_log_home-manager_file865=== RUN TestIsValidUploadKey/build_log_plus_in_name866=== PAUSE TestIsValidUploadKey/build_log_plus_in_name867=== RUN TestIsValidUploadKey/build_log_question_mark868=== PAUSE TestIsValidUploadKey/build_log_question_mark869=== RUN TestIsValidUploadKey/build_log_equals870=== PAUSE TestIsValidUploadKey/build_log_equals871=== RUN TestIsValidUploadKey/realisation872=== PAUSE TestIsValidUploadKey/realisation873=== RUN TestIsValidUploadKey/realisation_plus_in_output874=== PAUSE TestIsValidUploadKey/realisation_plus_in_output875=== RUN TestIsValidUploadKey/nix-cache-info876=== PAUSE TestIsValidUploadKey/nix-cache-info877=== RUN TestIsValidUploadKey/index.html878=== PAUSE TestIsValidUploadKey/index.html879=== RUN TestIsValidUploadKey/narinfo_key,_nar_type880=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type881=== RUN TestIsValidUploadKey/nar_key,_narinfo_type882=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type883=== RUN TestIsValidUploadKey/listing_key,_narinfo_type884=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type885=== RUN TestIsValidUploadKey/traversal886=== PAUSE TestIsValidUploadKey/traversal887=== RUN TestIsValidUploadKey/traversal_nar888=== PAUSE TestIsValidUploadKey/traversal_nar889=== RUN TestIsValidUploadKey/absolute890=== PAUSE TestIsValidUploadKey/absolute891=== RUN TestIsValidUploadKey/empty_key892=== PAUSE TestIsValidUploadKey/empty_key893=== RUN TestIsValidUploadKey/unknown_type894=== PAUSE TestIsValidUploadKey/unknown_type895=== CONT TestService_verifyS3Integrity8962026/09/10 18:32:42 OK 20241026095416_initial_model.sql (20.62ms)8972026/09/10 18:32:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures8982026/09/10 18:32:42 INFO Garbage collection started8992026/09/10 18:32:42 INFO Aborted multipart uploads count=09002026/09/10 18:32:42 WARN Force mode enabled - objects will be deleted immediately without grace period9012026/09/10 18:32:42 OK 20251210153512_drop_unused_gin_index.sql (6.42ms)9022026/09/10 18:32:42 OK 20251218171726_add_pins.sql (6ms)9032026/09/10 18:32:42 OK 20260628120000_add_object_size_and_stats.sql (5.57ms)9042026/09/10 18:32:42 goose: successfully migrated database to version: 202606281200009052026/09/10 18:32:42 OK 1_commit_pending_closure.sql (1.22ms)9062026/09/10 18:32:42 OK 2_object_stats_trigger.sql (216.83µs)9072026/09/10 18:32:42 goose: up to current file version: 29082026-09-10 18:32:42.520 UTC [22853] ERROR: relation "goose_db_version" does not exist at character 369092026-09-10 18:32:42.520 UTC [22853] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9102026/09/10 18:32:42 OK 20241026095416_initial_model.sql (32.36ms)9112026/09/10 18:32:42 OK 20251210153512_drop_unused_gin_index.sql (3.93ms)9122026/09/10 18:32:42 OK 20251218171726_add_pins.sql (1.24ms)9132026/09/10 18:32:42 OK 20260628120000_add_object_size_and_stats.sql (12.56ms)9142026/09/10 18:32:42 goose: successfully migrated database to version: 202606281200009152026/09/10 18:32:42 OK 1_commit_pending_closure.sql (1.2ms)9162026/09/10 18:32:42 OK 2_object_stats_trigger.sql (245.79µs)9172026/09/10 18:32:42 goose: up to current file version: 29182026/09/10 18:32:42 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=09192026/09/10 18:32:42 INFO Vacuumed table table=pending_closures9202026/09/10 18:32:42 INFO Vacuumed table table=pending_objects9212026/09/10 18:32:42 INFO Vacuumed table table=multipart_uploads9222026/09/10 18:32:42 INFO Vacuumed table table=closures9232026/09/10 18:32:42 INFO Vacuumed table table=objects9242026-09-10 18:32:42.663 UTC [22855] ERROR: relation "goose_db_version" does not exist at character 369252026-09-10 18:32:42.663 UTC [22855] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9262026/09/10 18:32:42 OK 20241026095416_initial_model.sql (24.94ms)9272026/09/10 18:32:42 OK 20251210153512_drop_unused_gin_index.sql (5.62ms)9282026/09/10 18:32:42 OK 20251218171726_add_pins.sql (5.81ms)9292026/09/10 18:32:42 OK 20260628120000_add_object_size_and_stats.sql (5.61ms)9302026/09/10 18:32:42 goose: successfully migrated database to version: 202606281200009312026/09/10 18:32:42 OK 1_commit_pending_closure.sql (1.18ms)9322026/09/10 18:32:42 OK 2_object_stats_trigger.sql (253.13µs)9332026/09/10 18:32:42 goose: up to current file version: 2934--- PASS: TestObjectStatsTrigger (1.49s)935=== CONT TestService_createPendingClosureHandler9362026/09/10 18:32:42 INFO Received uploads request method=POST path=/api/pending_closures937=== NAME TestOrphanedObjectsGC938 orphaned_objects_gc_test.go:290: GC Test Summary:939 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A940 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B941 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)942 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)943 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects944--- PASS: TestOrphanedObjectsGC (1.83s)945=== CONT TestService_cleanupPendingClosuresHandler946--- PASS: TestGCBugBareHashReferences (1.60s)947=== CONT TestUploadHandlersRejectOversizedBody948=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure949=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure950=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart951=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart952=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts953=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts954=== CONT TestUploadHandlersRejectInvalidKeys955=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info956=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info957=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal958=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal959=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key960=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key961=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key962=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key963=== CONT TestService_ReadScope_PublicByDefault964=== NAME TestPinProtectsFromGC965 client_integration_test.go:648: Pinned store path: /nix/var/nix/builds/nix-22629-883778699/TestPinProtectsFromGC1501066656/001/store/n09can55hfdpi19q23s0hvf048hb2c05-pinned-file.txt966 client_integration_test.go:649: Unpinned store path: /nix/var/nix/builds/nix-22629-883778699/TestPinProtectsFromGC1501066656/001/store/icr9528zjvczwcik2hzk1nm5582c6i17-unpinned-file.txt9672026/09/10 18:32:43 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9682026/09/10 18:32:43 INFO Received uploads request method=POST path=/api/pending_closures9692026-09-10 18:32:43.660 UTC [22876] ERROR: relation "goose_db_version" does not exist at character 369702026-09-10 18:32:43.660 UTC [22876] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9712026/09/10 18:32:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9722026/09/10 18:32:43 INFO Uploading n09can55hfdpi19q23s0hvf048hb2c05-pinned-file.txt (128B)9732026/09/10 18:32:43 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"9742026/09/10 18:32:43 WARN Failed to register uploaded object key=n09can55hfdpi19q23s0hvf048hb2c05.ls error="server returned 404: 404 page not found\n"9752026/09/10 18:32:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9762026/09/10 18:32:43 INFO Signed narinfos id=1 count=19772026/09/10 18:32:43 INFO Uploading 1 narinfos9782026/09/10 18:32:43 WARN Failed to register uploaded object key=n09can55hfdpi19q23s0hvf048hb2c05.narinfo error="server returned 404: 404 page not found\n"9792026/09/10 18:32:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9802026/09/10 18:32:43 INFO Completed upload id=19812026/09/10 18:32:43 INFO Upload complete. (169ms)9822026/09/10 18:32:43 OK 20241026095416_initial_model.sql (48.35ms)9832026/09/10 18:32:43 OK 20251210153512_drop_unused_gin_index.sql (8.43ms)9842026/09/10 18:32:43 OK 20251218171726_add_pins.sql (27.32ms)985=== NAME TestClientMultipleUploads986 client_integration_test.go:339: Created store path 0: /nix/var/nix/builds/nix-22629-883778699/TestClientMultipleUploads2100661010/001/store/8yv6bi1rs6ypl5dsxn85x0jw7q24kjm4-test-file-0.txt987=== NAME TestClientWithDependencies988 client_integration_test.go:594: Built derivation: /nix/var/nix/builds/nix-22629-883778699/TestClientWithDependencies3910270612/001/store/lx41bhvwi51y4ck2ccyc68impr1nl9x3-test-script9892026/09/10 18:32:43 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9902026/09/10 18:32:43 OK 20260628120000_add_object_size_and_stats.sql (19.63ms)9912026/09/10 18:32:43 goose: successfully migrated database to version: 202606281200009922026/09/10 18:32:43 OK 1_commit_pending_closure.sql (2.24ms)9932026/09/10 18:32:43 OK 2_object_stats_trigger.sql (501µs)9942026/09/10 18:32:43 goose: up to current file version: 29952026/09/10 18:32:43 INFO Received uploads request method=POST path=/api/pending_closures9962026/09/10 18:32:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9972026/09/10 18:32:43 INFO Uploading icr9528zjvczwcik2hzk1nm5582c6i17-unpinned-file.txt (128B)998 client_integration_test.go:596: Found 1 dependencies (including self)9992026/09/10 18:32:43 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"10002026/09/10 18:32:43 INFO Received uploads request method=POST path=/api/pending_closures10012026/09/10 18:32:43 WARN Failed to register uploaded object key=icr9528zjvczwcik2hzk1nm5582c6i17.ls error="server returned 404: 404 page not found\n"10022026/09/10 18:32:43 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10032026/09/10 18:32:43 INFO Signed narinfos id=2 count=110042026/09/10 18:32:43 INFO Uploading 1 narinfos1005=== NAME TestClientMultipleUploads1006 client_integration_test.go:339: Created store path 1: /nix/var/nix/builds/nix-22629-883778699/TestClientMultipleUploads2100661010/001/store/z51322f5ihivmfgsl5ldz4y2akiij6sq-test-file-1.txt10072026/09/10 18:32:43 WARN Failed to register uploaded object key=icr9528zjvczwcik2hzk1nm5582c6i17.narinfo error="server returned 404: 404 page not found\n"10082026/09/10 18:32:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10092026/09/10 18:32:43 INFO Completed upload id=210102026/09/10 18:32:43 INFO Upload complete. (117ms)10112026/09/10 18:32:43 INFO Received create pin request method=POST path=/api/pins/myapp10122026/09/10 18:32:43 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-22629-883778699/TestPinProtectsFromGC1501066656/001/store/n09can55hfdpi19q23s0hvf048hb2c05-pinned-file.txt narinfo_key=n09can55hfdpi19q23s0hvf048hb2c05.narinfo10132026/09/10 18:32:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures10142026/09/10 18:32:43 INFO Garbage collection started10152026/09/10 18:32:43 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10162026/09/10 18:32:43 INFO Received uploads request method=POST path=/api/pending_closures10172026/09/10 18:32:43 INFO Aborted multipart uploads count=010182026/09/10 18:32:43 WARN Force mode enabled - objects will be deleted immediately without grace period10192026/09/10 18:32:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10202026/09/10 18:32:43 INFO Uploading lx41bhvwi51y4ck2ccyc68impr1nl9x3-test-script (136B)1021 client_integration_test.go:339: Created store path 2: /nix/var/nix/builds/nix-22629-883778699/TestClientMultipleUploads2100661010/001/store/bzxwny8w002gymr0nq0b71ffccavvq0k-test-file-2.txt10222026/09/10 18:32:43 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"10232026/09/10 18:32:43 WARN Failed to register uploaded object key=log/zyckc5yww1riyiyzpsinx08cpgbhfvr5-test-script.drv error="server returned 404: 404 page not found\n"10242026/09/10 18:32:44 WARN Failed to register uploaded object key=lx41bhvwi51y4ck2ccyc68impr1nl9x3.ls error="server returned 404: 404 page not found\n"10252026/09/10 18:32:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10262026/09/10 18:32:44 INFO Signed narinfos id=1 count=110272026/09/10 18:32:44 INFO Uploading 1 narinfos10282026/09/10 18:32:44 WARN Failed to register uploaded object key=lx41bhvwi51y4ck2ccyc68impr1nl9x3.narinfo error="server returned 404: 404 page not found\n"10292026/09/10 18:32:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10302026/09/10 18:32:44 INFO Completed upload id=110312026/09/10 18:32:44 INFO Upload complete. (147ms)1032=== NAME TestClientWithDependencies1033 client_integration_test.go:598: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-22629-883778699/TestClientWithDependencies3910270612/001/store) requires matching store prefix10342026/09/10 18:32:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"1035--- PASS: TestClientWithDependencies (2.04s)1036=== CONT TestClientErrorHandling1037=== RUN TestClientErrorHandling/InvalidStorePath1038=== PAUSE TestClientErrorHandling/InvalidStorePath1039=== RUN TestClientErrorHandling/InvalidAuthToken1040=== PAUSE TestClientErrorHandling/InvalidAuthToken1041=== RUN TestClientErrorHandling/ServerNotAvailable1042=== PAUSE TestClientErrorHandling/ServerNotAvailable1043=== CONT TestClientCADerivations10442026/09/10 18:32:44 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10452026/09/10 18:32:44 INFO Received uploads request method=POST path=/api/pending_closures10462026/09/10 18:32:44 INFO Received uploads request method=POST path=/api/pending_closures10472026/09/10 18:32:44 INFO Received uploads request method=POST path=/api/pending_closures10482026/09/10 18:32:44 INFO Received uploads request method=POST path=/api/pending_closures10492026/09/10 18:32:44 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=010502026/09/10 18:32:44 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NTdmYTM2MmQtMjU4OC00ODM1LThjZDItN2U0N2M1OGMzZDdkLmU2MDBiZjQxLTBjYTEtNDBkZC04NjBmLTM3M2MzNjkzZDk3YXgxNzg5MDY1MTYyODgyNjIwMDAw parts=1210512026/09/10 18:32:44 INFO Received uploads request method=POST path=/api/pending_closures1052--- PASS: TestCompletedNarNotReofferedAcrossClosures (2.93s)1053=== CONT TestCacheStatsHandler10542026/09/10 18:32:44 INFO Vacuumed table table=pending_closures10552026/09/10 18:32:44 INFO Received uploads request method=POST path=/api/pending_closures10562026/09/10 18:32:44 INFO Received uploads request method=POST path=/api/pending_closures10572026/09/10 18:32:44 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)10582026/09/10 18:32:44 INFO Uploading 8yv6bi1rs6ypl5dsxn85x0jw7q24kjm4-test-file-0.txt (160B)10592026/09/10 18:32:44 INFO Uploading z51322f5ihivmfgsl5ldz4y2akiij6sq-test-file-1.txt (160B)10602026/09/10 18:32:44 INFO Uploading bzxwny8w002gymr0nq0b71ffccavvq0k-test-file-2.txt (160B)10612026-09-10 18:32:44.185 UTC [22908] ERROR: relation "goose_db_version" does not exist at character 3610622026-09-10 18:32:44.185 UTC [22908] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10632026/09/10 18:32:44 INFO Vacuumed table table=pending_objects10642026/09/10 18:32:44 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"10652026/09/10 18:32:44 INFO Vacuumed table table=multipart_uploads10662026/09/10 18:32:44 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"10672026/09/10 18:32:44 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"10682026/09/10 18:32:44 INFO Vacuumed table table=closures10692026/09/10 18:32:44 WARN Failed to register uploaded object key=8yv6bi1rs6ypl5dsxn85x0jw7q24kjm4.ls error="server returned 404: 404 page not found\n"10702026/09/10 18:32:44 WARN Failed to register uploaded object key=z51322f5ihivmfgsl5ldz4y2akiij6sq.ls error="server returned 404: 404 page not found\n"10712026/09/10 18:32:44 WARN Failed to register uploaded object key=bzxwny8w002gymr0nq0b71ffccavvq0k.ls error="server returned 404: 404 page not found\n"10722026/09/10 18:32:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign10732026/09/10 18:32:44 INFO Signed narinfos id=3 count=110742026/09/10 18:32:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10752026/09/10 18:32:44 INFO Signed narinfos id=1 count=110762026/09/10 18:32:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10772026/09/10 18:32:44 INFO Signed narinfos id=2 count=110782026/09/10 18:32:44 INFO Uploading 3 narinfos10792026/09/10 18:32:44 INFO Vacuumed table table=objects10802026/09/10 18:32:44 WARN Failed to register uploaded object key=bzxwny8w002gymr0nq0b71ffccavvq0k.narinfo error="server returned 404: 404 page not found\n"10812026/09/10 18:32:44 WARN Failed to register uploaded object key=8yv6bi1rs6ypl5dsxn85x0jw7q24kjm4.narinfo error="server returned 404: 404 page not found\n"10822026/09/10 18:32:44 WARN Failed to register uploaded object key=z51322f5ihivmfgsl5ldz4y2akiij6sq.narinfo error="server returned 404: 404 page not found\n"10832026/09/10 18:32:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10842026/09/10 18:32:44 INFO Completed upload id=110852026/09/10 18:32:44 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10862026/09/10 18:32:44 INFO Completed upload id=210872026/09/10 18:32:44 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete10882026/09/10 18:32:44 INFO Completed upload id=310892026/09/10 18:32:44 INFO Upload complete. (225ms)1090=== NAME TestClientMultipleUploads1091 client_integration_test.go:350: Uploaded 3 paths in 261.026208ms10922026/09/10 18:32:44 OK 20241026095416_initial_model.sql (73.63ms)10932026/09/10 18:32:44 OK 20251210153512_drop_unused_gin_index.sql (15.39ms)1094--- PASS: TestClientMultipleUploads (2.02s)1095=== CONT TestCacheConfigHandler1096=== RUN TestCacheConfigHandler/full_config,_no_issuer1097=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1098=== RUN TestCacheConfigHandler/no_cache_url_configured1099=== PAUSE TestCacheConfigHandler/no_cache_url_configured1100=== RUN TestCacheConfigHandler/no_signing_keys1101=== PAUSE TestCacheConfigHandler/no_signing_keys1102=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1103=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1104=== CONT TestSkippedUploadsHandler11052026/09/10 18:32:44 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001106--- PASS: TestSkippedUploadsHandler (0.00s)1107=== CONT TestProxyWriteTimeout1108=== RUN TestProxyWriteTimeout/narinfo1109=== PAUSE TestProxyWriteTimeout/narinfo1110=== RUN TestProxyWriteTimeout/1_GiB_nar1111=== PAUSE TestProxyWriteTimeout/1_GiB_nar1112=== RUN TestProxyWriteTimeout/10_GiB_nar1113=== PAUSE TestProxyWriteTimeout/10_GiB_nar1114=== RUN TestProxyWriteTimeout/unknown_size1115=== PAUSE TestProxyWriteTimeout/unknown_size1116=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle11172026/09/10 18:32:44 OK 20251218171726_add_pins.sql (7.69ms)11182026/09/10 18:32:44 OK 20260628120000_add_object_size_and_stats.sql (8.82ms)11192026/09/10 18:32:44 goose: successfully migrated database to version: 2026062812000011202026/09/10 18:32:44 OK 1_commit_pending_closure.sql (1.24ms)11212026/09/10 18:32:44 OK 2_object_stats_trigger.sql (448.58µs)11222026/09/10 18:32:44 goose: up to current file version: 211232026-09-10 18:32:44.378 UTC [22913] ERROR: relation "goose_db_version" does not exist at character 3611242026-09-10 18:32:44.378 UTC [22913] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11252026/09/10 18:32:44 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01126=== NAME TestClientIntegration1127 client_integration_test.go:304: Objects in database after GC:1128 client_integration_test.go:304: Successfully deleted all objects with GC --force1129--- PASS: TestClientIntegration (3.19s)1130=== CONT TestService_ReadAuthMiddleware11312026/09/10 18:32:44 INFO Received cleanup request method=DELETE path=/api/pending_closures11322026/09/10 18:32:44 INFO Aborted multipart uploads count=011332026/09/10 18:32:44 INFO Received uploads request method=POST path=/api/pending_closures11342026/09/10 18:32:44 INFO Received cleanup request method=DELETE path=/api/pending_closures11352026/09/10 18:32:44 OK 20241026095416_initial_model.sql (172.89ms)11362026/09/10 18:32:44 INFO Aborted multipart uploads count=111372026/09/10 18:32:44 OK 20251210153512_drop_unused_gin_index.sql (1.15ms)11382026/09/10 18:32:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11392026-09-10 18:32:44.632 UTC [22908] ERROR: Closure does not exist: id=111402026-09-10 18:32:44.632 UTC [22908] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE11412026-09-10 18:32:44.632 UTC [22908] STATEMENT: -- name: CommitPendingClosure :exec1142 SELECT commit_pending_closure($1::bigint)1143 1144--- PASS: TestService_cleanupPendingClosuresHandler (1.56s)1145=== CONT TestService_RequireScope_OIDC11462026/09/10 18:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53964/oidc11472026/09/10 18:32:44 OK 20251218171726_add_pins.sql (19.41ms)11482026/09/10 18:32:44 OK 20260628120000_add_object_size_and_stats.sql (25.31ms)11492026/09/10 18:32:44 goose: successfully migrated database to version: 2026062812000011502026/09/10 18:32:44 OK 1_commit_pending_closure.sql (6.77ms)11512026/09/10 18:32:44 OK 2_object_stats_trigger.sql (290.88µs)11522026/09/10 18:32:44 goose: up to current file version: 21153--- PASS: TestService_ReadScope_PublicByDefault (1.60s)1154=== CONT TestService_AuthMiddleware_OIDC11552026/09/10 18:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53968/oidc11562026/09/10 18:32:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11572026/09/10 18:32:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NTdmYTM2MmQtMjU4OC00ODM1LThjZDItN2U0N2M1OGMzZDdkLjY4OWZiZDllLTRhYmQtNDY0OC05NzVjLTljZjM1MWQ1OTY5OHgxNzg5MDY1MTYzODgzNDE3MDAw parts=1011582026/09/10 18:32:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11592026/09/10 18:32:45 INFO Completed upload id=111602026/09/10 18:32:45 INFO Received uploads request method=POST path=/api/pending_closures11612026/09/10 18:32:45 INFO Received uploads request method=POST path=/api/pending_closures11622026/09/10 18:32:45 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11632026/09/10 18:32:45 WARN Found objects in DB but missing from S3, will re-upload count=11164--- PASS: TestService_verifyS3Integrity (2.67s)1165=== CONT TestService_AuthMiddleware_MTLSBoundSubjects11662026/09/10 18:32:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11672026/09/10 18:32:45 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NTdmYTM2MmQtMjU4OC00ODM1LThjZDItN2U0N2M1OGMzZDdkLjNhMmFmOWE3LWM3YTktNDExOS1hM2JlLWRmN2MzMDdkNWRhM3gxNzg5MDY1MTY0MTcyODMzMDAw parts=1011682026/09/10 18:32:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11692026/09/10 18:32:45 INFO Completed upload id=111702026/09/10 18:32:45 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011712026/09/10 18:32:45 INFO Received uploads request method=POST path=/api/pending_closures11722026/09/10 18:32:45 INFO Starting cleanup of old closures method=DELETE path=/api/closures11732026-09-10 18:32:45.288 UTC [22922] ERROR: relation "goose_db_version" does not exist at character 3611742026-09-10 18:32:45.288 UTC [22922] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11752026/09/10 18:32:45 INFO Aborted multipart uploads count=011762026-09-10 18:32:45.292 UTC [22924] ERROR: relation "goose_db_version" does not exist at character 3611772026-09-10 18:32:45.292 UTC [22924] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11782026/09/10 18:32:45 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=011792026/09/10 18:32:45 INFO Vacuumed table table=pending_closures11802026/09/10 18:32:45 INFO Vacuumed table table=pending_objects11812026/09/10 18:32:45 INFO Vacuumed table table=multipart_uploads11822026/09/10 18:32:45 INFO Vacuumed table table=closures11832026/09/10 18:32:45 INFO Vacuumed table table=objects11842026/09/10 18:32:45 OK 20241026095416_initial_model.sql (15.53ms)11852026/09/10 18:32:45 OK 20241026095416_initial_model.sql (12.65ms)11862026/09/10 18:32:45 OK 20251210153512_drop_unused_gin_index.sql (661.75µs)11872026/09/10 18:32:45 OK 20251210153512_drop_unused_gin_index.sql (530.71µs)11882026/09/10 18:32:45 OK 20251218171726_add_pins.sql (1.91ms)11892026/09/10 18:32:45 OK 20251218171726_add_pins.sql (2.24ms)11902026/09/10 18:32:45 OK 20260628120000_add_object_size_and_stats.sql (4.43ms)11912026/09/10 18:32:45 goose: successfully migrated database to version: 2026062812000011922026/09/10 18:32:45 OK 20260628120000_add_object_size_and_stats.sql (5.4ms)11932026/09/10 18:32:45 goose: successfully migrated database to version: 2026062812000011942026/09/10 18:32:45 OK 1_commit_pending_closure.sql (1.72ms)11952026/09/10 18:32:45 OK 2_object_stats_trigger.sql (299.38µs)11962026/09/10 18:32:45 goose: up to current file version: 211972026/09/10 18:32:45 OK 1_commit_pending_closure.sql (1.15ms)11982026/09/10 18:32:45 OK 2_object_stats_trigger.sql (250.96µs)11992026/09/10 18:32:45 goose: up to current file version: 212002026/09/10 18:32:45 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001201--- PASS: TestService_createPendingClosureHandler (2.60s)1202=== CONT TestGenerateLandingPage1203--- PASS: TestGenerateLandingPage (0.00s)1204=== CONT TestMultipartCleanup12052026-09-10 18:32:45.385 UTC [22927] ERROR: relation "goose_db_version" does not exist at character 3612062026-09-10 18:32:45.385 UTC [22927] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1207=== NAME TestOrphanedObjectsGCStressTest1208 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains12092026/09/10 18:32:45 OK 20241026095416_initial_model.sql (81.2ms)12102026/09/10 18:32:45 OK 20251210153512_drop_unused_gin_index.sql (875.67µs)1211 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion12122026/09/10 18:32:45 OK 20251218171726_add_pins.sql (16.39ms)12132026/09/10 18:32:45 OK 20260628120000_add_object_size_and_stats.sql (13.11ms)12142026/09/10 18:32:45 goose: successfully migrated database to version: 2026062812000012152026/09/10 18:32:45 OK 1_commit_pending_closure.sql (1.56ms)12162026/09/10 18:32:45 OK 2_object_stats_trigger.sql (307.71µs)12172026/09/10 18:32:45 goose: up to current file version: 212182026-09-10 18:32:45.541 UTC [22929] ERROR: relation "goose_db_version" does not exist at character 3612192026-09-10 18:32:45.541 UTC [22929] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12202026-09-10 18:32:45.622 UTC [22931] ERROR: relation "goose_db_version" does not exist at character 3612212026-09-10 18:32:45.622 UTC [22931] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12222026/09/10 18:32:45 OK 20241026095416_initial_model.sql (66.39ms)12232026/09/10 18:32:45 OK 20251210153512_drop_unused_gin_index.sql (10.31ms)12242026/09/10 18:32:45 OK 20251218171726_add_pins.sql (13.77ms)12252026/09/10 18:32:45 OK 20260628120000_add_object_size_and_stats.sql (15.73ms)12262026/09/10 18:32:45 goose: successfully migrated database to version: 202606281200001227--- PASS: TestCacheStatsHandler (1.51s)1228=== CONT TestServerTLSConfig1229=== RUN TestServerTLSConfig/no_client_CA1230=== PAUSE TestServerTLSConfig/no_client_CA1231=== RUN TestServerTLSConfig/missing_CA_file1232=== PAUSE TestServerTLSConfig/missing_CA_file1233=== RUN TestServerTLSConfig/not_a_PEM_file1234=== PAUSE TestServerTLSConfig/not_a_PEM_file1235=== CONT TestService_NativeMTLS12362026/09/10 18:32:45 OK 1_commit_pending_closure.sql (1.2ms)12372026/09/10 18:32:45 OK 2_object_stats_trigger.sql (493.21µs)12382026/09/10 18:32:45 goose: up to current file version: 212392026/09/10 18:32:45 OK 20241026095416_initial_model.sql (49.31ms)12402026/09/10 18:32:45 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)12412026/09/10 18:32:45 OK 20251218171726_add_pins.sql (12.54ms)12422026/09/10 18:32:45 OK 20260628120000_add_object_size_and_stats.sql (12.24ms)12432026/09/10 18:32:45 goose: successfully migrated database to version: 2026062812000012442026/09/10 18:32:45 OK 1_commit_pending_closure.sql (1.4ms)12452026/09/10 18:32:45 OK 2_object_stats_trigger.sql (216.67µs)12462026/09/10 18:32:45 goose: up to current file version: 212472026-09-10 18:32:45.757 UTC [22937] ERROR: relation "goose_db_version" does not exist at character 3612482026-09-10 18:32:45.757 UTC [22937] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1249=== NAME TestClientCADerivations1250 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-22629-883778699/TestClientCADerivations2944920308/001/store/1w89v3haaxmdwiziknx1wwdg69avbbai-ca-test1251 client_ca_test.go:139: Found 1 dependencies (including self)12522026/09/10 18:32:45 INFO Received uploads request method=POST path=/api/pending_closures12532026/09/10 18:32:45 OK 20241026095416_initial_model.sql (46.86ms)12542026/09/10 18:32:45 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)12552026/09/10 18:32:45 OK 20251218171726_add_pins.sql (24.93ms)12562026/09/10 18:32:45 OK 20260628120000_add_object_size_and_stats.sql (8.29ms)12572026/09/10 18:32:45 goose: successfully migrated database to version: 2026062812000012582026/09/10 18:32:45 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12592026/09/10 18:32:45 OK 1_commit_pending_closure.sql (1.62ms)12602026/09/10 18:32:45 OK 2_object_stats_trigger.sql (1.19ms)12612026/09/10 18:32:45 goose: up to current file version: 212622026-09-10 18:32:45.886 UTC [22944] ERROR: relation "goose_db_version" does not exist at character 3612632026-09-10 18:32:45.886 UTC [22944] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12642026/09/10 18:32:45 INFO Received uploads request method=POST path=/api/pending_closures12652026/09/10 18:32:45 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01266=== NAME TestPinProtectsFromGC1267 client_integration_test.go:711: Pin successfully protected closure from garbage collection12682026/09/10 18:32:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12692026/09/10 18:32:45 INFO Uploading 1w89v3haaxmdwiziknx1wwdg69avbbai-ca-test (144B)12702026/09/10 18:32:45 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"12712026/09/10 18:32:45 WARN Failed to register uploaded object key=log/gv38qfhx5hd6rqlh28acn2ibpdwififs-ca-test.drv error="server returned 404: 404 page not found\n"1272--- PASS: TestPinProtectsFromGC (4.06s)1273=== CONT TestMetricsInventory12742026/09/10 18:32:45 WARN Failed to register uploaded object key=1w89v3haaxmdwiziknx1wwdg69avbbai.ls error="server returned 404: 404 page not found\n"12752026/09/10 18:32:45 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12762026/09/10 18:32:45 INFO Signed narinfos id=1 count=112772026/09/10 18:32:45 INFO Uploading 1 narinfos12782026/09/10 18:32:45 WARN Failed to register uploaded object key=1w89v3haaxmdwiziknx1wwdg69avbbai.narinfo error="server returned 404: 404 page not found\n"12792026/09/10 18:32:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12802026/09/10 18:32:45 INFO Completed upload id=112812026/09/10 18:32:45 INFO Upload complete. (161ms)1282=== NAME TestClientCADerivations1283 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-22629-883778699/TestClientCADerivations2944920308/001/store/1w89v3haaxmdwiziknx1wwdg69avbbai-ca-test1284 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1285 Compression: zstd1286 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1287 NarSize: 1441288 References: 1289 Deriver: /nix/var/nix/builds/nix-22629-883778699/TestClientCADerivations2944920308/001/store/gv38qfhx5hd6rqlh28acn2ibpdwififs-ca-test.drv1290 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1291 client_ca_test.go:185: Checking for realisation files in S3...1292 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1293 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache12942026/09/10 18:32:46 OK 20241026095416_initial_model.sql (84.73ms)12952026/09/10 18:32:46 OK 20251210153512_drop_unused_gin_index.sql (12.8ms)1296--- PASS: TestService_ReadAuthMiddleware (1.59s)1297=== CONT TestNARDeduplicationMetadataUploadBug12982026/09/10 18:32:46 OK 20251218171726_add_pins.sql (16.41ms)12992026/09/10 18:32:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13002026/09/10 18:32:46 OK 20260628120000_add_object_size_and_stats.sql (17.18ms)13012026/09/10 18:32:46 goose: successfully migrated database to version: 2026062812000013022026/09/10 18:32:46 OK 1_commit_pending_closure.sql (1.54ms)13032026/09/10 18:32:46 OK 2_object_stats_trigger.sql (249.38µs)13042026/09/10 18:32:46 goose: up to current file version: 21305=== NAME TestClientCADerivations1306 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket20?endpoint=http://localhost:53850®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-22629-883778699/TestClientCADerivations2944920308/001/store'1307 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11308--- PASS: TestClientCADerivations (2.01s)1309=== CONT TestCreatePendingClosureRejectsOversizedNAR13102026/09/10 18:32:46 INFO Received uploads request method=POST path=/api/pending_closures1311--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1312=== CONT TestCacheConfigHandlerMaxNarSize1313--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1314=== CONT TestReadProxyRootRedirectsToIndexHTML13152026-09-10 18:32:46.115 UTC [22954] ERROR: relation "goose_db_version" does not exist at character 3613162026-09-10 18:32:46.115 UTC [22954] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1317=== RUN TestService_RequireScope_OIDC/builder_may_write1318=== PAUSE TestService_RequireScope_OIDC/builder_may_write1319=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1320=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1321=== RUN TestService_RequireScope_OIDC/ops_may_admin1322=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1323=== RUN TestService_RequireScope_OIDC/ops_may_not_write1324=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1325=== RUN TestService_RequireScope_OIDC/reader_may_not_write1326=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1327=== RUN TestService_RequireScope_OIDC/static_token_may_admin1328=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1329=== RUN TestService_RequireScope_OIDC/static_token_may_write1330=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1331=== RUN TestService_RequireScope_OIDC/reader_may_read1332=== PAUSE TestService_RequireScope_OIDC/reader_may_read1333=== RUN TestService_RequireScope_OIDC/writer_implies_read1334=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1335=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1336=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1337=== CONT TestCompleteMultipartUpload_ErrorButObjectExists13382026/09/10 18:32:46 OK 20241026095416_initial_model.sql (108.96ms)13392026/09/10 18:32:46 OK 20251210153512_drop_unused_gin_index.sql (1.42ms)13402026/09/10 18:32:46 OK 20251218171726_add_pins.sql (26.27ms)13412026/09/10 18:32:46 OK 20260628120000_add_object_size_and_stats.sql (12.1ms)13422026/09/10 18:32:46 goose: successfully migrated database to version: 2026062812000013432026/09/10 18:32:46 OK 1_commit_pending_closure.sql (1.76ms)13442026/09/10 18:32:46 OK 2_object_stats_trigger.sql (302.67µs)13452026/09/10 18:32:46 goose: up to current file version: 21346=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1347=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1348=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1349=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1350=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1351=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1352=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1353=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1354=== CONT TestRedundantMultipartUpload13552026-09-10 18:32:46.405 UTC [22959] ERROR: relation "goose_db_version" does not exist at character 3613562026-09-10 18:32:46.405 UTC [22959] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13572026/09/10 18:32:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"13582026/09/10 18:32:46 WARN mTLS auth: bound subjects configured but subject DN unavailable13592026/09/10 18:32:46 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1360--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.47s)1361=== CONT TestReadRedirectUsesPublicS3URL13622026/09/10 18:32:46 OK 20241026095416_initial_model.sql (108.55ms)13632026/09/10 18:32:46 OK 20251210153512_drop_unused_gin_index.sql (6.78ms)13642026/09/10 18:32:46 OK 20251218171726_add_pins.sql (13.45ms)13652026/09/10 18:32:46 OK 20260628120000_add_object_size_and_stats.sql (17.04ms)13662026/09/10 18:32:46 goose: successfully migrated database to version: 2026062812000013672026/09/10 18:32:46 OK 1_commit_pending_closure.sql (1.98ms)13682026/09/10 18:32:46 OK 2_object_stats_trigger.sql (406.71µs)13692026/09/10 18:32:46 goose: up to current file version: 213702026/09/10 18:32:46 INFO Received uploads request method=POST path=/api/pending_closures13712026/09/10 18:32:46 INFO Received cleanup request method=DELETE path=/api/pending_closures13722026/09/10 18:32:46 INFO Aborted multipart uploads count=113732026-09-10 18:32:46.862 UTC [22963] ERROR: relation "goose_db_version" does not exist at character 3613742026-09-10 18:32:46.862 UTC [22963] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1375--- PASS: TestMultipartCleanup (1.53s)1376=== CONT TestReadProxyRangeRequest13772026/09/10 18:32:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13782026/09/10 18:32:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1379--- PASS: TestService_NativeMTLS (1.22s)1380=== CONT TestReadRedirectKeepsNarinfoProxied13812026-09-10 18:32:46.908 UTC [22965] ERROR: relation "goose_db_version" does not exist at character 3613822026-09-10 18:32:46.908 UTC [22965] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13832026-09-10 18:32:46.938 UTC [22969] ERROR: relation "goose_db_version" does not exist at character 3613842026-09-10 18:32:46.938 UTC [22969] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13852026/09/10 18:32:46 OK 20241026095416_initial_model.sql (31.03ms)13862026/09/10 18:32:46 OK 20241026095416_initial_model.sql (15.81ms)13872026/09/10 18:32:46 OK 20251210153512_drop_unused_gin_index.sql (515.75µs)13882026/09/10 18:32:46 OK 20251210153512_drop_unused_gin_index.sql (405.75µs)13892026/09/10 18:32:46 OK 20251218171726_add_pins.sql (996.79µs)13902026/09/10 18:32:46 OK 20251218171726_add_pins.sql (958.96µs)13912026-09-10 18:32:46.953 UTC [22970] ERROR: relation "goose_db_version" does not exist at character 3613922026-09-10 18:32:46.953 UTC [22970] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13932026/09/10 18:32:46 OK 20260628120000_add_object_size_and_stats.sql (11.54ms)13942026/09/10 18:32:46 goose: successfully migrated database to version: 2026062812000013952026/09/10 18:32:46 OK 1_commit_pending_closure.sql (1.29ms)13962026/09/10 18:32:46 OK 20260628120000_add_object_size_and_stats.sql (12.93ms)13972026/09/10 18:32:46 goose: successfully migrated database to version: 2026062812000013982026/09/10 18:32:46 OK 2_object_stats_trigger.sql (517.38µs)13992026/09/10 18:32:46 goose: up to current file version: 214002026/09/10 18:32:46 OK 1_commit_pending_closure.sql (1.51ms)14012026/09/10 18:32:46 OK 2_object_stats_trigger.sql (477.88µs)14022026/09/10 18:32:46 goose: up to current file version: 21403=== NAME TestOrphanedObjectsGCStressTest1404 orphaned_objects_gc_test.go:509: Stress test completed successfully:1405 orphaned_objects_gc_test.go:510: - Active objects preserved: 201406 orphaned_objects_gc_test.go:511: - Objects deleted: 2101407 orphaned_objects_gc_test.go:512: - Total GC'd: 2101408--- PASS: TestOrphanedObjectsGCStressTest (5.72s)1409=== CONT TestReadRedirectNar14102026/09/10 18:32:47 OK 20241026095416_initial_model.sql (47.53ms)14112026/09/10 18:32:47 OK 20251210153512_drop_unused_gin_index.sql (10.98ms)14122026/09/10 18:32:47 OK 20251218171726_add_pins.sql (70.86ms)14132026/09/10 18:32:47 OK 20241026095416_initial_model.sql (128.56ms)14142026/09/10 18:32:47 OK 20251210153512_drop_unused_gin_index.sql (5.45ms)14152026/09/10 18:32:47 OK 20260628120000_add_object_size_and_stats.sql (18ms)14162026/09/10 18:32:47 goose: successfully migrated database to version: 2026062812000014172026/09/10 18:32:47 OK 20251218171726_add_pins.sql (13.09ms)14182026/09/10 18:32:47 OK 1_commit_pending_closure.sql (2.36ms)14192026/09/10 18:32:47 OK 2_object_stats_trigger.sql (383.88µs)14202026/09/10 18:32:47 goose: up to current file version: 214212026/09/10 18:32:47 OK 20260628120000_add_object_size_and_stats.sql (14.17ms)14222026/09/10 18:32:47 goose: successfully migrated database to version: 2026062812000014232026/09/10 18:32:47 OK 1_commit_pending_closure.sql (1.89ms)14242026/09/10 18:32:47 OK 2_object_stats_trigger.sql (336.88µs)14252026/09/10 18:32:47 goose: up to current file version: 21426--- PASS: TestMetricsInventory (1.27s)1427=== CONT TestReadProxyDisabled14282026-09-10 18:32:47.602 UTC [22977] ERROR: relation "goose_db_version" does not exist at character 3614292026-09-10 18:32:47.602 UTC [22977] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1430=== NAME TestNARDeduplicationMetadataUploadBug1431 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-22629-883778699/TestNARDeduplicationMetadataUploadBug1475949303/001/store/g5khdm9h7nnljw0y1hcagnv4vxcbqj43-file1.txt1432--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.62s)1433=== CONT TestReadProxy40414342026/09/10 18:32:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14352026/09/10 18:32:47 OK 20241026095416_initial_model.sql (154.32ms)14362026/09/10 18:32:47 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)14372026/09/10 18:32:47 OK 20251218171726_add_pins.sql (22.85ms)14382026/09/10 18:32:47 INFO Received uploads request method=POST path=/api/pending_closures14392026/09/10 18:32:47 OK 20260628120000_add_object_size_and_stats.sql (26.69ms)14402026/09/10 18:32:47 goose: successfully migrated database to version: 2026062812000014412026/09/10 18:32:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14422026/09/10 18:32:47 INFO Uploading g5khdm9h7nnljw0y1hcagnv4vxcbqj43-file1.txt (160B)14432026/09/10 18:32:47 OK 1_commit_pending_closure.sql (7.44ms)14442026/09/10 18:32:47 OK 2_object_stats_trigger.sql (251.42µs)14452026/09/10 18:32:47 goose: up to current file version: 214462026/09/10 18:32:47 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"14472026-09-10 18:32:47.885 UTC [22986] ERROR: relation "goose_db_version" does not exist at character 3614482026-09-10 18:32:47.885 UTC [22986] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14492026/09/10 18:32:47 WARN Failed to register uploaded object key=g5khdm9h7nnljw0y1hcagnv4vxcbqj43.ls error="server returned 404: 404 page not found\n"14502026/09/10 18:32:47 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14512026/09/10 18:32:47 INFO Signed narinfos id=1 count=114522026/09/10 18:32:47 INFO Uploading 1 narinfos14532026/09/10 18:32:47 WARN Failed to register uploaded object key=g5khdm9h7nnljw0y1hcagnv4vxcbqj43.narinfo error="server returned 404: 404 page not found\n"14542026/09/10 18:32:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14552026/09/10 18:32:47 INFO Completed upload id=114562026/09/10 18:32:47 INFO Upload complete. (171ms)1457=== NAME TestNARDeduplicationMetadataUploadBug1458 metadata_upload_test.go:54: Retrieved narinfo from S3:1459 StorePath: /nix/var/nix/builds/nix-22629-883778699/TestNARDeduplicationMetadataUploadBug1475949303/001/store/g5khdm9h7nnljw0y1hcagnv4vxcbqj43-file1.txt1460 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1461 Compression: zstd1462 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1463 NarSize: 1601464 References: 1465 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1466 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1467 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1468 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}14692026/09/10 18:32:47 INFO Received uploads request method=POST path=/api/pending_closures1470 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-22629-883778699/TestNARDeduplicationMetadataUploadBug1475949303/001/store/2b6mnxpb5n8yrqb80bjim0h8rnhqxrsb-file2.txt14712026/09/10 18:32:48 OK 20241026095416_initial_model.sql (156.58ms)14722026/09/10 18:32:48 OK 20251210153512_drop_unused_gin_index.sql (17.15ms)14732026/09/10 18:32:48 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"14742026/09/10 18:32:48 OK 20251218171726_add_pins.sql (23.23ms)14752026/09/10 18:32:48 INFO Received uploads request method=POST path=/api/pending_closures14762026/09/10 18:32:48 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14772026/09/10 18:32:48 OK 20260628120000_add_object_size_and_stats.sql (44.68ms)14782026/09/10 18:32:48 goose: successfully migrated database to version: 2026062812000014792026/09/10 18:32:48 WARN Failed to register uploaded object key=2b6mnxpb5n8yrqb80bjim0h8rnhqxrsb.ls error="server returned 404: 404 page not found\n"14802026/09/10 18:32:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14812026/09/10 18:32:48 INFO Signed narinfos id=2 count=114822026/09/10 18:32:48 INFO Uploading 1 narinfos14832026/09/10 18:32:48 OK 1_commit_pending_closure.sql (7.11ms)14842026/09/10 18:32:48 OK 2_object_stats_trigger.sql (212.71µs)14852026/09/10 18:32:48 goose: up to current file version: 214862026/09/10 18:32:48 WARN Failed to register uploaded object key=2b6mnxpb5n8yrqb80bjim0h8rnhqxrsb.narinfo error="server returned 404: 404 page not found\n"14872026/09/10 18:32:48 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14882026/09/10 18:32:48 INFO Completed upload id=214892026/09/10 18:32:48 INFO Upload complete. (162ms)1490 metadata_upload_test.go:76: Retrieved narinfo from S3:1491 StorePath: /nix/var/nix/builds/nix-22629-883778699/TestNARDeduplicationMetadataUploadBug1475949303/001/store/2b6mnxpb5n8yrqb80bjim0h8rnhqxrsb-file2.txt1492 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1493 Compression: zstd1494 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1495 NarSize: 1601496 References: 1497 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1498 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1499 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1500 {"version":1,"root":{"type":"regular","size":44}}15012026/09/10 18:32:48 INFO Received uploads request method=POST path=/api/pending_closures15022026/09/10 18:32:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15032026/09/10 18:32:48 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NTdmYTM2MmQtMjU4OC00ODM1LThjZDItN2U0N2M1OGMzZDdkLjgyYmUxMDAxLTcyNDQtNGQxNC1iN2QwLWY3ZmVlZTBiZTRmMHgxNzg5MDY1MTY4MDIzMjQ3MDAw15042026/09/10 18:32:48 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NTdmYTM2MmQtMjU4OC00ODM1LThjZDItN2U0N2M1OGMzZDdkLjgyYmUxMDAxLTcyNDQtNGQxNC1iN2QwLWY3ZmVlZTBiZTRmMHgxNzg5MDY1MTY4MDIzMjQ3MDAw parts=11505--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.06s)1506=== CONT TestReadProxyConditionalGet1507=== CONT TestReadProxyHead1508--- PASS: TestNARDeduplicationMetadataUploadBug (2.27s)15092026/09/10 18:32:48 INFO Received uploads request method=POST path=/api/pending_closures1510--- PASS: TestReadRedirectUsesPublicS3URL (2.05s)1511=== CONT TestReadProxyInvalidPath15122026-09-10 18:32:48.689 UTC [23002] ERROR: relation "goose_db_version" does not exist at character 3615132026-09-10 18:32:48.689 UTC [23002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15142026-09-10 18:32:48.721 UTC [23003] ERROR: relation "goose_db_version" does not exist at character 3615152026-09-10 18:32:48.721 UTC [23003] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15162026-09-10 18:32:48.722 UTC [23004] ERROR: relation "goose_db_version" does not exist at character 3615172026-09-10 18:32:48.722 UTC [23004] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15182026/09/10 18:32:48 OK 20241026095416_initial_model.sql (17.28ms)15192026-09-10 18:32:48.751 UTC [23005] ERROR: relation "goose_db_version" does not exist at character 3615202026-09-10 18:32:48.751 UTC [23005] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15212026/09/10 18:32:48 OK 20251210153512_drop_unused_gin_index.sql (1.5ms)15222026/09/10 18:32:48 OK 20251218171726_add_pins.sql (1.63ms)15232026/09/10 18:32:48 OK 20260628120000_add_object_size_and_stats.sql (25.87ms)15242026/09/10 18:32:48 goose: successfully migrated database to version: 2026062812000015252026/09/10 18:32:48 OK 20241026095416_initial_model.sql (45.93ms)15262026/09/10 18:32:48 OK 20241026095416_initial_model.sql (46.95ms)15272026/09/10 18:32:48 OK 20251210153512_drop_unused_gin_index.sql (1.35ms)15282026/09/10 18:32:48 OK 1_commit_pending_closure.sql (8.99ms)15292026/09/10 18:32:48 OK 2_object_stats_trigger.sql (369.38µs)15302026/09/10 18:32:48 goose: up to current file version: 215312026/09/10 18:32:48 OK 20251210153512_drop_unused_gin_index.sql (6.93ms)15322026/09/10 18:32:48 OK 20251218171726_add_pins.sql (29.09ms)15332026/09/10 18:32:48 OK 20251218171726_add_pins.sql (23.52ms)15342026/09/10 18:32:48 OK 20260628120000_add_object_size_and_stats.sql (17.4ms)15352026/09/10 18:32:48 goose: successfully migrated database to version: 2026062812000015362026/09/10 18:32:48 OK 20260628120000_add_object_size_and_stats.sql (21.39ms)15372026/09/10 18:32:48 goose: successfully migrated database to version: 2026062812000015382026/09/10 18:32:48 OK 1_commit_pending_closure.sql (4.43ms)15392026/09/10 18:32:48 OK 2_object_stats_trigger.sql (573.29µs)15402026/09/10 18:32:48 goose: up to current file version: 215412026/09/10 18:32:48 OK 1_commit_pending_closure.sql (3.18ms)15422026/09/10 18:32:48 OK 2_object_stats_trigger.sql (394.54µs)15432026/09/10 18:32:48 goose: up to current file version: 215442026/09/10 18:32:48 OK 20241026095416_initial_model.sql (126.23ms)15452026/09/10 18:32:48 OK 20251210153512_drop_unused_gin_index.sql (7.88ms)15462026/09/10 18:32:48 OK 20251218171726_add_pins.sql (26.96ms)15472026/09/10 18:32:48 OK 20260628120000_add_object_size_and_stats.sql (16.38ms)15482026/09/10 18:32:48 goose: successfully migrated database to version: 2026062812000015492026/09/10 18:32:48 OK 1_commit_pending_closure.sql (10.41ms)15502026/09/10 18:32:48 OK 2_object_stats_trigger.sql (707.96µs)15512026/09/10 18:32:48 goose: up to current file version: 21552--- PASS: TestReadRedirectNar (2.13s)1553=== CONT TestService_Rustfstest1554--- PASS: TestReadProxyRangeRequest (2.52s)1555=== CONT TestParseSize1556--- PASS: TestParseSize (0.00s)1557=== CONT TestReadProxyNarinfoAlreadyDecompressed15582026-09-10 18:32:49.534 UTC [23010] ERROR: relation "goose_db_version" does not exist at character 3615592026-09-10 18:32:49.534 UTC [23010] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1560--- PASS: TestReadRedirectKeepsNarinfoProxied (2.75s)1561=== CONT TestReadProxyNarStreaming15622026/09/10 18:32:49 OK 20241026095416_initial_model.sql (194.58ms)15632026/09/10 18:32:49 OK 20251210153512_drop_unused_gin_index.sql (9.44ms)15642026/09/10 18:32:49 OK 20251218171726_add_pins.sql (40.64ms)15652026/09/10 18:32:49 OK 20260628120000_add_object_size_and_stats.sql (35.3ms)15662026/09/10 18:32:49 goose: successfully migrated database to version: 2026062812000015672026/09/10 18:32:49 OK 1_commit_pending_closure.sql (8.25ms)15682026/09/10 18:32:49 OK 2_object_stats_trigger.sql (645.54µs)15692026/09/10 18:32:49 goose: up to current file version: 215702026/09/10 18:32:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1571--- PASS: TestReadProxyDisabled (2.74s)1572=== CONT TestService_AuthMiddleware_MTLSProxyHeader15732026/09/10 18:32:50 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NTdmYTM2MmQtMjU4OC00ODM1LThjZDItN2U0N2M1OGMzZDdkLjUxY2FkNWZkLWZjZGEtNDg4NC05MjRkLTZjOTBlMjg1MjNjZngxNzg5MDY1MTY4Mjc1MTE0MDAw parts=121574--- PASS: TestRedundantMultipartUpload (3.67s)1575=== CONT TestPresignedUploadRegisteredBeforeCommit15762026-09-10 18:32:50.189 UTC [23019] ERROR: relation "goose_db_version" does not exist at character 3615772026-09-10 18:32:50.189 UTC [23019] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1578--- PASS: TestReadProxy404 (2.59s)1579=== CONT TestReadProxyNarinfo15802026-09-10 18:32:50.338 UTC [23020] ERROR: relation "goose_db_version" does not exist at character 3615812026-09-10 18:32:50.338 UTC [23020] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15822026/09/10 18:32:50 OK 20241026095416_initial_model.sql (115.3ms)15832026/09/10 18:32:50 OK 20251210153512_drop_unused_gin_index.sql (21.46ms)15842026-09-10 18:32:50.429 UTC [23023] ERROR: relation "goose_db_version" does not exist at character 3615852026-09-10 18:32:50.429 UTC [23023] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15862026/09/10 18:32:50 OK 20251218171726_add_pins.sql (22.81ms)15872026/09/10 18:32:50 OK 20260628120000_add_object_size_and_stats.sql (20.54ms)15882026/09/10 18:32:50 goose: successfully migrated database to version: 2026062812000015892026/09/10 18:32:50 OK 20241026095416_initial_model.sql (84.42ms)15902026/09/10 18:32:50 OK 1_commit_pending_closure.sql (3.09ms)15912026/09/10 18:32:50 OK 2_object_stats_trigger.sql (540.5µs)15922026/09/10 18:32:50 goose: up to current file version: 215932026/09/10 18:32:50 OK 20251210153512_drop_unused_gin_index.sql (8.71ms)15942026/09/10 18:32:50 OK 20251218171726_add_pins.sql (24.35ms)15952026/09/10 18:32:50 OK 20260628120000_add_object_size_and_stats.sql (28.76ms)15962026/09/10 18:32:50 goose: successfully migrated database to version: 2026062812000015972026/09/10 18:32:50 OK 1_commit_pending_closure.sql (3.6ms)15982026/09/10 18:32:50 OK 2_object_stats_trigger.sql (674.75µs)15992026/09/10 18:32:50 goose: up to current file version: 216002026/09/10 18:32:50 OK 20241026095416_initial_model.sql (97.97ms)16012026/09/10 18:32:50 OK 20251210153512_drop_unused_gin_index.sql (3.64ms)16022026/09/10 18:32:50 OK 20251218171726_add_pins.sql (16.91ms)16032026/09/10 18:32:50 OK 20260628120000_add_object_size_and_stats.sql (18.03ms)16042026/09/10 18:32:50 goose: successfully migrated database to version: 2026062812000016052026/09/10 18:32:50 OK 1_commit_pending_closure.sql (4.18ms)16062026/09/10 18:32:50 OK 2_object_stats_trigger.sql (703.79µs)16072026/09/10 18:32:50 goose: up to current file version: 21608--- PASS: TestReadProxyHead (2.40s)1609=== CONT TestGCTaskStore_Fail1610--- PASS: TestGCTaskStore_Fail (0.00s)1611=== CONT TestService_readinessHandler16122026-09-10 18:32:50.715 UTC [23024] ERROR: relation "goose_db_version" does not exist at character 3616132026-09-10 18:32:50.715 UTC [23024] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16142026/09/10 18:32:50 OK 20241026095416_initial_model.sql (85.17ms)16152026/09/10 18:32:50 OK 20251210153512_drop_unused_gin_index.sql (2.9ms)16162026/09/10 18:32:50 OK 20251218171726_add_pins.sql (26.59ms)16172026/09/10 18:32:50 OK 20260628120000_add_object_size_and_stats.sql (14.42ms)16182026/09/10 18:32:50 goose: successfully migrated database to version: 2026062812000016192026/09/10 18:32:50 OK 1_commit_pending_closure.sql (4.77ms)16202026/09/10 18:32:50 OK 2_object_stats_trigger.sql (825.71µs)16212026/09/10 18:32:50 goose: up to current file version: 21622--- PASS: TestReadProxyConditionalGet (2.62s)1623=== CONT TestService_healthCheckHandler16242026-09-10 18:32:50.914 UTC [23028] ERROR: relation "goose_db_version" does not exist at character 3616252026-09-10 18:32:50.914 UTC [23028] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16262026-09-10 18:32:51.050 UTC [23030] ERROR: relation "goose_db_version" does not exist at character 3616272026-09-10 18:32:51.050 UTC [23030] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16282026/09/10 18:32:51 OK 20241026095416_initial_model.sql (114.07ms)1629--- PASS: TestReadProxyInvalidPath (2.50s)1630=== CONT TestGracefulShutdownDrainsInflight16312026/09/10 18:32:51 INFO Starting HTTP server address=127.0.0.1:5407116322026/09/10 18:32:51 INFO Shutdown signal received, draining in-flight requests timeout=10s16332026/09/10 18:32:51 OK 20251210153512_drop_unused_gin_index.sql (5.22ms)16342026/09/10 18:32:51 OK 20251218171726_add_pins.sql (16.78ms)16352026-09-10 18:32:51.127 UTC [23031] ERROR: relation "goose_db_version" does not exist at character 3616362026-09-10 18:32:51.127 UTC [23031] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16372026/09/10 18:32:51 OK 20260628120000_add_object_size_and_stats.sql (18.54ms)16382026/09/10 18:32:51 goose: successfully migrated database to version: 2026062812000016392026/09/10 18:32:51 OK 1_commit_pending_closure.sql (3.77ms)16402026/09/10 18:32:51 OK 2_object_stats_trigger.sql (563.79µs)16412026/09/10 18:32:51 goose: up to current file version: 216422026/09/10 18:32:51 WARN Rate limiter enabled after throttle name=s3-test rate=516432026/09/10 18:32:51 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1644=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1645 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101646 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001647--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.85s)1648=== CONT TestGCTaskStore_CompletedAllowsNewTask1649--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1650=== CONT TestGCTaskStore_PhaseUpdates1651--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1652=== CONT TestGCTaskStore_GetReturnsLatest1653--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1654=== CONT TestIsValidCachePath/narinfo1655=== CONT TestIsValidCachePath/index.html1656=== CONT TestIsValidCachePath/nix-cache-info1657=== CONT TestIsValidCachePath/realisation1658=== CONT TestIsValidCachePath/log1659=== CONT TestIsValidCachePath/ls1660=== CONT TestIsValidCachePath/nar_uncompressed1661=== CONT TestIsValidCachePath/traversal_parent1662=== CONT TestIsValidCachePath/nar_bz21663=== CONT TestIsValidCachePath/nar_xz1664=== CONT TestIsValidCachePath/nar_zst1665=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1666=== CONT TestIsValidCachePath/empty1667=== CONT TestIsValidCachePath/short_hash1668=== CONT TestIsValidCachePath/wrong_extension1669=== CONT TestIsValidCachePath/leading_slash1670=== CONT TestIsValidCachePath/invalid_char_u1671=== CONT TestIsValidCachePath/random_path1672=== CONT TestIsValidCachePath/invalid_char_e1673=== CONT TestIsValidCachePath/traversal_in_middle1674--- PASS: TestIsValidCachePath (0.01s)1675 --- PASS: TestIsValidCachePath/narinfo (0.00s)1676 --- PASS: TestIsValidCachePath/index.html (0.00s)1677 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1678 --- PASS: TestIsValidCachePath/realisation (0.00s)1679 --- PASS: TestIsValidCachePath/log (0.00s)1680 --- PASS: TestIsValidCachePath/ls (0.00s)1681 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1682 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1683 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1684 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1685 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1686 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1687 --- PASS: TestIsValidCachePath/empty (0.00s)1688 --- PASS: TestIsValidCachePath/short_hash (0.00s)1689 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1690 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1691 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1692 --- PASS: TestIsValidCachePath/random_path (0.00s)1693 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1694 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1695=== CONT TestParseSingleRange/none1696=== CONT TestParseSingleRange/open-ended1697=== CONT TestParseSingleRange/start_far_past_EOF1698=== CONT TestParseSingleRange/start_past_EOF1699=== CONT TestParseSingleRange/single_byte1700=== CONT TestParseSingleRange/suffix_exceeds_size1701=== CONT TestParseSingleRange/suffix1702=== CONT TestParseSingleRange/end_clamped_to_size1703=== CONT TestParseSingleRange/multi-range_ignored1704=== CONT TestParseSingleRange/malformed_no_dash1705=== CONT TestParseSingleRange/unknown_unit1706=== CONT TestParseSingleRange/closed1707=== CONT TestParseSingleRange/malformed_end_before_start1708=== CONT TestParseSingleRange/malformed_both_empty1709--- PASS: TestParseSingleRange (0.01s)1710 --- PASS: TestParseSingleRange/none (0.00s)1711 --- PASS: TestParseSingleRange/open-ended (0.00s)1712 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1713 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1714 --- PASS: TestParseSingleRange/single_byte (0.00s)1715 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1716 --- PASS: TestParseSingleRange/suffix (0.00s)1717 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1718 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1719 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1720 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1721 --- PASS: TestParseSingleRange/closed (0.00s)1722 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1723 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1724=== CONT TestResolveDBConnectionString/flag_wins1725=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1726=== CONT TestResolveDBConnectionString/nothing_configured1727=== CONT TestResolveDBConnectionString/missing_file_is_an_error1728=== CONT TestResolveDBConnectionString/file_when_flag_empty1729=== CONT TestIsValidUploadKey/narinfo1730=== CONT TestIsValidUploadKey/realisation_plus_in_output1731=== CONT TestIsValidUploadKey/unknown_type1732=== CONT TestIsValidUploadKey/empty_key1733=== CONT TestIsValidUploadKey/absolute1734=== CONT TestIsValidUploadKey/traversal_nar1735=== CONT TestIsValidUploadKey/traversal1736=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1737=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1738=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1739=== CONT TestIsValidUploadKey/index.html1740=== CONT TestIsValidUploadKey/nix-cache-info1741=== CONT TestIsValidUploadKey/build_log_home-manager_file1742=== CONT TestIsValidUploadKey/realisation1743=== CONT TestIsValidUploadKey/build_log_equals1744=== CONT TestIsValidUploadKey/build_log_question_mark1745=== CONT TestIsValidUploadKey/build_log_plus_in_name1746=== CONT TestIsValidUploadKey/build_log1747=== CONT TestIsValidUploadKey/nar_xz1748=== CONT TestIsValidUploadKey/nar_zst1749=== CONT TestIsValidUploadKey/nar_plain1750=== CONT TestIsValidUploadKey/listing1751--- PASS: TestIsValidUploadKey (0.00s)1752 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1753 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1754 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1755 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1756 --- PASS: TestIsValidUploadKey/absolute (0.00s)1757 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1758 --- PASS: TestIsValidUploadKey/traversal (0.00s)1759 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1760 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1761 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1762 --- PASS: TestIsValidUploadKey/index.html (0.00s)1763 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1764 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1765 --- PASS: TestIsValidUploadKey/realisation (0.00s)1766 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1767 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1768 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1769 --- PASS: TestIsValidUploadKey/build_log (0.00s)1770 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1771 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1772 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1773 --- PASS: TestIsValidUploadKey/listing (0.00s)1774=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17752026/09/10 18:32:51 INFO Received uploads request method=POST path=/1776--- PASS: TestResolveDBConnectionString (0.01s)1777 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1778 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1779 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1780 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1781 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1782--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1783=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17842026/09/10 18:32:51 INFO Received request for more parts method=POST path=/17852026/09/10 18:32:51 OK 20241026095416_initial_model.sql (67.9ms)17862026/09/10 18:32:51 OK 20251210153512_drop_unused_gin_index.sql (8.64ms)17872026-09-10 18:32:51.183 UTC [23032] ERROR: relation "goose_db_version" does not exist at character 3617882026-09-10 18:32:51.183 UTC [23032] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17892026/09/10 18:32:51 OK 20251218171726_add_pins.sql (8.3ms)1790=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17912026/09/10 18:32:51 INFO Received complete multipart upload request method=POST path=/17922026/09/10 18:32:51 OK 20260628120000_add_object_size_and_stats.sql (19.05ms)17932026/09/10 18:32:51 goose: successfully migrated database to version: 2026062812000017942026/09/10 18:32:51 OK 1_commit_pending_closure.sql (1.51ms)17952026/09/10 18:32:51 OK 2_object_stats_trigger.sql (258.13µs)17962026/09/10 18:32:51 goose: up to current file version: 21797=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17982026/09/10 18:32:51 INFO Received uploads request method=POST path=/17992026/09/10 18:32:51 OK 20241026095416_initial_model.sql (60.09ms)1800=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18012026/09/10 18:32:51 INFO Received complete multipart upload request method=POST path=/1802=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18032026/09/10 18:32:51 INFO Received request for more parts method=POST path=/1804=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18052026/09/10 18:32:51 INFO Received uploads request method=POST path=/1806--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1807 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1808 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1809 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1810 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1811=== CONT TestClientErrorHandling/InvalidStorePath18122026/09/10 18:32:51 OK 20251210153512_drop_unused_gin_index.sql (8.83ms)18132026/09/10 18:32:51 OK 20251218171726_add_pins.sql (2.03ms)18142026/09/10 18:32:51 OK 20260628120000_add_object_size_and_stats.sql (23.6ms)18152026/09/10 18:32:51 goose: successfully migrated database to version: 2026062812000018162026/09/10 18:32:51 OK 1_commit_pending_closure.sql (2.44ms)18172026/09/10 18:32:51 OK 2_object_stats_trigger.sql (247.17µs)18182026/09/10 18:32:51 goose: up to current file version: 218192026/09/10 18:32:51 OK 20241026095416_initial_model.sql (54.27ms)18202026-09-10 18:32:51.264 UTC [23035] ERROR: relation "goose_db_version" does not exist at character 3618212026-09-10 18:32:51.264 UTC [23035] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18222026/09/10 18:32:51 OK 20251210153512_drop_unused_gin_index.sql (7.66ms)18232026/09/10 18:32:51 OK 20251218171726_add_pins.sql (12.87ms)1824--- PASS: TestService_Rustfstest (2.19s)1825=== CONT TestClientErrorHandling/ServerNotAvailable18262026/09/10 18:32:51 OK 20260628120000_add_object_size_and_stats.sql (9.54ms)18272026/09/10 18:32:51 goose: successfully migrated database to version: 2026062812000018282026/09/10 18:32:51 OK 1_commit_pending_closure.sql (7.82ms)18292026/09/10 18:32:51 OK 2_object_stats_trigger.sql (337.17µs)18302026/09/10 18:32:51 goose: up to current file version: 218312026/09/10 18:32:51 OK 20241026095416_initial_model.sql (47.71ms)18322026/09/10 18:32:51 OK 20251210153512_drop_unused_gin_index.sql (9.42ms)18332026/09/10 18:32:51 OK 20251218171726_add_pins.sql (15.96ms)18342026/09/10 18:32:51 OK 20260628120000_add_object_size_and_stats.sql (13.12ms)18352026/09/10 18:32:51 goose: successfully migrated database to version: 2026062812000018362026/09/10 18:32:51 OK 1_commit_pending_closure.sql (1.62ms)18372026/09/10 18:32:51 OK 2_object_stats_trigger.sql (939.21µs)18382026/09/10 18:32:51 goose: up to current file version: 21839=== CONT TestClientErrorHandling/InvalidAuthToken1840--- PASS: TestUploadHandlersRejectOversizedBody (0.04s)1841 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1842 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1843 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)18442026/09/10 18:32:51 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-config1845--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.06s)1846=== CONT TestCacheConfigHandler/full_config,_no_issuer1847=== CONT TestCacheConfigHandler/no_signing_keys1848=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1849=== CONT TestCacheConfigHandler/no_cache_url_configured1850--- PASS: TestCacheConfigHandler (0.00s)1851 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1852 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1853 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1854 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1855=== CONT TestProxyWriteTimeout/narinfo1856=== CONT TestProxyWriteTimeout/unknown_size1857=== CONT TestProxyWriteTimeout/10_GiB_nar1858=== CONT TestProxyWriteTimeout/1_GiB_nar1859--- PASS: TestProxyWriteTimeout (0.00s)1860 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1861 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1862 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1863 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1864=== CONT TestServerTLSConfig/no_client_CA1865=== CONT TestServerTLSConfig/not_a_PEM_file1866=== CONT TestServerTLSConfig/missing_CA_file1867--- PASS: TestServerTLSConfig (0.00s)1868 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1869 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1870 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1871=== CONT TestService_RequireScope_OIDC/builder_may_write18722026/09/10 18:32:51 INFO OIDC auth successful provider=test scopes=[write]1873=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1874=== CONT TestService_RequireScope_OIDC/writer_implies_read18752026/09/10 18:32:51 INFO OIDC auth successful provider=test scopes=[write]1876=== CONT TestService_RequireScope_OIDC/reader_may_read18772026/09/10 18:32:51 INFO OIDC auth successful provider=test scopes=[read]1878=== CONT TestService_RequireScope_OIDC/static_token_may_write1879=== CONT TestService_RequireScope_OIDC/static_token_may_admin1880=== CONT TestService_RequireScope_OIDC/reader_may_not_write18812026/09/10 18:32:51 INFO OIDC auth successful provider=test scopes=[read]1882=== CONT TestService_RequireScope_OIDC/ops_may_not_write18832026/09/10 18:32:51 INFO OIDC auth successful provider=test scopes=[admin]1884=== CONT TestService_RequireScope_OIDC/ops_may_admin18852026/09/10 18:32:51 INFO OIDC auth successful provider=test scopes=[admin]1886=== CONT TestService_RequireScope_OIDC/builder_may_not_admin18872026/09/10 18:32:51 INFO OIDC auth successful provider=test scopes=[write]1888=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token18892026/09/10 18:32:51 INFO OIDC auth successful provider=test scopes=[write]1890=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1891=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18922026/09/10 18:32:51 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]1893=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18942026/09/10 18:32:51 WARN Authentication failed token_preview=eyJhbGciOi...5grq90S-oA token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1895--- PASS: TestService_RequireScope_OIDC (1.59s)1896 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1897 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1898 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1899 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1900 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1901 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1902 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1903 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1904 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1905 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1906--- PASS: TestService_AuthMiddleware_OIDC (1.45s)1907 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1908 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1909 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1910 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)19112026-09-10 18:32:51.472 UTC [23044] ERROR: relation "goose_db_version" does not exist at character 3619122026-09-10 18:32:51.472 UTC [23044] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19132026/09/10 18:32:51 OK 20241026095416_initial_model.sql (43.9ms)19142026/09/10 18:32:51 OK 20251210153512_drop_unused_gin_index.sql (8.68ms)19152026/09/10 18:32:51 OK 20251218171726_add_pins.sql (7.64ms)19162026/09/10 18:32:51 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=186.325654ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19172026/09/10 18:32:51 OK 20260628120000_add_object_size_and_stats.sql (9.29ms)19182026/09/10 18:32:51 goose: successfully migrated database to version: 2026062812000019192026/09/10 18:32:51 OK 1_commit_pending_closure.sql (2.4ms)19202026/09/10 18:32:51 OK 2_object_stats_trigger.sql (261.08µs)19212026/09/10 18:32:51 goose: up to current file version: 219222026-09-10 18:32:51.572 UTC [23045] ERROR: relation "goose_db_version" does not exist at character 3619232026-09-10 18:32:51.572 UTC [23045] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1924--- PASS: TestReadProxyNarStreaming (1.96s)19252026/09/10 18:32:51 OK 20241026095416_initial_model.sql (38.16ms)19262026/09/10 18:32:51 OK 20251210153512_drop_unused_gin_index.sql (1.05ms)19272026/09/10 18:32:51 OK 20251218171726_add_pins.sql (7.61ms)19282026/09/10 18:32:51 OK 20260628120000_add_object_size_and_stats.sql (13.39ms)19292026/09/10 18:32:51 goose: successfully migrated database to version: 2026062812000019302026/09/10 18:32:51 OK 1_commit_pending_closure.sql (7.95ms)19312026/09/10 18:32:51 OK 2_object_stats_trigger.sql (377.04µs)19322026/09/10 18:32:51 goose: up to current file version: 21933--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.77s)19342026/09/10 18:32:51 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=363.527761ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19352026/09/10 18:32:51 INFO Received uploads request method=POST path=/api/pending_closures19362026/09/10 18:32:51 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst19372026/09/10 18:32:51 INFO Received uploads request method=POST path=/api/pending_closures19382026-09-10 18:32:51.959 UTC [23046] ERROR: relation "goose_db_version" does not exist at character 3619392026-09-10 18:32:51.959 UTC [23046] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1940--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.91s)19412026/09/10 18:32:52 OK 20241026095416_initial_model.sql (73.86ms)19422026/09/10 18:32:52 OK 20251210153512_drop_unused_gin_index.sql (10.61ms)19432026/09/10 18:32:52 OK 20251218171726_add_pins.sql (22.6ms)19442026/09/10 18:32:52 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=831.8159ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19452026/09/10 18:32:52 OK 20260628120000_add_object_size_and_stats.sql (22.38ms)19462026/09/10 18:32:52 goose: successfully migrated database to version: 2026062812000019472026/09/10 18:32:52 OK 1_commit_pending_closure.sql (5.46ms)19482026/09/10 18:32:52 OK 2_object_stats_trigger.sql (1.23ms)19492026/09/10 18:32:52 goose: up to current file version: 21950--- PASS: TestReadProxyNarinfo (1.82s)19512026-09-10 18:32:52.145 UTC [23047] ERROR: relation "goose_db_version" does not exist at character 3619522026-09-10 18:32:52.145 UTC [23047] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19532026/09/10 18:32:52 OK 20241026095416_initial_model.sql (49.53ms)19542026/09/10 18:32:52 OK 20251210153512_drop_unused_gin_index.sql (12.69ms)19552026/09/10 18:32:52 OK 20251218171726_add_pins.sql (15.24ms)19562026/09/10 18:32:52 OK 20260628120000_add_object_size_and_stats.sql (26.08ms)19572026/09/10 18:32:52 goose: successfully migrated database to version: 2026062812000019582026/09/10 18:32:52 WARN readiness check failed error="closed pool"1959--- PASS: TestService_readinessHandler (1.57s)19602026/09/10 18:32:52 OK 1_commit_pending_closure.sql (4.93ms)19612026/09/10 18:32:52 OK 2_object_stats_trigger.sql (1.04ms)19622026/09/10 18:32:52 goose: up to current file version: 21963--- PASS: TestService_healthCheckHandler (1.48s)19642026/09/10 18:32:52 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"19652026/09/10 18:32:52 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19662026/09/10 18:32:52 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.567847483s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config19672026/09/10 18:32:54 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"19682026/09/10 18:32:54 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_closures19692026/09/10 18:32:54 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=206.356324ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19702026/09/10 18:32:54 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=430.309207ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19712026/09/10 18:32:55 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=852.089159ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures19722026/09/10 18:32:56 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.673629109s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures1973--- PASS: TestClientErrorHandling (0.00s)1974 --- PASS: TestClientErrorHandling/InvalidStorePath (1.33s)1975 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.26s)1976 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.59s)1977PASS1978{"timestamp":"2026-09-10T18:32:57.870979Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53971","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1866,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}19792026-09-10 18:32:57.972 UTC [22713] LOG: received smart shutdown request19802026-09-10 18:32:57.973 UTC [22713] LOG: background worker "logical replication launcher" (PID 22723) exited with exit code 119812026-09-10 18:32:57.981 UTC [22718] LOG: shutting down19822026-09-10 18:32:57.981 UTC [22718] LOG: checkpoint starting: shutdown immediate19832026-09-10 18:32:59.073 UTC [22718] LOG: checkpoint complete: wrote 13491 buffers (82.3%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 15 recycled; write=0.800 s, sync=0.290 s, total=1.092 s; sync files=17141, longest=0.001 s, average=0.001 s; distance=240170 kB, estimate=240170 kB; lsn=0/10217AA0, redo lsn=0/10217AA019842026-09-10 18:32:59.077 UTC [22713] LOG: database system is shut down1985Running OIDC tests...1986=== RUN TestGlobMatch1987=== PAUSE TestGlobMatch1988=== RUN TestAudienceForIssuer1989=== PAUSE TestAudienceForIssuer1990=== RUN TestValidateToken_ValidToken1991=== PAUSE TestValidateToken_ValidToken1992=== RUN TestValidateToken_WrongAudience1993=== PAUSE TestValidateToken_WrongAudience1994=== RUN TestValidateToken_Expired1995=== PAUSE TestValidateToken_Expired1996=== RUN TestValidateToken_BoundClaimsMismatch1997=== PAUSE TestValidateToken_BoundClaimsMismatch1998=== RUN TestValidateToken_BoundSubjectMismatch1999=== PAUSE TestValidateToken_BoundSubjectMismatch2000=== RUN TestValidateToken_MultipleProviders2001=== PAUSE TestValidateToken_MultipleProviders2002=== RUN TestValidateToken_NoMatchingProvider2003=== PAUSE TestValidateToken_NoMatchingProvider2004=== RUN TestValidateToken_KubernetesServiceAccount2005=== PAUSE TestValidateToken_KubernetesServiceAccount2006=== RUN TestNewValidator_KubernetesRequiresCA2007=== PAUSE TestNewValidator_KubernetesRequiresCA2008=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2009=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2010=== RUN TestScopes_LegacyProviderDefaultsToWrite2011=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2012=== RUN TestScopes_Rules2013=== PAUSE TestScopes_Rules2014=== RUN TestScopes_ConfigValidation2015=== PAUSE TestScopes_ConfigValidation2016=== CONT TestGlobMatch2017=== CONT TestValidateToken_NoMatchingProvider2018=== CONT TestValidateToken_Expired2019=== RUN TestGlobMatch/foo_foo2020=== PAUSE TestGlobMatch/foo_foo2021=== RUN TestGlobMatch/foo_bar2022=== PAUSE TestGlobMatch/foo_bar2023=== RUN TestGlobMatch/*_2024=== PAUSE TestGlobMatch/*_2025=== RUN TestGlobMatch/*_anything2026=== PAUSE TestGlobMatch/*_anything2027=== RUN TestGlobMatch/foo*_foo2028=== CONT TestValidateToken_MultipleProviders2029=== CONT TestValidateToken_WrongAudience2030=== CONT TestValidateToken_ValidToken2031=== CONT TestAudienceForIssuer2032--- PASS: TestAudienceForIssuer (0.00s)2033=== CONT TestValidateToken_BoundSubjectMismatch2034=== CONT TestScopes_LegacyProviderDefaultsToWrite2035=== CONT TestScopes_ConfigValidation2036=== CONT TestScopes_Rules2037=== PAUSE TestGlobMatch/foo*_foo2038=== RUN TestGlobMatch/foo*_foobar2039=== PAUSE TestGlobMatch/foo*_foobar2040=== RUN TestGlobMatch/foo*_bar2041=== PAUSE TestGlobMatch/foo*_bar2042=== RUN TestGlobMatch/*bar_bar2043=== PAUSE TestGlobMatch/*bar_bar2044=== RUN TestGlobMatch/*bar_foobar2045=== PAUSE TestGlobMatch/*bar_foobar2046=== RUN TestGlobMatch/*bar_foo2047=== PAUSE TestGlobMatch/*bar_foo2048=== RUN TestGlobMatch/foo*bar_foobar2049=== PAUSE TestGlobMatch/foo*bar_foobar2050=== RUN TestGlobMatch/foo*bar_foo123bar2051=== PAUSE TestGlobMatch/foo*bar_foo123bar2052=== RUN TestGlobMatch/foo*bar_foobarbaz2053=== PAUSE TestGlobMatch/foo*bar_foobarbaz2054=== RUN TestGlobMatch/*/*_foo/bar2055=== PAUSE TestGlobMatch/*/*_foo/bar2056=== RUN TestGlobMatch/*/*_foo2057=== PAUSE TestGlobMatch/*/*_foo2058=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2059=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2060=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02061=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02062=== RUN TestGlobMatch/refs/*/main_refs/heads/main2063=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2064=== RUN TestGlobMatch/fo?_foo2065=== PAUSE TestGlobMatch/fo?_foo2066=== RUN TestGlobMatch/fo?_fo2067=== PAUSE TestGlobMatch/fo?_fo2068=== RUN TestGlobMatch/fo?_fooo2069=== PAUSE TestGlobMatch/fo?_fooo2070=== RUN TestGlobMatch/?oo_foo2071=== PAUSE TestGlobMatch/?oo_foo2072=== RUN TestGlobMatch/?oo_boo2073=== PAUSE TestGlobMatch/?oo_boo2074=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2075=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2076=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2077=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2078=== CONT TestNewValidator_KubernetesRequiresCA20792026/09/10 18:32:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54138/oidc20802026/09/10 18:32:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54133/oidc20812026/09/10 18:32:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54137/oidc20822026/09/10 18:32:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54136/oidc20832026/09/10 18:32:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54130/oidc20842026/09/10 18:32:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54132/oidc2085--- PASS: TestScopes_ConfigValidation (0.00s)2086=== CONT TestValidateToken_KubernetesIssuerFromOwnToken20872026/09/10 18:32:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54131/oidc20882026/09/10 18:32:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54139/oidc20892026/09/10 18:32:59 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:54135/oidc2090--- PASS: TestValidateToken_Expired (0.00s)2091=== CONT TestValidateToken_KubernetesServiceAccount20922026/09/10 18:32:59 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232093--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.00s)2094=== CONT TestValidateToken_BoundClaimsMismatch2095--- PASS: TestValidateToken_NoMatchingProvider (0.00s)2096=== CONT TestGlobMatch/foo_foo2097=== CONT TestGlobMatch/*/*_foo/bar2098=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2099=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2100=== CONT TestGlobMatch/?oo_boo2101=== CONT TestGlobMatch/?oo_foo2102=== CONT TestGlobMatch/fo?_fooo2103=== CONT TestGlobMatch/fo?_fo2104=== CONT TestGlobMatch/fo?_foo2105=== CONT TestGlobMatch/refs/*/main_refs/heads/main2106=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02107=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2108=== CONT TestGlobMatch/*/*_foo2109=== CONT TestGlobMatch/*bar_bar2110=== CONT TestGlobMatch/foo*bar_foobarbaz2111=== CONT TestGlobMatch/foo*_foo2112=== CONT TestGlobMatch/foo*_bar2113=== CONT TestGlobMatch/foo*bar_foobar2114=== CONT TestGlobMatch/foo*_foobar2115--- PASS: TestValidateToken_ValidToken (0.00s)2116=== CONT TestGlobMatch/foo*bar_foo123bar2117=== CONT TestGlobMatch/*bar_foobar2118=== CONT TestGlobMatch/foo_bar2119=== CONT TestGlobMatch/*_anything2120--- PASS: TestValidateToken_BoundSubjectMismatch (0.00s)2121=== CONT TestGlobMatch/*_2122=== CONT TestGlobMatch/*bar_foo2123--- PASS: TestGlobMatch (0.00s)2124 --- PASS: TestGlobMatch/foo_foo (0.00s)2125 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2126 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2127 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2128 --- PASS: TestGlobMatch/?oo_boo (0.00s)2129 --- PASS: TestGlobMatch/?oo_foo (0.00s)2130 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2131 --- PASS: TestGlobMatch/fo?_fo (0.00s)2132 --- PASS: TestGlobMatch/fo?_foo (0.00s)2133 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2134 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2135 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2136 --- PASS: TestGlobMatch/*/*_foo (0.00s)2137 --- PASS: TestGlobMatch/*bar_bar (0.00s)2138 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2139 --- PASS: TestGlobMatch/foo*_foo (0.00s)2140 --- PASS: TestGlobMatch/foo*_bar (0.00s)2141 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2142 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2143 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2144 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2145 --- PASS: TestGlobMatch/foo_bar (0.00s)2146 --- PASS: TestGlobMatch/*_anything (0.00s)2147 --- PASS: TestGlobMatch/*_ (0.00s)2148 --- PASS: TestGlobMatch/*bar_foo (0.00s)2149--- PASS: TestValidateToken_WrongAudience (0.00s)21502026/09/10 18:32:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54153/oidc2151--- PASS: TestValidateToken_MultipleProviders (0.01s)2152--- PASS: TestValidateToken_BoundClaimsMismatch (0.00s)21532026/09/10 18:32:59 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:541522154--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.01s)21552026/09/10 18:32:59 http: TLS handshake error from 127.0.0.1:54149: remote error: tls: bad certificate2156--- PASS: TestNewValidator_KubernetesRequiresCA (0.01s)2157--- PASS: TestScopes_Rules (0.01s)2158--- PASS: TestValidateToken_KubernetesServiceAccount (0.00s)2159PASS2160Running hook tests...2161=== RUN TestSendPathsEmpty2162=== PAUSE TestSendPathsEmpty2163=== RUN TestQueueEnqueueAndFetch2164=== PAUSE TestQueueEnqueueAndFetch2165=== RUN TestQueueDeduplication2166=== PAUSE TestQueueDeduplication2167=== RUN TestQueueRemove2168=== PAUSE TestQueueRemove2169=== RUN TestQueueFetchBatchLimit2170=== PAUSE TestQueueFetchBatchLimit2171=== RUN TestQueueRetryMovesToBack2172=== PAUSE TestQueueRetryMovesToBack2173=== RUN TestQueueFetchRemoveLifecycle2174=== PAUSE TestQueueFetchRemoveLifecycle2175=== RUN TestQueueConcurrentWriters2176=== PAUSE TestQueueConcurrentWriters2177=== RUN TestQueueRemoveLargeClosure2178=== PAUSE TestQueueRemoveLargeClosure2179=== RUN TestServerClientIntegration2180=== PAUSE TestServerClientIntegration2181=== RUN TestServerQueueError2182=== PAUSE TestServerQueueError2183=== RUN TestGetListenerSocketActivation2184 server_test.go:210: === RUN TestGetListenerSocketActivation2185 --- PASS: TestGetListenerSocketActivation (0.00s)2186 PASS2187 2188--- PASS: TestGetListenerSocketActivation (0.00s)2189=== RUN TestDrainIsolatesPoisonPath2190=== PAUSE TestDrainIsolatesPoisonPath2191=== RUN TestRunNotBlockedByPoisonHead2192=== PAUSE TestRunNotBlockedByPoisonHead2193=== RUN TestDrainGivesUpWhenServerDown2194=== PAUSE TestDrainGivesUpWhenServerDown2195=== RUN TestFailedPathPrunedByLaterClosure2196=== PAUSE TestFailedPathPrunedByLaterClosure2197=== RUN TestWorkerUploadsAndRemoves2198=== PAUSE TestWorkerUploadsAndRemoves2199=== RUN TestWorkerSkipsGCdPaths2200=== PAUSE TestWorkerSkipsGCdPaths2201=== RUN TestWorkerPrunesClosureDeps2202=== PAUSE TestWorkerPrunesClosureDeps2203=== RUN TestDrainTimeout2204=== PAUSE TestDrainTimeout2205=== CONT TestSendPathsEmpty2206--- PASS: TestSendPathsEmpty (0.00s)2207=== CONT TestServerQueueError2208=== CONT TestWorkerSkipsGCdPaths2209=== CONT TestServerClientIntegration2210=== CONT TestQueueRemoveLargeClosure2211=== CONT TestQueueRemove2212=== CONT TestQueueDeduplication2213=== CONT TestQueueEnqueueAndFetch2214=== CONT TestWorkerUploadsAndRemoves2215=== CONT TestDrainTimeout22162026/09/10 18:32:59 ERROR Failed to queue paths error="permission denied" count=12217=== CONT TestWorkerPrunesClosureDeps2218--- PASS: TestServerQueueError (0.00s)2219=== CONT TestQueueFetchBatchLimit2220--- PASS: TestServerClientIntegration (0.00s)2221=== CONT TestQueueConcurrentWriters2222--- PASS: TestQueueEnqueueAndFetch (0.00s)2223=== CONT TestQueueFetchRemoveLifecycle2224--- PASS: TestQueueFetchBatchLimit (0.00s)2225=== CONT TestQueueRetryMovesToBack22262026/09/10 18:32:59 INFO Uploading batch count=22227--- PASS: TestQueueRemove (0.00s)22282026/09/10 18:32:59 INFO Upload queue status pending=22229=== CONT TestDrainGivesUpWhenServerDown22302026/09/10 18:32:59 INFO Upload queue status pending=222312026/09/10 18:32:59 INFO Uploading batch count=222322026/09/10 18:32:59 INFO Upload queue status pending=222332026/09/10 18:32:59 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-22629-883778699/TestWorkerSkipsGCdPaths3603259720/002/nonexistent22342026/09/10 18:32:59 INFO Uploading batch count=122352026/09/10 18:32:59 INFO Uploading batch count=12236--- PASS: TestQueueDeduplication (0.01s)2237=== CONT TestFailedPathPrunedByLaterClosure2238--- PASS: TestQueueFetchRemoveLifecycle (0.00s)2239=== CONT TestRunNotBlockedByPoisonHead2240--- PASS: TestQueueRetryMovesToBack (0.00s)2241=== CONT TestDrainIsolatesPoisonPath22422026/09/10 18:32:59 INFO Uploading batch count=122432026/09/10 18:32:59 ERROR Upload failed error="upload failed" count=122442026/09/10 18:32:59 INFO Uploading batch count=222452026/09/10 18:32:59 ERROR Upload failed error="upload failed" count=222462026/09/10 18:32:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22629-883778699/TestDrainGivesUpWhenServerDown2185531497/002/a22472026/09/10 18:32:59 INFO Uploading batch count=122482026/09/10 18:32:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22629-883778699/TestDrainGivesUpWhenServerDown2185531497/002/b22492026/09/10 18:32:59 INFO Uploading batch count=222502026/09/10 18:32:59 ERROR Upload failed error="upload failed" count=222512026/09/10 18:32:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22629-883778699/TestDrainGivesUpWhenServerDown2185531497/002/c22522026/09/10 18:32:59 INFO Uploading batch count=122532026/09/10 18:32:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22629-883778699/TestDrainGivesUpWhenServerDown2185531497/002/d22542026/09/10 18:32:59 INFO Uploading batch count=222552026/09/10 18:32:59 ERROR Upload failed error="upload failed" count=222562026/09/10 18:32:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22629-883778699/TestDrainGivesUpWhenServerDown2185531497/002/e22572026/09/10 18:32:59 INFO Uploading batch count=422582026/09/10 18:32:59 ERROR Upload failed error="upload failed" count=422592026/09/10 18:32:59 INFO Upload queue status pending=322602026/09/10 18:32:59 INFO Uploading batch count=122612026/09/10 18:32:59 ERROR Upload failed error="upload failed" count=122622026/09/10 18:32:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22629-883778699/TestDrainIsolatesPoisonPath2330603450/002/bbb22632026/09/10 18:32:59 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-22629-883778699/TestDrainGivesUpWhenServerDown2185531497/002/f2264--- PASS: TestFailedPathPrunedByLaterClosure (0.00s)22652026/09/10 18:32:59 ERROR Drain finished with paths left in queue remaining=1022662026/09/10 18:32:59 INFO Uploading batch count=122672026/09/10 18:32:59 ERROR Upload failed error="upload failed" count=122682026/09/10 18:32:59 INFO Uploading batch count=122692026/09/10 18:32:59 ERROR Upload failed error="upload failed" count=122702026/09/10 18:32:59 INFO Uploading batch count=122712026/09/10 18:32:59 ERROR Upload failed error="upload failed" count=122722026/09/10 18:32:59 ERROR Drain finished with paths left in queue remaining=12273--- PASS: TestDrainGivesUpWhenServerDown (0.00s)2274--- PASS: TestDrainIsolatesPoisonPath (0.00s)2275--- PASS: TestWorkerSkipsGCdPaths (0.03s)2276--- PASS: TestWorkerUploadsAndRemoves (0.03s)2277--- PASS: TestWorkerPrunesClosureDeps (0.03s)2278--- PASS: TestQueueRemoveLargeClosure (0.04s)2279--- PASS: TestQueueConcurrentWriters (0.12s)22802026/09/10 18:32:59 ERROR Upload failed error="context deadline exceeded" count=222812026/09/10 18:32:59 ERROR Drain finished with paths left in queue remaining=42282--- PASS: TestDrainTimeout (0.21s)22832026/09/10 18:33:00 INFO Uploading batch count=122842026/09/10 18:33:00 INFO Uploading batch count=122852026/09/10 18:33:00 INFO Uploading batch count=122862026/09/10 18:33:00 ERROR Upload failed error="upload failed" count=122872026/09/10 18:33:00 INFO Uploading batch count=122882026/09/10 18:33:00 ERROR Upload failed error="upload failed" count=122892026/09/10 18:33:00 INFO Uploading batch count=122902026/09/10 18:33:00 ERROR Upload failed error="upload failed" count=122912026/09/10 18:33:00 INFO Uploading batch count=122922026/09/10 18:33:00 ERROR Upload failed error="upload failed" count=122932026/09/10 18:33:00 ERROR Drain finished with paths left in queue remaining=12294--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2295PASS