Merge branch 'master' into new-ui

.github/ISSUE_TEMPLATE/bug_report.md

@@ -0,0 +1,43 @@
+---
+name: Bug report
+about: Create a report to help us improve
+title: ''
+labels: bug
+assignees: ''
+
+---
+
+**Describe the bug**
+A clear and concise description of what the bug is.
+
+**To Reproduce**
+Steps to reproduce the behavior:
+1. Go to '...'
+2. Click on '....'
+3. Scroll down to '....'
+4. See error
+
+**Expected behavior**
+A clear and concise description of what you expected to happen.
+
+**Server (please complete the following information):**
+  - If using Docker: `docker ps` + `docker images`
+  - If building from git: `git describe` + `moonfire-nvr --version`
+  - Attach a [log file](https://github.com/scottlamb/moonfire-nvr/blob/master/guide/troubleshooting.md#viewing-moonfire-nvrs-logs). Run with the `RUST_BACKTRACE=1` environment variable set if possible.
+
+**Screenshots**
+If applicable, add screenshots to help explain your problem.
+
+**Desktop (please complete the following information):**
+ - OS: [e.g. iOS]
+ - Browser [e.g. chrome, safari]
+ - Version [e.g. 22]
+
+**Smartphone (please complete the following information):**
+ - Device: [e.g. iPhone6]
+ - OS: [e.g. iOS8.1]
+ - Browser [e.g. stock browser, safari]
+ - Version [e.g. 22]
+
+**Additional context**
+Add any other context about the problem here.

.github/workflows/ci.yml

@@ -3,6 +3,7 @@ on: [push, pull_request]
 
 env:
   CARGO_TERM_COLOR: always
+  MOONFIRE_COLOR: always
   RUST_BACKTRACE: 1
 
 jobs:

CHANGELOG.md

@@ -0,0 +1,34 @@
+# Moonfire NVR change log
+
+Below are some highlights in each release. For a full description of all
+changes, see Git history.
+
+Each release is tagged in Git and on the Docker repository
+[`scottlamb/moonfire-nvr`](https://hub.docker.com/r/scottlamb/moonfire-nvr).
+
+## `v0.6.2`
+
+*   Fix panics when a stream's PTS has extreme jumps
+    ([#113](https://github.com/scottlamb/moonfire-nvr/issues/113))
+*   Improve logging. Console log output is now color-coded. ffmpeg errors
+    and panics are now logged in the same way as other messages.
+*   Fix an error that could prevent the
+    `moonfire-nvr check --delete-orphan-rows` command from actually deleting
+    rows.
+
+## `v0.6.1`
+
+*   Improve the server's error messages on the console and in logs.
+*   Switch the UI build from the `yarn` package manager to `npm`.
+    This makes Moonfire NVR a bit easier to build from scratch.
+*   Extend the `moonfire-nvr check` command to clean up several problems that
+    can be caused by filesystem corruption.
+*   Set the page size to 16 KiB on `moonfire-nvr init` and
+    `moonfire-nvr upgrade`. This improves performance.
+*   Fix mangled favicons
+    ([#105](https://github.com/scottlamb/moonfire-nvr/issues/105))
+
+## `v0.6.0`
+
+This is the first tagged version and first Docker image release. I chose the
+version number 0.6.0 to match the current schema version 6.

README.md

@@ -20,7 +20,7 @@ console-based (rather than web-based) configuration UI.
 
 ![screenshot](screenshot.png)
 
-Moonfire NVR is currently at version 0.6.1. Until version 1.0, there will be no
+Moonfire NVR is currently at version 0.6.2. Until version 1.0, there will be no
 compatibility guarantees: configuration and storage formats may change from
 version to version. There is an [upgrade procedure](guide/schema.md) but it is
 not for the faint of heart.

docker/Dockerfile

@@ -12,62 +12,60 @@ FROM --platform=$BUILDPLATFORM ubuntu:20.04 AS dev-common
 LABEL maintainer="slamb@slamb.org"
 ARG BUILD_UID=1000
 ARG BUILD_GID=1000
+ARG INVALIDATE_CACHE_DEV_COMMON=
 ENV LC_ALL=C.UTF-8
 COPY docker/dev-common.bash /
-RUN /dev-common.bash
+RUN --mount=type=cache,id=var-cache-apt,target=/var/cache/apt,sharing=locked \
+    /dev-common.bash
 CMD [ "/bin/bash", "--login" ]
 
 # "dev" is a full development environment, suitable for shelling into or
 # using with the VS Code container plugin.
 FROM --platform=$BUILDPLATFORM dev-common AS dev
+LABEL maintainer="slamb@slamb.org"
 ARG BUILDARCH
 ARG TARGETARCH
-LABEL maintainer="slamb@slamb.org"
+ARG INVALIDATE_CACHE_DEV=
 COPY docker/dev.bash /
-RUN /dev.bash
+RUN --mount=type=cache,id=var-cache-apt,target=/var/cache/apt,sharing=locked \
+    /dev.bash
 USER moonfire-nvr:moonfire-nvr
 WORKDIR /var/lib/moonfire-nvr
 
 # Build the UI with node_modules and ui-dist outside the src dir.
 FROM --platform=$BUILDPLATFORM dev-common AS build-ui
+ARG INVALIDATE_CACHE_BUILD_UI=
 LABEL maintainer="slamb@slamb.org"
 WORKDIR /var/lib/moonfire-nvr/src/ui
+COPY docker/build-ui.bash /
 COPY ui /var/lib/moonfire-nvr/src/ui
 RUN --mount=type=tmpfs,target=/var/lib/moonfire-nvr/src/ui/node_modules \
-    npm ci && npm run build
+    /build-ui.bash
 
 # Build the Rust components. Note that dev.sh set up an environment variable
 # in .buildrc that similarly changes the target dir path.
 FROM --platform=$BUILDPLATFORM dev AS build-server
 LABEL maintainer="slamb@slamb.org"
-RUN --mount=type=cache,id=target,target=/var/lib/moonfire-nvr/target,sharing=locked,mode=1777 \
+ARG INVALIDATE_CACHE_BUILD_SERVER=
+COPY docker/build-server.bash /
+RUN --mount=type=cache,id=target,target=/var/lib/moonfire-nvr/target,sharing=locked,mode=777 \
+    --mount=type=cache,id=cargo,target=/cargo-cache,sharing=locked,mode=777 \
     --mount=type=bind,source=server,target=/var/lib/moonfire-nvr/src/server,readonly \
-    bash -c 'set -o xtrace && \
+    /build-server.bash
-             source ~/.buildrc && \
-             cd src/server && \
-             cargo test && \
-             cargo build --release && \
-             sudo install -m 755 ~/moonfire-nvr /usr/local/bin/moonfire-nvr'
 
 # Deployment environment, now in the target platform.
 FROM --platform=$TARGETPLATFORM ubuntu:20.04 AS deploy
 LABEL maintainer="slamb@slamb.org"
+ARG INVALIDATE_CACHE_BUILD_DEPLOY=
 ENV LC_ALL=C.UTF-8
-RUN export DEBIAN_FRONTEND=noninteractive && \
+COPY docker/deploy.bash /
-    apt-get update && \
+RUN --mount=type=cache,id=var-cache-apt,target=/var/cache/apt,sharing=locked \
-    apt-get install --assume-yes --no-install-recommends \
+    /deploy.bash
-        ffmpeg \
+COPY --from=dev-common /docker-build-debug/dev-common/ /docker-build-debug/dev-common/
-        libncurses6 \
+COPY --from=dev /docker-build-debug/dev/ /docker-build-debug/dev/
-        libncursesw6 \
+COPY --from=build-server /docker-build-debug/build-server/ /docker-build-debug/build-server/
-        locales \
-        sudo \
-        sqlite3 \
-        tzdata \
-        vim-nox && \
-    apt-get clean && \
-    rm -rf /var/lib/apt/lists/* && \
-    ln -s moonfire-nvr /usr/local/bin/nvr
 COPY --from=build-server /usr/local/bin/moonfire-nvr /usr/local/bin/moonfire-nvr
+COPY --from=build-ui /docker-build-debug/build-ui /docker-build-debug/build-ui
 COPY --from=build-ui /var/lib/moonfire-nvr/src/ui/build /usr/local/lib/moonfire-nvr/ui
 
 # The install instructions say to use --user in the docker run commandline.

docker/build-server.bash

@@ -0,0 +1,34 @@
+#!/bin/bash
+# This file is part of Moonfire NVR, a security camera network video recorder.
+# Copyright (C) 2021 The Moonfire NVR Authors; see AUTHORS and LICENSE.txt.
+# SPDX-License-Identifier: GPL-v3.0-or-later WITH GPL-3.0-linking-exception.
+
+# Build the "build-server" target. See Dockerfile.
+
+set -o errexit
+set -o pipefail
+set -o xtrace
+
+mkdir /docker-build-debug/build-server
+exec > >(tee -i /docker-build-debug/build-server/output) 2>&1
+ls -laFR /cargo-cache > /docker-build-debug/build-server/cargo-cache-before
+ls -laFR /var/lib/moonfire-nvr/target \
+    > /docker-build-debug/build-server/target-before
+
+source ~/.buildrc
+
+# The "mode" argument to cache mounts doesn't seem to work reliably
+# (as of Docker version 20.10.5, build 55c4c88, using a docker-container
+# builder), thus the chmod command.
+sudo chmod 777 /cargo-cache /var/lib/moonfire-nvr/target
+mkdir -p /cargo-cache/{git,registry}
+ln -s /cargo-cache/{git,registry} ~/.cargo
+
+cd src/server
+time cargo test
+time cargo build --release
+sudo install -m 755 ~/moonfire-nvr /usr/local/bin/moonfire-nvr
+
+ls -laFR /cargo-cache > /docker-build-debug/build-server/cargo-cache-after
+ls -laFR /var/lib/moonfire-nvr/target \
+    > /docker-build-debug/build-server/target-after

docker/build-ui.bash

@@ -0,0 +1,18 @@
+#!/bin/bash
+# This file is part of Moonfire NVR, a security camera network video recorder.
+# Copyright (C) 2021 The Moonfire NVR Authors; see AUTHORS and LICENSE.txt.
+# SPDX-License-Identifier: GPL-v3.0-or-later WITH GPL-3.0-linking-exception.
+
+# Build the "build-ui" target. See Dockerfile.
+
+set -o errexit
+set -o pipefail
+set -o xtrace
+
+mkdir /docker-build-debug/build-ui
+exec > >(tee -i /docker-build-debug/build-ui/output) 2>&1
+
+time npm ci
+time npm run build
+ls -laFR /var/lib/moonfire-nvr/src/ui/node_modules \
+    > /docker-build-debug/build-ui/node_modules-after

docker/deploy.bash

@@ -0,0 +1,32 @@
+#!/bin/bash
+# This file is part of Moonfire NVR, a security camera network video recorder.
+# Copyright (C) 2021 The Moonfire NVR Authors; see AUTHORS and LICENSE.txt.
+# SPDX-License-Identifier: GPL-v3.0-or-later WITH GPL-3.0-linking-exception.
+
+# Build the "deploy" target. See Dockerfile.
+
+set -o errexit
+set -o pipefail
+set -o xtrace
+
+mkdir -p /docker-build-debug/deploy
+exec > >(tee -i /docker-build-debug/deploy/output) 2>&1
+ls -laFR /var/cache/apt \
+    > /docker-build-debug/deploy/var-cache-apt-before
+
+export DEBIAN_FRONTEND=noninteractive
+time apt-get update
+time apt-get install --assume-yes --no-install-recommends \
+    ffmpeg \
+    libncurses6 \
+    libncursesw6 \
+    locales \
+    sudo \
+    sqlite3 \
+    tzdata \
+    vim-nox && \
+rm -rf /var/lib/apt/lists/*
+ln -s moonfire-nvr /usr/local/bin/nvr
+
+ls -laFR /var/cache/apt \
+    > /docker-build-debug/deploy/var-cache-apt-after

docker/dev-common.bash

@@ -11,6 +11,16 @@ set -o xtrace
 
 export DEBIAN_FRONTEND=noninteractive
 
+mkdir --mode=1777 /docker-build-debug
+mkdir /docker-build-debug/dev-common
+exec > >(tee -i /docker-build-debug/dev-common/output) 2>&1
+ls -laFR /var/cache/apt > /docker-build-debug/dev-common/var-cache-apt-before
+
+# This file cleans apt caches after every invocation. Instead, we use a
+# buildkit cachemount to avoid putting them in the image while still allowing
+# some reuse.
+rm /etc/apt/apt.conf.d/docker-clean
+
 packages=()
 
 # Install all packages necessary for building (and some for testing/debugging).
@@ -25,10 +35,8 @@ packages+=(
     tzdata
     vim-nox
 )
-apt-get update
+time apt-get update
-apt-get install --assume-yes --no-install-recommends "${packages[@]}"
+time apt-get install --assume-yes --no-install-recommends "${packages[@]}"
-apt-get clean
-rm -rf /var/lib/apt/lists/*
 
 # Create the user. On the dev environment, allow sudo.
 groupadd \
@@ -44,8 +52,10 @@ useradd \
     moonfire-nvr
 echo 'moonfire-nvr ALL=(ALL) NOPASSWD: ALL' >>/etc/sudoers
 
+
 # Install Rust. Note curl was already installed for yarn above.
-su moonfire-nvr -lc "curl --proto =https --tlsv1.2 -sSf https://sh.rustup.rs |
+time su moonfire-nvr -lc "
+    curl --proto =https --tlsv1.2 -sSf https://sh.rustup.rs |
     sh -s - -y"
 
 # Put configuration for the Rust build into a new ".buildrc" which is used
@@ -62,3 +72,5 @@ source \$HOME/.cargo/env
 export CARGO_BUILD_TARGET_DIR=/var/lib/moonfire-nvr/target
 EOF
 chown moonfire-nvr:moonfire-nvr /var/lib/moonfire-nvr/.buildrc
+
+ls -laFR /var/cache/apt > /docker-build-debug/dev-common/var-cache-apt-after

docker/dev.bash

@@ -13,6 +13,9 @@ export DEBIAN_FRONTEND=noninteractive
 
 packages=()
 
+mkdir -p /docker-build-debug/dev
+ls -laFR /var/cache/apt > /docker-build-debug/dev/var-cache-apt-before
+
 if [[ "${BUILDARCH}" != "${TARGETARCH}" ]]; then
     # Set up cross compilation.
     case "${TARGETARCH}" in
@@ -44,7 +47,7 @@ if [[ "${BUILDARCH}" != "${TARGETARCH}" ]]; then
     *) host_is_port=1 ;;
     esac
 
-    dpkg --add-architecture "${dpkg_arch}"
+    time dpkg --add-architecture "${dpkg_arch}"
 
     if [[ $target_is_port -ne $host_is_port ]]; then
         # Ubuntu stores non-x86 architectures at a different URL, so futz the
@@ -67,7 +70,7 @@ if [[ "${BUILDARCH}" != "${TARGETARCH}" ]]; then
     )
 fi
 
-apt-get update
+time apt-get update
 
 # Install the packages for the target architecture.
 packages+=(
@@ -78,10 +81,8 @@ packages+=(
     libncurses-dev"${apt_target_suffix}"
     libsqlite3-dev"${apt_target_suffix}"
 )
-apt-get update
+time apt-get update
-apt-get install --assume-yes --no-install-recommends "${packages[@]}"
+time apt-get install --assume-yes --no-install-recommends "${packages[@]}"
-apt-get clean
-rm -rf /var/lib/apt/lists/*
 
 # Set environment variables for cross-compiling.
 # Also set up a symlink that points to the release binary, because the
@@ -113,3 +114,5 @@ EOF
 else
     su moonfire-nvr -lc "ln -s target/release/moonfire-nvr ."
 fi
+
+ls -laFR /var/cache/apt > /docker-build-debug/dev/var-cache-apt-after

guide/build.md

@@ -10,6 +10,14 @@ tracker](https://github.com/scottlamb/moonfire-nvr/issues) or
 [mailing list](https://groups.google.com/d/forum/moonfire-nvr-users) when
 stuck. Please also send pull requests to improve this doc.
 
+* [Building Moonfire NVR](#building-moonfire-nvr)
+    * [Downloading](#downloading)
+    * [Docker builds](#docker-builds)
+        * [Release procedure](#release-procedure)
+    * [Non-Docker setup](#non-docker-setup)
+        * [Running interactively straight from the working copy](#running-interactively-straight-from-the-working-copy)
+        * [Running as a `systemd` service](#running-as-a-systemd-service)
+
 ## Downloading
 
 See the [github page](https://github.com/scottlamb/moonfire-nvr) (in case
@@ -35,7 +43,8 @@ which you can use from its shell via `docker run` or via something like
 Visual Studio Code's Docker plugin.
 
 ```
-$ docker buildx build --load --tag=moonfire-dev --target=dev 
+$ docker buildx build \
+        --load --tag=moonfire-dev --target=dev -f docker/Dockerfile .
 ...
 $ docker run \
         --rm --interactive=true --tty \
@@ -84,6 +93,51 @@ caveats:
     $ docker buildx build --load --platform=arm64/v8 ...
     ```
 
+On Linux hosts (as opposed to when using Docker Desktop on macOS/Windows),
+you'll likely see errors like the ones below. The solution is to [install
+emulators](https://github.com/tonistiigi/binfmt#installing-emulators).
+
+```
+Error while loading /usr/sbin/dpkg-split: No such file or directory
+Error while loading /usr/sbin/dpkg-deb: No such file or directory
+```
+
+Moonfire NVR's `Dockerfile` has some built-in debugging tools:
+
+*   Each stage saves some debug info to `/docker-build-debug/<stage>`, and
+    the `deploy` stage preserves the output from previous stages. The debug
+    info includes:
+    *    output (stdout + stderr) from the build script, running long operations
+         through the `time` command.
+    *    `ls -laFR` of cache mounts before and after.
+*   Each stage accepts a `INVALIDATE_CACHE_<stage>` argument. You can use eg
+    `--build-arg=INVALIDATE_CACHE_BUILD_SERVER=$(date +%s)` to force the
+    `build-server` stage to be rebuilt rather than use cached Docker layers.
+
+### Release procedure
+
+Releases are currently a bit manual. From a completely clean git work tree,
+
+1.  manually verify the current commit is pushed to github's master branch and
+    has a green checkmark indicating CI passed.
+2.  update versions:
+    *   update `server/Cargo.toml` version by hand; run `cargo test --workspace`
+        to update `Cargo.lock`.
+    *   ensure `README.md`, `CHANGELOG.md`, and `guide/install.md` refer to the
+        new version.
+3.  run commands:
+    ```bash
+    VERSION=x.y.z
+    git commit -am "prepare version ${VERSION}"
+    git tag -a "v${VERSION}" -m "version ${VERSION}"
+    ./release.bash
+    git push
+    git push origin "v${VERSION}"
+    ```
+
+The `release.bash` script needs [`jq`](https://stedolan.github.io/jq/)
+installed to work.
+
 ## Non-Docker setup
 
 You may prefer building without Docker on the host. Moonfire NVR should run
@@ -186,7 +240,7 @@ terminal, with no extra arguments, until you abort with Ctrl-C. Likewise,
 some of the shell script's subcommands that wrap Docker (`start`, `stop`, and
 `logs`) have no parallel with this `nvr`.
 
-## Running as a `systemd` service
+### Running as a `systemd` service
 
 If you want to deploy a non-Docker build on Linux, you may want to use
 `systemd`. Create `/etc/systemd/system/moonfire-nvr.service`:

guide/install.md

@@ -10,7 +10,7 @@ and verify you can run the container.
 
 ```
 $ docker run --rm -it scottlamb/moonfire-nvr:latest
-moonfire-nvr 0.6.1
+moonfire-nvr 0.6.2
 security camera network video recorder
 
 USAGE:
@@ -46,14 +46,13 @@ As you set up this script, adjust the `tz` variable as appropriate for your
 time zone.
 
 ```
-sudo sh -c 'cat > /usr/local/bin/nvr' <<EOF
+sudo sh -c 'cat > /usr/local/bin/nvr' <<'EOF'
 #!/bin/bash -e
 
 tz=America/Los_Angeles
 container_name=moonfire-nvr
 image_name=scottlamb/moonfire-nvr:latest
 common_docker_run_args=(
-        --mount=type=bind,source=/etc/localtime,destination=/etc/localtime
         --mount=type=bind,source=/var/lib/moonfire-nvr,destination=/var/lib/moonfire-nvr
         --user="$(id -u moonfire-nvr):$(id -g moonfire-nvr)"
         --env=RUST_BACKTRACE=1

guide/troubleshooting.md

@@ -4,37 +4,207 @@ Here are some tips for diagnosing various problems with Moonfire NVR. Feel free
 to open an [issue](https://github.com/scottlamb/moonfire-nvr/issues) if you
 need more help.
 
+* [Troubleshooting](#troubleshooting)
+    * [Viewing Moonfire NVR's logs](#viewing-moonfire-nvrs-logs)
+        * [Flushes](#flushes)
+        * [Panic errors](#panic-errors)
+        * [Slow operations](#slow-operations)
+        * [Camera stream errors](#camera-stream-errors)
+    * [Problems](#problems)
+        * [`Error: pts not monotonically increasing; got 26615520 then 26539470`](#error-pts-not-monotonically-increasing-got-26615520-then-26539470)
+        * [`moonfire-nvr config` displays garbage](#moonfire-nvr-config-displays-garbage)
+        * [Moonfire NVR reports problems with the database or filesystem](#moonfire-nvr-reports-problems-with-the-database-or-filesystem)
+        * [<a name="kernel-errors"></a> Errors in kernel logs](#-errors-in-kernel-logs)
+            * [UAS errors](#uas-errors)
+            * [Filesystem errors](#filesystem-errors)
+
 ## Viewing Moonfire NVR's logs
 
 While Moonfire NVR is running, logs will be written to stderr.
 
-   * When running the configuration UI, you typically should redirect stderr
+*   When running the configuration UI, you typically should redirect stderr
     to a text file to avoid poor interaction between the interactive stdout
     output and the logging. If you use the recommended
     `nvr config 2>debug-log` command, output will be in the `debug-log` file.
-   * When running detached through Docker, Docker saves the logs for you.
+*   When running detached through Docker, Docker saves the logs for you.
     Try `nvr logs` or `docker logs moonfire-nvr`.
-   * When running through systemd, stderr will be redirected to the journal.
+*   When running through systemd, stderr will be redirected to the journal.
     Try `sudo journalctl --unit moonfire-nvr` to view the logs. You also
     likely want to set `MOONFIRE_FORMAT=google-systemd` to format logs as
     expected by systemd.
 
 Logging options are controlled by environment variables:
 
-   * `MOONFIRE_LOG` controls the log level. Its format is similar to the
+*   `MOONFIRE_LOG` controls the log level. Its format is similar to the
     `RUST_LOG` variable used by the
     [env-logger](http://rust-lang-nursery.github.io/log/env_logger/) crate.
     `MOONFIRE_LOG=info` is the default.
     `MOONFIRE_LOG=info,moonfire_nvr=debug` gives more detailed logging of the
     `moonfire_nvr` crate itself.
-   * `MOONFIRE_FORMAT` selects the output format. The two options currently
+*   `MOONFIRE_FORMAT` selects the output format. The two options currently
     accepted are `google` (the default, like the Google
     [glog](https://github.com/google/glog) package) and `google-systemd` (a
     variation for better systemd compatibility).
-   * Errors include a backtrace if `RUST_BACKTRACE=1` is set.
+*   `MOONFIRE_COLOR` controls color coding when using the `google` format.
+    It accepts `always`, `never`, or `auto`. `auto` means to color code if
+    stderr is a terminal.
+*   Errors include a backtrace if `RUST_BACKTRACE=1` is set.
 
 If you use Docker, set these via Docker's `--env` argument.
 
+With the default `MOONFIRE_FORMAT=google`, log lines are in the following
+format:
+
+```text
+I20210308 21:31:24.255 main moonfire_nvr] Success.
+LYYYYmmdd HH:MM:SS.FFF TTTT PPPPPPPPPPPP] ...
+L    = level:
+       E = error; when color mode is on, the message will be bright red.
+       W = warn;  "    "     "    "  "   "   "       "    "  "      yellow.
+       I = info
+       D = debug
+       T = trace
+YYYY = year
+mm   = month
+dd   = day
+HH   = hour (using a 24-hour clock)
+MM   = minute
+SS   = second
+FFF  = fractional portion of the second
+TTTT = thread name (if set) or tid (otherwise)
+PPPP = log target (usually a module path)
+...  = message body
+```
+
+Moonfire NVR names a few important thread types as follows:
+
+*   `main`: during `moonfire-nvr run`, the main thread does initial setup then
+    just waits for the other threads. In other subcommands, it does everything.
+*   `s-CAMERA-TYPE`: there is one of these threads for every recorded stream
+    (up to two per camera, where `TYPE` is `main` or `sub`). These threads read
+    frames from the cameras via RTSP and write them to disk.
+*   `sync-PATH`: there is one of these threads for every sample file directory.
+    These threads call `fsync` to commit sample files to disk, delete old sample
+    files, and flush the database.
+
+You can use the following command to teach [`lnav`](http://lnav.org/) Moonfire
+NVR's log format:
+
+```
+$ lnav -i misc/moonfire_log.json
+```
+
+`lnav` versions prior to 0.9.0 print a (harmless) warning message on startup:
+
+```
+$ lnav -i git/moonfire-nvr/misc/moonfire_log.json
+warning:git/moonfire-nvr/misc/moonfire_log.json:line 2
+warning:  unexpected path --
+warning:    /$schema
+warning:  accepted paths --
+warning:    /(?<format_name>\w+)/  -- The definition of a log file format.
+info: installed: /home/slamb/.lnav/formats/installed/moonfire_log.json
+```
+
+You can avoid this by removing the `$schema` line from `moonfire_log.json`
+and rerunning the `lnav -i` command.
+
+Below are some interesting log lines you may encounter.
+
+### Flushes
+
+During normal operation, Moonfire NVR will periodically flush changes to its
+SQLite3 database. Every flush is logged, as in the following info message:
+
+```
+I20210308 23:14:18.388 sync-/media/14tb/sample moonfire_db::db] Flush 3810 (why: 120 sec after start of 1 minute 14 seconds courtyard-main recording 3/1842086):
+/media/6tb/sample: added 98M 864K 842B in 8 recordings (4/1839795, 7/1503516, 6/1853939, 1/1838087, 2/1852096, 12/1516945, 8/1514942, 10/1506111), deleted 111M 435K 587B in 5 (4/1801170, 4/1801171, 6/1799708, 1/1801528, 2/1815572), GCed 9 recordings (6/1799707, 7/1376577, 4/1801168, 1/1801527, 4/1801167, 4/1801169, 10/1243252, 2/1815571, 12/1418785).
+/media/14tb/sample: added 8M 364K 643B in 3 recordings (3/1842086, 9/1505359, 11/1516695), deleted 0B in 0 (), GCed 0 recordings ().
+```
+
+This log message is packed with debugging information:
+
+*   the date and time: `20210308 23:14:18.388`.
+*   the name of the thread that prompted the flush: `sync-/media/14tb/sample`.
+*   a sequence number: `3810`. This is handy for checking how often Moonfire NVR
+    is flushing.
+*   a reason for the flush: `120 sec after start of 1 minute 14 seconds courtyard-main recording 3/1842086`.
+    This was a regular periodic flush at the `flush_if_sec` for the stream,
+    as described in [install.md](install.md). `3/1842086` is an identifier for
+    the recording, in the form `stream_id/recording_id`. It corresponds to the
+    file `/media/14tb/sample/00000003001c1ba6`. On-disk files are named by
+    a fixed eight hexadecimal digits for the stream id and eight hexadecimal
+    digits for the recording id. You can convert with `printf`:
+    ```
+    $ printf '%08x%08x\n' 3 1842086
+    00000003001c1ba6
+    ```
+*   For each affected sample file directory (`/media/6tb/sample` and
+    `/media/14tb/sample`), a line showing the exact changes included in the
+    flush. There are three kinds of changes:
+
+    *   added recordings–these files are already fully written in the sample
+        file directory and now are being added to the database.
+    *   deleted recordings–these are being removed from the database's
+        `recording` table (and added to the `garbage` table) in preparation
+        for being deleted from the sample file directory. They can no longer
+        be accessed after this flush.
+    *   GCed (garbage-collected) recordings—these have been fully removed from
+        disk and no longer will be referenced in the database at all.
+
+    You can learn more about these in the "Lifecycle of a recording" section
+    of the [recording schema design document](../design/schema.md).
+
+    For added and deleted recordings, the line includes sizes in bytes
+    (`98M 864K 842B` represents 10,3646,026 bytes, or about 99 MiB), numbers
+    of recordings, and the IDs of each recording. For GCed recordings, the
+    sizes are omitted (as this information is not stored).
+
+### Panic errors
+
+Errors like the one below indicate a serious bug in Moonfire NVR. Please
+file a bug if you see one. It's helpful to set the `RUST_BACKTRACE`
+environment variable to include more information.
+
+```
+E20210304 11:09:29.230 main s-peck_west-main] panic at 'src/moonfire-nvr/server/db/writer.rs:750:54': should always be an unindexed sample
+
+(set environment variable RUST_BACKTRACE=1 to see backtraces)"
+```
+
+In this case, a stream thread (one starting with `s-`) panicked. That stream
+won't record again until Moonfire NVR is restarted.
+
+### Slow operations
+
+Warnings like the following indicate that some operation took more than 1
+second to perform. `PT2.070715796S` means about 2 seconds.
+
+It's normal to see these warnings on startup and occasionally while running.
+Frequent occurrences may indicate a performance problem.
+
+```
+W20201129 12:01:21.128 s-driveway-main moonfire_base::clock] opening rtsp://admin:redacted@192.168.5.108/cam/realmonitor?channel=1&subtype=0&unicast=true&proto=Onvif took PT2.070715796S!
+W20201129 12:32:15.870 s-west_side-sub moonfire_base::clock] getting next packet took PT10.158121387S!
+W20201228 12:09:29.050 s-back_east-sub moonfire_base::clock] database lock acquisition took PT8.122452
+W20201228 21:22:32.012 main moonfire_base::clock] database operation took PT39.526386958S!
+W20201228 21:27:11.402 s-driveway-sub moonfire_base::clock] writing 37 bytes took PT20.701894190S!
+```
+
+### Camera stream errors
+
+Warnings like the following indicate that a camera stream was lost due to some
+error and Moonfire NVR will try reconnecting shortly. In this case,
+`End of file` means that the camera ended the stream. This might happen when the
+camera is rebooting or if Moonfire is not consuming packets quickly enough.
+In the latter case, you'll likely see a `getting next packet took PT...S!`
+message as described above.
+
+```
+W20210309 00:28:55.527 s-courtyard-sub moonfire_nvr::streamer] courtyard-sub: sleeping for Duration { secs: 1, nanos: 0 } after error: End of file
+(set environment variable RUST_BACKTRACE=1 to see backtraces)
+```
+
 ## Problems
 
 ### `Error: pts not monotonically increasing; got 26615520 then 26539470`

misc/moonfire_log.json

@@ -0,0 +1,47 @@
+{
+    "$schema": "https://lnav.org/schemas/format-v1.schema.json",
+    "moonfire_log": {
+        "title": "Moonfire Log",
+        "description": "The Moonfire NVR log format.",
+        "timestamp-format": [
+            "%Y%m%d %H:%M:%S.%L",
+            "%m%d %H%M%S.%L"
+        ],
+        "url": "https://github.com/scottlamb/mylog/blob/master/src/lib.rs",
+        "regex": {
+            "std": {
+                "pattern": "^(?<level>[EWIDT])(?<timestamp>\\d{8} \\d{2}:\\d{2}:\\d{2}\\.\\d{3}|\\d{4} \\d{6}\\.\\d{3}) +(?<thread>[^ ]+) (?<module_path>[^ \\]]+)\\] (?<body>(?:.|\\n)*)"
+            }
+        },
+        "level-field": "level",
+        "level": {
+            "error": "E",
+            "warning": "W",
+            "info": "I",
+            "debug": "D",
+            "trace": "T"
+        },
+        "opid-field": "thread",
+        "value": {
+            "thread": {
+                "kind": "string",
+                "identifier": true
+            },
+            "module_path": {
+                "kind": "string",
+                "identifier": true
+            }
+        },
+        "sample": [
+            {
+                "line": "I20210308 21:31:24.255 main moonfire_nvr] Success."
+            },
+            {
+                "line": "I0308 213124.255 main moonfire_nvr] Older style."
+            },
+            {
+                "line": "W20210303 22:20:53.081 s-west_side-main moonfire_base::clock] getting next packet took PT8.153173367S!"
+            }
+        ]
+    }
+}

release.bash

@@ -0,0 +1,51 @@
+#!/bin/bash
+# This file is part of Moonfire NVR, a security camera network video recorder.
+# Copyright (C) 2021 The Moonfire NVR Authors; see AUTHORS and LICENSE.txt.
+# SPDX-License-Identifier: GPL-v3.0-or-later WITH GPL-3.0-linking-exception
+
+# Pushes a release to Docker. See guides/build.md#release-procedure.
+
+set -o errexit
+set -o pipefail
+set -o xtrace
+
+set_latest() {
+    # Our images are manifest lists (for multiple architectures).
+    # "docker tag" won't copy those. The technique below is adopted from here:
+    # https://github.com/docker/buildx/issues/459#issuecomment-750011371
+    local image="$1"
+    local hashes=($(docker manifest inspect "${image}:${version}" |
+                    jq --raw-output '.manifests[].digest'))
+    time docker manifest rm "${image}:latest" || true
+    time docker manifest create \
+        "${image}:latest" \
+        "${hashes[@]/#/${image}@}"
+    time docker manifest push "${image}:latest"
+}
+
+build_and_push() {
+    local image="$1"
+    local target="$2"
+    time docker buildx build \
+        --push \
+        --tag="${image}:${version}" \
+        --target="${target}" \
+        --platform=linux/amd64,linux/arm64/v8,linux/arm/v7 \
+        -f docker/Dockerfile .
+}
+
+version="$(git describe --dirty)"
+if [[ ! "${version}" =~ ^v[0-9]+\.[0-9]+\.[0-9]+$ ]]; then
+    echo "Expected a vX.Y.Z version tag, got ${version}." >&2
+    exit 1
+fi
+
+if [[ -n "$(git status --porcelain)" ]]; then
+    echo "git status says there's extra stuff in this directory." >&2
+    exit 1
+fi
+
+build_and_push scottlamb/moonfire-nvr deploy
+build_and_push scottlamb/moonfire-dev dev
+set_latest scottlamb/moonfire-nvr
+set_latest scottlamb/moonfire-dev

server/Cargo.lock

@@ -1204,7 +1204,7 @@ dependencies = [
 [[package]]
 name = "moonfire-ffmpeg"
 version = "0.0.1"
-source = "git+https://github.com/scottlamb/moonfire-ffmpeg#d008cebe93e12dcdeeb341cc39b60ca6daf07226"
+source = "git+https://github.com/scottlamb/moonfire-ffmpeg#16d3b7c951a5d93900d3a6731f1ad79a610ad69a"
 dependencies = [
  "cc",
  "libc",
@@ -1215,7 +1215,7 @@ dependencies = [
 
 [[package]]
 name = "moonfire-nvr"
-version = "0.6.1"
+version = "0.6.2"
 dependencies = [
  "base64",
  "blake3",
@@ -1274,9 +1274,10 @@ dependencies = [
 [[package]]
 name = "mylog"
 version = "0.1.0"
-source = "git+https://github.com/scottlamb/mylog#45cdec74e11b05d02b55d49cfb1a8391e0f281a5"
+source = "git+https://github.com/scottlamb/mylog#2b1085cfb3bd0b1f2afe7d8085045d81858c0050"
 dependencies = [
  "chrono",
+ "libc",
  "log",
  "parking_lot",
 ]

server/Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "moonfire-nvr"
-version = "0.6.1"
+version = "0.6.2"
 authors = ["Scott Lamb <slamb@slamb.org>"]
 edition = "2018"
 license-file = "../LICENSE.txt"

server/base/error.rs

@@ -36,6 +36,15 @@ impl Error {
     pub fn compat(self) -> failure::Compat<Context<ErrorKind>> {
         self.inner.compat()
     }
+
+    pub fn map<F>(self, op: F) -> Self
+    where
+        F: FnOnce(ErrorKind) -> ErrorKind,
+    {
+        Self {
+            inner: self.inner.map(op),
+        }
+    }
 }
 
 impl Fail for Error {
@@ -149,10 +158,10 @@ where
 #[macro_export]
 macro_rules! bail_t {
     ($t:ident, $e:expr) => {
-        return Err(failure::err_msg($e).context($crate::ErrorKind::$t).into());
+        return Err($crate::Error::from(failure::err_msg($e).context($crate::ErrorKind::$t)).into());
     };
     ($t:ident, $fmt:expr, $($arg:tt)+) => {
-        return Err(failure::err_msg(format!($fmt, $($arg)+)).context($crate::ErrorKind::$t).into());
+        return Err($crate::Error::from(failure::err_msg(format!($fmt, $($arg)+)).context($crate::ErrorKind::$t)).into());
     };
 }
 

server/db/auth.rs

@@ -3,7 +3,7 @@
 // SPDX-License-Identifier: GPL-v3.0-or-later WITH GPL-3.0-linking-exception.
 
 use crate::schema::Permissions;
-use base::strutil;
+use base::{bail_t, format_err_t, strutil, ErrorKind, ResultExt};
 use failure::{bail, format_err, Error};
 use fnv::FnvHashMap;
 use lazy_static::lazy_static;
@@ -678,23 +678,31 @@ impl State {
         conn: &Connection,
         req: Request,
         hash: &SessionHash,
-    ) -> Result<(&Session, &User), Error> {
+    ) -> Result<(&Session, &User), base::Error> {
         let s = match self.sessions.entry(*hash) {
             ::std::collections::hash_map::Entry::Occupied(e) => e.into_mut(),
-            ::std::collections::hash_map::Entry::Vacant(e) => e.insert(lookup_session(conn, hash)?),
+            ::std::collections::hash_map::Entry::Vacant(e) => {
+                let s = lookup_session(conn, hash).map_err(|e| {
+                    e.map(|k| match k {
+                        ErrorKind::NotFound => ErrorKind::Unauthenticated,
+                        e => e,
+                    })
+                })?;
+                e.insert(s)
+            }
         };
         let u = match self.users_by_id.get(&s.user_id) {
-            None => bail!("session references nonexistent user!"),
+            None => bail_t!(Internal, "session references nonexistent user!"),
             Some(u) => u,
         };
         if let Some(r) = s.revocation_reason {
-            bail!("session is no longer valid (reason={})", r);
+            bail_t!(Unauthenticated, "session is no longer valid (reason={})", r);
         }
         s.last_use = req;
         s.use_count += 1;
         s.dirty = true;
         if u.disabled() {
-            bail!("user {:?} is disabled", &u.username);
+            bail_t!(Unauthenticated, "user {:?} is disabled", &u.username);
         }
         Ok((s, u))
     }
@@ -811,8 +819,9 @@ impl State {
     }
 }
 
-fn lookup_session(conn: &Connection, hash: &SessionHash) -> Result<Session, Error> {
+fn lookup_session(conn: &Connection, hash: &SessionHash) -> Result<Session, base::Error> {
-    let mut stmt = conn.prepare_cached(
+    let mut stmt = conn
+        .prepare_cached(
             r#"
         select
             user_id,
@@ -839,39 +848,52 @@ fn lookup_session(conn: &Connection, hash: &SessionHash) -> Result<Session, Erro
         where
             session_id_hash = ?
         "#,
-    )?;
+        )
-    let mut rows = stmt.query(params![&hash.0[..]])?;
+        .err_kind(ErrorKind::Internal)?;
-    let row = rows.next()?.ok_or_else(|| format_err!("no such session"))?;
+    let mut rows = stmt
-    let creation_addr: FromSqlIpAddr = row.get(8)?;
+        .query(params![&hash.0[..]])
-    let revocation_addr: FromSqlIpAddr = row.get(11)?;
+        .err_kind(ErrorKind::Internal)?;
-    let last_use_addr: FromSqlIpAddr = row.get(16)?;
+    let row = rows
+        .next()
+        .err_kind(ErrorKind::Internal)?
+        .ok_or_else(|| format_err_t!(NotFound, "no such session"))?;
+    let creation_addr: FromSqlIpAddr = row.get(8).err_kind(ErrorKind::Internal)?;
+    let revocation_addr: FromSqlIpAddr = row.get(11).err_kind(ErrorKind::Internal)?;
+    let last_use_addr: FromSqlIpAddr = row.get(16).err_kind(ErrorKind::Internal)?;
     let mut permissions = Permissions::new();
-    permissions.merge_from_bytes(row.get_raw_checked(18)?.as_blob()?)?;
+    permissions
+        .merge_from_bytes(
+            row.get_raw_checked(18)
+                .err_kind(ErrorKind::Internal)?
+                .as_blob()
+                .err_kind(ErrorKind::Internal)?,
+        )
+        .err_kind(ErrorKind::Internal)?;
     Ok(Session {
-        user_id: row.get(0)?,
+        user_id: row.get(0).err_kind(ErrorKind::Internal)?,
-        seed: row.get(1)?,
+        seed: row.get(1).err_kind(ErrorKind::Internal)?,
-        flags: row.get(2)?,
+        flags: row.get(2).err_kind(ErrorKind::Internal)?,
-        domain: row.get(3)?,
+        domain: row.get(3).err_kind(ErrorKind::Internal)?,
-        description: row.get(4)?,
+        description: row.get(4).err_kind(ErrorKind::Internal)?,
-        creation_password_id: row.get(5)?,
+        creation_password_id: row.get(5).err_kind(ErrorKind::Internal)?,
         creation: Request {
-            when_sec: row.get(6)?,
+            when_sec: row.get(6).err_kind(ErrorKind::Internal)?,
-            user_agent: row.get(7)?,
+            user_agent: row.get(7).err_kind(ErrorKind::Internal)?,
             addr: creation_addr.0,
         },
         revocation: Request {
-            when_sec: row.get(9)?,
+            when_sec: row.get(9).err_kind(ErrorKind::Internal)?,
-            user_agent: row.get(10)?,
+            user_agent: row.get(10).err_kind(ErrorKind::Internal)?,
             addr: revocation_addr.0,
         },
-        revocation_reason: row.get(12)?,
+        revocation_reason: row.get(12).err_kind(ErrorKind::Internal)?,
-        revocation_reason_detail: row.get(13)?,
+        revocation_reason_detail: row.get(13).err_kind(ErrorKind::Internal)?,
         last_use: Request {
-            when_sec: row.get(14)?,
+            when_sec: row.get(14).err_kind(ErrorKind::Internal)?,
-            user_agent: row.get(15)?,
+            user_agent: row.get(15).err_kind(ErrorKind::Internal)?,
             addr: last_use_addr.0,
         },
-        use_count: row.get(17)?,
+        use_count: row.get(17).err_kind(ErrorKind::Internal)?,
         dirty: false,
         permissions,
     })
@@ -969,7 +991,10 @@ mod tests {
         let e = state
             .authenticate_session(&conn, req.clone(), &sid.hash())
             .unwrap_err();
-        assert_eq!(format!("{}", e), "session is no longer valid (reason=1)");
+        assert_eq!(
+            format!("{}", e),
+            "Unauthenticated: session is no longer valid (reason=1)"
+        );
 
         // Everything should persist across reload.
         drop(state);
@@ -977,7 +1002,10 @@ mod tests {
         let e = state
             .authenticate_session(&conn, req, &sid.hash())
             .unwrap_err();
-        assert_eq!(format!("{}", e), "session is no longer valid (reason=1)");
+        assert_eq!(
+            format!("{}", e),
+            "Unauthenticated: session is no longer valid (reason=1)"
+        );
     }
 
     #[test]
@@ -1028,7 +1056,10 @@ mod tests {
         let e = state
             .authenticate_session(&conn, req, &sid.hash())
             .unwrap_err();
-        assert_eq!(format!("{}", e), "session is no longer valid (reason=1)");
+        assert_eq!(
+            format!("{}", e),
+            "Unauthenticated: session is no longer valid (reason=1)"
+        );
     }
 
     #[test]
@@ -1159,7 +1190,10 @@ mod tests {
         let e = state
             .authenticate_session(&conn, req.clone(), &sid.hash())
             .unwrap_err();
-        assert_eq!(format!("{}", e), "user \"slamb\" is disabled");
+        assert_eq!(
+            format!("{}", e),
+            "Unauthenticated: user \"slamb\" is disabled"
+        );
 
         // The user should still be disabled after reload.
         drop(state);
@@ -1167,7 +1201,10 @@ mod tests {
         let e = state
             .authenticate_session(&conn, req, &sid.hash())
             .unwrap_err();
-        assert_eq!(format!("{}", e), "user \"slamb\" is disabled");
+        assert_eq!(
+            format!("{}", e),
+            "Unauthenticated: user \"slamb\" is disabled"
+        );
     }
 
     #[test]
@@ -1206,7 +1243,7 @@ mod tests {
         let e = state
             .authenticate_session(&conn, req.clone(), &sid.hash())
             .unwrap_err();
-        assert_eq!(format!("{}", e), "no such session");
+        assert_eq!(format!("{}", e), "Unauthenticated: no such session");
 
         // The user should still be deleted after reload.
         drop(state);
@@ -1215,7 +1252,7 @@ mod tests {
         let e = state
             .authenticate_session(&conn, req.clone(), &sid.hash())
             .unwrap_err();
-        assert_eq!(format!("{}", e), "no such session");
+        assert_eq!(format!("{}", e), "Unauthenticated: no such session");
     }
 
     #[test]

server/db/check.rs

@@ -171,9 +171,9 @@ pub fn run(conn: &mut rusqlite::Connection, opts: &Options) -> Result<i32, Error
         let tx = conn.transaction()?;
         if !ctx.rows_to_delete.is_empty() {
             info!("Deleting {} recording rows", ctx.rows_to_delete.len());
-            let mut d1 = tx.prepare("delete from recording where composite_id = ?")?;
+            let mut d1 = tx.prepare("delete from recording_playback where composite_id = ?")?;
-            let mut d2 = tx.prepare("delete from recording_playback where composite_id = ?")?;
+            let mut d2 = tx.prepare("delete from recording_integrity where composite_id = ?")?;
-            let mut d3 = tx.prepare("delete from recording_integrity where composite_id = ?")?;
+            let mut d3 = tx.prepare("delete from recording where composite_id = ?")?;
             for &id in &ctx.rows_to_delete {
                 d1.execute(params![id.0])?;
                 d2.execute(params![id.0])?;

server/db/db.rs

@@ -2173,7 +2173,7 @@ impl LockedDatabase {
         &mut self,
         req: auth::Request,
         sid: &auth::SessionHash,
-    ) -> Result<(&auth::Session, &User), Error> {
+    ) -> Result<(&auth::Session, &User), base::Error> {
         self.auth.authenticate_session(&self.conn, req, sid)
     }
 

server/db/writer.rs

@@ -709,7 +709,7 @@ impl<'a, C: Clocks + Clone, D: DirWriter> Writer<'a, C, D> {
         // We must restore it on all success or error paths.
 
         if let Some(unindexed) = w.unindexed_sample.take() {
-            let duration = i32::try_from(pts_90k - i64::from(unindexed.pts_90k))?;
+            let duration = pts_90k - unindexed.pts_90k;
             if duration <= 0 {
                 w.unindexed_sample = Some(unindexed); // restore invariant.
                 bail!(
@@ -718,6 +718,17 @@ impl<'a, C: Clocks + Clone, D: DirWriter> Writer<'a, C, D> {
                     pts_90k
                 );
             }
+            let duration = match i32::try_from(duration) {
+                Ok(d) => d,
+                Err(_) => {
+                    w.unindexed_sample = Some(unindexed); // restore invariant.
+                    bail!(
+                        "excessive pts jump from {} to {}",
+                        unindexed.pts_90k,
+                        pts_90k
+                    )
+                }
+            };
             if let Err(e) = w.add_sample(
                 duration,
                 unindexed.len,
@@ -1039,7 +1050,7 @@ mod tests {
         drop(tdb.syncer_channel);
         tdb.syncer_join.join().unwrap();
 
-        // Start a mocker syncer.
+        // Start a mock syncer.
         let dir = MockDir::new();
         let syncer = super::Syncer {
             dir_id: *tdb
@@ -1080,6 +1091,59 @@ mod tests {
         nix::Error::Sys(nix::errno::Errno::EIO)
     }
 
+    #[test]
+    fn excessive_pts_jump() {
+        testutil::init();
+        let mut h = new_harness(0);
+        let video_sample_entry_id =
+            h.db.lock()
+                .insert_video_sample_entry(VideoSampleEntryToInsert {
+                    width: 1920,
+                    height: 1080,
+                    pasp_h_spacing: 1,
+                    pasp_v_spacing: 1,
+                    data: [0u8; 100].to_vec(),
+                    rfc6381_codec: "avc1.000000".to_owned(),
+                })
+                .unwrap();
+        let mut w = Writer::new(
+            &h.dir,
+            &h.db,
+            &h.channel,
+            testutil::TEST_STREAM_ID,
+            video_sample_entry_id,
+        );
+        h.dir.expect(MockDirAction::Create(
+            CompositeId::new(1, 0),
+            Box::new(|_id| Err(nix_eio())),
+        ));
+        let f = MockFile::new();
+        h.dir.expect(MockDirAction::Create(
+            CompositeId::new(1, 0),
+            Box::new({
+                let f = f.clone();
+                move |_id| Ok(f.clone())
+            }),
+        ));
+        f.expect(MockFileAction::Write(Box::new(|_| Ok(1))));
+        f.expect(MockFileAction::SyncAll(Box::new(|| Ok(()))));
+        w.write(b"1", recording::Time(1), 0, true).unwrap();
+
+        let e = w
+            .write(b"2", recording::Time(2), i32::max_value() as i64 + 1, true)
+            .unwrap_err();
+        assert!(e.to_string().contains("excessive pts jump"));
+        h.dir.expect(MockDirAction::Sync(Box::new(|| Ok(()))));
+        drop(w);
+        assert!(h.syncer.iter(&h.syncer_rcv)); // AsyncSave
+        assert_eq!(h.syncer.planned_flushes.len(), 1);
+        assert!(h.syncer.iter(&h.syncer_rcv)); // planned flush
+        assert_eq!(h.syncer.planned_flushes.len(), 0);
+        assert!(h.syncer.iter(&h.syncer_rcv)); // DatabaseFlushed
+        f.ensure_done();
+        h.dir.ensure_done();
+    }
+
     /// Tests the database flushing while a syncer is still processing a previous flush event.
     #[test]
     fn double_flush() {

server/src/main.rs

@@ -1,10 +1,11 @@
 // This file is part of Moonfire NVR, a security camera network video recorder.
-// Copyright (C) 2020 The Moonfire NVR Authors; see AUTHORS and LICENSE.txt.
+// Copyright (C) 2021 The Moonfire NVR Authors; see AUTHORS and LICENSE.txt.
 // SPDX-License-Identifier: GPL-v3.0-or-later WITH GPL-3.0-linking-exception.
 
 #![cfg_attr(all(feature = "nightly", test), feature(test))]
 
 use log::{debug, error};
+use std::fmt::Write;
 use std::str::FromStr;
 use structopt::StructOpt;
 
@@ -107,6 +108,34 @@ impl Args {
     }
 }
 
+/// Custom panic hook that logs instead of directly writing to stderr.
+///
+/// This means it includes a timestamp and is more recognizable as a serious
+/// error (including console color coding by default, a format `lnav` will
+/// recognize, etc.).
+fn panic_hook(p: &std::panic::PanicInfo) {
+    let mut msg;
+    if let Some(l) = p.location() {
+        msg = format!("panic at '{}'", l);
+    } else {
+        msg = "panic".to_owned();
+    }
+    if let Some(s) = p.payload().downcast_ref::<&str>() {
+        write!(&mut msg, ": {}", s).unwrap();
+    }
+    let b = failure::Backtrace::new();
+    if b.is_empty() {
+        write!(
+            &mut msg,
+            "\n\n(set environment variable RUST_BACKTRACE=1 to see backtraces)"
+        )
+        .unwrap();
+    } else {
+        write!(&mut msg, "\n\nBacktrace:\n{}", b).unwrap();
+    }
+    error!("{}", msg);
+}
+
 fn main() {
     let args = Args::from_args();
     let mut h = mylog::Builder::new()
@@ -116,10 +145,18 @@ fn main() {
                 .and_then(|s| mylog::Format::from_str(&s))
                 .unwrap_or(mylog::Format::Google),
         )
+        .set_color(
+            ::std::env::var("MOONFIRE_COLOR")
+                .map_err(|_| ())
+                .and_then(|s| mylog::ColorMode::from_str(&s))
+                .unwrap_or(mylog::ColorMode::Auto),
+        )
         .set_spec(&::std::env::var("MOONFIRE_LOG").unwrap_or("info".to_owned()))
         .build();
     h.clone().install().unwrap();
 
+    std::panic::set_hook(Box::new(&panic_hook));
+
     let r = {
         let _a = h.async_scope();
         args.run()

server/src/web.rs

@@ -5,8 +5,8 @@
 use crate::body::Body;
 use crate::json;
 use crate::mp4;
-use base::clock::Clocks;
 use base::{bail_t, ErrorKind};
+use base::{clock::Clocks, format_err_t};
 use bytes::{BufMut, BytesMut};
 use core::borrow::Borrow;
 use core::str::FromStr;
@@ -35,6 +35,26 @@ use tokio_tungstenite::tungstenite;
 use url::form_urlencoded;
 use uuid::Uuid;
 
+/// An HTTP error response.
+/// This is a thin wrapper over the hyper response type; it doesn't even verify
+/// that the response actually uses a non-2xx status code. Its purpose is to
+/// allow automatic conversion from `base::Error`. Rust's orphan rule prevents
+/// this crate from defining a direct conversion from `base::Error` to
+/// `hyper::Response`.
+struct HttpError(Response<Body>);
+
+impl From<Response<Body>> for HttpError {
+    fn from(response: Response<Body>) -> Self {
+        HttpError(response)
+    }
+}
+
+impl From<base::Error> for HttpError {
+    fn from(err: base::Error) -> Self {
+        HttpError(from_base_error(err))
+    }
+}
+
 #[derive(Debug, Eq, PartialEq)]
 enum Path {
     TopLevel,                                         // "/api/"
@@ -141,23 +161,28 @@ fn plain_response<B: Into<Body>>(status: http::StatusCode, body: B) -> Response<
         .expect("hardcoded head should be valid")
 }
 
-fn not_found<B: Into<Body>>(body: B) -> Response<Body> {
+fn not_found<B: Into<Body>>(body: B) -> HttpError {
-    plain_response(StatusCode::NOT_FOUND, body)
+    HttpError(plain_response(StatusCode::NOT_FOUND, body))
 }
 
-fn bad_req<B: Into<Body>>(body: B) -> Response<Body> {
+fn bad_req<B: Into<Body>>(body: B) -> HttpError {
-    plain_response(StatusCode::BAD_REQUEST, body)
+    HttpError(plain_response(StatusCode::BAD_REQUEST, body))
 }
 
-fn internal_server_err<E: Into<Error>>(err: E) -> Response<Body> {
+fn internal_server_err<E: Into<Error>>(err: E) -> HttpError {
-    plain_response(StatusCode::INTERNAL_SERVER_ERROR, err.into().to_string())
+    HttpError(plain_response(
+        StatusCode::INTERNAL_SERVER_ERROR,
+        err.into().to_string(),
+    ))
 }
 
 fn from_base_error(err: base::Error) -> Response<Body> {
+    use ErrorKind::*;
     let status_code = match err.kind() {
-        ErrorKind::PermissionDenied | ErrorKind::Unauthenticated => StatusCode::UNAUTHORIZED,
+        Unauthenticated => StatusCode::UNAUTHORIZED,
-        ErrorKind::InvalidArgument => StatusCode::BAD_REQUEST,
+        PermissionDenied => StatusCode::FORBIDDEN,
-        ErrorKind::NotFound => StatusCode::NOT_FOUND,
+        InvalidArgument | FailedPrecondition => StatusCode::BAD_REQUEST,
+        NotFound => StatusCode::NOT_FOUND,
         _ => StatusCode::INTERNAL_SERVER_ERROR,
     };
     plain_response(status_code, err.to_string())
@@ -232,7 +257,7 @@ struct Caller {
     session: Option<json::Session>,
 }
 
-type ResponseResult = Result<Response<Body>, Response<Body>>;
+type ResponseResult = Result<Response<Body>, HttpError>;
 
 fn serve_json<T: serde::ser::Serialize>(req: &Request<hyper::Body>, out: &T) -> ResponseResult {
     let (mut resp, writer) = http_serve::streaming_body(&req).build();
@@ -277,12 +302,9 @@ fn extract_sid(req: &Request<hyper::Body>) -> Option<auth::RawSessionId> {
 /// This returns the request body as bytes rather than performing
 /// deserialization. Keeping the bytes allows the caller to use a `Deserialize`
 /// that borrows from the bytes.
-async fn extract_json_body(req: &mut Request<hyper::Body>) -> Result<Bytes, Response<Body>> {
+async fn extract_json_body(req: &mut Request<hyper::Body>) -> Result<Bytes, HttpError> {
     if *req.method() != http::method::Method::POST {
-        return Err(plain_response(
+        return Err(plain_response(StatusCode::METHOD_NOT_ALLOWED, "POST expected").into());
-            StatusCode::METHOD_NOT_ALLOWED,
-            "POST expected",
-        ));
     }
     let correct_mime_type = match req.headers().get(header::CONTENT_TYPE) {
         Some(t) if t == "application/json" => true,
@@ -376,10 +398,7 @@ impl Service {
         stream_type: db::StreamType,
     ) -> ResponseResult {
         if !caller.permissions.view_video {
-            return Err(plain_response(
+            bail_t!(PermissionDenied, "view_video required");
-                StatusCode::UNAUTHORIZED,
-                "view_video required",
-            ));
         }
 
         let stream_id;
@@ -389,10 +408,10 @@ impl Service {
             let mut db = self.db.lock();
             open_id = match db.open {
                 None => {
-                    return Err(plain_response(
+                    bail_t!(
-                        StatusCode::PRECONDITION_FAILED,
+                        FailedPrecondition,
-                        "database is read-only; there are no live streams",
+                        "database is read-only; there are no live streams"
-                    ))
+                    );
                 }
                 Some(o) => o.id,
             };
@@ -400,10 +419,7 @@ impl Service {
                 plain_response(StatusCode::NOT_FOUND, format!("no such camera {}", uuid))
             })?;
             stream_id = camera.streams[stream_type.index()].ok_or_else(|| {
-                plain_response(
+                format_err_t!(NotFound, "no such stream {}/{}", uuid, stream_type)
-                    StatusCode::NOT_FOUND,
-                    format!("no such stream {}/{}", uuid, stream_type),
-                )
             })?;
             db.watch_live(
                 stream_id,
@@ -525,10 +541,15 @@ impl Service {
             _ => Err(plain_response(
                 StatusCode::METHOD_NOT_ALLOWED,
                 "POST, GET, or HEAD expected",
-            )),
+            )
+            .into()),
         }
     }
 
+    /// Serves an HTTP request.
+    /// Note that the `serve` wrapper handles responses the same whether they
+    /// are `Ok` or `Err`. But returning `Err` here with the `?` operator is
+    /// convenient for error paths.
     async fn serve_inner(
         self: Arc<Self>,
         req: Request<::hyper::Body>,
@@ -586,6 +607,12 @@ impl Service {
         Ok(response)
     }
 
+    /// Serves an HTTP request.
+    /// An error return from this method causes hyper to abruptly drop the
+    /// HTTP connection rather than respond. That's not terribly useful, so this
+    /// method always returns `Ok`. It delegates to a `serve_inner` which is
+    /// allowed to generate `Err` results with the `?` operator, but returns
+    /// them to hyper as `Ok` results.
     pub async fn serve(
         self: Arc<Self>,
         req: Request<::hyper::Body>,
@@ -600,7 +627,10 @@ impl Service {
             Ok(c) => c,
             Err(e) => return Ok(from_base_error(e)),
         };
-        Ok(self.serve_inner(req, p, caller).await.unwrap_or_else(|e| e))
+        Ok(self
+            .serve_inner(req, p, caller)
+            .await
+            .unwrap_or_else(|e| e.0))
     }
 
     fn top_level(&self, req: &Request<::hyper::Body>, caller: Caller) -> ResponseResult {
@@ -619,10 +649,7 @@ impl Service {
 
         if camera_configs {
             if !caller.permissions.read_camera_configs {
-                return Err(plain_response(
+                bail_t!(PermissionDenied, "read_camera_configs required");
-                    StatusCode::UNAUTHORIZED,
-                    "read_camera_configs required",
-                ));
             }
         }
 
@@ -756,10 +783,7 @@ impl Service {
         debug: bool,
     ) -> ResponseResult {
         if !caller.permissions.view_video {
-            return Err(plain_response(
+            bail_t!(PermissionDenied, "view_video required");
-                StatusCode::UNAUTHORIZED,
-                "view_video required",
-            ));
         }
         let (stream_id, camera_name);
         {
@@ -884,10 +908,11 @@ impl Service {
                         };
                         if let Some(end) = s.end_time {
                             if end > cur_off {
-                                return Err(plain_response(
+                                bail_t!(
-                                    StatusCode::BAD_REQUEST,
+                                    InvalidArgument,
-                                    format!("end time {} is beyond specified recordings", end),
+                                    "end time {} is beyond specified recordings",
-                                ));
+                                    end
+                                );
                             }
                         }
                     }
@@ -1019,6 +1044,10 @@ impl Service {
         ))
     }
 
+    /// Returns true iff the client is connected over `https`.
+    /// Moonfire NVR currently doesn't directly serve `https`, but it supports
+    /// proxies which set the `X-Forwarded-Proto` header. See `guide/secure.md`
+    /// for more information.
     fn is_secure(&self, req: &Request<::hyper::Body>) -> bool {
         self.trust_forward_hdrs
             && req
@@ -1124,10 +1153,7 @@ impl Service {
 
     async fn post_signals(&self, mut req: Request<hyper::Body>, caller: Caller) -> ResponseResult {
         if !caller.permissions.update_signals {
-            return Err(plain_response(
+            bail_t!(PermissionDenied, "update_signals required");
-                StatusCode::UNAUTHORIZED,
-                "update_signals required",
-            ));
         }
         let r = extract_json_body(&mut req).await?;
         let r: json::PostSignalsRequest =
@@ -1180,6 +1206,18 @@ impl Service {
         serve_json(req, &signals)
     }
 
+    /// Authenticates the session (if any) and returns a Caller.
+    ///
+    /// If there's no session,
+    /// 1.  if `allow_unauthenticated_permissions` is configured, returns okay
+    ///     with those permissions.
+    /// 2.  if the caller specifies `unauth_path`, returns okay with no
+    ///     permissions.
+    /// 3.  returns `Unauthenticated` error otherwise.
+    ///
+    /// Does no authorization. That is, this doesn't check that the returned
+    /// permissions are sufficient for whatever operation the caller is
+    /// performing.
     fn authenticate(
         &self,
         req: &Request<hyper::Body>,
@@ -1188,22 +1226,28 @@ impl Service {
         if let Some(sid) = extract_sid(req) {
             let authreq = self.authreq(req);
 
-            // TODO: real error handling! this assumes all errors are due to lack of
+            match self
-            // authentication, when they could be logic errors in SQL or such.
-            if let Ok((s, u)) = self
                 .db
                 .lock()
                 .authenticate_session(authreq.clone(), &sid.hash())
             {
+                Ok((s, u)) => {
                     return Ok(Caller {
                         permissions: s.permissions.clone(),
                         session: Some(json::Session {
                             username: u.username.clone(),
                             csrf: s.csrf(),
                         }),
-                });
+                    })
                 }
-            info!("authenticate_session failed");
+                Err(e) if e.kind() == base::ErrorKind::Unauthenticated => {
+                    // Log the specific reason this session is unauthenticated.
+                    // Don't let the API client see it, as it may have a
+                    // revocation reason that isn't for their eyes.
+                    warn!("Session authentication failed: {:?}", &e);
+                }
+                Err(e) => return Err(e),
+            };
         }
 
         if let Some(s) = self.allow_unauthenticated_permissions.as_ref() {