niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #320
· raw
1tribuchet: building on eliza2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestCaseHackSuffix8=== PAUSE TestCaseHackSuffix9=== RUN TestFilterOversizedClosures10=== PAUSE TestFilterOversizedClosures11=== RUN TestUploadMultipart_PartsInParallel12=== PAUSE TestUploadMultipart_PartsInParallel13=== RUN TestPartSizeForNAR14=== PAUSE TestPartSizeForNAR15=== RUN TestUploadMultipart_SupersededByPeer16=== PAUSE TestUploadMultipart_SupersededByPeer17=== RUN TestDumpPathCaseHackMatchesNix18--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)19=== RUN TestDumpPathCaseHackCollision20--- PASS: TestDumpPathCaseHackCollision (0.00s)21=== RUN TestDumpPathMatchesNix22=== PAUSE TestDumpPathMatchesNix23=== RUN TestDumpPathSingleFile24=== PAUSE TestDumpPathSingleFile25=== RUN TestDumpPathWriterError26=== PAUSE TestDumpPathWriterError27=== RUN TestEncodeNixBase3228=== PAUSE TestEncodeNixBase3229=== RUN TestEncodeNixBase32WithRealHash30=== PAUSE TestEncodeNixBase32WithRealHash31=== RUN TestConvertHashToNix3232=== PAUSE TestConvertHashToNix3233=== RUN TestGetStorePathHash34=== PAUSE TestGetStorePathHash35=== RUN TestPathInfoHashCompatibility36=== PAUSE TestPathInfoHashCompatibility37=== RUN TestParsePathInfoJSON38=== PAUSE TestParsePathInfoJSON39=== RUN TestParsePathInfoJSONMultiplePaths40=== PAUSE TestParsePathInfoJSONMultiplePaths41=== RUN TestPathInfoCACompatibility42=== PAUSE TestPathInfoCACompatibility43=== RUN TestRateLimiterFeedback44=== PAUSE TestRateLimiterFeedback45=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess46=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess47=== RUN TestResolveStorePath48=== PAUSE TestResolveStorePath49=== RUN TestDoWithRetry_BodyReplayedViaGetBody50=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody51=== RUN TestShellSplit52=== PAUSE TestShellSplit53=== RUN TestShellSplitErrors54=== PAUSE TestShellSplitErrors55=== RUN TestStreamPushReportsEveryPath56=== PAUSE TestStreamPushReportsEveryPath57=== RUN TestStreamPushBatchesUnderLoad58=== PAUSE TestStreamPushBatchesUnderLoad59=== RUN TestStreamPushIsolatesFailures60=== PAUSE TestStreamPushIsolatesFailures61=== RUN TestStreamPushGivesUpOnDeadServer62=== PAUSE TestStreamPushGivesUpOnDeadServer63=== RUN TestStreamPushRequestLine64=== PAUSE TestStreamPushRequestLine65=== RUN TestStreamPushReportsSignatures66=== PAUSE TestStreamPushReportsSignatures67=== RUN TestClientSignaturesByStorePath68=== PAUSE TestClientSignaturesByStorePath69=== RUN TestSetClientTLS70=== PAUSE TestSetClientTLS71=== RUN TestSetClientTLSDoesNotMutateDefaultTransport72=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport73=== RUN TestSetClientTLSErrors74=== PAUSE TestSetClientTLSErrors75=== RUN TestStaticToken76=== PAUSE TestStaticToken77=== RUN TestFileTokenReadsAndCaches78=== PAUSE TestFileTokenReadsAndCaches79=== RUN TestFileTokenMissing80=== PAUSE TestFileTokenMissing81=== RUN TestFileTokenEmpty82=== PAUSE TestFileTokenEmpty83=== RUN TestScriptTokenNoExpiryRerunsEveryCall84=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall85=== RUN TestScriptTokenCachesUntilRefresh86=== PAUSE TestScriptTokenCachesUntilRefresh87=== RUN TestScriptTokenEmptyToken88=== PAUSE TestScriptTokenEmptyToken89=== RUN TestScriptTokenBadJSON90=== PAUSE TestScriptTokenBadJSON91=== RUN TestScriptTokenScriptFails92=== PAUSE TestScriptTokenScriptFails93=== RUN TestScriptTokenEmptyCommand94=== PAUSE TestScriptTokenEmptyCommand95=== CONT TestDoServerRequestAttachesToken96=== CONT TestScriptTokenBadJSON97=== CONT TestDoWithRetry_BodyReplayedViaGetBody98=== CONT TestScriptTokenEmptyToken99=== CONT TestScriptTokenCachesUntilRefresh100=== CONT TestScriptTokenNoExpiryRerunsEveryCall101=== CONT TestFileTokenEmpty102=== CONT TestFileTokenMissing103=== CONT TestFileTokenReadsAndCaches104=== CONT TestStaticToken105--- PASS: TestStaticToken (0.00s)106=== CONT TestPathInfoHashCompatibility107=== CONT TestEncodeNixBase32WithRealHash108--- PASS: TestEncodeNixBase32WithRealHash (0.00s)109=== CONT TestGetStorePathHash110=== CONT TestSetClientTLSErrors111=== CONT TestResolveStorePath112=== CONT TestSetClientTLSDoesNotMutateDefaultTransport113=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess114=== CONT TestStreamPushIsolatesFailures115=== CONT TestRateLimiterFeedback116=== CONT TestStreamPushBatchesUnderLoad117=== CONT TestPathInfoCACompatibility118=== CONT TestStreamPushReportsEveryPath119=== CONT TestParsePathInfoJSONMultiplePaths120=== CONT TestShellSplitErrors121=== CONT TestParsePathInfoJSON122=== CONT TestShellSplit123=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)124=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)125=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon126=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon127=== CONT TestUploadMultipart_SupersededByPeer128--- PASS: TestFileTokenEmpty (0.00s)1292026/10/01 09:47:11 WARN Rate limiter enabled after throttle name=server-test rate=51302026/10/01 09:47:11 WARN Rate limiter enabled after throttle name=server-test rate=5131=== RUN TestPathInfoCACompatibility/null_ca_field1322026/10/01 09:47:11 ERROR Upload failed error="bad path" count=3133=== RUN TestRateLimiterFeedback/429_enables_limiter1342026/10/01 09:47:11 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:46523135=== PAUSE TestRateLimiterFeedback/429_enables_limiter136=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI137=== CONT TestConvertHashToNix32138=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI139--- PASS: TestFileTokenMissing (0.00s)140=== CONT TestScriptTokenEmptyCommand141=== CONT TestDumpPathWriterError142=== CONT TestDumpPathSingleFile1432026/10/01 09:47:11 WARN Rate limiter backed off name=server-test rate=51442026/10/01 09:47:11 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:46523145=== RUN TestParsePathInfoJSON/Nix_format146=== CONT TestUploadMultipart_PartsInParallel147=== PAUSE TestParsePathInfoJSON/Nix_format148=== RUN TestParsePathInfoJSON/Lix_format149=== PAUSE TestParsePathInfoJSON/Lix_format150=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths151=== CONT TestSetClientTLS152=== CONT TestFilterOversizedClosures153=== RUN TestFilterOversizedClosures/no_limit_keeps_everything154=== CONT TestDumpPathMatchesNix155=== CONT TestEncodeNixBase32156=== CONT TestScriptTokenScriptFails157=== RUN TestEncodeNixBase32/test_string_hash158=== PAUSE TestEncodeNixBase32/test_string_hash159=== CONT TestPartSizeForNAR160=== RUN TestRateLimiterFeedback/503_enables_limiter161=== RUN TestConvertHashToNix32/SRI_format_to_Nix32162=== RUN TestGetStorePathHash/valid_store_path163=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512164--- PASS: TestScriptTokenBadJSON (0.00s)165=== CONT TestClientSignaturesByStorePath166=== RUN TestUploadMultipart_SupersededByPeer/exists167=== RUN TestParsePathInfoJSON/empty_input168=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything169=== RUN TestSetClientTLS/rejects_connection_without_client_cert170=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths171=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32172=== RUN TestConvertHashToNix32/already_Nix32_format173=== PAUSE TestUploadMultipart_SupersededByPeer/exists174=== CONT TestStreamPushRequestLine175=== RUN TestUploadMultipart_SupersededByPeer/missing176=== PAUSE TestUploadMultipart_SupersededByPeer/missing177=== PAUSE TestRateLimiterFeedback/503_enables_limiter178=== RUN TestPartSizeForNAR/zero_stays_at_minimum179=== RUN TestSetClientTLSErrors/missing_cert_file180=== PAUSE TestSetClientTLSErrors/missing_cert_file181=== RUN TestSetClientTLSErrors/missing_key_file182=== PAUSE TestSetClientTLSErrors/missing_key_file183=== RUN TestSetClientTLSErrors/missing_ca_file184=== CONT TestStreamPushGivesUpOnDeadServer1852026/10/01 09:47:11 ERROR Upload failed error=boom count=1186=== PAUSE TestGetStorePathHash/valid_store_path187=== PAUSE TestSetClientTLSErrors/missing_ca_file188=== RUN TestGetStorePathHash/basename_without_hyphen_should_error189=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error1902026/10/01 09:47:11 ERROR Upload failed error="connection refused" count=20191--- PASS: TestShellSplit (0.00s)1922026/10/01 09:47:11 ERROR Server seems unavailable, giving up on batch untried=17193=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error194=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error195=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error196=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512197=== CONT TestStreamPushReportsSignatures198=== PAUSE TestPathInfoCACompatibility/null_ca_field199=== RUN TestPathInfoCACompatibility/old_string_format_-_text200=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text201=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive202=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive203=== RUN TestPathInfoCACompatibility/new_structured_format_-_text204=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text205=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method206=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method207=== CONT TestUploadMultipart_SupersededByPeer/missing2082026/10/01 09:47:11 ERROR Upload failed error=boom count=1209=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512210=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI211=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped212=== CONT TestCaseHackSuffix213=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths214=== PAUSE TestConvertHashToNix32/already_Nix32_format215=== RUN TestEncodeNixBase32/empty_input216=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert217=== CONT TestRegisterUploadedObjectReusesConnections218=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA219=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA220=== RUN TestSetClientTLS/preserves_debug_logging_transport221=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter222=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter223=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter224=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum225=== RUN TestSetClientTLSErrors/invalid_ca_file226=== PAUSE TestSetClientTLSErrors/invalid_ca_file227--- PASS: TestScriptTokenEmptyToken (0.00s)228=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method229=== CONT TestPathInfoCACompatibility/new_structured_format_-_text230=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive231=== CONT TestPathInfoCACompatibility/old_string_format_-_text232=== CONT TestSetClientTLSErrors/missing_cert_file233=== CONT TestSetClientTLSErrors/invalid_ca_file234--- PASS: TestFileTokenReadsAndCaches (0.00s)235--- PASS: TestShellSplitErrors (0.00s)236--- PASS: TestStreamPushReportsEveryPath (0.00s)237--- PASS: TestStreamPushIsolatesFailures (0.00s)238--- PASS: TestScriptTokenEmptyCommand (0.00s)239--- PASS: TestDoServerRequestAttachesToken (0.01s)240=== CONT TestUploadMultipart_SupersededByPeer/exists241--- PASS: TestResolveStorePath (0.00s)242--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.04s)243--- PASS: TestClientSignaturesByStorePath (0.00s)244--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)245--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)246--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.03s)247--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)248--- PASS: TestStreamPushReportsSignatures (0.00s)249--- PASS: TestScriptTokenScriptFails (0.00s)250=== PAUSE TestParsePathInfoJSON/empty_input251=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)252=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped253=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths254=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon255=== PAUSE TestEncodeNixBase32/empty_input256=== RUN TestConvertHashToNix32/invalid_format257=== PAUSE TestSetClientTLS/preserves_debug_logging_transport258=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter259=== CONT TestRateLimiterFeedback/429_enables_limiter260=== CONT TestSetClientTLSErrors/missing_ca_file261=== CONT TestEncodeNixBase32/test_string_hash262=== CONT TestSetClientTLSErrors/missing_key_file263=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error264=== CONT TestGetStorePathHash/valid_store_path265=== CONT TestPathInfoCACompatibility/null_ca_field266=== PAUSE TestConvertHashToNix32/invalid_format267=== CONT TestConvertHashToNix32/SRI_format_to_Nix32268=== CONT TestSetClientTLS/rejects_connection_without_client_cert269=== RUN TestFilterOversizedClosures/all_closures_skipped270=== PAUSE TestFilterOversizedClosures/all_closures_skipped271=== CONT TestFilterOversizedClosures/no_limit_keeps_everything272=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths273=== RUN TestPartSizeForNAR/small_stays_at_minimum274=== CONT TestFilterOversizedClosures/all_closures_skipped275=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter276=== CONT TestConvertHashToNix32/invalid_format2772026/10/01 09:47:11 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50278=== CONT TestConvertHashToNix32/already_Nix32_format279=== PAUSE TestPartSizeForNAR/small_stays_at_minimum280=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum281=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum2822026/10/01 09:47:11 WARN Rate limiter enabled after throttle name=server-test rate=5283=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts2842026/10/01 09:47:11 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:35875285=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts286=== RUN TestPartSizeForNAR/1_TiB287=== PAUSE TestPartSizeForNAR/1_TiB288=== RUN TestPartSizeForNAR/5_TiB_S3_max_object289=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object290=== RUN TestPartSizeForNAR/capped_at_5_GiB291=== PAUSE TestPartSizeForNAR/capped_at_5_GiB292=== CONT TestPartSizeForNAR/zero_stays_at_minimum2932026/10/01 09:47:11 WARN Rate limiter backed off name=server-test rate=5294=== CONT TestEncodeNixBase32/empty_input295=== CONT TestPartSizeForNAR/5_TiB_S3_max_object296=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts297=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum298=== CONT TestPartSizeForNAR/small_stays_at_minimum299=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter300=== RUN TestParsePathInfoJSON/whitespace_only301=== PAUSE TestParsePathInfoJSON/whitespace_only302=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error303=== RUN TestParsePathInfoJSON/invalid_JSON304=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped305=== PAUSE TestParsePathInfoJSON/invalid_JSON3062026/10/01 09:47:11 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=2000307=== CONT TestParsePathInfoJSON/Nix_format308=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error309=== CONT TestPartSizeForNAR/capped_at_5_GiB310=== CONT TestRateLimiterFeedback/503_enables_limiter311=== CONT TestParsePathInfoJSON/whitespace_only312=== CONT TestParsePathInfoJSON/empty_input313=== CONT TestParsePathInfoJSON/Lix_format314=== CONT TestGetStorePathHash/basename_without_hyphen_should_error315=== CONT TestSetClientTLS/preserves_debug_logging_transport316--- PASS: TestPathInfoHashCompatibility (0.03s)317 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)318 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)319 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)320 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)321=== CONT TestPartSizeForNAR/1_TiB322--- PASS: TestUploadMultipart_SupersededByPeer (0.03s)323 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)324 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)325=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths326=== CONT TestParsePathInfoJSON/invalid_JSON327--- PASS: TestPathInfoCACompatibility (0.03s)328 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)329 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)330 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)331 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)332 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)333--- PASS: TestConvertHashToNix32 (0.03s)334 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)335 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)336 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)337--- PASS: TestParsePathInfoJSONMultiplePaths (0.04s)338 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)339 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)340--- PASS: TestEncodeNixBase32 (0.00s)341 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)342 --- PASS: TestEncodeNixBase32/empty_input (0.00s)343=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA344--- PASS: TestFilterOversizedClosures (0.03s)345 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)346 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)347 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)348--- PASS: TestPartSizeForNAR (0.00s)349 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)350 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)351 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)352 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)353 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)354 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)355 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)3562026/10/01 09:47:11 WARN Rate limiter enabled after throttle name=server-test rate=5357--- PASS: TestGetStorePathHash (0.04s)358 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)359 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)360 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)361 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)3622026/10/01 09:47:11 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:44493363--- PASS: TestParsePathInfoJSON (0.04s)364 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)365 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)366 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)367 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)368 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)369--- PASS: TestSetClientTLSErrors (0.04s)370 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)371 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)372 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)373 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)3742026/10/01 09:47:11 WARN Rate limiter backed off name=server-test rate=5375--- PASS: TestRateLimiterFeedback (0.04s)376 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)377 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)378 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)379 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)3802026/10/01 09:47:11 http: TLS handshake error from 127.0.0.1:53004: remote error: tls: bad certificate381--- PASS: TestSetClientTLS (0.03s)382 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)383 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)384 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)385--- PASS: TestRegisterUploadedObjectReusesConnections (0.02s)386--- PASS: TestStreamPushRequestLine (0.03s)387--- PASS: TestDumpPathSingleFile (0.06s)388--- PASS: TestCaseHackSuffix (0.03s)389--- PASS: TestDumpPathWriterError (0.07s)390--- PASS: TestStreamPushBatchesUnderLoad (0.10s)391--- PASS: TestDumpPathMatchesNix (0.11s)392--- PASS: TestUploadMultipart_PartsInParallel (0.65s)393--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)394PASS395Running server tests...396The files belonging to this database system will be owned by user "nixbld".397This user must also own the server process.398399The database cluster will be initialized with locale "C".400The default database encoding has accordingly been set to "SQL_ASCII".401The default text search configuration will be set to "english".402403Data page checksums are enabled.404405creating directory /build/postgres2139389107/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/postgres2139389107/data -l logfile start422423/build/postgres2139389107:5432 - no response4242026-10-01 09:47:12.746 UTC [129] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-10-01 09:47:12.747 UTC [129] LOG: listening on Unix socket "/build/postgres2139389107/.s.PGSQL.5432"4262026-10-01 09:47:12.751 UTC [136] LOG: database system was shut down at 2026-10-01 09:47:12 UTC4272026-10-01 09:47:12.754 UTC [129] LOG: database system is ready to accept connections428/build/postgres2139389107:5432 - accepting connections429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestClientPushesUseOnePush462=== PAUSE TestClientPushesUseOnePush463=== RUN TestClientFallsBackToClosures464=== PAUSE TestClientFallsBackToClosures465=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock466=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock467=== RUN TestResolveDBConnectionString468=== PAUSE TestResolveDBConnectionString469=== RUN TestLeadElectsOneAndHandsOver470=== PAUSE TestLeadElectsOneAndHandsOver471=== RUN TestLeadIncumbentWinsAfterRestart4722026-10-01 09:47:13.125 UTC [376] ERROR: relation "goose_db_version" does not exist at character 364732026-10-01 09:47:13.125 UTC [376] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4742026/10/01 09:47:13 OK 20241026095416_initial_model.sql (9.93ms)4752026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.84ms)4762026/10/01 09:47:13 OK 20251218171726_add_pins.sql (2.87ms)4772026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (2.71ms)4782026/10/01 09:47:13 OK 20260905000000_add_claims.sql (2.84ms)4792026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (1.73ms)4802026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (1.27ms)4812026/10/01 09:47:13 goose: successfully migrated database to version: 202609231200004822026/10/01 09:47:13 OK 1_commit_pending_closure.sql (1.57ms)4832026/10/01 09:47:13 OK 2_object_stats_trigger.sql (623.31µs)4842026/10/01 09:47:13 OK 3_commit_push.sql (511.11µs)4852026/10/01 09:47:13 goose: up to current file version: 34862026/10/01 09:47:13 INFO lead: acquired remote=192.0.2.1:12344872026/10/01 09:47:13 INFO lead: released remote=192.0.2.1:12344882026/10/01 09:47:13 INFO lead: acquired remote=192.0.2.1:12344892026/10/01 09:47:13 INFO lead: released remote=192.0.2.1:1234490--- PASS: TestLeadIncumbentWinsAfterRestart (0.78s)491=== RUN TestLeadEndsOnShutdown492=== PAUSE TestLeadEndsOnShutdown493=== RUN TestGCAdvisoryLockBlocksConcurrentRun4942026-10-01 09:47:13.890 UTC [387] ERROR: relation "goose_db_version" does not exist at character 364952026-10-01 09:47:13.890 UTC [387] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4962026/10/01 09:47:13 OK 20241026095416_initial_model.sql (8.77ms)4972026/10/01 09:47:13 OK 20251210153512_drop_unused_gin_index.sql (1.53ms)4982026/10/01 09:47:13 OK 20251218171726_add_pins.sql (2.73ms)4992026/10/01 09:47:13 OK 20260628120000_add_object_size_and_stats.sql (2.76ms)5002026/10/01 09:47:13 OK 20260905000000_add_claims.sql (2.31ms)5012026/10/01 09:47:13 OK 20260920000000_drop_claims.sql (1.47ms)5022026/10/01 09:47:13 OK 20260923120000_add_pushes.sql (1.04ms)5032026/10/01 09:47:13 goose: successfully migrated database to version: 202609231200005042026/10/01 09:47:13 OK 1_commit_pending_closure.sql (1.5ms)5052026/10/01 09:47:13 OK 2_object_stats_trigger.sql (654.63µs)5062026/10/01 09:47:13 OK 3_commit_push.sql (500.84µs)5072026/10/01 09:47:13 goose: up to current file version: 3508--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.12s)509=== RUN TestGCBugBareHashReferences510=== PAUSE TestGCBugBareHashReferences511=== RUN TestGCMetrics512=== PAUSE TestGCMetrics513=== RUN TestPushDedupSurvivesConcurrentGC514=== PAUSE TestPushDedupSurvivesConcurrentGC515=== RUN TestDeduplicatedObjectsRecordedAsPending516=== PAUSE TestDeduplicatedObjectsRecordedAsPending517=== RUN TestGCSweepSkipsPendingObjects518=== PAUSE TestGCSweepSkipsPendingObjects519=== RUN TestTombstonedObjectOfferedWithoutWaiting520=== PAUSE TestTombstonedObjectOfferedWithoutWaiting521=== RUN TestGCSweepDeliversEachKeyOnce522=== PAUSE TestGCSweepDeliversEachKeyOnce523=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection524=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== RUN TestForceGCDuringPushOffersSweptObject526=== PAUSE TestForceGCDuringPushOffersSweptObject527=== RUN TestFailedS3DeleteKeepsTombstone528=== PAUSE TestFailedS3DeleteKeepsTombstone529=== RUN TestSweepSkipsRowsLockedByPush530=== PAUSE TestSweepSkipsRowsLockedByPush531=== RUN TestRegisterCompletedObjectNeedsPendingRow532=== PAUSE TestRegisterCompletedObjectNeedsPendingRow533=== RUN TestGetExistingObjectsLocksRows534=== PAUSE TestGetExistingObjectsLocksRows535=== RUN TestSweepRechecksPendingAfterLocking536=== PAUSE TestSweepRechecksPendingAfterLocking537=== RUN TestPushWaitsForSweepHoldingRow538=== PAUSE TestPushWaitsForSweepHoldingRow539=== RUN TestCommitRacingPendingCleanupKeepsObjects540=== PAUSE TestCommitRacingPendingCleanupKeepsObjects541=== RUN TestGCEndsOnShutdown542=== PAUSE TestGCEndsOnShutdown543=== RUN TestGCTaskStore_StartNew544=== PAUSE TestGCTaskStore_StartNew545=== RUN TestGCTaskStore_DeduplicateSameParams546=== PAUSE TestGCTaskStore_DeduplicateSameParams547=== RUN TestGCTaskStore_ConflictDifferentParams548=== PAUSE TestGCTaskStore_ConflictDifferentParams549=== RUN TestGCTaskStore_GetEmpty550=== PAUSE TestGCTaskStore_GetEmpty551=== RUN TestGCTaskStore_GetReturnsLatest552=== PAUSE TestGCTaskStore_GetReturnsLatest553=== RUN TestGCTaskStore_CompletedAllowsNewTask554=== PAUSE TestGCTaskStore_CompletedAllowsNewTask555=== RUN TestGCTaskStore_PhaseUpdates556=== PAUSE TestGCTaskStore_PhaseUpdates557=== RUN TestGCTaskStore_Fail558=== PAUSE TestGCTaskStore_Fail559=== RUN TestGracefulShutdownDrainsInflight560=== PAUSE TestGracefulShutdownDrainsInflight561=== RUN TestService_healthCheckHandler562=== PAUSE TestService_healthCheckHandler563=== RUN TestService_readinessHandler564=== PAUSE TestService_readinessHandler565=== RUN TestGenerateLandingPage566=== PAUSE TestGenerateLandingPage567=== RUN TestCacheConfigHandlerMaxNarSize568=== PAUSE TestCacheConfigHandlerMaxNarSize569=== RUN TestCreatePendingClosureRejectsOversizedNAR570=== PAUSE TestCreatePendingClosureRejectsOversizedNAR571=== RUN TestNARDeduplicationMetadataUploadBug572=== PAUSE TestNARDeduplicationMetadataUploadBug573=== RUN TestMetricsInventory574=== PAUSE TestMetricsInventory575=== RUN TestService_NativeMTLS576=== PAUSE TestService_NativeMTLS577=== RUN TestServerTLSConfig578=== PAUSE TestServerTLSConfig579=== RUN TestMultipartCleanup580=== PAUSE TestMultipartCleanup581=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded582=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== RUN TestPendingCleanupUsesOneCutoff584=== PAUSE TestPendingCleanupUsesOneCutoff585=== RUN TestObjectStatsTrigger586=== PAUSE TestObjectStatsTrigger587=== RUN TestOrphanedObjectsGC588=== PAUSE TestOrphanedObjectsGC589=== RUN TestOrphanedObjectsGCStressTest590=== PAUSE TestOrphanedObjectsGCStressTest591=== RUN TestCreatePin_ReservedPins592=== PAUSE TestCreatePin_ReservedPins593=== RUN TestPresentReportsOnlyClosureRoots594=== PAUSE TestPresentReportsOnlyClosureRoots595=== RUN TestPresentNotReportedWhileGCDeletesClosure596=== PAUSE TestPresentNotReportedWhileGCDeletesClosure597=== RUN TestParseSingleRange598=== PAUSE TestParseSingleRange599=== RUN TestProxyHeadersOnlyTrustedOnSocket600=== PAUSE TestProxyHeadersOnlyTrustedOnSocket601=== RUN TestIsValidCachePath602=== PAUSE TestIsValidCachePath603=== RUN TestReadProxyNarinfo604=== PAUSE TestReadProxyNarinfo605=== RUN TestReadProxyNarinfoAlreadyDecompressed606=== PAUSE TestReadProxyNarinfoAlreadyDecompressed607=== RUN TestReadProxyNarStreaming608=== PAUSE TestReadProxyNarStreaming609=== RUN TestReadProxy404610=== PAUSE TestReadProxy404611=== RUN TestReadProxyInvalidPath612=== PAUSE TestReadProxyInvalidPath613=== RUN TestReadProxyHead614=== PAUSE TestReadProxyHead615=== RUN TestReadProxyConditionalGet616=== PAUSE TestReadProxyConditionalGet617=== RUN TestReadProxyRootRedirectsToIndexHTML618=== PAUSE TestReadProxyRootRedirectsToIndexHTML619=== RUN TestReadProxyDisabled620=== PAUSE TestReadProxyDisabled621=== RUN TestReadRedirectNar622=== PAUSE TestReadRedirectNar623=== RUN TestReadRedirectKeepsNarinfoProxied624=== PAUSE TestReadRedirectKeepsNarinfoProxied625=== RUN TestReadProxyRangeRequest626=== PAUSE TestReadProxyRangeRequest627=== RUN TestReadRedirectUsesPublicS3URL628=== PAUSE TestReadRedirectUsesPublicS3URL629=== RUN TestPush_OverlappingRootsStoreOneRowPerKey630=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey631=== RUN TestPush_CompleteCommitsEveryRoot632=== PAUSE TestPush_CompleteCommitsEveryRoot633=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit634=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit635=== RUN TestPush_RejectsBadRequests636=== PAUSE TestPush_RejectsBadRequests637=== RUN TestPush_SignsNarinfosOfItsPendingObjects638=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects639=== RUN TestRedundantMultipartUpload640=== PAUSE TestRedundantMultipartUpload641=== RUN TestCompleteMultipartUpload_ErrorButObjectExists642=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists643=== RUN TestCompletedNarNotReofferedAcrossClosures644=== PAUSE TestCompletedNarNotReofferedAcrossClosures645=== RUN TestPresignedUploadRegisteredBeforeCommit646=== PAUSE TestPresignedUploadRegisteredBeforeCommit647=== RUN TestService_Rustfstest648=== PAUSE TestService_Rustfstest649=== RUN TestParseSize650=== PAUSE TestParseSize651=== RUN TestSkippedUploadsHandler652=== PAUSE TestSkippedUploadsHandler653=== RUN TestSystemdListenerNotActivated654--- PASS: TestSystemdListenerNotActivated (0.00s)655=== RUN TestWatchdogBeatsWhenHealthy656--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)657=== RUN TestWatchdogSkipsWhenUnhealthy6582026/10/01 09:47:13 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6592026/10/01 09:47:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6602026/10/01 09:47:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6612026/10/01 09:47:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6622026/10/01 09:47:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6632026/10/01 09:47:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6642026/10/01 09:47:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6652026/10/01 09:47:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6662026/10/01 09:47:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6672026/10/01 09:47:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"668--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)669=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle670=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle671=== RUN TestProxyWriteTimeout672=== PAUSE TestProxyWriteTimeout673=== RUN TestIsValidUploadKey674=== PAUSE TestIsValidUploadKey675=== RUN TestUploadHandlersRejectInvalidKeys676=== PAUSE TestUploadHandlersRejectInvalidKeys677=== RUN TestUploadHandlersRejectOversizedBody678=== PAUSE TestUploadHandlersRejectOversizedBody679=== RUN TestService_cleanupPendingClosuresHandler680=== PAUSE TestService_cleanupPendingClosuresHandler681=== RUN TestService_createPendingClosureHandler682=== PAUSE TestService_createPendingClosureHandler683=== RUN TestService_verifyS3Integrity684=== PAUSE TestService_verifyS3Integrity685=== RUN TestCompleteMultipartUnregistered686=== PAUSE TestCompleteMultipartUnregistered687=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT688=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT689=== CONT TestParseSize690=== CONT TestCompletedNarNotReofferedAcrossClosures691=== CONT TestCompleteMultipartUpload_ErrorButObjectExists692=== CONT TestPushWaitsForSweepHoldingRow693=== CONT TestGCMetrics694=== CONT TestGCTaskStore_PhaseUpdates695=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT696=== CONT TestUploadHandlersRejectInvalidKeys697=== CONT TestPresignedUploadRegisteredBeforeCommit698=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info699=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info700=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal701=== CONT TestGCTaskStore_CompletedAllowsNewTask702=== CONT TestGCTaskStore_GetReturnsLatest703=== CONT TestService_cleanupPendingClosuresHandler704=== CONT TestCompleteMultipartUnregistered705=== CONT TestGCTaskStore_ConflictDifferentParams706=== CONT TestReadProxyInvalidPath707=== CONT TestGCTaskStore_DeduplicateSameParams708=== CONT TestReadRedirectNar709=== CONT TestGCTaskStore_StartNew710=== CONT TestReadProxyDisabled711=== CONT TestGCEndsOnShutdown712--- PASS: TestParseSize (0.00s)713--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)714=== CONT TestCommitRacingPendingCleanupKeepsObjects715=== CONT TestService_AuthMiddleware716=== CONT TestIsValidUploadKey717=== CONT TestProxyWriteTimeout718=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle719=== CONT TestSkippedUploadsHandler720=== CONT TestUploadHandlersRejectOversizedBody721=== CONT TestService_verifyS3Integrity722=== CONT TestService_createPendingClosureHandler723=== CONT TestService_Rustfstest724=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal725=== CONT TestGCTaskStore_GetEmpty726--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)727--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)728--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)729--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)730--- PASS: TestGCTaskStore_StartNew (0.00s)731=== RUN TestProxyWriteTimeout/narinfo732=== PAUSE TestProxyWriteTimeout/narinfo733=== RUN TestProxyWriteTimeout/1_GiB_nar734=== PAUSE TestProxyWriteTimeout/1_GiB_nar735=== RUN TestProxyWriteTimeout/10_GiB_nar736=== PAUSE TestProxyWriteTimeout/10_GiB_nar737=== RUN TestProxyWriteTimeout/unknown_size738=== PAUSE TestProxyWriteTimeout/unknown_size739=== CONT TestRedundantMultipartUpload740=== RUN TestIsValidUploadKey/narinfo741=== PAUSE TestIsValidUploadKey/narinfo742=== RUN TestIsValidUploadKey/nar_zst743=== PAUSE TestIsValidUploadKey/nar_zst744=== RUN TestIsValidUploadKey/nar_xz745=== PAUSE TestIsValidUploadKey/nar_xz746=== RUN TestIsValidUploadKey/nar_plain747=== PAUSE TestIsValidUploadKey/nar_plain748=== RUN TestIsValidUploadKey/listing749=== PAUSE TestIsValidUploadKey/listing750=== RUN TestIsValidUploadKey/build_log751=== PAUSE TestIsValidUploadKey/build_log752=== RUN TestIsValidUploadKey/build_log_home-manager_file753=== PAUSE TestIsValidUploadKey/build_log_home-manager_file754=== RUN TestIsValidUploadKey/build_log_plus_in_name755=== PAUSE TestIsValidUploadKey/build_log_plus_in_name756=== RUN TestIsValidUploadKey/build_log_question_mark757=== PAUSE TestIsValidUploadKey/build_log_question_mark758=== RUN TestIsValidUploadKey/build_log_equals759=== PAUSE TestIsValidUploadKey/build_log_equals760=== RUN TestIsValidUploadKey/realisation761=== PAUSE TestIsValidUploadKey/realisation762=== RUN TestIsValidUploadKey/realisation_plus_in_output763=== PAUSE TestIsValidUploadKey/realisation_plus_in_output764=== RUN TestIsValidUploadKey/nix-cache-info765=== PAUSE TestIsValidUploadKey/nix-cache-info766=== RUN TestIsValidUploadKey/index.html767=== PAUSE TestIsValidUploadKey/index.html768--- PASS: TestGCTaskStore_GetEmpty (0.00s)769=== RUN TestIsValidUploadKey/narinfo_key,_nar_type770=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key771=== CONT TestReadProxyRootRedirectsToIndexHTML772=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type773=== RUN TestIsValidUploadKey/nar_key,_narinfo_type774=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type775=== RUN TestIsValidUploadKey/listing_key,_narinfo_type776=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key777=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type778=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key779=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key780=== RUN TestIsValidUploadKey/traversal7812026/10/01 09:47:14 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000782=== PAUSE TestIsValidUploadKey/traversal783=== CONT TestPush_SignsNarinfosOfItsPendingObjects784=== RUN TestIsValidUploadKey/traversal_nar785=== PAUSE TestIsValidUploadKey/traversal_nar786=== RUN TestIsValidUploadKey/absolute787=== PAUSE TestIsValidUploadKey/absolute788=== RUN TestIsValidUploadKey/empty_key789=== PAUSE TestIsValidUploadKey/empty_key790=== RUN TestIsValidUploadKey/unknown_type791=== PAUSE TestIsValidUploadKey/unknown_type792=== CONT TestReadProxyConditionalGet793--- PASS: TestSkippedUploadsHandler (0.07s)794=== CONT TestProxyHeadersOnlyTrustedOnSocket7952026-10-01 09:47:14.312 UTC [456] ERROR: relation "goose_db_version" does not exist at character 367962026-10-01 09:47:14.312 UTC [456] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7972026-10-01 09:47:14.313 UTC [457] ERROR: relation "goose_db_version" does not exist at character 367982026-10-01 09:47:14.313 UTC [457] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7992026-10-01 09:47:14.315 UTC [458] ERROR: relation "goose_db_version" does not exist at character 368002026-10-01 09:47:14.315 UTC [458] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8012026-10-01 09:47:14.316 UTC [459] ERROR: relation "goose_db_version" does not exist at character 368022026-10-01 09:47:14.316 UTC [459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8032026-10-01 09:47:14.317 UTC [460] ERROR: relation "goose_db_version" does not exist at character 368042026-10-01 09:47:14.317 UTC [460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC805=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure806=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure807=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart808=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart809=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts810=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts811=== CONT TestReadProxyHead8122026-10-01 09:47:14.317 UTC [461] ERROR: relation "goose_db_version" does not exist at character 368132026-10-01 09:47:14.317 UTC [461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8142026/10/01 09:47:14 OK 20241026095416_initial_model.sql (60.6ms)8152026/10/01 09:47:14 OK 20241026095416_initial_model.sql (59.12ms)8162026/10/01 09:47:14 OK 20241026095416_initial_model.sql (59.02ms)8172026-10-01 09:47:14.408 UTC [466] ERROR: relation "goose_db_version" does not exist at character 368182026-10-01 09:47:14.408 UTC [466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8192026-10-01 09:47:14.409 UTC [468] ERROR: relation "goose_db_version" does not exist at character 368202026-10-01 09:47:14.409 UTC [468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8212026-10-01 09:47:14.409 UTC [467] ERROR: relation "goose_db_version" does not exist at character 368222026-10-01 09:47:14.409 UTC [467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8232026/10/01 09:47:14 OK 20241026095416_initial_model.sql (61.56ms)8242026/10/01 09:47:14 OK 20241026095416_initial_model.sql (62.81ms)8252026/10/01 09:47:14 OK 20241026095416_initial_model.sql (61.53ms)8262026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (4.38ms)8272026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (4.39ms)8282026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (4.35ms)8292026-10-01 09:47:14.414 UTC [469] ERROR: relation "goose_db_version" does not exist at character 368302026-10-01 09:47:14.414 UTC [469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8312026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (4.09ms)8322026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (4.27ms)8332026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (4.2ms)8342026-10-01 09:47:14.417 UTC [470] ERROR: relation "goose_db_version" does not exist at character 368352026-10-01 09:47:14.417 UTC [470] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8362026-10-01 09:47:14.422 UTC [471] ERROR: relation "goose_db_version" does not exist at character 368372026-10-01 09:47:14.422 UTC [471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8382026-10-01 09:47:14.423 UTC [472] ERROR: relation "goose_db_version" does not exist at character 368392026-10-01 09:47:14.423 UTC [472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8402026/10/01 09:47:14 OK 20251218171726_add_pins.sql (12.71ms)8412026/10/01 09:47:14 OK 20251218171726_add_pins.sql (14.49ms)8422026/10/01 09:47:14 OK 20251218171726_add_pins.sql (10.52ms)8432026/10/01 09:47:14 OK 20251218171726_add_pins.sql (10.47ms)8442026/10/01 09:47:14 OK 20251218171726_add_pins.sql (10.72ms)8452026/10/01 09:47:14 OK 20251218171726_add_pins.sql (14.6ms)8462026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (6.91ms)8472026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (5.57ms)8482026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (5.31ms)8492026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (5.46ms)8502026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (5.35ms)8512026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (5.58ms)8522026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.28ms)8532026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.52ms)8542026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.43ms)8552026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.47ms)8562026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.53ms)8572026/10/01 09:47:14 OK 20260905000000_add_claims.sql (5.3ms)8582026-10-01 09:47:14.438 UTC [474] ERROR: relation "goose_db_version" does not exist at character 368592026-10-01 09:47:14.438 UTC [474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8602026-10-01 09:47:14.438 UTC [473] ERROR: relation "goose_db_version" does not exist at character 368612026-10-01 09:47:14.438 UTC [473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8622026-10-01 09:47:14.439 UTC [475] ERROR: relation "goose_db_version" does not exist at character 368632026-10-01 09:47:14.439 UTC [475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8642026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.11ms)8652026/10/01 09:47:14 OK 20241026095416_initial_model.sql (11.88ms)8662026/10/01 09:47:14 OK 20241026095416_initial_model.sql (12.48ms)8672026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.39ms)8682026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.6ms)8692026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.57ms)8702026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.5ms)8712026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (4.25ms)8722026/10/01 09:47:14 OK 20241026095416_initial_model.sql (13.68ms)8732026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.98ms)8742026/10/01 09:47:14 goose: successfully migrated database to version: 202609231200008752026/10/01 09:47:14 OK 20241026095416_initial_model.sql (14.54ms)8762026-10-01 09:47:14.443 UTC [476] ERROR: relation "goose_db_version" does not exist at character 368772026-10-01 09:47:14.443 UTC [476] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8782026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.83ms)8792026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.8ms)8802026/10/01 09:47:14 goose: successfully migrated database to version: 202609231200008812026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (3ms)8822026-10-01 09:47:14.444 UTC [477] ERROR: relation "goose_db_version" does not exist at character 368832026-10-01 09:47:14.444 UTC [477] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8842026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.87ms)8852026/10/01 09:47:14 goose: successfully migrated database to version: 202609231200008862026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (3.71ms)8872026/10/01 09:47:14 goose: successfully migrated database to version: 202609231200008882026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (3.64ms)8892026-10-01 09:47:14.444 UTC [478] ERROR: relation "goose_db_version" does not exist at character 368902026-10-01 09:47:14.444 UTC [478] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8912026/10/01 09:47:14 goose: successfully migrated database to version: 202609231200008922026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.73ms)8932026-10-01 09:47:14.444 UTC [479] ERROR: relation "goose_db_version" does not exist at character 368942026-10-01 09:47:14.444 UTC [479] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8952026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (3.83ms)8962026/10/01 09:47:14 goose: successfully migrated database to version: 202609231200008972026-10-01 09:47:14.445 UTC [480] ERROR: relation "goose_db_version" does not exist at character 368982026-10-01 09:47:14.445 UTC [480] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8992026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.97ms)9002026/10/01 09:47:14 OK 1_commit_pending_closure.sql (3.69ms)9012026/10/01 09:47:14 OK 20241026095416_initial_model.sql (14.98ms)9022026/10/01 09:47:14 OK 1_commit_pending_closure.sql (3.41ms)9032026/10/01 09:47:14 OK 20251218171726_add_pins.sql (4.63ms)9042026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.95ms)9052026/10/01 09:47:14 OK 1_commit_pending_closure.sql (3.05ms)9062026/10/01 09:47:14 OK 1_commit_pending_closure.sql (3.17ms)9072026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.81ms)9082026/10/01 09:47:14 OK 2_object_stats_trigger.sql (2.04ms)9092026/10/01 09:47:14 OK 1_commit_pending_closure.sql (3.54ms)9102026/10/01 09:47:14 OK 20251218171726_add_pins.sql (5.45ms)9112026-10-01 09:47:14.449 UTC [481] ERROR: relation "goose_db_version" does not exist at character 369122026-10-01 09:47:14.449 UTC [481] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9132026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.71ms)9142026/10/01 09:47:14 OK 2_object_stats_trigger.sql (2.22ms)9152026/10/01 09:47:14 OK 20241026095416_initial_model.sql (14.3ms)9162026/10/01 09:47:14 OK 2_object_stats_trigger.sql (2.14ms)9172026/10/01 09:47:14 OK 20251218171726_add_pins.sql (5.3ms)9182026/10/01 09:47:14 OK 2_object_stats_trigger.sql (2.33ms)9192026/10/01 09:47:14 OK 3_commit_push.sql (2.36ms)9202026/10/01 09:47:14 OK 20251218171726_add_pins.sql (5.05ms)9212026/10/01 09:47:14 goose: up to current file version: 39222026/10/01 09:47:14 OK 20241026095416_initial_model.sql (15.9ms)9232026/10/01 09:47:14 OK 3_commit_push.sql (2.02ms)9242026/10/01 09:47:14 goose: up to current file version: 39252026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.99ms)9262026/10/01 09:47:14 OK 3_commit_push.sql (2.52ms)9272026/10/01 09:47:14 goose: up to current file version: 39282026/10/01 09:47:14 OK 3_commit_push.sql (2.3ms)9292026/10/01 09:47:14 goose: up to current file version: 39302026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.94ms)9312026/10/01 09:47:14 OK 3_commit_push.sql (2.21ms)9322026/10/01 09:47:14 goose: up to current file version: 39332026/10/01 09:47:14 OK 3_commit_push.sql (2.32ms)9342026/10/01 09:47:14 goose: up to current file version: 39352026-10-01 09:47:14.454 UTC [482] ERROR: relation "goose_db_version" does not exist at character 369362026-10-01 09:47:14.454 UTC [482] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC9372026/10/01 09:47:14 OK 20251218171726_add_pins.sql (4.94ms)9382026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (5.46ms)9392026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (4.36ms)9402026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.76ms)9412026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (5.39ms)9422026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (5ms)9432026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.35ms)9442026/10/01 09:47:14 OK 20241026095416_initial_model.sql (12.05ms)9452026/10/01 09:47:14 OK 20241026095416_initial_model.sql (11.83ms)9462026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.3ms)9472026/10/01 09:47:14 OK 20241026095416_initial_model.sql (12.13ms)9482026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.34ms)9492026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.06ms)9502026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.29ms)9512026/10/01 09:47:14 OK 20251218171726_add_pins.sql (5.53ms)9522026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (5.84ms)9532026/10/01 09:47:14 OK 20251218171726_add_pins.sql (4.61ms)9542026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.63ms)9552026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.63ms)9562026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.44ms)9572026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.81ms)9582026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.93ms)9592026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.79ms)9602026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.27ms)9612026/10/01 09:47:14 goose: successfully migrated database to version: 202609231200009622026/10/01 09:47:14 OK 20241026095416_initial_model.sql (11.5ms)9632026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.83ms)9642026/10/01 09:47:14 goose: successfully migrated database to version: 202609231200009652026/10/01 09:47:14 OK 20241026095416_initial_model.sql (12.23ms)9662026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.64ms)9672026/10/01 09:47:14 goose: successfully migrated database to version: 202609231200009682026/10/01 09:47:14 OK 20241026095416_initial_model.sql (14.99ms)9692026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.87ms)9702026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.93ms)9712026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.88ms)9722026/10/01 09:47:14 goose: successfully migrated database to version: 202609231200009732026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.65ms)9742026/10/01 09:47:14 OK 20251218171726_add_pins.sql (4.8ms)9752026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (5.05ms)9762026/10/01 09:47:14 OK 20251218171726_add_pins.sql (4.73ms)9772026/10/01 09:47:14 OK 20251218171726_add_pins.sql (5.3ms)9782026/10/01 09:47:14 OK 20241026095416_initial_model.sql (13.72ms)9792026/10/01 09:47:14 OK 20241026095416_initial_model.sql (13.96ms)9802026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.57ms)9812026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.3ms)9822026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.21ms)9832026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.59ms)9842026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.8ms)9852026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.49ms)9862026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.7ms)9872026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.64ms)9882026/10/01 09:47:14 OK 3_commit_push.sql (1.5ms)9892026/10/01 09:47:14 goose: up to current file version: 39902026/10/01 09:47:14 OK 20241026095416_initial_model.sql (12.05ms)9912026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.23ms)9922026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.31ms)9932026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.47ms)9942026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.4ms)9952026/10/01 09:47:14 OK 2_object_stats_trigger.sql (2.34ms)9962026/10/01 09:47:14 OK 2_object_stats_trigger.sql (2.26ms)9972026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.53ms)9982026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.2ms)9992026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010002026/10/01 09:47:14 OK 2_object_stats_trigger.sql (2.12ms)10012026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.96ms)10022026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.86ms)10032026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.9ms)10042026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.06ms)10052026/10/01 09:47:14 OK 3_commit_push.sql (1.7ms)10062026/10/01 09:47:14 OK 3_commit_push.sql (1.77ms)10072026/10/01 09:47:14 goose: up to current file version: 310082026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures10092026/10/01 09:47:14 goose: up to current file version: 310102026/10/01 09:47:14 OK 20251218171726_add_pins.sql (4.56ms)10112026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.78ms)10122026/10/01 09:47:14 OK 3_commit_push.sql (2.28ms)10132026/10/01 09:47:14 goose: up to current file version: 310142026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.25ms)10152026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.8ms)10162026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.95ms)10172026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.67ms)10182026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.38ms)10192026/10/01 09:47:14 OK 20251218171726_add_pins.sql (4.66ms)10202026/10/01 09:47:14 OK 20241026095416_initial_model.sql (13.13ms)10212026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.25ms)10222026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.2ms)10232026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.44ms)10242026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (1.78ms)10252026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010262026/10/01 09:47:14 OK 20260905000000_add_claims.sql (2.98ms)10272026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.12ms)10282026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.26ms)10292026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (1.62ms)10302026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.22ms)10312026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010322026/10/01 09:47:14 OK 3_commit_push.sql (988.87µs)10332026/10/01 09:47:14 goose: up to current file version: 310342026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.88ms)10352026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.56ms)10362026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.9ms)10372026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.55ms)10382026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (5.02ms)10392026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.89ms)10402026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.38ms)10412026-10-01 09:47:14.479 UTC [483] ERROR: relation "goose_db_version" does not exist at character 3610422026-10-01 09:47:14.479 UTC [483] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC10432026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.72ms)10442026/10/01 09:47:14 OK 1_commit_pending_closure.sql (3.39ms)10452026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.92ms)10462026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.9ms)10472026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.42ms)10482026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.64ms)10492026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.75ms)10502026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010512026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.71ms)10522026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010532026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.26ms)10542026/10/01 09:47:14 OK 3_commit_push.sql (1.11ms)10552026/10/01 09:47:14 goose: up to current file version: 310562026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.61ms)10572026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010582026/10/01 09:47:14 OK 2_object_stats_trigger.sql (2.18ms)10592026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.09ms)10602026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.88ms)10612026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.94ms)10622026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.47ms)10632026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.6ms)10642026/10/01 09:47:14 OK 3_commit_push.sql (806.83µs)10652026/10/01 09:47:14 goose: up to current file version: 310662026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.11ms)10672026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.69ms)10682026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.44ms)10692026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.68ms)10702026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.27ms)10712026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (1.99ms)10722026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.36ms)10732026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.43ms)1074--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.32s)1075=== CONT TestReadProxy40410762026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.39ms)10772026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.47ms)10782026/10/01 09:47:14 OK 3_commit_push.sql (1.56ms)10792026/10/01 09:47:14 goose: up to current file version: 310802026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.21ms)10812026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.29ms)10822026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010832026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010842026/10/01 09:47:14 OK 3_commit_push.sql (5.89ms)10852026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (6.14ms)10862026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (5.12ms)10872026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010882026/10/01 09:47:14 goose: up to current file version: 310892026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (6.51ms)10902026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010912026/10/01 09:47:14 OK 1_commit_pending_closure.sql (4.17ms)10922026/10/01 09:47:14 OK 2_object_stats_trigger.sql (5.97ms)10932026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010942026/10/01 09:47:14 OK 1_commit_pending_closure.sql (4.06ms)10952026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (5.75ms)10962026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000010972026/10/01 09:47:14 OK 20260905000000_add_claims.sql (7.91ms)10982026/10/01 09:47:14 OK 3_commit_push.sql (1.34ms)10992026/10/01 09:47:14 goose: up to current file version: 311002026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures11012026/10/01 09:47:14 OK 1_commit_pending_closure.sql (1.61ms)11022026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.63ms)11032026/10/01 09:47:14 OK 1_commit_pending_closure.sql (1.97ms)11042026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.8ms)11052026/10/01 09:47:14 OK 1_commit_pending_closure.sql (1.85ms)11062026/10/01 09:47:14 OK 1_commit_pending_closure.sql (1.77ms)11072026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (1.9ms)11082026/10/01 09:47:14 OK 2_object_stats_trigger.sql (793.91µs)11092026/10/01 09:47:14 OK 3_commit_push.sql (687.67µs)11102026/10/01 09:47:14 goose: up to current file version: 311112026/10/01 09:47:14 OK 2_object_stats_trigger.sql (783.47µs)11122026/10/01 09:47:14 OK 2_object_stats_trigger.sql (898.67µs)11132026/10/01 09:47:14 OK 3_commit_push.sql (937.87µs)11142026/10/01 09:47:14 goose: up to current file version: 311152026/10/01 09:47:14 OK 20241026095416_initial_model.sql (8.73ms)11162026/10/01 09:47:14 OK 3_commit_push.sql (1.25ms)11172026/10/01 09:47:14 goose: up to current file version: 311182026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.46ms)11192026/10/01 09:47:14 OK 3_commit_push.sql (1.11ms)11202026/10/01 09:47:14 goose: up to current file version: 311212026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (1.78ms)11222026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000011232026/10/01 09:47:14 OK 3_commit_push.sql (1.29ms)11242026/10/01 09:47:14 goose: up to current file version: 311252026/10/01 09:47:14 OK 3_commit_push.sql (481.94µs)11262026/10/01 09:47:14 goose: up to current file version: 311272026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (1.07ms)11282026/10/01 09:47:14 OK 1_commit_pending_closure.sql (1.81ms)11292026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.08ms)11302026/10/01 09:47:14 OK 20251218171726_add_pins.sql (2.61ms)11312026/10/01 09:47:14 OK 3_commit_push.sql (450.54µs)11322026/10/01 09:47:14 goose: up to current file version: 311332026/10/01 09:47:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11342026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.07ms)11352026/10/01 09:47:14 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1136--- PASS: TestCompleteMultipartUnregistered (0.33s)1137=== CONT TestPush_RejectsBadRequests11382026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.09ms)11392026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (1.58ms)11402026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (1.82ms)11412026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000011422026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.06ms)11432026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.1ms)11442026/10/01 09:47:14 OK 3_commit_push.sql (1.41ms)11452026/10/01 09:47:14 goose: up to current file version: 311462026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures11472026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures11482026/10/01 09:47:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11492026/10/01 09:47:14 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NjQ1YWQxZWYtMzliNS00MDBkLTk3YjAtMjVhYzA3NTFhMTUxLjNhNmY1Zjk0LTcyNWQtNDdlYy1hMGRjLWFiOTUwOTBjNGVlZHgxNzkwODQ4MDM0NTE5NzQ0ODky11502026/10/01 09:47:14 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11512026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures11522026/10/01 09:47:14 INFO Aborted multipart uploads count=0 kept=011532026/10/01 09:47:14 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NjQ1YWQxZWYtMzliNS00MDBkLTk3YjAtMjVhYzA3NTFhMTUxLjNhNmY1Zjk0LTcyNWQtNDdlYy1hMGRjLWFiOTUwOTBjNGVlZHgxNzkwODQ4MDM0NTE5NzQ0ODky parts=11154--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.38s)1155=== CONT TestReadProxyNarinfoAlreadyDecompressed1156--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.38s)1157=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit11582026/10/01 09:47:14 WARN Force mode enabled - objects will be deleted immediately without grace period11592026/10/01 09:47:14 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011602026/10/01 09:47:14 INFO Vacuumed table table=pending_closures11612026/10/01 09:47:14 INFO Vacuumed table table=pending_objects1162--- PASS: TestReadProxyInvalidPath (0.39s)11632026/10/01 09:47:14 INFO Vacuumed table table=multipart_uploads1164=== CONT TestReadProxyNarStreaming11652026/10/01 09:47:14 INFO Vacuumed table table=closures11662026/10/01 09:47:14 INFO Vacuumed table table=objects11672026-10-01 09:47:14.560 UTC [494] ERROR: relation "goose_db_version" does not exist at character 3611682026-10-01 09:47:14.560 UTC [494] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1169--- PASS: TestGCMetrics (0.40s)1170=== CONT TestReadProxyNarinfo11712026/10/01 09:47:14 OK 20241026095416_initial_model.sql (8.6ms)11722026/10/01 09:47:14 INFO Received cleanup request method=DELETE path=/api/pending_closures11732026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (1.91ms)11742026/10/01 09:47:14 INFO Aborted multipart uploads count=0 kept=011752026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures11762026-10-01 09:47:14.579 UTC [501] ERROR: relation "goose_db_version" does not exist at character 3611772026-10-01 09:47:14.579 UTC [501] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11782026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.29ms)11792026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.47ms)11802026/10/01 09:47:14 OK 20260905000000_add_claims.sql (2.67ms)11812026/10/01 09:47:14 INFO Received cleanup request method=DELETE path=/api/pending_closures11822026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.72ms)11832026/10/01 09:47:14 INFO Aborted multipart uploads count=1 kept=011842026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (1.67ms)11852026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000011862026/10/01 09:47:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11872026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.18ms)11882026-10-01 09:47:14.593 UTC [468] ERROR: Closure does not exist: id=111892026-10-01 09:47:14.593 UTC [468] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 12 at RAISE11902026-10-01 09:47:14.593 UTC [468] STATEMENT: -- name: CommitPendingClosure :exec1191 SELECT commit_pending_closure($1::bigint)1192 1193--- PASS: TestService_cleanupPendingClosuresHandler (0.42s)1194=== CONT TestPush_CompleteCommitsEveryRoot11952026/10/01 09:47:14 OK 20241026095416_initial_model.sql (9.08ms)11962026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.16ms)11972026/10/01 09:47:14 OK 3_commit_push.sql (924.39µs)11982026/10/01 09:47:14 goose: up to current file version: 311992026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (1.34ms)12002026/10/01 09:47:14 OK 20251218171726_add_pins.sql (2.69ms)12012026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.2ms)1202--- PASS: TestReadRedirectNar (0.43s)1203=== CONT TestForceGCDuringPushOffersSweptObject1204=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1205=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1206=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1207=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1208=== CONT TestIsValidCachePath1209=== RUN TestIsValidCachePath/narinfo1210=== PAUSE TestIsValidCachePath/narinfo1211=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1212=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1213=== RUN TestIsValidCachePath/nar_zst1214=== PAUSE TestIsValidCachePath/nar_zst1215=== RUN TestIsValidCachePath/nar_xz1216=== PAUSE TestIsValidCachePath/nar_xz1217=== RUN TestIsValidCachePath/nar_bz21218=== PAUSE TestIsValidCachePath/nar_bz21219=== RUN TestIsValidCachePath/nar_uncompressed1220=== PAUSE TestIsValidCachePath/nar_uncompressed1221=== RUN TestIsValidCachePath/ls1222=== PAUSE TestIsValidCachePath/ls1223=== RUN TestIsValidCachePath/log1224=== PAUSE TestIsValidCachePath/log1225=== RUN TestIsValidCachePath/realisation1226=== PAUSE TestIsValidCachePath/realisation1227=== RUN TestIsValidCachePath/nix-cache-info1228=== PAUSE TestIsValidCachePath/nix-cache-info1229=== RUN TestIsValidCachePath/index.html1230=== PAUSE TestIsValidCachePath/index.html1231=== RUN TestIsValidCachePath/traversal_parent1232=== PAUSE TestIsValidCachePath/traversal_parent1233=== RUN TestIsValidCachePath/traversal_in_middle1234=== PAUSE TestIsValidCachePath/traversal_in_middle1235=== RUN TestIsValidCachePath/invalid_char_e1236=== PAUSE TestIsValidCachePath/invalid_char_e1237=== RUN TestIsValidCachePath/invalid_char_u1238=== PAUSE TestIsValidCachePath/invalid_char_u1239=== RUN TestIsValidCachePath/random_path1240=== PAUSE TestIsValidCachePath/random_path1241=== RUN TestIsValidCachePath/empty1242=== PAUSE TestIsValidCachePath/empty1243=== RUN TestIsValidCachePath/leading_slash1244=== PAUSE TestIsValidCachePath/leading_slash1245=== RUN TestIsValidCachePath/wrong_extension1246=== PAUSE TestIsValidCachePath/wrong_extension1247=== RUN TestIsValidCachePath/short_hash1248=== PAUSE TestIsValidCachePath/short_hash1249=== CONT TestPush_OverlappingRootsStoreOneRowPerKey12502026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.18ms)12512026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (7.66ms)12522026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.73ms)12532026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000012542026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.34ms)1255--- PASS: TestGCEndsOnShutdown (0.45s)1256=== CONT TestSweepRechecksPendingAfterLocking12572026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.49ms)12582026/10/01 09:47:14 OK 3_commit_push.sql (1.3ms)12592026/10/01 09:47:14 goose: up to current file version: 312602026/10/01 09:47:14 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1261--- PASS: TestService_AuthMiddleware (0.46s)1262=== CONT TestReadRedirectUsesPublicS3URL12632026-10-01 09:47:14.635 UTC [508] ERROR: relation "goose_db_version" does not exist at character 3612642026-10-01 09:47:14.635 UTC [508] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12652026-10-01 09:47:14.635 UTC [509] ERROR: relation "goose_db_version" does not exist at character 3612662026-10-01 09:47:14.635 UTC [509] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12672026-10-01 09:47:14.636 UTC [510] ERROR: relation "goose_db_version" does not exist at character 3612682026-10-01 09:47:14.636 UTC [510] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12692026-10-01 09:47:14.639 UTC [512] ERROR: relation "goose_db_version" does not exist at character 3612702026-10-01 09:47:14.639 UTC [512] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12712026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures12722026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures12732026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures12742026/10/01 09:47:14 OK 20241026095416_initial_model.sql (12.3ms)12752026/10/01 09:47:14 OK 20241026095416_initial_model.sql (12.27ms)12762026/10/01 09:47:14 OK 20241026095416_initial_model.sql (12.49ms)12772026/10/01 09:47:14 OK 20241026095416_initial_model.sql (11.26ms)12782026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (1.86ms)12792026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)12802026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.11ms)12812026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)12822026/10/01 09:47:14 OK 20251218171726_add_pins.sql (8.03ms)12832026/10/01 09:47:14 OK 20251218171726_add_pins.sql (8.72ms)12842026/10/01 09:47:14 OK 20251218171726_add_pins.sql (7.94ms)12852026/10/01 09:47:14 OK 20251218171726_add_pins.sql (8.57ms)12862026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.39ms)12872026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.79ms)12882026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.4ms)12892026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.5ms)1290--- PASS: TestReadProxyDisabled (0.50s)1291=== CONT TestServerTLSConfig1292=== RUN TestServerTLSConfig/no_client_CA1293=== PAUSE TestServerTLSConfig/no_client_CA1294=== RUN TestServerTLSConfig/missing_CA_file1295=== PAUSE TestServerTLSConfig/missing_CA_file1296=== RUN TestServerTLSConfig/not_a_PEM_file1297=== PAUSE TestServerTLSConfig/not_a_PEM_file1298=== CONT TestGetExistingObjectsLocksRows12992026/10/01 09:47:14 OK 20260905000000_add_claims.sql (2.97ms)13002026/10/01 09:47:14 OK 20260905000000_add_claims.sql (2.99ms)13012026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.57ms)13022026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.82ms)13032026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.67ms)13042026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.27ms)13052026-10-01 09:47:14.676 UTC [514] ERROR: relation "goose_db_version" does not exist at character 3613062026-10-01 09:47:14.676 UTC [514] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13072026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.54ms)13082026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000013092026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.21ms)13102026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.8ms)13112026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.14ms)13122026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000013132026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.37ms)13142026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.24ms)13152026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000013162026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.3ms)13172026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000013182026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.16ms)13192026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.22ms)13202026/10/01 09:47:14 OK 3_commit_push.sql (1.57ms)13212026/10/01 09:47:14 goose: up to current file version: 313222026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.22ms)13232026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.17ms)13242026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.58ms)13252026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.37ms)13262026-10-01 09:47:14.684 UTC [517] ERROR: relation "goose_db_version" does not exist at character 3613272026-10-01 09:47:14.684 UTC [517] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13282026/10/01 09:47:14 OK 2_object_stats_trigger.sql (2.22ms)13292026/10/01 09:47:14 OK 3_commit_push.sql (1.85ms)13302026/10/01 09:47:14 goose: up to current file version: 313312026/10/01 09:47:14 OK 3_commit_push.sql (1.24ms)13322026/10/01 09:47:14 goose: up to current file version: 313332026/10/01 09:47:14 OK 3_commit_push.sql (1.14ms)13342026/10/01 09:47:14 goose: up to current file version: 313352026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures13362026/10/01 09:47:14 OK 20241026095416_initial_model.sql (9.75ms)13372026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (1.55ms)13382026-10-01 09:47:14.694 UTC [518] ERROR: relation "goose_db_version" does not exist at character 3613392026-10-01 09:47:14.694 UTC [518] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13402026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.26ms)13412026/10/01 09:47:14 OK 20241026095416_initial_model.sql (10.31ms)13422026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.71ms)13432026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)13442026-10-01 09:47:14.704 UTC [519] ERROR: relation "goose_db_version" does not exist at character 3613452026-10-01 09:47:14.704 UTC [519] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13462026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.37ms)13472026/10/01 09:47:14 OK 20251218171726_add_pins.sql (2.89ms)13482026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.74ms)13492026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.36ms)13502026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.57ms)13512026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000013522026/10/01 09:47:14 OK 20241026095416_initial_model.sql (9.85ms)13532026/10/01 09:47:14 OK 20260905000000_add_claims.sql (2.66ms)13542026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures13552026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.1ms)13562026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.4ms)13572026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.45ms)13582026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.59ms)13592026/10/01 09:47:14 OK 3_commit_push.sql (1.25ms)13602026/10/01 09:47:14 goose: up to current file version: 313612026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.27ms)13622026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000013632026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.79ms)13642026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.2ms)13652026/10/01 09:47:14 OK 20241026095416_initial_model.sql (8.71ms)13662026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.16ms)13672026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.79ms)13682026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)13692026/10/01 09:47:14 OK 3_commit_push.sql (1.08ms)13702026/10/01 09:47:14 goose: up to current file version: 313712026/10/01 09:47:14 OK 20251218171726_add_pins.sql (2.72ms)13722026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.69ms)13732026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.32ms)13742026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.1ms)13752026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (1.92ms)13762026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000013772026/10/01 09:47:14 OK 20260905000000_add_claims.sql (2.36ms)13782026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures13792026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.43ms)13802026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.14ms)13812026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.04ms)13822026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (1.39ms)13832026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000013842026/10/01 09:47:14 OK 3_commit_push.sql (839.33µs)13852026/10/01 09:47:14 goose: up to current file version: 313862026/10/01 09:47:14 OK 1_commit_pending_closure.sql (1.49ms)13872026/10/01 09:47:14 OK 2_object_stats_trigger.sql (679.71µs)13882026/10/01 09:47:14 OK 3_commit_push.sql (502.05µs)13892026/10/01 09:47:14 goose: up to current file version: 313902026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures13912026-10-01 09:47:14.742 UTC [520] ERROR: relation "goose_db_version" does not exist at character 3613922026-10-01 09:47:14.742 UTC [520] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13932026/10/01 09:47:14 INFO Received push request method=POST path=/api/pushes13942026/10/01 09:47:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13952026/10/01 09:47:14 INFO Signed narinfos id=1 count=113962026/10/01 09:47:14 OK 20241026095416_initial_model.sql (11.75ms)1397--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.58s)13982026/10/01 09:47:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1399=== CONT TestReadProxyRangeRequest14002026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (1.63ms)14012026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.39ms)14022026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (2.84ms)14032026/10/01 09:47:14 OK 20260905000000_add_claims.sql (2.38ms)14042026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.19ms)14052026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (1.76ms)14062026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000014072026/10/01 09:47:14 OK 1_commit_pending_closure.sql (3.33ms)14082026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.77ms)14092026/10/01 09:47:14 OK 3_commit_push.sql (765.05µs)14102026/10/01 09:47:14 goose: up to current file version: 31411--- PASS: TestService_Rustfstest (0.61s)1412=== CONT TestRegisterCompletedObjectNeedsPendingRow14132026/10/01 09:47:14 INFO Aborted multipart uploads count=0 kept=014142026/10/01 09:47:14 WARN Force mode enabled - objects will be deleted immediately without grace period14152026/10/01 09:47:14 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014162026/10/01 09:47:14 INFO Vacuumed table table=pending_closures1417--- PASS: TestReadProxyConditionalGet (0.58s)1418=== CONT TestParseSingleRange1419=== RUN TestParseSingleRange/none1420=== PAUSE TestParseSingleRange/none1421=== RUN TestParseSingleRange/unknown_unit1422=== PAUSE TestParseSingleRange/unknown_unit1423=== RUN TestParseSingleRange/multi-range_ignored1424=== PAUSE TestParseSingleRange/multi-range_ignored1425=== RUN TestParseSingleRange/malformed_no_dash1426=== PAUSE TestParseSingleRange/malformed_no_dash1427=== RUN TestParseSingleRange/malformed_both_empty1428=== PAUSE TestParseSingleRange/malformed_both_empty1429=== RUN TestParseSingleRange/malformed_end_before_start1430=== PAUSE TestParseSingleRange/malformed_end_before_start1431=== RUN TestParseSingleRange/closed1432=== PAUSE TestParseSingleRange/closed1433=== RUN TestParseSingleRange/open-ended1434=== PAUSE TestParseSingleRange/open-ended1435=== RUN TestParseSingleRange/end_clamped_to_size1436=== PAUSE TestParseSingleRange/end_clamped_to_size1437=== RUN TestParseSingleRange/suffix14382026/10/01 09:47:14 INFO Vacuumed table table=pending_objects1439=== PAUSE TestParseSingleRange/suffix1440=== RUN TestParseSingleRange/suffix_exceeds_size1441=== PAUSE TestParseSingleRange/suffix_exceeds_size1442=== RUN TestParseSingleRange/single_byte1443=== PAUSE TestParseSingleRange/single_byte1444=== RUN TestParseSingleRange/start_past_EOF1445=== PAUSE TestParseSingleRange/start_past_EOF1446=== RUN TestParseSingleRange/start_far_past_EOF1447=== PAUSE TestParseSingleRange/start_far_past_EOF1448=== CONT TestReadRedirectKeepsNarinfoProxied14492026/10/01 09:47:14 INFO Vacuumed table table=multipart_uploads14502026/10/01 09:47:14 INFO Vacuumed table table=closures14512026/10/01 09:47:14 INFO Vacuumed table table=objects1452--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.65s)1453=== CONT TestSweepSkipsRowsLockedByPush1454--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.65s)1455=== CONT TestPresentNotReportedWhileGCDeletesClosure14562026-10-01 09:47:14.832 UTC [530] ERROR: relation "goose_db_version" does not exist at character 3614572026-10-01 09:47:14.832 UTC [530] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14582026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures14592026/10/01 09:47:14 OK 20241026095416_initial_model.sql (11.48ms)14602026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.39ms)14612026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.44ms)14622026-10-01 09:47:14.858 UTC [535] ERROR: relation "goose_db_version" does not exist at character 3614632026-10-01 09:47:14.858 UTC [535] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14642026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.43ms)14652026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.63ms)14662026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.96ms)14672026/10/01 09:47:14 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket2597673859/001/proxy.sock14682026/10/01 09:47:14 INFO Starting HTTP server address=127.0.0.1:4100314692026/10/01 09:47:14 WARN mTLS auth: subject not in bound subjects subject="CN=someone"14702026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.63ms)14712026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000014722026/10/01 09:47:14 INFO Shutdown signal received, draining in-flight requests timeout=10s1473--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.63s)1474=== CONT TestFailedS3DeleteKeepsTombstone14752026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.73ms)14762026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.86ms)14772026/10/01 09:47:14 OK 20241026095416_initial_model.sql (11.43ms)14782026/10/01 09:47:14 OK 3_commit_push.sql (1.19ms)14792026/10/01 09:47:14 goose: up to current file version: 314802026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.02ms)14812026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.92ms)14822026-10-01 09:47:14.889 UTC [538] ERROR: relation "goose_db_version" does not exist at character 3614832026-10-01 09:47:14.889 UTC [538] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14842026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (10.24ms)14852026/10/01 09:47:14 OK 20260905000000_add_claims.sql (4.34ms)1486--- PASS: TestReadProxyHead (0.58s)1487=== CONT TestPresentReportsOnlyClosureRoots14882026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (3.32ms)14892026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.55ms)14902026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000014912026/10/01 09:47:14 OK 1_commit_pending_closure.sql (3.22ms)14922026/10/01 09:47:14 OK 20241026095416_initial_model.sql (10.15ms)14932026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.05ms)14942026/10/01 09:47:14 OK 3_commit_push.sql (1.26ms)14952026/10/01 09:47:14 goose: up to current file version: 314962026-10-01 09:47:14.908 UTC [541] ERROR: relation "goose_db_version" does not exist at character 3614972026-10-01 09:47:14.908 UTC [541] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14982026-10-01 09:47:14.909 UTC [542] ERROR: relation "goose_db_version" does not exist at character 3614992026-10-01 09:47:14.909 UTC [542] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15002026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.91ms)1501--- PASS: TestReadProxy404 (0.43s)1502=== CONT TestCreatePin_ReservedPins15032026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.38ms)15042026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.3ms)15052026/10/01 09:47:14 OK 20260905000000_add_claims.sql (2.88ms)15062026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.27ms)15072026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.2ms)15082026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000015092026/10/01 09:47:14 OK 20241026095416_initial_model.sql (10.73ms)15102026/10/01 09:47:14 OK 20241026095416_initial_model.sql (11.11ms)15112026/10/01 09:47:14 OK 1_commit_pending_closure.sql (3.25ms)15122026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)15132026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.45ms)15142026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.76ms)15152026/10/01 09:47:14 OK 3_commit_push.sql (1.07ms)15162026/10/01 09:47:14 goose: up to current file version: 315172026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.55ms)15182026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.22ms)1519=== RUN TestPush_RejectsBadRequests/bad_root1520=== PAUSE TestPush_RejectsBadRequests/bad_root1521=== RUN TestPush_RejectsBadRequests/root_not_in_objects1522=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1523=== RUN TestPush_RejectsBadRequests/no_roots1524=== PAUSE TestPush_RejectsBadRequests/no_roots1525=== RUN TestPush_RejectsBadRequests/no_objects1526=== PAUSE TestPush_RejectsBadRequests/no_objects1527=== CONT TestDeduplicatedObjectsRecordedAsPending15282026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (4.12ms)15292026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.35ms)15302026/10/01 09:47:14 OK 20260905000000_add_claims.sql (2.94ms)15312026/10/01 09:47:14 OK 20260905000000_add_claims.sql (2.77ms)15322026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.14ms)15332026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.55ms)15342026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (1.9ms)15352026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000015362026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2ms)15372026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000015382026/10/01 09:47:14 OK 1_commit_pending_closure.sql (1.95ms)15392026/10/01 09:47:14 OK 1_commit_pending_closure.sql (1.82ms)15402026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.27ms)15412026-10-01 09:47:14.946 UTC [545] ERROR: relation "goose_db_version" does not exist at character 3615422026-10-01 09:47:14.946 UTC [545] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15432026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.54ms)15442026/10/01 09:47:14 OK 3_commit_push.sql (1.41ms)15452026/10/01 09:47:14 goose: up to current file version: 315462026/10/01 09:47:14 OK 3_commit_push.sql (1.03ms)15472026/10/01 09:47:14 goose: up to current file version: 315482026/10/01 09:47:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1549--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.41s)1550=== CONT TestTombstonedObjectOfferedWithoutWaiting15512026/10/01 09:47:14 OK 20241026095416_initial_model.sql (11.43ms)15522026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.25ms)15532026/10/01 09:47:14 OK 20251218171726_add_pins.sql (3.46ms)15542026-10-01 09:47:14.971 UTC [552] ERROR: relation "goose_db_version" does not exist at character 3615552026-10-01 09:47:14.971 UTC [552] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15562026/10/01 09:47:14 OK 20260628120000_add_object_size_and_stats.sql (3.52ms)15572026/10/01 09:47:14 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NjQ1YWQxZWYtMzliNS00MDBkLTk3YjAtMjVhYzA3NTFhMTUxLmE2MTlkYTJmLThiYmYtNDdlNy1hMTRlLThhOGQ1NGI4Yjc1Y3gxNzkwODQ4MDM0NjU4ODA2MDQz parts=1015582026/10/01 09:47:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15592026/10/01 09:47:14 OK 20260905000000_add_claims.sql (3.54ms)15602026/10/01 09:47:14 INFO Completed upload id=115612026/10/01 09:47:14 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000015622026/10/01 09:47:14 INFO Received uploads request method=POST path=/api/pending_closures15632026/10/01 09:47:14 OK 20260920000000_drop_claims.sql (2.55ms)15642026/10/01 09:47:14 OK 20260923120000_add_pushes.sql (2.43ms)15652026/10/01 09:47:14 goose: successfully migrated database to version: 2026092312000015662026/10/01 09:47:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures15672026/10/01 09:47:14 OK 1_commit_pending_closure.sql (2.73ms)1568--- PASS: TestReadProxyNarStreaming (0.42s)1569=== CONT TestGCSweepSkipsPendingObjects15702026/10/01 09:47:14 OK 2_object_stats_trigger.sql (1.53ms)15712026/10/01 09:47:14 INFO Aborted multipart uploads count=0 kept=015722026/10/01 09:47:14 OK 3_commit_push.sql (7.39ms)15732026/10/01 09:47:14 goose: up to current file version: 315742026/10/01 09:47:14 OK 20241026095416_initial_model.sql (16.62ms)1575--- PASS: TestPushWaitsForSweepHoldingRow (0.83s)1576=== CONT TestClientMultipleUploads15772026/10/01 09:47:14 OK 20251210153512_drop_unused_gin_index.sql (2.24ms)15782026/10/01 09:47:15 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=015792026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.66ms)15802026/10/01 09:47:15 INFO Vacuumed table table=pending_closures15812026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4.18ms)15822026/10/01 09:47:15 INFO Vacuumed table table=pending_objects1583--- PASS: TestReadProxyNarinfo (0.44s)1584=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection15852026-10-01 09:47:15.008 UTC [572] ERROR: relation "goose_db_version" does not exist at character 3615862026-10-01 09:47:15.008 UTC [572] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15872026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.81ms)15882026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads15892026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (3.08ms)15902026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (3.84ms)15912026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000015922026/10/01 09:47:15 INFO Vacuumed table table=closures15932026/10/01 09:47:15 OK 1_commit_pending_closure.sql (3.88ms)15942026/10/01 09:47:15 INFO Vacuumed table table=objects15952026/10/01 09:47:15 OK 2_object_stats_trigger.sql (2.87ms)15962026/10/01 09:47:15 OK 3_commit_push.sql (3.44ms)15972026/10/01 09:47:15 goose: up to current file version: 315982026/10/01 09:47:15 OK 20241026095416_initial_model.sql (13.24ms)15992026/10/01 09:47:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40457/oidc16002026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes16012026/10/01 09:47:15 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001602--- PASS: TestService_createPendingClosureHandler (0.86s)1603=== CONT TestPendingCleanupUsesOneCutoff16042026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (6.78ms)16052026/10/01 09:47:15 OK 20251218171726_add_pins.sql (10.63ms)16062026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4.84ms)16072026/10/01 09:47:15 OK 20260905000000_add_claims.sql (4.49ms)16082026-10-01 09:47:15.057 UTC [579] ERROR: relation "goose_db_version" does not exist at character 3616092026-10-01 09:47:15.057 UTC [579] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16102026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.8ms)16112026/10/01 09:47:15 INFO Received complete push request method=POST path=/api/pushes/1/complete16122026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes16132026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (8.17ms)16142026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000016152026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.52ms)16162026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes16172026/10/01 09:47:15 OK 2_object_stats_trigger.sql (2.7ms)16182026/10/01 09:47:15 OK 3_commit_push.sql (1.92ms)16192026/10/01 09:47:15 goose: up to current file version: 316202026/10/01 09:47:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16212026-10-01 09:47:15.078 UTC [581] ERROR: relation "goose_db_version" does not exist at character 3616222026-10-01 09:47:15.078 UTC [581] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16232026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.29ms)16242026-10-01 09:47:15.082 UTC [582] ERROR: relation "goose_db_version" does not exist at character 3616252026-10-01 09:47:15.082 UTC [582] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16262026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.37ms)16272026/10/01 09:47:15 INFO Received complete push request method=POST path=/api/pushes/1/complete16282026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes16292026/10/01 09:47:15 OK 20251218171726_add_pins.sql (4.05ms)16302026-10-01 09:47:15.092 UTC [585] ERROR: relation "goose_db_version" does not exist at character 3616312026-10-01 09:47:15.092 UTC [585] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16322026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4.92ms)1633--- PASS: TestPush_CompleteCommitsEveryRoot (0.50s)1634=== CONT TestGCSweepDeliversEachKeyOnce16352026/10/01 09:47:15 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NjQ1YWQxZWYtMzliNS00MDBkLTk3YjAtMjVhYzA3NTFhMTUxLmQ0OWQyNTIwLTNiYTUtNGRjNC1hN2QwLWVlZjNiZTg3YTViNHgxNzkwODQ4MDM0NzE4NTQzOTAw parts=1216362026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.07ms)16372026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures16382026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.83ms)16392026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.9ms)16402026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (3.32ms)1641--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.93s)1642=== CONT TestOrphanedObjectsGC16432026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.63ms)16442026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.22ms)16452026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.34ms)16462026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000016472026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.65ms)16482026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.35ms)16492026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.61ms)16502026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.32ms)1651--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.50s)1652=== CONT TestGCBugBareHashReferences16532026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.89ms)16542026/10/01 09:47:15 OK 3_commit_push.sql (1.4ms)16552026/10/01 09:47:15 goose: up to current file version: 316562026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.34ms)16572026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.46ms)16582026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.11ms)16592026/10/01 09:47:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16602026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.51ms)16612026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.54ms)16622026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.23ms)16632026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000016642026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.46ms)16652026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.19ms)16662026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.24ms)16672026-10-01 09:47:15.115 UTC [593] ERROR: relation "goose_db_version" does not exist at character 3616682026-10-01 09:47:15.115 UTC [593] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16692026/10/01 09:47:15 OK 2_object_stats_trigger.sql (2.34ms)16702026-10-01 09:47:15.118 UTC [595] ERROR: relation "goose_db_version" does not exist at character 3616712026-10-01 09:47:15.118 UTC [595] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16722026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (3.64ms)16732026/10/01 09:47:15 OK 3_commit_push.sql (1.72ms)16742026/10/01 09:47:15 goose: up to current file version: 316752026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4.51ms)16762026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.42ms)16772026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000016782026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.4ms)16792026/10/01 09:47:15 OK 20260905000000_add_claims.sql (4.08ms)16802026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.61ms)16812026/10/01 09:47:15 OK 3_commit_push.sql (1.86ms)16822026/10/01 09:47:15 goose: up to current file version: 316832026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (3.69ms)16842026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=016852026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.48ms)16862026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000016872026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=016882026/10/01 09:47:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NjQ1YWQxZWYtMzliNS00MDBkLTk3YjAtMjVhYzA3NTFhMTUxLjEzNTgxNDMyLWNhZWYtNDk4NS04MTdkLWFhNzA5YjBmM2RhNHgxNzkwODQ4MDM0NzM1OTQ2OTU3 parts=1216892026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures16902026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.36ms)16912026/10/01 09:47:15 WARN Force mode enabled - objects will be deleted immediately without grace period16922026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.59ms)16932026/10/01 09:47:15 WARN Force mode enabled - objects will be deleted immediately without grace period16942026/10/01 09:47:15 OK 2_object_stats_trigger.sql (2.28ms)16952026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.72ms)16962026/10/01 09:47:15 OK 3_commit_push.sql (1.44ms)16972026/10/01 09:47:15 goose: up to current file version: 316982026/10/01 09:47:15 OK 20241026095416_initial_model.sql (12.22ms)16992026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures17002026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (8.19ms)17012026/10/01 09:47:15 OK 20251218171726_add_pins.sql (9.83ms)17022026/10/01 09:47:15 OK 20251218171726_add_pins.sql (4.66ms)17032026/10/01 09:47:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01704--- PASS: TestReadRedirectUsesPublicS3URL (0.52s)1705=== CONT TestObjectStatsTrigger17062026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (5.51ms)17072026/10/01 09:47:15 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=017082026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.87ms)17092026/10/01 09:47:15 INFO Vacuumed table table=pending_closures17102026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.17ms)17112026/10/01 09:47:15 INFO Vacuumed table table=pending_closures17122026/10/01 09:47:15 INFO Vacuumed table table=pending_objects17132026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.87ms)17142026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.57ms)17152026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads17162026/10/01 09:47:15 INFO Vacuumed table table=closures17172026/10/01 09:47:15 INFO Vacuumed table table=pending_objects17182026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.44ms)17192026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000017202026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads17212026/10/01 09:47:15 INFO Vacuumed table table=objects17222026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.78ms)17232026/10/01 09:47:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1724--- PASS: TestSweepRechecksPendingAfterLocking (0.54s)1725=== CONT TestPushDedupSurvivesConcurrentGC17262026/10/01 09:47:15 INFO Vacuumed table table=closures17272026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.67ms)17282026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.61ms)17292026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000017302026/10/01 09:47:15 INFO Vacuumed table table=objects17312026/10/01 09:47:15 OK 2_object_stats_trigger.sql (2.17ms)17322026/10/01 09:47:15 OK 1_commit_pending_closure.sql (3.07ms)17332026/10/01 09:47:15 INFO Received complete push request method=POST path=/api/pushes/2/complete17342026/10/01 09:47:15 OK 3_commit_push.sql (1.68ms)17352026/10/01 09:47:15 goose: up to current file version: 317362026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.4ms)17372026/10/01 09:47:15 OK 3_commit_push.sql (1.2ms)17382026/10/01 09:47:15 goose: up to current file version: 31739--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.62s)1740=== CONT TestLeadEndsOnShutdown17412026-10-01 09:47:15.171 UTC [602] ERROR: relation "goose_db_version" does not exist at character 3617422026-10-01 09:47:15.171 UTC [602] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1743--- PASS: TestGetExistingObjectsLocksRows (0.50s)1744=== CONT TestService_ReadScope_PublicByDefault17452026-10-01 09:47:15.178 UTC [604] ERROR: relation "goose_db_version" does not exist at character 3617462026-10-01 09:47:15.178 UTC [604] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17472026/10/01 09:47:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NjQ1YWQxZWYtMzliNS00MDBkLTk3YjAtMjVhYzA3NTFhMTUxLjdmM2U3MDFkLWQxYjMtNDNkYS1hYmM1LTI0NWM2MDgwZjBmZHgxNzkwODQ4MDM0ODUzNjc0NTE1 parts=1017482026/10/01 09:47:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17492026/10/01 09:47:15 INFO Completed upload id=117502026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures17512026-10-01 09:47:15.185 UTC [609] ERROR: relation "goose_db_version" does not exist at character 3617522026-10-01 09:47:15.185 UTC [609] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17532026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures17542026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.61ms)1755--- PASS: TestReadProxyRangeRequest (0.43s)1756=== CONT TestOrphanedObjectsGCStressTest17572026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.15ms)17582026/10/01 09:47:15 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo17592026/10/01 09:47:15 WARN Found objects in DB but missing from S3, will re-upload count=11760--- PASS: TestService_verifyS3Integrity (1.02s)1761=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded17622026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.66ms)17632026/10/01 09:47:15 OK 20241026095416_initial_model.sql (13.53ms)17642026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4.02ms)17652026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.73ms)17662026/10/01 09:47:15 OK 20260905000000_add_claims.sql (4.06ms)1767--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.42s)1768=== CONT TestMultipartCleanup17692026/10/01 09:47:15 OK 20241026095416_initial_model.sql (18.24ms)17702026/10/01 09:47:15 OK 20251218171726_add_pins.sql (10.97ms)17712026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (9.94ms)17722026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.82ms)17732026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (3.95ms)17742026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000017752026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (5.05ms)17762026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.7ms)17772026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.86ms)17782026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.65ms)17792026/10/01 09:47:15 OK 20260905000000_add_claims.sql (4.49ms)17802026/10/01 09:47:15 OK 2_object_stats_trigger.sql (2.19ms)17812026/10/01 09:47:15 OK 3_commit_push.sql (1.58ms)17822026/10/01 09:47:15 goose: up to current file version: 317832026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.64ms)17842026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (3.79ms)17852026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.27ms)17862026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.7ms)17872026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000017882026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.05ms)17892026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000017902026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.55ms)17912026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.45ms)1792--- PASS: TestReadRedirectKeepsNarinfoProxied (0.42s)1793=== CONT TestClientIntegration17942026/10/01 09:47:15 OK 2_object_stats_trigger.sql (2.17ms)17952026/10/01 09:47:15 OK 2_object_stats_trigger.sql (2.27ms)17962026/10/01 09:47:15 OK 3_commit_push.sql (1.77ms)17972026/10/01 09:47:15 goose: up to current file version: 317982026-10-01 09:47:15.236 UTC [616] ERROR: relation "goose_db_version" does not exist at character 3617992026-10-01 09:47:15.236 UTC [616] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18002026/10/01 09:47:15 OK 3_commit_push.sql (1.97ms)18012026/10/01 09:47:15 goose: up to current file version: 318022026-10-01 09:47:15.248 UTC [619] ERROR: relation "goose_db_version" does not exist at character 3618032026-10-01 09:47:15.248 UTC [619] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18042026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.34ms)18052026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)18062026/10/01 09:47:15 OK 20251218171726_add_pins.sql (4.57ms)18072026-10-01 09:47:15.260 UTC [620] ERROR: relation "goose_db_version" does not exist at character 3618082026-10-01 09:47:15.260 UTC [620] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18092026-10-01 09:47:15.261 UTC [621] ERROR: relation "goose_db_version" does not exist at character 3618102026-10-01 09:47:15.261 UTC [621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18112026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.43ms)18122026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.39ms)18132026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.83ms)18142026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.58ms)18152026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.59ms)18162026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.08ms)18172026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000018182026-10-01 09:47:15.272 UTC [623] ERROR: relation "goose_db_version" does not exist at character 3618192026-10-01 09:47:15.272 UTC [623] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18202026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.88ms)18212026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.45ms)18222026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.15ms)18232026-10-01 09:47:15.276 UTC [624] ERROR: relation "goose_db_version" does not exist at character 3618242026-10-01 09:47:15.276 UTC [624] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18252026/10/01 09:47:15 OK 3_commit_push.sql (1.14ms)18262026/10/01 09:47:15 goose: up to current file version: 318272026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.67ms)18282026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.42ms)18292026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.88ms)18302026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.93ms)18312026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.06ms)18322026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)18332026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.26ms)18342026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.14ms)18352026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.23ms)18362026-10-01 09:47:15.284 UTC [625] ERROR: relation "goose_db_version" does not exist at character 3618372026-10-01 09:47:15.284 UTC [625] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18382026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.46ms)18392026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000018402026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.47ms)18412026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.38ms)18422026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.98ms)18432026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.23ms)18442026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.76ms)18452026/10/01 09:47:15 OK 3_commit_push.sql (1.4ms)18462026/10/01 09:47:15 goose: up to current file version: 318472026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.86ms)18482026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=018492026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures18502026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.21ms)18512026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.96ms)18522026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.26ms)18532026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.01ms)18542026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.01ms)18552026/10/01 09:47:15 WARN Force mode enabled - objects will be deleted immediately without grace period18562026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.65ms)18572026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.9ms)18582026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000018592026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.17ms)18602026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.42ms)18612026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000018622026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.18ms)18632026/10/01 09:47:15 OK 1_commit_pending_closure.sql (1.74ms)18642026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3ms)18652026/10/01 09:47:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=018662026/10/01 09:47:15 OK 2_object_stats_trigger.sql (888.29µs)18672026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.26ms)18682026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.5ms)18692026/10/01 09:47:15 INFO Vacuumed table table=pending_closures18702026/10/01 09:47:15 OK 3_commit_push.sql (866.03µs)18712026/10/01 09:47:15 goose: up to current file version: 318722026/10/01 09:47:15 OK 3_commit_push.sql (784.65µs)18732026/10/01 09:47:15 goose: up to current file version: 318742026/10/01 09:47:15 INFO Vacuumed table table=pending_objects18752026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (2.5ms)18762026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads18772026/10/01 09:47:15 INFO Vacuumed table table=closures18782026/10/01 09:47:15 OK 20260905000000_add_claims.sql (2.95ms)18792026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.59ms)18802026/10/01 09:47:15 INFO Vacuumed table table=objects18812026/10/01 09:47:15 OK 20260905000000_add_claims.sql (2.43ms)18822026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.16ms)18832026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (1.62ms)18842026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (1.88ms)18852026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.52ms)18862026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000018872026-10-01 09:47:15.304 UTC [628] ERROR: relation "goose_db_version" does not exist at character 3618882026-10-01 09:47:15.304 UTC [628] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18892026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=018902026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.63ms)18912026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000018922026/10/01 09:47:15 OK 20251218171726_add_pins.sql (2.86ms)18932026/10/01 09:47:15 OK 1_commit_pending_closure.sql (1.44ms)18942026/10/01 09:47:15 OK 2_object_stats_trigger.sql (633.23µs)18952026/10/01 09:47:15 OK 1_commit_pending_closure.sql (1.52ms)18962026/10/01 09:47:15 OK 3_commit_push.sql (495.78µs)18972026/10/01 09:47:15 goose: up to current file version: 318982026/10/01 09:47:15 OK 2_object_stats_trigger.sql (753.23µs)18992026/10/01 09:47:15 WARN Force mode enabled - objects will be deleted immediately without grace period19002026/10/01 09:47:15 OK 3_commit_push.sql (461.13µs)19012026/10/01 09:47:15 goose: up to current file version: 319022026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (2.87ms)19032026/10/01 09:47:15 OK 20260905000000_add_claims.sql (2.93ms)19042026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (1.92ms)19052026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.81ms)19062026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000019072026/10/01 09:47:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=019082026/10/01 09:47:15 INFO Vacuumed table table=pending_closures19092026/10/01 09:47:15 INFO Vacuumed table table=pending_objects1910--- PASS: TestPresentReportsOnlyClosureRoots (0.42s)19112026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads1912=== CONT TestCacheConfigHandlerMaxNarSize1913--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)19142026/10/01 09:47:15 INFO Vacuumed table table=closures1915=== CONT TestClientCADerivations19162026/10/01 09:47:15 OK 1_commit_pending_closure.sql (1.8ms)19172026/10/01 09:47:15 OK 2_object_stats_trigger.sql (774.75µs)19182026/10/01 09:47:15 OK 3_commit_push.sql (558.65µs)19192026/10/01 09:47:15 goose: up to current file version: 319202026/10/01 09:47:15 INFO Vacuumed table table=objects19212026/10/01 09:47:15 OK 20241026095416_initial_model.sql (9.52ms)1922--- PASS: TestSweepSkipsRowsLockedByPush (0.49s)1923=== CONT TestService_NativeMTLS19242026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.25ms)19252026/10/01 09:47:15 OK 20251218171726_add_pins.sql (2.91ms)19262026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.02ms)19272026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.15ms)19282026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures19292026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.19ms)19302026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.19ms)19312026/10/01 09:47:15 goose: successfully migrated database to version: 202609231200001932--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.40s)1933=== CONT TestClientErrorHandling1934=== RUN TestClientErrorHandling/InvalidStorePath1935=== PAUSE TestClientErrorHandling/InvalidStorePath1936=== RUN TestClientErrorHandling/InvalidAuthToken1937=== PAUSE TestClientErrorHandling/InvalidAuthToken1938=== RUN TestClientErrorHandling/ServerNotAvailable1939=== PAUSE TestClientErrorHandling/ServerNotAvailable1940=== CONT TestMetricsInventory19412026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.29ms)19422026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.68ms)19432026/10/01 09:47:15 OK 3_commit_push.sql (1.51ms)19442026/10/01 09:47:15 goose: up to current file version: 319452026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures1946--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.40s)1947=== CONT TestCacheStatsHandler19482026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=019492026/10/01 09:47:15 WARN Force mode enabled - objects will be deleted immediately without grace period19502026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures19512026/10/01 09:47:15 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."19522026/10/01 09:47:15 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1953--- PASS: TestFailedS3DeleteKeepsTombstone (0.51s)1954=== CONT TestCreatePendingClosureRejectsOversizedNAR19552026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures1956--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1957=== CONT TestLeadElectsOneAndHandsOver19582026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=019592026/10/01 09:47:15 WARN Force mode enabled - objects will be deleted immediately without grace period19602026-10-01 09:47:15.392 UTC [640] ERROR: relation "goose_db_version" does not exist at character 3619612026-10-01 09:47:15.392 UTC [640] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19622026-10-01 09:47:15.395 UTC [642] ERROR: relation "goose_db_version" does not exist at character 3619632026-10-01 09:47:15.395 UTC [642] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19642026/10/01 09:47:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019652026/10/01 09:47:15 INFO Vacuumed table table=pending_closures19662026/10/01 09:47:15 INFO Vacuumed table table=pending_objects19672026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads19682026/10/01 09:47:15 INFO Vacuumed table table=closures19692026/10/01 09:47:15 INFO Vacuumed table table=objects19702026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.97ms)19712026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures1972--- PASS: TestGCSweepSkipsPendingObjects (0.43s)1973=== CONT TestNARDeduplicationMetadataUploadBug19742026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.76ms)19752026-10-01 09:47:15.413 UTC [644] ERROR: relation "goose_db_version" does not exist at character 3619762026-10-01 09:47:15.413 UTC [644] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19772026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.04ms)19782026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.29ms)19792026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2ms)19802026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.46ms)19812026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.38ms)19822026/10/01 09:47:15 OK 20260905000000_add_claims.sql (2.92ms)19832026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4.61ms)19842026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.47ms)1985=== NAME TestClientMultipleUploads1986 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads400187263/001/store/h5fyrd6azhnlidjzdrfw4fbnv3m30f0b-test-file-0.txt19872026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (7.16ms)19882026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000019892026/10/01 09:47:15 OK 20260905000000_add_claims.sql (8.61ms)19902026/10/01 09:47:15 OK 20241026095416_initial_model.sql (14.38ms)19912026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.47ms)19922026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)19932026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.83ms)19942026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.65ms)19952026/10/01 09:47:15 OK 3_commit_push.sql (1.24ms)19962026/10/01 09:47:15 goose: up to current file version: 319972026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.25ms)19982026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000019992026/10/01 09:47:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux20002026/10/01 09:47:15 WARN Refused reserved pin name=worker-x86_64-linux20012026/10/01 09:47:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux20022026/10/01 09:47:15 INFO Received create pin request method=POST path=/api/pins/my-app20032026/10/01 09:47:15 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux20042026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.98ms)2005--- PASS: TestCreatePin_ReservedPins (0.53s)2006=== CONT TestCacheConfigHandler2007=== RUN TestCacheConfigHandler/full_config,_no_issuer2008=== PAUSE TestCacheConfigHandler/full_config,_no_issuer2009=== RUN TestCacheConfigHandler/no_cache_url_configured2010=== PAUSE TestCacheConfigHandler/no_cache_url_configured2011=== RUN TestCacheConfigHandler/no_signing_keys2012=== PAUSE TestCacheConfigHandler/no_signing_keys2013=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2014=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2015=== CONT TestService_healthCheckHandler20162026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.49ms)20172026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.51ms)20182026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4ms)20192026-10-01 09:47:15.444 UTC [664] ERROR: relation "goose_db_version" does not exist at character 3620202026-10-01 09:47:15.444 UTC [664] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20212026/10/01 09:47:15 OK 3_commit_push.sql (1.74ms)20222026/10/01 09:47:15 goose: up to current file version: 320232026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.35ms)20242026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.46ms)20252026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures20262026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.64ms)20272026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000020282026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.45ms)20292026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.46ms)20302026/10/01 09:47:15 OK 3_commit_push.sql (1.47ms)20312026/10/01 09:47:15 goose: up to current file version: 320322026-10-01 09:47:15.459 UTC [667] ERROR: relation "goose_db_version" does not exist at character 3620332026-10-01 09:47:15.459 UTC [667] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20342026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.11ms)20352026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)20362026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures2037=== NAME TestClientMultipleUploads2038 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads400187263/001/store/hv1rzrpzb5kfln7prk4f8kvjmpfw6mzs-test-file-1.txt20392026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.74ms)20402026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.66ms)20412026/10/01 09:47:15 INFO Received cleanup request method=DELETE path=/api/pending_closures20422026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.59ms)20432026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.73ms)20442026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.26ms)20452026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)20462026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.75ms)20472026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000020482026-10-01 09:47:15.480 UTC [685] ERROR: relation "goose_db_version" does not exist at character 3620492026-10-01 09:47:15.480 UTC [685] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20502026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.3ms)20512026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.06ms)20522026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.12ms)20532026/10/01 09:47:15 OK 3_commit_push.sql (1.07ms)20542026/10/01 09:47:15 goose: up to current file version: 320552026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4.53ms)20562026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.54ms)20572026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.46ms)20582026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.33ms)20592026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000020602026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.2ms)20612026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.19ms)20622026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.23ms)20632026/10/01 09:47:15 OK 2_object_stats_trigger.sql (878.53µs)2064 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads400187263/001/store/ni7nv772vk1ij7154nd0y0b3yv6nsm0i-test-file-2.txt20652026/10/01 09:47:15 OK 3_commit_push.sql (1.47ms)20662026/10/01 09:47:15 goose: up to current file version: 320672026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=020682026/10/01 09:47:15 OK 20251218171726_add_pins.sql (2.51ms)20692026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (2.74ms)20702026/10/01 09:47:15 WARN Force mode enabled - objects will be deleted immediately without grace period20712026/10/01 09:47:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20722026/10/01 09:47:15 OK 20260905000000_add_claims.sql (2.83ms)20732026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (1.85ms)20742026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.51ms)20752026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000020762026/10/01 09:47:15 OK 1_commit_pending_closure.sql (1.86ms)20772026-10-01 09:47:15.511 UTC [704] ERROR: relation "goose_db_version" does not exist at character 3620782026-10-01 09:47:15.511 UTC [704] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20792026/10/01 09:47:15 OK 2_object_stats_trigger.sql (724.63µs)20802026/10/01 09:47:15 OK 3_commit_push.sql (697.93µs)20812026/10/01 09:47:15 goose: up to current file version: 320822026/10/01 09:47:15 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NjQ1YWQxZWYtMzliNS00MDBkLTk3YjAtMjVhYzA3NTFhMTUxLmI5ZmI0OWFjLWI0NjQtNDk4NC05MDEzLWUxOTNlM2M1ZjkzNXgxNzkwODQ4MDM1MTQ3OTYyMDIy error="Get \"http://127.0.0.1:1/bucket18/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"20832026/10/01 09:47:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NjQ1YWQxZWYtMzliNS00MDBkLTk3YjAtMjVhYzA3NTFhMTUxLjViZWE1MTY2LWI4MWUtNDE0Ni04YTU5LTU2NmZjNDZhN2FkYXgxNzkwODQ4MDM1MTM1NzI0NTcy parts=1220842026/10/01 09:47:15 INFO Received cleanup request method=DELETE path=/api/pending_closures20852026/10/01 09:47:15 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=020862026/10/01 09:47:15 INFO Aborted multipart uploads count=1 kept=020872026/10/01 09:47:15 INFO Vacuumed table table=pending_closures20882026/10/01 09:47:15 INFO Vacuumed table table=pending_objects20892026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads20902026/10/01 09:47:15 INFO Vacuumed table table=closures20912026/10/01 09:47:15 INFO Vacuumed table table=objects2092--- PASS: TestGCSweepDeliversEachKeyOnce (0.43s)2093=== CONT TestPinProtectsFromGC2094=== CONT TestGracefulShutdownDrainsInflight2095--- PASS: TestRedundantMultipartUpload (1.35s)20962026/10/01 09:47:15 INFO Starting HTTP server address=127.0.0.1:3662520972026/10/01 09:47:15 INFO Shutdown signal received, draining in-flight requests timeout=10s20982026/10/01 09:47:15 OK 20241026095416_initial_model.sql (9.75ms)20992026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.15ms)21002026/10/01 09:47:15 OK 20251218171726_add_pins.sql (2.57ms)21012026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.2ms)21022026/10/01 09:47:15 OK 20260905000000_add_claims.sql (2.99ms)21032026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.61ms)21042026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.5ms)21052026/10/01 09:47:15 goose: successfully migrated database to version: 202609231200002106--- PASS: TestObjectStatsTrigger (0.39s)2107=== CONT TestGenerateLandingPage21082026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.23ms)2109--- PASS: TestGenerateLandingPage (0.00s)2110=== CONT TestGCTaskStore_Fail2111--- PASS: TestGCTaskStore_Fail (0.00s)2112=== CONT TestClientSharedPathCommittedMidPush21132026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.34ms)21142026/10/01 09:47:15 OK 3_commit_push.sql (1.34ms)21152026/10/01 09:47:15 goose: up to current file version: 32116--- PASS: TestService_ReadScope_PublicByDefault (0.39s)2117=== CONT TestService_readinessHandler21182026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures21192026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes21202026/10/01 09:47:15 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)21212026/10/01 09:47:15 INFO Uploading hv1rzrpzb5kfln7prk4f8kvjmpfw6mzs-test-file-1.txt (160B)21222026/10/01 09:47:15 INFO Uploading h5fyrd6azhnlidjzdrfw4fbnv3m30f0b-test-file-0.txt (160B)21232026/10/01 09:47:15 INFO Uploading ni7nv772vk1ij7154nd0y0b3yv6nsm0i-test-file-2.txt (160B)21242026/10/01 09:47:15 INFO lead: acquired remote=192.0.2.1:123421252026/10/01 09:47:15 INFO lead: released remote=192.0.2.1:12342126--- PASS: TestLeadEndsOnShutdown (0.41s)2127=== CONT TestService_ReadAuthMiddleware21282026/10/01 09:47:15 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"21292026/10/01 09:47:15 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"21302026/10/01 09:47:15 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"21312026/10/01 09:47:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21322026/10/01 09:47:15 WARN Failed to register uploaded object key=hv1rzrpzb5kfln7prk4f8kvjmpfw6mzs.ls error="server returned 404: 404 page not found\n"21332026/10/01 09:47:15 WARN Failed to register uploaded object key=ni7nv772vk1ij7154nd0y0b3yv6nsm0i.ls error="server returned 404: 404 page not found\n"21342026/10/01 09:47:15 WARN Failed to register uploaded object key=h5fyrd6azhnlidjzdrfw4fbnv3m30f0b.ls error="server returned 404: 404 page not found\n"21352026/10/01 09:47:15 INFO Signed narinfos id=1 count=321362026/10/01 09:47:15 INFO Uploading 3 narinfos21372026/10/01 09:47:15 WARN Failed to register uploaded object key=h5fyrd6azhnlidjzdrfw4fbnv3m30f0b.narinfo error="server returned 404: 404 page not found\n"21382026-10-01 09:47:15.591 UTC [748] ERROR: relation "goose_db_version" does not exist at character 3621392026-10-01 09:47:15.591 UTC [748] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21402026/10/01 09:47:15 WARN Failed to register uploaded object key=ni7nv772vk1ij7154nd0y0b3yv6nsm0i.narinfo error="server returned 404: 404 page not found\n"2141--- PASS: TestGracefulShutdownDrainsInflight (0.07s)2142=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock21432026/10/01 09:47:15 INFO Received complete push request method=POST path=/api/pushes/1/complete21442026/10/01 09:47:15 WARN Failed to register uploaded object key=hv1rzrpzb5kfln7prk4f8kvjmpfw6mzs.narinfo error="server returned 404: 404 page not found\n"21452026/10/01 09:47:15 INFO Upload complete. (61ms)2146=== NAME TestClientMultipleUploads2147 client_integration_test.go:369: Uploaded 3 paths in 98.837729ms2148--- PASS: TestClientMultipleUploads (0.61s)2149=== CONT TestClientWithDependencies21502026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.5ms)21512026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.81ms)21522026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.68ms)21532026-10-01 09:47:15.613 UTC [753] ERROR: relation "goose_db_version" does not exist at character 3621542026-10-01 09:47:15.613 UTC [753] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21552026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.8ms)2156--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.61s)2157=== CONT TestResolveDBConnectionString2158=== RUN TestResolveDBConnectionString/flag_wins2159=== PAUSE TestResolveDBConnectionString/flag_wins2160=== RUN TestResolveDBConnectionString/file_when_flag_empty2161=== PAUSE TestResolveDBConnectionString/file_when_flag_empty21622026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.33ms)2163=== RUN TestResolveDBConnectionString/missing_file_is_an_error2164=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error2165=== RUN TestResolveDBConnectionString/PGHOST_allows_empty2166=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty2167=== RUN TestResolveDBConnectionString/nothing_configured2168=== PAUSE TestResolveDBConnectionString/nothing_configured2169=== CONT TestService_RequireScope_OIDC21702026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.59ms)21712026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.49ms)21722026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000021732026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures21742026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.42ms)21752026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.93ms)21762026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.19ms)21772026/10/01 09:47:15 OK 3_commit_push.sql (1.25ms)21782026/10/01 09:47:15 goose: up to current file version: 321792026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.23ms)21802026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.55ms)21812026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=021822026-10-01 09:47:15.640 UTC [757] ERROR: relation "goose_db_version" does not exist at character 3621832026-10-01 09:47:15.640 UTC [757] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2184--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.45s)2185=== CONT TestClientPushesUseOnePush21862026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (10.29ms)21872026/10/01 09:47:15 INFO Received uploads request method=POST path=/api/pending_closures21882026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.95ms)21892026/10/01 09:47:15 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=021902026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.62ms)21912026/10/01 09:47:15 INFO Vacuumed table table=pending_closures21922026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.1ms)21932026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000021942026/10/01 09:47:15 INFO Vacuumed table table=pending_objects21952026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads21962026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.14ms)21972026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.37ms)21982026/10/01 09:47:15 OK 3_commit_push.sql (1.54ms)21992026/10/01 09:47:15 goose: up to current file version: 322002026/10/01 09:47:15 OK 20241026095416_initial_model.sql (12.39ms)22012026/10/01 09:47:15 INFO Vacuumed table table=closures22022026/10/01 09:47:15 INFO Vacuumed table table=objects22032026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.12ms)22042026-10-01 09:47:15.663 UTC [763] ERROR: relation "goose_db_version" does not exist at character 3622052026-10-01 09:47:15.663 UTC [763] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22062026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=022072026/10/01 09:47:15 OK 20251218171726_add_pins.sql (4.35ms)22082026/10/01 09:47:15 WARN Force mode enabled - objects will be deleted immediately without grace period22092026-10-01 09:47:15.669 UTC [764] ERROR: relation "goose_db_version" does not exist at character 3622102026-10-01 09:47:15.669 UTC [764] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22112026/10/01 09:47:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=022122026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4.36ms)22132026/10/01 09:47:15 INFO Vacuumed table table=pending_closures22142026/10/01 09:47:15 OK 20260905000000_add_claims.sql (2.93ms)22152026/10/01 09:47:15 INFO Vacuumed table table=pending_objects22162026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads22172026/10/01 09:47:15 INFO Vacuumed table table=closures22182026/10/01 09:47:15 INFO Vacuumed table table=objects22192026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.76ms)22202026/10/01 09:47:15 OK 20241026095416_initial_model.sql (8.84ms)2221--- PASS: TestPushDedupSurvivesConcurrentGC (0.52s)2222=== CONT TestService_AuthMiddleware_MTLSBoundSubjects22232026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.89ms)22242026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000022252026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.33ms)22262026/10/01 09:47:15 OK 1_commit_pending_closure.sql (3.04ms)22272026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.25ms)22282026-10-01 09:47:15.683 UTC [766] ERROR: relation "goose_db_version" does not exist at character 3622292026-10-01 09:47:15.683 UTC [766] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22302026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.36ms)22312026/10/01 09:47:15 OK 20241026095416_initial_model.sql (9.68ms)22322026/10/01 09:47:15 OK 3_commit_push.sql (1.06ms)22332026/10/01 09:47:15 goose: up to current file version: 322342026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.54ms)22352026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.19ms)22362026/10/01 09:47:15 OK 20251218171726_add_pins.sql (2.82ms)22372026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.11ms)22382026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (1.98ms)22392026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.12ms)22402026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.07ms)22412026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000022422026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.18ms)22432026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.41ms)22442026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.33ms)22452026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.61ms)22462026/10/01 09:47:15 OK 3_commit_push.sql (1.18ms)22472026/10/01 09:47:15 goose: up to current file version: 322482026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.91ms)22492026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000022502026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.06ms)22512026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.31ms)22522026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.11ms)22532026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.33ms)22542026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.34ms)22552026/10/01 09:47:15 OK 3_commit_push.sql (1.87ms)22562026/10/01 09:47:15 goose: up to current file version: 322572026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.36ms)22582026/10/01 09:47:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34199/oidc22592026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.19ms)2260=== NAME TestClientIntegration2261 client_integration_test.go:286: Created store path: /build/TestClientIntegration1458900540/002/store/vdb8smvv9rnigdg9433rbvyp5f4scks5-test-file.txt22622026/10/01 09:47:15 WARN mTLS auth: subject not in bound subjects subject="CN=reader"22632026/10/01 09:47:15 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2264--- PASS: TestService_NativeMTLS (0.39s)2265=== CONT TestClientFallsBackToClosures22662026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.43ms)22672026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.15ms)22682026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000022692026-10-01 09:47:15.717 UTC [787] ERROR: relation "goose_db_version" does not exist at character 3622702026-10-01 09:47:15.717 UTC [787] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC22712026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.2ms)22722026/10/01 09:47:15 OK 2_object_stats_trigger.sql (702.81µs)22732026/10/01 09:47:15 OK 3_commit_push.sql (1.15ms)22742026/10/01 09:47:15 goose: up to current file version: 32275--- PASS: TestGCBugBareHashReferences (0.63s)2276=== CONT TestService_AuthMiddleware_OIDC22772026/10/01 09:47:15 OK 20241026095416_initial_model.sql (18.06ms)22782026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)22792026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.44ms)22802026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.58ms)22812026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.37ms)22822026-10-01 09:47:15.754 UTC [826] ERROR: relation "goose_db_version" does not exist at character 3622832026-10-01 09:47:15.754 UTC [826] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2284--- PASS: TestMetricsInventory (0.42s)2285=== CONT TestService_AuthMiddleware_MTLSProxyHeader22862026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.68ms)2287--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.93s)2288=== CONT TestProxyWriteTimeout/narinfo2289=== CONT TestProxyWriteTimeout/unknown_size2290=== CONT TestProxyWriteTimeout/10_GiB_nar2291=== CONT TestProxyWriteTimeout/1_GiB_nar2292--- PASS: TestProxyWriteTimeout (0.00s)2293 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)2294 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)2295 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)2296 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)2297=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info22982026/10/01 09:47:15 INFO Received uploads request method=POST path=/2299=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key23002026/10/01 09:47:15 INFO Received complete multipart upload request method=POST path=/2301=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key23022026/10/01 09:47:15 INFO Received request for more parts method=POST path=/2303=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal23042026/10/01 09:47:15 INFO Received uploads request method=POST path=/2305--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)2306 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)2307 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)2308 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)2309 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)2310=== CONT TestIsValidUploadKey/narinfo2311=== CONT TestIsValidUploadKey/realisation_plus_in_output2312=== CONT TestIsValidUploadKey/unknown_type2313=== CONT TestIsValidUploadKey/empty_key2314=== CONT TestIsValidUploadKey/absolute2315=== CONT TestIsValidUploadKey/traversal_nar2316=== CONT TestIsValidUploadKey/traversal2317=== CONT TestIsValidUploadKey/listing_key,_narinfo_type2318=== CONT TestIsValidUploadKey/nar_key,_narinfo_type2319=== CONT TestIsValidUploadKey/narinfo_key,_nar_type2320=== CONT TestIsValidUploadKey/index.html2321=== CONT TestIsValidUploadKey/nix-cache-info2322=== CONT TestIsValidUploadKey/build_log_home-manager_file2323=== CONT TestIsValidUploadKey/realisation2324=== CONT TestIsValidUploadKey/build_log_equals2325=== CONT TestIsValidUploadKey/build_log_question_mark2326=== CONT TestIsValidUploadKey/build_log_plus_in_name2327=== CONT TestIsValidUploadKey/nar_plain2328=== CONT TestIsValidUploadKey/build_log2329=== CONT TestIsValidUploadKey/listing2330=== CONT TestIsValidUploadKey/nar_xz2331=== CONT TestIsValidUploadKey/nar_zst2332=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure23332026/10/01 09:47:15 INFO Received uploads request method=POST path=/2334--- PASS: TestIsValidUploadKey (0.07s)2335 --- PASS: TestIsValidUploadKey/narinfo (0.00s)2336 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)2337 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)2338 --- PASS: TestIsValidUploadKey/empty_key (0.00s)2339 --- PASS: TestIsValidUploadKey/absolute (0.00s)2340 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)2341 --- PASS: TestIsValidUploadKey/traversal (0.00s)2342 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)2343 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)2344 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)2345 --- PASS: TestIsValidUploadKey/index.html (0.00s)2346 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)2347 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)2348 --- PASS: TestIsValidUploadKey/realisation (0.00s)2349 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)2350 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)2351 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)2352 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)2353 --- PASS: TestIsValidUploadKey/build_log (0.00s)2354 --- PASS: TestIsValidUploadKey/listing (0.00s)2355 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)2356 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)23572026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.19ms)23582026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000023592026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.28ms)23602026/10/01 09:47:15 INFO Received cleanup request method=DELETE path=/api/pending_closures23612026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.59ms)23622026/10/01 09:47:15 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket61/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""23632026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=123642026/10/01 09:47:15 OK 3_commit_push.sql (1.22ms)23652026/10/01 09:47:15 goose: up to current file version: 32366--- PASS: TestCacheStatsHandler (0.41s)2367=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts23682026/10/01 09:47:15 INFO Received request for more parts method=POST path=/23692026/10/01 09:47:15 INFO Received cleanup request method=DELETE path=/api/pending_closures23702026/10/01 09:47:15 INFO Aborted multipart uploads count=1 kept=023712026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.91ms)23722026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.87ms)2373--- PASS: TestMultipartCleanup (0.57s)2374=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart23752026/10/01 09:47:15 INFO Received complete multipart upload request method=POST path=/23762026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.96ms)23772026/10/01 09:47:15 INFO lead: acquired remote=192.0.2.1:12342378=== NAME TestClientCADerivations2379 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations394310892/001/store/x2rrvf18707aanp353bf9zn51axqi6dp-ca-test23802026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.31ms)23812026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes23822026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.21ms)23832026-10-01 09:47:15.783 UTC [864] ERROR: relation "goose_db_version" does not exist at character 3623842026-10-01 09:47:15.783 UTC [864] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23852026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.9ms)23862026/10/01 09:47:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23872026/10/01 09:47:15 INFO Uploading vdb8smvv9rnigdg9433rbvyp5f4scks5-test-file.txt (152B)23882026-10-01 09:47:15.787 UTC [867] ERROR: relation "goose_db_version" does not exist at character 3623892026-10-01 09:47:15.787 UTC [867] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC23902026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.49ms)23912026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000023922026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.12ms)23932026/10/01 09:47:15 WARN Failed to register uploaded object key=vdb8smvv9rnigdg9433rbvyp5f4scks5.ls error="server returned 404: 404 page not found\n"23942026/10/01 09:47:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23952026/10/01 09:47:15 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"23962026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.3ms)23972026/10/01 09:47:15 INFO Signed narinfos id=1 count=123982026/10/01 09:47:15 INFO Uploading 1 narinfos23992026/10/01 09:47:15 OK 3_commit_push.sql (658.35µs)24002026/10/01 09:47:15 goose: up to current file version: 324012026/10/01 09:47:15 INFO Received complete push request method=POST path=/api/pushes/1/complete24022026/10/01 09:47:15 WARN Failed to register uploaded object key=vdb8smvv9rnigdg9433rbvyp5f4scks5.narinfo error="server returned 404: 404 page not found\n"24032026/10/01 09:47:15 OK 20241026095416_initial_model.sql (12.1ms)24042026/10/01 09:47:15 INFO Upload complete. (58ms)24052026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.03ms)24062026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.36ms)24072026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.09ms)24082026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.6ms)2409 client_ca_test.go:139: Found 1 dependencies (including self)2410=== NAME TestOrphanedObjectsGC2411 orphaned_objects_gc_test.go:290: GC Test Summary:2412 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A2413 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B2414 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)2415 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)2416 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects2417--- PASS: TestOrphanedObjectsGC (0.71s)2418=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows24192026/10/01 09:47:15 OK 20251218171726_add_pins.sql (4.12ms)24202026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4.45ms)24212026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (4.48ms)24222026/10/01 09:47:15 OK 20260905000000_add_claims.sql (4.15ms)24232026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (3.67ms)24242026/10/01 09:47:15 OK 20260905000000_add_claims.sql (4.55ms)24252026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (3.69ms)24262026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000024272026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (4.32ms)24282026/10/01 09:47:15 OK 1_commit_pending_closure.sql (3.55ms)24292026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (4.21ms)24302026/10/01 09:47:15 goose: successfully migrated database to version: 202609231200002431=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check2432--- PASS: TestService_healthCheckHandler (0.39s)2433=== CONT TestIsValidCachePath/narinfo2434=== CONT TestIsValidCachePath/index.html2435=== CONT TestIsValidCachePath/short_hash2436=== CONT TestIsValidCachePath/wrong_extension2437=== CONT TestIsValidCachePath/leading_slash2438=== CONT TestIsValidCachePath/empty2439=== CONT TestIsValidCachePath/random_path2440=== CONT TestIsValidCachePath/nix-cache-info2441=== CONT TestIsValidCachePath/invalid_char_u2442=== CONT TestIsValidCachePath/nar_uncompressed2443=== CONT TestIsValidCachePath/invalid_char_e2444=== CONT TestIsValidCachePath/log2445=== CONT TestIsValidCachePath/realisation2446=== CONT TestIsValidCachePath/ls2447=== CONT TestIsValidCachePath/traversal_parent2448=== CONT TestIsValidCachePath/nar_xz2449=== CONT TestIsValidCachePath/traversal_in_middle2450=== CONT TestIsValidCachePath/nar_bz22451=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2452=== CONT TestIsValidCachePath/nar_zst2453=== CONT TestServerTLSConfig/no_client_CA2454=== CONT TestServerTLSConfig/missing_CA_file2455--- PASS: TestIsValidCachePath (0.00s)2456 --- PASS: TestIsValidCachePath/narinfo (0.00s)2457 --- PASS: TestIsValidCachePath/index.html (0.00s)2458 --- PASS: TestIsValidCachePath/short_hash (0.00s)2459 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2460 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2461 --- PASS: TestIsValidCachePath/empty (0.00s)2462 --- PASS: TestIsValidCachePath/random_path (0.00s)2463 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2464 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2465 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2466 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2467 --- PASS: TestIsValidCachePath/log (0.00s)2468 --- PASS: TestIsValidCachePath/realisation (0.00s)2469 --- PASS: TestIsValidCachePath/ls (0.00s)2470 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2471 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2472 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2473 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2474 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2475 --- PASS: TestIsValidCachePath/nar_zst (0.00s)24762026/10/01 09:47:15 OK 2_object_stats_trigger.sql (3.5ms)2477=== CONT TestServerTLSConfig/not_a_PEM_file2478=== CONT TestParseSingleRange/none2479=== CONT TestParseSingleRange/start_past_EOF2480=== CONT TestParseSingleRange/single_byte2481=== CONT TestParseSingleRange/suffix_exceeds_size2482=== CONT TestParseSingleRange/suffix2483=== CONT TestParseSingleRange/end_clamped_to_size2484=== CONT TestParseSingleRange/open-ended2485=== CONT TestParseSingleRange/closed2486=== CONT TestParseSingleRange/malformed_end_before_start2487=== CONT TestParseSingleRange/malformed_no_dash2488=== CONT TestParseSingleRange/multi-range_ignored2489=== CONT TestParseSingleRange/unknown_unit2490=== CONT TestParseSingleRange/start_far_past_EOF2491=== CONT TestParseSingleRange/malformed_both_empty2492--- PASS: TestParseSingleRange (0.00s)2493 --- PASS: TestParseSingleRange/none (0.00s)2494 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2495 --- PASS: TestParseSingleRange/single_byte (0.00s)2496 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2497 --- PASS: TestParseSingleRange/suffix (0.00s)2498 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2499 --- PASS: TestParseSingleRange/open-ended (0.00s)2500 --- PASS: TestParseSingleRange/closed (0.00s)2501 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)2502 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2503 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2504 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2505 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2506 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2507=== CONT TestPush_RejectsBadRequests/bad_root25082026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes2509=== CONT TestPush_RejectsBadRequests/no_roots2510--- PASS: TestServerTLSConfig (0.00s)2511 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2512 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2513 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2514=== CONT TestPush_RejectsBadRequests/no_objects25152026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes2516=== CONT TestPush_RejectsBadRequests/root_not_in_objects25172026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes25182026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes2519=== CONT TestClientErrorHandling/InvalidStorePath2520=== CONT TestClientErrorHandling/InvalidAuthToken2521--- PASS: TestPush_RejectsBadRequests (0.43s)2522 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2523 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2524 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2525 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)25262026-10-01 09:47:15.833 UTC [889] ERROR: relation "goose_db_version" does not exist at character 3625272026-10-01 09:47:15.833 UTC [889] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25282026/10/01 09:47:15 OK 1_commit_pending_closure.sql (4.9ms)25292026/10/01 09:47:15 OK 3_commit_push.sql (5.7ms)25302026/10/01 09:47:15 goose: up to current file version: 325312026/10/01 09:47:15 OK 2_object_stats_trigger.sql (7.01ms)25322026/10/01 09:47:15 OK 3_commit_push.sql (6.63ms)25332026/10/01 09:47:15 goose: up to current file version: 325342026/10/01 09:47:15 INFO All 1 paths already cached2535=== NAME TestClientIntegration2536 client_integration_test.go:312: Retrieved narinfo from S3:2537 StorePath: /build/TestClientIntegration1458900540/002/store/vdb8smvv9rnigdg9433rbvyp5f4scks5-test-file.txt2538 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2539 Compression: zstd2540 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12541 NarSize: 1522542 References: 2543 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12544 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2545 client_integration_test.go:313: Decompressed .ls content (64 bytes):2546 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2547 client_integration_test.go:316: Testing garbage collection...25482026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.13ms)25492026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.93ms)2550=== NAME TestNARDeduplicationMetadataUploadBug2551 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1626492572/001/store/nmz5shxydxd5y7v8cwa1aaach0624i4j-file1.txt25522026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.91ms)25532026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (11.19ms)25542026/10/01 09:47:15 OK 20260905000000_add_claims.sql (4.71ms)25552026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (5.78ms)25562026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (2.74ms)25572026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000025582026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.21ms)25592026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.26ms)25602026/10/01 09:47:15 INFO Starting cleanup of old closures method=DELETE path=/api/closures25612026/10/01 09:47:15 INFO Garbage collection started25622026/10/01 09:47:15 OK 3_commit_push.sql (1.46ms)25632026/10/01 09:47:15 goose: up to current file version: 325642026-10-01 09:47:15.899 UTC [1002] ERROR: relation "goose_db_version" does not exist at character 3625652026-10-01 09:47:15.899 UTC [1002] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25662026/10/01 09:47:15 INFO Aborted multipart uploads count=0 kept=025672026/10/01 09:47:15 WARN Force mode enabled - objects will be deleted immediately without grace period25682026/10/01 09:47:15 WARN readiness check failed error="closed pool"2569--- PASS: TestService_readinessHandler (0.35s)2570=== CONT TestClientErrorHandling/ServerNotAvailable25712026/10/01 09:47:15 OK 20241026095416_initial_model.sql (13.68ms)25722026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes25732026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (2.6ms)25742026/10/01 09:47:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=025752026-10-01 09:47:15.924 UTC [1040] ERROR: relation "goose_db_version" does not exist at character 3625762026-10-01 09:47:15.924 UTC [1040] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25772026/10/01 09:47:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)25782026/10/01 09:47:15 INFO Uploading x2rrvf18707aanp353bf9zn51axqi6dp-ca-test (144B)25792026/10/01 09:47:15 INFO Vacuumed table table=pending_closures25802026/10/01 09:47:15 OK 20251218171726_add_pins.sql (4.12ms)25812026/10/01 09:47:15 INFO Vacuumed table table=pending_objects25822026/10/01 09:47:15 INFO Vacuumed table table=multipart_uploads25832026/10/01 09:47:15 INFO lead: released remote=192.0.2.1:123425842026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.56ms)25852026/10/01 09:47:15 INFO Vacuumed table table=closures25862026/10/01 09:47:15 WARN Failed to register uploaded object key=x2rrvf18707aanp353bf9zn51axqi6dp.ls error="server returned 404: 404 page not found\n"25872026/10/01 09:47:15 WARN Failed to register uploaded object key=log/fywrh8anfa0cs8zshvrg8a7h4qgwjsmv-ca-test.drv error="server returned 404: 404 page not found\n"25882026/10/01 09:47:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25892026/10/01 09:47:15 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"25902026/10/01 09:47:15 INFO Signed narinfos id=1 count=125912026/10/01 09:47:15 INFO Uploading 1 narinfos25922026/10/01 09:47:15 INFO Received push request method=POST path=/api/pushes25932026/10/01 09:47:15 INFO Vacuumed table table=objects25942026-10-01 09:47:15.932 UTC [1044] ERROR: relation "goose_db_version" does not exist at character 3625952026-10-01 09:47:15.932 UTC [1044] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC25962026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.35ms)25972026/10/01 09:47:15 INFO Received complete push request method=POST path=/api/pushes/1/complete25982026/10/01 09:47:15 WARN Failed to register uploaded object key=x2rrvf18707aanp353bf9zn51axqi6dp.narinfo error="server returned 404: 404 page not found\n"25992026/10/01 09:47:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)26002026/10/01 09:47:15 INFO Uploading nmz5shxydxd5y7v8cwa1aaach0624i4j-file1.txt (160B)26012026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.68ms)26022026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.87ms)26032026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000026042026-10-01 09:47:15.938 UTC [1076] ERROR: relation "goose_db_version" does not exist at character 3626052026-10-01 09:47:15.938 UTC [1076] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC2606--- PASS: TestService_ReadAuthMiddleware (0.35s)2607=== CONT TestCacheConfigHandler/full_config,_no_issuer2608=== CONT TestCacheConfigHandler/no_signing_keys2609=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2610=== CONT TestCacheConfigHandler/no_cache_url_configured2611--- PASS: TestCacheConfigHandler (0.00s)2612 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2613 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2614 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2615 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2616=== CONT TestResolveDBConnectionString/flag_wins2617=== CONT TestResolveDBConnectionString/nothing_configured2618=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2619=== CONT TestResolveDBConnectionString/missing_file_is_an_error2620=== CONT TestResolveDBConnectionString/file_when_flag_empty2621--- PASS: TestResolveDBConnectionString (0.00s)2622 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2623 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2624 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2625 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2626 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)26272026/10/01 09:47:15 OK 20241026095416_initial_model.sql (11.19ms)26282026/10/01 09:47:15 WARN Failed to register uploaded object key=nmz5shxydxd5y7v8cwa1aaach0624i4j.ls error="server returned 404: 404 page not found\n"26292026/10/01 09:47:15 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign26302026/10/01 09:47:15 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"26312026/10/01 09:47:15 OK 1_commit_pending_closure.sql (3.44ms)26322026/10/01 09:47:15 INFO Signed narinfos id=1 count=126332026/10/01 09:47:15 INFO Upload complete. (96ms)26342026/10/01 09:47:15 INFO Uploading 1 narinfos26352026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.6ms)26362026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.13ms)26372026/10/01 09:47:15 OK 3_commit_push.sql (828.63µs)26382026/10/01 09:47:15 goose: up to current file version: 326392026/10/01 09:47:15 OK 20251218171726_add_pins.sql (2.96ms)2640=== NAME TestClientCADerivations2641 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations394310892/001/store/x2rrvf18707aanp353bf9zn51axqi6dp-ca-test2642 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2643 Compression: zstd2644 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2645 NarSize: 1442646 References: 2647 Deriver: /build/TestClientCADerivations394310892/001/store/fywrh8anfa0cs8zshvrg8a7h4qgwjsmv-ca-test.drv2648 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2649 client_ca_test.go:185: Checking for realisation files in S3...26502026/10/01 09:47:15 INFO Received complete push request method=POST path=/api/pushes/1/complete26512026/10/01 09:47:15 WARN Failed to register uploaded object key=nmz5shxydxd5y7v8cwa1aaach0624i4j.narinfo error="server returned 404: 404 page not found\n"2652=== NAME TestPinProtectsFromGC2653 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC3455690308/001/store/kkgz53swgby3fzd8icbjybfs38cmyccl-pinned-file.txt2654 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC3455690308/001/store/c3kzazcrj3kcdxlzwxfxk6xax736hd6n-unpinned-file.txt2655=== NAME TestClientCADerivations2656 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2657 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache26582026/10/01 09:47:15 OK 20241026095416_initial_model.sql (10.46ms)26592026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (3.14ms)26602026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.22ms)26612026/10/01 09:47:15 OK 20260905000000_add_claims.sql (3.28ms)26622026/10/01 09:47:15 INFO Upload complete. (59ms)26632026/10/01 09:47:15 OK 20251218171726_add_pins.sql (3.08ms)26642026/10/01 09:47:15 OK 20241026095416_initial_model.sql (9.36ms)2665=== NAME TestNARDeduplicationMetadataUploadBug2666 metadata_upload_test.go:54: Retrieved narinfo from S3:2667 StorePath: /build/TestNARDeduplicationMetadataUploadBug1626492572/001/store/nmz5shxydxd5y7v8cwa1aaach0624i4j-file1.txt2668 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2669 Compression: zstd2670 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2671 NarSize: 1602672 References: 2673 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf26742026/10/01 09:47:15 OK 20251210153512_drop_unused_gin_index.sql (1.16ms)26752026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (2.23ms)26762026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (2.98ms)26772026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.85ms)26782026/10/01 09:47:15 goose: successfully migrated database to version: 202609231200002679 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)26802026/10/01 09:47:15 OK 20251218171726_add_pins.sql (2.22ms)2681 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2682 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}26832026/10/01 09:47:15 OK 1_commit_pending_closure.sql (2.14ms)26842026/10/01 09:47:15 OK 20260905000000_add_claims.sql (2.69ms)26852026/10/01 09:47:15 OK 20260628120000_add_object_size_and_stats.sql (2.63ms)26862026/10/01 09:47:15 OK 2_object_stats_trigger.sql (1.02ms)26872026/10/01 09:47:15 OK 3_commit_push.sql (817.07µs)26882026/10/01 09:47:15 goose: up to current file version: 326892026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (1.75ms)26902026/10/01 09:47:15 OK 20260905000000_add_claims.sql (2.19ms)26912026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.44ms)26922026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000026932026/10/01 09:47:15 OK 20260920000000_drop_claims.sql (1.61ms)26942026/10/01 09:47:15 OK 1_commit_pending_closure.sql (1.62ms)26952026/10/01 09:47:15 OK 20260923120000_add_pushes.sql (1.18ms)26962026/10/01 09:47:15 goose: successfully migrated database to version: 2026092312000026972026/10/01 09:47:15 OK 2_object_stats_trigger.sql (731.79µs)26982026/10/01 09:47:15 OK 3_commit_push.sql (561.87µs)26992026/10/01 09:47:15 goose: up to current file version: 327002026/10/01 09:47:15 OK 1_commit_pending_closure.sql (1.41ms)27012026/10/01 09:47:15 OK 2_object_stats_trigger.sql (677.11µs)27022026/10/01 09:47:15 OK 3_commit_push.sql (519.65µs)27032026/10/01 09:47:15 goose: up to current file version: 327042026/10/01 09:47:15 INFO lead: acquired remote=192.0.2.1:123427052026/10/01 09:47:15 INFO lead: released remote=192.0.2.1:12342706--- PASS: TestLeadElectsOneAndHandsOver (0.60s)2707=== NAME TestNARDeduplicationMetadataUploadBug2708 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1626492572/001/store/qpcsh3g9m4pb3r79qrc3jq3vhzfgf7kf-file2.txt27092026/10/01 09:47:15 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present27102026/10/01 09:47:16 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"27112026/10/01 09:47:16 WARN mTLS auth: bound subjects configured but subject DN unavailable27122026/10/01 09:47:16 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2713--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.33s)27142026/10/01 09:47:16 INFO Received push request method=POST path=/api/pushes27152026/10/01 09:47:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)27162026/10/01 09:47:16 INFO Uploading kkgz53swgby3fzd8icbjybfs38cmyccl-pinned-file.txt (128B)27172026/10/01 09:47:16 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"27182026/10/01 09:47:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27192026/10/01 09:47:16 WARN Failed to register uploaded object key=kkgz53swgby3fzd8icbjybfs38cmyccl.ls error="server returned 404: 404 page not found\n"27202026/10/01 09:47:16 INFO Signed narinfos id=1 count=127212026/10/01 09:47:16 INFO Uploading 1 narinfos27222026/10/01 09:47:16 INFO Received complete push request method=POST path=/api/pushes/1/complete27232026/10/01 09:47:16 WARN Failed to register uploaded object key=kkgz53swgby3fzd8icbjybfs38cmyccl.narinfo error="server returned 404: 404 page not found\n"27242026/10/01 09:47:16 INFO Upload complete. (55ms)27252026/10/01 09:47:16 INFO Received push request method=POST path=/api/pushes2726=== NAME TestClientCADerivations2727 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2728 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2729 error: binary cache 's3://bucket63?endpoint=http://localhost:33613®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations394310892/001/store'2730 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 127312026/10/01 09:47:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45065/oidc2732--- PASS: TestClientCADerivations (0.72s)27332026/10/01 09:47:16 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)27342026/10/01 09:47:16 INFO Uploading mq0y99p0zxpi0imbr23fawbyq2j5a8d7-top (224B)27352026/10/01 09:47:16 INFO Uploading 6cvls4d2ydmr9s70c2wdffp0qrs2xdry-shared-dep (136B)27362026/10/01 09:47:16 WARN Failed to register uploaded object key=nar/014yvm58c779lvilra5j2c2kwbqv12zlsi37prrl0bmq381kx28l.nar.zst error="server returned 404: 404 page not found\n"27372026/10/01 09:47:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"27382026/10/01 09:47:16 WARN Failed to register uploaded object key=6cvls4d2ydmr9s70c2wdffp0qrs2xdry.ls error="server returned 404: 404 page not found\n"27392026/10/01 09:47:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign27402026/10/01 09:47:16 WARN Failed to register uploaded object key=mq0y99p0zxpi0imbr23fawbyq2j5a8d7.ls error="server returned 404: 404 page not found\n"27412026/10/01 09:47:16 INFO Signed narinfos id=1 count=227422026/10/01 09:47:16 INFO Uploading 2 narinfos27432026/10/01 09:47:16 WARN Failed to register uploaded object key=6cvls4d2ydmr9s70c2wdffp0qrs2xdry.narinfo error="server returned 404: 404 page not found\n"27442026/10/01 09:47:16 INFO Received complete push request method=POST path=/api/pushes/1/complete2745=== RUN TestService_RequireScope_OIDC/builder_may_write2746=== PAUSE TestService_RequireScope_OIDC/builder_may_write27472026/10/01 09:47:16 WARN Failed to register uploaded object key=mq0y99p0zxpi0imbr23fawbyq2j5a8d7.narinfo error="server returned 404: 404 page not found\n"2748=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2749=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2750=== RUN TestService_RequireScope_OIDC/ops_may_admin2751=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2752=== RUN TestService_RequireScope_OIDC/ops_may_not_write2753=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2754=== RUN TestService_RequireScope_OIDC/reader_may_not_write2755=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2756=== RUN TestService_RequireScope_OIDC/static_token_may_admin2757=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2758=== RUN TestService_RequireScope_OIDC/static_token_may_write2759=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2760=== RUN TestService_RequireScope_OIDC/reader_may_read2761=== PAUSE TestService_RequireScope_OIDC/reader_may_read2762=== RUN TestService_RequireScope_OIDC/writer_implies_read2763=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2764=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2765=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2766=== CONT TestService_RequireScope_OIDC/builder_may_write2767=== CONT TestService_RequireScope_OIDC/reader_may_read2768=== CONT TestService_RequireScope_OIDC/static_token_may_admin2769=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2770=== CONT TestService_RequireScope_OIDC/ops_may_not_write2771=== CONT TestService_RequireScope_OIDC/writer_implies_read2772=== CONT TestService_RequireScope_OIDC/static_token_may_write2773=== CONT TestService_RequireScope_OIDC/reader_may_not_write2774=== CONT TestService_RequireScope_OIDC/ops_may_admin2775=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2776--- PASS: TestService_RequireScope_OIDC (0.43s)2777 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2778 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2779 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2780 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2781 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2782 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2783 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2784 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2785 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2786 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)27872026/10/01 09:47:16 INFO Upload complete. (57ms)2788=== NAME TestClientSharedPathCommittedMidPush2789 client_integration_test.go:680: Retrieved narinfo from S3:2790 StorePath: /build/TestClientSharedPathCommittedMidPush3244715660/001/store/6cvls4d2ydmr9s70c2wdffp0qrs2xdry-shared-dep2791 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2792 Compression: zstd2793 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822794 NarSize: 1362795 References: 2796 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2797=== NAME TestClientWithDependencies2798 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies2342877503/001/store/4jwbfs8cmjic62kqh273yr1zpk607nsk-test-script27992026/10/01 09:47:16 INFO Received push request method=POST path=/api/pushes2800=== NAME TestClientSharedPathCommittedMidPush2801 client_integration_test.go:680: Retrieved narinfo from S3:2802 StorePath: /build/TestClientSharedPathCommittedMidPush3244715660/001/store/mq0y99p0zxpi0imbr23fawbyq2j5a8d7-top2803 URL: nar/014yvm58c779lvilra5j2c2kwbqv12zlsi37prrl0bmq381kx28l.nar.zst2804 Compression: zstd2805 NarHash: sha256:014yvm58c779lvilra5j2c2kwbqv12zlsi37prrl0bmq381kx28l2806 NarSize: 2242807 References: /build/TestClientSharedPathCommittedMidPush3244715660/001/store/6cvls4d2ydmr9s70c2wdffp0qrs2xdry-shared-dep2808 CA: text:sha256:03fkxk2f13q3j1rqqp5idzpnma0cy2rjsg6i0pvlbr13j6g1fp0k28092026/10/01 09:47:16 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)2810--- PASS: TestClientSharedPathCommittedMidPush (0.52s)28112026/10/01 09:47:16 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign28122026/10/01 09:47:16 WARN Failed to register uploaded object key=qpcsh3g9m4pb3r79qrc3jq3vhzfgf7kf.ls error="server returned 404: 404 page not found\n"28132026/10/01 09:47:16 INFO Signed narinfos id=2 count=128142026/10/01 09:47:16 INFO Uploading 1 narinfos2815--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.32s)28162026/10/01 09:47:16 INFO Received complete push request method=POST path=/api/pushes/2/complete28172026/10/01 09:47:16 WARN Failed to register uploaded object key=qpcsh3g9m4pb3r79qrc3jq3vhzfgf7kf.narinfo error="server returned 404: 404 page not found\n"28182026/10/01 09:47:16 INFO Upload complete. (53ms)2819=== NAME TestNARDeduplicationMetadataUploadBug2820 metadata_upload_test.go:76: Retrieved narinfo from S3:2821 StorePath: /build/TestNARDeduplicationMetadataUploadBug1626492572/001/store/qpcsh3g9m4pb3r79qrc3jq3vhzfgf7kf-file2.txt2822 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2823 Compression: zstd2824 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2825 NarSize: 1602826 References: 2827 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2828 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2829 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2830 {"version":1,"root":{"type":"regular","size":44}}2831--- PASS: TestNARDeduplicationMetadataUploadBug (0.67s)2832=== NAME TestClientWithDependencies2833 client_integration_test.go:615: Found 1 dependencies (including self)28342026/10/01 09:47:16 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=184.264233ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present28352026/10/01 09:47:16 INFO Received uploads request method=POST path=/api/pending_closures28362026/10/01 09:47:16 INFO Received push request method=POST path=/api/pushes28372026/10/01 09:47:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)28382026/10/01 09:47:16 INFO Uploading c3kzazcrj3kcdxlzwxfxk6xax736hd6n-unpinned-file.txt (128B)28392026/10/01 09:47:16 INFO Aborted multipart uploads count=0 kept=028402026/10/01 09:47:16 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"28412026/10/01 09:47:16 WARN Failed to register uploaded object key=c3kzazcrj3kcdxlzwxfxk6xax736hd6n.ls error="server returned 404: 404 page not found\n"28422026/10/01 09:47:16 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign28432026/10/01 09:47:16 INFO Signed narinfos id=2 count=128442026/10/01 09:47:16 INFO Uploading 1 narinfos28452026/10/01 09:47:16 WARN Force mode enabled - objects will be deleted immediately without grace period28462026/10/01 09:47:16 INFO Received complete push request method=POST path=/api/pushes/2/complete28472026/10/01 09:47:16 WARN Failed to register uploaded object key=c3kzazcrj3kcdxlzwxfxk6xax736hd6n.narinfo error="server returned 404: 404 page not found\n"28482026/10/01 09:47:16 INFO Upload complete. (47ms)28492026-10-01 09:47:16.115 UTC [1549] ERROR: relation "goose_db_version" does not exist at character 3628502026-10-01 09:47:16.115 UTC [1549] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC28512026/10/01 09:47:16 INFO Received uploads request method=POST path=/api/pending_closures28522026/10/01 09:47:16 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=028532026/10/01 09:47:16 INFO Vacuumed table table=pending_closures28542026/10/01 09:47:16 INFO Vacuumed table table=pending_objects28552026/10/01 09:47:16 INFO Vacuumed table table=multipart_uploads28562026/10/01 09:47:16 INFO Vacuumed table table=closures28572026/10/01 09:47:16 INFO Vacuumed table table=objects28582026/10/01 09:47:16 INFO Aborted multipart uploads count=0 kept=028592026/10/01 09:47:16 OK 20241026095416_initial_model.sql (10.63ms)28602026/10/01 09:47:16 WARN Force mode enabled - objects will be deleted immediately without grace period28612026/10/01 09:47:16 OK 20251210153512_drop_unused_gin_index.sql (1.61ms)28622026/10/01 09:47:16 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=028632026/10/01 09:47:16 OK 20251218171726_add_pins.sql (3.1ms)28642026/10/01 09:47:16 INFO Vacuumed table table=pending_closures28652026/10/01 09:47:16 INFO Vacuumed table table=pending_objects28662026/10/01 09:47:16 OK 20260628120000_add_object_size_and_stats.sql (3.42ms)28672026/10/01 09:47:16 INFO Vacuumed table table=multipart_uploads28682026/10/01 09:47:16 INFO Vacuumed table table=closures28692026/10/01 09:47:16 INFO Vacuumed table table=objects28702026/10/01 09:47:16 OK 20260905000000_add_claims.sql (3.14ms)28712026/10/01 09:47:16 OK 20260920000000_drop_claims.sql (2.68ms)28722026/10/01 09:47:16 OK 20260923120000_add_pushes.sql (1.78ms)28732026/10/01 09:47:16 goose: successfully migrated database to version: 2026092312000028742026/10/01 09:47:16 OK 1_commit_pending_closure.sql (1.83ms)28752026/10/01 09:47:16 OK 2_object_stats_trigger.sql (929.79µs)28762026/10/01 09:47:16 OK 3_commit_push.sql (568.99µs)28772026/10/01 09:47:16 goose: up to current file version: 328782026/10/01 09:47:16 INFO Starting cleanup of old closures method=DELETE path=/api/closures28792026/10/01 09:47:16 INFO Garbage collection started2880--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2881 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.33s)2882 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.32s)28832026/10/01 09:47:16 INFO Received push request method=POST path=/api/pushes28842026/10/01 09:47:16 INFO Received push request method=POST path=/api/pushes28852026/10/01 09:47:16 INFO Aborted multipart uploads count=0 kept=028862026/10/01 09:47:16 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)28872026/10/01 09:47:16 INFO Uploading 4jwbfs8cmjic62kqh273yr1zpk607nsk-test-script (136B)28882026/10/01 09:47:16 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)28892026/10/01 09:47:16 INFO Uploading x8lkkrfw4k45dvaj6ikdy7d5z17h1mch-shared-dep (136B)28902026/10/01 09:47:16 INFO Uploading dn1sq599abj5n4d77va32x9xjfjkg9n8-a (208B)28912026/10/01 09:47:16 WARN Force mode enabled - objects will be deleted immediately without grace period28922026/10/01 09:47:16 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"28932026/10/01 09:47:16 WARN Failed to register uploaded object key=x8lkkrfw4k45dvaj6ikdy7d5z17h1mch.ls error="server returned 404: 404 page not found\n"28942026/10/01 09:47:16 WARN Failed to register uploaded object key=log/c3qk4gaaklsrgmam7v55kfxgrfdckcgc-test-script.drv error="server returned 404: 404 page not found\n"28952026/10/01 09:47:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign28962026/10/01 09:47:16 WARN Failed to register uploaded object key=4jwbfs8cmjic62kqh273yr1zpk607nsk.ls error="server returned 404: 404 page not found\n"28972026/10/01 09:47:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"2898=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2899=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2900=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2901=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected29022026/10/01 09:47:16 WARN Failed to register uploaded object key=nar/1nsisj648n99ip8ys8dglh5y2m4gi11454pkd0k5xbc05609znbj.nar.zst error="server returned 404: 404 page not found\n"2903=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2904=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2905=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2906=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2907=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2908=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected29092026/10/01 09:47:16 WARN Failed to register uploaded object key=2mkgw1dmc86pazyqpafy7gl9sw863zgm.ls error="server returned 404: 404 page not found\n"2910=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured29112026/10/01 09:47:16 INFO Signed narinfos id=1 count=12912=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected29132026/10/01 09:47:16 INFO Uploading 1 narinfos29142026/10/01 09:47:16 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]29152026/10/01 09:47:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign29162026/10/01 09:47:16 WARN Failed to register uploaded object key=dn1sq599abj5n4d77va32x9xjfjkg9n8.ls error="server returned 404: 404 page not found\n"29172026/10/01 09:47:16 INFO Signed narinfos id=1 count=329182026/10/01 09:47:16 INFO Uploading 3 narinfos29192026/10/01 09:47:16 INFO Received complete push request method=POST path=/api/pushes/1/complete29202026/10/01 09:47:16 WARN Authentication failed token_preview=eyJhbGciOi...X3k0L5prtQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]29212026/10/01 09:47:16 WARN Failed to register uploaded object key=4jwbfs8cmjic62kqh273yr1zpk607nsk.narinfo error="server returned 404: 404 page not found\n"2922--- PASS: TestService_AuthMiddleware_OIDC (0.44s)2923 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2924 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2925 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2926 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)29272026/10/01 09:47:16 WARN Failed to register uploaded object key=x8lkkrfw4k45dvaj6ikdy7d5z17h1mch.narinfo error="server returned 404: 404 page not found\n"29282026/10/01 09:47:16 WARN Failed to register uploaded object key=dn1sq599abj5n4d77va32x9xjfjkg9n8.narinfo error="server returned 404: 404 page not found\n"29292026/10/01 09:47:16 INFO Received complete push request method=POST path=/api/pushes/1/complete29302026/10/01 09:47:16 WARN Failed to register uploaded object key=2mkgw1dmc86pazyqpafy7gl9sw863zgm.narinfo error="server returned 404: 404 page not found\n"29312026/10/01 09:47:16 INFO Upload complete. (57ms)29322026/10/01 09:47:16 INFO Upload complete. (57ms)29332026/10/01 09:47:16 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=02934=== NAME TestClientPushesUseOnePush2935 client_pushes_test.go:97: Retrieved narinfo from S3:2936 StorePath: /build/TestClientPushesUseOnePush75932030/001/store/x8lkkrfw4k45dvaj6ikdy7d5z17h1mch-shared-dep2937 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2938 Compression: zstd2939 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822940 NarSize: 1362941 References: 2942 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2943=== NAME TestClientWithDependencies2944 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2342877503/001/store) requires matching store prefix29452026/10/01 09:47:16 INFO Vacuumed table table=pending_closures2946=== NAME TestClientPushesUseOnePush2947 client_pushes_test.go:97: Retrieved narinfo from S3:2948 StorePath: /build/TestClientPushesUseOnePush75932030/001/store/dn1sq599abj5n4d77va32x9xjfjkg9n8-a2949 URL: nar/1nsisj648n99ip8ys8dglh5y2m4gi11454pkd0k5xbc05609znbj.nar.zst2950 Compression: zstd2951 NarHash: sha256:1nsisj648n99ip8ys8dglh5y2m4gi11454pkd0k5xbc05609znbj2952 NarSize: 2082953 References: /build/TestClientPushesUseOnePush75932030/001/store/x8lkkrfw4k45dvaj6ikdy7d5z17h1mch-shared-dep2954 CA: text:sha256:163kr128m9qprwv62ivjblcmxx9j72i6x81jiw1jahpnvb5ahy1f2955--- PASS: TestClientWithDependencies (0.58s)29562026/10/01 09:47:16 INFO Vacuumed table table=pending_objects29572026/10/01 09:47:16 INFO Vacuumed table table=multipart_uploads29582026/10/01 09:47:16 INFO Vacuumed table table=closures2959=== NAME TestClientPushesUseOnePush2960 client_pushes_test.go:97: Retrieved narinfo from S3:2961 StorePath: /build/TestClientPushesUseOnePush75932030/001/store/2mkgw1dmc86pazyqpafy7gl9sw863zgm-b2962 URL: nar/1nsisj648n99ip8ys8dglh5y2m4gi11454pkd0k5xbc05609znbj.nar.zst2963 Compression: zstd2964 NarHash: sha256:1nsisj648n99ip8ys8dglh5y2m4gi11454pkd0k5xbc05609znbj2965 NarSize: 2082966 References: /build/TestClientPushesUseOnePush75932030/001/store/x8lkkrfw4k45dvaj6ikdy7d5z17h1mch-shared-dep2967 CA: text:sha256:163kr128m9qprwv62ivjblcmxx9j72i6x81jiw1jahpnvb5ahy1f29682026/10/01 09:47:16 INFO Vacuumed table table=objects2969--- PASS: TestClientPushesUseOnePush (0.55s)29702026/10/01 09:47:16 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"29712026/10/01 09:47:16 INFO Received uploads request method=POST path=/api/pending_closures29722026/10/01 09:47:16 INFO Received uploads request method=POST path=/api/pending_closures29732026/10/01 09:47:16 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)29742026/10/01 09:47:16 INFO Uploading bi93mm40zjc9x346az9a6mhmw5apw7h4-a (216B)29752026/10/01 09:47:16 INFO Uploading 7as9nmikbg1mp8rrbg5szf8fhcg4ydcs-shared-dep (136B)29762026/10/01 09:47:16 WARN Failed to register uploaded object key=ff9c0bliwsw8b5vx56i012zrbyqmw8pc.ls error="server returned 404: 404 page not found\n"29772026/10/01 09:47:16 WARN Failed to register uploaded object key=nar/109m3053g0yzpwbrp2s72pdwmsf2q0qsvqz40q5by7kkflirry88.nar.zst error="server returned 404: 404 page not found\n"29782026/10/01 09:47:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"29792026/10/01 09:47:16 WARN Failed to register uploaded object key=bi93mm40zjc9x346az9a6mhmw5apw7h4.ls error="server returned 404: 404 page not found\n"29802026/10/01 09:47:16 WARN Failed to register uploaded object key=7as9nmikbg1mp8rrbg5szf8fhcg4ydcs.ls error="server returned 404: 404 page not found\n"29812026/10/01 09:47:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign29822026/10/01 09:47:16 INFO Signed narinfos id=1 count=229832026/10/01 09:47:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign29842026/10/01 09:47:16 INFO Signed narinfos id=2 count=229852026/10/01 09:47:16 INFO Uploading 4 narinfos29862026/10/01 09:47:16 WARN Failed to register uploaded object key=bi93mm40zjc9x346az9a6mhmw5apw7h4.narinfo error="server returned 404: 404 page not found\n"29872026/10/01 09:47:16 WARN Failed to register uploaded object key=ff9c0bliwsw8b5vx56i012zrbyqmw8pc.narinfo error="server returned 404: 404 page not found\n"29882026/10/01 09:47:16 WARN Failed to register uploaded object key=7as9nmikbg1mp8rrbg5szf8fhcg4ydcs.narinfo error="server returned 404: 404 page not found\n"29892026/10/01 09:47:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete29902026/10/01 09:47:16 WARN Failed to register uploaded object key=7as9nmikbg1mp8rrbg5szf8fhcg4ydcs.narinfo error="server returned 404: 404 page not found\n"29912026/10/01 09:47:16 INFO Completed upload id=129922026/10/01 09:47:16 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete29932026/10/01 09:47:16 INFO Completed upload id=229942026/10/01 09:47:16 INFO Upload complete. (60ms)29952026/10/01 09:47:16 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2996=== NAME TestClientFallsBackToClosures2997 client_pushes_test.go:112: Retrieved narinfo from S3:2998 StorePath: /build/TestClientFallsBackToClosures3804052121/001/store/7as9nmikbg1mp8rrbg5szf8fhcg4ydcs-shared-dep2999 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst3000 Compression: zstd3001 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y823002 NarSize: 1363003 References: 3004 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n3005 client_pushes_test.go:112: Retrieved narinfo from S3:3006 StorePath: /build/TestClientFallsBackToClosures3804052121/001/store/bi93mm40zjc9x346az9a6mhmw5apw7h4-a3007 URL: nar/109m3053g0yzpwbrp2s72pdwmsf2q0qsvqz40q5by7kkflirry88.nar.zst3008 Compression: zstd3009 NarHash: sha256:109m3053g0yzpwbrp2s72pdwmsf2q0qsvqz40q5by7kkflirry883010 NarSize: 2163011 References: /build/TestClientFallsBackToClosures3804052121/001/store/7as9nmikbg1mp8rrbg5szf8fhcg4ydcs-shared-dep3012 CA: text:sha256:0ydnk93ywhxqq5fligg1v4r220i4vranskmlqrgyiw7jynnn3zwl3013 client_pushes_test.go:112: Retrieved narinfo from S3:3014 StorePath: /build/TestClientFallsBackToClosures3804052121/001/store/ff9c0bliwsw8b5vx56i012zrbyqmw8pc-b3015 URL: nar/109m3053g0yzpwbrp2s72pdwmsf2q0qsvqz40q5by7kkflirry88.nar.zst3016 Compression: zstd3017 NarHash: sha256:109m3053g0yzpwbrp2s72pdwmsf2q0qsvqz40q5by7kkflirry883018 NarSize: 2163019 References: /build/TestClientFallsBackToClosures3804052121/001/store/7as9nmikbg1mp8rrbg5szf8fhcg4ydcs-shared-dep3020 CA: text:sha256:0ydnk93ywhxqq5fligg1v4r220i4vranskmlqrgyiw7jynnn3zwl3021--- PASS: TestClientFallsBackToClosures (0.55s)30222026/10/01 09:47:16 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=362.848568ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present3023--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.74s)3024--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)3025 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.06s)3026 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)3027 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.89s)30282026/10/01 09:47:16 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=843.664865ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present3029=== NAME TestOrphanedObjectsGCStressTest3030 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains3031 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion3032 orphaned_objects_gc_test.go:509: Stress test completed successfully:3033 orphaned_objects_gc_test.go:510: - Active objects preserved: 203034 orphaned_objects_gc_test.go:511: - Objects deleted: 2103035 orphaned_objects_gc_test.go:512: - Total GC'd: 2103036--- PASS: TestOrphanedObjectsGCStressTest (1.87s)30372026/10/01 09:47:17 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.493317888s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present30382026/10/01 09:47:17 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=03039=== NAME TestClientIntegration3040 client_integration_test.go:323: Objects in database after GC:3041 client_integration_test.go:323: Successfully deleted all objects with GC --force3042--- PASS: TestClientIntegration (2.67s)30432026/10/01 09:47:18 WARN Rate limiter enabled after throttle name=s3-test rate=530442026/10/01 09:47:18 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."3045=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle3046 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=103047 throttle_test.go:215: Rate limiter: enabled=true, rate=5.003048--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.85s)30492026/10/01 09:47:18 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=030502026/10/01 09:47:18 INFO Received create pin request method=POST path=/api/pins/myapp30512026/10/01 09:47:18 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3455690308/001/store/kkgz53swgby3fzd8icbjybfs38cmyccl-pinned-file.txt narinfo_key=kkgz53swgby3fzd8icbjybfs38cmyccl.narinfo30522026/10/01 09:47:18 INFO Starting cleanup of old closures method=DELETE path=/api/closures30532026/10/01 09:47:18 INFO Garbage collection started30542026/10/01 09:47:18 INFO Aborted multipart uploads count=0 kept=030552026/10/01 09:47:18 WARN Force mode enabled - objects will be deleted immediately without grace period30562026/10/01 09:47:18 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=030572026/10/01 09:47:18 INFO Vacuumed table table=pending_closures30582026/10/01 09:47:18 INFO Vacuumed table table=pending_objects30592026/10/01 09:47:18 INFO Vacuumed table table=multipart_uploads30602026/10/01 09:47:18 INFO Vacuumed table table=closures30612026/10/01 09:47:18 INFO Vacuumed table table=objects30622026/10/01 09:47:19 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30632026/10/01 09:47:19 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=199.706345ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30642026/10/01 09:47:19 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=363.86082ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30652026/10/01 09:47:19 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=781.605058ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config3066=== NAME TestPinProtectsFromGC3067 client_integration_test.go:840: Pin successfully protected closure from garbage collection3068--- PASS: TestPinProtectsFromGC (4.65s)30692026/10/01 09:47:20 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.597138599s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30702026/10/01 09:47:21 INFO Aborted multipart uploads count=1 kept=030712026/10/01 09:47:21 INFO Received cleanup request method=DELETE path=/api/pending_closures30722026/10/01 09:47:21 INFO Aborted multipart uploads count=1 kept=03073--- PASS: TestPendingCleanupUsesOneCutoff (6.45s)30742026/10/01 09:47:22 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"30752026/10/01 09:47:22 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30762026/10/01 09:47:22 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=213.839267ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30772026/10/01 09:47:22 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=375.097676ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30782026/10/01 09:47:22 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=814.379937ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30792026/10/01 09:47:23 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.51010511s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config30802026/10/01 09:47:25 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30812026/10/01 09:47:25 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=210.509633ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30822026/10/01 09:47:25 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=391.221466ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30832026/10/01 09:47:25 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=808.831668ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures30842026/10/01 09:47:26 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.617652211s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures3085--- PASS: TestClientErrorHandling (0.00s)3086 --- PASS: TestClientErrorHandling/InvalidStorePath (0.33s)3087 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.43s)3088 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.31s)3089PASS30902026-10-01 09:47:28.450 UTC [129] LOG: received smart shutdown request30912026-10-01 09:47:28.454 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 130922026-10-01 09:47:28.464 UTC [134] LOG: shutting down30932026-10-01 09:47:28.464 UTC [134] LOG: checkpoint starting: shutdown immediate30942026-10-01 09:47:29.289 UTC [134] LOG: checkpoint complete: wrote 10312 buffers (62.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 24 recycled; write=0.175 s, sync=0.622 s, total=0.825 s; sync files=28648, longest=0.003 s, average=0.001 s; distance=396526 kB, estimate=396526 kB; lsn=0/19AA1568, redo lsn=0/19AA156830952026-10-01 09:47:29.369 UTC [129] LOG: database system is shut down3096Running OIDC tests...3097=== RUN TestAudienceForIssuer3098=== PAUSE TestAudienceForIssuer3099=== RUN TestGlobMatch3100=== PAUSE TestGlobMatch3101=== RUN TestValidateToken_ValidToken3102=== PAUSE TestValidateToken_ValidToken3103=== RUN TestValidateToken_WrongAudience3104=== PAUSE TestValidateToken_WrongAudience3105=== RUN TestValidateToken_Expired3106=== PAUSE TestValidateToken_Expired3107=== RUN TestValidateToken_BoundClaimsMismatch3108=== PAUSE TestValidateToken_BoundClaimsMismatch3109=== RUN TestValidateToken_BoundSubjectMismatch3110=== PAUSE TestValidateToken_BoundSubjectMismatch3111=== RUN TestValidateToken_MultipleProviders3112=== PAUSE TestValidateToken_MultipleProviders3113=== RUN TestValidateToken_NoMatchingProvider3114=== PAUSE TestValidateToken_NoMatchingProvider3115=== RUN TestValidateToken_KubernetesServiceAccount3116=== PAUSE TestValidateToken_KubernetesServiceAccount3117=== RUN TestNewValidator_KubernetesRequiresCA3118=== PAUSE TestNewValidator_KubernetesRequiresCA3119=== RUN TestValidateToken_KubernetesIssuerFromOwnToken3120=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken3121=== RUN TestPins_ReservedForMatchingRule3122=== PAUSE TestPins_ReservedForMatchingRule3123=== RUN TestPins_TopLevelShorthand3124=== PAUSE TestPins_TopLevelShorthand3125=== RUN TestPins_ConfigValidation3126=== PAUSE TestPins_ConfigValidation3127=== RUN TestScopes_LegacyProviderDefaultsToWrite3128=== PAUSE TestScopes_LegacyProviderDefaultsToWrite3129=== RUN TestScopes_Rules3130=== PAUSE TestScopes_Rules3131=== RUN TestScopes_ConfigValidation3132=== PAUSE TestScopes_ConfigValidation3133=== CONT TestAudienceForIssuer3134=== CONT TestValidateToken_BoundClaimsMismatch3135--- PASS: TestAudienceForIssuer (0.00s)3136=== CONT TestValidateToken_Expired3137=== CONT TestValidateToken_KubernetesServiceAccount3138=== CONT TestPins_ConfigValidation3139=== CONT TestValidateToken_ValidToken3140=== CONT TestValidateToken_MultipleProviders3141=== CONT TestPins_ReservedForMatchingRule3142=== CONT TestPins_TopLevelShorthand3143=== CONT TestValidateToken_KubernetesIssuerFromOwnToken3144=== CONT TestNewValidator_KubernetesRequiresCA3145=== CONT TestValidateToken_WrongAudience3146=== CONT TestScopes_Rules3147=== CONT TestScopes_ConfigValidation3148=== CONT TestValidateToken_NoMatchingProvider3149=== CONT TestValidateToken_BoundSubjectMismatch3150--- PASS: TestPins_ConfigValidation (0.00s)3151=== CONT TestGlobMatch3152=== CONT TestScopes_LegacyProviderDefaultsToWrite3153=== RUN TestGlobMatch/foo_foo3154=== PAUSE TestGlobMatch/foo_foo3155=== RUN TestGlobMatch/foo_bar3156=== PAUSE TestGlobMatch/foo_bar3157=== RUN TestGlobMatch/*_3158=== PAUSE TestGlobMatch/*_3159=== RUN TestGlobMatch/*_anything3160=== PAUSE TestGlobMatch/*_anything3161--- PASS: TestScopes_ConfigValidation (0.00s)3162=== RUN TestGlobMatch/foo*_foo3163=== PAUSE TestGlobMatch/foo*_foo3164=== RUN TestGlobMatch/foo*_foobar3165=== PAUSE TestGlobMatch/foo*_foobar3166=== RUN TestGlobMatch/foo*_bar3167=== PAUSE TestGlobMatch/foo*_bar3168=== RUN TestGlobMatch/*bar_bar3169=== PAUSE TestGlobMatch/*bar_bar3170=== RUN TestGlobMatch/*bar_foobar3171=== PAUSE TestGlobMatch/*bar_foobar3172=== RUN TestGlobMatch/*bar_foo3173=== PAUSE TestGlobMatch/*bar_foo3174=== RUN TestGlobMatch/foo*bar_foobar3175=== PAUSE TestGlobMatch/foo*bar_foobar3176=== RUN TestGlobMatch/foo*bar_foo123bar3177=== PAUSE TestGlobMatch/foo*bar_foo123bar3178=== RUN TestGlobMatch/foo*bar_foobarbaz3179=== PAUSE TestGlobMatch/foo*bar_foobarbaz3180=== RUN TestGlobMatch/*/*_foo/bar3181=== PAUSE TestGlobMatch/*/*_foo/bar3182=== RUN TestGlobMatch/*/*_foo3183=== PAUSE TestGlobMatch/*/*_foo3184=== RUN TestGlobMatch/refs/heads/*_refs/heads/main3185=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main3186=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.03187=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.03188=== RUN TestGlobMatch/refs/*/main_refs/heads/main3189=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main3190=== RUN TestGlobMatch/fo?_foo3191=== PAUSE TestGlobMatch/fo?_foo3192=== RUN TestGlobMatch/fo?_fo3193=== PAUSE TestGlobMatch/fo?_fo3194=== RUN TestGlobMatch/fo?_fooo3195=== PAUSE TestGlobMatch/fo?_fooo3196=== RUN TestGlobMatch/?oo_foo3197=== PAUSE TestGlobMatch/?oo_foo3198=== RUN TestGlobMatch/?oo_boo3199=== PAUSE TestGlobMatch/?oo_boo3200=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3201=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3202=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3203=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3204=== CONT TestGlobMatch/foo_foo3205=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.03206=== CONT TestGlobMatch/foo*_foobar3207=== CONT TestGlobMatch/foo*_foo3208=== CONT TestGlobMatch/foo*bar_foobar3209=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main3210=== CONT TestGlobMatch/foo_bar3211=== CONT TestGlobMatch/*/*_foo3212=== CONT TestGlobMatch/refs/heads/*_refs/heads/main3213=== CONT TestGlobMatch/fo?_fo3214=== CONT TestGlobMatch/fo?_fooo3215=== CONT TestGlobMatch/fo?_foo3216=== CONT TestGlobMatch/*/*_foo/bar3217=== CONT TestGlobMatch/refs/*/main_refs/heads/main3218=== CONT TestGlobMatch/foo*bar_foobarbaz3219=== CONT TestGlobMatch/foo*bar_foo123bar3220=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main3221=== CONT TestGlobMatch/?oo_boo3222=== CONT TestGlobMatch/*bar_foo3223=== CONT TestGlobMatch/*bar_foobar3224=== CONT TestGlobMatch/*bar_bar3225=== CONT TestGlobMatch/foo*_bar3226=== CONT TestGlobMatch/?oo_foo3227=== CONT TestGlobMatch/*_anything3228=== CONT TestGlobMatch/*_3229--- PASS: TestGlobMatch (0.00s)3230 --- PASS: TestGlobMatch/foo_foo (0.00s)3231 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)3232 --- PASS: TestGlobMatch/foo*_foobar (0.00s)3233 --- PASS: TestGlobMatch/foo*_foo (0.00s)3234 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)3235 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)3236 --- PASS: TestGlobMatch/foo_bar (0.00s)3237 --- PASS: TestGlobMatch/*/*_foo (0.00s)3238 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)3239 --- PASS: TestGlobMatch/fo?_fo (0.00s)3240 --- PASS: TestGlobMatch/fo?_fooo (0.00s)3241 --- PASS: TestGlobMatch/fo?_foo (0.00s)3242 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)3243 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)3244 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)3245 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)3246 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)3247 --- PASS: TestGlobMatch/?oo_boo (0.00s)3248 --- PASS: TestGlobMatch/*bar_foo (0.00s)3249 --- PASS: TestGlobMatch/*bar_foobar (0.00s)3250 --- PASS: TestGlobMatch/*bar_bar (0.00s)3251 --- PASS: TestGlobMatch/foo*_bar (0.00s)3252 --- PASS: TestGlobMatch/?oo_foo (0.00s)3253 --- PASS: TestGlobMatch/*_anything (0.00s)3254 --- PASS: TestGlobMatch/*_ (0.00s)32552026/10/01 09:47:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45921/oidc32562026/10/01 09:47:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34209/oidc3257--- PASS: TestPins_ReservedForMatchingRule (0.05s)3258--- PASS: TestPins_TopLevelShorthand (0.05s)32592026/10/01 09:47:30 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:462253260--- PASS: TestValidateToken_KubernetesServiceAccount (0.06s)32612026/10/01 09:47:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34065/oidc3262--- PASS: TestScopes_Rules (0.08s)32632026/10/01 09:47:30 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1233264--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.10s)32652026/10/01 09:47:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32939/oidc3266--- PASS: TestValidateToken_WrongAudience (0.13s)32672026/10/01 09:47:30 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:42179/oidc32682026/10/01 09:47:30 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:33677/oidc3269--- PASS: TestValidateToken_MultipleProviders (0.14s)32702026/10/01 09:47:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36207/oidc3271--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.15s)32722026/10/01 09:47:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32875/oidc3273--- PASS: TestValidateToken_ValidToken (0.16s)32742026/10/01 09:47:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34215/oidc3275--- PASS: TestValidateToken_BoundSubjectMismatch (0.16s)32762026/10/01 09:47:30 http: TLS handshake error from 127.0.0.1:59954: remote error: tls: bad certificate3277--- PASS: TestNewValidator_KubernetesRequiresCA (0.17s)32782026/10/01 09:47:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43169/oidc3279--- PASS: TestValidateToken_Expired (0.17s)32802026/10/01 09:47:31 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:41881/oidc3281--- PASS: TestValidateToken_NoMatchingProvider (0.35s)32822026/10/01 09:47:31 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34663/oidc3283--- PASS: TestValidateToken_BoundClaimsMismatch (0.37s)3284PASS3285Running hook tests...3286=== RUN TestSendPathsEmpty3287=== PAUSE TestSendPathsEmpty3288=== RUN TestQueueEnqueueAndFetch3289=== PAUSE TestQueueEnqueueAndFetch3290=== RUN TestQueueDeduplication3291=== PAUSE TestQueueDeduplication3292=== RUN TestQueueRemove3293=== PAUSE TestQueueRemove3294=== RUN TestQueueFetchBatchLimit3295=== PAUSE TestQueueFetchBatchLimit3296=== RUN TestQueueRetryMovesToBack3297=== PAUSE TestQueueRetryMovesToBack3298=== RUN TestQueueFetchRemoveLifecycle3299=== PAUSE TestQueueFetchRemoveLifecycle3300=== RUN TestQueueConcurrentWriters3301=== PAUSE TestQueueConcurrentWriters3302=== RUN TestQueueRemoveLargeClosure3303=== PAUSE TestQueueRemoveLargeClosure3304=== RUN TestServerClientIntegration3305=== PAUSE TestServerClientIntegration3306=== RUN TestServerQueueError3307=== PAUSE TestServerQueueError3308=== RUN TestGetListenerSocketActivation3309 server_test.go:210: === RUN TestGetListenerSocketActivation3310 --- PASS: TestGetListenerSocketActivation (0.00s)3311 PASS3312 3313--- PASS: TestGetListenerSocketActivation (0.01s)3314=== RUN TestDrainIsolatesPoisonPath3315=== PAUSE TestDrainIsolatesPoisonPath3316=== RUN TestRunNotBlockedByPoisonHead3317=== PAUSE TestRunNotBlockedByPoisonHead3318=== RUN TestDrainGivesUpWhenServerDown3319=== PAUSE TestDrainGivesUpWhenServerDown3320=== RUN TestFailedPathPrunedByLaterClosure3321=== PAUSE TestFailedPathPrunedByLaterClosure3322=== RUN TestWorkerUploadsAndRemoves3323=== PAUSE TestWorkerUploadsAndRemoves3324=== RUN TestWorkerSkipsGCdPaths3325=== PAUSE TestWorkerSkipsGCdPaths3326=== RUN TestWorkerPrunesClosureDeps3327=== PAUSE TestWorkerPrunesClosureDeps3328=== RUN TestDrainTimeout3329=== PAUSE TestDrainTimeout3330=== CONT TestSendPathsEmpty3331=== CONT TestDrainIsolatesPoisonPath3332=== CONT TestDrainGivesUpWhenServerDown3333--- PASS: TestSendPathsEmpty (0.00s)3334=== CONT TestServerQueueError3335=== CONT TestServerClientIntegration3336=== CONT TestQueueRemoveLargeClosure3337=== CONT TestQueueConcurrentWriters3338=== CONT TestWorkerUploadsAndRemoves3339=== CONT TestQueueFetchRemoveLifecycle3340=== CONT TestQueueRetryMovesToBack3341=== CONT TestDrainTimeout3342=== CONT TestWorkerPrunesClosureDeps3343=== CONT TestQueueFetchBatchLimit33442026/10/01 09:47:31 ERROR Failed to queue paths error="permission denied" count=13345=== CONT TestWorkerSkipsGCdPaths3346=== CONT TestQueueRemove3347=== CONT TestQueueDeduplication3348=== CONT TestRunNotBlockedByPoisonHead3349=== CONT TestQueueEnqueueAndFetch3350=== CONT TestFailedPathPrunedByLaterClosure3351--- PASS: TestServerQueueError (0.00s)3352--- PASS: TestServerClientIntegration (0.00s)33532026/10/01 09:47:31 INFO Upload queue status pending=233542026/10/01 09:47:31 INFO Uploading batch count=133552026/10/01 09:47:31 INFO Upload queue status pending=233562026/10/01 09:47:31 INFO Uploading batch count=133572026/10/01 09:47:31 INFO Uploading batch count=233582026/10/01 09:47:31 ERROR Upload failed error="upload failed" count=133592026/10/01 09:47:31 INFO Upload queue status pending=233602026/10/01 09:47:31 INFO Uploading batch count=233612026/10/01 09:47:31 INFO Uploading batch count=433622026/10/01 09:47:31 ERROR Upload failed error="upload failed" count=433632026/10/01 09:47:31 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2288665357/002/nonexistent33642026/10/01 09:47:31 INFO Uploading batch count=233652026/10/01 09:47:31 ERROR Upload failed error="upload failed" count=233662026/10/01 09:47:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1950843939/002/a3367--- PASS: TestQueueRetryMovesToBack (0.01s)3368--- PASS: TestQueueEnqueueAndFetch (0.01s)33692026/10/01 09:47:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath2392436494/002/bbb3370--- PASS: TestQueueFetchBatchLimit (0.01s)33712026/10/01 09:47:31 INFO Upload queue status pending=333722026/10/01 09:47:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1950843939/002/b33732026/10/01 09:47:31 INFO Uploading batch count=133742026/10/01 09:47:31 INFO Uploading batch count=13375--- PASS: TestQueueRemove (0.01s)33762026/10/01 09:47:31 ERROR Upload failed error="upload failed" count=133772026/10/01 09:47:31 INFO Uploading batch count=13378--- PASS: TestQueueDeduplication (0.01s)3379--- PASS: TestQueueFetchRemoveLifecycle (0.01s)33802026/10/01 09:47:31 INFO Uploading batch count=133812026/10/01 09:47:31 INFO Uploading batch count=233822026/10/01 09:47:31 ERROR Upload failed error="upload failed" count=233832026/10/01 09:47:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1950843939/002/c33842026/10/01 09:47:31 INFO Uploading batch count=133852026/10/01 09:47:31 ERROR Upload failed error="upload failed" count=133862026/10/01 09:47:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1950843939/002/d33872026/10/01 09:47:31 INFO Uploading batch count=233882026/10/01 09:47:31 ERROR Upload failed error="upload failed" count=233892026/10/01 09:47:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1950843939/002/e33902026/10/01 09:47:31 INFO Uploading batch count=133912026/10/01 09:47:31 ERROR Upload failed error="upload failed" count=133922026/10/01 09:47:31 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1950843939/002/f3393--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)33942026/10/01 09:47:31 INFO Uploading batch count=133952026/10/01 09:47:31 ERROR Upload failed error="upload failed" count=133962026/10/01 09:47:31 ERROR Drain finished with paths left in queue remaining=1033972026/10/01 09:47:31 ERROR Drain finished with paths left in queue remaining=13398--- PASS: TestDrainIsolatesPoisonPath (0.02s)3399--- PASS: TestDrainGivesUpWhenServerDown (0.02s)3400--- PASS: TestWorkerPrunesClosureDeps (0.03s)3401--- PASS: TestWorkerSkipsGCdPaths (0.03s)3402--- PASS: TestWorkerUploadsAndRemoves (0.03s)3403--- PASS: TestQueueRemoveLargeClosure (0.15s)3404--- PASS: TestQueueConcurrentWriters (0.20s)34052026/10/01 09:47:31 ERROR Upload failed error="context deadline exceeded" count=234062026/10/01 09:47:31 ERROR Drain finished with paths left in queue remaining=43407--- PASS: TestDrainTimeout (0.21s)34082026/10/01 09:47:32 INFO Uploading batch count=134092026/10/01 09:47:32 INFO Uploading batch count=134102026/10/01 09:47:32 INFO Uploading batch count=134112026/10/01 09:47:32 ERROR Upload failed error="upload failed" count=134122026/10/01 09:47:32 INFO Uploading batch count=134132026/10/01 09:47:32 ERROR Upload failed error="upload failed" count=134142026/10/01 09:47:32 INFO Uploading batch count=134152026/10/01 09:47:32 ERROR Upload failed error="upload failed" count=134162026/10/01 09:47:32 INFO Uploading batch count=134172026/10/01 09:47:32 ERROR Upload failed error="upload failed" count=134182026/10/01 09:47:32 ERROR Drain finished with paths left in queue remaining=13419--- PASS: TestRunNotBlockedByPoisonHead (1.03s)3420PASS