From 08f3497a9e6229a607b0093c04a118a125c97d30 Mon Sep 17 00:00:00 2001 From: Winston Li Date: Sun, 3 Apr 2016 12:10:05 +0100 Subject: [PATCH] Improve logging around main operations. PostbackManager.java: check for actual postback promise before waiting. --- .../ac/ic/wlgitbridge/bridge/BridgeAPI.java | 53 ++++++-- .../wlgitbridge/data/CandidateSnapshot.java | 16 ++- .../ac/ic/wlgitbridge/data/ServletFile.java | 5 + .../wlgitbridge/data/filestore/RawFile.java | 3 + .../ic/wlgitbridge/data/model/DataStore.java | 113 ++++++++++++++---- .../data/model/db/SqlitePersistentStore.java | 9 ++ .../snapshot/push/PostbackManager.java | 42 +++++-- .../java/uk/ac/ic/wlgitbridge/util/Log.java | 1 + .../java/uk/ac/ic/wlgitbridge/util/Util.java | 1 + 9 files changed, 196 insertions(+), 47 deletions(-) diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/bridge/BridgeAPI.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/bridge/BridgeAPI.java index 1bc93fc6d4..30e3fcc38c 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/bridge/BridgeAPI.java +++ b/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, diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/CandidateSnapshot.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/CandidateSnapshot.java index dfed107715..62d546636c 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/CandidateSnapshot.java +++ b/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(); + } + } diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/ServletFile.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/ServletFile.java index 100e1f45c7..bc42ba8c9b 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/ServletFile.java +++ b/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(); + } + } diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/filestore/RawFile.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/filestore/RawFile.java index c37d6ee168..8031208ec3 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/filestore/RawFile.java +++ b/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 diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/model/DataStore.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/model/DataStore.java index 82b5729a71..8df74088fa 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/model/DataStore.java +++ b/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 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 snapshots = snapshotFetcher.getSnapshotsForProjectAfterVersion(oauth2, name, persistentStore.getLatestVersionForProject(name)); + public void updateProjectWithName(Credential oauth2, + String name, + Repository repository) + throws IOException, + SnapshotPostException, + GitAPIException, + ForbiddenException { + LinkedList 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 snapshots) throws IOException, GitAPIException, SnapshotPostException { + private void makeCommitsFromSnapshots(String name, + Repository repository, + List snapshots) + throws IOException, GitAPIException, SnapshotPostException { for (Snapshot snapshot : snapshots) { List files = new LinkedList(); files.addAll(snapshot.getSrcs()); Map fetchedUrls = new HashMap(); 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 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 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) { diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/model/db/SqlitePersistentStore.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/model/db/SqlitePersistentStore.java index 7a56d6111f..40b5d53ca9 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/data/model/db/SqlitePersistentStore.java +++ b/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); } diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/snapshot/push/PostbackManager.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/snapshot/push/PostbackManager.java index 6530377722..6dca0b6b3d 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/snapshot/push/PostbackManager.java +++ b/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(); } - 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); } diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Log.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Log.java index 862d211ff3..1cabf22bcd 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Log.java +++ b/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); diff --git a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Util.java b/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Util.java index d964e93f40..c2bf08eea3 100644 --- a/services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/util/Util.java +++ b/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()); } } }