game crashed: TextureCache::drop() assertion failed

[TiborB]

Hi,

when testing AI I got following crash - assertion failed:

/var/widelands/BZR/ai-post-b19-2/src/graphic/texture_cache.cc:79: void TextureCache::drop(): Assertion `it != entries_.end()' failed.

I have nothing - no savegame, because I run test games without save enabled, but perhaps this will be usefull for somebody.

More logs in https://bugs.launchpad.net/widelands/+bug/1721884

Appears in font handler, line 90:

    rendered_text = render_cache_->insert(hash, rt_renderer_->render(text, w));

Can be triggered by drawing overlays like current gametime and building names.

[kaputtnik (franku)]

Confirmed by another player in the Forum: https://wl.widelands.org/forum/topic/2799/

[Alexander Kampmann (alexander-kampmann)]

It happens for me on Fedora 25 in a self-compiled version. bzr log -l 1 says:

------------------------------------------------------------
revno: 8227 [merge]
committer: Wideland's Bunnybot <email address hidden>
branch nick: _widelands_dev_widelands_trunk
timestamp: Tue 2016-12-20 10:46:01 +0100
message:
  Merged lp:~widelands-dev/widelands/document_mine:
  Document the mine command. I read through the code to get to this documentation, I hope it is correct.
------------------------------------------------------------

I compiled this version with the update.sh script.

However, this happened often in the past month or so, and I ran update.sh several times, so it occurred in versions before this one as well.

[Notabilis (notabilis27)]

I think I can provide 1.5 backtraces for this bug. The first backtrace comes after a crash with the mentioned assertion. The second one is another crash but the backtrace seems similar so it might be related.

While posting, I noticed that the last output before the crash is in both cases about drop_stalled_soldiers. Not sure whether it is related, though, since I don't know about the times of output and crash.

[SirVer (sirver)]

I cannot reproduce this on my machine (Mac OS X, llvm 3.8).

This is my analysis: a texture should be inserted in the cache, but it would go over memory budget and therefore drops data. While dropping it refers to its internal least-recently-used (LRU) list called 'access_history_' to figure out what to drop. The LRU item it finds is no longer in the the 'entries_' of the cache anymore and the assert crashes.

Problem is, as far as I can see in the code, this is impossible in a single thread, and Widelands is single threaded: The cache uses a std::list<> (access_history_) and a std::map<> (entries_). It only uses .find, .end, .splice, .insert, .erase and .pop_front which all do not invalidate iterators. It only ever deletes anything from 'entries_' when it also deletes it from 'access_history_'. It makes sure in insert() that a hash is not already used.

Looking at the crash in #4 it seems to me that the std::map implementation used there is not fulfilling the no-iterator-invalidation contract - but I cannot be sure.

I pushed a branch[1] that ups the debug output in texture_cache and drastically reduces its size (from 30 MB to 1024kb) to trigger the error earlier. I would much appreciate if this branch could be tested from people who see this crash. Please also provide as much information as possible about compiler, version, OS and STL library used and the new (very verbose) stdout in completion.

[1] https://code.launchpad.net/~widelands-dev/widelands/more_debug_texture_cache

[kaputtnik (franku)]

Hm, behaving is different, i believe depending on the mapname (or its description text):
When starting a new game and in window "Choose a map", clicking on one of the first two entries ('Checkmate' or 'Crater') an endless loop in terminal regarding fonts appears. See output.txt. Some buttons show only black rectangles then instead of text.
When clicking on map 'Firegames' the crash happens immediately:

Dropping 4752 bytes, new size 4464. Hash: DejaVu/DejaVuSans-Bold.ttf:14:perform:d1d1d1:8
Dropping 432 bytes, new size 4032. Hash: DejaVu/DejaVuSans-Bold.ttf:14: :d1d1d1:8
Dropping 4032 bytes, new size 0. Hash: DejaVu/DejaVuSans-Bold.ttf:14:poorly.:d1d1d1:8
widelands: /home/kaputtnik/Quellcode/widelands-repo/more_debug_texture_cache/src/graphic/texture_cache.cc:79: void TextureCache::drop(): Assertion `!access_history_.empty()' failed.

Versions:
Archlinux
gcc 6.2.1-1
cmake 3.6.3-1
make 4.2.1-1
sdl2 2.0.5
sdl2_ttf 2.0.14-1
sdl2_image 2.0.1-1
sdl2_gfx 1:1.0.1-1
boost 1.62.0-4

Don't know what you mean with 'STL' or how i could get such information, i guessed you mean 'SDL'.

[TiborB (tiborb95)]

I got also a crash, though I did not see the failed assert, so can be something different. I dont have a backtrace

last lines from console:

Inserting 13032 bytes, new size would be 1057460. Hash <0<rt><p align=left><font face=condensed size=14 bold=1 shadow=1 color=ffff00> 14.5 fps (avg: 22.7 fps)</font></p></rt>>.
Dropping 2376 bytes, new size 1042052. Hash: DejaVu/DejaVuSansCondensed-Bold.ttf:14:14.1:ffff00:8
Dropping 13032 bytes, new size 1029020. Hash: 0<rt><p align=left><font face=condensed size=14 bold=1 shadow=1 color=ffff00> 14.1 fps (avg: 21.7 fps)</font></p></rt>
Inserting 2376 bytes, new size would be 1044428. Hash <DejaVu/DejaVuSansCondensed-Bold.ttf:14:66.7:ffff00:8>.
Inserting 13032 bytes, new size would be 1057460. Hash <0<rt><p align=left><font face=condensed size=14 bold=1 shadow=1 color=ffff00> 66.7 fps (avg: 23.3 fps)</font></p></rt>>.
Dropping 3024 bytes, new size 1041404. Hash: DejaVu/DejaVuSansCondensed-Bold.ttf:14:111.1:ffff00:8
Dropping 13680 bytes, new size 1027724. Hash: 0<rt><p align=left><font face=condensed size=14 bold=1 shadow=1 color=ffff00>111.1 fps (avg: 23.3 fps)</font></p></rt>
Inserting 13032 bytes, new size would be 1053788. Hash <0<rt><p align=left><font face=condensed size=14 bold=1 shadow=1 color=ffff00> 29.4 fps (avg: 24.4 fps)</font></p></rt>>.
Dropping 4032 bytes, new size 1036724. Hash: 0<rt><p align=left><font face=condensed size=14 bold=1 shadow=1 color=ffff00>1:47:28</font></p></rt>
Dropping 4032 bytes, new size 1032692. Hash: DejaVu/DejaVuSansCondensed-Bold.ttf:14:1:47:29:ffff00:8

It is archlinux, 64 bit, packages are probably the very same as Kaputtnik listed above....

[SirVer (sirver)]

Thanks for the feedback. I made the cache too small - I repushed a bigger cache. Could you all try again?

[kaputtnik (franku)]

I couldn't trigger the error with the adjusted cache.

Ran the map 'The Nile' with 8 players (ai) for about 20 hours (gametime at 10x speed).

[GunChleoc (gunchleoc)]

I have added a check to the TextureCache implementation in the fh1-multitexture branch that the drop() function is only ever called when there is a texture left in the cache. This way, one could have the cache consisting of 1 texture that is bigger than the cache allows. When that branch hits trunk, individual textures will also be a lot smaller.

[TiborB (tiborb95)]

I just got something similar....

widelands: /var/widelands2/BZR/trunk/src/graphic/text/transient_cache.h:143: void TransientCache<T>::drop() [with T = UI::RenderedText]: Assertion `it != entries_.end()' failed.

Thread 1 "widelands" received signal SIGABRT, Aborted.
0x00007ffff50af8a0 in raise () from /usr/lib/libc.so.6
#0 0x00007ffff50af8a0 in raise () from /usr/lib/libc.so.6
#1 0x00007ffff50b0f09 in abort () from /usr/lib/libc.so.6
#2 0x00007ffff50a80dc in __assert_fail_base () from /usr/lib/libc.so.6
#3 0x00007ffff50a8153 in __assert_fail () from /usr/lib/libc.so.6
#4 0x0000555555f418ed in TransientCache<UI::RenderedText>::drop (this=0x555556d45f50) at /var/widelands2/BZR/trunk/src/graphic/text/transient_cache.h:143
#5 0x0000555555f40b9d in TransientCache<UI::RenderedText>::insert (this=0x555556d45f50, hash="0<rt><p align=left><font face=condensed size=14 bold=1 shadow=1 color=ffff00>(18, 24)</font></p></rt>", entry=std::shared_ptr (count 2, weak 0) 0x55555fac7a90, entry_size_in_size_unit=4) at /var/widelands2/BZR/trunk/src/graphic/text/transient_cache.h:127
#6 0x0000555555f3fd60 in UI::FontHandler1::RenderCache::insert (this=0x555556d45f50, hash="0<rt><p align=left><font face=condensed size=14 bold=1 shadow=1 color=ffff00>(18, 24)</font></p></rt>", entry=std::shared_ptr (count 2, weak 0) 0x55555fac7a90) at /var/widelands2/BZR/trunk/src/graphic/font_handler1.cc:67
#7 0x0000555555f401cf in UI::FontHandler1::render (this=0x555556d3f2f0, text="<rt><p align=left><font face=condensed size=14 bold=1 shadow=1 color=ffff00>(18, 24)</font></p></rt>", w=0) at /var/widelands2/BZR/trunk/src/graphic/font_handler1.cc:90
#8 0x000055555621b8d2 in InteractiveBase::draw_overlay (this=0x555559210240, dst=...) at /var/widelands2/BZR/trunk/src/wui/interactive_base.cc:448
#9 0x00005555562300c8 in InteractiveGameBase::draw_overlay (this=0x555559210240, dst=...) at /var/widelands2/BZR/trunk/src/wui/interactive_gamebase.cc:108
#10 0x000055555617e37c in UI::Panel::do_draw_inner (this=0x555559210240, dst=...) at /var/widelands2/BZR/trunk/src/ui_basic/panel.cc:731
#11 0x000055555617e4f8 in UI::Panel::do_draw (this=0x555559210240, dst=...) at /var/widelands2/BZR/trunk/src/ui_basic/panel.cc:758
#12 0x000055555617cfba in UI::Panel::do_run (this=0x555559210240) at /var/widelands2/BZR/trunk/src/ui_basic/panel.cc:190

[Steven De Herdt (stdh)]

I experienced this as well (stacktrace attached):

widelands: ../src/graphic/text/transient_cache.h:143: void TransientCache<T>::drop() [with T = UI::RenderedText]: Controletest 'it != entries_.end()' faalt.

Also, I saved a core file, maybe that could be handy? It's too large for me to upload, but if you tell me what to look up (and how to do that) I could help.

[TiborB (tiborb95)]

I just had another crash. English version now, the backtrace points to another line I think, full output in attachment. I was just working with iron mine - going to upgrade or so:

#26 0x0000555555f41925 in TransientCache<UI::RenderedText>::drop (this=0x555556d0a300) at /var/widelands2/BZR/trunk/src/graphic/text/transient_cache.h:152
#27 0x0000555555f40b9d in TransientCache<UI::RenderedText>::insert (this=0x555556d0a300, hash="120<rt><p align=center><font face=condensed size=14 bold=1 shadow=1 color=ffff00>Deep Iron Mine</font></p></rt>", entry=std::shared_ptr (count 2, weak 0) 0x555559442320, entry_size_in_size_unit=6) at /var/widelands2/BZR/trunk/src/graphic/text/transient_cache.h:127
#28 0x0000555555f3fd60 in UI::FontHandler1::RenderCache::insert (this=0x555556d0a300, hash="120<rt><p align=center><font face=condensed size=14 bold=1 shadow=1 color=ffff00>Deep Iron Mine</font></p></rt>", entry=std::shared_ptr (count 2, weak 0) 0x555559442320) at /var/widelands2/BZR/trunk/src/graphic/font_handler1.cc:67
#29 0x0000555555f401cf in UI::FontHandler1::render (this=0x555556d03720, text="<rt><p align=center><font face=condensed size=14 bold=1 shadow=1 color=ffff00>Deep Iron Mine</font></p></rt>", w=120) at /var/widelands2/BZR/trunk/src/graphic/font_handler1.cc:90

[GunChleoc (gunchleoc)]

These get triggered by the font handler, line 90:

    rendered_text = render_cache_->insert(hash, rt_renderer_->render(text, w));

Looks like the texture is in the cache's access history but not in its entries somehow when dropping old textures.

[GunChleoc (gunchleoc)]

I have been unable to trigger this so far, so a savegame would help.

[GunChleoc (gunchleoc)]

We added some fixes to the TransientCache thanks to ASan. Does anybody still get this bug?

[GunChleoc (gunchleoc)]

Fixed in build20-rc1