Hi Jim, one user undoubtedly experienced a hang of PanX yesterday, although she did not report this. The server log shows these two lines repeated three times per second for over six minutes (over 1100 times):
04/02/2021
9:59:29 am
Session 35 (Lisa —’s 2019 iMac:Lisa —) locked record 7995 of database: SD Matters
04/02/2021
9:59:29 am
Automatic unlock of record 7995 in database: SD Matters (already locked by this user)
(We found earlier that the text list refresh procedure when used in a text editor procedure could cause this problem, but I have ruled out that as a cause.)
Do you have any other idea what could cause this? The log seems to say that the client keeps trying to lock a record that it has already locked. The log does not show a successful locking of the record. The very first time the locking occurs during this session, the automatic unlock immediately occurs. I reviewed every reference to this record from the time it was created 4 days earlier and did not find anything unusual.
The day before, the user’s computer synchronized and this record was one of the changed records included in the syncing, but no other reference to the record appears in the log with this user accessing the record. (Other users also received this record during a sync.)
I can tell you what’s happening on the server side. When a request comes in to lock a record, the server checks to see if that record is already locked by that user. Theoretically that shouldn’t ever happen, but if it does, the server says ok, I’ll let you lock it again because you’ve already got it locked. So that shouldn’t cause a problem other than possibly the extra delay of the redundant request.
What I don’t know is why the client is sending redundant lock requests. You mention that there is a Text List on your form and my first speculation is that it might be related to that. If a Text List is associated with a database field then clicking on it will lock the record. It should only do that once, but I’ve noticed that Apple’s NSTable class, which is used for Text Lists and Matrixes, sometimes sends out extra messages. That should get filtered out on the client side, but still I think that would be the first place for me to look. Especially since it is happening multiple times per second, that definitely sounds like an NSTable issue.
I think it does, actually. When the automatic unlock happens, the server actually puts two lines into the log – first the unlock, then the lock. Maybe I should change the way the log works so that there is only one line that says re-locked record, because that is what is happening. But then maybe you wouldn’t have noticed this, and it’s good that you did because I should investigate this. But I think it’s quite probable that this isn’t causing any actual problem for you other than extra network traffic. It’s quite possible that the user didn’t report a hang because she didn’t notice anything wrong. Then it stopped because she moved to a different record.
The text lists in this database do not use Database Navigator; they all display variables. Maybe that affects the hypothesis of a TextList causing the problem. but I am still investigating other possible sources of attempted locking.
Unfortunately, I cannot reconstruct now the exact mouse clicks by the user when the problem began.
I wrote: The log does not show a successful locking of the record, then you replied:
I reviewed the log from the creation of record 7995 until the failure occurred. It was locked 11 times over the 4 days since it was created. For each of those there is a corresponding commit record in the log. So I do not think it was locked 9:59:29 on 4/2 when the first lock/Automatic unlock statements appeared in the log.
The final log entry in the series of lock/Automatic unlock appears at 10:05:46, and there is no corresponding unlock log entry, suggesting that the record was left locked. The next entry from this user is:
I thought that indicated that the server connection to her computer had been lost (she would have force quit) and that when she reconnected the server resumed the session. (That was an issue that you fixed early in our testing.)
ID 7995 was finally unlocked on 4/3/21:
04/03/2021 9:43:34 am Automatic unlock of record 7995 in database: SD Matters (original session gone) (Query, why didn’t the server unlock it much earlier when it did not confirm with a Keep Alive message from client?)
Then it was locked then committed several times by me while investigating this issue.
I was not thinking that they used Database Navigator, I was thinking that they were linked to a database field (to display/edit that field). If they are linked to variables, then my hypothesis is wrong.
Since I don’t have the complete log, I could well be wrong in my analysis. But I did want to let you know that an auto-unlock in the log will always be paired with a lock immediately after.
Thanks for your thorough reporting, unfortunately still leaving a mystery as to why the client repeatedly locked the same record.