niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #335
· 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.07s)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 TestStreamPushReportsSignatures65=== PAUSE TestStreamPushReportsSignatures66=== RUN TestClientSignaturesByStorePath67=== PAUSE TestClientSignaturesByStorePath68=== RUN TestSetClientTLS69=== PAUSE TestSetClientTLS70=== RUN TestSetClientTLSDoesNotMutateDefaultTransport71=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport72=== RUN TestSetClientTLSErrors73=== PAUSE TestSetClientTLSErrors74=== RUN TestStaticToken75=== PAUSE TestStaticToken76=== RUN TestFileTokenReadsAndCaches77=== PAUSE TestFileTokenReadsAndCaches78=== RUN TestFileTokenMissing79=== PAUSE TestFileTokenMissing80=== RUN TestFileTokenEmpty81=== PAUSE TestFileTokenEmpty82=== RUN TestScriptTokenNoExpiryRerunsEveryCall83=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall84=== RUN TestScriptTokenCachesUntilRefresh85=== PAUSE TestScriptTokenCachesUntilRefresh86=== RUN TestScriptTokenEmptyToken87=== PAUSE TestScriptTokenEmptyToken88=== RUN TestScriptTokenBadJSON89=== PAUSE TestScriptTokenBadJSON90=== RUN TestScriptTokenScriptFails91=== PAUSE TestScriptTokenScriptFails92=== RUN TestScriptTokenEmptyCommand93=== PAUSE TestScriptTokenEmptyCommand94=== CONT TestDoServerRequestAttachesToken95=== CONT TestStreamPushBatchesUnderLoad96=== CONT TestGetStorePathHash97=== RUN TestGetStorePathHash/valid_store_path98=== PAUSE TestGetStorePathHash/valid_store_path99=== RUN TestGetStorePathHash/basename_without_hyphen_should_error100=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error101=== CONT TestStreamPushReportsEveryPath102=== CONT TestShellSplitErrors103--- PASS: TestShellSplitErrors (0.00s)104=== CONT TestPathInfoCACompatibility105=== CONT TestShellSplit106=== RUN TestPathInfoCACompatibility/null_ca_field107=== PAUSE TestPathInfoCACompatibility/null_ca_field108=== RUN TestPathInfoCACompatibility/old_string_format_-_text109=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text110=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive111=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive112=== RUN TestPathInfoCACompatibility/new_structured_format_-_text113=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text114=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method115=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method116=== CONT TestParsePathInfoJSONMultiplePaths117=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths118=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths119=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths120=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths121=== CONT TestParsePathInfoJSON122=== RUN TestParsePathInfoJSON/Nix_format123=== PAUSE TestParsePathInfoJSON/Nix_format124=== RUN TestParsePathInfoJSON/Lix_format125=== PAUSE TestParsePathInfoJSON/Lix_format126=== RUN TestParsePathInfoJSON/empty_input127=== PAUSE TestParsePathInfoJSON/empty_input128=== RUN TestParsePathInfoJSON/whitespace_only129=== PAUSE TestParsePathInfoJSON/whitespace_only130=== RUN TestParsePathInfoJSON/invalid_JSON131=== PAUSE TestParsePathInfoJSON/invalid_JSON132=== CONT TestPathInfoHashCompatibility133=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)134=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)135=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon136=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon137=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI138=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI139=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512140=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512141--- PASS: TestShellSplit (0.00s)142=== CONT TestResolveStorePath143=== CONT TestDoWithRetry_BodyReplayedViaGetBody144=== CONT TestRateLimiterFeedback145=== RUN TestRateLimiterFeedback/429_enables_limiter146=== CONT TestScriptTokenEmptyCommand147=== PAUSE TestRateLimiterFeedback/429_enables_limiter148=== RUN TestRateLimiterFeedback/503_enables_limiter149--- PASS: TestScriptTokenEmptyCommand (0.00s)150=== PAUSE TestRateLimiterFeedback/503_enables_limiter151=== CONT TestScriptTokenScriptFails152=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter153=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter154=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter155=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter156=== CONT TestFileTokenReadsAndCaches157=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error158=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error159=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error160=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error161=== CONT TestScriptTokenEmptyToken162=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess163--- PASS: TestStreamPushReportsEveryPath (0.00s)164=== CONT TestScriptTokenCachesUntilRefresh165=== CONT TestScriptTokenBadJSON1662026/10/01 10:21:09 WARN Rate limiter enabled after throttle name=server-test rate=5167--- PASS: TestFileTokenReadsAndCaches (0.00s)168=== CONT TestScriptTokenNoExpiryRerunsEveryCall1692026/10/01 10:21:09 WARN Rate limiter enabled after throttle name=server-test rate=51702026/10/01 10:21:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:59993171=== CONT TestFileTokenEmpty172--- PASS: TestResolveStorePath (0.01s)173--- PASS: TestDoServerRequestAttachesToken (0.01s)174=== CONT TestFileTokenMissing175--- PASS: TestScriptTokenScriptFails (0.01s)176=== CONT TestEncodeNixBase32177=== RUN TestEncodeNixBase32/test_string_hash178=== PAUSE TestEncodeNixBase32/test_string_hash179=== RUN TestEncodeNixBase32/empty_input180=== PAUSE TestEncodeNixBase32/empty_input181=== CONT TestConvertHashToNix32182=== RUN TestConvertHashToNix32/SRI_format_to_Nix32183=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32184=== RUN TestConvertHashToNix32/already_Nix32_format185=== PAUSE TestConvertHashToNix32/already_Nix32_format186=== RUN TestConvertHashToNix32/invalid_format1872026/10/01 10:21:09 WARN Rate limiter backed off name=server-test rate=5188=== PAUSE TestConvertHashToNix32/invalid_format189=== CONT TestEncodeNixBase32WithRealHash190--- PASS: TestEncodeNixBase32WithRealHash (0.00s)191=== CONT TestDumpPathMatchesNix1922026/10/01 10:21:09 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:59993193--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)194=== CONT TestDumpPathWriterError195--- PASS: TestFileTokenMissing (0.01s)196=== CONT TestDumpPathSingleFile197--- PASS: TestFileTokenEmpty (0.01s)198=== CONT TestCaseHackSuffix199--- PASS: TestScriptTokenEmptyToken (0.02s)200=== CONT TestUploadMultipart_SupersededByPeer201=== CONT TestPartSizeForNAR202--- PASS: TestScriptTokenBadJSON (0.02s)203=== RUN TestUploadMultipart_SupersededByPeer/exists204=== PAUSE TestUploadMultipart_SupersededByPeer/exists205=== RUN TestPartSizeForNAR/zero_stays_at_minimum206=== RUN TestUploadMultipart_SupersededByPeer/missing207=== PAUSE TestUploadMultipart_SupersededByPeer/missing208=== CONT TestClientSignaturesByStorePath209--- PASS: TestClientSignaturesByStorePath (0.00s)210=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum211=== CONT TestRegisterUploadedObjectReusesConnections212=== RUN TestPartSizeForNAR/small_stays_at_minimum213=== PAUSE TestPartSizeForNAR/small_stays_at_minimum214=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum215=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum216=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts217=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts218=== RUN TestPartSizeForNAR/1_TiB219=== PAUSE TestPartSizeForNAR/1_TiB220=== RUN TestPartSizeForNAR/5_TiB_S3_max_object221=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object222=== RUN TestPartSizeForNAR/capped_at_5_GiB223=== PAUSE TestPartSizeForNAR/capped_at_5_GiB224=== CONT TestStreamPushRequestLine2252026/10/01 10:21:09 ERROR Upload failed error=boom count=1226--- PASS: TestStreamPushRequestLine (0.02s)227=== CONT TestStreamPushReportsSignatures2282026/10/01 10:21:09 ERROR Upload failed error=boom count=1229--- PASS: TestStreamPushReportsSignatures (0.00s)230=== CONT TestFilterOversizedClosures231=== RUN TestFilterOversizedClosures/no_limit_keeps_everything232=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything233=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped234=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped235=== RUN TestFilterOversizedClosures/all_closures_skipped236=== PAUSE TestFilterOversizedClosures/all_closures_skipped237=== CONT TestSetClientTLSErrors238--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)239=== CONT TestSetClientTLSDoesNotMutateDefaultTransport240=== RUN TestSetClientTLSErrors/missing_cert_file241=== PAUSE TestSetClientTLSErrors/missing_cert_file242=== RUN TestSetClientTLSErrors/missing_key_file243=== PAUSE TestSetClientTLSErrors/missing_key_file244=== RUN TestSetClientTLSErrors/missing_ca_file245=== PAUSE TestSetClientTLSErrors/missing_ca_file246=== RUN TestSetClientTLSErrors/invalid_ca_file247=== PAUSE TestSetClientTLSErrors/invalid_ca_file248=== CONT TestStaticToken249--- PASS: TestStaticToken (0.00s)250=== CONT TestUploadMultipart_PartsInParallel251--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)252=== CONT TestSetClientTLS253--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)254=== CONT TestStreamPushGivesUpOnDeadServer2552026/10/01 10:21:09 ERROR Upload failed error="connection refused" count=202562026/10/01 10:21:09 ERROR Server seems unavailable, giving up on batch untried=17257--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)258=== CONT TestStreamPushIsolatesFailures2592026/10/01 10:21:09 ERROR Upload failed error="bad path" count=3260--- PASS: TestStreamPushIsolatesFailures (0.00s)261=== CONT TestPathInfoCACompatibility/null_ca_field262=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths263=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method264=== CONT TestPathInfoCACompatibility/new_structured_format_-_text265=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive266=== CONT TestPathInfoCACompatibility/old_string_format_-_text267--- PASS: TestPathInfoCACompatibility (0.00s)268 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)269 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)270 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)271 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)272 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)273=== CONT TestParsePathInfoJSON/Nix_format274=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths275--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)276 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)277 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)278=== CONT TestParsePathInfoJSON/whitespace_only279=== CONT TestParsePathInfoJSON/invalid_JSON280=== CONT TestParsePathInfoJSON/empty_input281=== CONT TestParsePathInfoJSON/Lix_format282=== RUN TestSetClientTLS/rejects_connection_without_client_cert283=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert284=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA285=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA286=== RUN TestSetClientTLS/preserves_debug_logging_transport287=== PAUSE TestSetClientTLS/preserves_debug_logging_transport288--- PASS: TestParsePathInfoJSON (0.00s)289 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)290 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)291 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)292 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)293 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)294=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)295=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512296=== CONT TestGetStorePathHash/valid_store_path297=== CONT TestRateLimiterFeedback/429_enables_limiter298=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error299=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error300=== CONT TestGetStorePathHash/basename_without_hyphen_should_error301--- PASS: TestGetStorePathHash (0.00s)302 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)303 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)304 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)305 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)306=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter3072026/10/01 10:21:09 WARN Rate limiter enabled after throttle name=server-test rate=53082026/10/01 10:21:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:600663092026/10/01 10:21:09 WARN Rate limiter backed off name=server-test rate=5310=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon311=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter312=== CONT TestRateLimiterFeedback/503_enables_limiter313=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI314--- PASS: TestPathInfoHashCompatibility (0.00s)315 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)316 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)317 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)318 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)319=== CONT TestEncodeNixBase32/test_string_hash320=== CONT TestEncodeNixBase32/empty_input321--- PASS: TestEncodeNixBase32 (0.00s)322 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)323 --- PASS: TestEncodeNixBase32/empty_input (0.00s)324=== CONT TestConvertHashToNix32/SRI_format_to_Nix32325=== CONT TestConvertHashToNix32/invalid_format326=== CONT TestConvertHashToNix32/already_Nix32_format327--- PASS: TestConvertHashToNix32 (0.00s)328 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)329 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)330 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)331=== CONT TestUploadMultipart_SupersededByPeer/exists3322026/10/01 10:21:09 WARN Rate limiter enabled after throttle name=server-test rate=53332026/10/01 10:21:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:600723342026/10/01 10:21:09 WARN Rate limiter backed off name=server-test rate=5335--- PASS: TestRateLimiterFeedback (0.00s)336 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)337 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)338 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)339 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)340=== CONT TestUploadMultipart_SupersededByPeer/missing341=== CONT TestPartSizeForNAR/zero_stays_at_minimum342=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts343=== CONT TestPartSizeForNAR/1_TiB344=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum345=== CONT TestPartSizeForNAR/capped_at_5_GiB346=== CONT TestPartSizeForNAR/5_TiB_S3_max_object347=== CONT TestPartSizeForNAR/small_stays_at_minimum348--- PASS: TestPartSizeForNAR (0.00s)349 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)350 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)351 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)352 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)353 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)354 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)355 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)356=== CONT TestFilterOversizedClosures/no_limit_keeps_everything357=== CONT TestFilterOversizedClosures/all_closures_skipped3582026/10/01 10:21:09 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/stor--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)359 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)360 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)361e/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50362=== CONT TestSetClientTLSErrors/missing_cert_file363=== CONT TestSetClientTLSErrors/missing_ca_file364=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3652026/10/01 10:21:09 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=2000366--- PASS: TestFilterOversizedClosures (0.00s)367 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)368 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)369 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)370=== CONT TestSetClientTLSErrors/invalid_ca_file371=== CONT TestSetClientTLSErrors/missing_key_file372=== CONT TestSetClientTLS/rejects_connection_without_client_cert373=== CONT TestSetClientTLS/preserves_debug_logging_transport374--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)375=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA376--- PASS: TestSetClientTLSErrors (0.01s)377 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)378 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)379 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)380 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)381--- PASS: TestDumpPathWriterError (0.07s)3822026/10/01 10:21:09 http: TLS handshake error from 127.0.0.1:60082: remote error: tls: bad certificate383--- PASS: TestSetClientTLS (0.00s)384 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)385 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)386 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)387--- PASS: TestCaseHackSuffix (0.08s)388--- PASS: TestDumpPathSingleFile (0.08s)389--- PASS: TestStreamPushBatchesUnderLoad (0.11s)390--- PASS: TestDumpPathMatchesNix (0.14s)391--- PASS: TestUploadMultipart_PartsInParallel (0.62s)392--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)393PASS394Running server tests...395The files belonging to this database system will be owned by user "_nixbld10".396This user must also own the server process.397398The database cluster will be initialized with locale "C".399The default database encoding has accordingly been set to "SQL_ASCII".400The default text search configuration will be set to "english".401402Data page checksums are enabled.403404creating directory /nix/var/nix/builds/nix-26883-1285942671/postgres972981779/data ... ok405creating subdirectories ... ok406selecting dynamic shared memory implementation ... posix407selecting default "max_connections" ... 100408selecting default "shared_buffers" ... 128MB409selecting default time zone ... UTC410creating configuration files ... ok411running bootstrap script ... ok412performing post-bootstrap initialization ... ok413syncing data to disk ... ok414415initdb: warning: enabling "trust" authentication for local connections416initdb: 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.417418Success. You can now start the database server using:419420 pg_ctl -D /nix/var/nix/builds/nix-26883-1285942671/postgres972981779/data -l logfile start421422/nix/var/nix/builds/nix-26883-1285942671/postgres972981779:5432 - no response4232026-10-01 10:21:12.018 UTC [27021] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 10:21:12.018 UTC [27021] LOG: listening on Unix socket "/nix/var/nix/builds/nix-26883-1285942671/postgres972981779/.s.PGSQL.5432"4252026-10-01 10:21:12.024 UTC [27033] LOG: database system was shut down at 2026-10-01 10:21:11 UTC4262026-10-01 10:21:12.027 UTC [27021] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-26883-1285942671/postgres972981779:5432 - accepting connections428{"timestamp":"2026-10-01T10:21:12.229269Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"947b5afe-ee7b-41c2-b64a-c56a923ec192","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}429{"timestamp":"2026-10-01T10:21:12.331544Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"cac3bb93-566a-4001-a6da-95bf74c3984e","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock468=== RUN TestResolveDBConnectionString469=== PAUSE TestResolveDBConnectionString470=== RUN TestLeadElectsOneAndHandsOver471=== PAUSE TestLeadElectsOneAndHandsOver472=== RUN TestLeadIncumbentWinsAfterRestart4732026-10-01 10:21:12.535 UTC [27082] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 10:21:12.535 UTC [27082] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 10:21:12 OK 20241026095416_initial_model.sql (4.29ms)4762026/10/01 10:21:12 OK 20251210153512_drop_unused_gin_index.sql (790.63µs)4772026/10/01 10:21:12 OK 20251218171726_add_pins.sql (1.09ms)4782026/10/01 10:21:12 OK 20260628120000_add_object_size_and_stats.sql (1ms)4792026/10/01 10:21:12 OK 20260905000000_add_claims.sql (1.14ms)4802026/10/01 10:21:12 OK 20260920000000_drop_claims.sql (711.08µs)4812026/10/01 10:21:12 OK 20260923120000_add_pushes.sql (605.29µs)4822026/10/01 10:21:12 goose: successfully migrated database to version: 202609231200004832026/10/01 10:21:12 OK 1_commit_pending_closure.sql (1.01ms)4842026/10/01 10:21:12 OK 2_object_stats_trigger.sql (214.75µs)4852026/10/01 10:21:12 OK 3_commit_push.sql (233µs)4862026/10/01 10:21:12 goose: up to current file version: 34872026/10/01 10:21:12 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 10:21:13 INFO lead: released remote=192.0.2.1:12344892026/10/01 10:21:13 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 10:21:13 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (0.94s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 10:21:13.440 UTC [27098] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 10:21:13.440 UTC [27098] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 10:21:13 OK 20241026095416_initial_model.sql (6.29ms)4982026/10/01 10:21:13 OK 20251210153512_drop_unused_gin_index.sql (749.63µs)4992026/10/01 10:21:13 OK 20251218171726_add_pins.sql (946.29µs)5002026/10/01 10:21:13 OK 20260628120000_add_object_size_and_stats.sql (990.63µs)5012026/10/01 10:21:13 OK 20260905000000_add_claims.sql (1.1ms)5022026/10/01 10:21:13 OK 20260920000000_drop_claims.sql (1.12ms)5032026/10/01 10:21:13 OK 20260923120000_add_pushes.sql (1.02ms)5042026/10/01 10:21:13 goose: successfully migrated database to version: 202609231200005052026/10/01 10:21:13 OK 1_commit_pending_closure.sql (1.02ms)5062026/10/01 10:21:13 OK 2_object_stats_trigger.sql (241.29µs)5072026/10/01 10:21:13 OK 3_commit_push.sql (180.67µs)5082026/10/01 10:21:13 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.21s)510=== RUN TestGCBugBareHashReferences511=== PAUSE TestGCBugBareHashReferences512=== RUN TestGCMetrics513=== PAUSE TestGCMetrics514=== RUN TestPushDedupSurvivesConcurrentGC515=== PAUSE TestPushDedupSurvivesConcurrentGC516=== RUN TestDeduplicatedObjectsRecordedAsPending517=== PAUSE TestDeduplicatedObjectsRecordedAsPending518=== RUN TestGCSweepSkipsPendingObjects519=== PAUSE TestGCSweepSkipsPendingObjects520=== RUN TestTombstonedObjectOfferedWithoutWaiting521=== PAUSE TestTombstonedObjectOfferedWithoutWaiting522=== RUN TestGCSweepDeliversEachKeyOnce523=== PAUSE TestGCSweepDeliversEachKeyOnce524=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== RUN TestForceGCDuringPushOffersSweptObject527=== PAUSE TestForceGCDuringPushOffersSweptObject528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestSweepRechecksPendingAfterLocking537=== PAUSE TestSweepRechecksPendingAfterLocking538=== RUN TestPushWaitsForSweepHoldingRow539=== PAUSE TestPushWaitsForSweepHoldingRow540=== RUN TestCommitRacingPendingCleanupKeepsObjects541=== PAUSE TestCommitRacingPendingCleanupKeepsObjects542=== RUN TestGCEndsOnShutdown543=== PAUSE TestGCEndsOnShutdown544=== RUN TestGCTaskStore_StartNew545=== PAUSE TestGCTaskStore_StartNew546=== RUN TestGCTaskStore_DeduplicateSameParams547=== PAUSE TestGCTaskStore_DeduplicateSameParams548=== RUN TestGCTaskStore_ConflictDifferentParams549=== PAUSE TestGCTaskStore_ConflictDifferentParams550=== RUN TestGCTaskStore_GetEmpty551=== PAUSE TestGCTaskStore_GetEmpty552=== RUN TestGCTaskStore_GetReturnsLatest553=== PAUSE TestGCTaskStore_GetReturnsLatest554=== RUN TestGCTaskStore_CompletedAllowsNewTask555=== PAUSE TestGCTaskStore_CompletedAllowsNewTask556=== RUN TestGCTaskStore_PhaseUpdates557=== PAUSE TestGCTaskStore_PhaseUpdates558=== RUN TestGCTaskStore_Fail559=== PAUSE TestGCTaskStore_Fail560=== RUN TestGracefulShutdownDrainsInflight561=== PAUSE TestGracefulShutdownDrainsInflight562=== RUN TestService_healthCheckHandler563=== PAUSE TestService_healthCheckHandler564=== RUN TestService_readinessHandler565=== PAUSE TestService_readinessHandler566=== RUN TestGenerateLandingPage567=== PAUSE TestGenerateLandingPage568=== RUN TestCacheConfigHandlerMaxNarSize569=== PAUSE TestCacheConfigHandlerMaxNarSize570=== RUN TestCreatePendingClosureRejectsOversizedNAR571=== PAUSE TestCreatePendingClosureRejectsOversizedNAR572=== RUN TestNARDeduplicationMetadataUploadBug573=== PAUSE TestNARDeduplicationMetadataUploadBug574=== RUN TestMetricsInventory575=== PAUSE TestMetricsInventory576=== RUN TestService_NativeMTLS577=== PAUSE TestService_NativeMTLS578=== RUN TestServerTLSConfig579=== PAUSE TestServerTLSConfig580=== RUN TestMultipartCleanup581=== PAUSE TestMultipartCleanup582=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded584=== RUN TestPendingCleanupUsesOneCutoff585=== PAUSE TestPendingCleanupUsesOneCutoff586=== RUN TestObjectStatsTrigger587=== PAUSE TestObjectStatsTrigger588=== RUN TestOrphanedObjectsGC589=== PAUSE TestOrphanedObjectsGC590=== RUN TestOrphanedObjectsGCStressTest591=== PAUSE TestOrphanedObjectsGCStressTest592=== RUN TestCreatePin_ReservedPins593=== PAUSE TestCreatePin_ReservedPins594=== RUN TestPresentReportsOnlyClosureRoots595=== PAUSE TestPresentReportsOnlyClosureRoots596=== RUN TestPresentNotReportedWhileGCDeletesClosure597=== PAUSE TestPresentNotReportedWhileGCDeletesClosure598=== RUN TestParseSingleRange599=== PAUSE TestParseSingleRange600=== RUN TestProxyHeadersOnlyTrustedOnSocket601=== PAUSE TestProxyHeadersOnlyTrustedOnSocket602=== RUN TestIsValidCachePath603=== PAUSE TestIsValidCachePath604=== RUN TestReadProxyNarinfo605=== PAUSE TestReadProxyNarinfo606=== RUN TestReadProxyNarinfoAlreadyDecompressed607=== PAUSE TestReadProxyNarinfoAlreadyDecompressed608=== RUN TestReadProxyNarStreaming609=== PAUSE TestReadProxyNarStreaming610=== RUN TestReadProxy404611=== PAUSE TestReadProxy404612=== RUN TestReadProxyInvalidPath613=== PAUSE TestReadProxyInvalidPath614=== RUN TestReadProxyHead615=== PAUSE TestReadProxyHead616=== RUN TestReadProxyConditionalGet617=== PAUSE TestReadProxyConditionalGet618=== RUN TestReadProxyRootRedirectsToIndexHTML619=== PAUSE TestReadProxyRootRedirectsToIndexHTML620=== RUN TestReadProxyDisabled621=== PAUSE TestReadProxyDisabled622=== RUN TestReadRedirectNar623=== PAUSE TestReadRedirectNar624=== RUN TestReadRedirectKeepsNarinfoProxied625=== PAUSE TestReadRedirectKeepsNarinfoProxied626=== RUN TestReadProxyRangeRequest627=== PAUSE TestReadProxyRangeRequest628=== RUN TestReadRedirectUsesPublicS3URL629=== PAUSE TestReadRedirectUsesPublicS3URL630=== RUN TestPush_OverlappingRootsStoreOneRowPerKey631=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey632=== RUN TestPush_CompleteCommitsEveryRoot633=== PAUSE TestPush_CompleteCommitsEveryRoot634=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit635=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit636=== RUN TestPush_RejectsBadRequests637=== PAUSE TestPush_RejectsBadRequests638=== RUN TestPush_SignsNarinfosOfItsPendingObjects639=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects640=== RUN TestRedundantMultipartUpload641=== PAUSE TestRedundantMultipartUpload642=== RUN TestCompleteMultipartUpload_ErrorButObjectExists643=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists644=== RUN TestCompletedNarNotReofferedAcrossClosures645=== PAUSE TestCompletedNarNotReofferedAcrossClosures646=== RUN TestPresignedUploadRegisteredBeforeCommit647=== PAUSE TestPresignedUploadRegisteredBeforeCommit648=== RUN TestService_Rustfstest649=== PAUSE TestService_Rustfstest650=== RUN TestParseSize651=== PAUSE TestParseSize652=== RUN TestSkippedUploadsHandler653=== PAUSE TestSkippedUploadsHandler654=== RUN TestSystemdListenerNotActivated655--- PASS: TestSystemdListenerNotActivated (0.00s)656=== RUN TestWatchdogBeatsWhenHealthy657--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)658=== RUN TestWatchdogSkipsWhenUnhealthy6592026/10/01 10:21:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 10:21:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 10:21:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 10:21:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 10:21:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 10:21:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 10:21:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 10:21:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 10:21:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6682026/10/01 10:21:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"669--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)670=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle671=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle672=== RUN TestProxyWriteTimeout673=== PAUSE TestProxyWriteTimeout674=== RUN TestIsValidUploadKey675=== PAUSE TestIsValidUploadKey676=== RUN TestUploadHandlersRejectInvalidKeys677=== PAUSE TestUploadHandlersRejectInvalidKeys678=== RUN TestUploadHandlersRejectOversizedBody679=== PAUSE TestUploadHandlersRejectOversizedBody680=== RUN TestService_cleanupPendingClosuresHandler681=== PAUSE TestService_cleanupPendingClosuresHandler682=== RUN TestService_createPendingClosureHandler683=== PAUSE TestService_createPendingClosureHandler684=== RUN TestService_verifyS3Integrity685=== PAUSE TestService_verifyS3Integrity686=== RUN TestCompleteMultipartUnregistered687=== PAUSE TestCompleteMultipartUnregistered688=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT689=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT690=== CONT TestService_AuthMiddleware691=== CONT TestPresentNotReportedWhileGCDeletesClosure692=== CONT TestPush_RejectsBadRequests693=== CONT TestReadProxyConditionalGet694=== CONT TestProxyWriteTimeout695=== RUN TestProxyWriteTimeout/narinfo696=== CONT TestReadProxyHead697=== CONT TestPresentReportsOnlyClosureRoots698=== PAUSE TestProxyWriteTimeout/narinfo699=== RUN TestProxyWriteTimeout/1_GiB_nar700=== PAUSE TestProxyWriteTimeout/1_GiB_nar701=== CONT TestReadProxyNarinfo702=== CONT TestService_createPendingClosureHandler703=== RUN TestProxyWriteTimeout/10_GiB_nar704=== PAUSE TestProxyWriteTimeout/10_GiB_nar705=== CONT TestService_cleanupPendingClosuresHandler706=== RUN TestProxyWriteTimeout/unknown_size707=== PAUSE TestProxyWriteTimeout/unknown_size708=== CONT TestUploadHandlersRejectOversizedBody709=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure710=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure711=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart712=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart713=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts714=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts715=== CONT TestUploadHandlersRejectInvalidKeys716=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info717=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info718=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal719=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal720=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key721=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key722=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key723=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key724=== CONT TestCreatePin_ReservedPins7252026/10/01 10:21:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60106/oidc7262026-10-01 10:21:14.092 UTC [27127] ERROR: relation "goose_db_version" does not exist at character 367272026-10-01 10:21:14.092 UTC [27127] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7282026-10-01 10:21:14.096 UTC [27128] ERROR: relation "goose_db_version" does not exist at character 367292026-10-01 10:21:14.096 UTC [27128] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7302026-10-01 10:21:14.097 UTC [27129] ERROR: relation "goose_db_version" does not exist at character 367312026-10-01 10:21:14.097 UTC [27129] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7322026-10-01 10:21:14.099 UTC [27130] ERROR: relation "goose_db_version" does not exist at character 367332026-10-01 10:21:14.099 UTC [27130] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7342026-10-01 10:21:14.099 UTC [27131] ERROR: relation "goose_db_version" does not exist at character 367352026-10-01 10:21:14.099 UTC [27131] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7362026-10-01 10:21:14.102 UTC [27133] ERROR: relation "goose_db_version" does not exist at character 367372026-10-01 10:21:14.102 UTC [27133] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7382026-10-01 10:21:14.103 UTC [27135] ERROR: relation "goose_db_version" does not exist at character 367392026-10-01 10:21:14.103 UTC [27135] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7402026-10-01 10:21:14.103 UTC [27132] ERROR: relation "goose_db_version" does not exist at character 367412026-10-01 10:21:14.103 UTC [27132] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7422026-10-01 10:21:14.105 UTC [27136] ERROR: relation "goose_db_version" does not exist at character 367432026-10-01 10:21:14.105 UTC [27136] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7442026/10/01 10:21:14 OK 20241026095416_initial_model.sql (15.05ms)7452026/10/01 10:21:14 OK 20241026095416_initial_model.sql (15.38ms)7462026/10/01 10:21:14 OK 20241026095416_initial_model.sql (13.95ms)7472026/10/01 10:21:14 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)7482026/10/01 10:21:14 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)7492026/10/01 10:21:14 OK 20241026095416_initial_model.sql (17.03ms)7502026/10/01 10:21:14 OK 20241026095416_initial_model.sql (17.14ms)7512026/10/01 10:21:14 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)7522026/10/01 10:21:14 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)7532026/10/01 10:21:14 OK 20251210153512_drop_unused_gin_index.sql (1.4ms)7542026/10/01 10:21:14 OK 20251218171726_add_pins.sql (3.46ms)7552026/10/01 10:21:14 OK 20251218171726_add_pins.sql (3.81ms)7562026/10/01 10:21:14 OK 20251218171726_add_pins.sql (3.45ms)7572026/10/01 10:21:14 OK 20251218171726_add_pins.sql (3.38ms)7582026/10/01 10:21:14 OK 20251218171726_add_pins.sql (3.62ms)7592026/10/01 10:21:14 OK 20241026095416_initial_model.sql (14.05ms)7602026/10/01 10:21:14 OK 20241026095416_initial_model.sql (13.89ms)7612026/10/01 10:21:14 OK 20260628120000_add_object_size_and_stats.sql (2.76ms)7622026/10/01 10:21:14 OK 20260628120000_add_object_size_and_stats.sql (2.65ms)7632026/10/01 10:21:14 OK 20241026095416_initial_model.sql (13.91ms)7642026/10/01 10:21:14 OK 20251210153512_drop_unused_gin_index.sql (1.07ms)7652026/10/01 10:21:14 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)7662026/10/01 10:21:14 OK 20260628120000_add_object_size_and_stats.sql (2.97ms)7672026/10/01 10:21:14 OK 20260628120000_add_object_size_and_stats.sql (2.48ms)7682026/10/01 10:21:14 OK 20251210153512_drop_unused_gin_index.sql (1.34ms)7692026/10/01 10:21:14 OK 20260628120000_add_object_size_and_stats.sql (3ms)7702026/10/01 10:21:14 OK 20251218171726_add_pins.sql (2.73ms)7712026/10/01 10:21:14 OK 20241026095416_initial_model.sql (17.97ms)7722026/10/01 10:21:14 OK 20251218171726_add_pins.sql (2.69ms)7732026/10/01 10:21:14 OK 20260905000000_add_claims.sql (3.63ms)7742026/10/01 10:21:14 OK 20260905000000_add_claims.sql (3.63ms)7752026/10/01 10:21:14 OK 20251210153512_drop_unused_gin_index.sql (1.01ms)7762026/10/01 10:21:14 OK 20260905000000_add_claims.sql (3.86ms)7772026/10/01 10:21:14 OK 20251218171726_add_pins.sql (2.79ms)7782026/10/01 10:21:14 OK 20260905000000_add_claims.sql (3.89ms)7792026/10/01 10:21:14 OK 20260628120000_add_object_size_and_stats.sql (2.09ms)7802026/10/01 10:21:14 OK 20260905000000_add_claims.sql (3.63ms)7812026/10/01 10:21:14 OK 20260628120000_add_object_size_and_stats.sql (2.49ms)7822026/10/01 10:21:14 OK 20260920000000_drop_claims.sql (2ms)7832026/10/01 10:21:14 OK 20260920000000_drop_claims.sql (2.16ms)7842026/10/01 10:21:14 OK 20260920000000_drop_claims.sql (2.11ms)7852026/10/01 10:21:14 OK 20251218171726_add_pins.sql (3.04ms)7862026/10/01 10:21:14 OK 20260923120000_add_pushes.sql (1.6ms)7872026/10/01 10:21:14 goose: successfully migrated database to version: 202609231200007882026/10/01 10:21:14 OK 20260628120000_add_object_size_and_stats.sql (2.79ms)7892026/10/01 10:21:14 OK 20260923120000_add_pushes.sql (1.8ms)7902026/10/01 10:21:14 goose: successfully migrated database to version: 202609231200007912026/10/01 10:21:14 OK 20260920000000_drop_claims.sql (2.69ms)7922026/10/01 10:21:14 OK 20260923120000_add_pushes.sql (2.01ms)7932026/10/01 10:21:14 goose: successfully migrated database to version: 202609231200007942026/10/01 10:21:14 OK 20260920000000_drop_claims.sql (3.47ms)7952026-10-01 10:21:14.137 UTC [27138] ERROR: relation "goose_db_version" does not exist at character 367962026-10-01 10:21:14.137 UTC [27138] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7972026/10/01 10:21:14 OK 20260905000000_add_claims.sql (4.34ms)7982026/10/01 10:21:14 OK 20260923120000_add_pushes.sql (2.14ms)7992026/10/01 10:21:14 goose: successfully migrated database to version: 202609231200008002026/10/01 10:21:14 OK 1_commit_pending_closure.sql (2.76ms)8012026/10/01 10:21:14 OK 20260905000000_add_claims.sql (4.81ms)8022026/10/01 10:21:14 OK 1_commit_pending_closure.sql (3.07ms)8032026/10/01 10:21:14 OK 1_commit_pending_closure.sql (2.04ms)8042026/10/01 10:21:14 OK 20260923120000_add_pushes.sql (1.51ms)8052026/10/01 10:21:14 goose: successfully migrated database to version: 202609231200008062026/10/01 10:21:14 OK 20260628120000_add_object_size_and_stats.sql (3.74ms)8072026/10/01 10:21:14 OK 2_object_stats_trigger.sql (802.21µs)8082026/10/01 10:21:14 OK 2_object_stats_trigger.sql (599.92µs)8092026/10/01 10:21:14 OK 20260905000000_add_claims.sql (3.74ms)8102026/10/01 10:21:14 OK 2_object_stats_trigger.sql (687.08µs)8112026/10/01 10:21:14 OK 3_commit_push.sql (628.63µs)8122026/10/01 10:21:14 goose: up to current file version: 38132026/10/01 10:21:14 OK 20260920000000_drop_claims.sql (2.21ms)8142026/10/01 10:21:14 OK 3_commit_push.sql (728.92µs)8152026/10/01 10:21:14 goose: up to current file version: 38162026/10/01 10:21:14 OK 1_commit_pending_closure.sql (1.97ms)8172026/10/01 10:21:14 OK 20260920000000_drop_claims.sql (1.96ms)8182026/10/01 10:21:14 OK 2_object_stats_trigger.sql (507.92µs)8192026/10/01 10:21:14 OK 3_commit_push.sql (737.04µs)8202026/10/01 10:21:14 goose: up to current file version: 38212026/10/01 10:21:14 OK 20260920000000_drop_claims.sql (1.72ms)8222026/10/01 10:21:14 OK 3_commit_push.sql (419.17µs)8232026/10/01 10:21:14 goose: up to current file version: 38242026/10/01 10:21:14 OK 1_commit_pending_closure.sql (2.06ms)8252026/10/01 10:21:14 OK 20260923120000_add_pushes.sql (1.17ms)8262026/10/01 10:21:14 goose: successfully migrated database to version: 202609231200008272026/10/01 10:21:14 OK 2_object_stats_trigger.sql (311.83µs)8282026/10/01 10:21:14 OK 20260905000000_add_claims.sql (2.66ms)8292026/10/01 10:21:14 OK 20260923120000_add_pushes.sql (1.44ms)8302026/10/01 10:21:14 goose: successfully migrated database to version: 202609231200008312026/10/01 10:21:14 OK 3_commit_push.sql (493.67µs)8322026/10/01 10:21:14 goose: up to current file version: 38332026/10/01 10:21:14 OK 20260923120000_add_pushes.sql (1.29ms)8342026/10/01 10:21:14 goose: successfully migrated database to version: 202609231200008352026/10/01 10:21:14 OK 1_commit_pending_closure.sql (1.22ms)8362026/10/01 10:21:14 OK 20260920000000_drop_claims.sql (1.25ms)8372026/10/01 10:21:14 OK 2_object_stats_trigger.sql (610.71µs)8382026/10/01 10:21:14 OK 3_commit_push.sql (268µs)8392026/10/01 10:21:14 goose: up to current file version: 38402026/10/01 10:21:14 OK 1_commit_pending_closure.sql (1.52ms)8412026/10/01 10:21:14 OK 1_commit_pending_closure.sql (1.25ms)8422026/10/01 10:21:14 OK 2_object_stats_trigger.sql (329.46µs)8432026/10/01 10:21:14 OK 20260923120000_add_pushes.sql (841.58µs)8442026/10/01 10:21:14 goose: successfully migrated database to version: 202609231200008452026/10/01 10:21:14 OK 2_object_stats_trigger.sql (377.29µs)8462026/10/01 10:21:14 OK 3_commit_push.sql (222.54µs)8472026/10/01 10:21:14 goose: up to current file version: 38482026/10/01 10:21:14 OK 3_commit_push.sql (205.63µs)8492026/10/01 10:21:14 goose: up to current file version: 38502026/10/01 10:21:14 OK 1_commit_pending_closure.sql (1.04ms)8512026/10/01 10:21:14 OK 2_object_stats_trigger.sql (242.5µs)8522026/10/01 10:21:14 OK 3_commit_push.sql (232.13µs)8532026/10/01 10:21:14 goose: up to current file version: 38542026/10/01 10:21:14 OK 20241026095416_initial_model.sql (47.22ms)8552026/10/01 10:21:14 OK 20251210153512_drop_unused_gin_index.sql (622.58µs)8562026/10/01 10:21:14 OK 20251218171726_add_pins.sql (9.16ms)8572026/10/01 10:21:14 OK 20260628120000_add_object_size_and_stats.sql (4.51ms)8582026/10/01 10:21:14 OK 20260905000000_add_claims.sql (7.36ms)8592026/10/01 10:21:14 OK 20260920000000_drop_claims.sql (8.31ms)8602026/10/01 10:21:14 OK 20260923120000_add_pushes.sql (581.21µs)8612026/10/01 10:21:14 goose: successfully migrated database to version: 202609231200008622026/10/01 10:21:14 OK 1_commit_pending_closure.sql (1.02ms)8632026/10/01 10:21:14 OK 2_object_stats_trigger.sql (254.21µs)8642026/10/01 10:21:14 OK 3_commit_push.sql (212.54µs)8652026/10/01 10:21:14 goose: up to current file version: 3866--- PASS: TestReadProxyConditionalGet (0.46s)867=== CONT TestIsValidUploadKey868=== RUN TestIsValidUploadKey/narinfo869=== PAUSE TestIsValidUploadKey/narinfo870=== RUN TestIsValidUploadKey/nar_zst871=== PAUSE TestIsValidUploadKey/nar_zst872=== RUN TestIsValidUploadKey/nar_xz873=== PAUSE TestIsValidUploadKey/nar_xz874=== RUN TestIsValidUploadKey/nar_plain875=== PAUSE TestIsValidUploadKey/nar_plain876=== RUN TestIsValidUploadKey/listing877=== PAUSE TestIsValidUploadKey/listing878=== RUN TestIsValidUploadKey/build_log879=== PAUSE TestIsValidUploadKey/build_log880=== RUN TestIsValidUploadKey/build_log_home-manager_file881=== PAUSE TestIsValidUploadKey/build_log_home-manager_file882=== RUN TestIsValidUploadKey/build_log_plus_in_name883=== PAUSE TestIsValidUploadKey/build_log_plus_in_name884=== RUN TestIsValidUploadKey/build_log_question_mark885=== PAUSE TestIsValidUploadKey/build_log_question_mark886=== RUN TestIsValidUploadKey/build_log_equals887=== PAUSE TestIsValidUploadKey/build_log_equals888=== RUN TestIsValidUploadKey/realisation889=== PAUSE TestIsValidUploadKey/realisation890=== RUN TestIsValidUploadKey/realisation_plus_in_output891=== PAUSE TestIsValidUploadKey/realisation_plus_in_output892=== RUN TestIsValidUploadKey/nix-cache-info893=== PAUSE TestIsValidUploadKey/nix-cache-info894=== RUN TestIsValidUploadKey/index.html895=== PAUSE TestIsValidUploadKey/index.html896=== RUN TestIsValidUploadKey/narinfo_key,_nar_type897=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type898=== RUN TestIsValidUploadKey/nar_key,_narinfo_type899=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type900=== RUN TestIsValidUploadKey/listing_key,_narinfo_type901=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type902=== RUN TestIsValidUploadKey/traversal903=== PAUSE TestIsValidUploadKey/traversal904=== RUN TestIsValidUploadKey/traversal_nar905=== PAUSE TestIsValidUploadKey/traversal_nar906=== RUN TestIsValidUploadKey/absolute907=== PAUSE TestIsValidUploadKey/absolute908=== RUN TestIsValidUploadKey/empty_key909=== PAUSE TestIsValidUploadKey/empty_key910=== RUN TestIsValidUploadKey/unknown_type911=== PAUSE TestIsValidUploadKey/unknown_type912=== CONT TestOrphanedObjectsGCStressTest9132026/10/01 10:21:14 INFO Received cleanup request method=DELETE path=/api/pending_closures9142026/10/01 10:21:14 INFO Aborted multipart uploads count=0 kept=09152026/10/01 10:21:14 INFO Received uploads request method=POST path=/api/pending_closures9162026/10/01 10:21:14 INFO Received cleanup request method=DELETE path=/api/pending_closures9172026/10/01 10:21:14 INFO Aborted multipart uploads count=1 kept=09182026/10/01 10:21:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9192026-10-01 10:21:14.487 UTC [27131] ERROR: Closure does not exist: id=19202026-10-01 10:21:14.487 UTC [27131] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE9212026-10-01 10:21:14.487 UTC [27131] STATEMENT: -- name: CommitPendingClosure :exec922 SELECT commit_pending_closure($1::bigint)923 924--- PASS: TestService_cleanupPendingClosuresHandler (0.66s)925=== CONT TestOrphanedObjectsGC926--- PASS: TestReadProxyHead (0.97s)927=== CONT TestForceGCDuringPushOffersSweptObject928=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows929=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows930=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check931=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check932=== CONT TestFailedS3DeleteKeepsTombstone933=== RUN TestPush_RejectsBadRequests/no_objects934=== PAUSE TestPush_RejectsBadRequests/no_objects935=== RUN TestPush_RejectsBadRequests/bad_root936=== PAUSE TestPush_RejectsBadRequests/bad_root937=== RUN TestPush_RejectsBadRequests/root_not_in_objects938=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects939=== RUN TestPush_RejectsBadRequests/no_roots940=== PAUSE TestPush_RejectsBadRequests/no_roots941=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection9422026-10-01 10:21:15.078 UTC [27148] ERROR: relation "goose_db_version" does not exist at character 369432026-10-01 10:21:15.078 UTC [27148] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC944--- PASS: TestPresentNotReportedWhileGCDeletesClosure (1.29s)945=== CONT TestObjectStatsTrigger946--- PASS: TestPresentReportsOnlyClosureRoots (1.30s)947=== CONT TestGCSweepDeliversEachKeyOnce9482026-10-01 10:21:15.191 UTC [27153] ERROR: relation "goose_db_version" does not exist at character 369492026-10-01 10:21:15.191 UTC [27153] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9502026/10/01 10:21:15 OK 20241026095416_initial_model.sql (78.18ms)9512026/10/01 10:21:15 OK 20251210153512_drop_unused_gin_index.sql (5.64ms)9522026/10/01 10:21:15 OK 20251218171726_add_pins.sql (8.9ms)9532026/10/01 10:21:15 OK 20260628120000_add_object_size_and_stats.sql (15.8ms)9542026/10/01 10:21:15 OK 20260905000000_add_claims.sql (48.9ms)9552026/10/01 10:21:15 OK 20260920000000_drop_claims.sql (22.89ms)9562026/10/01 10:21:15 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"957--- PASS: TestService_AuthMiddleware (1.48s)958=== CONT TestPendingCleanupUsesOneCutoff9592026/10/01 10:21:15 OK 20241026095416_initial_model.sql (79.05ms)9602026/10/01 10:21:15 OK 20260923120000_add_pushes.sql (14.74ms)9612026/10/01 10:21:15 goose: successfully migrated database to version: 202609231200009622026/10/01 10:21:15 OK 1_commit_pending_closure.sql (2.14ms)9632026/10/01 10:21:15 OK 2_object_stats_trigger.sql (649.08µs)9642026/10/01 10:21:15 OK 3_commit_push.sql (395.25µs)9652026/10/01 10:21:15 goose: up to current file version: 39662026/10/01 10:21:15 OK 20251210153512_drop_unused_gin_index.sql (14.51ms)9672026/10/01 10:21:15 OK 20251218171726_add_pins.sql (27.81ms)9682026/10/01 10:21:15 OK 20260628120000_add_object_size_and_stats.sql (9.68ms)9692026/10/01 10:21:15 OK 20260905000000_add_claims.sql (21.48ms)9702026/10/01 10:21:15 OK 20260920000000_drop_claims.sql (9.73ms)9712026/10/01 10:21:15 OK 20260923120000_add_pushes.sql (7.45ms)9722026/10/01 10:21:15 goose: successfully migrated database to version: 202609231200009732026/10/01 10:21:15 OK 1_commit_pending_closure.sql (2.53ms)9742026/10/01 10:21:15 OK 2_object_stats_trigger.sql (499µs)9752026/10/01 10:21:15 OK 3_commit_push.sql (334.83µs)9762026/10/01 10:21:15 goose: up to current file version: 39772026-10-01 10:21:15.437 UTC [27156] ERROR: relation "goose_db_version" does not exist at character 369782026-10-01 10:21:15.437 UTC [27156] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9792026/10/01 10:21:15 INFO Received uploads request method=POST path=/api/pending_closures9802026/10/01 10:21:15 INFO Received uploads request method=POST path=/api/pending_closures9812026/10/01 10:21:15 INFO Received uploads request method=POST path=/api/pending_closures9822026/10/01 10:21:15 OK 20241026095416_initial_model.sql (104.14ms)9832026/10/01 10:21:15 OK 20251210153512_drop_unused_gin_index.sql (9.42ms)9842026/10/01 10:21:15 OK 20251218171726_add_pins.sql (24.91ms)9852026/10/01 10:21:15 OK 20260628120000_add_object_size_and_stats.sql (24.16ms)9862026/10/01 10:21:15 OK 20260905000000_add_claims.sql (31.1ms)9872026-10-01 10:21:15.692 UTC [27157] ERROR: relation "goose_db_version" does not exist at character 369882026-10-01 10:21:15.692 UTC [27157] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9892026/10/01 10:21:15 OK 20260920000000_drop_claims.sql (39.92ms)990--- PASS: TestReadProxyNarinfo (1.89s)991=== CONT TestTombstonedObjectOfferedWithoutWaiting9922026/10/01 10:21:15 OK 20260923120000_add_pushes.sql (14.8ms)9932026/10/01 10:21:15 goose: successfully migrated database to version: 202609231200009942026/10/01 10:21:15 OK 1_commit_pending_closure.sql (2.53ms)9952026/10/01 10:21:15 OK 2_object_stats_trigger.sql (961.25µs)9962026/10/01 10:21:15 OK 3_commit_push.sql (571.17µs)9972026/10/01 10:21:15 goose: up to current file version: 39982026/10/01 10:21:15 OK 20241026095416_initial_model.sql (129.16ms)9992026/10/01 10:21:15 OK 20251210153512_drop_unused_gin_index.sql (6.94ms)10002026/10/01 10:21:15 OK 20251218171726_add_pins.sql (28.75ms)10012026/10/01 10:21:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10022026/10/01 10:21:15 WARN Refused reserved pin name=worker-x86_64-linux10032026/10/01 10:21:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10042026/10/01 10:21:15 INFO Received create pin request method=POST path=/api/pins/my-app10052026/10/01 10:21:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1006--- PASS: TestCreatePin_ReservedPins (2.08s)1007=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded10082026/10/01 10:21:15 OK 20260628120000_add_object_size_and_stats.sql (33.18ms)10092026/10/01 10:21:15 OK 20260905000000_add_claims.sql (25.93ms)10102026/10/01 10:21:15 OK 20260920000000_drop_claims.sql (12.68ms)10112026/10/01 10:21:16 OK 20260923120000_add_pushes.sql (24.05ms)10122026/10/01 10:21:16 goose: successfully migrated database to version: 2026092312000010132026/10/01 10:21:16 OK 1_commit_pending_closure.sql (1.47ms)10142026/10/01 10:21:16 OK 2_object_stats_trigger.sql (314.17µs)10152026/10/01 10:21:16 OK 3_commit_push.sql (253.79µs)10162026/10/01 10:21:16 goose: up to current file version: 310172026-10-01 10:21:16.380 UTC [27162] ERROR: relation "goose_db_version" does not exist at character 3610182026-10-01 10:21:16.380 UTC [27162] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10192026-10-01 10:21:16.459 UTC [27163] ERROR: relation "goose_db_version" does not exist at character 3610202026-10-01 10:21:16.459 UTC [27163] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10212026/10/01 10:21:16 OK 20241026095416_initial_model.sql (199.39ms)10222026/10/01 10:21:16 OK 20251210153512_drop_unused_gin_index.sql (13.92ms)10232026/10/01 10:21:16 OK 20251218171726_add_pins.sql (13.67ms)10242026/10/01 10:21:16 OK 20241026095416_initial_model.sql (169.57ms)10252026/10/01 10:21:16 OK 20251210153512_drop_unused_gin_index.sql (13.27ms)10262026/10/01 10:21:16 OK 20260628120000_add_object_size_and_stats.sql (22.32ms)10272026/10/01 10:21:16 INFO Received uploads request method=POST path=/api/pending_closures10282026/10/01 10:21:16 OK 20251218171726_add_pins.sql (25.38ms)10292026/10/01 10:21:16 OK 20260628120000_add_object_size_and_stats.sql (45.5ms)10302026/10/01 10:21:16 OK 20260905000000_add_claims.sql (87.2ms)10312026/10/01 10:21:16 OK 20260920000000_drop_claims.sql (56.43ms)10322026/10/01 10:21:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10332026/10/01 10:21:16 OK 20260905000000_add_claims.sql (77.75ms)10342026/10/01 10:21:16 OK 20260923120000_add_pushes.sql (43.03ms)10352026/10/01 10:21:16 goose: successfully migrated database to version: 2026092312000010362026/10/01 10:21:16 OK 1_commit_pending_closure.sql (4.6ms)10372026/10/01 10:21:16 OK 2_object_stats_trigger.sql (1.16ms)10382026/10/01 10:21:16 OK 3_commit_push.sql (839.83µs)10392026/10/01 10:21:16 goose: up to current file version: 310402026/10/01 10:21:16 OK 20260920000000_drop_claims.sql (52.45ms)10412026/10/01 10:21:16 INFO Aborted multipart uploads count=0 kept=010422026/10/01 10:21:16 OK 20260923120000_add_pushes.sql (15ms)10432026/10/01 10:21:16 goose: successfully migrated database to version: 2026092312000010442026/10/01 10:21:16 OK 1_commit_pending_closure.sql (2.65ms)10452026/10/01 10:21:16 WARN Force mode enabled - objects will be deleted immediately without grace period10462026/10/01 10:21:16 OK 2_object_stats_trigger.sql (573µs)10472026/10/01 10:21:16 OK 3_commit_push.sql (393.79µs)10482026/10/01 10:21:16 goose: up to current file version: 310492026/10/01 10:21:16 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."10502026/10/01 10:21:16 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."10512026/10/01 10:21:16 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=OTQ0YTg0OWItNGQxNy00MDM5LWI3NmEtNThjOTk1YjUzYzdmLjk1N2M2MjI2LTU4NjctNGI1Ny1iZTlkLTBkODNmYzQzYTcxNHgxNzkwODUwMDc1NDkwNDc3MDAw parts=1010522026/10/01 10:21:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1053--- PASS: TestFailedS3DeleteKeepsTombstone (2.16s)1054=== CONT TestGCSweepSkipsPendingObjects10552026/10/01 10:21:16 INFO Completed upload id=110562026/10/01 10:21:16 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010572026/10/01 10:21:16 INFO Received uploads request method=POST path=/api/pending_closures10582026/10/01 10:21:16 INFO Starting cleanup of old closures method=DELETE path=/api/closures10592026/10/01 10:21:16 INFO Aborted multipart uploads count=0 kept=010602026/10/01 10:21:16 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010612026/10/01 10:21:16 INFO Vacuumed table table=pending_closures10622026/10/01 10:21:17 INFO Vacuumed table table=pending_objects10632026/10/01 10:21:17 INFO Vacuumed table table=multipart_uploads10642026/10/01 10:21:17 INFO Vacuumed table table=closures10652026/10/01 10:21:17 INFO Received uploads request method=POST path=/api/pending_closures10662026-10-01 10:21:17.091 UTC [27168] ERROR: relation "goose_db_version" does not exist at character 3610672026-10-01 10:21:17.091 UTC [27168] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10682026/10/01 10:21:17 INFO Vacuumed table table=objects10692026/10/01 10:21:17 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001070--- PASS: TestService_createPendingClosureHandler (3.30s)1071=== CONT TestMultipartCleanup1072=== NAME TestOrphanedObjectsGC1073 orphaned_objects_gc_test.go:290: GC Test Summary:1074 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1075 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1076 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1077 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1078 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1079--- PASS: TestOrphanedObjectsGC (2.71s)1080=== CONT TestPushDedupSurvivesConcurrentGC10812026/10/01 10:21:17 OK 20241026095416_initial_model.sql (156.04ms)10822026/10/01 10:21:17 OK 20251210153512_drop_unused_gin_index.sql (13.72ms)1083--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (2.38s)1084=== CONT TestDeduplicatedObjectsRecordedAsPending10852026/10/01 10:21:17 OK 20251218171726_add_pins.sql (26.52ms)10862026/10/01 10:21:17 OK 20260628120000_add_object_size_and_stats.sql (29.98ms)10872026/10/01 10:21:17 OK 20260905000000_add_claims.sql (33.75ms)10882026/10/01 10:21:17 INFO Aborted multipart uploads count=0 kept=010892026/10/01 10:21:17 WARN Force mode enabled - objects will be deleted immediately without grace period10902026/10/01 10:21:17 OK 20260920000000_drop_claims.sql (41.29ms)10912026/10/01 10:21:17 OK 20260923120000_add_pushes.sql (7.79ms)10922026/10/01 10:21:17 goose: successfully migrated database to version: 2026092312000010932026/10/01 10:21:17 OK 1_commit_pending_closure.sql (2.45ms)10942026/10/01 10:21:17 OK 2_object_stats_trigger.sql (400.21µs)10952026/10/01 10:21:17 OK 3_commit_push.sql (345.38µs)10962026/10/01 10:21:17 goose: up to current file version: 310972026/10/01 10:21:17 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=010982026/10/01 10:21:17 INFO Vacuumed table table=pending_closures10992026/10/01 10:21:17 INFO Vacuumed table table=pending_objects11002026/10/01 10:21:17 INFO Vacuumed table table=multipart_uploads11012026/10/01 10:21:17 INFO Vacuumed table table=closures11022026/10/01 10:21:17 INFO Vacuumed table table=objects1103--- PASS: TestGCSweepDeliversEachKeyOnce (2.38s)1104=== CONT TestGCMetrics11052026-10-01 10:21:17.561 UTC [27177] ERROR: relation "goose_db_version" does not exist at character 3611062026-10-01 10:21:17.561 UTC [27177] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1107--- PASS: TestObjectStatsTrigger (2.52s)1108=== CONT TestServerTLSConfig1109=== RUN TestServerTLSConfig/no_client_CA1110=== PAUSE TestServerTLSConfig/no_client_CA1111=== RUN TestServerTLSConfig/missing_CA_file1112=== PAUSE TestServerTLSConfig/missing_CA_file1113=== RUN TestServerTLSConfig/not_a_PEM_file1114=== PAUSE TestServerTLSConfig/not_a_PEM_file1115=== CONT TestGCBugBareHashReferences11162026-10-01 10:21:17.756 UTC [27182] ERROR: relation "goose_db_version" does not exist at character 3611172026-10-01 10:21:17.756 UTC [27182] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11182026/10/01 10:21:17 OK 20241026095416_initial_model.sql (155.82ms)11192026/10/01 10:21:17 OK 20251210153512_drop_unused_gin_index.sql (8.12ms)11202026/10/01 10:21:17 OK 20251218171726_add_pins.sql (21.57ms)11212026/10/01 10:21:17 INFO Received uploads request method=POST path=/api/pending_closures11222026/10/01 10:21:17 OK 20260628120000_add_object_size_and_stats.sql (73.8ms)11232026/10/01 10:21:17 OK 20260905000000_add_claims.sql (49.27ms)11242026/10/01 10:21:17 INFO Received uploads request method=POST path=/api/pending_closures11252026/10/01 10:21:17 OK 20241026095416_initial_model.sql (105.2ms)11262026/10/01 10:21:17 OK 20251210153512_drop_unused_gin_index.sql (10.28ms)11272026/10/01 10:21:17 OK 20260920000000_drop_claims.sql (27.34ms)11282026/10/01 10:21:17 OK 20251218171726_add_pins.sql (22.13ms)11292026/10/01 10:21:17 OK 20260923120000_add_pushes.sql (16.01ms)11302026/10/01 10:21:17 goose: successfully migrated database to version: 2026092312000011312026/10/01 10:21:17 INFO Received cleanup request method=DELETE path=/api/pending_closures11322026/10/01 10:21:17 OK 1_commit_pending_closure.sql (2.82ms)11332026/10/01 10:21:17 OK 2_object_stats_trigger.sql (623.58µs)11342026/10/01 10:21:17 OK 3_commit_push.sql (472.54µs)11352026/10/01 10:21:17 goose: up to current file version: 311362026/10/01 10:21:17 OK 20260628120000_add_object_size_and_stats.sql (28.7ms)11372026/10/01 10:21:18 OK 20260905000000_add_claims.sql (49.48ms)11382026/10/01 10:21:18 OK 20260920000000_drop_claims.sql (26.6ms)11392026/10/01 10:21:18 OK 20260923120000_add_pushes.sql (27.89ms)11402026/10/01 10:21:18 goose: successfully migrated database to version: 2026092312000011412026/10/01 10:21:18 OK 1_commit_pending_closure.sql (5.96ms)11422026/10/01 10:21:18 OK 2_object_stats_trigger.sql (1ms)11432026/10/01 10:21:18 OK 3_commit_push.sql (488.96µs)11442026/10/01 10:21:18 goose: up to current file version: 311452026/10/01 10:21:18 INFO Received uploads request method=POST path=/api/pending_closures1146--- PASS: TestTombstonedObjectOfferedWithoutWaiting (2.58s)1147=== CONT TestService_NativeMTLS11482026/10/01 10:21:18 INFO Received uploads request method=POST path=/api/pending_closures1149--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (2.71s)1150=== CONT TestLeadEndsOnShutdown11512026-10-01 10:21:18.705 UTC [27187] ERROR: relation "goose_db_version" does not exist at character 3611522026-10-01 10:21:18.705 UTC [27187] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11532026-10-01 10:21:18.836 UTC [27189] ERROR: relation "goose_db_version" does not exist at character 3611542026-10-01 10:21:18.836 UTC [27189] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11552026-10-01 10:21:18.837 UTC [27190] ERROR: relation "goose_db_version" does not exist at character 3611562026-10-01 10:21:18.837 UTC [27190] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11572026/10/01 10:21:18 OK 20241026095416_initial_model.sql (91.83ms)11582026/10/01 10:21:18 OK 20251210153512_drop_unused_gin_index.sql (4.35ms)11592026/10/01 10:21:18 OK 20251218171726_add_pins.sql (19.92ms)11602026/10/01 10:21:18 OK 20260628120000_add_object_size_and_stats.sql (22.14ms)11612026-10-01 10:21:18.884 UTC [27191] ERROR: relation "goose_db_version" does not exist at character 3611622026-10-01 10:21:18.884 UTC [27191] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11632026/10/01 10:21:18 OK 20260905000000_add_claims.sql (35.95ms)11642026/10/01 10:21:18 OK 20260920000000_drop_claims.sql (8.98ms)11652026/10/01 10:21:18 OK 20260923120000_add_pushes.sql (11.37ms)11662026/10/01 10:21:18 goose: successfully migrated database to version: 2026092312000011672026/10/01 10:21:18 OK 1_commit_pending_closure.sql (3.01ms)11682026/10/01 10:21:18 OK 2_object_stats_trigger.sql (531.29µs)11692026/10/01 10:21:18 OK 3_commit_push.sql (391.25µs)11702026/10/01 10:21:18 goose: up to current file version: 311712026/10/01 10:21:18 OK 20241026095416_initial_model.sql (90.79ms)11722026/10/01 10:21:18 OK 20251210153512_drop_unused_gin_index.sql (8.72ms)11732026/10/01 10:21:18 OK 20241026095416_initial_model.sql (108.29ms)11742026-10-01 10:21:18.991 UTC [27192] ERROR: relation "goose_db_version" does not exist at character 3611752026-10-01 10:21:18.991 UTC [27192] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11762026/10/01 10:21:18 OK 20251210153512_drop_unused_gin_index.sql (8.64ms)11772026/10/01 10:21:19 OK 20251218171726_add_pins.sql (27.38ms)11782026/10/01 10:21:19 OK 20251218171726_add_pins.sql (18.77ms)11792026/10/01 10:21:19 OK 20260628120000_add_object_size_and_stats.sql (37.63ms)11802026/10/01 10:21:19 OK 20260628120000_add_object_size_and_stats.sql (46.46ms)11812026/10/01 10:21:19 OK 20260905000000_add_claims.sql (69.07ms)11822026/10/01 10:21:19 OK 20260905000000_add_claims.sql (51.49ms)11832026/10/01 10:21:19 OK 20241026095416_initial_model.sql (190.34ms)11842026/10/01 10:21:19 OK 20251210153512_drop_unused_gin_index.sql (16.75ms)11852026/10/01 10:21:19 OK 20260920000000_drop_claims.sql (42.29ms)11862026/10/01 10:21:19 OK 20260920000000_drop_claims.sql (42.72ms)11872026/10/01 10:21:19 OK 20251218171726_add_pins.sql (24.3ms)11882026/10/01 10:21:19 OK 20260923120000_add_pushes.sql (33.41ms)11892026/10/01 10:21:19 OK 20260923120000_add_pushes.sql (34.07ms)11902026/10/01 10:21:19 goose: successfully migrated database to version: 2026092312000011912026/10/01 10:21:19 goose: successfully migrated database to version: 2026092312000011922026/10/01 10:21:19 OK 1_commit_pending_closure.sql (4.88ms)11932026/10/01 10:21:19 OK 1_commit_pending_closure.sql (5ms)11942026/10/01 10:21:19 OK 2_object_stats_trigger.sql (1.05ms)11952026/10/01 10:21:19 OK 3_commit_push.sql (3.02ms)11962026/10/01 10:21:19 goose: up to current file version: 311972026/10/01 10:21:19 OK 2_object_stats_trigger.sql (4.38ms)11982026/10/01 10:21:19 OK 3_commit_push.sql (4.1ms)11992026/10/01 10:21:19 goose: up to current file version: 312002026/10/01 10:21:19 OK 20260628120000_add_object_size_and_stats.sql (48.92ms)12012026/10/01 10:21:19 OK 20241026095416_initial_model.sql (198.19ms)12022026/10/01 10:21:19 INFO Received uploads request method=POST path=/api/pending_closures12032026/10/01 10:21:19 OK 20251210153512_drop_unused_gin_index.sql (7.92ms)12042026/10/01 10:21:19 OK 20260905000000_add_claims.sql (62.75ms)12052026/10/01 10:21:19 OK 20251218171726_add_pins.sql (32.01ms)12062026/10/01 10:21:19 OK 20260920000000_drop_claims.sql (33.7ms)12072026/10/01 10:21:19 OK 20260923120000_add_pushes.sql (13.5ms)12082026/10/01 10:21:19 goose: successfully migrated database to version: 2026092312000012092026/10/01 10:21:19 OK 1_commit_pending_closure.sql (3.65ms)12102026/10/01 10:21:19 OK 2_object_stats_trigger.sql (766.75µs)12112026/10/01 10:21:19 OK 3_commit_push.sql (449.33µs)12122026/10/01 10:21:19 goose: up to current file version: 312132026/10/01 10:21:19 INFO Aborted multipart uploads count=0 kept=012142026-10-01 10:21:19.327 UTC [27193] ERROR: relation "goose_db_version" does not exist at character 3612152026-10-01 10:21:19.327 UTC [27193] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12162026/10/01 10:21:19 OK 20260628120000_add_object_size_and_stats.sql (36.5ms)12172026/10/01 10:21:19 WARN Force mode enabled - objects will be deleted immediately without grace period12182026/10/01 10:21:19 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=012192026/10/01 10:21:19 INFO Vacuumed table table=pending_closures12202026/10/01 10:21:19 INFO Vacuumed table table=pending_objects12212026/10/01 10:21:19 INFO Vacuumed table table=multipart_uploads12222026/10/01 10:21:19 INFO Vacuumed table table=closures12232026/10/01 10:21:19 INFO Vacuumed table table=objects12242026/10/01 10:21:19 OK 20260905000000_add_claims.sql (37.89ms)1225--- PASS: TestGCSweepSkipsPendingObjects (2.44s)1226=== CONT TestMetricsInventory12272026/10/01 10:21:19 OK 20260920000000_drop_claims.sql (24.9ms)12282026/10/01 10:21:19 OK 20260923120000_add_pushes.sql (13.13ms)12292026/10/01 10:21:19 goose: successfully migrated database to version: 2026092312000012302026/10/01 10:21:19 OK 1_commit_pending_closure.sql (2.11ms)12312026/10/01 10:21:19 OK 2_object_stats_trigger.sql (494.96µs)12322026/10/01 10:21:19 OK 3_commit_push.sql (386.5µs)12332026/10/01 10:21:19 goose: up to current file version: 312342026/10/01 10:21:19 OK 20241026095416_initial_model.sql (138.12ms)12352026/10/01 10:21:19 OK 20251210153512_drop_unused_gin_index.sql (9.65ms)12362026/10/01 10:21:19 OK 20251218171726_add_pins.sql (35.21ms)12372026/10/01 10:21:19 OK 20260628120000_add_object_size_and_stats.sql (32.12ms)12382026/10/01 10:21:19 INFO Received uploads request method=POST path=/api/pending_closures12392026/10/01 10:21:19 OK 20260905000000_add_claims.sql (58.51ms)12402026/10/01 10:21:19 OK 20260920000000_drop_claims.sql (34.22ms)12412026/10/01 10:21:19 OK 20260923120000_add_pushes.sql (21.78ms)12422026/10/01 10:21:19 goose: successfully migrated database to version: 2026092312000012432026/10/01 10:21:19 OK 1_commit_pending_closure.sql (4.35ms)12442026/10/01 10:21:19 OK 2_object_stats_trigger.sql (891.04µs)12452026/10/01 10:21:19 OK 3_commit_push.sql (618.67µs)12462026/10/01 10:21:19 goose: up to current file version: 312472026/10/01 10:21:19 INFO Aborted multipart uploads count=0 kept=012482026/10/01 10:21:19 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012492026/10/01 10:21:19 INFO Vacuumed table table=pending_closures12502026/10/01 10:21:19 INFO Vacuumed table table=pending_objects12512026/10/01 10:21:19 INFO Vacuumed table table=multipart_uploads12522026/10/01 10:21:19 INFO Vacuumed table table=closures12532026/10/01 10:21:19 INFO Vacuumed table table=objects12542026/10/01 10:21:19 INFO Received uploads request method=POST path=/api/pending_closures12552026/10/01 10:21:19 INFO Aborted multipart uploads count=0 kept=012562026/10/01 10:21:19 WARN Force mode enabled - objects will be deleted immediately without grace period12572026/10/01 10:21:19 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=012582026/10/01 10:21:19 INFO Vacuumed table table=pending_closures12592026/10/01 10:21:19 INFO Vacuumed table table=pending_objects12602026/10/01 10:21:19 INFO Vacuumed table table=multipart_uploads12612026/10/01 10:21:19 INFO Vacuumed table table=closures12622026/10/01 10:21:19 INFO Vacuumed table table=objects1263--- PASS: TestPushDedupSurvivesConcurrentGC (2.68s)1264=== CONT TestLeadElectsOneAndHandsOver12652026/10/01 10:21:19 INFO Received cleanup request method=DELETE path=/api/pending_closures12662026/10/01 10:21:19 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket24/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12672026/10/01 10:21:19 INFO Aborted multipart uploads count=0 kept=112682026/10/01 10:21:19 INFO Received cleanup request method=DELETE path=/api/pending_closures12692026/10/01 10:21:20 INFO Aborted multipart uploads count=1 kept=012702026-10-01 10:21:20.012 UTC [27200] ERROR: relation "goose_db_version" does not exist at character 3612712026-10-01 10:21:20.012 UTC [27200] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1272--- PASS: TestMultipartCleanup (2.90s)1273=== CONT TestNARDeduplicationMetadataUploadBug12742026/10/01 10:21:20 INFO Received uploads request method=POST path=/api/pending_closures1275--- PASS: TestDeduplicatedObjectsRecordedAsPending (2.85s)1276=== CONT TestResolveDBConnectionString1277=== RUN TestResolveDBConnectionString/flag_wins1278=== PAUSE TestResolveDBConnectionString/flag_wins1279=== RUN TestResolveDBConnectionString/file_when_flag_empty1280=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1281=== RUN TestResolveDBConnectionString/missing_file_is_an_error1282=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1283=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1284=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1285=== RUN TestResolveDBConnectionString/nothing_configured1286=== PAUSE TestResolveDBConnectionString/nothing_configured1287=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12882026/10/01 10:21:20 OK 20241026095416_initial_model.sql (265.13ms)12892026/10/01 10:21:20 OK 20251210153512_drop_unused_gin_index.sql (17.89ms)12902026/10/01 10:21:20 OK 20251218171726_add_pins.sql (46.29ms)12912026/10/01 10:21:20 OK 20260628120000_add_object_size_and_stats.sql (45.36ms)12922026/10/01 10:21:20 INFO Aborted multipart uploads count=0 kept=012932026/10/01 10:21:20 OK 20260905000000_add_claims.sql (82.29ms)12942026/10/01 10:21:20 WARN Force mode enabled - objects will be deleted immediately without grace period12952026/10/01 10:21:20 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=012962026/10/01 10:21:20 INFO Vacuumed table table=pending_closures12972026-10-01 10:21:20.539 UTC [27205] ERROR: relation "goose_db_version" does not exist at character 3612982026-10-01 10:21:20.539 UTC [27205] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12992026/10/01 10:21:20 INFO Vacuumed table table=pending_objects13002026/10/01 10:21:20 INFO Vacuumed table table=multipart_uploads13012026/10/01 10:21:20 INFO Vacuumed table table=closures13022026/10/01 10:21:20 INFO Vacuumed table table=objects13032026/10/01 10:21:20 OK 20260920000000_drop_claims.sql (26.87ms)1304--- PASS: TestGCMetrics (3.05s)1305=== CONT TestCreatePendingClosureRejectsOversizedNAR13062026/10/01 10:21:20 INFO Received uploads request method=POST path=/api/pending_closures1307--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1308=== CONT TestClientFallsBackToClosures13092026/10/01 10:21:20 OK 20260923120000_add_pushes.sql (14.2ms)13102026/10/01 10:21:20 goose: successfully migrated database to version: 2026092312000013112026/10/01 10:21:20 OK 1_commit_pending_closure.sql (2.6ms)13122026/10/01 10:21:20 OK 2_object_stats_trigger.sql (549µs)13132026/10/01 10:21:20 OK 3_commit_push.sql (376.58µs)13142026/10/01 10:21:20 goose: up to current file version: 313152026/10/01 10:21:20 OK 20241026095416_initial_model.sql (204.88ms)13162026/10/01 10:21:20 OK 20251210153512_drop_unused_gin_index.sql (15.03ms)13172026/10/01 10:21:20 OK 20251218171726_add_pins.sql (43.03ms)13182026/10/01 10:21:20 OK 20260628120000_add_object_size_and_stats.sql (40.92ms)13192026/10/01 10:21:20 OK 20260905000000_add_claims.sql (93.8ms)1320--- PASS: TestGCBugBareHashReferences (3.41s)1321=== CONT TestCacheConfigHandlerMaxNarSize1322--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1323=== CONT TestClientPushesUseOnePush13242026/10/01 10:21:21 OK 20260920000000_drop_claims.sql (44.81ms)13252026/10/01 10:21:21 OK 20260923120000_add_pushes.sql (22.53ms)13262026/10/01 10:21:21 goose: successfully migrated database to version: 2026092312000013272026/10/01 10:21:21 OK 1_commit_pending_closure.sql (2.35ms)13282026/10/01 10:21:21 OK 2_object_stats_trigger.sql (444.75µs)13292026/10/01 10:21:21 OK 3_commit_push.sql (340.17µs)13302026/10/01 10:21:21 goose: up to current file version: 313312026/10/01 10:21:21 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13322026/10/01 10:21:21 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1333--- PASS: TestService_NativeMTLS (2.84s)1334=== CONT TestGenerateLandingPage1335--- PASS: TestGenerateLandingPage (0.00s)1336=== CONT TestPinProtectsFromGC13372026/10/01 10:21:21 INFO lead: acquired remote=192.0.2.1:123413382026/10/01 10:21:21 INFO lead: released remote=192.0.2.1:12341339--- PASS: TestLeadEndsOnShutdown (2.84s)1340=== CONT TestService_readinessHandler13412026-10-01 10:21:21.781 UTC [27215] ERROR: relation "goose_db_version" does not exist at character 3613422026-10-01 10:21:21.781 UTC [27215] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13432026/10/01 10:21:22 OK 20241026095416_initial_model.sql (222.94ms)13442026/10/01 10:21:22 OK 20251210153512_drop_unused_gin_index.sql (18.97ms)13452026/10/01 10:21:22 OK 20251218171726_add_pins.sql (53.68ms)13462026/10/01 10:21:22 OK 20260628120000_add_object_size_and_stats.sql (61.42ms)1347=== NAME TestOrphanedObjectsGCStressTest1348 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains13492026/10/01 10:21:22 OK 20260905000000_add_claims.sql (71.05ms)1350 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion13512026/10/01 10:21:22 OK 20260920000000_drop_claims.sql (27.35ms)13522026/10/01 10:21:22 OK 20260923120000_add_pushes.sql (18.41ms)13532026/10/01 10:21:22 goose: successfully migrated database to version: 2026092312000013542026/10/01 10:21:22 OK 1_commit_pending_closure.sql (3.81ms)13552026/10/01 10:21:22 OK 2_object_stats_trigger.sql (918.54µs)13562026/10/01 10:21:22 OK 3_commit_push.sql (552.33µs)13572026/10/01 10:21:22 goose: up to current file version: 313582026-10-01 10:21:22.332 UTC [27216] ERROR: relation "goose_db_version" does not exist at character 3613592026-10-01 10:21:22.332 UTC [27216] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13602026-10-01 10:21:22.350 UTC [27217] ERROR: relation "goose_db_version" does not exist at character 3613612026-10-01 10:21:22.350 UTC [27217] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13622026-10-01 10:21:22.361 UTC [27218] ERROR: relation "goose_db_version" does not exist at character 3613632026-10-01 10:21:22.361 UTC [27218] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13642026/10/01 10:21:22 OK 20241026095416_initial_model.sql (69.82ms)13652026/10/01 10:21:22 OK 20241026095416_initial_model.sql (81.9ms)13662026/10/01 10:21:22 OK 20241026095416_initial_model.sql (72.81ms)13672026/10/01 10:21:22 OK 20251210153512_drop_unused_gin_index.sql (8.91ms)13682026/10/01 10:21:22 OK 20251210153512_drop_unused_gin_index.sql (8.71ms)13692026/10/01 10:21:22 OK 20251210153512_drop_unused_gin_index.sql (8.57ms)13702026/10/01 10:21:22 OK 20251218171726_add_pins.sql (26.72ms)13712026/10/01 10:21:22 OK 20251218171726_add_pins.sql (27.06ms)13722026/10/01 10:21:22 OK 20251218171726_add_pins.sql (27.9ms)13732026/10/01 10:21:22 OK 20260628120000_add_object_size_and_stats.sql (24.88ms)13742026/10/01 10:21:22 OK 20260628120000_add_object_size_and_stats.sql (24.9ms)13752026/10/01 10:21:22 OK 20260628120000_add_object_size_and_stats.sql (38.29ms)13762026-10-01 10:21:22.543 UTC [27219] ERROR: relation "goose_db_version" does not exist at character 3613772026-10-01 10:21:22.543 UTC [27219] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13782026/10/01 10:21:22 OK 20260905000000_add_claims.sql (28.04ms)13792026/10/01 10:21:22 OK 20260905000000_add_claims.sql (29.53ms)13802026/10/01 10:21:22 OK 20260920000000_drop_claims.sql (17.94ms)13812026/10/01 10:21:22 OK 20260920000000_drop_claims.sql (17.22ms)13822026/10/01 10:21:22 OK 20260905000000_add_claims.sql (27.29ms)13832026/10/01 10:21:22 OK 20260923120000_add_pushes.sql (11.93ms)13842026/10/01 10:21:22 goose: successfully migrated database to version: 2026092312000013852026/10/01 10:21:22 OK 20260923120000_add_pushes.sql (11.35ms)13862026/10/01 10:21:22 goose: successfully migrated database to version: 2026092312000013872026/10/01 10:21:22 OK 1_commit_pending_closure.sql (3.33ms)13882026/10/01 10:21:22 OK 1_commit_pending_closure.sql (3.41ms)13892026/10/01 10:21:22 OK 2_object_stats_trigger.sql (629.75µs)13902026/10/01 10:21:22 OK 2_object_stats_trigger.sql (635.04µs)13912026/10/01 10:21:22 OK 3_commit_push.sql (447.75µs)13922026/10/01 10:21:22 goose: up to current file version: 313932026/10/01 10:21:22 OK 3_commit_push.sql (562.54µs)13942026/10/01 10:21:22 goose: up to current file version: 313952026/10/01 10:21:22 OK 20260920000000_drop_claims.sql (20.88ms)1396--- PASS: TestMetricsInventory (3.19s)1397=== CONT TestClientSharedPathCommittedMidPush13982026/10/01 10:21:22 OK 20260923120000_add_pushes.sql (17.58ms)13992026/10/01 10:21:22 goose: successfully migrated database to version: 2026092312000014002026/10/01 10:21:22 OK 1_commit_pending_closure.sql (2.43ms)14012026/10/01 10:21:22 OK 2_object_stats_trigger.sql (662.71µs)14022026/10/01 10:21:22 OK 3_commit_push.sql (356.96µs)14032026/10/01 10:21:22 goose: up to current file version: 314042026/10/01 10:21:22 OK 20241026095416_initial_model.sql (77.27ms)14052026/10/01 10:21:22 OK 20251210153512_drop_unused_gin_index.sql (8.86ms)14062026/10/01 10:21:22 OK 20251218171726_add_pins.sql (15.1ms)14072026/10/01 10:21:22 OK 20260628120000_add_object_size_and_stats.sql (59.85ms)14082026/10/01 10:21:22 OK 20260905000000_add_claims.sql (37.3ms)14092026/10/01 10:21:22 OK 20260920000000_drop_claims.sql (56.09ms)14102026/10/01 10:21:22 OK 20260923120000_add_pushes.sql (6.42ms)14112026/10/01 10:21:22 goose: successfully migrated database to version: 2026092312000014122026/10/01 10:21:22 OK 1_commit_pending_closure.sql (6.84ms)14132026/10/01 10:21:22 OK 2_object_stats_trigger.sql (842.04µs)14142026/10/01 10:21:22 OK 3_commit_push.sql (460.63µs)14152026/10/01 10:21:22 goose: up to current file version: 314162026-10-01 10:21:22.965 UTC [27222] ERROR: relation "goose_db_version" does not exist at character 3614172026-10-01 10:21:22.965 UTC [27222] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14182026-10-01 10:21:23.015 UTC [27223] ERROR: relation "goose_db_version" does not exist at character 3614192026-10-01 10:21:23.015 UTC [27223] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14202026/10/01 10:21:23 INFO lead: acquired remote=192.0.2.1:123414212026/10/01 10:21:23 OK 20241026095416_initial_model.sql (117.19ms)14222026/10/01 10:21:23 OK 20251210153512_drop_unused_gin_index.sql (10.79ms)14232026/10/01 10:21:23 OK 20251218171726_add_pins.sql (10.75ms)14242026/10/01 10:21:23 OK 20241026095416_initial_model.sql (81.59ms)14252026/10/01 10:21:23 OK 20251210153512_drop_unused_gin_index.sql (8.28ms)14262026/10/01 10:21:23 OK 20260628120000_add_object_size_and_stats.sql (17.32ms)14272026-10-01 10:21:23.161 UTC [27225] ERROR: relation "goose_db_version" does not exist at character 3614282026-10-01 10:21:23.161 UTC [27225] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14292026/10/01 10:21:23 OK 20251218171726_add_pins.sql (12.96ms)14302026/10/01 10:21:23 OK 20260628120000_add_object_size_and_stats.sql (18.96ms)14312026/10/01 10:21:23 OK 20260905000000_add_claims.sql (29.67ms)14322026/10/01 10:21:23 OK 20260920000000_drop_claims.sql (12.61ms)14332026/10/01 10:21:23 OK 20260923120000_add_pushes.sql (6.34ms)14342026/10/01 10:21:23 goose: successfully migrated database to version: 2026092312000014352026/10/01 10:21:23 OK 20260905000000_add_claims.sql (19.12ms)14362026/10/01 10:21:23 OK 1_commit_pending_closure.sql (2.93ms)14372026/10/01 10:21:23 OK 2_object_stats_trigger.sql (506.92µs)14382026/10/01 10:21:23 OK 3_commit_push.sql (473.83µs)14392026/10/01 10:21:23 goose: up to current file version: 314402026/10/01 10:21:23 INFO lead: released remote=192.0.2.1:123414412026/10/01 10:21:23 OK 20260920000000_drop_claims.sql (11.29ms)14422026/10/01 10:21:23 OK 20260923120000_add_pushes.sql (5.85ms)14432026/10/01 10:21:23 goose: successfully migrated database to version: 2026092312000014442026/10/01 10:21:23 OK 1_commit_pending_closure.sql (3.22ms)14452026/10/01 10:21:23 OK 2_object_stats_trigger.sql (492.83µs)14462026/10/01 10:21:23 OK 3_commit_push.sql (350.75µs)14472026/10/01 10:21:23 goose: up to current file version: 314482026/10/01 10:21:23 OK 20241026095416_initial_model.sql (76.94ms)14492026/10/01 10:21:23 INFO lead: acquired remote=192.0.2.1:123414502026/10/01 10:21:23 INFO lead: released remote=192.0.2.1:12341451--- PASS: TestLeadElectsOneAndHandsOver (3.38s)1452=== CONT TestService_healthCheckHandler14532026/10/01 10:21:23 OK 20251210153512_drop_unused_gin_index.sql (8.14ms)14542026/10/01 10:21:23 OK 20251218171726_add_pins.sql (11.18ms)14552026/10/01 10:21:23 OK 20260628120000_add_object_size_and_stats.sql (16.36ms)14562026/10/01 10:21:23 OK 20260905000000_add_claims.sql (37.67ms)14572026/10/01 10:21:23 OK 20260920000000_drop_claims.sql (36.61ms)14582026/10/01 10:21:23 OK 20260923120000_add_pushes.sql (12.2ms)14592026/10/01 10:21:23 goose: successfully migrated database to version: 2026092312000014602026/10/01 10:21:23 OK 1_commit_pending_closure.sql (1.91ms)14612026/10/01 10:21:23 OK 2_object_stats_trigger.sql (324.88µs)14622026/10/01 10:21:23 OK 3_commit_push.sql (225.96µs)14632026/10/01 10:21:23 goose: up to current file version: 31464=== NAME TestNARDeduplicationMetadataUploadBug1465 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-26883-1285942671/TestNARDeduplicationMetadataUploadBug897776796/001/store/gnrabjd11pq3bl3ap4a4bp6pk2js8w7i-file1.txt14662026/10/01 10:21:23 INFO Received push request method=POST path=/api/pushes14672026/10/01 10:21:23 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14682026/10/01 10:21:23 INFO Uploading gnrabjd11pq3bl3ap4a4bp6pk2js8w7i-file1.txt (160B)14692026/10/01 10:21:23 WARN Failed to register uploaded object key=gnrabjd11pq3bl3ap4a4bp6pk2js8w7i.ls error="server returned 404: 404 page not found\n"14702026/10/01 10:21:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14712026/10/01 10:21:23 INFO Signed narinfos id=1 count=114722026/10/01 10:21:23 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"14732026/10/01 10:21:23 INFO Uploading 1 narinfos14742026/10/01 10:21:23 INFO Received complete push request method=POST path=/api/pushes/1/complete14752026/10/01 10:21:23 WARN Failed to register uploaded object key=gnrabjd11pq3bl3ap4a4bp6pk2js8w7i.narinfo error="server returned 404: 404 page not found\n"14762026/10/01 10:21:23 INFO Upload complete. (154ms)1477 metadata_upload_test.go:54: Retrieved narinfo from S3:1478 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestNARDeduplicationMetadataUploadBug897776796/001/store/gnrabjd11pq3bl3ap4a4bp6pk2js8w7i-file1.txt1479 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1480 Compression: zstd1481 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1482 NarSize: 1601483 References: 1484 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1485 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1486 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1487 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1488--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (3.48s)1489=== CONT TestGracefulShutdownDrainsInflight14902026/10/01 10:21:23 INFO Starting HTTP server address=127.0.0.1:6020314912026/10/01 10:21:23 INFO Shutdown signal received, draining in-flight requests timeout=10s1492=== NAME TestNARDeduplicationMetadataUploadBug1493 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-26883-1285942671/TestNARDeduplicationMetadataUploadBug897776796/001/store/wmbjyfym10rbqsrgyqp32fm1z2ynx1mm-file2.txt1494--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1495=== CONT TestGCTaskStore_Fail1496--- PASS: TestGCTaskStore_Fail (0.00s)1497=== CONT TestGCTaskStore_PhaseUpdates1498--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1499=== CONT TestGCTaskStore_CompletedAllowsNewTask1500--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1501=== CONT TestGCTaskStore_GetReturnsLatest1502--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1503=== CONT TestGCTaskStore_GetEmpty1504--- PASS: TestGCTaskStore_GetEmpty (0.00s)1505=== CONT TestGCTaskStore_ConflictDifferentParams1506--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1507=== CONT TestGCTaskStore_DeduplicateSameParams1508--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1509=== CONT TestGCTaskStore_StartNew1510--- PASS: TestGCTaskStore_StartNew (0.00s)1511=== CONT TestGCEndsOnShutdown15122026-10-01 10:21:23.727 UTC [27242] ERROR: relation "goose_db_version" does not exist at character 3615132026-10-01 10:21:23.727 UTC [27242] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15142026/10/01 10:21:23 INFO Received push request method=POST path=/api/pushes15152026/10/01 10:21:23 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15162026/10/01 10:21:23 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15172026/10/01 10:21:23 INFO Signed narinfos id=2 count=115182026/10/01 10:21:23 WARN Failed to register uploaded object key=wmbjyfym10rbqsrgyqp32fm1z2ynx1mm.ls error="server returned 404: 404 page not found\n"15192026/10/01 10:21:23 INFO Uploading 1 narinfos15202026/10/01 10:21:23 INFO Received complete push request method=POST path=/api/pushes/2/complete15212026/10/01 10:21:23 WARN Failed to register uploaded object key=wmbjyfym10rbqsrgyqp32fm1z2ynx1mm.narinfo error="server returned 404: 404 page not found\n"15222026/10/01 10:21:23 INFO Upload complete. (106ms)1523=== NAME TestNARDeduplicationMetadataUploadBug1524 metadata_upload_test.go:76: Retrieved narinfo from S3:1525 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestNARDeduplicationMetadataUploadBug897776796/001/store/wmbjyfym10rbqsrgyqp32fm1z2ynx1mm-file2.txt1526 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1527 Compression: zstd1528 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1529 NarSize: 1601530 References: 1531 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1532 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1533 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1534 {"version":1,"root":{"type":"regular","size":44}}15352026/10/01 10:21:23 OK 20241026095416_initial_model.sql (131.19ms)15362026/10/01 10:21:23 OK 20251210153512_drop_unused_gin_index.sql (12.65ms)15372026/10/01 10:21:23 OK 20251218171726_add_pins.sql (29.55ms)1538--- PASS: TestNARDeduplicationMetadataUploadBug (3.91s)1539=== CONT TestCommitRacingPendingCleanupKeepsObjects15402026/10/01 10:21:23 INFO Received uploads request method=POST path=/api/pending_closures15412026/10/01 10:21:23 OK 20260628120000_add_object_size_and_stats.sql (25.61ms)15422026/10/01 10:21:23 OK 20260905000000_add_claims.sql (35.52ms)15432026/10/01 10:21:23 INFO Received uploads request method=POST path=/api/pending_closures15442026/10/01 10:21:23 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15452026/10/01 10:21:23 INFO Uploading vni70dx3ar26jsi9l91lri0wq5wpl571-shared-dep (136B)15462026/10/01 10:21:23 INFO Uploading b8iw02imvrygv20d9d8by6n7i6pr4h9a-a (248B)15472026/10/01 10:21:23 INFO Aborted multipart uploads count=1 kept=015482026/10/01 10:21:24 WARN Failed to register uploaded object key=29ylifsgld2v3kpwpr07wwqs8s0qfv92.ls error="server returned 404: 404 page not found\n"15492026/10/01 10:21:24 WARN Failed to register uploaded object key=b8iw02imvrygv20d9d8by6n7i6pr4h9a.ls error="server returned 404: 404 page not found\n"15502026/10/01 10:21:24 WARN Failed to register uploaded object key=nar/1qlsb9g29a4y3mk2m1mf5zjc9qzi9hynlrlf0b3c3gvajcl6w9hv.nar.zst error="server returned 404: 404 page not found\n"15512026/10/01 10:21:24 WARN Failed to register uploaded object key=vni70dx3ar26jsi9l91lri0wq5wpl571.ls error="server returned 404: 404 page not found\n"15522026/10/01 10:21:24 INFO Received cleanup request method=DELETE path=/api/pending_closures15532026/10/01 10:21:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15542026/10/01 10:21:24 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15552026/10/01 10:21:24 INFO Aborted multipart uploads count=1 kept=015562026/10/01 10:21:24 INFO Signed narinfos id=1 count=215572026/10/01 10:21:24 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15582026/10/01 10:21:24 INFO Signed narinfos id=2 count=215592026/10/01 10:21:24 INFO Uploading 4 narinfos15602026/10/01 10:21:24 OK 20260920000000_drop_claims.sql (53.56ms)1561--- PASS: TestPendingCleanupUsesOneCutoff (8.74s)1562=== CONT TestPushWaitsForSweepHoldingRow15632026/10/01 10:21:24 OK 20260923120000_add_pushes.sql (9.52ms)15642026/10/01 10:21:24 goose: successfully migrated database to version: 2026092312000015652026/10/01 10:21:24 WARN Failed to register uploaded object key=vni70dx3ar26jsi9l91lri0wq5wpl571.narinfo error="server returned 404: 404 page not found\n"15662026/10/01 10:21:24 WARN Failed to register uploaded object key=b8iw02imvrygv20d9d8by6n7i6pr4h9a.narinfo error="server returned 404: 404 page not found\n"15672026/10/01 10:21:24 OK 1_commit_pending_closure.sql (2.39ms)15682026/10/01 10:21:24 WARN Failed to register uploaded object key=29ylifsgld2v3kpwpr07wwqs8s0qfv92.narinfo error="server returned 404: 404 page not found\n"15692026/10/01 10:21:24 OK 2_object_stats_trigger.sql (376.08µs)15702026/10/01 10:21:24 OK 3_commit_push.sql (208.88µs)15712026/10/01 10:21:24 goose: up to current file version: 315722026/10/01 10:21:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15732026/10/01 10:21:24 WARN Failed to register uploaded object key=vni70dx3ar26jsi9l91lri0wq5wpl571.narinfo error="server returned 404: 404 page not found\n"15742026/10/01 10:21:24 INFO Completed upload id=115752026/10/01 10:21:24 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15762026/10/01 10:21:24 INFO Completed upload id=215772026/10/01 10:21:24 INFO Upload complete. (200ms)1578=== NAME TestClientFallsBackToClosures1579 client_pushes_test.go:112: Retrieved narinfo from S3:1580 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestClientFallsBackToClosures1294269501/001/store/vni70dx3ar26jsi9l91lri0wq5wpl571-shared-dep1581 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1582 Compression: zstd1583 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821584 NarSize: 1361585 References: 1586 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1587 client_pushes_test.go:112: Retrieved narinfo from S3:1588 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestClientFallsBackToClosures1294269501/001/store/b8iw02imvrygv20d9d8by6n7i6pr4h9a-a1589 URL: nar/1qlsb9g29a4y3mk2m1mf5zjc9qzi9hynlrlf0b3c3gvajcl6w9hv.nar.zst1590 Compression: zstd1591 NarHash: sha256:1qlsb9g29a4y3mk2m1mf5zjc9qzi9hynlrlf0b3c3gvajcl6w9hv1592 NarSize: 2481593 References: /nix/var/nix/builds/nix-26883-1285942671/TestClientFallsBackToClosures1294269501/001/store/vni70dx3ar26jsi9l91lri0wq5wpl571-shared-dep1594 CA: text:sha256:0djqzmjyi159w5mxnxjxiz1b8ajv5k21jlbif2ag07rpsvlyy0hv1595 client_pushes_test.go:112: Retrieved narinfo from S3:1596 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestClientFallsBackToClosures1294269501/001/store/29ylifsgld2v3kpwpr07wwqs8s0qfv92-b1597 URL: nar/1qlsb9g29a4y3mk2m1mf5zjc9qzi9hynlrlf0b3c3gvajcl6w9hv.nar.zst1598 Compression: zstd1599 NarHash: sha256:1qlsb9g29a4y3mk2m1mf5zjc9qzi9hynlrlf0b3c3gvajcl6w9hv1600 NarSize: 2481601 References: /nix/var/nix/builds/nix-26883-1285942671/TestClientFallsBackToClosures1294269501/001/store/vni70dx3ar26jsi9l91lri0wq5wpl571-shared-dep1602 CA: text:sha256:0djqzmjyi159w5mxnxjxiz1b8ajv5k21jlbif2ag07rpsvlyy0hv16032026/10/01 10:21:24 INFO Received push request method=POST path=/api/pushes1604--- PASS: TestClientFallsBackToClosures (3.61s)1605=== CONT TestSweepRechecksPendingAfterLocking16062026/10/01 10:21:24 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16072026/10/01 10:21:24 INFO Uploading h6j1s26lm82pv57pns3zdwksx9v0c21s-b (248B)16082026/10/01 10:21:24 INFO Uploading pj2svmmvwf8r0cgdvr0gq05mn0d25z9h-shared-dep (136B)16092026/10/01 10:21:24 WARN Failed to register uploaded object key=dipjn93z8kf0dvwrwmvn26d9aglxqv2q.ls error="server returned 404: 404 page not found\n"16102026/10/01 10:21:24 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16112026/10/01 10:21:24 WARN Failed to register uploaded object key=h6j1s26lm82pv57pns3zdwksx9v0c21s.ls error="server returned 404: 404 page not found\n"16122026/10/01 10:21:24 WARN Failed to register uploaded object key=nar/0dk94gr7x380yhdjy9xqy9ayv2qlj32kwzk0bjdzhjd5ck9r26sh.nar.zst error="server returned 404: 404 page not found\n"16132026/10/01 10:21:24 WARN Failed to register uploaded object key=pj2svmmvwf8r0cgdvr0gq05mn0d25z9h.ls error="server returned 404: 404 page not found\n"16142026/10/01 10:21:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16152026/10/01 10:21:24 INFO Signed narinfos id=1 count=316162026/10/01 10:21:24 INFO Uploading 3 narinfos16172026/10/01 10:21:24 WARN Failed to register uploaded object key=pj2svmmvwf8r0cgdvr0gq05mn0d25z9h.narinfo error="server returned 404: 404 page not found\n"16182026/10/01 10:21:24 INFO Received complete push request method=POST path=/api/pushes/1/complete16192026/10/01 10:21:24 WARN Failed to register uploaded object key=dipjn93z8kf0dvwrwmvn26d9aglxqv2q.narinfo error="server returned 404: 404 page not found\n"16202026/10/01 10:21:24 WARN Failed to register uploaded object key=h6j1s26lm82pv57pns3zdwksx9v0c21s.narinfo error="server returned 404: 404 page not found\n"16212026/10/01 10:21:24 INFO Upload complete. (156ms)1622=== NAME TestClientPushesUseOnePush1623 client_pushes_test.go:97: Retrieved narinfo from S3:1624 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestClientPushesUseOnePush816947472/001/store/pj2svmmvwf8r0cgdvr0gq05mn0d25z9h-shared-dep1625 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1626 Compression: zstd1627 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821628 NarSize: 1361629 References: 1630 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1631 client_pushes_test.go:97: Retrieved narinfo from S3:1632 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestClientPushesUseOnePush816947472/001/store/dipjn93z8kf0dvwrwmvn26d9aglxqv2q-a1633 URL: nar/0dk94gr7x380yhdjy9xqy9ayv2qlj32kwzk0bjdzhjd5ck9r26sh.nar.zst1634 Compression: zstd1635 NarHash: sha256:0dk94gr7x380yhdjy9xqy9ayv2qlj32kwzk0bjdzhjd5ck9r26sh1636 NarSize: 2481637 References: /nix/var/nix/builds/nix-26883-1285942671/TestClientPushesUseOnePush816947472/001/store/pj2svmmvwf8r0cgdvr0gq05mn0d25z9h-shared-dep1638 CA: text:sha256:026jwyfm26y9w8p5kksrm8gy6smsam1a4rq2dhnph04p9zyx3yij1639 client_pushes_test.go:97: Retrieved narinfo from S3:1640 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestClientPushesUseOnePush816947472/001/store/h6j1s26lm82pv57pns3zdwksx9v0c21s-b1641 URL: nar/0dk94gr7x380yhdjy9xqy9ayv2qlj32kwzk0bjdzhjd5ck9r26sh.nar.zst1642 Compression: zstd1643 NarHash: sha256:0dk94gr7x380yhdjy9xqy9ayv2qlj32kwzk0bjdzhjd5ck9r26sh1644 NarSize: 2481645 References: /nix/var/nix/builds/nix-26883-1285942671/TestClientPushesUseOnePush816947472/001/store/pj2svmmvwf8r0cgdvr0gq05mn0d25z9h-shared-dep1646 CA: text:sha256:026jwyfm26y9w8p5kksrm8gy6smsam1a4rq2dhnph04p9zyx3yij16472026/10/01 10:21:24 WARN readiness check failed error="closed pool"1648--- PASS: TestService_readinessHandler (2.77s)1649=== CONT TestGetExistingObjectsLocksRows1650=== NAME TestPinProtectsFromGC1651 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-26883-1285942671/TestPinProtectsFromGC2443368751/001/store/hx2ac2i9yhcf41bc7ra3ngfcwvxnh954-pinned-file.txt1652 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-26883-1285942671/TestPinProtectsFromGC2443368751/001/store/ghy78rbgk9nbnbbz9n0q96vdbv92ig6k-unpinned-file.txt1653--- PASS: TestClientPushesUseOnePush (3.28s)1654=== CONT TestRegisterCompletedObjectNeedsPendingRow16552026/10/01 10:21:24 INFO Received push request method=POST path=/api/pushes16562026/10/01 10:21:24 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16572026/10/01 10:21:24 INFO Uploading hx2ac2i9yhcf41bc7ra3ngfcwvxnh954-pinned-file.txt (128B)16582026/10/01 10:21:24 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16592026/10/01 10:21:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16602026/10/01 10:21:24 WARN Failed to register uploaded object key=hx2ac2i9yhcf41bc7ra3ngfcwvxnh954.ls error="server returned 404: 404 page not found\n"16612026/10/01 10:21:24 INFO Signed narinfos id=1 count=116622026/10/01 10:21:24 INFO Uploading 1 narinfos16632026/10/01 10:21:24 INFO Received complete push request method=POST path=/api/pushes/1/complete16642026/10/01 10:21:24 WARN Failed to register uploaded object key=hx2ac2i9yhcf41bc7ra3ngfcwvxnh954.narinfo error="server returned 404: 404 page not found\n"16652026/10/01 10:21:24 INFO Upload complete. (182ms)16662026/10/01 10:21:24 INFO Received push request method=POST path=/api/pushes16672026/10/01 10:21:24 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16682026/10/01 10:21:24 INFO Uploading ghy78rbgk9nbnbbz9n0q96vdbv92ig6k-unpinned-file.txt (128B)16692026/10/01 10:21:24 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16702026/10/01 10:21:24 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16712026/10/01 10:21:24 INFO Signed narinfos id=2 count=116722026/10/01 10:21:24 INFO Uploading 1 narinfos16732026/10/01 10:21:24 WARN Failed to register uploaded object key=ghy78rbgk9nbnbbz9n0q96vdbv92ig6k.ls error="server returned 404: 404 page not found\n"16742026/10/01 10:21:24 INFO Received complete push request method=POST path=/api/pushes/2/complete16752026/10/01 10:21:24 WARN Failed to register uploaded object key=ghy78rbgk9nbnbbz9n0q96vdbv92ig6k.narinfo error="server returned 404: 404 page not found\n"16762026/10/01 10:21:24 INFO Upload complete. (92ms)16772026/10/01 10:21:24 INFO Starting cleanup of old closures method=DELETE path=/api/closures16782026/10/01 10:21:24 INFO Garbage collection started16792026/10/01 10:21:24 INFO Aborted multipart uploads count=0 kept=016802026/10/01 10:21:24 WARN Force mode enabled - objects will be deleted immediately without grace period16812026-10-01 10:21:24.773 UTC [27295] ERROR: relation "goose_db_version" does not exist at character 3616822026-10-01 10:21:24.773 UTC [27295] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16832026/10/01 10:21:24 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=016842026/10/01 10:21:24 INFO Vacuumed table table=pending_closures16852026/10/01 10:21:24 INFO Vacuumed table table=pending_objects16862026/10/01 10:21:24 INFO Vacuumed table table=multipart_uploads16872026/10/01 10:21:24 INFO Vacuumed table table=closures16882026/10/01 10:21:24 INFO Vacuumed table table=objects1689=== NAME TestOrphanedObjectsGCStressTest1690 orphaned_objects_gc_test.go:509: Stress test completed successfully:1691 orphaned_objects_gc_test.go:510: - Active objects preserved: 201692 orphaned_objects_gc_test.go:511: - Objects deleted: 2101693 orphaned_objects_gc_test.go:512: - Total GC'd: 2101694--- PASS: TestOrphanedObjectsGCStressTest (10.60s)1695=== CONT TestSweepSkipsRowsLockedByPush16962026/10/01 10:21:24 OK 20241026095416_initial_model.sql (101.16ms)16972026/10/01 10:21:24 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)16982026/10/01 10:21:24 OK 20251218171726_add_pins.sql (2.85ms)16992026/10/01 10:21:24 INFO Received push request method=POST path=/api/pushes17002026/10/01 10:21:24 OK 20260628120000_add_object_size_and_stats.sql (5.82ms)17012026/10/01 10:21:24 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17022026/10/01 10:21:24 INFO Uploading cjlc9sx50xw3v9y7pcdf0wqpi4wczd57-shared-dep (136B)17032026/10/01 10:21:24 INFO Uploading lk3xrj0p65zy4hhx2545rhg9619sn041-top (256B)17042026/10/01 10:21:24 OK 20260905000000_add_claims.sql (6.25ms)17052026/10/01 10:21:24 WARN Failed to register uploaded object key=cjlc9sx50xw3v9y7pcdf0wqpi4wczd57.ls error="server returned 404: 404 page not found\n"17062026/10/01 10:21:24 WARN Failed to register uploaded object key=lk3xrj0p65zy4hhx2545rhg9619sn041.ls error="server returned 404: 404 page not found\n"17072026/10/01 10:21:24 WARN Failed to register uploaded object key=nar/0qrbwim4g059vwfi7lf5qhi3764j50yfix39yza6g6y34q3zan5x.nar.zst error="server returned 404: 404 page not found\n"17082026/10/01 10:21:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17092026/10/01 10:21:24 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17102026/10/01 10:21:24 INFO Signed narinfos id=1 count=217112026/10/01 10:21:24 INFO Uploading 2 narinfos17122026/10/01 10:21:24 INFO Received complete push request method=POST path=/api/pushes/1/complete17132026/10/01 10:21:24 WARN Failed to register uploaded object key=cjlc9sx50xw3v9y7pcdf0wqpi4wczd57.narinfo error="server returned 404: 404 page not found\n"17142026/10/01 10:21:24 WARN Failed to register uploaded object key=lk3xrj0p65zy4hhx2545rhg9619sn041.narinfo error="server returned 404: 404 page not found\n"17152026/10/01 10:21:24 OK 20260920000000_drop_claims.sql (15.86ms)17162026/10/01 10:21:24 OK 20260923120000_add_pushes.sql (687.04µs)17172026/10/01 10:21:24 goose: successfully migrated database to version: 2026092312000017182026/10/01 10:21:24 OK 1_commit_pending_closure.sql (887.75µs)17192026/10/01 10:21:24 OK 2_object_stats_trigger.sql (236.79µs)17202026/10/01 10:21:24 OK 3_commit_push.sql (190.46µs)17212026/10/01 10:21:24 goose: up to current file version: 317222026/10/01 10:21:24 INFO Upload complete. (107ms)1723=== NAME TestClientSharedPathCommittedMidPush1724 client_integration_test.go:680: Retrieved narinfo from S3:1725 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestClientSharedPathCommittedMidPush2956082019/001/store/cjlc9sx50xw3v9y7pcdf0wqpi4wczd57-shared-dep1726 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1727 Compression: zstd1728 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821729 NarSize: 1361730 References: 1731 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1732 client_integration_test.go:680: Retrieved narinfo from S3:1733 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestClientSharedPathCommittedMidPush2956082019/001/store/lk3xrj0p65zy4hhx2545rhg9619sn041-top1734 URL: nar/0qrbwim4g059vwfi7lf5qhi3764j50yfix39yza6g6y34q3zan5x.nar.zst1735 Compression: zstd1736 NarHash: sha256:0qrbwim4g059vwfi7lf5qhi3764j50yfix39yza6g6y34q3zan5x1737 NarSize: 2561738 References: /nix/var/nix/builds/nix-26883-1285942671/TestClientSharedPathCommittedMidPush2956082019/001/store/cjlc9sx50xw3v9y7pcdf0wqpi4wczd57-shared-dep1739 CA: text:sha256:02zx7fb91s803hy8fmi37kxwfb55vpckjbxwpi8qxh0wy67wb0r31740--- PASS: TestClientSharedPathCommittedMidPush (2.47s)1741=== CONT TestClientWithDependencies1742--- PASS: TestService_healthCheckHandler (1.91s)1743=== CONT TestClientMultipleUploads17442026-10-01 10:21:25.218 UTC [27329] ERROR: relation "goose_db_version" does not exist at character 3617452026-10-01 10:21:25.218 UTC [27329] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17462026-10-01 10:21:25.230 UTC [27330] ERROR: relation "goose_db_version" does not exist at character 3617472026-10-01 10:21:25.230 UTC [27330] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17482026/10/01 10:21:25 OK 20241026095416_initial_model.sql (11.14ms)17492026/10/01 10:21:25 OK 20251210153512_drop_unused_gin_index.sql (502.83µs)17502026/10/01 10:21:25 OK 20251218171726_add_pins.sql (1.32ms)17512026/10/01 10:21:25 OK 20260628120000_add_object_size_and_stats.sql (1.85ms)17522026/10/01 10:21:25 OK 20260905000000_add_claims.sql (1.24ms)17532026/10/01 10:21:25 OK 20260920000000_drop_claims.sql (974.04µs)17542026/10/01 10:21:25 OK 20260923120000_add_pushes.sql (908.75µs)17552026/10/01 10:21:25 goose: successfully migrated database to version: 2026092312000017562026/10/01 10:21:25 OK 20241026095416_initial_model.sql (9.56ms)17572026/10/01 10:21:25 OK 20251210153512_drop_unused_gin_index.sql (914.58µs)17582026/10/01 10:21:25 OK 1_commit_pending_closure.sql (2.17ms)17592026/10/01 10:21:25 OK 2_object_stats_trigger.sql (583.13µs)17602026/10/01 10:21:25 OK 3_commit_push.sql (572.63µs)17612026/10/01 10:21:25 goose: up to current file version: 317622026/10/01 10:21:25 OK 20251218171726_add_pins.sql (2.61ms)17632026/10/01 10:21:25 OK 20260628120000_add_object_size_and_stats.sql (26.58ms)17642026/10/01 10:21:25 OK 20260905000000_add_claims.sql (15.95ms)17652026/10/01 10:21:25 OK 20260920000000_drop_claims.sql (31.71ms)17662026/10/01 10:21:25 OK 20260923120000_add_pushes.sql (3.85ms)17672026/10/01 10:21:25 goose: successfully migrated database to version: 2026092312000017682026/10/01 10:21:25 OK 1_commit_pending_closure.sql (2.77ms)17692026/10/01 10:21:25 OK 2_object_stats_trigger.sql (250.92µs)17702026/10/01 10:21:25 OK 3_commit_push.sql (230.96µs)17712026/10/01 10:21:25 goose: up to current file version: 317722026-10-01 10:21:25.404 UTC [27341] ERROR: relation "goose_db_version" does not exist at character 3617732026-10-01 10:21:25.404 UTC [27341] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17742026-10-01 10:21:25.428 UTC [27344] ERROR: relation "goose_db_version" does not exist at character 3617752026-10-01 10:21:25.428 UTC [27344] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1776--- PASS: TestGCEndsOnShutdown (1.84s)1777=== CONT TestClientIntegration17782026/10/01 10:21:25 OK 20241026095416_initial_model.sql (132.09ms)17792026/10/01 10:21:25 OK 20251210153512_drop_unused_gin_index.sql (14.62ms)17802026/10/01 10:21:25 OK 20251218171726_add_pins.sql (11.79ms)17812026/10/01 10:21:25 OK 20241026095416_initial_model.sql (157.96ms)17822026/10/01 10:21:25 OK 20251210153512_drop_unused_gin_index.sql (12.94ms)17832026/10/01 10:21:25 OK 20260628120000_add_object_size_and_stats.sql (43.83ms)17842026/10/01 10:21:25 OK 20251218171726_add_pins.sql (18.54ms)17852026/10/01 10:21:25 OK 20260905000000_add_claims.sql (33.13ms)17862026/10/01 10:21:25 OK 20260628120000_add_object_size_and_stats.sql (31.28ms)17872026/10/01 10:21:25 OK 20260920000000_drop_claims.sql (15.9ms)17882026/10/01 10:21:25 OK 20260923120000_add_pushes.sql (4.4ms)17892026/10/01 10:21:25 goose: successfully migrated database to version: 2026092312000017902026/10/01 10:21:25 OK 1_commit_pending_closure.sql (1.78ms)17912026/10/01 10:21:25 OK 2_object_stats_trigger.sql (395.42µs)17922026/10/01 10:21:25 OK 3_commit_push.sql (355.42µs)17932026/10/01 10:21:25 goose: up to current file version: 317942026-10-01 10:21:25.708 UTC [27359] ERROR: relation "goose_db_version" does not exist at character 3617952026-10-01 10:21:25.708 UTC [27359] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17962026/10/01 10:21:25 OK 20260905000000_add_claims.sql (29.2ms)17972026-10-01 10:21:25.731 UTC [27360] ERROR: relation "goose_db_version" does not exist at character 3617982026-10-01 10:21:25.731 UTC [27360] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17992026/10/01 10:21:25 OK 20260920000000_drop_claims.sql (22.9ms)18002026/10/01 10:21:25 OK 20260923120000_add_pushes.sql (11.72ms)18012026/10/01 10:21:25 goose: successfully migrated database to version: 2026092312000018022026/10/01 10:21:25 OK 1_commit_pending_closure.sql (2.88ms)18032026/10/01 10:21:25 OK 2_object_stats_trigger.sql (608.21µs)18042026/10/01 10:21:25 OK 3_commit_push.sql (349.88µs)18052026/10/01 10:21:25 goose: up to current file version: 318062026/10/01 10:21:25 OK 20241026095416_initial_model.sql (110.71ms)18072026/10/01 10:21:25 OK 20251210153512_drop_unused_gin_index.sql (21.04ms)18082026/10/01 10:21:25 OK 20251218171726_add_pins.sql (20.51ms)18092026/10/01 10:21:25 INFO Aborted multipart uploads count=0 kept=018102026/10/01 10:21:25 OK 20241026095416_initial_model.sql (141.79ms)18112026/10/01 10:21:25 WARN Force mode enabled - objects will be deleted immediately without grace period18122026/10/01 10:21:25 OK 20260628120000_add_object_size_and_stats.sql (32.55ms)18132026/10/01 10:21:25 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=018142026/10/01 10:21:25 OK 20251210153512_drop_unused_gin_index.sql (10.03ms)18152026/10/01 10:21:25 INFO Vacuumed table table=pending_closures18162026/10/01 10:21:25 INFO Vacuumed table table=pending_objects18172026/10/01 10:21:25 INFO Vacuumed table table=multipart_uploads18182026/10/01 10:21:25 OK 20251218171726_add_pins.sql (40.53ms)18192026/10/01 10:21:25 INFO Vacuumed table table=closures18202026/10/01 10:21:25 INFO Vacuumed table table=objects18212026/10/01 10:21:26 OK 20260905000000_add_claims.sql (67.1ms)18222026/10/01 10:21:26 OK 20260628120000_add_object_size_and_stats.sql (23.68ms)1823--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.08s)1824=== CONT TestClientErrorHandling1825=== RUN TestClientErrorHandling/InvalidStorePath1826=== PAUSE TestClientErrorHandling/InvalidStorePath1827=== RUN TestClientErrorHandling/InvalidAuthToken1828=== PAUSE TestClientErrorHandling/InvalidAuthToken1829=== RUN TestClientErrorHandling/ServerNotAvailable1830=== PAUSE TestClientErrorHandling/ServerNotAvailable1831=== CONT TestClientCADerivations18322026/10/01 10:21:26 OK 20260920000000_drop_claims.sql (10.58ms)18332026/10/01 10:21:26 OK 20260923120000_add_pushes.sql (8.02ms)18342026/10/01 10:21:26 goose: successfully migrated database to version: 2026092312000018352026/10/01 10:21:26 OK 1_commit_pending_closure.sql (1.39ms)18362026/10/01 10:21:26 OK 2_object_stats_trigger.sql (298.92µs)18372026/10/01 10:21:26 OK 3_commit_push.sql (178.71µs)18382026/10/01 10:21:26 goose: up to current file version: 318392026/10/01 10:21:26 OK 20260905000000_add_claims.sql (33.57ms)18402026/10/01 10:21:26 OK 20260920000000_drop_claims.sql (28.57ms)18412026/10/01 10:21:26 OK 20260923120000_add_pushes.sql (10.53ms)18422026/10/01 10:21:26 goose: successfully migrated database to version: 2026092312000018432026/10/01 10:21:26 INFO Received uploads request method=POST path=/api/pending_closures18442026/10/01 10:21:26 OK 1_commit_pending_closure.sql (4.22ms)18452026/10/01 10:21:26 OK 2_object_stats_trigger.sql (656.79µs)18462026/10/01 10:21:26 OK 3_commit_push.sql (472.33µs)18472026/10/01 10:21:26 goose: up to current file version: 318482026-10-01 10:21:26.136 UTC [27371] ERROR: relation "goose_db_version" does not exist at character 3618492026-10-01 10:21:26.136 UTC [27371] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18502026/10/01 10:21:26 OK 20241026095416_initial_model.sql (119.72ms)18512026/10/01 10:21:26 OK 20251210153512_drop_unused_gin_index.sql (15.68ms)18522026/10/01 10:21:26 OK 20251218171726_add_pins.sql (6.24ms)18532026/10/01 10:21:26 OK 20260628120000_add_object_size_and_stats.sql (40.57ms)18542026-10-01 10:21:26.342 UTC [27376] ERROR: relation "goose_db_version" does not exist at character 3618552026-10-01 10:21:26.342 UTC [27376] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18562026/10/01 10:21:26 INFO Aborted multipart uploads count=0 kept=018572026/10/01 10:21:26 WARN Force mode enabled - objects will be deleted immediately without grace period18582026/10/01 10:21:26 OK 20260905000000_add_claims.sql (38.43ms)18592026/10/01 10:21:26 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=018602026/10/01 10:21:26 OK 20260920000000_drop_claims.sql (23.58ms)18612026/10/01 10:21:26 INFO Vacuumed table table=pending_closures18622026/10/01 10:21:26 OK 20260923120000_add_pushes.sql (4.94ms)18632026/10/01 10:21:26 goose: successfully migrated database to version: 2026092312000018642026/10/01 10:21:26 INFO Vacuumed table table=pending_objects18652026/10/01 10:21:26 INFO Vacuumed table table=multipart_uploads18662026/10/01 10:21:26 INFO Vacuumed table table=closures18672026/10/01 10:21:26 OK 1_commit_pending_closure.sql (4.03ms)18682026/10/01 10:21:26 OK 2_object_stats_trigger.sql (633.46µs)18692026/10/01 10:21:26 OK 3_commit_push.sql (470.71µs)18702026/10/01 10:21:26 goose: up to current file version: 318712026/10/01 10:21:26 INFO Vacuumed table table=objects1872--- PASS: TestSweepRechecksPendingAfterLocking (2.27s)1873=== CONT TestService_RequireScope_OIDC18742026-10-01 10:21:26.448 UTC [27380] ERROR: relation "goose_db_version" does not exist at character 3618752026-10-01 10:21:26.448 UTC [27380] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18762026/10/01 10:21:26 OK 20241026095416_initial_model.sql (66.94ms)18772026/10/01 10:21:26 OK 20251210153512_drop_unused_gin_index.sql (7.57ms)18782026/10/01 10:21:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60282/oidc18792026/10/01 10:21:26 OK 20251218171726_add_pins.sql (6.69ms)18802026/10/01 10:21:26 OK 20260628120000_add_object_size_and_stats.sql (25.83ms)1881--- PASS: TestGetExistingObjectsLocksRows (2.27s)1882=== CONT TestService_AuthMiddleware_OIDC18832026/10/01 10:21:26 OK 20260905000000_add_claims.sql (38.1ms)18842026/10/01 10:21:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60287/oidc18852026/10/01 10:21:26 OK 20260920000000_drop_claims.sql (2.8ms)18862026/10/01 10:21:26 OK 20260923120000_add_pushes.sql (5.7ms)18872026/10/01 10:21:26 goose: successfully migrated database to version: 2026092312000018882026/10/01 10:21:26 OK 1_commit_pending_closure.sql (890.88µs)18892026/10/01 10:21:26 OK 2_object_stats_trigger.sql (194.83µs)18902026/10/01 10:21:26 OK 3_commit_push.sql (158.79µs)18912026/10/01 10:21:26 goose: up to current file version: 318922026/10/01 10:21:26 OK 20241026095416_initial_model.sql (81.19ms)1893--- PASS: TestPushWaitsForSweepHoldingRow (2.55s)1894=== CONT TestService_ReadAuthMiddleware18952026/10/01 10:21:26 OK 20251210153512_drop_unused_gin_index.sql (36.49ms)18962026/10/01 10:21:26 OK 20251218171726_add_pins.sql (17.3ms)18972026/10/01 10:21:26 OK 20260628120000_add_object_size_and_stats.sql (14.48ms)18982026/10/01 10:21:26 OK 20260905000000_add_claims.sql (20.79ms)18992026/10/01 10:21:26 OK 20260920000000_drop_claims.sql (19.61ms)1900--- PASS: TestRegisterCompletedObjectNeedsPendingRow (2.37s)1901=== CONT TestCacheStatsHandler19022026/10/01 10:21:26 OK 20260923120000_add_pushes.sql (12.11ms)19032026/10/01 10:21:26 goose: successfully migrated database to version: 2026092312000019042026/10/01 10:21:26 OK 1_commit_pending_closure.sql (944.29µs)19052026/10/01 10:21:26 OK 2_object_stats_trigger.sql (204.83µs)19062026/10/01 10:21:26 OK 3_commit_push.sql (138.13µs)19072026/10/01 10:21:26 goose: up to current file version: 319082026/10/01 10:21:26 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=019092026/10/01 10:21:26 INFO Received create pin request method=POST path=/api/pins/myapp19102026/10/01 10:21:26 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-26883-1285942671/TestPinProtectsFromGC2443368751/001/store/hx2ac2i9yhcf41bc7ra3ngfcwvxnh954-pinned-file.txt narinfo_key=hx2ac2i9yhcf41bc7ra3ngfcwvxnh954.narinfo19112026/10/01 10:21:26 INFO Starting cleanup of old closures method=DELETE path=/api/closures19122026/10/01 10:21:26 INFO Garbage collection started19132026/10/01 10:21:26 INFO Aborted multipart uploads count=0 kept=019142026/10/01 10:21:26 WARN Force mode enabled - objects will be deleted immediately without grace period19152026/10/01 10:21:26 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=019162026/10/01 10:21:26 INFO Vacuumed table table=pending_closures19172026/10/01 10:21:26 INFO Vacuumed table table=pending_objects19182026/10/01 10:21:26 INFO Vacuumed table table=multipart_uploads19192026/10/01 10:21:26 INFO Vacuumed table table=closures19202026/10/01 10:21:26 INFO Vacuumed table table=objects19212026-10-01 10:21:26.777 UTC [27424] ERROR: relation "goose_db_version" does not exist at character 3619222026-10-01 10:21:26.777 UTC [27424] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19232026/10/01 10:21:26 INFO Aborted multipart uploads count=0 kept=019242026/10/01 10:21:26 WARN Force mode enabled - objects will be deleted immediately without grace period19252026/10/01 10:21:26 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=019262026/10/01 10:21:26 INFO Vacuumed table table=pending_closures19272026/10/01 10:21:26 INFO Vacuumed table table=pending_objects19282026/10/01 10:21:26 INFO Vacuumed table table=multipart_uploads19292026/10/01 10:21:26 INFO Vacuumed table table=closures19302026/10/01 10:21:26 INFO Vacuumed table table=objects19312026/10/01 10:21:26 OK 20241026095416_initial_model.sql (102.67ms)19322026/10/01 10:21:26 OK 20251210153512_drop_unused_gin_index.sql (10ms)19332026/10/01 10:21:26 INFO Aborted multipart uploads count=0 kept=019342026/10/01 10:21:26 WARN Force mode enabled - objects will be deleted immediately without grace period19352026/10/01 10:21:26 OK 20251218171726_add_pins.sql (13.77ms)19362026/10/01 10:21:26 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=019372026/10/01 10:21:26 INFO Vacuumed table table=pending_closures19382026/10/01 10:21:26 INFO Vacuumed table table=pending_objects19392026/10/01 10:21:26 INFO Vacuumed table table=multipart_uploads19402026/10/01 10:21:26 INFO Vacuumed table table=closures19412026/10/01 10:21:26 INFO Vacuumed table table=objects1942--- PASS: TestSweepSkipsRowsLockedByPush (2.06s)1943=== CONT TestService_AuthMiddleware_MTLSBoundSubjects19442026/10/01 10:21:26 OK 20260628120000_add_object_size_and_stats.sql (35.36ms)19452026/10/01 10:21:26 OK 20260905000000_add_claims.sql (23.47ms)19462026/10/01 10:21:27 OK 20260920000000_drop_claims.sql (37.2ms)19472026/10/01 10:21:27 OK 20260923120000_add_pushes.sql (18.48ms)19482026/10/01 10:21:27 goose: successfully migrated database to version: 2026092312000019492026/10/01 10:21:27 OK 1_commit_pending_closure.sql (1.3ms)19502026/10/01 10:21:27 OK 2_object_stats_trigger.sql (249.33µs)19512026/10/01 10:21:27 OK 3_commit_push.sql (187.63µs)19522026/10/01 10:21:27 goose: up to current file version: 319532026-10-01 10:21:27.247 UTC [27440] ERROR: relation "goose_db_version" does not exist at character 3619542026-10-01 10:21:27.247 UTC [27440] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1955=== NAME TestClientMultipleUploads1956 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-26883-1285942671/TestClientMultipleUploads316354710/001/store/618v081sbymp6xnjix8afidficlga0qh-test-file-0.txt19572026/10/01 10:21:27 OK 20241026095416_initial_model.sql (154.69ms)19582026/10/01 10:21:27 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)1959=== NAME TestClientWithDependencies1960 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-26883-1285942671/TestClientWithDependencies186653250/001/store/xwymh9zl1n8pzif3mydm7r5ipb4jn17q-test-script19612026/10/01 10:21:27 OK 20251218171726_add_pins.sql (20.42ms)19622026/10/01 10:21:27 OK 20260628120000_add_object_size_and_stats.sql (16.54ms)1963=== NAME TestClientMultipleUploads1964 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-26883-1285942671/TestClientMultipleUploads316354710/001/store/rbg3gfrrmab59gpya69gr4z8xkh0x6y3-test-file-1.txt1965=== NAME TestClientWithDependencies1966 client_integration_test.go:615: Found 1 dependencies (including self)19672026/10/01 10:21:27 OK 20260905000000_add_claims.sql (34.92ms)19682026/10/01 10:21:27 OK 20260920000000_drop_claims.sql (19.14ms)1969=== NAME TestClientMultipleUploads1970 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-26883-1285942671/TestClientMultipleUploads316354710/001/store/sqcw8lmcy7lxcsrkki9xj0914fzzlciz-test-file-2.txt19712026/10/01 10:21:27 OK 20260923120000_add_pushes.sql (9.02ms)19722026/10/01 10:21:27 goose: successfully migrated database to version: 2026092312000019732026/10/01 10:21:27 OK 1_commit_pending_closure.sql (1.65ms)19742026/10/01 10:21:27 OK 2_object_stats_trigger.sql (246.38µs)19752026/10/01 10:21:27 OK 3_commit_push.sql (181.46µs)19762026/10/01 10:21:27 goose: up to current file version: 319772026/10/01 10:21:27 INFO Received push request method=POST path=/api/pushes19782026/10/01 10:21:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19792026/10/01 10:21:27 INFO Uploading xwymh9zl1n8pzif3mydm7r5ipb4jn17q-test-script (136B)19802026/10/01 10:21:27 INFO Received push request method=POST path=/api/pushes19812026/10/01 10:21:27 WARN Failed to register uploaded object key=xwymh9zl1n8pzif3mydm7r5ipb4jn17q.ls error="server returned 404: 404 page not found\n"19822026/10/01 10:21:27 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"19832026/10/01 10:21:27 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19842026/10/01 10:21:27 INFO Uploading sqcw8lmcy7lxcsrkki9xj0914fzzlciz-test-file-2.txt (160B)19852026/10/01 10:21:27 INFO Uploading 618v081sbymp6xnjix8afidficlga0qh-test-file-0.txt (160B)19862026/10/01 10:21:27 INFO Uploading rbg3gfrrmab59gpya69gr4z8xkh0x6y3-test-file-1.txt (160B)19872026/10/01 10:21:27 WARN Failed to register uploaded object key=log/psf66brywaldj8ws6kg2dmlfm0qxb1if-test-script.drv error="server returned 404: 404 page not found\n"19882026/10/01 10:21:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19892026/10/01 10:21:27 INFO Signed narinfos id=1 count=119902026/10/01 10:21:27 INFO Uploading 1 narinfos19912026/10/01 10:21:27 WARN Failed to register uploaded object key=rbg3gfrrmab59gpya69gr4z8xkh0x6y3.ls error="server returned 404: 404 page not found\n"19922026/10/01 10:21:27 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19932026/10/01 10:21:27 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19942026/10/01 10:21:27 WARN Failed to register uploaded object key=618v081sbymp6xnjix8afidficlga0qh.ls error="server returned 404: 404 page not found\n"19952026/10/01 10:21:27 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19962026/10/01 10:21:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19972026/10/01 10:21:27 WARN Failed to register uploaded object key=sqcw8lmcy7lxcsrkki9xj0914fzzlciz.ls error="server returned 404: 404 page not found\n"19982026/10/01 10:21:27 INFO Signed narinfos id=1 count=319992026/10/01 10:21:27 INFO Uploading 3 narinfos20002026/10/01 10:21:27 INFO Received complete push request method=POST path=/api/pushes/1/complete20012026/10/01 10:21:27 WARN Failed to register uploaded object key=xwymh9zl1n8pzif3mydm7r5ipb4jn17q.narinfo error="server returned 404: 404 page not found\n"20022026/10/01 10:21:27 WARN Failed to register uploaded object key=rbg3gfrrmab59gpya69gr4z8xkh0x6y3.narinfo error="server returned 404: 404 page not found\n"20032026/10/01 10:21:27 INFO Upload complete. (170ms)2004=== NAME TestClientWithDependencies2005 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-26883-1285942671/TestClientWithDependencies186653250/001/store) requires matching store prefix20062026/10/01 10:21:27 WARN Failed to register uploaded object key=618v081sbymp6xnjix8afidficlga0qh.narinfo error="server returned 404: 404 page not found\n"20072026/10/01 10:21:27 INFO Received complete push request method=POST path=/api/pushes/1/complete20082026/10/01 10:21:27 WARN Failed to register uploaded object key=sqcw8lmcy7lxcsrkki9xj0914fzzlciz.narinfo error="server returned 404: 404 page not found\n"2009=== NAME TestClientIntegration2010 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-26883-1285942671/TestClientIntegration3583302944/002/store/pvbkf3yjfrycicblqcd8v732rdyd4c5x-test-file.txt20112026/10/01 10:21:27 INFO Upload complete. (138ms)2012=== NAME TestClientMultipleUploads2013 client_integration_test.go:369: Uploaded 3 paths in 174.112042ms2014--- PASS: TestClientWithDependencies (2.73s)2015=== CONT TestCacheConfigHandler2016=== RUN TestCacheConfigHandler/full_config,_no_issuer2017=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2018=== RUN TestCacheConfigHandler/no_cache_url_configured2019=== PAUSE TestCacheConfigHandler/no_cache_url_configured2020=== RUN TestCacheConfigHandler/no_signing_keys2021=== PAUSE TestCacheConfigHandler/no_signing_keys2022=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2023=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2024=== CONT TestService_AuthMiddleware_MTLSProxyHeader2025--- PASS: TestClientMultipleUploads (2.65s)2026=== CONT TestService_ReadScope_PublicByDefault20272026/10/01 10:21:27 INFO Received push request method=POST path=/api/pushes20282026-10-01 10:21:27.841 UTC [27493] ERROR: relation "goose_db_version" does not exist at character 3620292026-10-01 10:21:27.841 UTC [27493] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20302026/10/01 10:21:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20312026/10/01 10:21:27 INFO Uploading pvbkf3yjfrycicblqcd8v732rdyd4c5x-test-file.txt (152B)20322026/10/01 10:21:27 WARN Failed to register uploaded object key=pvbkf3yjfrycicblqcd8v732rdyd4c5x.ls error="server returned 404: 404 page not found\n"20332026/10/01 10:21:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20342026/10/01 10:21:27 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"20352026/10/01 10:21:27 INFO Signed narinfos id=1 count=120362026/10/01 10:21:27 INFO Uploading 1 narinfos20372026/10/01 10:21:27 INFO Received complete push request method=POST path=/api/pushes/1/complete20382026/10/01 10:21:27 WARN Failed to register uploaded object key=pvbkf3yjfrycicblqcd8v732rdyd4c5x.narinfo error="server returned 404: 404 page not found\n"20392026/10/01 10:21:27 INFO Upload complete. (124ms)20402026-10-01 10:21:27.915 UTC [27497] ERROR: relation "goose_db_version" does not exist at character 3620412026-10-01 10:21:27.915 UTC [27497] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20422026/10/01 10:21:27 INFO All 1 paths already cached20432026-10-01 10:21:27.928 UTC [27499] ERROR: relation "goose_db_version" does not exist at character 3620442026-10-01 10:21:27.928 UTC [27499] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2045=== NAME TestClientIntegration2046 client_integration_test.go:312: Retrieved narinfo from S3:2047 StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestClientIntegration3583302944/002/store/pvbkf3yjfrycicblqcd8v732rdyd4c5x-test-file.txt2048 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2049 Compression: zstd2050 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12051 NarSize: 1522052 References: 2053 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12054 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2055 client_integration_test.go:313: Decompressed .ls content (64 bytes):2056 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2057 client_integration_test.go:316: Testing garbage collection...20582026/10/01 10:21:27 OK 20241026095416_initial_model.sql (70.09ms)20592026/10/01 10:21:27 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)20602026/10/01 10:21:27 OK 20251218171726_add_pins.sql (2.25ms)20612026-10-01 10:21:27.951 UTC [27502] ERROR: relation "goose_db_version" does not exist at character 3620622026-10-01 10:21:27.951 UTC [27502] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20632026/10/01 10:21:27 OK 20260628120000_add_object_size_and_stats.sql (4.31ms)20642026/10/01 10:21:27 OK 20241026095416_initial_model.sql (12.38ms)20652026/10/01 10:21:27 OK 20260905000000_add_claims.sql (3.98ms)20662026/10/01 10:21:27 OK 20251210153512_drop_unused_gin_index.sql (1.1ms)20672026/10/01 10:21:27 OK 20241026095416_initial_model.sql (9.8ms)20682026/10/01 10:21:27 OK 20260920000000_drop_claims.sql (1.87ms)20692026/10/01 10:21:27 OK 20251210153512_drop_unused_gin_index.sql (899.67µs)20702026/10/01 10:21:27 OK 20260923120000_add_pushes.sql (954.75µs)20712026/10/01 10:21:27 goose: successfully migrated database to version: 2026092312000020722026/10/01 10:21:27 OK 1_commit_pending_closure.sql (2.3ms)20732026/10/01 10:21:27 OK 2_object_stats_trigger.sql (564.46µs)20742026/10/01 10:21:27 OK 3_commit_push.sql (314.33µs)20752026/10/01 10:21:27 goose: up to current file version: 320762026/10/01 10:21:27 OK 20251218171726_add_pins.sql (8.04ms)20772026/10/01 10:21:27 OK 20251218171726_add_pins.sql (9.67ms)20782026/10/01 10:21:27 INFO Starting cleanup of old closures method=DELETE path=/api/closures20792026/10/01 10:21:27 INFO Garbage collection started20802026/10/01 10:21:27 INFO Aborted multipart uploads count=0 kept=020812026/10/01 10:21:27 OK 20260628120000_add_object_size_and_stats.sql (19.16ms)20822026/10/01 10:21:27 WARN Force mode enabled - objects will be deleted immediately without grace period20832026/10/01 10:21:27 OK 20260628120000_add_object_size_and_stats.sql (29.33ms)20842026/10/01 10:21:28 OK 20260905000000_add_claims.sql (26.49ms)20852026/10/01 10:21:28 OK 20260905000000_add_claims.sql (23.81ms)20862026/10/01 10:21:28 OK 20260920000000_drop_claims.sql (8.43ms)20872026-10-01 10:21:28.020 UTC [27541] ERROR: relation "goose_db_version" does not exist at character 3620882026-10-01 10:21:28.020 UTC [27541] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20892026/10/01 10:21:28 OK 20260923120000_add_pushes.sql (1.32ms)20902026/10/01 10:21:28 goose: successfully migrated database to version: 2026092312000020912026/10/01 10:21:28 OK 20260920000000_drop_claims.sql (2.53ms)20922026/10/01 10:21:28 OK 1_commit_pending_closure.sql (1.54ms)20932026/10/01 10:21:28 OK 2_object_stats_trigger.sql (212.33µs)20942026/10/01 10:21:28 OK 3_commit_push.sql (757.38µs)20952026/10/01 10:21:28 goose: up to current file version: 320962026/10/01 10:21:28 OK 20260923120000_add_pushes.sql (8.34ms)20972026/10/01 10:21:28 goose: successfully migrated database to version: 2026092312000020982026/10/01 10:21:28 OK 1_commit_pending_closure.sql (1.25ms)20992026/10/01 10:21:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=021002026/10/01 10:21:28 OK 2_object_stats_trigger.sql (202.17µs)21012026/10/01 10:21:28 OK 3_commit_push.sql (151.42µs)21022026/10/01 10:21:28 goose: up to current file version: 321032026/10/01 10:21:28 OK 20241026095416_initial_model.sql (71.61ms)21042026/10/01 10:21:28 OK 20251210153512_drop_unused_gin_index.sql (5.83ms)21052026/10/01 10:21:28 INFO Vacuumed table table=pending_closures21062026/10/01 10:21:28 OK 20251218171726_add_pins.sql (31.01ms)21072026/10/01 10:21:28 INFO Vacuumed table table=pending_objects21082026/10/01 10:21:28 INFO Vacuumed table table=multipart_uploads21092026/10/01 10:21:28 INFO Vacuumed table table=closures21102026/10/01 10:21:28 OK 20260628120000_add_object_size_and_stats.sql (23.02ms)21112026/10/01 10:21:28 INFO Vacuumed table table=objects21122026/10/01 10:21:28 OK 20260905000000_add_claims.sql (24.21ms)21132026/10/01 10:21:28 OK 20260920000000_drop_claims.sql (20.32ms)21142026/10/01 10:21:28 OK 20260923120000_add_pushes.sql (10.93ms)21152026/10/01 10:21:28 goose: successfully migrated database to version: 2026092312000021162026/10/01 10:21:28 OK 20241026095416_initial_model.sql (93.36ms)21172026/10/01 10:21:28 OK 1_commit_pending_closure.sql (863.17µs)21182026/10/01 10:21:28 OK 2_object_stats_trigger.sql (190.42µs)21192026/10/01 10:21:28 OK 3_commit_push.sql (130.17µs)21202026/10/01 10:21:28 goose: up to current file version: 321212026/10/01 10:21:28 OK 20251210153512_drop_unused_gin_index.sql (10.47ms)21222026/10/01 10:21:28 OK 20251218171726_add_pins.sql (7.98ms)2123=== NAME TestClientCADerivations2124 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-26883-1285942671/TestClientCADerivations966751329/001/store/zgimr6x5562i1rpv0f6z9jzsc8sms4l2-ca-test2125=== RUN TestService_RequireScope_OIDC/builder_may_write2126=== PAUSE TestService_RequireScope_OIDC/builder_may_write2127=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2128=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2129=== RUN TestService_RequireScope_OIDC/ops_may_admin2130=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2131=== RUN TestService_RequireScope_OIDC/ops_may_not_write2132=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2133=== RUN TestService_RequireScope_OIDC/reader_may_not_write2134=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2135=== RUN TestService_RequireScope_OIDC/static_token_may_admin2136=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2137=== RUN TestService_RequireScope_OIDC/static_token_may_write2138=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2139=== RUN TestService_RequireScope_OIDC/reader_may_read2140=== PAUSE TestService_RequireScope_OIDC/reader_may_read2141=== RUN TestService_RequireScope_OIDC/writer_implies_read2142=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2143=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2144=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2145=== CONT TestPresignedUploadRegisteredBeforeCommit21462026/10/01 10:21:28 OK 20260628120000_add_object_size_and_stats.sql (34.27ms)2147=== NAME TestClientCADerivations2148 client_ca_test.go:139: Found 1 dependencies (including self)21492026/10/01 10:21:28 OK 20260905000000_add_claims.sql (16.23ms)21502026/10/01 10:21:28 OK 20260920000000_drop_claims.sql (14.64ms)21512026/10/01 10:21:28 OK 20260923120000_add_pushes.sql (7.32ms)21522026/10/01 10:21:28 goose: successfully migrated database to version: 2026092312000021532026/10/01 10:21:28 OK 1_commit_pending_closure.sql (3.26ms)21542026/10/01 10:21:28 OK 2_object_stats_trigger.sql (242.96µs)21552026/10/01 10:21:28 OK 3_commit_push.sql (172.92µs)21562026/10/01 10:21:28 goose: up to current file version: 32157=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2158=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2159=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2160=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2161=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2162=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2163=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2164=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2165=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle21662026/10/01 10:21:28 INFO Received push request method=POST path=/api/pushes21672026/10/01 10:21:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21682026/10/01 10:21:28 INFO Uploading zgimr6x5562i1rpv0f6z9jzsc8sms4l2-ca-test (144B)21692026/10/01 10:21:28 WARN Failed to register uploaded object key=zgimr6x5562i1rpv0f6z9jzsc8sms4l2.ls error="server returned 404: 404 page not found\n"21702026/10/01 10:21:28 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"21712026/10/01 10:21:28 WARN Failed to register uploaded object key=log/71v853gay2mf6xl5n07z2b6kwg8iylsa-ca-test.drv error="server returned 404: 404 page not found\n"21722026/10/01 10:21:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21732026/10/01 10:21:28 INFO Signed narinfos id=1 count=121742026/10/01 10:21:28 INFO Uploading 1 narinfos21752026/10/01 10:21:28 INFO Received complete push request method=POST path=/api/pushes/1/complete21762026/10/01 10:21:28 WARN Failed to register uploaded object key=zgimr6x5562i1rpv0f6z9jzsc8sms4l2.narinfo error="server returned 404: 404 page not found\n"21772026/10/01 10:21:28 INFO Upload complete. (203ms)2178=== NAME TestClientCADerivations2179 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-26883-1285942671/TestClientCADerivations966751329/001/store/zgimr6x5562i1rpv0f6z9jzsc8sms4l2-ca-test2180 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2181 Compression: zstd2182 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2183 NarSize: 1442184 References: 2185 Deriver: /nix/var/nix/builds/nix-26883-1285942671/TestClientCADerivations966751329/001/store/71v853gay2mf6xl5n07z2b6kwg8iylsa-ca-test.drv2186 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2187 client_ca_test.go:185: Checking for realisation files in S3...2188 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2189 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2190--- PASS: TestService_ReadAuthMiddleware (1.93s)2191=== CONT TestSkippedUploadsHandler21922026/10/01 10:21:28 INFO Client skipped oversized paths paths=3 nar_bytes=50000000002193--- PASS: TestSkippedUploadsHandler (0.00s)2194=== CONT TestParseSize2195--- PASS: TestParseSize (0.00s)2196=== CONT TestService_Rustfstest2197=== NAME TestClientCADerivations2198 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket50?endpoint=http://localhost:60087®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-26883-1285942671/TestClientCADerivations966751329/001/store'2199 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12200--- PASS: TestClientCADerivations (2.61s)2201=== CONT TestService_verifyS3Integrity2202=== NAME TestPinProtectsFromGC2203 client_integration_test.go:840: Pin successfully protected closure from garbage collection2204--- PASS: TestCacheStatsHandler (2.06s)2205=== CONT TestReadProxy4042206--- PASS: TestPinProtectsFromGC (7.62s)2207=== CONT TestReadProxyInvalidPath22082026/10/01 10:21:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"22092026/10/01 10:21:28 WARN mTLS auth: bound subjects configured but subject DN unavailable22102026/10/01 10:21:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2211--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (1.94s)2212=== CONT TestReadProxyNarStreaming22132026-10-01 10:21:28.889 UTC [27594] ERROR: relation "goose_db_version" does not exist at character 3622142026-10-01 10:21:28.889 UTC [27594] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22152026-10-01 10:21:28.914 UTC [27597] ERROR: relation "goose_db_version" does not exist at character 3622162026-10-01 10:21:28.914 UTC [27597] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22172026/10/01 10:21:28 OK 20241026095416_initial_model.sql (14.97ms)22182026/10/01 10:21:28 OK 20251210153512_drop_unused_gin_index.sql (1.11ms)22192026/10/01 10:21:28 OK 20241026095416_initial_model.sql (11.32ms)22202026/10/01 10:21:28 OK 20251218171726_add_pins.sql (1.87ms)22212026/10/01 10:21:28 OK 20251210153512_drop_unused_gin_index.sql (616.38µs)22222026/10/01 10:21:28 OK 20251218171726_add_pins.sql (2.34ms)22232026/10/01 10:21:28 OK 20260628120000_add_object_size_and_stats.sql (3.86ms)22242026/10/01 10:21:28 OK 20260905000000_add_claims.sql (4.11ms)22252026/10/01 10:21:28 OK 20260628120000_add_object_size_and_stats.sql (5.37ms)22262026/10/01 10:21:28 OK 20260920000000_drop_claims.sql (803.21µs)22272026/10/01 10:21:28 OK 20260923120000_add_pushes.sql (1.12ms)22282026/10/01 10:21:28 goose: successfully migrated database to version: 2026092312000022292026/10/01 10:21:28 OK 1_commit_pending_closure.sql (925.17µs)22302026/10/01 10:21:28 OK 2_object_stats_trigger.sql (195.63µs)22312026/10/01 10:21:28 OK 3_commit_push.sql (281.04µs)22322026/10/01 10:21:28 goose: up to current file version: 322332026/10/01 10:21:28 OK 20260905000000_add_claims.sql (4ms)22342026/10/01 10:21:28 OK 20260920000000_drop_claims.sql (1.59ms)22352026/10/01 10:21:28 OK 20260923120000_add_pushes.sql (2.3ms)22362026/10/01 10:21:28 goose: successfully migrated database to version: 2026092312000022372026/10/01 10:21:28 OK 1_commit_pending_closure.sql (977.21µs)22382026/10/01 10:21:28 OK 2_object_stats_trigger.sql (227.42µs)22392026/10/01 10:21:28 OK 3_commit_push.sql (157.08µs)22402026/10/01 10:21:28 goose: up to current file version: 32241--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (1.31s)2242=== CONT TestReadProxyRangeRequest2243--- PASS: TestService_ReadScope_PublicByDefault (1.45s)2244=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit22452026-10-01 10:21:29.309 UTC [27609] ERROR: relation "goose_db_version" does not exist at character 3622462026-10-01 10:21:29.309 UTC [27609] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22472026/10/01 10:21:29 OK 20241026095416_initial_model.sql (21.37ms)22482026/10/01 10:21:29 OK 20251210153512_drop_unused_gin_index.sql (871.04µs)22492026/10/01 10:21:29 OK 20251218171726_add_pins.sql (2.49ms)22502026-10-01 10:21:29.360 UTC [27611] ERROR: relation "goose_db_version" does not exist at character 3622512026-10-01 10:21:29.360 UTC [27611] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22522026-10-01 10:21:29.361 UTC [27610] ERROR: relation "goose_db_version" does not exist at character 3622532026-10-01 10:21:29.361 UTC [27610] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22542026/10/01 10:21:29 OK 20260628120000_add_object_size_and_stats.sql (11.67ms)22552026/10/01 10:21:29 OK 20260905000000_add_claims.sql (9.07ms)22562026/10/01 10:21:29 OK 20260920000000_drop_claims.sql (3.11ms)22572026/10/01 10:21:29 OK 20260923120000_add_pushes.sql (4.55ms)22582026/10/01 10:21:29 goose: successfully migrated database to version: 2026092312000022592026/10/01 10:21:29 OK 1_commit_pending_closure.sql (5.17ms)22602026/10/01 10:21:29 OK 2_object_stats_trigger.sql (630.58µs)22612026/10/01 10:21:29 OK 3_commit_push.sql (4.38ms)22622026/10/01 10:21:29 goose: up to current file version: 322632026/10/01 10:21:29 OK 20241026095416_initial_model.sql (13.56ms)22642026/10/01 10:21:29 OK 20251210153512_drop_unused_gin_index.sql (411.71µs)22652026/10/01 10:21:29 OK 20251218171726_add_pins.sql (856.46µs)22662026/10/01 10:21:29 OK 20260628120000_add_object_size_and_stats.sql (33.1ms)22672026/10/01 10:21:29 OK 20241026095416_initial_model.sql (73.51ms)22682026/10/01 10:21:29 OK 20251210153512_drop_unused_gin_index.sql (2.59ms)22692026/10/01 10:21:29 OK 20260905000000_add_claims.sql (29.58ms)22702026/10/01 10:21:29 OK 20251218171726_add_pins.sql (3.64ms)22712026/10/01 10:21:29 OK 20260920000000_drop_claims.sql (4.53ms)22722026/10/01 10:21:29 OK 20260923120000_add_pushes.sql (7.74ms)22732026/10/01 10:21:29 goose: successfully migrated database to version: 2026092312000022742026/10/01 10:21:29 OK 1_commit_pending_closure.sql (902.38µs)22752026/10/01 10:21:29 OK 2_object_stats_trigger.sql (691.71µs)22762026/10/01 10:21:29 OK 3_commit_push.sql (192.83µs)22772026/10/01 10:21:29 goose: up to current file version: 322782026/10/01 10:21:29 OK 20260628120000_add_object_size_and_stats.sql (22.61ms)22792026/10/01 10:21:29 OK 20260905000000_add_claims.sql (29.08ms)22802026/10/01 10:21:29 OK 20260920000000_drop_claims.sql (15.25ms)22812026/10/01 10:21:29 OK 20260923120000_add_pushes.sql (8.18ms)22822026/10/01 10:21:29 goose: successfully migrated database to version: 2026092312000022832026/10/01 10:21:29 OK 1_commit_pending_closure.sql (1.36ms)22842026/10/01 10:21:29 OK 2_object_stats_trigger.sql (218.04µs)22852026/10/01 10:21:29 OK 3_commit_push.sql (159.75µs)22862026/10/01 10:21:29 goose: up to current file version: 322872026-10-01 10:21:29.556 UTC [27618] ERROR: relation "goose_db_version" does not exist at character 3622882026-10-01 10:21:29.556 UTC [27618] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22892026/10/01 10:21:29 INFO Received uploads request method=POST path=/api/pending_closures22902026/10/01 10:21:29 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst22912026/10/01 10:21:29 INFO Received uploads request method=POST path=/api/pending_closures2292--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.48s)2293=== CONT TestCompleteMultipartUnregistered22942026/10/01 10:21:29 OK 20241026095416_initial_model.sql (113.22ms)22952026/10/01 10:21:29 OK 20251210153512_drop_unused_gin_index.sql (3.76ms)22962026/10/01 10:21:29 OK 20251218171726_add_pins.sql (15.72ms)22972026/10/01 10:21:29 OK 20260628120000_add_object_size_and_stats.sql (28.53ms)22982026/10/01 10:21:29 OK 20260905000000_add_claims.sql (30.12ms)22992026-10-01 10:21:29.792 UTC [27706] ERROR: relation "goose_db_version" does not exist at character 3623002026-10-01 10:21:29.792 UTC [27706] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23012026/10/01 10:21:29 OK 20260920000000_drop_claims.sql (21.58ms)23022026/10/01 10:21:29 OK 20260923120000_add_pushes.sql (13.33ms)23032026/10/01 10:21:29 goose: successfully migrated database to version: 202609231200002304--- PASS: TestService_Rustfstest (1.30s)2305=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT23062026/10/01 10:21:29 OK 1_commit_pending_closure.sql (3.41ms)23072026/10/01 10:21:29 OK 2_object_stats_trigger.sql (741.75µs)23082026/10/01 10:21:29 OK 3_commit_push.sql (895.75µs)23092026/10/01 10:21:29 goose: up to current file version: 323102026-10-01 10:21:29.891 UTC [27745] ERROR: relation "goose_db_version" does not exist at character 3623112026-10-01 10:21:29.891 UTC [27745] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23122026/10/01 10:21:29 OK 20241026095416_initial_model.sql (107.18ms)23132026/10/01 10:21:29 OK 20251210153512_drop_unused_gin_index.sql (3.54ms)23142026/10/01 10:21:29 OK 20251218171726_add_pins.sql (17.89ms)23152026-10-01 10:21:29.971 UTC [27763] ERROR: relation "goose_db_version" does not exist at character 3623162026-10-01 10:21:29.971 UTC [27763] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23172026/10/01 10:21:29 OK 20260628120000_add_object_size_and_stats.sql (16.26ms)23182026/10/01 10:21:29 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02319=== NAME TestClientIntegration2320 client_integration_test.go:323: Objects in database after GC:23212026/10/01 10:21:29 OK 20241026095416_initial_model.sql (71.68ms)2322 client_integration_test.go:323: Successfully deleted all objects with GC --force23232026/10/01 10:21:29 OK 20251210153512_drop_unused_gin_index.sql (5.6ms)23242026/10/01 10:21:29 OK 20260905000000_add_claims.sql (18.2ms)2325--- PASS: TestClientIntegration (4.45s)2326=== CONT TestPush_CompleteCommitsEveryRoot23272026/10/01 10:21:30 OK 20251218171726_add_pins.sql (18.74ms)23282026/10/01 10:21:30 OK 20260920000000_drop_claims.sql (26.42ms)23292026/10/01 10:21:30 OK 20260628120000_add_object_size_and_stats.sql (23.01ms)23302026/10/01 10:21:30 OK 20260923120000_add_pushes.sql (19.99ms)23312026/10/01 10:21:30 goose: successfully migrated database to version: 2026092312000023322026/10/01 10:21:30 OK 1_commit_pending_closure.sql (1.42ms)23332026/10/01 10:21:30 OK 2_object_stats_trigger.sql (336.96µs)23342026/10/01 10:21:30 OK 3_commit_push.sql (182.33µs)23352026/10/01 10:21:30 goose: up to current file version: 323362026/10/01 10:21:30 OK 20260905000000_add_claims.sql (46.34ms)23372026/10/01 10:21:30 INFO Received uploads request method=POST path=/api/pending_closures23382026/10/01 10:21:30 OK 20260920000000_drop_claims.sql (51.7ms)23392026/10/01 10:21:30 OK 20241026095416_initial_model.sql (143.48ms)23402026/10/01 10:21:30 OK 20260923120000_add_pushes.sql (23.83ms)23412026/10/01 10:21:30 goose: successfully migrated database to version: 2026092312000023422026/10/01 10:21:30 OK 1_commit_pending_closure.sql (1.17ms)23432026/10/01 10:21:30 OK 2_object_stats_trigger.sql (226.21µs)23442026/10/01 10:21:30 OK 3_commit_push.sql (173.83µs)23452026/10/01 10:21:30 goose: up to current file version: 323462026/10/01 10:21:30 OK 20251210153512_drop_unused_gin_index.sql (4.16ms)23472026/10/01 10:21:30 OK 20251218171726_add_pins.sql (16.61ms)23482026/10/01 10:21:30 OK 20260628120000_add_object_size_and_stats.sql (36.68ms)23492026/10/01 10:21:30 OK 20260905000000_add_claims.sql (66.84ms)23502026/10/01 10:21:30 OK 20260920000000_drop_claims.sql (31.18ms)23512026/10/01 10:21:30 OK 20260923120000_add_pushes.sql (17.37ms)23522026/10/01 10:21:30 goose: successfully migrated database to version: 2026092312000023532026/10/01 10:21:30 OK 1_commit_pending_closure.sql (1.08ms)23542026/10/01 10:21:30 OK 2_object_stats_trigger.sql (261.38µs)23552026/10/01 10:21:30 OK 3_commit_push.sql (216.08µs)23562026/10/01 10:21:30 goose: up to current file version: 323572026/10/01 10:21:30 INFO Received uploads request method=POST path=/api/pending_closures23582026/10/01 10:21:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23592026-10-01 10:21:30.478 UTC [27821] ERROR: relation "goose_db_version" does not exist at character 3623602026-10-01 10:21:30.478 UTC [27821] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2361--- PASS: TestReadProxyInvalidPath (1.90s)2362=== CONT TestCompleteMultipartUpload_ErrorButObjectExists23632026/10/01 10:21:30 OK 20241026095416_initial_model.sql (146.86ms)23642026/10/01 10:21:30 OK 20251210153512_drop_unused_gin_index.sql (13.82ms)23652026/10/01 10:21:30 OK 20251218171726_add_pins.sql (48.69ms)23662026/10/01 10:21:30 OK 20260628120000_add_object_size_and_stats.sql (34.45ms)23672026/10/01 10:21:30 OK 20260905000000_add_claims.sql (50.1ms)23682026-10-01 10:21:30.837 UTC [27824] ERROR: relation "goose_db_version" does not exist at character 3623692026-10-01 10:21:30.837 UTC [27824] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23702026/10/01 10:21:30 OK 20260920000000_drop_claims.sql (35.29ms)23712026/10/01 10:21:30 OK 20260923120000_add_pushes.sql (23.89ms)23722026/10/01 10:21:30 goose: successfully migrated database to version: 2026092312000023732026/10/01 10:21:30 OK 1_commit_pending_closure.sql (2.05ms)23742026/10/01 10:21:30 OK 2_object_stats_trigger.sql (482.92µs)23752026/10/01 10:21:30 OK 3_commit_push.sql (372.88µs)23762026/10/01 10:21:30 goose: up to current file version: 32377--- PASS: TestReadProxy404 (2.37s)2378=== CONT TestPush_OverlappingRootsStoreOneRowPerKey23792026/10/01 10:21:31 OK 20241026095416_initial_model.sql (235.42ms)23802026/10/01 10:21:31 OK 20251210153512_drop_unused_gin_index.sql (11.33ms)23812026/10/01 10:21:31 OK 20251218171726_add_pins.sql (39.01ms)23822026/10/01 10:21:31 OK 20260628120000_add_object_size_and_stats.sql (38.22ms)23832026/10/01 10:21:31 OK 20260905000000_add_claims.sql (56.39ms)23842026/10/01 10:21:31 OK 20260920000000_drop_claims.sql (50.1ms)23852026/10/01 10:21:31 OK 20260923120000_add_pushes.sql (14.5ms)23862026/10/01 10:21:31 goose: successfully migrated database to version: 2026092312000023872026/10/01 10:21:31 OK 1_commit_pending_closure.sql (5.48ms)23882026/10/01 10:21:31 OK 2_object_stats_trigger.sql (626.92µs)23892026/10/01 10:21:31 OK 3_commit_push.sql (422.83µs)23902026/10/01 10:21:31 goose: up to current file version: 32391--- PASS: TestReadProxyNarStreaming (2.54s)2392=== CONT TestCompletedNarNotReofferedAcrossClosures23932026-10-01 10:21:31.589 UTC [27829] ERROR: relation "goose_db_version" does not exist at character 3623942026-10-01 10:21:31.589 UTC [27829] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2395--- PASS: TestReadProxyRangeRequest (2.66s)2396=== CONT TestReadRedirectUsesPublicS3URL23972026/10/01 10:21:31 OK 20241026095416_initial_model.sql (225.14ms)23982026/10/01 10:21:31 OK 20251210153512_drop_unused_gin_index.sql (23.5ms)23992026/10/01 10:21:31 OK 20251218171726_add_pins.sql (26.73ms)24002026/10/01 10:21:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete24012026/10/01 10:21:31 OK 20260628120000_add_object_size_and_stats.sql (41.99ms)24022026/10/01 10:21:32 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=OTQ0YTg0OWItNGQxNy00MDM5LWI3NmEtNThjOTk1YjUzYzdmLjA4ZTBlYzQyLTIzNDctNDk5Yy04ODJkLWVkN2I0MGVmMDBjZngxNzkwODUwMDkwNDI3MjM1MDAw parts=1024032026/10/01 10:21:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete24042026/10/01 10:21:32 INFO Received push request method=POST path=/api/pushes24052026-10-01 10:21:32.055 UTC [27832] ERROR: relation "goose_db_version" does not exist at character 3624062026-10-01 10:21:32.055 UTC [27832] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24072026/10/01 10:21:32 OK 20260905000000_add_claims.sql (87.55ms)24082026/10/01 10:21:32 INFO Completed upload id=124092026/10/01 10:21:32 INFO Received uploads request method=POST path=/api/pending_closures24102026/10/01 10:21:32 INFO Received uploads request method=POST path=/api/pending_closures24112026/10/01 10:21:32 OK 20260920000000_drop_claims.sql (16.63ms)24122026/10/01 10:21:32 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo24132026/10/01 10:21:32 WARN Found objects in DB but missing from S3, will re-upload count=12414--- PASS: TestService_verifyS3Integrity (3.47s)2415=== CONT TestRedundantMultipartUpload24162026/10/01 10:21:32 OK 20260923120000_add_pushes.sql (31.57ms)24172026/10/01 10:21:32 goose: successfully migrated database to version: 2026092312000024182026/10/01 10:21:32 OK 1_commit_pending_closure.sql (61.34ms)24192026/10/01 10:21:32 OK 2_object_stats_trigger.sql (7.06ms)24202026/10/01 10:21:32 INFO Received complete push request method=POST path=/api/pushes/1/complete24212026/10/01 10:21:32 OK 3_commit_push.sql (2.69ms)24222026/10/01 10:21:32 goose: up to current file version: 324232026-10-01 10:21:32.192 UTC [27836] ERROR: relation "goose_db_version" does not exist at character 3624242026-10-01 10:21:32.192 UTC [27836] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24252026/10/01 10:21:32 OK 20241026095416_initial_model.sql (82.15ms)24262026/10/01 10:21:32 OK 20251210153512_drop_unused_gin_index.sql (1.94ms)24272026/10/01 10:21:32 INFO Received push request method=POST path=/api/pushes24282026/10/01 10:21:32 OK 20251218171726_add_pins.sql (22.4ms)24292026/10/01 10:21:32 OK 20260628120000_add_object_size_and_stats.sql (29.59ms)24302026/10/01 10:21:32 OK 20260905000000_add_claims.sql (39.23ms)24312026/10/01 10:21:32 OK 20260920000000_drop_claims.sql (15.29ms)24322026/10/01 10:21:32 OK 20260923120000_add_pushes.sql (5.46ms)24332026/10/01 10:21:32 goose: successfully migrated database to version: 2026092312000024342026/10/01 10:21:32 INFO Aborted multipart uploads count=0 kept=024352026/10/01 10:21:32 OK 1_commit_pending_closure.sql (1.94ms)24362026/10/01 10:21:32 WARN Force mode enabled - objects will be deleted immediately without grace period24372026/10/01 10:21:32 OK 2_object_stats_trigger.sql (308.58µs)24382026/10/01 10:21:32 OK 3_commit_push.sql (231.58µs)24392026/10/01 10:21:32 goose: up to current file version: 324402026/10/01 10:21:32 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2 objects-failed-to-delete=024412026/10/01 10:21:32 INFO Vacuumed table table=pending_closures24422026/10/01 10:21:32 INFO Vacuumed table table=pending_objects24432026/10/01 10:21:32 OK 20241026095416_initial_model.sql (126.88ms)24442026/10/01 10:21:32 INFO Vacuumed table table=multipart_uploads24452026/10/01 10:21:32 OK 20251210153512_drop_unused_gin_index.sql (9.55ms)24462026/10/01 10:21:32 INFO Vacuumed table table=closures24472026/10/01 10:21:32 OK 20251218171726_add_pins.sql (23.8ms)24482026/10/01 10:21:32 INFO Vacuumed table table=objects24492026/10/01 10:21:32 INFO Received complete push request method=POST path=/api/pushes/2/complete2450--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (3.16s)2451=== CONT TestReadRedirectNar24522026/10/01 10:21:32 OK 20260628120000_add_object_size_and_stats.sql (37.15ms)24532026/10/01 10:21:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete24542026/10/01 10:21:32 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst2455--- PASS: TestCompleteMultipartUnregistered (2.80s)2456=== CONT TestPush_SignsNarinfosOfItsPendingObjects24572026/10/01 10:21:32 OK 20260905000000_add_claims.sql (45.05ms)24582026/10/01 10:21:32 OK 20260920000000_drop_claims.sql (30.38ms)24592026/10/01 10:21:32 OK 20260923120000_add_pushes.sql (8.04ms)24602026/10/01 10:21:32 goose: successfully migrated database to version: 2026092312000024612026/10/01 10:21:32 OK 1_commit_pending_closure.sql (2.43ms)24622026/10/01 10:21:32 OK 2_object_stats_trigger.sql (338.29µs)24632026/10/01 10:21:32 OK 3_commit_push.sql (246.42µs)24642026/10/01 10:21:32 goose: up to current file version: 324652026-10-01 10:21:32.602 UTC [27842] ERROR: relation "goose_db_version" does not exist at character 3624662026-10-01 10:21:32.602 UTC [27842] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24672026/10/01 10:21:32 INFO Received uploads request method=POST path=/api/pending_closures2468--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.96s)2469=== CONT TestReadRedirectKeepsNarinfoProxied24702026/10/01 10:21:32 OK 20241026095416_initial_model.sql (142.44ms)24712026/10/01 10:21:32 OK 20251210153512_drop_unused_gin_index.sql (3.57ms)24722026/10/01 10:21:32 OK 20251218171726_add_pins.sql (26.82ms)24732026/10/01 10:21:32 OK 20260628120000_add_object_size_and_stats.sql (24.37ms)24742026/10/01 10:21:32 OK 20260905000000_add_claims.sql (30.89ms)24752026/10/01 10:21:32 OK 20260920000000_drop_claims.sql (19.55ms)24762026/10/01 10:21:32 OK 20260923120000_add_pushes.sql (10.8ms)24772026/10/01 10:21:32 goose: successfully migrated database to version: 2026092312000024782026/10/01 10:21:32 OK 1_commit_pending_closure.sql (2.91ms)24792026/10/01 10:21:32 OK 2_object_stats_trigger.sql (329.79µs)24802026/10/01 10:21:32 OK 3_commit_push.sql (258.54µs)24812026/10/01 10:21:32 goose: up to current file version: 324822026/10/01 10:21:32 INFO Received push request method=POST path=/api/pushes24832026-10-01 10:21:33.020 UTC [27848] ERROR: relation "goose_db_version" does not exist at character 3624842026-10-01 10:21:33.020 UTC [27848] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24852026/10/01 10:21:33 INFO Received complete push request method=POST path=/api/pushes/1/complete2486--- PASS: TestPush_CompleteCommitsEveryRoot (3.10s)2487=== CONT TestProxyHeadersOnlyTrustedOnSocket24882026/10/01 10:21:33 OK 20241026095416_initial_model.sql (81.64ms)24892026/10/01 10:21:33 OK 20251210153512_drop_unused_gin_index.sql (4.18ms)24902026-10-01 10:21:33.200 UTC [27860] ERROR: relation "goose_db_version" does not exist at character 3624912026-10-01 10:21:33.200 UTC [27860] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24922026/10/01 10:21:33 OK 20251218171726_add_pins.sql (31.14ms)24932026/10/01 10:21:33 OK 20260628120000_add_object_size_and_stats.sql (28.98ms)24942026/10/01 10:21:33 INFO Received uploads request method=POST path=/api/pending_closures24952026/10/01 10:21:33 OK 20260905000000_add_claims.sql (27.11ms)24962026/10/01 10:21:33 OK 20260920000000_drop_claims.sql (18.76ms)24972026/10/01 10:21:33 OK 20260923120000_add_pushes.sql (8.63ms)24982026/10/01 10:21:33 goose: successfully migrated database to version: 2026092312000024992026/10/01 10:21:33 OK 1_commit_pending_closure.sql (4.14ms)25002026/10/01 10:21:33 OK 2_object_stats_trigger.sql (282.25µs)25012026/10/01 10:21:33 OK 3_commit_push.sql (242µs)25022026/10/01 10:21:33 goose: up to current file version: 325032026-10-01 10:21:33.315 UTC [27861] ERROR: relation "goose_db_version" does not exist at character 3625042026-10-01 10:21:33.315 UTC [27861] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25052026/10/01 10:21:33 OK 20241026095416_initial_model.sql (99.8ms)25062026/10/01 10:21:33 OK 20251210153512_drop_unused_gin_index.sql (10.79ms)25072026/10/01 10:21:33 OK 20251218171726_add_pins.sql (29.8ms)25082026/10/01 10:21:33 OK 20260628120000_add_object_size_and_stats.sql (19.93ms)25092026/10/01 10:21:33 OK 20260905000000_add_claims.sql (15.32ms)25102026/10/01 10:21:33 OK 20260920000000_drop_claims.sql (34.54ms)25112026/10/01 10:21:33 OK 20260923120000_add_pushes.sql (6.84ms)25122026/10/01 10:21:33 goose: successfully migrated database to version: 2026092312000025132026/10/01 10:21:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete25142026/10/01 10:21:33 OK 1_commit_pending_closure.sql (2.35ms)25152026/10/01 10:21:33 OK 2_object_stats_trigger.sql (228.17µs)25162026/10/01 10:21:33 OK 3_commit_push.sql (174.5µs)25172026/10/01 10:21:33 goose: up to current file version: 325182026/10/01 10:21:33 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTQ0YTg0OWItNGQxNy00MDM5LWI3NmEtNThjOTk1YjUzYzdmLmQ3YTU1YWFlLWE0NDItNDBhOC1hYmI1LTJmMmMxMTI1ZWJjM3gxNzkwODUwMDkzMjU2NjkyMDAw25192026/10/01 10:21:33 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=OTQ0YTg0OWItNGQxNy00MDM5LWI3NmEtNThjOTk1YjUzYzdmLmQ3YTU1YWFlLWE0NDItNDBhOC1hYmI1LTJmMmMxMTI1ZWJjM3gxNzkwODUwMDkzMjU2NjkyMDAw parts=12520--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (2.82s)2521=== CONT TestIsValidCachePath2522=== RUN TestIsValidCachePath/narinfo2523=== PAUSE TestIsValidCachePath/narinfo2524=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars2525=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars2526=== RUN TestIsValidCachePath/nar_zst2527=== PAUSE TestIsValidCachePath/nar_zst2528=== RUN TestIsValidCachePath/nar_xz2529=== PAUSE TestIsValidCachePath/nar_xz2530=== RUN TestIsValidCachePath/nar_bz22531=== PAUSE TestIsValidCachePath/nar_bz22532=== RUN TestIsValidCachePath/nar_uncompressed2533=== PAUSE TestIsValidCachePath/nar_uncompressed2534=== RUN TestIsValidCachePath/ls2535=== PAUSE TestIsValidCachePath/ls2536=== RUN TestIsValidCachePath/log2537=== PAUSE TestIsValidCachePath/log2538=== RUN TestIsValidCachePath/realisation2539=== PAUSE TestIsValidCachePath/realisation2540=== RUN TestIsValidCachePath/nix-cache-info2541=== PAUSE TestIsValidCachePath/nix-cache-info2542=== RUN TestIsValidCachePath/index.html2543=== PAUSE TestIsValidCachePath/index.html2544=== RUN TestIsValidCachePath/traversal_parent2545=== PAUSE TestIsValidCachePath/traversal_parent2546=== RUN TestIsValidCachePath/traversal_in_middle2547=== PAUSE TestIsValidCachePath/traversal_in_middle2548=== RUN TestIsValidCachePath/invalid_char_e2549=== PAUSE TestIsValidCachePath/invalid_char_e2550=== RUN TestIsValidCachePath/invalid_char_u2551=== PAUSE TestIsValidCachePath/invalid_char_u2552=== RUN TestIsValidCachePath/random_path2553=== PAUSE TestIsValidCachePath/random_path2554=== RUN TestIsValidCachePath/empty2555=== PAUSE TestIsValidCachePath/empty2556=== RUN TestIsValidCachePath/leading_slash2557=== PAUSE TestIsValidCachePath/leading_slash2558=== RUN TestIsValidCachePath/wrong_extension2559=== PAUSE TestIsValidCachePath/wrong_extension2560=== RUN TestIsValidCachePath/short_hash2561=== PAUSE TestIsValidCachePath/short_hash2562=== CONT TestParseSingleRange2563=== RUN TestParseSingleRange/none2564=== PAUSE TestParseSingleRange/none2565=== RUN TestParseSingleRange/unknown_unit2566=== PAUSE TestParseSingleRange/unknown_unit2567=== RUN TestParseSingleRange/multi-range_ignored2568=== PAUSE TestParseSingleRange/multi-range_ignored2569=== RUN TestParseSingleRange/malformed_no_dash2570=== PAUSE TestParseSingleRange/malformed_no_dash2571=== RUN TestParseSingleRange/malformed_both_empty2572=== PAUSE TestParseSingleRange/malformed_both_empty2573=== RUN TestParseSingleRange/malformed_end_before_start2574=== PAUSE TestParseSingleRange/malformed_end_before_start2575=== RUN TestParseSingleRange/closed2576=== PAUSE TestParseSingleRange/closed2577=== RUN TestParseSingleRange/open-ended2578=== PAUSE TestParseSingleRange/open-ended2579=== RUN TestParseSingleRange/end_clamped_to_size2580=== PAUSE TestParseSingleRange/end_clamped_to_size2581=== RUN TestParseSingleRange/suffix2582=== PAUSE TestParseSingleRange/suffix2583=== RUN TestParseSingleRange/suffix_exceeds_size2584=== PAUSE TestParseSingleRange/suffix_exceeds_size2585=== RUN TestParseSingleRange/single_byte2586=== PAUSE TestParseSingleRange/single_byte2587=== RUN TestParseSingleRange/start_past_EOF2588=== PAUSE TestParseSingleRange/start_past_EOF2589=== RUN TestParseSingleRange/start_far_past_EOF2590=== PAUSE TestParseSingleRange/start_far_past_EOF2591=== CONT TestReadProxyDisabled25922026/10/01 10:21:33 OK 20241026095416_initial_model.sql (133.62ms)25932026/10/01 10:21:33 OK 20251210153512_drop_unused_gin_index.sql (11.08ms)25942026/10/01 10:21:33 INFO Received push request method=POST path=/api/pushes25952026/10/01 10:21:33 OK 20251218171726_add_pins.sql (16.87ms)25962026/10/01 10:21:33 OK 20260628120000_add_object_size_and_stats.sql (30.4ms)2597--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.52s)2598=== CONT TestReadProxyRootRedirectsToIndexHTML25992026/10/01 10:21:33 OK 20260905000000_add_claims.sql (88.95ms)26002026/10/01 10:21:33 OK 20260920000000_drop_claims.sql (15.27ms)26012026/10/01 10:21:33 OK 20260923120000_add_pushes.sql (3.62ms)26022026/10/01 10:21:33 goose: successfully migrated database to version: 2026092312000026032026/10/01 10:21:33 OK 1_commit_pending_closure.sql (930µs)26042026/10/01 10:21:33 OK 2_object_stats_trigger.sql (251.46µs)26052026/10/01 10:21:33 OK 3_commit_push.sql (192.54µs)26062026/10/01 10:21:33 goose: up to current file version: 326072026-10-01 10:21:33.723 UTC [27874] ERROR: relation "goose_db_version" does not exist at character 3626082026-10-01 10:21:33.723 UTC [27874] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26092026/10/01 10:21:33 INFO Received uploads request method=POST path=/api/pending_closures26102026/10/01 10:21:34 OK 20241026095416_initial_model.sql (229.77ms)26112026/10/01 10:21:34 OK 20251210153512_drop_unused_gin_index.sql (16.23ms)26122026-10-01 10:21:34.031 UTC [27876] ERROR: relation "goose_db_version" does not exist at character 3626132026-10-01 10:21:34.031 UTC [27876] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26142026/10/01 10:21:34 OK 20251218171726_add_pins.sql (11.59ms)26152026-10-01 10:21:34.040 UTC [27875] ERROR: relation "goose_db_version" does not exist at character 3626162026-10-01 10:21:34.040 UTC [27875] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26172026/10/01 10:21:34 OK 20260628120000_add_object_size_and_stats.sql (17.79ms)26182026/10/01 10:21:34 OK 20260905000000_add_claims.sql (51.99ms)26192026/10/01 10:21:34 OK 20260920000000_drop_claims.sql (48.21ms)26202026/10/01 10:21:34 OK 20260923120000_add_pushes.sql (20.73ms)26212026/10/01 10:21:34 goose: successfully migrated database to version: 202609231200002622--- PASS: TestReadRedirectUsesPublicS3URL (2.42s)2623=== CONT TestProxyWriteTimeout/narinfo2624=== CONT TestReadProxyNarinfoAlreadyDecompressed26252026/10/01 10:21:34 OK 1_commit_pending_closure.sql (5ms)26262026/10/01 10:21:34 OK 2_object_stats_trigger.sql (627.21µs)26272026/10/01 10:21:34 OK 3_commit_push.sql (359.25µs)26282026/10/01 10:21:34 goose: up to current file version: 326292026/10/01 10:21:34 OK 20241026095416_initial_model.sql (207.97ms)26302026/10/01 10:21:34 OK 20251210153512_drop_unused_gin_index.sql (8.25ms)26312026/10/01 10:21:34 WARN Rate limiter enabled after throttle name=s3-test rate=526322026/10/01 10:21:34 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2633=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2634 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102635 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002636--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.97s)2637=== CONT TestProxyWriteTimeout/10_GiB_nar2638=== CONT TestProxyWriteTimeout/unknown_size2639=== CONT TestProxyWriteTimeout/1_GiB_nar2640--- PASS: TestProxyWriteTimeout (0.00s)2641 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2642 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2643 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2644 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2645=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure26462026/10/01 10:21:34 INFO Received uploads request method=POST path=/26472026/10/01 10:21:34 OK 20241026095416_initial_model.sql (226.75ms)26482026/10/01 10:21:34 OK 20251210153512_drop_unused_gin_index.sql (9.91ms)26492026/10/01 10:21:34 OK 20251218171726_add_pins.sql (35.62ms)26502026/10/01 10:21:34 OK 20251218171726_add_pins.sql (19.97ms)26512026/10/01 10:21:34 OK 20260628120000_add_object_size_and_stats.sql (30.83ms)26522026/10/01 10:21:34 OK 20260628120000_add_object_size_and_stats.sql (48.24ms)26532026/10/01 10:21:34 OK 20260905000000_add_claims.sql (74.37ms)26542026/10/01 10:21:34 OK 20260905000000_add_claims.sql (54.18ms)26552026/10/01 10:21:34 OK 20260920000000_drop_claims.sql (27.49ms)26562026/10/01 10:21:34 OK 20260923120000_add_pushes.sql (14.37ms)26572026/10/01 10:21:34 goose: successfully migrated database to version: 2026092312000026582026/10/01 10:21:34 OK 1_commit_pending_closure.sql (919.71µs)26592026/10/01 10:21:34 OK 2_object_stats_trigger.sql (215.08µs)26602026/10/01 10:21:34 OK 3_commit_push.sql (169.38µs)26612026/10/01 10:21:34 goose: up to current file version: 326622026/10/01 10:21:34 OK 20260920000000_drop_claims.sql (39.47ms)26632026/10/01 10:21:34 INFO Received uploads request method=POST path=/api/pending_closures26642026/10/01 10:21:34 OK 20260923120000_add_pushes.sql (17.31ms)26652026/10/01 10:21:34 goose: successfully migrated database to version: 2026092312000026662026/10/01 10:21:34 OK 1_commit_pending_closure.sql (1.23ms)26672026/10/01 10:21:34 OK 2_object_stats_trigger.sql (214.33µs)26682026/10/01 10:21:34 OK 3_commit_push.sql (257.5µs)26692026/10/01 10:21:34 goose: up to current file version: 326702026/10/01 10:21:34 INFO Received uploads request method=POST path=/api/pending_closures2671=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts26722026/10/01 10:21:34 INFO Received request for more parts method=POST path=/2673=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart26742026/10/01 10:21:34 INFO Received complete multipart upload request method=POST path=/2675=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info26762026/10/01 10:21:34 INFO Received uploads request method=POST path=/2677--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)2678 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.31s)2679 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)2680 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2681=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key26822026/10/01 10:21:34 INFO Received complete multipart upload request method=POST path=/2683=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key26842026/10/01 10:21:34 INFO Received request for more parts method=POST path=/2685=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal26862026/10/01 10:21:34 INFO Received uploads request method=POST path=/2687--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2688 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2689 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2690 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2691 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2692=== CONT TestIsValidUploadKey/narinfo2693=== CONT TestIsValidUploadKey/realisation_plus_in_output2694=== CONT TestIsValidUploadKey/unknown_type2695=== CONT TestIsValidUploadKey/empty_key2696=== CONT TestIsValidUploadKey/absolute2697=== CONT TestIsValidUploadKey/traversal_nar2698=== CONT TestIsValidUploadKey/traversal2699=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2700=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2701=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2702=== CONT TestIsValidUploadKey/index.html2703=== CONT TestIsValidUploadKey/nix-cache-info2704=== CONT TestIsValidUploadKey/build_log_home-manager_file2705=== CONT TestIsValidUploadKey/realisation2706=== CONT TestIsValidUploadKey/build_log_equals2707=== CONT TestIsValidUploadKey/build_log_question_mark2708=== CONT TestIsValidUploadKey/build_log_plus_in_name2709=== CONT TestIsValidUploadKey/nar_plain2710=== CONT TestIsValidUploadKey/build_log2711=== CONT TestIsValidUploadKey/listing2712=== CONT TestIsValidUploadKey/nar_xz2713=== CONT TestIsValidUploadKey/nar_zst2714--- PASS: TestIsValidUploadKey (0.00s)2715 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2716 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2717 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2718 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2719 --- PASS: TestIsValidUploadKey/absolute (0.00s)2720 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2721 --- PASS: TestIsValidUploadKey/traversal (0.00s)2722 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2723 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2724 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2725 --- PASS: TestIsValidUploadKey/index.html (0.00s)2726 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2727 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2728 --- PASS: TestIsValidUploadKey/realisation (0.00s)2729 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2730 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2731 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2732 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2733 --- PASS: TestIsValidUploadKey/build_log (0.00s)2734 --- PASS: TestIsValidUploadKey/listing (0.00s)2735 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2736 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2737=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows27382026-10-01 10:21:34.658 UTC [27879] ERROR: relation "goose_db_version" does not exist at character 3627392026-10-01 10:21:34.658 UTC [27879] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27402026/10/01 10:21:34 INFO Received push request method=POST path=/api/pushes27412026/10/01 10:21:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27422026/10/01 10:21:34 INFO Signed narinfos id=1 count=12743--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.49s)2744=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check27452026/10/01 10:21:35 OK 20241026095416_initial_model.sql (334.43ms)27462026/10/01 10:21:35 OK 20251210153512_drop_unused_gin_index.sql (21.18ms)27472026/10/01 10:21:35 OK 20251218171726_add_pins.sql (37.65ms)27482026/10/01 10:21:35 OK 20260628120000_add_object_size_and_stats.sql (24.55ms)27492026/10/01 10:21:35 OK 20260905000000_add_claims.sql (109.4ms)27502026/10/01 10:21:35 OK 20260920000000_drop_claims.sql (42.41ms)2751--- PASS: TestReadRedirectNar (2.87s)2752=== CONT TestPush_RejectsBadRequests/no_objects27532026/10/01 10:21:35 INFO Received push request method=POST path=/api/pushes2754=== CONT TestPush_RejectsBadRequests/root_not_in_objects27552026/10/01 10:21:35 INFO Received push request method=POST path=/api/pushes2756=== CONT TestPush_RejectsBadRequests/no_roots27572026/10/01 10:21:35 INFO Received push request method=POST path=/api/pushes2758=== CONT TestPush_RejectsBadRequests/bad_root27592026/10/01 10:21:35 INFO Received push request method=POST path=/api/pushes2760=== CONT TestServerTLSConfig/no_client_CA2761=== CONT TestServerTLSConfig/not_a_PEM_file2762--- PASS: TestPush_RejectsBadRequests (1.11s)2763 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2764 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2765 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2766 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)27672026/10/01 10:21:35 OK 20260923120000_add_pushes.sql (22.27ms)27682026/10/01 10:21:35 goose: successfully migrated database to version: 2026092312000027692026/10/01 10:21:35 OK 1_commit_pending_closure.sql (2.25ms)27702026/10/01 10:21:35 OK 2_object_stats_trigger.sql (474.04µs)27712026/10/01 10:21:35 OK 3_commit_push.sql (388.21µs)27722026/10/01 10:21:35 goose: up to current file version: 32773=== CONT TestServerTLSConfig/missing_CA_file2774=== CONT TestResolveDBConnectionString/flag_wins2775--- PASS: TestServerTLSConfig (0.00s)2776 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2777 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)2778 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2779=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2780=== CONT TestResolveDBConnectionString/nothing_configured2781=== CONT TestResolveDBConnectionString/missing_file_is_an_error2782=== CONT TestResolveDBConnectionString/file_when_flag_empty2783=== CONT TestClientErrorHandling/InvalidStorePath2784--- PASS: TestResolveDBConnectionString (0.02s)2785 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2786 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2787 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2788 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2789 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)27902026-10-01 10:21:35.698 UTC [27886] ERROR: relation "goose_db_version" does not exist at character 3627912026-10-01 10:21:35.698 UTC [27886] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2792--- PASS: TestReadRedirectKeepsNarinfoProxied (3.02s)2793=== CONT TestClientErrorHandling/ServerNotAvailable27942026/10/01 10:21:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete27952026/10/01 10:21:35 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=OTQ0YTg0OWItNGQxNy00MDM5LWI3NmEtNThjOTk1YjUzYzdmLmVjODhmYWY4LWE3ODgtNDVjMC1iYmFlLWM0YmIzYmVjNzJhZngxNzkwODUwMDkzODUyOTMzMDAw parts=1227962026/10/01 10:21:35 INFO Received uploads request method=POST path=/api/pending_closures2797--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.53s)2798=== CONT TestClientErrorHandling/InvalidAuthToken27992026/10/01 10:21:36 OK 20241026095416_initial_model.sql (273.01ms)28002026/10/01 10:21:36 OK 20251210153512_drop_unused_gin_index.sql (2.55ms)28012026/10/01 10:21:36 OK 20251218171726_add_pins.sql (40.47ms)28022026/10/01 10:21:36 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28032026/10/01 10:21:36 OK 20260628120000_add_object_size_and_stats.sql (39.86ms)28042026/10/01 10:21:36 OK 20260905000000_add_claims.sql (13.08ms)28052026/10/01 10:21:36 OK 20260920000000_drop_claims.sql (2.26ms)28062026-10-01 10:21:36.208 UTC [27893] ERROR: relation "goose_db_version" does not exist at character 3628072026-10-01 10:21:36.208 UTC [27893] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28082026/10/01 10:21:36 OK 20260923120000_add_pushes.sql (3.2ms)28092026/10/01 10:21:36 goose: successfully migrated database to version: 2026092312000028102026-10-01 10:21:36.214 UTC [27894] ERROR: relation "goose_db_version" does not exist at character 3628112026-10-01 10:21:36.214 UTC [27894] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28122026/10/01 10:21:36 OK 1_commit_pending_closure.sql (5.11ms)28132026/10/01 10:21:36 OK 2_object_stats_trigger.sql (982.79µs)28142026/10/01 10:21:36 OK 3_commit_push.sql (715.21µs)28152026/10/01 10:21:36 goose: up to current file version: 328162026/10/01 10:21:36 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=190.576951ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28172026/10/01 10:21:36 OK 20241026095416_initial_model.sql (92.11ms)28182026/10/01 10:21:36 OK 20251210153512_drop_unused_gin_index.sql (13.3ms)28192026/10/01 10:21:36 OK 20251218171726_add_pins.sql (26.76ms)28202026/10/01 10:21:36 OK 20241026095416_initial_model.sql (158.17ms)28212026/10/01 10:21:36 OK 20260628120000_add_object_size_and_stats.sql (28.33ms)28222026/10/01 10:21:36 OK 20251210153512_drop_unused_gin_index.sql (8.51ms)28232026/10/01 10:21:36 OK 20251218171726_add_pins.sql (21.47ms)28242026/10/01 10:21:36 OK 20260905000000_add_claims.sql (37.51ms)28252026/10/01 10:21:36 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=388.723129ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28262026/10/01 10:21:36 OK 20260628120000_add_object_size_and_stats.sql (28.46ms)28272026/10/01 10:21:36 INFO Starting HTTP server address=/nix/var/nix/builds/nix-26883-1285942671/TestProxyHeadersOnlyTrustedOnSocket2250193221/001/proxy.sock28282026/10/01 10:21:36 INFO Starting HTTP server address=127.0.0.1:6046728292026/10/01 10:21:36 WARN mTLS auth: subject not in bound subjects subject="CN=someone"28302026/10/01 10:21:36 INFO Shutdown signal received, draining in-flight requests timeout=10s28312026/10/01 10:21:36 OK 20260920000000_drop_claims.sql (36.58ms)2832--- PASS: TestProxyHeadersOnlyTrustedOnSocket (3.39s)2833=== CONT TestCacheConfigHandler/full_config,_no_issuer2834=== CONT TestCacheConfigHandler/no_signing_keys2835=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2836=== CONT TestCacheConfigHandler/no_cache_url_configured2837--- PASS: TestCacheConfigHandler (0.00s)2838 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2839 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2840 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2841 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2842=== CONT TestService_RequireScope_OIDC/builder_may_write2843=== CONT TestService_RequireScope_OIDC/static_token_may_admin2844=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2845=== CONT TestService_RequireScope_OIDC/writer_implies_read2846=== CONT TestService_RequireScope_OIDC/reader_may_read2847=== CONT TestService_RequireScope_OIDC/static_token_may_write2848=== CONT TestService_RequireScope_OIDC/ops_may_not_write2849=== CONT TestService_RequireScope_OIDC/reader_may_not_write2850=== CONT TestService_RequireScope_OIDC/ops_may_admin2851=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2852=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2853=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected28542026/10/01 10:21:36 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]2855=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2856=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected28572026/10/01 10:21:36 WARN Authentication failed token_preview=eyJhbGciOi...IbF-l-PJkA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2858=== CONT TestIsValidCachePath/narinfo2859=== CONT TestIsValidCachePath/index.html2860=== CONT TestIsValidCachePath/short_hash2861=== CONT TestIsValidCachePath/wrong_extension2862=== CONT TestIsValidCachePath/invalid_char_e2863=== CONT TestIsValidCachePath/traversal_in_middle2864=== CONT TestIsValidCachePath/traversal_parent2865=== CONT TestIsValidCachePath/nar_uncompressed2866=== CONT TestIsValidCachePath/nix-cache-info2867=== CONT TestIsValidCachePath/invalid_char_u2868=== CONT TestIsValidCachePath/realisation2869=== CONT TestIsValidCachePath/log2870=== CONT TestIsValidCachePath/leading_slash2871=== CONT TestIsValidCachePath/ls2872=== CONT TestIsValidCachePath/empty2873=== CONT TestIsValidCachePath/random_path2874=== CONT TestIsValidCachePath/nar_xz2875=== CONT TestIsValidCachePath/nar_bz22876=== CONT TestIsValidCachePath/nar_zst2877=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2878--- PASS: TestIsValidCachePath (0.00s)2879 --- PASS: TestIsValidCachePath/narinfo (0.00s)2880 --- PASS: TestIsValidCachePath/index.html (0.00s)2881 --- PASS: TestIsValidCachePath/short_hash (0.00s)2882 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2883 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2884 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2885 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2886 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2887 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2888 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2889 --- PASS: TestIsValidCachePath/realisation (0.00s)2890 --- PASS: TestIsValidCachePath/log (0.00s)2891 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2892 --- PASS: TestIsValidCachePath/ls (0.00s)2893 --- PASS: TestIsValidCachePath/empty (0.00s)2894 --- PASS: TestIsValidCachePath/random_path (0.00s)2895 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2896 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2897 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2898 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2899=== CONT TestParseSingleRange/none2900=== CONT TestParseSingleRange/open-ended2901=== CONT TestParseSingleRange/start_far_past_EOF2902=== CONT TestParseSingleRange/start_past_EOF2903=== CONT TestParseSingleRange/single_byte2904=== CONT TestParseSingleRange/suffix_exceeds_size2905=== CONT TestParseSingleRange/suffix2906=== CONT TestParseSingleRange/malformed_both_empty2907=== CONT TestParseSingleRange/closed2908=== CONT TestParseSingleRange/malformed_end_before_start2909=== CONT TestParseSingleRange/multi-range_ignored2910=== CONT TestParseSingleRange/end_clamped_to_size2911=== CONT TestParseSingleRange/malformed_no_dash2912=== CONT TestParseSingleRange/unknown_unit2913--- PASS: TestParseSingleRange (0.00s)2914 --- PASS: TestParseSingleRange/none (0.00s)2915 --- PASS: TestParseSingleRange/open-ended (0.00s)2916 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2917 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2918 --- PASS: TestParseSingleRange/single_byte (0.00s)2919 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2920 --- PASS: TestParseSingleRange/suffix (0.00s)2921 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2922 --- PASS: TestParseSingleRange/closed (0.00s)2923 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2924 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2925 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2926 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2927 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2928--- PASS: TestService_RequireScope_OIDC (1.75s)2929 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2930 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2931 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2932 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2933 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2934 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2935 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2936 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2937 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2938 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2939--- PASS: TestService_AuthMiddleware_OIDC (1.82s)2940 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2941 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2942 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2943 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)29442026/10/01 10:21:36 OK 20260923120000_add_pushes.sql (18.06ms)29452026/10/01 10:21:36 goose: successfully migrated database to version: 2026092312000029462026/10/01 10:21:36 OK 1_commit_pending_closure.sql (1.41ms)29472026/10/01 10:21:36 OK 2_object_stats_trigger.sql (327.38µs)29482026/10/01 10:21:36 OK 3_commit_push.sql (271.71µs)29492026/10/01 10:21:36 goose: up to current file version: 329502026/10/01 10:21:36 INFO Received complete multipart upload request method=POST path=/api/multipart/complete29512026/10/01 10:21:36 OK 20260905000000_add_claims.sql (74.56ms)29522026/10/01 10:21:36 OK 20260920000000_drop_claims.sql (75.77ms)29532026/10/01 10:21:36 OK 20260923120000_add_pushes.sql (37.71ms)29542026/10/01 10:21:36 goose: successfully migrated database to version: 2026092312000029552026/10/01 10:21:36 OK 1_commit_pending_closure.sql (3.29ms)29562026/10/01 10:21:36 OK 2_object_stats_trigger.sql (941.38µs)29572026/10/01 10:21:36 OK 3_commit_push.sql (550.88µs)29582026/10/01 10:21:36 goose: up to current file version: 329592026/10/01 10:21:36 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=OTQ0YTg0OWItNGQxNy00MDM5LWI3NmEtNThjOTk1YjUzYzdmLjczNGE1YTY4LTZmZDUtNGI1Zi04YTU0LTVjZTRmNjkyMTkzZXgxNzkwODUwMDk0NTQwMTU5MDAw parts=1229602026/10/01 10:21:36 INFO Received uploads request method=POST path=/api/pending_closures29612026/10/01 10:21:36 INFO Received uploads request method=POST path=/api/pending_closures29622026/10/01 10:21:36 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=841.862443ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2963--- PASS: TestReadProxyRootRedirectsToIndexHTML (3.40s)2964--- PASS: TestReadProxyDisabled (3.94s)29652026-10-01 10:21:37.644 UTC [27895] ERROR: relation "goose_db_version" does not exist at character 3629662026-10-01 10:21:37.644 UTC [27895] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29672026/10/01 10:21:37 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.648284225s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29682026-10-01 10:21:37.837 UTC [27896] ERROR: relation "goose_db_version" does not exist at character 3629692026-10-01 10:21:37.837 UTC [27896] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29702026/10/01 10:21:37 OK 20241026095416_initial_model.sql (144.66ms)29712026/10/01 10:21:37 OK 20251210153512_drop_unused_gin_index.sql (7.23ms)29722026-10-01 10:21:37.887 UTC [27897] ERROR: relation "goose_db_version" does not exist at character 3629732026-10-01 10:21:37.887 UTC [27897] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29742026/10/01 10:21:37 OK 20251218171726_add_pins.sql (14.2ms)29752026/10/01 10:21:37 OK 20260628120000_add_object_size_and_stats.sql (36.05ms)29762026/10/01 10:21:37 OK 20260905000000_add_claims.sql (46.75ms)29772026/10/01 10:21:38 OK 20260920000000_drop_claims.sql (30.41ms)29782026/10/01 10:21:38 OK 20260923120000_add_pushes.sql (10.47ms)29792026/10/01 10:21:38 goose: successfully migrated database to version: 2026092312000029802026/10/01 10:21:38 OK 1_commit_pending_closure.sql (3.73ms)29812026/10/01 10:21:38 OK 2_object_stats_trigger.sql (928.13µs)29822026/10/01 10:21:38 OK 3_commit_push.sql (479.5µs)29832026/10/01 10:21:38 goose: up to current file version: 329842026-10-01 10:21:38.048 UTC [27898] ERROR: relation "goose_db_version" does not exist at character 3629852026-10-01 10:21:38.048 UTC [27898] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29862026/10/01 10:21:38 OK 20241026095416_initial_model.sql (174.01ms)29872026/10/01 10:21:38 OK 20251210153512_drop_unused_gin_index.sql (11.53ms)29882026/10/01 10:21:38 OK 20251218171726_add_pins.sql (41.39ms)29892026/10/01 10:21:38 OK 20241026095416_initial_model.sql (218.36ms)29902026/10/01 10:21:38 OK 20260628120000_add_object_size_and_stats.sql (30.16ms)29912026/10/01 10:21:38 OK 20251210153512_drop_unused_gin_index.sql (9.27ms)29922026/10/01 10:21:38 OK 20251218171726_add_pins.sql (33.62ms)29932026/10/01 10:21:38 OK 20260628120000_add_object_size_and_stats.sql (40.24ms)29942026/10/01 10:21:38 OK 20260905000000_add_claims.sql (97.67ms)29952026/10/01 10:21:38 OK 20260920000000_drop_claims.sql (67.65ms)29962026/10/01 10:21:38 OK 20260905000000_add_claims.sql (103.66ms)29972026/10/01 10:21:38 OK 20260923120000_add_pushes.sql (20.84ms)29982026/10/01 10:21:38 goose: successfully migrated database to version: 2026092312000029992026/10/01 10:21:38 OK 1_commit_pending_closure.sql (4.61ms)30002026/10/01 10:21:38 OK 2_object_stats_trigger.sql (861.63µs)30012026/10/01 10:21:38 OK 3_commit_push.sql (640.13µs)30022026/10/01 10:21:38 goose: up to current file version: 330032026/10/01 10:21:38 OK 20260920000000_drop_claims.sql (36.07ms)30042026/10/01 10:21:38 OK 20241026095416_initial_model.sql (235.1ms)30052026/10/01 10:21:38 OK 20251210153512_drop_unused_gin_index.sql (11.77ms)30062026/10/01 10:21:38 OK 20260923120000_add_pushes.sql (22.06ms)30072026/10/01 10:21:38 goose: successfully migrated database to version: 202609231200003008--- PASS: TestReadProxyNarinfoAlreadyDecompressed (4.22s)30092026/10/01 10:21:38 OK 1_commit_pending_closure.sql (2.81ms)30102026/10/01 10:21:38 OK 2_object_stats_trigger.sql (586.08µs)30112026/10/01 10:21:38 OK 3_commit_push.sql (363.92µs)30122026/10/01 10:21:38 goose: up to current file version: 330132026/10/01 10:21:38 OK 20251218171726_add_pins.sql (57.33ms)30142026/10/01 10:21:38 OK 20260628120000_add_object_size_and_stats.sql (42.68ms)30152026/10/01 10:21:38 OK 20260905000000_add_claims.sql (51.79ms)30162026/10/01 10:21:38 OK 20260920000000_drop_claims.sql (9.85ms)30172026/10/01 10:21:38 OK 20260923120000_add_pushes.sql (13.38ms)30182026/10/01 10:21:38 goose: successfully migrated database to version: 2026092312000030192026/10/01 10:21:38 OK 1_commit_pending_closure.sql (2.63ms)30202026/10/01 10:21:38 OK 2_object_stats_trigger.sql (474.5µs)30212026/10/01 10:21:38 OK 3_commit_push.sql (388.83µs)30222026/10/01 10:21:38 goose: up to current file version: 330232026-10-01 10:21:38.640 UTC [27899] ERROR: relation "goose_db_version" does not exist at character 3630242026-10-01 10:21:38.640 UTC [27899] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC30252026/10/01 10:21:38 INFO Received uploads request method=POST path=/api/pending_closures30262026/10/01 10:21:38 INFO Aborted multipart uploads count=0 kept=030272026/10/01 10:21:38 WARN Force mode enabled - objects will be deleted immediately without grace period30282026/10/01 10:21:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete30292026/10/01 10:21:38 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=030302026/10/01 10:21:38 INFO Vacuumed table table=pending_closures30312026/10/01 10:21:38 INFO Vacuumed table table=pending_objects30322026/10/01 10:21:38 INFO Vacuumed table table=multipart_uploads30332026/10/01 10:21:38 INFO Vacuumed table table=closures30342026/10/01 10:21:38 INFO Vacuumed table table=objects30352026/10/01 10:21:38 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OTQ0YTg0OWItNGQxNy00MDM5LWI3NmEtNThjOTk1YjUzYzdmLmJmN2E0NWM0LTRiYTYtNDlkMy1iM2VmLTFmMjk5YmVlNjBlN3gxNzkwODUwMDk2NzQwMDY4MDAw error="Get \"http://127.0.0.1:1/bucket74/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"30362026/10/01 10:21:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=OTQ0YTg0OWItNGQxNy00MDM5LWI3NmEtNThjOTk1YjUzYzdmLmQyOTM5NWY4LWVjOTUtNDEyOS1hMDk2LWFiMjcxNDU4Y2RmNHgxNzkwODUwMDk2NjgyOTUzMDAw parts=1230372026/10/01 10:21:38 INFO Received cleanup request method=DELETE path=/api/pending_closures30382026/10/01 10:21:38 INFO Aborted multipart uploads count=1 kept=03039--- PASS: TestRedundantMultipartUpload (6.83s)30402026/10/01 10:21:38 OK 20241026095416_initial_model.sql (258.74ms)30412026/10/01 10:21:38 OK 20251210153512_drop_unused_gin_index.sql (7.48ms)30422026/10/01 10:21:39 OK 20251218171726_add_pins.sql (40.15ms)30432026/10/01 10:21:39 OK 20260628120000_add_object_size_and_stats.sql (31.19ms)30442026/10/01 10:21:39 INFO Received uploads request method=POST path=/api/pending_closures30452026/10/01 10:21:39 OK 20260905000000_add_claims.sql (65.02ms)30462026/10/01 10:21:39 INFO Aborted multipart uploads count=0 kept=030472026/10/01 10:21:39 WARN Force mode enabled - objects will be deleted immediately without grace period30482026/10/01 10:21:39 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=030492026/10/01 10:21:39 INFO Vacuumed table table=pending_closures30502026/10/01 10:21:39 OK 20260920000000_drop_claims.sql (28.29ms)30512026/10/01 10:21:39 INFO Vacuumed table table=pending_objects30522026/10/01 10:21:39 OK 20260923120000_add_pushes.sql (18.83ms)30532026/10/01 10:21:39 goose: successfully migrated database to version: 2026092312000030542026/10/01 10:21:39 INFO Vacuumed table table=multipart_uploads30552026/10/01 10:21:39 INFO Vacuumed table table=closures30562026/10/01 10:21:39 OK 1_commit_pending_closure.sql (1.63ms)30572026/10/01 10:21:39 OK 2_object_stats_trigger.sql (348.92µs)30582026/10/01 10:21:39 OK 3_commit_push.sql (230.88µs)30592026/10/01 10:21:39 goose: up to current file version: 330602026/10/01 10:21:39 INFO Vacuumed table table=objects3061--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)3062 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (4.34s)3063 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (4.28s)30642026/10/01 10:21:39 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30652026/10/01 10:21:39 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=197.071598ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30662026/10/01 10:21:39 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=386.197736ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30672026/10/01 10:21:40 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30682026/10/01 10:21:40 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30692026/10/01 10:21:40 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=794.560607ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30702026/10/01 10:21:40 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.676981802s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30712026/10/01 10:21:42 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"30722026/10/01 10:21:42 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30732026/10/01 10:21:42 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=208.087562ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30742026/10/01 10:21:42 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=367.28793ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30752026/10/01 10:21:43 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=854.740647ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30762026/10/01 10:21:44 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.629149723s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30772026/10/01 10:21:45 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30782026/10/01 10:21:45 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=199.256056ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30792026/10/01 10:21:46 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=417.675617ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30802026/10/01 10:21:46 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=741.094498ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30812026/10/01 10:21:47 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.493806665s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3082--- PASS: TestClientErrorHandling (0.00s)3083 --- PASS: TestClientErrorHandling/InvalidStorePath (4.09s)3084 --- PASS: TestClientErrorHandling/InvalidAuthToken (4.15s)3085 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.96s)3086PASS3087{"timestamp":"2026-10-01T10:21:48.755005Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60407","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}30882026-10-01 10:21:49.737 UTC [27021] LOG: received smart shutdown request30892026-10-01 10:21:49.739 UTC [27021] LOG: background worker "logical replication launcher" (PID 27036) exited with exit code 130902026-10-01 10:21:49.749 UTC [27031] LOG: shutting down30912026-10-01 10:21:49.750 UTC [27031] LOG: checkpoint starting: shutdown immediate30922026/10/01 10:21:58 ERROR failed to kill rustfs error="no such process"30932026/10/01 10:21:59 INFO killed rustfs30942026/10/01 10:21:59 ERROR failed to wait for rustfs error="signal: killed"30952026-10-01 10:21:59.790 UTC [27031] PANIC: could not fsync file "base/17885/4146": No such file or directory3096Running OIDC tests...3097=== RUN TestAudienceForIssuer3098=== PAUSE TestAudienceForIssuer3099=== RUN TestGlobMatch3100=== PAUSE TestGlobMatch3101=== RUN TestValidateToken_ValidToken3102=== PAUSE TestValidateToken_ValidToken3103=== RUN TestValidateToken_WrongAudience3104=== PAUSE TestValidateToken_WrongAudience3105=== RUN TestValidateToken_Expired3106=== PAUSE TestValidateToken_Expired3107=== RUN TestValidateToken_BoundClaimsMismatch3108=== PAUSE TestValidateToken_BoundClaimsMismatch3109=== RUN TestValidateToken_BoundSubjectMismatch3110=== PAUSE TestValidateToken_BoundSubjectMismatch3111=== RUN TestValidateToken_MultipleProviders3112=== PAUSE TestValidateToken_MultipleProviders3113=== RUN TestValidateToken_NoMatchingProvider3114=== PAUSE TestValidateToken_NoMatchingProvider3115=== RUN TestValidateToken_KubernetesServiceAccount3116=== PAUSE TestValidateToken_KubernetesServiceAccount3117=== RUN TestNewValidator_KubernetesRequiresCA3118=== PAUSE TestNewValidator_KubernetesRequiresCA3119=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3120=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3121=== RUN TestPins_ReservedForMatchingRule3122=== PAUSE TestPins_ReservedForMatchingRule3123=== RUN TestPins_TopLevelShorthand3124=== PAUSE TestPins_TopLevelShorthand3125=== RUN TestPins_ConfigValidation3126=== PAUSE TestPins_ConfigValidation3127=== RUN TestScopes_LegacyProviderDefaultsToWrite3128=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3129=== RUN TestScopes_Rules3130=== PAUSE TestScopes_Rules3131=== RUN TestScopes_ConfigValidation3132=== PAUSE TestScopes_ConfigValidation3133=== CONT TestAudienceForIssuer3134--- PASS: TestAudienceForIssuer (0.00s)3135=== CONT TestValidateToken_NoMatchingProvider3136=== CONT TestPins_ConfigValidation3137=== CONT TestScopes_ConfigValidation3138=== CONT TestPins_ReservedForMatchingRule3139=== CONT TestScopes_LegacyProviderDefaultsToWrite3140=== CONT TestValidateToken_KubernetesServiceAccount3141=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3142=== CONT TestNewValidator_KubernetesRequiresCA3143--- PASS: TestPins_ConfigValidation (0.00s)3144=== CONT TestValidateToken_MultipleProviders3145--- PASS: TestScopes_ConfigValidation (0.00s)3146=== CONT TestValidateToken_BoundClaimsMismatch3147=== CONT TestScopes_Rules3148=== CONT TestValidateToken_BoundSubjectMismatch31492026/10/01 10:22:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60543/oidc31502026/10/01 10:22:07 http: TLS handshake error from 127.0.0.1:60545: read tcp 127.0.0.1:60544->127.0.0.1:60545: use of closed network connection3151--- PASS: TestNewValidator_KubernetesRequiresCA (0.34s)3152=== CONT TestPins_TopLevelShorthand3153--- PASS: TestValidateToken_BoundClaimsMismatch (0.40s)3154=== CONT TestValidateToken_ValidToken31552026/10/01 10:22:07 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:605473156--- PASS: TestValidateToken_KubernetesServiceAccount (0.45s)3157=== CONT TestValidateToken_WrongAudience31582026/10/01 10:22:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60549/oidc3159--- PASS: TestScopes_Rules (0.67s)3160=== CONT TestGlobMatch3161=== RUN TestGlobMatch/foo_foo3162=== PAUSE TestGlobMatch/foo_foo3163=== RUN TestGlobMatch/foo_bar3164=== PAUSE TestGlobMatch/foo_bar3165=== RUN TestGlobMatch/*_3166=== PAUSE TestGlobMatch/*_3167=== RUN TestGlobMatch/*_anything3168=== PAUSE TestGlobMatch/*_anything3169=== RUN TestGlobMatch/foo*_foo3170=== PAUSE TestGlobMatch/foo*_foo3171=== RUN TestGlobMatch/foo*_foobar3172=== PAUSE TestGlobMatch/foo*_foobar3173=== RUN TestGlobMatch/foo*_bar3174=== PAUSE TestGlobMatch/foo*_bar3175=== RUN TestGlobMatch/*bar_bar3176=== PAUSE TestGlobMatch/*bar_bar3177=== RUN TestGlobMatch/*bar_foobar3178=== PAUSE TestGlobMatch/*bar_foobar3179=== RUN TestGlobMatch/*bar_foo3180=== PAUSE TestGlobMatch/*bar_foo3181=== RUN TestGlobMatch/foo*bar_foobar3182=== PAUSE TestGlobMatch/foo*bar_foobar3183=== RUN TestGlobMatch/foo*bar_foo123bar3184=== PAUSE TestGlobMatch/foo*bar_foo123bar3185=== RUN TestGlobMatch/foo*bar_foobarbaz3186=== PAUSE TestGlobMatch/foo*bar_foobarbaz3187=== RUN TestGlobMatch/*/*_foo/bar3188=== PAUSE TestGlobMatch/*/*_foo/bar3189=== RUN TestGlobMatch/*/*_foo3190=== PAUSE TestGlobMatch/*/*_foo3191=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3192=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3193=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03194=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03195=== RUN TestGlobMatch/refs/*/main_refs/heads/main3196=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3197=== RUN TestGlobMatch/fo?_foo3198=== PAUSE TestGlobMatch/fo?_foo3199=== RUN TestGlobMatch/fo?_fo3200=== PAUSE TestGlobMatch/fo?_fo3201=== RUN TestGlobMatch/fo?_fooo3202=== PAUSE TestGlobMatch/fo?_fooo3203=== RUN TestGlobMatch/?oo_foo3204=== PAUSE TestGlobMatch/?oo_foo3205=== RUN TestGlobMatch/?oo_boo3206=== PAUSE TestGlobMatch/?oo_boo3207=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3208=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3209=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3210=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3211=== CONT TestValidateToken_Expired32122026/10/01 10:22:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60551/oidc3213--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.76s)3214=== CONT TestGlobMatch/foo_foo32152026/10/01 10:22:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60554/oidc3216=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3217=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3218=== CONT TestGlobMatch/?oo_boo3219=== CONT TestGlobMatch/?oo_foo3220=== CONT TestGlobMatch/fo?_fooo3221=== CONT TestGlobMatch/fo?_fo3222=== CONT TestGlobMatch/fo?_foo3223=== CONT TestGlobMatch/refs/*/main_refs/heads/main3224=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03225=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3226=== CONT TestGlobMatch/*/*_foo3227=== CONT TestGlobMatch/*/*_foo/bar3228=== CONT TestGlobMatch/foo*bar_foobarbaz3229=== CONT TestGlobMatch/foo*bar_foo123bar3230=== CONT TestGlobMatch/foo*bar_foobar3231=== CONT TestGlobMatch/*bar_foo3232=== CONT TestGlobMatch/*bar_foobar3233=== CONT TestGlobMatch/*bar_bar3234=== CONT TestGlobMatch/foo*_bar3235=== CONT TestGlobMatch/foo*_foobar3236=== CONT TestGlobMatch/foo*_foo3237=== CONT TestGlobMatch/*_anything3238=== CONT TestGlobMatch/*_3239=== CONT TestGlobMatch/foo_bar3240--- PASS: TestGlobMatch (0.00s)3241 --- PASS: TestGlobMatch/foo_foo (0.00s)3242 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3243 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3244 --- PASS: TestGlobMatch/?oo_boo (0.00s)3245 --- PASS: TestGlobMatch/?oo_foo (0.00s)3246 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3247 --- PASS: TestGlobMatch/fo?_fo (0.00s)3248 --- PASS: TestGlobMatch/fo?_foo (0.00s)3249 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3250 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3251 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3252 --- PASS: TestGlobMatch/*/*_foo (0.00s)3253 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3254 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3255 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3256 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3257 --- PASS: TestGlobMatch/*bar_foo (0.00s)3258 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3259 --- PASS: TestGlobMatch/*bar_bar (0.00s)3260 --- PASS: TestGlobMatch/foo*_bar (0.00s)3261 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3262 --- PASS: TestGlobMatch/foo*_foo (0.00s)3263 --- PASS: TestGlobMatch/*_anything (0.00s)3264 --- PASS: TestGlobMatch/*_ (0.00s)3265 --- PASS: TestGlobMatch/foo_bar (0.00s)32662026/10/01 10:22:08 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233267--- PASS: TestPins_ReservedForMatchingRule (0.77s)3268--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.92s)32692026/10/01 10:22:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60559/oidc3270--- PASS: TestValidateToken_BoundSubjectMismatch (0.92s)32712026/10/01 10:22:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60561/oidc3272--- PASS: TestPins_TopLevelShorthand (0.88s)32732026/10/01 10:22:08 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60552/oidc32742026/10/01 10:22:08 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:60563/oidc3275--- PASS: TestValidateToken_MultipleProviders (1.26s)32762026/10/01 10:22:08 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:60558/oidc3277--- PASS: TestValidateToken_NoMatchingProvider (1.47s)32782026/10/01 10:22:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60568/oidc3279--- PASS: TestValidateToken_ValidToken (1.18s)32802026/10/01 10:22:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60570/oidc3281--- PASS: TestValidateToken_Expired (0.89s)32822026/10/01 10:22:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:60572/oidc3283--- PASS: TestValidateToken_WrongAudience (1.22s)3284PASS3285Running hook tests...3286=== RUN TestSendPathsEmpty3287=== PAUSE TestSendPathsEmpty3288=== RUN TestQueueEnqueueAndFetch3289=== PAUSE TestQueueEnqueueAndFetch3290=== RUN TestQueueDeduplication3291=== PAUSE TestQueueDeduplication3292=== RUN TestQueueRemove3293=== PAUSE TestQueueRemove3294=== RUN TestQueueFetchBatchLimit3295=== PAUSE TestQueueFetchBatchLimit3296=== RUN TestQueueRetryMovesToBack3297=== PAUSE TestQueueRetryMovesToBack3298=== RUN TestQueueFetchRemoveLifecycle3299=== PAUSE TestQueueFetchRemoveLifecycle3300=== RUN TestQueueConcurrentWriters3301=== PAUSE TestQueueConcurrentWriters3302=== RUN TestQueueRemoveLargeClosure3303=== PAUSE TestQueueRemoveLargeClosure3304=== RUN TestServerClientIntegration3305=== PAUSE TestServerClientIntegration3306=== RUN TestServerQueueError3307=== PAUSE TestServerQueueError3308=== RUN TestGetListenerSocketActivation3309 server_test.go:210: === RUN TestGetListenerSocketActivation3310 --- PASS: TestGetListenerSocketActivation (0.00s)3311 PASS3312 3313--- PASS: TestGetListenerSocketActivation (0.01s)3314=== RUN TestDrainIsolatesPoisonPath3315=== PAUSE TestDrainIsolatesPoisonPath3316=== RUN TestRunNotBlockedByPoisonHead3317=== PAUSE TestRunNotBlockedByPoisonHead3318=== RUN TestDrainGivesUpWhenServerDown3319=== PAUSE TestDrainGivesUpWhenServerDown3320=== RUN TestFailedPathPrunedByLaterClosure3321=== PAUSE TestFailedPathPrunedByLaterClosure3322=== RUN TestWorkerUploadsAndRemoves3323=== PAUSE TestWorkerUploadsAndRemoves3324=== RUN TestWorkerSkipsGCdPaths3325=== PAUSE TestWorkerSkipsGCdPaths3326=== RUN TestWorkerPrunesClosureDeps3327=== PAUSE TestWorkerPrunesClosureDeps3328=== RUN TestDrainTimeout3329=== PAUSE TestDrainTimeout3330=== CONT TestSendPathsEmpty3331=== CONT TestQueueConcurrentWriters3332--- PASS: TestSendPathsEmpty (0.00s)3333=== CONT TestQueueFetchRemoveLifecycle3334=== CONT TestServerQueueError3335=== CONT TestDrainTimeout3336=== CONT TestWorkerPrunesClosureDeps3337=== CONT TestWorkerSkipsGCdPaths3338=== CONT TestWorkerUploadsAndRemoves3339=== CONT TestFailedPathPrunedByLaterClosure3340=== CONT TestDrainGivesUpWhenServerDown3341=== CONT TestRunNotBlockedByPoisonHead33422026/10/01 10:22:09 ERROR Failed to queue paths error="permission denied" count=13343--- PASS: TestServerQueueError (0.00s)3344=== CONT TestDrainIsolatesPoisonPath3345--- PASS: TestQueueFetchRemoveLifecycle (0.01s)3346=== CONT TestQueueRetryMovesToBack33472026/10/01 10:22:09 INFO Uploading batch count=233482026/10/01 10:22:09 ERROR Upload failed error="upload failed" count=233492026/10/01 10:22:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26883-1285942671/TestDrainGivesUpWhenServerDown3728452978/002/a33502026/10/01 10:22:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26883-1285942671/TestDrainGivesUpWhenServerDown3728452978/002/b33512026/10/01 10:22:09 INFO Uploading batch count=233522026/10/01 10:22:09 ERROR Upload failed error="upload failed" count=233532026/10/01 10:22:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26883-1285942671/TestDrainGivesUpWhenServerDown3728452978/002/c33542026/10/01 10:22:09 INFO Uploading batch count=133552026/10/01 10:22:09 ERROR Upload failed error="upload failed" count=133562026/10/01 10:22:09 INFO Upload queue status pending=233572026/10/01 10:22:09 INFO Uploading batch count=13358--- PASS: TestQueueRetryMovesToBack (0.00s)3359=== CONT TestServerClientIntegration33602026/10/01 10:22:09 INFO Uploading batch count=133612026/10/01 10:22:09 INFO Uploading batch count=233622026/10/01 10:22:09 INFO Uploading batch count=433632026/10/01 10:22:09 ERROR Upload failed error="upload failed" count=433642026/10/01 10:22:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26883-1285942671/TestDrainIsolatesPoisonPath186897662/002/bbb33652026/10/01 10:22:09 INFO Uploading batch count=133662026/10/01 10:22:09 ERROR Upload failed error="upload failed" count=13367--- PASS: TestServerClientIntegration (0.00s)3368=== CONT TestQueueRemoveLargeClosure33692026/10/01 10:22:09 INFO Uploading batch count=133702026/10/01 10:22:09 ERROR Upload failed error="upload failed" count=133712026/10/01 10:22:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26883-1285942671/TestDrainGivesUpWhenServerDown3728452978/002/d33722026/10/01 10:22:09 INFO Uploading batch count=133732026/10/01 10:22:09 INFO Upload queue status pending=233742026/10/01 10:22:09 INFO Uploading batch count=233752026/10/01 10:22:09 INFO Uploading batch count=133762026/10/01 10:22:09 ERROR Upload failed error="upload failed" count=133772026/10/01 10:22:09 INFO Upload queue status pending=333782026/10/01 10:22:09 INFO Uploading batch count=133792026/10/01 10:22:09 ERROR Upload failed error="upload failed" count=133802026/10/01 10:22:09 ERROR Drain finished with paths left in queue remaining=133812026/10/01 10:22:09 INFO Uploading batch count=233822026/10/01 10:22:09 ERROR Upload failed error="upload failed" count=233832026/10/01 10:22:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26883-1285942671/TestDrainGivesUpWhenServerDown3728452978/002/e33842026/10/01 10:22:09 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-26883-1285942671/TestDrainGivesUpWhenServerDown3728452978/002/f33852026/10/01 10:22:09 ERROR Drain finished with paths left in queue remaining=103386--- PASS: TestDrainIsolatesPoisonPath (0.01s)3387=== CONT TestQueueFetchBatchLimit3388--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)3389=== CONT TestQueueRemove33902026/10/01 10:22:09 INFO Upload queue status pending=233912026/10/01 10:22:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-26883-1285942671/TestWorkerSkipsGCdPaths1242781132/002/nonexistent3392--- PASS: TestDrainGivesUpWhenServerDown (0.01s)3393=== CONT TestQueueDeduplication33942026/10/01 10:22:09 INFO Uploading batch count=13395--- PASS: TestQueueRemove (0.01s)3396=== CONT TestQueueEnqueueAndFetch3397--- PASS: TestQueueEnqueueAndFetch (0.00s)3398--- PASS: TestQueueFetchBatchLimit (0.01s)3399--- PASS: TestQueueDeduplication (0.01s)3400--- PASS: TestWorkerPrunesClosureDeps (0.03s)3401--- PASS: TestWorkerUploadsAndRemoves (0.03s)3402--- PASS: TestWorkerSkipsGCdPaths (0.04s)3403--- PASS: TestQueueConcurrentWriters (0.15s)34042026/10/01 10:22:09 ERROR Upload failed error="context deadline exceeded" count=234052026/10/01 10:22:09 ERROR Drain finished with paths left in queue remaining=43406--- PASS: TestDrainTimeout (0.21s)3407--- PASS: TestQueueRemoveLargeClosure (0.28s)34082026/10/01 10:22:10 INFO Uploading batch count=134092026/10/01 10:22:10 INFO Uploading batch count=134102026/10/01 10:22:10 INFO Uploading batch count=134112026/10/01 10:22:10 ERROR Upload failed error="upload failed" count=134122026/10/01 10:22:10 INFO Uploading batch count=134132026/10/01 10:22:10 ERROR Upload failed error="upload failed" count=134142026/10/01 10:22:10 INFO Uploading batch count=134152026/10/01 10:22:10 ERROR Upload failed error="upload failed" count=134162026/10/01 10:22:10 INFO Uploading batch count=134172026/10/01 10:22:10 ERROR Upload failed error="upload failed" count=134182026/10/01 10:22:10 ERROR Drain finished with paths left in queue remaining=13419--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3420PASS