[SLING-5847] Deadlock in JcrResourceBundleProvider.getResourceBundleInternal when preloading is enabled

• Type: Bug
• Status: Closed
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: i18n 2.4.4
• Fix Version/s: i18n 2.4.8
• Component/s: Extensions
• Assignee: Konrad Windszus
• Reporter: Konrad Windszus
• Created: 15/Jul/16 06:56
• Updated: 05/Aug/16 08:37
• Resolved: 15/Jul/16 08:17

Description

Under particular timing situations the reloadBundle job and a parallel call to JcrResourceBundleProvider.getResourceBundleInternal() might block each other and also all new threads calling JcrResourceBundleProvider.getResourceBundleInternal().

The thread dump in that situation looks like follows

"0:0:0:0:0:0:0:1 [1468492407436] GET <some request url> HTTP/1.1" - Thread t@69826
   java.lang.Thread.State: BLOCKED
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.registerResourceBundle(JcrResourceBundleProvider.java:458)
	- waiting to lock <19c60354> (a org.apache.sling.i18n.impl.JcrResourceBundleProvider) owned by "pool-8-thread-5" t@111
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.getResourceBundleInternal(JcrResourceBundleProvider.java:437)
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.createResourceBundle(JcrResourceBundleProvider.java:480)
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.getResourceBundleInternal(JcrResourceBundleProvider.java:435)
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.getResourceBundle(JcrResourceBundleProvider.java:185)
	at org.apache.sling.i18n.impl.I18NFilter$CombinedBundleProvider.getResourceBundle(I18NFilter.java:217)
	at org.apache.sling.i18n.impl.I18NFilter$BaseI18NSlingHttpServletRequest.getResourceBundle(I18NFilter.java:311)
	at org.apache.sling.api.wrappers.SlingHttpServletRequestWrapper.getResourceBundle(SlingHttpServletRequestWrapper.java:115)
	at org.apache.sling.api.wrappers.SlingHttpServletRequestWrapper.getResourceBundle(SlingHttpServletRequestWrapper.java:115)
	at org.apache.sling.api.wrappers.SlingHttpServletRequestWrapper.getResourceBundle(SlingHttpServletRequestWrapper.java:115)
	at org.apache.sling.api.wrappers.SlingHttpServletRequestWrapper.getResourceBundle(SlingHttpServletRequestWrapper.java:115)
	at org.apache.sling.api.wrappers.SlingHttpServletRequestWrapper.getResourceBundle(SlingHttpServletRequestWrapper.java:115)
	at ...

"pool-8-thread-5" - Thread t@111
   java.lang.Thread.State: WAITING
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for <69b06467> (a java.util.concurrent.Semaphore$NonfairSync)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
	at java.util.concurrent.Semaphore.acquire(Semaphore.java:312)
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.getResourceBundleInternal(JcrResourceBundleProvider.java:429)
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.createResourceBundle(JcrResourceBundleProvider.java:480)
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.getResourceBundleInternal(JcrResourceBundleProvider.java:435)
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.getResourceBundle(JcrResourceBundleProvider.java:185)
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.reloadBundle(JcrResourceBundleProvider.java:357)
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider.reloadBundle(JcrResourceBundleProvider.java:352)
	at org.apache.sling.i18n.impl.JcrResourceBundleProvider$2.run(JcrResourceBundleProvider.java:320)
	- locked <19c60354> (a org.apache.sling.i18n.impl.JcrResourceBundleProvider)
	at org.apache.sling.commons.scheduler.impl.QuartzJobExecutor.execute(QuartzJobExecutor.java:115)
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

Here is what happens internally:

Thread 1 has acquired a semaphore for a specific key and now waits for the lock hold by thread 2 in

 private void registerResourceBundle(Key key, JcrResourceBundle resourceBundle) {
        Dictionary<Object, Object> serviceProps = new Hashtable<Object, Object>();
        if (key.baseName != null) {
            serviceProps.put("baseName", key.baseName);
        }
        serviceProps.put("locale", key.locale.toString());
        ServiceRegistration serviceReg = bundleContext.registerService(ResourceBundle.class.getName(),
                resourceBundle, serviceProps);
->        synchronized (this) {
            bundleServiceRegistrations.put(key, serviceReg);
        }

Thread 2 holds that lock in

private void scheduleReloadBundle(JcrResourceBundle bundle) {
        String baseName = bundle.getBaseName();
        Locale locale = bundle.getLocale();
        final Key key = new Key(baseName, locale);

        // defer this job
        ScheduleOptions options = scheduler.AT(new Date(System.currentTimeMillis() + invalidationDelay));
        final String jobName = "JcrResourceBundleProvider: reload bundle with key " + key.toString();
        scheduledJobNames.add(jobName);
        options.name(jobName);
        scheduler.schedule(new Runnable() {
            @Override
            public void run() {
                synchronized(JcrResourceBundleProvider.this) {
->                    reloadBundle(key);
                }
                scheduledJobNames.remove(jobName);
            }
        }, options);
    }

and now waits for the same semaphore that is being hold by thread 1 during the preloading.