Pruner: parallel pruning

refs #62

Gopkg.lock

@@ -7,6 +7,12 @@
   revision = "346938d642f2ec3594ed81d874461961cd0faa76"
   version = "v1.1.0"
 
+[[projects]]
+  branch = "master"
+  name = "github.com/dustin/go-humanize"
+  packages = ["."]
+  revision = "bb3d318650d48840a39aa21a027c6630e198e626"
+
 [[projects]]
   branch = "master"
   name = "github.com/ftrvxmtrx/fd"
@@ -25,12 +31,6 @@
   packages = ["."]
   revision = "eb3733d160e74a9c7e442f435eb3bea458e1d19f"
 
-[[projects]]
-  name = "github.com/inconshreveable/mousetrap"
-  packages = ["."]
-  revision = "76626ae9c91c4f2a10f34cad8ce83ea42c93bb75"
-  version = "v1.0"
-
 [[projects]]
   branch = "master"
   name = "github.com/jinzhu/copier"
@@ -55,6 +55,12 @@
   packages = ["."]
   revision = "7cafcd837844e784b526369c9bce262804aebc60"
 
+[[projects]]
+  name = "github.com/mattn/go-isatty"
+  packages = ["."]
+  revision = "0360b2af4f38e8d38c7fce2a9f4e702702d73a39"
+  version = "v0.0.3"
+
 [[projects]]
   branch = "master"
   name = "github.com/mitchellh/mapstructure"
@@ -73,6 +79,18 @@
   revision = "792786c7400a136282c1664665ae0a8db921c6c2"
   version = "v1.0.0"
 
+[[projects]]
+  branch = "master"
+  name = "github.com/problame/go-netssh"
+  packages = ["."]
+  revision = "ffa145d2506e222977205e7666a9722d6b9959ac"
+
+[[projects]]
+  branch = "master"
+  name = "github.com/problame/go-rwccmd"
+  packages = ["."]
+  revision = "391d2c78c8404a9683d79f75dd24ab53040f89f7"
+
 [[projects]]
   branch = "master"
   name = "github.com/spf13/cobra"
@@ -91,9 +109,15 @@
   revision = "69483b4bd14f5845b5a1e55bca19e954e827f1d0"
   version = "v1.1.4"
 
+[[projects]]
+  branch = "master"
+  name = "golang.org/x/sys"
+  packages = ["unix"]
+  revision = "bf42f188b9bc6f2cf5b8ee5a912ef1aedd0eba4c"
+
 [solve-meta]
   analyzer-name = "dep"
   analyzer-version = 1
-  inputs-digest = "d654c5e91ee04baf1a373bb241b94ab41d3838fb69a56e91fe54cc8b962eab56"
+  inputs-digest = "fcfc66322b5f9dbe329411b7688a4e9dcebe3c529c1dadf4f78bcdb2bcfb8fbf"
   solver-name = "gps-cdcl"
   solver-version = 1

Gopkg.toml

@@ -1,25 +1,4 @@
-
-# Gopkg.toml example
-#
-# Refer to https://github.com/golang/dep/blob/master/docs/Gopkg.toml.md
-# for detailed Gopkg.toml documentation.
-#
-# required = ["github.com/user/thing/cmd/thing"]
-# ignored = ["github.com/user/project/pkgX", "bitbucket.org/user/project/pkgA/pkgY"]
-#
-# [[constraint]]
-#   name = "github.com/user/project"
-#   version = "1.0.0"
-#
-# [[constraint]]
-#   name = "github.com/user/project2"
-#   branch = "dev"
-#   source = "github.com/myfork/project2"
-#
-# [[override]]
-#  name = "github.com/x/y"
-#  version = "2.4.0"
-
+ignored = [ "github.com/inconshreveable/mousetrap" ]
 
 [[constraint]]
   branch = "master"
@@ -64,3 +43,11 @@
 [[constraint]]
   name = "github.com/go-logfmt/logfmt"
   version = "*"
+
+[[constraint]]
+  name = "github.com/problame/go-rwccmd"
+  branch = "master"
+
+[[constraint]]
+  name = "github.com/problame/go-netssh"
+  branch = "master"

Makefile

@@ -1,19 +1,38 @@
-.PHONY: generate build test vet cover release clean
+.PHONY: generate build test vet cover release docs docs-clean clean vendordeps
+.DEFAULT_GOAL := build
 
 ROOT := github.com/zrepl/zrepl
-SUBPKGS := cmd logger rpc sshbytestream util
+SUBPKGS := cmd logger rpc util zfs
 
 _TESTPKGS := $(ROOT) $(foreach p,$(SUBPKGS),$(ROOT)/$(p))
 
 ARTIFACTDIR := artifacts
 
+ifndef ZREPL_VERSION
+    ZREPL_VERSION := $(shell git describe --dirty 2>/dev/null || echo "ZREPL_BUILD_INVALID_VERSION" )
+    ifeq ($(ZREPL_VERSION),ZREPL_BUILD_INVALID_VERSION) # can't use .SHELLSTATUS because Debian Stretch is still on gmake 4.1
+        $(error cannot infer variable ZREPL_VERSION using git and variable is not overriden by make invocation)
+    endif
+endif
+GO_LDFLAGS := "-X github.com/zrepl/zrepl/cmd.zreplVersion=$(ZREPL_VERSION)"
+
+GO_BUILD := go build -ldflags $(GO_LDFLAGS)
+
+RELEASE_BINS := $(ARTIFACTDIR)/zrepl-freebsd-amd64 $(ARTIFACTDIR)/zrepl-linux-amd64
+RELEASE_NOARCH := $(ARTIFACTDIR)/zrepl-noarch.tar
+THIS_PLATFORM_RELEASE_BIN := $(shell bash -c 'source <(go env) && echo "zrepl-$${GOOS}-$${GOARCH}"' )
+
+vendordeps:
+	dep ensure -v -vendor-only
+
 generate: #not part of the build, must do that manually
 	@for pkg in $(_TESTPKGS); do\
 		go generate "$$pkg" || exit 1; \
 	done;
 
 build:
-		go build -o $(ARTIFACTDIR)/zrepl
+	@echo "INFO: In case of missing dependencies, run 'make vendordeps'"
+	$(GO_BUILD) -o "$(ARTIFACTDIR)/zrepl"
 
 test:
 	@for pkg in $(_TESTPKGS); do \
@@ -36,12 +55,52 @@ cover: artifacts
 		fi; \
 	done;
 
-artifacts:
-	mkdir artifacts
+$(ARTIFACTDIR):
+	mkdir -p "$@"
 
-release: artifacts vet test
-	GOOS=linux GOARCH=amd64   go build -o "$(ARTIFACTDIR)/zrepl-linux-amd64"
-	GOOS=freebsd GOARCH=amd64 go build -o "$(ARTIFACTDIR)/zrepl-freebsd-amd64"
+$(ARTIFACTDIR)/docs: $(ARTIFACTDIR)
+	mkdir -p "$@"
 
-clean:
+$(ARTIFACTDIR)/bash_completion: $(RELEASE_BINS)
+	artifacts/$(THIS_PLATFORM_RELEASE_BIN) bashcomp "$@"
+
+$(ARTIFACTDIR)/go_version.txt:
+	go version > $@
+
+docs: $(ARTIFACTDIR)/docs
+	make -C docs \
+		html \
+		BUILDDIR=../artifacts/docs \
+
+docs-clean:
+	make -C docs \
+		clean \
+		BUILDDIR=../artifacts/docs
+
+
+.PHONY: $(RELEASE_BINS)
+# TODO: two wildcards possible
+$(RELEASE_BINS): $(ARTIFACTDIR)/zrepl-%-amd64: generate $(ARTIFACTDIR) vet test
+	@echo "INFO: In case of missing dependencies, run 'make vendordeps'"
+	GOOS=$* GOARCH=amd64   $(GO_BUILD) -o "$(ARTIFACTDIR)/zrepl-$*-amd64"
+
+$(RELEASE_NOARCH): docs $(ARTIFACTDIR)/bash_completion $(ARTIFACTDIR)/go_version.txt
+	tar --mtime='1970-01-01' --sort=name \
+		--transform 's/$(ARTIFACTDIR)/zrepl-$(ZREPL_VERSION)-noarch/' \
+		-acf $@ \
+		$(ARTIFACTDIR)/docs/html \
+		$(ARTIFACTDIR)/bash_completion \
+		$(ARTIFACTDIR)/go_version.txt
+
+release: $(RELEASE_BINS) $(RELEASE_NOARCH)
+	rm -rf "$(ARTIFACTDIR)/release"
+	mkdir -p "$(ARTIFACTDIR)/release"
+	cp $^ "$(ARTIFACTDIR)/release"
+	cd "$(ARTIFACTDIR)/release" && sha512sum $$(ls | sort) > sha512sum.txt
+	@if echo "$(ZREPL_VERSION)" | grep dirty > /dev/null; then\
+		echo '[WARN] Do not publish the artifacts, make variable ZREPL_VERSION=$(ZREPL_VERSION) indicates they are dirty!'; \
+		exit 1; \
+	fi
+
+clean: docs-clean
 	rm -rf "$(ARTIFACTDIR)"

README.md

@@ -3,7 +3,7 @@ zrepl is a ZFS filesystem backup & replication solution written in Go.
 
 ## User Documentation
 
-**User Documentation** cab be found at [zrepl.github.io](https://zrepl.github.io).
+**User Documentation** can be found at [zrepl.github.io](https://zrepl.github.io).
 
 ## Bug Reports
 
@@ -20,8 +20,20 @@ zrepl is a ZFS filesystem backup & replication solution written in Go.
 The above does not apply if you already implemented everything.
 Check out the *Coding Workflow* section below for details.
 
+## Package Maintainer Information
+
+* Follow the steps in `docs/installation.rst -> Compiling from Source` and read the Makefile / shell scripts used in this process.
+* Make sure your distro is compatible with the paths in `docs/installation.rst`.
+* Ship a default config that adheres to your distro's `hier` and logging system.
+* Ship a service manager file and _please_ try to upstream it to this repository.
+* Use `make release ZREPL_VERSION='mydistro-1.2.3_1'`
+    * Your distro's name and any versioning supplemental to zrepl's (e.g. package revision) should be in this string
+* Make sure you are informed about new zrepl versions, e.g. by subscribing to GitHub's release RSS feed.
+
 ## Developer Documentation
 
+First, use `./lazy.sh devsetup` to install build dependencies and read `docs/installation.rst -> Compiling from Source`.
+
 ### Overall Architecture
 
 The application architecture is documented as part of the user docs in the *Implementation* section (`docs/content/impl`).
@@ -34,14 +46,13 @@ Make sure to develop an understanding how zrepl is typically used by studying th
 │   ├── sampleconf          # example configuration
 ├── docs                    # sphinx-based documentation
 │   ├── **/*.rst            # documentation in reStructuredText
-│   ├── conf.py             # sphinx configuration
+│   ├── sphinxconf
+│   │   └── conf.py         # sphinx config (see commit 445a280 why its not in docs/)
+│   ├── requirements.txt    # pip3 requirements to build documentation
 │   ├── publish.sh          # shell script for automated rendering & deploy to zrepl.github.io repo
-│   ├── public_git          # checkout of zrepl.github.io used by above shell script
-├── jobrun                  # OBSOLETE
+│   ├── public_git          # checkout of zrepl.github.io managed by above shell script
 ├── logger                  # logger package used by zrepl
 ├── rpc                     # rpc protocol implementation
-├── scratchpad              # small example programs demoing some internal packages. probably OBSOLETE
-├── sshbytestream           # io.ReadWriteCloser over SSH
 ├── util
 └── zfs                     # ZFS wrappers, filesystemm diffing
 ```
@@ -76,11 +87,3 @@ There will not be a big refactoring (an attempt was made, but it's destroying to
 
 However, new contributions & patches should fix naming without further notice in the commit message.
 
-### Building `docs`
-
-```
-cd docs
-pip install sphinx sphinx-rtd-theme
-make clean html
-xdg-open _build/html/index.html
-```

build.Dockerfile

@@ -0,0 +1,16 @@
+FROM golang:latest
+
+RUN apt-get update && apt-get install -y \
+    python3-pip
+
+ADD lazy.sh /tmp/lazy.sh
+ADD docs/requirements.txt /tmp/requirements.txt
+ENV ZREPL_LAZY_DOCS_REQPATH=/tmp/requirements.txt
+RUN /tmp/lazy.sh devsetup
+
+# prepare volume mount of git checkout to /zrepl
+RUN mkdir -p /go/src/github.com/zrepl/zrepl
+RUN chmod -R 0777 /go
+WORKDIR /go/src/github.com/zrepl/zrepl
+
+

clone_and_build.sh

@@ -1,46 +0,0 @@
-#!/bin/sh
-set -e
-
-bold=$(tput bold)
-normal=$(tput sgr0)
-
-step() {
-    echo "${bold}$1${normal}"
-}
-
-if [ -z "$GOPATH" ]; then
-    step "Make sure you have your GOPATH configured correctly" 1>&2
-    exit 1
-fi
-
-step "Checkout sources to \$GOPATH/github.com/zrepl/zrepl"
-CHECKOUTPATH="${GOPATH}/src/github.com/zrepl/zrepl"
-if [ -e "$CHECKOUTPATH" ]; then
-    echo "${CHECKOUTPATH} already exists"
-    if [ ! -d "$CHECKOUTPATH" ]; then
-        echo "${CHECKOUTPATH} is not a directory, aborting" 1>&2
-    else
-        cd "$CHECKOUTPATH"
-    fi
-else
-    mkdir -p "$GOPATH/src/github.com/zrepl"
-    cd "$GOPATH/src/github.com/zrepl"
-    git clone https://github.com/zrepl/zrepl.git
-    cd zrepl
-fi
-
-step "Install build depdencies using 'go get' to \$GOPATH/bin"
-go get -u golang.org/x/tools/cmd/stringer
-go get -u github.com/golang/dep/cmd/dep
-if ! type stringer || ! type dep; then
-    echo "Installed dependencies but can't find them in \$PATH, adjust it to contain \$GOPATH/bin" 1>&2
-    exit 1
-fi
-
-step "Fetching dependencies using 'dep ensure'"
-dep ensure
-
-step "Making release"
-make release
-
-step "Release artifacts are available in $(pwd)/artifacts"

cmd/autosnap.go

@@ -5,56 +5,59 @@ import (
 	"fmt"
 	"github.com/zrepl/zrepl/zfs"
 	"sort"
+	"sync"
 	"time"
 )
 
 type IntervalAutosnap struct {
+	task             *Task
 	DatasetFilter    zfs.DatasetFilter
 	Prefix           string
 	SnapshotInterval time.Duration
-
-	log       Logger
-	snaptimes []snapTime
 }
 
+func (a *IntervalAutosnap) filterFilesystems() (fss []*zfs.DatasetPath, stop bool) {
+	a.task.Enter("filter_filesystems")
+	defer a.task.Finish()
+	fss, err := zfs.ZFSListMapping(a.DatasetFilter)
+	stop = err != nil
+	if err != nil {
+		a.task.Log().WithError(err).Error("cannot list datasets")
+	}
+	if len(fss) == 0 {
+		a.task.Log().Warn("no filesystem matching filesystem filter")
+	}
+	return fss, stop
+}
+
+func (a *IntervalAutosnap) findSyncPoint(fss []*zfs.DatasetPath) (syncPoint time.Time, err error) {
+	a.task.Enter("find_sync_point")
+	defer a.task.Finish()
 	type snapTime struct {
 		ds   *zfs.DatasetPath
 		time time.Time
 	}
 
-func (a *IntervalAutosnap) Run(ctx context.Context, didSnaps chan struct{}) {
-
-	a.log = ctx.Value(contextKeyLog).(Logger)
-
-	const LOG_TIME_FMT string = time.ANSIC
-
-	ds, err := zfs.ZFSListMapping(a.DatasetFilter)
-	if err != nil {
-		a.log.WithError(err).Error("cannot list datasets")
-		return
-	}
-	if len(ds) == 0 {
-		a.log.Warn("no filesystem matching filesystem filter")
-		return
+	if len(fss) == 0 {
+		return time.Now(), nil
 	}
 
-	a.snaptimes = make([]snapTime, len(ds))
+	snaptimes := make([]snapTime, 0, len(fss))
 
 	now := time.Now()
 
-	a.log.Debug("examine filesystem state")
-	for i, d := range ds {
+	a.task.Log().Debug("examine filesystem state")
+	for _, d := range fss {
 
-		l := a.log.WithField(logFSField, d.ToString())
+		l := a.task.Log().WithField(logFSField, d.ToString())
 
-		fsvs, err := zfs.ZFSListFilesystemVersions(d, &PrefixSnapshotFilter{a.Prefix})
+		fsvs, err := zfs.ZFSListFilesystemVersions(d, NewPrefixFilter(a.Prefix))
 		if err != nil {
 			l.WithError(err).Error("cannot list filesystem versions")
 			continue
 		}
 		if len(fsvs) <= 0 {
 			l.WithField("prefix", a.Prefix).Info("no filesystem versions with prefix")
-			a.snaptimes[i] = snapTime{d, now}
 			continue
 		}
 
@@ -78,34 +81,75 @@ func (a *IntervalAutosnap) Run(ctx context.Context, didSnaps chan struct{}) {
 		if since < a.SnapshotInterval {
 			next = latest.Creation.Add(a.SnapshotInterval)
 		}
-		a.snaptimes[i] = snapTime{d, next}
+		snaptimes = append(snaptimes, snapTime{d, next})
 	}
 
-	sort.Slice(a.snaptimes, func(i, j int) bool {
-		return a.snaptimes[i].time.Before(a.snaptimes[j].time)
+	if len(snaptimes) == 0 {
+		snaptimes = append(snaptimes, snapTime{nil, now})
+	}
+
+	sort.Slice(snaptimes, func(i, j int) bool {
+		return snaptimes[i].time.Before(snaptimes[j].time)
 	})
 
-	syncPoint := a.snaptimes[0]
-	a.log.WithField("sync_point", syncPoint.time.Format(LOG_TIME_FMT)).
+	return snaptimes[0].time, nil
+
+}
+
+func (a *IntervalAutosnap) waitForSyncPoint(ctx context.Context, syncPoint time.Time) {
+	a.task.Enter("wait_sync_point")
+	defer a.task.Finish()
+
+	const LOG_TIME_FMT string = time.ANSIC
+
+	a.task.Log().WithField("sync_point", syncPoint.Format(LOG_TIME_FMT)).
 		Info("wait for sync point")
 
 	select {
 	case <-ctx.Done():
-		a.log.WithError(ctx.Err()).Info("context done")
+		a.task.Log().WithError(ctx.Err()).Info("context done")
 		return
-
-	case <-time.After(syncPoint.time.Sub(now)):
-		a.log.Debug("snapshot all filesystems to enable further snaps in lockstep")
-		a.doSnapshots(didSnaps)
+	case <-time.After(syncPoint.Sub(time.Now())):
+	}
 }
 
-	ticker := time.NewTicker(a.SnapshotInterval)
+func (a *IntervalAutosnap) syncUpRun(ctx context.Context, didSnaps chan struct{}) (stop bool) {
+	a.task.Enter("sync_up")
+	defer a.task.Finish()
 
+	fss, stop := a.filterFilesystems()
+	if stop {
+		return true
+	}
+
+	syncPoint, err := a.findSyncPoint(fss)
+	if err != nil {
+		return true
+	}
+
+	a.waitForSyncPoint(ctx, syncPoint)
+
+	a.task.Log().Debug("snapshot all filesystems to enable further snaps in lockstep")
+	a.doSnapshots(didSnaps)
+	return false
+}
+
+func (a *IntervalAutosnap) Run(ctx context.Context, didSnaps chan struct{}) {
+
+	if a.syncUpRun(ctx, didSnaps) {
+		a.task.Log().Error("stoppping autosnap after error in sync up")
+		return
+	}
+
+	// task drops back to idle here
+
+	a.task.Log().Debug("setting up ticker in SnapshotInterval")
+	ticker := time.NewTicker(a.SnapshotInterval)
 	for {
 		select {
 		case <-ctx.Done():
 			ticker.Stop()
-			a.log.WithError(ctx.Err()).Info("context done")
+			a.task.Log().WithError(ctx.Err()).Info("context done")
 			return
 
 		case <-ticker.C:
@@ -117,32 +161,55 @@ func (a *IntervalAutosnap) Run(ctx context.Context, didSnaps chan struct{}) {
 
 func (a *IntervalAutosnap) doSnapshots(didSnaps chan struct{}) {
 
-	// fetch new dataset list in case user added new dataset
-	ds, err := zfs.ZFSListMapping(a.DatasetFilter)
-	if err != nil {
-		a.log.WithError(err).Error("cannot list datasets")
+	a.task.Enter("do_snapshots")
+	defer a.task.Finish()
+
+	// don't cache the result from previous run in case the user added
+	// a new dataset in the meantime
+	fss, stop := a.filterFilesystems()
+	if stop {
 		return
 	}
 
+	a.task.Log().Info("beginning parallel snapshots")
+
 	// TODO channel programs -> allow a little jitter?
-	for _, d := range ds {
+	var wg sync.WaitGroup
+	for fsi := range fss {
+		wg.Add(1)
+		go func(fs *zfs.DatasetPath) {
+			defer wg.Done()
+
 			suffix := time.Now().In(time.UTC).Format("20060102_150405_000")
 			snapname := fmt.Sprintf("%s%s", a.Prefix, suffix)
 
-		a.log.WithField(logFSField, d.ToString()).
-			WithField("snapname", snapname).
-			Info("create snapshot")
+			l := a.task.Log().WithField(logFSField, fs.ToString()).
+				WithField("snapname", snapname)
 
-		err := zfs.ZFSSnapshot(d, snapname, false)
+			l.Info("create snapshot")
+			err := zfs.ZFSSnapshot(fs, snapname, false)
 			if err != nil {
-			a.log.WithError(err).Error("cannot create snapshot")
+				l.WithError(err).Error("cannot create snapshot")
+				return
 			}
+
+			l.Info("create corresponding bookmark")
+			err = zfs.ZFSBookmark(fs, snapname, snapname)
+			if err != nil {
+				l.WithError(err).Error("cannot create bookmark")
 			}
 
+		}(fss[fsi])
+	}
+
+	a.task.Log().Info("waiting for parallel snapshots to finish")
+	wg.Wait()
+	a.task.Log().Info("snapshots finished")
+
 	select {
 	case didSnaps <- struct{}{}:
 	default:
-		a.log.Error("warning: callback channel is full, discarding")
+		a.task.Log().Error("warning: callback channel is full, discarding")
 	}
 
 }

cmd/bashcomp.go

@@ -0,0 +1,29 @@
+package cmd
+
+import (
+	"fmt"
+
+	"github.com/spf13/cobra"
+	"os"
+)
+
+var bashcompCmd = &cobra.Command{
+	Use:   "bashcomp path/to/out/file",
+	Short: "generate bash completions",
+	Run: func(cmd *cobra.Command, args []string) {
+		if len(args) != 1 {
+			fmt.Fprintf(os.Stderr, "specify exactly one positional agument\n")
+			cmd.Usage()
+			os.Exit(1)
+		}
+		if err := RootCmd.GenBashCompletionFile(args[0]); err != nil {
+			fmt.Fprintf(os.Stderr, "error generating bash completion: %s", err)
+			os.Exit(1)
+		}
+	},
+	Hidden: true,
+}
+
+func init() {
+	RootCmd.AddCommand(bashcompCmd)
+}

cmd/config.go

@@ -59,11 +59,13 @@ type SSHStdinServerConnectDescr struct {
 }
 
 type PrunePolicy interface {
+	// Prune filters versions and decide which to keep and which to remove.
+	// Prune **does not** implement the actual removal of the versions.
 	Prune(fs *zfs.DatasetPath, versions []zfs.FilesystemVersion) (keep, remove []zfs.FilesystemVersion, err error)
 }
 
 type PruningJob interface {
-	Pruner(side PrunePolicySide, dryRun bool) (Pruner, error)
+	Pruner(task *Task, side PrunePolicySide, dryRun bool) (Pruner, error)
 }
 
 // A type for constants describing different prune policies of a PruningJob

cmd/config_connect.go

@@ -4,10 +4,11 @@ import (
 	"fmt"
 	"io"
 
+	"context"
 	"github.com/jinzhu/copier"
 	"github.com/mitchellh/mapstructure"
 	"github.com/pkg/errors"
-	"github.com/zrepl/zrepl/sshbytestream"
+	"github.com/problame/go-netssh"
 )
 
 type SSHStdinserverConnecter struct {
@@ -34,11 +35,12 @@ func parseSSHStdinserverConnecter(i map[string]interface{}) (c *SSHStdinserverCo
 }
 
 func (c *SSHStdinserverConnecter) Connect() (rwc io.ReadWriteCloser, err error) {
-	var rpcTransport sshbytestream.SSHTransport
-	if err = copier.Copy(&rpcTransport, c); err != nil {
+
+	var endpoint netssh.Endpoint
+	if err = copier.Copy(&endpoint, c); err != nil {
 		return
 	}
-	if rwc, err = sshbytestream.Outgoing(rpcTransport); err != nil {
+	if rwc, err = netssh.Dial(context.TODO(), endpoint); err != nil {
 		err = errors.WithStack(err)
 		return
 	}

cmd/config_fsvfilter.go

@@ -6,8 +6,18 @@ import (
 	"strings"
 )
 
-type PrefixSnapshotFilter struct {
-	Prefix string
+type PrefixFilter struct {
+	prefix    string
+	fstype    zfs.VersionType
+	fstypeSet bool // optionals anyone?
+}
+
+func NewPrefixFilter(prefix string) *PrefixFilter {
+	return &PrefixFilter{prefix: prefix}
+}
+
+func NewTypedPrefixFilter(prefix string, versionType zfs.VersionType) *PrefixFilter {
+	return &PrefixFilter{prefix, versionType, true}
 }
 
 func parseSnapshotPrefix(i string) (p string, err error) {
@@ -19,15 +29,8 @@ func parseSnapshotPrefix(i string) (p string, err error) {
 	return
 }
 
-func parsePrefixSnapshotFilter(i string) (f *PrefixSnapshotFilter, err error) {
-	if !(len(i) > 0) {
-		err = errors.Errorf("snapshot prefix must be longer than 0 characters")
-		return
-	}
-	f = &PrefixSnapshotFilter{i}
-	return
-}
-
-func (f *PrefixSnapshotFilter) Filter(fsv zfs.FilesystemVersion) (accept bool, err error) {
-	return fsv.Type == zfs.Snapshot && strings.HasPrefix(fsv.Name, f.Prefix), nil
+func (f *PrefixFilter) Filter(fsv zfs.FilesystemVersion) (accept bool, err error) {
+	fstypeMatches := (!f.fstypeSet || fsv.Type == f.fstype)
+	prefixMatches := strings.HasPrefix(fsv.Name, f.prefix)
+	return fstypeMatches && prefixMatches, nil
 }

cmd/config_job_control.go

@@ -1,11 +1,13 @@
 package cmd
 
 import (
+	"bytes"
 	"context"
+	"encoding/json"
 	"github.com/pkg/errors"
+	"io"
 	"net"
 	"net/http"
-	"net/http/pprof"
 )
 
 type ControlJob struct {
@@ -29,8 +31,14 @@ func (j *ControlJob) JobName() string {
 	return j.Name
 }
 
+func (j *ControlJob) JobStatus(ctx context.Context) (*JobStatus, error) {
+	return &JobStatus{Tasks: nil}, nil
+}
+
 const (
-	ControlJobEndpointProfile string = "/debug/pprof/profile"
+	ControlJobEndpointPProf   string = "/debug/pprof"
+	ControlJobEndpointVersion string = "/version"
+	ControlJobEndpointStatus  string = "/status"
 )
 
 func (j *ControlJob) JobStart(ctx context.Context) {
@@ -38,14 +46,35 @@ func (j *ControlJob) JobStart(ctx context.Context) {
 	log := ctx.Value(contextKeyLog).(Logger)
 	defer log.Info("control job finished")
 
+	daemon := ctx.Value(contextKeyDaemon).(*Daemon)
+
 	l, err := ListenUnixPrivate(j.sockaddr)
 	if err != nil {
 		log.WithError(err).Error("error listening")
 		return
 	}
 
+	pprofServer := NewPProfServer(ctx)
+
 	mux := http.NewServeMux()
-	mux.Handle(ControlJobEndpointProfile, requestLogger{log, pprof.Profile})
+	mux.Handle(ControlJobEndpointPProf, requestLogger{log: log, handlerFunc: func(w http.ResponseWriter, r *http.Request) {
+		var msg PprofServerControlMsg
+		err := json.NewDecoder(r.Body).Decode(&msg)
+		if err != nil {
+			log.WithError(err).Error("bad pprof request from client")
+			w.WriteHeader(http.StatusBadRequest)
+		}
+		pprofServer.Control(msg)
+		w.WriteHeader(200)
+	}})
+	mux.Handle(ControlJobEndpointVersion,
+		requestLogger{log: log, handler: jsonResponder{func() (interface{}, error) {
+			return NewZreplVersionInformation(), nil
+		}}})
+	mux.Handle(ControlJobEndpointStatus,
+		requestLogger{log: log, handler: jsonResponder{func() (interface{}, error) {
+			return daemon.Status(), nil
+		}}})
 	server := http.Server{Handler: mux}
 
 outer:
@@ -73,14 +102,42 @@ outer:
 
 }
 
+type jsonResponder struct {
+	producer func() (interface{}, error)
+}
+
+func (j jsonResponder) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	res, err := j.producer()
+	if err != nil {
+		w.WriteHeader(http.StatusInternalServerError)
+		io.WriteString(w, err.Error())
+		return
+	}
+	var buf bytes.Buffer
+	err = json.NewEncoder(&buf).Encode(res)
+	if err != nil {
+		w.WriteHeader(http.StatusInternalServerError)
+		io.WriteString(w, err.Error())
+	} else {
+		io.Copy(w, &buf)
+	}
+}
+
 type requestLogger struct {
 	log         Logger
-	handlerFunc func(w http.ResponseWriter, r *http.Request)
+	handler     http.Handler
+	handlerFunc http.HandlerFunc
 }
 
 func (l requestLogger) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	log := l.log.WithField("method", r.Method).WithField("url", r.URL)
 	log.Info("start")
+	if l.handlerFunc != nil {
 		l.handlerFunc(w, r)
+	} else if l.handler != nil {
+		l.handler.ServeHTTP(w, r)
+	} else {
+		log.Error("no handler or handlerFunc configured")
+	}
 	log.Info("finish")
 }

cmd/config_job_local.go

@@ -20,6 +20,11 @@ type LocalJob struct {
 	PruneLHS          PrunePolicy
 	PruneRHS          PrunePolicy
 	Debug             JobDebugSettings
+	snapperTask       *Task
+	mainTask          *Task
+	handlerTask       *Task
+	pruneRHSTask      *Task
+	pruneLHSTask      *Task
 }
 
 func parseLocalJob(c JobParsingContext, name string, i map[string]interface{}) (j *LocalJob, err error) {
@@ -58,11 +63,11 @@ func parseLocalJob(c JobParsingContext, name string, i map[string]interface{}) (
 		return
 	}
 
-	if j.PruneLHS, err = parsePrunePolicy(asMap.PruneLHS); err != nil {
+	if j.PruneLHS, err = parsePrunePolicy(asMap.PruneLHS, true); err != nil {
 		err = errors.Wrap(err, "cannot parse 'prune_lhs'")
 		return
 	}
-	if j.PruneRHS, err = parsePrunePolicy(asMap.PruneRHS); err != nil {
+	if j.PruneRHS, err = parsePrunePolicy(asMap.PruneRHS, false); err != nil {
 		err = errors.Wrap(err, "cannot parse 'prune_rhs'")
 		return
 	}
@@ -81,8 +86,13 @@ func (j *LocalJob) JobName() string {
 
 func (j *LocalJob) JobStart(ctx context.Context) {
 
-	log := ctx.Value(contextKeyLog).(Logger)
-	defer log.Info("exiting")
+	rootLog := ctx.Value(contextKeyLog).(Logger)
+
+	j.snapperTask = NewTask("snapshot", rootLog)
+	j.mainTask = NewTask("main", rootLog)
+	j.handlerTask = NewTask("handler", rootLog)
+	j.pruneRHSTask = NewTask("prune_rhs", rootLog)
+	j.pruneLHSTask = NewTask("prune_lhs", rootLog)
 
 	local := rpc.NewLocalRPC()
 	// Allow access to any dataset since we control what mapping
@@ -90,78 +100,69 @@ func (j *LocalJob) JobStart(ctx context.Context) {
 	// All local datasets will be passed to its Map() function,
 	// but only those for which a mapping exists will actually be pulled.
 	// We can pay this small performance penalty for now.
-	handler := NewHandler(log.WithField(logTaskField, "handler"), localPullACL{}, &PrefixSnapshotFilter{j.SnapshotPrefix})
+	handler := NewHandler(j.handlerTask.Log(), localPullACL{}, NewPrefixFilter(j.SnapshotPrefix))
 
 	registerEndpoints(local, handler)
 
 	snapper := IntervalAutosnap{
+		task:             j.snapperTask,
 		DatasetFilter:    j.Mapping.AsFilter(),
 		Prefix:           j.SnapshotPrefix,
 		SnapshotInterval: j.Interval,
 	}
 
-	plhs, err := j.Pruner(PrunePolicySideLeft, false)
+	plhs, err := j.Pruner(j.pruneLHSTask, PrunePolicySideLeft, false)
 	if err != nil {
-		log.WithError(err).Error("error creating lhs pruner")
+		rootLog.WithError(err).Error("error creating lhs pruner")
 		return
 	}
-	prhs, err := j.Pruner(PrunePolicySideRight, false)
+	prhs, err := j.Pruner(j.pruneRHSTask, PrunePolicySideRight, false)
 	if err != nil {
-		log.WithError(err).Error("error creating rhs pruner")
+		rootLog.WithError(err).Error("error creating rhs pruner")
 		return
 	}
 
-	makeCtx := func(parent context.Context, taskName string) (ctx context.Context) {
-		return context.WithValue(parent, contextKeyLog, log.WithField(logTaskField, taskName))
-	}
-	var snapCtx, plCtx, prCtx, pullCtx context.Context
-	snapCtx = makeCtx(ctx, "autosnap")
-	plCtx = makeCtx(ctx, "prune_lhs")
-	prCtx = makeCtx(ctx, "prune_rhs")
-	pullCtx = makeCtx(ctx, "repl")
-
 	didSnaps := make(chan struct{})
-	go snapper.Run(snapCtx, didSnaps)
+	go snapper.Run(ctx, didSnaps)
 
 outer:
 	for {
 
 		select {
 		case <-ctx.Done():
+			j.mainTask.Log().WithError(ctx.Err()).Info("context")
 			break outer
 		case <-didSnaps:
-			log.Debug("finished taking snapshots")
-			log.Info("starting replication procedure")
+			j.mainTask.Log().Debug("finished taking snapshots")
+			j.mainTask.Log().Info("starting replication procedure")
 		}
 
-		{
-			log := pullCtx.Value(contextKeyLog).(Logger)
-			log.Debug("replicating from lhs to rhs")
-			err := doPull(PullContext{local, log, j.Mapping, j.InitialReplPolicy})
-			if err != nil {
-				log.WithError(err).Error("error replicating lhs to rhs")
-			}
-			// use a ctx as soon as doPull gains ctx support
+		j.mainTask.Log().Debug("replicating from lhs to rhs")
+		j.mainTask.Enter("replicate")
+		puller := Puller{j.mainTask, local, j.Mapping, j.InitialReplPolicy}
+		puller.Pull()
+		j.mainTask.Finish()
+
+		// use a ctx as soon as Pull gains ctx support
 		select {
 		case <-ctx.Done():
 			break outer
 		default:
 		}
-		}
 
 		var wg sync.WaitGroup
 
-		log.Info("pruning lhs")
+		j.mainTask.Log().Info("pruning lhs")
 		wg.Add(1)
 		go func() {
-			plhs.Run(plCtx)
+			plhs.Run(ctx)
 			wg.Done()
 		}()
 
-		log.Info("pruning rhs")
+		j.mainTask.Log().Info("pruning rhs")
 		wg.Add(1)
 		go func() {
-			prhs.Run(prCtx)
+			prhs.Run(ctx)
 			wg.Done()
 		}()
 
@@ -169,11 +170,18 @@ outer:
 
 	}
 
-	log.WithError(ctx.Err()).Info("context")
-
 }
 
-func (j *LocalJob) Pruner(side PrunePolicySide, dryRun bool) (p Pruner, err error) {
+func (j *LocalJob) JobStatus(ctxt context.Context) (*JobStatus, error) {
+	return &JobStatus{Tasks: []*TaskStatus{
+		j.snapperTask.Status(),
+		j.pruneLHSTask.Status(),
+		j.pruneRHSTask.Status(),
+		j.mainTask.Status(),
+	}}, nil
+}
+
+func (j *LocalJob) Pruner(task *Task, side PrunePolicySide, dryRun bool) (p Pruner, err error) {
 
 	var dsfilter zfs.DatasetFilter
 	var pp PrunePolicy
@@ -194,6 +202,7 @@ func (j *LocalJob) Pruner(side PrunePolicySide, dryRun bool) (p Pruner, err erro
 	}
 
 	p = Pruner{
+		task,
 		time.Now(),
 		dryRun,
 		dsfilter,

cmd/config_job_pull.go

@@ -4,6 +4,7 @@ import (
 	"time"
 
 	"context"
+	"fmt"
 	"github.com/mitchellh/mapstructure"
 	"github.com/pkg/errors"
 	"github.com/zrepl/zrepl/rpc"
@@ -21,6 +22,8 @@ type PullJob struct {
 	InitialReplPolicy InitialReplPolicy
 	Prune             PrunePolicy
 	Debug             JobDebugSettings
+
+	task *Task
 }
 
 func parsePullJob(c JobParsingContext, name string, i map[string]interface{}) (j *PullJob, err error) {
@@ -74,7 +77,7 @@ func parsePullJob(c JobParsingContext, name string, i map[string]interface{}) (j
 		return
 	}
 
-	if j.Prune, err = parsePrunePolicy(asMap.Prune); err != nil {
+	if j.Prune, err = parsePrunePolicy(asMap.Prune, false); err != nil {
 		err = errors.Wrap(err, "cannot parse prune policy")
 		return
 	}
@@ -95,15 +98,31 @@ func (j *PullJob) JobStart(ctx context.Context) {
 
 	log := ctx.Value(contextKeyLog).(Logger)
 	defer log.Info("exiting")
+	j.task = NewTask("main", log)
+
+	// j.task is idle here idle here
 
 	ticker := time.NewTicker(j.Interval)
+	for {
+		j.doRun(ctx)
+		select {
+		case <-ctx.Done():
+			j.task.Log().WithError(ctx.Err()).Info("context")
+			return
+		case <-ticker.C:
+		}
+	}
+}
 
-start:
+func (j *PullJob) doRun(ctx context.Context) {
 
-	log.Info("connecting")
+	j.task.Enter("run")
+	defer j.task.Finish()
+
+	j.task.Log().Info("connecting")
 	rwc, err := j.Connect.Connect()
 	if err != nil {
-		log.WithError(err).Error("error connecting")
+		j.task.Log().WithError(err).Error("error connecting")
 		return
 	}
 
@@ -114,43 +133,34 @@ start:
 
 	client := rpc.NewClient(rwc)
 	if j.Debug.RPC.Log {
-		client.SetLogger(log, true)
+		client.SetLogger(j.task.Log(), true)
 	}
 
-	log.Info("starting pull")
+	j.task.Enter("pull")
+	puller := Puller{j.task, client, j.Mapping, j.InitialReplPolicy}
+	puller.Pull()
+	closeRPCWithTimeout(j.task, client, time.Second*1, "")
+	rwc.Close()
+	j.task.Finish()
 
-	pullLog := log.WithField(logTaskField, "pull")
-	err = doPull(PullContext{client, pullLog, j.Mapping, j.InitialReplPolicy})
+	j.task.Enter("prune")
+	pruner, err := j.Pruner(j.task, PrunePolicySideDefault, false)
 	if err != nil {
-		log.WithError(err).Error("error doing pull")
-	}
-
-	closeRPCWithTimeout(log, client, time.Second*10, "")
-
-	log.Info("starting prune")
-	prunectx := context.WithValue(ctx, contextKeyLog, log.WithField(logTaskField, "prune"))
-	pruner, err := j.Pruner(PrunePolicySideDefault, false)
-	if err != nil {
-		log.WithError(err).Error("error creating pruner")
-		return
-	}
-
-	pruner.Run(prunectx)
-	log.Info("finish prune")
-
-	log.Info("wait for next interval")
-	select {
-	case <-ctx.Done():
-		log.WithError(ctx.Err()).Info("context")
-		return
-	case <-ticker.C:
-		goto start
+		j.task.Log().WithError(err).Error("error creating pruner")
+	} else {
+		pruner.Run(ctx)
 	}
+	j.task.Finish()
 
 }
 
-func (j *PullJob) Pruner(side PrunePolicySide, dryRun bool) (p Pruner, err error) {
+func (j *PullJob) JobStatus(ctxt context.Context) (*JobStatus, error) {
+	return &JobStatus{Tasks: []*TaskStatus{j.task.Status()}}, nil
+}
+
+func (j *PullJob) Pruner(task *Task, side PrunePolicySide, dryRun bool) (p Pruner, err error) {
 	p = Pruner{
+		task,
 		time.Now(),
 		dryRun,
 		j.pruneFilter,
@@ -160,6 +170,26 @@ func (j *PullJob) Pruner(side PrunePolicySide, dryRun bool) (p Pruner, err error
 	return
 }
 
-func (j *PullJob) doRun(ctx context.Context) {
+func closeRPCWithTimeout(task *Task, remote rpc.RPCClient, timeout time.Duration, goodbye string) {
 
+	task.Log().Info("closing rpc connection")
+
+	ch := make(chan error)
+	go func() {
+		ch <- remote.Close()
+		close(ch)
+	}()
+
+	var err error
+	select {
+	case <-time.After(timeout):
+		err = fmt.Errorf("timeout exceeded (%s)", timeout)
+	case closeRequestErr := <-ch:
+		err = closeRequestErr
+	}
+
+	if err != nil {
+		task.Log().WithError(err).Error("error closing connection")
+	}
+	return
 }

cmd/config_job_source.go

@@ -19,6 +19,9 @@ type SourceJob struct {
 	Interval       time.Duration
 	Prune          PrunePolicy
 	Debug          JobDebugSettings
+	serveTask      *Task
+	autosnapTask   *Task
+	pruneTask      *Task
 }
 
 func parseSourceJob(c JobParsingContext, name string, i map[string]interface{}) (j *SourceJob, err error) {
@@ -56,7 +59,7 @@ func parseSourceJob(c JobParsingContext, name string, i map[string]interface{})
 		return
 	}
 
-	if j.Prune, err = parsePrunePolicy(asMap.Prune); err != nil {
+	if j.Prune, err = parsePrunePolicy(asMap.Prune, true); err != nil {
 		err = errors.Wrap(err, "cannot parse 'prune'")
 		return
 	}
@@ -78,20 +81,22 @@ func (j *SourceJob) JobStart(ctx context.Context) {
 	log := ctx.Value(contextKeyLog).(Logger)
 	defer log.Info("exiting")
 
-	a := IntervalAutosnap{DatasetFilter: j.Filesystems, Prefix: j.SnapshotPrefix, SnapshotInterval: j.Interval}
-	p, err := j.Pruner(PrunePolicySideDefault, false)
+	j.autosnapTask = NewTask("autosnap", log)
+	j.pruneTask = NewTask("prune", log)
+	j.serveTask = NewTask("serve", log)
+
+	a := IntervalAutosnap{j.autosnapTask, j.Filesystems, j.SnapshotPrefix, j.Interval}
+	p, err := j.Pruner(j.pruneTask, PrunePolicySideDefault, false)
+
 	if err != nil {
 		log.WithError(err).Error("error creating pruner")
 		return
 	}
 
-	snapContext := context.WithValue(ctx, contextKeyLog, log.WithField(logTaskField, "autosnap"))
-	prunerContext := context.WithValue(ctx, contextKeyLog, log.WithField(logTaskField, "prune"))
-	serveContext := context.WithValue(ctx, contextKeyLog, log.WithField(logTaskField, "serve"))
 	didSnaps := make(chan struct{})
 
-	go j.serve(serveContext)
-	go a.Run(snapContext, didSnaps)
+	go j.serve(ctx, j.serveTask)
+	go a.Run(ctx, didSnaps)
 
 outer:
 	for {
@@ -100,16 +105,26 @@ outer:
 			break outer
 		case <-didSnaps:
 			log.Info("starting pruner")
-			p.Run(prunerContext)
+			p.Run(ctx)
 			log.Info("pruner done")
 		}
 	}
-	log.WithError(prunerContext.Err()).Info("context")
+	log.WithError(ctx.Err()).Info("context")
 
 }
 
-func (j *SourceJob) Pruner(side PrunePolicySide, dryRun bool) (p Pruner, err error) {
+func (j *SourceJob) JobStatus(ctxt context.Context) (*JobStatus, error) {
+	return &JobStatus{
+		Tasks: []*TaskStatus{
+			j.autosnapTask.Status(),
+			j.pruneTask.Status(),
+			j.serveTask.Status(),
+		}}, nil
+}
+
+func (j *SourceJob) Pruner(task *Task, side PrunePolicySide, dryRun bool) (p Pruner, err error) {
 	p = Pruner{
+		task,
 		time.Now(),
 		dryRun,
 		j.Filesystems,
@@ -119,13 +134,11 @@ func (j *SourceJob) Pruner(side PrunePolicySide, dryRun bool) (p Pruner, err err
 	return
 }
 
-func (j *SourceJob) serve(ctx context.Context) {
-
-	log := ctx.Value(contextKeyLog).(Logger)
+func (j *SourceJob) serve(ctx context.Context, task *Task) {
 
 	listener, err := j.Serve.Listen()
 	if err != nil {
-		log.WithError(err).Error("error listening")
+		task.Log().WithError(err).Error("error listening")
 		return
 	}
 
@@ -154,44 +167,84 @@ outer:
 		case rwcMsg := <-rwcChan:
 
 			if rwcMsg.err != nil {
-				log.WithError(err).Error("error accepting connection")
+				task.Log().WithError(err).Error("error accepting connection")
 				break outer
 			}
 
-			rwc, err := util.NewReadWriteCloserLogger(rwcMsg.rwc, j.Debug.Conn.ReadDump, j.Debug.Conn.WriteDump)
-			if err != nil {
-				panic(err)
-			}
-
-			// construct connection handler
-			handler := NewHandler(log, j.Filesystems, &PrefixSnapshotFilter{j.SnapshotPrefix})
-
-			// handle connection
-			rpcServer := rpc.NewServer(rwc)
-			if j.Debug.RPC.Log {
-				rpclog := log.WithField("subsystem", "rpc")
-				rpcServer.SetLogger(rpclog, true)
-			}
-			registerEndpoints(rpcServer, handler)
-			if err = rpcServer.Serve(); err != nil {
-				log.WithError(err).Error("error serving connection")
-			}
-			rwc.Close()
+			j.handleConnection(rwcMsg.rwc, task)
 
 		case <-ctx.Done():
-			log.WithError(ctx.Err()).Info("context")
+			task.Log().WithError(ctx.Err()).Info("context")
 			break outer
 
 		}
 
 	}
 
-	log.Info("closing listener")
+	task.Enter("close_listener")
+	defer task.Finish()
 	err = listener.Close()
 	if err != nil {
-		log.WithError(err).Error("error closing listener")
+		task.Log().WithError(err).Error("error closing listener")
 	}
 
 	return
 
 }
+
+func (j *SourceJob) handleConnection(rwc io.ReadWriteCloser, task *Task) {
+
+	task.Enter("handle_connection")
+	defer task.Finish()
+
+	task.Log().Info("handling client connection")
+
+	rwc, err := util.NewReadWriteCloserLogger(rwc, j.Debug.Conn.ReadDump, j.Debug.Conn.WriteDump)
+	if err != nil {
+		panic(err)
+	}
+
+	// construct connection handler
+	handler := NewHandler(task.Log(), j.Filesystems, NewPrefixFilter(j.SnapshotPrefix))
+
+	// handle connection
+	rpcServer := rpc.NewServer(rwc)
+	if j.Debug.RPC.Log {
+		rpclog := task.Log().WithField("subsystem", "rpc")
+		rpcServer.SetLogger(rpclog, true)
+	}
+	registerEndpoints(rpcServer, handler)
+	if err = rpcServer.Serve(); err != nil {
+		task.Log().WithError(err).Error("error serving connection")
+	}
+
+	// wait for client to close connection
+	// FIXME: we cannot just close it like we would to with a TCP socket because
+	// FIXME: go-nettsh's Close() may overtake the remaining data in the pipe
+	const CLIENT_HANGUP_TIMEOUT = 1 * time.Second
+	task.Log().
+		WithField("timeout", CLIENT_HANGUP_TIMEOUT).
+		Debug("waiting for client to hang up")
+
+	wchan := make(chan error)
+	go func() {
+		var pseudo [1]byte
+		_, err := io.ReadFull(rwc, pseudo[:])
+		wchan <- err
+	}()
+	var werr error
+	select {
+	case werr = <-wchan:
+		// all right
+	case <-time.After(CLIENT_HANGUP_TIMEOUT):
+		werr = errors.New("client did not close connection within timeout")
+	}
+	if werr != nil && werr != io.EOF {
+		task.Log().WithError(werr).
+			Error("error waiting for client to hang up")
+	}
+	task.Log().Info("closing client connection")
+	if err = rwc.Close(); err != nil {
+		task.Log().WithError(err).Error("error force-closing connection")
+	}
+}

cmd/config_logging.go

@@ -3,6 +3,7 @@ package cmd
 import (
 	"crypto/tls"
 	"crypto/x509"
+	"github.com/mattn/go-isatty"
 	"github.com/mitchellh/mapstructure"
 	"github.com/pkg/errors"
 	"github.com/zrepl/zrepl/logger"
@@ -12,17 +13,18 @@ import (
 )
 
 type LoggingConfig struct {
-	Outlets logger.Outlets
+	Outlets *logger.Outlets
 }
 
-type SetNoMetadataFormatter interface {
-	SetNoMetadata(noMetadata bool)
-}
+type MetadataFlags int64
 
-type OutletCommon struct {
-	MinLevel  logger.Level
-	Formatter EntryFormatter
-}
+const (
+	MetadataTime MetadataFlags = 1 << iota
+	MetadataLevel
+
+	MetadataNone MetadataFlags = 0
+	MetadataAll  MetadataFlags = ^0
+)
 
 func parseLogging(i interface{}) (c *LoggingConfig, err error) {
 
@@ -109,13 +111,12 @@ func parseOutlet(i interface{}) (o logger.Outlet, level logger.Level, err error)
 		return
 	}
 
-	common := &OutletCommon{}
-	common.MinLevel, err = logger.ParseLevel(in.Level)
+	minLevel, err := logger.ParseLevel(in.Level)
 	if err != nil {
 		err = errors.Wrap(err, "cannot parse 'level' field")
 		return
 	}
-	common.Formatter, err = parseLogFormat(in.Format)
+	formatter, err := parseLogFormat(in.Format)
 	if err != nil {
 		err = errors.Wrap(err, "cannot parse")
 		return
@@ -123,29 +124,41 @@ func parseOutlet(i interface{}) (o logger.Outlet, level logger.Level, err error)
 
 	switch in.Outlet {
 	case "stdout":
-		o, err = parseStdoutOutlet(i, common)
+		o, err = parseStdoutOutlet(i, formatter)
 	case "tcp":
-		o, err = parseTCPOutlet(i, common)
+		o, err = parseTCPOutlet(i, formatter)
 	case "syslog":
-		o, err = parseSyslogOutlet(i, common)
+		o, err = parseSyslogOutlet(i, formatter)
 	default:
 		err = errors.Errorf("unknown outlet type '%s'", in.Outlet)
 	}
-	return o, common.MinLevel, err
+	return o, minLevel, err
 
 }
 
-func parseStdoutOutlet(i interface{}, common *OutletCommon) (WriterOutlet, error) {
+func parseStdoutOutlet(i interface{}, formatter EntryFormatter) (WriterOutlet, error) {
+
+	var in struct {
+		Time bool
+	}
+	if err := mapstructure.Decode(i, &in); err != nil {
+		return WriterOutlet{}, errors.Wrap(err, "invalid structure for stdout outlet")
+	}
+
+	flags := MetadataAll
+	writer := os.Stdout
+	if !isatty.IsTerminal(writer.Fd()) && !in.Time {
+		flags &= ^MetadataTime
+	}
+
+	formatter.SetMetadataFlags(flags)
 	return WriterOutlet{
-		common.Formatter,
+		formatter,
 		os.Stdout,
 	}, nil
 }
 
-func parseTCPOutlet(i interface{}, common *OutletCommon) (out *TCPOutlet, err error) {
-
-	out = &TCPOutlet{}
-	out.Formatter = common.Formatter
+func parseTCPOutlet(i interface{}, formatter EntryFormatter) (out *TCPOutlet, err error) {
 
 	var in struct {
 		Net           string
@@ -161,13 +174,19 @@ func parseTCPOutlet(i interface{}, common *OutletCommon) (out *TCPOutlet, err er
 		return nil, errors.Wrap(err, "mapstructure error")
 	}
 
-	out.RetryInterval, err = time.ParseDuration(in.RetryInterval)
+	retryInterval, err := time.ParseDuration(in.RetryInterval)
 	if err != nil {
 		return nil, errors.Wrap(err, "cannot parse 'retry_interval'")
 	}
 
-	out.Net, out.Address = in.Net, in.Address
+	if len(in.Net) == 0 {
+		return nil, errors.New("field 'net' must not be empty")
+	}
+	if len(in.Address) == 0 {
+		return nil, errors.New("field 'address' must not be empty")
+	}
 
+	var tlsConfig *tls.Config
 	if in.TLS != nil {
 
 		cert, err := tls.LoadX509KeyPair(in.TLS.Cert, in.TLS.Key)
@@ -194,19 +213,20 @@ func parseTCPOutlet(i interface{}, common *OutletCommon) (out *TCPOutlet, err er
 			return nil, errors.Wrap(err, "cannot load root ca pool")
 		}
 
-		out.TLS = &tls.Config{
+		tlsConfig = &tls.Config{
 			Certificates: []tls.Certificate{cert},
 			RootCAs:      rootCAs,
 		}
 
-		out.TLS.BuildNameToCertificate()
+		tlsConfig.BuildNameToCertificate()
 	}
 
-	return
+	formatter.SetMetadataFlags(MetadataAll)
+	return NewTCPOutlet(formatter, in.Net, in.Address, tlsConfig, retryInterval), nil
 
 }
 
-func parseSyslogOutlet(i interface{}, common *OutletCommon) (out *SyslogOutlet, err error) {
+func parseSyslogOutlet(i interface{}, formatter EntryFormatter) (out *SyslogOutlet, err error) {
 
 	var in struct {
 		RetryInterval string `mapstructure:"retry_interval"`
@@ -216,10 +236,8 @@ func parseSyslogOutlet(i interface{}, common *OutletCommon) (out *SyslogOutlet,
 	}
 
 	out = &SyslogOutlet{}
-	out.Formatter = common.Formatter
-	if f, ok := out.Formatter.(SetNoMetadataFormatter); ok {
-		f.SetNoMetadata(true)
-	}
+	out.Formatter = formatter
+	out.Formatter.SetMetadataFlags(MetadataNone)
 
 	out.RetryInterval = 0 // default to 0 as we assume local syslog will just work
 	if in.RetryInterval != "" {

cmd/config_parse.go

@@ -220,7 +220,7 @@ err:
 	return
 }
 
-func parsePrunePolicy(v map[string]interface{}) (p PrunePolicy, err error) {
+func parsePrunePolicy(v map[string]interface{}, willSeeBookmarks bool) (p PrunePolicy, err error) {
 
 	policyName, err := extractStringField(v, "policy", true)
 	if err != nil {
@@ -229,14 +229,13 @@ func parsePrunePolicy(v map[string]interface{}) (p PrunePolicy, err error) {
 
 	switch policyName {
 	case "grid":
-		return parseGridPrunePolicy(v)
+		return parseGridPrunePolicy(v, willSeeBookmarks)
 	case "noprune":
 		return NoPrunePolicy{}, nil
 	default:
 		err = errors.Errorf("unknown policy '%s'", policyName)
 		return
 	}
-
 }
 
 func parseAuthenticatedChannelListenerFactory(c JobParsingContext, v map[string]interface{}) (p AuthenticatedChannelListenerFactory, err error) {

cmd/config_prune_grid.go

@@ -6,6 +6,7 @@ import (
 	"github.com/pkg/errors"
 	"github.com/zrepl/zrepl/util"
 	"github.com/zrepl/zrepl/zfs"
+	"math"
 	"regexp"
 	"sort"
 	"strconv"
@@ -15,8 +16,11 @@ import (
 
 type GridPrunePolicy struct {
 	RetentionGrid *util.RetentionGrid
+	MaxBookmarks  int
 }
 
+const GridPrunePolicyMaxBookmarksKeepAll = -1
+
 type retentionGridAdaptor struct {
 	zfs.FilesystemVersion
 }
@@ -29,12 +33,27 @@ func (a retentionGridAdaptor) LessThan(b util.RetentionGridEntry) bool {
 	return a.CreateTXG < b.(retentionGridAdaptor).CreateTXG
 }
 
+// Prune filters snapshots with the retention grid.
+// Bookmarks are deleted such that KeepBookmarks are kept in the end.
+// The oldest bookmarks are removed first.
 func (p *GridPrunePolicy) Prune(_ *zfs.DatasetPath, versions []zfs.FilesystemVersion) (keep, remove []zfs.FilesystemVersion, err error) {
+	skeep, sremove := p.pruneSnapshots(versions)
+	keep, remove = p.pruneBookmarks(skeep)
+	remove = append(remove, sremove...)
+	return keep, remove, nil
+}
+
+func (p *GridPrunePolicy) pruneSnapshots(versions []zfs.FilesystemVersion) (keep, remove []zfs.FilesystemVersion) {
 
 	// Build adaptors for retention grid
-	adaptors := make([]util.RetentionGridEntry, len(versions))
+	keep = []zfs.FilesystemVersion{}
+	adaptors := make([]util.RetentionGridEntry, 0)
 	for fsv := range versions {
-		adaptors[fsv] = retentionGridAdaptor{versions[fsv]}
+		if versions[fsv].Type != zfs.Snapshot {
+			keep = append(keep, versions[fsv])
+			continue
+		}
+		adaptors = append(adaptors, retentionGridAdaptor{versions[fsv]})
 	}
 
 	sort.SliceStable(adaptors, func(i, j int) bool {
@@ -46,9 +65,8 @@ func (p *GridPrunePolicy) Prune(_ *zfs.DatasetPath, versions []zfs.FilesystemVer
 	keepa, removea := p.RetentionGrid.FitEntries(now, adaptors)
 
 	// Revert adaptors
-	keep = make([]zfs.FilesystemVersion, len(keepa))
 	for i := range keepa {
-		keep[i] = keepa[i].(retentionGridAdaptor).FilesystemVersion
+		keep = append(keep, keepa[i].(retentionGridAdaptor).FilesystemVersion)
 	}
 	remove = make([]zfs.FilesystemVersion, len(removea))
 	for i := range removea {
@@ -58,20 +76,60 @@ func (p *GridPrunePolicy) Prune(_ *zfs.DatasetPath, versions []zfs.FilesystemVer
 
 }
 
-func parseGridPrunePolicy(e map[string]interface{}) (p *GridPrunePolicy, err error) {
+func (p *GridPrunePolicy) pruneBookmarks(versions []zfs.FilesystemVersion) (keep, remove []zfs.FilesystemVersion) {
 
-	var i struct {
-		Grid string
+	if p.MaxBookmarks == GridPrunePolicyMaxBookmarksKeepAll {
+		return versions, []zfs.FilesystemVersion{}
 	}
 
-	if err = mapstructure.Decode(e, &i); err != nil {
+	keep = []zfs.FilesystemVersion{}
+	bookmarks := make([]zfs.FilesystemVersion, 0)
+	for fsv := range versions {
+		if versions[fsv].Type != zfs.Bookmark {
+			keep = append(keep, versions[fsv])
+			continue
+		}
+		bookmarks = append(bookmarks, versions[fsv])
+	}
+
+	if len(bookmarks) == 0 {
+		return keep, []zfs.FilesystemVersion{}
+	}
+	if len(bookmarks) < p.MaxBookmarks {
+		keep = append(keep, bookmarks...)
+		return keep, []zfs.FilesystemVersion{}
+	}
+
+	// NOTE: sorting descending by descending by createtxg <=> sorting ascending wrt creation time
+	sort.SliceStable(bookmarks, func(i, j int) bool {
+		return (bookmarks[i].CreateTXG > bookmarks[j].CreateTXG)
+	})
+
+	keep = append(keep, bookmarks[:p.MaxBookmarks]...)
+	remove = bookmarks[p.MaxBookmarks:]
+
+	return keep, remove
+}
+
+func parseGridPrunePolicy(e map[string]interface{}, willSeeBookmarks bool) (p *GridPrunePolicy, err error) {
+
+	const KeepBookmarksAllString = "all"
+	var i struct {
+		Grid          string
+		KeepBookmarks string `mapstructure:"keep_bookmarks"`
+	}
+
+	dec, err := mapstructure.NewDecoder(&mapstructure.DecoderConfig{Result: &i, WeaklyTypedInput: true})
+	if err != nil {
+		err = errors.Wrap(err, "mapstructure error")
+		return
+	}
+	if err = dec.Decode(e); err != nil {
 		err = errors.Wrapf(err, "mapstructure error")
 		return
 	}
 
-	p = &GridPrunePolicy{}
-
-	// Parse grid policy
+	// Parse grid
 	intervals, err := parseRetentionGridIntervalsString(i.Grid)
 	if err != nil {
 		err = fmt.Errorf("cannot parse retention grid: %s", err)
@@ -97,9 +155,22 @@ func parseGridPrunePolicy(e map[string]interface{}) (p *GridPrunePolicy, err err
 		lastDuration = intervals[i].Length
 
 	}
-	p.RetentionGrid = util.NewRetentionGrid(intervals)
 
-	return
+	// Parse KeepBookmarks
+	keepBookmarks := 0
+	if i.KeepBookmarks == KeepBookmarksAllString || (i.KeepBookmarks == "" && !willSeeBookmarks) {
+		keepBookmarks = GridPrunePolicyMaxBookmarksKeepAll
+	} else {
+		i, err := strconv.ParseInt(i.KeepBookmarks, 10, 32)
+		if err != nil || i <= 0 || i > math.MaxInt32 {
+			return nil, errors.Errorf("keep_bookmarks must be positive integer or 'all'")
+		}
+		keepBookmarks = int(i)
+	}
+	return &GridPrunePolicy{
+		util.NewRetentionGrid(intervals),
+		keepBookmarks,
+	}, nil
 }
 
 var retentionStringIntervalRegex *regexp.Regexp = regexp.MustCompile(`^\s*(\d+)\s*x\s*([^\(]+)\s*(\((.*)\))?\s*$`)

cmd/config_serve_stdinserver.go

@@ -1,18 +1,16 @@
 package cmd
 
 import (
-	"github.com/ftrvxmtrx/fd"
 	"github.com/mitchellh/mapstructure"
 	"github.com/pkg/errors"
+	"github.com/problame/go-netssh"
 	"io"
-	"net"
-	"os"
 	"path"
 )
 
 type StdinserverListenerFactory struct {
 	ClientIdentity string `mapstructure:"client_identity"`
-	sockaddr       *net.UnixAddr
+	sockpath       string
 }
 
 func parseStdinserverListenerFactory(c JobParsingContext, i map[string]interface{}) (f *StdinserverListenerFactory, err error) {
@@ -27,78 +25,32 @@ func parseStdinserverListenerFactory(c JobParsingContext, i map[string]interface
 		return
 	}
 
-	f.sockaddr, err = stdinserverListenerSocket(c.Global.Serve.Stdinserver.SockDir, f.ClientIdentity)
-	if err != nil {
-		return
-	}
+	f.sockpath = path.Join(c.Global.Serve.Stdinserver.SockDir, f.ClientIdentity)
 
 	return
 }
 
-func stdinserverListenerSocket(sockdir, clientIdentity string) (addr *net.UnixAddr, err error) {
-	sockpath := path.Join(sockdir, clientIdentity)
-	addr, err = net.ResolveUnixAddr("unix", sockpath)
-	if err != nil {
-		return nil, errors.Wrap(err, "cannot resolve unix address")
-	}
-	return addr, nil
-}
-
 func (f *StdinserverListenerFactory) Listen() (al AuthenticatedChannelListener, err error) {
 
-	ul, err := ListenUnixPrivate(f.sockaddr)
-	if err != nil {
-		return nil, errors.Wrapf(err, "cannot listen on unix socket %s", f.sockaddr)
+	if err = PreparePrivateSockpath(f.sockpath); err != nil {
+		return nil, err
 	}
 
-	l := &StdinserverListener{ul}
-
-	return l, nil
+	l, err := netssh.Listen(f.sockpath)
+	if err != nil {
+		return nil, err
+	}
+	return StdinserverListener{l}, nil
 }
 
 type StdinserverListener struct {
-	l *net.UnixListener
+	l *netssh.Listener
 }
 
-type fdRWC struct {
-	stdin, stdout *os.File
-	control       *net.UnixConn
+func (l StdinserverListener) Accept() (ch io.ReadWriteCloser, err error) {
+	return l.l.Accept()
 }
 
-func (f fdRWC) Read(p []byte) (n int, err error) {
-	return f.stdin.Read(p)
-}
-
-func (f fdRWC) Write(p []byte) (n int, err error) {
-	return f.stdout.Write(p)
-}
-
-func (f fdRWC) Close() (err error) {
-	f.stdin.Close()
-	f.stdout.Close()
-	return f.control.Close()
-}
-
-func (l *StdinserverListener) Accept() (ch io.ReadWriteCloser, err error) {
-	c, err := l.l.Accept()
-	if err != nil {
-		err = errors.Wrap(err, "error accepting on unix listener")
-		return
-	}
-
-	// Read the stdin and stdout of the stdinserver command
-	files, err := fd.Get(c.(*net.UnixConn), 2, []string{"stdin", "stdout"})
-	if err != nil {
-		err = errors.Wrap(err, "error receiving fds from stdinserver command")
-		c.Close()
-	}
-
-	rwc := fdRWC{files[0], files[1], c.(*net.UnixConn)}
-
-	return rwc, nil
-
-}
-
-func (l *StdinserverListener) Close() (err error) {
-	return l.l.Close() // removes socket file automatically
+func (l StdinserverListener) Close() (err error) {
+	return l.l.Close()
 }

cmd/control.go

@@ -1,15 +1,22 @@
 package cmd
 
 import (
+	"bytes"
 	"context"
+	"encoding/json"
 	"fmt"
+	"github.com/dustin/go-humanize"
+	"github.com/pkg/errors"
 	"github.com/spf13/cobra"
+	"github.com/zrepl/zrepl/logger"
 	"io"
 	golog "log"
 	"net"
 	"net/http"
-	"net/url"
 	"os"
+	"sort"
+	"strings"
+	"time"
 )
 
 var controlCmd = &cobra.Command{
@@ -18,18 +25,78 @@ var controlCmd = &cobra.Command{
 }
 
 var pprofCmd = &cobra.Command{
-	Use:   "pprof cpu OUTFILE",
-	Short: "pprof CPU of daemon to OUTFILE (- for stdout)",
+	Use:   "pprof off | [on TCP_LISTEN_ADDRESS]",
+	Short: "start a http server exposing go-tool-compatible profiling endpoints at TCP_LISTEN_ADDRESS",
 	Run:   doControlPProf,
+	PreRunE: func(cmd *cobra.Command, args []string) error {
+		if cmd.Flags().NArg() < 1 {
+			goto enargs
+		}
+		switch cmd.Flags().Arg(0) {
+		case "on":
+			pprofCmdArgs.msg.Run = true
+			if cmd.Flags().NArg() != 2 {
+				return errors.New("must specify TCP_LISTEN_ADDRESS as second positional argument")
+			}
+			pprofCmdArgs.msg.HttpListenAddress = cmd.Flags().Arg(1)
+		case "off":
+			if cmd.Flags().NArg() != 1 {
+				goto enargs
+			}
+			pprofCmdArgs.msg.Run = false
+		}
+		return nil
+	enargs:
+		return errors.New("invalid number of positional arguments")
+
+	},
 }
 var pprofCmdArgs struct {
-	seconds int64
+	msg PprofServerControlMsg
+}
+
+var controlVersionCmd = &cobra.Command{
+	Use:   "version",
+	Short: "print version of running zrepl daemon",
+	Run:   doControLVersionCmd,
+}
+
+var controlStatusCmdArgs struct {
+	format      string
+	level       logger.Level
+	onlyShowJob string
+}
+
+var controlStatusCmd = &cobra.Command{
+	Use:   "status [JOB_NAME]",
+	Short: "get current status",
+	Run:   doControlStatusCmd,
 }
 
 func init() {
 	RootCmd.AddCommand(controlCmd)
 	controlCmd.AddCommand(pprofCmd)
-	pprofCmd.Flags().Int64Var(&pprofCmdArgs.seconds, "seconds", 30, "seconds to profile")
+	controlCmd.AddCommand(controlVersionCmd)
+	controlCmd.AddCommand(controlStatusCmd)
+	controlStatusCmd.Flags().StringVar(&controlStatusCmdArgs.format, "format", "human", "output format (human|raw)")
+	controlStatusCmdArgs.level = logger.Warn
+	controlStatusCmd.Flags().Var(&controlStatusCmdArgs.level, "level", "minimum log level to show")
+}
+
+func controlHttpClient() (client http.Client, err error) {
+
+	conf, err := ParseConfig(rootArgs.configFile)
+	if err != nil {
+		return http.Client{}, err
+	}
+
+	return http.Client{
+		Transport: &http.Transport{
+			DialContext: func(_ context.Context, _, _ string) (net.Conn, error) {
+				return net.Dial("unix", conf.Global.Control.Sockpath)
+			},
+		},
+	}, nil
 }
 
 func doControlPProf(cmd *cobra.Command, args []string) {
@@ -41,60 +108,198 @@ func doControlPProf(cmd *cobra.Command, args []string) {
 		os.Exit(1)
 	}
 
-	conf, err := ParseConfig(rootArgs.configFile)
+	log.Printf("connecting to zrepl daemon")
+	httpc, err := controlHttpClient()
 	if err != nil {
 		log.Printf("error parsing config: %s", err)
 		die()
 	}
 
-	if cmd.Flags().Arg(0) != "cpu" {
-		log.Printf("only CPU profiles are supported")
-		log.Printf("%s", cmd.UsageString())
+	var buf bytes.Buffer
+	if err := json.NewEncoder(&buf).Encode(&pprofCmdArgs.msg); err != nil {
+		log.Printf("error marshaling request: %s", err)
 		die()
 	}
-
-	outfn := cmd.Flags().Arg(1)
-	if outfn == "" {
-		log.Printf("must specify output filename")
-		log.Printf("%s", cmd.UsageString())
-		die()
-	}
-	var out io.Writer
-	if outfn == "-" {
-		out = os.Stdout
-	} else {
-		out, err = os.Create(outfn)
-		if err != nil {
-			log.Printf("error creating output file: %s", err)
-			die()
-		}
-	}
-
-	log.Printf("connecting to daemon")
-	httpc := http.Client{
-		Transport: &http.Transport{
-			DialContext: func(_ context.Context, _, _ string) (net.Conn, error) {
-				return net.Dial("unix", conf.Global.Control.Sockpath)
-			},
-		},
-	}
-
-	log.Printf("profiling...")
-	v := url.Values{}
-	v.Set("seconds", fmt.Sprintf("%d", pprofCmdArgs.seconds))
-	v.Encode()
-	resp, err := httpc.Get("http://unix" + ControlJobEndpointProfile + "?" + v.Encode())
+	_, err = httpc.Post("http://unix"+ControlJobEndpointPProf, "application/json", &buf)
 	if err != nil {
 		log.Printf("error: %s", err)
 		die()
 	}
 
-	_, err = io.Copy(out, resp.Body)
+	log.Printf("finished")
+}
+
+func doControLVersionCmd(cmd *cobra.Command, args []string) {
+
+	log := golog.New(os.Stderr, "", 0)
+
+	die := func() {
+		log.Printf("exiting after error")
+		os.Exit(1)
+	}
+
+	httpc, err := controlHttpClient()
 	if err != nil {
-		log.Printf("error writing profile: %s", err)
+		log.Printf("could not connect to daemon: %s", err)
 		die()
 	}
 
-	log.Printf("finished")
+	resp, err := httpc.Get("http://unix" + ControlJobEndpointVersion)
+	if err != nil {
+		log.Printf("error: %s", err)
+		die()
+	} else if resp.StatusCode != http.StatusOK {
+		var msg bytes.Buffer
+		io.CopyN(&msg, resp.Body, 4096)
+		log.Printf("error: %s", msg.String())
+		die()
+	}
+
+	var info ZreplVersionInformation
+	err = json.NewDecoder(resp.Body).Decode(&info)
+	if err != nil {
+		log.Printf("error unmarshaling response: %s", err)
+		die()
+	}
+
+	fmt.Println(info.String())
+
+}
+
+func doControlStatusCmd(cmd *cobra.Command, args []string) {
+
+	log := golog.New(os.Stderr, "", 0)
+
+	die := func() {
+		log.Print("exiting after error")
+		os.Exit(1)
+	}
+
+	if len(args) == 1 {
+		controlStatusCmdArgs.onlyShowJob = args[0]
+	} else if len(args) > 1 {
+		log.Print("can only specify one job as positional argument")
+		cmd.Usage()
+		die()
+	}
+
+	httpc, err := controlHttpClient()
+	if err != nil {
+		log.Printf("could not connect to daemon: %s", err)
+		die()
+	}
+
+	resp, err := httpc.Get("http://unix" + ControlJobEndpointStatus)
+	if err != nil {
+		log.Printf("error: %s", err)
+		die()
+	} else if resp.StatusCode != http.StatusOK {
+		var msg bytes.Buffer
+		io.CopyN(&msg, resp.Body, 4096)
+		log.Printf("error: %s", msg.String())
+		die()
+	}
+
+	var status DaemonStatus
+	err = json.NewDecoder(resp.Body).Decode(&status)
+	if err != nil {
+		log.Printf("error unmarshaling response: %s", err)
+		die()
+	}
+
+	switch controlStatusCmdArgs.format {
+	case "raw":
+		enc := json.NewEncoder(os.Stdout)
+		enc.SetIndent("", "  ")
+		if err := enc.Encode(status); err != nil {
+			log.Panic(err)
+		}
+	case "human":
+
+		formatter := HumanFormatter{}
+		formatter.SetMetadataFlags(MetadataAll)
+		formatter.SetIgnoreFields([]string{
+			logJobField,
+		})
+		jobNames := make([]string, 0, len(status.Jobs))
+		for name, _ := range status.Jobs {
+			jobNames = append(jobNames, name)
+		}
+		sort.Slice(jobNames, func(i, j int) bool {
+			return strings.Compare(jobNames[i], jobNames[j]) == -1
+		})
+		now := time.Now()
+		for _, name := range jobNames {
+
+			if controlStatusCmdArgs.onlyShowJob != "" && name != controlStatusCmdArgs.onlyShowJob {
+				continue
+			}
+
+			job := status.Jobs[name]
+			jobLogEntries := make([]logger.Entry, 0)
+			informAboutError := false
+
+			fmt.Printf("Job '%s':\n", name)
+			for _, task := range job.Tasks {
+
+				var header bytes.Buffer
+				fmt.Fprintf(&header, "  Task '%s': ", task.Name)
+				if !task.Idle {
+					fmt.Fprint(&header, strings.Join(task.ActivityStack, "."))
+				} else {
+					fmt.Fprint(&header, "<idle>")
+				}
+				fmt.Fprint(&header, " ")
+				const TASK_STALLED_HOLDOFF_DURATION = 10 * time.Second
+				sinceLastUpdate := now.Sub(task.LastUpdate)
+				if !task.Idle || task.ProgressRx != 0 || task.ProgressTx != 0 {
+					fmt.Fprintf(&header, "(%s / %s , Rx/Tx",
+						humanize.Bytes(uint64(task.ProgressRx)),
+						humanize.Bytes(uint64(task.ProgressTx)))
+					if task.Idle {
+						fmt.Fprint(&header, ", values from last run")
+					}
+					fmt.Fprint(&header, ")")
+				}
+				fmt.Fprint(&header, "\n")
+				if !task.Idle && !task.LastUpdate.IsZero() && sinceLastUpdate >= TASK_STALLED_HOLDOFF_DURATION {
+					informAboutError = true
+					fmt.Fprintf(&header, "    WARNING: last update %s ago at %s)",
+						sinceLastUpdate.String(),
+						task.LastUpdate.Format(HumanFormatterDateFormat))
+					fmt.Fprint(&header, "\n")
+				}
+				io.Copy(os.Stdout, &header)
+
+				jobLogEntries = append(jobLogEntries, task.LogEntries...)
+				informAboutError = informAboutError || task.MaxLogLevel >= logger.Warn
+			}
+
+			sort.Slice(jobLogEntries, func(i, j int) bool {
+				return jobLogEntries[i].Time.Before(jobLogEntries[j].Time)
+			})
+			if informAboutError {
+				fmt.Println("    WARNING: Some tasks encountered problems since the last time they left idle state:")
+				fmt.Println("             check the logs below or your log file for more information.")
+				fmt.Println("             Use the --level flag if you need debug information.")
+				fmt.Println()
+			}
+			for _, e := range jobLogEntries {
+				if e.Level < controlStatusCmdArgs.level {
+					continue
+				}
+				formatted, err := formatter.Format(&e)
+				if err != nil {
+					panic(err)
+				}
+				fmt.Printf("      %s\n", string(formatted))
+			}
+			fmt.Println()
+
+		}
+	default:
+		log.Printf("invalid output format '%s'", controlStatusCmdArgs.format)
+		die()
+	}
 
 }

cmd/control_pprof.go

@@ -0,0 +1,80 @@
+package cmd
+
+import (
+	"net/http"
+	// FIXME: importing this package has the side-effect of poisoning the http.DefaultServeMux
+	// FIXME: with the /debug/pprof endpoints
+	"context"
+	"net"
+	"net/http/pprof"
+)
+
+type PProfServer struct {
+	cc       chan PprofServerControlMsg
+	state    PprofServerControlMsg
+	listener net.Listener
+}
+
+type PprofServerControlMsg struct {
+	// Whether the server should listen for requests on the given address
+	Run bool
+	// Must be set if Run is true, undefined otherwise
+	HttpListenAddress string
+}
+
+func NewPProfServer(ctx context.Context) *PProfServer {
+
+	s := &PProfServer{
+		cc: make(chan PprofServerControlMsg),
+	}
+
+	go s.controlLoop(ctx)
+	return s
+}
+
+func (s *PProfServer) controlLoop(ctx context.Context) {
+outer:
+	for {
+
+		var msg PprofServerControlMsg
+		select {
+		case <-ctx.Done():
+			if s.listener != nil {
+				s.listener.Close()
+			}
+			break outer
+		case msg = <-s.cc:
+			// proceed
+		}
+
+		var err error
+		if msg.Run && s.listener == nil {
+
+			s.listener, err = net.Listen("tcp", msg.HttpListenAddress)
+			if err != nil {
+				s.listener = nil
+				continue
+			}
+
+			// FIXME: because net/http/pprof does not provide a mux,
+			mux := http.NewServeMux()
+			mux.Handle("/debug/pprof/", http.HandlerFunc(pprof.Index))
+			mux.Handle("/debug/pprof/cmdline", http.HandlerFunc(pprof.Cmdline))
+			mux.Handle("/debug/pprof/profile", http.HandlerFunc(pprof.Profile))
+			mux.Handle("/debug/pprof/symbol", http.HandlerFunc(pprof.Symbol))
+			mux.Handle("/debug/pprof/trace", http.HandlerFunc(pprof.Trace))
+			go http.Serve(s.listener, mux)
+			continue
+		}
+
+		if !msg.Run && s.listener != nil {
+			s.listener.Close()
+			s.listener = nil
+			continue
+		}
+	}
+}
+
+func (s *PProfServer) Control(msg PprofServerControlMsg) {
+	s.cc <- msg
+}

cmd/daemon.go

@@ -1,12 +1,16 @@
 package cmd
 
 import (
+	"container/list"
 	"context"
 	"fmt"
 	"github.com/spf13/cobra"
 	"github.com/zrepl/zrepl/logger"
+	"io"
 	"os"
 	"os/signal"
+	"strings"
+	"sync"
 	"syscall"
 	"time"
 )
@@ -25,18 +29,20 @@ func init() {
 type Job interface {
 	JobName() string
 	JobStart(ctxt context.Context)
+	JobStatus(ctxt context.Context) (*JobStatus, error)
 }
 
 func doDaemon(cmd *cobra.Command, args []string) {
 
 	conf, err := ParseConfig(rootArgs.configFile)
 	if err != nil {
-		fmt.Fprintf(os.Stderr, "error parsing config: %s", err)
+		fmt.Fprintf(os.Stderr, "error parsing config: %s\n", err)
 		os.Exit(1)
 	}
 
 	log := logger.NewLogger(conf.Global.logging.Outlets, 1*time.Second)
 
+	log.Info(NewZreplVersionInformation().String())
 	log.Debug("starting daemon")
 	ctx := context.WithValue(context.Background(), contextKeyLog, log)
 	ctx = context.WithValue(ctx, contextKeyLog, log)
@@ -50,21 +56,26 @@ type contextKey string
 
 const (
 	contextKeyLog    contextKey = contextKey("log")
+	contextKeyDaemon contextKey = contextKey("daemon")
 )
 
 type Daemon struct {
 	conf      *Config
+	startedAt time.Time
 }
 
 func NewDaemon(initialConf *Config) *Daemon {
-	return &Daemon{initialConf}
+	return &Daemon{conf: initialConf}
 }
 
 func (d *Daemon) Loop(ctx context.Context) {
 
+	d.startedAt = time.Now()
+
 	log := ctx.Value(contextKeyLog).(Logger)
 
 	ctx, cancel := context.WithCancel(ctx)
+	ctx = context.WithValue(ctx, contextKeyDaemon, d)
 
 	sigChan := make(chan os.Signal, 1)
 	finishs := make(chan Job)
@@ -108,3 +119,276 @@ outer:
 	log.Info("exiting")
 
 }
+
+// Representation of a Job's status that is composed of Tasks
+type JobStatus struct {
+	// Statuses of all tasks of this job
+	Tasks []*TaskStatus
+	// Error != "" if JobStatus() returned an error
+	JobStatusError string
+}
+
+// Representation of a Daemon's status that is composed of Jobs
+type DaemonStatus struct {
+	StartedAt time.Time
+	Jobs      map[string]*JobStatus
+}
+
+func (d *Daemon) Status() (s *DaemonStatus) {
+
+	s = &DaemonStatus{}
+	s.StartedAt = d.startedAt
+
+	s.Jobs = make(map[string]*JobStatus, len(d.conf.Jobs))
+
+	for name, j := range d.conf.Jobs {
+		status, err := j.JobStatus(context.TODO())
+		if err != nil {
+			s.Jobs[name] = &JobStatus{nil, err.Error()}
+			continue
+		}
+		s.Jobs[name] = status
+	}
+
+	return
+}
+
+// Representation of a Task's status
+type TaskStatus struct {
+	Name string
+	// Whether the task is idle.
+	Idle bool
+	// The stack of activities the task is currently executing.
+	// The first element is the root activity and equal to Name.
+	ActivityStack []string
+	// Number of bytes received by the task since it last left idle state.
+	ProgressRx int64
+	// Number of bytes sent by the task since it last left idle state.
+	ProgressTx int64
+	// Log entries emitted by the task since it last left idle state.
+	// Only contains the log entries emitted through the task's logger
+	// (provided by Task.Log()).
+	LogEntries []logger.Entry
+	// The maximum log level of LogEntries.
+	// Only valid if len(LogEntries) > 0.
+	MaxLogLevel logger.Level
+	// Last time something about the Task changed
+	LastUpdate time.Time
+}
+
+// An instance of Task tracks  a single thread of activity that is part of a Job.
+type Task struct {
+	// Stack of activities the task is currently in
+	// Members are instances of taskActivity
+	activities *list.List
+	// Last time activities was changed (not the activities inside, the list)
+	activitiesLastUpdate time.Time
+	// Protects Task members from modification
+	rwl sync.RWMutex
+}
+
+// Structure that describes the progress a Task has made
+type taskProgress struct {
+	rx         int64
+	tx         int64
+	lastUpdate time.Time
+	logEntries []logger.Entry
+	mtx        sync.RWMutex
+}
+
+func newTaskProgress() (p *taskProgress) {
+	return &taskProgress{
+		logEntries: make([]logger.Entry, 0),
+	}
+}
+
+func (p *taskProgress) UpdateIO(drx, dtx int64) {
+	p.mtx.Lock()
+	defer p.mtx.Unlock()
+	p.rx += drx
+	p.tx += dtx
+	p.lastUpdate = time.Now()
+}
+
+func (p *taskProgress) UpdateLogEntry(entry logger.Entry) {
+	p.mtx.Lock()
+	defer p.mtx.Unlock()
+	// FIXME: ensure maximum size (issue #48)
+	p.logEntries = append(p.logEntries, entry)
+	p.lastUpdate = time.Now()
+}
+
+func (p *taskProgress) DeepCopy() (out taskProgress) {
+	p.mtx.RLock()
+	defer p.mtx.RUnlock()
+	out.rx, out.tx = p.rx, p.tx
+	out.lastUpdate = p.lastUpdate
+	out.logEntries = make([]logger.Entry, len(p.logEntries))
+	for i := range p.logEntries {
+		out.logEntries[i] = p.logEntries[i]
+	}
+	return
+}
+
+// returns a copy of this taskProgress, the mutex carries no semantic value
+func (p *taskProgress) Read() (out taskProgress) {
+	p.mtx.RLock()
+	defer p.mtx.RUnlock()
+	return p.DeepCopy()
+}
+
+// Element of a Task's activity stack
+type taskActivity struct {
+	name   string
+	idle   bool
+	logger *logger.Logger
+	// The progress of the task that is updated by UpdateIO() and UpdateLogEntry()
+	//
+	// Progress happens on a task-level and is thus global to the task.
+	// That's why progress is just a pointer to the current taskProgress:
+	// we reset progress when leaving the idle root activity
+	progress *taskProgress
+}
+
+func NewTask(name string, lg *logger.Logger) *Task {
+	t := &Task{
+		activities: list.New(),
+	}
+	rootLogger := lg.ReplaceField(logTaskField, name).
+		WithOutlet(t, logger.Debug)
+	rootAct := &taskActivity{name, true, rootLogger, newTaskProgress()}
+	t.activities.PushFront(rootAct)
+	return t
+}
+
+// callers must hold t.rwl
+func (t *Task) cur() *taskActivity {
+	return t.activities.Front().Value.(*taskActivity)
+}
+
+// buildActivityStack returns the stack of activity names
+// t.rwl must be held, but the slice can be returned since strings are immutable
+func (t *Task) buildActivityStack() []string {
+	comps := make([]string, 0, t.activities.Len())
+	for e := t.activities.Back(); e != nil; e = e.Prev() {
+		act := e.Value.(*taskActivity)
+		comps = append(comps, act.name)
+	}
+	return comps
+}
+
+// Start a sub-activity.
+// Must always be matched with a call to t.Finish()
+// --- consider using defer for this purpose.
+func (t *Task) Enter(activity string) {
+	t.rwl.Lock()
+	defer t.rwl.Unlock()
+
+	prev := t.cur()
+	if prev.idle {
+		// reset progress when leaving idle task
+		// we leave the old progress dangling to have the user not worry about
+		prev.progress = newTaskProgress()
+	}
+	act := &taskActivity{activity, false, nil, prev.progress}
+	t.activities.PushFront(act)
+	stack := t.buildActivityStack()
+	activityField := strings.Join(stack, ".")
+	act.logger = prev.logger.ReplaceField(logTaskField, activityField)
+
+	t.activitiesLastUpdate = time.Now()
+}
+
+func (t *Task) UpdateProgress(dtx, drx int64) {
+	t.rwl.RLock()
+	p := t.cur().progress // protected by own rwlock
+	t.rwl.RUnlock()
+	p.UpdateIO(dtx, drx)
+}
+
+// Returns a wrapper io.Reader that updates this task's _current_ progress value.
+// Progress updates after this task resets its progress value are discarded.
+func (t *Task) ProgressUpdater(r io.Reader) *IOProgressUpdater {
+	t.rwl.RLock()
+	defer t.rwl.RUnlock()
+	return &IOProgressUpdater{r, t.cur().progress}
+}
+
+func (t *Task) Status() *TaskStatus {
+	t.rwl.RLock()
+	defer t.rwl.RUnlock()
+	// NOTE
+	// do not return any state in TaskStatus that is protected by t.rwl
+
+	cur := t.cur()
+	stack := t.buildActivityStack()
+	prog := cur.progress.Read()
+
+	var maxLevel logger.Level
+	for _, entry := range prog.logEntries {
+		if maxLevel < entry.Level {
+			maxLevel = entry.Level
+		}
+	}
+
+	lastUpdate := prog.lastUpdate
+	if lastUpdate.Before(t.activitiesLastUpdate) {
+		lastUpdate = t.activitiesLastUpdate
+	}
+
+	s := &TaskStatus{
+		Name:          stack[0],
+		ActivityStack: stack,
+		Idle:          cur.idle,
+		ProgressRx:    prog.rx,
+		ProgressTx:    prog.tx,
+		LogEntries:    prog.logEntries,
+		MaxLogLevel:   maxLevel,
+		LastUpdate:    lastUpdate,
+	}
+
+	return s
+}
+
+// Finish a sub-activity.
+// Corresponds to a preceding call to t.Enter()
+func (t *Task) Finish() {
+	t.rwl.Lock()
+	defer t.rwl.Unlock()
+	top := t.activities.Front()
+	if top.Next() == nil {
+		return // cannot remove root activity
+	}
+	t.activities.Remove(top)
+	t.activitiesLastUpdate = time.Now()
+
+}
+
+// Returns a logger derived from the logger passed to the constructor function.
+// The logger's task field contains the current activity stack joined by '.'.
+func (t *Task) Log() *logger.Logger {
+	t.rwl.RLock()
+	defer t.rwl.RUnlock()
+	// FIXME should influence TaskStatus's LastUpdate field
+	return t.cur().logger
+}
+
+// implement logger.Outlet interface
+func (t *Task) WriteEntry(entry logger.Entry) error {
+	t.rwl.RLock()
+	defer t.rwl.RUnlock()
+	t.cur().progress.UpdateLogEntry(entry)
+	return nil
+}
+
+type IOProgressUpdater struct {
+	r io.Reader
+	p *taskProgress
+}
+
+func (u *IOProgressUpdater) Read(p []byte) (n int, err error) {
+	n, err = u.r.Read(p)
+	u.p.UpdateIO(int64(n), 0)
+	return
+
+}

cmd/handler.go

@@ -99,7 +99,7 @@ func (h Handler) HandleFilesystemVersionsRequest(r *FilesystemVersionsRequest, v
 		return
 	}
 
-	log.WithField("resposne", vs).Debug("response")
+	log.WithField("response", vs).Debug("response")
 
 	*versions = vs
 	return

cmd/helpers.go

@@ -7,28 +7,42 @@ import (
 	"path/filepath"
 )
 
-func ListenUnixPrivate(sockaddr *net.UnixAddr) (*net.UnixListener, error) {
-
-	sockdir := filepath.Dir(sockaddr.Name)
+func PreparePrivateSockpath(sockpath string) error {
+	sockdir := filepath.Dir(sockpath)
 	sdstat, err := os.Stat(sockdir)
 	if err != nil {
-		return nil, errors.Wrapf(err, "cannot stat(2) '%s'", sockdir)
+		return errors.Wrapf(err, "cannot stat(2) '%s'", sockdir)
 	}
 	if !sdstat.IsDir() {
-		return nil, errors.Errorf("not a directory: %s", sockdir)
+		return errors.Errorf("not a directory: %s", sockdir)
 	}
 	p := sdstat.Mode().Perm()
 	if p&0007 != 0 {
-		return nil, errors.Errorf("socket directory not be world-accessible: %s (permissions are %#o)", sockdir, p)
+		return errors.Errorf("socket directory must not be world-accessible: %s (permissions are %#o)", sockdir, p)
 	}
 
 	// Maybe things have not been cleaned up before
-	s, err := os.Stat(sockaddr.Name)
-	if err == nil {
-		if s.Mode()&os.ModeSocket != 0 {
-			// opportunistically try to remove it, but if this fails, it is not an error
-			os.Remove(sockaddr.Name)
+	s, err := os.Stat(sockpath)
+	if os.IsNotExist(err) {
+		return nil
 	}
+	if err != nil {
+		return errors.Wrapf(err, "cannot stat(2) '%s'", sockpath)
+	}
+	if s.Mode()&os.ModeSocket == 0 {
+		return errors.Errorf("unexpected file type at path '%s'", sockpath)
+	}
+	err = os.Remove(sockpath)
+	if err != nil {
+		return errors.Wrapf(err, "cannot remove presumably stale socket '%s'", sockpath)
+	}
+	return nil
+}
+
+func ListenUnixPrivate(sockaddr *net.UnixAddr) (*net.UnixListener, error) {
+
+	if err := PreparePrivateSockpath(sockaddr.Name); err != nil {
+		return nil, err
 	}
 
 	return net.ListenUnix("unix", sockaddr)

cmd/logging_formatters.go

@@ -7,11 +7,11 @@ import (
 	"github.com/go-logfmt/logfmt"
 	"github.com/pkg/errors"
 	"github.com/zrepl/zrepl/logger"
-	"strings"
 	"time"
 )
 
 type EntryFormatter interface {
+	SetMetadataFlags(flags MetadataFlags)
 	Format(e *logger.Entry) ([]byte, error)
 }
 
@@ -33,25 +33,47 @@ const (
 
 type NoFormatter struct{}
 
+func (f NoFormatter) SetMetadataFlags(flags MetadataFlags) {}
+
 func (f NoFormatter) Format(e *logger.Entry) ([]byte, error) {
 	return []byte(e.Message), nil
 }
 
 type HumanFormatter struct {
-	NoMetadata bool
+	metadataFlags MetadataFlags
+	ignoreFields  map[string]bool
 }
 
-var _ SetNoMetadataFormatter = &HumanFormatter{}
+const HumanFormatterDateFormat = time.RFC3339
 
-func (f *HumanFormatter) SetNoMetadata(noMetadata bool) {
-	f.NoMetadata = noMetadata
+func (f *HumanFormatter) SetMetadataFlags(flags MetadataFlags) {
+	f.metadataFlags = flags
+}
+
+func (f *HumanFormatter) SetIgnoreFields(ignore []string) {
+	if ignore == nil {
+		f.ignoreFields = nil
+		return
+	}
+	f.ignoreFields = make(map[string]bool, len(ignore))
+
+	for _, field := range ignore {
+		f.ignoreFields[field] = true
+	}
+}
+
+func (f *HumanFormatter) ignored(field string) bool {
+	return f.ignoreFields != nil && f.ignoreFields[field]
 }
 
 func (f *HumanFormatter) Format(e *logger.Entry) (out []byte, err error) {
 
 	var line bytes.Buffer
 
-	if !f.NoMetadata {
+	if f.metadataFlags&MetadataTime != 0 {
+		fmt.Fprintf(&line, "%s ", e.Time.Format(HumanFormatterDateFormat))
+	}
+	if f.metadataFlags&MetadataLevel != 0 {
 		fmt.Fprintf(&line, "[%s]", e.Level.Short())
 	}
 
@@ -60,8 +82,10 @@ func (f *HumanFormatter) Format(e *logger.Entry) (out []byte, err error) {
 	for _, field := range prefixFields {
 		val, ok := e.Fields[field].(string)
 		if ok {
+			if !f.ignored(field) {
 				fmt.Fprintf(&line, "[%s]", val)
 				prefixed[field] = true
+			}
 		} else {
 			break
 		}
@@ -69,13 +93,13 @@ func (f *HumanFormatter) Format(e *logger.Entry) (out []byte, err error) {
 	// even more prefix fields
 	mapFrom, mapFromOk := e.Fields[logMapFromField].(string)
 	mapTo, mapToOk := e.Fields[logMapToField].(string)
-	if mapFromOk && mapToOk {
+	if mapFromOk && mapToOk && !f.ignored(logMapFromField) && !f.ignored(logMapToField) {
 		fmt.Fprintf(&line, "[%s => %s]", mapFrom, mapTo)
 		prefixed[logMapFromField], prefixed[logMapToField] = true, true
 	}
 	incFrom, incFromOk := e.Fields[logIncFromField].(string)
 	incTo, incToOk := e.Fields[logIncToField].(string)
-	if incFromOk && incToOk {
+	if incFromOk && incToOk && !f.ignored(logIncFromField) && !f.ignored(logMapToField) {
 		fmt.Fprintf(&line, "[%s => %s]", incFrom, incTo)
 		prefixed[logIncFromField], prefixed[logIncToField] = true, true
 	}
@@ -85,22 +109,29 @@ func (f *HumanFormatter) Format(e *logger.Entry) (out []byte, err error) {
 	}
 	fmt.Fprint(&line, e.Message)
 
+	if len(e.Fields)-len(prefixed) > 0 {
+		fmt.Fprint(&line, " ")
+		enc := logfmt.NewEncoder(&line)
 		for field, value := range e.Fields {
-
-		if prefixed[field] {
+			if prefixed[field] || f.ignored(field) {
 				continue
 			}
-
-		if strings.ContainsAny(field, " \t") {
-			return nil, errors.Errorf("field must not contain whitespace: '%s'", field)
+			if err := logfmtTryEncodeKeyval(enc, field, value); err != nil {
+				return nil, err
+			}
 		}
-		fmt.Fprintf(&line, " %s=\"%s\"", field, value)
 	}
 
 	return line.Bytes(), nil
 }
 
-type JSONFormatter struct{}
+type JSONFormatter struct {
+	metadataFlags MetadataFlags
+}
+
+func (f *JSONFormatter) SetMetadataFlags(flags MetadataFlags) {
+	f.metadataFlags = flags
+}
 
 func (f *JSONFormatter) Format(e *logger.Entry) ([]byte, error) {
 	data := make(logger.Fields, len(e.Fields)+3)
@@ -128,21 +159,21 @@ func (f *JSONFormatter) Format(e *logger.Entry) ([]byte, error) {
 }
 
 type LogfmtFormatter struct {
-	NoMetadata bool
+	metadataFlags MetadataFlags
 }
 
-var _ SetNoMetadataFormatter = &LogfmtFormatter{}
-
-func (f *LogfmtFormatter) SetNoMetadata(noMetadata bool) {
-	f.NoMetadata = noMetadata
+func (f *LogfmtFormatter) SetMetadataFlags(flags MetadataFlags) {
+	f.metadataFlags = flags
 }
 
 func (f *LogfmtFormatter) Format(e *logger.Entry) ([]byte, error) {
 	var buf bytes.Buffer
 	enc := logfmt.NewEncoder(&buf)
 
-	if !f.NoMetadata {
+	if f.metadataFlags&MetadataTime != 0 {
 		enc.EncodeKeyval(FieldTime, e.Time)
+	}
+	if f.metadataFlags&MetadataLevel != 0 {
 		enc.EncodeKeyval(FieldLevel, e.Level)
 	}
 
@@ -154,7 +185,9 @@ func (f *LogfmtFormatter) Format(e *logger.Entry) ([]byte, error) {
 		if !ok {
 			break
 		}
-		enc.EncodeKeyval(pf, v)
+		if err := logfmtTryEncodeKeyval(enc, pf, v); err != nil {
+			return nil, err // unlikely
+		}
 		prefixed[pf] = true
 	}
 
@@ -162,13 +195,25 @@ func (f *LogfmtFormatter) Format(e *logger.Entry) ([]byte, error) {
 
 	for k, v := range e.Fields {
 		if !prefixed[k] {
-			enc.EncodeKeyval(k, v)
-		}
-	}
-
-	if err := enc.EndRecord(); err != nil {
+			if err := logfmtTryEncodeKeyval(enc, k, v); err != nil {
 				return nil, err
 			}
+		}
+	}
 
 	return buf.Bytes(), nil
 }
+
+func logfmtTryEncodeKeyval(enc *logfmt.Encoder, field, value interface{}) error {
+
+	err := enc.EncodeKeyval(field, value)
+	switch err {
+	case nil: // ok
+		return nil
+	case logfmt.ErrUnsupportedValueType:
+		enc.EncodeKeyval(field, fmt.Sprintf("<%T>", value))
+		return nil
+	}
+	return errors.Wrapf(err, "cannot encode field '%s'", field)
+
+}

cmd/logging_outlets.go

@@ -1,6 +1,7 @@
 package cmd
 
 import (
+	"bytes"
 	"context"
 	"crypto/tls"
 	"github.com/pkg/errors"
@@ -16,7 +17,7 @@ type WriterOutlet struct {
 	Writer    io.Writer
 }
 
-func (h WriterOutlet) WriteEntry(ctx context.Context, entry logger.Entry) error {
+func (h WriterOutlet) WriteEntry(entry logger.Entry) error {
 	bytes, err := h.Formatter.Format(&entry)
 	if err != nil {
 		return err
@@ -27,56 +28,92 @@ func (h WriterOutlet) WriteEntry(ctx context.Context, entry logger.Entry) error
 }
 
 type TCPOutlet struct {
-	Formatter    EntryFormatter
-	Net, Address string
-	Dialer       net.Dialer
-	TLS          *tls.Config
+	formatter EntryFormatter
 	// Specifies how much time must pass between a connection error and a reconnection attempt
 	// Log entries written to the outlet during this time interval are silently dropped.
-	RetryInterval time.Duration
-	// nil if there was an error sending / connecting to remote server
-	conn net.Conn
-	// Last time an error occurred when sending / connecting to remote server
-	retry time.Time
+	connect   func(ctx context.Context) (net.Conn, error)
+	entryChan chan *bytes.Buffer
 }
 
-func (h *TCPOutlet) WriteEntry(ctx context.Context, e logger.Entry) error {
+func NewTCPOutlet(formatter EntryFormatter, network, address string, tlsConfig *tls.Config, retryInterval time.Duration) *TCPOutlet {
 
-	b, err := h.Formatter.Format(&e)
+	connect := func(ctx context.Context) (conn net.Conn, err error) {
+		deadl, ok := ctx.Deadline()
+		if !ok {
+			deadl = time.Time{}
+		}
+		dialer := net.Dialer{
+			Deadline: deadl,
+		}
+		if tlsConfig != nil {
+			conn, err = tls.DialWithDialer(&dialer, network, address, tlsConfig)
+		} else {
+			conn, err = dialer.DialContext(ctx, network, address)
+		}
+		return
+	}
+
+	entryChan := make(chan *bytes.Buffer, 1) // allow one message in flight while previos is in io.Copy()
+
+	o := &TCPOutlet{
+		formatter: formatter,
+		connect:   connect,
+		entryChan: entryChan,
+	}
+
+	go o.outLoop(retryInterval)
+
+	return o
+}
+
+// FIXME: use this method
+func (h *TCPOutlet) Close() {
+	close(h.entryChan)
+}
+
+func (h *TCPOutlet) outLoop(retryInterval time.Duration) {
+
+	var retry time.Time
+	var conn net.Conn
+	for msg := range h.entryChan {
+		var err error
+		for conn == nil {
+			time.Sleep(time.Until(retry))
+			ctx, cancel := context.WithDeadline(context.TODO(), time.Now().Add(retryInterval))
+			conn, err = h.connect(ctx)
+			cancel()
+			if err != nil {
+				retry = time.Now().Add(retryInterval)
+				conn = nil
+			}
+		}
+		conn.SetWriteDeadline(time.Now().Add(retryInterval))
+		_, err = io.Copy(conn, msg)
+		if err != nil {
+			retry = time.Now().Add(retryInterval)
+			conn.Close()
+			conn = nil
+		}
+	}
+}
+
+func (h *TCPOutlet) WriteEntry(e logger.Entry) error {
+
+	ebytes, err := h.formatter.Format(&e)
 	if err != nil {
 		return err
 	}
 
-	if h.conn == nil {
-		if time.Now().Sub(h.retry) < h.RetryInterval {
-			// cool-down phase, drop the log entry
+	buf := new(bytes.Buffer)
+	buf.Write(ebytes)
+	buf.WriteString("\n")
+
+	select {
+	case h.entryChan <- buf:
 		return nil
+	default:
+		return errors.New("connection broken or not fast enough")
 	}
-
-		if h.TLS != nil {
-			h.conn, err = tls.DialWithDialer(&h.Dialer, h.Net, h.Address, h.TLS)
-		} else {
-			h.conn, err = h.Dialer.DialContext(ctx, h.Net, h.Address)
-		}
-		if err != nil {
-			h.conn = nil
-			h.retry = time.Now()
-			return errors.Wrap(err, "cannot dial")
-		}
-	}
-
-	_, err = h.conn.Write(b)
-	if err == nil {
-		_, err = h.conn.Write([]byte("\n"))
-	}
-	if err != nil {
-		h.conn.Close()
-		h.conn = nil
-		h.retry = time.Now()
-		return errors.Wrap(err, "cannot write")
-	}
-
-	return nil
 }
 
 type SyslogOutlet struct {
@@ -86,7 +123,7 @@ type SyslogOutlet struct {
 	lastConnectAttempt time.Time
 }
 
-func (o *SyslogOutlet) WriteEntry(ctx context.Context, entry logger.Entry) error {
+func (o *SyslogOutlet) WriteEntry(entry logger.Entry) error {
 
 	bytes, err := o.Formatter.Format(&entry)
 	if err != nil {

cmd/main.go

@@ -20,6 +20,10 @@ import (
 //	Printf(format string, v ...interface{})
 //}
 
+var (
+	zreplVersion string // set by build infrastructure
+)
+
 type Logger = *logger.Logger
 
 var RootCmd = &cobra.Command{

cmd/prune.go

@@ -3,11 +3,14 @@ package cmd
 import (
 	"context"
 	"fmt"
+	"github.com/zrepl/zrepl/util"
 	"github.com/zrepl/zrepl/zfs"
+	"sync"
 	"time"
 )
 
 type Pruner struct {
+	task           *Task
 	Now            time.Time
 	DryRun         bool
 	DatasetFilter  zfs.DatasetFilter
@@ -22,44 +25,50 @@ type PruneResult struct {
 	Remove     []zfs.FilesystemVersion
 }
 
-func (p *Pruner) Run(ctx context.Context) (r []PruneResult, err error) {
-
-	log := ctx.Value(contextKeyLog).(Logger)
-
-	if p.DryRun {
-		log.Info("doing dry run")
-	}
-
+// FIXME must not call p.task.Enter because it runs in parallel
+func (p *Pruner) filterFilesystems() (filesystems []*zfs.DatasetPath, stop bool) {
 	filesystems, err := zfs.ZFSListMapping(p.DatasetFilter)
 	if err != nil {
-		log.WithError(err).Error("error applying filesystem filter")
-		return nil, err
+		p.task.Log().WithError(err).Error("error applying filesystem filter")
+		return nil, true
 	}
 	if len(filesystems) <= 0 {
-		log.Info("no filesystems matching filter")
-		return nil, err
+		p.task.Log().Info("no filesystems matching filter")
+		return nil, true
+	}
+	return filesystems, false
 }
 
-	r = make([]PruneResult, 0, len(filesystems))
+// FIXME must not call p.task.Enter because it runs in parallel
+func (p *Pruner) filterVersions(fs *zfs.DatasetPath) (fsversions []zfs.FilesystemVersion, stop bool) {
+	log := p.task.Log().WithField(logFSField, fs.ToString())
 
-	for _, fs := range filesystems {
-
-		log := log.WithField(logFSField, fs.ToString())
-
-		fsversions, err := zfs.ZFSListFilesystemVersions(fs, &PrefixSnapshotFilter{p.SnapshotPrefix})
+	filter := NewPrefixFilter(p.SnapshotPrefix)
+	fsversions, err := zfs.ZFSListFilesystemVersions(fs, filter)
 	if err != nil {
 		log.WithError(err).Error("error listing filesytem versions")
-			continue
+		return nil, true
 	}
 	if len(fsversions) == 0 {
 		log.WithField("prefix", p.SnapshotPrefix).Info("no filesystem versions matching prefix")
-			continue
+		return nil, true
+	}
+	return fsversions, false
+}
+
+// FIXME must not call p.task.Enter because it runs in parallel
+func (p *Pruner) pruneFilesystem(fs *zfs.DatasetPath, destroySemaphore util.Semaphore) (r PruneResult, valid bool) {
+	log := p.task.Log().WithField(logFSField, fs.ToString())
+
+	fsversions, stop := p.filterVersions(fs)
+	if stop {
+		return
 	}
 
 	keep, remove, err := p.PrunePolicy.Prune(fs, fsversions)
 	if err != nil {
 		log.WithError(err).Error("error evaluating prune policy")
-			continue
+		return
 	}
 
 	log.WithField("fsversions", fsversions).
@@ -67,10 +76,15 @@ func (p *Pruner) Run(ctx context.Context) (r []PruneResult, err error) {
 		WithField("remove", remove).
 		Debug("prune policy debug dump")
 
-		r = append(r, PruneResult{fs, fsversions, keep, remove})
+	r = PruneResult{fs, fsversions, keep, remove}
 
-		makeFields := func(v zfs.FilesystemVersion) (fields map[string]interface{}) {
-			fields = make(map[string]interface{})
+	var wg sync.WaitGroup
+	for v := range remove {
+		wg.Add(1)
+		go func(v zfs.FilesystemVersion) {
+			defer wg.Done()
+			// log fields
+			fields := make(map[string]interface{})
 			fields["version"] = v.ToAbsPath(fs)
 			timeSince := v.Creation.Sub(p.Now)
 			fields["age_ns"] = timeSince
@@ -78,24 +92,64 @@ func (p *Pruner) Run(ctx context.Context) (r []PruneResult, err error) {
 			days := timeSince / day
 			remainder := timeSince % day
 			fields["age_str"] = fmt.Sprintf("%dd%s", days, remainder)
-			return
-		}
 
-		for _, v := range remove {
-			fields := makeFields(v)
 			log.WithFields(fields).Info("destroying version")
 			// echo what we'll do and exec zfs destroy if not dry run
 			// TODO special handling for EBUSY (zfs hold)
 			// TODO error handling for clones? just echo to cli, skip over, and exit with non-zero status code (we're idempotent)
 			if !p.DryRun {
+				destroySemaphore.Down()
 				err := zfs.ZFSDestroyFilesystemVersion(fs, v)
+				destroySemaphore.Up()
 				if err != nil {
-					// handle
 					log.WithFields(fields).WithError(err).Error("error destroying version")
 				}
 			}
+		}(remove[v])
+	}
+	wg.Wait()
+
+	return r, true
 }
 
+func (p *Pruner) Run(ctx context.Context) (r []PruneResult, err error) {
+	p.task.Enter("run")
+	defer p.task.Finish()
+
+	if p.DryRun {
+		p.task.Log().Info("doing dry run")
+	}
+
+	filesystems, stop := p.filterFilesystems()
+	if stop {
+		return
+	}
+
+	maxConcurrentDestroy := len(filesystems)
+	p.task.Log().WithField("max_concurrent_destroy", maxConcurrentDestroy).Info("begin concurrent destroy")
+	destroySem := util.NewSemaphore(maxConcurrentDestroy)
+
+	resChan := make(chan PruneResult, len(filesystems))
+	var wg sync.WaitGroup
+	for _, fs := range filesystems {
+		wg.Add(1)
+		go func(fs *zfs.DatasetPath) {
+			defer wg.Done()
+			res, ok := p.pruneFilesystem(fs, destroySem)
+			if ok {
+				resChan <- res
+			}
+
+		}(fs)
+	}
+	wg.Wait()
+	close(resChan)
+
+	p.task.Log().Info("destroys done")
+
+	r = make([]PruneResult, 0, len(filesystems))
+	for res := range resChan {
+		r = append(r, res)
 	}
 
 	return

cmd/replication.go

@@ -3,12 +3,10 @@ package cmd
 import (
 	"fmt"
 	"io"
-	"time"
 
 	"bytes"
 	"encoding/json"
 	"github.com/zrepl/zrepl/rpc"
-	"github.com/zrepl/zrepl/util"
 	"github.com/zrepl/zrepl/zfs"
 )
 
@@ -18,8 +16,6 @@ func (a localPullACL) Filter(p *zfs.DatasetPath) (pass bool, err error) {
 	return true, nil
 }
 
-const LOCAL_TRANSPORT_IDENTITY string = "local"
-
 const DEFAULT_INITIAL_REPL_POLICY = InitialReplPolicyMostRecent
 
 type InitialReplPolicy string
@@ -29,110 +25,68 @@ const (
 	InitialReplPolicyAll        InitialReplPolicy = "all"
 )
 
-func closeRPCWithTimeout(log Logger, remote rpc.RPCClient, timeout time.Duration, goodbye string) {
-	log.Info("closing rpc connection")
-
-	ch := make(chan error)
-	go func() {
-		ch <- remote.Close()
-		close(ch)
-	}()
-
-	var err error
-	select {
-	case <-time.After(timeout):
-		err = fmt.Errorf("timeout exceeded (%s)", timeout)
-	case closeRequestErr := <-ch:
-		err = closeRequestErr
-	}
-
-	if err != nil {
-		log.WithError(err).Error("error closing connection")
-	}
-	return
-}
-
-type PullContext struct {
+type Puller struct {
+	task              *Task
 	Remote            rpc.RPCClient
-	Log               Logger
 	Mapping           DatasetMapping
 	InitialReplPolicy InitialReplPolicy
 }
 
-func doPull(pull PullContext) (err error) {
-
-	remote := pull.Remote
-	log := pull.Log
-
-	log.Info("request remote filesystem list")
-	fsr := FilesystemRequest{}
-	var remoteFilesystems []*zfs.DatasetPath
-	if err = remote.Call("FilesystemRequest", &fsr, &remoteFilesystems); err != nil {
-		return
-	}
-
-	log.Debug("map remote filesystems to local paths and determine order for per-filesystem sync")
-	type RemoteLocalMapping struct {
+type remoteLocalMapping struct {
 	Remote *zfs.DatasetPath
 	Local  *zfs.DatasetPath
 }
-	replMapping := make(map[string]RemoteLocalMapping, len(remoteFilesystems))
-	localTraversal := zfs.NewDatasetPathForest()
+
+func (p *Puller) getRemoteFilesystems() (rfs []*zfs.DatasetPath, ok bool) {
+	p.task.Enter("fetch_remote_fs_list")
+	defer p.task.Finish()
+
+	fsr := FilesystemRequest{}
+	if err := p.Remote.Call("FilesystemRequest", &fsr, &rfs); err != nil {
+		p.task.Log().WithError(err).Error("cannot fetch remote filesystem list")
+		return nil, false
+	}
+	return rfs, true
+}
+
+func (p *Puller) buildReplMapping(remoteFilesystems []*zfs.DatasetPath) (replMapping map[string]remoteLocalMapping, ok bool) {
+	p.task.Enter("build_repl_mapping")
+	defer p.task.Finish()
+
+	replMapping = make(map[string]remoteLocalMapping, len(remoteFilesystems))
 	for fs := range remoteFilesystems {
 		var err error
 		var localFs *zfs.DatasetPath
-		localFs, err = pull.Mapping.Map(remoteFilesystems[fs])
+		localFs, err = p.Mapping.Map(remoteFilesystems[fs])
 		if err != nil {
 			err := fmt.Errorf("error mapping %s: %s", remoteFilesystems[fs], err)
-			log.WithError(err).WithField(logMapFromField, remoteFilesystems[fs]).Error("cannot map")
-			return err
+			p.task.Log().WithError(err).WithField(logMapFromField, remoteFilesystems[fs]).Error("cannot map")
+			return nil, false
 		}
 		if localFs == nil {
 			continue
 		}
-		log.WithField(logMapFromField, remoteFilesystems[fs].ToString()).
+		p.task.Log().WithField(logMapFromField, remoteFilesystems[fs].ToString()).
 			WithField(logMapToField, localFs.ToString()).Debug("mapping")
-		m := RemoteLocalMapping{remoteFilesystems[fs], localFs}
+		m := remoteLocalMapping{remoteFilesystems[fs], localFs}
 		replMapping[m.Local.ToString()] = m
-		localTraversal.Add(m.Local)
+	}
+	return replMapping, true
 }
 
-	log.Debug("build cache for already present local filesystem state")
-	localFilesystemState, err := zfs.ZFSListFilesystemState()
-	if err != nil {
-		log.WithError(err).Error("cannot request local filesystem state")
-		return err
-	}
+// returns true if the receiving filesystem (local side) exists and can have child filesystems
+func (p *Puller) replFilesystem(m remoteLocalMapping, localFilesystemState map[string]zfs.FilesystemState) (localExists bool) {
 
-	log.Info("start per-filesystem sync")
-	localTraversal.WalkTopDown(func(v zfs.DatasetPathVisit) bool {
+	p.task.Enter("repl_fs")
+	defer p.task.Finish()
+	var err error
+	remote := p.Remote
 
-		log := log.WithField(logFSField, v.Path.ToString())
+	log := p.task.Log().
+		WithField(logMapFromField, m.Remote.ToString()).
+		WithField(logMapToField, m.Local.ToString())
 
-		if v.FilledIn {
-			if _, exists := localFilesystemState[v.Path.ToString()]; exists {
-				// No need to verify if this is a placeholder or not. It is sufficient
-				// to know we can add child filesystems to it
-				return true
-			}
-			log.Debug("create placeholder filesystem")
-			err = zfs.ZFSCreatePlaceholderFilesystem(v.Path)
-			if err != nil {
-				log.Error("cannot create placeholder filesystem")
-				return false
-			}
-			return true
-		}
-
-		m, ok := replMapping[v.Path.ToString()]
-		if !ok {
-			panic("internal inconsistency: replMapping should contain mapping for any path that was not filled in by WalkTopDown()")
-		}
-
-		log = log.WithField(logMapToField, m.Remote.ToString()).
-			WithField(logMapFromField, m.Local.ToString())
-
-		log.Debug("examing local filesystem state")
+	log.Debug("examining local filesystem state")
 	localState, localExists := localFilesystemState[m.Local.ToString()]
 	var versions []zfs.FilesystemVersion
 	switch {
@@ -171,10 +125,10 @@ func doPull(pull PullContext) (err error) {
 	switch diff.Conflict {
 	case zfs.ConflictAllRight:
 
-			log.WithField("replication_policy", pull.InitialReplPolicy).Info("performing initial sync, following policy")
+		log.WithField("replication_policy", p.InitialReplPolicy).Info("performing initial sync, following policy")
 
-			if pull.InitialReplPolicy != InitialReplPolicyMostRecent {
-				panic(fmt.Sprintf("policy '%s' not implemented", pull.InitialReplPolicy))
+		if p.InitialReplPolicy != InitialReplPolicyMostRecent {
+			panic(fmt.Sprintf("policy '%s' not implemented", p.InitialReplPolicy))
 		}
 
 		snapsOnly := make([]zfs.FilesystemVersion, 0, len(diff.MRCAPathRight))
@@ -205,26 +159,23 @@ func doPull(pull PullContext) (err error) {
 		log.Debug("received initial transfer request response")
 
 		log.Debug("invoke zfs receive")
-			watcher := util.IOProgressWatcher{Reader: stream}
-			watcher.KickOff(1*time.Second, func(p util.IOProgress) {
-				log.WithField("total_rx", p.TotalRX).Info("progress on receive operation")
-			})
-
 		recvArgs := []string{"-u"}
 		if localState.Placeholder {
 			log.Info("receive with forced rollback to replace placeholder filesystem")
 			recvArgs = append(recvArgs, "-F")
 		}
-
-			if err = zfs.ZFSRecv(m.Local, &watcher, recvArgs...); err != nil {
-				log.WithError(err).Error("canot receive stream")
+		progressStream := p.task.ProgressUpdater(stream)
+		if err = zfs.ZFSRecv(m.Local, progressStream, recvArgs...); err != nil {
+			log.WithError(err).Error("cannot receive stream")
 			return false
 		}
-			log.WithField("total_rx", watcher.Progress().TotalRX).
-				Info("finished receiving stream")
+		log.Info("finished receiving stream") // TODO rx delta
 
+		// TODO unify with recv path of ConflictIncremental
 		log.Debug("configuring properties of received filesystem")
-			if err = zfs.ZFSSet(m.Local, "readonly", "on"); err != nil {
+		props := zfs.NewZFSProperties()
+		props.Set("readonly", "on")
+		if err = zfs.ZFSSet(m.Local, props); err != nil {
 			log.WithError(err).Error("cannot set readonly property")
 		}
 
@@ -239,8 +190,6 @@ func doPull(pull PullContext) (err error) {
 		}
 
 		log.Info("following incremental path from diff")
-			var pathRx uint64
-
 		for i := 0; i < len(diff.IncrementalPath)-1; i++ {
 
 			from, to := diff.IncrementalPath[i], diff.IncrementalPath[i+1]
@@ -260,23 +209,16 @@ func doPull(pull PullContext) (err error) {
 			}
 
 			log.Debug("invoking zfs receive")
-				watcher := util.IOProgressWatcher{Reader: stream}
-				watcher.KickOff(1*time.Second, func(p util.IOProgress) {
-					log.WithField("total_rx", p.TotalRX).Info("progress on receive operation")
-				})
-
-				if err = zfs.ZFSRecv(m.Local, &watcher); err != nil {
+			progressStream := p.task.ProgressUpdater(stream)
+			// TODO protect against malicious incremental stream
+			if err = zfs.ZFSRecv(m.Local, progressStream); err != nil {
 				log.WithError(err).Error("cannot receive stream")
 				return false
 			}
-
-				totalRx := watcher.Progress().TotalRX
-				pathRx += totalRx
-				log.WithField("total_rx", totalRx).Info("finished incremental transfer")
+			log.Info("finished incremental transfer") // TODO increment rx
 
 		}
-
-			log.WithField("total_rx", pathRx).Info("finished following incremental path")
+		log.Info("finished following incremental path") // TODO path rx
 		return true
 
 	case zfs.ConflictNoCommonAncestor:
@@ -311,7 +253,69 @@ func doPull(pull PullContext) (err error) {
 	}
 
 	panic("should not be reached")
+}
 
+func (p *Puller) Pull() {
+	p.task.Enter("run")
+	defer p.task.Finish()
+
+	p.task.Log().Info("request remote filesystem list")
+	remoteFilesystems, ok := p.getRemoteFilesystems()
+	if !ok {
+		return
+	}
+
+	p.task.Log().Debug("map remote filesystems to local paths and determine order for per-filesystem sync")
+	replMapping, ok := p.buildReplMapping(remoteFilesystems)
+	if !ok {
+
+	}
+
+	p.task.Log().Debug("build cache for already present local filesystem state")
+	p.task.Enter("cache_local_fs_state")
+	localFilesystemState, err := zfs.ZFSListFilesystemState()
+	p.task.Finish()
+	if err != nil {
+		p.task.Log().WithError(err).Error("cannot request local filesystem state")
+		return
+	}
+
+	localTraversal := zfs.NewDatasetPathForest()
+	for _, m := range replMapping {
+		localTraversal.Add(m.Local)
+	}
+
+	p.task.Log().Info("start per-filesystem sync")
+	localTraversal.WalkTopDown(func(v zfs.DatasetPathVisit) bool {
+
+		p.task.Enter("tree_walk")
+		defer p.task.Finish()
+
+		log := p.task.Log().WithField(logFSField, v.Path.ToString())
+
+		if v.FilledIn {
+			if _, exists := localFilesystemState[v.Path.ToString()]; exists {
+				// No need to verify if this is a placeholder or not. It is sufficient
+				// to know we can add child filesystems to it
+				return true
+			}
+			log.Debug("create placeholder filesystem")
+			p.task.Enter("create_placeholder")
+			err = zfs.ZFSCreatePlaceholderFilesystem(v.Path)
+			p.task.Finish()
+			if err != nil {
+				log.Error("cannot create placeholder filesystem")
+				return false
+			}
+			return true
+		}
+
+		m, ok := replMapping[v.Path.ToString()]
+		if !ok {
+			panic("internal inconsistency: replMapping should contain mapping for any path that was not filled in by WalkTopDown()")
+		}
+
+		return p.replFilesystem(m, localFilesystemState)
 	})
 
 	return

cmd/sampleconf/localbackup/host1.yml

@@ -19,6 +19,7 @@ jobs:
   prune_lhs:
     policy: grid
     grid: 1x1h(keep=all)
+    keep_bookmarks: all
 
   # follow a grandfathering scheme for filesystems on the right-hand-side of the mapping
   prune_rhs:

cmd/sampleconf/pullbackup/productionhost.yml

@@ -37,9 +37,11 @@ jobs:
   interval: 10m
 
 
-  # keep a one day window 10m interval snapshots in case pull doesn't work (link down, etc)
-  # (we cannot keep more than one day because this host will run out of disk space)
+  # keep 1 hour of snapshots (6 at 10m interval)
+  # and  one day of bookmarks in case pull doesn't work (link down, etc)
+  # => keep_bookmarks = 24h / interval = 24h / 10m = 144
   prune:
     policy: grid
-    grid: 1x1d(keep=all)
+    grid: 1x1h(keep=all)
+    keep_bookmarks: 144
 

cmd/sampleconf/random/debugging.yml

@@ -30,4 +30,4 @@ jobs:
   prune:
     policy: grid
     grid: 1x10s(keep=all)
-
+    keep_bookmarks: all

cmd/stdinserver.go

@@ -1,14 +1,13 @@
 package cmd
 
 import (
-	"fmt"
 	"os"
 
-	"github.com/ftrvxmtrx/fd"
+	"context"
+	"github.com/problame/go-netssh"
 	"github.com/spf13/cobra"
-	"io"
 	"log"
-	"net"
+	"path"
 )
 
 var StdinserverCmd = &cobra.Command{
@@ -23,71 +22,34 @@ func init() {
 
 func cmdStdinServer(cmd *cobra.Command, args []string) {
 
-	log := log.New(os.Stderr, "", log.LUTC|log.Ldate|log.Ltime)
+	// NOTE: the netssh proxying protocol requires exiting with non-zero status if anything goes wrong
+	defer os.Exit(1)
 
-	die := func() {
-		log.Printf("stdinserver exiting after fatal error")
-		os.Exit(1)
-	}
+	log := log.New(os.Stderr, "", log.LUTC|log.Ldate|log.Ltime)
 
 	conf, err := ParseConfig(rootArgs.configFile)
 	if err != nil {
 		log.Printf("error parsing config: %s", err)
-		die()
+		return
 	}
 
 	if len(args) != 1 || args[0] == "" {
-		err = fmt.Errorf("must specify client_identity as positional argument")
-		die()
-	}
-	identity := args[0]
-
-	unixaddr, err := stdinserverListenerSocket(conf.Global.Serve.Stdinserver.SockDir, identity)
-	if err != nil {
-		log.Printf("%s", err)
-		os.Exit(1)
-	}
-
-	log.Printf("opening control connection to zrepld via %s", unixaddr)
-	conn, err := net.DialUnix("unix", nil, unixaddr)
-	if err != nil {
-		log.Printf("error connecting to zrepld: %s", err)
-		die()
-	}
-
-	log.Printf("sending stdin and stdout fds to zrepld")
-	err = fd.Put(conn, os.Stdin, os.Stdout)
-	if err != nil {
-		log.Printf("error: %s", err)
-		die()
-	}
-
-	log.Printf("waiting for zrepld to close control connection")
-	for {
-
-		var buf [64]byte
-		n, err := conn.Read(buf[:])
-		if err == nil && n != 0 {
-			log.Printf("protocol error: read expected to timeout or EOF returned bytes")
-		}
-
-		if err == io.EOF {
-			log.Printf("zrepld closed control connection, terminating")
-			break
-		}
-
-		neterr, ok := err.(net.Error)
-		if !ok {
-			log.Printf("received unexpected error type: %T %s", err, err)
-			die()
-		}
-		if !neterr.Timeout() {
-			log.Printf("receivd unexpected net.Error (not a timeout): %s", neterr)
-			die()
-		}
-		// Read timed out, as expected
-	}
-
+		log.Print("must specify client_identity as positional argument")
 		return
+	}
+
+	identity := args[0]
+	unixaddr := path.Join(conf.Global.Serve.Stdinserver.SockDir, identity)
+
+	log.Printf("proxying client identity '%s' to zrepl daemon '%s'", identity, unixaddr)
+
+	ctx := netssh.ContextWithLog(context.TODO(), log)
+
+	err = netssh.Proxy(ctx, unixaddr)
+	if err == nil {
+		log.Print("proxying finished successfully, exiting with status 0")
+		os.Exit(0)
+	}
+	log.Printf("error proxying: %s", err)
 
 }

cmd/test.go

@@ -36,7 +36,7 @@ var testConfigSyntaxCmd = &cobra.Command{
 var testDatasetMapFilter = &cobra.Command{
 	Use:     "pattern jobname test/zfs/dataset/path",
 	Short:   "test dataset mapping / filter specified in config",
-	Example: ` zrepl test pattern prune.clean_backups tank/backups/legacyscript/foo`,
+	Example: ` zrepl test pattern my_pull_job tank/tmp`,
 	Run:     doTestDatasetMapFilter,
 }
 
@@ -170,7 +170,8 @@ func doTestPrunePolicy(cmd *cobra.Command, args []string) {
 
 	log.Printf("job dump:\n%s", pretty.Sprint(jobp))
 
-	pruner, err := jobp.Pruner(testPrunePolicyArgs.side, true)
+	task := NewTask("", log)
+	pruner, err := jobp.Pruner(task, testPrunePolicyArgs.side, true)
 	if err != nil {
 		log.Printf("cannot create test pruner: %s", err)
 		os.Exit(1)

cmd/version.go

@@ -0,0 +1,42 @@
+package cmd
+
+import (
+	"fmt"
+	"github.com/spf13/cobra"
+	"runtime"
+)
+
+var versionCmd = &cobra.Command{
+	Use:   "version",
+	Short: "print version of zrepl binary (for running daemon 'zrepl control version' command)",
+	Run:   doVersion,
+}
+
+func init() {
+	RootCmd.AddCommand(versionCmd)
+}
+
+func doVersion(cmd *cobra.Command, args []string) {
+	fmt.Println(NewZreplVersionInformation().String())
+}
+
+type ZreplVersionInformation struct {
+	Version         string
+	RuntimeGOOS     string
+	RuntimeGOARCH   string
+	RUNTIMECompiler string
+}
+
+func NewZreplVersionInformation() *ZreplVersionInformation {
+	return &ZreplVersionInformation{
+		Version:         zreplVersion,
+		RuntimeGOOS:     runtime.GOOS,
+		RuntimeGOARCH:   runtime.GOARCH,
+		RUNTIMECompiler: runtime.Compiler,
+	}
+}
+
+func (i *ZreplVersionInformation) String() string {
+	return fmt.Sprintf("zrepl version=%s GOOS=%s GOARCH=%s Compiler=%s",
+		i.Version, i.RuntimeGOOS, i.RuntimeGOARCH, i.RUNTIMECompiler)
+}

docs/Makefile

@@ -10,11 +10,11 @@ BUILDDIR      = _build
 
 # Put it first so that "make" without argument is like "make help".
 help:
-	@$(SPHINXBUILD) -M help "$(SOURCEDIR)" "$(BUILDDIR)" $(SPHINXOPTS) $(O)
+	@$(SPHINXBUILD) -M help "$(SOURCEDIR)" "$(BUILDDIR)" -c sphinxconf $(SPHINXOPTS) $(O)
 
 .PHONY: help Makefile
 
 # Catch-all target: route all unknown targets to Sphinx using the new
 # "make mode" option.  $(O) is meant as a shortcut for $(SPHINXOPTS).
 %: Makefile
-	@$(SPHINXBUILD) -M $@ "$(SOURCEDIR)" "$(BUILDDIR)" $(SPHINXOPTS) $(O)
+	@$(SPHINXBUILD) -M $@ "$(SOURCEDIR)" "$(BUILDDIR)" -c sphinxconf $(SPHINXOPTS) $(O)

docs/changelog.rst

@@ -1,5 +1,7 @@
 .. |break_config| replace:: **[BREAK]**
+.. |break| replace:: **[BREAK]**
 .. |bugfix| replace:: [BUG]
+.. |feature| replace:: [FEATURE]
 
 Changelog
 =========
@@ -7,11 +9,34 @@ Changelog
 The changelog summarized bugfixes that are deemed relevant for users.
 Developers should consult the git commit log or GitHub issue tracker.
 
-0.0.2
+0.0.3
 -----
 
-Breaking
-~~~~~~~~
+* |break_config| |feature| :issue:`34`: automatic bookmarking of snapshots
+
+  * Snapshots are automatically bookmarked and pruning of bookmarks **must** be configured.
+  * This breaks existing configuration: ``grid`` :ref:`prune policy <prune-retention-grid>`  specifications require the new ``keep_bookmarks`` parameter.
+  * Make sure to understand the meaning bookmarks have for :ref:`maximum replication downtime <replication-downtime>`.
+  * Example: :sampleconf:`pullbackup/productionhost.yml`
+
+* |break| :commit:`ccd062e`: both sides of a replication setup must be updated and restarted. Otherwise the connecting side will hang and not time out.
+* |break_config| :commit:`2bfcfa5`: first outlet in ``global.logging`` is now used for logging meta-errors, for example problems encountered when writing to other outlets.
+* |feature| :issue:`10`: ``zrepl control status`` subcommand
+
+  * Allows inspection of job activity per task and their log output at runtime.
+  * Supports ``--format raw`` option for JSON output, usable for monitoring from scripts.
+
+* |feature| :commit:`d7f3fb9`: subcommand bash completions
+
+  * Package maintainers should install this as appropriate.
+
+* |bugfix| :issue:`61`: fix excessive memory usage
+* |bugfix| :issue:`8` and :issue:`56`: ``ssh+stdinserver`` transport properly reaps SSH child processes
+* |bugfix| :commit:`cef63ac`: ``human`` format now prints non-string values correctly
+* |bugfix| :issue:`26`: slow TCP outlets no longer block the daemon
+
+0.0.2
+-----
 
 * |break_config| :commit:`b95260f`: ``global.logging`` is no longer a dictionary but a list
 

docs/conf.py

@@ -1,169 +0,0 @@
-#!/usr/bin/env python3
-# -*- coding: utf-8 -*-
-#
-# zrepl documentation build configuration file, created by
-# sphinx-quickstart on Wed Nov  8 22:28:10 2017.
-#
-# This file is execfile()d with the current directory set to its
-# containing dir.
-#
-# Note that not all possible configuration values are present in this
-# autogenerated file.
-#
-# All configuration values have a default; values that are commented out
-# serve to show the default.
-
-# If extensions (or modules to document with autodoc) are in another directory,
-# add these directories to sys.path here. If the directory is relative to the
-# documentation root, use os.path.abspath to make it absolute, like shown here.
-#
-# import os
-# import sys
-# sys.path.insert(0, os.path.abspath('.'))
-
-
-# -- General configuration ------------------------------------------------
-
-# If your documentation needs a minimal Sphinx version, state it here.
-#
-# needs_sphinx = '1.0'
-
-# Add any Sphinx extension module names here, as strings. They can be
-# extensions coming with Sphinx (named 'sphinx.ext.*') or your custom
-# ones.
-extensions = ['sphinx.ext.todo',
-    'sphinx.ext.githubpages',
-    'sphinx.ext.extlinks']
-
-# Add any paths that contain templates here, relative to this directory.
-templates_path = ['_templates']
-
-# The suffix(es) of source filenames.
-# You can specify multiple suffix as a list of string:
-#
-# source_suffix = ['.rst', '.md']
-source_suffix = '.rst'
-
-# The master toctree document.
-master_doc = 'index'
-
-# General information about the project.
-project = 'zrepl'
-copyright = '2017, Christian Schwarz'
-author = 'Christian Schwarz'
-
-# The version info for the project you're documenting, acts as replacement for
-# |version| and |release|, also used in various other places throughout the
-# built documents.
-#
-# The short X.Y version.
-import subprocess
-version = subprocess.check_output(["git", "describe"]).decode("utf-8")
-# The full version, including alpha/beta/rc tags.
-release = version
-
-# The language for content autogenerated by Sphinx. Refer to documentation
-# for a list of supported languages.
-#
-# This is also used if you do content translation via gettext catalogs.
-# Usually you set "language" from the command line for these cases.
-language = None
-
-# List of patterns, relative to source directory, that match files and
-# directories to ignore when looking for source files.
-# This patterns also effect to html_static_path and html_extra_path
-exclude_patterns = ['_build', 'Thumbs.db', '.DS_Store']
-
-# The name of the Pygments (syntax highlighting) style to use.
-pygments_style = 'sphinx'
-
-# If true, `todo` and `todoList` produce output, else they produce nothing.
-todo_include_todos = True
-
-
-# -- Options for HTML output ----------------------------------------------
-
-# The theme to use for HTML and HTML Help pages.  See the documentation for
-# a list of builtin themes.
-#
-html_theme = 'sphinx_rtd_theme'
-
-# Theme options are theme-specific and customize the look and feel of a theme
-# further.  For a list of options available for each theme, see the
-# documentation.
-#
-# html_theme_options = {}
-
-# Add any paths that contain custom static files (such as style sheets) here,
-# relative to this directory. They are copied after the builtin static files,
-# so a file named "default.css" will overwrite the builtin "default.css".
-html_static_path = ['_static']
-
-
-html_logo = '_static/zrepl.svg'
-
-# -- Options for HTMLHelp output ------------------------------------------
-
-# Output file base name for HTML help builder.
-htmlhelp_basename = 'zrepldoc'
-
-
-# -- Options for LaTeX output ---------------------------------------------
-
-latex_elements = {
-    # The paper size ('letterpaper' or 'a4paper').
-    #
-    # 'papersize': 'letterpaper',
-
-    # The font size ('10pt', '11pt' or '12pt').
-    #
-    # 'pointsize': '10pt',
-
-    # Additional stuff for the LaTeX preamble.
-    #
-    # 'preamble': '',
-
-    # Latex figure (float) alignment
-    #
-    # 'figure_align': 'htbp',
-}
-
-# Grouping the document tree into LaTeX files. List of tuples
-# (source start file, target name, title,
-#  author, documentclass [howto, manual, or own class]).
-latex_documents = [
-    (master_doc, 'zrepl.tex', 'zrepl Documentation',
-     'Christian Schwarz', 'manual'),
-]
-
-
-# -- Options for manual page output ---------------------------------------
-
-# One entry per manual page. List of tuples
-# (source start file, name, description, authors, manual section).
-man_pages = [
-    (master_doc, 'zrepl', 'zrepl Documentation',
-     [author], 1)
-]
-
-
-# -- Options for Texinfo output -------------------------------------------
-
-# Grouping the document tree into Texinfo files. List of tuples
-# (source start file, target name, title, author,
-#  dir menu entry, description, category)
-texinfo_documents = [
-    (master_doc, 'zrepl', 'zrepl Documentation',
-     author, 'zrepl', 'One line description of project.',
-     'Miscellaneous'),
-]
-
-
-# -- Options for the extlinks extension -----------------------------------
-# http://www.sphinx-doc.org/en/stable/ext/extlinks.html
-extlinks = {
-    'issue':('https://github.com/zrepl/zrepl/issues/%s', 'issue #'),
-    'sampleconf':('https://github.com/zrepl/zrepl/blob/master/cmd/sampleconf/%s', 'cmd/sampleconf'),
-    'commit':('https://github.com/zrepl/zrepl/commit/%s', 'commit '),
-        }
-

docs/conf.py

@@ -0,0 +1 @@
+sphinxconf/conf.py

docs/configuration.rst

@@ -7,6 +7,7 @@ Configuration
 
 .. toctree::
 
+    configuration/preface
     configuration/jobs
     configuration/transports
     configuration/map_filter_syntax

docs/configuration/jobs.rst

@@ -48,13 +48,14 @@ Example: :sampleconf:`pullbackup/productionhost.yml`.
     * - ``interval``
       - snapshotting interval
     * - ``prune``
-      - |prune| policy for filesytems in ``filesystems`` with prefix ``snapshot_prefix``
+      - |prune| for versions of filesytems in ``filesystems``, versions prefixed with ``snapshot_prefix``
 
 
 - Snapshotting Task (every ``interval``, |patient|)
 
   - A snapshot of filesystems matched by ``filesystems`` is taken every ``interval`` with prefix ``snapshot_prefix``.
-  - The ``prune`` policy is triggered on filesystems matched by ``filesystems`` with snapshots matched by ``snapshot_prefix``.
+  - A bookmark of that snapshot is created with the same name.
+  - The ``prune`` policy is evaluated for versions of filesystems matched by ``filesystems``, versions prefixed with ``snapshot_prefix``.
 
 - Serve Task
 
@@ -62,12 +63,8 @@ Example: :sampleconf:`pullbackup/productionhost.yml`.
 
 A source job is the counterpart to a :ref:`job-pull`.
 
-Note that the prune policy determines the maximum replication lag:
-a pull job may stop replication due to link failure, misconfiguration or administrative action.
-The source prune policy will eventually destroy the last common snapshot between source and pull job, requiring full replication.
 Make sure you read the |prune| policy documentation.
 
-
 .. _job-pull:
 
 Pull Job
@@ -96,7 +93,7 @@ Example: :sampleconf:`pullbackup/backuphost.yml`
     * - ``snapshot_prefix``
       - prefix snapshots must match to be considered for replication & pruning
     * - ``prune``
-      - |prune| policy for local filesystems reachable by ``mapping``
+      - |prune| policy for versions of filesystems of local filesystems reachable by ``mapping``, versions prefixed with ``snapshot_prefix``
 
 * Main Task (every ``interval``, |patient|)
  
@@ -109,10 +106,11 @@ Example: :sampleconf:`pullbackup/backuphost.yml`
      #. If the local target filesystem does not exist, ``initial_repl_policy`` is used.
      #. On conflicts, an error is logged but replication of other filesystems with mapping continues.
   
-  #. The ``prune`` policy is triggered for all *target filesystems*
+  #. The ``prune`` policy is evaluated for all *target filesystems*
 
 A pull job is the counterpart to a :ref:`job-source`.
 
+Make sure you read the |prune| policy documentation.
 
 .. _job-local:
 
@@ -148,6 +146,7 @@ Example: :sampleconf:`localbackup/host1.yml`
 
   #. Evaluate ``mapping`` for local filesystems, those with a *target filesystem* are called *mapped filesystems*.
   #. Snapshot *mapped filesystems* with ``snapshot_prefix``.
+  #. Bookmark the snapshot created above.
   #. Replicate *mapped filesystems* to their respective *target filesystems*:
 
      #. Only snapshots with prefix ``snapshot_prefix`` are replicated.
@@ -182,3 +181,7 @@ patient task
         * waits for the last invocation to finish
         * logs a warning with the effective task duration
         * immediately starts a new invocation of the task
+
+filesystem version
+
+    A snapshot or a bookmark.

docs/configuration/logging.rst

@@ -27,6 +27,14 @@ Check out :sampleconf:`random/logging.yml` for an example on how to configure mu
     
     jobs: ...
 
+.. _logging-error-outlet:
+
+.. ATTENTION::
+    The **first outlet is special**: if an error writing to any outlet occurs, the first outlet receives the error and can print it.
+    Thus, the first outlet must be the one that always works and does not block, e.g. ``stdout``, which is the default.
+
+.. _logging-default-config:
+
 Default Configuration
 ---------------------
 
@@ -41,10 +49,6 @@ By default, the following logging configuration is used
           level:  "warn"
           format: "human"
 
-.. ATTENTION::
-    Output to **stderr** should always be considered a **critical error**.
-    Only errors in the logging infrastructure itself, e.g. IO errors when writing to an outlet, are sent to stderr.
-
 Building Blocks
 ---------------
 
@@ -98,6 +102,11 @@ Formats
         ``encoding/json.Marshal()``, which is particularly useful for processing in
         log aggregation or when processing state dumps.
 
+Outlets
+~~~~~~~
+
+Outlets are the destination for log entries.
+
 .. _logging-outlet-stdout:
 
 ``stdout`` Outlet
@@ -115,8 +124,11 @@ Formats
       -  minimum  :ref:`log level <logging-levels>`
     * - ``format``
       - output :ref:`format <logging-formats>`
+    * - ``time``
+      - always include time in output (``true`` or ``false``)
 
 Writes all log entries with minimum level ``level`` formatted by ``format`` to stdout.
+If stdout is a tty, interactive usage is assumed and the current time is included in the output.
 
 Can only be specified once.
 
@@ -145,12 +157,6 @@ Can only be specified once.
 ``tcp`` Outlet
 --------------
 
-.. WARNING::
-
-    The TCP outlet is not fully asynchronous and blocks the calling goroutine when it cannot connect.
-    Currently it should only be used for local connections that are guaranteed to not fail / be slow.
-    This issue is tracked in :issue:`26`
-
 .. list-table::
     :widths: 10 90
     :header-rows: 1
@@ -192,6 +198,15 @@ This is particularly useful in combination with log aggregation services that ru
     * - ``key``
       - PEM-encoded, unencrypted client private key identifying this zrepl daemon toward the remote server
 
+.. WARNING::
+
+    zrepl drops log messages to the TCP outlet if the underlying connection is not fast enough.
+    Note that TCP buffering in the kernel must first run full becfore messages are dropped.
+
+    Make sure to always configure a ``stdout`` outlet as the special error outlet to be informed about problems
+    with the TCP outlet (see :ref:`above <logging-error-outlet>` ).
+
+
 .. NOTE::
 
     zrepl uses Go's ``crypto/tls`` and ``crypto/x509`` packages and leaves all but the required fields in ``tls.Config`` at their default values.

docs/configuration/map_filter_syntax.rst

@@ -82,6 +82,10 @@ The example is from the :sampleconf:`localbackup/host1.yml` example config.
     zroot/poudriere/ports/2017Q3        => NOT MAPPED
     zroot/poudriere/ports/HEAD          => NOT MAPPED
 
+.. TIP::
+
+   You can try out patterns for a configured job using the ``zrepl test`` subcommand.
+
 .. _pattern-filter:
 
 Filters

docs/configuration/misc.rst

@@ -13,10 +13,9 @@ zrepl daemon creates various UNIX sockets to allow communicating with it:
 
 There is no further authentication on these sockets.
 Therefore we have to make sure they can only be created and accessed by ``zrepl daemon``.
-
 In fact, ``zrepl daemon`` will not bind a socket to a path in a directory that is world-accessible.
 
-The directories can be configured in the main configuration file:
+The directories can be configured in the main configuration file, the defaults are provided below:
 
 ::
 

docs/configuration/preface.rst

@@ -0,0 +1,39 @@
+
+.. _configuration_preface:
+
+=======
+Preface
+=======
+
+-----------------------
+Configuration File Path
+-----------------------
+
+zrepl searches for its main configuration file in the following locations (in that order):
+
+* If set, the location specified via the global ``--config`` flag
+* ``/etc/zrepl/zrepl.yml``
+* ``/usr/local/etc/zrepl/zrepl.yml``
+
+The examples in the :ref:`tutorial` or the ``cmd/sampleconf`` directory should provide a good starting point.
+
+-------------------
+Runtime Directories
+-------------------
+
+zrepl requires runtime directories for various UNIX sockets --- they are documented in the :ref:`config file<conf-runtime-directories>`.
+Your package maintainer / init script should take care of creating them.
+Alternatively, for default settings, the following should to the trick.
+
+::
+
+    mkdir -p /var/run/zrepl/stdinserver
+    chmod -R 0700 /var/run/zrepl
+
+
+----------
+Validating
+----------
+
+The config can be validated using the ``zrepl test`` subcommand.
+

docs/configuration/prune.rst

@@ -3,15 +3,19 @@
 Pruning Policies
 ================
 
-In zrepl, *pruning* means *destroying snapshots by some policy*.
+In zrepl, *pruning* means *destroying filesystem versions by some policy* where filesystem versions are bookmarks and snapshots.
 
-A *pruning policy* takes a list of snapshots and -- for each snapshot -- decides whether it should be kept or destroyed.
+A *pruning policy* takes a list of filesystem versions and decides for each whether it should be kept or destroyed.
 
 The job context defines which snapshots are even considered for pruning, for example through the ``snapshot_prefix`` variable.
 Check the respective :ref:`job definition <job>` for details.
 
 Currently, the :ref:`prune-retention-grid` is the only supported pruning policy.
 
+.. TIP::
+
+    You can perform a dry-run of a job's pruning policy using the ``zrepl test`` subcommand.
+
 .. _prune-retention-grid:
 
 Retention Grid
@@ -21,6 +25,7 @@ Retention Grid
 
     jobs:
     - name: pull_app-srv
+      type: pull
       ...
       prune:
         policy: grid
@@ -30,6 +35,15 @@ Retention Grid
                                 │
                                 └─ 24 adjacent one-hour intervals
 
+    - name: pull_backup
+      type: source
+      interval: 10m
+      prune:
+        policy: grid
+        grid: 1x1d(keep=all)
+        keep_bookmarks: 144
+
+
 The retention grid can be thought of as a time-based sieve:
 The ``grid`` field specifies a list of adjacent time intervals:
 the left edge of the leftmost (first) interval is the ``creation`` date of the youngest snapshot.
@@ -39,6 +53,11 @@ Each interval carries a maximum number of snapshots to keep.
 It is secified via ``(keep=N)``, where ``N`` is either ``all`` (all snapshots are kept) or a positive integer.
 The default value is **1**.
 
+Bookmarks are not affected by the above.
+Instead, the ``keep_bookmarks`` field specifies the number of bookmarks to be kept per filesystem.
+You only need to specify ``keep_bookmarks`` at the source-side of a replication setup since the destination side does not receive bookmarks.
+You can specify ``all`` as a value to keep all bookmarks, but be warned that you should install some other way to prune unneeded ones then (see below).
+
 The following procedure happens during pruning:
 
 #. The list of snapshots eligible for pruning is sorted by ``creation``
@@ -50,15 +69,16 @@ The following procedure happens during pruning:
    #. the contained snapshot list is sorted by creation.
    #. snapshots from the list, oldest first, are destroyed until the specified ``keep`` count is reached.
    #. all remaining snapshots on the list are kept.
+#. The list of bookmarks eligible for pruning is sorted by ``createtxg`` and the most recent ``keep_bookmarks`` bookmarks are kept.
+
+.. _replication-downtime:
 
 .. ATTENTION::
 
-    .. TODO this is obsolete as soon as bookmarks are created during snapshotting
+    Be aware that ``keep_bookmarks x interval`` (interval of the job level) controls the **maximum allowable replication downtime** between source and destination.
+    If replication does not work for whatever reason, source and destination will eventually run out of sync because the source will continue pruning snapshots.
+    The only recovery in that case is full replication, which may not always be viable due to disk space or traffic constraints.
 
-    The configuration of the first interval (``1x1h(keep=all)`` in the example) determines the **maximum allowable replication lag** between source and destination.
-    After the first interval, source and destination likely have different retention settings.
-    This means source and destination may prune different snapshots, prohibiting incremental replication froms snapshots that are not in the first interval.
-
-    **Always** configure the first interval to ``1x?(keep=all)``, substituting ``?`` with the maximum time replication may fail due to downtimes, maintenance, connectivity issues, etc.
-    After outages longer than ``?`` you may be required to perform **full replication** again.
+    Further note that while bookmarks consume a constant amount of disk space, listing them requires temporary dynamic **kernel memory** proportional to the number of bookmarks.
+    Thus, do not use ``all`` or an inappropriately high value without good reason.
 

docs/configuration/transports.rst

@@ -16,7 +16,7 @@ Currently, only the ``ssh+stdinserver`` transport is supported.
 -----------------------------
 
 The way the ``ssh+stdinserver`` transport works is inspired by `git shell <https://git-scm.com/docs/git-shell>`_ and `Borg Backup <https://borgbackup.readthedocs.io/en/stable/deployment.html>`_.
-It is implemented in the Go package ``github.com/zrepl/zrepl/sshbytestream``.
+It is provided by the Go package ``github.com/problame/go-netssh``.
 The config excerpts are taken from the :ref:`tutorial` which you should complete before reading further.
 
 .. _transport-ssh+stdinserver-serve:

docs/index.rst

@@ -82,6 +82,7 @@ Table of Contents
    tutorial
    installation
    configuration
+   usage
    implementation
    changelog
    GitHub Repository & Issue Tracker <https://github.com/zrepl/zrepl>

docs/installation.rst

@@ -1,3 +1,5 @@
+.. _binary releases: https://github.com/zrepl/zrepl/releases
+
 .. _installation:
 
 Installation
@@ -18,8 +20,9 @@ However, until we get around documenting those setups, you will have to run zrep
 Packages
 --------
 
-zrepl releases are signed & tagged by the author in the git repository.
+zrepl source releases are signed & tagged by the author in the git repository.
 Your OS vendor may provide binary packages of zrepl through the package manager.
+Additionally, `binary releases`_ are provided on GitHub.
 The following list may be incomplete, feel free to submit a PR with an update:
 
 .. list-table::
@@ -33,98 +36,53 @@ The following list may be incomplete, feel free to submit a PR with an update:
       - `<https://www.freshports.org/sysutils/zrepl/>`_
     * - Others
       -
-      - Install from source, see below
+      - Use `binary releases`_ or build from source.
 
 Compile From Source
 ~~~~~~~~~~~~~~~~~~~
 
-Go 1.9 or newer and a configured ``$GOPATH`` environment variable and a few build dependencies are required to build zrepl.
-A tutorial is available over at `golang.org <https://golang.org/doc/install>`_.
-If Go 1.9 is not available on your distro consider build in Docker (see below).
+Producing a release requires **Go 1.9** or newer and **Python 3** + **pip3** + ``docs/requirements.txt`` for the Sphinx documentation.
+A tutorial to install Go is available over at `golang.org <https://golang.org/doc/install>`_.
+Python and pip3 should probably be installed via your distro's package manager.
 
-The following shell script checks out the zrepl project into your ``$GOPATH``,
-installs the build dependencies, installs dependencies using ``dep ensure`` and does a ``make release``.
-Build artifacts are placed into ``$GOPATH/github.com/zrepl/zrepl/artifacts/``.
-
-When doing builds afterwards, it should be sufficient to checkout the new revision, run ``dep ensure`` and ``make release``.
-You may want to switch to a tagged commit (we use `semver <http://semver.org>`_) but master should generally be considered stable.
-
-**Note**: it is your job to install the apropriate binary in the zrepl users's ``$PATH``, e.g. ``/usr/local/bin/zrepl``.
-Otherwise, the examples in the :ref:`tutorial` may need to be adjusted.
-
-**You are encouraged to understand what happens by auditing the script.**
-
-::
-
-    curl 'https://raw.githubusercontent.com/zrepl/zrepl/master/clone_and_build.sh' | sh
-
-You can also build in a Docker container if you want an isolated build environment or don't have a compatible Go version.
+Alternatively, you can use the Docker build process:
+it is used to produce the official zrepl `binary releases`_
+and serves as a reference for build dependencies and procedure:
 
 ::
 
     git clone https://github.com/zrepl/zrepl.git
     cd zrepl
+    sudo docker build -t zrepl_build -f build.Dockerfile .
     sudo docker run -it --rm \
-        -v "${PWD}:/zrepl" \
+        -v "${PWD}:/go/src/github.com/zrepl/zrepl" \
         --user "$(id -u):$(id -g)" \
-        golang:latest bash -c 'export CLONEPATH=/go/src/github.com/zrepl; mkdir -p "$CLONEPATH" && ln -s /zrepl $CLONEPATH/zrepl && ${CLONEPATH}/zrepl/clone_and_build.sh'
+        zrepl_build make vendordeps release
 
-.. literalinclude:: ../clone_and_build.sh
-    :language: sh
-
-
-.. _mainconfigfile:
-
-Configuration Files
--------------------
-
-zrepl searches for its main configuration file in the following locations (in that order):
-
-* ``/etc/zrepl/zrepl.yml``
-* ``/usr/local/etc/zrepl/zrepl.yml``
-
-Alternatively, use CLI flags to specify a config location.
-Copy a config from the :ref:`tutorial` or the ``cmd/sampleconf`` directory to one of these locations and customize it to your setup.
-
-Runtime Directories
--------------------
-
-zrepl requires ephemeral runtime directories where control sockets, etc are placed.
-Refer to the :ref:`configuration documentation <conf-runtime-directories>` for more information.
-
-When installing from a package, the package maintainer should have taken care of setting them up through the init system.
-Alternatively, for default settings, the following should to the trick.
+Alternatively, you can install build dependencies on your local system and then build in your ``$GOPATH``:
 
 ::
 
-    mkdir -p /var/run/zrepl/stdinserver
-    chmod -R 0700 /var/run/zrepl
+    mkdir -p "${GOPATH}/src/github.com/zrepl/zrepl"
+    git clone https://github.com/zrepl/zrepl.git "${GOPATH}/src/github.com/zrepl/zrepl"
+    cd "${GOPATH}/src/github.com/zrepl/zrepl"
+    ./lazy.sh devsetup
+    make vendordeps release
 
+Build results are located in the ``artifacts/`` directory.
 
-Running the Daemon
-------------------
+.. NOTE::
 
-All actual work zrepl does is performed by a daemon process.
-Logging is configurable via the config file. Please refer to the :ref:`logging documention <logging>`.
+    It is your job to install the apropriate binary in the zrepl users's ``$PATH``, e.g. ``/usr/local/bin/zrepl``.
+    Otherwise, the examples in the :ref:`tutorial` may need to be adjusted.
 
-When installating from a package, the package maintainer should have provided an init script / systemd.service file.
-You should thus be able to start zrepl daemon using your init system.
+.. _mainconfigfile:
 
-Alternatively, or for running zrepl in the foreground, simply execute ``zrepl daemon``.
-Note that you won't see any output unless you configure :ref:`stdout logging outlet <logging-outlet-stdout>`.
+What next?
+----------
 
-.. ATTENTION::
+Read the :ref:`configuration chapter<configuration_toc>` and optionally create the :ref:`runtime directories <configuration_preface>`.
+Afterwards, continue with the :ref:`usage chapter<usage>`.
 
-    Make sure to actually monitor the error level output of zrepl: some configuration errors will not make the daemon exit.
+**Reminder**: If you want a quick introduction, please read the :ref:`tutorial`.
 
-    Example: if the daemon cannot create the :ref:`transport-ssh+stdinserver` sockets in the runtime directory,
-    it will emit an error message but not exit because other tasks such as periodic snapshots & pruning are of equal importance.
-
-.. _install-restarting:
-
-Restarting
-~~~~~~~~~~
-
-The daemon handles SIGINT and SIGTERM for graceful shutdown.
-Graceful shutdown means at worst that a job will not be rescheduled for the next interval.
-The daemon exits as soon as all jobs have reported shut down.

docs/publish.sh

@@ -16,6 +16,11 @@ exit_msg() {
 }
 trap exit_msg EXIT
 
+if ! type sphinx-versioning >/dev/null; then
+    echo "install sphinx-versioning and come back"
+    exit 1
+fi
+
 cd "$SCRIPTDIR"
 
 if [ ! -d "$PUBLICDIR" ]; then
@@ -23,7 +28,7 @@ if [ ! -d "$PUBLICDIR" ]; then
     exit 1
 fi
 
-echo -n "PRESS ENTER to confirm you commited the docs changes to the zrepl repo"
+echo -n "PRESS ENTER to confirm you commited and pushed docs changes and tags to the zrepl repo"
 read
 
 pushd "$PUBLICDIR" 
@@ -47,9 +52,12 @@ popd
 
 echo "building site"
 set -e
-make clean
-make html
-rsync -a _build/html/ public_git/
+sphinx-versioning build \
+   --show-banner \
+   docs ./public_git \
+   -- -c sphinxconf # older conf.py throw errors because they used
+                    # version = subprocess.show_output(["git", "describe"])
+                    # which fails when building with sphinxcontrib-versioning
 set +e
 
 CURRENT_COMMIT=$(git rev-parse HEAD)
@@ -57,7 +65,7 @@ git status --porcelain
 if [[ "$(git status --porcelain)" != "" ]]; then
     CURRENT_COMMIT="${CURRENT_COMMIT}(dirty)" 
 fi
-COMMIT_MSG="sphinx render from publish.sh - `date -u` - ${CURRENT_COMMIT}"
+COMMIT_MSG="sphinx-versioning render from publish.sh - `date -u` - ${CURRENT_COMMIT}"
 
 pushd "$PUBLICDIR"
 

docs/requirements.txt

@@ -0,0 +1,28 @@
+Babel==2.5.1
+certifi==2017.11.5
+chardet==3.0.4
+click==6.7
+colorclass==2.2.0
+cryptography==1.7.1
+docutils==0.14
+idna==2.6
+imagesize==0.7.1
+Jinja2==2.10
+keyring==10.1
+keyrings.alt==1.3
+MarkupSafe==1.0
+pyasn1==0.1.9
+pycrypto==2.6.1
+Pygments==2.2.0
+pygobject==3.22.0
+pytz==2017.3
+pyxdg==0.25
+requests==2.18.4
+SecretStorage==2.3.1
+six==1.10.0
+snowballstemmer==1.2.1
+Sphinx==1.6.5
+sphinx-rtd-theme==0.2.4
+sphinxcontrib-versioning==2.2.1
+sphinxcontrib-websupport==1.0.1
+urllib3==1.22

docs/sphinxconf/conf.py

@@ -0,0 +1,168 @@
+#!/usr/bin/env python3
+# -*- coding: utf-8 -*-
+#
+# zrepl documentation build configuration file, created by
+# sphinx-quickstart on Wed Nov  8 22:28:10 2017.
+#
+# This file is execfile()d with the current directory set to its
+# containing dir.
+#
+# Note that not all possible configuration values are present in this
+# autogenerated file.
+#
+# All configuration values have a default; values that are commented out
+# serve to show the default.
+
+# If extensions (or modules to document with autodoc) are in another directory,
+# add these directories to sys.path here. If the directory is relative to the
+# documentation root, use os.path.abspath to make it absolute, like shown here.
+#
+# import os
+# import sys
+# sys.path.insert(0, os.path.abspath('.'))
+
+
+# -- General configuration ------------------------------------------------
+
+# If your documentation needs a minimal Sphinx version, state it here.
+#
+# needs_sphinx = '1.0'
+
+# Add any Sphinx extension module names here, as strings. They can be
+# extensions coming with Sphinx (named 'sphinx.ext.*') or your custom
+# ones.
+extensions = ['sphinx.ext.todo',
+    'sphinx.ext.githubpages',
+    'sphinx.ext.extlinks']
+
+# Add any paths that contain templates here, relative to this directory.
+templates_path = ['../_templates']
+
+# The suffix(es) of source filenames.
+# You can specify multiple suffix as a list of string:
+#
+# source_suffix = ['.rst', '.md']
+source_suffix = '.rst'
+
+# The master toctree document.
+master_doc = 'index'
+
+# General information about the project.
+project = 'zrepl'
+copyright = '2017, Christian Schwarz'
+author = 'Christian Schwarz'
+
+# The version info for the project you're documenting, acts as replacement for
+# |version| and |release|, also used in various other places throughout the
+# built documents.
+#
+# The short X.Y version.
+#version = set by sphinxcontrib-versioning
+# The full version, including alpha/beta/rc tags.
+#release = version
+
+# The language for content autogenerated by Sphinx. Refer to documentation
+# for a list of supported languages.
+#
+# This is also used if you do content translation via gettext catalogs.
+# Usually you set "language" from the command line for these cases.
+language = None
+
+# List of patterns, relative to source directory, that match files and
+# directories to ignore when looking for source files.
+# This patterns also effect to html_static_path and html_extra_path
+exclude_patterns = ['_build', 'Thumbs.db', '.DS_Store']
+
+# The name of the Pygments (syntax highlighting) style to use.
+pygments_style = 'sphinx'
+
+# If true, `todo` and `todoList` produce output, else they produce nothing.
+todo_include_todos = True
+
+
+# -- Options for HTML output ----------------------------------------------
+
+# The theme to use for HTML and HTML Help pages.  See the documentation for
+# a list of builtin themes.
+#
+html_theme = 'sphinx_rtd_theme'
+
+# Theme options are theme-specific and customize the look and feel of a theme
+# further.  For a list of options available for each theme, see the
+# documentation.
+#
+# html_theme_options = {}
+
+# Add any paths that contain custom static files (such as style sheets) here,
+# relative to this directory. They are copied after the builtin static files,
+# so a file named "default.css" will overwrite the builtin "default.css".
+html_static_path = ['../_static']
+
+
+html_logo = '../_static/zrepl.svg'
+
+# -- Options for HTMLHelp output ------------------------------------------
+
+# Output file base name for HTML help builder.
+htmlhelp_basename = 'zrepldoc'
+
+
+# -- Options for LaTeX output ---------------------------------------------
+
+latex_elements = {
+    # The paper size ('letterpaper' or 'a4paper').
+    #
+    # 'papersize': 'letterpaper',
+
+    # The font size ('10pt', '11pt' or '12pt').
+    #
+    # 'pointsize': '10pt',
+
+    # Additional stuff for the LaTeX preamble.
+    #
+    # 'preamble': '',
+
+    # Latex figure (float) alignment
+    #
+    # 'figure_align': 'htbp',
+}
+
+# Grouping the document tree into LaTeX files. List of tuples
+# (source start file, target name, title,
+#  author, documentclass [howto, manual, or own class]).
+latex_documents = [
+    (master_doc, 'zrepl.tex', 'zrepl Documentation',
+     'Christian Schwarz', 'manual'),
+]
+
+
+# -- Options for manual page output ---------------------------------------
+
+# One entry per manual page. List of tuples
+# (source start file, name, description, authors, manual section).
+man_pages = [
+    (master_doc, 'zrepl', 'zrepl Documentation',
+     [author], 1)
+]
+
+
+# -- Options for Texinfo output -------------------------------------------
+
+# Grouping the document tree into Texinfo files. List of tuples
+# (source start file, target name, title, author,
+#  dir menu entry, description, category)
+texinfo_documents = [
+    (master_doc, 'zrepl', 'zrepl Documentation',
+     author, 'zrepl', 'One line description of project.',
+     'Miscellaneous'),
+]
+
+
+# -- Options for the extlinks extension -----------------------------------
+# http://www.sphinx-doc.org/en/stable/ext/extlinks.html
+extlinks = {
+    'issue':('https://github.com/zrepl/zrepl/issues/%s', 'issue #'),
+    'sampleconf':('https://github.com/zrepl/zrepl/blob/master/cmd/sampleconf/%s', 'cmd/sampleconf'),
+    'commit':('https://github.com/zrepl/zrepl/commit/%s', 'commit '),
+        }
+

docs/tutorial.rst

@@ -119,6 +119,7 @@ We define a corresponding **source job** named ``pull_backup`` in the |mainconfi
       prune:
           policy: grid
           grid: 1x1d(keep=all)
+          keep_bookmarks: 144
 
 
 The ``serve`` section corresponds to the ``connect`` section in the configuration of ``backup-srv``.
@@ -153,12 +154,15 @@ Apply Configuration Changes
 ---------------------------
 
 We need to restart the zrepl daemon on **both** ``app-srv`` and ``backup-srv``.
-This is :ref:`OS-specific <install-restarting>`.
+This is :ref:`OS-specific <usage-zrepl-daemon-restarting>`.
 
 Watch it Work
 -------------
 
-A common setup is to ``watch`` the log output and ``zfs list`` of snapshots on both machines.
+Run ``zrepl control status`` to view the current activity of the configured jobs.
+If a job encountered problems since it last left idle state, the output contains useful debug log.
+
+Additionally, you can check the detailed structured logs of the `zrepl daemon` process and use GNU *watch* to view the snapshots present on both machines.
 
 If you like tmux, here is a handy script that works on FreeBSD: ::
 

docs/usage.rst

@@ -0,0 +1,62 @@
+.. _usage:
+
+*****
+Usage
+*****
+
+============
+CLI Overview
+============
+
+.. NOTE::
+
+    To avoid duplication, the zrepl binary is self-documenting:
+    invoke any subcommand at any level with the ``--help`` flag to get information on the subcommand, available flags, etc.
+
+.. list-table::
+    :widths: 30 70
+    :header-rows: 1
+
+    * - Subcommand
+      - Description
+    * - ``zrepl daemon``
+      - run the daemon, required for all zrepl functionality
+    * - ``zrepl control``
+      - control / query the daemon
+    * - ``zrepl control status``
+      - show job activity / monitoring (``--format raw``)
+    * - ``zrepl test``
+      - test configuration, try pattern syntax, dry run pruning policy, etc.
+    * - ``zrepl stdinserver``
+      - see :ref:`transport-ssh+stdinserver`
+
+.. _usage-zrepl-daemon:
+
+============
+zrepl daemon
+============
+
+All actual work zrepl does is performed by a daemon process.
+Logging is configurable via the config file. Please refer to the :ref:`logging documention <logging>`.
+
+When installating from a package, the package maintainer should have provided an init script / systemd.service file.
+You should thus be able to start zrepl daemon using your init system.
+
+Alternatively, or for running zrepl in the foreground, simply execute ``zrepl daemon``.
+Note that you won't see much output with the :ref:`default logging configuration<logging-default-config>`:
+
+.. ATTENTION::
+
+    Make sure to actually monitor the error level output of zrepl: some configuration errors will not make the daemon exit.
+
+    Example: if the daemon cannot create the :ref:`transport-ssh+stdinserver` sockets in the runtime directory,
+    it will emit an error message but not exit because other tasks such as periodic snapshots & pruning are of equal importance.
+
+.. _usage-zrepl-daemon-restarting:
+
+Restarting
+~~~~~~~~~~
+
+The daemon handles SIGINT and SIGTERM for graceful shutdown.
+Graceful shutdown means at worst that a job will not be rescheduled for the next interval.
+The daemon exits as soon as all jobs have reported shut down.

lazy.sh

@@ -0,0 +1,80 @@
+#!/bin/bash
+set -e
+
+if tty -s; then
+    bold=$(tput bold)
+    normal=$(tput sgr0)
+else
+    bold=""
+    normal=""
+fi
+
+step() {
+    echo "${bold}$1${normal}"
+}
+
+if ! type go >/dev/null; then
+    step "go binary not installed or not in \$PATH" 1>&2
+    exit 1
+fi
+
+if [ -z "$GOPATH" ]; then
+    step "Make sure you have your GOPATH configured correctly" 1>&2
+    exit 1
+fi
+
+CHECKOUTPATH="${GOPATH}/src/github.com/zrepl/zrepl"
+
+builddep() {
+    step "Install build depdencies using 'go get' to \$GOPATH/bin"
+    go get -u golang.org/x/tools/cmd/stringer
+    go get -u github.com/golang/dep/cmd/dep
+    if ! type stringer || ! type dep; then
+        echo "Installed dependencies but can't find them in \$PATH, adjust it to contain \$GOPATH/bin" 1>&2
+        exit 1
+    fi
+}
+
+godep() {
+    step "Fetching dependencies using 'dep ensure'"
+    dep ensure
+}
+
+docdep() {
+    if ! type pip3; then
+        step "pip3 binary not installed or not in \$PATH" 1>&2
+        exit 1
+    fi
+    step "Installing doc build dependencies"
+    local reqpath="${CHECKOUTPATH}/docs/requirements.txt"
+    if [ ! -z "$ZREPL_LAZY_DOCS_REQPATH" ]; then
+        reqpath="$ZREPL_LAZY_DOCS_REQPATH"
+    fi
+    pip3 install -r "$reqpath"
+}
+
+release() {
+    step "Making release"
+    make release
+}
+
+for cmd in "$@"; do
+    case "$cmd" in
+        builddep|godep|docdep|release_bins|docs)
+            eval $cmd
+            continue
+            ;;
+        devsetup)
+            step "Installing development dependencies"
+            builddep
+            docdep
+            step "Development dependencies installed"
+            continue
+            ;;
+        *)
+            step "Invalid command ${cmd}, exiting"
+            exit 1
+            ;;
+    esac
+done
+

logger/datastructures.go

@@ -1,10 +1,11 @@
 package logger
 
 import (
-	"context"
+	"bytes"
 	"encoding/json"
 	"fmt"
 	"github.com/pkg/errors"
+	"sync"
 	"time"
 )
 
@@ -14,6 +15,38 @@ func (l Level) MarshalJSON() ([]byte, error) {
 	return json.Marshal(l.String())
 }
 
+func (l *Level) UnmarshalJSON(input []byte) (err error) {
+	var s string
+	if err = json.Unmarshal(input, &s); err != nil {
+		return err
+	}
+	*l, err = ParseLevel(s)
+	return err
+}
+
+// implement flag.Value
+// implement github.com/spf13/pflag.Value
+func (l *Level) Set(s string) error {
+	newl, err := ParseLevel(s)
+	if err != nil {
+		return err
+	}
+	*l = newl
+	return nil
+}
+
+// implement github.com/spf13/pflag.Value
+func (l *Level) Type() string {
+	var buf bytes.Buffer
+	for i, l := range AllLevels {
+		fmt.Fprintf(&buf, "%s", l)
+		if i != len(AllLevels)-1 {
+			fmt.Fprintf(&buf, "|")
+		}
+	}
+	return fmt.Sprintf("(%s)", buf.String())
+}
+
 const (
 	Debug Level = iota
 	Info
@@ -72,20 +105,67 @@ type Entry struct {
 	Fields  Fields
 }
 
+// An outlet receives log entries produced by the Logger and writes them to some destination.
 type Outlet interface {
+	// Write the entry to the destination.
+	//
+	// Logger waits for all outlets to return from WriteEntry() before returning from the log call.
+	// An implementation of Outlet must assert that it does not block in WriteEntry.
+	// Otherwise, it will slow down the program.
+	//
 	// Note: os.Stderr is also used by logger.Logger for reporting errors returned by outlets
 	//       => you probably don't want to log there
-	WriteEntry(ctx context.Context, entry Entry) error
+	WriteEntry(entry Entry) error
 }
 
-type Outlets map[Level][]Outlet
-
-func NewOutlets() Outlets {
-	return make(Outlets, len(AllLevels))
+type Outlets struct {
+	mtx  sync.RWMutex
+	outs map[Level][]Outlet
 }
 
-func (os Outlets) Add(outlet Outlet, minLevel Level) {
+func NewOutlets() *Outlets {
+	return &Outlets{
+		mtx:  sync.RWMutex{},
+		outs: make(map[Level][]Outlet, len(AllLevels)),
+	}
+}
+
+func (os *Outlets) DeepCopy() (copy *Outlets) {
+	copy = NewOutlets()
+	for level := range os.outs {
+		for i := range os.outs[level] {
+			copy.outs[level] = append(copy.outs[level], os.outs[level][i])
+		}
+	}
+	return copy
+}
+
+func (os *Outlets) Add(outlet Outlet, minLevel Level) {
+	os.mtx.Lock()
+	defer os.mtx.Unlock()
 	for _, l := range AllLevels[minLevel:] {
-		os[l] = append(os[l], outlet)
+		os.outs[l] = append(os.outs[l], outlet)
 	}
 }
+
+func (os *Outlets) Get(level Level) []Outlet {
+	os.mtx.RLock()
+	defer os.mtx.RUnlock()
+	return os.outs[level]
+}
+
+// Return the first outlet added to this Outlets list using Add()
+// with minLevel <= Error.
+// If no such outlet is in this Outlets list, a discarding outlet is returned.
+func (os *Outlets) GetLoggerErrorOutlet() Outlet {
+	os.mtx.RLock()
+	defer os.mtx.RUnlock()
+	if len(os.outs[Error]) < 1 {
+		return nullOutlet{}
+	}
+	return os.outs[Error][0]
+}
+
+type nullOutlet struct{}
+
+func (nullOutlet) WriteEntry(entry Entry) error { return nil }

logger/logger.go

@@ -1,9 +1,7 @@
 package logger
 
 import (
-	"context"
 	"fmt"
-	"os"
 	"runtime/debug"
 	"sync"
 	"time"
@@ -15,17 +13,16 @@ const (
 )
 
 const DefaultUserFieldCapacity = 5
-const InternalErrorPrefix = "github.com/zrepl/zrepl/logger: "
 
 type Logger struct {
 	fields        Fields
-	outlets       Outlets
+	outlets       *Outlets
 	outletTimeout time.Duration
 
 	mtx *sync.Mutex
 }
 
-func NewLogger(outlets Outlets, outletTimeout time.Duration) *Logger {
+func NewLogger(outlets *Outlets, outletTimeout time.Duration) *Logger {
 	return &Logger{
 		make(Fields, DefaultUserFieldCapacity),
 		outlets,
@@ -34,6 +31,29 @@ func NewLogger(outlets Outlets, outletTimeout time.Duration) *Logger {
 	}
 }
 
+type outletResult struct {
+	Outlet Outlet
+	Error  error
+}
+
+func (l *Logger) logInternalError(outlet Outlet, err string) {
+	fields := Fields{}
+	if outlet != nil {
+		if _, ok := outlet.(fmt.Stringer); ok {
+			fields["outlet"] = fmt.Sprintf("%s", outlet)
+		}
+		fields["outlet_type"] = fmt.Sprintf("%T", outlet)
+	}
+	fields[FieldError] = err
+	entry := Entry{
+		Error,
+		"outlet error",
+		time.Now(),
+		fields,
+	}
+	l.outlets.GetLoggerErrorOutlet().WriteEntry(entry)
+}
+
 func (l *Logger) log(level Level, msg string) {
 
 	l.mtx.Lock()
@@ -41,45 +61,43 @@ func (l *Logger) log(level Level, msg string) {
 
 	entry := Entry{level, msg, time.Now(), l.fields}
 
-	ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(l.outletTimeout))
-	ech := make(chan error)
-
-	louts := l.outlets[level]
+	louts := l.outlets.Get(level)
+	ech := make(chan outletResult, len(louts))
 	for i := range louts {
-		go func(ctx context.Context, outlet Outlet, entry Entry) {
-			ech <- outlet.WriteEntry(ctx, entry)
-		}(ctx, louts[i], entry)
+		go func(outlet Outlet, entry Entry) {
+			ech <- outletResult{outlet, outlet.WriteEntry(entry)}
+		}(louts[i], entry)
 	}
-
 	for fin := 0; fin < len(louts); fin++ {
-		select {
-		case err := <-ech:
-			if err != nil {
-				fmt.Fprintf(os.Stderr, "%s outlet error: %s\n", InternalErrorPrefix, err)
-			}
-		case <-ctx.Done():
-			if ctx.Err() == context.DeadlineExceeded {
-				fmt.Fprintf(os.Stderr, "%s outlets exceeded deadline, keep waiting anyways", InternalErrorPrefix)
+		res := <-ech
+		if res.Error != nil {
+			l.logInternalError(res.Outlet, res.Error.Error())
 		}
 	}
-	}
-
-	cancel() // make go vet happy
+	close(ech)
 
 }
 
-func (l *Logger) WithField(field string, val interface{}) *Logger {
-
+func (l *Logger) WithOutlet(outlet Outlet, level Level) *Logger {
 	l.mtx.Lock()
 	defer l.mtx.Unlock()
-
-	if _, ok := l.fields[field]; ok {
-		fmt.Fprintf(os.Stderr, "%s caller overwrites field '%s'. Stack:\n%s\n", InternalErrorPrefix, field, string(debug.Stack()))
+	newOutlets := l.outlets.DeepCopy()
+	newOutlets.Add(outlet, level)
+	child := &Logger{
+		fields:        l.fields,
+		outlets:       newOutlets,
+		outletTimeout: l.outletTimeout,
+		mtx:           l.mtx,
 	}
+	return child
+}
+
+// callers must hold l.mtx
+func (l *Logger) forkLogger(field string, val interface{}) *Logger {
 
 	child := &Logger{
 		fields:        make(Fields, len(l.fields)+1),
-		outlets:       l.outlets, // cannot be changed after logger initialized
+		outlets:       l.outlets,
 		outletTimeout: l.outletTimeout,
 		mtx:           l.mtx,
 	}
@@ -89,14 +107,29 @@ func (l *Logger) WithField(field string, val interface{}) *Logger {
 	child.fields[field] = val
 
 	return child
+}
 
+func (l *Logger) ReplaceField(field string, val interface{}) *Logger {
+	l.mtx.Lock()
+	defer l.mtx.Unlock()
+	return l.forkLogger(field, val)
+}
+
+func (l *Logger) WithField(field string, val interface{}) *Logger {
+	l.mtx.Lock()
+	defer l.mtx.Unlock()
+	if val, ok := l.fields[field]; ok && val != nil {
+		l.logInternalError(nil,
+			fmt.Sprintf("caller overwrites field '%s'. Stack: %s", field, string(debug.Stack())))
+	}
+	return l.forkLogger(field, val)
 }
 
 func (l *Logger) WithFields(fields Fields) (ret *Logger) {
 	// TODO optimize
 	ret = l
 	for field, value := range fields {
-		ret = l.WithField(field, value)
+		ret = ret.WithField(field, value)
 	}
 	return ret
 }

logger/logger_test.go

@@ -1,7 +1,6 @@
 package logger_test
 
 import (
-	"context"
 	"fmt"
 	"github.com/kr/pretty"
 	"github.com/zrepl/zrepl/logger"
@@ -13,7 +12,7 @@ type TestOutlet struct {
 	Record []logger.Entry
 }
 
-func (o *TestOutlet) WriteEntry(ctx context.Context, entry logger.Entry) error {
+func (o *TestOutlet) WriteEntry(entry logger.Entry) error {
 	o.Record = append(o.Record, entry)
 	return nil
 }

rpc/datatype_string.go

@@ -0,0 +1,17 @@
+// Code generated by "stringer -type=DataType"; DO NOT EDIT.
+
+package rpc
+
+import "fmt"
+
+const _DataType_name = "DataTypeNoneDataTypeControlDataTypeMarshaledJSONDataTypeOctets"
+
+var _DataType_index = [...]uint8{0, 12, 27, 48, 62}
+
+func (i DataType) String() string {
+	i -= 1
+	if i >= DataType(len(_DataType_index)-1) {
+		return fmt.Sprintf("DataType(%d)", i+1)
+	}
+	return _DataType_name[_DataType_index[i]:_DataType_index[i+1]]
+}

rpc/frame_layer.go

@@ -57,6 +57,7 @@ func NewErrorHeader(status Status, format string, args ...interface{}) (h *Heade
 	return
 }
 
+//go:generate stringer -type=DataType
 type DataType uint8
 
 const (

sshbytestream/ssh.go

@@ -1,123 +0,0 @@
-package sshbytestream
-
-import (
-	"fmt"
-	"io"
-	"os"
-	"runtime"
-	"syscall"
-
-	"github.com/zrepl/zrepl/util"
-)
-
-type Error struct {
-	Stderr  []byte
-	WaitErr error
-}
-
-func (e Error) Error() string {
-	return fmt.Sprintf("ssh command failed with error: %v. stderr:\n%s\n", e.WaitErr, e.Stderr)
-}
-
-type SSHTransport struct {
-	Host         string
-	User         string
-	Port         uint16
-	IdentityFile string
-	SSHCommand   string
-	Options      []string
-}
-
-var SSHCommand string = "ssh"
-var SSHServerAliveInterval uint = 60
-
-func Incoming() (wc io.ReadWriteCloser, err error) {
-	// derivce ReadWriteCloser from stdin & stdout
-	return IncomingReadWriteCloser{}, nil
-}
-
-type IncomingReadWriteCloser struct{}
-
-func (f IncomingReadWriteCloser) Read(p []byte) (n int, err error) {
-	return os.Stdin.Read(p)
-}
-
-func (f IncomingReadWriteCloser) Write(p []byte) (n int, err error) {
-	return os.Stdout.Write(p)
-}
-
-func (f IncomingReadWriteCloser) Close() (err error) {
-	if err = os.Stdin.Close(); err != nil {
-		return
-	}
-	if err = os.Stdout.Close(); err != nil {
-		return
-	}
-	return
-}
-
-type OutgoingSSHByteStream struct {
-	c *util.IOCommand
-}
-
-func Outgoing(remote SSHTransport) (s OutgoingSSHByteStream, err error) {
-
-	sshArgs := make([]string, 0, 2*len(remote.Options)+4)
-	sshArgs = append(sshArgs,
-		"-p", fmt.Sprintf("%d", remote.Port),
-		"-q",
-		"-i", remote.IdentityFile,
-		"-o", "BatchMode=yes",
-		"-o", fmt.Sprintf("ServerAliveInterval=%d", SSHServerAliveInterval),
-	)
-	for _, option := range remote.Options {
-		sshArgs = append(sshArgs, "-o", option)
-	}
-	sshArgs = append(sshArgs, fmt.Sprintf("%s@%s", remote.User, remote.Host))
-
-	var sshCommand = SSHCommand
-	if len(remote.SSHCommand) > 0 {
-		sshCommand = remote.SSHCommand
-	}
-
-	if s.c, err = util.NewIOCommand(sshCommand, sshArgs, util.IOCommandStderrBufSize); err != nil {
-		return
-	}
-
-	// Clear environment of cmd, ssh shall not rely on SSH_AUTH_SOCK, etc.
-	s.c.Cmd.Env = []string{}
-
-	err = s.c.Start()
-	return
-}
-
-func (s OutgoingSSHByteStream) Read(p []byte) (n int, err error) {
-	return s.c.Read(p)
-}
-
-func (s OutgoingSSHByteStream) Write(p []byte) (n int, err error) {
-	return s.c.Write(p)
-}
-
-func (s OutgoingSSHByteStream) Close() (err error) {
-	err = s.c.Close()
-	if err == nil || s.c.ExitResult == nil {
-		return
-	}
-
-	// SSH catches SIGTERM and has different exit codes on different platforms
-	ws := s.c.ExitResult.WaitStatus
-	switch runtime.GOOS {
-	case "linux":
-		if ws.ExitStatus() == 128+int(syscall.SIGTERM) { // OpenSSH_7.5p1, OpenSSL 1.1.0f  25 May 2017 Arch Linux
-			err = nil
-		}
-	case "freebsd": // OpenSSH_7.2p2, OpenSSL 1.0.2k-freebsd  26 Jan 2017
-		if ws.ExitStatus() == 255 {
-			err = nil
-		}
-	default: // TODO
-	}
-
-	return
-}

util/io.go

@@ -3,7 +3,6 @@ package util
 import (
 	"io"
 	"os"
-	"time"
 )
 
 type ReadWriteCloserLogger struct {
@@ -97,52 +96,3 @@ func (c *ChainedReader) Read(buf []byte) (n int, err error) {
 
 	return
 }
-
-type IOProgress struct {
-	TotalRX uint64
-}
-
-type IOProgressCallback func(progress IOProgress)
-
-type IOProgressWatcher struct {
-	Reader         io.Reader
-	callback       IOProgressCallback
-	callbackTicker *time.Ticker
-	progress       IOProgress
-	updateChannel  chan int
-}
-
-func (w *IOProgressWatcher) KickOff(callbackInterval time.Duration, callback IOProgressCallback) {
-	w.callback = callback
-	w.callbackTicker = time.NewTicker(callbackInterval)
-	w.updateChannel = make(chan int)
-	go func() {
-	outer:
-		for {
-			select {
-			case newBytes, more := <-w.updateChannel:
-				w.progress.TotalRX += uint64(newBytes)
-				if !more {
-					w.callbackTicker.Stop()
-					break outer
-				}
-			case <-w.callbackTicker.C:
-				w.callback(w.progress)
-			}
-		}
-		w.callback(w.progress)
-	}()
-}
-
-func (w *IOProgressWatcher) Progress() IOProgress {
-	return w.progress
-}
-
-func (w *IOProgressWatcher) Read(p []byte) (n int, err error) {
-	n, err = w.Reader.Read(p)
-	w.updateChannel <- n
-	if err != nil {
-		close(w.updateChannel)
-	}
-	return
-}

util/semaphore.go

@@ -0,0 +1,17 @@
+package util
+
+type Semaphore struct {
+	c chan struct{}
+}
+
+func NewSemaphore(cap int) Semaphore {
+	return Semaphore{make(chan struct{}, cap)}
+}
+
+func (s Semaphore) Down() {
+	s.c <- struct{}{}
+}
+
+func (s Semaphore) Up() {
+	<-s.c
+}

zfs/mapping.go

@@ -1,6 +1,9 @@
 package zfs
 
-import "fmt"
+import (
+	"context"
+	"fmt"
+)
 
 type DatasetFilter interface {
 	Filter(p *DatasetPath) (pass bool, err error)
@@ -12,15 +15,21 @@ func ZFSListMapping(filter DatasetFilter) (datasets []*DatasetPath, err error) {
 		panic("filter must not be nil")
 	}
 
-	var lines [][]string
-	lines, err = ZFSList([]string{"name"}, "-r", "-t", "filesystem,volume")
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+	rchan := make(chan ZFSListResult)
+	go ZFSListChan(ctx, rchan, []string{"name"}, "-r", "-t", "filesystem,volume")
 
-	datasets = make([]*DatasetPath, 0, len(lines))
+	datasets = make([]*DatasetPath, 0)
+	for r := range rchan {
 
-	for _, line := range lines {
+		if r.err != nil {
+			err = r.err
+			return
+		}
 
 		var path *DatasetPath
-		if path, err = NewDatasetPath(line[0]); err != nil {
+		if path, err = NewDatasetPath(r.fields[0]); err != nil {
 			return
 		}
 

zfs/versions.go

@@ -2,6 +2,7 @@ package zfs
 
 import (
 	"bytes"
+	"context"
 	"errors"
 	"fmt"
 	"strconv"
@@ -61,17 +62,23 @@ type FilesystemVersionFilter interface {
 }
 
 func ZFSListFilesystemVersions(fs *DatasetPath, filter FilesystemVersionFilter) (res []FilesystemVersion, err error) {
-	var fieldLines [][]string
-	fieldLines, err = ZFSList(
+	listResults := make(chan ZFSListResult)
+
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+	go ZFSListChan(ctx, listResults,
 		[]string{"name", "guid", "createtxg", "creation"},
 		"-r", "-d", "1",
 		"-t", "bookmark,snapshot",
 		"-s", "createtxg", fs.ToString())
-	if err != nil {
-		return
+
+	res = make([]FilesystemVersion, 0)
+	for listResult := range listResults {
+		if listResult.err != nil {
+			return nil, listResult.err
 		}
-	res = make([]FilesystemVersion, 0, len(fieldLines))
-	for _, line := range fieldLines {
+
+		line := listResult.fields
 
 		if len(line[0]) < 3 {
 			err = errors.New(fmt.Sprintf("snapshot or bookmark name implausibly short: %s", line[0]))

zfs/zfs.go

@@ -10,6 +10,8 @@ import (
 	"os/exec"
 	"strings"
 
+	"context"
+	"github.com/problame/go-rwccmd"
 	"github.com/zrepl/zrepl/util"
 )
 
@@ -185,6 +187,68 @@ func ZFSList(properties []string, zfsArgs ...string) (res [][]string, err error)
 	return
 }
 
+type ZFSListResult struct {
+	fields []string
+	err    error
+}
+
+// ZFSListChan executes `zfs list` and sends the results to the `out` channel.
+// The `out` channel is always closed by ZFSListChan:
+// If an error occurs, it is closed after sending a result with the err field set.
+// If no error occurs, it is just closed.
+// If the operation is cancelled via context, the channel is just closed.
+//
+// However, if callers do not drain `out` or cancel via `ctx`, the process will leak either running because
+// IO is pending or as a zombie.
+func ZFSListChan(ctx context.Context, out chan ZFSListResult, properties []string, zfsArgs ...string) {
+	defer close(out)
+
+	args := make([]string, 0, 4+len(zfsArgs))
+	args = append(args,
+		"list", "-H", "-p",
+		"-o", strings.Join(properties, ","))
+	args = append(args, zfsArgs...)
+
+	sendResult := func(fields []string, err error) (done bool) {
+		select {
+		case <-ctx.Done():
+			return true
+		case out <- ZFSListResult{fields, err}:
+			return false
+		}
+	}
+
+	cmd, err := rwccmd.CommandContext(ctx, ZFS_BINARY, args, []string{})
+	if err != nil {
+		sendResult(nil, err)
+		return
+	}
+	if err = cmd.Start(); err != nil {
+		sendResult(nil, err)
+		return
+	}
+	defer cmd.Close()
+
+	s := bufio.NewScanner(cmd)
+	buf := make([]byte, 1024) // max line length
+	s.Buffer(buf, 0)
+
+	for s.Scan() {
+		fields := strings.SplitN(s.Text(), "\t", len(properties))
+		if len(fields) != len(properties) {
+			sendResult(nil, errors.New("unexpected output"))
+			return
+		}
+		if sendResult(fields, nil) {
+			return
+		}
+	}
+	if s.Err() != nil {
+		sendResult(nil, s.Err())
+	}
+	return
+}
+
 func ZFSSend(fs *DatasetPath, from, to *FilesystemVersion) (stream io.Reader, err error) {
 
 	args := make([]string, 0)
@@ -239,13 +303,39 @@ func ZFSRecv(fs *DatasetPath, stream io.Reader, additionalArgs ...string) (err e
 	return nil
 }
 
-func ZFSSet(fs *DatasetPath, prop, val string) (err error) {
-
-	if strings.ContainsRune(prop, '=') {
-		panic("prop contains rune '=' which is the delimiter between property name and value")
+type ZFSProperties struct {
+	m map[string]string
 }
 
-	cmd := exec.Command(ZFS_BINARY, "set", fmt.Sprintf("%s=%s", prop, val), fs.ToString())
+func NewZFSProperties() *ZFSProperties {
+	return &ZFSProperties{make(map[string]string, 4)}
+}
+
+func (p *ZFSProperties) Set(key, val string) {
+	p.m[key] = val
+}
+
+func (p *ZFSProperties) appendArgs(args *[]string) (err error) {
+	for prop, val := range p.m {
+		if strings.Contains(prop, "=") {
+			return errors.New("prop contains rune '=' which is the delimiter between property name and value")
+		}
+		*args = append(*args, fmt.Sprintf("%s=%s", prop, val))
+	}
+	return nil
+}
+
+func ZFSSet(fs *DatasetPath, props *ZFSProperties) (err error) {
+
+	args := make([]string, 0)
+	args = append(args, "set")
+	err = props.appendArgs(&args)
+	if err != nil {
+		return err
+	}
+	args = append(args, fs.ToString())
+
+	cmd := exec.Command(ZFS_BINARY, args...)
 
 	stderr := bytes.NewBuffer(make([]byte, 0, 1024))
 	cmd.Stderr = stderr
@@ -286,9 +376,17 @@ func ZFSDestroy(dataset string) (err error) {
 
 }
 
+func zfsBuildSnapName(fs *DatasetPath, name string) string { // TODO defensive
+	return fmt.Sprintf("%s@%s", fs.ToString(), name)
+}
+
+func zfsBuildBookmarkName(fs *DatasetPath, name string) string { // TODO defensive
+	return fmt.Sprintf("%s#%s", fs.ToString(), name)
+}
+
 func ZFSSnapshot(fs *DatasetPath, name string, recursive bool) (err error) {
 
-	snapname := fmt.Sprintf("%s@%s", fs.ToString(), name)
+	snapname := zfsBuildSnapName(fs, name)
 	cmd := exec.Command(ZFS_BINARY, "snapshot", snapname)
 
 	stderr := bytes.NewBuffer(make([]byte, 0, 1024))
@@ -308,3 +406,28 @@ func ZFSSnapshot(fs *DatasetPath, name string, recursive bool) (err error) {
 	return
 
 }
+
+func ZFSBookmark(fs *DatasetPath, snapshot, bookmark string) (err error) {
+
+	snapname := zfsBuildSnapName(fs, snapshot)
+	bookmarkname := zfsBuildBookmarkName(fs, bookmark)
+
+	cmd := exec.Command(ZFS_BINARY, "bookmark", snapname, bookmarkname)
+
+	stderr := bytes.NewBuffer(make([]byte, 0, 1024))
+	cmd.Stderr = stderr
+
+	if err = cmd.Start(); err != nil {
+		return err
+	}
+
+	if err = cmd.Wait(); err != nil {
+		err = ZFSError{
+			Stderr:  stderr.Bytes(),
+			WaitErr: err,
+		}
+	}
+
+	return
+
+}