From 100ee17086cd3842a63f93d3ce8e88b2137eb0a8 Mon Sep 17 00:00:00 2001
From: Aaron Hurt <ahurt@anbcs.com>
Date: Sun, 1 Sep 2024 15:39:45 -0500
Subject: [PATCH] improve logging and add tests (#47)

Previous logging was always sent to stdout in functions, this prevented
some functions like snapList from logging the commands sent as these
functions printed return values used by other functions. To fix this,
all user facing logging has been switched to stderr which is not picked
up by calling functions. This commit also adds tests for the --status/-s
and --help/-h options which includes testing of the sortLogs function.
---
 test/find.sh     |   7 +-
 test/test.sh     | 187 +++++++++++++++++++++++++++++++----------------
 zfs-replicate.sh |  41 ++++++-----
 3 files changed, 149 insertions(+), 86 deletions(-)

diff --git a/test/find.sh b/test/find.sh
index d10f69d..b9b1530 100755
--- a/test/find.sh
+++ b/test/find.sh
@@ -7,8 +7,11 @@ set -eu
 (set -o pipefail 2> /dev/null) && set -o pipefail
 
 _fakeFIND() {
-  printf "find %s\n" "$*"
+  path="$1"
+  printf "%s/autorep-test1.log\n" "$path"
+  printf "%s/autorep-test2.log\n" "$path"
+  printf "%s/autorep-test3.log\n" "$path"
   return 0
 }
 
-_fakeZFS "$@"
+_fakeFIND "$@"
diff --git a/test/test.sh b/test/test.sh
index e6510ae..5ce833e 100755
--- a/test/test.sh
+++ b/test/test.sh
@@ -46,8 +46,8 @@ _testZFSReplicate() {
     # shellcheck source=/dev/null
     . ../zfs-replicate.sh
     printf "_testZFSReplicate/loadConfigWithoutError\n"
-    line=$(loadConfig)
-    _fail "$line" "null" ## we expect no output here
+    lines=$(loadConfig 2>&1)
+    _fail "$lines" "null" ## we expect no output here
   )
 
   ## test loadConfig with missing values
@@ -58,37 +58,66 @@ _testZFSReplicate() {
     # shellcheck source=/dev/null
     . ../zfs-replicate.sh
     printf "_testZFSReplicate/loadConfigWithError\n"
-    ! line=$(loadConfig) && true ## prevent tests from exiting
-    _fail "$line" "missing required setting REPLICATE_SETS"
+    ! lines=$(loadConfig 2>&1) && true ## prevent tests from exiting
+    _fail "$lines" "missing required setting REPLICATE_SETS"
   )
 
   ## test config override of script defaults
   (
-    ## likely default values at script load time
-    FIND="/usr/bin/find"
-    ZFS="/sbin/zfs"
-    SSH="/usr/sbin/ssh"
+    ## generic default values
+    FIND="fakeFIND"
+    ZFS="fakeZFS"
+    SSH="fakeSSH"
     REPLICATE_SETS="fakeSource:fakeDest"
     # shellcheck source=/dev/null
     . ../zfs-replicate.sh
     printf "_testZFSReplicate/loadConfigOverrideDefaults\n"
-    _fail "/usr/sbin/ssh %HOST% /sbin/zfs receive -vFd" "$DEST_PIPE_WITH_HOST"
-    _fail "/sbin/zfs receive -vFd" "$DEST_PIPE_WITHOUT_HOST"
+    _fail "fakeSSH %HOST% /sbin/zfs receive -vFd" "$DEST_PIPE_WITH_HOST"
+    _fail "fakeZFS receive -vFd" "$DEST_PIPE_WITHOUT_HOST"
     ## generate config
     config="$(mktemp)"
     printf "ZFS=\"myZFS\"\n" >> "$config"
     ## set SSH via environment
     SSH="mySSH"
-    loadConfig "$config" && rm -f "$config"
+    loadConfig "$config" 2>&1 && rm -f "$config"
     ## values should match config and environment
     _fail "mySSH %HOST% myZFS receive -vFd" "$DEST_PIPE_WITH_HOST"
     _fail "myZFS receive -vFd" "$DEST_PIPE_WITHOUT_HOST"
   )
 
+  ## test loadConfig with options
+  (
+    FIND="${SCRIPT_PATH}/find.sh"
+    ZFS="fakeZFS"
+    SSH="fakeSSH"
+    LOG_BASE="$(mktemp -d)"
+    # shellcheck source=/dev/null
+    . ../zfs-replicate.sh
+    ## test --help and -h
+    printf "_testZFSReplicate/loadConfigWithHelp\n"
+    ! lines=$(loadConfig "--help" 2>&1) && true ## prevent tests from exiting
+    _fail "$lines" "Usage: test.sh"
+    ! lines=$(loadConfig "-h" 2>&1) && true ## prevent tests from exiting
+    _fail "$lines" "Usage: test.sh"
+    ## test --status and -s
+    printf "_testZFSReplicate/loadConfigWithStatus\n"
+    ## generate fake log files with staggered creation time
+    for idx in $(seq 1 3); do
+      printf "testing log %d\n" "$idx" > "${LOG_BASE}/autorep-test${idx}.log" && sleep 1
+    done
+    ## check status command
+    ! lines=$(loadConfig "--status" 2>&1) && true ## prevent tests from exiting
+    _fail "$lines" "testing log 3"
+    ! lines=$(loadConfig "-s" 2>&1) && true ## prevent tests from exiting
+    _fail "$lines" "testing log 3"
+    ## cleanup
+    rm -rvf "${LOG_BASE}"
+  )
+
   ## test snapCreate with different set combinations
   (
     ## configure test parameters
-    FIND="${SCRIPT_PATH}/find.sh"
+    FIND="fakeFIND"
     ZFS="${SCRIPT_PATH}/zfs.sh"
     SSH="${SCRIPT_PATH}/ssh.sh"
     HOST_CHECK="${ECHO} %HOST%"
@@ -101,7 +130,7 @@ _testZFSReplicate() {
     . ../zfs-replicate.sh && loadConfig
     printf "_testZFSReplicate/snapCreateWithoutErrors\n"
     idx=0
-    snapCreate | while IFS= read -r line; do
+    snapCreate 2>&1 | while IFS= read -r line; do
       match=""
       printf "%d %s\n" "$idx" "$line"
       case $idx in
@@ -114,129 +143,159 @@ _testZFSReplicate() {
         3)
           match="cmd=${ZFS} list -H -o name dstPool0/dstFS0"
           ;;
+        5)
+          match="cmd=${ZFS} list -Hr -o name -s creation -t snapshot -d 1 srcPool0/srcFS0"
+          ;;
         6)
+          match="cmd=${ZFS} list -Hr -o name -s creation -t snapshot dstPool0/dstFS0"
+          ;;
+        8)
           match="cmd=${ZFS} destroy srcPool0/srcFS0@autorep-test1"
           ;;
-        7)
+        9)
           match="cmd=${ZFS} snapshot srcPool0/srcFS0@autorep-"
           ;;
-        8)
+        10)
           match="creating lockfile ${TMPDIR}/.replicate.send.lock"
           ;;
-        9)
+        11)
           match="cmd=${ZFS} send -Rs -I srcPool0/srcFS0@autorep-test3 srcPool0/srcFS0@autorep-${TAG} |"
           match="$match ${DEST_PIPE_WITHOUT_HOST} dstPool0/dstFS0"
           ;;
-        10)
+        12)
           match="receive -vFd dstPool0/dstFS0"
           ;;
-        11)
+        13)
           match="deleting lockfile ${TMPDIR}/.replicate.send.lock"
           ;;
-        12)
+        14)
           match="cmd=${ECHO} dstHost1"
           ;;
-        13)
+        15)
           match="cmd=${ZFS} list -H -o name srcPool1/srcFS1/subFS1"
           ;;
-        15)
+        17)
           match="cmd=${SSH} dstHost1 ${ZFS} list -H -o name dstPool1/dstFS1"
           ;;
-        18)
+        19)
+          match="cmd=${ZFS} list -Hr -o name -s creation -t snapshot -d 1 srcPool1/srcFS1/subFS1"
+          ;;
+        20)
+          match="cmd=${SSH} dstHost1 ${ZFS} list -Hr -o name -s creation -t snapshot dstPool1/dstFS1"
+          ;;
+        22)
           match="cmd=${ZFS} destroy srcPool1/srcFS1/subFS1@autorep-test1"
           ;;
-        19)
+        23)
           match="cmd=${ZFS} snapshot srcPool1/srcFS1/subFS1@autorep-${TAG}"
           ;;
-        20)
+        24)
           match="creating lockfile ${TMPDIR}/.replicate.send.lock"
           ;;
-        21)
+        25)
           match="cmd=${ZFS} send -Rs -I srcPool1/srcFS1/subFS1@autorep-test3 srcPool1/srcFS1/subFS1@autorep-${TAG} |"
           match="$match ${SSH} dstHost1 ${ZFS} receive -vFd dstPool1/dstFS1"
           ;;
-        23)
+        27)
           match="deleting lockfile ${TMPDIR}/.replicate.send.lock"
           ;;
-        24)
+        28)
           match="cmd=${ECHO} dstHost2"
           ;;
-        25)
+        29)
           match="cmd=${ZFS} list -H -o name srcPool2/srcFS2"
           ;;
-        27)
+        31)
           match="cmd=${SSH} dstHost2 ${ZFS} list -H -o name dstPool2/dstFS2"
           ;;
-        30)
+        33)
+          match="cmd=${ZFS} list -Hr -o name -s creation -t snapshot -d 1 srcPool2/srcFS2"
+          ;;
+        34)
+          match="cmd=${SSH} dstHost2 ${ZFS} list -Hr -o name -s creation -t snapshot dstPool2/dstFS2"
+          ;;
+        36)
           match="cmd=${ZFS} destroy srcPool2/srcFS2@autorep-test1"
           ;;
-        31)
+        37)
           match="cmd=${ZFS} snapshot srcPool2/srcFS2@autorep-${TAG}"
           ;;
-        32)
+        38)
           match="creating lockfile ${TMPDIR}/.replicate.send.lock"
           ;;
-        33)
+        39)
           match="cmd=${ZFS} send -Rs -I srcPool2/srcFS2@autorep-test3 srcPool2/srcFS2@autorep-${TAG} |"
           match="$match ${SSH} dstHost2 ${ZFS} receive -vFd dstPool2/dstFS2"
           ;;
-        35)
+        41)
           match="deleting lockfile ${TMPDIR}/.replicate.send.lock"
           ;;
-        36)
+        42)
           match="cmd=${ECHO} srcHost3"
           ;;
-        37)
+        43)
           match=" cmd=${SSH} srcHost3 ${ZFS} list -H -o name srcPool3/srcFS3"
           ;;
-        39)
+        45)
           match="cmd=${ZFS} list -H -o name dstPool3/dstFS3"
           ;;
-        42)
+        47)
+          match="cmd=${SSH} srcHost3 ${ZFS} list -Hr -o name -s creation -t snapshot -d 1 srcPool3/srcFS3"
+          ;;
+        48)
+          match="cmd=${ZFS} list -Hr -o name -s creation -t snapshot dstPool3/dstFS3"
+          ;;
+        50)
           match="cmd=${SSH} srcHost3 ${ZFS} destroy srcPool3/srcFS3@autorep-test1"
           ;;
-        43)
+        51)
           match="cmd=${SSH} srcHost3 ${ZFS} snapshot srcPool3/srcFS3@autorep-${TAG}"
           ;;
-        44)
+        52)
           match="creating lockfile ${TMPDIR}/.replicate.send.lock"
           ;;
-        45)
+        53)
           match="cmd=${SSH} srcHost3 ${ZFS} send -Rs -I srcPool3/srcFS3@autorep-test3 srcPool3/srcFS3@autorep-${TAG} |"
           match="$match ${ZFS} receive -vFd dstPool3/dstFS3"
           ;;
-        47)
+        55)
           match="deleting lockfile ${TMPDIR}/.replicate.send.lock"
           ;;
-        48)
+        56)
           match="cmd=${ECHO} srcHost4"
           ;;
-        49)
+        57)
           match="cmd=${ECHO} dstHost4"
           ;;
-        50)
+        58)
           match="cmd=${SSH} srcHost4 ${ZFS} list -H -o name srcPool4/srcFS4"
           ;;
-        52)
+        60)
           match="cmd=${SSH} dstHost4 ${ZFS} list -H -o name dstPool4/dstFS4"
           ;;
-        55)
+        62)
+          match="cmd=${SSH} srcHost4 ${ZFS} list -Hr -o name -s creation -t snapshot -d 1 srcPool4/srcFS4"
+          ;;
+        63)
+          match="cmd=${SSH} dstHost4 ${ZFS} list -Hr -o name -s creation -t snapshot dstPool4/dstFS4"
+          ;;
+        65)
           match="cmd=${SSH} srcHost4 ${ZFS} destroy srcPool4/srcFS4@autorep-test1"
           ;;
-        56)
+        66)
           match="cmd=${SSH} srcHost4 ${ZFS} snapshot srcPool4/srcFS4@autorep-${TAG}"
           ;;
-        57)
+        67)
           match="creating lockfile ${TMPDIR}/.replicate.send.lock"
           ;;
-        58)
+        68)
           match="cmd=${SSH} srcHost4 ${ZFS} send -Rs -I srcPool4/srcFS4@autorep-test3 srcPool4/srcFS4@autorep-${TAG} |"
           match="$match ${SSH} dstHost4 ${ZFS} receive -vFd dstPool4/dstFS4"
           ;;
-        60)
+        70)
           match="deleting lockfile ${TMPDIR}/.replicate.send.lock"
           ;;
-        61)
+        71)
           match="deleting lockfile ${TMPDIR}/.replicate.snapshot.lock"
           ;;
       esac
@@ -248,7 +307,7 @@ _testZFSReplicate() {
   ## test snapCreate with host check errors
   (
     ## configure test parameters
-    FIND="${SCRIPT_PATH}/find.sh"
+    FIND="fakeFIND"
     ZFS="${SCRIPT_PATH}/zfs.sh"
     SSH="${SCRIPT_PATH}/ssh.sh"
     HOST_CHECK="false"
@@ -261,16 +320,13 @@ _testZFSReplicate() {
     . ../zfs-replicate.sh && loadConfig
     printf "_testZFSReplicate/snapCreateWithHostCheckErrors\n"
     idx=0
-    snapCreate | while IFS= read -r line; do
+    snapCreate 2>&1 | while IFS= read -r line; do
       match=""
       printf "%d %s\n" "$idx" "$line"
       case $idx in
         0)
           match="creating lockfile ${TMPDIR}/.replicate.snapshot.lock"
           ;;
-        13)
-          match="source or destination host check failed"
-          ;;
         15)
           match="source or destination host check failed"
           ;;
@@ -280,7 +336,10 @@ _testZFSReplicate() {
         19)
           match="source or destination host check failed"
           ;;
-        20)
+        21)
+          match="source or destination host check failed"
+          ;;
+        22)
           match="deleting lockfile ${TMPDIR}/.replicate.snapshot.lock"
           ;;
       esac
@@ -292,7 +351,7 @@ _testZFSReplicate() {
   ## test snapCreate with dataset check errors
   (
     ## configure test parameters
-    FIND="${SCRIPT_PATH}/find.sh"
+    FIND="fakeFIND"
     ZFS="${SCRIPT_PATH}/zfs.sh"
     SSH="${SCRIPT_PATH}/ssh.sh"
     HOST_CHECK="${ECHO} %HOST%"
@@ -303,7 +362,7 @@ _testZFSReplicate() {
     . ../zfs-replicate.sh && loadConfig
     printf "_testZFSReplicate/snapCreateWithDatasetCheckErrors\n"
     idx=0
-    snapCreate | while IFS= read -r line; do
+    snapCreate 2>&1 | while IFS= read -r line; do
       match=""
       printf "%d %s\n" "$idx" "$line"
       case $idx in
@@ -362,9 +421,9 @@ _testZFSReplicate() {
     # shellcheck source=/dev/null
     . ../zfs-replicate.sh && loadConfig
     printf "_testZFSReplicate/exitCleanSuccess\n"
-    line=$(exitClean 0 "test message")
+    lines=$(exitClean 0 "test message" 2>&1)
     match="success total sets 0 skipped 0: test message" ## counts are modified in snapCreate
-    _fail "$line" "$match"
+    _fail "$lines" "$match"
   )
 
   ## test exitClean code=99 with error message
@@ -377,9 +436,9 @@ _testZFSReplicate() {
     # shellcheck source=/dev/null
     . ../zfs-replicate.sh && loadConfig
     printf "_testZFSReplicate/exitCleanError\n"
-    ! line=$(exitClean 99 "error message") && true ## prevent tests from exiting
+    ! lines=$(exitClean 99 "error message" 2>&1) && true ## prevent tests from exiting
     match="operation exited unexpectedly: code=99 msg=error message"
-    _fail "$line" "$match"
+    _fail "$lines" "$match"
   )
 
   ## yay, tests completed!
diff --git a/zfs-replicate.sh b/zfs-replicate.sh
index f2cf5cf..fda5b45 100755
--- a/zfs-replicate.sh
+++ b/zfs-replicate.sh
@@ -77,7 +77,7 @@ pruneLogs() {
   fi
   if [ "$logCount" -gt "$LOG_KEEP" ]; then
     prune="$(printf "%s\n" "$logs" | sed -n "$((LOG_KEEP + 1)),\$p")"
-    printf "pruning %d logs\n" "$((logCount - LOG_KEEP + 1))"
+    printf "pruning %d logs\n" "$((logCount - LOG_KEEP + 1))" 1>&2
     printf "%s\n" "$prune" | xargs rm -vf
   fi
 }
@@ -86,7 +86,7 @@ pruneLogs() {
 clearLock() {
   lockFile=$1
   if [ -f "$lockFile" ]; then
-    printf "deleting lockfile %s\n" "$lockFile"
+    printf "deleting lockfile %s\n" "$lockFile" 1>&2
     rm "$lockFile"
   fi
 }
@@ -118,7 +118,7 @@ exitClean() {
   clearLock "${TMPDIR}/.replicate.snapshot.lock"
   clearLock "${TMPDIR}/.replicate.send.lock"
   ## print log message and exit
-  printf "%s\n" "$logMsg"
+  printf "%s\n" "$logMsg" 1>&2
   exit "$exitCode"
 }
 
@@ -130,16 +130,16 @@ checkLock() {
     ## see if this pid is still running
     if ps -p "$(cat "$lockFile")" > /dev/null 2>&1; then
       ## looks like it's still running
-      printf "ERROR: script is already running as: %d\n" "$(cat "$lockFile")"
+      printf "ERROR: script is already running as: %d\n" "$(cat "$lockFile")" 1>&2
     else
       ## stale lock file?
-      printf "ERROR: stale lockfile %s\n" "$lockFile"
+      printf "ERROR: stale lockfile %s\n" "$lockFile" 1>&2
     fi
     ## cleanup and exit
     exitClean 128 "confirm script is not running and delete lockfile $lockFile"
   fi
   ## well no lockfile..let's make a new one
-  printf "creating lockfile %s\n" "$lockFile"
+  printf "creating lockfile %s\n" "$lockFile" 1>&2
   printf "%d\n" "$$" > "$lockFile"
 }
 
@@ -154,7 +154,7 @@ checkHost() {
     return 0
   fi
   cmd=$(printf "%s\n" "$HOST_CHECK" | sed "s/%HOST%/$host/g")
-  printf "checking host cmd=%s\n" "$cmd"
+  printf "checking host cmd=%s\n" "$cmd" 2>&1
   ## run the check
   if ! $cmd > /dev/null 2>&1; then
     return 1
@@ -172,7 +172,7 @@ checkDataset() {
     cmd="$SSH $host "
   fi
   cmd="$cmd$ZFS list -H -o name $set"
-  printf "checking dataset cmd=%s\n" "$cmd"
+  printf "checking dataset cmd=%s\n" "$cmd" 1>&2
   ## execute command
   if ! $cmd; then
     return 1
@@ -194,7 +194,7 @@ snapDestroy() {
     cmd="$cmd -r"
   fi
   cmd="$cmd $snap"
-  printf "destroying snapshot cmd=%s\n" "$cmd"
+  printf "destroying snapshot cmd=%s\n" "$cmd" 1>&2
   ## ignore error from destroy and count on logging to alert the end-user
   ## destroying recursive snapshots can lead to "snapshot not found" errors
   $cmd || true
@@ -227,7 +227,7 @@ snapSend() {
     pipe=$(printf "%s\n" "$DEST_PIPE_WITH_HOST" | sed "s/%HOST%/$dstHost/g")
   fi
   pipe="$pipe $dst"
-  printf "sending snapshot cmd=%s | %s\n" "$cmd" "$pipe"
+  printf "sending snapshot cmd=%s | %s\n" "$cmd" "$pipe" 1>&2
   ## execute send and check return
   if ! $cmd | $pipe; then
     snapDestroy "${src}@${name}" "$srcHost"
@@ -252,6 +252,7 @@ snapList() {
     cmd="$cmd -d $depth"
   fi
   cmd="$cmd $set"
+  printf "listing snapshots cmd=%s\n" "$cmd" 1>&2
   ## get snapshots from host
   if ! snaps=$($cmd); then
     exitClean 128 "failed to list snapshots for dataset: $set"
@@ -276,7 +277,7 @@ snapCreate() {
     if [ "$ALLOW_ROOT_DATASETS" -ne 1 ]; then
       if [ "$dst" = "$(basename "$dst")" ] || [ "$dst" = "$(basename "$dst")/" ]; then
         temps="replicating root datasets can lead to data loss - set ALLOW_ROOT_DATASETS=1 to override"
-        printf "WARNING: skipping replication set '%s' - %s\n" "$pair" "$temps"
+        printf "WARNING: skipping replication set '%s' - %s\n" "$pair" "$temps" 1>&2
         __SKIP_COUNT=$((__SKIP_COUNT + 1))
         continue
       fi
@@ -296,13 +297,13 @@ snapCreate() {
     fi
     ## check source and destination hosts
     if ! checkHost "$srcHost" || ! checkHost "$dstHost"; then
-      printf "WARNING: skipping replication set '%s' - source or destination host check failed\n" "$pair"
+      printf "WARNING: skipping replication set '%s' - source or destination host check failed\n" "$pair" 1>&2
       __SKIP_COUNT=$((__SKIP_COUNT + 1))
       continue
     fi
     ## check source and destination datasets
     if ! checkDataset "$src" "$srcHost" || ! checkDataset "$dst" "$dstHost"; then
-      printf "WARNING: skipping replication set '%s' - source or destination dataset check failed\n" "$pair"
+      printf "WARNING: skipping replication set '%s' - source or destination dataset check failed\n" "$pair" 1>&2
       __SKIP_COUNT=$((__SKIP_COUNT + 1))
       continue
     fi
@@ -313,7 +314,7 @@ snapCreate() {
       ## while we are here...check for our current snap name
       if [ "$snap" = "${src}@${name}" ]; then
         ## looks like it's here...we better kill it
-        printf "destroying duplicate snapshot: %s@%s\n" "$src" "$name"
+        printf "destroying duplicate snapshot: %s@%s\n" "$src" "$name" 1>&2
         snapDestroy "${src}@${name}" "$srcHost"
       fi
     done
@@ -346,7 +347,7 @@ snapCreate() {
       if [ -z "$base" ] && [ "$ALLOW_RECONCILIATION" -ne 1 ]; then
         temps=$(printf "source snapshot '%s' not in destination dataset: %s" "$ss" "$dst")
         temps=$(printf "%s - set 'ALLOW_RECONCILIATION=1' to fallback to a full send" "$temps")
-        printf "WARNING: skipping replication set '%s' - %s\n" "$pair" "$temps"
+        printf "WARNING: skipping replication set '%s' - %s\n" "$pair" "$temps" 1>&2
         __SKIP_COUNT=$((__SKIP_COUNT + 1))
         continue
       fi
@@ -356,12 +357,12 @@ snapCreate() {
       ## allowed to prune remote dataset?
       if [ "$ALLOW_RECONCILIATION" -ne 1 ]; then
         temps="destination contains snapshots not in source - set 'ALLOW_RECONCILIATION=1' to prune snapshots"
-        printf "WARNING: skipping replication set '%s' - %s\n" "$pair" "$temps"
+        printf "WARNING: skipping replication set '%s' - %s\n" "$pair" "$temps" 1>&2
         __SKIP_COUNT=$((__SKIP_COUNT + 1))
         continue
       fi
       ## prune destination snapshots
-      printf "pruning destination snapshots: %s\n" "$dstSnaps"
+      printf "pruning destination snapshots: %s\n" "$dstSnaps" 1>&2
       for snap in $dstSnaps; do
         snapDestroy "$snap" "$dstHost"
       done
@@ -370,7 +371,7 @@ snapCreate() {
     if [ "$srcSnapCount" -ge "$SNAP_KEEP" ]; then
       ## snaps are sorted above by creation in ascending order
       printf "%s\n" "$srcSnaps" | sed -n "1,$((srcSnapCount - SNAP_KEEP))p" | while read -r snap; do
-        printf "found old snapshot %s\n" "$snap"
+        printf "found old snapshot %s\n" "$snap" 1>&2
         snapDestroy "$snap" "$srcHost"
       done
     fi
@@ -386,7 +387,7 @@ snapCreate() {
     fi
     cmd="$cmd ${src}@${name}"
     ## come on already...take that snapshot
-    printf "creating snapshot cmd=%s\n" "$cmd"
+    printf "creating snapshot cmd=%s\n" "$cmd" 1>&2
     if ! $cmd; then
       snapDestroy "${src}@${name}" "$srcHost"
       exitClean 128 "failed to create snapshot: ${src}@${name}"
@@ -407,7 +408,7 @@ writeLog() {
     logf="${LOG_BASE}/${LOG_FILE}"
   fi
   ## always print to stdout and copy to logfile if set
-  printf "%s %s[%d]: %s\n" "$(date '+%b %d %T')" "$SCRIPT" "$$" "$line" | tee -a "$logf"
+  printf "%s %s[%d]: %s\n" "$(date '+%b %d %T')" "$SCRIPT" "$$" "$line" | tee -a "$logf" 1>&2
   ## if syslog has been enabled write to syslog via logger
   if [ "$SYSLOG" -eq 1 ] && [ -n "$LOGGER" ]; then
     $LOGGER -p "${SYSLOG_FACILITY}.info" -t "$SCRIPT" "$line"