Logout exception after DB Recreate: ERROR: relation "persistent_logins" does not exist

chrisbeaham · September 30, 2022, 12:29pm

Jmix version: 1.3.3
Jmix Studio plugin version: 1.3.7-213
IntelliJ IDEA 2022.2.2 (Community Edition)
Build #IC-222.4167.29, built on September 13, 2022
Runtime version: 17.0.4+7-b469.53 x86_64
VM: OpenJDK 64-Bit Server VM by JetBrains s.r.o.
Kotlin: 222-1.7.10-release-334-IJ4167.29
Java 17.0.4 2022-08-18 LTS
Java ™ SE Runtime Environment (build 17.0.4.1+1-LTS-2)
Java HotSpot ™ 64-Bit Server VM (build 17.0.4.1+1-LTS-2, mixed mode, sharing)
Operating System: macOS 12.6 (21G115)
File System: Case-Sensitive Journaled HFS+ (APFS)
Database: PostgreSQL 13

Hello Everyone

For your information, after pulling my current master version to my laptop I did a “Main Data Store → Recreate” which generated the following new change log:

<?xml version="1.0" encoding="UTF-8"?>
<databaseChangeLog
        xmlns="http://www.liquibase.org/xml/ns/dbchangelog"
        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
        xsi:schemaLocation="http://www.liquibase.org/xml/ns/dbchangelog
                      http://www.liquibase.org/xml/ns/dbchangelog/dbchangelog-4.11.xsd"
        objectQuotingStrategy="QUOTE_ONLY_RESERVED_WORDS">
    <changeSet id="1" author="notefall">
        <dropTable cascadeConstraints="true" tableName="persistent_logins"/>
    </changeSet>
</databaseChangeLog>

and since its execution I receive the following error in my web browser when I logout:

Whitelabel Error Page
This application has no explicit mapping for /error, so you are seeing this as a fallback.
Fri Sep 30 08:18:41 CEST 2022
There was an unexpected error (type=Internal Server Error, status=500).

and the following error and stack trace are in Jmix Studio and my logfile:

Caused by: org.postgresql.util.PSQLException: ERROR: relation “persistent_logins” does not exist

org.springframework.jdbc.BadSqlGrammarException: PreparedStatementCallback; bad SQL grammar [delete from persistent_logins where username = ?]; nested exception is org.postgresql.util.PSQLException: ERROR: relation “persistent_logins” does not exist
Position: 13
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:239) ~[spring-jdbc-5.3.22.jar:5.3.22]
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:70) ~[spring-jdbc-5.3.22.jar:5.3.22]
at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1541) ~[spring-jdbc-5.3.22.jar:5.3.22]
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:667) ~[spring-jdbc-5.3.22.jar:5.3.22]
at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:960) ~[spring-jdbc-5.3.22.jar:5.3.22]
at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1015) ~[spring-jdbc-5.3.22.jar:5.3.22]
at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:1025) ~[spring-jdbc-5.3.22.jar:5.3.22]
at org.springframework.security.web.authentication.rememberme.JdbcTokenRepositoryImpl.removeUserTokens(JdbcTokenRepositoryImpl.java:115) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.authentication.rememberme.PersistentTokenBasedRememberMeServices.logout(PersistentTokenBasedRememberMeServices.java:162) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.authentication.logout.CompositeLogoutHandler.logout(CompositeLogoutHandler.java:54) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:99) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.22.jar:5.3.22]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:112) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:82) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:55) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.22.jar:5.3.22]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.session.DisableEncodeUrlFilter.doFilterInternal(DisableEncodeUrlFilter.java:42) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.22.jar:5.3.22]
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183) ~[spring-security-web-5.7.2.jar:5.7.2]
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354) ~[spring-web-5.3.22.jar:5.3.22]
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267) ~[spring-web-5.3.22.jar:5.3.22]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.22.jar:5.3.22]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.22.jar:5.3.22]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.22.jar:5.3.22]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.22.jar:5.3.22]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.22.jar:5.3.22]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.22.jar:5.3.22]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:360) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:399) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:890) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1789) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.65.jar:9.0.65]
at java.base/java.lang.Thread.run(Thread.java:829) ~[na:na]
Caused by: org.postgresql.util.PSQLException: ERROR: relation “persistent_logins” does not exist
Position: 13
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2675) ~[postgresql-42.3.6.jar:42.3.6]
Caused by: org.postgresql.util.PSQLException: ERROR: relation “persistent_logins” does not exist

at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2365) ~[postgresql-42.3.6.jar:42.3.6]
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:355) ~[postgresql-42.3.6.jar:42.3.6]
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:490) ~[postgresql-42.3.6.jar:42.3.6]
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:408) ~[postgresql-42.3.6.jar:42.3.6]
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:167) ~[postgresql-42.3.6.jar:42.3.6]
at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:135) ~[postgresql-42.3.6.jar:42.3.6]
at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-4.0.3.jar:na]
at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-4.0.3.jar:na]
at org.springframework.jdbc.core.JdbcTemplate.lambda$update$2(JdbcTemplate.java:965) ~[spring-jdbc-5.3.22.jar:5.3.22]
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651) ~[spring-jdbc-5.3.22.jar:5.3.22]
… 56 common frames omitted

What do you recommend to resolve this problem?

Thanks in advance for your feedback.

Best regards
Chris

krivopustov · October 3, 2022, 12:40pm

Hi Chris,

To restore the table, create a changelog in your project and add the following changeset:

    <changeSet id="4" author="security-data">
        <createTable tableName="persistent_logins">
            <column name="series" type="varchar(64)">
                <constraints primaryKey="true" nullable="false"/>
            </column>
            <column name="username" type="varchar(64)">
                <constraints nullable="false"/>
            </column>
            <column name="token" type="varchar(64)">
                <constraints nullable="false"/>
            </column>
            <column name="last_used" type="timestamp">
                <constraints nullable="false"/>
            </column>
        </createTable>
    </changeSet>

Let’s try to find out, why Studio has generated that dropTable changeset. Do you have the main.datasource.studio.liquibase.excludePrefixes property in application.properties?

Also, are you sure you have executed the Recreate command? Normally it drops the entire database and creates a new one using your set of changelogs, without generating new ones.

Regards,
Konstantin

chrisbeaham · October 4, 2022, 7:43pm

@krivopustov

Hi Konstantin

Thank you for your support and the change log source; it has resolved the problems.

I have the main.datasource.studio.liquibase.excludePrefixes property in my application properties but with a different spelling, exclude-prefixes instead of excludePrefixes:

main.datasource.studio.liquibase.exclude-prefixes=audit_,email_,sys_,ui_,qrtz_,sec_role,sec_group,sec_group_hierarchy,sec_user_role,sec_permission,sec_constraint,sec_localized_constraint_msg,sec_session_attr,sec_user_setting,sec_user_substitution,sec_logged_entity,sec_logged_attr,sec_entity_log,sec_filter

If I remember correctly, this property and most of these values where assigned during the Cuba to Jmix migration. I added some others myself after reading the documentation.

I am absolutely sure that I executed a Recreate command; this is my standard procedure when I move to working with my laptop. I check everything on my iMac into my Github repository, then I update IntelliJ, Jmix Studio, Postgresql and Java on my laptop, pull my Master to my laptop and then recreate my database. While logging in, my application required a Admin password reset and displayed a few other options, which confirms that my database was recreated when this problem occurred.

Please note that I did not check in the <dropTable cascadeConstraints="true" tableName="persistent_logins"/> change log or your corrective change log to my GitHub repository and I have not yet moved back to working on my iMac; therefore, I could try and perform the same procedure on my iMac as I did on my laptop to try and reproduce the problem there. I am not able to reproduce it on my laptop.

Is there any other information that you need or do you have any further suggestions before I try and reproduce it on my iMac?

Best regards
Chris

krivopustov · October 7, 2022, 1:20pm

Hi Chris,

Thank you for the thorough explanation.
Regarding the property name - it should work with kebab case too, so it’s not a problem.

We have an idea why this property is not read sometimes from the framework module, and will try to fix it.

To eliminate the issue in your project regardless of the future fix, you can add the persistent_logins value to the property of your project, like:

main.datasource.studio.liquibase.exclude-prefixes=audit_,...,persistent_logins

Regards,
Konstantin

chrisbeaham · October 8, 2022, 5:55pm

@krivopustov

Hi Konstantin

Thank you very much for the information and the problem resolution.

I was not able to reproduce the problem when moving back to my iMac development environment (before adding persistent_logins to exclude-prefixes) but I repeat this procedure approximately once a month and will let you know if it ever happens again.

Best regards
Chris