Mac: JSF: why are development stage JSF web apps not always catching composite component changes?

Question

Mac OS X: Yosemite 10.10.5
NetBeans8.1beta or NetBeans8.1
Glassfish4.1 or Glassfish4.1.1
Mojarra 2.2.7 or 2.2.12 [2016-08-14 EDIT: or 2.2.8-17]
[EDIT: Primefaces 5.3]

I am an experienced NetBeans + JSF developer, which is to say I know how it is supposed to work, and usually works, but this is for some reason no longer working properly, on one (and only one as far as I can tell) MacBook Pro machine [EDIT: 2016-08-14 and also on a MacMini with the same OS X Version].

Short description of the problem: A few days ago, while I was happily developing a large JSF/Primefaces web application, I found that after a couple of reloads of complex JSF/Primefaces pages I was working on it stopped updating/reflecting changes I made (and saved) in composite components. I found however that if I wait for some minutes, I could then perform the reload again ok, for a few times, reflecting the CC changes, until it "got stuck" again.

It happens, as far as I can tell, only on my main development machine which is a MacBook Pro 15" (macbookpro11,3 Mid2014.).

[EDIT: 2016-08-14 Now reproduced also on a macmini4,1 Mid2010 running the same OS X version and running a (slightly) adapted *copied* version of the entire same NetBeans/GlassFish setup NB8.1Beta/GF4.1, and with JSF 2.2.8-17]

It does not seem to matter whether:

• I use NetBeans-8.1beta/Glassfish4.1 or NetBeans8.1/Glassfish4.1.1 [ASIDE: the reason I am mostly using NB8.1beta/GF4.1 not NB8.1/GF4.1.1 is explained at: https://stackoverflow.com/questions/35681181/jsfobjectdb-why-might-deployment-of-a-large-web-app-to-glassfish-4-1-1-take-5]

• I use a completely fresh NetBeans+Glassfish install or an existing one.

• I use JDK1.7 (jdk1.7.0_51.jdk) or JDK1.8 (jdk1.8.0_60.jdk) (including for NetBeans/Glassfish and/or for source code compilation and execution).

• I use a project that involves Git (the problem first happened in a large project, but I have since reproduced it in the simplest of projects without Git, i.e. it has something to only with what is happening detecting facelets changes under /build/web/).

• I use Primefaces or not (I can get it to happen in a very basic JSF app).

• I use a clean GET reload or a browser command reload.

But it does NOT happen, as far as I can tell, with an almost identical setup on an older MacMini (macmini4,1 Mid2010).

[EDIT: 2016-08-14 Yes it does happen on that MacMini too if I reload JSF pages often enough in the full, large web app I am developing, not just a mini test app]

Some other things I think I know about it:

• This is with the Deploy on Save feature OFF in all cases.

• It does not seem to afflict JSF templates or includes, it only seems to afflict composite components.

• It is not a problem with the javax.faces.FACELETS_REFRESH_PERIOD (which by default for mojarra is 2). If I change it to 0, the problem vanishes (there is no caching) but the load/reload times for large complex JSF pages becomes painful, in some cases minutes instead of seconds.

• Just moving from one JSF page to another does not help.

• It makes no difference what JSF scope I use.

• It happens with an application deployed over /build/web.

• The timestamps of the changed XHTML files for the composite components are definitely changing as a I save them in NetBeans (they are being copied correctly into /build/web/resources/...).

• I have not done any OS software updates or installs for many days.

I made screencasts (not available here) of the entire problem as reported below.

Experience with the original very large web app

When I first encountered the problem it was in a very large web app. I noticed it with a tiny little composite component that generates some text with a style class (for an icon), which CC was used inside a p:accordionPanel and p:tab. I found that after reloading the changes a couple of times it would stop catching the changes. It was only by accident that I discovered that if I wait many minutes, sometimes up to 10 minutes, it would then "catch" the change.

I then went back in my commits a few days, to a time when I clearly was able to develop without any problem, and the problem happened again ! I have tested this many times, whatever the problem is, it is not in the .git commit (which includes /nbproject/private but not all subfolders of /nbproject/private).

Experience with a smaller Primefaces test web app

I then tried it with a much smaller test web app with some Primefaces test pages. I was able to reproduce the problem if I reloaded the index.xhtml page a few times, while changing a tiny one-implementation-line composite component used in the index.html page. I then found I had to wait about 10 seconds or sometimes a whole minute, and then the change would "catch" again.

Experience with a tiny JSF core web app

With one index.xhtml, and a single composite component with a single h:outputText word, I could get the problem to happen if I saved the CC and then reloaded the index.xhtml very quickly. I am not talking about it not appearing to change (because one "beat" the javax.faces.FACELETS_REFRESH_PERIOD) I am talking about it "locking up" so that it does not catch the change in the CC at all after that, no matter how often one reloads the page, until the Ghost in the Machine decides to "unlock" itself.

Normally I would indeed provide an example or 'Steps to reproduce the problem' but it makes little sense to do it; when I move the test project from one machine (my MacBook Pro) to another (the MacMini running the same OS version) the problem vanishes. And I can get it to happen (on my main MacBook Pro development machine) with the simplest possible NetBeans JSF web app with an index.xhtml that includes a single CC.

[EDIT: 2016-08-14 I can indeed reproduce it on that MacMini running the same OS version, but I could only reproduce it so far with the very large web app I am developing, which can't easily be provided to others for testing (and I would need, for example, to strip out the ObjectDB database dependency and provide dummy data)]

I realise that normally one asks a single question on Stackoverflow, but answers to any of these, which might help me move forward, would be appreciated:

Q0: Has anybody experienced anything similar (on a Mac) ?

Q1: What else can I try to diagnose it ? I am out of ideas.

Q2: Does anybody know of anything specific to a MacBook Pro that might affect the polling/detection of changes in the build/web folders that could explain it ?

Q3: Is there anything about how Facelets and/or Glassfish work together with an application deployed over /build/web that might explain it ?

Answer 1

It seems I can't debug correctly all the stack trace through com.sun.faces.facelets.impl.DefaultFaceletFactory.createFacelet(URL), the source code is not aligned with compiled classes for jsf-impl-2.2.12-jbossorg-2.jar.

To cut a long story short, I rewrote the cache.

With this new cache, createFacelet(URL) is now called one time for facelet on each request, effectively reloading composite component facelets changes.

This cache implementation it's not fully tested and absolutely it's not production-ready, but it's a start.

Nevertheless it should be thread-safe, because the internal semi-cache is request scoped.

Note that I've used only API imports (javax.faces.*) and no com.sun.faces.*, so this should work with any Mojarra/MyFaces 2.2.x implementation.

public class DebugFaceletCacheFactory extends FaceletCacheFactory
{
    protected final FaceletCacheFactory wrapped;

    public DebugFaceletCacheFactory(FaceletCacheFactory wrapped)
    {
        this.wrapped = wrapped;
    }

    @Override
    public FaceletCacheFactory getWrapped()
    {
        return wrapped;
    }

    @Override
    public FaceletCache<?> getFaceletCache()
    {
        return new DebugFaceletCache();
    }

    public static class DebugFaceletCache extends FaceletCache<Facelet>
    {
        protected static final String MEMBER_CACHE_KEY = DebugFaceletCache.class.getName() + "#MEMBER_CACHE";

        protected static final String METADATA_CACHE_KEY = DebugFaceletCache.class.getName() + "#METADATA_CACHE";

        protected Map<URL, Facelet> getCache(String key)
        {
            Map<String, Object> requestMap = FacesContext.getCurrentInstance().getExternalContext().getRequestMap();

            Map<URL, Facelet> cache = (Map<URL, Facelet>) requestMap.get(key);
            if(cache == null)
            {
                cache = new HashMap<>();
                requestMap.put(key, cache);
            }

            return cache;
        }

        protected MemberFactory<Facelet> getFactory(String key)
        {
            if(MEMBER_CACHE_KEY.equals(key))
            {
                return getMemberFactory();
            }

            if(METADATA_CACHE_KEY.equals(key))
            {
                return getMetadataMemberFactory();
            }

            throw new IllegalArgumentException();
        }

        protected Facelet getFacelet(String key, URL url) throws IOException
        {
            Map<URL, Facelet> cache = getCache(key);
            Facelet facelet = cache.get(url);
            if(facelet == null)
            {
                MemberFactory<Facelet> factory = getFactory(key);
                facelet = factory.newInstance(url);

                cache.put(url, facelet);
            }

            return facelet;
        }

        @Override
        public Facelet getFacelet(URL url) throws IOException
        {
            return getFacelet(MEMBER_CACHE_KEY, url);
        }

        @Override
        public boolean isFaceletCached(URL url)
        {
            return getCache(MEMBER_CACHE_KEY).containsKey(url);
        }

        @Override
        public Facelet getViewMetadataFacelet(URL url) throws IOException
        {
            return getFacelet(METADATA_CACHE_KEY, url);
        }

        @Override
        public boolean isViewMetadataFaceletCached(URL url)
        {
            return getCache(METADATA_CACHE_KEY).containsKey(url);
        }
    }
}

and it's activated through faces-config.xml:

<?xml version="1.0" encoding="utf-8"?>
<faces-config version="2.2" xmlns="http://xmlns.jcp.org/xml/ns/javaee" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/javaee http://xmlns.jcp.org/xml/ns/javaee/web-facesconfig_2_2.xsd">

    ...
    
    <factory>
        <facelet-cache-factory>it.shape.core.jsf.factory.DebugFaceletCacheFactory</facelet-cache-factory>
    </factory>
</faces-config>

Happy composite coding ;)

---

UPDATE

I found JRebel interfering with eclipse debugger, so I disabled it and restarted.

And I found some new intersting things:

1. The cache implementation with JRebel enabled is read as com.sun.faces.facelets.impl.DefaultFaceletCache.NoCache but it is com.sun.faces.util.ExpiringConcurrentCache instead. That's why I had scrambled source code lines while debugging.
2. JSF (and specifically Mojarra) needs a deep refactoring, seriously: there are at least 5 different factories and 2 different caches involved in the creation/caching of facelets and metadata, most doing simple boilerplate delegation job.
3. com.sun.faces.facelets.impl.DefaultFaceletCache._metadataFaceletCache and com.sun.faces.application.view.FaceletViewHandlingStrategy.metadataCache are poorly paired: they contain the very same data and they have dependant-synced unidirectional handling. Conceptually wrong and memory consuming.
4. The default facelet refresh period is different from what I thought: it is 2000 instead of 0.

So another workaround is to set:

<context-param>
    <param-name>javax.faces.FACELETS_REFRESH_PERIOD</param-name>
    <param-value>0</param-value>
</context-param>

in web.xml, but honestly this is much less efficient than my simple cache implementation, because it creates facelets and metadata two times per composite component instance...

Finally, in this debugging session, I've never hit a case where the modified facelet doesn't get refreshed and even if the implementation is monstrously inefficient and schizofrenic, this version (2.2.12) seems to work.

In my case, I think it's a JRebel issue.

However, now I can finally develop with JRebel enabled and facelets reloading.

If I'll hit a hidden case (such as eclipse not copying/updating facelets to target folder and/or not setting last modified file date, on saving from editor) I'll update this answer.

---

P.S.
They use abstract classes in some case because interfaces are stateless and are not suitable for all conceptual patterns. Single class inheritance is IMO the most serious Java issue. However, with Java 8, we have default/defender methods, which help mitigating the problem. Nevertheless, they can't be called by JSF ExpressionLanguage 3.0 :(

---

CONCLUSION

Ok I found the issue. It's not simple to explain, and requires special (although common) conditions to be reproduced.

Suppose you have:

1. FACELET_REFRESH_PERIOD=2
2. a composite component named x:myComp
3. a page where x:myComp is used 100 times

Now here's what's going on under the hood.

1. the first time a x:myComp is encountered during page evaluation a cache Record is created with _creation=System.currentTimeMillis()
2. for every other time x:myComp is encountered during page evaluation, the Record retrieved from cache and DefaultFaceletCache.Record.getNextRefreshTime() is called two times (on get() and containsKey()) to verify expiration.
3. composite components get evaluated 2 times
4. assuming that full page evaluation completes in less than 2 seconds, in the end DefaultFaceletCache.Record.getNextRefreshTime() has been called ((100 * 2) - 1) * 2 = 398 times
5. when DefaultFaceletCache.Record.getNextRefreshTime() is called, it increments an atomic local variable _nextRefreshTime by FACELET_REFRESH_PERIOD * 1000 = 2000
6. so, in the end, _nextRefreshTime = initial System.currentTimeMillis() + (398 * 2000 = 796 s)

now this facelet will expire in 796 seconds since it has been created. Each access to this page before expiration adds another 796 seconds!

the problem is that cache checking is coupled (2^2 times!!) with life extension.

See JAVASERVERFACES-4107 and JAVASERVERFACES-4176 (and now primarily JAVASERVERFACES-4178) for further details.

---

Waiting for the issue resolution, I'm using my own cache impl (Java 8 required), maybe it's also useful for you to use/adapt (manually condensed in one single big class, maybe there's some copy'n'paste mistake):

/**
 * A factory for creating ShapeFaceletCache objects.
 *
 * @author Michele Mariotti
 */
public class ShapeFaceletCacheFactory extends FaceletCacheFactory
{
    protected FaceletCacheFactory wrapped;

    public ShapeFaceletCacheFactory(FaceletCacheFactory wrapped)
    {
        this.wrapped = wrapped;
    }

    @Override
    public FaceletCacheFactory getWrapped()
    {
        return wrapped;
    }

    @Override
    public ShapeFaceletCache getFaceletCache()
    {
        String param = FacesContext.getCurrentInstance()
            .getExternalContext()
            .getInitParameter(ViewHandler.FACELETS_REFRESH_PERIOD_PARAM_NAME);

        long period = NumberUtils.toLong(param, 2) * 1000;

        if(period < 0)
        {
            return new UnlimitedFaceletCache();
        }

        if(period == 0)
        {
            return new DevelopmentFaceletCache();
        }

        return new ExpiringFaceletCache(period);
    }

    public static abstract class ShapeFaceletCache extends FaceletCache<Facelet>
    {
        protected static volatile ShapeFaceletCache INSTANCE;

        protected Map<URL, FaceletRecord> memberCache = new ConcurrentHashMap<>();

        protected Map<URL, FaceletRecord> metadataCache = new ConcurrentHashMap<>();

        protected ShapeFaceletCache()
        {
            INSTANCE = this;
        }

        public static ShapeFaceletCache getInstance()
        {
            return INSTANCE;
        }

        protected Facelet getFacelet(FaceletCacheKey key, URL url)
        {
            Map<URL, FaceletRecord> cache = getLocalCache(key);
            FaceletRecord record = cache.compute(url, (u, r) -> computeFaceletRecord(key, u, r));
            Facelet facelet = record.getFacelet();
            return facelet;
        }

        protected boolean isCached(FaceletCacheKey key, URL url)
        {
            Map<URL, FaceletRecord> cache = getLocalCache(key);
            FaceletRecord record = cache.computeIfPresent(url, (u, r) -> checkFaceletRecord(key, u, r));
            return record != null;
        }

        protected FaceletRecord computeFaceletRecord(FaceletCacheKey key, URL url, FaceletRecord record)
        {
            if(record == null || checkFaceletRecord(key, url, record) == null)
            {
                return buildFaceletRecord(key, url);
            }

            return record;
        }

        protected FaceletRecord buildFaceletRecord(FaceletCacheKey key, URL url)
        {
            try
            {
                MemberFactory<Facelet> factory = getFactory(key);
                Facelet facelet = factory.newInstance(url);
                long lastModified = URLUtils.getLastModified(url);
                FaceletRecord record = new FaceletRecord(facelet, lastModified);
                return record;
            }
            catch(IOException e)
            {
                throw new FacesException(e.getMessage(), e);
            }
        }

        protected FaceletRecord checkFaceletRecord(FaceletCacheKey key, URL url, FaceletRecord record)
        {
            return record;
        }

        protected Map<URL, FaceletRecord> getLocalCache(FaceletCacheKey key)
        {
            if(key == FaceletCacheKey.MEMBER)
            {
                return memberCache;
            }

            if(key == FaceletCacheKey.METADATA)
            {
                return metadataCache;
            }

            throw new IllegalArgumentException();
        }

        protected MemberFactory<Facelet> getFactory(FaceletCacheKey key)
        {
            if(key == FaceletCacheKey.MEMBER)
            {
                return getMemberFactory();
            }

            if(key == FaceletCacheKey.METADATA)
            {
                return getMetadataMemberFactory();
            }

            throw new IllegalArgumentException();
        }

        @Override
        public Facelet getFacelet(URL url) throws IOException
        {
            return getFacelet(FaceletCacheKey.MEMBER, url);
        }

        @Override
        public Facelet getViewMetadataFacelet(URL url) throws IOException
        {
            return getFacelet(FaceletCacheKey.METADATA, url);
        }

        @Override
        public boolean isFaceletCached(URL url)
        {
            return isCached(FaceletCacheKey.MEMBER, url);
        }

        @Override
        public boolean isViewMetadataFaceletCached(URL url)
        {
            return isCached(FaceletCacheKey.METADATA, url);
        }

        public void clearFacelets()
        {
            getLocalCache(FaceletCacheKey.MEMBER).clear();
        }

        public void clearViewMetadataFacelets()
        {
            getLocalCache(FaceletCacheKey.METADATA).clear();
        }

        public void clearAll()
        {
            clearViewMetadataFacelets();
            clearFacelets();
        }
    }

    public static class UnlimitedFaceletCache extends ShapeFaceletCache
    {
        public UnlimitedFaceletCache()
        {
            super();
        }
    }

    public static class DevelopmentFaceletCache extends ShapeFaceletCache
    {
        public DevelopmentFaceletCache()
        {
            super();
        }

        @Override
        protected FaceletRecord checkFaceletRecord(FaceletCacheKey key, URL url, FaceletRecord record)
        {
            try
            {
                Set<URL> urls = (Set<URL>) FacesContext.getCurrentInstance()
                    .getAttributes()
                    .computeIfAbsent(key, x -> new HashSet<>());

                if(urls.add(url))
                {
                    long lastModified = URLUtils.getLastModified(url);
                    if(lastModified != record.getLastModified())
                    {
                        return null;
                    }
                }

                return record;
            }
            catch(IOException e)
            {
                throw new FacesException(e.getMessage(), e);
            }
        }
    }

    public static class ExpiringFaceletCache extends ShapeFaceletCache
    {
        protected final long period;

        public ExpiringFaceletCache(long period)
        {
            super();
            this.period = period;
        }

        @Override
        protected FaceletRecord checkFaceletRecord(FaceletCacheKey key, URL url, FaceletRecord record)
        {
            try
            {
                long now = System.currentTimeMillis();
                if(now > record.getLastChecked() + period)
                {
                    long lastModified = URLUtils.getLastModified(url);
                    if(lastModified != record.getLastModified())
                    {
                        return null;
                    }

                    record.setLastChecked(now);
                }

                return record;
            }
            catch(IOException e)
            {
                throw new FacesException(e.getMessage(), e);
            }
        }
    }

    public static class FaceletRecord
    {
        protected final Facelet facelet;

        protected final long lastModified;

        protected long lastChecked;

        public FaceletRecord(Facelet facelet, long lastModified)
        {
            this.facelet = facelet;
            this.lastModified = lastModified;
            lastChecked = System.currentTimeMillis();
        }

        public long getLastModified()
        {
            return lastModified;
        }

        public Facelet getFacelet()
        {
            return facelet;
        }
        
        public long getLastChecked()
        {
            return lastChecked;
        }

        public void setLastChecked(long lastChecked)
        {
            this.lastChecked = lastChecked;
        }
    }

    public static enum FaceletCacheKey
    {
        MEMBER,
        METADATA;

        @Override
        public String toString()
        {
            return getClass().getName() + "." + name();
        }
    }

    public static class URLUtils
    {
        public static long getLastModified(URL url) throws IOException
        {
            URLConnection urlConnection = url.openConnection();

            if(urlConnection instanceof JarURLConnection)
            {
                JarURLConnection jarUrlConnection = (JarURLConnection) urlConnection;
                URL jarFileUrl = jarUrlConnection.getJarFileURL();

                return getLastModified(jarFileUrl);
            }

            try(InputStream input = urlConnection.getInputStream())
            {
                return urlConnection.getLastModified();
            }
        }
    }
}