Nightly build crash on SVN Log with log cache enabled

[Daniel Sahlberg]

Hi,

I'm experiencing crashes in the TortoiseSVN, Show log command (tortoiseproc.exe /command:log ...) with the latest nightly builds. If I disable the log cache the crashes go away.

Other commands, for example Update, works fine so I don't think it is related to the OpenSSL or Serf changes I've been working on.

I'm not able to reproduce it with a source build from /trunk under Visual Studio, no idea why. That also makes it a bit hard to bisect.. I will find some more time to look at it but the days ahead are quite full already.

/Daniel

[Pavel Lyalyakin]

 I'm reproducing a different behavior. When log caching is enabled and I click 'Show Log', I see the error message "Illegal repository URL 'i'" where 'i' is some random sequence of characters. The problem doesn't occur when log caching is disabled.

--

With best regards,
Pavel Lyalyakin
VisualSVN Team

[Pavel Lyalyakin]

And yes, TortoiseProc.exe indeed crashes. It seems that it crashed several times at first, but then the crash doesn't occur anymore and I get the error message "Illegal repository URL 'foo'".

From Windows Application event log:

[[[

Faulting application name: TortoiseProc.exe, version: 1.14.99.29562, time stamp: 0x646c29e2
Faulting module name: mfc140u.dll, version: 14.30.30704.0, time stamp: 0x615a9438
Exception code: 0xc0000005
Fault offset: 0x0000000000003040
Faulting process id: 0x5f4
Faulting application start time: 0x01d98d7c205b66e3
Faulting application path: C:\Program Files\TortoiseSVN\bin\TortoiseProc.exe
Faulting module path: C:\WINDOWS\SYSTEM32\mfc140u.dll
Report Id: 36f9c282-5614-4e5c-8c3e-d7ab8c4828ba
Faulting package full name:
Faulting package-relative application ID:

]]]

[[[

Fault bucket 2300242071444530166, type 4
Event Name: APPCRASH
Response: Not available
Cab Id: 0

Problem signature:
P1: TortoiseProc.exe
P2: 1.14.99.29562
P3: 646c29e2
P4: mfc140u.dll
P5: 14.30.30704.0
P6: 615a9438
P7: c0000005
P8: 0000000000003040
P9:
P10:

]]]

 

--

With best regards,
Pavel Lyalyakin
VisualSVN Team

[Stefan]

I made a few changes to the log caching, but those changes are mostly refactoring.

Unfortunately, I can't reproduce a crash of the error message on my machine here.

Maybe you guys can debug the problem on your machine?

[Daniel Sahlberg]

tisdag 23 maj 2023 kl. 18:53:06 UTC+2 skrev Stefan:

I made a few changes to the log caching, but those changes are mostly refactoring.

Unfortunately, I can't reproduce a crash of the error message on my machine here.

Maybe you guys can debug the problem on your machine?'

I found a way to reproduce it: when I deleted the log cache, the error also occured within Visual Studio.

I believe the error is the following change. Please note the comment, it was added in r14384 when the arguments was changed from const CString& to CString (ie, the opposite of the change below). I'm supporting the analysis that the parameters may come from a cache entry being deleted, in this case from a call in CLogCachePool::AutoRemoveUnused() where the repositoryInfo->data object is iterated and then the very same object is deleted by DropEntry. Suddenly the uuid and urls are unreachable.

[[[

Index: src/LogCache/RepositoryInfo.h
===================================================================
--- src/LogCache/RepositoryInfo.h (revision 29553)
+++ src/LogCache/RepositoryInfo.h (revision 29554)

[...]

@@ -232,27 +232,27 @@
     /// Parameters must be copied because they may stem from the
     /// info object being deleted.
 
-    void DropEntry(CString uuid, CString url);
+    void                   DropEntry(const CString& uuid, const CString& url);
 ]]]

I've reverted this in r29564 and the crash seems to be gone.

Kind regards,

Daniel

[Daniel Sahlberg]

onsdag 24 maj 2023 kl. 21:52:29 UTC+2 skrev Daniel Sahlberg:

I've reverted this in r29564 and the crash seems to be gone.

Unfortunately it was not enough, the log still crash (I've also seen the same error as in Pavel's screen shot "Illegal repository URL '[gibberish]'". I'll try to take a second look.

Kind regards,

Daniel

[Stefan]

and I still don't see the crash on my machine.

Tried showing log for several working copies, single files in them. Even showed the log for urls instead of local paths.

I don't get any crashes or error messages about illegal repo urls.

Also deleted the whole log cache and tried everything again. Still, no crash for me :(

[Daniel Sahlberg]

It is a bit strange; I can't reproduce the issue under Visual Studio or even with my own builds. However with the nightly builds there is a crash. I downloaded the nightly builds and the debug symbols and I believe I have a trace.

In CLogCachePool::GetCache

repositoryInfo->data.AutoInsert(uuid, root)

return a nullptr. This seems to come from CRepositoryInfo::CData::Lookup not finding hitting a suitable record.

There is also a call to CRepositoryInfo::CData::Add that hits the new "avoid duplicate entries" check - I don't know if that would have made the call to AutoInsert succeed if Lookup didn't find a record.

I noticed that I only get the crasch if I uncheck the "Allow ambiguous URLs" and "Allow ambiguous UUIDs" in the settings.

Hopefully this may add some more information.

Kind regards,

Daniel

[Daniel Sahlberg]

I really need some help with this...

My understanding is as follows:

CRepositoryInfo::CData::AutoInsert() is called to find/add an SPerRepositoryInfo() object (basically a {uuid, root} tuple) to data (and urlIndex, uuidIndex, fullIndex). 

It will first call CRepositoryInfo::CData::Lookup() to see if there already exists an object with the key {uuid, root} by searching fullIndex (and possibly uuidIndex, urlIndex, depending on the AllowAmbiguousUUID and AllowAmbiguousURL settings). If it finds something it will return a pointer, otherwise nullptr.

If Lookup() returns a nullptr, CRepositoryInfo::CData::Add() is called to create a new SPerRepositoryInfo and to add it to data (and urlIndex, uuidIndex, fullIndex).

However Add() will "avoid duplicate entries" by searching data with std::ranges::find_if() and checking for equality using SPerRepositoryInfo::operator==(). If it finds a duplicate, it will not add anything to the data/indicies.

AutoInsert() will then try the Lookup() again to find the newly added object and assumes success since the object was just Add()ed.

Only in my test case the object was NOT added by Add(), since Add() hits line 176 and returns "to avoid duplicate entries".

I believe there is a difference between the code in Lookup() (using fullIndex.find(std::make_pair(uuid, root))) and the code in Add() (using std::ranges::find_if(data, [&](auto* i) { return (*i) == info; }) where the code in Lookup() fail to find an object that is later found by Add().

However I'm not clever enough to figure out what the difference is. I was first suspecting that SPerRepositoryInfo::operator==() was too sensitive, but I figure if that was the case objects would be added even though they are "duplicate".

I'm currently leaning towards changing CRepositoryInfo::CData::Add(const SPerRepositoryInfo& info) to return a pointer to the newInfo object, to let AutoInsert return this instead of doing another Lookup(), but I feel this would only plaster over the difference between the code in Lookup() and Add().

I'm also considering reverting r29558 (which added the "avoid duplicate entries" in Add()) but I'm assuming it was added for good reasons.

Kind regards,

Daniel

[Stefan]

you're right. The problem is the == operator. To work properly it would require to know the settings allowAmbiguousUrl/Uuid and act accordingly.

While that could be done, it would make for very ugly code.

I added the 'avoid duplicate' code because my local cache showed 10 entries for the same repo in the settings dialog. But maybe my cache was just corrupted.

So I reverted that commit for now. If I ever get those multiple entries again, I'll try to come up with a solution that works.

[Daniel Sahlberg]

Thanks! I'll test the nightly build tomorrow.

Any idea why only the nightly build would fail and not when I built it myself? The settings should have been the same...

[Stefan]

not sure, but maybe it has something to do with the version of VS that's used? I mean on the build server there's definitely not VS 17.6 installed...

[Daniel Sahlberg]

- Good news: No more crasches.

- Bad news: Logcache shows a lot of duplicates. There seems to be only one file in %appdata%\TortoiseSVN\logcache.

So something should probably be done to the logcache "add to cache" logic. I'm favoring letting Add() have the same functionality as AutoInsert already has (and getting rid of the latter). However no time to look at the code before next week (probably not before next weekend).

/Daniel

[Stefan]

I had that situation too, then I added the logic that caused the crashes.

But now I can't get it to show the duplicate entries anymore! I deleted my old cache. And showing logs for different repos just don't get me to where duplicate entries are shown.

[Daniel Sahlberg]

torsdag 8 juni 2023 kl. 19:23:42 UTC+2 skrev Stefan:

I had that situation too, then I added the logic that caused the crashes.

But now I can't get it to show the duplicate entries anymore! I deleted my old cache. And showing logs for different repos just don't get me to where duplicate entries are shown.

I can reproduce this by:

* deleting %appdata%\TortoiseSVN\logcache

* doing Show log and clicking a few different revisions

* Settings, Log Caching, Cached Repositories now show 4 items for the repository

* repeating steps 2 and 3 seems to add 4 items to the list per iteration

When checking %appdata%\TortoiseSVN\logcache, it seems only Repositories.dat is actually changed by steps 2 and 3 (at least as long as I'm clicking the same revisions).

I'm out of time right now (and away from my main dev machine) so I can't debug any further, but I hope this can give a few more ideas. I'd start looking in the Show log code next, specifically when things are added to the data vector.

Kind regards,

Daniel

[Stefan]

On Saturday, June 10, 2023 at 6:27:59 PM UTC+2 daniel.l...@gmail.com wrote:

I can reproduce this by:

* deleting %appdata%\TortoiseSVN\logcache

* doing Show log and clicking a few different revisions

* Settings, Log Caching, Cached Repositories now show 4 items for the repository

* repeating steps 2 and 3 seems to add 4 items to the list per iteration

I still can't reproduce this.

Also, I can't see why clicking on revisions in the log dialog would ADD something to the cache. I also don't see where this would even touch the cache?

Another thing:

The CRepositoryInfo::CData::Add() method is only called from code where a CRepositoryInfo::CData::Lookup() is called before. So it should not be possible to add entries that already exist.

I'm out of ideas.... 

[Daniel Sahlberg]

måndag 12 juni 2023 kl. 20:24:38 UTC+2 skrev Stefan:

On Saturday, June 10, 2023 at 6:27:59 PM UTC+2 daniel.l...@gmail.com wrote:

I can reproduce this by:

* deleting %appdata%\TortoiseSVN\logcache

* doing Show log and clicking a few different revisions

* Settings, Log Caching, Cached Repositories now show 4 items for the repository

* repeating steps 2 and 3 seems to add 4 items to the list per iteration

I still can't reproduce this.

I can reproduce this only with a nightly build (I can even load the EXE in Visual Studio, add the PDBs and debug from there). No luck reproducing with my own build.

 

Also, I can't see why clicking on revisions in the log dialog would ADD something to the cache. I also don't see where this would even touch the cache?

 

That was a red herring, sorry. It is enough to just show the log.

Another thing:

The CRepositoryInfo::CData::Add() method is only called from code where a CRepositoryInfo::CData::Lookup() is called before. So it should not be possible to add entries that already exist.

I'm out of ideas.... 

I believe the additional entries in the log cache are added from for example CRepositoryInfo::GetRepositoryRootAndUUID. It seems like CRepositoryInfo::CData::Lookup() fail to find the existing entries.

I have a feeling something goes bad in TFullIndex::const_iterator iter = fullIndex.find(std::make_pair(uuid, root)). I can't really find any 

In the nightly builds, Visual Studio claim that fullIndex is "optimized away" so I can't really see that it contains, therefor making it difficult to debug further. 

I've tried to switch the nightly builds to use the debug target in r29586, hoping to see more debugging info in the next nightly build.

/Daniel