niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #239
· raw
1Running client tests...2=== RUN TestDoServerRequestAttachesToken3=== PAUSE TestDoServerRequestAttachesToken4=== RUN TestRegisterUploadedObjectReusesConnections5=== PAUSE TestRegisterUploadedObjectReusesConnections6=== RUN TestCaseHackSuffix7=== PAUSE TestCaseHackSuffix8=== RUN TestFilterOversizedClosures9=== PAUSE TestFilterOversizedClosures10=== RUN TestUploadMultipart_PartsInParallel11=== PAUSE TestUploadMultipart_PartsInParallel12=== RUN TestPartSizeForNAR13=== PAUSE TestPartSizeForNAR14=== RUN TestUploadMultipart_SupersededByPeer15=== PAUSE TestUploadMultipart_SupersededByPeer16=== RUN TestDumpPathCaseHackMatchesNix17--- PASS: TestDumpPathCaseHackMatchesNix (0.13s)18=== RUN TestDumpPathCaseHackCollision19--- PASS: TestDumpPathCaseHackCollision (0.00s)20=== RUN TestDumpPathMatchesNix21=== PAUSE TestDumpPathMatchesNix22=== RUN TestDumpPathSingleFile23=== PAUSE TestDumpPathSingleFile24=== RUN TestDumpPathWriterError25=== PAUSE TestDumpPathWriterError26=== RUN TestEncodeNixBase3227=== PAUSE TestEncodeNixBase3228=== RUN TestEncodeNixBase32WithRealHash29=== PAUSE TestEncodeNixBase32WithRealHash30=== RUN TestConvertHashToNix3231=== PAUSE TestConvertHashToNix3232=== RUN TestGetStorePathHash33=== PAUSE TestGetStorePathHash34=== RUN TestPathInfoHashCompatibility35=== PAUSE TestPathInfoHashCompatibility36=== RUN TestParsePathInfoJSON37=== PAUSE TestParsePathInfoJSON38=== RUN TestParsePathInfoJSONMultiplePaths39=== PAUSE TestParsePathInfoJSONMultiplePaths40=== RUN TestPathInfoCACompatibility41=== PAUSE TestPathInfoCACompatibility42=== RUN TestRateLimiterFeedback43=== PAUSE TestRateLimiterFeedback44=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess45=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== RUN TestResolveStorePath47=== PAUSE TestResolveStorePath48=== RUN TestDoWithRetry_BodyReplayedViaGetBody49=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody50=== RUN TestShellSplit51=== PAUSE TestShellSplit52=== RUN TestShellSplitErrors53=== PAUSE TestShellSplitErrors54=== RUN TestStreamPushReportsEveryPath55=== PAUSE TestStreamPushReportsEveryPath56=== RUN TestStreamPushBatchesUnderLoad57=== PAUSE TestStreamPushBatchesUnderLoad58=== RUN TestStreamPushIsolatesFailures59=== PAUSE TestStreamPushIsolatesFailures60=== RUN TestStreamPushGivesUpOnDeadServer61=== PAUSE TestStreamPushGivesUpOnDeadServer62=== RUN TestStreamPushRequestLine63=== PAUSE TestStreamPushRequestLine64=== RUN TestSetClientTLS65=== PAUSE TestSetClientTLS66=== RUN TestSetClientTLSDoesNotMutateDefaultTransport67=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport68=== RUN TestSetClientTLSErrors69=== PAUSE TestSetClientTLSErrors70=== RUN TestStaticToken71=== PAUSE TestStaticToken72=== RUN TestFileTokenReadsAndCaches73=== PAUSE TestFileTokenReadsAndCaches74=== RUN TestFileTokenMissing75=== PAUSE TestFileTokenMissing76=== RUN TestFileTokenEmpty77=== PAUSE TestFileTokenEmpty78=== RUN TestScriptTokenNoExpiryRerunsEveryCall79=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall80=== RUN TestScriptTokenCachesUntilRefresh81=== PAUSE TestScriptTokenCachesUntilRefresh82=== RUN TestScriptTokenEmptyToken83=== PAUSE TestScriptTokenEmptyToken84=== RUN TestScriptTokenBadJSON85=== PAUSE TestScriptTokenBadJSON86=== RUN TestScriptTokenScriptFails87=== PAUSE TestScriptTokenScriptFails88=== RUN TestScriptTokenEmptyCommand89=== PAUSE TestScriptTokenEmptyCommand90=== CONT TestDoServerRequestAttachesToken91=== CONT TestDoWithRetry_BodyReplayedViaGetBody92=== CONT TestStaticToken93--- PASS: TestStaticToken (0.00s)94=== CONT TestFileTokenMissing95=== CONT TestScriptTokenEmptyCommand96--- PASS: TestScriptTokenEmptyCommand (0.00s)97=== CONT TestFileTokenReadsAndCaches98=== CONT TestScriptTokenScriptFails99--- PASS: TestFileTokenMissing (0.00s)100=== CONT TestEncodeNixBase32WithRealHash101--- PASS: TestEncodeNixBase32WithRealHash (0.00s)102=== CONT TestResolveStorePath103=== CONT TestScriptTokenBadJSON104=== CONT TestScriptTokenEmptyToken105=== CONT TestScriptTokenCachesUntilRefresh106=== CONT TestScriptTokenNoExpiryRerunsEveryCall107=== CONT TestFileTokenEmpty108--- PASS: TestFileTokenReadsAndCaches (0.00s)109=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1102026/09/21 18:12:30 WARN Rate limiter enabled after throttle name=server-test rate=5111--- PASS: TestFileTokenEmpty (0.00s)112=== CONT TestRateLimiterFeedback113=== RUN TestRateLimiterFeedback/429_enables_limiter114--- PASS: TestResolveStorePath (0.00s)115=== CONT TestPathInfoCACompatibility116=== RUN TestPathInfoCACompatibility/null_ca_field117=== PAUSE TestPathInfoCACompatibility/null_ca_field118=== RUN TestPathInfoCACompatibility/old_string_format_-_text119=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text120=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive121=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive122=== RUN TestPathInfoCACompatibility/new_structured_format_-_text123=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text124=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method125=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method126=== CONT TestParsePathInfoJSONMultiplePaths127=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths128=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths129=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths130=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths131=== CONT TestParsePathInfoJSON132=== RUN TestParsePathInfoJSON/Nix_format133=== PAUSE TestParsePathInfoJSON/Nix_format134=== RUN TestParsePathInfoJSON/Lix_format135=== PAUSE TestParsePathInfoJSON/Lix_format136=== RUN TestParsePathInfoJSON/empty_input137=== PAUSE TestParsePathInfoJSON/empty_input138=== RUN TestParsePathInfoJSON/whitespace_only139=== PAUSE TestParsePathInfoJSON/whitespace_only140=== RUN TestParsePathInfoJSON/invalid_JSON141=== PAUSE TestParsePathInfoJSON/invalid_JSON142=== CONT TestPathInfoHashCompatibility143=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)144=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)145=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon146=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon147=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI148=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI149=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512150=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512151=== CONT TestGetStorePathHash152=== RUN TestGetStorePathHash/valid_store_path153=== PAUSE TestGetStorePathHash/valid_store_path154=== RUN TestGetStorePathHash/basename_without_hyphen_should_error155=== PAUSE TestRateLimiterFeedback/429_enables_limiter156=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error157=== RUN TestRateLimiterFeedback/503_enables_limiter158=== PAUSE TestRateLimiterFeedback/503_enables_limiter159=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter160=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter161=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter162=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter163=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error164=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error165=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error166=== CONT TestConvertHashToNix321672026/09/21 18:12:30 WARN Rate limiter enabled after throttle name=server-test rate=5168=== RUN TestConvertHashToNix32/SRI_format_to_Nix321692026/09/21 18:12:30 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:50764170=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error171--- PASS: TestDoServerRequestAttachesToken (0.00s)172=== CONT TestEncodeNixBase32173=== CONT TestUploadMultipart_SupersededByPeer174=== RUN TestEncodeNixBase32/test_string_hash175=== PAUSE TestEncodeNixBase32/test_string_hash176=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32177=== RUN TestConvertHashToNix32/already_Nix32_format178=== RUN TestUploadMultipart_SupersededByPeer/exists179=== PAUSE TestConvertHashToNix32/already_Nix32_format180=== PAUSE TestUploadMultipart_SupersededByPeer/exists181=== RUN TestConvertHashToNix32/invalid_format182=== PAUSE TestConvertHashToNix32/invalid_format183=== RUN TestEncodeNixBase32/empty_input184=== PAUSE TestEncodeNixBase32/empty_input185=== CONT TestDumpPathWriterError186=== RUN TestUploadMultipart_SupersededByPeer/missing187=== CONT TestDumpPathSingleFile188=== PAUSE TestUploadMultipart_SupersededByPeer/missing189=== CONT TestDumpPathMatchesNix1902026/09/21 18:12:30 WARN Rate limiter backed off name=server-test rate=51912026/09/21 18:12:30 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:50764192--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)193=== CONT TestFilterOversizedClosures194=== RUN TestFilterOversizedClosures/no_limit_keeps_everything195=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything196=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped197=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped198=== RUN TestFilterOversizedClosures/all_closures_skipped199=== PAUSE TestFilterOversizedClosures/all_closures_skipped200=== CONT TestPartSizeForNAR201=== RUN TestPartSizeForNAR/zero_stays_at_minimum202--- PASS: TestScriptTokenScriptFails (0.01s)203=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum204=== RUN TestPartSizeForNAR/small_stays_at_minimum205=== PAUSE TestPartSizeForNAR/small_stays_at_minimum206=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum207=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum208=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts209=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts210=== RUN TestPartSizeForNAR/1_TiB211=== PAUSE TestPartSizeForNAR/1_TiB212=== RUN TestPartSizeForNAR/5_TiB_S3_max_object213=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object214=== RUN TestPartSizeForNAR/capped_at_5_GiB215=== PAUSE TestPartSizeForNAR/capped_at_5_GiB216=== CONT TestCaseHackSuffix217=== CONT TestUploadMultipart_PartsInParallel218--- PASS: TestScriptTokenBadJSON (0.01s)219=== CONT TestStreamPushGivesUpOnDeadServer2202026/09/21 18:12:30 ERROR Upload failed error="connection refused" count=202212026/09/21 18:12:30 ERROR Server seems unavailable, giving up on batch untried=17222--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)223=== CONT TestSetClientTLSErrors224--- PASS: TestScriptTokenEmptyToken (0.01s)225=== CONT TestSetClientTLSDoesNotMutateDefaultTransport226=== RUN TestSetClientTLSErrors/missing_cert_file227=== PAUSE TestSetClientTLSErrors/missing_cert_file228=== RUN TestSetClientTLSErrors/missing_key_file229=== PAUSE TestSetClientTLSErrors/missing_key_file230=== RUN TestSetClientTLSErrors/missing_ca_file231=== PAUSE TestSetClientTLSErrors/missing_ca_file232=== RUN TestSetClientTLSErrors/invalid_ca_file233=== PAUSE TestSetClientTLSErrors/invalid_ca_file234=== CONT TestSetClientTLS235--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)236=== CONT TestStreamPushRequestLine2372026/09/21 18:12:30 ERROR Upload failed error=boom count=1238=== RUN TestSetClientTLS/rejects_connection_without_client_cert239=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert240=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA241=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA242=== RUN TestSetClientTLS/preserves_debug_logging_transport243=== PAUSE TestSetClientTLS/preserves_debug_logging_transport244=== CONT TestRegisterUploadedObjectReusesConnections245--- PASS: TestStreamPushRequestLine (0.01s)246=== CONT TestStreamPushReportsEveryPath247--- PASS: TestStreamPushReportsEveryPath (0.00s)248=== CONT TestStreamPushIsolatesFailures2492026/09/21 18:12:30 ERROR Upload failed error="bad path" count=3250--- PASS: TestStreamPushIsolatesFailures (0.00s)251=== CONT TestStreamPushBatchesUnderLoad252--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)253=== CONT TestShellSplitErrors254--- PASS: TestShellSplitErrors (0.00s)255=== CONT TestShellSplit256--- PASS: TestShellSplit (0.00s)257=== CONT TestPathInfoCACompatibility/null_ca_field258=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths259=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method260=== CONT TestPathInfoCACompatibility/new_structured_format_-_text261=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive262=== CONT TestPathInfoCACompatibility/old_string_format_-_text263--- PASS: TestPathInfoCACompatibility (0.00s)264 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)265 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)266 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)267 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)268 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)269=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths270=== CONT TestParsePathInfoJSON/empty_input271=== CONT TestParsePathInfoJSON/whitespace_only272=== CONT TestParsePathInfoJSON/Lix_format273=== CONT TestParsePathInfoJSON/invalid_JSON274=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)275=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI276=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512277=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon278=== CONT TestRateLimiterFeedback/429_enables_limiter279--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)280--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)281 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)282 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)283=== CONT TestParsePathInfoJSON/Nix_format284--- PASS: TestPathInfoHashCompatibility (0.00s)285 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)286 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)287 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)288 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)289--- PASS: TestParsePathInfoJSON (0.00s)290 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)291 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)292 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)293 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)294 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)295=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2962026/09/21 18:12:30 WARN Rate limiter enabled after throttle name=server-test rate=52972026/09/21 18:12:30 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:508402982026/09/21 18:12:30 WARN Rate limiter backed off name=server-test rate=5299=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter300=== CONT TestRateLimiterFeedback/503_enables_limiter301=== CONT TestGetStorePathHash/valid_store_path302=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error303=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error304=== CONT TestGetStorePathHash/basename_without_hyphen_should_error305--- PASS: TestGetStorePathHash (0.00s)306 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)307 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)308 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)309 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)310=== CONT TestEncodeNixBase32/test_string_hash311=== CONT TestConvertHashToNix32/SRI_format_to_Nix32312=== CONT TestConvertHashToNix32/invalid_format313=== CONT TestConvertHashToNix32/already_Nix32_format314--- PASS: TestConvertHashToNix32 (0.00s)315 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)316 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)317 2026/09/21 18:12:30 WARN Rate limiter enabled after throttle name=server-test rate=53182026/09/21 18:12:30 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:508463192026/09/21 18:12:30 WARN Rate limiter backed off name=server-test rate=5320 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)321=== CONT TestEncodeNixBase32/empty_input322=== CONT TestUploadMultipart_SupersededByPeer/missing323=== CONT TestUploadMultipart_SupersededByPeer/exists324--- PASS: TestRateLimiterFeedback (0.00s)325 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)326 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)327 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)328 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)329--- PASS: TestEncodeNixBase32 (0.00s)330 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)331 --- PASS: TestEncodeNixBase32/empty_input (0.00s)332=== CONT TestFilterOversizedClosures/no_limit_keeps_everything333=== CONT TestFilterOversizedClosures/all_closures_skipped3342026/09/21 18:12:30 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50335=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3362026/09/21 18:12:30 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=2000337--- PASS: TestFilterOversizedClosures (0.00s)338 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)339 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)340 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)341--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)342 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)343 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)344=== CONT TestPartSizeForNAR/1_TiB345=== CONT TestPartSizeForNAR/capped_at_5_GiB346=== CONT TestPartSizeForNAR/5_TiB_S3_max_object347=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum348=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts349=== CONT TestPartSizeForNAR/small_stays_at_minimum350=== CONT TestSetClientTLSErrors/missing_cert_file351=== CONT TestPartSizeForNAR/zero_stays_at_minimum352--- PASS: TestPartSizeForNAR (0.00s)353 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)354 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)355 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)356 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)357 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)358 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)359 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)360=== CONT TestSetClientTLSErrors/invalid_ca_file361=== CONT TestSetClientTLSErrors/missing_ca_file362--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)363=== CONT TestSetClientTLSErrors/missing_key_file364=== CONT TestSetClientTLS/rejects_connection_without_client_cert365=== CONT TestSetClientTLS/preserves_debug_logging_transport366=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA367--- PASS: TestDumpPathWriterError (0.04s)368--- PASS: TestSetClientTLSErrors (0.00s)369 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)370 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)371 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)372 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)3732026/09/21 18:12:30 http: TLS handshake error from 127.0.0.1:50852: remote error: tls: bad certificate374--- PASS: TestSetClientTLS (0.00s)375 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)376 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)377 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)378--- PASS: TestDumpPathSingleFile (0.05s)379--- PASS: TestCaseHackSuffix (0.05s)380--- PASS: TestDumpPathMatchesNix (0.07s)381--- PASS: TestStreamPushBatchesUnderLoad (0.10s)382--- PASS: TestUploadMultipart_PartsInParallel (0.61s)383--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)384PASS385Running server tests...386The files belonging to this database system will be owned by user "_nixbld10".387This user must also own the server process.388389The database cluster will be initialized with locale "C".390The default database encoding has accordingly been set to "SQL_ASCII".391The default text search configuration will be set to "english".392393Data page checksums are enabled.394395creating directory /nix/var/nix/builds/nix-4239-4131808779/postgres417042305/data ... ok396creating subdirectories ... ok397selecting dynamic shared memory implementation ... posix398selecting default "max_connections" ... 100399selecting default "shared_buffers" ... 128MB400selecting default time zone ... UTC401creating configuration files ... ok402running bootstrap script ... ok403performing post-bootstrap initialization ... ok404syncing data to disk ... ok405406initdb: warning: enabling "trust" authentication for local connections407initdb: 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.408409Success. You can now start the database server using:410411 pg_ctl -D /nix/var/nix/builds/nix-4239-4131808779/postgres417042305/data -l logfile start4124132026-09-21 18:12:32.225 UTC [4312] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4142026-09-21 18:12:32.225 UTC [4312] LOG: listening on Unix socket "/nix/var/nix/builds/nix-4239-4131808779/postgres417042305/.s.PGSQL.5432"4152026-09-21 18:12:32.227 UTC [4319] LOG: database system was shut down at 2026-09-21 18:12:32 UTC4162026-09-21 18:12:32.228 UTC [4320] FATAL: the database system is starting up417/nix/var/nix/builds/nix-4239-4131808779/postgres417042305:5432 - rejecting connections4182026-09-21 18:12:32.228 UTC [4312] LOG: database system is ready to accept connections419/nix/var/nix/builds/nix-4239-4131808779/postgres417042305:5432 - accepting connections420{"timestamp":"2026-09-21T18:12:32.476959Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"1d4734bb-0e5e-4d9e-a388-a73e69791b35","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"duration_ms":9,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":430,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}421{"timestamp":"2026-09-21T18:12:32.584351Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"d7791de1-889b-4ba9-9ee0-c57a2d22f85d","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":430,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}422{"timestamp":"2026-09-21T18:12:32.687517Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"9314ca9b-631f-4e22-8dcf-14edb86484a4","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":430,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}423=== RUN TestService_AuthMiddleware424=== PAUSE TestService_AuthMiddleware425=== RUN TestService_AuthMiddleware_MTLSProxyHeader426=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader427=== RUN TestService_AuthMiddleware_MTLSBoundSubjects428=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects429=== RUN TestService_ReadAuthMiddleware430=== PAUSE TestService_ReadAuthMiddleware431=== RUN TestService_AuthMiddleware_OIDC432=== PAUSE TestService_AuthMiddleware_OIDC433=== RUN TestService_RequireScope_OIDC434=== PAUSE TestService_RequireScope_OIDC435=== RUN TestService_ReadScope_PublicByDefault436=== PAUSE TestService_ReadScope_PublicByDefault437=== RUN TestCacheConfigHandler438=== PAUSE TestCacheConfigHandler439=== RUN TestCacheStatsHandler440=== PAUSE TestCacheStatsHandler441=== RUN TestClientCADerivations442=== PAUSE TestClientCADerivations443=== RUN TestClientErrorHandling444=== PAUSE TestClientErrorHandling445=== RUN TestClientIntegration446=== PAUSE TestClientIntegration447=== RUN TestClientMultipleUploads448=== PAUSE TestClientMultipleUploads449=== RUN TestClientWithDependencies450=== PAUSE TestClientWithDependencies451=== RUN TestClientSharedPathCommittedMidPush452=== PAUSE TestClientSharedPathCommittedMidPush453=== RUN TestPinProtectsFromGC454=== PAUSE TestPinProtectsFromGC455=== RUN TestResolveDBConnectionString456=== PAUSE TestResolveDBConnectionString457=== RUN TestLeadElectsOneAndHandsOver458=== PAUSE TestLeadElectsOneAndHandsOver459=== RUN TestLeadIncumbentWinsAfterRestart4602026-09-21 18:12:32.898 UTC [4398] ERROR: relation "goose_db_version" does not exist at character 364612026-09-21 18:12:32.898 UTC [4398] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4622026/09/21 18:12:32 OK 20241026095416_initial_model.sql (4.96ms)4632026/09/21 18:12:32 OK 20251210153512_drop_unused_gin_index.sql (468.63µs)4642026/09/21 18:12:32 OK 20251218171726_add_pins.sql (946.17µs)4652026/09/21 18:12:32 OK 20260628120000_add_object_size_and_stats.sql (1.02ms)4662026/09/21 18:12:32 OK 20260905000000_add_claims.sql (1.06ms)4672026/09/21 18:12:32 OK 20260920000000_drop_claims.sql (642.67µs)4682026/09/21 18:12:32 goose: successfully migrated database to version: 202609200000004692026/09/21 18:12:32 OK 1_commit_pending_closure.sql (1.64ms)4702026/09/21 18:12:32 OK 2_object_stats_trigger.sql (202.38µs)4712026/09/21 18:12:32 goose: up to current file version: 24722026/09/21 18:12:32 INFO lead: acquired remote=192.0.2.1:12344732026/09/21 18:12:33 INFO lead: released remote=192.0.2.1:12344742026/09/21 18:12:33 INFO lead: acquired remote=192.0.2.1:12344752026/09/21 18:12:33 INFO lead: released remote=192.0.2.1:1234476--- PASS: TestLeadIncumbentWinsAfterRestart (0.85s)477=== RUN TestLeadEndsOnShutdown478=== PAUSE TestLeadEndsOnShutdown479=== RUN TestGCAdvisoryLockBlocksConcurrentRun4802026-09-21 18:12:33.680 UTC [4411] ERROR: relation "goose_db_version" does not exist at character 364812026-09-21 18:12:33.680 UTC [4411] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4822026/09/21 18:12:33 OK 20241026095416_initial_model.sql (3.02ms)4832026/09/21 18:12:33 OK 20251210153512_drop_unused_gin_index.sql (377.5µs)4842026/09/21 18:12:33 OK 20251218171726_add_pins.sql (718.88µs)4852026/09/21 18:12:33 OK 20260628120000_add_object_size_and_stats.sql (810.5µs)4862026/09/21 18:12:33 OK 20260905000000_add_claims.sql (873.92µs)4872026/09/21 18:12:33 OK 20260920000000_drop_claims.sql (564.04µs)4882026/09/21 18:12:33 goose: successfully migrated database to version: 202609200000004892026/09/21 18:12:33 OK 1_commit_pending_closure.sql (786.88µs)4902026/09/21 18:12:33 OK 2_object_stats_trigger.sql (207.63µs)4912026/09/21 18:12:33 goose: up to current file version: 2492--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.11s)493=== RUN TestGCBugBareHashReferences494=== PAUSE TestGCBugBareHashReferences495=== RUN TestGCMetrics496=== PAUSE TestGCMetrics497=== RUN TestGCTaskStore_StartNew498=== PAUSE TestGCTaskStore_StartNew499=== RUN TestGCTaskStore_DeduplicateSameParams500=== PAUSE TestGCTaskStore_DeduplicateSameParams501=== RUN TestGCTaskStore_ConflictDifferentParams502=== PAUSE TestGCTaskStore_ConflictDifferentParams503=== RUN TestGCTaskStore_GetEmpty504=== PAUSE TestGCTaskStore_GetEmpty505=== RUN TestGCTaskStore_GetReturnsLatest506=== PAUSE TestGCTaskStore_GetReturnsLatest507=== RUN TestGCTaskStore_CompletedAllowsNewTask508=== PAUSE TestGCTaskStore_CompletedAllowsNewTask509=== RUN TestGCTaskStore_PhaseUpdates510=== PAUSE TestGCTaskStore_PhaseUpdates511=== RUN TestGCTaskStore_Fail512=== PAUSE TestGCTaskStore_Fail513=== RUN TestGracefulShutdownDrainsInflight514=== PAUSE TestGracefulShutdownDrainsInflight515=== RUN TestService_healthCheckHandler516=== PAUSE TestService_healthCheckHandler517=== RUN TestService_readinessHandler518=== PAUSE TestService_readinessHandler519=== RUN TestGenerateLandingPage520=== PAUSE TestGenerateLandingPage521=== RUN TestCacheConfigHandlerMaxNarSize522=== PAUSE TestCacheConfigHandlerMaxNarSize523=== RUN TestCreatePendingClosureRejectsOversizedNAR524=== PAUSE TestCreatePendingClosureRejectsOversizedNAR525=== RUN TestNARDeduplicationMetadataUploadBug526=== PAUSE TestNARDeduplicationMetadataUploadBug527=== RUN TestMetricsInventory528=== PAUSE TestMetricsInventory529=== RUN TestService_NativeMTLS530=== PAUSE TestService_NativeMTLS531=== RUN TestServerTLSConfig532=== PAUSE TestServerTLSConfig533=== RUN TestMultipartCleanup534=== PAUSE TestMultipartCleanup535=== RUN TestObjectStatsTrigger536=== PAUSE TestObjectStatsTrigger537=== RUN TestOrphanedObjectsGC538=== PAUSE TestOrphanedObjectsGC539=== RUN TestOrphanedObjectsGCStressTest540=== PAUSE TestOrphanedObjectsGCStressTest541=== RUN TestResurrectedObjectNotDeleted542=== PAUSE TestResurrectedObjectNotDeleted543=== RUN TestCreatePin_ReservedPins544=== PAUSE TestCreatePin_ReservedPins545=== RUN TestParseSingleRange546=== PAUSE TestParseSingleRange547=== RUN TestIsValidCachePath548=== PAUSE TestIsValidCachePath549=== RUN TestReadProxyNarinfo550=== PAUSE TestReadProxyNarinfo551=== RUN TestReadProxyNarinfoAlreadyDecompressed552=== PAUSE TestReadProxyNarinfoAlreadyDecompressed553=== RUN TestReadProxyNarStreaming554=== PAUSE TestReadProxyNarStreaming555=== RUN TestReadProxy404556=== PAUSE TestReadProxy404557=== RUN TestReadProxyInvalidPath558=== PAUSE TestReadProxyInvalidPath559=== RUN TestReadProxyHead560=== PAUSE TestReadProxyHead561=== RUN TestReadProxyConditionalGet562=== PAUSE TestReadProxyConditionalGet563=== RUN TestReadProxyRootRedirectsToIndexHTML564=== PAUSE TestReadProxyRootRedirectsToIndexHTML565=== RUN TestReadProxyDisabled566=== PAUSE TestReadProxyDisabled567=== RUN TestReadRedirectNar568=== PAUSE TestReadRedirectNar569=== RUN TestReadRedirectKeepsNarinfoProxied570=== PAUSE TestReadRedirectKeepsNarinfoProxied571=== RUN TestReadProxyRangeRequest572=== PAUSE TestReadProxyRangeRequest573=== RUN TestReadRedirectUsesPublicS3URL574=== PAUSE TestReadRedirectUsesPublicS3URL575=== RUN TestRedundantMultipartUpload576=== PAUSE TestRedundantMultipartUpload577=== RUN TestCompleteMultipartUpload_ErrorButObjectExists578=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists579=== RUN TestCompletedNarNotReofferedAcrossClosures580=== PAUSE TestCompletedNarNotReofferedAcrossClosures581=== RUN TestPresignedUploadRegisteredBeforeCommit582=== PAUSE TestPresignedUploadRegisteredBeforeCommit583=== RUN TestService_Rustfstest584=== PAUSE TestService_Rustfstest585=== RUN TestParseSize586=== PAUSE TestParseSize587=== RUN TestSkippedUploadsHandler588=== PAUSE TestSkippedUploadsHandler589=== RUN TestSystemdListenerNotActivated590--- PASS: TestSystemdListenerNotActivated (0.00s)591=== RUN TestWatchdogBeatsWhenHealthy592--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)593=== RUN TestWatchdogSkipsWhenUnhealthy5942026/09/21 18:12:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5952026/09/21 18:12:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5962026/09/21 18:12:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5972026/09/21 18:12:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5982026/09/21 18:12:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"5992026/09/21 18:12:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6002026/09/21 18:12:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6012026/09/21 18:12:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6022026/09/21 18:12:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6032026/09/21 18:12:33 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"604--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)605=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle606=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle607=== RUN TestProxyWriteTimeout608=== PAUSE TestProxyWriteTimeout609=== RUN TestIsValidUploadKey610=== PAUSE TestIsValidUploadKey611=== RUN TestUploadHandlersRejectInvalidKeys612=== PAUSE TestUploadHandlersRejectInvalidKeys613=== RUN TestUploadHandlersRejectOversizedBody614=== PAUSE TestUploadHandlersRejectOversizedBody615=== RUN TestService_cleanupPendingClosuresHandler616=== PAUSE TestService_cleanupPendingClosuresHandler617=== RUN TestService_createPendingClosureHandler618=== PAUSE TestService_createPendingClosureHandler619=== RUN TestService_verifyS3Integrity620=== PAUSE TestService_verifyS3Integrity621=== RUN TestCompleteMultipartUnregistered622=== PAUSE TestCompleteMultipartUnregistered623=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT624=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT625=== CONT TestService_AuthMiddleware626=== CONT TestMultipartCleanup627=== CONT TestGCMetrics628=== CONT TestGCBugBareHashReferences629=== CONT TestService_healthCheckHandler630=== CONT TestService_AuthMiddleware_OIDC631=== CONT TestClientErrorHandling632=== RUN TestClientErrorHandling/InvalidStorePath633=== PAUSE TestClientErrorHandling/InvalidStorePath634=== CONT TestService_RequireScope_OIDC635=== CONT TestClientCADerivations636=== CONT TestCacheStatsHandler637=== RUN TestClientErrorHandling/InvalidAuthToken638=== PAUSE TestClientErrorHandling/InvalidAuthToken639=== RUN TestClientErrorHandling/ServerNotAvailable640=== PAUSE TestClientErrorHandling/ServerNotAvailable641=== CONT TestCacheConfigHandler642=== RUN TestCacheConfigHandler/full_config,_no_issuer643=== PAUSE TestCacheConfigHandler/full_config,_no_issuer644=== RUN TestCacheConfigHandler/no_cache_url_configured645=== PAUSE TestCacheConfigHandler/no_cache_url_configured646=== RUN TestCacheConfigHandler/no_signing_keys647=== PAUSE TestCacheConfigHandler/no_signing_keys648=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator649=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator650=== CONT TestService_ReadScope_PublicByDefault6512026/09/21 18:12:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50873/oidc6522026/09/21 18:12:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50872/oidc6532026-09-21 18:12:34.300 UTC [4435] ERROR: relation "goose_db_version" does not exist at character 366542026-09-21 18:12:34.300 UTC [4435] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6552026-09-21 18:12:34.305 UTC [4436] ERROR: relation "goose_db_version" does not exist at character 366562026-09-21 18:12:34.305 UTC [4436] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6572026-09-21 18:12:34.307 UTC [4437] ERROR: relation "goose_db_version" does not exist at character 366582026-09-21 18:12:34.307 UTC [4437] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6592026-09-21 18:12:34.308 UTC [4438] ERROR: relation "goose_db_version" does not exist at character 366602026-09-21 18:12:34.308 UTC [4438] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6612026-09-21 18:12:34.311 UTC [4439] ERROR: relation "goose_db_version" does not exist at character 366622026-09-21 18:12:34.311 UTC [4439] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6632026-09-21 18:12:34.311 UTC [4440] ERROR: relation "goose_db_version" does not exist at character 366642026-09-21 18:12:34.311 UTC [4440] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6652026-09-21 18:12:34.312 UTC [4441] ERROR: relation "goose_db_version" does not exist at character 366662026-09-21 18:12:34.312 UTC [4441] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6672026-09-21 18:12:34.312 UTC [4443] ERROR: relation "goose_db_version" does not exist at character 366682026-09-21 18:12:34.312 UTC [4443] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6692026-09-21 18:12:34.313 UTC [4442] ERROR: relation "goose_db_version" does not exist at character 366702026-09-21 18:12:34.313 UTC [4442] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6712026-09-21 18:12:34.314 UTC [4444] ERROR: relation "goose_db_version" does not exist at character 366722026-09-21 18:12:34.314 UTC [4444] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6732026/09/21 18:12:34 OK 20241026095416_initial_model.sql (5.65ms)6742026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (1.09ms)6752026/09/21 18:12:34 OK 20241026095416_initial_model.sql (8.72ms)6762026/09/21 18:12:34 OK 20251218171726_add_pins.sql (1.89ms)6772026/09/21 18:12:34 OK 20241026095416_initial_model.sql (7.66ms)6782026/09/21 18:12:34 OK 20241026095416_initial_model.sql (7.23ms)6792026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (1.31ms)6802026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (821.04µs)6812026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (888.54µs)6822026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (2.45ms)6832026/09/21 18:12:34 OK 20251218171726_add_pins.sql (1.69ms)6842026/09/21 18:12:34 OK 20251218171726_add_pins.sql (1.88ms)6852026/09/21 18:12:34 OK 20251218171726_add_pins.sql (2.49ms)6862026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (1.91ms)6872026/09/21 18:12:34 OK 20260905000000_add_claims.sql (2.57ms)6882026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (1.74ms)6892026/09/21 18:12:34 OK 20241026095416_initial_model.sql (7.87ms)6902026/09/21 18:12:34 OK 20241026095416_initial_model.sql (8.22ms)6912026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (1.87ms)6922026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (847.75µs)6932026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (1.42ms)6942026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000006952026/09/21 18:12:34 OK 20241026095416_initial_model.sql (8.78ms)6962026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (810.21µs)6972026/09/21 18:12:34 OK 20260905000000_add_claims.sql (2.2ms)6982026/09/21 18:12:34 OK 20241026095416_initial_model.sql (8.44ms)6992026/09/21 18:12:34 OK 20241026095416_initial_model.sql (7.82ms)7002026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (821.67µs)7012026/09/21 18:12:34 OK 20251218171726_add_pins.sql (1.33ms)7022026/09/21 18:12:34 OK 20260905000000_add_claims.sql (1.7ms)7032026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (735.25µs)7042026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (896.96µs)7052026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (1.41ms)7062026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000007072026/09/21 18:12:34 OK 1_commit_pending_closure.sql (2.09ms)7082026/09/21 18:12:34 OK 20260905000000_add_claims.sql (3.28ms)7092026/09/21 18:12:34 OK 20251218171726_add_pins.sql (1.98ms)7102026/09/21 18:12:34 OK 20251218171726_add_pins.sql (1.55ms)7112026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (1.22ms)7122026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000007132026/09/21 18:12:34 OK 20241026095416_initial_model.sql (9.92ms)7142026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (1.47ms)7152026/09/21 18:12:34 OK 2_object_stats_trigger.sql (766.17µs)7162026/09/21 18:12:34 goose: up to current file version: 27172026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (949.25µs)7182026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000007192026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (834.13µs)7202026/09/21 18:12:34 OK 1_commit_pending_closure.sql (1.75ms)7212026/09/21 18:12:34 OK 20251218171726_add_pins.sql (1.84ms)7222026/09/21 18:12:34 OK 20251218171726_add_pins.sql (2.36ms)7232026/09/21 18:12:34 OK 1_commit_pending_closure.sql (1.26ms)7242026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (1.7ms)7252026/09/21 18:12:34 OK 2_object_stats_trigger.sql (652.25µs)7262026/09/21 18:12:34 goose: up to current file version: 27272026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (1.99ms)7282026/09/21 18:12:34 OK 1_commit_pending_closure.sql (1.13ms)7292026/09/21 18:12:34 OK 2_object_stats_trigger.sql (560.58µs)7302026/09/21 18:12:34 goose: up to current file version: 27312026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (1.22ms)7322026/09/21 18:12:34 OK 2_object_stats_trigger.sql (532.08µs)7332026/09/21 18:12:34 goose: up to current file version: 27342026/09/21 18:12:34 OK 20260905000000_add_claims.sql (2.17ms)7352026/09/21 18:12:34 OK 20251218171726_add_pins.sql (1.56ms)7362026/09/21 18:12:34 OK 20260905000000_add_claims.sql (1.82ms)7372026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (2.3ms)7382026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (5.15ms)7392026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000007402026/09/21 18:12:34 OK 1_commit_pending_closure.sql (975.71µs)7412026/09/21 18:12:34 OK 20260905000000_add_claims.sql (7.07ms)7422026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (5.38ms)7432026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000007442026/09/21 18:12:34 OK 20260905000000_add_claims.sql (6.67ms)7452026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (6.52ms)7462026/09/21 18:12:34 OK 2_object_stats_trigger.sql (505.67µs)7472026/09/21 18:12:34 goose: up to current file version: 27482026/09/21 18:12:34 OK 20260905000000_add_claims.sql (6.06ms)7492026/09/21 18:12:34 OK 1_commit_pending_closure.sql (1.02ms)7502026/09/21 18:12:34 OK 2_object_stats_trigger.sql (181µs)7512026/09/21 18:12:34 goose: up to current file version: 27522026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (21.08ms)7532026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000007542026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (21.22ms)7552026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000007562026/09/21 18:12:34 OK 1_commit_pending_closure.sql (883.63µs)7572026/09/21 18:12:34 OK 1_commit_pending_closure.sql (694µs)7582026/09/21 18:12:34 OK 2_object_stats_trigger.sql (193.96µs)7592026/09/21 18:12:34 goose: up to current file version: 27602026/09/21 18:12:34 OK 2_object_stats_trigger.sql (209.29µs)7612026/09/21 18:12:34 goose: up to current file version: 27622026/09/21 18:12:34 OK 20260905000000_add_claims.sql (24.92ms)7632026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (24.4ms)7642026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000007652026/09/21 18:12:34 OK 1_commit_pending_closure.sql (681.63µs)7662026/09/21 18:12:34 OK 2_object_stats_trigger.sql (180.33µs)7672026/09/21 18:12:34 goose: up to current file version: 27682026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (5.9ms)7692026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000007702026/09/21 18:12:34 OK 1_commit_pending_closure.sql (653.83µs)7712026/09/21 18:12:34 OK 2_object_stats_trigger.sql (174.63µs)7722026/09/21 18:12:34 goose: up to current file version: 27732026/09/21 18:12:34 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"774--- PASS: TestService_AuthMiddleware (0.45s)775=== CONT TestGCTaskStore_Fail776--- PASS: TestGCTaskStore_Fail (0.00s)777=== CONT TestGracefulShutdownDrainsInflight7782026/09/21 18:12:34 INFO Starting HTTP server address=127.0.0.1:508777792026/09/21 18:12:34 INFO Shutdown signal received, draining in-flight requests timeout=10s780--- PASS: TestGracefulShutdownDrainsInflight (0.07s)781=== CONT TestNARDeduplicationMetadataUploadBug782--- PASS: TestCacheStatsHandler (0.85s)783=== CONT TestServerTLSConfig784=== RUN TestServerTLSConfig/no_client_CA785=== PAUSE TestServerTLSConfig/no_client_CA786=== RUN TestServerTLSConfig/missing_CA_file787=== PAUSE TestServerTLSConfig/missing_CA_file788=== RUN TestServerTLSConfig/not_a_PEM_file789=== PAUSE TestServerTLSConfig/not_a_PEM_file790=== CONT TestService_NativeMTLS791=== NAME TestClientCADerivations792 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-4239-4131808779/TestClientCADerivations281731113/001/store/n0sc9zlvr7gfy3xjdh2s2spw05q3i35q-ca-test7932026-09-21 18:12:34.894 UTC [4457] ERROR: relation "goose_db_version" does not exist at character 367942026-09-21 18:12:34.894 UTC [4457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC795 client_ca_test.go:139: Found 1 dependencies (including self)796--- PASS: TestGCBugBareHashReferences (0.95s)797=== CONT TestMetricsInventory7982026/09/21 18:12:34 OK 20241026095416_initial_model.sql (46.01ms)7992026/09/21 18:12:34 OK 20251210153512_drop_unused_gin_index.sql (5.65ms)800--- PASS: TestService_healthCheckHandler (0.98s)801=== CONT TestPinProtectsFromGC8022026/09/21 18:12:34 OK 20251218171726_add_pins.sql (5.36ms)8032026/09/21 18:12:34 OK 20260628120000_add_object_size_and_stats.sql (1.91ms)8042026/09/21 18:12:34 OK 20260905000000_add_claims.sql (11.21ms)8052026/09/21 18:12:34 OK 20260920000000_drop_claims.sql (15.33ms)8062026/09/21 18:12:34 goose: successfully migrated database to version: 202609200000008072026/09/21 18:12:34 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"8082026/09/21 18:12:34 OK 1_commit_pending_closure.sql (1.7ms)8092026/09/21 18:12:34 OK 2_object_stats_trigger.sql (626.83µs)8102026/09/21 18:12:34 goose: up to current file version: 28112026/09/21 18:12:35 INFO Received uploads request method=POST path=/api/pending_closures8122026/09/21 18:12:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8132026/09/21 18:12:35 INFO Uploading n0sc9zlvr7gfy3xjdh2s2spw05q3i35q-ca-test (144B)8142026/09/21 18:12:35 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"8152026/09/21 18:12:35 WARN Failed to register uploaded object key=log/6iyv6dv5la6jczx31l1ya9jx9bf5ahw2-ca-test.drv error="server returned 404: 404 page not found\n"8162026/09/21 18:12:35 WARN Failed to register uploaded object key=n0sc9zlvr7gfy3xjdh2s2spw05q3i35q.ls error="server returned 404: 404 page not found\n"8172026/09/21 18:12:35 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign8182026/09/21 18:12:35 INFO Signed narinfos id=1 count=18192026/09/21 18:12:35 INFO Uploading 1 narinfos8202026/09/21 18:12:35 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8212026/09/21 18:12:35 WARN Failed to register uploaded object key=n0sc9zlvr7gfy3xjdh2s2spw05q3i35q.narinfo error="server returned 404: 404 page not found\n"8222026/09/21 18:12:35 INFO Completed upload id=18232026/09/21 18:12:35 INFO Upload complete. (115ms)8242026-09-21 18:12:35.067 UTC [4471] ERROR: relation "goose_db_version" does not exist at character 368252026-09-21 18:12:35.067 UTC [4471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC826=== NAME TestClientCADerivations827 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-4239-4131808779/TestClientCADerivations281731113/001/store/n0sc9zlvr7gfy3xjdh2s2spw05q3i35q-ca-test828 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst829 Compression: zstd830 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n831 NarSize: 144832 References: 833 Deriver: /nix/var/nix/builds/nix-4239-4131808779/TestClientCADerivations281731113/001/store/6iyv6dv5la6jczx31l1ya9jx9bf5ahw2-ca-test.drv834 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n835 client_ca_test.go:185: Checking for realisation files in S3...836 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations837 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache8382026/09/21 18:12:35 INFO Aborted multipart uploads count=08392026/09/21 18:12:35 OK 20241026095416_initial_model.sql (12.72ms)8402026/09/21 18:12:35 WARN Force mode enabled - objects will be deleted immediately without grace period8412026/09/21 18:12:35 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=08422026/09/21 18:12:35 INFO Vacuumed table table=pending_closures8432026/09/21 18:12:35 INFO Vacuumed table table=pending_objects8442026/09/21 18:12:35 INFO Vacuumed table table=multipart_uploads8452026/09/21 18:12:35 INFO Vacuumed table table=closures8462026/09/21 18:12:35 INFO Vacuumed table table=objects847--- PASS: TestGCMetrics (1.12s)848=== CONT TestLeadEndsOnShutdown8492026/09/21 18:12:35 OK 20251210153512_drop_unused_gin_index.sql (5.56ms)8502026/09/21 18:12:35 OK 20251218171726_add_pins.sql (5.17ms)8512026/09/21 18:12:35 OK 20260628120000_add_object_size_and_stats.sql (9.71ms)8522026/09/21 18:12:35 OK 20260905000000_add_claims.sql (1.72ms)8532026/09/21 18:12:35 OK 20260920000000_drop_claims.sql (14.09ms)8542026/09/21 18:12:35 goose: successfully migrated database to version: 202609200000008552026/09/21 18:12:35 OK 1_commit_pending_closure.sql (1.02ms)8562026/09/21 18:12:35 OK 2_object_stats_trigger.sql (238.92µs)8572026/09/21 18:12:35 goose: up to current file version: 2858=== NAME TestClientCADerivations859 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket4?endpoint=http://localhost:50857®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-4239-4131808779/TestClientCADerivations281731113/001/store'860 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 1861--- PASS: TestClientCADerivations (1.19s)862=== CONT TestLeadElectsOneAndHandsOver8632026-09-21 18:12:35.228 UTC [4479] ERROR: relation "goose_db_version" does not exist at character 368642026-09-21 18:12:35.228 UTC [4479] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC865=== RUN TestService_RequireScope_OIDC/builder_may_write866=== PAUSE TestService_RequireScope_OIDC/builder_may_write867=== RUN TestService_RequireScope_OIDC/builder_may_not_admin868=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin869=== RUN TestService_RequireScope_OIDC/ops_may_admin870=== PAUSE TestService_RequireScope_OIDC/ops_may_admin871=== RUN TestService_RequireScope_OIDC/ops_may_not_write872=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write873=== RUN TestService_RequireScope_OIDC/reader_may_not_write874=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write875=== RUN TestService_RequireScope_OIDC/static_token_may_admin876=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin877=== RUN TestService_RequireScope_OIDC/static_token_may_write878=== PAUSE TestService_RequireScope_OIDC/static_token_may_write879=== RUN TestService_RequireScope_OIDC/reader_may_read880=== PAUSE TestService_RequireScope_OIDC/reader_may_read881=== RUN TestService_RequireScope_OIDC/writer_implies_read882=== PAUSE TestService_RequireScope_OIDC/writer_implies_read883=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read884=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read885=== CONT TestResolveDBConnectionString886=== RUN TestResolveDBConnectionString/flag_wins887=== PAUSE TestResolveDBConnectionString/flag_wins888=== RUN TestResolveDBConnectionString/file_when_flag_empty889=== PAUSE TestResolveDBConnectionString/file_when_flag_empty890=== RUN TestResolveDBConnectionString/missing_file_is_an_error891=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error892=== RUN TestResolveDBConnectionString/PGHOST_allows_empty893=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty894=== RUN TestResolveDBConnectionString/nothing_configured895=== PAUSE TestResolveDBConnectionString/nothing_configured896=== CONT TestClientWithDependencies8972026-09-21 18:12:35.268 UTC [4482] ERROR: relation "goose_db_version" does not exist at character 368982026-09-21 18:12:35.268 UTC [4482] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8992026/09/21 18:12:35 OK 20241026095416_initial_model.sql (42.59ms)9002026/09/21 18:12:35 OK 20251210153512_drop_unused_gin_index.sql (10.08ms)9012026/09/21 18:12:35 OK 20251218171726_add_pins.sql (8.79ms)9022026/09/21 18:12:35 OK 20260628120000_add_object_size_and_stats.sql (17.55ms)9032026/09/21 18:12:35 OK 20260905000000_add_claims.sql (16.7ms)9042026/09/21 18:12:35 OK 20260920000000_drop_claims.sql (10.34ms)9052026/09/21 18:12:35 goose: successfully migrated database to version: 202609200000009062026/09/21 18:12:35 INFO Received uploads request method=POST path=/api/pending_closures9072026/09/21 18:12:35 OK 20241026095416_initial_model.sql (53.38ms)9082026/09/21 18:12:35 OK 1_commit_pending_closure.sql (1.11ms)9092026/09/21 18:12:35 OK 20251210153512_drop_unused_gin_index.sql (503.79µs)9102026/09/21 18:12:35 OK 2_object_stats_trigger.sql (441.21µs)9112026/09/21 18:12:35 goose: up to current file version: 29122026/09/21 18:12:35 OK 20251218171726_add_pins.sql (1.14ms)9132026/09/21 18:12:35 OK 20260628120000_add_object_size_and_stats.sql (19.53ms)9142026/09/21 18:12:35 OK 20260905000000_add_claims.sql (25.18ms)9152026/09/21 18:12:35 OK 20260920000000_drop_claims.sql (7.73ms)9162026/09/21 18:12:35 goose: successfully migrated database to version: 202609200000009172026/09/21 18:12:35 OK 1_commit_pending_closure.sql (851.04µs)9182026/09/21 18:12:35 OK 2_object_stats_trigger.sql (183.29µs)9192026/09/21 18:12:35 goose: up to current file version: 2920--- PASS: TestService_ReadScope_PublicByDefault (1.48s)921=== CONT TestClientSharedPathCommittedMidPush9222026/09/21 18:12:35 INFO Received cleanup request method=DELETE path=/api/pending_closures9232026/09/21 18:12:35 INFO Aborted multipart uploads count=1924--- PASS: TestMultipartCleanup (1.52s)925=== CONT TestGCTaskStore_PhaseUpdates926--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)927=== CONT TestReadProxyRangeRequest928=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token929=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token930=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected931=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected932=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected933=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected934=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured935=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured936=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT9372026-09-21 18:12:35.836 UTC [4492] ERROR: relation "goose_db_version" does not exist at character 369382026-09-21 18:12:35.836 UTC [4492] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC939=== NAME TestNARDeduplicationMetadataUploadBug940 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-4239-4131808779/TestNARDeduplicationMetadataUploadBug1726787480/001/store/0q0jxcn577j80fhbcmn9w05hajx403ac-file1.txt9412026/09/21 18:12:35 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9422026/09/21 18:12:35 WARN mTLS auth: subject not in bound subjects subject="CN=reader"943--- PASS: TestService_NativeMTLS (1.04s)944=== CONT TestCompleteMultipartUnregistered9452026-09-21 18:12:35.878 UTC [4495] ERROR: relation "goose_db_version" does not exist at character 369462026-09-21 18:12:35.878 UTC [4495] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9472026/09/21 18:12:35 OK 20241026095416_initial_model.sql (25.93ms)9482026/09/21 18:12:35 OK 20251210153512_drop_unused_gin_index.sql (5.96ms)9492026/09/21 18:12:35 OK 20251218171726_add_pins.sql (6.41ms)9502026/09/21 18:12:35 OK 20260628120000_add_object_size_and_stats.sql (16.48ms)9512026/09/21 18:12:35 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"9522026/09/21 18:12:35 OK 20260905000000_add_claims.sql (14.36ms)9532026/09/21 18:12:35 OK 20260920000000_drop_claims.sql (11.91ms)9542026/09/21 18:12:35 goose: successfully migrated database to version: 202609200000009552026/09/21 18:12:35 OK 1_commit_pending_closure.sql (1.31ms)9562026/09/21 18:12:35 OK 2_object_stats_trigger.sql (441.38µs)9572026/09/21 18:12:35 goose: up to current file version: 29582026-09-21 18:12:35.960 UTC [4501] ERROR: relation "goose_db_version" does not exist at character 369592026-09-21 18:12:35.960 UTC [4501] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9602026/09/21 18:12:35 OK 20241026095416_initial_model.sql (57.24ms)9612026/09/21 18:12:35 OK 20251210153512_drop_unused_gin_index.sql (6.81ms)9622026/09/21 18:12:35 OK 20251218171726_add_pins.sql (17.15ms)9632026/09/21 18:12:35 INFO Received uploads request method=POST path=/api/pending_closures9642026/09/21 18:12:35 OK 20260628120000_add_object_size_and_stats.sql (13.7ms)9652026/09/21 18:12:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9662026/09/21 18:12:36 INFO Uploading 0q0jxcn577j80fhbcmn9w05hajx403ac-file1.txt (160B)9672026/09/21 18:12:36 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"9682026/09/21 18:12:36 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign9692026/09/21 18:12:36 INFO Signed narinfos id=1 count=19702026/09/21 18:12:36 WARN Failed to register uploaded object key=0q0jxcn577j80fhbcmn9w05hajx403ac.ls error="server returned 404: 404 page not found\n"9712026/09/21 18:12:36 INFO Uploading 1 narinfos9722026/09/21 18:12:36 OK 20260905000000_add_claims.sql (21.85ms)9732026/09/21 18:12:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9742026/09/21 18:12:36 WARN Failed to register uploaded object key=0q0jxcn577j80fhbcmn9w05hajx403ac.narinfo error="server returned 404: 404 page not found\n"9752026/09/21 18:12:36 OK 20260920000000_drop_claims.sql (7.21ms)9762026/09/21 18:12:36 goose: successfully migrated database to version: 202609200000009772026/09/21 18:12:36 OK 1_commit_pending_closure.sql (948.5µs)9782026/09/21 18:12:36 OK 2_object_stats_trigger.sql (243µs)9792026/09/21 18:12:36 goose: up to current file version: 29802026/09/21 18:12:36 INFO Completed upload id=19812026/09/21 18:12:36 INFO Upload complete. (148ms)982=== NAME TestNARDeduplicationMetadataUploadBug983 metadata_upload_test.go:54: Retrieved narinfo from S3:984 StorePath: /nix/var/nix/builds/nix-4239-4131808779/TestNARDeduplicationMetadataUploadBug1726787480/001/store/0q0jxcn577j80fhbcmn9w05hajx403ac-file1.txt985 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst986 Compression: zstd987 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf988 NarSize: 160989 References: 990 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf991--- PASS: TestMetricsInventory (1.11s)992=== CONT TestService_verifyS3Integrity993=== NAME TestNARDeduplicationMetadataUploadBug994 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)995 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):996 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}9972026/09/21 18:12:36 OK 20241026095416_initial_model.sql (56.17ms)9982026/09/21 18:12:36 OK 20251210153512_drop_unused_gin_index.sql (927.25µs)9992026/09/21 18:12:36 OK 20251218171726_add_pins.sql (7.17ms)10002026/09/21 18:12:36 OK 20260628120000_add_object_size_and_stats.sql (15.62ms)10012026/09/21 18:12:36 OK 20260905000000_add_claims.sql (10.55ms)1002 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-4239-4131808779/TestNARDeduplicationMetadataUploadBug1726787480/001/store/biw7j5l7viaizl2nqxfbk08gmixbhv7i-file2.txt10032026/09/21 18:12:36 OK 20260920000000_drop_claims.sql (7.03ms)10042026/09/21 18:12:36 goose: successfully migrated database to version: 2026092000000010052026/09/21 18:12:36 OK 1_commit_pending_closure.sql (962.79µs)10062026/09/21 18:12:36 OK 2_object_stats_trigger.sql (258.71µs)10072026/09/21 18:12:36 goose: up to current file version: 210082026/09/21 18:12:36 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10092026/09/21 18:12:36 INFO Received uploads request method=POST path=/api/pending_closures10102026/09/21 18:12:36 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10112026/09/21 18:12:36 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10122026/09/21 18:12:36 INFO Signed narinfos id=2 count=110132026/09/21 18:12:36 INFO Uploading 1 narinfos10142026/09/21 18:12:36 WARN Failed to register uploaded object key=biw7j5l7viaizl2nqxfbk08gmixbhv7i.ls error="server returned 404: 404 page not found\n"10152026-09-21 18:12:36.210 UTC [4515] ERROR: relation "goose_db_version" does not exist at character 3610162026-09-21 18:12:36.210 UTC [4515] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10172026-09-21 18:12:36.211 UTC [4514] ERROR: relation "goose_db_version" does not exist at character 3610182026-09-21 18:12:36.211 UTC [4514] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10192026/09/21 18:12:36 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10202026/09/21 18:12:36 WARN Failed to register uploaded object key=biw7j5l7viaizl2nqxfbk08gmixbhv7i.narinfo error="server returned 404: 404 page not found\n"10212026/09/21 18:12:36 INFO Completed upload id=210222026/09/21 18:12:36 INFO Upload complete. (94ms)1023 metadata_upload_test.go:76: Retrieved narinfo from S3:1024 StorePath: /nix/var/nix/builds/nix-4239-4131808779/TestNARDeduplicationMetadataUploadBug1726787480/001/store/biw7j5l7viaizl2nqxfbk08gmixbhv7i-file2.txt1025 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1026 Compression: zstd1027 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1028 NarSize: 1601029 References: 1030 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1031 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1032 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1033 {"version":1,"root":{"type":"regular","size":44}}1034--- PASS: TestNARDeduplicationMetadataUploadBug (1.72s)1035=== CONT TestService_createPendingClosureHandler1036=== NAME TestPinProtectsFromGC1037 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-4239-4131808779/TestPinProtectsFromGC1950452453/001/store/pcgq0b0kv081c27xssplimg71nixgzkj-pinned-file.txt1038 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-4239-4131808779/TestPinProtectsFromGC1950452453/001/store/jz0qbl683gaq6q9m89a5przzfx99wqmr-unpinned-file.txt10392026/09/21 18:12:36 INFO lead: acquired remote=192.0.2.1:123410402026/09/21 18:12:36 INFO lead: released remote=192.0.2.1:12341041--- PASS: TestLeadEndsOnShutdown (1.22s)1042=== CONT TestService_cleanupPendingClosuresHandler10432026/09/21 18:12:36 OK 20241026095416_initial_model.sql (68.78ms)10442026/09/21 18:12:36 OK 20241026095416_initial_model.sql (68.79ms)10452026-09-21 18:12:36.318 UTC [4522] ERROR: relation "goose_db_version" does not exist at character 3610462026-09-21 18:12:36.318 UTC [4522] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10472026/09/21 18:12:36 OK 20251210153512_drop_unused_gin_index.sql (19.2ms)10482026/09/21 18:12:36 OK 20251210153512_drop_unused_gin_index.sql (19.32ms)10492026/09/21 18:12:36 OK 20251218171726_add_pins.sql (8.57ms)10502026/09/21 18:12:36 OK 20251218171726_add_pins.sql (14.15ms)10512026/09/21 18:12:36 OK 20260628120000_add_object_size_and_stats.sql (13.15ms)10522026/09/21 18:12:36 OK 20260628120000_add_object_size_and_stats.sql (8.18ms)10532026/09/21 18:12:36 OK 20260905000000_add_claims.sql (10.87ms)10542026/09/21 18:12:36 OK 20260920000000_drop_claims.sql (6.08ms)10552026/09/21 18:12:36 goose: successfully migrated database to version: 2026092000000010562026/09/21 18:12:36 OK 1_commit_pending_closure.sql (816.71µs)10572026/09/21 18:12:36 OK 2_object_stats_trigger.sql (249.88µs)10582026/09/21 18:12:36 goose: up to current file version: 210592026/09/21 18:12:36 OK 20260905000000_add_claims.sql (22.41ms)10602026/09/21 18:12:36 OK 20260920000000_drop_claims.sql (1.45ms)10612026/09/21 18:12:36 goose: successfully migrated database to version: 2026092000000010622026/09/21 18:12:36 OK 20241026095416_initial_model.sql (32.75ms)10632026/09/21 18:12:36 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10642026/09/21 18:12:36 OK 20251210153512_drop_unused_gin_index.sql (936.96µs)10652026/09/21 18:12:36 OK 1_commit_pending_closure.sql (1.27ms)10662026/09/21 18:12:36 OK 2_object_stats_trigger.sql (362.58µs)10672026/09/21 18:12:36 goose: up to current file version: 210682026/09/21 18:12:36 OK 20251218171726_add_pins.sql (12.66ms)10692026/09/21 18:12:36 OK 20260628120000_add_object_size_and_stats.sql (11.11ms)10702026/09/21 18:12:36 OK 20260905000000_add_claims.sql (24.55ms)10712026/09/21 18:12:36 INFO Received uploads request method=POST path=/api/pending_closures10722026/09/21 18:12:36 OK 20260920000000_drop_claims.sql (6.68ms)10732026/09/21 18:12:36 goose: successfully migrated database to version: 2026092000000010742026/09/21 18:12:36 OK 1_commit_pending_closure.sql (896.17µs)10752026/09/21 18:12:36 OK 2_object_stats_trigger.sql (271.17µs)10762026/09/21 18:12:36 goose: up to current file version: 210772026/09/21 18:12:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10782026/09/21 18:12:36 INFO Uploading pcgq0b0kv081c27xssplimg71nixgzkj-pinned-file.txt (128B)10792026/09/21 18:12:36 INFO lead: acquired remote=192.0.2.1:123410802026/09/21 18:12:36 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"10812026/09/21 18:12:36 WARN Failed to register uploaded object key=pcgq0b0kv081c27xssplimg71nixgzkj.ls error="server returned 404: 404 page not found\n"10822026/09/21 18:12:36 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10832026/09/21 18:12:36 INFO Signed narinfos id=1 count=110842026/09/21 18:12:36 INFO Uploading 1 narinfos10852026/09/21 18:12:36 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10862026/09/21 18:12:36 WARN Failed to register uploaded object key=pcgq0b0kv081c27xssplimg71nixgzkj.narinfo error="server returned 404: 404 page not found\n"10872026/09/21 18:12:36 INFO Completed upload id=110882026/09/21 18:12:36 INFO Upload complete. (135ms)10892026-09-21 18:12:36.540 UTC [4534] ERROR: relation "goose_db_version" does not exist at character 3610902026-09-21 18:12:36.540 UTC [4534] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10912026/09/21 18:12:36 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"10922026/09/21 18:12:36 OK 20241026095416_initial_model.sql (28.51ms)10932026/09/21 18:12:36 OK 20251210153512_drop_unused_gin_index.sql (9.8ms)10942026/09/21 18:12:36 INFO Received uploads request method=POST path=/api/pending_closures10952026/09/21 18:12:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10962026/09/21 18:12:36 INFO Uploading jz0qbl683gaq6q9m89a5przzfx99wqmr-unpinned-file.txt (128B)10972026/09/21 18:12:36 INFO lead: released remote=192.0.2.1:123410982026/09/21 18:12:36 OK 20251218171726_add_pins.sql (11.61ms)10992026/09/21 18:12:36 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"11002026/09/21 18:12:36 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign11012026/09/21 18:12:36 INFO Signed narinfos id=2 count=111022026/09/21 18:12:36 INFO Uploading 1 narinfos11032026/09/21 18:12:36 WARN Failed to register uploaded object key=jz0qbl683gaq6q9m89a5przzfx99wqmr.ls error="server returned 404: 404 page not found\n"11042026/09/21 18:12:36 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11052026/09/21 18:12:36 WARN Failed to register uploaded object key=jz0qbl683gaq6q9m89a5przzfx99wqmr.narinfo error="server returned 404: 404 page not found\n"11062026/09/21 18:12:36 INFO Completed upload id=211072026/09/21 18:12:36 OK 20260628120000_add_object_size_and_stats.sql (16.05ms)11082026/09/21 18:12:36 INFO Upload complete. (119ms)11092026/09/21 18:12:36 OK 20260905000000_add_claims.sql (17.23ms)11102026/09/21 18:12:36 INFO lead: acquired remote=192.0.2.1:123411112026/09/21 18:12:36 INFO lead: released remote=192.0.2.1:12341112--- PASS: TestLeadElectsOneAndHandsOver (1.49s)1113=== CONT TestUploadHandlersRejectOversizedBody11142026/09/21 18:12:36 OK 20260920000000_drop_claims.sql (15.84ms)11152026/09/21 18:12:36 goose: successfully migrated database to version: 2026092000000011162026/09/21 18:12:36 INFO Received create pin request method=POST path=/api/pins/myapp11172026/09/21 18:12:36 OK 1_commit_pending_closure.sql (1.61ms)11182026/09/21 18:12:36 OK 2_object_stats_trigger.sql (344.38µs)11192026/09/21 18:12:36 goose: up to current file version: 21120=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1121=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1122=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1123=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1124=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1125=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1126=== CONT TestUploadHandlersRejectInvalidKeys1127=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1128=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1129=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1130=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1131=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1132=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1133=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1134=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1135=== CONT TestIsValidUploadKey1136=== RUN TestIsValidUploadKey/narinfo1137=== PAUSE TestIsValidUploadKey/narinfo1138=== RUN TestIsValidUploadKey/nar_zst1139=== PAUSE TestIsValidUploadKey/nar_zst1140=== RUN TestIsValidUploadKey/nar_xz1141=== PAUSE TestIsValidUploadKey/nar_xz1142=== RUN TestIsValidUploadKey/nar_plain1143=== PAUSE TestIsValidUploadKey/nar_plain1144=== RUN TestIsValidUploadKey/listing1145=== PAUSE TestIsValidUploadKey/listing1146=== RUN TestIsValidUploadKey/build_log1147=== PAUSE TestIsValidUploadKey/build_log1148=== RUN TestIsValidUploadKey/build_log_home-manager_file1149=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1150=== RUN TestIsValidUploadKey/build_log_plus_in_name1151=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1152=== RUN TestIsValidUploadKey/build_log_question_mark1153=== PAUSE TestIsValidUploadKey/build_log_question_mark1154=== RUN TestIsValidUploadKey/build_log_equals1155=== PAUSE TestIsValidUploadKey/build_log_equals1156=== RUN TestIsValidUploadKey/realisation1157=== PAUSE TestIsValidUploadKey/realisation1158=== RUN TestIsValidUploadKey/realisation_plus_in_output1159=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1160=== RUN TestIsValidUploadKey/nix-cache-info1161=== PAUSE TestIsValidUploadKey/nix-cache-info1162=== RUN TestIsValidUploadKey/index.html1163=== PAUSE TestIsValidUploadKey/index.html1164=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1165=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1166=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1167=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1168=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1169=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1170=== RUN TestIsValidUploadKey/traversal1171=== PAUSE TestIsValidUploadKey/traversal1172=== RUN TestIsValidUploadKey/traversal_nar1173=== PAUSE TestIsValidUploadKey/traversal_nar1174=== RUN TestIsValidUploadKey/absolute1175=== PAUSE TestIsValidUploadKey/absolute1176=== RUN TestIsValidUploadKey/empty_key1177=== PAUSE TestIsValidUploadKey/empty_key1178=== RUN TestIsValidUploadKey/unknown_type1179=== PAUSE TestIsValidUploadKey/unknown_type1180=== CONT TestProxyWriteTimeout1181=== RUN TestProxyWriteTimeout/narinfo1182=== PAUSE TestProxyWriteTimeout/narinfo1183=== RUN TestProxyWriteTimeout/1_GiB_nar1184=== PAUSE TestProxyWriteTimeout/1_GiB_nar1185=== RUN TestProxyWriteTimeout/10_GiB_nar1186=== PAUSE TestProxyWriteTimeout/10_GiB_nar1187=== RUN TestProxyWriteTimeout/unknown_size1188=== PAUSE TestProxyWriteTimeout/unknown_size1189=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle11902026/09/21 18:12:36 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-4239-4131808779/TestPinProtectsFromGC1950452453/001/store/pcgq0b0kv081c27xssplimg71nixgzkj-pinned-file.txt narinfo_key=pcgq0b0kv081c27xssplimg71nixgzkj.narinfo11912026-09-21 18:12:36.684 UTC [4543] ERROR: relation "goose_db_version" does not exist at character 3611922026-09-21 18:12:36.684 UTC [4543] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11932026/09/21 18:12:36 INFO Starting cleanup of old closures method=DELETE path=/api/closures11942026/09/21 18:12:36 INFO Garbage collection started11952026/09/21 18:12:36 INFO Aborted multipart uploads count=011962026/09/21 18:12:36 WARN Force mode enabled - objects will be deleted immediately without grace period11972026/09/21 18:12:36 OK 20241026095416_initial_model.sql (44.14ms)1198--- PASS: TestReadProxyRangeRequest (1.26s)1199=== CONT TestSkippedUploadsHandler12002026/09/21 18:12:36 INFO Client skipped oversized paths paths=3 nar_bytes=500000000012012026/09/21 18:12:36 OK 20251210153512_drop_unused_gin_index.sql (8.79ms)1202--- PASS: TestSkippedUploadsHandler (0.00s)1203=== CONT TestParseSize1204--- PASS: TestParseSize (0.00s)1205=== CONT TestService_Rustfstest12062026/09/21 18:12:36 OK 20251218171726_add_pins.sql (14.51ms)12072026/09/21 18:12:36 OK 20260628120000_add_object_size_and_stats.sql (7.51ms)12082026/09/21 18:12:36 OK 20260905000000_add_claims.sql (14.18ms)12092026/09/21 18:12:36 OK 20260920000000_drop_claims.sql (13.53ms)12102026/09/21 18:12:36 goose: successfully migrated database to version: 2026092000000012112026/09/21 18:12:36 OK 1_commit_pending_closure.sql (1.31ms)12122026/09/21 18:12:36 OK 2_object_stats_trigger.sql (401.71µs)12132026/09/21 18:12:36 goose: up to current file version: 212142026-09-21 18:12:36.839 UTC [4553] ERROR: relation "goose_db_version" does not exist at character 3612152026-09-21 18:12:36.839 UTC [4553] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1216=== NAME TestClientWithDependencies1217 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-4239-4131808779/TestClientWithDependencies1610225338/001/store/sch3k6y7hdyr1dk0g9ak17ayk8n5km8f-test-script12182026/09/21 18:12:36 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=012192026/09/21 18:12:36 INFO Vacuumed table table=pending_closures12202026/09/21 18:12:36 OK 20241026095416_initial_model.sql (37.76ms)12212026-09-21 18:12:36.904 UTC [4556] ERROR: relation "goose_db_version" does not exist at character 3612222026-09-21 18:12:36.904 UTC [4556] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12232026/09/21 18:12:36 OK 20251210153512_drop_unused_gin_index.sql (3.93ms)12242026/09/21 18:12:36 INFO Vacuumed table table=pending_objects12252026/09/21 18:12:36 INFO Vacuumed table table=multipart_uploads1226 client_integration_test.go:615: Found 1 dependencies (including self)12272026/09/21 18:12:36 OK 20251218171726_add_pins.sql (18.67ms)12282026/09/21 18:12:36 INFO Vacuumed table table=closures12292026/09/21 18:12:36 INFO Vacuumed table table=objects12302026/09/21 18:12:36 OK 20260628120000_add_object_size_and_stats.sql (16.54ms)12312026/09/21 18:12:36 OK 20260905000000_add_claims.sql (19.37ms)12322026/09/21 18:12:36 OK 20260920000000_drop_claims.sql (6.73ms)12332026/09/21 18:12:36 goose: successfully migrated database to version: 2026092000000012342026/09/21 18:12:36 OK 1_commit_pending_closure.sql (1.79ms)12352026/09/21 18:12:36 OK 2_object_stats_trigger.sql (569.25µs)12362026/09/21 18:12:36 goose: up to current file version: 212372026/09/21 18:12:36 OK 20241026095416_initial_model.sql (44.83ms)12382026/09/21 18:12:36 OK 20251210153512_drop_unused_gin_index.sql (593.75µs)12392026/09/21 18:12:36 OK 20251218171726_add_pins.sql (5.99ms)12402026/09/21 18:12:36 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12412026/09/21 18:12:36 INFO Received uploads request method=POST path=/api/pending_closures12422026/09/21 18:12:36 OK 20260628120000_add_object_size_and_stats.sql (9.98ms)12432026/09/21 18:12:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12442026/09/21 18:12:36 INFO Uploading sch3k6y7hdyr1dk0g9ak17ayk8n5km8f-test-script (136B)12452026/09/21 18:12:37 OK 20260905000000_add_claims.sql (13.01ms)12462026/09/21 18:12:37 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"12472026/09/21 18:12:37 OK 20260920000000_drop_claims.sql (11.81ms)12482026/09/21 18:12:37 goose: successfully migrated database to version: 2026092000000012492026/09/21 18:12:37 WARN Failed to register uploaded object key=log/hfdlh9h39z0fcmmazvg4p39xb1mzrmpv-test-script.drv error="server returned 404: 404 page not found\n"12502026/09/21 18:12:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12512026/09/21 18:12:37 INFO Signed narinfos id=1 count=112522026/09/21 18:12:37 WARN Failed to register uploaded object key=sch3k6y7hdyr1dk0g9ak17ayk8n5km8f.ls error="server returned 404: 404 page not found\n"12532026/09/21 18:12:37 INFO Uploading 1 narinfos12542026/09/21 18:12:37 OK 1_commit_pending_closure.sql (1.3ms)12552026/09/21 18:12:37 OK 2_object_stats_trigger.sql (371.75µs)12562026/09/21 18:12:37 goose: up to current file version: 212572026/09/21 18:12:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12582026/09/21 18:12:37 WARN Failed to register uploaded object key=sch3k6y7hdyr1dk0g9ak17ayk8n5km8f.narinfo error="server returned 404: 404 page not found\n"12592026/09/21 18:12:37 INFO Completed upload id=112602026/09/21 18:12:37 INFO Upload complete. (88ms)1261 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-4239-4131808779/TestClientWithDependencies1610225338/001/store) requires matching store prefix12622026/09/21 18:12:37 INFO Received uploads request method=POST path=/api/pending_closures1263--- PASS: TestClientWithDependencies (1.81s)1264=== CONT TestPresignedUploadRegisteredBeforeCommit1265--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.50s)1266=== CONT TestCompletedNarNotReofferedAcrossClosures12672026/09/21 18:12:37 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12682026/09/21 18:12:37 INFO Received uploads request method=POST path=/api/pending_closures12692026/09/21 18:12:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12702026/09/21 18:12:37 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1271--- PASS: TestCompleteMultipartUnregistered (1.32s)1272=== CONT TestCompleteMultipartUpload_ErrorButObjectExists12732026-09-21 18:12:37.228 UTC [4581] ERROR: relation "goose_db_version" does not exist at character 3612742026-09-21 18:12:37.228 UTC [4581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12752026/09/21 18:12:37 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"12762026/09/21 18:12:37 INFO Received uploads request method=POST path=/api/pending_closures12772026/09/21 18:12:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12782026/09/21 18:12:37 INFO Uploading fcvbzg19qi0qg5ib1zb0fklg6ffmq14a-shared-dep (136B)12792026/09/21 18:12:37 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12802026/09/21 18:12:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12812026/09/21 18:12:37 INFO Signed narinfos id=2 count=112822026/09/21 18:12:37 WARN Failed to register uploaded object key=fcvbzg19qi0qg5ib1zb0fklg6ffmq14a.ls error="server returned 404: 404 page not found\n"12832026/09/21 18:12:37 INFO Uploading 1 narinfos12842026/09/21 18:12:37 OK 20241026095416_initial_model.sql (55.99ms)12852026/09/21 18:12:37 OK 20251210153512_drop_unused_gin_index.sql (1.05ms)12862026/09/21 18:12:37 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12872026/09/21 18:12:37 WARN Failed to register uploaded object key=fcvbzg19qi0qg5ib1zb0fklg6ffmq14a.narinfo error="server returned 404: 404 page not found\n"12882026/09/21 18:12:37 INFO Completed upload id=212892026/09/21 18:12:37 INFO Upload complete. (130ms)12902026/09/21 18:12:37 INFO Received uploads request method=POST path=/api/pending_closures12912026/09/21 18:12:37 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12922026/09/21 18:12:37 INFO Uploading jik1z7mqgsvnlghmi0a0w5abc5xkc8bh-top (256B)12932026/09/21 18:12:37 INFO Uploading fcvbzg19qi0qg5ib1zb0fklg6ffmq14a-shared-dep (136B)12942026/09/21 18:12:37 OK 20251218171726_add_pins.sql (16.11ms)12952026/09/21 18:12:37 INFO Received uploads request method=POST path=/api/pending_closures12962026/09/21 18:12:37 WARN Failed to register uploaded object key=nar/0r439b4yl54kj1ing72ay0kncws23736lx2c1lzb1hjlij476nn3.nar.zst error="server returned 404: 404 page not found\n"12972026-09-21 18:12:37.329 UTC [4584] ERROR: relation "goose_db_version" does not exist at character 3612982026-09-21 18:12:37.329 UTC [4584] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12992026/09/21 18:12:37 OK 20260628120000_add_object_size_and_stats.sql (9.79ms)13002026/09/21 18:12:37 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13012026/09/21 18:12:37 WARN Failed to register uploaded object key=jik1z7mqgsvnlghmi0a0w5abc5xkc8bh.ls error="server returned 404: 404 page not found\n"13022026/09/21 18:12:37 OK 20260905000000_add_claims.sql (2.15ms)13032026/09/21 18:12:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13042026/09/21 18:12:37 INFO Signed narinfos id=1 count=113052026/09/21 18:12:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign13062026/09/21 18:12:37 WARN Failed to register uploaded object key=fcvbzg19qi0qg5ib1zb0fklg6ffmq14a.ls error="server returned 404: 404 page not found\n"13072026/09/21 18:12:37 INFO Signed narinfos id=3 count=113082026/09/21 18:12:37 INFO Uploading 2 narinfos13092026/09/21 18:12:37 WARN Failed to register uploaded object key=jik1z7mqgsvnlghmi0a0w5abc5xkc8bh.narinfo error="server returned 404: 404 page not found\n"13102026/09/21 18:12:37 OK 20260920000000_drop_claims.sql (22.2ms)13112026/09/21 18:12:37 goose: successfully migrated database to version: 2026092000000013122026/09/21 18:12:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13132026/09/21 18:12:37 WARN Failed to register uploaded object key=fcvbzg19qi0qg5ib1zb0fklg6ffmq14a.narinfo error="server returned 404: 404 page not found\n"13142026/09/21 18:12:37 OK 1_commit_pending_closure.sql (1.36ms)13152026/09/21 18:12:37 INFO Completed upload id=113162026/09/21 18:12:37 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete13172026/09/21 18:12:37 OK 2_object_stats_trigger.sql (218.83µs)13182026/09/21 18:12:37 goose: up to current file version: 213192026/09/21 18:12:37 INFO Completed upload id=313202026/09/21 18:12:37 INFO Upload complete. (304ms)1321=== NAME TestClientSharedPathCommittedMidPush1322 client_integration_test.go:680: Retrieved narinfo from S3:1323 StorePath: /nix/var/nix/builds/nix-4239-4131808779/TestClientSharedPathCommittedMidPush1958394184/001/store/fcvbzg19qi0qg5ib1zb0fklg6ffmq14a-shared-dep1324 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1325 Compression: zstd1326 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821327 NarSize: 1361328 References: 1329 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1330 client_integration_test.go:680: Retrieved narinfo from S3:1331 StorePath: /nix/var/nix/builds/nix-4239-4131808779/TestClientSharedPathCommittedMidPush1958394184/001/store/jik1z7mqgsvnlghmi0a0w5abc5xkc8bh-top1332 URL: nar/0r439b4yl54kj1ing72ay0kncws23736lx2c1lzb1hjlij476nn3.nar.zst1333 Compression: zstd1334 NarHash: sha256:0r439b4yl54kj1ing72ay0kncws23736lx2c1lzb1hjlij476nn31335 NarSize: 2561336 References: /nix/var/nix/builds/nix-4239-4131808779/TestClientSharedPathCommittedMidPush1958394184/001/store/fcvbzg19qi0qg5ib1zb0fklg6ffmq14a-shared-dep1337 CA: text:sha256:1n107r1nr1dq6ck15r6if1zhfs6l6zi15lwyrlhk1vzf3ird6rlc1338--- PASS: TestClientSharedPathCommittedMidPush (1.91s)1339=== CONT TestRedundantMultipartUpload13402026/09/21 18:12:37 OK 20241026095416_initial_model.sql (74.78ms)13412026/09/21 18:12:37 OK 20251210153512_drop_unused_gin_index.sql (13.77ms)13422026/09/21 18:12:37 OK 20251218171726_add_pins.sql (14.71ms)13432026/09/21 18:12:37 OK 20260628120000_add_object_size_and_stats.sql (17.07ms)13442026/09/21 18:12:37 INFO Received uploads request method=POST path=/api/pending_closures13452026/09/21 18:12:37 INFO Received uploads request method=POST path=/api/pending_closures13462026/09/21 18:12:37 INFO Received uploads request method=POST path=/api/pending_closures13472026/09/21 18:12:37 OK 20260905000000_add_claims.sql (71.14ms)13482026/09/21 18:12:37 OK 20260920000000_drop_claims.sql (16.72ms)13492026/09/21 18:12:37 goose: successfully migrated database to version: 2026092000000013502026/09/21 18:12:37 OK 1_commit_pending_closure.sql (1.4ms)13512026/09/21 18:12:37 OK 2_object_stats_trigger.sql (321.46µs)13522026/09/21 18:12:37 goose: up to current file version: 213532026/09/21 18:12:37 INFO Received cleanup request method=DELETE path=/api/pending_closures13542026/09/21 18:12:37 INFO Aborted multipart uploads count=013552026/09/21 18:12:37 INFO Received uploads request method=POST path=/api/pending_closures13562026/09/21 18:12:37 INFO Received cleanup request method=DELETE path=/api/pending_closures13572026/09/21 18:12:37 INFO Aborted multipart uploads count=113582026/09/21 18:12:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13592026-09-21 18:12:37.802 UTC [4556] ERROR: Closure does not exist: id=113602026-09-21 18:12:37.802 UTC [4556] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE13612026-09-21 18:12:37.802 UTC [4556] STATEMENT: -- name: CommitPendingClosure :exec1362 SELECT commit_pending_closure($1::bigint)1363 1364--- PASS: TestService_cleanupPendingClosuresHandler (1.49s)1365=== CONT TestReadRedirectUsesPublicS3URL13662026/09/21 18:12:37 INFO Received uploads request method=POST path=/api/pending_closures1367--- PASS: TestService_Rustfstest (1.50s)1368=== CONT TestGCTaskStore_ConflictDifferentParams1369--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1370=== CONT TestGCTaskStore_GetEmpty1371--- PASS: TestGCTaskStore_GetEmpty (0.00s)1372=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13732026/09/21 18:12:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13742026-09-21 18:12:38.383 UTC [4591] ERROR: relation "goose_db_version" does not exist at character 3613752026-09-21 18:12:38.383 UTC [4591] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13762026-09-21 18:12:38.440 UTC [4593] ERROR: relation "goose_db_version" does not exist at character 3613772026-09-21 18:12:38.440 UTC [4593] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13782026/09/21 18:12:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13792026/09/21 18:12:38 OK 20241026095416_initial_model.sql (58.39ms)13802026/09/21 18:12:38 OK 20251210153512_drop_unused_gin_index.sql (712.75µs)13812026/09/21 18:12:38 OK 20251218171726_add_pins.sql (39.59ms)13822026-09-21 18:12:38.523 UTC [4594] ERROR: relation "goose_db_version" does not exist at character 3613832026-09-21 18:12:38.523 UTC [4594] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13842026/09/21 18:12:38 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NGQxZTA5NzAtOGVmMS00YmFiLWE3ZGItOTQ3M2I1ZjJjYzEzLmFmZjVmYmFmLTJmZTYtNDE5MC1iYWQ2LTRhNGJkYjQ0NGVmY3gxNzkwMDE0MzU3MzMyMDc0MDAw parts=1013852026/09/21 18:12:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13862026/09/21 18:12:38 OK 20241026095416_initial_model.sql (65.15ms)13872026/09/21 18:12:38 OK 20251210153512_drop_unused_gin_index.sql (7.08ms)13882026/09/21 18:12:38 INFO Completed upload id=113892026/09/21 18:12:38 OK 20260628120000_add_object_size_and_stats.sql (15.35ms)13902026/09/21 18:12:38 INFO Received uploads request method=POST path=/api/pending_closures13912026/09/21 18:12:38 OK 20251218171726_add_pins.sql (3.14ms)13922026/09/21 18:12:38 INFO Received uploads request method=POST path=/api/pending_closures13932026/09/21 18:12:38 OK 20260905000000_add_claims.sql (4.04ms)13942026/09/21 18:12:38 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13952026/09/21 18:12:38 WARN Found objects in DB but missing from S3, will re-upload count=11396--- PASS: TestService_verifyS3Integrity (2.51s)1397=== CONT TestService_ReadAuthMiddleware13982026/09/21 18:12:38 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)13992026/09/21 18:12:38 OK 20260920000000_drop_claims.sql (4.67ms)14002026/09/21 18:12:38 goose: successfully migrated database to version: 2026092000000014012026/09/21 18:12:38 OK 20260905000000_add_claims.sql (5.42ms)14022026/09/21 18:12:38 OK 1_commit_pending_closure.sql (3.02ms)14032026/09/21 18:12:38 OK 2_object_stats_trigger.sql (861.25µs)14042026/09/21 18:12:38 goose: up to current file version: 214052026/09/21 18:12:38 OK 20260920000000_drop_claims.sql (2.03ms)14062026/09/21 18:12:38 goose: successfully migrated database to version: 2026092000000014072026/09/21 18:12:38 OK 20241026095416_initial_model.sql (11.44ms)14082026/09/21 18:12:38 OK 20251210153512_drop_unused_gin_index.sql (805.63µs)14092026/09/21 18:12:38 OK 1_commit_pending_closure.sql (2.54ms)14102026/09/21 18:12:38 OK 2_object_stats_trigger.sql (505.71µs)14112026/09/21 18:12:38 goose: up to current file version: 214122026/09/21 18:12:38 OK 20251218171726_add_pins.sql (28.49ms)14132026/09/21 18:12:38 OK 20260628120000_add_object_size_and_stats.sql (24.83ms)14142026/09/21 18:12:38 OK 20260905000000_add_claims.sql (29.27ms)14152026/09/21 18:12:38 OK 20260920000000_drop_claims.sql (10.38ms)14162026/09/21 18:12:38 goose: successfully migrated database to version: 2026092000000014172026/09/21 18:12:38 OK 1_commit_pending_closure.sql (1.86ms)14182026/09/21 18:12:38 OK 2_object_stats_trigger.sql (374.92µs)14192026/09/21 18:12:38 goose: up to current file version: 214202026/09/21 18:12:38 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=01421=== NAME TestPinProtectsFromGC1422 client_integration_test.go:794: Pin successfully protected closure from garbage collection14232026/09/21 18:12:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14242026-09-21 18:12:38.715 UTC [4597] ERROR: relation "goose_db_version" does not exist at character 3614252026-09-21 18:12:38.715 UTC [4597] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1426--- PASS: TestPinProtectsFromGC (3.80s)1427=== CONT TestGCTaskStore_CompletedAllowsNewTask1428--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1429=== CONT TestCreatePendingClosureRejectsOversizedNAR14302026/09/21 18:12:38 INFO Received uploads request method=POST path=/api/pending_closures1431--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1432=== CONT TestCacheConfigHandlerMaxNarSize1433--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1434=== CONT TestGenerateLandingPage1435--- PASS: TestGenerateLandingPage (0.00s)1436=== CONT TestService_readinessHandler14372026/09/21 18:12:38 INFO Received uploads request method=POST path=/api/pending_closures14382026/09/21 18:12:38 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NGQxZTA5NzAtOGVmMS00YmFiLWE3ZGItOTQ3M2I1ZjJjYzEzLmQ1MmExNDYzLWYyMTYtNGNhMy1iZTdmLTc5Nzg5OGQxYzM2N3gxNzkwMDE0MzU3NTQ3MDc1MDAw parts=1014392026/09/21 18:12:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14402026/09/21 18:12:38 INFO Completed upload id=114412026/09/21 18:12:38 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014422026/09/21 18:12:38 INFO Received uploads request method=POST path=/api/pending_closures14432026/09/21 18:12:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures14442026/09/21 18:12:38 INFO Aborted multipart uploads count=014452026/09/21 18:12:38 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst14462026/09/21 18:12:38 INFO Received uploads request method=POST path=/api/pending_closures1447--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.75s)1448=== CONT TestGCTaskStore_StartNew1449--- PASS: TestGCTaskStore_StartNew (0.00s)1450=== CONT TestGCTaskStore_DeduplicateSameParams1451--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1452=== CONT TestService_AuthMiddleware_MTLSProxyHeader14532026/09/21 18:12:38 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=014542026/09/21 18:12:38 INFO Vacuumed table table=pending_closures14552026/09/21 18:12:38 OK 20241026095416_initial_model.sql (37.7ms)14562026/09/21 18:12:38 INFO Vacuumed table table=pending_objects14572026/09/21 18:12:38 OK 20251210153512_drop_unused_gin_index.sql (10.81ms)14582026/09/21 18:12:38 INFO Vacuumed table table=multipart_uploads14592026/09/21 18:12:38 OK 20251218171726_add_pins.sql (3.23ms)14602026/09/21 18:12:38 INFO Vacuumed table table=closures14612026/09/21 18:12:38 INFO Vacuumed table table=objects14622026/09/21 18:12:38 OK 20260628120000_add_object_size_and_stats.sql (20.75ms)14632026/09/21 18:12:38 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001464--- PASS: TestService_createPendingClosureHandler (2.65s)1465=== CONT TestReadProxyRootRedirectsToIndexHTML14662026/09/21 18:12:38 OK 20260905000000_add_claims.sql (24.29ms)14672026/09/21 18:12:38 OK 20260920000000_drop_claims.sql (18.83ms)14682026/09/21 18:12:38 goose: successfully migrated database to version: 2026092000000014692026/09/21 18:12:38 OK 1_commit_pending_closure.sql (1.72ms)14702026/09/21 18:12:38 OK 2_object_stats_trigger.sql (341.46µs)14712026/09/21 18:12:38 goose: up to current file version: 214722026/09/21 18:12:38 INFO Received uploads request method=POST path=/api/pending_closures14732026-09-21 18:12:38.993 UTC [4605] ERROR: relation "goose_db_version" does not exist at character 3614742026-09-21 18:12:38.993 UTC [4605] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14752026/09/21 18:12:39 INFO Received uploads request method=POST path=/api/pending_closures14762026/09/21 18:12:39 OK 20241026095416_initial_model.sql (153.88ms)14772026/09/21 18:12:39 OK 20251210153512_drop_unused_gin_index.sql (8.25ms)14782026/09/21 18:12:39 OK 20251218171726_add_pins.sql (24.48ms)14792026/09/21 18:12:39 OK 20260628120000_add_object_size_and_stats.sql (28.08ms)14802026/09/21 18:12:39 OK 20260905000000_add_claims.sql (69.77ms)14812026/09/21 18:12:39 OK 20260920000000_drop_claims.sql (24.4ms)14822026/09/21 18:12:39 goose: successfully migrated database to version: 2026092000000014832026/09/21 18:12:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14842026/09/21 18:12:39 OK 1_commit_pending_closure.sql (5.79ms)14852026/09/21 18:12:39 OK 2_object_stats_trigger.sql (1.07ms)14862026/09/21 18:12:39 goose: up to current file version: 214872026/09/21 18:12:39 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NGQxZTA5NzAtOGVmMS00YmFiLWE3ZGItOTQ3M2I1ZjJjYzEzLjBkNmE5OGUyLWM2ZWItNGEzYi05MDQ4LTdkZTE1MGQyM2VjMngxNzkwMDE0MzU5MTQ1MDM3MDAw14882026/09/21 18:12:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NGQxZTA5NzAtOGVmMS00YmFiLWE3ZGItOTQ3M2I1ZjJjYzEzLjBkNmE5OGUyLWM2ZWItNGEzYi05MDQ4LTdkZTE1MGQyM2VjMngxNzkwMDE0MzU5MTQ1MDM3MDAw parts=11489--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.18s)1490=== CONT TestReadProxyNarStreaming14912026/09/21 18:12:39 INFO Received uploads request method=POST path=/api/pending_closures14922026/09/21 18:12:39 INFO Received uploads request method=POST path=/api/pending_closures14932026-09-21 18:12:39.456 UTC [4608] ERROR: relation "goose_db_version" does not exist at character 3614942026-09-21 18:12:39.456 UTC [4608] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1495--- PASS: TestReadRedirectUsesPublicS3URL (1.87s)1496=== CONT TestReadRedirectKeepsNarinfoProxied14972026/09/21 18:12:39 OK 20241026095416_initial_model.sql (265.89ms)14982026/09/21 18:12:39 OK 20251210153512_drop_unused_gin_index.sql (17.29ms)14992026/09/21 18:12:39 OK 20251218171726_add_pins.sql (32.71ms)15002026/09/21 18:12:39 OK 20260628120000_add_object_size_and_stats.sql (47.34ms)15012026/09/21 18:12:39 OK 20260905000000_add_claims.sql (72.32ms)15022026/09/21 18:12:40 OK 20260920000000_drop_claims.sql (53.97ms)15032026/09/21 18:12:40 goose: successfully migrated database to version: 2026092000000015042026/09/21 18:12:40 OK 1_commit_pending_closure.sql (4ms)15052026/09/21 18:12:40 OK 2_object_stats_trigger.sql (919.25µs)15062026/09/21 18:12:40 goose: up to current file version: 215072026-09-21 18:12:40.028 UTC [4611] ERROR: relation "goose_db_version" does not exist at character 3615082026-09-21 18:12:40.028 UTC [4611] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15092026/09/21 18:12:40 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15102026/09/21 18:12:40 WARN mTLS auth: bound subjects configured but subject DN unavailable15112026/09/21 18:12:40 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1512--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.14s)1513=== CONT TestReadProxyDisabled15142026/09/21 18:12:40 OK 20241026095416_initial_model.sql (307.72ms)15152026/09/21 18:12:40 OK 20251210153512_drop_unused_gin_index.sql (18.16ms)15162026/09/21 18:12:40 OK 20251218171726_add_pins.sql (31.71ms)15172026/09/21 18:12:40 OK 20260628120000_add_object_size_and_stats.sql (42.19ms)15182026/09/21 18:12:40 OK 20260905000000_add_claims.sql (109.73ms)15192026/09/21 18:12:40 OK 20260920000000_drop_claims.sql (47.19ms)15202026/09/21 18:12:40 goose: successfully migrated database to version: 2026092000000015212026/09/21 18:12:40 OK 1_commit_pending_closure.sql (2.79ms)15222026/09/21 18:12:40 OK 2_object_stats_trigger.sql (487.63µs)15232026/09/21 18:12:40 goose: up to current file version: 215242026/09/21 18:12:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15252026/09/21 18:12:40 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NGQxZTA5NzAtOGVmMS00YmFiLWE3ZGItOTQ3M2I1ZjJjYzEzLjZlY2ZmNmE3LTI5MDMtNDA1MC1hYmUyLWFhYmQ1YTNmNzJhOXgxNzkwMDE0MzU4OTQ3MDM2MDAw parts=1215262026/09/21 18:12:40 INFO Received uploads request method=POST path=/api/pending_closures1527--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.68s)1528=== CONT TestReadRedirectNar15292026-09-21 18:12:40.796 UTC [4614] ERROR: relation "goose_db_version" does not exist at character 3615302026-09-21 18:12:40.796 UTC [4614] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15312026-09-21 18:12:40.797 UTC [4615] ERROR: relation "goose_db_version" does not exist at character 3615322026-09-21 18:12:40.797 UTC [4615] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15332026-09-21 18:12:40.908 UTC [4618] ERROR: relation "goose_db_version" does not exist at character 3615342026-09-21 18:12:40.908 UTC [4618] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1535--- PASS: TestService_ReadAuthMiddleware (2.41s)1536=== CONT TestReadProxyConditionalGet15372026/09/21 18:12:40 OK 20241026095416_initial_model.sql (151.94ms)15382026/09/21 18:12:40 OK 20241026095416_initial_model.sql (160.05ms)15392026/09/21 18:12:40 OK 20251210153512_drop_unused_gin_index.sql (14.27ms)15402026/09/21 18:12:40 OK 20251210153512_drop_unused_gin_index.sql (15.36ms)15412026/09/21 18:12:41 OK 20251218171726_add_pins.sql (33.26ms)15422026/09/21 18:12:41 OK 20251218171726_add_pins.sql (32.81ms)15432026/09/21 18:12:41 OK 20260628120000_add_object_size_and_stats.sql (18.67ms)15442026/09/21 18:12:41 OK 20260628120000_add_object_size_and_stats.sql (23.57ms)15452026/09/21 18:12:41 OK 20260905000000_add_claims.sql (28.77ms)15462026/09/21 18:12:41 OK 20241026095416_initial_model.sql (130.76ms)15472026/09/21 18:12:41 OK 20260905000000_add_claims.sql (16.33ms)15482026/09/21 18:12:41 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)15492026/09/21 18:12:41 OK 20260920000000_drop_claims.sql (3.33ms)15502026/09/21 18:12:41 goose: successfully migrated database to version: 2026092000000015512026/09/21 18:12:41 OK 20260920000000_drop_claims.sql (3.57ms)15522026/09/21 18:12:41 goose: successfully migrated database to version: 2026092000000015532026/09/21 18:12:41 OK 1_commit_pending_closure.sql (2.18ms)15542026/09/21 18:12:41 OK 2_object_stats_trigger.sql (393.29µs)15552026/09/21 18:12:41 goose: up to current file version: 215562026/09/21 18:12:41 OK 1_commit_pending_closure.sql (1.58ms)15572026/09/21 18:12:41 OK 2_object_stats_trigger.sql (410.63µs)15582026/09/21 18:12:41 goose: up to current file version: 215592026/09/21 18:12:41 OK 20251218171726_add_pins.sql (15.02ms)15602026/09/21 18:12:41 OK 20260628120000_add_object_size_and_stats.sql (41.36ms)15612026/09/21 18:12:41 OK 20260905000000_add_claims.sql (55.47ms)15622026/09/21 18:12:41 OK 20260920000000_drop_claims.sql (46.06ms)15632026/09/21 18:12:41 goose: successfully migrated database to version: 2026092000000015642026/09/21 18:12:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15652026/09/21 18:12:41 OK 1_commit_pending_closure.sql (55ms)15662026/09/21 18:12:41 OK 2_object_stats_trigger.sql (2.97ms)15672026/09/21 18:12:41 goose: up to current file version: 215682026/09/21 18:12:41 WARN readiness check failed error="closed pool"1569--- PASS: TestService_readinessHandler (2.59s)1570=== CONT TestReadProxyHead15712026/09/21 18:12:41 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NGQxZTA5NzAtOGVmMS00YmFiLWE3ZGItOTQ3M2I1ZjJjYzEzLmNlNmNiYzVlLWFmOTQtNDBjMy1iZGI3LTZmOGE2NjJjMTkwYngxNzkwMDE0MzU5NDE5MTM4MDAw parts=121572--- PASS: TestRedundantMultipartUpload (4.00s)1573=== CONT TestClientIntegration15742026-09-21 18:12:41.497 UTC [4625] ERROR: relation "goose_db_version" does not exist at character 3615752026-09-21 18:12:41.497 UTC [4625] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1576--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (2.78s)1577=== CONT TestClientMultipleUploads15782026/09/21 18:12:41 OK 20241026095416_initial_model.sql (118.9ms)15792026/09/21 18:12:41 OK 20251210153512_drop_unused_gin_index.sql (11.53ms)15802026-09-21 18:12:41.728 UTC [4628] ERROR: relation "goose_db_version" does not exist at character 3615812026-09-21 18:12:41.728 UTC [4628] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15822026/09/21 18:12:41 OK 20251218171726_add_pins.sql (24.8ms)15832026/09/21 18:12:41 OK 20260628120000_add_object_size_and_stats.sql (34.11ms)15842026/09/21 18:12:41 OK 20260905000000_add_claims.sql (50.6ms)1585--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.94s)1586=== CONT TestCreatePin_ReservedPins15872026/09/21 18:12:41 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50964/oidc15882026/09/21 18:12:41 OK 20260920000000_drop_claims.sql (11.99ms)15892026/09/21 18:12:41 goose: successfully migrated database to version: 2026092000000015902026/09/21 18:12:41 OK 1_commit_pending_closure.sql (6.38ms)15912026/09/21 18:12:41 OK 2_object_stats_trigger.sql (1.49ms)15922026/09/21 18:12:41 goose: up to current file version: 215932026/09/21 18:12:41 OK 20241026095416_initial_model.sql (59.92ms)15942026/09/21 18:12:41 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)15952026/09/21 18:12:41 OK 20251218171726_add_pins.sql (11.74ms)15962026/09/21 18:12:41 OK 20260628120000_add_object_size_and_stats.sql (25.74ms)15972026/09/21 18:12:41 OK 20260905000000_add_claims.sql (19.06ms)15982026/09/21 18:12:41 OK 20260920000000_drop_claims.sql (12.5ms)15992026/09/21 18:12:41 goose: successfully migrated database to version: 2026092000000016002026/09/21 18:12:41 OK 1_commit_pending_closure.sql (3.02ms)16012026/09/21 18:12:41 OK 2_object_stats_trigger.sql (603.42µs)16022026/09/21 18:12:41 goose: up to current file version: 216032026-09-21 18:12:41.915 UTC [4631] ERROR: relation "goose_db_version" does not exist at character 3616042026-09-21 18:12:41.915 UTC [4631] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16052026/09/21 18:12:41 WARN Rate limiter enabled after throttle name=s3-test rate=516062026/09/21 18:12:41 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1607=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1608 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101609 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001610--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.24s)1611=== CONT TestReadProxyNarinfo1612--- PASS: TestReadProxyNarStreaming (2.70s)1613=== CONT TestReadProxyNarinfoAlreadyDecompressed16142026/09/21 18:12:42 OK 20241026095416_initial_model.sql (157.91ms)16152026/09/21 18:12:42 OK 20251210153512_drop_unused_gin_index.sql (8.92ms)16162026/09/21 18:12:42 OK 20251218171726_add_pins.sql (38.4ms)16172026/09/21 18:12:42 OK 20260628120000_add_object_size_and_stats.sql (41.08ms)16182026/09/21 18:12:42 OK 20260905000000_add_claims.sql (61.66ms)16192026/09/21 18:12:42 OK 20260920000000_drop_claims.sql (29.99ms)16202026/09/21 18:12:42 goose: successfully migrated database to version: 2026092000000016212026/09/21 18:12:42 OK 1_commit_pending_closure.sql (5.06ms)16222026/09/21 18:12:42 OK 2_object_stats_trigger.sql (1.52ms)16232026/09/21 18:12:42 goose: up to current file version: 21624--- PASS: TestReadRedirectKeepsNarinfoProxied (2.69s)1625=== CONT TestIsValidCachePath1626=== RUN TestIsValidCachePath/narinfo1627=== PAUSE TestIsValidCachePath/narinfo1628=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1629=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1630=== RUN TestIsValidCachePath/nar_zst1631=== PAUSE TestIsValidCachePath/nar_zst1632=== RUN TestIsValidCachePath/nar_xz1633=== PAUSE TestIsValidCachePath/nar_xz1634=== RUN TestIsValidCachePath/nar_bz21635=== PAUSE TestIsValidCachePath/nar_bz21636=== RUN TestIsValidCachePath/nar_uncompressed1637=== PAUSE TestIsValidCachePath/nar_uncompressed1638=== RUN TestIsValidCachePath/ls1639=== PAUSE TestIsValidCachePath/ls1640=== RUN TestIsValidCachePath/log1641=== PAUSE TestIsValidCachePath/log1642=== RUN TestIsValidCachePath/realisation1643=== PAUSE TestIsValidCachePath/realisation1644=== RUN TestIsValidCachePath/nix-cache-info1645=== PAUSE TestIsValidCachePath/nix-cache-info1646=== RUN TestIsValidCachePath/index.html1647=== PAUSE TestIsValidCachePath/index.html1648=== RUN TestIsValidCachePath/traversal_parent1649=== PAUSE TestIsValidCachePath/traversal_parent1650=== RUN TestIsValidCachePath/traversal_in_middle1651=== PAUSE TestIsValidCachePath/traversal_in_middle1652=== RUN TestIsValidCachePath/invalid_char_e1653=== PAUSE TestIsValidCachePath/invalid_char_e1654=== RUN TestIsValidCachePath/invalid_char_u1655=== PAUSE TestIsValidCachePath/invalid_char_u1656=== RUN TestIsValidCachePath/random_path1657=== PAUSE TestIsValidCachePath/random_path1658=== RUN TestIsValidCachePath/empty1659=== PAUSE TestIsValidCachePath/empty1660=== RUN TestIsValidCachePath/leading_slash1661=== PAUSE TestIsValidCachePath/leading_slash1662=== RUN TestIsValidCachePath/wrong_extension1663=== PAUSE TestIsValidCachePath/wrong_extension1664=== RUN TestIsValidCachePath/short_hash1665=== PAUSE TestIsValidCachePath/short_hash1666=== CONT TestParseSingleRange1667=== RUN TestParseSingleRange/none1668=== PAUSE TestParseSingleRange/none1669=== RUN TestParseSingleRange/unknown_unit1670=== PAUSE TestParseSingleRange/unknown_unit1671=== RUN TestParseSingleRange/multi-range_ignored1672=== PAUSE TestParseSingleRange/multi-range_ignored1673=== RUN TestParseSingleRange/malformed_no_dash1674=== PAUSE TestParseSingleRange/malformed_no_dash1675=== RUN TestParseSingleRange/malformed_both_empty1676=== PAUSE TestParseSingleRange/malformed_both_empty1677=== RUN TestParseSingleRange/malformed_end_before_start1678=== PAUSE TestParseSingleRange/malformed_end_before_start1679=== RUN TestParseSingleRange/closed1680=== PAUSE TestParseSingleRange/closed1681=== RUN TestParseSingleRange/open-ended1682=== PAUSE TestParseSingleRange/open-ended1683=== RUN TestParseSingleRange/end_clamped_to_size1684=== PAUSE TestParseSingleRange/end_clamped_to_size1685=== RUN TestParseSingleRange/suffix1686=== PAUSE TestParseSingleRange/suffix1687=== RUN TestParseSingleRange/suffix_exceeds_size1688=== PAUSE TestParseSingleRange/suffix_exceeds_size1689=== RUN TestParseSingleRange/single_byte1690=== PAUSE TestParseSingleRange/single_byte1691=== RUN TestParseSingleRange/start_past_EOF1692=== PAUSE TestParseSingleRange/start_past_EOF1693=== RUN TestParseSingleRange/start_far_past_EOF1694=== PAUSE TestParseSingleRange/start_far_past_EOF1695=== CONT TestReadProxyInvalidPath16962026-09-21 18:12:42.485 UTC [4638] ERROR: relation "goose_db_version" does not exist at character 3616972026-09-21 18:12:42.485 UTC [4638] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1698--- PASS: TestReadProxyDisabled (2.19s)1699=== CONT TestReadProxy40417002026-09-21 18:12:42.604 UTC [4639] ERROR: relation "goose_db_version" does not exist at character 3617012026-09-21 18:12:42.604 UTC [4639] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17022026/09/21 18:12:42 OK 20241026095416_initial_model.sql (106.57ms)17032026/09/21 18:12:42 OK 20251210153512_drop_unused_gin_index.sql (8.52ms)17042026/09/21 18:12:42 OK 20251218171726_add_pins.sql (33.36ms)17052026/09/21 18:12:42 OK 20260628120000_add_object_size_and_stats.sql (67.93ms)17062026/09/21 18:12:42 OK 20241026095416_initial_model.sql (114.69ms)17072026/09/21 18:12:42 OK 20251210153512_drop_unused_gin_index.sql (8.29ms)17082026/09/21 18:12:42 OK 20260905000000_add_claims.sql (42.85ms)17092026/09/21 18:12:42 OK 20251218171726_add_pins.sql (33.11ms)17102026/09/21 18:12:42 OK 20260920000000_drop_claims.sql (4.96ms)17112026/09/21 18:12:42 goose: successfully migrated database to version: 2026092000000017122026/09/21 18:12:42 OK 1_commit_pending_closure.sql (6.4ms)17132026/09/21 18:12:42 OK 2_object_stats_trigger.sql (1.6ms)17142026/09/21 18:12:42 goose: up to current file version: 217152026-09-21 18:12:42.824 UTC [4642] ERROR: relation "goose_db_version" does not exist at character 3617162026-09-21 18:12:42.824 UTC [4642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17172026/09/21 18:12:42 OK 20260628120000_add_object_size_and_stats.sql (16.35ms)17182026-09-21 18:12:42.825 UTC [4643] ERROR: relation "goose_db_version" does not exist at character 3617192026-09-21 18:12:42.825 UTC [4643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17202026/09/21 18:12:42 OK 20260905000000_add_claims.sql (11.9ms)17212026/09/21 18:12:42 OK 20260920000000_drop_claims.sql (15.46ms)17222026/09/21 18:12:42 goose: successfully migrated database to version: 2026092000000017232026/09/21 18:12:42 OK 1_commit_pending_closure.sql (3.19ms)17242026/09/21 18:12:42 OK 2_object_stats_trigger.sql (557.29µs)17252026/09/21 18:12:42 goose: up to current file version: 217262026/09/21 18:12:43 OK 20241026095416_initial_model.sql (165.43ms)17272026/09/21 18:12:43 OK 20241026095416_initial_model.sql (182.29ms)17282026/09/21 18:12:43 OK 20251210153512_drop_unused_gin_index.sql (10.91ms)17292026/09/21 18:12:43 OK 20251210153512_drop_unused_gin_index.sql (16.08ms)17302026/09/21 18:12:43 OK 20251218171726_add_pins.sql (34.82ms)17312026/09/21 18:12:43 OK 20251218171726_add_pins.sql (42.28ms)17322026/09/21 18:12:43 OK 20260628120000_add_object_size_and_stats.sql (54.21ms)17332026/09/21 18:12:43 OK 20260628120000_add_object_size_and_stats.sql (39.07ms)1734--- PASS: TestReadRedirectNar (2.43s)1735=== CONT TestOrphanedObjectsGCStressTest17362026/09/21 18:12:43 OK 20260905000000_add_claims.sql (52.93ms)17372026/09/21 18:12:43 OK 20260905000000_add_claims.sql (54.41ms)17382026-09-21 18:12:43.223 UTC [4644] ERROR: relation "goose_db_version" does not exist at character 3617392026-09-21 18:12:43.223 UTC [4644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17402026/09/21 18:12:43 OK 20260920000000_drop_claims.sql (24.42ms)17412026/09/21 18:12:43 goose: successfully migrated database to version: 2026092000000017422026/09/21 18:12:43 OK 1_commit_pending_closure.sql (1.79ms)17432026/09/21 18:12:43 OK 2_object_stats_trigger.sql (389.38µs)17442026/09/21 18:12:43 goose: up to current file version: 217452026/09/21 18:12:43 OK 20260920000000_drop_claims.sql (27.54ms)17462026/09/21 18:12:43 goose: successfully migrated database to version: 2026092000000017472026/09/21 18:12:43 OK 1_commit_pending_closure.sql (1.78ms)17482026/09/21 18:12:43 OK 2_object_stats_trigger.sql (467.71µs)17492026/09/21 18:12:43 goose: up to current file version: 217502026/09/21 18:12:43 OK 20241026095416_initial_model.sql (179.92ms)17512026/09/21 18:12:43 OK 20251210153512_drop_unused_gin_index.sql (21.63ms)1752--- PASS: TestReadProxyConditionalGet (2.53s)1753=== CONT TestOrphanedObjectsGC17542026/09/21 18:12:43 OK 20251218171726_add_pins.sql (26.23ms)17552026/09/21 18:12:43 OK 20260628120000_add_object_size_and_stats.sql (31.37ms)17562026/09/21 18:12:43 OK 20260905000000_add_claims.sql (48.35ms)17572026/09/21 18:12:43 OK 20260920000000_drop_claims.sql (61.35ms)17582026/09/21 18:12:43 goose: successfully migrated database to version: 2026092000000017592026/09/21 18:12:43 OK 1_commit_pending_closure.sql (5.58ms)17602026/09/21 18:12:43 OK 2_object_stats_trigger.sql (1.26ms)17612026/09/21 18:12:43 goose: up to current file version: 217622026-09-21 18:12:43.941 UTC [4652] ERROR: relation "goose_db_version" does not exist at character 3617632026-09-21 18:12:43.941 UTC [4652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17642026-09-21 18:12:44.039 UTC [4655] ERROR: relation "goose_db_version" does not exist at character 3617652026-09-21 18:12:44.039 UTC [4655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1766=== NAME TestClientIntegration1767 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-4239-4131808779/TestClientIntegration1268208526/002/store/zw4s2sm88zs9212l27laf4pkizpnhviz-test-file.txt1768--- PASS: TestReadProxyHead (2.71s)1769=== CONT TestResurrectedObjectNotDeleted17702026-09-21 18:12:44.076 UTC [4658] ERROR: relation "goose_db_version" does not exist at character 3617712026-09-21 18:12:44.076 UTC [4658] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17722026/09/21 18:12:44 OK 20241026095416_initial_model.sql (89.32ms)17732026/09/21 18:12:44 OK 20251210153512_drop_unused_gin_index.sql (2.44ms)17742026/09/21 18:12:44 OK 20251218171726_add_pins.sql (9.79ms)17752026/09/21 18:12:44 OK 20260628120000_add_object_size_and_stats.sql (11.76ms)17762026/09/21 18:12:44 OK 20241026095416_initial_model.sql (52.13ms)17772026-09-21 18:12:44.127 UTC [4662] ERROR: relation "goose_db_version" does not exist at character 3617782026-09-21 18:12:44.127 UTC [4662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17792026/09/21 18:12:44 OK 20251210153512_drop_unused_gin_index.sql (3.33ms)17802026/09/21 18:12:44 OK 20260905000000_add_claims.sql (14.53ms)17812026/09/21 18:12:44 OK 20260920000000_drop_claims.sql (9.59ms)17822026/09/21 18:12:44 goose: successfully migrated database to version: 2026092000000017832026/09/21 18:12:44 OK 20251218171726_add_pins.sql (15.28ms)17842026/09/21 18:12:44 OK 1_commit_pending_closure.sql (1.09ms)17852026/09/21 18:12:44 OK 2_object_stats_trigger.sql (427.21µs)17862026/09/21 18:12:44 goose: up to current file version: 217872026/09/21 18:12:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"17882026/09/21 18:12:44 OK 20241026095416_initial_model.sql (62.38ms)17892026/09/21 18:12:44 OK 20260628120000_add_object_size_and_stats.sql (17.73ms)17902026/09/21 18:12:44 OK 20251210153512_drop_unused_gin_index.sql (6.26ms)17912026/09/21 18:12:44 OK 20251218171726_add_pins.sql (13.57ms)17922026/09/21 18:12:44 OK 20260905000000_add_claims.sql (32.52ms)17932026/09/21 18:12:44 OK 20260628120000_add_object_size_and_stats.sql (14.85ms)17942026/09/21 18:12:44 OK 20260920000000_drop_claims.sql (7.46ms)17952026/09/21 18:12:44 goose: successfully migrated database to version: 2026092000000017962026-09-21 18:12:44.204 UTC [4666] ERROR: relation "goose_db_version" does not exist at character 3617972026-09-21 18:12:44.204 UTC [4666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17982026/09/21 18:12:44 INFO Received uploads request method=POST path=/api/pending_closures17992026/09/21 18:12:44 OK 1_commit_pending_closure.sql (1.22ms)18002026/09/21 18:12:44 OK 2_object_stats_trigger.sql (232.88µs)18012026/09/21 18:12:44 goose: up to current file version: 218022026/09/21 18:12:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18032026/09/21 18:12:44 INFO Uploading zw4s2sm88zs9212l27laf4pkizpnhviz-test-file.txt (152B)18042026/09/21 18:12:44 OK 20260905000000_add_claims.sql (38.27ms)18052026/09/21 18:12:44 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18062026/09/21 18:12:44 OK 20260920000000_drop_claims.sql (1.22ms)18072026/09/21 18:12:44 goose: successfully migrated database to version: 2026092000000018082026/09/21 18:12:44 OK 20241026095416_initial_model.sql (74.54ms)18092026/09/21 18:12:44 OK 20251210153512_drop_unused_gin_index.sql (822.13µs)18102026/09/21 18:12:44 OK 1_commit_pending_closure.sql (1.53ms)18112026/09/21 18:12:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18122026/09/21 18:12:44 WARN Failed to register uploaded object key=zw4s2sm88zs9212l27laf4pkizpnhviz.ls error="server returned 404: 404 page not found\n"18132026/09/21 18:12:44 INFO Signed narinfos id=1 count=118142026/09/21 18:12:44 INFO Uploading 1 narinfos18152026/09/21 18:12:44 OK 2_object_stats_trigger.sql (279.58µs)18162026/09/21 18:12:44 goose: up to current file version: 218172026/09/21 18:12:44 OK 20251218171726_add_pins.sql (6.77ms)18182026/09/21 18:12:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18192026/09/21 18:12:44 WARN Failed to register uploaded object key=zw4s2sm88zs9212l27laf4pkizpnhviz.narinfo error="server returned 404: 404 page not found\n"18202026/09/21 18:12:44 OK 20260628120000_add_object_size_and_stats.sql (10.65ms)18212026/09/21 18:12:44 INFO Completed upload id=118222026/09/21 18:12:44 INFO Upload complete. (159ms)18232026/09/21 18:12:44 OK 20260905000000_add_claims.sql (6.79ms)18242026/09/21 18:12:44 OK 20241026095416_initial_model.sql (33.18ms)18252026/09/21 18:12:44 OK 20260920000000_drop_claims.sql (8.56ms)18262026/09/21 18:12:44 goose: successfully migrated database to version: 2026092000000018272026/09/21 18:12:44 OK 1_commit_pending_closure.sql (827.54µs)18282026/09/21 18:12:44 OK 2_object_stats_trigger.sql (216.13µs)18292026/09/21 18:12:44 goose: up to current file version: 218302026/09/21 18:12:44 OK 20251210153512_drop_unused_gin_index.sql (5.58ms)18312026/09/21 18:12:44 OK 20251218171726_add_pins.sql (9.3ms)18322026/09/21 18:12:44 INFO All 1 paths already cached1833=== NAME TestClientIntegration1834 client_integration_test.go:312: Retrieved narinfo from S3:1835 StorePath: /nix/var/nix/builds/nix-4239-4131808779/TestClientIntegration1268208526/002/store/zw4s2sm88zs9212l27laf4pkizpnhviz-test-file.txt1836 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1837 Compression: zstd1838 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11839 NarSize: 1521840 References: 1841 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11842 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1843 client_integration_test.go:313: Decompressed .ls content (64 bytes):1844 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1845 client_integration_test.go:316: Testing garbage collection...18462026/09/21 18:12:44 OK 20260628120000_add_object_size_and_stats.sql (11.2ms)18472026/09/21 18:12:44 OK 20260905000000_add_claims.sql (14.75ms)18482026/09/21 18:12:44 OK 20260920000000_drop_claims.sql (8.05ms)18492026/09/21 18:12:44 goose: successfully migrated database to version: 202609200000001850=== NAME TestClientMultipleUploads1851 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-4239-4131808779/TestClientMultipleUploads4019813612/001/store/9408f64s4wr3iycn584zby5pisqfr3p7-test-file-0.txt18522026/09/21 18:12:44 OK 1_commit_pending_closure.sql (1.89ms)18532026/09/21 18:12:44 OK 2_object_stats_trigger.sql (370.83µs)18542026/09/21 18:12:44 goose: up to current file version: 218552026/09/21 18:12:44 INFO Starting cleanup of old closures method=DELETE path=/api/closures18562026/09/21 18:12:44 INFO Garbage collection started18572026/09/21 18:12:44 INFO Aborted multipart uploads count=018582026/09/21 18:12:44 WARN Force mode enabled - objects will be deleted immediately without grace period1859 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-4239-4131808779/TestClientMultipleUploads4019813612/001/store/pwyfkljhram0h3qfj70wq62bdc3h223q-test-file-1.txt18602026/09/21 18:12:44 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18612026/09/21 18:12:44 WARN Refused reserved pin name=worker-x86_64-linux18622026/09/21 18:12:44 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux18632026/09/21 18:12:44 INFO Received create pin request method=POST path=/api/pins/my-app18642026/09/21 18:12:44 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1865--- PASS: TestCreatePin_ReservedPins (2.57s)1866=== CONT TestObjectStatsTrigger18672026-09-21 18:12:44.413 UTC [4679] ERROR: relation "goose_db_version" does not exist at character 3618682026-09-21 18:12:44.413 UTC [4679] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1869=== NAME TestClientMultipleUploads1870 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-4239-4131808779/TestClientMultipleUploads4019813612/001/store/bjag73m79i3nn3qaddy1aqxw7dwp1mmi-test-file-2.txt18712026/09/21 18:12:44 OK 20241026095416_initial_model.sql (34.68ms)18722026/09/21 18:12:44 OK 20251210153512_drop_unused_gin_index.sql (3.66ms)18732026/09/21 18:12:44 OK 20251218171726_add_pins.sql (7.13ms)18742026/09/21 18:12:44 OK 20260628120000_add_object_size_and_stats.sql (25.86ms)18752026/09/21 18:12:44 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"18762026-09-21 18:12:44.515 UTC [4686] ERROR: relation "goose_db_version" does not exist at character 3618772026-09-21 18:12:44.515 UTC [4686] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18782026/09/21 18:12:44 OK 20260905000000_add_claims.sql (19.64ms)18792026/09/21 18:12:44 OK 20260920000000_drop_claims.sql (1.52ms)18802026/09/21 18:12:44 goose: successfully migrated database to version: 2026092000000018812026/09/21 18:12:44 OK 1_commit_pending_closure.sql (1.13ms)18822026/09/21 18:12:44 OK 2_object_stats_trigger.sql (325.21µs)18832026/09/21 18:12:44 goose: up to current file version: 21884--- PASS: TestReadProxyNarinfo (2.61s)1885=== CONT TestGCTaskStore_GetReturnsLatest1886--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1887=== CONT TestClientErrorHandling/InvalidStorePath18882026/09/21 18:12: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=018892026/09/21 18:12:44 INFO Vacuumed table table=pending_closures18902026/09/21 18:12:44 INFO Vacuumed table table=pending_objects18912026/09/21 18:12:44 INFO Vacuumed table table=multipart_uploads18922026/09/21 18:12:44 INFO Received uploads request method=POST path=/api/pending_closures18932026/09/21 18:12:44 OK 20241026095416_initial_model.sql (29.14ms)18942026/09/21 18:12:44 OK 20251210153512_drop_unused_gin_index.sql (7.19ms)18952026/09/21 18:12:44 INFO Vacuumed table table=closures18962026/09/21 18:12:44 INFO Vacuumed table table=objects18972026/09/21 18:12:44 INFO Received uploads request method=POST path=/api/pending_closures18982026/09/21 18:12:44 INFO Received uploads request method=POST path=/api/pending_closures18992026/09/21 18:12:44 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19002026/09/21 18:12:44 INFO Uploading pwyfkljhram0h3qfj70wq62bdc3h223q-test-file-1.txt (160B)19012026/09/21 18:12:44 INFO Uploading 9408f64s4wr3iycn584zby5pisqfr3p7-test-file-0.txt (160B)19022026/09/21 18:12:44 INFO Uploading bjag73m79i3nn3qaddy1aqxw7dwp1mmi-test-file-2.txt (160B)19032026/09/21 18:12:44 OK 20251218171726_add_pins.sql (10.56ms)19042026/09/21 18:12:44 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19052026/09/21 18:12:44 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19062026/09/21 18:12:44 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19072026/09/21 18:12:44 WARN Failed to register uploaded object key=pwyfkljhram0h3qfj70wq62bdc3h223q.ls error="server returned 404: 404 page not found\n"19082026/09/21 18:12:44 WARN Failed to register uploaded object key=9408f64s4wr3iycn584zby5pisqfr3p7.ls error="server returned 404: 404 page not found\n"19092026/09/21 18:12:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign19102026/09/21 18:12:44 WARN Failed to register uploaded object key=bjag73m79i3nn3qaddy1aqxw7dwp1mmi.ls error="server returned 404: 404 page not found\n"19112026/09/21 18:12:44 INFO Signed narinfos id=1 count=119122026/09/21 18:12:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign19132026/09/21 18:12:44 INFO Signed narinfos id=2 count=119142026/09/21 18:12:44 INFO Received sign narinfos request method=POST path=/api/pending_closures/3/sign19152026/09/21 18:12:44 INFO Signed narinfos id=3 count=119162026/09/21 18:12:44 INFO Uploading 3 narinfos19172026/09/21 18:12:44 OK 20260628120000_add_object_size_and_stats.sql (19.74ms)19182026/09/21 18:12:44 WARN Failed to register uploaded object key=pwyfkljhram0h3qfj70wq62bdc3h223q.narinfo error="server returned 404: 404 page not found\n"19192026/09/21 18:12:44 WARN Failed to register uploaded object key=bjag73m79i3nn3qaddy1aqxw7dwp1mmi.narinfo error="server returned 404: 404 page not found\n"19202026/09/21 18:12:44 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19212026/09/21 18:12:44 WARN Failed to register uploaded object key=9408f64s4wr3iycn584zby5pisqfr3p7.narinfo error="server returned 404: 404 page not found\n"19222026/09/21 18:12:44 INFO Completed upload id=119232026/09/21 18:12:44 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete19242026/09/21 18:12:44 INFO Completed upload id=219252026/09/21 18:12:44 INFO Received complete upload request method=POST path=/api/pending_closures/3/complete19262026/09/21 18:12:44 INFO Completed upload id=319272026/09/21 18:12:44 INFO Upload complete. (149ms)1928=== NAME TestClientMultipleUploads1929 client_integration_test.go:369: Uploaded 3 paths in 185.034125ms19302026/09/21 18:12:44 OK 20260905000000_add_claims.sql (21.67ms)19312026/09/21 18:12:44 OK 20260920000000_drop_claims.sql (2.1ms)19322026/09/21 18:12:44 goose: successfully migrated database to version: 2026092000000019332026/09/21 18:12:44 OK 1_commit_pending_closure.sql (876.83µs)19342026/09/21 18:12:44 OK 2_object_stats_trigger.sql (228.08µs)19352026/09/21 18:12:44 goose: up to current file version: 21936--- PASS: TestClientMultipleUploads (3.05s)1937=== CONT TestClientErrorHandling/ServerNotAvailable19382026-09-21 18:12:44.645 UTC [4692] ERROR: relation "goose_db_version" does not exist at character 3619392026-09-21 18:12:44.645 UTC [4692] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1940--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.60s)1941=== CONT TestClientErrorHandling/InvalidAuthToken19422026/09/21 18:12:44 OK 20241026095416_initial_model.sql (42.13ms)19432026/09/21 18:12:44 OK 20251210153512_drop_unused_gin_index.sql (806µs)19442026/09/21 18:12:44 OK 20251218171726_add_pins.sql (7.73ms)19452026/09/21 18:12:44 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19462026/09/21 18:12:44 OK 20260628120000_add_object_size_and_stats.sql (8.31ms)19472026/09/21 18:12:44 OK 20260905000000_add_claims.sql (7.62ms)19482026/09/21 18:12:44 OK 20260920000000_drop_claims.sql (15.96ms)19492026/09/21 18:12:44 goose: successfully migrated database to version: 2026092000000019502026/09/21 18:12:44 OK 1_commit_pending_closure.sql (1.03ms)19512026/09/21 18:12:44 OK 2_object_stats_trigger.sql (217.5µs)19522026/09/21 18:12:44 goose: up to current file version: 21953--- PASS: TestReadProxyInvalidPath (2.44s)1954=== CONT TestCacheConfigHandler/full_config,_no_issuer1955=== CONT TestCacheConfigHandler/no_signing_keys1956=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1957=== CONT TestCacheConfigHandler/no_cache_url_configured1958--- PASS: TestCacheConfigHandler (0.00s)1959 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1960 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1961 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1962 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1963=== CONT TestServerTLSConfig/no_client_CA1964=== CONT TestServerTLSConfig/not_a_PEM_file1965=== CONT TestServerTLSConfig/missing_CA_file1966--- PASS: TestServerTLSConfig (0.00s)1967 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1968 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1969 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1970=== CONT TestService_RequireScope_OIDC/builder_may_write1971=== CONT TestService_RequireScope_OIDC/static_token_may_admin1972=== CONT TestService_RequireScope_OIDC/reader_may_not_write1973=== CONT TestService_RequireScope_OIDC/ops_may_not_write1974=== CONT TestService_RequireScope_OIDC/ops_may_admin1975=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1976=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1977=== CONT TestService_RequireScope_OIDC/static_token_may_write1978=== CONT TestService_RequireScope_OIDC/writer_implies_read1979=== CONT TestService_RequireScope_OIDC/reader_may_read1980=== CONT TestResolveDBConnectionString/flag_wins1981=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1982=== CONT TestResolveDBConnectionString/nothing_configured1983=== CONT TestResolveDBConnectionString/missing_file_is_an_error1984=== CONT TestResolveDBConnectionString/file_when_flag_empty1985=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1986=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1987=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19882026/09/21 18:12:44 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]1989=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1990--- PASS: TestResolveDBConnectionString (0.00s)1991 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1992 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1993 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1994 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1995 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1996--- PASS: TestService_RequireScope_OIDC (1.26s)1997 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1998 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1999 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2000 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2001 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2002 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2003 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2004 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2005 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2006 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)20072026/09/21 18:12:44 WARN Authentication failed token_preview=eyJhbGciOi...KLmwB83yAw token_length=702 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2008=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts20092026/09/21 18:12:44 INFO Received request for more parts method=POST path=/2010--- PASS: TestService_AuthMiddleware_OIDC (1.60s)2011 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2012 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2013 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2014 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2015=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure20162026/09/21 18:12:44 INFO Received uploads request method=POST path=/20172026-09-21 18:12:44.841 UTC [4698] ERROR: relation "goose_db_version" does not exist at character 3620182026-09-21 18:12:44.841 UTC [4698] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20192026/09/21 18:12:44 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.910668ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20202026/09/21 18:12:44 OK 20241026095416_initial_model.sql (28.32ms)20212026/09/21 18:12:44 OK 20251210153512_drop_unused_gin_index.sql (4.91ms)20222026/09/21 18:12:44 OK 20251218171726_add_pins.sql (9.26ms)20232026/09/21 18:12:44 OK 20260628120000_add_object_size_and_stats.sql (11.7ms)20242026/09/21 18:12:44 OK 20260905000000_add_claims.sql (14.93ms)2025--- PASS: TestReadProxy404 (2.34s)2026=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart20272026/09/21 18:12:44 INFO Received complete multipart upload request method=POST path=/20282026/09/21 18:12:44 OK 20260920000000_drop_claims.sql (1.44ms)20292026/09/21 18:12:44 goose: successfully migrated database to version: 2026092000000020302026/09/21 18:12:44 OK 1_commit_pending_closure.sql (1.22ms)20312026/09/21 18:12:44 OK 2_object_stats_trigger.sql (239.29µs)20322026/09/21 18:12:44 goose: up to current file version: 22033=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20342026/09/21 18:12:44 INFO Received uploads request method=POST path=/2035=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20362026/09/21 18:12:44 INFO Received complete multipart upload request method=POST path=/2037=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20382026/09/21 18:12:44 INFO Received request for more parts method=POST path=/2039=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20402026/09/21 18:12:44 INFO Received uploads request method=POST path=/2041--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2042 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2043 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2044 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2045 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2046=== CONT TestIsValidUploadKey/narinfo2047=== CONT TestIsValidUploadKey/realisation_plus_in_output2048=== CONT TestIsValidUploadKey/unknown_type2049=== CONT TestIsValidUploadKey/empty_key2050=== CONT TestIsValidUploadKey/absolute2051=== CONT TestIsValidUploadKey/traversal_nar2052=== CONT TestIsValidUploadKey/traversal2053=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2054=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2055=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2056=== CONT TestIsValidUploadKey/index.html2057=== CONT TestIsValidUploadKey/nix-cache-info2058=== CONT TestIsValidUploadKey/build_log_home-manager_file2059=== CONT TestIsValidUploadKey/realisation2060=== CONT TestIsValidUploadKey/build_log_equals2061=== CONT TestIsValidUploadKey/build_log_question_mark2062=== CONT TestIsValidUploadKey/build_log_plus_in_name2063=== CONT TestIsValidUploadKey/nar_plain2064=== CONT TestIsValidUploadKey/build_log2065=== CONT TestIsValidUploadKey/listing2066=== CONT TestIsValidUploadKey/nar_xz2067=== CONT TestIsValidUploadKey/nar_zst2068--- PASS: TestIsValidUploadKey (0.00s)2069 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2070 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2071 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2072 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2073 --- PASS: TestIsValidUploadKey/absolute (0.00s)2074 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2075 --- PASS: TestIsValidUploadKey/traversal (0.00s)2076 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2077 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2078 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2079 --- PASS: TestIsValidUploadKey/index.html (0.00s)2080 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2081 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2082 --- PASS: TestIsValidUploadKey/realisation (0.00s)2083 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2084 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2085 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2086 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2087 --- PASS: TestIsValidUploadKey/build_log (0.00s)2088 --- PASS: TestIsValidUploadKey/listing (0.00s)2089 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2090 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2091=== CONT TestProxyWriteTimeout/narinfo2092=== CONT TestProxyWriteTimeout/10_GiB_nar2093=== CONT TestProxyWriteTimeout/unknown_size2094=== CONT TestProxyWriteTimeout/1_GiB_nar2095--- PASS: TestProxyWriteTimeout (0.00s)2096 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2097 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2098 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2099 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2100=== CONT TestIsValidCachePath/narinfo2101=== CONT TestIsValidCachePath/index.html2102=== CONT TestIsValidCachePath/short_hash2103=== CONT TestIsValidCachePath/wrong_extension2104=== CONT TestIsValidCachePath/leading_slash2105=== CONT TestIsValidCachePath/empty2106=== CONT TestIsValidCachePath/random_path2107=== CONT TestIsValidCachePath/invalid_char_u2108=== CONT TestIsValidCachePath/invalid_char_e2109=== CONT TestIsValidCachePath/traversal_in_middle2110=== CONT TestIsValidCachePath/traversal_parent2111=== CONT TestIsValidCachePath/nar_uncompressed2112=== CONT TestIsValidCachePath/nix-cache-info2113=== CONT TestIsValidCachePath/realisation2114=== CONT TestIsValidCachePath/log2115=== CONT TestIsValidCachePath/ls2116=== CONT TestIsValidCachePath/nar_xz2117=== CONT TestIsValidCachePath/nar_bz22118=== CONT TestIsValidCachePath/nar_zst2119=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2120--- PASS: TestIsValidCachePath (0.00s)2121 --- PASS: TestIsValidCachePath/narinfo (0.00s)2122 --- PASS: TestIsValidCachePath/index.html (0.00s)2123 --- PASS: TestIsValidCachePath/short_hash (0.00s)2124 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2125 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2126 --- PASS: TestIsValidCachePath/empty (0.00s)2127 --- PASS: TestIsValidCachePath/random_path (0.00s)2128 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2129 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2130 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2131 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2132 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2133 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2134 --- PASS: TestIsValidCachePath/realisation (0.00s)2135 --- PASS: TestIsValidCachePath/log (0.00s)2136 --- PASS: TestIsValidCachePath/ls (0.00s)2137 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2138 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2139 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2140 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2141=== CONT TestParseSingleRange/none2142=== CONT TestParseSingleRange/open-ended2143=== CONT TestParseSingleRange/start_far_past_EOF2144=== CONT TestParseSingleRange/start_past_EOF2145=== CONT TestParseSingleRange/single_byte2146=== CONT TestParseSingleRange/suffix_exceeds_size2147=== CONT TestParseSingleRange/suffix2148=== CONT TestParseSingleRange/end_clamped_to_size2149=== CONT TestParseSingleRange/malformed_both_empty2150=== CONT TestParseSingleRange/closed2151=== CONT TestParseSingleRange/malformed_end_before_start2152=== CONT TestParseSingleRange/malformed_no_dash2153=== CONT TestParseSingleRange/unknown_unit2154=== CONT TestParseSingleRange/multi-range_ignored2155--- PASS: TestParseSingleRange (0.00s)2156 --- PASS: TestParseSingleRange/none (0.00s)2157 --- PASS: TestParseSingleRange/open-ended (0.00s)2158 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2159 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2160 --- PASS: TestParseSingleRange/single_byte (0.00s)2161 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2162 --- PASS: TestParseSingleRange/suffix (0.00s)2163 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2164 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2165 --- PASS: TestParseSingleRange/closed (0.00s)2166 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2167 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2168 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2169 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)21702026-09-21 18:12:44.973 UTC [4699] ERROR: relation "goose_db_version" does not exist at character 3621712026-09-21 18:12:44.973 UTC [4699] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21722026/09/21 18:12:45 OK 20241026095416_initial_model.sql (26.51ms)21732026/09/21 18:12:45 OK 20251210153512_drop_unused_gin_index.sql (458.96µs)21742026/09/21 18:12:45 OK 20251218171726_add_pins.sql (8.98ms)21752026/09/21 18:12:45 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=406.816015ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21762026/09/21 18:12:45 OK 20260628120000_add_object_size_and_stats.sql (13.49ms)21772026/09/21 18:12:45 OK 20260905000000_add_claims.sql (16.23ms)21782026/09/21 18:12:45 OK 20260920000000_drop_claims.sql (802.04µs)21792026/09/21 18:12:45 goose: successfully migrated database to version: 2026092000000021802026/09/21 18:12:45 OK 1_commit_pending_closure.sql (959.21µs)21812026/09/21 18:12:45 OK 2_object_stats_trigger.sql (323.5µs)21822026/09/21 18:12:45 goose: up to current file version: 22183--- PASS: TestUploadHandlersRejectOversizedBody (0.02s)2184 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2185 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2186 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.26s)21872026-09-21 18:12:45.109 UTC [4700] ERROR: relation "goose_db_version" does not exist at character 3621882026-09-21 18:12:45.109 UTC [4700] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21892026/09/21 18:12:45 OK 20241026095416_initial_model.sql (36.76ms)21902026/09/21 18:12:45 OK 20251210153512_drop_unused_gin_index.sql (7.43ms)21912026/09/21 18:12:45 OK 20251218171726_add_pins.sql (12.95ms)21922026/09/21 18:12:45 OK 20260628120000_add_object_size_and_stats.sql (5.85ms)21932026/09/21 18:12:45 OK 20260905000000_add_claims.sql (1.22ms)21942026/09/21 18:12:45 OK 20260920000000_drop_claims.sql (1.3ms)21952026/09/21 18:12:45 goose: successfully migrated database to version: 2026092000000021962026/09/21 18:12:45 OK 1_commit_pending_closure.sql (1.07ms)21972026/09/21 18:12:45 OK 2_object_stats_trigger.sql (267.92µs)21982026/09/21 18:12:45 goose: up to current file version: 22199--- PASS: TestResurrectedObjectNotDeleted (1.23s)2200--- PASS: TestObjectStatsTrigger (1.01s)22012026/09/21 18:12:45 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=723.955423ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2202=== NAME TestOrphanedObjectsGC2203 orphaned_objects_gc_test.go:290: GC Test Summary:2204 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2205 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2206 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2207 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2208 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2209--- PASS: TestOrphanedObjectsGC (2.07s)22102026/09/21 18:12:45 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22112026/09/21 18:12:45 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: server returned 404: 404 page not found\n"22122026/09/21 18:12:45 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2213=== NAME TestOrphanedObjectsGCStressTest2214 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2215 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion2216 orphaned_objects_gc_test.go:509: Stress test completed successfully:2217 orphaned_objects_gc_test.go:510: - Active objects preserved: 202218 orphaned_objects_gc_test.go:511: - Objects deleted: 2102219 orphaned_objects_gc_test.go:512: - Total GC'd: 2102220--- PASS: TestOrphanedObjectsGCStressTest (2.74s)22212026/09/21 18:12:46 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.475081243s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22222026/09/21 18:12:46 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02223=== NAME TestClientIntegration2224 client_integration_test.go:323: Objects in database after GC:2225 client_integration_test.go:323: Successfully deleted all objects with GC --force2226--- PASS: TestClientIntegration (4.97s)22272026/09/21 18:12:47 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22282026/09/21 18:12:47 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=202.088512ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22292026/09/21 18:12:48 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=433.954752ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22302026/09/21 18:12:48 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=748.055684ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22312026/09/21 18:12:49 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.48998842s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22322026/09/21 18:12:50 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 127.0.0.1:19999: connect: connection refused"22332026/09/21 18:12:50 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22342026/09/21 18:12:50 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=184.255833ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22352026/09/21 18:12:51 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=386.681007ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22362026/09/21 18:12:51 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=729.181045ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22372026/09/21 18:12:52 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.47155966s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2238--- PASS: TestClientErrorHandling (0.00s)2239 --- PASS: TestClientErrorHandling/InvalidStorePath (1.05s)2240 --- PASS: TestClientErrorHandling/InvalidAuthToken (1.14s)2241 --- PASS: TestClientErrorHandling/ServerNotAvailable (9.05s)2242PASS2243{"timestamp":"2026-09-21T18:12:53.679031Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:50946","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":1880,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}22442026-09-21 18:12:53.779 UTC [4312] LOG: received smart shutdown request22452026-09-21 18:12:53.780 UTC [4312] LOG: background worker "logical replication launcher" (PID 4323) exited with exit code 122462026-09-21 18:12:53.788 UTC [4317] LOG: shutting down22472026-09-21 18:12:53.788 UTC [4317] LOG: checkpoint starting: shutdown immediate22482026-09-21 18:12:54.920 UTC [4317] LOG: checkpoint complete: wrote 13244 buffers (80.8%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 16 recycled; write=0.786 s, sync=0.321 s, total=1.133 s; sync files=19072, longest=0.001 s, average=0.001 s; distance=264771 kB, estimate=264771 kB; lsn=0/11A1DF28, redo lsn=0/11A1DF2822492026-09-21 18:12:54.925 UTC [4312] LOG: database system is shut down2250Running OIDC tests...2251=== RUN TestGlobMatch2252=== PAUSE TestGlobMatch2253=== RUN TestAudienceForIssuer2254=== PAUSE TestAudienceForIssuer2255=== RUN TestValidateToken_ValidToken2256=== PAUSE TestValidateToken_ValidToken2257=== RUN TestValidateToken_WrongAudience2258=== PAUSE TestValidateToken_WrongAudience2259=== RUN TestValidateToken_Expired2260=== PAUSE TestValidateToken_Expired2261=== RUN TestValidateToken_BoundClaimsMismatch2262=== PAUSE TestValidateToken_BoundClaimsMismatch2263=== RUN TestValidateToken_BoundSubjectMismatch2264=== PAUSE TestValidateToken_BoundSubjectMismatch2265=== RUN TestValidateToken_MultipleProviders2266=== PAUSE TestValidateToken_MultipleProviders2267=== RUN TestValidateToken_NoMatchingProvider2268=== PAUSE TestValidateToken_NoMatchingProvider2269=== RUN TestValidateToken_KubernetesServiceAccount2270=== PAUSE TestValidateToken_KubernetesServiceAccount2271=== RUN TestNewValidator_KubernetesRequiresCA2272=== PAUSE TestNewValidator_KubernetesRequiresCA2273=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2274=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2275=== RUN TestPins_ReservedForMatchingRule2276=== PAUSE TestPins_ReservedForMatchingRule2277=== RUN TestPins_TopLevelShorthand2278=== PAUSE TestPins_TopLevelShorthand2279=== RUN TestPins_ConfigValidation2280=== PAUSE TestPins_ConfigValidation2281=== RUN TestScopes_LegacyProviderDefaultsToWrite2282=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2283=== RUN TestScopes_Rules2284=== PAUSE TestScopes_Rules2285=== RUN TestScopes_ConfigValidation2286=== PAUSE TestScopes_ConfigValidation2287=== CONT TestGlobMatch2288=== CONT TestValidateToken_KubernetesServiceAccount2289=== RUN TestGlobMatch/foo_foo2290=== PAUSE TestGlobMatch/foo_foo2291=== RUN TestGlobMatch/foo_bar2292=== CONT TestPins_ConfigValidation2293=== PAUSE TestGlobMatch/foo_bar2294=== RUN TestGlobMatch/*_2295=== PAUSE TestGlobMatch/*_2296=== RUN TestGlobMatch/*_anything2297=== PAUSE TestGlobMatch/*_anything2298=== RUN TestGlobMatch/foo*_foo2299=== PAUSE TestGlobMatch/foo*_foo2300=== RUN TestGlobMatch/foo*_foobar2301=== PAUSE TestGlobMatch/foo*_foobar2302=== RUN TestGlobMatch/foo*_bar2303=== PAUSE TestGlobMatch/foo*_bar2304=== RUN TestGlobMatch/*bar_bar2305=== PAUSE TestGlobMatch/*bar_bar2306=== RUN TestGlobMatch/*bar_foobar2307=== PAUSE TestGlobMatch/*bar_foobar2308=== CONT TestScopes_Rules2309=== CONT TestScopes_ConfigValidation2310=== CONT TestValidateToken_MultipleProviders2311=== CONT TestValidateToken_NoMatchingProvider2312=== CONT TestValidateToken_BoundSubjectMismatch2313=== CONT TestScopes_LegacyProviderDefaultsToWrite2314=== CONT TestValidateToken_WrongAudience2315=== RUN TestGlobMatch/*bar_foo2316=== PAUSE TestGlobMatch/*bar_foo2317=== RUN TestGlobMatch/foo*bar_foobar2318=== PAUSE TestGlobMatch/foo*bar_foobar2319=== RUN TestGlobMatch/foo*bar_foo123bar2320=== PAUSE TestGlobMatch/foo*bar_foo123bar2321=== RUN TestGlobMatch/foo*bar_foobarbaz2322=== PAUSE TestGlobMatch/foo*bar_foobarbaz2323=== RUN TestGlobMatch/*/*_foo/bar2324=== PAUSE TestGlobMatch/*/*_foo/bar2325=== RUN TestGlobMatch/*/*_foo2326=== PAUSE TestGlobMatch/*/*_foo2327=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2328=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2329=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02330=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02331=== RUN TestGlobMatch/refs/*/main_refs/heads/main2332=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2333=== RUN TestGlobMatch/fo?_foo2334=== PAUSE TestGlobMatch/fo?_foo2335=== RUN TestGlobMatch/fo?_fo2336=== PAUSE TestGlobMatch/fo?_fo2337=== RUN TestGlobMatch/fo?_fooo2338=== PAUSE TestGlobMatch/fo?_fooo2339=== RUN TestGlobMatch/?oo_foo2340=== PAUSE TestGlobMatch/?oo_foo2341=== RUN TestGlobMatch/?oo_boo2342--- PASS: TestPins_ConfigValidation (0.00s)2343=== PAUSE TestGlobMatch/?oo_boo2344=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2345=== CONT TestValidateToken_Expired2346=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2347=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2348=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2349=== CONT TestValidateToken_ValidToken23502026/09/21 18:12:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51068/oidc2351--- PASS: TestScopes_ConfigValidation (0.00s)2352=== CONT TestPins_ReservedForMatchingRule23532026/09/21 18:12:55 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:51063/oidc23542026/09/21 18:12:55 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:51064/oidc23552026/09/21 18:12:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51066/oidc23562026/09/21 18:12:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51065/oidc23572026/09/21 18:12:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51071/oidc23582026/09/21 18:12:55 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:51070/oidc23592026/09/21 18:12:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51082/oidc2360--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.01s)23612026/09/21 18:12:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51080/oidc23622026/09/21 18:12:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51079/oidc2363=== CONT TestPins_TopLevelShorthand23642026/09/21 18:12:55 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:510672365--- PASS: TestValidateToken_BoundSubjectMismatch (0.01s)2366=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2367--- PASS: TestValidateToken_NoMatchingProvider (0.01s)2368=== CONT TestNewValidator_KubernetesRequiresCA2369--- PASS: TestValidateToken_WrongAudience (0.01s)2370=== CONT TestAudienceForIssuer2371--- PASS: TestAudienceForIssuer (0.00s)2372=== CONT TestValidateToken_BoundClaimsMismatch23732026/09/21 18:12:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51086/oidc23742026/09/21 18:12:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51088/oidc2375--- PASS: TestValidateToken_ValidToken (0.01s)2376=== CONT TestGlobMatch/foo_foo2377=== CONT TestGlobMatch/*/*_foo/bar2378=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2379=== CONT TestGlobMatch/*bar_bar2380=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2381=== CONT TestGlobMatch/foo*bar_foobarbaz2382=== CONT TestGlobMatch/?oo_boo2383=== CONT TestGlobMatch/?oo_foo2384=== CONT TestGlobMatch/foo*bar_foobar2385=== CONT TestGlobMatch/fo?_fooo2386=== CONT TestGlobMatch/*bar_foo2387=== CONT TestGlobMatch/fo?_fo2388=== CONT TestGlobMatch/*bar_foobar2389=== CONT TestGlobMatch/fo?_foo2390=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02391=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2392=== CONT TestGlobMatch/refs/*/main_refs/heads/main2393=== CONT TestGlobMatch/*/*_foo2394=== CONT TestGlobMatch/foo*_foo2395=== CONT TestGlobMatch/foo*_bar2396=== CONT TestGlobMatch/foo*_foobar2397=== CONT TestGlobMatch/*_2398=== CONT TestGlobMatch/*_anything2399=== CONT TestGlobMatch/foo_bar2400=== CONT TestGlobMatch/foo*bar_foo123bar2401--- PASS: TestValidateToken_Expired (0.01s)2402--- PASS: TestGlobMatch (0.00s)2403 --- PASS: TestGlobMatch/foo_foo (0.00s)2404 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2405 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2406 --- PASS: TestGlobMatch/*bar_bar (0.00s)2407 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2408 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2409 --- PASS: TestGlobMatch/?oo_boo (0.00s)2410 --- PASS: TestGlobMatch/?oo_foo (0.00s)2411 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2412 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2413 --- PASS: TestGlobMatch/*bar_foo (0.00s)2414 --- PASS: TestGlobMatch/fo?_fo (0.00s)2415 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2416 --- PASS: TestGlobMatch/fo?_foo (0.00s)2417 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2418 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2419 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2420 --- PASS: TestGlobMatch/*/*_foo (0.00s)2421 --- PASS: TestGlobMatch/foo*_foo (0.00s)2422 --- PASS: TestGlobMatch/foo*_bar (0.00s)2423 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2424 --- PASS: TestGlobMatch/*_ (0.00s)2425 --- PASS: TestGlobMatch/*_anything (0.00s)2426 --- PASS: TestGlobMatch/foo_bar (0.00s)2427 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2428--- PASS: TestValidateToken_MultipleProviders (0.01s)2429--- PASS: TestPins_TopLevelShorthand (0.01s)24302026/09/21 18:12:55 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232431--- PASS: TestValidateToken_BoundClaimsMismatch (0.00s)2432--- PASS: TestPins_ReservedForMatchingRule (0.01s)2433--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)2434--- PASS: TestScopes_Rules (0.02s)2435--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.01s)24362026/09/21 18:12:55 http: TLS handshake error from 127.0.0.1:51091: remote error: tls: bad certificate2437--- PASS: TestNewValidator_KubernetesRequiresCA (0.01s)2438PASS2439Running hook tests...2440=== RUN TestSendPathsEmpty2441=== PAUSE TestSendPathsEmpty2442=== RUN TestQueueEnqueueAndFetch2443=== PAUSE TestQueueEnqueueAndFetch2444=== RUN TestQueueDeduplication2445=== PAUSE TestQueueDeduplication2446=== RUN TestQueueRemove2447=== PAUSE TestQueueRemove2448=== RUN TestQueueFetchBatchLimit2449=== PAUSE TestQueueFetchBatchLimit2450=== RUN TestQueueRetryMovesToBack2451=== PAUSE TestQueueRetryMovesToBack2452=== RUN TestQueueFetchRemoveLifecycle2453=== PAUSE TestQueueFetchRemoveLifecycle2454=== RUN TestQueueConcurrentWriters2455=== PAUSE TestQueueConcurrentWriters2456=== RUN TestQueueRemoveLargeClosure2457=== PAUSE TestQueueRemoveLargeClosure2458=== RUN TestServerClientIntegration2459=== PAUSE TestServerClientIntegration2460=== RUN TestServerQueueError2461=== PAUSE TestServerQueueError2462=== RUN TestGetListenerSocketActivation2463 server_test.go:210: === RUN TestGetListenerSocketActivation2464 --- PASS: TestGetListenerSocketActivation (0.00s)2465 PASS2466 2467--- PASS: TestGetListenerSocketActivation (0.01s)2468=== RUN TestDrainIsolatesPoisonPath2469=== PAUSE TestDrainIsolatesPoisonPath2470=== RUN TestRunNotBlockedByPoisonHead2471=== PAUSE TestRunNotBlockedByPoisonHead2472=== RUN TestDrainGivesUpWhenServerDown2473=== PAUSE TestDrainGivesUpWhenServerDown2474=== RUN TestFailedPathPrunedByLaterClosure2475=== PAUSE TestFailedPathPrunedByLaterClosure2476=== RUN TestWorkerUploadsAndRemoves2477=== PAUSE TestWorkerUploadsAndRemoves2478=== RUN TestWorkerSkipsGCdPaths2479=== PAUSE TestWorkerSkipsGCdPaths2480=== RUN TestWorkerPrunesClosureDeps2481=== PAUSE TestWorkerPrunesClosureDeps2482=== RUN TestDrainTimeout2483=== PAUSE TestDrainTimeout2484=== CONT TestSendPathsEmpty2485=== CONT TestServerQueueError2486=== CONT TestQueueRetryMovesToBack2487--- PASS: TestSendPathsEmpty (0.00s)2488=== CONT TestQueueFetchBatchLimit2489=== CONT TestQueueRemove2490=== CONT TestQueueDeduplication2491=== CONT TestQueueEnqueueAndFetch2492=== CONT TestQueueRemoveLargeClosure2493=== CONT TestServerClientIntegration2494=== CONT TestQueueConcurrentWriters2495=== CONT TestQueueFetchRemoveLifecycle24962026/09/21 18:12:56 ERROR Failed to queue paths error="permission denied" count=12497--- PASS: TestServerQueueError (0.00s)2498=== CONT TestWorkerUploadsAndRemoves2499--- PASS: TestServerClientIntegration (0.00s)2500=== CONT TestDrainTimeout2501--- PASS: TestQueueRetryMovesToBack (0.01s)2502=== CONT TestWorkerPrunesClosureDeps25032026/09/21 18:12:56 INFO Upload queue status pending=225042026/09/21 18:12:56 INFO Uploading batch count=22505--- PASS: TestQueueDeduplication (0.01s)2506=== CONT TestWorkerSkipsGCdPaths25072026/09/21 18:12:56 INFO Uploading batch count=22508--- PASS: TestQueueFetchBatchLimit (0.01s)2509=== CONT TestDrainGivesUpWhenServerDown2510--- PASS: TestQueueEnqueueAndFetch (0.01s)2511=== CONT TestFailedPathPrunedByLaterClosure2512--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2513=== CONT TestRunNotBlockedByPoisonHead2514--- PASS: TestQueueRemove (0.02s)2515=== CONT TestDrainIsolatesPoisonPath25162026/09/21 18:12:56 INFO Upload queue status pending=225172026/09/21 18:12:56 INFO Upload queue status pending=225182026/09/21 18:12:56 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-4239-4131808779/TestWorkerSkipsGCdPaths52078190/002/nonexistent25192026/09/21 18:12:56 INFO Uploading batch count=125202026/09/21 18:12:56 INFO Uploading batch count=125212026/09/21 18:12:56 INFO Uploading batch count=125222026/09/21 18:12:56 ERROR Upload failed error="upload failed" count=125232026/09/21 18:12:56 INFO Uploading batch count=125242026/09/21 18:12:56 INFO Uploading batch count=125252026/09/21 18:12:56 INFO Upload queue status pending=325262026/09/21 18:12:56 INFO Uploading batch count=125272026/09/21 18:12:56 ERROR Upload failed error="upload failed" count=125282026/09/21 18:12:56 INFO Uploading batch count=425292026/09/21 18:12:56 ERROR Upload failed error="upload failed" count=425302026/09/21 18:12:56 INFO Uploading batch count=225312026/09/21 18:12:56 ERROR Upload failed error="upload failed" count=225322026/09/21 18:12:56 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4239-4131808779/TestDrainIsolatesPoisonPath433588881/002/bbb25332026/09/21 18:12:56 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4239-4131808779/TestDrainGivesUpWhenServerDown1100798773/002/a25342026/09/21 18:12:56 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4239-4131808779/TestDrainGivesUpWhenServerDown1100798773/002/b2535--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)25362026/09/21 18:12:56 INFO Uploading batch count=225372026/09/21 18:12:56 ERROR Upload failed error="upload failed" count=225382026/09/21 18:12:56 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4239-4131808779/TestDrainGivesUpWhenServerDown1100798773/002/c25392026/09/21 18:12:56 INFO Uploading batch count=125402026/09/21 18:12:56 ERROR Upload failed error="upload failed" count=125412026/09/21 18:12:56 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4239-4131808779/TestDrainGivesUpWhenServerDown1100798773/002/d25422026/09/21 18:12:56 INFO Uploading batch count=125432026/09/21 18:12:56 ERROR Upload failed error="upload failed" count=125442026/09/21 18:12:56 INFO Uploading batch count=225452026/09/21 18:12:56 ERROR Upload failed error="upload failed" count=225462026/09/21 18:12:56 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4239-4131808779/TestDrainGivesUpWhenServerDown1100798773/002/e25472026/09/21 18:12:56 INFO Uploading batch count=125482026/09/21 18:12:56 ERROR Upload failed error="upload failed" count=125492026/09/21 18:12:56 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-4239-4131808779/TestDrainGivesUpWhenServerDown1100798773/002/f25502026/09/21 18:12:56 ERROR Drain finished with paths left in queue remaining=125512026/09/21 18:12:56 ERROR Drain finished with paths left in queue remaining=102552--- PASS: TestDrainIsolatesPoisonPath (0.01s)2553--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2554--- PASS: TestWorkerUploadsAndRemoves (0.03s)2555--- PASS: TestWorkerSkipsGCdPaths (0.02s)2556--- PASS: TestWorkerPrunesClosureDeps (0.02s)2557--- PASS: TestQueueRemoveLargeClosure (0.06s)2558--- PASS: TestQueueConcurrentWriters (0.16s)25592026/09/21 18:12:56 ERROR Upload failed error="context deadline exceeded" count=225602026/09/21 18:12:56 ERROR Drain finished with paths left in queue remaining=42561--- PASS: TestDrainTimeout (0.21s)25622026/09/21 18:12:57 INFO Uploading batch count=125632026/09/21 18:12:57 INFO Uploading batch count=125642026/09/21 18:12:57 INFO Uploading batch count=125652026/09/21 18:12:57 ERROR Upload failed error="upload failed" count=125662026/09/21 18:12:57 INFO Uploading batch count=125672026/09/21 18:12:57 ERROR Upload failed error="upload failed" count=125682026/09/21 18:12:57 INFO Uploading batch count=125692026/09/21 18:12:57 ERROR Upload failed error="upload failed" count=125702026/09/21 18:12:57 INFO Uploading batch count=125712026/09/21 18:12:57 ERROR Upload failed error="upload failed" count=125722026/09/21 18:12:57 ERROR Drain finished with paths left in queue remaining=12573--- PASS: TestRunNotBlockedByPoisonHead (1.01s)2574PASS