FWD » Core Development » Base Language

I'm having issues with accessing the 'fwd' database in one test, the database seems to be setup to use H2 and I don't see anything wrong with the configuration/df/sql files for it. When I try a simple find first on the 'customer' table it gives me this:

[03/15/2021 15:21:46 EET] (com.goldencode.p2j.persist.Persistence:WARNING) [00000001:0000000D:bogus-->local/fwd/primary] error loading record
select customer.recid from Customer__Impl__ as customer order by customer.customernum asc
[03/15/2021 15:21:46 EET] (com.goldencode.p2j.persist.Persistence:SEVERE) [00000001:0000000D:bogus-->local/fwd/primary] error loading record
com.goldencode.p2j.persist.PersistenceException: Error uniqueResult
Caused by: java.sql.SQLException: A problem occurred while trying to acquire a cached PreparedStatement in a background thread.
        at com.mchange.v2.c3p0.stmt.GooGooStatementCache.acquireStatement(GooGooStatementCache.java:571)
        at com.mchange.v2.c3p0.stmt.GooGooStatementCache.checkoutStatement(GooGooStatementCache.java:204)
        at com.mchange.v2.c3p0.impl.NewPooledConnection.checkoutStatement(NewPooledConnection.java:321)
        at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:553)
        at com.goldencode.p2j.persist.orm.SQLQuery.uniqueResult(SQLQuery.java:248)
        at com.goldencode.p2j.persist.orm.Query.uniqueResult(Query.java:256)
        at com.goldencode.p2j.persist.Persistence.load(Persistence.java:1598)
        at com.goldencode.p2j.persist.RandomAccessQuery.executeImpl(RandomAccessQuery.java:4269)
        at com.goldencode.p2j.persist.RandomAccessQuery.execute(RandomAccessQuery.java:3437)
        at com.goldencode.p2j.persist.RandomAccessQuery.first(RandomAccessQuery.java:1501)
        at com.goldencode.p2j.persist.RandomAccessQuery.first(RandomAccessQuery.java:1387)
        at com.goldencode.testcases.oo.json.object_.ReadHandle.lambda$3(ReadHandle.java:141)
        at com.goldencode.p2j.util.Block.body(Block.java:604)
        at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:8556)
        at com.goldencode.p2j.util.BlockManager.topLevelBlock(BlockManager.java:8225)
        at com.goldencode.p2j.util.BlockManager.externalProcedure(BlockManager.java:493)
        at com.goldencode.p2j.util.BlockManager.externalProcedure(BlockManager.java:464)
        at com.goldencode.testcases.oo.json.object_.ReadHandle.execute(ReadHandle.java:68)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.goldencode.p2j.util.Utils.invoke(Utils.java:1548)
        at com.goldencode.p2j.main.StandardServer$MainInvoker.execute(StandardServer.java:2210)
        at com.goldencode.p2j.main.StandardServer.invoke(StandardServer.java:1646)
        at com.goldencode.p2j.main.StandardServer.standardEntry(StandardServer.java:581)
        at com.goldencode.p2j.main.StandardServerMethodAccess.invoke(Unknown Source)
        at com.goldencode.p2j.util.MethodInvoker.invoke(MethodInvoker.java:156)
        at com.goldencode.p2j.net.Dispatcher.processInbound(Dispatcher.java:783)
        at com.goldencode.p2j.net.Conversation.block(Conversation.java:422)
        at com.goldencode.p2j.net.Conversation.run(Conversation.java:232)
        at java.lang.Thread.run(Thread.java:745)
Caused by: org.h2.jdbc.JdbcSQLSyntaxErrorException: Table "CUSTOMER" not found; SQL statement:

When the server starts I can see those entries that seems to be related to persistence:

115 [main] INFO com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, contextClassLoaderSource -> caller, dataSourceName -> 1hge2ybagf0bhy41cz4rf0|236206f8, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> org.h2.Driver, extensions -> {}, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, forceSynchronousCheckins -> false, forceUseNamedDriverClass -> false, identityToken -> 1hge2ybagf0bhy41cz4rf0|236206f8, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:h2:mem:_meta_fwd;db_close_delay=-1;mv_store=false;query_cache_size=1024;, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 15, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 3, numHelperThreads -> 3, preferredTestQuery -> null, privilegeSpawnedThreads -> false, properties -> {user=******, password=******}, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, userOverrides -> {}, usesTraditionalReflectiveProxies -> false ]
[03/15/2021 15:33:52 EET] (com.goldencode.p2j.persist.DatabaseManager:INFO) Database local/fwd/primary initialized in 0 ms.
[03/15/2021 15:33:52 EET] (com.goldencode.p2j.util.TransactionManager:WARNING) Multiple registration of 'fwd' database.
[03/15/2021 15:33:52 EET] (com.goldencode.p2j.persist.orm.PooledDataSourceProvider:WARNING) Can't find a setter for the specified c3p0 parameter c3p0.validate
301 [main] INFO com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 2, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, contextClassLoaderSource -> caller, dataSourceName -> 1hge2ybagf0bhy41cz4rf0|4d071e4b, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> org.h2.Driver, extensions -> {}, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, forceSynchronousCheckins -> false, forceUseNamedDriverClass -> false, identityToken -> 1hge2ybagf0bhy41cz4rf0|4d071e4b, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:h2:../db/fwd;DB_CLOSE_DELAY=-1;MV_STORE=FALSE, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 900, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 0, maxStatementsPerConnection -> 100, minPoolSize -> 4, numHelperThreads -> 3, preferredTestQuery -> null, privilegeSpawnedThreads -> false, properties -> {user=******, password=******}, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, userOverrides -> {}, usesTraditionalReflectiveProxies -> false ]
303 [main] WARN com.mchange.v2.resourcepool.BasicResourcePool - Bad pool size config, start 3 < min 4. Using 4 as start.
[03/15/2021 15:33:54 EET] (com.goldencode.p2j.persist.Persistence:INFO) UDF version for db local/fwd/primary is FWD version undefined
Duplicate database Settings for local/fwd/dirty
2482 [main] INFO com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, contextClassLoaderSource -> caller, dataSourceName -> 1hge2ybagf0bhy41cz4rf0|22a22f1, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> org.h2.Driver, extensions -> {}, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, forceSynchronousCheckins -> false, forceUseNamedDriverClass -> false, identityToken -> 1hge2ybagf0bhy41cz4rf0|22a22f1, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:h2:mem:fwd;db_close_delay=-1;mv_store=false;query_cache_size=1024;, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 15, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 3, numHelperThreads -> 3, preferredTestQuery -> null, privilegeSpawnedThreads -> false, properties -> {user=******, password=******}, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, userOverrides -> {}, usesTraditionalReflectiveProxies -> false ]

Anything I can do to fix that, something we have setup wrong on testcases project?

Thanks

Is CUSTOMER a persistent table or a temp-table?

If persistent, what is the size of your database file (deploy/db/*.h2.db)?

Eric Faulhaber wrote:

Is CUSTOMER a persistent table or a temp-table?

If persistent, what is the size of your database file (deploy/db/*.h2.db)?

It's a persistent one, the size on deploy/db/fwd.h2.db is 172.032 bytes, though seems that last modified is 1st March 2021... If I open it there are a bunch of references to "CUSTOMER" table, odd is an ALTER TABLE statement is before the CREATE CACHED TABLE one but other than that no idea if it's anything wrong with that file :(

Eric Faulhaber wrote:

Is CUSTOMER a persistent table or a temp-table?

If persistent, what is the size of your database file (deploy/db/*.h2.db)?

Did a deploy.all and that seems to be recreated the database, all good now... hmm, maybe one of the server crashes could have broken the database?

Eric Faulhaber wrote:

Marian Edu wrote:

Did a deploy.all and that seems to be recreated the database, all good now... hmm, maybe one of the server crashes could have broken the database?

I assume you mean session crashes? Usually, any open transactions are rolled back if a session ends abnormally. However, H2 is not as well-tested as PostgreSQL, so it's possible.

Yes, it happens from time to time that Eclipse is crashing and leave the server process running so just have to kill it or MS$ decide is time for an upgrade or it simply crash with the blue screen :)

Problem is now it looks no matter what I'm trying I can't get the database to work anymore, running `clean.db.h2, create.db.h2, import.db.h2` does recreate the H2 databases but I can't access any table in there so I'm running out of ideas :(

Try to manually delete deploy/db/*.h2.db before recreating/importing the database.

Note that h2 DBM runs within the same process with the FWD server (by default, although it can be configured as a standalone server). Killing FWD can prevent rolling back pending/unfinished transactions, causing the storage (the *.h2.db files) to become corrupted. I also must occasionally kill the FWD process but I do not remember this kind of things to happen. It seems there are some differences between MS$ and Ubuntu in this regard.

Launching the FWD server from Eclipse may also make this problem worse. Consider starting the server separately.

Ovidiu Maxiniuc wrote:

Try to manually delete deploy/db/*.h2.db before recreating/importing the database.

Well, of course I've did that and the files were re-created but still no luck :(

Note that h2 DBM runs within the same process with the FWD server (by default, although it can be configured as a standalone server). Killing FWD can prevent rolling back pending/unfinished transactions, causing the storage (the *.h2.db files) to become corrupted. I also must occasionally kill the FWD process but I do not remember this kind of things to happen. It seems there are some differences between MS$ and Ubuntu in this regard.

What puzzle me is it did work yesterday but today no matter how many tries I've made the file gets recreated but still same error... stupid MS$, maybe it only works in 'odd' days :)

Greg Shah wrote:

Launching the FWD server from Eclipse may also make this problem worse. Consider starting the server separately.

True but since most of the fun takes part on the server side launching that in 'debug' mode from Eclipse makes it so much easier...

Marian Edu wrote:

Greg Shah wrote:

Launching the FWD server from Eclipse may also make this problem worse. Consider starting the server separately.

True but since most of the fun takes part on the server side launching that in 'debug' mode from Eclipse makes it so much easier...

I use the Community edition of IntelliJ instead of Eclipse. You may want to give it a try if you have some spare time. I think the interface is more user friendly, but you will need to get used with it, especially the different shortcuts.

At any rate, if you launch the server separately, use -d parameter to put it in debug mode. Then use the IDE to attach to the process, so you can debug. The default port is 2080. After that I see no difference between the two resulting environments, but maybe you will work around the issue this way.

Is it possible that the working directory for the server has changed? If so, then the database files would not be found. It is important to have the server's working directory in deploy/server/.

Greg Shah wrote:

Is it possible that the working directory for the server has changed? If so, then the database files would not be found. It is important to have the server's working directory in deploy/server/.

Nothing has changed, the files are there and looks like are being visible to the server as it does output this in console during startup...

38 [main] INFO com.mchange.v2.c3p0.C3P0Registry - Initializing c3p0-0.9.5.2 [built 08-December-2015 22:06:04 -0800; debug? true; trace: 10]
110 [main] INFO com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, contextClassLoaderSource -> caller, dataSourceName -> 1hge2ybagkc953812byn1j|7bb3294c, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> org.h2.Driver, extensions -> {}, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, forceSynchronousCheckins -> false, forceUseNamedDriverClass -> false, identityToken -> 1hge2ybagkc953812byn1j|7bb3294c, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:h2:mem:_meta_fwd;db_close_delay=-1;mv_store=false;query_cache_size=1024;, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 15, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 3, numHelperThreads -> 3, preferredTestQuery -> null, privilegeSpawnedThreads -> false, properties -> {user=******, password=******}, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, userOverrides -> {}, usesTraditionalReflectiveProxies -> false ]
[03/19/2021 09:06:49 EET] (com.goldencode.p2j.persist.DatabaseManager:INFO) Database local/fwd/primary initialized in 0 ms.
[03/19/2021 09:06:49 EET] (com.goldencode.p2j.util.TransactionManager:WARNING) Multiple registration of 'fwd' database.
[03/19/2021 09:06:49 EET] (com.goldencode.p2j.persist.orm.PooledDataSourceProvider:WARNING) Can't find a setter for the specified c3p0 parameter c3p0.validate
494 [main] INFO com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 2, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, contextClassLoaderSource -> caller, dataSourceName -> 1hge2ybagkc953812byn1j|2daf0cc9, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> org.h2.Driver, extensions -> {}, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, forceSynchronousCheckins -> false, forceUseNamedDriverClass -> false, identityToken -> 1hge2ybagkc953812byn1j|2daf0cc9, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:h2:../db/fwd;DB_CLOSE_DELAY=-1;MV_STORE=FALSE, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 900, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 20, maxStatements -> 0, maxStatementsPerConnection -> 100, minPoolSize -> 4, numHelperThreads -> 3, preferredTestQuery -> null, privilegeSpawnedThreads -> false, properties -> {user=******, password=******}, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, userOverrides -> {}, usesTraditionalReflectiveProxies -> false ]
496 [main] WARN com.mchange.v2.resourcepool.BasicResourcePool - Bad pool size config, start 3 < min 4. Using 4 as start.
[03/19/2021 09:06:51 EET] (com.goldencode.p2j.persist.Persistence:INFO) UDF version for db local/fwd/primary is FWD version undefined
Duplicate database Settings for local/fwd/dirty

Not sure about those warnings but then again it was always like that and it did work, even two days ago after recreating the database file but now it doesn't... maybe it's time for the classical OS restart :(

I don't normally see all this noise in the log at startup. Can you post your directory.xml, please?

Is the size or timestamp of your database file (deploy/db/fwd.h2.db) different before and after you run the server?

Eric Faulhaber wrote:

I don't normally see all this noise in the log at startup. Can you post your directory.xml, please?

Is the size or timestamp of your database file (deploy/db/fwd.h2.db) different before and after you run the server?

Good catch, the file was not changed at all when starting the server and turns out the working folder for the server process was 'testcases' while the file path in directory.xml was relative to deploy/server... what was happening is that FWD created the database in '../db' folder so it was not looking at the ones generated by db tasks :(

Problem solved, thanks and sorry for this... don't remember now if I had to create the directory at some point or FWD just managed to create it. If the database is not there it gets created automatically but looks like it's empty, probably some settings in FWD as I was expecting an error instead :)