Permission denied in getting spanner session create in a java spring boot project using spanner emul-CodePudding

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]

CodePudding user response：

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:

Set the environment variable SPANNER_EMULATOR_HOST=localhost:9010
OR: Edit the JDBC connection URL to include the autoConfigEmulator=true property. Your JDBC URL would then become jdbc:cloudspanner:/projects/test-project/instances/test-instance/databases/test-database;autoConfigEmulator=true

The 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.