search

RADAR-base / RADAR-Rest-Source-Auth

A simple application to support authorization of wearable devices using OAuth using a webservice with REST Endpoints.
https://radar-base.org/
Apache License 2.0
1 stars 0 forks source link

User exists error but UI shows user as ready for authorizing #225

Closed yatharthranjan closed 1 year ago

yatharthranjan commented 1 year ago

We have a user who is shown as ok to authorize in the UI, but once we start Authorization, the following exception is thrown -

SCR-20230127-h72

image

Logs - 

[2023-01-26 20:25:30,469] ERROR - Rolling back operation (HibernateRepository.kt:54)
org.radarbase.jersey.exception.HttpConflictException: [409] user_exists: User 5dffc387-7a1b-430f-bad4-a61c384d4821 already exists.
    at org.radarbase.authorizer.doa.RestSourceUserRepositoryImpl$create$1.invoke(RestSourceUserRepositoryImpl.kt:53) ~[authorizer-app-backend-4.1.1.jar:?]
    at org.radarbase.authorizer.doa.RestSourceUserRepositoryImpl$create$1.invoke(RestSourceUserRepositoryImpl.kt:38) ~[authorizer-app-backend-4.1.1.jar:?]
    at org.radarbase.jersey.hibernate.HibernateRepository$transact$1.invoke(HibernateRepository.kt:26) ~[radar-jersey-hibernate-0.9.0.jar:0.9.0]
    at org.radarbase.jersey.hibernate.HibernateRepository$transact$1.invoke(HibernateRepository.kt:25) ~[radar-jersey-hibernate-0.9.0.jar:0.9.0]
    at org.radarbase.jersey.hibernate.HibernateRepository.createTransaction(HibernateRepository.kt:38) ~[radar-jersey-hibernate-0.9.0.jar:0.9.0]
    at org.radarbase.jersey.hibernate.HibernateRepository.transact(HibernateRepository.kt:25) ~[radar-jersey-hibernate-0.9.0.jar:0.9.0]
    at org.radarbase.jersey.hibernate.HibernateRepository.transact(HibernateRepository.kt:18) ~[radar-jersey-hibernate-0.9.0.jar:0.9.0]
    at org.radarbase.authorizer.doa.RestSourceUserRepositoryImpl.create(RestSourceUserRepositoryImpl.kt:38) ~[authorizer-app-backend-4.1.1.jar:?]
    at org.radarbase.authorizer.service.RestSourceUserService.create(RestSourceUserService.kt:37) ~[authorizer-app-backend-4.1.1.jar:?]
    at org.radarbase.authorizer.resources.RestSourceUserResource.create(RestSourceUserResource.kt:115) ~[authorizer-app-backend-4.1.1.jar:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
    at java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]
    at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:52) ~[jersey-server-3.0.5.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:134) ~[jersey-server-3.0.5.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:177) ~[jersey-server-3.0.5.jar:?]
    at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:176) ~[jersey-server-3.0.5.jar:?]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:81) ~[jersey-server-3.0.5.jar:?]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:475) ~[jersey-server-3.0.5.jar:?]

Additional info

App version: 4.1.1

blootsvoets commented 1 year ago

This was caused by #214. It’s fixed in the latest release 4.2.0 — https://github.com/RADAR-base/RADAR-Rest-Source-Auth/releases/tag/v4.2.0.

yatharthranjan commented 1 year ago

I actually tried to upgrade to 4.2.0 previously but got an exception. Is there any additional config required for the upgrade?

[2023-01-27 16:14:18,804] INFO  - Reading configuration from /etc/radar-rest-sources-backend/authorizer.yml (ConfigLoader.kt:64)
[2023-01-27 16:14:19,959] INFO  - RADAR_IS_CONFIG_LOCATION environment variable not set, looking for it on the classpath (TokenVerifierPublicKeyConfig.java:59)
[2023-01-27 16:14:19,960] INFO  - Token public key endpoints set to [http://management-portal:8080/managementportal/oauth/token_key] (TokenVerifierPublicKeyConfig.java:85)
[2023-01-27 16:14:19,964] INFO  - Getting the JWT public key at http://management-portal:8080/managementportal/oauth/token_key (TokenValidator.java:231)
[2023-01-27 16:14:20,164] INFO  - Initializing EntityManagerFactory with config: RadarPersistenceInfo(managedClasses=[org.radarbase.authorizer.doa.entity.RestSourceUser, org.radarbase.authorizer.doa.entity.RegistrationState], properties={hibernate.connection.provider_class=org.hibernate.connection.C3P0ConnectionProvider, jakarta.persistence.jdbc.driver=org.postgresql.Driver, hibernate.c3p0.max_size=50, hibernate.c3p0.idle_test_period=300, hibernate.c3p0.max_statements=0, hibernate.dialect=org.hibernate.dialect.PostgreSQLDialect, hibernate.c3p0.min_size=0, jakarta.persistence.jdbc.url=jdbc:postgresql://radar-base-prod-postgres-1.ceojkvumrsd7.eu-west-2.rds.amazonaws.com:5432/rest_sources_auth, hibernate.c3p0.acquireRetryAttempts=3, hibernate.c3p0.breakAfterAcquireFailure=false, jakarta.persistence.jdbc.user=postgres, hibernate.c3p0.timeout=100, hibernate.c3p0.checkoutTimeout=5000, org.hibernate.flushMode=COMMIT, hibernate.c3p0.acquire_increment=1, jakarta.persistence.schema-generation.database.action=none, jakarta.persistence.jdbc.password===97.heaven.HEART.distant.47==}) (RadarEntityManagerFactoryFactory.kt:24)
[2023-01-27 16:14:20,177] INFO  - HHH000204: Processing PersistenceUnitInfo [name: org.radarbase.jersey.hibernate] (LogHelper.java:31)
[2023-01-27 16:14:20,219] INFO  - HHH000412: Hibernate ORM core version 6.1.5.Final (Version.java:44)
[2023-01-27 16:14:20,351] WARN  - HHH90000021: Encountered deprecated setting [javax.persistence.sharedCache.mode], use [jakarta.persistence.sharedCache.mode] instead (MetadataBuilderImpl.java:626)
[2023-01-27 16:14:20,447] INFO  - HHH000130: Instantiating explicit connection provider: org.hibernate.connection.C3P0ConnectionProvider (ConnectionProviderInitiator.java:125)
[2023-01-27 16:14:20,449] INFO  - HHH010002: C3P0 using driver: org.postgresql.Driver at URL: jdbc:postgresql://radar-base-prod-postgres-1.ceojkvumrsd7.eu-west-2.rds.amazonaws.com:5432/rest_sources_auth (C3P0ConnectionProvider.java:111)
[2023-01-27 16:14:20,449] INFO  - HHH10001001: Connection properties: {password=****, user=postgres} (C3P0ConnectionProvider.java:112)
[2023-01-27 16:14:20,450] INFO  - HHH10001003: Autocommit mode: false (C3P0ConnectionProvider.java:115)
[2023-01-27 16:14:20,464] INFO  - MLog clients using slf4j logging. (Slf4jMLog.java:212)
[2023-01-27 16:14:20,500] INFO  - Initializing c3p0-0.9.5.5 [built 11-December-2019 22:18:33 -0800; debug? true; trace: 10] (Slf4jMLog.java:212)
[2023-01-27 16:14:20,530] INFO  - HHH10001007: JDBC isolation level: <unknown> (C3P0ConnectionProvider.java:191)
[2023-01-27 16:14:20,553] INFO  - Initializing c3p0 pool... com.mchange.v2.c3p0.PoolBackedDataSource@b7f51595 [ connectionPoolDataSource -> com.mchange.v2.c3p0.WrapperConnectionPoolDataSource@cecbf844 [ acquireIncrement -> 1, acquireRetryAttempts -> 3, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 5000, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, contextClassLoaderSource -> caller, debugUnreturnedConnectionStackTraces -> false, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, forceSynchronousCheckins -> false, identityToken -> 1hgekbqat1vpbyo01s4mf3v|3b3056a6, idleConnectionTestPeriod -> 300, initialPoolSize -> 0, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 100, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 50, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 0, nestedDataSource -> com.mchange.v2.c3p0.DriverManagerDataSource@2e7361f8 [ description -> null, driverClass -> null, factoryClassLocation -> null, forceUseNamedDriverClass -> false, identityToken -> 1hgekbqat1vpbyo01s4mf3v|54c11750, jdbcUrl -> jdbc:postgresql://radar-base-prod-postgres-1.ceojkvumrsd7.eu-west-2.rds.amazonaws.com:5432/rest_sources_auth, properties -> {password=******, user=******} ], preferredTestQuery -> null, privilegeSpawnedThreads -> false, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false; userOverrides: {} ], dataSourceName -> null, extensions -> {}, factoryClassLocation -> null, identityToken -> 1hgekbqat1vpbyo01s4mf3v|69eb544f, numHelperThreads -> 3 ] (Slf4jMLog.java:212)
[2023-01-27 16:14:20,760] INFO  - HHH000400: Using dialect: org.hibernate.dialect.PostgreSQLDialect (DialectFactoryImpl.java:66)
[2023-01-27 16:14:21,018] INFO  - HV000001: Hibernate Validator 8.0.0.Final (Version.java:21)
[2023-01-27 16:14:21,396] INFO  - HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform] (JtaPlatformInitiator.java:51)
[2023-01-27 16:14:21,549] INFO  - Initializing Liquibase (DatabaseInitialization.kt:45)
[2023-01-27 16:14:21,667] INFO  - Set default schema name to public (JavaLogger.java:36)
[2023-01-27 16:14:22,097] INFO  - Reading from public.databasechangelog (JavaLogger.java:36)
[2023-01-27 16:14:22,142] INFO  - Successfully released change log lock (JavaLogger.java:36)
Exception in thread "main" java.lang.IllegalStateException: Cannot initialize database.
    at org.radarbase.jersey.hibernate.DatabaseInitialization.onEvent(DatabaseInitialization.kt:40)
    at org.glassfish.jersey.server.internal.monitoring.CompositeApplicationEventListener.onEvent(CompositeApplicationEventListener.java:49)
    at org.glassfish.jersey.server.ApplicationHandler.initialize(ApplicationHandler.java:440)
    at org.glassfish.jersey.server.ApplicationHandler.lambda$initialize$1(ApplicationHandler.java:297)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:292)
    at org.glassfish.jersey.internal.Errors.process(Errors.java:274)
    at org.glassfish.jersey.internal.Errors.processWithException(Errors.java:232)
    at org.glassfish.jersey.server.ApplicationHandler.initialize(ApplicationHandler.java:296)
    at org.glassfish.jersey.server.ApplicationHandler.<init>(ApplicationHandler.java:261)
    at org.glassfish.jersey.server.ApplicationHandler.<init>(ApplicationHandler.java:248)
    at org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpContainer.<init>(GrizzlyHttpContainer.java:310)
    at org.glassfish.jersey.grizzly2.httpserver.GrizzlyHttpServerFactory.createHttpServer(GrizzlyHttpServerFactory.java:93)
    at org.radarbase.jersey.GrizzlyServer.<init>(GrizzlyServer.kt:32)
    at org.radarbase.jersey.GrizzlyServer.<init>(GrizzlyServer.kt:21)
    at org.radarbase.authorizer.Main.main(Main.kt:42)
Caused by: liquibase.exception.ValidationFailedException: Validation Failed:
     1 changesets check sum
          db/changelog/changes/20211008113000_add_registration_created_at.xml::Add registration creation date::joris was: 8:39804bd8c15f83cb8fba7aa3c43b3ebe but is now: 8:b591643f784627ece6fbb19d838a3784

    at liquibase.changelog.DatabaseChangeLog.validate(DatabaseChangeLog.java:337)
    at liquibase.Liquibase.lambda$update$1(Liquibase.java:257)
    at liquibase.Scope.lambda$child$0(Scope.java:180)
    at liquibase.Scope.child(Scope.java:189)
    at liquibase.Scope.child(Scope.java:179)
    at liquibase.Scope.child(Scope.java:158)
    at liquibase.Liquibase.runInScope(Liquibase.java:2447)
    at liquibase.Liquibase.update(Liquibase.java:236)
    at liquibase.Liquibase.update(Liquibase.java:221)
    at liquibase.Liquibase.update(Liquibase.java:207)
    at org.radarbase.jersey.hibernate.DatabaseInitialization.initializeLiquibase(DatabaseInitialization.kt:53)
    at org.radarbase.jersey.hibernate.DatabaseInitialization.access$initializeLiquibase(DatabaseInitialization.kt:23)
    at org.radarbase.jersey.hibernate.DatabaseInitialization$onEvent$1$1.invoke(DatabaseInitialization.kt:35)
    at org.radarbase.jersey.hibernate.DatabaseInitialization$onEvent$1$1.invoke(DatabaseInitialization.kt:33)
    at org.radarbase.jersey.hibernate.DatabaseInitialization$Companion.useConnection$lambda$1(DatabaseInitialization.kt:64)
    at org.hibernate.jdbc.WorkExecutor.executeWork(WorkExecutor.java:37)
    at org.hibernate.internal.AbstractSharedSessionContract.lambda$doWork$3(AbstractSharedSessionContract.java:947)
    at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.coordinateWork(JdbcCoordinatorImpl.java:304)
    at org.hibernate.internal.AbstractSharedSessionContract.doWork(AbstractSharedSessionContract.java:963)
    at org.hibernate.internal.AbstractSharedSessionContract.doWork(AbstractSharedSessionContract.java:950)
    at org.radarbase.jersey.hibernate.DatabaseInitialization$Companion.useConnection(DatabaseInitialization.kt:64)
    at org.radarbase.jersey.hibernate.DatabaseInitialization.onEvent(DatabaseInitialization.kt:33)
    ... 14 more
blootsvoets commented 1 year ago

Ah good to know. The checksum could be disabled for one change set? https://stackoverflow.com/a/37483172