Add more debug output for view resolution

grails-core/src/main/groovy/grails/util/CacheEntry.java

@@ -15,6 +15,9 @@
  */
 package grails.util;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import java.util.concurrent.Callable;
 import java.util.concurrent.ConcurrentMap;
 import java.util.concurrent.atomic.AtomicReference;
@@ -34,6 +37,7 @@
  * @since 2.3.4
  */
 public class CacheEntry<V> {
+    private static final Logger LOG = LoggerFactory.getLogger(CacheEntry.class);
     private final AtomicReference<V> valueRef=new AtomicReference<V>(null);
     private long createdMillis;
     private final ReadWriteLock lock=new ReentrantReadWriteLock();
@@ -131,17 +135,24 @@ public V getValue(long timeout, Callable<V> updater, boolean returnExpiredWhileU
                         if(isInitialized()) {
                             return getValueWhileUpdating(cacheRequestObject);
                         } else {
+                            if(LOG.isDebugEnabled()) {
+                                LOG.debug("Locking cache for update");
+                            }
                             writeLock.lock();
                         }
                     }
                 } else {
+                    LOG.debug("Locking cache for update");
                     writeLock.lock();
                 }
                 lockAcquired = true;
                 V value;
                 if (!isInitialized() || shouldUpdate(beforeLockingCreatedMillis, cacheRequestObject)) {
                     try {
                         value = updateValue(getValue(), updater, cacheRequestObject);
+                        if(LOG.isDebugEnabled()) {
+                            LOG.debug("Updating cache for value [{}]", value);
+                        }
                         setValue(value);
                     }
                     catch (Exception e) {
@@ -154,6 +165,9 @@ public V getValue(long timeout, Callable<V> updater, boolean returnExpiredWhileU
                 return value;
             } finally {
                 if(lockAcquired) {
+                    if(LOG.isDebugEnabled()) {
+                        LOG.debug("Unlocking cache for update");
+                    }
                     writeLock.unlock();
                 }
             }

grails-gsp/src/main/groovy/org/grails/gsp/io/DefaultGroovyPageLocator.java

@@ -28,6 +28,8 @@
 import org.grails.io.support.GrailsResourceUtils;
 import org.grails.plugins.BinaryGrailsPlugin;
 import org.grails.taglib.TemplateVariableBinding;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.beans.BeansException;
 import org.springframework.context.ApplicationContext;
 import org.springframework.context.ApplicationContextAware;
@@ -53,7 +55,7 @@
  */
 public class DefaultGroovyPageLocator implements GroovyPageLocator, ResourceLoaderAware, ApplicationContextAware, PluginManagerAware {
 
-    private static final Log LOG = LogFactory.getLog(DefaultGroovyPageLocator.class);
+    private static final Logger LOG = LoggerFactory.getLogger(DefaultGroovyPageLocator.class);
     public static final String PATH_TO_WEB_INF_VIEWS = "/WEB-INF/grails-app/views";
     private static final String SLASHED_VIEWS_DIR_PATH = "/" + GrailsResourceUtils.VIEWS_DIR_PATH;
     private static final String PLUGINS_PATH = "/plugins/";
@@ -204,8 +206,14 @@ protected GroovyPageScriptSource findBinaryScriptSource(String uri) {
             }
 
             BinaryGrailsPlugin binaryPlugin = (BinaryGrailsPlugin) plugin;
+            if(LOG.isDebugEnabled()) {
+                LOG.debug("Searching plugin [{}] for GSP view [{}]", plugin.getName(), uri);
+            }
             GroovyPageScriptSource scriptSource = resolveViewInBinaryPlugin(binaryPlugin, uri);
             if (scriptSource != null) {
+                if(LOG.isDebugEnabled()) {
+                    LOG.debug("Found GSP view [{}] in plugin [{}]", uri, plugin.getName());
+                }
                 return scriptSource;
             }
             else if(binaryPlugin.getProjectDirectory() != null) {
@@ -296,22 +304,21 @@ protected List<String> resolveSearchPaths(String uri) {
 
         uri = removeViewLocationPrefixes(uri);
         if (warDeployed) {
-            if (uri.startsWith(PLUGINS_PATH)) {
-                PluginViewPathInfo pathInfo = getPluginViewPathInfo(uri);
-
-                searchPaths = CollectionUtils.newList(
-                        GrailsResourceUtils.appendPiecesForUri(GrailsResourceUtils.WEB_INF, PLUGINS_PATH, pathInfo.pluginName, GrailsResourceUtils.VIEWS_DIR_PATH, pathInfo.path),
-                        GrailsResourceUtils.appendPiecesForUri(GrailsResourceUtils.WEB_INF, uri),
-                        uri);
-            } else {
-                searchPaths = CollectionUtils.newList(
-                        GrailsResourceUtils.appendPiecesForUri(PATH_TO_WEB_INF_VIEWS, uri),
-                        uri);
-            }
+                if (uri.startsWith(PLUGINS_PATH)) {
+                    PluginViewPathInfo pathInfo = getPluginViewPathInfo(uri);
+
+                    searchPaths = CollectionUtils.newList(
+                            GrailsResourceUtils.appendPiecesForUri(GrailsResourceUtils.WEB_INF, PLUGINS_PATH, pathInfo.pluginName, GrailsResourceUtils.VIEWS_DIR_PATH, pathInfo.path),
+                            GrailsResourceUtils.appendPiecesForUri(GrailsResourceUtils.WEB_INF, uri),
+                            uri);
+                } else {
+                    searchPaths = CollectionUtils.newList(
+                            GrailsResourceUtils.appendPiecesForUri(PATH_TO_WEB_INF_VIEWS, uri),
+                            uri);
+                }
         } else {
             searchPaths = CollectionUtils.newList(
                 GrailsResourceUtils.appendPiecesForUri(SLASHED_VIEWS_DIR_PATH, uri),
-                GrailsResourceUtils.appendPiecesForUri(PATH_TO_WEB_INF_VIEWS, uri),
                 uri);
         }
         return searchPaths;
@@ -323,21 +330,34 @@ protected GroovyPageScriptSource findResourceScriptPathForSearchPaths(String uri
             for (String searchPath : searchPaths) {
                 String gspClassName = precompiledGspMap.get(searchPath);
                 if (gspClassName != null && !reloadedPrecompiledGspClassNames.contains(gspClassName)) {
+                    if(LOG.isDebugEnabled()) {
+                        LOG.debug("Found pre-compiled GSP template [{}] for path [{}]", gspClassName, searchPath);
+                    }
                     Class<GroovyPage> gspClass = null;
                     try {
+                        if(LOG.isDebugEnabled()) {
+                            LOG.debug("Loading GSP template [{}]", gspClassName);
+                        }
                         gspClass = (Class<GroovyPage>) Class.forName(gspClassName, true, Thread.currentThread().getContextClassLoader());
                     } catch (ClassNotFoundException e) {
                         LOG.warn("Cannot load class " + gspClassName + ". Resuming on non-precompiled implementation.", e);
                     }
                     if (gspClass != null) {
-                        return createGroovyPageCompiledScriptSource(uri, searchPath, gspClass);
+                        GroovyPageCompiledScriptSource groovyPageCompiledScriptSource = createGroovyPageCompiledScriptSource(uri, searchPath, gspClass);
+                        if(LOG.isDebugEnabled()) {
+                            LOG.debug("Returning new GSP script source for class [{}]", gspClassName);
+                        }
+                        return groovyPageCompiledScriptSource;
                     }
                 }
             }
         }
+        else {
+            Resource foundResource = findResource(searchPaths);
+            return foundResource == null ? null : new GroovyPageResourceScriptSource(uri, foundResource);
+        }
 
-        Resource foundResource = findResource(searchPaths);
-        return foundResource == null ? null : new GroovyPageResourceScriptSource(uri, foundResource);
+        return null;
     }
 
     protected Resource findResource(String uri) {

grails-web-gsp/src/main/groovy/org/grails/web/servlet/view/GrailsLayoutViewResolver.java

@@ -21,6 +21,8 @@
 
 import org.grails.web.sitemesh.GrailsLayoutView;
 import org.grails.web.sitemesh.GroovyPageLayoutFinder;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.beans.BeansException;
 import org.springframework.context.ApplicationContext;
 import org.springframework.context.ApplicationContextAware;
@@ -31,6 +33,8 @@
 import org.springframework.web.servlet.ViewResolver;
 
 public class GrailsLayoutViewResolver implements LayoutViewResolver, Ordered, ServletContextAware, ApplicationContextAware {
+    private static final Logger LOG = LoggerFactory.getLogger(GrailsLayoutViewResolver.class);
+
     protected ViewResolver innerViewResolver;
     protected GroovyPageLayoutFinder groovyPageLayoutFinder;
     private int order = Ordered.LOWEST_PRECEDENCE - 30;
@@ -47,12 +51,18 @@ public GrailsLayoutViewResolver() {
 
     @Override
     public View resolveViewName(String viewName, Locale locale) throws Exception {
+        if(LOG.isDebugEnabled()) {
+            LOG.debug("Resolving view for name {} and locale {}", viewName, locale);
+        }
         View innerView = innerViewResolver.resolveViewName(viewName, locale);
         if(innerView == null) {
             return null;
         } else if(innerView instanceof SmartView && ((SmartView)innerView).isRedirectView()) { 
             return innerView;
         } else {
+            if(LOG.isDebugEnabled()) {
+                LOG.debug("Creating layout view name {} and locale {}", viewName, locale);
+            }
             return createLayoutView(innerView);
         }
     }

grails-web-gsp/src/main/groovy/org/grails/web/servlet/view/GroovyPageViewResolver.java

@@ -33,6 +33,8 @@
 import org.grails.gsp.io.GroovyPageScriptSource;
 import org.grails.web.servlet.mvc.GrailsWebRequest;
 import org.grails.web.util.WebUtils;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.beans.factory.annotation.Qualifier;
 import org.springframework.core.Ordered;
@@ -49,7 +51,7 @@
  * @since 0.1
  */
 public class GroovyPageViewResolver extends InternalResourceViewResolver implements GrailsViewResolver {
-    private static final Log LOG = LogFactory.getLog(GroovyPageViewResolver.class);
+    private static final Logger LOG = LoggerFactory.getLogger(GroovyPageViewResolver.class);
 
     public static final String GSP_SUFFIX = ".gsp";
     public static final String JSP_SUFFIX = ".jsp";
@@ -143,8 +145,8 @@ public View call() throws Exception {
      * @return prefix for cache key that contains current controller's context (currently plugin and namespace)
      */
     protected String resolveCurrentControllerKeyPrefixes() {
-        String pluginContextPath = null;
-        String namespace = null;
+        String pluginContextPath;
+        String namespace;
         GrailsWebRequest webRequest = GrailsWebRequest.lookup();
         if(webRequest != null) {
             namespace = webRequest.getControllerNamespace();
@@ -183,9 +185,15 @@ protected View createGrailsView(String viewName) throws Exception {
 
         GroovyPageScriptSource scriptSource;
         if (controller == null) {
+            if(LOG.isDebugEnabled()) {
+                LOG.debug("Locating GSP view for path {}", viewName);
+            }
             scriptSource = groovyPageLocator.findViewByPath(viewName);
         }
         else {
+            if(LOG.isDebugEnabled()) {
+                LOG.debug("Locating GSP view for controller {} and path {}",controller, viewName);
+            }
             scriptSource = groovyPageLocator.findView(controller, viewName);
         }
         if (scriptSource != null) {
@@ -208,6 +216,9 @@ private View createGroovyPageView(String gspView, ScriptSource scriptSource) {
         gspSpringView.setScriptSource(scriptSource);
         try {
             gspSpringView.afterPropertiesSet();
+            if (LOG.isDebugEnabled()) {
+                LOG.debug("Initialized GSP view for URI [{}]", gspView);
+            }
         } catch (Exception e) {
             throw new RuntimeException("Error initializing GroovyPageView", e);
         }
@@ -216,6 +227,9 @@ private View createGroovyPageView(String gspView, ScriptSource scriptSource) {
 
     protected View createFallbackView(String viewName) throws Exception {
         if(resolveJspView) {
+            if(LOG.isDebugEnabled()) {
+                LOG.debug("No GSP view found, falling back to locating JSTL view for name [{}]", viewName);
+            }
             return createJstlView(viewName);
         }
         return null;

grails-web-sitemesh/src/main/groovy/org/grails/web/sitemesh/GrailsLayoutView.java

@@ -26,13 +26,16 @@
 import org.grails.web.servlet.WrappedResponseHolder;
 import org.grails.web.servlet.mvc.GrailsWebRequest;
 import org.grails.web.servlet.view.AbstractGrailsView;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.http.MediaType;
 import org.springframework.web.servlet.View;
 
 import com.opensymphony.module.sitemesh.RequestConstants;
 import com.opensymphony.sitemesh.Content;
 
 public class GrailsLayoutView extends AbstractGrailsView {
+    private static final Logger LOG = LoggerFactory.getLogger(GrailsLayoutView.class);
     GroovyPageLayoutFinder groovyPageLayoutFinder;
 
     protected View innerView;
@@ -54,6 +57,7 @@ protected void renderTemplate(Map<String, Object> model, GrailsWebRequest webReq
             HttpServletResponse response) throws Exception {
             Content content = obtainContent(model, webRequest, request, response);
         if (content != null) {
+
             beforeDecorating(content, model, webRequest, request, response);
             switch (request.getDispatcherType()) {
                 case INCLUDE:
@@ -62,14 +66,24 @@ protected void renderTemplate(Map<String, Object> model, GrailsWebRequest webReq
                 case ERROR:
                 case FORWARD:
                 case REQUEST:
+                    if(LOG.isDebugEnabled()) {
+                        LOG.debug("Finding layout for request and content" );
+                    }
                     SpringMVCViewDecorator decorator = (SpringMVCViewDecorator) groovyPageLayoutFinder.findLayout(request, content);
                     if (decorator != null) {
+                        if(LOG.isDebugEnabled()) {
+                            LOG.debug("Found layout. Rendering content for layout and model {}", decorator.getPage(), model);
+                        }
+
                         decorator.render(content, model, request, response, webRequest.getServletContext());
                         return;
                     }
                     break;
             }
             PrintWriter writer = response.getWriter();
+            if(LOG.isDebugEnabled()) {
+                LOG.debug("Layout not applicable to response, writing original content");
+            }
             content.writeOriginal(writer);
             if (!response.isCommitted()) {
                 writer.flush();
@@ -122,6 +136,9 @@ protected Content obtainContent(Map<String, Object> model, GrailsWebRequest webR
     protected void renderInnerView(Map<String, Object> model, GrailsWebRequest webRequest, HttpServletRequest request,
             HttpServletResponse response,
             GrailsContentBufferingResponse contentBufferingResponse) throws Exception {
+        if(LOG.isDebugEnabled()) {
+            LOG.debug("Rendering inner view for layout and model {}", model);
+        }
         innerView.render(model, request, contentBufferingResponse);
     }
 

grails-web-sitemesh/src/main/groovy/org/grails/web/sitemesh/GroovyPageLayoutFinder.java

@@ -36,6 +36,8 @@
 import org.grails.web.servlet.view.AbstractGrailsView;
 import org.grails.web.servlet.view.GrailsViewResolver;
 import org.grails.web.servlet.view.LayoutViewResolver;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.context.ApplicationListener;
 import org.springframework.context.event.ContextRefreshedEvent;
 import org.springframework.web.servlet.View;
@@ -56,7 +58,7 @@ public class GroovyPageLayoutFinder implements ApplicationListener<ContextRefres
     public static final String LAYOUT_ATTRIBUTE = "org.grails.layout.name";
     public static final String NONE_LAYOUT = "_none_";
     public static final String RENDERING_VIEW_ATTRIBUTE = "org.grails.rendering.view";
-    private static final Log LOG = LogFactory.getLog(GrailsLayoutDecoratorMapper.class);
+    private static final Logger LOG = LoggerFactory.getLogger(GrailsLayoutDecoratorMapper.class);
     private static final long LAYOUT_CACHE_EXPIRATION_MILLIS = Long.getLong("grails.gsp.reload.interval", 5000);
     private static final String LAYOUTS_PATH = "/layouts";
 
@@ -124,7 +126,7 @@ public Decorator findLayout(HttpServletRequest request, Page page) {
                     if(controllerName != null && actionUri != null) {
 
                         if (LOG.isDebugEnabled()) {
-                            LOG.debug("Found controller in request, location layout for controller [" + controllerName
+                            LOG.debug("Found controller in request, locating layout for controller [" + controllerName
                                     + "] and action [" + actionUri + "]");
                         }
 
@@ -145,6 +147,9 @@ public Decorator findLayout(HttpServletRequest request, Page page) {
                         if (d == null && !cachedIsNull) {
                             d = resolveDecorator(request, controller, controllerName, actionUri);
                             if (cacheEnabled) {
+                                if(LOG.isDebugEnabled() && d != null) {
+                                    LOG.debug("Caching resolved layout {} for controller {} and action {}",d.getPage(), controllerName, actionUri);
+                                }
                                 layoutDecoratorCache.put(cacheKey, new DecoratorCacheValue(d));
                             }
                         }