backup: show errors at top of email notification

The helper is just bytes->str conversion with errors=backslashreplace,
which we can use for more than just paths.

backup.py

@@ -23,8 +23,8 @@ import yaml
 import wcmatch.glob # type: ignore
 import humanfriendly # type: ignore
 
-def pstr(path: bytes) -> str:
-    return path.decode(errors='backslashreplace')
+def b2s(raw: bytes) -> str:
+    return raw.decode(errors='backslashreplace')
 
 def format_size(n: int) -> str:
     return humanfriendly.format_size(n, keep_width=True, binary=True)
@@ -111,28 +111,31 @@ class Backup:
         self.dry_run = dry_run
         self.root_seen: typing.Dict[bytes, bool] = {}
 
-        # Saved log messages
+        # Saved log messages (which includes borg output)
         self.logs: typing.List[typing.Tuple[str, str]] = []
 
-        # All captured borg output
-        self.captured_output: typing.List[bytes] = []
-
     def out(self, path: bytes):
         self.outfile.write(path + (b'\n' if self.dry_run else b'\0'))
 
     def log(self, letter: str, msg: str, bold: bool=False):
-        colors = { 'E': 31, 'W': 33, 'I': 36 };
+        colors = {
+            'E': 31, # red: error
+            'W': 33, # yellow: warning
+            'N': 34, # blue: notice, a weaker warning (no email generated)
+            'I': 36, # cyan: info, backup.py script output
+            'O': 37, # white: regular output from borg
+        };
         c = colors[letter] if letter in colors else 0
         b = "" if bold else "\033[22m"
-        sys.stderr.write(f"\033[1;{c}m{letter}:{b} {msg}\033[0m\n")
-        sys.stderr.flush()
+        sys.stdout.write(f"\033[1;{c}m{letter}:{b} {msg}\033[0m\n")
+        sys.stdout.flush()
         self.logs.append((letter, msg))
 
     def run(self, outfile: typing.IO[bytes]):
         self.outfile = outfile
         for root in self.config.roots:
             if root in self.root_seen:
-                self.log('I', f"ignoring root, already seen: {pstr(root)}")
+                self.log('I', f"ignoring root, already seen: {b2s(root)}")
                 continue
 
             try:
@@ -140,13 +143,13 @@ class Backup:
                 if not stat.S_ISDIR(st.st_mode):
                     raise NotADirectoryError
             except FileNotFoundError:
-                self.log('E', f"root does not exist: {pstr(root)}")
+                self.log('E', f"root does not exist: {b2s(root)}")
                 continue
             except NotADirectoryError:
-                self.log('E', f"root is not a directory: {pstr(root)}")
+                self.log('E', f"root is not a directory: {b2s(root)}")
                 continue
 
-            self.log('I', f"processing root {pstr(root)}")
+            self.log('I', f"processing root {b2s(root)}")
             self.scan(root)
 
     def scan(self, path: bytes, parent_st: os.stat_result=None):
@@ -199,7 +202,7 @@ class Backup:
             force = self.config.match_re(self.config.unexclude, decorated_path)
             if exclude_reason and not force:
                 self.log(exclude_reason[0],
-                         f"{exclude_reason[1]}: {pstr(path)}")
+                         f"{exclude_reason[1]}: {b2s(path)}")
                 return
 
             # Print path for Borg
@@ -221,7 +224,7 @@ class Backup:
                         with open(path + b'/CACHEDIR.TAG', 'rb') as f:
                             if f.read(len(tag)) == tag:
                                 self.log(
-                                    'I', f"skipping, cache dir: {pstr(path)}")
+                                    'I', f"skipping, cache dir: {b2s(path)}")
                                 return
                     except:
                         pass
@@ -235,7 +238,7 @@ class Backup:
                 IsADirectoryError,
                 NotADirectoryError,
                 PermissionError) as e:
-            self.log('E', f"can't read {pstr(path)}: {str(e)}")
+            self.log('E', f"can't read {b2s(path)}: {str(e)}")
             return
 
     def run_borg(self, argv: typing.List[str],
@@ -251,6 +254,9 @@ class Backup:
         if borg.stdin is None:
             raise Exception("no pipe")
 
+        # Count warnings and errors from Borg, so we can interpret its
+        # error codes correctly (e.g. ignoring exit codes if warnings
+        # were all harmless).
         borg_saw_warnings = 0
         borg_saw_errors = 0
 
@@ -262,24 +268,30 @@ class Backup:
             for line in fh:
                 try:
                     data = json.loads(line)
+
                     if data['type'] == 'log_message':
-                        # Count warnings and errors, but ignore some.
                         changed_msg = "file changed while we backed it up"
                         if data['levelname'] == 'WARNING':
-                            prefix = "warning: "
-                            if changed_msg not in data['message']:
+                            if changed_msg in data['message']:
+                                # harmless; don't count as a Borg warning
+                                outlevel = 'N'
+                            else:
                                 borg_saw_warnings += 1
+                                outlevel = 'W'
+                            output = "warning: "
                         elif data['levelname'] not in ('DEBUG', 'INFO'):
-                            prefix = "error: "
                             borg_saw_errors += 1
+                            outlevel = 'E'
+                            output = "error: "
                         else:
-                            prefix = ""
-
-                        line = (prefix + data['message'] + '\n').encode()
+                            outlevel = 'O'
+                            output = ""
+                        output += data['message']
 
                     elif (data['type'] == 'progress_message'
                           and 'message' in data):
-                        line = (data['message'] + '\n').encode()
+                        outlevel = 'O'
+                        output = data['message']
 
                     elif data['type'] == 'archive_progress':
                         now = time.time()
@@ -287,12 +299,12 @@ class Backup:
                             last_progress = now
                             def size(short: str, full: str) -> str:
                                 return f" {short}={format_size(data[full])}"
-                            line = (f"progress:" +
-                                    f" files={data['nfiles']}" +
-                                    size('orig', 'original_size') +
-                                    size('comp', 'compressed_size') +
-                                    size('dedup', 'deduplicated_size') +
-                                    "\n").encode()
+                            outlevel = 'O'
+                            output = (f"progress:" +
+                                      f" files={data['nfiles']}" +
+                                      size('orig', 'original_size') +
+                                      size('comp', 'compressed_size') +
+                                      size('dedup', 'deduplicated_size'))
                         else:
                             continue
                     else:
@@ -300,10 +312,9 @@ class Backup:
                         continue
                 except Exception as e:
                     # on error, print raw line with exception
-                    line = f"[exception: {str(e)} ]".encode() + line
-                sys.stdout.buffer.write(line)
-                sys.stdout.flush()
-                self.captured_output.append(line)
+                    outlevel = 'E'
+                    output = f"[exception: {str(e)}] " + b2s(line).rstrip()
+                self.log(outlevel, output)
             fh.close()
         def _reader_thread(fh):
             try:
@@ -322,8 +333,7 @@ class Backup:
                 time.sleep(1)
                 stdin_writer(borg.stdin)
         except BrokenPipeError:
-            sys.stderr.write(f"broken pipe\n")
-            sys.stderr.flush()
+            self.log('E', "<broken pipe>")
         finally:
             try:
                 borg.stdin.close()
@@ -460,19 +470,24 @@ def main(argv: typing.List[str]):
         if email and not args.dry_run:
             backup.log('I', f"sending error notification to {email}")
 
-            # Show all of our warnings and errors.  Use a ">" prefix
-            # so warnings and errors get highlighted by the mail reader.
-            body = [ "Logs from backup.py:" ]
-            for (letter, msg) in backup.logs:
-                if letter == "E" or letter == "W":
-                    prefix = ">"
-                else:
-                    prefix = " "
-                body.append(f"{prefix}{letter}: {msg}")
-            body_text = "\n".join(body).encode()
-
-            # Followed by borg output
-            body_text += b"\n\nBorg output:\n" + b"".join(backup.captured_output)
+            def write_logs(title, only_include=None):
+                body = [ title ]
+                for (letter, msg) in backup.logs:
+                    if only_include and letter not in only_include:
+                        continue
+                    # Use a ":" prefix for warnings/errors/notices so that
+                    # the mail reader highlights them.
+                    if letter in "EWN":
+                        prefix = ":"
+                    else:
+                        prefix = " "
+                    body.append(f"{prefix}{letter}: {msg}")
+                return "\n".join(body).encode()
+
+
+            body_text = write_logs("Logged errors and warnings:", "EWN")
+            body_text += "\n"
+            body_text += write_logs("All logs:")
 
             # Subject summary
             if errmsg and warnmsg:

initial-setup.sh

@@ -278,6 +278,8 @@ ExecStart=${BORG_DIR}/backup.py
 Nice=10
 IOSchedulingClass=best-effort
 IOSchedulingPriority=6
+Restart=on-failure
+RestartSec=600
 EOF
 
     log "Setting up systemd"