Plugin: LoadHistory not finding anything?

Post by **jclausius** » Thu Sep 29, 2005 7:56 am

You should be able to set the server's log in Debug mode to see the calls to Plugins.

Another thought, you said you notice this when there is heavy transaction usage. Do you have a queue set up to handle when multiple transactions occur back to back to back?

For example, in the Vault ShadowFolder plugin all the web service OnEndTx() event does is place the call into an queue. There is another thread running which chekcs the queue, and processes the results from there.

Is it possible that if the plugin is busy with a history query, it misses other OnEndTx() events?

ismangil · Post by **ismangil** » Thu Sep 29, 2005 9:46 am

jclausius wrote:You should be able to set the server's log in Debug mode to see the calls to Plugins.

I will do that.

jclausius wrote: Another thought, you said you notice this when there is heavy transaction usage. Do you have a queue set up to handle when multiple transactions occur back to back to back?

No, the plugin is not async nor multithreaded. Basically OnEndTx() does the whole work for the transaction. Just like the sample

jclausius wrote: For example, in the Vault ShadowFolder plugin all the web service OnEndTx() event does is place the call into an queue. There is another thread running which chekcs the queue, and processes the results from there.

Is it possible that if the plugin is busy with a history query, it misses other OnEndTx() events?

I don't think it misses the tx event. I mean, the plugin log shows that it does process every txid. It's just that when processing certain txid, usually one or two in a number of transactions, the historyquery API returns 0 rows.

Post by **jclausius** » Thu Sep 29, 2005 10:03 am

Can you try something else? Can you put a Thread.Sleep(1000) just before you begin the history query?

I don't know if this will help, but I wonder if BeginHistoryQuery() is being called before the server has even updated its own internal repository tree. This would be creating a kind of "race" condition - where the database is up to date, but the server has yet to finish updating its own internal objects.

In a case like this, the server will use the "last" known tree for the history query, which might explain why you are not seeing the last transaction.

Edit: added race condition

ismangil · Post by **ismangil** » Tue Nov 08, 2005 7:30 am

Another go at this problem

This is stil happening occasionally. It does seems to be some kind of multithreading issue. I've managed to extract some logs around the problem transactions. I've added five logs to this post and a few more to the next post.

Here's my analysis:

- Tx 11203 up to 11206 seems fine. Even though the plugin was called less than a second after the transaction, history query works as expected.

- Tx 11207 is the problem. Although the history query is done at 08:02:08, it only got 2 (irrelevant) rows. Compare this with history query for 11206 at 08:02:05 which returns 6 rows!

- Only at 08:02:12 when tx 11208 history query is done we got 9 rows.
- 11209 is the same strange results again, only 2 rows, however they were the right rows.
- 11210 is back to normal with 11 rows, including the relevant rows.

And additional point is that although I separated the logs for easier analysis, all the things happening above were in fact happening almost concurrently, you can see that by the log timestamp. And some were happening on different threads (presumably allocated by asmx ASP.NET implementation), some were reused.

I can understand if it behaves consistently as you said, which is the tree is not yet updated, but in this case it can be shown that a previous history query contains more transaction compared to a more recent history query (all within almost the same history timeframe).

I'm gonna stop now cos my head hurts...

ismangil · Post by **ismangil** » Tue Nov 08, 2005 7:31 am

Additional logs.

ismangil · Post by **ismangil** » Wed Nov 16, 2005 4:57 am

Bump! I understand that the Vault API is unsupported though, so I guess it is OK for this thing to be unresolved...

Post by **jclausius** » Wed Nov 16, 2005 7:36 am

Sorry, I took the mention of a multi-threaded issue as a problem in the plugin, and was waiting for additional info.

I'll take a look at things.

Post by **jclausius** » Wed Nov 16, 2005 8:57 am

Did the Thread.Sleep() code get placed into the plugin before the query is ever executed?

What if you made it sleep for 3 seconds?

Post by **jclausius** » Wed Nov 16, 2005 9:00 am

Another question... Is your plugin on the *same* machine as the Vault server, or is it located on another web server?

ismangil · Post by **ismangil** » Wed Nov 16, 2005 9:02 am

jclausius wrote:Did the Thread.Sleep() code get placed into the plugin before the query is ever executed?

What if you made it sleep for 3 seconds?

The logs above are from the plugin without the thread.sleep. I have not had the chance to deploy the updated code.

I will deploy it as soon as possible.

ismangil · Post by **ismangil** » Wed Nov 16, 2005 9:02 am

jclausius wrote:Another question... Is your plugin on the *same* machine as the Vault server, or is it located on another web server?

It is located on the same machine as the Vault server.

Post by **jclausius** » Wed Nov 16, 2005 9:37 am

One other thing comes to mind...

The history query's time parameter is based on when the transaction began. For example, if OnEndTx is called after a 3 minute transaction, a history query using a floor of 30 seconds ago (with no ceiling), will not retrieve any results.

A thought on solving this problem in a different way... It is possible to retrieve a floor date/time derived from the "Version" history on $/. This transaction date (minus 1 second) could then be used as the floor of the history query.

ismangil · Post by **ismangil** » Wed Nov 16, 2005 9:44 am

jclausius wrote:One other thing comes to mind...

The history query's time parameter is based on when the transaction began. For example, if OnEndTx is called after a 3 minute transaction, a history query using a floor of 30 seconds ago (with no ceiling), will not retrieve any results.

Makes sense. However in this case it is querying with a floor of 5 mins ago, and I am sure that no transaction lasts more than 5 mins.

jclausius wrote: A thought on solving this problem in a different way... It is possible to retrieve a floor date/time derived from the "Version" history on $/. This transaction date (minus 1 second) could then be used as the floor of the history query.

I don't get this. Why would this be better?

Post by **jclausius** » Wed Nov 16, 2005 9:58 am

ismangil wrote:
jclausius wrote: A thought on solving this problem in a different way... It is possible to retrieve a floor date/time derived from the "Version" history on $/. This transaction date (minus 1 second) could then be used as the floor of the history query.
I don't get this. Why would this be better?

It would be more robust as the 5 minute window would not be required as you know the transaction's correct date.

Again, this was merely a suggestion, since there is no guarantee as to the timing of when OnEndTx() will be called.

ismangil · Post by **ismangil** » Wed Nov 16, 2005 10:16 am

jclausius wrote:It would be more robust as the 5 minute window would not be required as you know the transaction's correct date.

Again, this was merely a suggestion, since there is no guarantee as to the timing of when OnEndTx() will be called.

Maybe it will be more robust, but in this particular issue isn't the case that the transaction datetime happens well within the floor on the history query?