Introduced generic logging and initial server side uncaught exception handling

java/com.sap.sailing.gwt.ui/src/main/java/com/sap/sailing/gwt/home/shared/dispatch/DispatchSystemImpl.java

@@ -1,8 +1,10 @@
 package com.sap.sailing.gwt.home.shared.dispatch;
 
+import com.google.gwt.core.shared.GWT;
 import com.google.gwt.user.client.rpc.AsyncCallback;
 import com.sap.sailing.gwt.ui.shared.dispatch.Action;
 import com.sap.sailing.gwt.ui.shared.dispatch.Result;
+import com.sap.sailing.gwt.ui.shared.dispatch.ServerDispatchException;
 
 public class DispatchSystemImpl implements DispatchSystem {
     
@@ -10,8 +12,25 @@ public class DispatchSystemImpl implements DispatchSystem {
     private final DispatchAsync dispatch = new AutomaticBatchingDispatch(simpleDispatch);
 
     @Override
-    public <R extends Result, A extends Action<R>> void execute(A action, AsyncCallback<R> callback) {
-        dispatch.execute(action, callback);
+    public <R extends Result, A extends Action<R>> void execute(final A action, final AsyncCallback<R> callback) {
+        // TODO: client side execution time logging
+        AsyncCallback<R> wrappedCallback = new AsyncCallback<R>() {
+            @Override
+            public void onFailure(Throwable caught) {
+                if (caught instanceof ServerDispatchException) {
+                    ServerDispatchException sde = (ServerDispatchException) caught;
+                    // TODO: browser console log
+                    GWT.log("Server exception with id: " + sde.getUuid());
+                }
+                callback.onFailure(caught);
+            }
+
+            @Override
+            public void onSuccess(R result) {
+                callback.onSuccess(result);
+            }
+        };
+        dispatch.execute(action, wrappedCallback);
     }
 
 }

java/com.sap.sailing.gwt.ui/src/main/java/com/sap/sailing/gwt/ui/server/dispatch/DispatchRPCImpl.java

@@ -1,5 +1,9 @@
 package com.sap.sailing.gwt.ui.server.dispatch;
 
+import java.util.UUID;
+import java.util.logging.Level;
+import java.util.logging.Logger;
+
 import org.osgi.framework.BundleContext;
 import org.osgi.util.tracker.ServiceTracker;
 
@@ -11,6 +15,7 @@ import com.sap.sailing.gwt.ui.shared.dispatch.DispatchException;
 import com.sap.sailing.gwt.ui.shared.dispatch.RequestWrapper;
 import com.sap.sailing.gwt.ui.shared.dispatch.Result;
 import com.sap.sailing.gwt.ui.shared.dispatch.ResultWrapper;
+import com.sap.sailing.gwt.ui.shared.dispatch.ServerDispatchException;
 import com.sap.sailing.gwt.ui.shared.dispatch.rpc.DispatchRPC;
 import com.sap.sailing.news.EventNewsService;
 import com.sap.sailing.server.RacingEventService;
@@ -18,6 +23,7 @@ import com.sap.sse.util.ServiceTrackerFactory;
 
 public class DispatchRPCImpl extends ProxiedRemoteServiceServlet implements DispatchRPC {
     private static final long serialVersionUID = -245230476512348999L;
+    private static final Logger logger = Logger.getLogger(DispatchRPCImpl.class.getName());
 
     private final ServiceTracker<RacingEventService, RacingEventService> racingEventServiceTracker;
     private final ServiceTracker<EventNewsService, EventNewsService> eventNewsServiceTracker;
@@ -31,8 +37,32 @@ public class DispatchRPCImpl extends ProxiedRemoteServiceServlet implements Disp
 
     @Override
     public <R extends Result, A extends Action<R>> ResultWrapper<R> execute(RequestWrapper<R, A> request) throws DispatchException {
-        R executionResult = request.getAction().execute(new DispatchContextImpl(request.getCurrentClientTime(), racingEventServiceTracker.getService(), eventNewsServiceTracker.getService(), request.getClientLocaleName()));
-        return new ResultWrapper<R>(executionResult);
+        A action = request.getAction();
+        long start = System.currentTimeMillis();
+        try {
+            R executionResult = action.execute(
+                    new DispatchContextImpl(request.getCurrentClientTime(), racingEventServiceTracker.getService(),
+                            eventNewsServiceTracker.getService(), request.getClientLocaleName()));
+            return new ResultWrapper<R>(executionResult);
+        } catch (DispatchException d) {
+            logger.log(Level.WARNING, "Server exception", d);
+            throw d;
+        } catch (Throwable t) {
+            String serverExceptionUUID = UUID.randomUUID().toString();
+            logger.log(Level.SEVERE, "Uncaught server exception id: " + serverExceptionUUID, t);
+            throw new ServerDispatchException(serverExceptionUUID, t);
+        } finally {
+            long duration = System.currentTimeMillis() - start;
+            final Level logLevel;
+            if (duration < 100) {
+                logLevel = Level.FINEST;
+            } else if (duration < 500) {
+                logLevel = Level.INFO;
+            } else {
+                logLevel = Level.WARNING;
+            }
+            logger.log(logLevel, "Dispatch took " + duration + "ms for " + action.getClass().getSimpleName());
+        }
     }
 
 }

java/com.sap.sailing.gwt.ui/src/main/java/com/sap/sailing/gwt/ui/shared/dispatch/BatchAction.java

@@ -29,8 +29,10 @@ public class BatchAction implements Action<BatchResult> {
         final int nrOfActions = getActions().length;
         final ArrayList<Result> results = new ArrayList<Result>(nrOfActions);
         final ArrayList<DispatchException> exceptions = new ArrayList<DispatchException>(nrOfActions);
+
         for (Action<?> a : getActions()) {
             Result result = null;
+            long start = System.currentTimeMillis();
             try {
                 result = a.execute(ctx);
                 exceptions.add(null);
@@ -38,6 +40,17 @@ public class BatchAction implements Action<BatchResult> {
                 DispatchException e2 = handleException(e);
                 exceptions.add(e2);
                 logger.log(Level.SEVERE, "Error trying to dispatch action from type " + a.getClass().getName(), e);
+            } finally {
+                long duration = System.currentTimeMillis() - start;
+                final Level logLevel;
+                if (duration < 100) {
+                    logLevel = Level.FINEST;
+                } else if (duration < 500) {
+                    logLevel = Level.INFO;
+                } else {
+                    logLevel = Level.WARNING;
+                }
+                logger.log(logLevel, "Dispatch took " + duration + "ms for " + a.getClass().getSimpleName());
             }
             results.add(result);
         }

java/com.sap.sailing.gwt.ui/src/main/java/com/sap/sailing/gwt/ui/shared/dispatch/ServerDispatchException.java

@@ -0,0 +1,21 @@
+package com.sap.sailing.gwt.ui.shared.dispatch;
+
+
+public class ServerDispatchException extends DispatchException {
+    
+    private static final long serialVersionUID = 8192187255698006941L;
+    private String uuid;
+    
+    protected ServerDispatchException() {
+    }
+
+    public ServerDispatchException(String uuid, Throwable cause) {
+        super(cause.getMessage());
+        this.uuid = uuid;
+    }
+
+    public String getUuid() {
+        return uuid;
+    }
+
+}

java/com.sap.sailing.gwt.ui/src/main/java/com/sap/sailing/gwt/ui/shared/dispatch/event/GetLiveRacesForEventAction.java

@@ -1,8 +1,6 @@
 package com.sap.sailing.gwt.ui.shared.dispatch.event;
 
 import java.util.UUID;
-import java.util.logging.Level;
-import java.util.logging.Logger;
 
 import com.google.gwt.core.shared.GwtIncompatible;
 import com.sap.sailing.gwt.ui.shared.dispatch.Action;
@@ -10,8 +8,6 @@ import com.sap.sailing.gwt.ui.shared.dispatch.DispatchContext;
 import com.sap.sailing.gwt.ui.shared.dispatch.ResultWithTTL;
 
 public class GetLiveRacesForEventAction implements Action<ResultWithTTL<LiveRacesDTO>> {
-    private static final Logger logger = Logger.getLogger(GetLiveRacesForEventAction.class.getName());
-    
     private UUID eventId;
     
     @SuppressWarnings("unused")
@@ -25,13 +21,9 @@ public class GetLiveRacesForEventAction implements Action<ResultWithTTL<LiveRace
     @Override
     @GwtIncompatible
     public ResultWithTTL<LiveRacesDTO> execute(DispatchContext context) {
-        long start = System.currentTimeMillis();
         LiveRaceCalculator liveRaceCalculator = new LiveRaceCalculator();
         RacesActionUtil.forRacesOfEvent(context, eventId, liveRaceCalculator);
         ResultWithTTL<LiveRacesDTO> result = liveRaceCalculator.getResult();
-        
-        long duration = System.currentTimeMillis() - start;
-        logger.log(Level.INFO, "Calculating live races for event "+ eventId + " took: "+ duration + "ms");
         return result;
     }
 }

java/com.sap.sailing.gwt.ui/src/main/java/com/sap/sailing/gwt/ui/shared/dispatch/event/GetMiniLeaderbordAction.java

@@ -20,7 +20,7 @@ import com.sap.sailing.server.RacingEventService;
 
 public class GetMiniLeaderbordAction implements Action<ResultWithTTL<ListResult<MiniLeaderboardItemDTO>>> {
     private static final Logger logger = Logger.getLogger(GetMiniLeaderbordAction.class.getName());
-    
+
     @SuppressWarnings("unused")
     private UUID eventId;
     private String leaderboardName;
@@ -39,24 +39,22 @@ public class GetMiniLeaderbordAction implements Action<ResultWithTTL<ListResult<
     public ResultWithTTL<ListResult<MiniLeaderboardItemDTO>> execute(DispatchContext context) {
         final Leaderboard leaderboard = context.getRacingEventService().getLeaderboardByName(leaderboardName);
         if (leaderboard == null) {
-            return new ResultWithTTL<ListResult<MiniLeaderboardItemDTO>>(1000 * 60 * 5, new ListResult<>(Collections.<MiniLeaderboardItemDTO>emptyList()));
+            return new ResultWithTTL<ListResult<MiniLeaderboardItemDTO>>(1000 * 60 * 5, new ListResult<>(
+                    Collections.<MiniLeaderboardItemDTO> emptyList()));
         }
         RacingEventService service = context.getRacingEventService();
         try {
-            LeaderboardDTO leaderboardDTO = leaderboard.getLeaderboardDTO(null,
-                    Collections.<String>emptyList(), true, service, service.getBaseDomainFactory(), false);
-            
+            LeaderboardDTO leaderboardDTO = leaderboard.getLeaderboardDTO(null, Collections.<String> emptyList(), true,
+                    service, service.getBaseDomainFactory(), false);
             int rank = 0;
             LinkedList<MiniLeaderboardItemDTO> items = new LinkedList<MiniLeaderboardItemDTO>();
-            for(CompetitorDTO competitor : leaderboardDTO.competitors) {
+            for (CompetitorDTO competitor : leaderboardDTO.competitors) {
                 rank++;
                 LeaderboardRowDTO row = leaderboardDTO.rows.get(competitor);
                 items.add(new MiniLeaderboardItemDTO(competitor, rank, row.totalPoints));
             }
-            return new ResultWithTTL<ListResult<MiniLeaderboardItemDTO>>(1000 * 60 * 5, new ListResult<MiniLeaderboardItemDTO>(items));
-            
-            // TODO: mini leaderboard magic
-            
+            return new ResultWithTTL<ListResult<MiniLeaderboardItemDTO>>(1000 * 60 * 5,
+                    new ListResult<MiniLeaderboardItemDTO>(items));
         } catch (Exception e) {
             logger.log(Level.SEVERE, "Error loading leaderboard", e);
             throw new DispatchException("Error loading leaderboard");