Hi,
I have this class:
@Transactional
@Component
public class ProjectTransactionsImpl implements ProjectTransactions {
@SuppressWarnings("constantname")
private static final Logger logger =
LoggerFactory.getLogger(ProjectTransactionsImpl.class);
@Autowired
private ProviderService providerService;
@Override
public Provider findProvider(String providerId) {
Provider provider = providerService.find(providerId);
logger.debug("Returning: {}", provider.getClass());
return provider;
}
}
And a unit test calling it like this:
@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration(locations =
{"file:src/test/resources/testContext.xml"})
@TransactionConfiguration(transactionManager = "transactionManager",
defaultRollback = false)
public class MigrateProjects extends AbstractMigrationClass {
private static final Logger logger =
LoggerFactory.getLogger(MigrateProjects.class);
@Autowired
private ProjectTransactions trans;
private int projectsAdded = 0;
private final Map<String, Integer> providerProjectCountBefore = new
HashMap<>();
@Test
public void test1() throws Exception {
logger.debug("Getting provider");
Provider provider = trans.findProvider("GTI");
logger.debug("Returned: {}", provider);
}
}
Using OpenJPA 2.4.0 with Spring 4.1.7.RELEASE.
The log shows this:
09:56:52.913 [main] DEBUG c.g.e.a.t.MigrateProjects -
[MigrateProjects.java(54) MigrateProjects::test1] Getting provider
09:56:52.914 [main] DEBUG c.g.e.a.t.ProjectTransactionsImpl -
[ProjectTransactionsImpl.java(41) ProjectTransactionsImpl::findProvider]
Returning: class com.groupgti.esb.assessments.model.jpaimpl.ProviderImpl
09:56:52.915 [main] DEBUG c.g.e.a.t.MigrateProjects -
[MigrateProjects.java(56) MigrateProjects::test1] Returned: null
So I had an object in the call to findProvider, but it has become null
by the time if gets to the call site.
If I change the logging line in findProvider to:
logger.debug("Returning: {}", provider);
Then I get this:
09:59:44.234 [main] DEBUG c.g.e.a.t.MigrateProjects -
[MigrateProjects.java(54) MigrateProjects::test1] Getting provider
09:59:44.235 [main] DEBUG c.g.e.a.t.ProjectTransactionsImpl -
[ProjectTransactionsImpl.java(41) ProjectTransactionsImpl::findProvider]
Returning: ProviderImpl{id=8, providerId=GTI, projects=20,
maintenanceWindows=0, textBlocks=0}
09:59:44.238 [main] DEBUG c.g.e.a.t.MigrateProjects -
[MigrateProjects.java(56) MigrateProjects::test1] Returned:
ProviderImpl{id=8, providerId=GTI, projects=20, maintenanceWindows=0,
textBlocks=0}
So if I log the object it gets output, but if I don't I get null.
I can't debug this because the act of debugging makes it work!
If I change the logging line to:
provider.getProjects();
Just to prove I've really got an object and to ensure that a collection
gets loaded.
Then I get:
10:01:37.101 [main] DEBUG c.g.e.a.t.MigrateProjects -
[MigrateProjects.java(54) MigrateProjects::test1] Getting provider
10:01:37.109 [main] DEBUG c.g.e.a.t.MigrateProjects -
[MigrateProjects.java(56) MigrateProjects::test1] Returned: null
If I change the logging line to:
provider.toString();
Then it works again:
10:03:09.843 [main] DEBUG c.g.e.a.t.MigrateProjects -
[MigrateProjects.java(54) MigrateProjects::test1] Getting provider
10:03:09.847 [main] DEBUG c.g.e.a.t.MigrateProjects -
[MigrateProjects.java(56) MigrateProjects::test1] Returned:
ProviderImpl{id=8, providerId=GTI, projects=20, maintenanceWindows=0,
textBlocks=0}
So something in toString seems to be making it work.
The toString() implementation isn't very complicated:
@Override
public String toString() {
try {
return "ProviderImpl{" + "id=" + id + ", providerId=" +
providerId + ", projects=" + projects.size() + ", maintenanceWindows=" +
maintenanceWindows.size()
+ ", textBlocks=" + textBlocks.size() + '}';
} catch (NullPointerException ex) {
return null;
}
}
It's not hitting any NPE because it is returning a correct string.
Can anyone shed some light on what is happening here?
Or suggest some approach I can take to debug it?
Thanks
Jim
