niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #320
· 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.05s)19=== RUN TestDumpPathCaseHackCollision20--- PASS: TestDumpPathCaseHackCollision (0.00s)21=== RUN TestDumpPathMatchesNix22=== PAUSE TestDumpPathMatchesNix23=== RUN TestDumpPathSingleFile24=== PAUSE TestDumpPathSingleFile25=== RUN TestDumpPathWriterError26=== PAUSE TestDumpPathWriterError27=== RUN TestEncodeNixBase3228=== PAUSE TestEncodeNixBase3229=== RUN TestEncodeNixBase32WithRealHash30=== PAUSE TestEncodeNixBase32WithRealHash31=== RUN TestConvertHashToNix3232=== PAUSE TestConvertHashToNix3233=== RUN TestGetStorePathHash34=== PAUSE TestGetStorePathHash35=== RUN TestPathInfoHashCompatibility36=== PAUSE TestPathInfoHashCompatibility37=== RUN TestParsePathInfoJSON38=== PAUSE TestParsePathInfoJSON39=== RUN TestParsePathInfoJSONMultiplePaths40=== PAUSE TestParsePathInfoJSONMultiplePaths41=== RUN TestPathInfoCACompatibility42=== PAUSE TestPathInfoCACompatibility43=== RUN TestRateLimiterFeedback44=== PAUSE TestRateLimiterFeedback45=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess47=== RUN TestResolveStorePath48=== PAUSE TestResolveStorePath49=== RUN TestDoWithRetry_BodyReplayedViaGetBody50=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody51=== RUN TestShellSplit52=== PAUSE TestShellSplit53=== RUN TestShellSplitErrors54=== PAUSE TestShellSplitErrors55=== RUN TestStreamPushReportsEveryPath56=== PAUSE TestStreamPushReportsEveryPath57=== RUN TestStreamPushBatchesUnderLoad58=== PAUSE TestStreamPushBatchesUnderLoad59=== RUN TestStreamPushIsolatesFailures60=== PAUSE TestStreamPushIsolatesFailures61=== RUN TestStreamPushGivesUpOnDeadServer62=== PAUSE TestStreamPushGivesUpOnDeadServer63=== RUN TestStreamPushRequestLine64=== PAUSE TestStreamPushRequestLine65=== RUN TestStreamPushReportsSignatures66=== PAUSE TestStreamPushReportsSignatures67=== RUN TestClientSignaturesByStorePath68=== PAUSE TestClientSignaturesByStorePath69=== RUN TestSetClientTLS70=== PAUSE TestSetClientTLS71=== RUN TestSetClientTLSDoesNotMutateDefaultTransport72=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport73=== RUN TestSetClientTLSErrors74=== PAUSE TestSetClientTLSErrors75=== RUN TestStaticToken76=== PAUSE TestStaticToken77=== RUN TestFileTokenReadsAndCaches78=== PAUSE TestFileTokenReadsAndCaches79=== RUN TestFileTokenMissing80=== PAUSE TestFileTokenMissing81=== RUN TestFileTokenEmpty82=== PAUSE TestFileTokenEmpty83=== RUN TestScriptTokenNoExpiryRerunsEveryCall84=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall85=== RUN TestScriptTokenCachesUntilRefresh86=== PAUSE TestScriptTokenCachesUntilRefresh87=== RUN TestScriptTokenEmptyToken88=== PAUSE TestScriptTokenEmptyToken89=== RUN TestScriptTokenBadJSON90=== PAUSE TestScriptTokenBadJSON91=== RUN TestScriptTokenScriptFails92=== PAUSE TestScriptTokenScriptFails93=== RUN TestScriptTokenEmptyCommand94=== PAUSE TestScriptTokenEmptyCommand95=== CONT TestDoServerRequestAttachesToken96=== CONT TestShellSplit97=== CONT TestEncodeNixBase32WithRealHash98--- PASS: TestEncodeNixBase32WithRealHash (0.00s)99=== CONT TestScriptTokenScriptFails100=== CONT TestSetClientTLS101=== CONT TestDoWithRetry_BodyReplayedViaGetBody102=== CONT TestResolveStorePath103=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess104=== CONT TestRateLimiterFeedback105=== CONT TestScriptTokenBadJSON106=== CONT TestPathInfoCACompatibility107=== RUN TestPathInfoCACompatibility/null_ca_field108=== CONT TestParsePathInfoJSONMultiplePaths109=== CONT TestPathInfoHashCompatibility110=== CONT TestGetStorePathHash111=== CONT TestConvertHashToNix32112=== CONT TestEncodeNixBase32113=== CONT TestUploadMultipart_SupersededByPeer114=== CONT TestFilterOversizedClosures115=== CONT TestDumpPathSingleFile116=== CONT TestPartSizeForNAR117=== CONT TestDumpPathMatchesNix1182026/10/01 09:47:07 WARN Rate limiter enabled after throttle name=server-test rate=5119=== CONT TestUploadMultipart_PartsInParallel120=== CONT TestSetClientTLSErrors121=== CONT TestStreamPushRequestLine122=== CONT TestScriptTokenEmptyCommand123=== CONT TestSetClientTLSDoesNotMutateDefaultTransport124--- PASS: TestShellSplit (0.00s)125=== RUN TestRateLimiterFeedback/429_enables_limiter126=== CONT TestClientSignaturesByStorePath127=== CONT TestParsePathInfoJSON128=== PAUSE TestPathInfoCACompatibility/null_ca_field129=== RUN TestEncodeNixBase32/test_string_hash130=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths131=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)132=== CONT TestScriptTokenEmptyToken133=== RUN TestGetStorePathHash/valid_store_path134=== RUN TestFilterOversizedClosures/no_limit_keeps_everything135=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything136=== RUN TestUploadMultipart_SupersededByPeer/exists137=== RUN TestConvertHashToNix32/SRI_format_to_Nix32138=== RUN TestPartSizeForNAR/zero_stays_at_minimum139--- PASS: TestClientSignaturesByStorePath (0.00s)140--- PASS: TestResolveStorePath (0.00s)141--- PASS: TestScriptTokenScriptFails (0.00s)142=== CONT TestScriptTokenCachesUntilRefresh143=== RUN TestParsePathInfoJSON/Nix_format144=== RUN TestPathInfoCACompatibility/old_string_format_-_text145=== PAUSE TestRateLimiterFeedback/429_enables_limiter146=== PAUSE TestEncodeNixBase32/test_string_hash147=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths148=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)149=== PAUSE TestGetStorePathHash/valid_store_path150=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped151=== RUN TestGetStorePathHash/basename_without_hyphen_should_error152--- PASS: TestScriptTokenEmptyCommand (0.00s)153=== PAUSE TestUploadMultipart_SupersededByPeer/exists154=== RUN TestUploadMultipart_SupersededByPeer/missing155=== PAUSE TestUploadMultipart_SupersededByPeer/missing156=== CONT TestStreamPushReportsSignatures157=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32158=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum159=== RUN TestConvertHashToNix32/already_Nix32_format160=== PAUSE TestConvertHashToNix32/already_Nix32_format161=== RUN TestConvertHashToNix32/invalid_format162=== PAUSE TestConvertHashToNix32/invalid_format163=== RUN TestPartSizeForNAR/small_stays_at_minimum164=== PAUSE TestPartSizeForNAR/small_stays_at_minimum165=== CONT TestScriptTokenNoExpiryRerunsEveryCall166=== PAUSE TestParsePathInfoJSON/Nix_format167=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text1682026/10/01 09:47:07 ERROR Upload failed error=boom count=1169=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive1702026/10/01 09:47:07 ERROR Upload failed error=boom count=1171=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive172--- PASS: TestDoServerRequestAttachesToken (0.03s)173=== RUN TestParsePathInfoJSON/Lix_format174=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths175=== PAUSE TestParsePathInfoJSON/Lix_format1762026/10/01 09:47:07 WARN Rate limiter enabled after throttle name=server-test rate=5177=== CONT TestStreamPushBatchesUnderLoad1782026/10/01 09:47:07 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:37377179--- PASS: TestStreamPushReportsSignatures (0.00s)180=== CONT TestFileTokenEmpty181=== CONT TestFileTokenMissing182=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum183=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum184=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts185=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts186=== RUN TestPartSizeForNAR/1_TiB187=== PAUSE TestPartSizeForNAR/1_TiB188=== RUN TestRateLimiterFeedback/503_enables_limiter189=== CONT TestStreamPushGivesUpOnDeadServer190=== RUN TestPathInfoCACompatibility/new_structured_format_-_text191=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text192=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method193=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method194=== RUN TestEncodeNixBase32/empty_input195=== PAUSE TestEncodeNixBase32/empty_input1962026/10/01 09:47:07 ERROR Upload failed error="connection refused" count=20197=== CONT TestFileTokenReadsAndCaches1982026/10/01 09:47:07 ERROR Server seems unavailable, giving up on batch untried=17199=== CONT TestStreamPushIsolatesFailures200=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2012026/10/01 09:47:07 WARN Rate limiter backed off name=server-test rate=5202=== RUN TestFilterOversizedClosures/all_closures_skipped203=== PAUSE TestFilterOversizedClosures/all_closures_skipped2042026/10/01 09:47:07 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:37377205=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error206=== CONT TestRegisterUploadedObjectReusesConnections207=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error2082026/10/01 09:47:07 ERROR Upload failed error="bad path" count=3209=== CONT TestStreamPushReportsEveryPath210=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error211=== RUN TestSetClientTLSErrors/missing_cert_file212=== PAUSE TestSetClientTLSErrors/missing_cert_file213=== CONT TestConvertHashToNix32/SRI_format_to_Nix32214=== CONT TestConvertHashToNix32/invalid_format215=== CONT TestConvertHashToNix32/already_Nix32_format216=== CONT TestPathInfoCACompatibility/null_ca_field217=== CONT TestEncodeNixBase32/test_string_hash218=== CONT TestPathInfoCACompatibility/old_string_format_-_text219=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method220=== CONT TestPathInfoCACompatibility/new_structured_format_-_text221=== RUN TestSetClientTLS/rejects_connection_without_client_cert222=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert223=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA224=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA225=== RUN TestSetClientTLS/preserves_debug_logging_transport226=== PAUSE TestSetClientTLS/preserves_debug_logging_transport227=== RUN TestParsePathInfoJSON/empty_input228=== PAUSE TestParsePathInfoJSON/empty_input229=== RUN TestParsePathInfoJSON/whitespace_only230=== PAUSE TestParsePathInfoJSON/whitespace_only231=== RUN TestParsePathInfoJSON/invalid_JSON232=== PAUSE TestParsePathInfoJSON/invalid_JSON233=== CONT TestEncodeNixBase32/empty_input234=== CONT TestFilterOversizedClosures/all_closures_skipped2352026/10/01 09:47:07 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50236=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2372026/10/01 09:47:07 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=2000238=== CONT TestSetClientTLS/rejects_connection_without_client_cert239=== CONT TestFilterOversizedClosures/no_limit_keeps_everything240=== CONT TestParsePathInfoJSON/Nix_format241=== CONT TestParsePathInfoJSON/invalid_JSON242=== CONT TestParsePathInfoJSON/whitespace_only243=== CONT TestParsePathInfoJSON/empty_input244=== CONT TestParsePathInfoJSON/Lix_format245=== CONT TestSetClientTLS/preserves_debug_logging_transport246=== CONT TestUploadMultipart_SupersededByPeer/exists247--- PASS: TestScriptTokenBadJSON (0.03s)248--- PASS: TestScriptTokenEmptyToken (0.03s)249--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)250--- PASS: TestFileTokenMissing (0.00s)251--- PASS: TestFileTokenEmpty (0.00s)252--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.03s)253--- PASS: TestStreamPushIsolatesFailures (0.00s)254=== RUN TestPartSizeForNAR/5_TiB_S3_max_object255=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object256=== RUN TestPartSizeForNAR/capped_at_5_GiB257=== PAUSE TestPartSizeForNAR/capped_at_5_GiB258=== PAUSE TestRateLimiterFeedback/503_enables_limiter259=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter260=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA261=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter262=== CONT TestStaticToken263=== CONT TestPartSizeForNAR/zero_stays_at_minimum264=== CONT TestCaseHackSuffix265=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths266=== CONT TestShellSplitErrors267=== CONT TestDumpPathWriterError268=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error269=== CONT TestUploadMultipart_SupersededByPeer/missing270=== RUN TestSetClientTLSErrors/missing_key_file271=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive272--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)273--- PASS: TestStreamPushReportsEveryPath (0.00s)274--- PASS: TestFileTokenReadsAndCaches (0.00s)275=== CONT TestPartSizeForNAR/capped_at_5_GiB276=== CONT TestPartSizeForNAR/5_TiB_S3_max_object277=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error278=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter279=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter280=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths281=== CONT TestRateLimiterFeedback/429_enables_limiter282=== CONT TestPartSizeForNAR/1_TiB283=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error284=== CONT TestGetStorePathHash/basename_without_hyphen_should_error285=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts286=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter287=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum288=== CONT TestRateLimiterFeedback/503_enables_limiter289=== CONT TestPartSizeForNAR/small_stays_at_minimum290=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error2912026/10/01 09:47:07 WARN Rate limiter enabled after throttle name=server-test rate=52922026/10/01 09:47:07 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:35133293=== PAUSE TestSetClientTLSErrors/missing_key_file294=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon2952026/10/01 09:47:07 WARN Rate limiter backed off name=server-test rate=5296=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon297=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI298=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI299=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512300=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512301=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)302--- PASS: TestConvertHashToNix32 (0.03s)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: TestStaticToken (0.00s)307=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512308=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI309--- PASS: TestShellSplitErrors (0.00s)310=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon311=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths312=== CONT TestGetStorePathHash/valid_store_path313=== RUN TestSetClientTLSErrors/missing_ca_file314=== PAUSE TestSetClientTLSErrors/missing_ca_file3152026/10/01 09:47:07 WARN Rate limiter enabled after throttle name=server-test rate=5316=== RUN TestSetClientTLSErrors/invalid_ca_file317=== PAUSE TestSetClientTLSErrors/invalid_ca_file3182026/10/01 09:47:07 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:42181319=== CONT TestSetClientTLSErrors/missing_cert_file320--- PASS: TestParsePathInfoJSONMultiplePaths (0.03s)321 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)322 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)3232026/10/01 09:47:07 WARN Rate limiter backed off name=server-test rate=5324--- PASS: TestPartSizeForNAR (0.03s)325 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)326 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)327 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)328 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)329 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)330 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)331 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)332--- PASS: TestUploadMultipart_SupersededByPeer (0.03s)333 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)334 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)335--- PASS: TestFilterOversizedClosures (0.03s)336 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)337 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)338 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)339--- PASS: TestParsePathInfoJSON (0.03s)340 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)341 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)342 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)343 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)344 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)345--- PASS: TestEncodeNixBase32 (0.03s)346 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)347 --- PASS: TestEncodeNixBase32/empty_input (0.00s)348--- PASS: TestPathInfoCACompatibility (0.03s)349 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)350 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)351 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)352 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)353 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)354=== CONT TestSetClientTLSErrors/invalid_ca_file355=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter356=== CONT TestSetClientTLSErrors/missing_ca_file357=== CONT TestSetClientTLSErrors/missing_key_file358--- PASS: TestPathInfoHashCompatibility (0.03s)359 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)360 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)361 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)362 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)363--- PASS: TestGetStorePathHash (0.03s)364 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)365 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)366 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)367 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)368--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)369--- PASS: TestRateLimiterFeedback (0.03s)370 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)371 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)372 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)373 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)374--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)375--- PASS: TestSetClientTLSErrors (0.03s)376 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)377 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)378 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.01s)379 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)3802026/10/01 09:47:07 http: TLS handshake error from 127.0.0.1:52612: remote error: tls: bad certificate381--- PASS: TestSetClientTLS (0.03s)382 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)383 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)384 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)385--- PASS: TestStreamPushRequestLine (0.05s)386--- PASS: TestDumpPathSingleFile (0.06s)387--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)388--- PASS: TestCaseHackSuffix (0.04s)389--- PASS: TestDumpPathWriterError (0.04s)390--- PASS: TestDumpPathMatchesNix (0.11s)391--- PASS: TestStreamPushBatchesUnderLoad (0.10s)392--- PASS: TestUploadMultipart_PartsInParallel (0.65s)393--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)394PASS395Running server tests...396The files belonging to this database system will be owned by user "nixbld".397This user must also own the server process.398399The database cluster will be initialized with locale "C".400The default database encoding has accordingly been set to "SQL_ASCII".401The default text search configuration will be set to "english".402403Data page checksums are enabled.404405creating directory /build/postgres3663600836/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/postgres3663600836/data -l logfile start422423/build/postgres3663600836:5432 - no response4242026-10-01 09:47:09.312 UTC [130] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 09:47:09.312 UTC [130] LOG: listening on Unix socket "/build/postgres3663600836/.s.PGSQL.5432"4262026-10-01 09:47:09.317 UTC [137] LOG: database system was shut down at 2026-10-01 09:47:08 UTC4272026-10-01 09:47:09.321 UTC [130] LOG: database system is ready to accept connections428/build/postgres3663600836:5432 - accepting connections429{"timestamp":"2026-10-01T09:47:09.615865185Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"7b657535-0ccd-4506-8499-51e36a77ca8f","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(392)"}430=== RUN TestService_AuthMiddleware431=== PAUSE TestService_AuthMiddleware432=== RUN TestService_AuthMiddleware_MTLSProxyHeader433=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader434=== RUN TestService_AuthMiddleware_MTLSBoundSubjects435=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects436=== RUN TestService_ReadAuthMiddleware437=== PAUSE TestService_ReadAuthMiddleware438=== RUN TestService_AuthMiddleware_OIDC439=== PAUSE TestService_AuthMiddleware_OIDC440=== RUN TestService_RequireScope_OIDC441=== PAUSE TestService_RequireScope_OIDC442=== RUN TestService_ReadScope_PublicByDefault443=== PAUSE TestService_ReadScope_PublicByDefault444=== RUN TestCacheConfigHandler445=== PAUSE TestCacheConfigHandler446=== RUN TestCacheStatsHandler447=== PAUSE TestCacheStatsHandler448=== RUN TestClientCADerivations449=== PAUSE TestClientCADerivations450=== RUN TestClientErrorHandling451=== PAUSE TestClientErrorHandling452=== RUN TestClientIntegration453=== PAUSE TestClientIntegration454=== RUN TestClientMultipleUploads455=== PAUSE TestClientMultipleUploads456=== RUN TestClientWithDependencies457=== PAUSE TestClientWithDependencies458=== RUN TestClientSharedPathCommittedMidPush459=== PAUSE TestClientSharedPathCommittedMidPush460=== RUN TestPinProtectsFromGC461=== PAUSE TestPinProtectsFromGC462=== RUN TestClientPushesUseOnePush463=== PAUSE TestClientPushesUseOnePush464=== RUN TestClientFallsBackToClosures465=== PAUSE TestClientFallsBackToClosures466=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock468=== RUN TestResolveDBConnectionString469=== PAUSE TestResolveDBConnectionString470=== RUN TestLeadElectsOneAndHandsOver471=== PAUSE TestLeadElectsOneAndHandsOver472=== RUN TestLeadIncumbentWinsAfterRestart4732026-10-01 09:47:09.802 UTC [567] ERROR: relation "goose_db_version" does not exist at character 364742026-10-01 09:47:09.802 UTC [567] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4752026/10/01 09:47:09 OK 20241026095416_initial_model.sql (6.67ms)4762026/10/01 09:47:09 OK 20251210153512_drop_unused_gin_index.sql (1.74ms)4772026/10/01 09:47:09 OK 20251218171726_add_pins.sql (2.1ms)4782026/10/01 09:47:09 OK 20260628120000_add_object_size_and_stats.sql (1.96ms)4792026/10/01 09:47:09 OK 20260905000000_add_claims.sql (2.4ms)4802026/10/01 09:47:09 OK 20260920000000_drop_claims.sql (1.53ms)4812026/10/01 09:47:09 OK 20260923120000_add_pushes.sql (1.03ms)4822026/10/01 09:47:09 goose: successfully migrated database to version: 202609231200004832026/10/01 09:47:09 OK 1_commit_pending_closure.sql (1.56ms)4842026/10/01 09:47:09 OK 2_object_stats_trigger.sql (692.79µs)4852026/10/01 09:47:09 OK 3_commit_push.sql (678.14µs)4862026/10/01 09:47:09 goose: up to current file version: 34872026/10/01 09:47:09 INFO lead: acquired remote=192.0.2.1:12344882026/10/01 09:47:10 INFO lead: released remote=192.0.2.1:12344892026/10/01 09:47:10 INFO lead: acquired remote=192.0.2.1:12344902026/10/01 09:47:10 INFO lead: released remote=192.0.2.1:1234491--- PASS: TestLeadIncumbentWinsAfterRestart (0.79s)492=== RUN TestLeadEndsOnShutdown493=== PAUSE TestLeadEndsOnShutdown494=== RUN TestGCAdvisoryLockBlocksConcurrentRun4952026-10-01 09:47:10.584 UTC [577] ERROR: relation "goose_db_version" does not exist at character 364962026-10-01 09:47:10.584 UTC [577] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4972026/10/01 09:47:10 OK 20241026095416_initial_model.sql (6.68ms)4982026/10/01 09:47:10 OK 20251210153512_drop_unused_gin_index.sql (1ms)4992026/10/01 09:47:10 OK 20251218171726_add_pins.sql (2.46ms)5002026/10/01 09:47:10 OK 20260628120000_add_object_size_and_stats.sql (2.3ms)5012026/10/01 09:47:10 OK 20260905000000_add_claims.sql (2.55ms)5022026/10/01 09:47:10 OK 20260920000000_drop_claims.sql (1.54ms)5032026/10/01 09:47:10 OK 20260923120000_add_pushes.sql (1.07ms)5042026/10/01 09:47:10 goose: successfully migrated database to version: 202609231200005052026/10/01 09:47:10 OK 1_commit_pending_closure.sql (1.53ms)5062026/10/01 09:47:10 OK 2_object_stats_trigger.sql (887.7µs)5072026/10/01 09:47:10 OK 3_commit_push.sql (758.86µs)5082026/10/01 09:47:10 goose: up to current file version: 3509--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.13s)510=== RUN TestGCBugBareHashReferences511=== PAUSE TestGCBugBareHashReferences512=== RUN TestGCMetrics513=== PAUSE TestGCMetrics514=== RUN TestPushDedupSurvivesConcurrentGC515=== PAUSE TestPushDedupSurvivesConcurrentGC516=== RUN TestDeduplicatedObjectsRecordedAsPending517=== PAUSE TestDeduplicatedObjectsRecordedAsPending518=== RUN TestGCSweepSkipsPendingObjects519=== PAUSE TestGCSweepSkipsPendingObjects520=== RUN TestTombstonedObjectOfferedWithoutWaiting521=== PAUSE TestTombstonedObjectOfferedWithoutWaiting522=== RUN TestGCSweepDeliversEachKeyOnce523=== PAUSE TestGCSweepDeliversEachKeyOnce524=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== RUN TestForceGCDuringPushOffersSweptObject527=== PAUSE TestForceGCDuringPushOffersSweptObject528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestSweepRechecksPendingAfterLocking537=== PAUSE TestSweepRechecksPendingAfterLocking538=== RUN TestPushWaitsForSweepHoldingRow539=== PAUSE TestPushWaitsForSweepHoldingRow540=== RUN TestCommitRacingPendingCleanupKeepsObjects541=== PAUSE TestCommitRacingPendingCleanupKeepsObjects542=== RUN TestGCEndsOnShutdown543=== PAUSE TestGCEndsOnShutdown544=== RUN TestGCTaskStore_StartNew545=== PAUSE TestGCTaskStore_StartNew546=== RUN TestGCTaskStore_DeduplicateSameParams547=== PAUSE TestGCTaskStore_DeduplicateSameParams548=== RUN TestGCTaskStore_ConflictDifferentParams549=== PAUSE TestGCTaskStore_ConflictDifferentParams550=== RUN TestGCTaskStore_GetEmpty551=== PAUSE TestGCTaskStore_GetEmpty552=== RUN TestGCTaskStore_GetReturnsLatest553=== PAUSE TestGCTaskStore_GetReturnsLatest554=== RUN TestGCTaskStore_CompletedAllowsNewTask555=== PAUSE TestGCTaskStore_CompletedAllowsNewTask556=== RUN TestGCTaskStore_PhaseUpdates557=== PAUSE TestGCTaskStore_PhaseUpdates558=== RUN TestGCTaskStore_Fail559=== PAUSE TestGCTaskStore_Fail560=== RUN TestGracefulShutdownDrainsInflight561=== PAUSE TestGracefulShutdownDrainsInflight562=== RUN TestService_healthCheckHandler563=== PAUSE TestService_healthCheckHandler564=== RUN TestService_readinessHandler565=== PAUSE TestService_readinessHandler566=== RUN TestGenerateLandingPage567=== PAUSE TestGenerateLandingPage568=== RUN TestCacheConfigHandlerMaxNarSize569=== PAUSE TestCacheConfigHandlerMaxNarSize570=== RUN TestCreatePendingClosureRejectsOversizedNAR571=== PAUSE TestCreatePendingClosureRejectsOversizedNAR572=== RUN TestNARDeduplicationMetadataUploadBug573=== PAUSE TestNARDeduplicationMetadataUploadBug574=== RUN TestMetricsInventory575=== PAUSE TestMetricsInventory576=== RUN TestService_NativeMTLS577=== PAUSE TestService_NativeMTLS578=== RUN TestServerTLSConfig579=== PAUSE TestServerTLSConfig580=== RUN TestMultipartCleanup581=== PAUSE TestMultipartCleanup582=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded584=== RUN TestPendingCleanupUsesOneCutoff585=== PAUSE TestPendingCleanupUsesOneCutoff586=== RUN TestObjectStatsTrigger587=== PAUSE TestObjectStatsTrigger588=== RUN TestOrphanedObjectsGC589=== PAUSE TestOrphanedObjectsGC590=== RUN TestOrphanedObjectsGCStressTest591=== PAUSE TestOrphanedObjectsGCStressTest592=== RUN TestCreatePin_ReservedPins593=== PAUSE TestCreatePin_ReservedPins594=== RUN TestPresentReportsOnlyClosureRoots595=== PAUSE TestPresentReportsOnlyClosureRoots596=== RUN TestPresentNotReportedWhileGCDeletesClosure597=== PAUSE TestPresentNotReportedWhileGCDeletesClosure598=== RUN TestParseSingleRange599=== PAUSE TestParseSingleRange600=== RUN TestProxyHeadersOnlyTrustedOnSocket601=== PAUSE TestProxyHeadersOnlyTrustedOnSocket602=== RUN TestIsValidCachePath603=== PAUSE TestIsValidCachePath604=== RUN TestReadProxyNarinfo605=== PAUSE TestReadProxyNarinfo606=== RUN TestReadProxyNarinfoAlreadyDecompressed607=== PAUSE TestReadProxyNarinfoAlreadyDecompressed608=== RUN TestReadProxyNarStreaming609=== PAUSE TestReadProxyNarStreaming610=== RUN TestReadProxy404611=== PAUSE TestReadProxy404612=== RUN TestReadProxyInvalidPath613=== PAUSE TestReadProxyInvalidPath614=== RUN TestReadProxyHead615=== PAUSE TestReadProxyHead616=== RUN TestReadProxyConditionalGet617=== PAUSE TestReadProxyConditionalGet618=== RUN TestReadProxyRootRedirectsToIndexHTML619=== PAUSE TestReadProxyRootRedirectsToIndexHTML620=== RUN TestReadProxyDisabled621=== PAUSE TestReadProxyDisabled622=== RUN TestReadRedirectNar623=== PAUSE TestReadRedirectNar624=== RUN TestReadRedirectKeepsNarinfoProxied625=== PAUSE TestReadRedirectKeepsNarinfoProxied626=== RUN TestReadProxyRangeRequest627=== PAUSE TestReadProxyRangeRequest628=== RUN TestReadRedirectUsesPublicS3URL629=== PAUSE TestReadRedirectUsesPublicS3URL630=== RUN TestPush_OverlappingRootsStoreOneRowPerKey631=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey632=== RUN TestPush_CompleteCommitsEveryRoot633=== PAUSE TestPush_CompleteCommitsEveryRoot634=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit635=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit636=== RUN TestPush_RejectsBadRequests637=== PAUSE TestPush_RejectsBadRequests638=== RUN TestPush_SignsNarinfosOfItsPendingObjects639=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects640=== RUN TestRedundantMultipartUpload641=== PAUSE TestRedundantMultipartUpload642=== RUN TestCompleteMultipartUpload_ErrorButObjectExists643=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists644=== RUN TestCompletedNarNotReofferedAcrossClosures645=== PAUSE TestCompletedNarNotReofferedAcrossClosures646=== RUN TestPresignedUploadRegisteredBeforeCommit647=== PAUSE TestPresignedUploadRegisteredBeforeCommit648=== RUN TestService_Rustfstest649=== PAUSE TestService_Rustfstest650=== RUN TestParseSize651=== PAUSE TestParseSize652=== RUN TestSkippedUploadsHandler653=== PAUSE TestSkippedUploadsHandler654=== RUN TestSystemdListenerNotActivated655--- PASS: TestSystemdListenerNotActivated (0.00s)656=== RUN TestWatchdogBeatsWhenHealthy657--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)658=== RUN TestWatchdogSkipsWhenUnhealthy6592026/10/01 09:47:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:47:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:47:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:47:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:47:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:47:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:47:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 09:47:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 09:47:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6682026/10/01 09:47:10 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"669--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)670=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle671=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle672=== RUN TestProxyWriteTimeout673=== PAUSE TestProxyWriteTimeout674=== RUN TestIsValidUploadKey675=== PAUSE TestIsValidUploadKey676=== RUN TestUploadHandlersRejectInvalidKeys677=== PAUSE TestUploadHandlersRejectInvalidKeys678=== RUN TestUploadHandlersRejectOversizedBody679=== PAUSE TestUploadHandlersRejectOversizedBody680=== RUN TestService_cleanupPendingClosuresHandler681=== PAUSE TestService_cleanupPendingClosuresHandler682=== RUN TestService_createPendingClosureHandler683=== PAUSE TestService_createPendingClosureHandler684=== RUN TestService_verifyS3Integrity685=== PAUSE TestService_verifyS3Integrity686=== RUN TestCompleteMultipartUnregistered687=== PAUSE TestCompleteMultipartUnregistered688=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT689=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT690=== CONT TestService_AuthMiddleware691=== CONT TestTombstonedObjectOfferedWithoutWaiting692=== CONT TestMetricsInventory693=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT694=== CONT TestCompleteMultipartUnregistered695=== CONT TestService_verifyS3Integrity696=== CONT TestService_createPendingClosureHandler697=== CONT TestService_cleanupPendingClosuresHandler698=== CONT TestUploadHandlersRejectOversizedBody699=== CONT TestUploadHandlersRejectInvalidKeys700=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info701=== CONT TestIsValidUploadKey702=== RUN TestIsValidUploadKey/narinfo703=== PAUSE TestIsValidUploadKey/narinfo704=== RUN TestIsValidUploadKey/nar_zst705=== PAUSE TestIsValidUploadKey/nar_zst706=== RUN TestIsValidUploadKey/nar_xz707=== PAUSE TestIsValidUploadKey/nar_xz708=== RUN TestIsValidUploadKey/nar_plain709=== PAUSE TestIsValidUploadKey/nar_plain710=== RUN TestIsValidUploadKey/listing711=== PAUSE TestIsValidUploadKey/listing712=== RUN TestIsValidUploadKey/build_log713=== PAUSE TestIsValidUploadKey/build_log714=== RUN TestIsValidUploadKey/build_log_home-manager_file715=== PAUSE TestIsValidUploadKey/build_log_home-manager_file716=== RUN TestIsValidUploadKey/build_log_plus_in_name717=== PAUSE TestIsValidUploadKey/build_log_plus_in_name718=== RUN TestIsValidUploadKey/build_log_question_mark719=== PAUSE TestIsValidUploadKey/build_log_question_mark720=== RUN TestIsValidUploadKey/build_log_equals721=== PAUSE TestIsValidUploadKey/build_log_equals722=== RUN TestIsValidUploadKey/realisation723=== CONT TestProxyWriteTimeout724=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle725=== RUN TestProxyWriteTimeout/narinfo726=== CONT TestSkippedUploadsHandler727=== CONT TestParseSize728=== CONT TestService_Rustfstest729=== CONT TestPresignedUploadRegisteredBeforeCommit730=== CONT TestCompletedNarNotReofferedAcrossClosures731=== CONT TestCompleteMultipartUpload_ErrorButObjectExists732=== CONT TestRedundantMultipartUpload733=== CONT TestPush_SignsNarinfosOfItsPendingObjects734=== CONT TestPush_RejectsBadRequests735=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit736=== CONT TestPush_CompleteCommitsEveryRoot737=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info738=== PAUSE TestIsValidUploadKey/realisation739--- PASS: TestParseSize (0.00s)740=== CONT TestPush_OverlappingRootsStoreOneRowPerKey7412026/10/01 09:47:10 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000742=== PAUSE TestProxyWriteTimeout/narinfo743=== RUN TestIsValidUploadKey/realisation_plus_in_output744=== RUN TestProxyWriteTimeout/1_GiB_nar745=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal746=== PAUSE TestProxyWriteTimeout/1_GiB_nar747=== RUN TestProxyWriteTimeout/10_GiB_nar748=== PAUSE TestProxyWriteTimeout/10_GiB_nar749=== PAUSE TestIsValidUploadKey/realisation_plus_in_output750=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal751=== RUN TestProxyWriteTimeout/unknown_size752=== RUN TestIsValidUploadKey/nix-cache-info753=== PAUSE TestIsValidUploadKey/nix-cache-info754=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key755=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key756=== PAUSE TestProxyWriteTimeout/unknown_size757=== RUN TestIsValidUploadKey/index.html758=== CONT TestReadRedirectUsesPublicS3URL759=== PAUSE TestIsValidUploadKey/index.html760=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key761=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key762=== RUN TestIsValidUploadKey/narinfo_key,_nar_type763=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type764=== RUN TestIsValidUploadKey/nar_key,_narinfo_type765=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type766=== CONT TestReadProxyRangeRequest767=== RUN TestIsValidUploadKey/listing_key,_narinfo_type768=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type769=== RUN TestIsValidUploadKey/traversal770=== PAUSE TestIsValidUploadKey/traversal771=== RUN TestIsValidUploadKey/traversal_nar772=== PAUSE TestIsValidUploadKey/traversal_nar773=== RUN TestIsValidUploadKey/absolute774=== PAUSE TestIsValidUploadKey/absolute775=== RUN TestIsValidUploadKey/empty_key776=== PAUSE TestIsValidUploadKey/empty_key777=== RUN TestIsValidUploadKey/unknown_type778=== PAUSE TestIsValidUploadKey/unknown_type779=== CONT TestReadRedirectKeepsNarinfoProxied780--- PASS: TestSkippedUploadsHandler (0.10s)781=== CONT TestReadRedirectNar782=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure783=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure784=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart785=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart786=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts787=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts788=== CONT TestReadProxyDisabled7892026-10-01 09:47:11.080 UTC [642] ERROR: relation "goose_db_version" does not exist at character 367902026-10-01 09:47:11.080 UTC [642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7912026-10-01 09:47:11.105 UTC [645] ERROR: relation "goose_db_version" does not exist at character 367922026-10-01 09:47:11.105 UTC [645] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7932026-10-01 09:47:11.105 UTC [646] ERROR: relation "goose_db_version" does not exist at character 367942026-10-01 09:47:11.105 UTC [646] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7952026-10-01 09:47:11.105 UTC [647] ERROR: relation "goose_db_version" does not exist at character 367962026-10-01 09:47:11.105 UTC [647] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7972026-10-01 09:47:11.108 UTC [648] ERROR: relation "goose_db_version" does not exist at character 367982026-10-01 09:47:11.108 UTC [648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7992026-10-01 09:47:11.108 UTC [649] ERROR: relation "goose_db_version" does not exist at character 368002026-10-01 09:47:11.108 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8012026-10-01 09:47:11.113 UTC [650] ERROR: relation "goose_db_version" does not exist at character 368022026-10-01 09:47:11.113 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8032026-10-01 09:47:11.134 UTC [654] ERROR: relation "goose_db_version" does not exist at character 368042026-10-01 09:47:11.134 UTC [654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8052026/10/01 09:47:11 OK 20241026095416_initial_model.sql (15.3ms)8062026-10-01 09:47:11.140 UTC [655] ERROR: relation "goose_db_version" does not exist at character 368072026-10-01 09:47:11.140 UTC [655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8082026/10/01 09:47:11 OK 20241026095416_initial_model.sql (25.95ms)8092026/10/01 09:47:11 OK 20241026095416_initial_model.sql (24.35ms)8102026/10/01 09:47:11 OK 20241026095416_initial_model.sql (26.51ms)8112026/10/01 09:47:11 OK 20241026095416_initial_model.sql (26.97ms)8122026/10/01 09:47:11 OK 20241026095416_initial_model.sql (28.19ms)8132026/10/01 09:47:11 OK 20241026095416_initial_model.sql (41.57ms)8142026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (12.54ms)8152026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (5.83ms)8162026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (3ms)8172026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.92ms)8182026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (3.73ms)8192026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (3.65ms)8202026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (3.86ms)8212026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.58ms)8222026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.87ms)8232026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.99ms)8242026/10/01 09:47:11 OK 20251218171726_add_pins.sql (6.57ms)8252026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (6.35ms)8262026/10/01 09:47:11 OK 20251218171726_add_pins.sql (9.11ms)8272026/10/01 09:47:11 OK 20251218171726_add_pins.sql (8.95ms)8282026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (7.25ms)8292026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (8.84ms)8302026/10/01 09:47:11 OK 20251218171726_add_pins.sql (10.79ms)8312026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (7.42ms)8322026/10/01 09:47:11 OK 20260905000000_add_claims.sql (6.85ms)8332026/10/01 09:47:11 OK 20241026095416_initial_model.sql (18.76ms)8342026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (3.24ms)8352026/10/01 09:47:11 OK 20260905000000_add_claims.sql (8.39ms)8362026/10/01 09:47:11 OK 20260905000000_add_claims.sql (6.71ms)8372026/10/01 09:47:11 OK 20260905000000_add_claims.sql (8.62ms)8382026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (10.35ms)8392026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (10.45ms)8402026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (5.99ms)8412026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (10.39ms)8422026/10/01 09:47:11 OK 20251218171726_add_pins.sql (13.99ms)8432026/10/01 09:47:11 OK 20241026095416_initial_model.sql (31.54ms)8442026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (12.42ms)8452026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (12.66ms)8462026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (12.59ms)8472026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (14.58ms)8482026/10/01 09:47:11 goose: successfully migrated database to version: 202609231200008492026/10/01 09:47:11 OK 20260905000000_add_claims.sql (16.34ms)8502026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (6.7ms)8512026/10/01 09:47:11 OK 1_commit_pending_closure.sql (4.77ms)8522026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (7.57ms)8532026/10/01 09:47:11 goose: successfully migrated database to version: 202609231200008542026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (7.66ms)8552026/10/01 09:47:11 goose: successfully migrated database to version: 202609231200008562026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (7.43ms)8572026/10/01 09:47:11 goose: successfully migrated database to version: 202609231200008582026/10/01 09:47:11 OK 20260905000000_add_claims.sql (21.67ms)8592026/10/01 09:47:11 OK 20260905000000_add_claims.sql (20ms)8602026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (6.17ms)8612026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (11.7ms)8622026/10/01 09:47:11 OK 2_object_stats_trigger.sql (3.33ms)8632026/10/01 09:47:11 OK 1_commit_pending_closure.sql (4.9ms)8642026/10/01 09:47:11 OK 1_commit_pending_closure.sql (4.81ms)8652026/10/01 09:47:11 OK 3_commit_push.sql (3.37ms)8662026/10/01 09:47:11 goose: up to current file version: 38672026/10/01 09:47:11 OK 1_commit_pending_closure.sql (6.58ms)8682026/10/01 09:47:11 OK 20251218171726_add_pins.sql (8.72ms)8692026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (6.5ms)8702026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (6.69ms)8712026/10/01 09:47:11 OK 20260905000000_add_claims.sql (5.5ms)8722026/10/01 09:47:11 OK 2_object_stats_trigger.sql (3.54ms)8732026/10/01 09:47:11 OK 2_object_stats_trigger.sql (3.71ms)8742026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (6.07ms)8752026/10/01 09:47:11 goose: successfully migrated database to version: 202609231200008762026/10/01 09:47:11 OK 2_object_stats_trigger.sql (4.09ms)8772026-10-01 09:47:11.210 UTC [656] ERROR: relation "goose_db_version" does not exist at character 368782026-10-01 09:47:11.210 UTC [656] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8792026/10/01 09:47:11 OK 3_commit_push.sql (5.48ms)8802026/10/01 09:47:11 OK 3_commit_push.sql (5.61ms)8812026/10/01 09:47:11 goose: up to current file version: 38822026/10/01 09:47:11 goose: up to current file version: 38832026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (6.06ms)8842026/10/01 09:47:11 goose: successfully migrated database to version: 202609231200008852026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (6.37ms)8862026/10/01 09:47:11 OK 3_commit_push.sql (5.35ms)8872026/10/01 09:47:11 goose: up to current file version: 38882026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (9.55ms)8892026/10/01 09:47:11 OK 1_commit_pending_closure.sql (7.83ms)8902026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (8.83ms)8912026/10/01 09:47:11 goose: successfully migrated database to version: 202609231200008922026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (3.5ms)8932026/10/01 09:47:11 goose: successfully migrated database to version: 202609231200008942026/10/01 09:47:11 OK 2_object_stats_trigger.sql (4.09ms)8952026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures8962026/10/01 09:47:11 OK 1_commit_pending_closure.sql (18.28ms)8972026/10/01 09:47:11 OK 20260905000000_add_claims.sql (16.21ms)8982026/10/01 09:47:11 OK 1_commit_pending_closure.sql (16ms)8992026/10/01 09:47:11 OK 1_commit_pending_closure.sql (17.77ms)9002026/10/01 09:47:11 OK 3_commit_push.sql (15.64ms)9012026/10/01 09:47:11 goose: up to current file version: 39022026/10/01 09:47:11 OK 2_object_stats_trigger.sql (5.74ms)9032026/10/01 09:47:11 OK 2_object_stats_trigger.sql (3.7ms)9042026/10/01 09:47:11 OK 2_object_stats_trigger.sql (7.17ms)9052026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (8.04ms)9062026/10/01 09:47:11 OK 3_commit_push.sql (2.93ms)9072026/10/01 09:47:11 goose: up to current file version: 39082026/10/01 09:47:11 OK 3_commit_push.sql (2.95ms)9092026/10/01 09:47:11 goose: up to current file version: 39102026/10/01 09:47:11 OK 3_commit_push.sql (3.08ms)9112026/10/01 09:47:11 goose: up to current file version: 39122026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (3.57ms)9132026/10/01 09:47:11 goose: successfully migrated database to version: 202609231200009142026-10-01 09:47:11.246 UTC [657] ERROR: relation "goose_db_version" does not exist at character 369152026-10-01 09:47:11.246 UTC [657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9162026-10-01 09:47:11.246 UTC [659] ERROR: relation "goose_db_version" does not exist at character 369172026-10-01 09:47:11.246 UTC [659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9182026-10-01 09:47:11.246 UTC [658] ERROR: relation "goose_db_version" does not exist at character 369192026-10-01 09:47:11.246 UTC [658] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9202026/10/01 09:47:11 OK 1_commit_pending_closure.sql (4.88ms)9212026/10/01 09:47:11 OK 20241026095416_initial_model.sql (12.79ms)9222026-10-01 09:47:11.250 UTC [661] ERROR: relation "goose_db_version" does not exist at character 369232026-10-01 09:47:11.250 UTC [661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9242026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.61ms)9252026-10-01 09:47:11.252 UTC [662] ERROR: relation "goose_db_version" does not exist at character 369262026-10-01 09:47:11.252 UTC [662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9272026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.19ms)9282026/10/01 09:47:11 OK 3_commit_push.sql (2.06ms)9292026/10/01 09:47:11 goose: up to current file version: 3930--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.38s)931=== CONT TestClientSharedPathCommittedMidPush9322026-10-01 09:47:11.254 UTC [663] ERROR: relation "goose_db_version" does not exist at character 369332026-10-01 09:47:11.254 UTC [663] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9342026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures9352026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures9362026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures9372026-10-01 09:47:11.256 UTC [664] ERROR: relation "goose_db_version" does not exist at character 369382026-10-01 09:47:11.256 UTC [664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9392026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.95ms)9402026-10-01 09:47:11.260 UTC [665] ERROR: relation "goose_db_version" does not exist at character 369412026-10-01 09:47:11.260 UTC [665] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9422026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.14ms)9432026-10-01 09:47:11.261 UTC [666] ERROR: relation "goose_db_version" does not exist at character 369442026-10-01 09:47:11.261 UTC [666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9452026-10-01 09:47:11.262 UTC [667] ERROR: relation "goose_db_version" does not exist at character 369462026-10-01 09:47:11.262 UTC [667] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9472026/10/01 09:47:11 OK 20241026095416_initial_model.sql (10.01ms)9482026-10-01 09:47:11.263 UTC [669] ERROR: relation "goose_db_version" does not exist at character 369492026-10-01 09:47:11.263 UTC [669] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9502026/10/01 09:47:11 OK 20241026095416_initial_model.sql (11.16ms)9512026/10/01 09:47:11 OK 20260905000000_add_claims.sql (4.01ms)9522026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)9532026/10/01 09:47:11 OK 20241026095416_initial_model.sql (11.54ms)9542026-10-01 09:47:11.265 UTC [671] ERROR: relation "goose_db_version" does not exist at character 369552026-10-01 09:47:11.265 UTC [671] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9562026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (1.93ms)9572026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)9582026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.46ms)9592026/10/01 09:47:11 OK 20241026095416_initial_model.sql (9.52ms)9602026-10-01 09:47:11.268 UTC [672] ERROR: relation "goose_db_version" does not exist at character 369612026-10-01 09:47:11.268 UTC [672] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9622026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.34ms)9632026/10/01 09:47:11 OK 20241026095416_initial_model.sql (9.93ms)9642026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)9652026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.27ms)9662026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (3.12ms)9672026/10/01 09:47:11 goose: successfully migrated database to version: 202609231200009682026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.44ms)9692026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)9702026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.09ms)9712026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.72ms)9722026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.84ms)9732026/10/01 09:47:11 OK 20241026095416_initial_model.sql (12.74ms)9742026-10-01 09:47:11.274 UTC [673] ERROR: relation "goose_db_version" does not exist at character 369752026-10-01 09:47:11.274 UTC [673] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9762026/10/01 09:47:11 OK 20251218171726_add_pins.sql (5.18ms)9772026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (6.55ms)9782026/10/01 09:47:11 OK 20241026095416_initial_model.sql (12.63ms)9792026/10/01 09:47:11 OK 2_object_stats_trigger.sql (3.58ms)9802026/10/01 09:47:11 OK 20260905000000_add_claims.sql (5.06ms)9812026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.08ms)9822026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (6.17ms)9832026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (3.12ms)9842026/10/01 09:47:11 OK 3_commit_push.sql (1.33ms)9852026/10/01 09:47:11 goose: up to current file version: 39862026/10/01 09:47:11 OK 20241026095416_initial_model.sql (12.87ms)9872026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.86ms)9882026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.92ms)9892026/10/01 09:47:11 OK 20260905000000_add_claims.sql (4.16ms)9902026/10/01 09:47:11 OK 20241026095416_initial_model.sql (11.73ms)9912026/10/01 09:47:11 OK 20241026095416_initial_model.sql (11.77ms)9922026/10/01 09:47:11 OK 20260905000000_add_claims.sql (4.86ms)9932026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.75ms)9942026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (5.8ms)9952026/10/01 09:47:11 OK 20260905000000_add_claims.sql (4.95ms)9962026/10/01 09:47:11 OK 20241026095416_initial_model.sql (11.79ms)9972026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.52ms)9982026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures9992026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (3.07ms)10002026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010012026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)10022026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.53ms)10032026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (3.09ms)10042026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.83ms)10052026/10/01 09:47:11 OK 20241026095416_initial_model.sql (12.24ms)10062026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.31ms)10072026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (3.22ms)10082026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (3.02ms)10092026/10/01 09:47:11 OK 20260905000000_add_claims.sql (3.65ms)10102026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.58ms)10112026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.72ms)10122026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010132026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.11ms)10142026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)10152026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.26ms)10162026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.62ms)10172026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.73ms)10182026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.23ms)10192026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.63ms)10202026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010212026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.96ms)10222026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010232026/10/01 09:47:11 OK 20241026095416_initial_model.sql (11.04ms)10242026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.78ms)10252026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)10262026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (3.24ms)10272026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.49ms)10282026/10/01 09:47:11 OK 3_commit_push.sql (1.46ms)10292026/10/01 09:47:11 goose: up to current file version: 310302026/10/01 09:47:11 OK 20251218171726_add_pins.sql (2.9ms)10312026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.99ms)10322026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.45ms)10332026/10/01 09:47:11 OK 20260905000000_add_claims.sql (3.97ms)10342026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.25ms)10352026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (5.27ms)10362026/10/01 09:47:11 OK 1_commit_pending_closure.sql (3.7ms)10372026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.97ms)10382026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (3.07ms)10392026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010402026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.1ms)10412026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (5.59ms)10422026/10/01 09:47:11 OK 20241026095416_initial_model.sql (10.89ms)10432026/10/01 09:47:11 OK 20260905000000_add_claims.sql (4.62ms)10442026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.66ms)10452026/10/01 09:47:11 OK 3_commit_push.sql (1.86ms)10462026/10/01 09:47:11 goose: up to current file version: 310472026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.03ms)10482026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.36ms)10492026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (5.62ms)10502026/10/01 09:47:11 OK 3_commit_push.sql (2.18ms)10512026/10/01 09:47:11 goose: up to current file version: 310522026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.39ms)10532026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.79ms)10542026/10/01 09:47:11 OK 20260905000000_add_claims.sql (4.29ms)10552026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.31ms)10562026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.68ms)10572026/10/01 09:47:11 OK 3_commit_push.sql (7.18ms)10582026/10/01 09:47:11 goose: up to current file version: 310592026/10/01 09:47:11 OK 20260905000000_add_claims.sql (10.05ms)10602026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (8.26ms)10612026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010622026/10/01 09:47:11 OK 2_object_stats_trigger.sql (7.4ms)10632026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (7.08ms)10642026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010652026/10/01 09:47:11 OK 20260905000000_add_claims.sql (10.13ms)10662026/10/01 09:47:11 OK 20260905000000_add_claims.sql (8.76ms)10672026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (7.96ms)10682026/10/01 09:47:11 OK 20251218171726_add_pins.sql (7.19ms)10692026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (7.63ms)10702026/10/01 09:47:11 OK 20260905000000_add_claims.sql (8.7ms)10712026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (5.67ms)10722026/10/01 09:47:11 OK 1_commit_pending_closure.sql (5.61ms)10732026/10/01 09:47:11 OK 3_commit_push.sql (4.59ms)10742026/10/01 09:47:11 goose: up to current file version: 310752026/10/01 09:47:11 OK 1_commit_pending_closure.sql (4.35ms)10762026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (3.92ms)10772026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010782026/10/01 09:47:11 OK 20260905000000_add_claims.sql (3.72ms)10792026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (4.69ms)10802026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (4.89ms)10812026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.63ms)10822026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (4.41ms)10832026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.28ms)10842026/10/01 09:47:11 OK 2_object_stats_trigger.sql (11.28ms)10852026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (11.96ms)10862026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010872026/10/01 09:47:11 OK 3_commit_push.sql (22.07ms)10882026/10/01 09:47:11 goose: up to current file version: 310892026/10/01 09:47:11 OK 1_commit_pending_closure.sql (22.95ms)10902026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (22.7ms)10912026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010922026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (23.62ms)10932026/10/01 09:47:11 OK 20260905000000_add_claims.sql (22.48ms)10942026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (22.45ms)10952026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010962026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (22.64ms)10972026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000010982026/10/01 09:47:11 OK 3_commit_push.sql (13.62ms)10992026/10/01 09:47:11 goose: up to current file version: 311002026/10/01 09:47:11 OK 1_commit_pending_closure.sql (13.29ms)11012026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.45ms)11022026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.56ms)11032026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (3.15ms)11042026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000011052026/10/01 09:47:11 OK 1_commit_pending_closure.sql (3.34ms)11062026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.85ms)11072026/10/01 09:47:11 OK 3_commit_push.sql (2.18ms)11082026/10/01 09:47:11 goose: up to current file version: 311092026/10/01 09:47:11 OK 1_commit_pending_closure.sql (3.84ms)11102026/10/01 09:47:11 OK 1_commit_pending_closure.sql (3.91ms)11112026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.27ms)11122026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000011132026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.71ms)11142026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.44ms)11152026/10/01 09:47:11 OK 3_commit_push.sql (1.39ms)11162026/10/01 09:47:11 goose: up to current file version: 311172026/10/01 09:47:11 OK 2_object_stats_trigger.sql (25.35ms)11182026/10/01 09:47:11 OK 3_commit_push.sql (26.55ms)11192026/10/01 09:47:11 goose: up to current file version: 311202026/10/01 09:47:11 OK 2_object_stats_trigger.sql (25.94ms)11212026/10/01 09:47:11 OK 1_commit_pending_closure.sql (26.66ms)11222026/10/01 09:47:11 OK 2_object_stats_trigger.sql (27.14ms)11232026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures11242026/10/01 09:47:11 OK 3_commit_push.sql (2.32ms)11252026/10/01 09:47:11 goose: up to current file version: 311262026/10/01 09:47:11 OK 3_commit_push.sql (1.31ms)11272026/10/01 09:47:11 goose: up to current file version: 311282026/10/01 09:47:11 OK 3_commit_push.sql (2.39ms)11292026/10/01 09:47:11 goose: up to current file version: 311302026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.72ms)11312026/10/01 09:47:11 OK 3_commit_push.sql (1.47ms)11322026/10/01 09:47:11 goose: up to current file version: 311332026-10-01 09:47:11.376 UTC [675] ERROR: relation "goose_db_version" does not exist at character 3611342026-10-01 09:47:11.376 UTC [675] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1135--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.50s)1136=== CONT TestReadProxyRootRedirectsToIndexHTML11372026/10/01 09:47:11 OK 20241026095416_initial_model.sql (7.04ms)11382026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (956.31µs)11392026/10/01 09:47:11 OK 20251218171726_add_pins.sql (2.5ms)11402026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures11412026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (2.98ms)11422026/10/01 09:47:11 OK 20260905000000_add_claims.sql (13.07ms)11432026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (3.58ms)11442026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.1ms)11452026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000011462026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.16ms)11472026/10/01 09:47:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11482026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.35ms)11492026/10/01 09:47:11 OK 3_commit_push.sql (1.26ms)11502026/10/01 09:47:11 goose: up to current file version: 311512026/10/01 09:47:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11522026/10/01 09:47:11 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1153--- PASS: TestCompleteMultipartUnregistered (0.55s)1154=== CONT TestReadProxyConditionalGet11552026/10/01 09:47:11 INFO Received cleanup request method=DELETE path=/api/pending_closures11562026/10/01 09:47:11 INFO Aborted multipart uploads count=0 kept=011572026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures11582026-10-01 09:47:11.470 UTC [680] ERROR: relation "goose_db_version" does not exist at character 3611592026-10-01 09:47:11.470 UTC [680] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11602026/10/01 09:47:11 INFO Received cleanup request method=DELETE path=/api/pending_closures11612026/10/01 09:47:11 INFO Aborted multipart uploads count=1 kept=011622026/10/01 09:47:11 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1163--- PASS: TestService_AuthMiddleware (0.60s)11642026/10/01 09:47:11 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1165=== CONT TestReadProxyHead11662026-10-01 09:47:11.478 UTC [654] ERROR: Closure does not exist: id=111672026-10-01 09:47:11.478 UTC [654] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE11682026-10-01 09:47:11.478 UTC [654] STATEMENT: -- name: CommitPendingClosure :exec1169 SELECT commit_pending_closure($1::bigint)1170 1171--- PASS: TestService_cleanupPendingClosuresHandler (0.60s)1172=== CONT TestGCSweepSkipsPendingObjects11732026/10/01 09:47:11 OK 20241026095416_initial_model.sql (8.21ms)11742026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (1.61ms)11752026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.5ms)11762026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (3.2ms)11772026/10/01 09:47:11 OK 20260905000000_add_claims.sql (3.03ms)11782026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.19ms)11792026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.47ms)11802026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000011812026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.79ms)11822026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.39ms)11832026/10/01 09:47:11 OK 3_commit_push.sql (1.2ms)11842026/10/01 09:47:11 goose: up to current file version: 311852026-10-01 09:47:11.525 UTC [685] ERROR: relation "goose_db_version" does not exist at character 3611862026-10-01 09:47:11.525 UTC [685] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11872026/10/01 09:47:11 INFO Received push request method=POST path=/api/pushes1188--- PASS: TestMetricsInventory (0.66s)1189=== CONT TestReadProxyInvalidPath11902026/10/01 09:47:11 OK 20241026095416_initial_model.sql (9.08ms)11912026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.21ms)11922026/10/01 09:47:11 OK 20251218171726_add_pins.sql (2.7ms)11932026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (3.85ms)11942026/10/01 09:47:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11952026/10/01 09:47:11 INFO Signed narinfos id=1 count=11196--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.56s)1197=== CONT TestDeduplicatedObjectsRecordedAsPending11982026/10/01 09:47:11 OK 20260905000000_add_claims.sql (11.02ms)11992026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (4.14ms)12002026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.68ms)12012026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000012022026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.56ms)12032026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.66ms)12042026-10-01 09:47:11.572 UTC [690] ERROR: relation "goose_db_version" does not exist at character 3612052026-10-01 09:47:11.572 UTC [690] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12062026/10/01 09:47:11 OK 3_commit_push.sql (1.42ms)12072026/10/01 09:47:11 goose: up to current file version: 312082026-10-01 09:47:11.575 UTC [691] ERROR: relation "goose_db_version" does not exist at character 3612092026-10-01 09:47:11.575 UTC [691] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1210--- PASS: TestReadRedirectUsesPublicS3URL (0.59s)1211=== CONT TestReadProxy40412122026/10/01 09:47:11 OK 20241026095416_initial_model.sql (8.83ms)12132026/10/01 09:47:11 OK 20241026095416_initial_model.sql (8.24ms)12142026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.32ms)12152026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)12162026/10/01 09:47:11 OK 20251218171726_add_pins.sql (2.8ms)12172026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.2ms)1218--- PASS: TestService_Rustfstest (0.61s)1219=== CONT TestPushDedupSurvivesConcurrentGC12202026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (3.92ms)12212026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.14ms)12222026/10/01 09:47:11 OK 20260905000000_add_claims.sql (3.04ms)12232026/10/01 09:47:11 OK 20260905000000_add_claims.sql (2.87ms)12242026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.41ms)12252026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.44ms)12262026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (1.73ms)12272026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000012282026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.73ms)12292026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000012302026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.7ms)12312026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.08ms)12322026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.94ms)12332026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.03ms)12342026/10/01 09:47:11 OK 3_commit_push.sql (1.89ms)12352026/10/01 09:47:11 goose: up to current file version: 312362026/10/01 09:47:11 OK 3_commit_push.sql (1.83ms)12372026/10/01 09:47:11 goose: up to current file version: 312382026/10/01 09:47:11 INFO Received push request method=POST path=/api/pushes12392026-10-01 09:47:11.632 UTC [696] ERROR: relation "goose_db_version" does not exist at character 3612402026-10-01 09:47:11.632 UTC [696] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12412026/10/01 09:47:11 OK 20241026095416_initial_model.sql (8.52ms)12422026/10/01 09:47:11 INFO Received complete push request method=POST path=/api/pushes/1/complete12432026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)12442026/10/01 09:47:11 OK 20251218171726_add_pins.sql (2.81ms)12452026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures12462026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (3.5ms)12472026/10/01 09:47:11 INFO Received push request method=POST path=/api/pushes12482026-10-01 09:47:11.658 UTC [698] ERROR: relation "goose_db_version" does not exist at character 3612492026-10-01 09:47:11.658 UTC [698] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12502026/10/01 09:47:11 OK 20260905000000_add_claims.sql (9.78ms)12512026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (7.43ms)12522026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.5ms)12532026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000012542026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.53ms)12552026/10/01 09:47:11 OK 20241026095416_initial_model.sql (8.54ms)12562026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.09ms)12572026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (1.56ms)12582026/10/01 09:47:11 OK 3_commit_push.sql (1.51ms)12592026/10/01 09:47:11 goose: up to current file version: 312602026/10/01 09:47:11 OK 20251218171726_add_pins.sql (2.74ms)12612026/10/01 09:47:11 INFO Received push request method=POST path=/api/pushes12622026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (2.83ms)12632026/10/01 09:47:11 OK 20260905000000_add_claims.sql (2.64ms)12642026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (1.85ms)12652026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (1.06ms)12662026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000012672026-10-01 09:47:11.698 UTC [699] ERROR: relation "goose_db_version" does not exist at character 3612682026-10-01 09:47:11.698 UTC [699] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12692026/10/01 09:47:11 OK 1_commit_pending_closure.sql (3.69ms)12702026-10-01 09:47:11.698 UTC [700] ERROR: relation "goose_db_version" does not exist at character 3612712026-10-01 09:47:11.698 UTC [700] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12722026/10/01 09:47:11 OK 2_object_stats_trigger.sql (710.77µs)12732026/10/01 09:47:11 OK 3_commit_push.sql (626.16µs)12742026/10/01 09:47:11 goose: up to current file version: 312752026/10/01 09:47:11 OK 20241026095416_initial_model.sql (7.48ms)12762026/10/01 09:47:11 OK 20241026095416_initial_model.sql (7.81ms)12772026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (909.34µs)1278--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.72s)1279=== CONT TestReadProxyNarStreaming12802026/10/01 09:47:11 INFO Received push request method=POST path=/api/pushes12812026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (1.09ms)12822026/10/01 09:47:11 OK 20251218171726_add_pins.sql (2.29ms)12832026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.36ms)12842026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (2.62ms)12852026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (3.61ms)12862026/10/01 09:47:11 OK 20260905000000_add_claims.sql (2.5ms)12872026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (1.65ms)12882026/10/01 09:47:11 OK 20260905000000_add_claims.sql (3.25ms)12892026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.47ms)12902026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000012912026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.47ms)12922026/10/01 09:47:11 OK 1_commit_pending_closure.sql (1.46ms)12932026/10/01 09:47:11 OK 2_object_stats_trigger.sql (904.8µs)12942026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (1.34ms)12952026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000012962026/10/01 09:47:11 OK 3_commit_push.sql (741.69µs)12972026/10/01 09:47:11 goose: up to current file version: 312982026/10/01 09:47:11 OK 1_commit_pending_closure.sql (3.39ms)12992026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.87ms)13002026/10/01 09:47:11 INFO Aborted multipart uploads count=0 kept=013012026/10/01 09:47:11 OK 3_commit_push.sql (799.66µs)13022026/10/01 09:47:11 goose: up to current file version: 313032026/10/01 09:47:11 WARN Force mode enabled - objects will be deleted immediately without grace period13042026/10/01 09:47:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13052026/10/01 09:47:11 INFO Received complete push request method=POST path=/api/pushes/1/complete1306--- PASS: TestPush_CompleteCommitsEveryRoot (0.76s)1307=== CONT TestGCMetrics1308--- PASS: TestReadRedirectKeepsNarinfoProxied (0.76s)1309=== CONT TestReadProxyNarinfoAlreadyDecompressed13102026/10/01 09:47:11 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=013112026/10/01 09:47:11 INFO Vacuumed table table=pending_closures13122026/10/01 09:47:11 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MGNmOTFlZDQtZGRjYS00ZGU1LTljYzAtODQ2OTY1MGMyNWYwLmQxM2Y3MDA3LTQ0MmMtNDVlYy1hZWNjLTg3NzAwZjEzN2IwZHgxNzkwODQ4MDMxMjY4MjQ1MTc1 parts=1013132026/10/01 09:47:11 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13142026/10/01 09:47:11 INFO Vacuumed table table=pending_objects13152026/10/01 09:47:11 INFO Vacuumed table table=multipart_uploads13162026/10/01 09:47:11 INFO Completed upload id=113172026/10/01 09:47:11 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013182026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures13192026/10/01 09:47:11 INFO Vacuumed table table=closures13202026/10/01 09:47:11 INFO Starting cleanup of old closures method=DELETE path=/api/closures13212026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures13222026/10/01 09:47:11 INFO Vacuumed table table=objects13232026/10/01 09:47:11 INFO Received complete push request method=POST path=/api/pushes/2/complete1324--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.79s)1325=== CONT TestReadProxyNarinfo13262026/10/01 09:47:11 INFO Aborted multipart uploads count=0 kept=013272026/10/01 09:47:11 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=013282026/10/01 09:47:11 INFO Vacuumed table table=pending_closures13292026/10/01 09:47:11 INFO Vacuumed table table=pending_objects13302026/10/01 09:47:11 INFO Vacuumed table table=multipart_uploads13312026-10-01 09:47:11.799 UTC [729] ERROR: relation "goose_db_version" does not exist at character 3613322026-10-01 09:47:11.799 UTC [729] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13332026/10/01 09:47:11 INFO Vacuumed table table=closures13342026/10/01 09:47:11 INFO Vacuumed table table=objects1335--- PASS: TestReadProxyRangeRequest (0.82s)1336=== CONT TestGCBugBareHashReferences13372026/10/01 09:47:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13382026/10/01 09:47:11 OK 20241026095416_initial_model.sql (10.36ms)13392026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)13402026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.02ms)13412026/10/01 09:47:11 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013422026/10/01 09:47:11 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MGNmOTFlZDQtZGRjYS00ZGU1LTljYzAtODQ2OTY1MGMyNWYwLmM0MzcyZjZlLWQ4OWMtNDNhYi1hZjMyLTEzM2E3MjliY2RiOHgxNzkwODQ4MDMxNzg1OTY1NzMy1343--- PASS: TestService_createPendingClosureHandler (0.94s)1344=== CONT TestIsValidCachePath1345=== RUN TestIsValidCachePath/narinfo1346=== PAUSE TestIsValidCachePath/narinfo1347=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1348=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1349=== RUN TestIsValidCachePath/nar_zst1350=== PAUSE TestIsValidCachePath/nar_zst1351=== RUN TestIsValidCachePath/nar_xz1352=== PAUSE TestIsValidCachePath/nar_xz1353=== RUN TestIsValidCachePath/nar_bz21354=== PAUSE TestIsValidCachePath/nar_bz21355=== RUN TestIsValidCachePath/nar_uncompressed1356=== PAUSE TestIsValidCachePath/nar_uncompressed1357=== RUN TestIsValidCachePath/ls1358=== PAUSE TestIsValidCachePath/ls1359=== RUN TestIsValidCachePath/log1360=== PAUSE TestIsValidCachePath/log1361=== RUN TestIsValidCachePath/realisation1362=== PAUSE TestIsValidCachePath/realisation1363=== RUN TestIsValidCachePath/nix-cache-info1364=== PAUSE TestIsValidCachePath/nix-cache-info1365=== RUN TestIsValidCachePath/index.html1366=== PAUSE TestIsValidCachePath/index.html1367=== RUN TestIsValidCachePath/traversal_parent1368=== PAUSE TestIsValidCachePath/traversal_parent1369=== RUN TestIsValidCachePath/traversal_in_middle1370=== PAUSE TestIsValidCachePath/traversal_in_middle1371=== RUN TestIsValidCachePath/invalid_char_e1372=== PAUSE TestIsValidCachePath/invalid_char_e1373=== RUN TestIsValidCachePath/invalid_char_u1374=== PAUSE TestIsValidCachePath/invalid_char_u1375=== RUN TestIsValidCachePath/random_path1376=== PAUSE TestIsValidCachePath/random_path1377=== RUN TestIsValidCachePath/empty1378=== PAUSE TestIsValidCachePath/empty1379=== RUN TestIsValidCachePath/leading_slash1380=== PAUSE TestIsValidCachePath/leading_slash1381=== RUN TestIsValidCachePath/wrong_extension1382=== PAUSE TestIsValidCachePath/wrong_extension1383=== RUN TestIsValidCachePath/short_hash1384=== PAUSE TestIsValidCachePath/short_hash1385=== CONT TestProxyHeadersOnlyTrustedOnSocket1386--- PASS: TestReadProxyDisabled (0.76s)1387=== CONT TestLeadEndsOnShutdown13882026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (12.72ms)13892026/10/01 09:47:11 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MGNmOTFlZDQtZGRjYS00ZGU1LTljYzAtODQ2OTY1MGMyNWYwLmM0MzcyZjZlLWQ4OWMtNDNhYi1hZjMyLTEzM2E3MjliY2RiOHgxNzkwODQ4MDMxNzg1OTY1NzMy parts=11390--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.85s)1391=== CONT TestParseSingleRange1392=== RUN TestParseSingleRange/none1393=== PAUSE TestParseSingleRange/none1394=== RUN TestParseSingleRange/unknown_unit1395=== PAUSE TestParseSingleRange/unknown_unit1396=== RUN TestParseSingleRange/multi-range_ignored1397=== PAUSE TestParseSingleRange/multi-range_ignored1398=== RUN TestParseSingleRange/malformed_no_dash1399=== PAUSE TestParseSingleRange/malformed_no_dash1400=== RUN TestParseSingleRange/malformed_both_empty1401=== PAUSE TestParseSingleRange/malformed_both_empty1402=== RUN TestParseSingleRange/malformed_end_before_start1403=== PAUSE TestParseSingleRange/malformed_end_before_start1404=== RUN TestParseSingleRange/closed1405=== PAUSE TestParseSingleRange/closed1406=== RUN TestParseSingleRange/open-ended1407=== PAUSE TestParseSingleRange/open-ended1408=== RUN TestParseSingleRange/end_clamped_to_size1409=== PAUSE TestParseSingleRange/end_clamped_to_size1410=== RUN TestParseSingleRange/suffix1411=== PAUSE TestParseSingleRange/suffix1412=== RUN TestParseSingleRange/suffix_exceeds_size1413=== PAUSE TestParseSingleRange/suffix_exceeds_size1414=== RUN TestParseSingleRange/single_byte1415=== PAUSE TestParseSingleRange/single_byte1416=== RUN TestParseSingleRange/start_past_EOF1417=== PAUSE TestParseSingleRange/start_past_EOF1418=== RUN TestParseSingleRange/start_far_past_EOF1419=== PAUSE TestParseSingleRange/start_far_past_EOF1420=== CONT TestLeadElectsOneAndHandsOver14212026/10/01 09:47:11 OK 20260905000000_add_claims.sql (13.54ms)14222026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.58ms)14232026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.95ms)14242026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000014252026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.17ms)14262026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.65ms)14272026/10/01 09:47:11 OK 3_commit_push.sql (2.46ms)14282026/10/01 09:47:11 goose: up to current file version: 314292026-10-01 09:47:11.861 UTC [738] ERROR: relation "goose_db_version" does not exist at character 3614302026-10-01 09:47:11.861 UTC [738] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14312026-10-01 09:47:11.864 UTC [739] ERROR: relation "goose_db_version" does not exist at character 3614322026-10-01 09:47:11.864 UTC [739] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14332026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures14342026/10/01 09:47:11 OK 20241026095416_initial_model.sql (11.86ms)14352026/10/01 09:47:11 OK 20241026095416_initial_model.sql (9.83ms)14362026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)14372026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.58ms)14382026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.64ms)14392026-10-01 09:47:11.887 UTC [740] ERROR: relation "goose_db_version" does not exist at character 3614402026-10-01 09:47:11.887 UTC [740] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14412026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.6ms)14422026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures14432026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.3ms)14442026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.22ms)14452026/10/01 09:47:11 OK 20260905000000_add_claims.sql (3.47ms)14462026/10/01 09:47:11 OK 20260905000000_add_claims.sql (3.58ms)14472026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.65ms)14482026/10/01 09:47:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14492026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.43ms)14502026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures14512026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.65ms)14522026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000014532026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.92ms)14542026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000014552026/10/01 09:47:11 OK 20241026095416_initial_model.sql (9.46ms)14562026/10/01 09:47:11 OK 1_commit_pending_closure.sql (13.55ms)14572026/10/01 09:47:11 OK 1_commit_pending_closure.sql (15.8ms)14582026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (14.69ms)14592026/10/01 09:47:11 OK 2_object_stats_trigger.sql (5.17ms)14602026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.65ms)14612026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.29ms)14622026/10/01 09:47:11 OK 3_commit_push.sql (1.84ms)14632026/10/01 09:47:11 goose: up to current file version: 314642026/10/01 09:47:11 OK 3_commit_push.sql (1.55ms)14652026/10/01 09:47:11 goose: up to current file version: 314662026/10/01 09:47:11 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MGNmOTFlZDQtZGRjYS00ZGU1LTljYzAtODQ2OTY1MGMyNWYwLjVlNTc5NDMyLTVjN2UtNGY0Mi1iMzIxLTQ2NDM4MWNlZjQzOXgxNzkwODQ4MDMxNDE1ODc2NTIx parts=1014672026/10/01 09:47:11 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14682026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.09ms)14692026-10-01 09:47:11.928 UTC [741] ERROR: relation "goose_db_version" does not exist at character 3614702026-10-01 09:47:11.928 UTC [741] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14712026/10/01 09:47:11 OK 20260905000000_add_claims.sql (3.13ms)14722026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.05ms)14732026/10/01 09:47:11 INFO Completed upload id=114742026/10/01 09:47:11 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst14752026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures1476=== RUN TestPush_RejectsBadRequests/bad_root1477=== PAUSE TestPush_RejectsBadRequests/bad_root1478=== RUN TestPush_RejectsBadRequests/root_not_in_objects1479=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1480=== RUN TestPush_RejectsBadRequests/no_roots1481=== PAUSE TestPush_RejectsBadRequests/no_roots1482=== RUN TestPush_RejectsBadRequests/no_objects1483=== PAUSE TestPush_RejectsBadRequests/no_objects1484=== CONT TestPresentNotReportedWhileGCDeletesClosure14852026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures14862026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.75ms)14872026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000014882026/10/01 09:47:11 OK 1_commit_pending_closure.sql (3.02ms)1489--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.95s)1490=== CONT TestResolveDBConnectionString14912026/10/01 09:47:11 INFO Received uploads request method=POST path=/api/pending_closures1492=== RUN TestResolveDBConnectionString/flag_wins1493=== PAUSE TestResolveDBConnectionString/flag_wins1494=== RUN TestResolveDBConnectionString/file_when_flag_empty1495=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1496=== RUN TestResolveDBConnectionString/missing_file_is_an_error1497=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1498=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1499=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty15002026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.55ms)1501=== RUN TestResolveDBConnectionString/nothing_configured1502=== PAUSE TestResolveDBConnectionString/nothing_configured1503=== CONT TestPresentReportsOnlyClosureRoots15042026/10/01 09:47:11 OK 3_commit_push.sql (1.08ms)15052026/10/01 09:47:11 goose: up to current file version: 315062026-10-01 09:47:11.940 UTC [743] ERROR: relation "goose_db_version" does not exist at character 3615072026-10-01 09:47:11.940 UTC [743] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15082026/10/01 09:47:11 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo15092026/10/01 09:47:11 WARN Found objects in DB but missing from S3, will re-upload count=11510--- PASS: TestService_verifyS3Integrity (1.06s)1511=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock15122026/10/01 09:47:11 OK 20241026095416_initial_model.sql (9.08ms)15132026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (1.77ms)15142026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.04ms)15152026/10/01 09:47:11 OK 20241026095416_initial_model.sql (8.38ms)15162026-10-01 09:47:11.954 UTC [749] ERROR: relation "goose_db_version" does not exist at character 3615172026-10-01 09:47:11.954 UTC [749] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15182026-10-01 09:47:11.955 UTC [750] ERROR: relation "goose_db_version" does not exist at character 3615192026-10-01 09:47:11.955 UTC [750] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15202026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.6ms)15212026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.44ms)15222026/10/01 09:47:11 OK 20251218171726_add_pins.sql (2.93ms)15232026/10/01 09:47:11 OK 20260905000000_add_claims.sql (4.21ms)15242026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.7ms)15252026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (4.01ms)15262026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.77ms)15272026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000015282026/10/01 09:47:11 OK 20260905000000_add_claims.sql (3.65ms)15292026/10/01 09:47:11 OK 1_commit_pending_closure.sql (3.01ms)15302026/10/01 09:47:11 OK 20241026095416_initial_model.sql (9.88ms)15312026/10/01 09:47:11 OK 20241026095416_initial_model.sql (8.89ms)15322026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (3.88ms)15332026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.26ms)1534--- PASS: TestReadRedirectNar (0.97s)1535=== CONT TestCreatePin_ReservedPins15362026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)15372026/10/01 09:47:11 OK 20251210153512_drop_unused_gin_index.sql (2.71ms)15382026/10/01 09:47:11 OK 3_commit_push.sql (1.91ms)15392026/10/01 09:47:11 goose: up to current file version: 315402026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (2.67ms)15412026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000015422026/10/01 09:47:11 OK 20251218171726_add_pins.sql (3.07ms)15432026/10/01 09:47:11 OK 20251218171726_add_pins.sql (4.02ms)15442026/10/01 09:47:11 OK 1_commit_pending_closure.sql (3.22ms)15452026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.72ms)15462026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (3.91ms)15472026/10/01 09:47:11 OK 3_commit_push.sql (1.94ms)15482026/10/01 09:47:11 goose: up to current file version: 315492026/10/01 09:47:11 OK 20260628120000_add_object_size_and_stats.sql (3.93ms)15502026/10/01 09:47:11 OK 20260905000000_add_claims.sql (2.76ms)15512026/10/01 09:47:11 OK 20260905000000_add_claims.sql (2.92ms)15522026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.61ms)15532026/10/01 09:47:11 OK 20260920000000_drop_claims.sql (2.38ms)15542026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (1.77ms)15552026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000015562026/10/01 09:47:11 OK 20260923120000_add_pushes.sql (1.82ms)15572026/10/01 09:47:11 goose: successfully migrated database to version: 2026092312000015582026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.32ms)15592026/10/01 09:47:11 OK 1_commit_pending_closure.sql (2.34ms)15602026/10/01 09:47:11 OK 2_object_stats_trigger.sql (2.08ms)15612026/10/01 09:47:11 OK 2_object_stats_trigger.sql (1.64ms)15622026/10/01 09:47:11 OK 3_commit_push.sql (1.54ms)15632026/10/01 09:47:11 goose: up to current file version: 315642026/10/01 09:47:11 OK 3_commit_push.sql (1.63ms)15652026/10/01 09:47:11 goose: up to current file version: 31566--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.65s)1567=== CONT TestClientFallsBackToClosures15682026-10-01 09:47:12.055 UTC [771] ERROR: relation "goose_db_version" does not exist at character 3615692026-10-01 09:47:12.055 UTC [771] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15702026-10-01 09:47:12.059 UTC [772] ERROR: relation "goose_db_version" does not exist at character 3615712026-10-01 09:47:12.059 UTC [772] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15722026-10-01 09:47:12.064 UTC [773] ERROR: relation "goose_db_version" does not exist at character 3615732026-10-01 09:47:12.064 UTC [773] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1574--- PASS: TestReadProxyConditionalGet (0.64s)1575=== CONT TestOrphanedObjectsGCStressTest15762026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.07ms)15772026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (1.77ms)15782026/10/01 09:47:12 OK 20241026095416_initial_model.sql (8.46ms)15792026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)15802026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.15ms)15812026/10/01 09:47:12 OK 20251218171726_add_pins.sql (2.95ms)15822026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.23ms)15832026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.18ms)15842026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (1.46ms)15852026/10/01 09:47:12 OK 20260905000000_add_claims.sql (2.99ms)15862026/10/01 09:47:12 OK 20251218171726_add_pins.sql (2.72ms)15872026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (4.77ms)15882026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.49ms)15892026/10/01 09:47:12 OK 20260905000000_add_claims.sql (2.78ms)15902026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.58ms)15912026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000015922026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (4.17ms)15932026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.46ms)15942026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.57ms)15952026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.75ms)15962026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000015972026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.65ms)15982026/10/01 09:47:12 OK 2_object_stats_trigger.sql (2.11ms)15992026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.07ms)16002026/10/01 09:47:12 OK 3_commit_push.sql (1.8ms)16012026/10/01 09:47:12 goose: up to current file version: 316022026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.41ms)16032026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures16042026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (3.11ms)16052026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000016062026/10/01 09:47:12 OK 2_object_stats_trigger.sql (2.78ms)16072026/10/01 09:47:12 OK 3_commit_push.sql (1.4ms)16082026/10/01 09:47:12 goose: up to current file version: 316092026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.51ms)16102026/10/01 09:47:12 OK 2_object_stats_trigger.sql (2.15ms)16112026/10/01 09:47:12 OK 3_commit_push.sql (1.45ms)16122026/10/01 09:47:12 goose: up to current file version: 316132026/10/01 09:47:12 INFO Aborted multipart uploads count=0 kept=016142026/10/01 09:47:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33205/oidc16152026-10-01 09:47:12.128 UTC [811] ERROR: relation "goose_db_version" does not exist at character 3616162026-10-01 09:47:12.128 UTC [811] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16172026/10/01 09:47:12 WARN Force mode enabled - objects will be deleted immediately without grace period16182026/10/01 09:47:12 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=01619--- PASS: TestReadProxyHead (0.66s)1620=== CONT TestClientPushesUseOnePush16212026/10/01 09:47:12 INFO Vacuumed table table=pending_closures16222026/10/01 09:47:12 INFO Vacuumed table table=pending_objects16232026/10/01 09:47:12 INFO Vacuumed table table=multipart_uploads16242026/10/01 09:47:12 INFO Vacuumed table table=closures16252026/10/01 09:47:12 INFO Vacuumed table table=objects16262026/10/01 09:47:12 OK 20241026095416_initial_model.sql (8.15ms)16272026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.45ms)16282026/10/01 09:47:12 OK 20251218171726_add_pins.sql (2.94ms)1629--- PASS: TestGCSweepSkipsPendingObjects (0.67s)1630=== CONT TestOrphanedObjectsGC16312026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.44ms)16322026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.04ms)1633--- PASS: TestReadProxyInvalidPath (0.62s)1634=== CONT TestPinProtectsFromGC16352026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.67ms)16362026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (1.75ms)16372026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000016382026-10-01 09:47:12.168 UTC [821] ERROR: relation "goose_db_version" does not exist at character 3616392026-10-01 09:47:12.168 UTC [821] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16402026/10/01 09:47:12 OK 1_commit_pending_closure.sql (11.27ms)16412026/10/01 09:47:12 OK 2_object_stats_trigger.sql (3.48ms)16422026/10/01 09:47:12 INFO Received push request method=POST path=/api/pushes16432026/10/01 09:47:12 OK 3_commit_push.sql (1.43ms)16442026/10/01 09:47:12 goose: up to current file version: 316452026/10/01 09:47:12 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16462026/10/01 09:47:12 INFO Uploading 76jsjlx8743gzj096mp4kc8nqas5kllj-top (224B)16472026/10/01 09:47:12 INFO Uploading vbp8g967vrn7rncnkkf3qzllpdlmwgjm-shared-dep (136B)16482026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.28ms)16492026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.15ms)16502026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.68ms)16512026/10/01 09:47:12 WARN Failed to register uploaded object key=nar/0r1xb3003829kp8wb58rlsxv01nkw6ldckqrzk6jrxawdjlfs59l.nar.zst error="server returned 404: 404 page not found\n"16522026/10/01 09:47:12 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16532026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures16542026/10/01 09:47:12 WARN Failed to register uploaded object key=76jsjlx8743gzj096mp4kc8nqas5kllj.ls error="server returned 404: 404 page not found\n"16552026/10/01 09:47:12 WARN Failed to register uploaded object key=vbp8g967vrn7rncnkkf3qzllpdlmwgjm.ls error="server returned 404: 404 page not found\n"16562026/10/01 09:47:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16572026/10/01 09:47:12 INFO Signed narinfos id=1 count=216582026/10/01 09:47:12 INFO Uploading 2 narinfos16592026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (4.16ms)16602026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.67ms)16612026/10/01 09:47:12 WARN Failed to register uploaded object key=76jsjlx8743gzj096mp4kc8nqas5kllj.narinfo error="server returned 404: 404 page not found\n"16622026/10/01 09:47:12 INFO Received complete push request method=POST path=/api/pushes/1/complete16632026/10/01 09:47:12 WARN Failed to register uploaded object key=vbp8g967vrn7rncnkkf3qzllpdlmwgjm.narinfo error="server returned 404: 404 page not found\n"16642026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.21ms)1665--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.65s)1666=== CONT TestObjectStatsTrigger16672026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.37ms)16682026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000016692026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.26ms)16702026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.5ms)16712026/10/01 09:47:12 OK 3_commit_push.sql (1.36ms)16722026/10/01 09:47:12 goose: up to current file version: 316732026/10/01 09:47:12 INFO Upload complete. (80ms)1674=== NAME TestClientSharedPathCommittedMidPush1675 client_integration_test.go:680: Retrieved narinfo from S3:1676 StorePath: /build/TestClientSharedPathCommittedMidPush244210621/001/store/vbp8g967vrn7rncnkkf3qzllpdlmwgjm-shared-dep1677 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1678 Compression: zstd1679 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821680 NarSize: 1361681 References: 1682 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1683 client_integration_test.go:680: Retrieved narinfo from S3:1684 StorePath: /build/TestClientSharedPathCommittedMidPush244210621/001/store/76jsjlx8743gzj096mp4kc8nqas5kllj-top1685 URL: nar/0r1xb3003829kp8wb58rlsxv01nkw6ldckqrzk6jrxawdjlfs59l.nar.zst1686 Compression: zstd1687 NarHash: sha256:0r1xb3003829kp8wb58rlsxv01nkw6ldckqrzk6jrxawdjlfs59l1688 NarSize: 2241689 References: /build/TestClientSharedPathCommittedMidPush244210621/001/store/vbp8g967vrn7rncnkkf3qzllpdlmwgjm-shared-dep1690 CA: text:sha256:1nca0zxl9bkq1gjxj46hpvrws765w23hdkxi1p5nn3hrns34f9yk1691--- PASS: TestClientSharedPathCommittedMidPush (0.97s)1692=== CONT TestPendingCleanupUsesOneCutoff16932026-10-01 09:47:12.229 UTC [842] ERROR: relation "goose_db_version" does not exist at character 3616942026-10-01 09:47:12.229 UTC [842] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16952026/10/01 09:47:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16962026-10-01 09:47:12.236 UTC [845] ERROR: relation "goose_db_version" does not exist at character 3616972026-10-01 09:47:12.236 UTC [845] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16982026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.26ms)1699--- PASS: TestReadProxy404 (0.67s)1700=== CONT TestCacheConfigHandler1701=== RUN TestCacheConfigHandler/full_config,_no_issuer1702=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1703=== RUN TestCacheConfigHandler/no_cache_url_configured1704=== PAUSE TestCacheConfigHandler/no_cache_url_configured1705=== RUN TestCacheConfigHandler/no_signing_keys1706=== PAUSE TestCacheConfigHandler/no_signing_keys1707=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1708=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1709=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded17102026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (11.59ms)17112026/10/01 09:47:12 OK 20241026095416_initial_model.sql (16.09ms)17122026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures17132026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.37ms)17142026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)17152026/10/01 09:47:12 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MGNmOTFlZDQtZGRjYS00ZGU1LTljYzAtODQ2OTY1MGMyNWYwLjk2ZGIwZTBiLWM2ZjAtNDQzMi05MTdkLTU0YjkyYTUxZjU3OHgxNzkwODQ4MDMxNjc4ODk1MTc0 parts=1217162026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.78ms)17172026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures17182026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.31ms)17192026-10-01 09:47:12.267 UTC [848] ERROR: relation "goose_db_version" does not exist at character 3617202026-10-01 09:47:12.267 UTC [848] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17212026/10/01 09:47:12 OK 20260905000000_add_claims.sql (4.55ms)17222026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (4.66ms)17232026-10-01 09:47:12.270 UTC [849] ERROR: relation "goose_db_version" does not exist at character 3617242026-10-01 09:47:12.270 UTC [849] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1725--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.28s)1726=== CONT TestClientWithDependencies17272026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (3.27ms)17282026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.31ms)17292026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000017302026/10/01 09:47:12 OK 20260905000000_add_claims.sql (4.66ms)17312026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.58ms)17322026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.95ms)17332026/10/01 09:47:12 OK 2_object_stats_trigger.sql (3.03ms)17342026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (3.36ms)17352026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000017362026/10/01 09:47:12 OK 3_commit_push.sql (1.86ms)17372026/10/01 09:47:12 goose: up to current file version: 317382026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.17ms)17392026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.78ms)17402026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.19ms)17412026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (1.99ms)17422026/10/01 09:47:12 OK 2_object_stats_trigger.sql (2.3ms)17432026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.57ms)17442026/10/01 09:47:12 OK 3_commit_push.sql (2.15ms)17452026/10/01 09:47:12 goose: up to current file version: 317462026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.34ms)1747--- PASS: TestReadProxyNarStreaming (0.58s)1748=== CONT TestMultipartCleanup17492026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.22ms)17502026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.49ms)17512026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.97ms)17522026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.55ms)17532026/10/01 09:47:12 OK 20260905000000_add_claims.sql (2.95ms)17542026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.14ms)17552026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.18ms)17562026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.38ms)17572026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000017582026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.84ms)17592026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000017602026/10/01 09:47:12 OK 1_commit_pending_closure.sql (3.51ms)17612026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.29ms)17622026/10/01 09:47:12 OK 2_object_stats_trigger.sql (2.31ms)17632026-10-01 09:47:12.308 UTC [854] ERROR: relation "goose_db_version" does not exist at character 3617642026-10-01 09:47:12.308 UTC [854] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17652026/10/01 09:47:12 OK 2_object_stats_trigger.sql (2.05ms)17662026/10/01 09:47:12 OK 3_commit_push.sql (2.29ms)17672026/10/01 09:47:12 goose: up to current file version: 317682026/10/01 09:47:12 OK 3_commit_push.sql (2.04ms)17692026/10/01 09:47:12 goose: up to current file version: 317702026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.31ms)17712026/10/01 09:47:12 INFO Aborted multipart uploads count=0 kept=017722026-10-01 09:47:12.324 UTC [856] ERROR: relation "goose_db_version" does not exist at character 3617732026-10-01 09:47:12.324 UTC [856] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17742026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)17752026/10/01 09:47:12 WARN Force mode enabled - objects will be deleted immediately without grace period17762026/10/01 09:47:12 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=017772026/10/01 09:47:12 INFO Vacuumed table table=pending_closures17782026/10/01 09:47:12 INFO Vacuumed table table=pending_objects17792026/10/01 09:47:12 INFO Vacuumed table table=multipart_uploads17802026/10/01 09:47:12 INFO Vacuumed table table=closures17812026/10/01 09:47:12 INFO Vacuumed table table=objects17822026/10/01 09:47:12 INFO Aborted multipart uploads count=0 kept=017832026/10/01 09:47:12 OK 20251218171726_add_pins.sql (14.24ms)17842026/10/01 09:47:12 OK 20241026095416_initial_model.sql (12.17ms)17852026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.12ms)17862026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (1.52ms)1787--- PASS: TestGCMetrics (0.60s)1788=== CONT TestClientMultipleUploads17892026/10/01 09:47:12 OK 20260905000000_add_claims.sql (2.78ms)17902026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.04ms)17912026/10/01 09:47:12 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=017922026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.65ms)17932026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.75ms)17942026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (3.17ms)17952026/10/01 09:47:12 goose: successfully migrated database to version: 202609231200001796--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.60s)1797=== CONT TestServerTLSConfig1798=== RUN TestServerTLSConfig/no_client_CA17992026/10/01 09:47:12 INFO Vacuumed table table=pending_closures1800=== PAUSE TestServerTLSConfig/no_client_CA1801=== RUN TestServerTLSConfig/missing_CA_file1802=== PAUSE TestServerTLSConfig/missing_CA_file1803=== RUN TestServerTLSConfig/not_a_PEM_file1804=== PAUSE TestServerTLSConfig/not_a_PEM_file1805=== CONT TestClientIntegration18062026-10-01 09:47:12.354 UTC [859] ERROR: relation "goose_db_version" does not exist at character 3618072026-10-01 09:47:12.354 UTC [859] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18082026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.01ms)18092026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.96ms)18102026/10/01 09:47:12 INFO Vacuumed table table=pending_objects18112026/10/01 09:47:12 INFO Vacuumed table table=multipart_uploads18122026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.41ms)18132026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.7ms)18142026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.09ms)18152026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000018162026/10/01 09:47:12 OK 3_commit_push.sql (1.88ms)18172026/10/01 09:47:12 goose: up to current file version: 318182026/10/01 09:47:12 INFO Vacuumed table table=closures18192026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.15ms)18202026/10/01 09:47:12 INFO Vacuumed table table=objects18212026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.77ms)18222026/10/01 09:47:12 OK 3_commit_push.sql (1.05ms)18232026/10/01 09:47:12 goose: up to current file version: 318242026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.05ms)18252026/10/01 09:47:12 INFO Aborted multipart uploads count=0 kept=018262026/10/01 09:47:12 WARN Force mode enabled - objects will be deleted immediately without grace period18272026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)18282026/10/01 09:47:12 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=018292026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.7ms)18302026/10/01 09:47:12 INFO Vacuumed table table=pending_closures18312026-10-01 09:47:12.376 UTC [863] ERROR: relation "goose_db_version" does not exist at character 3618322026-10-01 09:47:12.376 UTC [863] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18332026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (4.68ms)18342026/10/01 09:47:12 INFO Vacuumed table table=pending_objects18352026/10/01 09:47:12 INFO Vacuumed table table=multipart_uploads18362026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.44ms)18372026/10/01 09:47:12 INFO Vacuumed table table=closures1838--- PASS: TestReadProxyNarinfo (0.61s)1839=== CONT TestService_NativeMTLS18402026/10/01 09:47:12 INFO Vacuumed table table=objects18412026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.82ms)1842--- PASS: TestPushDedupSurvivesConcurrentGC (0.79s)1843=== CONT TestClientErrorHandling1844=== RUN TestClientErrorHandling/InvalidStorePath1845=== PAUSE TestClientErrorHandling/InvalidStorePath1846=== RUN TestClientErrorHandling/InvalidAuthToken1847=== PAUSE TestClientErrorHandling/InvalidAuthToken1848=== RUN TestClientErrorHandling/ServerNotAvailable1849=== PAUSE TestClientErrorHandling/ServerNotAvailable1850=== CONT TestClientCADerivations18512026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.26ms)18522026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000018532026/10/01 09:47:12 OK 1_commit_pending_closure.sql (1.86ms)18542026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.22ms)18552026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.89ms)18562026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (1.14ms)18572026/10/01 09:47:12 OK 3_commit_push.sql (959.65µs)18582026/10/01 09:47:12 goose: up to current file version: 318592026/10/01 09:47:12 OK 20251218171726_add_pins.sql (2.36ms)18602026-10-01 09:47:12.397 UTC [867] ERROR: relation "goose_db_version" does not exist at character 3618612026-10-01 09:47:12.397 UTC [867] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18622026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.64ms)18632026/10/01 09:47:12 OK 20260905000000_add_claims.sql (4.04ms)18642026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.82ms)18652026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.41ms)18662026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000018672026/10/01 09:47:12 OK 1_commit_pending_closure.sql (3.05ms)18682026/10/01 09:47:12 OK 2_object_stats_trigger.sql (2.33ms)18692026/10/01 09:47:12 OK 20241026095416_initial_model.sql (11.17ms)18702026/10/01 09:47:12 OK 3_commit_push.sql (2.29ms)18712026/10/01 09:47:12 goose: up to current file version: 318722026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.54ms)18732026/10/01 09:47:12 OK 20251218171726_add_pins.sql (14.05ms)18742026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (5.84ms)18752026/10/01 09:47:12 INFO Starting HTTP server address=127.0.0.1:4421918762026/10/01 09:47:12 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket1349432463/001/proxy.sock18772026/10/01 09:47:12 WARN mTLS auth: subject not in bound subjects subject="CN=someone"18782026/10/01 09:47:12 INFO Shutdown signal received, draining in-flight requests timeout=10s18792026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.7ms)1880--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.62s)1881=== CONT TestCacheStatsHandler18822026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.8ms)18832026-10-01 09:47:12.446 UTC [869] ERROR: relation "goose_db_version" does not exist at character 3618842026-10-01 09:47:12.446 UTC [869] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18852026-10-01 09:47:12.448 UTC [870] ERROR: relation "goose_db_version" does not exist at character 3618862026-10-01 09:47:12.448 UTC [870] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18872026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (11.93ms)18882026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000018892026/10/01 09:47:12 OK 1_commit_pending_closure.sql (3.2ms)18902026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.79ms)18912026/10/01 09:47:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18922026/10/01 09:47:12 OK 3_commit_push.sql (2.27ms)18932026/10/01 09:47:12 goose: up to current file version: 318942026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.26ms)18952026/10/01 09:47:12 OK 20241026095416_initial_model.sql (10.49ms)18962026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)18972026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)18982026/10/01 09:47:12 OK 20251218171726_add_pins.sql (2.74ms)18992026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.09ms)19002026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)19012026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (4.18ms)19022026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.21ms)19032026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.55ms)19042026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.42ms)19052026/10/01 09:47:12 INFO lead: acquired remote=192.0.2.1:123419062026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.36ms)19072026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.69ms)19082026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000019092026-10-01 09:47:12.490 UTC [873] ERROR: relation "goose_db_version" does not exist at character 3619102026-10-01 09:47:12.490 UTC [873] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19112026-10-01 09:47:12.490 UTC [874] ERROR: relation "goose_db_version" does not exist at character 3619122026-10-01 09:47:12.490 UTC [874] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19132026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.81ms)19142026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000019152026/10/01 09:47:12 OK 1_commit_pending_closure.sql (3.49ms)19162026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.9ms)19172026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.87ms)19182026/10/01 09:47:12 OK 3_commit_push.sql (878.87µs)19192026/10/01 09:47:12 goose: up to current file version: 319202026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.35ms)19212026/10/01 09:47:12 OK 3_commit_push.sql (1.17ms)19222026/10/01 09:47:12 goose: up to current file version: 319232026/10/01 09:47:12 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MGNmOTFlZDQtZGRjYS00ZGU1LTljYzAtODQ2OTY1MGMyNWYwLmJjNmE3YjI2LWFlMjYtNGE1My1iZjcyLThlNDZlNDZmZTBiMngxNzkwODQ4MDMxODgyNTc4NDk3 parts=1219242026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures19252026/10/01 09:47:12 OK 20241026095416_initial_model.sql (8.24ms)19262026/10/01 09:47:12 OK 20241026095416_initial_model.sql (8.51ms)19272026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)19282026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)19292026/10/01 09:47:12 OK 20251218171726_add_pins.sql (2.59ms)19302026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.52ms)19312026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures19322026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.32ms)19332026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (4ms)19342026/10/01 09:47:12 OK 20260905000000_add_claims.sql (2.68ms)19352026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.05ms)19362026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.17ms)19372026/10/01 09:47:12 INFO lead: acquired remote=192.0.2.1:123419382026/10/01 09:47:12 INFO lead: released remote=192.0.2.1:123419392026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.27ms)1940--- PASS: TestLeadEndsOnShutdown (0.69s)1941=== CONT TestGCTaskStore_ConflictDifferentParams1942--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1943=== CONT TestService_AuthMiddleware_OIDC19442026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.06ms)19452026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000019462026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (1.6ms)19472026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000019482026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.22ms)19492026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.07ms)19502026/10/01 09:47:12 OK 2_object_stats_trigger.sql (756.15µs)19512026/10/01 09:47:12 OK 2_object_stats_trigger.sql (888.16µs)19522026/10/01 09:47:12 OK 3_commit_push.sql (1.12ms)19532026/10/01 09:47:12 goose: up to current file version: 319542026/10/01 09:47:12 OK 3_commit_push.sql (1.29ms)19552026/10/01 09:47:12 goose: up to current file version: 319562026-10-01 09:47:12.537 UTC [876] ERROR: relation "goose_db_version" does not exist at character 3619572026-10-01 09:47:12.537 UTC [876] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19582026/10/01 09:47:12 OK 20241026095416_initial_model.sql (6.75ms)19592026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (963.93µs)19602026/10/01 09:47:12 OK 20251218171726_add_pins.sql (1.77ms)19612026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (2.56ms)19622026/10/01 09:47:12 OK 20260905000000_add_claims.sql (1.97ms)19632026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (1.34ms)19642026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (1.12ms)19652026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000019662026/10/01 09:47:12 OK 1_commit_pending_closure.sql (1.57ms)19672026/10/01 09:47:12 OK 2_object_stats_trigger.sql (665.82µs)19682026/10/01 09:47:12 OK 3_commit_push.sql (640µs)19692026/10/01 09:47:12 goose: up to current file version: 31970--- PASS: TestPresentReportsOnlyClosureRoots (0.64s)1971=== CONT TestGracefulShutdownDrainsInflight19722026/10/01 09:47:12 INFO Starting HTTP server address=127.0.0.1:4612119732026/10/01 09:47:12 INFO Shutdown signal received, draining in-flight requests timeout=10s19742026/10/01 09:47:12 INFO lead: released remote=192.0.2.1:12341975--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1976=== CONT TestGCTaskStore_Fail1977--- PASS: TestGCTaskStore_Fail (0.00s)1978=== CONT TestService_ReadScope_PublicByDefault1979--- PASS: TestGCBugBareHashReferences (0.84s)1980=== CONT TestGCTaskStore_PhaseUpdates1981--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1982=== CONT TestService_RequireScope_OIDC19832026/10/01 09:47:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46095/oidc19842026/10/01 09:47:12 INFO lead: acquired remote=192.0.2.1:123419852026/10/01 09:47:12 INFO lead: released remote=192.0.2.1:12341986--- PASS: TestLeadElectsOneAndHandsOver (0.85s)1987=== CONT TestGCTaskStore_CompletedAllowsNewTask1988--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1989=== CONT TestGCTaskStore_GetReturnsLatest1990--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1991=== CONT TestCacheConfigHandlerMaxNarSize1992--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1993=== CONT TestGCTaskStore_GetEmpty1994--- PASS: TestGCTaskStore_GetEmpty (0.00s)1995=== CONT TestNARDeduplicationMetadataUploadBug19962026/10/01 09:47:12 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux19972026/10/01 09:47:12 WARN Refused reserved pin name=worker-x86_64-linux19982026/10/01 09:47:12 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux19992026/10/01 09:47:12 INFO Received create pin request method=POST path=/api/pins/my-app20002026/10/01 09:47:12 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux2001--- PASS: TestCreatePin_ReservedPins (0.73s)2002=== CONT TestGenerateLandingPage2003--- PASS: TestGenerateLandingPage (0.00s)2004=== CONT TestCreatePendingClosureRejectsOversizedNAR20052026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures2006--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)2007=== CONT TestService_AuthMiddleware_MTLSBoundSubjects20082026-10-01 09:47:12.736 UTC [923] ERROR: relation "goose_db_version" does not exist at character 3620092026-10-01 09:47:12.736 UTC [923] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20102026/10/01 09:47:12 OK 20241026095416_initial_model.sql (8.76ms)20112026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)20122026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.64ms)20132026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.75ms)20142026/10/01 09:47:12 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44207/oidc20152026/10/01 09:47:12 OK 20260905000000_add_claims.sql (12.52ms)20162026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.73ms)20172026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.48ms)20182026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000020192026-10-01 09:47:12.784 UTC [964] ERROR: relation "goose_db_version" does not exist at character 3620202026-10-01 09:47:12.784 UTC [964] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20212026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.31ms)20222026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.66ms)20232026/10/01 09:47:12 OK 3_commit_push.sql (715.74µs)20242026/10/01 09:47:12 goose: up to current file version: 320252026-10-01 09:47:12.792 UTC [981] ERROR: relation "goose_db_version" does not exist at character 3620262026-10-01 09:47:12.792 UTC [981] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20272026-10-01 09:47:12.796 UTC [983] ERROR: relation "goose_db_version" does not exist at character 3620282026-10-01 09:47:12.796 UTC [983] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20292026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.71ms)20302026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.71ms)20312026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.25ms)20322026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.02ms)20332026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (5.08ms)20342026/10/01 09:47:12 OK 20241026095416_initial_model.sql (12.14ms)20352026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (1.03ms)20362026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.91ms)20372026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.38ms)20382026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.94ms)20392026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.78ms)20402026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.97ms)20412026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.41ms)20422026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.06ms)20432026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000020442026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.78ms)20452026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.62ms)20462026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (4.82ms)20472026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.24ms)20482026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (1.99ms)20492026/10/01 09:47:12 OK 3_commit_push.sql (1.48ms)20502026/10/01 09:47:12 goose: up to current file version: 320512026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.19ms)20522026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000020532026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.78ms)20542026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.57ms)20552026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.55ms)20562026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures2057--- PASS: TestObjectStatsTrigger (0.63s)2058=== CONT TestService_ReadAuthMiddleware20592026/10/01 09:47:12 OK 2_object_stats_trigger.sql (2.18ms)20602026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.72ms)20612026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000020622026/10/01 09:47:12 OK 3_commit_push.sql (1.16ms)20632026/10/01 09:47:12 goose: up to current file version: 320642026/10/01 09:47:12 OK 1_commit_pending_closure.sql (2.44ms)20652026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.94ms)20662026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures20672026/10/01 09:47:12 OK 3_commit_push.sql (1.75ms)20682026/10/01 09:47:12 goose: up to current file version: 320692026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures20702026/10/01 09:47:12 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)20712026/10/01 09:47:12 INFO Uploading y91plx9ikczi913qq45a13hrdvcn5sxc-b (216B)20722026/10/01 09:47:12 INFO Uploading hby91xhd6h9g85qp0v2rvy3r4i0s1x27-shared-dep (136B)20732026/10/01 09:47:12 WARN Failed to register uploaded object key=bcyjsykryyn4i66h2zqqc5vhc0xqc70h.ls error="server returned 404: 404 page not found\n"20742026/10/01 09:47:12 WARN Failed to register uploaded object key=nar/1j3b47ac7ca908lbyg18yyq4qw34gjz76b61gvr7qdqn4mk29n86.nar.zst error="server returned 404: 404 page not found\n"20752026/10/01 09:47:12 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"20762026/10/01 09:47:12 WARN Failed to register uploaded object key=y91plx9ikczi913qq45a13hrdvcn5sxc.ls error="server returned 404: 404 page not found\n"20772026/10/01 09:47:12 WARN Failed to register uploaded object key=hby91xhd6h9g85qp0v2rvy3r4i0s1x27.ls error="server returned 404: 404 page not found\n"20782026/10/01 09:47:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign20792026/10/01 09:47:12 INFO Signed narinfos id=1 count=220802026/10/01 09:47:12 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign20812026/10/01 09:47:12 INFO Signed narinfos id=2 count=220822026/10/01 09:47:12 INFO Uploading 4 narinfos20832026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures20842026/10/01 09:47:12 WARN Failed to register uploaded object key=hby91xhd6h9g85qp0v2rvy3r4i0s1x27.narinfo error="server returned 404: 404 page not found\n"20852026/10/01 09:47:12 WARN Failed to register uploaded object key=y91plx9ikczi913qq45a13hrdvcn5sxc.narinfo error="server returned 404: 404 page not found\n"20862026/10/01 09:47:12 WARN Failed to register uploaded object key=bcyjsykryyn4i66h2zqqc5vhc0xqc70h.narinfo error="server returned 404: 404 page not found\n"20872026/10/01 09:47:12 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20882026/10/01 09:47:12 WARN Failed to register uploaded object key=hby91xhd6h9g85qp0v2rvy3r4i0s1x27.narinfo error="server returned 404: 404 page not found\n"20892026/10/01 09:47:12 INFO Received cleanup request method=DELETE path=/api/pending_closures2090=== NAME TestPinProtectsFromGC2091 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC3533578953/001/store/6hj48h9qg26ijl9ib2w6av3pnljjqm8z-pinned-file.txt2092 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC3533578953/001/store/hy32j45f5qyiir0ksrpj8y7h0f27hhl0-unpinned-file.txt20932026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures20942026/10/01 09:47:12 INFO Completed upload id=120952026/10/01 09:47:12 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete20962026-10-01 09:47:12.872 UTC [1073] ERROR: relation "goose_db_version" does not exist at character 3620972026-10-01 09:47:12.872 UTC [1073] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20982026/10/01 09:47:12 INFO Completed upload id=220992026/10/01 09:47:12 INFO Upload complete. (88ms)2100=== NAME TestClientFallsBackToClosures2101 client_pushes_test.go:112: Retrieved narinfo from S3:2102 StorePath: /build/TestClientFallsBackToClosures156744726/001/store/hby91xhd6h9g85qp0v2rvy3r4i0s1x27-shared-dep2103 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2104 Compression: zstd2105 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822106 NarSize: 1362107 References: 2108 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2109 client_pushes_test.go:112: Retrieved narinfo from S3:2110 StorePath: /build/TestClientFallsBackToClosures156744726/001/store/bcyjsykryyn4i66h2zqqc5vhc0xqc70h-a2111 URL: nar/1j3b47ac7ca908lbyg18yyq4qw34gjz76b61gvr7qdqn4mk29n86.nar.zst2112 Compression: zstd2113 NarHash: sha256:1j3b47ac7ca908lbyg18yyq4qw34gjz76b61gvr7qdqn4mk29n862114 NarSize: 2162115 References: /build/TestClientFallsBackToClosures156744726/001/store/hby91xhd6h9g85qp0v2rvy3r4i0s1x27-shared-dep2116 CA: text:sha256:00f448sgvw9xsh5ykjan2zj67kgqxl2aijn1qvg4r8lpa3w6kfrh2117 client_pushes_test.go:112: Retrieved narinfo from S3:2118 StorePath: /build/TestClientFallsBackToClosures156744726/001/store/y91plx9ikczi913qq45a13hrdvcn5sxc-b2119 URL: nar/1j3b47ac7ca908lbyg18yyq4qw34gjz76b61gvr7qdqn4mk29n86.nar.zst2120 Compression: zstd2121 NarHash: sha256:1j3b47ac7ca908lbyg18yyq4qw34gjz76b61gvr7qdqn4mk29n862122 NarSize: 2162123 References: /build/TestClientFallsBackToClosures156744726/001/store/hby91xhd6h9g85qp0v2rvy3r4i0s1x27-shared-dep2124 CA: text:sha256:00f448sgvw9xsh5ykjan2zj67kgqxl2aijn1qvg4r8lpa3w6kfrh21252026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.16ms)2126--- PASS: TestClientFallsBackToClosures (0.86s)21272026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (1.68ms)2128=== CONT TestGetExistingObjectsLocksRows21292026/10/01 09:47:12 OK 20251218171726_add_pins.sql (3.07ms)2130--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.64s)2131=== CONT TestGCTaskStore_DeduplicateSameParams2132--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)2133=== CONT TestFailedS3DeleteKeepsTombstone21342026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (3.65ms)21352026/10/01 09:47:12 OK 20260905000000_add_claims.sql (3.08ms)21362026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (2.33ms)21372026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (2.14ms)21382026/10/01 09:47:12 goose: successfully migrated database to version: 2026092312000021392026/10/01 09:47:12 OK 1_commit_pending_closure.sql (1.89ms)21402026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.26ms)21412026/10/01 09:47:12 OK 3_commit_push.sql (1.45ms)21422026/10/01 09:47:12 goose: up to current file version: 321432026/10/01 09:47:12 INFO Received uploads request method=POST path=/api/pending_closures21442026/10/01 09:47:12 INFO Received push request method=POST path=/api/pushes21452026-10-01 09:47:12.939 UTC [1150] ERROR: relation "goose_db_version" does not exist at character 3621462026-10-01 09:47:12.939 UTC [1150] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21472026/10/01 09:47:12 INFO Received push request method=POST path=/api/pushes2148--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.01s)2149=== CONT TestGCTaskStore_StartNew2150--- PASS: TestGCTaskStore_StartNew (0.00s)2151=== CONT TestRegisterCompletedObjectNeedsPendingRow21522026/10/01 09:47:12 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)21532026/10/01 09:47:12 INFO Uploading zk9y3w2mjsksf4q0wczny5i60kccfn0p-shared-dep (136B)21542026/10/01 09:47:12 INFO Uploading sh447x4q590s09ai13iq69r3vydvzvkb-b (208B)21552026/10/01 09:47:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21562026/10/01 09:47:12 INFO Uploading 6hj48h9qg26ijl9ib2w6av3pnljjqm8z-pinned-file.txt (128B)21572026/10/01 09:47:12 WARN Failed to register uploaded object key=cpdvfxifgcyxjzgynckiry569svnym46.ls error="server returned 404: 404 page not found\n"21582026/10/01 09:47:12 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"21592026/10/01 09:47:12 WARN Failed to register uploaded object key=zk9y3w2mjsksf4q0wczny5i60kccfn0p.ls error="server returned 404: 404 page not found\n"21602026/10/01 09:47:12 OK 20241026095416_initial_model.sql (9.32ms)21612026/10/01 09:47:12 WARN Failed to register uploaded object key=nar/1p9hsag7zdz4hbc0ds3ivr95698v793qqgq4n59p98p2lkdmvc8r.nar.zst error="server returned 404: 404 page not found\n"21622026/10/01 09:47:12 WARN Failed to register uploaded object key=sh447x4q590s09ai13iq69r3vydvzvkb.ls error="server returned 404: 404 page not found\n"21632026/10/01 09:47:12 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"21642026/10/01 09:47:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21652026/10/01 09:47:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21662026/10/01 09:47:12 WARN Failed to register uploaded object key=6hj48h9qg26ijl9ib2w6av3pnljjqm8z.ls error="server returned 404: 404 page not found\n"21672026/10/01 09:47:12 INFO Signed narinfos id=1 count=121682026/10/01 09:47:12 INFO Uploading 1 narinfos21692026/10/01 09:47:12 INFO Signed narinfos id=1 count=321702026/10/01 09:47:12 OK 20251210153512_drop_unused_gin_index.sql (2.46ms)21712026/10/01 09:47:12 INFO Uploading 3 narinfos21722026/10/01 09:47:12 OK 20251218171726_add_pins.sql (2.85ms)21732026/10/01 09:47:12 INFO Received complete push request method=POST path=/api/pushes/1/complete21742026/10/01 09:47:12 WARN Failed to register uploaded object key=6hj48h9qg26ijl9ib2w6av3pnljjqm8z.narinfo error="server returned 404: 404 page not found\n"21752026/10/01 09:47:12 WARN Failed to register uploaded object key=zk9y3w2mjsksf4q0wczny5i60kccfn0p.narinfo error="server returned 404: 404 page not found\n"21762026/10/01 09:47:12 WARN Failed to register uploaded object key=sh447x4q590s09ai13iq69r3vydvzvkb.narinfo error="server returned 404: 404 page not found\n"21772026/10/01 09:47:12 INFO Received complete push request method=POST path=/api/pushes/1/complete21782026/10/01 09:47:12 WARN Failed to register uploaded object key=cpdvfxifgcyxjzgynckiry569svnym46.narinfo error="server returned 404: 404 page not found\n"21792026/10/01 09:47:12 OK 20260628120000_add_object_size_and_stats.sql (6.06ms)21802026/10/01 09:47:12 OK 20260905000000_add_claims.sql (4.76ms)21812026/10/01 09:47:12 INFO Upload complete. (79ms)21822026/10/01 09:47:12 OK 20260920000000_drop_claims.sql (4.39ms)21832026/10/01 09:47:12 INFO Upload complete. (100ms)2184=== NAME TestClientPushesUseOnePush2185 client_pushes_test.go:97: Retrieved narinfo from S3:2186 StorePath: /build/TestClientPushesUseOnePush764937542/001/store/zk9y3w2mjsksf4q0wczny5i60kccfn0p-shared-dep2187 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2188 Compression: zstd2189 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822190 NarSize: 1362191 References: 2192 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n21932026/10/01 09:47:12 OK 20260923120000_add_pushes.sql (3.26ms)21942026/10/01 09:47:12 goose: successfully migrated database to version: 202609231200002195 client_pushes_test.go:97: Retrieved narinfo from S3:2196 StorePath: /build/TestClientPushesUseOnePush764937542/001/store/cpdvfxifgcyxjzgynckiry569svnym46-a2197 URL: nar/1p9hsag7zdz4hbc0ds3ivr95698v793qqgq4n59p98p2lkdmvc8r.nar.zst2198 Compression: zstd2199 NarHash: sha256:1p9hsag7zdz4hbc0ds3ivr95698v793qqgq4n59p98p2lkdmvc8r2200 NarSize: 2082201 References: /build/TestClientPushesUseOnePush764937542/001/store/zk9y3w2mjsksf4q0wczny5i60kccfn0p-shared-dep2202 CA: text:sha256:1d3gvzqx45limx5jy23aw7d7fg00cr2s7s8psfxm6hp334cmk8dd2203=== NAME TestClientWithDependencies2204 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies2805379537/001/store/f1acxq2rc6q2hps6j1w9npapp9adg9ix-test-script22052026/10/01 09:47:12 OK 1_commit_pending_closure.sql (3.33ms)22062026/10/01 09:47:12 OK 2_object_stats_trigger.sql (1.48ms)2207=== NAME TestClientPushesUseOnePush2208 client_pushes_test.go:97: Retrieved narinfo from S3:2209 StorePath: /build/TestClientPushesUseOnePush764937542/001/store/sh447x4q590s09ai13iq69r3vydvzvkb-b2210 URL: nar/1p9hsag7zdz4hbc0ds3ivr95698v793qqgq4n59p98p2lkdmvc8r.nar.zst2211 Compression: zstd2212 NarHash: sha256:1p9hsag7zdz4hbc0ds3ivr95698v793qqgq4n59p98p2lkdmvc8r2213 NarSize: 2082214 References: /build/TestClientPushesUseOnePush764937542/001/store/zk9y3w2mjsksf4q0wczny5i60kccfn0p-shared-dep2215 CA: text:sha256:1d3gvzqx45limx5jy23aw7d7fg00cr2s7s8psfxm6hp334cmk8dd22162026/10/01 09:47:12 OK 3_commit_push.sql (930.44µs)22172026/10/01 09:47:12 goose: up to current file version: 322182026-10-01 09:47:12.995 UTC [1195] ERROR: relation "goose_db_version" does not exist at character 3622192026-10-01 09:47:12.995 UTC [1195] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2220--- PASS: TestClientPushesUseOnePush (0.86s)2221=== CONT TestGCEndsOnShutdown22222026-10-01 09:47:13.004 UTC [1209] ERROR: relation "goose_db_version" does not exist at character 3622232026-10-01 09:47:13.004 UTC [1209] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2224=== NAME TestClientIntegration2225 client_integration_test.go:286: Created store path: /build/TestClientIntegration2074687970/002/store/r6l0jvx2hwdmz6ininr6yiwb3p57w3r1-test-file.txt22262026/10/01 09:47:13 OK 20241026095416_initial_model.sql (14.78ms)2227=== NAME TestClientWithDependencies2228 client_integration_test.go:615: Found 1 dependencies (including self)22292026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (2.5ms)22302026/10/01 09:47:13 OK 20251218171726_add_pins.sql (4.8ms)22312026/10/01 09:47:13 OK 20241026095416_initial_model.sql (18.6ms)2232=== NAME TestClientMultipleUploads2233 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads16627474/001/store/wmxkhr189harblw266lgljdrli7c5da2-test-file-0.txt22342026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (2.7ms)22352026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (5.48ms)22362026/10/01 09:47:13 OK 20251218171726_add_pins.sql (6.22ms)22372026/10/01 09:47:13 OK 20260905000000_add_claims.sql (5.25ms)22382026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (2.78ms)22392026/10/01 09:47:13 WARN mTLS auth: subject not in bound subjects subject="CN=reader"22402026/10/01 09:47:13 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2241--- PASS: TestService_NativeMTLS (0.66s)2242=== CONT TestSweepSkipsRowsLockedByPush22432026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (2.48ms)22442026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000022452026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (7.33ms)22462026/10/01 09:47:13 OK 1_commit_pending_closure.sql (2.42ms)22472026/10/01 09:47:13 OK 2_object_stats_trigger.sql (1.57ms)22482026/10/01 09:47:13 OK 3_commit_push.sql (1.49ms)22492026/10/01 09:47:13 goose: up to current file version: 322502026/10/01 09:47:13 OK 20260905000000_add_claims.sql (5.35ms)22512026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes22522026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (3.73ms)2253--- PASS: TestPresentNotReportedWhileGCDeletesClosure (1.12s)2254=== CONT TestService_healthCheckHandler22552026/10/01 09:47:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22562026-10-01 09:47:13.056 UTC [1337] ERROR: relation "goose_db_version" does not exist at character 3622572026-10-01 09:47:13.056 UTC [1337] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22582026/10/01 09:47:13 INFO Uploading hy32j45f5qyiir0ksrpj8y7h0f27hhl0-unpinned-file.txt (128B)22592026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (3.43ms)22602026/10/01 09:47:13 goose: successfully migrated database to version: 202609231200002261=== NAME TestClientMultipleUploads2262 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads16627474/001/store/qi0z80pi8lzrvdc7wp9nk9bmd2hvlvgx-test-file-1.txt22632026/10/01 09:47:13 OK 1_commit_pending_closure.sql (2.69ms)22642026/10/01 09:47:13 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"22652026/10/01 09:47:13 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign22662026/10/01 09:47:13 INFO Signed narinfos id=2 count=122672026/10/01 09:47:13 WARN Failed to register uploaded object key=hy32j45f5qyiir0ksrpj8y7h0f27hhl0.ls error="server returned 404: 404 page not found\n"22682026/10/01 09:47:13 INFO Uploading 1 narinfos22692026/10/01 09:47:13 OK 2_object_stats_trigger.sql (2.52ms)22702026/10/01 09:47:13 INFO Received cleanup request method=DELETE path=/api/pending_closures22712026/10/01 09:47:13 OK 3_commit_push.sql (1.99ms)22722026/10/01 09:47:13 goose: up to current file version: 322732026/10/01 09:47:13 INFO Received complete push request method=POST path=/api/pushes/2/complete22742026/10/01 09:47:13 WARN Failed to register uploaded object key=hy32j45f5qyiir0ksrpj8y7h0f27hhl0.narinfo error="server returned 404: 404 page not found\n"22752026/10/01 09:47:13 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket57/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""22762026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=122772026/10/01 09:47:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22782026/10/01 09:47:13 INFO Upload complete. (51ms)22792026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes22802026/10/01 09:47:13 OK 20241026095416_initial_model.sql (9.03ms)22812026/10/01 09:47:13 INFO Received cleanup request method=DELETE path=/api/pending_closures22822026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.63ms)22832026/10/01 09:47:13 INFO Aborted multipart uploads count=1 kept=022842026/10/01 09:47:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22852026/10/01 09:47:13 INFO Uploading r6l0jvx2hwdmz6ininr6yiwb3p57w3r1-test-file.txt (152B)22862026/10/01 09:47:13 OK 20251218171726_add_pins.sql (2.74ms)2287=== NAME TestOrphanedObjectsGC2288 orphaned_objects_gc_test.go:290: GC Test Summary:2289 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2290 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2291 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2292 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2293 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2294--- PASS: TestOrphanedObjectsGC (0.93s)2295=== CONT TestCommitRacingPendingCleanupKeepsObjects22962026/10/01 09:47:13 WARN Failed to register uploaded object key=r6l0jvx2hwdmz6ininr6yiwb3p57w3r1.ls error="server returned 404: 404 page not found\n"22972026/10/01 09:47:13 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"22982026/10/01 09:47:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22992026/10/01 09:47:13 INFO Signed narinfos id=1 count=123002026/10/01 09:47:13 INFO Uploading 1 narinfos23012026/10/01 09:47:13 INFO Received complete push request method=POST path=/api/pushes/1/complete23022026/10/01 09:47:13 WARN Failed to register uploaded object key=r6l0jvx2hwdmz6ininr6yiwb3p57w3r1.narinfo error="server returned 404: 404 page not found\n"23032026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (19.3ms)23042026/10/01 09:47:13 INFO Upload complete. (63ms)2305--- PASS: TestMultipartCleanup (0.81s)2306=== CONT TestService_readinessHandler2307=== NAME TestClientMultipleUploads2308 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads16627474/001/store/93rhjhgzgb9njqwim7wpp9ammj18c1ah-test-file-2.txt23092026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes23102026/10/01 09:47:13 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MGNmOTFlZDQtZGRjYS00ZGU1LTljYzAtODQ2OTY1MGMyNWYwLjIzMjkxYTk1LTc2YTUtNGE1Yy1hNmQxLWQzYjI4NTcxZDdjNXgxNzkwODQ4MDMyNTEzMjcyOTQ3 error="Get \"http://127.0.0.1:1/bucket23/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"23112026/10/01 09:47:13 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MGNmOTFlZDQtZGRjYS00ZGU1LTljYzAtODQ2OTY1MGMyNWYwLmUyM2NkMGRkLTJkMDktNDUzOS1hZWU4LWE5Y2U4NDkwMDcyYngxNzkwODQ4MDMyNTA0NTg5NDY3 parts=1223122026/10/01 09:47:13 OK 20260905000000_add_claims.sql (2.88ms)2313--- PASS: TestService_ReadScope_PublicByDefault (0.45s)2314=== CONT TestPushWaitsForSweepHoldingRow23152026/10/01 09:47:13 INFO Received cleanup request method=DELETE path=/api/pending_closures23162026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (2.44ms)23172026/10/01 09:47:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23182026/10/01 09:47:13 INFO Uploading f1acxq2rc6q2hps6j1w9npapp9adg9ix-test-script (136B)23192026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (1.79ms)23202026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000023212026/10/01 09:47:13 INFO Starting cleanup of old closures method=DELETE path=/api/closures23222026/10/01 09:47:13 INFO Garbage collection started23232026/10/01 09:47:13 OK 1_commit_pending_closure.sql (2.27ms)2324--- PASS: TestCacheStatsHandler (0.66s)2325=== CONT TestService_AuthMiddleware_MTLSProxyHeader23262026/10/01 09:47:13 OK 2_object_stats_trigger.sql (1.23ms)23272026/10/01 09:47:13 INFO Aborted multipart uploads count=1 kept=023282026/10/01 09:47:13 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"23292026/10/01 09:47:13 WARN Failed to register uploaded object key=f1acxq2rc6q2hps6j1w9npapp9adg9ix.ls error="server returned 404: 404 page not found\n"23302026/10/01 09:47:13 WARN Failed to register uploaded object key=log/cbvials90yy4lv04q5d62mv17hlqqj1w-test-script.drv error="server returned 404: 404 page not found\n"23312026/10/01 09:47:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23322026/10/01 09:47:13 OK 3_commit_push.sql (2.06ms)23332026/10/01 09:47:13 goose: up to current file version: 323342026/10/01 09:47:13 INFO Signed narinfos id=1 count=123352026/10/01 09:47:13 INFO Uploading 1 narinfos23362026/10/01 09:47:13 INFO Received complete push request method=POST path=/api/pushes/1/complete23372026/10/01 09:47:13 WARN Failed to register uploaded object key=f1acxq2rc6q2hps6j1w9npapp9adg9ix.narinfo error="server returned 404: 404 page not found\n"2338--- PASS: TestRedundantMultipartUpload (2.13s)2339=== CONT TestSweepRechecksPendingAfterLocking23402026-10-01 09:47:13.120 UTC [1461] ERROR: relation "goose_db_version" does not exist at character 3623412026-10-01 09:47:13.120 UTC [1461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2342=== NAME TestClientCADerivations2343 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations390122353/001/store/d3yhsg57cvyf668p5y3w6m4h4yihxj6k-ca-test23442026/10/01 09:47:13 INFO Upload complete. (65ms)2345=== NAME TestClientWithDependencies2346 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2805379537/001/store) requires matching store prefix23472026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=02348--- PASS: TestClientWithDependencies (0.86s)2349=== CONT TestForceGCDuringPushOffersSweptObject2350=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows2351=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows2352=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check2353=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check2354=== CONT TestGCSweepDeliversEachKeyOnce23552026/10/01 09:47:13 INFO All 1 paths already cached2356=== NAME TestClientIntegration2357 client_integration_test.go:312: Retrieved narinfo from S3:2358 StorePath: /build/TestClientIntegration2074687970/002/store/r6l0jvx2hwdmz6ininr6yiwb3p57w3r1-test-file.txt2359 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2360 Compression: zstd2361 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12362 NarSize: 1522363 References: 2364 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12365=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2366=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2367=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2368=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2369=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2370=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2371=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured23722026/10/01 09:47:13 WARN Force mode enabled - objects will be deleted immediately without grace period2373=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2374=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection2375=== NAME TestClientIntegration2376 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2377 client_integration_test.go:313: Decompressed .ls content (64 bytes):2378 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2379 client_integration_test.go:316: Testing garbage collection...23802026/10/01 09:47:13 OK 20241026095416_initial_model.sql (10.22ms)23812026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (2.72ms)23822026/10/01 09:47:13 OK 20251218171726_add_pins.sql (2.84ms)23832026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (4.09ms)23842026/10/01 09:47:13 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=023852026/10/01 09:47:13 OK 20260905000000_add_claims.sql (4.17ms)23862026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (2.76ms)23872026/10/01 09:47:13 INFO Vacuumed table table=pending_closures2388=== NAME TestClientCADerivations23892026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (3.47ms)2390 client_ca_test.go:139: Found 1 dependencies (including self)23912026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000023922026-10-01 09:47:13.160 UTC [1523] ERROR: relation "goose_db_version" does not exist at character 3623932026-10-01 09:47:13.160 UTC [1523] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23942026/10/01 09:47:13 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"23952026/10/01 09:47:13 WARN mTLS auth: bound subjects configured but subject DN unavailable23962026/10/01 09:47:13 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2397--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.46s)2398=== CONT TestProxyWriteTimeout/narinfo2399=== CONT TestProxyWriteTimeout/unknown_size2400=== CONT TestProxyWriteTimeout/10_GiB_nar2401=== CONT TestProxyWriteTimeout/1_GiB_nar2402--- PASS: TestProxyWriteTimeout (0.10s)2403 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2404 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2405 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2406 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2407=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info24082026/10/01 09:47:13 INFO Received uploads request method=POST path=/2409=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key24102026/10/01 09:47:13 INFO Received request for more parts method=POST path=/2411=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key24122026/10/01 09:47:13 INFO Received complete multipart upload request method=POST path=/2413=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal24142026/10/01 09:47:13 INFO Received uploads request method=POST path=/2415--- PASS: TestUploadHandlersRejectInvalidKeys (0.11s)2416 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2417 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2418 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2419 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2420=== CONT TestIsValidUploadKey/narinfo2421=== CONT TestIsValidUploadKey/unknown_type2422=== CONT TestIsValidUploadKey/empty_key2423=== CONT TestIsValidUploadKey/absolute2424=== CONT TestIsValidUploadKey/traversal_nar2425=== CONT TestIsValidUploadKey/traversal2426=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2427=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2428=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2429=== CONT TestIsValidUploadKey/index.html2430=== CONT TestIsValidUploadKey/nix-cache-info2431=== CONT TestIsValidUploadKey/realisation_plus_in_output2432=== CONT TestIsValidUploadKey/realisation2433=== CONT TestIsValidUploadKey/build_log_equals2434=== CONT TestIsValidUploadKey/build_log_question_mark2435=== CONT TestIsValidUploadKey/nar_plain2436=== CONT TestIsValidUploadKey/nar_xz2437=== CONT TestIsValidUploadKey/nar_zst2438=== CONT TestIsValidUploadKey/build_log_home-manager_file2439=== CONT TestIsValidUploadKey/listing2440=== CONT TestIsValidUploadKey/build_log2441=== CONT TestIsValidUploadKey/build_log_plus_in_name2442--- PASS: TestIsValidUploadKey (0.11s)2443 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2444 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2445 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2446 --- PASS: TestIsValidUploadKey/absolute (0.00s)2447 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2448 --- PASS: TestIsValidUploadKey/traversal (0.00s)2449 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2450 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2451 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2452 --- PASS: TestIsValidUploadKey/index.html (0.00s)2453 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2454 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2455 --- PASS: TestIsValidUploadKey/realisation (0.00s)2456 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2457 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2458 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2459 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2460 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2461 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2462 --- PASS: TestIsValidUploadKey/listing (0.00s)2463 --- PASS: TestIsValidUploadKey/build_log (0.00s)2464 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2465=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure24662026/10/01 09:47:13 INFO Received uploads request method=POST path=/24672026/10/01 09:47:13 INFO Starting cleanup of old closures method=DELETE path=/api/closures24682026/10/01 09:47:13 INFO Garbage collection started24692026/10/01 09:47:13 OK 1_commit_pending_closure.sql (14.11ms)24702026/10/01 09:47:13 INFO Vacuumed table table=pending_objects24712026/10/01 09:47:13 OK 2_object_stats_trigger.sql (2.56ms)24722026/10/01 09:47:13 INFO Vacuumed table table=multipart_uploads24732026/10/01 09:47:13 OK 3_commit_push.sql (1.93ms)24742026/10/01 09:47:13 goose: up to current file version: 324752026/10/01 09:47:13 INFO Vacuumed table table=closures24762026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=024772026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes24782026/10/01 09:47:13 INFO Vacuumed table table=objects24792026/10/01 09:47:13 WARN Force mode enabled - objects will be deleted immediately without grace period24802026-10-01 09:47:13.182 UTC [1562] ERROR: relation "goose_db_version" does not exist at character 3624812026-10-01 09:47:13.182 UTC [1562] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24822026/10/01 09:47:13 OK 20241026095416_initial_model.sql (11.08ms)24832026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (2.43ms)24842026/10/01 09:47:13 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)24852026/10/01 09:47:13 INFO Uploading 93rhjhgzgb9njqwim7wpp9ammj18c1ah-test-file-2.txt (160B)24862026/10/01 09:47:13 INFO Uploading wmxkhr189harblw266lgljdrli7c5da2-test-file-0.txt (160B)24872026/10/01 09:47:13 INFO Uploading qi0z80pi8lzrvdc7wp9nk9bmd2hvlvgx-test-file-1.txt (160B)24882026/10/01 09:47:13 OK 20251218171726_add_pins.sql (6.8ms)24892026/10/01 09:47:13 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"24902026/10/01 09:47:13 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"24912026/10/01 09:47:13 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"24922026/10/01 09:47:13 WARN Failed to register uploaded object key=93rhjhgzgb9njqwim7wpp9ammj18c1ah.ls error="server returned 404: 404 page not found\n"24932026/10/01 09:47:13 WARN Failed to register uploaded object key=wmxkhr189harblw266lgljdrli7c5da2.ls error="server returned 404: 404 page not found\n"24942026/10/01 09:47:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24952026/10/01 09:47:13 WARN Failed to register uploaded object key=qi0z80pi8lzrvdc7wp9nk9bmd2hvlvgx.ls error="server returned 404: 404 page not found\n"24962026/10/01 09:47:13 INFO Signed narinfos id=1 count=324972026/10/01 09:47:13 INFO Uploading 3 narinfos24982026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (6.47ms)24992026/10/01 09:47:13 OK 20241026095416_initial_model.sql (11.98ms)25002026/10/01 09:47:13 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=025012026/10/01 09:47:13 WARN Failed to register uploaded object key=wmxkhr189harblw266lgljdrli7c5da2.narinfo error="server returned 404: 404 page not found\n"25022026/10/01 09:47:13 WARN Failed to register uploaded object key=93rhjhgzgb9njqwim7wpp9ammj18c1ah.narinfo error="server returned 404: 404 page not found\n"25032026/10/01 09:47:13 INFO Received complete push request method=POST path=/api/pushes/1/complete25042026/10/01 09:47:13 WARN Failed to register uploaded object key=qi0z80pi8lzrvdc7wp9nk9bmd2hvlvgx.narinfo error="server returned 404: 404 page not found\n"25052026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (2.05ms)25062026/10/01 09:47:13 OK 20260905000000_add_claims.sql (4.72ms)25072026/10/01 09:47:13 INFO Vacuumed table table=pending_closures25082026/10/01 09:47:13 OK 20251218171726_add_pins.sql (4.09ms)25092026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (3.58ms)25102026/10/01 09:47:13 INFO Vacuumed table table=pending_objects25112026/10/01 09:47:13 INFO Vacuumed table table=multipart_uploads25122026-10-01 09:47:13.219 UTC [1582] ERROR: relation "goose_db_version" does not exist at character 3625132026-10-01 09:47:13.219 UTC [1582] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25142026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (14.94ms)25152026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000025162026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (16.87ms)25172026/10/01 09:47:13 INFO Upload complete. (95ms)2518=== NAME TestClientMultipleUploads2519 client_integration_test.go:369: Uploaded 3 paths in 131.122126ms25202026/10/01 09:47:13 OK 1_commit_pending_closure.sql (4.42ms)25212026/10/01 09:47:13 OK 20260905000000_add_claims.sql (5.51ms)25222026/10/01 09:47:13 INFO Vacuumed table table=closures25232026/10/01 09:47:13 OK 2_object_stats_trigger.sql (2ms)25242026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (2.44ms)25252026/10/01 09:47:13 OK 3_commit_push.sql (1.75ms)25262026/10/01 09:47:13 goose: up to current file version: 325272026/10/01 09:47:13 INFO Vacuumed table table=objects2528=== RUN TestService_RequireScope_OIDC/builder_may_write25292026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (2.41ms)2530=== PAUSE TestService_RequireScope_OIDC/builder_may_write25312026/10/01 09:47:13 goose: successfully migrated database to version: 202609231200002532=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2533=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2534=== RUN TestService_RequireScope_OIDC/ops_may_admin2535=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2536=== RUN TestService_RequireScope_OIDC/ops_may_not_write2537=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2538=== RUN TestService_RequireScope_OIDC/reader_may_not_write2539=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2540=== NAME TestNARDeduplicationMetadataUploadBug2541 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1442600454/001/store/g0mqw2sykxm2y361x089j4gbzbgnbj2v-file1.txt2542=== RUN TestService_RequireScope_OIDC/static_token_may_admin2543=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2544=== RUN TestService_RequireScope_OIDC/static_token_may_write2545=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2546=== RUN TestService_RequireScope_OIDC/reader_may_read2547=== PAUSE TestService_RequireScope_OIDC/reader_may_read2548=== RUN TestService_RequireScope_OIDC/writer_implies_read2549=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2550=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2551=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2552=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts25532026/10/01 09:47:13 INFO Received request for more parts method=POST path=/25542026-10-01 09:47:13.238 UTC [1617] ERROR: relation "goose_db_version" does not exist at character 3625552026-10-01 09:47:13.238 UTC [1617] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25562026/10/01 09:47:13 OK 1_commit_pending_closure.sql (2.76ms)25572026/10/01 09:47:13 OK 20241026095416_initial_model.sql (10.04ms)25582026-10-01 09:47:13.240 UTC [1618] ERROR: relation "goose_db_version" does not exist at character 3625592026-10-01 09:47:13.240 UTC [1618] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25602026/10/01 09:47:13 OK 2_object_stats_trigger.sql (1.66ms)2561--- PASS: TestClientMultipleUploads (0.90s)2562=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart25632026/10/01 09:47:13 INFO Received complete multipart upload request method=POST path=/25642026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (2.65ms)25652026/10/01 09:47:13 OK 3_commit_push.sql (1.35ms)25662026/10/01 09:47:13 goose: up to current file version: 325672026/10/01 09:47:13 OK 20251218171726_add_pins.sql (2.69ms)2568--- PASS: TestService_ReadAuthMiddleware (0.42s)25692026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (3.33ms)2570=== CONT TestIsValidCachePath/narinfo2571=== CONT TestIsValidCachePath/index.html2572=== CONT TestIsValidCachePath/short_hash2573=== CONT TestIsValidCachePath/wrong_extension2574=== CONT TestIsValidCachePath/leading_slash2575=== CONT TestIsValidCachePath/empty2576=== CONT TestIsValidCachePath/random_path2577=== CONT TestIsValidCachePath/invalid_char_u2578=== CONT TestIsValidCachePath/invalid_char_e2579=== CONT TestIsValidCachePath/traversal_in_middle2580=== CONT TestIsValidCachePath/nar_uncompressed2581=== CONT TestIsValidCachePath/nix-cache-info2582=== CONT TestIsValidCachePath/realisation2583=== CONT TestIsValidCachePath/traversal_parent2584=== CONT TestIsValidCachePath/log2585=== CONT TestIsValidCachePath/nar_xz2586=== CONT TestIsValidCachePath/ls2587=== CONT TestIsValidCachePath/nar_bz22588=== CONT TestIsValidCachePath/nar_zst2589=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2590--- PASS: TestIsValidCachePath (0.00s)2591 --- PASS: TestIsValidCachePath/narinfo (0.00s)2592 --- PASS: TestIsValidCachePath/index.html (0.00s)2593 --- PASS: TestIsValidCachePath/short_hash (0.00s)2594 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2595 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2596 --- PASS: TestIsValidCachePath/empty (0.00s)2597 --- PASS: TestIsValidCachePath/random_path (0.00s)2598 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2599 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2600 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2601 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2602 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2603 --- PASS: TestIsValidCachePath/realisation (0.00s)2604 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2605 --- PASS: TestIsValidCachePath/log (0.00s)2606 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2607 --- PASS: TestIsValidCachePath/ls (0.00s)2608 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2609 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2610 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2611=== CONT TestParseSingleRange/none2612=== CONT TestParseSingleRange/open-ended2613=== CONT TestParseSingleRange/start_far_past_EOF2614=== CONT TestParseSingleRange/start_past_EOF2615=== CONT TestParseSingleRange/single_byte2616=== CONT TestParseSingleRange/suffix_exceeds_size2617=== CONT TestParseSingleRange/suffix2618=== CONT TestParseSingleRange/end_clamped_to_size2619=== CONT TestParseSingleRange/malformed_both_empty2620=== CONT TestParseSingleRange/closed2621=== CONT TestParseSingleRange/malformed_end_before_start2622=== CONT TestParseSingleRange/multi-range_ignored2623=== CONT TestParseSingleRange/malformed_no_dash2624=== CONT TestParseSingleRange/unknown_unit2625--- PASS: TestParseSingleRange (0.00s)2626 --- PASS: TestParseSingleRange/none (0.00s)2627 --- PASS: TestParseSingleRange/open-ended (0.00s)2628 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2629 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2630 --- PASS: TestParseSingleRange/single_byte (0.00s)2631 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2632 --- PASS: TestParseSingleRange/suffix (0.00s)2633 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2634 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2635 --- PASS: TestParseSingleRange/closed (0.00s)2636 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2637 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2638 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2639 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2640=== CONT TestPush_RejectsBadRequests/bad_root26412026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes2642=== CONT TestPush_RejectsBadRequests/no_roots26432026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes2644=== CONT TestPush_RejectsBadRequests/root_not_in_objects26452026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes2646=== CONT TestPush_RejectsBadRequests/no_objects26472026/10/01 09:47:13 OK 20260905000000_add_claims.sql (2.78ms)26482026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes2649=== CONT TestResolveDBConnectionString/flag_wins2650--- PASS: TestPush_RejectsBadRequests (0.94s)2651 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2652 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2653 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2654 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2655=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2656=== CONT TestResolveDBConnectionString/nothing_configured2657=== CONT TestResolveDBConnectionString/missing_file_is_an_error2658=== CONT TestResolveDBConnectionString/file_when_flag_empty26592026/10/01 09:47:13 OK 20241026095416_initial_model.sql (8.51ms)2660=== CONT TestCacheConfigHandler/full_config,_no_issuer26612026-10-01 09:47:13.252 UTC [1621] ERROR: relation "goose_db_version" does not exist at character 3626622026-10-01 09:47:13.252 UTC [1621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC26632026-10-01 09:47:13.252 UTC [1620] ERROR: relation "goose_db_version" does not exist at character 3626642026-10-01 09:47:13.252 UTC [1620] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2665=== CONT TestCacheConfigHandler/no_signing_keys2666=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2667=== CONT TestCacheConfigHandler/no_cache_url_configured2668--- PASS: TestCacheConfigHandler (0.00s)2669 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2670 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2671 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2672 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2673=== CONT TestServerTLSConfig/no_client_CA2674=== CONT TestServerTLSConfig/not_a_PEM_file2675--- PASS: TestResolveDBConnectionString (0.00s)2676 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2677 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2678 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2679 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2680 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)26812026/10/01 09:47:13 OK 20241026095416_initial_model.sql (7.67ms)26822026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (1.81ms)26832026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)2684=== CONT TestServerTLSConfig/missing_CA_file2685--- PASS: TestServerTLSConfig (0.00s)2686 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2687 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2688 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2689=== CONT TestClientErrorHandling/InvalidStorePath26902026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1ms)26912026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (2.09ms)26922026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000026932026/10/01 09:47:13 OK 20251218171726_add_pins.sql (2.87ms)26942026/10/01 09:47:13 OK 20251218171726_add_pins.sql (2.29ms)26952026/10/01 09:47:13 OK 1_commit_pending_closure.sql (1.62ms)26962026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes26972026/10/01 09:47:13 OK 2_object_stats_trigger.sql (1.41ms)26982026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (3.55ms)26992026-10-01 09:47:13.261 UTC [1639] ERROR: relation "goose_db_version" does not exist at character 3627002026-10-01 09:47:13.261 UTC [1639] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27012026/10/01 09:47:13 OK 3_commit_push.sql (2.29ms)27022026/10/01 09:47:13 goose: up to current file version: 327032026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (5.05ms)27042026-10-01 09:47:13.262 UTC [1641] ERROR: relation "goose_db_version" does not exist at character 3627052026-10-01 09:47:13.262 UTC [1641] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC27062026/10/01 09:47:13 OK 20260905000000_add_claims.sql (2.51ms)27072026/10/01 09:47:13 OK 20260905000000_add_claims.sql (4.21ms)27082026/10/01 09:47:13 OK 20241026095416_initial_model.sql (9.08ms)27092026/10/01 09:47:13 OK 20241026095416_initial_model.sql (9.11ms)27102026/10/01 09:47:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27112026/10/01 09:47:13 INFO Uploading d3yhsg57cvyf668p5y3w6m4h4yihxj6k-ca-test (144B)27122026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.01ms)27132026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.15ms)27142026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (7.17ms)27152026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (4.22ms)27162026/10/01 09:47:13 OK 20251218171726_add_pins.sql (5.53ms)27172026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (2.96ms)27182026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000027192026/10/01 09:47:13 OK 20251218171726_add_pins.sql (5.89ms)27202026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (3.43ms)27212026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000027222026/10/01 09:47:13 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"27232026/10/01 09:47:13 WARN Failed to register uploaded object key=d3yhsg57cvyf668p5y3w6m4h4yihxj6k.ls error="server returned 404: 404 page not found\n"27242026/10/01 09:47:13 WARN Failed to register uploaded object key=log/wqxdznsrphlni7rwgq3zfcxhx4d5ddrn-ca-test.drv error="server returned 404: 404 page not found\n"2725=== CONT TestClientErrorHandling/ServerNotAvailable27262026/10/01 09:47:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27272026/10/01 09:47:13 OK 1_commit_pending_closure.sql (2.47ms)27282026/10/01 09:47:13 INFO Signed narinfos id=1 count=127292026/10/01 09:47:13 INFO Uploading 1 narinfos27302026/10/01 09:47:13 OK 1_commit_pending_closure.sql (2.87ms)27312026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (3.64ms)27322026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (4.28ms)27332026/10/01 09:47:13 OK 2_object_stats_trigger.sql (2.96ms)27342026/10/01 09:47:13 OK 20241026095416_initial_model.sql (12.64ms)27352026/10/01 09:47:13 OK 2_object_stats_trigger.sql (3.04ms)27362026/10/01 09:47:13 OK 3_commit_push.sql (2.07ms)27372026/10/01 09:47:13 goose: up to current file version: 327382026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)27392026/10/01 09:47:13 OK 20241026095416_initial_model.sql (8.96ms)27402026/10/01 09:47:13 INFO Received complete push request method=POST path=/api/pushes/1/complete27412026/10/01 09:47:13 OK 20260905000000_add_claims.sql (4.17ms)27422026/10/01 09:47:13 OK 20260905000000_add_claims.sql (3.49ms)27432026/10/01 09:47:13 OK 3_commit_push.sql (1.12ms)27442026/10/01 09:47:13 goose: up to current file version: 327452026/10/01 09:47:13 WARN Failed to register uploaded object key=d3yhsg57cvyf668p5y3w6m4h4yihxj6k.narinfo error="server returned 404: 404 page not found\n"27462026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.03ms)27472026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (1.57ms)27482026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (1.67ms)27492026/10/01 09:47:13 OK 20251218171726_add_pins.sql (2.39ms)27502026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (2.29ms)27512026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000027522026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (2.23ms)27532026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000027542026/10/01 09:47:13 OK 20251218171726_add_pins.sql (3.14ms)27552026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (3.6ms)27562026/10/01 09:47:13 OK 1_commit_pending_closure.sql (2.66ms)27572026/10/01 09:47:13 OK 1_commit_pending_closure.sql (2.49ms)27582026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (3.17ms)27592026/10/01 09:47:13 OK 2_object_stats_trigger.sql (1.44ms)27602026/10/01 09:47:13 OK 2_object_stats_trigger.sql (1.37ms)27612026/10/01 09:47:13 OK 20260905000000_add_claims.sql (3.28ms)27622026/10/01 09:47:13 OK 3_commit_push.sql (1.26ms)27632026/10/01 09:47:13 goose: up to current file version: 327642026/10/01 09:47:13 OK 3_commit_push.sql (1.14ms)27652026/10/01 09:47:13 goose: up to current file version: 327662026/10/01 09:47:13 OK 20260905000000_add_claims.sql (2.69ms)27672026/10/01 09:47:13 INFO Upload complete. (104ms)27682026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (2.03ms)27692026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (1.67ms)27702026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (2ms)27712026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000027722026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (1.57ms)2773=== NAME TestClientCADerivations27742026/10/01 09:47:13 goose: successfully migrated database to version: 202609231200002775 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations390122353/001/store/d3yhsg57cvyf668p5y3w6m4h4yihxj6k-ca-test2776 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2777 Compression: zstd2778 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2779 NarSize: 1442780 References: 2781 Deriver: /build/TestClientCADerivations390122353/001/store/wqxdznsrphlni7rwgq3zfcxhx4d5ddrn-ca-test.drv2782 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2783 client_ca_test.go:185: Checking for realisation files in S3...27842026/10/01 09:47:13 OK 1_commit_pending_closure.sql (1.46ms)2785 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2786 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache27872026/10/01 09:47:13 OK 1_commit_pending_closure.sql (2.04ms)27882026/10/01 09:47:13 OK 2_object_stats_trigger.sql (1.45ms)27892026/10/01 09:47:13 OK 2_object_stats_trigger.sql (776.8µs)27902026/10/01 09:47:13 OK 3_commit_push.sql (1.13ms)27912026/10/01 09:47:13 goose: up to current file version: 327922026/10/01 09:47:13 OK 3_commit_push.sql (1.48ms)27932026/10/01 09:47:13 goose: up to current file version: 32794--- PASS: TestGetExistingObjectsLocksRows (0.41s)2795=== CONT TestClientErrorHandling/InvalidAuthToken27962026/10/01 09:47:13 INFO Received uploads request method=POST path=/api/pending_closures27972026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes27982026/10/01 09:47:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27992026/10/01 09:47:13 INFO Uploading g0mqw2sykxm2y361x089j4gbzbgnbj2v-file1.txt (160B)28002026/10/01 09:47:13 WARN Failed to register uploaded object key=g0mqw2sykxm2y361x089j4gbzbgnbj2v.ls error="server returned 404: 404 page not found\n"28012026/10/01 09:47:13 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"28022026/10/01 09:47:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign28032026/10/01 09:47:13 INFO Signed narinfos id=1 count=128042026/10/01 09:47:13 INFO Uploading 1 narinfos2805=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows28062026/10/01 09:47:13 INFO Received complete push request method=POST path=/api/pushes/1/complete28072026/10/01 09:47:13 WARN Failed to register uploaded object key=g0mqw2sykxm2y361x089j4gbzbgnbj2v.narinfo error="server returned 404: 404 page not found\n"2808--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.39s)2809=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2810=== NAME TestClientCADerivations2811 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2812 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2813 error: binary cache 's3://bucket60?endpoint=http://localhost:40619®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations390122353/001/store'2814 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12815--- PASS: TestClientCADerivations (1.05s)2816=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2817=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected28182026/10/01 09:47:13 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]2819=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected28202026/10/01 09:47:13 WARN Authentication failed token_preview=eyJhbGciOi...DEfn6TtPFA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2821=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2822=== CONT TestService_RequireScope_OIDC/builder_may_write2823--- PASS: TestService_AuthMiddleware_OIDC (0.62s)2824 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2825 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2826 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2827 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2828=== CONT TestService_RequireScope_OIDC/static_token_may_admin2829=== CONT TestService_RequireScope_OIDC/reader_may_not_write2830=== CONT TestService_RequireScope_OIDC/ops_may_not_write2831=== CONT TestService_RequireScope_OIDC/ops_may_admin2832=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2833=== CONT TestService_RequireScope_OIDC/static_token_may_write2834=== CONT TestService_RequireScope_OIDC/writer_implies_read2835=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2836=== CONT TestService_RequireScope_OIDC/reader_may_read2837--- PASS: TestService_RequireScope_OIDC (0.58s)2838 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2839 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2840 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2841 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2842 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2843 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2844 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2845 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2846 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2847 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)28482026/10/01 09:47:13 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/present28492026/10/01 09:47:13 INFO Upload complete. (231ms)2850=== NAME TestNARDeduplicationMetadataUploadBug2851 metadata_upload_test.go:54: Retrieved narinfo from S3:2852 StorePath: /build/TestNARDeduplicationMetadataUploadBug1442600454/001/store/g0mqw2sykxm2y361x089j4gbzbgnbj2v-file1.txt2853 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2854 Compression: zstd2855 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2856 NarSize: 1602857 References: 2858 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2859 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2860 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2861 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}28622026-10-01 09:47:13.513 UTC [1932] ERROR: relation "goose_db_version" does not exist at character 3628632026-10-01 09:47:13.513 UTC [1932] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28642026-10-01 09:47:13.513 UTC [1933] ERROR: relation "goose_db_version" does not exist at character 3628652026-10-01 09:47:13.513 UTC [1933] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28662026/10/01 09:47:13 OK 20241026095416_initial_model.sql (8.3ms)28672026/10/01 09:47:13 OK 20241026095416_initial_model.sql (8.66ms)28682026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (2.26ms)28692026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.96ms)28702026/10/01 09:47:13 OK 20251218171726_add_pins.sql (2.86ms)28712026/10/01 09:47:13 OK 20251218171726_add_pins.sql (3.09ms)28722026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (3.42ms)28732026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (3.78ms)28742026/10/01 09:47:13 OK 20260905000000_add_claims.sql (2.67ms)28752026/10/01 09:47:13 OK 20260905000000_add_claims.sql (2.95ms)28762026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (2ms)28772026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (2.23ms)28782026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (1.84ms)28792026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000028802026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (1.6ms)28812026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000028822026/10/01 09:47:13 OK 1_commit_pending_closure.sql (3.19ms)2883 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1442600454/001/store/rsngwg92wg97s0bhz1s7jksg8rqaw5nc-file2.txt28842026/10/01 09:47:13 OK 1_commit_pending_closure.sql (2.37ms)28852026/10/01 09:47:13 OK 2_object_stats_trigger.sql (1.18ms)28862026/10/01 09:47:13 OK 2_object_stats_trigger.sql (1.26ms)28872026/10/01 09:47:13 OK 3_commit_push.sql (964.3µs)28882026/10/01 09:47:13 goose: up to current file version: 328892026/10/01 09:47:13 OK 3_commit_push.sql (675.78µs)28902026/10/01 09:47:13 goose: up to current file version: 32891--- PASS: TestGCEndsOnShutdown (0.55s)28922026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=028932026/10/01 09:47:13 WARN Force mode enabled - objects will be deleted immediately without grace period28942026/10/01 09:47:13 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."28952026/10/01 09:47:13 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."2896--- PASS: TestFailedS3DeleteKeepsTombstone (0.69s)28972026/10/01 09:47:13 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=217.934845ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28982026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=028992026/10/01 09:47:13 WARN Force mode enabled - objects will be deleted immediately without grace period2900--- PASS: TestService_healthCheckHandler (0.54s)29012026/10/01 09:47:13 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=029022026/10/01 09:47:13 INFO Vacuumed table table=pending_closures29032026/10/01 09:47:13 INFO Vacuumed table table=pending_objects29042026/10/01 09:47:13 INFO Vacuumed table table=multipart_uploads29052026/10/01 09:47:13 INFO Vacuumed table table=closures29062026/10/01 09:47:13 INFO Vacuumed table table=objects29072026-10-01 09:47:13.607 UTC [1973] ERROR: relation "goose_db_version" does not exist at character 3629082026-10-01 09:47:13.607 UTC [1973] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29092026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=029102026/10/01 09:47:13 WARN Force mode enabled - objects will be deleted immediately without grace period29112026-10-01 09:47:13.616 UTC [1991] ERROR: relation "goose_db_version" does not exist at character 3629122026-10-01 09:47:13.616 UTC [1991] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC29132026/10/01 09:47:13 INFO Received push request method=POST path=/api/pushes29142026/10/01 09:47:13 OK 20241026095416_initial_model.sql (7.17ms)29152026/10/01 09:47:13 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=029162026/10/01 09:47:13 INFO Vacuumed table table=pending_closures29172026/10/01 09:47:13 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)29182026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.13ms)29192026/10/01 09:47:13 INFO Vacuumed table table=pending_objects29202026/10/01 09:47:13 INFO Vacuumed table table=multipart_uploads29212026/10/01 09:47:13 INFO Vacuumed table table=closures29222026/10/01 09:47:13 OK 20251218171726_add_pins.sql (2.29ms)29232026/10/01 09:47:13 INFO Vacuumed table table=objects2924--- PASS: TestSweepSkipsRowsLockedByPush (0.58s)29252026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (2.58ms)29262026/10/01 09:47:13 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign29272026/10/01 09:47:13 WARN Failed to register uploaded object key=rsngwg92wg97s0bhz1s7jksg8rqaw5nc.ls error="server returned 404: 404 page not found\n"29282026/10/01 09:47:13 INFO Signed narinfos id=2 count=129292026/10/01 09:47:13 INFO Uploading 1 narinfos29302026/10/01 09:47:13 OK 20260905000000_add_claims.sql (3.17ms)29312026/10/01 09:47:13 OK 20241026095416_initial_model.sql (8.06ms)29322026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (1.53ms)29332026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.14ms)29342026/10/01 09:47:13 INFO Received complete push request method=POST path=/api/pushes/2/complete29352026/10/01 09:47:13 WARN Failed to register uploaded object key=rsngwg92wg97s0bhz1s7jksg8rqaw5nc.narinfo error="server returned 404: 404 page not found\n"29362026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (1.45ms)29372026/10/01 09:47:13 goose: successfully migrated database to version: 2026092312000029382026/10/01 09:47:13 OK 20251218171726_add_pins.sql (1.82ms)29392026/10/01 09:47:13 OK 1_commit_pending_closure.sql (1.47ms)29402026/10/01 09:47:13 INFO Upload complete. (52ms)29412026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (2.48ms)29422026/10/01 09:47:13 OK 2_object_stats_trigger.sql (1.09ms)29432026/10/01 09:47:13 OK 3_commit_push.sql (770.97µs)2944=== NAME TestNARDeduplicationMetadataUploadBug29452026/10/01 09:47:13 goose: up to current file version: 32946 metadata_upload_test.go:76: Retrieved narinfo from S3:2947 StorePath: /build/TestNARDeduplicationMetadataUploadBug1442600454/001/store/rsngwg92wg97s0bhz1s7jksg8rqaw5nc-file2.txt2948 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2949 Compression: zstd2950 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2951 NarSize: 1602952 References: 2953 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf29542026/10/01 09:47:13 OK 20260905000000_add_claims.sql (1.8ms)29552026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (1.43ms)2956 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)29572026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (945.34µs)29582026/10/01 09:47:13 goose: successfully migrated database to version: 202609231200002959 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2960 {"version":1,"root":{"type":"regular","size":44}}29612026/10/01 09:47:13 OK 1_commit_pending_closure.sql (1.38ms)29622026/10/01 09:47:13 OK 2_object_stats_trigger.sql (777.96µs)29632026/10/01 09:47:13 OK 3_commit_push.sql (708.92µs)29642026/10/01 09:47:13 goose: up to current file version: 32965--- PASS: TestNARDeduplicationMetadataUploadBug (0.95s)29662026/10/01 09:47:13 WARN readiness check failed error="closed pool"2967--- PASS: TestService_readinessHandler (0.56s)29682026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=029692026/10/01 09:47:13 WARN Force mode enabled - objects will be deleted immediately without grace period29702026/10/01 09:47:13 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=029712026/10/01 09:47:13 INFO Vacuumed table table=pending_closures29722026/10/01 09:47:13 INFO Vacuumed table table=pending_objects29732026/10/01 09:47:13 INFO Vacuumed table table=multipart_uploads29742026/10/01 09:47:13 INFO Vacuumed table table=closures29752026/10/01 09:47:13 INFO Vacuumed table table=objects2976--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.58s)2977--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.61s)29782026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=029792026/10/01 09:47:13 WARN Force mode enabled - objects will be deleted immediately without grace period29802026/10/01 09:47:13 INFO Received uploads request method=POST path=/api/pending_closures2981--- PASS: TestUploadHandlersRejectOversizedBody (0.19s)2982 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2983 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.09s)2984 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.65s)29852026/10/01 09:47:13 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=029862026/10/01 09:47:13 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=411.327234ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present29872026/10/01 09:47:13 INFO Vacuumed table table=pending_closures29882026/10/01 09:47:13 INFO Vacuumed table table=pending_objects29892026/10/01 09:47:13 INFO Vacuumed table table=multipart_uploads29902026/10/01 09:47:13 INFO Vacuumed table table=closures29912026/10/01 09:47:13 INFO Received uploads request method=POST path=/api/pending_closures29922026/10/01 09:47:13 INFO Vacuumed table table=objects2993--- PASS: TestGCSweepDeliversEachKeyOnce (0.69s)29942026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=029952026/10/01 09:47:13 WARN Force mode enabled - objects will be deleted immediately without grace period29962026/10/01 09:47:13 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=029972026/10/01 09:47:13 INFO Vacuumed table table=pending_closures29982026/10/01 09:47:13 INFO Vacuumed table table=pending_objects29992026/10/01 09:47:13 INFO Vacuumed table table=multipart_uploads30002026/10/01 09:47:13 INFO Vacuumed table table=closures30012026/10/01 09:47:13 INFO Vacuumed table table=objects3002--- PASS: TestSweepRechecksPendingAfterLocking (0.76s)30032026/10/01 09:47:13 INFO Received uploads request method=POST path=/api/pending_closures30042026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=030052026/10/01 09:47:13 WARN Force mode enabled - objects will be deleted immediately without grace period30062026/10/01 09:47:13 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=030072026/10/01 09:47:13 INFO Vacuumed table table=pending_closures30082026/10/01 09:47:13 INFO Vacuumed table table=pending_objects30092026/10/01 09:47:13 INFO Vacuumed table table=multipart_uploads30102026/10/01 09:47:13 INFO Vacuumed table table=closures30112026/10/01 09:47:13 INFO Vacuumed table table=objects30122026/10/01 09:47:13 INFO Received uploads request method=POST path=/api/pending_closures30132026/10/01 09:47:13 INFO Aborted multipart uploads count=0 kept=030142026/10/01 09:47:13 WARN Force mode enabled - objects will be deleted immediately without grace period30152026/10/01 09:47:13 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"30162026/10/01 09:47:13 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=030172026/10/01 09:47:13 INFO Vacuumed table table=pending_closures30182026/10/01 09:47:13 INFO Vacuumed table table=pending_objects30192026/10/01 09:47:13 INFO Vacuumed table table=multipart_uploads30202026/10/01 09:47:13 INFO Vacuumed table table=closures30212026/10/01 09:47:13 INFO Vacuumed table table=objects3022--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)3023 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.62s)3024 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.67s)30252026/10/01 09:47:14 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"3026--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.89s)30272026/10/01 09:47:14 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=874.391274ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present3028--- PASS: TestPushWaitsForSweepHoldingRow (1.14s)3029=== NAME TestOrphanedObjectsGCStressTest3030 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains3031 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion3032 orphaned_objects_gc_test.go:509: Stress test completed successfully:3033 orphaned_objects_gc_test.go:510: - Active objects preserved: 203034 orphaned_objects_gc_test.go:511: - Objects deleted: 2103035 orphaned_objects_gc_test.go:512: - Total GC'd: 2103036--- PASS: TestOrphanedObjectsGCStressTest (2.83s)30372026/10/01 09:47:15 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=030382026/10/01 09:47:15 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.594449989s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present30392026/10/01 09:47:15 INFO Received create pin request method=POST path=/api/pins/myapp30402026/10/01 09:47:15 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3533578953/001/store/6hj48h9qg26ijl9ib2w6av3pnljjqm8z-pinned-file.txt narinfo_key=6hj48h9qg26ijl9ib2w6av3pnljjqm8z.narinfo30412026/10/01 09:47:15 INFO Starting cleanup of old closures method=DELETE path=/api/closures30422026/10/01 09:47:15 INFO Garbage collection started30432026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=030442026/10/01 09:47:15 WARN Force mode enabled - objects will be deleted immediately without grace period30452026/10/01 09:47:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=030462026/10/01 09:47:15 INFO Vacuumed table table=pending_closures30472026/10/01 09:47:15 INFO Vacuumed table table=pending_objects30482026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads30492026/10/01 09:47:15 INFO Vacuumed table table=closures30502026/10/01 09:47:15 INFO Vacuumed table table=objects30512026/10/01 09:47:15 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=03052=== NAME TestClientIntegration3053 client_integration_test.go:323: Objects in database after GC:3054 client_integration_test.go:323: Successfully deleted all objects with GC --force3055--- PASS: TestClientIntegration (2.83s)30562026/10/01 09:47:15 WARN Rate limiter enabled after throttle name=s3-test rate=530572026/10/01 09:47:15 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."3058=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle3059 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=103060 throttle_test.go:215: Rate limiter: enabled=true, rate=5.003061--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.39s)30622026/10/01 09:47:16 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30632026/10/01 09:47:16 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=189.678136ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30642026/10/01 09:47:17 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=404.747762ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config3065=== NAME TestPinProtectsFromGC3066 client_integration_test.go:840: Pin successfully protected closure from garbage collection3067--- PASS: TestPinProtectsFromGC (4.97s)30682026/10/01 09:47:17 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=767.703824ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30692026/10/01 09:47:18 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.697818883s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30702026/10/01 09:47:18 INFO Aborted multipart uploads count=1 kept=030712026/10/01 09:47:18 INFO Received cleanup request method=DELETE path=/api/pending_closures30722026/10/01 09:47:18 INFO Aborted multipart uploads count=1 kept=03073--- PASS: TestPendingCleanupUsesOneCutoff (6.66s)30742026/10/01 09:47:19 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"30752026/10/01 09:47:19 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-config30762026/10/01 09:47:20 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.773908ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30772026/10/01 09:47:20 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=388.571477ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30782026/10/01 09:47:20 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=843.42207ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30792026/10/01 09:47:21 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.666705609s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30802026/10/01 09:47:23 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_closures30812026/10/01 09:47:23 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.435411ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30822026/10/01 09:47:23 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=410.73321ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30832026/10/01 09:47:23 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=748.940539ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30842026/10/01 09:47:24 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.759935377s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3085--- PASS: TestClientErrorHandling (0.00s)3086 --- PASS: TestClientErrorHandling/InvalidStorePath (0.65s)3087 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.71s)3088 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.07s)3089PASS30902026-10-01 09:47:26.701 UTC [130] LOG: received smart shutdown request30912026-10-01 09:47:26.705 UTC [130] LOG: background worker "logical replication launcher" (PID 140) exited with exit code 130922026-10-01 09:47:26.716 UTC [135] LOG: shutting down30932026-10-01 09:47:26.717 UTC [135] LOG: checkpoint starting: shutdown immediate30942026-10-01 09:47:27.587 UTC [135] LOG: checkpoint complete: wrote 10696 buffers (65.3%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 24 recycled; write=0.274 s, sync=0.557 s, total=0.870 s; sync files=28648, longest=0.073 s, average=0.001 s; distance=396493 kB, estimate=396493 kB; lsn=0/19A99320, redo lsn=0/19A9932030952026-10-01 09:47:27.653 UTC [130] LOG: database system is shut down3096Running OIDC tests...3097=== RUN TestAudienceForIssuer3098=== PAUSE TestAudienceForIssuer3099=== RUN TestGlobMatch3100=== PAUSE TestGlobMatch3101=== RUN TestValidateToken_ValidToken3102=== PAUSE TestValidateToken_ValidToken3103=== RUN TestValidateToken_WrongAudience3104=== PAUSE TestValidateToken_WrongAudience3105=== RUN TestValidateToken_Expired3106=== PAUSE TestValidateToken_Expired3107=== RUN TestValidateToken_BoundClaimsMismatch3108=== PAUSE TestValidateToken_BoundClaimsMismatch3109=== RUN TestValidateToken_BoundSubjectMismatch3110=== PAUSE TestValidateToken_BoundSubjectMismatch3111=== RUN TestValidateToken_MultipleProviders3112=== PAUSE TestValidateToken_MultipleProviders3113=== RUN TestValidateToken_NoMatchingProvider3114=== PAUSE TestValidateToken_NoMatchingProvider3115=== RUN TestValidateToken_KubernetesServiceAccount3116=== PAUSE TestValidateToken_KubernetesServiceAccount3117=== RUN TestNewValidator_KubernetesRequiresCA3118=== PAUSE TestNewValidator_KubernetesRequiresCA3119=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3120=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3121=== RUN TestPins_ReservedForMatchingRule3122=== PAUSE TestPins_ReservedForMatchingRule3123=== RUN TestPins_TopLevelShorthand3124=== PAUSE TestPins_TopLevelShorthand3125=== RUN TestPins_ConfigValidation3126=== PAUSE TestPins_ConfigValidation3127=== RUN TestScopes_LegacyProviderDefaultsToWrite3128=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3129=== RUN TestScopes_Rules3130=== PAUSE TestScopes_Rules3131=== RUN TestScopes_ConfigValidation3132=== PAUSE TestScopes_ConfigValidation3133=== CONT TestAudienceForIssuer3134=== CONT TestValidateToken_KubernetesServiceAccount3135=== CONT TestValidateToken_WrongAudience3136--- PASS: TestAudienceForIssuer (0.00s)3137=== CONT TestValidateToken_ValidToken3138=== CONT TestGlobMatch3139=== RUN TestGlobMatch/foo_foo3140=== PAUSE TestGlobMatch/foo_foo3141=== CONT TestValidateToken_Expired3142=== CONT TestValidateToken_MultipleProviders3143=== CONT TestValidateToken_NoMatchingProvider3144=== CONT TestPins_ConfigValidation3145=== CONT TestScopes_ConfigValidation3146=== CONT TestScopes_Rules3147=== CONT TestScopes_LegacyProviderDefaultsToWrite3148--- PASS: TestPins_ConfigValidation (0.00s)3149--- PASS: TestScopes_ConfigValidation (0.00s)3150=== CONT TestValidateToken_BoundSubjectMismatch3151=== CONT TestPins_ReservedForMatchingRule3152=== CONT TestPins_TopLevelShorthand3153=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3154=== CONT TestNewValidator_KubernetesRequiresCA3155=== CONT TestValidateToken_BoundClaimsMismatch3156=== RUN TestGlobMatch/foo_bar3157=== PAUSE TestGlobMatch/foo_bar3158=== RUN TestGlobMatch/*_3159=== PAUSE TestGlobMatch/*_3160=== RUN TestGlobMatch/*_anything3161=== PAUSE TestGlobMatch/*_anything3162=== RUN TestGlobMatch/foo*_foo3163=== PAUSE TestGlobMatch/foo*_foo3164=== RUN TestGlobMatch/foo*_foobar3165=== PAUSE TestGlobMatch/foo*_foobar3166=== RUN TestGlobMatch/foo*_bar3167=== PAUSE TestGlobMatch/foo*_bar3168=== RUN TestGlobMatch/*bar_bar3169=== PAUSE TestGlobMatch/*bar_bar3170=== RUN TestGlobMatch/*bar_foobar3171=== PAUSE TestGlobMatch/*bar_foobar3172=== RUN TestGlobMatch/*bar_foo3173=== PAUSE TestGlobMatch/*bar_foo3174=== RUN TestGlobMatch/foo*bar_foobar3175=== PAUSE TestGlobMatch/foo*bar_foobar3176=== RUN TestGlobMatch/foo*bar_foo123bar3177=== PAUSE TestGlobMatch/foo*bar_foo123bar3178=== RUN TestGlobMatch/foo*bar_foobarbaz3179=== PAUSE TestGlobMatch/foo*bar_foobarbaz3180=== RUN TestGlobMatch/*/*_foo/bar3181=== PAUSE TestGlobMatch/*/*_foo/bar3182=== RUN TestGlobMatch/*/*_foo3183=== PAUSE TestGlobMatch/*/*_foo3184=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3185=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3186=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03187=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03188=== RUN TestGlobMatch/refs/*/main_refs/heads/main3189=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3190=== RUN TestGlobMatch/fo?_foo3191=== PAUSE TestGlobMatch/fo?_foo3192=== RUN TestGlobMatch/fo?_fo3193=== PAUSE TestGlobMatch/fo?_fo3194=== RUN TestGlobMatch/fo?_fooo3195=== PAUSE TestGlobMatch/fo?_fooo3196=== RUN TestGlobMatch/?oo_foo3197=== PAUSE TestGlobMatch/?oo_foo3198=== RUN TestGlobMatch/?oo_boo3199=== PAUSE TestGlobMatch/?oo_boo3200=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3201=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3202=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3203=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3204=== CONT TestGlobMatch/foo_foo3205=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3206=== CONT TestGlobMatch/fo?_fo3207=== CONT TestGlobMatch/*bar_bar3208=== CONT TestGlobMatch/foo*bar_foobarbaz3209=== CONT TestGlobMatch/*_anything3210=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3211=== CONT TestGlobMatch/*bar_foo3212=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03213=== CONT TestGlobMatch/foo*_bar3214=== CONT TestGlobMatch/*bar_foobar3215=== CONT TestGlobMatch/refs/*/main_refs/heads/main3216=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3217=== CONT TestGlobMatch/*/*_foo3218=== CONT TestGlobMatch/fo?_fooo3219=== CONT TestGlobMatch/foo*_foobar3220=== CONT TestGlobMatch/foo*bar_foobar3221=== CONT TestGlobMatch/foo*bar_foo123bar3222=== CONT TestGlobMatch/*/*_foo/bar3223=== CONT TestGlobMatch/foo*_foo3224=== CONT TestGlobMatch/?oo_foo3225=== CONT TestGlobMatch/*_3226=== CONT TestGlobMatch/foo_bar3227=== CONT TestGlobMatch/fo?_foo3228=== CONT TestGlobMatch/?oo_boo3229--- PASS: TestGlobMatch (0.01s)3230 --- PASS: TestGlobMatch/foo_foo (0.00s)3231 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3232 --- PASS: TestGlobMatch/fo?_fo (0.00s)3233 --- PASS: TestGlobMatch/*bar_bar (0.00s)3234 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3235 --- PASS: TestGlobMatch/*_anything (0.00s)3236 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3237 --- PASS: TestGlobMatch/*bar_foo (0.00s)3238 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3239 --- PASS: TestGlobMatch/foo*_bar (0.00s)3240 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3241 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3242 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3243 --- PASS: TestGlobMatch/*/*_foo (0.00s)3244 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3245 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3246 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3247 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3248 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3249 --- PASS: TestGlobMatch/foo*_foo (0.00s)3250 --- PASS: TestGlobMatch/?oo_foo (0.00s)3251 --- PASS: TestGlobMatch/*_ (0.00s)3252 --- PASS: TestGlobMatch/foo_bar (0.00s)3253 --- PASS: TestGlobMatch/fo?_foo (0.00s)3254 --- PASS: TestGlobMatch/?oo_boo (0.00s)32552026/10/01 09:47:29 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:417653256--- PASS: TestValidateToken_KubernetesServiceAccount (0.05s)32572026/10/01 09:47:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40299/oidc3258--- PASS: TestValidateToken_Expired (0.05s)32592026/10/01 09:47:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37575/oidc32602026/10/01 09:47:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37629/oidc3261--- PASS: TestPins_TopLevelShorthand (0.06s)3262--- PASS: TestValidateToken_WrongAudience (0.06s)32632026/10/01 09:47:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40891/oidc32642026/10/01 09:47:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34177/oidc3265--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.08s)3266--- PASS: TestScopes_Rules (0.08s)32672026/10/01 09:47:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40041/oidc3268--- PASS: TestValidateToken_BoundSubjectMismatch (0.09s)32692026/10/01 09:47:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38231/oidc3270--- PASS: TestValidateToken_BoundClaimsMismatch (0.09s)32712026/10/01 09:47:29 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:44453/oidc3272--- PASS: TestValidateToken_NoMatchingProvider (0.11s)32732026/10/01 09:47:29 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:36115/oidc32742026/10/01 09:47:29 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:37467/oidc32752026/10/01 09:47:29 http: TLS handshake error from 127.0.0.1:38224: remote error: tls: bad certificate3276--- PASS: TestValidateToken_MultipleProviders (0.12s)3277--- PASS: TestNewValidator_KubernetesRequiresCA (0.11s)32782026/10/01 09:47:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46061/oidc3279--- PASS: TestPins_ReservedForMatchingRule (0.11s)32802026/10/01 09:47:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35473/oidc3281--- PASS: TestValidateToken_ValidToken (0.13s)32822026/10/01 09:47:29 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233283--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.16s)3284PASS3285Running hook tests...3286=== RUN TestSendPathsEmpty3287=== PAUSE TestSendPathsEmpty3288=== RUN TestQueueEnqueueAndFetch3289=== PAUSE TestQueueEnqueueAndFetch3290=== RUN TestQueueDeduplication3291=== PAUSE TestQueueDeduplication3292=== RUN TestQueueRemove3293=== PAUSE TestQueueRemove3294=== RUN TestQueueFetchBatchLimit3295=== PAUSE TestQueueFetchBatchLimit3296=== RUN TestQueueRetryMovesToBack3297=== PAUSE TestQueueRetryMovesToBack3298=== RUN TestQueueFetchRemoveLifecycle3299=== PAUSE TestQueueFetchRemoveLifecycle3300=== RUN TestQueueConcurrentWriters3301=== PAUSE TestQueueConcurrentWriters3302=== RUN TestQueueRemoveLargeClosure3303=== PAUSE TestQueueRemoveLargeClosure3304=== RUN TestServerClientIntegration3305=== PAUSE TestServerClientIntegration3306=== RUN TestServerQueueError3307=== PAUSE TestServerQueueError3308=== RUN TestGetListenerSocketActivation3309 server_test.go:210: === RUN TestGetListenerSocketActivation3310 --- PASS: TestGetListenerSocketActivation (0.00s)3311 PASS3312 3313--- PASS: TestGetListenerSocketActivation (0.01s)3314=== RUN TestDrainIsolatesPoisonPath3315=== PAUSE TestDrainIsolatesPoisonPath3316=== RUN TestRunNotBlockedByPoisonHead3317=== PAUSE TestRunNotBlockedByPoisonHead3318=== RUN TestDrainGivesUpWhenServerDown3319=== PAUSE TestDrainGivesUpWhenServerDown3320=== RUN TestFailedPathPrunedByLaterClosure3321=== PAUSE TestFailedPathPrunedByLaterClosure3322=== RUN TestWorkerUploadsAndRemoves3323=== PAUSE TestWorkerUploadsAndRemoves3324=== RUN TestWorkerSkipsGCdPaths3325=== PAUSE TestWorkerSkipsGCdPaths3326=== RUN TestWorkerPrunesClosureDeps3327=== PAUSE TestWorkerPrunesClosureDeps3328=== RUN TestDrainTimeout3329=== PAUSE TestDrainTimeout3330=== CONT TestSendPathsEmpty3331=== CONT TestWorkerPrunesClosureDeps3332=== CONT TestFailedPathPrunedByLaterClosure3333=== CONT TestDrainTimeout3334=== CONT TestWorkerSkipsGCdPaths3335=== CONT TestWorkerUploadsAndRemoves3336=== CONT TestQueueRetryMovesToBack3337=== CONT TestServerClientIntegration3338=== CONT TestQueueRemoveLargeClosure3339=== CONT TestQueueConcurrentWriters3340--- PASS: TestSendPathsEmpty (0.00s)3341=== CONT TestServerQueueError3342=== CONT TestQueueFetchBatchLimit3343=== CONT TestQueueFetchRemoveLifecycle3344=== CONT TestQueueEnqueueAndFetch3345=== CONT TestQueueRemove3346=== CONT TestRunNotBlockedByPoisonHead3347=== CONT TestDrainGivesUpWhenServerDown33482026/10/01 09:47:29 ERROR Failed to queue paths error="permission denied" count=13349=== CONT TestDrainIsolatesPoisonPath3350=== CONT TestQueueDeduplication3351--- PASS: TestServerQueueError (0.00s)3352--- PASS: TestServerClientIntegration (0.00s)33532026/10/01 09:47:29 INFO Upload queue status pending=233542026/10/01 09:47:29 INFO Uploading batch count=133552026/10/01 09:47:29 ERROR Upload failed error="upload failed" count=133562026/10/01 09:47:29 INFO Uploading batch count=233572026/10/01 09:47:29 INFO Uploading batch count=433582026/10/01 09:47:29 ERROR Upload failed error="upload failed" count=433592026/10/01 09:47:29 INFO Uploading batch count=233602026/10/01 09:47:29 INFO Upload queue status pending=233612026/10/01 09:47:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3769894058/002/bbb3362--- PASS: TestQueueEnqueueAndFetch (0.02s)33632026/10/01 09:47:29 INFO Uploading batch count=233642026/10/01 09:47:29 ERROR Upload failed error="upload failed" count=233652026/10/01 09:47:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1033197094/002/a3366--- PASS: TestQueueFetchBatchLimit (0.02s)33672026/10/01 09:47:29 INFO Upload queue status pending=333682026/10/01 09:47:29 INFO Uploading batch count=13369--- PASS: TestQueueRemove (0.02s)33702026/10/01 09:47:29 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2092519605/002/nonexistent33712026/10/01 09:47:29 INFO Upload queue status pending=233722026/10/01 09:47:29 INFO Uploading batch count=133732026/10/01 09:47:29 ERROR Upload failed error="upload failed" count=133742026/10/01 09:47:29 INFO Uploading batch count=133752026/10/01 09:47:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1033197094/002/b33762026/10/01 09:47:29 INFO Uploading batch count=133772026/10/01 09:47:29 INFO Uploading batch count=13378--- PASS: TestQueueFetchRemoveLifecycle (0.02s)3379--- PASS: TestQueueRetryMovesToBack (0.02s)3380--- PASS: TestQueueDeduplication (0.02s)33812026/10/01 09:47:29 INFO Uploading batch count=233822026/10/01 09:47:29 ERROR Upload failed error="upload failed" count=233832026/10/01 09:47:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1033197094/002/c33842026/10/01 09:47:29 INFO Uploading batch count=133852026/10/01 09:47:29 ERROR Upload failed error="upload failed" count=133862026/10/01 09:47:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1033197094/002/d33872026/10/01 09:47:29 INFO Uploading batch count=133882026/10/01 09:47:29 ERROR Upload failed error="upload failed" count=133892026/10/01 09:47:29 INFO Uploading batch count=233902026/10/01 09:47:29 ERROR Upload failed error="upload failed" count=233912026/10/01 09:47:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1033197094/002/e3392--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)33932026/10/01 09:47:29 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1033197094/002/f33942026/10/01 09:47:29 INFO Uploading batch count=133952026/10/01 09:47:29 ERROR Upload failed error="upload failed" count=133962026/10/01 09:47:29 ERROR Drain finished with paths left in queue remaining=1033972026/10/01 09:47:29 ERROR Drain finished with paths left in queue remaining=13398--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3399--- PASS: TestDrainIsolatesPoisonPath (0.02s)3400--- PASS: TestWorkerUploadsAndRemoves (0.03s)3401--- PASS: TestWorkerSkipsGCdPaths (0.04s)3402--- PASS: TestWorkerPrunesClosureDeps (0.04s)3403--- PASS: TestQueueRemoveLargeClosure (0.07s)34042026/10/01 09:47:29 ERROR Upload failed error="context deadline exceeded" count=234052026/10/01 09:47:29 ERROR Drain finished with paths left in queue remaining=43406--- PASS: TestDrainTimeout (0.22s)3407--- PASS: TestQueueConcurrentWriters (0.38s)34082026/10/01 09:47:30 INFO Uploading batch count=134092026/10/01 09:47:30 INFO Uploading batch count=134102026/10/01 09:47:30 INFO Uploading batch count=134112026/10/01 09:47:30 ERROR Upload failed error="upload failed" count=134122026/10/01 09:47:30 INFO Uploading batch count=134132026/10/01 09:47:30 ERROR Upload failed error="upload failed" count=134142026/10/01 09:47:30 INFO Uploading batch count=134152026/10/01 09:47:30 ERROR Upload failed error="upload failed" count=134162026/10/01 09:47:30 INFO Uploading batch count=134172026/10/01 09:47:30 ERROR Upload failed error="upload failed" count=134182026/10/01 09:47:30 ERROR Drain finished with paths left in queue remaining=13419--- PASS: TestRunNotBlockedByPoisonHead (1.04s)3420PASS