niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #277
· 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 TestStreamPushGivesUpOnDeadServer97=== CONT TestScriptTokenEmptyCommand98--- PASS: TestScriptTokenEmptyCommand (0.00s)99=== CONT TestShellSplitErrors100=== CONT TestStreamPushRequestLine101=== CONT TestShellSplit102=== CONT TestSetClientTLSDoesNotMutateDefaultTransport103=== CONT TestUploadMultipart_SupersededByPeer1042026/09/29 08:16:22 ERROR Upload failed error="connection refused" count=20105=== CONT TestSetClientTLS106=== RUN TestUploadMultipart_SupersededByPeer/exists107=== PAUSE TestUploadMultipart_SupersededByPeer/exists1082026/09/29 08:16:22 ERROR Server seems unavailable, giving up on batch untried=17109=== CONT TestClientSignaturesByStorePath110=== CONT TestStreamPushReportsSignatures111=== CONT TestStreamPushBatchesUnderLoad112=== CONT TestStreamPushIsolatesFailures113=== CONT TestEncodeNixBase32WithRealHash114=== CONT TestDoWithRetry_BodyReplayedViaGetBody115=== CONT TestResolveStorePath116=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess117=== CONT TestPathInfoHashCompatibility118=== CONT TestGetStorePathHash119=== CONT TestConvertHashToNix32120=== CONT TestPathInfoCACompatibility121=== CONT TestRateLimiterFeedback122=== CONT TestSetClientTLSErrors123=== CONT TestStreamPushReportsEveryPath124=== CONT TestScriptTokenScriptFails125=== CONT TestParsePathInfoJSON126=== RUN TestUploadMultipart_SupersededByPeer/missing127=== CONT TestScriptTokenBadJSON128--- PASS: TestShellSplitErrors (0.00s)129--- PASS: TestShellSplit (0.00s)130--- PASS: TestClientSignaturesByStorePath (0.00s)131=== CONT TestScriptTokenEmptyToken132=== RUN TestConvertHashToNix32/SRI_format_to_Nix32133--- PASS: TestEncodeNixBase32WithRealHash (0.00s)134=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix321352026/09/29 08:16:22 ERROR Upload failed error="bad path" count=3136=== RUN TestPathInfoCACompatibility/null_ca_field137=== PAUSE TestPathInfoCACompatibility/null_ca_field138=== RUN TestPathInfoCACompatibility/old_string_format_-_text139=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text140=== RUN TestParsePathInfoJSON/Nix_format141=== PAUSE TestParsePathInfoJSON/Nix_format142=== RUN TestParsePathInfoJSON/Lix_format143=== PAUSE TestParsePathInfoJSON/Lix_format144=== RUN TestParsePathInfoJSON/empty_input145=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)146=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)147=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon148=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon1492026/09/29 08:16:22 WARN Rate limiter enabled after throttle name=server-test rate=5150=== CONT TestEncodeNixBase32151=== RUN TestEncodeNixBase32/test_string_hash152=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI153=== RUN TestConvertHashToNix32/already_Nix32_format154=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI155=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512156=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive157=== RUN TestRateLimiterFeedback/429_enables_limiter158=== PAUSE TestParsePathInfoJSON/empty_input159=== RUN TestGetStorePathHash/valid_store_path160=== PAUSE TestUploadMultipart_SupersededByPeer/missing161=== PAUSE TestEncodeNixBase32/test_string_hash162=== RUN TestEncodeNixBase32/empty_input163=== PAUSE TestEncodeNixBase32/empty_input164=== CONT TestDumpPathWriterError165--- PASS: TestResolveStorePath (0.00s)166=== CONT TestScriptTokenNoExpiryRerunsEveryCall167--- PASS: TestStreamPushIsolatesFailures (0.00s)168=== CONT TestDumpPathSingleFile1692026/09/29 08:16:22 ERROR Upload failed error=boom count=1170=== CONT TestFileTokenEmpty171=== CONT TestFileTokenMissing172--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)173=== RUN TestSetClientTLSErrors/missing_cert_file174--- PASS: TestScriptTokenEmptyToken (0.00s)175=== CONT TestDumpPathMatchesNix176--- PASS: TestStreamPushReportsSignatures (0.00s)177--- PASS: TestScriptTokenScriptFails (0.00s)178=== CONT TestParsePathInfoJSONMultiplePaths179=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths180--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)181--- PASS: TestFileTokenMissing (0.00s)182--- PASS: TestFileTokenEmpty (0.00s)183=== CONT TestFilterOversizedClosures184=== RUN TestFilterOversizedClosures/no_limit_keeps_everything185=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything186=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped187=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped188=== RUN TestFilterOversizedClosures/all_closures_skipped189=== RUN TestSetClientTLS/rejects_connection_without_client_cert190=== PAUSE TestFilterOversizedClosures/all_closures_skipped191=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert192=== CONT TestPartSizeForNAR193=== RUN TestPartSizeForNAR/zero_stays_at_minimum194=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum195=== RUN TestPartSizeForNAR/small_stays_at_minimum196=== PAUSE TestPartSizeForNAR/small_stays_at_minimum197=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum198=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum199=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA200=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts201=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts202=== RUN TestPartSizeForNAR/1_TiB203=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA204=== RUN TestSetClientTLS/preserves_debug_logging_transport205=== CONT TestUploadMultipart_PartsInParallel206--- PASS: TestScriptTokenBadJSON (0.00s)207=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2082026/09/29 08:16:22 WARN Rate limiter enabled after throttle name=server-test rate=5209=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512210=== RUN TestPathInfoCACompatibility/new_structured_format_-_text211=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text2122026/09/29 08:16:22 ERROR Upload failed error=boom count=1213=== CONT TestCaseHackSuffix2142026/09/29 08:16:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:35451215=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths216=== PAUSE TestGetStorePathHash/valid_store_path217=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths218=== CONT TestFileTokenReadsAndCaches219=== RUN TestParsePathInfoJSON/whitespace_only220=== PAUSE TestRateLimiterFeedback/429_enables_limiter221=== CONT TestScriptTokenCachesUntilRefresh222=== PAUSE TestConvertHashToNix32/already_Nix32_format223=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method224=== PAUSE TestSetClientTLSErrors/missing_cert_file225=== PAUSE TestSetClientTLS/preserves_debug_logging_transport226=== CONT TestStaticToken227=== CONT TestUploadMultipart_SupersededByPeer/missing228--- PASS: TestStreamPushReportsEveryPath (0.00s)229--- PASS: TestDoServerRequestAttachesToken (0.01s)230=== CONT TestRegisterUploadedObjectReusesConnections231=== CONT TestUploadMultipart_SupersededByPeer/exists232=== RUN TestSetClientTLSErrors/missing_key_file233=== PAUSE TestPartSizeForNAR/1_TiB234=== RUN TestPartSizeForNAR/5_TiB_S3_max_object235=== RUN TestRateLimiterFeedback/503_enables_limiter236=== PAUSE TestSetClientTLSErrors/missing_key_file237=== PAUSE TestRateLimiterFeedback/503_enables_limiter238=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter239=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter240=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter241=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter242=== CONT TestEncodeNixBase32/test_string_hash243--- PASS: TestDumpPathSingleFile (0.03s)244=== CONT TestEncodeNixBase32/empty_input245=== CONT TestFilterOversizedClosures/no_limit_keeps_everything246=== CONT TestFilterOversizedClosures/all_closures_skipped2472026/09/29 08:16:22 WARN Rate limiter backed off name=server-test rate=52482026/09/29 08:16:22 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:35451249=== RUN TestGetStorePathHash/basename_without_hyphen_should_error250--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.04s)251=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped252--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)253 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.03s)254 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.03s)2552026/09/29 08:16:22 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=2000256=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI257=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)258=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512259=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon260=== CONT TestSetClientTLS/rejects_connection_without_client_cert261=== PAUSE TestParsePathInfoJSON/whitespace_only262--- PASS: TestStaticToken (0.00s)263=== CONT TestSetClientTLS/preserves_debug_logging_transport264--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)265=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA266=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method267=== RUN TestParsePathInfoJSON/invalid_JSON268=== PAUSE TestParsePathInfoJSON/invalid_JSON269=== CONT TestRateLimiterFeedback/429_enables_limiter270--- PASS: TestFileTokenReadsAndCaches (0.00s)271=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter272=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter273=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths274=== CONT TestRateLimiterFeedback/503_enables_limiter2752026/09/29 08:16:22 WARN Rate limiter enabled after throttle name=server-test rate=52762026/09/29 08:16:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:37963277=== CONT TestPathInfoCACompatibility/null_ca_field278=== CONT TestParsePathInfoJSON/Nix_format279=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method2802026/09/29 08:16:22 WARN Rate limiter backed off name=server-test rate=5281=== CONT TestPathInfoCACompatibility/new_structured_format_-_text2822026/09/29 08:16:22 WARN Rate limiter enabled after throttle name=server-test rate=5283=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2842026/09/29 08:16:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:33591285=== CONT TestPathInfoCACompatibility/old_string_format_-_text286=== CONT TestParsePathInfoJSON/invalid_JSON287=== CONT TestParsePathInfoJSON/empty_input288=== CONT TestParsePathInfoJSON/Lix_format289=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths290=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths291--- PASS: TestPathInfoCACompatibility (0.04s)292 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)293 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)294 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)295 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)296 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)2972026/09/29 08:16:22 WARN Rate limiter backed off name=server-test rate=5298=== CONT TestParsePathInfoJSON/whitespace_only299--- PASS: TestParsePathInfoJSON (0.04s)300 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)301 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)302 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)303 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)304 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)305--- PASS: TestParsePathInfoJSONMultiplePaths (0.03s)306 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)307 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)308--- PASS: TestRateLimiterFeedback (0.03s)309 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)310 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)311 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)312 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)313=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object314=== RUN TestPartSizeForNAR/capped_at_5_GiB315=== PAUSE TestPartSizeForNAR/capped_at_5_GiB316=== RUN TestSetClientTLSErrors/missing_ca_file317=== PAUSE TestSetClientTLSErrors/missing_ca_file318=== RUN TestSetClientTLSErrors/invalid_ca_file319=== PAUSE TestSetClientTLSErrors/invalid_ca_file320=== CONT TestSetClientTLSErrors/missing_cert_file3212026/09/29 08:16:22 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=50322--- PASS: TestEncodeNixBase32 (0.00s)323 --- PASS: TestEncodeNixBase32/empty_input (0.00s)324 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)325=== CONT TestPartSizeForNAR/zero_stays_at_minimum326=== CONT TestSetClientTLSErrors/invalid_ca_file327=== CONT TestSetClientTLSErrors/missing_ca_file328--- PASS: TestPathInfoHashCompatibility (0.00s)329 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)330 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)331 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)332 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)333=== CONT TestPartSizeForNAR/5_TiB_S3_max_object334=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts335=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum336=== CONT TestPartSizeForNAR/small_stays_at_minimum337=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error338=== CONT TestPartSizeForNAR/capped_at_5_GiB339=== RUN TestConvertHashToNix32/invalid_format340=== CONT TestSetClientTLSErrors/missing_key_file341--- PASS: TestFilterOversizedClosures (0.00s)342 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)343 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)344 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)345=== CONT TestPartSizeForNAR/1_TiB346=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error347=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error348=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error349=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error350=== CONT TestGetStorePathHash/valid_store_path351=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error352=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error353=== CONT TestGetStorePathHash/basename_without_hyphen_should_error354--- PASS: TestGetStorePathHash (0.05s)355 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)356 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)357 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)358 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)359=== PAUSE TestConvertHashToNix32/invalid_format360=== CONT TestConvertHashToNix32/SRI_format_to_Nix32361=== CONT TestConvertHashToNix32/invalid_format362=== CONT TestConvertHashToNix32/already_Nix32_format363--- PASS: TestConvertHashToNix32 (0.05s)364 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)365 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)366 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)367--- PASS: TestPartSizeForNAR (0.04s)368 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)369 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)370 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)371 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)372 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)373 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)374 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)375--- PASS: TestSetClientTLSErrors (0.04s)376 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)377 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.01s)378 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)379 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.01s)380--- PASS: TestScriptTokenCachesUntilRefresh (0.02s)3812026/09/29 08:16:22 http: TLS handshake error from 127.0.0.1:58618: remote error: tls: bad certificate382--- PASS: TestSetClientTLS (0.01s)383 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)384 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)385 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)386--- PASS: TestStreamPushRequestLine (0.06s)387--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)388--- PASS: TestCaseHackSuffix (0.07s)389--- PASS: TestDumpPathWriterError (0.08s)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/postgres784262310/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/postgres784262310/data -l logfile start422423/build/postgres784262310:5432 - no response4242026-09-29 08:16:24.650 UTC [128] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit4252026-09-29 08:16:24.650 UTC [128] LOG: listening on Unix socket "/build/postgres784262310/.s.PGSQL.5432"4262026-09-29 08:16:24.654 UTC [135] LOG: database system was shut down at 2026-09-29 08:16:24 UTC4272026-09-29 08:16:24.658 UTC [128] LOG: database system is ready to accept connections428/build/postgres784262310:5432 - accepting connections429=== RUN TestService_AuthMiddleware430=== PAUSE TestService_AuthMiddleware431=== RUN TestService_AuthMiddleware_MTLSProxyHeader432=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader433=== RUN TestService_AuthMiddleware_MTLSBoundSubjects434=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects435=== RUN TestService_ReadAuthMiddleware436=== PAUSE TestService_ReadAuthMiddleware437=== RUN TestService_AuthMiddleware_OIDC438=== PAUSE TestService_AuthMiddleware_OIDC439=== RUN TestService_RequireScope_OIDC440=== PAUSE TestService_RequireScope_OIDC441=== RUN TestService_ReadScope_PublicByDefault442=== PAUSE TestService_ReadScope_PublicByDefault443=== RUN TestCacheConfigHandler444=== PAUSE TestCacheConfigHandler445=== RUN TestCacheStatsHandler446=== PAUSE TestCacheStatsHandler447=== RUN TestClientCADerivations448=== PAUSE TestClientCADerivations449=== RUN TestClientErrorHandling450=== PAUSE TestClientErrorHandling451=== RUN TestClientIntegration452=== PAUSE TestClientIntegration453=== RUN TestClientMultipleUploads454=== PAUSE TestClientMultipleUploads455=== RUN TestClientWithDependencies456=== PAUSE TestClientWithDependencies457=== RUN TestClientSharedPathCommittedMidPush458=== PAUSE TestClientSharedPathCommittedMidPush459=== RUN TestPinProtectsFromGC460=== PAUSE TestPinProtectsFromGC461=== RUN TestClientPushesUseOnePush462=== PAUSE TestClientPushesUseOnePush463=== RUN TestClientFallsBackToClosures464=== PAUSE TestClientFallsBackToClosures465=== RUN TestResolveDBConnectionString466=== PAUSE TestResolveDBConnectionString467=== RUN TestLeadElectsOneAndHandsOver468=== PAUSE TestLeadElectsOneAndHandsOver469=== RUN TestLeadIncumbentWinsAfterRestart4702026-09-29 08:16:25.041 UTC [374] ERROR: relation "goose_db_version" does not exist at character 364712026-09-29 08:16:25.041 UTC [374] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4722026/09/29 08:16:25 OK 20241026095416_initial_model.sql (12.25ms)4732026/09/29 08:16:25 OK 20251210153512_drop_unused_gin_index.sql (1.48ms)4742026/09/29 08:16:25 OK 20251218171726_add_pins.sql (3.19ms)4752026/09/29 08:16:25 OK 20260628120000_add_object_size_and_stats.sql (2.94ms)4762026/09/29 08:16:25 OK 20260905000000_add_claims.sql (3.27ms)4772026/09/29 08:16:25 OK 20260920000000_drop_claims.sql (1.98ms)4782026/09/29 08:16:25 OK 20260923120000_add_pushes.sql (1.53ms)4792026/09/29 08:16:25 goose: successfully migrated database to version: 202609231200004802026/09/29 08:16:25 OK 1_commit_pending_closure.sql (1.74ms)4812026/09/29 08:16:25 OK 2_object_stats_trigger.sql (795.59µs)4822026/09/29 08:16:25 OK 3_commit_push.sql (668.37µs)4832026/09/29 08:16:25 goose: up to current file version: 34842026/09/29 08:16:25 INFO lead: acquired remote=192.0.2.1:12344852026/09/29 08:16:25 INFO lead: released remote=192.0.2.1:12344862026/09/29 08:16:25 INFO lead: acquired remote=192.0.2.1:12344872026/09/29 08:16:25 INFO lead: released remote=192.0.2.1:1234488--- PASS: TestLeadIncumbentWinsAfterRestart (0.80s)489=== RUN TestLeadEndsOnShutdown490=== PAUSE TestLeadEndsOnShutdown491=== RUN TestGCAdvisoryLockBlocksConcurrentRun4922026-09-29 08:16:25.814 UTC [384] ERROR: relation "goose_db_version" does not exist at character 364932026-09-29 08:16:25.814 UTC [384] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC4942026/09/29 08:16:25 OK 20241026095416_initial_model.sql (9.5ms)4952026/09/29 08:16:25 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)4962026/09/29 08:16:25 OK 20251218171726_add_pins.sql (3.35ms)4972026/09/29 08:16:25 OK 20260628120000_add_object_size_and_stats.sql (3.08ms)4982026/09/29 08:16:25 OK 20260905000000_add_claims.sql (2.78ms)4992026/09/29 08:16:25 OK 20260920000000_drop_claims.sql (1.77ms)5002026/09/29 08:16:25 OK 20260923120000_add_pushes.sql (1.24ms)5012026/09/29 08:16:25 goose: successfully migrated database to version: 202609231200005022026/09/29 08:16:25 OK 1_commit_pending_closure.sql (1.51ms)5032026/09/29 08:16:25 OK 2_object_stats_trigger.sql (665.27µs)5042026/09/29 08:16:25 OK 3_commit_push.sql (587.55µs)5052026/09/29 08:16:25 goose: up to current file version: 3506--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.12s)507=== RUN TestGCBugBareHashReferences508=== PAUSE TestGCBugBareHashReferences509=== RUN TestGCMetrics510=== PAUSE TestGCMetrics511=== RUN TestGCTaskStore_StartNew512=== PAUSE TestGCTaskStore_StartNew513=== RUN TestGCTaskStore_DeduplicateSameParams514=== PAUSE TestGCTaskStore_DeduplicateSameParams515=== RUN TestGCTaskStore_ConflictDifferentParams516=== PAUSE TestGCTaskStore_ConflictDifferentParams517=== RUN TestGCTaskStore_GetEmpty518=== PAUSE TestGCTaskStore_GetEmpty519=== RUN TestGCTaskStore_GetReturnsLatest520=== PAUSE TestGCTaskStore_GetReturnsLatest521=== RUN TestGCTaskStore_CompletedAllowsNewTask522=== PAUSE TestGCTaskStore_CompletedAllowsNewTask523=== RUN TestGCTaskStore_PhaseUpdates524=== PAUSE TestGCTaskStore_PhaseUpdates525=== RUN TestGCTaskStore_Fail526=== PAUSE TestGCTaskStore_Fail527=== RUN TestGracefulShutdownDrainsInflight528=== PAUSE TestGracefulShutdownDrainsInflight529=== RUN TestService_healthCheckHandler530=== PAUSE TestService_healthCheckHandler531=== RUN TestService_readinessHandler532=== PAUSE TestService_readinessHandler533=== RUN TestGenerateLandingPage534=== PAUSE TestGenerateLandingPage535=== RUN TestCacheConfigHandlerMaxNarSize536=== PAUSE TestCacheConfigHandlerMaxNarSize537=== RUN TestCreatePendingClosureRejectsOversizedNAR538=== PAUSE TestCreatePendingClosureRejectsOversizedNAR539=== RUN TestNARDeduplicationMetadataUploadBug540=== PAUSE TestNARDeduplicationMetadataUploadBug541=== RUN TestMetricsInventory542=== PAUSE TestMetricsInventory543=== RUN TestService_NativeMTLS544=== PAUSE TestService_NativeMTLS545=== RUN TestServerTLSConfig546=== PAUSE TestServerTLSConfig547=== RUN TestMultipartCleanup548=== PAUSE TestMultipartCleanup549=== RUN TestObjectStatsTrigger550=== PAUSE TestObjectStatsTrigger551=== RUN TestOrphanedObjectsGC552=== PAUSE TestOrphanedObjectsGC553=== RUN TestOrphanedObjectsGCStressTest554=== PAUSE TestOrphanedObjectsGCStressTest555=== RUN TestResurrectedObjectNotDeleted556=== PAUSE TestResurrectedObjectNotDeleted557=== RUN TestCreatePin_ReservedPins558=== PAUSE TestCreatePin_ReservedPins559=== RUN TestParseSingleRange560=== PAUSE TestParseSingleRange561=== RUN TestProxyHeadersOnlyTrustedOnSocket562=== PAUSE TestProxyHeadersOnlyTrustedOnSocket563=== RUN TestIsValidCachePath564=== PAUSE TestIsValidCachePath565=== RUN TestReadProxyNarinfo566=== PAUSE TestReadProxyNarinfo567=== RUN TestReadProxyNarinfoAlreadyDecompressed568=== PAUSE TestReadProxyNarinfoAlreadyDecompressed569=== RUN TestReadProxyNarStreaming570=== PAUSE TestReadProxyNarStreaming571=== RUN TestReadProxy404572=== PAUSE TestReadProxy404573=== RUN TestReadProxyInvalidPath574=== PAUSE TestReadProxyInvalidPath575=== RUN TestReadProxyHead576=== PAUSE TestReadProxyHead577=== RUN TestReadProxyConditionalGet578=== PAUSE TestReadProxyConditionalGet579=== RUN TestReadProxyRootRedirectsToIndexHTML580=== PAUSE TestReadProxyRootRedirectsToIndexHTML581=== RUN TestReadProxyDisabled582=== PAUSE TestReadProxyDisabled583=== RUN TestReadRedirectNar584=== PAUSE TestReadRedirectNar585=== RUN TestReadRedirectKeepsNarinfoProxied586=== PAUSE TestReadRedirectKeepsNarinfoProxied587=== RUN TestReadProxyRangeRequest588=== PAUSE TestReadProxyRangeRequest589=== RUN TestReadRedirectUsesPublicS3URL590=== PAUSE TestReadRedirectUsesPublicS3URL591=== RUN TestPush_OverlappingRootsStoreOneRowPerKey592=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey593=== RUN TestPush_CompleteCommitsEveryRoot594=== PAUSE TestPush_CompleteCommitsEveryRoot595=== RUN TestPush_CommitFailsWhenSkippedKeyWasCollected596=== PAUSE TestPush_CommitFailsWhenSkippedKeyWasCollected597=== RUN TestPush_RejectsBadRequests598=== PAUSE TestPush_RejectsBadRequests599=== RUN TestPush_SignsNarinfosOfItsPendingObjects600=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects601=== RUN TestRedundantMultipartUpload602=== PAUSE TestRedundantMultipartUpload603=== RUN TestCompleteMultipartUpload_ErrorButObjectExists604=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists605=== RUN TestCompletedNarNotReofferedAcrossClosures606=== PAUSE TestCompletedNarNotReofferedAcrossClosures607=== RUN TestPresignedUploadRegisteredBeforeCommit608=== PAUSE TestPresignedUploadRegisteredBeforeCommit609=== RUN TestService_Rustfstest610=== PAUSE TestService_Rustfstest611=== RUN TestParseSize612=== PAUSE TestParseSize613=== RUN TestSkippedUploadsHandler614=== PAUSE TestSkippedUploadsHandler615=== RUN TestSystemdListenerNotActivated616--- PASS: TestSystemdListenerNotActivated (0.00s)617=== RUN TestWatchdogBeatsWhenHealthy618--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)619=== RUN TestWatchdogSkipsWhenUnhealthy6202026/09/29 08:16:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6212026/09/29 08:16:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6222026/09/29 08:16:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6232026/09/29 08:16:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6242026/09/29 08:16:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6252026/09/29 08:16:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6262026/09/29 08:16:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6272026/09/29 08:16:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6282026/09/29 08:16:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"629--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)630=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle631=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle632=== RUN TestProxyWriteTimeout633=== PAUSE TestProxyWriteTimeout634=== RUN TestIsValidUploadKey635=== PAUSE TestIsValidUploadKey636=== RUN TestUploadHandlersRejectInvalidKeys637=== PAUSE TestUploadHandlersRejectInvalidKeys638=== RUN TestUploadHandlersRejectOversizedBody639=== PAUSE TestUploadHandlersRejectOversizedBody640=== RUN TestService_cleanupPendingClosuresHandler641=== PAUSE TestService_cleanupPendingClosuresHandler642=== RUN TestService_createPendingClosureHandler643=== PAUSE TestService_createPendingClosureHandler644=== RUN TestService_verifyS3Integrity645=== PAUSE TestService_verifyS3Integrity646=== RUN TestCompleteMultipartUnregistered647=== PAUSE TestCompleteMultipartUnregistered648=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT649=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT650=== CONT TestProxyWriteTimeout651=== RUN TestProxyWriteTimeout/narinfo652=== PAUSE TestProxyWriteTimeout/narinfo653=== CONT TestService_AuthMiddleware654=== CONT TestReadProxy404655=== CONT TestReadProxyNarStreaming656=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle657=== CONT TestReadProxyNarinfoAlreadyDecompressed658=== CONT TestSkippedUploadsHandler659=== CONT TestReadProxyNarinfo660=== CONT TestParseSize661--- PASS: TestParseSize (0.00s)662=== CONT TestIsValidCachePath663=== CONT TestService_Rustfstest664=== CONT TestProxyHeadersOnlyTrustedOnSocket665=== CONT TestPresignedUploadRegisteredBeforeCommit666=== CONT TestParseSingleRange667=== CONT TestCompletedNarNotReofferedAcrossClosures668=== CONT TestCreatePin_ReservedPins669=== CONT TestCompleteMultipartUpload_ErrorButObjectExists670=== CONT TestResurrectedObjectNotDeleted671=== CONT TestRedundantMultipartUpload672=== CONT TestOrphanedObjectsGCStressTest673=== CONT TestOrphanedObjectsGC674=== CONT TestPush_SignsNarinfosOfItsPendingObjects675=== CONT TestObjectStatsTrigger676=== CONT TestPush_RejectsBadRequests677=== RUN TestProxyWriteTimeout/1_GiB_nar678=== CONT TestMultipartCleanup6792026/09/29 08:16:26 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000680=== PAUSE TestProxyWriteTimeout/1_GiB_nar681=== RUN TestProxyWriteTimeout/10_GiB_nar682=== PAUSE TestProxyWriteTimeout/10_GiB_nar683=== RUN TestProxyWriteTimeout/unknown_size684=== RUN TestIsValidCachePath/narinfo685=== PAUSE TestIsValidCachePath/narinfo686=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars687=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars688=== RUN TestIsValidCachePath/nar_zst689=== PAUSE TestIsValidCachePath/nar_zst690=== RUN TestIsValidCachePath/nar_xz691=== PAUSE TestIsValidCachePath/nar_xz692=== RUN TestIsValidCachePath/nar_bz2693=== PAUSE TestProxyWriteTimeout/unknown_size694=== PAUSE TestIsValidCachePath/nar_bz2695=== RUN TestIsValidCachePath/nar_uncompressed696=== PAUSE TestIsValidCachePath/nar_uncompressed697=== RUN TestIsValidCachePath/ls698=== PAUSE TestIsValidCachePath/ls699=== RUN TestIsValidCachePath/log700=== PAUSE TestIsValidCachePath/log701=== RUN TestIsValidCachePath/realisation702=== PAUSE TestIsValidCachePath/realisation703=== RUN TestIsValidCachePath/nix-cache-info704=== PAUSE TestIsValidCachePath/nix-cache-info705=== RUN TestIsValidCachePath/index.html706=== PAUSE TestIsValidCachePath/index.html707=== RUN TestIsValidCachePath/traversal_parent708=== PAUSE TestIsValidCachePath/traversal_parent709=== RUN TestIsValidCachePath/traversal_in_middle710=== PAUSE TestIsValidCachePath/traversal_in_middle711=== RUN TestIsValidCachePath/invalid_char_e712=== PAUSE TestIsValidCachePath/invalid_char_e713=== RUN TestIsValidCachePath/invalid_char_u714=== PAUSE TestIsValidCachePath/invalid_char_u715=== RUN TestIsValidCachePath/random_path716=== PAUSE TestIsValidCachePath/random_path717=== RUN TestIsValidCachePath/empty718=== CONT TestPush_CommitFailsWhenSkippedKeyWasCollected719=== RUN TestParseSingleRange/none720=== PAUSE TestIsValidCachePath/empty721=== PAUSE TestParseSingleRange/none722=== RUN TestIsValidCachePath/leading_slash723=== RUN TestParseSingleRange/unknown_unit724=== PAUSE TestParseSingleRange/unknown_unit725=== RUN TestParseSingleRange/multi-range_ignored726=== PAUSE TestParseSingleRange/multi-range_ignored727=== RUN TestParseSingleRange/malformed_no_dash728=== PAUSE TestParseSingleRange/malformed_no_dash729=== RUN TestParseSingleRange/malformed_both_empty730=== PAUSE TestParseSingleRange/malformed_both_empty731=== RUN TestParseSingleRange/malformed_end_before_start732=== PAUSE TestIsValidCachePath/leading_slash733=== RUN TestIsValidCachePath/wrong_extension734=== PAUSE TestIsValidCachePath/wrong_extension735=== RUN TestIsValidCachePath/short_hash736=== PAUSE TestIsValidCachePath/short_hash737=== PAUSE TestParseSingleRange/malformed_end_before_start738=== RUN TestParseSingleRange/closed739=== PAUSE TestParseSingleRange/closed740=== RUN TestParseSingleRange/open-ended741=== CONT TestServerTLSConfig742=== RUN TestServerTLSConfig/no_client_CA743=== PAUSE TestParseSingleRange/open-ended744=== RUN TestParseSingleRange/end_clamped_to_size745=== PAUSE TestParseSingleRange/end_clamped_to_size746=== RUN TestParseSingleRange/suffix747=== PAUSE TestParseSingleRange/suffix748=== RUN TestParseSingleRange/suffix_exceeds_size749=== PAUSE TestServerTLSConfig/no_client_CA750=== PAUSE TestParseSingleRange/suffix_exceeds_size751=== RUN TestParseSingleRange/single_byte752=== RUN TestServerTLSConfig/missing_CA_file753=== PAUSE TestParseSingleRange/single_byte754=== PAUSE TestServerTLSConfig/missing_CA_file755=== RUN TestParseSingleRange/start_past_EOF756=== RUN TestServerTLSConfig/not_a_PEM_file757=== PAUSE TestParseSingleRange/start_past_EOF758=== RUN TestParseSingleRange/start_far_past_EOF759=== PAUSE TestParseSingleRange/start_far_past_EOF760=== PAUSE TestServerTLSConfig/not_a_PEM_file761=== CONT TestPush_CompleteCommitsEveryRoot762=== CONT TestService_NativeMTLS763--- PASS: TestSkippedUploadsHandler (0.00s)764=== CONT TestPush_OverlappingRootsStoreOneRowPerKey7652026-09-29 08:16:26.186 UTC [449] ERROR: relation "goose_db_version" does not exist at character 367662026-09-29 08:16:26.186 UTC [449] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7672026-09-29 08:16:26.259 UTC [450] ERROR: relation "goose_db_version" does not exist at character 367682026-09-29 08:16:26.259 UTC [450] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7692026-09-29 08:16:26.259 UTC [451] ERROR: relation "goose_db_version" does not exist at character 367702026-09-29 08:16:26.259 UTC [451] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7712026-09-29 08:16:26.261 UTC [452] ERROR: relation "goose_db_version" does not exist at character 367722026-09-29 08:16:26.261 UTC [452] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7732026-09-29 08:16:26.268 UTC [453] ERROR: relation "goose_db_version" does not exist at character 367742026-09-29 08:16:26.268 UTC [453] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7752026/09/29 08:16:26 OK 20241026095416_initial_model.sql (23.12ms)7762026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (5.49ms)7772026/09/29 08:16:26 OK 20251218171726_add_pins.sql (12.05ms)7782026-09-29 08:16:26.298 UTC [458] ERROR: relation "goose_db_version" does not exist at character 367792026-09-29 08:16:26.298 UTC [458] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7802026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (22.05ms)7812026/09/29 08:16:26 OK 20241026095416_initial_model.sql (47.39ms)7822026/09/29 08:16:26 OK 20260905000000_add_claims.sql (5.23ms)7832026/09/29 08:16:26 OK 20241026095416_initial_model.sql (47.21ms)7842026/09/29 08:16:26 OK 20241026095416_initial_model.sql (48.04ms)7852026-09-29 08:16:26.326 UTC [459] ERROR: relation "goose_db_version" does not exist at character 367862026-09-29 08:16:26.326 UTC [459] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7872026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.99ms)7882026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (4.35ms)7892026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (3.77ms)7902026-09-29 08:16:26.328 UTC [460] ERROR: relation "goose_db_version" does not exist at character 367912026-09-29 08:16:26.328 UTC [460] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7922026-09-29 08:16:26.328 UTC [462] ERROR: relation "goose_db_version" does not exist at character 367932026-09-29 08:16:26.328 UTC [462] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7942026-09-29 08:16:26.328 UTC [461] ERROR: relation "goose_db_version" does not exist at character 367952026-09-29 08:16:26.328 UTC [461] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC7962026/09/29 08:16:26 OK 20241026095416_initial_model.sql (43.71ms)7972026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (4.31ms)7982026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.48ms)7992026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200008002026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (3.19ms)8012026/09/29 08:16:26 OK 20251218171726_add_pins.sql (5.61ms)8022026-09-29 08:16:26.334 UTC [463] ERROR: relation "goose_db_version" does not exist at character 368032026-09-29 08:16:26.334 UTC [463] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8042026/09/29 08:16:26 OK 1_commit_pending_closure.sql (10.98ms)8052026/09/29 08:16:26 OK 20251218171726_add_pins.sql (13.85ms)8062026/09/29 08:16:26 OK 20251218171726_add_pins.sql (13.88ms)8072026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (10.23ms)8082026/09/29 08:16:26 OK 20251218171726_add_pins.sql (10.89ms)8092026/09/29 08:16:26 OK 20241026095416_initial_model.sql (19.05ms)8102026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.52ms)8112026/09/29 08:16:26 OK 3_commit_push.sql (1.52ms)8122026/09/29 08:16:26 goose: up to current file version: 38132026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)8142026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.99ms)8152026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.69ms)8162026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (5.45ms)8172026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (5.6ms)8182026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.86ms)8192026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.64ms)8202026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.82ms)8212026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.92ms)8222026-09-29 08:16:26.354 UTC [465] ERROR: relation "goose_db_version" does not exist at character 368232026-09-29 08:16:26.354 UTC [465] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8242026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.8ms)8252026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.81ms)8262026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200008272026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.26ms)8282026-09-29 08:16:26.355 UTC [464] ERROR: relation "goose_db_version" does not exist at character 368292026-09-29 08:16:26.355 UTC [464] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8302026/09/29 08:16:26 OK 20241026095416_initial_model.sql (11ms)8312026-09-29 08:16:26.356 UTC [466] ERROR: relation "goose_db_version" does not exist at character 368322026-09-29 08:16:26.356 UTC [466] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8332026-09-29 08:16:26.357 UTC [467] ERROR: relation "goose_db_version" does not exist at character 368342026-09-29 08:16:26.357 UTC [467] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8352026-09-29 08:16:26.357 UTC [470] ERROR: relation "goose_db_version" does not exist at character 368362026-09-29 08:16:26.357 UTC [470] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8372026-09-29 08:16:26.357 UTC [468] ERROR: relation "goose_db_version" does not exist at character 368382026-09-29 08:16:26.357 UTC [468] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8392026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.79ms)8402026-09-29 08:16:26.357 UTC [469] ERROR: relation "goose_db_version" does not exist at character 368412026-09-29 08:16:26.357 UTC [469] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8422026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.26ms)8432026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.21ms)8442026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200008452026-09-29 08:16:26.358 UTC [473] ERROR: relation "goose_db_version" does not exist at character 368462026-09-29 08:16:26.358 UTC [473] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8472026-09-29 08:16:26.358 UTC [471] ERROR: relation "goose_db_version" does not exist at character 368482026-09-29 08:16:26.358 UTC [471] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8492026/09/29 08:16:26 OK 1_commit_pending_closure.sql (4.22ms)8502026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (7.04ms)8512026-09-29 08:16:26.359 UTC [472] ERROR: relation "goose_db_version" does not exist at character 368522026-09-29 08:16:26.359 UTC [472] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8532026/09/29 08:16:26 OK 20241026095416_initial_model.sql (14.68ms)8542026/09/29 08:16:26 OK 20241026095416_initial_model.sql (14.76ms)8552026/09/29 08:16:26 OK 20241026095416_initial_model.sql (14.67ms)8562026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (3.18ms)8572026-09-29 08:16:26.360 UTC [474] ERROR: relation "goose_db_version" does not exist at character 368582026-09-29 08:16:26.360 UTC [474] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8592026-09-29 08:16:26.360 UTC [475] ERROR: relation "goose_db_version" does not exist at character 368602026-09-29 08:16:26.360 UTC [475] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC8612026/09/29 08:16:26 OK 20241026095416_initial_model.sql (15.65ms)8622026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.1ms)8632026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200008642026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.73ms)8652026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200008662026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.18ms)8672026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.85ms)8682026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.45ms)8692026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.06ms)8702026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.44ms)8712026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.6ms)8722026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (3.54ms)8732026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.63ms)8742026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.3ms)8752026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.71ms)8762026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.1ms)8772026/09/29 08:16:26 OK 3_commit_push.sql (2.02ms)8782026/09/29 08:16:26 goose: up to current file version: 38792026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.31ms)8802026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.18ms)8812026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.16ms)8822026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.77ms)8832026/09/29 08:16:26 OK 3_commit_push.sql (2.21ms)8842026/09/29 08:16:26 goose: up to current file version: 38852026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.18ms)8862026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.99ms)8872026/09/29 08:16:26 OK 3_commit_push.sql (2.22ms)8882026/09/29 08:16:26 goose: up to current file version: 38892026/09/29 08:16:26 OK 20251218171726_add_pins.sql (5.03ms)8902026/09/29 08:16:26 OK 3_commit_push.sql (1.54ms)8912026/09/29 08:16:26 goose: up to current file version: 38922026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.57ms)8932026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.21ms)8942026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200008952026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.99ms)8962026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (5.92ms)8972026/09/29 08:16:26 OK 1_commit_pending_closure.sql (4.02ms)8982026/09/29 08:16:26 OK 20241026095416_initial_model.sql (13.16ms)8992026/09/29 08:16:26 OK 20260905000000_add_claims.sql (5.15ms)9002026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (6.72ms)9012026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (6.03ms)9022026/09/29 08:16:26 OK 20241026095416_initial_model.sql (12.82ms)9032026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.67ms)9042026/09/29 08:16:26 OK 20241026095416_initial_model.sql (12.26ms)9052026/09/29 08:16:26 OK 20241026095416_initial_model.sql (12.35ms)9062026/09/29 08:16:26 OK 20241026095416_initial_model.sql (13.65ms)9072026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.51ms)9082026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.41ms)9092026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.59ms)9102026/09/29 08:16:26 OK 20241026095416_initial_model.sql (12.72ms)9112026/09/29 08:16:26 OK 20241026095416_initial_model.sql (12.65ms)9122026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.24ms)9132026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.76ms)9142026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.53ms)9152026/09/29 08:16:26 OK 20241026095416_initial_model.sql (14.78ms)9162026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.65ms)9172026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.33ms)9182026/09/29 08:16:26 OK 20241026095416_initial_model.sql (14.02ms)9192026/09/29 08:16:26 OK 3_commit_push.sql (2.29ms)9202026/09/29 08:16:26 goose: up to current file version: 39212026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.78ms)9222026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.75ms)9232026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.86ms)9242026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.32ms)9252026/09/29 08:16:26 OK 20241026095416_initial_model.sql (13.51ms)9262026/09/29 08:16:26 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42601/oidc9272026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.95ms)9282026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200009292026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (3.37ms)930--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.29s)931=== CONT TestMetricsInventory9322026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.6ms)9332026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.54ms)9342026/09/29 08:16:26 OK 20241026095416_initial_model.sql (16.04ms)9352026/09/29 08:16:26 OK 20251218171726_add_pins.sql (5.68ms)9362026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (4.12ms)9372026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.55ms)9382026/09/29 08:16:26 OK 20251218171726_add_pins.sql (5.6ms)9392026/09/29 08:16:26 OK 20241026095416_initial_model.sql (16.09ms)9402026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.52ms)9412026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200009422026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.58ms)9432026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.15ms)9442026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (4.35ms)9452026/09/29 08:16:26 OK 20251218171726_add_pins.sql (5.39ms)9462026/09/29 08:16:26 OK 20251218171726_add_pins.sql (5.21ms)9472026/09/29 08:16:26 OK 20251218171726_add_pins.sql (5.3ms)9482026/09/29 08:16:26 OK 20251218171726_add_pins.sql (5.19ms)9492026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.53ms)9502026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200009512026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.37ms)9522026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.9ms)9532026/09/29 08:16:26 OK 20251218171726_add_pins.sql (5.74ms)9542026/09/29 08:16:26 OK 20251218171726_add_pins.sql (5.08ms)9552026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.48ms)9562026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200009572026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.96ms)9582026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.14ms)9592026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.2ms)9602026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200009612026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.56ms)9622026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.86ms)9632026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.33ms)9642026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.75ms)9652026/09/29 08:16:26 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"966--- PASS: TestService_AuthMiddleware (0.29s)967=== CONT TestReadRedirectUsesPublicS3URL9682026/09/29 08:16:26 OK 3_commit_push.sql (2.07ms)9692026/09/29 08:16:26 goose: up to current file version: 39702026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.57ms)9712026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.73ms)9722026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.98ms)9732026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.74ms)9742026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.16ms)9752026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.71ms)9762026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.08ms)9772026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4ms)9782026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (5.37ms)9792026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.14ms)9802026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.86ms)9812026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.98ms)9822026/09/29 08:16:26 OK 3_commit_push.sql (1.9ms)9832026/09/29 08:16:26 goose: up to current file version: 39842026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.78ms)9852026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.47ms)9862026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.88ms)9872026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.04ms)9882026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.08ms)9892026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.14ms)9902026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.03ms)9912026/09/29 08:16:26 OK 3_commit_push.sql (1.45ms)9922026/09/29 08:16:26 goose: up to current file version: 39932026/09/29 08:16:26 OK 3_commit_push.sql (1.35ms)9942026/09/29 08:16:26 goose: up to current file version: 39952026/09/29 08:16:26 OK 3_commit_push.sql (2.02ms)9962026/09/29 08:16:26 goose: up to current file version: 39972026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.1ms)9982026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.54ms)9992026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.09ms)10002026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.02ms)10012026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.05ms)10022026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.66ms)10032026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.15ms)10042026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.99ms)10052026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.23ms)10062026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.64ms)10072026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.2ms)10082026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.47ms)10092026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.1ms)10102026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.62ms)10112026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3ms)10122026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.82ms)10132026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010142026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.37ms)10152026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.18ms)10162026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010172026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.83ms)10182026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.43ms)10192026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.48ms)10202026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.52ms)10212026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.28ms)10222026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010232026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.35ms)10242026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010252026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.03ms)10262026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.25ms)10272026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010282026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.27ms)10292026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.87ms)10302026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.98ms)10312026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.8ms)10322026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.3ms)10332026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010342026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.38ms)10352026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.71ms)10362026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.93ms)10372026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010382026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.5ms)10392026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010402026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.04ms)10412026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010422026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.73ms)10432026/09/29 08:16:26 OK 3_commit_push.sql (1.23ms)10442026/09/29 08:16:26 goose: up to current file version: 310452026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.19ms)10462026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.17ms)10472026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010482026/09/29 08:16:26 OK 1_commit_pending_closure.sql (1.92ms)10492026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.71ms)10502026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.07ms)10512026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010522026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (1.75ms)10532026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000010542026/09/29 08:16:26 OK 1_commit_pending_closure.sql (1.93ms)10552026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.24ms)10562026/09/29 08:16:26 OK 1_commit_pending_closure.sql (1.55ms)10572026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.12ms)10582026/09/29 08:16:26 OK 1_commit_pending_closure.sql (1.78ms)10592026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.12ms)10602026/09/29 08:16:26 OK 3_commit_push.sql (1.2ms)10612026/09/29 08:16:26 goose: up to current file version: 310622026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.85ms)10632026/09/29 08:16:26 OK 3_commit_push.sql (1.4ms)10642026/09/29 08:16:26 goose: up to current file version: 310652026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.45ms)10662026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.04ms)10672026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.52ms)10682026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.93ms)10692026/09/29 08:16:26 OK 3_commit_push.sql (1.99ms)10702026/09/29 08:16:26 goose: up to current file version: 310712026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.09ms)10722026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.55ms)10732026/09/29 08:16:26 OK 3_commit_push.sql (1.89ms)10742026/09/29 08:16:26 goose: up to current file version: 310752026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.44ms)1076--- PASS: TestService_Rustfstest (0.31s)10772026/09/29 08:16:26 OK 3_commit_push.sql (1.94ms)1078=== CONT TestNARDeduplicationMetadataUploadBug10792026/09/29 08:16:26 goose: up to current file version: 310802026/09/29 08:16:26 OK 3_commit_push.sql (2.08ms)10812026/09/29 08:16:26 goose: up to current file version: 310822026/09/29 08:16:26 OK 3_commit_push.sql (2.89ms)10832026/09/29 08:16:26 goose: up to current file version: 310842026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.1ms)10852026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.95ms)10862026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.79ms)10872026/09/29 08:16:26 OK 3_commit_push.sql (790.45µs)10882026/09/29 08:16:26 goose: up to current file version: 310892026/09/29 08:16:26 OK 3_commit_push.sql (2.13ms)10902026/09/29 08:16:26 goose: up to current file version: 310912026/09/29 08:16:26 OK 3_commit_push.sql (853.09µs)10922026/09/29 08:16:26 goose: up to current file version: 310932026/09/29 08:16:26 OK 3_commit_push.sql (724.57µs)10942026/09/29 08:16:26 goose: up to current file version: 31095--- PASS: TestReadProxyNarinfo (0.34s)1096=== CONT TestReadProxyRangeRequest1097--- PASS: TestReadProxy404 (0.35s)1098=== CONT TestCreatePendingClosureRejectsOversizedNAR10992026/09/29 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures1100--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1101=== CONT TestReadRedirectKeepsNarinfoProxied11022026/09/29 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures11032026/09/29 08:16:26 INFO Received push request method=POST path=/api/pushes11042026/09/29 08:16:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11052026/09/29 08:16:26 INFO Signed narinfos id=1 count=11106--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.40s)1107=== CONT TestCacheConfigHandlerMaxNarSize1108--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1109=== CONT TestReadRedirectNar11102026/09/29 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures11112026-09-29 08:16:26.500 UTC [490] ERROR: relation "goose_db_version" does not exist at character 3611122026-09-29 08:16:26.500 UTC [490] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11132026-09-29 08:16:26.501 UTC [491] ERROR: relation "goose_db_version" does not exist at character 3611142026-09-29 08:16:26.501 UTC [491] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11152026-09-29 08:16:26.501 UTC [492] ERROR: relation "goose_db_version" does not exist at character 3611162026-09-29 08:16:26.501 UTC [492] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11172026-09-29 08:16:26.509 UTC [495] ERROR: relation "goose_db_version" does not exist at character 3611182026-09-29 08:16:26.509 UTC [495] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11192026/09/29 08:16:26 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11202026/09/29 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures11212026/09/29 08:16:26 OK 20241026095416_initial_model.sql (11.9ms)1122--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.42s)1123=== CONT TestGenerateLandingPage11242026/09/29 08:16:26 OK 20241026095416_initial_model.sql (12.57ms)1125--- PASS: TestGenerateLandingPage (0.00s)1126=== CONT TestReadProxyDisabled11272026/09/29 08:16:26 OK 20241026095416_initial_model.sql (13.38ms)11282026/09/29 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures11292026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (10.1ms)11302026/09/29 08:16:26 OK 20241026095416_initial_model.sql (16.38ms)11312026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (10.09ms)11322026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (9.25ms)11332026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.15ms)11342026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.8ms)11352026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.63ms)11362026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.22ms)11372026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.75ms)11382026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.72ms)11392026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.94ms)11402026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.04ms)11412026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.45ms)11422026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.32ms)11432026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.92ms)11442026-09-29 08:16:26.545 UTC [498] ERROR: relation "goose_db_version" does not exist at character 3611452026-09-29 08:16:26.545 UTC [498] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11462026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.89ms)11472026-09-29 08:16:26.545 UTC [499] ERROR: relation "goose_db_version" does not exist at character 3611482026-09-29 08:16:26.545 UTC [499] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC11492026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.25ms)11502026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.85ms)11512026/09/29 08:16:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11522026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.12ms)11532026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.83ms)1154=== RUN TestPush_RejectsBadRequests/no_roots1155=== PAUSE TestPush_RejectsBadRequests/no_roots1156=== RUN TestPush_RejectsBadRequests/no_objects1157=== PAUSE TestPush_RejectsBadRequests/no_objects1158=== RUN TestPush_RejectsBadRequests/bad_root1159=== PAUSE TestPush_RejectsBadRequests/bad_root1160=== RUN TestPush_RejectsBadRequests/root_not_in_objects1161=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1162=== CONT TestService_readinessHandler11632026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.61ms)11642026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.37ms)11652026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000011662026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.58ms)11672026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000011682026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.44ms)11692026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000011702026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.59ms)11712026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000011722026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.26ms)11732026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.15ms)11742026/09/29 08:16:26 OK 1_commit_pending_closure.sql (3.03ms)11752026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.99ms)11762026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.28ms)11772026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.6ms)11782026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.43ms)11792026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.54ms)11802026/09/29 08:16:26 OK 3_commit_push.sql (1.56ms)11812026/09/29 08:16:26 goose: up to current file version: 311822026/09/29 08:16:26 OK 3_commit_push.sql (2.08ms)11832026/09/29 08:16:26 goose: up to current file version: 311842026/09/29 08:16:26 OK 3_commit_push.sql (2.03ms)11852026/09/29 08:16:26 goose: up to current file version: 311862026/09/29 08:16:26 OK 3_commit_push.sql (1.22ms)11872026/09/29 08:16:26 goose: up to current file version: 311882026/09/29 08:16:26 OK 20241026095416_initial_model.sql (9.77ms)11892026/09/29 08:16:26 OK 20241026095416_initial_model.sql (10.02ms)11902026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (1.43ms)11912026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (1.64ms)11922026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.54ms)11932026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.47ms)11942026/09/29 08:16:26 INFO Starting HTTP server address=127.0.0.1:4272711952026/09/29 08:16:26 INFO Starting HTTP server address=/build/TestProxyHeadersOnlyTrustedOnSocket2625875222/001/proxy.sock11962026/09/29 08:16:26 WARN mTLS auth: subject not in bound subjects subject="CN=someone"11972026/09/29 08:16:26 INFO Shutdown signal received, draining in-flight requests timeout=10s11982026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.87ms)1199--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.47s)1200=== CONT TestReadProxyRootRedirectsToIndexHTML12012026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.91ms)12022026-09-29 08:16:26.572 UTC [502] ERROR: relation "goose_db_version" does not exist at character 3612032026-09-29 08:16:26.572 UTC [502] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12042026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.74ms)12052026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.54ms)12062026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.46ms)12072026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.54ms)12082026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.23ms)12092026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000012102026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.07ms)12112026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000012122026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.26ms)12132026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.45ms)12142026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.62ms)12152026/09/29 08:16:26 OK 3_commit_push.sql (1.32ms)12162026/09/29 08:16:26 goose: up to current file version: 312172026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.46ms)12182026/09/29 08:16:26 OK 3_commit_push.sql (1.06ms)12192026/09/29 08:16:26 goose: up to current file version: 312202026/09/29 08:16:26 OK 20241026095416_initial_model.sql (10.23ms)12212026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.26ms)12222026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.7ms)12232026-09-29 08:16:26.596 UTC [505] ERROR: relation "goose_db_version" does not exist at character 3612242026-09-29 08:16:26.596 UTC [505] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12252026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.99ms)12262026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.31ms)12272026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.77ms)12282026/09/29 08:16:26 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12292026/09/29 08:16:26 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1230--- PASS: TestService_NativeMTLS (0.51s)1231=== CONT TestService_healthCheckHandler12322026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (9.38ms)12332026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000012342026/09/29 08:16:26 OK 20241026095416_initial_model.sql (13.7ms)12352026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.27ms)12362026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.28ms)12372026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.9ms)12382026/09/29 08:16:26 OK 3_commit_push.sql (1.28ms)12392026/09/29 08:16:26 goose: up to current file version: 312402026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.43ms)12412026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.48ms)12422026-09-29 08:16:26.626 UTC [508] ERROR: relation "goose_db_version" does not exist at character 3612432026-09-29 08:16:26.626 UTC [508] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12442026/09/29 08:16:26 INFO Received push request method=POST path=/api/pushes12452026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.86ms)12462026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3ms)12472026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.91ms)12482026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000012492026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.34ms)12502026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.85ms)12512026/09/29 08:16:26 OK 20241026095416_initial_model.sql (9.65ms)12522026/09/29 08:16:26 INFO Received cleanup request method=DELETE path=/api/pending_closures12532026/09/29 08:16:26 OK 3_commit_push.sql (1.43ms)12542026/09/29 08:16:26 goose: up to current file version: 312552026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (1.54ms)12562026-09-29 08:16:26.643 UTC [509] ERROR: relation "goose_db_version" does not exist at character 3612572026-09-29 08:16:26.643 UTC [509] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12582026/09/29 08:16:26 INFO Aborted multipart uploads count=112592026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.12ms)12602026/09/29 08:16:26 INFO Received complete push request method=POST path=/api/pushes/1/complete1261--- PASS: TestMultipartCleanup (0.55s)1262=== CONT TestReadProxyConditionalGet12632026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.44ms)12642026/09/29 08:16:26 INFO Received push request method=POST path=/api/pushes12652026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.56ms)12662026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.58ms)1267--- PASS: TestPush_CompleteCommitsEveryRoot (0.56s)1268=== CONT TestGracefulShutdownDrainsInflight12692026/09/29 08:16:26 INFO Starting HTTP server address=127.0.0.1:4229312702026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.16ms)12712026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000012722026/09/29 08:16:26 INFO Shutdown signal received, draining in-flight requests timeout=10s12732026/09/29 08:16:26 OK 20241026095416_initial_model.sql (10.8ms)12742026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.47ms)12752026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.47ms)12762026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)12772026/09/29 08:16:26 OK 3_commit_push.sql (1.33ms)12782026/09/29 08:16:26 goose: up to current file version: 312792026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.35ms)12802026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.13ms)12812026/09/29 08:16:26 INFO Received complete push request method=POST path=/api/pushes/1/complete12822026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.03ms)12832026/09/29 08:16:26 INFO Received push request method=POST path=/api/pushes12842026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.55ms)12852026/09/29 08:16:26 INFO Received push request method=POST path=/api/pushes12862026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.22ms)12872026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000012882026/09/29 08:16:26 OK 1_commit_pending_closure.sql (1.74ms)12892026/09/29 08:16:26 OK 2_object_stats_trigger.sql (865.85µs)12902026-09-29 08:16:26.681 UTC [515] ERROR: relation "goose_db_version" does not exist at character 3612912026-09-29 08:16:26.681 UTC [515] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC12922026/09/29 08:16:26 OK 3_commit_push.sql (1.15ms)12932026/09/29 08:16:26 goose: up to current file version: 312942026/09/29 08:16:26 INFO Received complete push request method=POST path=/api/pushes/2/complete12952026-09-29 08:16:26.684 UTC [514] ERROR: Push object missing: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.narinfo12962026-09-29 08:16:26.684 UTC [514] CONTEXT: PL/pgSQL function commit_push(bigint) line 37 at RAISE12972026-09-29 08:16:26.684 UTC [514] STATEMENT: -- name: CommitPush :exec1298 SELECT commit_push($1::bigint)1299 1300--- PASS: TestPush_CommitFailsWhenSkippedKeyWasCollected (0.59s)1301=== CONT TestReadProxyHead13022026/09/29 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures1303--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.59s)1304=== CONT TestGCTaskStore_Fail1305--- PASS: TestGCTaskStore_Fail (0.00s)1306=== CONT TestReadProxyInvalidPath13072026/09/29 08:16:26 OK 20241026095416_initial_model.sql (10.31ms)13082026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (1.79ms)13092026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.39ms)13102026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.81ms)13112026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.45ms)13122026/09/29 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures13132026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.64ms)13142026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.42ms)13152026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000013162026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.66ms)13172026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.43ms)13182026/09/29 08:16:26 OK 3_commit_push.sql (1.53ms)13192026/09/29 08:16:26 goose: up to current file version: 313202026-09-29 08:16:26.721 UTC [522] ERROR: relation "goose_db_version" does not exist at character 3613212026-09-29 08:16:26.721 UTC [522] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1322=== CONT TestGCTaskStore_PhaseUpdates1323--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1324=== CONT TestUploadHandlersRejectOversizedBody1325--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)13262026/09/29 08:16:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13272026/09/29 08:16:26 OK 20241026095416_initial_model.sql (8.94ms)13282026/09/29 08:16:26 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NmE4ODNjNjktZjQ0Yi00N2M1LTk3NjgtNDk2MTQwZjY4ZWY4LmRiYjk3NjE4LTM0OWEtNDhmZi1iMTQ1LWU2ZTA4OWI0MTEzNngxNzkwNjY5Nzg2NzE3MzI0NjQ313292026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (1.73ms)1330--- PASS: TestObjectStatsTrigger (0.65s)1331=== CONT TestGCTaskStore_CompletedAllowsNewTask1332--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1333=== CONT TestService_cleanupPendingClosuresHandler13342026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.69ms)13352026/09/29 08:16:26 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NmE4ODNjNjktZjQ0Yi00N2M1LTk3NjgtNDk2MTQwZjY4ZWY4LmRiYjk3NjE4LTM0OWEtNDhmZi1iMTQ1LWU2ZTA4OWI0MTEzNngxNzkwNjY5Nzg2NzE3MzI0NjQ3 parts=11336--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.65s)1337=== CONT TestGCTaskStore_GetReturnsLatest1338--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1339=== CONT TestCompleteMultipartUnregistered13402026-09-29 08:16:26.755 UTC [523] ERROR: relation "goose_db_version" does not exist at character 3613412026-09-29 08:16:26.755 UTC [523] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13422026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.78ms)13432026/09/29 08:16:26 OK 20260905000000_add_claims.sql (2.44ms)13442026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (1.68ms)13452026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (1.38ms)13462026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000013472026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.2ms)13482026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.4ms)13492026/09/29 08:16:26 OK 3_commit_push.sql (1.22ms)13502026/09/29 08:16:26 goose: up to current file version: 313512026-09-29 08:16:26.766 UTC [528] ERROR: relation "goose_db_version" does not exist at character 3613522026-09-29 08:16:26.766 UTC [528] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13532026/09/29 08:16:26 OK 20241026095416_initial_model.sql (9.69ms)13542026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (1.47ms)13552026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.85ms)1356--- PASS: TestReadProxyNarStreaming (0.68s)1357=== CONT TestGCTaskStore_GetEmpty1358--- PASS: TestGCTaskStore_GetEmpty (0.00s)1359=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT13602026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.07ms)13612026/09/29 08:16:26 OK 20241026095416_initial_model.sql (10.77ms)13622026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.64ms)13632026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (1.97ms)13642026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.71ms)13652026/09/29 08:16:26 OK 20251218171726_add_pins.sql (2.97ms)13662026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (1.66ms)13672026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200001368--- PASS: TestResurrectedObjectNotDeleted (0.69s)1369=== CONT TestGCTaskStore_ConflictDifferentParams1370--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1371=== CONT TestService_verifyS3Integrity13722026/09/29 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures13732026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.31ms)13742026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.69ms)13752026/09/29 08:16:26 OK 2_object_stats_trigger.sql (997.65µs)13762026/09/29 08:16:26 OK 3_commit_push.sql (1.26ms)13772026/09/29 08:16:26 goose: up to current file version: 313782026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.43ms)13792026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.09ms)13802026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.63ms)13812026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000013822026/09/29 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures13832026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.15ms)13842026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.48ms)13852026/09/29 08:16:26 OK 3_commit_push.sql (2.03ms)13862026/09/29 08:16:26 goose: up to current file version: 313872026-09-29 08:16:26.835 UTC [533] ERROR: relation "goose_db_version" does not exist at character 3613882026-09-29 08:16:26.835 UTC [533] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13892026-09-29 08:16:26.836 UTC [534] ERROR: relation "goose_db_version" does not exist at character 3613902026-09-29 08:16:26.836 UTC [534] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC13912026/09/29 08:16:26 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13922026/09/29 08:16:26 WARN Refused reserved pin name=worker-x86_64-linux13932026/09/29 08:16:26 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13942026/09/29 08:16:26 INFO Received create pin request method=POST path=/api/pins/my-app13952026/09/29 08:16:26 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1396--- PASS: TestCreatePin_ReservedPins (0.74s)1397=== CONT TestGCTaskStore_DeduplicateSameParams1398--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1399=== CONT TestUploadHandlersRejectInvalidKeys1400=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1401=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1402=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1403=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1404=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1405=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1406=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1407=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1408=== CONT TestGCTaskStore_StartNew1409--- PASS: TestGCTaskStore_StartNew (0.00s)1410=== CONT TestIsValidUploadKey1411=== RUN TestIsValidUploadKey/narinfo1412=== PAUSE TestIsValidUploadKey/narinfo1413=== RUN TestIsValidUploadKey/nar_zst1414=== PAUSE TestIsValidUploadKey/nar_zst1415=== RUN TestIsValidUploadKey/nar_xz1416=== PAUSE TestIsValidUploadKey/nar_xz1417=== RUN TestIsValidUploadKey/nar_plain1418=== PAUSE TestIsValidUploadKey/nar_plain1419=== RUN TestIsValidUploadKey/listing1420=== PAUSE TestIsValidUploadKey/listing1421=== RUN TestIsValidUploadKey/build_log1422=== PAUSE TestIsValidUploadKey/build_log1423=== RUN TestIsValidUploadKey/build_log_home-manager_file1424=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1425=== RUN TestIsValidUploadKey/build_log_plus_in_name1426=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1427=== RUN TestIsValidUploadKey/build_log_question_mark1428=== PAUSE TestIsValidUploadKey/build_log_question_mark1429=== RUN TestIsValidUploadKey/build_log_equals1430=== PAUSE TestIsValidUploadKey/build_log_equals1431=== RUN TestIsValidUploadKey/realisation1432=== PAUSE TestIsValidUploadKey/realisation1433=== RUN TestIsValidUploadKey/realisation_plus_in_output1434=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1435=== RUN TestIsValidUploadKey/nix-cache-info1436=== PAUSE TestIsValidUploadKey/nix-cache-info1437=== RUN TestIsValidUploadKey/index.html1438=== PAUSE TestIsValidUploadKey/index.html1439=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1440=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1441=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1442=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1443=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1444=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1445=== RUN TestIsValidUploadKey/traversal1446=== PAUSE TestIsValidUploadKey/traversal1447=== RUN TestIsValidUploadKey/traversal_nar1448=== PAUSE TestIsValidUploadKey/traversal_nar1449=== RUN TestIsValidUploadKey/absolute1450=== PAUSE TestIsValidUploadKey/absolute1451=== RUN TestIsValidUploadKey/empty_key1452=== PAUSE TestIsValidUploadKey/empty_key1453=== RUN TestIsValidUploadKey/unknown_type1454=== PAUSE TestIsValidUploadKey/unknown_type1455=== CONT TestGCMetrics14562026/09/29 08:16:26 OK 20241026095416_initial_model.sql (11.45ms)14572026/09/29 08:16:26 OK 20241026095416_initial_model.sql (11.99ms)14582026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (1.95ms)14592026-09-29 08:16:26.857 UTC [537] ERROR: relation "goose_db_version" does not exist at character 3614602026-09-29 08:16:26.857 UTC [537] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14612026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.35ms)14622026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.1ms)14632026/09/29 08:16:26 OK 20251218171726_add_pins.sql (2.77ms)14642026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.42ms)14652026-09-29 08:16:26.865 UTC [538] ERROR: relation "goose_db_version" does not exist at character 3614662026-09-29 08:16:26.865 UTC [538] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC14672026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (3.83ms)14682026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.43ms)14692026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.28ms)1470--- PASS: TestReadRedirectUsesPublicS3URL (0.48s)1471=== CONT TestGCBugBareHashReferences1472=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1473=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1474=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1475=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1476=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1477=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1478=== CONT TestClientIntegration14792026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.81ms)14802026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.55ms)14812026/09/29 08:16:26 OK 20241026095416_initial_model.sql (10.1ms)14822026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.41ms)14832026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000014842026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.3ms)14852026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000014862026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)14872026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.6ms)14882026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.8ms)14892026/09/29 08:16:26 OK 20251218171726_add_pins.sql (2.58ms)14902026/09/29 08:16:26 OK 2_object_stats_trigger.sql (991.99µs)14912026/09/29 08:16:26 OK 2_object_stats_trigger.sql (984.19µs)14922026/09/29 08:16:26 OK 3_commit_push.sql (742.11µs)14932026/09/29 08:16:26 goose: up to current file version: 314942026/09/29 08:16:26 OK 3_commit_push.sql (1.45ms)14952026/09/29 08:16:26 goose: up to current file version: 314962026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (2.68ms)14972026/09/29 08:16:26 OK 20241026095416_initial_model.sql (10.73ms)14982026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (1.8ms)14992026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.23ms)15002026/09/29 08:16:26 OK 20251218171726_add_pins.sql (3.54ms)15012026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.6ms)1502--- PASS: TestMetricsInventory (0.51s)1503=== CONT TestClientCADerivations15042026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (3.38ms)15052026/09/29 08:16:26 goose: successfully migrated database to version: 2026092312000015062026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.6ms)15072026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.47ms)15082026/09/29 08:16:26 OK 2_object_stats_trigger.sql (2.32ms)15092026/09/29 08:16:26 OK 20260905000000_add_claims.sql (3.94ms)15102026/09/29 08:16:26 OK 3_commit_push.sql (1.34ms)15112026/09/29 08:16:26 goose: up to current file version: 315122026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (2.96ms)15132026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.38ms)15142026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200001515=== NAME TestOrphanedObjectsGC1516 orphaned_objects_gc_test.go:290: GC Test Summary:1517 orphaned_objects_gc_test.go:291: - Kept: 2 objects from closure A1518 orphaned_objects_gc_test.go:292: - Deleted: 2 objects from closure B1519 orphaned_objects_gc_test.go:293: - Deleted: 6 orphaned chain objects (X1->X2->X3)1520 orphaned_objects_gc_test.go:294: - Deleted: 2 orphaned single objects (Y)1521 orphaned_objects_gc_test.go:295: - Total deleted: 10 objects1522--- PASS: TestOrphanedObjectsGC (0.80s)1523=== CONT TestService_createPendingClosureHandler15242026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.36ms)15252026/09/29 08:16:26 OK 2_object_stats_trigger.sql (1.6ms)15262026/09/29 08:16:26 OK 3_commit_push.sql (1.39ms)15272026/09/29 08:16:26 goose: up to current file version: 315282026-09-29 08:16:26.919 UTC [552] ERROR: relation "goose_db_version" does not exist at character 3615292026-09-29 08:16:26.919 UTC [552] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1530--- PASS: TestReadRedirectKeepsNarinfoProxied (0.49s)1531=== CONT TestCacheStatsHandler1532=== NAME TestNARDeduplicationMetadataUploadBug1533 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3377021641/001/store/gvag4vavz65bvdn559mnr1irkpqwmfia-file1.txt15342026/09/29 08:16:26 OK 20241026095416_initial_model.sql (12.83ms)15352026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.41ms)15362026/09/29 08:16:26 OK 20251218171726_add_pins.sql (4.14ms)1537--- PASS: TestReadProxyRangeRequest (0.52s)1538=== CONT TestClientErrorHandling1539=== RUN TestClientErrorHandling/InvalidStorePath1540=== PAUSE TestClientErrorHandling/InvalidStorePath1541=== RUN TestClientErrorHandling/InvalidAuthToken1542=== PAUSE TestClientErrorHandling/InvalidAuthToken1543=== RUN TestClientErrorHandling/ServerNotAvailable1544=== PAUSE TestClientErrorHandling/ServerNotAvailable1545=== CONT TestCacheConfigHandler1546=== RUN TestCacheConfigHandler/full_config,_no_issuer1547=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1548=== RUN TestCacheConfigHandler/no_cache_url_configured1549=== PAUSE TestCacheConfigHandler/no_cache_url_configured1550=== RUN TestCacheConfigHandler/no_signing_keys1551=== PAUSE TestCacheConfigHandler/no_signing_keys1552=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1553=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1554=== CONT TestClientPushesUseOnePush15552026-09-29 08:16:26.959 UTC [572] ERROR: relation "goose_db_version" does not exist at character 3615562026-09-29 08:16:26.959 UTC [572] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15572026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (4.71ms)15582026/09/29 08:16:26 OK 20260905000000_add_claims.sql (4.38ms)15592026-09-29 08:16:26.966 UTC [574] ERROR: relation "goose_db_version" does not exist at character 3615602026-09-29 08:16:26.966 UTC [574] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15612026/09/29 08:16:26 OK 20260920000000_drop_claims.sql (3.22ms)15622026/09/29 08:16:26 OK 20260923120000_add_pushes.sql (2.95ms)15632026/09/29 08:16:26 goose: successfully migrated database to version: 202609231200001564--- PASS: TestReadRedirectNar (0.48s)1565=== CONT TestService_ReadScope_PublicByDefault15662026/09/29 08:16:26 OK 1_commit_pending_closure.sql (2.93ms)15672026-09-29 08:16:26.975 UTC [576] ERROR: relation "goose_db_version" does not exist at character 3615682026-09-29 08:16:26.975 UTC [576] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15692026/09/29 08:16:26 OK 2_object_stats_trigger.sql (3.03ms)15702026/09/29 08:16:26 OK 20241026095416_initial_model.sql (12.85ms)15712026/09/29 08:16:26 OK 3_commit_push.sql (1.94ms)15722026/09/29 08:16:26 goose: up to current file version: 315732026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.4ms)1574--- PASS: TestReadProxyDisabled (0.47s)1575=== CONT TestLeadEndsOnShutdown15762026/09/29 08:16:26 OK 20251218171726_add_pins.sql (12.79ms)15772026/09/29 08:16:26 OK 20241026095416_initial_model.sql (22.09ms)15782026/09/29 08:16:26 OK 20241026095416_initial_model.sql (13.99ms)15792026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (2.51ms)15802026/09/29 08:16:26 OK 20260628120000_add_object_size_and_stats.sql (5.82ms)15812026/09/29 08:16:26 OK 20251210153512_drop_unused_gin_index.sql (3.87ms)15822026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.72ms)15832026/09/29 08:16:27 OK 20260905000000_add_claims.sql (3.84ms)15842026/09/29 08:16:27 OK 20251218171726_add_pins.sql (4.28ms)15852026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (4.08ms)15862026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.96ms)15872026-09-29 08:16:27.008 UTC [599] ERROR: relation "goose_db_version" does not exist at character 3615882026-09-29 08:16:27.008 UTC [599] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC15892026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (4.77ms)15902026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (3.66ms)15912026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000015922026/09/29 08:16:27 OK 20260905000000_add_claims.sql (4.31ms)15932026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.84ms)15942026/09/29 08:16:27 OK 20260905000000_add_claims.sql (4.19ms)15952026/09/29 08:16:27 WARN readiness check failed error="closed pool"1596--- PASS: TestService_readinessHandler (0.47s)1597=== CONT TestLeadElectsOneAndHandsOver15982026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (3.95ms)15992026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.76ms)16002026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (3.33ms)16012026/09/29 08:16:27 OK 3_commit_push.sql (1.67ms)16022026/09/29 08:16:27 goose: up to current file version: 316032026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (3.69ms)16042026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000016052026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (3.26ms)16062026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000016072026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.5ms)16082026-09-29 08:16:27.022 UTC [601] ERROR: relation "goose_db_version" does not exist at character 3616092026-09-29 08:16:27.022 UTC [601] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16102026/09/29 08:16:27 OK 1_commit_pending_closure.sql (3.1ms)16112026/09/29 08:16:27 OK 2_object_stats_trigger.sql (2.65ms)16122026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.46ms)16132026/09/29 08:16:27 OK 3_commit_push.sql (1.4ms)16142026/09/29 08:16:27 goose: up to current file version: 316152026/09/29 08:16:27 OK 3_commit_push.sql (1.35ms)16162026/09/29 08:16:27 goose: up to current file version: 316172026/09/29 08:16:27 OK 20241026095416_initial_model.sql (12.49ms)16182026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes16192026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)16202026/09/29 08:16:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16212026/09/29 08:16:27 INFO Uploading gvag4vavz65bvdn559mnr1irkpqwmfia-file1.txt (160B)16222026/09/29 08:16:27 OK 20251218171726_add_pins.sql (5.33ms)16232026-09-29 08:16:27.039 UTC [620] ERROR: relation "goose_db_version" does not exist at character 3616242026-09-29 08:16:27.039 UTC [620] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC16252026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"16262026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1627--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.47s)1628=== CONT TestService_RequireScope_OIDC16292026/09/29 08:16:27 WARN Failed to register uploaded object key=gvag4vavz65bvdn559mnr1irkpqwmfia.ls error="server returned 404: 404 page not found\n"16302026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (7.25ms)16312026/09/29 08:16:27 INFO Signed narinfos id=1 count=116322026/09/29 08:16:27 INFO Uploading 1 narinfos16332026/09/29 08:16:27 OK 20241026095416_initial_model.sql (14.76ms)16342026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)16352026/09/29 08:16:27 OK 20260905000000_add_claims.sql (3.75ms)16362026/09/29 08:16:27 INFO Received complete push request method=POST path=/api/pushes/1/complete16372026/09/29 08:16:27 WARN Failed to register uploaded object key=gvag4vavz65bvdn559mnr1irkpqwmfia.narinfo error="server returned 404: 404 page not found\n"16382026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.62ms)16392026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.97ms)16402026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (1.92ms)16412026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000016422026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.23ms)16432026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (4.24ms)16442026/09/29 08:16:27 INFO Upload complete. (69ms)16452026/09/29 08:16:27 OK 2_object_stats_trigger.sql (2ms)16462026/09/29 08:16:27 OK 20241026095416_initial_model.sql (10.69ms)16472026/09/29 08:16:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1648=== NAME TestNARDeduplicationMetadataUploadBug1649 metadata_upload_test.go:54: Retrieved narinfo from S3:1650 StorePath: /build/TestNARDeduplicationMetadataUploadBug3377021641/001/store/gvag4vavz65bvdn559mnr1irkpqwmfia-file1.txt1651 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1652 Compression: zstd1653 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1654 NarSize: 1601655 References: 1656 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf16572026-09-29 08:16:27.058 UTC [621] ERROR: relation "goose_db_version" does not exist at character 3616582026-09-29 08:16:27.058 UTC [621] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1659 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1660 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1661 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1662--- PASS: TestService_healthCheckHandler (0.45s)1663=== CONT TestPinProtectsFromGC16642026/09/29 08:16:27 OK 3_commit_push.sql (8.39ms)16652026/09/29 08:16:27 goose: up to current file version: 316662026/09/29 08:16:27 OK 20260905000000_add_claims.sql (10.97ms)16672026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (9.88ms)16682026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (3.02ms)16692026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.67ms)16702026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.79ms)16712026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000016722026/09/29 08:16:27 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NmE4ODNjNjktZjQ0Yi00N2M1LTk3NjgtNDk2MTQwZjY4ZWY4LjFmYTg0NDk5LWE4MmYtNDI5MC1iZGJiLTA5NTQxZWUyMjFjMngxNzkwNjY5Nzg2Njk5MDk2NTg5 parts=1216732026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (3.7ms)16742026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures16752026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.5ms)16762026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.63ms)16772026-09-29 08:16:27.077 UTC [638] ERROR: relation "goose_db_version" does not exist at character 3616782026-09-29 08:16:27.077 UTC [638] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1679--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.98s)1680=== CONT TestResolveDBConnectionString16812026/09/29 08:16:27 OK 3_commit_push.sql (1.58ms)16822026/09/29 08:16:27 goose: up to current file version: 316832026/09/29 08:16:27 OK 20260905000000_add_claims.sql (4.1ms)1684=== RUN TestResolveDBConnectionString/flag_wins1685=== PAUSE TestResolveDBConnectionString/flag_wins1686=== RUN TestResolveDBConnectionString/file_when_flag_empty1687=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1688=== RUN TestResolveDBConnectionString/missing_file_is_an_error1689=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1690=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1691=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1692=== RUN TestResolveDBConnectionString/nothing_configured1693=== PAUSE TestResolveDBConnectionString/nothing_configured1694=== CONT TestService_AuthMiddleware_OIDC16952026/09/29 08:16:27 OK 20241026095416_initial_model.sql (12.92ms)16962026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (4.4ms)16972026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (3.19ms)16982026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.04ms)16992026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000017002026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.24ms)17012026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.96ms)17022026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.48ms)17032026/09/29 08:16:27 OK 3_commit_push.sql (1.33ms)17042026/09/29 08:16:27 goose: up to current file version: 317052026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (4.15ms)1706--- PASS: TestReadProxyConditionalGet (0.44s)1707=== CONT TestClientSharedPathCommittedMidPush17082026/09/29 08:16:27 OK 20241026095416_initial_model.sql (10.69ms)1709=== NAME TestNARDeduplicationMetadataUploadBug1710 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3377021641/001/store/bywp59mwjavfp94vg5h5psar58c504a5-file2.txt17112026/09/29 08:16:27 OK 20260905000000_add_claims.sql (3.58ms)17122026-09-29 08:16:27.095 UTC [646] ERROR: relation "goose_db_version" does not exist at character 3617132026-09-29 08:16:27.095 UTC [646] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17142026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (2.74ms)17152026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.85ms)17162026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.28ms)17172026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000017182026/09/29 08:16:27 OK 20251218171726_add_pins.sql (2.87ms)17192026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.18ms)17202026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.41ms)17212026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (4.35ms)17222026/09/29 08:16:27 OK 3_commit_push.sql (1.19ms)17232026/09/29 08:16:27 goose: up to current file version: 317242026/09/29 08:16:27 OK 20260905000000_add_claims.sql (3.71ms)17252026/09/29 08:16:27 OK 20241026095416_initial_model.sql (9.14ms)17262026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (3.16ms)17272026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (1.89ms)1728--- PASS: TestReadProxyHead (0.43s)1729=== CONT TestClientFallsBackToClosures17302026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.19ms)17312026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000017322026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.31ms)17332026/09/29 08:16:27 OK 20251218171726_add_pins.sql (4.37ms)17342026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.34ms)17352026/09/29 08:16:27 OK 3_commit_push.sql (1.14ms)17362026/09/29 08:16:27 goose: up to current file version: 317372026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (3.62ms)17382026/09/29 08:16:27 OK 20260905000000_add_claims.sql (3.63ms)17392026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (3.22ms)1740--- PASS: TestReadProxyInvalidPath (0.44s)1741=== CONT TestService_ReadAuthMiddleware17422026/09/29 08:16:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44467/oidc17432026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.65ms)17442026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000017452026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.56ms)17462026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.53ms)17472026/09/29 08:16:27 OK 3_commit_push.sql (1.28ms)17482026/09/29 08:16:27 goose: up to current file version: 317492026-09-29 08:16:27.143 UTC [683] ERROR: relation "goose_db_version" does not exist at character 3617502026-09-29 08:16:27.143 UTC [683] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17512026/09/29 08:16:27 INFO Received cleanup request method=DELETE path=/api/pending_closures17522026/09/29 08:16:27 INFO Aborted multipart uploads count=017532026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures17542026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes17552026/09/29 08:16:27 OK 20241026095416_initial_model.sql (14.92ms)17562026/09/29 08:16:27 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17572026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (2.1ms)17582026/09/29 08:16:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17592026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17602026/09/29 08:16:27 INFO Signed narinfos id=2 count=117612026/09/29 08:16:27 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst17622026/09/29 08:16:27 INFO Uploading 1 narinfos17632026/09/29 08:16:27 WARN Failed to register uploaded object key=bywp59mwjavfp94vg5h5psar58c504a5.ls error="server returned 404: 404 page not found\n"1764--- PASS: TestCompleteMultipartUnregistered (0.42s)17652026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.71ms)1766=== CONT TestClientWithDependencies17672026/09/29 08:16:27 INFO Received cleanup request method=DELETE path=/api/pending_closures17682026/09/29 08:16:27 INFO Aborted multipart uploads count=117692026-09-29 08:16:27.174 UTC [701] ERROR: relation "goose_db_version" does not exist at character 3617702026-09-29 08:16:27.174 UTC [701] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC17712026/09/29 08:16:27 INFO Received complete push request method=POST path=/api/pushes/2/complete17722026/09/29 08:16:27 WARN Failed to register uploaded object key=bywp59mwjavfp94vg5h5psar58c504a5.narinfo error="server returned 404: 404 page not found\n"17732026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (4.18ms)17742026/09/29 08:16:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17752026-09-29 08:16:27.177 UTC [534] ERROR: Closure does not exist: id=117762026-09-29 08:16:27.177 UTC [534] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 16 at RAISE17772026-09-29 08:16:27.177 UTC [534] STATEMENT: -- name: CommitPendingClosure :exec1778 SELECT commit_pending_closure($1::bigint)1779 1780--- PASS: TestService_cleanupPendingClosuresHandler (0.43s)1781=== CONT TestClientMultipleUploads17822026/09/29 08:16:27 INFO Upload complete. (49ms)17832026/09/29 08:16:27 OK 20260905000000_add_claims.sql (3.57ms)1784=== NAME TestNARDeduplicationMetadataUploadBug1785 metadata_upload_test.go:76: Retrieved narinfo from S3:1786 StorePath: /build/TestNARDeduplicationMetadataUploadBug3377021641/001/store/bywp59mwjavfp94vg5h5psar58c504a5-file2.txt1787 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1788 Compression: zstd1789 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1790 NarSize: 1601791 References: 1792 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1793 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1794 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1795 {"version":1,"root":{"type":"regular","size":44}}17962026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.83ms)17972026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.86ms)17982026/09/29 08:16:27 goose: successfully migrated database to version: 202609231200001799--- PASS: TestNARDeduplicationMetadataUploadBug (0.78s)1800=== CONT TestService_AuthMiddleware_MTLSProxyHeader18012026/09/29 08:16:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete18022026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.44ms)18032026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures18042026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.57ms)18052026/09/29 08:16:27 OK 3_commit_push.sql (1.89ms)18062026/09/29 08:16:27 goose: up to current file version: 318072026/09/29 08:16:27 OK 20241026095416_initial_model.sql (11.81ms)18082026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (2.14ms)18092026-09-29 08:16:27.197 UTC [708] ERROR: relation "goose_db_version" does not exist at character 3618102026-09-29 08:16:27.197 UTC [708] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC18112026/09/29 08:16:27 OK 20251218171726_add_pins.sql (4.15ms)1812--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.42s)1813=== CONT TestService_AuthMiddleware_MTLSBoundSubjects18142026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (4.06ms)18152026/09/29 08:16:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38023/oidc18162026/09/29 08:16:27 OK 20260905000000_add_claims.sql (3.52ms)18172026/09/29 08:16:27 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NmE4ODNjNjktZjQ0Yi00N2M1LTk3NjgtNDk2MTQwZjY4ZWY4LjFlZTEzNWU0LWZhNWQtNGIxOS05Mjk5LTg5YTIwMzYyZTZiZngxNzkwNjY5Nzg2Nzk5MjEyODcz parts=121818--- PASS: TestRedundantMultipartUpload (1.11s)1819=== CONT TestProxyWriteTimeout/narinfo1820=== CONT TestProxyWriteTimeout/1_GiB_nar1821=== CONT TestProxyWriteTimeout/unknown_size1822=== CONT TestProxyWriteTimeout/10_GiB_nar1823--- PASS: TestProxyWriteTimeout (0.00s)1824 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1825 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1826 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1827 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1828=== CONT TestIsValidCachePath/narinfo1829=== CONT TestIsValidCachePath/short_hash1830=== CONT TestIsValidCachePath/wrong_extension1831=== CONT TestIsValidCachePath/leading_slash1832=== CONT TestIsValidCachePath/realisation1833=== CONT TestIsValidCachePath/log1834=== CONT TestIsValidCachePath/ls1835=== CONT TestIsValidCachePath/nar_uncompressed1836=== CONT TestIsValidCachePath/nar_bz21837=== CONT TestIsValidCachePath/nar_xz1838=== CONT TestIsValidCachePath/nar_zst1839=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1840=== CONT TestIsValidCachePath/invalid_char_e1841=== CONT TestIsValidCachePath/empty1842=== CONT TestIsValidCachePath/random_path1843=== CONT TestIsValidCachePath/invalid_char_u1844=== CONT TestIsValidCachePath/traversal_parent1845=== CONT TestIsValidCachePath/traversal_in_middle1846=== CONT TestIsValidCachePath/index.html1847=== CONT TestIsValidCachePath/nix-cache-info1848--- PASS: TestIsValidCachePath (0.00s)1849 --- PASS: TestIsValidCachePath/narinfo (0.00s)1850 --- PASS: TestIsValidCachePath/short_hash (0.00s)1851 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1852 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1853 --- PASS: TestIsValidCachePath/realisation (0.00s)1854 --- PASS: TestIsValidCachePath/log (0.00s)1855 --- PASS: TestIsValidCachePath/ls (0.00s)1856 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1857 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1858 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1859 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1860 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1861 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1862 --- PASS: TestIsValidCachePath/empty (0.00s)1863 --- PASS: TestIsValidCachePath/random_path (0.00s)1864 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1865 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1866 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1867 --- PASS: TestIsValidCachePath/index.html (0.00s)1868 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1869=== CONT TestParseSingleRange/none1870=== CONT TestParseSingleRange/end_clamped_to_size1871=== CONT TestParseSingleRange/start_far_past_EOF18722026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.68ms)1873=== CONT TestParseSingleRange/start_past_EOF1874=== CONT TestParseSingleRange/suffix1875=== CONT TestParseSingleRange/malformed_both_empty1876=== CONT TestParseSingleRange/suffix_exceeds_size1877=== CONT TestParseSingleRange/open-ended1878=== CONT TestParseSingleRange/single_byte1879=== CONT TestParseSingleRange/closed1880=== CONT TestParseSingleRange/malformed_end_before_start1881=== CONT TestParseSingleRange/multi-range_ignored1882=== CONT TestParseSingleRange/malformed_no_dash1883=== CONT TestServerTLSConfig/no_client_CA1884=== CONT TestServerTLSConfig/not_a_PEM_file18852026-09-29 08:16:27.210 UTC [710] ERROR: relation "goose_db_version" does not exist at character 3618862026-09-29 08:16:27.210 UTC [710] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC1887=== CONT TestServerTLSConfig/missing_CA_file1888--- PASS: TestServerTLSConfig (0.00s)1889 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1890 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1891 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1892=== CONT TestParseSingleRange/unknown_unit1893--- PASS: TestParseSingleRange (0.00s)1894 --- PASS: TestParseSingleRange/none (0.00s)1895 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1896 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1897 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1898 --- PASS: TestParseSingleRange/suffix (0.00s)1899 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1900 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1901 --- PASS: TestParseSingleRange/open-ended (0.00s)1902 --- PASS: TestParseSingleRange/single_byte (0.00s)1903 --- PASS: TestParseSingleRange/closed (0.00s)1904 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1905 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1906 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1907 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1908=== CONT TestPush_RejectsBadRequests/no_roots19092026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes1910=== CONT TestPush_RejectsBadRequests/bad_root19112026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes1912=== CONT TestPush_RejectsBadRequests/root_not_in_objects19132026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes1914=== CONT TestPush_RejectsBadRequests/no_objects19152026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes1916=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19172026/09/29 08:16:27 INFO Received uploads request method=POST path=/1918--- PASS: TestPush_RejectsBadRequests (0.45s)1919 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1920 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1921 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1922 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1923=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19242026/09/29 08:16:27 INFO Received request for more parts method=POST path=/1925=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19262026/09/29 08:16:27 INFO Received complete multipart upload request method=POST path=/1927=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19282026/09/29 08:16:27 INFO Received uploads request method=POST path=/1929--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1930 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1931 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1932 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1933 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1934=== CONT TestIsValidUploadKey/narinfo19352026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.28ms)1936=== CONT TestIsValidUploadKey/realisation_plus_in_output19372026/09/29 08:16:27 goose: successfully migrated database to version: 202609231200001938=== CONT TestIsValidUploadKey/unknown_type1939=== CONT TestIsValidUploadKey/empty_key1940=== CONT TestIsValidUploadKey/absolute1941=== CONT TestIsValidUploadKey/traversal_nar1942=== CONT TestIsValidUploadKey/traversal1943=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1944=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1945=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1946=== CONT TestIsValidUploadKey/index.html1947=== CONT TestIsValidUploadKey/nix-cache-info1948=== CONT TestIsValidUploadKey/nar_plain19492026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures1950=== CONT TestIsValidUploadKey/build_log1951=== CONT TestIsValidUploadKey/listing1952=== CONT TestIsValidUploadKey/build_log_home-manager_file1953=== CONT TestIsValidUploadKey/build_log_equals1954=== CONT TestIsValidUploadKey/build_log_question_mark1955=== CONT TestIsValidUploadKey/realisation1956=== CONT TestIsValidUploadKey/build_log_plus_in_name1957=== CONT TestIsValidUploadKey/nar_xz1958=== CONT TestIsValidUploadKey/nar_zst1959--- PASS: TestIsValidUploadKey (0.00s)1960 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1961 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1962 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1963 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1964 --- PASS: TestIsValidUploadKey/absolute (0.00s)1965 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1966 --- PASS: TestIsValidUploadKey/traversal (0.00s)1967 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1968 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1969 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1970 --- PASS: TestIsValidUploadKey/index.html (0.00s)1971 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1972 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1973 --- PASS: TestIsValidUploadKey/build_log (0.00s)1974 --- PASS: TestIsValidUploadKey/listing (0.00s)1975 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1976 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1977 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1978 --- PASS: TestIsValidUploadKey/realisation (0.00s)1979 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1980 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1981 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1982=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19832026/09/29 08:16:27 INFO Received uploads request method=POST path=/19842026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.29ms)19852026/09/29 08:16:27 OK 20241026095416_initial_model.sql (10.48ms)19862026/09/29 08:16:27 OK 2_object_stats_trigger.sql (863.13µs)19872026/09/29 08:16:27 OK 3_commit_push.sql (1.85ms)19882026/09/29 08:16:27 goose: up to current file version: 319892026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (2.52ms)19902026-09-29 08:16:27.220 UTC [714] ERROR: relation "goose_db_version" does not exist at character 3619912026-09-29 08:16:27.220 UTC [714] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC19922026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.53ms)19932026/09/29 08:16:27 OK 20241026095416_initial_model.sql (15.17ms)19942026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (11.17ms)19952026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (2.68ms)19962026/09/29 08:16:27 OK 20260905000000_add_claims.sql (3.94ms)19972026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.39ms)19982026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (3.71ms)19992026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.7ms)20002026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000020012026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (4.43ms)20022026/09/29 08:16:27 INFO Aborted multipart uploads count=020032026/09/29 08:16:27 OK 20241026095416_initial_model.sql (12.09ms)20042026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.62ms)20052026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (2.07ms)20062026/09/29 08:16:27 WARN Force mode enabled - objects will be deleted immediately without grace period20072026/09/29 08:16:27 OK 20260905000000_add_claims.sql (4.48ms)20082026/09/29 08:16:27 OK 2_object_stats_trigger.sql (2.46ms)20092026/09/29 08:16:27 OK 3_commit_push.sql (1.83ms)20102026/09/29 08:16:27 goose: up to current file version: 320112026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.63ms)20122026/09/29 08:16:27 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=020132026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (3.95ms)20142026/09/29 08:16:27 INFO Vacuumed table table=pending_closures20152026/09/29 08:16:27 INFO Vacuumed table table=pending_objects20162026/09/29 08:16:27 INFO Vacuumed table table=multipart_uploads20172026/09/29 08:16:27 INFO Vacuumed table table=closures20182026/09/29 08:16:27 INFO Vacuumed table table=objects20192026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.24ms)20202026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000020212026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (4.31ms)20222026-09-29 08:16:27.255 UTC [716] ERROR: relation "goose_db_version" does not exist at character 3620232026-09-29 08:16:27.255 UTC [716] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20242026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.43ms)2025--- PASS: TestGCMetrics (0.42s)2026=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts20272026/09/29 08:16:27 INFO Received request for more parts method=POST path=/20282026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.74ms)20292026/09/29 08:16:27 OK 3_commit_push.sql (1.3ms)20302026/09/29 08:16:27 goose: up to current file version: 320312026/09/29 08:16:27 OK 20260905000000_add_claims.sql (4.73ms)20322026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.45ms)20332026-09-29 08:16:27.263 UTC [717] ERROR: relation "goose_db_version" does not exist at character 3620342026-09-29 08:16:27.263 UTC [717] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20352026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2ms)20362026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000020372026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.39ms)20382026/09/29 08:16:27 OK 2_object_stats_trigger.sql (3.16ms)20392026-09-29 08:16:27.270 UTC [718] ERROR: relation "goose_db_version" does not exist at character 3620402026-09-29 08:16:27.270 UTC [718] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20412026/09/29 08:16:27 OK 20241026095416_initial_model.sql (9.8ms)20422026/09/29 08:16:27 OK 3_commit_push.sql (1.8ms)20432026/09/29 08:16:27 goose: up to current file version: 320442026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (2.27ms)20452026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.58ms)20462026/09/29 08:16:27 OK 20241026095416_initial_model.sql (9.73ms)20472026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (3.22ms)20482026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (1.85ms)20492026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.3ms)20502026/09/29 08:16:27 OK 20260905000000_add_claims.sql (4.69ms)20512026/09/29 08:16:27 OK 20241026095416_initial_model.sql (9.07ms)20522026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (1.37ms)20532026-09-29 08:16:27.287 UTC [719] ERROR: relation "goose_db_version" does not exist at character 3620542026-09-29 08:16:27.287 UTC [719] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20552026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.31ms)20562026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (3.04ms)20572026-09-29 08:16:27.289 UTC [720] ERROR: relation "goose_db_version" does not exist at character 3620582026-09-29 08:16:27.289 UTC [720] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC20592026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.18ms)20602026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000020612026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.39ms)20622026/09/29 08:16:27 OK 1_commit_pending_closure.sql (1.87ms)20632026/09/29 08:16:27 OK 20260905000000_add_claims.sql (3.78ms)20642026/09/29 08:16:27 OK 2_object_stats_trigger.sql (932.19µs)20652026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (3.46ms)20662026/09/29 08:16:27 OK 3_commit_push.sql (959.41µs)20672026/09/29 08:16:27 goose: up to current file version: 320682026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.37ms)20692026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (1.85ms)20702026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000020712026/09/29 08:16:27 OK 20260905000000_add_claims.sql (2.82ms)2072=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart20732026/09/29 08:16:27 INFO Received complete multipart upload request method=POST path=/20742026/09/29 08:16:27 OK 1_commit_pending_closure.sql (10.15ms)20752026/09/29 08:16:27 OK 20241026095416_initial_model.sql (14.13ms)20762026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (9.93ms)20772026/09/29 08:16:27 OK 20241026095416_initial_model.sql (12.36ms)20782026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.07ms)20792026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (1.61ms)20802026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (1.67ms)20812026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (1.79ms)20822026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000020832026/09/29 08:16:27 OK 3_commit_push.sql (900.15µs)20842026/09/29 08:16:27 goose: up to current file version: 320852026/09/29 08:16:27 OK 1_commit_pending_closure.sql (1.82ms)20862026/09/29 08:16:27 OK 20251218171726_add_pins.sql (2.96ms)20872026/09/29 08:16:27 OK 2_object_stats_trigger.sql (964.07µs)20882026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.02ms)20892026/09/29 08:16:27 OK 3_commit_push.sql (588.27µs)20902026/09/29 08:16:27 goose: up to current file version: 320912026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (3.34ms)20922026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (3.76ms)20932026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures20942026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures20952026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures20962026/09/29 08:16:27 OK 20260905000000_add_claims.sql (2.67ms)20972026/09/29 08:16:27 OK 20260905000000_add_claims.sql (3.36ms)20982026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.88ms)20992026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.29ms)21002026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (1.63ms)21012026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000021022026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.01ms)21032026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000021042026/09/29 08:16:27 OK 1_commit_pending_closure.sql (1.62ms)21052026/09/29 08:16:27 OK 1_commit_pending_closure.sql (1.81ms)21062026/09/29 08:16:27 OK 2_object_stats_trigger.sql (992.03µs)21072026/09/29 08:16:27 OK 2_object_stats_trigger.sql (795.63µs)21082026/09/29 08:16:27 OK 3_commit_push.sql (837.61µs)21092026/09/29 08:16:27 goose: up to current file version: 321102026/09/29 08:16:27 OK 3_commit_push.sql (599.41µs)21112026/09/29 08:16:27 goose: up to current file version: 32112=== CONT TestClientErrorHandling/InvalidStorePath2113=== NAME TestClientIntegration2114 client_integration_test.go:286: Created store path: /build/TestClientIntegration4128416161/002/store/qjjkb77nwmxdpag8ghyj59kcfhaj2axg-test-file.txt2115--- PASS: TestCacheStatsHandler (0.41s)2116=== CONT TestClientErrorHandling/ServerNotAvailable2117=== NAME TestClientCADerivations2118 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations434554092/001/store/qn1jwq920q0f5mkwjw4xln30g8s4jibc-ca-test2119--- PASS: TestService_ReadScope_PublicByDefault (0.41s)2120=== CONT TestClientErrorHandling/InvalidAuthToken21212026/09/29 08:16:27 INFO lead: acquired remote=192.0.2.1:123421222026/09/29 08:16:27 INFO lead: released remote=192.0.2.1:12342123--- PASS: TestLeadEndsOnShutdown (0.41s)2124=== CONT TestCacheConfigHandler/full_config,_no_issuer2125=== CONT TestCacheConfigHandler/no_signing_keys2126=== CONT TestCacheConfigHandler/no_cache_url_configured2127=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2128--- PASS: TestCacheConfigHandler (0.00s)2129 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2130 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2131 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2132 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2133=== CONT TestResolveDBConnectionString/flag_wins2134=== CONT TestResolveDBConnectionString/nothing_configured2135=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2136=== CONT TestResolveDBConnectionString/missing_file_is_an_error2137=== CONT TestResolveDBConnectionString/file_when_flag_empty2138--- PASS: TestResolveDBConnectionString (0.00s)2139 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2140 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2141 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2142 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2143 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)2144=== NAME TestClientCADerivations2145 client_ca_test.go:139: Found 1 dependencies (including self)21462026/09/29 08:16:27 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/present21472026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes21482026-09-29 08:16:27.416 UTC [884] ERROR: relation "goose_db_version" does not exist at character 3621492026-09-29 08:16:27.416 UTC [884] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21502026/09/29 08:16:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)21512026/09/29 08:16:27 INFO Uploading qjjkb77nwmxdpag8ghyj59kcfhaj2axg-test-file.txt (152B)21522026/09/29 08:16:27 INFO lead: acquired remote=192.0.2.1:123421532026/09/29 08:16:27 WARN Failed to register uploaded object key=qjjkb77nwmxdpag8ghyj59kcfhaj2axg.ls error="server returned 404: 404 page not found\n"21542026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign21552026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"21562026/09/29 08:16:27 INFO Signed narinfos id=1 count=121572026/09/29 08:16:27 INFO Uploading 1 narinfos21582026/09/29 08:16:27 INFO Received complete push request method=POST path=/api/pushes/1/complete21592026/09/29 08:16:27 WARN Failed to register uploaded object key=qjjkb77nwmxdpag8ghyj59kcfhaj2axg.narinfo error="server returned 404: 404 page not found\n"21602026/09/29 08:16:27 OK 20241026095416_initial_model.sql (9.07ms)21612026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (1.59ms)21622026/09/29 08:16:27 INFO Upload complete. (56ms)21632026/09/29 08:16:27 OK 20251218171726_add_pins.sql (3.33ms)21642026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (34.33ms)21652026/09/29 08:16:27 OK 20260905000000_add_claims.sql (5.35ms)21662026/09/29 08:16:27 INFO All 1 paths already cached2167=== NAME TestClientIntegration2168 client_integration_test.go:312: Retrieved narinfo from S3:2169 StorePath: /build/TestClientIntegration4128416161/002/store/qjjkb77nwmxdpag8ghyj59kcfhaj2axg-test-file.txt2170 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2171 Compression: zstd2172 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12173 NarSize: 1522174 References: 2175 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk121762026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (2.46ms)21772026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (2.14ms)21782026/09/29 08:16:27 goose: successfully migrated database to version: 202609231200002179 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2180 client_integration_test.go:313: Decompressed .ls content (64 bytes):2181 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2182 client_integration_test.go:316: Testing garbage collection...2183--- PASS: TestGCBugBareHashReferences (0.61s)21842026/09/29 08:16:27 OK 1_commit_pending_closure.sql (2.32ms)21852026-09-29 08:16:27.483 UTC [973] ERROR: relation "goose_db_version" does not exist at character 3621862026-09-29 08:16:27.483 UTC [973] STATEMENT: SELECT version_id, is_applied from goose_db_version ORDER BY id DESC21872026/09/29 08:16:27 OK 2_object_stats_trigger.sql (1.13ms)21882026/09/29 08:16:27 OK 3_commit_push.sql (752.35µs)21892026/09/29 08:16:27 goose: up to current file version: 321902026/09/29 08:16:27 OK 20241026095416_initial_model.sql (9.48ms)21912026/09/29 08:16:27 OK 20251210153512_drop_unused_gin_index.sql (1.34ms)21922026/09/29 08:16:27 OK 20251218171726_add_pins.sql (2.59ms)21932026/09/29 08:16:27 OK 20260628120000_add_object_size_and_stats.sql (2.63ms)21942026/09/29 08:16:27 OK 20260905000000_add_claims.sql (2.74ms)21952026/09/29 08:16:27 OK 20260920000000_drop_claims.sql (1.97ms)21962026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes21972026/09/29 08:16:27 OK 20260923120000_add_pushes.sql (1.78ms)21982026/09/29 08:16:27 goose: successfully migrated database to version: 2026092312000021992026/09/29 08:16:27 INFO Starting cleanup of old closures method=DELETE path=/api/closures22002026/09/29 08:16:27 INFO Garbage collection started22012026/09/29 08:16:27 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=182.846297ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present22022026/09/29 08:16:27 OK 1_commit_pending_closure.sql (1.88ms)22032026/09/29 08:16:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)22042026/09/29 08:16:27 INFO Uploading qn1jwq920q0f5mkwjw4xln30g8s4jibc-ca-test (144B)22052026/09/29 08:16:27 OK 2_object_stats_trigger.sql (946.67µs)22062026/09/29 08:16:27 OK 3_commit_push.sql (661.93µs)22072026/09/29 08:16:27 goose: up to current file version: 322082026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"22092026/09/29 08:16:27 WARN Failed to register uploaded object key=qn1jwq920q0f5mkwjw4xln30g8s4jibc.ls error="server returned 404: 404 page not found\n"22102026/09/29 08:16:27 WARN Failed to register uploaded object key=log/jaqldsga6z7q487j48mavisj9dgmw9bh-ca-test.drv error="server returned 404: 404 page not found\n"22112026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22122026/09/29 08:16:27 INFO Aborted multipart uploads count=022132026/09/29 08:16:27 INFO Signed narinfos id=1 count=122142026/09/29 08:16:27 INFO Uploading 1 narinfos22152026/09/29 08:16:27 WARN Force mode enabled - objects will be deleted immediately without grace period22162026/09/29 08:16:27 INFO Received complete push request method=POST path=/api/pushes/1/complete22172026/09/29 08:16:27 WARN Failed to register uploaded object key=qn1jwq920q0f5mkwjw4xln30g8s4jibc.narinfo error="server returned 404: 404 page not found\n"22182026/09/29 08:16:27 INFO Upload complete. (96ms)2219=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2220=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2221=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2222=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2223=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2224=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2225=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2226=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2227=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2228=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2229=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected2230=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected22312026/09/29 08:16:27 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]2232=== NAME TestClientCADerivations2233 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations434554092/001/store/qn1jwq920q0f5mkwjw4xln30g8s4jibc-ca-test2234 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2235 Compression: zstd2236 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n22372026/09/29 08:16:27 WARN Authentication failed token_preview=eyJhbGciOi...uBc5ase_Rw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2238 NarSize: 1442239 References: 2240 Deriver: /build/TestClientCADerivations434554092/001/store/jaqldsga6z7q487j48mavisj9dgmw9bh-ca-test.drv2241 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2242 client_ca_test.go:185: Checking for realisation files in S3...2243--- PASS: TestService_AuthMiddleware_OIDC (0.46s)2244 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2245 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2246 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2247 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2248=== NAME TestClientCADerivations2249 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2250 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2251=== NAME TestPinProtectsFromGC2252 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC1249811932/001/store/ryb8da79kbmcgblcnnlryxxgfl031p1h-pinned-file.txt2253 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC1249811932/001/store/n3hmrxm8kdakr5i6mvkwkh25fzkqwqj4-unpinned-file.txt22542026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes2255--- PASS: TestService_ReadAuthMiddleware (0.42s)22562026/09/29 08:16:27 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)22572026/09/29 08:16:27 INFO Uploading 2p5dwh0j348yd74a1cmidhd3c9qn9k7l-shared-dep (136B)22582026/09/29 08:16:27 INFO Uploading fr2r7z40w6qvjkqm4dv1x9h39plz025z-b (216B)22592026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"22602026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/16zmad8kjd0105jiqgsf3m4j56vp5z24yslpqg9rsrs490rfmzkj.nar.zst error="server returned 404: 404 page not found\n"22612026/09/29 08:16:27 WARN Failed to register uploaded object key=dvqlky9gf7nwsa122a4gqcfbxfmihvjg.ls error="server returned 404: 404 page not found\n"22622026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign22632026/09/29 08:16:27 WARN Failed to register uploaded object key=fr2r7z40w6qvjkqm4dv1x9h39plz025z.ls error="server returned 404: 404 page not found\n"22642026/09/29 08:16:27 WARN Failed to register uploaded object key=2p5dwh0j348yd74a1cmidhd3c9qn9k7l.ls error="server returned 404: 404 page not found\n"22652026/09/29 08:16:27 INFO Signed narinfos id=1 count=322662026/09/29 08:16:27 INFO Uploading 3 narinfos22672026/09/29 08:16:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22682026/09/29 08:16:27 WARN Failed to register uploaded object key=fr2r7z40w6qvjkqm4dv1x9h39plz025z.narinfo error="server returned 404: 404 page not found\n"22692026/09/29 08:16:27 WARN Failed to register uploaded object key=dvqlky9gf7nwsa122a4gqcfbxfmihvjg.narinfo error="server returned 404: 404 page not found\n"22702026/09/29 08:16:27 INFO Received complete push request method=POST path=/api/pushes/1/complete22712026/09/29 08:16:27 WARN Failed to register uploaded object key=2p5dwh0j348yd74a1cmidhd3c9qn9k7l.narinfo error="server returned 404: 404 page not found\n"22722026/09/29 08:16:27 INFO lead: released remote=192.0.2.1:123422732026/09/29 08:16:27 INFO Upload complete. (63ms)2274=== NAME TestClientPushesUseOnePush2275 client_pushes_test.go:97: Retrieved narinfo from S3:2276 StorePath: /build/TestClientPushesUseOnePush1441946108/001/store/2p5dwh0j348yd74a1cmidhd3c9qn9k7l-shared-dep2277 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2278 Compression: zstd2279 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822280 NarSize: 1362281 References: 2282 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2283 client_pushes_test.go:97: Retrieved narinfo from S3:2284 StorePath: /build/TestClientPushesUseOnePush1441946108/001/store/dvqlky9gf7nwsa122a4gqcfbxfmihvjg-a2285 URL: nar/16zmad8kjd0105jiqgsf3m4j56vp5z24yslpqg9rsrs490rfmzkj.nar.zst2286 Compression: zstd2287 NarHash: sha256:16zmad8kjd0105jiqgsf3m4j56vp5z24yslpqg9rsrs490rfmzkj2288 NarSize: 2162289 References: /build/TestClientPushesUseOnePush1441946108/001/store/2p5dwh0j348yd74a1cmidhd3c9qn9k7l-shared-dep2290 CA: text:sha256:1qccgjrn7gfmx0p4iviqbnlfljw80arv3v2icp2b24jwpxps63qm2291 client_pushes_test.go:97: Retrieved narinfo from S3:2292 StorePath: /build/TestClientPushesUseOnePush1441946108/001/store/fr2r7z40w6qvjkqm4dv1x9h39plz025z-b2293 URL: nar/16zmad8kjd0105jiqgsf3m4j56vp5z24yslpqg9rsrs490rfmzkj.nar.zst2294 Compression: zstd2295 NarHash: sha256:16zmad8kjd0105jiqgsf3m4j56vp5z24yslpqg9rsrs490rfmzkj2296 NarSize: 2162297 References: /build/TestClientPushesUseOnePush1441946108/001/store/2p5dwh0j348yd74a1cmidhd3c9qn9k7l-shared-dep2298 CA: text:sha256:1qccgjrn7gfmx0p4iviqbnlfljw80arv3v2icp2b24jwpxps63qm22992026/09/29 08:16:27 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NmE4ODNjNjktZjQ0Yi00N2M1LTk3NjgtNDk2MTQwZjY4ZWY4LjUxODI0NWNiLTFjZTQtNDM5NC05NTFjLTc1OGFkMWE2NWQ0ZngxNzkwNjY5Nzg3MjE5MDAzODU0 parts=1023002026/09/29 08:16:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete23012026/09/29 08:16:27 INFO Completed upload id=12302--- PASS: TestClientPushesUseOnePush (0.63s)23032026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures23042026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures23052026/09/29 08:16:27 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo23062026/09/29 08:16:27 WARN Found objects in DB but missing from S3, will re-upload count=12307--- PASS: TestService_verifyS3Integrity (0.80s)2308--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.43s)23092026/09/29 08:16:27 INFO lead: acquired remote=192.0.2.1:123423102026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes23112026/09/29 08:16:27 INFO lead: released remote=192.0.2.1:12342312--- PASS: TestLeadElectsOneAndHandsOver (0.61s)23132026/09/29 08:16:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)23142026/09/29 08:16:27 INFO Uploading ryb8da79kbmcgblcnnlryxxgfl031p1h-pinned-file.txt (128B)2315=== NAME TestClientCADerivations2316 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2317 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2318 error: binary cache 's3://bucket46?endpoint=http://localhost:41839®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations434554092/001/store'2319 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 123202026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"2321--- PASS: TestClientCADerivations (0.75s)23222026/09/29 08:16:27 WARN Failed to register uploaded object key=ryb8da79kbmcgblcnnlryxxgfl031p1h.ls error="server returned 404: 404 page not found\n"23232026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23242026/09/29 08:16:27 INFO Signed narinfos id=1 count=123252026/09/29 08:16:27 INFO Uploading 1 narinfos2326=== NAME TestClientMultipleUploads2327 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads2868585601/001/store/x4qazwc1lb4zn57mm85k682v35scas4q-test-file-0.txt23282026/09/29 08:16:27 INFO Received complete push request method=POST path=/api/pushes/1/complete23292026/09/29 08:16:27 WARN Failed to register uploaded object key=ryb8da79kbmcgblcnnlryxxgfl031p1h.narinfo error="server returned 404: 404 page not found\n"23302026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes23312026/09/29 08:16:27 INFO Upload complete. (64ms)23322026/09/29 08:16:27 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"23332026/09/29 08:16:27 WARN mTLS auth: bound subjects configured but subject DN unavailable23342026/09/29 08:16:27 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2335--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.45s)23362026/09/29 08:16:27 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)23372026/09/29 08:16:27 INFO Uploading 02qylmydrhvwsqsr8asbr49i2y2ciiwh-shared-dep (136B)23382026/09/29 08:16:27 INFO Uploading l040qrbng551yb6w2iyg9klwsypqy94g-top (224B)2339=== RUN TestService_RequireScope_OIDC/builder_may_write2340=== PAUSE TestService_RequireScope_OIDC/builder_may_write2341=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2342=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2343=== RUN TestService_RequireScope_OIDC/ops_may_admin2344=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2345=== RUN TestService_RequireScope_OIDC/ops_may_not_write2346=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2347=== RUN TestService_RequireScope_OIDC/reader_may_not_write2348=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2349=== RUN TestService_RequireScope_OIDC/static_token_may_admin2350=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2351=== RUN TestService_RequireScope_OIDC/static_token_may_write2352=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2353=== RUN TestService_RequireScope_OIDC/reader_may_read2354=== PAUSE TestService_RequireScope_OIDC/reader_may_read2355=== RUN TestService_RequireScope_OIDC/writer_implies_read2356=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2357=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2358=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2359=== CONT TestService_RequireScope_OIDC/builder_may_write2360=== CONT TestService_RequireScope_OIDC/reader_may_not_write2361=== CONT TestService_RequireScope_OIDC/writer_implies_read2362=== CONT TestService_RequireScope_OIDC/ops_may_admin2363=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2364=== CONT TestService_RequireScope_OIDC/ops_may_not_write2365=== CONT TestService_RequireScope_OIDC/static_token_may_write2366=== CONT TestService_RequireScope_OIDC/static_token_may_admin2367=== CONT TestService_RequireScope_OIDC/reader_may_read2368=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2369--- PASS: TestService_RequireScope_OIDC (0.61s)2370 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2371 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2372 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2373 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2374 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2375 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2376 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2377 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2378 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2379 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)23802026/09/29 08:16:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete23812026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/1kkg5kk1xz0w97vcz3k2j9ygx7g0pdirqbdrg1iyv2sc34ascvbv.nar.zst error="server returned 404: 404 page not found\n"23822026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign23832026/09/29 08:16:27 WARN Failed to register uploaded object key=l040qrbng551yb6w2iyg9klwsypqy94g.ls error="server returned 404: 404 page not found\n"23842026/09/29 08:16:27 WARN Failed to register uploaded object key=02qylmydrhvwsqsr8asbr49i2y2ciiwh.ls error="server returned 404: 404 page not found\n"23852026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"23862026/09/29 08:16:27 INFO Signed narinfos id=1 count=223872026/09/29 08:16:27 INFO Uploading 2 narinfos23882026/09/29 08:16:27 WARN Failed to register uploaded object key=l040qrbng551yb6w2iyg9klwsypqy94g.narinfo error="server returned 404: 404 page not found\n"23892026/09/29 08:16:27 INFO Received complete push request method=POST path=/api/pushes/1/complete23902026/09/29 08:16:27 WARN Failed to register uploaded object key=02qylmydrhvwsqsr8asbr49i2y2ciiwh.narinfo error="server returned 404: 404 page not found\n"2391=== NAME TestClientWithDependencies2392 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies1955262678/001/store/y8n88rh34v7nwqg9yxj65vb1b4ql03vv-test-script23932026/09/29 08:16:27 INFO Upload complete. (57ms)2394=== NAME TestClientSharedPathCommittedMidPush2395 client_integration_test.go:680: Retrieved narinfo from S3:2396 StorePath: /build/TestClientSharedPathCommittedMidPush376103747/001/store/02qylmydrhvwsqsr8asbr49i2y2ciiwh-shared-dep23972026/09/29 08:16:27 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NmE4ODNjNjktZjQ0Yi00N2M1LTk3NjgtNDk2MTQwZjY4ZWY4LjMxYjI4ZWI2LWJhNzUtNDVjZS05N2ViLTZmOWIyYTI3MDkxMXgxNzkwNjY5Nzg3MzI1MDEzNzg5 parts=102398 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2399 Compression: zstd2400 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822401 NarSize: 1362402 References: 2403 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n24042026/09/29 08:16:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete24052026/09/29 08:16:27 INFO Completed upload id=12406 client_integration_test.go:680: Retrieved narinfo from S3:2407 StorePath: /build/TestClientSharedPathCommittedMidPush376103747/001/store/l040qrbng551yb6w2iyg9klwsypqy94g-top2408 URL: nar/1kkg5kk1xz0w97vcz3k2j9ygx7g0pdirqbdrg1iyv2sc34ascvbv.nar.zst2409 Compression: zstd2410 NarHash: sha256:1kkg5kk1xz0w97vcz3k2j9ygx7g0pdirqbdrg1iyv2sc34ascvbv2411 NarSize: 2242412 References: /build/TestClientSharedPathCommittedMidPush376103747/001/store/02qylmydrhvwsqsr8asbr49i2y2ciiwh-shared-dep2413 CA: text:sha256:08gkjzyhfyk9pybh7w7102i3d1d1059h3mzzyza896jjbgy3z2fk24142026/09/29 08:16:27 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000024152026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures24162026/09/29 08:16:27 INFO Starting cleanup of old closures method=DELETE path=/api/closures2417--- PASS: TestClientSharedPathCommittedMidPush (0.58s)2418=== NAME TestClientMultipleUploads2419 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads2868585601/001/store/x60spnm35c5yh01m61099s46jjzrycb0-test-file-1.txt24202026/09/29 08:16:27 INFO Aborted multipart uploads count=024212026/09/29 08:16:27 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=0 objects-failed-to-delete=024222026/09/29 08:16:27 INFO Vacuumed table table=pending_closures2423=== NAME TestClientWithDependencies2424 client_integration_test.go:615: Found 1 dependencies (including self)24252026/09/29 08:16:27 INFO Vacuumed table table=pending_objects24262026/09/29 08:16:27 INFO Vacuumed table table=multipart_uploads24272026/09/29 08:16:27 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=416.044185ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present24282026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures24292026/09/29 08:16:27 INFO Vacuumed table table=closures24302026/09/29 08:16:27 INFO Vacuumed table table=objects24312026/09/29 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures24322026/09/29 08:16:27 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)24332026/09/29 08:16:27 INFO Uploading p99bk44i0j55jp5d9gikzw5hrg7q94m9-b (216B)24342026/09/29 08:16:27 INFO Uploading ipfcpzdzs0y7ga8hcrm4s0xrgvs7hxfk-shared-dep (136B)24352026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/00kr2h052fgw200hwqkcr78pkpqj5br5l2ch2x81cslg59mah1jq.nar.zst error="server returned 404: 404 page not found\n"24362026/09/29 08:16:27 WARN Failed to register uploaded object key=p99bk44i0j55jp5d9gikzw5hrg7q94m9.ls error="server returned 404: 404 page not found\n"24372026/09/29 08:16:27 WARN Failed to register uploaded object key=22bxxc42iqzc0b980fvgbl1y85mzbda6.ls error="server returned 404: 404 page not found\n"24382026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"24392026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign24402026/09/29 08:16:27 WARN Failed to register uploaded object key=ipfcpzdzs0y7ga8hcrm4s0xrgvs7hxfk.ls error="server returned 404: 404 page not found\n"24412026/09/29 08:16:27 INFO Signed narinfos id=1 count=224422026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign24432026/09/29 08:16:27 INFO Signed narinfos id=2 count=224442026/09/29 08:16:27 INFO Uploading 4 narinfos2445=== NAME TestClientMultipleUploads2446 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads2868585601/001/store/dx1mc5aa6sc70bacxl59pnakwv16d92l-test-file-2.txt24472026/09/29 08:16:27 WARN Failed to register uploaded object key=p99bk44i0j55jp5d9gikzw5hrg7q94m9.narinfo error="server returned 404: 404 page not found\n"24482026/09/29 08:16:27 WARN Failed to register uploaded object key=ipfcpzdzs0y7ga8hcrm4s0xrgvs7hxfk.narinfo error="server returned 404: 404 page not found\n"24492026/09/29 08:16:27 WARN Failed to register uploaded object key=22bxxc42iqzc0b980fvgbl1y85mzbda6.narinfo error="server returned 404: 404 page not found\n"24502026/09/29 08:16:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete24512026/09/29 08:16:27 WARN Failed to register uploaded object key=ipfcpzdzs0y7ga8hcrm4s0xrgvs7hxfk.narinfo error="server returned 404: 404 page not found\n"24522026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes24532026/09/29 08:16:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24542026/09/29 08:16:27 INFO Uploading n3hmrxm8kdakr5i6mvkwkh25fzkqwqj4-unpinned-file.txt (128B)24552026/09/29 08:16:27 INFO Completed upload id=124562026/09/29 08:16:27 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete24572026/09/29 08:16:27 INFO Completed upload id=224582026/09/29 08:16:27 INFO Upload complete. (52ms)24592026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"24602026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign24612026/09/29 08:16:27 WARN Failed to register uploaded object key=n3hmrxm8kdakr5i6mvkwkh25fzkqwqj4.ls error="server returned 404: 404 page not found\n"24622026/09/29 08:16:27 INFO Signed narinfos id=2 count=124632026/09/29 08:16:27 INFO Uploading 1 narinfos2464=== NAME TestClientFallsBackToClosures2465 client_pushes_test.go:112: Retrieved narinfo from S3:2466 StorePath: /build/TestClientFallsBackToClosures1450209022/001/store/ipfcpzdzs0y7ga8hcrm4s0xrgvs7hxfk-shared-dep2467 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2468 Compression: zstd2469 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822470 NarSize: 1362471 References: 2472 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n24732026/09/29 08:16:27 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000002474 client_pushes_test.go:112: Retrieved narinfo from S3:2475 StorePath: /build/TestClientFallsBackToClosures1450209022/001/store/22bxxc42iqzc0b980fvgbl1y85mzbda6-a2476 URL: nar/00kr2h052fgw200hwqkcr78pkpqj5br5l2ch2x81cslg59mah1jq.nar.zst2477 Compression: zstd2478 NarHash: sha256:00kr2h052fgw200hwqkcr78pkpqj5br5l2ch2x81cslg59mah1jq2479 NarSize: 2162480 References: /build/TestClientFallsBackToClosures1450209022/001/store/ipfcpzdzs0y7ga8hcrm4s0xrgvs7hxfk-shared-dep2481 CA: text:sha256:0ir4k2pqp6dsk33jr7ac8y0r6cbawhgrxc89jfk07qm11xld4g782482--- PASS: TestService_createPendingClosureHandler (0.82s)24832026/09/29 08:16:27 INFO Received complete push request method=POST path=/api/pushes/2/complete24842026/09/29 08:16:27 WARN Failed to register uploaded object key=n3hmrxm8kdakr5i6mvkwkh25fzkqwqj4.narinfo error="server returned 404: 404 page not found\n"24852026/09/29 08:16:27 INFO Upload complete. (45ms)2486=== NAME TestClientFallsBackToClosures2487 client_pushes_test.go:112: Retrieved narinfo from S3:2488 StorePath: /build/TestClientFallsBackToClosures1450209022/001/store/p99bk44i0j55jp5d9gikzw5hrg7q94m9-b2489 URL: nar/00kr2h052fgw200hwqkcr78pkpqj5br5l2ch2x81cslg59mah1jq.nar.zst2490 Compression: zstd2491 NarHash: sha256:00kr2h052fgw200hwqkcr78pkpqj5br5l2ch2x81cslg59mah1jq2492 NarSize: 2162493 References: /build/TestClientFallsBackToClosures1450209022/001/store/ipfcpzdzs0y7ga8hcrm4s0xrgvs7hxfk-shared-dep2494 CA: text:sha256:0ir4k2pqp6dsk33jr7ac8y0r6cbawhgrxc89jfk07qm11xld4g782495--- PASS: TestClientFallsBackToClosures (0.62s)24962026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes24972026/09/29 08:16:27 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"24982026/09/29 08:16:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)24992026/09/29 08:16:27 INFO Uploading y8n88rh34v7nwqg9yxj65vb1b4ql03vv-test-script (136B)25002026/09/29 08:16:27 INFO Received create pin request method=POST path=/api/pins/myapp25012026/09/29 08:16:27 WARN Failed to register uploaded object key=y8n88rh34v7nwqg9yxj65vb1b4ql03vv.ls error="server returned 404: 404 page not found\n"25022026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"25032026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25042026/09/29 08:16:27 WARN Failed to register uploaded object key=log/2lj242j0q5ianmkmkad8wi3awfygq3dn-test-script.drv error="server returned 404: 404 page not found\n"25052026/09/29 08:16:27 INFO Signed narinfos id=1 count=125062026/09/29 08:16:27 INFO Uploading 1 narinfos25072026/09/29 08:16:27 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1249811932/001/store/ryb8da79kbmcgblcnnlryxxgfl031p1h-pinned-file.txt narinfo_key=ryb8da79kbmcgblcnnlryxxgfl031p1h.narinfo25082026/09/29 08:16:27 INFO Received complete push request method=POST path=/api/pushes/1/complete25092026/09/29 08:16:27 WARN Failed to register uploaded object key=y8n88rh34v7nwqg9yxj65vb1b4ql03vv.narinfo error="server returned 404: 404 page not found\n"25102026/09/29 08:16:27 INFO Starting cleanup of old closures method=DELETE path=/api/closures25112026/09/29 08:16:27 INFO Garbage collection started25122026/09/29 08:16:27 INFO Upload complete. (51ms)25132026/09/29 08:16:27 INFO Aborted multipart uploads count=02514=== NAME TestClientWithDependencies2515 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1955262678/001/store) requires matching store prefix25162026/09/29 08:16:27 WARN Force mode enabled - objects will be deleted immediately without grace period2517--- PASS: TestClientWithDependencies (0.61s)25182026/09/29 08:16:27 INFO Received push request method=POST path=/api/pushes25192026/09/29 08:16:27 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)25202026/09/29 08:16:27 INFO Uploading x4qazwc1lb4zn57mm85k682v35scas4q-test-file-0.txt (160B)25212026/09/29 08:16:27 INFO Uploading dx1mc5aa6sc70bacxl59pnakwv16d92l-test-file-2.txt (160B)25222026/09/29 08:16:27 INFO Uploading x60spnm35c5yh01m61099s46jjzrycb0-test-file-1.txt (160B)25232026/09/29 08:16:27 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"25242026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"25252026/09/29 08:16:27 WARN Failed to register uploaded object key=dx1mc5aa6sc70bacxl59pnakwv16d92l.ls error="server returned 404: 404 page not found\n"25262026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"25272026/09/29 08:16:27 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"25282026/09/29 08:16:27 WARN Failed to register uploaded object key=x60spnm35c5yh01m61099s46jjzrycb0.ls error="server returned 404: 404 page not found\n"25292026/09/29 08:16:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign25302026/09/29 08:16:27 WARN Failed to register uploaded object key=x4qazwc1lb4zn57mm85k682v35scas4q.ls error="server returned 404: 404 page not found\n"25312026/09/29 08:16:27 INFO Signed narinfos id=1 count=325322026/09/29 08:16:27 INFO Uploading 3 narinfos25332026/09/29 08:16:27 WARN Failed to register uploaded object key=dx1mc5aa6sc70bacxl59pnakwv16d92l.narinfo error="server returned 404: 404 page not found\n"25342026/09/29 08:16:27 WARN Failed to register uploaded object key=x4qazwc1lb4zn57mm85k682v35scas4q.narinfo error="server returned 404: 404 page not found\n"25352026/09/29 08:16:27 INFO Received complete push request method=POST path=/api/pushes/1/complete25362026/09/29 08:16:27 WARN Failed to register uploaded object key=x60spnm35c5yh01m61099s46jjzrycb0.narinfo error="server returned 404: 404 page not found\n"25372026/09/29 08:16:27 INFO Upload complete. (55ms)2538=== NAME TestClientMultipleUploads2539 client_integration_test.go:369: Uploaded 3 paths in 91.56125ms2540--- PASS: TestClientMultipleUploads (0.63s)25412026/09/29 08:16:28 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=781.708733ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2542=== NAME TestOrphanedObjectsGCStressTest2543 orphaned_objects_gc_test.go:425: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2544 orphaned_objects_gc_test.go:446: Marked 210 objects for deletion2545--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)2546 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2547 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2548 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.95s)25492026/09/29 08:16:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=02550=== NAME TestOrphanedObjectsGCStressTest2551 orphaned_objects_gc_test.go:509: Stress test completed successfully:2552 orphaned_objects_gc_test.go:510: - Active objects preserved: 202553 orphaned_objects_gc_test.go:511: - Objects deleted: 2102554 orphaned_objects_gc_test.go:512: - Total GC'd: 2102555--- PASS: TestOrphanedObjectsGCStressTest (2.31s)25562026/09/29 08:16:28 INFO Vacuumed table table=pending_closures25572026/09/29 08:16:28 INFO Vacuumed table table=pending_objects25582026/09/29 08:16:28 INFO Vacuumed table table=multipart_uploads25592026/09/29 08:16:28 INFO Vacuumed table table=closures25602026/09/29 08:16:28 INFO Vacuumed table table=objects25612026/09/29 08:16:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=2001 objects-failed-to-delete=025622026/09/29 08:16:28 INFO Vacuumed table table=pending_closures25632026/09/29 08:16:28 INFO Vacuumed table table=pending_objects25642026/09/29 08:16:28 INFO Vacuumed table table=multipart_uploads25652026/09/29 08:16:28 INFO Vacuumed table table=closures25662026/09/29 08:16:28 INFO Vacuumed table table=objects25672026/09/29 08:16:28 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.613970138s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present25682026/09/29 08:16:29 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02569=== NAME TestClientIntegration2570 client_integration_test.go:323: Objects in database after GC:2571 client_integration_test.go:323: Successfully deleted all objects with GC --force2572--- PASS: TestClientIntegration (2.65s)25732026/09/29 08:16:29 WARN Rate limiter enabled after throttle name=s3-test rate=525742026/09/29 08:16:29 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2575=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2576 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102577 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002578--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.64s)25792026/09/29 08:16:29 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=2001 objects_failed=02580=== NAME TestPinProtectsFromGC2581 client_integration_test.go:794: Pin successfully protected closure from garbage collection2582--- PASS: TestPinProtectsFromGC (2.72s)25832026/09/29 08:16:30 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-config25842026/09/29 08:16:30 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=212.058062ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25852026/09/29 08:16:30 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=419.310379ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25862026/09/29 08:16:31 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=759.206502ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25872026/09/29 08:16:32 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.569559597s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25882026/09/29 08:16:33 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"25892026/09/29 08:16:33 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-config25902026/09/29 08:16:33 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=211.474684ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25912026/09/29 08:16:33 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=373.841946ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25922026/09/29 08:16:34 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=851.829666ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25932026/09/29 08:16:35 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.583138897s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config25942026/09/29 08:16:36 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_closures25952026/09/29 08:16:36 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=207.835988ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures25962026/09/29 08:16:37 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=364.853103ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures25972026/09/29 08:16:37 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=725.187147ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures25982026/09/29 08:16:38 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.483310283s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2599--- PASS: TestClientErrorHandling (0.00s)2600 --- PASS: TestClientErrorHandling/InvalidStorePath (0.36s)2601 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.42s)2602 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.28s)2603PASS2604{"timestamp":"2026-09-29T08:16:39.631782582Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:43140","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2260,"threadName":"rustfs-worker","threadId":"ThreadId(205)"}26052026-09-29 08:16:39.858 UTC [128] LOG: received smart shutdown request26062026-09-29 08:16:39.862 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 126072026-09-29 08:16:39.874 UTC [133] LOG: shutting down26082026-09-29 08:16:39.874 UTC [133] LOG: checkpoint starting: shutdown immediate26092026-09-29 08:16:40.715 UTC [133] LOG: checkpoint complete: wrote 10928 buffers (66.7%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 18 recycled; write=0.198 s, sync=0.621 s, total=0.842 s; sync files=21875, longest=0.012 s, average=0.001 s; distance=297524 kB, estimate=297524 kB; lsn=0/139F30D0, redo lsn=0/139F30D026102026-09-29 08:16:40.784 UTC [128] LOG: database system is shut down2611Running OIDC tests...2612=== RUN TestAudienceForIssuer2613=== PAUSE TestAudienceForIssuer2614=== RUN TestGlobMatch2615=== PAUSE TestGlobMatch2616=== RUN TestValidateToken_ValidToken2617=== PAUSE TestValidateToken_ValidToken2618=== RUN TestValidateToken_WrongAudience2619=== PAUSE TestValidateToken_WrongAudience2620=== RUN TestValidateToken_Expired2621=== PAUSE TestValidateToken_Expired2622=== RUN TestValidateToken_BoundClaimsMismatch2623=== PAUSE TestValidateToken_BoundClaimsMismatch2624=== RUN TestValidateToken_BoundSubjectMismatch2625=== PAUSE TestValidateToken_BoundSubjectMismatch2626=== RUN TestValidateToken_MultipleProviders2627=== PAUSE TestValidateToken_MultipleProviders2628=== RUN TestValidateToken_NoMatchingProvider2629=== PAUSE TestValidateToken_NoMatchingProvider2630=== RUN TestValidateToken_KubernetesServiceAccount2631=== PAUSE TestValidateToken_KubernetesServiceAccount2632=== RUN TestNewValidator_KubernetesRequiresCA2633=== PAUSE TestNewValidator_KubernetesRequiresCA2634=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2635=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2636=== RUN TestPins_ReservedForMatchingRule2637=== PAUSE TestPins_ReservedForMatchingRule2638=== RUN TestPins_TopLevelShorthand2639=== PAUSE TestPins_TopLevelShorthand2640=== RUN TestPins_ConfigValidation2641=== PAUSE TestPins_ConfigValidation2642=== RUN TestScopes_LegacyProviderDefaultsToWrite2643=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2644=== RUN TestScopes_Rules2645=== PAUSE TestScopes_Rules2646=== RUN TestScopes_ConfigValidation2647=== PAUSE TestScopes_ConfigValidation2648=== CONT TestAudienceForIssuer2649=== CONT TestPins_ConfigValidation2650=== CONT TestValidateToken_KubernetesServiceAccount2651=== CONT TestValidateToken_BoundClaimsMismatch2652--- PASS: TestAudienceForIssuer (0.00s)2653=== CONT TestValidateToken_Expired2654=== CONT TestValidateToken_WrongAudience2655=== CONT TestValidateToken_ValidToken2656=== CONT TestGlobMatch2657=== RUN TestGlobMatch/foo_foo2658=== PAUSE TestGlobMatch/foo_foo2659=== RUN TestGlobMatch/foo_bar2660=== PAUSE TestGlobMatch/foo_bar2661=== RUN TestGlobMatch/*_2662=== PAUSE TestGlobMatch/*_2663=== RUN TestGlobMatch/*_anything2664=== CONT TestValidateToken_MultipleProviders2665=== CONT TestValidateToken_NoMatchingProvider2666=== CONT TestPins_ReservedForMatchingRule2667=== CONT TestPins_TopLevelShorthand2668=== CONT TestScopes_Rules2669=== CONT TestScopes_ConfigValidation2670=== CONT TestScopes_LegacyProviderDefaultsToWrite2671=== CONT TestValidateToken_BoundSubjectMismatch2672=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2673=== CONT TestNewValidator_KubernetesRequiresCA2674=== PAUSE TestGlobMatch/*_anything2675=== RUN TestGlobMatch/foo*_foo2676=== PAUSE TestGlobMatch/foo*_foo2677=== RUN TestGlobMatch/foo*_foobar2678=== PAUSE TestGlobMatch/foo*_foobar2679=== RUN TestGlobMatch/foo*_bar2680=== PAUSE TestGlobMatch/foo*_bar2681=== RUN TestGlobMatch/*bar_bar2682=== PAUSE TestGlobMatch/*bar_bar2683=== RUN TestGlobMatch/*bar_foobar2684=== PAUSE TestGlobMatch/*bar_foobar2685=== RUN TestGlobMatch/*bar_foo2686--- PASS: TestPins_ConfigValidation (0.00s)2687=== PAUSE TestGlobMatch/*bar_foo2688=== RUN TestGlobMatch/foo*bar_foobar2689=== PAUSE TestGlobMatch/foo*bar_foobar2690=== RUN TestGlobMatch/foo*bar_foo123bar2691=== PAUSE TestGlobMatch/foo*bar_foo123bar2692=== RUN TestGlobMatch/foo*bar_foobarbaz2693=== PAUSE TestGlobMatch/foo*bar_foobarbaz2694=== RUN TestGlobMatch/*/*_foo/bar2695=== PAUSE TestGlobMatch/*/*_foo/bar2696=== RUN TestGlobMatch/*/*_foo2697=== PAUSE TestGlobMatch/*/*_foo2698=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2699=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2700=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02701=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02702--- PASS: TestScopes_ConfigValidation (0.00s)2703=== RUN TestGlobMatch/refs/*/main_refs/heads/main2704=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2705=== RUN TestGlobMatch/fo?_foo2706=== PAUSE TestGlobMatch/fo?_foo2707=== RUN TestGlobMatch/fo?_fo2708=== PAUSE TestGlobMatch/fo?_fo2709=== RUN TestGlobMatch/fo?_fooo2710=== PAUSE TestGlobMatch/fo?_fooo2711=== RUN TestGlobMatch/?oo_foo2712=== PAUSE TestGlobMatch/?oo_foo2713=== RUN TestGlobMatch/?oo_boo2714=== PAUSE TestGlobMatch/?oo_boo2715=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2716=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2717=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2718=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2719=== CONT TestGlobMatch/foo_foo2720=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2721=== CONT TestGlobMatch/*/*_foo/bar2722=== CONT TestGlobMatch/foo*_foobar2723=== CONT TestGlobMatch/*_anything2724=== CONT TestGlobMatch/*_2725=== CONT TestGlobMatch/foo_bar2726=== CONT TestGlobMatch/foo*bar_foobarbaz2727=== CONT TestGlobMatch/?oo_boo2728=== CONT TestGlobMatch/fo?_fooo2729=== CONT TestGlobMatch/fo?_fo2730=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2731=== CONT TestGlobMatch/refs/*/main_refs/heads/main2732=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02733=== CONT TestGlobMatch/*/*_foo2734=== CONT TestGlobMatch/fo?_foo2735=== CONT TestGlobMatch/foo*_foo2736=== CONT TestGlobMatch/?oo_foo2737=== CONT TestGlobMatch/foo*bar_foo123bar2738=== CONT TestGlobMatch/foo*bar_foobar2739=== CONT TestGlobMatch/*bar_foo2740=== CONT TestGlobMatch/*bar_foobar2741=== CONT TestGlobMatch/*bar_bar2742=== CONT TestGlobMatch/foo*_bar2743=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2744--- PASS: TestGlobMatch (0.00s)2745 --- PASS: TestGlobMatch/foo_foo (0.00s)2746 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2747 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2748 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2749 --- PASS: TestGlobMatch/*_anything (0.00s)2750 --- PASS: TestGlobMatch/*_ (0.00s)2751 --- PASS: TestGlobMatch/foo_bar (0.00s)2752 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2753 --- PASS: TestGlobMatch/?oo_boo (0.00s)2754 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2755 --- PASS: TestGlobMatch/fo?_fo (0.00s)2756 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2757 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2758 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2759 --- PASS: TestGlobMatch/*/*_foo (0.00s)2760 --- PASS: TestGlobMatch/fo?_foo (0.00s)2761 --- PASS: TestGlobMatch/foo*_foo (0.00s)2762 --- PASS: TestGlobMatch/?oo_foo (0.00s)2763 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2764 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2765 --- PASS: TestGlobMatch/*bar_foo (0.00s)2766 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2767 --- PASS: TestGlobMatch/*bar_bar (0.00s)2768 --- PASS: TestGlobMatch/foo*_bar (0.00s)2769 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)27702026/09/29 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45675/oidc2771--- PASS: TestValidateToken_Expired (0.07s)27722026/09/29 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38047/oidc2773--- PASS: TestValidateToken_BoundSubjectMismatch (0.09s)27742026/09/29 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37563/oidc2775--- PASS: TestScopes_Rules (0.10s)27762026/09/29 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36355/oidc2777--- PASS: TestValidateToken_WrongAudience (0.11s)27782026/09/29 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33909/oidc27792026/09/29 08:16:42 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:34535/oidc27802026/09/29 08:16:42 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:35465/oidc2781--- PASS: TestPins_TopLevelShorthand (0.13s)2782--- PASS: TestValidateToken_MultipleProviders (0.13s)27832026/09/29 08:16:42 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12327842026/09/29 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39803/oidc2785--- PASS: TestValidateToken_BoundClaimsMismatch (0.14s)2786--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.14s)27872026/09/29 08:16:42 http: TLS handshake error from 127.0.0.1:40174: remote error: tls: bad certificate2788--- PASS: TestNewValidator_KubernetesRequiresCA (0.16s)27892026/09/29 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37273/oidc27902026/09/29 08:16:42 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:46309/oidc2791--- PASS: TestValidateToken_ValidToken (0.20s)2792--- PASS: TestValidateToken_NoMatchingProvider (0.20s)27932026/09/29 08:16:42 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:390412794--- PASS: TestValidateToken_KubernetesServiceAccount (0.21s)27952026/09/29 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32817/oidc2796--- PASS: TestPins_ReservedForMatchingRule (0.23s)27972026/09/29 08:16:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41063/oidc2798--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.27s)2799PASS2800Running hook tests...2801=== RUN TestSendPathsEmpty2802=== PAUSE TestSendPathsEmpty2803=== RUN TestQueueEnqueueAndFetch2804=== PAUSE TestQueueEnqueueAndFetch2805=== RUN TestQueueDeduplication2806=== PAUSE TestQueueDeduplication2807=== RUN TestQueueRemove2808=== PAUSE TestQueueRemove2809=== RUN TestQueueFetchBatchLimit2810=== PAUSE TestQueueFetchBatchLimit2811=== RUN TestQueueRetryMovesToBack2812=== PAUSE TestQueueRetryMovesToBack2813=== RUN TestQueueFetchRemoveLifecycle2814=== PAUSE TestQueueFetchRemoveLifecycle2815=== RUN TestQueueConcurrentWriters2816=== PAUSE TestQueueConcurrentWriters2817=== RUN TestQueueRemoveLargeClosure2818=== PAUSE TestQueueRemoveLargeClosure2819=== RUN TestServerClientIntegration2820=== PAUSE TestServerClientIntegration2821=== RUN TestServerQueueError2822=== PAUSE TestServerQueueError2823=== RUN TestGetListenerSocketActivation2824 server_test.go:210: === RUN TestGetListenerSocketActivation2825 --- PASS: TestGetListenerSocketActivation (0.00s)2826 PASS2827 2828--- PASS: TestGetListenerSocketActivation (0.01s)2829=== RUN TestDrainIsolatesPoisonPath2830=== PAUSE TestDrainIsolatesPoisonPath2831=== RUN TestRunNotBlockedByPoisonHead2832=== PAUSE TestRunNotBlockedByPoisonHead2833=== RUN TestDrainGivesUpWhenServerDown2834=== PAUSE TestDrainGivesUpWhenServerDown2835=== RUN TestFailedPathPrunedByLaterClosure2836=== PAUSE TestFailedPathPrunedByLaterClosure2837=== RUN TestWorkerUploadsAndRemoves2838=== PAUSE TestWorkerUploadsAndRemoves2839=== RUN TestWorkerSkipsGCdPaths2840=== PAUSE TestWorkerSkipsGCdPaths2841=== RUN TestWorkerPrunesClosureDeps2842=== PAUSE TestWorkerPrunesClosureDeps2843=== RUN TestDrainTimeout2844=== PAUSE TestDrainTimeout2845=== CONT TestSendPathsEmpty2846=== CONT TestDrainGivesUpWhenServerDown2847=== CONT TestQueueFetchBatchLimit2848--- PASS: TestSendPathsEmpty (0.00s)2849=== CONT TestRunNotBlockedByPoisonHead2850=== CONT TestDrainIsolatesPoisonPath2851=== CONT TestWorkerSkipsGCdPaths2852=== CONT TestServerQueueError2853=== CONT TestServerClientIntegration2854=== CONT TestDrainTimeout2855=== CONT TestQueueRemoveLargeClosure2856=== CONT TestQueueRemove2857=== CONT TestWorkerPrunesClosureDeps2858=== CONT TestQueueDeduplication2859=== CONT TestQueueEnqueueAndFetch28602026/09/29 08:16:42 ERROR Failed to queue paths error="permission denied" count=12861=== CONT TestWorkerUploadsAndRemoves2862=== CONT TestQueueFetchRemoveLifecycle2863=== CONT TestQueueRetryMovesToBack2864=== CONT TestQueueConcurrentWriters2865=== CONT TestFailedPathPrunedByLaterClosure2866--- PASS: TestServerClientIntegration (0.00s)2867--- PASS: TestServerQueueError (0.00s)28682026/09/29 08:16:42 INFO Uploading batch count=128692026/09/29 08:16:42 ERROR Upload failed error="upload failed" count=12870--- PASS: TestQueueFetchBatchLimit (0.01s)28712026/09/29 08:16:42 INFO Uploading batch count=228722026/09/29 08:16:42 INFO Uploading batch count=428732026/09/29 08:16:42 ERROR Upload failed error="upload failed" count=428742026/09/29 08:16:42 INFO Upload queue status pending=228752026/09/29 08:16:42 INFO Uploading batch count=228762026/09/29 08:16:42 ERROR Upload failed error="upload failed" count=228772026/09/29 08:16:42 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown959737178/002/a28782026/09/29 08:16:42 INFO Uploading batch count=128792026/09/29 08:16:42 INFO Upload queue status pending=22880--- PASS: TestQueueEnqueueAndFetch (0.01s)28812026/09/29 08:16:42 INFO Uploading batch count=228822026/09/29 08:16:42 INFO Upload queue status pending=22883--- PASS: TestQueueRetryMovesToBack (0.01s)28842026/09/29 08:16:42 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1781605080/002/nonexistent28852026/09/29 08:16:42 INFO Upload queue status pending=328862026/09/29 08:16:42 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath391763426/002/bbb28872026/09/29 08:16:42 INFO Uploading batch count=128882026/09/29 08:16:42 ERROR Upload failed error="upload failed" count=128892026/09/29 08:16:42 INFO Uploading batch count=128902026/09/29 08:16:42 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown959737178/002/b2891--- PASS: TestQueueRemove (0.01s)28922026/09/29 08:16:42 INFO Uploading batch count=12893--- PASS: TestQueueDeduplication (0.01s)28942026/09/29 08:16:42 INFO Uploading batch count=12895--- PASS: TestQueueFetchRemoveLifecycle (0.01s)28962026/09/29 08:16:42 INFO Uploading batch count=228972026/09/29 08:16:42 ERROR Upload failed error="upload failed" count=228982026/09/29 08:16:42 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown959737178/002/c28992026/09/29 08:16:42 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown959737178/002/d29002026/09/29 08:16:42 INFO Uploading batch count=129012026/09/29 08:16:42 ERROR Upload failed error="upload failed" count=129022026/09/29 08:16:42 INFO Uploading batch count=229032026/09/29 08:16:42 ERROR Upload failed error="upload failed" count=229042026/09/29 08:16:42 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown959737178/002/e29052026/09/29 08:16:42 INFO Uploading batch count=129062026/09/29 08:16:42 ERROR Upload failed error="upload failed" count=129072026/09/29 08:16:42 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown959737178/002/f2908--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)29092026/09/29 08:16:42 INFO Uploading batch count=129102026/09/29 08:16:42 ERROR Upload failed error="upload failed" count=129112026/09/29 08:16:42 ERROR Drain finished with paths left in queue remaining=1029122026/09/29 08:16:42 ERROR Drain finished with paths left in queue remaining=12913--- PASS: TestDrainIsolatesPoisonPath (0.02s)2914--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2915--- PASS: TestWorkerSkipsGCdPaths (0.03s)2916--- PASS: TestWorkerPrunesClosureDeps (0.03s)2917--- PASS: TestWorkerUploadsAndRemoves (0.03s)2918--- PASS: TestQueueRemoveLargeClosure (0.14s)2919--- PASS: TestQueueConcurrentWriters (0.20s)29202026/09/29 08:16:42 ERROR Upload failed error="context deadline exceeded" count=229212026/09/29 08:16:42 ERROR Drain finished with paths left in queue remaining=42922--- PASS: TestDrainTimeout (0.21s)29232026/09/29 08:16:43 INFO Uploading batch count=129242026/09/29 08:16:43 INFO Uploading batch count=129252026/09/29 08:16:43 INFO Uploading batch count=129262026/09/29 08:16:43 ERROR Upload failed error="upload failed" count=129272026/09/29 08:16:43 INFO Uploading batch count=129282026/09/29 08:16:43 ERROR Upload failed error="upload failed" count=129292026/09/29 08:16:43 INFO Uploading batch count=129302026/09/29 08:16:43 ERROR Upload failed error="upload failed" count=129312026/09/29 08:16:43 INFO Uploading batch count=129322026/09/29 08:16:43 ERROR Upload failed error="upload failed" count=129332026/09/29 08:16:43 ERROR Drain finished with paths left in queue remaining=12934--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2935PASS