Merge pull request #135 from overleaf/spd-debugging

Add extra debug logging, and enable it

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

@@ -451,6 +451,7 @@ public class Bridge {
             RawDirectory oldDirectoryContents,
             String hostname
     ) throws SnapshotPostException, IOException, MissingRepositoryException, ForbiddenException, GitUserException {
+        Log.debug("[{}] pushing to Overleaf", projectName);
         try (LockGuard __ = lock.lockGuard(projectName)) {
             pushCritical(
                     oauth2,
@@ -538,10 +539,11 @@ public class Bridge {
         if (maxFileNum.isPresent()) {
           long maxFileNum_ = maxFileNum.get();
           if (directoryContents.getFileTable().size() > maxFileNum_) {
+            Log.debug("[{}] Too many files: {}/{}", projectName, directoryContents.getFileTable().size(), maxFileNum_);
             throw new FileLimitExceededException(directoryContents.getFileTable().size(), maxFileNum_);
           }
         }
-        Log.info("[{}] Pushing", projectName);
+        Log.info("[{}] Pushing files ({} new, {} old)", projectName, directoryContents.getFileTable().size(), oldDirectoryContents.getFileTable().size());
         String postbackKey = postbackManager.makeKeyForProject(projectName);
         Log.info(
                 "[{}] Created postback key: {}",

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

@@ -7,6 +7,7 @@ import java.util.Map;
 import java.util.concurrent.locks.Lock;
 import java.util.concurrent.locks.ReentrantLock;
 import java.util.concurrent.locks.ReentrantReadWriteLock;
+import uk.ac.ic.wlgitbridge.util.Log;
 
 /**
  * Created by Winston on 20/11/14.
@@ -35,29 +36,40 @@ public class ProjectLockImpl implements ProjectLock {
 
     @Override
     public void lockForProject(String projectName) {
+        Log.debug("[{}] taking project lock", projectName);
         getLockForProjectName(projectName).lock();
+        Log.debug("[{}] taking reentrant lock", projectName);
         rlock.lock();
+        Log.debug("[{}] taken locks", projectName);
     }
 
     @Override
     public void unlockForProject(String projectName) {
+        Log.debug("[{}] releasing project lock", projectName);
         getLockForProjectName(projectName).unlock();
+        Log.debug("[{}] releasing reentrant lock", projectName);
         rlock.unlock();
+        Log.debug("[{}] released locks", projectName);
         if (waiting) {
+            Log.debug("[{}] waiting for remaining threads", projectName);
             trySignal();
         }
     }
 
     private void trySignal() {
         int threads = rwlock.getReadLockCount();
+        Log.debug("-> waiting for {} threads", threads);
         if (waiter != null && threads > 0) {
             waiter.threadsRemaining(threads);
         }
+        Log.debug("-> finished waiting for threads");
     }
 
     public void lockAll() {
+        Log.debug("-> locking all threads");
         waiting = true;
         trySignal();
+        Log.debug("-> locking reentrant write lock");
         wlock.lock();
     }
 

services/git-bridge/src/main/java/uk/ac/ic/wlgitbridge/git/handler/hook/WriteLatexPutHook.java

@@ -65,6 +65,7 @@ public class WriteLatexPutHook implements PreReceiveHook {
             ReceivePack receivePack,
             Collection<ReceiveCommand> receiveCommands
     ) {
+        Log.debug("-> Handling {} commands in {}", receiveCommands.size(), receivePack.getRepository().getDirectory().getAbsolutePath());
         for (ReceiveCommand receiveCommand : receiveCommands) {
             try {
                 handleReceiveCommand(
@@ -73,17 +74,20 @@ public class WriteLatexPutHook implements PreReceiveHook {
                         receiveCommand
                 );
             } catch (IOException e) {
+                Log.debug("IOException on pre receive: {}", e.getMessage());
                 receivePack.sendError(e.getMessage());
                 receiveCommand.setResult(
                         Result.REJECTED_OTHER_REASON,
                         e.getMessage()
                 );
             } catch (OutOfDateException e) {
+                Log.debug("OutOfDateException on pre receive: {}", e.getMessage());
                 receiveCommand.setResult(Result.REJECTED_NONFASTFORWARD);
             } catch (GitUserException e) {
+                Log.debug("GitUserException on pre receive: {}", e.getMessage());
                 handleSnapshotPostException(receivePack, receiveCommand, e);
             } catch (Throwable t) {
-                Log.warn("Throwable on pre receive: ", t);
+                Log.warn("Throwable on pre receive: {}", t.getMessage());
                 handleSnapshotPostException(
                         receivePack,
                         receiveCommand,
@@ -91,6 +95,7 @@ public class WriteLatexPutHook implements PreReceiveHook {
                 );
             }
         }
+        Log.debug("-> Handled {} commands in {}", receiveCommands.size(), receivePack.getRepository().getDirectory().getAbsolutePath());
     }
 
     private void handleSnapshotPostException(

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

@@ -27,6 +27,10 @@ public class Log {
         logger.debug(msg, t);
     }
 
+    public static void debug(String format, Object... args) {
+        logger.info(format, args);
+    }
+
     public static void info(String msg) {
         logger.info(msg);
     }

services/git-bridge/src/main/resources/logback.xml

@@ -22,10 +22,10 @@
     </appender>
 
     <!-- Set log levels for the application (or parts of the application). -->
-    <logger name="uk.ac.ic.wlgitbridge" level="INFO" />
+    <logger name="uk.ac.ic.wlgitbridge" level="DEBUG" />
 
     <!-- The root log level determines how much our dependencies put in the logs. -->
-    <root level="WARN">
+    <root level="INFO">
         <appender-ref ref="stdout" />
         <appender-ref ref="stderr" />
     </root>