Improve logging around main operations.

PostbackManager.java: check for actual postback promise before waiting.

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/bridge/BridgeAPI.java

@@ -7,8 +7,8 @@ import org.eclipse.jgit.transport.ServiceMayNotContinueException;
 import uk.ac.ic.wlgitbridge.data.CandidateSnapshot;
 import uk.ac.ic.wlgitbridge.data.ProjectLock;
 import uk.ac.ic.wlgitbridge.data.ShutdownHook;
-import uk.ac.ic.wlgitbridge.data.model.DataStore;
 import uk.ac.ic.wlgitbridge.data.filestore.RawDirectory;
+import uk.ac.ic.wlgitbridge.data.model.DataStore;
 import uk.ac.ic.wlgitbridge.snapshot.base.ForbiddenException;
 import uk.ac.ic.wlgitbridge.snapshot.exception.FailedConnectionException;
 import uk.ac.ic.wlgitbridge.snapshot.getdoc.GetDocRequest;
@@ -18,7 +18,6 @@ import uk.ac.ic.wlgitbridge.snapshot.push.PushRequest;
 import uk.ac.ic.wlgitbridge.snapshot.push.PushResult;
 import uk.ac.ic.wlgitbridge.snapshot.push.exception.*;
 import uk.ac.ic.wlgitbridge.util.Log;
-import uk.ac.ic.wlgitbridge.util.Util;
 
 import java.io.IOException;
 
@@ -72,7 +71,7 @@ public class BridgeAPI {
                    SnapshotPostException,
                    GitAPIException,
                    ForbiddenException {
-        Util.sout("Fetching project: " + projectName);
+        Log.info("[{}] Fetching", projectName);
         dataStore.updateProjectWithName(oauth2, projectName, repository);
     }
 
@@ -86,19 +85,24 @@ public class BridgeAPI {
         mainProjectLock.lockForProject(projectName);
         CandidateSnapshot candidate = null;
         try {
-            Log.info("[Project {}] Pushing", projectName);
+            Log.info("[{}] Pushing", projectName);
             String postbackKey = postbackManager.makeKeyForProject(projectName);
             Log.info(
-                    "[Project {}] Created postback key: {}",
+                    "[{}] Created postback key: {}",
                     projectName,
                     postbackKey
             );
             candidate =
-                    dataStore.createCandidateSnapshotFromProjectWithContents(
+                    dataStore.createCandidateSnapshot(
                             projectName,
                             directoryContents,
                             oldDirectoryContents
                     );
+            Log.info(
+                    "[{}] Candindate snapshot created: {}",
+                    projectName,
+                    candidate
+            );
             PushRequest pushRequest = new PushRequest(
                     oauth2,
                     candidate,
@@ -108,39 +112,52 @@ public class BridgeAPI {
             PushResult result = pushRequest.getResult();
             if (result.wasSuccessful()) {
                 Log.info(
-                        "[Project {}] Push to Overleaf successful",
+                        "[{}] Push to Overleaf successful",
                         projectName
                 );
-                Log.info("[Project {}] Waiting for postback...", projectName);
+                Log.info("[{}] Waiting for postback...", projectName);
                 int versionID =
                         postbackManager.waitForVersionIdOrThrow(projectName);
                 Log.info(
-                        "[Project {}] Got version ID for push: {}",
+                        "[{}] Got version ID for push: {}",
                         projectName,
                         versionID
                 );
                 dataStore.approveSnapshot(versionID, candidate);
                 Log.info(
-                        "[Project {}] Approved version ID: {}",
+                        "[{}] Approved version ID: {}",
                         projectName,
                         versionID
                 );
             } else {
+                Log.warn(
+                        "[{}] Went out of date while waiting for push",
+                        projectName
+                );
                 throw new OutOfDateException();
             }
         } catch (SevereSnapshotPostException e) {
-            Log.warn("Failed to put to Overleaf", e);
+            Log.warn("[" + projectName + "] Failed to put to Overleaf", e);
             throw e;
         } catch (SnapshotPostException e) {
+            /* Stack trace should be printed further up */
+            Log.warn(
+                    "[{}] Exception when waiting for postback: {}",
+                    projectName,
+                    e.getClass().getSimpleName()
+            );
             throw e;
         } catch (IOException e) {
+            Log.warn("[{}] IOException on put", projectName);
             throw e;
         } finally {
             if (candidate != null) {
                 candidate.deleteServletFiles();
             } else {
                 Log.error(
-                        "Candidate snapshot was null: this should never happen."
+                        "[{}] Candidate snapshot was null: " +
+                                "this should never happen.",
+                        projectName
                 );
             }
             mainProjectLock.unlockForProject(projectName);
@@ -157,13 +174,23 @@ public class BridgeAPI {
                                              String postbackKey,
                                              int versionID)
             throws UnexpectedPostbackException {
-        postbackManager.postVersionIDForProject(projectName, versionID, postbackKey);
+        Log.info(
+                "[{}]" +
+                        " Postback received by postback thread, version: {}",
+                projectName,
+                versionID);
+        postbackManager.postVersionIDForProject(
+                projectName,
+                versionID,
+                postbackKey
+        );
     }
 
     public void postbackReceivedWithException(String projectName,
                                               String postbackKey,
                                               SnapshotPostException exception)
             throws UnexpectedPostbackException {
+        Log.warn("[{}] Postback received with exception", projectName);
         postbackManager.postExceptionForProject(
                 projectName,
                 exception,

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/CandidateSnapshot.java

@@ -76,7 +76,9 @@ public class CandidateSnapshot {
         JsonObject jsonObject = new JsonObject();
         jsonObject.addProperty("latestVerId", currentVersion);
         jsonObject.add("files", getFilesAsJson(projectURL, postbackKey));
-        jsonObject.addProperty("postbackUrl", projectURL + "/" + postbackKey + "/postback");
+        jsonObject.addProperty(
+                "postbackUrl", projectURL + "/" + postbackKey + "/postback"
+        );
         return jsonObject;
     }
 
@@ -105,4 +107,16 @@ public class CandidateSnapshot {
         return deleted;
     }
 
+    @Override
+    public String toString() {
+        StringBuilder sb = new StringBuilder();
+        sb.append("VersionId: ");
+        sb.append(currentVersion);
+        sb.append(", files: ");
+        sb.append(files);
+        sb.append(", deleted: ");
+        sb.append(deleted);
+        return sb.toString();
+    }
+
 }

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/ServletFile.java

@@ -29,4 +29,9 @@ public class ServletFile extends RawFile {
         return changed;
     }
 
+    @Override
+    public String toString() {
+        return getPath();
+    }
+
 }

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/filestore/RawFile.java

@@ -1,5 +1,7 @@
 package uk.ac.ic.wlgitbridge.data.filestore;
 
+import uk.ac.ic.wlgitbridge.util.Log;
+
 import java.io.File;
 import java.io.FileOutputStream;
 import java.io.IOException;
@@ -21,6 +23,7 @@ public abstract class RawFile {
         OutputStream out = new FileOutputStream(file);
         out.write(getContents());
         out.close();
+        Log.info("Wrote file: {}", file.getAbsolutePath());
     }
 
     @Override

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/model/DataStore.java

@@ -11,11 +11,11 @@ import uk.ac.ic.wlgitbridge.data.filestore.GitDirectoryContents;
 import uk.ac.ic.wlgitbridge.data.filestore.RawDirectory;
 import uk.ac.ic.wlgitbridge.data.filestore.RawFile;
 import uk.ac.ic.wlgitbridge.data.model.db.PersistentStore;
-import uk.ac.ic.wlgitbridge.snapshot.base.ForbiddenException;
 import uk.ac.ic.wlgitbridge.data.model.db.SqlitePersistentStore;
-import uk.ac.ic.wlgitbridge.snapshot.exception.FailedConnectionException;
+import uk.ac.ic.wlgitbridge.snapshot.base.ForbiddenException;
 import uk.ac.ic.wlgitbridge.snapshot.getforversion.SnapshotAttachment;
 import uk.ac.ic.wlgitbridge.snapshot.push.exception.SnapshotPostException;
+import uk.ac.ic.wlgitbridge.util.Log;
 import uk.ac.ic.wlgitbridge.util.Util;
 
 import java.io.File;
@@ -37,35 +37,78 @@ public class DataStore {
         persistentStore = new SqlitePersistentStore(rootGitDirectory);
         List<String> excludedFromDeletion = persistentStore.getProjectNames();
         excludedFromDeletion.add(".wlgb");
-        Util.deleteInDirectoryApartFrom(rootGitDirectory, excludedFromDeletion.toArray(new String[] {}));
+        Util.deleteInDirectoryApartFrom(
+                rootGitDirectory,
+                excludedFromDeletion.toArray(new String[] {})
+        );
 
         snapshotFetcher = new SnapshotFetcher();
         resourceFetcher = new ResourceFetcher(persistentStore);
     }
 
-    public void updateProjectWithName(Credential oauth2, String name, Repository repository) throws IOException, SnapshotPostException, GitAPIException, ForbiddenException {
-        LinkedList<Snapshot> snapshots = snapshotFetcher.getSnapshotsForProjectAfterVersion(oauth2, name, persistentStore.getLatestVersionForProject(name));
+    public void updateProjectWithName(Credential oauth2,
+                                      String name,
+                                      Repository repository)
+            throws IOException,
+                   SnapshotPostException,
+                   GitAPIException,
+                   ForbiddenException {
+        LinkedList<Snapshot> snapshots =
+                snapshotFetcher.getSnapshotsForProjectAfterVersion(
+                        oauth2,
+                        name,
+                        persistentStore.getLatestVersionForProject(name)
+                );
 
         makeCommitsFromSnapshots(name, repository, snapshots);
 
         if (!snapshots.isEmpty()) {
-            persistentStore.setLatestVersionForProject(name, snapshots.getLast().getVersionID());
+            persistentStore.setLatestVersionForProject(
+                    name,
+                    snapshots.getLast().getVersionID()
+            );
         }
     }
 
-    private void makeCommitsFromSnapshots(String name, Repository repository, List<Snapshot> snapshots) throws IOException, GitAPIException, SnapshotPostException {
+    private void makeCommitsFromSnapshots(String name,
+                                          Repository repository,
+                                          List<Snapshot> snapshots)
+            throws IOException, GitAPIException, SnapshotPostException {
         for (Snapshot snapshot : snapshots) {
             List<RawFile> files = new LinkedList<RawFile>();
             files.addAll(snapshot.getSrcs());
             Map<String, byte[]> fetchedUrls = new HashMap<String, byte[]>();
             for (SnapshotAttachment snapshotAttachment : snapshot.getAtts()) {
-                files.add(resourceFetcher.get(name, snapshotAttachment.getUrl(), snapshotAttachment.getPath(), repository, fetchedUrls));
+                files.add(
+                        resourceFetcher.get(
+                                name,
+                                snapshotAttachment.getUrl(),
+                                snapshotAttachment.getPath(),
+                                repository,
+                                fetchedUrls
+                        )
+                );
             }
-            commit(name, new GitDirectoryContents(files, rootGitDirectory, name, snapshot), repository);
+            Log.info(
+                    "[{}] Committing version ID: {}",
+                    name,
+                    snapshot.getVersionID()
+            );
+            commit(name,
+                    new GitDirectoryContents(
+                            files,
+                            rootGitDirectory,
+                            name,
+                            snapshot),
+                    repository);
         }
     }
 
-    private void commit(String name, GitDirectoryContents contents, Repository repository) throws IOException, GitAPIException {
+    private void commit(String name,
+                        GitDirectoryContents contents,
+                        Repository repository) throws IOException,
+                                                      GitAPIException {
+        Log.info("[{}] Writing commit", name);
         contents.write();
         Git git = new Git(repository);
         Set<String> missingFiles = git.status().call().getMissing();
@@ -73,26 +116,56 @@ public class DataStore {
             git.rm().setCached(true).addFilepattern(missing).call();
         }
         git.add().addFilepattern(".").call();
-        git.commit().setAuthor(new PersonIdent(contents.getUserName(), contents.getUserEmail(), contents.getWhen(), TimeZone.getDefault()))
-                .setMessage(contents.getCommitMessage())
-                .call();
-        persistentStore.deleteFilesForProject(name, missingFiles.toArray(new String[missingFiles.size()]));
+        git.commit(
+        ).setAuthor(
+                new PersonIdent(
+                        contents.getUserName(),
+                        contents.getUserEmail(),
+                        contents.getWhen(),
+                        TimeZone.getDefault()
+                )
+        ).setMessage(
+                contents.getCommitMessage()
+        ).call();
+        persistentStore.deleteFilesForProject(
+                name,
+                missingFiles.toArray(new String[missingFiles.size()])
+        );
+        Log.info(
+                "[{}] Deleting files in directory: {}",
+                name,
+                contents.getDirectory().getAbsolutePath()
+        );
         Util.deleteInDirectoryApartFrom(contents.getDirectory(), ".git");
     }
 
-    public CandidateSnapshot createCandidateSnapshotFromProjectWithContents(String projectName, RawDirectory directoryContents, RawDirectory oldDirectoryContents) throws SnapshotPostException, IOException, FailedConnectionException {
-        CandidateSnapshot candidateSnapshot = new CandidateSnapshot(projectName,
+    public CandidateSnapshot
+    createCandidateSnapshot(String projectName,
+                            RawDirectory directoryContents,
+                            RawDirectory oldDirectoryContents)
+            throws SnapshotPostException,
+                   IOException {
+        CandidateSnapshot candidateSnapshot = new CandidateSnapshot(
+                projectName,
                 persistentStore.getLatestVersionForProject(projectName),
                 directoryContents,
-                oldDirectoryContents);
+                oldDirectoryContents
+        );
         candidateSnapshot.writeServletFiles(rootGitDirectory);
         return candidateSnapshot;
     }
 
-    public void approveSnapshot(int versionID, CandidateSnapshot candidateSnapshot) {
+    public void approveSnapshot(int versionID,
+                                CandidateSnapshot candidateSnapshot) {
         List<String> deleted = candidateSnapshot.getDeleted();
-        persistentStore.setLatestVersionForProject(candidateSnapshot.getProjectName(), versionID);
-        persistentStore.deleteFilesForProject(candidateSnapshot.getProjectName(), deleted.toArray(new String[deleted.size()]));
+        persistentStore.setLatestVersionForProject(
+                candidateSnapshot.getProjectName(),
+                versionID
+        );
+        persistentStore.deleteFilesForProject(
+                candidateSnapshot.getProjectName(),
+                deleted.toArray(new String[deleted.size()])
+        );
     }
 
     private File initRootGitDirectory(String rootGitDirectoryPath) {

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/model/db/SqlitePersistentStore.java

@@ -1,9 +1,11 @@
 package uk.ac.ic.wlgitbridge.data.model.db;
 
 import uk.ac.ic.wlgitbridge.data.model.db.sql.SQLiteWLDatabase;
+import uk.ac.ic.wlgitbridge.util.Log;
 
 import java.io.File;
 import java.sql.SQLException;
+import java.util.Arrays;
 import java.util.List;
 
 /**
@@ -35,6 +37,7 @@ public class SqlitePersistentStore implements PersistentStore {
     public void setLatestVersionForProject(String project, int versionID) {
         try {
             database.setVersionIDForProject(project, versionID);
+            Log.info("[{}] Wrote latest versionId: {}", project, versionID);
         } catch (SQLException e) {
             throw new RuntimeException(e);
         }
@@ -53,6 +56,7 @@ public class SqlitePersistentStore implements PersistentStore {
     public void addURLIndexForProject(String projectName, String url, String path) {
         try {
             database.addURLIndex(projectName, url, path);
+            Log.info("[{}] Wrote url index: {} -> {}", projectName, url, path);
         } catch (SQLException e) {
             throw new RuntimeException(e);
         }
@@ -62,6 +66,11 @@ public class SqlitePersistentStore implements PersistentStore {
     public void deleteFilesForProject(String project, String... files) {
         try {
             database.deleteFilesForProject(project, files);
+            Log.info(
+                    "[{}] Deleting from url index: {}",
+                    project,
+                    Arrays.toString(files)
+            );
         } catch (SQLException e) {
             throw new RuntimeException(e);
         }

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/snapshot/push/PostbackManager.java

@@ -1,8 +1,7 @@
 package uk.ac.ic.wlgitbridge.snapshot.push;
 
-import uk.ac.ic.wlgitbridge.snapshot.push.exception.InvalidPostbackKeyException;
-import uk.ac.ic.wlgitbridge.snapshot.push.exception.SnapshotPostException;
-import uk.ac.ic.wlgitbridge.snapshot.push.exception.UnexpectedPostbackException;
+import uk.ac.ic.wlgitbridge.snapshot.push.exception.*;
+import uk.ac.ic.wlgitbridge.util.Log;
 
 import java.math.BigInteger;
 import java.security.SecureRandom;
@@ -22,25 +21,41 @@ public class PostbackManager {
         postbackContentsTable = new HashMap<String, PostbackPromise>();
     }
 
-    public int waitForVersionIdOrThrow(String projectName) throws SnapshotPostException {
+    public int waitForVersionIdOrThrow(String projectName)
+            throws SnapshotPostException {
         try {
-            return postbackContentsTable.get(projectName).waitForPostback();
-        } catch (SnapshotPostException e) {
-            throw e;
+            PostbackPromise postbackPromise =
+                    postbackContentsTable.get(projectName);
+            if (postbackPromise == null) {
+                Log.warn("[{}] PostbackPromise was null.", projectName);
+                throw new InternalErrorException();
+            }
+            return postbackPromise.waitForPostback();
         } finally {
             postbackContentsTable.remove(projectName);
         }
     }
 
-    public void postVersionIDForProject(String projectName, int versionID, String postbackKey) throws UnexpectedPostbackException {
-        getPostbackForProject(projectName).receivedVersionID(versionID, postbackKey);
+    public void postVersionIDForProject(String projectName,
+                                        int versionID,
+                                        String postbackKey)
+            throws UnexpectedPostbackException {
+        getPostbackForProject(
+                projectName
+        ).receivedVersionID(versionID, postbackKey);
     }
 
-    public void postExceptionForProject(String projectName, SnapshotPostException exception, String postbackKey) throws UnexpectedPostbackException {
-        getPostbackForProject(projectName).receivedException(exception, postbackKey);
+    public void postExceptionForProject(String projectName,
+                                        SnapshotPostException exception,
+                                        String postbackKey)
+            throws UnexpectedPostbackException {
+        getPostbackForProject(
+                projectName
+        ).receivedException(exception, postbackKey);
     }
 
-    private PostbackPromise getPostbackForProject(String projectName) throws UnexpectedPostbackException {
+    private PostbackPromise getPostbackForProject(String projectName)
+            throws UnexpectedPostbackException {
         PostbackPromise contents = postbackContentsTable.remove(projectName);
         if (contents == null) {
             throw new UnexpectedPostbackException();
@@ -55,7 +70,8 @@ public class PostbackManager {
         return key;
     }
 
-    public void checkPostbackKey(String projectName, String postbackKey) throws InvalidPostbackKeyException {
+    public void checkPostbackKey(String projectName, String postbackKey)
+            throws InvalidPostbackKeyException {
         postbackContentsTable.get(projectName).checkPostbackKey(postbackKey);
     }
 

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Log.java

@@ -13,6 +13,7 @@ public class Log {
     static {
         System.setProperty(SimpleLogger.SHOW_DATE_TIME_KEY, "true");
         System.setProperty(SimpleLogger.DATE_TIME_FORMAT_KEY, "yyyy-MM-dd HH:mm:ss:SSS Z");
+        System.setProperty(SimpleLogger.SHOW_SHORT_LOG_NAME_KEY, "true");
     }
 
     private static Logger logger = LoggerFactory.getLogger(GitBridgeApp.class);

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Util.java

@@ -144,6 +144,7 @@ public class Util {
                             deleteInDirectory(file);
                         }
                         file.delete();
+                        Log.info("Deleted file: {}", file.getAbsolutePath());
                     }
                 }
             }