Add debug logging to help when a repository uses classes that are missing annotations

[philwebb]

See this Twitter discussion.

It would be nice if we could trigger additional debug/warning logs to help track down this kind of problem.

[paulbakker]

Setup:

@Repository
public interface ActionMovieRepository extends CrudRepository<ActionMovie, Long> {
}

//Note the missing @Table
public class ActionMovie implements Movie {

    @Id 
    private Long id;

    //More fields and methods

}

@Configuration
@EnableJdbcRepositories
@EnableTransactionManagement
public class JdbcDataConfig {

    @Bean
    public DataSource dataSource() {
        EmbeddedDatabaseBuilder builder = new EmbeddedDatabaseBuilder().addScript("sql/tables.sql");
        return builder.setType(EmbeddedDatabaseType.HSQL).build();
    }

}

Result: The logs say:

2019-12-13 15:14:03.116  INFO 61034 --- [           main] .RepositoryConfigurationExtensionSupport : Spring Data JDBC - Could not safely identify store assignment for repository candidate interface com.netflix.graphql.dgs.example.repository.ActionMovieRepository. If you want this repository to be a JDBC repository, consider annotating your entities with one of these annotations: org.springframework.data.relational.core.mapping.Table.

However, the application fails startup with the cause of ActionMovieRepository couldn't be autowired.

The reason is obvious once I found the log above, but it got lost in the rest of startup logs. Maybe it would be better to make this either a warning, or even fail startup when an incorrectly configured repository is found?

[odrotbohm]

The problem is that your starting point is not valid configuration. You have multiple store modules on the classpath and each of them is trying to identify the domain types it's supposed to manage. Neither your repository nor your domain type give any hints about this. In multi-store mode, each store module knows about a set of criterias it uses to identify the repository that it should handle. It now of course drops the ones it cannot properly identify as its own as other modules later in the bootstrap chain might claim it. So the JDBC module is basically telling you: I would've picked this up in single-module mode but as there are multiple store modules on the classpath, I do not claim this repository as there might be other modules whose assignment criterias this repository interfaces matches.

That however is not something we want to pollute the log with WARN messages for. If there's another store that actively claims the repo, all is fine. Whether that's the case is nothing we can know at the point in time that the JDBC module is creating bean definitions. Each module acts on its own and does not know about any other module. So there's also no code that's running after all of them so that it could verify the global set of repositories. Not even mentioning that this would need to re-scan for all the interfaces considering the scanning setups of each module in turn.

All of that said, if you can think of better wording for the log message, I'll happily take suggestions. Also: maybe it's more an issue of consistently making sure we use the annotation in ever sample, the reference docs although not strictly necessary in less complex scenarios?

[philwebb]

I wonder if Spring Boot could do more if there was also a programmatic way to receive those events outside of just logging them. Perhaps then if the ActionMovieRepository bean can't be injected we could check for those evens and provide a failure analyzer to point it out.

I imagine one reason that the log gets missed is because it's superseded by an actual exception. My initial instinct would be to start with the stacktrace, rather than to think about hunting backwards in the logs for other messages.

[wilkinsona]

The problem is that your starting point is not valid configuration

It may be invalid now, but you're rather lulled into a false sense of security as there's no indication that it's invalid to begin with. If you start developing an app with only a single store on the classpath, the output looks like the following:

2019-12-16 15:59:18.627  INFO 7833 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JDBC repositories in DEFAULT mode.
2019-12-16 15:59:18.663  INFO 7833 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 32ms. Found 1 JDBC repository interfaces.

There's nothing here to indicate that there's a potential problem with the configuration and that it's valid only because there's a single store on the classpath.

With a second store on the classpath, the following output is logged:

2019-12-16 16:00:55.044  INFO 7837 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!
2019-12-16 16:00:55.045  INFO 7837 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JDBC repositories in DEFAULT mode.
2019-12-16 16:00:55.079  INFO 7837 --- [           main] .RepositoryConfigurationExtensionSupport : Spring Data JDBC - Could not safely identify store assignment for repository candidate interface com.example.demo.ActionMovieRepository. If you want this repository to be a JDBC repository, consider annotating your entities with one of these annotations: org.springframework.data.relational.core.mapping.Table.
2019-12-16 16:00:55.079  INFO 7837 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 30ms. Found 0 JDBC repository interfaces.
2019-12-16 16:00:55.090  INFO 7837 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode!
2019-12-16 16:00:55.090  INFO 7837 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data JPA repositories in DEFAULT mode.
2019-12-16 16:00:55.095  INFO 7837 --- [           main] .RepositoryConfigurationExtensionSupport : Spring Data JPA - Could not safely identify store assignment for repository candidate interface com.example.demo.ActionMovieRepository. If you want this repository to be a JPA repository, consider annotating your entities with one of these annotations: javax.persistence.Entity, javax.persistence.MappedSuperclass (preferred), or consider extending one of the following types with your repository: org.springframework.data.jpa.repository.JpaRepository.
2019-12-16 16:00:55.096  INFO 7837 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 2ms. Found 0 JPA repository interfaces.

It feels like Spring Data has been too helpful in the first case and then not helpful enough in the second.

To improve the second situation, I wonder if a diagnostic repository scanner could run after all of the real scanners. It could throw an exception describing anything that went unclaimed. Boot could perform some failure analysis of this exception so that it's presented to the user has helpfully as possible.

I wonder if the first could be improved too. Perhaps a warning message could be logged to recommend the addition of a @Table annotation so that adding a second store doesn't break the first store unexpectedly.

[odrotbohm]

It feels like Spring Data has been too helpful in the first case and then not helpful enough in the second.

Care to elaborate? The log clearly states the change in configuration mode. The mentioned terms can clearly be found in the reference documentation describing the multi-store mode. The latter even describes the matching algorithm in elaborate detail. It then reports the offending repository and gives advice what to do to resolve the situation which matches what's described in the reference documentation.

So what exactly is "lulling" people into a false sense of security here? As indicated above, the individual store modules cannot be more constraining at the point they're discovering the scenario as that would take other stores the opportunity to claim the repository interface.

I am happy to explore means to resolve the situation that include means that exceed the scope of solely Spring Data. So far the problem hasn't really popped up at all or at least not reached the team. Phil's suggestions sound like a great idea I am happy to explore. That said, I think it's rather harsh to suggest we're acting with bad intentions and'd actively mislead users and make it hard for them to identify the root of the problem.

[wilkinsona]

In the first case, Spring Data has gone the extra mile and figured out that ActionMovieRepository should be a Spring Data JDBC repository despite the lack of @Table on ActionMovie. This is great in a single-store arrangement but sets you up for failure when you add a second store. That's why I said that it feels like it has been too helpful. I think a warning or similar that draws the user's attention to the fact that things won't work if another store is added would be beneficial.

In the second case, I feel that the info messages aren't doing enough to help the user to figure out why something that worked with a single store has now stopped working when a second store was added. I suspect's that not because of their content, but because they're only logged at info level and are therefore easily missed. Phil suggested a reason for this above:

I imagine one reason that the log gets missed is because it's superseded by an actual exception. My initial instinct would be to start with the stacktrace, rather than to think about hunting backwards in the logs for other messages.

That sounds quite plausible to me.

As indicated above, the individual store modules cannot be more constraining at the point they're discovering the scenario as that would take other stores the opportunity to claim the repository interface.

That's why I was wondering if some sort of diagnostic scanner could run after all the proper stores have had a chance to claim all of the repository interfaces. It could then report on any that had gone unclaimed.

That said, I think it's rather harsh to suggest we're acting with bad intentions and'd actively mislead users and make it hard for them to identify the root of the problem.

Sorry. I had no intention of suggesting that intentions were bad or that the current situation was due to a choice to mislead users. My intention was only to offer an opinion about why users may find the current behaviour hard to debug and to hopefully make some constructive suggestions about how it could be improved.