niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #288
· 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.17s)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 TestShellSplit96=== CONT TestSetClientTLSDoesNotMutateDefaultTransport97--- PASS: TestShellSplit (0.00s)98=== CONT TestStreamPushBatchesUnderLoad99=== CONT TestSetClientTLS100=== CONT TestClientSignaturesByStorePath101=== CONT TestStreamPushReportsSignatures102=== CONT TestStreamPushRequestLine103=== CONT TestStreamPushGivesUpOnDeadServer104=== CONT TestStreamPushIsolatesFailures1052026/10/01 07:36:43 ERROR Upload failed error="connection refused" count=201062026/10/01 07:36:43 ERROR Server seems unavailable, giving up on batch untried=171072026/10/01 07:36:43 ERROR Upload failed error=boom count=1108=== CONT TestShellSplitErrors109=== CONT TestScriptTokenEmptyCommand110=== CONT TestEncodeNixBase32WithRealHash111=== CONT TestScriptTokenScriptFails1122026/10/01 07:36:43 ERROR Upload failed error=boom count=11132026/10/01 07:36:43 ERROR Upload failed error="bad path" count=3114=== CONT TestScriptTokenBadJSON115=== CONT TestSetClientTLSErrors116=== CONT TestDoWithRetry_BodyReplayedViaGetBody117--- PASS: TestClientSignaturesByStorePath (0.00s)118--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)119--- PASS: TestShellSplitErrors (0.00s)120--- PASS: TestScriptTokenEmptyCommand (0.00s)121--- PASS: TestEncodeNixBase32WithRealHash (0.00s)122--- PASS: TestStreamPushReportsSignatures (0.00s)123--- PASS: TestStreamPushIsolatesFailures (0.00s)124=== CONT TestStreamPushReportsEveryPath125--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)126=== CONT TestScriptTokenEmptyToken1272026/10/01 07:36:43 WARN Rate limiter enabled after throttle name=server-test rate=51282026/10/01 07:36:43 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:55937129--- PASS: TestStreamPushReportsEveryPath (0.00s)130=== CONT TestScriptTokenCachesUntilRefresh131=== RUN TestSetClientTLSErrors/missing_cert_file132=== PAUSE TestSetClientTLSErrors/missing_cert_file133=== RUN TestSetClientTLSErrors/missing_key_file134=== PAUSE TestSetClientTLSErrors/missing_key_file135=== RUN TestSetClientTLSErrors/missing_ca_file136=== PAUSE TestSetClientTLSErrors/missing_ca_file137=== CONT TestScriptTokenNoExpiryRerunsEveryCall138=== RUN TestSetClientTLSErrors/invalid_ca_file139=== PAUSE TestSetClientTLSErrors/invalid_ca_file140--- PASS: TestDoServerRequestAttachesToken (0.01s)141=== CONT TestResolveStorePath142=== RUN TestSetClientTLS/rejects_connection_without_client_cert143=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert144=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA145=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA146=== RUN TestSetClientTLS/preserves_debug_logging_transport147=== PAUSE TestSetClientTLS/preserves_debug_logging_transport148=== CONT TestFileTokenEmpty149--- PASS: TestScriptTokenScriptFails (0.00s)150=== CONT TestFileTokenMissing1512026/10/01 07:36:43 WARN Rate limiter backed off name=server-test rate=51522026/10/01 07:36:43 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:55937153--- PASS: TestFileTokenMissing (0.00s)154=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1552026/10/01 07:36:43 WARN Rate limiter enabled after throttle name=server-test rate=5156--- PASS: TestFileTokenEmpty (0.00s)157--- PASS: TestResolveStorePath (0.00s)158=== CONT TestRateLimiterFeedback159=== RUN TestRateLimiterFeedback/429_enables_limiter160=== PAUSE TestRateLimiterFeedback/429_enables_limiter161=== RUN TestRateLimiterFeedback/503_enables_limiter162=== PAUSE TestRateLimiterFeedback/503_enables_limiter163=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter164=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter165=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter166--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)167=== CONT TestStaticToken168--- PASS: TestStaticToken (0.00s)169=== CONT TestPathInfoCACompatibility170=== RUN TestPathInfoCACompatibility/null_ca_field171=== PAUSE TestPathInfoCACompatibility/null_ca_field172=== RUN TestPathInfoCACompatibility/old_string_format_-_text173=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text174=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive175=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive176=== RUN TestPathInfoCACompatibility/new_structured_format_-_text177=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text178=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method179=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method180=== CONT TestFileTokenReadsAndCaches181=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter182=== CONT TestParsePathInfoJSONMultiplePaths183=== CONT TestUploadMultipart_SupersededByPeer184=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths185=== RUN TestUploadMultipart_SupersededByPeer/exists186=== PAUSE TestUploadMultipart_SupersededByPeer/exists187=== RUN TestUploadMultipart_SupersededByPeer/missing188=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths189=== PAUSE TestUploadMultipart_SupersededByPeer/missing190=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths191--- PASS: TestFileTokenReadsAndCaches (0.00s)192=== CONT TestParsePathInfoJSON193=== RUN TestParsePathInfoJSON/Nix_format194=== PAUSE TestParsePathInfoJSON/Nix_format195=== RUN TestParsePathInfoJSON/Lix_format196=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths197=== CONT TestEncodeNixBase32198=== RUN TestEncodeNixBase32/test_string_hash199=== PAUSE TestEncodeNixBase32/test_string_hash200=== RUN TestEncodeNixBase32/empty_input201=== PAUSE TestEncodeNixBase32/empty_input202=== CONT TestPathInfoHashCompatibility203=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)204=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)205=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon206=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon207=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI208=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI209=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512210=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512211=== CONT TestDumpPathWriterError212=== PAUSE TestParsePathInfoJSON/Lix_format213=== RUN TestParsePathInfoJSON/empty_input214=== PAUSE TestParsePathInfoJSON/empty_input215=== RUN TestParsePathInfoJSON/whitespace_only216=== PAUSE TestParsePathInfoJSON/whitespace_only217=== RUN TestParsePathInfoJSON/invalid_JSON218=== PAUSE TestParsePathInfoJSON/invalid_JSON219--- PASS: TestScriptTokenBadJSON (0.01s)220=== CONT TestDumpPathSingleFile221=== CONT TestConvertHashToNix32222=== CONT TestGetStorePathHash223=== RUN TestConvertHashToNix32/SRI_format_to_Nix32224=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32225=== RUN TestConvertHashToNix32/already_Nix32_format226=== PAUSE TestConvertHashToNix32/already_Nix32_format227=== RUN TestConvertHashToNix32/invalid_format228=== PAUSE TestConvertHashToNix32/invalid_format229=== RUN TestGetStorePathHash/valid_store_path230=== PAUSE TestGetStorePathHash/valid_store_path231=== RUN TestGetStorePathHash/basename_without_hyphen_should_error232=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error233=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error234=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error235=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error236=== CONT TestDumpPathMatchesNix237=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error238=== CONT TestPartSizeForNAR239=== RUN TestPartSizeForNAR/zero_stays_at_minimum240=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum241=== RUN TestPartSizeForNAR/small_stays_at_minimum242--- PASS: TestScriptTokenEmptyToken (0.01s)243=== PAUSE TestPartSizeForNAR/small_stays_at_minimum244=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum245=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum246=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts247=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts248=== RUN TestPartSizeForNAR/1_TiB249=== PAUSE TestPartSizeForNAR/1_TiB250=== RUN TestPartSizeForNAR/5_TiB_S3_max_object251=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object252=== RUN TestPartSizeForNAR/capped_at_5_GiB253=== PAUSE TestPartSizeForNAR/capped_at_5_GiB254=== CONT TestRegisterUploadedObjectReusesConnections255=== CONT TestCaseHackSuffix256--- PASS: TestStreamPushRequestLine (0.03s)257=== CONT TestUploadMultipart_PartsInParallel258--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)259=== CONT TestFilterOversizedClosures260=== RUN TestFilterOversizedClosures/no_limit_keeps_everything261=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything262=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped263=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped264=== RUN TestFilterOversizedClosures/all_closures_skipped265=== PAUSE TestFilterOversizedClosures/all_closures_skipped266=== CONT TestSetClientTLSErrors/missing_cert_file267=== CONT TestSetClientTLS/rejects_connection_without_client_cert268--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)269=== CONT TestSetClientTLS/preserves_debug_logging_transport270=== CONT TestSetClientTLSErrors/missing_ca_file271=== CONT TestSetClientTLSErrors/invalid_ca_file272=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA273=== CONT TestSetClientTLSErrors/missing_key_file274=== CONT TestPathInfoCACompatibility/null_ca_field275=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method276=== CONT TestRateLimiterFeedback/429_enables_limiter277--- PASS: TestSetClientTLSErrors (0.01s)278 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)279 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)280 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)281 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)2822026/10/01 07:36:43 WARN Rate limiter enabled after throttle name=server-test rate=52832026/10/01 07:36:43 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:560132842026/10/01 07:36:43 WARN Rate limiter backed off name=server-test rate=5285=== CONT TestPathInfoCACompatibility/new_structured_format_-_text286=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive287=== CONT TestPathInfoCACompatibility/old_string_format_-_text288--- PASS: TestPathInfoCACompatibility (0.00s)289 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)290 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)291 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)292 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)293 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)294=== CONT TestRateLimiterFeedback/503_enables_limiter2952026/10/01 07:36:43 WARN Rate limiter enabled after throttle name=server-test rate=52962026/10/01 07:36:43 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:560172972026/10/01 07:36:43 WARN Rate limiter backed off name=server-test rate=5298=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2992026/10/01 07:36:43 http: TLS handshake error from 127.0.0.1:56008: read tcp 127.0.0.1:55939->127.0.0.1:56008: use of closed network connection300--- PASS: TestSetClientTLS (0.01s)301 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)302 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)303 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)304=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter305=== CONT TestUploadMultipart_SupersededByPeer/exists306--- PASS: TestRateLimiterFeedback (0.00s)307 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)308 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)309 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)310 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)311=== CONT TestUploadMultipart_SupersededByPeer/missing312=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths313=== CONT TestEncodeNixBase32/test_string_hash314=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)315=== CONT TestEncodeNixBase32/empty_input316=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI317--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)318 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)319 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)320--- PASS: TestDumpPathWriterError (0.05s)321=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon322=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512323=== CONT TestParsePathInfoJSON/Nix_format324--- PASS: TestPathInfoHashCompatibility (0.00s)325 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)326 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)327 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)328 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)329--- PASS: TestEncodeNixBase32 (0.00s)330 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)331 --- PASS: TestEncodeNixBase32/empty_input (0.00s)332=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths333=== CONT TestParsePathInfoJSON/invalid_JSON334=== CONT TestParsePathInfoJSON/empty_input335=== CONT TestParsePathInfoJSON/Lix_format336=== CONT TestConvertHashToNix32/SRI_format_to_Nix32337--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)338 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)339 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)340=== CONT TestParsePathInfoJSON/whitespace_only341=== CONT TestConvertHashToNix32/already_Nix32_format342--- PASS: TestParsePathInfoJSON (0.00s)343 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)344 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)345 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)346 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)347 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)348=== CONT TestConvertHashToNix32/invalid_format349--- PASS: TestConvertHashToNix32 (0.00s)350 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)351 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)352 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)353=== CONT TestGetStorePathHash/valid_store_path354=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error355=== CONT TestPartSizeForNAR/5_TiB_S3_max_object356=== CONT TestPartSizeForNAR/zero_stays_at_minimum357=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error358=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts359=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum360=== CONT TestPartSizeForNAR/capped_at_5_GiB361=== CONT TestPartSizeForNAR/small_stays_at_minimum362=== CONT TestPartSizeForNAR/1_TiB363--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)364=== CONT TestFilterOversizedClosures/all_closures_skipped365--- PASS: TestPartSizeForNAR (0.00s)366 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)367 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)368 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)369 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)370 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)371 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)372 --- PASS: TestPart2026/10/01 07:36:43 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50373SizeForNAR/1_TiB (0.00s)374=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3752026/10/01 07:36:43 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=2000376=== CONT TestGetStorePathHash/basename_without_hyphen_should_error377--- PASS: TestGetStorePathHash (0.00s)378 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)379 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)380 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)381 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)382=== CONT TestFilterOversizedClosures/no_limit_keeps_everything383--- PASS: TestFilterOversizedClosures (0.00s)384 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)385 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)386 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)387--- PASS: TestStreamPushBatchesUnderLoad (0.10s)388--- PASS: TestCaseHackSuffix (0.21s)389--- PASS: TestDumpPathSingleFile (0.22s)390--- PASS: TestDumpPathMatchesNix (0.39s)391--- PASS: TestUploadMultipart_PartsInParallel (0.63s)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-54868-424906470/postgres3189583463/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-54868-424906470/postgres3189583463/data -l logfile start421422/nix/var/nix/builds/nix-54868-424906470/postgres3189583463:5432 - no response4232026-10-01 07:36:46.165 UTC [55546] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4242026-10-01 07:36:46.165 UTC [55546] LOG: listening on Unix socket "/nix/var/nix/builds/nix-54868-424906470/postgres3189583463/.s.PGSQL.5432"4252026-10-01 07:36:46.174 UTC [55553] LOG: database system was shut down at 2026-10-01 07:36:46 UTC4262026-10-01 07:36:46.176 UTC [55546] LOG: database system is ready to accept connections427/nix/var/nix/builds/nix-54868-424906470/postgres3189583463:5432 - accepting connections428{"timestamp":"2026-10-01T07:36:46.39457Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"04c59243-2a1f-48fd-9f8f-379dc1a267cd","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(4)"}429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestClientPushesUseOnePush462=== PAUSE TestClientPushesUseOnePush463=== RUN TestClientFallsBackToClosures464=== PAUSE TestClientFallsBackToClosures465=== RUN TestResolveDBConnectionString466=== PAUSE TestResolveDBConnectionString467=== RUN TestLeadElectsOneAndHandsOver468=== PAUSE TestLeadElectsOneAndHandsOver469=== RUN TestLeadIncumbentWinsAfterRestart4702026-10-01 07:36:46.727 UTC [55628] ERROR: relation "goose_db_version" does not exist at character 364712026-10-01 07:36:46.727 UTC [55628] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4722026/10/01 07:36:46 OK 20241026095416_initial_model.sql (5.69ms)4732026/10/01 07:36:46 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)4742026/10/01 07:36:46 OK 20251218171726_add_pins.sql (2.66ms)4752026/10/01 07:36:46 OK 20260628120000_add_object_size_and_stats.sql (3.5ms)4762026/10/01 07:36:46 OK 20260905000000_add_claims.sql (17.69ms)4772026/10/01 07:36:46 OK 20260920000000_drop_claims.sql (1.67ms)4782026/10/01 07:36:46 OK 20260923120000_add_pushes.sql (1.46ms)4792026/10/01 07:36:46 goose: successfully migrated database to version: 202609231200004802026/10/01 07:36:46 OK 1_commit_pending_closure.sql (2.96ms)4812026/10/01 07:36:46 OK 2_object_stats_trigger.sql (2.58ms)4822026/10/01 07:36:46 OK 3_commit_push.sql (540.17µs)4832026/10/01 07:36:46 goose: up to current file version: 34842026/10/01 07:36:46 INFO lead: acquired remote=192.0.2.1:12344852026/10/01 07:36:47 INFO lead: released remote=192.0.2.1:12344862026/10/01 07:36:47 INFO lead: acquired remote=192.0.2.1:12344872026/10/01 07:36:47 INFO lead: released remote=192.0.2.1:1234488--- PASS: TestLeadIncumbentWinsAfterRestart (1.13s)489=== RUN TestLeadEndsOnShutdown490=== PAUSE TestLeadEndsOnShutdown491=== RUN TestGCAdvisoryLockBlocksConcurrentRun4922026-10-01 07:36:47.690 UTC [55790] ERROR: relation "goose_db_version" does not exist at character 364932026-10-01 07:36:47.690 UTC [55790] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4942026/10/01 07:36:47 OK 20241026095416_initial_model.sql (6.26ms)4952026/10/01 07:36:47 OK 20251210153512_drop_unused_gin_index.sql (3.88ms)4962026/10/01 07:36:47 OK 20251218171726_add_pins.sql (2.56ms)4972026/10/01 07:36:47 OK 20260628120000_add_object_size_and_stats.sql (2.38ms)4982026/10/01 07:36:47 OK 20260905000000_add_claims.sql (3.51ms)4992026/10/01 07:36:47 OK 20260920000000_drop_claims.sql (1.52ms)5002026/10/01 07:36:47 OK 20260923120000_add_pushes.sql (1.76ms)5012026/10/01 07:36:47 goose: successfully migrated database to version: 202609231200005022026/10/01 07:36:47 OK 1_commit_pending_closure.sql (2.16ms)5032026/10/01 07:36:47 OK 2_object_stats_trigger.sql (981.83µs)5042026/10/01 07:36:47 OK 3_commit_push.sql (568.5µs)5052026/10/01 07:36:47 goose: up to current file version: 3506--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.20s)507=== RUN TestGCBugBareHashReferences508=== PAUSE TestGCBugBareHashReferences509=== RUN TestGCMetrics510=== PAUSE TestGCMetrics511=== RUN TestPushDedupSurvivesConcurrentGC512=== PAUSE TestPushDedupSurvivesConcurrentGC513=== RUN TestDeduplicatedObjectsRecordedAsPending514=== PAUSE TestDeduplicatedObjectsRecordedAsPending515=== RUN TestGCSweepSkipsPendingObjects516=== PAUSE TestGCSweepSkipsPendingObjects517=== RUN TestTombstonedObjectOfferedWithoutWaiting518=== PAUSE TestTombstonedObjectOfferedWithoutWaiting519=== RUN TestGCSweepDeliversEachKeyOnce520=== PAUSE TestGCSweepDeliversEachKeyOnce521=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection522=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== RUN TestFailedS3DeleteKeepsTombstone524=== PAUSE TestFailedS3DeleteKeepsTombstone525=== RUN TestSweepSkipsRowsLockedByPush526=== PAUSE TestSweepSkipsRowsLockedByPush527=== RUN TestRegisterCompletedObjectNeedsPendingRow528=== PAUSE TestRegisterCompletedObjectNeedsPendingRow529=== RUN TestGetExistingObjectsLocksRows530=== PAUSE TestGetExistingObjectsLocksRows531=== RUN TestGCTaskStore_StartNew532=== PAUSE TestGCTaskStore_StartNew533=== RUN TestGCTaskStore_DeduplicateSameParams534=== PAUSE TestGCTaskStore_DeduplicateSameParams535=== RUN TestGCTaskStore_ConflictDifferentParams536=== PAUSE TestGCTaskStore_ConflictDifferentParams537=== RUN TestGCTaskStore_GetEmpty538=== PAUSE TestGCTaskStore_GetEmpty539=== RUN TestGCTaskStore_GetReturnsLatest540=== PAUSE TestGCTaskStore_GetReturnsLatest541=== RUN TestGCTaskStore_CompletedAllowsNewTask542=== PAUSE TestGCTaskStore_CompletedAllowsNewTask543=== RUN TestGCTaskStore_PhaseUpdates544=== PAUSE TestGCTaskStore_PhaseUpdates545=== RUN TestGCTaskStore_Fail546=== PAUSE TestGCTaskStore_Fail547=== RUN TestGracefulShutdownDrainsInflight548=== PAUSE TestGracefulShutdownDrainsInflight549=== RUN TestService_healthCheckHandler550=== PAUSE TestService_healthCheckHandler551=== RUN TestService_readinessHandler552=== PAUSE TestService_readinessHandler553=== RUN TestGenerateLandingPage554=== PAUSE TestGenerateLandingPage555=== RUN TestCacheConfigHandlerMaxNarSize556=== PAUSE TestCacheConfigHandlerMaxNarSize557=== RUN TestCreatePendingClosureRejectsOversizedNAR558=== PAUSE TestCreatePendingClosureRejectsOversizedNAR559=== RUN TestNARDeduplicationMetadataUploadBug560=== PAUSE TestNARDeduplicationMetadataUploadBug561=== RUN TestMetricsInventory562=== PAUSE TestMetricsInventory563=== RUN TestService_NativeMTLS564=== PAUSE TestService_NativeMTLS565=== RUN TestServerTLSConfig566=== PAUSE TestServerTLSConfig567=== RUN TestMultipartCleanup568=== PAUSE TestMultipartCleanup569=== RUN TestObjectStatsTrigger570=== PAUSE TestObjectStatsTrigger571=== RUN TestOrphanedObjectsGC572=== PAUSE TestOrphanedObjectsGC573=== RUN TestOrphanedObjectsGCStressTest574=== PAUSE TestOrphanedObjectsGCStressTest575=== RUN TestCreatePin_ReservedPins576=== PAUSE TestCreatePin_ReservedPins577=== RUN TestParseSingleRange578=== PAUSE TestParseSingleRange579=== RUN TestProxyHeadersOnlyTrustedOnSocket580=== PAUSE TestProxyHeadersOnlyTrustedOnSocket581=== RUN TestIsValidCachePath582=== PAUSE TestIsValidCachePath583=== RUN TestReadProxyNarinfo584=== PAUSE TestReadProxyNarinfo585=== RUN TestReadProxyNarinfoAlreadyDecompressed586=== PAUSE TestReadProxyNarinfoAlreadyDecompressed587=== RUN TestReadProxyNarStreaming588=== PAUSE TestReadProxyNarStreaming589=== RUN TestReadProxy404590=== PAUSE TestReadProxy404591=== RUN TestReadProxyInvalidPath592=== PAUSE TestReadProxyInvalidPath593=== RUN TestReadProxyHead594=== PAUSE TestReadProxyHead595=== RUN TestReadProxyConditionalGet596=== PAUSE TestReadProxyConditionalGet597=== RUN TestReadProxyRootRedirectsToIndexHTML598=== PAUSE TestReadProxyRootRedirectsToIndexHTML599=== RUN TestReadProxyDisabled600=== PAUSE TestReadProxyDisabled601=== RUN TestReadRedirectNar602=== PAUSE TestReadRedirectNar603=== RUN TestReadRedirectKeepsNarinfoProxied604=== PAUSE TestReadRedirectKeepsNarinfoProxied605=== RUN TestReadProxyRangeRequest606=== PAUSE TestReadProxyRangeRequest607=== RUN TestReadRedirectUsesPublicS3URL608=== PAUSE TestReadRedirectUsesPublicS3URL609=== RUN TestPush_OverlappingRootsStoreOneRowPerKey610=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey611=== RUN TestPush_CompleteCommitsEveryRoot612=== PAUSE TestPush_CompleteCommitsEveryRoot613=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit614=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit615=== RUN TestPush_RejectsBadRequests616=== PAUSE TestPush_RejectsBadRequests617=== RUN TestPush_SignsNarinfosOfItsPendingObjects618=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects619=== RUN TestRedundantMultipartUpload620=== PAUSE TestRedundantMultipartUpload621=== RUN TestCompleteMultipartUpload_ErrorButObjectExists622=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists623=== RUN TestCompletedNarNotReofferedAcrossClosures624=== PAUSE TestCompletedNarNotReofferedAcrossClosures625=== RUN TestPresignedUploadRegisteredBeforeCommit626=== PAUSE TestPresignedUploadRegisteredBeforeCommit627=== RUN TestService_Rustfstest628=== PAUSE TestService_Rustfstest629=== RUN TestParseSize630=== PAUSE TestParseSize631=== RUN TestSkippedUploadsHandler632=== PAUSE TestSkippedUploadsHandler633=== RUN TestSystemdListenerNotActivated634--- PASS: TestSystemdListenerNotActivated (0.00s)635=== RUN TestWatchdogBeatsWhenHealthy636--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)637=== RUN TestWatchdogSkipsWhenUnhealthy6382026/10/01 07:36:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6392026/10/01 07:36:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6402026/10/01 07:36:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6412026/10/01 07:36:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6422026/10/01 07:36:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6432026/10/01 07:36:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6442026/10/01 07:36:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6452026/10/01 07:36:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6462026/10/01 07:36:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6472026/10/01 07:36:48 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"648--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)649=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle650=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle651=== RUN TestProxyWriteTimeout652=== PAUSE TestProxyWriteTimeout653=== RUN TestIsValidUploadKey654=== PAUSE TestIsValidUploadKey655=== RUN TestUploadHandlersRejectInvalidKeys656=== PAUSE TestUploadHandlersRejectInvalidKeys657=== RUN TestUploadHandlersRejectOversizedBody658=== PAUSE TestUploadHandlersRejectOversizedBody659=== RUN TestService_cleanupPendingClosuresHandler660=== PAUSE TestService_cleanupPendingClosuresHandler661=== RUN TestService_createPendingClosureHandler662=== PAUSE TestService_createPendingClosureHandler663=== RUN TestService_verifyS3Integrity664=== PAUSE TestService_verifyS3Integrity665=== RUN TestCompleteMultipartUnregistered666=== PAUSE TestCompleteMultipartUnregistered667=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT668=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT669=== CONT TestService_AuthMiddleware670=== CONT TestNARDeduplicationMetadataUploadBug671=== CONT TestPushDedupSurvivesConcurrentGC672=== CONT TestDeduplicatedObjectsRecordedAsPending673=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT674=== CONT TestClientMultipleUploads675=== CONT TestCompleteMultipartUnregistered676=== CONT TestService_verifyS3Integrity677=== CONT TestGCMetrics678=== CONT TestService_createPendingClosureHandler6792026-10-01 07:36:48.375 UTC [55927] ERROR: relation "goose_db_version" does not exist at character 366802026-10-01 07:36:48.375 UTC [55927] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6812026-10-01 07:36:48.377 UTC [55929] ERROR: relation "goose_db_version" does not exist at character 366822026-10-01 07:36:48.377 UTC [55929] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6832026-10-01 07:36:48.458 UTC [55945] ERROR: relation "goose_db_version" does not exist at character 366842026-10-01 07:36:48.458 UTC [55945] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6852026-10-01 07:36:48.459 UTC [55946] ERROR: relation "goose_db_version" does not exist at character 366862026-10-01 07:36:48.459 UTC [55946] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6872026-10-01 07:36:48.494 UTC [55949] ERROR: relation "goose_db_version" does not exist at character 366882026-10-01 07:36:48.494 UTC [55949] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6892026-10-01 07:36:48.496 UTC [55950] ERROR: relation "goose_db_version" does not exist at character 366902026-10-01 07:36:48.496 UTC [55950] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC6912026/10/01 07:36:48 OK 20241026095416_initial_model.sql (9.63ms)6922026/10/01 07:36:48 OK 20241026095416_initial_model.sql (12.1ms)6932026/10/01 07:36:48 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)6942026/10/01 07:36:48 OK 20251210153512_drop_unused_gin_index.sql (1.1ms)6952026/10/01 07:36:48 OK 20241026095416_initial_model.sql (8.18ms)6962026/10/01 07:36:48 OK 20251210153512_drop_unused_gin_index.sql (648.38µs)6972026/10/01 07:36:48 OK 20251218171726_add_pins.sql (2.41ms)6982026-10-01 07:36:48.505 UTC [55951] ERROR: relation "goose_db_version" does not exist at character 366992026-10-01 07:36:48.505 UTC [55951] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7002026/10/01 07:36:48 OK 20260628120000_add_object_size_and_stats.sql (7.01ms)7012026/10/01 07:36:48 OK 20251218171726_add_pins.sql (44.79ms)7022026/10/01 07:36:48 OK 20260905000000_add_claims.sql (37.97ms)7032026/10/01 07:36:48 OK 20260920000000_drop_claims.sql (15.16ms)7042026/10/01 07:36:48 OK 20260628120000_add_object_size_and_stats.sql (16.23ms)7052026/10/01 07:36:48 OK 20241026095416_initial_model.sql (15.62ms)7062026/10/01 07:36:48 OK 20241026095416_initial_model.sql (65.34ms)7072026/10/01 07:36:48 OK 20260923120000_add_pushes.sql (2.52ms)7082026/10/01 07:36:48 goose: successfully migrated database to version: 202609231200007092026/10/01 07:36:48 OK 20260905000000_add_claims.sql (2.87ms)7102026/10/01 07:36:48 OK 20241026095416_initial_model.sql (55.59ms)7112026/10/01 07:36:48 OK 20251218171726_add_pins.sql (65.44ms)7122026/10/01 07:36:48 OK 20241026095416_initial_model.sql (66.11ms)7132026/10/01 07:36:48 OK 1_commit_pending_closure.sql (2.34ms)7142026/10/01 07:36:48 OK 20251210153512_drop_unused_gin_index.sql (5.79ms)7152026/10/01 07:36:48 OK 20251210153512_drop_unused_gin_index.sql (7.48ms)7162026/10/01 07:36:48 OK 2_object_stats_trigger.sql (7.52ms)7172026-10-01 07:36:48.576 UTC [55964] ERROR: relation "goose_db_version" does not exist at character 367182026-10-01 07:36:48.576 UTC [55964] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7192026-10-01 07:36:48.576 UTC [55963] ERROR: relation "goose_db_version" does not exist at character 367202026-10-01 07:36:48.576 UTC [55963] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7212026/10/01 07:36:48 OK 20260920000000_drop_claims.sql (10.71ms)7222026/10/01 07:36:48 OK 20260628120000_add_object_size_and_stats.sql (10.28ms)7232026/10/01 07:36:48 OK 20251210153512_drop_unused_gin_index.sql (10.6ms)7242026/10/01 07:36:48 OK 20251218171726_add_pins.sql (7.55ms)7252026/10/01 07:36:48 OK 20251210153512_drop_unused_gin_index.sql (11.87ms)7262026/10/01 07:36:48 OK 3_commit_push.sql (5.06ms)7272026/10/01 07:36:48 goose: up to current file version: 37282026-10-01 07:36:48.581 UTC [55966] ERROR: relation "goose_db_version" does not exist at character 367292026-10-01 07:36:48.581 UTC [55966] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7302026/10/01 07:36:48 OK 20251218171726_add_pins.sql (9.84ms)7312026/10/01 07:36:48 OK 20260923120000_add_pushes.sql (5.81ms)7322026/10/01 07:36:48 goose: successfully migrated database to version: 202609231200007332026/10/01 07:36:48 OK 20251218171726_add_pins.sql (4.58ms)7342026/10/01 07:36:48 OK 20260628120000_add_object_size_and_stats.sql (5.4ms)7352026/10/01 07:36:48 OK 20260905000000_add_claims.sql (7.34ms)7362026/10/01 07:36:48 OK 20251218171726_add_pins.sql (7.69ms)7372026/10/01 07:36:48 OK 1_commit_pending_closure.sql (3.18ms)7382026/10/01 07:36:48 OK 20260920000000_drop_claims.sql (2.51ms)7392026/10/01 07:36:48 OK 2_object_stats_trigger.sql (688.79µs)7402026/10/01 07:36:48 OK 20260628120000_add_object_size_and_stats.sql (4.81ms)7412026/10/01 07:36:48 OK 3_commit_push.sql (283.5µs)7422026/10/01 07:36:48 goose: up to current file version: 37432026/10/01 07:36:48 OK 20260905000000_add_claims.sql (10.97ms)7442026/10/01 07:36:48 OK 20260628120000_add_object_size_and_stats.sql (11.32ms)7452026/10/01 07:36:48 OK 20260628120000_add_object_size_and_stats.sql (17.25ms)7462026/10/01 07:36:48 OK 20260923120000_add_pushes.sql (15.15ms)7472026/10/01 07:36:48 goose: successfully migrated database to version: 202609231200007482026/10/01 07:36:48 OK 1_commit_pending_closure.sql (1.54ms)7492026/10/01 07:36:48 OK 2_object_stats_trigger.sql (622.08µs)7502026/10/01 07:36:48 OK 3_commit_push.sql (472.21µs)7512026/10/01 07:36:48 goose: up to current file version: 37522026/10/01 07:36:48 OK 20260920000000_drop_claims.sql (16.59ms)7532026/10/01 07:36:48 OK 20260905000000_add_claims.sql (32.1ms)7542026/10/01 07:36:48 OK 20260905000000_add_claims.sql (24.54ms)7552026/10/01 07:36:48 OK 20260923120000_add_pushes.sql (16.43ms)7562026/10/01 07:36:48 goose: successfully migrated database to version: 202609231200007572026/10/01 07:36:48 OK 20260920000000_drop_claims.sql (9.81ms)7582026/10/01 07:36:48 OK 20260905000000_add_claims.sql (28.74ms)7592026/10/01 07:36:48 OK 20260920000000_drop_claims.sql (11.75ms)7602026/10/01 07:36:48 OK 1_commit_pending_closure.sql (3.94ms)7612026/10/01 07:36:48 OK 20260923120000_add_pushes.sql (3.39ms)7622026/10/01 07:36:48 goose: successfully migrated database to version: 202609231200007632026/10/01 07:36:48 OK 20260923120000_add_pushes.sql (3.44ms)7642026/10/01 07:36:48 goose: successfully migrated database to version: 202609231200007652026/10/01 07:36:48 OK 2_object_stats_trigger.sql (2.02ms)7662026/10/01 07:36:48 OK 20241026095416_initial_model.sql (51.6ms)7672026/10/01 07:36:48 OK 20260920000000_drop_claims.sql (4.7ms)7682026/10/01 07:36:48 OK 20241026095416_initial_model.sql (49.43ms)7692026/10/01 07:36:48 OK 20241026095416_initial_model.sql (52.25ms)7702026/10/01 07:36:48 OK 3_commit_push.sql (1.85ms)7712026/10/01 07:36:48 goose: up to current file version: 37722026/10/01 07:36:48 OK 1_commit_pending_closure.sql (2.82ms)7732026/10/01 07:36:48 OK 1_commit_pending_closure.sql (3.59ms)7742026/10/01 07:36:48 OK 2_object_stats_trigger.sql (612.75µs)7752026/10/01 07:36:48 OK 2_object_stats_trigger.sql (681.42µs)7762026/10/01 07:36:48 OK 3_commit_push.sql (399.67µs)7772026/10/01 07:36:48 goose: up to current file version: 37782026/10/01 07:36:48 OK 3_commit_push.sql (393.75µs)7792026/10/01 07:36:48 goose: up to current file version: 37802026/10/01 07:36:48 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)7812026/10/01 07:36:48 OK 20251210153512_drop_unused_gin_index.sql (2.15ms)7822026/10/01 07:36:48 OK 20251210153512_drop_unused_gin_index.sql (2.61ms)7832026/10/01 07:36:48 OK 20260923120000_add_pushes.sql (3.2ms)7842026/10/01 07:36:48 goose: successfully migrated database to version: 202609231200007852026/10/01 07:36:48 OK 1_commit_pending_closure.sql (6.08ms)7862026/10/01 07:36:48 OK 2_object_stats_trigger.sql (1.39ms)7872026/10/01 07:36:48 OK 3_commit_push.sql (1.15ms)7882026/10/01 07:36:48 goose: up to current file version: 37892026/10/01 07:36:48 OK 20251218171726_add_pins.sql (30.78ms)7902026/10/01 07:36:48 OK 20251218171726_add_pins.sql (30.89ms)7912026/10/01 07:36:48 OK 20251218171726_add_pins.sql (30.93ms)7922026/10/01 07:36:48 OK 20260628120000_add_object_size_and_stats.sql (19.9ms)7932026/10/01 07:36:48 OK 20260628120000_add_object_size_and_stats.sql (20.28ms)7942026/10/01 07:36:48 OK 20260628120000_add_object_size_and_stats.sql (22.14ms)7952026/10/01 07:36:48 OK 20260905000000_add_claims.sql (13.78ms)7962026/10/01 07:36:48 OK 20260905000000_add_claims.sql (14.28ms)7972026/10/01 07:36:48 OK 20260905000000_add_claims.sql (14.39ms)7982026/10/01 07:36:48 OK 20260920000000_drop_claims.sql (15.55ms)7992026/10/01 07:36:48 OK 20260920000000_drop_claims.sql (18.11ms)8002026/10/01 07:36:48 OK 20260920000000_drop_claims.sql (18.47ms)8012026/10/01 07:36:48 OK 20260923120000_add_pushes.sql (1.75ms)8022026/10/01 07:36:48 goose: successfully migrated database to version: 202609231200008032026/10/01 07:36:48 OK 20260923120000_add_pushes.sql (1.54ms)8042026/10/01 07:36:48 goose: successfully migrated database to version: 202609231200008052026/10/01 07:36:48 OK 20260923120000_add_pushes.sql (2.13ms)8062026/10/01 07:36:48 goose: successfully migrated database to version: 202609231200008072026/10/01 07:36:48 OK 1_commit_pending_closure.sql (1.18ms)8082026/10/01 07:36:48 OK 1_commit_pending_closure.sql (989.54µs)8092026/10/01 07:36:48 OK 1_commit_pending_closure.sql (938.88µs)8102026/10/01 07:36:48 OK 2_object_stats_trigger.sql (250.04µs)8112026/10/01 07:36:48 OK 2_object_stats_trigger.sql (287.58µs)8122026/10/01 07:36:48 OK 2_object_stats_trigger.sql (259.71µs)8132026/10/01 07:36:48 OK 3_commit_push.sql (273.75µs)8142026/10/01 07:36:48 goose: up to current file version: 38152026/10/01 07:36:48 OK 3_commit_push.sql (407.67µs)8162026/10/01 07:36:48 goose: up to current file version: 38172026/10/01 07:36:48 OK 3_commit_push.sql (448.25µs)8182026/10/01 07:36:48 goose: up to current file version: 38192026/10/01 07:36:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8202026/10/01 07:36:48 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst821--- PASS: TestCompleteMultipartUnregistered (0.70s)822=== CONT TestService_cleanupPendingClosuresHandler8232026/10/01 07:36:48 INFO Aborted multipart uploads count=08242026/10/01 07:36:48 WARN Force mode enabled - objects will be deleted immediately without grace period8252026/10/01 07:36:48 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=08262026/10/01 07:36:48 INFO Vacuumed table table=pending_closures8272026/10/01 07:36:48 INFO Vacuumed table table=pending_objects8282026/10/01 07:36:48 INFO Vacuumed table table=multipart_uploads8292026/10/01 07:36:48 INFO Vacuumed table table=closures8302026/10/01 07:36:48 INFO Vacuumed table table=objects831--- PASS: TestGCMetrics (0.87s)832=== CONT TestGCBugBareHashReferences8332026-10-01 07:36:49.063 UTC [56028] ERROR: relation "goose_db_version" does not exist at character 368342026-10-01 07:36:49.063 UTC [56028] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8352026/10/01 07:36:49 OK 20241026095416_initial_model.sql (87.74ms)8362026/10/01 07:36:49 OK 20251210153512_drop_unused_gin_index.sql (10.23ms)8372026/10/01 07:36:49 OK 20251218171726_add_pins.sql (15.21ms)8382026/10/01 07:36:49 OK 20260628120000_add_object_size_and_stats.sql (33.57ms)8392026/10/01 07:36:49 OK 20260905000000_add_claims.sql (37.28ms)8402026/10/01 07:36:49 OK 20260920000000_drop_claims.sql (22.26ms)8412026/10/01 07:36:49 OK 20260923120000_add_pushes.sql (5.05ms)8422026/10/01 07:36:49 goose: successfully migrated database to version: 202609231200008432026-10-01 07:36:49.294 UTC [56062] ERROR: relation "goose_db_version" does not exist at character 368442026-10-01 07:36:49.294 UTC [56062] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8452026/10/01 07:36:49 OK 1_commit_pending_closure.sql (2.22ms)8462026/10/01 07:36:49 OK 2_object_stats_trigger.sql (286µs)8472026/10/01 07:36:49 OK 3_commit_push.sql (199.04µs)8482026/10/01 07:36:49 goose: up to current file version: 38492026/10/01 07:36:49 OK 20241026095416_initial_model.sql (20.35ms)8502026/10/01 07:36:49 OK 20251210153512_drop_unused_gin_index.sql (17.41ms)8512026/10/01 07:36:49 OK 20251218171726_add_pins.sql (16.23ms)8522026/10/01 07:36:49 OK 20260628120000_add_object_size_and_stats.sql (13.94ms)8532026/10/01 07:36:49 OK 20260905000000_add_claims.sql (11.95ms)8542026/10/01 07:36:49 OK 20260920000000_drop_claims.sql (1.78ms)8552026/10/01 07:36:49 OK 20260923120000_add_pushes.sql (1.58ms)8562026/10/01 07:36:49 goose: successfully migrated database to version: 202609231200008572026/10/01 07:36:49 OK 1_commit_pending_closure.sql (2.47ms)8582026/10/01 07:36:49 OK 2_object_stats_trigger.sql (743.83µs)8592026/10/01 07:36:49 OK 3_commit_push.sql (512.29µs)8602026/10/01 07:36:49 goose: up to current file version: 38612026/10/01 07:36:49 INFO Received uploads request method=POST path=/api/pending_closures8622026/10/01 07:36:49 INFO Received uploads request method=POST path=/api/pending_closures8632026/10/01 07:36:49 INFO Received uploads request method=POST path=/api/pending_closures864=== NAME TestClientMultipleUploads865 client_integration_test.go:358: Created store path 0: /nix/var/nix/builds/nix-54868-424906470/TestClientMultipleUploads2889737338/001/store/zmq9s3cl9lwm0ibsrwxqcw51zdnxh0m0-test-file-0.txt8662026/10/01 07:36:49 INFO Received uploads request method=POST path=/api/pending_closures867--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.61s)868=== CONT TestUploadHandlersRejectOversizedBody869=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts870=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts871=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure872=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure873=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart874=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart875=== CONT TestUploadHandlersRejectInvalidKeys876=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info877=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info878=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal879=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal880=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key881=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key882=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key883=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key884=== CONT TestIsValidUploadKey885=== RUN TestIsValidUploadKey/narinfo886=== PAUSE TestIsValidUploadKey/narinfo887=== RUN TestIsValidUploadKey/nar_zst888=== PAUSE TestIsValidUploadKey/nar_zst889=== RUN TestIsValidUploadKey/nar_xz890=== PAUSE TestIsValidUploadKey/nar_xz891=== RUN TestIsValidUploadKey/nar_plain892=== PAUSE TestIsValidUploadKey/nar_plain893=== RUN TestIsValidUploadKey/listing894=== PAUSE TestIsValidUploadKey/listing895=== RUN TestIsValidUploadKey/build_log896=== PAUSE TestIsValidUploadKey/build_log897=== RUN TestIsValidUploadKey/build_log_home-manager_file898=== PAUSE TestIsValidUploadKey/build_log_home-manager_file899=== RUN TestIsValidUploadKey/build_log_plus_in_name900=== PAUSE TestIsValidUploadKey/build_log_plus_in_name901=== RUN TestIsValidUploadKey/build_log_question_mark902=== PAUSE TestIsValidUploadKey/build_log_question_mark903=== RUN TestIsValidUploadKey/build_log_equals904=== PAUSE TestIsValidUploadKey/build_log_equals905=== RUN TestIsValidUploadKey/realisation906=== PAUSE TestIsValidUploadKey/realisation907=== RUN TestIsValidUploadKey/realisation_plus_in_output908=== PAUSE TestIsValidUploadKey/realisation_plus_in_output909=== RUN TestIsValidUploadKey/nix-cache-info910=== PAUSE TestIsValidUploadKey/nix-cache-info911=== RUN TestIsValidUploadKey/index.html912=== PAUSE TestIsValidUploadKey/index.html913=== RUN TestIsValidUploadKey/narinfo_key,_nar_type914=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type915=== RUN TestIsValidUploadKey/nar_key,_narinfo_type916=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type917=== RUN TestIsValidUploadKey/listing_key,_narinfo_type918=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type919=== RUN TestIsValidUploadKey/traversal920=== PAUSE TestIsValidUploadKey/traversal921=== RUN TestIsValidUploadKey/traversal_nar922=== PAUSE TestIsValidUploadKey/traversal_nar923=== RUN TestIsValidUploadKey/absolute924=== PAUSE TestIsValidUploadKey/absolute925=== RUN TestIsValidUploadKey/empty_key926=== PAUSE TestIsValidUploadKey/empty_key927=== RUN TestIsValidUploadKey/unknown_type928=== PAUSE TestIsValidUploadKey/unknown_type929=== CONT TestProxyWriteTimeout930=== RUN TestProxyWriteTimeout/narinfo931=== PAUSE TestProxyWriteTimeout/narinfo932=== RUN TestProxyWriteTimeout/1_GiB_nar933=== PAUSE TestProxyWriteTimeout/1_GiB_nar934=== RUN TestProxyWriteTimeout/10_GiB_nar935=== PAUSE TestProxyWriteTimeout/10_GiB_nar936=== RUN TestProxyWriteTimeout/unknown_size937=== PAUSE TestProxyWriteTimeout/unknown_size938=== CONT TestLeadEndsOnShutdown939=== NAME TestClientMultipleUploads940 client_integration_test.go:358: Created store path 1: /nix/var/nix/builds/nix-54868-424906470/TestClientMultipleUploads2889737338/001/store/sg83dx509wa34jvdgfzc51v1aihsg3vh-test-file-1.txt9412026-10-01 07:36:49.965 UTC [56132] ERROR: relation "goose_db_version" does not exist at character 369422026-10-01 07:36:49.965 UTC [56132] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9432026/10/01 07:36:50 OK 20241026095416_initial_model.sql (26.44ms)9442026/10/01 07:36:50 OK 20251210153512_drop_unused_gin_index.sql (3.5ms)9452026/10/01 07:36:50 OK 20251218171726_add_pins.sql (12.01ms)9462026/10/01 07:36:50 OK 20260628120000_add_object_size_and_stats.sql (6.12ms)9472026/10/01 07:36:50 OK 20260905000000_add_claims.sql (2.5ms)9482026/10/01 07:36:50 OK 20260920000000_drop_claims.sql (4.94ms)9492026/10/01 07:36:50 OK 20260923120000_add_pushes.sql (7.93ms)9502026/10/01 07:36:50 goose: successfully migrated database to version: 202609231200009512026/10/01 07:36:50 OK 1_commit_pending_closure.sql (1.88ms)9522026/10/01 07:36:50 OK 2_object_stats_trigger.sql (526.29µs)9532026/10/01 07:36:50 OK 3_commit_push.sql (428.04µs)9542026/10/01 07:36:50 goose: up to current file version: 39552026/10/01 07:36:50 INFO Received uploads request method=POST path=/api/pending_closures956 client_integration_test.go:358: Created store path 2: /nix/var/nix/builds/nix-54868-424906470/TestClientMultipleUploads2889737338/001/store/lgc8z6g7j5kxwghcglhwxrg1x4hrp6j4-test-file-2.txt957=== NAME TestNARDeduplicationMetadataUploadBug958 metadata_upload_test.go:48: First store path: /nix/var/nix/builds/nix-54868-424906470/TestNARDeduplicationMetadataUploadBug542615903/001/store/a9q4i6kqmm51i6rw1bslj2rx8jiipdbf-file1.txt9592026/10/01 07:36:50 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"960--- PASS: TestService_AuthMiddleware (2.38s)961=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle9622026-10-01 07:36:50.658 UTC [56207] ERROR: relation "goose_db_version" does not exist at character 369632026-10-01 07:36:50.658 UTC [56207] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9642026/10/01 07:36:50 OK 20241026095416_initial_model.sql (26.38ms)9652026/10/01 07:36:50 OK 20251210153512_drop_unused_gin_index.sql (4.72ms)9662026/10/01 07:36:50 OK 20251218171726_add_pins.sql (5.99ms)9672026/10/01 07:36:50 OK 20260628120000_add_object_size_and_stats.sql (2.72ms)9682026/10/01 07:36:50 OK 20260905000000_add_claims.sql (5.15ms)9692026/10/01 07:36:50 OK 20260920000000_drop_claims.sql (1.37ms)9702026/10/01 07:36:50 OK 20260923120000_add_pushes.sql (1.26ms)9712026/10/01 07:36:50 goose: successfully migrated database to version: 202609231200009722026/10/01 07:36:50 OK 1_commit_pending_closure.sql (2.07ms)9732026/10/01 07:36:50 OK 2_object_stats_trigger.sql (552.17µs)9742026/10/01 07:36:50 OK 3_commit_push.sql (406.33µs)9752026/10/01 07:36:50 goose: up to current file version: 39762026/10/01 07:36:50 INFO Received push request method=POST path=/api/pushes9772026/10/01 07:36:50 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)9782026/10/01 07:36:50 INFO Uploading zmq9s3cl9lwm0ibsrwxqcw51zdnxh0m0-test-file-0.txt (160B)9792026/10/01 07:36:50 INFO Uploading lgc8z6g7j5kxwghcglhwxrg1x4hrp6j4-test-file-2.txt (160B)9802026/10/01 07:36:50 INFO Uploading sg83dx509wa34jvdgfzc51v1aihsg3vh-test-file-1.txt (160B)9812026/10/01 07:36:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9822026/10/01 07:36:50 WARN Failed to register uploaded object key=lgc8z6g7j5kxwghcglhwxrg1x4hrp6j4.ls error="server returned 404: 404 page not found\n"9832026/10/01 07:36:50 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"9842026/10/01 07:36:50 WARN Failed to register uploaded object key=zmq9s3cl9lwm0ibsrwxqcw51zdnxh0m0.ls error="server returned 404: 404 page not found\n"9852026/10/01 07:36:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9862026/10/01 07:36:50 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"9872026/10/01 07:36:50 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"9882026/10/01 07:36:50 WARN Failed to register uploaded object key=sg83dx509wa34jvdgfzc51v1aihsg3vh.ls error="server returned 404: 404 page not found\n"9892026/10/01 07:36:50 INFO Signed narinfos id=1 count=39902026/10/01 07:36:50 INFO Uploading 3 narinfos9912026/10/01 07:36:50 INFO Received uploads request method=POST path=/api/pending_closures9922026/10/01 07:36:50 INFO Received push request method=POST path=/api/pushes9932026/10/01 07:36:50 WARN Failed to register uploaded object key=sg83dx509wa34jvdgfzc51v1aihsg3vh.narinfo error="server returned 404: 404 page not found\n"9942026/10/01 07:36:50 WARN Failed to register uploaded object key=zmq9s3cl9lwm0ibsrwxqcw51zdnxh0m0.narinfo error="server returned 404: 404 page not found\n"9952026/10/01 07:36:50 INFO Received complete push request method=POST path=/api/pushes/1/complete9962026/10/01 07:36:50 WARN Failed to register uploaded object key=lgc8z6g7j5kxwghcglhwxrg1x4hrp6j4.narinfo error="server returned 404: 404 page not found\n"9972026/10/01 07:36:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9982026/10/01 07:36:50 INFO Uploading a9q4i6kqmm51i6rw1bslj2rx8jiipdbf-file1.txt (160B)9992026/10/01 07:36:50 INFO Upload complete. (423ms)1000=== NAME TestClientMultipleUploads1001 client_integration_test.go:369: Uploaded 3 paths in 745.210375ms10022026/10/01 07:36:50 WARN Failed to register uploaded object key=a9q4i6kqmm51i6rw1bslj2rx8jiipdbf.ls error="server returned 404: 404 page not found\n"10032026/10/01 07:36:50 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YzJlZDBmMmYtNDRlMS00NjdhLTkxMzQtMmE2YjY5MDVhZDU1LmU3NzE0ODUyLTcwNjktNDFhNi04YjI5LTZhM2YzMmMzZDY3OHgxNzkwODQwMjA5NDI3ODk4MDAw parts=1010042026/10/01 07:36:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10052026/10/01 07:36:50 INFO Completed upload id=110062026/10/01 07:36:50 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010072026/10/01 07:36:50 INFO Received uploads request method=POST path=/api/pending_closures10082026/10/01 07:36:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10092026/10/01 07:36:50 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10102026/10/01 07:36:50 INFO Signed narinfos id=1 count=110112026/10/01 07:36:50 INFO Uploading 1 narinfos10122026/10/01 07:36:50 INFO Starting cleanup of old closures method=DELETE path=/api/closures10132026/10/01 07:36:50 INFO Aborted multipart uploads count=010142026/10/01 07:36:50 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=01015--- PASS: TestClientMultipleUploads (2.90s)1016=== CONT TestSkippedUploadsHandler10172026/10/01 07:36:50 INFO Client skipped oversized paths paths=3 nar_bytes=500000000010182026/10/01 07:36:50 INFO Vacuumed table table=pending_closures1019--- PASS: TestSkippedUploadsHandler (0.00s)1020=== CONT TestParseSize1021--- PASS: TestParseSize (0.00s)1022=== CONT TestLeadElectsOneAndHandsOver10232026/10/01 07:36:50 INFO Vacuumed table table=pending_objects10242026/10/01 07:36:50 INFO Received complete push request method=POST path=/api/pushes/1/complete10252026/10/01 07:36:50 WARN Failed to register uploaded object key=a9q4i6kqmm51i6rw1bslj2rx8jiipdbf.narinfo error="server returned 404: 404 page not found\n"10262026/10/01 07:36:50 INFO Vacuumed table table=multipart_uploads10272026/10/01 07:36:50 INFO Aborted multipart uploads count=010282026/10/01 07:36:50 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=010292026/10/01 07:36:51 INFO Vacuumed table table=closures10302026/10/01 07:36:51 INFO Upload complete. (401ms)1031=== NAME TestNARDeduplicationMetadataUploadBug1032 metadata_upload_test.go:54: Retrieved narinfo from S3:1033 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestNARDeduplicationMetadataUploadBug542615903/001/store/a9q4i6kqmm51i6rw1bslj2rx8jiipdbf-file1.txt1034 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1035 Compression: zstd1036 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1037 NarSize: 1601038 References: 1039 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1040 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1041 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1042 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}10432026/10/01 07:36:51 INFO Vacuumed table table=pending_closures10442026/10/01 07:36:51 INFO Vacuumed table table=objects10452026/10/01 07:36:51 INFO Vacuumed table table=pending_objects10462026/10/01 07:36:51 INFO Vacuumed table table=multipart_uploads10472026/10/01 07:36:51 INFO Vacuumed table table=closures10482026/10/01 07:36:51 INFO Vacuumed table table=objects10492026/10/01 07:36:51 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001050--- PASS: TestService_createPendingClosureHandler (2.99s)1051=== CONT TestService_Rustfstest10522026/10/01 07:36:51 INFO Aborted multipart uploads count=010532026/10/01 07:36:51 WARN Force mode enabled - objects will be deleted immediately without grace period10542026/10/01 07:36:51 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=010552026/10/01 07:36:51 INFO Vacuumed table table=pending_closures10562026/10/01 07:36:51 INFO Vacuumed table table=pending_objects10572026/10/01 07:36:51 INFO Vacuumed table table=multipart_uploads10582026/10/01 07:36:51 INFO Vacuumed table table=closures10592026/10/01 07:36:51 INFO Vacuumed table table=objects1060--- PASS: TestPushDedupSurvivesConcurrentGC (3.05s)1061=== CONT TestResolveDBConnectionString1062=== RUN TestResolveDBConnectionString/flag_wins1063=== PAUSE TestResolveDBConnectionString/flag_wins1064=== RUN TestResolveDBConnectionString/file_when_flag_empty1065=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1066=== RUN TestResolveDBConnectionString/missing_file_is_an_error1067=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1068=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1069=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1070=== RUN TestResolveDBConnectionString/nothing_configured1071=== PAUSE TestResolveDBConnectionString/nothing_configured1072=== CONT TestPresignedUploadRegisteredBeforeCommit10732026/10/01 07:36:51 INFO Received uploads request method=POST path=/api/pending_closures1074--- PASS: TestDeduplicatedObjectsRecordedAsPending (3.14s)1075=== CONT TestCompletedNarNotReofferedAcrossClosures1076=== NAME TestNARDeduplicationMetadataUploadBug1077 metadata_upload_test.go:64: Second store path (same content): /nix/var/nix/builds/nix-54868-424906470/TestNARDeduplicationMetadataUploadBug542615903/001/store/1pdhrcyj7nx63x1mjdsan8wiikk8j6sd-file2.txt10782026/10/01 07:36:51 INFO Received cleanup request method=DELETE path=/api/pending_closures10792026/10/01 07:36:51 INFO Aborted multipart uploads count=010802026/10/01 07:36:51 INFO Received uploads request method=POST path=/api/pending_closures10812026/10/01 07:36:51 INFO Received cleanup request method=DELETE path=/api/pending_closures10822026/10/01 07:36:51 INFO Aborted multipart uploads count=110832026/10/01 07:36:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10842026-10-01 07:36:51.649 UTC [56028] ERROR: Closure does not exist: id=110852026-10-01 07:36:51.649 UTC [56028] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE10862026-10-01 07:36:51.649 UTC [56028] STATEMENT: -- name: CommitPendingClosure :exec1087 SELECT commit_pending_closure($1::bigint)1088 1089--- PASS: TestService_cleanupPendingClosuresHandler (2.88s)1090=== CONT TestClientFallsBackToClosures10912026/10/01 07:36:51 INFO Received push request method=POST path=/api/pushes10922026/10/01 07:36:51 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)10932026/10/01 07:36:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10942026-10-01 07:36:51.994 UTC [56363] ERROR: relation "goose_db_version" does not exist at character 3610952026-10-01 07:36:51.994 UTC [56363] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10962026/10/01 07:36:52 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign10972026/10/01 07:36:52 WARN Failed to register uploaded object key=1pdhrcyj7nx63x1mjdsan8wiikk8j6sd.ls error="server returned 404: 404 page not found\n"10982026/10/01 07:36:52 INFO Signed narinfos id=2 count=110992026/10/01 07:36:52 INFO Uploading 1 narinfos11002026-10-01 07:36:52.079 UTC [56374] ERROR: relation "goose_db_version" does not exist at character 3611012026-10-01 07:36:52.079 UTC [56374] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11022026/10/01 07:36:52 INFO Received complete push request method=POST path=/api/pushes/2/complete11032026/10/01 07:36:52 WARN Failed to register uploaded object key=1pdhrcyj7nx63x1mjdsan8wiikk8j6sd.narinfo error="server returned 404: 404 page not found\n"11042026/10/01 07:36:52 INFO Upload complete. (469ms)1105--- PASS: TestGCBugBareHashReferences (3.14s)1106=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1107=== NAME TestNARDeduplicationMetadataUploadBug1108 metadata_upload_test.go:76: Retrieved narinfo from S3:1109 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestNARDeduplicationMetadataUploadBug542615903/001/store/1pdhrcyj7nx63x1mjdsan8wiikk8j6sd-file2.txt1110 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1111 Compression: zstd1112 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1113 NarSize: 1601114 References: 1115 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1116 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1117 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1118 {"version":1,"root":{"type":"regular","size":44}}11192026/10/01 07:36:52 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YzJlZDBmMmYtNDRlMS00NjdhLTkxMzQtMmE2YjY5MDVhZDU1LmRlMTc0YzYxLTQyMTctNDZiMi1hNjVlLTQzY2VhZGU4NGQwM3gxNzkwODQwMjEwMTI5OTkzMDAw parts=1011202026/10/01 07:36:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11212026/10/01 07:36:52 INFO Completed upload id=111222026-10-01 07:36:52.099 UTC [56372] ERROR: relation "goose_db_version" does not exist at character 3611232026-10-01 07:36:52.099 UTC [56372] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11242026-10-01 07:36:52.099 UTC [56377] ERROR: relation "goose_db_version" does not exist at character 3611252026-10-01 07:36:52.099 UTC [56377] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11262026/10/01 07:36:52 INFO Received uploads request method=POST path=/api/pending_closures11272026/10/01 07:36:52 INFO Received uploads request method=POST path=/api/pending_closures11282026/10/01 07:36:52 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11292026/10/01 07:36:52 WARN Found objects in DB but missing from S3, will re-upload count=11130--- PASS: TestService_verifyS3Integrity (4.04s)1131=== CONT TestRedundantMultipartUpload1132--- PASS: TestNARDeduplicationMetadataUploadBug (4.08s)1133=== CONT TestPush_SignsNarinfosOfItsPendingObjects11342026/10/01 07:36:52 OK 20241026095416_initial_model.sql (108.62ms)11352026/10/01 07:36:52 INFO lead: acquired remote=192.0.2.1:123411362026/10/01 07:36:52 INFO lead: released remote=192.0.2.1:12341137--- PASS: TestLeadEndsOnShutdown (2.45s)1138=== CONT TestPush_RejectsBadRequests11392026/10/01 07:36:52 OK 20251210153512_drop_unused_gin_index.sql (2.26ms)11402026/10/01 07:36:52 OK 20251218171726_add_pins.sql (12.95ms)11412026/10/01 07:36:52 OK 20241026095416_initial_model.sql (88.21ms)11422026/10/01 07:36:52 OK 20251210153512_drop_unused_gin_index.sql (5.64ms)11432026/10/01 07:36:52 OK 20241026095416_initial_model.sql (84.99ms)11442026/10/01 07:36:52 OK 20251218171726_add_pins.sql (19.03ms)11452026/10/01 07:36:52 OK 20251210153512_drop_unused_gin_index.sql (3.26ms)11462026/10/01 07:36:52 OK 20260628120000_add_object_size_and_stats.sql (33.3ms)11472026/10/01 07:36:52 OK 20260628120000_add_object_size_and_stats.sql (22.52ms)11482026/10/01 07:36:52 OK 20241026095416_initial_model.sql (103.13ms)11492026/10/01 07:36:52 OK 20251218171726_add_pins.sql (26.61ms)11502026/10/01 07:36:52 OK 20260905000000_add_claims.sql (12.08ms)11512026/10/01 07:36:52 OK 20260920000000_drop_claims.sql (5.92ms)11522026/10/01 07:36:52 OK 20260923120000_add_pushes.sql (6.25ms)11532026/10/01 07:36:52 goose: successfully migrated database to version: 2026092312000011542026/10/01 07:36:52 OK 20260905000000_add_claims.sql (41.78ms)11552026/10/01 07:36:52 OK 1_commit_pending_closure.sql (2.65ms)11562026/10/01 07:36:52 OK 2_object_stats_trigger.sql (624.04µs)11572026/10/01 07:36:52 OK 20260920000000_drop_claims.sql (1.09ms)11582026/10/01 07:36:52 OK 3_commit_push.sql (577.29µs)11592026/10/01 07:36:52 goose: up to current file version: 311602026/10/01 07:36:52 OK 20260923120000_add_pushes.sql (1.82ms)11612026/10/01 07:36:52 goose: successfully migrated database to version: 2026092312000011622026/10/01 07:36:52 OK 1_commit_pending_closure.sql (2.27ms)11632026/10/01 07:36:52 OK 2_object_stats_trigger.sql (2.96ms)11642026/10/01 07:36:52 OK 3_commit_push.sql (1.37ms)11652026/10/01 07:36:52 goose: up to current file version: 311662026/10/01 07:36:52 OK 20251210153512_drop_unused_gin_index.sql (39.52ms)11672026/10/01 07:36:52 OK 20260628120000_add_object_size_and_stats.sql (44.47ms)11682026/10/01 07:36:52 OK 20251218171726_add_pins.sql (13.6ms)11692026/10/01 07:36:52 OK 20260628120000_add_object_size_and_stats.sql (17.03ms)11702026/10/01 07:36:52 OK 20260905000000_add_claims.sql (22.34ms)11712026/10/01 07:36:52 OK 20260905000000_add_claims.sql (12.66ms)11722026/10/01 07:36:52 OK 20260920000000_drop_claims.sql (12.47ms)11732026/10/01 07:36:52 OK 20260920000000_drop_claims.sql (19.98ms)11742026/10/01 07:36:52 OK 20260923120000_add_pushes.sql (8.53ms)11752026/10/01 07:36:52 goose: successfully migrated database to version: 2026092312000011762026/10/01 07:36:52 OK 1_commit_pending_closure.sql (2.15ms)11772026/10/01 07:36:52 OK 2_object_stats_trigger.sql (601.58µs)11782026/10/01 07:36:52 OK 3_commit_push.sql (420.29µs)11792026/10/01 07:36:52 goose: up to current file version: 311802026/10/01 07:36:52 OK 20260923120000_add_pushes.sql (15.22ms)11812026/10/01 07:36:52 goose: successfully migrated database to version: 2026092312000011822026/10/01 07:36:52 OK 1_commit_pending_closure.sql (2.33ms)11832026/10/01 07:36:52 OK 2_object_stats_trigger.sql (568.04µs)11842026/10/01 07:36:52 OK 3_commit_push.sql (440.67µs)11852026/10/01 07:36:52 goose: up to current file version: 311862026/10/01 07:36:52 INFO Received uploads request method=POST path=/api/pending_closures11872026-10-01 07:36:52.556 UTC [56422] ERROR: relation "goose_db_version" does not exist at character 3611882026-10-01 07:36:52.556 UTC [56422] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11892026/10/01 07:36:52 OK 20241026095416_initial_model.sql (59.86ms)11902026/10/01 07:36:52 OK 20251210153512_drop_unused_gin_index.sql (15.11ms)11912026/10/01 07:36:52 INFO Received uploads request method=POST path=/api/pending_closures11922026/10/01 07:36:52 OK 20251218171726_add_pins.sql (33.56ms)11932026/10/01 07:36:52 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11942026/10/01 07:36:52 INFO Received uploads request method=POST path=/api/pending_closures1195--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.59s)1196=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit11972026/10/01 07:36:52 OK 20260628120000_add_object_size_and_stats.sql (27.11ms)11982026/10/01 07:36:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11992026/10/01 07:36:52 OK 20260905000000_add_claims.sql (36.02ms)12002026/10/01 07:36:52 OK 20260920000000_drop_claims.sql (30.36ms)12012026/10/01 07:36:52 OK 20260923120000_add_pushes.sql (10.89ms)12022026/10/01 07:36:52 goose: successfully migrated database to version: 2026092312000012032026/10/01 07:36:52 OK 1_commit_pending_closure.sql (3.53ms)12042026/10/01 07:36:52 OK 2_object_stats_trigger.sql (785.42µs)12052026/10/01 07:36:52 OK 3_commit_push.sql (552.25µs)12062026/10/01 07:36:52 goose: up to current file version: 312072026-10-01 07:36:52.870 UTC [56438] ERROR: relation "goose_db_version" does not exist at character 3612082026-10-01 07:36:52.870 UTC [56438] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12092026-10-01 07:36:52.871 UTC [56434] ERROR: relation "goose_db_version" does not exist at character 3612102026-10-01 07:36:52.871 UTC [56434] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12112026-10-01 07:36:52.872 UTC [56440] ERROR: relation "goose_db_version" does not exist at character 3612122026-10-01 07:36:52.872 UTC [56440] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12132026-10-01 07:36:52.872 UTC [56439] ERROR: relation "goose_db_version" does not exist at character 3612142026-10-01 07:36:52.872 UTC [56439] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12152026/10/01 07:36:52 OK 20241026095416_initial_model.sql (33.06ms)12162026/10/01 07:36:52 OK 20241026095416_initial_model.sql (34.11ms)12172026/10/01 07:36:52 OK 20241026095416_initial_model.sql (33.54ms)12182026/10/01 07:36:52 OK 20251210153512_drop_unused_gin_index.sql (969.46µs)12192026/10/01 07:36:52 OK 20251210153512_drop_unused_gin_index.sql (1.06ms)12202026/10/01 07:36:52 OK 20251210153512_drop_unused_gin_index.sql (1.96ms)12212026/10/01 07:36:52 OK 20251218171726_add_pins.sql (8.14ms)12222026/10/01 07:36:52 OK 20251218171726_add_pins.sql (8.22ms)12232026/10/01 07:36:52 OK 20241026095416_initial_model.sql (44.28ms)12242026/10/01 07:36:52 OK 20251218171726_add_pins.sql (14.26ms)12252026/10/01 07:36:52 OK 20251210153512_drop_unused_gin_index.sql (4.4ms)12262026/10/01 07:36:52 OK 20260628120000_add_object_size_and_stats.sql (19.58ms)12272026/10/01 07:36:52 OK 20260628120000_add_object_size_and_stats.sql (19.6ms)12282026/10/01 07:36:52 OK 20260628120000_add_object_size_and_stats.sql (13.96ms)12292026/10/01 07:36:52 OK 20251218171726_add_pins.sql (13.46ms)12302026/10/01 07:36:52 OK 20260905000000_add_claims.sql (2.63ms)12312026/10/01 07:36:52 OK 20260905000000_add_claims.sql (2.84ms)1232--- PASS: TestService_Rustfstest (1.90s)1233=== CONT TestPush_CompleteCommitsEveryRoot12342026/10/01 07:36:52 OK 20260920000000_drop_claims.sql (14.64ms)12352026/10/01 07:36:52 OK 20260920000000_drop_claims.sql (14.43ms)12362026/10/01 07:36:52 OK 20260905000000_add_claims.sql (15.55ms)12372026/10/01 07:36:52 OK 20260628120000_add_object_size_and_stats.sql (30.11ms)12382026/10/01 07:36:52 OK 20260923120000_add_pushes.sql (20.11ms)12392026/10/01 07:36:52 goose: successfully migrated database to version: 2026092312000012402026/10/01 07:36:52 OK 20260923120000_add_pushes.sql (20.24ms)12412026/10/01 07:36:52 goose: successfully migrated database to version: 2026092312000012422026/10/01 07:36:52 OK 1_commit_pending_closure.sql (1.7ms)12432026/10/01 07:36:52 OK 1_commit_pending_closure.sql (1.94ms)12442026/10/01 07:36:52 OK 2_object_stats_trigger.sql (551.54µs)12452026/10/01 07:36:52 OK 2_object_stats_trigger.sql (493.17µs)12462026/10/01 07:36:52 OK 3_commit_push.sql (481.38µs)12472026/10/01 07:36:52 goose: up to current file version: 312482026/10/01 07:36:52 OK 3_commit_push.sql (448.13µs)12492026/10/01 07:36:52 goose: up to current file version: 312502026/10/01 07:36:53 OK 20260920000000_drop_claims.sql (27.16ms)12512026/10/01 07:36:53 OK 20260923120000_add_pushes.sql (5.57ms)12522026/10/01 07:36:53 goose: successfully migrated database to version: 2026092312000012532026/10/01 07:36:53 OK 1_commit_pending_closure.sql (2.12ms)12542026/10/01 07:36:53 OK 2_object_stats_trigger.sql (605.67µs)12552026/10/01 07:36:53 OK 3_commit_push.sql (449.54µs)12562026/10/01 07:36:53 goose: up to current file version: 312572026/10/01 07:36:53 OK 20260905000000_add_claims.sql (29.09ms)12582026/10/01 07:36:53 OK 20260920000000_drop_claims.sql (3.14ms)12592026/10/01 07:36:53 OK 20260923120000_add_pushes.sql (20.7ms)12602026/10/01 07:36:53 goose: successfully migrated database to version: 2026092312000012612026/10/01 07:36:53 OK 1_commit_pending_closure.sql (5.77ms)12622026/10/01 07:36:53 OK 2_object_stats_trigger.sql (4.88ms)12632026/10/01 07:36:53 OK 3_commit_push.sql (2.8ms)12642026/10/01 07:36:53 goose: up to current file version: 312652026-10-01 07:36:53.164 UTC [56462] ERROR: relation "goose_db_version" does not exist at character 3612662026-10-01 07:36:53.164 UTC [56462] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12672026/10/01 07:36:53 INFO lead: acquired remote=192.0.2.1:123412682026/10/01 07:36:53 OK 20241026095416_initial_model.sql (51.79ms)12692026/10/01 07:36:53 OK 20251210153512_drop_unused_gin_index.sql (4.33ms)12702026/10/01 07:36:53 OK 20251218171726_add_pins.sql (7.14ms)12712026/10/01 07:36:53 OK 20260628120000_add_object_size_and_stats.sql (16.46ms)12722026/10/01 07:36:53 OK 20260905000000_add_claims.sql (10.76ms)12732026/10/01 07:36:53 OK 20260920000000_drop_claims.sql (3.97ms)12742026/10/01 07:36:53 OK 20260923120000_add_pushes.sql (7.43ms)12752026/10/01 07:36:53 goose: successfully migrated database to version: 2026092312000012762026/10/01 07:36:53 OK 1_commit_pending_closure.sql (2.26ms)12772026/10/01 07:36:53 OK 2_object_stats_trigger.sql (762.21µs)12782026/10/01 07:36:53 OK 3_commit_push.sql (521.25µs)12792026/10/01 07:36:53 goose: up to current file version: 312802026/10/01 07:36:53 INFO lead: released remote=192.0.2.1:123412812026-10-01 07:36:53.360 UTC [56475] ERROR: relation "goose_db_version" does not exist at character 3612822026-10-01 07:36:53.360 UTC [56475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12832026/10/01 07:36:53 INFO Received uploads request method=POST path=/api/pending_closures12842026/10/01 07:36:53 INFO lead: acquired remote=192.0.2.1:123412852026/10/01 07:36:53 OK 20241026095416_initial_model.sql (27.11ms)12862026/10/01 07:36:53 INFO lead: released remote=192.0.2.1:12341287--- PASS: TestLeadElectsOneAndHandsOver (2.44s)1288=== CONT TestPush_OverlappingRootsStoreOneRowPerKey12892026/10/01 07:36:53 OK 20251210153512_drop_unused_gin_index.sql (10.37ms)12902026/10/01 07:36:53 OK 20251218171726_add_pins.sql (11.4ms)12912026/10/01 07:36:53 OK 20260628120000_add_object_size_and_stats.sql (20ms)12922026/10/01 07:36:53 OK 20260905000000_add_claims.sql (27.29ms)12932026/10/01 07:36:53 OK 20260920000000_drop_claims.sql (3.72ms)12942026/10/01 07:36:53 OK 20260923120000_add_pushes.sql (7.6ms)12952026/10/01 07:36:53 goose: successfully migrated database to version: 2026092312000012962026/10/01 07:36:53 OK 1_commit_pending_closure.sql (2.32ms)12972026/10/01 07:36:53 OK 2_object_stats_trigger.sql (2.64ms)12982026/10/01 07:36:53 OK 3_commit_push.sql (552.92µs)12992026/10/01 07:36:53 goose: up to current file version: 313002026/10/01 07:36:53 INFO Received push request method=POST path=/api/pushes13012026/10/01 07:36:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13022026/10/01 07:36:53 INFO Signed narinfos id=1 count=11303--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (1.77s)1304=== CONT TestClientPushesUseOnePush13052026-10-01 07:36:54.019 UTC [56517] ERROR: relation "goose_db_version" does not exist at character 3613062026-10-01 07:36:54.019 UTC [56517] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13072026/10/01 07:36:54 OK 20241026095416_initial_model.sql (65.01ms)13082026/10/01 07:36:54 OK 20251210153512_drop_unused_gin_index.sql (13.72ms)13092026/10/01 07:36:54 INFO Received uploads request method=POST path=/api/pending_closures13102026/10/01 07:36:54 OK 20251218171726_add_pins.sql (22.93ms)13112026/10/01 07:36:54 OK 20260628120000_add_object_size_and_stats.sql (39.8ms)13122026/10/01 07:36:54 INFO Received uploads request method=POST path=/api/pending_closures13132026/10/01 07:36:54 OK 20260905000000_add_claims.sql (16.43ms)13142026/10/01 07:36:54 OK 20260920000000_drop_claims.sql (5.19ms)13152026/10/01 07:36:54 OK 20260923120000_add_pushes.sql (1.01ms)13162026/10/01 07:36:54 goose: successfully migrated database to version: 2026092312000013172026/10/01 07:36:54 OK 1_commit_pending_closure.sql (1.92ms)13182026/10/01 07:36:54 OK 2_object_stats_trigger.sql (329.38µs)13192026/10/01 07:36:54 OK 3_commit_push.sql (612.42µs)13202026/10/01 07:36:54 goose: up to current file version: 31321=== RUN TestPush_RejectsBadRequests/no_roots1322=== PAUSE TestPush_RejectsBadRequests/no_roots1323=== RUN TestPush_RejectsBadRequests/no_objects1324=== PAUSE TestPush_RejectsBadRequests/no_objects1325=== RUN TestPush_RejectsBadRequests/bad_root1326=== PAUSE TestPush_RejectsBadRequests/bad_root1327=== RUN TestPush_RejectsBadRequests/root_not_in_objects1328=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1329=== CONT TestReadRedirectUsesPublicS3URL13302026/10/01 07:36:54 INFO Received uploads request method=POST path=/api/pending_closures13312026/10/01 07:36:54 INFO Received uploads request method=POST path=/api/pending_closures13322026/10/01 07:36:54 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13332026/10/01 07:36:54 INFO Uploading cf1qhcqq5gl1xyd9cz62lpn14r7lrdqd-b (248B)13342026/10/01 07:36:54 INFO Uploading wzsxcr0lsjj0gbxgsycglhxsb39my44j-shared-dep (136B)13352026/10/01 07:36:54 WARN Failed to register uploaded object key=wzsxcr0lsjj0gbxgsycglhxsb39my44j.ls error="server returned 404: 404 page not found\n"13362026/10/01 07:36:54 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13372026/10/01 07:36:54 WARN Failed to register uploaded object key=0f6izish2jf0dw678j3ndr0dgs6qd0p0.ls error="server returned 404: 404 page not found\n"13382026/10/01 07:36:54 WARN Failed to register uploaded object key=nar/03nqbakiy238mvmicamqsmirrc58dw401cb26fyb1jf02n4axmvq.nar.zst error="server returned 404: 404 page not found\n"13392026/10/01 07:36:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13402026/10/01 07:36:54 WARN Failed to register uploaded object key=cf1qhcqq5gl1xyd9cz62lpn14r7lrdqd.ls error="server returned 404: 404 page not found\n"13412026/10/01 07:36:54 INFO Signed narinfos id=1 count=213422026/10/01 07:36:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13432026/10/01 07:36:54 INFO Signed narinfos id=2 count=213442026/10/01 07:36:54 INFO Uploading 4 narinfos13452026/10/01 07:36:54 WARN Failed to register uploaded object key=0f6izish2jf0dw678j3ndr0dgs6qd0p0.narinfo error="server returned 404: 404 page not found\n"13462026/10/01 07:36:54 WARN Failed to register uploaded object key=wzsxcr0lsjj0gbxgsycglhxsb39my44j.narinfo error="server returned 404: 404 page not found\n"13472026/10/01 07:36:54 WARN Failed to register uploaded object key=cf1qhcqq5gl1xyd9cz62lpn14r7lrdqd.narinfo error="server returned 404: 404 page not found\n"13482026/10/01 07:36:54 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13492026/10/01 07:36:54 WARN Failed to register uploaded object key=wzsxcr0lsjj0gbxgsycglhxsb39my44j.narinfo error="server returned 404: 404 page not found\n"13502026/10/01 07:36:54 INFO Completed upload id=213512026/10/01 07:36:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13522026/10/01 07:36:54 INFO Completed upload id=113532026-10-01 07:36:54.701 UTC [56572] ERROR: relation "goose_db_version" does not exist at character 3613542026-10-01 07:36:54.701 UTC [56572] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13552026/10/01 07:36:54 INFO Upload complete. (326ms)1356=== NAME TestClientFallsBackToClosures1357 client_pushes_test.go:112: Retrieved narinfo from S3:1358 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestClientFallsBackToClosures446737855/001/store/wzsxcr0lsjj0gbxgsycglhxsb39my44j-shared-dep1359 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1360 Compression: zstd1361 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821362 NarSize: 1361363 References: 1364 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1365 client_pushes_test.go:112: Retrieved narinfo from S3:1366 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestClientFallsBackToClosures446737855/001/store/0f6izish2jf0dw678j3ndr0dgs6qd0p0-a1367 URL: nar/03nqbakiy238mvmicamqsmirrc58dw401cb26fyb1jf02n4axmvq.nar.zst1368 Compression: zstd1369 NarHash: sha256:03nqbakiy238mvmicamqsmirrc58dw401cb26fyb1jf02n4axmvq1370 NarSize: 2481371 References: /nix/var/nix/builds/nix-54868-424906470/TestClientFallsBackToClosures446737855/001/store/wzsxcr0lsjj0gbxgsycglhxsb39my44j-shared-dep1372 CA: text:sha256:0cwfmvr2bvx7rakcxk8mc3sh9fqh7x768pxj9fp3ngdj6dhc5jq41373 client_pushes_test.go:112: Retrieved narinfo from S3:1374 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestClientFallsBackToClosures446737855/001/store/cf1qhcqq5gl1xyd9cz62lpn14r7lrdqd-b1375 URL: nar/03nqbakiy238mvmicamqsmirrc58dw401cb26fyb1jf02n4axmvq.nar.zst1376 Compression: zstd1377 NarHash: sha256:03nqbakiy238mvmicamqsmirrc58dw401cb26fyb1jf02n4axmvq1378 NarSize: 2481379 References: /nix/var/nix/builds/nix-54868-424906470/TestClientFallsBackToClosures446737855/001/store/wzsxcr0lsjj0gbxgsycglhxsb39my44j-shared-dep1380 CA: text:sha256:0cwfmvr2bvx7rakcxk8mc3sh9fqh7x768pxj9fp3ngdj6dhc5jq413812026/10/01 07:36:54 INFO Received uploads request method=POST path=/api/pending_closures1382--- PASS: TestClientFallsBackToClosures (3.11s)1383=== CONT TestPinProtectsFromGC13842026/10/01 07:36:54 OK 20241026095416_initial_model.sql (11.91ms)13852026/10/01 07:36:54 OK 20251210153512_drop_unused_gin_index.sql (6.41ms)13862026/10/01 07:36:54 OK 20251218171726_add_pins.sql (35.19ms)13872026/10/01 07:36:54 OK 20260628120000_add_object_size_and_stats.sql (44.45ms)13882026/10/01 07:36:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13892026/10/01 07:36:54 OK 20260905000000_add_claims.sql (89.5ms)13902026/10/01 07:36:54 OK 20260920000000_drop_claims.sql (46.03ms)13912026/10/01 07:36:55 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YzJlZDBmMmYtNDRlMS00NjdhLTkxMzQtMmE2YjY5MDVhZDU1LmY3YzljZDkzLThhNzktNDI0Yy1iMDc0LTk3ZTc3M2I2ZTBhZHgxNzkwODQwMjEzNDM4Njc5MDAw parts=1213922026/10/01 07:36:55 INFO Received uploads request method=POST path=/api/pending_closures1393--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.80s)1394=== CONT TestClientSharedPathCommittedMidPush13952026/10/01 07:36:55 OK 20260923120000_add_pushes.sql (46.24ms)13962026/10/01 07:36:55 goose: successfully migrated database to version: 2026092312000013972026/10/01 07:36:55 OK 1_commit_pending_closure.sql (3.8ms)13982026/10/01 07:36:55 OK 2_object_stats_trigger.sql (668.08µs)13992026/10/01 07:36:55 OK 3_commit_push.sql (498.5µs)14002026/10/01 07:36:55 goose: up to current file version: 314012026/10/01 07:36:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14022026/10/01 07:36:55 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzJlZDBmMmYtNDRlMS00NjdhLTkxMzQtMmE2YjY5MDVhZDU1Ljk0ZGRlMDYyLTU0YzQtNDVkZS1iODk5LTFlOTFiNmNjODhiMHgxNzkwODQwMjE0NzczNTUzMDAw14032026/10/01 07:36:55 INFO Received push request method=POST path=/api/pushes14042026/10/01 07:36:55 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YzJlZDBmMmYtNDRlMS00NjdhLTkxMzQtMmE2YjY5MDVhZDU1Ljk0ZGRlMDYyLTU0YzQtNDVkZS1iODk5LTFlOTFiNmNjODhiMHgxNzkwODQwMjE0NzczNTUzMDAw parts=11405--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (3.09s)1406=== CONT TestClientWithDependencies14072026/10/01 07:36:55 INFO Received complete push request method=POST path=/api/pushes/1/complete14082026/10/01 07:36:55 INFO Received push request method=POST path=/api/pushes14092026/10/01 07:36:55 INFO Aborted multipart uploads count=014102026/10/01 07:36:55 WARN Force mode enabled - objects will be deleted immediately without grace period14112026/10/01 07:36:55 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=014122026/10/01 07:36:55 INFO Vacuumed table table=pending_closures14132026/10/01 07:36:55 INFO Vacuumed table table=pending_objects14142026/10/01 07:36:55 INFO Received push request method=POST path=/api/pushes14152026/10/01 07:36:55 INFO Vacuumed table table=multipart_uploads14162026/10/01 07:36:55 INFO Vacuumed table table=closures14172026/10/01 07:36:55 INFO Vacuumed table table=objects14182026/10/01 07:36:55 INFO Received complete push request method=POST path=/api/pushes/2/complete1419--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (2.79s)1420=== CONT TestReadProxyRangeRequest14212026/10/01 07:36:55 INFO Received complete push request method=POST path=/api/pushes/1/complete1422--- PASS: TestPush_CompleteCommitsEveryRoot (2.58s)1423=== CONT TestIsValidCachePath1424=== RUN TestIsValidCachePath/narinfo1425=== PAUSE TestIsValidCachePath/narinfo1426=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1427=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1428=== RUN TestIsValidCachePath/nar_zst1429=== PAUSE TestIsValidCachePath/nar_zst1430=== RUN TestIsValidCachePath/nar_xz1431=== PAUSE TestIsValidCachePath/nar_xz1432=== RUN TestIsValidCachePath/nar_bz21433=== PAUSE TestIsValidCachePath/nar_bz21434=== RUN TestIsValidCachePath/nar_uncompressed1435=== PAUSE TestIsValidCachePath/nar_uncompressed1436=== RUN TestIsValidCachePath/ls1437=== PAUSE TestIsValidCachePath/ls1438=== RUN TestIsValidCachePath/log1439=== PAUSE TestIsValidCachePath/log1440=== RUN TestIsValidCachePath/realisation1441=== PAUSE TestIsValidCachePath/realisation1442=== RUN TestIsValidCachePath/nix-cache-info1443=== PAUSE TestIsValidCachePath/nix-cache-info1444=== RUN TestIsValidCachePath/index.html1445=== PAUSE TestIsValidCachePath/index.html1446=== RUN TestIsValidCachePath/traversal_parent1447=== PAUSE TestIsValidCachePath/traversal_parent1448=== RUN TestIsValidCachePath/traversal_in_middle1449=== PAUSE TestIsValidCachePath/traversal_in_middle1450=== RUN TestIsValidCachePath/invalid_char_e1451=== PAUSE TestIsValidCachePath/invalid_char_e1452=== RUN TestIsValidCachePath/invalid_char_u1453=== PAUSE TestIsValidCachePath/invalid_char_u1454=== RUN TestIsValidCachePath/random_path1455=== PAUSE TestIsValidCachePath/random_path1456=== RUN TestIsValidCachePath/empty1457=== PAUSE TestIsValidCachePath/empty1458=== RUN TestIsValidCachePath/leading_slash1459=== PAUSE TestIsValidCachePath/leading_slash1460=== RUN TestIsValidCachePath/wrong_extension1461=== PAUSE TestIsValidCachePath/wrong_extension1462=== RUN TestIsValidCachePath/short_hash1463=== PAUSE TestIsValidCachePath/short_hash1464=== CONT TestReadProxyNarinfo14652026-10-01 07:36:55.729 UTC [56634] ERROR: relation "goose_db_version" does not exist at character 3614662026-10-01 07:36:55.729 UTC [56634] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14672026/10/01 07:36:55 INFO Received push request method=POST path=/api/pushes1468--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (2.45s)1469=== CONT TestProxyHeadersOnlyTrustedOnSocket14702026/10/01 07:36:55 OK 20241026095416_initial_model.sql (137.67ms)14712026/10/01 07:36:55 OK 20251210153512_drop_unused_gin_index.sql (7.78ms)14722026/10/01 07:36:55 OK 20251218171726_add_pins.sql (18ms)14732026/10/01 07:36:55 OK 20260628120000_add_object_size_and_stats.sql (38.29ms)14742026/10/01 07:36:56 OK 20260905000000_add_claims.sql (38.25ms)14752026/10/01 07:36:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14762026/10/01 07:36:56 OK 20260920000000_drop_claims.sql (41.2ms)14772026/10/01 07:36:56 OK 20260923120000_add_pushes.sql (28.93ms)14782026/10/01 07:36:56 goose: successfully migrated database to version: 2026092312000014792026/10/01 07:36:56 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YzJlZDBmMmYtNDRlMS00NjdhLTkxMzQtMmE2YjY5MDVhZDU1LjUyYzA4N2QxLTIwZjctNDM5Yy1iYjJhLTAxYjk4YmNmM2E1MHgxNzkwODQwMjE0MTgyNzQ3MDAw parts=121480--- PASS: TestRedundantMultipartUpload (3.98s)1481=== CONT TestParseSingleRange1482=== RUN TestParseSingleRange/none1483=== PAUSE TestParseSingleRange/none1484=== RUN TestParseSingleRange/unknown_unit1485=== PAUSE TestParseSingleRange/unknown_unit1486=== RUN TestParseSingleRange/multi-range_ignored1487=== PAUSE TestParseSingleRange/multi-range_ignored1488=== RUN TestParseSingleRange/malformed_no_dash1489=== PAUSE TestParseSingleRange/malformed_no_dash1490=== RUN TestParseSingleRange/malformed_both_empty1491=== PAUSE TestParseSingleRange/malformed_both_empty1492=== RUN TestParseSingleRange/malformed_end_before_start1493=== PAUSE TestParseSingleRange/malformed_end_before_start1494=== RUN TestParseSingleRange/closed1495=== PAUSE TestParseSingleRange/closed1496=== RUN TestParseSingleRange/open-ended1497=== PAUSE TestParseSingleRange/open-ended1498=== RUN TestParseSingleRange/end_clamped_to_size1499=== PAUSE TestParseSingleRange/end_clamped_to_size1500=== RUN TestParseSingleRange/suffix1501=== PAUSE TestParseSingleRange/suffix1502=== RUN TestParseSingleRange/suffix_exceeds_size1503=== PAUSE TestParseSingleRange/suffix_exceeds_size1504=== RUN TestParseSingleRange/single_byte1505=== PAUSE TestParseSingleRange/single_byte1506=== RUN TestParseSingleRange/start_past_EOF1507=== PAUSE TestParseSingleRange/start_past_EOF1508=== RUN TestParseSingleRange/start_far_past_EOF1509=== PAUSE TestParseSingleRange/start_far_past_EOF1510=== CONT TestReadRedirectKeepsNarinfoProxied15112026/10/01 07:36:56 OK 1_commit_pending_closure.sql (3.06ms)15122026/10/01 07:36:56 OK 2_object_stats_trigger.sql (10.83ms)15132026/10/01 07:36:56 OK 3_commit_push.sql (66.97ms)15142026/10/01 07:36:56 goose: up to current file version: 31515--- PASS: TestReadRedirectUsesPublicS3URL (1.98s)1516=== CONT TestReadRedirectNar15172026-10-01 07:36:56.468 UTC [56685] ERROR: relation "goose_db_version" does not exist at character 3615182026-10-01 07:36:56.468 UTC [56685] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15192026-10-01 07:36:56.578 UTC [56690] ERROR: relation "goose_db_version" does not exist at character 3615202026-10-01 07:36:56.578 UTC [56690] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15212026/10/01 07:36:56 OK 20241026095416_initial_model.sql (89.41ms)15222026/10/01 07:36:56 OK 20251210153512_drop_unused_gin_index.sql (2.85ms)15232026/10/01 07:36:56 OK 20251218171726_add_pins.sql (24.9ms)15242026/10/01 07:36:56 OK 20260628120000_add_object_size_and_stats.sql (25.08ms)15252026/10/01 07:36:56 OK 20241026095416_initial_model.sql (71.5ms)15262026-10-01 07:36:56.691 UTC [56695] ERROR: relation "goose_db_version" does not exist at character 3615272026-10-01 07:36:56.691 UTC [56695] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15282026/10/01 07:36:56 OK 20251210153512_drop_unused_gin_index.sql (11.54ms)15292026/10/01 07:36:56 OK 20260905000000_add_claims.sql (39.26ms)15302026/10/01 07:36:56 OK 20251218171726_add_pins.sql (19.44ms)15312026/10/01 07:36:56 OK 20260920000000_drop_claims.sql (8.73ms)15322026/10/01 07:36:56 OK 20260923120000_add_pushes.sql (8.93ms)15332026/10/01 07:36:56 goose: successfully migrated database to version: 2026092312000015342026/10/01 07:36:56 OK 1_commit_pending_closure.sql (2.48ms)15352026/10/01 07:36:56 OK 2_object_stats_trigger.sql (633.88µs)15362026-10-01 07:36:56.733 UTC [56698] ERROR: relation "goose_db_version" does not exist at character 3615372026-10-01 07:36:56.733 UTC [56698] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15382026/10/01 07:36:56 OK 3_commit_push.sql (688.29µs)15392026/10/01 07:36:56 goose: up to current file version: 315402026/10/01 07:36:56 OK 20260628120000_add_object_size_and_stats.sql (16.79ms)15412026/10/01 07:36:56 OK 20260905000000_add_claims.sql (26.95ms)15422026/10/01 07:36:56 OK 20260920000000_drop_claims.sql (8.49ms)15432026-10-01 07:36:56.773 UTC [56700] ERROR: relation "goose_db_version" does not exist at character 3615442026-10-01 07:36:56.773 UTC [56700] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15452026/10/01 07:36:56 OK 20241026095416_initial_model.sql (52.82ms)15462026/10/01 07:36:56 OK 20260923120000_add_pushes.sql (1.91ms)15472026/10/01 07:36:56 goose: successfully migrated database to version: 2026092312000015482026/10/01 07:36:56 OK 1_commit_pending_closure.sql (1.05ms)15492026/10/01 07:36:56 OK 2_object_stats_trigger.sql (548.33µs)15502026/10/01 07:36:56 OK 3_commit_push.sql (420.13µs)15512026/10/01 07:36:56 goose: up to current file version: 315522026/10/01 07:36:56 OK 20251210153512_drop_unused_gin_index.sql (8.66ms)15532026/10/01 07:36:56 OK 20251218171726_add_pins.sql (13.63ms)15542026/10/01 07:36:56 OK 20260628120000_add_object_size_and_stats.sql (5.39ms)15552026/10/01 07:36:56 OK 20241026095416_initial_model.sql (50.84ms)15562026/10/01 07:36:56 OK 20251210153512_drop_unused_gin_index.sql (11.75ms)15572026/10/01 07:36:56 OK 20260905000000_add_claims.sql (48.54ms)15582026/10/01 07:36:56 OK 20251218171726_add_pins.sql (31.45ms)15592026/10/01 07:36:56 OK 20260920000000_drop_claims.sql (41.22ms)15602026/10/01 07:36:56 OK 20260628120000_add_object_size_and_stats.sql (30.77ms)15612026/10/01 07:36:56 OK 20260923120000_add_pushes.sql (6.5ms)15622026/10/01 07:36:56 goose: successfully migrated database to version: 2026092312000015632026/10/01 07:36:56 OK 20241026095416_initial_model.sql (100.92ms)15642026/10/01 07:36:56 OK 1_commit_pending_closure.sql (1.98ms)15652026/10/01 07:36:56 OK 2_object_stats_trigger.sql (652.96µs)15662026/10/01 07:36:56 OK 3_commit_push.sql (459.33µs)15672026/10/01 07:36:56 goose: up to current file version: 315682026/10/01 07:36:56 OK 20251210153512_drop_unused_gin_index.sql (9.27ms)15692026/10/01 07:36:56 INFO Received push request method=POST path=/api/pushes15702026/10/01 07:36:56 OK 20260905000000_add_claims.sql (26.9ms)15712026/10/01 07:36:56 OK 20251218171726_add_pins.sql (17.48ms)15722026/10/01 07:36:56 OK 20260920000000_drop_claims.sql (7.42ms)15732026/10/01 07:36:56 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15742026/10/01 07:36:56 INFO Uploading 6r7izixvrjwxfh5kcsxldb306rfq0rqg-shared-dep (136B)15752026/10/01 07:36:56 INFO Uploading s7cfy9c5vnhb0xvxffvdjnqb9ryyys22-b (248B)15762026/10/01 07:36:56 WARN Failed to register uploaded object key=6r7izixvrjwxfh5kcsxldb306rfq0rqg.ls error="server returned 404: 404 page not found\n"15772026/10/01 07:36:56 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15782026/10/01 07:36:56 WARN Failed to register uploaded object key=nar/1s3mddzfvdfdxq9895m73h7bsss1qz5vr6wp7pkhwg0jr36xh997.nar.zst error="server returned 404: 404 page not found\n"15792026/10/01 07:36:56 WARN Failed to register uploaded object key=nfxpcljl725msc6625w9pcq93yll1xnh.ls error="server returned 404: 404 page not found\n"15802026/10/01 07:36:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15812026/10/01 07:36:56 WARN Failed to register uploaded object key=s7cfy9c5vnhb0xvxffvdjnqb9ryyys22.ls error="server returned 404: 404 page not found\n"15822026/10/01 07:36:56 INFO Signed narinfos id=1 count=315832026/10/01 07:36:56 INFO Uploading 3 narinfos15842026/10/01 07:36:56 OK 20260923120000_add_pushes.sql (30.68ms)15852026/10/01 07:36:56 goose: successfully migrated database to version: 2026092312000015862026/10/01 07:36:56 OK 20260628120000_add_object_size_and_stats.sql (37.43ms)15872026/10/01 07:36:56 OK 1_commit_pending_closure.sql (2.13ms)15882026/10/01 07:36:56 OK 2_object_stats_trigger.sql (355.04µs)15892026/10/01 07:36:56 OK 3_commit_push.sql (224.71µs)15902026/10/01 07:36:56 goose: up to current file version: 315912026/10/01 07:36:56 WARN Failed to register uploaded object key=6r7izixvrjwxfh5kcsxldb306rfq0rqg.narinfo error="server returned 404: 404 page not found\n"15922026/10/01 07:36:56 WARN Failed to register uploaded object key=s7cfy9c5vnhb0xvxffvdjnqb9ryyys22.narinfo error="server returned 404: 404 page not found\n"15932026/10/01 07:36:56 INFO Received complete push request method=POST path=/api/pushes/1/complete15942026/10/01 07:36:56 WARN Failed to register uploaded object key=nfxpcljl725msc6625w9pcq93yll1xnh.narinfo error="server returned 404: 404 page not found\n"15952026/10/01 07:36:57 INFO Upload complete. (284ms)1596=== NAME TestClientPushesUseOnePush1597 client_pushes_test.go:97: Retrieved narinfo from S3:1598 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestClientPushesUseOnePush2829544719/001/store/6r7izixvrjwxfh5kcsxldb306rfq0rqg-shared-dep1599 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1600 Compression: zstd1601 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821602 NarSize: 1361603 References: 1604 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1605 client_pushes_test.go:97: Retrieved narinfo from S3:1606 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestClientPushesUseOnePush2829544719/001/store/nfxpcljl725msc6625w9pcq93yll1xnh-a1607 URL: nar/1s3mddzfvdfdxq9895m73h7bsss1qz5vr6wp7pkhwg0jr36xh997.nar.zst1608 Compression: zstd1609 NarHash: sha256:1s3mddzfvdfdxq9895m73h7bsss1qz5vr6wp7pkhwg0jr36xh9971610 NarSize: 2481611 References: /nix/var/nix/builds/nix-54868-424906470/TestClientPushesUseOnePush2829544719/001/store/6r7izixvrjwxfh5kcsxldb306rfq0rqg-shared-dep1612 CA: text:sha256:19n85a1mvm88mjs6v1x2kw8ysws4v71980cc3gsxmmcli7k19lw016132026/10/01 07:36:57 OK 20260905000000_add_claims.sql (64.22ms)1614 client_pushes_test.go:97: Retrieved narinfo from S3:1615 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestClientPushesUseOnePush2829544719/001/store/s7cfy9c5vnhb0xvxffvdjnqb9ryyys22-b1616 URL: nar/1s3mddzfvdfdxq9895m73h7bsss1qz5vr6wp7pkhwg0jr36xh997.nar.zst1617 Compression: zstd1618 NarHash: sha256:1s3mddzfvdfdxq9895m73h7bsss1qz5vr6wp7pkhwg0jr36xh9971619 NarSize: 2481620 References: /nix/var/nix/builds/nix-54868-424906470/TestClientPushesUseOnePush2829544719/001/store/6r7izixvrjwxfh5kcsxldb306rfq0rqg-shared-dep1621 CA: text:sha256:19n85a1mvm88mjs6v1x2kw8ysws4v71980cc3gsxmmcli7k19lw016222026/10/01 07:36:57 OK 20260920000000_drop_claims.sql (29.35ms)16232026/10/01 07:36:57 OK 20260923120000_add_pushes.sql (22.12ms)16242026/10/01 07:36:57 goose: successfully migrated database to version: 2026092312000016252026/10/01 07:36:57 OK 1_commit_pending_closure.sql (2.13ms)16262026/10/01 07:36:57 OK 2_object_stats_trigger.sql (560.33µs)16272026/10/01 07:36:57 OK 3_commit_push.sql (434.67µs)16282026/10/01 07:36:57 goose: up to current file version: 31629--- PASS: TestClientPushesUseOnePush (3.17s)1630=== CONT TestReadProxyDisabled1631=== NAME TestPinProtectsFromGC1632 client_integration_test.go:731: Pinned store path: /nix/var/nix/builds/nix-54868-424906470/TestPinProtectsFromGC2789548337/001/store/qvwxj8n05ln7pipjbm0zli8crfvwip10-pinned-file.txt1633 client_integration_test.go:732: Unpinned store path: /nix/var/nix/builds/nix-54868-424906470/TestPinProtectsFromGC2789548337/001/store/fwg3j5xddbp885mlw114gfkiirml8lw4-unpinned-file.txt16342026/10/01 07:36:57 WARN Rate limiter enabled after throttle name=s3-test rate=516352026/10/01 07:36:57 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1636=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1637 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101638 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001639--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.90s)1640=== CONT TestReadProxyRootRedirectsToIndexHTML16412026/10/01 07:36:57 INFO Received push request method=POST path=/api/pushes16422026-10-01 07:36:57.415 UTC [56756] ERROR: relation "goose_db_version" does not exist at character 3616432026-10-01 07:36:57.415 UTC [56756] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16442026/10/01 07:36:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16452026/10/01 07:36:57 INFO Uploading qvwxj8n05ln7pipjbm0zli8crfvwip10-pinned-file.txt (128B)16462026/10/01 07:36:57 WARN Failed to register uploaded object key=qvwxj8n05ln7pipjbm0zli8crfvwip10.ls error="server returned 404: 404 page not found\n"16472026/10/01 07:36:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16482026/10/01 07:36:57 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16492026/10/01 07:36:57 INFO Signed narinfos id=1 count=116502026/10/01 07:36:57 INFO Uploading 1 narinfos16512026/10/01 07:36:57 INFO Received complete push request method=POST path=/api/pushes/1/complete16522026/10/01 07:36:57 WARN Failed to register uploaded object key=qvwxj8n05ln7pipjbm0zli8crfvwip10.narinfo error="server returned 404: 404 page not found\n"16532026/10/01 07:36:57 INFO Upload complete. (197ms)16542026/10/01 07:36:57 INFO Received push request method=POST path=/api/pushes16552026/10/01 07:36:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16562026/10/01 07:36:57 INFO Uploading fwg3j5xddbp885mlw114gfkiirml8lw4-unpinned-file.txt (128B)16572026/10/01 07:36:57 OK 20241026095416_initial_model.sql (243.74ms)16582026/10/01 07:36:57 OK 20251210153512_drop_unused_gin_index.sql (14.72ms)16592026/10/01 07:36:57 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16602026/10/01 07:36:57 WARN Failed to register uploaded object key=fwg3j5xddbp885mlw114gfkiirml8lw4.ls error="server returned 404: 404 page not found\n"16612026/10/01 07:36:57 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16622026/10/01 07:36:57 INFO Signed narinfos id=2 count=116632026/10/01 07:36:57 INFO Uploading 1 narinfos16642026/10/01 07:36:57 OK 20251218171726_add_pins.sql (49.53ms)16652026/10/01 07:36:57 INFO Received complete push request method=POST path=/api/pushes/2/complete16662026/10/01 07:36:57 WARN Failed to register uploaded object key=fwg3j5xddbp885mlw114gfkiirml8lw4.narinfo error="server returned 404: 404 page not found\n"16672026/10/01 07:36:57 INFO Upload complete. (182ms)16682026/10/01 07:36:57 OK 20260628120000_add_object_size_and_stats.sql (45.41ms)16692026/10/01 07:36:57 INFO Received push request method=POST path=/api/pushes16702026/10/01 07:36:57 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16712026/10/01 07:36:57 INFO Uploading 12fasnyr0n1cks85b7vnd63jvhr2lawa-top (256B)16722026/10/01 07:36:57 INFO Uploading 4fppcl8py2zhr5yhscpv8nlvg0imf0gi-shared-dep (136B)16732026/10/01 07:36:57 INFO Received create pin request method=POST path=/api/pins/myapp16742026/10/01 07:36:57 WARN Failed to register uploaded object key=nar/1qwqimrxh8xj9xsvlwn44fcqr7f4d2ib8cbdsyndjln0j1rwfqfh.nar.zst error="server returned 404: 404 page not found\n"16752026/10/01 07:36:57 WARN Failed to register uploaded object key=12fasnyr0n1cks85b7vnd63jvhr2lawa.ls error="server returned 404: 404 page not found\n"16762026/10/01 07:36:57 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16772026/10/01 07:36:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16782026/10/01 07:36:57 WARN Failed to register uploaded object key=4fppcl8py2zhr5yhscpv8nlvg0imf0gi.ls error="server returned 404: 404 page not found\n"16792026/10/01 07:36:57 INFO Signed narinfos id=1 count=216802026/10/01 07:36:57 INFO Uploading 2 narinfos16812026/10/01 07:36:57 OK 20260905000000_add_claims.sql (89.06ms)16822026/10/01 07:36:57 INFO Created/updated pin name=myapp store_path=/nix/var/nix/builds/nix-54868-424906470/TestPinProtectsFromGC2789548337/001/store/qvwxj8n05ln7pipjbm0zli8crfvwip10-pinned-file.txt narinfo_key=qvwxj8n05ln7pipjbm0zli8crfvwip10.narinfo16832026/10/01 07:36:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures16842026/10/01 07:36:57 INFO Garbage collection started16852026/10/01 07:36:57 INFO Aborted multipart uploads count=016862026/10/01 07:36:57 WARN Force mode enabled - objects will be deleted immediately without grace period16872026/10/01 07:36:57 WARN Failed to register uploaded object key=12fasnyr0n1cks85b7vnd63jvhr2lawa.narinfo error="server returned 404: 404 page not found\n"16882026/10/01 07:36:57 INFO Received complete push request method=POST path=/api/pushes/1/complete16892026/10/01 07:36:57 WARN Failed to register uploaded object key=4fppcl8py2zhr5yhscpv8nlvg0imf0gi.narinfo error="server returned 404: 404 page not found\n"16902026/10/01 07:36:57 INFO Upload complete. (231ms)1691=== NAME TestClientSharedPathCommittedMidPush1692 client_integration_test.go:680: Retrieved narinfo from S3:1693 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestClientSharedPathCommittedMidPush1309924240/001/store/4fppcl8py2zhr5yhscpv8nlvg0imf0gi-shared-dep1694 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1695 Compression: zstd1696 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821697 NarSize: 1361698 References: 1699 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1700 client_integration_test.go:680: Retrieved narinfo from S3:1701 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestClientSharedPathCommittedMidPush1309924240/001/store/12fasnyr0n1cks85b7vnd63jvhr2lawa-top1702 URL: nar/1qwqimrxh8xj9xsvlwn44fcqr7f4d2ib8cbdsyndjln0j1rwfqfh.nar.zst1703 Compression: zstd1704 NarHash: sha256:1qwqimrxh8xj9xsvlwn44fcqr7f4d2ib8cbdsyndjln0j1rwfqfh1705 NarSize: 2561706 References: /nix/var/nix/builds/nix-54868-424906470/TestClientSharedPathCommittedMidPush1309924240/001/store/4fppcl8py2zhr5yhscpv8nlvg0imf0gi-shared-dep1707 CA: text:sha256:0863fff94z9fmwzyyiavjfnirvq8q7v86jhp747v8cziij3p9fkw17082026/10/01 07:36:57 OK 20260920000000_drop_claims.sql (60.25ms)17092026/10/01 07:36:57 OK 20260923120000_add_pushes.sql (14.63ms)17102026/10/01 07:36:57 goose: successfully migrated database to version: 2026092312000017112026/10/01 07:36:57 OK 1_commit_pending_closure.sql (2.6ms)17122026/10/01 07:36:57 OK 2_object_stats_trigger.sql (575.88µs)17132026/10/01 07:36:57 OK 3_commit_push.sql (456.63µs)17142026/10/01 07:36:57 goose: up to current file version: 317152026/10/01 07:36:57 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=01716--- PASS: TestReadProxyNarinfo (2.46s)1717=== CONT TestReadProxyConditionalGet17182026/10/01 07:36:57 INFO Vacuumed table table=pending_closures1719--- PASS: TestClientSharedPathCommittedMidPush (2.99s)1720=== CONT TestReadProxyHead17212026/10/01 07:36:58 INFO Vacuumed table table=pending_objects17222026/10/01 07:36:58 INFO Vacuumed table table=multipart_uploads17232026/10/01 07:36:58 INFO Vacuumed table table=closures17242026-10-01 07:36:58.085 UTC [56788] ERROR: relation "goose_db_version" does not exist at character 3617252026-10-01 07:36:58.085 UTC [56788] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17262026/10/01 07:36:58 INFO Vacuumed table table=objects17272026-10-01 07:36:58.138 UTC [56794] ERROR: relation "goose_db_version" does not exist at character 3617282026-10-01 07:36:58.138 UTC [56794] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1729--- PASS: TestReadProxyRangeRequest (2.78s)1730=== CONT TestReadProxyInvalidPath17312026/10/01 07:36:58 OK 20241026095416_initial_model.sql (194.97ms)17322026/10/01 07:36:58 OK 20251210153512_drop_unused_gin_index.sql (13.45ms)17332026/10/01 07:36:58 OK 20251218171726_add_pins.sql (35.05ms)17342026/10/01 07:36:58 OK 20241026095416_initial_model.sql (211.19ms)17352026/10/01 07:36:58 OK 20260628120000_add_object_size_and_stats.sql (15.61ms)1736=== NAME TestClientWithDependencies1737 client_integration_test.go:613: Built derivation: /nix/var/nix/builds/nix-54868-424906470/TestClientWithDependencies3575715257/001/store/68aypbnbfc0w7brkpq19d1v92s6s0jxk-test-script17382026/10/01 07:36:58 OK 20251210153512_drop_unused_gin_index.sql (22.42ms)17392026/10/01 07:36:58 OK 20260905000000_add_claims.sql (41.96ms)17402026/10/01 07:36:58 OK 20260920000000_drop_claims.sql (9.66ms)17412026/10/01 07:36:58 OK 20251218171726_add_pins.sql (28.08ms)17422026/10/01 07:36:58 OK 20260923120000_add_pushes.sql (12.23ms)17432026/10/01 07:36:58 goose: successfully migrated database to version: 202609231200001744 client_integration_test.go:615: Found 1 dependencies (including self)17452026/10/01 07:36:58 OK 1_commit_pending_closure.sql (8.79ms)17462026/10/01 07:36:58 OK 2_object_stats_trigger.sql (11.25ms)17472026/10/01 07:36:58 OK 3_commit_push.sql (486.17µs)17482026/10/01 07:36:58 goose: up to current file version: 317492026/10/01 07:36:58 OK 20260628120000_add_object_size_and_stats.sql (38.82ms)17502026-10-01 07:36:58.532 UTC [56802] ERROR: relation "goose_db_version" does not exist at character 3617512026-10-01 07:36:58.532 UTC [56802] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17522026/10/01 07:36:58 OK 20260905000000_add_claims.sql (88.99ms)17532026/10/01 07:36:58 OK 20260920000000_drop_claims.sql (20.24ms)17542026/10/01 07:36:58 OK 20260923120000_add_pushes.sql (30.48ms)17552026/10/01 07:36:58 goose: successfully migrated database to version: 2026092312000017562026/10/01 07:36:58 OK 1_commit_pending_closure.sql (2.44ms)17572026/10/01 07:36:58 OK 2_object_stats_trigger.sql (607.58µs)17582026/10/01 07:36:58 OK 3_commit_push.sql (306.96µs)17592026/10/01 07:36:58 goose: up to current file version: 317602026/10/01 07:36:58 INFO Starting HTTP server address=127.0.0.1:5624117612026/10/01 07:36:58 INFO Starting HTTP server address=/nix/var/nix/builds/nix-54868-424906470/TestProxyHeadersOnlyTrustedOnSocket838078080/001/proxy.sock17622026/10/01 07:36:58 INFO Received push request method=POST path=/api/pushes17632026/10/01 07:36:58 WARN mTLS auth: subject not in bound subjects subject="CN=someone"17642026/10/01 07:36:58 INFO Shutdown signal received, draining in-flight requests timeout=10s1765--- PASS: TestProxyHeadersOnlyTrustedOnSocket (2.78s)1766=== CONT TestReadProxy40417672026/10/01 07:36:58 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17682026/10/01 07:36:58 INFO Uploading 68aypbnbfc0w7brkpq19d1v92s6s0jxk-test-script (136B)17692026/10/01 07:36:58 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17702026/10/01 07:36:58 WARN Failed to register uploaded object key=68aypbnbfc0w7brkpq19d1v92s6s0jxk.ls error="server returned 404: 404 page not found\n"17712026/10/01 07:36:58 WARN Failed to register uploaded object key=log/d6r3w9ssfqr4ld08apr49wx7miznfg38-test-script.drv error="server returned 404: 404 page not found\n"17722026/10/01 07:36:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17732026/10/01 07:36:58 INFO Signed narinfos id=1 count=117742026/10/01 07:36:58 INFO Uploading 1 narinfos17752026/10/01 07:36:58 INFO Received complete push request method=POST path=/api/pushes/1/complete17762026/10/01 07:36:58 WARN Failed to register uploaded object key=68aypbnbfc0w7brkpq19d1v92s6s0jxk.narinfo error="server returned 404: 404 page not found\n"17772026/10/01 07:36:58 INFO Upload complete. (247ms)1778=== NAME TestClientWithDependencies1779 client_integration_test.go:617: Skipping nix copy test - isolated store (/nix/var/nix/builds/nix-54868-424906470/TestClientWithDependencies3575715257/001/store) requires matching store prefix17802026/10/01 07:36:58 OK 20241026095416_initial_model.sql (140.39ms)17812026/10/01 07:36:58 OK 20251210153512_drop_unused_gin_index.sql (7.45ms)17822026/10/01 07:36:58 OK 20251218171726_add_pins.sql (44.2ms)1783--- PASS: TestClientWithDependencies (3.68s)1784=== CONT TestReadProxyNarStreaming17852026/10/01 07:36:58 OK 20260628120000_add_object_size_and_stats.sql (42.11ms)17862026/10/01 07:36:58 OK 20260905000000_add_claims.sql (27.24ms)1787--- PASS: TestReadRedirectKeepsNarinfoProxied (2.85s)1788=== CONT TestCreatePin_ReservedPins17892026/10/01 07:36:58 OK 20260920000000_drop_claims.sql (47.15ms)17902026/10/01 07:36:58 OK 20260923120000_add_pushes.sql (21.83ms)17912026/10/01 07:36:58 goose: successfully migrated database to version: 2026092312000017922026/10/01 07:36:58 OK 1_commit_pending_closure.sql (2.19ms)17932026/10/01 07:36:58 OK 2_object_stats_trigger.sql (258.21µs)17942026/10/01 07:36:58 OK 3_commit_push.sql (197.67µs)17952026/10/01 07:36:58 goose: up to current file version: 317962026/10/01 07:36:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56256/oidc17972026-10-01 07:36:59.044 UTC [56819] ERROR: relation "goose_db_version" does not exist at character 3617982026-10-01 07:36:59.044 UTC [56819] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1799--- PASS: TestReadRedirectNar (2.73s)1800=== CONT TestReadProxyNarinfoAlreadyDecompressed18012026/10/01 07:36:59 OK 20241026095416_initial_model.sql (148.45ms)18022026/10/01 07:36:59 OK 20251210153512_drop_unused_gin_index.sql (13.62ms)18032026/10/01 07:36:59 OK 20251218171726_add_pins.sql (5.95ms)18042026/10/01 07:36:59 OK 20260628120000_add_object_size_and_stats.sql (28.91ms)18052026/10/01 07:36:59 OK 20260905000000_add_claims.sql (43.32ms)18062026/10/01 07:36:59 OK 20260920000000_drop_claims.sql (5.69ms)1807--- PASS: TestReadProxyDisabled (2.30s)1808=== CONT TestService_ReadScope_PublicByDefault18092026/10/01 07:36:59 OK 20260923120000_add_pushes.sql (56.23ms)18102026/10/01 07:36:59 goose: successfully migrated database to version: 2026092312000018112026/10/01 07:36:59 OK 1_commit_pending_closure.sql (2.05ms)18122026/10/01 07:36:59 OK 2_object_stats_trigger.sql (302.63µs)18132026/10/01 07:36:59 OK 3_commit_push.sql (182.96µs)18142026/10/01 07:36:59 goose: up to current file version: 318152026-10-01 07:36:59.468 UTC [56831] ERROR: relation "goose_db_version" does not exist at character 3618162026-10-01 07:36:59.468 UTC [56831] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18172026-10-01 07:36:59.468 UTC [56828] ERROR: relation "goose_db_version" does not exist at character 3618182026-10-01 07:36:59.468 UTC [56828] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18192026-10-01 07:36:59.548 UTC [56841] ERROR: relation "goose_db_version" does not exist at character 3618202026-10-01 07:36:59.548 UTC [56841] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18212026/10/01 07:36:59 OK 20241026095416_initial_model.sql (102.89ms)18222026/10/01 07:36:59 OK 20241026095416_initial_model.sql (109.32ms)18232026/10/01 07:36:59 OK 20251210153512_drop_unused_gin_index.sql (12.13ms)18242026/10/01 07:36:59 OK 20251210153512_drop_unused_gin_index.sql (20.71ms)18252026/10/01 07:36:59 OK 20251218171726_add_pins.sql (15.95ms)18262026/10/01 07:36:59 OK 20251218171726_add_pins.sql (37.66ms)18272026/10/01 07:36:59 OK 20260628120000_add_object_size_and_stats.sql (40.51ms)18282026/10/01 07:36:59 OK 20260628120000_add_object_size_and_stats.sql (12.97ms)18292026/10/01 07:36:59 OK 20260905000000_add_claims.sql (39.81ms)18302026/10/01 07:36:59 OK 20260905000000_add_claims.sql (30.61ms)18312026/10/01 07:36:59 OK 20260920000000_drop_claims.sql (16.02ms)18322026/10/01 07:36:59 OK 20241026095416_initial_model.sql (127.66ms)18332026/10/01 07:36:59 OK 20260920000000_drop_claims.sql (30.29ms)18342026/10/01 07:36:59 OK 20251210153512_drop_unused_gin_index.sql (16ms)18352026/10/01 07:36:59 OK 20260923120000_add_pushes.sql (21.36ms)18362026/10/01 07:36:59 goose: successfully migrated database to version: 202609231200001837--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.43s)1838=== CONT TestClientIntegration18392026/10/01 07:36:59 OK 20260923120000_add_pushes.sql (28.19ms)18402026/10/01 07:36:59 goose: successfully migrated database to version: 2026092312000018412026/10/01 07:36:59 OK 1_commit_pending_closure.sql (21.14ms)18422026/10/01 07:36:59 OK 2_object_stats_trigger.sql (9.72ms)18432026/10/01 07:36:59 OK 1_commit_pending_closure.sql (11.52ms)18442026/10/01 07:36:59 OK 20251218171726_add_pins.sql (34.75ms)18452026/10/01 07:36:59 OK 3_commit_push.sql (9.22ms)18462026/10/01 07:36:59 goose: up to current file version: 318472026/10/01 07:36:59 OK 2_object_stats_trigger.sql (8.83ms)18482026/10/01 07:36:59 OK 3_commit_push.sql (1.11ms)18492026/10/01 07:36:59 goose: up to current file version: 318502026/10/01 07:36:59 OK 20260628120000_add_object_size_and_stats.sql (38.49ms)18512026/10/01 07:36:59 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01852=== NAME TestPinProtectsFromGC1853 client_integration_test.go:794: Pin successfully protected closure from garbage collection18542026-10-01 07:36:59.895 UTC [56856] ERROR: relation "goose_db_version" does not exist at character 3618552026-10-01 07:36:59.895 UTC [56856] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18562026/10/01 07:36:59 OK 20260905000000_add_claims.sql (35.5ms)1857--- PASS: TestPinProtectsFromGC (5.15s)1858=== CONT TestClientErrorHandling1859=== RUN TestClientErrorHandling/InvalidStorePath1860=== PAUSE TestClientErrorHandling/InvalidStorePath1861=== RUN TestClientErrorHandling/InvalidAuthToken1862=== PAUSE TestClientErrorHandling/InvalidAuthToken1863=== RUN TestClientErrorHandling/ServerNotAvailable1864=== PAUSE TestClientErrorHandling/ServerNotAvailable1865=== CONT TestOrphanedObjectsGCStressTest18662026/10/01 07:36:59 OK 20260920000000_drop_claims.sql (12.98ms)18672026/10/01 07:36:59 OK 20260923120000_add_pushes.sql (18.75ms)18682026/10/01 07:36:59 goose: successfully migrated database to version: 2026092312000018692026-10-01 07:36:59.948 UTC [56868] ERROR: relation "goose_db_version" does not exist at character 3618702026-10-01 07:36:59.948 UTC [56868] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18712026/10/01 07:36:59 OK 1_commit_pending_closure.sql (22ms)18722026/10/01 07:36:59 OK 2_object_stats_trigger.sql (14.9ms)18732026/10/01 07:37:00 OK 3_commit_push.sql (33.27ms)18742026/10/01 07:37:00 goose: up to current file version: 318752026/10/01 07:37:00 OK 20241026095416_initial_model.sql (123.55ms)18762026/10/01 07:37:00 OK 20251210153512_drop_unused_gin_index.sql (25.45ms)18772026-10-01 07:37:00.084 UTC [56884] ERROR: relation "goose_db_version" does not exist at character 3618782026-10-01 07:37:00.084 UTC [56884] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18792026/10/01 07:37:00 OK 20251218171726_add_pins.sql (23.1ms)18802026/10/01 07:37:00 OK 20260628120000_add_object_size_and_stats.sql (32.81ms)18812026/10/01 07:37:00 OK 20241026095416_initial_model.sql (112.89ms)18822026/10/01 07:37:00 OK 20260905000000_add_claims.sql (33.28ms)18832026/10/01 07:37:00 OK 20251210153512_drop_unused_gin_index.sql (11.35ms)18842026/10/01 07:37:00 OK 20260920000000_drop_claims.sql (19.75ms)18852026/10/01 07:37:00 OK 20251218171726_add_pins.sql (23.66ms)18862026/10/01 07:37:00 OK 20241026095416_initial_model.sql (80.75ms)18872026/10/01 07:37:00 OK 20260923120000_add_pushes.sql (23.51ms)18882026/10/01 07:37:00 goose: successfully migrated database to version: 2026092312000018892026/10/01 07:37:00 OK 20251210153512_drop_unused_gin_index.sql (10.88ms)18902026/10/01 07:37:00 OK 1_commit_pending_closure.sql (3.51ms)18912026/10/01 07:37:00 OK 2_object_stats_trigger.sql (811.63µs)18922026/10/01 07:37:00 OK 3_commit_push.sql (311.71µs)18932026/10/01 07:37:00 goose: up to current file version: 318942026/10/01 07:37:00 OK 20251218171726_add_pins.sql (16.55ms)18952026/10/01 07:37:00 OK 20260628120000_add_object_size_and_stats.sql (30.91ms)1896--- PASS: TestReadProxyHead (2.27s)1897=== CONT TestOrphanedObjectsGC18982026/10/01 07:37:00 OK 20260628120000_add_object_size_and_stats.sql (42.82ms)18992026-10-01 07:37:00.286 UTC [56887] ERROR: relation "goose_db_version" does not exist at character 3619002026-10-01 07:37:00.286 UTC [56887] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19012026/10/01 07:37:00 OK 20260905000000_add_claims.sql (49.65ms)19022026/10/01 07:37:00 OK 20260905000000_add_claims.sql (23.14ms)19032026/10/01 07:37:00 OK 20260920000000_drop_claims.sql (14.14ms)19042026/10/01 07:37:00 OK 20260920000000_drop_claims.sql (11.48ms)19052026/10/01 07:37:00 OK 20260923120000_add_pushes.sql (9.63ms)19062026/10/01 07:37:00 goose: successfully migrated database to version: 2026092312000019072026/10/01 07:37:00 OK 1_commit_pending_closure.sql (1.66ms)19082026/10/01 07:37:00 OK 2_object_stats_trigger.sql (285.79µs)19092026/10/01 07:37:00 OK 3_commit_push.sql (232.54µs)19102026/10/01 07:37:00 goose: up to current file version: 319112026/10/01 07:37:00 OK 20260923120000_add_pushes.sql (32.26ms)19122026/10/01 07:37:00 goose: successfully migrated database to version: 2026092312000019132026/10/01 07:37:00 OK 1_commit_pending_closure.sql (2.06ms)19142026/10/01 07:37:00 OK 2_object_stats_trigger.sql (611.04µs)19152026/10/01 07:37:00 OK 3_commit_push.sql (467.67µs)19162026/10/01 07:37:00 goose: up to current file version: 319172026-10-01 07:37:00.425 UTC [56892] ERROR: relation "goose_db_version" does not exist at character 3619182026-10-01 07:37:00.425 UTC [56892] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19192026/10/01 07:37:00 OK 20241026095416_initial_model.sql (120.43ms)19202026/10/01 07:37:00 OK 20251210153512_drop_unused_gin_index.sql (10.55ms)19212026/10/01 07:37:00 OK 20251218171726_add_pins.sql (19.02ms)19222026/10/01 07:37:00 OK 20260628120000_add_object_size_and_stats.sql (20.99ms)19232026/10/01 07:37:00 OK 20260905000000_add_claims.sql (21.09ms)19242026/10/01 07:37:00 OK 20260920000000_drop_claims.sql (9.98ms)19252026/10/01 07:37:00 OK 20260923120000_add_pushes.sql (11.29ms)19262026/10/01 07:37:00 goose: successfully migrated database to version: 2026092312000019272026/10/01 07:37:00 OK 1_commit_pending_closure.sql (2.22ms)19282026/10/01 07:37:00 OK 2_object_stats_trigger.sql (508.17µs)19292026/10/01 07:37:00 OK 3_commit_push.sql (588.13µs)19302026/10/01 07:37:00 goose: up to current file version: 31931--- PASS: TestReadProxyConditionalGet (2.57s)1932=== CONT TestClientCADerivations19332026/10/01 07:37:00 OK 20241026095416_initial_model.sql (124.05ms)19342026/10/01 07:37:00 OK 20251210153512_drop_unused_gin_index.sql (8.56ms)19352026/10/01 07:37:00 OK 20251218171726_add_pins.sql (22.8ms)19362026/10/01 07:37:00 OK 20260628120000_add_object_size_and_stats.sql (36.09ms)19372026/10/01 07:37:00 OK 20260905000000_add_claims.sql (10.8ms)19382026/10/01 07:37:00 OK 20260920000000_drop_claims.sql (18.66ms)19392026/10/01 07:37:00 OK 20260923120000_add_pushes.sql (11.29ms)19402026/10/01 07:37:00 goose: successfully migrated database to version: 2026092312000019412026/10/01 07:37:00 OK 1_commit_pending_closure.sql (1.9ms)19422026/10/01 07:37:00 OK 2_object_stats_trigger.sql (280.33µs)19432026/10/01 07:37:00 OK 3_commit_push.sql (202.79µs)19442026/10/01 07:37:00 goose: up to current file version: 31945--- PASS: TestReadProxyInvalidPath (2.53s)1946=== CONT TestCacheStatsHandler19472026-10-01 07:37:00.905 UTC [56906] ERROR: relation "goose_db_version" does not exist at character 3619482026-10-01 07:37:00.905 UTC [56906] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19492026-10-01 07:37:00.978 UTC [56909] ERROR: relation "goose_db_version" does not exist at character 3619502026-10-01 07:37:00.978 UTC [56909] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19512026/10/01 07:37:01 OK 20241026095416_initial_model.sql (107.05ms)19522026/10/01 07:37:01 OK 20251210153512_drop_unused_gin_index.sql (11.53ms)19532026/10/01 07:37:01 OK 20251218171726_add_pins.sql (13.53ms)19542026/10/01 07:37:01 OK 20260628120000_add_object_size_and_stats.sql (20.46ms)19552026/10/01 07:37:01 OK 20241026095416_initial_model.sql (107.39ms)19562026/10/01 07:37:01 OK 20251210153512_drop_unused_gin_index.sql (4.06ms)19572026/10/01 07:37:01 OK 20260905000000_add_claims.sql (14.26ms)1958--- PASS: TestReadProxy404 (2.49s)1959=== CONT TestCacheConfigHandler1960=== RUN TestCacheConfigHandler/full_config,_no_issuer1961=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1962=== RUN TestCacheConfigHandler/no_cache_url_configured1963=== PAUSE TestCacheConfigHandler/no_cache_url_configured1964=== RUN TestCacheConfigHandler/no_signing_keys1965=== PAUSE TestCacheConfigHandler/no_signing_keys1966=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1967=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1968=== CONT TestObjectStatsTrigger19692026/10/01 07:37:01 OK 20260920000000_drop_claims.sql (31.43ms)19702026/10/01 07:37:01 OK 20251218171726_add_pins.sql (39.46ms)19712026/10/01 07:37:01 OK 20260923120000_add_pushes.sql (19.63ms)19722026/10/01 07:37:01 goose: successfully migrated database to version: 2026092312000019732026/10/01 07:37:01 OK 1_commit_pending_closure.sql (2.24ms)19742026/10/01 07:37:01 OK 2_object_stats_trigger.sql (611.58µs)19752026/10/01 07:37:01 OK 3_commit_push.sql (418.42µs)19762026/10/01 07:37:01 goose: up to current file version: 319772026/10/01 07:37:01 OK 20260628120000_add_object_size_and_stats.sql (33.69ms)19782026/10/01 07:37:01 OK 20260905000000_add_claims.sql (21.25ms)19792026/10/01 07:37:01 OK 20260920000000_drop_claims.sql (21.76ms)19802026/10/01 07:37:01 OK 20260923120000_add_pushes.sql (15.16ms)19812026/10/01 07:37:01 goose: successfully migrated database to version: 2026092312000019822026/10/01 07:37:01 OK 1_commit_pending_closure.sql (1.57ms)19832026/10/01 07:37:01 OK 2_object_stats_trigger.sql (885.25µs)19842026/10/01 07:37:01 OK 3_commit_push.sql (387.17µs)19852026/10/01 07:37:01 goose: up to current file version: 319862026/10/01 07:37:01 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux19872026/10/01 07:37:01 WARN Refused reserved pin name=worker-x86_64-linux19882026/10/01 07:37:01 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux19892026/10/01 07:37:01 INFO Received create pin request method=POST path=/api/pins/my-app19902026/10/01 07:37:01 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1991--- PASS: TestCreatePin_ReservedPins (2.47s)1992=== CONT TestMultipartCleanup19932026-10-01 07:37:01.438 UTC [56921] ERROR: relation "goose_db_version" does not exist at character 3619942026-10-01 07:37:01.438 UTC [56921] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19952026-10-01 07:37:01.497 UTC [56924] ERROR: relation "goose_db_version" does not exist at character 3619962026-10-01 07:37:01.497 UTC [56924] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19972026/10/01 07:37:01 OK 20241026095416_initial_model.sql (56.54ms)19982026/10/01 07:37:01 OK 20241026095416_initial_model.sql (85.93ms)19992026/10/01 07:37:01 OK 20251210153512_drop_unused_gin_index.sql (8.67ms)20002026/10/01 07:37:01 OK 20251210153512_drop_unused_gin_index.sql (11.2ms)20012026/10/01 07:37:01 OK 20251218171726_add_pins.sql (11.5ms)20022026/10/01 07:37:01 OK 20251218171726_add_pins.sql (23.17ms)20032026/10/01 07:37:01 OK 20260628120000_add_object_size_and_stats.sql (23.1ms)20042026/10/01 07:37:01 OK 20260628120000_add_object_size_and_stats.sql (28.14ms)20052026/10/01 07:37:01 OK 20260905000000_add_claims.sql (36.65ms)20062026/10/01 07:37:01 OK 20260905000000_add_claims.sql (31.15ms)20072026/10/01 07:37:01 OK 20260920000000_drop_claims.sql (15.14ms)20082026/10/01 07:37:01 OK 20260920000000_drop_claims.sql (15.55ms)20092026/10/01 07:37:01 OK 20260923120000_add_pushes.sql (14.76ms)20102026/10/01 07:37:01 goose: successfully migrated database to version: 2026092312000020112026/10/01 07:37:01 OK 20260923120000_add_pushes.sql (15.11ms)20122026/10/01 07:37:01 goose: successfully migrated database to version: 2026092312000020132026/10/01 07:37:01 OK 1_commit_pending_closure.sql (1.69ms)20142026/10/01 07:37:01 OK 2_object_stats_trigger.sql (431.08µs)20152026/10/01 07:37:01 OK 1_commit_pending_closure.sql (1.03ms)20162026/10/01 07:37:01 OK 3_commit_push.sql (226.88µs)20172026/10/01 07:37:01 goose: up to current file version: 320182026/10/01 07:37:01 OK 2_object_stats_trigger.sql (320.46µs)20192026/10/01 07:37:01 OK 3_commit_push.sql (218.42µs)20202026/10/01 07:37:01 goose: up to current file version: 32021--- PASS: TestReadProxyNarStreaming (2.90s)2022=== CONT TestServerTLSConfig2023=== RUN TestServerTLSConfig/no_client_CA2024=== PAUSE TestServerTLSConfig/no_client_CA2025=== RUN TestServerTLSConfig/missing_CA_file2026=== PAUSE TestServerTLSConfig/missing_CA_file2027=== RUN TestServerTLSConfig/not_a_PEM_file2028=== PAUSE TestServerTLSConfig/not_a_PEM_file2029=== CONT TestService_NativeMTLS20302026-10-01 07:37:01.878 UTC [56979] ERROR: relation "goose_db_version" does not exist at character 3620312026-10-01 07:37:01.878 UTC [56979] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20322026/10/01 07:37:02 OK 20241026095416_initial_model.sql (84.83ms)20332026/10/01 07:37:02 OK 20251210153512_drop_unused_gin_index.sql (8.75ms)2034--- PASS: TestReadProxyNarinfoAlreadyDecompressed (2.85s)2035=== CONT TestGCTaskStore_GetEmpty2036--- PASS: TestGCTaskStore_GetEmpty (0.00s)2037=== CONT TestMetricsInventory20382026/10/01 07:37:02 OK 20251218171726_add_pins.sql (45.17ms)20392026/10/01 07:37:02 OK 20260628120000_add_object_size_and_stats.sql (32.97ms)20402026/10/01 07:37:02 OK 20260905000000_add_claims.sql (32.91ms)20412026-10-01 07:37:02.134 UTC [57000] ERROR: relation "goose_db_version" does not exist at character 3620422026-10-01 07:37:02.134 UTC [57000] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20432026/10/01 07:37:02 OK 20260920000000_drop_claims.sql (21.21ms)20442026/10/01 07:37:02 OK 20260923120000_add_pushes.sql (13.19ms)20452026/10/01 07:37:02 goose: successfully migrated database to version: 2026092312000020462026/10/01 07:37:02 OK 1_commit_pending_closure.sql (1.36ms)20472026/10/01 07:37:02 OK 2_object_stats_trigger.sql (563.29µs)20482026/10/01 07:37:02 OK 3_commit_push.sql (308.92µs)20492026/10/01 07:37:02 goose: up to current file version: 32050--- PASS: TestService_ReadScope_PublicByDefault (2.86s)2051=== CONT TestCreatePendingClosureRejectsOversizedNAR20522026/10/01 07:37:02 INFO Received uploads request method=POST path=/api/pending_closures2053--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2054=== CONT TestCacheConfigHandlerMaxNarSize2055--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)2056=== CONT TestService_ReadAuthMiddleware20572026/10/01 07:37:02 OK 20241026095416_initial_model.sql (86.28ms)20582026/10/01 07:37:02 OK 20251210153512_drop_unused_gin_index.sql (5.21ms)20592026-10-01 07:37:02.293 UTC [57002] ERROR: relation "goose_db_version" does not exist at character 3620602026-10-01 07:37:02.293 UTC [57002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20612026/10/01 07:37:02 OK 20251218171726_add_pins.sql (36.34ms)20622026/10/01 07:37:02 OK 20260628120000_add_object_size_and_stats.sql (8.48ms)20632026/10/01 07:37:02 OK 20260905000000_add_claims.sql (5.44ms)20642026/10/01 07:37:02 OK 20260920000000_drop_claims.sql (20.71ms)20652026/10/01 07:37:02 OK 20260923120000_add_pushes.sql (1.92ms)20662026/10/01 07:37:02 goose: successfully migrated database to version: 2026092312000020672026/10/01 07:37:02 OK 1_commit_pending_closure.sql (1.85ms)20682026/10/01 07:37:02 OK 2_object_stats_trigger.sql (485.17µs)20692026/10/01 07:37:02 OK 3_commit_push.sql (398.63µs)20702026/10/01 07:37:02 goose: up to current file version: 320712026/10/01 07:37:02 OK 20241026095416_initial_model.sql (49.84ms)20722026/10/01 07:37:02 OK 20251210153512_drop_unused_gin_index.sql (1.58ms)20732026/10/01 07:37:02 OK 20251218171726_add_pins.sql (18.53ms)20742026/10/01 07:37:02 OK 20260628120000_add_object_size_and_stats.sql (23.91ms)20752026/10/01 07:37:02 OK 20260905000000_add_claims.sql (47.03ms)20762026/10/01 07:37:02 OK 20260920000000_drop_claims.sql (32.53ms)20772026/10/01 07:37:02 OK 20260923120000_add_pushes.sql (3.45ms)20782026/10/01 07:37:02 goose: successfully migrated database to version: 2026092312000020792026/10/01 07:37:02 OK 1_commit_pending_closure.sql (1.6ms)20802026/10/01 07:37:02 OK 2_object_stats_trigger.sql (492.83µs)20812026/10/01 07:37:02 OK 3_commit_push.sql (360.96µs)20822026/10/01 07:37:02 goose: up to current file version: 32083=== NAME TestClientIntegration2084 client_integration_test.go:286: Created store path: /nix/var/nix/builds/nix-54868-424906470/TestClientIntegration2507321846/002/store/7pzg1v641f22c4iy3a55yk0a85wmpr36-test-file.txt20852026-10-01 07:37:02.761 UTC [57056] ERROR: relation "goose_db_version" does not exist at character 3620862026-10-01 07:37:02.761 UTC [57056] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20872026/10/01 07:37:02 INFO Received push request method=POST path=/api/pushes20882026/10/01 07:37:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20892026/10/01 07:37:02 INFO Uploading 7pzg1v641f22c4iy3a55yk0a85wmpr36-test-file.txt (152B)20902026/10/01 07:37:02 WARN Failed to register uploaded object key=7pzg1v641f22c4iy3a55yk0a85wmpr36.ls error="server returned 404: 404 page not found\n"20912026/10/01 07:37:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20922026/10/01 07:37:02 INFO Signed narinfos id=1 count=120932026/10/01 07:37:02 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"20942026/10/01 07:37:02 INFO Uploading 1 narinfos20952026/10/01 07:37:02 INFO Received complete push request method=POST path=/api/pushes/1/complete20962026/10/01 07:37:02 WARN Failed to register uploaded object key=7pzg1v641f22c4iy3a55yk0a85wmpr36.narinfo error="server returned 404: 404 page not found\n"20972026/10/01 07:37:02 INFO Upload complete. (150ms)20982026/10/01 07:37:02 INFO All 1 paths already cached2099 client_integration_test.go:312: Retrieved narinfo from S3:2100 StorePath: /nix/var/nix/builds/nix-54868-424906470/TestClientIntegration2507321846/002/store/7pzg1v641f22c4iy3a55yk0a85wmpr36-test-file.txt2101 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2102 Compression: zstd2103 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12104 NarSize: 1522105 References: 2106 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12107 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2108 client_integration_test.go:313: Decompressed .ls content (64 bytes):2109 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2110 client_integration_test.go:316: Testing garbage collection...21112026/10/01 07:37:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures21122026/10/01 07:37:02 INFO Garbage collection started21132026/10/01 07:37:02 INFO Aborted multipart uploads count=021142026/10/01 07:37:02 WARN Force mode enabled - objects will be deleted immediately without grace period21152026/10/01 07:37:03 OK 20241026095416_initial_model.sql (201.14ms)21162026/10/01 07:37:03 OK 20251210153512_drop_unused_gin_index.sql (9.91ms)21172026/10/01 07:37:03 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=021182026/10/01 07:37:03 OK 20251218171726_add_pins.sql (28.94ms)21192026/10/01 07:37:03 INFO Vacuumed table table=pending_closures21202026/10/01 07:37:03 OK 20260628120000_add_object_size_and_stats.sql (39.76ms)21212026/10/01 07:37:03 INFO Vacuumed table table=pending_objects21222026/10/01 07:37:03 INFO Vacuumed table table=multipart_uploads21232026/10/01 07:37:03 INFO Vacuumed table table=closures21242026/10/01 07:37:03 OK 20260905000000_add_claims.sql (64.89ms)21252026/10/01 07:37:03 OK 20260920000000_drop_claims.sql (34.92ms)21262026/10/01 07:37:03 INFO Vacuumed table table=objects21272026/10/01 07:37:03 OK 20260923120000_add_pushes.sql (5.5ms)21282026/10/01 07:37:03 goose: successfully migrated database to version: 2026092312000021292026-10-01 07:37:03.209 UTC [57076] ERROR: relation "goose_db_version" does not exist at character 3621302026-10-01 07:37:03.209 UTC [57076] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21312026/10/01 07:37:03 OK 1_commit_pending_closure.sql (1.37ms)21322026/10/01 07:37:03 OK 2_object_stats_trigger.sql (293.38µs)21332026/10/01 07:37:03 OK 3_commit_push.sql (236.67µs)21342026/10/01 07:37:03 goose: up to current file version: 321352026/10/01 07:37:03 OK 20241026095416_initial_model.sql (196.52ms)21362026/10/01 07:37:03 OK 20251210153512_drop_unused_gin_index.sql (12.11ms)21372026/10/01 07:37:03 OK 20251218171726_add_pins.sql (33.27ms)21382026/10/01 07:37:03 OK 20260628120000_add_object_size_and_stats.sql (30.83ms)21392026/10/01 07:37:03 OK 20260905000000_add_claims.sql (92.17ms)21402026/10/01 07:37:03 OK 20260920000000_drop_claims.sql (32.33ms)21412026/10/01 07:37:03 OK 20260923120000_add_pushes.sql (28.45ms)21422026/10/01 07:37:03 goose: successfully migrated database to version: 2026092312000021432026/10/01 07:37:03 OK 1_commit_pending_closure.sql (1.76ms)21442026/10/01 07:37:03 OK 2_object_stats_trigger.sql (252.17µs)21452026/10/01 07:37:03 OK 3_commit_push.sql (220.08µs)21462026/10/01 07:37:03 goose: up to current file version: 321472026-10-01 07:37:03.861 UTC [57080] ERROR: relation "goose_db_version" does not exist at character 3621482026-10-01 07:37:03.861 UTC [57080] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2149--- PASS: TestCacheStatsHandler (3.12s)2150=== CONT TestService_RequireScope_OIDC2151=== NAME TestOrphanedObjectsGC2152 orphaned_objects_gc_test.go:290: GC Test Summary:2153 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2154 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2155 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2156 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2157 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2158--- PASS: TestOrphanedObjectsGC (3.68s)2159=== CONT TestService_AuthMiddleware_OIDC21602026/10/01 07:37:03 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56322/oidc21612026/10/01 07:37:04 OK 20241026095416_initial_model.sql (136.23ms)21622026/10/01 07:37:04 OK 20251210153512_drop_unused_gin_index.sql (18.36ms)21632026/10/01 07:37:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56324/oidc21642026/10/01 07:37:04 OK 20251218171726_add_pins.sql (69.08ms)2165=== NAME TestClientCADerivations2166 client_ca_test.go:136: Built CA derivation: /nix/var/nix/builds/nix-54868-424906470/TestClientCADerivations4197557600/001/store/36xi9x79zcf2y4nv91fp265frsqxhkys-ca-test21672026/10/01 07:37:04 OK 20260628120000_add_object_size_and_stats.sql (12.54ms)2168 client_ca_test.go:139: Found 1 dependencies (including self)21692026/10/01 07:37:04 OK 20260905000000_add_claims.sql (60.82ms)2170--- PASS: TestObjectStatsTrigger (3.11s)2171=== CONT TestGenerateLandingPage2172--- PASS: TestGenerateLandingPage (0.00s)2173=== CONT TestService_AuthMiddleware_MTLSBoundSubjects21742026/10/01 07:37:04 OK 20260920000000_drop_claims.sql (50.5ms)21752026/10/01 07:37:04 OK 20260923120000_add_pushes.sql (10.99ms)21762026/10/01 07:37:04 goose: successfully migrated database to version: 2026092312000021772026/10/01 07:37:04 OK 1_commit_pending_closure.sql (956.33µs)21782026/10/01 07:37:04 OK 2_object_stats_trigger.sql (222.67µs)21792026/10/01 07:37:04 OK 3_commit_push.sql (199.75µs)21802026/10/01 07:37:04 goose: up to current file version: 321812026/10/01 07:37:04 INFO Received push request method=POST path=/api/pushes21822026/10/01 07:37:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21832026/10/01 07:37:04 INFO Uploading 36xi9x79zcf2y4nv91fp265frsqxhkys-ca-test (144B)21842026/10/01 07:37:04 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"21852026/10/01 07:37:04 WARN Failed to register uploaded object key=36xi9x79zcf2y4nv91fp265frsqxhkys.ls error="server returned 404: 404 page not found\n"21862026/10/01 07:37:04 WARN Failed to register uploaded object key=log/00ah3rdjwlc4ap15yxmnc7ryf2j7b792-ca-test.drv error="server returned 404: 404 page not found\n"21872026/10/01 07:37:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21882026/10/01 07:37:04 INFO Signed narinfos id=1 count=121892026/10/01 07:37:04 INFO Uploading 1 narinfos21902026/10/01 07:37:04 INFO Received complete push request method=POST path=/api/pushes/1/complete21912026/10/01 07:37:04 WARN Failed to register uploaded object key=36xi9x79zcf2y4nv91fp265frsqxhkys.narinfo error="server returned 404: 404 page not found\n"21922026/10/01 07:37:04 INFO Received uploads request method=POST path=/api/pending_closures21932026/10/01 07:37:04 INFO Upload complete. (270ms)2194=== NAME TestClientCADerivations2195 client_ca_test.go:180: Narinfo contains CA field: StorePath: /nix/var/nix/builds/nix-54868-424906470/TestClientCADerivations4197557600/001/store/36xi9x79zcf2y4nv91fp265frsqxhkys-ca-test2196 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2197 Compression: zstd2198 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2199 NarSize: 1442200 References: 2201 Deriver: /nix/var/nix/builds/nix-54868-424906470/TestClientCADerivations4197557600/001/store/00ah3rdjwlc4ap15yxmnc7ryf2j7b792-ca-test.drv2202 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2203 client_ca_test.go:185: Checking for realisation files in S3...2204 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2205 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2206 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket52?endpoint=http://localhost:56031®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/nix/var/nix/builds/nix-54868-424906470/TestClientCADerivations4197557600/001/store'2207 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 122082026/10/01 07:37:04 INFO Received cleanup request method=DELETE path=/api/pending_closures22092026/10/01 07:37:04 INFO Aborted multipart uploads count=12210--- PASS: TestMultipartCleanup (3.32s)2211=== CONT TestService_readinessHandler2212--- PASS: TestClientCADerivations (4.18s)2213=== CONT TestGCTaskStore_PhaseUpdates2214--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)2215=== CONT TestGCTaskStore_CompletedAllowsNewTask2216--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)2217=== CONT TestGCTaskStore_GetReturnsLatest2218--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)2219=== CONT TestGCTaskStore_Fail2220--- PASS: TestGCTaskStore_Fail (0.00s)2221=== CONT TestSweepSkipsRowsLockedByPush22222026/10/01 07:37:04 WARN mTLS auth: subject not in bound subjects subject="CN=reader"22232026/10/01 07:37:04 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2224--- PASS: TestService_NativeMTLS (3.06s)2225=== CONT TestService_healthCheckHandler22262026/10/01 07:37:04 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02227=== NAME TestClientIntegration2228 client_integration_test.go:323: Objects in database after GC:2229 client_integration_test.go:323: Successfully deleted all objects with GC --force2230--- PASS: TestClientIntegration (5.28s)2231=== CONT TestGCTaskStore_ConflictDifferentParams2232--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)2233=== CONT TestGracefulShutdownDrainsInflight22342026/10/01 07:37:05 INFO Starting HTTP server address=127.0.0.1:5634322352026/10/01 07:37:05 INFO Shutdown signal received, draining in-flight requests timeout=10s2236--- PASS: TestGracefulShutdownDrainsInflight (0.07s)2237=== CONT TestGCTaskStore_DeduplicateSameParams2238--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)2239=== CONT TestGCTaskStore_StartNew2240--- PASS: TestGCTaskStore_StartNew (0.00s)2241=== CONT TestService_AuthMiddleware_MTLSProxyHeader2242--- PASS: TestMetricsInventory (3.19s)2243=== CONT TestGetExistingObjectsLocksRows2244--- PASS: TestService_ReadAuthMiddleware (3.21s)2245=== CONT TestRegisterCompletedObjectNeedsPendingRow22462026-10-01 07:37:05.729 UTC [57169] ERROR: relation "goose_db_version" does not exist at character 3622472026-10-01 07:37:05.729 UTC [57169] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22482026/10/01 07:37:05 OK 20241026095416_initial_model.sql (84.97ms)22492026/10/01 07:37:05 OK 20251210153512_drop_unused_gin_index.sql (17.44ms)22502026-10-01 07:37:05.907 UTC [57170] ERROR: relation "goose_db_version" does not exist at character 3622512026-10-01 07:37:05.907 UTC [57170] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22522026/10/01 07:37:05 OK 20251218171726_add_pins.sql (20.43ms)22532026/10/01 07:37:05 OK 20260628120000_add_object_size_and_stats.sql (32.16ms)22542026/10/01 07:37:05 OK 20260905000000_add_claims.sql (18.26ms)22552026/10/01 07:37:05 OK 20260920000000_drop_claims.sql (25.93ms)22562026/10/01 07:37:05 OK 20260923120000_add_pushes.sql (9.76ms)22572026/10/01 07:37:05 goose: successfully migrated database to version: 2026092312000022582026/10/01 07:37:05 OK 1_commit_pending_closure.sql (3.11ms)22592026/10/01 07:37:05 OK 2_object_stats_trigger.sql (249.67µs)22602026/10/01 07:37:05 OK 3_commit_push.sql (152µs)22612026/10/01 07:37:05 goose: up to current file version: 322622026-10-01 07:37:06.068 UTC [57172] ERROR: relation "goose_db_version" does not exist at character 3622632026-10-01 07:37:06.068 UTC [57172] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22642026/10/01 07:37:06 OK 20241026095416_initial_model.sql (141.32ms)22652026/10/01 07:37:06 OK 20251210153512_drop_unused_gin_index.sql (18.22ms)22662026/10/01 07:37:06 OK 20251218171726_add_pins.sql (31.45ms)22672026/10/01 07:37:06 OK 20260628120000_add_object_size_and_stats.sql (43.52ms)22682026/10/01 07:37:06 OK 20260905000000_add_claims.sql (49.79ms)22692026/10/01 07:37:06 OK 20241026095416_initial_model.sql (147.64ms)22702026/10/01 07:37:06 OK 20260920000000_drop_claims.sql (48.22ms)22712026/10/01 07:37:06 OK 20251210153512_drop_unused_gin_index.sql (14.79ms)22722026/10/01 07:37:06 OK 20260923120000_add_pushes.sql (33.88ms)22732026/10/01 07:37:06 goose: successfully migrated database to version: 2026092312000022742026/10/01 07:37:06 OK 1_commit_pending_closure.sql (4.14ms)22752026/10/01 07:37:06 OK 2_object_stats_trigger.sql (248.75µs)22762026/10/01 07:37:06 OK 3_commit_push.sql (361.46µs)22772026/10/01 07:37:06 goose: up to current file version: 322782026/10/01 07:37:06 OK 20251218171726_add_pins.sql (30.5ms)2279=== RUN TestService_RequireScope_OIDC/builder_may_write2280=== PAUSE TestService_RequireScope_OIDC/builder_may_write2281=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2282=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2283=== RUN TestService_RequireScope_OIDC/ops_may_admin2284=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2285=== RUN TestService_RequireScope_OIDC/ops_may_not_write2286=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2287=== RUN TestService_RequireScope_OIDC/reader_may_not_write2288=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2289=== RUN TestService_RequireScope_OIDC/static_token_may_admin2290=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2291=== RUN TestService_RequireScope_OIDC/static_token_may_write2292=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2293=== RUN TestService_RequireScope_OIDC/reader_may_read2294=== PAUSE TestService_RequireScope_OIDC/reader_may_read2295=== RUN TestService_RequireScope_OIDC/writer_implies_read2296=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2297=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2298=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2299=== CONT TestGCSweepDeliversEachKeyOnce23002026/10/01 07:37:06 OK 20260628120000_add_object_size_and_stats.sql (53.58ms)23012026/10/01 07:37:06 OK 20260905000000_add_claims.sql (57.72ms)23022026/10/01 07:37:06 OK 20260920000000_drop_claims.sql (34.1ms)23032026/10/01 07:37:06 OK 20260923120000_add_pushes.sql (26.26ms)23042026/10/01 07:37:06 goose: successfully migrated database to version: 2026092312000023052026/10/01 07:37:06 OK 1_commit_pending_closure.sql (1.91ms)23062026/10/01 07:37:06 OK 2_object_stats_trigger.sql (329.13µs)23072026/10/01 07:37:06 OK 3_commit_push.sql (192.54µs)23082026/10/01 07:37:06 goose: up to current file version: 32309=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2310=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2311=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2312=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2313=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2314=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2315=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2316=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2317=== CONT TestTombstonedObjectOfferedWithoutWaiting23182026-10-01 07:37:06.767 UTC [57268] ERROR: relation "goose_db_version" does not exist at character 3623192026-10-01 07:37:06.767 UTC [57268] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23202026-10-01 07:37:06.807 UTC [57275] ERROR: relation "goose_db_version" does not exist at character 3623212026-10-01 07:37:06.807 UTC [57275] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23222026/10/01 07:37:07 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"23232026/10/01 07:37:07 WARN mTLS auth: bound subjects configured but subject DN unavailable23242026/10/01 07:37:07 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2325--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (2.82s)2326=== CONT TestFailedS3DeleteKeepsTombstone23272026-10-01 07:37:07.073 UTC [57276] ERROR: relation "goose_db_version" does not exist at character 3623282026-10-01 07:37:07.073 UTC [57276] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23292026/10/01 07:37:07 OK 20241026095416_initial_model.sql (176.97ms)23302026/10/01 07:37:07 OK 20241026095416_initial_model.sql (214.79ms)23312026/10/01 07:37:07 OK 20251210153512_drop_unused_gin_index.sql (10.16ms)23322026/10/01 07:37:07 OK 20251210153512_drop_unused_gin_index.sql (16.81ms)23332026/10/01 07:37:07 OK 20251218171726_add_pins.sql (27.7ms)23342026/10/01 07:37:07 OK 20251218171726_add_pins.sql (22.89ms)23352026/10/01 07:37:07 OK 20260628120000_add_object_size_and_stats.sql (31.56ms)23362026/10/01 07:37:07 OK 20260628120000_add_object_size_and_stats.sql (45.71ms)23372026-10-01 07:37:07.178 UTC [57279] ERROR: relation "goose_db_version" does not exist at character 3623382026-10-01 07:37:07.178 UTC [57279] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23392026/10/01 07:37:07 OK 20260905000000_add_claims.sql (44.45ms)23402026/10/01 07:37:07 OK 20260920000000_drop_claims.sql (11.44ms)23412026-10-01 07:37:07.203 UTC [57280] ERROR: relation "goose_db_version" does not exist at character 3623422026-10-01 07:37:07.203 UTC [57280] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23432026/10/01 07:37:07 OK 20260905000000_add_claims.sql (48.43ms)23442026/10/01 07:37:07 OK 20260923120000_add_pushes.sql (9.5ms)23452026/10/01 07:37:07 goose: successfully migrated database to version: 2026092312000023462026/10/01 07:37:07 OK 1_commit_pending_closure.sql (2.91ms)23472026/10/01 07:37:07 OK 2_object_stats_trigger.sql (230.88µs)23482026/10/01 07:37:07 OK 3_commit_push.sql (156.71µs)23492026/10/01 07:37:07 goose: up to current file version: 323502026/10/01 07:37:07 OK 20260920000000_drop_claims.sql (50.02ms)23512026/10/01 07:37:07 OK 20241026095416_initial_model.sql (147.71ms)23522026/10/01 07:37:07 OK 20251210153512_drop_unused_gin_index.sql (19.73ms)23532026/10/01 07:37:07 OK 20260923120000_add_pushes.sql (42.5ms)23542026/10/01 07:37:07 goose: successfully migrated database to version: 2026092312000023552026/10/01 07:37:07 OK 1_commit_pending_closure.sql (8.71ms)23562026/10/01 07:37:07 OK 20251218171726_add_pins.sql (12.85ms)23572026/10/01 07:37:07 OK 2_object_stats_trigger.sql (650.17µs)23582026/10/01 07:37:07 OK 3_commit_push.sql (4.19ms)23592026/10/01 07:37:07 goose: up to current file version: 323602026/10/01 07:37:07 OK 20260628120000_add_object_size_and_stats.sql (64.97ms)23612026/10/01 07:37:07 OK 20241026095416_initial_model.sql (166.69ms)23622026/10/01 07:37:07 OK 20260905000000_add_claims.sql (29.79ms)23632026/10/01 07:37:07 OK 20251210153512_drop_unused_gin_index.sql (18.15ms)23642026/10/01 07:37:07 OK 20260920000000_drop_claims.sql (54.08ms)23652026-10-01 07:37:07.461 UTC [57282] ERROR: relation "goose_db_version" does not exist at character 3623662026-10-01 07:37:07.461 UTC [57282] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23672026/10/01 07:37:07 OK 20251218171726_add_pins.sql (36.6ms)23682026/10/01 07:37:07 OK 20241026095416_initial_model.sql (165.99ms)23692026/10/01 07:37:07 OK 20251210153512_drop_unused_gin_index.sql (15.71ms)23702026/10/01 07:37:07 OK 20260923120000_add_pushes.sql (46.65ms)23712026/10/01 07:37:07 goose: successfully migrated database to version: 2026092312000023722026/10/01 07:37:07 OK 20251218171726_add_pins.sql (23.71ms)23732026/10/01 07:37:07 OK 20260628120000_add_object_size_and_stats.sql (50.19ms)23742026/10/01 07:37:07 OK 1_commit_pending_closure.sql (4.64ms)23752026/10/01 07:37:07 OK 2_object_stats_trigger.sql (3.27ms)23762026/10/01 07:37:07 OK 3_commit_push.sql (523.04µs)23772026/10/01 07:37:07 goose: up to current file version: 323782026/10/01 07:37:07 OK 20260628120000_add_object_size_and_stats.sql (50.59ms)23792026/10/01 07:37:07 OK 20260905000000_add_claims.sql (65.65ms)23802026/10/01 07:37:07 OK 20260905000000_add_claims.sql (30.63ms)23812026/10/01 07:37:07 OK 20260920000000_drop_claims.sql (62.1ms)23822026/10/01 07:37:07 OK 20260923120000_add_pushes.sql (20.69ms)23832026/10/01 07:37:07 goose: successfully migrated database to version: 2026092312000023842026/10/01 07:37:07 OK 20260920000000_drop_claims.sql (69.1ms)23852026/10/01 07:37:07 OK 1_commit_pending_closure.sql (4.01ms)23862026/10/01 07:37:07 OK 2_object_stats_trigger.sql (994.63µs)23872026/10/01 07:37:07 OK 3_commit_push.sql (333.21µs)23882026/10/01 07:37:07 goose: up to current file version: 323892026/10/01 07:37:07 OK 20260923120000_add_pushes.sql (31.17ms)23902026/10/01 07:37:07 goose: successfully migrated database to version: 2026092312000023912026/10/01 07:37:07 OK 1_commit_pending_closure.sql (1.53ms)23922026/10/01 07:37:07 OK 2_object_stats_trigger.sql (223.58µs)23932026/10/01 07:37:07 OK 3_commit_push.sql (178.71µs)23942026/10/01 07:37:07 goose: up to current file version: 323952026/10/01 07:37:07 INFO Aborted multipart uploads count=023962026/10/01 07:37:07 WARN Force mode enabled - objects will be deleted immediately without grace period23972026/10/01 07:37:07 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=023982026/10/01 07:37:07 INFO Vacuumed table table=pending_closures23992026/10/01 07:37:07 INFO Vacuumed table table=pending_objects24002026/10/01 07:37:07 INFO Vacuumed table table=multipart_uploads24012026/10/01 07:37:07 INFO Vacuumed table table=closures24022026/10/01 07:37:07 INFO Vacuumed table table=objects24032026/10/01 07:37:07 INFO Aborted multipart uploads count=024042026/10/01 07:37:07 WARN Force mode enabled - objects will be deleted immediately without grace period24052026/10/01 07:37:07 OK 20241026095416_initial_model.sql (225.56ms)24062026/10/01 07:37:07 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=024072026/10/01 07:37:07 INFO Vacuumed table table=pending_closures24082026/10/01 07:37:07 INFO Vacuumed table table=pending_objects24092026/10/01 07:37:07 INFO Vacuumed table table=multipart_uploads24102026/10/01 07:37:07 INFO Vacuumed table table=closures24112026/10/01 07:37:07 OK 20251210153512_drop_unused_gin_index.sql (10.93ms)24122026/10/01 07:37:07 INFO Vacuumed table table=objects2413--- PASS: TestSweepSkipsRowsLockedByPush (3.08s)2414=== CONT TestGCSweepSkipsPendingObjects24152026/10/01 07:37:07 OK 20251218171726_add_pins.sql (35.28ms)24162026/10/01 07:37:07 OK 20260628120000_add_object_size_and_stats.sql (39.72ms)24172026/10/01 07:37:07 WARN readiness check failed error="closed pool"2418--- PASS: TestService_readinessHandler (3.23s)24192026/10/01 07:37:07 OK 20260905000000_add_claims.sql (62.97ms)2420=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection24212026/10/01 07:37:07 OK 20260920000000_drop_claims.sql (18.85ms)24222026/10/01 07:37:07 OK 20260923120000_add_pushes.sql (22.75ms)24232026/10/01 07:37:07 goose: successfully migrated database to version: 2026092312000024242026/10/01 07:37:07 OK 1_commit_pending_closure.sql (964.63µs)24252026/10/01 07:37:07 OK 2_object_stats_trigger.sql (245.04µs)24262026/10/01 07:37:07 OK 3_commit_push.sql (191.79µs)24272026/10/01 07:37:07 goose: up to current file version: 32428--- PASS: TestService_healthCheckHandler (3.48s)2429=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts24302026/10/01 07:37:08 INFO Received request for more parts method=POST path=/2431=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info24322026/10/01 07:37:08 INFO Received uploads request method=POST path=/2433=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart24342026/10/01 07:37:08 INFO Received complete multipart upload request method=POST path=/2435=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure24362026/10/01 07:37:08 INFO Received uploads request method=POST path=/24372026-10-01 07:37:08.593 UTC [57310] ERROR: relation "goose_db_version" does not exist at character 3624382026-10-01 07:37:08.593 UTC [57310] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2439=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key2440--- PASS: TestUploadHandlersRejectOversizedBody (0.05s)2441 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)2442 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)2443 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.32s)24442026/10/01 07:37:08 INFO Received complete multipart upload request method=POST path=/2445=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key24462026/10/01 07:37:08 INFO Received request for more parts method=POST path=/2447=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal24482026/10/01 07:37:08 INFO Received uploads request method=POST path=/2449--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2450 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2451 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2452 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2453 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2454=== CONT TestIsValidUploadKey/narinfo2455=== CONT TestIsValidUploadKey/realisation_plus_in_output2456=== CONT TestIsValidUploadKey/unknown_type2457=== CONT TestIsValidUploadKey/empty_key2458=== CONT TestIsValidUploadKey/absolute2459=== CONT TestIsValidUploadKey/traversal_nar2460=== CONT TestIsValidUploadKey/traversal2461=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2462=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2463=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2464=== CONT TestIsValidUploadKey/index.html2465=== CONT TestIsValidUploadKey/nix-cache-info2466=== CONT TestIsValidUploadKey/build_log_home-manager_file2467=== CONT TestIsValidUploadKey/realisation2468=== CONT TestIsValidUploadKey/build_log_equals2469=== CONT TestIsValidUploadKey/build_log_question_mark2470=== CONT TestIsValidUploadKey/build_log_plus_in_name2471=== CONT TestIsValidUploadKey/nar_plain2472=== CONT TestIsValidUploadKey/build_log2473=== CONT TestIsValidUploadKey/listing2474=== CONT TestIsValidUploadKey/nar_xz2475=== CONT TestIsValidUploadKey/nar_zst2476--- PASS: TestIsValidUploadKey (0.00s)2477 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2478 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2479 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2480 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2481 --- PASS: TestIsValidUploadKey/absolute (0.00s)2482 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2483 --- PASS: TestIsValidUploadKey/traversal (0.00s)2484 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2485 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2486 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2487 --- PASS: TestIsValidUploadKey/index.html (0.00s)2488 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2489 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2490 --- PASS: TestIsValidUploadKey/realisation (0.00s)2491 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2492 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2493 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2494 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2495 --- PASS: TestIsValidUploadKey/build_log (0.00s)2496 --- PASS: TestIsValidUploadKey/listing (0.00s)2497 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2498 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2499=== CONT TestProxyWriteTimeout/narinfo2500=== CONT TestProxyWriteTimeout/10_GiB_nar2501=== CONT TestProxyWriteTimeout/unknown_size2502=== CONT TestProxyWriteTimeout/1_GiB_nar2503--- PASS: TestProxyWriteTimeout (0.00s)2504 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2505 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2506 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2507 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2508=== CONT TestResolveDBConnectionString/flag_wins2509=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2510=== CONT TestResolveDBConnectionString/nothing_configured2511=== CONT TestResolveDBConnectionString/missing_file_is_an_error2512=== CONT TestResolveDBConnectionString/file_when_flag_empty2513=== CONT TestPush_RejectsBadRequests/no_roots25142026/10/01 07:37:08 INFO Received push request method=POST path=/api/pushes2515=== CONT TestPush_RejectsBadRequests/root_not_in_objects25162026/10/01 07:37:08 INFO Received push request method=POST path=/api/pushes2517=== CONT TestPush_RejectsBadRequests/bad_root25182026/10/01 07:37:08 INFO Received push request method=POST path=/api/pushes2519=== CONT TestPush_RejectsBadRequests/no_objects25202026/10/01 07:37:08 INFO Received push request method=POST path=/api/pushes2521=== CONT TestIsValidCachePath/narinfo2522=== CONT TestIsValidCachePath/index.html2523=== CONT TestIsValidCachePath/nix-cache-info2524=== CONT TestIsValidCachePath/realisation2525=== CONT TestIsValidCachePath/log2526=== CONT TestIsValidCachePath/ls2527=== CONT TestIsValidCachePath/nar_uncompressed2528=== CONT TestIsValidCachePath/nar_bz22529=== CONT TestIsValidCachePath/nar_xz2530=== CONT TestIsValidCachePath/nar_zst2531=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2532=== CONT TestIsValidCachePath/empty2533=== CONT TestIsValidCachePath/traversal_parent2534=== CONT TestIsValidCachePath/random_path2535=== CONT TestIsValidCachePath/invalid_char_u2536=== CONT TestIsValidCachePath/invalid_char_e2537=== CONT TestIsValidCachePath/traversal_in_middle2538=== CONT TestIsValidCachePath/wrong_extension2539=== CONT TestIsValidCachePath/short_hash2540=== CONT TestIsValidCachePath/leading_slash2541=== CONT TestParseSingleRange/none2542=== CONT TestParseSingleRange/open-ended2543--- PASS: TestPush_RejectsBadRequests (2.28s)2544 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2545 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2546 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2547 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2548=== CONT TestParseSingleRange/closed2549=== CONT TestParseSingleRange/malformed_end_before_start2550=== CONT TestParseSingleRange/malformed_both_empty2551=== CONT TestParseSingleRange/malformed_no_dash2552=== CONT TestParseSingleRange/multi-range_ignored2553=== CONT TestParseSingleRange/unknown_unit2554=== CONT TestParseSingleRange/start_past_EOF2555=== CONT TestParseSingleRange/end_clamped_to_size2556=== CONT TestParseSingleRange/single_byte2557=== CONT TestParseSingleRange/suffix_exceeds_size2558--- PASS: TestIsValidCachePath (0.00s)2559 --- PASS: TestIsValidCachePath/narinfo (0.00s)2560 --- PASS: TestIsValidCachePath/index.html (0.00s)2561 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2562 --- PASS: TestIsValidCachePath/realisation (0.00s)2563 --- PASS: TestIsValidCachePath/log (0.00s)2564 --- PASS: TestIsValidCachePath/ls (0.00s)2565 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2566 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2567 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2568 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2569 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2570 --- PASS: TestIsValidCachePath/empty (0.00s)2571 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2572 --- PASS: TestIsValidCachePath/random_path (0.00s)2573 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2574 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2575 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2576 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2577 --- PASS: TestIsValidCachePath/short_hash (0.00s)2578 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2579=== CONT TestParseSingleRange/suffix2580=== CONT TestParseSingleRange/start_far_past_EOF2581=== CONT TestClientErrorHandling/InvalidStorePath2582--- PASS: TestParseSingleRange (0.00s)2583 --- PASS: TestParseSingleRange/none (0.00s)2584 --- PASS: TestParseSingleRange/open-ended (0.00s)2585 --- PASS: TestParseSingleRange/closed (0.00s)2586 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2587 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2588 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2589 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2590 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2591 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2592 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2593 --- PASS: TestParseSingleRange/single_byte (0.00s)2594 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2595 --- PASS: TestParseSingleRange/suffix (0.00s)2596 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2597--- PASS: TestResolveDBConnectionString (0.03s)2598 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2599 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2600 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2601 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2602 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2603--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (3.59s)2604=== CONT TestClientErrorHandling/ServerNotAvailable26052026/10/01 07:37:08 OK 20241026095416_initial_model.sql (175.37ms)26062026/10/01 07:37:08 OK 20251210153512_drop_unused_gin_index.sql (16.98ms)26072026/10/01 07:37:08 OK 20251218171726_add_pins.sql (50.57ms)26082026/10/01 07:37:08 OK 20260628120000_add_object_size_and_stats.sql (65.28ms)26092026/10/01 07:37:09 OK 20260905000000_add_claims.sql (110.82ms)26102026/10/01 07:37:09 OK 20260920000000_drop_claims.sql (89.64ms)26112026-10-01 07:37:09.207 UTC [57316] ERROR: relation "goose_db_version" does not exist at character 3626122026-10-01 07:37:09.207 UTC [57316] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26132026/10/01 07:37:09 OK 20260923120000_add_pushes.sql (29.07ms)26142026/10/01 07:37:09 goose: successfully migrated database to version: 2026092312000026152026/10/01 07:37:09 OK 1_commit_pending_closure.sql (909.46µs)26162026/10/01 07:37:09 OK 2_object_stats_trigger.sql (233.29µs)26172026/10/01 07:37:09 OK 3_commit_push.sql (197.29µs)26182026/10/01 07:37:09 goose: up to current file version: 32619=== NAME TestOrphanedObjectsGCStressTest2620 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains26212026/10/01 07:37:09 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/present2622--- PASS: TestGetExistingObjectsLocksRows (4.03s)2623=== CONT TestClientErrorHandling/InvalidAuthToken26242026/10/01 07:37:09 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=216.213089ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2625=== NAME TestOrphanedObjectsGCStressTest2626 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion26272026/10/01 07:37:09 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=367.760853ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present26282026/10/01 07:37:09 OK 20241026095416_initial_model.sql (258.39ms)26292026/10/01 07:37:09 OK 20251210153512_drop_unused_gin_index.sql (30.34ms)2630--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.16s)2631=== CONT TestCacheConfigHandler/full_config,_no_issuer2632=== CONT TestCacheConfigHandler/no_signing_keys2633=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2634=== CONT TestCacheConfigHandler/no_cache_url_configured2635--- PASS: TestCacheConfigHandler (0.00s)2636 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2637 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2638 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2639 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2640=== CONT TestServerTLSConfig/no_client_CA2641=== CONT TestServerTLSConfig/not_a_PEM_file26422026-10-01 07:37:09.637 UTC [57322] ERROR: relation "goose_db_version" does not exist at character 3626432026-10-01 07:37:09.637 UTC [57322] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26442026/10/01 07:37:09 OK 20251218171726_add_pins.sql (18.44ms)2645=== CONT TestServerTLSConfig/missing_CA_file2646--- PASS: TestServerTLSConfig (0.00s)2647 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2648 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.04s)2649 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2650=== CONT TestService_RequireScope_OIDC/builder_may_write2651=== CONT TestService_RequireScope_OIDC/static_token_may_admin2652=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2653=== CONT TestService_RequireScope_OIDC/writer_implies_read2654=== CONT TestService_RequireScope_OIDC/reader_may_read2655=== CONT TestService_RequireScope_OIDC/static_token_may_write2656=== CONT TestService_RequireScope_OIDC/ops_may_not_write2657=== CONT TestService_RequireScope_OIDC/reader_may_not_write2658=== CONT TestService_RequireScope_OIDC/ops_may_admin2659=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2660=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2661=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected26622026/10/01 07:37:09 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]2663=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2664=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected26652026/10/01 07:37:09 WARN Authentication failed token_preview=eyJhbGciOi...uagOBGInqQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2666--- PASS: TestService_AuthMiddleware_OIDC (2.74s)2667 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2668 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2669 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2670 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2671--- PASS: TestService_RequireScope_OIDC (2.45s)2672 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2673 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2674 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2675 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2676 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2677 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2678 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2679 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2680 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2681 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)26822026/10/01 07:37:09 OK 20260628120000_add_object_size_and_stats.sql (78.46ms)26832026/10/01 07:37:09 OK 20260905000000_add_claims.sql (134.27ms)26842026/10/01 07:37:09 OK 20260920000000_drop_claims.sql (50.21ms)26852026/10/01 07:37:09 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=838.052598ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present26862026/10/01 07:37:09 OK 20260923120000_add_pushes.sql (23.91ms)26872026/10/01 07:37:09 goose: successfully migrated database to version: 2026092312000026882026/10/01 07:37:09 OK 1_commit_pending_closure.sql (1.81ms)26892026/10/01 07:37:09 OK 2_object_stats_trigger.sql (757.29µs)26902026/10/01 07:37:09 OK 3_commit_push.sql (425.42µs)26912026/10/01 07:37:09 goose: up to current file version: 326922026/10/01 07:37:10 OK 20241026095416_initial_model.sql (256.25ms)26932026/10/01 07:37:10 OK 20251210153512_drop_unused_gin_index.sql (16.48ms)26942026/10/01 07:37:10 OK 20251218171726_add_pins.sql (49.77ms)26952026/10/01 07:37:10 OK 20260628120000_add_object_size_and_stats.sql (74.08ms)26962026/10/01 07:37:10 INFO Aborted multipart uploads count=026972026/10/01 07:37:10 WARN Force mode enabled - objects will be deleted immediately without grace period26982026/10/01 07:37:10 OK 20260905000000_add_claims.sql (107.41ms)26992026/10/01 07:37:10 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=027002026/10/01 07:37:10 INFO Vacuumed table table=pending_closures27012026/10/01 07:37:10 INFO Vacuumed table table=pending_objects27022026/10/01 07:37:10 INFO Vacuumed table table=multipart_uploads27032026/10/01 07:37:10 INFO Vacuumed table table=closures27042026/10/01 07:37:10 OK 20260920000000_drop_claims.sql (106.31ms)27052026/10/01 07:37:10 OK 20260923120000_add_pushes.sql (15.79ms)27062026/10/01 07:37:10 goose: successfully migrated database to version: 2026092312000027072026/10/01 07:37:10 INFO Vacuumed table table=objects2708--- PASS: TestGCSweepDeliversEachKeyOnce (4.01s)27092026/10/01 07:37:10 OK 1_commit_pending_closure.sql (1.93ms)27102026/10/01 07:37:10 OK 2_object_stats_trigger.sql (283.33µs)27112026/10/01 07:37:10 OK 3_commit_push.sql (197µs)27122026/10/01 07:37:10 goose: up to current file version: 327132026/10/01 07:37:10 INFO Received uploads request method=POST path=/api/pending_closures2714--- PASS: TestTombstonedObjectOfferedWithoutWaiting (3.88s)27152026/10/01 07:37:10 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.747268522s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27162026/10/01 07:37:10 INFO Received uploads request method=POST path=/api/pending_closures27172026-10-01 07:37:10.886 UTC [57324] ERROR: relation "goose_db_version" does not exist at character 3627182026-10-01 07:37:10.886 UTC [57324] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27192026-10-01 07:37:10.933 UTC [57325] ERROR: relation "goose_db_version" does not exist at character 3627202026-10-01 07:37:10.933 UTC [57325] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27212026/10/01 07:37:11 INFO Aborted multipart uploads count=027222026/10/01 07:37:11 WARN Force mode enabled - objects will be deleted immediately without grace period27232026/10/01 07:37:11 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."27242026/10/01 07:37:11 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."2725--- PASS: TestFailedS3DeleteKeepsTombstone (4.04s)27262026/10/01 07:37:11 OK 20241026095416_initial_model.sql (216.97ms)27272026/10/01 07:37:11 OK 20241026095416_initial_model.sql (106.99ms)27282026/10/01 07:37:11 OK 20251210153512_drop_unused_gin_index.sql (34.17ms)27292026/10/01 07:37:11 OK 20251210153512_drop_unused_gin_index.sql (30.64ms)27302026/10/01 07:37:11 OK 20251218171726_add_pins.sql (10.54ms)27312026/10/01 07:37:11 OK 20251218171726_add_pins.sql (12.47ms)27322026/10/01 07:37:11 OK 20260628120000_add_object_size_and_stats.sql (23.22ms)27332026-10-01 07:37:11.221 UTC [57327] ERROR: relation "goose_db_version" does not exist at character 3627342026-10-01 07:37:11.221 UTC [57327] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27352026/10/01 07:37:11 OK 20260628120000_add_object_size_and_stats.sql (29.03ms)27362026/10/01 07:37:11 OK 20260905000000_add_claims.sql (8.44ms)27372026/10/01 07:37:11 OK 20260905000000_add_claims.sql (11.34ms)27382026/10/01 07:37:11 OK 20260920000000_drop_claims.sql (62.16ms)27392026/10/01 07:37:11 OK 20260920000000_drop_claims.sql (64.42ms)27402026/10/01 07:37:11 OK 20260923120000_add_pushes.sql (10.24ms)27412026/10/01 07:37:11 goose: successfully migrated database to version: 2026092312000027422026/10/01 07:37:11 OK 20260923120000_add_pushes.sql (11.03ms)27432026/10/01 07:37:11 goose: successfully migrated database to version: 2026092312000027442026/10/01 07:37:11 OK 1_commit_pending_closure.sql (2.39ms)27452026/10/01 07:37:11 OK 1_commit_pending_closure.sql (2.5ms)27462026/10/01 07:37:11 OK 2_object_stats_trigger.sql (2.2ms)27472026/10/01 07:37:11 OK 2_object_stats_trigger.sql (2.01ms)27482026/10/01 07:37:11 OK 3_commit_push.sql (286.5µs)27492026/10/01 07:37:11 goose: up to current file version: 327502026/10/01 07:37:11 OK 3_commit_push.sql (395.83µs)27512026/10/01 07:37:11 goose: up to current file version: 327522026/10/01 07:37:11 OK 20241026095416_initial_model.sql (105.39ms)27532026/10/01 07:37:11 OK 20251210153512_drop_unused_gin_index.sql (10.63ms)27542026/10/01 07:37:11 OK 20251218171726_add_pins.sql (40.41ms)27552026/10/01 07:37:11 OK 20260628120000_add_object_size_and_stats.sql (40.47ms)27562026/10/01 07:37:11 OK 20260905000000_add_claims.sql (56.26ms)27572026/10/01 07:37:11 OK 20260920000000_drop_claims.sql (24.78ms)27582026/10/01 07:37:11 OK 20260923120000_add_pushes.sql (1.97ms)27592026/10/01 07:37:11 goose: successfully migrated database to version: 2026092312000027602026/10/01 07:37:11 OK 1_commit_pending_closure.sql (2.03ms)27612026/10/01 07:37:11 OK 2_object_stats_trigger.sql (274.04µs)27622026/10/01 07:37:11 OK 3_commit_push.sql (343.71µs)27632026/10/01 07:37:11 goose: up to current file version: 327642026/10/01 07:37:11 INFO Received uploads request method=POST path=/api/pending_closures27652026-10-01 07:37:11.717 UTC [57328] ERROR: relation "goose_db_version" does not exist at character 3627662026-10-01 07:37:11.717 UTC [57328] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2767--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (3.89s)27682026/10/01 07:37:11 OK 20241026095416_initial_model.sql (77.56ms)27692026/10/01 07:37:11 OK 20251210153512_drop_unused_gin_index.sql (13.42ms)27702026/10/01 07:37:11 OK 20251218171726_add_pins.sql (30ms)27712026/10/01 07:37:11 OK 20260628120000_add_object_size_and_stats.sql (57.17ms)27722026/10/01 07:37:12 INFO Received uploads request method=POST path=/api/pending_closures27732026/10/01 07:37:12 OK 20260905000000_add_claims.sql (105.32ms)27742026/10/01 07:37:12 OK 20260920000000_drop_claims.sql (17.79ms)27752026/10/01 07:37:12 OK 20260923120000_add_pushes.sql (21.2ms)27762026/10/01 07:37:12 goose: successfully migrated database to version: 2026092312000027772026/10/01 07:37:12 OK 1_commit_pending_closure.sql (1.95ms)27782026/10/01 07:37:12 OK 2_object_stats_trigger.sql (624.5µs)27792026/10/01 07:37:12 OK 3_commit_push.sql (230.58µs)27802026/10/01 07:37:12 goose: up to current file version: 327812026/10/01 07:37:12 INFO Aborted multipart uploads count=027822026/10/01 07:37:12 WARN Force mode enabled - objects will be deleted immediately without grace period27832026/10/01 07:37:12 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=027842026/10/01 07:37:12 INFO Vacuumed table table=pending_closures27852026/10/01 07:37:12 INFO Vacuumed table table=pending_objects27862026/10/01 07:37:12 INFO Vacuumed table table=multipart_uploads27872026/10/01 07:37:12 INFO Vacuumed table table=closures27882026/10/01 07:37:12 INFO Vacuumed table table=objects2789--- PASS: TestGCSweepSkipsPendingObjects (4.39s)27902026/10/01 07:37:12 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-config27912026/10/01 07:37:12 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=197.085424ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27922026/10/01 07:37:12 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=390.421384ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27932026/10/01 07:37:12 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"27942026/10/01 07:37:13 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2795=== NAME TestOrphanedObjectsGCStressTest2796 orphaned_objects_gc_test.go:509: Stress test completed successfully:2797 orphaned_objects_gc_test.go:510: - Active objects preserved: 202798 orphaned_objects_gc_test.go:511: - Objects deleted: 2102799 orphaned_objects_gc_test.go:512: - Total GC'd: 2102800--- PASS: TestOrphanedObjectsGCStressTest (13.18s)28012026/10/01 07:37:13 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=860.701921ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28022026/10/01 07:37:14 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.530620319s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28032026/10/01 07:37:15 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"28042026/10/01 07:37:15 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-config28052026/10/01 07:37:15 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=217.315912ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28062026/10/01 07:37:16 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=398.652233ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28072026/10/01 07:37:16 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=805.605977ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28082026/10/01 07:37:17 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.59333342s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28092026/10/01 07:37:18 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_closures28102026/10/01 07:37:18 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=198.036252ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28112026/10/01 07:37:19 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=436.92966ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28122026/10/01 07:37:19 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=855.245858ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28132026/10/01 07:37:20 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.518116152s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2814--- PASS: TestClientErrorHandling (0.00s)2815 --- PASS: TestClientErrorHandling/InvalidStorePath (3.87s)2816 --- PASS: TestClientErrorHandling/InvalidAuthToken (3.82s)2817 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.23s)2818PASS28192026-10-01 07:37:23.838 UTC [55546] LOG: received smart shutdown request28202026-10-01 07:37:23.840 UTC [55546] LOG: background worker "logical replication launcher" (PID 55556) exited with exit code 128212026-10-01 07:37:24.057 UTC [55551] LOG: shutting down28222026-10-01 07:37:24.063 UTC [55551] LOG: checkpoint starting: shutdown immediate28232026/10/01 07:37:31 ERROR failed to kill rustfs error="no such process"28242026/10/01 07:37:33 INFO killed rustfs28252026/10/01 07:37:33 ERROR failed to wait for rustfs error="signal: killed"28262026-10-01 07:37:34.454 UTC [55551] FATAL: could not open directory "pg_wal": No such file or directory2827Running OIDC tests...2828=== RUN TestAudienceForIssuer2829=== PAUSE TestAudienceForIssuer2830=== RUN TestGlobMatch2831=== PAUSE TestGlobMatch2832=== RUN TestValidateToken_ValidToken2833=== PAUSE TestValidateToken_ValidToken2834=== RUN TestValidateToken_WrongAudience2835=== PAUSE TestValidateToken_WrongAudience2836=== RUN TestValidateToken_Expired2837=== PAUSE TestValidateToken_Expired2838=== RUN TestValidateToken_BoundClaimsMismatch2839=== PAUSE TestValidateToken_BoundClaimsMismatch2840=== RUN TestValidateToken_BoundSubjectMismatch2841=== PAUSE TestValidateToken_BoundSubjectMismatch2842=== RUN TestValidateToken_MultipleProviders2843=== PAUSE TestValidateToken_MultipleProviders2844=== RUN TestValidateToken_NoMatchingProvider2845=== PAUSE TestValidateToken_NoMatchingProvider2846=== RUN TestValidateToken_KubernetesServiceAccount2847=== PAUSE TestValidateToken_KubernetesServiceAccount2848=== RUN TestNewValidator_KubernetesRequiresCA2849=== PAUSE TestNewValidator_KubernetesRequiresCA2850=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2851=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2852=== RUN TestPins_ReservedForMatchingRule2853=== PAUSE TestPins_ReservedForMatchingRule2854=== RUN TestPins_TopLevelShorthand2855=== PAUSE TestPins_TopLevelShorthand2856=== RUN TestPins_ConfigValidation2857=== PAUSE TestPins_ConfigValidation2858=== RUN TestScopes_LegacyProviderDefaultsToWrite2859=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2860=== RUN TestScopes_Rules2861=== PAUSE TestScopes_Rules2862=== RUN TestScopes_ConfigValidation2863=== PAUSE TestScopes_ConfigValidation2864=== CONT TestAudienceForIssuer2865--- PASS: TestAudienceForIssuer (0.00s)2866=== CONT TestScopes_ConfigValidation2867=== CONT TestValidateToken_KubernetesServiceAccount2868=== CONT TestPins_TopLevelShorthand2869=== CONT TestValidateToken_BoundClaimsMismatch2870=== CONT TestValidateToken_WrongAudience2871--- PASS: TestScopes_ConfigValidation (0.00s)2872=== CONT TestValidateToken_ValidToken2873=== CONT TestValidateToken_MultipleProviders2874=== CONT TestGlobMatch2875=== RUN TestGlobMatch/foo_foo2876=== PAUSE TestGlobMatch/foo_foo2877=== RUN TestGlobMatch/foo_bar2878=== PAUSE TestGlobMatch/foo_bar2879=== RUN TestGlobMatch/*_2880=== PAUSE TestGlobMatch/*_2881=== RUN TestGlobMatch/*_anything2882=== PAUSE TestGlobMatch/*_anything2883=== RUN TestGlobMatch/foo*_foo2884=== PAUSE TestGlobMatch/foo*_foo2885=== RUN TestGlobMatch/foo*_foobar2886=== PAUSE TestGlobMatch/foo*_foobar2887=== RUN TestGlobMatch/foo*_bar2888=== PAUSE TestGlobMatch/foo*_bar2889=== RUN TestGlobMatch/*bar_bar2890=== PAUSE TestGlobMatch/*bar_bar2891=== RUN TestGlobMatch/*bar_foobar2892=== PAUSE TestGlobMatch/*bar_foobar2893=== RUN TestGlobMatch/*bar_foo2894=== PAUSE TestGlobMatch/*bar_foo2895=== RUN TestGlobMatch/foo*bar_foobar2896=== PAUSE TestGlobMatch/foo*bar_foobar2897=== RUN TestGlobMatch/foo*bar_foo123bar2898=== PAUSE TestGlobMatch/foo*bar_foo123bar2899=== RUN TestGlobMatch/foo*bar_foobarbaz2900=== PAUSE TestGlobMatch/foo*bar_foobarbaz2901=== RUN TestGlobMatch/*/*_foo/bar2902=== PAUSE TestGlobMatch/*/*_foo/bar2903=== RUN TestGlobMatch/*/*_foo2904=== PAUSE TestGlobMatch/*/*_foo2905=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2906=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2907=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02908=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02909=== RUN TestGlobMatch/refs/*/main_refs/heads/main2910=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2911=== RUN TestGlobMatch/fo?_foo2912=== PAUSE TestGlobMatch/fo?_foo2913=== RUN TestGlobMatch/fo?_fo2914=== PAUSE TestGlobMatch/fo?_fo2915=== RUN TestGlobMatch/fo?_fooo2916=== PAUSE TestGlobMatch/fo?_fooo2917=== RUN TestGlobMatch/?oo_foo2918=== PAUSE TestGlobMatch/?oo_foo2919=== RUN TestGlobMatch/?oo_boo2920=== PAUSE TestGlobMatch/?oo_boo2921=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2922=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2923=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2924=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2925=== CONT TestValidateToken_Expired2926=== CONT TestPins_ConfigValidation2927=== CONT TestScopes_LegacyProviderDefaultsToWrite2928=== CONT TestScopes_Rules2929--- PASS: TestPins_ConfigValidation (0.00s)2930=== CONT TestValidateToken_KubernetesIssuerFromOwnToken29312026/10/01 07:37:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56914/oidc2932--- PASS: TestPins_TopLevelShorthand (0.18s)2933=== CONT TestPins_ReservedForMatchingRule29342026/10/01 07:37:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56917/oidc29352026/10/01 07:37:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56916/oidc2936--- PASS: TestScopes_Rules (0.35s)2937=== CONT TestValidateToken_BoundSubjectMismatch29382026/10/01 07:37:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56920/oidc2939--- PASS: TestValidateToken_Expired (0.49s)2940=== CONT TestNewValidator_KubernetesRequiresCA2941--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.49s)2942=== CONT TestValidateToken_NoMatchingProvider29432026/10/01 07:37:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56922/oidc2944--- PASS: TestPins_ReservedForMatchingRule (0.32s)2945=== CONT TestGlobMatch/foo_foo2946=== CONT TestGlobMatch/*/*_foo/bar2947=== CONT TestGlobMatch/fo?_fo2948=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2949=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2950=== CONT TestGlobMatch/?oo_boo2951=== CONT TestGlobMatch/?oo_foo2952=== CONT TestGlobMatch/fo?_fooo2953=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02954=== CONT TestGlobMatch/fo?_foo2955=== CONT TestGlobMatch/refs/*/main_refs/heads/main2956=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2957=== CONT TestGlobMatch/*/*_foo2958=== CONT TestGlobMatch/*bar_bar2959=== CONT TestGlobMatch/foo*bar_foobarbaz2960=== CONT TestGlobMatch/foo*bar_foo123bar2961=== CONT TestGlobMatch/foo*bar_foobar2962=== CONT TestGlobMatch/*bar_foo2963=== CONT TestGlobMatch/*bar_foobar2964=== CONT TestGlobMatch/foo*_foo2965=== CONT TestGlobMatch/foo*_bar2966=== CONT TestGlobMatch/foo*_foobar2967=== CONT TestGlobMatch/*_2968=== CONT TestGlobMatch/*_anything2969=== CONT TestGlobMatch/foo_bar2970--- PASS: TestGlobMatch (0.00s)2971 --- PASS: TestGlobMatch/foo_foo (0.00s)2972 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2973 --- PASS: TestGlobMatch/fo?_fo (0.00s)2974 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2975 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2976 --- PASS: TestGlobMatch/?oo_boo (0.00s)2977 --- PASS: TestGlobMatch/?oo_foo (0.00s)2978 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2979 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2980 --- PASS: TestGlobMatch/fo?_foo (0.00s)2981 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2982 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2983 --- PASS: TestGlobMatch/*/*_foo (0.00s)2984 --- PASS: TestGlobMatch/*bar_bar (0.00s)2985 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2986 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2987 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2988 --- PASS: TestGlobMatch/*bar_foo (0.00s)2989 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2990 --- PASS: TestGlobMatch/foo*_foo (0.00s)2991 --- PASS: TestGlobMatch/foo*_bar (0.00s)2992 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2993 --- PASS: TestGlobMatch/*_ (0.00s)2994 --- PASS: TestGlobMatch/*_anything (0.00s)2995 --- PASS: TestGlobMatch/foo_bar (0.00s)29962026/10/01 07:37:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56924/oidc29972026/10/01 07:37:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56928/oidc2998--- PASS: TestValidateToken_ValidToken (0.58s)2999--- PASS: TestValidateToken_BoundSubjectMismatch (0.23s)30002026/10/01 07:37:50 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56930/oidc30012026/10/01 07:37:50 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12330022026/10/01 07:37:50 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56932/oidc3003--- PASS: TestValidateToken_WrongAudience (0.65s)3004--- PASS: TestValidateToken_BoundClaimsMismatch (0.67s)3005--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.66s)30062026/10/01 07:37:50 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:569363007--- PASS: TestValidateToken_KubernetesServiceAccount (0.77s)30082026/10/01 07:37:50 http: TLS handshake error from 127.0.0.1:56939: remote error: tls: bad certificate3009--- PASS: TestNewValidator_KubernetesRequiresCA (0.28s)30102026/10/01 07:37:50 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56913/oidc30112026/10/01 07:37:50 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:56940/oidc3012--- PASS: TestValidateToken_MultipleProviders (0.80s)30132026/10/01 07:37:50 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56945/oidc3014--- PASS: TestValidateToken_NoMatchingProvider (1.03s)3015PASS3016Running hook tests...3017=== RUN TestSendPathsEmpty3018=== PAUSE TestSendPathsEmpty3019=== RUN TestQueueEnqueueAndFetch3020=== PAUSE TestQueueEnqueueAndFetch3021=== RUN TestQueueDeduplication3022=== PAUSE TestQueueDeduplication3023=== RUN TestQueueRemove3024=== PAUSE TestQueueRemove3025=== RUN TestQueueFetchBatchLimit3026=== PAUSE TestQueueFetchBatchLimit3027=== RUN TestQueueRetryMovesToBack3028=== PAUSE TestQueueRetryMovesToBack3029=== RUN TestQueueFetchRemoveLifecycle3030=== PAUSE TestQueueFetchRemoveLifecycle3031=== RUN TestQueueConcurrentWriters3032=== PAUSE TestQueueConcurrentWriters3033=== RUN TestQueueRemoveLargeClosure3034=== PAUSE TestQueueRemoveLargeClosure3035=== RUN TestServerClientIntegration3036=== PAUSE TestServerClientIntegration3037=== RUN TestServerQueueError3038=== PAUSE TestServerQueueError3039=== RUN TestGetListenerSocketActivation3040 server_test.go:210: === RUN TestGetListenerSocketActivation3041 --- PASS: TestGetListenerSocketActivation (0.00s)3042 PASS3043 3044--- PASS: TestGetListenerSocketActivation (0.01s)3045=== RUN TestDrainIsolatesPoisonPath3046=== PAUSE TestDrainIsolatesPoisonPath3047=== RUN TestRunNotBlockedByPoisonHead3048=== PAUSE TestRunNotBlockedByPoisonHead3049=== RUN TestDrainGivesUpWhenServerDown3050=== PAUSE TestDrainGivesUpWhenServerDown3051=== RUN TestFailedPathPrunedByLaterClosure3052=== PAUSE TestFailedPathPrunedByLaterClosure3053=== RUN TestWorkerUploadsAndRemoves3054=== PAUSE TestWorkerUploadsAndRemoves3055=== RUN TestWorkerSkipsGCdPaths3056=== PAUSE TestWorkerSkipsGCdPaths3057=== RUN TestWorkerPrunesClosureDeps3058=== PAUSE TestWorkerPrunesClosureDeps3059=== RUN TestDrainTimeout3060=== PAUSE TestDrainTimeout3061=== CONT TestSendPathsEmpty3062=== CONT TestServerQueueError3063=== CONT TestQueueRetryMovesToBack3064--- PASS: TestSendPathsEmpty (0.00s)3065=== CONT TestQueueFetchBatchLimit3066=== CONT TestQueueRemove3067=== CONT TestQueueDeduplication3068=== CONT TestQueueEnqueueAndFetch3069=== CONT TestQueueConcurrentWriters3070=== CONT TestWorkerUploadsAndRemoves3071=== CONT TestDrainTimeout3072=== CONT TestWorkerPrunesClosureDeps30732026/10/01 07:37:51 ERROR Failed to queue paths error="permission denied" count=13074--- PASS: TestServerQueueError (0.00s)3075=== CONT TestWorkerSkipsGCdPaths30762026/10/01 07:37:51 INFO Upload queue status pending=230772026/10/01 07:37:51 WARN Store path no longer exists (garbage collected?), removing from queue path=/nix/var/nix/builds/nix-54868-424906470/TestWorkerSkipsGCdPaths1613811241/002/nonexistent30782026/10/01 07:37:51 INFO Upload queue status pending=230792026/10/01 07:37:51 INFO Uploading batch count=230802026/10/01 07:37:51 INFO Upload queue status pending=230812026/10/01 07:37:51 INFO Uploading batch count=130822026/10/01 07:37:51 INFO Uploading batch count=230832026/10/01 07:37:51 INFO Uploading batch count=13084--- PASS: TestQueueFetchBatchLimit (0.01s)3085=== CONT TestServerClientIntegration3086--- PASS: TestQueueRemove (0.01s)3087=== CONT TestQueueFetchRemoveLifecycle3088--- PASS: TestQueueDeduplication (0.01s)3089=== CONT TestDrainGivesUpWhenServerDown3090--- PASS: TestQueueRetryMovesToBack (0.01s)3091=== CONT TestFailedPathPrunedByLaterClosure3092--- PASS: TestQueueEnqueueAndFetch (0.01s)3093=== CONT TestRunNotBlockedByPoisonHead3094--- PASS: TestServerClientIntegration (0.00s)3095=== CONT TestQueueRemoveLargeClosure30962026/10/01 07:37:51 INFO Uploading batch count=130972026/10/01 07:37:51 ERROR Upload failed error="upload failed" count=130982026/10/01 07:37:51 INFO Uploading batch count=230992026/10/01 07:37:51 ERROR Upload failed error="upload failed" count=231002026/10/01 07:37:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-54868-424906470/TestDrainGivesUpWhenServerDown3836228260/002/a31012026/10/01 07:37:51 INFO Uploading batch count=13102--- PASS: TestQueueFetchRemoveLifecycle (0.00s)3103=== CONT TestDrainIsolatesPoisonPath31042026/10/01 07:37:51 INFO Uploading batch count=131052026/10/01 07:37:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-54868-424906470/TestDrainGivesUpWhenServerDown3836228260/002/b31062026/10/01 07:37:51 INFO Upload queue status pending=331072026/10/01 07:37:51 INFO Uploading batch count=131082026/10/01 07:37:51 ERROR Upload failed error="upload failed" count=131092026/10/01 07:37:51 INFO Uploading batch count=231102026/10/01 07:37:51 ERROR Upload failed error="upload failed" count=231112026/10/01 07:37:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-54868-424906470/TestDrainGivesUpWhenServerDown3836228260/002/c31122026/10/01 07:37:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-54868-424906470/TestDrainGivesUpWhenServerDown3836228260/002/d3113--- PASS: TestFailedPathPrunedByLaterClosure (0.00s)31142026/10/01 07:37:51 INFO Uploading batch count=231152026/10/01 07:37:51 ERROR Upload failed error="upload failed" count=231162026/10/01 07:37:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-54868-424906470/TestDrainGivesUpWhenServerDown3836228260/002/e31172026/10/01 07:37:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-54868-424906470/TestDrainGivesUpWhenServerDown3836228260/002/f31182026/10/01 07:37:51 ERROR Drain finished with paths left in queue remaining=1031192026/10/01 07:37:51 INFO Uploading batch count=431202026/10/01 07:37:51 ERROR Upload failed error="upload failed" count=431212026/10/01 07:37:51 ERROR Upload failed, will retry later error="upload failed" path=/nix/var/nix/builds/nix-54868-424906470/TestDrainIsolatesPoisonPath238596833/002/bbb31222026/10/01 07:37:51 INFO Uploading batch count=131232026/10/01 07:37:51 ERROR Upload failed error="upload failed" count=131242026/10/01 07:37:51 INFO Uploading batch count=131252026/10/01 07:37:51 ERROR Upload failed error="upload failed" count=13126--- PASS: TestDrainGivesUpWhenServerDown (0.01s)31272026/10/01 07:37:51 INFO Uploading batch count=131282026/10/01 07:37:51 ERROR Upload failed error="upload failed" count=131292026/10/01 07:37:51 ERROR Drain finished with paths left in queue remaining=13130--- PASS: TestDrainIsolatesPoisonPath (0.00s)3131--- PASS: TestWorkerUploadsAndRemoves (0.03s)3132--- PASS: TestWorkerSkipsGCdPaths (0.03s)3133--- PASS: TestWorkerPrunesClosureDeps (0.03s)3134--- PASS: TestQueueConcurrentWriters (0.14s)31352026/10/01 07:37:51 ERROR Upload failed error="context deadline exceeded" count=231362026/10/01 07:37:51 ERROR Drain finished with paths left in queue remaining=43137--- PASS: TestDrainTimeout (0.21s)3138--- PASS: TestQueueRemoveLargeClosure (0.23s)31392026/10/01 07:37:52 INFO Uploading batch count=131402026/10/01 07:37:52 INFO Uploading batch count=131412026/10/01 07:37:52 INFO Uploading batch count=131422026/10/01 07:37:52 ERROR Upload failed error="upload failed" count=131432026/10/01 07:37:52 INFO Uploading batch count=131442026/10/01 07:37:52 ERROR Upload failed error="upload failed" count=131452026/10/01 07:37:52 INFO Uploading batch count=131462026/10/01 07:37:52 ERROR Upload failed error="upload failed" count=131472026/10/01 07:37:52 INFO Uploading batch count=131482026/10/01 07:37:52 ERROR Upload failed error="upload failed" count=131492026/10/01 07:37:52 ERROR Drain finished with paths left in queue remaining=13150--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3151PASS