stop swallowing git exection failures (#274)

This is a bit of a WIP - some of the exception handling is still a bit of a mess.  But it's important to stop silently swallowing process execution failures, and this gets that done.

common/src/main/java/net/pcal/fastback/logging/SystemLogger.java

@@ -18,6 +18,8 @@
 
 package net.pcal.fastback.logging;
 
+import java.util.function.Supplier;
+
 /**
  * Singleton logger instance that writes to the serverside console.
  *
@@ -46,6 +48,10 @@ default void error(Throwable e) {
 
     void debug(String message);
 
+    default void trace(Supplier<String> message) {
+        debug(message.get()); //FIXME
+    }
+
     void debug(String message, Throwable t);
 
     default void debug(Throwable t) {

common/src/main/java/net/pcal/fastback/repo/CommitUtils.java

@@ -21,6 +21,7 @@
 import net.pcal.fastback.config.GitConfig;
 import net.pcal.fastback.logging.UserLogger;
 import net.pcal.fastback.utils.EnvironmentUtils;
+import net.pcal.fastback.utils.ProcessUtils.ExecException;
 import org.apache.commons.io.FileUtils;
 import org.eclipse.jgit.api.AddCommand;
 import org.eclipse.jgit.api.Git;
@@ -61,7 +62,7 @@
  */
 abstract class CommitUtils {
 
-    public static SnapshotId doCommitSnapshot(final RepoImpl repo, final UserLogger ulog) throws IOException {
+    static SnapshotId doCommitSnapshot(final RepoImpl repo, final UserLogger ulog) throws IOException, ExecException {
         PreflightUtils.doPreflight(repo);
         final WorldId uuid = repo.getWorldId();
         final GitConfig conf = repo.getConfig();
@@ -115,25 +116,31 @@ private static void doSettingsBackup(RepoImpl repo, UserLogger ulog) {
         }
     }
 
-    private static void native_commit(final String newBranchName, final Repo repo, final UserLogger log) throws IOException, InterruptedException {
+    private static void native_commit(final String newBranchName, final Repo repo, final UserLogger ulog) throws IOException, InterruptedException {
         syslog().debug("Start native_commit");
-        log.update(styledLocalized("fastback.hud.local-saving", NATIVE_GIT));
+        ulog.update(styledLocalized("fastback.hud.local-saving", NATIVE_GIT));
         final File worktree = repo.getWorkTree();
         final Map<String, String> env = Map.of("GIT_LFS_FORCE_PROGRESS", "1");
-        final Consumer<String> outputConsumer = line -> log.update(styledRaw(line, NATIVE_GIT));
+        final Consumer<String> outputConsumer = line -> ulog.update(styledRaw(line, NATIVE_GIT));
         String[] checkout = {"git", "-C", worktree.getAbsolutePath(), "checkout", "--orphan", newBranchName};
-        doExec(checkout, env, outputConsumer, outputConsumer);
-        mod().setWorldSaveEnabled(false);
         try {
-            String[] add = {"git", "-C", worktree.getAbsolutePath(), "add", "-v", "."};
-            doExec(add, env, outputConsumer, outputConsumer);
-        } finally {
-            mod().setWorldSaveEnabled(true);
-            syslog().debug("World save re-enabled.");
-        }
-        {
-            String[] commit = {"git", "-C", worktree.getAbsolutePath(), "commit", "-m", newBranchName};
-            doExec(commit, env, outputConsumer, outputConsumer);
+            doExec(checkout, env, outputConsumer, outputConsumer);
+            mod().setWorldSaveEnabled(false);
+            try {
+                String[] add = {"git", "-C", worktree.getAbsolutePath(), "add", "-v", "."};
+                doExec(add, env, outputConsumer, outputConsumer);
+            } finally {
+                mod().setWorldSaveEnabled(true);
+                syslog().debug("World save re-enabled.");
+            }
+            {
+                String[] commit = {"git", "-C", worktree.getAbsolutePath(), "commit", "-m", newBranchName};
+                doExec(commit, env, outputConsumer, outputConsumer);
+            }
+        } catch (ExecException e) {
+            syslog().error(e);
+            e.report(ulog);
+            return;
         }
         syslog().debug("End native_commit");
     }

common/src/main/java/net/pcal/fastback/repo/PreflightUtils.java

@@ -21,6 +21,7 @@
 import net.pcal.fastback.config.GitConfig;
 import net.pcal.fastback.logging.SystemLogger;
 import net.pcal.fastback.utils.EnvironmentUtils;
+import net.pcal.fastback.utils.ProcessUtils.ExecException;
 import org.eclipse.jgit.api.Git;
 
 import java.io.IOException;
@@ -49,7 +50,7 @@ abstract class PreflightUtils {
      * Should be called prior to any heavy-lifting with git (e.g. commiting and pushing).  Ensures that
      * key files are all set correctly.
      */
-    static void doPreflight(RepoImpl repo) throws IOException {
+    static void doPreflight(RepoImpl repo) throws IOException, ExecException {
         final SystemLogger syslog = syslog();
         syslog.debug("Doing world maintenance");
         final Git jgit = repo.getJGit();
@@ -68,11 +69,7 @@ static void doPreflight(RepoImpl repo) throws IOException {
                 writeResourceToFile("world/gitattributes-jgit", targetPath);
             }
         }
-        try {
-            updateNativeLfsInstallation(repo);
-        } catch (InterruptedException e) {
-            throw new IOException(e);
-        }
+        updateNativeLfsInstallation(repo);
     }
 
     // ======================================================================
@@ -81,14 +78,12 @@ static void doPreflight(RepoImpl repo) throws IOException {
     /**
      * Ensures that git-lfs is installed or uninstalled in the worktree as appropriate.
      */
-    private static void updateNativeLfsInstallation(final Repo repo) throws IOException, InterruptedException {
+    private static void updateNativeLfsInstallation(final Repo repo) throws ExecException {
         if (EnvironmentUtils.isNativeGitInstalled()) {
             final boolean isNativeEnabled = repo.getConfig().getBoolean(IS_NATIVE_GIT_ENABLED);
             final String action = isNativeEnabled ? "install" : "uninstall";
             final String[] cmd = {"git", "-C", repo.getWorkTree().getAbsolutePath(), "lfs", action, "--local"};
-            doExec(cmd, Collections.emptyMap(), s -> {
-            }, s -> {
-            });
+            doExec(cmd, Collections.emptyMap(), s -> {}, s -> {});
         }
     }
 }

common/src/main/java/net/pcal/fastback/repo/PushUtils.java

@@ -21,6 +21,7 @@
 import com.google.common.collect.ListMultimap;
 import net.pcal.fastback.config.GitConfig;
 import net.pcal.fastback.logging.UserLogger;
+import net.pcal.fastback.utils.ProcessUtils.ExecException;
 import org.eclipse.jgit.api.Git;
 import org.eclipse.jgit.api.errors.GitAPIException;
 import org.eclipse.jgit.lib.ObjectId;
@@ -71,7 +72,8 @@ static boolean isTempBranch(String branchName) {
         return branchName.startsWith("temp/");
     }
 
-    static void doPush(SnapshotId sid, RepoImpl repo, UserLogger ulog) throws IOException {
+    // TODO stop throwing IOE
+    static void doPush(SnapshotId sid, RepoImpl repo, UserLogger ulog) throws IOException, ExecException {
         try {
             final GitConfig conf = repo.getConfig();
             final String pushUrl = conf.getString(REMOTE_PUSH_URL);
@@ -102,7 +104,6 @@ static void doPush(SnapshotId sid, RepoImpl repo, UserLogger ulog) throws IOExce
             syslog().debug("Pushing to " + pushUrl);
 
             PreflightUtils.doPreflight(repo);
-
             if (conf.getBoolean(IS_NATIVE_GIT_ENABLED)) {
                 native_doPush(repo, sid.getBranchName(), ulog);
             } else if (conf.getBoolean(IS_SMART_PUSH_ENABLED)) {
@@ -112,12 +113,12 @@ static void doPush(SnapshotId sid, RepoImpl repo, UserLogger ulog) throws IOExce
                 jgit_doPush(jgit, sid.getBranchName(), conf, ulog);
             }
             syslog().info("Remote backup complete.");
-        } catch (GitAPIException | InterruptedException e) {
+        } catch (GitAPIException e) {
             throw new IOException(e);
         }
     }
 
-    private static void native_doPush(final Repo repo, final String branchNameToPush, final UserLogger log) throws IOException, InterruptedException {
+    private static void native_doPush(final Repo repo, final String branchNameToPush, final UserLogger log) throws ExecException {
         syslog().debug("Start native_push");
         log.update(styledLocalized("fastback.chat.push-started", NATIVE_GIT));
         final File worktree = repo.getWorkTree();
@@ -131,16 +132,12 @@ private static void native_doPush(final Repo repo, final String branchNameToPush
     }
 
 
-    private static void jgit_doPush(final Git jgit, final String branchNameToPush, final GitConfig conf, final UserLogger ulog) throws IOException {
+    private static void jgit_doPush(final Git jgit, final String branchNameToPush, final GitConfig conf, final UserLogger ulog) throws GitAPIException {
         final ProgressMonitor pm = new JGitIncrementalProgressMonitor(new JGitPushProgressMonitor(ulog), 100);
         final String remoteName = conf.getString(REMOTE_NAME);
         syslog().info("Doing simple push of " + branchNameToPush);
-        try {
-            jgit.push().setProgressMonitor(pm).setRemote(remoteName).
-                    setRefSpecs(new RefSpec(branchNameToPush + ":" + branchNameToPush)).call();
-        } catch (GitAPIException e) {
-            throw new IOException(e);
-        }
+        jgit.push().setProgressMonitor(pm).setRemote(remoteName).
+                setRefSpecs(new RefSpec(branchNameToPush + ":" + branchNameToPush)).call();
     }
 
     /**

common/src/main/java/net/pcal/fastback/repo/ReclamationUtils.java

@@ -21,6 +21,7 @@
 import net.pcal.fastback.config.GitConfig;
 import net.pcal.fastback.logging.UserLogger;
 import net.pcal.fastback.utils.FileUtils;
+import net.pcal.fastback.utils.ProcessUtils.ExecException;
 import org.eclipse.jgit.api.errors.GitAPIException;
 import org.eclipse.jgit.internal.storage.file.FileRepository;
 import org.eclipse.jgit.internal.storage.file.GC;
@@ -61,23 +62,19 @@
  */
 abstract class ReclamationUtils {
 
-    static void doReclamation(RepoImpl repo, UserLogger ulog) throws IOException {
+    static void doReclamation(RepoImpl repo, UserLogger ulog) throws GitAPIException, ExecException {
         if (repo.getConfig().getBoolean(IS_NATIVE_GIT_ENABLED)) {
-            try {
-                native_doLfsPrune(repo, ulog);
-            } catch (InterruptedException e) {
-                throw new IOException(e);
-            }
+            native_doLfsPrune(repo, ulog);
         } else {
             try {
                 jgit_doGc(repo, ulog);
-            } catch (GitAPIException | ParseException e) {
-                throw new IOException(e);
+            } catch (ParseException | IOException e) {
+                throw new RuntimeException(e);
             }
         }
     }
 
-    private static void native_doLfsPrune(RepoImpl repo, UserLogger ulog) throws IOException, InterruptedException {
+    private static void native_doLfsPrune(RepoImpl repo, UserLogger ulog) throws ExecException {
         final File worktree = repo.getWorkTree();
         final String[] push = {"git", "-C", worktree.getAbsolutePath(), "-c", "lfs.pruneoffsetdays=999999", "lfs", "prune", "--verbose", "--no-verify-remote",};
         final Consumer<String> outputConsumer = line->ulog.update(styledRaw(line, NATIVE_GIT));
@@ -89,7 +86,7 @@ private static void native_doLfsPrune(RepoImpl repo, UserLogger ulog) throws IOE
      * Runs git garbage collection.  Aggressively deletes reflogs, tracking branches and stray temporary branches
      * in an attempt to free up objects and reclaim disk space.
      */
-    private static void jgit_doGc(RepoImpl repo, UserLogger ulog) throws IOException, GitAPIException, ParseException {
+    private static void jgit_doGc(RepoImpl repo, UserLogger ulog) throws GitAPIException, ParseException, IOException {
         final File gitDir = repo.getJGit().getRepository().getDirectory();
         final GitConfig config = repo.getConfig();
         ulog.update(styledLocalized("fastback.hud.gc-percent", JGIT, 0));

common/src/main/java/net/pcal/fastback/repo/Repo.java

@@ -20,6 +20,7 @@
 
 import net.pcal.fastback.config.GitConfig;
 import net.pcal.fastback.logging.UserLogger;
+import net.pcal.fastback.utils.ProcessUtils.ExecException;
 import org.eclipse.jgit.api.errors.GitAPIException;
 import org.eclipse.jgit.errors.NoWorkTreeException;
 
@@ -63,9 +64,9 @@ public interface Repo extends AutoCloseable {
 
     Collection<SnapshotId> doRemotePrune(UserLogger ulog) throws IOException;
 
-    void doGc(UserLogger ulog) throws IOException;
+    void doGc(UserLogger ulog);
 
-    void doPushSnapshot(SnapshotId sid, UserLogger ulog) throws IOException, ParseException;
+    void doPushSnapshot(SnapshotId sid, UserLogger ulog);
 
     Path doRestoreSnapshot(String uri, Path restoresDir, String worldName, SnapshotId sid, UserLogger ulog) throws IOException;
 

common/src/main/java/net/pcal/fastback/repo/RepoImpl.java

@@ -24,6 +24,7 @@
 import net.pcal.fastback.repo.SnapshotIdUtils.SnapshotIdCodec;
 import net.pcal.fastback.repo.WorldIdUtils.WorldIdInfo;
 import net.pcal.fastback.utils.EnvironmentUtils;
+import net.pcal.fastback.utils.ProcessUtils.ExecException;
 import org.eclipse.jgit.api.Git;
 import org.eclipse.jgit.api.errors.GitAPIException;
 import org.eclipse.jgit.errors.NoWorkTreeException;
@@ -97,6 +98,12 @@ public void doCommitAndPush(final UserLogger ulog) {
         try {
             newSid = CommitUtils.doCommitSnapshot(this, ulog);
         } catch(IOException ioe) {
+            syslog().error(ioe);
+            ulog.message(styledLocalized("fastback.chat.commit-failed", ERROR));
+            return;
+        } catch (ExecException e) {
+            syslog().error(e);
+            e.report(ulog);
             ulog.message(styledLocalized("fastback.chat.commit-failed", ERROR));
             return;
         }
@@ -106,6 +113,11 @@ public void doCommitAndPush(final UserLogger ulog) {
             ulog.message(styledLocalized("fastback.chat.push-failed", ERROR));
             syslog().error(ioe);
             return;
+        } catch(ExecException e) {
+            syslog().error(e);
+            e.report(ulog);
+            ulog.message(styledLocalized("fastback.chat.push-failed", ERROR));
+            return;
         }
         ulog.message(localized("fastback.chat.backup-complete-elapsed", getDuration(start)));
     }
@@ -123,12 +135,17 @@ public void doCommitSnapshot(final UserLogger ulog) {
             ulog.message(styledLocalized("fastback.chat.commit-failed", ERROR));
             syslog().error(ioe);
             return;
+        } catch (ExecException e) {
+            e.report(ulog);
+            ulog.message(styledLocalized("fastback.chat.commit-failed", ERROR));
+            syslog().error(e);
+            return;
         }
         ulog.message(localized("fastback.chat.backup-complete-elapsed", getDuration(start)));
     }
 
     @Override
-    public void doPushSnapshot(SnapshotId sid, final UserLogger ulog) throws IOException, ParseException {
+    public void doPushSnapshot(SnapshotId sid, final UserLogger ulog) {
         if (!this.getConfig().isSet(REMOTE_PUSH_URL)) {
             ulog.message(styledLocalized("No remote is configured.  Run set-remote <url>", ERROR)); //FIXME i18n
             return;
@@ -141,6 +158,11 @@ public void doPushSnapshot(SnapshotId sid, final UserLogger ulog) throws IOExcep
             ulog.message(styledLocalized("fastback.chat.commit-failed", ERROR));
             syslog().error(ioe);
             return;
+        } catch(ExecException e) {
+            syslog().error(e);
+            e.report(ulog);
+            ulog.message(styledLocalized("fastback.chat.push-failed", ERROR));
+            return;
         }
         ulog.message(UserMessage.localized("Successfully pushed " + sid.getShortName() + ".  Time elapsed: "+getDuration(start))); // FIXME i18n
     }
@@ -157,9 +179,18 @@ public Collection<SnapshotId> doRemotePrune(final UserLogger ulog) throws IOExce
     }
 
     @Override
-    public void doGc(final UserLogger ulog) throws IOException {
+    public void doGc(final UserLogger ulog)  {
         if (!doNativeCheck(ulog)) return;
-        ReclamationUtils.doReclamation(this, ulog);
+        try {
+            ReclamationUtils.doReclamation(this, ulog);
+        } catch (GitAPIException e) {
+            ulog.message(styledLocalized("Command failed.  Check log for details.", ERROR)); // FIXME i18n
+            syslog().error(e);
+        } catch (ExecException e) {
+            syslog().error(e);
+            e.report(ulog);
+            ulog.message(styledLocalized("Command failed.  Check log for details.", ERROR)); // FIXME i18n
+        }
     }
 
     @Override

common/src/main/java/net/pcal/fastback/utils/EnvironmentUtils.java

@@ -18,7 +18,8 @@
 
 package net.pcal.fastback.utils;
 
-import java.io.IOException;
+import net.pcal.fastback.utils.ProcessUtils.ExecException;
+
 import java.util.ArrayList;
 import java.util.Collections;
 import java.util.List;
@@ -46,7 +47,7 @@ private static String execForVersion(String[] cmd) {
         try {
             exit = doExec(cmd, Collections.emptyMap(), stdout::add, line -> {
             });
-        } catch (IOException | InterruptedException e) {
+        } catch (ExecException e) {
             syslog().debug("Could not run " + String.join(" ", cmd), e);
             return null;
         }