fix(certs): a trial that gets no answer says so after 10 minutes

admin/internal/certs/certs.go

@@ -8,6 +8,7 @@ import (
 	"context"
 	"crypto/tls"
 	"encoding/json"
+	"fmt"
 	"io"
 	"log"
 	"math"
@@ -61,6 +62,45 @@ func Observe(ctx context.Context, network, addr, serverName string) Observation
 	return obs
 }
 
+// TrialPatience is how long the trial runs before the page says it is stuck.
+const TrialPatience = 10 * time.Minute
+
+// LastLine is the newest line Caddy logged about identifier, whatever it
+// says, for a person to read: "09:14:05 waiting on internal rate limiter".
+func LastLine(path, identifier string) string {
+	f, err := os.Open(path)
+	if err != nil {
+		return ""
+	}
+	defer f.Close()
+	const tail = 256 << 10
+	if fi, err := f.Stat(); err == nil && fi.Size() > tail {
+		f.Seek(fi.Size()-tail, io.SeekStart)
+	}
+	last := ""
+	sc := bufio.NewScanner(f)
+	sc.Buffer(make([]byte, 64<<10), 1<<20)
+	for sc.Scan() {
+		line := sc.Bytes()
+		if !bytes.Contains(line, []byte(identifier)) {
+			continue
+		}
+		var rec struct {
+			TS    float64 `json:"ts"`
+			Msg   string  `json:"msg"`
+			Error string  `json:"error"`
+		}
+		if json.Unmarshal(line, &rec) != nil || rec.Msg == "" {
+			continue
+		}
+		last = time.Unix(0, int64(rec.TS*float64(time.Second))).Local().Format("15:04:05") + " " + rec.Msg
+		if rec.Error != "" {
+			last += ": " + redact(rec.Error)
+		}
+	}
+	return last
+}
+
 // Event is the last thing Caddy logged about the wildcard.
 type Event struct {
 	At     time.Time
@@ -245,6 +285,13 @@ func Compute(s state.Settings, obs Observation, ev *Event, check *dns.Problem, z
 			st.State = "issuing" // the watcher moves to live any moment
 		case fresh && ev.Error != "":
 			return failed()
+		case !c.StartedAt.IsZero() && now.Sub(c.StartedAt) > TrialPatience:
+			// Caddy retries without the line explain reads (waiting on DNS,
+			// on its rate limiter): the page spun on "Proving you own" for
+			// 92 minutes. Said here, with Caddy's last line as the detail;
+			// it keeps trying, and a staging certificate still moves it on.
+			st.State = "failed"
+			st.Message = fmt.Sprintf("Proving you own %s is taking far longer than it should: %d minutes, where it usually takes one to three. The proxy keeps trying; Details shows the last thing it logged.", zone, int(now.Sub(c.StartedAt).Minutes()))
 		default:
 			st.State = "trial"
 		}

admin/internal/certs/certs_test.go

@@ -81,6 +81,16 @@ func TestCompute(t *testing.T) {
 	if s := Compute(pub(state.StageTrial), Observation{Issuer: IssuerStaging}, newErr, nil, "", now); s.State != "issuing" {
 		t.Fatalf("staging served: %s", s.State)
 	}
+	// A trial with no answer either way stops spinning after TrialPatience,
+	// and a staging certificate still moves it on after that.
+	stuck := pub(state.StageTrial)
+	stuck.Certificates.StartedAt = now.Add(-92 * time.Minute)
+	if s := Compute(stuck, Observation{}, nil, nil, "example.org", now); s.State != "failed" || !strings.Contains(s.Message, "92 minutes") {
+		t.Fatalf("stuck trial: %+v", s)
+	}
+	if s := Compute(stuck, Observation{Issuer: IssuerStaging}, nil, nil, "example.org", now); s.State != "issuing" {
+		t.Fatalf("stuck, then staging served: %s", s.State)
+	}
 	if s := Compute(pub(state.StageLive), Observation{Issuer: IssuerStaging}, nil, nil, "", now); s.State != "issuing" {
 		t.Fatalf("live, still staging: %s", s.State)
 	}
@@ -160,3 +170,18 @@ func TestRedactKeepsTokensOutOfDetails(t *testing.T) {
 		t.Fatalf("token in detail: %s", detail)
 	}
 }
+
+func TestLastLine(t *testing.T) {
+	dir := t.TempDir()
+	log := filepath.Join(dir, "issuance.log")
+	os.WriteFile(log, []byte(`{"ts":1793360000.5,"msg":"obtaining certificate","identifier":"*.example.org"}
+{"ts":1793360030.5,"msg":"waiting on internal rate limiter","identifiers":["*.example.org"]}
+{"ts":1793360040.5,"msg":"obtaining certificate","identifier":"*.other.nz"}
+`), 0o644)
+	if got := LastLine(log, "*.example.org"); !strings.HasSuffix(got, " waiting on internal rate limiter") {
+		t.Errorf("LastLine = %q", got)
+	}
+	if got := LastLine(filepath.Join(dir, "none"), "*.example.org"); got != "" {
+		t.Errorf("no log: %q", got)
+	}
+}

admin/internal/server/certificates.go

@@ -37,7 +37,11 @@ func (s *Server) certStatus(ctx context.Context, st *state.State) certs.Status {
 		bad = nil // renewed since: the token works again
 	}
 	s.mu.Unlock()
-	return certs.Compute(st.Settings, obs, ev, bad, st.Settings.Domain, time.Now())
+	status := certs.Compute(st.Settings, obs, ev, bad, st.Settings.Domain, time.Now())
+	if status.State == "failed" && status.Detail == "" && s.IssuanceLog != "" {
+		status.Detail = certs.LastLine(s.IssuanceLog, "*."+st.Settings.Domain)
+	}
+	return status
 }
 
 // WatchToken asks the DNS provider once a day whether the saved token