fmsg: implement suspend in writer

This removes the requirement to call fmsg.Exit on every exit path, and enables direct use of the "log" package. However, fmsg.BeforeExit is still encouraged when possible to catch exit on suspended output.

Signed-off-by: Ophestra <cat@gensokyo.uk>

23 files changed, 225 insertions, 242 deletions

diff --git a/internal/app/init/early.go b/internal/app/init/early.go
index cc1c2f7e..ac2fedbf 100644
--- a/internal/app/init/early.go
+++ b/internal/app/init/early.go
@@ -4,7 +4,7 @@ import (
 	"os"
 	"path"
 
-	"git.gensokyo.uk/security/fortify/internal/fmsg"
+	"git.gensokyo.uk/security/fortify/internal"
 )
 
 // used by the parent process
@@ -13,6 +13,6 @@ import (
 func TryArgv0() {
 	if len(os.Args) > 0 && path.Base(os.Args[0]) == "init" {
 		Main()
-		fmsg.Exit(0)
+		internal.Exit(0)
 	}
 }
diff --git a/internal/app/init/main.go b/internal/app/init/main.go
index 4c69312e..bf9ecbae 100644
--- a/internal/app/init/main.go
+++ b/internal/app/init/main.go
@@ -2,6 +2,7 @@ package init0
 
 import (
 	"errors"
+	"log"
 	"os"
 	"os/exec"
 	"os/signal"
@@ -24,17 +25,15 @@ const (
 func Main() {
 	// sharing stdout with shim
 	// USE WITH CAUTION
-	fmsg.SetPrefix("init")
+	fmsg.Prepare("init")
 
 	// setting this prevents ptrace
 	if err := internal.PR_SET_DUMPABLE__SUID_DUMP_DISABLE(); err != nil {
-		fmsg.Fatalf("cannot set SUID_DUMP_DISABLE: %s", err)
-		panic("unreachable")
+		log.Fatalf("cannot set SUID_DUMP_DISABLE: %s", err)
 	}
 
 	if os.Getpid() != 1 {
-		fmsg.Fatal("this process must run as pid 1")
-		panic("unreachable")
+		log.Fatal("this process must run as pid 1")
 	}
 
 	// receive setup payload
@@ -44,30 +43,29 @@ func Main() {
 	)
 	if f, err := proc.Receive(Env, &payload); err != nil {
 		if errors.Is(err, proc.ErrInvalid) {
-			fmsg.Fatal("invalid config descriptor")
+			log.Fatal("invalid config descriptor")
 		}
 		if errors.Is(err, proc.ErrNotSet) {
-			fmsg.Fatal("FORTIFY_INIT not set")
+			log.Fatal("FORTIFY_INIT not set")
 		}
 
-		fmsg.Fatalf("cannot decode init setup payload: %v", err)
-		panic("unreachable")
+		log.Fatalf("cannot decode init setup payload: %v", err)
 	} else {
-		fmsg.SetVerbose(payload.Verbose)
+		fmsg.Store(payload.Verbose)
 		closeSetup = f
 
 		// child does not need to see this
 		if err = os.Unsetenv(Env); err != nil {
-			fmsg.Printf("cannot unset %s: %v", Env, err)
+			log.Printf("cannot unset %s: %v", Env, err)
 			// not fatal
 		} else {
-			fmsg.VPrintln("received configuration")
+			fmsg.Verbose("received configuration")
 		}
 	}
 
 	// die with parent
 	if err := internal.PR_SET_PDEATHSIG__SIGKILL(); err != nil {
-		fmsg.Fatalf("prctl(PR_SET_PDEATHSIG, SIGKILL): %v", err)
+		log.Fatalf("prctl(PR_SET_PDEATHSIG, SIGKILL): %v", err)
 	}
 
 	cmd := exec.Command(payload.Argv0)
@@ -76,13 +74,13 @@ func Main() {
 	cmd.Env = os.Environ()
 
 	if err := cmd.Start(); err != nil {
-		fmsg.Fatalf("cannot start %q: %v", payload.Argv0, err)
+		log.Fatalf("cannot start %q: %v", payload.Argv0, err)
 	}
 	fmsg.Suspend()
 
 	// close setup pipe as setup is now complete
 	if err := closeSetup(); err != nil {
-		fmsg.Println("cannot close setup pipe:", err)
+		log.Println("cannot close setup pipe:", err)
 		// not fatal
 	}
 
@@ -119,7 +117,7 @@ func Main() {
 			}
 		}
 		if !errors.Is(err, syscall.ECHILD) {
-			fmsg.Println("unexpected wait4 response:", err)
+			log.Println("unexpected wait4 response:", err)
 		}
 
 		close(done)
@@ -132,9 +130,12 @@ func Main() {
 	for {
 		select {
 		case s := <-sig:
-			fmsg.VPrintln("received", s.String())
-			fmsg.Resume() // output could still be withheld at this point, so resume is called
-			fmsg.Exit(0)
+			if fmsg.Resume() {
+				fmsg.Verbosef("terminating on %s after process start", s.String())
+			} else {
+				fmsg.Verbosef("terminating on %s", s.String())
+			}
+			internal.Exit(0)
 		case w := <-info:
 			if w.wpid == cmd.Process.Pid {
 				// initial process exited, output is most likely available again
@@ -155,10 +156,10 @@ func Main() {
 				}()
 			}
 		case <-done:
-			fmsg.Exit(r)
+			internal.Exit(r)
 		case <-timeout:
-			fmsg.Println("timeout exceeded waiting for lingering processes")
-			fmsg.Exit(r)
+			log.Println("timeout exceeded waiting for lingering processes")
+			internal.Exit(r)
 		}
 	}
 }
diff --git a/internal/app/seal.go b/internal/app/seal.go
index c78add93..fb3b3ce2 100644
--- a/internal/app/seal.go
+++ b/internal/app/seal.go
@@ -191,7 +191,7 @@ func (a *app) Seal(config *fst.Config) error {
 
 	// map sandbox config to bwrap
 	if config.Confinement.Sandbox == nil {
-		fmsg.VPrintln("sandbox configuration not supplied, PROCEED WITH CAUTION")
+		fmsg.Verbose("sandbox configuration not supplied, PROCEED WITH CAUTION")
 
 		// permissive defaults
 		conf := &fst.SandboxConfig{
@@ -264,7 +264,7 @@ func (a *app) Seal(config *fst.Config) error {
 	}
 
 	// verbose log seal information
-	fmsg.VPrintf("created application seal for uid %s (%s) groups: %v, command: %s",
+	fmsg.Verbosef("created application seal for uid %s (%s) groups: %v, command: %s",
 		seal.sys.user.us, seal.sys.user.username, config.Confinement.Groups, config.Command)
 
 	// seal app and release lock
diff --git a/internal/app/share.go b/internal/app/share.go
index 9e7d0f17..c7f0c7a3 100644
--- a/internal/app/share.go
+++ b/internal/app/share.go
@@ -143,7 +143,7 @@ func (seal *appSeal) setupShares(bus [2]*dbus.Config, os linux.System) error {
 	if seal.et.Has(system.EWayland) {
 		var socketPath string
 		if name, ok := os.LookupEnv(wl.WaylandDisplay); !ok {
-			fmsg.VPrintln(wl.WaylandDisplay + " is not set, assuming " + wl.FallbackName)
+			fmsg.Verbose(wl.WaylandDisplay + " is not set, assuming " + wl.FallbackName)
 			socketPath = path.Join(seal.RuntimePath, wl.FallbackName)
 		} else if !path.IsAbs(name) {
 			socketPath = path.Join(seal.RuntimePath, name)
@@ -166,7 +166,7 @@ func (seal *appSeal) setupShares(bus [2]*dbus.Config, os linux.System) error {
 			seal.sys.Wayland(outerPath, socketPath, appID, seal.id)
 			seal.sys.bwrap.Bind(outerPath, innerPath)
 		} else { // bind mount wayland socket (insecure)
-			fmsg.VPrintln("direct wayland access, PROCEED WITH CAUTION")
+			fmsg.Verbose("direct wayland access, PROCEED WITH CAUTION")
 			seal.sys.bwrap.Bind(socketPath, innerPath)
 
 			// ensure Wayland socket ACL (e.g. `/run/user/%d/wayland-%d`)
@@ -229,7 +229,7 @@ func (seal *appSeal) setupShares(bus [2]*dbus.Config, os linux.System) error {
 		// publish current user's pulse cookie for target user
 		if src, err := discoverPulseCookie(os); err != nil {
 			// not fatal
-			fmsg.VPrintln(strings.TrimSpace(err.(*fmsg.BaseError).Message()))
+			fmsg.Verbose(strings.TrimSpace(err.(*fmsg.BaseError).Message()))
 		} else {
 			dst := path.Join(seal.share, "pulse-cookie")
 			innerDst := fst.Tmp + "/pulse-cookie"
diff --git a/internal/app/shim/main.go b/internal/app/shim/main.go
index 39b7d4f9..7616945f 100644
--- a/internal/app/shim/main.go
+++ b/internal/app/shim/main.go
@@ -3,6 +3,7 @@ package shim
 import (
 	"context"
 	"errors"
+	"log"
 	"os"
 	"os/exec"
 	"os/signal"
@@ -25,12 +26,11 @@ import (
 func Main() {
 	// sharing stdout with fortify
 	// USE WITH CAUTION
-	fmsg.SetPrefix("shim")
+	fmsg.Prepare("shim")
 
 	// setting this prevents ptrace
 	if err := internal.PR_SET_DUMPABLE__SUID_DUMP_DISABLE(); err != nil {
-		fmsg.Fatalf("cannot set SUID_DUMP_DISABLE: %s", err)
-		panic("unreachable")
+		log.Fatalf("cannot set SUID_DUMP_DISABLE: %s", err)
 	}
 
 	// receive setup payload
@@ -40,21 +40,20 @@ func Main() {
 	)
 	if f, err := proc.Receive(Env, &payload); err != nil {
 		if errors.Is(err, proc.ErrInvalid) {
-			fmsg.Fatal("invalid config descriptor")
+			log.Fatal("invalid config descriptor")
 		}
 		if errors.Is(err, proc.ErrNotSet) {
-			fmsg.Fatal("FORTIFY_SHIM not set")
+			log.Fatal("FORTIFY_SHIM not set")
 		}
 
-		fmsg.Fatalf("cannot decode shim setup payload: %v", err)
-		panic("unreachable")
+		log.Fatalf("cannot decode shim setup payload: %v", err)
 	} else {
-		fmsg.SetVerbose(payload.Verbose)
+		fmsg.Store(payload.Verbose)
 		closeSetup = f
 	}
 
 	if payload.Bwrap == nil {
-		fmsg.Fatal("bwrap config not supplied")
+		log.Fatal("bwrap config not supplied")
 	}
 
 	// restore bwrap sync fd
@@ -65,7 +64,7 @@ func Main() {
 
 	// close setup socket
 	if err := closeSetup(); err != nil {
-		fmsg.Println("cannot close setup pipe:", err)
+		log.Println("cannot close setup pipe:", err)
 		// not fatal
 	}
 
@@ -73,15 +72,15 @@ func Main() {
 	if s, err := os.Stat(payload.Home); err != nil {
 		if os.IsNotExist(err) {
 			if err = os.Mkdir(payload.Home, 0700); err != nil {
-				fmsg.Fatalf("cannot create home directory: %v", err)
+				log.Fatalf("cannot create home directory: %v", err)
 			}
 		} else {
-			fmsg.Fatalf("cannot access home directory: %v", err)
+			log.Fatalf("cannot access home directory: %v", err)
 		}
 
 		// home directory is created, proceed
 	} else if !s.IsDir() {
-		fmsg.Fatalf("data path %q is not a directory", payload.Home)
+		log.Fatalf("data path %q is not a directory", payload.Home)
 	}
 
 	var ic init0.Payload
@@ -95,10 +94,10 @@ func Main() {
 		// no argv, look up shell instead
 		var ok bool
 		if payload.Bwrap.SetEnv == nil {
-			fmsg.Fatal("no command was specified and environment is unset")
+			log.Fatal("no command was specified and environment is unset")
 		}
 		if ic.Argv0, ok = payload.Bwrap.SetEnv["SHELL"]; !ok {
-			fmsg.Fatal("no command was specified and $SHELL was unset")
+			log.Fatal("no command was specified and $SHELL was unset")
 		}
 
 		ic.Argv = []string{ic.Argv0}
@@ -110,20 +109,20 @@ func Main() {
 
 	// serve setup payload
 	if fd, encoder, err := proc.Setup(&extraFiles); err != nil {
-		fmsg.Fatalf("cannot pipe: %v", err)
+		log.Fatalf("cannot pipe: %v", err)
 	} else {
 		conf.SetEnv[init0.Env] = strconv.Itoa(fd)
 		go func() {
-			fmsg.VPrintln("transmitting config to init")
+			fmsg.Verbose("transmitting config to init")
 			if err = encoder.Encode(&ic); err != nil {
-				fmsg.Fatalf("cannot transmit init config: %v", err)
+				log.Fatalf("cannot transmit init config: %v", err)
 			}
 		}()
 	}
 
 	helper.BubblewrapName = payload.Exec[0] // resolved bwrap path by parent
-	if fmsg.Verbose() {
-		seccomp.CPrintln = fmsg.Println
+	if fmsg.Load() {
+		seccomp.CPrintln = log.Println
 	}
 	if b, err := helper.NewBwrap(
 		conf, path.Join(fst.Tmp, "sbin/init"),
@@ -131,7 +130,7 @@ func Main() {
 		extraFiles,
 		syncFd,
 	); err != nil {
-		fmsg.Fatalf("malformed sandbox config: %v", err)
+		log.Fatalf("malformed sandbox config: %v", err)
 	} else {
 		b.Stdin(os.Stdin).Stdout(os.Stdout).Stderr(os.Stderr)
 		ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM)
@@ -139,15 +138,15 @@ func Main() {
 
 		// run and pass through exit code
 		if err = b.Start(ctx, false); err != nil {
-			fmsg.Fatalf("cannot start target process: %v", err)
+			log.Fatalf("cannot start target process: %v", err)
 		} else if err = b.Wait(); err != nil {
 			var exitError *exec.ExitError
 			if !errors.As(err, &exitError) {
-				fmsg.Println("wait:", err)
-				fmsg.Exit(127)
+				log.Printf("wait: %v", err)
+				internal.Exit(127)
 				panic("unreachable")
 			}
-			fmsg.Exit(exitError.ExitCode())
+			internal.Exit(exitError.ExitCode())
 			panic("unreachable")
 		}
 	}
diff --git a/internal/app/shim/manager.go b/internal/app/shim/manager.go
index 106e4865..c4605635 100644
--- a/internal/app/shim/manager.go
+++ b/internal/app/shim/manager.go
@@ -4,6 +4,7 @@ import (
 	"context"
 	"encoding/gob"
 	"errors"
+	"log"
 	"os"
 	"os/exec"
 	"strconv"
@@ -54,8 +55,7 @@ func (s *Shim) Start(
 	// prepare user switcher invocation
 	var fsu string
 	if p, ok := internal.Path(internal.Fsu); !ok {
-		fmsg.Fatal("invalid fsu path, this copy of fortify is not compiled correctly")
-		panic("unreachable")
+		log.Fatal("invalid fsu path, this copy of fortify is not compiled correctly")
 	} else {
 		fsu = p
 	}
@@ -75,7 +75,7 @@ func (s *Shim) Start(
 
 	// format fsu supplementary groups
 	if len(supp) > 0 {
-		fmsg.VPrintf("attaching supplementary group ids %s", supp)
+		fmsg.Verbosef("attaching supplementary group ids %s", supp)
 		s.cmd.Env = append(s.cmd.Env, "FORTIFY_GROUPS="+strings.Join(supp, " "))
 	}
 	s.cmd.Stdin, s.cmd.Stdout, s.cmd.Stderr = os.Stdin, os.Stdout, os.Stderr
@@ -87,7 +87,7 @@ func (s *Shim) Start(
 		s.sync = &fd
 	}
 
-	fmsg.VPrintln("starting shim via fsu:", s.cmd)
+	fmsg.Verbose("starting shim via fsu:", s.cmd)
 	// withhold messages to stderr
 	fmsg.Suspend()
 	if err := s.cmd.Start(); err != nil {
diff --git a/internal/app/start.go b/internal/app/start.go
index 171e707e..467735e1 100644
--- a/internal/app/start.go
+++ b/internal/app/start.go
@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"log"
 	"os/exec"
 	"path/filepath"
 	"strings"
@@ -81,7 +82,7 @@ func (a *app) Run(ctx context.Context, rs *RunState) error {
 			Bwrap: a.seal.sys.bwrap,
 			Home:  a.seal.sys.user.data,
 
-			Verbose: fmsg.Verbose(),
+			Verbose: fmsg.Load(),
 		}); err != nil {
 			return err
 		}
@@ -119,8 +120,8 @@ func (a *app) Run(ctx context.Context, rs *RunState) error {
 		} else {
 			rs.ExitCode = a.shim.Unwrap().ProcessState.ExitCode()
 		}
-		if fmsg.Verbose() {
-			fmsg.VPrintf("process %d exited with exit code %d", a.shim.Unwrap().Process.Pid, rs.ExitCode)
+		if fmsg.Load() {
+			fmsg.Verbosef("process %d exited with exit code %d", a.shim.Unwrap().Process.Pid, rs.ExitCode)
 		}
 
 	// this is reached when a fault makes an already running shim impossible to continue execution
@@ -128,11 +129,11 @@ func (a *app) Run(ctx context.Context, rs *RunState) error {
 	// the effects of this is similar to the alternative exit path and ensures shim death
 	case err := <-a.shim.WaitFallback():
 		rs.ExitCode = 255
-		fmsg.Printf("cannot terminate shim on faulted setup: %v", err)
+		log.Printf("cannot terminate shim on faulted setup: %v", err)
 
 	// alternative exit path relying on shim behaviour on monitor process exit
 	case <-ctx.Done():
-		fmsg.VPrintln("alternative exit path selected")
+		fmsg.Verbose("alternative exit path selected")
 	}
 
 	// child process exited, resume output
@@ -163,10 +164,10 @@ func (a *app) Run(ctx context.Context, rs *RunState) error {
 			} else {
 				if l := len(states); l == 0 {
 					// cleanup globals as the final launcher
-					fmsg.VPrintln("no other launchers active, will clean up globals")
+					fmsg.Verbose("no other launchers active, will clean up globals")
 					ec.Set(system.User)
 				} else {
-					fmsg.VPrintf("found %d active launchers, cleaning up without globals", l)
+					fmsg.Verbosef("found %d active launchers, cleaning up without globals", l)
 				}
 
 				// accumulate capabilities of other launchers
@@ -174,7 +175,7 @@ func (a *app) Run(ctx context.Context, rs *RunState) error {
 					if s.Config != nil {
 						*rt |= s.Config.Confinement.Enablements
 					} else {
-						fmsg.Printf("state entry %d does not contain config", i)
+						log.Printf("state entry %d does not contain config", i)
 					}
 				}
 			}
@@ -184,7 +185,7 @@ func (a *app) Run(ctx context.Context, rs *RunState) error {
 					ec.Set(i)
 				}
 			}
-			if fmsg.Verbose() {
+			if fmsg.Load() {
 				labels := make([]string, 0, system.ELen+1)
 				for i := system.Enablement(0); i < system.Enablement(system.ELen+2); i++ {
 					if ec.Has(i) {
@@ -192,7 +193,7 @@ func (a *app) Run(ctx context.Context, rs *RunState) error {
 					}
 				}
 				if len(labels) > 0 {
-					fmsg.VPrintln("reverting operations labelled", strings.Join(labels, ", "))
+					fmsg.Verbose("reverting operations labelled", strings.Join(labels, ", "))
 				}
 			}
 
diff --git a/internal/executable.go b/internal/executable.go
new file mode 100644
index 00000000..86ffab96
--- /dev/null
+++ b/internal/executable.go
@@ -0,0 +1,25 @@
+package internal
+
+import (
+	"log"
+	"os"
+	"sync"
+)
+
+var (
+	executable     string
+	executableOnce sync.Once
+)
+
+func copyExecutable() {
+	if name, err := os.Executable(); err != nil {
+		log.Fatalf("cannot read executable path: %v", err)
+	} else {
+		executable = name
+	}
+}
+
+func MustExecutable() string {
+	executableOnce.Do(copyExecutable)
+	return executable
+}
diff --git a/internal/exit.go b/internal/exit.go
new file mode 100644
index 00000000..67819436
--- /dev/null
+++ b/internal/exit.go
@@ -0,0 +1,9 @@
+package internal
+
+import (
+	"os"
+
+	"git.gensokyo.uk/security/fortify/internal/fmsg"
+)
+
+func Exit(code int) { fmsg.BeforeExit(); os.Exit(code) }
diff --git a/internal/fmsg/defer.go b/internal/fmsg/defer.go
deleted file mode 100644
index 677f5ceb..00000000
--- a/internal/fmsg/defer.go
+++ /dev/null
@@ -1,98 +0,0 @@
-package fmsg
-
-import (
-	"os"
-	"sync"
-	"sync/atomic"
-)
-
-var (
-	wstate   atomic.Bool
-	dropped  atomic.Uint64
-	withhold = make(chan struct{}, 1)
-	msgbuf   = make(chan dOp, 64) // these ops are tiny so a large buffer is allocated for withholding output
-
-	dequeueOnce sync.Once
-	queueSync   sync.WaitGroup
-)
-
-func dequeue() {
-	go func() {
-		for {
-			select {
-			case op := <-msgbuf:
-				op.Do()
-				queueSync.Done()
-			case <-withhold:
-				<-withhold
-			}
-		}
-	}()
-}
-
-// queue submits ops to msgbuf but drops messages
-// when the buffer is full and dequeue is withholding
-func queue(op dOp) {
-	queueSync.Add(1)
-
-	select {
-	case msgbuf <- op:
-	default:
-		// send the op anyway if not withholding
-		// as dequeue will get to it eventually
-		if !wstate.Load() {
-			msgbuf <- op
-		} else {
-			queueSync.Done()
-			// increment dropped message count
-			dropped.Add(1)
-		}
-	}
-}
-
-type dOp interface{ Do() }
-
-func Exit(code int) {
-	Resume() // resume here to avoid deadlock
-	queueSync.Wait()
-	os.Exit(code)
-}
-
-func Suspend() {
-	dequeueOnce.Do(dequeue)
-	if wstate.CompareAndSwap(false, true) {
-		queueSync.Wait()
-		withhold <- struct{}{}
-	}
-}
-
-func Resume() {
-	dequeueOnce.Do(dequeue)
-	if wstate.CompareAndSwap(true, false) {
-		withhold <- struct{}{}
-		if d := dropped.Swap(0); d != 0 {
-			Printf("dropped %d messages during withhold", d)
-		}
-	}
-}
-
-type dPrint []any
-
-func (v dPrint) Do() {
-	std.Print(v...)
-}
-
-type dPrintf struct {
-	format string
-	v      []any
-}
-
-func (d *dPrintf) Do() {
-	std.Printf(d.format, d.v...)
-}
-
-type dPrintln []any
-
-func (v dPrintln) Do() {
-	std.Println(v...)
-}
diff --git a/internal/fmsg/fmsg.go b/internal/fmsg/fmsg.go
index d4027204..48538380 100644
--- a/internal/fmsg/fmsg.go
+++ b/internal/fmsg/fmsg.go
@@ -2,39 +2,85 @@
 package fmsg
 
 import (
+	"bytes"
+	"io"
 	"log"
 	"os"
+	"sync"
+	"sync/atomic"
+	"syscall"
 )
 
-var std = log.New(os.Stderr, "fortify: ", 0)
+const (
+	bufSize    = 4 * 1024
+	bufSizeMax = 16 * 1024 * 1024
+)
 
-func SetPrefix(prefix string) {
-	prefix += ": "
-	std.SetPrefix(prefix)
-	std.SetPrefix(prefix)
-}
+var o = &suspendable{w: os.Stderr}
+
+// Prepare configures the system logger for [Suspend] and [Resume] to take effect.
+func Prepare(prefix string) { log.SetPrefix(prefix + ": "); log.SetFlags(0); log.SetOutput(o) }
+
+type suspendable struct {
+	w io.Writer
+	s atomic.Bool
 
-func Print(v ...any) {
-	dequeueOnce.Do(dequeue)
-	queue(dPrint(v))
+	buf     bytes.Buffer
+	bufOnce sync.Once
+	bufMu   sync.Mutex
+	dropped int
 }
 
-func Printf(format string, v ...any) {
-	dequeueOnce.Do(dequeue)
-	queue(&dPrintf{format, v})
+func (s *suspendable) Write(p []byte) (n int, err error) {
+	if !s.s.Load() {
+		return s.w.Write(p)
+	}
+	s.bufOnce.Do(func() { s.prepareBuf() })
+
+	s.bufMu.Lock()
+	defer s.bufMu.Unlock()
+
+	if l := len(p); s.buf.Len()+l > bufSizeMax {
+		s.dropped += l
+		return 0, syscall.ENOMEM
+	}
+	return s.buf.Write(p)
 }
 
-func Println(v ...any) {
-	dequeueOnce.Do(dequeue)
-	queue(dPrintln(v))
+func (s *suspendable) prepareBuf()   { s.buf.Grow(bufSize) }
+func (s *suspendable) Suspend() bool { return o.s.CompareAndSwap(false, true) }
+func (s *suspendable) Resume() (resumed bool, dropped uintptr, n int64, err error) {
+	if o.s.CompareAndSwap(true, false) {
+		o.bufMu.Lock()
+		defer o.bufMu.Unlock()
+
+		resumed = true
+		dropped = uintptr(o.dropped)
+
+		o.dropped = 0
+		n, err = io.Copy(s.w, &s.buf)
+		s.buf = bytes.Buffer{}
+		s.prepareBuf()
+	}
+	return
 }
 
-func Fatal(v ...any) {
-	Print(v...)
-	Exit(1)
+func Suspend() bool { return o.Suspend() }
+func Resume() bool {
+	resumed, dropped, _, err := o.Resume()
+	if err != nil {
+		// probably going to result in an error as well,
+		// so this call is as good as unreachable
+		log.Printf("cannot dump buffer on resume: %v", err)
+	}
+	if resumed && dropped > 0 {
+		log.Fatalf("dropped %d bytes while output is suspended", dropped)
+	}
+	return resumed
 }
 
-func Fatalf(format string, v ...any) {
-	Printf(format, v...)
-	Exit(1)
+func BeforeExit() {
+	if Resume() {
+		log.Printf("beforeExit reached on suspended output")
+	}
 }
diff --git a/internal/fmsg/verbose.go b/internal/fmsg/verbose.go
index 72a92a69..a8e4c81f 100644
--- a/internal/fmsg/verbose.go
+++ b/internal/fmsg/verbose.go
@@ -1,25 +1,23 @@
 package fmsg
 
-import "sync/atomic"
+import (
+	"log"
+	"sync/atomic"
+)
 
 var verbose = new(atomic.Bool)
 
-func Verbose() bool {
-	return verbose.Load()
-}
-
-func SetVerbose(v bool) {
-	verbose.Store(v)
-}
+func Load() bool   { return verbose.Load() }
+func Store(v bool) { verbose.Store(v) }
 
-func VPrintf(format string, v ...any) {
+func Verbosef(format string, v ...any) {
 	if verbose.Load() {
-		Printf(format, v...)
+		log.Printf(format, v...)
 	}
 }
 
-func VPrintln(v ...any) {
+func Verbose(v ...any) {
 	if verbose.Load() {
-		Println(v...)
+		log.Println(v...)
 	}
 }
diff --git a/internal/linux/interface.go b/internal/linux/interface.go
index 68129363..cf25ecb1 100644
--- a/internal/linux/interface.go
+++ b/internal/linux/interface.go
@@ -54,7 +54,7 @@ type Paths struct {
 func CopyPaths(os System, v *Paths) {
 	v.SharePath = path.Join(os.TempDir(), "fortify."+strconv.Itoa(os.Geteuid()))
 
-	fmsg.VPrintf("process share directory at %q", v.SharePath)
+	fmsg.Verbosef("process share directory at %q", v.SharePath)
 
 	if r, ok := os.LookupEnv(xdgRuntimeDir); !ok || r == "" || !path.IsAbs(r) {
 		// fall back to path in share since fortify has no hard XDG dependency
@@ -65,5 +65,5 @@ func CopyPaths(os System, v *Paths) {
 		v.RunDirPath = path.Join(v.RuntimePath, "fortify")
 	}
 
-	fmsg.VPrintf("runtime directory at %q", v.RunDirPath)
+	fmsg.Verbosef("runtime directory at %q", v.RunDirPath)
 }
diff --git a/internal/linux/std.go b/internal/linux/std.go
index 1434f1be..4850cf94 100644
--- a/internal/linux/std.go
+++ b/internal/linux/std.go
@@ -3,6 +3,7 @@ package linux
 import (
 	"errors"
 	"io/fs"
+	"log"
 	"os"
 	"os/exec"
 	"os/user"
@@ -11,9 +12,7 @@ import (
 	"sync"
 	"syscall"
 
-	"git.gensokyo.uk/security/fortify/helper/proc"
 	"git.gensokyo.uk/security/fortify/internal"
-	"git.gensokyo.uk/security/fortify/internal/fmsg"
 )
 
 // Std implements System using the standard library.
@@ -33,13 +32,13 @@ func (s *Std) Geteuid() int                                 { return os.Geteuid(
 func (s *Std) LookupEnv(key string) (string, bool)          { return os.LookupEnv(key) }
 func (s *Std) TempDir() string                              { return os.TempDir() }
 func (s *Std) LookPath(file string) (string, error)         { return exec.LookPath(file) }
-func (s *Std) MustExecutable() string                       { return proc.MustExecutable() }
+func (s *Std) MustExecutable() string                       { return internal.MustExecutable() }
 func (s *Std) LookupGroup(name string) (*user.Group, error) { return user.LookupGroup(name) }
 func (s *Std) ReadDir(name string) ([]os.DirEntry, error)   { return os.ReadDir(name) }
 func (s *Std) Stat(name string) (fs.FileInfo, error)        { return os.Stat(name) }
 func (s *Std) Open(name string) (fs.File, error)            { return os.Open(name) }
 func (s *Std) EvalSymlinks(path string) (string, error)     { return filepath.EvalSymlinks(path) }
-func (s *Std) Exit(code int)                                { fmsg.Exit(code) }
+func (s *Std) Exit(code int)                                { internal.Exit(code) }
 
 const xdgRuntimeDir = "XDG_RUNTIME_DIR"
 
@@ -74,8 +73,9 @@ func (s *Std) Uid(aid int) (int, error) {
 
 	u.uid = -1
 	if fsu, ok := internal.Check(internal.Fsu); !ok {
-		fmsg.Fatal("invalid fsu path, this copy of fortify is not compiled correctly")
-		panic("unreachable")
+		log.Fatal("invalid fsu path, this copy of fortify is not compiled correctly")
+		// unreachable
+		return 0, syscall.EBADE
 	} else {
 		cmd := exec.Command(fsu)
 		cmd.Path = fsu
diff --git a/internal/state/multi.go b/internal/state/multi.go
index bb3764f6..ee43ccf3 100644
--- a/internal/state/multi.go
+++ b/internal/state/multi.go
@@ -85,17 +85,17 @@ func (s *multiStore) List() ([]int, error) {
 	for _, e := range entries {
 		// skip non-directories
 		if !e.IsDir() {
-			fmsg.VPrintf("skipped non-directory entry %q", e.Name())
+			fmsg.Verbosef("skipped non-directory entry %q", e.Name())
 			continue
 		}
 
 		// skip non-numerical names
 		if v, err := strconv.Atoi(e.Name()); err != nil {
-			fmsg.VPrintf("skipped non-aid entry %q", e.Name())
+			fmsg.Verbosef("skipped non-aid entry %q", e.Name())
 			continue
 		} else {
 			if v < 0 || v > 9999 {
-				fmsg.VPrintf("skipped out of bounds entry %q", e.Name())
+				fmsg.Verbosef("skipped out of bounds entry %q", e.Name())
 				continue
 			}
 
diff --git a/internal/system/acl.go b/internal/system/acl.go
index 935bee4e..e6e6e370 100644
--- a/internal/system/acl.go
+++ b/internal/system/acl.go
@@ -36,18 +36,18 @@ func (a *ACL) Type() Enablement {
 }
 
 func (a *ACL) apply(sys *I) error {
-	fmsg.VPrintln("applying ACL", a)
+	fmsg.Verbose("applying ACL", a)
 	return fmsg.WrapErrorSuffix(acl.UpdatePerm(a.path, sys.uid, a.perms...),
 		fmt.Sprintf("cannot apply ACL entry to %q:", a.path))
 }
 
 func (a *ACL) revert(sys *I, ec *Criteria) error {
 	if ec.hasType(a) {
-		fmsg.VPrintln("stripping ACL", a)
+		fmsg.Verbose("stripping ACL", a)
 		return fmsg.WrapErrorSuffix(acl.UpdatePerm(a.path, sys.uid),
 			fmt.Sprintf("cannot strip ACL entry from %q:", a.path))
 	} else {
-		fmsg.VPrintln("skipping ACL", a)
+		fmsg.Verbose("skipping ACL", a)
 		return nil
 	}
 }
diff --git a/internal/system/dbus.go b/internal/system/dbus.go
index fd995bb0..f52adf15 100644
--- a/internal/system/dbus.go
+++ b/internal/system/dbus.go
@@ -3,6 +3,7 @@ package system
 import (
 	"bytes"
 	"errors"
+	"log"
 	"strings"
 	"sync"
 
@@ -47,12 +48,12 @@ func (sys *I) ProxyDBus(session, system *dbus.Config, sessionPath, systemPath st
 	d.proxy = dbus.New(sessionBus, systemBus)
 
 	defer func() {
-		if fmsg.Verbose() && d.proxy.Sealed() {
-			fmsg.VPrintln("sealed session proxy", session.Args(sessionBus))
+		if fmsg.Load() && d.proxy.Sealed() {
+			fmsg.Verbose("sealed session proxy", session.Args(sessionBus))
 			if system != nil {
-				fmsg.VPrintln("sealed system proxy", system.Args(systemBus))
+				fmsg.Verbose("sealed system proxy", system.Args(systemBus))
 			}
-			fmsg.VPrintln("message bus proxy final args:", d.proxy)
+			fmsg.Verbose("message bus proxy final args:", d.proxy)
 		}
 	}()
 
@@ -78,9 +79,9 @@ func (d *DBus) Type() Enablement {
 }
 
 func (d *DBus) apply(sys *I) error {
-	fmsg.VPrintf("session bus proxy on %q for upstream %q", d.proxy.Session()[1], d.proxy.Session()[0])
+	fmsg.Verbosef("session bus proxy on %q for upstream %q", d.proxy.Session()[1], d.proxy.Session()[0])
 	if d.system {
-		fmsg.VPrintf("system bus proxy on %q for upstream %q", d.proxy.System()[1], d.proxy.System()[0])
+		fmsg.Verbosef("system bus proxy on %q for upstream %q", d.proxy.System()[1], d.proxy.System()[0])
 	}
 
 	// this starts the process and blocks until ready
@@ -89,15 +90,15 @@ func (d *DBus) apply(sys *I) error {
 		return fmsg.WrapErrorSuffix(err,
 			"cannot start message bus proxy:")
 	}
-	fmsg.VPrintln("starting message bus proxy:", d.proxy)
+	fmsg.Verbose("starting message bus proxy:", d.proxy)
 	return nil
 }
 
 func (d *DBus) revert(_ *I, _ *Criteria) error {
 	// criteria ignored here since dbus is always process-scoped
-	fmsg.VPrintln("terminating message bus proxy")
+	fmsg.Verbose("terminating message bus proxy")
 	d.proxy.Close()
-	defer fmsg.VPrintln("message bus proxy exit")
+	defer fmsg.Verbose("message bus proxy exit")
 	return fmsg.WrapErrorSuffix(d.proxy.Wait(), "message bus proxy error:")
 }
 
@@ -144,7 +145,7 @@ func (s *scanToFmsg) write(p []byte, a int) (int, error) {
 func (s *scanToFmsg) Dump() {
 	s.mu.RLock()
 	for _, msg := range s.msgbuf {
-		fmsg.Println(msg)
+		log.Println(msg)
 	}
 	s.mu.RUnlock()
 }
diff --git a/internal/system/link.go b/internal/system/link.go
index cbde3a1f..7e690c78 100644
--- a/internal/system/link.go
+++ b/internal/system/link.go
@@ -28,18 +28,18 @@ type Hardlink struct {
 func (l *Hardlink) Type() Enablement { return l.et }
 
 func (l *Hardlink) apply(_ *I) error {
-	fmsg.VPrintln("linking ", l)
+	fmsg.Verbose("linking ", l)
 	return fmsg.WrapErrorSuffix(os.Link(l.src, l.dst),
 		fmt.Sprintf("cannot link %q:", l.dst))
 }
 
 func (l *Hardlink) revert(_ *I, ec *Criteria) error {
 	if ec.hasType(l) {
-		fmsg.VPrintf("removing hard link %q", l.dst)
+		fmsg.Verbosef("removing hard link %q", l.dst)
 		return fmsg.WrapErrorSuffix(os.Remove(l.dst),
 			fmt.Sprintf("cannot remove hard link %q:", l.dst))
 	} else {
-		fmsg.VPrintf("skipping hard link %q", l.dst)
+		fmsg.Verbosef("skipping hard link %q", l.dst)
 		return nil
 	}
 }
diff --git a/internal/system/mkdir.go b/internal/system/mkdir.go
index b634da45..855b339d 100644
--- a/internal/system/mkdir.go
+++ b/internal/system/mkdir.go
@@ -40,7 +40,7 @@ func (m *Mkdir) Type() Enablement {
 }
 
 func (m *Mkdir) apply(_ *I) error {
-	fmsg.VPrintln("ensuring directory", m)
+	fmsg.Verbose("ensuring directory", m)
 
 	// create directory
 	err := os.Mkdir(m.path, m.perm)
@@ -61,11 +61,11 @@ func (m *Mkdir) revert(_ *I, ec *Criteria) error {
 	}
 
 	if ec.hasType(m) {
-		fmsg.VPrintln("destroying ephemeral directory", m)
+		fmsg.Verbose("destroying ephemeral directory", m)
 		return fmsg.WrapErrorSuffix(os.Remove(m.path),
 			fmt.Sprintf("cannot remove ephemeral directory %q:", m.path))
 	} else {
-		fmsg.VPrintln("skipping ephemeral directory", m)
+		fmsg.Verbose("skipping ephemeral directory", m)
 		return nil
 	}
 }
diff --git a/internal/system/op.go b/internal/system/op.go
index 8a98fa78..08b57946 100644
--- a/internal/system/op.go
+++ b/internal/system/op.go
@@ -3,6 +3,7 @@ package system
 import (
 	"context"
 	"errors"
+	"log"
 	"os"
 	"sync"
 
@@ -105,9 +106,9 @@ func (sys *I) Commit(ctx context.Context) error {
 		// sp is set to nil when all ops are applied
 		if sp != nil {
 			// rollback partial commit
-			fmsg.VPrintf("commit faulted after %d ops, rolling back partial commit", len(sp.ops))
+			fmsg.Verbosef("commit faulted after %d ops, rolling back partial commit", len(sp.ops))
 			if err := sp.Revert(&Criteria{nil}); err != nil {
-				fmsg.Println("errors returned reverting partial commit:", err)
+				log.Println("errors returned reverting partial commit:", err)
 			}
 		}
 	}()
diff --git a/internal/system/tmpfiles.go b/internal/system/tmpfiles.go
index 7dff7c2d..8208e030 100644
--- a/internal/system/tmpfiles.go
+++ b/internal/system/tmpfiles.go
@@ -44,7 +44,7 @@ func (t *Tmpfile) Type() Enablement {
 func (t *Tmpfile) apply(_ *I) error {
 	switch t.method {
 	case tmpfileCopy:
-		fmsg.VPrintln("publishing tmpfile", t)
+		fmsg.Verbose("publishing tmpfile", t)
 		return fmsg.WrapErrorSuffix(copyFile(t.dst, t.src),
 			fmt.Sprintf("cannot copy tmpfile %q:", t.dst))
 	default:
@@ -54,11 +54,11 @@ func (t *Tmpfile) apply(_ *I) error {
 
 func (t *Tmpfile) revert(_ *I, ec *Criteria) error {
 	if ec.hasType(t) {
-		fmsg.VPrintf("removing tmpfile %q", t.dst)
+		fmsg.Verbosef("removing tmpfile %q", t.dst)
 		return fmsg.WrapErrorSuffix(os.Remove(t.dst),
 			fmt.Sprintf("cannot remove tmpfile %q:", t.dst))
 	} else {
-		fmsg.VPrintf("skipping tmpfile %q", t.dst)
+		fmsg.Verbosef("skipping tmpfile %q", t.dst)
 		return nil
 	}
 }
diff --git a/internal/system/wayland.go b/internal/system/wayland.go
index 9646b467..ac3634ae 100644
--- a/internal/system/wayland.go
+++ b/internal/system/wayland.go
@@ -45,7 +45,7 @@ func (w Wayland) apply(sys *I) error {
 		return fmsg.WrapErrorSuffix(err,
 			fmt.Sprintf("cannot attach to wayland on %q:", w.pair[1]))
 	} else {
-		fmsg.VPrintf("wayland attached on %q", w.pair[1])
+		fmsg.Verbosef("wayland attached on %q", w.pair[1])
 	}
 
 	if sp, err := w.conn.Bind(w.pair[0], w.appID, w.instanceID); err != nil {
@@ -53,7 +53,7 @@ func (w Wayland) apply(sys *I) error {
 			fmt.Sprintf("cannot bind to socket on %q:", w.pair[0]))
 	} else {
 		sys.sp = sp
-		fmsg.VPrintf("wayland listening on %q", w.pair[0])
+		fmsg.Verbosef("wayland listening on %q", w.pair[0])
 		return fmsg.WrapErrorSuffix(errors.Join(os.Chmod(w.pair[0], 0), acl.UpdatePerm(w.pair[0], sys.uid, acl.Read, acl.Write, acl.Execute)),
 			fmt.Sprintf("cannot chmod socket on %q:", w.pair[0]))
 	}
@@ -61,16 +61,16 @@ func (w Wayland) apply(sys *I) error {
 
 func (w Wayland) revert(_ *I, ec *Criteria) error {
 	if ec.hasType(w) {
-		fmsg.VPrintf("removing wayland socket on %q", w.pair[0])
+		fmsg.Verbosef("removing wayland socket on %q", w.pair[0])
 		if err := os.Remove(w.pair[0]); err != nil && !errors.Is(err, os.ErrNotExist) {
 			return err
 		}
 
-		fmsg.VPrintf("detaching from wayland on %q", w.pair[1])
+		fmsg.Verbosef("detaching from wayland on %q", w.pair[1])
 		return fmsg.WrapErrorSuffix(w.conn.Close(),
 			fmt.Sprintf("cannot detach from wayland on %q:", w.pair[1]))
 	} else {
-		fmsg.VPrintf("skipping wayland cleanup on %q", w.pair[0])
+		fmsg.Verbosef("skipping wayland cleanup on %q", w.pair[0])
 		return nil
 	}
 }
diff --git a/internal/system/xhost.go b/internal/system/xhost.go
index 57168b81..89e63db5 100644
--- a/internal/system/xhost.go
+++ b/internal/system/xhost.go
@@ -24,18 +24,18 @@ func (x XHost) Type() Enablement {
 }
 
 func (x XHost) apply(_ *I) error {
-	fmsg.VPrintf("inserting entry %s to X11", x)
+	fmsg.Verbosef("inserting entry %s to X11", x)
 	return fmsg.WrapErrorSuffix(xcb.ChangeHosts(xcb.HostModeInsert, xcb.FamilyServerInterpreted, "localuser\x00"+string(x)),
 		fmt.Sprintf("cannot insert entry %s to X11:", x))
 }
 
 func (x XHost) revert(_ *I, ec *Criteria) error {
 	if ec.hasType(x) {
-		fmsg.VPrintf("deleting entry %s from X11", x)
+		fmsg.Verbosef("deleting entry %s from X11", x)
 		return fmsg.WrapErrorSuffix(xcb.ChangeHosts(xcb.HostModeDelete, xcb.FamilyServerInterpreted, "localuser\x00"+string(x)),
 			fmt.Sprintf("cannot delete entry %s from X11:", x))
 	} else {
-		fmsg.VPrintf("skipping entry %s in X11", x)
+		fmsg.Verbosef("skipping entry %s in X11", x)
 		return nil
 	}
 }