niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #282
· raw
1tribuchet: building on eliza2Running 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 TestShellSplit97=== CONT TestEncodeNixBase32WithRealHash98=== CONT TestEncodeNixBase3299=== CONT TestDoWithRetry_BodyReplayedViaGetBody100=== CONT TestSetClientTLSErrors101=== CONT TestScriptTokenEmptyCommand102=== CONT TestDumpPathWriterError103=== CONT TestScriptTokenScriptFails104=== CONT TestScriptTokenBadJSON105=== CONT TestScriptTokenEmptyToken106=== CONT TestScriptTokenCachesUntilRefresh107=== CONT TestScriptTokenNoExpiryRerunsEveryCall108=== CONT TestFileTokenEmpty109=== CONT TestFileTokenMissing110=== CONT TestFileTokenReadsAndCaches111=== CONT TestStaticToken112=== CONT TestParsePathInfoJSONMultiplePaths113=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths114=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1152026/10/01 07:32:22 WARN Rate limiter enabled after throttle name=server-test rate=5116=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths117=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths118=== CONT TestStreamPushRequestLine1192026/10/01 07:32:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:43707120=== CONT TestResolveStorePath121=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess122=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1232026/10/01 07:32:22 WARN Rate limiter backed off name=server-test rate=51242026/10/01 07:32:22 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:437071252026/10/01 07:32:22 WARN Rate limiter enabled after throttle name=server-test rate=5126=== RUN TestSetClientTLSErrors/missing_cert_file127=== PAUSE TestSetClientTLSErrors/missing_cert_file128=== RUN TestSetClientTLSErrors/missing_key_file129=== PAUSE TestSetClientTLSErrors/missing_key_file130=== RUN TestSetClientTLSErrors/missing_ca_file131=== PAUSE TestSetClientTLSErrors/missing_ca_file132=== RUN TestSetClientTLSErrors/invalid_ca_file133=== PAUSE TestSetClientTLSErrors/invalid_ca_file134=== CONT TestRateLimiterFeedback135=== RUN TestRateLimiterFeedback/429_enables_limiter136=== PAUSE TestRateLimiterFeedback/429_enables_limiter137=== CONT TestSetClientTLS138=== CONT TestClientSignaturesByStorePath139=== CONT TestStreamPushReportsSignatures140=== CONT TestStreamPushBatchesUnderLoad141=== CONT TestUploadMultipart_PartsInParallel142=== CONT TestStreamPushGivesUpOnDeadServer143=== CONT TestStreamPushIsolatesFailures144=== CONT TestStreamPushReportsEveryPath145--- PASS: TestShellSplit (0.00s)146=== CONT TestUploadMultipart_SupersededByPeer147=== RUN TestEncodeNixBase32/test_string_hash148=== CONT TestDumpPathSingleFile149=== CONT TestDumpPathMatchesNix150=== CONT TestPathInfoCACompatibility151=== RUN TestRateLimiterFeedback/503_enables_limiter152=== CONT TestPathInfoHashCompatibility153=== CONT TestParsePathInfoJSON154=== CONT TestGetStorePathHash155=== CONT TestPartSizeForNAR156=== CONT TestFilterOversizedClosures157=== CONT TestCaseHackSuffix158--- PASS: TestEncodeNixBase32WithRealHash (0.00s)159=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)1602026/10/01 07:32:22 ERROR Upload failed error="bad path" count=3161=== RUN TestFilterOversizedClosures/no_limit_keeps_everything1622026/10/01 07:32:22 ERROR Upload failed error=boom count=11632026/10/01 07:32:22 ERROR Upload failed error="connection refused" count=201642026/10/01 07:32:22 ERROR Server seems unavailable, giving up on batch untried=171652026/10/01 07:32:22 ERROR Upload failed error=boom count=1166--- PASS: TestScriptTokenEmptyCommand (0.00s)167--- PASS: TestScriptTokenScriptFails (0.00s)168--- PASS: TestFileTokenEmpty (0.00s)169--- PASS: TestStaticToken (0.00s)170--- PASS: TestFileTokenMissing (0.00s)171--- PASS: TestFileTokenReadsAndCaches (0.00s)172--- PASS: TestScriptTokenBadJSON (0.01s)173--- PASS: TestDoServerRequestAttachesToken (0.01s)174=== RUN TestUploadMultipart_SupersededByPeer/exists175=== PAUSE TestUploadMultipart_SupersededByPeer/exists176=== RUN TestUploadMultipart_SupersededByPeer/missing177=== PAUSE TestUploadMultipart_SupersededByPeer/missing178=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths179--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)180=== RUN TestParsePathInfoJSON/Nix_format181=== RUN TestPathInfoCACompatibility/null_ca_field182=== CONT TestRegisterUploadedObjectReusesConnections183=== RUN TestGetStorePathHash/valid_store_path184=== CONT TestShellSplitErrors185=== RUN TestPartSizeForNAR/zero_stays_at_minimum186=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)187=== PAUSE TestEncodeNixBase32/test_string_hash188=== CONT TestConvertHashToNix32189--- PASS: TestResolveStorePath (0.00s)190--- PASS: TestClientSignaturesByStorePath (0.00s)191--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)192--- PASS: TestScriptTokenEmptyToken (0.01s)193--- PASS: TestStreamPushIsolatesFailures (0.01s)194--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)195--- PASS: TestStreamPushReportsSignatures (0.01s)196--- PASS: TestStreamPushReportsEveryPath (0.00s)197=== RUN TestSetClientTLS/rejects_connection_without_client_cert198=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert199=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA200=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths201=== CONT TestSetClientTLSErrors/missing_cert_file202=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything203=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon204=== RUN TestEncodeNixBase32/empty_input205=== PAUSE TestGetStorePathHash/valid_store_path206=== RUN TestGetStorePathHash/basename_without_hyphen_should_error207=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error208=== PAUSE TestPathInfoCACompatibility/null_ca_field209=== RUN TestPathInfoCACompatibility/old_string_format_-_text210=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text211=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive212=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive213=== RUN TestPathInfoCACompatibility/new_structured_format_-_text214=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text215=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method216=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method217=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error218=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error219=== RUN TestConvertHashToNix32/SRI_format_to_Nix32220=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32221=== RUN TestConvertHashToNix32/already_Nix32_format222=== PAUSE TestConvertHashToNix32/already_Nix32_format223=== RUN TestConvertHashToNix32/invalid_format224=== PAUSE TestConvertHashToNix32/invalid_format225=== CONT TestSetClientTLSErrors/missing_key_file226=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error227=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error228=== PAUSE TestRateLimiterFeedback/503_enables_limiter229=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter230=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter231=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter232=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter233--- PASS: TestShellSplitErrors (0.00s)234=== CONT TestSetClientTLSErrors/invalid_ca_file235=== CONT TestUploadMultipart_SupersededByPeer/exists236=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method237=== CONT TestPathInfoCACompatibility/new_structured_format_-_text238=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive239=== CONT TestPathInfoCACompatibility/old_string_format_-_text240=== CONT TestGetStorePathHash/valid_store_path241=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped242=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped243=== RUN TestFilterOversizedClosures/all_closures_skipped244=== PAUSE TestFilterOversizedClosures/all_closures_skipped245=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error246=== CONT TestRateLimiterFeedback/429_enables_limiter247=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error248=== CONT TestGetStorePathHash/basename_without_hyphen_should_error249--- PASS: TestGetStorePathHash (0.03s)250 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)251 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)252 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)253 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)254=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum255=== RUN TestPartSizeForNAR/small_stays_at_minimum256=== PAUSE TestPartSizeForNAR/small_stays_at_minimum257=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum258=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum259=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts260=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts261=== RUN TestPartSizeForNAR/1_TiB262=== PAUSE TestPartSizeForNAR/1_TiB263=== RUN TestPartSizeForNAR/5_TiB_S3_max_object264=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter265=== CONT TestSetClientTLSErrors/missing_ca_file266=== PAUSE TestParsePathInfoJSON/Nix_format267=== CONT TestUploadMultipart_SupersededByPeer/missing268=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA269--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)270 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)271 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.01s)272--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)273=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon274=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI275=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI276=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512277=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512278=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object279=== RUN TestPartSizeForNAR/capped_at_5_GiB280=== PAUSE TestPartSizeForNAR/capped_at_5_GiB281=== PAUSE TestEncodeNixBase32/empty_input282=== CONT TestFilterOversizedClosures/no_limit_keeps_everything283=== CONT TestPathInfoCACompatibility/null_ca_field284=== RUN TestSetClientTLS/preserves_debug_logging_transport285=== CONT TestPartSizeForNAR/capped_at_5_GiB286=== CONT TestPartSizeForNAR/5_TiB_S3_max_object287=== CONT TestPartSizeForNAR/1_TiB288=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts289=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum290=== CONT TestPartSizeForNAR/small_stays_at_minimum291=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512292=== PAUSE TestSetClientTLS/preserves_debug_logging_transport293=== CONT TestEncodeNixBase32/empty_input294=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI295=== CONT TestConvertHashToNix32/already_Nix32_format296=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon297=== CONT TestEncodeNixBase32/test_string_hash298=== CONT TestSetClientTLS/rejects_connection_without_client_cert299=== CONT TestSetClientTLS/preserves_debug_logging_transport300=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3012026/10/01 07:32:22 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=2000302=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)303=== RUN TestParsePathInfoJSON/Lix_format304=== CONT TestConvertHashToNix32/SRI_format_to_Nix32305--- PASS: TestPathInfoCACompatibility (0.03s)306 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)307 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)308 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)309 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)310 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)311=== CONT TestPartSizeForNAR/zero_stays_at_minimum312--- PASS: TestEncodeNixBase32 (0.05s)313 --- PASS: TestEncodeNixBase32/empty_input (0.00s)314 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)315--- PASS: TestPartSizeForNAR (0.04s)316 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)317 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)318 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)319 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)320 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)321 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)322 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)323=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter324=== CONT TestFilterOversizedClosures/all_closures_skipped3252026/10/01 07:32:22 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=50326=== CONT TestConvertHashToNix32/invalid_format327=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA328=== PAUSE TestParsePathInfoJSON/Lix_format329--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)330=== RUN TestParsePathInfoJSON/empty_input331=== PAUSE TestParsePathInfoJSON/empty_input332=== RUN TestParsePathInfoJSON/whitespace_only333=== PAUSE TestParsePathInfoJSON/whitespace_only334=== RUN TestParsePathInfoJSON/invalid_JSON335=== PAUSE TestParsePathInfoJSON/invalid_JSON336=== CONT TestParsePathInfoJSON/Nix_format337--- PASS: TestPathInfoHashCompatibility (0.04s)338 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)339 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)340 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)341 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)342=== CONT TestParsePathInfoJSON/invalid_JSON343=== CONT TestParsePathInfoJSON/whitespace_only344=== CONT TestParsePathInfoJSON/empty_input345=== CONT TestParsePathInfoJSON/Lix_format346--- PASS: TestSetClientTLSErrors (0.01s)347 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)348 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)349 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)350 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)351--- PASS: TestConvertHashToNix32 (0.00s)352 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)353 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)354 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)355--- PASS: TestParsePathInfoJSON (0.04s)356 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)357 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)358 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)359 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)360 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)361--- PASS: TestFilterOversizedClosures (0.03s)362 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)363 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)364 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)365=== CONT TestRateLimiterFeedback/503_enables_limiter3662026/10/01 07:32:22 WARN Rate limiter enabled after throttle name=server-test rate=53672026/10/01 07:32:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:336733682026/10/01 07:32:22 WARN Rate limiter backed off name=server-test rate=53692026/10/01 07:32:22 WARN Rate limiter enabled after throttle name=server-test rate=53702026/10/01 07:32:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:338153712026/10/01 07:32:22 WARN Rate limiter backed off name=server-test rate=5372--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)373 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)374 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)375--- PASS: TestRateLimiterFeedback (0.04s)376 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)377 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)378 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)379 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)3802026/10/01 07:32:22 http: TLS handshake error from 127.0.0.1:55292: remote error: tls: bad certificate381--- PASS: TestSetClientTLS (0.05s)382 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)383 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)384 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)385--- PASS: TestStreamPushRequestLine (0.06s)386--- PASS: TestDumpPathWriterError (0.07s)387--- PASS: TestDumpPathSingleFile (0.06s)388--- PASS: TestCaseHackSuffix (0.06s)389--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)390--- PASS: TestStreamPushBatchesUnderLoad (0.10s)391--- PASS: TestDumpPathMatchesNix (0.10s)392--- PASS: TestUploadMultipart_PartsInParallel (0.65s)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/postgres2846878084/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/postgres2846878084/data -l logfile start422423/build/postgres2846878084:5432 - no response4242026-10-01 07:32:24.705 UTC [128] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 07:32:24.706 UTC [128] LOG: listening on Unix socket "/build/postgres2846878084/.s.PGSQL.5432"4262026-10-01 07:32:24.713 UTC [135] LOG: database system was shut down at 2026-10-01 07:32:24 UTC4272026-10-01 07:32:24.717 UTC [128] LOG: database system is ready to accept connections428/build/postgres2846878084:5432 - accepting connections429{"timestamp":"2026-10-01T07:32:24.908271475Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"c0916f98-8707-40bc-90d5-0c650c6a9ef7","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(209)"}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 TestResolveDBConnectionString467=== PAUSE TestResolveDBConnectionString468=== RUN TestLeadElectsOneAndHandsOver469=== PAUSE TestLeadElectsOneAndHandsOver470=== RUN TestLeadIncumbentWinsAfterRestart4712026-10-01 07:32:25.094 UTC [374] ERROR: relation "goose_db_version" does not exist at character 364722026-10-01 07:32:25.094 UTC [374] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4732026/10/01 07:32:25 OK 20241026095416_initial_model.sql (9.58ms)4742026/10/01 07:32:25 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)4752026/10/01 07:32:25 OK 20251218171726_add_pins.sql (3.01ms)4762026/10/01 07:32:25 OK 20260628120000_add_object_size_and_stats.sql (3.02ms)4772026/10/01 07:32:25 OK 20260905000000_add_claims.sql (3.26ms)4782026/10/01 07:32:25 OK 20260920000000_drop_claims.sql (2.21ms)4792026/10/01 07:32:25 OK 20260923120000_add_pushes.sql (1.79ms)4802026/10/01 07:32:25 goose: successfully migrated database to version: 202609231200004812026/10/01 07:32:25 OK 1_commit_pending_closure.sql (2.04ms)4822026/10/01 07:32:25 OK 2_object_stats_trigger.sql (1.18ms)4832026/10/01 07:32:25 OK 3_commit_push.sql (746.85µs)4842026/10/01 07:32:25 goose: up to current file version: 34852026/10/01 07:32:25 INFO lead: acquired remote=192.0.2.1:12344862026/10/01 07:32:25 INFO lead: released remote=192.0.2.1:12344872026/10/01 07:32:25 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 07:32:25 INFO lead: released remote=192.0.2.1:1234489--- PASS: TestLeadIncumbentWinsAfterRestart (0.80s)490=== RUN TestLeadEndsOnShutdown491=== PAUSE TestLeadEndsOnShutdown492=== RUN TestGCAdvisoryLockBlocksConcurrentRun4932026-10-01 07:32:25.891 UTC [383] ERROR: relation "goose_db_version" does not exist at character 364942026-10-01 07:32:25.891 UTC [383] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4952026/10/01 07:32:25 OK 20241026095416_initial_model.sql (9.46ms)4962026/10/01 07:32:25 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)4972026/10/01 07:32:25 OK 20251218171726_add_pins.sql (3.96ms)4982026/10/01 07:32:25 OK 20260628120000_add_object_size_and_stats.sql (7.72ms)4992026/10/01 07:32:25 OK 20260905000000_add_claims.sql (8.03ms)5002026/10/01 07:32:25 OK 20260920000000_drop_claims.sql (3.82ms)5012026/10/01 07:32:25 OK 20260923120000_add_pushes.sql (5.37ms)5022026/10/01 07:32:25 goose: successfully migrated database to version: 202609231200005032026/10/01 07:32:25 OK 1_commit_pending_closure.sql (2.32ms)5042026/10/01 07:32:25 OK 2_object_stats_trigger.sql (985.43µs)5052026/10/01 07:32:25 OK 3_commit_push.sql (2.77ms)5062026/10/01 07:32:25 goose: up to current file version: 3507--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.18s)508=== RUN TestGCBugBareHashReferences509=== PAUSE TestGCBugBareHashReferences510=== RUN TestGCMetrics511=== PAUSE TestGCMetrics512=== RUN TestPushDedupSurvivesConcurrentGC513=== PAUSE TestPushDedupSurvivesConcurrentGC514=== RUN TestDeduplicatedObjectsRecordedAsPending515=== PAUSE TestDeduplicatedObjectsRecordedAsPending516=== RUN TestGCSweepSkipsPendingObjects517=== PAUSE TestGCSweepSkipsPendingObjects518=== RUN TestTombstonedObjectOfferedWithoutWaiting519=== PAUSE TestTombstonedObjectOfferedWithoutWaiting520=== RUN TestGCSweepDeliversEachKeyOnce521=== PAUSE TestGCSweepDeliversEachKeyOnce522=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection524=== RUN TestGCTaskStore_StartNew525=== PAUSE TestGCTaskStore_StartNew526=== RUN TestGCTaskStore_DeduplicateSameParams527=== PAUSE TestGCTaskStore_DeduplicateSameParams528=== RUN TestGCTaskStore_ConflictDifferentParams529=== PAUSE TestGCTaskStore_ConflictDifferentParams530=== RUN TestGCTaskStore_GetEmpty531=== PAUSE TestGCTaskStore_GetEmpty532=== RUN TestGCTaskStore_GetReturnsLatest533=== PAUSE TestGCTaskStore_GetReturnsLatest534=== RUN TestGCTaskStore_CompletedAllowsNewTask535=== PAUSE TestGCTaskStore_CompletedAllowsNewTask536=== RUN TestGCTaskStore_PhaseUpdates537=== PAUSE TestGCTaskStore_PhaseUpdates538=== RUN TestGCTaskStore_Fail539=== PAUSE TestGCTaskStore_Fail540=== RUN TestGracefulShutdownDrainsInflight541=== PAUSE TestGracefulShutdownDrainsInflight542=== RUN TestService_healthCheckHandler543=== PAUSE TestService_healthCheckHandler544=== RUN TestService_readinessHandler545=== PAUSE TestService_readinessHandler546=== RUN TestGenerateLandingPage547=== PAUSE TestGenerateLandingPage548=== RUN TestCacheConfigHandlerMaxNarSize549=== PAUSE TestCacheConfigHandlerMaxNarSize550=== RUN TestCreatePendingClosureRejectsOversizedNAR551=== PAUSE TestCreatePendingClosureRejectsOversizedNAR552=== RUN TestNARDeduplicationMetadataUploadBug553=== PAUSE TestNARDeduplicationMetadataUploadBug554=== RUN TestMetricsInventory555=== PAUSE TestMetricsInventory556=== RUN TestService_NativeMTLS557=== PAUSE TestService_NativeMTLS558=== RUN TestServerTLSConfig559=== PAUSE TestServerTLSConfig560=== RUN TestMultipartCleanup561=== PAUSE TestMultipartCleanup562=== RUN TestObjectStatsTrigger563=== PAUSE TestObjectStatsTrigger564=== RUN TestOrphanedObjectsGC565=== PAUSE TestOrphanedObjectsGC566=== RUN TestOrphanedObjectsGCStressTest567=== PAUSE TestOrphanedObjectsGCStressTest568=== RUN TestResurrectedObjectNotDeleted569=== PAUSE TestResurrectedObjectNotDeleted570=== RUN TestCreatePin_ReservedPins571=== PAUSE TestCreatePin_ReservedPins572=== RUN TestParseSingleRange573=== PAUSE TestParseSingleRange574=== RUN TestProxyHeadersOnlyTrustedOnSocket575=== PAUSE TestProxyHeadersOnlyTrustedOnSocket576=== RUN TestIsValidCachePath577=== PAUSE TestIsValidCachePath578=== RUN TestReadProxyNarinfo579=== PAUSE TestReadProxyNarinfo580=== RUN TestReadProxyNarinfoAlreadyDecompressed581=== PAUSE TestReadProxyNarinfoAlreadyDecompressed582=== RUN TestReadProxyNarStreaming583=== PAUSE TestReadProxyNarStreaming584=== RUN TestReadProxy404585=== PAUSE TestReadProxy404586=== RUN TestReadProxyInvalidPath587=== PAUSE TestReadProxyInvalidPath588=== RUN TestReadProxyHead589=== PAUSE TestReadProxyHead590=== RUN TestReadProxyConditionalGet591=== PAUSE TestReadProxyConditionalGet592=== RUN TestReadProxyRootRedirectsToIndexHTML593=== PAUSE TestReadProxyRootRedirectsToIndexHTML594=== RUN TestReadProxyDisabled595=== PAUSE TestReadProxyDisabled596=== RUN TestReadRedirectNar597=== PAUSE TestReadRedirectNar598=== RUN TestReadRedirectKeepsNarinfoProxied599=== PAUSE TestReadRedirectKeepsNarinfoProxied600=== RUN TestReadProxyRangeRequest601=== PAUSE TestReadProxyRangeRequest602=== RUN TestReadRedirectUsesPublicS3URL603=== PAUSE TestReadRedirectUsesPublicS3URL604=== RUN TestPush_OverlappingRootsStoreOneRowPerKey605=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey606=== RUN TestPush_CompleteCommitsEveryRoot607=== PAUSE TestPush_CompleteCommitsEveryRoot608=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit609=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit610=== RUN TestPush_RejectsBadRequests611=== PAUSE TestPush_RejectsBadRequests612=== RUN TestPush_SignsNarinfosOfItsPendingObjects613=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects614=== RUN TestRedundantMultipartUpload615=== PAUSE TestRedundantMultipartUpload616=== RUN TestCompleteMultipartUpload_ErrorButObjectExists617=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists618=== RUN TestCompletedNarNotReofferedAcrossClosures619=== PAUSE TestCompletedNarNotReofferedAcrossClosures620=== RUN TestPresignedUploadRegisteredBeforeCommit621=== PAUSE TestPresignedUploadRegisteredBeforeCommit622=== RUN TestService_Rustfstest623=== PAUSE TestService_Rustfstest624=== RUN TestParseSize625=== PAUSE TestParseSize626=== RUN TestSkippedUploadsHandler627=== PAUSE TestSkippedUploadsHandler628=== RUN TestSystemdListenerNotActivated629--- PASS: TestSystemdListenerNotActivated (0.00s)630=== RUN TestWatchdogBeatsWhenHealthy631--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)632=== RUN TestWatchdogSkipsWhenUnhealthy6332026/10/01 07:32:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6342026/10/01 07:32:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6352026/10/01 07:32:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6362026/10/01 07:32:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6372026/10/01 07:32:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6382026/10/01 07:32:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6392026/10/01 07:32:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6402026/10/01 07:32:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6412026/10/01 07:32:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6422026/10/01 07:32:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"643--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)644=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle645=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle646=== RUN TestProxyWriteTimeout647=== PAUSE TestProxyWriteTimeout648=== RUN TestIsValidUploadKey649=== PAUSE TestIsValidUploadKey650=== RUN TestUploadHandlersRejectInvalidKeys651=== PAUSE TestUploadHandlersRejectInvalidKeys652=== RUN TestUploadHandlersRejectOversizedBody653=== PAUSE TestUploadHandlersRejectOversizedBody654=== RUN TestService_cleanupPendingClosuresHandler655=== PAUSE TestService_cleanupPendingClosuresHandler656=== RUN TestService_createPendingClosureHandler657=== PAUSE TestService_createPendingClosureHandler658=== RUN TestService_verifyS3Integrity659=== PAUSE TestService_verifyS3Integrity660=== RUN TestCompleteMultipartUnregistered661=== PAUSE TestCompleteMultipartUnregistered662=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT663=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT664=== CONT TestService_AuthMiddleware665=== CONT TestServerTLSConfig666=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT667=== RUN TestServerTLSConfig/no_client_CA668=== CONT TestCompleteMultipartUnregistered669=== CONT TestService_verifyS3Integrity670=== CONT TestService_createPendingClosureHandler671=== CONT TestService_cleanupPendingClosuresHandler672=== CONT TestUploadHandlersRejectOversizedBody673=== CONT TestUploadHandlersRejectInvalidKeys674=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info675=== CONT TestIsValidUploadKey676=== RUN TestIsValidUploadKey/narinfo677=== CONT TestProxyWriteTimeout678=== RUN TestProxyWriteTimeout/narinfo679=== PAUSE TestProxyWriteTimeout/narinfo680=== RUN TestProxyWriteTimeout/1_GiB_nar681=== PAUSE TestProxyWriteTimeout/1_GiB_nar682=== RUN TestProxyWriteTimeout/10_GiB_nar683=== PAUSE TestProxyWriteTimeout/10_GiB_nar684=== RUN TestProxyWriteTimeout/unknown_size685=== PAUSE TestProxyWriteTimeout/unknown_size686=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle687=== CONT TestReadProxyNarStreaming688=== CONT TestSkippedUploadsHandler689=== CONT TestParseSize690=== CONT TestService_Rustfstest691=== CONT TestPresignedUploadRegisteredBeforeCommit692=== CONT TestCompletedNarNotReofferedAcrossClosures693=== CONT TestCompleteMultipartUpload_ErrorButObjectExists694=== CONT TestRedundantMultipartUpload695=== CONT TestPush_SignsNarinfosOfItsPendingObjects696=== CONT TestPush_RejectsBadRequests697=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit698=== CONT TestPush_CompleteCommitsEveryRoot699=== CONT TestPush_OverlappingRootsStoreOneRowPerKey700=== CONT TestReadRedirectUsesPublicS3URL701=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info7022026/10/01 07:32:26 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000703=== PAUSE TestServerTLSConfig/no_client_CA704=== RUN TestServerTLSConfig/missing_CA_file705=== PAUSE TestServerTLSConfig/missing_CA_file706=== RUN TestServerTLSConfig/not_a_PEM_file707--- PASS: TestParseSize (0.00s)708=== PAUSE TestIsValidUploadKey/narinfo709=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal710=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal711=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key712=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key713=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key714=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key715=== PAUSE TestServerTLSConfig/not_a_PEM_file716=== CONT TestReadProxyRangeRequest717=== RUN TestIsValidUploadKey/nar_zst718=== PAUSE TestIsValidUploadKey/nar_zst719=== RUN TestIsValidUploadKey/nar_xz720=== PAUSE TestIsValidUploadKey/nar_xz721=== RUN TestIsValidUploadKey/nar_plain722=== PAUSE TestIsValidUploadKey/nar_plain723=== RUN TestIsValidUploadKey/listing724=== PAUSE TestIsValidUploadKey/listing725=== CONT TestReadRedirectKeepsNarinfoProxied726=== RUN TestIsValidUploadKey/build_log727=== PAUSE TestIsValidUploadKey/build_log728=== RUN TestIsValidUploadKey/build_log_home-manager_file729=== PAUSE TestIsValidUploadKey/build_log_home-manager_file730=== RUN TestIsValidUploadKey/build_log_plus_in_name731=== PAUSE TestIsValidUploadKey/build_log_plus_in_name732=== RUN TestIsValidUploadKey/build_log_question_mark733=== PAUSE TestIsValidUploadKey/build_log_question_mark734=== RUN TestIsValidUploadKey/build_log_equals735=== PAUSE TestIsValidUploadKey/build_log_equals736=== RUN TestIsValidUploadKey/realisation737=== PAUSE TestIsValidUploadKey/realisation738=== RUN TestIsValidUploadKey/realisation_plus_in_output739=== PAUSE TestIsValidUploadKey/realisation_plus_in_output740=== RUN TestIsValidUploadKey/nix-cache-info741=== PAUSE TestIsValidUploadKey/nix-cache-info742=== RUN TestIsValidUploadKey/index.html743=== PAUSE TestIsValidUploadKey/index.html744=== RUN TestIsValidUploadKey/narinfo_key,_nar_type745=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type746=== RUN TestIsValidUploadKey/nar_key,_narinfo_type747=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type748=== RUN TestIsValidUploadKey/listing_key,_narinfo_type749=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type750=== RUN TestIsValidUploadKey/traversal751=== PAUSE TestIsValidUploadKey/traversal752=== RUN TestIsValidUploadKey/traversal_nar753=== PAUSE TestIsValidUploadKey/traversal_nar754=== RUN TestIsValidUploadKey/absolute755=== PAUSE TestIsValidUploadKey/absolute756=== RUN TestIsValidUploadKey/empty_key757=== PAUSE TestIsValidUploadKey/empty_key758=== RUN TestIsValidUploadKey/unknown_type759=== PAUSE TestIsValidUploadKey/unknown_type760=== CONT TestReadRedirectNar761--- PASS: TestSkippedUploadsHandler (0.06s)762=== CONT TestReadProxyDisabled763=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure764=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure765=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart766=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart767=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts768=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts769=== CONT TestReadProxyRootRedirectsToIndexHTML7702026-10-01 07:32:26.394 UTC [449] ERROR: relation "goose_db_version" does not exist at character 367712026-10-01 07:32:26.394 UTC [449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7722026-10-01 07:32:26.395 UTC [448] ERROR: relation "goose_db_version" does not exist at character 367732026-10-01 07:32:26.395 UTC [448] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7742026-10-01 07:32:26.411 UTC [451] ERROR: relation "goose_db_version" does not exist at character 367752026-10-01 07:32:26.411 UTC [451] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7762026-10-01 07:32:26.411 UTC [453] ERROR: relation "goose_db_version" does not exist at character 367772026-10-01 07:32:26.411 UTC [453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7782026-10-01 07:32:26.411 UTC [450] ERROR: relation "goose_db_version" does not exist at character 367792026-10-01 07:32:26.411 UTC [450] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7802026-10-01 07:32:26.453 UTC [455] ERROR: relation "goose_db_version" does not exist at character 367812026-10-01 07:32:26.453 UTC [455] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7822026-10-01 07:32:26.489 UTC [456] ERROR: relation "goose_db_version" does not exist at character 367832026-10-01 07:32:26.489 UTC [456] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7842026/10/01 07:32:26 OK 20241026095416_initial_model.sql (62.25ms)7852026/10/01 07:32:26 OK 20241026095416_initial_model.sql (59.91ms)7862026-10-01 07:32:26.505 UTC [460] ERROR: relation "goose_db_version" does not exist at character 367872026-10-01 07:32:26.505 UTC [460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7882026-10-01 07:32:26.506 UTC [461] ERROR: relation "goose_db_version" does not exist at character 367892026-10-01 07:32:26.506 UTC [461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7902026/10/01 07:32:26 OK 20241026095416_initial_model.sql (70.85ms)7912026/10/01 07:32:26 OK 20241026095416_initial_model.sql (42.77ms)7922026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (8.73ms)7932026/10/01 07:32:26 OK 20241026095416_initial_model.sql (23.57ms)7942026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (9.44ms)7952026-10-01 07:32:26.516 UTC [462] ERROR: relation "goose_db_version" does not exist at character 367962026-10-01 07:32:26.516 UTC [462] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7972026-10-01 07:32:26.520 UTC [463] ERROR: relation "goose_db_version" does not exist at character 367982026-10-01 07:32:26.520 UTC [463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7992026/10/01 07:32:26 OK 20241026095416_initial_model.sql (92.56ms)8002026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (17.66ms)8012026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (16.51ms)8022026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (17.04ms)8032026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (6.53ms)8042026/10/01 07:32:26 OK 20251218171726_add_pins.sql (35.33ms)8052026/10/01 07:32:26 OK 20251218171726_add_pins.sql (19.39ms)8062026/10/01 07:32:26 OK 20251218171726_add_pins.sql (22.06ms)8072026/10/01 07:32:26 OK 20251218171726_add_pins.sql (49.38ms)8082026/10/01 07:32:26 OK 20251218171726_add_pins.sql (38.03ms)8092026/10/01 07:32:26 OK 20251218171726_add_pins.sql (38.21ms)8102026-10-01 07:32:26.582 UTC [464] ERROR: relation "goose_db_version" does not exist at character 368112026-10-01 07:32:26.582 UTC [464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8122026-10-01 07:32:26.583 UTC [465] ERROR: relation "goose_db_version" does not exist at character 368132026-10-01 07:32:26.583 UTC [465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8142026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (32.83ms)8152026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (41.65ms)8162026/10/01 07:32:26 OK 20241026095416_initial_model.sql (84.53ms)8172026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (41.68ms)8182026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (22.84ms)8192026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (28.84ms)8202026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (3.17ms)8212026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (24.48ms)8222026/10/01 07:32:26 OK 20241026095416_initial_model.sql (53.01ms)8232026-10-01 07:32:26.604 UTC [467] ERROR: relation "goose_db_version" does not exist at character 368242026-10-01 07:32:26.604 UTC [467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8252026-10-01 07:32:26.605 UTC [466] ERROR: relation "goose_db_version" does not exist at character 368262026-10-01 07:32:26.605 UTC [466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8272026-10-01 07:32:26.606 UTC [468] ERROR: relation "goose_db_version" does not exist at character 368282026-10-01 07:32:26.606 UTC [468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8292026/10/01 07:32:26 OK 20260905000000_add_claims.sql (14.05ms)8302026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (9.26ms)8312026-10-01 07:32:26.607 UTC [469] ERROR: relation "goose_db_version" does not exist at character 368322026-10-01 07:32:26.607 UTC [469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8332026/10/01 07:32:26 OK 20251218171726_add_pins.sql (13.74ms)8342026-10-01 07:32:26.608 UTC [470] ERROR: relation "goose_db_version" does not exist at character 368352026-10-01 07:32:26.608 UTC [470] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8362026/10/01 07:32:26 OK 20241026095416_initial_model.sql (75.97ms)8372026/10/01 07:32:26 OK 20260905000000_add_claims.sql (18.72ms)8382026/10/01 07:32:26 OK 20260905000000_add_claims.sql (16.45ms)8392026/10/01 07:32:26 OK 20260905000000_add_claims.sql (18.8ms)8402026/10/01 07:32:26 OK 20260905000000_add_claims.sql (16.53ms)8412026/10/01 07:32:26 OK 20260905000000_add_claims.sql (15.16ms)8422026/10/01 07:32:26 OK 20241026095416_initial_model.sql (50.26ms)8432026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (6.25ms)8442026/10/01 07:32:26 OK 20241026095416_initial_model.sql (82.84ms)8452026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (6.32ms)8462026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (6.67ms)8472026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (9.19ms)8482026-10-01 07:32:26.620 UTC [471] ERROR: relation "goose_db_version" does not exist at character 368492026-10-01 07:32:26.620 UTC [471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8502026-10-01 07:32:26.620 UTC [472] ERROR: relation "goose_db_version" does not exist at character 368512026-10-01 07:32:26.620 UTC [472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8522026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (11.79ms)8532026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (5.38ms)8542026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200008552026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (4.83ms)8562026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200008572026/10/01 07:32:26 OK 20251218171726_add_pins.sql (13.97ms)8582026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (7ms)8592026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (12.62ms)8602026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (5.22ms)8612026/10/01 07:32:26 OK 20251218171726_add_pins.sql (6.43ms)8622026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (13.13ms)8632026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (5.48ms)8642026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200008652026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (12.95ms)8662026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (3.5ms)8672026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200008682026-10-01 07:32:26.625 UTC [473] ERROR: relation "goose_db_version" does not exist at character 368692026-10-01 07:32:26.625 UTC [473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8702026/10/01 07:32:26 OK 1_commit_pending_closure.sql (5.62ms)8712026/10/01 07:32:26 OK 1_commit_pending_closure.sql (5.93ms)8722026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (4.37ms)8732026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200008742026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (5.4ms)8752026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200008762026/10/01 07:32:26 OK 1_commit_pending_closure.sql (3.32ms)8772026/10/01 07:32:26 OK 20251218171726_add_pins.sql (6.45ms)8782026/10/01 07:32:26 OK 1_commit_pending_closure.sql (5.57ms)8792026/10/01 07:32:26 OK 20260905000000_add_claims.sql (6.48ms)8802026/10/01 07:32:26 OK 20241026095416_initial_model.sql (11.55ms)8812026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (6.22ms)8822026/10/01 07:32:26 OK 20251218171726_add_pins.sql (7.07ms)8832026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (7.98ms)8842026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.38ms)8852026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.32ms)8862026/10/01 07:32:26 OK 20241026095416_initial_model.sql (29.03ms)8872026/10/01 07:32:26 OK 2_object_stats_trigger.sql (3.88ms)8882026/10/01 07:32:26 OK 20241026095416_initial_model.sql (23.69ms)8892026/10/01 07:32:26 OK 1_commit_pending_closure.sql (5.04ms)8902026/10/01 07:32:26 OK 20241026095416_initial_model.sql (14.9ms)8912026/10/01 07:32:26 OK 2_object_stats_trigger.sql (4.26ms)8922026-10-01 07:32:26.632 UTC [474] ERROR: relation "goose_db_version" does not exist at character 368932026-10-01 07:32:26.632 UTC [474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8942026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (4.37ms)8952026/10/01 07:32:26 OK 3_commit_push.sql (4.68ms)8962026/10/01 07:32:26 goose: up to current file version: 38972026/10/01 07:32:26 OK 3_commit_push.sql (4.67ms)8982026/10/01 07:32:26 goose: up to current file version: 38992026/10/01 07:32:26 OK 1_commit_pending_closure.sql (6.25ms)9002026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (3.96ms)9012026/10/01 07:32:26 OK 3_commit_push.sql (2.88ms)9022026/10/01 07:32:26 goose: up to current file version: 39032026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (6.9ms)9042026/10/01 07:32:26 OK 3_commit_push.sql (2.33ms)9052026/10/01 07:32:26 goose: up to current file version: 39062026/10/01 07:32:26 OK 20260905000000_add_claims.sql (6.21ms)9072026/10/01 07:32:26 OK 20260905000000_add_claims.sql (5.47ms)9082026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.58ms)9092026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (3.61ms)9102026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (7.52ms)9112026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (3.44ms)9122026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (7ms)9132026/10/01 07:32:26 OK 2_object_stats_trigger.sql (3.1ms)9142026/10/01 07:32:26 OK 3_commit_push.sql (3.16ms)9152026/10/01 07:32:26 goose: up to current file version: 39162026/10/01 07:32:26 OK 20241026095416_initial_model.sql (15.35ms)9172026/10/01 07:32:26 OK 20251218171726_add_pins.sql (5.82ms)9182026/10/01 07:32:26 OK 20241026095416_initial_model.sql (15.66ms)9192026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (4.12ms)9202026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (4.87ms)9212026-10-01 07:32:26.640 UTC [476] ERROR: relation "goose_db_version" does not exist at character 369222026-10-01 07:32:26.640 UTC [476] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9232026-10-01 07:32:26.641 UTC [475] ERROR: relation "goose_db_version" does not exist at character 369242026-10-01 07:32:26.641 UTC [475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9252026/10/01 07:32:26 OK 3_commit_push.sql (3.68ms)9262026/10/01 07:32:26 goose: up to current file version: 39272026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (5.75ms)9282026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200009292026/10/01 07:32:26 OK 20260905000000_add_claims.sql (6.55ms)9302026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (4.47ms)9312026/10/01 07:32:26 OK 20260905000000_add_claims.sql (7.18ms)9322026/10/01 07:32:26 OK 20251218171726_add_pins.sql (7.4ms)9332026/10/01 07:32:26 OK 20241026095416_initial_model.sql (18.62ms)9342026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (5.51ms)9352026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (6.09ms)9362026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200009372026/10/01 07:32:26 OK 20251218171726_add_pins.sql (10.87ms)9382026/10/01 07:32:26 OK 20251218171726_add_pins.sql (9.61ms)9392026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (6.22ms)9402026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200009412026/10/01 07:32:26 OK 1_commit_pending_closure.sql (4.71ms)9422026/10/01 07:32:26 OK 20241026095416_initial_model.sql (16.47ms)9432026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (8.22ms)9442026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (5.74ms)9452026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (4.88ms)9462026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (4.81ms)9472026/10/01 07:32:26 OK 2_object_stats_trigger.sql (3.55ms)9482026/10/01 07:32:26 OK 20241026095416_initial_model.sql (13.72ms)9492026/10/01 07:32:26 OK 20241026095416_initial_model.sql (21.53ms)9502026/10/01 07:32:26 OK 1_commit_pending_closure.sql (5.12ms)9512026/10/01 07:32:26 OK 1_commit_pending_closure.sql (5.05ms)9522026/10/01 07:32:26 OK 20251218171726_add_pins.sql (8.43ms)9532026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (5.08ms)9542026/10/01 07:32:26 OK 3_commit_push.sql (2.11ms)9552026/10/01 07:32:26 goose: up to current file version: 39562026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (4.22ms)9572026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200009582026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (9.15ms)9592026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (4.86ms)9602026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200009612026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (2.49ms)9622026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (7.02ms)9632026/10/01 07:32:26 OK 20260905000000_add_claims.sql (5.45ms)9642026/10/01 07:32:26 OK 20251218171726_add_pins.sql (8.47ms)9652026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.89ms)9662026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (7.09ms)9672026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (3.06ms)9682026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.1ms)9692026/10/01 07:32:26 OK 20251218171726_add_pins.sql (5.49ms)9702026/10/01 07:32:26 OK 3_commit_push.sql (2.33ms)9712026/10/01 07:32:26 goose: up to current file version: 39722026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (6.59ms)9732026/10/01 07:32:26 OK 20260905000000_add_claims.sql (5.63ms)9742026/10/01 07:32:26 OK 1_commit_pending_closure.sql (5.54ms)9752026/10/01 07:32:26 OK 20251218171726_add_pins.sql (6.24ms)9762026/10/01 07:32:26 OK 1_commit_pending_closure.sql (5.71ms)9772026/10/01 07:32:26 OK 20241026095416_initial_model.sql (15.19ms)9782026/10/01 07:32:26 OK 20260905000000_add_claims.sql (6.54ms)9792026/10/01 07:32:26 OK 20260905000000_add_claims.sql (6.39ms)9802026/10/01 07:32:26 OK 20251218171726_add_pins.sql (6.59ms)9812026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (6.57ms)9822026/10/01 07:32:26 OK 3_commit_push.sql (6.45ms)9832026/10/01 07:32:26 goose: up to current file version: 39842026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (6.14ms)9852026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.11ms)9862026/10/01 07:32:26 OK 20251218171726_add_pins.sql (6.87ms)9872026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (7.77ms)9882026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.22ms)9892026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (3ms)9902026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (3.73ms)9912026/10/01 07:32:26 OK 20260905000000_add_claims.sql (4.41ms)9922026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (4.25ms)9932026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (5.29ms)9942026/10/01 07:32:26 OK 3_commit_push.sql (3.03ms)9952026/10/01 07:32:26 goose: up to current file version: 39962026/10/01 07:32:26 OK 20241026095416_initial_model.sql (12.48ms)9972026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (4.15ms)9982026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200009992026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (4.11ms)10002026/10/01 07:32:26 OK 3_commit_push.sql (2.86ms)10012026/10/01 07:32:26 goose: up to current file version: 310022026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (5.36ms)10032026/10/01 07:32:26 INFO Received uploads request method=POST path=/api/pending_closures10042026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (3.22ms)10052026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010062026/10/01 07:32:26 OK 20241026095416_initial_model.sql (15.58ms)10072026/10/01 07:32:26 OK 20251218171726_add_pins.sql (3.78ms)10082026/10/01 07:32:26 OK 20260905000000_add_claims.sql (4.7ms)10092026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (5.09ms)10102026/10/01 07:32:26 OK 20260905000000_add_claims.sql (5.76ms)10112026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (3.35ms)10122026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (4.28ms)10132026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (2.98ms)10142026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010152026/10/01 07:32:26 OK 1_commit_pending_closure.sql (5.44ms)10162026/10/01 07:32:26 OK 1_commit_pending_closure.sql (3.82ms)10172026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (5.44ms)10182026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010192026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (3.59ms)10202026/10/01 07:32:26 OK 20260905000000_add_claims.sql (5.62ms)10212026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (4.71ms)10222026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (5.62ms)10232026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (7.8ms)10242026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010252026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.15ms)10262026/10/01 07:32:26 OK 20260905000000_add_claims.sql (6.59ms)10272026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (5.83ms)10282026/10/01 07:32:26 OK 20260905000000_add_claims.sql (5.67ms)10292026/10/01 07:32:26 OK 2_object_stats_trigger.sql (3.13ms)10302026/10/01 07:32:26 OK 1_commit_pending_closure.sql (3.21ms)10312026/10/01 07:32:26 OK 1_commit_pending_closure.sql (3.53ms)10322026/10/01 07:32:26 OK 20251218171726_add_pins.sql (4.64ms)10332026/10/01 07:32:26 OK 3_commit_push.sql (1.43ms)10342026/10/01 07:32:26 goose: up to current file version: 310352026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (4.03ms)10362026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (3.61ms)10372026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010382026/10/01 07:32:26 OK 20251218171726_add_pins.sql (4.59ms)10392026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.6ms)10402026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.65ms)10412026/10/01 07:32:26 OK 1_commit_pending_closure.sql (3.87ms)10422026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (3.69ms)10432026/10/01 07:32:26 OK 3_commit_push.sql (2.84ms)10442026/10/01 07:32:26 goose: up to current file version: 310452026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (4.03ms)10462026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010472026/10/01 07:32:26 OK 20260905000000_add_claims.sql (4.73ms)10482026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (4.75ms)10492026/10/01 07:32:26 OK 3_commit_push.sql (1.24ms)10502026/10/01 07:32:26 goose: up to current file version: 310512026/10/01 07:32:26 OK 3_commit_push.sql (1.21ms)10522026/10/01 07:32:26 goose: up to current file version: 310532026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (3.13ms)10542026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010552026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (4.1ms)10562026/10/01 07:32:26 OK 1_commit_pending_closure.sql (2.69ms)10572026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.73ms)10582026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (4.11ms)10592026/10/01 07:32:26 OK 3_commit_push.sql (3.27ms)10602026/10/01 07:32:26 goose: up to current file version: 310612026/10/01 07:32:26 OK 1_commit_pending_closure.sql (3.8ms)10622026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (4.16ms)10632026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010642026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (4.4ms)10652026/10/01 07:32:26 OK 2_object_stats_trigger.sql (3.69ms)10662026/10/01 07:32:26 OK 1_commit_pending_closure.sql (5.37ms)10672026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (5.9ms)10682026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010692026/10/01 07:32:26 OK 20260905000000_add_claims.sql (4.66ms)10702026/10/01 07:32:26 OK 20260905000000_add_claims.sql (3.9ms)10712026/10/01 07:32:26 OK 3_commit_push.sql (1.1ms)10722026/10/01 07:32:26 goose: up to current file version: 310732026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.39ms)10742026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.05ms)10752026/10/01 07:32:26 OK 1_commit_pending_closure.sql (2.27ms)10762026/10/01 07:32:26 OK 3_commit_push.sql (1.63ms)10772026/10/01 07:32:26 goose: up to current file version: 310782026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (3.18ms)10792026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010802026/10/01 07:32:26 OK 3_commit_push.sql (1.79ms)10812026/10/01 07:32:26 goose: up to current file version: 310822026/10/01 07:32:26 OK 1_commit_pending_closure.sql (2.57ms)10832026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.47ms)10842026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (2.86ms)10852026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (3.37ms)10862026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.97ms)10872026/10/01 07:32:26 OK 1_commit_pending_closure.sql (2.83ms)10882026/10/01 07:32:26 OK 3_commit_push.sql (2.93ms)10892026/10/01 07:32:26 goose: up to current file version: 310902026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (2.67ms)10912026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010922026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (6.35ms)10932026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000010942026/10/01 07:32:26 OK 2_object_stats_trigger.sql (4.54ms)10952026/10/01 07:32:26 OK 3_commit_push.sql (5.06ms)10962026/10/01 07:32:26 goose: up to current file version: 310972026/10/01 07:32:26 OK 1_commit_pending_closure.sql (4.14ms)10982026/10/01 07:32:26 OK 3_commit_push.sql (1.29ms)10992026/10/01 07:32:26 goose: up to current file version: 311002026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.36ms)11012026/10/01 07:32:26 INFO Received uploads request method=POST path=/api/pending_closures11022026/10/01 07:32:26 OK 1_commit_pending_closure.sql (3.88ms)11032026/10/01 07:32:26 OK 3_commit_push.sql (2.74ms)11042026/10/01 07:32:26 goose: up to current file version: 311052026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.21ms)11062026/10/01 07:32:26 OK 3_commit_push.sql (2.27ms)11072026/10/01 07:32:26 goose: up to current file version: 31108--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.49s)1109=== CONT TestReadProxyConditionalGet11102026/10/01 07:32:26 INFO Received cleanup request method=DELETE path=/api/pending_closures11112026/10/01 07:32:26 INFO Aborted multipart uploads count=011122026/10/01 07:32:26 INFO Received uploads request method=POST path=/api/pending_closures11132026/10/01 07:32:26 INFO Received cleanup request method=DELETE path=/api/pending_closures11142026/10/01 07:32:26 INFO Aborted multipart uploads count=111152026/10/01 07:32:26 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11162026-10-01 07:32:26.745 UTC [448] ERROR: Closure does not exist: id=111172026-10-01 07:32:26.745 UTC [448] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE11182026-10-01 07:32:26.745 UTC [448] STATEMENT: -- name: CommitPendingClosure :exec1119 SELECT commit_pending_closure($1::bigint)1120 1121--- PASS: TestService_cleanupPendingClosuresHandler (0.52s)1122=== CONT TestReadProxyHead11232026/10/01 07:32:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11242026/10/01 07:32:26 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1125--- PASS: TestCompleteMultipartUnregistered (0.53s)1126=== CONT TestReadProxyInvalidPath11272026-10-01 07:32:26.818 UTC [485] ERROR: relation "goose_db_version" does not exist at character 3611282026-10-01 07:32:26.818 UTC [485] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1129--- PASS: TestReadProxyNarStreaming (0.60s)1130=== CONT TestReadProxy40411312026/10/01 07:32:26 OK 20241026095416_initial_model.sql (9.88ms)11322026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)11332026-10-01 07:32:26.838 UTC [486] ERROR: relation "goose_db_version" does not exist at character 3611342026-10-01 07:32:26.838 UTC [486] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11352026/10/01 07:32:26 OK 20251218171726_add_pins.sql (3.15ms)11362026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (3.98ms)11372026/10/01 07:32:26 OK 20260905000000_add_claims.sql (5.65ms)11382026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (2.97ms)11392026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (2.85ms)11402026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000011412026/10/01 07:32:26 OK 20241026095416_initial_model.sql (14.07ms)11422026/10/01 07:32:26 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1143--- PASS: TestService_AuthMiddleware (0.64s)1144=== CONT TestPushDedupSurvivesConcurrentGC11452026/10/01 07:32:26 OK 1_commit_pending_closure.sql (2.59ms)11462026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)11472026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.7ms)11482026/10/01 07:32:26 OK 3_commit_push.sql (2.29ms)11492026/10/01 07:32:26 goose: up to current file version: 311502026/10/01 07:32:26 OK 20251218171726_add_pins.sql (5.06ms)11512026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (5.76ms)11522026/10/01 07:32:26 OK 20260905000000_add_claims.sql (4.92ms)11532026-10-01 07:32:26.881 UTC [491] ERROR: relation "goose_db_version" does not exist at character 3611542026-10-01 07:32:26.881 UTC [491] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11552026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (3.15ms)11562026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (3.05ms)11572026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000011582026/10/01 07:32:26 OK 1_commit_pending_closure.sql (2.63ms)11592026/10/01 07:32:26 OK 2_object_stats_trigger.sql (2.48ms)11602026/10/01 07:32:26 OK 3_commit_push.sql (1.46ms)11612026/10/01 07:32:26 goose: up to current file version: 311622026/10/01 07:32:26 OK 20241026095416_initial_model.sql (9.67ms)11632026/10/01 07:32:26 INFO Received uploads request method=POST path=/api/pending_closures11642026/10/01 07:32:26 INFO Received uploads request method=POST path=/api/pending_closures11652026/10/01 07:32:26 INFO Received uploads request method=POST path=/api/pending_closures11662026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (1.99ms)11672026/10/01 07:32:26 OK 20251218171726_add_pins.sql (3.76ms)11682026-10-01 07:32:26.905 UTC [492] ERROR: relation "goose_db_version" does not exist at character 3611692026-10-01 07:32:26.905 UTC [492] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11702026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)11712026/10/01 07:32:26 OK 20260905000000_add_claims.sql (12.12ms)11722026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (2.9ms)11732026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (2.2ms)11742026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000011752026/10/01 07:32:26 OK 1_commit_pending_closure.sql (2.33ms)11762026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.68ms)11772026/10/01 07:32:26 OK 20241026095416_initial_model.sql (9.31ms)11782026/10/01 07:32:26 OK 3_commit_push.sql (1.28ms)11792026/10/01 07:32:26 goose: up to current file version: 311802026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)11812026-10-01 07:32:26.933 UTC [493] ERROR: relation "goose_db_version" does not exist at character 3611822026-10-01 07:32:26.933 UTC [493] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11832026/10/01 07:32:26 INFO Received push request method=POST path=/api/pushes11842026/10/01 07:32:26 OK 20251218171726_add_pins.sql (3.91ms)11852026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (4.15ms)11862026/10/01 07:32:26 OK 20260905000000_add_claims.sql (3.9ms)11872026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (4.15ms)11882026/10/01 07:32:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11892026/10/01 07:32:26 INFO Signed narinfos id=1 count=111902026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (5.36ms)1191--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.73s)11922026/10/01 07:32:26 goose: successfully migrated database to version: 202609231200001193=== CONT TestService_NativeMTLS11942026/10/01 07:32:26 OK 20241026095416_initial_model.sql (13.23ms)11952026/10/01 07:32:26 OK 20251210153512_drop_unused_gin_index.sql (2.75ms)11962026/10/01 07:32:26 OK 1_commit_pending_closure.sql (3.08ms)11972026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.49ms)11982026/10/01 07:32:26 OK 3_commit_push.sql (1.08ms)11992026/10/01 07:32:26 goose: up to current file version: 312002026/10/01 07:32:26 OK 20251218171726_add_pins.sql (3.93ms)12012026/10/01 07:32:26 OK 20260628120000_add_object_size_and_stats.sql (4.51ms)12022026/10/01 07:32:26 OK 20260905000000_add_claims.sql (6.41ms)12032026/10/01 07:32:26 OK 20260920000000_drop_claims.sql (3.59ms)12042026/10/01 07:32:26 INFO Received uploads request method=POST path=/api/pending_closures12052026/10/01 07:32:26 OK 20260923120000_add_pushes.sql (3.67ms)12062026/10/01 07:32:26 goose: successfully migrated database to version: 2026092312000012072026/10/01 07:32:26 OK 1_commit_pending_closure.sql (2.74ms)12082026/10/01 07:32:26 OK 2_object_stats_trigger.sql (1.81ms)12092026/10/01 07:32:26 OK 3_commit_push.sql (2.49ms)12102026/10/01 07:32:26 goose: up to current file version: 312112026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures12122026-10-01 07:32:27.022 UTC [496] ERROR: relation "goose_db_version" does not exist at character 3612132026-10-01 07:32:27.022 UTC [496] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12142026/10/01 07:32:27 OK 20241026095416_initial_model.sql (9.46ms)12152026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.13ms)12162026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.27ms)12172026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.66ms)12182026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures12192026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.59ms)12202026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.47ms)12212026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (1.92ms)12222026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000012232026/10/01 07:32:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12242026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.37ms)12252026/10/01 07:32:27 OK 2_object_stats_trigger.sql (965.93µs)12262026/10/01 07:32:27 OK 3_commit_push.sql (702.59µs)12272026/10/01 07:32:27 goose: up to current file version: 312282026/10/01 07:32:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12292026/10/01 07:32:27 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12302026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures1231--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.84s)1232=== CONT TestMetricsInventory12332026/10/01 07:32:27 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YTAwM2ViOWYtNWM1NC00MWEwLTgxOGYtN2YwMjFjMzVhY2Y0LmEzZWVjMDY0LWM3ODctNGQ0ZS1hNjZjLTliYmIyYTA1YTQ3OXgxNzkwODM5OTQ2Njc1NTI3ODU4 parts=1012342026/10/01 07:32:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12352026/10/01 07:32:27 INFO Completed upload id=112362026/10/01 07:32:27 INFO Received push request method=POST path=/api/pushes12372026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures12382026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures12392026/10/01 07:32:27 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12402026/10/01 07:32:27 WARN Found objects in DB but missing from S3, will re-upload count=11241--- PASS: TestService_verifyS3Integrity (0.87s)1242=== CONT TestNARDeduplicationMetadataUploadBug12432026/10/01 07:32:27 INFO Received complete push request method=POST path=/api/pushes/1/complete12442026/10/01 07:32:27 INFO Received push request method=POST path=/api/pushes12452026/10/01 07:32:27 INFO Received push request method=POST path=/api/pushes12462026-10-01 07:32:27.152 UTC [519] ERROR: relation "goose_db_version" does not exist at character 3612472026-10-01 07:32:27.152 UTC [519] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1248--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.93s)1249=== CONT TestCreatePendingClosureRejectsOversizedNAR12502026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures1251--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1252=== CONT TestCacheConfigHandlerMaxNarSize1253--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1254=== CONT TestGenerateLandingPage1255--- PASS: TestGenerateLandingPage (0.00s)1256=== CONT TestService_readinessHandler12572026/10/01 07:32:27 OK 20241026095416_initial_model.sql (9.17ms)12582026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (1.67ms)12592026-10-01 07:32:27.169 UTC [522] ERROR: relation "goose_db_version" does not exist at character 3612602026-10-01 07:32:27.169 UTC [522] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12612026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.48ms)12622026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.85ms)1263--- PASS: TestReadProxyRangeRequest (0.89s)1264=== CONT TestService_healthCheckHandler12652026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.79ms)12662026/10/01 07:32:27 INFO Aborted multipart uploads count=012672026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (11.16ms)12682026/10/01 07:32:27 WARN Force mode enabled - objects will be deleted immediately without grace period12692026/10/01 07:32:27 OK 20241026095416_initial_model.sql (16.42ms)12702026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.8ms)12712026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (3.98ms)12722026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000012732026/10/01 07:32:27 OK 1_commit_pending_closure.sql (3.01ms)12742026/10/01 07:32:27 OK 20251218171726_add_pins.sql (4.95ms)12752026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.95ms)12762026/10/01 07:32:27 OK 3_commit_push.sql (1.5ms)12772026/10/01 07:32:27 goose: up to current file version: 312782026/10/01 07:32:27 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=012792026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.19ms)12802026/10/01 07:32:27 INFO Vacuumed table table=pending_closures12812026/10/01 07:32:27 OK 20260905000000_add_claims.sql (4.16ms)12822026/10/01 07:32:27 INFO Vacuumed table table=pending_objects12832026/10/01 07:32:27 INFO Vacuumed table table=multipart_uploads12842026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (3.3ms)12852026/10/01 07:32:27 INFO Vacuumed table table=closures12862026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (3.29ms)12872026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000012882026/10/01 07:32:27 INFO Vacuumed table table=objects12892026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.34ms)12902026/10/01 07:32:27 INFO Received complete push request method=POST path=/api/pushes/2/complete1291--- PASS: TestReadRedirectUsesPublicS3URL (0.99s)1292=== CONT TestGracefulShutdownDrainsInflight12932026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.4ms)12942026/10/01 07:32:27 INFO Starting HTTP server address=127.0.0.1:3656512952026/10/01 07:32:27 INFO Shutdown signal received, draining in-flight requests timeout=10s12962026/10/01 07:32:27 OK 3_commit_push.sql (1.5ms)12972026/10/01 07:32:27 goose: up to current file version: 31298--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.94s)1299=== CONT TestGCTaskStore_Fail1300--- PASS: TestGCTaskStore_Fail (0.00s)1301=== CONT TestGCTaskStore_PhaseUpdates1302--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1303=== CONT TestGCTaskStore_CompletedAllowsNewTask1304--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1305=== CONT TestGCTaskStore_GetReturnsLatest1306--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1307=== CONT TestGCTaskStore_GetEmpty1308--- PASS: TestGCTaskStore_GetEmpty (0.00s)1309=== CONT TestGCTaskStore_ConflictDifferentParams1310--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1311=== CONT TestGCTaskStore_DeduplicateSameParams1312--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1313=== CONT TestGCTaskStore_StartNew1314--- PASS: TestGCTaskStore_StartNew (0.00s)1315=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1316=== RUN TestPush_RejectsBadRequests/no_roots1317=== PAUSE TestPush_RejectsBadRequests/no_roots1318=== RUN TestPush_RejectsBadRequests/no_objects1319=== PAUSE TestPush_RejectsBadRequests/no_objects1320=== RUN TestPush_RejectsBadRequests/bad_root1321=== PAUSE TestPush_RejectsBadRequests/bad_root1322=== RUN TestPush_RejectsBadRequests/root_not_in_objects1323=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1324=== CONT TestGCSweepDeliversEachKeyOnce13252026-10-01 07:32:27.233 UTC [525] ERROR: relation "goose_db_version" does not exist at character 3613262026-10-01 07:32:27.233 UTC [525] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13272026/10/01 07:32:27 OK 20241026095416_initial_model.sql (11.04ms)13282026-10-01 07:32:27.254 UTC [530] ERROR: relation "goose_db_version" does not exist at character 3613292026-10-01 07:32:27.254 UTC [530] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13302026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)13312026/10/01 07:32:27 OK 20251218171726_add_pins.sql (4.45ms)13322026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.53ms)13332026/10/01 07:32:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13342026/10/01 07:32:27 OK 20260905000000_add_claims.sql (4.14ms)13352026/10/01 07:32:27 OK 20241026095416_initial_model.sql (10.06ms)1336--- PASS: TestReadRedirectNar (0.98s)1337=== CONT TestTombstonedObjectOfferedWithoutWaiting13382026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (4.14ms)13392026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.98ms)13402026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (2.91ms)13412026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000013422026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.78ms)13432026/10/01 07:32:27 OK 1_commit_pending_closure.sql (3.02ms)13442026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.85ms)13452026/10/01 07:32:27 OK 3_commit_push.sql (3.9ms)13462026/10/01 07:32:27 goose: up to current file version: 313472026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (6.65ms)13482026/10/01 07:32:27 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YTAwM2ViOWYtNWM1NC00MWEwLTgxOGYtN2YwMjFjMzVhY2Y0LjBhMTQ4NGFkLTE5Y2UtNDhmZS1hN2M4LWM5Nzc4NTA1ZThlNXgxNzkwODM5OTQ2OTA3MDA3NTEy parts=1013492026/10/01 07:32:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13502026/10/01 07:32:27 OK 20260905000000_add_claims.sql (4.26ms)13512026/10/01 07:32:27 INFO Completed upload id=11352--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1353=== CONT TestGCSweepSkipsPendingObjects13542026/10/01 07:32:27 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013552026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures13562026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.98ms)13572026/10/01 07:32:27 INFO Starting cleanup of old closures method=DELETE path=/api/closures1358--- PASS: TestReadProxyDisabled (1.01s)1359=== CONT TestGCMetrics13602026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (10.42ms)13612026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000013622026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.99ms)13632026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.46ms)13642026/10/01 07:32:27 OK 3_commit_push.sql (994.25µs)13652026/10/01 07:32:27 goose: up to current file version: 313662026/10/01 07:32:27 INFO Aborted multipart uploads count=013672026-10-01 07:32:27.316 UTC [538] ERROR: relation "goose_db_version" does not exist at character 3613682026-10-01 07:32:27.316 UTC [538] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13692026/10/01 07:32:27 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=013702026-10-01 07:32:27.320 UTC [539] ERROR: relation "goose_db_version" does not exist at character 3613712026-10-01 07:32:27.320 UTC [539] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13722026/10/01 07:32:27 INFO Vacuumed table table=pending_closures13732026/10/01 07:32:27 INFO Vacuumed table table=pending_objects13742026/10/01 07:32:27 INFO Vacuumed table table=multipart_uploads13752026/10/01 07:32:27 INFO Vacuumed table table=closures13762026/10/01 07:32:27 INFO Vacuumed table table=objects13772026/10/01 07:32:27 OK 20241026095416_initial_model.sql (10.54ms)1378--- PASS: TestReadRedirectKeepsNarinfoProxied (1.05s)1379=== CONT TestDeduplicatedObjectsRecordedAsPending13802026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.32ms)13812026/10/01 07:32:27 OK 20241026095416_initial_model.sql (10.57ms)13822026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.74ms)13832026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (1.71ms)13842026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.89ms)13852026/10/01 07:32:27 OK 20251218171726_add_pins.sql (4.09ms)13862026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.73ms)13872026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures13882026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.36ms)13892026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (3.17ms)13902026/10/01 07:32:27 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001391--- PASS: TestService_createPendingClosureHandler (1.13s)1392=== CONT TestGCBugBareHashReferences13932026/10/01 07:32:27 OK 20260905000000_add_claims.sql (4.31ms)13942026-10-01 07:32:27.354 UTC [542] ERROR: relation "goose_db_version" does not exist at character 3613952026-10-01 07:32:27.354 UTC [542] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13962026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (3.65ms)13972026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000013982026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (5.72ms)13992026/10/01 07:32:27 OK 1_commit_pending_closure.sql (5.97ms)14002026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (2.2ms)14012026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000014022026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.83ms)14032026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures14042026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.6ms)14052026/10/01 07:32:27 OK 3_commit_push.sql (2.6ms)14062026/10/01 07:32:27 goose: up to current file version: 314072026/10/01 07:32:27 OK 2_object_stats_trigger.sql (2.06ms)14082026/10/01 07:32:27 OK 3_commit_push.sql (1.35ms)14092026/10/01 07:32:27 goose: up to current file version: 314102026-10-01 07:32:27.371 UTC [545] ERROR: relation "goose_db_version" does not exist at character 3614112026-10-01 07:32:27.371 UTC [545] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14122026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures14132026-10-01 07:32:27.378 UTC [546] ERROR: relation "goose_db_version" does not exist at character 3614142026-10-01 07:32:27.378 UTC [546] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14152026/10/01 07:32:27 OK 20241026095416_initial_model.sql (19.27ms)14162026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.58ms)14172026/10/01 07:32:27 OK 20251218171726_add_pins.sql (6.43ms)14182026/10/01 07:32:27 INFO Received push request method=POST path=/api/pushes14192026/10/01 07:32:27 OK 20241026095416_initial_model.sql (11.99ms)14202026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (5.42ms)14212026/10/01 07:32:27 OK 20241026095416_initial_model.sql (10.99ms)14222026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.41ms)14232026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (3.79ms)14242026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.94ms)14252026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.45ms)14262026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.98ms)14272026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (3.47ms)14282026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (2.74ms)14292026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000014302026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.64ms)14312026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.93ms)14322026-10-01 07:32:27.408 UTC [547] ERROR: relation "goose_db_version" does not exist at character 3614332026-10-01 07:32:27.408 UTC [547] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14342026/10/01 07:32:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14352026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.86ms)14362026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.68ms)14372026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.38ms)14382026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.82ms)14392026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.61ms)14402026/10/01 07:32:27 INFO Received complete push request method=POST path=/api/pushes/1/complete14412026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.93ms)14422026/10/01 07:32:27 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTAwM2ViOWYtNWM1NC00MWEwLTgxOGYtN2YwMjFjMzVhY2Y0LmRkNDllNTk3LWYxZWQtNGNjNi1hNTU3LWFlOWE1MDNkMjAyNngxNzkwODM5OTQ3MzgzMjYyOTM014432026/10/01 07:32:27 OK 3_commit_push.sql (990.37µs)14442026/10/01 07:32:27 goose: up to current file version: 314452026/10/01 07:32:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14462026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (4.41ms)14472026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000014482026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (4.26ms)14492026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000014502026-10-01 07:32:27.422 UTC [550] ERROR: relation "goose_db_version" does not exist at character 3614512026-10-01 07:32:27.422 UTC [550] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14522026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.58ms)14532026/10/01 07:32:27 OK 20241026095416_initial_model.sql (8.56ms)14542026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.68ms)14552026/10/01 07:32:27 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTAwM2ViOWYtNWM1NC00MWEwLTgxOGYtN2YwMjFjMzVhY2Y0LmRkNDllNTk3LWYxZWQtNGNjNi1hNTU3LWFlOWE1MDNkMjAyNngxNzkwODM5OTQ3MzgzMjYyOTM0 parts=11456--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.14s)1457=== CONT TestClientIntegration14582026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.05ms)14592026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.01ms)1460--- PASS: TestPush_CompleteCommitsEveryRoot (1.14s)1461=== CONT TestClientErrorHandling1462=== RUN TestClientErrorHandling/InvalidStorePath14632026/10/01 07:32:27 OK 3_commit_push.sql (1.07ms)1464=== PAUSE TestClientErrorHandling/InvalidStorePath14652026/10/01 07:32:27 goose: up to current file version: 31466=== RUN TestClientErrorHandling/InvalidAuthToken1467=== PAUSE TestClientErrorHandling/InvalidAuthToken1468=== RUN TestClientErrorHandling/ServerNotAvailable1469=== PAUSE TestClientErrorHandling/ServerNotAvailable1470=== CONT TestLeadEndsOnShutdown14712026/10/01 07:32:27 OK 3_commit_push.sql (1.2ms)14722026/10/01 07:32:27 goose: up to current file version: 31473--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.05s)1474=== CONT TestClientCADerivations14752026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.56ms)14762026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.01ms)14772026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.51ms)14782026/10/01 07:32:27 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YTAwM2ViOWYtNWM1NC00MWEwLTgxOGYtN2YwMjFjMzVhY2Y0LjEwZjBkZDkyLWRkMTQtNDY3ZC1iZDRhLTkzNTFiODRlODEzYXgxNzkwODM5OTQ3MDE2OTEzNDM5 parts=1214792026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures14802026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.81ms)14812026/10/01 07:32:27 OK 20241026095416_initial_model.sql (9.37ms)1482--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.21s)1483=== CONT TestCacheStatsHandler14842026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.54ms)14852026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (1.88ms)14862026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (3.04ms)14872026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000014882026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.98ms)1489--- PASS: TestService_Rustfstest (1.16s)1490=== CONT TestLeadElectsOneAndHandsOver14912026/10/01 07:32:27 OK 1_commit_pending_closure.sql (3.1ms)14922026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.76ms)14932026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.37ms)14942026/10/01 07:32:27 OK 3_commit_push.sql (1.62ms)14952026/10/01 07:32:27 goose: up to current file version: 314962026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.87ms)14972026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (3.17ms)14982026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (2.34ms)14992026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000015002026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.94ms)15012026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.78ms)15022026/10/01 07:32:27 OK 3_commit_push.sql (1.74ms)15032026/10/01 07:32:27 goose: up to current file version: 31504--- PASS: TestReadProxyConditionalGet (0.78s)1505=== CONT TestCacheConfigHandler1506=== RUN TestCacheConfigHandler/full_config,_no_issuer1507=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1508=== RUN TestCacheConfigHandler/no_cache_url_configured1509=== PAUSE TestCacheConfigHandler/no_cache_url_configured1510=== RUN TestCacheConfigHandler/no_signing_keys1511=== PAUSE TestCacheConfigHandler/no_signing_keys1512=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1513=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1514=== CONT TestResolveDBConnectionString1515=== RUN TestResolveDBConnectionString/flag_wins1516=== PAUSE TestResolveDBConnectionString/flag_wins1517=== RUN TestResolveDBConnectionString/file_when_flag_empty1518=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1519=== RUN TestResolveDBConnectionString/missing_file_is_an_error1520=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1521=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1522=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1523=== RUN TestResolveDBConnectionString/nothing_configured1524=== PAUSE TestResolveDBConnectionString/nothing_configured1525=== CONT TestService_ReadScope_PublicByDefault15262026-10-01 07:32:27.542 UTC [563] ERROR: relation "goose_db_version" does not exist at character 3615272026-10-01 07:32:27.542 UTC [563] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15282026-10-01 07:32:27.543 UTC [564] ERROR: relation "goose_db_version" does not exist at character 3615292026-10-01 07:32:27.543 UTC [564] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1530--- PASS: TestReadProxyHead (0.80s)1531=== CONT TestService_RequireScope_OIDC15322026-10-01 07:32:27.549 UTC [565] ERROR: relation "goose_db_version" does not exist at character 3615332026-10-01 07:32:27.549 UTC [565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15342026/10/01 07:32:27 OK 20241026095416_initial_model.sql (15.44ms)15352026/10/01 07:32:27 OK 20241026095416_initial_model.sql (12.29ms)15362026/10/01 07:32:27 OK 20241026095416_initial_model.sql (14.23ms)15372026-10-01 07:32:27.569 UTC [566] ERROR: relation "goose_db_version" does not exist at character 3615382026-10-01 07:32:27.569 UTC [566] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1539--- PASS: TestReadProxyInvalidPath (0.82s)1540=== CONT TestClientFallsBackToClosures15412026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)15422026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (3.63ms)15432026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (4.25ms)15442026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.78ms)15452026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.62ms)15462026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.37ms)15472026-10-01 07:32:27.578 UTC [568] ERROR: relation "goose_db_version" does not exist at character 3615482026-10-01 07:32:27.578 UTC [568] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15492026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)15502026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.65ms)15512026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.51ms)15522026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.85ms)15532026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.22ms)15542026-10-01 07:32:27.585 UTC [570] ERROR: relation "goose_db_version" does not exist at character 3615552026-10-01 07:32:27.585 UTC [570] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15562026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.48ms)15572026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (3.62ms)15582026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (3.13ms)15592026/10/01 07:32:27 OK 20241026095416_initial_model.sql (11.04ms)15602026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (2.88ms)15612026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000015622026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (4.7ms)15632026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (3.1ms)15642026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000015652026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.13ms)15662026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (3.25ms)15672026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000015682026/10/01 07:32:27 OK 1_commit_pending_closure.sql (3.33ms)15692026/10/01 07:32:27 OK 1_commit_pending_closure.sql (3.21ms)15702026/10/01 07:32:27 OK 20251218171726_add_pins.sql (6.69ms)15712026/10/01 07:32:27 OK 1_commit_pending_closure.sql (5.07ms)15722026/10/01 07:32:27 OK 20241026095416_initial_model.sql (14.19ms)15732026/10/01 07:32:27 OK 2_object_stats_trigger.sql (5.15ms)15742026/10/01 07:32:27 OK 2_object_stats_trigger.sql (5.22ms)15752026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.96ms)15762026/10/01 07:32:27 OK 3_commit_push.sql (2.48ms)15772026/10/01 07:32:27 goose: up to current file version: 315782026/10/01 07:32:27 OK 3_commit_push.sql (2.54ms)15792026/10/01 07:32:27 goose: up to current file version: 315802026/10/01 07:32:27 OK 3_commit_push.sql (2.44ms)15812026/10/01 07:32:27 goose: up to current file version: 315822026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (6.28ms)15832026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (4.49ms)1584--- PASS: TestReadProxy404 (0.77s)15852026/10/01 07:32:27 OK 20241026095416_initial_model.sql (12.3ms)1586=== CONT TestService_AuthMiddleware_OIDC15872026/10/01 07:32:27 OK 20251218171726_add_pins.sql (4.3ms)15882026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.89ms)15892026/10/01 07:32:27 OK 20260905000000_add_claims.sql (5.49ms)15902026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.73ms)15912026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.78ms)15922026/10/01 07:32:27 OK 20251218171726_add_pins.sql (4.71ms)15932026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (2.86ms)15942026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000015952026/10/01 07:32:27 OK 20260905000000_add_claims.sql (6.68ms)15962026/10/01 07:32:27 OK 1_commit_pending_closure.sql (6.28ms)15972026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (7.56ms)15982026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (3.77ms)15992026/10/01 07:32:27 OK 2_object_stats_trigger.sql (2.28ms)16002026/10/01 07:32:27 OK 20260905000000_add_claims.sql (4.78ms)16012026/10/01 07:32:27 OK 3_commit_push.sql (3.01ms)16022026/10/01 07:32:27 goose: up to current file version: 316032026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (3.13ms)16042026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000016052026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.51ms)16062026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.48ms)16072026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.21ms)16082026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (2.36ms)16092026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000016102026/10/01 07:32:27 OK 3_commit_push.sql (1.08ms)16112026/10/01 07:32:27 goose: up to current file version: 316122026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.51ms)16132026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.16ms)16142026/10/01 07:32:27 OK 3_commit_push.sql (2.04ms)16152026/10/01 07:32:27 goose: up to current file version: 316162026-10-01 07:32:27.641 UTC [571] ERROR: relation "goose_db_version" does not exist at character 3616172026-10-01 07:32:27.641 UTC [571] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16182026/10/01 07:32:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38607/oidc16192026/10/01 07:32:27 OK 20241026095416_initial_model.sql (12.45ms)16202026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)16212026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.14ms)16222026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.96ms)16232026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures16242026/10/01 07:32:27 OK 20260905000000_add_claims.sql (5.17ms)16252026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (4.1ms)16262026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (4.07ms)16272026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000016282026/10/01 07:32:27 WARN mTLS auth: subject not in bound subjects subject="CN=reader"16292026/10/01 07:32:27 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1630--- PASS: TestService_NativeMTLS (0.73s)1631=== CONT TestClientPushesUseOnePush16322026/10/01 07:32:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35761/oidc16332026/10/01 07:32:27 OK 1_commit_pending_closure.sql (4.01ms)16342026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.79ms)16352026/10/01 07:32:27 OK 3_commit_push.sql (3.14ms)16362026/10/01 07:32:27 goose: up to current file version: 316372026-10-01 07:32:27.736 UTC [578] ERROR: relation "goose_db_version" does not exist at character 3616382026-10-01 07:32:27.736 UTC [578] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1639--- PASS: TestMetricsInventory (0.67s)1640=== CONT TestService_ReadAuthMiddleware16412026/10/01 07:32:27 INFO Aborted multipart uploads count=016422026/10/01 07:32:27 OK 20241026095416_initial_model.sql (10.16ms)16432026/10/01 07:32:27 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=016442026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2ms)16452026/10/01 07:32:27 INFO Vacuumed table table=pending_closures16462026/10/01 07:32:27 INFO Vacuumed table table=pending_objects16472026/10/01 07:32:27 INFO Vacuumed table table=multipart_uploads16482026/10/01 07:32:27 OK 20251218171726_add_pins.sql (4.05ms)16492026/10/01 07:32:27 INFO Vacuumed table table=closures16502026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.53ms)16512026-10-01 07:32:27.772 UTC [584] ERROR: relation "goose_db_version" does not exist at character 3616522026-10-01 07:32:27.772 UTC [584] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16532026-10-01 07:32:27.772 UTC [583] ERROR: relation "goose_db_version" does not exist at character 3616542026-10-01 07:32:27.772 UTC [583] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16552026/10/01 07:32:27 INFO Vacuumed table table=objects16562026/10/01 07:32:27 OK 20260905000000_add_claims.sql (4.06ms)16572026/10/01 07:32:27 INFO Aborted multipart uploads count=016582026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.95ms)16592026/10/01 07:32:27 WARN Force mode enabled - objects will be deleted immediately without grace period16602026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (3.67ms)16612026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000016622026/10/01 07:32:27 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=016632026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.74ms)16642026/10/01 07:32:27 INFO Vacuumed table table=pending_closures16652026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.5ms)16662026/10/01 07:32:27 OK 3_commit_push.sql (774.59µs)16672026/10/01 07:32:27 goose: up to current file version: 316682026/10/01 07:32:27 INFO Vacuumed table table=pending_objects16692026/10/01 07:32:27 INFO Vacuumed table table=multipart_uploads16702026/10/01 07:32:27 WARN readiness check failed error="closed pool"1671--- PASS: TestService_readinessHandler (0.63s)1672=== CONT TestPinProtectsFromGC16732026/10/01 07:32:27 OK 20241026095416_initial_model.sql (13.04ms)16742026/10/01 07:32:27 OK 20241026095416_initial_model.sql (14.34ms)16752026/10/01 07:32:27 INFO Vacuumed table table=closures16762026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.21ms)16772026/10/01 07:32:27 INFO Vacuumed table table=objects16782026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (3.25ms)1679--- PASS: TestPushDedupSurvivesConcurrentGC (0.94s)1680=== CONT TestService_AuthMiddleware_MTLSBoundSubjects16812026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.59ms)16822026/10/01 07:32:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16832026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.91ms)16842026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.29ms)1685=== NAME TestNARDeduplicationMetadataUploadBug1686 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug859241779/001/store/pz0k5la6kdk85zn1vf6mj26wvf32nhd2-file1.txt16872026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.92ms)16882026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.24ms)16892026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.73ms)16902026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.75ms)16912026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (1.87ms)16922026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000016932026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.15ms)16942026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.57ms)16952026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (3.06ms)16962026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000016972026-10-01 07:32:27.815 UTC [606] ERROR: relation "goose_db_version" does not exist at character 3616982026-10-01 07:32:27.815 UTC [606] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16992026/10/01 07:32:27 OK 2_object_stats_trigger.sql (2.53ms)17002026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.6ms)17012026/10/01 07:32:27 OK 3_commit_push.sql (1.7ms)17022026/10/01 07:32:27 goose: up to current file version: 317032026/10/01 07:32:27 OK 2_object_stats_trigger.sql (2.46ms)17042026/10/01 07:32:27 OK 3_commit_push.sql (2.19ms)17052026/10/01 07:32:27 goose: up to current file version: 31706--- PASS: TestService_healthCheckHandler (0.65s)1707=== CONT TestClientSharedPathCommittedMidPush17082026/10/01 07:32:27 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YTAwM2ViOWYtNWM1NC00MWEwLTgxOGYtN2YwMjFjMzVhY2Y0LjVlNzdiMGFjLWUyYmItNGY4MS1iOTc1LWU4NGZkNjU4OWI1NXgxNzkwODM5OTQ3MzYwMzQyNzU3 parts=121709--- PASS: TestRedundantMultipartUpload (1.54s)1710=== CONT TestService_AuthMiddleware_MTLSProxyHeader17112026/10/01 07:32:27 OK 20241026095416_initial_model.sql (10.91ms)17122026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.13ms)17132026/10/01 07:32:27 OK 20251218171726_add_pins.sql (7.8ms)17142026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.82ms)17152026/10/01 07:32:27 OK 20260905000000_add_claims.sql (10.66ms)17162026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (4.51ms)17172026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures17182026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (2.97ms)17192026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000017202026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.83ms)17212026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.77ms)17222026-10-01 07:32:27.872 UTC [629] ERROR: relation "goose_db_version" does not exist at character 3617232026-10-01 07:32:27.872 UTC [629] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17242026/10/01 07:32:27 OK 3_commit_push.sql (3.27ms)17252026/10/01 07:32:27 goose: up to current file version: 317262026-10-01 07:32:27.879 UTC [630] ERROR: relation "goose_db_version" does not exist at character 3617272026-10-01 07:32:27.879 UTC [630] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17282026/10/01 07:32:27 INFO Received push request method=POST path=/api/pushes17292026/10/01 07:32:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17302026/10/01 07:32:27 INFO Uploading pz0k5la6kdk85zn1vf6mj26wvf32nhd2-file1.txt (160B)17312026/10/01 07:32:27 OK 20241026095416_initial_model.sql (11.54ms)17322026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)17332026/10/01 07:32:27 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"17342026/10/01 07:32:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17352026/10/01 07:32:27 WARN Failed to register uploaded object key=pz0k5la6kdk85zn1vf6mj26wvf32nhd2.ls error="server returned 404: 404 page not found\n"17362026/10/01 07:32:27 INFO Signed narinfos id=1 count=117372026/10/01 07:32:27 INFO Uploading 1 narinfos17382026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.88ms)17392026/10/01 07:32:27 OK 20241026095416_initial_model.sql (11.23ms)17402026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.94ms)17412026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)17422026/10/01 07:32:27 INFO Received complete push request method=POST path=/api/pushes/1/complete17432026/10/01 07:32:27 WARN Failed to register uploaded object key=pz0k5la6kdk85zn1vf6mj26wvf32nhd2.narinfo error="server returned 404: 404 page not found\n"17442026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.12ms)17452026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.57ms)17462026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.53ms)17472026/10/01 07:32:27 INFO Upload complete. (61ms)17482026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.11ms)17492026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (1.57ms)17502026/10/01 07:32:27 goose: successfully migrated database to version: 202609231200001751=== NAME TestNARDeduplicationMetadataUploadBug1752 metadata_upload_test.go:54: Retrieved narinfo from S3:1753 StorePath: /build/TestNARDeduplicationMetadataUploadBug859241779/001/store/pz0k5la6kdk85zn1vf6mj26wvf32nhd2-file1.txt1754 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1755 Compression: zstd1756 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1757 NarSize: 1601758 References: 1759 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf17602026-10-01 07:32:27.909 UTC [648] ERROR: relation "goose_db_version" does not exist at character 3617612026-10-01 07:32:27.909 UTC [648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17622026/10/01 07:32:27 OK 1_commit_pending_closure.sql (1.71ms)17632026/10/01 07:32:27 OK 20260905000000_add_claims.sql (2.64ms)17642026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.15ms)1765 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1766 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1767 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}17682026/10/01 07:32:27 OK 3_commit_push.sql (966.99µs)17692026/10/01 07:32:27 goose: up to current file version: 317702026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (1.9ms)17712026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures17722026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (1.45ms)17732026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000017742026-10-01 07:32:27.915 UTC [649] ERROR: relation "goose_db_version" does not exist at character 3617752026-10-01 07:32:27.915 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17762026/10/01 07:32:27 OK 1_commit_pending_closure.sql (1.6ms)1777--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.65s)1778=== CONT TestClientWithDependencies17792026/10/01 07:32:27 OK 2_object_stats_trigger.sql (693.19µs)17802026/10/01 07:32:27 INFO Aborted multipart uploads count=017812026/10/01 07:32:27 WARN Force mode enabled - objects will be deleted immediately without grace period17822026/10/01 07:32:27 OK 3_commit_push.sql (10.24ms)17832026/10/01 07:32:27 goose: up to current file version: 317842026/10/01 07:32:27 OK 20241026095416_initial_model.sql (13.36ms)17852026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (1.99ms)17862026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.42ms)17872026/10/01 07:32:27 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=017882026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (4.64ms)17892026/10/01 07:32:27 INFO Vacuumed table table=pending_closures17902026/10/01 07:32:27 OK 20241026095416_initial_model.sql (10.33ms)17912026/10/01 07:32:27 INFO Vacuumed table table=pending_objects17922026/10/01 07:32:27 INFO Vacuumed table table=multipart_uploads17932026/10/01 07:32:27 INFO Vacuumed table table=closures17942026/10/01 07:32:27 OK 20251210153512_drop_unused_gin_index.sql (1.27ms)17952026/10/01 07:32:27 OK 20260905000000_add_claims.sql (2.9ms)17962026/10/01 07:32:27 INFO Vacuumed table table=objects1797--- PASS: TestGCSweepDeliversEachKeyOnce (0.71s)1798=== CONT TestClientMultipleUploads17992026/10/01 07:32:27 OK 20251218171726_add_pins.sql (3.44ms)18002026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.57ms)18012026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures1802=== NAME TestNARDeduplicationMetadataUploadBug1803 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug859241779/001/store/cppq7rrwhg0bqjxi26qh6wwak9vg5mn9-file2.txt18042026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (2.67ms)18052026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000018062026/10/01 07:32:27 OK 20260628120000_add_object_size_and_stats.sql (3.84ms)18072026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.49ms)18082026/10/01 07:32:27 OK 2_object_stats_trigger.sql (2.06ms)18092026/10/01 07:32:27 OK 20260905000000_add_claims.sql (3.98ms)18102026/10/01 07:32:27 OK 3_commit_push.sql (961.19µs)18112026/10/01 07:32:27 goose: up to current file version: 318122026/10/01 07:32:27 OK 20260920000000_drop_claims.sql (2.24ms)18132026/10/01 07:32:27 OK 20260923120000_add_pushes.sql (2.75ms)18142026/10/01 07:32:27 goose: successfully migrated database to version: 2026092312000018152026/10/01 07:32:27 OK 1_commit_pending_closure.sql (2.38ms)18162026/10/01 07:32:27 OK 2_object_stats_trigger.sql (1.62ms)18172026/10/01 07:32:27 OK 3_commit_push.sql (1.61ms)18182026/10/01 07:32:27 goose: up to current file version: 318192026/10/01 07:32:27 INFO Aborted multipart uploads count=018202026/10/01 07:32:27 WARN Force mode enabled - objects will be deleted immediately without grace period18212026/10/01 07:32:27 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=018222026/10/01 07:32:27 INFO Aborted multipart uploads count=018232026/10/01 07:32:27 INFO Vacuumed table table=pending_closures18242026/10/01 07:32:27 INFO Vacuumed table table=pending_objects18252026/10/01 07:32:27 INFO Vacuumed table table=multipart_uploads18262026/10/01 07:32:27 INFO Vacuumed table table=closures18272026/10/01 07:32:27 WARN Force mode enabled - objects will be deleted immediately without grace period18282026/10/01 07:32:27 INFO Vacuumed table table=objects18292026/10/01 07:32:27 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=018302026/10/01 07:32:27 INFO Vacuumed table table=pending_closures18312026/10/01 07:32:27 INFO Vacuumed table table=pending_objects18322026/10/01 07:32:27 INFO Vacuumed table table=multipart_uploads18332026/10/01 07:32:27 INFO Vacuumed table table=closures18342026/10/01 07:32:27 INFO Vacuumed table table=objects1835--- PASS: TestGCMetrics (0.69s)1836=== CONT TestCreatePin_ReservedPins1837--- PASS: TestGCSweepSkipsPendingObjects (0.70s)1838=== CONT TestIsValidCachePath1839=== RUN TestIsValidCachePath/narinfo1840=== PAUSE TestIsValidCachePath/narinfo1841=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1842=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1843=== RUN TestIsValidCachePath/nar_zst1844=== PAUSE TestIsValidCachePath/nar_zst1845=== RUN TestIsValidCachePath/nar_xz1846=== PAUSE TestIsValidCachePath/nar_xz1847=== RUN TestIsValidCachePath/nar_bz21848=== PAUSE TestIsValidCachePath/nar_bz21849=== RUN TestIsValidCachePath/nar_uncompressed1850=== PAUSE TestIsValidCachePath/nar_uncompressed1851=== RUN TestIsValidCachePath/ls1852=== PAUSE TestIsValidCachePath/ls1853=== RUN TestIsValidCachePath/log1854=== PAUSE TestIsValidCachePath/log1855=== RUN TestIsValidCachePath/realisation1856=== PAUSE TestIsValidCachePath/realisation1857=== RUN TestIsValidCachePath/nix-cache-info1858=== PAUSE TestIsValidCachePath/nix-cache-info1859=== RUN TestIsValidCachePath/index.html1860=== PAUSE TestIsValidCachePath/index.html1861=== RUN TestIsValidCachePath/traversal_parent1862=== PAUSE TestIsValidCachePath/traversal_parent1863=== RUN TestIsValidCachePath/traversal_in_middle1864=== PAUSE TestIsValidCachePath/traversal_in_middle1865=== RUN TestIsValidCachePath/invalid_char_e1866=== PAUSE TestIsValidCachePath/invalid_char_e18672026/10/01 07:32:27 INFO Received uploads request method=POST path=/api/pending_closures1868=== RUN TestIsValidCachePath/invalid_char_u1869=== PAUSE TestIsValidCachePath/invalid_char_u1870=== RUN TestIsValidCachePath/random_path1871=== PAUSE TestIsValidCachePath/random_path1872=== RUN TestIsValidCachePath/empty1873=== PAUSE TestIsValidCachePath/empty1874=== RUN TestIsValidCachePath/leading_slash1875=== PAUSE TestIsValidCachePath/leading_slash1876=== RUN TestIsValidCachePath/wrong_extension1877=== PAUSE TestIsValidCachePath/wrong_extension1878=== RUN TestIsValidCachePath/short_hash1879=== PAUSE TestIsValidCachePath/short_hash1880=== CONT TestProxyHeadersOnlyTrustedOnSocket1881--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.67s)1882=== CONT TestReadProxyNarinfoAlreadyDecompressed18832026-10-01 07:32:28.003 UTC [694] ERROR: relation "goose_db_version" does not exist at character 3618842026-10-01 07:32:28.003 UTC [694] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18852026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes18862026/10/01 07:32:28 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)18872026/10/01 07:32:28 OK 20241026095416_initial_model.sql (8.89ms)18882026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18892026/10/01 07:32:28 WARN Failed to register uploaded object key=cppq7rrwhg0bqjxi26qh6wwak9vg5mn9.ls error="server returned 404: 404 page not found\n"18902026/10/01 07:32:28 INFO Signed narinfos id=2 count=118912026/10/01 07:32:28 INFO Uploading 1 narinfos18922026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)18932026-10-01 07:32:28.020 UTC [715] ERROR: relation "goose_db_version" does not exist at character 3618942026-10-01 07:32:28.020 UTC [715] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18952026/10/01 07:32:28 INFO Received complete push request method=POST path=/api/pushes/2/complete18962026/10/01 07:32:28 WARN Failed to register uploaded object key=cppq7rrwhg0bqjxi26qh6wwak9vg5mn9.narinfo error="server returned 404: 404 page not found\n"18972026/10/01 07:32:28 OK 20251218171726_add_pins.sql (4.2ms)18982026/10/01 07:32:28 INFO Upload complete. (49ms)18992026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (4.49ms)1900=== NAME TestNARDeduplicationMetadataUploadBug1901 metadata_upload_test.go:76: Retrieved narinfo from S3:1902 StorePath: /build/TestNARDeduplicationMetadataUploadBug859241779/001/store/cppq7rrwhg0bqjxi26qh6wwak9vg5mn9-file2.txt1903 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1904 Compression: zstd1905 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1906 NarSize: 1601907 References: 1908 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf19092026/10/01 07:32:28 OK 20260905000000_add_claims.sql (3.99ms)1910 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1911 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1912 {"version":1,"root":{"type":"regular","size":44}}19132026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (2.67ms)1914--- PASS: TestNARDeduplicationMetadataUploadBug (0.94s)1915=== CONT TestParseSingleRange1916=== RUN TestParseSingleRange/none1917=== PAUSE TestParseSingleRange/none1918=== RUN TestParseSingleRange/unknown_unit1919=== PAUSE TestParseSingleRange/unknown_unit1920=== RUN TestParseSingleRange/multi-range_ignored1921=== PAUSE TestParseSingleRange/multi-range_ignored1922=== RUN TestParseSingleRange/malformed_no_dash1923=== PAUSE TestParseSingleRange/malformed_no_dash1924=== RUN TestParseSingleRange/malformed_both_empty1925=== PAUSE TestParseSingleRange/malformed_both_empty1926=== RUN TestParseSingleRange/malformed_end_before_start1927=== PAUSE TestParseSingleRange/malformed_end_before_start1928=== RUN TestParseSingleRange/closed1929=== PAUSE TestParseSingleRange/closed1930=== RUN TestParseSingleRange/open-ended1931=== PAUSE TestParseSingleRange/open-ended1932=== RUN TestParseSingleRange/end_clamped_to_size1933=== PAUSE TestParseSingleRange/end_clamped_to_size1934=== RUN TestParseSingleRange/suffix1935=== PAUSE TestParseSingleRange/suffix1936=== RUN TestParseSingleRange/suffix_exceeds_size1937=== PAUSE TestParseSingleRange/suffix_exceeds_size1938=== RUN TestParseSingleRange/single_byte1939=== PAUSE TestParseSingleRange/single_byte1940=== RUN TestParseSingleRange/start_past_EOF1941=== PAUSE TestParseSingleRange/start_past_EOF1942=== RUN TestParseSingleRange/start_far_past_EOF1943=== PAUSE TestParseSingleRange/start_far_past_EOF1944=== CONT TestReadProxyNarinfo19452026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (2.36ms)19462026/10/01 07:32:28 goose: successfully migrated database to version: 2026092312000019472026/10/01 07:32:28 OK 1_commit_pending_closure.sql (3.18ms)19482026/10/01 07:32:28 OK 20241026095416_initial_model.sql (13.15ms)19492026/10/01 07:32:28 OK 2_object_stats_trigger.sql (1.4ms)19502026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)19512026/10/01 07:32:28 OK 3_commit_push.sql (1.92ms)19522026/10/01 07:32:28 goose: up to current file version: 319532026/10/01 07:32:28 OK 20251218171726_add_pins.sql (5.15ms)19542026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (4.67ms)19552026/10/01 07:32:28 OK 20260905000000_add_claims.sql (3.99ms)19562026/10/01 07:32:28 INFO lead: acquired remote=192.0.2.1:123419572026/10/01 07:32:28 INFO lead: released remote=192.0.2.1:12341958--- PASS: TestLeadEndsOnShutdown (0.63s)1959=== CONT TestOrphanedObjectsGC19602026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (2.82ms)19612026-10-01 07:32:28.062 UTC [719] ERROR: relation "goose_db_version" does not exist at character 3619622026-10-01 07:32:28.062 UTC [719] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19632026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (2.8ms)19642026/10/01 07:32:28 goose: successfully migrated database to version: 2026092312000019652026/10/01 07:32:28 OK 1_commit_pending_closure.sql (2.3ms)19662026/10/01 07:32:28 OK 2_object_stats_trigger.sql (1.43ms)19672026/10/01 07:32:28 OK 3_commit_push.sql (1.26ms)19682026/10/01 07:32:28 goose: up to current file version: 31969--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.85s)1970=== CONT TestResurrectedObjectNotDeleted19712026-10-01 07:32:28.071 UTC [727] ERROR: relation "goose_db_version" does not exist at character 3619722026-10-01 07:32:28.071 UTC [727] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1973=== NAME TestClientIntegration1974 client_integration_test.go:286: Created store path: /build/TestClientIntegration1958314343/002/store/krzwzl1wk0m3cwikab0aylbs1xkhzcgd-test-file.txt19752026/10/01 07:32:28 OK 20241026095416_initial_model.sql (9.91ms)19762026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (2.23ms)19772026/10/01 07:32:28 OK 20251218171726_add_pins.sql (9.66ms)19782026/10/01 07:32:28 OK 20241026095416_initial_model.sql (14.2ms)19792026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (3.02ms)19802026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (5.29ms)19812026/10/01 07:32:28 OK 20260905000000_add_claims.sql (7.77ms)19822026/10/01 07:32:28 OK 20251218171726_add_pins.sql (11.99ms)19832026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (8.74ms)19842026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (8.12ms)19852026-10-01 07:32:28.116 UTC [760] ERROR: relation "goose_db_version" does not exist at character 3619862026-10-01 07:32:28.116 UTC [760] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19872026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (9.68ms)19882026/10/01 07:32:28 goose: successfully migrated database to version: 2026092312000019892026/10/01 07:32:28 OK 20260905000000_add_claims.sql (14.18ms)19902026/10/01 07:32:28 OK 1_commit_pending_closure.sql (13.46ms)19912026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (10.03ms)19922026/10/01 07:32:28 OK 2_object_stats_trigger.sql (7.61ms)19932026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (4.33ms)19942026/10/01 07:32:28 goose: successfully migrated database to version: 2026092312000019952026/10/01 07:32:28 OK 20241026095416_initial_model.sql (12.59ms)19962026/10/01 07:32:28 OK 3_commit_push.sql (1.25ms)19972026/10/01 07:32:28 goose: up to current file version: 319982026-10-01 07:32:28.145 UTC [778] ERROR: relation "goose_db_version" does not exist at character 3619992026-10-01 07:32:28.145 UTC [778] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20002026/10/01 07:32:28 OK 1_commit_pending_closure.sql (2.76ms)20012026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (2.71ms)20022026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes20032026/10/01 07:32:28 OK 2_object_stats_trigger.sql (975.05µs)20042026/10/01 07:32:28 OK 3_commit_push.sql (807.91µs)20052026/10/01 07:32:28 goose: up to current file version: 320062026/10/01 07:32:28 OK 20251218171726_add_pins.sql (2.88ms)20072026/10/01 07:32:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20082026/10/01 07:32:28 INFO Uploading krzwzl1wk0m3cwikab0aylbs1xkhzcgd-test-file.txt (152B)2009--- PASS: TestCacheStatsHandler (0.72s)2010=== CONT TestOrphanedObjectsGCStressTest20112026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (4.87ms)20122026-10-01 07:32:28.157 UTC [797] ERROR: relation "goose_db_version" does not exist at character 3620132026-10-01 07:32:28.157 UTC [797] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20142026/10/01 07:32:28 WARN Failed to register uploaded object key=krzwzl1wk0m3cwikab0aylbs1xkhzcgd.ls error="server returned 404: 404 page not found\n"20152026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20162026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"20172026/10/01 07:32:28 OK 20260905000000_add_claims.sql (3.38ms)20182026/10/01 07:32:28 INFO Signed narinfos id=1 count=120192026/10/01 07:32:28 INFO Uploading 1 narinfos20202026/10/01 07:32:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36517/oidc20212026/10/01 07:32:28 OK 20241026095416_initial_model.sql (8.78ms)20222026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (2.8ms)20232026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)20242026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (1.64ms)20252026/10/01 07:32:28 goose: successfully migrated database to version: 2026092312000020262026/10/01 07:32:28 INFO Received complete push request method=POST path=/api/pushes/1/complete20272026/10/01 07:32:28 WARN Failed to register uploaded object key=krzwzl1wk0m3cwikab0aylbs1xkhzcgd.narinfo error="server returned 404: 404 page not found\n"20282026/10/01 07:32:28 OK 1_commit_pending_closure.sql (2.21ms)20292026/10/01 07:32:28 OK 20251218171726_add_pins.sql (3.91ms)20302026/10/01 07:32:28 OK 2_object_stats_trigger.sql (1.4ms)20312026/10/01 07:32:28 OK 3_commit_push.sql (1.35ms)20322026/10/01 07:32:28 goose: up to current file version: 320332026/10/01 07:32:28 INFO lead: acquired remote=192.0.2.1:123420342026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (5.84ms)20352026/10/01 07:32:28 INFO Upload complete. (64ms)20362026/10/01 07:32:28 OK 20241026095416_initial_model.sql (10.76ms)20372026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (3.07ms)20382026/10/01 07:32:28 OK 20260905000000_add_claims.sql (5.1ms)20392026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (2.94ms)20402026/10/01 07:32:28 OK 20251218171726_add_pins.sql (4.11ms)20412026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (2.46ms)20422026/10/01 07:32:28 goose: successfully migrated database to version: 2026092312000020432026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (4.53ms)20442026/10/01 07:32:28 OK 1_commit_pending_closure.sql (3.53ms)20452026/10/01 07:32:28 OK 2_object_stats_trigger.sql (1.51ms)20462026/10/01 07:32:28 OK 3_commit_push.sql (1.56ms)20472026/10/01 07:32:28 goose: up to current file version: 320482026/10/01 07:32:28 OK 20260905000000_add_claims.sql (4.59ms)2049=== NAME TestClientCADerivations2050 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations123950264/001/store/4q8aywz2ybgi6521iw8symz8cbi6qc2i-ca-test20512026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (3.17ms)20522026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (2.61ms)2053--- PASS: TestService_ReadScope_PublicByDefault (0.71s)20542026/10/01 07:32:28 goose: successfully migrated database to version: 202609231200002055=== CONT TestObjectStatsTrigger20562026/10/01 07:32:28 OK 1_commit_pending_closure.sql (2.53ms)20572026/10/01 07:32:28 OK 2_object_stats_trigger.sql (1.63ms)20582026/10/01 07:32:28 OK 3_commit_push.sql (1.17ms)20592026/10/01 07:32:28 goose: up to current file version: 320602026/10/01 07:32:28 INFO All 1 paths already cached2061=== NAME TestClientIntegration2062 client_integration_test.go:312: Retrieved narinfo from S3:2063 StorePath: /build/TestClientIntegration1958314343/002/store/krzwzl1wk0m3cwikab0aylbs1xkhzcgd-test-file.txt2064 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2065 Compression: zstd2066 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12067 NarSize: 1522068 References: 2069 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12070=== NAME TestClientCADerivations2071 client_ca_test.go:139: Found 1 dependencies (including self)2072=== NAME TestClientIntegration2073 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2074 client_integration_test.go:313: Decompressed .ls content (64 bytes):2075 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2076 client_integration_test.go:316: Testing garbage collection...20772026-10-01 07:32:28.235 UTC [860] ERROR: relation "goose_db_version" does not exist at character 3620782026-10-01 07:32:28.235 UTC [860] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20792026-10-01 07:32:28.240 UTC [861] ERROR: relation "goose_db_version" does not exist at character 3620802026-10-01 07:32:28.240 UTC [861] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2081--- PASS: TestGCBugBareHashReferences (0.90s)2082=== CONT TestMultipartCleanup20832026/10/01 07:32:28 OK 20241026095416_initial_model.sql (10.15ms)20842026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)20852026/10/01 07:32:28 OK 20241026095416_initial_model.sql (9.93ms)20862026/10/01 07:32:28 OK 20251218171726_add_pins.sql (3.66ms)20872026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (2.43ms)20882026/10/01 07:32:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures20892026/10/01 07:32:28 INFO Garbage collection started20902026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (4.02ms)20912026/10/01 07:32:28 OK 20251218171726_add_pins.sql (4.57ms)20922026/10/01 07:32:28 OK 20260905000000_add_claims.sql (3.63ms)20932026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (4.05ms)20942026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (2.14ms)20952026/10/01 07:32:28 INFO Aborted multipart uploads count=020962026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (2.85ms)20972026/10/01 07:32:28 goose: successfully migrated database to version: 2026092312000020982026/10/01 07:32:28 OK 20260905000000_add_claims.sql (5.13ms)20992026/10/01 07:32:28 OK 1_commit_pending_closure.sql (2.55ms)2100=== RUN TestService_RequireScope_OIDC/builder_may_write2101=== PAUSE TestService_RequireScope_OIDC/builder_may_write2102=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2103=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2104=== RUN TestService_RequireScope_OIDC/ops_may_admin2105=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2106=== RUN TestService_RequireScope_OIDC/ops_may_not_write2107=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2108=== RUN TestService_RequireScope_OIDC/reader_may_not_write2109=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2110=== RUN TestService_RequireScope_OIDC/static_token_may_admin2111=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2112=== RUN TestService_RequireScope_OIDC/static_token_may_write2113=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2114=== RUN TestService_RequireScope_OIDC/reader_may_read2115=== PAUSE TestService_RequireScope_OIDC/reader_may_read2116=== RUN TestService_RequireScope_OIDC/writer_implies_read2117=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2118=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read21192026/10/01 07:32:28 WARN Force mode enabled - objects will be deleted immediately without grace period2120=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2121=== CONT TestProxyWriteTimeout/narinfo2122=== CONT TestProxyWriteTimeout/unknown_size2123=== CONT TestProxyWriteTimeout/10_GiB_nar2124=== CONT TestProxyWriteTimeout/1_GiB_nar2125--- PASS: TestProxyWriteTimeout (0.00s)2126 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2127 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2128 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2129 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2130=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info21312026/10/01 07:32:28 INFO Received uploads request method=POST path=/2132=== CONT TestServerTLSConfig/no_client_CA2133=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key21342026/10/01 07:32:28 INFO Received complete multipart upload request method=POST path=/2135=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key21362026/10/01 07:32:28 INFO Received request for more parts method=POST path=/2137=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal21382026/10/01 07:32:28 OK 2_object_stats_trigger.sql (1.05ms)21392026/10/01 07:32:28 INFO Received uploads request method=POST path=/2140--- PASS: TestUploadHandlersRejectInvalidKeys (0.06s)2141 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2142 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2143 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2144 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)21452026-10-01 07:32:28.276 UTC [917] ERROR: relation "goose_db_version" does not exist at character 3621462026-10-01 07:32:28.276 UTC [917] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2147=== CONT TestServerTLSConfig/not_a_PEM_file21482026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (2.81ms)21492026/10/01 07:32:28 OK 3_commit_push.sql (872.75µs)21502026/10/01 07:32:28 goose: up to current file version: 32151=== CONT TestServerTLSConfig/missing_CA_file2152--- PASS: TestServerTLSConfig (0.06s)2153 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2154 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2155 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2156=== CONT TestIsValidUploadKey/narinfo2157=== CONT TestIsValidUploadKey/realisation_plus_in_output2158=== CONT TestIsValidUploadKey/unknown_type2159=== CONT TestIsValidUploadKey/empty_key2160=== CONT TestIsValidUploadKey/absolute2161=== CONT TestIsValidUploadKey/traversal_nar2162=== CONT TestIsValidUploadKey/traversal2163=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2164=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2165=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2166=== CONT TestIsValidUploadKey/index.html2167=== CONT TestIsValidUploadKey/nix-cache-info2168=== CONT TestIsValidUploadKey/build_log_home-manager_file2169=== CONT TestIsValidUploadKey/realisation2170=== CONT TestIsValidUploadKey/build_log_equals2171=== CONT TestIsValidUploadKey/build_log_question_mark2172=== CONT TestIsValidUploadKey/build_log_plus_in_name2173=== CONT TestIsValidUploadKey/nar_plain2174=== CONT TestIsValidUploadKey/build_log2175=== CONT TestIsValidUploadKey/listing2176=== CONT TestIsValidUploadKey/nar_xz2177=== CONT TestIsValidUploadKey/nar_zst2178--- PASS: TestIsValidUploadKey (0.06s)2179 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2180 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2181 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2182 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2183 --- PASS: TestIsValidUploadKey/absolute (0.00s)2184 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2185 --- PASS: TestIsValidUploadKey/traversal (0.00s)2186 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2187 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2188 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2189 --- PASS: TestIsValidUploadKey/index.html (0.00s)2190 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2191 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2192 --- PASS: TestIsValidUploadKey/realisation (0.00s)2193 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2194 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2195 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2196 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2197 --- PASS: TestIsValidUploadKey/build_log (0.00s)2198 --- PASS: TestIsValidUploadKey/listing (0.00s)2199 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2200 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2201=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure22022026/10/01 07:32:28 INFO Received uploads request method=POST path=/22032026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (3.36ms)22042026/10/01 07:32:28 goose: successfully migrated database to version: 2026092312000022052026/10/01 07:32:28 OK 1_commit_pending_closure.sql (4.48ms)22062026/10/01 07:32:28 OK 2_object_stats_trigger.sql (2.43ms)22072026/10/01 07:32:28 OK 3_commit_push.sql (1.61ms)22082026/10/01 07:32:28 goose: up to current file version: 32209=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2210=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2211=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2212=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2213=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2214=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2215=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2216=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2217=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts22182026/10/01 07:32:28 INFO Received request for more parts method=POST path=/22192026/10/01 07:32:28 OK 20241026095416_initial_model.sql (9.93ms)22202026/10/01 07:32:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=022212026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (2.16ms)22222026/10/01 07:32:28 INFO Vacuumed table table=pending_closures22232026/10/01 07:32:28 OK 20251218171726_add_pins.sql (3.67ms)22242026/10/01 07:32:28 INFO Vacuumed table table=pending_objects22252026/10/01 07:32:28 INFO Vacuumed table table=multipart_uploads22262026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (5.33ms)22272026/10/01 07:32:28 INFO Vacuumed table table=closures22282026/10/01 07:32:28 INFO Vacuumed table table=objects22292026/10/01 07:32:28 OK 20260905000000_add_claims.sql (3.69ms)22302026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (2.53ms)22312026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (2.54ms)22322026/10/01 07:32:28 goose: successfully migrated database to version: 2026092312000022332026/10/01 07:32:28 OK 1_commit_pending_closure.sql (2.19ms)22342026/10/01 07:32:28 OK 2_object_stats_trigger.sql (1.22ms)22352026/10/01 07:32:28 OK 3_commit_push.sql (1.09ms)22362026/10/01 07:32:28 goose: up to current file version: 322372026/10/01 07:32:28 INFO lead: released remote=192.0.2.1:123422382026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes22392026-10-01 07:32:28.331 UTC [962] ERROR: relation "goose_db_version" does not exist at character 3622402026-10-01 07:32:28.331 UTC [962] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22412026/10/01 07:32:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22422026/10/01 07:32:28 INFO Uploading 4q8aywz2ybgi6521iw8symz8cbi6qc2i-ca-test (144B)22432026/10/01 07:32:28 WARN Failed to register uploaded object key=log/wn20x9ywsn15qiphljy0x3zw0b9lg1j2-ca-test.drv error="server returned 404: 404 page not found\n"22442026/10/01 07:32:28 WARN Failed to register uploaded object key=4q8aywz2ybgi6521iw8symz8cbi6qc2i.ls error="server returned 404: 404 page not found\n"22452026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22462026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"22472026/10/01 07:32:28 INFO Signed narinfos id=1 count=12248=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart22492026/10/01 07:32:28 INFO Uploading 1 narinfos22502026/10/01 07:32:28 INFO Received complete multipart upload request method=POST path=/2251--- PASS: TestService_ReadAuthMiddleware (0.60s)2252=== CONT TestPush_RejectsBadRequests/no_roots22532026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes2254=== CONT TestPush_RejectsBadRequests/bad_root22552026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes2256=== CONT TestPush_RejectsBadRequests/root_not_in_objects22572026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes2258=== CONT TestPush_RejectsBadRequests/no_objects22592026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes2260=== CONT TestClientErrorHandling/InvalidStorePath2261--- PASS: TestPush_RejectsBadRequests (0.94s)2262 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2263 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2264 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2265 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)22662026/10/01 07:32:28 OK 20241026095416_initial_model.sql (8.52ms)22672026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (1.36ms)22682026/10/01 07:32:28 INFO Received complete push request method=POST path=/api/pushes/1/complete22692026/10/01 07:32:28 WARN Failed to register uploaded object key=4q8aywz2ybgi6521iw8symz8cbi6qc2i.narinfo error="server returned 404: 404 page not found\n"22702026/10/01 07:32:28 OK 20251218171726_add_pins.sql (2.84ms)22712026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (3.01ms)22722026/10/01 07:32:28 INFO Upload complete. (99ms)22732026/10/01 07:32:28 OK 20260905000000_add_claims.sql (3.89ms)22742026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (2.34ms)2275=== NAME TestClientCADerivations2276 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations123950264/001/store/4q8aywz2ybgi6521iw8symz8cbi6qc2i-ca-test2277 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2278 Compression: zstd2279 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2280 NarSize: 1442281 References: 2282 Deriver: /build/TestClientCADerivations123950264/001/store/wn20x9ywsn15qiphljy0x3zw0b9lg1j2-ca-test.drv2283 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2284 client_ca_test.go:185: Checking for realisation files in S3...22852026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (2.6ms)22862026/10/01 07:32:28 goose: successfully migrated database to version: 202609231200002287 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2288 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache22892026/10/01 07:32:28 OK 1_commit_pending_closure.sql (2.58ms)22902026/10/01 07:32:28 OK 2_object_stats_trigger.sql (1.92ms)22912026/10/01 07:32:28 OK 3_commit_push.sql (1.31ms)22922026/10/01 07:32:28 goose: up to current file version: 322932026/10/01 07:32:28 INFO lead: acquired remote=192.0.2.1:123422942026/10/01 07:32:28 INFO lead: released remote=192.0.2.1:12342295--- PASS: TestLeadElectsOneAndHandsOver (0.93s)2296=== CONT TestClientErrorHandling/ServerNotAvailable2297=== CONT TestClientErrorHandling/InvalidAuthToken22982026/10/01 07:32:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"22992026/10/01 07:32:28 WARN mTLS auth: bound subjects configured but subject DN unavailable23002026/10/01 07:32:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2301--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.61s)2302=== CONT TestCacheConfigHandler/full_config,_no_issuer2303=== CONT TestResolveDBConnectionString/flag_wins2304=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2305=== CONT TestCacheConfigHandler/no_signing_keys2306=== CONT TestCacheConfigHandler/no_cache_url_configured2307--- PASS: TestCacheConfigHandler (0.00s)2308 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2309 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2310 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2311 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2312=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2313=== CONT TestResolveDBConnectionString/nothing_configured2314=== CONT TestResolveDBConnectionString/missing_file_is_an_error2315=== CONT TestResolveDBConnectionString/file_when_flag_empty2316--- PASS: TestResolveDBConnectionString (0.00s)2317 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2318 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2319 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2320 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2321 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2322=== CONT TestIsValidCachePath/narinfo2323=== CONT TestIsValidCachePath/index.html2324=== CONT TestIsValidCachePath/short_hash2325=== CONT TestIsValidCachePath/wrong_extension2326=== CONT TestIsValidCachePath/leading_slash2327=== CONT TestIsValidCachePath/empty2328=== CONT TestIsValidCachePath/random_path2329=== CONT TestIsValidCachePath/invalid_char_u2330=== CONT TestIsValidCachePath/invalid_char_e2331=== CONT TestIsValidCachePath/traversal_in_middle2332=== CONT TestIsValidCachePath/traversal_parent2333=== CONT TestIsValidCachePath/nar_uncompressed2334=== CONT TestIsValidCachePath/nix-cache-info2335=== CONT TestIsValidCachePath/realisation2336=== CONT TestIsValidCachePath/log2337=== CONT TestIsValidCachePath/ls2338=== CONT TestIsValidCachePath/nar_xz2339=== CONT TestIsValidCachePath/nar_bz22340=== CONT TestIsValidCachePath/nar_zst2341=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2342--- PASS: TestIsValidCachePath (0.00s)2343 --- PASS: TestIsValidCachePath/narinfo (0.00s)2344 --- PASS: TestIsValidCachePath/index.html (0.00s)2345 --- PASS: TestIsValidCachePath/short_hash (0.00s)2346 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2347 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2348 --- PASS: TestIsValidCachePath/empty (0.00s)2349 --- PASS: TestIsValidCachePath/random_path (0.00s)2350 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2351 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2352 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2353 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2354 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2355 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2356 --- PASS: TestIsValidCachePath/realisation (0.00s)2357 --- PASS: TestIsValidCachePath/log (0.00s)2358 --- PASS: TestIsValidCachePath/ls (0.00s)2359 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2360 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2361 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2362 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2363=== CONT TestParseSingleRange/none2364=== CONT TestParseSingleRange/open-ended2365=== CONT TestParseSingleRange/start_far_past_EOF2366=== CONT TestParseSingleRange/suffix2367=== CONT TestParseSingleRange/end_clamped_to_size2368=== CONT TestParseSingleRange/start_past_EOF2369=== CONT TestParseSingleRange/malformed_both_empty2370=== CONT TestParseSingleRange/suffix_exceeds_size2371=== CONT TestParseSingleRange/closed2372=== CONT TestParseSingleRange/single_byte2373=== CONT TestParseSingleRange/malformed_end_before_start2374=== CONT TestParseSingleRange/unknown_unit2375=== CONT TestParseSingleRange/malformed_no_dash2376=== CONT TestParseSingleRange/multi-range_ignored2377--- PASS: TestParseSingleRange (0.00s)2378 --- PASS: TestParseSingleRange/none (0.00s)2379 --- PASS: TestParseSingleRange/open-ended (0.00s)2380 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2381 --- PASS: TestParseSingleRange/suffix (0.00s)2382 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2383 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2384 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2385 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2386 --- PASS: TestParseSingleRange/closed (0.00s)2387 --- PASS: TestParseSingleRange/single_byte (0.00s)2388 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2389 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2390 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2391 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2392=== CONT TestService_RequireScope_OIDC/builder_may_write2393=== CONT TestService_RequireScope_OIDC/static_token_may_admin2394=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2395=== CONT TestService_RequireScope_OIDC/writer_implies_read2396=== CONT TestService_RequireScope_OIDC/reader_may_read2397=== CONT TestService_RequireScope_OIDC/static_token_may_write2398=== CONT TestService_RequireScope_OIDC/reader_may_not_write2399=== CONT TestService_RequireScope_OIDC/ops_may_admin2400=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2401=== CONT TestService_RequireScope_OIDC/ops_may_not_write2402=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2403--- PASS: TestService_RequireScope_OIDC (0.73s)2404 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2405 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2406 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2407 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2408 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2409 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2410 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2411 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2412 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2413 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)24142026/10/01 07:32:28 INFO Received uploads request method=POST path=/api/pending_closures2415=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected24162026/10/01 07:32:28 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]2417=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2418=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected24192026/10/01 07:32:28 WARN Authentication failed token_preview=eyJhbGciOi...NzHu07jogA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2420--- PASS: TestService_AuthMiddleware_OIDC (0.69s)2421 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2422 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2423 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2424 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)24252026/10/01 07:32:28 INFO Received uploads request method=POST path=/api/pending_closures24262026/10/01 07:32:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)24272026/10/01 07:32:28 INFO Uploading x7v458pa4lkp98rlh7r6rmhycij9fw8l-b (216B)24282026/10/01 07:32:28 INFO Uploading 74i16bbzpr56fahdz0py5ccvawsnylc9-shared-dep (136B)24292026-10-01 07:32:28.421 UTC [1119] ERROR: relation "goose_db_version" does not exist at character 3624302026-10-01 07:32:28.421 UTC [1119] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24312026/10/01 07:32:28 WARN Failed to register uploaded object key=x7v458pa4lkp98rlh7r6rmhycij9fw8l.ls error="server returned 404: 404 page not found\n"24322026/10/01 07:32:28 WARN Failed to register uploaded object key=ammimqamx8zianfw2c5i4i2dk8zyp85j.ls error="server returned 404: 404 page not found\n"24332026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24342026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign24352026/10/01 07:32:28 WARN Failed to register uploaded object key=74i16bbzpr56fahdz0py5ccvawsnylc9.ls error="server returned 404: 404 page not found\n"24362026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/0nr54q43l4z1zmb31ldiv8kr95052g7a8zpng27486g797635m6s.nar.zst error="server returned 404: 404 page not found\n"24372026/10/01 07:32:28 INFO Signed narinfos id=1 count=224382026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign24392026/10/01 07:32:28 INFO Signed narinfos id=2 count=224402026/10/01 07:32:28 INFO Uploading 4 narinfos24412026/10/01 07:32:28 WARN Failed to register uploaded object key=ammimqamx8zianfw2c5i4i2dk8zyp85j.narinfo error="server returned 404: 404 page not found\n"24422026/10/01 07:32:28 WARN Failed to register uploaded object key=74i16bbzpr56fahdz0py5ccvawsnylc9.narinfo error="server returned 404: 404 page not found\n"24432026/10/01 07:32:28 WARN Failed to register uploaded object key=x7v458pa4lkp98rlh7r6rmhycij9fw8l.narinfo error="server returned 404: 404 page not found\n"24442026/10/01 07:32:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete24452026/10/01 07:32:28 WARN Failed to register uploaded object key=74i16bbzpr56fahdz0py5ccvawsnylc9.narinfo error="server returned 404: 404 page not found\n"24462026/10/01 07:32:28 OK 20241026095416_initial_model.sql (11.04ms)24472026/10/01 07:32:28 INFO Completed upload id=124482026/10/01 07:32:28 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete24492026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (3.44ms)24502026/10/01 07:32:28 INFO Completed upload id=224512026/10/01 07:32:28 INFO Upload complete. (75ms)2452=== NAME TestClientFallsBackToClosures2453 client_pushes_test.go:112: Retrieved narinfo from S3:2454 StorePath: /build/TestClientFallsBackToClosures3860573748/001/store/74i16bbzpr56fahdz0py5ccvawsnylc9-shared-dep2455 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2456 Compression: zstd2457 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822458 NarSize: 1362459 References: 2460 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n24612026/10/01 07:32:28 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/present24622026/10/01 07:32:28 OK 20251218171726_add_pins.sql (5.2ms)2463=== NAME TestPinProtectsFromGC2464 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC3968030983/001/store/0l754ypis1zfsx5ciygjz04bnb18qbmh-pinned-file.txt2465 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC3968030983/001/store/xr0khb4bz8qh0p76y27w7asiv1kvyrfi-unpinned-file.txt2466=== NAME TestClientFallsBackToClosures2467 client_pushes_test.go:112: Retrieved narinfo from S3:2468 StorePath: /build/TestClientFallsBackToClosures3860573748/001/store/ammimqamx8zianfw2c5i4i2dk8zyp85j-a2469 URL: nar/0nr54q43l4z1zmb31ldiv8kr95052g7a8zpng27486g797635m6s.nar.zst2470 Compression: zstd2471 NarHash: sha256:0nr54q43l4z1zmb31ldiv8kr95052g7a8zpng27486g797635m6s2472 NarSize: 2162473 References: /build/TestClientFallsBackToClosures3860573748/001/store/74i16bbzpr56fahdz0py5ccvawsnylc9-shared-dep2474 CA: text:sha256:1dh8xhf93k2g3vbjh81y8wqc7dbsi68w25cavlv1l9333xcy55cw24752026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (5.41ms)2476 client_pushes_test.go:112: Retrieved narinfo from S3:2477 StorePath: /build/TestClientFallsBackToClosures3860573748/001/store/x7v458pa4lkp98rlh7r6rmhycij9fw8l-b2478 URL: nar/0nr54q43l4z1zmb31ldiv8kr95052g7a8zpng27486g797635m6s.nar.zst2479 Compression: zstd2480 NarHash: sha256:0nr54q43l4z1zmb31ldiv8kr95052g7a8zpng27486g797635m6s2481 NarSize: 2162482 References: /build/TestClientFallsBackToClosures3860573748/001/store/74i16bbzpr56fahdz0py5ccvawsnylc9-shared-dep2483 CA: text:sha256:1dh8xhf93k2g3vbjh81y8wqc7dbsi68w25cavlv1l9333xcy55cw24842026/10/01 07:32:28 OK 20260905000000_add_claims.sql (4.66ms)2485--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.63s)24862026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (3.44ms)2487--- PASS: TestClientFallsBackToClosures (0.89s)24882026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (2.73ms)24892026/10/01 07:32:28 goose: successfully migrated database to version: 202609231200002490=== NAME TestClientCADerivations24912026/10/01 07:32:28 OK 1_commit_pending_closure.sql (2.09ms)2492 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2493 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2494 error: binary cache 's3://bucket46?endpoint=http://localhost:38501®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations123950264/001/store'2495 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12496--- PASS: TestClientCADerivations (1.04s)24972026/10/01 07:32:28 OK 2_object_stats_trigger.sql (3.23ms)24982026/10/01 07:32:28 OK 3_commit_push.sql (1.04ms)24992026/10/01 07:32:28 goose: up to current file version: 325002026-10-01 07:32:28.475 UTC [1302] ERROR: relation "goose_db_version" does not exist at character 3625012026-10-01 07:32:28.475 UTC [1302] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25022026/10/01 07:32:28 OK 20241026095416_initial_model.sql (11.39ms)25032026/10/01 07:32:28 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)25042026/10/01 07:32:28 OK 20251218171726_add_pins.sql (4.58ms)25052026/10/01 07:32:28 OK 20260628120000_add_object_size_and_stats.sql (3.56ms)25062026/10/01 07:32:28 OK 20260905000000_add_claims.sql (3.73ms)25072026/10/01 07:32:28 OK 20260920000000_drop_claims.sql (2.55ms)25082026/10/01 07:32:28 OK 20260923120000_add_pushes.sql (2.1ms)25092026/10/01 07:32:28 goose: successfully migrated database to version: 2026092312000025102026/10/01 07:32:28 OK 1_commit_pending_closure.sql (1.82ms)25112026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes25122026/10/01 07:32:28 OK 2_object_stats_trigger.sql (1.55ms)25132026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes25142026/10/01 07:32:28 OK 3_commit_push.sql (3.84ms)25152026/10/01 07:32:28 goose: up to current file version: 325162026/10/01 07:32:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)25172026/10/01 07:32:28 INFO Uploading lc7z0ixmhxn2pl68blg4277xpf37mgyz-b (216B)25182026/10/01 07:32:28 INFO Uploading hmcz2mjg972rzl0223pyk4kcl5pll63j-shared-dep (136B)25192026/10/01 07:32:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25202026/10/01 07:32:28 INFO Uploading 0l754ypis1zfsx5ciygjz04bnb18qbmh-pinned-file.txt (128B)25212026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"25222026/10/01 07:32:28 WARN Failed to register uploaded object key=jdszipszhnnzjxdp6svpbszfvs8cm09q.ls error="server returned 404: 404 page not found\n"25232026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/18jfb50zy37h3frv5lqz2ppgb32kad02rbm46b6q30f494xkj1rd.nar.zst error="server returned 404: 404 page not found\n"25242026/10/01 07:32:28 WARN Failed to register uploaded object key=hmcz2mjg972rzl0223pyk4kcl5pll63j.ls error="server returned 404: 404 page not found\n"25252026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25262026/10/01 07:32:28 WARN Failed to register uploaded object key=lc7z0ixmhxn2pl68blg4277xpf37mgyz.ls error="server returned 404: 404 page not found\n"25272026/10/01 07:32:28 INFO Signed narinfos id=1 count=325282026/10/01 07:32:28 INFO Uploading 3 narinfos25292026/10/01 07:32:28 WARN Failed to register uploaded object key=0l754ypis1zfsx5ciygjz04bnb18qbmh.ls error="server returned 404: 404 page not found\n"25302026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25312026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"25322026/10/01 07:32:28 INFO Signed narinfos id=1 count=125332026/10/01 07:32:28 INFO Uploading 1 narinfos25342026/10/01 07:32:28 WARN Failed to register uploaded object key=jdszipszhnnzjxdp6svpbszfvs8cm09q.narinfo error="server returned 404: 404 page not found\n"25352026/10/01 07:32:28 WARN Failed to register uploaded object key=lc7z0ixmhxn2pl68blg4277xpf37mgyz.narinfo error="server returned 404: 404 page not found\n"25362026/10/01 07:32:28 INFO Received complete push request method=POST path=/api/pushes/1/complete25372026/10/01 07:32:28 WARN Failed to register uploaded object key=hmcz2mjg972rzl0223pyk4kcl5pll63j.narinfo error="server returned 404: 404 page not found\n"25382026/10/01 07:32:28 INFO Received complete push request method=POST path=/api/pushes/1/complete25392026/10/01 07:32:28 WARN Failed to register uploaded object key=0l754ypis1zfsx5ciygjz04bnb18qbmh.narinfo error="server returned 404: 404 page not found\n"25402026/10/01 07:32:28 INFO Upload complete. (62ms)25412026/10/01 07:32:28 INFO Upload complete. (58ms)2542=== NAME TestClientPushesUseOnePush2543 client_pushes_test.go:97: Retrieved narinfo from S3:2544 StorePath: /build/TestClientPushesUseOnePush2401073841/001/store/hmcz2mjg972rzl0223pyk4kcl5pll63j-shared-dep2545 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2546 Compression: zstd2547 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822548 NarSize: 1362549 References: 2550 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2551 client_pushes_test.go:97: Retrieved narinfo from S3:2552 StorePath: /build/TestClientPushesUseOnePush2401073841/001/store/jdszipszhnnzjxdp6svpbszfvs8cm09q-a2553 URL: nar/18jfb50zy37h3frv5lqz2ppgb32kad02rbm46b6q30f494xkj1rd.nar.zst2554 Compression: zstd2555 NarHash: sha256:18jfb50zy37h3frv5lqz2ppgb32kad02rbm46b6q30f494xkj1rd2556 NarSize: 2162557 References: /build/TestClientPushesUseOnePush2401073841/001/store/hmcz2mjg972rzl0223pyk4kcl5pll63j-shared-dep2558 CA: text:sha256:0p156bx4frg564b4y1l1d2k1qwcpy5zk25fbq6mpkw54cr1z88sr2559 client_pushes_test.go:97: Retrieved narinfo from S3:2560 StorePath: /build/TestClientPushesUseOnePush2401073841/001/store/lc7z0ixmhxn2pl68blg4277xpf37mgyz-b2561 URL: nar/18jfb50zy37h3frv5lqz2ppgb32kad02rbm46b6q30f494xkj1rd.nar.zst2562 Compression: zstd2563 NarHash: sha256:18jfb50zy37h3frv5lqz2ppgb32kad02rbm46b6q30f494xkj1rd2564 NarSize: 2162565 References: /build/TestClientPushesUseOnePush2401073841/001/store/hmcz2mjg972rzl0223pyk4kcl5pll63j-shared-dep2566 CA: text:sha256:0p156bx4frg564b4y1l1d2k1qwcpy5zk25fbq6mpkw54cr1z88sr25672026/10/01 07:32:28 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=194.275766ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present25682026/10/01 07:32:28 INFO Starting HTTP server address=127.0.0.1:3597725692026/10/01 07:32:28 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket3787543554/001/proxy.sock25702026/10/01 07:32:28 WARN mTLS auth: subject not in bound subjects subject="CN=someone"25712026/10/01 07:32:28 INFO Shutdown signal received, draining in-flight requests timeout=10s2572--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.56s)2573--- PASS: TestClientPushesUseOnePush (0.87s)2574=== NAME TestClientMultipleUploads2575 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads3278118911/001/store/jsdl6msfdwxj23xx4x8b01m94bmkd0vv-test-file-0.txt2576--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.58s)2577=== NAME TestClientWithDependencies2578 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies1901746600/001/store/14jc70gxmpp0azdgxhbzq6mz6kijy8a0-test-script25792026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes25802026/10/01 07:32:28 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)25812026/10/01 07:32:28 INFO Uploading bafznxw150jx7hzdfpx6cfba7kgd29pm-top (224B)25822026/10/01 07:32:28 INFO Uploading 3zk2sk6z5ay7jf7dg4gi7inbhgzg65s4-shared-dep (136B)25832026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"25842026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/0sm95apx61bhm6p2w6jlsyvfmffr73zqkxl6gykcj7ap7hd7647b.nar.zst error="server returned 404: 404 page not found\n"25852026/10/01 07:32:28 WARN Failed to register uploaded object key=bafznxw150jx7hzdfpx6cfba7kgd29pm.ls error="server returned 404: 404 page not found\n"25862026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25872026/10/01 07:32:28 WARN Failed to register uploaded object key=3zk2sk6z5ay7jf7dg4gi7inbhgzg65s4.ls error="server returned 404: 404 page not found\n"25882026/10/01 07:32:28 INFO Signed narinfos id=1 count=225892026/10/01 07:32:28 INFO Uploading 2 narinfos2590=== NAME TestClientMultipleUploads2591 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads3278118911/001/store/ljb0fij6gb6i3nr7gdfqp7rnr0hwfimg-test-file-1.txt2592--- PASS: TestReadProxyNarinfo (0.57s)25932026/10/01 07:32:28 WARN Failed to register uploaded object key=3zk2sk6z5ay7jf7dg4gi7inbhgzg65s4.narinfo error="server returned 404: 404 page not found\n"25942026/10/01 07:32:28 INFO Received complete push request method=POST path=/api/pushes/1/complete25952026/10/01 07:32:28 WARN Failed to register uploaded object key=bafznxw150jx7hzdfpx6cfba7kgd29pm.narinfo error="server returned 404: 404 page not found\n"25962026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes25972026/10/01 07:32:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25982026/10/01 07:32:28 INFO Uploading xr0khb4bz8qh0p76y27w7asiv1kvyrfi-unpinned-file.txt (128B)25992026/10/01 07:32:28 INFO Upload complete. (59ms)2600=== NAME TestClientSharedPathCommittedMidPush2601 client_integration_test.go:680: Retrieved narinfo from S3:2602 StorePath: /build/TestClientSharedPathCommittedMidPush3073161729/001/store/3zk2sk6z5ay7jf7dg4gi7inbhgzg65s4-shared-dep2603 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2604 Compression: zstd2605 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822606 NarSize: 1362607 References: 2608 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n26092026/10/01 07:32:28 WARN Failed to register uploaded object key=xr0khb4bz8qh0p76y27w7asiv1kvyrfi.ls error="server returned 404: 404 page not found\n"26102026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign26112026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"2612 client_integration_test.go:680: Retrieved narinfo from S3:2613 StorePath: /build/TestClientSharedPathCommittedMidPush3073161729/001/store/bafznxw150jx7hzdfpx6cfba7kgd29pm-top2614 URL: nar/0sm95apx61bhm6p2w6jlsyvfmffr73zqkxl6gykcj7ap7hd7647b.nar.zst2615 Compression: zstd2616 NarHash: sha256:0sm95apx61bhm6p2w6jlsyvfmffr73zqkxl6gykcj7ap7hd7647b2617 NarSize: 2242618 References: /build/TestClientSharedPathCommittedMidPush3073161729/001/store/3zk2sk6z5ay7jf7dg4gi7inbhgzg65s4-shared-dep2619 CA: text:sha256:03saavpr3f2rcz6ad7zjyc42mxqxm6ybbkz9ldxb5nd04ggjinf926202026/10/01 07:32:28 INFO Signed narinfos id=2 count=126212026/10/01 07:32:28 INFO Uploading 1 narinfos2622=== NAME TestClientWithDependencies2623 client_integration_test.go:615: Found 1 dependencies (including self)2624--- PASS: TestClientSharedPathCommittedMidPush (0.80s)26252026/10/01 07:32:28 INFO Received complete push request method=POST path=/api/pushes/2/complete26262026/10/01 07:32:28 WARN Failed to register uploaded object key=xr0khb4bz8qh0p76y27w7asiv1kvyrfi.narinfo error="server returned 404: 404 page not found\n"26272026/10/01 07:32:28 INFO Upload complete. (59ms)2628=== NAME TestClientMultipleUploads2629 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads3278118911/001/store/sa89j1w0fy7sf5v84nj566915vvlrc1j-test-file-2.txt26302026/10/01 07:32:28 INFO Received create pin request method=POST path=/api/pins/myapp26312026/10/01 07:32:28 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3968030983/001/store/0l754ypis1zfsx5ciygjz04bnb18qbmh-pinned-file.txt narinfo_key=0l754ypis1zfsx5ciygjz04bnb18qbmh.narinfo26322026/10/01 07:32:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures26332026/10/01 07:32:28 INFO Garbage collection started26342026/10/01 07:32:28 INFO Aborted multipart uploads count=026352026/10/01 07:32:28 WARN Force mode enabled - objects will be deleted immediately without grace period2636--- PASS: TestResurrectedObjectNotDeleted (0.62s)26372026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes26382026/10/01 07:32:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=026392026/10/01 07:32:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26402026/10/01 07:32:28 INFO Uploading 14jc70gxmpp0azdgxhbzq6mz6kijy8a0-test-script (136B)26412026/10/01 07:32:28 INFO Received push request method=POST path=/api/pushes26422026/10/01 07:32:28 INFO Vacuumed table table=pending_closures26432026/10/01 07:32:28 INFO Vacuumed table table=pending_objects26442026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"26452026/10/01 07:32:28 WARN Failed to register uploaded object key=log/srgd0nic7vczfpw5c9yl9jwqwsc34pkv-test-script.drv error="server returned 404: 404 page not found\n"26462026/10/01 07:32:28 INFO Vacuumed table table=multipart_uploads26472026/10/01 07:32:28 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)26482026/10/01 07:32:28 INFO Uploading ljb0fij6gb6i3nr7gdfqp7rnr0hwfimg-test-file-1.txt (160B)26492026/10/01 07:32:28 INFO Uploading jsdl6msfdwxj23xx4x8b01m94bmkd0vv-test-file-0.txt (160B)26502026/10/01 07:32:28 INFO Uploading sa89j1w0fy7sf5v84nj566915vvlrc1j-test-file-2.txt (160B)26512026/10/01 07:32:28 INFO Vacuumed table table=closures26522026/10/01 07:32:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux26532026/10/01 07:32:28 WARN Refused reserved pin name=worker-x86_64-linux26542026/10/01 07:32:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux26552026/10/01 07:32:28 INFO Received create pin request method=POST path=/api/pins/my-app26562026/10/01 07:32:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux26572026/10/01 07:32:28 INFO Vacuumed table table=objects2658--- PASS: TestCreatePin_ReservedPins (0.72s)26592026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26602026/10/01 07:32:28 WARN Failed to register uploaded object key=14jc70gxmpp0azdgxhbzq6mz6kijy8a0.ls error="server returned 404: 404 page not found\n"26612026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"26622026/10/01 07:32:28 INFO Signed narinfos id=1 count=126632026/10/01 07:32:28 WARN Failed to register uploaded object key=ljb0fij6gb6i3nr7gdfqp7rnr0hwfimg.ls error="server returned 404: 404 page not found\n"26642026/10/01 07:32:28 INFO Uploading 1 narinfos26652026/10/01 07:32:28 WARN Failed to register uploaded object key=sa89j1w0fy7sf5v84nj566915vvlrc1j.ls error="server returned 404: 404 page not found\n"26662026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"26672026/10/01 07:32:28 WARN Failed to register uploaded object key=jsdl6msfdwxj23xx4x8b01m94bmkd0vv.ls error="server returned 404: 404 page not found\n"26682026/10/01 07:32:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26692026/10/01 07:32:28 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"26702026/10/01 07:32:28 INFO Signed narinfos id=1 count=326712026/10/01 07:32:28 INFO Uploading 3 narinfos26722026/10/01 07:32:28 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=426.495189ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present26732026/10/01 07:32:28 INFO Received complete push request method=POST path=/api/pushes/1/complete26742026/10/01 07:32:28 WARN Failed to register uploaded object key=14jc70gxmpp0azdgxhbzq6mz6kijy8a0.narinfo error="server returned 404: 404 page not found\n"26752026/10/01 07:32:28 WARN Failed to register uploaded object key=ljb0fij6gb6i3nr7gdfqp7rnr0hwfimg.narinfo error="server returned 404: 404 page not found\n"26762026/10/01 07:32:28 INFO Received complete push request method=POST path=/api/pushes/1/complete26772026/10/01 07:32:28 WARN Failed to register uploaded object key=sa89j1w0fy7sf5v84nj566915vvlrc1j.narinfo error="server returned 404: 404 page not found\n"26782026/10/01 07:32:28 WARN Failed to register uploaded object key=jsdl6msfdwxj23xx4x8b01m94bmkd0vv.narinfo error="server returned 404: 404 page not found\n"26792026/10/01 07:32:28 INFO Upload complete. (96ms)26802026/10/01 07:32:28 INFO Upload complete. (86ms)2681=== NAME TestClientMultipleUploads2682 client_integration_test.go:369: Uploaded 3 paths in 117.145549ms2683=== NAME TestClientWithDependencies2684 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1901746600/001/store) requires matching store prefix2685--- PASS: TestClientWithDependencies (0.84s)2686--- PASS: TestClientMultipleUploads (0.82s)2687--- PASS: TestObjectStatsTrigger (0.57s)26882026/10/01 07:32:28 INFO Received uploads request method=POST path=/api/pending_closures26892026/10/01 07:32:28 INFO Received cleanup request method=DELETE path=/api/pending_closures26902026/10/01 07:32:28 INFO Aborted multipart uploads count=126912026/10/01 07:32:28 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2692--- PASS: TestMultipartCleanup (0.65s)26932026/10/01 07:32:28 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2694=== NAME TestOrphanedObjectsGC2695 orphaned_objects_gc_test.go:290: GC Test Summary:2696 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2697 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2698 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2699 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2700 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2701--- PASS: TestOrphanedObjectsGC (0.88s)2702--- PASS: TestUploadHandlersRejectOversizedBody (0.16s)2703 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)2704 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)2705 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.76s)27062026/10/01 07:32:29 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=749.959895ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27072026/10/01 07:32:29 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.753280309s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2708=== NAME TestOrphanedObjectsGCStressTest2709 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2710 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion27112026/10/01 07:32:30 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02712=== NAME TestClientIntegration2713 client_integration_test.go:323: Objects in database after GC:2714 client_integration_test.go:323: Successfully deleted all objects with GC --force2715--- PASS: TestClientIntegration (2.85s)2716=== NAME TestOrphanedObjectsGCStressTest2717 orphaned_objects_gc_test.go:509: Stress test completed successfully:2718 orphaned_objects_gc_test.go:510: - Active objects preserved: 202719 orphaned_objects_gc_test.go:511: - Objects deleted: 2102720 orphaned_objects_gc_test.go:512: - Total GC'd: 2102721--- PASS: TestOrphanedObjectsGCStressTest (2.28s)27222026/10/01 07:32:30 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02723=== NAME TestPinProtectsFromGC2724 client_integration_test.go:794: Pin successfully protected closure from garbage collection2725--- PASS: TestPinProtectsFromGC (2.89s)27262026/10/01 07:32:31 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-config27272026/10/01 07:32:31 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.372222ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27282026/10/01 07:32:32 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=438.829442ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27292026/10/01 07:32:32 WARN Rate limiter enabled after throttle name=s3-test rate=527302026/10/01 07:32:32 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2731=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2732 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102733 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002734--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (6.02s)27352026/10/01 07:32:32 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=794.31875ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27362026/10/01 07:32:33 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.637613389s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27372026/10/01 07:32:34 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"27382026/10/01 07:32:34 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-config27392026/10/01 07:32:34 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=182.657813ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27402026/10/01 07:32:35 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=413.512986ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27412026/10/01 07:32:35 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=736.860852ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27422026/10/01 07:32:36 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.560054808s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27432026/10/01 07:32:37 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_closures27442026/10/01 07:32:37 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=183.010655ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27452026/10/01 07:32:38 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=399.851946ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27462026/10/01 07:32:38 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=831.207028ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27472026/10/01 07:32:39 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.641364487s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2748--- PASS: TestClientErrorHandling (0.00s)2749 --- PASS: TestClientErrorHandling/InvalidStorePath (0.49s)2750 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.53s)2751 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.67s)2752PASS27532026-10-01 07:32:41.243 UTC [128] LOG: received smart shutdown request27542026-10-01 07:32:41.247 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 127552026-10-01 07:32:41.259 UTC [133] LOG: shutting down27562026-10-01 07:32:41.259 UTC [133] LOG: checkpoint starting: shutdown immediate27572026-10-01 07:32:42.968 UTC [133] LOG: checkpoint complete: wrote 10664 buffers (65.1%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 20 recycled; write=0.207 s, sync=1.471 s, total=1.709 s; sync files=23917, longest=0.017 s, average=0.001 s; distance=325397 kB, estimate=325397 kB; lsn=0/1552B2C8, redo lsn=0/1552B2C827582026-10-01 07:32:43.044 UTC [128] LOG: database system is shut down2759Running OIDC tests...2760=== RUN TestAudienceForIssuer2761=== PAUSE TestAudienceForIssuer2762=== RUN TestGlobMatch2763=== PAUSE TestGlobMatch2764=== RUN TestValidateToken_ValidToken2765=== PAUSE TestValidateToken_ValidToken2766=== RUN TestValidateToken_WrongAudience2767=== PAUSE TestValidateToken_WrongAudience2768=== RUN TestValidateToken_Expired2769=== PAUSE TestValidateToken_Expired2770=== RUN TestValidateToken_BoundClaimsMismatch2771=== PAUSE TestValidateToken_BoundClaimsMismatch2772=== RUN TestValidateToken_BoundSubjectMismatch2773=== PAUSE TestValidateToken_BoundSubjectMismatch2774=== RUN TestValidateToken_MultipleProviders2775=== PAUSE TestValidateToken_MultipleProviders2776=== RUN TestValidateToken_NoMatchingProvider2777=== PAUSE TestValidateToken_NoMatchingProvider2778=== RUN TestValidateToken_KubernetesServiceAccount2779=== PAUSE TestValidateToken_KubernetesServiceAccount2780=== RUN TestNewValidator_KubernetesRequiresCA2781=== PAUSE TestNewValidator_KubernetesRequiresCA2782=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2783=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2784=== RUN TestPins_ReservedForMatchingRule2785=== PAUSE TestPins_ReservedForMatchingRule2786=== RUN TestPins_TopLevelShorthand2787=== PAUSE TestPins_TopLevelShorthand2788=== RUN TestPins_ConfigValidation2789=== PAUSE TestPins_ConfigValidation2790=== RUN TestScopes_LegacyProviderDefaultsToWrite2791=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2792=== RUN TestScopes_Rules2793=== PAUSE TestScopes_Rules2794=== RUN TestScopes_ConfigValidation2795=== PAUSE TestScopes_ConfigValidation2796=== CONT TestAudienceForIssuer2797=== CONT TestPins_ConfigValidation2798=== CONT TestValidateToken_KubernetesServiceAccount2799=== CONT TestScopes_Rules2800--- PASS: TestAudienceForIssuer (0.00s)2801=== CONT TestValidateToken_NoMatchingProvider2802=== CONT TestPins_TopLevelShorthand2803=== CONT TestValidateToken_MultipleProviders2804--- PASS: TestPins_ConfigValidation (0.00s)2805=== CONT TestValidateToken_BoundSubjectMismatch2806=== CONT TestPins_ReservedForMatchingRule2807=== CONT TestValidateToken_BoundClaimsMismatch2808=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2809=== CONT TestValidateToken_Expired2810=== CONT TestValidateToken_WrongAudience2811=== CONT TestNewValidator_KubernetesRequiresCA2812=== CONT TestValidateToken_ValidToken2813=== CONT TestGlobMatch2814=== RUN TestGlobMatch/foo_foo2815=== PAUSE TestGlobMatch/foo_foo2816=== RUN TestGlobMatch/foo_bar2817=== PAUSE TestGlobMatch/foo_bar2818=== RUN TestGlobMatch/*_2819=== PAUSE TestGlobMatch/*_2820=== RUN TestGlobMatch/*_anything2821=== PAUSE TestGlobMatch/*_anything2822=== RUN TestGlobMatch/foo*_foo2823=== PAUSE TestGlobMatch/foo*_foo2824=== RUN TestGlobMatch/foo*_foobar2825=== PAUSE TestGlobMatch/foo*_foobar2826=== RUN TestGlobMatch/foo*_bar2827=== PAUSE TestGlobMatch/foo*_bar2828=== RUN TestGlobMatch/*bar_bar2829=== PAUSE TestGlobMatch/*bar_bar2830=== RUN TestGlobMatch/*bar_foobar2831=== PAUSE TestGlobMatch/*bar_foobar2832=== RUN TestGlobMatch/*bar_foo2833=== PAUSE TestGlobMatch/*bar_foo2834=== RUN TestGlobMatch/foo*bar_foobar2835=== PAUSE TestGlobMatch/foo*bar_foobar2836=== RUN TestGlobMatch/foo*bar_foo123bar2837=== PAUSE TestGlobMatch/foo*bar_foo123bar2838=== RUN TestGlobMatch/foo*bar_foobarbaz2839=== PAUSE TestGlobMatch/foo*bar_foobarbaz2840=== RUN TestGlobMatch/*/*_foo/bar2841=== PAUSE TestGlobMatch/*/*_foo/bar2842=== RUN TestGlobMatch/*/*_foo2843=== PAUSE TestGlobMatch/*/*_foo2844=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2845=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2846=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02847=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02848=== RUN TestGlobMatch/refs/*/main_refs/heads/main2849=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2850=== RUN TestGlobMatch/fo?_foo2851=== PAUSE TestGlobMatch/fo?_foo2852=== RUN TestGlobMatch/fo?_fo2853=== PAUSE TestGlobMatch/fo?_fo2854=== RUN TestGlobMatch/fo?_fooo2855=== PAUSE TestGlobMatch/fo?_fooo2856=== RUN TestGlobMatch/?oo_foo2857=== PAUSE TestGlobMatch/?oo_foo2858=== RUN TestGlobMatch/?oo_boo2859=== PAUSE TestGlobMatch/?oo_boo2860=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2861=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2862=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2863=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2864=== CONT TestGlobMatch/foo_foo2865=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2866=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2867=== CONT TestGlobMatch/?oo_boo2868=== CONT TestGlobMatch/?oo_foo2869=== CONT TestGlobMatch/fo?_fooo2870=== CONT TestGlobMatch/fo?_fo2871=== CONT TestGlobMatch/fo?_foo2872=== CONT TestGlobMatch/refs/*/main_refs/heads/main2873=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02874=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2875=== CONT TestGlobMatch/*/*_foo2876=== CONT TestGlobMatch/*/*_foo/bar2877=== CONT TestGlobMatch/foo*bar_foobarbaz2878=== CONT TestGlobMatch/foo*bar_foo123bar2879=== CONT TestGlobMatch/foo*bar_foobar2880=== CONT TestGlobMatch/*bar_foo2881=== CONT TestGlobMatch/*bar_foobar2882=== CONT TestGlobMatch/*bar_bar2883=== CONT TestGlobMatch/foo*_bar2884=== CONT TestGlobMatch/foo*_foobar2885=== CONT TestGlobMatch/foo*_foo2886=== CONT TestGlobMatch/*_anything2887=== CONT TestGlobMatch/*_2888=== CONT TestGlobMatch/foo_bar2889--- PASS: TestGlobMatch (0.00s)2890 --- PASS: TestGlobMatch/foo_foo (0.00s)2891 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2892 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2893 --- PASS: TestGlobMatch/?oo_boo (0.00s)2894 --- PASS: TestGlobMatch/?oo_foo (0.00s)2895 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2896 --- PASS: TestGlobMatch/fo?_fo (0.00s)2897 --- PASS: TestGlobMatch/fo?_foo (0.00s)2898 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2899 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2900 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2901 --- PASS: TestGlobMatch/*/*_foo (0.00s)2902 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2903 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2904 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2905 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2906 --- PASS: TestGlobMatch/*bar_foo (0.00s)2907 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2908 --- PASS: TestGlobMatch/*bar_bar (0.00s)2909 --- PASS: TestGlobMatch/foo*_bar (0.00s)2910 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2911 --- PASS: TestGlobMatch/foo*_foo (0.00s)2912 --- PASS: TestGlobMatch/*_anything (0.00s)2913 --- PASS: TestGlobMatch/*_ (0.00s)2914 --- PASS: TestGlobMatch/foo_bar (0.00s)2915=== CONT TestScopes_ConfigValidation2916=== CONT TestScopes_LegacyProviderDefaultsToWrite2917--- PASS: TestScopes_ConfigValidation (0.00s)29182026/10/01 07:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33157/oidc2919--- PASS: TestValidateToken_BoundSubjectMismatch (0.09s)29202026/10/01 07:32:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:39007/oidc29212026/10/01 07:32:44 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:42877/oidc29222026/10/01 07:32:44 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:340092923--- PASS: TestValidateToken_MultipleProviders (0.11s)29242026/10/01 07:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35197/oidc2925--- PASS: TestValidateToken_KubernetesServiceAccount (0.12s)2926--- PASS: TestValidateToken_Expired (0.11s)29272026/10/01 07:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37355/oidc2928--- PASS: TestValidateToken_BoundClaimsMismatch (0.12s)29292026/10/01 07:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37451/oidc2930--- PASS: TestPins_TopLevelShorthand (0.13s)29312026/10/01 07:32:44 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12329322026/10/01 07:32:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:33769/oidc2933--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.14s)29342026/10/01 07:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38567/oidc2935--- PASS: TestValidateToken_NoMatchingProvider (0.15s)29362026/10/01 07:32:44 http: TLS handshake error from 127.0.0.1:53546: remote error: tls: bad certificate2937--- PASS: TestNewValidator_KubernetesRequiresCA (0.15s)29382026/10/01 07:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44037/oidc2939--- PASS: TestScopes_Rules (0.16s)2940--- PASS: TestPins_ReservedForMatchingRule (0.16s)29412026/10/01 07:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42089/oidc2942--- PASS: TestValidateToken_ValidToken (0.17s)29432026/10/01 07:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41881/oidc2944--- PASS: TestValidateToken_WrongAudience (0.19s)29452026/10/01 07:32:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33195/oidc2946--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.19s)2947PASS2948Running hook tests...2949=== RUN TestSendPathsEmpty2950=== PAUSE TestSendPathsEmpty2951=== RUN TestQueueEnqueueAndFetch2952=== PAUSE TestQueueEnqueueAndFetch2953=== RUN TestQueueDeduplication2954=== PAUSE TestQueueDeduplication2955=== RUN TestQueueRemove2956=== PAUSE TestQueueRemove2957=== RUN TestQueueFetchBatchLimit2958=== PAUSE TestQueueFetchBatchLimit2959=== RUN TestQueueRetryMovesToBack2960=== PAUSE TestQueueRetryMovesToBack2961=== RUN TestQueueFetchRemoveLifecycle2962=== PAUSE TestQueueFetchRemoveLifecycle2963=== RUN TestQueueConcurrentWriters2964=== PAUSE TestQueueConcurrentWriters2965=== RUN TestQueueRemoveLargeClosure2966=== PAUSE TestQueueRemoveLargeClosure2967=== RUN TestServerClientIntegration2968=== PAUSE TestServerClientIntegration2969=== RUN TestServerQueueError2970=== PAUSE TestServerQueueError2971=== RUN TestGetListenerSocketActivation2972 server_test.go:210: === RUN TestGetListenerSocketActivation2973 --- PASS: TestGetListenerSocketActivation (0.00s)2974 PASS2975 2976--- PASS: TestGetListenerSocketActivation (0.01s)2977=== RUN TestDrainIsolatesPoisonPath2978=== PAUSE TestDrainIsolatesPoisonPath2979=== RUN TestRunNotBlockedByPoisonHead2980=== PAUSE TestRunNotBlockedByPoisonHead2981=== RUN TestDrainGivesUpWhenServerDown2982=== PAUSE TestDrainGivesUpWhenServerDown2983=== RUN TestFailedPathPrunedByLaterClosure2984=== PAUSE TestFailedPathPrunedByLaterClosure2985=== RUN TestWorkerUploadsAndRemoves2986=== PAUSE TestWorkerUploadsAndRemoves2987=== RUN TestWorkerSkipsGCdPaths2988=== PAUSE TestWorkerSkipsGCdPaths2989=== RUN TestWorkerPrunesClosureDeps2990=== PAUSE TestWorkerPrunesClosureDeps2991=== RUN TestDrainTimeout2992=== PAUSE TestDrainTimeout2993=== CONT TestSendPathsEmpty2994--- PASS: TestSendPathsEmpty (0.00s)2995=== CONT TestQueueRemoveLargeClosure2996=== CONT TestWorkerSkipsGCdPaths2997=== CONT TestQueueDeduplication2998=== CONT TestDrainTimeout2999=== CONT TestQueueFetchRemoveLifecycle3000=== CONT TestQueueFetchBatchLimit3001=== CONT TestServerClientIntegration3002=== CONT TestQueueConcurrentWriters3003=== CONT TestWorkerPrunesClosureDeps3004=== CONT TestQueueRetryMovesToBack3005=== CONT TestQueueEnqueueAndFetch3006=== CONT TestDrainGivesUpWhenServerDown3007=== CONT TestWorkerUploadsAndRemoves3008=== CONT TestFailedPathPrunedByLaterClosure3009=== CONT TestQueueRemove3010=== CONT TestDrainIsolatesPoisonPath3011=== CONT TestRunNotBlockedByPoisonHead3012=== CONT TestServerQueueError30132026/10/01 07:32:44 ERROR Failed to queue paths error="permission denied" count=13014--- PASS: TestServerClientIntegration (0.00s)3015--- PASS: TestServerQueueError (0.00s)30162026/10/01 07:32:44 INFO Upload queue status pending=230172026/10/01 07:32:44 INFO Uploading batch count=130182026/10/01 07:32:44 INFO Upload queue status pending=230192026/10/01 07:32:44 INFO Upload queue status pending=330202026/10/01 07:32:44 INFO Uploading batch count=230212026/10/01 07:32:44 INFO Uploading batch count=130222026/10/01 07:32:44 ERROR Upload failed error="upload failed" count=130232026/10/01 07:32:44 INFO Uploading batch count=230242026/10/01 07:32:44 INFO Uploading batch count=230252026/10/01 07:32:44 ERROR Upload failed error="upload failed" count=230262026/10/01 07:32:44 INFO Uploading batch count=430272026/10/01 07:32:44 ERROR Upload failed error="upload failed" count=430282026/10/01 07:32:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown962374755/002/a30292026/10/01 07:32:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown962374755/002/b30302026/10/01 07:32:44 INFO Upload queue status pending=23031--- PASS: TestQueueEnqueueAndFetch (0.01s)30322026/10/01 07:32:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3572543028/002/nonexistent3033--- PASS: TestQueueDeduplication (0.02s)30342026/10/01 07:32:44 INFO Uploading batch count=230352026/10/01 07:32:44 ERROR Upload failed error="upload failed" count=230362026/10/01 07:32:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown962374755/002/c30372026/10/01 07:32:44 INFO Uploading batch count=130382026/10/01 07:32:44 ERROR Upload failed error="upload failed" count=13039--- PASS: TestQueueFetchRemoveLifecycle (0.02s)3040--- PASS: TestQueueFetchBatchLimit (0.02s)30412026/10/01 07:32:44 INFO Uploading batch count=130422026/10/01 07:32:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath4091479503/002/bbb30432026/10/01 07:32:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown962374755/002/d3044--- PASS: TestQueueRetryMovesToBack (0.02s)30452026/10/01 07:32:44 INFO Uploading batch count=13046--- PASS: TestQueueRemove (0.02s)30472026/10/01 07:32:44 INFO Uploading batch count=230482026/10/01 07:32:44 ERROR Upload failed error="upload failed" count=230492026/10/01 07:32:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown962374755/002/e30502026/10/01 07:32:44 INFO Uploading batch count=130512026/10/01 07:32:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown962374755/002/f30522026/10/01 07:32:44 INFO Uploading batch count=130532026/10/01 07:32:44 ERROR Upload failed error="upload failed" count=130542026/10/01 07:32:44 ERROR Drain finished with paths left in queue remaining=1030552026/10/01 07:32:44 INFO Uploading batch count=130562026/10/01 07:32:44 ERROR Upload failed error="upload failed" count=130572026/10/01 07:32:44 INFO Uploading batch count=130582026/10/01 07:32:44 ERROR Upload failed error="upload failed" count=13059--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)30602026/10/01 07:32:44 ERROR Drain finished with paths left in queue remaining=13061--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3062--- PASS: TestDrainIsolatesPoisonPath (0.02s)3063--- PASS: TestWorkerUploadsAndRemoves (0.03s)3064--- PASS: TestWorkerPrunesClosureDeps (0.03s)3065--- PASS: TestWorkerSkipsGCdPaths (0.04s)3066--- PASS: TestQueueRemoveLargeClosure (0.11s)30672026/10/01 07:32:44 ERROR Upload failed error="context deadline exceeded" count=230682026/10/01 07:32:44 ERROR Drain finished with paths left in queue remaining=43069--- PASS: TestDrainTimeout (0.22s)3070--- PASS: TestQueueConcurrentWriters (0.27s)30712026/10/01 07:32:45 INFO Uploading batch count=130722026/10/01 07:32:45 INFO Uploading batch count=130732026/10/01 07:32:45 INFO Uploading batch count=130742026/10/01 07:32:45 ERROR Upload failed error="upload failed" count=130752026/10/01 07:32:45 INFO Uploading batch count=130762026/10/01 07:32:45 ERROR Upload failed error="upload failed" count=130772026/10/01 07:32:45 INFO Uploading batch count=130782026/10/01 07:32:45 ERROR Upload failed error="upload failed" count=130792026/10/01 07:32:45 INFO Uploading batch count=130802026/10/01 07:32:45 ERROR Upload failed error="upload failed" count=130812026/10/01 07:32:45 ERROR Drain finished with paths left in queue remaining=13082--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3083PASS