niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #287
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestCaseHackSuffix8=== PAUSE TestCaseHackSuffix9=== RUN TestFilterOversizedClosures10=== PAUSE TestFilterOversizedClosures11=== RUN TestUploadMultipart_PartsInParallel12=== PAUSE TestUploadMultipart_PartsInParallel13=== RUN TestPartSizeForNAR14=== PAUSE TestPartSizeForNAR15=== RUN TestUploadMultipart_SupersededByPeer16=== PAUSE TestUploadMultipart_SupersededByPeer17=== RUN TestDumpPathCaseHackMatchesNix18--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)19=== RUN TestDumpPathCaseHackCollision20--- PASS: TestDumpPathCaseHackCollision (0.00s)21=== RUN TestDumpPathMatchesNix22=== PAUSE TestDumpPathMatchesNix23=== RUN TestDumpPathSingleFile24=== PAUSE TestDumpPathSingleFile25=== RUN TestDumpPathWriterError26=== PAUSE TestDumpPathWriterError27=== RUN TestEncodeNixBase3228=== PAUSE TestEncodeNixBase3229=== RUN TestEncodeNixBase32WithRealHash30=== PAUSE TestEncodeNixBase32WithRealHash31=== RUN TestConvertHashToNix3232=== PAUSE TestConvertHashToNix3233=== RUN TestGetStorePathHash34=== PAUSE TestGetStorePathHash35=== RUN TestPathInfoHashCompatibility36=== PAUSE TestPathInfoHashCompatibility37=== RUN TestParsePathInfoJSON38=== PAUSE TestParsePathInfoJSON39=== RUN TestParsePathInfoJSONMultiplePaths40=== PAUSE TestParsePathInfoJSONMultiplePaths41=== RUN TestPathInfoCACompatibility42=== PAUSE TestPathInfoCACompatibility43=== RUN TestRateLimiterFeedback44=== PAUSE TestRateLimiterFeedback45=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess47=== RUN TestResolveStorePath48=== PAUSE TestResolveStorePath49=== RUN TestDoWithRetry_BodyReplayedViaGetBody50=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody51=== RUN TestShellSplit52=== PAUSE TestShellSplit53=== RUN TestShellSplitErrors54=== PAUSE TestShellSplitErrors55=== RUN TestStreamPushReportsEveryPath56=== PAUSE TestStreamPushReportsEveryPath57=== RUN TestStreamPushBatchesUnderLoad58=== PAUSE TestStreamPushBatchesUnderLoad59=== RUN TestStreamPushIsolatesFailures60=== PAUSE TestStreamPushIsolatesFailures61=== RUN TestStreamPushGivesUpOnDeadServer62=== PAUSE TestStreamPushGivesUpOnDeadServer63=== RUN TestStreamPushRequestLine64=== PAUSE TestStreamPushRequestLine65=== RUN TestStreamPushReportsSignatures66=== PAUSE TestStreamPushReportsSignatures67=== RUN TestClientSignaturesByStorePath68=== PAUSE TestClientSignaturesByStorePath69=== RUN TestSetClientTLS70=== PAUSE TestSetClientTLS71=== RUN TestSetClientTLSDoesNotMutateDefaultTransport72=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport73=== RUN TestSetClientTLSErrors74=== PAUSE TestSetClientTLSErrors75=== RUN TestStaticToken76=== PAUSE TestStaticToken77=== RUN TestFileTokenReadsAndCaches78=== PAUSE TestFileTokenReadsAndCaches79=== RUN TestFileTokenMissing80=== PAUSE TestFileTokenMissing81=== RUN TestFileTokenEmpty82=== PAUSE TestFileTokenEmpty83=== RUN TestScriptTokenNoExpiryRerunsEveryCall84=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall85=== RUN TestScriptTokenCachesUntilRefresh86=== PAUSE TestScriptTokenCachesUntilRefresh87=== RUN TestScriptTokenEmptyToken88=== PAUSE TestScriptTokenEmptyToken89=== RUN TestScriptTokenBadJSON90=== PAUSE TestScriptTokenBadJSON91=== RUN TestScriptTokenScriptFails92=== PAUSE TestScriptTokenScriptFails93=== RUN TestScriptTokenEmptyCommand94=== PAUSE TestScriptTokenEmptyCommand95=== CONT TestDoServerRequestAttachesToken96=== CONT TestEncodeNixBase32WithRealHash97--- PASS: TestEncodeNixBase32WithRealHash (0.00s)98=== CONT TestUploadMultipart_PartsInParallel99=== CONT TestShellSplit100--- PASS: TestShellSplit (0.00s)101=== CONT TestDumpPathMatchesNix102=== CONT TestScriptTokenEmptyCommand103=== CONT TestScriptTokenScriptFails104--- PASS: TestScriptTokenEmptyCommand (0.00s)105=== CONT TestSetClientTLSDoesNotMutateDefaultTransport106=== CONT TestScriptTokenBadJSON107=== CONT TestScriptTokenEmptyToken108=== CONT TestScriptTokenCachesUntilRefresh109=== CONT TestScriptTokenNoExpiryRerunsEveryCall110=== CONT TestFileTokenEmpty111=== CONT TestFileTokenMissing112=== CONT TestFileTokenReadsAndCaches113=== CONT TestStreamPushRequestLine114=== CONT TestStreamPushGivesUpOnDeadServer115=== CONT TestStreamPushIsolatesFailures116=== CONT TestStreamPushBatchesUnderLoad117=== CONT TestStreamPushReportsEveryPath118=== CONT TestUploadMultipart_SupersededByPeer119=== CONT TestShellSplitErrors120=== CONT TestClientSignaturesByStorePath121=== CONT TestEncodeNixBase32122=== CONT TestFilterOversizedClosures123=== CONT TestDumpPathWriterError124=== CONT TestPartSizeForNAR125=== CONT TestDumpPathSingleFile126--- PASS: TestScriptTokenScriptFails (0.00s)127=== CONT TestStaticToken128=== CONT TestSetClientTLSErrors1292026/10/01 07:33:56 ERROR Upload failed error="bad path" count=31302026/10/01 07:33:56 ERROR Upload failed error=boom count=1131=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1322026/10/01 07:33:56 WARN Rate limiter enabled after throttle name=server-test rate=51332026/10/01 07:33:56 ERROR Upload failed error="connection refused" count=201342026/10/01 07:33:56 ERROR Server seems unavailable, giving up on batch untried=17135--- PASS: TestFileTokenEmpty (0.00s)136--- PASS: TestFileTokenMissing (0.00s)137--- PASS: TestStreamPushReportsEveryPath (0.00s)138--- PASS: TestFileTokenReadsAndCaches (0.00s)139--- PASS: TestClientSignaturesByStorePath (0.00s)140--- PASS: TestStreamPushIsolatesFailures (0.00s)141--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)142--- PASS: TestShellSplitErrors (0.00s)143=== RUN TestFilterOversizedClosures/no_limit_keeps_everything144=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything145=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped146=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped147=== RUN TestFilterOversizedClosures/all_closures_skipped148=== PAUSE TestFilterOversizedClosures/all_closures_skipped149=== CONT TestSetClientTLS150=== CONT TestPathInfoHashCompatibility151=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)152=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)153=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon154=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon155=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI156=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI157=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512158=== RUN TestSetClientTLSErrors/missing_cert_file159=== PAUSE TestSetClientTLSErrors/missing_cert_file160=== RUN TestSetClientTLSErrors/missing_key_file161=== RUN TestPartSizeForNAR/zero_stays_at_minimum162=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512163=== RUN TestUploadMultipart_SupersededByPeer/exists164=== CONT TestCaseHackSuffix165=== CONT TestParsePathInfoJSON166=== CONT TestConvertHashToNix32167=== RUN TestConvertHashToNix32/SRI_format_to_Nix32168=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32169=== RUN TestConvertHashToNix32/already_Nix32_format170=== PAUSE TestUploadMultipart_SupersededByPeer/exists171=== RUN TestUploadMultipart_SupersededByPeer/missing172=== RUN TestEncodeNixBase32/test_string_hash173=== CONT TestResolveStorePath174=== CONT TestDoWithRetry_BodyReplayedViaGetBody175=== CONT TestGetStorePathHash176=== CONT TestRateLimiterFeedback177--- PASS: TestStaticToken (0.00s)178=== PAUSE TestSetClientTLSErrors/missing_key_file179--- PASS: TestScriptTokenEmptyToken (0.03s)180--- PASS: TestDoServerRequestAttachesToken (0.03s)181=== RUN TestSetClientTLSErrors/missing_ca_file182=== PAUSE TestSetClientTLSErrors/missing_ca_file183=== RUN TestSetClientTLSErrors/invalid_ca_file184--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.03s)185=== RUN TestGetStorePathHash/valid_store_path186=== PAUSE TestSetClientTLSErrors/invalid_ca_file187--- PASS: TestScriptTokenBadJSON (0.03s)188=== CONT TestParsePathInfoJSONMultiplePaths189=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths190=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths191=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths192=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths193=== RUN TestParsePathInfoJSON/Nix_format194=== PAUSE TestParsePathInfoJSON/Nix_format195=== RUN TestParsePathInfoJSON/Lix_format196=== PAUSE TestParsePathInfoJSON/Lix_format197=== RUN TestParsePathInfoJSON/empty_input198=== CONT TestRegisterUploadedObjectReusesConnections199=== RUN TestSetClientTLS/rejects_connection_without_client_cert200=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert201--- PASS: TestResolveStorePath (0.00s)202=== PAUSE TestUploadMultipart_SupersededByPeer/missing203=== PAUSE TestEncodeNixBase32/test_string_hash2042026/10/01 07:33:56 WARN Rate limiter enabled after throttle name=server-test rate=52052026/10/01 07:33:56 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:45517206=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum207=== CONT TestPathInfoCACompatibility208=== RUN TestPathInfoCACompatibility/null_ca_field209=== PAUSE TestPathInfoCACompatibility/null_ca_field210=== RUN TestPathInfoCACompatibility/old_string_format_-_text211=== RUN TestRateLimiterFeedback/429_enables_limiter212=== PAUSE TestRateLimiterFeedback/429_enables_limiter213=== RUN TestRateLimiterFeedback/503_enables_limiter2142026/10/01 07:33:56 WARN Rate limiter backed off name=server-test rate=5215=== PAUSE TestRateLimiterFeedback/503_enables_limiter216=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter217=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter2182026/10/01 07:33:56 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:45517219=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter220=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter221=== RUN TestPartSizeForNAR/small_stays_at_minimum222=== PAUSE TestPartSizeForNAR/small_stays_at_minimum223=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum224=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum225=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts226=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts227=== RUN TestPartSizeForNAR/1_TiB228=== PAUSE TestPartSizeForNAR/1_TiB229=== RUN TestPartSizeForNAR/5_TiB_S3_max_object230=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object231=== RUN TestPartSizeForNAR/capped_at_5_GiB232=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)233=== PAUSE TestPartSizeForNAR/capped_at_5_GiB234=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512235=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon236=== CONT TestFilterOversizedClosures/no_limit_keeps_everything237=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI238--- PASS: TestPathInfoHashCompatibility (0.00s)239 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)240 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)241 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)242 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)243=== CONT TestSetClientTLSErrors/missing_cert_file244=== PAUSE TestParsePathInfoJSON/empty_input245=== RUN TestParsePathInfoJSON/whitespace_only246=== PAUSE TestParsePathInfoJSON/whitespace_only247=== RUN TestParsePathInfoJSON/invalid_JSON248=== PAUSE TestParsePathInfoJSON/invalid_JSON249=== CONT TestSetClientTLSErrors/missing_ca_file250=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths251=== CONT TestUploadMultipart_SupersededByPeer/exists252=== CONT TestSetClientTLSErrors/missing_key_file253=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths254=== CONT TestSetClientTLSErrors/invalid_ca_file255=== PAUSE TestConvertHashToNix32/already_Nix32_format256=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA257--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)258=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2592026/10/01 07:33:56 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=2000260=== RUN TestConvertHashToNix32/invalid_format261=== PAUSE TestConvertHashToNix32/invalid_format262=== RUN TestEncodeNixBase32/empty_input263=== PAUSE TestEncodeNixBase32/empty_input264=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA265=== RUN TestSetClientTLS/preserves_debug_logging_transport266=== PAUSE TestSetClientTLS/preserves_debug_logging_transport267=== CONT TestPartSizeForNAR/5_TiB_S3_max_object268=== CONT TestPartSizeForNAR/1_TiB269=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts270=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum271=== CONT TestPartSizeForNAR/small_stays_at_minimum272=== CONT TestParsePathInfoJSON/Nix_format273=== CONT TestParsePathInfoJSON/invalid_JSON274=== CONT TestParsePathInfoJSON/empty_input275=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter276=== CONT TestParsePathInfoJSON/Lix_format277=== CONT TestConvertHashToNix32/SRI_format_to_Nix32278=== CONT TestParsePathInfoJSON/whitespace_only279=== CONT TestConvertHashToNix32/already_Nix32_format280=== CONT TestEncodeNixBase32/test_string_hash281=== CONT TestEncodeNixBase32/empty_input282=== CONT TestSetClientTLS/rejects_connection_without_client_cert283=== CONT TestRateLimiterFeedback/503_enables_limiter284=== CONT TestSetClientTLS/preserves_debug_logging_transport285=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA286=== PAUSE TestGetStorePathHash/valid_store_path287=== RUN TestGetStorePathHash/basename_without_hyphen_should_error288=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error289=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error290=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error291=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error292=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error293=== CONT TestGetStorePathHash/valid_store_path294=== CONT TestStreamPushReportsSignatures295=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error296=== CONT TestFilterOversizedClosures/all_closures_skipped297=== CONT TestUploadMultipart_SupersededByPeer/missing298=== CONT TestRateLimiterFeedback/429_enables_limiter2992026/10/01 07:33:56 WARN Rate limiter enabled after throttle name=server-test rate=5300=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3012026/10/01 07:33:56 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:39897302--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)303 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)304 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)3052026/10/01 07:33:56 ERROR Upload failed error=boom count=1306=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text307=== CONT TestPartSizeForNAR/zero_stays_at_minimum308=== CONT TestPartSizeForNAR/capped_at_5_GiB309=== CONT TestConvertHashToNix32/invalid_format310=== CONT TestGetStorePathHash/basename_without_hyphen_should_error311=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error312--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)3132026/10/01 07:33:56 WARN Rate limiter backed off name=server-test rate=53142026/10/01 07:33:56 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=50315=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive316=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive317=== RUN TestPathInfoCACompatibility/new_structured_format_-_text318=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text319=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method320=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method321=== CONT TestPathInfoCACompatibility/null_ca_field322=== CONT TestPathInfoCACompatibility/new_structured_format_-_text3232026/10/01 07:33:56 WARN Rate limiter enabled after throttle name=server-test rate=5324=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive3252026/10/01 07:33:56 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:40763326=== CONT TestPathInfoCACompatibility/old_string_format_-_text327--- PASS: TestFilterOversizedClosures (0.00s)328 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)329 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)330 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)3312026/10/01 07:33:56 WARN Rate limiter backed off name=server-test rate=5332=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method333--- PASS: TestEncodeNixBase32 (0.01s)334 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)335 --- PASS: TestEncodeNixBase32/empty_input (0.00s)336--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)337--- PASS: TestStreamPushReportsSignatures (0.00s)338--- PASS: TestSetClientTLSErrors (0.00s)339 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)340 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)341 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)342 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)343--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)344 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)345 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)346--- PASS: TestPartSizeForNAR (0.00s)347 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)348 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)349 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)350 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)351 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)352 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)353 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)354--- PASS: TestRateLimiterFeedback (0.00s)355 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)356 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)357 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)358 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)359--- PASS: TestGetStorePathHash (0.01s)360 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)361 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)362 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)363 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)364--- PASS: TestConvertHashToNix32 (0.01s)365 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)366 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)367 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)368--- PASS: TestParsePathInfoJSON (0.00s)369 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)370 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)371 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)372 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)373 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)374--- PASS: TestPathInfoCACompatibility (0.01s)375 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)376 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)377 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)378 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)379 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)3802026/10/01 07:33:56 http: TLS handshake error from 127.0.0.1:49634: remote error: tls: bad certificate381--- PASS: TestSetClientTLS (0.01s)382 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)383 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)384 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)385--- PASS: TestStreamPushRequestLine (0.02s)386--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)387--- PASS: TestCaseHackSuffix (0.03s)388--- PASS: TestDumpPathWriterError (0.03s)389--- PASS: TestDumpPathSingleFile (0.04s)390--- PASS: TestDumpPathMatchesNix (0.10s)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/postgres2490544738/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/postgres2490544738/data -l logfile start422423/build/postgres2490544738:5432 - no response4242026-10-01 07:33:58.319 UTC [130] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 07:33:58.320 UTC [130] LOG: listening on Unix socket "/build/postgres2490544738/.s.PGSQL.5432"4262026-10-01 07:33:58.325 UTC [137] LOG: database system was shut down at 2026-10-01 07:33:58 UTC4272026-10-01 07:33:58.332 UTC [130] LOG: database system is ready to accept connections428/build/postgres2490544738:5432 - accepting connections429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestClientPushesUseOnePush462=== PAUSE TestClientPushesUseOnePush463=== RUN TestClientFallsBackToClosures464=== PAUSE TestClientFallsBackToClosures465=== RUN TestResolveDBConnectionString466=== PAUSE TestResolveDBConnectionString467=== RUN TestLeadElectsOneAndHandsOver468=== PAUSE TestLeadElectsOneAndHandsOver469=== RUN TestLeadIncumbentWinsAfterRestart4702026-10-01 07:33:58.822 UTC [563] ERROR: relation "goose_db_version" does not exist at character 364712026-10-01 07:33:58.822 UTC [563] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4722026/10/01 07:33:58 OK 20241026095416_initial_model.sql (7.43ms)4732026/10/01 07:33:58 OK 20251210153512_drop_unused_gin_index.sql (1.65ms)4742026/10/01 07:33:58 OK 20251218171726_add_pins.sql (2.15ms)4752026/10/01 07:33:58 OK 20260628120000_add_object_size_and_stats.sql (2ms)4762026/10/01 07:33:58 OK 20260905000000_add_claims.sql (2.75ms)4772026/10/01 07:33:58 OK 20260920000000_drop_claims.sql (1.66ms)4782026/10/01 07:33:58 OK 20260923120000_add_pushes.sql (991.6µs)4792026/10/01 07:33:58 goose: successfully migrated database to version: 202609231200004802026/10/01 07:33:58 OK 1_commit_pending_closure.sql (1.33ms)4812026/10/01 07:33:58 OK 2_object_stats_trigger.sql (678.95µs)4822026/10/01 07:33:58 OK 3_commit_push.sql (592.32µs)4832026/10/01 07:33:58 goose: up to current file version: 34842026/10/01 07:33:58 INFO lead: acquired remote=192.0.2.1:12344852026/10/01 07:33:59 INFO lead: released remote=192.0.2.1:12344862026/10/01 07:33:59 INFO lead: acquired remote=192.0.2.1:12344872026/10/01 07:33:59 INFO lead: released remote=192.0.2.1:1234488--- PASS: TestLeadIncumbentWinsAfterRestart (0.80s)489=== RUN TestLeadEndsOnShutdown490=== PAUSE TestLeadEndsOnShutdown491=== RUN TestGCAdvisoryLockBlocksConcurrentRun4922026-10-01 07:33:59.590 UTC [573] ERROR: relation "goose_db_version" does not exist at character 364932026-10-01 07:33:59.590 UTC [573] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4942026/10/01 07:33:59 OK 20241026095416_initial_model.sql (6.41ms)4952026/10/01 07:33:59 OK 20251210153512_drop_unused_gin_index.sql (1.93ms)4962026/10/01 07:33:59 OK 20251218171726_add_pins.sql (2.36ms)4972026/10/01 07:33:59 OK 20260628120000_add_object_size_and_stats.sql (3.17ms)4982026/10/01 07:33:59 OK 20260905000000_add_claims.sql (2.31ms)4992026/10/01 07:33:59 OK 20260920000000_drop_claims.sql (1.35ms)5002026/10/01 07:33:59 OK 20260923120000_add_pushes.sql (1.13ms)5012026/10/01 07:33:59 goose: successfully migrated database to version: 202609231200005022026/10/01 07:33:59 OK 1_commit_pending_closure.sql (1.52ms)5032026/10/01 07:33:59 OK 2_object_stats_trigger.sql (797.66µs)5042026/10/01 07:33:59 OK 3_commit_push.sql (635.82µs)5052026/10/01 07:33:59 goose: up to current file version: 3506--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.13s)507=== RUN TestGCBugBareHashReferences508=== PAUSE TestGCBugBareHashReferences509=== RUN TestGCMetrics510=== PAUSE TestGCMetrics511=== RUN TestPushDedupSurvivesConcurrentGC512=== PAUSE TestPushDedupSurvivesConcurrentGC513=== RUN TestDeduplicatedObjectsRecordedAsPending514=== PAUSE TestDeduplicatedObjectsRecordedAsPending515=== RUN TestGCSweepSkipsPendingObjects516=== PAUSE TestGCSweepSkipsPendingObjects517=== RUN TestTombstonedObjectOfferedWithoutWaiting518=== PAUSE TestTombstonedObjectOfferedWithoutWaiting519=== RUN TestGCSweepDeliversEachKeyOnce520=== PAUSE TestGCSweepDeliversEachKeyOnce521=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection522=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== RUN TestFailedS3DeleteKeepsTombstone524=== PAUSE TestFailedS3DeleteKeepsTombstone525=== RUN TestSweepSkipsRowsLockedByPush526=== PAUSE TestSweepSkipsRowsLockedByPush527=== RUN TestRegisterCompletedObjectNeedsPendingRow528=== PAUSE TestRegisterCompletedObjectNeedsPendingRow529=== RUN TestGetExistingObjectsLocksRows530=== PAUSE TestGetExistingObjectsLocksRows531=== RUN TestGCTaskStore_StartNew532=== PAUSE TestGCTaskStore_StartNew533=== RUN TestGCTaskStore_DeduplicateSameParams534=== PAUSE TestGCTaskStore_DeduplicateSameParams535=== RUN TestGCTaskStore_ConflictDifferentParams536=== PAUSE TestGCTaskStore_ConflictDifferentParams537=== RUN TestGCTaskStore_GetEmpty538=== PAUSE TestGCTaskStore_GetEmpty539=== RUN TestGCTaskStore_GetReturnsLatest540=== PAUSE TestGCTaskStore_GetReturnsLatest541=== RUN TestGCTaskStore_CompletedAllowsNewTask542=== PAUSE TestGCTaskStore_CompletedAllowsNewTask543=== RUN TestGCTaskStore_PhaseUpdates544=== PAUSE TestGCTaskStore_PhaseUpdates545=== RUN TestGCTaskStore_Fail546=== PAUSE TestGCTaskStore_Fail547=== RUN TestGracefulShutdownDrainsInflight548=== PAUSE TestGracefulShutdownDrainsInflight549=== RUN TestService_healthCheckHandler550=== PAUSE TestService_healthCheckHandler551=== RUN TestService_readinessHandler552=== PAUSE TestService_readinessHandler553=== RUN TestGenerateLandingPage554=== PAUSE TestGenerateLandingPage555=== RUN TestCacheConfigHandlerMaxNarSize556=== PAUSE TestCacheConfigHandlerMaxNarSize557=== RUN TestCreatePendingClosureRejectsOversizedNAR558=== PAUSE TestCreatePendingClosureRejectsOversizedNAR559=== RUN TestNARDeduplicationMetadataUploadBug560=== PAUSE TestNARDeduplicationMetadataUploadBug561=== RUN TestMetricsInventory562=== PAUSE TestMetricsInventory563=== RUN TestService_NativeMTLS564=== PAUSE TestService_NativeMTLS565=== RUN TestServerTLSConfig566=== PAUSE TestServerTLSConfig567=== RUN TestMultipartCleanup568=== PAUSE TestMultipartCleanup569=== RUN TestObjectStatsTrigger570=== PAUSE TestObjectStatsTrigger571=== RUN TestOrphanedObjectsGC572=== PAUSE TestOrphanedObjectsGC573=== RUN TestOrphanedObjectsGCStressTest574=== PAUSE TestOrphanedObjectsGCStressTest575=== RUN TestCreatePin_ReservedPins576=== PAUSE TestCreatePin_ReservedPins577=== RUN TestParseSingleRange578=== PAUSE TestParseSingleRange579=== RUN TestProxyHeadersOnlyTrustedOnSocket580=== PAUSE TestProxyHeadersOnlyTrustedOnSocket581=== RUN TestIsValidCachePath582=== PAUSE TestIsValidCachePath583=== RUN TestReadProxyNarinfo584=== PAUSE TestReadProxyNarinfo585=== RUN TestReadProxyNarinfoAlreadyDecompressed586=== PAUSE TestReadProxyNarinfoAlreadyDecompressed587=== RUN TestReadProxyNarStreaming588=== PAUSE TestReadProxyNarStreaming589=== RUN TestReadProxy404590=== PAUSE TestReadProxy404591=== RUN TestReadProxyInvalidPath592=== PAUSE TestReadProxyInvalidPath593=== RUN TestReadProxyHead594=== PAUSE TestReadProxyHead595=== RUN TestReadProxyConditionalGet596=== PAUSE TestReadProxyConditionalGet597=== RUN TestReadProxyRootRedirectsToIndexHTML598=== PAUSE TestReadProxyRootRedirectsToIndexHTML599=== RUN TestReadProxyDisabled600=== PAUSE TestReadProxyDisabled601=== RUN TestReadRedirectNar602=== PAUSE TestReadRedirectNar603=== RUN TestReadRedirectKeepsNarinfoProxied604=== PAUSE TestReadRedirectKeepsNarinfoProxied605=== RUN TestReadProxyRangeRequest606=== PAUSE TestReadProxyRangeRequest607=== RUN TestReadRedirectUsesPublicS3URL608=== PAUSE TestReadRedirectUsesPublicS3URL609=== RUN TestPush_OverlappingRootsStoreOneRowPerKey610=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey611=== RUN TestPush_CompleteCommitsEveryRoot612=== PAUSE TestPush_CompleteCommitsEveryRoot613=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit614=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit615=== RUN TestPush_RejectsBadRequests616=== PAUSE TestPush_RejectsBadRequests617=== RUN TestPush_SignsNarinfosOfItsPendingObjects618=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects619=== RUN TestRedundantMultipartUpload620=== PAUSE TestRedundantMultipartUpload621=== RUN TestCompleteMultipartUpload_ErrorButObjectExists622=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists623=== RUN TestCompletedNarNotReofferedAcrossClosures624=== PAUSE TestCompletedNarNotReofferedAcrossClosures625=== RUN TestPresignedUploadRegisteredBeforeCommit626=== PAUSE TestPresignedUploadRegisteredBeforeCommit627=== RUN TestService_Rustfstest628=== PAUSE TestService_Rustfstest629=== RUN TestParseSize630=== PAUSE TestParseSize631=== RUN TestSkippedUploadsHandler632=== PAUSE TestSkippedUploadsHandler633=== RUN TestSystemdListenerNotActivated634--- PASS: TestSystemdListenerNotActivated (0.00s)635=== RUN TestWatchdogBeatsWhenHealthy636--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)637=== RUN TestWatchdogSkipsWhenUnhealthy6382026/10/01 07:33:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6392026/10/01 07:33:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6402026/10/01 07:33:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6412026/10/01 07:33:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6422026/10/01 07:33:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6432026/10/01 07:33:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6442026/10/01 07:33:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6452026/10/01 07:33:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6462026/10/01 07:33:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6472026/10/01 07:33:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"648--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)649=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle650=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle651=== RUN TestProxyWriteTimeout652=== PAUSE TestProxyWriteTimeout653=== RUN TestIsValidUploadKey654=== PAUSE TestIsValidUploadKey655=== RUN TestUploadHandlersRejectInvalidKeys656=== PAUSE TestUploadHandlersRejectInvalidKeys657=== RUN TestUploadHandlersRejectOversizedBody658=== PAUSE TestUploadHandlersRejectOversizedBody659=== RUN TestService_cleanupPendingClosuresHandler660=== PAUSE TestService_cleanupPendingClosuresHandler661=== RUN TestService_createPendingClosureHandler662=== PAUSE TestService_createPendingClosureHandler663=== RUN TestService_verifyS3Integrity664=== PAUSE TestService_verifyS3Integrity665=== RUN TestCompleteMultipartUnregistered666=== PAUSE TestCompleteMultipartUnregistered667=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT668=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT669=== CONT TestService_AuthMiddleware670=== CONT TestIsValidCachePath671=== RUN TestIsValidCachePath/narinfo672=== CONT TestFailedS3DeleteKeepsTombstone673=== CONT TestProxyHeadersOnlyTrustedOnSocket674=== CONT TestParseSingleRange675=== RUN TestParseSingleRange/none676=== PAUSE TestParseSingleRange/none677=== CONT TestCreatePin_ReservedPins678=== CONT TestOrphanedObjectsGCStressTest679=== CONT TestOrphanedObjectsGC680=== CONT TestObjectStatsTrigger681=== CONT TestMultipartCleanup682=== CONT TestServerTLSConfig683=== RUN TestServerTLSConfig/no_client_CA684=== PAUSE TestServerTLSConfig/no_client_CA685=== RUN TestServerTLSConfig/missing_CA_file686=== PAUSE TestServerTLSConfig/missing_CA_file687=== RUN TestServerTLSConfig/not_a_PEM_file688=== PAUSE TestServerTLSConfig/not_a_PEM_file689=== CONT TestService_NativeMTLS690=== CONT TestMetricsInventory691=== CONT TestNARDeduplicationMetadataUploadBug692=== CONT TestCreatePendingClosureRejectsOversizedNAR693=== CONT TestCacheConfigHandlerMaxNarSize694=== CONT TestGenerateLandingPage695=== CONT TestService_readinessHandler696=== CONT TestService_healthCheckHandler697=== CONT TestGracefulShutdownDrainsInflight698=== CONT TestGCTaskStore_Fail699=== CONT TestGCTaskStore_DeduplicateSameParams700=== CONT TestGCTaskStore_StartNew701=== CONT TestGetExistingObjectsLocksRows702=== PAUSE TestIsValidCachePath/narinfo703=== RUN TestParseSingleRange/unknown_unit704=== CONT TestRegisterCompletedObjectNeedsPendingRow7052026/10/01 07:33:59 INFO Received uploads request method=POST path=/api/pending_closures706--- PASS: TestGCTaskStore_Fail (0.00s)707=== CONT TestSweepSkipsRowsLockedByPush708--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)709=== CONT TestGCTaskStore_CompletedAllowsNewTask710--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)711=== CONT TestGCTaskStore_PhaseUpdates712--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)713=== CONT TestGCTaskStore_GetReturnsLatest714--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)715=== CONT TestGCTaskStore_GetEmpty716--- PASS: TestGCTaskStore_GetEmpty (0.00s)717=== CONT TestPush_SignsNarinfosOfItsPendingObjects718--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)719=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT720--- PASS: TestGCTaskStore_StartNew (0.00s)721=== CONT TestCompleteMultipartUnregistered722=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars723=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars724=== RUN TestIsValidCachePath/nar_zst725=== PAUSE TestIsValidCachePath/nar_zst726=== RUN TestIsValidCachePath/nar_xz727=== PAUSE TestIsValidCachePath/nar_xz728=== RUN TestIsValidCachePath/nar_bz2729=== PAUSE TestIsValidCachePath/nar_bz2730--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)731=== CONT TestGCTaskStore_ConflictDifferentParams732=== PAUSE TestParseSingleRange/unknown_unit7332026/10/01 07:33:59 INFO Starting HTTP server address=127.0.0.1:41127734=== RUN TestIsValidCachePath/nar_uncompressed735=== PAUSE TestIsValidCachePath/nar_uncompressed736=== RUN TestIsValidCachePath/ls737=== PAUSE TestIsValidCachePath/ls738=== RUN TestIsValidCachePath/log739=== PAUSE TestIsValidCachePath/log740=== RUN TestIsValidCachePath/realisation7412026/10/01 07:33:59 INFO Shutdown signal received, draining in-flight requests timeout=10s742=== PAUSE TestIsValidCachePath/realisation743=== RUN TestIsValidCachePath/nix-cache-info744--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)745=== CONT TestService_verifyS3Integrity746=== RUN TestParseSingleRange/multi-range_ignored747=== PAUSE TestIsValidCachePath/nix-cache-info748=== PAUSE TestParseSingleRange/multi-range_ignored749=== RUN TestIsValidCachePath/index.html750=== PAUSE TestIsValidCachePath/index.html751=== RUN TestIsValidCachePath/traversal_parent752--- PASS: TestGenerateLandingPage (0.00s)753=== RUN TestParseSingleRange/malformed_no_dash754=== PAUSE TestIsValidCachePath/traversal_parent755=== CONT TestService_createPendingClosureHandler756=== PAUSE TestParseSingleRange/malformed_no_dash757=== RUN TestParseSingleRange/malformed_both_empty758=== RUN TestIsValidCachePath/traversal_in_middle759=== PAUSE TestParseSingleRange/malformed_both_empty760=== PAUSE TestIsValidCachePath/traversal_in_middle761=== RUN TestParseSingleRange/malformed_end_before_start762=== PAUSE TestParseSingleRange/malformed_end_before_start763=== RUN TestParseSingleRange/closed764=== PAUSE TestParseSingleRange/closed765=== RUN TestParseSingleRange/open-ended766=== PAUSE TestParseSingleRange/open-ended767=== RUN TestParseSingleRange/end_clamped_to_size768=== PAUSE TestParseSingleRange/end_clamped_to_size769=== RUN TestParseSingleRange/suffix770=== PAUSE TestParseSingleRange/suffix771=== RUN TestParseSingleRange/suffix_exceeds_size772=== PAUSE TestParseSingleRange/suffix_exceeds_size773=== RUN TestIsValidCachePath/invalid_char_e774=== PAUSE TestIsValidCachePath/invalid_char_e775=== RUN TestIsValidCachePath/invalid_char_u776=== PAUSE TestIsValidCachePath/invalid_char_u777=== RUN TestIsValidCachePath/random_path778=== PAUSE TestIsValidCachePath/random_path779=== RUN TestIsValidCachePath/empty780=== RUN TestParseSingleRange/single_byte781=== PAUSE TestParseSingleRange/single_byte782=== PAUSE TestIsValidCachePath/empty783=== RUN TestParseSingleRange/start_past_EOF784=== PAUSE TestParseSingleRange/start_past_EOF785=== RUN TestParseSingleRange/start_far_past_EOF786=== PAUSE TestParseSingleRange/start_far_past_EOF787=== RUN TestIsValidCachePath/leading_slash788=== PAUSE TestIsValidCachePath/leading_slash789=== RUN TestIsValidCachePath/wrong_extension790=== PAUSE TestIsValidCachePath/wrong_extension791=== RUN TestIsValidCachePath/short_hash792=== PAUSE TestIsValidCachePath/short_hash793=== CONT TestService_cleanupPendingClosuresHandler794=== CONT TestUploadHandlersRejectOversizedBody7952026/10/01 07:33:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37729/oidc796--- PASS: TestGracefulShutdownDrainsInflight (0.11s)797=== CONT TestReadProxyDisabled798=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart799=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart800=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts801=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts802=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure803=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure804=== CONT TestUploadHandlersRejectInvalidKeys805=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info806=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info807=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal808=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal809=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key810=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key811=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key812=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key813=== CONT TestPush_RejectsBadRequests8142026-10-01 07:34:00.243 UTC [645] ERROR: relation "goose_db_version" does not exist at character 368152026-10-01 07:34:00.243 UTC [645] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8162026-10-01 07:34:00.381 UTC [646] ERROR: relation "goose_db_version" does not exist at character 368172026-10-01 07:34:00.381 UTC [646] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8182026-10-01 07:34:00.386 UTC [647] ERROR: relation "goose_db_version" does not exist at character 368192026-10-01 07:34:00.386 UTC [647] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8202026/10/01 07:34:00 OK 20241026095416_initial_model.sql (39.81ms)8212026-10-01 07:34:00.388 UTC [648] ERROR: relation "goose_db_version" does not exist at character 368222026-10-01 07:34:00.388 UTC [648] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8232026-10-01 07:34:00.392 UTC [649] ERROR: relation "goose_db_version" does not exist at character 368242026-10-01 07:34:00.392 UTC [649] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8252026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (17.21ms)8262026/10/01 07:34:00 OK 20251218171726_add_pins.sql (11.82ms)8272026-10-01 07:34:00.423 UTC [650] ERROR: relation "goose_db_version" does not exist at character 368282026-10-01 07:34:00.423 UTC [650] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8292026-10-01 07:34:00.428 UTC [651] ERROR: relation "goose_db_version" does not exist at character 368302026-10-01 07:34:00.428 UTC [651] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8312026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (11.8ms)8322026/10/01 07:34:00 OK 20241026095416_initial_model.sql (16.59ms)8332026/10/01 07:34:00 OK 20241026095416_initial_model.sql (15.13ms)8342026-10-01 07:34:00.441 UTC [652] ERROR: relation "goose_db_version" does not exist at character 368352026-10-01 07:34:00.441 UTC [652] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8362026-10-01 07:34:00.442 UTC [653] ERROR: relation "goose_db_version" does not exist at character 368372026-10-01 07:34:00.442 UTC [653] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8382026/10/01 07:34:00 OK 20260905000000_add_claims.sql (7.56ms)8392026/10/01 07:34:00 OK 20241026095416_initial_model.sql (19.2ms)8402026-10-01 07:34:00.450 UTC [654] ERROR: relation "goose_db_version" does not exist at character 368412026-10-01 07:34:00.450 UTC [654] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8422026-10-01 07:34:00.451 UTC [657] ERROR: relation "goose_db_version" does not exist at character 368432026-10-01 07:34:00.451 UTC [657] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8442026-10-01 07:34:00.451 UTC [656] ERROR: relation "goose_db_version" does not exist at character 368452026-10-01 07:34:00.451 UTC [656] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8462026-10-01 07:34:00.452 UTC [655] ERROR: relation "goose_db_version" does not exist at character 368472026-10-01 07:34:00.452 UTC [655] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8482026-10-01 07:34:00.457 UTC [658] ERROR: relation "goose_db_version" does not exist at character 368492026-10-01 07:34:00.457 UTC [658] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8502026/10/01 07:34:00 OK 20241026095416_initial_model.sql (27.64ms)8512026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (16.58ms)8522026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (15.86ms)8532026/10/01 07:34:00 OK 20241026095416_initial_model.sql (21.65ms)8542026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (16.81ms)8552026/10/01 07:34:00 OK 20241026095416_initial_model.sql (16.01ms)8562026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (17.19ms)8572026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (6.86ms)8582026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (6.85ms)8592026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200008602026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (3.93ms)8612026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (4.08ms)8622026/10/01 07:34:00 OK 20251218171726_add_pins.sql (8.7ms)8632026/10/01 07:34:00 OK 20251218171726_add_pins.sql (5.69ms)8642026/10/01 07:34:00 OK 20251218171726_add_pins.sql (6.62ms)8652026/10/01 07:34:00 OK 20251218171726_add_pins.sql (5.17ms)8662026/10/01 07:34:00 OK 20251218171726_add_pins.sql (4.69ms)8672026/10/01 07:34:00 OK 20251218171726_add_pins.sql (4.98ms)8682026/10/01 07:34:00 OK 1_commit_pending_closure.sql (5.09ms)8692026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (6.72ms)8702026-10-01 07:34:00.474 UTC [659] ERROR: relation "goose_db_version" does not exist at character 368712026-10-01 07:34:00.474 UTC [659] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8722026-10-01 07:34:00.474 UTC [661] ERROR: relation "goose_db_version" does not exist at character 368732026-10-01 07:34:00.474 UTC [661] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8742026/10/01 07:34:00 OK 2_object_stats_trigger.sql (3.73ms)8752026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (6.95ms)8762026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (6.39ms)8772026-10-01 07:34:00.476 UTC [660] ERROR: relation "goose_db_version" does not exist at character 368782026-10-01 07:34:00.476 UTC [660] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8792026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (7.78ms)8802026/10/01 07:34:00 OK 3_commit_push.sql (2.65ms)8812026/10/01 07:34:00 goose: up to current file version: 38822026/10/01 07:34:00 OK 20241026095416_initial_model.sql (14.64ms)8832026/10/01 07:34:00 OK 20241026095416_initial_model.sql (14.25ms)8842026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (6.87ms)8852026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (6.99ms)8862026/10/01 07:34:00 OK 20241026095416_initial_model.sql (14.82ms)8872026/10/01 07:34:00 OK 20260905000000_add_claims.sql (4.95ms)8882026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.52ms)8892026-10-01 07:34:00.479 UTC [662] ERROR: relation "goose_db_version" does not exist at character 368902026-10-01 07:34:00.479 UTC [662] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8912026/10/01 07:34:00 OK 20260905000000_add_claims.sql (4.54ms)8922026/10/01 07:34:00 OK 20260905000000_add_claims.sql (4.36ms)8932026/10/01 07:34:00 OK 20241026095416_initial_model.sql (13.09ms)8942026/10/01 07:34:00 OK 20241026095416_initial_model.sql (13.1ms)8952026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.8ms)8962026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.85ms)8972026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.03ms)8982026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.13ms)8992026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.56ms)9002026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (3.62ms)9012026/10/01 07:34:00 OK 20260905000000_add_claims.sql (4.62ms)9022026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.39ms)9032026/10/01 07:34:00 OK 20241026095416_initial_model.sql (13.52ms)9042026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.09ms)9052026-10-01 07:34:00.484 UTC [663] ERROR: relation "goose_db_version" does not exist at character 369062026-10-01 07:34:00.484 UTC [663] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9072026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.55ms)9082026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200009092026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (3.32ms)9102026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.5ms)9112026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200009122026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.36ms)9132026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.86ms)9142026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.97ms)9152026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.8ms)9162026/10/01 07:34:00 OK 20251218171726_add_pins.sql (4.63ms)9172026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.7ms)9182026/10/01 07:34:00 OK 20241026095416_initial_model.sql (12.62ms)9192026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.38ms)9202026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.73ms)9212026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200009222026/10/01 07:34:00 OK 1_commit_pending_closure.sql (3.24ms)9232026/10/01 07:34:00 OK 20251218171726_add_pins.sql (4.43ms)9242026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (3.1ms)9252026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200009262026/10/01 07:34:00 OK 1_commit_pending_closure.sql (3.42ms)9272026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.87ms)9282026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200009292026/10/01 07:34:00 OK 20251218171726_add_pins.sql (4.33ms)9302026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)9312026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.04ms)9322026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (3.37ms)9332026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200009342026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.87ms)9352026/10/01 07:34:00 OK 20251218171726_add_pins.sql (5.03ms)9362026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (5.14ms)9372026/10/01 07:34:00 OK 1_commit_pending_closure.sql (4.09ms)9382026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (5.3ms)9392026-10-01 07:34:00.492 UTC [664] ERROR: relation "goose_db_version" does not exist at character 369402026-10-01 07:34:00.492 UTC [664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9412026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (5.96ms)9422026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.9ms)9432026/10/01 07:34:00 OK 3_commit_push.sql (2.23ms)9442026/10/01 07:34:00 goose: up to current file version: 39452026/10/01 07:34:00 OK 1_commit_pending_closure.sql (4.11ms)9462026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.76ms)9472026/10/01 07:34:00 OK 3_commit_push.sql (1.78ms)9482026/10/01 07:34:00 goose: up to current file version: 39492026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.87ms)9502026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.95ms)9512026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.59ms)9522026-10-01 07:34:00.494 UTC [665] ERROR: relation "goose_db_version" does not exist at character 369532026-10-01 07:34:00.494 UTC [665] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9542026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.65ms)9552026/10/01 07:34:00 OK 20241026095416_initial_model.sql (11.96ms)9562026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (5.61ms)9572026-10-01 07:34:00.495 UTC [666] ERROR: relation "goose_db_version" does not exist at character 369582026-10-01 07:34:00.495 UTC [666] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9592026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.5ms)9602026/10/01 07:34:00 OK 3_commit_push.sql (1.97ms)9612026/10/01 07:34:00 goose: up to current file version: 39622026/10/01 07:34:00 OK 2_object_stats_trigger.sql (3.1ms)9632026/10/01 07:34:00 OK 20260905000000_add_claims.sql (4.04ms)9642026/10/01 07:34:00 OK 20260905000000_add_claims.sql (4.27ms)9652026/10/01 07:34:00 OK 20260905000000_add_claims.sql (4.15ms)9662026/10/01 07:34:00 OK 3_commit_push.sql (2.34ms)9672026/10/01 07:34:00 goose: up to current file version: 39682026/10/01 07:34:00 OK 20241026095416_initial_model.sql (11.35ms)9692026/10/01 07:34:00 OK 20241026095416_initial_model.sql (13.08ms)9702026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (5.5ms)9712026/10/01 07:34:00 OK 3_commit_push.sql (2.13ms)9722026/10/01 07:34:00 goose: up to current file version: 39732026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.97ms)9742026/10/01 07:34:00 OK 20260905000000_add_claims.sql (4.29ms)9752026/10/01 07:34:00 OK 3_commit_push.sql (1.8ms)9762026/10/01 07:34:00 goose: up to current file version: 39772026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.84ms)9782026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (5.32ms)9792026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.17ms)9802026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.13ms)9812026/10/01 07:34:00 OK 20241026095416_initial_model.sql (11.65ms)9822026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.77ms)9832026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.83ms)9842026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (4ms)9852026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.47ms)9862026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.06ms)9872026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.65ms)9882026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.27ms)9892026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200009902026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.76ms)9912026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.42ms)9922026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200009932026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.51ms)9942026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (1.98ms)9952026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200009962026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)9972026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.36ms)9982026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.06ms)9992026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.71ms)10002026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000010012026/10/01 07:34:00 OK 20241026095416_initial_model.sql (10.86ms)10022026/10/01 07:34:00 OK 20251218171726_add_pins.sql (4.47ms)10032026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (3.05ms)10042026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000010052026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.67ms)10062026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.46ms)10072026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.94ms)10082026/10/01 07:34:00 OK 1_commit_pending_closure.sql (3.27ms)10092026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.66ms)10102026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000010112026-10-01 07:34:00.506 UTC [667] ERROR: relation "goose_db_version" does not exist at character 3610122026-10-01 07:34:00.506 UTC [667] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10132026/10/01 07:34:00 OK 20251218171726_add_pins.sql (4.15ms)10142026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.36ms)10152026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.88ms)10162026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.81ms)10172026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.53ms)10182026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.25ms)10192026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000010202026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.39ms)10212026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.16ms)10222026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)10232026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.99ms)10242026/10/01 07:34:00 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket476018324/001/proxy.sock10252026/10/01 07:34:00 INFO Starting HTTP server address=127.0.0.1:3520510262026/10/01 07:34:00 OK 3_commit_push.sql (1.44ms)10272026/10/01 07:34:00 goose: up to current file version: 310282026/10/01 07:34:00 WARN mTLS auth: subject not in bound subjects subject="CN=someone"10292026/10/01 07:34:00 OK 1_commit_pending_closure.sql (3.47ms)10302026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.67ms)10312026/10/01 07:34:00 OK 3_commit_push.sql (1.8ms)10322026/10/01 07:34:00 goose: up to current file version: 310332026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.23ms)10342026/10/01 07:34:00 OK 3_commit_push.sql (1.88ms)10352026/10/01 07:34:00 goose: up to current file version: 310362026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (5.03ms)10372026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.19ms)10382026/10/01 07:34:00 INFO Shutdown signal received, draining in-flight requests timeout=10s10392026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.36ms)10402026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.74ms)10412026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.37ms)10422026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.25ms)10432026/10/01 07:34:00 OK 3_commit_push.sql (1.35ms)10442026/10/01 07:34:00 goose: up to current file version: 310452026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.21ms)1046--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.63s)1047=== CONT TestIsValidUploadKey1048=== RUN TestIsValidUploadKey/narinfo10492026/10/01 07:34:00 OK 3_commit_push.sql (1.97ms)1050=== PAUSE TestIsValidUploadKey/narinfo10512026/10/01 07:34:00 goose: up to current file version: 31052=== RUN TestIsValidUploadKey/nar_zst1053=== PAUSE TestIsValidUploadKey/nar_zst1054=== RUN TestIsValidUploadKey/nar_xz1055=== PAUSE TestIsValidUploadKey/nar_xz1056=== RUN TestIsValidUploadKey/nar_plain1057=== PAUSE TestIsValidUploadKey/nar_plain1058=== RUN TestIsValidUploadKey/listing1059=== PAUSE TestIsValidUploadKey/listing1060=== RUN TestIsValidUploadKey/build_log1061=== PAUSE TestIsValidUploadKey/build_log1062=== RUN TestIsValidUploadKey/build_log_home-manager_file1063=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1064=== RUN TestIsValidUploadKey/build_log_plus_in_name1065=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1066=== RUN TestIsValidUploadKey/build_log_question_mark1067=== PAUSE TestIsValidUploadKey/build_log_question_mark1068=== RUN TestIsValidUploadKey/build_log_equals1069=== PAUSE TestIsValidUploadKey/build_log_equals1070=== RUN TestIsValidUploadKey/realisation1071=== PAUSE TestIsValidUploadKey/realisation1072=== RUN TestIsValidUploadKey/realisation_plus_in_output1073=== PAUSE TestIsValidUploadKey/realisation_plus_in_output10742026/10/01 07:34:00 OK 3_commit_push.sql (1.97ms)1075=== RUN TestIsValidUploadKey/nix-cache-info10762026/10/01 07:34:00 goose: up to current file version: 31077=== PAUSE TestIsValidUploadKey/nix-cache-info1078=== RUN TestIsValidUploadKey/index.html10792026/10/01 07:34:00 OK 20241026095416_initial_model.sql (10.59ms)1080=== PAUSE TestIsValidUploadKey/index.html1081=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1082=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type10832026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.24ms)1084=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1085=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type10862026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.21ms)1087=== RUN TestIsValidUploadKey/listing_key,_narinfo_type10882026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.63ms)1089=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1090=== RUN TestIsValidUploadKey/traversal1091=== PAUSE TestIsValidUploadKey/traversal1092=== RUN TestIsValidUploadKey/traversal_nar1093=== PAUSE TestIsValidUploadKey/traversal_nar1094=== RUN TestIsValidUploadKey/absolute1095=== PAUSE TestIsValidUploadKey/absolute1096=== RUN TestIsValidUploadKey/empty_key1097=== PAUSE TestIsValidUploadKey/empty_key10982026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.86ms)1099=== RUN TestIsValidUploadKey/unknown_type1100=== PAUSE TestIsValidUploadKey/unknown_type11012026/10/01 07:34:00 OK 20241026095416_initial_model.sql (11.23ms)1102=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit11032026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.49ms)11042026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.02ms)11052026/10/01 07:34:00 OK 20241026095416_initial_model.sql (9.81ms)11062026/10/01 07:34:00 OK 3_commit_push.sql (1.41ms)11072026/10/01 07:34:00 goose: up to current file version: 311082026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (1.51ms)11092026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (1.68ms)11102026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000011112026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (1.91ms)11122026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000011132026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (1.78ms)11142026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (1.9ms)11152026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (1.27ms)11162026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.31ms)11172026/10/01 07:34:00 OK 20260905000000_add_claims.sql (2.87ms)11182026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.24ms)11192026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.29ms)11202026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000011212026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.95ms)11222026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.66ms)11232026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (1.94ms)11242026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000011252026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.25ms)11262026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.07ms)11272026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (1.92ms)11282026-10-01 07:34:00.520 UTC [668] ERROR: relation "goose_db_version" does not exist at character 3611292026-10-01 07:34:00.520 UTC [668] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11302026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.09ms)11312026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.1ms)11322026/10/01 07:34:00 OK 3_commit_push.sql (1.73ms)11332026/10/01 07:34:00 goose: up to current file version: 311342026/10/01 07:34:00 OK 1_commit_pending_closure.sql (3.05ms)11352026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.66ms)11362026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.02ms)11372026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000011382026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (3.33ms)11392026/10/01 07:34:00 OK 3_commit_push.sql (872.22µs)11402026/10/01 07:34:00 goose: up to current file version: 311412026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (2.96ms)11422026/10/01 07:34:00 OK 20241026095416_initial_model.sql (8.2ms)11432026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (3.44ms)11442026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.24ms)11452026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.09ms)11462026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.81ms)11472026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.43ms)11482026/10/01 07:34:00 OK 3_commit_push.sql (1.73ms)11492026/10/01 07:34:00 goose: up to current file version: 311502026/10/01 07:34:00 OK 3_commit_push.sql (1.62ms)11512026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.32ms)11522026/10/01 07:34:00 goose: up to current file version: 311532026/10/01 07:34:00 OK 20260905000000_add_claims.sql (2.75ms)11542026/10/01 07:34:00 OK 20260905000000_add_claims.sql (2.99ms)11552026/10/01 07:34:00 OK 2_object_stats_trigger.sql (946.57µs)11562026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.06ms)11572026/10/01 07:34:00 OK 3_commit_push.sql (1.91ms)11582026/10/01 07:34:00 goose: up to current file version: 311592026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.03ms)11602026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.83ms)11612026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.98ms)11622026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.11ms)11632026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000011642026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (1.68ms)11652026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000011662026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.42ms)11672026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000011682026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.02ms)11692026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (3.8ms)11702026/10/01 07:34:00 OK 1_commit_pending_closure.sql (1.79ms)11712026/10/01 07:34:00 OK 2_object_stats_trigger.sql (877.6µs)11722026/10/01 07:34:00 OK 1_commit_pending_closure.sql (1.92ms)11732026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.04ms)11742026/10/01 07:34:00 OK 3_commit_push.sql (578.79µs)11752026/10/01 07:34:00 goose: up to current file version: 311762026/10/01 07:34:00 OK 20260905000000_add_claims.sql (2.08ms)11772026/10/01 07:34:00 OK 3_commit_push.sql (673.83µs)11782026/10/01 07:34:00 goose: up to current file version: 311792026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.12ms)11802026/10/01 07:34:00 OK 3_commit_push.sql (981.77µs)11812026/10/01 07:34:00 goose: up to current file version: 311822026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (1.72ms)11832026/10/01 07:34:00 OK 20241026095416_initial_model.sql (10.15ms)11842026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (1.15ms)11852026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (1.39ms)11862026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000011872026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.29ms)11882026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.42ms)11892026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.67ms)11902026/10/01 07:34:00 OK 3_commit_push.sql (1.47ms)11912026/10/01 07:34:00 goose: up to current file version: 311922026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (3.56ms)11932026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.73ms)11942026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.31ms)11952026/10/01 07:34:00 INFO Received push request method=POST path=/api/pushes11962026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.61ms)11972026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000011982026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.8ms)11992026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.44ms)12002026/10/01 07:34:00 OK 3_commit_push.sql (1.48ms)12012026/10/01 07:34:00 goose: up to current file version: 312022026/10/01 07:34:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12032026/10/01 07:34:00 INFO Signed narinfos id=1 count=11204--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.68s)1205=== CONT TestProxyWriteTimeout1206=== RUN TestProxyWriteTimeout/narinfo1207=== PAUSE TestProxyWriteTimeout/narinfo1208=== RUN TestProxyWriteTimeout/1_GiB_nar1209=== PAUSE TestProxyWriteTimeout/1_GiB_nar1210=== RUN TestProxyWriteTimeout/10_GiB_nar1211=== PAUSE TestProxyWriteTimeout/10_GiB_nar1212=== RUN TestProxyWriteTimeout/unknown_size1213=== PAUSE TestProxyWriteTimeout/unknown_size1214=== CONT TestPush_CompleteCommitsEveryRoot1215--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.69s)1216=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle12172026/10/01 07:34:00 INFO Received uploads request method=POST path=/api/pending_closures12182026-10-01 07:34:00.624 UTC [681] ERROR: relation "goose_db_version" does not exist at character 3612192026-10-01 07:34:00.624 UTC [681] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12202026/10/01 07:34:00 INFO Received uploads request method=POST path=/api/pending_closures12212026/10/01 07:34:00 OK 20241026095416_initial_model.sql (9.14ms)12222026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (1.74ms)12232026/10/01 07:34:00 OK 20251218171726_add_pins.sql (2.62ms)12242026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (3.04ms)12252026/10/01 07:34:00 OK 20260905000000_add_claims.sql (2.82ms)12262026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (11.93ms)12272026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.12ms)12282026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000012292026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.28ms)12302026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.56ms)12312026/10/01 07:34:00 OK 3_commit_push.sql (727.14µs)12322026/10/01 07:34:00 goose: up to current file version: 31233--- PASS: TestObjectStatsTrigger (0.79s)1234=== CONT TestPush_OverlappingRootsStoreOneRowPerKey12352026/10/01 07:34:00 WARN readiness check failed error="closed pool"1236--- PASS: TestService_readinessHandler (0.79s)1237=== CONT TestSkippedUploadsHandler12382026/10/01 07:34:00 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001239--- PASS: TestSkippedUploadsHandler (0.01s)1240=== CONT TestReadRedirectUsesPublicS3URL12412026-10-01 07:34:00.689 UTC [684] ERROR: relation "goose_db_version" does not exist at character 3612422026-10-01 07:34:00.689 UTC [684] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12432026-10-01 07:34:00.689 UTC [683] ERROR: relation "goose_db_version" does not exist at character 3612442026-10-01 07:34:00.689 UTC [683] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12452026/10/01 07:34:00 INFO Aborted multipart uploads count=012462026/10/01 07:34:00 WARN Force mode enabled - objects will be deleted immediately without grace period12472026/10/01 07:34:00 OK 20241026095416_initial_model.sql (7.67ms)12482026/10/01 07:34:00 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."12492026/10/01 07:34:00 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12502026/10/01 07:34:00 OK 20241026095416_initial_model.sql (8.24ms)12512026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)12522026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)1253--- PASS: TestFailedS3DeleteKeepsTombstone (0.82s)12542026/10/01 07:34:00 OK 20251218171726_add_pins.sql (2.86ms)1255=== CONT TestParseSize1256--- PASS: TestParseSize (0.00s)1257=== CONT TestReadProxyRangeRequest12582026/10/01 07:34:00 OK 20251218171726_add_pins.sql (2.77ms)12592026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (3.54ms)12602026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)12612026/10/01 07:34:00 OK 20260905000000_add_claims.sql (2.95ms)12622026/10/01 07:34:00 OK 20260905000000_add_claims.sql (2.64ms)1263--- PASS: TestGetExistingObjectsLocksRows (0.82s)1264=== CONT TestService_Rustfstest12652026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (1.83ms)12662026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.06ms)12672026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.48ms)12682026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000012692026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.51ms)12702026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000012712026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.46ms)12722026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.82ms)12732026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.92ms)12742026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.48ms)12752026/10/01 07:34:00 OK 3_commit_push.sql (1.54ms)12762026/10/01 07:34:00 goose: up to current file version: 312772026/10/01 07:34:00 OK 3_commit_push.sql (1.61ms)12782026/10/01 07:34:00 goose: up to current file version: 312792026/10/01 07:34:00 INFO Received cleanup request method=DELETE path=/api/pending_closures12802026/10/01 07:34:00 INFO Aborted multipart uploads count=11281--- PASS: TestMultipartCleanup (0.88s)1282=== CONT TestReadRedirectKeepsNarinfoProxied1283--- PASS: TestMetricsInventory (0.88s)1284=== CONT TestPresignedUploadRegisteredBeforeCommit12852026/10/01 07:34:00 INFO Received uploads request method=POST path=/api/pending_closures12862026/10/01 07:34:00 INFO Aborted multipart uploads count=012872026-10-01 07:34:00.785 UTC [700] ERROR: relation "goose_db_version" does not exist at character 3612882026-10-01 07:34:00.785 UTC [700] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12892026/10/01 07:34:00 WARN Force mode enabled - objects will be deleted immediately without grace period1290--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.90s)1291=== CONT TestReadRedirectNar12922026/10/01 07:34:00 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=01293--- PASS: TestService_healthCheckHandler (0.90s)1294=== CONT TestCompletedNarNotReofferedAcrossClosures12952026/10/01 07:34:00 INFO Vacuumed table table=pending_closures12962026/10/01 07:34:00 INFO Vacuumed table table=pending_objects12972026/10/01 07:34:00 INFO Vacuumed table table=multipart_uploads12982026/10/01 07:34:00 INFO Vacuumed table table=closures12992026/10/01 07:34:00 INFO Vacuumed table table=objects13002026-10-01 07:34:00.799 UTC [704] ERROR: relation "goose_db_version" does not exist at character 3613012026-10-01 07:34:00.799 UTC [704] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13022026/10/01 07:34:00 OK 20241026095416_initial_model.sql (10.12ms)13032026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.17ms)13042026/10/01 07:34:00 INFO Aborted multipart uploads count=013052026/10/01 07:34:00 WARN Force mode enabled - objects will be deleted immediately without grace period13062026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.04ms)13072026/10/01 07:34:00 INFO Received uploads request method=POST path=/api/pending_closures13082026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.49ms)13092026/10/01 07:34:00 OK 20241026095416_initial_model.sql (8.49ms)13102026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)13112026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.83ms)13122026/10/01 07:34:00 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=013132026/10/01 07:34:00 INFO Vacuumed table table=pending_closures13142026/10/01 07:34:00 INFO Vacuumed table table=pending_objects13152026/10/01 07:34:00 INFO Vacuumed table table=multipart_uploads13162026/10/01 07:34:00 INFO Vacuumed table table=closures13172026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.81ms)13182026/10/01 07:34:00 OK 20251218171726_add_pins.sql (5.09ms)13192026/10/01 07:34:00 INFO Vacuumed table table=objects13202026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (1.9ms)13212026/10/01 07:34:00 goose: successfully migrated database to version: 202609231200001322--- PASS: TestSweepSkipsRowsLockedByPush (0.93s)1323=== CONT TestCompleteMultipartUpload_ErrorButObjectExists13242026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)13252026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.68ms)13262026-10-01 07:34:00.827 UTC [706] ERROR: relation "goose_db_version" does not exist at character 3613272026-10-01 07:34:00.827 UTC [706] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13282026-10-01 07:34:00.831 UTC [708] ERROR: relation "goose_db_version" does not exist at character 3613292026-10-01 07:34:00.831 UTC [708] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1330--- PASS: TestReadProxyDisabled (0.83s)1331=== CONT TestRedundantMultipartUpload13322026/10/01 07:34:00 OK 2_object_stats_trigger.sql (17.44ms)13332026/10/01 07:34:00 OK 20260905000000_add_claims.sql (18.76ms)13342026/10/01 07:34:00 OK 3_commit_push.sql (1.62ms)13352026/10/01 07:34:00 goose: up to current file version: 313362026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.95ms)13372026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (3.52ms)13382026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000013392026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.83ms)13402026/10/01 07:34:00 OK 20241026095416_initial_model.sql (11.24ms)13412026/10/01 07:34:00 OK 20241026095416_initial_model.sql (11.23ms)13422026/10/01 07:34:00 INFO Received cleanup request method=DELETE path=/api/pending_closures13432026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.93ms)13442026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.77ms)13452026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)13462026/10/01 07:34:00 OK 3_commit_push.sql (2.16ms)13472026/10/01 07:34:00 goose: up to current file version: 313482026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.71ms)13492026/10/01 07:34:00 INFO Aborted multipart uploads count=013502026/10/01 07:34:00 OK 20251218171726_add_pins.sql (5.35ms)13512026/10/01 07:34:00 INFO Received uploads request method=POST path=/api/pending_closures13522026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)13532026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.34ms)13542026/10/01 07:34:00 OK 20260905000000_add_claims.sql (4.62ms)13552026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.72ms)13562026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.99ms)13572026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.07ms)13582026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.62ms)13592026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000013602026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.3ms)13612026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000013622026/10/01 07:34:00 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1363--- PASS: TestService_AuthMiddleware (0.99s)13642026-10-01 07:34:00.879 UTC [712] ERROR: relation "goose_db_version" does not exist at character 3613652026-10-01 07:34:00.879 UTC [712] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13662026/10/01 07:34:00 INFO Received cleanup request method=DELETE path=/api/pending_closures1367=== CONT TestGCMetrics13682026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.77ms)13692026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.98ms)13702026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.8ms)13712026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.07ms)13722026/10/01 07:34:00 OK 3_commit_push.sql (2.31ms)13732026/10/01 07:34:00 goose: up to current file version: 313742026/10/01 07:34:00 INFO Aborted multipart uploads count=113752026/10/01 07:34:00 OK 3_commit_push.sql (2.46ms)13762026/10/01 07:34:00 goose: up to current file version: 313772026-10-01 07:34:00.889 UTC [713] ERROR: relation "goose_db_version" does not exist at character 3613782026-10-01 07:34:00.889 UTC [713] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13792026/10/01 07:34:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13802026-10-01 07:34:00.890 UTC [659] ERROR: Closure does not exist: id=113812026-10-01 07:34:00.890 UTC [659] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE13822026-10-01 07:34:00.890 UTC [659] STATEMENT: -- name: CommitPendingClosure :exec1383 SELECT commit_pending_closure($1::bigint)1384 1385--- PASS: TestService_cleanupPendingClosuresHandler (0.99s)1386=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection13872026/10/01 07:34:00 INFO Received uploads request method=POST path=/api/pending_closures13882026/10/01 07:34:00 INFO Received uploads request method=POST path=/api/pending_closures13892026/10/01 07:34:00 INFO Received uploads request method=POST path=/api/pending_closures13902026/10/01 07:34:00 OK 20241026095416_initial_model.sql (17.64ms)13912026/10/01 07:34:00 OK 20241026095416_initial_model.sql (11.48ms)13922026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (4.72ms)13932026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.6ms)13942026/10/01 07:34:00 OK 20251218171726_add_pins.sql (2.87ms)13952026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.68ms)13962026-10-01 07:34:00.913 UTC [718] ERROR: relation "goose_db_version" does not exist at character 3613972026-10-01 07:34:00.913 UTC [718] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13982026-10-01 07:34:00.916 UTC [719] ERROR: relation "goose_db_version" does not exist at character 3613992026-10-01 07:34:00.916 UTC [719] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14002026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (5ms)14012026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.69ms)14022026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.66ms)14032026/10/01 07:34:00 OK 20260905000000_add_claims.sql (4.69ms)14042026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.49ms)14052026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.4ms)14062026/10/01 07:34:00 WARN mTLS auth: subject not in bound subjects subject="CN=reader"14072026/10/01 07:34:00 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1408--- PASS: TestService_NativeMTLS (1.03s)1409=== CONT TestPinProtectsFromGC14102026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.72ms)14112026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000014122026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (3.86ms)14132026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000014142026/10/01 07:34:00 OK 20241026095416_initial_model.sql (9.77ms)14152026/10/01 07:34:00 OK 1_commit_pending_closure.sql (3.39ms)14162026/10/01 07:34:00 OK 1_commit_pending_closure.sql (1.97ms)14172026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)14182026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.17ms)14192026/10/01 07:34:00 OK 20241026095416_initial_model.sql (8.9ms)14202026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.19ms)14212026/10/01 07:34:00 OK 3_commit_push.sql (1.56ms)14222026/10/01 07:34:00 goose: up to current file version: 314232026/10/01 07:34:00 OK 3_commit_push.sql (1.83ms)14242026/10/01 07:34:00 goose: up to current file version: 314252026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.2ms)14262026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.69ms)14272026-10-01 07:34:00.937 UTC [721] ERROR: relation "goose_db_version" does not exist at character 3614282026-10-01 07:34:00.937 UTC [721] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14292026/10/01 07:34:00 OK 20251218171726_add_pins.sql (7.19ms)14302026-10-01 07:34:00.942 UTC [723] ERROR: relation "goose_db_version" does not exist at character 3614312026-10-01 07:34:00.942 UTC [723] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14322026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (7.47ms)14332026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.13ms)14342026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.47ms)14352026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.55ms)14362026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.36ms)14372026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.77ms)14382026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000014392026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (2.5ms)14402026/10/01 07:34:00 OK 20241026095416_initial_model.sql (9.37ms)14412026/10/01 07:34:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14422026/10/01 07:34:00 OK 1_commit_pending_closure.sql (2.89ms)14432026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (2.43ms)14442026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (3.65ms)14452026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000014462026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.17ms)1447=== NAME TestOrphanedObjectsGC1448 orphaned_objects_gc_test.go:290: GC Test Summary:1449 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1450 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1451 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)14522026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.16ms)1453 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1454 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects14552026/10/01 07:34:00 OK 20241026095416_initial_model.sql (11.21ms)1456--- PASS: TestOrphanedObjectsGC (1.07s)1457=== CONT TestGCSweepDeliversEachKeyOnce14582026/10/01 07:34:00 OK 3_commit_push.sql (2.24ms)14592026/10/01 07:34:00 goose: up to current file version: 314602026/10/01 07:34:00 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1461--- PASS: TestCompleteMultipartUnregistered (1.07s)1462=== CONT TestTombstonedObjectOfferedWithoutWaiting14632026/10/01 07:34:00 OK 1_commit_pending_closure.sql (3.06ms)14642026/10/01 07:34:00 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)14652026/10/01 07:34:00 OK 2_object_stats_trigger.sql (1.64ms)14662026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (4.32ms)14672026/10/01 07:34:00 OK 20251218171726_add_pins.sql (3.44ms)14682026/10/01 07:34:00 OK 3_commit_push.sql (2.93ms)14692026/10/01 07:34:00 goose: up to current file version: 314702026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.52ms)14712026/10/01 07:34:00 OK 20260628120000_add_object_size_and_stats.sql (5.21ms)14722026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.39ms)14732026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (2.24ms)14742026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000014752026/10/01 07:34:00 OK 20260905000000_add_claims.sql (3.83ms)14762026/10/01 07:34:00 OK 1_commit_pending_closure.sql (3.83ms)14772026/10/01 07:34:00 OK 20260920000000_drop_claims.sql (3.98ms)14782026/10/01 07:34:00 OK 2_object_stats_trigger.sql (2.76ms)14792026/10/01 07:34:00 OK 20260923120000_add_pushes.sql (4.46ms)14802026/10/01 07:34:00 goose: successfully migrated database to version: 2026092312000014812026/10/01 07:34:00 OK 3_commit_push.sql (9.44ms)14822026/10/01 07:34:00 goose: up to current file version: 314832026-10-01 07:34:00.993 UTC [740] ERROR: relation "goose_db_version" does not exist at character 3614842026-10-01 07:34:00.993 UTC [740] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14852026/10/01 07:34:01 OK 1_commit_pending_closure.sql (33.32ms)14862026/10/01 07:34:01 OK 2_object_stats_trigger.sql (3.73ms)14872026/10/01 07:34:01 OK 3_commit_push.sql (1.1ms)14882026/10/01 07:34:01 goose: up to current file version: 31489=== NAME TestNARDeduplicationMetadataUploadBug1490 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug787576620/001/store/38hvwy3zfzm9n9gn8ss2qjf52jgawwbf-file1.txt14912026/10/01 07:34:01 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14922026/10/01 07:34:01 WARN Refused reserved pin name=worker-x86_64-linux14932026/10/01 07:34:01 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14942026/10/01 07:34:01 INFO Received create pin request method=POST path=/api/pins/my-app14952026/10/01 07:34:01 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux14962026/10/01 07:34:01 OK 20241026095416_initial_model.sql (9.06ms)1497--- PASS: TestCreatePin_ReservedPins (1.14s)1498=== CONT TestGCBugBareHashReferences14992026-10-01 07:34:01.030 UTC [757] ERROR: relation "goose_db_version" does not exist at character 3615002026-10-01 07:34:01.030 UTC [757] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15012026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.61ms)15022026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.67ms)15032026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.36ms)1504=== RUN TestPush_RejectsBadRequests/bad_root1505=== PAUSE TestPush_RejectsBadRequests/bad_root1506=== RUN TestPush_RejectsBadRequests/root_not_in_objects1507=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1508=== RUN TestPush_RejectsBadRequests/no_roots1509=== PAUSE TestPush_RejectsBadRequests/no_roots1510=== RUN TestPush_RejectsBadRequests/no_objects1511=== PAUSE TestPush_RejectsBadRequests/no_objects1512=== CONT TestGCSweepSkipsPendingObjects15132026/10/01 07:34:01 OK 20260905000000_add_claims.sql (4.22ms)15142026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.63ms)15152026/10/01 07:34:01 OK 20241026095416_initial_model.sql (10.63ms)15162026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (3.98ms)15172026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000015182026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)15192026/10/01 07:34:01 OK 1_commit_pending_closure.sql (3ms)15202026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.71ms)15212026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.09ms)15222026/10/01 07:34:01 OK 3_commit_push.sql (1.95ms)15232026/10/01 07:34:01 goose: up to current file version: 315242026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.78ms)15252026-10-01 07:34:01.057 UTC [763] ERROR: relation "goose_db_version" does not exist at character 3615262026-10-01 07:34:01.057 UTC [763] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15272026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes15282026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.78ms)15292026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.62ms)15302026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.61ms)15312026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000015322026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.58ms)15332026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.86ms)15342026/10/01 07:34:01 OK 3_commit_push.sql (2.14ms)15352026/10/01 07:34:01 goose: up to current file version: 315362026/10/01 07:34:01 OK 20241026095416_initial_model.sql (10.17ms)15372026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)15382026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures15392026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.11ms)15402026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/1/complete15412026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.48ms)15422026-10-01 07:34:01.085 UTC [782] ERROR: relation "goose_db_version" does not exist at character 3615432026-10-01 07:34:01.085 UTC [782] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15442026-10-01 07:34:01.086 UTC [783] ERROR: relation "goose_db_version" does not exist at character 3615452026-10-01 07:34:01.086 UTC [783] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15462026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.02ms)15472026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.16ms)15482026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes15492026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.01ms)15502026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000015512026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.67ms)15522026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.24ms)15532026/10/01 07:34:01 OK 3_commit_push.sql (2.98ms)15542026/10/01 07:34:01 goose: up to current file version: 315552026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes15562026/10/01 07:34:01 OK 20241026095416_initial_model.sql (18.5ms)15572026/10/01 07:34:01 OK 20241026095416_initial_model.sql (19.51ms)15582026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (4.01ms)15592026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)15602026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes15612026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.18ms)15622026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.16ms)15632026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes15642026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)15652026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (4.09ms)15662026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.41ms)15672026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.21ms)15682026/10/01 07:34:01 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15692026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.81ms)15702026/10/01 07:34:01 INFO Uploading 38hvwy3zfzm9n9gn8ss2qjf52jgawwbf-file1.txt (160B)15712026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.25ms)15722026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/1/complete15732026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (1.35ms)15742026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000015752026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (1.41ms)15762026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000015772026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.31ms)15782026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.81ms)15792026/10/01 07:34:01 OK 2_object_stats_trigger.sql (829.84µs)15802026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.08ms)15812026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"15822026/10/01 07:34:01 OK 3_commit_push.sql (708.57µs)15832026/10/01 07:34:01 goose: up to current file version: 315842026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15852026/10/01 07:34:01 WARN Failed to register uploaded object key=38hvwy3zfzm9n9gn8ss2qjf52jgawwbf.ls error="server returned 404: 404 page not found\n"15862026/10/01 07:34:01 OK 3_commit_push.sql (1.01ms)15872026/10/01 07:34:01 goose: up to current file version: 315882026/10/01 07:34:01 INFO Signed narinfos id=1 count=115892026/10/01 07:34:01 INFO Uploading 1 narinfos1590--- PASS: TestPush_CompleteCommitsEveryRoot (0.56s)1591=== CONT TestLeadEndsOnShutdown15922026-10-01 07:34:01.137 UTC [804] ERROR: relation "goose_db_version" does not exist at character 3615932026-10-01 07:34:01.137 UTC [804] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15942026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/1/complete15952026/10/01 07:34:01 WARN Failed to register uploaded object key=38hvwy3zfzm9n9gn8ss2qjf52jgawwbf.narinfo error="server returned 404: 404 page not found\n"15962026-10-01 07:34:01.147 UTC [810] ERROR: relation "goose_db_version" does not exist at character 3615972026-10-01 07:34:01.147 UTC [810] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1598--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.47s)1599=== CONT TestDeduplicatedObjectsRecordedAsPending16002026/10/01 07:34:01 INFO Upload complete. (77ms)16012026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.32ms)16022026/10/01 07:34:01 INFO Aborted multipart uploads count=01603=== NAME TestNARDeduplicationMetadataUploadBug1604 metadata_upload_test.go:54: Retrieved narinfo from S3:1605 StorePath: /build/TestNARDeduplicationMetadataUploadBug787576620/001/store/38hvwy3zfzm9n9gn8ss2qjf52jgawwbf-file1.txt16062026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.61ms)1607 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1608 Compression: zstd1609 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1610 NarSize: 1601611 References: 1612 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf16132026/10/01 07:34:01 WARN Force mode enabled - objects will be deleted immediately without grace period1614 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1615 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1616 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}16172026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.67ms)1618--- PASS: TestReadRedirectUsesPublicS3URL (0.47s)1619=== CONT TestLeadElectsOneAndHandsOver16202026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.56ms)1621--- PASS: TestService_Rustfstest (0.45s)1622=== CONT TestResolveDBConnectionString1623=== RUN TestResolveDBConnectionString/flag_wins1624=== PAUSE TestResolveDBConnectionString/flag_wins16252026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.57ms)1626=== RUN TestResolveDBConnectionString/file_when_flag_empty1627=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1628=== RUN TestResolveDBConnectionString/missing_file_is_an_error1629=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error16302026/10/01 07:34:01 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=01631=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1632=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1633=== RUN TestResolveDBConnectionString/nothing_configured1634=== PAUSE TestResolveDBConnectionString/nothing_configured1635=== CONT TestClientFallsBackToClosures16362026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.15ms)16372026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.56ms)16382026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.43ms)16392026/10/01 07:34:01 INFO Vacuumed table table=pending_closures16402026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.91ms)16412026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (1.99ms)16422026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000016432026/10/01 07:34:01 INFO Vacuumed table table=pending_objects16442026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.41ms)16452026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (4.47ms)16462026/10/01 07:34:01 INFO Vacuumed table table=multipart_uploads16472026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.17ms)16482026/10/01 07:34:01 OK 3_commit_push.sql (2.05ms)16492026/10/01 07:34:01 goose: up to current file version: 316502026/10/01 07:34:01 OK 20260905000000_add_claims.sql (4.22ms)16512026/10/01 07:34:01 INFO Vacuumed table table=closures16522026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.17ms)16532026/10/01 07:34:01 INFO Vacuumed table table=objects16542026/10/01 07:34:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16552026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/2/complete16562026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.57ms)16572026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000016582026/10/01 07:34:01 OK 1_commit_pending_closure.sql (3.86ms)1659--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.67s)1660=== CONT TestPushDedupSurvivesConcurrentGC16612026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.67ms)16622026/10/01 07:34:01 OK 3_commit_push.sql (1.36ms)16632026/10/01 07:34:01 goose: up to current file version: 31664--- PASS: TestReadProxyRangeRequest (0.48s)1665=== CONT TestCacheStatsHandler1666=== NAME TestNARDeduplicationMetadataUploadBug1667 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug787576620/001/store/ss56sgcjhcp0srbq71zkviifa25aphb7-file2.txt1668--- PASS: TestReadRedirectKeepsNarinfoProxied (0.44s)1669=== CONT TestClientPushesUseOnePush16702026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures16712026/10/01 07:34:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16722026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures16732026-10-01 07:34:01.257 UTC [876] ERROR: relation "goose_db_version" does not exist at character 3616742026-10-01 07:34:01.257 UTC [876] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16752026/10/01 07:34:01 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst16762026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures16772026/10/01 07:34:01 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MzI0ZDkxMzMtZDk2ZS00YzQ2LWI1NDctMzkzY2RlNzEzNTM4LmU3Y2NiNzNmLTgxYmEtNDk2MS04YWVmLWE2MzA2NDJkMjIwNngxNzkwODQwMDQwODIxODg5Njk5 parts=1016782026/10/01 07:34:01 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1679--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.49s)1680=== CONT TestClientSharedPathCommittedMidPush16812026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes16822026/10/01 07:34:01 INFO Completed upload id=11683--- PASS: TestReadRedirectNar (0.48s)1684=== CONT TestClientWithDependencies16852026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures16862026/10/01 07:34:01 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16872026-10-01 07:34:01.270 UTC [895] ERROR: relation "goose_db_version" does not exist at character 3616882026-10-01 07:34:01.270 UTC [895] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16892026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures16902026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16912026/10/01 07:34:01 WARN Failed to register uploaded object key=ss56sgcjhcp0srbq71zkviifa25aphb7.ls error="server returned 404: 404 page not found\n"16922026/10/01 07:34:01 INFO Signed narinfos id=2 count=116932026/10/01 07:34:01 INFO Uploading 1 narinfos16942026/10/01 07:34:01 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo16952026/10/01 07:34:01 WARN Found objects in DB but missing from S3, will re-upload count=116962026/10/01 07:34:01 OK 20241026095416_initial_model.sql (12.42ms)1697--- PASS: TestService_verifyS3Integrity (1.38s)1698=== CONT TestReadProxyConditionalGet16992026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/2/complete17002026/10/01 07:34:01 WARN Failed to register uploaded object key=ss56sgcjhcp0srbq71zkviifa25aphb7.narinfo error="server returned 404: 404 page not found\n"17012026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.64ms)17022026-10-01 07:34:01.280 UTC [899] ERROR: relation "goose_db_version" does not exist at character 3617032026-10-01 07:34:01.280 UTC [899] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17042026/10/01 07:34:01 INFO Upload complete. (53ms)1705=== NAME TestNARDeduplicationMetadataUploadBug17062026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.39ms)1707 metadata_upload_test.go:76: Retrieved narinfo from S3:1708 StorePath: /build/TestNARDeduplicationMetadataUploadBug787576620/001/store/ss56sgcjhcp0srbq71zkviifa25aphb7-file2.txt1709 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1710 Compression: zstd1711 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1712 NarSize: 1601713 References: 1714 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf17152026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures1716 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1717 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1718 {"version":1,"root":{"type":"regular","size":44}}17192026-10-01 07:34:01.287 UTC [902] ERROR: relation "goose_db_version" does not exist at character 3617202026-10-01 07:34:01.287 UTC [902] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1721--- PASS: TestNARDeduplicationMetadataUploadBug (1.40s)1722=== CONT TestClientMultipleUploads17232026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (19.6ms)17242026/10/01 07:34:01 OK 20241026095416_initial_model.sql (25.63ms)17252026/10/01 07:34:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17262026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (3.38ms)17272026/10/01 07:34:01 OK 20260905000000_add_claims.sql (4.92ms)17282026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures17292026/10/01 07:34:01 OK 20251218171726_add_pins.sql (5.51ms)17302026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (5.16ms)17312026/10/01 07:34:01 OK 20241026095416_initial_model.sql (10.25ms)17322026/10/01 07:34:01 OK 20241026095416_initial_model.sql (11.6ms)17332026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.71ms)17342026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (5.87ms)17352026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (3.24ms)17362026-10-01 07:34:01.317 UTC [905] ERROR: relation "goose_db_version" does not exist at character 3617372026-10-01 07:34:01.317 UTC [905] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17382026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (5.03ms)17392026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000017402026/10/01 07:34:01 OK 20251218171726_add_pins.sql (5.7ms)17412026-10-01 07:34:01.322 UTC [906] ERROR: relation "goose_db_version" does not exist at character 3617422026-10-01 07:34:01.322 UTC [906] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17432026/10/01 07:34:01 OK 20260905000000_add_claims.sql (5.52ms)17442026/10/01 07:34:01 OK 1_commit_pending_closure.sql (4.9ms)17452026/10/01 07:34:01 OK 20251218171726_add_pins.sql (5.33ms)17462026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.59ms)17472026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (4.23ms)17482026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (3.57ms)17492026/10/01 07:34:01 OK 3_commit_push.sql (2.38ms)17502026/10/01 07:34:01 goose: up to current file version: 317512026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (5.03ms)17522026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.83ms)17532026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000017542026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.67ms)17552026/10/01 07:34:01 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MzI0ZDkxMzMtZDk2ZS00YzQ2LWI1NDctMzkzY2RlNzEzNTM4LmE0OWE2ZDM4LTBmYzEtNDFlYy1hZWYwLTdlMjE0OTQ1MDMzN3gxNzkwODQwMDQwOTExMzc3NjI2 parts=1017562026/10/01 07:34:01 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17572026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.63ms)17582026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures17592026/10/01 07:34:01 OK 1_commit_pending_closure.sql (3.5ms)17602026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (4.03ms)17612026/10/01 07:34:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17622026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (3.39ms)17632026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.66ms)17642026/10/01 07:34:01 OK 20241026095416_initial_model.sql (10.97ms)17652026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (3.05ms)17662026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000017672026/10/01 07:34:01 INFO Completed upload id=117682026/10/01 07:34:01 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzI0ZDkxMzMtZDk2ZS00YzQ2LWI1NDctMzkzY2RlNzEzNTM4LjAxNzNlNWQzLWM0YzEtNDI5Ni1iYjM4LWJiYzA5YjFhNGFhN3gxNzkwODQwMDQxMzA1MTI1MzU217692026/10/01 07:34:01 OK 3_commit_push.sql (1.86ms)17702026/10/01 07:34:01 goose: up to current file version: 317712026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.45ms)17722026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000017732026/10/01 07:34:01 OK 20241026095416_initial_model.sql (9.6ms)17742026/10/01 07:34:01 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000017752026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.8ms)17762026/10/01 07:34:01 OK 1_commit_pending_closure.sql (3.18ms)17772026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)17782026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures17792026/10/01 07:34:01 OK 1_commit_pending_closure.sql (3.18ms)17802026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.09ms)17812026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.02ms)17822026/10/01 07:34:01 OK 2_object_stats_trigger.sql (3.17ms)17832026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.33ms)17842026/10/01 07:34:01 INFO Starting cleanup of old closures method=DELETE path=/api/closures17852026/10/01 07:34:01 OK 3_commit_push.sql (1.87ms)17862026/10/01 07:34:01 goose: up to current file version: 317872026/10/01 07:34:01 OK 3_commit_push.sql (1.97ms)17882026/10/01 07:34:01 goose: up to current file version: 317892026/10/01 07:34:01 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzI0ZDkxMzMtZDk2ZS00YzQ2LWI1NDctMzkzY2RlNzEzNTM4LjAxNzNlNWQzLWM0YzEtNDI5Ni1iYjM4LWJiYzA5YjFhNGFhN3gxNzkwODQwMDQxMzA1MTI1MzU2 parts=117902026/10/01 07:34:01 INFO Aborted multipart uploads count=01791--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.52s)1792=== CONT TestReadProxyRootRedirectsToIndexHTML17932026-10-01 07:34:01.347 UTC [908] ERROR: relation "goose_db_version" does not exist at character 3617942026-10-01 07:34:01.347 UTC [908] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17952026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (4.46ms)17962026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.73ms)17972026/10/01 07:34:01 WARN Force mode enabled - objects will be deleted immediately without grace period17982026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.56ms)17992026/10/01 07:34:01 OK 20260905000000_add_claims.sql (2.76ms)18002026/10/01 07:34:01 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=018012026/10/01 07:34:01 INFO Vacuumed table table=pending_closures18022026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.81ms)18032026/10/01 07:34:01 INFO Vacuumed table table=pending_objects18042026/10/01 07:34:01 INFO Vacuumed table table=multipart_uploads18052026/10/01 07:34:01 INFO Vacuumed table table=closures18062026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (3.2ms)18072026/10/01 07:34:01 INFO Vacuumed table table=objects18082026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.62ms)18092026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000018102026/10/01 07:34:01 INFO Aborted multipart uploads count=01811--- PASS: TestGCMetrics (0.48s)1812=== CONT TestClientIntegration18132026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (11.18ms)18142026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000018152026/10/01 07:34:01 OK 1_commit_pending_closure.sql (13.41ms)18162026/10/01 07:34:01 OK 20241026095416_initial_model.sql (17.45ms)18172026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures18182026/10/01 07:34:01 OK 1_commit_pending_closure.sql (5.03ms)18192026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.38ms)18202026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.13ms)18212026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.93ms)18222026/10/01 07:34:01 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=018232026/10/01 07:34:01 OK 3_commit_push.sql (1.84ms)18242026/10/01 07:34:01 goose: up to current file version: 318252026/10/01 07:34:01 OK 3_commit_push.sql (1.84ms)18262026/10/01 07:34:01 goose: up to current file version: 318272026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.92ms)18282026/10/01 07:34:01 INFO Vacuumed table table=pending_closures18292026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (4.7ms)18302026/10/01 07:34:01 INFO Vacuumed table table=pending_objects18312026-10-01 07:34:01.384 UTC [914] ERROR: relation "goose_db_version" does not exist at character 3618322026-10-01 07:34:01.384 UTC [914] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18332026-10-01 07:34:01.384 UTC [915] ERROR: relation "goose_db_version" does not exist at character 3618342026-10-01 07:34:01.384 UTC [915] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18352026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.33ms)18362026/10/01 07:34:01 INFO Vacuumed table table=multipart_uploads18372026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (3.35ms)18382026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (1.42ms)18392026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000018402026/10/01 07:34:01 INFO Vacuumed table table=closures18412026-10-01 07:34:01.393 UTC [916] ERROR: relation "goose_db_version" does not exist at character 3618422026-10-01 07:34:01.393 UTC [916] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18432026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.31ms)18442026/10/01 07:34:01 INFO Vacuumed table table=objects18452026/10/01 07:34:01 OK 2_object_stats_trigger.sql (847.13µs)18462026/10/01 07:34:01 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001847--- PASS: TestService_createPendingClosureHandler (1.50s)1848=== CONT TestClientErrorHandling1849=== RUN TestClientErrorHandling/InvalidStorePath1850=== PAUSE TestClientErrorHandling/InvalidStorePath1851=== RUN TestClientErrorHandling/InvalidAuthToken1852=== PAUSE TestClientErrorHandling/InvalidAuthToken1853=== RUN TestClientErrorHandling/ServerNotAvailable1854=== PAUSE TestClientErrorHandling/ServerNotAvailable1855=== CONT TestReadProxyInvalidPath18562026/10/01 07:34:01 OK 3_commit_push.sql (1.31ms)18572026/10/01 07:34:01 goose: up to current file version: 318582026-10-01 07:34:01.401 UTC [918] ERROR: relation "goose_db_version" does not exist at character 3618592026-10-01 07:34:01.401 UTC [918] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18602026/10/01 07:34:01 OK 20241026095416_initial_model.sql (9.5ms)18612026/10/01 07:34:01 OK 20241026095416_initial_model.sql (9.45ms)18622026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)18632026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.7ms)18642026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.9ms)18652026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.91ms)18662026/10/01 07:34:01 OK 20241026095416_initial_model.sql (9.02ms)18672026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.11ms)18682026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.07ms)18692026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.19ms)18702026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.04ms)18712026/10/01 07:34:01 OK 20260905000000_add_claims.sql (4.09ms)18722026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.91ms)18732026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.83ms)18742026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.68ms)18752026/10/01 07:34:01 OK 20241026095416_initial_model.sql (9.13ms)18762026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.67ms)18772026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.95ms)18782026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000018792026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.66ms)18802026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.9ms)18812026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000018822026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.52ms)18832026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.65ms)18842026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.5ms)18852026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.71ms)18862026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.08ms)18872026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.95ms)18882026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.84ms)18892026/10/01 07:34:01 OK 3_commit_push.sql (2.04ms)18902026/10/01 07:34:01 goose: up to current file version: 318912026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.53ms)18922026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000018932026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.92ms)18942026/10/01 07:34:01 OK 3_commit_push.sql (1.94ms)18952026/10/01 07:34:01 goose: up to current file version: 318962026/10/01 07:34:01 OK 1_commit_pending_closure.sql (3.78ms)18972026/10/01 07:34:01 OK 20260905000000_add_claims.sql (4.77ms)18982026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.13ms)18992026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.53ms)19002026/10/01 07:34:01 OK 3_commit_push.sql (1.71ms)19012026/10/01 07:34:01 goose: up to current file version: 319022026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures19032026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.36ms)19042026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000019052026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.36ms)19062026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.38ms)19072026/10/01 07:34:01 OK 3_commit_push.sql (1.24ms)19082026/10/01 07:34:01 goose: up to current file version: 319092026/10/01 07:34:01 INFO Aborted multipart uploads count=01910--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.48s)1911=== CONT TestReadProxyNarStreaming19122026/10/01 07:34:01 WARN Force mode enabled - objects will be deleted immediately without grace period1913=== NAME TestPinProtectsFromGC1914 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC3879863284/001/store/4scjwxflqpmp40lhiayqvyjlirixhk3s-pinned-file.txt1915 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC3879863284/001/store/x3zbkpvshvq7s169v7l1pl1hdaalsija-unpinned-file.txt19162026/10/01 07:34:01 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=019172026/10/01 07:34:01 INFO Vacuumed table table=pending_closures19182026/10/01 07:34:01 INFO Vacuumed table table=pending_objects19192026/10/01 07:34:01 INFO Vacuumed table table=multipart_uploads19202026/10/01 07:34:01 INFO Vacuumed table table=closures19212026/10/01 07:34:01 INFO Vacuumed table table=objects1922--- PASS: TestGCSweepDeliversEachKeyOnce (0.52s)1923=== CONT TestReadProxyHead19242026-10-01 07:34:01.477 UTC [958] ERROR: relation "goose_db_version" does not exist at character 3619252026-10-01 07:34:01.477 UTC [958] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19262026-10-01 07:34:01.478 UTC [959] ERROR: relation "goose_db_version" does not exist at character 3619272026-10-01 07:34:01.478 UTC [959] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19282026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures19292026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.7ms)19302026/10/01 07:34:01 OK 20241026095416_initial_model.sql (9ms)19312026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.05ms)19322026-10-01 07:34:01.493 UTC [962] ERROR: relation "goose_db_version" does not exist at character 3619332026-10-01 07:34:01.493 UTC [962] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19342026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)19352026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.76ms)19362026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.14ms)19372026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.32ms)19382026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3ms)19392026/10/01 07:34:01 INFO lead: acquired remote=192.0.2.1:123419402026/10/01 07:34:01 INFO lead: released remote=192.0.2.1:12341941--- PASS: TestLeadEndsOnShutdown (0.36s)1942=== CONT TestService_AuthMiddleware_OIDC19432026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.46ms)19442026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.77ms)19452026/10/01 07:34:01 OK 20241026095416_initial_model.sql (7.82ms)19462026/10/01 07:34:01 INFO Aborted multipart uploads count=019472026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.76ms)19482026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (1.92ms)19492026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.55ms)19502026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (1.82ms)19512026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000019522026/10/01 07:34:01 WARN Force mode enabled - objects will be deleted immediately without grace period19532026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.01ms)19542026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000019552026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.26ms)19562026/10/01 07:34:01 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=019572026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.64ms)19582026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.91ms)19592026/10/01 07:34:01 OK 20251218171726_add_pins.sql (4.73ms)19602026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.96ms)19612026/10/01 07:34:01 OK 3_commit_push.sql (1.64ms)19622026/10/01 07:34:01 goose: up to current file version: 319632026/10/01 07:34:01 OK 3_commit_push.sql (1.61ms)19642026/10/01 07:34:01 goose: up to current file version: 319652026/10/01 07:34:01 INFO Vacuumed table table=pending_closures19662026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (4.34ms)19672026/10/01 07:34:01 INFO Vacuumed table table=pending_objects19682026/10/01 07:34:01 INFO Vacuumed table table=multipart_uploads19692026/10/01 07:34:01 INFO Vacuumed table table=closures19702026/10/01 07:34:01 OK 20260905000000_add_claims.sql (2.92ms)19712026/10/01 07:34:01 INFO Vacuumed table table=objects19722026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.18ms)19732026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.05ms)19742026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000019752026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures19762026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.9ms)19772026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.31ms)1978--- PASS: TestGCSweepSkipsPendingObjects (0.49s)1979=== CONT TestReadProxy40419802026/10/01 07:34:01 OK 3_commit_push.sql (2.05ms)19812026/10/01 07:34:01 goose: up to current file version: 31982--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.38s)1983=== CONT TestCacheConfigHandler1984=== RUN TestCacheConfigHandler/full_config,_no_issuer1985=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1986=== RUN TestCacheConfigHandler/no_cache_url_configured1987=== PAUSE TestCacheConfigHandler/no_cache_url_configured1988=== RUN TestCacheConfigHandler/no_signing_keys1989=== PAUSE TestCacheConfigHandler/no_signing_keys1990=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1991=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1992=== CONT TestService_ReadScope_PublicByDefault19932026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes19942026/10/01 07:34:01 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19952026/10/01 07:34:01 INFO Uploading 4scjwxflqpmp40lhiayqvyjlirixhk3s-pinned-file.txt (128B)19962026-10-01 07:34:01.554 UTC [1003] ERROR: relation "goose_db_version" does not exist at character 3619972026-10-01 07:34:01.554 UTC [1003] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19982026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"19992026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20002026/10/01 07:34:01 WARN Failed to register uploaded object key=4scjwxflqpmp40lhiayqvyjlirixhk3s.ls error="server returned 404: 404 page not found\n"20012026/10/01 07:34:01 INFO Signed narinfos id=1 count=120022026/10/01 07:34:01 INFO Uploading 1 narinfos20032026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/1/complete20042026/10/01 07:34:01 WARN Failed to register uploaded object key=4scjwxflqpmp40lhiayqvyjlirixhk3s.narinfo error="server returned 404: 404 page not found\n"20052026/10/01 07:34:01 OK 20241026095416_initial_model.sql (9.08ms)20062026/10/01 07:34:01 INFO lead: acquired remote=192.0.2.1:123420072026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.88ms)20082026/10/01 07:34:01 INFO Upload complete. (69ms)20092026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.24ms)2010--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.69s)2011=== CONT TestService_AuthMiddleware_MTLSBoundSubjects20122026-10-01 07:34:01.578 UTC [1005] ERROR: relation "goose_db_version" does not exist at character 3620132026-10-01 07:34:01.578 UTC [1005] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20142026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (4.32ms)20152026/10/01 07:34:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46653/oidc20162026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.13ms)20172026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (1.95ms)20182026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (16.37ms)20192026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000020202026/10/01 07:34:01 OK 20241026095416_initial_model.sql (17.86ms)20212026/10/01 07:34:01 OK 1_commit_pending_closure.sql (3.31ms)20222026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (3.23ms)20232026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2ms)20242026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.06ms)20252026/10/01 07:34:01 OK 3_commit_push.sql (2.03ms)20262026/10/01 07:34:01 goose: up to current file version: 320272026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.56ms)20282026/10/01 07:34:01 OK 20260905000000_add_claims.sql (2.36ms)20292026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.42ms)20302026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (1.57ms)20312026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000020322026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.1ms)20332026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.84ms)20342026-10-01 07:34:01.623 UTC [1047] ERROR: relation "goose_db_version" does not exist at character 3620352026-10-01 07:34:01.623 UTC [1047] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20362026/10/01 07:34:01 OK 3_commit_push.sql (1.21ms)20372026/10/01 07:34:01 goose: up to current file version: 320382026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures20392026-10-01 07:34:01.629 UTC [1064] ERROR: relation "goose_db_version" does not exist at character 3620402026-10-01 07:34:01.629 UTC [1064] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2041--- PASS: TestCacheStatsHandler (0.44s)2042=== CONT TestService_RequireScope_OIDC20432026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.7ms)20442026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.44ms)20452026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.92ms)20462026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.68ms)20472026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.67ms)20482026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.48ms)20492026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.41ms)20502026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.31ms)20512026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.02ms)20522026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes20532026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.47ms)20542026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.37ms)20552026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000020562026/10/01 07:34:01 OK 20260905000000_add_claims.sql (2.93ms)20572026/10/01 07:34:01 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20582026/10/01 07:34:01 INFO Uploading x3zbkpvshvq7s169v7l1pl1hdaalsija-unpinned-file.txt (128B)20592026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.3ms)20602026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (3.18ms)20612026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.06ms)20622026/10/01 07:34:01 OK 3_commit_push.sql (2.02ms)20632026/10/01 07:34:01 goose: up to current file version: 320642026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.62ms)20652026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000020662026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"20672026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20682026/10/01 07:34:01 WARN Failed to register uploaded object key=x3zbkpvshvq7s169v7l1pl1hdaalsija.ls error="server returned 404: 404 page not found\n"20692026/10/01 07:34:01 INFO Signed narinfos id=2 count=120702026/10/01 07:34:01 INFO Uploading 1 narinfos20712026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.29ms)20722026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.21ms)20732026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/2/complete20742026/10/01 07:34:01 WARN Failed to register uploaded object key=x3zbkpvshvq7s169v7l1pl1hdaalsija.narinfo error="server returned 404: 404 page not found\n"20752026/10/01 07:34:01 OK 3_commit_push.sql (1.5ms)20762026/10/01 07:34:01 goose: up to current file version: 320772026/10/01 07:34:01 INFO Upload complete. (60ms)20782026-10-01 07:34:01.694 UTC [1119] ERROR: relation "goose_db_version" does not exist at character 3620792026-10-01 07:34:01.694 UTC [1119] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20802026-10-01 07:34:01.694 UTC [1120] ERROR: relation "goose_db_version" does not exist at character 3620812026-10-01 07:34:01.694 UTC [1120] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20822026/10/01 07:34:01 INFO Aborted multipart uploads count=020832026/10/01 07:34:01 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=020842026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.22ms)20852026/10/01 07:34:01 INFO Received create pin request method=POST path=/api/pins/myapp20862026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.94ms)20872026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.13ms)20882026/10/01 07:34:01 INFO Vacuumed table table=pending_closures20892026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.24ms)20902026/10/01 07:34:01 INFO Vacuumed table table=pending_objects20912026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.32ms)20922026/10/01 07:34:01 INFO Vacuumed table table=multipart_uploads20932026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.11ms)20942026/10/01 07:34:01 INFO Vacuumed table table=closures20952026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (2.88ms)2096--- PASS: TestGCBugBareHashReferences (0.68s)2097=== CONT TestService_ReadAuthMiddleware20982026/10/01 07:34:01 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3879863284/001/store/4scjwxflqpmp40lhiayqvyjlirixhk3s-pinned-file.txt narinfo_key=4scjwxflqpmp40lhiayqvyjlirixhk3s.narinfo20992026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.37ms)2100--- PASS: TestReadProxyConditionalGet (0.44s)21012026/10/01 07:34:01 INFO Vacuumed table table=objects2102=== CONT TestService_AuthMiddleware_MTLSProxyHeader21032026/10/01 07:34:01 INFO Starting cleanup of old closures method=DELETE path=/api/closures21042026/10/01 07:34:01 INFO Garbage collection started21052026/10/01 07:34:01 OK 20260905000000_add_claims.sql (2.57ms)21062026/10/01 07:34:01 OK 20260905000000_add_claims.sql (2.45ms)21072026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (1.98ms)21082026/10/01 07:34:01 INFO Aborted multipart uploads count=021092026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (1.8ms)21102026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (1.11ms)21112026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000021122026/10/01 07:34:01 WARN Force mode enabled - objects will be deleted immediately without grace period21132026/10/01 07:34:01 INFO lead: released remote=192.0.2.1:123421142026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (1.02ms)21152026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000021162026/10/01 07:34:01 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=021172026/10/01 07:34:01 OK 1_commit_pending_closure.sql (1.51ms)21182026/10/01 07:34:01 OK 1_commit_pending_closure.sql (1.58ms)21192026/10/01 07:34:01 OK 2_object_stats_trigger.sql (909.66µs)21202026/10/01 07:34:01 INFO Vacuumed table table=pending_closures21212026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.2ms)21222026/10/01 07:34:01 OK 3_commit_push.sql (903.36µs)21232026/10/01 07:34:01 goose: up to current file version: 321242026/10/01 07:34:01 INFO Vacuumed table table=pending_objects21252026/10/01 07:34:01 OK 3_commit_push.sql (715.5µs)21262026/10/01 07:34:01 goose: up to current file version: 321272026/10/01 07:34:01 INFO Vacuumed table table=multipart_uploads21282026/10/01 07:34:01 INFO Aborted multipart uploads count=021292026/10/01 07:34:01 INFO Vacuumed table table=closures21302026/10/01 07:34:01 WARN Force mode enabled - objects will be deleted immediately without grace period21312026/10/01 07:34:01 INFO Vacuumed table table=objects2132--- PASS: TestPushDedupSurvivesConcurrentGC (0.54s)2133=== CONT TestReadProxyNarinfoAlreadyDecompressed21342026/10/01 07:34:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44315/oidc21352026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures21362026/10/01 07:34:01 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=02137=== NAME TestClientWithDependencies2138 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies2635129860/001/store/595x9davpm0qk82vg950j22pi9d7k01h-test-script2139--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.41s)2140=== CONT TestClientCADerivations21412026/10/01 07:34:01 INFO Vacuumed table table=pending_closures21422026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures21432026/10/01 07:34:01 INFO Vacuumed table table=pending_objects21442026/10/01 07:34:01 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)21452026/10/01 07:34:01 INFO Uploading mzrg28wj5blsana7szgfp9jpp797qhdp-a (216B)21462026/10/01 07:34:01 INFO Uploading 3zgj9svf3rnlals8b1zn4a0c6wg9sjhf-shared-dep (136B)21472026/10/01 07:34:01 INFO Vacuumed table table=multipart_uploads21482026/10/01 07:34:01 WARN Failed to register uploaded object key=cm08dgkhkpv4mp2k1925vy7sk12kfclk.ls error="server returned 404: 404 page not found\n"21492026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/1skybil3i8wpky73aq4rmj79b1rkqv2h23dd9rqfxrppd56gxcql.nar.zst error="server returned 404: 404 page not found\n"21502026/10/01 07:34:01 WARN Failed to register uploaded object key=3zgj9svf3rnlals8b1zn4a0c6wg9sjhf.ls error="server returned 404: 404 page not found\n"21512026/10/01 07:34:01 WARN Failed to register uploaded object key=mzrg28wj5blsana7szgfp9jpp797qhdp.ls error="server returned 404: 404 page not found\n"21522026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"21532026/10/01 07:34:01 INFO Vacuumed table table=closures21542026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign21552026/10/01 07:34:01 INFO lead: acquired remote=192.0.2.1:123421562026/10/01 07:34:01 INFO Signed narinfos id=1 count=221572026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign21582026/10/01 07:34:01 INFO Signed narinfos id=2 count=221592026/10/01 07:34:01 INFO Uploading 4 narinfos21602026/10/01 07:34:01 INFO Vacuumed table table=objects21612026/10/01 07:34:01 WARN Failed to register uploaded object key=3zgj9svf3rnlals8b1zn4a0c6wg9sjhf.narinfo error="server returned 404: 404 page not found\n"21622026/10/01 07:34:01 WARN Failed to register uploaded object key=mzrg28wj5blsana7szgfp9jpp797qhdp.narinfo error="server returned 404: 404 page not found\n"2163=== NAME TestClientMultipleUploads21642026/10/01 07:34:01 WARN Failed to register uploaded object key=cm08dgkhkpv4mp2k1925vy7sk12kfclk.narinfo error="server returned 404: 404 page not found\n"2165 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads196097424/001/store/mdz7wm3amki5sqmgmblshb3rbnjn5gyi-test-file-0.txt21662026/10/01 07:34:01 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21672026/10/01 07:34:01 WARN Failed to register uploaded object key=3zgj9svf3rnlals8b1zn4a0c6wg9sjhf.narinfo error="server returned 404: 404 page not found\n"21682026/10/01 07:34:01 INFO lead: released remote=192.0.2.1:12342169--- PASS: TestLeadElectsOneAndHandsOver (0.63s)2170=== CONT TestReadProxyNarinfo21712026/10/01 07:34:01 INFO Completed upload id=121722026/10/01 07:34:01 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete2173=== NAME TestClientWithDependencies2174 client_integration_test.go:615: Found 1 dependencies (including self)21752026/10/01 07:34:01 INFO Completed upload id=221762026/10/01 07:34:01 INFO Upload complete. (80ms)2177=== NAME TestClientFallsBackToClosures2178 client_pushes_test.go:112: Retrieved narinfo from S3:2179 StorePath: /build/TestClientFallsBackToClosures373787176/001/store/3zgj9svf3rnlals8b1zn4a0c6wg9sjhf-shared-dep2180 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2181 Compression: zstd2182 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822183 NarSize: 1362184 References: 2185 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2186--- PASS: TestReadProxyInvalidPath (0.40s)2187=== CONT TestServerTLSConfig/no_client_CA2188=== NAME TestClientFallsBackToClosures2189 client_pushes_test.go:112: Retrieved narinfo from S3:2190 StorePath: /build/TestClientFallsBackToClosures373787176/001/store/mzrg28wj5blsana7szgfp9jpp797qhdp-a2191 URL: nar/1skybil3i8wpky73aq4rmj79b1rkqv2h23dd9rqfxrppd56gxcql.nar.zst2192 Compression: zstd21932026/10/01 07:34:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2194 NarHash: sha256:1skybil3i8wpky73aq4rmj79b1rkqv2h23dd9rqfxrppd56gxcql2195 NarSize: 2162196 References: /build/TestClientFallsBackToClosures373787176/001/store/3zgj9svf3rnlals8b1zn4a0c6wg9sjhf-shared-dep2197 CA: text:sha256:0anid3lkav3kw8ki4dsjrqa6j22c1s6n3r0jcfhfdnkvpjn4s8cz2198=== CONT TestServerTLSConfig/not_a_PEM_file2199=== CONT TestServerTLSConfig/missing_CA_file2200=== CONT TestParseSingleRange/none2201=== CONT TestParseSingleRange/open-ended2202=== CONT TestParseSingleRange/end_clamped_to_size2203=== CONT TestParseSingleRange/closed2204=== CONT TestParseSingleRange/malformed_end_before_start2205=== CONT TestParseSingleRange/malformed_both_empty2206=== CONT TestParseSingleRange/malformed_no_dash2207=== CONT TestParseSingleRange/multi-range_ignored2208=== CONT TestParseSingleRange/unknown_unit2209=== CONT TestParseSingleRange/start_far_past_EOF2210=== CONT TestParseSingleRange/single_byte2211=== CONT TestParseSingleRange/start_past_EOF2212=== CONT TestParseSingleRange/suffix2213=== CONT TestParseSingleRange/suffix_exceeds_size2214=== CONT TestIsValidCachePath/narinfo2215--- PASS: TestServerTLSConfig (0.00s)2216 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2217 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2218 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2219=== CONT TestIsValidCachePath/index.html2220=== CONT TestIsValidCachePath/short_hash2221=== CONT TestIsValidCachePath/wrong_extension2222=== CONT TestIsValidCachePath/leading_slash2223=== CONT TestIsValidCachePath/nix-cache-info2224=== CONT TestIsValidCachePath/realisation2225=== CONT TestIsValidCachePath/empty2226=== CONT TestIsValidCachePath/random_path2227=== CONT TestIsValidCachePath/invalid_char_u2228=== CONT TestIsValidCachePath/log2229=== CONT TestIsValidCachePath/invalid_char_e2230=== CONT TestIsValidCachePath/traversal_in_middle2231=== CONT TestIsValidCachePath/ls2232=== CONT TestIsValidCachePath/traversal_parent2233--- PASS: TestParseSingleRange (0.01s)2234 --- PASS: TestParseSingleRange/none (0.00s)2235 --- PASS: TestParseSingleRange/open-ended (0.00s)2236 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2237 --- PASS: TestParseSingleRange/closed (0.00s)2238 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2239 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2240 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2241 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2242 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2243 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2244 --- PASS: TestParseSingleRange/single_byte (0.00s)2245 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2246 --- PASS: TestParseSingleRange/suffix (0.00s)2247 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2248=== NAME TestClientFallsBackToClosures2249 client_pushes_test.go:112: Retrieved narinfo from S3:2250=== CONT TestIsValidCachePath/nar_uncompressed2251=== CONT TestIsValidCachePath/nar_zst2252=== CONT TestIsValidCachePath/nar_xz2253=== NAME TestClientFallsBackToClosures2254 StorePath: /build/TestClientFallsBackToClosures373787176/001/store/cm08dgkhkpv4mp2k1925vy7sk12kfclk-b2255 URL: nar/1skybil3i8wpky73aq4rmj79b1rkqv2h23dd9rqfxrppd56gxcql.nar.zst2256 Compression: zstd2257 NarHash: sha256:1skybil3i8wpky73aq4rmj79b1rkqv2h23dd9rqfxrppd56gxcql2258 NarSize: 2162259 References: /build/TestClientFallsBackToClosures373787176/001/store/3zgj9svf3rnlals8b1zn4a0c6wg9sjhf-shared-dep2260 CA: text:sha256:0anid3lkav3kw8ki4dsjrqa6j22c1s6n3r0jcfhfdnkvpjn4s8cz2261=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2262=== CONT TestIsValidCachePath/nar_bz22263=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart22642026/10/01 07:34:01 INFO Received complete multipart upload request method=POST path=/2265--- PASS: TestIsValidCachePath (0.01s)2266 --- PASS: TestIsValidCachePath/narinfo (0.00s)2267 --- PASS: TestIsValidCachePath/index.html (0.00s)2268 --- PASS: TestIsValidCachePath/short_hash (0.00s)2269 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2270 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2271 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2272 --- PASS: TestIsValidCachePath/realisation (0.00s)2273 --- PASS: TestIsValidCachePath/empty (0.00s)2274 --- PASS: TestIsValidCachePath/random_path (0.00s)2275 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2276 --- PASS: TestIsValidCachePath/log (0.00s)2277 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2278 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2279 --- PASS: TestIsValidCachePath/ls (0.00s)2280 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2281 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2282 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2283 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2284 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2285 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2286--- PASS: TestClientFallsBackToClosures (0.66s)2287=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure22882026/10/01 07:34:01 INFO Received uploads request method=POST path=/22892026-10-01 07:34:01.824 UTC [1397] ERROR: relation "goose_db_version" does not exist at character 3622902026-10-01 07:34:01.824 UTC [1397] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2291=== NAME TestClientMultipleUploads2292 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads196097424/001/store/jm0564rdrfbjm9mkxsma7hy1iirr4a56-test-file-1.txt2293=== NAME TestClientIntegration2294 client_integration_test.go:286: Created store path: /build/TestClientIntegration1730118340/002/store/27zzh3mdw92z3cr501cwc9m0slcq99gv-test-file.txt22952026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes22962026/10/01 07:34:01 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MzI0ZDkxMzMtZDk2ZS00YzQ2LWI1NDctMzkzY2RlNzEzNTM4LmU3MjFiMzAyLWNiNmEtNGRmNC05ZWU4LTdlYWQ4ZDk1NmJjNXgxNzkwODQwMDQxMjQ5OTEzMTg0 parts=1222972026/10/01 07:34:01 INFO Received uploads request method=POST path=/api/pending_closures2298--- PASS: TestReadProxyNarStreaming (0.41s)2299=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts23002026/10/01 07:34:01 INFO Received request for more parts method=POST path=/23012026/10/01 07:34:01 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)23022026/10/01 07:34:01 INFO Uploading gzahxx3hwndgdv2xvnwxbwh7dp07cjsa-top (224B)23032026/10/01 07:34:01 INFO Uploading fcpxfifx4x51qw9vxcqnz8dda62iz3h3-shared-dep (136B)23042026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.94ms)2305--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.07s)2306=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info23072026/10/01 07:34:01 INFO Received uploads request method=POST path=/2308=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key23092026/10/01 07:34:01 INFO Received complete multipart upload request method=POST path=/2310=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal23112026/10/01 07:34:01 INFO Received uploads request method=POST path=/2312=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key23132026/10/01 07:34:01 INFO Received request for more parts method=POST path=/2314--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)2315 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2316 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2317 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2318 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2319=== CONT TestIsValidUploadKey/narinfo2320=== CONT TestIsValidUploadKey/realisation_plus_in_output2321=== CONT TestIsValidUploadKey/unknown_type2322=== CONT TestIsValidUploadKey/empty_key2323=== CONT TestIsValidUploadKey/absolute2324=== CONT TestIsValidUploadKey/traversal_nar2325=== CONT TestIsValidUploadKey/traversal2326=== CONT TestIsValidUploadKey/listing_key,_narinfo_type23272026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.1ms)2328=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2329=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2330=== CONT TestIsValidUploadKey/build_log_home-manager_file2331=== CONT TestIsValidUploadKey/index.html2332=== CONT TestIsValidUploadKey/nix-cache-info2333=== CONT TestIsValidUploadKey/realisation2334=== CONT TestIsValidUploadKey/build_log_equals2335=== CONT TestIsValidUploadKey/build_log_question_mark2336=== CONT TestIsValidUploadKey/build_log_plus_in_name2337=== CONT TestIsValidUploadKey/build_log2338=== CONT TestIsValidUploadKey/listing2339=== CONT TestIsValidUploadKey/nar_plain2340=== CONT TestIsValidUploadKey/nar_xz2341=== CONT TestIsValidUploadKey/nar_zst2342=== CONT TestProxyWriteTimeout/narinfo2343--- PASS: TestIsValidUploadKey (0.00s)2344 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2345 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2346 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2347 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2348 --- PASS: TestIsValidUploadKey/absolute (0.00s)2349 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2350 --- PASS: TestIsValidUploadKey/traversal (0.00s)2351 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2352 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2353 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2354 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2355 --- PASS: TestIsValidUploadKey/index.html (0.00s)2356 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2357 --- PASS: TestIsValidUploadKey/realisation (0.00s)2358 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2359 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2360 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2361 --- PASS: TestIsValidUploadKey/build_log (0.00s)2362 --- PASS: TestIsValidUploadKey/listing (0.00s)2363 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2364 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2365 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)2366=== CONT TestProxyWriteTimeout/10_GiB_nar2367=== NAME TestClientMultipleUploads2368 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads196097424/001/store/n76m9harinzbw5dq3nb61px7wdxg0s58-test-file-2.txt23692026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/17s3n6ja3m9jjyg41n49px8wqk5gcxwxz7xd43qhv9sbj6vl29sd.nar.zst error="server returned 404: 404 page not found\n"2370=== CONT TestProxyWriteTimeout/unknown_size2371=== CONT TestProxyWriteTimeout/1_GiB_nar2372--- PASS: TestProxyWriteTimeout (0.00s)2373 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2374 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2375 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2376 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)23772026-10-01 07:34:01.864 UTC [1453] ERROR: relation "goose_db_version" does not exist at character 3623782026-10-01 07:34:01.864 UTC [1453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2379=== CONT TestPush_RejectsBadRequests/bad_root23802026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes23812026/10/01 07:34:01 WARN Failed to register uploaded object key=gzahxx3hwndgdv2xvnwxbwh7dp07cjsa.ls error="server returned 404: 404 page not found\n"2382=== CONT TestPush_RejectsBadRequests/no_roots23832026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes2384=== CONT TestPush_RejectsBadRequests/root_not_in_objects23852026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes2386=== CONT TestPush_RejectsBadRequests/no_objects23872026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes2388=== CONT TestResolveDBConnectionString/flag_wins2389--- PASS: TestPush_RejectsBadRequests (0.98s)2390 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2391 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2392 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2393 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2394=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2395=== CONT TestResolveDBConnectionString/nothing_configured23962026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.4ms)2397=== CONT TestResolveDBConnectionString/missing_file_is_an_error2398=== CONT TestResolveDBConnectionString/file_when_flag_empty23992026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"2400=== CONT TestClientErrorHandling/InvalidStorePath24012026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24022026/10/01 07:34:01 WARN Failed to register uploaded object key=fcpxfifx4x51qw9vxcqnz8dda62iz3h3.ls error="server returned 404: 404 page not found\n"24032026/10/01 07:34:01 INFO Signed narinfos id=1 count=22404--- PASS: TestResolveDBConnectionString (0.00s)2405 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2406 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2407 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2408 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2409 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)24102026/10/01 07:34:01 INFO Uploading 2 narinfos24112026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes24122026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes24132026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (4.62ms)24142026/10/01 07:34:01 WARN Failed to register uploaded object key=fcpxfifx4x51qw9vxcqnz8dda62iz3h3.narinfo error="server returned 404: 404 page not found\n"24152026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/1/complete24162026/10/01 07:34:01 WARN Failed to register uploaded object key=gzahxx3hwndgdv2xvnwxbwh7dp07cjsa.narinfo error="server returned 404: 404 page not found\n"24172026/10/01 07:34:01 OK 20260905000000_add_claims.sql (2.88ms)24182026/10/01 07:34:01 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)24192026/10/01 07:34:01 INFO Uploading mf162jbycyl486gx5gfzz5awgsjjmnmp-a (208B)24202026/10/01 07:34:01 INFO Uploading 4694l86gzhz1sls5baw4199wgpgja5g6-shared-dep (136B)24212026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.44ms)2422--- PASS: TestReadProxyHead (0.40s)2423=== CONT TestClientErrorHandling/ServerNotAvailable24242026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.8ms)24252026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000024262026/10/01 07:34:01 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24272026/10/01 07:34:01 INFO Uploading 595x9davpm0qk82vg950j22pi9d7k01h-test-script (136B)24282026/10/01 07:34:01 INFO Upload complete. (75ms)24292026/10/01 07:34:01 WARN Failed to register uploaded object key=76zx0i209gdb5794m6ijiym81vgjp1r6.ls error="server returned 404: 404 page not found\n"24302026-10-01 07:34:01.881 UTC [1506] ERROR: relation "goose_db_version" does not exist at character 3624312026-10-01 07:34:01.881 UTC [1506] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2432=== NAME TestClientSharedPathCommittedMidPush24332026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.95ms)2434 client_integration_test.go:680: Retrieved narinfo from S3:24352026-10-01 07:34:01.882 UTC [1497] ERROR: relation "goose_db_version" does not exist at character 3624362026-10-01 07:34:01.882 UTC [1497] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2437 StorePath: /build/TestClientSharedPathCommittedMidPush4280553567/001/store/fcpxfifx4x51qw9vxcqnz8dda62iz3h3-shared-dep24382026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/0h5y5hv415dyrxp1qisv61qaa45r6ls6amhzibrzh7wrqrl1sq7b.nar.zst error="server returned 404: 404 page not found\n"2439 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst24402026/10/01 07:34:01 WARN Failed to register uploaded object key=4694l86gzhz1sls5baw4199wgpgja5g6.ls error="server returned 404: 404 page not found\n"2441 Compression: zstd2442 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822443 NarSize: 1362444 References: 24452026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"2446 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n24472026/10/01 07:34:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete24482026/10/01 07:34:01 OK 2_object_stats_trigger.sql (971.89µs)24492026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24502026/10/01 07:34:01 WARN Failed to register uploaded object key=mf162jbycyl486gx5gfzz5awgsjjmnmp.ls error="server returned 404: 404 page not found\n"24512026/10/01 07:34:01 INFO Signed narinfos id=1 count=324522026/10/01 07:34:01 INFO Uploading 3 narinfos24532026/10/01 07:34:01 OK 3_commit_push.sql (1.19ms)24542026/10/01 07:34:01 goose: up to current file version: 324552026/10/01 07:34:01 WARN Failed to register uploaded object key=log/ldd0cbziw9yy3q8vsxnjhvj4cdxzgvbs-test-script.drv error="server returned 404: 404 page not found\n"2456 client_integration_test.go:680: Retrieved narinfo from S3:2457 StorePath: /build/TestClientSharedPathCommittedMidPush4280553567/001/store/gzahxx3hwndgdv2xvnwxbwh7dp07cjsa-top2458 URL: nar/17s3n6ja3m9jjyg41n49px8wqk5gcxwxz7xd43qhv9sbj6vl29sd.nar.zst2459 Compression: zstd2460 NarHash: sha256:17s3n6ja3m9jjyg41n49px8wqk5gcxwxz7xd43qhv9sbj6vl29sd2461 NarSize: 2242462 References: /build/TestClientSharedPathCommittedMidPush4280553567/001/store/fcpxfifx4x51qw9vxcqnz8dda62iz3h3-shared-dep2463 CA: text:sha256:14mykigsn7xw05h1xnygh4xk4lc5x3qkanwkmp0kwjlhc3xkqmf224642026/10/01 07:34:01 WARN Failed to register uploaded object key=595x9davpm0qk82vg950j22pi9d7k01h.ls error="server returned 404: 404 page not found\n"24652026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign24662026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"24672026/10/01 07:34:01 INFO Signed narinfos id=1 count=124682026/10/01 07:34:01 INFO Uploading 1 narinfos24692026/10/01 07:34:01 OK 20241026095416_initial_model.sql (14.55ms)24702026/10/01 07:34:01 WARN Failed to register uploaded object key=mf162jbycyl486gx5gfzz5awgsjjmnmp.narinfo error="server returned 404: 404 page not found\n"24712026/10/01 07:34:01 WARN Failed to register uploaded object key=76zx0i209gdb5794m6ijiym81vgjp1r6.narinfo error="server returned 404: 404 page not found\n"24722026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/1/complete24732026/10/01 07:34:01 WARN Failed to register uploaded object key=4694l86gzhz1sls5baw4199wgpgja5g6.narinfo error="server returned 404: 404 page not found\n"2474=== CONT TestClientErrorHandling/InvalidAuthToken24752026-10-01 07:34:01.891 UTC [1512] ERROR: relation "goose_db_version" does not exist at character 3624762026-10-01 07:34:01.891 UTC [1512] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC24772026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (3.99ms)2478--- PASS: TestReadProxy404 (0.36s)2479=== CONT TestCacheConfigHandler/full_config,_no_issuer2480=== CONT TestCacheConfigHandler/no_signing_keys2481=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2482=== CONT TestCacheConfigHandler/no_cache_url_configured24832026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/1/complete2484--- PASS: TestCacheConfigHandler (0.00s)2485 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2486 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2487 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2488 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)24892026/10/01 07:34:01 WARN Failed to register uploaded object key=595x9davpm0qk82vg950j22pi9d7k01h.narinfo error="server returned 404: 404 page not found\n"2490--- PASS: TestClientSharedPathCommittedMidPush (0.63s)24912026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.54ms)24922026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.77ms)24932026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.69ms)24942026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.73ms)24952026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.78ms)24962026/10/01 07:34:01 OK 20251218171726_add_pins.sql (3.28ms)24972026/10/01 07:34:01 INFO Upload complete. (78ms)24982026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (5.6ms)2499=== NAME TestClientPushesUseOnePush2500 client_pushes_test.go:97: Retrieved narinfo from S3:2501 StorePath: /build/TestClientPushesUseOnePush671496895/001/store/4694l86gzhz1sls5baw4199wgpgja5g6-shared-dep2502 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2503 Compression: zstd2504 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822505 NarSize: 1362506 References: 2507 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n25082026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.85ms)25092026/10/01 07:34:01 INFO Upload complete. (72ms)25102026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.55ms)2511 client_pushes_test.go:97: Retrieved narinfo from S3:2512 StorePath: /build/TestClientPushesUseOnePush671496895/001/store/mf162jbycyl486gx5gfzz5awgsjjmnmp-a2513 URL: nar/0h5y5hv415dyrxp1qisv61qaa45r6ls6amhzibrzh7wrqrl1sq7b.nar.zst2514 Compression: zstd2515 NarHash: sha256:0h5y5hv415dyrxp1qisv61qaa45r6ls6amhzibrzh7wrqrl1sq7b2516 NarSize: 2082517 References: /build/TestClientPushesUseOnePush671496895/001/store/4694l86gzhz1sls5baw4199wgpgja5g6-shared-dep2518 CA: text:sha256:1wf33izwkm3vi0vsds91vwd6xyc3f94rfbhh0vqp6jrkjsp4q2rw25192026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.75ms)2520=== NAME TestClientWithDependencies2521 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2635129860/001/store) requires matching store prefix25222026/10/01 07:34:01 OK 20260905000000_add_claims.sql (4.39ms)25232026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (4.1ms)2524=== NAME TestClientPushesUseOnePush2525 client_pushes_test.go:97: Retrieved narinfo from S3:2526 StorePath: /build/TestClientPushesUseOnePush671496895/001/store/76zx0i209gdb5794m6ijiym81vgjp1r6-b25272026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.34ms)2528 URL: nar/0h5y5hv415dyrxp1qisv61qaa45r6ls6amhzibrzh7wrqrl1sq7b.nar.zst2529 Compression: zstd25302026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)2531 NarHash: sha256:0h5y5hv415dyrxp1qisv61qaa45r6ls6amhzibrzh7wrqrl1sq7b2532 NarSize: 2082533 References: /build/TestClientPushesUseOnePush671496895/001/store/4694l86gzhz1sls5baw4199wgpgja5g6-shared-dep2534 CA: text:sha256:1wf33izwkm3vi0vsds91vwd6xyc3f94rfbhh0vqp6jrkjsp4q2rw25352026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (3.49ms)25362026/10/01 07:34:01 OK 20260905000000_add_claims.sql (2.98ms)25372026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.32ms)25382026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.67ms)25392026/10/01 07:34:01 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MzI0ZDkxMzMtZDk2ZS00YzQ2LWI1NDctMzkzY2RlNzEzNTM4LjA4MzNjMDE5LWI3YWEtNGI2OC1hMTBhLWJiMmNlNjYwMjdiMXgxNzkwODQwMDQxMzI2MDcyMDQ0 parts=1225402026-10-01 07:34:01.912 UTC [1535] ERROR: relation "goose_db_version" does not exist at character 3625412026-10-01 07:34:01.912 UTC [1535] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25422026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.1ms)25432026/10/01 07:34:01 goose: successfully migrated database to version: 202609231200002544--- PASS: TestRedundantMultipartUpload (1.08s)25452026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.93ms)25462026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (3.39ms)2547--- PASS: TestClientWithDependencies (0.65s)25482026/10/01 07:34:01 goose: successfully migrated database to version: 202609231200002549--- PASS: TestService_ReadScope_PublicByDefault (0.38s)25502026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)2551--- PASS: TestClientPushesUseOnePush (0.71s)25522026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.98ms)25532026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.58ms)25542026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000025552026/10/01 07:34:01 OK 1_commit_pending_closure.sql (4.21ms)25562026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.52ms)25572026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.92ms)25582026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.94ms)25592026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.15ms)25602026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.03ms)25612026/10/01 07:34:01 OK 3_commit_push.sql (1.4ms)25622026/10/01 07:34:01 goose: up to current file version: 325632026/10/01 07:34:01 OK 3_commit_push.sql (1.67ms)25642026/10/01 07:34:01 goose: up to current file version: 325652026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.42ms)25662026/10/01 07:34:01 OK 3_commit_push.sql (1.89ms)25672026/10/01 07:34:01 goose: up to current file version: 325682026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes25692026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.09ms)25702026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000025712026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.84ms)25722026/10/01 07:34:01 OK 20241026095416_initial_model.sql (8.53ms)25732026/10/01 07:34:01 OK 2_object_stats_trigger.sql (2.03ms)25742026/10/01 07:34:01 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25752026/10/01 07:34:01 INFO Uploading 27zzh3mdw92z3cr501cwc9m0slcq99gv-test-file.txt (152B)25762026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)25772026/10/01 07:34:01 OK 3_commit_push.sql (1.56ms)25782026/10/01 07:34:01 goose: up to current file version: 325792026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.88ms)25802026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"25812026/10/01 07:34:01 INFO Received push request method=POST path=/api/pushes25822026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25832026/10/01 07:34:01 WARN Failed to register uploaded object key=27zzh3mdw92z3cr501cwc9m0slcq99gv.ls error="server returned 404: 404 page not found\n"25842026/10/01 07:34:01 INFO Signed narinfos id=1 count=12585=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token25862026/10/01 07:34:01 INFO Uploading 1 narinfos2587=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2588=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2589=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2590=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2591=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2592=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2593=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2594=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2595=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2596=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected25972026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (3.4ms)2598=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected25992026/10/01 07:34:01 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]26002026/10/01 07:34:01 OK 20260905000000_add_claims.sql (3.03ms)26012026/10/01 07:34:01 WARN Authentication failed token_preview=eyJhbGciOi...6GnkjyTrfg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2602--- PASS: TestService_AuthMiddleware_OIDC (0.44s)2603 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2604 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2605 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2606 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)26072026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.15ms)26082026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/1/complete26092026/10/01 07:34:01 WARN Failed to register uploaded object key=27zzh3mdw92z3cr501cwc9m0slcq99gv.narinfo error="server returned 404: 404 page not found\n"26102026/10/01 07:34:01 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)26112026/10/01 07:34:01 INFO Uploading mdz7wm3amki5sqmgmblshb3rbnjn5gyi-test-file-0.txt (160B)26122026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (2.02ms)26132026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000026142026/10/01 07:34:01 INFO Uploading n76m9harinzbw5dq3nb61px7wdxg0s58-test-file-2.txt (160B)26152026/10/01 07:34:01 INFO Uploading jm0564rdrfbjm9mkxsma7hy1iirr4a56-test-file-1.txt (160B)26162026/10/01 07:34:01 OK 1_commit_pending_closure.sql (2.35ms)26172026/10/01 07:34:01 OK 2_object_stats_trigger.sql (1.33ms)26182026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"26192026/10/01 07:34:01 WARN Failed to register uploaded object key=mdz7wm3amki5sqmgmblshb3rbnjn5gyi.ls error="server returned 404: 404 page not found\n"26202026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"26212026/10/01 07:34:01 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"26222026/10/01 07:34:01 OK 3_commit_push.sql (1.27ms)26232026/10/01 07:34:01 goose: up to current file version: 326242026/10/01 07:34:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26252026/10/01 07:34:01 WARN Failed to register uploaded object key=n76m9harinzbw5dq3nb61px7wdxg0s58.ls error="server returned 404: 404 page not found\n"26262026/10/01 07:34:01 WARN Failed to register uploaded object key=jm0564rdrfbjm9mkxsma7hy1iirr4a56.ls error="server returned 404: 404 page not found\n"26272026/10/01 07:34:01 INFO Upload complete. (67ms)26282026/10/01 07:34:01 INFO Signed narinfos id=1 count=326292026/10/01 07:34:01 INFO Uploading 3 narinfos26302026/10/01 07:34:01 WARN Failed to register uploaded object key=n76m9harinzbw5dq3nb61px7wdxg0s58.narinfo error="server returned 404: 404 page not found\n"26312026/10/01 07:34:01 WARN Failed to register uploaded object key=mdz7wm3amki5sqmgmblshb3rbnjn5gyi.narinfo error="server returned 404: 404 page not found\n"26322026/10/01 07:34:01 INFO Received complete push request method=POST path=/api/pushes/1/complete26332026/10/01 07:34:01 WARN Failed to register uploaded object key=jm0564rdrfbjm9mkxsma7hy1iirr4a56.narinfo error="server returned 404: 404 page not found\n"26342026/10/01 07:34:01 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"26352026/10/01 07:34:01 WARN mTLS auth: bound subjects configured but subject DN unavailable26362026/10/01 07:34:01 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2637--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.38s)26382026/10/01 07:34:01 INFO Upload complete. (71ms)2639=== NAME TestClientMultipleUploads2640 client_integration_test.go:369: Uploaded 3 paths in 102.603995ms26412026/10/01 07:34:01 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/present26422026-10-01 07:34:01.972 UTC [1606] ERROR: relation "goose_db_version" does not exist at character 3626432026-10-01 07:34:01.972 UTC [1606] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2644--- PASS: TestService_ReadAuthMiddleware (0.26s)2645--- PASS: TestClientMultipleUploads (0.69s)26462026/10/01 07:34:01 OK 20241026095416_initial_model.sql (7.36ms)26472026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.05ms)26482026/10/01 07:34:01 INFO All 1 paths already cached26492026-10-01 07:34:01.986 UTC [1624] ERROR: relation "goose_db_version" does not exist at character 3626502026-10-01 07:34:01.986 UTC [1624] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2651=== NAME TestClientIntegration2652 client_integration_test.go:312: Retrieved narinfo from S3:2653 StorePath: /build/TestClientIntegration1730118340/002/store/27zzh3mdw92z3cr501cwc9m0slcq99gv-test-file.txt2654 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2655 Compression: zstd2656 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12657 NarSize: 1522658 References: 2659 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk126602026/10/01 07:34:01 OK 20251218171726_add_pins.sql (2.06ms)26612026/10/01 07:34:01 OK 20260628120000_add_object_size_and_stats.sql (2.08ms)2662 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2663 client_integration_test.go:313: Decompressed .ls content (64 bytes):2664 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2665 client_integration_test.go:316: Testing garbage collection...26662026/10/01 07:34:01 OK 20260905000000_add_claims.sql (2.84ms)26672026/10/01 07:34:01 OK 20260920000000_drop_claims.sql (2.86ms)26682026/10/01 07:34:01 OK 20260923120000_add_pushes.sql (1.34ms)26692026/10/01 07:34:01 goose: successfully migrated database to version: 2026092312000026702026/10/01 07:34:01 OK 20241026095416_initial_model.sql (6.64ms)2671--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.28s)26722026/10/01 07:34:01 OK 20251210153512_drop_unused_gin_index.sql (1.08ms)26732026/10/01 07:34:01 OK 1_commit_pending_closure.sql (1.72ms)26742026/10/01 07:34:01 OK 2_object_stats_trigger.sql (834.19µs)26752026/10/01 07:34:02 OK 3_commit_push.sql (603.95µs)26762026/10/01 07:34:02 goose: up to current file version: 326772026/10/01 07:34:02 OK 20251218171726_add_pins.sql (2.17ms)26782026/10/01 07:34:02 OK 20260628120000_add_object_size_and_stats.sql (2.51ms)26792026/10/01 07:34:02 OK 20260905000000_add_claims.sql (1.89ms)26802026/10/01 07:34:02 OK 20260920000000_drop_claims.sql (1.49ms)26812026/10/01 07:34:02 OK 20260923120000_add_pushes.sql (1.16ms)26822026/10/01 07:34:02 goose: successfully migrated database to version: 2026092312000026832026/10/01 07:34:02 OK 1_commit_pending_closure.sql (1.35ms)26842026/10/01 07:34:02 OK 2_object_stats_trigger.sql (635.72µs)26852026/10/01 07:34:02 OK 3_commit_push.sql (613.11µs)26862026/10/01 07:34:02 goose: up to current file version: 32687--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.29s)26882026/10/01 07:34:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures26892026/10/01 07:34:02 INFO Garbage collection started26902026/10/01 07:34:02 INFO Aborted multipart uploads count=026912026/10/01 07:34:02 WARN Force mode enabled - objects will be deleted immediately without grace period26922026/10/01 07:34:02 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=026932026/10/01 07:34:02 INFO Vacuumed table table=pending_closures26942026/10/01 07:34:02 INFO Vacuumed table table=pending_objects26952026/10/01 07:34:02 INFO Vacuumed table table=multipart_uploads26962026/10/01 07:34:02 INFO Vacuumed table table=closures26972026/10/01 07:34:02 INFO Vacuumed table table=objects2698=== RUN TestService_RequireScope_OIDC/builder_may_write2699=== PAUSE TestService_RequireScope_OIDC/builder_may_write2700=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2701=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2702=== RUN TestService_RequireScope_OIDC/ops_may_admin2703=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2704=== RUN TestService_RequireScope_OIDC/ops_may_not_write2705=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2706=== RUN TestService_RequireScope_OIDC/reader_may_not_write2707=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2708=== RUN TestService_RequireScope_OIDC/static_token_may_admin2709=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2710=== RUN TestService_RequireScope_OIDC/static_token_may_write2711=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2712=== RUN TestService_RequireScope_OIDC/reader_may_read2713=== PAUSE TestService_RequireScope_OIDC/reader_may_read2714=== RUN TestService_RequireScope_OIDC/writer_implies_read2715=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2716=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2717=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2718=== CONT TestService_RequireScope_OIDC/builder_may_write2719=== CONT TestService_RequireScope_OIDC/static_token_may_write2720=== CONT TestService_RequireScope_OIDC/static_token_may_admin2721=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2722=== CONT TestService_RequireScope_OIDC/ops_may_not_write2723=== CONT TestService_RequireScope_OIDC/writer_implies_read2724=== CONT TestService_RequireScope_OIDC/reader_may_read2725=== CONT TestService_RequireScope_OIDC/reader_may_not_write2726=== CONT TestService_RequireScope_OIDC/ops_may_admin2727=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2728--- PASS: TestService_RequireScope_OIDC (0.43s)2729 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2730 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2731 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2732 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2733 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2734 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2735 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2736 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2737 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2738 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)27392026/10/01 07:34:02 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=219.739557ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2740--- PASS: TestReadProxyNarinfo (0.31s)2741=== NAME TestClientCADerivations2742 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations225376780/001/store/w7ikg3ynfdys9wviyhk885wysc89ljvc-ca-test27432026/10/01 07:34:02 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2744 client_ca_test.go:139: Found 1 dependencies (including self)2745=== NAME TestOrphanedObjectsGCStressTest2746 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2747 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion27482026/10/01 07:34:02 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"27492026/10/01 07:34:02 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=380.402504ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27502026/10/01 07:34:02 INFO Received push request method=POST path=/api/pushes27512026/10/01 07:34:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27522026/10/01 07:34:02 INFO Uploading w7ikg3ynfdys9wviyhk885wysc89ljvc-ca-test (144B)27532026/10/01 07:34:02 WARN Failed to register uploaded object key=w7ikg3ynfdys9wviyhk885wysc89ljvc.ls error="server returned 404: 404 page not found\n"27542026/10/01 07:34:02 WARN Failed to register uploaded object key=log/3mshdd00nc60j1fb299irbxb4hrm26jg-ca-test.drv error="server returned 404: 404 page not found\n"27552026/10/01 07:34:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27562026/10/01 07:34:02 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"27572026/10/01 07:34:02 INFO Signed narinfos id=1 count=127582026/10/01 07:34:02 INFO Uploading 1 narinfos27592026/10/01 07:34:02 INFO Received complete push request method=POST path=/api/pushes/1/complete27602026/10/01 07:34:02 WARN Failed to register uploaded object key=w7ikg3ynfdys9wviyhk885wysc89ljvc.narinfo error="server returned 404: 404 page not found\n"27612026/10/01 07:34:02 INFO Upload complete. (103ms)2762--- PASS: TestUploadHandlersRejectOversizedBody (0.16s)2763 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.09s)2764 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.08s)2765 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.58s)2766=== NAME TestClientCADerivations2767 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations225376780/001/store/w7ikg3ynfdys9wviyhk885wysc89ljvc-ca-test2768 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2769 Compression: zstd2770 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2771 NarSize: 1442772 References: 2773 Deriver: /build/TestClientCADerivations225376780/001/store/3mshdd00nc60j1fb299irbxb4hrm26jg-ca-test.drv2774 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2775 client_ca_test.go:185: Checking for realisation files in S3...2776 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2777 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2778 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2779 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2780 error: binary cache 's3://bucket71?endpoint=http://localhost:41667®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations225376780/001/store'2781 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12782--- PASS: TestClientCADerivations (0.78s)2783=== NAME TestOrphanedObjectsGCStressTest2784 orphaned_objects_gc_test.go:509: Stress test completed successfully:2785 orphaned_objects_gc_test.go:510: - Active objects preserved: 202786 orphaned_objects_gc_test.go:511: - Objects deleted: 2102787 orphaned_objects_gc_test.go:512: - Total GC'd: 2102788--- PASS: TestOrphanedObjectsGCStressTest (2.66s)27892026/10/01 07:34:02 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=765.751062ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27902026/10/01 07:34:03 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.681122746s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27912026/10/01 07:34:03 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02792=== NAME TestPinProtectsFromGC2793 client_integration_test.go:794: Pin successfully protected closure from garbage collection2794--- PASS: TestPinProtectsFromGC (2.80s)27952026/10/01 07:34:04 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02796=== NAME TestClientIntegration2797 client_integration_test.go:323: Objects in database after GC:2798 client_integration_test.go:323: Successfully deleted all objects with GC --force2799--- PASS: TestClientIntegration (2.67s)28002026/10/01 07:34:05 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-config28012026/10/01 07:34:05 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=207.502144ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28022026/10/01 07:34:05 WARN Rate limiter enabled after throttle name=s3-test rate=528032026/10/01 07:34:05 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2804=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2805 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102806 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002807--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.68s)28082026/10/01 07:34:05 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=389.705982ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28092026/10/01 07:34:05 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=806.113154ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28102026/10/01 07:34:06 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.686275278s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28112026/10/01 07:34:08 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"28122026/10/01 07:34:08 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-config28132026/10/01 07:34:08 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=214.560361ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28142026/10/01 07:34:08 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=423.161831ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28152026/10/01 07:34:09 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=836.738899ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28162026/10/01 07:34:09 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.456726622s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config28172026/10/01 07:34:11 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_closures28182026/10/01 07:34:11 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=192.196189ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28192026/10/01 07:34:11 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=376.936034ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28202026/10/01 07:34:12 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=770.328103ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures28212026/10/01 07:34:12 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.664482025s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2822--- PASS: TestClientErrorHandling (0.00s)2823 --- PASS: TestClientErrorHandling/InvalidStorePath (0.28s)2824 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.36s)2825 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.64s)2826PASS28272026-10-01 07:34:14.853 UTC [130] LOG: received smart shutdown request28282026-10-01 07:34:14.857 UTC [130] LOG: background worker "logical replication launcher" (PID 140) exited with exit code 128292026-10-01 07:34:14.867 UTC [135] LOG: shutting down28302026-10-01 07:34:14.868 UTC [135] LOG: checkpoint starting: shutdown immediate28312026-10-01 07:34:16.904 UTC [135] LOG: checkpoint complete: wrote 10852 buffers (66.2%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 21 recycled; write=0.296 s, sync=1.692 s, total=2.037 s; sync files=24927, longest=0.030 s, average=0.001 s; distance=339149 kB, estimate=339149 kB; lsn=0/162992E8, redo lsn=0/162992E828322026-10-01 07:34:16.983 UTC [130] LOG: database system is shut down2833Running OIDC tests...2834=== RUN TestAudienceForIssuer2835=== PAUSE TestAudienceForIssuer2836=== RUN TestGlobMatch2837=== PAUSE TestGlobMatch2838=== RUN TestValidateToken_ValidToken2839=== PAUSE TestValidateToken_ValidToken2840=== RUN TestValidateToken_WrongAudience2841=== PAUSE TestValidateToken_WrongAudience2842=== RUN TestValidateToken_Expired2843=== PAUSE TestValidateToken_Expired2844=== RUN TestValidateToken_BoundClaimsMismatch2845=== PAUSE TestValidateToken_BoundClaimsMismatch2846=== RUN TestValidateToken_BoundSubjectMismatch2847=== PAUSE TestValidateToken_BoundSubjectMismatch2848=== RUN TestValidateToken_MultipleProviders2849=== PAUSE TestValidateToken_MultipleProviders2850=== RUN TestValidateToken_NoMatchingProvider2851=== PAUSE TestValidateToken_NoMatchingProvider2852=== RUN TestValidateToken_KubernetesServiceAccount2853=== PAUSE TestValidateToken_KubernetesServiceAccount2854=== RUN TestNewValidator_KubernetesRequiresCA2855=== PAUSE TestNewValidator_KubernetesRequiresCA2856=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2857=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2858=== RUN TestPins_ReservedForMatchingRule2859=== PAUSE TestPins_ReservedForMatchingRule2860=== RUN TestPins_TopLevelShorthand2861=== PAUSE TestPins_TopLevelShorthand2862=== RUN TestPins_ConfigValidation2863=== PAUSE TestPins_ConfigValidation2864=== RUN TestScopes_LegacyProviderDefaultsToWrite2865=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2866=== RUN TestScopes_Rules2867=== PAUSE TestScopes_Rules2868=== RUN TestScopes_ConfigValidation2869=== PAUSE TestScopes_ConfigValidation2870=== CONT TestAudienceForIssuer2871=== CONT TestPins_ConfigValidation2872--- PASS: TestAudienceForIssuer (0.00s)2873=== CONT TestValidateToken_NoMatchingProvider2874=== CONT TestValidateToken_MultipleProviders2875=== CONT TestValidateToken_KubernetesServiceAccount2876=== CONT TestValidateToken_BoundSubjectMismatch2877=== CONT TestValidateToken_BoundClaimsMismatch2878=== CONT TestValidateToken_Expired2879=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2880=== CONT TestValidateToken_WrongAudience2881=== CONT TestValidateToken_ValidToken2882=== CONT TestNewValidator_KubernetesRequiresCA2883=== CONT TestGlobMatch2884=== CONT TestScopes_Rules2885=== RUN TestGlobMatch/foo_foo2886=== PAUSE TestGlobMatch/foo_foo2887=== RUN TestGlobMatch/foo_bar2888=== PAUSE TestGlobMatch/foo_bar2889=== RUN TestGlobMatch/*_2890=== PAUSE TestGlobMatch/*_2891=== RUN TestGlobMatch/*_anything2892=== CONT TestPins_TopLevelShorthand2893=== CONT TestScopes_ConfigValidation2894=== CONT TestScopes_LegacyProviderDefaultsToWrite2895=== CONT TestPins_ReservedForMatchingRule2896--- PASS: TestPins_ConfigValidation (0.00s)2897=== PAUSE TestGlobMatch/*_anything2898=== RUN TestGlobMatch/foo*_foo2899=== PAUSE TestGlobMatch/foo*_foo2900=== RUN TestGlobMatch/foo*_foobar2901=== PAUSE TestGlobMatch/foo*_foobar2902=== RUN TestGlobMatch/foo*_bar2903=== PAUSE TestGlobMatch/foo*_bar2904=== RUN TestGlobMatch/*bar_bar2905=== PAUSE TestGlobMatch/*bar_bar2906=== RUN TestGlobMatch/*bar_foobar2907=== PAUSE TestGlobMatch/*bar_foobar2908=== RUN TestGlobMatch/*bar_foo2909=== PAUSE TestGlobMatch/*bar_foo2910=== RUN TestGlobMatch/foo*bar_foobar2911=== PAUSE TestGlobMatch/foo*bar_foobar2912=== RUN TestGlobMatch/foo*bar_foo123bar2913=== PAUSE TestGlobMatch/foo*bar_foo123bar2914=== RUN TestGlobMatch/foo*bar_foobarbaz2915=== PAUSE TestGlobMatch/foo*bar_foobarbaz2916=== RUN TestGlobMatch/*/*_foo/bar2917=== PAUSE TestGlobMatch/*/*_foo/bar2918=== RUN TestGlobMatch/*/*_foo2919=== PAUSE TestGlobMatch/*/*_foo2920=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2921=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2922=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02923=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02924=== RUN TestGlobMatch/refs/*/main_refs/heads/main2925=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2926=== RUN TestGlobMatch/fo?_foo2927=== PAUSE TestGlobMatch/fo?_foo2928=== RUN TestGlobMatch/fo?_fo2929=== PAUSE TestGlobMatch/fo?_fo2930=== RUN TestGlobMatch/fo?_fooo2931=== PAUSE TestGlobMatch/fo?_fooo2932=== RUN TestGlobMatch/?oo_foo2933=== PAUSE TestGlobMatch/?oo_foo2934=== RUN TestGlobMatch/?oo_boo2935=== PAUSE TestGlobMatch/?oo_boo2936=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2937=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2938=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2939=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2940--- PASS: TestScopes_ConfigValidation (0.00s)2941=== CONT TestGlobMatch/?oo_boo2942=== CONT TestGlobMatch/*/*_foo2943=== CONT TestGlobMatch/foo*_bar2944=== CONT TestGlobMatch/foo*_foobar2945=== CONT TestGlobMatch/fo?_fo2946=== CONT TestGlobMatch/foo_foo2947=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2948=== CONT TestGlobMatch/foo*bar_foo123bar2949=== CONT TestGlobMatch/*_2950=== CONT TestGlobMatch/*/*_foo/bar2951=== CONT TestGlobMatch/foo_bar2952=== CONT TestGlobMatch/*_anything2953=== CONT TestGlobMatch/*bar_foo2954=== CONT TestGlobMatch/foo*bar_foobarbaz2955=== CONT TestGlobMatch/*bar_foobar2956=== CONT TestGlobMatch/*bar_bar2957=== CONT TestGlobMatch/fo?_foo2958=== CONT TestGlobMatch/foo*bar_foobar2959=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02960=== CONT TestGlobMatch/?oo_foo2961=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2962=== CONT TestGlobMatch/fo?_fooo2963=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2964=== CONT TestGlobMatch/foo*_foo2965=== CONT TestGlobMatch/refs/*/main_refs/heads/main2966--- PASS: TestGlobMatch (0.00s)2967 --- PASS: TestGlobMatch/?oo_boo (0.00s)2968 --- PASS: TestGlobMatch/*/*_foo (0.00s)2969 --- PASS: TestGlobMatch/foo*_bar (0.00s)2970 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2971 --- PASS: TestGlobMatch/fo?_fo (0.00s)2972 --- PASS: TestGlobMatch/foo_foo (0.00s)2973 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2974 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2975 --- PASS: TestGlobMatch/*_ (0.00s)2976 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2977 --- PASS: TestGlobMatch/foo_bar (0.00s)2978 --- PASS: TestGlobMatch/*_anything (0.00s)2979 --- PASS: TestGlobMatch/*bar_foo (0.00s)2980 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2981 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2982 --- PASS: TestGlobMatch/*bar_bar (0.00s)2983 --- PASS: TestGlobMatch/fo?_foo (0.00s)2984 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2985 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2986 --- PASS: TestGlobMatch/?oo_foo (0.00s)2987 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2988 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2989 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2990 --- PASS: TestGlobMatch/foo*_foo (0.00s)2991 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)29922026/10/01 07:34:18 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:419432993--- PASS: TestValidateToken_KubernetesServiceAccount (0.02s)29942026/10/01 07:34:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41941/oidc29952026/10/01 07:34:18 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12329962026/10/01 07:34:18 http: TLS handshake error from 127.0.0.1:35520: remote error: tls: bad certificate2997--- PASS: TestNewValidator_KubernetesRequiresCA (0.03s)2998--- PASS: TestValidateToken_ValidToken (0.03s)29992026/10/01 07:34:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39861/oidc3000--- PASS: TestValidateToken_BoundClaimsMismatch (0.04s)3001--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.04s)30022026/10/01 07:34:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39577/oidc3003--- PASS: TestValidateToken_Expired (0.06s)30042026/10/01 07:34:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45989/oidc3005--- PASS: TestPins_TopLevelShorthand (0.05s)30062026/10/01 07:34:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43111/oidc30072026/10/01 07:34:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38459/oidc3008--- PASS: TestPins_ReservedForMatchingRule (0.07s)30092026/10/01 07:34:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36561/oidc3010--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)3011--- PASS: TestScopes_Rules (0.08s)30122026/10/01 07:34:18 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:43675/oidc30132026/10/01 07:34:18 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:39297/oidc3014--- PASS: TestValidateToken_MultipleProviders (0.11s)30152026/10/01 07:34:18 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:45351/oidc3016--- PASS: TestValidateToken_NoMatchingProvider (0.12s)30172026/10/01 07:34:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36189/oidc3018--- PASS: TestValidateToken_BoundSubjectMismatch (0.13s)30192026/10/01 07:34:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45209/oidc3020--- PASS: TestValidateToken_WrongAudience (0.13s)3021PASS3022Running hook tests...3023=== RUN TestSendPathsEmpty3024=== PAUSE TestSendPathsEmpty3025=== RUN TestQueueEnqueueAndFetch3026=== PAUSE TestQueueEnqueueAndFetch3027=== RUN TestQueueDeduplication3028=== PAUSE TestQueueDeduplication3029=== RUN TestQueueRemove3030=== PAUSE TestQueueRemove3031=== RUN TestQueueFetchBatchLimit3032=== PAUSE TestQueueFetchBatchLimit3033=== RUN TestQueueRetryMovesToBack3034=== PAUSE TestQueueRetryMovesToBack3035=== RUN TestQueueFetchRemoveLifecycle3036=== PAUSE TestQueueFetchRemoveLifecycle3037=== RUN TestQueueConcurrentWriters3038=== PAUSE TestQueueConcurrentWriters3039=== RUN TestQueueRemoveLargeClosure3040=== PAUSE TestQueueRemoveLargeClosure3041=== RUN TestServerClientIntegration3042=== PAUSE TestServerClientIntegration3043=== RUN TestServerQueueError3044=== PAUSE TestServerQueueError3045=== RUN TestGetListenerSocketActivation3046 server_test.go:210: === RUN TestGetListenerSocketActivation3047 --- PASS: TestGetListenerSocketActivation (0.00s)3048 PASS3049 3050--- PASS: TestGetListenerSocketActivation (0.01s)3051=== RUN TestDrainIsolatesPoisonPath3052=== PAUSE TestDrainIsolatesPoisonPath3053=== RUN TestRunNotBlockedByPoisonHead3054=== PAUSE TestRunNotBlockedByPoisonHead3055=== RUN TestDrainGivesUpWhenServerDown3056=== PAUSE TestDrainGivesUpWhenServerDown3057=== RUN TestFailedPathPrunedByLaterClosure3058=== PAUSE TestFailedPathPrunedByLaterClosure3059=== RUN TestWorkerUploadsAndRemoves3060=== PAUSE TestWorkerUploadsAndRemoves3061=== RUN TestWorkerSkipsGCdPaths3062=== PAUSE TestWorkerSkipsGCdPaths3063=== RUN TestWorkerPrunesClosureDeps3064=== PAUSE TestWorkerPrunesClosureDeps3065=== RUN TestDrainTimeout3066=== PAUSE TestDrainTimeout3067=== CONT TestSendPathsEmpty3068=== CONT TestServerQueueError3069=== CONT TestQueueRetryMovesToBack3070--- PASS: TestSendPathsEmpty (0.00s)3071=== CONT TestWorkerUploadsAndRemoves3072=== CONT TestServerClientIntegration3073=== CONT TestDrainTimeout3074=== CONT TestQueueFetchBatchLimit3075=== CONT TestQueueRemove30762026/10/01 07:34:18 ERROR Failed to queue paths error="permission denied" count=13077=== CONT TestWorkerPrunesClosureDeps3078=== CONT TestQueueDeduplication3079=== CONT TestWorkerSkipsGCdPaths3080=== CONT TestQueueEnqueueAndFetch3081=== CONT TestDrainGivesUpWhenServerDown3082=== CONT TestQueueConcurrentWriters3083=== CONT TestFailedPathPrunedByLaterClosure3084=== CONT TestQueueRemoveLargeClosure3085=== CONT TestRunNotBlockedByPoisonHead3086=== CONT TestDrainIsolatesPoisonPath3087=== CONT TestQueueFetchRemoveLifecycle3088--- PASS: TestServerClientIntegration (0.00s)3089--- PASS: TestServerQueueError (0.00s)30902026/10/01 07:34:18 INFO Upload queue status pending=230912026/10/01 07:34:18 INFO Uploading batch count=230922026/10/01 07:34:18 INFO Uploading batch count=130932026/10/01 07:34:18 ERROR Upload failed error="upload failed" count=130942026/10/01 07:34:18 INFO Uploading batch count=430952026/10/01 07:34:18 ERROR Upload failed error="upload failed" count=430962026/10/01 07:34:18 INFO Uploading batch count=230972026/10/01 07:34:18 ERROR Upload failed error="upload failed" count=230982026/10/01 07:34:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown535350031/002/a30992026/10/01 07:34:18 INFO Uploading batch count=231002026/10/01 07:34:18 INFO Uploading batch count=13101--- PASS: TestQueueFetchBatchLimit (0.02s)31022026/10/01 07:34:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown535350031/002/b3103--- PASS: TestQueueEnqueueAndFetch (0.02s)31042026/10/01 07:34:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2554226924/002/bbb31052026/10/01 07:34:18 INFO Upload queue status pending=231062026/10/01 07:34:18 INFO Upload queue status pending=331072026/10/01 07:34:18 INFO Upload queue status pending=23108--- PASS: TestQueueDeduplication (0.02s)31092026/10/01 07:34:18 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths3217654028/002/nonexistent31102026/10/01 07:34:18 INFO Uploading batch count=231112026/10/01 07:34:18 ERROR Upload failed error="upload failed" count=231122026/10/01 07:34:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown535350031/002/c31132026/10/01 07:34:18 INFO Uploading batch count=13114--- PASS: TestQueueFetchRemoveLifecycle (0.02s)31152026/10/01 07:34:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown535350031/002/d31162026/10/01 07:34:18 INFO Uploading batch count=13117--- PASS: TestQueueRetryMovesToBack (0.02s)31182026/10/01 07:34:18 INFO Uploading batch count=131192026/10/01 07:34:18 ERROR Upload failed error="upload failed" count=13120--- PASS: TestQueueRemove (0.02s)31212026/10/01 07:34:18 INFO Uploading batch count=131222026/10/01 07:34:18 INFO Uploading batch count=231232026/10/01 07:34:18 ERROR Upload failed error="upload failed" count=231242026/10/01 07:34:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown535350031/002/e31252026/10/01 07:34:18 INFO Uploading batch count=131262026/10/01 07:34:18 ERROR Upload failed error="upload failed" count=131272026/10/01 07:34:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown535350031/002/f31282026/10/01 07:34:18 INFO Uploading batch count=131292026/10/01 07:34:18 ERROR Upload failed error="upload failed" count=13130--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)31312026/10/01 07:34:18 ERROR Drain finished with paths left in queue remaining=1031322026/10/01 07:34:18 INFO Uploading batch count=131332026/10/01 07:34:18 ERROR Upload failed error="upload failed" count=131342026/10/01 07:34:18 ERROR Drain finished with paths left in queue remaining=13135--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3136--- PASS: TestDrainIsolatesPoisonPath (0.03s)3137--- PASS: TestWorkerUploadsAndRemoves (0.04s)3138--- PASS: TestWorkerSkipsGCdPaths (0.04s)3139--- PASS: TestWorkerPrunesClosureDeps (0.04s)3140--- PASS: TestQueueRemoveLargeClosure (0.08s)31412026/10/01 07:34:19 ERROR Upload failed error="context deadline exceeded" count=231422026/10/01 07:34:19 ERROR Drain finished with paths left in queue remaining=43143--- PASS: TestDrainTimeout (0.22s)3144--- PASS: TestQueueConcurrentWriters (0.28s)31452026/10/01 07:34:19 INFO Uploading batch count=131462026/10/01 07:34:19 INFO Uploading batch count=131472026/10/01 07:34:19 INFO Uploading batch count=131482026/10/01 07:34:19 ERROR Upload failed error="upload failed" count=131492026/10/01 07:34:19 INFO Uploading batch count=131502026/10/01 07:34:19 ERROR Upload failed error="upload failed" count=131512026/10/01 07:34:19 INFO Uploading batch count=131522026/10/01 07:34:19 ERROR Upload failed error="upload failed" count=131532026/10/01 07:34:19 INFO Uploading batch count=131542026/10/01 07:34:19 ERROR Upload failed error="upload failed" count=131552026/10/01 07:34:19 ERROR Drain finished with paths left in queue remaining=13156--- PASS: TestRunNotBlockedByPoisonHead (1.04s)3157PASS