diff --git a/internal/cmd/service_create.go b/internal/cmd/service_create.go index 05394df0..263b5b06 100644 --- a/internal/cmd/service_create.go +++ b/internal/cmd/service_create.go @@ -203,7 +203,21 @@ Note: You can specify both CPU and memory together, or specify only one (the oth }); waitErr != nil { fmt.Fprintf(statusOutput, "❌ Error: %s\n", waitErr) } else { - fmt.Fprintf(statusOutput, "🎉 Service is ready and running!\n") + // READY only means the control plane finished reconciling. Confirm + // the endpoint serves before claiming the service is usable. + if common.WaitForConnectable(cmd.Context(), common.ConnectableWaitArgs{ + Client: client, + Config: cfg, + ProjectID: projectID, + ServiceID: serviceID, + Role: "tsdbadmin", + InitialPassword: util.Deref(service.InitialPassword), + Output: statusOutput, + }) { + fmt.Fprintf(statusOutput, "🎉 Service is ready and running!\n") + } else { + fmt.Fprintf(statusOutput, "✅ Service provisioned.\n") + } printConnectMessage(statusOutput, passwordSaved, createNoSetDefault, serviceID) } } diff --git a/internal/cmd/service_fork.go b/internal/cmd/service_fork.go index 2b0d490d..d62f37da 100644 --- a/internal/cmd/service_fork.go +++ b/internal/cmd/service_fork.go @@ -224,6 +224,16 @@ Examples: }); waitErr != nil { fmt.Fprintf(statusOutput, "❌ Error: %s\n", waitErr) } else { + // A fresh fork reports READY before its endpoint is up, same as create. + common.WaitForConnectable(cmd.Context(), common.ConnectableWaitArgs{ + Client: client, + Config: cfg, + ProjectID: projectID, + ServiceID: forkedServiceID, + Role: "tsdbadmin", + InitialPassword: util.Deref(forkedService.InitialPassword), + Output: statusOutput, + }) fmt.Fprintf(statusOutput, "🎉 Service fork completed successfully!\n") printConnectMessage(statusOutput, passwordSaved, forkNoSetDefault, forkedServiceID) } diff --git a/internal/cmd/service_start.go b/internal/cmd/service_start.go index 929dedd9..2089a990 100644 --- a/internal/cmd/service_start.go +++ b/internal/cmd/service_start.go @@ -104,6 +104,17 @@ Examples: return err } + // A resumed service reports READY before its endpoint is back up, so + // confirm it serves before handing control back. + common.WaitForConnectable(cmd.Context(), common.ConnectableWaitArgs{ + Client: client, + Config: cfg, + ProjectID: projectID, + ServiceID: serviceID, + Role: "tsdbadmin", + Output: statusOutput, + }) + fmt.Fprintf(statusOutput, "✅ Service has been successfully started!\n") return nil }, diff --git a/internal/common/wait_connectable.go b/internal/common/wait_connectable.go new file mode 100644 index 00000000..a6e5eac8 --- /dev/null +++ b/internal/common/wait_connectable.go @@ -0,0 +1,229 @@ +package common + +import ( + "context" + "errors" + "fmt" + "io" + "net" + "syscall" + "time" + + "github.com/jackc/pgx/v5" + "github.com/jackc/pgx/v5/pgconn" + + "github.com/timescale/tiger-cli/internal/api" + "github.com/timescale/tiger-cli/internal/config" +) + +// A READY status means the control plane finished reconciling. savannah-deployer +// gates it on in-cluster signals (the leader pod serving, post-deploy runners +// passing) and never on the customer-facing endpoint, so the allocated port, DNS +// and load balancer can all still be catching up when the status flips. +// ready.go documents READY as "accepting connections", so waiting on the status +// alone leaves that promise unkept, and any caller that connects immediately +// (rather than after some incidental latency) races it. +// +// WaitForConnectable closes that gap by probing the endpoint until it answers. +// No control-plane gate can fully replace this: readiness is a property of the +// path between a particular client and the service, not of the service alone. + +// DefaultConnectableTimeout bounds the endpoint probe. It is deliberately much +// shorter than the provisioning wait: once the control plane reports READY the +// endpoint comes up in seconds, so a longer wait here only delays the report +// that we could not reach it. +const DefaultConnectableTimeout = 2 * time.Minute + +// connectableProbeTimeout bounds a single connection attempt, so one blackholed +// dial can't consume the whole budget. +const connectableProbeTimeout = 5 * time.Second + +type ConnectableWaitArgs struct { + Client api.ClientWithResponsesInterface + Config *config.Config + ProjectID string + ServiceID string + + // Role is the database role to probe with (e.g. "tsdbadmin"). + Role string + + // InitialPassword lets the probe authenticate fully. It is optional: without + // it the server answers with an auth error, which still proves the endpoint + // is serving (see classifyProbe). + InitialPassword string + + Output io.Writer + + // Timeout bounds the whole probe. Zero means DefaultConnectableTimeout. + Timeout time.Duration +} + +// WaitForConnectable blocks until the service's Postgres endpoint answers and +// reports whether it got there. It is best-effort by design: an unverified +// endpoint warns on Output instead of failing, because a service can be +// legitimately unreachable from where the CLI runs (VPC-only, IP allowlist) +// while being perfectly healthy, and failing those users buys nothing. +func WaitForConnectable(ctx context.Context, args ConnectableWaitArgs) bool { + timeout := args.Timeout + if timeout <= 0 { + timeout = DefaultConnectableTimeout + } + ctx, cancel := context.WithTimeout(ctx, timeout) + defer cancel() + + verified, cause := args.pollEndpoint(ctx) + if !verified { + warnUnverified(args.Output, cause) + } + return verified +} + +// pollEndpoint owns the spinner so it is always stopped before the caller prints +// anything, and returns the last failure to explain why it gave up. +func (args ConnectableWaitArgs) pollEndpoint(ctx context.Context) (bool, error) { + spinner := NewSpinner(args.Output, "Waiting for the endpoint to accept connections") + defer spinner.Stop() + + ticker := time.NewTicker(1 * time.Second) + defer ticker.Stop() + + for { + verdict, err := args.probe(ctx) + switch verdict { + case probeServing: + return true, nil + case probeUnreachable: + // Not "not yet" but "not from here": waiting longer won't help. + return false, err + } + + if err != nil { + spinner.Update(fmt.Sprintf("Endpoint not accepting connections yet: %s", err)) + } + + select { + case <-ctx.Done(): + return false, err + case <-ticker.C: + } + } +} + +func warnUnverified(out io.Writer, cause error) { + fmt.Fprintf(out, "⚠️ Warning: service reports READY but its endpoint could not be verified from here") + if cause != nil { + fmt.Fprintf(out, " (%s)", cause) + } + fmt.Fprintf(out, ".\n The service may still be starting, or may not be reachable from this network.\n") +} + +// probe fetches the current service and makes one connection attempt. The +// service is re-fetched every round because the create response predates the +// endpoint being assigned, so the host/port can appear part-way through. +func (args ConnectableWaitArgs) probe(ctx context.Context) (probeVerdict, error) { + resp, err := args.Client.GetServiceWithResponse(ctx, args.ProjectID, args.ServiceID) + if err != nil { + return probeNotYet, err + } + if resp.StatusCode() != 200 || resp.JSON200 == nil { + return probeNotYet, fmt.Errorf("unexpected %s while fetching service", resp.Status()) + } + + details, err := GetConnectionDetails(args.Config, *resp.JSON200, ConnectionDetailsOptions{ + Role: args.Role, + WithPassword: true, + InitialPassword: args.InitialPassword, + }) + if err != nil { + // Typically "endpoint host not available": not assigned yet. + return probeNotYet, err + } + + attemptCtx, cancel := context.WithTimeout(ctx, connectableProbeTimeout) + defer cancel() + + conn, err := pgx.Connect(attemptCtx, details.String()) + if err != nil { + return classifyProbe(ctx, err), err + } + defer conn.Close(attemptCtx) + + if err := conn.Ping(attemptCtx); err != nil { + return classifyProbe(ctx, err), err + } + return probeServing, nil +} + +// probeVerdict is what one connection attempt tells us about the endpoint. +type probeVerdict int + +const ( + // probeNotYet: the endpoint isn't up but plausibly will be. Keep waiting. + probeNotYet probeVerdict = iota + // probeServing: Postgres answered. Ready, even if it refused our credentials. + probeServing + // probeUnreachable: we can't tell from here. Stop waiting and say so. + probeUnreachable +) + +// classifyProbe decides what a failed connection attempt means. +// +// The load-bearing rule: any Postgres protocol error proves the server is up and +// talking, so it counts as serving even when it's an auth failure. That keeps +// the probe useful without credentials, which matters because +// --password-storage=none leaves the CLI with no password to offer. +// +// parent is the overall wait context, used to tell "this attempt timed out" from +// "the whole budget ran out". +func classifyProbe(parent context.Context, err error) probeVerdict { + if err == nil { + return probeServing + } + + // 57P03 (CANNOT_CONNECT_NOW) is the one protocol error that means "up but + // still starting", so it's the one that keeps us waiting. + var pgErr *pgconn.PgError + if errors.As(err, &pgErr) { + if pgErr.Code == "57P03" { + return probeNotYet + } + return probeServing + } + + switch { + // A single slow attempt is inconclusive; keep waiting unless the whole + // budget is spent, in which case the caller reports it unverified. + case errors.Is(err, context.DeadlineExceeded): + if parent.Err() != nil { + return probeUnreachable + } + return probeNotYet + case errors.Is(err, context.Canceled): + return probeUnreachable + // Nothing listening yet: the exact shape of the race this fixes. + case errors.Is(err, syscall.ECONNREFUSED): + return probeNotYet + // Endpoint DNS can lag the status flip. + case isDNSNotFound(err): + return probeNotYet + // Any other dial-stage failure. Checked after the specific cases above so + // the common ones stay self-documenting, and so the fix doesn't depend on + // one errno matching identically on every platform we release for. + case isDialFailure(err): + return probeNotYet + } + + // Anything else (TLS failure, unexpected protocol framing) is not something + // more waiting resolves. + return probeUnreachable +} + +func isDNSNotFound(err error) bool { + var dnsErr *net.DNSError + return errors.As(err, &dnsErr) && dnsErr.IsNotFound +} + +func isDialFailure(err error) bool { + var opErr *net.OpError + return errors.As(err, &opErr) +} diff --git a/internal/common/wait_connectable_test.go b/internal/common/wait_connectable_test.go new file mode 100644 index 00000000..ab732c14 --- /dev/null +++ b/internal/common/wait_connectable_test.go @@ -0,0 +1,221 @@ +package common + +import ( + "context" + "encoding/json" + "errors" + "fmt" + "net" + "net/http" + "net/http/httptest" + "strings" + "syscall" + "testing" + "time" + + "github.com/jackc/pgx/v5/pgconn" + + "github.com/timescale/tiger-cli/internal/api" + "github.com/timescale/tiger-cli/internal/util" +) + +// liveCtx is a context that hasn't expired, i.e. budget remaining. +func liveCtx() context.Context { return context.Background() } + +// spentCtx is a context whose deadline has already passed, i.e. budget gone. +func spentCtx(t *testing.T) context.Context { + t.Helper() + ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(-time.Second)) + t.Cleanup(cancel) + return ctx +} + +func TestClassifyProbe(t *testing.T) { + tests := []struct { + name string + parent context.Context + err error + want probeVerdict + }{ + { + name: "success", + err: nil, + want: probeServing, + }, + { + // The race this exists to fix: control plane said READY, nothing listening. + name: "connection refused", + err: &net.OpError{Op: "dial", Err: syscall.ECONNREFUSED}, + want: probeNotYet, + }, + { + name: "endpoint dns not resolving yet", + err: &net.OpError{Op: "dial", Err: &net.DNSError{IsNotFound: true}}, + want: probeNotYet, + }, + { + // 57P03 is the server saying "up, still starting". + name: "cannot connect now", + err: &pgconn.PgError{Code: "57P03"}, + want: probeNotYet, + }, + { + // The load-bearing case: no password to offer, server rejects us, but + // it answered, so the endpoint is serving. + name: "invalid password proves the server is serving", + err: &pgconn.PgError{Code: "28P01"}, + want: probeServing, + }, + { + name: "insufficient privilege also proves it is serving", + err: &pgconn.PgError{Code: "42501"}, + want: probeServing, + }, + { + name: "wrapped pg error is still unwrapped", + err: fmt.Errorf("failed to connect: %w", &pgconn.PgError{Code: "28P01"}), + want: probeServing, + }, + { + name: "attempt timed out but budget remains", + parent: liveCtx(), + err: context.DeadlineExceeded, + want: probeNotYet, + }, + { + name: "attempt timed out and budget is gone", + // parent set to a spent context below. + err: context.DeadlineExceeded, + want: probeUnreachable, + }, + { + name: "canceled", + err: context.Canceled, + want: probeUnreachable, + }, + { + // Waiting doesn't fix TLS. Report rather than spin. + name: "tls failure is not a waiting problem", + err: errors.New("tls: failed to verify certificate"), + want: probeUnreachable, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + parent := tt.parent + if parent == nil { + if tt.want == probeUnreachable && errors.Is(tt.err, context.DeadlineExceeded) { + parent = spentCtx(t) + } else { + parent = liveCtx() + } + } + if got := classifyProbe(parent, tt.err); got != tt.want { + t.Errorf("classifyProbe(%v) = %v, want %v", tt.err, got, tt.want) + } + }) + } +} + +// A refused dial must keep the probe waiting regardless of which platform's +// errno shape it arrives in, since that is the failure the fix targets. +func TestClassifyProbeRefusedVariants(t *testing.T) { + for _, err := range []error{ + syscall.ECONNREFUSED, + &net.OpError{Op: "dial", Net: "tcp", Err: syscall.ECONNREFUSED}, + fmt.Errorf("dial tcp 10.0.0.1:5432: %w", syscall.ECONNREFUSED), + &net.OpError{Op: "dial", Err: errors.New("some platform-specific refusal")}, + } { + if got := classifyProbe(liveCtx(), err); got != probeNotYet { + t.Errorf("classifyProbe(%v) = %v, want probeNotYet", err, got) + } + } +} + +// closedPort returns a port with nothing listening on it, so a dial gets +// refused: the same signal the endpoint gives while Postgres is still starting. +func closedPort(t *testing.T) int { + t.Helper() + l, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("reserving a port: %v", err) + } + port := l.Addr().(*net.TCPAddr).Port + if err := l.Close(); err != nil { + t.Fatalf("closing listener: %v", err) + } + return port +} + +// A refused endpoint must give up on its own budget and warn, never hang: this +// runs inside `tiger service create`, so an unbounded loop would wedge the CLI. +func TestWaitForConnectableGivesUpWithinBudget(t *testing.T) { + port := closedPort(t) + host := "127.0.0.1" + status := api.READY + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "application/json") + if err := json.NewEncoder(w).Encode(api.Service{ + ServiceId: util.Ptr("svc-test"), + Status: &status, + Endpoint: &api.Endpoint{Host: &host, Port: &port}, + }); err != nil { + t.Errorf("encoding service: %v", err) + } + })) + t.Cleanup(server.Close) + + client, err := api.NewClientWithResponses(server.URL) + if err != nil { + t.Fatalf("building client: %v", err) + } + + var out strings.Builder + budget := 2 * time.Second + start := time.Now() + + // InitialPassword is set so the probe skips password storage entirely; this + // test is about the loop, not about credential lookup. + verified := WaitForConnectable(context.Background(), ConnectableWaitArgs{ + Client: client, + ProjectID: "proj-test", + ServiceID: "svc-test", + Role: "tsdbadmin", + InitialPassword: "irrelevant", + Output: &out, + Timeout: budget, + }) + elapsed := time.Since(start) + + if verified { + t.Error("WaitForConnectable() = true for a refused endpoint, want false") + } + if elapsed > budget+5*time.Second { + t.Errorf("took %v, want it to respect its %v budget", elapsed, budget) + } + if !strings.Contains(out.String(), "could not be verified") { + t.Errorf("output = %q, want an unverified warning", out.String()) + } +} + +func TestWarnUnverifiedMentionsCause(t *testing.T) { + var sb strings.Builder + warnUnverified(&sb, errors.New("connection refused")) + got := sb.String() + + for _, want := range []string{"Warning", "READY", "connection refused"} { + if !strings.Contains(got, want) { + t.Errorf("warnUnverified() = %q, want it to contain %q", got, want) + } + } +} + +func TestWarnUnverifiedWithoutCause(t *testing.T) { + var sb strings.Builder + warnUnverified(&sb, nil) + if got := sb.String(); !strings.Contains(got, "Warning") || strings.Contains(got, "()") { + t.Errorf("warnUnverified(nil) = %q, want a warning with no empty parens", got) + } +}