niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #306
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestCaseHackSuffix8=== PAUSE TestCaseHackSuffix9=== RUN TestFilterOversizedClosures10=== PAUSE TestFilterOversizedClosures11=== RUN TestUploadMultipart_PartsInParallel12=== PAUSE TestUploadMultipart_PartsInParallel13=== RUN TestPartSizeForNAR14=== PAUSE TestPartSizeForNAR15=== RUN TestUploadMultipart_SupersededByPeer16=== PAUSE TestUploadMultipart_SupersededByPeer17=== RUN TestDumpPathCaseHackMatchesNix18--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)19=== RUN TestDumpPathCaseHackCollision20--- PASS: TestDumpPathCaseHackCollision (0.00s)21=== RUN TestDumpPathMatchesNix22=== PAUSE TestDumpPathMatchesNix23=== RUN TestDumpPathSingleFile24=== PAUSE TestDumpPathSingleFile25=== RUN TestDumpPathWriterError26=== PAUSE TestDumpPathWriterError27=== RUN TestEncodeNixBase3228=== PAUSE TestEncodeNixBase3229=== RUN TestEncodeNixBase32WithRealHash30=== PAUSE TestEncodeNixBase32WithRealHash31=== RUN TestConvertHashToNix3232=== PAUSE TestConvertHashToNix3233=== RUN TestGetStorePathHash34=== PAUSE TestGetStorePathHash35=== RUN TestPathInfoHashCompatibility36=== PAUSE TestPathInfoHashCompatibility37=== RUN TestParsePathInfoJSON38=== PAUSE TestParsePathInfoJSON39=== RUN TestParsePathInfoJSONMultiplePaths40=== PAUSE TestParsePathInfoJSONMultiplePaths41=== RUN TestPathInfoCACompatibility42=== PAUSE TestPathInfoCACompatibility43=== RUN TestRateLimiterFeedback44=== PAUSE TestRateLimiterFeedback45=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess47=== RUN TestResolveStorePath48=== PAUSE TestResolveStorePath49=== RUN TestDoWithRetry_BodyReplayedViaGetBody50=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody51=== RUN TestShellSplit52=== PAUSE TestShellSplit53=== RUN TestShellSplitErrors54=== PAUSE TestShellSplitErrors55=== RUN TestStreamPushReportsEveryPath56=== PAUSE TestStreamPushReportsEveryPath57=== RUN TestStreamPushBatchesUnderLoad58=== PAUSE TestStreamPushBatchesUnderLoad59=== RUN TestStreamPushIsolatesFailures60=== PAUSE TestStreamPushIsolatesFailures61=== RUN TestStreamPushGivesUpOnDeadServer62=== PAUSE TestStreamPushGivesUpOnDeadServer63=== RUN TestStreamPushRequestLine64=== PAUSE TestStreamPushRequestLine65=== RUN TestStreamPushReportsSignatures66=== PAUSE TestStreamPushReportsSignatures67=== RUN TestClientSignaturesByStorePath68=== PAUSE TestClientSignaturesByStorePath69=== RUN TestSetClientTLS70=== PAUSE TestSetClientTLS71=== RUN TestSetClientTLSDoesNotMutateDefaultTransport72=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport73=== RUN TestSetClientTLSErrors74=== PAUSE TestSetClientTLSErrors75=== RUN TestStaticToken76=== PAUSE TestStaticToken77=== RUN TestFileTokenReadsAndCaches78=== PAUSE TestFileTokenReadsAndCaches79=== RUN TestFileTokenMissing80=== PAUSE TestFileTokenMissing81=== RUN TestFileTokenEmpty82=== PAUSE TestFileTokenEmpty83=== RUN TestScriptTokenNoExpiryRerunsEveryCall84=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall85=== RUN TestScriptTokenCachesUntilRefresh86=== PAUSE TestScriptTokenCachesUntilRefresh87=== RUN TestScriptTokenEmptyToken88=== PAUSE TestScriptTokenEmptyToken89=== RUN TestScriptTokenBadJSON90=== PAUSE TestScriptTokenBadJSON91=== RUN TestScriptTokenScriptFails92=== PAUSE TestScriptTokenScriptFails93=== RUN TestScriptTokenEmptyCommand94=== PAUSE TestScriptTokenEmptyCommand95=== CONT TestDoServerRequestAttachesToken96=== CONT TestStreamPushBatchesUnderLoad97=== CONT TestConvertHashToNix3298=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess99=== CONT TestStreamPushReportsEveryPath100=== CONT TestShellSplitErrors101=== RUN TestConvertHashToNix32/SRI_format_to_Nix32102=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32103=== RUN TestConvertHashToNix32/already_Nix32_format104=== PAUSE TestConvertHashToNix32/already_Nix32_format105=== RUN TestConvertHashToNix32/invalid_format106=== PAUSE TestConvertHashToNix32/invalid_format107--- PASS: TestShellSplitErrors (0.00s)108=== CONT TestDoWithRetry_BodyReplayedViaGetBody109=== CONT TestResolveStorePath110=== CONT TestParsePathInfoJSONMultiplePaths111=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1122026/10/01 09:18:05 WARN Rate limiter enabled after throttle name=server-test rate=5113=== CONT TestRateLimiterFeedback114=== RUN TestRateLimiterFeedback/429_enables_limiter115=== CONT TestPathInfoCACompatibility116=== CONT TestFileTokenReadsAndCaches117=== CONT TestScriptTokenEmptyCommand118=== CONT TestScriptTokenScriptFails119=== CONT TestScriptTokenBadJSON120=== CONT TestScriptTokenEmptyToken121=== CONT TestScriptTokenCachesUntilRefresh122=== CONT TestScriptTokenNoExpiryRerunsEveryCall123=== CONT TestFileTokenEmpty124=== CONT TestFileTokenMissing125=== CONT TestParsePathInfoJSON126=== CONT TestEncodeNixBase32127=== CONT TestGetStorePathHash128=== CONT TestDumpPathMatchesNix129=== CONT TestShellSplit130=== CONT TestDumpPathWriterError131=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths132--- PASS: TestResolveStorePath (0.00s)133=== CONT TestDumpPathSingleFile134=== RUN TestGetStorePathHash/valid_store_path135--- PASS: TestStreamPushReportsEveryPath (0.00s)136--- PASS: TestScriptTokenEmptyCommand (0.00s)137--- PASS: TestShellSplit (0.00s)138=== PAUSE TestGetStorePathHash/valid_store_path139=== RUN TestPathInfoCACompatibility/null_ca_field140=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths141=== CONT TestEncodeNixBase32WithRealHash142=== CONT TestPathInfoHashCompatibility143=== CONT TestUploadMultipart_PartsInParallel144=== RUN TestParsePathInfoJSON/Nix_format145=== PAUSE TestRateLimiterFeedback/429_enables_limiter146=== RUN TestGetStorePathHash/basename_without_hyphen_should_error147=== RUN TestEncodeNixBase32/test_string_hash148--- PASS: TestFileTokenReadsAndCaches (0.00s)149--- PASS: TestFileTokenEmpty (0.00s)150--- PASS: TestScriptTokenScriptFails (0.00s)151--- PASS: TestFileTokenMissing (0.00s)1522026/10/01 09:18:05 WARN Rate limiter enabled after throttle name=server-test rate=5153=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths1542026/10/01 09:18:05 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:46523155=== CONT TestRegisterUploadedObjectReusesConnections156--- PASS: TestEncodeNixBase32WithRealHash (0.00s)157=== CONT TestClientSignaturesByStorePath158--- PASS: TestClientSignaturesByStorePath (0.00s)1592026/10/01 09:18:05 WARN Rate limiter backed off name=server-test rate=5160=== CONT TestStaticToken1612026/10/01 09:18:05 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:46523162--- PASS: TestStaticToken (0.00s)163=== CONT TestSetClientTLSErrors164=== CONT TestUploadMultipart_SupersededByPeer165=== PAUSE TestPathInfoCACompatibility/null_ca_field166=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)167=== PAUSE TestEncodeNixBase32/test_string_hash168=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error169=== CONT TestPartSizeForNAR170=== CONT TestCaseHackSuffix171=== CONT TestFilterOversizedClosures172=== RUN TestFilterOversizedClosures/no_limit_keeps_everything173=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything174=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped175=== CONT TestStreamPushIsolatesFailures176=== PAUSE TestParsePathInfoJSON/Nix_format177=== RUN TestParsePathInfoJSON/Lix_format178=== PAUSE TestParsePathInfoJSON/Lix_format179=== RUN TestParsePathInfoJSON/empty_input1802026/10/01 09:18:05 ERROR Upload failed error="bad path" count=3181=== PAUSE TestParsePathInfoJSON/empty_input182=== RUN TestParsePathInfoJSON/whitespace_only183=== PAUSE TestParsePathInfoJSON/whitespace_only184=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped185=== RUN TestFilterOversizedClosures/all_closures_skipped186=== CONT TestStreamPushRequestLine187=== CONT TestConvertHashToNix32/SRI_format_to_Nix32188--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)189--- PASS: TestDoServerRequestAttachesToken (0.02s)190=== CONT TestConvertHashToNix32/already_Nix32_format191=== CONT TestConvertHashToNix32/invalid_format192=== CONT TestSetClientTLSDoesNotMutateDefaultTransport193=== CONT TestSetClientTLS194=== RUN TestRateLimiterFeedback/503_enables_limiter195=== RUN TestUploadMultipart_SupersededByPeer/exists196=== CONT TestStreamPushGivesUpOnDeadServer197=== RUN TestPathInfoCACompatibility/old_string_format_-_text198=== RUN TestEncodeNixBase32/empty_input199=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error2002026/10/01 09:18:05 ERROR Upload failed error=boom count=1201=== RUN TestPartSizeForNAR/zero_stays_at_minimum202=== CONT TestStreamPushReportsSignatures203=== RUN TestParsePathInfoJSON/invalid_JSON204=== PAUSE TestParsePathInfoJSON/invalid_JSON205=== PAUSE TestUploadMultipart_SupersededByPeer/exists206=== RUN TestUploadMultipart_SupersededByPeer/missing207=== PAUSE TestUploadMultipart_SupersededByPeer/missing208=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)209=== PAUSE TestEncodeNixBase32/empty_input210=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error211=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error212=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error2132026/10/01 09:18:05 ERROR Upload failed error="connection refused" count=20214=== CONT TestUploadMultipart_SupersededByPeer/exists2152026/10/01 09:18:05 ERROR Server seems unavailable, giving up on batch untried=17216=== CONT TestParsePathInfoJSON/whitespace_only217=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon218=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon219=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI220=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI221=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512222=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512223--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)224--- PASS: TestScriptTokenEmptyToken (0.07s)225--- PASS: TestScriptTokenBadJSON (0.07s)226--- PASS: TestDumpPathSingleFile (0.07s)227--- PASS: TestStreamPushIsolatesFailures (0.00s)2282026/10/01 09:18:05 ERROR Upload failed error=boom count=1229--- PASS: TestConvertHashToNix32 (0.00s)230 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)231 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)232 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)233=== CONT TestParsePathInfoJSON/Lix_format234--- PASS: TestStreamPushReportsSignatures (0.00s)235=== CONT TestUploadMultipart_SupersededByPeer/missing236=== PAUSE TestRateLimiterFeedback/503_enables_limiter237=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter238--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)239=== CONT TestEncodeNixBase32/test_string_hash240=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter241=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter242=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter243=== CONT TestEncodeNixBase32/empty_input244--- PASS: TestEncodeNixBase32 (0.07s)245 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)246 --- PASS: TestEncodeNixBase32/empty_input (0.00s)247=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text248=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive249=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive250=== RUN TestPathInfoCACompatibility/new_structured_format_-_text251=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text252=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method253=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method254=== CONT TestGetStorePathHash/valid_store_path255=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error256=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)257=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths258=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512259=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI260=== CONT TestRateLimiterFeedback/429_enables_limiter261=== RUN TestSetClientTLSErrors/missing_cert_file262=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error263=== CONT TestParsePathInfoJSON/Nix_format264=== PAUSE TestFilterOversizedClosures/all_closures_skipped265=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum266=== CONT TestParsePathInfoJSON/invalid_JSON267=== CONT TestParsePathInfoJSON/empty_input268=== PAUSE TestSetClientTLSErrors/missing_cert_file269=== RUN TestSetClientTLSErrors/missing_key_file270=== PAUSE TestSetClientTLSErrors/missing_key_file271=== RUN TestSetClientTLSErrors/missing_ca_file272=== CONT TestPathInfoCACompatibility/null_ca_field273=== CONT TestPathInfoCACompatibility/old_string_format_-_text274=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method275=== CONT TestFilterOversizedClosures/no_limit_keeps_everything276=== CONT TestFilterOversizedClosures/all_closures_skipped277=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2782026/10/01 09:18:05 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=50279--- PASS: TestParsePathInfoJSON (0.07s)280 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)281 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)282 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)283 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)284 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)2852026/10/01 09:18:05 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=2000286=== CONT TestPathInfoCACompatibility/new_structured_format_-_text287--- PASS: TestUploadMultipart_SupersededByPeer (0.07s)288 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)289 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)2902026/10/01 09:18:05 WARN Rate limiter enabled after throttle name=server-test rate=5291--- PASS: TestFilterOversizedClosures (0.00s)292 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)293 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)294 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)295=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2962026/10/01 09:18:05 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:38895297=== RUN TestSetClientTLS/rejects_connection_without_client_cert298=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert299=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA300=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA301=== RUN TestSetClientTLS/preserves_debug_logging_transport302=== PAUSE TestSetClientTLS/preserves_debug_logging_transport303=== CONT TestSetClientTLS/rejects_connection_without_client_cert304=== PAUSE TestSetClientTLSErrors/missing_ca_file305=== CONT TestGetStorePathHash/basename_without_hyphen_should_error306=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3072026/10/01 09:18:05 WARN Rate limiter backed off name=server-test rate=5308--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)309--- PASS: TestGetStorePathHash (0.07s)310 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)311 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)312 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)313 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)314=== RUN TestPartSizeForNAR/small_stays_at_minimum315=== PAUSE TestPartSizeForNAR/small_stays_at_minimum316=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum317=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum318=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts319=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts320=== RUN TestPartSizeForNAR/1_TiB321=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon322=== CONT TestRateLimiterFeedback/503_enables_limiter323=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter324=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive325=== CONT TestSetClientTLS/preserves_debug_logging_transport326=== RUN TestSetClientTLSErrors/invalid_ca_file327=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths328--- PASS: TestPathInfoHashCompatibility (0.07s)329 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)330 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)331 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)332 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)333--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)334 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)335 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)336=== PAUSE TestSetClientTLSErrors/invalid_ca_file337=== CONT TestSetClientTLSErrors/missing_cert_file338=== CONT TestSetClientTLSErrors/invalid_ca_file3392026/10/01 09:18:05 WARN Rate limiter enabled after throttle name=server-test rate=5340=== PAUSE TestPartSizeForNAR/1_TiB3412026/10/01 09:18:05 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:37417342=== RUN TestPartSizeForNAR/5_TiB_S3_max_object343=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object344=== RUN TestPartSizeForNAR/capped_at_5_GiB3452026/10/01 09:18:05 WARN Rate limiter backed off name=server-test rate=5346=== PAUSE TestPartSizeForNAR/capped_at_5_GiB347=== CONT TestPartSizeForNAR/zero_stays_at_minimum348--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.08s)349--- PASS: TestPathInfoCACompatibility (0.08s)350 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)351 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)352 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)353 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)354 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)355=== CONT TestSetClientTLSErrors/missing_ca_file356=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts357=== CONT TestPartSizeForNAR/small_stays_at_minimum358=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum359=== CONT TestSetClientTLSErrors/missing_key_file360--- PASS: TestRateLimiterFeedback (0.08s)361 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)362 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)363 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)364 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)365=== CONT TestPartSizeForNAR/5_TiB_S3_max_object366=== CONT TestPartSizeForNAR/capped_at_5_GiB367=== CONT TestPartSizeForNAR/1_TiB368--- PASS: TestPartSizeForNAR (0.01s)369 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)370 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)371 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)372 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)373 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)374 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)375 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)376--- PASS: TestSetClientTLSErrors (0.08s)377 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)378 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)379 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)380 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)3812026/10/01 09:18:05 http: TLS handshake error from 127.0.0.1:57602: remote error: tls: bad certificate382--- PASS: TestSetClientTLS (0.00s)383 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)384 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)385 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)386--- PASS: TestStreamPushRequestLine (0.03s)387--- PASS: TestRegisterUploadedObjectReusesConnections (0.10s)388--- PASS: TestCaseHackSuffix (0.03s)389--- PASS: TestDumpPathWriterError (0.11s)390--- PASS: TestStreamPushBatchesUnderLoad (0.13s)391--- PASS: TestDumpPathMatchesNix (0.18s)392--- PASS: TestUploadMultipart_PartsInParallel (0.69s)393--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)394PASS395Running server tests...396The files belonging to this database system will be owned by user "nixbld".397This user must also own the server process.398399The database cluster will be initialized with locale "C".400The default database encoding has accordingly been set to "SQL_ASCII".401The default text search configuration will be set to "english".402403Data page checksums are enabled.404405creating directory /build/postgres2804279740/data ... ok406creating subdirectories ... ok407selecting dynamic shared memory implementation ... posix408selecting default "max_connections" ... 100409selecting default "shared_buffers" ... 128MB410selecting default time zone ... UTC411creating configuration files ... ok412running bootstrap script ... ok413performing post-bootstrap initialization ... ok414syncing data to disk ... ok415416initdb: warning: enabling "trust" authentication for local connections417initdb: 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.418419Success. You can now start the database server using:420421 pg_ctl -D /build/postgres2804279740/data -l logfile start422423/build/postgres2804279740:5432 - no response4242026-10-01 09:18:07.070 UTC [128] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 09:18:07.070 UTC [128] LOG: listening on Unix socket "/build/postgres2804279740/.s.PGSQL.5432"4262026-10-01 09:18:07.080 UTC [135] LOG: database system was shut down at 2026-10-01 09:18:06 UTC4272026-10-01 09:18:07.086 UTC [128] LOG: database system is ready to accept connections428/build/postgres2804279740:5432 - accepting connections429{"timestamp":"2026-10-01T09:18:07.374456803Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"e8033c57-b8b7-4a4f-a68f-3dbe33d2765a","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(387)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock468=== RUN TestResolveDBConnectionString469=== PAUSE TestResolveDBConnectionString470=== RUN TestLeadElectsOneAndHandsOver471=== PAUSE TestLeadElectsOneAndHandsOver472=== RUN TestLeadIncumbentWinsAfterRestart4732026-10-01 09:18:07.558 UTC [562] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 09:18:07.558 UTC [562] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 09:18:07 OK 20241026095416_initial_model.sql (6.17ms)4762026/10/01 09:18:07 OK 20251210153512_drop_unused_gin_index.sql (1.28ms)4772026/10/01 09:18:07 OK 20251218171726_add_pins.sql (1.96ms)4782026/10/01 09:18:07 OK 20260628120000_add_object_size_and_stats.sql (1.95ms)4792026/10/01 09:18:07 OK 20260905000000_add_claims.sql (2.09ms)4802026/10/01 09:18:07 OK 20260920000000_drop_claims.sql (1.29ms)4812026/10/01 09:18:07 OK 20260923120000_add_pushes.sql (961.12µs)4822026/10/01 09:18:07 goose: successfully migrated database to version: 202609231200004832026/10/01 09:18:07 OK 1_commit_pending_closure.sql (1.48ms)4842026/10/01 09:18:07 OK 2_object_stats_trigger.sql (607.77µs)4852026/10/01 09:18:07 OK 3_commit_push.sql (567.77µs)4862026/10/01 09:18:07 goose: up to current file version: 34872026/10/01 09:18:07 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 09:18:08 INFO lead: released remote=192.0.2.1:12344892026/10/01 09:18:08 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 09:18:08 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (0.78s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 09:18:08.323 UTC [572] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 09:18:08.323 UTC [572] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 09:18:08 OK 20241026095416_initial_model.sql (6.45ms)4982026/10/01 09:18:08 OK 20251210153512_drop_unused_gin_index.sql (1.06ms)4992026/10/01 09:18:08 OK 20251218171726_add_pins.sql (2.43ms)5002026/10/01 09:18:08 OK 20260628120000_add_object_size_and_stats.sql (2.34ms)5012026/10/01 09:18:08 OK 20260905000000_add_claims.sql (2.58ms)5022026/10/01 09:18:08 OK 20260920000000_drop_claims.sql (1.47ms)5032026/10/01 09:18:08 OK 20260923120000_add_pushes.sql (1.1ms)5042026/10/01 09:18:08 goose: successfully migrated database to version: 202609231200005052026/10/01 09:18:08 OK 1_commit_pending_closure.sql (1.49ms)5062026/10/01 09:18:08 OK 2_object_stats_trigger.sql (834.35µs)5072026/10/01 09:18:08 OK 3_commit_push.sql (777.96µs)5082026/10/01 09:18:08 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.12s)510=== RUN TestGCBugBareHashReferences511=== PAUSE TestGCBugBareHashReferences512=== RUN TestGCMetrics513=== PAUSE TestGCMetrics514=== RUN TestPushDedupSurvivesConcurrentGC515=== PAUSE TestPushDedupSurvivesConcurrentGC516=== RUN TestDeduplicatedObjectsRecordedAsPending517=== PAUSE TestDeduplicatedObjectsRecordedAsPending518=== RUN TestGCSweepSkipsPendingObjects519=== PAUSE TestGCSweepSkipsPendingObjects520=== RUN TestTombstonedObjectOfferedWithoutWaiting521=== PAUSE TestTombstonedObjectOfferedWithoutWaiting522=== RUN TestGCSweepDeliversEachKeyOnce523=== PAUSE TestGCSweepDeliversEachKeyOnce524=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== RUN TestForceGCDuringPushOffersSweptObject527=== PAUSE TestForceGCDuringPushOffersSweptObject528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestSweepRechecksPendingAfterLocking537=== PAUSE TestSweepRechecksPendingAfterLocking538=== RUN TestPushWaitsForSweepHoldingRow539=== PAUSE TestPushWaitsForSweepHoldingRow540=== RUN TestCommitRacingPendingCleanupKeepsObjects541=== PAUSE TestCommitRacingPendingCleanupKeepsObjects542=== RUN TestGCTaskStore_StartNew543=== PAUSE TestGCTaskStore_StartNew544=== RUN TestGCTaskStore_DeduplicateSameParams545=== PAUSE TestGCTaskStore_DeduplicateSameParams546=== RUN TestGCTaskStore_ConflictDifferentParams547=== PAUSE TestGCTaskStore_ConflictDifferentParams548=== RUN TestGCTaskStore_GetEmpty549=== PAUSE TestGCTaskStore_GetEmpty550=== RUN TestGCTaskStore_GetReturnsLatest551=== PAUSE TestGCTaskStore_GetReturnsLatest552=== RUN TestGCTaskStore_CompletedAllowsNewTask553=== PAUSE TestGCTaskStore_CompletedAllowsNewTask554=== RUN TestGCTaskStore_PhaseUpdates555=== PAUSE TestGCTaskStore_PhaseUpdates556=== RUN TestGCTaskStore_Fail557=== PAUSE TestGCTaskStore_Fail558=== RUN TestGracefulShutdownDrainsInflight559=== PAUSE TestGracefulShutdownDrainsInflight560=== RUN TestService_healthCheckHandler561=== PAUSE TestService_healthCheckHandler562=== RUN TestService_readinessHandler563=== PAUSE TestService_readinessHandler564=== RUN TestGenerateLandingPage565=== PAUSE TestGenerateLandingPage566=== RUN TestCacheConfigHandlerMaxNarSize567=== PAUSE TestCacheConfigHandlerMaxNarSize568=== RUN TestCreatePendingClosureRejectsOversizedNAR569=== PAUSE TestCreatePendingClosureRejectsOversizedNAR570=== RUN TestNARDeduplicationMetadataUploadBug571=== PAUSE TestNARDeduplicationMetadataUploadBug572=== RUN TestMetricsInventory573=== PAUSE TestMetricsInventory574=== RUN TestService_NativeMTLS575=== PAUSE TestService_NativeMTLS576=== RUN TestServerTLSConfig577=== PAUSE TestServerTLSConfig578=== RUN TestMultipartCleanup579=== PAUSE TestMultipartCleanup580=== RUN TestObjectStatsTrigger581=== PAUSE TestObjectStatsTrigger582=== RUN TestOrphanedObjectsGC583=== PAUSE TestOrphanedObjectsGC584=== RUN TestOrphanedObjectsGCStressTest585=== PAUSE TestOrphanedObjectsGCStressTest586=== RUN TestCreatePin_ReservedPins587=== PAUSE TestCreatePin_ReservedPins588=== RUN TestParseSingleRange589=== PAUSE TestParseSingleRange590=== RUN TestProxyHeadersOnlyTrustedOnSocket591=== PAUSE TestProxyHeadersOnlyTrustedOnSocket592=== RUN TestIsValidCachePath593=== PAUSE TestIsValidCachePath594=== RUN TestReadProxyNarinfo595=== PAUSE TestReadProxyNarinfo596=== RUN TestReadProxyNarinfoAlreadyDecompressed597=== PAUSE TestReadProxyNarinfoAlreadyDecompressed598=== RUN TestReadProxyNarStreaming599=== PAUSE TestReadProxyNarStreaming600=== RUN TestReadProxy404601=== PAUSE TestReadProxy404602=== RUN TestReadProxyInvalidPath603=== PAUSE TestReadProxyInvalidPath604=== RUN TestReadProxyHead605=== PAUSE TestReadProxyHead606=== RUN TestReadProxyConditionalGet607=== PAUSE TestReadProxyConditionalGet608=== RUN TestReadProxyRootRedirectsToIndexHTML609=== PAUSE TestReadProxyRootRedirectsToIndexHTML610=== RUN TestReadProxyDisabled611=== PAUSE TestReadProxyDisabled612=== RUN TestReadRedirectNar613=== PAUSE TestReadRedirectNar614=== RUN TestReadRedirectKeepsNarinfoProxied615=== PAUSE TestReadRedirectKeepsNarinfoProxied616=== RUN TestReadProxyRangeRequest617=== PAUSE TestReadProxyRangeRequest618=== RUN TestReadRedirectUsesPublicS3URL619=== PAUSE TestReadRedirectUsesPublicS3URL620=== RUN TestPush_OverlappingRootsStoreOneRowPerKey621=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey622=== RUN TestPush_CompleteCommitsEveryRoot623=== PAUSE TestPush_CompleteCommitsEveryRoot624=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit625=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit626=== RUN TestPush_RejectsBadRequests627=== PAUSE TestPush_RejectsBadRequests628=== RUN TestPush_SignsNarinfosOfItsPendingObjects629=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects630=== RUN TestRedundantMultipartUpload631=== PAUSE TestRedundantMultipartUpload632=== RUN TestCompleteMultipartUpload_ErrorButObjectExists633=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists634=== RUN TestCompletedNarNotReofferedAcrossClosures635=== PAUSE TestCompletedNarNotReofferedAcrossClosures636=== RUN TestPresignedUploadRegisteredBeforeCommit637=== PAUSE TestPresignedUploadRegisteredBeforeCommit638=== RUN TestService_Rustfstest639=== PAUSE TestService_Rustfstest640=== RUN TestParseSize641=== PAUSE TestParseSize642=== RUN TestSkippedUploadsHandler643=== PAUSE TestSkippedUploadsHandler644=== RUN TestSystemdListenerNotActivated645--- PASS: TestSystemdListenerNotActivated (0.00s)646=== RUN TestWatchdogBeatsWhenHealthy647--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)648=== RUN TestWatchdogSkipsWhenUnhealthy6492026/10/01 09:18:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6502026/10/01 09:18:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6512026/10/01 09:18:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6522026/10/01 09:18:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6532026/10/01 09:18:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6542026/10/01 09:18:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6552026/10/01 09:18:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6562026/10/01 09:18:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6572026/10/01 09:18:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6582026/10/01 09:18:08 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"659--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)660=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle661=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle662=== RUN TestProxyWriteTimeout663=== PAUSE TestProxyWriteTimeout664=== RUN TestIsValidUploadKey665=== PAUSE TestIsValidUploadKey666=== RUN TestUploadHandlersRejectInvalidKeys667=== PAUSE TestUploadHandlersRejectInvalidKeys668=== RUN TestUploadHandlersRejectOversizedBody669=== PAUSE TestUploadHandlersRejectOversizedBody670=== RUN TestService_cleanupPendingClosuresHandler671=== PAUSE TestService_cleanupPendingClosuresHandler672=== RUN TestService_createPendingClosureHandler673=== PAUSE TestService_createPendingClosureHandler674=== RUN TestService_verifyS3Integrity675=== PAUSE TestService_verifyS3Integrity676=== RUN TestCompleteMultipartUnregistered677=== PAUSE TestCompleteMultipartUnregistered678=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT679=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT680=== CONT TestService_AuthMiddleware681=== CONT TestCacheConfigHandlerMaxNarSize682=== CONT TestDeduplicatedObjectsRecordedAsPending683--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)684=== CONT TestLeadElectsOneAndHandsOver685=== CONT TestGenerateLandingPage686=== CONT TestService_readinessHandler687=== CONT TestService_healthCheckHandler688=== CONT TestGracefulShutdownDrainsInflight689=== CONT TestGCTaskStore_Fail6902026/10/01 09:18:08 INFO Starting HTTP server address=127.0.0.1:38923691--- PASS: TestGCTaskStore_Fail (0.00s)692=== CONT TestGCTaskStore_PhaseUpdates693=== CONT TestGCTaskStore_CompletedAllowsNewTask694=== CONT TestGCTaskStore_GetReturnsLatest695=== CONT TestGCTaskStore_GetEmpty696=== CONT TestGCTaskStore_ConflictDifferentParams697=== CONT TestGCTaskStore_DeduplicateSameParams698=== CONT TestGCTaskStore_StartNew699=== CONT TestClientWithDependencies700=== CONT TestCommitRacingPendingCleanupKeepsObjects701=== CONT TestPushDedupSurvivesConcurrentGC702=== CONT TestGCMetrics703=== CONT TestPushWaitsForSweepHoldingRow704=== CONT TestGCBugBareHashReferences705=== CONT TestSweepRechecksPendingAfterLocking706=== CONT TestLeadEndsOnShutdown707=== CONT TestGetExistingObjectsLocksRows708=== CONT TestRegisterCompletedObjectNeedsPendingRow7092026/10/01 09:18:08 INFO Shutdown signal received, draining in-flight requests timeout=10s710--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)711--- PASS: TestGCTaskStore_GetEmpty (0.00s)712--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)713--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)714--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)715--- PASS: TestGCTaskStore_StartNew (0.00s)716--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)717=== CONT TestResolveDBConnectionString718=== CONT TestSweepSkipsRowsLockedByPush719=== RUN TestResolveDBConnectionString/flag_wins720=== CONT TestFailedS3DeleteKeepsTombstone721=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock722=== CONT TestForceGCDuringPushOffersSweptObject723=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows724=== CONT TestClientFallsBackToClosures725=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection726=== PAUSE TestResolveDBConnectionString/flag_wins727=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows728=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check729=== RUN TestResolveDBConnectionString/file_when_flag_empty730=== PAUSE TestResolveDBConnectionString/file_when_flag_empty731=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check732--- PASS: TestGenerateLandingPage (0.01s)733=== CONT TestClientPushesUseOnePush734=== RUN TestResolveDBConnectionString/missing_file_is_an_error735=== CONT TestGCSweepDeliversEachKeyOnce736=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error737=== RUN TestResolveDBConnectionString/PGHOST_allows_empty738=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty739=== RUN TestResolveDBConnectionString/nothing_configured740=== PAUSE TestResolveDBConnectionString/nothing_configured741=== CONT TestPinProtectsFromGC742--- PASS: TestGracefulShutdownDrainsInflight (0.07s)743=== CONT TestTombstonedObjectOfferedWithoutWaiting7442026-10-01 09:18:08.788 UTC [639] ERROR: relation "goose_db_version" does not exist at character 367452026-10-01 09:18:08.788 UTC [639] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7462026-10-01 09:18:08.838 UTC [640] ERROR: relation "goose_db_version" does not exist at character 367472026-10-01 09:18:08.838 UTC [640] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7482026-10-01 09:18:08.880 UTC [641] ERROR: relation "goose_db_version" does not exist at character 367492026-10-01 09:18:08.880 UTC [641] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7502026/10/01 09:18:08 OK 20241026095416_initial_model.sql (22.9ms)7512026/10/01 09:18:08 OK 20241026095416_initial_model.sql (58.72ms)7522026/10/01 09:18:08 OK 20251210153512_drop_unused_gin_index.sql (5.46ms)7532026/10/01 09:18:08 OK 20251210153512_drop_unused_gin_index.sql (3.88ms)7542026/10/01 09:18:08 OK 20241026095416_initial_model.sql (22.5ms)7552026/10/01 09:18:08 OK 20251218171726_add_pins.sql (4.56ms)7562026/10/01 09:18:08 OK 20251210153512_drop_unused_gin_index.sql (2.87ms)7572026/10/01 09:18:08 OK 20251218171726_add_pins.sql (5.81ms)7582026/10/01 09:18:08 OK 20260628120000_add_object_size_and_stats.sql (4.77ms)7592026-10-01 09:18:08.939 UTC [642] ERROR: relation "goose_db_version" does not exist at character 367602026-10-01 09:18:08.939 UTC [642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7612026-10-01 09:18:08.940 UTC [643] ERROR: relation "goose_db_version" does not exist at character 367622026-10-01 09:18:08.940 UTC [643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7632026-10-01 09:18:08.940 UTC [644] ERROR: relation "goose_db_version" does not exist at character 367642026-10-01 09:18:08.940 UTC [644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7652026/10/01 09:18:08 OK 20251218171726_add_pins.sql (4.3ms)7662026/10/01 09:18:08 OK 20260905000000_add_claims.sql (4.86ms)7672026/10/01 09:18:08 OK 20260628120000_add_object_size_and_stats.sql (8.29ms)7682026/10/01 09:18:08 OK 20260628120000_add_object_size_and_stats.sql (6.63ms)7692026/10/01 09:18:08 OK 20260920000000_drop_claims.sql (3.84ms)7702026/10/01 09:18:08 OK 20260923120000_add_pushes.sql (4.48ms)7712026/10/01 09:18:08 goose: successfully migrated database to version: 202609231200007722026/10/01 09:18:08 OK 20260905000000_add_claims.sql (6.9ms)7732026/10/01 09:18:08 OK 20260905000000_add_claims.sql (8.7ms)7742026/10/01 09:18:08 OK 1_commit_pending_closure.sql (3.48ms)7752026/10/01 09:18:08 OK 20260920000000_drop_claims.sql (4.27ms)7762026/10/01 09:18:08 OK 2_object_stats_trigger.sql (2.31ms)7772026/10/01 09:18:08 OK 20260920000000_drop_claims.sql (4.86ms)7782026/10/01 09:18:08 OK 3_commit_push.sql (1.98ms)7792026/10/01 09:18:08 goose: up to current file version: 37802026/10/01 09:18:08 OK 20260923120000_add_pushes.sql (5.62ms)7812026/10/01 09:18:08 goose: successfully migrated database to version: 202609231200007822026/10/01 09:18:08 OK 20260923120000_add_pushes.sql (18.4ms)7832026/10/01 09:18:08 goose: successfully migrated database to version: 202609231200007842026/10/01 09:18:08 OK 1_commit_pending_closure.sql (17.68ms)7852026/10/01 09:18:08 OK 20241026095416_initial_model.sql (33.05ms)7862026/10/01 09:18:08 OK 20241026095416_initial_model.sql (34.6ms)7872026/10/01 09:18:08 OK 20241026095416_initial_model.sql (32.98ms)7882026/10/01 09:18:08 OK 2_object_stats_trigger.sql (3.41ms)7892026/10/01 09:18:08 OK 1_commit_pending_closure.sql (9.51ms)7902026/10/01 09:18:08 OK 3_commit_push.sql (3.22ms)7912026/10/01 09:18:08 goose: up to current file version: 37922026/10/01 09:18:08 OK 20251210153512_drop_unused_gin_index.sql (4.46ms)7932026/10/01 09:18:08 OK 20251210153512_drop_unused_gin_index.sql (4.86ms)7942026/10/01 09:18:08 OK 20251210153512_drop_unused_gin_index.sql (3.96ms)7952026/10/01 09:18:08 OK 2_object_stats_trigger.sql (4.83ms)7962026/10/01 09:18:08 OK 20251218171726_add_pins.sql (5.25ms)7972026-10-01 09:18:08.996 UTC [649] ERROR: relation "goose_db_version" does not exist at character 367982026-10-01 09:18:08.996 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7992026/10/01 09:18:08 OK 20251218171726_add_pins.sql (6.64ms)8002026/10/01 09:18:08 OK 3_commit_push.sql (3.34ms)8012026/10/01 09:18:08 goose: up to current file version: 38022026-10-01 09:18:08.997 UTC [648] ERROR: relation "goose_db_version" does not exist at character 368032026-10-01 09:18:08.997 UTC [648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8042026-10-01 09:18:08.998 UTC [650] ERROR: relation "goose_db_version" does not exist at character 368052026-10-01 09:18:08.998 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8062026/10/01 09:18:08 OK 20251218171726_add_pins.sql (6.55ms)8072026-10-01 09:18:08.998 UTC [651] ERROR: relation "goose_db_version" does not exist at character 368082026-10-01 09:18:08.998 UTC [651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8092026-10-01 09:18:09.002 UTC [653] ERROR: relation "goose_db_version" does not exist at character 368102026-10-01 09:18:09.002 UTC [653] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8112026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.76ms)8122026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.62ms)8132026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.64ms)8142026-10-01 09:18:09.006 UTC [655] ERROR: relation "goose_db_version" does not exist at character 368152026-10-01 09:18:09.006 UTC [655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8162026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.93ms)8172026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.26ms)8182026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.99ms)8192026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.97ms)8202026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.98ms)8212026/10/01 09:18:09 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"822--- PASS: TestService_AuthMiddleware (0.40s)823=== CONT TestClientSharedPathCommittedMidPush8242026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (3.61ms)8252026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200008262026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.86ms)8272026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (3.96ms)8282026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200008292026-10-01 09:18:09.017 UTC [656] ERROR: relation "goose_db_version" does not exist at character 368302026-10-01 09:18:09.017 UTC [656] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8312026/10/01 09:18:09 OK 1_commit_pending_closure.sql (13.2ms)8322026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (16.23ms)8332026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200008342026/10/01 09:18:09 OK 1_commit_pending_closure.sql (15.5ms)8352026/10/01 09:18:09 OK 2_object_stats_trigger.sql (5.84ms)8362026/10/01 09:18:09 INFO lead: acquired remote=192.0.2.1:12348372026/10/01 09:18:09 OK 2_object_stats_trigger.sql (3.54ms)8382026/10/01 09:18:09 OK 20241026095416_initial_model.sql (24.16ms)8392026/10/01 09:18:09 OK 3_commit_push.sql (3.19ms)8402026/10/01 09:18:09 goose: up to current file version: 38412026/10/01 09:18:09 OK 1_commit_pending_closure.sql (5.57ms)8422026/10/01 09:18:09 OK 3_commit_push.sql (2.94ms)8432026/10/01 09:18:09 goose: up to current file version: 38442026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.97ms)8452026/10/01 09:18:09 OK 20241026095416_initial_model.sql (25.47ms)8462026/10/01 09:18:09 OK 2_object_stats_trigger.sql (3.8ms)8472026/10/01 09:18:09 OK 20241026095416_initial_model.sql (25.44ms)8482026/10/01 09:18:09 OK 20241026095416_initial_model.sql (25.15ms)8492026/10/01 09:18:09 OK 20241026095416_initial_model.sql (28.17ms)8502026/10/01 09:18:09 OK 3_commit_push.sql (2.14ms)8512026/10/01 09:18:09 goose: up to current file version: 38522026/10/01 09:18:09 OK 20251218171726_add_pins.sql (5.04ms)8532026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (3.78ms)8542026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (3.16ms)8552026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (3.1ms)8562026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (3.05ms)8572026/10/01 09:18:09 OK 20241026095416_initial_model.sql (13.94ms)8582026/10/01 09:18:09 OK 20251218171726_add_pins.sql (5.16ms)8592026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.78ms)8602026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.49ms)8612026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.83ms)8622026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.62ms)8632026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.42ms)8642026-10-01 09:18:09.050 UTC [677] ERROR: relation "goose_db_version" does not exist at character 368652026-10-01 09:18:09.050 UTC [677] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8662026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.9ms)8672026/10/01 09:18:09 OK 20251218171726_add_pins.sql (5.1ms)8682026/10/01 09:18:09 OK 20241026095416_initial_model.sql (14.73ms)8692026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.43ms)8702026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.57ms)8712026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.95ms)8722026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.33ms)8732026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.22ms)8742026-10-01 09:18:09.057 UTC [678] ERROR: relation "goose_db_version" does not exist at character 368752026-10-01 09:18:09.057 UTC [678] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8762026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.81ms)8772026-10-01 09:18:09.058 UTC [679] ERROR: relation "goose_db_version" does not exist at character 368782026-10-01 09:18:09.058 UTC [679] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8792026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.34ms)8802026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.39ms)8812026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.72ms)8822026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (3.81ms)8832026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200008842026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.64ms)8852026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.91ms)8862026-10-01 09:18:09.061 UTC [681] ERROR: relation "goose_db_version" does not exist at character 368872026-10-01 09:18:09.061 UTC [681] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8882026-10-01 09:18:09.061 UTC [682] ERROR: relation "goose_db_version" does not exist at character 368892026-10-01 09:18:09.061 UTC [682] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8902026-10-01 09:18:09.062 UTC [680] ERROR: relation "goose_db_version" does not exist at character 368912026-10-01 09:18:09.062 UTC [680] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8922026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.43ms)8932026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.52ms)8942026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.25ms)8952026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.74ms)8962026/10/01 09:18:09 OK 1_commit_pending_closure.sql (3.79ms)8972026-10-01 09:18:09.064 UTC [683] ERROR: relation "goose_db_version" does not exist at character 368982026-10-01 09:18:09.064 UTC [683] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8992026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.88ms)9002026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200009012026-10-01 09:18:09.066 UTC [685] ERROR: relation "goose_db_version" does not exist at character 369022026-10-01 09:18:09.066 UTC [685] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9032026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.85ms)9042026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200009052026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.42ms)9062026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.88ms)9072026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.89ms)9082026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.63ms)9092026/10/01 09:18:09 OK 1_commit_pending_closure.sql (3.17ms)9102026/10/01 09:18:09 OK 3_commit_push.sql (1.8ms)9112026/10/01 09:18:09 goose: up to current file version: 39122026-10-01 09:18:09.069 UTC [700] ERROR: relation "goose_db_version" does not exist at character 369132026-10-01 09:18:09.069 UTC [700] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9142026-10-01 09:18:09.069 UTC [688] ERROR: relation "goose_db_version" does not exist at character 369152026-10-01 09:18:09.069 UTC [688] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9162026/10/01 09:18:09 OK 1_commit_pending_closure.sql (3.24ms)9172026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.03ms)9182026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.49ms)9192026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.61ms)9202026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200009212026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (3.15ms)9222026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200009232026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.04ms)9242026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.71ms)9252026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.41ms)9262026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200009272026/10/01 09:18:09 OK 3_commit_push.sql (1.87ms)9282026/10/01 09:18:09 goose: up to current file version: 39292026/10/01 09:18:09 OK 3_commit_push.sql (2.09ms)9302026/10/01 09:18:09 goose: up to current file version: 39312026/10/01 09:18:09 OK 1_commit_pending_closure.sql (3.32ms)9322026/10/01 09:18:09 OK 1_commit_pending_closure.sql (3.42ms)9332026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.67ms)9342026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.51ms)9352026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.8ms)9362026/10/01 09:18:09 OK 1_commit_pending_closure.sql (4.54ms)9372026/10/01 09:18:09 OK 20241026095416_initial_model.sql (12.15ms)9382026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (3.56ms)9392026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200009402026/10/01 09:18:09 OK 20241026095416_initial_model.sql (13.2ms)9412026/10/01 09:18:09 OK 3_commit_push.sql (2.25ms)9422026/10/01 09:18:09 goose: up to current file version: 39432026-10-01 09:18:09.079 UTC [703] ERROR: relation "goose_db_version" does not exist at character 369442026-10-01 09:18:09.079 UTC [703] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9452026/10/01 09:18:09 OK 3_commit_push.sql (1.92ms)9462026/10/01 09:18:09 goose: up to current file version: 39472026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.82ms)9482026/10/01 09:18:09 OK 20241026095416_initial_model.sql (13.2ms)9492026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.82ms)9502026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.92ms)9512026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.37ms)9522026/10/01 09:18:09 OK 3_commit_push.sql (1.28ms)9532026/10/01 09:18:09 goose: up to current file version: 39542026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.47ms)9552026/10/01 09:18:09 INFO lead: acquired remote=192.0.2.1:12349562026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.65ms)9572026/10/01 09:18:09 INFO lead: released remote=192.0.2.1:1234958--- PASS: TestLeadEndsOnShutdown (0.47s)959=== CONT TestGCSweepSkipsPendingObjects9602026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.08ms)9612026/10/01 09:18:09 OK 20241026095416_initial_model.sql (13.51ms)9622026/10/01 09:18:09 OK 3_commit_push.sql (1.98ms)9632026/10/01 09:18:09 goose: up to current file version: 39642026/10/01 09:18:09 OK 20241026095416_initial_model.sql (15.65ms)965=== NAME TestClientWithDependencies9662026/10/01 09:18:09 OK 20251218171726_add_pins.sql (6.99ms)967 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies3639075796/001/store/jhfwq93xprm205c9n9da39x4c9jw0iiq-test-script9682026/10/01 09:18:09 OK 20251218171726_add_pins.sql (7.66ms)9692026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (4.38ms)9702026/10/01 09:18:09 OK 20241026095416_initial_model.sql (17.06ms)9712026/10/01 09:18:09 OK 20241026095416_initial_model.sql (15.79ms)9722026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures9732026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.62ms)9742026/10/01 09:18:09 OK 20241026095416_initial_model.sql (15.33ms)9752026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (5.63ms)9762026/10/01 09:18:09 OK 20241026095416_initial_model.sql (14.95ms)9772026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (5.12ms)9782026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.97ms)9792026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (7.76ms)9802026/10/01 09:18:09 OK 20251218171726_add_pins.sql (7.66ms)9812026/10/01 09:18:09 OK 20241026095416_initial_model.sql (16.42ms)9822026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.24ms)9832026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.59ms)9842026/10/01 09:18:09 OK 20260905000000_add_claims.sql (8.13ms)9852026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.7ms)9862026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.65ms)9872026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.66ms)9882026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.15ms)9892026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.24ms)9902026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.86ms)9912026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.81ms)9922026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.77ms)9932026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.53ms)9942026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.03ms)9952026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200009962026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)9972026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.16ms)9982026/10/01 09:18:09 OK 20241026095416_initial_model.sql (10.42ms)9992026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.69ms)10002026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.52ms)10012026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.9ms)10022026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000010032026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.7ms)10042026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.2ms)10052026/10/01 09:18:09 OK 20260905000000_add_claims.sql (2.72ms)10062026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.24ms)10072026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.04ms)10082026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.16ms)10092026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.67ms)10102026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.8ms)10112026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.93ms)10122026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.77ms)10132026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.26ms)10142026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.74ms)10152026/10/01 09:18:09 OK 3_commit_push.sql (2.07ms)10162026/10/01 09:18:09 goose: up to current file version: 310172026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.02ms)10182026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.19ms)10192026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.32ms)10202026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.39ms)10212026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.72ms)10222026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.44ms)10232026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000010242026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.66ms)10252026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.5ms)10262026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000010272026/10/01 09:18:09 OK 3_commit_push.sql (1.37ms)10282026/10/01 09:18:09 goose: up to current file version: 310292026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.67ms)10302026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.79ms)10312026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.83ms)10322026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.09ms)10332026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.44ms)10342026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000010352026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.84ms)10362026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.36ms)10372026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.78ms)10382026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.96ms)10392026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000010402026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (1.68ms)10412026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000010422026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.24ms)10432026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.35ms)10442026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.22ms)10452026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.32ms)10462026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000010472026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.43ms)10482026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.12ms)10492026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.06ms)10502026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.4ms)10512026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.99ms)10522026/10/01 09:18:09 OK 3_commit_push.sql (1.94ms)10532026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (3.05ms)10542026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000010552026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.8ms)10562026/10/01 09:18:09 OK 3_commit_push.sql (2.04ms)10572026/10/01 09:18:09 goose: up to current file version: 310582026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.6ms)10592026/10/01 09:18:09 goose: up to current file version: 310602026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.53ms)10612026/10/01 09:18:09 INFO Aborted multipart uploads count=010622026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period10632026/10/01 09:18:09 OK 2_object_stats_trigger.sql (8.53ms)10642026/10/01 09:18:09 OK 2_object_stats_trigger.sql (8.45ms)10652026/10/01 09:18:09 OK 3_commit_push.sql (9.47ms)10662026/10/01 09:18:09 goose: up to current file version: 310672026/10/01 09:18:09 OK 1_commit_pending_closure.sql (9.55ms)10682026/10/01 09:18:09 OK 2_object_stats_trigger.sql (9.3ms)10692026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (8.83ms)10702026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000010712026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (12.17ms)10722026/10/01 09:18:09 OK 3_commit_push.sql (2.85ms)10732026/10/01 09:18:09 goose: up to current file version: 310742026/10/01 09:18:09 OK 3_commit_push.sql (2.75ms)10752026/10/01 09:18:09 goose: up to current file version: 310762026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.16ms)10772026/10/01 09:18:09 OK 3_commit_push.sql (1.05ms)10782026/10/01 09:18:09 goose: up to current file version: 310792026/10/01 09:18:09 OK 3_commit_push.sql (1.24ms)10802026/10/01 09:18:09 goose: up to current file version: 310812026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.85ms)1082--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.52s)1083=== CONT TestCacheConfigHandler1084=== RUN TestCacheConfigHandler/full_config,_no_issuer1085=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1086=== RUN TestCacheConfigHandler/no_cache_url_configured1087=== PAUSE TestCacheConfigHandler/no_cache_url_configured1088=== RUN TestCacheConfigHandler/no_signing_keys1089=== PAUSE TestCacheConfigHandler/no_signing_keys1090=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1091=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1092=== CONT TestClientMultipleUploads10932026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.01ms)1094=== NAME TestClientWithDependencies10952026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.73ms)1096 client_integration_test.go:615: Found 1 dependencies (including self)10972026/10/01 09:18:09 OK 3_commit_push.sql (1.12ms)10982026/10/01 09:18:09 goose: up to current file version: 310992026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.57ms)11002026-10-01 09:18:09.139 UTC [726] ERROR: relation "goose_db_version" does not exist at character 3611012026-10-01 09:18:09.139 UTC [726] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11022026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.61ms)11032026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000011042026/10/01 09:18:09 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=011052026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.83ms)11062026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.04ms)11072026/10/01 09:18:09 INFO Vacuumed table table=pending_closures11082026/10/01 09:18:09 OK 3_commit_push.sql (975.55µs)11092026/10/01 09:18:09 goose: up to current file version: 311102026/10/01 09:18:09 INFO Vacuumed table table=pending_objects11112026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads11122026/10/01 09:18:09 INFO Vacuumed table table=closures11132026/10/01 09:18:09 INFO Vacuumed table table=objects1114--- PASS: TestSweepRechecksPendingAfterLocking (0.53s)1115=== CONT TestClientIntegration11162026/10/01 09:18:09 OK 20241026095416_initial_model.sql (8.2ms)11172026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)11182026/10/01 09:18:09 OK 20251218171726_add_pins.sql (2.69ms)11192026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.14ms)11202026/10/01 09:18:09 OK 20260905000000_add_claims.sql (2.96ms)11212026/10/01 09:18:09 WARN readiness check failed error="closed pool"1122--- PASS: TestService_readinessHandler (0.55s)1123=== CONT TestReadProxyRangeRequest11242026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.32ms)11252026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.48ms)11262026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000011272026/10/01 09:18:09 INFO Aborted multipart uploads count=011282026/10/01 09:18:09 OK 1_commit_pending_closure.sql (3.61ms)11292026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.93ms)11302026/10/01 09:18:09 OK 3_commit_push.sql (1.22ms)11312026/10/01 09:18:09 goose: up to current file version: 311322026/10/01 09:18:09 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=011332026/10/01 09:18:09 INFO Vacuumed table table=pending_closures11342026/10/01 09:18:09 INFO lead: released remote=192.0.2.1:123411352026/10/01 09:18:09 INFO Vacuumed table table=pending_objects11362026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads11372026/10/01 09:18:09 INFO Vacuumed table table=closures11382026/10/01 09:18:09 INFO Vacuumed table table=objects11392026-10-01 09:18:09.197 UTC [752] ERROR: relation "goose_db_version" does not exist at character 3611402026-10-01 09:18:09.197 UTC [752] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11412026/10/01 09:18:09 INFO Aborted multipart uploads count=011422026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period11432026/10/01 09:18:09 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=011442026/10/01 09:18:09 INFO Vacuumed table table=pending_closures11452026/10/01 09:18:09 INFO Vacuumed table table=pending_objects11462026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads11472026/10/01 09:18:09 INFO Vacuumed table table=closures11482026/10/01 09:18:09 INFO Vacuumed table table=objects1149--- PASS: TestPushDedupSurvivesConcurrentGC (0.60s)1150=== CONT TestClientErrorHandling1151=== RUN TestClientErrorHandling/InvalidStorePath1152=== PAUSE TestClientErrorHandling/InvalidStorePath1153=== RUN TestClientErrorHandling/InvalidAuthToken1154=== PAUSE TestClientErrorHandling/InvalidAuthToken1155=== RUN TestClientErrorHandling/ServerNotAvailable1156=== PAUSE TestClientErrorHandling/ServerNotAvailable1157=== CONT TestClientCADerivations11582026/10/01 09:18:09 OK 20241026095416_initial_model.sql (10.21ms)11592026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)11602026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures11612026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.23ms)11622026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.74ms)1163--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.61s)1164=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT11652026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.89ms)11662026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.93ms)11672026/10/01 09:18:09 INFO lead: acquired remote=192.0.2.1:123411682026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.28ms)11692026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000011702026/10/01 09:18:09 INFO Received push request method=POST path=/api/pushes11712026/10/01 09:18:09 OK 1_commit_pending_closure.sql (12.51ms)11722026/10/01 09:18:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11732026/10/01 09:18:09 INFO Uploading jhfwq93xprm205c9n9da39x4c9jw0iiq-test-script (136B)11742026/10/01 09:18:09 INFO lead: released remote=192.0.2.1:12341175--- PASS: TestLeadElectsOneAndHandsOver (0.64s)1176=== CONT TestCacheStatsHandler11772026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.92ms)11782026/10/01 09:18:09 OK 3_commit_push.sql (1.91ms)11792026/10/01 09:18:09 goose: up to current file version: 311802026/10/01 09:18:09 INFO Aborted multipart uploads count=011812026-10-01 09:18:09.255 UTC [775] ERROR: relation "goose_db_version" does not exist at character 3611822026-10-01 09:18:09.255 UTC [775] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11832026/10/01 09:18:09 WARN Failed to register uploaded object key=log/n3dwvw7k45igmv598x2p1qx5wlq3xsf8-test-script.drv error="server returned 404: 404 page not found\n"11842026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period11852026/10/01 09:18:09 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=011862026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"11872026/10/01 09:18:09 INFO Vacuumed table table=pending_closures1188--- PASS: TestService_healthCheckHandler (0.65s)11892026/10/01 09:18:09 WARN Failed to register uploaded object key=jhfwq93xprm205c9n9da39x4c9jw0iiq.ls error="server returned 404: 404 page not found\n"1190=== CONT TestCompleteMultipartUnregistered11912026/10/01 09:18:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11922026/10/01 09:18:09 INFO Vacuumed table table=pending_objects11932026/10/01 09:18:09 INFO Signed narinfos id=1 count=111942026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads11952026/10/01 09:18:09 INFO Uploading 1 narinfos11962026/10/01 09:18:09 INFO Vacuumed table table=closures11972026/10/01 09:18:09 INFO Vacuumed table table=objects11982026-10-01 09:18:09.266 UTC [779] ERROR: relation "goose_db_version" does not exist at character 3611992026-10-01 09:18:09.266 UTC [779] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12002026/10/01 09:18:09 INFO Received complete push request method=POST path=/api/pushes/1/complete12012026/10/01 09:18:09 WARN Failed to register uploaded object key=jhfwq93xprm205c9n9da39x4c9jw0iiq.narinfo error="server returned 404: 404 page not found\n"1202--- PASS: TestGCMetrics (0.66s)1203=== CONT TestService_AuthMiddleware_OIDC12042026/10/01 09:18:09 OK 20241026095416_initial_model.sql (11.56ms)12052026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.39ms)12062026-10-01 09:18:09.280 UTC [783] ERROR: relation "goose_db_version" does not exist at character 3612072026-10-01 09:18:09.280 UTC [783] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12082026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.19ms)12092026/10/01 09:18:09 INFO Upload complete. (96ms)12102026/10/01 09:18:09 OK 20241026095416_initial_model.sql (11.16ms)1211=== NAME TestClientWithDependencies1212 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3639075796/001/store) requires matching store prefix12132026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.34ms)12142026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.18ms)12152026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.28ms)12162026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.2ms)1217--- PASS: TestClientWithDependencies (0.68s)1218=== CONT TestService_verifyS3Integrity12192026/10/01 09:18:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33833/oidc12202026/10/01 09:18:09 OK 20241026095416_initial_model.sql (9.71ms)12212026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.19ms)12222026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.7ms)12232026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (3.2ms)12242026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (3.9ms)12252026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000012262026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.79ms)12272026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.6ms)12282026/10/01 09:18:09 OK 1_commit_pending_closure.sql (3.67ms)12292026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.3ms)12302026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.13ms)12312026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.49ms)12322026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000012332026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.54ms)12342026/10/01 09:18:09 OK 3_commit_push.sql (1.72ms)12352026/10/01 09:18:09 goose: up to current file version: 312362026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.57ms)12372026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.19ms)12382026/10/01 09:18:09 OK 2_object_stats_trigger.sql (11.58ms)12392026/10/01 09:18:09 INFO Aborted multipart uploads count=012402026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period12412026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (14.35ms)12422026/10/01 09:18:09 OK 3_commit_push.sql (5.55ms)12432026/10/01 09:18:09 goose: up to current file version: 312442026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (4.03ms)12452026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000012462026/10/01 09:18:09 OK 1_commit_pending_closure.sql (3.59ms)12472026-10-01 09:18:09.336 UTC [790] ERROR: relation "goose_db_version" does not exist at character 3612482026-10-01 09:18:09.336 UTC [790] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12492026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.17ms)12502026/10/01 09:18:09 OK 3_commit_push.sql (2.01ms)12512026/10/01 09:18:09 goose: up to current file version: 312522026/10/01 09:18:09 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=012532026/10/01 09:18:09 INFO Vacuumed table table=pending_closures12542026/10/01 09:18:09 INFO Vacuumed table table=pending_objects12552026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads12562026/10/01 09:18:09 INFO Vacuumed table table=closures12572026-10-01 09:18:09.351 UTC [792] ERROR: relation "goose_db_version" does not exist at character 3612582026-10-01 09:18:09.351 UTC [792] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12592026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures12602026/10/01 09:18:09 OK 20241026095416_initial_model.sql (10.13ms)12612026/10/01 09:18:09 INFO Vacuumed table table=objects12622026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.78ms)1263--- PASS: TestGCSweepDeliversEachKeyOnce (0.73s)1264=== CONT TestService_ReadScope_PublicByDefault12652026/10/01 09:18:09 OK 20251218171726_add_pins.sql (2.8ms)12662026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.17ms)12672026/10/01 09:18:09 OK 20241026095416_initial_model.sql (9.14ms)12682026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.88ms)12692026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)12702026-10-01 09:18:09.368 UTC [811] ERROR: relation "goose_db_version" does not exist at character 3612712026-10-01 09:18:09.368 UTC [811] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12722026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.21ms)12732026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.14ms)12742026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.22ms)12752026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000012762026-10-01 09:18:09.372 UTC [815] ERROR: relation "goose_db_version" does not exist at character 3612772026-10-01 09:18:09.372 UTC [815] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12782026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.34ms)12792026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.33ms)12802026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.51ms)12812026/10/01 09:18:09 OK 3_commit_push.sql (1.68ms)12822026/10/01 09:18:09 goose: up to current file version: 312832026/10/01 09:18:09 INFO Aborted multipart uploads count=012842026/10/01 09:18:09 OK 20260905000000_add_claims.sql (13ms)12852026/10/01 09:18:09 OK 20241026095416_initial_model.sql (14.62ms)12862026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.37ms)12872026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period12882026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (3.18ms)1289--- PASS: TestGCBugBareHashReferences (0.78s)1290=== CONT TestService_createPendingClosureHandler12912026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures12922026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (3.26ms)12932026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000012942026/10/01 09:18:09 OK 20241026095416_initial_model.sql (10.23ms)12952026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.88ms)12962026/10/01 09:18:09 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=012972026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.58ms)12982026/10/01 09:18:09 INFO Vacuumed table table=pending_closures12992026/10/01 09:18:09 INFO Vacuumed table table=pending_objects13002026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.51ms)13012026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads13022026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.5ms)13032026/10/01 09:18:09 INFO Vacuumed table table=closures13042026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (3.61ms)13052026/10/01 09:18:09 OK 3_commit_push.sql (918.3µs)13062026/10/01 09:18:09 goose: up to current file version: 313072026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.31ms)13082026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.11ms)13092026/10/01 09:18:09 INFO Vacuumed table table=objects13102026-10-01 09:18:09.406 UTC [836] ERROR: relation "goose_db_version" does not exist at character 3613112026-10-01 09:18:09.406 UTC [836] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13122026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.65ms)13132026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (3.63ms)13142026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (1.8ms)13152026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000013162026/10/01 09:18:09 INFO Aborted multipart uploads count=013172026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.28ms)13182026-10-01 09:18:09.412 UTC [837] ERROR: relation "goose_db_version" does not exist at character 3613192026-10-01 09:18:09.412 UTC [837] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13202026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period13212026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.12ms)13222026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.3ms)13232026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.74ms)13242026/10/01 09:18:09 OK 3_commit_push.sql (1.67ms)13252026/10/01 09:18:09 goose: up to current file version: 313262026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.68ms)13272026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000013282026/10/01 09:18:09 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=013292026/10/01 09:18:09 INFO Vacuumed table table=pending_closures13302026/10/01 09:18:09 INFO Vacuumed table table=pending_objects13312026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads13322026/10/01 09:18:09 INFO Vacuumed table table=closures13332026/10/01 09:18:09 OK 1_commit_pending_closure.sql (4.17ms)13342026/10/01 09:18:09 INFO Vacuumed table table=objects13352026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.14ms)13362026/10/01 09:18:09 OK 20241026095416_initial_model.sql (9.79ms)1337--- PASS: TestSweepSkipsRowsLockedByPush (0.81s)1338=== CONT TestService_RequireScope_OIDC13392026/10/01 09:18:09 OK 3_commit_push.sql (1.37ms)13402026/10/01 09:18:09 goose: up to current file version: 313412026/10/01 09:18:09 OK 20241026095416_initial_model.sql (15.87ms)13422026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.66ms)13432026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (3.04ms)13442026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.73ms)13452026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.54ms)13462026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (3.62ms)13472026/10/01 09:18:09 OK 20260905000000_add_claims.sql (2.86ms)13482026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (1.58ms)13492026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.38ms)13502026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (1.91ms)13512026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000013522026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.7ms)13532026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.21ms)13542026-10-01 09:18:09.453 UTC [875] ERROR: relation "goose_db_version" does not exist at character 3613552026-10-01 09:18:09.453 UTC [875] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13562026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.55ms)13572026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.88ms)13582026/10/01 09:18:09 OK 3_commit_push.sql (1.25ms)13592026/10/01 09:18:09 goose: up to current file version: 313602026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.59ms)13612026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000013622026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.57ms)13632026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.5ms)13642026/10/01 09:18:09 OK 3_commit_push.sql (1.43ms)13652026/10/01 09:18:09 goose: up to current file version: 313662026/10/01 09:18:09 OK 20241026095416_initial_model.sql (7.75ms)13672026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)13682026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.24ms)13692026/10/01 09:18:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40533/oidc13702026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (3.35ms)13712026/10/01 09:18:09 OK 20260905000000_add_claims.sql (2.94ms)13722026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (1.79ms)13732026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (1.74ms)13742026/10/01 09:18:09 goose: successfully migrated database to version: 202609231200001375--- PASS: TestGetExistingObjectsLocksRows (0.86s)1376=== CONT TestService_cleanupPendingClosuresHandler13772026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.11ms)13782026/10/01 09:18:09 OK 2_object_stats_trigger.sql (765.24µs)13792026/10/01 09:18:09 OK 3_commit_push.sql (1.01ms)13802026/10/01 09:18:09 goose: up to current file version: 313812026-10-01 09:18:09.493 UTC [917] ERROR: relation "goose_db_version" does not exist at character 3613822026-10-01 09:18:09.493 UTC [917] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1383=== NAME TestPinProtectsFromGC1384 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC915262911/001/store/sdy5nk1dw20x027zjwpr94nv0p0z2gpy-pinned-file.txt1385 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC915262911/001/store/zg3hya2i5pxzwb3qxk2yl11lz3n8d2jh-unpinned-file.txt13862026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures13872026/10/01 09:18:09 OK 20241026095416_initial_model.sql (8.57ms)13882026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.89ms)13892026/10/01 09:18:09 OK 20251218171726_add_pins.sql (2.61ms)13902026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (3.87ms)13912026/10/01 09:18:09 INFO Received push request method=POST path=/api/pushes13922026/10/01 09:18:09 OK 20260905000000_add_claims.sql (2.93ms)13932026/10/01 09:18:09 INFO Aborted multipart uploads count=013942026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.57ms)13952026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period13962026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.08ms)13972026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000013982026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.21ms)13992026/10/01 09:18:09 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14002026/10/01 09:18:09 INFO Uploading bq0ach089mk22q5mlxxikij735n7nrq4-a (216B)14012026/10/01 09:18:09 INFO Uploading 41rqvh9h8x2dygamavb6w4n57rwfgnzf-shared-dep (136B)14022026/10/01 09:18:09 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=014032026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.26ms)14042026/10/01 09:18:09 WARN Failed to register uploaded object key=asdx0m2ffrb26c69v28iqsnm9zzz9ysd.ls error="server returned 404: 404 page not found\n"14052026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/0bxkchq1ys7cdy1y8y0qi2q90piah1j4zfncalls6mfddd2gx2h8.nar.zst error="server returned 404: 404 page not found\n"14062026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14072026/10/01 09:18:09 WARN Failed to register uploaded object key=bq0ach089mk22q5mlxxikij735n7nrq4.ls error="server returned 404: 404 page not found\n"14082026/10/01 09:18:09 WARN Failed to register uploaded object key=41rqvh9h8x2dygamavb6w4n57rwfgnzf.ls error="server returned 404: 404 page not found\n"14092026/10/01 09:18:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14102026/10/01 09:18:09 INFO Signed narinfos id=1 count=314112026/10/01 09:18:09 INFO Uploading 3 narinfos14122026/10/01 09:18:09 OK 3_commit_push.sql (9.29ms)14132026/10/01 09:18:09 goose: up to current file version: 314142026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures1415--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.92s)1416=== CONT TestUploadHandlersRejectOversizedBody14172026/10/01 09:18:09 INFO Vacuumed table table=pending_closures14182026/10/01 09:18:09 WARN Failed to register uploaded object key=41rqvh9h8x2dygamavb6w4n57rwfgnzf.narinfo error="server returned 404: 404 page not found\n"14192026/10/01 09:18:09 WARN Failed to register uploaded object key=asdx0m2ffrb26c69v28iqsnm9zzz9ysd.narinfo error="server returned 404: 404 page not found\n"14202026/10/01 09:18:09 INFO Received complete push request method=POST path=/api/pushes/1/complete14212026/10/01 09:18:09 WARN Failed to register uploaded object key=bq0ach089mk22q5mlxxikij735n7nrq4.narinfo error="server returned 404: 404 page not found\n"14222026/10/01 09:18:09 INFO Vacuumed table table=pending_objects14232026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads14242026/10/01 09:18:09 INFO Vacuumed table table=closures14252026/10/01 09:18:09 INFO Vacuumed table table=objects1426--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.87s)1427=== CONT TestIsValidCachePath1428=== RUN TestIsValidCachePath/narinfo1429=== PAUSE TestIsValidCachePath/narinfo1430=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1431=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars14322026/10/01 09:18:09 INFO Upload complete. (81ms)1433=== RUN TestIsValidCachePath/nar_zst1434=== PAUSE TestIsValidCachePath/nar_zst1435=== RUN TestIsValidCachePath/nar_xz1436=== PAUSE TestIsValidCachePath/nar_xz1437=== RUN TestIsValidCachePath/nar_bz21438=== PAUSE TestIsValidCachePath/nar_bz21439=== RUN TestIsValidCachePath/nar_uncompressed1440=== PAUSE TestIsValidCachePath/nar_uncompressed1441=== RUN TestIsValidCachePath/ls14422026/10/01 09:18:09 INFO Received push request method=POST path=/api/pushes1443=== PAUSE TestIsValidCachePath/ls1444=== RUN TestIsValidCachePath/log1445=== PAUSE TestIsValidCachePath/log1446=== RUN TestIsValidCachePath/realisation1447=== PAUSE TestIsValidCachePath/realisation1448=== RUN TestIsValidCachePath/nix-cache-info1449=== PAUSE TestIsValidCachePath/nix-cache-info1450=== RUN TestIsValidCachePath/index.html1451=== PAUSE TestIsValidCachePath/index.html1452=== RUN TestIsValidCachePath/traversal_parent1453=== PAUSE TestIsValidCachePath/traversal_parent1454=== RUN TestIsValidCachePath/traversal_in_middle1455=== PAUSE TestIsValidCachePath/traversal_in_middle1456=== RUN TestIsValidCachePath/invalid_char_e1457=== PAUSE TestIsValidCachePath/invalid_char_e1458--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.00s)1459=== CONT TestUploadHandlersRejectInvalidKeys1460=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1461=== RUN TestIsValidCachePath/invalid_char_u1462=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1463=== NAME TestClientPushesUseOnePush1464 client_pushes_test.go:97: Retrieved narinfo from S3:1465 StorePath: /build/TestClientPushesUseOnePush2456912185/001/store/41rqvh9h8x2dygamavb6w4n57rwfgnzf-shared-dep1466 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1467 Compression: zstd1468 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821469 NarSize: 1361470 References: 1471 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1472=== PAUSE TestIsValidCachePath/invalid_char_u1473=== RUN TestIsValidCachePath/random_path1474=== PAUSE TestIsValidCachePath/random_path1475=== RUN TestIsValidCachePath/empty1476=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1477--- PASS: TestCommitRacingPendingCleanupKeepsObjects (1.01s)1478=== CONT TestReadRedirectKeepsNarinfoProxied1479=== PAUSE TestIsValidCachePath/empty1480=== RUN TestIsValidCachePath/leading_slash1481=== PAUSE TestIsValidCachePath/leading_slash1482=== RUN TestIsValidCachePath/wrong_extension1483=== PAUSE TestIsValidCachePath/wrong_extension1484=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1485=== RUN TestIsValidCachePath/short_hash1486=== PAUSE TestIsValidCachePath/short_hash1487=== CONT TestIsValidUploadKey1488=== RUN TestIsValidUploadKey/narinfo1489=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1490=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1491=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1492=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1493=== PAUSE TestIsValidUploadKey/narinfo1494=== RUN TestIsValidUploadKey/nar_zst1495=== PAUSE TestIsValidUploadKey/nar_zst1496=== RUN TestIsValidUploadKey/nar_xz1497=== CONT TestReadRedirectNar1498=== PAUSE TestIsValidUploadKey/nar_xz1499=== NAME TestClientPushesUseOnePush1500 client_pushes_test.go:97: Retrieved narinfo from S3:1501 StorePath: /build/TestClientPushesUseOnePush2456912185/001/store/bq0ach089mk22q5mlxxikij735n7nrq4-a1502 URL: nar/0bxkchq1ys7cdy1y8y0qi2q90piah1j4zfncalls6mfddd2gx2h8.nar.zst1503 Compression: zstd1504 NarHash: sha256:0bxkchq1ys7cdy1y8y0qi2q90piah1j4zfncalls6mfddd2gx2h81505 NarSize: 2161506 References: /build/TestClientPushesUseOnePush2456912185/001/store/41rqvh9h8x2dygamavb6w4n57rwfgnzf-shared-dep1507 CA: text:sha256:0fj8acfmmq3nm7m3lpz55vjapp00y3szkjpyi021zicwqz4zciwd1508=== RUN TestIsValidUploadKey/nar_plain1509=== PAUSE TestIsValidUploadKey/nar_plain1510=== RUN TestIsValidUploadKey/listing1511=== PAUSE TestIsValidUploadKey/listing1512=== RUN TestIsValidUploadKey/build_log1513=== PAUSE TestIsValidUploadKey/build_log1514=== RUN TestIsValidUploadKey/build_log_home-manager_file1515=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1516=== RUN TestIsValidUploadKey/build_log_plus_in_name1517=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1518=== RUN TestIsValidUploadKey/build_log_question_mark15192026/10/01 09:18:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1520=== PAUSE TestIsValidUploadKey/build_log_question_mark15212026/10/01 09:18:09 INFO Uploading sdy5nk1dw20x027zjwpr94nv0p0z2gpy-pinned-file.txt (128B)1522=== RUN TestIsValidUploadKey/build_log_equals1523=== PAUSE TestIsValidUploadKey/build_log_equals1524=== RUN TestIsValidUploadKey/realisation1525=== PAUSE TestIsValidUploadKey/realisation1526=== RUN TestIsValidUploadKey/realisation_plus_in_output1527=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1528=== RUN TestIsValidUploadKey/nix-cache-info1529=== PAUSE TestIsValidUploadKey/nix-cache-info1530=== RUN TestIsValidUploadKey/index.html15312026-10-01 09:18:09.631 UTC [1026] ERROR: relation "goose_db_version" does not exist at character 3615322026-10-01 09:18:09.631 UTC [1026] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1533=== PAUSE TestIsValidUploadKey/index.html1534=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1535=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1536=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1537=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1538=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1539=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1540=== RUN TestIsValidUploadKey/traversal1541=== PAUSE TestIsValidUploadKey/traversal15422026-10-01 09:18:09.631 UTC [1027] ERROR: relation "goose_db_version" does not exist at character 3615432026-10-01 09:18:09.631 UTC [1027] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1544=== RUN TestIsValidUploadKey/traversal_nar1545=== PAUSE TestIsValidUploadKey/traversal_nar1546=== RUN TestIsValidUploadKey/absolute1547=== PAUSE TestIsValidUploadKey/absolute1548=== NAME TestClientPushesUseOnePush1549 client_pushes_test.go:97: Retrieved narinfo from S3:1550 StorePath: /build/TestClientPushesUseOnePush2456912185/001/store/asdx0m2ffrb26c69v28iqsnm9zzz9ysd-b1551 URL: nar/0bxkchq1ys7cdy1y8y0qi2q90piah1j4zfncalls6mfddd2gx2h8.nar.zst1552 Compression: zstd1553 NarHash: sha256:0bxkchq1ys7cdy1y8y0qi2q90piah1j4zfncalls6mfddd2gx2h81554 NarSize: 2161555 References: /build/TestClientPushesUseOnePush2456912185/001/store/41rqvh9h8x2dygamavb6w4n57rwfgnzf-shared-dep1556 CA: text:sha256:0fj8acfmmq3nm7m3lpz55vjapp00y3szkjpyi021zicwqz4zciwd1557=== RUN TestIsValidUploadKey/empty_key1558=== PAUSE TestIsValidUploadKey/empty_key1559=== RUN TestIsValidUploadKey/unknown_type1560=== PAUSE TestIsValidUploadKey/unknown_type1561=== CONT TestProxyWriteTimeout1562=== RUN TestProxyWriteTimeout/narinfo1563=== PAUSE TestProxyWriteTimeout/narinfo1564=== RUN TestProxyWriteTimeout/1_GiB_nar1565=== PAUSE TestProxyWriteTimeout/1_GiB_nar1566=== RUN TestProxyWriteTimeout/10_GiB_nar1567=== PAUSE TestProxyWriteTimeout/10_GiB_nar1568=== RUN TestProxyWriteTimeout/unknown_size1569=== PAUSE TestProxyWriteTimeout/unknown_size1570=== CONT TestReadProxyDisabled15712026/10/01 09:18:09 INFO Aborted multipart uploads count=015722026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15732026/10/01 09:18:09 WARN Failed to register uploaded object key=sdy5nk1dw20x027zjwpr94nv0p0z2gpy.ls error="server returned 404: 404 page not found\n"15742026/10/01 09:18:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15752026/10/01 09:18:09 INFO Signed narinfos id=1 count=115762026/10/01 09:18:09 INFO Uploading 1 narinfos15772026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period1578--- PASS: TestClientPushesUseOnePush (1.02s)1579=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle15802026/10/01 09:18:09 INFO Received complete push request method=POST path=/api/pushes/1/complete15812026/10/01 09:18:09 WARN Failed to register uploaded object key=sdy5nk1dw20x027zjwpr94nv0p0z2gpy.narinfo error="server returned 404: 404 page not found\n"15822026/10/01 09:18:09 OK 20241026095416_initial_model.sql (8.12ms)15832026/10/01 09:18:09 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."15842026/10/01 09:18:09 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."15852026/10/01 09:18:09 OK 20241026095416_initial_model.sql (8.51ms)15862026/10/01 09:18:09 INFO Upload complete. (108ms)15872026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.3ms)15882026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.2ms)1589--- PASS: TestFailedS3DeleteKeepsTombstone (1.03s)1590=== CONT TestReadProxyRootRedirectsToIndexHTML15912026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures15922026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.09ms)15932026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.35ms)15942026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (3.88ms)15952026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.21ms)15962026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.82ms)15972026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.7ms)15982026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.87ms)15992026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (4.04ms)16002026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.04ms)16012026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000016022026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.06ms)16032026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000016042026/10/01 09:18:09 OK 1_commit_pending_closure.sql (1.93ms)16052026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.01ms)16062026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.34ms)16072026/10/01 09:18:09 INFO Aborted multipart uploads count=016082026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.73ms)16092026/10/01 09:18:09 OK 3_commit_push.sql (1.8ms)16102026/10/01 09:18:09 goose: up to current file version: 316112026/10/01 09:18:09 OK 3_commit_push.sql (1.89ms)16122026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period16132026/10/01 09:18:09 goose: up to current file version: 316142026/10/01 09:18:09 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=016152026/10/01 09:18:09 INFO Vacuumed table table=pending_closures16162026/10/01 09:18:09 INFO Vacuumed table table=pending_objects16172026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads16182026/10/01 09:18:09 INFO Vacuumed table table=closures16192026/10/01 09:18:09 INFO Vacuumed table table=objects1620--- PASS: TestGCSweepSkipsPendingObjects (0.61s)1621=== CONT TestReadProxyConditionalGet16222026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures1623--- PASS: TestReadProxyRangeRequest (0.53s)1624=== CONT TestSkippedUploadsHandler16252026/10/01 09:18:09 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001626--- PASS: TestSkippedUploadsHandler (0.00s)1627=== CONT TestReadProxyHead1628=== NAME TestClientMultipleUploads1629 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads2696676936/001/store/c59rfr7rxw3drxg4ikhfccvidkmc7059-test-file-0.txt16302026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures16312026/10/01 09:18:09 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)1632=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure16332026/10/01 09:18:09 INFO Uploading 6zqbcj173178d3i3hdh4q3pjb4nc02v9-a (216B)1634=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1635=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart16362026/10/01 09:18:09 INFO Uploading xibbir91dqj3sw6s3kbcsgnfm2sjnhc6-shared-dep (136B)1637=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1638=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1639=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1640=== CONT TestParseSize1641--- PASS: TestParseSize (0.00s)1642=== CONT TestReadProxyInvalidPath16432026/10/01 09:18:09 WARN Failed to register uploaded object key=b6f0id0klzcjr6v8p745b6sl539l91vh.ls error="server returned 404: 404 page not found\n"16442026/10/01 09:18:09 INFO Received push request method=POST path=/api/pushes16452026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16462026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/0f39kvsff436f2qavwlsisjlmgf250k8yqin479wrj6wczwmsdyv.nar.zst error="server returned 404: 404 page not found\n"1647=== NAME TestClientIntegration1648 client_integration_test.go:286: Created store path: /build/TestClientIntegration2359903848/002/store/pc2zhla2gxfsy74c6myrhjd6rvdjx9yh-test-file.txt16492026/10/01 09:18:09 WARN Failed to register uploaded object key=xibbir91dqj3sw6s3kbcsgnfm2sjnhc6.ls error="server returned 404: 404 page not found\n"16502026/10/01 09:18:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16512026/10/01 09:18:09 INFO Signed narinfos id=1 count=216522026/10/01 09:18:09 WARN Failed to register uploaded object key=6zqbcj173178d3i3hdh4q3pjb4nc02v9.ls error="server returned 404: 404 page not found\n"16532026/10/01 09:18:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16542026/10/01 09:18:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16552026/10/01 09:18:09 INFO Uploading zg3hya2i5pxzwb3qxk2yl11lz3n8d2jh-unpinned-file.txt (128B)16562026/10/01 09:18:09 INFO Signed narinfos id=2 count=216572026/10/01 09:18:09 INFO Uploading 4 narinfos16582026/10/01 09:18:09 WARN Failed to register uploaded object key=xibbir91dqj3sw6s3kbcsgnfm2sjnhc6.narinfo error="server returned 404: 404 page not found\n"16592026/10/01 09:18:09 WARN Failed to register uploaded object key=b6f0id0klzcjr6v8p745b6sl539l91vh.narinfo error="server returned 404: 404 page not found\n"16602026/10/01 09:18:09 WARN Failed to register uploaded object key=6zqbcj173178d3i3hdh4q3pjb4nc02v9.narinfo error="server returned 404: 404 page not found\n"16612026/10/01 09:18:09 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16622026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16632026/10/01 09:18:09 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16642026/10/01 09:18:09 WARN Failed to register uploaded object key=xibbir91dqj3sw6s3kbcsgnfm2sjnhc6.narinfo error="server returned 404: 404 page not found\n"16652026/10/01 09:18:09 WARN Failed to register uploaded object key=zg3hya2i5pxzwb3qxk2yl11lz3n8d2jh.ls error="server returned 404: 404 page not found\n"16662026/10/01 09:18:09 INFO Signed narinfos id=2 count=116672026/10/01 09:18:09 INFO Uploading 1 narinfos16682026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures16692026/10/01 09:18:09 INFO Received complete push request method=POST path=/api/pushes/2/complete16702026/10/01 09:18:09 WARN Failed to register uploaded object key=zg3hya2i5pxzwb3qxk2yl11lz3n8d2jh.narinfo error="server returned 404: 404 page not found\n"16712026/10/01 09:18:09 INFO Completed upload id=216722026/10/01 09:18:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16732026/10/01 09:18:09 INFO Upload complete. (62ms)16742026/10/01 09:18:09 INFO Completed upload id=116752026/10/01 09:18:09 INFO Upload complete. (95ms)1676=== NAME TestClientFallsBackToClosures1677 client_pushes_test.go:112: Retrieved narinfo from S3:1678 StorePath: /build/TestClientFallsBackToClosures1463236210/001/store/xibbir91dqj3sw6s3kbcsgnfm2sjnhc6-shared-dep1679 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1680 Compression: zstd1681 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821682 NarSize: 1361683 References: 1684 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1685=== NAME TestClientMultipleUploads1686 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads2696676936/001/store/k4dal0aci6xlh4sw39lc6vd8374lzmwa-test-file-1.txt16872026-10-01 09:18:09.753 UTC [1210] ERROR: relation "goose_db_version" does not exist at character 3616882026-10-01 09:18:09.753 UTC [1210] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1689=== NAME TestClientFallsBackToClosures1690 client_pushes_test.go:112: Retrieved narinfo from S3:1691 StorePath: /build/TestClientFallsBackToClosures1463236210/001/store/6zqbcj173178d3i3hdh4q3pjb4nc02v9-a1692 URL: nar/0f39kvsff436f2qavwlsisjlmgf250k8yqin479wrj6wczwmsdyv.nar.zst1693 Compression: zstd1694 NarHash: sha256:0f39kvsff436f2qavwlsisjlmgf250k8yqin479wrj6wczwmsdyv1695 NarSize: 2161696 References: /build/TestClientFallsBackToClosures1463236210/001/store/xibbir91dqj3sw6s3kbcsgnfm2sjnhc6-shared-dep1697 CA: text:sha256:06dmafh4nwx298qpc1z56avbx7l8chry3bf36673b067dhnnfx0a16982026-10-01 09:18:09.755 UTC [1211] ERROR: relation "goose_db_version" does not exist at character 3616992026-10-01 09:18:09.755 UTC [1211] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1700 client_pushes_test.go:112: Retrieved narinfo from S3:1701 StorePath: /build/TestClientFallsBackToClosures1463236210/001/store/b6f0id0klzcjr6v8p745b6sl539l91vh-b1702 URL: nar/0f39kvsff436f2qavwlsisjlmgf250k8yqin479wrj6wczwmsdyv.nar.zst1703 Compression: zstd1704 NarHash: sha256:0f39kvsff436f2qavwlsisjlmgf250k8yqin479wrj6wczwmsdyv1705 NarSize: 2161706 References: /build/TestClientFallsBackToClosures1463236210/001/store/xibbir91dqj3sw6s3kbcsgnfm2sjnhc6-shared-dep1707 CA: text:sha256:06dmafh4nwx298qpc1z56avbx7l8chry3bf36673b067dhnnfx0a1708--- PASS: TestClientFallsBackToClosures (1.14s)1709=== CONT TestService_Rustfstest1710--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.54s)1711=== CONT TestReadProxy40417122026-10-01 09:18:09.764 UTC [1263] ERROR: relation "goose_db_version" does not exist at character 3617132026-10-01 09:18:09.764 UTC [1263] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17142026/10/01 09:18:09 OK 20241026095416_initial_model.sql (8.15ms)17152026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)17162026-10-01 09:18:09.771 UTC [1268] ERROR: relation "goose_db_version" does not exist at character 3617172026-10-01 09:18:09.771 UTC [1268] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17182026/10/01 09:18:09 OK 20241026095416_initial_model.sql (10.72ms)17192026/10/01 09:18:09 OK 20251218171726_add_pins.sql (2.93ms)17202026/10/01 09:18:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17212026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (9.57ms)17222026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (11.07ms)17232026/10/01 09:18:09 OK 20241026095416_initial_model.sql (13.62ms)1724--- PASS: TestCacheStatsHandler (0.53s)1725=== CONT TestPresignedUploadRegisteredBeforeCommit17262026/10/01 09:18:09 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1727--- PASS: TestCompleteMultipartUnregistered (0.52s)1728=== CONT TestReadProxyNarStreaming17292026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.78ms)17302026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.51ms)1731=== NAME TestClientMultipleUploads1732 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads2696676936/001/store/p0fj5vp5mr5ynwmsy80p4w4ycr32x3a8-test-file-2.txt17332026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.01ms)17342026/10/01 09:18:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures17352026-10-01 09:18:09.789 UTC [1274] ERROR: relation "goose_db_version" does not exist at character 3617362026-10-01 09:18:09.789 UTC [1274] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17372026/10/01 09:18:09 INFO Garbage collection started17382026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.4ms)17392026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.61ms)17402026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (4.29ms)17412026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.67ms)17422026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (4.32ms)17432026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000017442026/10/01 09:18:09 OK 20260905000000_add_claims.sql (6.43ms)17452026/10/01 09:18:09 OK 20241026095416_initial_model.sql (13.17ms)17462026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures17472026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.31ms)17482026/10/01 09:18:09 OK 1_commit_pending_closure.sql (3.15ms)17492026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.78ms)17502026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.37ms)17512026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)17522026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.66ms)17532026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.48ms)17542026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000017552026/10/01 09:18:09 INFO Received push request method=POST path=/api/pushes17562026/10/01 09:18:09 OK 3_commit_push.sql (1.52ms)17572026/10/01 09:18:09 goose: up to current file version: 317582026/10/01 09:18:09 INFO Received push request method=POST path=/api/pushes17592026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.46ms)17602026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000017612026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.34ms)17622026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.68ms)17632026/10/01 09:18:09 OK 20241026095416_initial_model.sql (10.95ms)17642026/10/01 09:18:09 INFO Aborted multipart uploads count=017652026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.53ms)17662026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.69ms)17672026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.97ms)17682026/10/01 09:18:09 OK 3_commit_push.sql (1.89ms)17692026/10/01 09:18:09 goose: up to current file version: 317702026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (3.86ms)17712026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.84ms)17722026/10/01 09:18:09 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17732026/10/01 09:18:09 INFO Uploading pc2zhla2gxfsy74c6myrhjd6rvdjx9yh-test-file.txt (152B)17742026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period17752026/10/01 09:18:09 OK 3_commit_push.sql (2.41ms)17762026/10/01 09:18:09 goose: up to current file version: 317772026/10/01 09:18:09 WARN Failed to register uploaded object key=pc2zhla2gxfsy74c6myrhjd6rvdjx9yh.ls error="server returned 404: 404 page not found\n"17782026/10/01 09:18:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17792026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"17802026/10/01 09:18:09 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17812026/10/01 09:18:09 INFO Uploading 2xgrvr1diiijdhchcjacg1hk31s8npql-top (224B)17822026/10/01 09:18:09 INFO Uploading mhqxnlb00wwk0mkivas8w5jywmdiym6i-shared-dep (136B)17832026/10/01 09:18:09 INFO Signed narinfos id=1 count=117842026/10/01 09:18:09 INFO Uploading 1 narinfos17852026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.61ms)17862026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.65ms)1787=== NAME TestClientCADerivations1788 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3390725823/001/store/mx8dk8b403y5ya8k1289q9axvcnrxair-ca-test17892026/10/01 09:18:09 INFO Received complete push request method=POST path=/api/pushes/1/complete17902026/10/01 09:18:09 WARN Failed to register uploaded object key=pc2zhla2gxfsy74c6myrhjd6rvdjx9yh.narinfo error="server returned 404: 404 page not found\n"17912026/10/01 09:18:09 WARN Failed to register uploaded object key=2xgrvr1diiijdhchcjacg1hk31s8npql.ls error="server returned 404: 404 page not found\n"17922026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17932026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.55ms)17942026/10/01 09:18:09 WARN Failed to register uploaded object key=mhqxnlb00wwk0mkivas8w5jywmdiym6i.ls error="server returned 404: 404 page not found\n"17952026/10/01 09:18:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17962026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)17972026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/1c7r7vd2pnxngvxaj9g9b0f5zqcvx9mljxqgjb4lgxjbwn52p3xx.nar.zst error="server returned 404: 404 page not found\n"17982026/10/01 09:18:09 INFO Signed narinfos id=1 count=21799=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token18002026/10/01 09:18:09 INFO Uploading 2 narinfos1801=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1802=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1803=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1804=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1805=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1806=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1807=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1808=== CONT TestCompletedNarNotReofferedAcrossClosures18092026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.61ms)18102026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000018112026/10/01 09:18:09 INFO Received complete push request method=POST path=/api/pushes/1/complete18122026/10/01 09:18:09 WARN Failed to register uploaded object key=2xgrvr1diiijdhchcjacg1hk31s8npql.narinfo error="server returned 404: 404 page not found\n"18132026/10/01 09:18:09 WARN Failed to register uploaded object key=mhqxnlb00wwk0mkivas8w5jywmdiym6i.narinfo error="server returned 404: 404 page not found\n"18142026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.7ms)18152026/10/01 09:18:09 OK 20260905000000_add_claims.sql (5.83ms)18162026/10/01 09:18:09 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=018172026/10/01 09:18:09 OK 2_object_stats_trigger.sql (2.06ms)18182026/10/01 09:18:09 OK 3_commit_push.sql (3.75ms)18192026/10/01 09:18:09 goose: up to current file version: 318202026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (5.53ms)18212026/10/01 09:18:09 INFO Upload complete. (68ms)18222026/10/01 09:18:09 INFO Vacuumed table table=pending_closures18232026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (3.14ms)18242026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000018252026/10/01 09:18:09 INFO Upload complete. (76ms)1826=== NAME TestClientSharedPathCommittedMidPush1827 client_integration_test.go:680: Retrieved narinfo from S3:1828 StorePath: /build/TestClientSharedPathCommittedMidPush124951427/001/store/mhqxnlb00wwk0mkivas8w5jywmdiym6i-shared-dep1829 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1830 Compression: zstd1831 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821832 NarSize: 1361833 References: 1834 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1835 client_integration_test.go:680: Retrieved narinfo from S3:1836 StorePath: /build/TestClientSharedPathCommittedMidPush124951427/001/store/2xgrvr1diiijdhchcjacg1hk31s8npql-top1837 URL: nar/1c7r7vd2pnxngvxaj9g9b0f5zqcvx9mljxqgjb4lgxjbwn52p3xx.nar.zst1838 Compression: zstd1839 NarHash: sha256:1c7r7vd2pnxngvxaj9g9b0f5zqcvx9mljxqgjb4lgxjbwn52p3xx1840 NarSize: 2241841 References: /build/TestClientSharedPathCommittedMidPush124951427/001/store/mhqxnlb00wwk0mkivas8w5jywmdiym6i-shared-dep1842 CA: text:sha256:0czz3rggfij1prp7vb45ddqv2n7ky6nx414nkhjmbq50ayx6bvkc1843--- PASS: TestService_ReadScope_PublicByDefault (0.49s)1844=== CONT TestReadProxyNarinfoAlreadyDecompressed1845--- PASS: TestClientSharedPathCommittedMidPush (0.83s)1846=== CONT TestCompleteMultipartUpload_ErrorButObjectExists18472026/10/01 09:18:09 OK 1_commit_pending_closure.sql (10.54ms)18482026/10/01 09:18:09 INFO Vacuumed table table=pending_objects18492026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.98ms)18502026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads18512026/10/01 09:18:09 OK 3_commit_push.sql (1.68ms)18522026/10/01 09:18:09 goose: up to current file version: 318532026-10-01 09:18:09.853 UTC [1390] ERROR: relation "goose_db_version" does not exist at character 3618542026-10-01 09:18:09.853 UTC [1390] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18552026-10-01 09:18:09.853 UTC [1388] ERROR: relation "goose_db_version" does not exist at character 3618562026-10-01 09:18:09.853 UTC [1388] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18572026/10/01 09:18:09 INFO Vacuumed table table=closures18582026/10/01 09:18:09 INFO Vacuumed table table=objects1859=== NAME TestClientCADerivations1860 client_ca_test.go:139: Found 1 dependencies (including self)1861--- PASS: TestPushWaitsForSweepHoldingRow (1.24s)1862=== CONT TestReadProxyNarinfo18632026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures18642026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures18652026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures18662026-10-01 09:18:09.867 UTC [1410] ERROR: relation "goose_db_version" does not exist at character 3618672026-10-01 09:18:09.867 UTC [1410] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18682026/10/01 09:18:09 INFO All 1 paths already cached18692026/10/01 09:18:09 INFO Received push request method=POST path=/api/pushes1870=== NAME TestClientIntegration1871 client_integration_test.go:312: Retrieved narinfo from S3:1872 StorePath: /build/TestClientIntegration2359903848/002/store/pc2zhla2gxfsy74c6myrhjd6rvdjx9yh-test-file.txt1873 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1874 Compression: zstd1875 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11876 NarSize: 1521877 References: 1878 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk118792026/10/01 09:18:09 OK 20241026095416_initial_model.sql (17.22ms)18802026/10/01 09:18:09 OK 20241026095416_initial_model.sql (16.8ms)18812026-10-01 09:18:09.878 UTC [1451] ERROR: relation "goose_db_version" does not exist at character 3618822026-10-01 09:18:09.878 UTC [1451] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1883 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1884 client_integration_test.go:313: Decompressed .ls content (64 bytes):1885 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1886 client_integration_test.go:316: Testing garbage collection...18872026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)18882026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.7ms)18892026/10/01 09:18:09 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18902026/10/01 09:18:09 INFO Uploading k4dal0aci6xlh4sw39lc6vd8374lzmwa-test-file-1.txt (160B)18912026/10/01 09:18:09 INFO Uploading c59rfr7rxw3drxg4ikhfccvidkmc7059-test-file-0.txt (160B)18922026/10/01 09:18:09 INFO Uploading p0fj5vp5mr5ynwmsy80p4w4ycr32x3a8-test-file-2.txt (160B)18932026/10/01 09:18:09 OK 20251218171726_add_pins.sql (5.54ms)18942026/10/01 09:18:09 OK 20251218171726_add_pins.sql (5.43ms)18952026/10/01 09:18:09 OK 20241026095416_initial_model.sql (11.39ms)18962026/10/01 09:18:09 INFO Received cleanup request method=DELETE path=/api/pending_closures18972026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.58ms)18982026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)18992026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.26ms)19002026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19012026/10/01 09:18:09 WARN Failed to register uploaded object key=p0fj5vp5mr5ynwmsy80p4w4ycr32x3a8.ls error="server returned 404: 404 page not found\n"19022026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19032026/10/01 09:18:09 WARN Failed to register uploaded object key=c59rfr7rxw3drxg4ikhfccvidkmc7059.ls error="server returned 404: 404 page not found\n"19042026/10/01 09:18:09 WARN Failed to register uploaded object key=k4dal0aci6xlh4sw39lc6vd8374lzmwa.ls error="server returned 404: 404 page not found\n"19052026/10/01 09:18:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19062026/10/01 09:18:09 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19072026/10/01 09:18:09 INFO Signed narinfos id=1 count=319082026/10/01 09:18:09 INFO Uploading 3 narinfos19092026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.35ms)19102026/10/01 09:18:09 INFO Aborted multipart uploads count=019112026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.38ms)19122026/10/01 09:18:09 INFO Received uploads request method=POST path=/api/pending_closures19132026/10/01 09:18:09 OK 20241026095416_initial_model.sql (12.23ms)19142026/10/01 09:18:09 WARN Failed to register uploaded object key=p0fj5vp5mr5ynwmsy80p4w4ycr32x3a8.narinfo error="server returned 404: 404 page not found\n"19152026/10/01 09:18:09 WARN Failed to register uploaded object key=k4dal0aci6xlh4sw39lc6vd8374lzmwa.narinfo error="server returned 404: 404 page not found\n"19162026/10/01 09:18:09 INFO Received complete push request method=POST path=/api/pushes/1/complete19172026/10/01 09:18:09 WARN Failed to register uploaded object key=c59rfr7rxw3drxg4ikhfccvidkmc7059.narinfo error="server returned 404: 404 page not found\n"19182026/10/01 09:18:09 OK 20260905000000_add_claims.sql (5.22ms)19192026-10-01 09:18:09.898 UTC [1454] ERROR: relation "goose_db_version" does not exist at character 3619202026-10-01 09:18:09.898 UTC [1454] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19212026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.98ms)19222026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (4.14ms)19232026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (1.66ms)19242026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.32ms)19252026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.83ms)19262026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000019272026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.5ms)19282026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.38ms)19292026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.18ms)19302026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000019312026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.43ms)19322026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (2.51ms)19332026/10/01 09:18:09 INFO Received cleanup request method=DELETE path=/api/pending_closures19342026/10/01 09:18:09 INFO Aborted multipart uploads count=119352026-10-01 09:18:09.910 UTC [1473] ERROR: relation "goose_db_version" does not exist at character 3619362026-10-01 09:18:09.910 UTC [1473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19372026/10/01 09:18:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures19382026/10/01 09:18:09 INFO Garbage collection started19392026/10/01 09:18:09 OK 2_object_stats_trigger.sql (10.94ms)19402026/10/01 09:18:09 OK 1_commit_pending_closure.sql (11.52ms)19412026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (12.86ms)1942=== RUN TestService_RequireScope_OIDC/builder_may_write1943=== PAUSE TestService_RequireScope_OIDC/builder_may_write1944=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1945=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1946=== RUN TestService_RequireScope_OIDC/ops_may_admin1947=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1948=== RUN TestService_RequireScope_OIDC/ops_may_not_write1949=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1950=== RUN TestService_RequireScope_OIDC/reader_may_not_write1951=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1952=== RUN TestService_RequireScope_OIDC/static_token_may_admin1953=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1954=== RUN TestService_RequireScope_OIDC/static_token_may_write1955=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1956=== RUN TestService_RequireScope_OIDC/reader_may_read1957=== PAUSE TestService_RequireScope_OIDC/reader_may_read1958=== RUN TestService_RequireScope_OIDC/writer_implies_read1959=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1960=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1961=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1962=== CONT TestRedundantMultipartUpload19632026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (12.77ms)19642026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000019652026/10/01 09:18:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete19662026/10/01 09:18:09 INFO Upload complete. (89ms)1967=== NAME TestClientMultipleUploads1968 client_integration_test.go:369: Uploaded 3 paths in 130.721043ms19692026-10-01 09:18:09.919 UTC [1026] ERROR: Closure does not exist: id=119702026-10-01 09:18:09.919 UTC [1026] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE19712026-10-01 09:18:09.919 UTC [1026] STATEMENT: -- name: CommitPendingClosure :exec1972 SELECT commit_pending_closure($1::bigint)1973 19742026/10/01 09:18:09 OK 2_object_stats_trigger.sql (3.73ms)1975--- PASS: TestService_cleanupPendingClosuresHandler (0.44s)19762026/10/01 09:18:09 OK 20241026095416_initial_model.sql (13.99ms)1977=== CONT TestService_AuthMiddleware_MTLSBoundSubjects19782026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.7ms)19792026/10/01 09:18:09 OK 3_commit_push.sql (3.8ms)19802026/10/01 09:18:09 goose: up to current file version: 319812026/10/01 09:18:09 OK 1_commit_pending_closure.sql (2.18ms)19822026/10/01 09:18:09 OK 3_commit_push.sql (1.54ms)19832026/10/01 09:18:09 goose: up to current file version: 319842026/10/01 09:18:09 OK 2_object_stats_trigger.sql (995.62µs)19852026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)19862026/10/01 09:18:09 OK 3_commit_push.sql (816.14µs)19872026/10/01 09:18:09 goose: up to current file version: 319882026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (5.48ms)19892026/10/01 09:18:09 OK 20251218171726_add_pins.sql (4.52ms)19902026/10/01 09:18:09 INFO Aborted multipart uploads count=019912026-10-01 09:18:09.927 UTC [1493] ERROR: relation "goose_db_version" does not exist at character 3619922026-10-01 09:18:09.927 UTC [1493] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19932026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (2.05ms)19942026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000019952026/10/01 09:18:09 OK 1_commit_pending_closure.sql (3.32ms)1996--- PASS: TestClientMultipleUploads (0.80s)1997=== CONT TestPush_SignsNarinfosOfItsPendingObjects19982026/10/01 09:18:09 WARN Force mode enabled - objects will be deleted immediately without grace period19992026/10/01 09:18:09 OK 20241026095416_initial_model.sql (13.31ms)20002026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.24ms)20012026/10/01 09:18:09 OK 2_object_stats_trigger.sql (1.49ms)20022026/10/01 09:18:09 OK 3_commit_push.sql (1.7ms)20032026/10/01 09:18:09 goose: up to current file version: 320042026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)20052026/10/01 09:18:09 OK 20260905000000_add_claims.sql (4.64ms)20062026/10/01 09:18:09 OK 20251218171726_add_pins.sql (3.73ms)20072026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (3.56ms)2008--- PASS: TestReadRedirectKeepsNarinfoProxied (0.32s)2009=== CONT TestService_ReadAuthMiddleware20102026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (6.2ms)20112026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (8.68ms)20122026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000020132026/10/01 09:18:09 OK 20241026095416_initial_model.sql (15.51ms)20142026/10/01 09:18:09 OK 20260905000000_add_claims.sql (7.66ms)20152026/10/01 09:18:09 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=020162026/10/01 09:18:09 OK 1_commit_pending_closure.sql (6.01ms)20172026/10/01 09:18:09 OK 20251210153512_drop_unused_gin_index.sql (6.08ms)20182026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (6.56ms)20192026/10/01 09:18:09 OK 20251218171726_add_pins.sql (5.16ms)20202026/10/01 09:18:09 OK 2_object_stats_trigger.sql (5.44ms)20212026/10/01 09:18:09 INFO Vacuumed table table=pending_closures20222026/10/01 09:18:09 OK 3_commit_push.sql (4.01ms)20232026/10/01 09:18:09 goose: up to current file version: 320242026/10/01 09:18:09 OK 20260923120000_add_pushes.sql (6.15ms)20252026/10/01 09:18:09 goose: successfully migrated database to version: 2026092312000020262026/10/01 09:18:09 OK 20260628120000_add_object_size_and_stats.sql (5.82ms)20272026/10/01 09:18:09 OK 1_commit_pending_closure.sql (4.02ms)20282026/10/01 09:18:09 OK 20260905000000_add_claims.sql (3.47ms)20292026/10/01 09:18:09 INFO Vacuumed table table=pending_objects20302026/10/01 09:18:09 INFO Vacuumed table table=multipart_uploads20312026/10/01 09:18:09 OK 2_object_stats_trigger.sql (3.14ms)20322026/10/01 09:18:09 OK 20260920000000_drop_claims.sql (5.31ms)20332026-10-01 09:18:09.980 UTC [1519] ERROR: relation "goose_db_version" does not exist at character 3620342026-10-01 09:18:09.980 UTC [1519] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20352026/10/01 09:18:09 OK 3_commit_push.sql (7.79ms)20362026/10/01 09:18:09 goose: up to current file version: 320372026-10-01 09:18:09.983 UTC [1520] ERROR: relation "goose_db_version" does not exist at character 3620382026-10-01 09:18:09.983 UTC [1520] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2039--- PASS: TestReadRedirectNar (0.37s)2040=== CONT TestPush_RejectsBadRequests20412026-10-01 09:18:09.993 UTC [1538] ERROR: relation "goose_db_version" does not exist at character 3620422026-10-01 09:18:09.993 UTC [1538] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20432026/10/01 09:18:09 INFO Received push request method=POST path=/api/pushes20442026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (37.01ms)20452026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000020462026/10/01 09:18:10 INFO Vacuumed table table=closures20472026/10/01 09:18:10 OK 1_commit_pending_closure.sql (4.23ms)20482026/10/01 09:18:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20492026/10/01 09:18:10 INFO Uploading mx8dk8b403y5ya8k1289q9axvcnrxair-ca-test (144B)20502026/10/01 09:18:10 OK 2_object_stats_trigger.sql (2.06ms)20512026/10/01 09:18:10 INFO Vacuumed table table=objects20522026/10/01 09:18:10 OK 3_commit_push.sql (2.17ms)20532026/10/01 09:18:10 goose: up to current file version: 320542026/10/01 09:18:10 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20552026/10/01 09:18:10 WARN Failed to register uploaded object key=mx8dk8b403y5ya8k1289q9axvcnrxair.ls error="server returned 404: 404 page not found\n"20562026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures20572026/10/01 09:18:10 WARN Failed to register uploaded object key=log/7jspwwfzdzvydgpggnsjjb18g1fs5blb-ca-test.drv error="server returned 404: 404 page not found\n"20582026/10/01 09:18:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20592026/10/01 09:18:10 INFO Signed narinfos id=1 count=120602026/10/01 09:18:10 INFO Uploading 1 narinfos20612026-10-01 09:18:10.027 UTC [1541] ERROR: relation "goose_db_version" does not exist at character 3620622026-10-01 09:18:10.027 UTC [1541] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20632026/10/01 09:18:10 OK 20241026095416_initial_model.sql (10.35ms)20642026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)20652026/10/01 09:18:10 INFO Received complete push request method=POST path=/api/pushes/1/complete20662026/10/01 09:18:10 WARN Failed to register uploaded object key=mx8dk8b403y5ya8k1289q9axvcnrxair.narinfo error="server returned 404: 404 page not found\n"20672026/10/01 09:18:10 OK 20251218171726_add_pins.sql (4.42ms)20682026/10/01 09:18:10 OK 20241026095416_initial_model.sql (17.17ms)20692026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (3ms)20702026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (4.05ms)20712026/10/01 09:18:10 OK 20241026095416_initial_model.sql (21.26ms)20722026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)20732026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.27ms)20742026/10/01 09:18:10 OK 20251218171726_add_pins.sql (5.26ms)20752026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.47ms)20762026/10/01 09:18:10 INFO Upload complete. (142ms)20772026/10/01 09:18:10 OK 20241026095416_initial_model.sql (11.41ms)20782026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.06ms)20792026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000020802026/10/01 09:18:10 OK 20251218171726_add_pins.sql (6.75ms)2081=== NAME TestClientCADerivations20822026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)2083 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3390725823/001/store/mx8dk8b403y5ya8k1289q9axvcnrxair-ca-test2084 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2085 Compression: zstd2086 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2087 NarSize: 1442088 References: 2089 Deriver: /build/TestClientCADerivations3390725823/001/store/7jspwwfzdzvydgpggnsjjb18g1fs5blb-ca-test.drv2090 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2091 client_ca_test.go:185: Checking for realisation files in S3...2092--- PASS: TestReadProxyDisabled (0.42s)2093=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit2094=== NAME TestClientCADerivations2095 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2096 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache20972026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (9.69ms)20982026/10/01 09:18:10 OK 1_commit_pending_closure.sql (6.7ms)20992026/10/01 09:18:10 OK 20251218171726_add_pins.sql (5.7ms)21002026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (7.83ms)21012026/10/01 09:18:10 OK 2_object_stats_trigger.sql (2.3ms)21022026/10/01 09:18:10 OK 20260905000000_add_claims.sql (5.31ms)21032026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.43ms)21042026/10/01 09:18:10 OK 3_commit_push.sql (2.34ms)21052026/10/01 09:18:10 goose: up to current file version: 321062026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (5.42ms)21072026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.95ms)21082026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.29ms)21092026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.05ms)21102026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2.44ms)21112026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000021122026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.19ms)21132026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000021142026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.51ms)21152026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.46ms)21162026/10/01 09:18:10 OK 1_commit_pending_closure.sql (3.56ms)21172026/10/01 09:18:10 OK 2_object_stats_trigger.sql (2.13ms)21182026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.39ms)21192026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000021202026/10/01 09:18:10 OK 2_object_stats_trigger.sql (2.14ms)21212026-10-01 09:18:10.071 UTC [1545] ERROR: relation "goose_db_version" does not exist at character 3621222026-10-01 09:18:10.071 UTC [1545] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21232026/10/01 09:18:10 OK 3_commit_push.sql (2.37ms)21242026/10/01 09:18:10 goose: up to current file version: 321252026/10/01 09:18:10 OK 3_commit_push.sql (2.58ms)21262026/10/01 09:18:10 goose: up to current file version: 321272026/10/01 09:18:10 OK 1_commit_pending_closure.sql (3.61ms)21282026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.92ms)21292026-10-01 09:18:10.083 UTC [1546] ERROR: relation "goose_db_version" does not exist at character 3621302026-10-01 09:18:10.083 UTC [1546] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2131--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.44s)2132=== CONT TestCreatePin_ReservedPins21332026/10/01 09:18:10 OK 3_commit_push.sql (12.74ms)21342026/10/01 09:18:10 goose: up to current file version: 321352026/10/01 09:18:10 OK 20241026095416_initial_model.sql (8.68ms)21362026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.46ms)21372026/10/01 09:18:10 OK 20241026095416_initial_model.sql (8.41ms)21382026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.43ms)21392026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)21402026-10-01 09:18:10.103 UTC [1565] ERROR: relation "goose_db_version" does not exist at character 3621412026-10-01 09:18:10.103 UTC [1565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21422026-10-01 09:18:10.103 UTC [1566] ERROR: relation "goose_db_version" does not exist at character 3621432026-10-01 09:18:10.103 UTC [1566] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21442026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.98ms)21452026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (4.41ms)21462026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.46ms)21472026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.57ms)21482026/10/01 09:18:10 OK 20260905000000_add_claims.sql (2.65ms)21492026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (1.94ms)21502026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.32ms)21512026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2.39ms)21522026/10/01 09:18:10 goose: successfully migrated database to version: 202609231200002153--- PASS: TestReadProxyHead (0.41s)2154=== CONT TestProxyHeadersOnlyTrustedOnSocket21552026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2.29ms)21562026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000021572026/10/01 09:18:10 OK 1_commit_pending_closure.sql (3.15ms)21582026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.45ms)21592026/10/01 09:18:10 OK 2_object_stats_trigger.sql (2.29ms)21602026/10/01 09:18:10 OK 20241026095416_initial_model.sql (10.1ms)21612026/10/01 09:18:10 OK 3_commit_push.sql (1.53ms)21622026/10/01 09:18:10 goose: up to current file version: 321632026/10/01 09:18:10 OK 2_object_stats_trigger.sql (2.2ms)21642026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.56ms)21652026/10/01 09:18:10 OK 3_commit_push.sql (1.13ms)21662026/10/01 09:18:10 goose: up to current file version: 321672026/10/01 09:18:10 OK 20241026095416_initial_model.sql (13.04ms)21682026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.74ms)21692026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.31ms)21702026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (4.57ms)21712026/10/01 09:18:10 OK 20251218171726_add_pins.sql (4.16ms)21722026-10-01 09:18:10.131 UTC [1693] ERROR: relation "goose_db_version" does not exist at character 3621732026-10-01 09:18:10.131 UTC [1693] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21742026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.5ms)21752026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.71ms)21762026/10/01 09:18:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21772026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (5.35ms)21782026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2.56ms)21792026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000021802026/10/01 09:18:10 OK 20260905000000_add_claims.sql (4.54ms)21812026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.87ms)2182--- PASS: TestReadProxyConditionalGet (0.45s)2183=== CONT TestParseSingleRange21842026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.53ms)2185=== RUN TestParseSingleRange/none2186=== PAUSE TestParseSingleRange/none2187=== RUN TestParseSingleRange/unknown_unit2188=== PAUSE TestParseSingleRange/unknown_unit2189=== RUN TestParseSingleRange/multi-range_ignored2190=== PAUSE TestParseSingleRange/multi-range_ignored2191=== RUN TestParseSingleRange/malformed_no_dash2192=== PAUSE TestParseSingleRange/malformed_no_dash2193=== RUN TestParseSingleRange/malformed_both_empty2194=== PAUSE TestParseSingleRange/malformed_both_empty2195=== RUN TestParseSingleRange/malformed_end_before_start21962026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (3ms)2197=== PAUSE TestParseSingleRange/malformed_end_before_start2198=== RUN TestParseSingleRange/closed2199=== PAUSE TestParseSingleRange/closed2200=== RUN TestParseSingleRange/open-ended2201=== PAUSE TestParseSingleRange/open-ended2202=== RUN TestParseSingleRange/end_clamped_to_size2203=== PAUSE TestParseSingleRange/end_clamped_to_size2204=== RUN TestParseSingleRange/suffix2205=== PAUSE TestParseSingleRange/suffix2206=== RUN TestParseSingleRange/suffix_exceeds_size2207=== PAUSE TestParseSingleRange/suffix_exceeds_size2208=== RUN TestParseSingleRange/single_byte2209=== PAUSE TestParseSingleRange/single_byte22102026/10/01 09:18:10 OK 3_commit_push.sql (1.22ms)2211=== RUN TestParseSingleRange/start_past_EOF22122026/10/01 09:18:10 goose: up to current file version: 32213=== PAUSE TestParseSingleRange/start_past_EOF2214=== RUN TestParseSingleRange/start_far_past_EOF2215=== PAUSE TestParseSingleRange/start_far_past_EOF2216=== CONT TestPush_CompleteCommitsEveryRoot22172026/10/01 09:18:10 OK 20241026095416_initial_model.sql (8.85ms)22182026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.56ms)22192026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000022202026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.75ms)22212026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.56ms)22222026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.95ms)22232026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.49ms)22242026/10/01 09:18:10 OK 3_commit_push.sql (1.59ms)22252026/10/01 09:18:10 goose: up to current file version: 322262026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.29ms)22272026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.08ms)22282026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.22ms)22292026-10-01 09:18:10.160 UTC [1765] ERROR: relation "goose_db_version" does not exist at character 3622302026-10-01 09:18:10.160 UTC [1765] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22312026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2.21ms)22322026/10/01 09:18:10 goose: successfully migrated database to version: 202609231200002233--- PASS: TestReadProxyInvalidPath (0.44s)2234=== CONT TestOrphanedObjectsGCStressTest22352026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.69ms)22362026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.77ms)22372026/10/01 09:18:10 OK 3_commit_push.sql (1.54ms)22382026/10/01 09:18:10 goose: up to current file version: 32239=== NAME TestClientCADerivations2240 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2241 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2242 error: binary cache 's3://bucket32?endpoint=http://localhost:42151®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3390725823/001/store'2243 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 122442026/10/01 09:18:10 OK 20241026095416_initial_model.sql (8.56ms)22452026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.77ms)2246--- PASS: TestClientCADerivations (0.96s)2247=== CONT TestPush_OverlappingRootsStoreOneRowPerKey22482026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.67ms)22492026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.68ms)2250--- PASS: TestService_Rustfstest (0.43s)2251=== CONT TestReadRedirectUsesPublicS3URL22522026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.22ms)22532026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.21ms)22542026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (1.88ms)22552026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000022562026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.22ms)22572026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.66ms)22582026/10/01 09:18:10 OK 3_commit_push.sql (1.33ms)22592026/10/01 09:18:10 goose: up to current file version: 322602026/10/01 09:18:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2261--- PASS: TestReadProxy404 (0.45s)2262=== CONT TestService_NativeMTLS22632026-10-01 09:18:10.222 UTC [1773] ERROR: relation "goose_db_version" does not exist at character 3622642026-10-01 09:18:10.222 UTC [1773] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22652026/10/01 09:18:10 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33085/oidc22662026/10/01 09:18:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NmJhYzU4YjEtOTc4My00MzU1LWJlNGQtNTI3MWI2NmZjYTgxLmIyNGI1MWJlLWI1OTQtNDgxMC04NGM3LTgxYjU0ZDRkNGE2OHgxNzkwODQ2Mjg5ODEwMTI5NTgz parts=1022672026/10/01 09:18:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22682026/10/01 09:18:10 INFO Completed upload id=122692026/10/01 09:18:10 OK 20241026095416_initial_model.sql (10.52ms)22702026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures2271--- PASS: TestReadProxyNarStreaming (0.46s)2272=== CONT TestMultipartCleanup22732026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.67ms)22742026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures22752026-10-01 09:18:10.252 UTC [1794] ERROR: relation "goose_db_version" does not exist at character 3622762026-10-01 09:18:10.252 UTC [1794] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22772026/10/01 09:18:10 OK 20251218171726_add_pins.sql (3.78ms)22782026/10/01 09:18:10 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo22792026/10/01 09:18:10 WARN Found objects in DB but missing from S3, will re-upload count=12280--- PASS: TestService_verifyS3Integrity (0.96s)2281=== CONT TestObjectStatsTrigger22822026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (4.66ms)22832026/10/01 09:18:10 OK 20260905000000_add_claims.sql (4.34ms)22842026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.63ms)22852026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.85ms)22862026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000022872026/10/01 09:18:10 OK 20241026095416_initial_model.sql (9.89ms)22882026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures22892026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.78ms)22902026/10/01 09:18:10 OK 1_commit_pending_closure.sql (3.19ms)22912026-10-01 09:18:10.275 UTC [1799] ERROR: relation "goose_db_version" does not exist at character 3622922026-10-01 09:18:10.275 UTC [1799] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22932026/10/01 09:18:10 OK 2_object_stats_trigger.sql (11.57ms)22942026/10/01 09:18:10 OK 20251218171726_add_pins.sql (17.27ms)22952026/10/01 09:18:10 OK 3_commit_push.sql (7.36ms)22962026/10/01 09:18:10 goose: up to current file version: 322972026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (4.66ms)22982026/10/01 09:18:10 OK 20260905000000_add_claims.sql (4.26ms)22992026/10/01 09:18:10 OK 20241026095416_initial_model.sql (10ms)23002026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures23012026-10-01 09:18:10.300 UTC [1800] ERROR: relation "goose_db_version" does not exist at character 3623022026-10-01 09:18:10.300 UTC [1800] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23032026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (3.05ms)23042026-10-01 09:18:10.300 UTC [1801] ERROR: relation "goose_db_version" does not exist at character 3623052026-10-01 09:18:10.300 UTC [1801] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23062026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)23072026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2.34ms)23082026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000023092026/10/01 09:18:10 OK 20251218171726_add_pins.sql (3.33ms)23102026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.67ms)23112026/10/01 09:18:10 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst23122026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures23132026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.53ms)23142026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.24ms)23152026/10/01 09:18:10 OK 3_commit_push.sql (1.33ms)23162026/10/01 09:18:10 goose: up to current file version: 32317--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.53s)2318=== CONT TestServerTLSConfig2319=== RUN TestServerTLSConfig/no_client_CA2320=== PAUSE TestServerTLSConfig/no_client_CA2321=== RUN TestServerTLSConfig/missing_CA_file2322=== PAUSE TestServerTLSConfig/missing_CA_file2323=== RUN TestServerTLSConfig/not_a_PEM_file2324=== PAUSE TestServerTLSConfig/not_a_PEM_file2325=== CONT TestOrphanedObjectsGC23262026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.3ms)23272026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.57ms)23282026/10/01 09:18:10 OK 20241026095416_initial_model.sql (10.68ms)23292026/10/01 09:18:10 OK 20241026095416_initial_model.sql (10.62ms)23302026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.46ms)23312026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000023322026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)23332026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (3.33ms)23342026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.89ms)23352026/10/01 09:18:10 OK 20251218171726_add_pins.sql (4.1ms)23362026/10/01 09:18:10 OK 2_object_stats_trigger.sql (2.83ms)23372026/10/01 09:18:10 OK 20251218171726_add_pins.sql (3.87ms)23382026/10/01 09:18:10 OK 3_commit_push.sql (1.33ms)23392026/10/01 09:18:10 goose: up to current file version: 323402026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.94ms)23412026-10-01 09:18:10.329 UTC [1804] ERROR: relation "goose_db_version" does not exist at character 3623422026-10-01 09:18:10.329 UTC [1804] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23432026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures23442026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.59ms)23452026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.09ms)23462026/10/01 09:18:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23472026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.33ms)23482026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (3.13ms)23492026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.18ms)23502026/10/01 09:18:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23512026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2.8ms)23522026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000023532026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.5ms)23542026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000023552026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.22ms)23562026/10/01 09:18:10 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NmJhYzU4YjEtOTc4My00MzU1LWJlNGQtNTI3MWI2NmZjYTgxLjViNWYwZjQ5LWI2YjgtNDI5NS05YTljLTUyYjE1ZDBmNDRhZHgxNzkwODQ2MjkwMzEyMzg4MjM523572026/10/01 09:18:10 OK 1_commit_pending_closure.sql (3.66ms)23582026/10/01 09:18:10 OK 2_object_stats_trigger.sql (2.1ms)23592026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.92ms)23602026/10/01 09:18:10 OK 3_commit_push.sql (1.6ms)23612026/10/01 09:18:10 goose: up to current file version: 323622026/10/01 09:18:10 OK 20241026095416_initial_model.sql (9.73ms)23632026/10/01 09:18:10 OK 3_commit_push.sql (1.57ms)23642026/10/01 09:18:10 goose: up to current file version: 323652026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)23662026/10/01 09:18:10 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NmJhYzU4YjEtOTc4My00MzU1LWJlNGQtNTI3MWI2NmZjYTgxLjViNWYwZjQ5LWI2YjgtNDI5NS05YTljLTUyYjE1ZDBmNDRhZHgxNzkwODQ2MjkwMzEyMzg4MjM5 parts=12367--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.51s)2368=== CONT TestMetricsInventory23692026/10/01 09:18:10 OK 20251218171726_add_pins.sql (4.25ms)23702026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.68ms)23712026/10/01 09:18:10 OK 20260905000000_add_claims.sql (2.76ms)23722026-10-01 09:18:10.360 UTC [1805] ERROR: relation "goose_db_version" does not exist at character 3623732026-10-01 09:18:10.360 UTC [1805] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23742026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.38ms)23752026/10/01 09:18:10 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NmJhYzU4YjEtOTc4My00MzU1LWJlNGQtNTI3MWI2NmZjYTgxLjc4YjNhZDFhLWE4ZGEtNDE3ZC04YzBmLTlhOGFkNjhjOWU2N3gxNzkwODQ2Mjg5ODc3ODMzMTY1 parts=1023762026/10/01 09:18:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete2377--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.53s)2378=== CONT TestNARDeduplicationMetadataUploadBug23792026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (10.5ms)23802026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000023812026/10/01 09:18:10 INFO Completed upload id=123822026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.12ms)23832026/10/01 09:18:10 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000023842026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.11ms)23852026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures23862026/10/01 09:18:10 OK 3_commit_push.sql (1.51ms)23872026/10/01 09:18:10 goose: up to current file version: 323882026/10/01 09:18:10 INFO Starting cleanup of old closures method=DELETE path=/api/closures23892026-10-01 09:18:10.385 UTC [1810] ERROR: relation "goose_db_version" does not exist at character 3623902026-10-01 09:18:10.385 UTC [1810] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23912026/10/01 09:18:10 OK 20241026095416_initial_model.sql (10.68ms)23922026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)23932026/10/01 09:18:10 OK 20251218171726_add_pins.sql (3.92ms)2394--- PASS: TestReadProxyNarinfo (0.54s)2395=== CONT TestCreatePendingClosureRejectsOversizedNAR23962026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures2397--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2398=== CONT TestService_AuthMiddleware_MTLSProxyHeader23992026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (4.82ms)24002026/10/01 09:18:10 INFO Aborted multipart uploads count=024012026-10-01 09:18:10.401 UTC [1812] ERROR: relation "goose_db_version" does not exist at character 3624022026-10-01 09:18:10.401 UTC [1812] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24032026/10/01 09:18:10 OK 20241026095416_initial_model.sql (10.06ms)24042026/10/01 09:18:10 OK 20260905000000_add_claims.sql (5.76ms)24052026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (3.3ms)24062026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (3.32ms)24072026/10/01 09:18:10 OK 20251218171726_add_pins.sql (3.05ms)24082026/10/01 09:18:10 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=024092026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.05ms)24102026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000024112026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.58ms)24122026/10/01 09:18:10 OK 1_commit_pending_closure.sql (3.12ms)24132026/10/01 09:18:10 INFO Vacuumed table table=pending_closures24142026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.58ms)24152026/10/01 09:18:10 OK 2_object_stats_trigger.sql (3.47ms)24162026/10/01 09:18:10 INFO Vacuumed table table=pending_objects24172026/10/01 09:18:10 OK 20241026095416_initial_model.sql (10.55ms)24182026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures24192026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.5ms)24202026/10/01 09:18:10 OK 3_commit_push.sql (1.75ms)24212026/10/01 09:18:10 goose: up to current file version: 324222026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.64ms)24232026/10/01 09:18:10 INFO Vacuumed table table=multipart_uploads24242026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.36ms)24252026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000024262026/10/01 09:18:10 OK 20251218171726_add_pins.sql (3.09ms)24272026/10/01 09:18:10 OK 1_commit_pending_closure.sql (3.02ms)24282026/10/01 09:18:10 INFO Vacuumed table table=closures24292026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.11ms)24302026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.35ms)24312026/10/01 09:18:10 INFO Vacuumed table table=objects24322026/10/01 09:18:10 OK 3_commit_push.sql (2.26ms)24332026/10/01 09:18:10 goose: up to current file version: 324342026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.32ms)24352026/10/01 09:18:10 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000024362026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.48ms)2437--- PASS: TestService_createPendingClosureHandler (1.04s)2438=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows24392026-10-01 09:18:10.435 UTC [1815] ERROR: relation "goose_db_version" does not exist at character 3624402026-10-01 09:18:10.435 UTC [1815] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24412026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures24422026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.6ms)24432026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000024442026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.5ms)24452026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.95ms)24462026/10/01 09:18:10 OK 3_commit_push.sql (1.24ms)24472026/10/01 09:18:10 goose: up to current file version: 324482026/10/01 09:18:10 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"24492026/10/01 09:18:10 WARN mTLS auth: bound subjects configured but subject DN unavailable24502026/10/01 09:18:10 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2451--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.53s)2452=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check24532026/10/01 09:18:10 OK 20241026095416_initial_model.sql (8.81ms)24542026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.94ms)24552026/10/01 09:18:10 OK 20251218171726_add_pins.sql (3.44ms)24562026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (4.61ms)24572026/10/01 09:18:10 OK 20260905000000_add_claims.sql (11.31ms)24582026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (4.03ms)24592026/10/01 09:18:10 INFO Received push request method=POST path=/api/pushes24602026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2.14ms)24612026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000024622026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.36ms)24632026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.55ms)24642026/10/01 09:18:10 OK 3_commit_push.sql (1.5ms)24652026/10/01 09:18:10 goose: up to current file version: 324662026-10-01 09:18:10.485 UTC [1820] ERROR: relation "goose_db_version" does not exist at character 3624672026-10-01 09:18:10.485 UTC [1820] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24682026-10-01 09:18:10.491 UTC [1821] ERROR: relation "goose_db_version" does not exist at character 3624692026-10-01 09:18:10.491 UTC [1821] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24702026/10/01 09:18:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24712026/10/01 09:18:10 INFO Signed narinfos id=1 count=12472--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.57s)2473=== CONT TestResolveDBConnectionString/flag_wins2474=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2475=== CONT TestResolveDBConnectionString/nothing_configured2476=== CONT TestResolveDBConnectionString/missing_file_is_an_error24772026/10/01 09:18:10 OK 20241026095416_initial_model.sql (8.25ms)2478=== CONT TestResolveDBConnectionString/file_when_flag_empty2479=== CONT TestCacheConfigHandler/full_config,_no_issuer2480=== CONT TestCacheConfigHandler/no_signing_keys2481=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2482=== CONT TestCacheConfigHandler/no_cache_url_configured2483--- PASS: TestCacheConfigHandler (0.00s)2484 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2485 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2486 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2487 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2488=== CONT TestClientErrorHandling/InvalidStorePath2489--- PASS: TestResolveDBConnectionString (0.00s)2490 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2491 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2492 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2493 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2494 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)24952026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.35ms)24962026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.81ms)24972026/10/01 09:18:10 OK 20241026095416_initial_model.sql (8.28ms)24982026-10-01 09:18:10.506 UTC [1822] ERROR: relation "goose_db_version" does not exist at character 3624992026-10-01 09:18:10.506 UTC [1822] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2500--- PASS: TestService_ReadAuthMiddleware (0.56s)2501=== CONT TestClientErrorHandling/ServerNotAvailable25022026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.29ms)25032026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.5ms)25042026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.5ms)25052026/10/01 09:18:10 OK 20251218171726_add_pins.sql (3.21ms)25062026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.4ms)25072026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.38ms)25082026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2.71ms)25092026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000025102026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.28ms)25112026/10/01 09:18:10 OK 1_commit_pending_closure.sql (3.13ms)25122026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.22ms)25132026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.63ms)25142026/10/01 09:18:10 OK 20241026095416_initial_model.sql (9.03ms)25152026/10/01 09:18:10 OK 3_commit_push.sql (1.55ms)25162026/10/01 09:18:10 goose: up to current file version: 325172026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.06ms)25182026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000025192026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.79ms)25202026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.04ms)25212026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.91ms)25222026/10/01 09:18:10 OK 2_object_stats_trigger.sql (2.11ms)25232026/10/01 09:18:10 OK 3_commit_push.sql (1.36ms)25242026/10/01 09:18:10 goose: up to current file version: 325252026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.6ms)25262026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.03ms)25272026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.23ms)2528=== RUN TestPush_RejectsBadRequests/no_roots2529=== PAUSE TestPush_RejectsBadRequests/no_roots2530=== RUN TestPush_RejectsBadRequests/no_objects2531=== PAUSE TestPush_RejectsBadRequests/no_objects2532=== RUN TestPush_RejectsBadRequests/bad_root2533=== PAUSE TestPush_RejectsBadRequests/bad_root2534=== RUN TestPush_RejectsBadRequests/root_not_in_objects2535=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects2536=== CONT TestClientErrorHandling/InvalidAuthToken25372026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2ms)25382026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000025392026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.35ms)25402026/10/01 09:18:10 OK 2_object_stats_trigger.sql (2ms)25412026/10/01 09:18:10 OK 3_commit_push.sql (1.28ms)25422026/10/01 09:18:10 goose: up to current file version: 325432026-10-01 09:18:10.553 UTC [1844] ERROR: relation "goose_db_version" does not exist at character 3625442026-10-01 09:18:10.553 UTC [1844] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25452026-10-01 09:18:10.554 UTC [1845] ERROR: relation "goose_db_version" does not exist at character 3625462026-10-01 09:18:10.554 UTC [1845] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25472026/10/01 09:18:10 INFO Received push request method=POST path=/api/pushes25482026/10/01 09:18:10 OK 20241026095416_initial_model.sql (8.34ms)25492026/10/01 09:18:10 OK 20241026095416_initial_model.sql (9.52ms)25502026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (2.16ms)25512026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.51ms)25522026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.7ms)25532026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.9ms)25542026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (14.32ms)25552026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (13.04ms)25562026/10/01 09:18:10 INFO Received complete push request method=POST path=/api/pushes/1/complete25572026/10/01 09:18:10 OK 20260905000000_add_claims.sql (3.2ms)25582026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.38ms)25592026/10/01 09:18:10 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/present25602026/10/01 09:18:10 INFO Starting HTTP server address=127.0.0.1:3404325612026/10/01 09:18:10 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket3282203767/001/proxy.sock25622026/10/01 09:18:10 OK 20260905000000_add_claims.sql (6.88ms)25632026/10/01 09:18:10 WARN mTLS auth: subject not in bound subjects subject="CN=someone"25642026/10/01 09:18:10 INFO Shutdown signal received, draining in-flight requests timeout=10s25652026/10/01 09:18:10 INFO Received push request method=POST path=/api/pushes2566--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.48s)2567=== CONT TestIsValidCachePath/narinfo2568=== CONT TestIsValidCachePath/index.html2569=== CONT TestIsValidCachePath/random_path2570=== CONT TestIsValidCachePath/invalid_char_u2571=== CONT TestIsValidCachePath/short_hash25722026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (2.64ms)2573=== CONT TestIsValidCachePath/invalid_char_e25742026/10/01 09:18:10 goose: successfully migrated database to version: 202609231200002575=== CONT TestIsValidCachePath/wrong_extension2576=== CONT TestIsValidCachePath/traversal_parent2577=== CONT TestIsValidCachePath/leading_slash2578=== CONT TestIsValidCachePath/nar_uncompressed2579=== CONT TestIsValidCachePath/empty2580=== CONT TestIsValidCachePath/traversal_in_middle2581=== CONT TestIsValidCachePath/log2582=== CONT TestIsValidCachePath/nix-cache-info2583=== CONT TestIsValidCachePath/ls2584=== CONT TestIsValidCachePath/realisation2585=== CONT TestIsValidCachePath/nar_bz22586=== CONT TestIsValidCachePath/nar_xz2587=== CONT TestIsValidCachePath/nar_zst2588=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2589--- PASS: TestIsValidCachePath (0.07s)2590 --- PASS: TestIsValidCachePath/narinfo (0.00s)2591 --- PASS: TestIsValidCachePath/index.html (0.00s)2592 --- PASS: TestIsValidCachePath/random_path (0.00s)2593 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2594 --- PASS: TestIsValidCachePath/short_hash (0.00s)2595 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2596 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2597 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2598 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2599 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2600 --- PASS: TestIsValidCachePath/empty (0.00s)2601 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2602 --- PASS: TestIsValidCachePath/log (0.00s)2603 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2604 --- PASS: TestIsValidCachePath/ls (0.00s)2605 --- PASS: TestIsValidCachePath/realisation (0.00s)2606 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2607 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2608 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2609 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2610=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info26112026/10/01 09:18:10 INFO Received uploads request method=POST path=/2612=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key26132026/10/01 09:18:10 INFO Received request for more parts method=POST path=/2614=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key26152026/10/01 09:18:10 INFO Received complete multipart upload request method=POST path=/2616=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal26172026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (2.99ms)26182026/10/01 09:18:10 INFO Received uploads request method=POST path=/2619--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2620 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2621 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2622 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2623 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2624=== CONT TestIsValidUploadKey/narinfo2625=== CONT TestIsValidUploadKey/empty_key2626=== CONT TestIsValidUploadKey/absolute2627=== CONT TestIsValidUploadKey/unknown_type2628=== CONT TestIsValidUploadKey/traversal_nar2629=== CONT TestIsValidUploadKey/build_log_question_mark2630=== CONT TestIsValidUploadKey/build_log_equals2631=== CONT TestIsValidUploadKey/nar_plain2632=== CONT TestIsValidUploadKey/traversal2633=== CONT TestIsValidUploadKey/nar_xz2634=== CONT TestIsValidUploadKey/nar_zst2635=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2636=== CONT TestIsValidUploadKey/index.html2637=== CONT TestIsValidUploadKey/listing2638=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2639=== CONT TestIsValidUploadKey/narinfo_key,_nar_type26402026-10-01 09:18:10.599 UTC [1865] ERROR: relation "goose_db_version" does not exist at character 3626412026-10-01 09:18:10.599 UTC [1865] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2642=== CONT TestIsValidUploadKey/build_log_plus_in_name2643=== CONT TestIsValidUploadKey/nix-cache-info2644=== CONT TestIsValidUploadKey/build_log2645=== CONT TestIsValidUploadKey/build_log_home-manager_file2646=== CONT TestIsValidUploadKey/realisation_plus_in_output2647=== CONT TestIsValidUploadKey/realisation2648=== CONT TestProxyWriteTimeout/narinfo2649=== CONT TestProxyWriteTimeout/10_GiB_nar2650=== CONT TestProxyWriteTimeout/unknown_size2651=== CONT TestProxyWriteTimeout/1_GiB_nar2652=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure26532026/10/01 09:18:10 INFO Received uploads request method=POST path=/2654--- PASS: TestIsValidUploadKey (0.01s)2655 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2656 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2657 --- PASS: TestIsValidUploadKey/absolute (0.00s)2658 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2659 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2660 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2661 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2662 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2663 --- PASS: TestIsValidUploadKey/traversal (0.00s)2664 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2665 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2666 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2667 --- PASS: TestIsValidUploadKey/index.html (0.00s)2668 --- PASS: TestIsValidUploadKey/listing (0.00s)2669 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2670 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2671 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2672 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2673 --- PASS: TestIsValidUploadKey/build_log (0.00s)2674 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2675 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2676 --- PASS: TestIsValidUploadKey/realisation (0.00s)26772026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.4ms)2678--- PASS: TestProxyWriteTimeout (0.00s)2679 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2680 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2681 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2682 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)26832026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.56ms)26842026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (3.26ms)26852026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000026862026/10/01 09:18:10 OK 3_commit_push.sql (1.05ms)26872026/10/01 09:18:10 goose: up to current file version: 326882026/10/01 09:18:10 OK 1_commit_pending_closure.sql (2.76ms)26892026/10/01 09:18:10 OK 2_object_stats_trigger.sql (1.52ms)26902026/10/01 09:18:10 OK 3_commit_push.sql (1.31ms)26912026/10/01 09:18:10 goose: up to current file version: 326922026/10/01 09:18:10 OK 20241026095416_initial_model.sql (8.19ms)26932026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.15ms)26942026/10/01 09:18:10 OK 20251218171726_add_pins.sql (3.08ms)26952026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (2.38ms)26962026/10/01 09:18:10 INFO Received push request method=POST path=/api/pushes26972026/10/01 09:18:10 OK 20260905000000_add_claims.sql (2.38ms)26982026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (1.42ms)26992026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (1.17ms)27002026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000027012026/10/01 09:18:10 OK 1_commit_pending_closure.sql (1.57ms)27022026-10-01 09:18:10.627 UTC [1866] ERROR: relation "goose_db_version" does not exist at character 3627032026-10-01 09:18:10.627 UTC [1866] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27042026/10/01 09:18:10 OK 2_object_stats_trigger.sql (936.66µs)27052026/10/01 09:18:10 OK 3_commit_push.sql (686.58µs)27062026/10/01 09:18:10 goose: up to current file version: 327072026/10/01 09:18:10 OK 20241026095416_initial_model.sql (7.89ms)27082026/10/01 09:18:10 INFO Received complete push request method=POST path=/api/pushes/1/complete27092026/10/01 09:18:10 OK 20251210153512_drop_unused_gin_index.sql (1.57ms)27102026/10/01 09:18:10 OK 20251218171726_add_pins.sql (2.68ms)27112026/10/01 09:18:10 OK 20260628120000_add_object_size_and_stats.sql (3.78ms)2712--- PASS: TestPush_CompleteCommitsEveryRoot (0.51s)2713=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart27142026/10/01 09:18:10 INFO Received complete multipart upload request method=POST path=/27152026/10/01 09:18:10 OK 20260905000000_add_claims.sql (2.64ms)27162026/10/01 09:18:10 OK 20260920000000_drop_claims.sql (3.04ms)27172026/10/01 09:18:10 OK 20260923120000_add_pushes.sql (1.65ms)27182026/10/01 09:18:10 goose: successfully migrated database to version: 2026092312000027192026/10/01 09:18:10 INFO Aborted multipart uploads count=027202026/10/01 09:18:10 OK 1_commit_pending_closure.sql (1.8ms)27212026/10/01 09:18:10 OK 2_object_stats_trigger.sql (805.05µs)27222026/10/01 09:18:10 WARN Force mode enabled - objects will be deleted immediately without grace period27232026/10/01 09:18:10 OK 3_commit_push.sql (788.39µs)27242026/10/01 09:18:10 goose: up to current file version: 327252026/10/01 09:18:10 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=027262026/10/01 09:18:10 INFO Vacuumed table table=pending_closures27272026/10/01 09:18:10 INFO Vacuumed table table=pending_objects27282026/10/01 09:18:10 INFO Vacuumed table table=multipart_uploads27292026/10/01 09:18:10 INFO Vacuumed table table=closures27302026/10/01 09:18:10 INFO Vacuumed table table=objects27312026/10/01 09:18:10 INFO Received complete push request method=POST path=/api/pushes/2/complete2732--- PASS: TestReadRedirectUsesPublicS3URL (0.50s)2733=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2734=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts2735--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.63s)27362026/10/01 09:18:10 INFO Received request for more parts method=POST path=/2737=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected27382026/10/01 09:18:10 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]2739=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected27402026/10/01 09:18:10 WARN Authentication failed token_preview=eyJhbGciOi...fdOUCVHoVg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2741=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2742=== CONT TestService_RequireScope_OIDC/builder_may_write2743--- PASS: TestService_AuthMiddleware_OIDC (0.55s)2744 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2745 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2746 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2747 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2748=== CONT TestService_RequireScope_OIDC/static_token_may_admin2749=== CONT TestService_RequireScope_OIDC/reader_may_not_write2750=== CONT TestService_RequireScope_OIDC/ops_may_not_write2751=== CONT TestService_RequireScope_OIDC/ops_may_admin2752=== CONT TestService_RequireScope_OIDC/static_token_may_write2753=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2754=== CONT TestService_RequireScope_OIDC/writer_implies_read2755=== CONT TestService_RequireScope_OIDC/reader_may_read2756=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2757=== CONT TestParseSingleRange/none2758=== CONT TestParseSingleRange/open-ended27592026/10/01 09:18:10 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=192.536796ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2760=== CONT TestParseSingleRange/closed2761=== CONT TestParseSingleRange/malformed_end_before_start2762=== CONT TestParseSingleRange/malformed_both_empty2763=== CONT TestParseSingleRange/malformed_no_dash2764=== CONT TestParseSingleRange/multi-range_ignored2765=== CONT TestParseSingleRange/unknown_unit2766=== CONT TestParseSingleRange/start_past_EOF2767=== CONT TestParseSingleRange/end_clamped_to_size2768=== CONT TestParseSingleRange/single_byte2769=== CONT TestParseSingleRange/suffix_exceeds_size2770=== CONT TestParseSingleRange/start_far_past_EOF2771=== CONT TestParseSingleRange/suffix2772--- PASS: TestParseSingleRange (0.00s)2773 --- PASS: TestParseSingleRange/none (0.00s)2774 --- PASS: TestParseSingleRange/open-ended (0.00s)2775 --- PASS: TestParseSingleRange/closed (0.00s)2776 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2777 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2778 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2779 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2780 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2781 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2782 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2783 --- PASS: TestParseSingleRange/single_byte (0.00s)2784 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2785 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2786 --- PASS: TestParseSingleRange/suffix (0.00s)2787=== CONT TestServerTLSConfig/no_client_CA2788=== CONT TestServerTLSConfig/not_a_PEM_file2789--- PASS: TestService_RequireScope_OIDC (0.49s)2790 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2791 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2792 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2793 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2794 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2795 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2796 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2797 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2798 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2799 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2800=== CONT TestServerTLSConfig/missing_CA_file2801--- PASS: TestServerTLSConfig (0.00s)2802 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2803 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2804 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2805=== CONT TestPush_RejectsBadRequests/no_roots28062026/10/01 09:18:10 INFO Received push request method=POST path=/api/pushes2807=== CONT TestPush_RejectsBadRequests/bad_root28082026/10/01 09:18:10 INFO Received push request method=POST path=/api/pushes2809=== CONT TestPush_RejectsBadRequests/root_not_in_objects28102026/10/01 09:18:10 INFO Received push request method=POST path=/api/pushes2811=== CONT TestPush_RejectsBadRequests/no_objects28122026/10/01 09:18:10 INFO Received push request method=POST path=/api/pushes2813--- PASS: TestPush_RejectsBadRequests (0.55s)2814 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2815 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2816 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2817 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)28182026/10/01 09:18:10 INFO Received push request method=POST path=/api/pushes2819--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.54s)28202026/10/01 09:18:10 WARN mTLS auth: subject not in bound subjects subject="CN=reader"28212026/10/01 09:18:10 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2822--- PASS: TestService_NativeMTLS (0.51s)28232026/10/01 09:18:10 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux28242026/10/01 09:18:10 WARN Refused reserved pin name=worker-x86_64-linux28252026/10/01 09:18:10 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux28262026/10/01 09:18:10 INFO Received create pin request method=POST path=/api/pins/my-app28272026/10/01 09:18:10 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux2828--- PASS: TestCreatePin_ReservedPins (0.67s)2829--- PASS: TestObjectStatsTrigger (0.53s)28302026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures28312026/10/01 09:18:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete28322026/10/01 09:18:10 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=389.542267ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28332026/10/01 09:18:10 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NmJhYzU4YjEtOTc4My00MzU1LWJlNGQtNTI3MWI2NmZjYTgxLjFlNTYyY2RhLTg1ZDEtNDBjNi1hMmNmLWIyMGNlOGM1NWViNXgxNzkwODQ2MjkwMzQzNjY2NDM1 parts=122834--- PASS: TestMetricsInventory (0.54s)28352026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures2836--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.07s)2837=== NAME TestNARDeduplicationMetadataUploadBug2838 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1855725928/001/store/0lnim65ba0hn8pzy4ndpydl47cl4k4b6-file1.txt2839--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.51s)28402026/10/01 09:18:10 INFO Received cleanup request method=DELETE path=/api/pending_closures28412026/10/01 09:18:10 INFO Aborted multipart uploads count=12842--- PASS: TestMultipartCleanup (0.67s)28432026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures28442026/10/01 09:18:10 INFO Aborted multipart uploads count=028452026/10/01 09:18:10 WARN Force mode enabled - objects will be deleted immediately without grace period28462026/10/01 09:18:10 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=028472026/10/01 09:18:10 INFO Vacuumed table table=pending_closures28482026/10/01 09:18:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete28492026/10/01 09:18:10 INFO Vacuumed table table=pending_objects28502026/10/01 09:18:10 INFO Vacuumed table table=multipart_uploads28512026/10/01 09:18:10 INFO Vacuumed table table=closures28522026/10/01 09:18:10 INFO Vacuumed table table=objects28532026/10/01 09:18:10 INFO Received uploads request method=POST path=/api/pending_closures28542026/10/01 09:18:10 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NmJhYzU4YjEtOTc4My00MzU1LWJlNGQtNTI3MWI2NmZjYTgxLjdlZWY4ZGRiLTI0YTUtNDk1Ny05MGRiLWE5OTllNDI4YjIyZXgxNzkwODQ2MjkwNDMwNTg3NTQz parts=1228552026/10/01 09:18:10 INFO Aborted multipart uploads count=02856--- PASS: TestRedundantMultipartUpload (1.05s)28572026/10/01 09:18:10 WARN Force mode enabled - objects will be deleted immediately without grace period28582026/10/01 09:18:10 INFO Received push request method=POST path=/api/pushes28592026/10/01 09:18:10 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=028602026/10/01 09:18:10 INFO Vacuumed table table=pending_closures28612026/10/01 09:18:10 INFO Vacuumed table table=pending_objects28622026/10/01 09:18:10 INFO Vacuumed table table=multipart_uploads28632026/10/01 09:18:10 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)28642026/10/01 09:18:10 INFO Vacuumed table table=closures28652026/10/01 09:18:10 INFO Uploading 0lnim65ba0hn8pzy4ndpydl47cl4k4b6-file1.txt (160B)28662026/10/01 09:18:10 INFO Vacuumed table table=objects28672026/10/01 09:18:10 WARN Failed to register uploaded object key=0lnim65ba0hn8pzy4ndpydl47cl4k4b6.ls error="server returned 404: 404 page not found\n"28682026/10/01 09:18:10 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign28692026/10/01 09:18:10 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"28702026/10/01 09:18:10 INFO Signed narinfos id=1 count=128712026/10/01 09:18:10 INFO Uploading 1 narinfos28722026/10/01 09:18:10 INFO Received complete push request method=POST path=/api/pushes/1/complete28732026/10/01 09:18:10 WARN Failed to register uploaded object key=0lnim65ba0hn8pzy4ndpydl47cl4k4b6.narinfo error="server returned 404: 404 page not found\n"28742026/10/01 09:18:10 INFO Upload complete. (64ms)2875=== NAME TestNARDeduplicationMetadataUploadBug2876 metadata_upload_test.go:54: Retrieved narinfo from S3:2877 StorePath: /build/TestNARDeduplicationMetadataUploadBug1855725928/001/store/0lnim65ba0hn8pzy4ndpydl47cl4k4b6-file1.txt2878 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2879 Compression: zstd2880 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2881 NarSize: 1602882 References: 2883 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2884 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2885 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2886 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}2887--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2888 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.51s)2889 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.57s)2890=== NAME TestNARDeduplicationMetadataUploadBug2891 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1855725928/001/store/49wqr4gqpfhccf5vxjppmq4h0y406l0z-file2.txt28922026/10/01 09:18:11 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"28932026/10/01 09:18:11 INFO Received push request method=POST path=/api/pushes2894=== NAME TestOrphanedObjectsGC2895 orphaned_objects_gc_test.go:290: GC Test Summary:2896 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2897 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2898 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2899 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2900 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2901--- PASS: TestOrphanedObjectsGC (0.81s)29022026/10/01 09:18:11 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)29032026/10/01 09:18:11 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign29042026/10/01 09:18:11 WARN Failed to register uploaded object key=49wqr4gqpfhccf5vxjppmq4h0y406l0z.ls error="server returned 404: 404 page not found\n"29052026/10/01 09:18:11 INFO Signed narinfos id=2 count=129062026/10/01 09:18:11 INFO Uploading 1 narinfos29072026/10/01 09:18:11 INFO Received complete push request method=POST path=/api/pushes/2/complete29082026/10/01 09:18:11 WARN Failed to register uploaded object key=49wqr4gqpfhccf5vxjppmq4h0y406l0z.narinfo error="server returned 404: 404 page not found\n"29092026/10/01 09:18:11 INFO Upload complete. (44ms)2910=== NAME TestNARDeduplicationMetadataUploadBug2911 metadata_upload_test.go:76: Retrieved narinfo from S3:2912 StorePath: /build/TestNARDeduplicationMetadataUploadBug1855725928/001/store/49wqr4gqpfhccf5vxjppmq4h0y406l0z-file2.txt2913 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2914 Compression: zstd2915 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2916 NarSize: 1602917 References: 2918 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf29192026/10/01 09:18:11 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2920 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2921 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2922 {"version":1,"root":{"type":"regular","size":44}}2923--- PASS: TestNARDeduplicationMetadataUploadBug (0.78s)2924--- PASS: TestUploadHandlersRejectOversizedBody (0.18s)2925 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)2926 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2927 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.58s)29282026/10/01 09:18:11 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=768.681143ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29292026/10/01 09:18:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=029302026/10/01 09:18:11 INFO Received create pin request method=POST path=/api/pins/myapp29312026/10/01 09:18:11 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC915262911/001/store/sdy5nk1dw20x027zjwpr94nv0p0z2gpy-pinned-file.txt narinfo_key=sdy5nk1dw20x027zjwpr94nv0p0z2gpy.narinfo29322026/10/01 09:18:11 INFO Starting cleanup of old closures method=DELETE path=/api/closures29332026/10/01 09:18:11 INFO Garbage collection started29342026/10/01 09:18:11 INFO Aborted multipart uploads count=029352026/10/01 09:18:11 WARN Force mode enabled - objects will be deleted immediately without grace period29362026/10/01 09:18:11 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=029372026/10/01 09:18:11 INFO Vacuumed table table=pending_closures29382026/10/01 09:18:11 INFO Vacuumed table table=pending_objects29392026/10/01 09:18:11 INFO Vacuumed table table=multipart_uploads29402026/10/01 09:18:11 INFO Vacuumed table table=closures29412026/10/01 09:18:11 INFO Vacuumed table table=objects29422026/10/01 09:18:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02943=== NAME TestClientIntegration2944 client_integration_test.go:323: Objects in database after GC:2945 client_integration_test.go:323: Successfully deleted all objects with GC --force2946--- PASS: TestClientIntegration (2.77s)2947=== NAME TestOrphanedObjectsGCStressTest2948 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2949 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion29502026/10/01 09:18:12 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.52776808s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2951 orphaned_objects_gc_test.go:509: Stress test completed successfully:2952 orphaned_objects_gc_test.go:510: - Active objects preserved: 202953 orphaned_objects_gc_test.go:511: - Objects deleted: 2102954 orphaned_objects_gc_test.go:512: - Total GC'd: 2102955--- PASS: TestOrphanedObjectsGCStressTest (2.19s)29562026/10/01 09:18:13 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-config29572026/10/01 09:18:13 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=217.609163ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2958=== NAME TestPinProtectsFromGC2959 client_integration_test.go:840: Pin successfully protected closure from garbage collection2960--- PASS: TestPinProtectsFromGC (5.19s)29612026/10/01 09:18:13 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=375.862128ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29622026/10/01 09:18:14 WARN Rate limiter enabled after throttle name=s3-test rate=529632026/10/01 09:18:14 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2964=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2965 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102966 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002967--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.41s)29682026/10/01 09:18:14 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=786.933034ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29692026/10/01 09:18:15 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.608990865s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29702026/10/01 09:18:16 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"29712026/10/01 09:18:16 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-config29722026/10/01 09:18:16 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=199.559245ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29732026/10/01 09:18:17 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=387.876569ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29742026/10/01 09:18:17 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=839.493929ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29752026/10/01 09:18:18 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.443815281s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config29762026/10/01 09:18:19 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_closures29772026/10/01 09:18:19 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=190.717759ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures29782026/10/01 09:18:19 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=402.069198ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures29792026/10/01 09:18:20 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=829.347985ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures29802026/10/01 09:18:21 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.529668713s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2981--- PASS: TestClientErrorHandling (0.00s)2982 --- PASS: TestClientErrorHandling/InvalidStorePath (0.52s)2983 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.61s)2984 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.25s)2985PASS2986{"timestamp":"2026-10-01T09:18:22.75924013Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:44236","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(391)"}29872026-10-01 09:18:23.089 UTC [128] LOG: received smart shutdown request29882026-10-01 09:18:23.093 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 129892026-10-01 09:18:23.106 UTC [133] LOG: shutting down29902026-10-01 09:18:23.107 UTC [133] LOG: checkpoint starting: shutdown immediate29912026-10-01 09:18:24.906 UTC [133] LOG: checkpoint complete: wrote 10912 buffers (66.6%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 23 recycled; write=0.302 s, sync=1.448 s, total=1.800 s; sync files=26968, longest=0.015 s, average=0.001 s; distance=373704 kB, estimate=373704 kB; lsn=0/18457D20, redo lsn=0/18457D2029922026-10-01 09:18:24.968 UTC [128] LOG: database system is shut down2993Running OIDC tests...2994=== RUN TestAudienceForIssuer2995=== PAUSE TestAudienceForIssuer2996=== RUN TestGlobMatch2997=== PAUSE TestGlobMatch2998=== RUN TestValidateToken_ValidToken2999=== PAUSE TestValidateToken_ValidToken3000=== RUN TestValidateToken_WrongAudience3001=== PAUSE TestValidateToken_WrongAudience3002=== RUN TestValidateToken_Expired3003=== PAUSE TestValidateToken_Expired3004=== RUN TestValidateToken_BoundClaimsMismatch3005=== PAUSE TestValidateToken_BoundClaimsMismatch3006=== RUN TestValidateToken_BoundSubjectMismatch3007=== PAUSE TestValidateToken_BoundSubjectMismatch3008=== RUN TestValidateToken_MultipleProviders3009=== PAUSE TestValidateToken_MultipleProviders3010=== RUN TestValidateToken_NoMatchingProvider3011=== PAUSE TestValidateToken_NoMatchingProvider3012=== RUN TestValidateToken_KubernetesServiceAccount3013=== PAUSE TestValidateToken_KubernetesServiceAccount3014=== RUN TestNewValidator_KubernetesRequiresCA3015=== PAUSE TestNewValidator_KubernetesRequiresCA3016=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3017=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3018=== RUN TestPins_ReservedForMatchingRule3019=== PAUSE TestPins_ReservedForMatchingRule3020=== RUN TestPins_TopLevelShorthand3021=== PAUSE TestPins_TopLevelShorthand3022=== RUN TestPins_ConfigValidation3023=== PAUSE TestPins_ConfigValidation3024=== RUN TestScopes_LegacyProviderDefaultsToWrite3025=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3026=== RUN TestScopes_Rules3027=== PAUSE TestScopes_Rules3028=== RUN TestScopes_ConfigValidation3029=== PAUSE TestScopes_ConfigValidation3030=== CONT TestAudienceForIssuer3031=== CONT TestValidateToken_KubernetesServiceAccount3032--- PASS: TestAudienceForIssuer (0.00s)3033=== CONT TestValidateToken_Expired3034=== CONT TestValidateToken_WrongAudience3035=== CONT TestValidateToken_ValidToken3036=== CONT TestGlobMatch3037=== RUN TestGlobMatch/foo_foo3038=== PAUSE TestGlobMatch/foo_foo3039=== RUN TestGlobMatch/foo_bar3040=== PAUSE TestGlobMatch/foo_bar3041=== RUN TestGlobMatch/*_3042=== PAUSE TestGlobMatch/*_3043=== RUN TestGlobMatch/*_anything3044=== PAUSE TestGlobMatch/*_anything3045=== RUN TestGlobMatch/foo*_foo3046=== PAUSE TestGlobMatch/foo*_foo3047=== CONT TestValidateToken_BoundClaimsMismatch3048=== CONT TestPins_ConfigValidation3049=== CONT TestValidateToken_BoundSubjectMismatch3050=== CONT TestScopes_ConfigValidation3051=== CONT TestPins_ReservedForMatchingRule3052=== CONT TestScopes_Rules3053=== CONT TestPins_TopLevelShorthand3054=== CONT TestScopes_LegacyProviderDefaultsToWrite3055=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3056=== CONT TestValidateToken_NoMatchingProvider3057=== CONT TestNewValidator_KubernetesRequiresCA3058=== CONT TestValidateToken_MultipleProviders3059=== RUN TestGlobMatch/foo*_foobar3060=== PAUSE TestGlobMatch/foo*_foobar3061=== RUN TestGlobMatch/foo*_bar3062=== PAUSE TestGlobMatch/foo*_bar3063=== RUN TestGlobMatch/*bar_bar3064=== PAUSE TestGlobMatch/*bar_bar3065=== RUN TestGlobMatch/*bar_foobar3066=== PAUSE TestGlobMatch/*bar_foobar3067=== RUN TestGlobMatch/*bar_foo3068=== PAUSE TestGlobMatch/*bar_foo3069=== RUN TestGlobMatch/foo*bar_foobar3070=== PAUSE TestGlobMatch/foo*bar_foobar3071=== RUN TestGlobMatch/foo*bar_foo123bar3072=== PAUSE TestGlobMatch/foo*bar_foo123bar3073=== RUN TestGlobMatch/foo*bar_foobarbaz3074=== PAUSE TestGlobMatch/foo*bar_foobarbaz3075=== RUN TestGlobMatch/*/*_foo/bar3076=== PAUSE TestGlobMatch/*/*_foo/bar3077=== RUN TestGlobMatch/*/*_foo3078=== PAUSE TestGlobMatch/*/*_foo3079=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3080=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3081=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03082=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03083=== RUN TestGlobMatch/refs/*/main_refs/heads/main3084=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3085=== RUN TestGlobMatch/fo?_foo3086=== PAUSE TestGlobMatch/fo?_foo3087=== RUN TestGlobMatch/fo?_fo3088=== PAUSE TestGlobMatch/fo?_fo3089=== RUN TestGlobMatch/fo?_fooo3090=== PAUSE TestGlobMatch/fo?_fooo3091=== RUN TestGlobMatch/?oo_foo3092=== PAUSE TestGlobMatch/?oo_foo3093=== RUN TestGlobMatch/?oo_boo3094=== PAUSE TestGlobMatch/?oo_boo3095=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3096=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3097=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3098=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3099=== CONT TestGlobMatch/foo_foo3100=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3101=== CONT TestGlobMatch/foo*bar_foo123bar3102=== CONT TestGlobMatch/foo*bar_foobar3103=== CONT TestGlobMatch/*bar_foo3104=== CONT TestGlobMatch/*bar_foobar3105=== CONT TestGlobMatch/*bar_bar3106=== CONT TestGlobMatch/foo*_bar3107=== CONT TestGlobMatch/foo*_foobar3108=== CONT TestGlobMatch/foo*_foo3109=== CONT TestGlobMatch/*_anything3110=== CONT TestGlobMatch/*_3111=== CONT TestGlobMatch/foo_bar3112=== CONT TestGlobMatch/fo?_foo3113=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3114=== CONT TestGlobMatch/?oo_boo3115=== CONT TestGlobMatch/?oo_foo3116=== CONT TestGlobMatch/fo?_fooo3117=== CONT TestGlobMatch/fo?_fo3118=== CONT TestGlobMatch/foo*bar_foobarbaz3119=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3120=== CONT TestGlobMatch/refs/*/main_refs/heads/main3121=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03122=== CONT TestGlobMatch/*/*_foo3123=== CONT TestGlobMatch/*/*_foo/bar3124--- PASS: TestGlobMatch (0.00s)3125 --- PASS: TestGlobMatch/foo_foo (0.00s)3126 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3127 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3128 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3129 --- PASS: TestGlobMatch/*bar_foo (0.00s)3130 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3131 --- PASS: TestGlobMatch/*bar_bar (0.00s)3132 --- PASS: TestGlobMatch/foo*_bar (0.00s)3133 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3134 --- PASS: TestGlobMatch/foo*_foo (0.00s)3135 --- PASS: TestGlobMatch/*_anything (0.00s)3136 --- PASS: TestGlobMatch/*_ (0.00s)3137 --- PASS: TestGlobMatch/foo_bar (0.00s)3138 --- PASS: TestGlobMatch/fo?_foo (0.00s)3139 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3140 --- PASS: TestGlobMatch/?oo_boo (0.00s)3141 --- PASS: TestGlobMatch/?oo_foo (0.00s)3142 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3143 --- PASS: TestGlobMatch/fo?_fo (0.00s)3144 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3145 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3146 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3147 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3148 --- PASS: TestGlobMatch/*/*_foo (0.00s)3149 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3150--- PASS: TestPins_ConfigValidation (0.00s)3151--- PASS: TestScopes_ConfigValidation (0.00s)31522026/10/01 09:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43891/oidc31532026/10/01 09:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46509/oidc3154--- PASS: TestValidateToken_BoundClaimsMismatch (0.04s)3155--- PASS: TestScopes_Rules (0.04s)31562026/10/01 09:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39053/oidc3157--- PASS: TestValidateToken_BoundSubjectMismatch (0.05s)31582026/10/01 09:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43291/oidc31592026/10/01 09:18:26 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:419153160--- PASS: TestValidateToken_ValidToken (0.06s)3161--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)31622026/10/01 09:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44021/oidc3163--- PASS: TestPins_ReservedForMatchingRule (0.07s)31642026/10/01 09:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36819/oidc3165--- PASS: TestPins_TopLevelShorthand (0.07s)31662026/10/01 09:18:26 http: TLS handshake error from 127.0.0.1:36828: remote error: tls: bad certificate3167--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)31682026/10/01 09:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33135/oidc3169--- PASS: TestValidateToken_WrongAudience (0.10s)31702026/10/01 09:18:26 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:45725/oidc3171--- PASS: TestValidateToken_NoMatchingProvider (0.10s)31722026/10/01 09:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32953/oidc3173--- PASS: TestValidateToken_Expired (0.13s)31742026/10/01 09:18:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40367/oidc3175--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.14s)31762026/10/01 09:18:26 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233177--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.20s)31782026/10/01 09:18:27 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:37345/oidc31792026/10/01 09:18:27 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:37151/oidc3180--- PASS: TestValidateToken_MultipleProviders (0.22s)3181PASS3182Running hook tests...3183=== RUN TestSendPathsEmpty3184=== PAUSE TestSendPathsEmpty3185=== RUN TestQueueEnqueueAndFetch3186=== PAUSE TestQueueEnqueueAndFetch3187=== RUN TestQueueDeduplication3188=== PAUSE TestQueueDeduplication3189=== RUN TestQueueRemove3190=== PAUSE TestQueueRemove3191=== RUN TestQueueFetchBatchLimit3192=== PAUSE TestQueueFetchBatchLimit3193=== RUN TestQueueRetryMovesToBack3194=== PAUSE TestQueueRetryMovesToBack3195=== RUN TestQueueFetchRemoveLifecycle3196=== PAUSE TestQueueFetchRemoveLifecycle3197=== RUN TestQueueConcurrentWriters3198=== PAUSE TestQueueConcurrentWriters3199=== RUN TestQueueRemoveLargeClosure3200=== PAUSE TestQueueRemoveLargeClosure3201=== RUN TestServerClientIntegration3202=== PAUSE TestServerClientIntegration3203=== RUN TestServerQueueError3204=== PAUSE TestServerQueueError3205=== RUN TestGetListenerSocketActivation3206 server_test.go:210: === RUN TestGetListenerSocketActivation3207 --- PASS: TestGetListenerSocketActivation (0.00s)3208 PASS3209 3210--- PASS: TestGetListenerSocketActivation (0.01s)3211=== RUN TestDrainIsolatesPoisonPath3212=== PAUSE TestDrainIsolatesPoisonPath3213=== RUN TestRunNotBlockedByPoisonHead3214=== PAUSE TestRunNotBlockedByPoisonHead3215=== RUN TestDrainGivesUpWhenServerDown3216=== PAUSE TestDrainGivesUpWhenServerDown3217=== RUN TestFailedPathPrunedByLaterClosure3218=== PAUSE TestFailedPathPrunedByLaterClosure3219=== RUN TestWorkerUploadsAndRemoves3220=== PAUSE TestWorkerUploadsAndRemoves3221=== RUN TestWorkerSkipsGCdPaths3222=== PAUSE TestWorkerSkipsGCdPaths3223=== RUN TestWorkerPrunesClosureDeps3224=== PAUSE TestWorkerPrunesClosureDeps3225=== RUN TestDrainTimeout3226=== PAUSE TestDrainTimeout3227=== CONT TestSendPathsEmpty3228=== CONT TestServerQueueError3229=== CONT TestWorkerUploadsAndRemoves3230--- PASS: TestSendPathsEmpty (0.00s)3231=== CONT TestQueueFetchBatchLimit3232=== CONT TestQueueRemove3233=== CONT TestQueueDeduplication3234=== CONT TestQueueEnqueueAndFetch3235=== CONT TestQueueRemoveLargeClosure3236=== CONT TestServerClientIntegration32372026/10/01 09:18:27 ERROR Failed to queue paths error="permission denied" count=13238=== CONT TestQueueConcurrentWriters3239=== CONT TestWorkerPrunesClosureDeps3240=== CONT TestQueueRetryMovesToBack3241=== CONT TestDrainTimeout3242=== CONT TestQueueFetchRemoveLifecycle3243=== CONT TestWorkerSkipsGCdPaths3244=== CONT TestRunNotBlockedByPoisonHead3245=== CONT TestDrainGivesUpWhenServerDown3246=== CONT TestDrainIsolatesPoisonPath3247=== CONT TestFailedPathPrunedByLaterClosure3248--- PASS: TestServerQueueError (0.00s)3249--- PASS: TestServerClientIntegration (0.00s)32502026/10/01 09:18:27 INFO Upload queue status pending=232512026/10/01 09:18:27 INFO Uploading batch count=232522026/10/01 09:18:27 INFO Uploading batch count=232532026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=232542026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1314971640/002/a32552026/10/01 09:18:27 INFO Upload queue status pending=232562026/10/01 09:18:27 INFO Uploading batch count=132572026/10/01 09:18:27 INFO Uploading batch count=13258--- PASS: TestQueueDeduplication (0.02s)32592026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=132602026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1314971640/002/b32612026/10/01 09:18:27 INFO Upload queue status pending=332622026/10/01 09:18:27 INFO Uploading batch count=432632026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=43264--- PASS: TestQueueFetchBatchLimit (0.02s)32652026/10/01 09:18:27 INFO Uploading batch count=232662026/10/01 09:18:27 INFO Uploading batch count=13267--- PASS: TestQueueEnqueueAndFetch (0.02s)32682026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=132692026/10/01 09:18:27 INFO Upload queue status pending=232702026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath103912483/002/bbb32712026/10/01 09:18:27 INFO Uploading batch count=132722026/10/01 09:18:27 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1108455434/002/nonexistent3273--- PASS: TestQueueFetchRemoveLifecycle (0.02s)32742026/10/01 09:18:27 INFO Uploading batch count=232752026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=23276--- PASS: TestQueueRemove (0.02s)32772026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1314971640/002/c32782026/10/01 09:18:27 INFO Uploading batch count=132792026/10/01 09:18:27 INFO Uploading batch count=132802026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1314971640/002/d3281--- PASS: TestQueueRetryMovesToBack (0.02s)32822026/10/01 09:18:27 INFO Uploading batch count=132832026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=132842026/10/01 09:18:27 INFO Uploading batch count=232852026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=232862026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1314971640/002/e32872026/10/01 09:18:27 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1314971640/002/f32882026/10/01 09:18:27 INFO Uploading batch count=132892026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=132902026/10/01 09:18:27 ERROR Drain finished with paths left in queue remaining=1032912026/10/01 09:18:27 INFO Uploading batch count=132922026/10/01 09:18:27 ERROR Upload failed error="upload failed" count=13293--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)32942026/10/01 09:18:27 ERROR Drain finished with paths left in queue remaining=13295--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3296--- PASS: TestDrainIsolatesPoisonPath (0.02s)3297--- PASS: TestWorkerUploadsAndRemoves (0.04s)3298--- PASS: TestWorkerPrunesClosureDeps (0.03s)3299--- PASS: TestWorkerSkipsGCdPaths (0.04s)3300--- PASS: TestQueueRemoveLargeClosure (0.07s)33012026/10/01 09:18:27 ERROR Upload failed error="context deadline exceeded" count=233022026/10/01 09:18:27 ERROR Drain finished with paths left in queue remaining=43303--- PASS: TestDrainTimeout (0.22s)3304--- PASS: TestQueueConcurrentWriters (0.28s)33052026/10/01 09:18:28 INFO Uploading batch count=133062026/10/01 09:18:28 INFO Uploading batch count=133072026/10/01 09:18:28 INFO Uploading batch count=133082026/10/01 09:18:28 ERROR Upload failed error="upload failed" count=133092026/10/01 09:18:28 INFO Uploading batch count=133102026/10/01 09:18:28 ERROR Upload failed error="upload failed" count=133112026/10/01 09:18:28 INFO Uploading batch count=133122026/10/01 09:18:28 ERROR Upload failed error="upload failed" count=133132026/10/01 09:18:28 INFO Uploading batch count=133142026/10/01 09:18:28 ERROR Upload failed error="upload failed" count=133152026/10/01 09:18:28 ERROR Drain finished with paths left in queue remaining=13316--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3317PASS