PrintToVeraeTimeStamp/cmd/verae-print/serve.go

package main

import (
	"bytes"
	"flag"
	"fmt"
	"net/http"
	"os"
	"path/filepath"
	"runtime"
	"strings"
	"time"

	"github.com/OpenPrinting/goipp"

	"github.com/VeraeLLC/PrintToVeraeTimeStamp/internal/auth"
	"github.com/VeraeLLC/PrintToVeraeTimeStamp/internal/job"
	"github.com/VeraeLLC/PrintToVeraeTimeStamp/internal/settings"
	"github.com/VeraeLLC/PrintToVeraeTimeStamp/internal/statuslang"
	"github.com/VeraeLLC/PrintToVeraeTimeStamp/internal/vlog"
	"github.com/VeraeLLC/PrintToVeraeTimeStamp/internal/winprint"
)

func isHelperExe() bool {
	exe, err := os.Executable()
	if err != nil {
		return false
	}
	return strings.Contains(strings.ToLower(filepath.Base(exe)), "printhelper")
}

// fallbackDropDir is the folder the "Verae TimeStamp PDF (Local Port)" queue writes into.
func fallbackDropDir() string {
	if v := os.Getenv("VERAE_FALLBACK_DIR"); v != "" {
		return v
	}
	if runtime.GOOS == "windows" {
		pd := os.Getenv("ProgramData")
		if pd == "" {
			pd = `C:\ProgramData`
		}
		return filepath.Join(pd, "Verae", "spool", "fallback")
	}
	return filepath.Join(os.TempDir(), "verae-fallback")
}

func userWorkDir() string {
	base, err := os.UserCacheDir() // %LOCALAPPDATA% on Windows
	if err != nil {
		base = os.TempDir()
	}
	return filepath.Join(base, "Verae", "PrintStamp", "spool")
}

func runServe(args []string) int {
	fs := flag.NewFlagSet("serve", flag.ExitOnError)
	addr := fs.String("addr", envOr("VERAE_IPP_ADDR", "127.0.0.1:8631"), "IPP listen address")
	noIPP := fs.Bool("no-ipp", false, "disable IPP loopback printer")
	noWatch := fs.Bool("no-watch", false, "disable fallback folder watcher")
	debug := fs.Bool("debug", false, "verbose logging (also VERAE_DEBUG=1)")
	outDir := fs.String("out-dir", "", "output dir (default Documents\\Verae Timestamps)")
	_ = fs.Parse(args)

	cfg, _ := settings.Load()
	vlog.SetDebug(*debug || debugFromRegistry() || cfg.LogLevel == "debug")
	logPath := vlog.Init("helper", !isHelperExe())
	host, _ := os.Hostname()
	home, _ := os.UserHomeDir()
	exe, _ := os.Executable()
	vlog.Printf("==== verae-print helper %s start exe=%q os=%s/%s host=%s home=%q log=%q debug=%v",
		job.HelperVersion, exe, runtime.GOOS, runtime.GOARCH, host, home, logPath, vlog.DebugEnabled())
	logAuthState()

	proc := makeProcessor(*outDir)
	go pendingOnStart()
	errc := make(chan error, 2)
	if !*noIPP {
		serveListenAddr = *addr
		srv := &winprint.IPPServer{
			Addr: *addr, Name: "Verae TimeStamp PDF",
			SpoolDir: filepath.Join(userWorkDir(), "ipp"), Process: proc,
			// PT-W3 tray substitute: GET-only status on the same loopback port as IPP.
			// POST remains pure IPP — Windows print clients are unaffected.
			ExtraHealth: helperExtraHealth,
			ServeQueue:  handleQueueHTTP,
			ServeStatus: handleStatusHTTP,
		}
		go func() { errc <- srv.ListenAndServe() }()
		vlog.Printf("status: queue http://%s/queue · status http://%s/status (GET only; hold id ≠ evidence)", *addr, *addr)
		if n := len(listPending()); n > 0 {
			ht, hb := statuslang.NotifyHeldJobs(n)
			notifyUser(ht, notifyQueueHint(hb))
		}
	}
	if !*noWatch {
		w := &winprint.Watcher{Dir: fallbackDropDir(), WorkDir: filepath.Join(userWorkDir(), "fallback"), Process: proc}
		go w.Run()
	}
	if *noIPP {
		select {}
	}
	err := <-errc
	vlog.Errorf("helper exiting: %v", err)
	fmt.Fprintln(os.Stderr, err)
	return 1
}

func logAuthState() {
	_, xerr := auth.LoadXVeraeToken()
	_, jerr := auth.LoadVeraeJWT()
	vlog.Printf("auth: preferred=%s xVerae-token=%v jwt(auth.properties)=%v", auth.PreferredChannel(), errState(xerr), errState(jerr))
}

func errState(err error) string {
	if err == nil {
		return "present"
	}
	return "missing (" + err.Error() + ")"
}

var processor winprint.Processor

// makeProcessor: IPP/fallback jobs → stamp. Key missing/invalid/expired
// (HTTP 401/403) → the PDF is held in the pending folder, ONE sign-in prompt
// is shown, and all held jobs are retried after a new key is saved.
func makeProcessor(outDir string) winprint.Processor {
	processor = func(j winprint.Job) error {
		lj := vlog.Job(j.ID)
		lj.Printf("process: source=%s title=%q user=%q format=%s bytes=%d path=%q", j.Source, j.Title, j.User, j.Format, j.Bytes, j.Path)
		if !strings.Contains(j.Format, "pdf") && !sniffPDF(j.Path) {
			return fmt.Errorf("received %s (not PDF); raster→PDF conversion is not implemented — file kept at %s. Set VERAE_IPP_FORMATS=application/pdf", j.Format, j.Path)
		}
		target := stampTarget{Title: j.Title, OutDir: outDir}
		if cfg, _ := settings.Load(); cfg.Prompt() {
			p, ok := askSaveTarget(lj, j.Title, outDir)
			if !ok {
				_ = os.Remove(j.Path)
				lj.Printf("process: Save As cancelled by user — job discarded (not stamped, no credit used)")
				return nil
			}
			target.OutPath = p
		}
		res, err := stampFile(j.Path, target, lj)
		if err != nil {
			if isAuthFailure(err) {
				m, herr := holdJob(j.Path, target, j.Source, err, true)
				if herr != nil {
					lj.Errorf("process: could not hold job: %v (PDF left at %s)", herr, j.Path)
					return err
				}
				lj.Printf("process: HELD as pending %s (%v); prompting for sign-in", m.ID, err)
				notifyUser(statuslang.NotifyTitle("held"), notifyQueueHint(statuslang.NotifyBody("held", m.Title, m.ID)))
				go handleAuthFailure(authReason(err), stampFile)
				return nil // the job is safe; IPP reports success to Windows
			}
			if isBillingFailure(err) {
				m, herr := holdJob(j.Path, target, j.Source, err, true)
				if herr != nil {
					lj.Errorf("process: could not hold job: %v (PDF left at %s)", herr, j.Path)
					go offerBillingCheckout(billingReason(err))
					return err
				}
				lj.Printf("process: HELD as pending %s (%v); opening Zap Billing", m.ID, err)
				notifyUser(statuslang.NotifyTitle("billing"), notifyQueueHint(statuslang.NotifyBody("billing", m.Title, m.ID)))
				go handleBillingFailure(billingReason(err))
				return nil // job held; user adds funds then reprint / retry pending
			}
			notifyUser(statuslang.NotifyTitle("failed"), statuslang.NotifyBody("failed", j.Title, err.Error()))
			return err
		}
		_ = os.Remove(j.Path)
		notifyUser(statuslang.NotifyTitle("final"), statuslang.NotifyBody("final", j.Title, res.ReceiptID))
		openOnComplete(lj, res.CertificatePDF)
		// a successful stamp proves the key works: flush anything still pending
		if len(listPending()) > 0 {
			go retryPending(stampFile)
		}
		return nil
	}
	return processor
}

// pendingOnStart retries held jobs at helper start, and whenever a key is saved
// by another process (Start-menu "Setup signing key", installer).
func pendingOnStart() {
	markKeySeen()
	if n := len(listPending()); n > 0 {
		vlog.Printf("pending: %d held job(s) found at start in %s", n, pendingDir())
		if auth.HasXVeraeToken() {
			if _, _, authFail := retryPending(stampFile); !authFail {
				goto watch
			}
		}
		handleAuthFailure("Print jobs from an earlier session are waiting for a valid Verae signing key.", stampFile)
	}
watch:
	for range time.Tick(30 * time.Second) {
		if keyChangedSinceSeen() && len(listPending()) > 0 {
			vlog.Printf("pending: a new key was saved; retrying held jobs")
			retryPending(stampFile)
		}
	}
}

func loggingDo(lj vlog.Job) func(*http.Request) (*http.Response, error) {
	return func(r *http.Request) (*http.Response, error) {
		start := time.Now()
		res, err := http.DefaultClient.Do(r)
		if err != nil {
			lj.Errorf("api: %s %s → error after %s: %v", r.Method, r.URL.Redacted(), time.Since(start).Round(time.Millisecond), err)
			return res, err
		}
		lj.Printf("api: %s %s → HTTP %d in %s", r.Method, r.URL.Redacted(), res.StatusCode, time.Since(start).Round(time.Millisecond))
		return res, nil
	}
}

func sniffPDF(p string) bool {
	f, err := os.Open(p)
	if err != nil {
		return false
	}
	defer f.Close()
	b := make([]byte, 5)
	n, _ := f.Read(b)
	return n == 5 && string(b) == "%PDF-"
}

func safeStem(title string) string {
	t := filepath.Base(strings.ReplaceAll(title, `\`, "/"))
	if ext := filepath.Ext(t); ext != "" && len(ext) <= 5 {
		t = strings.TrimSuffix(t, ext)
	}
	var b strings.Builder
	for _, r := range t {
		switch {
		case r == ' ' || r == '-' || r == '_' || r == '.' || (r >= '0' && r <= '9') || (r >= 'a' && r <= 'z') || (r >= 'A' && r <= 'Z'):
			b.WriteRune(r)
		}
		if b.Len() >= 80 {
			break
		}
	}
	s := strings.TrimSpace(b.String())
	if s == "" {
		s = "document-" + time.Now().Format("20060102-150405")
	}
	return s
}

// runIPPSelftest sends Get-Printer-Attributes + Validate-Job to the helper.
func runIPPSelftest(args []string) int {
	fs := flag.NewFlagSet("ipp-selftest", flag.ExitOnError)
	addr := fs.String("addr", "127.0.0.1:8631", "helper address")
	_ = fs.Parse(args)
	uri := "ipp://" + *addr + "/ipp/print"
	ok := true
	for _, op := range []goipp.Op{goipp.OpGetPrinterAttributes, goipp.OpValidateJob} {
		m := goipp.NewRequest(goipp.DefaultVersion, op, 1)
		m.Operation.Add(goipp.MakeAttribute("attributes-charset", goipp.TagCharset, goipp.String("utf-8")))
		m.Operation.Add(goipp.MakeAttribute("attributes-natural-language", goipp.TagLanguage, goipp.String("en")))
		m.Operation.Add(goipp.MakeAttribute("printer-uri", goipp.TagURI, goipp.String(uri)))
		if op == goipp.OpValidateJob {
			m.Operation.Add(goipp.MakeAttribute("document-format", goipp.TagMimeType, goipp.String("application/pdf")))
		}
		b, _ := m.EncodeBytes()
		res, err := http.Post("http://"+*addr+"/ipp/print", goipp.ContentType, bytes.NewReader(b))
		if err != nil {
			fmt.Printf("FAIL %s: %v\n", op, err)
			return 1
		}
		var out goipp.Message
		err = out.Decode(res.Body)
		res.Body.Close()
		if err != nil {
			fmt.Printf("FAIL %s: decode: %v\n", op, err)
			return 1
		}
		st := goipp.Status(out.Code)
		fmt.Printf("%s → %s (%d printer attrs)\n", op, st, len(out.Printer))
		if st != goipp.StatusOk {
			ok = false
		}
		if op == goipp.OpGetPrinterAttributes {
			for _, a := range out.Printer {
				if a.Name == "document-format-supported" || a.Name == "printer-name" || a.Name == "printer-uri-supported" {
					fmt.Printf("  %s = %s\n", a.Name, a.Values)
				}
			}
		}
	}
	if !ok {
		return 1
	}
	fmt.Println("IPP helper OK:", uri)
	return 0
}