Plugin: LoadHistory not finding anything?

[ismangil]

I am trying to track down a subtle bug in a plugin I have written based on Jeremy's template. The plugin works most of the time, but it fails in the manner I will describe below.

Vault server 3.1.1, with the plugin is using 3.0.6 client API dll's.

Using VS2003 integration, when checking in multiple files together across several projects through the "Pending Checkins" window, Vault server will register it as several transactions (see attached log). Is this normal? I though 1 changeset = 1 transaction?

In the attached log, the user checks in 13 files (across several projects in the solution) together through VS2003. It seems to translate to 5 Tx: 7955 through 7959.

The puzzling thing is, for each of tx 7955-7958, LoadHistory does not return anything, despite specifying a time window of -5 and +2 mins of current time (note the time span compare to log time). This means for the four transactions the plugin 'ignores' the user.[/list]

Now for tx 7959, suddenly LoadHistory sees all 13 items, for tx 7955-7958 as well. However since at this point I am only interested in 7959, that tx is processed as normal.

Does this make any sense?

[dan]

First off, yes, when checking files in from the IDE, change sets are not always what you think they should be. Visual Studio sends files to us in batches, probably one batch per project. Since the VS API is such that we don't know whether more files will be coming or not, we just put all files in a single batch into one change set (since we don't know more are coming, the best we can do is process it this way). So, for a single checkin from VS, you can see multiple change sets.

For the history issues, I'm not sure what is happening. The code looks right, but I'm not sure I understand about ignoring users - it doesn't look like users are being filtered on. Perhaps I need to understand more about the app.

The server time clue might make sense too. You might want check the server time and make sure it is within 2 minutes of the client time, or just increase the future time by quite a bit just to make sure.

[ismangil]

First off, yes, when checking files in from the IDE, change sets are not always what you think they should be.

OK, I gathered as much that it is an SCC issue, just to make sure. It may have a bearing though, because I just tested an 18 file checkin across multiple folders as one changeset from GUI client and the plugin processed the single transaction, all 18 items, flawlessly.

For the history issues, I'm not sure what is happening. The code looks right, but I'm not sure I understand about ignoring users - it doesn't look like users are being filtered on. Perhaps I need to understand more about the app.

I'm sorry the "user filter" was misleading. What I meant was because the history query returned 0 rows, the plugin can't do any work.

The server time clue might make sense too. You might want check the server time and make sure it is within 2 minutes of the client time, or just increase the future time by quite a bit just to make sure.

The plugin is now hosted in the same server as the Vault server, so they will have exactly the same time. The 2mins I added was because I was looking at the transaction table in sgvault database and it seems things were happening in split-second timing so on a hunch I widened the query a bit. It appears that was not the issue however, because the history query apparently still returns 0.

So the main issue boils down to: why does history query could not find any thing in the specified time window? Could it be that OnEndTx is already called with a tx number but the database has not been committed yet?

Related to multiple batches by VS2003 as described above, could it be that the actual commit is only at the end of the last batch?

[ismangil]

OK, I am officially baffled.

On a test VS2003 solution which contains multiple projects, I checked out 2 files each from 9 projects. Checked them in together through Pending Checkin box. Whaddya know? It's processed as one transaction, all 18 items! So multiple project = multiple transactions? Not always....

Another hunch:

Would multiple history checks by the same Vault user from different locations affect history query behaviour?

This is because I have a single user account called build that is used by the plugin and also by the autobuild server which is running ccnet for continuous integration. So almost at the same time the plugin and ccnet would querying history through this build user.

[dan]

Yea, the VS API is fairly unpredictable at times, so it wouldn't surprise me if it seems random when files are grouped together and when they are not.

Also, I should have paid closer attention - this is a server plugin issue, and not necessarily a client API problem, and I must admit in the interests of full disclosure, that don't know a great deal about our plugin interface.

If this can wait until Monday, our plugin expert will be available then. If not, I can try to slog through it today.

I would guess it has something to do with a lot of transactions being committed close together. I think plugins have a low priority compared to the server, so maybe that has something to do with it too.

[ismangil]

If this can wait until Monday, our plugin expert will be available then. If not, I can try to slog through it today.

That's fine, I'm off for the weekend anyway!

Thanks for the (as usual) very quick response.

[jclausius]

ismangil:

Just a quick overview for OnEndTx().

The server first processes the changeset items from BeginTx(). This includes adding file deltas to the database, updating tree structures, etc. Assuming these change set items were all processed successfully, the server then commits all changes to the database.

After all this has been completed, but just before the method returns, the server starts up a thread with the newly committed transaction. This asynchronous thread then calls the OnEndTx() event for all registered plugins.


The only thing that I would think is causing the problems is something in the filter.

- Do the OnEndTx() times come close enough to those of the server's EndTx() time? Do you see the "new" history items if the time range is expanded?

- Is it possible something else is filtering out the history (incorrect TopName, repository ID)?

[ismangil]

The only thing that I would think is causing the problems is something in the filter.

- Do the OnEndTx() times come close enough to those of the server's EndTx() time?

It does. The web service is invoked within milliseconds of the txend as noted in transaction table in Vault database.

Do you see the "new" history items if the time range is expanded?

In the issue as attached above, I have already expanded the range to -5min to +2min (previously, when this sort of issue happened on previous occasions, it was -5 min to now).

As an additional note I haven't been able to reproduce the issue, as it seems to happen only on multiple transactions from single checkin, therefore as noted above only happens randomly from VS2003.

- Is it possible something else is filtering out the history (incorrect TopName, repository ID)?

TopName is currently set to "$".

RepositoryID is set at the beginning of OnEndTx, using the nRepID passed in by the webservice caller, using the FindRepositoryByID code. The whole bit of logging in and setting this repository is unchanged from the original sample plugin template.

[jclausius]

As an additional note I haven't been able to reproduce the issue, as it seems to happen only on multiple transactions from single checkin, therefore as noted above only happens randomly from VS2003.

I'm not certain what may be the problem. In the case you describe, you should receive "n" events (where n is the number of individual transactions). Of course when history is executed at transaction n-3, it will not contain items not yet committed. So items in n-2, n-1 and n will not be displayed until committed.

[ismangil]

[I'm not certain what may be the problem. In the case you describe, you should receive "n" events (where n is the number of individual transactions). Of course when history is executed at transaction n-3, it will not contain items not yet committed. So items in n-2, n-1 and n will not be displayed until committed.

Not quite clear on this relationship between transaction and commit.

So are you saying then, when the plugin responds to OnEndTx with the tx id, there may not be any history attached to it?

In other words, the plugin may not be able to know what has happened in a given tx id?

[jclausius]

So are you saying then, when the plugin responds to OnEndTx with the tx id, there may not be any history attached to it?

In other words, the plugin may not be always able to tell what has happened in a given tx id?

No. Let me rephrase this.

If VS.Net sends three distinct "version control transactions" due to the nature of Visual Studio and not the Vault IDE client, the Vault server will call OnEndTx() 3 different times.

When the first transaction is committed and your OnEndTx() is triggered for the first time, the history query will not contain results for the other VS.Net transactions, as they have not yet been committed. The history query will only contain info for the firsttransaction.

When the second transaction is committed and OnEndTx() is triggered again, the history query will most likely contain results for this transaction and the first transaction (assuming it fits within your date range). However, the third transaction has not yet been committed so it is not in the history query.

The same thing would apply to the third and final transaction.


However, this would not really explain the 0 rows you have reported. I wonder if this is still being "filtered" by something. What if we just put a "floor" on the date range. Something like:

Code: Select all

// remove all date filtering, except:
req.DateFilterMask = VaultQueryRequestDates.HistoryAfter;
req.BeginDate = DateTime.Now.AddMinutes(-5);

[ismangil]

When the first transaction is committed and your OnEndTx() is triggered for the first time, the history query will not contain results for the other VS.Net transactions, as they have not yet been committed. The history query will only contain info for the first transaction.

This is understandable and it is OK. Our plugin does not require that multiple transactions be related in any way. If a tx contains only one item (although technically part of a larger checkin) that is fine.

However, this would not really explain the 0 rows you have reported. I wonder if this is still being "filtered" by something. What if we just put a "floor" on the date range. Something like:

Code: Select all

// remove all date filtering, except:
req.DateFilterMask = VaultQueryRequestDates.HistoryAfter;
req.BeginDate = DateTime.Now.AddMinutes(-5);

I will try this and will also from now consider a history query that returns 0 rows to be fatal (in the case of this particular plugin that is) so I can trigger notifications etc.

Thanks for all your help so far.

[ismangil]

What if we just put a "floor" on the date range. Something like:

Code: Select all

// remove all date filtering, except:
req.DateFilterMask = VaultQueryRequestDates.HistoryAfter;
req.BeginDate = DateTime.Now.AddMinutes(-5);

After struggling to get floor to work, finally looked up CLC code, turns out you have the floor at the EndDate like so:

Code: Select all

// remove all date filtering, except:
req.DateFilterMask = VaultQueryRequestDates.HistoryAfter;
req.EndDate = DateTime.Now.AddMinutes(-5);

Will see over the next few days whether this solve the problem or not...

[jclausius]

OK... Sorry about that, glad you figured it out. Hopefully it will do the trick.

[ismangil]

The latest on this issue that it is still happening. As near as I can tell, it would happen if there is a large number of transactions happening at the same time.

I don't have time to debug this issue right now though, so can't provide proper diagnostics.

Just thought you'd like an update, if you feel so inclined to test the HistoryQuery API..