README.md

@@ -50,6 +50,10 @@ Two variables set the default addresses. `--help` shows each value and where it  Add `?log` to a path for its git history, newest first: one line per commit, which opens to the full message and the diff. A tracked directory's listing opens it from its first entry, `<(git log)`, and a tracked doc or code page from a line at its top that names its last commit. A commit's hash opens its diff for that path, with a link to all its files. Shares show it without trailers, and only when other users could read the repo. See [doc/history.md](doc/history.md). +## Log++mdserve logs every run, server event and page request to the systemd journal: `journalctl --user -t mdserve`. Without a journal it writes `~/.local/state/mdserve/log`. See [doc/log.md](doc/log.md).+ ## Install  mdserve needs pandoc 2.15 or later and git.

doc/log.md

new file mode 100644@@ -0,0 +1,25 @@+# Log++mdserve logs every action, always. There is no flag and no level to set, because a filter set before a mistake drops the entry that would explain it.++Entries go to the systemd journal, tagged `mdserve`:++```+journalctl --user -t mdserve --since -1h+journalctl --user -t mdserve MDSERVE_ENDPOINT=127.31.1.1-80+journalctl --user -t mdserve -p err+```++Each entry carries the endpoint it concerns in `MDSERVE_ENDPOINT` and its priority in `PRIORITY`: 3 for faults, 6 for the rest. The journal also holds what explains a vanished server, such as a suspend, an OOM kill or a logout.+Where no journal socket exists, entries go to `~/.local/state/mdserve/log` instead, or below `$XDG_STATE_HOME` when set. Its lines hold time, PID, endpoint, priority and the message. The file is mode 600 and rotates once to `log.1` at 1 MB. `mdserve --help` names the place in use.++## What is logged++Every run of `mdserve`, with its arguments, working directory and binary, and its outcome when it fails. A run that joins a server or finds its tree already served says so.+Each server's start with its binary and commit, eg `/usr/bin/mdserve 54cca2a`, and `+modified` for a build from uncommitted code. A stale binary is the first suspect when a page looks wrong.+Each tree served and withdrawn, with the cause: a deleted lock, a Delete lock or Kill server button, or a signal. Then the server's stop and exit.+Stale locks and registry links cleared after a crash, and the SIGTERM that `--kill` and `--restart` send.+Every page request, with method, path, status and time taken. Live reload streams, the stylesheet, fonts and the favicon come with every page and are left out. A shared server adds the visitor's address.+Faults: pandoc and git failures, refused links, inotify falling back to polling, and what net/http reports. A detached server's stderr goes to the same place, so a panic is kept.++A secret share's token never reaches the log. Paths do, and on shares so do visitors' addresses. Your user journal is readable by you and by members of `adm` and `systemd-journal`.

lock.go

@@ -95,10 +95,13 @@ func findLive(path string) (lockInfo, bool) { 	if err != nil { 		return lockInfo{}, false 	}-	if l := parseLock(b); l.live(bootID()) {+	l := parseLock(b)+	if l.live(bootID()) { 		return l, true 	}-	os.Remove(path)+	if os.Remove(path) == nil {+		logInfo("removed stale lock %s: pid %d is gone or from an earlier boot", path, l.pid)+	} 	return lockInfo{}, false } 

log.go

new file mode 100644@@ -0,0 +1,262 @@+package main++import (+	"bytes"+	"encoding/binary"+	"fmt"+	"net"+	"os"+	"path/filepath"+	"runtime/debug"+	"strings"+	"sync"+	"syscall"+	"time"+)++// mdserve logs every action, so a later look can tell what the user and+// mdserve did: each run with its arguments, each server's start and stop+// with the cause, trees joining and leaving, and page requests. Entries go+// to the systemd journal, tagged mdserve, or to a file in the state+// directory where no journal runs. Nothing is filtered when written; the+// journal's PRIORITY filters when read.++// Syslog priorities, as the journal's PRIORITY field takes them.+const (+	prioErr  = 3+	prioInfo = 6+)++// journalSocket takes entries in the journal's native protocol, and+// journalStream takes a process's stderr; tests point them elsewhere.+var (+	journalSocket = "/run/systemd/journal/socket"+	journalStream = "/run/systemd/journal/stdout"+)++// maxEntry caps a message, so one entry fits a datagram.+const maxEntry = 8 << 10++// maxLogFile is the size at which the fallback file rotates to log.1.+const maxLogFile = 1 << 20++var logger struct {+	mu    sync.Mutex+	ep    string // the endpoint this process acts on, eg 127.31.1.1-80, or ""+	conn  *net.UnixConn+	tried bool+}++// setLogEndpoint tags this process's later entries with ep.+func setLogEndpoint(ep string) {+	logger.mu.Lock()+	logger.ep = ep+	logger.mu.Unlock()+}++func logInfo(format string, a ...any) { logEntry(prioInfo, fmt.Sprintf(format, a...)) }+func logErr(format string, a ...any)  { logEntry(prioErr, fmt.Sprintf(format, a...)) }++// logEntry sends msg to the journal, or to the fallback file when the+// journal is absent or refuses it. A lost entry is not worth failing for.+func logEntry(prio int, msg string) {+	if len(msg) > maxEntry {+		msg = msg[:maxEntry] + " [cut]"+	}+	logger.mu.Lock()+	defer logger.mu.Unlock()+	if !logger.tried {+		logger.tried = true+		if c, err := net.DialUnix("unixgram", nil, &net.UnixAddr{Name: journalSocket, Net: "unixgram"}); err == nil {+			logger.conn = c+		}+	}+	if logger.conn != nil {+		if _, err := logger.conn.Write(journalEntry(prio, logger.ep, msg)); err == nil {+			return+		}+		// journald may have restarted; the next entry dials again.+		logger.conn.Close()+		logger.conn, logger.tried = nil, false+	}+	appendLogFile(prio, logger.ep, msg)+}++// journalEntry encodes one entry in the native protocol: KEY=value lines,+// and a value that holds a newline as the key, a newline, its length as a+// little-endian uint64, the value and a newline.+func journalEntry(prio int, ep, msg string) []byte {+	var b bytes.Buffer+	field := func(k, v string) {+		if !strings.Contains(v, "\n") {+			b.WriteString(k + "=" + v + "\n")+			return+		}+		b.WriteString(k + "\n")+		binary.Write(&b, binary.LittleEndian, uint64(len(v)))+		b.WriteString(v + "\n")+	}+	field("MESSAGE", msg)+	field("PRIORITY", fmt.Sprint(prio))+	field("SYSLOG_IDENTIFIER", "mdserve")+	if ep != "" {+		field("MDSERVE_ENDPOINT", ep)+	}+	return b.Bytes()+}++// logFile is the fallback log, eg ~/.local/state/mdserve/log.+func logFile() (string, error) {+	base, err := stateDir()+	if err != nil {+		return "", err+	}+	return filepath.Join(base, "mdserve", "log"), nil+}++// appendLogFile writes one line: time, PID, endpoint, priority and the+// message, its later lines indented. Each process opens the file per+// entry, so a rotation by one process never strands another on log.1.+func appendLogFile(prio int, ep, msg string) {+	path, err := logFile()+	if err != nil {+		return+	}+	f, err := openLogFile(path)+	if err != nil {+		return+	}+	defer f.Close()+	if ep == "" {+		ep = "-"+	}+	level := "info"+	if prio <= prioErr {+		level = "err"+	}+	line := fmt.Sprintf("%s %d %s %s %s\n", time.Now().Format("2006-01-02T15:04:05.000Z07:00"),+		os.Getpid(), ep, level, strings.ReplaceAll(msg, "\n", "\n    "))+	f.WriteString(line)+}++// openLogFile opens path for appending, after rotating it to path.1 once+// it reaches maxLogFile. An flock orders rotations: a process that waited+// finds a new file at path and leaves it be.+func openLogFile(path string) (*os.File, error) {+	if err := os.MkdirAll(filepath.Dir(path), 0o700); err != nil {+		return nil, err+	}+	f, err := os.OpenFile(path, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0o600)+	if err != nil {+		return nil, err+	}+	if info, err := f.Stat(); err != nil || info.Size() < maxLogFile {+		return f, nil+	}+	flock(f, syscall.LOCK_EX)+	if info, err := os.Stat(path); err == nil && info.Size() >= maxLogFile {+		if fi, err := f.Stat(); err == nil && os.SameFile(info, fi) {+			os.Rename(path, path+".1")+		}+	}+	f.Close()+	return os.OpenFile(path, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0o600)+}++// logSink is where a detached server's stderr goes: a journal stream, or+// the fallback file. A panic writes there, past every logger. It returns+// nil when neither opens, and stderr then goes nowhere, as before.+func logSink() *os.File {+	if c, err := net.DialUnix("unix", nil, &net.UnixAddr{Name: journalStream, Net: "unix"}); err == nil {+		defer c.Close()+		// The stream's header: identifier, unit, priority, level prefix,+		// and forwarding to syslog, kmsg and console.+		if _, err := c.Write([]byte("mdserve\n\n3\n0\n0\n0\n0\n")); err == nil {+			if f, err := c.File(); err == nil {+				return f+			}+		}+	}+	path, err := logFile()+	if err != nil {+		return nil+	}+	f, err := openLogFile(path)+	if err != nil {+		return nil+	}+	return f+}++// build names the running binary and its commit, eg /usr/bin/mdserve+// 54cca2a, with +modified for a build from uncommitted code. A stale binary+// is the first thing to rule out.+func build() string {+	exe, err := os.Executable()+	if err != nil {+		exe = "mdserve"+	}+	rev, modified := "", false+	if info, ok := debug.ReadBuildInfo(); ok {+		for _, s := range info.Settings {+			switch s.Key {+			case "vcs.revision":+				rev = s.Value+			case "vcs.modified":+				modified = s.Value == "true"+			}+		}+	}+	if len(rev) > 7 {+		rev = rev[:7]+	}+	if rev == "" {+		rev = "unknown commit"+	}+	if modified {+		rev += "+modified"+	}+	return exe + " " + rev+}++// commandLine quotes args for the log as a shell would need them, with a+// secret token hidden.+func commandLine(args []string) string {+	out := []string{"mdserve"}+	for _, a := range args {+		switch {+		case strings.HasPrefix(a, "--secret=") && a != "--secret=":+			a = "--secret=<token>"+		case a == "" || strings.ContainsAny(a, " \t\n'\"\\$`*?[]{}()<>|&;#~"):+			a = "'" + strings.ReplaceAll(a, "'", `'\''`) + "'"+		}+		out = append(out, a)+	}+	return strings.Join(out, " ")+}++// logRun records an invocation: its arguments, directory and binary.+func logRun(args []string) {+	cwd, _ := os.Getwd()+	logInfo("run: %s (in %s, %s)", commandLine(args), cwd, build())+}++// logHelp tells --help where the log is.+func logHelp() string {+	where := "  journalctl --user -t mdserve\n"+	if info, err := os.Stat(journalSocket); err != nil || info.Mode().Type() != os.ModeSocket {+		where = "  " + filepath.Join("$XDG_STATE_HOME", "mdserve", "log") + "\n"+		if p, err := logFile(); err == nil {+			where = "  " + p + "\n"+		}+	}+	return "\nlog: every run, server event and page request\n" + where+}++// logWriter takes what net/http logs, such as a handler's panic, as errors.+type logWriter struct{}++func (logWriter) Write(b []byte) (int, error) {+	logErr("%s", strings.TrimRight(string(b), "\n"))+	return len(b), nil+}

log_test.go

new file mode 100644@@ -0,0 +1,174 @@+package main++import (+	"bytes"+	"encoding/binary"+	"net"+	"os"+	"path/filepath"+	"strings"+	"testing"+	"time"+)++// TestMain keeps the tests' entries out of the user's journal and state+// directory.+func TestMain(m *testing.M) {+	dir, err := os.MkdirTemp("", "mdserve-test-")+	if err != nil {+		panic(err)+	}+	os.Setenv("XDG_STATE_HOME", dir)+	journalSocket = filepath.Join(dir, "no-journal")+	journalStream = filepath.Join(dir, "no-journal-stream")+	code := m.Run()+	os.RemoveAll(dir)+	os.Exit(code)+}++// useJournal points the logger at a fresh socket and returns what reaches+// it; with sock "" it points at none, so entries go to the file.+func useJournal(t *testing.T, sock string) {+	t.Helper()+	old := journalSocket+	logger.mu.Lock()+	if logger.conn != nil {+		logger.conn.Close()+	}+	logger.conn, logger.tried, logger.ep = nil, false, ""+	journalSocket = sock+	if sock == "" {+		journalSocket = filepath.Join(t.TempDir(), "none")+	}+	logger.mu.Unlock()+	t.Cleanup(func() {+		logger.mu.Lock()+		if logger.conn != nil {+			logger.conn.Close()+		}+		logger.conn, logger.tried, logger.ep = nil, false, ""+		journalSocket = old+		logger.mu.Unlock()+	})+}++func TestJournalEntry(t *testing.T) {+	sock := filepath.Join(t.TempDir(), "socket")+	pc, err := net.ListenUnixgram("unixgram", &net.UnixAddr{Name: sock, Net: "unixgram"})+	if err != nil {+		t.Skip("no unix datagram sockets:", err)+	}+	defer pc.Close()+	useJournal(t, sock)+	setLogEndpoint("127.31.1.1-80")+	logErr("E5: pandoc: exit 1\nline two")++	pc.SetReadDeadline(time.Now().Add(2 * time.Second))+	buf := make([]byte, 65536)+	n, err := pc.Read(buf)+	if err != nil {+		t.Fatal(err)+	}+	got := buf[:n]+	for _, want := range []string{"PRIORITY=3\n", "SYSLOG_IDENTIFIER=mdserve\n", "MDSERVE_ENDPOINT=127.31.1.1-80\n"} {+		if !bytes.Contains(got, []byte(want)) {+			t.Errorf("entry lacks %q:\n%q", want, got)+		}+	}+	// A message with a newline goes as its length and bytes.+	msg := "E5: pandoc: exit 1\nline two"+	var want bytes.Buffer+	want.WriteString("MESSAGE\n")+	binary.Write(&want, binary.LittleEndian, uint64(len(msg)))+	want.WriteString(msg + "\n")+	if !bytes.HasPrefix(got, want.Bytes()) {+		t.Errorf("message encoded as %q, want %q", got, want.Bytes())+	}+}++func TestLogFileFallback(t *testing.T) {+	useJournal(t, "")+	t.Setenv("XDG_STATE_HOME", t.TempDir())+	setLogEndpoint("127.31.1.1-8080")+	logInfo("server starts\nsecond line")+	path, _ := logFile()+	b, err := os.ReadFile(path)+	if err != nil {+		t.Fatal(err)+	}+	line := string(b)+	if !strings.Contains(line, " 127.31.1.1-8080 info server starts\n    second line\n") {+		t.Errorf("log line %q", line)+	}+	if info, _ := os.Stat(path); info.Mode().Perm() != 0o600 {+		t.Errorf("log mode %o, want 600", info.Mode().Perm())+	}+}++// The file rotates once at maxLogFile, and the next entry starts a new one.+func TestLogFileRotates(t *testing.T) {+	useJournal(t, "")+	t.Setenv("XDG_STATE_HOME", t.TempDir())+	path, _ := logFile()+	os.MkdirAll(filepath.Dir(path), 0o700)+	os.WriteFile(path, bytes.Repeat([]byte("x"), maxLogFile), 0o600)+	logInfo("after")+	if info, err := os.Stat(path + ".1"); err != nil || info.Size() != maxLogFile {+		t.Fatalf("log.1: %v %v", info, err)+	}+	if b, _ := os.ReadFile(path); !strings.HasSuffix(string(b), " info after\n") || len(b) > 200 {+		t.Errorf("new log %q", b)+	}+}++func TestCommandLine(t *testing.T) {+	got := commandLine([]string{"-n", "--share", "--secret=abc", "my docs", "it's"})+	want := `mdserve -n --share --secret=<token> 'my docs' 'it'\''s'`+	if got != want {+		t.Errorf("got %s, want %s", got, want)+	}+}++// Requests are logged but for the ones each page brings along, and a+// secret tree's token stays out.+func TestRequestLog(t *testing.T) {+	useJournal(t, "")+	t.Setenv("XDG_STATE_HOME", t.TempDir())+	s, tr, _ := serveTree(t, true)+	h := s.handler()+	for _, p := range []string{"/_mdserve/style.css", "/favicon.ico", "/_mdserve/live?path=/", "/index.md"} {+		get(h, p)+	}+	tr.prefix, tr.secret = "/s3cr3t/", true+	get(h, "/s3cr3t/index.md?raw")+	get(h, "/s3cr3t?log")++	path, _ := logFile()+	b, _ := os.ReadFile(path)+	log := string(b)+	for _, skip := range []string{"style.css", "favicon", "/_mdserve/live", "s3cr3t"} {+		if strings.Contains(log, skip) {+			t.Errorf("log holds %s:\n%s", skip, log)+		}+	}+	if !strings.Contains(log, " info GET /index.md 200 ") || !strings.Contains(log, " info GET /<token>/index.md?raw 200 ") {+		t.Errorf("log lacks the page requests:\n%s", log)+	}+	if !strings.Contains(log, " info GET /<token>?log 302 ") {+		t.Errorf("log lacks the bare secret path:\n%s", log)+	}+}++// A shared server logs who asked.+func TestRequestLogShared(t *testing.T) {+	useJournal(t, "")+	t.Setenv("XDG_STATE_HOME", t.TempDir())+	s, tr, _ := serveTree(t, true)+	s.shared, tr.shared = true, true+	get(s.handler(), "/index.md")+	path, _ := logFile()+	b, _ := os.ReadFile(path)+	if !strings.Contains(string(b), " from 192.0.2.1:1234\n") {+		t.Errorf("shared log lacks the visitor:\n%s", b)+	}+}

main.go

@@ -233,6 +233,7 @@ func main() { 	c, err := parseArgs(os.Args[1:]) 	switch { 	case err != nil:+		noteRun() 		code := failNow(errnoOf(err), err.Error()) 		io.WriteString(os.Stderr, usageText) 		os.Exit(code)@@ -241,17 +242,24 @@ func main() { 		defaultPort = 80 	} 	if c.help {-		io.WriteString(os.Stdout, usageText+environment(os.Getuid()))+		io.WriteString(os.Stdout, usageText+environment(os.Getuid())+logHelp()) 		os.Exit(0) 	} 	if hint := spacedShare(c); hint != "" {+		noteRun() 		os.Exit(failNow(syscall.ENOENT, hint)) 	} 	ep, err := endpointOf(c, os.Getuid()) 	if err != nil {+		noteRun() 		os.Exit(failNow(errnoOf(err), err.Error())) 	} 	c.ep = ep+	// --list, --kill and --restart without an address cover every server.+	if !(c.list || c.kill || c.restart) || c.addr != "" || c.sharing {+		setLogEndpoint(endpointName(ep))+	}+	noteRun() 	if c.secret && c.token == "" { 		c.token = newToken() 	}@@ -274,6 +282,14 @@ func main() { 	} } +// noteRun logs this run, once its endpoint is known or it fails without+// one. A detached server is the same run, re-executed; its start says so.+func noteRun() {+	if os.Getenv(readyEnv) == "" {+		logRun(os.Args[1:])+	}+}+ // Environment variables that set the default addresses. const ( 	addrEnv  = "MDSERVE_ADDR"@@ -505,6 +521,7 @@ func (r *reporter) finish() { }  func (r *reporter) fail(code syscall.Errno, msg string) int {+	logErr("E%d: %s", code, msg) 	r.send("err", fmt.Sprintf("E%d: %s", code, msg)) 	r.finish() 	return int(code)@@ -549,6 +566,12 @@ func detach(c config) int { 	cmd.Env = append(os.Environ(), readyEnv+"=3") 	cmd.ExtraFiles = []*os.File{w} 	cmd.SysProcAttr = &syscall.SysProcAttr{Setsid: true}+	// Without a terminal, the server's stderr goes to the log, so a panic+	// is kept.+	if sink := logSink(); sink != nil {+		cmd.Stderr = sink+		defer sink.Close()+	} 	if err := cmd.Start(); err != nil { 		return failNow(errnoOf(err), "cannot start server: "+err.Error()) 	}@@ -575,6 +598,7 @@ func detach(c config) int { }  func failNow(code syscall.Errno, msg string) int {+	logErr("E%d: %s", code, msg) 	fmt.Fprintf(os.Stderr, "E%d: %s\n", code, msg) 	return int(code) }

restart.go

@@ -125,6 +125,7 @@ func kill(c config) int { // stopServer sends the server on ep SIGTERM and waits until it has removed // the locks of trees. func stopServer(ep netip.AddrPort, pid int, trees []servedTree) error {+	logInfo("sends SIGTERM to the server on %s, pid %d", ep, pid) 	if err := syscall.Kill(pid, syscall.SIGTERM); err != nil && !errors.Is(err, syscall.ESRCH) { 		return &errno{errnoOf(err), "cannot stop the server on " + ep.String() + ": " + err.Error()} 	}

serve.go

@@ -4,6 +4,7 @@ import ( 	"context" 	"errors" 	"fmt"+	"log" 	"net" 	"net/http" 	"net/netip"@@ -65,6 +66,7 @@ func run(c config, rep *reporter) int { 	lockPath := filepath.Join(dir, lockName(c.ep)) 	if l, ok := findLive(lockPath); ok { 		reg.close()+		logInfo("already served: %s", dir) 		if c.secret { 			rep.send("note", "already served; --secret applies to a new share. Delete "+lockPath+" and share again to change it.") 		}@@ -104,6 +106,7 @@ func join(ep netip.AddrPort, rep *reporter, reg *registry, dir, lockPath, token 	for end := time.Now().Add(joinWait); time.Now().Before(end); time.Sleep(20 * time.Millisecond) { 		if b, err := os.ReadFile(lockPath); err == nil { 			if l := parseLock(b); l.live(bootID()) {+				logInfo("joined the server on %s: %s", ep, dir) 				report(rep, ep, l.url) 				return 0 			}@@ -198,6 +201,7 @@ func ifaceOf(a netip.Addr) string { // the registry lock, which serve releases once dir is adopted and a crashed // server's leftovers are gone. func serve(c config, rep *reporter, ln net.Listener, reg *registry, dir, home string) int {+	logInfo("server starts on %s: %s", c.ep, build()) 	h := &hub{ep: c.ep, home: home, reg: reg, ln: ln, srv: newServer(), w: newWatcher(lockMask), 		done: make(chan struct{}), fresh: map[net.Conn]bool{}} 	defer h.w.close()@@ -223,15 +227,16 @@ func serve(c config, rep *reporter, ln net.Listener, reg *registry, dir, home st 	h.srv.about = newAbout(c.ep) 	h.srv.live = newLive() 	defer h.srv.live.close()-	h.httpd = &http.Server{Handler: h.srv.handler(), ReadHeaderTimeout: 10 * time.Second, ConnState: h.track}+	h.httpd = &http.Server{Handler: h.srv.handler(), ReadHeaderTimeout: 10 * time.Second, ConnState: h.track,+		ErrorLog: log.New(logWriter{}, "", 0)}  	sigs := make(chan os.Signal, 1) 	signal.Notify(sigs, syscall.SIGINT, syscall.SIGTERM, syscall.SIGHUP) 	defer signal.Stop(sigs) 	go func() { 		select {-		case <-sigs:-			h.shutdown()+		case sig := <-sigs:+			h.shutdown(signalName(sig)) 		case <-h.done: 		} 	}()@@ -240,15 +245,33 @@ func serve(c config, rep *reporter, ln net.Listener, reg *registry, dir, home st 	url := h.origin + t.prefixURL() 	report(rep, c.ep, url) 	if err := h.httpd.Serve(ln); !h.halted.Load() {-		h.shutdown()+		h.shutdown("cannot serve: " + err.Error()) 		<-h.done-		fmt.Fprintf(os.Stderr, "E%d: %s\n", syscall.EIO, err)+		logErr("E%d: %s", syscall.EIO, err)+		// Detached, stderr is the log itself.+		if rep.pipe == nil {+			fmt.Fprintf(os.Stderr, "E%d: %s\n", syscall.EIO, err)+		} 		return int(syscall.EIO) 	} 	<-h.done+	logInfo("server exits") 	return 0 } +// signalName names the signals serve stops on, as kill(1) does.+func signalName(sig os.Signal) string {+	switch sig {+	case syscall.SIGINT:+		return "SIGINT"+	case syscall.SIGTERM:+		return "SIGTERM"+	case syscall.SIGHUP:+		return "SIGHUP"+	}+	return sig.String()+}+ // hub keeps the served trees in line with their locks and the registry. It // adopts a tree that joins, withdraws a tree whose lock is gone, and stops // the server with the last tree.@@ -300,7 +323,9 @@ func (h *hub) dropLeftovers() { 	links, _ := h.reg.links() 	for link, target := range links { 		if lockPath, _ := splitTarget(target); filepath.Base(lockPath) == lockName(h.ep) {-			os.Remove(lockPath)+			if os.Remove(lockPath) == nil {+				logInfo("removed %s, left by a crashed server", lockPath)+			} 		} 		os.Remove(link) 	}@@ -356,16 +381,26 @@ func (h *hub) adopt(lockPath, link, token string) (*tree, error) { 	} 	t.wd = h.w.add(dir) 	h.srv.add(t)+	logInfo("serves %s at %s", dir, h.where(t)) 	return t, nil } -// withdraw stops serving t and removes its lock and link. A link that is-// not the one the server knows is a new join for the same directory, and-// stays. The caller holds the lock.-func (h *hub) withdraw(t *tree) {+// where is t's URL for the log; a secret tree's would hold its token.+func (h *hub) where(t *tree) string {+	if t.secret {+		return h.origin + "/<token>/"+	}+	return h.origin + t.prefixURL()+}++// withdraw stops serving t for the cause why and removes its lock and link.+// A link that is not the one the server knows is a new join for the same+// directory, and stays. The caller holds the lock.+func (h *hub) withdraw(t *tree, why string) { 	if !h.srv.remove(t) { 		return 	}+	logInfo("withdraws %s: %s", t.dir, why) 	t.lock.remove() 	if info, err := os.Lstat(t.link); err == nil && os.SameFile(info, t.linkInfo) { 		os.Remove(t.link)@@ -385,7 +420,7 @@ func (h *hub) sync() bool { 	} 	for _, t := range h.srv.list() { 		if t.lock.gone() {-			h.withdraw(t)+			h.withdraw(t, "its lock "+t.lock.path+" was deleted or replaced") 		} 	} 	served := map[string]bool{}@@ -399,11 +434,12 @@ func (h *hub) sync() bool { 		} 		lockPath, token := splitTarget(target) 		if _, err := h.adopt(lockPath, link, token); err != nil {+			logErr("E%d: refused %s: %v", errnoOf(err), lockPath, err) 			os.Remove(link) 		} 	} 	if len(h.srv.list()) == 0 {-		h.halt()+		h.halt("its last tree is gone") 		return false 	} 	return true@@ -430,22 +466,22 @@ func (h *hub) loop() {  // stop withdraws trees at the press of a button. The loop then stops the // server if no tree is left.-func (h *hub) stop(trees []*tree) {+func (h *hub) stop(trees []*tree, why string) { 	h.lock() 	for _, t := range trees {-		h.withdraw(t)+		h.withdraw(t, why) 	} 	h.unlock() 	h.w.signal() }  // shutdown withdraws every tree and stops the server, as on a signal.-func (h *hub) shutdown() {+func (h *hub) shutdown(why string) { 	h.lock() 	for _, t := range h.srv.list() {-		h.withdraw(t)+		h.withdraw(t, why) 	}-	h.halt()+	h.halt(why) 	h.unlock() 	h.w.signal() }@@ -454,10 +490,11 @@ func (h *hub) shutdown() { // mdserve finds the address free and starts a new server instead of // linking into this one. Open connections drain in the background. The // caller holds the lock.-func (h *hub) halt() {+func (h *hub) halt(why string) { 	if h.halted.Swap(true) { 		return 	}+	logInfo("server stops: %s", why) 	h.ln.Close() 	// Live reload streams never end on their own, and Shutdown waits for them. 	h.srv.live.close()

server.go

@@ -59,7 +59,7 @@ var csp = "default-src 'none'; script-src " + scriptSrc(liveJS) + "; connect-src type server struct { 	mu     sync.RWMutex 	trees  []*tree-	stop   func([]*tree) // withdraws trees; set by the hub+	stop   func([]*tree, string) // withdraws trees for a cause; set by the hub 	about  about 	shared bool  // on an address beyond loopback: it shows the trees and nothing of the machine 	live   *live // nil in tests that do without live reload@@ -124,7 +124,7 @@ func clock(t time.Time) string { }  func newServer() *server {-	return &server{stop: func([]*tree) {}}+	return &server{stop: func([]*tree, string) {}} }  // tree is one served directory, exposed with everything below it.@@ -278,9 +278,62 @@ func (s *server) handler() http.Handler { 	} 	mux.HandleFunc("GET /_mdserve/live", s.handleLive) 	mux.HandleFunc("GET /", s.handlePath)-	return guard(mux, s.shared)+	return s.logged(guard(mux, s.shared)) } +// logged records each request but those that come with every page: live+// reload streams, the stylesheet, fonts and the favicon. A shared server+// adds the visitor's address. A secret tree's token stays out of the log.+func (s *server) logged(next http.Handler) http.Handler {+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {+		p := r.URL.Path+		if p == "/favicon.ico" || strings.HasPrefix(p, "/_mdserve/") && p != "/_mdserve/stop" {+			next.ServeHTTP(w, r)+			return+		}+		uri := r.URL.RequestURI()+		if t := s.lookup(p); t != nil && t.secret {+			uri = "/<token>/" + strings.TrimPrefix(uri, t.prefix)+		} else if t := s.byPrefix(p + "/"); t != nil && t.secret {+			// The secret path without its slash, which redirects.+			uri = "/<token>" + strings.TrimPrefix(uri, p)+		}+		start := time.Now()+		sw := &statusWriter{ResponseWriter: w, status: http.StatusOK}+		next.ServeHTTP(sw, r)+		msg := fmt.Sprintf("%s %s %d %dms", r.Method, uri, sw.status, time.Since(start).Milliseconds())+		if s.shared {+			msg += " from " + r.RemoteAddr+		}+		if sw.status >= 500 {+			logErr("%s", msg)+		} else {+			logInfo("%s", msg)+		}+	})+}++// statusWriter keeps the status a handler sent, for the log.+type statusWriter struct {+	http.ResponseWriter+	status int+	wrote  bool+}++func (w *statusWriter) WriteHeader(code int) {+	if !w.wrote {+		w.status, w.wrote = code, true+	}+	w.ResponseWriter.WriteHeader(code)+}++func (w *statusWriter) Write(b []byte) (int, error) {+	w.wrote = true+	return w.ResponseWriter.Write(b)+}++func (w *statusWriter) Unwrap() http.ResponseWriter { return w.ResponseWriter }+ // guard rejects requests for any host but this machine, which defeats DNS // rebinding, and sets the headers every response needs. A shared server // takes any host, since visitors use whatever name reaches it; a secret@@ -368,19 +421,19 @@ func (s *server) handleStop(w http.ResponseWriter, r *http.Request) { 		http.Error(w, "stop must come from an mdserve page", http.StatusForbidden) 		return 	}-	trees, crumbs, what := s.list(), []crumb{{Label: "mdserve"}}, "Stopped mdserve"+	trees, crumbs, what, why := s.list(), []crumb{{Label: "mdserve"}}, "Stopped mdserve", "Kill server button" 	if prefix := r.PostFormValue("tree"); prefix != "" { 		t := s.byPrefix(prefix) 		if t == nil { 			s.serveIndex(w, r, http.StatusNotFound, "Not served: "+prefix) 			return 		}-		trees, crumbs, what = []*tree{t}, []crumb{t.rootCrumb()}, "Stopped serving "+t.label+		trees, crumbs, what, why = []*tree{t}, []crumb{t.rootCrumb()}, "Stopped serving "+t.label, "Delete lock button" 		// While other trees remain the server lives on: a button on the 		// index returns there, and a tree's page links it. 		if len(s.list()) > 1 { 			if r.PostFormValue("from") == "index" {-				s.stop(trees)+				s.stop(trees, why+" on the index") 				http.Redirect(w, r, "/", http.StatusSeeOther) 				return 			}@@ -403,7 +456,7 @@ func (s *server) handleStop(w http.ResponseWriter, r *http.Request) { 	}) 	// stop only withdraws; the hub shuts down on its own goroutine, since 	// Shutdown waits for this response to finish.-	s.stop(trees)+	s.stop(trees, why) }  // sameOrigin trusts Sec-Fetch-Site when present: browsers set it and pages@@ -908,6 +961,14 @@ func (t *tree) why(ref *refusal) string { }  func (t *tree) fail(w http.ResponseWriter, r *http.Request, name string, status int, msg string) {+	// The request's own entry says not found; a refusal or fault says why+	// only here.+	switch {+	case status >= 500:+		logErr("%s: %s", t.dir, msg)+	case status != http.StatusNotFound:+		logInfo("%s: %s", t.dir, msg)+	} 	t.render(w, r, status, page{ 		Title:  t.title(name), 		Crumbs: t.crumbs(name),

server_test.go

@@ -195,7 +195,7 @@ func TestNoEscapeFromRoot(t *testing.T) { func TestStopRefusesOtherSites(t *testing.T) { 	s, _, _ := serveTree(t, true) 	stopped := make(chan struct{}, 1)-	s.stop = func([]*tree) { stopped <- struct{}{} }+	s.stop = func([]*tree, string) { stopped <- struct{}{} } 	h := s.handler() 	if rec := do(h, "POST", "/_mdserve/stop", "Sec-Fetch-Site", "cross-site"); rec.Code != http.StatusForbidden { 		t.Errorf("cross-site stop: status %d, want 403", rec.Code)@@ -232,7 +232,7 @@ func TestIndexDeleteReturns(t *testing.T) { 	tr.prefix, tr.label = "/notes/", "~/notes" 	addTree(t, s, filepath.Join(dir, "a"), "/other/", "~/other", "") 	var got []*tree-	s.stop = func(ts []*tree) {+	s.stop = func(ts []*tree, _ string) { 		got = ts 		for _, t := range ts { 			s.remove(t)@@ -366,7 +366,7 @@ func TestStopWithdrawsOneTree(t *testing.T) { 	s, tr, dir := serveTree(t, false) 	other := addTree(t, s, filepath.Join(dir, "a"), "/other/", "~/other", "") 	var got []*tree-	s.stop = func(ts []*tree) { got = ts }+	s.stop = func(ts []*tree, _ string) { got = ts } 	body := get(s.handler(), "/other/").Body.String() 	if !strings.Contains(body, `<input type="hidden" name="tree" value="/other/">`) { 		t.Fatalf("tree page lacks its stop form: %s", body)

watch.go

@@ -38,6 +38,7 @@ func newWatcher(mask uint32) *watcher { 	w := &watcher{fd: -1, mask: mask, wake: make(chan struct{}, 1)} 	fd, err := inotifyInit(syscall.IN_NONBLOCK | syscall.IN_CLOEXEC) 	if err != nil {+		logErr("inotify unavailable, polling every second: %v", err) 		w.poll.Store(true) 		return w 	}@@ -78,7 +79,9 @@ func (w *watcher) add(dir string) int { 		return -1 	} 	if err != nil {-		w.poll.Store(true)+		if !w.poll.Swap(true) {+			logErr("cannot watch %s, polling every second: %v", dir, err)+		} 		return -1 	} 	return wd