intermittent error with GETLABELDIFF

[eldi.espinosa]

Hi,

we are using Vault 3.0.7 for a while now and in the last couple of days I've been getting an error getting Labels diffs. I've discovered that the command fails 1 of every 2 times I try it from the command line. I wanted to know if this is a sympthom of a maintenance due or what could be causing the problem.

--------------------------------------------------------------------------------------------------------------------------------------------------------------------------



Repro Steps:

1- type on a command window:

“C:\Program Files\SourceGear\Vault Client\vault.exe” GETLABELDIFFS $/PROJECT/PATH LABEL1 LABEL2 -host [SERVER] -username [VAULT.USER] -password [PASSWORD] -repository [REPO] –ssl

--------------------------------------------------------------------------------------------------------------------------------------------------------------------------



Results:


One of every 2 attempts returns the following message:


<vault>

<error>

Invalid label: LABEL1

</error>

<exception>

System.ArgumentException: Invalid label: LABEL1

at VaultCmdLineClient.VaultCmdLineClient.GetLabelTimeStamps(String item, String label1, String label2, DateTime& timestamp1, DateTime& timestamp2)

at VaultCmdLineClient.VaultCmdLineClient.ProcessCommandGetLabelDiffs(String strReposPath, String strLabel1, String strLabel2)

at VaultCmdLineClient.VaultCmdLineClient.ProcessCommand(Args curArg)

at VaultCmdLineClient.VaultCmdLineClient.Main(String[] args)

</exception>

<result success="no" />

</vault>

--------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Expected Results:


<vault>

<history fromLabel="LABEL1" fromDate="2/3/2006 1:31:47 AM" toLabel="LABEL2" toDate="2/7/2006 1:32:01 AM">

<item/>
<item/>
.
.
.

</history>

<result success="yes" />

</vault>

[dan]

Does the server report any errors in the server log when the command fails? (Check C:\windows\temp\sgvault on the server machine for entries).

[eldi.espinosa]

Here's the log sequence for a failed attempt and a succesful one:


----2/7/2006 10:51:43 AM builder--SERVER(0.0.0.0)--SSL Enabled Login
----2/7/2006 10:51:43 AM builder--SERVER(0.0.0.0)--SSL Enabled GetUserOptions returned: Success
----2/7/2006 10:51:43 AM builder--SERVER(0.0.0.0)--SSL Enabled GetRepositories returned: Success
----2/7/2006 10:51:43 AM builder--SERVER(0.0.0.0)--SSL Enabled Getting repository Structure.
----2/7/2006 10:51:43 AM builder--SERVER(0.0.0.0)--SSL Enabled VaultServiceAPI::GetRepositoryTreeDelta() UserID:7 RepID:2 Base:43691 Target:43691 Calling VaultRepUtil.DiffRepTrees() - in-memory tree diff.
----2/7/2006 10:51:43 AM builder--SERVER(0.0.0.0)--SSL Enabled GetRepositoryStructure returned: Success
----2/7/2006 10:51:43 AM builder--SERVER(0.0.0.0)--SSL Enabled Getting list of checkout changes.
----2/7/2006 10:51:43 AM builder--SERVER(0.0.0.0)--SSL Enabled GetCheckOutListChanges returned: Success
----2/7/2006 10:51:44 AM builder--SERVER(0.0.0.0)--SSL Enabled GetUserEmailOptions returned Success
----2/7/2006 10:51:44 AM builder--SERVER(0.0.0.0)--SSL Enabled ListWatchers returned Success
----2/7/2006 10:51:44 AM builder--SERVER(0.0.0.0)--SSL Enabled ListCloakedObjects returned: Success
----2/7/2006 10:51:44 AM builder--SERVER(0.0.0.0)--SSL Enabled GetRepositoryOptions returned: Success
----2/7/2006 10:51:48 AM builder--SERVER(0.0.0.0)--SSL Enabled BeginHistoryQuery returned: Success
----2/7/2006 10:51:48 AM builder--SERVER(0.0.0.0)--SSL Enabled GetHistoryQueryItems returned: Success
----2/7/2006 10:51:51 AM builder--SERVER(0.0.0.0)--SSL Enabled EndHistoryQuery returned: Success
----2/7/2006 10:51:53 AM builder--SERVER(0.0.0.0)--SSL Enabled BeginHistoryQuery returned: Success
----2/7/2006 10:51:53 AM builder--SERVER(0.0.0.0)--SSL Enabled GetHistoryQueryItems returned: Success
----2/7/2006 10:51:53 AM builder--SERVER(0.0.0.0)--SSL Enabled EndHistoryQuery returned: Success
----2/7/2006 10:51:53 AM builder--SERVER(0.0.0.0)--SSL Enabled Logout

[dan]

OK, that didn't reveal much. Try to turn on client logging for the command line client - it might have something useful in it.

See http://support.sourcegear.com/viewtopic.php?t=1534 for how to get setup with logging (use the directions for the command line client)

[eldi.espinosa]

this is what the server reports after a falied attempt:

----2/9/2006 9:47:10 AM builder--SERVER(0.0.0.0)--SSL Enabled Login
----2/9/2006 9:47:10 AM builder--SERVER(0.0.0.0)--SSL Enabled GetUserOptions returned: Success
----2/9/2006 9:47:10 AM builder--SERVER(0.0.0.0)--SSL Enabled GetRepositories returned: Success
----2/9/2006 9:47:11 AM builder--SERVER(0.0.0.0)--SSL Enabled Getting repository Structure.
----2/9/2006 9:47:11 AM builder--SERVER(0.0.0.0)--SSL Enabled VaultServiceAPI::GetRepositoryTreeDelta() UserID:7 RepID:2 Base:43762 Target:43762 Calling VaultRepUtil.DiffRepTrees() - in-memory tree diff.
----2/9/2006 9:47:11 AM builder--SERVER(0.0.0.0)--SSL Enabled GetRepositoryStructure returned: Success
----2/9/2006 9:47:12 AM builder--SERVER(0.0.0.0)--SSL Enabled Getting list of checkout changes.
----2/9/2006 9:47:12 AM builder--SERVER(0.0.0.0)--SSL Enabled GetCheckOutListChanges returned: Success
----2/9/2006 9:47:12 AM builder--SERVER(0.0.0.0)--SSL Enabled GetUserEmailOptions returned Success
----2/9/2006 9:47:12 AM builder--SERVER(0.0.0.0)--SSL Enabled ListWatchers returned Success
----2/9/2006 9:47:12 AM builder--SERVER(0.0.0.0)--SSL Enabled ListCloakedObjects returned: Success
----2/9/2006 9:47:12 AM builder--SERVER(0.0.0.0)--SSL Enabled GetRepositoryOptions returned: Success
----2/9/2006 9:47:16 AM builder--SERVER(0.0.0.0)--SSL Enabled BeginHistoryQuery returned: Success
----2/9/2006 9:47:16 AM builder--SERVER(0.0.0.0)--SSL Enabled GetHistoryQueryItems returned: Success
----2/9/2006 9:47:18 AM builder--SERVER(0.0.0.0)--SSL Enabled EndHistoryQuery returned: Success
----2/9/2006 9:47:18 AM builder--SERVER(0.0.0.0)--SSL Enabled Logout

--------------------------------------------------------------------------------------------------------------------------------------------------------------------------

This is what the client is logging. I turned on logging for all events. I also removed most of the log entry because it was mostly repetitive for every subdirectory (mutex took, locked, released, created)


2/9/2006 9:47:04 AM <generic>: [<No Name>:3836] vault, Version=3.0.7.2863, Culture=neutral, PublicKeyToken=null
2/9/2006 9:47:04 AM <generic>: [<No Name>:3836] Logging all classes
2/9/2006 9:47:04 AM <connection>: [<No Name>:3836] InitService started.
2/9/2006 9:47:06 AM <connection>: [<No Name>:3836] InitService finished.
2/9/2006 9:47:06 AM <connection>: [<No Name>:3836] Login started.
2/9/2006 9:47:10 AM <connection>: [<No Name>:3836] Login finished.
2/9/2006 9:47:10 AM <connection>: [<No Name>:3836] GetOptions started.
2/9/2006 9:47:10 AM <connection>: [<No Name>:3836] GetOptions finished.
2/9/2006 9:47:10 AM <connection>: [<No Name>:3836] GetRepositories started.
2/9/2006 9:47:10 AM <connection>: [<No Name>:3836] GetRepositories finished.
2/9/2006 9:47:10 AM <mutex>: [<No Name>:3836] Created mutex 784
2/9/2006 9:47:10 AM <mutex>: [<No Name>:3836] Took mutex 784
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Released mutex 784
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Created mutex 788
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Took mutex 788
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Released mutex 788
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Created mutex 768
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Took mutex 768
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Released mutex 768
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Created mutex 764
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Took mutex 764
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Released mutex 764
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Created mutex 760
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Took mutex 760
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Released mutex 760
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Created mutex 756
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Took mutex 756
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Released mutex 756
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Created mutex 752
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Took mutex 752
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Released mutex 752
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Created mutex 748
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Took mutex 748
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Released mutex 748
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Created mutex 744
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Took mutex 744
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Released mutex 744
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Created mutex 740
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Took mutex 740
2/9/2006 9:47:11 AM <mutex>: [<No Name>:3836] Released mutex 740
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] Refresh started
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] delta passed in was null, retrieving one
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] calling GetRepositoryStructure(2, 43762, -1, ref, 5/6/2005 7:44:56 AM)
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] GetRepositoryStructure started.
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] GetRepositoryStructure started
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] Calling client service GetRepositoryStructure(2, 43762, -1, 5/6/2005 7:44:56 AM, ref, ref, ref)
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] Client service GetRepositoryStructure returned: dtLatestCheck 5/6/2005 7:44:56 AM, nReturnDestRevision 43762, rd not null True
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] GetRepositoryStructure finished
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] GetRepositoryStructure finished.
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3836] Took mutex 744
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3836] Released mutex 744
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] GetRepositoryStructure returned: returnedRevision 43762, newLatestDate 5/6/2005 7:44:56 AM, delta not null: True
2/9/2006 9:47:12 AM <checkoutlist>: [<No Name>:3836] RefreshCheckOutList started
2/9/2006 9:47:12 AM <checkoutlist>: [<No Name>:3836] Calling GetCheckOutListChanges(
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] GetCheckOutListChanges started.
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] GetCheckOutListChanges finished.
2/9/2006 9:47:12 AM <checkoutlist>: [<No Name>:3836] GetCheckOutListChanges returned: completeListReturned False, newLastUpdate 7/1/1850 12:00:00 AM
2/9/2006 9:47:12 AM <checkoutlist>: [<No Name>:3836] New items:
2/9/2006 9:47:12 AM <checkoutlist>: [<No Name>:3836] <null>
2/9/2006 9:47:12 AM <checkoutlist>: [<No Name>:3836] Release items:
2/9/2006 9:47:12 AM <checkoutlist>: [<No Name>:3836] <null>
2/9/2006 9:47:12 AM <checkoutlist>: [<No Name>:3836] Source and target check out list revisions are both 42985, and last locking date match. Returning with no update
2/9/2006 9:47:12 AM <checkoutlist>: [<No Name>:3836] RefreshCheckOutList finished
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] Calling Repository.Update with delta
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] Repository.Update finished, calling SaveRepositoryIfNothingOnDisk()
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3836] Took mutex 784
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] SaveIfNothingOnDisk: not saving
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3836] Released mutex 784
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] Refreshing working folder associations from disk
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3836] Took mutex 788
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3836] Released mutex 788
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] Refreshing all change set items without notify
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3836] Took mutex 760
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3836] Released mutex 760
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3836] Took mutex 756
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3836] Released mutex 756
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] Calling UpdateKnownChanges_RefreshKnown with notify
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] Calling NotifyTreeStructureChanged
2/9/2006 9:47:12 AM <refresh>: [<No Name>:3836] Refresh finished
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] GetUserEmailOptions started.
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] GetUserEmailOptions finished.
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] ListWatchers started.
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] ListWatchers finished.
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] ListCloakedObjects started.
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] ListCloakedObjects finished.
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] GetRepositoryOptions started.
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] GetRepositoryOptions finished.
2/9/2006 9:47:12 AM <updateknownchanges>: [<No Name>:3836] Starting new background thread, notifyChangeSetItemsChanged: True
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3032] Created mutex 704
2/9/2006 9:47:12 AM <connection>: [<No Name>:3836] HistoryBegin started.
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3032] Took mutex 704
2/9/2006 9:47:12 AM <wf>: [<No Name>:3032] wf C:\LOCAL\PATH mutex locked
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3032] Released mutex 704
2/9/2006 9:47:12 AM <wf>: [<No Name>:3032] wf C:\LOCAL\PATH mutex released
2/9/2006 9:47:12 AM <wf>: [<No Name>:3032] wf for C:\LOCAL\PATH created
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3032] Created mutex 648
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3032] Took mutex 648
2/9/2006 9:47:12 AM <wf>: [<No Name>:3032] wf C:\LOCAL\PATH\PROJECT mutex locked
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3032] Released mutex 648
2/9/2006 9:47:12 AM <wf>: [<No Name>:3032] wf C:\LOCAL\PATH\PROJECT mutex released
2/9/2006 9:47:12 AM <wf>: [<No Name>:3032] wf for C:\LOCAL\PATH\PROJECT created
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3032] Created mutex 644
2/9/2006 9:47:12 AM <mutex>: [<No Name>:3032] Took mutex 644
.
.
.
2/9/2006 9:47:16 AM <connection>: [<No Name>:3836] HistoryBegin finished.
2/9/2006 9:47:16 AM <connection>: [<No Name>:3836] HistoryFetch started.
2/9/2006 9:47:16 AM <mutex>: [<No Name>:3032] Released mutex 524
.
.
.
2/9/2006 9:47:18 AM <connection>: [<No Name>:3836] HistoryFetch finished.
2/9/2006 9:47:18 AM <connection>: [<No Name>:3836] HistoryEnd started.
2/9/2006 9:47:18 AM <connection>: [<No Name>:3836] HistoryEnd finished.
2/9/2006 9:47:18 AM <mutex>: [<No Name>:3032] Released mutex 268
.
.
.
2/9/2006 9:47:18 AM <connection>: [<No Name>:3836] Logout finished.
2/9/2006 9:47:18 AM <mutex>: [<No Name>:3032] Took mutex 272
.
.
.
2/9/2006 9:47:19 AM <generic>: [<No Name>:188] SimpleLogger finalized

[dan]

Well, nothing is showing up as having gone wrong.

Is this part of a script that gets run regularly, or is the command manually typed in every time? Is it possible there really isn't a "LABEL1" label at the time the command is invoked?

We may need to get access to your database or perhaps login remotely to see this. Another option is to get the CLC source on your end (available in the Client API installer) and try to debug it from there to see if there is more info to go on.

[eldi.espinosa]

well both, it is part of a nightly build script but it also fails when I run it manually from the command line. It fails one out of every two times I run it, the second time it runs succesfully so if I run it 10 times it fails on 1,3,5,7 and 9 but succeeds on 2,4,6,8 and 10.

I have the API let me see what I can find there. For now I've decided to call the command again if there's an error. Is there a specific error code for this case? I would hate to create an infinite loop because of a real error.

[dan]

I'm not sure if there is a specific error code or not, but the first place I'd check is the GETLABELDIFFS code where the failure happens and verify that the label text being passed in didn't get changed somehow, and that the error being reported is indeed the error that happens.

[dan]

Just to follow up on this thread, see http://support.sourcegear.com/viewtopic ... 3178#23178 for a description of the same problem, and also note the post at the bottom that you should use the HISTORY command to do this going forward.