niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #293
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestCaseHackSuffix8=== PAUSE TestCaseHackSuffix9=== RUN TestFilterOversizedClosures10=== PAUSE TestFilterOversizedClosures11=== RUN TestUploadMultipart_PartsInParallel12=== PAUSE TestUploadMultipart_PartsInParallel13=== RUN TestPartSizeForNAR14=== PAUSE TestPartSizeForNAR15=== RUN TestUploadMultipart_SupersededByPeer16=== PAUSE TestUploadMultipart_SupersededByPeer17=== RUN TestDumpPathCaseHackMatchesNix18--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)19=== RUN TestDumpPathCaseHackCollision20--- PASS: TestDumpPathCaseHackCollision (0.00s)21=== RUN TestDumpPathMatchesNix22=== PAUSE TestDumpPathMatchesNix23=== RUN TestDumpPathSingleFile24=== PAUSE TestDumpPathSingleFile25=== RUN TestDumpPathWriterError26=== PAUSE TestDumpPathWriterError27=== RUN TestEncodeNixBase3228=== PAUSE TestEncodeNixBase3229=== RUN TestEncodeNixBase32WithRealHash30=== PAUSE TestEncodeNixBase32WithRealHash31=== RUN TestConvertHashToNix3232=== PAUSE TestConvertHashToNix3233=== RUN TestGetStorePathHash34=== PAUSE TestGetStorePathHash35=== RUN TestPathInfoHashCompatibility36=== PAUSE TestPathInfoHashCompatibility37=== RUN TestParsePathInfoJSON38=== PAUSE TestParsePathInfoJSON39=== RUN TestParsePathInfoJSONMultiplePaths40=== PAUSE TestParsePathInfoJSONMultiplePaths41=== RUN TestPathInfoCACompatibility42=== PAUSE TestPathInfoCACompatibility43=== RUN TestRateLimiterFeedback44=== PAUSE TestRateLimiterFeedback45=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess47=== RUN TestResolveStorePath48=== PAUSE TestResolveStorePath49=== RUN TestDoWithRetry_BodyReplayedViaGetBody50=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody51=== RUN TestShellSplit52=== PAUSE TestShellSplit53=== RUN TestShellSplitErrors54=== PAUSE TestShellSplitErrors55=== RUN TestStreamPushReportsEveryPath56=== PAUSE TestStreamPushReportsEveryPath57=== RUN TestStreamPushBatchesUnderLoad58=== PAUSE TestStreamPushBatchesUnderLoad59=== RUN TestStreamPushIsolatesFailures60=== PAUSE TestStreamPushIsolatesFailures61=== RUN TestStreamPushGivesUpOnDeadServer62=== PAUSE TestStreamPushGivesUpOnDeadServer63=== RUN TestStreamPushRequestLine64=== PAUSE TestStreamPushRequestLine65=== RUN TestStreamPushReportsSignatures66=== PAUSE TestStreamPushReportsSignatures67=== RUN TestClientSignaturesByStorePath68=== PAUSE TestClientSignaturesByStorePath69=== RUN TestSetClientTLS70=== PAUSE TestSetClientTLS71=== RUN TestSetClientTLSDoesNotMutateDefaultTransport72=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport73=== RUN TestSetClientTLSErrors74=== PAUSE TestSetClientTLSErrors75=== RUN TestStaticToken76=== PAUSE TestStaticToken77=== RUN TestFileTokenReadsAndCaches78=== PAUSE TestFileTokenReadsAndCaches79=== RUN TestFileTokenMissing80=== PAUSE TestFileTokenMissing81=== RUN TestFileTokenEmpty82=== PAUSE TestFileTokenEmpty83=== RUN TestScriptTokenNoExpiryRerunsEveryCall84=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall85=== RUN TestScriptTokenCachesUntilRefresh86=== PAUSE TestScriptTokenCachesUntilRefresh87=== RUN TestScriptTokenEmptyToken88=== PAUSE TestScriptTokenEmptyToken89=== RUN TestScriptTokenBadJSON90=== PAUSE TestScriptTokenBadJSON91=== RUN TestScriptTokenScriptFails92=== PAUSE TestScriptTokenScriptFails93=== RUN TestScriptTokenEmptyCommand94=== PAUSE TestScriptTokenEmptyCommand95=== CONT TestDoServerRequestAttachesToken96=== CONT TestShellSplit97=== CONT TestEncodeNixBase32WithRealHash98=== CONT TestScriptTokenScriptFails99=== CONT TestScriptTokenBadJSON100=== CONT TestDoWithRetry_BodyReplayedViaGetBody101=== CONT TestResolveStorePath102=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess103=== CONT TestRateLimiterFeedback104=== CONT TestPathInfoCACompatibility105=== CONT TestParsePathInfoJSONMultiplePaths106=== CONT TestParsePathInfoJSON107=== CONT TestPathInfoHashCompatibility108=== CONT TestGetStorePathHash109=== CONT TestUploadMultipart_SupersededByPeer110=== CONT TestConvertHashToNix32111=== RUN TestPathInfoCACompatibility/null_ca_field112=== RUN TestGetStorePathHash/valid_store_path113=== PAUSE TestGetStorePathHash/valid_store_path114=== PAUSE TestPathInfoCACompatibility/null_ca_field115=== RUN TestPathInfoCACompatibility/old_string_format_-_text116=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text1172026/10/01 07:37:43 WARN Rate limiter enabled after throttle name=server-test rate=5118=== RUN TestConvertHashToNix32/SRI_format_to_Nix32119=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32120=== CONT TestDumpPathWriterError121=== CONT TestFilterOversizedClosures122=== CONT TestDumpPathSingleFile123=== CONT TestPartSizeForNAR124=== CONT TestDumpPathMatchesNix125=== CONT TestUploadMultipart_PartsInParallel126=== CONT TestSetClientTLSErrors127=== CONT TestScriptTokenEmptyCommand128=== CONT TestRegisterUploadedObjectReusesConnections129--- PASS: TestShellSplit (0.00s)130=== RUN TestUploadMultipart_SupersededByPeer/exists131=== PAUSE TestUploadMultipart_SupersededByPeer/exists132--- PASS: TestEncodeNixBase32WithRealHash (0.00s)133--- PASS: TestScriptTokenScriptFails (0.00s)134=== RUN TestUploadMultipart_SupersededByPeer/missing135=== PAUSE TestUploadMultipart_SupersededByPeer/missing136=== RUN TestRateLimiterFeedback/429_enables_limiter137=== PAUSE TestRateLimiterFeedback/429_enables_limiter138=== RUN TestRateLimiterFeedback/503_enables_limiter139=== PAUSE TestRateLimiterFeedback/503_enables_limiter140=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter141=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter142=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter143=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter144=== RUN TestPartSizeForNAR/zero_stays_at_minimum145=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum146=== RUN TestPartSizeForNAR/small_stays_at_minimum147=== PAUSE TestPartSizeForNAR/small_stays_at_minimum148=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum149=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum150=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts151=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts152=== RUN TestPartSizeForNAR/1_TiB153=== PAUSE TestPartSizeForNAR/1_TiB154=== RUN TestPartSizeForNAR/5_TiB_S3_max_object155=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object156=== RUN TestPartSizeForNAR/capped_at_5_GiB157=== PAUSE TestPartSizeForNAR/capped_at_5_GiB158=== CONT TestEncodeNixBase32159=== RUN TestEncodeNixBase32/test_string_hash160=== PAUSE TestEncodeNixBase32/test_string_hash161=== CONT TestSetClientTLSDoesNotMutateDefaultTransport162=== RUN TestEncodeNixBase32/empty_input163--- PASS: TestResolveStorePath (0.00s)164=== CONT TestScriptTokenEmptyToken165=== RUN TestGetStorePathHash/basename_without_hyphen_should_error166=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive167=== CONT TestScriptTokenCachesUntilRefresh168=== RUN TestConvertHashToNix32/already_Nix32_format169=== CONT TestScriptTokenNoExpiryRerunsEveryCall170=== RUN TestParsePathInfoJSON/Nix_format171=== CONT TestStreamPushRequestLine172=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths173=== RUN TestFilterOversizedClosures/no_limit_keeps_everything174=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)175=== PAUSE TestParsePathInfoJSON/Nix_format176=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive177=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error178=== CONT TestSetClientTLS179=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)180=== RUN TestParsePathInfoJSON/Lix_format181=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error182=== PAUSE TestEncodeNixBase32/empty_input183=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything184=== PAUSE TestConvertHashToNix32/already_Nix32_format185=== PAUSE TestParsePathInfoJSON/Lix_format1862026/10/01 07:37:43 WARN Rate limiter enabled after throttle name=server-test rate=51872026/10/01 07:37:43 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:41783188=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped189--- PASS: TestScriptTokenEmptyCommand (0.00s)190--- PASS: TestScriptTokenBadJSON (0.02s)1912026/10/01 07:37:43 WARN Rate limiter backed off name=server-test rate=51922026/10/01 07:37:43 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:417831932026/10/01 07:37:43 ERROR Upload failed error=boom count=1194=== RUN TestPathInfoCACompatibility/new_structured_format_-_text195=== CONT TestCaseHackSuffix196=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths197=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon198=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error199=== RUN TestParsePathInfoJSON/empty_input200=== CONT TestClientSignaturesByStorePath201=== CONT TestFileTokenEmpty202--- PASS: TestScriptTokenEmptyToken (0.01s)203=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped204=== RUN TestFilterOversizedClosures/all_closures_skipped205=== CONT TestStreamPushReportsSignatures206=== PAUSE TestFilterOversizedClosures/all_closures_skipped207=== RUN TestSetClientTLS/rejects_connection_without_client_cert208=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert209=== PAUSE TestParsePathInfoJSON/empty_input210=== RUN TestParsePathInfoJSON/whitespace_only211=== PAUSE TestParsePathInfoJSON/whitespace_only212=== RUN TestParsePathInfoJSON/invalid_JSON213=== PAUSE TestParsePathInfoJSON/invalid_JSON214=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths2152026/10/01 07:37:43 ERROR Upload failed error=boom count=1216=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths217=== CONT TestStreamPushReportsEveryPath218=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon219--- PASS: TestDoServerRequestAttachesToken (0.02s)220=== CONT TestStreamPushIsolatesFailures221=== RUN TestConvertHashToNix32/invalid_format222=== PAUSE TestConvertHashToNix32/invalid_format223=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA224=== CONT TestUploadMultipart_SupersededByPeer/exists2252026/10/01 07:37:43 ERROR Upload failed error="bad path" count=3226=== CONT TestRateLimiterFeedback/429_enables_limiter227=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA228=== RUN TestSetClientTLS/preserves_debug_logging_transport229=== PAUSE TestSetClientTLS/preserves_debug_logging_transport230=== CONT TestFileTokenMissing231=== CONT TestPartSizeForNAR/zero_stays_at_minimum232=== CONT TestUploadMultipart_SupersededByPeer/missing233=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter234=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2352026/10/01 07:37:43 WARN Rate limiter enabled after throttle name=server-test rate=52362026/10/01 07:37:43 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:38955237=== CONT TestRateLimiterFeedback/503_enables_limiter238=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text239=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method240=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method241=== CONT TestStaticToken242=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts2432026/10/01 07:37:43 WARN Rate limiter backed off name=server-test rate=5244=== CONT TestPartSizeForNAR/5_TiB_S3_max_object245=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum246=== CONT TestPartSizeForNAR/small_stays_at_minimum247=== CONT TestFilterOversizedClosures/no_limit_keeps_everything248=== CONT TestPartSizeForNAR/capped_at_5_GiB249=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2502026/10/01 07:37:43 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000251=== CONT TestParsePathInfoJSON/Nix_format252=== CONT TestParsePathInfoJSON/invalid_JSON253=== CONT TestParsePathInfoJSON/whitespace_only254=== CONT TestParsePathInfoJSON/Lix_format255=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths256=== CONT TestEncodeNixBase32/empty_input257=== CONT TestConvertHashToNix32/SRI_format_to_Nix32258=== CONT TestConvertHashToNix32/already_Nix32_format259=== CONT TestSetClientTLS/rejects_connection_without_client_cert2602026/10/01 07:37:43 WARN Rate limiter enabled after throttle name=server-test rate=52612026/10/01 07:37:43 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:35757262=== CONT TestParsePathInfoJSON/empty_input263=== CONT TestPartSizeForNAR/1_TiB264=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA2652026/10/01 07:37:43 WARN Rate limiter backed off name=server-test rate=5266=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths267=== CONT TestPathInfoCACompatibility/null_ca_field268=== CONT TestPathInfoCACompatibility/new_structured_format_-_text269=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive270=== CONT TestPathInfoCACompatibility/old_string_format_-_text271=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method272=== CONT TestStreamPushGivesUpOnDeadServer273=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error274=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error275=== CONT TestGetStorePathHash/valid_store_path276=== CONT TestShellSplitErrors2772026/10/01 07:37:43 ERROR Upload failed error="connection refused" count=20278=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error2792026/10/01 07:37:43 ERROR Server seems unavailable, giving up on batch untried=17280=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI281=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI282=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512283=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512284=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)285=== CONT TestStreamPushBatchesUnderLoad286=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512287=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon288=== CONT TestFileTokenReadsAndCaches289=== RUN TestSetClientTLSErrors/missing_cert_file290=== PAUSE TestSetClientTLSErrors/missing_cert_file291=== CONT TestFilterOversizedClosures/all_closures_skipped2922026/10/01 07:37:43 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50293=== CONT TestEncodeNixBase32/test_string_hash294=== CONT TestConvertHashToNix32/invalid_format295=== CONT TestSetClientTLS/preserves_debug_logging_transport296=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error297=== CONT TestGetStorePathHash/basename_without_hyphen_should_error298=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI299--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.05s)300--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.04s)301--- PASS: TestStreamPushReportsSignatures (0.00s)302--- PASS: TestClientSignaturesByStorePath (0.00s)303--- PASS: TestStreamPushReportsEveryPath (0.00s)304--- PASS: TestStreamPushIsolatesFailures (0.00s)305=== RUN TestSetClientTLSErrors/missing_key_file306=== PAUSE TestSetClientTLSErrors/missing_key_file307=== RUN TestSetClientTLSErrors/missing_ca_file308=== PAUSE TestSetClientTLSErrors/missing_ca_file309=== RUN TestSetClientTLSErrors/invalid_ca_file310=== PAUSE TestSetClientTLSErrors/invalid_ca_file311=== CONT TestSetClientTLSErrors/missing_cert_file312=== CONT TestSetClientTLSErrors/invalid_ca_file313--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)314--- PASS: TestFileTokenEmpty (0.00s)315--- PASS: TestFileTokenMissing (0.00s)316--- PASS: TestStaticToken (0.00s)317=== CONT TestSetClientTLSErrors/missing_ca_file318--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)319 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)320 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)321--- PASS: TestParsePathInfoJSON (0.05s)322 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)323 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)324 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)325 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)326 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)327--- PASS: TestShellSplitErrors (0.00s)328--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)329=== CONT TestSetClientTLSErrors/missing_key_file330--- PASS: TestFileTokenReadsAndCaches (0.00s)331--- PASS: TestDumpPathSingleFile (0.05s)332--- PASS: TestGetStorePathHash (0.05s)333 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)334 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)335 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)336 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)337--- PASS: TestPartSizeForNAR (0.00s)338 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)339 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)340 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (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: TestParsePathInfoJSONMultiplePaths (0.05s)346 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)347 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)348--- PASS: TestRateLimiterFeedback (0.00s)349 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)350 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)351 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)352 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)353--- PASS: TestPathInfoCACompatibility (0.05s)354 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)355 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)356 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)357 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)358 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)359--- PASS: TestFilterOversizedClosures (0.04s)360 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)361 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)362 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)363--- PASS: TestEncodeNixBase32 (0.01s)364 --- PASS: TestEncodeNixBase32/empty_input (0.00s)365 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)366--- PASS: TestConvertHashToNix32 (0.04s)367 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)368 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)369 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)370--- PASS: TestPathInfoHashCompatibility (0.05s)371 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)372 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)373 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)374 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)375--- PASS: TestSetClientTLSErrors (0.05s)376 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)377 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)378 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)379 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)3802026/10/01 07:37:43 http: TLS handshake error from 127.0.0.1:56192: remote error: tls: bad certificate381--- PASS: TestSetClientTLS (0.03s)382 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)383 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)384 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)385--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)386--- PASS: TestStreamPushRequestLine (0.05s)387--- PASS: TestRegisterUploadedObjectReusesConnections (0.07s)388--- PASS: TestCaseHackSuffix (0.04s)389--- PASS: TestDumpPathWriterError (0.08s)390--- PASS: TestDumpPathMatchesNix (0.12s)391--- PASS: TestStreamPushBatchesUnderLoad (0.10s)392--- PASS: TestUploadMultipart_PartsInParallel (0.66s)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/postgres499005586/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/postgres499005586/data -l logfile start422423/build/postgres499005586:5432 - no response4242026-10-01 07:37:45.477 UTC [129] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 07:37:45.478 UTC [129] LOG: listening on Unix socket "/build/postgres499005586/.s.PGSQL.5432"4262026-10-01 07:37:45.488 UTC [136] LOG: database system was shut down at 2026-10-01 07:37:45 UTC4272026-10-01 07:37:45.491 UTC [129] LOG: database system is ready to accept connections428/build/postgres499005586:5432 - accepting connections429{"timestamp":"2026-10-01T07:37:45.783849459Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"735d8560-344d-430d-b2ec-2454f7eaddac","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(394)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestResolveDBConnectionString467=== PAUSE TestResolveDBConnectionString468=== RUN TestLeadElectsOneAndHandsOver469=== PAUSE TestLeadElectsOneAndHandsOver470=== RUN TestLeadIncumbentWinsAfterRestart4712026-10-01 07:37:45.974 UTC [566] ERROR: relation "goose_db_version" does not exist at character 364722026-10-01 07:37:45.974 UTC [566] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4732026/10/01 07:37:45 OK 20241026095416_initial_model.sql (7.33ms)4742026/10/01 07:37:45 OK 20251210153512_drop_unused_gin_index.sql (1.04ms)4752026/10/01 07:37:45 OK 20251218171726_add_pins.sql (1.91ms)4762026/10/01 07:37:45 OK 20260628120000_add_object_size_and_stats.sql (1.77ms)4772026/10/01 07:37:45 OK 20260905000000_add_claims.sql (2.07ms)4782026/10/01 07:37:45 OK 20260920000000_drop_claims.sql (1.28ms)4792026/10/01 07:37:45 OK 20260923120000_add_pushes.sql (1.12ms)4802026/10/01 07:37:45 goose: successfully migrated database to version: 202609231200004812026/10/01 07:37:46 OK 1_commit_pending_closure.sql (1.32ms)4822026/10/01 07:37:46 OK 2_object_stats_trigger.sql (626.84µs)4832026/10/01 07:37:46 OK 3_commit_push.sql (559.31µs)4842026/10/01 07:37:46 goose: up to current file version: 34852026/10/01 07:37:46 INFO lead: acquired remote=192.0.2.1:12344862026/10/01 07:37:46 INFO lead: released remote=192.0.2.1:12344872026/10/01 07:37:46 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 07:37:46 INFO lead: released remote=192.0.2.1:1234489--- PASS: TestLeadIncumbentWinsAfterRestart (0.79s)490=== RUN TestLeadEndsOnShutdown491=== PAUSE TestLeadEndsOnShutdown492=== RUN TestGCAdvisoryLockBlocksConcurrentRun4932026-10-01 07:37:46.750 UTC [577] ERROR: relation "goose_db_version" does not exist at character 364942026-10-01 07:37:46.750 UTC [577] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4952026/10/01 07:37:46 OK 20241026095416_initial_model.sql (6.73ms)4962026/10/01 07:37:46 OK 20251210153512_drop_unused_gin_index.sql (865.86µs)4972026/10/01 07:37:46 OK 20251218171726_add_pins.sql (2.66ms)4982026/10/01 07:37:46 OK 20260628120000_add_object_size_and_stats.sql (2.55ms)4992026/10/01 07:37:46 OK 20260905000000_add_claims.sql (2.03ms)5002026/10/01 07:37:46 OK 20260920000000_drop_claims.sql (1.38ms)5012026/10/01 07:37:46 OK 20260923120000_add_pushes.sql (945.68µs)5022026/10/01 07:37:46 goose: successfully migrated database to version: 202609231200005032026/10/01 07:37:46 OK 1_commit_pending_closure.sql (1.27ms)5042026/10/01 07:37:46 OK 2_object_stats_trigger.sql (594.75µs)5052026/10/01 07:37:46 OK 3_commit_push.sql (608.21µs)5062026/10/01 07:37:46 goose: up to current file version: 3507--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.12s)508=== RUN TestGCBugBareHashReferences509=== PAUSE TestGCBugBareHashReferences510=== RUN TestGCMetrics511=== PAUSE TestGCMetrics512=== RUN TestPushDedupSurvivesConcurrentGC513=== PAUSE TestPushDedupSurvivesConcurrentGC514=== RUN TestDeduplicatedObjectsRecordedAsPending515=== PAUSE TestDeduplicatedObjectsRecordedAsPending516=== RUN TestGCSweepSkipsPendingObjects517=== PAUSE TestGCSweepSkipsPendingObjects518=== RUN TestTombstonedObjectOfferedWithoutWaiting519=== PAUSE TestTombstonedObjectOfferedWithoutWaiting520=== RUN TestGCSweepDeliversEachKeyOnce521=== PAUSE TestGCSweepDeliversEachKeyOnce522=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection524=== RUN TestGCTaskStore_StartNew525=== PAUSE TestGCTaskStore_StartNew526=== RUN TestGCTaskStore_DeduplicateSameParams527=== PAUSE TestGCTaskStore_DeduplicateSameParams528=== RUN TestGCTaskStore_ConflictDifferentParams529=== PAUSE TestGCTaskStore_ConflictDifferentParams530=== RUN TestGCTaskStore_GetEmpty531=== PAUSE TestGCTaskStore_GetEmpty532=== RUN TestGCTaskStore_GetReturnsLatest533=== PAUSE TestGCTaskStore_GetReturnsLatest534=== RUN TestGCTaskStore_CompletedAllowsNewTask535=== PAUSE TestGCTaskStore_CompletedAllowsNewTask536=== RUN TestGCTaskStore_PhaseUpdates537=== PAUSE TestGCTaskStore_PhaseUpdates538=== RUN TestGCTaskStore_Fail539=== PAUSE TestGCTaskStore_Fail540=== RUN TestGracefulShutdownDrainsInflight541=== PAUSE TestGracefulShutdownDrainsInflight542=== RUN TestService_healthCheckHandler543=== PAUSE TestService_healthCheckHandler544=== RUN TestService_readinessHandler545=== PAUSE TestService_readinessHandler546=== RUN TestGenerateLandingPage547=== PAUSE TestGenerateLandingPage548=== RUN TestCacheConfigHandlerMaxNarSize549=== PAUSE TestCacheConfigHandlerMaxNarSize550=== RUN TestCreatePendingClosureRejectsOversizedNAR551=== PAUSE TestCreatePendingClosureRejectsOversizedNAR552=== RUN TestNARDeduplicationMetadataUploadBug553=== PAUSE TestNARDeduplicationMetadataUploadBug554=== RUN TestMetricsInventory555=== PAUSE TestMetricsInventory556=== RUN TestService_NativeMTLS557=== PAUSE TestService_NativeMTLS558=== RUN TestServerTLSConfig559=== PAUSE TestServerTLSConfig560=== RUN TestMultipartCleanup561=== PAUSE TestMultipartCleanup562=== RUN TestObjectStatsTrigger563=== PAUSE TestObjectStatsTrigger564=== RUN TestOrphanedObjectsGC565=== PAUSE TestOrphanedObjectsGC566=== RUN TestOrphanedObjectsGCStressTest567=== PAUSE TestOrphanedObjectsGCStressTest568=== RUN TestResurrectedObjectNotDeleted569=== PAUSE TestResurrectedObjectNotDeleted570=== RUN TestCreatePin_ReservedPins571=== PAUSE TestCreatePin_ReservedPins572=== RUN TestParseSingleRange573=== PAUSE TestParseSingleRange574=== RUN TestProxyHeadersOnlyTrustedOnSocket575=== PAUSE TestProxyHeadersOnlyTrustedOnSocket576=== RUN TestIsValidCachePath577=== PAUSE TestIsValidCachePath578=== RUN TestReadProxyNarinfo579=== PAUSE TestReadProxyNarinfo580=== RUN TestReadProxyNarinfoAlreadyDecompressed581=== PAUSE TestReadProxyNarinfoAlreadyDecompressed582=== RUN TestReadProxyNarStreaming583=== PAUSE TestReadProxyNarStreaming584=== RUN TestReadProxy404585=== PAUSE TestReadProxy404586=== RUN TestReadProxyInvalidPath587=== PAUSE TestReadProxyInvalidPath588=== RUN TestReadProxyHead589=== PAUSE TestReadProxyHead590=== RUN TestReadProxyConditionalGet591=== PAUSE TestReadProxyConditionalGet592=== RUN TestReadProxyRootRedirectsToIndexHTML593=== PAUSE TestReadProxyRootRedirectsToIndexHTML594=== RUN TestReadProxyDisabled595=== PAUSE TestReadProxyDisabled596=== RUN TestReadRedirectNar597=== PAUSE TestReadRedirectNar598=== RUN TestReadRedirectKeepsNarinfoProxied599=== PAUSE TestReadRedirectKeepsNarinfoProxied600=== RUN TestReadProxyRangeRequest601=== PAUSE TestReadProxyRangeRequest602=== RUN TestReadRedirectUsesPublicS3URL603=== PAUSE TestReadRedirectUsesPublicS3URL604=== RUN TestPush_OverlappingRootsStoreOneRowPerKey605=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey606=== RUN TestPush_CompleteCommitsEveryRoot607=== PAUSE TestPush_CompleteCommitsEveryRoot608=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit609=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit610=== RUN TestPush_RejectsBadRequests611=== PAUSE TestPush_RejectsBadRequests612=== RUN TestPush_SignsNarinfosOfItsPendingObjects613=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects614=== RUN TestRedundantMultipartUpload615=== PAUSE TestRedundantMultipartUpload616=== RUN TestCompleteMultipartUpload_ErrorButObjectExists617=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists618=== RUN TestCompletedNarNotReofferedAcrossClosures619=== PAUSE TestCompletedNarNotReofferedAcrossClosures620=== RUN TestPresignedUploadRegisteredBeforeCommit621=== PAUSE TestPresignedUploadRegisteredBeforeCommit622=== RUN TestService_Rustfstest623=== PAUSE TestService_Rustfstest624=== RUN TestParseSize625=== PAUSE TestParseSize626=== RUN TestSkippedUploadsHandler627=== PAUSE TestSkippedUploadsHandler628=== RUN TestSystemdListenerNotActivated629--- PASS: TestSystemdListenerNotActivated (0.00s)630=== RUN TestWatchdogBeatsWhenHealthy631--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)632=== RUN TestWatchdogSkipsWhenUnhealthy6332026/10/01 07:37:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6342026/10/01 07:37:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6352026/10/01 07:37:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6362026/10/01 07:37:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6372026/10/01 07:37:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6382026/10/01 07:37:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6392026/10/01 07:37:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6402026/10/01 07:37:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6412026/10/01 07:37:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6422026/10/01 07:37:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"643--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)644=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle645=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle646=== RUN TestProxyWriteTimeout647=== PAUSE TestProxyWriteTimeout648=== RUN TestIsValidUploadKey649=== PAUSE TestIsValidUploadKey650=== RUN TestUploadHandlersRejectInvalidKeys651=== PAUSE TestUploadHandlersRejectInvalidKeys652=== RUN TestUploadHandlersRejectOversizedBody653=== PAUSE TestUploadHandlersRejectOversizedBody654=== RUN TestService_cleanupPendingClosuresHandler655=== PAUSE TestService_cleanupPendingClosuresHandler656=== RUN TestService_createPendingClosureHandler657=== PAUSE TestService_createPendingClosureHandler658=== RUN TestService_verifyS3Integrity659=== PAUSE TestService_verifyS3Integrity660=== RUN TestCompleteMultipartUnregistered661=== PAUSE TestCompleteMultipartUnregistered662=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT663=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT664=== CONT TestService_AuthMiddleware665=== CONT TestServerTLSConfig666=== CONT TestPush_OverlappingRootsStoreOneRowPerKey667=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT668=== CONT TestCompleteMultipartUnregistered669=== CONT TestService_verifyS3Integrity670=== CONT TestService_createPendingClosureHandler671=== CONT TestService_cleanupPendingClosuresHandler672=== CONT TestUploadHandlersRejectOversizedBody673=== CONT TestUploadHandlersRejectInvalidKeys674=== CONT TestIsValidUploadKey675=== CONT TestProxyWriteTimeout676=== RUN TestProxyWriteTimeout/narinfo677=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle678=== CONT TestSkippedUploadsHandler679=== CONT TestParseSize680=== CONT TestService_Rustfstest681=== CONT TestPresignedUploadRegisteredBeforeCommit682=== CONT TestCompletedNarNotReofferedAcrossClosures683=== CONT TestCompleteMultipartUpload_ErrorButObjectExists684=== CONT TestRedundantMultipartUpload685=== CONT TestPush_SignsNarinfosOfItsPendingObjects686=== CONT TestPush_RejectsBadRequests687=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit688=== CONT TestPush_CompleteCommitsEveryRoot689=== RUN TestServerTLSConfig/no_client_CA690=== RUN TestIsValidUploadKey/narinfo691=== PAUSE TestIsValidUploadKey/narinfo692=== RUN TestIsValidUploadKey/nar_zst693=== PAUSE TestIsValidUploadKey/nar_zst6942026/10/01 07:37:47 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000695=== RUN TestIsValidUploadKey/nar_xz696=== PAUSE TestIsValidUploadKey/nar_xz697=== RUN TestIsValidUploadKey/nar_plain698=== PAUSE TestIsValidUploadKey/nar_plain699=== RUN TestIsValidUploadKey/listing700=== PAUSE TestIsValidUploadKey/listing701=== RUN TestIsValidUploadKey/build_log702=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info703=== PAUSE TestProxyWriteTimeout/narinfo704=== RUN TestProxyWriteTimeout/1_GiB_nar705--- PASS: TestParseSize (0.00s)706=== CONT TestReadProxyNarStreaming707--- PASS: TestSkippedUploadsHandler (0.01s)708=== CONT TestReadRedirectUsesPublicS3URL709=== PAUSE TestIsValidUploadKey/build_log710=== PAUSE TestProxyWriteTimeout/1_GiB_nar711=== RUN TestProxyWriteTimeout/10_GiB_nar712=== PAUSE TestProxyWriteTimeout/10_GiB_nar713=== RUN TestProxyWriteTimeout/unknown_size714=== PAUSE TestProxyWriteTimeout/unknown_size715=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info716=== PAUSE TestServerTLSConfig/no_client_CA717=== RUN TestIsValidUploadKey/build_log_home-manager_file718=== PAUSE TestIsValidUploadKey/build_log_home-manager_file719=== CONT TestReadProxyRangeRequest720=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal721=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal722=== RUN TestServerTLSConfig/missing_CA_file723=== RUN TestIsValidUploadKey/build_log_plus_in_name724=== PAUSE TestServerTLSConfig/missing_CA_file725=== RUN TestServerTLSConfig/not_a_PEM_file726=== PAUSE TestServerTLSConfig/not_a_PEM_file727=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key728=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key729=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key730=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key731=== PAUSE TestIsValidUploadKey/build_log_plus_in_name732=== RUN TestIsValidUploadKey/build_log_question_mark733=== PAUSE TestIsValidUploadKey/build_log_question_mark734=== RUN TestIsValidUploadKey/build_log_equals735=== PAUSE TestIsValidUploadKey/build_log_equals736=== RUN TestIsValidUploadKey/realisation737=== PAUSE TestIsValidUploadKey/realisation738=== CONT TestReadRedirectKeepsNarinfoProxied739=== CONT TestReadRedirectNar740=== RUN TestIsValidUploadKey/realisation_plus_in_output741=== PAUSE TestIsValidUploadKey/realisation_plus_in_output742=== RUN TestIsValidUploadKey/nix-cache-info743=== PAUSE TestIsValidUploadKey/nix-cache-info744=== RUN TestIsValidUploadKey/index.html745=== PAUSE TestIsValidUploadKey/index.html746=== RUN TestIsValidUploadKey/narinfo_key,_nar_type747=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type748=== RUN TestIsValidUploadKey/nar_key,_narinfo_type749=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type750=== RUN TestIsValidUploadKey/listing_key,_narinfo_type751=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type752=== RUN TestIsValidUploadKey/traversal753=== PAUSE TestIsValidUploadKey/traversal754=== RUN TestIsValidUploadKey/traversal_nar755=== PAUSE TestIsValidUploadKey/traversal_nar756=== RUN TestIsValidUploadKey/absolute757=== PAUSE TestIsValidUploadKey/absolute758=== RUN TestIsValidUploadKey/empty_key759=== PAUSE TestIsValidUploadKey/empty_key760=== RUN TestIsValidUploadKey/unknown_type761=== PAUSE TestIsValidUploadKey/unknown_type762=== CONT TestReadProxyDisabled763=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure764=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure765=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart766=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart767=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts768=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts769=== CONT TestReadProxyRootRedirectsToIndexHTML7702026-10-01 07:37:47.286 UTC [643] ERROR: relation "goose_db_version" does not exist at character 367712026-10-01 07:37:47.286 UTC [643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7722026-10-01 07:37:47.382 UTC [644] ERROR: relation "goose_db_version" does not exist at character 367732026-10-01 07:37:47.382 UTC [644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7742026/10/01 07:37:47 OK 20241026095416_initial_model.sql (28.84ms)7752026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (3.46ms)7762026/10/01 07:37:47 OK 20251218171726_add_pins.sql (4.59ms)7772026-10-01 07:37:47.402 UTC [645] ERROR: relation "goose_db_version" does not exist at character 367782026-10-01 07:37:47.402 UTC [645] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7792026-10-01 07:37:47.408 UTC [646] ERROR: relation "goose_db_version" does not exist at character 367802026-10-01 07:37:47.408 UTC [646] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7812026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (17.86ms)7822026/10/01 07:37:47 OK 20260905000000_add_claims.sql (7.64ms)7832026/10/01 07:37:47 OK 20241026095416_initial_model.sql (30.09ms)7842026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (4.31ms)7852026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.88ms)7862026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (3.3ms)7872026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200007882026-10-01 07:37:47.437 UTC [647] ERROR: relation "goose_db_version" does not exist at character 367892026-10-01 07:37:47.437 UTC [647] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7902026-10-01 07:37:47.441 UTC [648] ERROR: relation "goose_db_version" does not exist at character 367912026-10-01 07:37:47.441 UTC [648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7922026-10-01 07:37:47.443 UTC [649] ERROR: relation "goose_db_version" does not exist at character 367932026-10-01 07:37:47.443 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7942026-10-01 07:37:47.446 UTC [650] ERROR: relation "goose_db_version" does not exist at character 367952026-10-01 07:37:47.446 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7962026/10/01 07:37:47 OK 20251218171726_add_pins.sql (17.27ms)7972026/10/01 07:37:47 OK 1_commit_pending_closure.sql (18.26ms)7982026/10/01 07:37:47 OK 20241026095416_initial_model.sql (20.38ms)7992026/10/01 07:37:47 OK 20241026095416_initial_model.sql (31.85ms)8002026/10/01 07:37:47 OK 2_object_stats_trigger.sql (3.13ms)8012026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (4.55ms)8022026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (4.41ms)8032026/10/01 07:37:47 OK 3_commit_push.sql (3.53ms)8042026/10/01 07:37:47 goose: up to current file version: 38052026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (11.06ms)8062026/10/01 07:37:47 OK 20251218171726_add_pins.sql (5.62ms)8072026/10/01 07:37:47 OK 20251218171726_add_pins.sql (7.09ms)8082026/10/01 07:37:47 OK 20260905000000_add_claims.sql (6.27ms)8092026-10-01 07:37:47.469 UTC [651] ERROR: relation "goose_db_version" does not exist at character 368102026-10-01 07:37:47.469 UTC [651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8112026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (4.68ms)8122026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (8.8ms)8132026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (8.36ms)8142026/10/01 07:37:47 OK 20241026095416_initial_model.sql (18.91ms)8152026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (4.52ms)8162026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200008172026/10/01 07:37:47 OK 20260905000000_add_claims.sql (4.69ms)8182026-10-01 07:37:47.481 UTC [653] ERROR: relation "goose_db_version" does not exist at character 368192026-10-01 07:37:47.481 UTC [653] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8202026/10/01 07:37:47 OK 20241026095416_initial_model.sql (17.13ms)8212026-10-01 07:37:47.482 UTC [654] ERROR: relation "goose_db_version" does not exist at character 368222026-10-01 07:37:47.482 UTC [654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8232026/10/01 07:37:47 OK 20260905000000_add_claims.sql (5.23ms)8242026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (3.84ms)8252026/10/01 07:37:47 OK 1_commit_pending_closure.sql (5.78ms)8262026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (4.8ms)8272026/10/01 07:37:47 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"828--- PASS: TestService_AuthMiddleware (0.45s)829=== CONT TestReadProxyConditionalGet8302026-10-01 07:37:47.492 UTC [655] ERROR: relation "goose_db_version" does not exist at character 368312026-10-01 07:37:47.492 UTC [655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8322026-10-01 07:37:47.493 UTC [657] ERROR: relation "goose_db_version" does not exist at character 368332026-10-01 07:37:47.493 UTC [657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8342026/10/01 07:37:47 OK 20241026095416_initial_model.sql (28.31ms)8352026/10/01 07:37:47 OK 2_object_stats_trigger.sql (15.87ms)8362026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (16.03ms)8372026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200008382026/10/01 07:37:47 OK 20251218171726_add_pins.sql (15.83ms)8392026/10/01 07:37:47 OK 20241026095416_initial_model.sql (31.43ms)8402026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (16.48ms)8412026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (17.06ms)8422026/10/01 07:37:47 OK 3_commit_push.sql (1.84ms)8432026/10/01 07:37:47 goose: up to current file version: 38442026/10/01 07:37:47 OK 20241026095416_initial_model.sql (18.03ms)8452026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (6.75ms)8462026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (3.38ms)8472026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200008482026/10/01 07:37:47 OK 1_commit_pending_closure.sql (4.43ms)8492026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (3.73ms)8502026/10/01 07:37:47 OK 20251218171726_add_pins.sql (5.35ms)8512026/10/01 07:37:47 OK 2_object_stats_trigger.sql (2.44ms)8522026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (6.9ms)8532026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (4.03ms)8542026/10/01 07:37:47 OK 20251218171726_add_pins.sql (5.04ms)8552026/10/01 07:37:47 OK 1_commit_pending_closure.sql (3.97ms)8562026/10/01 07:37:47 OK 3_commit_push.sql (2.44ms)8572026/10/01 07:37:47 goose: up to current file version: 38582026/10/01 07:37:47 OK 2_object_stats_trigger.sql (2.23ms)8592026/10/01 07:37:47 OK 20251218171726_add_pins.sql (7.42ms)8602026/10/01 07:37:47 OK 20251218171726_add_pins.sql (5.88ms)8612026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (7.28ms)8622026/10/01 07:37:47 OK 3_commit_push.sql (2.29ms)8632026/10/01 07:37:47 goose: up to current file version: 38642026/10/01 07:37:47 OK 20260905000000_add_claims.sql (6.07ms)8652026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (5.65ms)8662026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (4.12ms)8672026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.8ms)8682026/10/01 07:37:47 OK 20241026095416_initial_model.sql (16.41ms)8692026/10/01 07:37:47 OK 20241026095416_initial_model.sql (14.53ms)8702026/10/01 07:37:47 OK 20241026095416_initial_model.sql (17.01ms)8712026/10/01 07:37:47 OK 20260905000000_add_claims.sql (5.52ms)8722026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (6.57ms)8732026-10-01 07:37:47.520 UTC [662] ERROR: relation "goose_db_version" does not exist at character 368742026-10-01 07:37:47.520 UTC [662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8752026/10/01 07:37:47 OK 20241026095416_initial_model.sql (12.23ms)8762026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (5.95ms)8772026-10-01 07:37:47.521 UTC [659] ERROR: relation "goose_db_version" does not exist at character 368782026-10-01 07:37:47.521 UTC [659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8792026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2ms)8802026-10-01 07:37:47.521 UTC [664] ERROR: relation "goose_db_version" does not exist at character 368812026-10-01 07:37:47.521 UTC [664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8822026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)8832026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.86ms)8842026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200008852026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (1.88ms)8862026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.7ms)8872026-10-01 07:37:47.522 UTC [663] ERROR: relation "goose_db_version" does not exist at character 368882026-10-01 07:37:47.522 UTC [663] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8892026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.8ms)8902026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (3.18ms)8912026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.06ms)8922026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.52ms)8932026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.36ms)8942026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200008952026-10-01 07:37:47.524 UTC [665] ERROR: relation "goose_db_version" does not exist at character 368962026-10-01 07:37:47.524 UTC [665] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8972026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.18ms)8982026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200008992026/10/01 07:37:47 OK 20251218171726_add_pins.sql (3.66ms)9002026/10/01 07:37:47 OK 1_commit_pending_closure.sql (3.27ms)9012026/10/01 07:37:47 OK 20251218171726_add_pins.sql (3.15ms)9022026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.22ms)9032026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.22ms)9042026/10/01 07:37:47 INFO Received push request method=POST path=/api/pushes9052026/10/01 07:37:47 OK 20251218171726_add_pins.sql (3.85ms)9062026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.46ms)9072026/10/01 07:37:47 OK 20251218171726_add_pins.sql (4.21ms)9082026-10-01 07:37:47.527 UTC [666] ERROR: relation "goose_db_version" does not exist at character 369092026-10-01 07:37:47.527 UTC [666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9102026/10/01 07:37:47 OK 1_commit_pending_closure.sql (4.04ms)9112026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (1.97ms)9122026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200009132026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.72ms)9142026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (1.9ms)9152026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200009162026/10/01 07:37:47 OK 3_commit_push.sql (1.29ms)9172026/10/01 07:37:47 goose: up to current file version: 39182026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.14ms)9192026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (3.88ms)9202026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.71ms)9212026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (4.05ms)9222026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.67ms)9232026-10-01 07:37:47.531 UTC [667] ERROR: relation "goose_db_version" does not exist at character 369242026-10-01 07:37:47.531 UTC [667] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9252026/10/01 07:37:47 OK 3_commit_push.sql (1.42ms)9262026/10/01 07:37:47 goose: up to current file version: 39272026/10/01 07:37:47 OK 3_commit_push.sql (1.96ms)9282026/10/01 07:37:47 goose: up to current file version: 39292026/10/01 07:37:47 OK 1_commit_pending_closure.sql (3.14ms)9302026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (4.53ms)9312026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (4.26ms)9322026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.15ms)9332026/10/01 07:37:47 OK 20260905000000_add_claims.sql (2.44ms)9342026/10/01 07:37:47 OK 20260905000000_add_claims.sql (2.53ms)9352026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.34ms)9362026/10/01 07:37:47 OK 3_commit_push.sql (1.54ms)9372026/10/01 07:37:47 goose: up to current file version: 39382026/10/01 07:37:47 OK 3_commit_push.sql (1.32ms)9392026/10/01 07:37:47 goose: up to current file version: 39402026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.75ms)9412026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.55ms)9422026-10-01 07:37:47.535 UTC [668] ERROR: relation "goose_db_version" does not exist at character 369432026-10-01 07:37:47.535 UTC [668] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9442026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.36ms)9452026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.3ms)9462026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.62ms)9472026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200009482026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.48ms)9492026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200009502026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (3.17ms)9512026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (3.4ms)9522026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.91ms)9532026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.72ms)9542026-10-01 07:37:47.541 UTC [669] ERROR: relation "goose_db_version" does not exist at character 369552026-10-01 07:37:47.541 UTC [669] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9562026-10-01 07:37:47.542 UTC [670] ERROR: relation "goose_db_version" does not exist at character 369572026-10-01 07:37:47.542 UTC [670] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9582026/10/01 07:37:47 OK 2_object_stats_trigger.sql (2.19ms)9592026/10/01 07:37:47 OK 2_object_stats_trigger.sql (2.39ms)9602026/10/01 07:37:47 OK 20241026095416_initial_model.sql (12.32ms)9612026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (4.45ms)9622026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200009632026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (4.52ms)9642026/10/01 07:37:47 goose: successfully migrated database to version: 202609231200009652026/10/01 07:37:47 OK 20241026095416_initial_model.sql (11.24ms)9662026/10/01 07:37:47 OK 20241026095416_initial_model.sql (12.23ms)9672026/10/01 07:37:47 OK 3_commit_push.sql (1.36ms)9682026/10/01 07:37:47 goose: up to current file version: 39692026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures9702026/10/01 07:37:47 OK 3_commit_push.sql (2.05ms)9712026/10/01 07:37:47 OK 20241026095416_initial_model.sql (12.56ms)9722026/10/01 07:37:47 OK 20241026095416_initial_model.sql (12.15ms)9732026-10-01 07:37:47.546 UTC [672] ERROR: relation "goose_db_version" does not exist at character 369742026-10-01 07:37:47.546 UTC [672] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9752026/10/01 07:37:47 goose: up to current file version: 39762026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.76ms)9772026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.65ms)9782026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.99ms)9792026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)9802026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.25ms)9812026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (1.74ms)9822026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)9832026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.64ms)9842026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.59ms)985--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.52s)986=== CONT TestReadProxyHead9872026/10/01 07:37:47 OK 20241026095416_initial_model.sql (11.16ms)9882026/10/01 07:37:47 OK 3_commit_push.sql (1.91ms)9892026/10/01 07:37:47 goose: up to current file version: 39902026/10/01 07:37:47 OK 3_commit_push.sql (2.04ms)9912026/10/01 07:37:47 goose: up to current file version: 39922026/10/01 07:37:47 OK 20251218171726_add_pins.sql (4.33ms)9932026/10/01 07:37:47 OK 20251218171726_add_pins.sql (4.38ms)9942026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)9952026/10/01 07:37:47 OK 20251218171726_add_pins.sql (4.44ms)9962026/10/01 07:37:47 OK 20251218171726_add_pins.sql (3.29ms)9972026/10/01 07:37:47 OK 20251218171726_add_pins.sql (4.31ms)9982026/10/01 07:37:47 OK 20241026095416_initial_model.sql (10.76ms)9992026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (4.23ms)10002026/10/01 07:37:47 OK 20251218171726_add_pins.sql (4.18ms)10012026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (4.39ms)10022026/10/01 07:37:47 OK 20241026095416_initial_model.sql (12.39ms)10032026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (5.13ms)10042026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)10052026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (5.96ms)10062026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (5.25ms)10072026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (5.21ms)10082026/10/01 07:37:47 OK 20260905000000_add_claims.sql (5.71ms)10092026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (6.48ms)10102026/10/01 07:37:47 OK 20260905000000_add_claims.sql (6.62ms)10112026/10/01 07:37:47 OK 20251218171726_add_pins.sql (4.91ms)10122026/10/01 07:37:47 OK 20241026095416_initial_model.sql (14.33ms)10132026/10/01 07:37:47 OK 20260905000000_add_claims.sql (5.92ms)10142026/10/01 07:37:47 OK 20241026095416_initial_model.sql (12.23ms)10152026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (1.92ms)10162026/10/01 07:37:47 OK 20260905000000_add_claims.sql (6.46ms)10172026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)10182026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.25ms)10192026/10/01 07:37:47 OK 20260905000000_add_claims.sql (7.53ms)10202026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)10212026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.9ms)10222026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.37ms)10232026/10/01 07:37:47 OK 20251218171726_add_pins.sql (4.17ms)10242026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.06ms)10252026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.19ms)10262026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000010272026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.12ms)10282026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000010292026/10/01 07:37:47 OK 20241026095416_initial_model.sql (13.15ms)10302026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (4.41ms)10312026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (1.56ms)10322026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000010332026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures10342026/10/01 07:37:47 OK 20251218171726_add_pins.sql (2.93ms)10352026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.35ms)10362026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (1.56ms)10372026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000010382026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.11ms)10392026/10/01 07:37:47 OK 1_commit_pending_closure.sql (1.89ms)10402026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (1.23ms)10412026/10/01 07:37:47 OK 1_commit_pending_closure.sql (1.77ms)10422026/10/01 07:37:47 OK 20251218171726_add_pins.sql (3.4ms)10432026/10/01 07:37:47 OK 1_commit_pending_closure.sql (1.86ms)10442026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.05ms)10452026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000010462026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.4ms)10472026/10/01 07:37:47 OK 1_commit_pending_closure.sql (1.85ms)10482026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (1.7ms)10492026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000010502026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (4.03ms)10512026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.4ms)10522026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.02ms)10532026/10/01 07:37:47 OK 2_object_stats_trigger.sql (992.35µs)10542026/10/01 07:37:47 OK 3_commit_push.sql (683.04µs)10552026/10/01 07:37:47 goose: up to current file version: 310562026/10/01 07:37:47 OK 2_object_stats_trigger.sql (866.79µs)10572026/10/01 07:37:47 OK 3_commit_push.sql (927.62µs)10582026/10/01 07:37:47 goose: up to current file version: 310592026/10/01 07:37:47 OK 20251218171726_add_pins.sql (2.75ms)10602026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (3.65ms)10612026/10/01 07:37:47 OK 1_commit_pending_closure.sql (1.76ms)10622026/10/01 07:37:47 OK 3_commit_push.sql (1.33ms)10632026/10/01 07:37:47 goose: up to current file version: 310642026/10/01 07:37:47 OK 3_commit_push.sql (920.8µs)10652026/10/01 07:37:47 goose: up to current file version: 310662026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.32ms)10672026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.06ms)10682026/10/01 07:37:47 OK 20260905000000_add_claims.sql (2.88ms)10692026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.84ms)10702026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.36ms)10712026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (4.77ms)10722026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (1.77ms)10732026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000010742026/10/01 07:37:47 OK 20260905000000_add_claims.sql (2.91ms)10752026/10/01 07:37:47 OK 3_commit_push.sql (1.19ms)10762026/10/01 07:37:47 goose: up to current file version: 310772026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (3.89ms)10782026/10/01 07:37:47 OK 3_commit_push.sql (1.42ms)10792026/10/01 07:37:47 goose: up to current file version: 310802026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.51ms)10812026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.52ms)10822026/10/01 07:37:47 OK 1_commit_pending_closure.sql (3.33ms)10832026/10/01 07:37:47 OK 20260905000000_add_claims.sql (4.09ms)10842026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (3ms)10852026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000010862026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.32ms)10872026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (1.96ms)10882026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000010892026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.98ms)1090--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.55s)1091=== CONT TestReadProxyInvalidPath10922026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.49ms)10932026/10/01 07:37:47 OK 3_commit_push.sql (830.06µs)10942026/10/01 07:37:47 goose: up to current file version: 310952026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.5ms)10962026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.54ms)10972026/10/01 07:37:47 OK 1_commit_pending_closure.sql (1.88ms)10982026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (1.76ms)10992026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000011002026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (1.33ms)11012026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000011022026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.23ms)11032026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.17ms)11042026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures11052026/10/01 07:37:47 OK 3_commit_push.sql (1.06ms)11062026/10/01 07:37:47 goose: up to current file version: 311072026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.03ms)11082026/10/01 07:37:47 OK 1_commit_pending_closure.sql (1.71ms)11092026/10/01 07:37:47 OK 3_commit_push.sql (1.59ms)11102026/10/01 07:37:47 goose: up to current file version: 311112026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.05ms)11122026/10/01 07:37:47 OK 2_object_stats_trigger.sql (2.01ms)11132026/10/01 07:37:47 OK 3_commit_push.sql (1.46ms)11142026/10/01 07:37:47 goose: up to current file version: 311152026/10/01 07:37:47 OK 3_commit_push.sql (1.05ms)11162026/10/01 07:37:47 goose: up to current file version: 311172026/10/01 07:37:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11182026/10/01 07:37:47 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1119--- PASS: TestCompleteMultipartUnregistered (0.58s)1120=== CONT TestReadProxy4041121--- PASS: TestService_Rustfstest (0.59s)1122=== CONT TestPushDedupSurvivesConcurrentGC11232026-10-01 07:37:47.633 UTC [682] ERROR: relation "goose_db_version" does not exist at character 3611242026-10-01 07:37:47.633 UTC [682] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11252026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures11262026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures11272026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures11282026/10/01 07:37:47 OK 20241026095416_initial_model.sql (11.34ms)11292026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (3.35ms)11302026/10/01 07:37:47 OK 20251218171726_add_pins.sql (3.14ms)11312026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (3.6ms)11322026/10/01 07:37:47 INFO Received cleanup request method=DELETE path=/api/pending_closures11332026/10/01 07:37:47 OK 20260905000000_add_claims.sql (2.91ms)11342026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.06ms)11352026/10/01 07:37:47 INFO Aborted multipart uploads count=011362026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.33ms)11372026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000011382026/10/01 07:37:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11392026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures11402026-10-01 07:37:47.671 UTC [684] ERROR: relation "goose_db_version" does not exist at character 3611412026-10-01 07:37:47.671 UTC [684] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11422026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.73ms)11432026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.67ms)11442026/10/01 07:37:47 OK 3_commit_push.sql (1.5ms)11452026/10/01 07:37:47 goose: up to current file version: 311462026/10/01 07:37:47 INFO Received cleanup request method=DELETE path=/api/pending_closures11472026/10/01 07:37:47 INFO Aborted multipart uploads count=111482026/10/01 07:37:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11492026-10-01 07:37:47.686 UTC [649] ERROR: Closure does not exist: id=111502026-10-01 07:37:47.686 UTC [649] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE11512026-10-01 07:37:47.686 UTC [649] STATEMENT: -- name: CommitPendingClosure :exec1152 SELECT commit_pending_closure($1::bigint)1153 1154--- PASS: TestService_cleanupPendingClosuresHandler (0.65s)11552026/10/01 07:37:47 OK 20241026095416_initial_model.sql (9.08ms)1156=== CONT TestService_NativeMTLS11572026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (1.99ms)11582026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures11592026/10/01 07:37:47 OK 20251218171726_add_pins.sql (3.32ms)11602026-10-01 07:37:47.694 UTC [685] ERROR: relation "goose_db_version" does not exist at character 3611612026-10-01 07:37:47.694 UTC [685] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11622026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (4.36ms)11632026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.87ms)11642026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (14.39ms)11652026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (4.12ms)11662026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000011672026/10/01 07:37:47 OK 20241026095416_initial_model.sql (19.2ms)11682026/10/01 07:37:47 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11692026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures11702026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)11712026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.74ms)11722026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures1173--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.69s)1174=== CONT TestMetricsInventory11752026/10/01 07:37:47 OK 2_object_stats_trigger.sql (2.11ms)11762026/10/01 07:37:47 OK 20251218171726_add_pins.sql (3.27ms)11772026/10/01 07:37:47 OK 3_commit_push.sql (753.74µs)11782026/10/01 07:37:47 goose: up to current file version: 311792026-10-01 07:37:47.729 UTC [688] ERROR: relation "goose_db_version" does not exist at character 3611802026-10-01 07:37:47.729 UTC [688] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11812026-10-01 07:37:47.729 UTC [689] ERROR: relation "goose_db_version" does not exist at character 3611822026-10-01 07:37:47.729 UTC [689] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11832026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (3.62ms)11842026/10/01 07:37:47 OK 20260905000000_add_claims.sql (2.84ms)11852026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (1.58ms)11862026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures11872026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.77ms)11882026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000011892026/10/01 07:37:47 OK 1_commit_pending_closure.sql (6.73ms)11902026/10/01 07:37:47 OK 20241026095416_initial_model.sql (11.23ms)11912026/10/01 07:37:47 OK 20241026095416_initial_model.sql (11.19ms)11922026/10/01 07:37:47 OK 2_object_stats_trigger.sql (2.18ms)11932026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.01ms)11942026/10/01 07:37:47 OK 3_commit_push.sql (1.3ms)11952026/10/01 07:37:47 goose: up to current file version: 311962026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (2.1ms)11972026/10/01 07:37:47 OK 20251218171726_add_pins.sql (9.05ms)11982026/10/01 07:37:47 OK 20251218171726_add_pins.sql (11.41ms)11992026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (4.29ms)12002026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (3.92ms)12012026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.05ms)12022026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures12032026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.56ms)12042026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.65ms)12052026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (2.52ms)12062026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (3.1ms)12072026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000012082026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (3.07ms)12092026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000012102026/10/01 07:37:47 OK 1_commit_pending_closure.sql (4.98ms)12112026/10/01 07:37:47 OK 1_commit_pending_closure.sql (4.02ms)12122026/10/01 07:37:47 OK 2_object_stats_trigger.sql (2.6ms)12132026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.99ms)12142026/10/01 07:37:47 OK 3_commit_push.sql (2.13ms)12152026/10/01 07:37:47 goose: up to current file version: 312162026/10/01 07:37:47 OK 3_commit_push.sql (1.74ms)12172026/10/01 07:37:47 goose: up to current file version: 312182026-10-01 07:37:47.798 UTC [692] ERROR: relation "goose_db_version" does not exist at character 3612192026-10-01 07:37:47.798 UTC [692] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12202026/10/01 07:37:47 INFO Received push request method=POST path=/api/pushes12212026/10/01 07:37:47 OK 20241026095416_initial_model.sql (8.28ms)12222026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (4.17ms)12232026/10/01 07:37:47 OK 20251218171726_add_pins.sql (2.36ms)12242026/10/01 07:37:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12252026/10/01 07:37:47 INFO Signed narinfos id=1 count=11226--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.79s)1227=== CONT TestNARDeduplicationMetadataUploadBug12282026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (6.46ms)12292026-10-01 07:37:47.825 UTC [693] ERROR: relation "goose_db_version" does not exist at character 3612302026-10-01 07:37:47.825 UTC [693] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12312026/10/01 07:37:47 OK 20260905000000_add_claims.sql (3.03ms)12322026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (1.86ms)12332026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (1.53ms)12342026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000012352026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.32ms)12362026/10/01 07:37:47 OK 2_object_stats_trigger.sql (809.67µs)12372026/10/01 07:37:47 OK 3_commit_push.sql (935.58µs)12382026/10/01 07:37:47 goose: up to current file version: 312392026/10/01 07:37:47 OK 20241026095416_initial_model.sql (7.9ms)12402026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (1.39ms)12412026/10/01 07:37:47 OK 20251218171726_add_pins.sql (2.22ms)1242--- PASS: TestReadProxyRangeRequest (0.72s)1243=== CONT TestCreatePendingClosureRejectsOversizedNAR12442026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures1245--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1246=== CONT TestCacheConfigHandlerMaxNarSize1247--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1248=== CONT TestGenerateLandingPage1249--- PASS: TestGenerateLandingPage (0.00s)12502026/10/01 07:37:47 OK 20260628120000_add_object_size_and_stats.sql (3.21ms)1251=== CONT TestService_readinessHandler12522026/10/01 07:37:47 OK 20260905000000_add_claims.sql (4.4ms)12532026/10/01 07:37:47 OK 20260920000000_drop_claims.sql (1.48ms)12542026/10/01 07:37:47 OK 20260923120000_add_pushes.sql (2.14ms)12552026/10/01 07:37:47 goose: successfully migrated database to version: 2026092312000012562026/10/01 07:37:47 OK 1_commit_pending_closure.sql (2.24ms)12572026/10/01 07:37:47 OK 2_object_stats_trigger.sql (1.88ms)12582026/10/01 07:37:47 OK 3_commit_push.sql (1.21ms)12592026/10/01 07:37:47 goose: up to current file version: 312602026/10/01 07:37:47 INFO Received uploads request method=POST path=/api/pending_closures12612026/10/01 07:37:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1262--- PASS: TestMetricsInventory (0.18s)1263=== CONT TestService_healthCheckHandler12642026/10/01 07:37:47 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjExMzc5MDEtZjQ2NC00ZTBhLWIwNGEtYWU2NDVhYzI2MTc1LmJjMTg2MDk3LTMyZjItNGQyMC04YWVmLWFhOTFjYmY0MWYwY3gxNzkwODQwMjY3ODczNjcyNjQ412652026/10/01 07:37:47 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjExMzc5MDEtZjQ2NC00ZTBhLWIwNGEtYWU2NDVhYzI2MTc1LmJjMTg2MDk3LTMyZjItNGQyMC04YWVmLWFhOTFjYmY0MWYwY3gxNzkwODQwMjY3ODczNjcyNjQ4 parts=11266--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.91s)1267=== CONT TestGracefulShutdownDrainsInflight12682026/10/01 07:37:47 INFO Starting HTTP server address=127.0.0.1:4058112692026/10/01 07:37:47 INFO Shutdown signal received, draining in-flight requests timeout=10s1270--- PASS: TestReadProxyNarStreaming (0.92s)1271=== CONT TestGCTaskStore_Fail1272--- PASS: TestGCTaskStore_Fail (0.00s)1273=== CONT TestGCTaskStore_PhaseUpdates1274--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1275=== CONT TestGCTaskStore_CompletedAllowsNewTask12762026-10-01 07:37:47.959 UTC [701] ERROR: relation "goose_db_version" does not exist at character 3612772026-10-01 07:37:47.959 UTC [701] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1278--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1279=== CONT TestGCTaskStore_GetReturnsLatest1280--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1281=== CONT TestGCTaskStore_GetEmpty1282--- PASS: TestGCTaskStore_GetEmpty (0.00s)1283=== CONT TestGCTaskStore_ConflictDifferentParams1284--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1285=== CONT TestGCTaskStore_DeduplicateSameParams1286--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1287=== CONT TestGCTaskStore_StartNew1288--- PASS: TestGCTaskStore_StartNew (0.00s)12892026-10-01 07:37:47.960 UTC [702] ERROR: relation "goose_db_version" does not exist at character 3612902026-10-01 07:37:47.960 UTC [702] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1291=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12922026/10/01 07:37:47 OK 20241026095416_initial_model.sql (13.44ms)12932026/10/01 07:37:47 OK 20241026095416_initial_model.sql (19.91ms)12942026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (12.41ms)12952026/10/01 07:37:47 OK 20251210153512_drop_unused_gin_index.sql (9.04ms)12962026/10/01 07:37:47 OK 20251218171726_add_pins.sql (5.37ms)12972026/10/01 07:37:47 OK 20251218171726_add_pins.sql (2.99ms)12982026/10/01 07:37:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12992026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.05ms)13002026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (3.63ms)13012026/10/01 07:37:48 OK 20260905000000_add_claims.sql (3.28ms)13022026/10/01 07:37:48 OK 20260905000000_add_claims.sql (3.24ms)13032026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.25ms)13042026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.73ms)13052026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (1.93ms)13062026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000013072026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.39ms)13082026/10/01 07:37:48 goose: successfully migrated database to version: 202609231200001309--- PASS: TestReadRedirectUsesPublicS3URL (0.97s)1310=== CONT TestGCSweepDeliversEachKeyOnce13112026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.25ms)13122026/10/01 07:37:48 OK 1_commit_pending_closure.sql (1.77ms)13132026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.11ms)13142026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.05ms)13152026/10/01 07:37:48 OK 3_commit_push.sql (1.7ms)13162026/10/01 07:37:48 goose: up to current file version: 313172026/10/01 07:37:48 OK 3_commit_push.sql (2.13ms)13182026/10/01 07:37:48 goose: up to current file version: 31319--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1320=== CONT TestTombstonedObjectOfferedWithoutWaiting13212026-10-01 07:37:48.025 UTC [718] ERROR: relation "goose_db_version" does not exist at character 3613222026-10-01 07:37:48.025 UTC [718] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13232026/10/01 07:37:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YjExMzc5MDEtZjQ2NC00ZTBhLWIwNGEtYWU2NDVhYzI2MTc1LmQxNGI5OTQ0LWE3YmUtNGM3Zi05N2UxLWM0YmNlMWI5NjFkM3gxNzkwODQwMjY3NTU2Nzk1NTU4 parts=1013242026/10/01 07:37:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13252026/10/01 07:37:48 INFO Received push request method=POST path=/api/pushes13262026/10/01 07:37:48 INFO Completed upload id=113272026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures13282026/10/01 07:37:48 OK 20241026095416_initial_model.sql (9.67ms)13292026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures13302026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (2.51ms)13312026/10/01 07:37:48 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo13322026/10/01 07:37:48 WARN Found objects in DB but missing from S3, will re-upload count=11333--- PASS: TestService_verifyS3Integrity (1.01s)1334=== CONT TestGCSweepSkipsPendingObjects13352026/10/01 07:37:48 OK 20251218171726_add_pins.sql (4.12ms)13362026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.64ms)13372026/10/01 07:37:48 OK 20260905000000_add_claims.sql (3.75ms)13382026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.89ms)13392026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.34ms)13402026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000013412026/10/01 07:37:48 INFO Received complete push request method=POST path=/api/pushes/1/complete1342=== RUN TestPush_RejectsBadRequests/no_roots1343=== PAUSE TestPush_RejectsBadRequests/no_roots1344=== RUN TestPush_RejectsBadRequests/no_objects1345=== PAUSE TestPush_RejectsBadRequests/no_objects1346=== RUN TestPush_RejectsBadRequests/bad_root1347=== PAUSE TestPush_RejectsBadRequests/bad_root1348=== RUN TestPush_RejectsBadRequests/root_not_in_objects1349=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1350=== CONT TestClientMultipleUploads13512026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.94ms)13522026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.25ms)13532026/10/01 07:37:48 OK 3_commit_push.sql (1.41ms)13542026/10/01 07:37:48 goose: up to current file version: 31355--- PASS: TestPush_CompleteCommitsEveryRoot (1.05s)1356=== CONT TestDeduplicatedObjectsRecordedAsPending1357--- PASS: TestReadProxyDisabled (0.96s)1358=== CONT TestGCMetrics13592026-10-01 07:37:48.099 UTC [729] ERROR: relation "goose_db_version" does not exist at character 3613602026-10-01 07:37:48.099 UTC [729] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13612026/10/01 07:37:48 INFO Received push request method=POST path=/api/pushes13622026/10/01 07:37:48 OK 20241026095416_initial_model.sql (10.52ms)13632026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)13642026-10-01 07:37:48.121 UTC [732] ERROR: relation "goose_db_version" does not exist at character 3613652026-10-01 07:37:48.121 UTC [732] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13662026/10/01 07:37:48 OK 20251218171726_add_pins.sql (3.54ms)13672026-10-01 07:37:48.126 UTC [733] ERROR: relation "goose_db_version" does not exist at character 3613682026-10-01 07:37:48.126 UTC [733] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13692026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.33ms)13702026/10/01 07:37:48 OK 20260905000000_add_claims.sql (3.19ms)13712026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (5.01ms)13722026/10/01 07:37:48 OK 20241026095416_initial_model.sql (9.71ms)13732026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (4.08ms)13742026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000013752026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (2.85ms)13762026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.11ms)13772026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.52ms)13782026/10/01 07:37:48 OK 20251218171726_add_pins.sql (2.73ms)13792026/10/01 07:37:48 OK 20241026095416_initial_model.sql (9.07ms)13802026/10/01 07:37:48 INFO Received complete push request method=POST path=/api/pushes/1/complete13812026/10/01 07:37:48 OK 3_commit_push.sql (1.29ms)13822026/10/01 07:37:48 goose: up to current file version: 313832026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)13842026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (3.69ms)1385--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.94s)1386=== CONT TestClientFallsBackToClosures13872026/10/01 07:37:48 OK 20251218171726_add_pins.sql (3.62ms)13882026/10/01 07:37:48 OK 20260905000000_add_claims.sql (12.24ms)13892026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (13.77ms)13902026/10/01 07:37:48 INFO Received push request method=POST path=/api/pushes13912026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (5.56ms)13922026/10/01 07:37:48 OK 20260905000000_add_claims.sql (4.19ms)13932026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (3.06ms)13942026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000013952026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.85ms)13962026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.23ms)13972026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.51ms)13982026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000013992026/10/01 07:37:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14002026/10/01 07:37:48 OK 2_object_stats_trigger.sql (3.17ms)14012026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.57ms)14022026-10-01 07:37:48.177 UTC [737] ERROR: relation "goose_db_version" does not exist at character 3614032026-10-01 07:37:48.177 UTC [737] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14042026/10/01 07:37:48 OK 3_commit_push.sql (2.69ms)14052026/10/01 07:37:48 goose: up to current file version: 314062026/10/01 07:37:48 OK 2_object_stats_trigger.sql (2.62ms)1407--- PASS: TestReadRedirectKeepsNarinfoProxied (1.06s)1408=== CONT TestClientPushesUseOnePush14092026/10/01 07:37:48 OK 3_commit_push.sql (1.32ms)14102026/10/01 07:37:48 goose: up to current file version: 314112026/10/01 07:37:48 OK 20241026095416_initial_model.sql (8.3ms)14122026-10-01 07:37:48.192 UTC [740] ERROR: relation "goose_db_version" does not exist at character 3614132026-10-01 07:37:48.192 UTC [740] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14142026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)14152026/10/01 07:37:48 OK 20251218171726_add_pins.sql (4.53ms)14162026/10/01 07:37:48 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YjExMzc5MDEtZjQ2NC00ZTBhLWIwNGEtYWU2NDVhYzI2MTc1LjQ3YTQ5Y2I0LTRhNTItNDQ5Yy05NGExLTE2MTY1OWQ0MDlkNXgxNzkwODQwMjY3NjUzNzIzMjQ5 parts=1014172026-10-01 07:37:48.199 UTC [741] ERROR: relation "goose_db_version" does not exist at character 3614182026-10-01 07:37:48.199 UTC [741] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14192026/10/01 07:37:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14202026-10-01 07:37:48.201 UTC [742] ERROR: relation "goose_db_version" does not exist at character 3614212026-10-01 07:37:48.201 UTC [742] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14222026/10/01 07:37:48 INFO Completed upload id=114232026/10/01 07:37:48 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000014242026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (7.35ms)14252026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures1426--- PASS: TestReadRedirectNar (1.08s)14272026/10/01 07:37:48 INFO Starting cleanup of old closures method=DELETE path=/api/closures1428=== CONT TestGCBugBareHashReferences14292026/10/01 07:37:48 OK 20260905000000_add_claims.sql (4.04ms)14302026/10/01 07:37:48 OK 20241026095416_initial_model.sql (11.77ms)14312026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.85ms)14322026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)14332026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.53ms)14342026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000014352026/10/01 07:37:48 OK 20241026095416_initial_model.sql (10.54ms)14362026/10/01 07:37:48 OK 20251218171726_add_pins.sql (4.22ms)14372026/10/01 07:37:48 OK 1_commit_pending_closure.sql (3.02ms)14382026/10/01 07:37:48 OK 20241026095416_initial_model.sql (10.92ms)14392026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)14402026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.71ms)14412026/10/01 07:37:48 INFO Aborted multipart uploads count=014422026/10/01 07:37:48 OK 2_object_stats_trigger.sql (2.58ms)14432026/10/01 07:37:48 OK 20251218171726_add_pins.sql (3.26ms)14442026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.6ms)14452026/10/01 07:37:48 OK 3_commit_push.sql (1.69ms)14462026/10/01 07:37:48 goose: up to current file version: 314472026/10/01 07:37:48 OK 20251218171726_add_pins.sql (3.38ms)14482026/10/01 07:37:48 INFO Aborted multipart uploads count=014492026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.19ms)14502026/10/01 07:37:48 OK 20260905000000_add_claims.sql (5.24ms)14512026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.08ms)14522026/10/01 07:37:48 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=014532026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.24ms)14542026/10/01 07:37:48 OK 20260905000000_add_claims.sql (3.63ms)14552026/10/01 07:37:48 WARN Force mode enabled - objects will be deleted immediately without grace period14562026/10/01 07:37:48 OK 20260905000000_add_claims.sql (2.88ms)14572026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.19ms)14582026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000014592026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.68ms)14602026/10/01 07:37:48 INFO Vacuumed table table=pending_closures14612026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.64ms)14622026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.66ms)14632026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (3.05ms)14642026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000014652026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (4.25ms)14662026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000014672026/10/01 07:37:48 INFO Vacuumed table table=pending_objects14682026/10/01 07:37:48 OK 2_object_stats_trigger.sql (3.3ms)14692026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.32ms)14702026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.64ms)14712026/10/01 07:37:48 OK 3_commit_push.sql (1.6ms)14722026/10/01 07:37:48 goose: up to current file version: 314732026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.64ms)14742026/10/01 07:37:48 INFO Vacuumed table table=multipart_uploads14752026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.7ms)14762026/10/01 07:37:48 OK 3_commit_push.sql (1.65ms)14772026/10/01 07:37:48 goose: up to current file version: 314782026/10/01 07:37:48 OK 3_commit_push.sql (1.98ms)14792026/10/01 07:37:48 goose: up to current file version: 314802026/10/01 07:37:48 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=014812026/10/01 07:37:48 INFO Vacuumed table table=closures14822026/10/01 07:37:48 INFO Vacuumed table table=objects1483--- PASS: TestReadProxyConditionalGet (0.77s)1484=== CONT TestPinProtectsFromGC14852026/10/01 07:37:48 INFO Vacuumed table table=pending_closures14862026/10/01 07:37:48 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001487--- PASS: TestService_createPendingClosureHandler (1.23s)1488=== CONT TestClientSharedPathCommittedMidPush14892026-10-01 07:37:48.263 UTC [748] ERROR: relation "goose_db_version" does not exist at character 3614902026-10-01 07:37:48.263 UTC [748] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1491--- PASS: TestReadProxyHead (0.72s)1492=== CONT TestLeadEndsOnShutdown14932026/10/01 07:37:48 INFO Vacuumed table table=pending_objects14942026/10/01 07:37:48 INFO Vacuumed table table=multipart_uploads14952026/10/01 07:37:48 INFO Vacuumed table table=closures14962026/10/01 07:37:48 INFO Vacuumed table table=objects14972026/10/01 07:37:48 OK 20241026095416_initial_model.sql (9.56ms)14982026/10/01 07:37:48 INFO Received complete push request method=POST path=/api/pushes/2/complete14992026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (2.7ms)15002026/10/01 07:37:48 OK 20251218171726_add_pins.sql (4.41ms)1501--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.25s)1502=== CONT TestClientWithDependencies1503--- PASS: TestReadProxyInvalidPath (0.71s)1504=== CONT TestLeadElectsOneAndHandsOver15052026-10-01 07:37:48.291 UTC [753] ERROR: relation "goose_db_version" does not exist at character 3615062026-10-01 07:37:48.291 UTC [753] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15072026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.29ms)15082026/10/01 07:37:48 OK 20260905000000_add_claims.sql (4.45ms)15092026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.58ms)15102026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.02ms)15112026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000015122026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.34ms)15132026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.79ms)15142026/10/01 07:37:48 OK 3_commit_push.sql (1.92ms)15152026/10/01 07:37:48 goose: up to current file version: 315162026/10/01 07:37:48 OK 20241026095416_initial_model.sql (10.37ms)15172026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)15182026/10/01 07:37:48 OK 20251218171726_add_pins.sql (3.34ms)15192026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.74ms)15202026-10-01 07:37:48.322 UTC [758] ERROR: relation "goose_db_version" does not exist at character 3615212026-10-01 07:37:48.322 UTC [758] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15222026/10/01 07:37:48 OK 20260905000000_add_claims.sql (4.03ms)15232026/10/01 07:37:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15242026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (4.36ms)15252026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (3.4ms)15262026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000015272026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.53ms)15282026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.68ms)15292026/10/01 07:37:48 OK 3_commit_push.sql (1.26ms)15302026/10/01 07:37:48 goose: up to current file version: 315312026/10/01 07:37:48 OK 20241026095416_initial_model.sql (9.92ms)1532--- PASS: TestReadProxy404 (0.74s)1533=== CONT TestResolveDBConnectionString1534=== RUN TestResolveDBConnectionString/flag_wins1535=== PAUSE TestResolveDBConnectionString/flag_wins1536=== RUN TestResolveDBConnectionString/file_when_flag_empty1537=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1538=== RUN TestResolveDBConnectionString/missing_file_is_an_error1539=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1540=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1541=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1542=== RUN TestResolveDBConnectionString/nothing_configured1543=== PAUSE TestResolveDBConnectionString/nothing_configured1544=== CONT TestService_ReadScope_PublicByDefault15452026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (11.14ms)15462026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures15472026/10/01 07:37:48 OK 20251218171726_add_pins.sql (6.15ms)15482026/10/01 07:37:48 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjExMzc5MDEtZjQ2NC00ZTBhLWIwNGEtYWU2NDVhYzI2MTc1LjdhODZmYTcwLTY3NGQtNGU2Yy1iZDUyLTM0MmFhOWNkYmU1YXgxNzkwODQwMjY3NzMyNDAwMjA1 parts=1215492026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (7.11ms)1550--- PASS: TestRedundantMultipartUpload (1.33s)1551=== CONT TestCreatePin_ReservedPins15522026/10/01 07:37:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15532026/10/01 07:37:48 OK 20260905000000_add_claims.sql (6.07ms)15542026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.89ms)15552026/10/01 07:37:48 WARN mTLS auth: subject not in bound subjects subject="CN=reader"15562026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.67ms)15572026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000015582026/10/01 07:37:48 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1559--- PASS: TestService_NativeMTLS (0.69s)1560=== CONT TestClientIntegration15612026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.97ms)15622026-10-01 07:37:48.380 UTC [761] ERROR: relation "goose_db_version" does not exist at character 3615632026-10-01 07:37:48.380 UTC [761] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15642026/10/01 07:37:48 OK 2_object_stats_trigger.sql (2.26ms)15652026/10/01 07:37:48 OK 3_commit_push.sql (1.58ms)15662026/10/01 07:37:48 goose: up to current file version: 315672026-10-01 07:37:48.389 UTC [764] ERROR: relation "goose_db_version" does not exist at character 3615682026-10-01 07:37:48.389 UTC [764] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15692026-10-01 07:37:48.391 UTC [765] ERROR: relation "goose_db_version" does not exist at character 3615702026-10-01 07:37:48.391 UTC [765] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15712026/10/01 07:37:48 OK 20241026095416_initial_model.sql (9.34ms)15722026/10/01 07:37:48 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YjExMzc5MDEtZjQ2NC00ZTBhLWIwNGEtYWU2NDVhYzI2MTc1LjdmMTNlNmM0LTYyYzMtNDdjZS1hNGZkLWRiZmRhYzExOTY3N3gxNzkwODQwMjY3NzgwNzg0MDY2 parts=1215732026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.58ms)15742026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures1575--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.37s)15762026-10-01 07:37:48.402 UTC [766] ERROR: relation "goose_db_version" does not exist at character 3615772026-10-01 07:37:48.402 UTC [766] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1578=== CONT TestReadProxyNarinfoAlreadyDecompressed15792026/10/01 07:37:48 OK 20251218171726_add_pins.sql (4.3ms)15802026/10/01 07:37:48 OK 20241026095416_initial_model.sql (9.16ms)15812026/10/01 07:37:48 WARN readiness check failed error="closed pool"1582--- PASS: TestService_readinessHandler (0.56s)15832026/10/01 07:37:48 OK 20241026095416_initial_model.sql (8.66ms)1584=== CONT TestClientErrorHandling1585=== RUN TestClientErrorHandling/InvalidStorePath1586=== PAUSE TestClientErrorHandling/InvalidStorePath15872026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)1588=== RUN TestClientErrorHandling/InvalidAuthToken1589=== PAUSE TestClientErrorHandling/InvalidAuthToken1590=== RUN TestClientErrorHandling/ServerNotAvailable1591=== PAUSE TestClientErrorHandling/ServerNotAvailable1592=== CONT TestClientCADerivations15932026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (5.09ms)15942026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (2.15ms)15952026/10/01 07:37:48 OK 20251218171726_add_pins.sql (2.99ms)15962026-10-01 07:37:48.410 UTC [768] ERROR: relation "goose_db_version" does not exist at character 3615972026-10-01 07:37:48.410 UTC [768] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15982026/10/01 07:37:48 OK 20251218171726_add_pins.sql (2.99ms)15992026/10/01 07:37:48 OK 20260905000000_add_claims.sql (4.31ms)16002026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.21ms)16012026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)16022026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.81ms)16032026/10/01 07:37:48 OK 20260905000000_add_claims.sql (3.09ms)16042026/10/01 07:37:48 OK 20241026095416_initial_model.sql (9.54ms)16052026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.57ms)16062026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000016072026/10/01 07:37:48 OK 20260905000000_add_claims.sql (3.81ms)16082026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (2.37ms)16092026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (3.03ms)16102026/10/01 07:37:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36235/oidc16112026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.61ms)16122026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (3.32ms)16132026/10/01 07:37:48 OK 2_object_stats_trigger.sql (2.16ms)16142026/10/01 07:37:48 OK 20251218171726_add_pins.sql (4.04ms)16152026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (3.55ms)16162026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000016172026/10/01 07:37:48 INFO Aborted multipart uploads count=016182026/10/01 07:37:48 OK 3_commit_push.sql (10.72ms)16192026/10/01 07:37:48 goose: up to current file version: 316202026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (14.06ms)16212026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000016222026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (13.21ms)16232026/10/01 07:37:48 OK 1_commit_pending_closure.sql (12.99ms)16242026/10/01 07:37:48 OK 20241026095416_initial_model.sql (21.19ms)16252026/10/01 07:37:48 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=016262026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (3.23ms)16272026/10/01 07:37:48 OK 20260905000000_add_claims.sql (4.81ms)16282026/10/01 07:37:48 OK 1_commit_pending_closure.sql (4.89ms)16292026/10/01 07:37:48 OK 2_object_stats_trigger.sql (4.78ms)16302026/10/01 07:37:48 INFO Vacuumed table table=pending_closures16312026/10/01 07:37:48 OK 2_object_stats_trigger.sql (2.93ms)16322026/10/01 07:37:48 OK 3_commit_push.sql (2.88ms)16332026/10/01 07:37:48 goose: up to current file version: 316342026/10/01 07:37:48 OK 20251218171726_add_pins.sql (4.41ms)16352026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (3.95ms)16362026/10/01 07:37:48 OK 3_commit_push.sql (1.39ms)16372026/10/01 07:37:48 goose: up to current file version: 316382026/10/01 07:37:48 INFO Vacuumed table table=pending_objects16392026/10/01 07:37:48 INFO Vacuumed table table=multipart_uploads16402026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.56ms)16412026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000016422026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.6ms)16432026/10/01 07:37:48 OK 1_commit_pending_closure.sql (3.77ms)16442026/10/01 07:37:48 OK 20260905000000_add_claims.sql (3.67ms)16452026/10/01 07:37:48 INFO Vacuumed table table=closures16462026/10/01 07:37:48 OK 2_object_stats_trigger.sql (2.12ms)16472026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.64ms)16482026/10/01 07:37:48 OK 3_commit_push.sql (1.99ms)16492026/10/01 07:37:48 goose: up to current file version: 316502026/10/01 07:37:48 INFO Vacuumed table table=objects16512026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.27ms)16522026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000016532026/10/01 07:37:48 INFO Aborted multipart uploads count=016542026/10/01 07:37:48 WARN Force mode enabled - objects will be deleted immediately without grace period16552026/10/01 07:37:48 OK 1_commit_pending_closure.sql (3.01ms)16562026/10/01 07:37:48 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016572026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.66ms)1658--- PASS: TestService_healthCheckHandler (0.56s)1659=== CONT TestReadProxyNarinfo16602026/10/01 07:37:48 OK 3_commit_push.sql (1.98ms)16612026/10/01 07:37:48 goose: up to current file version: 316622026-10-01 07:37:48.467 UTC [776] ERROR: relation "goose_db_version" does not exist at character 3616632026-10-01 07:37:48.467 UTC [776] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16642026/10/01 07:37:48 INFO Vacuumed table table=pending_closures16652026/10/01 07:37:48 INFO Vacuumed table table=pending_objects16662026/10/01 07:37:48 INFO Vacuumed table table=multipart_uploads16672026/10/01 07:37:48 INFO Vacuumed table table=closures16682026/10/01 07:37:48 INFO Vacuumed table table=objects1669--- PASS: TestPushDedupSurvivesConcurrentGC (0.85s)1670=== CONT TestCacheStatsHandler1671=== NAME TestNARDeduplicationMetadataUploadBug1672 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug4004461320/001/store/bhyb2xplrld398x4gvc73xw0i3w1wbvj-file1.txt16732026/10/01 07:37:48 OK 20241026095416_initial_model.sql (12.77ms)16742026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (2.04ms)16752026/10/01 07:37:48 OK 20251218171726_add_pins.sql (4.09ms)16762026-10-01 07:37:48.494 UTC [798] ERROR: relation "goose_db_version" does not exist at character 3616772026-10-01 07:37:48.494 UTC [798] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16782026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (27.75ms)16792026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures16802026/10/01 07:37:48 OK 20260905000000_add_claims.sql (5.81ms)16812026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.27ms)16822026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.96ms)16832026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000016842026-10-01 07:37:48.538 UTC [816] ERROR: relation "goose_db_version" does not exist at character 3616852026-10-01 07:37:48.538 UTC [816] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16862026-10-01 07:37:48.539 UTC [817] ERROR: relation "goose_db_version" does not exist at character 3616872026-10-01 07:37:48.539 UTC [817] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16882026/10/01 07:37:48 OK 1_commit_pending_closure.sql (8.81ms)16892026-10-01 07:37:48.543 UTC [818] ERROR: relation "goose_db_version" does not exist at character 3616902026-10-01 07:37:48.543 UTC [818] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16912026/10/01 07:37:48 OK 20241026095416_initial_model.sql (23.66ms)16922026/10/01 07:37:48 OK 2_object_stats_trigger.sql (18.7ms)16932026/10/01 07:37:48 OK 20241026095416_initial_model.sql (22.29ms)16942026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (22.98ms)16952026/10/01 07:37:48 OK 3_commit_push.sql (24.52ms)16962026/10/01 07:37:48 goose: up to current file version: 316972026/10/01 07:37:48 OK 20241026095416_initial_model.sql (24.5ms)16982026/10/01 07:37:48 OK 20241026095416_initial_model.sql (24.48ms)16992026/10/01 07:37:48 INFO Received push request method=POST path=/api/pushes17002026/10/01 07:37:48 OK 20251218171726_add_pins.sql (19.56ms)17012026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (19.91ms)17022026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (14.66ms)17032026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (14.81ms)17042026/10/01 07:37:48 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17052026/10/01 07:37:48 INFO Uploading bhyb2xplrld398x4gvc73xw0i3w1wbvj-file1.txt (160B)17062026-10-01 07:37:48.604 UTC [838] ERROR: relation "goose_db_version" does not exist at character 3617072026-10-01 07:37:48.604 UTC [838] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17082026/10/01 07:37:48 OK 20251218171726_add_pins.sql (10.19ms)17092026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (10.57ms)17102026-10-01 07:37:48.605 UTC [837] ERROR: relation "goose_db_version" does not exist at character 3617112026-10-01 07:37:48.605 UTC [837] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17122026/10/01 07:37:48 OK 20251218171726_add_pins.sql (8.22ms)17132026/10/01 07:37:48 OK 20251218171726_add_pins.sql (8.21ms)17142026/10/01 07:37:48 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"17152026/10/01 07:37:48 WARN Failed to register uploaded object key=bhyb2xplrld398x4gvc73xw0i3w1wbvj.ls error="server returned 404: 404 page not found\n"17162026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (6.69ms)17172026/10/01 07:37:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17182026/10/01 07:37:48 INFO Signed narinfos id=1 count=117192026/10/01 07:37:48 INFO Uploading 1 narinfos17202026/10/01 07:37:48 OK 20260905000000_add_claims.sql (8.42ms)17212026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (4.94ms)17222026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (5.65ms)17232026/10/01 07:37:48 OK 20260905000000_add_claims.sql (5.56ms)17242026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (4.44ms)17252026/10/01 07:37:48 INFO Received complete push request method=POST path=/api/pushes/1/complete17262026/10/01 07:37:48 WARN Failed to register uploaded object key=bhyb2xplrld398x4gvc73xw0i3w1wbvj.narinfo error="server returned 404: 404 page not found\n"17272026/10/01 07:37:48 OK 20260905000000_add_claims.sql (5.65ms)17282026/10/01 07:37:48 OK 20260905000000_add_claims.sql (6.06ms)17292026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (3.7ms)17302026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000017312026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (4.53ms)17322026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.68ms)17332026/10/01 07:37:48 OK 20241026095416_initial_model.sql (9.26ms)17342026/10/01 07:37:48 OK 20241026095416_initial_model.sql (9.97ms)17352026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (1.78ms)17362026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000017372026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.48ms)17382026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.41ms)17392026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.69ms)17402026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000017412026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (4.28ms)17422026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)17432026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.73ms)17442026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.1ms)17452026/10/01 07:37:48 OK 20251218171726_add_pins.sql (2.25ms)17462026/10/01 07:37:48 OK 2_object_stats_trigger.sql (759.41µs)17472026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.16ms)17482026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000017492026/10/01 07:37:48 OK 3_commit_push.sql (1.28ms)17502026/10/01 07:37:48 goose: up to current file version: 317512026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.7ms)17522026/10/01 07:37:48 OK 20251218171726_add_pins.sql (2.37ms)17532026/10/01 07:37:48 OK 3_commit_push.sql (944.23µs)17542026/10/01 07:37:48 goose: up to current file version: 317552026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.68ms)17562026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.41ms)17572026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (3.78ms)17582026/10/01 07:37:48 INFO Upload complete. (100ms)17592026/10/01 07:37:48 INFO Aborted multipart uploads count=017602026/10/01 07:37:48 OK 3_commit_push.sql (1ms)17612026/10/01 07:37:48 goose: up to current file version: 317622026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (3.06ms)17632026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.06ms)1764 metadata_upload_test.go:54: Retrieved narinfo from S3:17652026/10/01 07:37:48 OK 3_commit_push.sql (1.04ms)1766 StorePath: /build/TestNARDeduplicationMetadataUploadBug4004461320/001/store/bhyb2xplrld398x4gvc73xw0i3w1wbvj-file1.txt17672026/10/01 07:37:48 goose: up to current file version: 31768 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1769 Compression: zstd17702026/10/01 07:37:48 OK 20260905000000_add_claims.sql (2.63ms)1771 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1772 NarSize: 1601773 References: 1774 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf17752026/10/01 07:37:48 OK 20260905000000_add_claims.sql (2.23ms)17762026/10/01 07:37:48 WARN Force mode enabled - objects will be deleted immediately without grace period17772026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures17782026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (1.41ms)17792026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (1.62ms)17802026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (982.41µs)17812026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000017822026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (977.93µs)17832026/10/01 07:37:48 goose: successfully migrated database to version: 202609231200001784 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1785 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1786 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}17872026/10/01 07:37:48 OK 1_commit_pending_closure.sql (1.47ms)17882026/10/01 07:37:48 OK 1_commit_pending_closure.sql (1.48ms)17892026/10/01 07:37:48 OK 2_object_stats_trigger.sql (686.94µs)17902026/10/01 07:37:48 OK 2_object_stats_trigger.sql (700.96µs)17912026/10/01 07:37:48 OK 3_commit_push.sql (888.76µs)1792--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.62s)17932026/10/01 07:37:48 goose: up to current file version: 31794=== CONT TestIsValidCachePath17952026/10/01 07:37:48 OK 3_commit_push.sql (789.26µs)1796=== RUN TestIsValidCachePath/narinfo17972026/10/01 07:37:48 goose: up to current file version: 31798=== PAUSE TestIsValidCachePath/narinfo1799=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1800=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1801=== RUN TestIsValidCachePath/nar_zst1802=== PAUSE TestIsValidCachePath/nar_zst1803=== RUN TestIsValidCachePath/nar_xz1804=== PAUSE TestIsValidCachePath/nar_xz1805=== RUN TestIsValidCachePath/nar_bz21806=== PAUSE TestIsValidCachePath/nar_bz21807=== RUN TestIsValidCachePath/nar_uncompressed1808=== PAUSE TestIsValidCachePath/nar_uncompressed1809=== RUN TestIsValidCachePath/ls1810=== PAUSE TestIsValidCachePath/ls1811=== RUN TestIsValidCachePath/log1812=== PAUSE TestIsValidCachePath/log1813=== RUN TestIsValidCachePath/realisation1814=== PAUSE TestIsValidCachePath/realisation1815=== RUN TestIsValidCachePath/nix-cache-info1816=== PAUSE TestIsValidCachePath/nix-cache-info1817=== RUN TestIsValidCachePath/index.html1818=== PAUSE TestIsValidCachePath/index.html1819=== RUN TestIsValidCachePath/traversal_parent1820=== PAUSE TestIsValidCachePath/traversal_parent1821=== RUN TestIsValidCachePath/traversal_in_middle1822=== PAUSE TestIsValidCachePath/traversal_in_middle1823=== RUN TestIsValidCachePath/invalid_char_e1824=== PAUSE TestIsValidCachePath/invalid_char_e1825=== RUN TestIsValidCachePath/invalid_char_u1826=== PAUSE TestIsValidCachePath/invalid_char_u1827=== RUN TestIsValidCachePath/random_path1828=== PAUSE TestIsValidCachePath/random_path1829=== RUN TestIsValidCachePath/empty1830=== PAUSE TestIsValidCachePath/empty1831=== RUN TestIsValidCachePath/leading_slash1832=== PAUSE TestIsValidCachePath/leading_slash1833=== RUN TestIsValidCachePath/wrong_extension1834=== PAUSE TestIsValidCachePath/wrong_extension1835=== RUN TestIsValidCachePath/short_hash1836=== PAUSE TestIsValidCachePath/short_hash1837=== CONT TestCacheConfigHandler1838=== RUN TestCacheConfigHandler/full_config,_no_issuer1839=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1840=== RUN TestCacheConfigHandler/no_cache_url_configured1841=== PAUSE TestCacheConfigHandler/no_cache_url_configured1842=== RUN TestCacheConfigHandler/no_signing_keys1843=== PAUSE TestCacheConfigHandler/no_signing_keys1844=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1845=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1846=== CONT TestProxyHeadersOnlyTrustedOnSocket18472026/10/01 07:37:48 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=018482026/10/01 07:37:48 INFO Vacuumed table table=pending_closures18492026/10/01 07:37:48 INFO Vacuumed table table=pending_objects18502026/10/01 07:37:48 INFO Vacuumed table table=multipart_uploads18512026/10/01 07:37:48 INFO Vacuumed table table=closures18522026/10/01 07:37:48 INFO Vacuumed table table=objects1853--- PASS: TestGCSweepDeliversEachKeyOnce (0.64s)1854=== CONT TestParseSingleRange1855=== RUN TestParseSingleRange/none1856=== PAUSE TestParseSingleRange/none1857=== RUN TestParseSingleRange/unknown_unit1858=== PAUSE TestParseSingleRange/unknown_unit1859=== RUN TestParseSingleRange/multi-range_ignored1860=== PAUSE TestParseSingleRange/multi-range_ignored1861=== RUN TestParseSingleRange/malformed_no_dash1862=== PAUSE TestParseSingleRange/malformed_no_dash1863=== RUN TestParseSingleRange/malformed_both_empty1864=== PAUSE TestParseSingleRange/malformed_both_empty1865=== RUN TestParseSingleRange/malformed_end_before_start1866=== PAUSE TestParseSingleRange/malformed_end_before_start1867=== RUN TestParseSingleRange/closed1868=== PAUSE TestParseSingleRange/closed1869=== RUN TestParseSingleRange/open-ended1870=== PAUSE TestParseSingleRange/open-ended1871=== RUN TestParseSingleRange/end_clamped_to_size1872=== PAUSE TestParseSingleRange/end_clamped_to_size1873=== RUN TestParseSingleRange/suffix1874=== PAUSE TestParseSingleRange/suffix1875=== RUN TestParseSingleRange/suffix_exceeds_size1876=== PAUSE TestParseSingleRange/suffix_exceeds_size1877=== RUN TestParseSingleRange/single_byte1878=== PAUSE TestParseSingleRange/single_byte1879=== RUN TestParseSingleRange/start_past_EOF1880=== PAUSE TestParseSingleRange/start_past_EOF1881=== RUN TestParseSingleRange/start_far_past_EOF1882=== PAUSE TestParseSingleRange/start_far_past_EOF1883=== CONT TestService_ReadAuthMiddleware18842026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures1885=== NAME TestNARDeduplicationMetadataUploadBug1886 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug4004461320/001/store/31vvajqm55c8sxrh7xpg1kgq2wng0ywm-file2.txt18872026/10/01 07:37:48 INFO Aborted multipart uploads count=018882026/10/01 07:37:48 WARN Force mode enabled - objects will be deleted immediately without grace period18892026/10/01 07:37:48 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018902026/10/01 07:37:48 INFO Vacuumed table table=pending_closures18912026/10/01 07:37:48 INFO Vacuumed table table=pending_objects18922026/10/01 07:37:48 INFO Vacuumed table table=multipart_uploads18932026/10/01 07:37:48 INFO Vacuumed table table=closures18942026/10/01 07:37:48 INFO Vacuumed table table=objects1895--- PASS: TestGCSweepSkipsPendingObjects (0.66s)1896=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1897--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.78s)1898=== CONT TestService_RequireScope_OIDC1899=== NAME TestClientMultipleUploads1900 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads3641561348/001/store/rdk4x4dipifahvv8pzdpgrhy7xrxq2aj-test-file-0.txt19012026/10/01 07:37:48 INFO Aborted multipart uploads count=019022026-10-01 07:37:48.744 UTC [919] ERROR: relation "goose_db_version" does not exist at character 3619032026-10-01 07:37:48.744 UTC [919] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19042026/10/01 07:37:48 INFO Received push request method=POST path=/api/pushes19052026/10/01 07:37:48 WARN Force mode enabled - objects will be deleted immediately without grace period19062026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures19072026/10/01 07:37:48 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19082026/10/01 07:37:48 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019092026/10/01 07:37:48 INFO Vacuumed table table=pending_closures19102026/10/01 07:37:48 INFO Vacuumed table table=pending_objects19112026/10/01 07:37:48 INFO Vacuumed table table=multipart_uploads19122026/10/01 07:37:48 INFO Vacuumed table table=closures19132026/10/01 07:37:48 INFO Vacuumed table table=objects19142026/10/01 07:37:48 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign1915--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.67s)1916=== CONT TestService_AuthMiddleware_OIDC19172026/10/01 07:37:48 INFO Signed narinfos id=2 count=119182026/10/01 07:37:48 WARN Failed to register uploaded object key=31vvajqm55c8sxrh7xpg1kgq2wng0ywm.ls error="server returned 404: 404 page not found\n"19192026/10/01 07:37:48 INFO Uploading 1 narinfos19202026/10/01 07:37:48 OK 20241026095416_initial_model.sql (7.48ms)19212026-10-01 07:37:48.758 UTC [920] ERROR: relation "goose_db_version" does not exist at character 3619222026-10-01 07:37:48.758 UTC [920] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19232026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)1924--- PASS: TestGCMetrics (0.67s)1925=== CONT TestOrphanedObjectsGC19262026/10/01 07:37:48 OK 20251218171726_add_pins.sql (2.58ms)19272026/10/01 07:37:48 INFO Received complete push request method=POST path=/api/pushes/2/complete19282026/10/01 07:37:48 WARN Failed to register uploaded object key=31vvajqm55c8sxrh7xpg1kgq2wng0ywm.narinfo error="server returned 404: 404 page not found\n"19292026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (3.32ms)19302026/10/01 07:37:48 INFO Upload complete. (57ms)1931=== NAME TestNARDeduplicationMetadataUploadBug1932 metadata_upload_test.go:76: Retrieved narinfo from S3:1933 StorePath: /build/TestNARDeduplicationMetadataUploadBug4004461320/001/store/31vvajqm55c8sxrh7xpg1kgq2wng0ywm-file2.txt1934 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1935 Compression: zstd1936 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1937 NarSize: 1601938 References: 1939 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1940 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)19412026/10/01 07:37:48 OK 20260905000000_add_claims.sql (5.26ms)1942 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1943 {"version":1,"root":{"type":"regular","size":44}}19442026/10/01 07:37:48 OK 20241026095416_initial_model.sql (7.56ms)1945=== NAME TestClientMultipleUploads1946 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads3641561348/001/store/q22b4pm4fsn9wsn65mshlpglwjf6k45c-test-file-1.txt19472026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.64ms)19482026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.8ms)19492026/10/01 07:37:48 OK 20251218171726_add_pins.sql (3.2ms)1950--- PASS: TestNARDeduplicationMetadataUploadBug (0.95s)1951=== CONT TestResurrectedObjectNotDeleted19522026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (4.2ms)19532026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000019542026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (3.55ms)19552026/10/01 07:37:48 OK 1_commit_pending_closure.sql (3.02ms)19562026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.81ms)19572026/10/01 07:37:48 OK 20260905000000_add_claims.sql (3.96ms)19582026/10/01 07:37:48 OK 3_commit_push.sql (2.33ms)19592026/10/01 07:37:48 goose: up to current file version: 319602026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (5.21ms)19612026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (2.1ms)19622026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000019632026/10/01 07:37:48 OK 1_commit_pending_closure.sql (2.24ms)19642026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.7ms)19652026/10/01 07:37:48 OK 3_commit_push.sql (1.62ms)19662026/10/01 07:37:48 goose: up to current file version: 319672026/10/01 07:37:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33475/oidc1968=== NAME TestClientMultipleUploads1969 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads3641561348/001/store/a0lx2ignksdb83sqb674yp954qn19vw6-test-file-2.txt19702026-10-01 07:37:48.818 UTC [978] ERROR: relation "goose_db_version" does not exist at character 3619712026-10-01 07:37:48.818 UTC [978] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19722026/10/01 07:37:48 OK 20241026095416_initial_model.sql (8.82ms)19732026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.87ms)19742026/10/01 07:37:48 OK 20251218171726_add_pins.sql (4.17ms)19752026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (12.25ms)19762026/10/01 07:37:48 OK 20260905000000_add_claims.sql (4.37ms)19772026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (1.78ms)19782026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (1.63ms)19792026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000019802026/10/01 07:37:48 OK 1_commit_pending_closure.sql (1.9ms)19812026-10-01 07:37:48.863 UTC [1033] ERROR: relation "goose_db_version" does not exist at character 3619822026-10-01 07:37:48.863 UTC [1033] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19832026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.29ms)19842026/10/01 07:37:48 OK 3_commit_push.sql (1.75ms)19852026/10/01 07:37:48 goose: up to current file version: 319862026-10-01 07:37:48.875 UTC [1035] ERROR: relation "goose_db_version" does not exist at character 3619872026-10-01 07:37:48.875 UTC [1035] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19882026/10/01 07:37:48 OK 20241026095416_initial_model.sql (8.2ms)19892026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)19902026/10/01 07:37:48 OK 20251218171726_add_pins.sql (2.95ms)19912026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (3.84ms)19922026/10/01 07:37:48 OK 20241026095416_initial_model.sql (7.7ms)19932026/10/01 07:37:48 OK 20260905000000_add_claims.sql (2.45ms)19942026/10/01 07:37:48 INFO Received push request method=POST path=/api/pushes19952026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)19962026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (1.51ms)19972026/10/01 07:37:48 OK 20251218171726_add_pins.sql (2.11ms)19982026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (1.51ms)19992026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000020002026/10/01 07:37:48 OK 1_commit_pending_closure.sql (1.38ms)20012026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (2.34ms)20022026/10/01 07:37:48 OK 2_object_stats_trigger.sql (888.36µs)20032026/10/01 07:37:48 OK 3_commit_push.sql (653.87µs)20042026/10/01 07:37:48 goose: up to current file version: 320052026/10/01 07:37:48 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)20062026/10/01 07:37:48 INFO Uploading a0lx2ignksdb83sqb674yp954qn19vw6-test-file-2.txt (160B)20072026/10/01 07:37:48 INFO Uploading rdk4x4dipifahvv8pzdpgrhy7xrxq2aj-test-file-0.txt (160B)20082026/10/01 07:37:48 OK 20260905000000_add_claims.sql (2.88ms)20092026/10/01 07:37:48 INFO Uploading q22b4pm4fsn9wsn65mshlpglwjf6k45c-test-file-1.txt (160B)20102026-10-01 07:37:48.899 UTC [1105] ERROR: relation "goose_db_version" does not exist at character 3620112026-10-01 07:37:48.899 UTC [1105] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20122026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (1.63ms)20132026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (1.03ms)20142026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000020152026/10/01 07:37:48 OK 1_commit_pending_closure.sql (1.37ms)20162026/10/01 07:37:48 OK 2_object_stats_trigger.sql (904.06µs)20172026/10/01 07:37:48 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"20182026/10/01 07:37:48 WARN Failed to register uploaded object key=rdk4x4dipifahvv8pzdpgrhy7xrxq2aj.ls error="server returned 404: 404 page not found\n"20192026/10/01 07:37:48 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"20202026/10/01 07:37:48 OK 3_commit_push.sql (774.1µs)20212026/10/01 07:37:48 goose: up to current file version: 320222026/10/01 07:37:48 WARN Failed to register uploaded object key=q22b4pm4fsn9wsn65mshlpglwjf6k45c.ls error="server returned 404: 404 page not found\n"20232026/10/01 07:37:48 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"20242026/10/01 07:37:48 INFO lead: acquired remote=192.0.2.1:123420252026/10/01 07:37:48 INFO lead: released remote=192.0.2.1:12342026--- PASS: TestLeadEndsOnShutdown (0.64s)2027=== CONT TestService_AuthMiddleware_MTLSProxyHeader20282026/10/01 07:37:48 WARN Failed to register uploaded object key=a0lx2ignksdb83sqb674yp954qn19vw6.ls error="server returned 404: 404 page not found\n"20292026/10/01 07:37:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20302026/10/01 07:37:48 INFO Signed narinfos id=1 count=320312026/10/01 07:37:48 INFO Uploading 3 narinfos20322026/10/01 07:37:48 WARN Failed to register uploaded object key=a0lx2ignksdb83sqb674yp954qn19vw6.narinfo error="server returned 404: 404 page not found\n"20332026/10/01 07:37:48 WARN Failed to register uploaded object key=q22b4pm4fsn9wsn65mshlpglwjf6k45c.narinfo error="server returned 404: 404 page not found\n"20342026/10/01 07:37:48 OK 20241026095416_initial_model.sql (7.62ms)20352026/10/01 07:37:48 INFO Received complete push request method=POST path=/api/pushes/1/complete20362026/10/01 07:37:48 WARN Failed to register uploaded object key=rdk4x4dipifahvv8pzdpgrhy7xrxq2aj.narinfo error="server returned 404: 404 page not found\n"20372026/10/01 07:37:48 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)20382026/10/01 07:37:48 OK 20251218171726_add_pins.sql (2.33ms)20392026/10/01 07:37:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43163/oidc20402026/10/01 07:37:48 OK 20260628120000_add_object_size_and_stats.sql (3.56ms)20412026/10/01 07:37:48 INFO Upload complete. (74ms)2042=== NAME TestClientMultipleUploads2043 client_integration_test.go:369: Uploaded 3 paths in 112.630503ms20442026/10/01 07:37:48 OK 20260905000000_add_claims.sql (3.44ms)20452026/10/01 07:37:48 OK 20260920000000_drop_claims.sql (2.03ms)20462026/10/01 07:37:48 OK 20260923120000_add_pushes.sql (1.7ms)20472026/10/01 07:37:48 goose: successfully migrated database to version: 2026092312000020482026/10/01 07:37:48 OK 1_commit_pending_closure.sql (1.82ms)20492026/10/01 07:37:48 OK 2_object_stats_trigger.sql (1.06ms)2050--- PASS: TestClientMultipleUploads (0.87s)2051=== CONT TestObjectStatsTrigger20522026/10/01 07:37:48 OK 3_commit_push.sql (1.59ms)20532026/10/01 07:37:48 goose: up to current file version: 320542026/10/01 07:37:48 INFO lead: acquired remote=192.0.2.1:12342055=== NAME TestPinProtectsFromGC2056 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC2426980869/001/store/y388z7xhq75qy9p0pzam7148m244v5g3-pinned-file.txt2057 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC2426980869/001/store/w1cf1a2r8nw39vsklgvg29xg7ys5fm5v-unpinned-file.txt20582026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures2059--- PASS: TestService_ReadScope_PublicByDefault (0.63s)2060=== CONT TestOrphanedObjectsGCStressTest20612026/10/01 07:37:48 INFO Received uploads request method=POST path=/api/pending_closures20622026/10/01 07:37:48 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)20632026/10/01 07:37:48 INFO Uploading crg9zzwih3ckiv1z8p4qqi24c1nlnm0c-b (216B)20642026/10/01 07:37:48 INFO Uploading x8w252aryqm85dyx55s91mkdmc3k5bb1-shared-dep (136B)20652026/10/01 07:37:48 WARN Failed to register uploaded object key=5d7kmvi5ydjmjmlgf7g6h42hx3pgd6iw.ls error="server returned 404: 404 page not found\n"20662026/10/01 07:37:48 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20672026/10/01 07:37:48 WARN Failed to register uploaded object key=x8w252aryqm85dyx55s91mkdmc3k5bb1.ls error="server returned 404: 404 page not found\n"20682026/10/01 07:37:48 WARN Failed to register uploaded object key=nar/1d6nkigd8v7hcfp3rmlway3r2122fc1yxfzyv1rbwdknxbqq1ll1.nar.zst error="server returned 404: 404 page not found\n"20692026/10/01 07:37:48 WARN Failed to register uploaded object key=crg9zzwih3ckiv1z8p4qqi24c1nlnm0c.ls error="server returned 404: 404 page not found\n"20702026/10/01 07:37:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign20712026/10/01 07:37:48 INFO Signed narinfos id=2 count=220722026/10/01 07:37:48 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign20732026/10/01 07:37:48 INFO Signed narinfos id=1 count=220742026/10/01 07:37:48 INFO Uploading 4 narinfos20752026/10/01 07:37:48 WARN Failed to register uploaded object key=x8w252aryqm85dyx55s91mkdmc3k5bb1.narinfo error="server returned 404: 404 page not found\n"20762026/10/01 07:37:49 WARN Failed to register uploaded object key=crg9zzwih3ckiv1z8p4qqi24c1nlnm0c.narinfo error="server returned 404: 404 page not found\n"20772026/10/01 07:37:49 WARN Failed to register uploaded object key=5d7kmvi5ydjmjmlgf7g6h42hx3pgd6iw.narinfo error="server returned 404: 404 page not found\n"20782026/10/01 07:37:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20792026/10/01 07:37:49 WARN Failed to register uploaded object key=x8w252aryqm85dyx55s91mkdmc3k5bb1.narinfo error="server returned 404: 404 page not found\n"20802026-10-01 07:37:49.003 UTC [1296] ERROR: relation "goose_db_version" does not exist at character 3620812026-10-01 07:37:49.003 UTC [1296] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20822026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes20832026/10/01 07:37:49 INFO Completed upload id=120842026/10/01 07:37:49 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20852026/10/01 07:37:49 INFO Completed upload id=220862026/10/01 07:37:49 INFO Upload complete. (87ms)20872026/10/01 07:37:49 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)20882026/10/01 07:37:49 INFO Uploading n423xgycls619hzfh1dx8z46vr6m22jv-shared-dep (136B)20892026/10/01 07:37:49 INFO Uploading rxsf39r00w183gq74qpbmm6vm4av38vr-a (216B)2090=== NAME TestClientFallsBackToClosures2091 client_pushes_test.go:112: Retrieved narinfo from S3:2092 StorePath: /build/TestClientFallsBackToClosures2646947309/001/store/x8w252aryqm85dyx55s91mkdmc3k5bb1-shared-dep2093 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2094 Compression: zstd2095 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822096 NarSize: 1362097 References: 2098 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n20992026/10/01 07:37:49 WARN Failed to register uploaded object key=k1s3zspa5kmijbb8124mzb647h756nbd.ls error="server returned 404: 404 page not found\n"21002026/10/01 07:37:49 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"2101 client_pushes_test.go:112: Retrieved narinfo from S3:2102 StorePath: /build/TestClientFallsBackToClosures2646947309/001/store/5d7kmvi5ydjmjmlgf7g6h42hx3pgd6iw-a2103 URL: nar/1d6nkigd8v7hcfp3rmlway3r2122fc1yxfzyv1rbwdknxbqq1ll1.nar.zst2104 Compression: zstd2105 NarHash: sha256:1d6nkigd8v7hcfp3rmlway3r2122fc1yxfzyv1rbwdknxbqq1ll12106 NarSize: 2162107 References: /build/TestClientFallsBackToClosures2646947309/001/store/x8w252aryqm85dyx55s91mkdmc3k5bb1-shared-dep2108 CA: text:sha256:0a3wa3mdlwwrdravzrybzji71xz95k6yvbmig4aswj77prfw9nqk21092026/10/01 07:37:49 WARN Failed to register uploaded object key=n423xgycls619hzfh1dx8z46vr6m22jv.ls error="server returned 404: 404 page not found\n"21102026/10/01 07:37:49 WARN Failed to register uploaded object key=nar/032z9h1bj22lw9vyna8j29b2dgbnwlblp5vdng0w7yqj2fxx3241.nar.zst error="server returned 404: 404 page not found\n"21112026/10/01 07:37:49 WARN Failed to register uploaded object key=rxsf39r00w183gq74qpbmm6vm4av38vr.ls error="server returned 404: 404 page not found\n"21122026/10/01 07:37:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21132026/10/01 07:37:49 INFO Signed narinfos id=1 count=32114 client_pushes_test.go:112: Retrieved narinfo from S3:2115 StorePath: /build/TestClientFallsBackToClosures2646947309/001/store/crg9zzwih3ckiv1z8p4qqi24c1nlnm0c-b2116 URL: nar/1d6nkigd8v7hcfp3rmlway3r2122fc1yxfzyv1rbwdknxbqq1ll1.nar.zst2117 Compression: zstd21182026-10-01 07:37:49.028 UTC [1330] ERROR: relation "goose_db_version" does not exist at character 3621192026-10-01 07:37:49.028 UTC [1330] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21202026/10/01 07:37:49 INFO Uploading 3 narinfos2121 NarHash: sha256:1d6nkigd8v7hcfp3rmlway3r2122fc1yxfzyv1rbwdknxbqq1ll12122 NarSize: 21621232026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes2124 References: /build/TestClientFallsBackToClosures2646947309/001/store/x8w252aryqm85dyx55s91mkdmc3k5bb1-shared-dep2125 CA: text:sha256:0a3wa3mdlwwrdravzrybzji71xz95k6yvbmig4aswj77prfw9nqk21262026/10/01 07:37:49 OK 20241026095416_initial_model.sql (9.84ms)21272026/10/01 07:37:49 OK 20251210153512_drop_unused_gin_index.sql (1.51ms)21282026/10/01 07:37:49 WARN Failed to register uploaded object key=n423xgycls619hzfh1dx8z46vr6m22jv.narinfo error="server returned 404: 404 page not found\n"21292026/10/01 07:37:49 WARN Failed to register uploaded object key=k1s3zspa5kmijbb8124mzb647h756nbd.narinfo error="server returned 404: 404 page not found\n"21302026/10/01 07:37:49 INFO Received complete push request method=POST path=/api/pushes/1/complete21312026/10/01 07:37:49 WARN Failed to register uploaded object key=rxsf39r00w183gq74qpbmm6vm4av38vr.narinfo error="server returned 404: 404 page not found\n"21322026-10-01 07:37:49.034 UTC [1338] ERROR: relation "goose_db_version" does not exist at character 3621332026-10-01 07:37:49.034 UTC [1338] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21342026/10/01 07:37:49 OK 20251218171726_add_pins.sql (2.47ms)21352026/10/01 07:37:49 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux21362026/10/01 07:37:49 WARN Refused reserved pin name=worker-x86_64-linux21372026/10/01 07:37:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)2138--- PASS: TestClientFallsBackToClosures (0.89s)21392026/10/01 07:37:49 INFO Uploading y388z7xhq75qy9p0pzam7148m244v5g3-pinned-file.txt (128B)2140=== CONT TestMultipartCleanup21412026/10/01 07:37:49 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux21422026/10/01 07:37:49 INFO Received create pin request method=POST path=/api/pins/my-app21432026/10/01 07:37:49 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux2144--- PASS: TestCreatePin_ReservedPins (0.67s)2145=== CONT TestProxyWriteTimeout/narinfo2146=== CONT TestProxyWriteTimeout/unknown_size2147=== CONT TestProxyWriteTimeout/10_GiB_nar2148=== CONT TestProxyWriteTimeout/1_GiB_nar21492026/10/01 07:37:49 OK 20260628120000_add_object_size_and_stats.sql (3.81ms)2150--- PASS: TestProxyWriteTimeout (0.09s)2151 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2152 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2153 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2154 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2155=== CONT TestServerTLSConfig/no_client_CA2156=== CONT TestServerTLSConfig/not_a_PEM_file2157=== CONT TestServerTLSConfig/missing_CA_file2158--- PASS: TestServerTLSConfig (0.09s)2159 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2160 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2161 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2162=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info21632026/10/01 07:37:49 INFO Received uploads request method=POST path=/2164=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key21652026/10/01 07:37:49 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"21662026/10/01 07:37:49 INFO Received complete multipart upload request method=POST path=/2167=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal21682026/10/01 07:37:49 INFO Received uploads request method=POST path=/2169=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key21702026/10/01 07:37:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21712026/10/01 07:37:49 INFO Received request for more parts method=POST path=/2172=== CONT TestIsValidUploadKey/narinfo2173=== CONT TestIsValidUploadKey/realisation_plus_in_output21742026/10/01 07:37:49 WARN Failed to register uploaded object key=y388z7xhq75qy9p0pzam7148m244v5g3.ls error="server returned 404: 404 page not found\n"2175=== CONT TestIsValidUploadKey/listing_key,_narinfo_type21762026/10/01 07:37:49 INFO Signed narinfos id=1 count=12177=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2178=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2179=== CONT TestIsValidUploadKey/index.html2180=== CONT TestIsValidUploadKey/nix-cache-info21812026/10/01 07:37:49 INFO Uploading 1 narinfos2182=== CONT TestIsValidUploadKey/build_log_home-manager_file2183=== CONT TestIsValidUploadKey/realisation2184--- PASS: TestUploadHandlersRejectInvalidKeys (0.09s)2185 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2186 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2187 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2188 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)21892026/10/01 07:37:49 OK 20260905000000_add_claims.sql (3.29ms)2190=== CONT TestIsValidUploadKey/build_log_equals2191=== CONT TestIsValidUploadKey/build_log_question_mark2192=== CONT TestIsValidUploadKey/build_log_plus_in_name2193=== CONT TestIsValidUploadKey/nar_plain2194=== CONT TestIsValidUploadKey/build_log2195=== CONT TestIsValidUploadKey/listing2196=== CONT TestIsValidUploadKey/empty_key2197=== CONT TestIsValidUploadKey/unknown_type2198=== CONT TestIsValidUploadKey/nar_xz2199=== CONT TestIsValidUploadKey/nar_zst2200=== CONT TestIsValidUploadKey/absolute2201=== CONT TestIsValidUploadKey/traversal_nar2202=== CONT TestIsValidUploadKey/traversal2203--- PASS: TestIsValidUploadKey (0.09s)2204 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2205 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2206 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2207 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2208 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2209 --- PASS: TestIsValidUploadKey/index.html (0.00s)2210 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2211 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2212 --- PASS: TestIsValidUploadKey/realisation (0.00s)2213 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2214 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2215 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2216 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2217 --- PASS: TestIsValidUploadKey/build_log (0.00s)2218 --- PASS: TestIsValidUploadKey/listing (0.00s)2219 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2220 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2221 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2222 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2223 --- PASS: TestIsValidUploadKey/absolute (0.00s)2224 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2225 --- PASS: TestIsValidUploadKey/traversal (0.00s)22262026/10/01 07:37:49 OK 20241026095416_initial_model.sql (8.65ms)2227=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure22282026/10/01 07:37:49 INFO Received uploads request method=POST path=/22292026/10/01 07:37:49 INFO Upload complete. (82ms)22302026/10/01 07:37:49 OK 20260920000000_drop_claims.sql (2.49ms)22312026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes22322026/10/01 07:37:49 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)2233=== NAME TestClientPushesUseOnePush2234 client_pushes_test.go:97: Retrieved narinfo from S3:2235 StorePath: /build/TestClientPushesUseOnePush2055965551/001/store/n423xgycls619hzfh1dx8z46vr6m22jv-shared-dep2236 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2237 Compression: zstd2238 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822239 NarSize: 1362240 References: 2241 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n22422026/10/01 07:37:49 INFO Received complete push request method=POST path=/api/pushes/1/complete22432026/10/01 07:37:49 WARN Failed to register uploaded object key=y388z7xhq75qy9p0pzam7148m244v5g3.narinfo error="server returned 404: 404 page not found\n"22442026/10/01 07:37:49 OK 20260923120000_add_pushes.sql (2.12ms)22452026/10/01 07:37:49 goose: successfully migrated database to version: 202609231200002246 client_pushes_test.go:97: Retrieved narinfo from S3:2247 StorePath: /build/TestClientPushesUseOnePush2055965551/001/store/rxsf39r00w183gq74qpbmm6vm4av38vr-a2248 URL: nar/032z9h1bj22lw9vyna8j29b2dgbnwlblp5vdng0w7yqj2fxx3241.nar.zst2249 Compression: zstd2250 NarHash: sha256:032z9h1bj22lw9vyna8j29b2dgbnwlblp5vdng0w7yqj2fxx32412251 NarSize: 2162252 References: /build/TestClientPushesUseOnePush2055965551/001/store/n423xgycls619hzfh1dx8z46vr6m22jv-shared-dep2253 CA: text:sha256:0apq6rfgnyz3blwb3655cky3xqpcx4qfzsbjr5mxpsdp1jkfypvz2254=== NAME TestClientIntegration2255 client_integration_test.go:286: Created store path: /build/TestClientIntegration3119793687/002/store/sl2qcq2y6xqy2qshmsfv49q1chjp0ivf-test-file.txt22562026/10/01 07:37:49 OK 20251218171726_add_pins.sql (3.38ms)22572026/10/01 07:37:49 OK 1_commit_pending_closure.sql (2.2ms)22582026/10/01 07:37:49 OK 20241026095416_initial_model.sql (9.16ms)2259=== NAME TestClientPushesUseOnePush2260 client_pushes_test.go:97: Retrieved narinfo from S3:2261 StorePath: /build/TestClientPushesUseOnePush2055965551/001/store/k1s3zspa5kmijbb8124mzb647h756nbd-b2262 URL: nar/032z9h1bj22lw9vyna8j29b2dgbnwlblp5vdng0w7yqj2fxx3241.nar.zst2263 Compression: zstd2264 NarHash: sha256:032z9h1bj22lw9vyna8j29b2dgbnwlblp5vdng0w7yqj2fxx32412265 NarSize: 21622662026/10/01 07:37:49 OK 2_object_stats_trigger.sql (1.66ms)2267 References: /build/TestClientPushesUseOnePush2055965551/001/store/n423xgycls619hzfh1dx8z46vr6m22jv-shared-dep2268 CA: text:sha256:0apq6rfgnyz3blwb3655cky3xqpcx4qfzsbjr5mxpsdp1jkfypvz2269=== NAME TestClientWithDependencies2270 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies1844633547/001/store/v2avd9ak7l1n61zl9j3hx5mpszsy02zr-test-script22712026/10/01 07:37:49 OK 20251210153512_drop_unused_gin_index.sql (1.96ms)22722026/10/01 07:37:49 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)22732026/10/01 07:37:49 INFO Uploading ch65x1g8dzjc0370zcbnf9zw05vw6ija-shared-dep (136B)22742026/10/01 07:37:49 INFO Uploading ssqw5ax8k1wji1530w76xvnh0ggjykgw-top (224B)22752026/10/01 07:37:49 OK 3_commit_push.sql (1.9ms)22762026/10/01 07:37:49 goose: up to current file version: 322772026/10/01 07:37:49 OK 20260628120000_add_object_size_and_stats.sql (4.3ms)2278--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.65s)2279=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts22802026/10/01 07:37:49 INFO Received request for more parts method=POST path=/22812026/10/01 07:37:49 WARN Failed to register uploaded object key=ch65x1g8dzjc0370zcbnf9zw05vw6ija.ls error="server returned 404: 404 page not found\n"22822026/10/01 07:37:49 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22832026/10/01 07:37:49 OK 20251218171726_add_pins.sql (6.25ms)22842026/10/01 07:37:49 WARN Failed to register uploaded object key=ssqw5ax8k1wji1530w76xvnh0ggjykgw.ls error="server returned 404: 404 page not found\n"22852026/10/01 07:37:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22862026/10/01 07:37:49 WARN Failed to register uploaded object key=nar/0mbv90rdbzbngajn3imh32aa673lyqgj9qfg77wd9jlpsvvvnkb5.nar.zst error="server returned 404: 404 page not found\n"22872026/10/01 07:37:49 INFO Signed narinfos id=1 count=222882026/10/01 07:37:49 INFO Uploading 2 narinfos2289--- PASS: TestClientPushesUseOnePush (0.88s)2290=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart22912026/10/01 07:37:49 INFO Received complete multipart upload request method=POST path=/22922026/10/01 07:37:49 OK 20260905000000_add_claims.sql (9.01ms)22932026/10/01 07:37:49 INFO Upload complete. (76ms)22942026/10/01 07:37:49 INFO Received complete push request method=POST path=/api/pushes/1/complete22952026/10/01 07:37:49 WARN Failed to register uploaded object key=ch65x1g8dzjc0370zcbnf9zw05vw6ija.narinfo error="server returned 404: 404 page not found\n"22962026/10/01 07:37:49 WARN Failed to register uploaded object key=ssqw5ax8k1wji1530w76xvnh0ggjykgw.narinfo error="server returned 404: 404 page not found\n"22972026/10/01 07:37:49 OK 20260628120000_add_object_size_and_stats.sql (7.03ms)22982026/10/01 07:37:49 OK 20260920000000_drop_claims.sql (6.51ms)22992026/10/01 07:37:49 OK 20260905000000_add_claims.sql (3.61ms)23002026/10/01 07:37:49 INFO Upload complete. (69ms)23012026/10/01 07:37:49 OK 20260920000000_drop_claims.sql (3.31ms)23022026/10/01 07:37:49 OK 20260923120000_add_pushes.sql (4.02ms)23032026/10/01 07:37:49 goose: successfully migrated database to version: 202609231200002304=== NAME TestClientSharedPathCommittedMidPush2305 client_integration_test.go:680: Retrieved narinfo from S3:2306 StorePath: /build/TestClientSharedPathCommittedMidPush4088090987/001/store/ch65x1g8dzjc0370zcbnf9zw05vw6ija-shared-dep2307 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2308 Compression: zstd2309 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822310 NarSize: 1362311 References: 2312 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n23132026/10/01 07:37:49 OK 20260923120000_add_pushes.sql (2.17ms)23142026/10/01 07:37:49 goose: successfully migrated database to version: 2026092312000023152026/10/01 07:37:49 OK 1_commit_pending_closure.sql (2.31ms)2316--- PASS: TestGCBugBareHashReferences (0.87s)2317=== CONT TestPush_RejectsBadRequests/no_roots23182026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes2319=== CONT TestPush_RejectsBadRequests/bad_root23202026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes2321=== NAME TestClientSharedPathCommittedMidPush2322 client_integration_test.go:680: Retrieved narinfo from S3:2323 StorePath: /build/TestClientSharedPathCommittedMidPush4088090987/001/store/ssqw5ax8k1wji1530w76xvnh0ggjykgw-top2324 URL: nar/0mbv90rdbzbngajn3imh32aa673lyqgj9qfg77wd9jlpsvvvnkb5.nar.zst2325 Compression: zstd2326 NarHash: sha256:0mbv90rdbzbngajn3imh32aa673lyqgj9qfg77wd9jlpsvvvnkb52327 NarSize: 2242328 References: /build/TestClientSharedPathCommittedMidPush4088090987/001/store/ch65x1g8dzjc0370zcbnf9zw05vw6ija-shared-dep2329 CA: text:sha256:1jiwycc349zsvgfk3w2yx8g1i3jg01bwxqi6zrj5dlyiwmxma9z62330=== CONT TestPush_RejectsBadRequests/root_not_in_objects23312026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes23322026/10/01 07:37:49 OK 2_object_stats_trigger.sql (1.99ms)2333=== CONT TestPush_RejectsBadRequests/no_objects23342026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes2335=== CONT TestResolveDBConnectionString/flag_wins2336--- PASS: TestPush_RejectsBadRequests (1.03s)2337 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2338 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2339 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2340 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2341=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2342=== CONT TestResolveDBConnectionString/nothing_configured2343=== CONT TestResolveDBConnectionString/missing_file_is_an_error2344=== CONT TestResolveDBConnectionString/file_when_flag_empty2345=== CONT TestClientErrorHandling/InvalidStorePath2346--- PASS: TestResolveDBConnectionString (0.00s)2347 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2348 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2349 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2350 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2351 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)23522026/10/01 07:37:49 OK 1_commit_pending_closure.sql (4.4ms)23532026/10/01 07:37:49 OK 3_commit_push.sql (2.98ms)23542026/10/01 07:37:49 goose: up to current file version: 323552026/10/01 07:37:49 OK 2_object_stats_trigger.sql (1.39ms)23562026/10/01 07:37:49 OK 3_commit_push.sql (978.56µs)23572026/10/01 07:37:49 goose: up to current file version: 323582026/10/01 07:37:49 INFO lead: released remote=192.0.2.1:12342359--- PASS: TestClientSharedPathCommittedMidPush (0.82s)2360=== CONT TestClientErrorHandling/ServerNotAvailable23612026-10-01 07:37:49.085 UTC [1401] ERROR: relation "goose_db_version" does not exist at character 3623622026-10-01 07:37:49.085 UTC [1401] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2363=== NAME TestClientWithDependencies2364 client_integration_test.go:615: Found 1 dependencies (including self)23652026/10/01 07:37:49 OK 20241026095416_initial_model.sql (9.2ms)23662026/10/01 07:37:49 OK 20251210153512_drop_unused_gin_index.sql (1.64ms)23672026/10/01 07:37:49 OK 20251218171726_add_pins.sql (3.1ms)23682026/10/01 07:37:49 OK 20260628120000_add_object_size_and_stats.sql (4.34ms)23692026/10/01 07:37:49 OK 20260905000000_add_claims.sql (4.44ms)23702026/10/01 07:37:49 OK 20260920000000_drop_claims.sql (2.38ms)23712026/10/01 07:37:49 OK 20260923120000_add_pushes.sql (1.85ms)23722026/10/01 07:37:49 goose: successfully migrated database to version: 202609231200002373=== CONT TestClientErrorHandling/InvalidAuthToken2374--- PASS: TestCacheStatsHandler (0.64s)2375=== CONT TestIsValidCachePath/narinfo2376=== CONT TestIsValidCachePath/index.html23772026/10/01 07:37:49 OK 1_commit_pending_closure.sql (2.11ms)2378=== CONT TestIsValidCachePath/nix-cache-info2379=== CONT TestIsValidCachePath/realisation2380=== CONT TestIsValidCachePath/log2381=== CONT TestIsValidCachePath/ls2382=== CONT TestIsValidCachePath/nar_uncompressed2383=== CONT TestIsValidCachePath/nar_bz22384=== CONT TestIsValidCachePath/nar_xz2385=== CONT TestIsValidCachePath/nar_zst2386=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2387=== CONT TestIsValidCachePath/empty2388=== CONT TestIsValidCachePath/traversal_parent2389=== CONT TestIsValidCachePath/random_path2390=== CONT TestIsValidCachePath/invalid_char_u2391=== CONT TestIsValidCachePath/invalid_char_e2392=== CONT TestIsValidCachePath/traversal_in_middle2393=== CONT TestIsValidCachePath/wrong_extension2394=== CONT TestIsValidCachePath/short_hash2395=== CONT TestIsValidCachePath/leading_slash23962026/10/01 07:37:49 OK 2_object_stats_trigger.sql (1.13ms)2397--- PASS: TestIsValidCachePath (0.00s)2398 --- PASS: TestIsValidCachePath/narinfo (0.00s)2399 --- PASS: TestIsValidCachePath/index.html (0.00s)2400 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2401 --- PASS: TestIsValidCachePath/realisation (0.00s)2402 --- PASS: TestIsValidCachePath/log (0.00s)2403 --- PASS: TestIsValidCachePath/ls (0.00s)2404 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2405 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2406 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2407 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2408 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2409 --- PASS: TestIsValidCachePath/empty (0.00s)2410 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2411 --- PASS: TestIsValidCachePath/random_path (0.00s)2412 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2413 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2414 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2415 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2416 --- PASS: TestIsValidCachePath/short_hash (0.00s)2417 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2418=== CONT TestCacheConfigHandler/full_config,_no_issuer2419=== CONT TestCacheConfigHandler/no_signing_keys2420=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2421=== CONT TestCacheConfigHandler/no_cache_url_configured2422--- PASS: TestCacheConfigHandler (0.00s)2423 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2424 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2425 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2426 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2427=== CONT TestParseSingleRange/none2428=== CONT TestParseSingleRange/start_past_EOF2429=== CONT TestParseSingleRange/single_byte2430=== CONT TestParseSingleRange/suffix_exceeds_size2431=== CONT TestParseSingleRange/suffix2432=== CONT TestParseSingleRange/end_clamped_to_size2433=== CONT TestParseSingleRange/open-ended2434=== CONT TestParseSingleRange/malformed_no_dash2435=== CONT TestParseSingleRange/multi-range_ignored2436=== CONT TestParseSingleRange/unknown_unit2437=== CONT TestParseSingleRange/start_far_past_EOF2438=== CONT TestParseSingleRange/malformed_both_empty2439=== CONT TestParseSingleRange/closed2440=== CONT TestParseSingleRange/malformed_end_before_start2441--- PASS: TestParseSingleRange (0.00s)2442 --- PASS: TestParseSingleRange/none (0.00s)2443 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2444 --- PASS: TestParseSingleRange/single_byte (0.00s)2445 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2446 --- PASS: TestParseSingleRange/suffix (0.00s)2447 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2448 --- PASS: TestParseSingleRange/open-ended (0.00s)2449 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2450 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2451 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2452 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2453 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2454 --- PASS: TestParseSingleRange/closed (0.00s)2455 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)24562026/10/01 07:37:49 OK 3_commit_push.sql (1.58ms)24572026/10/01 07:37:49 goose: up to current file version: 324582026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes24592026/10/01 07:37:49 INFO lead: acquired remote=192.0.2.1:123424602026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes24612026/10/01 07:37:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24622026/10/01 07:37:49 INFO Uploading sl2qcq2y6xqy2qshmsfv49q1chjp0ivf-test-file.txt (152B)24632026/10/01 07:37:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24642026/10/01 07:37:49 INFO Uploading w1cf1a2r8nw39vsklgvg29xg7ys5fm5v-unpinned-file.txt (128B)2465--- PASS: TestReadProxyNarinfo (0.67s)24662026-10-01 07:37:49.137 UTC [1534] ERROR: relation "goose_db_version" does not exist at character 3624672026-10-01 07:37:49.137 UTC [1534] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24682026/10/01 07:37:49 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"24692026/10/01 07:37:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24702026/10/01 07:37:49 INFO lead: released remote=192.0.2.1:123424712026/10/01 07:37:49 WARN Failed to register uploaded object key=sl2qcq2y6xqy2qshmsfv49q1chjp0ivf.ls error="server returned 404: 404 page not found\n"2472--- PASS: TestLeadElectsOneAndHandsOver (0.85s)24732026/10/01 07:37:49 INFO Signed narinfos id=1 count=124742026/10/01 07:37:49 INFO Uploading 1 narinfos24752026/10/01 07:37:49 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"24762026/10/01 07:37:49 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign24772026/10/01 07:37:49 INFO Signed narinfos id=2 count=124782026/10/01 07:37:49 WARN Failed to register uploaded object key=w1cf1a2r8nw39vsklgvg29xg7ys5fm5v.ls error="server returned 404: 404 page not found\n"24792026/10/01 07:37:49 INFO Uploading 1 narinfos24802026/10/01 07:37:49 INFO Received complete push request method=POST path=/api/pushes/1/complete24812026/10/01 07:37:49 WARN Failed to register uploaded object key=sl2qcq2y6xqy2qshmsfv49q1chjp0ivf.narinfo error="server returned 404: 404 page not found\n"24822026/10/01 07:37:49 INFO Received complete push request method=POST path=/api/pushes/2/complete24832026/10/01 07:37:49 WARN Failed to register uploaded object key=w1cf1a2r8nw39vsklgvg29xg7ys5fm5v.narinfo error="server returned 404: 404 page not found\n"24842026/10/01 07:37:49 INFO Upload complete. (50ms)24852026/10/01 07:37:49 INFO Starting HTTP server address=127.0.0.1:3480324862026/10/01 07:37:49 OK 20241026095416_initial_model.sql (9.27ms)24872026/10/01 07:37:49 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket4182559864/001/proxy.sock24882026/10/01 07:37:49 WARN mTLS auth: subject not in bound subjects subject="CN=someone"24892026/10/01 07:37:49 INFO Shutdown signal received, draining in-flight requests timeout=10s24902026/10/01 07:37:49 OK 20251210153512_drop_unused_gin_index.sql (1.82ms)2491--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.51s)24922026/10/01 07:37:49 INFO Upload complete. (68ms)24932026/10/01 07:37:49 OK 20251218171726_add_pins.sql (2.53ms)24942026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes24952026/10/01 07:37:49 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/present24962026/10/01 07:37:49 OK 20260628120000_add_object_size_and_stats.sql (21.78ms)24972026/10/01 07:37:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24982026/10/01 07:37:49 INFO Uploading v2avd9ak7l1n61zl9j3hx5mpszsy02zr-test-script (136B)24992026/10/01 07:37:49 OK 20260905000000_add_claims.sql (4.01ms)2500=== NAME TestClientCADerivations2501 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2544895770/001/store/kzfkfj1x1ks4cv89dbhid38cbjgqibr3-ca-test25022026/10/01 07:37:49 OK 20260920000000_drop_claims.sql (2.68ms)25032026/10/01 07:37:49 OK 20260923120000_add_pushes.sql (1.98ms)25042026/10/01 07:37:49 goose: successfully migrated database to version: 2026092312000025052026/10/01 07:37:49 INFO Received create pin request method=POST path=/api/pins/myapp25062026/10/01 07:37:49 WARN Failed to register uploaded object key=v2avd9ak7l1n61zl9j3hx5mpszsy02zr.ls error="server returned 404: 404 page not found\n"25072026/10/01 07:37:49 WARN Failed to register uploaded object key=log/s5420ipffw79vb2lybzm18bd0qxdylp0-test-script.drv error="server returned 404: 404 page not found\n"25082026/10/01 07:37:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25092026/10/01 07:37:49 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"25102026/10/01 07:37:49 INFO Signed narinfos id=1 count=125112026/10/01 07:37:49 INFO Uploading 1 narinfos25122026/10/01 07:37:49 OK 1_commit_pending_closure.sql (2.21ms)25132026/10/01 07:37:49 OK 2_object_stats_trigger.sql (780.36µs)25142026/10/01 07:37:49 OK 3_commit_push.sql (955.38µs)25152026/10/01 07:37:49 goose: up to current file version: 325162026-10-01 07:37:49.193 UTC [1624] ERROR: relation "goose_db_version" does not exist at character 3625172026-10-01 07:37:49.193 UTC [1624] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25182026/10/01 07:37:49 INFO Received complete push request method=POST path=/api/pushes/1/complete25192026/10/01 07:37:49 WARN Failed to register uploaded object key=v2avd9ak7l1n61zl9j3hx5mpszsy02zr.narinfo error="server returned 404: 404 page not found\n"2520--- PASS: TestService_ReadAuthMiddleware (0.54s)25212026/10/01 07:37:49 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2426980869/001/store/y388z7xhq75qy9p0pzam7148m244v5g3-pinned-file.txt narinfo_key=y388z7xhq75qy9p0pzam7148m244v5g3.narinfo25222026/10/01 07:37:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures25232026/10/01 07:37:49 INFO All 1 paths already cached25242026/10/01 07:37:49 INFO Garbage collection started2525=== NAME TestClientIntegration2526 client_integration_test.go:312: Retrieved narinfo from S3:2527 StorePath: /build/TestClientIntegration3119793687/002/store/sl2qcq2y6xqy2qshmsfv49q1chjp0ivf-test-file.txt2528 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2529 Compression: zstd2530 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12531 NarSize: 1522532 References: 2533 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12534 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2535 client_integration_test.go:313: Decompressed .ls content (64 bytes):2536 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2537 client_integration_test.go:316: Testing garbage collection...25382026/10/01 07:37:49 INFO Upload complete. (82ms)2539=== NAME TestClientWithDependencies2540 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1844633547/001/store) requires matching store prefix25412026/10/01 07:37:49 OK 20241026095416_initial_model.sql (8.84ms)25422026/10/01 07:37:49 OK 20251210153512_drop_unused_gin_index.sql (1.37ms)25432026/10/01 07:37:49 OK 20251218171726_add_pins.sql (2.6ms)25442026/10/01 07:37:49 INFO Aborted multipart uploads count=02545--- PASS: TestClientWithDependencies (0.93s)25462026/10/01 07:37:49 OK 20260628120000_add_object_size_and_stats.sql (3.86ms)25472026/10/01 07:37:49 WARN Force mode enabled - objects will be deleted immediately without grace period25482026/10/01 07:37:49 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"25492026/10/01 07:37:49 WARN mTLS auth: bound subjects configured but subject DN unavailable25502026/10/01 07:37:49 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2551--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.51s)25522026/10/01 07:37:49 OK 20260905000000_add_claims.sql (3.01ms)25532026/10/01 07:37:49 OK 20260920000000_drop_claims.sql (1.66ms)2554=== NAME TestClientCADerivations2555 client_ca_test.go:139: Found 1 dependencies (including self)25562026/10/01 07:37:49 OK 20260923120000_add_pushes.sql (1.76ms)25572026/10/01 07:37:49 goose: successfully migrated database to version: 2026092312000025582026/10/01 07:37:49 OK 1_commit_pending_closure.sql (1.51ms)25592026/10/01 07:37:49 OK 2_object_stats_trigger.sql (688.58µs)25602026/10/01 07:37:49 OK 3_commit_push.sql (495.1µs)25612026/10/01 07:37:49 goose: up to current file version: 325622026/10/01 07:37:49 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=025632026/10/01 07:37:49 INFO Vacuumed table table=pending_closures25642026/10/01 07:37:49 INFO Vacuumed table table=pending_objects25652026/10/01 07:37:49 INFO Vacuumed table table=multipart_uploads25662026-10-01 07:37:49.236 UTC [1645] ERROR: relation "goose_db_version" does not exist at character 3625672026-10-01 07:37:49.236 UTC [1645] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25682026/10/01 07:37:49 INFO Vacuumed table table=closures25692026/10/01 07:37:49 INFO Vacuumed table table=objects25702026/10/01 07:37:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures25712026/10/01 07:37:49 INFO Garbage collection started25722026/10/01 07:37:49 OK 20241026095416_initial_model.sql (7.42ms)25732026/10/01 07:37:49 OK 20251210153512_drop_unused_gin_index.sql (1.03ms)25742026/10/01 07:37:49 INFO Aborted multipart uploads count=025752026/10/01 07:37:49 OK 20251218171726_add_pins.sql (2.31ms)25762026/10/01 07:37:49 WARN Force mode enabled - objects will be deleted immediately without grace period25772026/10/01 07:37:49 OK 20260628120000_add_object_size_and_stats.sql (1.98ms)25782026/10/01 07:37:49 OK 20260905000000_add_claims.sql (3.29ms)25792026/10/01 07:37:49 OK 20260920000000_drop_claims.sql (1.54ms)25802026/10/01 07:37:49 OK 20260923120000_add_pushes.sql (995.44µs)25812026/10/01 07:37:49 goose: successfully migrated database to version: 2026092312000025822026/10/01 07:37:49 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=209.543636ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present25832026/10/01 07:37:49 OK 1_commit_pending_closure.sql (1.46ms)25842026/10/01 07:37:49 OK 2_object_stats_trigger.sql (856.99µs)25852026/10/01 07:37:49 OK 3_commit_push.sql (781.76µs)25862026/10/01 07:37:49 goose: up to current file version: 325872026/10/01 07:37:49 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=025882026/10/01 07:37:49 INFO Vacuumed table table=pending_closures25892026/10/01 07:37:49 INFO Vacuumed table table=pending_objects25902026/10/01 07:37:49 INFO Vacuumed table table=multipart_uploads25912026/10/01 07:37:49 INFO Vacuumed table table=closures25922026/10/01 07:37:49 INFO Vacuumed table table=objects2593=== RUN TestService_RequireScope_OIDC/builder_may_write2594=== PAUSE TestService_RequireScope_OIDC/builder_may_write2595=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2596=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2597=== RUN TestService_RequireScope_OIDC/ops_may_admin2598=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2599=== RUN TestService_RequireScope_OIDC/ops_may_not_write2600=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2601=== RUN TestService_RequireScope_OIDC/reader_may_not_write2602=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2603=== RUN TestService_RequireScope_OIDC/static_token_may_admin2604=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2605=== RUN TestService_RequireScope_OIDC/static_token_may_write2606=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2607=== RUN TestService_RequireScope_OIDC/reader_may_read2608=== PAUSE TestService_RequireScope_OIDC/reader_may_read2609=== RUN TestService_RequireScope_OIDC/writer_implies_read2610=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2611=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2612=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2613=== CONT TestService_RequireScope_OIDC/builder_may_write2614=== CONT TestService_RequireScope_OIDC/static_token_may_admin2615=== CONT TestService_RequireScope_OIDC/writer_implies_read2616=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2617=== CONT TestService_RequireScope_OIDC/ops_may_not_write2618=== CONT TestService_RequireScope_OIDC/reader_may_not_write2619=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2620=== CONT TestService_RequireScope_OIDC/reader_may_read2621=== CONT TestService_RequireScope_OIDC/ops_may_admin2622=== CONT TestService_RequireScope_OIDC/static_token_may_write2623--- PASS: TestService_RequireScope_OIDC (0.55s)2624 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2625 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2626 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2627 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2628 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2629 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2630 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2631 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2632 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2633 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2634--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.39s)2635--- PASS: TestResurrectedObjectNotDeleted (0.52s)2636=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2637=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2638=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2639=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2640=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2641=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2642=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2643=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2644=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2645=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2646=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected2647=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured26482026/10/01 07:37:49 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]26492026/10/01 07:37:49 WARN Authentication failed token_preview=eyJhbGciOi...yZ1lh2Vm8g token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2650--- PASS: TestService_AuthMiddleware_OIDC (0.56s)2651 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2652 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2653 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2654 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)26552026/10/01 07:37:49 INFO Received push request method=POST path=/api/pushes26562026/10/01 07:37:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26572026/10/01 07:37:49 INFO Uploading kzfkfj1x1ks4cv89dbhid38cbjgqibr3-ca-test (144B)2658--- PASS: TestObjectStatsTrigger (0.41s)26592026/10/01 07:37:49 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"26602026/10/01 07:37:49 WARN Failed to register uploaded object key=kzfkfj1x1ks4cv89dbhid38cbjgqibr3.ls error="server returned 404: 404 page not found\n"26612026/10/01 07:37:49 WARN Failed to register uploaded object key=log/hv2kq4045kgj9dy01ghnhl9asdb4jmy3-ca-test.drv error="server returned 404: 404 page not found\n"26622026/10/01 07:37:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26632026/10/01 07:37:49 INFO Signed narinfos id=1 count=126642026/10/01 07:37:49 INFO Uploading 1 narinfos26652026/10/01 07:37:49 INFO Received complete push request method=POST path=/api/pushes/1/complete26662026/10/01 07:37:49 WARN Failed to register uploaded object key=kzfkfj1x1ks4cv89dbhid38cbjgqibr3.narinfo error="server returned 404: 404 page not found\n"26672026/10/01 07:37:49 INFO Upload complete. (91ms)2668=== NAME TestClientCADerivations2669 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2544895770/001/store/kzfkfj1x1ks4cv89dbhid38cbjgqibr3-ca-test2670 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2671 Compression: zstd2672 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2673 NarSize: 1442674 References: 2675 Deriver: /build/TestClientCADerivations2544895770/001/store/hv2kq4045kgj9dy01ghnhl9asdb4jmy3-ca-test.drv2676 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2677 client_ca_test.go:185: Checking for realisation files in S3...2678 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2679 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache26802026/10/01 07:37:49 INFO Received uploads request method=POST path=/api/pending_closures26812026/10/01 07:37:49 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=433.15658ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present26822026/10/01 07:37:49 INFO Received cleanup request method=DELETE path=/api/pending_closures26832026/10/01 07:37:49 INFO Aborted multipart uploads count=12684 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2685 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2686 error: binary cache 's3://bucket56?endpoint=http://localhost:34297®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2544895770/001/store'2687--- PASS: TestMultipartCleanup (0.45s)2688=== NAME TestClientCADerivations2689 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12690--- PASS: TestClientCADerivations (1.09s)26912026/10/01 07:37:49 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2692=== NAME TestOrphanedObjectsGC2693 orphaned_objects_gc_test.go:290: GC Test Summary:2694 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2695 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2696 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2697 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2698 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2699--- PASS: TestOrphanedObjectsGC (0.77s)27002026/10/01 07:37:49 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2701--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)2702 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)2703 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2704 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.66s)27052026/10/01 07:37:49 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=849.152939ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2706=== NAME TestOrphanedObjectsGCStressTest2707 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2708 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion27092026/10/01 07:37:50 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.568633334s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2710 orphaned_objects_gc_test.go:509: Stress test completed successfully:2711 orphaned_objects_gc_test.go:510: - Active objects preserved: 202712 orphaned_objects_gc_test.go:511: - Objects deleted: 2102713 orphaned_objects_gc_test.go:512: - Total GC'd: 2102714--- PASS: TestOrphanedObjectsGCStressTest (2.04s)27152026/10/01 07:37:51 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02716=== NAME TestPinProtectsFromGC2717 client_integration_test.go:794: Pin successfully protected closure from garbage collection2718--- PASS: TestPinProtectsFromGC (2.96s)27192026/10/01 07:37:51 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02720=== NAME TestClientIntegration2721 client_integration_test.go:323: Objects in database after GC:2722 client_integration_test.go:323: Successfully deleted all objects with GC --force2723--- PASS: TestClientIntegration (2.87s)27242026/10/01 07:37:51 WARN Rate limiter enabled after throttle name=s3-test rate=527252026/10/01 07:37:51 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2726=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2727 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102728 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002729--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.47s)27302026/10/01 07:37:52 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-config27312026/10/01 07:37:52 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=208.647057ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27322026/10/01 07:37:52 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=393.657019ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27332026/10/01 07:37:53 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=743.800365ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27342026/10/01 07:37:53 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.722511933s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27352026/10/01 07:37:55 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"27362026/10/01 07:37:55 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-config27372026/10/01 07:37:55 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=191.066033ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27382026/10/01 07:37:55 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=378.576556ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27392026/10/01 07:37:56 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=802.317593ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27402026/10/01 07:37:57 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.489826134s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config27412026/10/01 07:37:58 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_closures27422026/10/01 07:37:58 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=215.828004ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27432026/10/01 07:37:58 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=410.165158ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27442026/10/01 07:37:59 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=826.696843ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures27452026/10/01 07:38:00 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.530248088s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2746--- PASS: TestClientErrorHandling (0.00s)2747 --- PASS: TestClientErrorHandling/InvalidStorePath (0.36s)2748 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.42s)2749 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.54s)2750PASS2751{"timestamp":"2026-10-01T07:38:01.627745452Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:38342","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(395)"}2752{"timestamp":"2026-10-01T07:38:01.627895182Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:37778","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(395)"}2753{"timestamp":"2026-10-01T07:38:01.628035041Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:38326","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(395)"}27542026-10-01 07:38:01.981 UTC [129] LOG: received smart shutdown request27552026-10-01 07:38:01.984 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 127562026-10-01 07:38:01.996 UTC [134] LOG: shutting down27572026-10-01 07:38:01.996 UTC [134] LOG: checkpoint starting: shutdown immediate27582026-10-01 07:38:02.818 UTC [134] LOG: checkpoint complete: wrote 10630 buffers (64.9%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 20 recycled; write=0.324 s, sync=0.462 s, total=0.823 s; sync files=23917, longest=0.097 s, average=0.001 s; distance=325419 kB, estimate=325419 kB; lsn=0/15530970, redo lsn=0/1553097027592026-10-01 07:38:02.899 UTC [129] LOG: database system is shut down2760Running OIDC tests...2761=== RUN TestAudienceForIssuer2762=== PAUSE TestAudienceForIssuer2763=== RUN TestGlobMatch2764=== PAUSE TestGlobMatch2765=== RUN TestValidateToken_ValidToken2766=== PAUSE TestValidateToken_ValidToken2767=== RUN TestValidateToken_WrongAudience2768=== PAUSE TestValidateToken_WrongAudience2769=== RUN TestValidateToken_Expired2770=== PAUSE TestValidateToken_Expired2771=== RUN TestValidateToken_BoundClaimsMismatch2772=== PAUSE TestValidateToken_BoundClaimsMismatch2773=== RUN TestValidateToken_BoundSubjectMismatch2774=== PAUSE TestValidateToken_BoundSubjectMismatch2775=== RUN TestValidateToken_MultipleProviders2776=== PAUSE TestValidateToken_MultipleProviders2777=== RUN TestValidateToken_NoMatchingProvider2778=== PAUSE TestValidateToken_NoMatchingProvider2779=== RUN TestValidateToken_KubernetesServiceAccount2780=== PAUSE TestValidateToken_KubernetesServiceAccount2781=== RUN TestNewValidator_KubernetesRequiresCA2782=== PAUSE TestNewValidator_KubernetesRequiresCA2783=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2784=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2785=== RUN TestPins_ReservedForMatchingRule2786=== PAUSE TestPins_ReservedForMatchingRule2787=== RUN TestPins_TopLevelShorthand2788=== PAUSE TestPins_TopLevelShorthand2789=== RUN TestPins_ConfigValidation2790=== PAUSE TestPins_ConfigValidation2791=== RUN TestScopes_LegacyProviderDefaultsToWrite2792=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2793=== RUN TestScopes_Rules2794=== PAUSE TestScopes_Rules2795=== RUN TestScopes_ConfigValidation2796=== PAUSE TestScopes_ConfigValidation2797=== CONT TestAudienceForIssuer2798=== CONT TestValidateToken_BoundSubjectMismatch2799--- PASS: TestAudienceForIssuer (0.00s)2800=== CONT TestValidateToken_NoMatchingProvider2801=== CONT TestValidateToken_MultipleProviders2802=== CONT TestValidateToken_BoundClaimsMismatch2803=== CONT TestValidateToken_ValidToken2804=== CONT TestGlobMatch2805=== RUN TestGlobMatch/foo_foo2806=== PAUSE TestGlobMatch/foo_foo2807=== CONT TestValidateToken_KubernetesServiceAccount2808=== CONT TestScopes_ConfigValidation2809=== CONT TestValidateToken_Expired2810=== CONT TestScopes_Rules2811=== CONT TestPins_TopLevelShorthand2812=== CONT TestScopes_LegacyProviderDefaultsToWrite2813=== CONT TestPins_ReservedForMatchingRule2814=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2815=== CONT TestPins_ConfigValidation2816=== CONT TestNewValidator_KubernetesRequiresCA2817=== CONT TestValidateToken_WrongAudience2818=== RUN TestGlobMatch/foo_bar2819=== PAUSE TestGlobMatch/foo_bar2820=== RUN TestGlobMatch/*_2821=== PAUSE TestGlobMatch/*_2822=== RUN TestGlobMatch/*_anything2823=== PAUSE TestGlobMatch/*_anything2824=== RUN TestGlobMatch/foo*_foo2825=== PAUSE TestGlobMatch/foo*_foo2826=== RUN TestGlobMatch/foo*_foobar2827=== PAUSE TestGlobMatch/foo*_foobar2828=== RUN TestGlobMatch/foo*_bar2829=== PAUSE TestGlobMatch/foo*_bar2830=== RUN TestGlobMatch/*bar_bar2831=== PAUSE TestGlobMatch/*bar_bar2832=== RUN TestGlobMatch/*bar_foobar2833=== PAUSE TestGlobMatch/*bar_foobar2834=== RUN TestGlobMatch/*bar_foo2835=== PAUSE TestGlobMatch/*bar_foo2836=== RUN TestGlobMatch/foo*bar_foobar2837=== PAUSE TestGlobMatch/foo*bar_foobar2838=== RUN TestGlobMatch/foo*bar_foo123bar2839=== PAUSE TestGlobMatch/foo*bar_foo123bar2840=== RUN TestGlobMatch/foo*bar_foobarbaz2841=== PAUSE TestGlobMatch/foo*bar_foobarbaz2842=== RUN TestGlobMatch/*/*_foo/bar2843=== PAUSE TestGlobMatch/*/*_foo/bar2844=== RUN TestGlobMatch/*/*_foo2845=== PAUSE TestGlobMatch/*/*_foo2846=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2847=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2848=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02849=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02850=== RUN TestGlobMatch/refs/*/main_refs/heads/main2851=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2852=== RUN TestGlobMatch/fo?_foo2853=== PAUSE TestGlobMatch/fo?_foo2854=== RUN TestGlobMatch/fo?_fo2855=== PAUSE TestGlobMatch/fo?_fo2856--- PASS: TestScopes_ConfigValidation (0.00s)2857=== RUN TestGlobMatch/fo?_fooo2858=== PAUSE TestGlobMatch/fo?_fooo2859=== RUN TestGlobMatch/?oo_foo2860=== PAUSE TestGlobMatch/?oo_foo2861=== RUN TestGlobMatch/?oo_boo2862=== PAUSE TestGlobMatch/?oo_boo2863=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2864=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2865=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2866=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2867=== CONT TestGlobMatch/foo_foo2868=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2869=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2870=== CONT TestGlobMatch/?oo_boo2871=== CONT TestGlobMatch/?oo_foo2872=== CONT TestGlobMatch/foo*bar_foobar2873=== CONT TestGlobMatch/*bar_foo2874=== CONT TestGlobMatch/*bar_foobar2875=== CONT TestGlobMatch/*bar_bar2876=== CONT TestGlobMatch/foo*_bar2877=== CONT TestGlobMatch/foo*_foobar2878=== CONT TestGlobMatch/foo*_foo2879=== CONT TestGlobMatch/*_anything2880=== CONT TestGlobMatch/*_2881=== CONT TestGlobMatch/foo_bar2882=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02883=== CONT TestGlobMatch/fo?_fooo2884=== CONT TestGlobMatch/fo?_fo2885=== CONT TestGlobMatch/foo*bar_foo123bar2886=== CONT TestGlobMatch/refs/*/main_refs/heads/main2887=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2888=== CONT TestGlobMatch/*/*_foo2889=== CONT TestGlobMatch/*/*_foo/bar2890=== CONT TestGlobMatch/foo*bar_foobarbaz2891=== CONT TestGlobMatch/fo?_foo2892--- PASS: TestGlobMatch (0.00s)2893 --- PASS: TestGlobMatch/foo_foo (0.00s)2894 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2895 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2896 --- PASS: TestGlobMatch/?oo_boo (0.00s)2897 --- PASS: TestGlobMatch/?oo_foo (0.00s)2898 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2899 --- PASS: TestGlobMatch/*bar_foo (0.00s)2900 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2901 --- PASS: TestGlobMatch/*bar_bar (0.00s)2902 --- PASS: TestGlobMatch/foo*_bar (0.00s)2903 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2904 --- PASS: TestGlobMatch/foo*_foo (0.00s)2905 --- PASS: TestGlobMatch/*_anything (0.00s)2906 --- PASS: TestGlobMatch/*_ (0.00s)2907 --- PASS: TestGlobMatch/foo_bar (0.00s)2908 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2909 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2910 --- PASS: TestGlobMatch/fo?_fo (0.00s)2911 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2912 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2913 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2914 --- PASS: TestGlobMatch/*/*_foo (0.00s)2915 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2916 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2917 --- PASS: TestGlobMatch/fo?_foo (0.00s)2918--- PASS: TestPins_ConfigValidation (0.00s)29192026/10/01 07:38:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35557/oidc2920--- PASS: TestValidateToken_WrongAudience (0.02s)29212026/10/01 07:38:04 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232922--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.03s)29232026/10/01 07:38:04 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:3925729242026/10/01 07:38:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44415/oidc2925--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.04s)2926--- PASS: TestValidateToken_KubernetesServiceAccount (0.04s)29272026/10/01 07:38:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35977/oidc2928--- PASS: TestValidateToken_Expired (0.04s)29292026/10/01 07:38:04 http: TLS handshake error from 127.0.0.1:40362: remote error: tls: bad certificate2930--- PASS: TestNewValidator_KubernetesRequiresCA (0.06s)29312026/10/01 07:38:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40935/oidc2932--- PASS: TestPins_TopLevelShorthand (0.07s)29332026/10/01 07:38:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44819/oidc29342026/10/01 07:38:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34751/oidc2935--- PASS: TestValidateToken_ValidToken (0.08s)2936--- PASS: TestValidateToken_BoundClaimsMismatch (0.08s)29372026/10/01 07:38:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36713/oidc2938--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)29392026/10/01 07:38:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45349/oidc2940--- PASS: TestPins_ReservedForMatchingRule (0.10s)29412026/10/01 07:38:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44791/oidc2942--- PASS: TestScopes_Rules (0.14s)29432026/10/01 07:38:04 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:44685/oidc29442026/10/01 07:38:04 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:38919/oidc2945--- PASS: TestValidateToken_MultipleProviders (0.17s)29462026/10/01 07:38:04 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:42417/oidc2947--- PASS: TestValidateToken_NoMatchingProvider (0.23s)2948PASS2949Running hook tests...2950=== RUN TestSendPathsEmpty2951=== PAUSE TestSendPathsEmpty2952=== RUN TestQueueEnqueueAndFetch2953=== PAUSE TestQueueEnqueueAndFetch2954=== RUN TestQueueDeduplication2955=== PAUSE TestQueueDeduplication2956=== RUN TestQueueRemove2957=== PAUSE TestQueueRemove2958=== RUN TestQueueFetchBatchLimit2959=== PAUSE TestQueueFetchBatchLimit2960=== RUN TestQueueRetryMovesToBack2961=== PAUSE TestQueueRetryMovesToBack2962=== RUN TestQueueFetchRemoveLifecycle2963=== PAUSE TestQueueFetchRemoveLifecycle2964=== RUN TestQueueConcurrentWriters2965=== PAUSE TestQueueConcurrentWriters2966=== RUN TestQueueRemoveLargeClosure2967=== PAUSE TestQueueRemoveLargeClosure2968=== RUN TestServerClientIntegration2969=== PAUSE TestServerClientIntegration2970=== RUN TestServerQueueError2971=== PAUSE TestServerQueueError2972=== RUN TestGetListenerSocketActivation2973 server_test.go:210: === RUN TestGetListenerSocketActivation2974 --- PASS: TestGetListenerSocketActivation (0.00s)2975 PASS2976 2977--- PASS: TestGetListenerSocketActivation (0.01s)2978=== RUN TestDrainIsolatesPoisonPath2979=== PAUSE TestDrainIsolatesPoisonPath2980=== RUN TestRunNotBlockedByPoisonHead2981=== PAUSE TestRunNotBlockedByPoisonHead2982=== RUN TestDrainGivesUpWhenServerDown2983=== PAUSE TestDrainGivesUpWhenServerDown2984=== RUN TestFailedPathPrunedByLaterClosure2985=== PAUSE TestFailedPathPrunedByLaterClosure2986=== RUN TestWorkerUploadsAndRemoves2987=== PAUSE TestWorkerUploadsAndRemoves2988=== RUN TestWorkerSkipsGCdPaths2989=== PAUSE TestWorkerSkipsGCdPaths2990=== RUN TestWorkerPrunesClosureDeps2991=== PAUSE TestWorkerPrunesClosureDeps2992=== RUN TestDrainTimeout2993=== PAUSE TestDrainTimeout2994=== CONT TestSendPathsEmpty2995=== CONT TestServerQueueError2996--- PASS: TestSendPathsEmpty (0.00s)2997=== CONT TestServerClientIntegration2998=== CONT TestQueueRemoveLargeClosure2999=== CONT TestQueueConcurrentWriters3000=== CONT TestQueueFetchRemoveLifecycle3001=== CONT TestQueueRetryMovesToBack30022026/10/01 07:38:04 ERROR Failed to queue paths error="permission denied" count=13003=== CONT TestWorkerUploadsAndRemoves3004=== CONT TestQueueFetchBatchLimit3005=== CONT TestQueueRemove3006--- PASS: TestServerQueueError (0.00s)3007=== CONT TestDrainTimeout3008=== CONT TestQueueDeduplication3009--- PASS: TestServerClientIntegration (0.00s)3010=== CONT TestWorkerPrunesClosureDeps3011=== CONT TestQueueEnqueueAndFetch3012=== CONT TestWorkerSkipsGCdPaths3013=== CONT TestDrainGivesUpWhenServerDown3014=== CONT TestFailedPathPrunedByLaterClosure3015=== CONT TestRunNotBlockedByPoisonHead3016=== CONT TestDrainIsolatesPoisonPath30172026/10/01 07:38:04 INFO Uploading batch count=130182026/10/01 07:38:04 ERROR Upload failed error="upload failed" count=130192026/10/01 07:38:04 INFO Uploading batch count=230202026/10/01 07:38:04 INFO Uploading batch count=430212026/10/01 07:38:04 ERROR Upload failed error="upload failed" count=430222026/10/01 07:38:04 INFO Upload queue status pending=330232026/10/01 07:38:04 INFO Uploading batch count=130242026/10/01 07:38:04 ERROR Upload failed error="upload failed" count=130252026/10/01 07:38:04 INFO Upload queue status pending=230262026/10/01 07:38:04 INFO Upload queue status pending=230272026/10/01 07:38:04 INFO Upload queue status pending=230282026/10/01 07:38:04 INFO Uploading batch count=230292026/10/01 07:38:04 INFO Uploading batch count=130302026/10/01 07:38:04 INFO Uploading batch count=130312026/10/01 07:38:04 INFO Uploading batch count=230322026/10/01 07:38:04 ERROR Upload failed error="upload failed" count=230332026/10/01 07:38:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1485556423/002/a30342026/10/01 07:38:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2402400989/002/bbb30352026/10/01 07:38:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1285346530/002/nonexistent3036--- PASS: TestQueueDeduplication (0.02s)30372026/10/01 07:38:04 INFO Uploading batch count=13038--- PASS: TestQueueRetryMovesToBack (0.02s)3039--- PASS: TestQueueEnqueueAndFetch (0.02s)3040--- PASS: TestQueueFetchBatchLimit (0.02s)30412026/10/01 07:38:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1485556423/002/b30422026/10/01 07:38:04 INFO Uploading batch count=13043--- PASS: TestQueueRemove (0.02s)3044--- PASS: TestQueueFetchRemoveLifecycle (0.02s)30452026/10/01 07:38:04 INFO Uploading batch count=130462026/10/01 07:38:04 ERROR Upload failed error="upload failed" count=130472026/10/01 07:38:04 INFO Uploading batch count=230482026/10/01 07:38:04 ERROR Upload failed error="upload failed" count=230492026/10/01 07:38:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1485556423/002/c3050--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)30512026/10/01 07:38:04 INFO Uploading batch count=130522026/10/01 07:38:04 ERROR Upload failed error="upload failed" count=130532026/10/01 07:38:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1485556423/002/d30542026/10/01 07:38:04 INFO Uploading batch count=130552026/10/01 07:38:04 ERROR Upload failed error="upload failed" count=130562026/10/01 07:38:04 INFO Uploading batch count=230572026/10/01 07:38:04 ERROR Upload failed error="upload failed" count=230582026/10/01 07:38:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1485556423/002/e30592026/10/01 07:38:04 ERROR Drain finished with paths left in queue remaining=130602026/10/01 07:38:04 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1485556423/002/f30612026/10/01 07:38:04 ERROR Drain finished with paths left in queue remaining=103062--- PASS: TestDrainIsolatesPoisonPath (0.02s)3063--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3064--- PASS: TestWorkerPrunesClosureDeps (0.04s)3065--- PASS: TestWorkerSkipsGCdPaths (0.04s)3066--- PASS: TestWorkerUploadsAndRemoves (0.04s)3067--- PASS: TestQueueRemoveLargeClosure (0.08s)30682026/10/01 07:38:05 ERROR Upload failed error="context deadline exceeded" count=230692026/10/01 07:38:05 ERROR Drain finished with paths left in queue remaining=43070--- PASS: TestDrainTimeout (0.22s)3071--- PASS: TestQueueConcurrentWriters (0.28s)30722026/10/01 07:38:05 INFO Uploading batch count=130732026/10/01 07:38:05 INFO Uploading batch count=130742026/10/01 07:38:05 INFO Uploading batch count=130752026/10/01 07:38:05 ERROR Upload failed error="upload failed" count=130762026/10/01 07:38:05 INFO Uploading batch count=130772026/10/01 07:38:05 ERROR Upload failed error="upload failed" count=130782026/10/01 07:38:05 INFO Uploading batch count=130792026/10/01 07:38:05 ERROR Upload failed error="upload failed" count=130802026/10/01 07:38:05 INFO Uploading batch count=130812026/10/01 07:38:05 ERROR Upload failed error="upload failed" count=130822026/10/01 07:38:05 ERROR Drain finished with paths left in queue remaining=13083--- PASS: TestRunNotBlockedByPoisonHead (1.04s)3084PASS