niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #313
· 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.03s)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 TestFileTokenMissing97=== CONT TestSetClientTLS98=== CONT TestDoWithRetry_BodyReplayedViaGetBody99=== CONT TestScriptTokenEmptyCommand100--- PASS: TestScriptTokenEmptyCommand (0.00s)101=== CONT TestPathInfoCACompatibility102--- PASS: TestFileTokenMissing (0.00s)103=== CONT TestParsePathInfoJSONMultiplePaths104=== RUN TestPathInfoCACompatibility/null_ca_field105=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths106=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths107=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths108=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths109=== PAUSE TestPathInfoCACompatibility/null_ca_field110=== RUN TestPathInfoCACompatibility/old_string_format_-_text111=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text112=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive113=== CONT TestParsePathInfoJSON114=== RUN TestParsePathInfoJSON/Nix_format115=== CONT TestStreamPushReportsSignatures116=== CONT TestStreamPushRequestLine117=== CONT TestStreamPushGivesUpOnDeadServer118=== CONT TestStreamPushIsolatesFailures119=== CONT TestStreamPushBatchesUnderLoad120=== CONT TestStreamPushReportsEveryPath121=== CONT TestShellSplitErrors122--- PASS: TestShellSplitErrors (0.00s)123=== CONT TestShellSplit124=== CONT TestStaticToken125=== CONT TestFileTokenReadsAndCaches126=== CONT TestSetClientTLSErrors127=== CONT TestScriptTokenEmptyToken128=== CONT TestEncodeNixBase32WithRealHash129=== CONT TestResolveStorePath130=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess131=== CONT TestRateLimiterFeedback132=== CONT TestScriptTokenBadJSON133=== CONT TestScriptTokenScriptFails134=== CONT TestClientSignaturesByStorePath135=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive136=== PAUSE TestParsePathInfoJSON/Nix_format137=== CONT TestPathInfoHashCompatibility138--- PASS: TestStaticToken (0.00s)139=== RUN TestRateLimiterFeedback/429_enables_limiter140--- PASS: TestShellSplit (0.00s)141=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)1422026/10/01 09:39:48 ERROR Upload failed error="connection refused" count=201432026/10/01 09:39:48 ERROR Server seems unavailable, giving up on batch untried=17144=== RUN TestParsePathInfoJSON/Lix_format145=== PAUSE TestParsePathInfoJSON/Lix_format146=== RUN TestParsePathInfoJSON/empty_input147=== PAUSE TestParsePathInfoJSON/empty_input148=== RUN TestParsePathInfoJSON/whitespace_only149=== PAUSE TestParsePathInfoJSON/whitespace_only150=== RUN TestPathInfoCACompatibility/new_structured_format_-_text151--- PASS: TestEncodeNixBase32WithRealHash (0.00s)152=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text153=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method154=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method155=== RUN TestParsePathInfoJSON/invalid_JSON156=== PAUSE TestParsePathInfoJSON/invalid_JSON157=== CONT TestEncodeNixBase321582026/10/01 09:39:48 ERROR Upload failed error=boom count=1159=== RUN TestEncodeNixBase32/test_string_hash160=== PAUSE TestEncodeNixBase32/test_string_hash1612026/10/01 09:39:48 WARN Rate limiter enabled after throttle name=server-test rate=5162=== CONT TestUploadMultipart_SupersededByPeer163=== CONT TestDumpPathMatchesNix164--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)165--- PASS: TestClientSignaturesByStorePath (0.00s)166=== RUN TestUploadMultipart_SupersededByPeer/exists167=== CONT TestDumpPathWriterError1682026/10/01 09:39:48 ERROR Upload failed error=boom count=1169=== CONT TestGetStorePathHash170=== RUN TestGetStorePathHash/valid_store_path171=== RUN TestEncodeNixBase32/empty_input172=== PAUSE TestRateLimiterFeedback/429_enables_limiter173=== PAUSE TestEncodeNixBase32/empty_input174=== CONT TestDumpPathSingleFile175=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)176=== CONT TestScriptTokenNoExpiryRerunsEveryCall1772026/10/01 09:39:48 ERROR Upload failed error="bad path" count=3178=== PAUSE TestGetStorePathHash/valid_store_path179=== CONT TestFilterOversizedClosures1802026/10/01 09:39:48 WARN Rate limiter enabled after throttle name=server-test rate=5181=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1822026/10/01 09:39:48 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:43505183=== CONT TestConvertHashToNix32184=== RUN TestConvertHashToNix32/SRI_format_to_Nix32185=== RUN TestRateLimiterFeedback/503_enables_limiter186=== PAUSE TestRateLimiterFeedback/503_enables_limiter187--- PASS: TestFileTokenReadsAndCaches (0.00s)188=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon189=== CONT TestFileTokenEmpty190=== RUN TestGetStorePathHash/basename_without_hyphen_should_error191=== RUN TestFilterOversizedClosures/no_limit_keeps_everything192=== PAUSE TestUploadMultipart_SupersededByPeer/exists193=== CONT TestPartSizeForNAR194=== RUN TestSetClientTLS/rejects_connection_without_client_cert195=== CONT TestScriptTokenCachesUntilRefresh196=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32197=== CONT TestUploadMultipart_PartsInParallel198=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything1992026/10/01 09:39:48 WARN Rate limiter backed off name=server-test rate=52002026/10/01 09:39:48 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:43505201=== CONT TestCaseHackSuffix202=== CONT TestRegisterUploadedObjectReusesConnections203--- PASS: TestStreamPushReportsSignatures (0.00s)204--- PASS: TestStreamPushIsolatesFailures (0.00s)205--- PASS: TestScriptTokenScriptFails (0.00s)206=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter207=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter208=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon209=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method210=== CONT TestPathInfoCACompatibility/new_structured_format_-_text211=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive212=== CONT TestPathInfoCACompatibility/old_string_format_-_text213=== CONT TestParsePathInfoJSON/whitespace_only214=== CONT TestParsePathInfoJSON/empty_input215=== CONT TestParsePathInfoJSON/Lix_format216=== CONT TestParsePathInfoJSON/invalid_JSON217=== CONT TestEncodeNixBase32/test_string_hash218=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI219=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI220=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512221=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512222=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)223=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error224=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths225=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error226=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error227=== RUN TestSetClientTLSErrors/missing_cert_file228=== PAUSE TestSetClientTLSErrors/missing_cert_file229=== RUN TestSetClientTLSErrors/missing_key_file230=== PAUSE TestSetClientTLSErrors/missing_key_file231=== RUN TestSetClientTLSErrors/missing_ca_file232=== PAUSE TestSetClientTLSErrors/missing_ca_file233=== RUN TestSetClientTLSErrors/invalid_ca_file234=== PAUSE TestSetClientTLSErrors/invalid_ca_file235=== RUN TestConvertHashToNix32/already_Nix32_format236=== PAUSE TestConvertHashToNix32/already_Nix32_format237=== RUN TestConvertHashToNix32/invalid_format238=== PAUSE TestConvertHashToNix32/invalid_format239=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped240=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped241=== RUN TestFilterOversizedClosures/all_closures_skipped242=== PAUSE TestFilterOversizedClosures/all_closures_skipped243=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon244=== CONT TestSetClientTLSErrors/invalid_ca_file245=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert246=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA247=== RUN TestPartSizeForNAR/zero_stays_at_minimum248=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA249=== RUN TestSetClientTLS/preserves_debug_logging_transport250=== PAUSE TestSetClientTLS/preserves_debug_logging_transport251=== CONT TestSetClientTLSErrors/missing_cert_file252=== CONT TestFilterOversizedClosures/no_limit_keeps_everything253=== CONT TestFilterOversizedClosures/all_closures_skipped2542026/10/01 09:39:48 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=50255=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2562026/10/01 09:39:48 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=2000257=== CONT TestSetClientTLS/rejects_connection_without_client_cert258=== CONT TestConvertHashToNix32/SRI_format_to_Nix32259=== CONT TestPathInfoCACompatibility/null_ca_field260=== CONT TestConvertHashToNix32/already_Nix32_format261--- PASS: TestResolveStorePath (0.00s)262=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter263=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum264=== RUN TestPartSizeForNAR/small_stays_at_minimum265=== PAUSE TestPartSizeForNAR/small_stays_at_minimum266=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum267=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum268=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts269=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts270=== RUN TestPartSizeForNAR/1_TiB271=== PAUSE TestPartSizeForNAR/1_TiB272=== CONT TestSetClientTLS/preserves_debug_logging_transport273--- PASS: TestScriptTokenEmptyToken (0.00s)274--- PASS: TestScriptTokenBadJSON (0.00s)275--- PASS: TestStreamPushReportsEveryPath (0.01s)276--- PASS: TestDoServerRequestAttachesToken (0.01s)277=== RUN TestPartSizeForNAR/5_TiB_S3_max_object278=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object279=== RUN TestPartSizeForNAR/capped_at_5_GiB280=== PAUSE TestPartSizeForNAR/capped_at_5_GiB281--- PASS: TestFileTokenEmpty (0.00s)282--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)283--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)284--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.05s)285=== CONT TestEncodeNixBase32/empty_input286--- PASS: TestFilterOversizedClosures (0.04s)287 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)288 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)289 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)290--- PASS: TestEncodeNixBase32 (0.00s)291 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)292 --- PASS: TestEncodeNixBase32/empty_input (0.00s)293--- PASS: TestPathInfoCACompatibility (0.00s)294 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)295 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)296 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)297 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)298 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)299=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA300=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error301=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error302=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI303=== CONT TestPartSizeForNAR/5_TiB_S3_max_object304=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts305=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum306=== CONT TestPartSizeForNAR/small_stays_at_minimum307=== CONT TestPartSizeForNAR/capped_at_5_GiB308=== CONT TestGetStorePathHash/valid_store_path309=== CONT TestSetClientTLSErrors/missing_ca_file310=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error311=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error312=== CONT TestPartSizeForNAR/1_TiB313=== CONT TestGetStorePathHash/basename_without_hyphen_should_error314--- PASS: TestGetStorePathHash (0.05s)315 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)316 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)317 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)318 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)319=== CONT TestParsePathInfoJSON/Nix_format320--- PASS: TestParsePathInfoJSON (0.00s)321 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)322 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)323 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)324 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)325 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)326=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths327--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)328 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)329 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)330=== CONT TestConvertHashToNix32/invalid_format331=== CONT TestSetClientTLSErrors/missing_key_file332=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter333=== RUN TestUploadMultipart_SupersededByPeer/missing334=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512335=== CONT TestPartSizeForNAR/zero_stays_at_minimum336=== PAUSE TestUploadMultipart_SupersededByPeer/missing337=== CONT TestUploadMultipart_SupersededByPeer/exists338--- PASS: TestPartSizeForNAR (0.03s)339 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)340 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)341 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)342 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)343 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)344 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)345 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)346--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)347=== CONT TestRateLimiterFeedback/429_enables_limiter348=== CONT TestUploadMultipart_SupersededByPeer/missing349=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter350=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3512026/10/01 09:39:48 WARN Rate limiter enabled after throttle name=server-test rate=5352=== CONT TestRateLimiterFeedback/503_enables_limiter3532026/10/01 09:39:48 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:41511354--- PASS: TestSetClientTLSErrors (0.04s)355 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)356 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)357 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)358 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)359--- PASS: TestConvertHashToNix32 (0.04s)360 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)361 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)362 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)363--- PASS: TestPathInfoHashCompatibility (0.04s)364 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)365 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)366 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)367 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)3682026/10/01 09:39:48 WARN Rate limiter backed off name=server-test rate=53692026/10/01 09:39:48 WARN Rate limiter enabled after throttle name=server-test rate=53702026/10/01 09:39:48 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:37673371--- PASS: TestUploadMultipart_SupersededByPeer (0.05s)372 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)373 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)3742026/10/01 09:39:48 WARN Rate limiter backed off name=server-test rate=5375--- PASS: TestRateLimiterFeedback (0.05s)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.00s)379 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)3802026/10/01 09:39:48 http: TLS handshake error from 127.0.0.1:44128: remote error: tls: bad certificate381--- PASS: TestSetClientTLS (0.05s)382 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)383 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)384 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)385--- PASS: TestRegisterUploadedObjectReusesConnections (0.02s)386--- PASS: TestStreamPushRequestLine (0.06s)387--- PASS: TestDumpPathWriterError (0.07s)388--- PASS: TestDumpPathSingleFile (0.07s)389--- PASS: TestCaseHackSuffix (0.03s)390--- PASS: TestStreamPushBatchesUnderLoad (0.10s)391--- PASS: TestDumpPathMatchesNix (0.11s)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/postgres3088188373/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/postgres3088188373/data -l logfile start422423/build/postgres3088188373:5432 - no response4242026-10-01 09:39:49.979 UTC [128] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 09:39:49.979 UTC [128] LOG: listening on Unix socket "/build/postgres3088188373/.s.PGSQL.5432"4262026-10-01 09:39:49.983 UTC [135] LOG: database system was shut down at 2026-10-01 09:39:49 UTC4272026-10-01 09:39:49.987 UTC [128] LOG: database system is ready to accept connections428/build/postgres3088188373:5432 - accepting connections429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestClientPushesUseOnePush462=== PAUSE TestClientPushesUseOnePush463=== RUN TestClientFallsBackToClosures464=== PAUSE TestClientFallsBackToClosures465=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock466=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== RUN TestResolveDBConnectionString468=== PAUSE TestResolveDBConnectionString469=== RUN TestLeadElectsOneAndHandsOver470=== PAUSE TestLeadElectsOneAndHandsOver471=== RUN TestLeadIncumbentWinsAfterRestart4722026-10-01 09:39:50.252 UTC [375] ERROR: relation "goose_db_version" does not exist at character 364732026-10-01 09:39:50.252 UTC [375] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4742026/10/01 09:39:50 OK 20241026095416_initial_model.sql (9.84ms)4752026/10/01 09:39:50 OK 20251210153512_drop_unused_gin_index.sql (1.61ms)4762026/10/01 09:39:50 OK 20251218171726_add_pins.sql (2.78ms)4772026/10/01 09:39:50 OK 20260628120000_add_object_size_and_stats.sql (2.54ms)4782026/10/01 09:39:50 OK 20260905000000_add_claims.sql (2.79ms)4792026/10/01 09:39:50 OK 20260920000000_drop_claims.sql (1.67ms)4802026/10/01 09:39:50 OK 20260923120000_add_pushes.sql (1.28ms)4812026/10/01 09:39:50 goose: successfully migrated database to version: 202609231200004822026/10/01 09:39:50 OK 1_commit_pending_closure.sql (1.56ms)4832026/10/01 09:39:50 OK 2_object_stats_trigger.sql (654.63µs)4842026/10/01 09:39:50 OK 3_commit_push.sql (512.89µs)4852026/10/01 09:39:50 goose: up to current file version: 34862026/10/01 09:39:50 INFO lead: acquired remote=192.0.2.1:12344872026/10/01 09:39:50 INFO lead: released remote=192.0.2.1:12344882026/10/01 09:39:50 INFO lead: acquired remote=192.0.2.1:12344892026/10/01 09:39:50 INFO lead: released remote=192.0.2.1:1234490--- PASS: TestLeadIncumbentWinsAfterRestart (0.77s)491=== RUN TestLeadEndsOnShutdown492=== PAUSE TestLeadEndsOnShutdown493=== RUN TestGCAdvisoryLockBlocksConcurrentRun4942026-10-01 09:39:51.013 UTC [386] ERROR: relation "goose_db_version" does not exist at character 364952026-10-01 09:39:51.013 UTC [386] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4962026/10/01 09:39:51 OK 20241026095416_initial_model.sql (8.94ms)4972026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (1.23ms)4982026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.08ms)4992026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (2.89ms)5002026/10/01 09:39:51 OK 20260905000000_add_claims.sql (2.81ms)5012026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (1.71ms)5022026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (1.18ms)5032026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200005042026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.49ms)5052026/10/01 09:39:51 OK 2_object_stats_trigger.sql (637.53µs)5062026/10/01 09:39:51 OK 3_commit_push.sql (517.54µs)5072026/10/01 09:39:51 goose: up to current file version: 3508--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.11s)509=== RUN TestGCBugBareHashReferences510=== PAUSE TestGCBugBareHashReferences511=== RUN TestGCMetrics512=== PAUSE TestGCMetrics513=== RUN TestPushDedupSurvivesConcurrentGC514=== PAUSE TestPushDedupSurvivesConcurrentGC515=== RUN TestDeduplicatedObjectsRecordedAsPending516=== PAUSE TestDeduplicatedObjectsRecordedAsPending517=== RUN TestGCSweepSkipsPendingObjects518=== PAUSE TestGCSweepSkipsPendingObjects519=== RUN TestTombstonedObjectOfferedWithoutWaiting520=== PAUSE TestTombstonedObjectOfferedWithoutWaiting521=== RUN TestGCSweepDeliversEachKeyOnce522=== PAUSE TestGCSweepDeliversEachKeyOnce523=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection524=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== RUN TestForceGCDuringPushOffersSweptObject526=== PAUSE TestForceGCDuringPushOffersSweptObject527=== RUN TestFailedS3DeleteKeepsTombstone528=== PAUSE TestFailedS3DeleteKeepsTombstone529=== RUN TestSweepSkipsRowsLockedByPush530=== PAUSE TestSweepSkipsRowsLockedByPush531=== RUN TestRegisterCompletedObjectNeedsPendingRow532=== PAUSE TestRegisterCompletedObjectNeedsPendingRow533=== RUN TestGetExistingObjectsLocksRows534=== PAUSE TestGetExistingObjectsLocksRows535=== RUN TestSweepRechecksPendingAfterLocking536=== PAUSE TestSweepRechecksPendingAfterLocking537=== RUN TestPushWaitsForSweepHoldingRow538=== PAUSE TestPushWaitsForSweepHoldingRow539=== RUN TestCommitRacingPendingCleanupKeepsObjects540=== PAUSE TestCommitRacingPendingCleanupKeepsObjects541=== RUN TestGCEndsOnShutdown542=== PAUSE TestGCEndsOnShutdown543=== RUN TestGCTaskStore_StartNew544=== PAUSE TestGCTaskStore_StartNew545=== RUN TestGCTaskStore_DeduplicateSameParams546=== PAUSE TestGCTaskStore_DeduplicateSameParams547=== RUN TestGCTaskStore_ConflictDifferentParams548=== PAUSE TestGCTaskStore_ConflictDifferentParams549=== RUN TestGCTaskStore_GetEmpty550=== PAUSE TestGCTaskStore_GetEmpty551=== RUN TestGCTaskStore_GetReturnsLatest552=== PAUSE TestGCTaskStore_GetReturnsLatest553=== RUN TestGCTaskStore_CompletedAllowsNewTask554=== PAUSE TestGCTaskStore_CompletedAllowsNewTask555=== RUN TestGCTaskStore_PhaseUpdates556=== PAUSE TestGCTaskStore_PhaseUpdates557=== RUN TestGCTaskStore_Fail558=== PAUSE TestGCTaskStore_Fail559=== RUN TestGracefulShutdownDrainsInflight560=== PAUSE TestGracefulShutdownDrainsInflight561=== RUN TestService_healthCheckHandler562=== PAUSE TestService_healthCheckHandler563=== RUN TestService_readinessHandler564=== PAUSE TestService_readinessHandler565=== RUN TestGenerateLandingPage566=== PAUSE TestGenerateLandingPage567=== RUN TestCacheConfigHandlerMaxNarSize568=== PAUSE TestCacheConfigHandlerMaxNarSize569=== RUN TestCreatePendingClosureRejectsOversizedNAR570=== PAUSE TestCreatePendingClosureRejectsOversizedNAR571=== RUN TestNARDeduplicationMetadataUploadBug572=== PAUSE TestNARDeduplicationMetadataUploadBug573=== RUN TestMetricsInventory574=== PAUSE TestMetricsInventory575=== RUN TestService_NativeMTLS576=== PAUSE TestService_NativeMTLS577=== RUN TestServerTLSConfig578=== PAUSE TestServerTLSConfig579=== RUN TestMultipartCleanup580=== PAUSE TestMultipartCleanup581=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded582=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== RUN TestPendingCleanupUsesOneCutoff584=== PAUSE TestPendingCleanupUsesOneCutoff585=== RUN TestObjectStatsTrigger586=== PAUSE TestObjectStatsTrigger587=== RUN TestOrphanedObjectsGC588=== PAUSE TestOrphanedObjectsGC589=== RUN TestOrphanedObjectsGCStressTest590=== PAUSE TestOrphanedObjectsGCStressTest591=== RUN TestCreatePin_ReservedPins592=== PAUSE TestCreatePin_ReservedPins593=== RUN TestPresentReportsOnlyClosureRoots594=== PAUSE TestPresentReportsOnlyClosureRoots595=== RUN TestPresentNotReportedWhileGCDeletesClosure596=== PAUSE TestPresentNotReportedWhileGCDeletesClosure597=== RUN TestParseSingleRange598=== PAUSE TestParseSingleRange599=== RUN TestProxyHeadersOnlyTrustedOnSocket600=== PAUSE TestProxyHeadersOnlyTrustedOnSocket601=== RUN TestIsValidCachePath602=== PAUSE TestIsValidCachePath603=== RUN TestReadProxyNarinfo604=== PAUSE TestReadProxyNarinfo605=== RUN TestReadProxyNarinfoAlreadyDecompressed606=== PAUSE TestReadProxyNarinfoAlreadyDecompressed607=== RUN TestReadProxyNarStreaming608=== PAUSE TestReadProxyNarStreaming609=== RUN TestReadProxy404610=== PAUSE TestReadProxy404611=== RUN TestReadProxyInvalidPath612=== PAUSE TestReadProxyInvalidPath613=== RUN TestReadProxyHead614=== PAUSE TestReadProxyHead615=== RUN TestReadProxyConditionalGet616=== PAUSE TestReadProxyConditionalGet617=== RUN TestReadProxyRootRedirectsToIndexHTML618=== PAUSE TestReadProxyRootRedirectsToIndexHTML619=== RUN TestReadProxyDisabled620=== PAUSE TestReadProxyDisabled621=== RUN TestReadRedirectNar622=== PAUSE TestReadRedirectNar623=== RUN TestReadRedirectKeepsNarinfoProxied624=== PAUSE TestReadRedirectKeepsNarinfoProxied625=== RUN TestReadProxyRangeRequest626=== PAUSE TestReadProxyRangeRequest627=== RUN TestReadRedirectUsesPublicS3URL628=== PAUSE TestReadRedirectUsesPublicS3URL629=== RUN TestPush_OverlappingRootsStoreOneRowPerKey630=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey631=== RUN TestPush_CompleteCommitsEveryRoot632=== PAUSE TestPush_CompleteCommitsEveryRoot633=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit634=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit635=== RUN TestPush_RejectsBadRequests636=== PAUSE TestPush_RejectsBadRequests637=== RUN TestPush_SignsNarinfosOfItsPendingObjects638=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects639=== RUN TestRedundantMultipartUpload640=== PAUSE TestRedundantMultipartUpload641=== RUN TestCompleteMultipartUpload_ErrorButObjectExists642=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists643=== RUN TestCompletedNarNotReofferedAcrossClosures644=== PAUSE TestCompletedNarNotReofferedAcrossClosures645=== RUN TestPresignedUploadRegisteredBeforeCommit646=== PAUSE TestPresignedUploadRegisteredBeforeCommit647=== RUN TestService_Rustfstest648=== PAUSE TestService_Rustfstest649=== RUN TestParseSize650=== PAUSE TestParseSize651=== RUN TestSkippedUploadsHandler652=== PAUSE TestSkippedUploadsHandler653=== RUN TestSystemdListenerNotActivated654--- PASS: TestSystemdListenerNotActivated (0.00s)655=== RUN TestWatchdogBeatsWhenHealthy656--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)657=== RUN TestWatchdogSkipsWhenUnhealthy6582026/10/01 09:39:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6592026/10/01 09:39:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:39:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:39:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:39:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:39:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:39:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:39:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 09:39:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 09:39:51 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"668--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)669=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle670=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle671=== RUN TestProxyWriteTimeout672=== PAUSE TestProxyWriteTimeout673=== RUN TestIsValidUploadKey674=== PAUSE TestIsValidUploadKey675=== RUN TestUploadHandlersRejectInvalidKeys676=== PAUSE TestUploadHandlersRejectInvalidKeys677=== RUN TestUploadHandlersRejectOversizedBody678=== PAUSE TestUploadHandlersRejectOversizedBody679=== RUN TestService_cleanupPendingClosuresHandler680=== PAUSE TestService_cleanupPendingClosuresHandler681=== RUN TestService_createPendingClosureHandler682=== PAUSE TestService_createPendingClosureHandler683=== RUN TestService_verifyS3Integrity684=== PAUSE TestService_verifyS3Integrity685=== RUN TestCompleteMultipartUnregistered686=== PAUSE TestCompleteMultipartUnregistered687=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT688=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT689=== CONT TestParseSize690=== CONT TestCompletedNarNotReofferedAcrossClosures691=== CONT TestForceGCDuringPushOffersSweptObject692=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows693=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows694=== CONT TestService_Rustfstest695=== CONT TestPresignedUploadRegisteredBeforeCommit696=== CONT TestGCTaskStore_CompletedAllowsNewTask697=== CONT TestDeduplicatedObjectsRecordedAsPending698=== CONT TestGCTaskStore_GetReturnsLatest699=== CONT TestPushDedupSurvivesConcurrentGC700=== CONT TestGCTaskStore_GetEmpty701=== CONT TestGCMetrics702=== CONT TestGCTaskStore_ConflictDifferentParams703=== CONT TestGCBugBareHashReferences704=== CONT TestGCTaskStore_DeduplicateSameParams705=== CONT TestGCTaskStore_StartNew706=== CONT TestLeadElectsOneAndHandsOver707=== CONT TestGCEndsOnShutdown708=== CONT TestCommitRacingPendingCleanupKeepsObjects709=== CONT TestPushWaitsForSweepHoldingRow710=== CONT TestSweepRechecksPendingAfterLocking711=== CONT TestGetExistingObjectsLocksRows712=== CONT TestRegisterCompletedObjectNeedsPendingRow713=== CONT TestSweepSkipsRowsLockedByPush714=== CONT TestFailedS3DeleteKeepsTombstone715=== CONT TestGCTaskStore_PhaseUpdates716=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection717=== CONT TestGCSweepDeliversEachKeyOnce718=== CONT TestTombstonedObjectOfferedWithoutWaiting719=== CONT TestService_AuthMiddleware720--- PASS: TestParseSize (0.00s)721=== CONT TestGCSweepSkipsPendingObjects722=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check723=== CONT TestLeadEndsOnShutdown724=== CONT TestResolveDBConnectionString725=== RUN TestResolveDBConnectionString/flag_wins726=== PAUSE TestResolveDBConnectionString/flag_wins727=== RUN TestResolveDBConnectionString/file_when_flag_empty728=== PAUSE TestResolveDBConnectionString/file_when_flag_empty729=== RUN TestResolveDBConnectionString/missing_file_is_an_error730=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error731=== RUN TestResolveDBConnectionString/PGHOST_allows_empty732=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty733=== RUN TestResolveDBConnectionString/nothing_configured734=== PAUSE TestResolveDBConnectionString/nothing_configured735=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock736--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)737--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)738--- PASS: TestGCTaskStore_GetEmpty (0.00s)739--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)740--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)741--- PASS: TestGCTaskStore_StartNew (0.00s)742--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)743=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check744=== CONT TestClientFallsBackToClosures7452026-10-01 09:39:51.480 UTC [452] ERROR: relation "goose_db_version" does not exist at character 367462026-10-01 09:39:51.480 UTC [452] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7472026-10-01 09:39:51.484 UTC [453] ERROR: relation "goose_db_version" does not exist at character 367482026-10-01 09:39:51.484 UTC [453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7492026-10-01 09:39:51.485 UTC [454] ERROR: relation "goose_db_version" does not exist at character 367502026-10-01 09:39:51.485 UTC [454] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7512026-10-01 09:39:51.486 UTC [455] ERROR: relation "goose_db_version" does not exist at character 367522026-10-01 09:39:51.486 UTC [455] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7532026-10-01 09:39:51.486 UTC [456] ERROR: relation "goose_db_version" does not exist at character 367542026-10-01 09:39:51.486 UTC [456] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7552026-10-01 09:39:51.524 UTC [457] ERROR: relation "goose_db_version" does not exist at character 367562026-10-01 09:39:51.524 UTC [457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7572026-10-01 09:39:51.524 UTC [458] ERROR: relation "goose_db_version" does not exist at character 367582026-10-01 09:39:51.524 UTC [458] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7592026-10-01 09:39:51.527 UTC [459] ERROR: relation "goose_db_version" does not exist at character 367602026-10-01 09:39:51.527 UTC [459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7612026-10-01 09:39:51.530 UTC [463] ERROR: relation "goose_db_version" does not exist at character 367622026-10-01 09:39:51.530 UTC [463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7632026-10-01 09:39:51.532 UTC [464] ERROR: relation "goose_db_version" does not exist at character 367642026-10-01 09:39:51.532 UTC [464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7652026/10/01 09:39:51 OK 20241026095416_initial_model.sql (64.82ms)7662026/10/01 09:39:51 OK 20241026095416_initial_model.sql (66.93ms)7672026/10/01 09:39:51 OK 20241026095416_initial_model.sql (67.08ms)7682026/10/01 09:39:51 OK 20241026095416_initial_model.sql (65.95ms)7692026/10/01 09:39:51 OK 20241026095416_initial_model.sql (73.15ms)7702026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (6.84ms)7712026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (9.28ms)7722026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (9.24ms)7732026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (8.83ms)7742026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (4.57ms)7752026/10/01 09:39:51 OK 20251218171726_add_pins.sql (5.61ms)7762026/10/01 09:39:51 OK 20251218171726_add_pins.sql (6.31ms)7772026/10/01 09:39:51 OK 20241026095416_initial_model.sql (21.85ms)7782026/10/01 09:39:51 OK 20251218171726_add_pins.sql (6.51ms)7792026/10/01 09:39:51 OK 20251218171726_add_pins.sql (6.41ms)7802026/10/01 09:39:51 OK 20241026095416_initial_model.sql (21.98ms)7812026/10/01 09:39:51 OK 20251218171726_add_pins.sql (5.35ms)7822026/10/01 09:39:51 OK 20241026095416_initial_model.sql (22.2ms)7832026/10/01 09:39:51 OK 20241026095416_initial_model.sql (21.47ms)7842026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)7852026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (3.01ms)7862026/10/01 09:39:51 OK 20241026095416_initial_model.sql (21.97ms)7872026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)7882026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.15ms)7892026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.43ms)7902026-10-01 09:39:51.606 UTC [465] ERROR: relation "goose_db_version" does not exist at character 367912026-10-01 09:39:51.606 UTC [465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7922026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.8ms)7932026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.73ms)7942026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.94ms)7952026-10-01 09:39:51.607 UTC [466] ERROR: relation "goose_db_version" does not exist at character 367962026-10-01 09:39:51.607 UTC [466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7972026-10-01 09:39:51.607 UTC [467] ERROR: relation "goose_db_version" does not exist at character 367982026-10-01 09:39:51.607 UTC [467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7992026-10-01 09:39:51.607 UTC [469] ERROR: relation "goose_db_version" does not exist at character 368002026-10-01 09:39:51.607 UTC [469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8012026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.63ms)8022026-10-01 09:39:51.608 UTC [468] ERROR: relation "goose_db_version" does not exist at character 368032026-10-01 09:39:51.608 UTC [468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8042026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (3.81ms)8052026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.84ms)8062026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.98ms)8072026-10-01 09:39:51.609 UTC [470] ERROR: relation "goose_db_version" does not exist at character 368082026-10-01 09:39:51.609 UTC [470] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8092026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.77ms)8102026/10/01 09:39:51 OK 20260905000000_add_claims.sql (4.43ms)8112026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.82ms)8122026/10/01 09:39:51 OK 20260905000000_add_claims.sql (4.04ms)8132026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.76ms)8142026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.91ms)8152026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.53ms)8162026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.42ms)8172026/10/01 09:39:51 OK 20251218171726_add_pins.sql (5.1ms)8182026-10-01 09:39:51.614 UTC [471] ERROR: relation "goose_db_version" does not exist at character 368192026-10-01 09:39:51.614 UTC [471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8202026-10-01 09:39:51.614 UTC [472] ERROR: relation "goose_db_version" does not exist at character 368212026-10-01 09:39:51.614 UTC [472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8222026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (6.19ms)8232026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (4.2ms)8242026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (6.28ms)8252026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.02ms)8262026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200008272026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.37ms)8282026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (4.39ms)8292026-10-01 09:39:51.616 UTC [473] ERROR: relation "goose_db_version" does not exist at character 368302026-10-01 09:39:51.616 UTC [473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8312026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (5.04ms)8322026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.02ms)8332026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.45ms)8342026-10-01 09:39:51.618 UTC [474] ERROR: relation "goose_db_version" does not exist at character 368352026-10-01 09:39:51.618 UTC [474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8362026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.94ms)8372026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200008382026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.92ms)8392026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200008402026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (3.01ms)8412026-10-01 09:39:51.619 UTC [475] ERROR: relation "goose_db_version" does not exist at character 368422026-10-01 09:39:51.619 UTC [475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8432026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200008442026-10-01 09:39:51.619 UTC [476] ERROR: relation "goose_db_version" does not exist at character 368452026-10-01 09:39:51.619 UTC [476] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8462026/10/01 09:39:51 OK 1_commit_pending_closure.sql (3.77ms)8472026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.7ms)8482026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200008492026/10/01 09:39:51 OK 20260905000000_add_claims.sql (4.72ms)8502026/10/01 09:39:51 OK 20260905000000_add_claims.sql (4.81ms)8512026/10/01 09:39:51 OK 20260905000000_add_claims.sql (4.95ms)8522026/10/01 09:39:51 OK 20260905000000_add_claims.sql (5.13ms)8532026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.11ms)8542026-10-01 09:39:51.621 UTC [477] ERROR: relation "goose_db_version" does not exist at character 368552026-10-01 09:39:51.621 UTC [477] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8562026/10/01 09:39:51 OK 2_object_stats_trigger.sql (2.08ms)8572026/10/01 09:39:51 OK 1_commit_pending_closure.sql (3.45ms)8582026-10-01 09:39:51.622 UTC [478] ERROR: relation "goose_db_version" does not exist at character 368592026-10-01 09:39:51.622 UTC [478] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8602026/10/01 09:39:51 OK 1_commit_pending_closure.sql (3.35ms)8612026/10/01 09:39:51 OK 1_commit_pending_closure.sql (3.18ms)8622026/10/01 09:39:51 OK 1_commit_pending_closure.sql (3ms)8632026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.12ms)8642026/10/01 09:39:51 OK 3_commit_push.sql (1.67ms)8652026/10/01 09:39:51 goose: up to current file version: 38662026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.63ms)8672026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.56ms)8682026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.65ms)8692026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (4.64ms)8702026/10/01 09:39:51 OK 2_object_stats_trigger.sql (2.19ms)8712026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (4.63ms)8722026/10/01 09:39:51 OK 2_object_stats_trigger.sql (2.19ms)8732026/10/01 09:39:51 OK 3_commit_push.sql (1.41ms)8742026/10/01 09:39:51 goose: up to current file version: 38752026/10/01 09:39:51 OK 3_commit_push.sql (1.24ms)8762026/10/01 09:39:51 goose: up to current file version: 38772026/10/01 09:39:51 OK 20260905000000_add_claims.sql (4.36ms)8782026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.87ms)8792026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200008802026/10/01 09:39:51 OK 3_commit_push.sql (1.91ms)8812026/10/01 09:39:51 goose: up to current file version: 38822026/10/01 09:39:51 OK 3_commit_push.sql (1.97ms)8832026/10/01 09:39:51 goose: up to current file version: 38842026/10/01 09:39:51 OK 20241026095416_initial_model.sql (10.57ms)8852026/10/01 09:39:51 OK 20241026095416_initial_model.sql (10.63ms)8862026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.86ms)8872026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200008882026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.85ms)8892026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200008902026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.8ms)8912026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200008922026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.74ms)8932026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.96ms)8942026/10/01 09:39:51 OK 20241026095416_initial_model.sql (13.23ms)8952026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.37ms)8962026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.48ms)8972026/10/01 09:39:51 OK 20241026095416_initial_model.sql (13.59ms)8982026/10/01 09:39:51 OK 20241026095416_initial_model.sql (14.3ms)8992026/10/01 09:39:51 OK 20241026095416_initial_model.sql (13.78ms)9002026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.84ms)9012026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.33ms)9022026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.74ms)9032026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.27ms)9042026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200009052026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.78ms)9062026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)9072026/10/01 09:39:51 OK 3_commit_push.sql (1.52ms)9082026/10/01 09:39:51 goose: up to current file version: 39092026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)9102026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.33ms)9112026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.31ms)9122026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.22ms)9132026/10/01 09:39:51 OK 2_object_stats_trigger.sql (2.29ms)9142026/10/01 09:39:51 OK 2_object_stats_trigger.sql (2.37ms)9152026/10/01 09:39:51 OK 2_object_stats_trigger.sql (2.2ms)9162026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.39ms)9172026/10/01 09:39:51 OK 20241026095416_initial_model.sql (13.05ms)9182026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.45ms)9192026/10/01 09:39:51 OK 3_commit_push.sql (1.63ms)9202026/10/01 09:39:51 goose: up to current file version: 39212026/10/01 09:39:51 OK 20241026095416_initial_model.sql (13.19ms)9222026/10/01 09:39:51 OK 3_commit_push.sql (1.58ms)9232026/10/01 09:39:51 goose: up to current file version: 39242026/10/01 09:39:51 OK 3_commit_push.sql (2.37ms)9252026/10/01 09:39:51 goose: up to current file version: 39262026/10/01 09:39:51 OK 2_object_stats_trigger.sql (2.49ms)9272026/10/01 09:39:51 OK 20241026095416_initial_model.sql (12.38ms)9282026/10/01 09:39:51 OK 20241026095416_initial_model.sql (9.97ms)9292026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.64ms)9302026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.92ms)9312026/10/01 09:39:51 OK 20241026095416_initial_model.sql (9.73ms)9322026/10/01 09:39:51 OK 20241026095416_initial_model.sql (11.08ms)9332026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.63ms)9342026/10/01 09:39:51 OK 3_commit_push.sql (1.58ms)9352026/10/01 09:39:51 goose: up to current file version: 39362026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.64ms)9372026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.6ms)9382026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.61ms)9392026/10/01 09:39:51 OK 20241026095416_initial_model.sql (9.42ms)9402026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.55ms)9412026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.48ms)9422026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.95ms)9432026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (3.33ms)9442026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.79ms)9452026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (3.3ms)9462026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (3.04ms)9472026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.82ms)9482026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (4.25ms)9492026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.33ms)9502026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.21ms)9512026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.12ms)9522026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.15ms)9532026/10/01 09:39:51 OK 20241026095416_initial_model.sql (12.27ms)9542026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (4.33ms)9552026/10/01 09:39:51 OK 20251218171726_add_pins.sql (4.08ms)9562026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.73ms)9572026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.75ms)9582026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.86ms)9592026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.7ms)9602026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.65ms)9612026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.55ms)9622026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.93ms)9632026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (4.52ms)9642026/10/01 09:39:51 OK 20260905000000_add_claims.sql (4.36ms)9652026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (4.38ms)9662026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.31ms)9672026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (6.23ms)9682026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.3ms)9692026/10/01 09:39:51 OK 20260905000000_add_claims.sql (5.39ms)9702026/10/01 09:39:51 OK 20260905000000_add_claims.sql (6.34ms)9712026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.43ms)9722026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.96ms)9732026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.72ms)9742026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.8ms)9752026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.8ms)9762026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.14ms)9772026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.92ms)9782026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (5.24ms)9792026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.91ms)9802026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.3ms)9812026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (3.39ms)9822026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200009832026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (4.1ms)9842026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.33ms)9852026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200009862026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (3.39ms)9872026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.1ms)9882026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200009892026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.64ms)9902026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200009912026/10/01 09:39:51 INFO Aborted multipart uploads count=0 kept=09922026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.59ms)9932026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.49ms)9942026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.63ms)9952026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.15ms)9962026/10/01 09:39:51 goose: successfully migrated database to version: 202609231200009972026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.47ms)9982026/10/01 09:39:51 OK 20260905000000_add_claims.sql (4.65ms)9992026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.61ms)10002026/10/01 09:39:51 OK 20260905000000_add_claims.sql (5.15ms)10012026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.87ms)10022026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.84ms)10032026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000010042026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (1.67ms)10052026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000010062026/10/01 09:39:51 OK 20260905000000_add_claims.sql (5.18ms)10072026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.11ms)10082026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (1.78ms)10092026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000010102026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.8ms)10112026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.48ms)10122026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.83ms)10132026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.85ms)10142026/10/01 09:39:51 WARN Force mode enabled - objects will be deleted immediately without grace period10152026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.68ms)10162026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.69ms)10172026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.9ms)10182026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.64ms)10192026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.65ms)10202026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.53ms)10212026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.93ms)10222026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.95ms)10232026/10/01 09:39:51 OK 3_commit_push.sql (906.53µs)10242026/10/01 09:39:51 goose: up to current file version: 310252026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.17ms)10262026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.57ms)10272026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.28ms)10282026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.52ms)10292026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.84ms)10302026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.17ms)10312026/10/01 09:39:51 OK 3_commit_push.sql (913.81µs)10322026/10/01 09:39:51 OK 3_commit_push.sql (1.26ms)10332026/10/01 09:39:51 goose: up to current file version: 310342026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.49ms)10352026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000010362026/10/01 09:39:51 OK 3_commit_push.sql (1.97ms)10372026/10/01 09:39:51 goose: up to current file version: 310382026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (1.87ms)10392026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000010402026/10/01 09:39:51 goose: up to current file version: 310412026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (1.79ms)10422026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000010432026/10/01 09:39:51 OK 2_object_stats_trigger.sql (2.03ms)10442026/10/01 09:39:51 OK 3_commit_push.sql (1.95ms)10452026/10/01 09:39:51 goose: up to current file version: 310462026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (1.63ms)10472026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000010482026/10/01 09:39:51 OK 3_commit_push.sql (838.19µs)10492026/10/01 09:39:51 goose: up to current file version: 310502026/10/01 09:39:51 OK 2_object_stats_trigger.sql (2.08ms)10512026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (1.88ms)10522026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000010532026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.22ms)10542026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000010552026/10/01 09:39:51 OK 3_commit_push.sql (1.06ms)10562026/10/01 09:39:51 goose: up to current file version: 310572026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.35ms)10582026/10/01 09:39:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010592026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.82ms)10602026/10/01 09:39:51 OK 3_commit_push.sql (1.11ms)10612026/10/01 09:39:51 goose: up to current file version: 310622026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.57ms)10632026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.7ms)10642026/10/01 09:39:51 INFO Received uploads request method=POST path=/api/pending_closures10652026/10/01 09:39:51 OK 2_object_stats_trigger.sql (705.57µs)10662026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.22ms)10672026/10/01 09:39:51 INFO Vacuumed table table=pending_closures10682026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.13ms)10692026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.23ms)10702026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.69ms)10712026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.16ms)10722026/10/01 09:39:51 OK 3_commit_push.sql (646.77µs)10732026/10/01 09:39:51 goose: up to current file version: 310742026/10/01 09:39:51 INFO Vacuumed table table=pending_objects10752026/10/01 09:39:51 OK 2_object_stats_trigger.sql (671.99µs)10762026/10/01 09:39:51 INFO Vacuumed table table=multipart_uploads10772026/10/01 09:39:51 OK 3_commit_push.sql (713.15µs)10782026/10/01 09:39:51 goose: up to current file version: 310792026/10/01 09:39:51 INFO Vacuumed table table=closures10802026/10/01 09:39:51 OK 2_object_stats_trigger.sql (794.91µs)10812026/10/01 09:39:51 OK 3_commit_push.sql (777.83µs)10822026/10/01 09:39:51 goose: up to current file version: 310832026/10/01 09:39:51 OK 3_commit_push.sql (821.19µs)10842026/10/01 09:39:51 goose: up to current file version: 310852026/10/01 09:39:51 INFO Vacuumed table table=objects10862026/10/01 09:39:51 OK 3_commit_push.sql (597.99µs)10872026/10/01 09:39:51 goose: up to current file version: 310882026/10/01 09:39:51 OK 3_commit_push.sql (546.73µs)10892026/10/01 09:39:51 goose: up to current file version: 31090--- PASS: TestGCMetrics (0.37s)1091=== CONT TestClientPushesUseOnePush1092--- PASS: TestService_Rustfstest (0.38s)1093=== CONT TestPinProtectsFromGC10942026/10/01 09:39:51 INFO Received uploads request method=POST path=/api/pending_closures1095--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.41s)1096=== CONT TestClientSharedPathCommittedMidPush10972026/10/01 09:39:51 INFO Received uploads request method=POST path=/api/pending_closures10982026/10/01 09:39:51 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10992026/10/01 09:39:51 INFO Received uploads request method=POST path=/api/pending_closures1100--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.44s)1101=== CONT TestClientWithDependencies11022026/10/01 09:39:51 INFO lead: acquired remote=192.0.2.1:123411032026-10-01 09:39:51.752 UTC [492] ERROR: relation "goose_db_version" does not exist at character 3611042026-10-01 09:39:51.752 UTC [492] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11052026-10-01 09:39:51.753 UTC [493] ERROR: relation "goose_db_version" does not exist at character 3611062026-10-01 09:39:51.753 UTC [493] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11072026/10/01 09:39:51 INFO Aborted multipart uploads count=0 kept=011082026/10/01 09:39:51 WARN Force mode enabled - objects will be deleted immediately without grace period11092026/10/01 09:39:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011102026/10/01 09:39:51 INFO Vacuumed table table=pending_closures11112026/10/01 09:39:51 OK 20241026095416_initial_model.sql (9.96ms)1112--- PASS: TestGCEndsOnShutdown (0.48s)1113=== CONT TestClientMultipleUploads11142026/10/01 09:39:51 INFO Vacuumed table table=pending_objects11152026/10/01 09:39:51 INFO Vacuumed table table=multipart_uploads11162026/10/01 09:39:51 OK 20241026095416_initial_model.sql (10.63ms)11172026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (1.98ms)11182026/10/01 09:39:51 INFO Vacuumed table table=closures11192026/10/01 09:39:51 INFO Vacuumed table table=objects11202026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (1.83ms)11212026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.05ms)11222026/10/01 09:39:51 OK 20251218171726_add_pins.sql (2.9ms)11232026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (3.27ms)11242026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (2.7ms)11252026-10-01 09:39:51.778 UTC [496] ERROR: relation "goose_db_version" does not exist at character 3611262026-10-01 09:39:51.778 UTC [496] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1127--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.49s)1128=== CONT TestClientIntegration11292026/10/01 09:39:51 OK 20260905000000_add_claims.sql (2.94ms)11302026/10/01 09:39:51 OK 20260905000000_add_claims.sql (4.08ms)11312026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.73ms)11322026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.54ms)11332026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.66ms)11342026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000011352026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.6ms)11362026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000011372026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.8ms)11382026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.22ms)11392026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.79ms)11402026/10/01 09:39:51 OK 3_commit_push.sql (543.03µs)11412026/10/01 09:39:51 goose: up to current file version: 311422026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.36ms)11432026/10/01 09:39:51 OK 3_commit_push.sql (1.28ms)11442026/10/01 09:39:51 goose: up to current file version: 311452026/10/01 09:39:51 OK 20241026095416_initial_model.sql (11.05ms)11462026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)11472026-10-01 09:39:51.799 UTC [500] ERROR: relation "goose_db_version" does not exist at character 3611482026-10-01 09:39:51.799 UTC [500] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11492026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.72ms)11502026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (10.25ms)11512026/10/01 09:39:51 INFO Received uploads request method=POST path=/api/pending_closures11522026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.75ms)11532026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.43ms)11542026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.59ms)11552026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000011562026/10/01 09:39:51 OK 1_commit_pending_closure.sql (3.32ms)11572026/10/01 09:39:51 OK 20241026095416_initial_model.sql (12.86ms)11582026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.58ms)11592026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (2.09ms)11602026/10/01 09:39:51 OK 3_commit_push.sql (1.09ms)11612026/10/01 09:39:51 goose: up to current file version: 311622026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.45ms)11632026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (3.41ms)11642026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.09ms)11652026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.14ms)11662026/10/01 09:39:51 INFO Received uploads request method=POST path=/api/pending_closures11672026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.12ms)11682026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000011692026-10-01 09:39:51.842 UTC [502] ERROR: relation "goose_db_version" does not exist at character 3611702026-10-01 09:39:51.842 UTC [502] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11712026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.7ms)11722026/10/01 09:39:51 INFO Received uploads request method=POST path=/api/pending_closures11732026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.02ms)11742026/10/01 09:39:51 OK 3_commit_push.sql (984.15µs)11752026/10/01 09:39:51 goose: up to current file version: 311762026-10-01 09:39:51.851 UTC [503] ERROR: relation "goose_db_version" does not exist at character 3611772026-10-01 09:39:51.851 UTC [503] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11782026/10/01 09:39:51 OK 20241026095416_initial_model.sql (8.83ms)11792026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (1.23ms)11802026/10/01 09:39:51 OK 20251218171726_add_pins.sql (2.68ms)1181--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.57s)1182=== CONT TestClientErrorHandling1183=== RUN TestClientErrorHandling/InvalidStorePath1184=== PAUSE TestClientErrorHandling/InvalidStorePath1185=== RUN TestClientErrorHandling/InvalidAuthToken1186=== PAUSE TestClientErrorHandling/InvalidAuthToken1187=== RUN TestClientErrorHandling/ServerNotAvailable1188=== PAUSE TestClientErrorHandling/ServerNotAvailable1189=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT11902026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (3.1ms)11912026/10/01 09:39:51 OK 20241026095416_initial_model.sql (9.89ms)11922026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.17ms)11932026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (1.54ms)11942026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (1.87ms)11952026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (1.67ms)11962026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000011972026/10/01 09:39:51 OK 20251218171726_add_pins.sql (3.2ms)11982026/10/01 09:39:51 OK 1_commit_pending_closure.sql (1.81ms)11992026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.06ms)12002026/10/01 09:39:51 OK 3_commit_push.sql (1.09ms)12012026/10/01 09:39:51 goose: up to current file version: 312022026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (3.81ms)12032026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.14ms)12042026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (2.56ms)12052026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (1.74ms)12062026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000012072026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.11ms)12082026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.39ms)12092026/10/01 09:39:51 OK 3_commit_push.sql (1.23ms)12102026/10/01 09:39:51 goose: up to current file version: 31211--- PASS: TestGetExistingObjectsLocksRows (0.60s)1212=== CONT TestUploadHandlersRejectOversizedBody12132026/10/01 09:39:51 INFO lead: released remote=192.0.2.1:123412142026/10/01 09:39:51 INFO Aborted multipart uploads count=0 kept=012152026/10/01 09:39:51 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=012162026/10/01 09:39:51 INFO Received uploads request method=POST path=/api/pending_closures12172026/10/01 09:39:51 INFO Aborted multipart uploads count=0 kept=012182026/10/01 09:39:51 INFO Vacuumed table table=pending_closures12192026/10/01 09:39:51 INFO Aborted multipart uploads count=0 kept=012202026/10/01 09:39:51 INFO Vacuumed table table=pending_objects12212026/10/01 09:39:51 INFO Vacuumed table table=multipart_uploads12222026/10/01 09:39:51 WARN Force mode enabled - objects will be deleted immediately without grace period12232026/10/01 09:39:51 INFO Vacuumed table table=closures12242026/10/01 09:39:51 WARN Force mode enabled - objects will be deleted immediately without grace period12252026/10/01 09:39:51 INFO Vacuumed table table=objects12262026/10/01 09:39:51 INFO Aborted multipart uploads count=0 kept=012272026/10/01 09:39:51 WARN Force mode enabled - objects will be deleted immediately without grace period12282026-10-01 09:39:51.928 UTC [511] ERROR: relation "goose_db_version" does not exist at character 3612292026-10-01 09:39:51.928 UTC [511] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12302026/10/01 09:39:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012312026/10/01 09:39:51 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12322026/10/01 09:39:51 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."12332026/10/01 09:39:51 INFO Vacuumed table table=pending_closures1234--- PASS: TestFailedS3DeleteKeepsTombstone (0.64s)12352026/10/01 09:39:51 INFO Vacuumed table table=pending_objects1236=== CONT TestClientCADerivations12372026/10/01 09:39:51 INFO Vacuumed table table=multipart_uploads12382026/10/01 09:39:51 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1239--- PASS: TestService_AuthMiddleware (0.64s)1240=== CONT TestCacheStatsHandler12412026/10/01 09:39:51 INFO Vacuumed table table=closures12422026/10/01 09:39:51 INFO Aborted multipart uploads count=0 kept=012432026/10/01 09:39:51 INFO Vacuumed table table=objects1244--- PASS: TestPushDedupSurvivesConcurrentGC (0.64s)1245=== CONT TestCacheConfigHandler1246=== RUN TestCacheConfigHandler/full_config,_no_issuer1247=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1248=== RUN TestCacheConfigHandler/no_cache_url_configured1249=== PAUSE TestCacheConfigHandler/no_cache_url_configured1250=== RUN TestCacheConfigHandler/no_signing_keys1251=== PAUSE TestCacheConfigHandler/no_signing_keys1252=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1253=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1254=== CONT TestService_ReadScope_PublicByDefault12552026/10/01 09:39:51 WARN Force mode enabled - objects will be deleted immediately without grace period12562026/10/01 09:39:51 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=012572026/10/01 09:39:51 INFO Vacuumed table table=pending_closures12582026/10/01 09:39:51 INFO Vacuumed table table=pending_objects12592026/10/01 09:39:51 INFO Vacuumed table table=multipart_uploads12602026/10/01 09:39:51 INFO Vacuumed table table=closures12612026/10/01 09:39:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012622026/10/01 09:39:51 INFO Vacuumed table table=objects12632026/10/01 09:39:51 INFO Vacuumed table table=pending_closures1264--- PASS: TestGCSweepDeliversEachKeyOnce (0.65s)1265=== CONT TestService_RequireScope_OIDC12662026/10/01 09:39:51 OK 20241026095416_initial_model.sql (10.22ms)12672026/10/01 09:39:51 INFO Vacuumed table table=pending_objects12682026/10/01 09:39:51 INFO Vacuumed table table=multipart_uploads12692026/10/01 09:39:51 INFO Vacuumed table table=closures12702026/10/01 09:39:51 INFO lead: acquired remote=192.0.2.1:123412712026/10/01 09:39:51 OK 20251210153512_drop_unused_gin_index.sql (1.7ms)12722026/10/01 09:39:51 INFO Vacuumed table table=objects12732026/10/01 09:39:51 INFO lead: released remote=192.0.2.1:12341274--- PASS: TestLeadElectsOneAndHandsOver (0.66s)1275=== CONT TestService_AuthMiddleware_OIDC12762026/10/01 09:39:51 OK 20251218171726_add_pins.sql (9.58ms)1277--- PASS: TestGCSweepSkipsPendingObjects (0.66s)1278=== CONT TestService_ReadAuthMiddleware12792026/10/01 09:39:51 OK 20260628120000_add_object_size_and_stats.sql (4.27ms)12802026/10/01 09:39:51 OK 20260905000000_add_claims.sql (3.55ms)12812026/10/01 09:39:51 OK 20260920000000_drop_claims.sql (3.11ms)12822026/10/01 09:39:51 OK 20260923120000_add_pushes.sql (2.24ms)12832026/10/01 09:39:51 goose: successfully migrated database to version: 2026092312000012842026/10/01 09:39:51 OK 1_commit_pending_closure.sql (2.77ms)12852026/10/01 09:39:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36549/oidc12862026/10/01 09:39:51 OK 2_object_stats_trigger.sql (1.86ms)12872026/10/01 09:39:51 OK 3_commit_push.sql (1.8ms)12882026/10/01 09:39:51 goose: up to current file version: 312892026-10-01 09:39:52.011 UTC [529] ERROR: relation "goose_db_version" does not exist at character 3612902026-10-01 09:39:52.011 UTC [529] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12912026-10-01 09:39:52.011 UTC [530] ERROR: relation "goose_db_version" does not exist at character 3612922026-10-01 09:39:52.011 UTC [530] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12932026-10-01 09:39:52.011 UTC [531] ERROR: relation "goose_db_version" does not exist at character 3612942026-10-01 09:39:52.011 UTC [531] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12952026/10/01 09:39:52 INFO Aborted multipart uploads count=0 kept=012962026/10/01 09:39:52 WARN Force mode enabled - objects will be deleted immediately without grace period12972026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures12982026/10/01 09:39:52 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=012992026/10/01 09:39:52 INFO Vacuumed table table=pending_closures13002026/10/01 09:39:52 INFO Vacuumed table table=pending_objects13012026/10/01 09:39:52 INFO Vacuumed table table=multipart_uploads13022026/10/01 09:39:52 INFO Vacuumed table table=closures13032026/10/01 09:39:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13042026/10/01 09:39:52 INFO Vacuumed table table=objects13052026/10/01 09:39:52 INFO Aborted multipart uploads count=0 kept=013062026/10/01 09:39:52 INFO lead: acquired remote=192.0.2.1:123413072026/10/01 09:39:52 INFO lead: released remote=192.0.2.1:12341308--- PASS: TestLeadEndsOnShutdown (0.74s)1309=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13102026-10-01 09:39:52.033 UTC [550] ERROR: relation "goose_db_version" does not exist at character 3613112026-10-01 09:39:52.033 UTC [550] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13122026/10/01 09:39:52 WARN Force mode enabled - objects will be deleted immediately without grace period13132026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.1ms)13142026/10/01 09:39:52 OK 20241026095416_initial_model.sql (13ms)1315=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1316=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1317=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1318=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1319=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1320=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1321=== CONT TestService_AuthMiddleware_MTLSProxyHeader13222026/10/01 09:39:52 OK 20241026095416_initial_model.sql (34.18ms)13232026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures13242026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.01ms)13252026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.73ms)13262026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.63ms)13272026/10/01 09:39:52 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZTJhOTlkODMtOWZjMS00MWNkLTg5ZGMtYjZiZTgyZjY5M2YyLjE0ZjRkMjM3LWNiZjAtNDIzYS05NTI0LWYzMGRkYzg5NTEyZXgxNzkwODQ3NTkxNjY3NTI2NjI1 parts=1213282026-10-01 09:39:52.064 UTC [584] ERROR: relation "goose_db_version" does not exist at character 3613292026-10-01 09:39:52.064 UTC [584] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13302026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures13312026/10/01 09:39:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=013322026/10/01 09:39:52 INFO Vacuumed table table=pending_closures13332026/10/01 09:39:52 INFO Vacuumed table table=pending_objects13342026/10/01 09:39:52 INFO Vacuumed table table=multipart_uploads1335--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.77s)1336=== CONT TestCompleteMultipartUnregistered13372026/10/01 09:39:52 INFO Vacuumed table table=closures13382026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.68ms)13392026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.66ms)13402026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.54ms)1341--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.78s)1342=== CONT TestService_createPendingClosureHandler13432026/10/01 09:39:52 INFO Vacuumed table table=objects13442026/10/01 09:39:52 OK 20241026095416_initial_model.sql (10.06ms)13452026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.08ms)1346--- PASS: TestSweepSkipsRowsLockedByPush (0.78s)1347=== CONT TestService_cleanupPendingClosuresHandler13482026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.68ms)13492026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.68ms)13502026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)13512026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.22ms)13522026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.45ms)13532026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.5ms)13542026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.53ms)13552026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.87ms)13562026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.5ms)13572026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.2ms)13582026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.08ms)13592026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.61ms)13602026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000013612026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.85ms)13622026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000013632026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (3.11ms)13642026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000013652026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.15ms)13662026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.57ms)13672026/10/01 09:39:52 OK 1_commit_pending_closure.sql (3.09ms)13682026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.36ms)13692026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.18ms)13702026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.85ms)13712026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.44ms)13722026/10/01 09:39:52 OK 2_object_stats_trigger.sql (2.2ms)13732026/10/01 09:39:52 OK 2_object_stats_trigger.sql (2.15ms)13742026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.84ms)13752026/10/01 09:39:52 OK 3_commit_push.sql (1.91ms)13762026/10/01 09:39:52 goose: up to current file version: 313772026/10/01 09:39:52 OK 3_commit_push.sql (2.13ms)13782026/10/01 09:39:52 goose: up to current file version: 313792026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.23ms)13802026/10/01 09:39:52 OK 3_commit_push.sql (2.43ms)13812026/10/01 09:39:52 goose: up to current file version: 313822026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (3.76ms)13832026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000013842026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.43ms)13852026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.23ms)13862026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.62ms)13872026/10/01 09:39:52 INFO Aborted multipart uploads count=0 kept=013882026/10/01 09:39:52 WARN Force mode enabled - objects will be deleted immediately without grace period13892026-10-01 09:39:52.101 UTC [610] ERROR: relation "goose_db_version" does not exist at character 3613902026-10-01 09:39:52.101 UTC [610] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13912026/10/01 09:39:52 OK 20260905000000_add_claims.sql (9.95ms)13922026/10/01 09:39:52 OK 3_commit_push.sql (8.12ms)13932026/10/01 09:39:52 goose: up to current file version: 313942026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.12ms)13952026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.44ms)13962026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000013972026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.19ms)13982026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.39ms)13992026/10/01 09:39:52 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=014002026/10/01 09:39:52 OK 3_commit_push.sql (1.53ms)14012026/10/01 09:39:52 goose: up to current file version: 314022026/10/01 09:39:52 INFO Vacuumed table table=pending_closures14032026/10/01 09:39:52 OK 20241026095416_initial_model.sql (11.92ms)14042026/10/01 09:39:52 INFO Vacuumed table table=pending_objects14052026/10/01 09:39:52 INFO Vacuumed table table=multipart_uploads14062026/10/01 09:39:52 INFO Vacuumed table table=closures14072026/10/01 09:39:52 INFO Vacuumed table table=objects14082026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.01ms)1409--- PASS: TestSweepRechecksPendingAfterLocking (0.83s)1410=== CONT TestService_verifyS3Integrity14112026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.67ms)14122026/10/01 09:39:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43285/oidc14132026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (2.88ms)14142026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.48ms)14152026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.38ms)14162026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.16ms)14172026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000014182026-10-01 09:39:52.139 UTC [634] ERROR: relation "goose_db_version" does not exist at character 3614192026-10-01 09:39:52.139 UTC [634] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14202026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.68ms)14212026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.59ms)14222026-10-01 09:39:52.144 UTC [652] ERROR: relation "goose_db_version" does not exist at character 3614232026-10-01 09:39:52.144 UTC [652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14242026/10/01 09:39:52 OK 3_commit_push.sql (2.46ms)14252026/10/01 09:39:52 goose: up to current file version: 314262026-10-01 09:39:52.153 UTC [655] ERROR: relation "goose_db_version" does not exist at character 3614272026-10-01 09:39:52.153 UTC [655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14282026-10-01 09:39:52.162 UTC [673] ERROR: relation "goose_db_version" does not exist at character 3614292026-10-01 09:39:52.162 UTC [673] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14302026/10/01 09:39:52 OK 20241026095416_initial_model.sql (18.54ms)14312026/10/01 09:39:52 OK 20241026095416_initial_model.sql (14.15ms)14322026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.83ms)14332026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)14342026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.61ms)14352026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4ms)14362026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures1437=== NAME TestPinProtectsFromGC1438 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC2487878059/001/store/mf5cmlb7y5djhys6jvbnh7d31mqwb9ir-pinned-file.txt1439 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC2487878059/001/store/c5ffaxi486jz139253n3p5x364s73cqz-unpinned-file.txt14402026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.21ms)1441--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.88s)1442=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle14432026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.15ms)14442026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures14452026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.88ms)14462026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.71ms)14472026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.45ms)14482026/10/01 09:39:52 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14492026/10/01 09:39:52 INFO Uploading 8g307iivg9lq752dvcjdch4nq6a2kgv7-a (216B)14502026/10/01 09:39:52 INFO Uploading l6x6cw77xy95ysqbcwl4a0vgf0k69b6f-shared-dep (136B)14512026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.16ms)14522026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.32ms)14532026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.93ms)1454--- PASS: TestGCBugBareHashReferences (0.89s)1455=== CONT TestProxyHeadersOnlyTrustedOnSocket14562026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.26ms)14572026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.88ms)14582026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (3.07ms)14592026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000014602026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.16ms)14612026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (3.26ms)14622026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000014632026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.09ms)14642026/10/01 09:39:52 WARN Failed to register uploaded object key=y08jvhkn8y0r0v825pcr2yrgfs0k8iza.ls error="server returned 404: 404 page not found\n"14652026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14662026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/0xznj80skll0anrfgj7gak6ykx7i1ldsrj5jazhnm8rlifa9nkal.nar.zst error="server returned 404: 404 page not found\n"14672026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.42ms)14682026/10/01 09:39:52 WARN Failed to register uploaded object key=l6x6cw77xy95ysqbcwl4a0vgf0k69b6f.ls error="server returned 404: 404 page not found\n"14692026/10/01 09:39:52 WARN Failed to register uploaded object key=8g307iivg9lq752dvcjdch4nq6a2kgv7.ls error="server returned 404: 404 page not found\n"14702026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14712026/10/01 09:39:52 INFO Signed narinfos id=1 count=214722026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.61ms)14732026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14742026/10/01 09:39:52 INFO Signed narinfos id=2 count=214752026/10/01 09:39:52 INFO Uploading 4 narinfos14762026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.81ms)14772026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.45ms)14782026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.5ms)14792026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.93ms)14802026/10/01 09:39:52 OK 3_commit_push.sql (1.22ms)14812026/10/01 09:39:52 goose: up to current file version: 314822026/10/01 09:39:52 OK 3_commit_push.sql (1.65ms)14832026/10/01 09:39:52 goose: up to current file version: 314842026/10/01 09:39:52 WARN Failed to register uploaded object key=l6x6cw77xy95ysqbcwl4a0vgf0k69b6f.narinfo error="server returned 404: 404 page not found\n"14852026/10/01 09:39:52 WARN Failed to register uploaded object key=8g307iivg9lq752dvcjdch4nq6a2kgv7.narinfo error="server returned 404: 404 page not found\n"14862026/10/01 09:39:52 WARN Failed to register uploaded object key=y08jvhkn8y0r0v825pcr2yrgfs0k8iza.narinfo error="server returned 404: 404 page not found\n"14872026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.63ms)14882026/10/01 09:39:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14892026/10/01 09:39:52 WARN Failed to register uploaded object key=l6x6cw77xy95ysqbcwl4a0vgf0k69b6f.narinfo error="server returned 404: 404 page not found\n"14902026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.49ms)14912026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.94ms)14922026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.24ms)14932026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000014942026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.35ms)14952026/10/01 09:39:52 INFO Completed upload id=114962026/10/01 09:39:52 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14972026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.57ms)14982026/10/01 09:39:52 INFO Completed upload id=214992026/10/01 09:39:52 INFO Upload complete. (69ms)15002026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.98ms)15012026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (3.14ms)15022026/10/01 09:39:52 goose: successfully migrated database to version: 202609231200001503=== NAME TestClientFallsBackToClosures1504 client_pushes_test.go:112: Retrieved narinfo from S3:1505 StorePath: /build/TestClientFallsBackToClosures1323079369/001/store/l6x6cw77xy95ysqbcwl4a0vgf0k69b6f-shared-dep1506 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1507 Compression: zstd1508 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821509 NarSize: 1361510 References: 1511 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n15122026-10-01 09:39:52.204 UTC [783] ERROR: relation "goose_db_version" does not exist at character 3615132026-10-01 09:39:52.204 UTC [783] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15142026/10/01 09:39:52 OK 3_commit_push.sql (1.55ms)15152026/10/01 09:39:52 goose: up to current file version: 315162026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.37ms)15172026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.49ms)1518 client_pushes_test.go:112: Retrieved narinfo from S3:1519 StorePath: /build/TestClientFallsBackToClosures1323079369/001/store/8g307iivg9lq752dvcjdch4nq6a2kgv7-a1520 URL: nar/0xznj80skll0anrfgj7gak6ykx7i1ldsrj5jazhnm8rlifa9nkal.nar.zst1521 Compression: zstd1522 NarHash: sha256:0xznj80skll0anrfgj7gak6ykx7i1ldsrj5jazhnm8rlifa9nkal1523 NarSize: 2161524 References: /build/TestClientFallsBackToClosures1323079369/001/store/l6x6cw77xy95ysqbcwl4a0vgf0k69b6f-shared-dep1525 CA: text:sha256:0ns4dkafqq9whbl8yxfipwd2vz069sfrmkwklfb2r16adgp1ixw915262026/10/01 09:39:52 OK 3_commit_push.sql (1.28ms)15272026/10/01 09:39:52 goose: up to current file version: 31528 client_pushes_test.go:112: Retrieved narinfo from S3:1529 StorePath: /build/TestClientFallsBackToClosures1323079369/001/store/y08jvhkn8y0r0v825pcr2yrgfs0k8iza-b1530 URL: nar/0xznj80skll0anrfgj7gak6ykx7i1ldsrj5jazhnm8rlifa9nkal.nar.zst1531 Compression: zstd1532 NarHash: sha256:0xznj80skll0anrfgj7gak6ykx7i1ldsrj5jazhnm8rlifa9nkal1533 NarSize: 2161534 References: /build/TestClientFallsBackToClosures1323079369/001/store/l6x6cw77xy95ysqbcwl4a0vgf0k69b6f-shared-dep1535 CA: text:sha256:0ns4dkafqq9whbl8yxfipwd2vz069sfrmkwklfb2r16adgp1ixw915362026-10-01 09:39:52.212 UTC [784] ERROR: relation "goose_db_version" does not exist at character 3615372026-10-01 09:39:52.212 UTC [784] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1538--- PASS: TestClientFallsBackToClosures (0.92s)1539=== CONT TestCompleteMultipartUpload_ErrorButObjectExists15402026/10/01 09:39:52 OK 20241026095416_initial_model.sql (8.78ms)15412026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.09ms)1542=== NAME TestClientMultipleUploads1543 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads676901091/001/store/gxsln3lkfclz4j2pvq99fnqvpj6y86zh-test-file-0.txt15442026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.44ms)1545--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.94s)1546=== CONT TestProxyWriteTimeout1547=== RUN TestProxyWriteTimeout/narinfo1548=== PAUSE TestProxyWriteTimeout/narinfo1549=== RUN TestProxyWriteTimeout/1_GiB_nar1550=== PAUSE TestProxyWriteTimeout/1_GiB_nar1551=== RUN TestProxyWriteTimeout/10_GiB_nar1552=== PAUSE TestProxyWriteTimeout/10_GiB_nar1553=== RUN TestProxyWriteTimeout/unknown_size1554=== PAUSE TestProxyWriteTimeout/unknown_size1555=== CONT TestRedundantMultipartUpload15562026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.14ms)15572026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.15ms)15582026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures15592026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.48ms)15602026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.77ms)15612026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.46ms)15622026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.55ms)15632026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes15642026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.44ms)15652026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (8.47ms)15662026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000015672026/10/01 09:39:52 OK 20260905000000_add_claims.sql (8.25ms)1568--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.39s)1569=== CONT TestUploadHandlersRejectInvalidKeys1570=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1571=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1572=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1573=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1574=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1575=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1576=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1577=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1578=== CONT TestPush_SignsNarinfosOfItsPendingObjects15792026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.31ms)15802026/10/01 09:39:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15812026/10/01 09:39:52 INFO Uploading mf5cmlb7y5djhys6jvbnh7d31mqwb9ir-pinned-file.txt (128B)1582=== NAME TestClientWithDependencies1583 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies35895431/001/store/nc1nvnbbzd1k3n6w1kk41c4w897i02an-test-script1584=== NAME TestClientIntegration1585 client_integration_test.go:286: Created store path: /build/TestClientIntegration362278698/002/store/n4x5v1js8l6d751byssxh3hr6yknyffr-test-file.txt15862026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.21ms)15872026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.48ms)15882026/10/01 09:39:52 OK 3_commit_push.sql (1.36ms)15892026/10/01 09:39:52 goose: up to current file version: 315902026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.12ms)15912026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000015922026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.56ms)15932026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15942026/10/01 09:39:52 WARN Failed to register uploaded object key=mf5cmlb7y5djhys6jvbnh7d31mqwb9ir.ls error="server returned 404: 404 page not found\n"15952026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15962026/10/01 09:39:52 INFO Signed narinfos id=1 count=115972026/10/01 09:39:52 INFO Uploading 1 narinfos15982026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.62ms)15992026/10/01 09:39:52 OK 3_commit_push.sql (1.34ms)16002026/10/01 09:39:52 goose: up to current file version: 316012026-10-01 09:39:52.259 UTC [913] ERROR: relation "goose_db_version" does not exist at character 3616022026-10-01 09:39:52.259 UTC [913] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16032026-10-01 09:39:52.259 UTC [914] ERROR: relation "goose_db_version" does not exist at character 3616042026-10-01 09:39:52.259 UTC [914] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16052026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/1/complete16062026/10/01 09:39:52 WARN Failed to register uploaded object key=mf5cmlb7y5djhys6jvbnh7d31mqwb9ir.narinfo error="server returned 404: 404 page not found\n"1607=== NAME TestClientMultipleUploads1608 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads676901091/001/store/rp5gdc0nrspy771v6jmj9cc8b9qvn9gc-test-file-1.txt16092026/10/01 09:39:52 INFO Upload complete. (64ms)1610--- PASS: TestService_ReadScope_PublicByDefault (0.34s)1611=== CONT TestIsValidUploadKey1612=== RUN TestIsValidUploadKey/narinfo1613=== PAUSE TestIsValidUploadKey/narinfo1614=== RUN TestIsValidUploadKey/nar_zst1615=== PAUSE TestIsValidUploadKey/nar_zst1616=== RUN TestIsValidUploadKey/nar_xz1617=== PAUSE TestIsValidUploadKey/nar_xz1618=== RUN TestIsValidUploadKey/nar_plain1619=== PAUSE TestIsValidUploadKey/nar_plain1620=== RUN TestIsValidUploadKey/listing1621=== PAUSE TestIsValidUploadKey/listing1622=== RUN TestIsValidUploadKey/build_log1623=== PAUSE TestIsValidUploadKey/build_log1624=== RUN TestIsValidUploadKey/build_log_home-manager_file1625=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1626=== RUN TestIsValidUploadKey/build_log_plus_in_name1627=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1628=== RUN TestIsValidUploadKey/build_log_question_mark1629=== PAUSE TestIsValidUploadKey/build_log_question_mark1630=== RUN TestIsValidUploadKey/build_log_equals1631=== PAUSE TestIsValidUploadKey/build_log_equals1632=== RUN TestIsValidUploadKey/realisation1633=== PAUSE TestIsValidUploadKey/realisation1634=== RUN TestIsValidUploadKey/realisation_plus_in_output1635=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1636=== RUN TestIsValidUploadKey/nix-cache-info1637=== PAUSE TestIsValidUploadKey/nix-cache-info1638=== RUN TestIsValidUploadKey/index.html1639=== PAUSE TestIsValidUploadKey/index.html1640=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1641=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1642=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1643=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1644=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1645=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1646=== RUN TestIsValidUploadKey/traversal1647=== PAUSE TestIsValidUploadKey/traversal1648=== RUN TestIsValidUploadKey/traversal_nar1649=== PAUSE TestIsValidUploadKey/traversal_nar1650=== RUN TestIsValidUploadKey/absolute1651=== PAUSE TestIsValidUploadKey/absolute1652=== RUN TestIsValidUploadKey/empty_key1653=== PAUSE TestIsValidUploadKey/empty_key1654=== RUN TestIsValidUploadKey/unknown_type1655=== PAUSE TestIsValidUploadKey/unknown_type1656=== CONT TestPush_RejectsBadRequests16572026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.64ms)16582026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.84ms)1659=== NAME TestClientWithDependencies1660 client_integration_test.go:615: Found 1 dependencies (including self)16612026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)16622026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.74ms)16632026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.81ms)16642026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.9ms)16652026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.99ms)16662026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.89ms)16672026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.11ms)16682026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.24ms)16692026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes16702026-10-01 09:39:52.294 UTC [1023] ERROR: relation "goose_db_version" does not exist at character 3616712026-10-01 09:39:52.294 UTC [1023] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16722026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.59ms)16732026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.57ms)16742026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.8ms)16752026/10/01 09:39:52 goose: successfully migrated database to version: 202609231200001676=== NAME TestClientMultipleUploads1677 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads676901091/001/store/043fah7avbi9nh5kbv375z9al6l6vzc2-test-file-2.txt16782026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes16792026/10/01 09:39:52 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16802026/10/01 09:39:52 INFO Uploading k5fi3mgnw9zxg3644sim8c54yngc76zs-top (224B)16812026/10/01 09:39:52 INFO Uploading 6pyqznw4b1hy6n7wlycz3lkcvs1fqb6b-shared-dep (136B)16822026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.8ms)16832026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000016842026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.29ms)16852026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.26ms)16862026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.8ms)16872026/10/01 09:39:52 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16882026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.72ms)16892026/10/01 09:39:52 WARN Failed to register uploaded object key=k5fi3mgnw9zxg3644sim8c54yngc76zs.ls error="server returned 404: 404 page not found\n"16902026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/1jvzvps5dl517hfd8n9yj65j7s3kcrwfkihac0m56blahfnk87vj.nar.zst error="server returned 404: 404 page not found\n"16912026/10/01 09:39:52 INFO Uploading pqb71790jgd9ln99c2lfgyj4f5y3mws2-shared-dep (136B)16922026/10/01 09:39:52 INFO Uploading mamx4fr50p2bwg6z9c94k3gjpvl2g1pf-b (216B)16932026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16942026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16952026/10/01 09:39:52 WARN Failed to register uploaded object key=6pyqznw4b1hy6n7wlycz3lkcvs1fqb6b.ls error="server returned 404: 404 page not found\n"16962026/10/01 09:39:52 OK 3_commit_push.sql (1.27ms)16972026/10/01 09:39:52 goose: up to current file version: 316982026/10/01 09:39:52 INFO Signed narinfos id=1 count=216992026/10/01 09:39:52 INFO Uploading 2 narinfos17002026/10/01 09:39:52 OK 3_commit_push.sql (1.4ms)17012026/10/01 09:39:52 goose: up to current file version: 31702--- PASS: TestCacheStatsHandler (0.37s)1703=== CONT TestSkippedUploadsHandler17042026/10/01 09:39:52 INFO Client skipped oversized paths paths=3 nar_bytes=500000000017052026/10/01 09:39:52 WARN Failed to register uploaded object key=3iwz6q9rx448ph47j4ag6b8x9pbpy222.ls error="server returned 404: 404 page not found\n"17062026/10/01 09:39:52 WARN Failed to register uploaded object key=pqb71790jgd9ln99c2lfgyj4f5y3mws2.ls error="server returned 404: 404 page not found\n"17072026/10/01 09:39:52 WARN Failed to register uploaded object key=mamx4fr50p2bwg6z9c94k3gjpvl2g1pf.ls error="server returned 404: 404 page not found\n"17082026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/0vi0dh25a99nlv39kys0j2v7bl2rla603xxdlwcjdii3bk1hrp49.nar.zst error="server returned 404: 404 page not found\n"17092026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17102026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17112026/10/01 09:39:52 WARN Failed to register uploaded object key=6pyqznw4b1hy6n7wlycz3lkcvs1fqb6b.narinfo error="server returned 404: 404 page not found\n"17122026/10/01 09:39:52 INFO Signed narinfos id=1 count=317132026/10/01 09:39:52 INFO Uploading 3 narinfos17142026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/1/complete17152026/10/01 09:39:52 WARN Failed to register uploaded object key=k5fi3mgnw9zxg3644sim8c54yngc76zs.narinfo error="server returned 404: 404 page not found\n"1716--- PASS: TestSkippedUploadsHandler (0.00s)1717=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit17182026/10/01 09:39:52 WARN Failed to register uploaded object key=mamx4fr50p2bwg6z9c94k3gjpvl2g1pf.narinfo error="server returned 404: 404 page not found\n"17192026/10/01 09:39:52 WARN Failed to register uploaded object key=pqb71790jgd9ln99c2lfgyj4f5y3mws2.narinfo error="server returned 404: 404 page not found\n"17202026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/1/complete17212026/10/01 09:39:52 WARN Failed to register uploaded object key=3iwz6q9rx448ph47j4ag6b8x9pbpy222.narinfo error="server returned 404: 404 page not found\n"17222026-10-01 09:39:52.311 UTC [1093] ERROR: relation "goose_db_version" does not exist at character 3617232026-10-01 09:39:52.311 UTC [1093] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17242026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.63ms)1725--- PASS: TestService_ReadAuthMiddleware (0.36s)1726=== CONT TestPush_CompleteCommitsEveryRoot17272026/10/01 09:39:52 INFO Upload complete. (65ms)1728--- PASS: TestPushWaitsForSweepHoldingRow (1.02s)1729=== CONT TestServerTLSConfig1730=== RUN TestServerTLSConfig/no_client_CA1731=== PAUSE TestServerTLSConfig/no_client_CA17322026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)1733=== RUN TestServerTLSConfig/missing_CA_file1734=== PAUSE TestServerTLSConfig/missing_CA_file1735=== RUN TestServerTLSConfig/not_a_PEM_file1736=== PAUSE TestServerTLSConfig/not_a_PEM_file1737=== CONT TestReadProxyConditionalGet1738=== NAME TestClientSharedPathCommittedMidPush1739 client_integration_test.go:680: Retrieved narinfo from S3:1740 StorePath: /build/TestClientSharedPathCommittedMidPush4096536983/001/store/6pyqznw4b1hy6n7wlycz3lkcvs1fqb6b-shared-dep1741 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1742 Compression: zstd1743 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821744 NarSize: 1361745 References: 1746 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n17472026/10/01 09:39:52 INFO Upload complete. (58ms)1748=== NAME TestClientPushesUseOnePush1749 client_pushes_test.go:97: Retrieved narinfo from S3:1750 StorePath: /build/TestClientPushesUseOnePush3632051650/001/store/pqb71790jgd9ln99c2lfgyj4f5y3mws2-shared-dep1751 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1752 Compression: zstd1753 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821754 NarSize: 1361755 References: 1756 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1757=== NAME TestClientSharedPathCommittedMidPush1758 client_integration_test.go:680: Retrieved narinfo from S3:1759 StorePath: /build/TestClientSharedPathCommittedMidPush4096536983/001/store/k5fi3mgnw9zxg3644sim8c54yngc76zs-top1760 URL: nar/1jvzvps5dl517hfd8n9yj65j7s3kcrwfkihac0m56blahfnk87vj.nar.zst1761 Compression: zstd1762 NarHash: sha256:1jvzvps5dl517hfd8n9yj65j7s3kcrwfkihac0m56blahfnk87vj1763 NarSize: 2241764 References: /build/TestClientSharedPathCommittedMidPush4096536983/001/store/6pyqznw4b1hy6n7wlycz3lkcvs1fqb6b-shared-dep1765 CA: text:sha256:1vivg9fzd1fddm9ml16l8fr32algkqhlbybfy8ncsclppm58lf8b17662026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.89ms)1767=== NAME TestClientPushesUseOnePush1768 client_pushes_test.go:97: Retrieved narinfo from S3:1769 StorePath: /build/TestClientPushesUseOnePush3632051650/001/store/3iwz6q9rx448ph47j4ag6b8x9pbpy222-a1770 URL: nar/0vi0dh25a99nlv39kys0j2v7bl2rla603xxdlwcjdii3bk1hrp49.nar.zst1771 Compression: zstd1772 NarHash: sha256:0vi0dh25a99nlv39kys0j2v7bl2rla603xxdlwcjdii3bk1hrp491773 NarSize: 2161774 References: /build/TestClientPushesUseOnePush3632051650/001/store/pqb71790jgd9ln99c2lfgyj4f5y3mws2-shared-dep1775 CA: text:sha256:1c6m5cldwcc2zazdm92yfslcv7xvqvb0ivi893bccb377dngd3bc1776--- PASS: TestClientSharedPathCommittedMidPush (0.63s)1777=== CONT TestReadProxyHead1778=== NAME TestClientPushesUseOnePush1779 client_pushes_test.go:97: Retrieved narinfo from S3:1780 StorePath: /build/TestClientPushesUseOnePush3632051650/001/store/mamx4fr50p2bwg6z9c94k3gjpvl2g1pf-b1781 URL: nar/0vi0dh25a99nlv39kys0j2v7bl2rla603xxdlwcjdii3bk1hrp49.nar.zst1782 Compression: zstd1783 NarHash: sha256:0vi0dh25a99nlv39kys0j2v7bl2rla603xxdlwcjdii3bk1hrp491784 NarSize: 2161785 References: /build/TestClientPushesUseOnePush3632051650/001/store/pqb71790jgd9ln99c2lfgyj4f5y3mws2-shared-dep1786 CA: text:sha256:1c6m5cldwcc2zazdm92yfslcv7xvqvb0ivi893bccb377dngd3bc1787--- PASS: TestClientPushesUseOnePush (0.66s)1788=== CONT TestParseSingleRange1789=== RUN TestParseSingleRange/none1790=== PAUSE TestParseSingleRange/none1791=== RUN TestParseSingleRange/unknown_unit1792=== PAUSE TestParseSingleRange/unknown_unit1793=== RUN TestParseSingleRange/multi-range_ignored1794=== PAUSE TestParseSingleRange/multi-range_ignored1795=== RUN TestParseSingleRange/malformed_no_dash1796=== PAUSE TestParseSingleRange/malformed_no_dash1797=== RUN TestParseSingleRange/malformed_both_empty1798=== PAUSE TestParseSingleRange/malformed_both_empty1799=== RUN TestParseSingleRange/malformed_end_before_start1800=== PAUSE TestParseSingleRange/malformed_end_before_start1801=== RUN TestParseSingleRange/closed1802=== PAUSE TestParseSingleRange/closed1803=== RUN TestParseSingleRange/open-ended1804=== PAUSE TestParseSingleRange/open-ended1805=== RUN TestParseSingleRange/end_clamped_to_size1806=== PAUSE TestParseSingleRange/end_clamped_to_size1807=== RUN TestParseSingleRange/suffix1808=== PAUSE TestParseSingleRange/suffix1809=== RUN TestParseSingleRange/suffix_exceeds_size1810=== PAUSE TestParseSingleRange/suffix_exceeds_size1811=== RUN TestParseSingleRange/single_byte1812=== PAUSE TestParseSingleRange/single_byte1813=== RUN TestParseSingleRange/start_past_EOF1814=== PAUSE TestParseSingleRange/start_past_EOF1815=== RUN TestParseSingleRange/start_far_past_EOF1816=== PAUSE TestParseSingleRange/start_far_past_EOF1817=== CONT TestCacheConfigHandlerMaxNarSize1818--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1819=== CONT TestReadProxyInvalidPath18202026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (10.74ms)18212026/10/01 09:39:52 OK 20241026095416_initial_model.sql (15.33ms)18222026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes18232026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.66ms)18242026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes18252026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.63ms)18262026/10/01 09:39:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18272026/10/01 09:39:52 INFO Uploading n4x5v1js8l6d751byssxh3hr6yknyffr-test-file.txt (152B)18282026/10/01 09:39:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18292026/10/01 09:39:52 INFO Uploading c5ffaxi486jz139253n3p5x364s73cqz-unpinned-file.txt (128B)18302026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.41ms)18312026/10/01 09:39:52 OK 20251218171726_add_pins.sql (5.16ms)18322026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.81ms)18332026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000018342026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18352026/10/01 09:39:52 WARN Failed to register uploaded object key=n4x5v1js8l6d751byssxh3hr6yknyffr.ls error="server returned 404: 404 page not found\n"18362026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18372026/10/01 09:39:52 INFO Signed narinfos id=1 count=118382026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18392026/10/01 09:39:52 WARN Failed to register uploaded object key=c5ffaxi486jz139253n3p5x364s73cqz.ls error="server returned 404: 404 page not found\n"18402026/10/01 09:39:52 INFO Uploading 1 narinfos18412026/10/01 09:39:52 INFO Signed narinfos id=2 count=118422026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18432026/10/01 09:39:52 INFO Uploading 1 narinfos18442026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.61ms)18452026-10-01 09:39:52.345 UTC [1176] ERROR: relation "goose_db_version" does not exist at character 3618462026-10-01 09:39:52.345 UTC [1176] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18472026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (5.04ms)1848=== NAME TestClientCADerivations1849 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3917059492/001/store/wdzjvxm8sm5bpfirg8zf3xsyp06fm6k9-ca-test18502026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.69ms)18512026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/1/complete18522026/10/01 09:39:52 WARN Failed to register uploaded object key=n4x5v1js8l6d751byssxh3hr6yknyffr.narinfo error="server returned 404: 404 page not found\n"18532026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/2/complete18542026/10/01 09:39:52 WARN Failed to register uploaded object key=c5ffaxi486jz139253n3p5x364s73cqz.narinfo error="server returned 404: 404 page not found\n"18552026/10/01 09:39:52 OK 3_commit_push.sql (1.48ms)18562026/10/01 09:39:52 goose: up to current file version: 318572026/10/01 09:39:52 INFO Upload complete. (51ms)18582026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.33ms)18592026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes18602026/10/01 09:39:52 INFO Upload complete. (66ms)18612026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.63ms)1862=== RUN TestService_RequireScope_OIDC/builder_may_write1863=== PAUSE TestService_RequireScope_OIDC/builder_may_write1864=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1865=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1866=== RUN TestService_RequireScope_OIDC/ops_may_admin1867=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1868=== RUN TestService_RequireScope_OIDC/ops_may_not_write1869=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1870=== RUN TestService_RequireScope_OIDC/reader_may_not_write1871=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1872=== RUN TestService_RequireScope_OIDC/static_token_may_admin1873=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1874=== RUN TestService_RequireScope_OIDC/static_token_may_write1875=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1876=== RUN TestService_RequireScope_OIDC/reader_may_read1877=== PAUSE TestService_RequireScope_OIDC/reader_may_read1878=== RUN TestService_RequireScope_OIDC/writer_implies_read1879=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1880=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1881=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1882=== CONT TestPush_OverlappingRootsStoreOneRowPerKey18832026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (3.73ms)18842026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000018852026/10/01 09:39:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18862026/10/01 09:39:52 INFO Uploading nc1nvnbbzd1k3n6w1kk41c4w897i02an-test-script (136B)18872026/10/01 09:39:52 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"18882026/10/01 09:39:52 WARN mTLS auth: bound subjects configured but subject DN unavailable18892026/10/01 09:39:52 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1890--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.33s)1891=== CONT TestReadProxy40418922026-10-01 09:39:52.358 UTC [1198] ERROR: relation "goose_db_version" does not exist at character 3618932026-10-01 09:39:52.358 UTC [1198] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18942026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.92ms)18952026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18962026/10/01 09:39:52 WARN Failed to register uploaded object key=log/yjqdhap98mlx5fgbki85kif0zp6iaj42-test-script.drv error="server returned 404: 404 page not found\n"18972026/10/01 09:39:52 WARN Failed to register uploaded object key=nc1nvnbbzd1k3n6w1kk41c4w897i02an.ls error="server returned 404: 404 page not found\n"18982026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18992026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.92ms)19002026/10/01 09:39:52 INFO Signed narinfos id=1 count=119012026/10/01 09:39:52 INFO Uploading 1 narinfos19022026/10/01 09:39:52 OK 3_commit_push.sql (1.83ms)19032026/10/01 09:39:52 goose: up to current file version: 319042026/10/01 09:39:52 OK 20241026095416_initial_model.sql (13.63ms)19052026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/1/complete19062026/10/01 09:39:52 WARN Failed to register uploaded object key=nc1nvnbbzd1k3n6w1kk41c4w897i02an.narinfo error="server returned 404: 404 page not found\n"19072026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)19082026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes19092026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures19102026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures19112026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures19122026/10/01 09:39:52 OK 20251218171726_add_pins.sql (11.67ms)19132026/10/01 09:39:52 OK 20241026095416_initial_model.sql (18.29ms)19142026/10/01 09:39:52 INFO Upload complete. (73ms)1915=== NAME TestClientCADerivations1916 client_ca_test.go:139: Found 1 dependencies (including self)19172026/10/01 09:39:52 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19182026/10/01 09:39:52 INFO Uploading 043fah7avbi9nh5kbv375z9al6l6vzc2-test-file-2.txt (160B)19192026/10/01 09:39:52 INFO Uploading rp5gdc0nrspy771v6jmj9cc8b9qvn9gc-test-file-1.txt (160B)19202026/10/01 09:39:52 INFO Uploading gxsln3lkfclz4j2pvq99fnqvpj6y86zh-test-file-0.txt (160B)19212026/10/01 09:39:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures19222026/10/01 09:39:52 INFO Garbage collection started19232026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.96ms)1924=== NAME TestClientWithDependencies1925 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies35895431/001/store) requires matching store prefix19262026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (9.02ms)1927--- PASS: TestClientWithDependencies (0.66s)19282026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"1929=== CONT TestReadRedirectUsesPublicS3URL19302026/10/01 09:39:52 WARN Failed to register uploaded object key=gxsln3lkfclz4j2pvq99fnqvpj6y86zh.ls error="server returned 404: 404 page not found\n"19312026/10/01 09:39:52 WARN Failed to register uploaded object key=043fah7avbi9nh5kbv375z9al6l6vzc2.ls error="server returned 404: 404 page not found\n"19322026/10/01 09:39:52 WARN Failed to register uploaded object key=rp5gdc0nrspy771v6jmj9cc8b9qvn9gc.ls error="server returned 404: 404 page not found\n"19332026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19342026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19352026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19362026/10/01 09:39:52 INFO Signed narinfos id=1 count=319372026/10/01 09:39:52 INFO Uploading 3 narinfos19382026/10/01 09:39:52 INFO All 1 paths already cached19392026-10-01 09:39:52.394 UTC [1275] ERROR: relation "goose_db_version" does not exist at character 3619402026-10-01 09:39:52.394 UTC [1275] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1941=== NAME TestClientIntegration1942 client_integration_test.go:312: Retrieved narinfo from S3:1943 StorePath: /build/TestClientIntegration362278698/002/store/n4x5v1js8l6d751byssxh3hr6yknyffr-test-file.txt1944 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1945 Compression: zstd1946 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11947 NarSize: 1521948 References: 1949 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk119502026/10/01 09:39:52 WARN Failed to register uploaded object key=rp5gdc0nrspy771v6jmj9cc8b9qvn9gc.narinfo error="server returned 404: 404 page not found\n"19512026/10/01 09:39:52 WARN Failed to register uploaded object key=gxsln3lkfclz4j2pvq99fnqvpj6y86zh.narinfo error="server returned 404: 404 page not found\n"19522026/10/01 09:39:52 OK 20251218171726_add_pins.sql (10ms)19532026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/1/complete19542026/10/01 09:39:52 OK 20260905000000_add_claims.sql (6.26ms)19552026/10/01 09:39:52 WARN Failed to register uploaded object key=043fah7avbi9nh5kbv375z9al6l6vzc2.narinfo error="server returned 404: 404 page not found\n"1956 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1957 client_integration_test.go:313: Decompressed .ls content (64 bytes):1958 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1959 client_integration_test.go:316: Testing garbage collection...19602026/10/01 09:39:52 INFO Aborted multipart uploads count=0 kept=019612026-10-01 09:39:52.404 UTC [1279] ERROR: relation "goose_db_version" does not exist at character 3619622026-10-01 09:39:52.404 UTC [1279] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19632026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (8.35ms)19642026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (11.64ms)19652026/10/01 09:39:52 INFO Upload complete. (71ms)1966=== NAME TestClientMultipleUploads1967 client_integration_test.go:369: Uploaded 3 paths in 110.01139ms19682026/10/01 09:39:52 WARN Force mode enabled - objects will be deleted immediately without grace period19692026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (6.41ms)19702026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000019712026/10/01 09:39:52 OK 1_commit_pending_closure.sql (5.85ms)19722026/10/01 09:39:52 OK 20260905000000_add_claims.sql (9.31ms)1973--- PASS: TestClientMultipleUploads (0.65s)1974=== CONT TestService_NativeMTLS19752026/10/01 09:39:52 OK 2_object_stats_trigger.sql (9.14ms)19762026/10/01 09:39:52 OK 20241026095416_initial_model.sql (17.84ms)19772026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (10.06ms)19782026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.43ms)19792026/10/01 09:39:52 OK 3_commit_push.sql (1.87ms)19802026/10/01 09:39:52 goose: up to current file version: 319812026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)19822026-10-01 09:39:52.430 UTC [1300] ERROR: relation "goose_db_version" does not exist at character 3619832026-10-01 09:39:52.430 UTC [1300] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19842026-10-01 09:39:52.430 UTC [1281] ERROR: relation "goose_db_version" does not exist at character 3619852026-10-01 09:39:52.430 UTC [1281] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19862026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.8ms)19872026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (3.91ms)19882026/10/01 09:39:52 goose: successfully migrated database to version: 202609231200001989--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.38s)1990=== CONT TestReadProxyNarStreaming19912026/10/01 09:39:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures19922026/10/01 09:39:52 INFO Garbage collection started19932026-10-01 09:39:52.436 UTC [1303] ERROR: relation "goose_db_version" does not exist at character 3619942026-10-01 09:39:52.436 UTC [1303] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19952026/10/01 09:39:52 OK 20251218171726_add_pins.sql (10.63ms)19962026/10/01 09:39:52 OK 1_commit_pending_closure.sql (9.96ms)19972026/10/01 09:39:52 OK 20251218171726_add_pins.sql (11.31ms)19982026/10/01 09:39:52 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=019992026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.85ms)20002026/10/01 09:39:52 INFO Aborted multipart uploads count=0 kept=020012026/10/01 09:39:52 OK 3_commit_push.sql (1.55ms)20022026/10/01 09:39:52 goose: up to current file version: 320032026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.99ms)20042026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (5.2ms)20052026/10/01 09:39:52 INFO Vacuumed table table=pending_closures20062026/10/01 09:39:52 WARN Force mode enabled - objects will be deleted immediately without grace period20072026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.62ms)20082026/10/01 09:39:52 INFO Vacuumed table table=pending_objects20092026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.49ms)20102026/10/01 09:39:52 INFO Vacuumed table table=multipart_uploads20112026-10-01 09:39:52.452 UTC [1325] ERROR: relation "goose_db_version" does not exist at character 3620122026-10-01 09:39:52.452 UTC [1325] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20132026-10-01 09:39:52.452 UTC [1324] ERROR: relation "goose_db_version" does not exist at character 3620142026-10-01 09:39:52.452 UTC [1324] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20152026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.36ms)20162026/10/01 09:39:52 OK 20241026095416_initial_model.sql (10.73ms)20172026/10/01 09:39:52 INFO Vacuumed table table=closures20182026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.95ms)20192026/10/01 09:39:52 OK 20241026095416_initial_model.sql (13.02ms)20202026/10/01 09:39:52 OK 20241026095416_initial_model.sql (13.58ms)20212026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.61ms)20222026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (3.42ms)20232026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000020242026/10/01 09:39:52 INFO Vacuumed table table=objects20252026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)20262026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.71ms)20272026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000020282026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)20292026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.29ms)20302026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.49ms)20312026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.7ms)20322026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.64ms)20332026/10/01 09:39:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20342026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.96ms)20352026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.1ms)20362026/10/01 09:39:52 OK 2_object_stats_trigger.sql (2.19ms)20372026/10/01 09:39:52 OK 3_commit_push.sql (2.28ms)20382026/10/01 09:39:52 goose: up to current file version: 320392026/10/01 09:39:52 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst2040--- PASS: TestCompleteMultipartUnregistered (0.40s)2041=== CONT TestReadProxyRangeRequest20422026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.19ms)20432026/10/01 09:39:52 OK 3_commit_push.sql (2.01ms)20442026/10/01 09:39:52 goose: up to current file version: 320452026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.25ms)20462026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.1ms)20472026/10/01 09:39:52 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=020482026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.64ms)20492026/10/01 09:39:52 OK 20241026095416_initial_model.sql (10.13ms)20502026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.83ms)20512026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.78ms)20522026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.84ms)20532026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3ms)20542026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.51ms)20552026/10/01 09:39:52 INFO Vacuumed table table=pending_closures20562026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.86ms)20572026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.91ms)20582026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.36ms)20592026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000020602026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.55ms)20612026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.57ms)20622026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.35ms)20632026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000020642026/10/01 09:39:52 INFO Vacuumed table table=pending_objects20652026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.12ms)20662026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.35ms)20672026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000020682026/10/01 09:39:52 INFO Vacuumed table table=multipart_uploads20692026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.67ms)20702026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.87ms)20712026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.73ms)20722026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.24ms)20732026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.22ms)20742026/10/01 09:39:52 OK 3_commit_push.sql (1.22ms)20752026/10/01 09:39:52 goose: up to current file version: 320762026/10/01 09:39:52 INFO Vacuumed table table=closures20772026/10/01 09:39:52 OK 2_object_stats_trigger.sql (2.05ms)20782026/10/01 09:39:52 OK 2_object_stats_trigger.sql (2.1ms)20792026/10/01 09:39:52 OK 3_commit_push.sql (1.26ms)20802026/10/01 09:39:52 goose: up to current file version: 320812026/10/01 09:39:52 OK 3_commit_push.sql (1.92ms)20822026/10/01 09:39:52 goose: up to current file version: 320832026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.12ms)20842026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.17ms)20852026/10/01 09:39:52 INFO Vacuumed table table=objects20862026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.17ms)20872026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.48ms)20882026/10/01 09:39:52 INFO Received cleanup request method=DELETE path=/api/pending_closures20892026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.71ms)20902026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000020912026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.54ms)20922026/10/01 09:39:52 INFO Aborted multipart uploads count=0 kept=020932026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.22ms)20942026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.87ms)20952026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000020962026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.46ms)20972026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures20982026/10/01 09:39:52 OK 3_commit_push.sql (1.24ms)20992026/10/01 09:39:52 goose: up to current file version: 321002026-10-01 09:39:52.493 UTC [1346] ERROR: relation "goose_db_version" does not exist at character 3621012026-10-01 09:39:52.493 UTC [1346] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21022026-10-01 09:39:52.494 UTC [1347] ERROR: relation "goose_db_version" does not exist at character 3621032026-10-01 09:39:52.494 UTC [1347] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21042026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.67ms)21052026/10/01 09:39:52 OK 2_object_stats_trigger.sql (2.04ms)21062026/10/01 09:39:52 OK 3_commit_push.sql (1.34ms)21072026/10/01 09:39:52 goose: up to current file version: 321082026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes21092026/10/01 09:39:52 INFO Received cleanup request method=DELETE path=/api/pending_closures21102026/10/01 09:39:52 INFO Aborted multipart uploads count=1 kept=021112026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures21122026-10-01 09:39:52.510 UTC [1365] ERROR: relation "goose_db_version" does not exist at character 3621132026-10-01 09:39:52.510 UTC [1365] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21142026/10/01 09:39:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21152026/10/01 09:39:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21162026/10/01 09:39:52 INFO Uploading wdzjvxm8sm5bpfirg8zf3xsyp06fm6k9-ca-test (144B)21172026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.14ms)21182026/10/01 09:39:52 OK 20241026095416_initial_model.sql (11.68ms)21192026-10-01 09:39:52.512 UTC [673] ERROR: Closure does not exist: id=121202026-10-01 09:39:52.512 UTC [673] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE21212026-10-01 09:39:52.512 UTC [673] STATEMENT: -- name: CommitPendingClosure :exec2122 SELECT commit_pending_closure($1::bigint)2123 2124--- PASS: TestService_cleanupPendingClosuresHandler (0.44s)2125=== CONT TestMetricsInventory21262026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.18ms)21272026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.73ms)21282026/10/01 09:39:52 WARN Failed to register uploaded object key=wdzjvxm8sm5bpfirg8zf3xsyp06fm6k9.ls error="server returned 404: 404 page not found\n"21292026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21302026/10/01 09:39:52 WARN Failed to register uploaded object key=log/6iq56iw58lxx93xzx3saxp60hh5i1js4-ca-test.drv error="server returned 404: 404 page not found\n"21312026/10/01 09:39:52 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"21322026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.5ms)21332026/10/01 09:39:52 INFO Signed narinfos id=1 count=121342026/10/01 09:39:52 INFO Uploading 1 narinfos21352026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.57ms)21362026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.89ms)21372026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/1/complete21382026/10/01 09:39:52 WARN Failed to register uploaded object key=wdzjvxm8sm5bpfirg8zf3xsyp06fm6k9.narinfo error="server returned 404: 404 page not found\n"21392026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.96ms)21402026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.32ms)21412026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.62ms)21422026/10/01 09:39:52 OK 20241026095416_initial_model.sql (9.75ms)21432026/10/01 09:39:52 INFO Upload complete. (98ms)21442026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.54ms)21452026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.13ms)21462026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.83ms)21472026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.26ms)21482026/10/01 09:39:52 goose: successfully migrated database to version: 202609231200002149=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2150=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2151=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2152=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2153=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2154=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2155=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2156=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2157=== CONT TestReadRedirectKeepsNarinfoProxied21582026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.57ms)21592026/10/01 09:39:52 goose: successfully migrated database to version: 202609231200002160=== NAME TestClientCADerivations2161 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3917059492/001/store/wdzjvxm8sm5bpfirg8zf3xsyp06fm6k9-ca-test2162 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2163 Compression: zstd2164 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2165 NarSize: 1442166 References: 2167 Deriver: /build/TestClientCADerivations3917059492/001/store/6iq56iw58lxx93xzx3saxp60hh5i1js4-ca-test.drv2168 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2169 client_ca_test.go:185: Checking for realisation files in S3...21702026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.25ms)21712026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.36ms)21722026/10/01 09:39:52 OK 1_commit_pending_closure.sql (1.76ms)2173 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2174 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache21752026/10/01 09:39:52 OK 2_object_stats_trigger.sql (733.49µs)21762026/10/01 09:39:52 OK 2_object_stats_trigger.sql (813.55µs)21772026/10/01 09:39:52 OK 3_commit_push.sql (664.53µs)21782026/10/01 09:39:52 goose: up to current file version: 321792026/10/01 09:39:52 OK 3_commit_push.sql (1.6ms)21802026/10/01 09:39:52 goose: up to current file version: 321812026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.33ms)21822026/10/01 09:39:52 OK 20260905000000_add_claims.sql (2.88ms)21832026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.03ms)21842026-10-01 09:39:52.541 UTC [1371] ERROR: relation "goose_db_version" does not exist at character 3621852026-10-01 09:39:52.541 UTC [1371] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21862026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.32ms)21872026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000021882026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.06ms)21892026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.38ms)21902026/10/01 09:39:52 OK 3_commit_push.sql (1.62ms)21912026/10/01 09:39:52 goose: up to current file version: 321922026/10/01 09:39:52 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket845178090/001/proxy.sock21932026/10/01 09:39:52 INFO Starting HTTP server address=127.0.0.1:4379321942026/10/01 09:39:52 WARN mTLS auth: subject not in bound subjects subject="CN=someone"21952026/10/01 09:39:52 INFO Shutdown signal received, draining in-flight requests timeout=10s2196--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.37s)2197=== CONT TestNARDeduplicationMetadataUploadBug21982026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.53ms)21992026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.2ms)22002026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.75ms)22012026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures22022026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)22032026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.6ms)22042026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.35ms)22052026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.25ms)22062026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000022072026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.45ms)22082026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.41ms)22092026/10/01 09:39:52 OK 3_commit_push.sql (1.44ms)22102026/10/01 09:39:52 goose: up to current file version: 322112026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures22122026-10-01 09:39:52.592 UTC [1392] ERROR: relation "goose_db_version" does not exist at character 3622132026-10-01 09:39:52.592 UTC [1392] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22142026-10-01 09:39:52.607 UTC [1393] ERROR: relation "goose_db_version" does not exist at character 3622152026-10-01 09:39:52.607 UTC [1393] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22162026/10/01 09:39:52 OK 20241026095416_initial_model.sql (10.62ms)22172026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures22182026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.19ms)22192026/10/01 09:39:52 OK 20251218171726_add_pins.sql (7.67ms)22202026/10/01 09:39:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2221=== NAME TestClientCADerivations2222 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2223 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2224 error: binary cache 's3://bucket34?endpoint=http://localhost:37645®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3917059492/001/store'2225 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 122262026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.9ms)2227--- PASS: TestClientCADerivations (0.69s)2228=== CONT TestReadRedirectNar22292026/10/01 09:39:52 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTJhOTlkODMtOWZjMS00MWNkLTg5ZGMtYjZiZTgyZjY5M2YyLjZmNmNmY2QwLTE3MGMtNDEwMi1hMTM5LTJjZTQwYTQwMTZhM3gxNzkwODQ3NTkyNTk3OTE3MTcx22302026/10/01 09:39:52 OK 20260905000000_add_claims.sql (2.79ms)22312026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures22322026/10/01 09:39:52 OK 20241026095416_initial_model.sql (8.41ms)22332026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.44ms)22342026/10/01 09:39:52 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZTJhOTlkODMtOWZjMS00MWNkLTg5ZGMtYjZiZTgyZjY5M2YyLjZmNmNmY2QwLTE3MGMtNDEwMi1hMTM5LTJjZTQwYTQwMTZhM3gxNzkwODQ3NTkyNTk3OTE3MTcx parts=122352026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.32ms)22362026-10-01 09:39:52.629 UTC [1491] ERROR: relation "goose_db_version" does not exist at character 3622372026-10-01 09:39:52.629 UTC [1491] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22382026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (1.5ms)22392026/10/01 09:39:52 goose: successfully migrated database to version: 202609231200002240--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.42s)2241=== CONT TestReadProxyNarinfoAlreadyDecompressed22422026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes22432026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.37ms)22442026/10/01 09:39:52 OK 20251218171726_add_pins.sql (2.99ms)22452026/10/01 09:39:52 OK 2_object_stats_trigger.sql (853.69µs)22462026/10/01 09:39:52 OK 3_commit_push.sql (1.07ms)22472026/10/01 09:39:52 goose: up to current file version: 322482026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.81ms)22492026/10/01 09:39:52 OK 20260905000000_add_claims.sql (2.96ms)22502026/10/01 09:39:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22512026/10/01 09:39:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22522026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.97ms)22532026/10/01 09:39:52 OK 20241026095416_initial_model.sql (10.4ms)22542026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.69ms)22552026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000022562026/10/01 09:39:52 INFO Signed narinfos id=1 count=12257--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.40s)2258=== CONT TestCreatePendingClosureRejectsOversizedNAR22592026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures2260--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2261=== CONT TestReadProxyDisabled22622026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.16ms)22632026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.57ms)22642026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.91ms)22652026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.9ms)2266=== RUN TestPush_RejectsBadRequests/no_roots2267=== PAUSE TestPush_RejectsBadRequests/no_roots2268=== RUN TestPush_RejectsBadRequests/no_objects2269=== PAUSE TestPush_RejectsBadRequests/no_objects2270=== RUN TestPush_RejectsBadRequests/bad_root2271=== PAUSE TestPush_RejectsBadRequests/bad_root2272=== RUN TestPush_RejectsBadRequests/root_not_in_objects2273=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects2274=== CONT TestReadProxyNarinfo22752026/10/01 09:39:52 OK 3_commit_push.sql (2ms)22762026/10/01 09:39:52 goose: up to current file version: 322772026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.3ms)22782026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.15ms)22792026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.35ms)22802026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (1.91ms)22812026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000022822026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.53ms)22832026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.43ms)22842026/10/01 09:39:52 OK 3_commit_push.sql (1.2ms)22852026/10/01 09:39:52 goose: up to current file version: 322862026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes22872026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/1/complete22882026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes22892026/10/01 09:39:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22902026-10-01 09:39:52.697 UTC [1501] ERROR: relation "goose_db_version" does not exist at character 3622912026-10-01 09:39:52.697 UTC [1501] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22922026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes22932026-10-01 09:39:52.708 UTC [1502] ERROR: relation "goose_db_version" does not exist at character 3622942026-10-01 09:39:52.708 UTC [1502] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2295--- PASS: TestReadProxyInvalidPath (0.38s)2296=== CONT TestReadProxyRootRedirectsToIndexHTML22972026-10-01 09:39:52.721 UTC [1504] ERROR: relation "goose_db_version" does not exist at character 3622982026-10-01 09:39:52.721 UTC [1504] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22992026/10/01 09:39:52 OK 20241026095416_initial_model.sql (10.96ms)23002026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.32ms)23012026/10/01 09:39:52 OK 20241026095416_initial_model.sql (10.53ms)23022026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.43ms)23032026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.13ms)23042026-10-01 09:39:52.727 UTC [1506] ERROR: relation "goose_db_version" does not exist at character 3623052026-10-01 09:39:52.727 UTC [1506] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23062026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.82ms)23072026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.36ms)23082026/10/01 09:39:52 OK 20260905000000_add_claims.sql (2.72ms)23092026/10/01 09:39:52 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZTJhOTlkODMtOWZjMS00MWNkLTg5ZGMtYjZiZTgyZjY5M2YyLjUwZmJhNzcwLTU4NDgtNDdhNi1hNDM2LTBmYmI0ZmYwYTI4Y3gxNzkwODQ3NTkyMzkwNzYxMTQ4 parts=1023102026/10/01 09:39:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete23112026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/1/complete23122026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.6ms)23132026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.81ms)23142026/10/01 09:39:52 INFO Completed upload id=123152026/10/01 09:39:52 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000023162026/10/01 09:39:52 OK 20241026095416_initial_model.sql (11.29ms)23172026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures23182026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (3.16ms)23192026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000023202026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.09ms)23212026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.32ms)23222026/10/01 09:39:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures23232026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.95ms)23242026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.86ms)23252026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.22ms)23262026/10/01 09:39:52 OK 20241026095416_initial_model.sql (11.18ms)23272026/10/01 09:39:52 OK 2_object_stats_trigger.sql (2ms)23282026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (1.78ms)23292026/10/01 09:39:52 goose: successfully migrated database to version: 202609231200002330--- PASS: TestPush_CompleteCommitsEveryRoot (0.43s)2331=== CONT TestGracefulShutdownDrainsInflight23322026/10/01 09:39:52 INFO Starting HTTP server address=127.0.0.1:4072323332026/10/01 09:39:52 INFO Shutdown signal received, draining in-flight requests timeout=10s23342026/10/01 09:39:52 OK 3_commit_push.sql (1.34ms)23352026/10/01 09:39:52 goose: up to current file version: 32336--- PASS: TestReadProxyConditionalGet (0.43s)2337=== CONT TestIsValidCachePath2338=== RUN TestIsValidCachePath/narinfo2339=== PAUSE TestIsValidCachePath/narinfo2340=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars2341=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars2342=== RUN TestIsValidCachePath/nar_zst2343=== PAUSE TestIsValidCachePath/nar_zst2344=== RUN TestIsValidCachePath/nar_xz2345=== PAUSE TestIsValidCachePath/nar_xz2346=== RUN TestIsValidCachePath/nar_bz22347=== PAUSE TestIsValidCachePath/nar_bz22348=== RUN TestIsValidCachePath/nar_uncompressed2349=== PAUSE TestIsValidCachePath/nar_uncompressed2350=== RUN TestIsValidCachePath/ls2351=== PAUSE TestIsValidCachePath/ls2352=== RUN TestIsValidCachePath/log2353=== PAUSE TestIsValidCachePath/log2354=== RUN TestIsValidCachePath/realisation2355=== PAUSE TestIsValidCachePath/realisation2356=== RUN TestIsValidCachePath/nix-cache-info2357=== PAUSE TestIsValidCachePath/nix-cache-info2358=== RUN TestIsValidCachePath/index.html2359=== PAUSE TestIsValidCachePath/index.html2360=== RUN TestIsValidCachePath/traversal_parent2361=== PAUSE TestIsValidCachePath/traversal_parent2362=== RUN TestIsValidCachePath/traversal_in_middle2363=== PAUSE TestIsValidCachePath/traversal_in_middle2364=== RUN TestIsValidCachePath/invalid_char_e2365=== PAUSE TestIsValidCachePath/invalid_char_e2366=== RUN TestIsValidCachePath/invalid_char_u2367=== PAUSE TestIsValidCachePath/invalid_char_u2368=== RUN TestIsValidCachePath/random_path2369=== PAUSE TestIsValidCachePath/random_path2370=== RUN TestIsValidCachePath/empty2371=== PAUSE TestIsValidCachePath/empty2372=== RUN TestIsValidCachePath/leading_slash2373=== PAUSE TestIsValidCachePath/leading_slash2374=== RUN TestIsValidCachePath/wrong_extension2375=== PAUSE TestIsValidCachePath/wrong_extension2376=== RUN TestIsValidCachePath/short_hash2377=== PAUSE TestIsValidCachePath/short_hash2378=== CONT TestGenerateLandingPage23792026/10/01 09:39:52 OK 1_commit_pending_closure.sql (1.93ms)23802026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.48ms)23812026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (2.88ms)23822026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.35ms)2383--- PASS: TestGenerateLandingPage (0.00s)2384=== CONT TestService_healthCheckHandler23852026/10/01 09:39:52 OK 3_commit_push.sql (1.37ms)23862026/10/01 09:39:52 goose: up to current file version: 323872026/10/01 09:39:52 INFO Aborted multipart uploads count=0 kept=023882026/10/01 09:39:52 OK 20251218171726_add_pins.sql (2.95ms)23892026/10/01 09:39:52 OK 20260905000000_add_claims.sql (2.75ms)23902026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.21ms)23912026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.43ms)23922026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (1.8ms)23932026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000023942026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.2ms)23952026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.69ms)23962026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.77ms)23972026/10/01 09:39:52 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=023982026/10/01 09:39:52 OK 3_commit_push.sql (1.14ms)23992026/10/01 09:39:52 goose: up to current file version: 324002026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.36ms)24012026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.6ms)2402--- PASS: TestReadProxyHead (0.44s)24032026/10/01 09:39:52 goose: successfully migrated database to version: 202609231200002404=== CONT TestPendingCleanupUsesOneCutoff24052026/10/01 09:39:52 INFO Vacuumed table table=pending_closures24062026/10/01 09:39:52 INFO Aborted multipart uploads count=0 kept=024072026/10/01 09:39:52 INFO Vacuumed table table=pending_objects24082026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.35ms)24092026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.6ms)24102026/10/01 09:39:52 WARN Force mode enabled - objects will be deleted immediately without grace period24112026/10/01 09:39:52 INFO Vacuumed table table=multipart_uploads24122026/10/01 09:39:52 OK 3_commit_push.sql (1.48ms)24132026/10/01 09:39:52 goose: up to current file version: 324142026/10/01 09:39:52 INFO Vacuumed table table=closures24152026/10/01 09:39:52 INFO Vacuumed table table=objects2416--- PASS: TestReadProxy404 (0.42s)2417=== CONT TestObjectStatsTrigger24182026/10/01 09:39:52 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=024192026/10/01 09:39:52 INFO Vacuumed table table=pending_closures24202026/10/01 09:39:52 INFO Vacuumed table table=pending_objects24212026/10/01 09:39:52 INFO Vacuumed table table=multipart_uploads24222026-10-01 09:39:52.786 UTC [1514] ERROR: relation "goose_db_version" does not exist at character 3624232026-10-01 09:39:52.786 UTC [1514] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24242026/10/01 09:39:52 INFO Vacuumed table table=closures24252026/10/01 09:39:52 INFO Vacuumed table table=objects24262026/10/01 09:39:52 INFO Received complete push request method=POST path=/api/pushes/2/complete24272026/10/01 09:39:52 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000002428--- PASS: TestService_createPendingClosureHandler (0.72s)2429=== CONT TestService_readinessHandler2430--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.49s)2431=== CONT TestCreatePin_ReservedPins24322026/10/01 09:39:52 INFO Received push request method=POST path=/api/pushes24332026/10/01 09:39:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete24342026/10/01 09:39:52 OK 20241026095416_initial_model.sql (11ms)24352026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)24362026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.93ms)2437--- PASS: TestGracefulShutdownDrainsInflight (0.07s)2438=== CONT TestPresentReportsOnlyClosureRoots24392026/10/01 09:39:52 WARN mTLS auth: subject not in bound subjects subject="CN=reader"24402026/10/01 09:39:52 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2441--- PASS: TestService_NativeMTLS (0.40s)2442=== CONT TestOrphanedObjectsGCStressTest24432026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (9.35ms)24442026/10/01 09:39:52 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZTJhOTlkODMtOWZjMS00MWNkLTg5ZGMtYjZiZTgyZjY5M2YyLjhmMjg0ZmJiLWRhYmMtNGNhOS05MmJlLTZhMDhkZWNmODE4NHgxNzkwODQ3NTkyNTE1NTM0Mjc0 parts=102445--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.47s)24462026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.32ms)2447=== CONT TestPresentNotReportedWhileGCDeletesClosure24482026/10/01 09:39:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete24492026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.45ms)24502026/10/01 09:39:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45209/oidc24512026/10/01 09:39:52 INFO Completed upload id=124522026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.29ms)24532026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000024542026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures24552026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.33ms)24562026-10-01 09:39:52.831 UTC [1525] ERROR: relation "goose_db_version" does not exist at character 3624572026-10-01 09:39:52.831 UTC [1525] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24582026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.81ms)24592026/10/01 09:39:52 INFO Received uploads request method=POST path=/api/pending_closures24602026/10/01 09:39:52 OK 3_commit_push.sql (1.64ms)24612026/10/01 09:39:52 goose: up to current file version: 324622026/10/01 09:39:52 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo24632026/10/01 09:39:52 WARN Found objects in DB but missing from S3, will re-upload count=12464--- PASS: TestService_verifyS3Integrity (0.71s)2465=== CONT TestGCTaskStore_Fail2466--- PASS: TestGCTaskStore_Fail (0.00s)2467=== CONT TestMultipartCleanup24682026-10-01 09:39:52.840 UTC [1529] ERROR: relation "goose_db_version" does not exist at character 3624692026-10-01 09:39:52.840 UTC [1529] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24702026/10/01 09:39:52 OK 20241026095416_initial_model.sql (11.93ms)24712026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)2472--- PASS: TestReadRedirectUsesPublicS3URL (0.47s)2473=== CONT TestOrphanedObjectsGC24742026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.58ms)24752026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.25ms)24762026-10-01 09:39:52.861 UTC [1532] ERROR: relation "goose_db_version" does not exist at character 3624772026-10-01 09:39:52.861 UTC [1532] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24782026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (10.3ms)2479--- PASS: TestReadProxyNarStreaming (0.44s)2480=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded24812026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (8.15ms)24822026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.78ms)24832026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.98ms)24842026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.86ms)24852026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.46ms)24862026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000024872026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.25ms)24882026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.75ms)24892026-10-01 09:39:52.880 UTC [1536] ERROR: relation "goose_db_version" does not exist at character 3624902026-10-01 09:39:52.880 UTC [1536] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24912026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.7ms)24922026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.42ms)24932026/10/01 09:39:52 OK 3_commit_push.sql (1.39ms)24942026/10/01 09:39:52 goose: up to current file version: 324952026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.37ms)24962026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2ms)24972026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.2ms)24982026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.95ms)24992026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.99ms)25002026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000025012026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.69ms)25022026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.42ms)25032026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.84ms)2504--- PASS: TestReadProxyRangeRequest (0.43s)2505=== CONT TestResolveDBConnectionString/flag_wins2506=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2507=== CONT TestResolveDBConnectionString/nothing_configured2508=== CONT TestResolveDBConnectionString/file_when_flag_empty2509=== CONT TestResolveDBConnectionString/missing_file_is_an_error2510=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2511--- PASS: TestResolveDBConnectionString (0.00s)2512 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2513 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2514 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2515 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2516 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)25172026-10-01 09:39:52.895 UTC [1538] ERROR: relation "goose_db_version" does not exist at character 3625182026-10-01 09:39:52.895 UTC [1538] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25192026-10-01 09:39:52.902 UTC [1539] ERROR: relation "goose_db_version" does not exist at character 3625202026-10-01 09:39:52.902 UTC [1539] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25212026/10/01 09:39:52 OK 20260905000000_add_claims.sql (9.34ms)25222026/10/01 09:39:52 OK 20241026095416_initial_model.sql (16.19ms)25232026/10/01 09:39:52 OK 3_commit_push.sql (8.09ms)25242026/10/01 09:39:52 goose: up to current file version: 325252026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)25262026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.6ms)25272026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.39ms)25282026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (3.24ms)25292026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000025302026-10-01 09:39:52.911 UTC [1542] ERROR: relation "goose_db_version" does not exist at character 3625312026-10-01 09:39:52.911 UTC [1542] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25322026/10/01 09:39:52 OK 1_commit_pending_closure.sql (3.23ms)25332026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)25342026-10-01 09:39:52.913 UTC [1544] ERROR: relation "goose_db_version" does not exist at character 3625352026-10-01 09:39:52.913 UTC [1544] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25362026-10-01 09:39:52.913 UTC [1543] ERROR: relation "goose_db_version" does not exist at character 3625372026-10-01 09:39:52.913 UTC [1543] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25382026/10/01 09:39:52 OK 2_object_stats_trigger.sql (2.06ms)25392026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.12ms)25402026/10/01 09:39:52 OK 3_commit_push.sql (1.92ms)25412026/10/01 09:39:52 goose: up to current file version: 325422026/10/01 09:39:52 OK 20260905000000_add_claims.sql (4.05ms)25432026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)25442026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.7ms)25452026/10/01 09:39:52 OK 20241026095416_initial_model.sql (9.25ms)25462026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.08ms)25472026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.66ms)25482026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000025492026/10/01 09:39:52 OK 20251218171726_add_pins.sql (4.38ms)2550--- PASS: TestMetricsInventory (0.41s)2551=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check25522026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.44ms)25532026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.85ms)25542026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.36ms)25552026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.86ms)25562026/10/01 09:39:52 OK 3_commit_push.sql (1.31ms)25572026/10/01 09:39:52 goose: up to current file version: 325582026/10/01 09:39:52 OK 20241026095416_initial_model.sql (9.97ms)25592026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.04ms)25602026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)25612026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.74ms)25622026/10/01 09:39:52 OK 20241026095416_initial_model.sql (11.02ms)25632026/10/01 09:39:52 OK 20241026095416_initial_model.sql (11.73ms)25642026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.61ms)25652026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.56ms)25662026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.09ms)25672026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.86ms)25682026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)25692026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.3ms)25702026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000025712026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.15ms)25722026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.42ms)25732026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.85ms)25742026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.92ms)25752026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.07ms)25762026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.55ms)25772026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000025782026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.9ms)25792026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.69ms)2580--- PASS: TestReadRedirectKeepsNarinfoProxied (0.41s)2581=== CONT TestClientErrorHandling/InvalidStorePath25822026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.58ms)25832026/10/01 09:39:52 OK 1_commit_pending_closure.sql (3.18ms)25842026/10/01 09:39:52 OK 3_commit_push.sql (1.89ms)25852026/10/01 09:39:52 goose: up to current file version: 325862026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.87ms)25872026-10-01 09:39:52.942 UTC [1547] ERROR: relation "goose_db_version" does not exist at character 3625882026-10-01 09:39:52.942 UTC [1547] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25892026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.43ms)25902026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.57ms)25912026/10/01 09:39:52 OK 3_commit_push.sql (1.18ms)25922026/10/01 09:39:52 goose: up to current file version: 325932026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.22ms)25942026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.48ms)25952026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.41ms)25962026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000025972026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.59ms)25982026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.46ms)25992026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (3.2ms)26002026-10-01 09:39:52.949 UTC [1549] ERROR: relation "goose_db_version" does not exist at character 3626012026-10-01 09:39:52.949 UTC [1549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26022026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.4ms)26032026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.78ms)26042026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000026052026/10/01 09:39:52 OK 3_commit_push.sql (1.52ms)26062026/10/01 09:39:52 goose: up to current file version: 326072026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.98ms)26082026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000026092026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.29ms)26102026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.3ms)26112026/10/01 09:39:52 OK 2_object_stats_trigger.sql (2.14ms)26122026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.8ms)26132026/10/01 09:39:52 OK 3_commit_push.sql (614.25µs)26142026/10/01 09:39:52 goose: up to current file version: 326152026/10/01 09:39:52 OK 3_commit_push.sql (1.27ms)26162026/10/01 09:39:52 goose: up to current file version: 326172026/10/01 09:39:52 OK 20241026095416_initial_model.sql (11.46ms)26182026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (2.22ms)26192026/10/01 09:39:52 OK 20241026095416_initial_model.sql (9.89ms)26202026/10/01 09:39:52 OK 20251218171726_add_pins.sql (3.57ms)26212026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.96ms)26222026-10-01 09:39:52.971 UTC [1552] ERROR: relation "goose_db_version" does not exist at character 3626232026-10-01 09:39:52.971 UTC [1552] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26242026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (10.08ms)26252026/10/01 09:39:52 OK 20251218171726_add_pins.sql (9.81ms)26262026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.75ms)26272026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (4.12ms)2628--- PASS: TestReadRedirectNar (0.36s)2629=== CONT TestClientErrorHandling/ServerNotAvailable26302026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.82ms)26312026/10/01 09:39:52 OK 20260905000000_add_claims.sql (3.23ms)26322026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.03ms)26332026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000026342026/10/01 09:39:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete26352026/10/01 09:39:52 OK 20260920000000_drop_claims.sql (2.24ms)26362026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.19ms)26372026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.38ms)26382026/10/01 09:39:52 OK 20260923120000_add_pushes.sql (2.05ms)26392026/10/01 09:39:52 goose: successfully migrated database to version: 2026092312000026402026/10/01 09:39:52 OK 3_commit_push.sql (1.62ms)26412026/10/01 09:39:52 goose: up to current file version: 326422026/10/01 09:39:52 OK 20241026095416_initial_model.sql (12.26ms)26432026/10/01 09:39:52 OK 1_commit_pending_closure.sql (2.09ms)26442026/10/01 09:39:52 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)26452026/10/01 09:39:52 OK 2_object_stats_trigger.sql (1.55ms)26462026/10/01 09:39:52 OK 3_commit_push.sql (1.05ms)26472026/10/01 09:39:52 goose: up to current file version: 326482026/10/01 09:39:52 OK 20251218171726_add_pins.sql (2.95ms)2649=== NAME TestNARDeduplicationMetadataUploadBug2650 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1309255425/001/store/z7y6p51bjvvy53sgqj42p8wiqzscw2im-file1.txt26512026/10/01 09:39:52 OK 20260628120000_add_object_size_and_stats.sql (3.21ms)2652--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.37s)2653=== CONT TestClientErrorHandling/InvalidAuthToken26542026-10-01 09:39:52.999 UTC [1570] ERROR: relation "goose_db_version" does not exist at character 3626552026-10-01 09:39:52.999 UTC [1570] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26562026/10/01 09:39:53 OK 20260905000000_add_claims.sql (3.43ms)26572026/10/01 09:39:53 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZTJhOTlkODMtOWZjMS00MWNkLTg5ZGMtYjZiZTgyZjY5M2YyLjI3NTM2MWUxLTEyZjMtNDBkZS05ODFkLWJkYmJiM2UwNDZhNXgxNzkwODQ3NTkyNjIyNTE4Njc3 parts=1226582026/10/01 09:39:53 OK 20260920000000_drop_claims.sql (2.09ms)26592026/10/01 09:39:53 INFO Received uploads request method=POST path=/api/pending_closures26602026/10/01 09:39:53 OK 20260923120000_add_pushes.sql (1.73ms)26612026/10/01 09:39:53 goose: successfully migrated database to version: 2026092312000026622026/10/01 09:39:53 OK 1_commit_pending_closure.sql (1.65ms)26632026/10/01 09:39:53 OK 2_object_stats_trigger.sql (811.59µs)26642026/10/01 09:39:53 OK 3_commit_push.sql (549.35µs)26652026/10/01 09:39:53 goose: up to current file version: 326662026/10/01 09:39:53 INFO Received uploads request method=POST path=/api/pending_closures2667--- PASS: TestReadProxyDisabled (0.37s)2668=== CONT TestCacheConfigHandler/full_config,_no_issuer2669=== CONT TestCacheConfigHandler/no_signing_keys2670=== CONT TestCacheConfigHandler/no_cache_url_configured2671=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2672=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure26732026/10/01 09:39:53 INFO Received uploads request method=POST path=/2674--- PASS: TestCacheConfigHandler (0.00s)2675 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2676 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2677 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2678 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)26792026/10/01 09:39:53 OK 20241026095416_initial_model.sql (10.41ms)26802026-10-01 09:39:53.016 UTC [1575] ERROR: relation "goose_db_version" does not exist at character 3626812026-10-01 09:39:53.016 UTC [1575] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26822026/10/01 09:39:53 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)26832026/10/01 09:39:53 OK 20251218171726_add_pins.sql (3.43ms)26842026/10/01 09:39:53 OK 20260628120000_add_object_size_and_stats.sql (3.56ms)26852026/10/01 09:39:53 OK 20260905000000_add_claims.sql (3.5ms)26862026/10/01 09:39:53 OK 20260920000000_drop_claims.sql (2.64ms)26872026/10/01 09:39:53 OK 20260923120000_add_pushes.sql (2.28ms)26882026/10/01 09:39:53 goose: successfully migrated database to version: 2026092312000026892026/10/01 09:39:53 OK 20241026095416_initial_model.sql (10.75ms)26902026/10/01 09:39:53 OK 1_commit_pending_closure.sql (2.28ms)26912026/10/01 09:39:53 OK 20251210153512_drop_unused_gin_index.sql (1.83ms)26922026/10/01 09:39:53 OK 2_object_stats_trigger.sql (1.04ms)26932026/10/01 09:39:53 OK 3_commit_push.sql (1.29ms)26942026/10/01 09:39:53 goose: up to current file version: 326952026/10/01 09:39:53 OK 20251218171726_add_pins.sql (3.41ms)2696--- PASS: TestReadProxyNarinfo (0.39s)2697=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts26982026/10/01 09:39:53 INFO Received request for more parts method=POST path=/26992026/10/01 09:39:53 OK 20260628120000_add_object_size_and_stats.sql (4.02ms)27002026/10/01 09:39:53 OK 20260905000000_add_claims.sql (3.52ms)27012026/10/01 09:39:53 OK 20260920000000_drop_claims.sql (2.33ms)27022026/10/01 09:39:53 OK 20260923120000_add_pushes.sql (2.23ms)27032026/10/01 09:39:53 goose: successfully migrated database to version: 2026092312000027042026/10/01 09:39:53 OK 1_commit_pending_closure.sql (2.23ms)27052026/10/01 09:39:53 OK 2_object_stats_trigger.sql (1.43ms)2706--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.34s)2707=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart27082026/10/01 09:39:53 INFO Received complete multipart upload request method=POST path=/27092026/10/01 09:39:53 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/present27102026/10/01 09:39:53 OK 3_commit_push.sql (1.25ms)27112026/10/01 09:39:53 goose: up to current file version: 327122026-10-01 09:39:53.068 UTC [1627] ERROR: relation "goose_db_version" does not exist at character 3627132026-10-01 09:39:53.068 UTC [1627] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27142026/10/01 09:39:53 INFO Received push request method=POST path=/api/pushes2715--- PASS: TestService_healthCheckHandler (0.32s)2716=== CONT TestProxyWriteTimeout/narinfo2717=== CONT TestProxyWriteTimeout/unknown_size2718=== CONT TestProxyWriteTimeout/10_GiB_nar2719=== CONT TestProxyWriteTimeout/1_GiB_nar2720--- PASS: TestProxyWriteTimeout (0.00s)2721 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2722 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2723 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2724 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2725=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info27262026/10/01 09:39:53 INFO Received uploads request method=POST path=/2727=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key27282026/10/01 09:39:53 INFO Received request for more parts method=POST path=/2729=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key27302026/10/01 09:39:53 INFO Received complete multipart upload request method=POST path=/2731=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal27322026/10/01 09:39:53 INFO Received uploads request method=POST path=/2733--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2734 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2735 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2736 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2737 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2738=== CONT TestIsValidUploadKey/narinfo2739=== CONT TestIsValidUploadKey/unknown_type2740=== CONT TestIsValidUploadKey/empty_key2741=== CONT TestIsValidUploadKey/absolute2742=== CONT TestIsValidUploadKey/traversal_nar2743=== CONT TestIsValidUploadKey/traversal2744=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2745=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2746=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2747=== CONT TestIsValidUploadKey/index.html2748=== CONT TestIsValidUploadKey/nix-cache-info2749=== CONT TestIsValidUploadKey/realisation_plus_in_output2750=== CONT TestIsValidUploadKey/realisation2751=== CONT TestIsValidUploadKey/build_log_equals2752=== CONT TestIsValidUploadKey/build_log_question_mark2753=== CONT TestIsValidUploadKey/build_log_plus_in_name2754=== CONT TestIsValidUploadKey/build_log_home-manager_file2755=== CONT TestIsValidUploadKey/build_log2756=== CONT TestIsValidUploadKey/listing2757=== CONT TestIsValidUploadKey/nar_plain2758=== CONT TestIsValidUploadKey/nar_zst2759=== CONT TestIsValidUploadKey/nar_xz2760--- PASS: TestIsValidUploadKey (0.00s)2761 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2762 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2763 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2764 --- PASS: TestIsValidUploadKey/absolute (0.00s)2765 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2766 --- PASS: TestIsValidUploadKey/traversal (0.00s)2767 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2768 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2769 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2770 --- PASS: TestIsValidUploadKey/index.html (0.00s)2771 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2772 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2773 --- PASS: TestIsValidUploadKey/realisation (0.00s)2774 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2775 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2776 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2777 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2778 --- PASS: TestIsValidUploadKey/build_log (0.00s)2779 --- PASS: TestIsValidUploadKey/listing (0.00s)2780 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2781 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2782 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2783=== CONT TestServerTLSConfig/no_client_CA2784=== CONT TestServerTLSConfig/not_a_PEM_file2785=== CONT TestServerTLSConfig/missing_CA_file2786--- PASS: TestServerTLSConfig (0.00s)2787 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2788 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2789 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2790=== CONT TestParseSingleRange/none2791=== CONT TestParseSingleRange/start_past_EOF2792=== CONT TestParseSingleRange/single_byte2793=== CONT TestParseSingleRange/suffix_exceeds_size2794=== CONT TestParseSingleRange/suffix2795=== CONT TestParseSingleRange/end_clamped_to_size2796=== CONT TestParseSingleRange/open-ended2797=== CONT TestParseSingleRange/closed2798=== CONT TestParseSingleRange/start_far_past_EOF2799=== CONT TestParseSingleRange/malformed_end_before_start2800=== CONT TestParseSingleRange/multi-range_ignored2801=== CONT TestParseSingleRange/unknown_unit2802=== CONT TestParseSingleRange/malformed_no_dash2803=== CONT TestParseSingleRange/malformed_both_empty2804--- PASS: TestParseSingleRange (0.00s)2805 --- PASS: TestParseSingleRange/none (0.00s)2806 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2807 --- PASS: TestParseSingleRange/single_byte (0.00s)2808 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2809 --- PASS: TestParseSingleRange/suffix (0.00s)2810 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2811 --- PASS: TestParseSingleRange/open-ended (0.00s)2812 --- PASS: TestParseSingleRange/closed (0.00s)2813 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2814 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2815 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2816 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2817 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2818 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2819=== CONT TestService_RequireScope_OIDC/builder_may_write2820=== CONT TestService_RequireScope_OIDC/static_token_may_admin2821=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2822=== CONT TestService_RequireScope_OIDC/writer_implies_read28232026/10/01 09:39:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)28242026/10/01 09:39:53 INFO Uploading z7y6p51bjvvy53sgqj42p8wiqzscw2im-file1.txt (160B)2825=== CONT TestService_RequireScope_OIDC/reader_may_read2826=== CONT TestService_RequireScope_OIDC/static_token_may_write2827=== CONT TestService_RequireScope_OIDC/reader_may_not_write2828=== CONT TestService_RequireScope_OIDC/ops_may_not_write2829=== CONT TestService_RequireScope_OIDC/ops_may_admin2830=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2831=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2832--- PASS: TestService_RequireScope_OIDC (0.41s)2833 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2834 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2835 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2836 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2837 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2838 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2839 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2840 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2841 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2842 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)28432026/10/01 09:39:53 WARN Failed to register uploaded object key=z7y6p51bjvvy53sgqj42p8wiqzscw2im.ls error="server returned 404: 404 page not found\n"28442026/10/01 09:39:53 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"28452026/10/01 09:39:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign2846=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected28472026/10/01 09:39:53 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]2848=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2849=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected28502026/10/01 09:39:53 INFO Signed narinfos id=1 count=128512026/10/01 09:39:53 INFO Uploading 1 narinfos28522026/10/01 09:39:53 WARN Authentication failed token_preview=eyJhbGciOi..._KFmNRwLPA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2853=== CONT TestPush_RejectsBadRequests/no_roots28542026/10/01 09:39:53 INFO Received push request method=POST path=/api/pushes2855=== CONT TestPush_RejectsBadRequests/bad_root28562026/10/01 09:39:53 INFO Received push request method=POST path=/api/pushes2857=== CONT TestPush_RejectsBadRequests/no_objects28582026/10/01 09:39:53 INFO Received push request method=POST path=/api/pushes2859=== CONT TestPush_RejectsBadRequests/root_not_in_objects28602026/10/01 09:39:53 OK 20241026095416_initial_model.sql (8.63ms)28612026/10/01 09:39:53 INFO Received push request method=POST path=/api/pushes2862=== CONT TestIsValidCachePath/narinfo2863--- PASS: TestService_AuthMiddleware_OIDC (0.58s)2864 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2865 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2866 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2867 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2868=== CONT TestIsValidCachePath/index.html2869=== CONT TestIsValidCachePath/short_hash2870=== CONT TestIsValidCachePath/wrong_extension2871=== CONT TestIsValidCachePath/nar_uncompressed2872--- PASS: TestPush_RejectsBadRequests (0.38s)2873 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2874 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2875 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2876 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2877=== CONT TestIsValidCachePath/leading_slash2878=== CONT TestIsValidCachePath/nix-cache-info2879=== CONT TestIsValidCachePath/empty2880=== CONT TestIsValidCachePath/realisation2881=== CONT TestIsValidCachePath/random_path2882=== CONT TestIsValidCachePath/log2883=== CONT TestIsValidCachePath/invalid_char_u2884=== CONT TestIsValidCachePath/ls28852026/10/01 09:39:53 INFO Received complete push request method=POST path=/api/pushes/1/complete2886=== CONT TestIsValidCachePath/invalid_char_e2887=== CONT TestIsValidCachePath/traversal_in_middle2888=== CONT TestIsValidCachePath/traversal_parent28892026/10/01 09:39:53 WARN Failed to register uploaded object key=z7y6p51bjvvy53sgqj42p8wiqzscw2im.narinfo error="server returned 404: 404 page not found\n"2890=== CONT TestIsValidCachePath/nar_xz2891=== CONT TestIsValidCachePath/nar_bz22892=== CONT TestIsValidCachePath/nar_zst2893=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2894--- PASS: TestIsValidCachePath (0.00s)2895 --- PASS: TestIsValidCachePath/narinfo (0.00s)2896 --- PASS: TestIsValidCachePath/index.html (0.00s)2897 --- PASS: TestIsValidCachePath/short_hash (0.00s)2898 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2899 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2900 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2901 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2902 --- PASS: TestIsValidCachePath/empty (0.00s)2903 --- PASS: TestIsValidCachePath/realisation (0.00s)2904 --- PASS: TestIsValidCachePath/random_path (0.00s)2905 --- PASS: TestIsValidCachePath/log (0.00s)2906 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2907 --- PASS: TestIsValidCachePath/ls (0.00s)2908 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2909 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2910 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2911 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2912 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2913 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2914 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)29152026/10/01 09:39:53 OK 20251210153512_drop_unused_gin_index.sql (1.18ms)29162026/10/01 09:39:53 OK 20251218171726_add_pins.sql (2.84ms)29172026/10/01 09:39:53 INFO Received uploads request method=POST path=/api/pending_closures29182026/10/01 09:39:53 INFO Upload complete. (57ms)29192026/10/01 09:39:53 OK 20260628120000_add_object_size_and_stats.sql (3.16ms)2920=== NAME TestNARDeduplicationMetadataUploadBug2921 metadata_upload_test.go:54: Retrieved narinfo from S3:2922 StorePath: /build/TestNARDeduplicationMetadataUploadBug1309255425/001/store/z7y6p51bjvvy53sgqj42p8wiqzscw2im-file1.txt2923 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2924 Compression: zstd2925 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2926 NarSize: 1602927 References: 2928 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf29292026/10/01 09:39:53 OK 20260905000000_add_claims.sql (2.81ms)2930 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2931 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2932 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}29332026/10/01 09:39:53 OK 20260920000000_drop_claims.sql (1.95ms)29342026/10/01 09:39:53 OK 20260923120000_add_pushes.sql (1.72ms)29352026/10/01 09:39:53 goose: successfully migrated database to version: 2026092312000029362026/10/01 09:39:53 OK 1_commit_pending_closure.sql (2.05ms)29372026/10/01 09:39:53 INFO Received uploads request method=POST path=/api/pending_closures29382026/10/01 09:39:53 OK 2_object_stats_trigger.sql (1.02ms)29392026/10/01 09:39:53 OK 3_commit_push.sql (1.03ms)29402026/10/01 09:39:53 goose: up to current file version: 329412026/10/01 09:39:53 INFO Received cleanup request method=DELETE path=/api/pending_closures2942--- PASS: TestObjectStatsTrigger (0.35s)2943=== NAME TestNARDeduplicationMetadataUploadBug2944 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1309255425/001/store/adw9ixpx370nk6a0iqd7s2lazzmi46g4-file2.txt29452026/10/01 09:39:53 WARN readiness check failed error="closed pool"2946--- PASS: TestService_readinessHandler (0.35s)29472026/10/01 09:39:53 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=214.54718ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2948--- PASS: TestPresentReportsOnlyClosureRoots (0.35s)29492026/10/01 09:39:53 INFO Received push request method=POST path=/api/pushes29502026/10/01 09:39:53 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)29512026/10/01 09:39:53 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign29522026/10/01 09:39:53 INFO Signed narinfos id=2 count=129532026/10/01 09:39:53 WARN Failed to register uploaded object key=adw9ixpx370nk6a0iqd7s2lazzmi46g4.ls error="server returned 404: 404 page not found\n"29542026/10/01 09:39:53 INFO Uploading 1 narinfos29552026/10/01 09:39:53 INFO Received complete push request method=POST path=/api/pushes/2/complete29562026/10/01 09:39:53 WARN Failed to register uploaded object key=adw9ixpx370nk6a0iqd7s2lazzmi46g4.narinfo error="server returned 404: 404 page not found\n"29572026/10/01 09:39:53 INFO Received uploads request method=POST path=/api/pending_closures29582026/10/01 09:39:53 INFO Upload complete. (45ms)2959=== NAME TestNARDeduplicationMetadataUploadBug2960 metadata_upload_test.go:76: Retrieved narinfo from S3:2961 StorePath: /build/TestNARDeduplicationMetadataUploadBug1309255425/001/store/adw9ixpx370nk6a0iqd7s2lazzmi46g4-file2.txt2962 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2963 Compression: zstd2964 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2965 NarSize: 1602966 References: 2967 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2968 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2969 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2970 {"version":1,"root":{"type":"regular","size":44}}2971--- PASS: TestNARDeduplicationMetadataUploadBug (0.66s)29722026/10/01 09:39:53 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux29732026/10/01 09:39:53 WARN Refused reserved pin name=worker-x86_64-linux29742026/10/01 09:39:53 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux29752026/10/01 09:39:53 INFO Received create pin request method=POST path=/api/pins/my-app29762026/10/01 09:39:53 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux2977--- PASS: TestCreatePin_ReservedPins (0.44s)29782026/10/01 09:39:53 INFO Received uploads request method=POST path=/api/pending_closures2979--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.40s)29802026/10/01 09:39:53 INFO Received uploads request method=POST path=/api/pending_closures29812026/10/01 09:39:53 INFO Aborted multipart uploads count=0 kept=029822026/10/01 09:39:53 WARN Force mode enabled - objects will be deleted immediately without grace period29832026/10/01 09:39:53 INFO Received uploads request method=POST path=/api/pending_closures29842026/10/01 09:39:53 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=029852026/10/01 09:39:53 INFO Vacuumed table table=pending_closures29862026/10/01 09:39:53 INFO Vacuumed table table=pending_objects29872026/10/01 09:39:53 INFO Vacuumed table table=multipart_uploads29882026/10/01 09:39:53 INFO Vacuumed table table=closures29892026/10/01 09:39:53 INFO Vacuumed table table=objects29902026/10/01 09:39:53 INFO Aborted multipart uploads count=0 kept=029912026/10/01 09:39:53 WARN Force mode enabled - objects will be deleted immediately without grace period29922026/10/01 09:39:53 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=029932026/10/01 09:39:53 INFO Vacuumed table table=pending_closures29942026/10/01 09:39:53 INFO Vacuumed table table=pending_objects29952026/10/01 09:39:53 INFO Vacuumed table table=multipart_uploads29962026/10/01 09:39:53 INFO Vacuumed table table=closures29972026/10/01 09:39:53 INFO Vacuumed table table=objects29982026/10/01 09:39:53 INFO Received cleanup request method=DELETE path=/api/pending_closures29992026/10/01 09:39:53 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket78/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""30002026/10/01 09:39:53 INFO Aborted multipart uploads count=0 kept=130012026/10/01 09:39:53 INFO Received cleanup request method=DELETE path=/api/pending_closures30022026/10/01 09:39:53 INFO Aborted multipart uploads count=1 kept=03003--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)3004 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.43s)3005 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.41s)3006--- PASS: TestMultipartCleanup (0.49s)30072026/10/01 09:39:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete30082026/10/01 09:39:53 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZTJhOTlkODMtOWZjMS00MWNkLTg5ZGMtYjZiZTgyZjY5M2YyLjE3MTQ1NmIyLTg0OGMtNDhmMS1iYjUyLThlNjY2YjkyMWJmY3gxNzkwODQ3NTkzMDEyMTU2NTk2 error="Get \"http://127.0.0.1:1/bucket49/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"30092026/10/01 09:39:53 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZTJhOTlkODMtOWZjMS00MWNkLTg5ZGMtYjZiZTgyZjY5M2YyLjQ1NGFjMDkwLTIxNGEtNDM1Yi1iY2U0LThiMWQwZTEzOWFkZHgxNzkwODQ3NTkzMDA3MjM5MDkx parts=1230102026/10/01 09:39:53 INFO Received cleanup request method=DELETE path=/api/pending_closures30112026/10/01 09:39:53 INFO Aborted multipart uploads count=1 kept=030122026/10/01 09:39:53 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=439.45046ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present3013--- PASS: TestRedundantMultipartUpload (1.14s)30142026/10/01 09:39:53 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30152026/10/01 09:39:53 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"3016=== NAME TestOrphanedObjectsGC3017 orphaned_objects_gc_test.go:290: GC Test Summary:3018 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A3019 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B3020 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)3021 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)3022 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects3023--- PASS: TestOrphanedObjectsGC (0.67s)3024--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.88s)30252026/10/01 09:39:53 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=797.438457ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present3026--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)3027 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.06s)3028 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)3029 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.90s)3030=== NAME TestOrphanedObjectsGCStressTest3031 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains3032 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion3033 orphaned_objects_gc_test.go:509: Stress test completed successfully:3034 orphaned_objects_gc_test.go:510: - Active objects preserved: 203035 orphaned_objects_gc_test.go:511: - Objects deleted: 2103036 orphaned_objects_gc_test.go:512: - Total GC'd: 2103037--- PASS: TestOrphanedObjectsGCStressTest (1.55s)30382026/10/01 09:39:54 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=030392026/10/01 09:39:54 INFO Received create pin request method=POST path=/api/pins/myapp30402026/10/01 09:39:54 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2487878059/001/store/mf5cmlb7y5djhys6jvbnh7d31mqwb9ir-pinned-file.txt narinfo_key=mf5cmlb7y5djhys6jvbnh7d31mqwb9ir.narinfo30412026/10/01 09:39:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures30422026/10/01 09:39:54 INFO Garbage collection started30432026/10/01 09:39:54 INFO Aborted multipart uploads count=0 kept=030442026/10/01 09:39:54 WARN Force mode enabled - objects will be deleted immediately without grace period30452026/10/01 09:39:54 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=030462026/10/01 09:39:54 INFO Vacuumed table table=pending_closures30472026/10/01 09:39:54 INFO Vacuumed table table=pending_objects30482026/10/01 09:39:54 INFO Vacuumed table table=multipart_uploads30492026/10/01 09:39:54 INFO Vacuumed table table=closures30502026/10/01 09:39:54 INFO Vacuumed table table=objects30512026/10/01 09:39:54 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=03052=== NAME TestClientIntegration3053 client_integration_test.go:323: Objects in database after GC:3054 client_integration_test.go:323: Successfully deleted all objects with GC --force3055--- PASS: TestClientIntegration (2.66s)30562026/10/01 09:39:54 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.689945796s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present30572026/10/01 09:39:56 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-config3058=== NAME TestPinProtectsFromGC3059 client_integration_test.go:840: Pin successfully protected closure from garbage collection3060--- PASS: TestPinProtectsFromGC (4.73s)30612026/10/01 09:39:56 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=203.70124ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30622026/10/01 09:39:56 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=369.733117ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30632026/10/01 09:39:56 WARN Rate limiter enabled after throttle name=s3-test rate=530642026/10/01 09:39:56 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."3065=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle3066 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=103067 throttle_test.go:215: Rate limiter: enabled=true, rate=5.003068--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.54s)30692026/10/01 09:39:57 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=725.498596ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30702026/10/01 09:39:57 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.721844829s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30712026/10/01 09:39:59 INFO Aborted multipart uploads count=1 kept=030722026/10/01 09:39:59 INFO Received cleanup request method=DELETE path=/api/pending_closures30732026/10/01 09:39:59 INFO Aborted multipart uploads count=1 kept=03074--- PASS: TestPendingCleanupUsesOneCutoff (6.36s)30752026/10/01 09:39:59 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"30762026/10/01 09:39:59 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-config30772026/10/01 09:39:59 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=216.392051ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30782026/10/01 09:39:59 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=382.340726ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30792026/10/01 09:40:00 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=803.424985ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30802026/10/01 09:40:00 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.69878869s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30812026/10/01 09:40:02 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_closures30822026/10/01 09:40:02 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=190.483699ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30832026/10/01 09:40:02 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=382.258941ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30842026/10/01 09:40:03 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=721.927462ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30852026/10/01 09:40:04 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.5645233s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3086--- PASS: TestClientErrorHandling (0.00s)3087 --- PASS: TestClientErrorHandling/InvalidStorePath (0.40s)3088 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.43s)3089 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.66s)3090PASS30912026-10-01 09:40:05.861 UTC [128] LOG: received smart shutdown request30922026-10-01 09:40:05.864 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 130932026-10-01 09:40:05.875 UTC [133] LOG: shutting down30942026-10-01 09:40:05.875 UTC [133] LOG: checkpoint starting: shutdown immediate30952026-10-01 09:40:06.719 UTC [133] LOG: checkpoint complete: wrote 10841 buffers (66.2%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 24 recycled; write=0.180 s, sync=0.637 s, total=0.845 s; sync files=28648, longest=0.002 s, average=0.001 s; distance=396501 kB, estimate=396501 kB; lsn=0/19A9B2F0, redo lsn=0/19A9B2F030962026-10-01 09:40:06.797 UTC [128] LOG: database system is shut down3097Running OIDC tests...3098=== RUN TestAudienceForIssuer3099=== PAUSE TestAudienceForIssuer3100=== RUN TestGlobMatch3101=== PAUSE TestGlobMatch3102=== RUN TestValidateToken_ValidToken3103=== PAUSE TestValidateToken_ValidToken3104=== RUN TestValidateToken_WrongAudience3105=== PAUSE TestValidateToken_WrongAudience3106=== RUN TestValidateToken_Expired3107=== PAUSE TestValidateToken_Expired3108=== RUN TestValidateToken_BoundClaimsMismatch3109=== PAUSE TestValidateToken_BoundClaimsMismatch3110=== RUN TestValidateToken_BoundSubjectMismatch3111=== PAUSE TestValidateToken_BoundSubjectMismatch3112=== RUN TestValidateToken_MultipleProviders3113=== PAUSE TestValidateToken_MultipleProviders3114=== RUN TestValidateToken_NoMatchingProvider3115=== PAUSE TestValidateToken_NoMatchingProvider3116=== RUN TestValidateToken_KubernetesServiceAccount3117=== PAUSE TestValidateToken_KubernetesServiceAccount3118=== RUN TestNewValidator_KubernetesRequiresCA3119=== PAUSE TestNewValidator_KubernetesRequiresCA3120=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3121=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3122=== RUN TestPins_ReservedForMatchingRule3123=== PAUSE TestPins_ReservedForMatchingRule3124=== RUN TestPins_TopLevelShorthand3125=== PAUSE TestPins_TopLevelShorthand3126=== RUN TestPins_ConfigValidation3127=== PAUSE TestPins_ConfigValidation3128=== RUN TestScopes_LegacyProviderDefaultsToWrite3129=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3130=== RUN TestScopes_Rules3131=== PAUSE TestScopes_Rules3132=== RUN TestScopes_ConfigValidation3133=== PAUSE TestScopes_ConfigValidation3134=== CONT TestAudienceForIssuer3135=== CONT TestValidateToken_KubernetesServiceAccount3136=== CONT TestPins_TopLevelShorthand3137--- PASS: TestAudienceForIssuer (0.00s)3138=== CONT TestValidateToken_Expired3139=== CONT TestPins_ConfigValidation3140=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3141=== CONT TestScopes_Rules3142=== CONT TestValidateToken_ValidToken3143=== CONT TestValidateToken_BoundClaimsMismatch3144=== CONT TestValidateToken_WrongAudience3145=== CONT TestValidateToken_NoMatchingProvider3146=== CONT TestScopes_ConfigValidation3147=== CONT TestValidateToken_MultipleProviders3148=== CONT TestValidateToken_BoundSubjectMismatch3149--- PASS: TestPins_ConfigValidation (0.00s)3150=== CONT TestScopes_LegacyProviderDefaultsToWrite3151=== CONT TestGlobMatch3152=== RUN TestGlobMatch/foo_foo3153=== PAUSE TestGlobMatch/foo_foo3154=== RUN TestGlobMatch/foo_bar3155=== PAUSE TestGlobMatch/foo_bar3156=== RUN TestGlobMatch/*_3157=== CONT TestNewValidator_KubernetesRequiresCA3158=== CONT TestPins_ReservedForMatchingRule3159=== PAUSE TestGlobMatch/*_3160=== RUN TestGlobMatch/*_anything3161=== PAUSE TestGlobMatch/*_anything3162--- PASS: TestScopes_ConfigValidation (0.00s)3163=== RUN TestGlobMatch/foo*_foo3164=== PAUSE TestGlobMatch/foo*_foo3165=== RUN TestGlobMatch/foo*_foobar3166=== PAUSE TestGlobMatch/foo*_foobar3167=== RUN TestGlobMatch/foo*_bar3168=== PAUSE TestGlobMatch/foo*_bar3169=== RUN TestGlobMatch/*bar_bar3170=== PAUSE TestGlobMatch/*bar_bar3171=== RUN TestGlobMatch/*bar_foobar3172=== PAUSE TestGlobMatch/*bar_foobar3173=== RUN TestGlobMatch/*bar_foo3174=== PAUSE TestGlobMatch/*bar_foo3175=== RUN TestGlobMatch/foo*bar_foobar3176=== PAUSE TestGlobMatch/foo*bar_foobar3177=== RUN TestGlobMatch/foo*bar_foo123bar3178=== PAUSE TestGlobMatch/foo*bar_foo123bar3179=== RUN TestGlobMatch/foo*bar_foobarbaz3180=== PAUSE TestGlobMatch/foo*bar_foobarbaz3181=== RUN TestGlobMatch/*/*_foo/bar3182=== PAUSE TestGlobMatch/*/*_foo/bar3183=== RUN TestGlobMatch/*/*_foo3184=== PAUSE TestGlobMatch/*/*_foo3185=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3186=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3187=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03188=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03189=== RUN TestGlobMatch/refs/*/main_refs/heads/main3190=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3191=== RUN TestGlobMatch/fo?_foo3192=== PAUSE TestGlobMatch/fo?_foo3193=== RUN TestGlobMatch/fo?_fo3194=== PAUSE TestGlobMatch/fo?_fo3195=== RUN TestGlobMatch/fo?_fooo3196=== PAUSE TestGlobMatch/fo?_fooo3197=== RUN TestGlobMatch/?oo_foo3198=== PAUSE TestGlobMatch/?oo_foo3199=== RUN TestGlobMatch/?oo_boo3200=== PAUSE TestGlobMatch/?oo_boo3201=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3202=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3203=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3204=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3205=== CONT TestGlobMatch/foo_foo3206=== CONT TestGlobMatch/?oo_foo3207=== CONT TestGlobMatch/foo*_foobar3208=== CONT TestGlobMatch/refs/*/main_refs/heads/main3209=== CONT TestGlobMatch/fo?_fo3210=== CONT TestGlobMatch/fo?_foo3211=== CONT TestGlobMatch/*bar_foo3212=== CONT TestGlobMatch/foo*bar_foo123bar3213=== CONT TestGlobMatch/fo?_fooo3214=== CONT TestGlobMatch/*bar_foobar3215=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3216=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03217=== CONT TestGlobMatch/*/*_foo/bar3218=== CONT TestGlobMatch/*/*_foo3219=== CONT TestGlobMatch/*bar_bar3220=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3221=== CONT TestGlobMatch/?oo_boo3222=== CONT TestGlobMatch/foo*_foo3223=== CONT TestGlobMatch/*_anything3224=== CONT TestGlobMatch/*_3225=== CONT TestGlobMatch/foo_bar3226=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3227=== CONT TestGlobMatch/foo*bar_foobarbaz3228=== CONT TestGlobMatch/foo*bar_foobar3229=== CONT TestGlobMatch/foo*_bar3230--- PASS: TestGlobMatch (0.00s)3231 --- PASS: TestGlobMatch/foo_foo (0.00s)3232 --- PASS: TestGlobMatch/?oo_foo (0.00s)3233 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3234 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3235 --- PASS: TestGlobMatch/fo?_fo (0.00s)3236 --- PASS: TestGlobMatch/fo?_foo (0.00s)3237 --- PASS: TestGlobMatch/*bar_foo (0.00s)3238 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3239 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3240 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3241 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3242 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3243 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3244 --- PASS: TestGlobMatch/*/*_foo (0.00s)3245 --- PASS: TestGlobMatch/*bar_bar (0.00s)3246 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3247 --- PASS: TestGlobMatch/?oo_boo (0.00s)3248 --- PASS: TestGlobMatch/foo*_foo (0.00s)3249 --- PASS: TestGlobMatch/*_anything (0.00s)3250 --- PASS: TestGlobMatch/*_ (0.00s)3251 --- PASS: TestGlobMatch/foo_bar (0.00s)3252 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3253 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3254 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3255 --- PASS: TestGlobMatch/foo*_bar (0.00s)32562026/10/01 09:40:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38337/oidc32572026/10/01 09:40:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36853/oidc3258--- PASS: TestScopes_Rules (0.04s)3259--- PASS: TestValidateToken_WrongAudience (0.05s)32602026/10/01 09:40:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43913/oidc3261--- PASS: TestValidateToken_Expired (0.06s)32622026/10/01 09:40:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36829/oidc3263--- PASS: TestValidateToken_ValidToken (0.07s)32642026/10/01 09:40:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37889/oidc3265--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)32662026/10/01 09:40:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40127/oidc3267--- PASS: TestValidateToken_BoundSubjectMismatch (0.15s)32682026/10/01 09:40:08 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:39831/oidc3269--- PASS: TestValidateToken_NoMatchingProvider (0.17s)32702026/10/01 09:40:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43863/oidc3271--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.18s)32722026/10/01 09:40:08 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:461773273--- PASS: TestValidateToken_KubernetesServiceAccount (0.22s)32742026/10/01 09:40:08 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:40633/oidc32752026/10/01 09:40:08 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:37141/oidc3276--- PASS: TestValidateToken_MultipleProviders (0.25s)32772026/10/01 09:40:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38331/oidc3278--- PASS: TestPins_ReservedForMatchingRule (0.26s)32792026/10/01 09:40:08 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233280--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.28s)32812026/10/01 09:40:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41465/oidc3282--- PASS: TestPins_TopLevelShorthand (0.32s)32832026/10/01 09:40:08 http: TLS handshake error from 127.0.0.1:56072: remote error: tls: bad certificate3284--- PASS: TestNewValidator_KubernetesRequiresCA (0.35s)3285PASS3286Running hook tests...3287=== RUN TestSendPathsEmpty3288=== PAUSE TestSendPathsEmpty3289=== RUN TestQueueEnqueueAndFetch3290=== PAUSE TestQueueEnqueueAndFetch3291=== RUN TestQueueDeduplication3292=== PAUSE TestQueueDeduplication3293=== RUN TestQueueRemove3294=== PAUSE TestQueueRemove3295=== RUN TestQueueFetchBatchLimit3296=== PAUSE TestQueueFetchBatchLimit3297=== RUN TestQueueRetryMovesToBack3298=== PAUSE TestQueueRetryMovesToBack3299=== RUN TestQueueFetchRemoveLifecycle3300=== PAUSE TestQueueFetchRemoveLifecycle3301=== RUN TestQueueConcurrentWriters3302=== PAUSE TestQueueConcurrentWriters3303=== RUN TestQueueRemoveLargeClosure3304=== PAUSE TestQueueRemoveLargeClosure3305=== RUN TestServerClientIntegration3306=== PAUSE TestServerClientIntegration3307=== RUN TestServerQueueError3308=== PAUSE TestServerQueueError3309=== RUN TestGetListenerSocketActivation3310 server_test.go:210: === RUN TestGetListenerSocketActivation3311 --- PASS: TestGetListenerSocketActivation (0.00s)3312 PASS3313 3314--- PASS: TestGetListenerSocketActivation (0.01s)3315=== RUN TestDrainIsolatesPoisonPath3316=== PAUSE TestDrainIsolatesPoisonPath3317=== RUN TestRunNotBlockedByPoisonHead3318=== PAUSE TestRunNotBlockedByPoisonHead3319=== RUN TestDrainGivesUpWhenServerDown3320=== PAUSE TestDrainGivesUpWhenServerDown3321=== RUN TestFailedPathPrunedByLaterClosure3322=== PAUSE TestFailedPathPrunedByLaterClosure3323=== RUN TestWorkerUploadsAndRemoves3324=== PAUSE TestWorkerUploadsAndRemoves3325=== RUN TestWorkerSkipsGCdPaths3326=== PAUSE TestWorkerSkipsGCdPaths3327=== RUN TestWorkerPrunesClosureDeps3328=== PAUSE TestWorkerPrunesClosureDeps3329=== RUN TestDrainTimeout3330=== PAUSE TestDrainTimeout3331=== CONT TestSendPathsEmpty3332=== CONT TestFailedPathPrunedByLaterClosure3333=== CONT TestQueueRemove3334--- PASS: TestSendPathsEmpty (0.00s)3335=== CONT TestDrainGivesUpWhenServerDown3336=== CONT TestRunNotBlockedByPoisonHead3337=== CONT TestDrainIsolatesPoisonPath3338=== CONT TestServerQueueError3339=== CONT TestServerClientIntegration3340=== CONT TestWorkerPrunesClosureDeps3341=== CONT TestQueueRemoveLargeClosure3342=== CONT TestQueueConcurrentWriters3343=== CONT TestQueueFetchRemoveLifecycle3344=== CONT TestDrainTimeout3345=== CONT TestQueueDeduplication33462026/10/01 09:40:08 ERROR Failed to queue paths error="permission denied" count=13347=== CONT TestQueueEnqueueAndFetch3348=== CONT TestQueueRetryMovesToBack3349=== CONT TestWorkerSkipsGCdPaths3350=== CONT TestQueueFetchBatchLimit3351=== CONT TestWorkerUploadsAndRemoves3352--- PASS: TestServerQueueError (0.00s)3353--- PASS: TestServerClientIntegration (0.00s)33542026/10/01 09:40:08 INFO Uploading batch count=233552026/10/01 09:40:08 INFO Upload queue status pending=233562026/10/01 09:40:08 INFO Upload queue status pending=233572026/10/01 09:40:08 INFO Uploading batch count=133582026/10/01 09:40:08 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths977645219/002/nonexistent3359--- PASS: TestQueueDeduplication (0.01s)33602026/10/01 09:40:08 INFO Uploading batch count=133612026/10/01 09:40:08 ERROR Upload failed error="upload failed" count=13362--- PASS: TestQueueFetchBatchLimit (0.01s)33632026/10/01 09:40:08 INFO Uploading batch count=13364--- PASS: TestQueueEnqueueAndFetch (0.01s)33652026/10/01 09:40:08 INFO Upload queue status pending=333662026/10/01 09:40:08 INFO Uploading batch count=133672026/10/01 09:40:08 INFO Uploading batch count=133682026/10/01 09:40:08 ERROR Upload failed error="upload failed" count=133692026/10/01 09:40:08 INFO Uploading batch count=233702026/10/01 09:40:08 ERROR Upload failed error="upload failed" count=233712026/10/01 09:40:08 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown666079201/002/a33722026/10/01 09:40:08 INFO Upload queue status pending=233732026/10/01 09:40:08 INFO Uploading batch count=233742026/10/01 09:40:08 INFO Uploading batch count=433752026/10/01 09:40:08 ERROR Upload failed error="upload failed" count=433762026/10/01 09:40:08 INFO Uploading batch count=13377--- PASS: TestQueueRetryMovesToBack (0.01s)33782026/10/01 09:40:08 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2005591031/002/bbb33792026/10/01 09:40:08 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown666079201/002/b3380--- PASS: TestQueueFetchRemoveLifecycle (0.01s)3381--- PASS: TestQueueRemove (0.02s)33822026/10/01 09:40:08 INFO Uploading batch count=233832026/10/01 09:40:08 ERROR Upload failed error="upload failed" count=233842026/10/01 09:40:08 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown666079201/002/c33852026/10/01 09:40:08 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown666079201/002/d33862026/10/01 09:40:08 INFO Uploading batch count=133872026/10/01 09:40:08 ERROR Upload failed error="upload failed" count=13388--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)33892026/10/01 09:40:08 INFO Uploading batch count=133902026/10/01 09:40:08 ERROR Upload failed error="upload failed" count=133912026/10/01 09:40:08 INFO Uploading batch count=233922026/10/01 09:40:08 ERROR Upload failed error="upload failed" count=233932026/10/01 09:40:08 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown666079201/002/e33942026/10/01 09:40:08 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown666079201/002/f33952026/10/01 09:40:08 INFO Uploading batch count=133962026/10/01 09:40:08 ERROR Upload failed error="upload failed" count=133972026/10/01 09:40:08 ERROR Drain finished with paths left in queue remaining=1033982026/10/01 09:40:08 ERROR Drain finished with paths left in queue remaining=13399--- PASS: TestDrainIsolatesPoisonPath (0.02s)3400--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3401--- PASS: TestWorkerSkipsGCdPaths (0.03s)3402--- PASS: TestWorkerPrunesClosureDeps (0.03s)3403--- PASS: TestWorkerUploadsAndRemoves (0.03s)3404--- PASS: TestQueueConcurrentWriters (0.13s)3405--- PASS: TestQueueRemoveLargeClosure (0.14s)34062026/10/01 09:40:08 ERROR Upload failed error="context deadline exceeded" count=234072026/10/01 09:40:08 ERROR Drain finished with paths left in queue remaining=43408--- PASS: TestDrainTimeout (0.21s)34092026/10/01 09:40:09 INFO Uploading batch count=134102026/10/01 09:40:09 INFO Uploading batch count=134112026/10/01 09:40:09 INFO Uploading batch count=134122026/10/01 09:40:09 ERROR Upload failed error="upload failed" count=134132026/10/01 09:40:09 INFO Uploading batch count=134142026/10/01 09:40:09 ERROR Upload failed error="upload failed" count=134152026/10/01 09:40:09 INFO Uploading batch count=134162026/10/01 09:40:09 ERROR Upload failed error="upload failed" count=134172026/10/01 09:40:09 INFO Uploading batch count=134182026/10/01 09:40:09 ERROR Upload failed error="upload failed" count=134192026/10/01 09:40:09 ERROR Drain finished with paths left in queue remaining=13420--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3421PASS