HHH-8071 - Add debug/trace logging to HibernatePersistenceProvider

hibernate-core/src/main/java/org/hibernate/boot/registry/classloading/internal/ClassLoaderServiceImpl.java

@@ -107,6 +107,15 @@ public class ClassLoaderServiceImpl implements ClassLoaderService {
 		addIfSet( providedClassLoaders, AvailableSettings.HIBERNATE_CLASSLOADER, configVales );
 		addIfSet( providedClassLoaders, AvailableSettings.ENVIRONMENT_CLASSLOADER, configVales );
 
+		if ( providedClassLoaders.isEmpty() ) {
+			log.debugf( "Incoming config yielded no classloaders; adding standard SE ones" );
+			final ClassLoader tccl = locateTCCL();
+			if ( tccl != null ) {
+				providedClassLoaders.add( tccl );
+			}
+			providedClassLoaders.add( ClassLoaderServiceImpl.class.getClassLoader() );
+		}
+
 		return new ClassLoaderServiceImpl( providedClassLoaders );
 	}
 

hibernate-core/src/test/resources/log4j.properties

@@ -1,17 +0,0 @@
-log4j.appender.stdout=org.apache.log4j.ConsoleAppender
-log4j.appender.stdout.Target=System.out
-log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
-log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n
-
-
-log4j.rootLogger=info, stdout
-
-log4j.logger.org.hibernate.tool.hbm2ddl=trace
-log4j.logger.org.hibernate.testing.cache=debug
-
-# SQL Logging - HHH-6833
-log4j.logger.org.hibernate.SQL=debug
-
-log4j.logger.org.hibernate.hql.internal.ast=debug
-
-log4j.logger.org.hibernate.sql.ordering.antlr=debug

hibernate-entitymanager/src/main/java/org/hibernate/jpa/HibernatePersistenceProvider.java

@@ -34,6 +34,8 @@ import javax.persistence.spi.PersistenceProvider;
 import javax.persistence.spi.PersistenceUnitInfo;
 import javax.persistence.spi.ProviderUtil;
 
+import org.jboss.logging.Logger;
+
 import org.hibernate.jpa.boot.internal.ParsedPersistenceXmlDescriptor;
 import org.hibernate.jpa.boot.internal.PersistenceXmlParser;
 import org.hibernate.jpa.boot.spi.Bootstrap;
@@ -49,6 +51,7 @@ import org.hibernate.jpa.internal.util.PersistenceUtilHelper;
  * @author Brett Meyer
  */
 public class HibernatePersistenceProvider implements PersistenceProvider {
+	private static final Logger log = Logger.getLogger( HibernatePersistenceProvider.class );
 
 	private final PersistenceUtilHelper.MetadataCache cache = new PersistenceUtilHelper.MetadataCache();
 	
@@ -69,16 +72,40 @@ public class HibernatePersistenceProvider implements PersistenceProvider {
 	 */
 	@Override
 	public EntityManagerFactory createEntityManagerFactory(String persistenceUnitName, Map properties) {
+		log.tracef( "Starting createEntityManagerFactory for persistenceUnitName %s", persistenceUnitName );
+
 		if ( environmentProperties != null ) {
 			properties.putAll( environmentProperties );
 		}
+
 		final EntityManagerFactoryBuilder builder = getEntityManagerFactoryBuilderOrNull( persistenceUnitName, properties );
-		return builder == null ? null : builder.build();
+		if ( builder == null ) {
+			log.trace( "Could not obtain matching EntityManagerFactoryBuilder, returning null" );
+			return null;
+		}
+		else {
+			return builder.build();
+		}
 	}
 
 	private EntityManagerFactoryBuilder getEntityManagerFactoryBuilderOrNull(String persistenceUnitName, Map properties) {
+		log.tracef( "Attempting to obtain correct EntityManagerFactoryBuilder for persistenceUnitName : %s", persistenceUnitName );
+
 		final Map integration = wrap( properties );
-		final List<ParsedPersistenceXmlDescriptor> units = PersistenceXmlParser.locatePersistenceUnits( integration );
+		final List<ParsedPersistenceXmlDescriptor> units;
+		try {
+			 units = PersistenceXmlParser.locatePersistenceUnits( integration );
+		}
+		catch (RuntimeException e) {
+			log.debug( "Unable to locate persistence units", e );
+			throw e;
+		}
+		catch (Exception e) {
+			log.debug( "Unable to locate persistence units", e );
+			throw new PersistenceException( "Unable to locate persistence units", e );
+		}
+
+		log.debugf( "Located and parsed %s persistence units; checking each", units.size() );
 
 		if ( persistenceUnitName == null && units.size() > 1 ) {
 			// no persistence-unit name to look for was given and we found multiple persistence-units
@@ -86,19 +113,29 @@ public class HibernatePersistenceProvider implements PersistenceProvider {
 		}
 
 		for ( ParsedPersistenceXmlDescriptor persistenceUnit : units ) {
+			log.debugf(
+					"Checking persistence-unit [name=%s, explicit-provider=%s] against incoming persistence unit name [%s]",
+					persistenceUnit.getName(),
+					persistenceUnit.getProviderClassName(),
+					persistenceUnitName
+			);
+
 			boolean matches = persistenceUnitName == null || persistenceUnit.getName().equals( persistenceUnitName );
 			if ( !matches ) {
+				log.debug( "Excluding from consideration due to name mis-match" );
 				continue;
 			}
 
 			// See if we (Hibernate) are the persistence provider
 			if ( ! ProviderChecker.isProvider( persistenceUnit, properties ) ) {
+				log.debug( "Excluding from consideration due to provider mis-match" );
 				continue;
 			}
 
 			return Bootstrap.getEntityManagerFactoryBuilder( persistenceUnit, integration );
 		}
 
+		log.debug( "Found no matching persistence units" );
 		return null;
 	}
 
@@ -114,6 +151,8 @@ public class HibernatePersistenceProvider implements PersistenceProvider {
 	 */
 	@Override
 	public EntityManagerFactory createContainerEntityManagerFactory(PersistenceUnitInfo info, Map properties) {
+		log.tracef( "Starting createContainerEntityManagerFactory : %s", info.getPersistenceUnitName() );
+
 		if ( environmentProperties != null ) {
 			properties.putAll( environmentProperties );
 		}
@@ -122,14 +161,19 @@ public class HibernatePersistenceProvider implements PersistenceProvider {
 
 	@Override
 	public void generateSchema(PersistenceUnitInfo info, Map map) {
+		log.tracef( "Starting generateSchema : PUI.name=%s", info.getPersistenceUnitName() );
+
 		EntityManagerFactoryBuilder builder = Bootstrap.getEntityManagerFactoryBuilder( info, map );
 		builder.generateSchema();
 	}
 
 	@Override
 	public boolean generateSchema(String persistenceUnitName, Map map) {
+		log.tracef( "Starting generateSchema for persistenceUnitName %s", persistenceUnitName );
+
 		final EntityManagerFactoryBuilder builder = getEntityManagerFactoryBuilderOrNull( persistenceUnitName, map );
 		if ( builder == null ) {
+			log.trace( "Could not obtain matching EntityManagerFactoryBuilder, returning false" );
 			return false;
 		}
 		builder.generateSchema();

hibernate-entitymanager/src/main/java/org/hibernate/jpa/boot/internal/PersistenceXmlParser.java

@@ -108,7 +108,7 @@ public class PersistenceXmlParser {
 	}
 
 	private List<ParsedPersistenceXmlDescriptor> parsePersistenceXml(URL xmlUrl, Map integration) {
-		// todo : if implementing a "xml binding service" this should be part of it, binding persistence.xml : HHH-6145
+		LOG.tracef( "Attempting to parse persistence.xml file : %s" + xmlUrl.toExternalForm() );
 
 		final Document doc = loadUrl( xmlUrl );
 		final Element top = doc.getDocumentElement();

hibernate-entitymanager/src/main/java/org/hibernate/jpa/boot/spi/ProviderChecker.java

@@ -25,8 +25,10 @@ package org.hibernate.jpa.boot.spi;
 
 import java.util.Map;
 
-import org.hibernate.ejb.AvailableSettings;
+import org.jboss.logging.Logger;
+
 import org.hibernate.ejb.HibernatePersistence;
+import org.hibernate.jpa.AvailableSettings;
 import org.hibernate.jpa.HibernatePersistenceProvider;
 
 /**
@@ -36,6 +38,9 @@ import org.hibernate.jpa.HibernatePersistenceProvider;
  * @author Steve Ebersole
  */
 public class ProviderChecker {
+	private static final Logger log = Logger.getLogger( ProviderChecker.class );
+
+	@SuppressWarnings("deprecation")
 	private static String[] HIBERNATE_PROVIDER_NAMES = new String[] {
 			HibernatePersistenceProvider.class.getName(),
 			HibernatePersistence.class.getName()
@@ -53,9 +58,7 @@ public class ProviderChecker {
 	 */
 	public static boolean isProvider(PersistenceUnitDescriptor persistenceUnit, Map integration) {
 		// See if we (Hibernate) are the persistence provider
-		final String requestedProviderName = extractRequestedProviderName( persistenceUnit, integration );
+		return hibernateProviderNamesContain( extractRequestedProviderName( persistenceUnit, integration ) );
-		// NOTE : if no requested name, we assume we are the provider (the calls got to us somehow...)
-		return requestedProviderName == null || hibernateProviderNamesContain( requestedProviderName );
 	}
 
 	/**
@@ -66,11 +69,18 @@ public class ProviderChecker {
 	 * @return {@code true} if Hibernate should be the provider; {@code false} otherwise.
 	 */
 	public static boolean hibernateProviderNamesContain(String requestedProviderName) {
+		log.tracef(
+				"Checking requested PersistenceProvider name [%s] against Hibernate provider names",
+				requestedProviderName
+		);
+
 		for ( String hibernateProviderName : HIBERNATE_PROVIDER_NAMES ) {
 			if ( requestedProviderName.equals( hibernateProviderName ) ) {
 				return true;
 			}
 		}
+
+		log.tracef( "Found no match against Hibernate provider names" );
 		return false;
 	}
 
@@ -85,15 +95,37 @@ public class ProviderChecker {
 	 * @return The extracted provider name, or {@code null} if none found.
 	 */
 	public static String extractRequestedProviderName(PersistenceUnitDescriptor persistenceUnit, Map integration) {
-		String providerName = integration == null ? null : (String) integration.get( AvailableSettings.PROVIDER );
+		final String integrationProviderName = extractProviderName( integration );
-		if ( providerName == null ) {
+		if ( integrationProviderName != null ) {
-			providerName = persistenceUnit.getProviderClassName();
+			log.debugf( "Integration provided explicit PersistenceProvider [%s]", integrationProviderName );
+			return integrationProviderName;
 		}
 
-		if ( providerName != null ) {
+		final String persistenceUnitRequestedProvider = extractProviderName( persistenceUnit );
-			providerName = providerName.trim();
+		if ( persistenceUnitRequestedProvider != null ) {
+			log.debugf(
+					"Persistence-unit [%s] requested PersistenceProvider [%s]",
+					persistenceUnit.getName(),
+					persistenceUnitRequestedProvider
+			);
+			return persistenceUnitRequestedProvider;
 		}
 
-		return providerName;
+		// NOTE : if no provider requested we assume we are the provider (the calls got to us somehow...)
+		log.debug( "No PersistenceProvider explicitly requested, assuming Hibernate" );
+		return HibernatePersistenceProvider.class.getName();
+	}
+
+	private static String extractProviderName(Map integration) {
+		if ( integration == null ) {
+			return null;
+		}
+		final String setting = (String) integration.get( AvailableSettings.PROVIDER );
+		return setting == null ? null : setting.trim();
+	}
+
+	private static String extractProviderName(PersistenceUnitDescriptor persistenceUnit) {
+		final String persistenceUnitRequestedProvider = persistenceUnit.getProviderClassName();
+		return persistenceUnitRequestedProvider == null ? null : persistenceUnitRequestedProvider.trim();
 	}
 }