Table not found although metadata successfully fetched

[kidharbachan]

I am currently using activejdbc-2.2 in a JBoss 6.4.5 AS in a 2 server domain. Both servers are connecting to the same datasource and we have verified that the table does exist in the db and the user is the owner of the database.

Server 1 works as expected.
Server 2 fails to find a table that was successfully registered at startup - it ALWAYS fails.
I have pasted the relevant log lines below as well as the exception.
Can you point me in a direction on what to check for next?

21:43:05,497 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Registered model: class estatements.batch_splitter.ports.sql.LetterTable
21:43:05,497 WARN [org.javalite.activejdbc.MetaModels] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Double-register: node_item_synchronization: MetaModel: node_item_synchronization, class estatements.settings.model.NodeItemSynchronizationTable
21:43:05,497 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Registered model: class estatements.batch_splitter.ports.sql.NodeItemSynchronizationTable
21:43:05,503 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.qtool.savetodatabase.camel-1_Worker-1) Fetched metadata for table: batch

...

21:43:05,610 INFO [org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory] (ServerService Thread Pool -- 66) HHH000397: Using ASTQueryTranslatorFactory
21:43:05,616 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.email_system.camel-1_Worker-1) Fetched metadata for table: node
21:43:05,623 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Fetched metadata for table: document_security
21:43:05,623 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.email_system.camel-1_Worker-1) Fetched metadata for table: node_item_synchronization
21:43:05,624 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.qtool.savetodatabase.camel-1_Worker-1) Fetched metadata for table: email_info

...

21:43:05,788 INFO [org.javalite.activejdbc.MetaModel] (DefaultQuartzScheduler-estatements.email_system.camel-1_Worker-1) Association found: EmailDispatchQueueTable ----------< EmailDispatchAttemptTable, type: has-many
21:43:05,789 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.qtool.savetodatabase.camel-1_Worker-1) Fetched metadata for table: node_item_synchronization
21:43:05,791 INFO [org.javalite.activejdbc.MetaModel] (DefaultQuartzScheduler-estatements.email_system.camel-1_Worker-1) Association found: EmailDispatchAttemptArchiveTable >---------- EmailDispatchResultTable, type: belongs-to
21:43:05,791 INFO [org.javalite.activejdbc.MetaModel] (DefaultQuartzScheduler-estatements.email_system.camel-1_Worker-1) Association found: EmailDispatchResultTable ----------< EmailDispatchAttemptArchiveTable, type: has-many

...

21:43:05,944 WARN [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Failed to retrieve metadata for table: 'invoice_email_description'. Are you sure this table exists? For some databases table names are case sensitive.
21:43:05,972 WARN [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Failed to retrieve metadata for table: 'invoice_recipient'. Are you sure this table exists? For some databases table names are case sensitive.
21:43:05,985 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Fetched metadata for table: letter
21:43:06,007 WARN [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Failed to retrieve metadata for table: 'letter_email_description'. Are you sure this table exists? For some databases table names are case sensitive.
21:43:06,052 WARN [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Failed to retrieve metadata for table: 'letter_recipient'. Are you sure this table exists? For some databases table names are case sensitive.
21:43:06,075 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Fetched metadata for table: node
21:43:06,090 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Fetched metadata for table: node_item_synchronization
21:43:06,112 INFO [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Fetched metadata for table: property

..

21:47:05,032 INFO [org.javalite.activejdbc.LazyList] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-7) {"sql":"SELECT * FROM property WHERE propertyGroup_Id IN (?) ORDER BY id","params":[2],"duration_millis":2,"cache":"miss"}
21:47:05,035 INFO [org.javalite.activejdbc.LazyList] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-7) {"sql":"SELECT * FROM property_group WHERE (NODE_ID IS NULL OR NODE_ID=?) AND NAME=?","params":[5,"email_dispatch_config"],"duration_millis":1,"cache":"miss"}
21:47:05,038 INFO [org.javalite.activejdbc.LazyList] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-7) {"sql":"SELECT * FROM property WHERE propertyGroup_Id IN (?) ORDER BY id","params":[7],"duration_millis":3,"cache":"miss"}
21:47:05,042 INFO [org.javalite.activejdbc.LazyList] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-7) {"sql":"SELECT * FROM property_group WHERE (NODE_ID IS NULL OR NODE_ID=?) AND NAME=?","params":[5,"crs_webservice_config"],"duration_millis":2,"cache":"miss"}
21:47:05,043 INFO [org.javalite.activejdbc.LazyList] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-7) {"sql":"SELECT * FROM property WHERE propertyGroup_Id IN (?) ORDER BY id","params":[32],"duration_millis":1,"cache":"miss"}
21:47:05,048 INFO [estatements.batch_splitter.ports.csf_files.CsfBatchQueue] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-7) Selected batch SVDOLETA_OCT01 for processing
21:47:05,059 ERROR [estatements.batch_splitter.ports.csf_files.CsfBatchQueue] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-7) Error processing batch SVDOLETA_OCT01: org.javalite.activejdbc.InitException: Failed to find table: node_item_synchronization
at org.javalite.activejdbc.MetaModel.getAttributeNames(MetaModel.java:266) [activejdbc-2.2.jar:]
at org.javalite.activejdbc.Model.hydrate(Model.java:234) [activejdbc-2.2.jar:]
at org.javalite.activejdbc.ModelDelegate.instance(ModelDelegate.java:268) [activejdbc-2.2.jar:]
at org.javalite.activejdbc.ModelDelegate.instance(ModelDelegate.java:262) [activejdbc-2.2.jar:]
at org.javalite.activejdbc.LazyList$1.onNext(LazyList.java:333) [activejdbc-2.2.jar:]
at org.javalite.activejdbc.RowListenerAdapter.next(RowListenerAdapter.java:30) [activejdbc-2.2.jar:]
at org.javalite.activejdbc.RowProcessor.processRS(RowProcessor.java:64) [activejdbc-2.2.jar:]
at org.javalite.activejdbc.RowProcessor.with(RowProcessor.java:38) [activejdbc-2.2.jar:]
at org.javalite.activejdbc.LazyList.hydrate(LazyList.java:331) [activejdbc-2.2.jar:]
at org.javalite.activejdbc.AbstractLazyList.size(AbstractLazyList.java:36) [activejdbc-2.2.jar:]
at estatements.settings.SettingsClient.find(SettingsClient.java:125) [settings-2.21.0.jar:]
at estatements.settings.SettingsClient.tryCreateOrFetch(SettingsClient.java:152) [settings-2.21.0.jar:]
at estatements.batch_splitter.adapters.SqlNodeSynchronizer.synchronizeNodes(SqlNodeSynchronizer.java:52) [batch-splitter-2.21.0.jar:]
at estatements.batch_splitter.adapters.SqlNodeSynchronizer.process(SqlNodeSynchronizer.java:31) [batch-splitter-2.21.0.jar:]
at estatements.batch_splitter.adapters.SqlNodeSynchronizer.process(SqlNodeSynchronizer.java:15) [batch-splitter-2.21.0.jar:]
at estatements.batch_splitter.ports.csf_files.CsfBatchQueue.processNext(CsfBatchQueue.java:162) [batch-splitter-2.21.0.jar:]
at estatements.batch_splitter.hosting.Schedule.executeSplittingProcess(Schedule.java:198) [classes:]
at estatements.batch_splitter.hosting.Schedule.access$500(Schedule.java:39) [classes:]
at estatements.batch_splitter.hosting.Schedule$3$1.process(Schedule.java:136) [classes:]
at org.apache.camel.processor.DelegateSyncProcessor.process(DelegateSyncProcessor.java:63) [camel-core-2.19.1.jar:2.19.1]
at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:77) [camel-core-2.19.1.jar:2.19.1]
at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:541) [camel-core-2.19.1.jar:2.19.1]
at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:198) [camel-core-2.19.1.jar:2.19.1]
at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:198) [camel-core-2.19.1.jar:2.19.1]
at org.apache.camel.processor.loadbalancer.QueueLoadBalancer.process(QueueLoadBalancer.java:44) [camel-core-2.19.1.jar:2.19.1]
at org.apache.camel.util.AsyncProcessorHelper.process(AsyncProcessorHelper.java:109) [camel-core-2.19.1.jar:2.19.1]
at org.apache.camel.processor.loadbalancer.LoadBalancerSupport.process(LoadBalancerSupport.java:97) [camel-core-2.19.1.jar:2.19.1]
at org.apache.camel.component.quartz2.CamelJob.execute(CamelJob.java:58) [camel-quartz2-2.19.1.jar:2.19.1]
at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [quartz-2.2.3.jar:]
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [quartz-2.2.3.jar:]

21:47:05,063 INFO [org.javalite.activejdbc.LazyList] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-7) {"sql":"SELECT * FROM property_group WHERE (NODE_ID IS NULL OR NODE_ID=?) AND NAME=?","params":[5,"pdf"],"duration_millis":1,"cache":"miss"}
21:47:05,066 INFO [org.javalite.activejdbc.LazyList] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-7) {"sql":"SELECT * FROM property WHERE propertyGroup_Id IN (?) ORDER BY id","params":[2],"duration_millis":3,"cache":"miss"}

[ipolevoy]

@kidharbachan it is hard to tell why looking at your logs. However, I think the reason is probably that your servers might use connections to the DB with different permissions - one can pull metadata, one cannot. Can you provide all log statements related
to ActiveJDBC for both servers?

Also, by default you are using Runtime Discovery feature, the one that queries the database for the structure at runtime (finds tables, relationships, etc).

However, there is a second method: Static Discovery. If you use this method, the schema discovery will be processed at build time, and the file with schema metadata will be automatically packed into your app. This way, ActiveJDBC will not be performing any runtime discovery. It is important to understand that your local database for the build must have the same structure as production (obviously).

[kidharbachan]

@ipolevoy I have confirmed that the user and permissions are exactly the same between working and non-working cases.
We are using the default Runtime Discovery and not the Static Discovery.

I have attached the working and non-working cases log files.
activejdbc.logs.working.zip
activejdbc.logs.broken.zip

[ipolevoy]

@kidharbachan this:

21:43:05,623 INFO  [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.email_system.camel-1_Worker-1) Fetched metadata for table: node_item_synchronization
21:43:05,789 INFO  [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.qtool.savetodatabase.camel-1_Worker-1) Fetched metadata for table: node_item_synchronization
21:43:06,090 INFO  [org.javalite.activejdbc.Registry] (DefaultQuartzScheduler-estatements.batch_splitter.camel-1_Worker-2) Fetched metadata for table: node_item_synchronization

is telling me that in the same process, you have metadata discovery happening in multiple threads at the same time. This is might cause some race conditions. Please, try changing code to run a simple SQL before you start multithreaded processes, as this will ensure that the discovery will not be trampling each other.

If you do not want to change any code, I suggest you use the static discovery as suggested above: #1055 (comment)

[kidharbachan]

Thank you for your input @ipolevoy
We will attempt the suggestions above

[ipolevoy]

@kidharbachan did you resolve your prod issue?

[kidharbachan]

@ipolevoy We are still checking howto make only one call to init function. We will let you know if that resolves the issue.

[kidharbachan]

@ipolevoy we found that the table was being created twice in the code. Removing the duplicate resolved the issue.
Thank you for your responses and support.

[ipolevoy]

@kidharbachan I'm glad your issue is resolved. Can you please explain how a table is created "in code". Are you using some kind of a migration mechanism?

[kidharbachan]

@ipolevoy I may have confused you. It was defined like this in the code in 2 classes.
class 1 @table("tableX"), class 2 @table("tableX")

[ipolevoy]

Ah, got it. Glad you sorted things out!