build: fix warning for cached builds with Go 1.10

https://github.com/golang/tools/commit/bd4635fd25596cdd56c1fb399c53b351d1a81f2d#diff-0415b5286e4cf3e373f349d917e5e039

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 = "53a2e445f8ace7ec678f2d8cdd9c1428dfef4562"
+
+[[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 @@
-
+ignored = [ "github.com/inconshreveable/mousetrap" ]
-# 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"
-
 
 [[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:
+$(ARTIFACTDIR):
-	mkdir artifacts
+	mkdir -p "$@"
 
-release: artifacts vet test
+$(ARTIFACTDIR)/docs: $(ARTIFACTDIR)
-	GOOS=linux GOARCH=amd64   go build -o "$(ARTIFACTDIR)/zrepl-linux-amd64"
+	mkdir -p "$@"
-	GOOS=freebsd GOARCH=amd64 go build -o "$(ARTIFACTDIR)/zrepl-freebsd-amd64"
 
-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
+│   ├── public_git          # checkout of zrepl.github.io managed by above shell script
-├── jobrun                  # OBSOLETE
 ├── 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,17 @@
+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
+RUN mkdir -p /.cache && chmod -R 0777 /.cache
+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

@@ -9,52 +9,54 @@ import (
 )
 
 type IntervalAutosnap struct {
+	task             *Task
 	DatasetFilter    zfs.DatasetFilter
 	Prefix           string
 	SnapshotInterval time.Duration
-
-	log       Logger
-	snaptimes []snapTime
 }
 
-type snapTime struct {
+func (a *IntervalAutosnap) filterFilesystems() (fss []*zfs.DatasetPath, stop bool) {
-	ds   *zfs.DatasetPath
+	a.task.Enter("filter_filesystems")
-	time time.Time
+	defer a.task.Finish()
-}
+	fss, err := zfs.ZFSListMapping(a.DatasetFilter)
-
+	stop = err != nil
-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")
+		a.task.Log().WithError(err).Error("cannot list datasets")
-		return
 	}
-	if len(ds) == 0 {
+	if len(fss) == 0 {
-		a.log.Warn("no filesystem matching filesystem filter")
+		a.task.Log().Warn("no filesystem matching filesystem filter")
-		return
+	}
+	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
 	}
 
-	a.snaptimes = make([]snapTime, len(ds))
+	if len(fss) == 0 {
+		return time.Now(), nil
+	}
+
+	snaptimes := make([]snapTime, 0, len(fss))
 
 	now := time.Now()
 
-	a.log.Debug("examine filesystem state")
+	a.task.Log().Debug("examine filesystem state")
-	for i, d := range ds {
+	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 +80,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 {
+	if len(snaptimes) == 0 {
-		return a.snaptimes[i].time.Before(a.snaptimes[j].time)
+		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]
+	return snaptimes[0].time, nil
-	a.log.WithField("sync_point", syncPoint.time.Format(LOG_TIME_FMT)).
+
+}
+
+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.Sub(time.Now())):
+	}
+}
 
-	case <-time.After(syncPoint.time.Sub(now)):
+func (a *IntervalAutosnap) syncUpRun(ctx context.Context, didSnaps chan struct{}) (stop bool) {
-		a.log.Debug("snapshot all filesystems to enable further snaps in lockstep")
+	a.task.Enter("sync_up")
-		a.doSnapshots(didSnaps)
+	defer a.task.Finish()
+
+	fss, stop := a.filterFilesystems()
+	if stop {
+		return true
 	}
 
-	ticker := time.NewTicker(a.SnapshotInterval)
+	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,10 +160,13 @@ 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
+	a.task.Enter("do_snapshots")
-	ds, err := zfs.ZFSListMapping(a.DatasetFilter)
+	defer a.task.Finish()
-	if err != nil {
+
-		a.log.WithError(err).Error("cannot list datasets")
+	// don't cache the result from previous run in case the user added
+	// a new dataset in the meantime
+	ds, stop := a.filterFilesystems()
+	if stop {
 		return
 	}
 
@@ -129,20 +175,27 @@ func (a *IntervalAutosnap) doSnapshots(didSnaps chan struct{}) {
 		suffix := time.Now().In(time.UTC).Format("20060102_150405_000")
 		snapname := fmt.Sprintf("%s%s", a.Prefix, suffix)
 
-		a.log.WithField(logFSField, d.ToString()).
+		l := a.task.Log().WithField(logFSField, d.ToString()).
-			WithField("snapname", snapname).
+			WithField("snapname", snapname)
-			Info("create snapshot")
 
+		l.Info("create snapshot")
 		err := zfs.ZFSSnapshot(d, snapname, false)
 		if err != nil {
-			a.log.WithError(err).Error("cannot create snapshot")
+			a.task.Log().WithError(err).Error("cannot create snapshot")
 		}
+
+		l.Info("create corresponding bookmark")
+		err = zfs.ZFSBookmark(d, snapname, snapname)
+		if err != nil {
+			a.task.Log().WithError(err).Error("cannot create bookmark")
+		}
+
 	}
 
 	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,12 @@ 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"
+	"time"
 )
 
 type SSHStdinserverConnecter struct {
@@ -18,6 +20,8 @@ type SSHStdinserverConnecter struct {
 	TransportOpenCommand []string `mapstructure:"transport_open_command"`
 	SSHCommand           string   `mapstructure:"ssh_command"`
 	Options              []string
+	DialTimeout          string `mapstructure:"dial_timeout"`
+	dialTimeout          time.Duration
 }
 
 func parseSSHStdinserverConnecter(i map[string]interface{}) (c *SSHStdinserverConnecter, err error) {
@@ -28,17 +32,33 @@ func parseSSHStdinserverConnecter(i map[string]interface{}) (c *SSHStdinserverCo
 		return nil, err
 	}
 
+	if c.DialTimeout != "" {
+		c.dialTimeout, err = time.ParseDuration(c.DialTimeout)
+		if err != nil {
+			return nil, errors.Wrap(err, "cannot parse dial_timeout")
+		}
+	} else {
+		c.dialTimeout = 10 * time.Second
+	}
+
 	// TODO assert fields are filled
 	return
 
 }
 
 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
-		return
+	if err = copier.Copy(&endpoint, c); err != nil {
+		return nil, errors.WithStack(err)
 	}
-	if rwc, err = sshbytestream.Outgoing(rpcTransport); err != nil {
+	var dialCtx context.Context
+	dialCtx, dialCancel := context.WithTimeout(context.TODO(), c.dialTimeout) // context.TODO tied to error handling below
+	defer dialCancel()
+	if rwc, err = netssh.Dial(dialCtx, endpoint); err != nil {
+		if err == context.DeadlineExceeded {
+			err = errors.Errorf("dial_timeout of %s exceeded", c.dialTimeout)
+		}
 		err = errors.WithStack(err)
 		return
 	}

cmd/config_fsvfilter.go

@@ -6,8 +6,18 @@ import (
 	"strings"
 )
 
-type PrefixSnapshotFilter struct {
+type PrefixFilter struct {
-	Prefix string
+	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) {
+func (f *PrefixFilter) Filter(fsv zfs.FilesystemVersion) (accept bool, err error) {
-	if !(len(i) > 0) {
+	fstypeMatches := (!f.fstypeSet || fsv.Type == f.fstype)
-		err = errors.Errorf("snapshot prefix must be longer than 0 characters")
+	prefixMatches := strings.HasPrefix(fsv.Name, f.prefix)
-		return
+	return fstypeMatches && prefixMatches, nil
-	}
-	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
 }

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")
-	l.handlerFunc(w, r)
+	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)
+	rootLog := ctx.Value(contextKeyLog).(Logger)
-	defer log.Info("exiting")
+
+	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")
+			j.mainTask.Log().Debug("finished taking snapshots")
-			log.Info("starting replication procedure")
+			j.mainTask.Log().Info("starting replication procedure")
 		}
 
-		{
+		j.mainTask.Log().Debug("replicating from lhs to rhs")
-			log := pullCtx.Value(contextKeyLog).(Logger)
+		j.mainTask.Enter("replicate")
-			log.Debug("replicating from lhs to rhs")
+		puller := Puller{j.mainTask, local, j.Mapping, j.InitialReplPolicy}
-			err := doPull(PullContext{local, log, j.Mapping, j.InitialReplPolicy})
+		puller.Pull()
-			if err != nil {
+		j.mainTask.Finish()
-				log.WithError(err).Error("error replicating lhs to rhs")
+
-			}
+		// use a ctx as soon as Pull gains ctx support
-			// use a ctx as soon as doPull gains ctx support
+		select {
-			select {
+		case <-ctx.Done():
-			case <-ctx.Done():
+			break outer
-				break outer
+		default:
-			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")
+	j.task.Enter("prune")
-	err = doPull(PullContext{client, pullLog, j.Mapping, j.InitialReplPolicy})
+	pruner, err := j.Pruner(j.task, PrunePolicySideDefault, false)
 	if err != nil {
-		log.WithError(err).Error("error doing pull")
+		j.task.Log().WithError(err).Error("error creating pruner")
-	}
+	} else {
-
+		pruner.Run(ctx)
-	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.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}
+	j.autosnapTask = NewTask("autosnap", log)
-	p, err := j.Pruner(PrunePolicySideDefault, false)
+	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 j.serve(ctx, j.serveTask)
-	go a.Run(snapContext, didSnaps)
+	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) {
+func (j *SourceJob) serve(ctx context.Context, task *Task) {
-
-	log := ctx.Value(contextKeyLog).(Logger)
 
 	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)
+			j.handleConnection(rwcMsg.rwc, task)
-			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()
 
 		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 {
+type MetadataFlags int64
-	SetNoMetadata(noMetadata bool)
-}
 
-type OutletCommon struct {
+const (
-	MinLevel  logger.Level
+	MetadataTime MetadataFlags = 1 << iota
-	Formatter EntryFormatter
+	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{}
+	minLevel, err := logger.ParseLevel(in.Level)
-	common.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) {
+func parseTCPOutlet(i interface{}, formatter EntryFormatter) (out *TCPOutlet, err error) {
-
-	out = &TCPOutlet{}
-	out.Formatter = common.Formatter
 
 	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
+	out.Formatter = formatter
-	if f, ok := out.Formatter.(SetNoMetadataFormatter); ok {
+	out.Formatter.SetMetadataFlags(MetadataNone)
-		f.SetNoMetadata(true)
-	}
 
 	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 {
+	if p.MaxBookmarks == GridPrunePolicyMaxBookmarksKeepAll {
-		Grid string
+		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
-
-	// Parse grid policy
 	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)
+	f.sockpath = path.Join(c.Global.Serve.Stdinserver.SockDir, f.ClientIdentity)
-	if err != nil {
-		return
-	}
 
 	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 = PreparePrivateSockpath(f.sockpath); err != nil {
-	if err != nil {
+		return nil, err
-		return nil, errors.Wrapf(err, "cannot listen on unix socket %s", f.sockaddr)
 	}
 
-	l := &StdinserverListener{ul}
+	l, err := netssh.Listen(f.sockpath)
-
+	if err != nil {
-	return l, nil
+		return nil, err
+	}
+	return StdinserverListener{l}, nil
 }
 
 type StdinserverListener struct {
-	l *net.UnixListener
+	l *netssh.Listener
 }
 
-type fdRWC struct {
+func (l StdinserverListener) Accept() (ch io.ReadWriteCloser, err error) {
-	stdin, stdout *os.File
+	return l.l.Accept()
-	control       *net.UnixConn
 }
 
-func (f fdRWC) Read(p []byte) (n int, err error) {
+func (l StdinserverListener) Close() (err error) {
-	return f.stdin.Read(p)
+	return l.l.Close()
-}
-
-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
 }

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",
+	Use:   "pprof off | [on TCP_LISTEN_ADDRESS]",
-	Short: "pprof CPU of daemon to OUTFILE (- for stdout)",
+	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" {
+	var buf bytes.Buffer
-		log.Printf("only CPU profiles are supported")
+	if err := json.NewEncoder(&buf).Encode(&pprofCmdArgs.msg); err != nil {
-		log.Printf("%s", cmd.UsageString())
+		log.Printf("error marshaling request: %s", err)
 		die()
 	}
-
+	_, err = httpc.Post("http://unix"+ControlJobEndpointPProf, "application/json", &buf)
-	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())
 	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)
@@ -49,22 +55,27 @@ func doDaemon(cmd *cobra.Command, args []string) {
 type contextKey string
 
 const (
-	contextKeyLog contextKey = contextKey("log")
+	contextKeyLog    contextKey = contextKey("log")
+	contextKeyDaemon contextKey = contextKey("daemon")
 )
 
 type Daemon struct {
-	conf *Config
+	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) {
+func PreparePrivateSockpath(sockpath string) error {
-
+	sockdir := filepath.Dir(sockpath)
-	sockdir := filepath.Dir(sockaddr.Name)
 	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)
+	s, err := os.Stat(sockpath)
-	if err == nil {
+	if os.IsNotExist(err) {
-		if s.Mode()&os.ModeSocket != 0 {
+		return nil
-			// opportunistically try to remove it, but if this fails, it is not an error
+	}
-			os.Remove(sockaddr.Name)
+	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) {
+func (f *HumanFormatter) SetMetadataFlags(flags MetadataFlags) {
-	f.NoMetadata = noMetadata
+	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 {
-			fmt.Fprintf(&line, "[%s]", val)
+			if !f.ignored(field) {
-			prefixed[field] = true
+				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)
 
-	for field, value := range e.Fields {
+	if len(e.Fields)-len(prefixed) > 0 {
-
+		fmt.Fprint(&line, " ")
-		if prefixed[field] {
+		enc := logfmt.NewEncoder(&line)
-			continue
+		for field, value := range e.Fields {
+			if prefixed[field] || f.ignored(field) {
+				continue
+			}
+			if err := logfmtTryEncodeKeyval(enc, field, value); err != nil {
+				return nil, err
+			}
 		}
-
-		if strings.ContainsAny(field, " \t") {
-			return nil, errors.Errorf("field must not contain whitespace: '%s'", field)
-		}
-		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) SetMetadataFlags(flags MetadataFlags) {
-
+	f.metadataFlags = flags
-func (f *LogfmtFormatter) SetNoMetadata(noMetadata bool) {
-	f.NoMetadata = noMetadata
 }
 
 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 := logfmtTryEncodeKeyval(enc, k, v); err != nil {
+				return nil, err
+			}
 		}
 	}
 
-	if err := enc.EndRecord(); 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
+	formatter EntryFormatter
-	Net, Address string
-	Dialer       net.Dialer
-	TLS          *tls.Config
 	// 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
+	connect   func(ctx context.Context) (net.Conn, error)
-	// nil if there was an error sending / connecting to remote server
+	entryChan chan *bytes.Buffer
-	conn net.Conn
-	// Last time an error occurred when sending / connecting to remote server
-	retry time.Time
 }
 
-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 {
+	buf := new(bytes.Buffer)
-		if time.Now().Sub(h.retry) < h.RetryInterval {
+	buf.Write(ebytes)
-			// cool-down phase, drop the log entry
+	buf.WriteString("\n")
-			return nil
-		}
 
-		if h.TLS != nil {
+	select {
-			h.conn, err = tls.DialWithDialer(&h.Dialer, h.Net, h.Address, h.TLS)
+	case h.entryChan <- buf:
-		} else {
+		return nil
-			h.conn, err = h.Dialer.DialContext(ctx, h.Net, h.Address)
+	default:
-		}
+		return errors.New("connection broken or not fast enough")
-		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

@@ -8,6 +8,7 @@ import (
 )
 
 type Pruner struct {
+	task           *Task
 	Now            time.Time
 	DryRun         bool
 	DatasetFilter  zfs.DatasetFilter
@@ -22,80 +23,114 @@ type PruneResult struct {
 	Remove     []zfs.FilesystemVersion
 }
 
-func (p *Pruner) Run(ctx context.Context) (r []PruneResult, err error) {
+func (p *Pruner) filterFilesystems() (filesystems []*zfs.DatasetPath, stop bool) {
-
+	p.task.Enter("filter_fs")
-	log := ctx.Value(contextKeyLog).(Logger)
+	defer p.task.Finish()
-
-	if p.DryRun {
-		log.Info("doing dry run")
-	}
-
 	filesystems, err := zfs.ZFSListMapping(p.DatasetFilter)
 	if err != nil {
-		log.WithError(err).Error("error applying filesystem filter")
+		p.task.Log().WithError(err).Error("error applying filesystem filter")
-		return nil, err
+		return nil, true
 	}
 	if len(filesystems) <= 0 {
-		log.Info("no filesystems matching filter")
+		p.task.Log().Info("no filesystems matching filter")
-		return nil, err
+		return nil, true
+	}
+	return filesystems, false
+}
+
+func (p *Pruner) filterVersions(fs *zfs.DatasetPath) (fsversions []zfs.FilesystemVersion, stop bool) {
+	p.task.Enter("filter_versions")
+	defer p.task.Finish()
+	log := p.task.Log().WithField(logFSField, fs.ToString())
+
+	filter := NewPrefixFilter(p.SnapshotPrefix)
+	fsversions, err := zfs.ZFSListFilesystemVersions(fs, filter)
+	if err != nil {
+		log.WithError(err).Error("error listing filesytem versions")
+		return nil, true
+	}
+	if len(fsversions) == 0 {
+		log.WithField("prefix", p.SnapshotPrefix).Info("no filesystem versions matching prefix")
+		return nil, true
+	}
+	return fsversions, false
+}
+
+func (p *Pruner) pruneFilesystem(fs *zfs.DatasetPath) (r PruneResult, valid bool) {
+	p.task.Enter("prune_fs")
+	defer p.task.Finish()
+	log := p.task.Log().WithField(logFSField, fs.ToString())
+
+	fsversions, stop := p.filterVersions(fs)
+	if stop {
+		return
+	}
+
+	p.task.Enter("prune_policy")
+	keep, remove, err := p.PrunePolicy.Prune(fs, fsversions)
+	p.task.Finish()
+	if err != nil {
+		log.WithError(err).Error("error evaluating prune policy")
+		return
+	}
+
+	log.WithField("fsversions", fsversions).
+		WithField("keep", keep).
+		WithField("remove", remove).
+		Debug("prune policy debug dump")
+
+	r = PruneResult{fs, fsversions, keep, remove}
+
+	makeFields := func(v zfs.FilesystemVersion) (fields map[string]interface{}) {
+		fields = make(map[string]interface{})
+		fields["version"] = v.ToAbsPath(fs)
+		timeSince := v.Creation.Sub(p.Now)
+		fields["age_ns"] = timeSince
+		const day time.Duration = 24 * time.Hour
+		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 {
+			p.task.Enter("destroy")
+			err := zfs.ZFSDestroyFilesystemVersion(fs, v)
+			p.task.Finish()
+			if err != nil {
+				log.WithFields(fields).WithError(err).Error("error destroying version")
+			}
+		}
+	}
+	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
 	}
 
 	r = make([]PruneResult, 0, len(filesystems))
 
 	for _, fs := range filesystems {
-
+		res, ok := p.pruneFilesystem(fs)
-		log := log.WithField(logFSField, fs.ToString())
+		if ok {
-
+			r = append(r, res)
-		fsversions, err := zfs.ZFSListFilesystemVersions(fs, &PrefixSnapshotFilter{p.SnapshotPrefix})
-		if err != nil {
-			log.WithError(err).Error("error listing filesytem versions")
-			continue
 		}
-		if len(fsversions) == 0 {
-			log.WithField("prefix", p.SnapshotPrefix).Info("no filesystem versions matching prefix")
-			continue
-		}
-
-		keep, remove, err := p.PrunePolicy.Prune(fs, fsversions)
-		if err != nil {
-			log.WithError(err).Error("error evaluating prune policy")
-			continue
-		}
-
-		log.WithField("fsversions", fsversions).
-			WithField("keep", keep).
-			WithField("remove", remove).
-			Debug("prune policy debug dump")
-
-		r = append(r, PruneResult{fs, fsversions, keep, remove})
-
-		makeFields := func(v zfs.FilesystemVersion) (fields map[string]interface{}) {
-			fields = make(map[string]interface{})
-			fields["version"] = v.ToAbsPath(fs)
-			timeSince := v.Creation.Sub(p.Now)
-			fields["age_ns"] = timeSince
-			const day time.Duration = 24 * time.Hour
-			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 {
-				err := zfs.ZFSDestroyFilesystemVersion(fs, v)
-				if err != nil {
-					// handle
-					log.WithFields(fields).WithError(err).Error("error destroying version")
-				}
-			}
-		}
-
 	}
 
 	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,85 +25,273 @@ const (
 	InitialReplPolicyAll        InitialReplPolicy = "all"
 )
 
-func closeRPCWithTimeout(log Logger, remote rpc.RPCClient, timeout time.Duration, goodbye string) {
+type Puller struct {
-	log.Info("closing rpc connection")
+	task              *Task
-
-	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 {
 	Remote            rpc.RPCClient
-	Log               Logger
 	Mapping           DatasetMapping
 	InitialReplPolicy InitialReplPolicy
 }
 
-func doPull(pull PullContext) (err error) {
+type remoteLocalMapping struct {
+	Remote *zfs.DatasetPath
+	Local  *zfs.DatasetPath
+}
 
-	remote := pull.Remote
+func (p *Puller) getRemoteFilesystems() (rfs []*zfs.DatasetPath, ok bool) {
-	log := pull.Log
+	p.task.Enter("fetch_remote_fs_list")
+	defer p.task.Finish()
 
-	log.Info("request remote filesystem list")
 	fsr := FilesystemRequest{}
-	var remoteFilesystems []*zfs.DatasetPath
+	if err := p.Remote.Call("FilesystemRequest", &fsr, &rfs); err != nil {
-	if err = remote.Call("FilesystemRequest", &fsr, &remoteFilesystems); err != nil {
+		p.task.Log().WithError(err).Error("cannot fetch remote filesystem list")
-		return
+		return nil, false
 	}
+	return rfs, true
+}
 
-	log.Debug("map remote filesystems to local paths and determine order for per-filesystem sync")
+func (p *Puller) buildReplMapping(remoteFilesystems []*zfs.DatasetPath) (replMapping map[string]remoteLocalMapping, ok bool) {
-	type RemoteLocalMapping struct {
+	p.task.Enter("build_repl_mapping")
-		Remote *zfs.DatasetPath
+	defer p.task.Finish()
-		Local  *zfs.DatasetPath
+
-	}
+	replMapping = make(map[string]remoteLocalMapping, len(remoteFilesystems))
-	replMapping := make(map[string]RemoteLocalMapping, len(remoteFilesystems))
-	localTraversal := zfs.NewDatasetPathForest()
 	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")
+			p.task.Log().WithError(err).WithField(logMapFromField, remoteFilesystems[fs]).Error("cannot map")
-			return err
+			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
+	}
+	return replMapping, true
+}
+
+// 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) {
+
+	p.task.Enter("repl_fs")
+	defer p.task.Finish()
+	var err error
+	remote := p.Remote
+
+	log := p.task.Log().
+		WithField(logMapFromField, m.Remote.ToString()).
+		WithField(logMapToField, m.Local.ToString())
+
+	log.Debug("examining local filesystem state")
+	localState, localExists := localFilesystemState[m.Local.ToString()]
+	var versions []zfs.FilesystemVersion
+	switch {
+	case !localExists:
+		log.Info("local filesystem does not exist")
+	case localState.Placeholder:
+		log.Info("local filesystem is marked as placeholder")
+	default:
+		log.Debug("local filesystem exists")
+		log.Debug("requesting local filesystem versions")
+		if versions, err = zfs.ZFSListFilesystemVersions(m.Local, nil); err != nil {
+			log.WithError(err).Error("cannot get local filesystem versions")
+			return false
+		}
+	}
+
+	log.Info("requesting remote filesystem versions")
+	r := FilesystemVersionsRequest{
+		Filesystem: m.Remote,
+	}
+	var theirVersions []zfs.FilesystemVersion
+	if err = remote.Call("FilesystemVersionsRequest", &r, &theirVersions); err != nil {
+		log.WithError(err).Error("cannot get remote filesystem versions")
+		log.Warn("stopping replication for all filesystems mapped as children of receiving filesystem")
+		return false
+	}
+
+	log.Debug("computing diff between remote and local filesystem versions")
+	diff := zfs.MakeFilesystemDiff(versions, theirVersions)
+	log.WithField("diff", diff).Debug("diff between local and remote filesystem")
+
+	if localState.Placeholder && diff.Conflict != zfs.ConflictAllRight {
+		panic("internal inconsistency: local placeholder implies ConflictAllRight")
+	}
+
+	switch diff.Conflict {
+	case zfs.ConflictAllRight:
+
+		log.WithField("replication_policy", p.InitialReplPolicy).Info("performing initial sync, following policy")
+
+		if p.InitialReplPolicy != InitialReplPolicyMostRecent {
+			panic(fmt.Sprintf("policy '%s' not implemented", p.InitialReplPolicy))
+		}
+
+		snapsOnly := make([]zfs.FilesystemVersion, 0, len(diff.MRCAPathRight))
+		for s := range diff.MRCAPathRight {
+			if diff.MRCAPathRight[s].Type == zfs.Snapshot {
+				snapsOnly = append(snapsOnly, diff.MRCAPathRight[s])
+			}
+		}
+
+		if len(snapsOnly) < 1 {
+			log.Warn("cannot perform initial sync: no remote snapshots")
+			return false
+		}
+
+		r := InitialTransferRequest{
+			Filesystem:        m.Remote,
+			FilesystemVersion: snapsOnly[len(snapsOnly)-1],
+		}
+
+		log.WithField("version", r.FilesystemVersion).Debug("requesting snapshot stream")
+
+		var stream io.Reader
+
+		if err = remote.Call("InitialTransferRequest", &r, &stream); err != nil {
+			log.WithError(err).Error("cannot request initial transfer")
+			return false
+		}
+		log.Debug("received initial transfer request response")
+
+		log.Debug("invoke zfs receive")
+		recvArgs := []string{"-u"}
+		if localState.Placeholder {
+			log.Info("receive with forced rollback to replace placeholder filesystem")
+			recvArgs = append(recvArgs, "-F")
+		}
+		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.Info("finished receiving stream") // TODO rx delta
+
+		// TODO unify with recv path of ConflictIncremental
+		log.Debug("configuring properties of received filesystem")
+		props := zfs.NewZFSProperties()
+		props.Set("readonly", "on")
+		if err = zfs.ZFSSet(m.Local, props); err != nil {
+			log.WithError(err).Error("cannot set readonly property")
+		}
+
+		log.Info("finished initial transfer")
+		return true
+
+	case zfs.ConflictIncremental:
+
+		if len(diff.IncrementalPath) < 2 {
+			log.Info("remote and local are in sync")
+			return true
+		}
+
+		log.Info("following incremental path from diff")
+		for i := 0; i < len(diff.IncrementalPath)-1; i++ {
+
+			from, to := diff.IncrementalPath[i], diff.IncrementalPath[i+1]
+
+			log, _ := log.WithField(logIncFromField, from.Name).WithField(logIncToField, to.Name), 0
+
+			log.Debug("requesting incremental snapshot stream")
+			r := IncrementalTransferRequest{
+				Filesystem: m.Remote,
+				From:       from,
+				To:         to,
+			}
+			var stream io.Reader
+			if err = remote.Call("IncrementalTransferRequest", &r, &stream); err != nil {
+				log.WithError(err).Error("cannot request incremental snapshot stream")
+				return false
+			}
+
+			log.Debug("invoking zfs receive")
+			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
+			}
+			log.Info("finished incremental transfer") // TODO increment rx
+
+		}
+		log.Info("finished following incremental path") // TODO path rx
+		return true
+
+	case zfs.ConflictNoCommonAncestor:
+		fallthrough
+	case zfs.ConflictDiverged:
+
+		var jsonDiff bytes.Buffer
+		if err := json.NewEncoder(&jsonDiff).Encode(diff); err != nil {
+			log.WithError(err).Error("cannot JSON-encode diff")
+			return false
+		}
+
+		var problem, resolution string
+
+		switch diff.Conflict {
+		case zfs.ConflictNoCommonAncestor:
+			problem = "remote and local filesystem have snapshots, but no common one"
+			resolution = "perform manual establish a common snapshot history"
+		case zfs.ConflictDiverged:
+			problem = "remote and local filesystem share a history but have diverged"
+			resolution = "perform manual replication or delete snapshots on the receiving" +
+				"side  to establish an incremental replication parse"
+		}
+
+		log.WithField("diff", jsonDiff.String()).
+			WithField("problem", problem).
+			WithField("resolution", resolution).
+			Error("manual conflict resolution required")
+
+		return false
+
+	}
+
+	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)
 	}
 
-	log.Debug("build cache for already present local filesystem state")
+	p.task.Log().Info("start per-filesystem sync")
-	localFilesystemState, err := zfs.ZFSListFilesystemState()
-	if err != nil {
-		log.WithError(err).Error("cannot request local filesystem state")
-		return err
-	}
-
-	log.Info("start per-filesystem sync")
 	localTraversal.WalkTopDown(func(v zfs.DatasetPathVisit) bool {
 
-		log := log.WithField(logFSField, v.Path.ToString())
+		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 {
@@ -116,7 +300,9 @@ func doPull(pull PullContext) (err error) {
 				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
@@ -129,189 +315,7 @@ func doPull(pull PullContext) (err error) {
 			panic("internal inconsistency: replMapping should contain mapping for any path that was not filled in by WalkTopDown()")
 		}
 
-		log = log.WithField(logMapToField, m.Remote.ToString()).
+		return p.replFilesystem(m, localFilesystemState)
-			WithField(logMapFromField, m.Local.ToString())
-
-		log.Debug("examing local filesystem state")
-		localState, localExists := localFilesystemState[m.Local.ToString()]
-		var versions []zfs.FilesystemVersion
-		switch {
-		case !localExists:
-			log.Info("local filesystem does not exist")
-		case localState.Placeholder:
-			log.Info("local filesystem is marked as placeholder")
-		default:
-			log.Debug("local filesystem exists")
-			log.Debug("requesting local filesystem versions")
-			if versions, err = zfs.ZFSListFilesystemVersions(m.Local, nil); err != nil {
-				log.WithError(err).Error("cannot get local filesystem versions")
-				return false
-			}
-		}
-
-		log.Info("requesting remote filesystem versions")
-		r := FilesystemVersionsRequest{
-			Filesystem: m.Remote,
-		}
-		var theirVersions []zfs.FilesystemVersion
-		if err = remote.Call("FilesystemVersionsRequest", &r, &theirVersions); err != nil {
-			log.WithError(err).Error("cannot get remote filesystem versions")
-			log.Warn("stopping replication for all filesystems mapped as children of receiving filesystem")
-			return false
-		}
-
-		log.Debug("computing diff between remote and local filesystem versions")
-		diff := zfs.MakeFilesystemDiff(versions, theirVersions)
-		log.WithField("diff", diff).Debug("diff between local and remote filesystem")
-
-		if localState.Placeholder && diff.Conflict != zfs.ConflictAllRight {
-			panic("internal inconsistency: local placeholder implies ConflictAllRight")
-		}
-
-		switch diff.Conflict {
-		case zfs.ConflictAllRight:
-
-			log.WithField("replication_policy", pull.InitialReplPolicy).Info("performing initial sync, following policy")
-
-			if pull.InitialReplPolicy != InitialReplPolicyMostRecent {
-				panic(fmt.Sprintf("policy '%s' not implemented", pull.InitialReplPolicy))
-			}
-
-			snapsOnly := make([]zfs.FilesystemVersion, 0, len(diff.MRCAPathRight))
-			for s := range diff.MRCAPathRight {
-				if diff.MRCAPathRight[s].Type == zfs.Snapshot {
-					snapsOnly = append(snapsOnly, diff.MRCAPathRight[s])
-				}
-			}
-
-			if len(snapsOnly) < 1 {
-				log.Warn("cannot perform initial sync: no remote snapshots")
-				return false
-			}
-
-			r := InitialTransferRequest{
-				Filesystem:        m.Remote,
-				FilesystemVersion: snapsOnly[len(snapsOnly)-1],
-			}
-
-			log.WithField("version", r.FilesystemVersion).Debug("requesting snapshot stream")
-
-			var stream io.Reader
-
-			if err = remote.Call("InitialTransferRequest", &r, &stream); err != nil {
-				log.WithError(err).Error("cannot request initial transfer")
-				return false
-			}
-			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")
-				return false
-			}
-			log.WithField("total_rx", watcher.Progress().TotalRX).
-				Info("finished receiving stream")
-
-			log.Debug("configuring properties of received filesystem")
-			if err = zfs.ZFSSet(m.Local, "readonly", "on"); err != nil {
-				log.WithError(err).Error("cannot set readonly property")
-			}
-
-			log.Info("finished initial transfer")
-			return true
-
-		case zfs.ConflictIncremental:
-
-			if len(diff.IncrementalPath) < 2 {
-				log.Info("remote and local are in sync")
-				return true
-			}
-
-			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]
-
-				log, _ := log.WithField(logIncFromField, from.Name).WithField(logIncToField, to.Name), 0
-
-				log.Debug("requesting incremental snapshot stream")
-				r := IncrementalTransferRequest{
-					Filesystem: m.Remote,
-					From:       from,
-					To:         to,
-				}
-				var stream io.Reader
-				if err = remote.Call("IncrementalTransferRequest", &r, &stream); err != nil {
-					log.WithError(err).Error("cannot request incremental snapshot stream")
-					return false
-				}
-
-				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 {
-					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.WithField("total_rx", pathRx).Info("finished following incremental path")
-			return true
-
-		case zfs.ConflictNoCommonAncestor:
-			fallthrough
-		case zfs.ConflictDiverged:
-
-			var jsonDiff bytes.Buffer
-			if err := json.NewEncoder(&jsonDiff).Encode(diff); err != nil {
-				log.WithError(err).Error("cannot JSON-encode diff")
-				return false
-			}
-
-			var problem, resolution string
-
-			switch diff.Conflict {
-			case zfs.ConflictNoCommonAncestor:
-				problem = "remote and local filesystem have snapshots, but no common one"
-				resolution = "perform manual establish a common snapshot history"
-			case zfs.ConflictDiverged:
-				problem = "remote and local filesystem share a history but have diverged"
-				resolution = "perform manual replication or delete snapshots on the receiving" +
-					"side  to establish an incremental replication parse"
-			}
-
-			log.WithField("diff", jsonDiff.String()).
-				WithField("problem", problem).
-				WithField("resolution", resolution).
-				Error("manual conflict resolution required")
-
-			return false
-
-		}
-
-		panic("should not be reached")
-
 	})
 
 	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)
+  # keep 1 hour of snapshots (6 at 10m interval)
-  # (we cannot keep more than one day because this host will run out of disk space)
+  # 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 := log.New(os.Stderr, "", log.LUTC|log.Ldate|log.Ltime)
-		log.Printf("stdinserver exiting after fatal error")
-		os.Exit(1)
-	}
 
 	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")
+		log.Print("must specify client_identity as positional argument")
-		die()
+		return
 	}
+
 	identity := args[0]
+	unixaddr := path.Join(conf.Global.Serve.Stdinserver.SockDir, identity)
 
-	unixaddr, err := stdinserverListenerSocket(conf.Global.Serve.Stdinserver.SockDir, identity)
+	log.Printf("proxying client identity '%s' to zrepl daemon '%s'", identity, unixaddr)
-	if err != nil {
+
-		log.Printf("%s", err)
+	ctx := netssh.ContextWithLog(context.TODO(), log)
-		os.Exit(1)
+
+	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)
-	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
-	}
-
-	return
 
 }

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,8 @@
 .. |break_config| replace:: **[BREAK]**
+.. |break| replace:: **[BREAK]**
 .. |bugfix| replace:: [BUG]
+.. |docs| replace:: [DOCS]
+.. |feature| replace:: [FEATURE]
 
 Changelog
 =========
@@ -7,11 +10,41 @@ 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`: ``ssh+stdinserver`` transport: changed protocol requires daemon restart on both sides
+
+  * The delicate procedure of talking to the serving-side zrepl daemon via the stdinserver proxy command now has better error handling.
+  * This includes handshakes between client+proxy and client + remote daemo, which is not implemented in previous versions of zrepl.
+  * The connecting side will therefore time out, with the message ``dial_timeout of 10s exceeded``.
+  * 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
+* |docs| :issue:`64`: tutorial: document ``known_host`` file entry
+
+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.
+    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.
-    After the first interval, source and destination likely have different retention settings.
+    Thus, do not use ``all`` or an inappropriately high value without good reason.
-    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.
 

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:
@@ -85,8 +85,9 @@ Connect Mode
         user: root
         port: 22
         identity_file: /etc/zrepl/ssh/identity
-        options: # optional
+        options: # optional, default [], `-o` arguments passed to ssh
         - "Compression=on"
+        dial_timeout: # optional, default 10s, max time.Duration until initial handshake is completed
 
 The connecting zrepl daemon
 
@@ -101,10 +102,13 @@ The connecting zrepl daemon
       #. The remote user, host and port correspond to those configured.
       #. Further options can be specified using the ``options`` field, which appends each entry in the list to the command line using ``-o $entry``.
 
-1. Wraps the pipe ends in an ``io.ReadWriteCloser`` and uses it for RPC.
+#. Wraps the pipe ends in an ``io.ReadWriteCloser`` and uses it for RPC.
+
 
 As discussed in the section above, the connecting zrepl daemon expects that ``zrepl stdinserver $client_identity`` is  executed automatically via an ``authorized_keys`` file entry.
 
+The ``known_hosts`` file used by the ssh command must contain an entry for the serving host, e.g., ``app-srv.example.com`` in the example above.
+
 .. NOTE::
 
     The environment variables of the underlying SSH process are cleared. ``$SSH_AUTH_SOCK`` will not be available.

docs/index.rst

@@ -16,7 +16,7 @@ zrepl - ZFS replication
 Getting started
 ~~~~~~~~~~~~~~~
 
-The :ref:`5 minute tutorial setup <tutorial>` gives you a first impression.
+The :ref:`10 minutes tutorial setup <tutorial>` gives you a first impression.
 
 Main Features
 ~~~~~~~~~~~~~
@@ -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.
+Producing a release requires **Go 1.9** or newer and **Python 3** + **pip3** + ``docs/requirements.txt`` for the Sphinx documentation.
-A tutorial is available over at `golang.org <https://golang.org/doc/install>`_.
+A tutorial to install Go 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).
+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``,
+Alternatively, you can use the Docker build process:
-installs the build dependencies, installs dependencies using ``dep ensure`` and does a ``make release``.
+it is used to produce the official zrepl `binary releases`_
-Build artifacts are placed into ``$GOPATH/github.com/zrepl/zrepl/artifacts/``.
+and serves as a reference for build dependencies and procedure:
-
-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.
 
 ::
 
     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
+Alternatively, you can install build dependencies on your local system and then build in your ``$GOPATH``:
-    :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.
 
 ::
 
-    mkdir -p /var/run/zrepl/stdinserver
+    mkdir -p "${GOPATH}/src/github.com/zrepl/zrepl"
-    chmod -R 0700 /var/run/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.
+    It is your job to install the apropriate binary in the zrepl users's ``$PATH``, e.g. ``/usr/local/bin/zrepl``.
-Logging is configurable via the config file. Please refer to the :ref:`logging documention <logging>`.
+    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.
+.. _mainconfigfile:
-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``.
+What next?
-Note that you won't see any output unless you configure :ref:`stdout logging outlet <logging-outlet-stdout>`.
+----------
 
-.. 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
+sphinx-versioning build \
-make html
+   --show-banner \
-rsync -a _build/html/ public_git/
+   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

@@ -60,26 +60,26 @@ Follow the :ref:`OS-specific installation instructions <installation>` and come
 Configure ``backup-srv``
 ------------------------
 
-We define a **pull job** named ``pull_app-srv`` in the |mainconfig|: ::
+We define a **pull job** named ``pull_app-srv`` in the |mainconfig| on host ``backup-srv``: ::
 
     jobs:
     - name: pull_app-srv
-    type: pull
+      type: pull
-    connect:
+      connect:
-        type: ssh+stdinserver
+          type: ssh+stdinserver
-        host: app-srv.example.com
+          host: app-srv.example.com
-        user: root
+          user: root
-        port: 22
+          port: 22
-        identity_file: /etc/zrepl/ssh/identity
+          identity_file: /etc/zrepl/ssh/identity
-    interval: 10m
+      interval: 10m
-    mapping: {
+      mapping: {
-        "<":"storage/zrepl/pull/app-srv"
+          "<":"storage/zrepl/pull/app-srv"
-    }
+      }
-    initial_repl_policy: most_recent
+      initial_repl_policy: most_recent
-    snapshot_prefix: zrepl_pull_backup_
+      snapshot_prefix: zrepl_pull_backup_
-    prune:
+      prune:
-        policy: grid
+          policy: grid
-        grid: 1x1h(keep=all) | 24x1h | 35x1d | 6x30d
+          grid: 1x1h(keep=all) | 24x1h | 35x1d | 6x30d
 
 The ``connect`` section instructs the zrepl daemon to use the ``stdinserver`` transport:
 ``backup-srv`` will connect to the specified SSH server and expect ``zrepl stdinserver CLIENT_IDENTITY`` instead of the shell on the other side.
@@ -94,6 +94,13 @@ It uses the private key specified at ``connect.identity_file`` which we still ne
 Note that most use cases do not benefit from separate keypairs per remote endpoint.
 Thus, it is sufficient to create one keypair and use it for all ``connect`` directives on one host.
 
+zrepl uses ssh's default ``known_hosts`` file, which must contain a host identification entry for ``app-srv.example.com``.
+If that entry does not already exist, we need to generate it.
+Run the following command, compare the host fingerprints, and confirm with yes if they match.
+You will not be able to get a shell with the identity file we just generated, which is fine. ::
+
+    ssh -i /etc/zrepl/ssh/identity root@app-srv.example.com
+
 Learn more about :ref:`transport-ssh+stdinserver` transport and the :ref:`pull job <job-pull>` format.
 
 .. _tutorial-configure-app-srv:
@@ -101,24 +108,25 @@ Learn more about :ref:`transport-ssh+stdinserver` transport and the :ref:`pull j
 Configure ``app-srv``
 ---------------------
 
-We define a corresponding **source job** named ``pull_backup`` in the |mainconfig|: ::
+We define a corresponding **source job** named ``pull_backup`` in the |mainconfig| on host ``app-srv``:  ::
 
     jobs:
     - name: pull_backup
-    type: source
+      type: source
-    serve:
+      serve:
-        type: stdinserver
+          type: stdinserver
-        client_identity: backup-srv.example.com
+          client_identity: backup-srv.example.com
-    filesystems: {
+      filesystems: {
-        "zroot/var/db": "ok",
+          "zroot/var/db": "ok",
-        "zroot/usr/home<": "ok",
+          "zroot/usr/home<": "ok",
-        "zroot/usr/home/paranoid": "!",
+          "zroot/usr/home/paranoid": "!",
-    }
+      }
-    snapshot_prefix: zrepl_pull_backup_
+      snapshot_prefix: zrepl_pull_backup_
-    interval: 10m
+      interval: 10m
-    prune:
+      prune:
-        policy: grid
+          policy: grid
-        grid: 1x1d(keep=all)
+          grid: 1x1d(keep=all)
+          keep_bookmarks: 144
 
 
 The ``serve`` section corresponds to the ``connect`` section in the configuration of ``backup-srv``.
@@ -153,12 +161,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
+type Outlets struct {
-
+	mtx  sync.RWMutex
-func NewOutlets() Outlets {
+	outs map[Level][]Outlet
-	return make(Outlets, len(AllLevels))
 }
 
-func (os Outlets) Add(outlet Outlet, minLevel Level) {
+func NewOutlets() *Outlets {
-	for _, l := range AllLevels[minLevel:] {
+	return &Outlets{
-		os[l] = append(os[l], outlet)
+		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.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))
+	louts := l.outlets.Get(level)
-	ech := make(chan error)
+	ech := make(chan outletResult, len(louts))
-
-	louts := l.outlets[level]
 	for i := range louts {
-		go func(ctx context.Context, outlet Outlet, entry Entry) {
+		go func(outlet Outlet, entry Entry) {
-			ech <- outlet.WriteEntry(ctx, entry)
+			ech <- outletResult{outlet, outlet.WriteEntry(entry)}
-		}(ctx, louts[i], entry)
+		}(louts[i], entry)
 	}
-
 	for fin := 0; fin < len(louts); fin++ {
-		select {
+		res := <-ech
-		case err := <-ech:
+		if res.Error != nil {
-			if err != nil {
+			l.logInternalError(res.Outlet, res.Error.Error())
-				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)
-			}
 		}
 	}
-
+	close(ech)
-	cancel() // make go vet happy
 
 }
 
-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()
-
+	newOutlets := l.outlets.DeepCopy()
-	if _, ok := l.fields[field]; ok {
+	newOutlets.Add(outlet, level)
-		fmt.Fprintf(os.Stderr, "%s caller overwrites field '%s'. Stack:\n%s\n", InternalErrorPrefix, field, string(debug.Stack()))
+	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 "strconv"
+
+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 "DataType(" + strconv.FormatInt(int64(i+1), 10) + ")"
+	}
+	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 (

rpc/frametype_string.go

@@ -2,7 +2,7 @@
 
 package rpc
 
-import "fmt"
+import "strconv"
 
 const (
 	_FrameType_name_0 = "FrameTypeHeaderFrameTypeDataFrameTypeTrailer"
@@ -11,7 +11,6 @@ const (
 
 var (
 	_FrameType_index_0 = [...]uint8{0, 15, 28, 44}
-	_FrameType_index_1 = [...]uint8{0, 12}
 )
 
 func (i FrameType) String() string {
@@ -22,6 +21,6 @@ func (i FrameType) String() string {
 	case i == 255:
 		return _FrameType_name_1
 	default:
-		return fmt.Sprintf("FrameType(%d)", i)
+		return "FrameType(" + strconv.FormatInt(int64(i), 10) + ")"
 	}
 }

rpc/status_string.go

@@ -2,7 +2,7 @@
 
 package rpc
 
-import "fmt"
+import "strconv"
 
 const _Status_name = "StatusOKStatusRequestErrorStatusServerErrorStatusError"
 
@@ -11,7 +11,7 @@ var _Status_index = [...]uint8{0, 8, 26, 43, 54}
 func (i Status) String() string {
 	i -= 1
 	if i >= Status(len(_Status_index)-1) {
-		return fmt.Sprintf("Status(%d)", i+1)
+		return "Status(" + strconv.FormatInt(int64(i+1), 10) + ")"
 	}
 	return _Status_name[_Status_index[i]:_Status_index[i+1]]
 }

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
-}

zfs/conflict_string.go

@@ -2,7 +2,7 @@
 
 package zfs
 
-import "fmt"
+import "strconv"
 
 const _Conflict_name = "ConflictIncrementalConflictAllRightConflictNoCommonAncestorConflictDiverged"
 
@@ -10,7 +10,7 @@ var _Conflict_index = [...]uint8{0, 19, 35, 59, 75}
 
 func (i Conflict) String() string {
 	if i < 0 || i >= Conflict(len(_Conflict_index)-1) {
-		return fmt.Sprintf("Conflict(%d)", i)
+		return "Conflict(" + strconv.FormatInt(int64(i), 10) + ")"
 	}
 	return _Conflict_name[_Conflict_index[i]:_Conflict_index[i+1]]
 }

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
+	ctx, cancel := context.WithCancel(context.Background())
-	lines, err = ZFSList([]string{"name"}, "-r", "-t", "filesystem,volume")
+	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
+	listResults := make(chan ZFSListResult)
-	fieldLines, err = ZFSList(
+
+	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 {
-	res = make([]FilesystemVersion, 0, len(fieldLines))
+		if listResult.err != nil {
-	for _, line := range fieldLines {
+			return nil, listResult.err
+		}
+
+		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) {
+type ZFSProperties struct {
+	m map[string]string
+}
 
-	if strings.ContainsRune(prop, '=') {
+func NewZFSProperties() *ZFSProperties {
-		panic("prop contains rune '=' which is the delimiter between property name and value")
+	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
+}
 
-	cmd := exec.Command(ZFS_BINARY, "set", fmt.Sprintf("%s=%s", prop, val), fs.ToString())
+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
+
+}