niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #288
· 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 TestClientSignaturesByStorePath96--- PASS: TestClientSignaturesByStorePath (0.00s)97=== CONT TestDumpPathMatchesNix98=== CONT TestDoServerRequestAttachesToken99=== CONT TestStreamPushReportsSignatures100=== CONT TestStreamPushRequestLine101=== CONT TestStreamPushGivesUpOnDeadServer102=== CONT TestStreamPushIsolatesFailures103=== CONT TestStreamPushBatchesUnderLoad104=== CONT TestStreamPushReportsEveryPath105=== CONT TestShellSplitErrors106=== CONT TestShellSplit107=== CONT TestDoWithRetry_BodyReplayedViaGetBody108=== CONT TestResolveStorePath1092026/10/01 07:36:09 ERROR Upload failed error="bad path" count=31102026/10/01 07:36:09 ERROR Upload failed error="connection refused" count=20111=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1122026/10/01 07:36:09 ERROR Server seems unavailable, giving up on batch untried=17113=== CONT TestFilterOversizedClosures1142026/10/01 07:36:09 ERROR Upload failed error=boom count=1115=== CONT TestRateLimiterFeedback1162026/10/01 07:36:09 WARN Rate limiter enabled after throttle name=server-test rate=5117=== RUN TestRateLimiterFeedback/429_enables_limiter118=== CONT TestPathInfoCACompatibility1192026/10/01 07:36:09 ERROR Upload failed error=boom count=1120=== CONT TestParsePathInfoJSONMultiplePaths121=== CONT TestParsePathInfoJSON122=== CONT TestPathInfoHashCompatibility123=== CONT TestGetStorePathHash124=== CONT TestConvertHashToNix32125=== CONT TestEncodeNixBase32WithRealHash126=== CONT TestEncodeNixBase32127=== CONT TestDumpPathWriterError128=== CONT TestDumpPathSingleFile129--- PASS: TestShellSplitErrors (0.00s)130=== CONT TestUploadMultipart_SupersededByPeer131=== CONT TestPartSizeForNAR132=== CONT TestUploadMultipart_PartsInParallel133=== RUN TestFilterOversizedClosures/no_limit_keeps_everything134=== CONT TestCaseHackSuffix135=== PAUSE TestRateLimiterFeedback/429_enables_limiter136=== CONT TestRegisterUploadedObjectReusesConnections137=== RUN TestPathInfoCACompatibility/null_ca_field138=== RUN TestConvertHashToNix32/SRI_format_to_Nix32139=== CONT TestFileTokenEmpty140=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)141=== RUN TestParsePathInfoJSON/Nix_format142=== RUN TestEncodeNixBase32/test_string_hash143=== RUN TestGetStorePathHash/valid_store_path144=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths145--- PASS: TestResolveStorePath (0.00s)146=== CONT TestScriptTokenBadJSON147--- PASS: TestShellSplit (0.00s)148--- PASS: TestStreamPushIsolatesFailures (0.00s)149--- PASS: TestStreamPushReportsEveryPath (0.00s)150=== PAUSE TestEncodeNixBase32/test_string_hash151=== RUN TestRateLimiterFeedback/503_enables_limiter152=== PAUSE TestGetStorePathHash/valid_store_path153=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)154--- PASS: TestStreamPushReportsSignatures (0.00s)155--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)156--- PASS: TestEncodeNixBase32WithRealHash (0.00s)157=== RUN TestPartSizeForNAR/zero_stays_at_minimum158=== RUN TestEncodeNixBase32/empty_input159=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32160=== PAUSE TestRateLimiterFeedback/503_enables_limiter161=== RUN TestGetStorePathHash/basename_without_hyphen_should_error162=== PAUSE TestParsePathInfoJSON/Nix_format163--- PASS: TestFileTokenEmpty (0.00s)164=== CONT TestScriptTokenEmptyCommand165--- PASS: TestScriptTokenEmptyCommand (0.00s)166=== CONT TestScriptTokenScriptFails167=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter168=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum169=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything170=== RUN TestUploadMultipart_SupersededByPeer/exists171=== PAUSE TestUploadMultipart_SupersededByPeer/exists172=== RUN TestUploadMultipart_SupersededByPeer/missing173=== PAUSE TestUploadMultipart_SupersededByPeer/missing174=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped175=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped176=== RUN TestFilterOversizedClosures/all_closures_skipped177=== CONT TestScriptTokenEmptyToken178=== PAUSE TestEncodeNixBase32/empty_input1792026/10/01 07:36:09 WARN Rate limiter enabled after throttle name=server-test rate=5180=== CONT TestScriptTokenCachesUntilRefresh181=== PAUSE TestFilterOversizedClosures/all_closures_skipped182=== CONT TestScriptTokenNoExpiryRerunsEveryCall1832026/10/01 07:36:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:42443184=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths185=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error186=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon1872026/10/01 07:36:09 WARN Rate limiter backed off name=server-test rate=5188=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon1892026/10/01 07:36:09 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:42443190=== RUN TestConvertHashToNix32/already_Nix32_format191=== PAUSE TestConvertHashToNix32/already_Nix32_format192=== RUN TestConvertHashToNix32/invalid_format193=== PAUSE TestConvertHashToNix32/invalid_format194=== CONT TestFileTokenMissing195=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter196=== CONT TestFileTokenReadsAndCaches197=== CONT TestSetClientTLSDoesNotMutateDefaultTransport198=== CONT TestSetClientTLSErrors199=== PAUSE TestPathInfoCACompatibility/null_ca_field200--- PASS: TestScriptTokenScriptFails (0.00s)201=== CONT TestStaticToken202=== CONT TestSetClientTLS203=== RUN TestParsePathInfoJSON/Lix_format204=== PAUSE TestParsePathInfoJSON/Lix_format205=== RUN TestParsePathInfoJSON/empty_input206=== PAUSE TestParsePathInfoJSON/empty_input207=== CONT TestUploadMultipart_SupersededByPeer/exists208=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths209=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths210=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error211=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error212=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error213=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error214=== CONT TestEncodeNixBase32/empty_input215=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI216=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI217=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512218=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512219=== CONT TestEncodeNixBase32/test_string_hash220=== CONT TestConvertHashToNix32/SRI_format_to_Nix32221=== CONT TestConvertHashToNix32/invalid_format222=== CONT TestConvertHashToNix32/already_Nix32_format223=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths224=== CONT TestUploadMultipart_SupersededByPeer/missing225=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths226=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)227=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped228=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter229=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error2302026/10/01 07:36:09 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=2000231=== RUN TestPartSizeForNAR/small_stays_at_minimum232=== PAUSE TestPartSizeForNAR/small_stays_at_minimum233=== RUN TestPathInfoCACompatibility/old_string_format_-_text234=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text235=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive236=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive237=== RUN TestPathInfoCACompatibility/new_structured_format_-_text238=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text239=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method240=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method241=== CONT TestFilterOversizedClosures/all_closures_skipped2422026/10/01 07:36:09 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=50243=== CONT TestGetStorePathHash/basename_without_hyphen_should_error244=== CONT TestPathInfoCACompatibility/null_ca_field245=== RUN TestParsePathInfoJSON/whitespace_only246=== PAUSE TestParsePathInfoJSON/whitespace_only247=== RUN TestParsePathInfoJSON/invalid_JSON248=== PAUSE TestParsePathInfoJSON/invalid_JSON249=== CONT TestParsePathInfoJSON/Nix_format250=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon251=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method252--- PASS: TestScriptTokenEmptyToken (0.05s)253--- PASS: TestScriptTokenBadJSON (0.05s)254--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.06s)255--- PASS: TestStaticToken (0.00s)256--- PASS: TestDumpPathSingleFile (0.06s)257--- PASS: TestDoServerRequestAttachesToken (0.06s)258=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum259=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum260=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts261=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts262=== RUN TestPartSizeForNAR/1_TiB263=== PAUSE TestPartSizeForNAR/1_TiB264=== RUN TestPartSizeForNAR/5_TiB_S3_max_object265=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object266=== RUN TestPartSizeForNAR/capped_at_5_GiB267=== PAUSE TestPartSizeForNAR/capped_at_5_GiB268--- PASS: TestCaseHackSuffix (0.05s)269--- PASS: TestEncodeNixBase32 (0.01s)270 --- PASS: TestEncodeNixBase32/empty_input (0.00s)271 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)272=== CONT TestPathInfoCACompatibility/new_structured_format_-_text273=== CONT TestParsePathInfoJSON/empty_input274=== CONT TestParsePathInfoJSON/Lix_format275=== CONT TestPartSizeForNAR/zero_stays_at_minimum276=== CONT TestFilterOversizedClosures/no_limit_keeps_everything277=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts278=== CONT TestPartSizeForNAR/5_TiB_S3_max_object279=== CONT TestPartSizeForNAR/1_TiB280=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum281=== CONT TestPartSizeForNAR/small_stays_at_minimum282=== CONT TestParsePathInfoJSON/whitespace_only283=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512284=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI285=== CONT TestGetStorePathHash/valid_store_path286=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive287=== RUN TestSetClientTLSErrors/missing_cert_file288=== CONT TestPathInfoCACompatibility/old_string_format_-_text289=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error290=== CONT TestParsePathInfoJSON/invalid_JSON291=== CONT TestPartSizeForNAR/capped_at_5_GiB292=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter293=== CONT TestRateLimiterFeedback/429_enables_limiter294=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter295=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter296=== CONT TestRateLimiterFeedback/503_enables_limiter297=== PAUSE TestSetClientTLSErrors/missing_cert_file298=== RUN TestSetClientTLSErrors/missing_key_file2992026/10/01 07:36:09 WARN Rate limiter enabled after throttle name=server-test rate=5300=== PAUSE TestSetClientTLSErrors/missing_key_file3012026/10/01 07:36:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:40045302--- PASS: TestConvertHashToNix32 (0.06s)303 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)304 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)305 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)306--- PASS: TestFileTokenMissing (0.00s)307--- PASS: TestFileTokenReadsAndCaches (0.00s)308=== RUN TestSetClientTLSErrors/missing_ca_file309=== PAUSE TestSetClientTLSErrors/missing_ca_file3102026/10/01 07:36:09 WARN Rate limiter backed off name=server-test rate=5311=== RUN TestSetClientTLSErrors/invalid_ca_file312=== PAUSE TestSetClientTLSErrors/invalid_ca_file313=== CONT TestSetClientTLSErrors/missing_cert_file314--- PASS: TestFilterOversizedClosures (0.01s)315 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)316 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)317 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)3182026/10/01 07:36:09 WARN Rate limiter enabled after throttle name=server-test rate=5319=== CONT TestSetClientTLSErrors/missing_ca_file3202026/10/01 07:36:09 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:41193321=== CONT TestSetClientTLSErrors/invalid_ca_file3222026/10/01 07:36:09 WARN Rate limiter backed off name=server-test rate=5323--- PASS: TestPathInfoCACompatibility (0.06s)324 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)325 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)326 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)327 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)328 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)329--- PASS: TestGetStorePathHash (0.06s)330 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)331 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)332 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)333 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)334--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)335--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)336 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)337 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)338=== CONT TestSetClientTLSErrors/missing_key_file339=== RUN TestSetClientTLS/rejects_connection_without_client_cert340--- PASS: TestParsePathInfoJSONMultiplePaths (0.06s)341 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)342 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)343=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert344--- PASS: TestPathInfoHashCompatibility (0.06s)345 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)346 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)347 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)348 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)349=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA350=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA351=== RUN TestSetClientTLS/preserves_debug_logging_transport352=== PAUSE TestSetClientTLS/preserves_debug_logging_transport353=== CONT TestSetClientTLS/rejects_connection_without_client_cert354--- PASS: TestRateLimiterFeedback (0.06s)355 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)356 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)357 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)358 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)359=== CONT TestSetClientTLS/preserves_debug_logging_transport360=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA361--- PASS: TestParsePathInfoJSON (0.06s)362 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)363 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)364 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)365 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)366 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)367--- PASS: TestPartSizeForNAR (0.05s)368 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)369 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)370 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)371 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)372 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)373 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)374 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)375--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)376--- PASS: TestSetClientTLSErrors (0.00s)377 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)378 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)379 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)380 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)381--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)382--- PASS: TestStreamPushRequestLine (0.08s)3832026/10/01 07:36:09 http: TLS handshake error from 127.0.0.1:51406: remote error: tls: bad certificate384--- PASS: TestSetClientTLS (0.01s)385 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)386 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)387 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)388--- PASS: TestRegisterUploadedObjectReusesConnections (0.07s)389--- PASS: TestDumpPathWriterError (0.09s)390--- PASS: TestStreamPushBatchesUnderLoad (0.11s)391--- PASS: TestDumpPathMatchesNix (0.14s)392--- PASS: TestUploadMultipart_PartsInParallel (0.68s)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/postgres556912778/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/postgres556912778/data -l logfile start422423/build/postgres556912778:5432 - no response4242026-10-01 07:36:11.210 UTC [128] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 07:36:11.210 UTC [128] LOG: listening on Unix socket "/build/postgres556912778/.s.PGSQL.5432"4262026-10-01 07:36:11.217 UTC [135] LOG: database system was shut down at 2026-10-01 07:36:10 UTC4272026-10-01 07:36:11.223 UTC [128] LOG: database system is ready to accept connections428/build/postgres556912778:5432 - accepting connections429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestClientPushesUseOnePush462=== PAUSE TestClientPushesUseOnePush463=== RUN TestClientFallsBackToClosures464=== PAUSE TestClientFallsBackToClosures465=== RUN TestResolveDBConnectionString466=== PAUSE TestResolveDBConnectionString467=== RUN TestLeadElectsOneAndHandsOver468=== PAUSE TestLeadElectsOneAndHandsOver469=== RUN TestLeadIncumbentWinsAfterRestart4702026-10-01 07:36:11.728 UTC [565] ERROR: relation "goose_db_version" does not exist at character 364712026-10-01 07:36:11.728 UTC [565] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4722026/10/01 07:36:11 OK 20241026095416_initial_model.sql (9.28ms)4732026/10/01 07:36:11 OK 20251210153512_drop_unused_gin_index.sql (1.45ms)4742026/10/01 07:36:11 OK 20251218171726_add_pins.sql (2.53ms)4752026/10/01 07:36:11 OK 20260628120000_add_object_size_and_stats.sql (2.03ms)4762026/10/01 07:36:11 OK 20260905000000_add_claims.sql (2.51ms)4772026/10/01 07:36:11 OK 20260920000000_drop_claims.sql (1.66ms)4782026/10/01 07:36:11 OK 20260923120000_add_pushes.sql (1.01ms)4792026/10/01 07:36:11 goose: successfully migrated database to version: 202609231200004802026/10/01 07:36:11 OK 1_commit_pending_closure.sql (1.48ms)4812026/10/01 07:36:11 OK 2_object_stats_trigger.sql (691.28µs)4822026/10/01 07:36:11 OK 3_commit_push.sql (453.8µs)4832026/10/01 07:36:11 goose: up to current file version: 34842026/10/01 07:36:11 INFO lead: acquired remote=192.0.2.1:12344852026/10/01 07:36:12 INFO lead: released remote=192.0.2.1:12344862026/10/01 07:36:12 INFO lead: acquired remote=192.0.2.1:12344872026/10/01 07:36:12 INFO lead: released remote=192.0.2.1:1234488--- PASS: TestLeadIncumbentWinsAfterRestart (0.81s)489=== RUN TestLeadEndsOnShutdown490=== PAUSE TestLeadEndsOnShutdown491=== RUN TestGCAdvisoryLockBlocksConcurrentRun4922026-10-01 07:36:12.570 UTC [575] ERROR: relation "goose_db_version" does not exist at character 364932026-10-01 07:36:12.570 UTC [575] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4942026/10/01 07:36:12 OK 20241026095416_initial_model.sql (7.4ms)4952026/10/01 07:36:12 OK 20251210153512_drop_unused_gin_index.sql (1.07ms)4962026/10/01 07:36:12 OK 20251218171726_add_pins.sql (2.3ms)4972026/10/01 07:36:12 OK 20260628120000_add_object_size_and_stats.sql (2.49ms)4982026/10/01 07:36:12 OK 20260905000000_add_claims.sql (2.17ms)4992026/10/01 07:36:12 OK 20260920000000_drop_claims.sql (1.33ms)5002026/10/01 07:36:12 OK 20260923120000_add_pushes.sql (964.26µs)5012026/10/01 07:36:12 goose: successfully migrated database to version: 202609231200005022026/10/01 07:36:12 OK 1_commit_pending_closure.sql (1.47ms)5032026/10/01 07:36:12 OK 2_object_stats_trigger.sql (585.7µs)5042026/10/01 07:36:12 OK 3_commit_push.sql (710.3µs)5052026/10/01 07:36:12 goose: up to current file version: 3506--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.19s)507=== RUN TestGCBugBareHashReferences508=== PAUSE TestGCBugBareHashReferences509=== RUN TestGCMetrics510=== PAUSE TestGCMetrics511=== RUN TestPushDedupSurvivesConcurrentGC512=== PAUSE TestPushDedupSurvivesConcurrentGC513=== RUN TestDeduplicatedObjectsRecordedAsPending514=== PAUSE TestDeduplicatedObjectsRecordedAsPending515=== RUN TestGCSweepSkipsPendingObjects516=== PAUSE TestGCSweepSkipsPendingObjects517=== RUN TestTombstonedObjectOfferedWithoutWaiting518=== PAUSE TestTombstonedObjectOfferedWithoutWaiting519=== RUN TestGCSweepDeliversEachKeyOnce520=== PAUSE TestGCSweepDeliversEachKeyOnce521=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection522=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== RUN TestFailedS3DeleteKeepsTombstone524=== PAUSE TestFailedS3DeleteKeepsTombstone525=== RUN TestSweepSkipsRowsLockedByPush526=== PAUSE TestSweepSkipsRowsLockedByPush527=== RUN TestRegisterCompletedObjectNeedsPendingRow528=== PAUSE TestRegisterCompletedObjectNeedsPendingRow529=== RUN TestGetExistingObjectsLocksRows530=== PAUSE TestGetExistingObjectsLocksRows531=== RUN TestGCTaskStore_StartNew532=== PAUSE TestGCTaskStore_StartNew533=== RUN TestGCTaskStore_DeduplicateSameParams534=== PAUSE TestGCTaskStore_DeduplicateSameParams535=== RUN TestGCTaskStore_ConflictDifferentParams536=== PAUSE TestGCTaskStore_ConflictDifferentParams537=== RUN TestGCTaskStore_GetEmpty538=== PAUSE TestGCTaskStore_GetEmpty539=== RUN TestGCTaskStore_GetReturnsLatest540=== PAUSE TestGCTaskStore_GetReturnsLatest541=== RUN TestGCTaskStore_CompletedAllowsNewTask542=== PAUSE TestGCTaskStore_CompletedAllowsNewTask543=== RUN TestGCTaskStore_PhaseUpdates544=== PAUSE TestGCTaskStore_PhaseUpdates545=== RUN TestGCTaskStore_Fail546=== PAUSE TestGCTaskStore_Fail547=== RUN TestGracefulShutdownDrainsInflight548=== PAUSE TestGracefulShutdownDrainsInflight549=== RUN TestService_healthCheckHandler550=== PAUSE TestService_healthCheckHandler551=== RUN TestService_readinessHandler552=== PAUSE TestService_readinessHandler553=== RUN TestGenerateLandingPage554=== PAUSE TestGenerateLandingPage555=== RUN TestCacheConfigHandlerMaxNarSize556=== PAUSE TestCacheConfigHandlerMaxNarSize557=== RUN TestCreatePendingClosureRejectsOversizedNAR558=== PAUSE TestCreatePendingClosureRejectsOversizedNAR559=== RUN TestNARDeduplicationMetadataUploadBug560=== PAUSE TestNARDeduplicationMetadataUploadBug561=== RUN TestMetricsInventory562=== PAUSE TestMetricsInventory563=== RUN TestService_NativeMTLS564=== PAUSE TestService_NativeMTLS565=== RUN TestServerTLSConfig566=== PAUSE TestServerTLSConfig567=== RUN TestMultipartCleanup568=== PAUSE TestMultipartCleanup569=== RUN TestObjectStatsTrigger570=== PAUSE TestObjectStatsTrigger571=== RUN TestOrphanedObjectsGC572=== PAUSE TestOrphanedObjectsGC573=== RUN TestOrphanedObjectsGCStressTest574=== PAUSE TestOrphanedObjectsGCStressTest575=== RUN TestCreatePin_ReservedPins576=== PAUSE TestCreatePin_ReservedPins577=== RUN TestParseSingleRange578=== PAUSE TestParseSingleRange579=== RUN TestProxyHeadersOnlyTrustedOnSocket580=== PAUSE TestProxyHeadersOnlyTrustedOnSocket581=== RUN TestIsValidCachePath582=== PAUSE TestIsValidCachePath583=== RUN TestReadProxyNarinfo584=== PAUSE TestReadProxyNarinfo585=== RUN TestReadProxyNarinfoAlreadyDecompressed586=== PAUSE TestReadProxyNarinfoAlreadyDecompressed587=== RUN TestReadProxyNarStreaming588=== PAUSE TestReadProxyNarStreaming589=== RUN TestReadProxy404590=== PAUSE TestReadProxy404591=== RUN TestReadProxyInvalidPath592=== PAUSE TestReadProxyInvalidPath593=== RUN TestReadProxyHead594=== PAUSE TestReadProxyHead595=== RUN TestReadProxyConditionalGet596=== PAUSE TestReadProxyConditionalGet597=== RUN TestReadProxyRootRedirectsToIndexHTML598=== PAUSE TestReadProxyRootRedirectsToIndexHTML599=== RUN TestReadProxyDisabled600=== PAUSE TestReadProxyDisabled601=== RUN TestReadRedirectNar602=== PAUSE TestReadRedirectNar603=== RUN TestReadRedirectKeepsNarinfoProxied604=== PAUSE TestReadRedirectKeepsNarinfoProxied605=== RUN TestReadProxyRangeRequest606=== PAUSE TestReadProxyRangeRequest607=== RUN TestReadRedirectUsesPublicS3URL608=== PAUSE TestReadRedirectUsesPublicS3URL609=== RUN TestPush_OverlappingRootsStoreOneRowPerKey610=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey611=== RUN TestPush_CompleteCommitsEveryRoot612=== PAUSE TestPush_CompleteCommitsEveryRoot613=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit614=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit615=== RUN TestPush_RejectsBadRequests616=== PAUSE TestPush_RejectsBadRequests617=== RUN TestPush_SignsNarinfosOfItsPendingObjects618=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects619=== RUN TestRedundantMultipartUpload620=== PAUSE TestRedundantMultipartUpload621=== RUN TestCompleteMultipartUpload_ErrorButObjectExists622=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists623=== RUN TestCompletedNarNotReofferedAcrossClosures624=== PAUSE TestCompletedNarNotReofferedAcrossClosures625=== RUN TestPresignedUploadRegisteredBeforeCommit626=== PAUSE TestPresignedUploadRegisteredBeforeCommit627=== RUN TestService_Rustfstest628=== PAUSE TestService_Rustfstest629=== RUN TestParseSize630=== PAUSE TestParseSize631=== RUN TestSkippedUploadsHandler632=== PAUSE TestSkippedUploadsHandler633=== RUN TestSystemdListenerNotActivated634--- PASS: TestSystemdListenerNotActivated (0.00s)635=== RUN TestWatchdogBeatsWhenHealthy636--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)637=== RUN TestWatchdogSkipsWhenUnhealthy6382026/10/01 07:36:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6392026/10/01 07:36:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6402026/10/01 07:36:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6412026/10/01 07:36:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6422026/10/01 07:36:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6432026/10/01 07:36:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6442026/10/01 07:36:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6452026/10/01 07:36:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6462026/10/01 07:36:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6472026/10/01 07:36:12 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"648--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)649=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle650=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle651=== RUN TestProxyWriteTimeout652=== PAUSE TestProxyWriteTimeout653=== RUN TestIsValidUploadKey654=== PAUSE TestIsValidUploadKey655=== RUN TestUploadHandlersRejectInvalidKeys656=== PAUSE TestUploadHandlersRejectInvalidKeys657=== RUN TestUploadHandlersRejectOversizedBody658=== PAUSE TestUploadHandlersRejectOversizedBody659=== RUN TestService_cleanupPendingClosuresHandler660=== PAUSE TestService_cleanupPendingClosuresHandler661=== RUN TestService_createPendingClosureHandler662=== PAUSE TestService_createPendingClosureHandler663=== RUN TestService_verifyS3Integrity664=== PAUSE TestService_verifyS3Integrity665=== RUN TestCompleteMultipartUnregistered666=== PAUSE TestCompleteMultipartUnregistered667=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT668=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT669=== CONT TestService_AuthMiddleware670=== CONT TestRedundantMultipartUpload671=== CONT TestPush_SignsNarinfosOfItsPendingObjects672=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT673=== CONT TestCompleteMultipartUnregistered674=== CONT TestService_verifyS3Integrity675=== CONT TestService_createPendingClosureHandler676=== CONT TestParseSize677=== CONT TestService_Rustfstest678=== CONT TestPresignedUploadRegisteredBeforeCommit679=== CONT TestCompletedNarNotReofferedAcrossClosures680=== CONT TestCompleteMultipartUpload_ErrorButObjectExists681=== CONT TestSkippedUploadsHandler6822026/10/01 07:36:12 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000683=== CONT TestService_cleanupPendingClosuresHandler684=== CONT TestUploadHandlersRejectOversizedBody685=== CONT TestUploadHandlersRejectInvalidKeys686=== CONT TestIsValidUploadKey687=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info688=== CONT TestProxyWriteTimeout689=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle690=== CONT TestGCTaskStore_CompletedAllowsNewTask691=== CONT TestPush_RejectsBadRequests692=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit693=== CONT TestPush_CompleteCommitsEveryRoot694=== CONT TestPush_OverlappingRootsStoreOneRowPerKey695--- PASS: TestParseSize (0.00s)696=== CONT TestReadRedirectUsesPublicS3URL697=== RUN TestIsValidUploadKey/narinfo698=== PAUSE TestIsValidUploadKey/narinfo699=== RUN TestIsValidUploadKey/nar_zst700=== PAUSE TestIsValidUploadKey/nar_zst701=== RUN TestIsValidUploadKey/nar_xz702=== PAUSE TestIsValidUploadKey/nar_xz703=== RUN TestIsValidUploadKey/nar_plain704=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info705=== RUN TestProxyWriteTimeout/narinfo706=== CONT TestReadProxyRangeRequest707=== PAUSE TestProxyWriteTimeout/narinfo708--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)709=== PAUSE TestIsValidUploadKey/nar_plain710=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal711=== RUN TestProxyWriteTimeout/1_GiB_nar712=== RUN TestIsValidUploadKey/listing713=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal714=== PAUSE TestProxyWriteTimeout/1_GiB_nar715=== RUN TestProxyWriteTimeout/10_GiB_nar716=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key717=== PAUSE TestIsValidUploadKey/listing718=== RUN TestIsValidUploadKey/build_log719=== PAUSE TestProxyWriteTimeout/10_GiB_nar720=== RUN TestProxyWriteTimeout/unknown_size721=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key722=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key723=== PAUSE TestIsValidUploadKey/build_log724=== RUN TestIsValidUploadKey/build_log_home-manager_file725--- PASS: TestSkippedUploadsHandler (0.02s)726=== PAUSE TestProxyWriteTimeout/unknown_size727=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key728=== CONT TestReadProxyDisabled729=== PAUSE TestIsValidUploadKey/build_log_home-manager_file730=== CONT TestReadRedirectKeepsNarinfoProxied731=== CONT TestReadRedirectNar732=== RUN TestIsValidUploadKey/build_log_plus_in_name733=== PAUSE TestIsValidUploadKey/build_log_plus_in_name734=== RUN TestIsValidUploadKey/build_log_question_mark735=== PAUSE TestIsValidUploadKey/build_log_question_mark736=== RUN TestIsValidUploadKey/build_log_equals737=== PAUSE TestIsValidUploadKey/build_log_equals738=== RUN TestIsValidUploadKey/realisation739=== PAUSE TestIsValidUploadKey/realisation740=== 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 TestReadProxyRootRedirectsToIndexHTML763=== 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 TestReadProxyConditionalGet7702026-10-01 07:36:13.075 UTC [642] ERROR: relation "goose_db_version" does not exist at character 367712026-10-01 07:36:13.075 UTC [642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7722026-10-01 07:36:13.165 UTC [643] ERROR: relation "goose_db_version" does not exist at character 367732026-10-01 07:36:13.165 UTC [643] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7742026-10-01 07:36:13.226 UTC [644] ERROR: relation "goose_db_version" does not exist at character 367752026-10-01 07:36:13.226 UTC [644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7762026/10/01 07:36:13 OK 20241026095416_initial_model.sql (91.47ms)7772026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (9.17ms)7782026/10/01 07:36:13 OK 20251218171726_add_pins.sql (24.88ms)7792026/10/01 07:36:13 OK 20241026095416_initial_model.sql (63.87ms)7802026/10/01 07:36:13 OK 20241026095416_initial_model.sql (38.08ms)7812026-10-01 07:36:13.296 UTC [650] ERROR: relation "goose_db_version" does not exist at character 367822026-10-01 07:36:13.296 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7832026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (12.78ms)7842026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (6.44ms)7852026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (5.94ms)7862026-10-01 07:36:13.301 UTC [652] ERROR: relation "goose_db_version" does not exist at character 367872026-10-01 07:36:13.301 UTC [652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7882026-10-01 07:36:13.301 UTC [651] ERROR: relation "goose_db_version" does not exist at character 367892026-10-01 07:36:13.301 UTC [651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7902026-10-01 07:36:13.302 UTC [653] ERROR: relation "goose_db_version" does not exist at character 367912026-10-01 07:36:13.302 UTC [653] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7922026-10-01 07:36:13.302 UTC [655] ERROR: relation "goose_db_version" does not exist at character 367932026-10-01 07:36:13.302 UTC [655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7942026-10-01 07:36:13.302 UTC [654] ERROR: relation "goose_db_version" does not exist at character 367952026-10-01 07:36:13.302 UTC [654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7962026/10/01 07:36:13 OK 20260905000000_add_claims.sql (6.52ms)7972026/10/01 07:36:13 OK 20251218171726_add_pins.sql (8.12ms)7982026-10-01 07:36:13.313 UTC [656] ERROR: relation "goose_db_version" does not exist at character 367992026-10-01 07:36:13.313 UTC [656] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8002026/10/01 07:36:13 OK 20251218171726_add_pins.sql (19.9ms)8012026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (14.14ms)8022026-10-01 07:36:13.320 UTC [657] ERROR: relation "goose_db_version" does not exist at character 368032026-10-01 07:36:13.320 UTC [657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8042026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (16.39ms)8052026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (7.75ms)8062026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200008072026/10/01 07:36:13 OK 20260905000000_add_claims.sql (5.24ms)8082026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (9.89ms)8092026/10/01 07:36:13 OK 20260905000000_add_claims.sql (6.36ms)8102026/10/01 07:36:13 OK 1_commit_pending_closure.sql (7.8ms)8112026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (7.41ms)8122026-10-01 07:36:13.338 UTC [662] ERROR: relation "goose_db_version" does not exist at character 368132026-10-01 07:36:13.338 UTC [662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8142026-10-01 07:36:13.339 UTC [660] ERROR: relation "goose_db_version" does not exist at character 368152026-10-01 07:36:13.339 UTC [660] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8162026-10-01 07:36:13.339 UTC [658] ERROR: relation "goose_db_version" does not exist at character 368172026-10-01 07:36:13.339 UTC [658] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8182026-10-01 07:36:13.339 UTC [659] ERROR: relation "goose_db_version" does not exist at character 368192026-10-01 07:36:13.339 UTC [659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8202026/10/01 07:36:13 OK 20241026095416_initial_model.sql (13.75ms)8212026-10-01 07:36:13.340 UTC [664] ERROR: relation "goose_db_version" does not exist at character 368222026-10-01 07:36:13.340 UTC [664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8232026-10-01 07:36:13.340 UTC [661] ERROR: relation "goose_db_version" does not exist at character 368242026-10-01 07:36:13.340 UTC [661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8252026-10-01 07:36:13.340 UTC [663] ERROR: relation "goose_db_version" does not exist at character 368262026-10-01 07:36:13.340 UTC [663] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8272026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (4.43ms)8282026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200008292026/10/01 07:36:13 OK 20241026095416_initial_model.sql (16.36ms)8302026/10/01 07:36:13 OK 20241026095416_initial_model.sql (16.29ms)8312026/10/01 07:36:13 OK 2_object_stats_trigger.sql (5.45ms)8322026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (6.11ms)8332026/10/01 07:36:13 OK 20241026095416_initial_model.sql (17.36ms)8342026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (3.52ms)8352026/10/01 07:36:13 OK 20241026095416_initial_model.sql (17.53ms)8362026/10/01 07:36:13 OK 20241026095416_initial_model.sql (17.95ms)8372026/10/01 07:36:13 OK 3_commit_push.sql (1.8ms)8382026/10/01 07:36:13 goose: up to current file version: 38392026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)8402026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.68ms)8412026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.52ms)8422026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200008432026/10/01 07:36:13 OK 1_commit_pending_closure.sql (3.75ms)8442026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)8452026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (3.06ms)8462026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (3.58ms)8472026-10-01 07:36:13.348 UTC [665] ERROR: relation "goose_db_version" does not exist at character 368482026-10-01 07:36:13.348 UTC [665] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8492026/10/01 07:36:13 OK 2_object_stats_trigger.sql (2.52ms)8502026/10/01 07:36:13 OK 20241026095416_initial_model.sql (12.63ms)8512026/10/01 07:36:13 OK 20251218171726_add_pins.sql (4.21ms)8522026/10/01 07:36:13 OK 20241026095416_initial_model.sql (11.56ms)8532026/10/01 07:36:13 OK 20251218171726_add_pins.sql (5.56ms)8542026/10/01 07:36:13 OK 20251218171726_add_pins.sql (4.08ms)8552026/10/01 07:36:13 OK 3_commit_push.sql (1.73ms)8562026/10/01 07:36:13 goose: up to current file version: 38572026/10/01 07:36:13 OK 1_commit_pending_closure.sql (5.02ms)8582026/10/01 07:36:13 OK 20251218171726_add_pins.sql (4.29ms)8592026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (1.83ms)8602026/10/01 07:36:13 OK 20251218171726_add_pins.sql (5.27ms)8612026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)8622026-10-01 07:36:13.353 UTC [666] ERROR: relation "goose_db_version" does not exist at character 368632026-10-01 07:36:13.353 UTC [666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8642026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.93ms)8652026/10/01 07:36:13 OK 20251218171726_add_pins.sql (5.08ms)8662026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.5ms)8672026/10/01 07:36:13 OK 3_commit_push.sql (2.12ms)8682026/10/01 07:36:13 goose: up to current file version: 38692026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (5.75ms)8702026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (5.35ms)8712026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (6.17ms)8722026-10-01 07:36:13.357 UTC [667] ERROR: relation "goose_db_version" does not exist at character 368732026-10-01 07:36:13.357 UTC [667] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8742026/10/01 07:36:13 OK 20251218171726_add_pins.sql (4.8ms)8752026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (6.83ms)8762026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (6.14ms)8772026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.16ms)8782026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (5.97ms)8792026-10-01 07:36:13.359 UTC [668] ERROR: relation "goose_db_version" does not exist at character 368802026-10-01 07:36:13.359 UTC [668] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8812026-10-01 07:36:13.360 UTC [669] ERROR: relation "goose_db_version" does not exist at character 368822026-10-01 07:36:13.360 UTC [669] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8832026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (5.23ms)8842026/10/01 07:36:13 OK 20260905000000_add_claims.sql (4.54ms)8852026/10/01 07:36:13 OK 20241026095416_initial_model.sql (12.72ms)8862026/10/01 07:36:13 OK 20241026095416_initial_model.sql (13.3ms)8872026/10/01 07:36:13 OK 20260905000000_add_claims.sql (6.9ms)8882026/10/01 07:36:13 OK 20260905000000_add_claims.sql (4.81ms)8892026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (6.18ms)8902026/10/01 07:36:13 OK 20260905000000_add_claims.sql (5.05ms)8912026/10/01 07:36:13 OK 20241026095416_initial_model.sql (12.44ms)8922026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (4.69ms)8932026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (3.24ms)8942026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.62ms)8952026/10/01 07:36:13 OK 20260905000000_add_claims.sql (5.03ms)8962026/10/01 07:36:13 OK 20241026095416_initial_model.sql (13.21ms)8972026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.75ms)8982026/10/01 07:36:13 OK 20241026095416_initial_model.sql (11.81ms)8992026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (3.63ms)9002026/10/01 07:36:13 OK 20241026095416_initial_model.sql (13.6ms)9012026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.95ms)9022026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.77ms)9032026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (3.66ms)9042026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (4.15ms)9052026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (3.95ms)9062026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (3.61ms)9072026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200009082026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (3.42ms)9092026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200009102026/10/01 07:36:13 OK 20260905000000_add_claims.sql (4.01ms)9112026/10/01 07:36:13 OK 20241026095416_initial_model.sql (14.35ms)9122026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (3.11ms)9132026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (1.85ms)9142026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (4.09ms)9152026/10/01 07:36:13 OK 20241026095416_initial_model.sql (13.43ms)9162026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.29ms)9172026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.35ms)9182026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.39ms)9192026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200009202026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.7ms)9212026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200009222026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.43ms)9232026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200009242026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.63ms)9252026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.55ms)9262026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (3.07ms)9272026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200009282026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.49ms)9292026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.16ms)9302026/10/01 07:36:13 OK 1_commit_pending_closure.sql (3.45ms)9312026/10/01 07:36:13 OK 1_commit_pending_closure.sql (3.35ms)9322026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.33ms)9332026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200009342026/10/01 07:36:13 OK 20251218171726_add_pins.sql (2.96ms)9352026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.65ms)9362026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.98ms)9372026/10/01 07:36:13 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"9382026/10/01 07:36:13 OK 2_object_stats_trigger.sql (2.12ms)939--- PASS: TestService_AuthMiddleware (0.52s)9402026/10/01 07:36:13 OK 20251218171726_add_pins.sql (4.15ms)941=== CONT TestReadProxyHead9422026-10-01 07:36:13.374 UTC [670] ERROR: relation "goose_db_version" does not exist at character 369432026-10-01 07:36:13.374 UTC [670] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9442026/10/01 07:36:13 OK 1_commit_pending_closure.sql (3.36ms)9452026/10/01 07:36:13 OK 1_commit_pending_closure.sql (3.57ms)9462026/10/01 07:36:13 OK 2_object_stats_trigger.sql (2.14ms)9472026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.27ms)9482026/10/01 07:36:13 OK 20241026095416_initial_model.sql (10.17ms)9492026/10/01 07:36:13 OK 1_commit_pending_closure.sql (3.57ms)9502026/10/01 07:36:13 OK 1_commit_pending_closure.sql (3.19ms)9512026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.65ms)9522026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200009532026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.62ms)9542026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.95ms)9552026/10/01 07:36:13 OK 3_commit_push.sql (1.92ms)9562026/10/01 07:36:13 goose: up to current file version: 39572026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.61ms)9582026/10/01 07:36:13 OK 3_commit_push.sql (1.57ms)9592026/10/01 07:36:13 goose: up to current file version: 39602026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.96ms)9612026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (5.04ms)9622026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.93ms)9632026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.13ms)9642026/10/01 07:36:13 OK 2_object_stats_trigger.sql (2.37ms)9652026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.85ms)9662026/10/01 07:36:13 OK 20251218171726_add_pins.sql (4.13ms)9672026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.89ms)9682026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (5.03ms)9692026/10/01 07:36:13 OK 3_commit_push.sql (1.56ms)9702026/10/01 07:36:13 goose: up to current file version: 39712026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.74ms)9722026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.67ms)9732026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.36ms)9742026/10/01 07:36:13 OK 3_commit_push.sql (1.93ms)9752026/10/01 07:36:13 goose: up to current file version: 39762026/10/01 07:36:13 OK 3_commit_push.sql (1.85ms)9772026/10/01 07:36:13 goose: up to current file version: 39782026/10/01 07:36:13 OK 3_commit_push.sql (1.62ms)9792026/10/01 07:36:13 goose: up to current file version: 39802026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.56ms)9812026/10/01 07:36:13 OK 20241026095416_initial_model.sql (11.1ms)9822026/10/01 07:36:13 OK 3_commit_push.sql (2.42ms)9832026/10/01 07:36:13 goose: up to current file version: 39842026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.37ms)9852026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (5.52ms)9862026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.66ms)9872026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.85ms)9882026/10/01 07:36:13 OK 20241026095416_initial_model.sql (11.81ms)9892026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.44ms)9902026/10/01 07:36:13 OK 3_commit_push.sql (1.26ms)9912026/10/01 07:36:13 goose: up to current file version: 39922026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.61ms)9932026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.22ms)9942026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.27ms)9952026/10/01 07:36:13 OK 20241026095416_initial_model.sql (11.5ms)9962026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.61ms)9972026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.38ms)9982026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.42ms)9992026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.77ms)10002026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.66ms)10012026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.51ms)10022026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010032026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.09ms)10042026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.78ms)10052026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.88ms)10062026/10/01 07:36:13 OK 20260905000000_add_claims.sql (2.81ms)10072026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (3.82ms)10082026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (3.07ms)10092026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.6ms)10102026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (1.89ms)10112026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010122026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.38ms)10132026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.54ms)10142026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010152026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (1.57ms)10162026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010172026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.14ms)10182026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.71ms)10192026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.44ms)10202026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.58ms)10212026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.07ms)10222026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010232026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.7ms)10242026/10/01 07:36:13 OK 20260905000000_add_claims.sql (2.82ms)10252026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.2ms)10262026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.67ms)10272026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.93ms)10282026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.29ms)10292026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (1.66ms)10302026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010312026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (1.63ms)10322026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010332026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.74ms)10342026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.1ms)10352026/10/01 07:36:13 OK 3_commit_push.sql (994.5µs)10362026/10/01 07:36:13 goose: up to current file version: 310372026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.07ms)10382026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010392026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.52ms)10402026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.44ms)10412026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.11ms)10422026/10/01 07:36:13 OK 2_object_stats_trigger.sql (2.11ms)10432026/10/01 07:36:13 OK 20241026095416_initial_model.sql (10.33ms)10442026/10/01 07:36:13 OK 3_commit_push.sql (1.11ms)10452026/10/01 07:36:13 goose: up to current file version: 310462026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.92ms)10472026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (1.35ms)10482026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010492026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.18ms)10502026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.37ms)10512026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.13ms)10522026/10/01 07:36:13 OK 2_object_stats_trigger.sql (2ms)10532026/10/01 07:36:13 OK 3_commit_push.sql (711.67µs)10542026/10/01 07:36:13 goose: up to current file version: 310552026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (1.2ms)10562026/10/01 07:36:13 OK 3_commit_push.sql (1.18ms)10572026/10/01 07:36:13 goose: up to current file version: 310582026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (6ms)10592026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.77ms)10602026/10/01 07:36:13 OK 3_commit_push.sql (1.25ms)10612026/10/01 07:36:13 goose: up to current file version: 310622026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.42ms)10632026/10/01 07:36:13 OK 1_commit_pending_closure.sql (1.93ms)10642026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.32ms)10652026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.48ms)10662026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.54ms)10672026/10/01 07:36:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10682026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.64ms)10692026/10/01 07:36:13 OK 3_commit_push.sql (1.52ms)10702026/10/01 07:36:13 goose: up to current file version: 310712026/10/01 07:36:13 OK 20251218171726_add_pins.sql (2.96ms)10722026/10/01 07:36:13 OK 3_commit_push.sql (813.95µs)10732026/10/01 07:36:13 goose: up to current file version: 310742026/10/01 07:36:13 OK 3_commit_push.sql (1.78ms)10752026/10/01 07:36:13 goose: up to current file version: 310762026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.62ms)10772026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.25ms)10782026/10/01 07:36:13 OK 3_commit_push.sql (574.3µs)10792026/10/01 07:36:13 goose: up to current file version: 310802026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.48ms)10812026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (1.72ms)10822026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (1.64ms)10832026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010842026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.32ms)10852026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (3.39ms)10862026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (1.44ms)10872026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010882026/10/01 07:36:13 OK 1_commit_pending_closure.sql (1.91ms)10892026/10/01 07:36:13 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1090--- PASS: TestCompleteMultipartUnregistered (0.55s)1091=== CONT TestReadProxyInvalidPath10922026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.2ms)10932026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000010942026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.77ms)10952026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.64ms)10962026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.03ms)10972026/10/01 07:36:13 OK 3_commit_push.sql (1.65ms)10982026/10/01 07:36:13 goose: up to current file version: 310992026/10/01 07:36:13 OK 2_object_stats_trigger.sql (3.07ms)11002026/10/01 07:36:13 OK 1_commit_pending_closure.sql (3.98ms)11012026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (3.58ms)11022026/10/01 07:36:13 OK 3_commit_push.sql (826.17µs)11032026/10/01 07:36:13 goose: up to current file version: 311042026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.31ms)11052026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (1.36ms)11062026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000011072026/10/01 07:36:13 OK 3_commit_push.sql (783.48µs)11082026/10/01 07:36:13 goose: up to current file version: 311092026/10/01 07:36:13 OK 1_commit_pending_closure.sql (1.52ms)11102026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures11112026/10/01 07:36:13 OK 2_object_stats_trigger.sql (876.13µs)11122026/10/01 07:36:13 OK 3_commit_push.sql (799.22µs)11132026/10/01 07:36:13 goose: up to current file version: 311142026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures11152026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures1116--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.59s)1117=== CONT TestReadProxy40411182026/10/01 07:36:13 INFO Received push request method=POST path=/api/pushes11192026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures11202026/10/01 07:36:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11212026/10/01 07:36:13 INFO Signed narinfos id=1 count=11122--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.63s)1123=== CONT TestReadProxyNarStreaming11242026-10-01 07:36:13.487 UTC [679] ERROR: relation "goose_db_version" does not exist at character 3611252026-10-01 07:36:13.487 UTC [679] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11262026/10/01 07:36:13 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11272026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures1128--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.63s)1129=== CONT TestReadProxyNarinfoAlreadyDecompressed11302026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures11312026-10-01 07:36:13.500 UTC [683] ERROR: relation "goose_db_version" does not exist at character 3611322026-10-01 07:36:13.500 UTC [683] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11332026/10/01 07:36:13 OK 20241026095416_initial_model.sql (12.06ms)11342026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.32ms)11352026/10/01 07:36:13 OK 20251218171726_add_pins.sql (4.56ms)11362026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.83ms)11372026/10/01 07:36:13 OK 20241026095416_initial_model.sql (13.22ms)11382026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.96ms)11392026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures11402026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (3.15ms)11412026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.79ms)11422026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.24ms)11432026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000011442026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.73ms)11452026/10/01 07:36:13 OK 1_commit_pending_closure.sql (1.8ms)11462026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.04ms)11472026/10/01 07:36:13 OK 3_commit_push.sql (2.18ms)11482026/10/01 07:36:13 goose: up to current file version: 311492026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.87ms)11502026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.62ms)11512026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.71ms)11522026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (1.84ms)11532026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000011542026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.24ms)11552026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.14ms)11562026/10/01 07:36:13 OK 3_commit_push.sql (1.26ms)11572026/10/01 07:36:13 goose: up to current file version: 311582026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures11592026-10-01 07:36:13.583 UTC [685] ERROR: relation "goose_db_version" does not exist at character 3611602026-10-01 07:36:13.583 UTC [685] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11612026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures11622026/10/01 07:36:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11632026/10/01 07:36:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11642026/10/01 07:36:13 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MGE0MjIyOTAtNjUxOS00MDMxLWJlZDUtMmFiNDhiMWFmOGZkLjJkZDRhNzAwLTA1MDUtNDA5Ni1iYzIzLTZhODQ3Njc1M2YxNngxNzkwODQwMTczNTY4MjcyMDUw11652026-10-01 07:36:13.639 UTC [686] ERROR: relation "goose_db_version" does not exist at character 3611662026-10-01 07:36:13.639 UTC [686] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11672026/10/01 07:36:13 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MGE0MjIyOTAtNjUxOS00MDMxLWJlZDUtMmFiNDhiMWFmOGZkLjJkZDRhNzAwLTA1MDUtNDA5Ni1iYzIzLTZhODQ3Njc1M2YxNngxNzkwODQwMTczNTY4MjcyMDUw parts=11168--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.79s)1169=== CONT TestReadProxyNarinfo11702026-10-01 07:36:13.651 UTC [687] ERROR: relation "goose_db_version" does not exist at character 3611712026-10-01 07:36:13.651 UTC [687] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11722026/10/01 07:36:13 OK 20241026095416_initial_model.sql (22.84ms)1173--- PASS: TestService_Rustfstest (0.82s)1174=== CONT TestIsValidCachePath1175=== RUN TestIsValidCachePath/narinfo1176=== PAUSE TestIsValidCachePath/narinfo1177=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1178=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1179=== RUN TestIsValidCachePath/nar_zst1180=== PAUSE TestIsValidCachePath/nar_zst1181=== RUN TestIsValidCachePath/nar_xz1182=== PAUSE TestIsValidCachePath/nar_xz1183=== RUN TestIsValidCachePath/nar_bz21184=== PAUSE TestIsValidCachePath/nar_bz21185=== RUN TestIsValidCachePath/nar_uncompressed1186=== PAUSE TestIsValidCachePath/nar_uncompressed1187=== RUN TestIsValidCachePath/ls1188=== PAUSE TestIsValidCachePath/ls1189=== RUN TestIsValidCachePath/log1190=== PAUSE TestIsValidCachePath/log1191=== RUN TestIsValidCachePath/realisation1192=== PAUSE TestIsValidCachePath/realisation1193=== RUN TestIsValidCachePath/nix-cache-info1194=== PAUSE TestIsValidCachePath/nix-cache-info1195=== RUN TestIsValidCachePath/index.html1196=== PAUSE TestIsValidCachePath/index.html1197=== RUN TestIsValidCachePath/traversal_parent1198=== PAUSE TestIsValidCachePath/traversal_parent1199=== RUN TestIsValidCachePath/traversal_in_middle1200=== PAUSE TestIsValidCachePath/traversal_in_middle1201=== RUN TestIsValidCachePath/invalid_char_e1202=== PAUSE TestIsValidCachePath/invalid_char_e1203=== RUN TestIsValidCachePath/invalid_char_u1204=== PAUSE TestIsValidCachePath/invalid_char_u1205=== RUN TestIsValidCachePath/random_path1206=== PAUSE TestIsValidCachePath/random_path1207=== RUN TestIsValidCachePath/empty1208=== PAUSE TestIsValidCachePath/empty1209=== RUN TestIsValidCachePath/leading_slash1210=== PAUSE TestIsValidCachePath/leading_slash1211=== RUN TestIsValidCachePath/wrong_extension1212=== PAUSE TestIsValidCachePath/wrong_extension1213=== RUN TestIsValidCachePath/short_hash1214=== PAUSE TestIsValidCachePath/short_hash1215=== CONT TestProxyHeadersOnlyTrustedOnSocket12162026/10/01 07:36:13 OK 20241026095416_initial_model.sql (19.51ms)12172026/10/01 07:36:13 OK 20241026095416_initial_model.sql (27.06ms)12182026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (20.09ms)12192026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (4.26ms)12202026/10/01 07:36:13 OK 20251218171726_add_pins.sql (6.14ms)12212026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (6.3ms)12222026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.13ms)12232026/10/01 07:36:13 OK 20251218171726_add_pins.sql (4.13ms)12242026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)12252026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (6.32ms)12262026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.22ms)12272026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (3.87ms)12282026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.23ms)12292026/10/01 07:36:13 OK 20260905000000_add_claims.sql (4.97ms)12302026/10/01 07:36:13 OK 20260905000000_add_claims.sql (4.15ms)12312026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.86ms)12322026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000012332026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (3.55ms)12342026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.72ms)12352026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.05ms)12362026/10/01 07:36:13 OK 2_object_stats_trigger.sql (2.16ms)12372026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (3.55ms)12382026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000012392026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (3.81ms)12402026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000012412026/10/01 07:36:13 OK 3_commit_push.sql (1.84ms)12422026/10/01 07:36:13 goose: up to current file version: 312432026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.87ms)12442026/10/01 07:36:13 OK 1_commit_pending_closure.sql (3.28ms)12452026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.56ms)12462026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.74ms)1247=== RUN TestPush_RejectsBadRequests/no_roots1248=== PAUSE TestPush_RejectsBadRequests/no_roots1249=== RUN TestPush_RejectsBadRequests/no_objects1250=== PAUSE TestPush_RejectsBadRequests/no_objects1251=== RUN TestPush_RejectsBadRequests/bad_root1252=== PAUSE TestPush_RejectsBadRequests/bad_root1253=== RUN TestPush_RejectsBadRequests/root_not_in_objects12542026/10/01 07:36:13 OK 3_commit_push.sql (1.51ms)1255=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects12562026/10/01 07:36:13 goose: up to current file version: 31257=== CONT TestParseSingleRange1258=== RUN TestParseSingleRange/none1259=== PAUSE TestParseSingleRange/none1260=== RUN TestParseSingleRange/unknown_unit1261=== PAUSE TestParseSingleRange/unknown_unit1262=== RUN TestParseSingleRange/multi-range_ignored1263=== PAUSE TestParseSingleRange/multi-range_ignored1264=== RUN TestParseSingleRange/malformed_no_dash1265=== PAUSE TestParseSingleRange/malformed_no_dash1266=== RUN TestParseSingleRange/malformed_both_empty12672026/10/01 07:36:13 OK 3_commit_push.sql (1.32ms)1268=== PAUSE TestParseSingleRange/malformed_both_empty12692026/10/01 07:36:13 goose: up to current file version: 31270=== RUN TestParseSingleRange/malformed_end_before_start1271=== PAUSE TestParseSingleRange/malformed_end_before_start1272=== RUN TestParseSingleRange/closed1273=== PAUSE TestParseSingleRange/closed1274=== RUN TestParseSingleRange/open-ended1275=== PAUSE TestParseSingleRange/open-ended1276=== RUN TestParseSingleRange/end_clamped_to_size1277=== PAUSE TestParseSingleRange/end_clamped_to_size1278=== RUN TestParseSingleRange/suffix1279=== PAUSE TestParseSingleRange/suffix1280=== RUN TestParseSingleRange/suffix_exceeds_size1281=== PAUSE TestParseSingleRange/suffix_exceeds_size1282=== RUN TestParseSingleRange/single_byte1283=== PAUSE TestParseSingleRange/single_byte1284=== RUN TestParseSingleRange/start_past_EOF1285=== PAUSE TestParseSingleRange/start_past_EOF1286=== RUN TestParseSingleRange/start_far_past_EOF1287=== PAUSE TestParseSingleRange/start_far_past_EOF1288=== CONT TestCreatePin_ReservedPins12892026/10/01 07:36:13 INFO Received push request method=POST path=/api/pushes12902026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures12912026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures12922026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures1293--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.91s)1294=== CONT TestOrphanedObjectsGCStressTest12952026-10-01 07:36:13.787 UTC [697] ERROR: relation "goose_db_version" does not exist at character 3612962026-10-01 07:36:13.787 UTC [697] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12972026/10/01 07:36:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42521/oidc1298--- PASS: TestReadRedirectNar (0.85s)1299=== CONT TestOrphanedObjectsGC13002026-10-01 07:36:13.790 UTC [698] ERROR: relation "goose_db_version" does not exist at character 3613012026-10-01 07:36:13.790 UTC [698] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13022026/10/01 07:36:13 INFO Received push request method=POST path=/api/pushes13032026/10/01 07:36:13 OK 20241026095416_initial_model.sql (11.37ms)13042026/10/01 07:36:13 OK 20241026095416_initial_model.sql (9.69ms)13052026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)13062026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (1.46ms)13072026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.19ms)13082026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.15ms)13092026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.61ms)13102026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.45ms)13112026/10/01 07:36:13 OK 20260905000000_add_claims.sql (2.43ms)13122026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.76ms)13132026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (1.74ms)13142026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.42ms)13152026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (1.73ms)13162026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000013172026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.18ms)13182026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.87ms)13192026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000013202026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.06ms)13212026/10/01 07:36:13 INFO Received complete push request method=POST path=/api/pushes/1/complete13222026/10/01 07:36:13 OK 3_commit_push.sql (797.42µs)13232026/10/01 07:36:13 goose: up to current file version: 313242026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.56ms)13252026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.07ms)13262026/10/01 07:36:13 OK 3_commit_push.sql (945.81µs)13272026/10/01 07:36:13 goose: up to current file version: 31328--- PASS: TestReadProxyRangeRequest (0.97s)1329=== CONT TestObjectStatsTrigger1330--- PASS: TestPush_CompleteCommitsEveryRoot (0.97s)1331=== CONT TestMultipartCleanup13322026/10/01 07:36:13 INFO Received push request method=POST path=/api/pushes13332026/10/01 07:36:13 INFO Received cleanup request method=DELETE path=/api/pending_closures13342026/10/01 07:36:13 INFO Aborted multipart uploads count=013352026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures13362026/10/01 07:36:13 INFO Received complete push request method=POST path=/api/pushes/1/complete13372026/10/01 07:36:13 INFO Received cleanup request method=DELETE path=/api/pending_closures13382026/10/01 07:36:13 INFO Aborted multipart uploads count=113392026/10/01 07:36:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13402026/10/01 07:36:13 INFO Received push request method=POST path=/api/pushes13412026-10-01 07:36:13.889 UTC [661] ERROR: Closure does not exist: id=113422026-10-01 07:36:13.889 UTC [661] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE13432026-10-01 07:36:13.889 UTC [661] STATEMENT: -- name: CommitPendingClosure :exec1344 SELECT commit_pending_closure($1::bigint)1345 13462026-10-01 07:36:13.889 UTC [710] ERROR: relation "goose_db_version" does not exist at character 3613472026-10-01 07:36:13.889 UTC [710] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1348--- PASS: TestService_cleanupPendingClosuresHandler (1.03s)1349=== CONT TestServerTLSConfig1350=== RUN TestServerTLSConfig/no_client_CA1351=== PAUSE TestServerTLSConfig/no_client_CA1352=== RUN TestServerTLSConfig/missing_CA_file1353=== PAUSE TestServerTLSConfig/missing_CA_file1354=== RUN TestServerTLSConfig/not_a_PEM_file1355=== PAUSE TestServerTLSConfig/not_a_PEM_file1356=== CONT TestService_NativeMTLS13572026/10/01 07:36:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13582026-10-01 07:36:13.904 UTC [712] ERROR: relation "goose_db_version" does not exist at character 3613592026-10-01 07:36:13.904 UTC [712] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13602026-10-01 07:36:13.904 UTC [713] ERROR: relation "goose_db_version" does not exist at character 3613612026-10-01 07:36:13.904 UTC [713] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1362--- PASS: TestReadRedirectUsesPublicS3URL (1.04s)1363=== CONT TestMetricsInventory13642026/10/01 07:36:13 OK 20241026095416_initial_model.sql (9.99ms)13652026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)1366--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.97s)1367=== CONT TestNARDeduplicationMetadataUploadBug13682026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.79ms)13692026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.19ms)13702026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.46ms)13712026/10/01 07:36:13 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MGE0MjIyOTAtNjUxOS00MDMxLWJlZDUtMmFiNDhiMWFmOGZkLjliMDM0MTFkLTI2MmItNDJlMy04OTk1LWI4NWYyNzJiMTM2NHgxNzkwODQwMTczNDIzNzQyOTU3 parts=1213722026/10/01 07:36:13 OK 20241026095416_initial_model.sql (10.9ms)13732026/10/01 07:36:13 OK 20241026095416_initial_model.sql (11.88ms)1374--- PASS: TestRedundantMultipartUpload (1.07s)1375=== CONT TestCreatePendingClosureRejectsOversizedNAR13762026/10/01 07:36:13 INFO Received uploads request method=POST path=/api/pending_closures13772026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (2.28ms)1378--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1379=== CONT TestCacheConfigHandlerMaxNarSize1380--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1381=== CONT TestGenerateLandingPage13822026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)13832026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (2.64ms)13842026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.15ms)1385--- PASS: TestGenerateLandingPage (0.00s)13862026/10/01 07:36:13 goose: successfully migrated database to version: 202609231200001387=== CONT TestService_readinessHandler13882026/10/01 07:36:13 OK 20251218171726_add_pins.sql (2.72ms)13892026/10/01 07:36:13 OK 20251218171726_add_pins.sql (2.8ms)13902026/10/01 07:36:13 OK 1_commit_pending_closure.sql (3.16ms)1391--- PASS: TestReadProxyDisabled (0.99s)1392=== CONT TestService_healthCheckHandler13932026/10/01 07:36:13 OK 2_object_stats_trigger.sql (12.1ms)13942026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (17.22ms)13952026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (18.08ms)13962026/10/01 07:36:13 OK 3_commit_push.sql (5.26ms)13972026/10/01 07:36:13 goose: up to current file version: 313982026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.25ms)13992026/10/01 07:36:13 OK 20260905000000_add_claims.sql (4.12ms)14002026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (1.91ms)14012026/10/01 07:36:13 INFO Aborted multipart uploads count=014022026/10/01 07:36:13 OK 20260920000000_drop_claims.sql (3.25ms)14032026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.11ms)14042026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000014052026/10/01 07:36:13 OK 20260923120000_add_pushes.sql (2.87ms)14062026/10/01 07:36:13 goose: successfully migrated database to version: 2026092312000014072026/10/01 07:36:13 OK 1_commit_pending_closure.sql (4.14ms)14082026/10/01 07:36:13 WARN Force mode enabled - objects will be deleted immediately without grace period14092026/10/01 07:36:13 OK 1_commit_pending_closure.sql (2.51ms)14102026/10/01 07:36:13 OK 2_object_stats_trigger.sql (2.23ms)14112026/10/01 07:36:13 OK 2_object_stats_trigger.sql (1.76ms)14122026/10/01 07:36:13 OK 3_commit_push.sql (1.62ms)14132026/10/01 07:36:13 goose: up to current file version: 314142026/10/01 07:36:13 OK 3_commit_push.sql (1.33ms)1415--- PASS: TestReadRedirectKeepsNarinfoProxied (1.02s)14162026/10/01 07:36:13 goose: up to current file version: 31417=== CONT TestGracefulShutdownDrainsInflight14182026/10/01 07:36:13 INFO Starting HTTP server address=127.0.0.1:4397114192026/10/01 07:36:13 INFO Shutdown signal received, draining in-flight requests timeout=10s14202026-10-01 07:36:13.964 UTC [737] ERROR: relation "goose_db_version" does not exist at character 3614212026-10-01 07:36:13.964 UTC [737] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14222026-10-01 07:36:13.965 UTC [738] ERROR: relation "goose_db_version" does not exist at character 3614232026-10-01 07:36:13.965 UTC [738] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14242026/10/01 07:36:13 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=014252026/10/01 07:36:13 INFO Vacuumed table table=pending_closures14262026/10/01 07:36:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1427--- PASS: TestReadProxyConditionalGet (0.96s)1428=== CONT TestGCTaskStore_Fail1429--- PASS: TestGCTaskStore_Fail (0.00s)1430=== CONT TestGCTaskStore_PhaseUpdates1431--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1432=== CONT TestLeadElectsOneAndHandsOver14332026/10/01 07:36:13 OK 20241026095416_initial_model.sql (11.69ms)14342026/10/01 07:36:13 INFO Vacuumed table table=pending_objects14352026/10/01 07:36:13 OK 20241026095416_initial_model.sql (11.87ms)14362026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (1.93ms)14372026/10/01 07:36:13 OK 20251210153512_drop_unused_gin_index.sql (1.93ms)14382026/10/01 07:36:13 INFO Vacuumed table table=multipart_uploads14392026/10/01 07:36:13 OK 20251218171726_add_pins.sql (2.96ms)14402026/10/01 07:36:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14412026/10/01 07:36:13 OK 20251218171726_add_pins.sql (3.12ms)14422026/10/01 07:36:13 INFO Vacuumed table table=closures14432026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)14442026/10/01 07:36:13 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)14452026/10/01 07:36:13 INFO Vacuumed table table=objects14462026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.41ms)14472026/10/01 07:36:13 INFO Received complete push request method=POST path=/api/pushes/2/complete14482026/10/01 07:36:13 OK 20260905000000_add_claims.sql (3.53ms)14492026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (3.49ms)14502026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.95ms)1451--- PASS: TestReadProxyHead (0.63s)1452=== CONT TestGCTaskStore_GetReturnsLatest1453--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1454=== CONT TestGCTaskStore_GetEmpty14552026/10/01 07:36:14 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MGE0MjIyOTAtNjUxOS00MDMxLWJlZDUtMmFiNDhiMWFmOGZkLjI0ZjhkYWVkLTI0ODItNDI5NC1hN2ZkLWQ1MDE0OTdlZDk3M3gxNzkwODQwMTczNTMyMjI2NDQ5 parts=121456--- PASS: TestGCTaskStore_GetEmpty (0.00s)1457=== CONT TestGCTaskStore_ConflictDifferentParams1458--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1459=== CONT TestGCTaskStore_DeduplicateSameParams1460--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1461=== CONT TestGCTaskStore_StartNew1462--- PASS: TestGCTaskStore_StartNew (0.00s)1463=== CONT TestGetExistingObjectsLocksRows14642026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures1465--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.14s)1466=== CONT TestRegisterCompletedObjectNeedsPendingRow14672026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (11.58ms)14682026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000014692026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (11.84ms)14702026/10/01 07:36:14 goose: successfully migrated database to version: 202609231200001471--- PASS: TestReadProxyInvalidPath (0.61s)1472=== CONT TestSweepSkipsRowsLockedByPush1473--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.16s)1474=== CONT TestFailedS3DeleteKeepsTombstone14752026/10/01 07:36:14 OK 1_commit_pending_closure.sql (5.5ms)14762026/10/01 07:36:14 OK 1_commit_pending_closure.sql (5.82ms)14772026/10/01 07:36:14 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MGE0MjIyOTAtNjUxOS00MDMxLWJlZDUtMmFiNDhiMWFmOGZkLjUxMTRmYWUyLTA0YTQtNGM3NS04MDJlLTdmNDFmMzVmZmEyM3gxNzkwODQwMTczNjQxOTg2MTA4 parts=1014782026/10/01 07:36:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14792026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.56ms)14802026/10/01 07:36:14 OK 2_object_stats_trigger.sql (2.38ms)14812026/10/01 07:36:14 OK 3_commit_push.sql (1.45ms)14822026/10/01 07:36:14 goose: up to current file version: 314832026/10/01 07:36:14 OK 3_commit_push.sql (1.76ms)14842026/10/01 07:36:14 goose: up to current file version: 314852026/10/01 07:36:14 INFO Completed upload id=114862026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures14872026-10-01 07:36:14.027 UTC [748] ERROR: relation "goose_db_version" does not exist at character 3614882026-10-01 07:36:14.027 UTC [748] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14892026-10-01 07:36:14.028 UTC [749] ERROR: relation "goose_db_version" does not exist at character 3614902026-10-01 07:36:14.028 UTC [749] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14912026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures14922026/10/01 07:36:14 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo14932026/10/01 07:36:14 WARN Found objects in DB but missing from S3, will re-upload count=11494--- PASS: TestService_verifyS3Integrity (1.18s)1495=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1496--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1497=== CONT TestGCSweepDeliversEachKeyOnce1498--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.55s)1499=== CONT TestTombstonedObjectOfferedWithoutWaiting15002026/10/01 07:36:14 OK 20241026095416_initial_model.sql (11.98ms)15012026/10/01 07:36:14 OK 20241026095416_initial_model.sql (14.4ms)15022026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.4ms)15032026-10-01 07:36:14.049 UTC [756] ERROR: relation "goose_db_version" does not exist at character 3615042026-10-01 07:36:14.049 UTC [756] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15052026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.78ms)15062026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.25ms)15072026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.51ms)15082026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.66ms)15092026-10-01 07:36:14.058 UTC [758] ERROR: relation "goose_db_version" does not exist at character 3615102026-10-01 07:36:14.058 UTC [758] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15112026-10-01 07:36:14.058 UTC [759] ERROR: relation "goose_db_version" does not exist at character 3615122026-10-01 07:36:14.058 UTC [759] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1513--- PASS: TestReadProxyNarStreaming (0.58s)1514=== CONT TestGCSweepSkipsPendingObjects15152026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.35ms)15162026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.5ms)15172026/10/01 07:36:14 OK 20260905000000_add_claims.sql (12.13ms)15182026/10/01 07:36:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1519--- PASS: TestReadProxy404 (0.63s)1520=== CONT TestDeduplicatedObjectsRecordedAsPending15212026/10/01 07:36:14 OK 20241026095416_initial_model.sql (20.27ms)15222026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (15.99ms)15232026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (6.68ms)15242026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)15252026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.99ms)15262026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000015272026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (3.82ms)15282026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000015292026/10/01 07:36:14 OK 1_commit_pending_closure.sql (3.41ms)15302026/10/01 07:36:14 OK 20251218171726_add_pins.sql (5.57ms)15312026/10/01 07:36:14 OK 1_commit_pending_closure.sql (3.05ms)15322026/10/01 07:36:14 OK 2_object_stats_trigger.sql (3.13ms)15332026/10/01 07:36:14 OK 2_object_stats_trigger.sql (2.6ms)15342026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.25ms)15352026/10/01 07:36:14 OK 3_commit_push.sql (2.68ms)15362026/10/01 07:36:14 goose: up to current file version: 315372026/10/01 07:36:14 OK 20241026095416_initial_model.sql (13.4ms)15382026/10/01 07:36:14 OK 20241026095416_initial_model.sql (13.47ms)15392026/10/01 07:36:14 OK 3_commit_push.sql (2.93ms)15402026/10/01 07:36:14 goose: up to current file version: 315412026/10/01 07:36:14 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MGE0MjIyOTAtNjUxOS00MDMxLWJlZDUtMmFiNDhiMWFmOGZkLjlhNmUyYzNlLTQxMWEtNDU4Ny1iMDgyLTkwZjRkY2QwNmZhY3gxNzkwODQwMTczNzczNzY2MDky parts=1015422026/10/01 07:36:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15432026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.9ms)15442026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.73ms)15452026/10/01 07:36:14 OK 20260905000000_add_claims.sql (5.77ms)15462026/10/01 07:36:14 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket467166931/001/proxy.sock15472026/10/01 07:36:14 INFO Starting HTTP server address=127.0.0.1:4325115482026/10/01 07:36:14 WARN mTLS auth: subject not in bound subjects subject="CN=someone"15492026/10/01 07:36:14 INFO Shutdown signal received, draining in-flight requests timeout=10s1550--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.42s)1551=== CONT TestPushDedupSurvivesConcurrentGC15522026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (3.46ms)15532026/10/01 07:36:14 OK 20251218171726_add_pins.sql (5.47ms)15542026/10/01 07:36:14 INFO Completed upload id=115552026/10/01 07:36:14 OK 20251218171726_add_pins.sql (5.62ms)15562026/10/01 07:36:14 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000015572026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures15582026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (4.81ms)15592026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000015602026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (6ms)15612026/10/01 07:36:14 OK 1_commit_pending_closure.sql (11.4ms)15622026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (15.95ms)15632026/10/01 07:36:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures15642026/10/01 07:36:14 OK 20260905000000_add_claims.sql (13.44ms)15652026/10/01 07:36:14 OK 2_object_stats_trigger.sql (5.53ms)1566--- PASS: TestReadProxyNarinfo (0.47s)1567=== CONT TestGCMetrics15682026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (3.25ms)15692026/10/01 07:36:14 OK 3_commit_push.sql (2.39ms)15702026/10/01 07:36:14 goose: up to current file version: 315712026/10/01 07:36:14 OK 20260905000000_add_claims.sql (7.98ms)15722026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (3.36ms)15732026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (5.07ms)15742026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000015752026/10/01 07:36:14 INFO Aborted multipart uploads count=015762026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (3.23ms)15772026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000015782026/10/01 07:36:14 OK 1_commit_pending_closure.sql (3.54ms)15792026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.34ms)15802026/10/01 07:36:14 OK 2_object_stats_trigger.sql (2.17ms)15812026-10-01 07:36:14.134 UTC [768] ERROR: relation "goose_db_version" does not exist at character 3615822026-10-01 07:36:14.134 UTC [768] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15832026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.88ms)15842026/10/01 07:36:14 OK 3_commit_push.sql (1.63ms)15852026/10/01 07:36:14 goose: up to current file version: 315862026/10/01 07:36:14 OK 3_commit_push.sql (1.57ms)15872026/10/01 07:36:14 goose: up to current file version: 315882026/10/01 07:36:14 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=015892026-10-01 07:36:14.140 UTC [770] ERROR: relation "goose_db_version" does not exist at character 3615902026-10-01 07:36:14.140 UTC [770] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15912026/10/01 07:36:14 INFO Vacuumed table table=pending_closures15922026/10/01 07:36:14 INFO Vacuumed table table=pending_objects15932026-10-01 07:36:14.148 UTC [771] ERROR: relation "goose_db_version" does not exist at character 3615942026-10-01 07:36:14.148 UTC [771] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15952026-10-01 07:36:14.152 UTC [772] ERROR: relation "goose_db_version" does not exist at character 3615962026-10-01 07:36:14.152 UTC [772] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15972026/10/01 07:36:14 INFO Vacuumed table table=multipart_uploads15982026/10/01 07:36:14 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15992026/10/01 07:36:14 WARN Refused reserved pin name=worker-x86_64-linux16002026/10/01 07:36:14 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux16012026/10/01 07:36:14 INFO Received create pin request method=POST path=/api/pins/my-app16022026/10/01 07:36:14 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux16032026-10-01 07:36:14.161 UTC [773] ERROR: relation "goose_db_version" does not exist at character 3616042026-10-01 07:36:14.161 UTC [773] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1605--- PASS: TestCreatePin_ReservedPins (0.44s)1606=== CONT TestGCBugBareHashReferences16072026/10/01 07:36:14 OK 20241026095416_initial_model.sql (17.9ms)16082026/10/01 07:36:14 OK 20241026095416_initial_model.sql (24.64ms)16092026/10/01 07:36:14 INFO Vacuumed table table=closures16102026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)16112026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.75ms)16122026/10/01 07:36:14 INFO Vacuumed table table=objects16132026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.59ms)16142026/10/01 07:36:14 OK 20251218171726_add_pins.sql (4.88ms)16152026-10-01 07:36:14.176 UTC [777] ERROR: relation "goose_db_version" does not exist at character 3616162026-10-01 07:36:14.176 UTC [777] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16172026-10-01 07:36:14.177 UTC [776] ERROR: relation "goose_db_version" does not exist at character 3616182026-10-01 07:36:14.177 UTC [776] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16192026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (5.27ms)16202026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (6.41ms)16212026/10/01 07:36:14 OK 20241026095416_initial_model.sql (12.69ms)16222026-10-01 07:36:14.181 UTC [778] ERROR: relation "goose_db_version" does not exist at character 3616232026-10-01 07:36:14.181 UTC [778] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16242026/10/01 07:36:14 OK 20241026095416_initial_model.sql (14.15ms)16252026/10/01 07:36:14 OK 20241026095416_initial_model.sql (13.77ms)16262026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)16272026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.84ms)16282026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)16292026/10/01 07:36:14 OK 20260905000000_add_claims.sql (5.05ms)16302026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.45ms)16312026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (3.2ms)16322026/10/01 07:36:14 OK 20251218171726_add_pins.sql (4.77ms)16332026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.88ms)16342026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (3.21ms)16352026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (3.04ms)16362026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000016372026/10/01 07:36:14 OK 20251218171726_add_pins.sql (4.86ms)16382026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.68ms)16392026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000016402026-10-01 07:36:14.192 UTC [779] ERROR: relation "goose_db_version" does not exist at character 3616412026-10-01 07:36:14.192 UTC [779] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16422026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.54ms)16432026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (5.14ms)16442026/10/01 07:36:14 OK 1_commit_pending_closure.sql (3.29ms)16452026/10/01 07:36:14 OK 20241026095416_initial_model.sql (10.63ms)16462026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.92ms)16472026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (3.98ms)16482026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)16492026/10/01 07:36:14 OK 2_object_stats_trigger.sql (2.94ms)16502026/10/01 07:36:14 OK 20260905000000_add_claims.sql (4.62ms)16512026/10/01 07:36:14 OK 20241026095416_initial_model.sql (13.42ms)16522026/10/01 07:36:14 OK 2_object_stats_trigger.sql (3.35ms)16532026/10/01 07:36:14 OK 20260905000000_add_claims.sql (5.29ms)16542026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.72ms)16552026/10/01 07:36:14 OK 3_commit_push.sql (2.08ms)16562026/10/01 07:36:14 goose: up to current file version: 316572026/10/01 07:36:14 OK 20260905000000_add_claims.sql (4.22ms)16582026-10-01 07:36:14.199 UTC [780] ERROR: relation "goose_db_version" does not exist at character 3616592026-10-01 07:36:14.199 UTC [780] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16602026/10/01 07:36:14 OK 3_commit_push.sql (2.01ms)16612026/10/01 07:36:14 goose: up to current file version: 316622026/10/01 07:36:14 OK 20241026095416_initial_model.sql (11.79ms)16632026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.38ms)16642026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.63ms)16652026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.96ms)16662026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.92ms)16672026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.45ms)16682026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.79ms)16692026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000016702026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.25ms)16712026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.63ms)16722026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.72ms)16732026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000016742026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.31ms)16752026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000016762026/10/01 07:36:14 OK 20251218171726_add_pins.sql (2.86ms)16772026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.4ms)16782026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.66ms)16792026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.84ms)16802026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.36ms)16812026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.49ms)16822026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.62ms)16832026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.42ms)16842026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.68ms)16852026/10/01 07:36:14 OK 3_commit_push.sql (1.05ms)16862026/10/01 07:36:14 goose: up to current file version: 316872026/10/01 07:36:14 OK 3_commit_push.sql (929.79µs)16882026/10/01 07:36:14 goose: up to current file version: 316892026/10/01 07:36:14 OK 3_commit_push.sql (1.15ms)16902026/10/01 07:36:14 goose: up to current file version: 316912026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (3.66ms)16922026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.17ms)16932026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures16942026/10/01 07:36:14 OK 20241026095416_initial_model.sql (9.86ms)1695--- PASS: TestObjectStatsTrigger (0.38s)1696=== CONT TestLeadEndsOnShutdown16972026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.86ms)16982026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000016992026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.4ms)17002026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)17012026/10/01 07:36:14 OK 20260905000000_add_claims.sql (2.85ms)17022026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.12ms)17032026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.52ms)17042026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.31ms)17052026/10/01 07:36:14 OK 20241026095416_initial_model.sql (9.86ms)17062026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.02ms)17072026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.85ms)17082026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000017092026/10/01 07:36:14 OK 3_commit_push.sql (1.18ms)17102026/10/01 07:36:14 goose: up to current file version: 317112026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.49ms)17122026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.19ms)17132026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.54ms)17142026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000017152026/10/01 07:36:14 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000017162026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.38ms)1717--- PASS: TestService_createPendingClosureHandler (1.36s)1718=== CONT TestPinProtectsFromGC17192026/10/01 07:36:14 OK 2_object_stats_trigger.sql (875.79µs)17202026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.87ms)17212026/10/01 07:36:14 OK 3_commit_push.sql (1.18ms)17222026/10/01 07:36:14 goose: up to current file version: 317232026/10/01 07:36:14 OK 2_object_stats_trigger.sql (953.91µs)17242026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.77ms)17252026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (3.87ms)17262026/10/01 07:36:14 OK 3_commit_push.sql (566.58µs)17272026/10/01 07:36:14 goose: up to current file version: 317282026-10-01 07:36:14.225 UTC [784] ERROR: relation "goose_db_version" does not exist at character 3617292026-10-01 07:36:14.225 UTC [784] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17302026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (6.21ms)17312026/10/01 07:36:14 OK 20260905000000_add_claims.sql (6.17ms)17322026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (3.38ms)17332026-10-01 07:36:14.230 UTC [786] ERROR: relation "goose_db_version" does not exist at character 3617342026-10-01 07:36:14.230 UTC [786] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17352026/10/01 07:36:14 OK 20260905000000_add_claims.sql (4.77ms)17362026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (4.86ms)17372026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000017382026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (10.22ms)17392026/10/01 07:36:14 OK 1_commit_pending_closure.sql (44.81ms)17402026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (43.26ms)17412026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000017422026/10/01 07:36:14 OK 20241026095416_initial_model.sql (49.34ms)17432026/10/01 07:36:14 OK 2_object_stats_trigger.sql (5.32ms)17442026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)17452026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.35ms)17462026/10/01 07:36:14 OK 3_commit_push.sql (2.07ms)17472026/10/01 07:36:14 goose: up to current file version: 317482026/10/01 07:36:14 OK 20241026095416_initial_model.sql (8.21ms)17492026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.9ms)17502026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.28ms)17512026/10/01 07:36:14 OK 3_commit_push.sql (1.44ms)17522026/10/01 07:36:14 goose: up to current file version: 317532026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)17542026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.28ms)17552026/10/01 07:36:14 WARN mTLS auth: subject not in bound subjects subject="CN=reader"17562026/10/01 07:36:14 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1757--- PASS: TestService_NativeMTLS (0.40s)1758=== CONT TestResolveDBConnectionString1759=== RUN TestResolveDBConnectionString/flag_wins1760=== PAUSE TestResolveDBConnectionString/flag_wins17612026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.94ms)1762=== RUN TestResolveDBConnectionString/file_when_flag_empty1763=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1764=== RUN TestResolveDBConnectionString/missing_file_is_an_error1765=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1766=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1767=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1768=== RUN TestResolveDBConnectionString/nothing_configured1769=== PAUSE TestResolveDBConnectionString/nothing_configured1770=== CONT TestClientFallsBackToClosures17712026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (3.54ms)17722026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.44ms)17732026-10-01 07:36:14.299 UTC [787] ERROR: relation "goose_db_version" does not exist at character 3617742026-10-01 07:36:14.299 UTC [787] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1775--- PASS: TestMetricsInventory (0.40s)1776=== CONT TestClientPushesUseOnePush17772026/10/01 07:36:14 OK 20260905000000_add_claims.sql (2.54ms)17782026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.09ms)17792026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.83ms)17802026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.96ms)17812026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000017822026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.65ms)17832026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000017842026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.51ms)17852026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.77ms)17862026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.2ms)17872026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.25ms)17882026/10/01 07:36:14 OK 3_commit_push.sql (1.3ms)17892026/10/01 07:36:14 goose: up to current file version: 317902026/10/01 07:36:14 OK 3_commit_push.sql (1.36ms)17912026/10/01 07:36:14 goose: up to current file version: 317922026/10/01 07:36:14 OK 20241026095416_initial_model.sql (8.2ms)17932026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)17942026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.6ms)17952026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (3.45ms)17962026/10/01 07:36:14 INFO Received cleanup request method=DELETE path=/api/pending_closures17972026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.49ms)17982026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (3.07ms)17992026/10/01 07:36:14 INFO Aborted multipart uploads count=118002026/10/01 07:36:14 WARN readiness check failed error="closed pool"1801--- PASS: TestService_readinessHandler (0.41s)1802=== CONT TestClientErrorHandling1803=== RUN TestClientErrorHandling/InvalidStorePath1804=== PAUSE TestClientErrorHandling/InvalidStorePath1805=== RUN TestClientErrorHandling/InvalidAuthToken1806=== PAUSE TestClientErrorHandling/InvalidAuthToken1807=== RUN TestClientErrorHandling/ServerNotAvailable1808=== PAUSE TestClientErrorHandling/ServerNotAvailable1809=== CONT TestService_RequireScope_OIDC18102026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (3.5ms)18112026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000018122026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.49ms)1813--- PASS: TestMultipartCleanup (0.50s)1814=== CONT TestClientCADerivations18152026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.27ms)18162026/10/01 07:36:14 OK 3_commit_push.sql (1ms)18172026/10/01 07:36:14 goose: up to current file version: 31818--- PASS: TestService_healthCheckHandler (0.42s)1819=== CONT TestClientSharedPathCommittedMidPush18202026-10-01 07:36:14.350 UTC [811] ERROR: relation "goose_db_version" does not exist at character 3618212026-10-01 07:36:14.350 UTC [811] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18222026/10/01 07:36:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40733/oidc1823=== NAME TestNARDeduplicationMetadataUploadBug1824 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2153409729/001/store/56vkd4xgvg5nby24fc6bx1gmhk8yaf16-file1.txt18252026-10-01 07:36:14.360 UTC [814] ERROR: relation "goose_db_version" does not exist at character 3618262026-10-01 07:36:14.360 UTC [814] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18272026/10/01 07:36:14 INFO lead: acquired remote=192.0.2.1:123418282026/10/01 07:36:14 OK 20241026095416_initial_model.sql (20.16ms)18292026/10/01 07:36:14 OK 20241026095416_initial_model.sql (13.94ms)18302026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (5.04ms)18312026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.98ms)18322026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.54ms)18332026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.8ms)18342026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.23ms)18352026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.09ms)18362026/10/01 07:36:14 OK 20260905000000_add_claims.sql (2.94ms)18372026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.14ms)18382026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.2ms)18392026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.97ms)18402026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.64ms)18412026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000018422026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.62ms)18432026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000018442026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.92ms)18452026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.2ms)18462026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.47ms)18472026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.47ms)18482026/10/01 07:36:14 OK 3_commit_push.sql (1.53ms)18492026/10/01 07:36:14 goose: up to current file version: 318502026/10/01 07:36:14 OK 3_commit_push.sql (1.13ms)18512026/10/01 07:36:14 goose: up to current file version: 31852--- PASS: TestGetExistingObjectsLocksRows (0.41s)1853=== CONT TestCacheStatsHandler18542026-10-01 07:36:14.413 UTC [837] ERROR: relation "goose_db_version" does not exist at character 3618552026-10-01 07:36:14.413 UTC [837] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18562026-10-01 07:36:14.414 UTC [840] ERROR: relation "goose_db_version" does not exist at character 3618572026-10-01 07:36:14.414 UTC [840] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1858--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.43s)1859=== CONT TestClientWithDependencies18602026/10/01 07:36:14 OK 20241026095416_initial_model.sql (11.31ms)18612026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.61ms)18622026/10/01 07:36:14 INFO Aborted multipart uploads count=018632026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.65ms)18642026/10/01 07:36:14 WARN Force mode enabled - objects will be deleted immediately without grace period18652026/10/01 07:36:14 OK 20241026095416_initial_model.sql (13.46ms)18662026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.77ms)18672026/10/01 07:36:14 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=018682026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures18692026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes18702026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.89ms)18712026/10/01 07:36:14 INFO Vacuumed table table=pending_closures18722026/10/01 07:36:14 INFO Vacuumed table table=pending_objects18732026/10/01 07:36:14 INFO Vacuumed table table=multipart_uploads18742026/10/01 07:36:14 INFO Vacuumed table table=closures18752026/10/01 07:36:14 OK 20251218171726_add_pins.sql (4.82ms)18762026/10/01 07:36:14 OK 20260905000000_add_claims.sql (4ms)18772026/10/01 07:36:14 INFO Vacuumed table table=objects18782026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (13.13ms)18792026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (15.79ms)18802026/10/01 07:36:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18812026/10/01 07:36:14 INFO Uploading 56vkd4xgvg5nby24fc6bx1gmhk8yaf16-file1.txt (160B)18822026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (3.73ms)18832026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000018842026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures18852026/10/01 07:36:14 INFO Aborted multipart uploads count=018862026/10/01 07:36:14 OK 20260905000000_add_claims.sql (4.08ms)18872026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.36ms)18882026/10/01 07:36:14 WARN Force mode enabled - objects will be deleted immediately without grace period18892026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.36ms)18902026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.45ms)18912026/10/01 07:36:14 OK 3_commit_push.sql (689.46µs)18922026/10/01 07:36:14 goose: up to current file version: 318932026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18942026/10/01 07:36:14 WARN Failed to register uploaded object key=56vkd4xgvg5nby24fc6bx1gmhk8yaf16.ls error="server returned 404: 404 page not found\n"18952026/10/01 07:36:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18962026/10/01 07:36:14 INFO Signed narinfos id=1 count=118972026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.17ms)18982026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000018992026/10/01 07:36:14 INFO Uploading 1 narinfos19002026-10-01 07:36:14.471 UTC [863] ERROR: relation "goose_db_version" does not exist at character 3619012026-10-01 07:36:14.471 UTC [863] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19022026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.04ms)19032026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.3ms)19042026/10/01 07:36:14 INFO Received complete push request method=POST path=/api/pushes/1/complete19052026/10/01 07:36:14 WARN Failed to register uploaded object key=56vkd4xgvg5nby24fc6bx1gmhk8yaf16.narinfo error="server returned 404: 404 page not found\n"19062026/10/01 07:36:14 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=019072026/10/01 07:36:14 OK 3_commit_push.sql (1.21ms)19082026-10-01 07:36:14.475 UTC [866] ERROR: relation "goose_db_version" does not exist at character 3619092026-10-01 07:36:14.475 UTC [866] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19102026/10/01 07:36:14 goose: up to current file version: 319112026/10/01 07:36:14 INFO Vacuumed table table=pending_closures19122026/10/01 07:36:14 INFO Vacuumed table table=pending_objects19132026-10-01 07:36:14.476 UTC [865] ERROR: relation "goose_db_version" does not exist at character 3619142026-10-01 07:36:14.476 UTC [865] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19152026/10/01 07:36:14 INFO Vacuumed table table=multipart_uploads19162026/10/01 07:36:14 INFO Vacuumed table table=closures19172026/10/01 07:36:14 INFO Vacuumed table table=objects1918--- PASS: TestSweepSkipsRowsLockedByPush (0.47s)1919=== CONT TestClientMultipleUploads19202026/10/01 07:36:14 INFO Upload complete. (79ms)1921=== NAME TestNARDeduplicationMetadataUploadBug1922 metadata_upload_test.go:54: Retrieved narinfo from S3:1923 StorePath: /build/TestNARDeduplicationMetadataUploadBug2153409729/001/store/56vkd4xgvg5nby24fc6bx1gmhk8yaf16-file1.txt1924 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1925 Compression: zstd1926 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1927 NarSize: 1601928 References: 1929 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1930 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1931 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1932 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}19332026/10/01 07:36:14 OK 20241026095416_initial_model.sql (8.29ms)19342026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures19352026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.29ms)1936=== NAME TestOrphanedObjectsGC1937 orphaned_objects_gc_test.go:290: GC Test Summary:1938 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1939 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1940 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1941 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1942 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1943--- PASS: TestOrphanedObjectsGC (0.70s)1944=== CONT TestCacheConfigHandler1945=== RUN TestCacheConfigHandler/full_config,_no_issuer1946=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1947=== RUN TestCacheConfigHandler/no_cache_url_configured1948=== PAUSE TestCacheConfigHandler/no_cache_url_configured1949=== RUN TestCacheConfigHandler/no_signing_keys1950=== PAUSE TestCacheConfigHandler/no_signing_keys1951=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1952=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1953=== CONT TestClientIntegration19542026/10/01 07:36:14 OK 20251218171726_add_pins.sql (2.94ms)19552026/10/01 07:36:14 OK 20241026095416_initial_model.sql (8.5ms)19562026/10/01 07:36:14 OK 20241026095416_initial_model.sql (8.46ms)19572026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.58ms)19582026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.41ms)19592026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (3.6ms)1960--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.46s)1961=== CONT TestService_ReadScope_PublicByDefault19622026/10/01 07:36:14 OK 20251218171726_add_pins.sql (2.65ms)19632026/10/01 07:36:14 OK 20251218171726_add_pins.sql (2.66ms)19642026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.23ms)19652026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (3.62ms)19662026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (2.97ms)19672026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.82ms)19682026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.2ms)19692026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000019702026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.69ms)19712026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.74ms)19722026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.97ms)19732026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.78ms)19742026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.17ms)19752026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.61ms)19762026/10/01 07:36:14 OK 3_commit_push.sql (1.04ms)19772026/10/01 07:36:14 goose: up to current file version: 319782026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.77ms)19792026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000019802026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.76ms)19812026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000019822026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.22ms)19832026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.4ms)19842026/10/01 07:36:14 OK 1_commit_pending_closure.sql (3.23ms)19852026/10/01 07:36:14 OK 3_commit_push.sql (2ms)19862026/10/01 07:36:14 goose: up to current file version: 319872026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.46ms)19882026/10/01 07:36:14 OK 3_commit_push.sql (1.13ms)19892026/10/01 07:36:14 goose: up to current file version: 319902026/10/01 07:36:14 INFO lead: released remote=192.0.2.1:12341991=== NAME TestNARDeduplicationMetadataUploadBug1992 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2153409729/001/store/l7h6i6chwyd4am2x8kqrd55wm22vhyz6-file2.txt19932026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures19942026-10-01 07:36:14.526 UTC [895] ERROR: relation "goose_db_version" does not exist at character 3619952026-10-01 07:36:14.526 UTC [895] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19962026/10/01 07:36:14 INFO Aborted multipart uploads count=019972026/10/01 07:36:14 WARN Force mode enabled - objects will be deleted immediately without grace period19982026-10-01 07:36:14.535 UTC [898] ERROR: relation "goose_db_version" does not exist at character 3619992026-10-01 07:36:14.535 UTC [898] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20002026/10/01 07:36:14 INFO Aborted multipart uploads count=020012026/10/01 07:36:14 WARN Force mode enabled - objects will be deleted immediately without grace period20022026/10/01 07:36:14 OK 20241026095416_initial_model.sql (8.87ms)20032026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures20042026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)20052026/10/01 07:36:14 INFO Aborted multipart uploads count=020062026/10/01 07:36:14 WARN Force mode enabled - objects will be deleted immediately without grace period20072026/10/01 07:36:14 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."20082026/10/01 07:36:14 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."20092026/10/01 07:36:14 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=020102026/10/01 07:36:14 OK 20251218171726_add_pins.sql (20.2ms)20112026/10/01 07:36:14 INFO lead: acquired remote=192.0.2.1:123420122026/10/01 07:36:14 OK 20241026095416_initial_model.sql (27.74ms)20132026/10/01 07:36:14 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=020142026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (5.2ms)2015--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.49s)2016=== CONT TestService_ReadAuthMiddleware2017--- PASS: TestFailedS3DeleteKeepsTombstone (0.55s)2018=== CONT TestService_AuthMiddleware_MTLSBoundSubjects20192026/10/01 07:36:14 INFO Vacuumed table table=pending_closures20202026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.64ms)20212026/10/01 07:36:14 INFO Vacuumed table table=pending_closures20222026/10/01 07:36:14 INFO Vacuumed table table=pending_objects20232026/10/01 07:36:14 INFO Vacuumed table table=multipart_uploads20242026/10/01 07:36:14 INFO Vacuumed table table=closures20252026/10/01 07:36:14 INFO Vacuumed table table=pending_objects20262026/10/01 07:36:14 INFO Vacuumed table table=multipart_uploads20272026/10/01 07:36:14 INFO Vacuumed table table=closures20282026/10/01 07:36:14 OK 20260905000000_add_claims.sql (4.11ms)20292026/10/01 07:36:14 INFO lead: released remote=192.0.2.1:12342030--- PASS: TestLeadElectsOneAndHandsOver (0.59s)2031=== CONT TestService_AuthMiddleware_OIDC20322026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.64ms)20332026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.1ms)20342026/10/01 07:36:14 INFO Vacuumed table table=objects20352026/10/01 07:36:14 INFO Vacuumed table table=objects2036--- PASS: TestGCSweepDeliversEachKeyOnce (0.54s)2037=== CONT TestService_AuthMiddleware_MTLSProxyHeader20382026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.79ms)20392026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000020402026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4ms)20412026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.01ms)20422026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.55ms)20432026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.17ms)2044--- PASS: TestGCSweepSkipsPendingObjects (0.52s)2045=== CONT TestProxyWriteTimeout/narinfo2046=== CONT TestProxyWriteTimeout/unknown_size2047=== CONT TestProxyWriteTimeout/10_GiB_nar2048=== CONT TestProxyWriteTimeout/1_GiB_nar2049--- PASS: TestProxyWriteTimeout (0.08s)2050 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2051 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2052 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2053 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)20542026/10/01 07:36:14 OK 3_commit_push.sql (1.37ms)2055=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info20562026/10/01 07:36:14 goose: up to current file version: 320572026/10/01 07:36:14 INFO Received uploads request method=POST path=/2058=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key20592026/10/01 07:36:14 INFO Received complete multipart upload request method=POST path=/2060=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal20612026/10/01 07:36:14 INFO Received uploads request method=POST path=/2062=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key20632026/10/01 07:36:14 INFO Received request for more parts method=POST path=/2064--- PASS: TestUploadHandlersRejectInvalidKeys (0.08s)2065 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2066 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2067 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2068 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2069=== CONT TestIsValidUploadKey/narinfo2070=== CONT TestIsValidUploadKey/realisation_plus_in_output2071=== CONT TestIsValidUploadKey/unknown_type2072=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2073=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2074=== CONT TestIsValidUploadKey/index.html2075=== CONT TestIsValidUploadKey/nix-cache-info2076=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2077=== CONT TestIsValidUploadKey/build_log_home-manager_file2078=== CONT TestIsValidUploadKey/empty_key2079=== CONT TestIsValidUploadKey/realisation2080=== CONT TestIsValidUploadKey/absolute2081=== CONT TestIsValidUploadKey/build_log_equals2082=== CONT TestIsValidUploadKey/traversal_nar2083=== CONT TestIsValidUploadKey/build_log_question_mark2084=== CONT TestIsValidUploadKey/traversal2085=== CONT TestIsValidUploadKey/build_log_plus_in_name2086=== CONT TestIsValidUploadKey/nar_plain2087=== CONT TestIsValidUploadKey/nar_xz2088=== CONT TestIsValidUploadKey/build_log2089=== CONT TestIsValidUploadKey/nar_zst2090=== CONT TestIsValidUploadKey/listing2091--- PASS: TestIsValidUploadKey (0.08s)2092 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2093 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2094 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2095 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2096 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2097 --- PASS: TestIsValidUploadKey/index.html (0.00s)2098 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2099 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2100 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2101 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2102 --- PASS: TestIsValidUploadKey/realisation (0.00s)2103 --- PASS: TestIsValidUploadKey/absolute (0.00s)2104 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2105 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2106 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2107 --- PASS: TestIsValidUploadKey/traversal (0.00s)2108 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2109 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2110 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2111 --- PASS: TestIsValidUploadKey/build_log (0.00s)2112 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2113 --- PASS: TestIsValidUploadKey/listing (0.00s)2114=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure21152026/10/01 07:36:14 INFO Received uploads request method=POST path=/21162026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (5.02ms)21172026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures21182026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.18ms)21192026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000021202026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes21212026/10/01 07:36:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45453/oidc21222026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.95ms)21232026/10/01 07:36:14 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)21242026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.98ms)21252026/10/01 07:36:14 OK 3_commit_push.sql (902.98µs)21262026/10/01 07:36:14 goose: up to current file version: 321272026/10/01 07:36:14 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign21282026/10/01 07:36:14 WARN Failed to register uploaded object key=l7h6i6chwyd4am2x8kqrd55wm22vhyz6.ls error="server returned 404: 404 page not found\n"21292026-10-01 07:36:14.598 UTC [943] ERROR: relation "goose_db_version" does not exist at character 3621302026-10-01 07:36:14.598 UTC [943] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21312026/10/01 07:36:14 INFO Signed narinfos id=2 count=121322026/10/01 07:36:14 INFO Uploading 1 narinfos21332026-10-01 07:36:14.600 UTC [944] ERROR: relation "goose_db_version" does not exist at character 3621342026-10-01 07:36:14.600 UTC [944] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21352026/10/01 07:36:14 INFO Aborted multipart uploads count=021362026/10/01 07:36:14 INFO Received complete push request method=POST path=/api/pushes/2/complete21372026/10/01 07:36:14 WARN Failed to register uploaded object key=l7h6i6chwyd4am2x8kqrd55wm22vhyz6.narinfo error="server returned 404: 404 page not found\n"21382026/10/01 07:36:14 WARN Force mode enabled - objects will be deleted immediately without grace period21392026/10/01 07:36:14 INFO Upload complete. (48ms)2140=== NAME TestNARDeduplicationMetadataUploadBug2141 metadata_upload_test.go:76: Retrieved narinfo from S3:2142 StorePath: /build/TestNARDeduplicationMetadataUploadBug2153409729/001/store/l7h6i6chwyd4am2x8kqrd55wm22vhyz6-file2.txt2143 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2144 Compression: zstd2145 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2146 NarSize: 1602147 References: 2148 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf21492026/10/01 07:36:14 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=02150 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2151 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2152 {"version":1,"root":{"type":"regular","size":44}}21532026/10/01 07:36:14 INFO Vacuumed table table=pending_closures21542026/10/01 07:36:14 INFO Vacuumed table table=pending_objects21552026/10/01 07:36:14 INFO Vacuumed table table=multipart_uploads21562026-10-01 07:36:14.609 UTC [947] ERROR: relation "goose_db_version" does not exist at character 3621572026-10-01 07:36:14.609 UTC [947] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21582026/10/01 07:36:14 INFO Vacuumed table table=closures21592026/10/01 07:36:14 INFO Vacuumed table table=objects2160--- PASS: TestNARDeduplicationMetadataUploadBug (0.70s)2161=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts21622026/10/01 07:36:14 INFO Received request for more parts method=POST path=/2163--- PASS: TestGCMetrics (0.49s)2164=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart21652026/10/01 07:36:14 OK 20241026095416_initial_model.sql (9.79ms)21662026/10/01 07:36:14 INFO Received complete multipart upload request method=POST path=/21672026/10/01 07:36:14 OK 20241026095416_initial_model.sql (9.83ms)21682026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.12ms)21692026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.5ms)21702026/10/01 07:36:14 OK 20251218171726_add_pins.sql (2.46ms)21712026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.06ms)21722026/10/01 07:36:14 INFO lead: acquired remote=192.0.2.1:123421732026/10/01 07:36:14 INFO lead: released remote=192.0.2.1:12342174--- PASS: TestLeadEndsOnShutdown (0.41s)2175=== CONT TestIsValidCachePath/narinfo2176=== CONT TestIsValidCachePath/index.html2177=== CONT TestIsValidCachePath/short_hash2178=== CONT TestIsValidCachePath/wrong_extension2179=== CONT TestIsValidCachePath/leading_slash2180=== CONT TestIsValidCachePath/empty2181=== CONT TestIsValidCachePath/random_path2182=== CONT TestIsValidCachePath/invalid_char_u2183=== CONT TestIsValidCachePath/invalid_char_e2184=== CONT TestIsValidCachePath/traversal_in_middle2185=== CONT TestIsValidCachePath/traversal_parent2186=== CONT TestIsValidCachePath/nar_xz2187=== CONT TestIsValidCachePath/nar_bz22188=== CONT TestIsValidCachePath/realisation2189=== CONT TestIsValidCachePath/nix-cache-info2190=== CONT TestIsValidCachePath/nar_zst2191=== CONT TestIsValidCachePath/nar_uncompressed2192=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2193=== CONT TestIsValidCachePath/log2194=== CONT TestIsValidCachePath/ls2195--- PASS: TestIsValidCachePath (0.00s)2196 --- PASS: TestIsValidCachePath/narinfo (0.00s)2197 --- PASS: TestIsValidCachePath/index.html (0.00s)2198 --- PASS: TestIsValidCachePath/short_hash (0.00s)2199 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2200 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2201 --- PASS: TestIsValidCachePath/empty (0.00s)2202 --- PASS: TestIsValidCachePath/random_path (0.00s)2203 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2204 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2205 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2206 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2207 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2208 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2209 --- PASS: TestIsValidCachePath/realisation (0.00s)2210 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2211 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2212 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2213 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2214 --- PASS: TestIsValidCachePath/log (0.00s)2215 --- PASS: TestIsValidCachePath/ls (0.00s)2216=== CONT TestPush_RejectsBadRequests/no_roots22172026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes2218=== CONT TestPush_RejectsBadRequests/bad_root22192026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes2220=== CONT TestPush_RejectsBadRequests/root_not_in_objects22212026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes2222=== CONT TestPush_RejectsBadRequests/no_objects22232026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes2224=== CONT TestParseSingleRange/none2225=== CONT TestParseSingleRange/start_past_EOF2226=== CONT TestParseSingleRange/single_byte2227=== CONT TestParseSingleRange/suffix_exceeds_size2228--- PASS: TestPush_RejectsBadRequests (0.85s)2229 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2230 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2231 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2232 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2233=== CONT TestParseSingleRange/suffix2234=== CONT TestParseSingleRange/end_clamped_to_size22352026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (3.46ms)2236=== CONT TestParseSingleRange/open-ended2237=== CONT TestParseSingleRange/closed2238=== CONT TestParseSingleRange/malformed_end_before_start2239=== CONT TestParseSingleRange/malformed_both_empty2240=== CONT TestParseSingleRange/malformed_no_dash2241=== CONT TestParseSingleRange/start_far_past_EOF2242=== CONT TestParseSingleRange/multi-range_ignored2243=== CONT TestParseSingleRange/unknown_unit2244=== CONT TestServerTLSConfig/no_client_CA2245=== CONT TestServerTLSConfig/missing_CA_file22462026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4ms)2247=== CONT TestServerTLSConfig/not_a_PEM_file2248--- PASS: TestParseSingleRange (0.00s)2249 --- PASS: TestParseSingleRange/none (0.00s)2250 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2251 --- PASS: TestParseSingleRange/single_byte (0.00s)2252 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2253 --- PASS: TestParseSingleRange/suffix (0.00s)2254 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2255 --- PASS: TestParseSingleRange/open-ended (0.00s)2256 --- PASS: TestParseSingleRange/closed (0.00s)2257 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2258 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2259 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2260 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2261 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2262 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2263=== CONT TestResolveDBConnectionString/flag_wins2264=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2265=== CONT TestResolveDBConnectionString/nothing_configured2266--- PASS: TestServerTLSConfig (0.00s)2267 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2268 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2269 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2270=== CONT TestResolveDBConnectionString/missing_file_is_an_error2271=== CONT TestResolveDBConnectionString/file_when_flag_empty2272=== CONT TestClientErrorHandling/InvalidStorePath22732026/10/01 07:36:14 OK 20241026095416_initial_model.sql (9.11ms)2274--- PASS: TestResolveDBConnectionString (0.00s)2275 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2276 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2277 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2278 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2279 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)22802026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.06ms)22812026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.47ms)22822026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)22832026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (2.17ms)22842026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.64ms)22852026/10/01 07:36:14 OK 20251218171726_add_pins.sql (2.8ms)22862026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.26ms)22872026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000022882026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (2.59ms)22892026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000022902026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.05ms)22912026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.82ms)22922026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (3.2ms)22932026/10/01 07:36:14 OK 2_object_stats_trigger.sql (963.66µs)22942026/10/01 07:36:14 OK 2_object_stats_trigger.sql (1.3ms)22952026/10/01 07:36:14 OK 3_commit_push.sql (1.18ms)22962026/10/01 07:36:14 goose: up to current file version: 322972026/10/01 07:36:14 OK 3_commit_push.sql (1.04ms)22982026/10/01 07:36:14 goose: up to current file version: 322992026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.12ms)23002026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (11.43ms)23012026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (4.09ms)23022026/10/01 07:36:14 goose: successfully migrated database to version: 202609231200002303=== CONT TestClientErrorHandling/InvalidAuthToken2304=== CONT TestClientErrorHandling/ServerNotAvailable23052026/10/01 07:36:14 OK 1_commit_pending_closure.sql (3.43ms)23062026/10/01 07:36:14 INFO Aborted multipart uploads count=023072026/10/01 07:36:14 OK 2_object_stats_trigger.sql (2.37ms)23082026/10/01 07:36:14 OK 3_commit_push.sql (2.02ms)23092026/10/01 07:36:14 goose: up to current file version: 323102026/10/01 07:36:14 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=02311--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.64s)2312=== CONT TestCacheConfigHandler/full_config,_no_issuer2313=== CONT TestCacheConfigHandler/no_signing_keys2314=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator23152026/10/01 07:36:14 INFO Vacuumed table table=pending_closures2316=== CONT TestCacheConfigHandler/no_cache_url_configured2317--- PASS: TestCacheConfigHandler (0.00s)2318 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2319 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2320 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2321 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)23222026/10/01 07:36:14 INFO Vacuumed table table=pending_objects23232026/10/01 07:36:14 INFO Vacuumed table table=multipart_uploads23242026/10/01 07:36:14 INFO Vacuumed table table=closures23252026/10/01 07:36:14 INFO Vacuumed table table=objects23262026-10-01 07:36:14.683 UTC [972] ERROR: relation "goose_db_version" does not exist at character 3623272026-10-01 07:36:14.683 UTC [972] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23282026-10-01 07:36:14.684 UTC [973] ERROR: relation "goose_db_version" does not exist at character 3623292026-10-01 07:36:14.684 UTC [973] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23302026/10/01 07:36:14 INFO Aborted multipart uploads count=023312026/10/01 07:36:14 WARN Force mode enabled - objects will be deleted immediately without grace period23322026/10/01 07:36:14 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=023332026/10/01 07:36:14 INFO Vacuumed table table=pending_closures23342026-10-01 07:36:14.690 UTC [991] ERROR: relation "goose_db_version" does not exist at character 3623352026-10-01 07:36:14.690 UTC [991] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23362026/10/01 07:36:14 INFO Vacuumed table table=pending_objects23372026/10/01 07:36:14 INFO Vacuumed table table=multipart_uploads23382026/10/01 07:36:14 INFO Vacuumed table table=closures23392026/10/01 07:36:14 INFO Vacuumed table table=objects2340--- PASS: TestPushDedupSurvivesConcurrentGC (0.60s)23412026/10/01 07:36:14 OK 20241026095416_initial_model.sql (8.86ms)23422026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)23432026/10/01 07:36:14 OK 20241026095416_initial_model.sql (11.42ms)23442026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)23452026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.74ms)23462026/10/01 07:36:14 OK 20241026095416_initial_model.sql (9.44ms)23472026/10/01 07:36:14 OK 20251218171726_add_pins.sql (2.6ms)23482026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.87ms)23492026-10-01 07:36:14.709 UTC [1010] ERROR: relation "goose_db_version" does not exist at character 3623502026-10-01 07:36:14.709 UTC [1010] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23512026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (4.09ms)23522026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (3.86ms)23532026/10/01 07:36:14 OK 20251218171726_add_pins.sql (3.51ms)23542026/10/01 07:36:14 OK 20260905000000_add_claims.sql (2.84ms)23552026/10/01 07:36:14 OK 20260905000000_add_claims.sql (2.76ms)23562026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.78ms)23572026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (6.37ms)23582026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (5.13ms)23592026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (4.21ms)23602026/10/01 07:36:14 goose: successfully migrated database to version: 202609231200002361=== RUN TestService_RequireScope_OIDC/builder_may_write2362=== PAUSE TestService_RequireScope_OIDC/builder_may_write2363=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2364=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2365=== RUN TestService_RequireScope_OIDC/ops_may_admin2366=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2367=== RUN TestService_RequireScope_OIDC/ops_may_not_write2368=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2369=== RUN TestService_RequireScope_OIDC/reader_may_not_write2370=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2371=== RUN TestService_RequireScope_OIDC/static_token_may_admin2372=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2373=== RUN TestService_RequireScope_OIDC/static_token_may_write2374=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2375=== RUN TestService_RequireScope_OIDC/reader_may_read2376=== PAUSE TestService_RequireScope_OIDC/reader_may_read2377=== RUN TestService_RequireScope_OIDC/writer_implies_read2378=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2379=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2380=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2381=== CONT TestService_RequireScope_OIDC/builder_may_write2382=== CONT TestService_RequireScope_OIDC/static_token_may_admin2383=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2384=== CONT TestService_RequireScope_OIDC/writer_implies_read2385=== CONT TestService_RequireScope_OIDC/reader_may_read2386=== CONT TestService_RequireScope_OIDC/static_token_may_write2387=== CONT TestService_RequireScope_OIDC/ops_may_admin2388=== CONT TestService_RequireScope_OIDC/ops_may_not_write2389=== CONT TestService_RequireScope_OIDC/reader_may_not_write2390=== CONT TestService_RequireScope_OIDC/builder_may_not_admin23912026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (9.93ms)23922026/10/01 07:36:14 goose: successfully migrated database to version: 202609231200002393--- PASS: TestService_RequireScope_OIDC (0.40s)2394 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2395 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2396 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2397 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2398 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2399 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2400 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2401 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2402 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2403 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)24042026/10/01 07:36:14 OK 1_commit_pending_closure.sql (11.31ms)24052026/10/01 07:36:14 OK 20260905000000_add_claims.sql (12.4ms)24062026/10/01 07:36:14 OK 20241026095416_initial_model.sql (15.28ms)24072026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.86ms)24082026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.98ms)24092026/10/01 07:36:14 OK 2_object_stats_trigger.sql (2.11ms)24102026/10/01 07:36:14 OK 2_object_stats_trigger.sql (2.64ms)24112026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (2.77ms)24122026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.84ms)24132026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000024142026/10/01 07:36:14 OK 3_commit_push.sql (1.34ms)24152026/10/01 07:36:14 goose: up to current file version: 324162026/10/01 07:36:14 OK 3_commit_push.sql (1.12ms)24172026/10/01 07:36:14 goose: up to current file version: 324182026/10/01 07:36:14 OK 20251218171726_add_pins.sql (2.9ms)24192026/10/01 07:36:14 OK 1_commit_pending_closure.sql (2.37ms)2420=== NAME TestPinProtectsFromGC2421 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC1937868533/001/store/29yyzw8cr1sqbb0gzazn7k5mxzb8l0p0-pinned-file.txt2422 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC1937868533/001/store/1dx86w1yz8x9376nw8kba8vl1qjsj2sh-unpinned-file.txt24232026/10/01 07:36:14 OK 2_object_stats_trigger.sql (873.3µs)24242026/10/01 07:36:14 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/present24252026/10/01 07:36:14 OK 3_commit_push.sql (773.91µs)24262026/10/01 07:36:14 goose: up to current file version: 324272026-10-01 07:36:14.741 UTC [1080] ERROR: relation "goose_db_version" does not exist at character 3624282026-10-01 07:36:14.741 UTC [1080] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24292026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (5.12ms)24302026/10/01 07:36:14 OK 20260905000000_add_claims.sql (2.43ms)24312026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.53ms)24322026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (998.53µs)24332026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000024342026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.6ms)24352026/10/01 07:36:14 OK 2_object_stats_trigger.sql (667.2µs)24362026/10/01 07:36:14 OK 3_commit_push.sql (595.61µs)24372026/10/01 07:36:14 goose: up to current file version: 324382026/10/01 07:36:14 OK 20241026095416_initial_model.sql (7.74ms)24392026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (963.49µs)24402026-10-01 07:36:14.756 UTC [1099] ERROR: relation "goose_db_version" does not exist at character 3624412026-10-01 07:36:14.756 UTC [1099] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24422026/10/01 07:36:14 OK 20251218171726_add_pins.sql (1.88ms)24432026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (2.43ms)24442026/10/01 07:36:14 OK 20260905000000_add_claims.sql (2.64ms)2445--- PASS: TestCacheStatsHandler (0.36s)24462026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.78ms)24472026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.45ms)24482026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000024492026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.85ms)24502026/10/01 07:36:14 OK 2_object_stats_trigger.sql (870.47µs)24512026/10/01 07:36:14 OK 20241026095416_initial_model.sql (8.34ms)24522026/10/01 07:36:14 OK 3_commit_push.sql (1.05ms)24532026/10/01 07:36:14 goose: up to current file version: 324542026/10/01 07:36:14 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)24552026/10/01 07:36:14 OK 20251218171726_add_pins.sql (2.19ms)24562026/10/01 07:36:14 OK 20260628120000_add_object_size_and_stats.sql (2.31ms)24572026/10/01 07:36:14 OK 20260905000000_add_claims.sql (3.2ms)24582026/10/01 07:36:14 OK 20260920000000_drop_claims.sql (1.52ms)24592026/10/01 07:36:14 OK 20260923120000_add_pushes.sql (1.05ms)24602026/10/01 07:36:14 goose: successfully migrated database to version: 2026092312000024612026/10/01 07:36:14 OK 1_commit_pending_closure.sql (1.39ms)24622026/10/01 07:36:14 OK 2_object_stats_trigger.sql (781.09µs)24632026/10/01 07:36:14 OK 3_commit_push.sql (607.57µs)24642026/10/01 07:36:14 goose: up to current file version: 32465=== NAME TestClientCADerivations2466 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations41441216/001/store/55pfks2dq5qxpm74s5jxi4jlzcfml4g3-ca-test2467--- PASS: TestService_ReadScope_PublicByDefault (0.33s)24682026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes24692026/10/01 07:36:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24702026/10/01 07:36:14 INFO Uploading 29yyzw8cr1sqbb0gzazn7k5mxzb8l0p0-pinned-file.txt (128B)2471=== NAME TestClientCADerivations2472 client_ca_test.go:139: Found 1 dependencies (including self)24732026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"24742026/10/01 07:36:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24752026/10/01 07:36:14 WARN Failed to register uploaded object key=29yyzw8cr1sqbb0gzazn7k5mxzb8l0p0.ls error="server returned 404: 404 page not found\n"24762026/10/01 07:36:14 INFO Signed narinfos id=1 count=124772026/10/01 07:36:14 INFO Uploading 1 narinfos24782026/10/01 07:36:14 INFO Received complete push request method=POST path=/api/pushes/1/complete24792026/10/01 07:36:14 WARN Failed to register uploaded object key=29yyzw8cr1sqbb0gzazn7k5mxzb8l0p0.narinfo error="server returned 404: 404 page not found\n"2480=== NAME TestClientIntegration2481 client_integration_test.go:286: Created store path: /build/TestClientIntegration895601604/002/store/h4md0b4r7f6bi7xm5s0nbr2427q80g52-test-file.txt24822026/10/01 07:36:14 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=191.835868ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present24832026/10/01 07:36:14 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"24842026/10/01 07:36:14 WARN mTLS auth: bound subjects configured but subject DN unavailable24852026/10/01 07:36:14 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2486--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.27s)2487--- PASS: TestGCBugBareHashReferences (0.68s)24882026/10/01 07:36:14 INFO Upload complete. (60ms)2489=== NAME TestClientMultipleUploads2490 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads700037513/001/store/vcq0jcwq259kqkzamn09h6wq35413bkx-test-file-0.txt2491--- PASS: TestService_ReadAuthMiddleware (0.29s)24922026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures2493--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.30s)2494=== NAME TestClientWithDependencies2495 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies1365193993/001/store/2wfi7ka5hz2js17psvdl9a8z3m2nr3sd-test-script24962026/10/01 07:36:14 INFO Received uploads request method=POST path=/api/pending_closures24972026/10/01 07:36:14 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)24982026/10/01 07:36:14 INFO Uploading hjq6phsw7r0nxgjgm6a22ggjgdcf9l6w-b (216B)24992026/10/01 07:36:14 INFO Uploading m1wcifwsy0f70daf6h72d412ii3vfxga-shared-dep (136B)2500=== NAME TestClientMultipleUploads2501 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads700037513/001/store/9v56v6nw0g316j22sj8qab6xhbjril1w-test-file-1.txt25022026/10/01 07:36:14 WARN Failed to register uploaded object key=np6r985m2czcwhx5mk656d5mwc2hy9w2.ls error="server returned 404: 404 page not found\n"25032026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"25042026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/123xlm7sqanw3f9m732nk0pfy2bqirad1xkifjsa9qnrab2chmng.nar.zst error="server returned 404: 404 page not found\n"25052026/10/01 07:36:14 WARN Failed to register uploaded object key=m1wcifwsy0f70daf6h72d412ii3vfxga.ls error="server returned 404: 404 page not found\n"25062026/10/01 07:36:14 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign25072026/10/01 07:36:14 WARN Failed to register uploaded object key=hjq6phsw7r0nxgjgm6a22ggjgdcf9l6w.ls error="server returned 404: 404 page not found\n"25082026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes25092026/10/01 07:36:14 INFO Signed narinfos id=1 count=225102026/10/01 07:36:14 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign25112026/10/01 07:36:14 INFO Signed narinfos id=2 count=225122026/10/01 07:36:14 INFO Uploading 4 narinfos25132026/10/01 07:36:14 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)25142026/10/01 07:36:14 INFO Uploading w9cwq22dxfh8wa1zn5r5ardsb70qx22w-b (208B)25152026/10/01 07:36:14 INFO Uploading bnnk7zmi3v33hwcfp5q6mxvrgwc4bn66-shared-dep (136B)25162026/10/01 07:36:14 WARN Failed to register uploaded object key=m1wcifwsy0f70daf6h72d412ii3vfxga.narinfo error="server returned 404: 404 page not found\n"2517=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token25182026/10/01 07:36:14 WARN Failed to register uploaded object key=np6r985m2czcwhx5mk656d5mwc2hy9w2.narinfo error="server returned 404: 404 page not found\n"2519=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2520=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2521=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2522=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2523=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2524=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2525=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2526=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token25272026/10/01 07:36:14 WARN Failed to register uploaded object key=hjq6phsw7r0nxgjgm6a22ggjgdcf9l6w.narinfo error="server returned 404: 404 page not found\n"2528=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected2529=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected25302026/10/01 07:36:14 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]2531=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured25322026/10/01 07:36:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete25332026/10/01 07:36:14 WARN Failed to register uploaded object key=m1wcifwsy0f70daf6h72d412ii3vfxga.narinfo error="server returned 404: 404 page not found\n"25342026/10/01 07:36:14 WARN Failed to register uploaded object key=is28rqz7yv4m4a24bfnbqz7d7m9mfh6n.ls error="server returned 404: 404 page not found\n"25352026/10/01 07:36:14 WARN Authentication failed token_preview=eyJhbGciOi...bAhkjISpeQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]25362026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"2537--- PASS: TestService_AuthMiddleware_OIDC (0.32s)2538 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2539 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2540 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2541 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)25422026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/15a0wvk0w6k85iwzc9m5m8qzsk5hvdna06vg06izrjpqplr5v6yc.nar.zst error="server returned 404: 404 page not found\n"25432026/10/01 07:36:14 WARN Failed to register uploaded object key=bnnk7zmi3v33hwcfp5q6mxvrgwc4bn66.ls error="server returned 404: 404 page not found\n"25442026/10/01 07:36:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25452026/10/01 07:36:14 WARN Failed to register uploaded object key=w9cwq22dxfh8wa1zn5r5ardsb70qx22w.ls error="server returned 404: 404 page not found\n"25462026/10/01 07:36:14 INFO Completed upload id=125472026/10/01 07:36:14 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete25482026/10/01 07:36:14 INFO Signed narinfos id=1 count=325492026/10/01 07:36:14 INFO Uploading 3 narinfos25502026/10/01 07:36:14 INFO Completed upload id=225512026/10/01 07:36:14 INFO Upload complete. (61ms)2552=== NAME TestClientFallsBackToClosures2553 client_pushes_test.go:112: Retrieved narinfo from S3:2554 StorePath: /build/TestClientFallsBackToClosures1612570850/001/store/m1wcifwsy0f70daf6h72d412ii3vfxga-shared-dep2555 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2556 Compression: zstd2557 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822558 NarSize: 1362559 References: 2560 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n25612026/10/01 07:36:14 WARN Failed to register uploaded object key=is28rqz7yv4m4a24bfnbqz7d7m9mfh6n.narinfo error="server returned 404: 404 page not found\n"25622026/10/01 07:36:14 WARN Failed to register uploaded object key=w9cwq22dxfh8wa1zn5r5ardsb70qx22w.narinfo error="server returned 404: 404 page not found\n"2563 client_pushes_test.go:112: Retrieved narinfo from S3:2564 StorePath: /build/TestClientFallsBackToClosures1612570850/001/store/np6r985m2czcwhx5mk656d5mwc2hy9w2-a2565 URL: nar/123xlm7sqanw3f9m732nk0pfy2bqirad1xkifjsa9qnrab2chmng.nar.zst2566 Compression: zstd2567 NarHash: sha256:123xlm7sqanw3f9m732nk0pfy2bqirad1xkifjsa9qnrab2chmng2568 NarSize: 2162569 References: /build/TestClientFallsBackToClosures1612570850/001/store/m1wcifwsy0f70daf6h72d412ii3vfxga-shared-dep2570 CA: text:sha256:17qj00687h65mifslgd1iw8mc7hm265bw2y37yzsd1pqn0rbcfwk25712026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes25722026/10/01 07:36:14 INFO Received complete push request method=POST path=/api/pushes/1/complete25732026/10/01 07:36:14 WARN Failed to register uploaded object key=bnnk7zmi3v33hwcfp5q6mxvrgwc4bn66.narinfo error="server returned 404: 404 page not found\n"2574 client_pushes_test.go:112: Retrieved narinfo from S3:2575 StorePath: /build/TestClientFallsBackToClosures1612570850/001/store/hjq6phsw7r0nxgjgm6a22ggjgdcf9l6w-b2576 URL: nar/123xlm7sqanw3f9m732nk0pfy2bqirad1xkifjsa9qnrab2chmng.nar.zst2577 Compression: zstd2578 NarHash: sha256:123xlm7sqanw3f9m732nk0pfy2bqirad1xkifjsa9qnrab2chmng2579 NarSize: 2162580 References: /build/TestClientFallsBackToClosures1612570850/001/store/m1wcifwsy0f70daf6h72d412ii3vfxga-shared-dep2581 CA: text:sha256:17qj00687h65mifslgd1iw8mc7hm265bw2y37yzsd1pqn0rbcfwk25822026/10/01 07:36:14 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)25832026/10/01 07:36:14 INFO Uploading c42pg3k52a6s8dwxhhqxjl5dwz3y597c-shared-dep (136B)25842026/10/01 07:36:14 INFO Upload complete. (56ms)25852026/10/01 07:36:14 INFO Uploading kchxsac588h3g0c58v4zzq7vwqh67az3-top (224B)2586=== NAME TestClientPushesUseOnePush2587 client_pushes_test.go:97: Retrieved narinfo from S3:2588 StorePath: /build/TestClientPushesUseOnePush664390995/001/store/bnnk7zmi3v33hwcfp5q6mxvrgwc4bn66-shared-dep2589 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2590 Compression: zstd2591 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822592 NarSize: 1362593 References: 2594 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2595--- PASS: TestClientFallsBackToClosures (0.61s)25962026/10/01 07:36:14 WARN Failed to register uploaded object key=kchxsac588h3g0c58v4zzq7vwqh67az3.ls error="server returned 404: 404 page not found\n"25972026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"25982026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/1j04xri6pxvpgvh1ca8ml2r6cig0g56a3jf3qxawlvr7hqv0qmir.nar.zst error="server returned 404: 404 page not found\n"25992026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes2600=== NAME TestClientPushesUseOnePush26012026/10/01 07:36:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign2602 client_pushes_test.go:97: Retrieved narinfo from S3:2603 StorePath: /build/TestClientPushesUseOnePush664390995/001/store/is28rqz7yv4m4a24bfnbqz7d7m9mfh6n-a2604 URL: nar/15a0wvk0w6k85iwzc9m5m8qzsk5hvdna06vg06izrjpqplr5v6yc.nar.zst2605 Compression: zstd2606 NarHash: sha256:15a0wvk0w6k85iwzc9m5m8qzsk5hvdna06vg06izrjpqplr5v6yc2607 NarSize: 2082608 References: /build/TestClientPushesUseOnePush664390995/001/store/bnnk7zmi3v33hwcfp5q6mxvrgwc4bn66-shared-dep2609 CA: text:sha256:0i5q2wclmrnqhm30blgd195d4qqlq96q7a6khl6h3ndbjn4zp9gy26102026/10/01 07:36:14 WARN Failed to register uploaded object key=c42pg3k52a6s8dwxhhqxjl5dwz3y597c.ls error="server returned 404: 404 page not found\n"26112026/10/01 07:36:14 INFO Signed narinfos id=1 count=226122026/10/01 07:36:14 INFO Uploading 2 narinfos26132026/10/01 07:36:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26142026/10/01 07:36:14 INFO Uploading 1dx86w1yz8x9376nw8kba8vl1qjsj2sh-unpinned-file.txt (128B)26152026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes2616 client_pushes_test.go:97: Retrieved narinfo from S3:2617 StorePath: /build/TestClientPushesUseOnePush664390995/001/store/w9cwq22dxfh8wa1zn5r5ardsb70qx22w-b2618 URL: nar/15a0wvk0w6k85iwzc9m5m8qzsk5hvdna06vg06izrjpqplr5v6yc.nar.zst2619 Compression: zstd2620 NarHash: sha256:15a0wvk0w6k85iwzc9m5m8qzsk5hvdna06vg06izrjpqplr5v6yc2621 NarSize: 2082622 References: /build/TestClientPushesUseOnePush664390995/001/store/bnnk7zmi3v33hwcfp5q6mxvrgwc4bn66-shared-dep2623 CA: text:sha256:0i5q2wclmrnqhm30blgd195d4qqlq96q7a6khl6h3ndbjn4zp9gy26242026/10/01 07:36:14 WARN Failed to register uploaded object key=c42pg3k52a6s8dwxhhqxjl5dwz3y597c.narinfo error="server returned 404: 404 page not found\n"26252026/10/01 07:36:14 INFO Received complete push request method=POST path=/api/pushes/1/complete26262026/10/01 07:36:14 WARN Failed to register uploaded object key=kchxsac588h3g0c58v4zzq7vwqh67az3.narinfo error="server returned 404: 404 page not found\n"26272026/10/01 07:36:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26282026/10/01 07:36:14 WARN Failed to register uploaded object key=1dx86w1yz8x9376nw8kba8vl1qjsj2sh.ls error="server returned 404: 404 page not found\n"26292026/10/01 07:36:14 INFO Uploading h4md0b4r7f6bi7xm5s0nbr2427q80g52-test-file.txt (152B)26302026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"26312026/10/01 07:36:14 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign2632--- PASS: TestClientPushesUseOnePush (0.61s)26332026/10/01 07:36:14 INFO Signed narinfos id=2 count=126342026/10/01 07:36:14 INFO Uploading 1 narinfos26352026/10/01 07:36:14 INFO Received complete push request method=POST path=/api/pushes/2/complete26362026/10/01 07:36:14 WARN Failed to register uploaded object key=1dx86w1yz8x9376nw8kba8vl1qjsj2sh.narinfo error="server returned 404: 404 page not found\n"2637=== NAME TestClientMultipleUploads26382026/10/01 07:36:14 WARN Failed to register uploaded object key=h4md0b4r7f6bi7xm5s0nbr2427q80g52.ls error="server returned 404: 404 page not found\n"2639 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads700037513/001/store/vbg62ckxc1k991n729a7ymsi7pqlnwkw-test-file-2.txt26402026/10/01 07:36:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26412026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"26422026/10/01 07:36:14 INFO Upload complete. (57ms)26432026/10/01 07:36:14 INFO Signed narinfos id=1 count=126442026/10/01 07:36:14 INFO Upload complete. (43ms)26452026/10/01 07:36:14 INFO Uploading 1 narinfos2646=== NAME TestClientSharedPathCommittedMidPush2647 client_integration_test.go:680: Retrieved narinfo from S3:2648 StorePath: /build/TestClientSharedPathCommittedMidPush2586816354/001/store/c42pg3k52a6s8dwxhhqxjl5dwz3y597c-shared-dep2649 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2650 Compression: zstd2651 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822652 NarSize: 1362653 References: 2654 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n26552026/10/01 07:36:14 INFO Received complete push request method=POST path=/api/pushes/1/complete26562026/10/01 07:36:14 WARN Failed to register uploaded object key=h4md0b4r7f6bi7xm5s0nbr2427q80g52.narinfo error="server returned 404: 404 page not found\n"2657 client_integration_test.go:680: Retrieved narinfo from S3:2658 StorePath: /build/TestClientSharedPathCommittedMidPush2586816354/001/store/kchxsac588h3g0c58v4zzq7vwqh67az3-top2659 URL: nar/1j04xri6pxvpgvh1ca8ml2r6cig0g56a3jf3qxawlvr7hqv0qmir.nar.zst2660 Compression: zstd2661 NarHash: sha256:1j04xri6pxvpgvh1ca8ml2r6cig0g56a3jf3qxawlvr7hqv0qmir2662 NarSize: 2242663 References: /build/TestClientSharedPathCommittedMidPush2586816354/001/store/c42pg3k52a6s8dwxhhqxjl5dwz3y597c-shared-dep2664 CA: text:sha256:03pj17g3md8slhk8sr4llp9pdcq3pmqlb9a4sjiz61j0flm6cki32665=== NAME TestClientWithDependencies2666 client_integration_test.go:615: Found 1 dependencies (including self)2667--- PASS: TestClientSharedPathCommittedMidPush (0.58s)26682026/10/01 07:36:14 INFO Upload complete. (49ms)26692026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes26702026/10/01 07:36:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26712026/10/01 07:36:14 INFO Uploading 55pfks2dq5qxpm74s5jxi4jlzcfml4g3-ca-test (144B)26722026/10/01 07:36:14 WARN Failed to register uploaded object key=55pfks2dq5qxpm74s5jxi4jlzcfml4g3.ls error="server returned 404: 404 page not found\n"26732026/10/01 07:36:14 WARN Failed to register uploaded object key=log/ljd64k7iik9i7a75x0f6n15mvb94wa8z-ca-test.drv error="server returned 404: 404 page not found\n"26742026/10/01 07:36:14 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"26752026/10/01 07:36:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26762026/10/01 07:36:14 INFO Received create pin request method=POST path=/api/pins/myapp26772026/10/01 07:36:14 INFO Signed narinfos id=1 count=126782026/10/01 07:36:14 INFO Uploading 1 narinfos26792026/10/01 07:36:14 INFO Received complete push request method=POST path=/api/pushes/1/complete26802026/10/01 07:36:14 WARN Failed to register uploaded object key=55pfks2dq5qxpm74s5jxi4jlzcfml4g3.narinfo error="server returned 404: 404 page not found\n"26812026/10/01 07:36:14 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1937868533/001/store/29yyzw8cr1sqbb0gzazn7k5mxzb8l0p0-pinned-file.txt narinfo_key=29yyzw8cr1sqbb0gzazn7k5mxzb8l0p0.narinfo26822026/10/01 07:36:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures26832026/10/01 07:36:14 INFO Garbage collection started26842026/10/01 07:36:14 INFO Upload complete. (93ms)26852026/10/01 07:36:14 INFO All 1 paths already cached2686=== NAME TestClientIntegration2687 client_integration_test.go:312: Retrieved narinfo from S3:2688 StorePath: /build/TestClientIntegration895601604/002/store/h4md0b4r7f6bi7xm5s0nbr2427q80g52-test-file.txt2689 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2690 Compression: zstd2691 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12692 NarSize: 1522693 References: 2694 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12695=== NAME TestClientCADerivations2696 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations41441216/001/store/55pfks2dq5qxpm74s5jxi4jlzcfml4g3-ca-test2697 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2698 Compression: zstd2699 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2700 NarSize: 1442701 References: 2702 Deriver: /build/TestClientCADerivations41441216/001/store/ljd64k7iik9i7a75x0f6n15mvb94wa8z-ca-test.drv2703 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2704 client_ca_test.go:185: Checking for realisation files in S3...2705 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2706 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2707=== NAME TestClientIntegration2708 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2709 client_integration_test.go:313: Decompressed .ls content (64 bytes):2710 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2711 client_integration_test.go:316: Testing garbage collection...27122026/10/01 07:36:14 INFO Aborted multipart uploads count=027132026/10/01 07:36:14 WARN Force mode enabled - objects will be deleted immediately without grace period27142026/10/01 07:36:14 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=027152026/10/01 07:36:14 INFO Vacuumed table table=pending_closures27162026/10/01 07:36:14 INFO Vacuumed table table=pending_objects27172026/10/01 07:36:14 INFO Vacuumed table table=multipart_uploads27182026/10/01 07:36:14 INFO Vacuumed table table=closures27192026/10/01 07:36:14 INFO Vacuumed table table=objects27202026/10/01 07:36:14 INFO Received push request method=POST path=/api/pushes27212026/10/01 07:36:14 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)27222026/10/01 07:36:14 INFO Uploading vcq0jcwq259kqkzamn09h6wq35413bkx-test-file-0.txt (160B)27232026/10/01 07:36:14 INFO Uploading 9v56v6nw0g316j22sj8qab6xhbjril1w-test-file-1.txt (160B)27242026/10/01 07:36:14 INFO Uploading vbg62ckxc1k991n729a7ymsi7pqlnwkw-test-file-2.txt (160B)27252026/10/01 07:36:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures27262026/10/01 07:36:14 INFO Garbage collection started27272026/10/01 07:36:15 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"27282026/10/01 07:36:15 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"27292026/10/01 07:36:15 WARN Failed to register uploaded object key=9v56v6nw0g316j22sj8qab6xhbjril1w.ls error="server returned 404: 404 page not found\n"27302026/10/01 07:36:15 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"27312026/10/01 07:36:15 WARN Failed to register uploaded object key=vcq0jcwq259kqkzamn09h6wq35413bkx.ls error="server returned 404: 404 page not found\n"27322026/10/01 07:36:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27332026/10/01 07:36:15 WARN Failed to register uploaded object key=vbg62ckxc1k991n729a7ymsi7pqlnwkw.ls error="server returned 404: 404 page not found\n"27342026/10/01 07:36:15 INFO Signed narinfos id=1 count=327352026/10/01 07:36:15 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"27362026/10/01 07:36:15 INFO Uploading 3 narinfos27372026/10/01 07:36:15 INFO Aborted multipart uploads count=027382026/10/01 07:36:15 INFO Received push request method=POST path=/api/pushes27392026/10/01 07:36:15 WARN Failed to register uploaded object key=vbg62ckxc1k991n729a7ymsi7pqlnwkw.narinfo error="server returned 404: 404 page not found\n"27402026/10/01 07:36:15 WARN Failed to register uploaded object key=9v56v6nw0g316j22sj8qab6xhbjril1w.narinfo error="server returned 404: 404 page not found\n"27412026/10/01 07:36:15 INFO Received complete push request method=POST path=/api/pushes/1/complete27422026/10/01 07:36:15 WARN Failed to register uploaded object key=vcq0jcwq259kqkzamn09h6wq35413bkx.narinfo error="server returned 404: 404 page not found\n"27432026/10/01 07:36:15 WARN Force mode enabled - objects will be deleted immediately without grace period27442026/10/01 07:36:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27452026/10/01 07:36:15 INFO Uploading 2wfi7ka5hz2js17psvdl9a8z3m2nr3sd-test-script (136B)27462026/10/01 07:36:15 INFO Upload complete. (58ms)2747=== NAME TestClientMultipleUploads2748 client_integration_test.go:369: Uploaded 3 paths in 94.459366ms27492026/10/01 07:36:15 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"27502026/10/01 07:36:15 WARN Failed to register uploaded object key=2wfi7ka5hz2js17psvdl9a8z3m2nr3sd.ls error="server returned 404: 404 page not found\n"27512026/10/01 07:36:15 WARN Failed to register uploaded object key=log/98f9hc4d8lgg7ryaq4wa7kwlg0mwvn10-test-script.drv error="server returned 404: 404 page not found\n"27522026/10/01 07:36:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27532026/10/01 07:36:15 INFO Signed narinfos id=1 count=127542026/10/01 07:36:15 INFO Uploading 1 narinfos27552026/10/01 07:36:15 INFO Received complete push request method=POST path=/api/pushes/1/complete27562026/10/01 07:36:15 WARN Failed to register uploaded object key=2wfi7ka5hz2js17psvdl9a8z3m2nr3sd.narinfo error="server returned 404: 404 page not found\n"27572026/10/01 07:36:15 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=02758--- PASS: TestClientMultipleUploads (0.54s)27592026/10/01 07:36:15 INFO Vacuumed table table=pending_closures27602026/10/01 07:36:15 INFO Upload complete. (55ms)27612026/10/01 07:36:15 INFO Vacuumed table table=pending_objects27622026/10/01 07:36:15 INFO Vacuumed table table=multipart_uploads2763=== NAME TestClientWithDependencies2764 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1365193993/001/store) requires matching store prefix27652026/10/01 07:36:15 INFO Vacuumed table table=closures27662026/10/01 07:36:15 INFO Vacuumed table table=objects2767--- PASS: TestClientWithDependencies (0.60s)27682026/10/01 07:36:15 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=364.173255ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27692026/10/01 07:36:15 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2770=== NAME TestClientCADerivations2771 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2772 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2773 error: binary cache 's3://bucket61?endpoint=http://localhost:42267®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations41441216/001/store'2774 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12775--- PASS: TestClientCADerivations (0.78s)2776--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)2777 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2778 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2779 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.73s)27802026/10/01 07:36:15 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=874.016299ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2781=== NAME TestOrphanedObjectsGCStressTest2782 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2783 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion2784 orphaned_objects_gc_test.go:509: Stress test completed successfully:2785 orphaned_objects_gc_test.go:510: - Active objects preserved: 202786 orphaned_objects_gc_test.go:511: - Objects deleted: 2102787 orphaned_objects_gc_test.go:512: - Total GC'd: 2102788--- PASS: TestOrphanedObjectsGCStressTest (2.18s)27892026/10/01 07:36:16 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.530824953s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27902026/10/01 07:36:16 WARN Rate limiter enabled after throttle name=s3-test rate=527912026/10/01 07:36:16 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2792=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2793 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102794 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002795--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.44s)27962026/10/01 07:36:16 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02797=== NAME TestPinProtectsFromGC2798 client_integration_test.go:794: Pin successfully protected closure from garbage collection2799--- PASS: TestPinProtectsFromGC (2.75s)28002026/10/01 07:36:16 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02801=== NAME TestClientIntegration2802 client_integration_test.go:323: Objects in database after GC:2803 client_integration_test.go:323: Successfully deleted all objects with GC --force2804--- PASS: TestClientIntegration (2.52s)28052026/10/01 07:36:17 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-config28062026/10/01 07:36:17 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=191.0012ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28072026/10/01 07:36:18 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=391.442224ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28082026/10/01 07:36:18 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=750.893631ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28092026/10/01 07:36:19 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.601557779s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28102026/10/01 07:36:20 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"28112026/10/01 07:36:20 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-config28122026/10/01 07:36:20 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=199.431541ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28132026/10/01 07:36:21 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=379.63188ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28142026/10/01 07:36:21 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=776.866168ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28152026/10/01 07:36:22 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.735717567s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28162026/10/01 07:36:24 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_closures28172026/10/01 07:36:24 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=194.261936ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28182026/10/01 07:36:24 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=380.514681ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28192026/10/01 07:36:24 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=860.979239ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28202026/10/01 07:36:25 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.688874791s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2821--- PASS: TestClientErrorHandling (0.00s)2822 --- PASS: TestClientErrorHandling/InvalidStorePath (0.31s)2823 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.39s)2824 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.67s)2825PASS2826{"timestamp":"2026-10-01T07:36:27.325384562Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:60266","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(393)"}28272026-10-01 07:36:27.710 UTC [128] LOG: received smart shutdown request28282026-10-01 07:36:27.713 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 128292026-10-01 07:36:27.727 UTC [133] LOG: shutting down28302026-10-01 07:36:27.728 UTC [133] LOG: checkpoint starting: shutdown immediate28312026-10-01 07:36:28.956 UTC [133] LOG: checkpoint complete: wrote 10573 buffers (64.5%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 21 recycled; write=0.333 s, sync=0.857 s, total=1.230 s; sync files=24927, longest=0.188 s, average=0.001 s; distance=339147 kB, estimate=339147 kB; lsn=0/16298A30, redo lsn=0/16298A3028322026-10-01 07:36:29.014 UTC [128] LOG: database system is shut down2833Running OIDC tests...2834=== RUN TestAudienceForIssuer2835=== PAUSE TestAudienceForIssuer2836=== RUN TestGlobMatch2837=== PAUSE TestGlobMatch2838=== RUN TestValidateToken_ValidToken2839=== PAUSE TestValidateToken_ValidToken2840=== RUN TestValidateToken_WrongAudience2841=== PAUSE TestValidateToken_WrongAudience2842=== RUN TestValidateToken_Expired2843=== PAUSE TestValidateToken_Expired2844=== RUN TestValidateToken_BoundClaimsMismatch2845=== PAUSE TestValidateToken_BoundClaimsMismatch2846=== RUN TestValidateToken_BoundSubjectMismatch2847=== PAUSE TestValidateToken_BoundSubjectMismatch2848=== RUN TestValidateToken_MultipleProviders2849=== PAUSE TestValidateToken_MultipleProviders2850=== RUN TestValidateToken_NoMatchingProvider2851=== PAUSE TestValidateToken_NoMatchingProvider2852=== RUN TestValidateToken_KubernetesServiceAccount2853=== PAUSE TestValidateToken_KubernetesServiceAccount2854=== RUN TestNewValidator_KubernetesRequiresCA2855=== PAUSE TestNewValidator_KubernetesRequiresCA2856=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2857=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2858=== RUN TestPins_ReservedForMatchingRule2859=== PAUSE TestPins_ReservedForMatchingRule2860=== RUN TestPins_TopLevelShorthand2861=== PAUSE TestPins_TopLevelShorthand2862=== RUN TestPins_ConfigValidation2863=== PAUSE TestPins_ConfigValidation2864=== RUN TestScopes_LegacyProviderDefaultsToWrite2865=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2866=== RUN TestScopes_Rules2867=== PAUSE TestScopes_Rules2868=== RUN TestScopes_ConfigValidation2869=== PAUSE TestScopes_ConfigValidation2870=== CONT TestAudienceForIssuer2871=== CONT TestPins_ConfigValidation2872=== CONT TestValidateToken_BoundClaimsMismatch2873--- PASS: TestAudienceForIssuer (0.00s)2874=== CONT TestValidateToken_KubernetesServiceAccount2875=== CONT TestValidateToken_Expired2876=== CONT TestValidateToken_WrongAudience2877--- PASS: TestPins_ConfigValidation (0.00s)2878=== CONT TestValidateToken_ValidToken2879=== CONT TestPins_TopLevelShorthand2880=== CONT TestPins_ReservedForMatchingRule2881=== CONT TestGlobMatch2882=== RUN TestGlobMatch/foo_foo2883=== PAUSE TestGlobMatch/foo_foo2884=== RUN TestGlobMatch/foo_bar2885=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2886=== CONT TestValidateToken_MultipleProviders2887=== CONT TestNewValidator_KubernetesRequiresCA2888=== CONT TestValidateToken_NoMatchingProvider2889=== CONT TestScopes_Rules2890=== CONT TestValidateToken_BoundSubjectMismatch2891=== CONT TestScopes_ConfigValidation2892=== CONT TestScopes_LegacyProviderDefaultsToWrite2893=== PAUSE TestGlobMatch/foo_bar2894=== RUN TestGlobMatch/*_2895=== PAUSE TestGlobMatch/*_2896=== RUN TestGlobMatch/*_anything2897=== PAUSE TestGlobMatch/*_anything2898=== RUN TestGlobMatch/foo*_foo2899=== PAUSE TestGlobMatch/foo*_foo2900=== RUN TestGlobMatch/foo*_foobar2901=== PAUSE TestGlobMatch/foo*_foobar2902=== RUN TestGlobMatch/foo*_bar2903=== PAUSE TestGlobMatch/foo*_bar2904=== RUN TestGlobMatch/*bar_bar2905=== PAUSE TestGlobMatch/*bar_bar2906=== RUN TestGlobMatch/*bar_foobar2907=== PAUSE TestGlobMatch/*bar_foobar2908=== RUN TestGlobMatch/*bar_foo2909=== PAUSE TestGlobMatch/*bar_foo2910=== RUN TestGlobMatch/foo*bar_foobar2911=== PAUSE TestGlobMatch/foo*bar_foobar2912=== RUN TestGlobMatch/foo*bar_foo123bar2913=== PAUSE TestGlobMatch/foo*bar_foo123bar2914=== RUN TestGlobMatch/foo*bar_foobarbaz2915=== PAUSE TestGlobMatch/foo*bar_foobarbaz2916=== RUN TestGlobMatch/*/*_foo/bar2917=== PAUSE TestGlobMatch/*/*_foo/bar2918=== RUN TestGlobMatch/*/*_foo2919=== PAUSE TestGlobMatch/*/*_foo2920=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2921=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2922=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02923=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02924=== RUN TestGlobMatch/refs/*/main_refs/heads/main2925=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2926=== RUN TestGlobMatch/fo?_foo2927=== PAUSE TestGlobMatch/fo?_foo2928=== RUN TestGlobMatch/fo?_fo2929=== PAUSE TestGlobMatch/fo?_fo2930=== RUN TestGlobMatch/fo?_fooo2931=== PAUSE TestGlobMatch/fo?_fooo2932=== RUN TestGlobMatch/?oo_foo2933=== PAUSE TestGlobMatch/?oo_foo2934=== RUN TestGlobMatch/?oo_boo2935=== PAUSE TestGlobMatch/?oo_boo2936=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2937=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2938=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2939=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2940=== CONT TestGlobMatch/foo_foo2941=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2942=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2943=== CONT TestGlobMatch/?oo_boo2944=== CONT TestGlobMatch/?oo_foo2945=== CONT TestGlobMatch/fo?_fooo2946=== CONT TestGlobMatch/fo?_fo2947=== CONT TestGlobMatch/fo?_foo2948=== CONT TestGlobMatch/refs/*/main_refs/heads/main2949=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02950=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2951=== CONT TestGlobMatch/*/*_foo2952=== CONT TestGlobMatch/*/*_foo/bar2953=== CONT TestGlobMatch/foo*bar_foobarbaz2954=== CONT TestGlobMatch/foo*bar_foo123bar2955=== CONT TestGlobMatch/foo*bar_foobar2956=== CONT TestGlobMatch/*bar_foo2957=== CONT TestGlobMatch/*bar_foobar2958=== CONT TestGlobMatch/*bar_bar2959=== CONT TestGlobMatch/foo*_bar2960=== CONT TestGlobMatch/foo*_foobar2961=== CONT TestGlobMatch/foo*_foo2962=== CONT TestGlobMatch/*_anything2963=== CONT TestGlobMatch/*_2964=== CONT TestGlobMatch/foo_bar2965--- PASS: TestGlobMatch (0.00s)2966 --- PASS: TestGlobMatch/foo_foo (0.00s)2967 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2968 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2969 --- PASS: TestGlobMatch/?oo_boo (0.00s)2970 --- PASS: TestGlobMatch/?oo_foo (0.00s)2971 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2972 --- PASS: TestGlobMatch/fo?_fo (0.00s)2973 --- PASS: TestGlobMatch/fo?_foo (0.00s)2974 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2975 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2976 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2977 --- PASS: TestGlobMatch/*/*_foo (0.00s)2978 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2979 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2980 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2981 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2982 --- PASS: TestGlobMatch/*bar_foo (0.00s)2983 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2984 --- PASS: TestGlobMatch/*bar_bar (0.00s)2985 --- PASS: TestGlobMatch/foo*_bar (0.00s)2986 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2987 --- PASS: TestGlobMatch/foo*_foo (0.00s)2988 --- PASS: TestGlobMatch/*_anything (0.00s)2989 --- PASS: TestGlobMatch/*_ (0.00s)2990 --- PASS: TestGlobMatch/foo_bar (0.00s)2991--- PASS: TestScopes_ConfigValidation (0.00s)29922026/10/01 07:36:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39565/oidc2993--- PASS: TestValidateToken_ValidToken (0.02s)29942026/10/01 07:36:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38013/oidc2995--- PASS: TestPins_TopLevelShorthand (0.03s)29962026/10/01 07:36:30 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12329972026/10/01 07:36:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38627/oidc2998--- PASS: TestValidateToken_WrongAudience (0.04s)29992026/10/01 07:36:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44897/oidc3000--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.04s)30012026/10/01 07:36:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43513/oidc30022026/10/01 07:36:30 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:40347/oidc3003--- PASS: TestValidateToken_Expired (0.05s)30042026/10/01 07:36:30 http: TLS handshake error from 127.0.0.1:58700: remote error: tls: bad certificate3005--- PASS: TestNewValidator_KubernetesRequiresCA (0.05s)30062026/10/01 07:36:30 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:354573007--- PASS: TestValidateToken_NoMatchingProvider (0.05s)3008--- PASS: TestScopes_Rules (0.05s)3009--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)30102026/10/01 07:36:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33619/oidc3011--- PASS: TestPins_ReservedForMatchingRule (0.06s)30122026/10/01 07:36:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44341/oidc3013--- PASS: TestValidateToken_BoundSubjectMismatch (0.07s)30142026/10/01 07:36:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42535/oidc3015--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.08s)30162026/10/01 07:36:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46873/oidc3017--- PASS: TestValidateToken_BoundClaimsMismatch (0.12s)30182026/10/01 07:36:31 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:42135/oidc30192026/10/01 07:36:31 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:36567/oidc3020--- PASS: TestValidateToken_MultipleProviders (0.24s)3021PASS3022Running hook tests...3023=== RUN TestSendPathsEmpty3024=== PAUSE TestSendPathsEmpty3025=== RUN TestQueueEnqueueAndFetch3026=== PAUSE TestQueueEnqueueAndFetch3027=== RUN TestQueueDeduplication3028=== PAUSE TestQueueDeduplication3029=== RUN TestQueueRemove3030=== PAUSE TestQueueRemove3031=== RUN TestQueueFetchBatchLimit3032=== PAUSE TestQueueFetchBatchLimit3033=== RUN TestQueueRetryMovesToBack3034=== PAUSE TestQueueRetryMovesToBack3035=== RUN TestQueueFetchRemoveLifecycle3036=== PAUSE TestQueueFetchRemoveLifecycle3037=== RUN TestQueueConcurrentWriters3038=== PAUSE TestQueueConcurrentWriters3039=== RUN TestQueueRemoveLargeClosure3040=== PAUSE TestQueueRemoveLargeClosure3041=== RUN TestServerClientIntegration3042=== PAUSE TestServerClientIntegration3043=== RUN TestServerQueueError3044=== PAUSE TestServerQueueError3045=== RUN TestGetListenerSocketActivation3046 server_test.go:210: === RUN TestGetListenerSocketActivation3047 --- PASS: TestGetListenerSocketActivation (0.00s)3048 PASS3049 3050--- PASS: TestGetListenerSocketActivation (0.01s)3051=== RUN TestDrainIsolatesPoisonPath3052=== PAUSE TestDrainIsolatesPoisonPath3053=== RUN TestRunNotBlockedByPoisonHead3054=== PAUSE TestRunNotBlockedByPoisonHead3055=== RUN TestDrainGivesUpWhenServerDown3056=== PAUSE TestDrainGivesUpWhenServerDown3057=== RUN TestFailedPathPrunedByLaterClosure3058=== PAUSE TestFailedPathPrunedByLaterClosure3059=== RUN TestWorkerUploadsAndRemoves3060=== PAUSE TestWorkerUploadsAndRemoves3061=== RUN TestWorkerSkipsGCdPaths3062=== PAUSE TestWorkerSkipsGCdPaths3063=== RUN TestWorkerPrunesClosureDeps3064=== PAUSE TestWorkerPrunesClosureDeps3065=== RUN TestDrainTimeout3066=== PAUSE TestDrainTimeout3067=== CONT TestSendPathsEmpty3068=== CONT TestServerQueueError3069--- PASS: TestSendPathsEmpty (0.00s)3070=== CONT TestServerClientIntegration3071=== CONT TestQueueRemoveLargeClosure3072=== CONT TestQueueConcurrentWriters3073=== CONT TestQueueFetchRemoveLifecycle3074=== CONT TestQueueRetryMovesToBack3075=== CONT TestQueueFetchBatchLimit3076=== CONT TestQueueRemove30772026/10/01 07:36:31 ERROR Failed to queue paths error="permission denied" count=13078=== CONT TestQueueDeduplication3079=== CONT TestQueueEnqueueAndFetch3080=== CONT TestWorkerPrunesClosureDeps3081=== CONT TestDrainTimeout3082=== CONT TestWorkerSkipsGCdPaths3083=== CONT TestDrainGivesUpWhenServerDown3084=== CONT TestFailedPathPrunedByLaterClosure3085=== CONT TestRunNotBlockedByPoisonHead3086=== CONT TestDrainIsolatesPoisonPath3087=== CONT TestWorkerUploadsAndRemoves3088--- PASS: TestServerClientIntegration (0.00s)3089--- PASS: TestServerQueueError (0.00s)30902026/10/01 07:36:31 INFO Uploading batch count=230912026/10/01 07:36:31 ERROR Upload failed error="upload failed" count=230922026/10/01 07:36:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1125357901/002/a30932026/10/01 07:36:31 INFO Upload queue status pending=230942026/10/01 07:36:31 INFO Uploading batch count=130952026/10/01 07:36:31 ERROR Upload failed error="upload failed" count=130962026/10/01 07:36:31 INFO Uploading batch count=230972026/10/01 07:36:31 INFO Uploading batch count=23098--- PASS: TestQueueFetchBatchLimit (0.04s)30992026/10/01 07:36:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1125357901/002/b31002026/10/01 07:36:31 INFO Uploading batch count=431012026/10/01 07:36:31 ERROR Upload failed error="upload failed" count=431022026/10/01 07:36:31 INFO Upload queue status pending=231032026/10/01 07:36:31 INFO Upload queue status pending=331042026/10/01 07:36:31 INFO Uploading batch count=131052026/10/01 07:36:31 INFO Uploading batch count=131062026/10/01 07:36:31 ERROR Upload failed error="upload failed" count=131072026/10/01 07:36:31 INFO Uploading batch count=131082026/10/01 07:36:31 INFO Upload queue status pending=231092026/10/01 07:36:31 INFO Uploading batch count=231102026/10/01 07:36:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath980232356/002/bbb31112026/10/01 07:36:31 ERROR Upload failed error="upload failed" count=231122026/10/01 07:36:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1125357901/002/c31132026/10/01 07:36:31 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3675636077/002/nonexistent3114--- PASS: TestQueueFetchRemoveLifecycle (0.05s)3115--- PASS: TestQueueRetryMovesToBack (0.05s)3116--- PASS: TestQueueEnqueueAndFetch (0.05s)3117--- PASS: TestQueueRemove (0.05s)31182026/10/01 07:36:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1125357901/002/d3119--- PASS: TestQueueDeduplication (0.05s)31202026/10/01 07:36:31 INFO Uploading batch count=131212026/10/01 07:36:31 INFO Uploading batch count=131222026/10/01 07:36:31 INFO Uploading batch count=231232026/10/01 07:36:31 ERROR Upload failed error="upload failed" count=231242026/10/01 07:36:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1125357901/002/e31252026/10/01 07:36:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1125357901/002/f31262026/10/01 07:36:31 INFO Uploading batch count=131272026/10/01 07:36:31 ERROR Upload failed error="upload failed" count=131282026/10/01 07:36:31 ERROR Drain finished with paths left in queue remaining=1031292026/10/01 07:36:31 INFO Uploading batch count=131302026/10/01 07:36:31 ERROR Upload failed error="upload failed" count=13131--- PASS: TestFailedPathPrunedByLaterClosure (0.05s)31322026/10/01 07:36:31 INFO Uploading batch count=131332026/10/01 07:36:31 ERROR Upload failed error="upload failed" count=131342026/10/01 07:36:31 ERROR Drain finished with paths left in queue remaining=13135--- PASS: TestDrainGivesUpWhenServerDown (0.05s)3136--- PASS: TestDrainIsolatesPoisonPath (0.05s)3137--- PASS: TestWorkerUploadsAndRemoves (0.06s)3138--- PASS: TestWorkerSkipsGCdPaths (0.06s)3139--- PASS: TestWorkerPrunesClosureDeps (0.07s)3140--- PASS: TestQueueRemoveLargeClosure (0.14s)31412026/10/01 07:36:31 ERROR Upload failed error="context deadline exceeded" count=231422026/10/01 07:36:31 ERROR Drain finished with paths left in queue remaining=43143--- PASS: TestDrainTimeout (0.25s)3144--- PASS: TestQueueConcurrentWriters (0.26s)31452026/10/01 07:36:32 INFO Uploading batch count=131462026/10/01 07:36:32 INFO Uploading batch count=131472026/10/01 07:36:32 INFO Uploading batch count=131482026/10/01 07:36:32 ERROR Upload failed error="upload failed" count=131492026/10/01 07:36:32 INFO Uploading batch count=131502026/10/01 07:36:32 ERROR Upload failed error="upload failed" count=131512026/10/01 07:36:32 INFO Uploading batch count=131522026/10/01 07:36:32 ERROR Upload failed error="upload failed" count=131532026/10/01 07:36:32 INFO Uploading batch count=131542026/10/01 07:36:32 ERROR Upload failed error="upload failed" count=131552026/10/01 07:36:32 ERROR Drain finished with paths left in queue remaining=13156--- PASS: TestRunNotBlockedByPoisonHead (1.07s)3157PASS