I am trying to run a basic spring boot application with JPA by using spanner emulator. However, I am getting the below error after startup after hitting any exposed end point.
PERMISSION_DENIED: com.google.api.gax.rpc.PermissionDeniedException: io.grpc.StatusRuntimeException: PERMISSION_DENIED: Caller is missing IAM permission spanner.sessions.create on resource projects/test-project/instances/test-instance/databases/test-database.
Project has been cloned from https://github.com/GoogleCloudPlatform/google-cloud-spanner-hibernate/tree/master/google-cloud-spanner-hibernate-samples/spring-data-jpa-sample and the only change I have done is updated the application.properties file. as per my understanding spanner emulator should not have any IAM related issues as it doesn't need any. I am not sure what is causing this issue here. I have verified that the emulator config is the active config and hence I would expect the code to connect to emulator.
# Application configuration to use Cloud Spanner with Spring Data JPA
# Spanner connection URL.
# - ${PROJECT_ID} Replace with your GCP project ID
# - ${INSTANCE_ID} Replace with your Spanner instance ID
# - ${DATABASE_NAME} Replace with your Spanner database name within your Spanner instance
spring.datasource.url=jdbc:cloudspanner:/projects/test-project/instances/test-instance/databases/test-database
# Specify the Spanner JDBC driver.
spring.datasource.driver-class-name=com.google.cloud.spanner.jdbc.JdbcDriver
# Specify the Spanner Hibernate dialect.
spring.jpa.properties.hibernate.dialect=com.google.cloud.spanner.hibernate.SpannerDialect
#spring.jpa.hibernate.ddl-auto=update //same error even if I uncomment this line
# Settings to enable batching statements for efficiency
spring.jpa.properties.hibernate.jdbc.batch_size=100
# You may display SQL statements and stats for debugging if needed.
spring.jpa.properties.hibernate.show_sql=true
spring.jpa.properties.hibernate.format_sql=true
Please find the console logs below:
2021-10-06 12:59:12.549 INFO 9747 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2021-10-06 12:59:12.556 INFO 9747 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2021-10-06 12:59:12.556 INFO 9747 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.53]
2021-10-06 12:59:12.617 INFO 9747 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2021-10-06 12:59:12.617 INFO 9747 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 694 ms
2021-10-06 12:59:12.707 INFO 9747 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2021-10-06 12:59:12.737 WARN 9747 --- [ main] c.g.a.oauth2.DefaultCredentialsProvider : Your application has authenticated using end user credentials from Google Cloud SDK. We recommend that most server applications use service accounts instead. If your application continues to use end user credentials from Cloud SDK, you might receive a "quota exceeded" or "API not enabled" error. For more information about service accounts, see https://cloud.google.com/docs/authentication/.
2021-10-06 12:59:14.558 INFO 9747 --- [ main] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Driver does not support get/set network timeout for connections. (Network timeout is not supported)
2021-10-06 12:59:22.165 INFO 9747 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
2021-10-06 12:59:22.197 INFO 9747 --- [ main] o.hibernate.jpa.internal.util.LogHelper : HHH000204: Processing PersistenceUnitInfo [name: default]
2021-10-06 12:59:22.231 INFO 9747 --- [ main] org.hibernate.Version : HHH000412: Hibernate ORM core version 5.4.29.Final
2021-10-06 12:59:22.337 INFO 9747 --- [ main] o.hibernate.annotations.common.Version : HCANN000001: Hibernate Commons Annotations {5.1.2.Final}
2021-10-06 12:59:22.396 INFO 9747 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: com.google.cloud.spanner.hibernate.SpannerDialect
2021-10-06 12:59:22.851 INFO 9747 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-10-06 12:59:22.857 INFO 9747 --- [ main] j.LocalContainerEntityManagerFactoryBean : Initialized JPA EntityManagerFactory for persistence unit 'default'
2021-10-06 12:59:23.060 WARN 9747 --- [ main] JpaBaseConfiguration$JpaWebConfiguration : spring.jpa.open-in-view is enabled by default. Therefore, database queries may be performed during view rendering. Explicitly configure spring.jpa.open-in-view to disable this warning
2021-10-06 12:59:23.184 INFO 9747 --- [ main] o.s.b.a.w.s.WelcomePageHandlerMapping : Adding welcome page template: index
2021-10-06 12:59:23.290 INFO 9747 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2021-10-06 12:59:23.298 INFO 9747 --- [ main] com.example.CoffeeApplication : Started CoffeeApplication in 12.957 seconds (JVM running for 13.227)
2021-10-06 12:59:33.646 INFO 9747 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2021-10-06 12:59:33.646 INFO 9747 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2021-10-06 12:59:33.647 INFO 9747 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
Hibernate:
select
customer0_.id as id1_1_,
customer0_.email as email2_1_,
customer0_.name as name3_1_
from
customer customer0_
2021-10-06 12:59:35.650 WARN 9747 --- [nio-8080-exec-1] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 7, SQLState: null
2021-10-06 12:59:35.650 ERROR 9747 --- [nio-8080-exec-1] o.h.engine.jdbc.spi.SqlExceptionHelper : PERMISSION_DENIED: com.google.api.gax.rpc.PermissionDeniedException: io.grpc.StatusRuntimeException: PERMISSION_DENIED: Caller is missing IAM permission spanner.sessions.create on resource projects/test-project/instances/test-instance/databases/test-database.
2021-10-06 12:59:35.668 ERROR 9747 --- [nio-8080-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.orm.jpa.JpaSystemException: could not extract ResultSet; nested exception is org.hibernate.exception.GenericJDBCException: could not extract ResultSet] with root cause
io.grpc.StatusRuntimeException: PERMISSION_DENIED: Caller is missing IAM permission spanner.sessions.create on resource projects/test-project/instances/test-instance/databases/test-database.
at io.grpc.Status.asRuntimeException(Status.java:535) ~[grpc-api-1.40.1.jar:1.40.1]
at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:533) ~[grpc-stub-1.40.1.jar:1.40.1]
at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39) ~[grpc-api-1.40.1.jar:1.40.1]
at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23) ~[grpc-api-1.40.1.jar:1.40.1]
at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40) ~[grpc-api-1.40.1.jar:1.40.1]
at com.google.cloud.spanner.spi.v1.SpannerErrorInterceptor$1$1.onClose(SpannerErrorInterceptor.java:100) ~[google-cloud-spanner-6.12.5.jar:6.12.5]
at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:557) ~[grpc-core-1.40.1.jar:1.40.1]
at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:69) ~[grpc-core-1.40.1.jar:1.40.1]
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:738) ~[grpc-core-1.40.1.jar:1.40.1]
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:717) ~[grpc-core-1.40.1.jar:1.40.1]
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[grpc-core-1.40.1.jar:1.40.1]
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133) ~[grpc-core-1.40.1.jar:1.40.1]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_281]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_281]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_281]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[na:1.8.0_281]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_281]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_281]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_281]
The error is a clear indication that your application is not trying to connect to the emulator, but to a real Spanner database. In order to connect to the emulator instead of 'real' Cloud Spanner, you should do one of the following:
SPANNER_EMULATOR_HOST=localhost:9010autoConfigEmulator=true property. Your JDBC URL would then become jdbc:cloudspanner:/projects/test-project/instances/test-instance/databases/test-database;autoConfigEmulator=trueThe advantage of the second alternative is that the autoConfigEmulator property will not only ensure that the JDBC driver is connecting to the emulator, it will also automatically create the test-instance and test-database on the emulator if they do not already exist.