Hi,
I am getting some strange results in writing/reading with Threads using
Cayenne and I'm sure it's something I'm not understanding about
Cayenne's data caching. I'm hoping to get a solution to force a direct
read somehow but so far I haven't found anything with Mr. Google.
I'm using 4.1.B2.
The issue is that I believe that I am writing a value to the database
and the database contents reflect the update but subsequent reads in
other Threads are not picking up the new value. Here's an example in my
log file where I log the first Thread update to the object and a
subsequent read from another Thread
2019-10-03,12:38:01:727,INFO
,[CAsteriskAMIMgrProxyRemoteIF-Thread-1570],ClientBase,::NotifyQueue -
PostUpdate NotifyQueue=[Complete](125)Test
call->Phone=416-712-2323::NotifyEvent=[Running](15)Test call
2019-10-03,12:38:01:728,INFO
,[NotifyTypeHandlerDialer-pool-449-thread-1],ClientBase,::NotifyQueue -
PostLoad NotifyQueue=[Running](125)Test
call->Phone=416-712-2323::NotifyEvent=[Running](15)Test call
The first line PostUpdate shows that the NotifyQueue item (125) is
Complete and when I check the database the value is definitely showing
Complete. However the next line from a different thread is reading the
same NotifyQueue record (125) and it's displaying Running. I don't
understand how this is possible. All indications show the PostUpdate is
working but PostLoad is not picking up the changed value.
Here's a second example with another pair of NotifyQueue items
(127,129). The Web page picks up the correct status values (Complete)
as indicated in the log below
2019-10-03,13:31:07:535,INFO
,[http-nio-8080-exec-126],ClientBase,::NotifyQueue - PostLoad
NotifyQueue=[Complete](127)Test
call->Phone=416-712-2323::NotifyEvent=[New](17)Test call
2019-10-03,13:31:07:535,INFO
,[http-nio-8080-exec-126],ClientBase,::NotifyQueue - PostLoad
NotifyQueue=[Complete](129)Test
call->Phone=416-712-2323::NotifyEvent=[New](19)Test call
And the background ThreadNotifyEventsForClient again does not pickup the
updated Complete status (shows Running) more than a few seconds later
(as opposed to the microseconds in the first logging example). When I
do a manual query on the DB, the status is definitely Complete.
2019-10-03,13:31:32:265,INFO
,[ThreadNotifyEventsForClient-pool-545-thread-1],NotifyEvent,ThreadNotifyEventsForClient::NotifyEvent=[Running](17)Test
call::checkForCompletedQueueItems NotifyQueueCount=1
2019-10-03,13:31:32:265,DEBUG,[ThreadNotifyEventsForClient-pool-545-thread-1],NotifyEvent,ThreadNotifyEventsForClient::NotifyEvent=[Running](17)Test
call::checkForCompletedQueueItems
NotifyQueueItem=NotifyQueue=[Running](127)Test
call->Phone=416-712-2323::NotifyEvent=[Running](17)Test call
2019-10-03,13:31:32:265,DEBUG,[ThreadNotifyEventsForClient-pool-545-thread-1],NotifyEvent,ThreadNotifyEventsForClient::NotifyEvent=[Running](17)Test
call::checkForCompletedQueueItems
INCOMPLETE->NotifyQueue=[Running](127)Test
call->Phone=416-712-2323::NotifyEvent=[Running](17)Test call DEBUG
UNCOMMITTED=0
2019-10-03,13:31:32:265,INFO
,[ThreadNotifyEventsForClient-pool-545-thread-1],NotifyEvent,ThreadNotifyEventsForClient::NotifyEvent=[Running](19)Test
call::checkForCompletedQueueItems NotifyQueueCount=1
2019-10-03,13:31:32:265,DEBUG,[ThreadNotifyEventsForClient-pool-545-thread-1],NotifyEvent,ThreadNotifyEventsForClient::NotifyEvent=[Running](19)Test
call::checkForCompletedQueueItems
NotifyQueueItem=NotifyQueue=[Running](129)Test
call->Phone=416-712-2323::NotifyEvent=[Running](19)Test call
2019-10-03,13:31:32:265,DEBUG,[ThreadNotifyEventsForClient-pool-545-thread-1],NotifyEvent,ThreadNotifyEventsForClient::NotifyEvent=[Running](19)Test
call::checkForCompletedQueueItems
INCOMPLETE->NotifyQueue=[Running](129)Test
call->Phone=416-712-2323::NotifyEvent=[Running](19)Test call DEBUG
UNCOMMITTED=0
2019-10-03,13:31:32:265,INFO
,[ThreadNotifyEventsForClient-pool-545-thread-1],NotifyEvent,ThreadNotifyEventsForClient::Callista
Computer Telephony Inc.::checkForCompletedQueueItems Done
I have now made a change in my code for the background
ThreadNotifyEventsForClient from
List<NotifyQueue> listQueue = notifyEvent.getListNotifyQueue();
to what should be the actual underlying transaction generated by Cayenne
List<NotifyQueue> listQueue =
ObjectSelect.query(NotifyQueue.class)
.where(NotifyQueue.NOTIFY_EVENT.eq(notifyEvent))
.select(ClientBaseAdmin.getObjectContext());
Here's the extract from the map.xml file for the relationship
<db-relationship name="listNotifyQueue" source="NotifyEvent"
target="NotifyQueue" toMany="true">
<db-attribute-pair source="id" target="notifyEventID"/>
<obj-relationship name="listNotifyQueue" source="NotifyEvent"
target="NotifyQueue" deleteRule="Cascade"
db-relationship-path="listNotifyQueue"/>
And guess what. It works consistently with the explicit code change
with a difference that I now get a PostLoad event now in the
ThreadNotifyEventsForClient
2019-10-03,14:12:00:103,INFO
,[CAsteriskAMIMgrProxyRemoteIF-Thread-5291],ClientBase,::NotifyQueue -
PostUpdateNotifyQueue=[Complete](133)Test
call->Phone=416-712-2323::NotifyEvent=[Running](23)Test call
2019-10-03,14:12:00:107,INFO
,[ThreadNotifyEventsForClient-pool-758-thread-1],ClientBase,::NotifyQueue
- PostLoad NotifyQueue=[Complete](133)Test
call->Phone=416-712-2323::NotifyEvent=[Running](23)Test call
2019-10-03,14:12:00:107,INFO
,[ThreadNotifyEventsForClient-pool-758-thread-1],NotifyEvent,ThreadNotifyEventsForClient::NotifyEvent=[Running](23)Test
call::checkForCompletedQueueItems NotifyQueueCount=1
2019-10-03,14:12:00:107,DEBUG,[ThreadNotifyEventsForClient-pool-758-thread-1],NotifyEvent,ThreadNotifyEventsForClient::NotifyEvent=[Running](23)Test
call::checkForCompletedQueueItems
NotifyQueueItem=NotifyQueue=[Complete](133)Test
call->Phone=416-712-2323::NotifyEvent=[Running](23)Test call
2019-10-03,14:12:00:107,INFO
,[ThreadNotifyEventsForClient-pool-758-thread-1],NotifyEvent,ThreadNotifyEventsForClient::NotifyEvent=[Running](23)Test
call::checkForCompletedQueueItems NotifyEvent has been completed
2019-10-03,14:12:00:107,DEBUG,[ThreadNotifyEventsForClient-pool-758-thread-1],NotifyEvent,ThreadNotifyEventsForClient::NotifyEvent=[Running](23)Test
call::checkForCompletedQueueItems Generating NotifyLog for
NotifyQueue->NotifyQueue=[Complete](133)Test
call->Phone=416-712-2323::NotifyEvent=[Running](23)Test call
Can someone explain why this is the case and how I can "fix it" without
the code change.
Thanks,
Andrew
