Improved server logging

ekuiter · Nov 19, 2018 · dc29257 · dc29257
1 parent 1b50fde
commit dc29257
Show file tree

Hide file tree

Showing 13 changed files with 138 additions and 41 deletions.
diff --git a/server/build.gradle b/server/build.gradle
@@ -32,6 +32,8 @@ dependencies {
     compile 'com.google.code.gson:gson:2.8.5'
     compile 'me.atrox.haikunator:Haikunator:1.3'
     compile 'org.jsweet:jsweet-core:6-SNAPSHOT'
+    compile 'org.tinylog:tinylog:1.3.5'
+    compile 'com.github.tobiasrm:tinylog-coloredconsole:1.3.1'
     compile fileTree(dir: 'lib', include: '*.jar')
 }
 

diff --git a/server/src/main/java/de/ovgu/spldev/varied/Artifact.java b/server/src/main/java/de/ovgu/spldev/varied/Artifact.java
@@ -23,10 +23,18 @@ public String getName() {
         return name;
     }
 
+    public Project getProject() {
+        return project;
+    }
+
     public Path getPath() {
         return new Path(project.getName(), name);
     }
 
+    public String toString() {
+        return getPath().toString();
+    }
+
     abstract public CollaborativeSession getCollaborativeSession();
 
     public static class Path {

diff --git a/server/src/main/java/de/ovgu/spldev/varied/CollaborativeSession.java b/server/src/main/java/de/ovgu/spldev/varied/CollaborativeSession.java
@@ -3,6 +3,7 @@
 import de.ovgu.spldev.varied.messaging.Api;
 import de.ovgu.spldev.varied.messaging.Message;
 import de.ovgu.spldev.varied.common.operations.Operation;
+import org.pmw.tinylog.Logger;
 
 import java.util.HashSet;
 import java.util.Objects;
@@ -21,7 +22,12 @@ public class CollaborativeSession {
         this.stateContext = Objects.requireNonNull(stateContext, "no state context given");
     }
 
+    public String toString() {
+        return stateContext.toString();
+    }
+
     public void join(User newUser) {
+        Logger.info("{} joins collaborative session {}", newUser, this);
         if (!users.add(newUser))
             throw new RuntimeException("user already joined");
         stateContext.sendInitialState(newUser);
@@ -30,6 +36,7 @@ public void join(User newUser) {
     }
 
     public void leave(User oldUser) {
+        Logger.info("{} leaves collaborative session {}", oldUser, this);
         if (users.remove(oldUser))
             broadcast(new Api.Leave(stateContext.getArtifactPath(), oldUser));
     }
@@ -59,23 +66,29 @@ private void broadcast(Message.IEncodable[] messages) {
     }
 
     public void onMessage(Message message) {
+        Logger.info("decoding message {}", message);
         Message.IDecodable decodableMessage = (Message.IDecodable) message;
         if (!decodableMessage.isValid(stateContext))
             throw new RuntimeException("invalid message " + message);
         Message.IEncodable[] response = null;
         if (message instanceof Message.IApplicable) {
+            Logger.info("processing applicable message {}", message);
             Message.IApplicable applicableMessage = (Message.IApplicable) message;
             response = applicableMessage.apply(stateContext);
         } else if (message instanceof Message.IUndoable) {
+            Logger.info("processing undoable message {}", message);
             Message.IUndoable undoableMessage = (Message.IUndoable) message;
             Operation operation = undoableMessage.getOperation(stateContext);
             if (operation != null) {
+                Logger.info("applying operation {}", operation);
                 stateContext.getOperationStack().apply(operation);
                 response = undoableMessage.getResponse(stateContext);
             }
         } else
             throw new RuntimeException("message can not be processed");
-        if (response != null)
+        if (response != null) {
+            Logger.info("broadcasting {} response message(s)", response.length);
             broadcast(response);
+        }
     }
 }
diff --git a/server/src/main/java/de/ovgu/spldev/varied/OperationStack.java b/server/src/main/java/de/ovgu/spldev/varied/OperationStack.java
@@ -2,6 +2,7 @@
 
 import de.ovgu.spldev.varied.common.operations.Operation;
 import edu.washington.cs.courses.cse143.UndoRedoStack;
+import org.pmw.tinylog.Logger;
 
 public class OperationStack {
     private UndoRedoStack<Operation> operationUndoRedoStack = new UndoRedoStack<>();
@@ -23,6 +24,7 @@ public void undo() {
         if (!operationUndoRedoStack.canUndo())
             throw new RuntimeException("can not undo");
         Operation operation = operationUndoRedoStack.peekUndoneValue();
+        Logger.debug("undoing operation {}", operation);
         operation.undo();
         operationUndoRedoStack.undo();
     }
@@ -31,6 +33,7 @@ public void redo() {
         if (!operationUndoRedoStack.canRedo())
             throw new RuntimeException("can not redo");
         Operation operation = operationUndoRedoStack.peekRedoneValue();
+        Logger.debug("redoing operation {}", operation);
         operation.apply();
         operationUndoRedoStack.redo();
     }

diff --git a/server/src/main/java/de/ovgu/spldev/varied/Project.java b/server/src/main/java/de/ovgu/spldev/varied/Project.java
@@ -1,6 +1,7 @@
 package de.ovgu.spldev.varied;
 
 import de.ovgu.spldev.varied.common.util.StringUtils;
+import org.pmw.tinylog.Logger;
 
 import java.util.Collection;
 import java.util.concurrent.ConcurrentHashMap;
@@ -19,14 +20,21 @@ public String getName() {
         return name;
     }
 
+    public String toString() {
+        return name;
+    }
+
     Artifact getArtifact(String name) {
         return artifacts.get(name);
     }
 
     void addArtifact(Artifact artifact) {
+        Logger.info("adding artifact {} to project {}", artifact, this);
         String name = artifact.getName();
         if (!StringUtils.isPresent(name))
             throw new RuntimeException("no name given for artifact");
+        if (artifact.getProject() != this)
+            throw new RuntimeException("artifact registered with another project");
         if (artifacts.containsValue(artifact))
             throw new RuntimeException("artifact already registered");
         if (artifacts.containsKey(name))
@@ -35,6 +43,7 @@ void addArtifact(Artifact artifact) {
     }
 
     public void removeArtifact(Artifact artifact) {
+        Logger.info("removing artifact {} from project {}", artifact, this);
         artifacts.remove(artifact.getName());
     }
 

diff --git a/server/src/main/java/de/ovgu/spldev/varied/ProjectManager.java b/server/src/main/java/de/ovgu/spldev/varied/ProjectManager.java
@@ -1,6 +1,7 @@
 package de.ovgu.spldev.varied;
 
 import de.ovgu.spldev.varied.common.util.StringUtils;
+import org.pmw.tinylog.Logger;
 
 import java.util.ArrayList;
 import java.util.Collection;
@@ -32,6 +33,7 @@ public Project getProject(String name) {
     }
 
     public void addProject(Project project) {
+        Logger.info("adding project {}", project);
         String name = project.getName();
         if (!StringUtils.isPresent(name))
             throw new RuntimeException("no name given for project");
@@ -43,6 +45,7 @@ public void addProject(Project project) {
     }
 
     public void removeProject(Project project) {
+        Logger.info("removing project {}", project);
         projects.remove(project.getName());
     }
 

diff --git a/server/src/main/java/de/ovgu/spldev/varied/StateContext.java b/server/src/main/java/de/ovgu/spldev/varied/StateContext.java
@@ -2,6 +2,7 @@
 
 import de.ovgu.featureide.fm.core.base.IFeatureModel;
 import de.ovgu.spldev.varied.messaging.Api;
+import org.pmw.tinylog.Logger;
 
 import java.util.Objects;
 
@@ -21,7 +22,16 @@ public OperationStack getOperationStack() {
         return operationStack;
     }
 
-    abstract void sendInitialState(User user);
+    public String toString() {
+        return artifactPath.toString();
+    }
+
+    void sendInitialState(User user) {
+        Logger.info("sending initial state to user {}", user);
+        _sendInitialState(user);
+    }
+
+    abstract void _sendInitialState(User user);
 
     public static class FeatureModel extends StateContext {
         private IFeatureModel featureModel;
@@ -35,7 +45,7 @@ public IFeatureModel getFeatureModel() {
             return featureModel;
         }
 
-        public void sendInitialState(User user) {
+        public void _sendInitialState(User user) {
             user.send(new Api.FeatureDiagramFeatureModel(artifactPath, featureModel));
         }
     }

diff --git a/server/src/main/java/de/ovgu/spldev/varied/User.java b/server/src/main/java/de/ovgu/spldev/varied/User.java
@@ -5,6 +5,7 @@
 import de.ovgu.spldev.varied.messaging.Message;
 import me.atrox.haikunator.Haikunator;
 import me.atrox.haikunator.HaikunatorBuilder;
+import org.pmw.tinylog.Logger;
 
 import java.util.ArrayList;
 import java.util.Objects;
@@ -38,10 +39,12 @@ public User(String name, WebSocket webSocket) {
     }
 
     public void send(Message.IEncodable message) {
+        Logger.info("sending message {} to user {}", message, this);
         webSocket.send(message);
     }
 
     public void sendInitialInformation() {
+        Logger.info("sending initial information to user {}", this);
         send(new Api.UserInfo(this));
         for (Artifact artifact : ProjectManager.getInstance().getArtifacts())
             send(new Api.ArtifactInfo(artifact.getPath()));
@@ -61,31 +64,38 @@ public String toString() {
 
     public void onMessage(Message message) {
         Objects.requireNonNull(message, "no message given");
+        Logger.info("received message {} from user {}", message, this);
 
         if (message.getArtifactPath() == null)
             throw new RuntimeException("no artifact path given");
 
         // This essentially forces the server to handle only one message at a time.
         // This assumption simplifies multithreaded access to feature models, but limits server performance.
         synchronized (lock) {
-            Artifact artifact = ProjectManager.getInstance().getArtifact(message.getArtifactPath());
-            if (artifact == null)
-                throw new RuntimeException("no artifact found for path " + message.getArtifactPath());
-            CollaborativeSession collaborativeSession = artifact.getCollaborativeSession();
-
-            if (message.isType(Api.TypeEnum.JOIN) || message.isType(Api.TypeEnum.LEAVE)) {
-                if (message.isType(Api.TypeEnum.JOIN))
-                    joinCollaborativeSession(collaborativeSession);
-                if (message.isType(Api.TypeEnum.LEAVE))
-                    leaveCollaborativeSession(collaborativeSession);
-                return;
-            }
-
-            for (CollaborativeSession _collaborativeSession : collaborativeSessions)
-                if (_collaborativeSession == collaborativeSession) {
-                    collaborativeSession.onMessage(message);
+            Logger.debug("entering locked region");
+            try {
+                Artifact artifact = ProjectManager.getInstance().getArtifact(message.getArtifactPath());
+                if (artifact == null)
+                    throw new RuntimeException("no artifact found for path " + message.getArtifactPath());
+                CollaborativeSession collaborativeSession = artifact.getCollaborativeSession();
+                Logger.debug("message concerns collaborative session {}", collaborativeSession);
+
+                if (message.isType(Api.TypeEnum.JOIN) || message.isType(Api.TypeEnum.LEAVE)) {
+                    if (message.isType(Api.TypeEnum.JOIN))
+                        joinCollaborativeSession(collaborativeSession);
+                    if (message.isType(Api.TypeEnum.LEAVE))
+                        leaveCollaborativeSession(collaborativeSession);
                     return;
                 }
+
+                for (CollaborativeSession _collaborativeSession : collaborativeSessions)
+                    if (_collaborativeSession == collaborativeSession) {
+                        collaborativeSession.onMessage(message);
+                        return;
+                    }
+            } finally {
+                Logger.debug("leaving locked region");
+            }
         }
 
         throw new RuntimeException("did not join collaborative session for given artifact path");

diff --git a/server/src/main/java/de/ovgu/spldev/varied/UserManager.java b/server/src/main/java/de/ovgu/spldev/varied/UserManager.java
@@ -2,6 +2,7 @@
 
 import de.ovgu.spldev.varied.common.util.StringUtils;
 import de.ovgu.spldev.varied.messaging.Message;
+import org.pmw.tinylog.Logger;
 
 import java.util.concurrent.ConcurrentHashMap;
 
@@ -26,6 +27,7 @@ boolean isNameAvailable(String name) {
     }
 
     public void register(User newUser) {
+        Logger.info("registering user {}", newUser);
         String name = newUser.getName();
         if (!StringUtils.isPresent(name))
             throw new RuntimeException("no name supplied on registration");
@@ -44,6 +46,7 @@ public void register(WebSocket webSocket) {
     }
 
     public void unregister(User oldUser) {
+        Logger.info("unregistering user {}", oldUser);
         oldUser.leaveAllCollaborativeSessions();
         users.remove(oldUser.getWebSocket());
     }