"Tried to read from writing cfile"

[Hirogen2]

A few weeks ago when I switched from g++-4.4 to g++-4.5 (the bug is reproducible with g++-4.4 too, though), I noticed a new bug. ZDoom started crashing whenever the intermission screen was finished melting to the next map. The crash is now delayed; I observe the following behavior:

+map02 - underhalls
J]changemap map03

+MAP03 - the gantlet
Tried to read from writing cfile

(Not triggerable with "map". It needs changemap.)
The game then aborts (i.e. goes to console and sits there, just like as if there were no Player 1 starts.) Quitting the game then causes a trail of valgrind/glibc double-free errors.

Code: Select all

*** glibc detected *** ./zdoom: double free or corruption (!prev): 0x08e2d4b0 ***
======= Backtrace: =========
/lib/libc.so.6(+0x6e0fb)[0xa695c0fb]
/lib/libc.so.6(+0x6ee7b)[0xa695ce7b]
/lib/libc.so.6(cfree+0x6d)[0xa6960bdd]
/usr/lib/libstdc++.so.6(_ZdlPv+0x1f)[0xa6b5298f]
/usr/lib/libstdc++.so.6(_ZdaPv+0x1b)[0xa6b529eb]
./zdoom(_Z15P_FreeLevelDatav+0x2ca)[0x8238f1a]
./zdoom[0x8239423]
./zdoom(_Z10call_termsv+0x1f)[0x8112c3f]
/lib/libc.so.6(+0x2e6ff)[0xa691c6ff]
/lib/libc.so.6(+0x2e75d)[0xa691c75d]
./zdoom[0x812aa4c]

Code: Select all

Tried to read from writing cfile
J]quit
==23569== Invalid free() / delete / delete[]
==23569==    at 0x402623F: operator delete[](void*) (in /usr/lib/valgrind/vgpreload_memcheck-x86-linux.so)
==23569==    by 0x8238F19: P_FreeLevelData() (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569==    by 0x8239422: ??? (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569==    by 0x8112C3E: call_terms() (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569==    by 0x4D2E6FE: __run_exit_handlers (in /lib/libc-2.11.2.so)
==23569==    by 0x4D2E75C: exit (in /lib/libc-2.11.2.so)
==23569==    by 0x812AA4B: Cmd_quit(FCommandLine&, APlayerPawn*, int) (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569==  Address 0x5e1f528 is 0 bytes inside a block of size 13,380 free'd
==23569==    at 0x402623F: operator delete[](void*) (in /usr/lib/valgrind/vgpreload_memcheck-x86-linux.so)
==23569==    by 0x8239063: P_FreeLevelData() (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569==    by 0x813060E: C_FullConsole() (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569==    by 0x81772A4: G_Ticker() (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569==    by 0x8156037: TryRunTics() (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569==    by 0x814DBD5: D_DoomLoop() (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569==    by 0x814F7EE: D_DoomMain() (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569==    by 0x81131F1: main (in /home/jengelh/code_nosov/zdoom/zdoom/obj/zdoom)
==23569== 

[randi]

Does not happen with gcc 4.5.0 (tdm-1). How do you reproduce this with GCC 4.4? I believe that's installed on my Ubuntu laptop, so I could at least check that out.

[Hirogen2]

(r2663) Combinatory testing indicates that gcc or the environment is not at fault. It just so happened that the memory scribble that's going on fired back best on my 32-bit desktop box. Anyway, the problem only happens when autosaving-at-the-start-of-a-map is enabled. To that end, I was able to reliably obtain this new valgrind trace:

Code: Select all

==10810== Syscall param read(buf) points to unaddressable byte(s)
==10810==    at 0x8D9C3FD: ??? (syscall-template.S:82)
==10810==    by 0x8D493F2: _IO_file_xsgetn (fileops.c:1457)
==10810==    by 0x8D3D4D9: fread (iofread.c:44)
==10810==    by 0x59E505: FileReader::Read(void*, long) (files.cpp:139)
==10810==    by 0x5D81D4: M_VerifyPNG(_IO_FILE*) (m_png.cpp:414)
==10810==    by 0x5C3202: M_ReadSaveStrings() (m_menu.cpp:791)
==10810==    by 0x5C3841: M_NotifyNewSave(char const*, char const*, bool) (m_menu.cpp:948)
==10810==    by 0x5A3EFE: G_DoSaveGame(bool, FString, char const*) (g_game.cpp:2063)
==10810==    by 0x5A38B0: G_DoAutoSave() (g_game.cpp:1932)
==10810==    by 0x5A17F8: G_Ticker() (g_game.cpp:1018)
==10810==    by 0x582FBA: TryRunTics() (d_net.cpp:1827)
==10810==    by 0x57A9BE: D_DoomLoop() (d_main.cpp:941)
==10810==  Address 0x7ff001000 is not stack'd, malloc'd or (recently) free'd

Further investigation into FileReader::Read showed

Code: Select all

read(0x7fff47f83a80, 8) Length=53248 FilePos=12645 StartPos=0
read(0x7fff47f83a80, 8) Length=53248 FilePos=12665 StartPos=0
read(0x7fff47f83a80, 8) Length=53248 FilePos=25376 StartPos=0
read(0x7fff47f83a80, 8) Length=53248 FilePos=25409 StartPos=0
read(0x7fff47f83a80, 8) Length=53248 FilePos=53497 StartPos=0
Ouch! len<0 after assignment in ::Read

[randi]

How about as of revision 2676?

[Hirogen2]

Negative, r2676 does not change things. I further observed that M_VerifyPNG is called multiple times. It seems that it does this for each save game that already exists in ~/.zdoom, before finally verifying the one that was just written. Assuming an empty ~/.zdoom, I trace:

Code: Select all

m_menu.cpp:M_ReadSaveStrings: calling M_VerifyPNG(/home/jengelh/.zdoom/auto1.zds)
Copying off broken files
`/home/jengelh/.zdoom/auto1.zds' -> `/tmp/auto1.zds'
m_png.cpp:M_VerifyPNG: PNG file apparently has 53248 bytes
[...]
m_png.cpp:M_VerifyPNG: chunk = {.size = 28076, .offset = 25354} ftell=53434
files.cpp:Read: Ouch! len=8 Length=53248 FilePos=53434 StartPos=0
g_game.cpp:G_DoSaveGame: calling M_VerifyPNG()
m_png.cpp:M_VerifyPNG: PNG file apparently has 53446 bytes
[...]
m_png.cpp:M_VerifyPNG: chunk = {.size = 21, .offset = 25321} ftell=25346
m_png.cpp:M_VerifyPNG: chunk = {.size = 28076, .offset = 25354} ftell=53434
game saved. (/home/jengelh/.zdoom/auto1.zds)

Judging from the backtrace of both the first and second invocation of M_VerifyPNG

Code: Select all

(gdb) bt
#0  M_VerifyPNG (file=0x13d53d0)
    at m_png.cpp:383
#1  0x00000000005c4094 in M_ReadSaveStrings ()
    at m_menu.cpp:793
#2  0x00000000005c46d3 in M_NotifyNewSave (file=
    0x13d1a0c "/home/jengelh/.zdoom/auto2.zds", title=
    0x7fffffffcc60 "Autosave Sep  3 17:48", okForQuicksave=false)
    at m_menu.cpp:950
#3  0x00000000005a4d35 in G_DoSaveGame (okForQuicksave=false, filename=...,
    description=0x7fffffffcc60 "Autosave Sep  3 17:48")
    at g_game.cpp:2064
#4  0x00000000005a46e7 in G_DoAutoSave ()
    at g_game.cpp:1933
#5  0x00000000005a2609 in G_Ticker ()
    at g_game.cpp:1018
#6  0x0000000000583d5b in TryRunTics ()
    at d_net.cpp:1827
#7  0x000000000057b75f in D_DoomLoop ()
    at d_main.cpp:941
#8  0x000000000057e503 in D_DoomMain ()
    at d_main.cpp:2244
#9  0x0000000000544aa4 in main (argc=7, argv=0x7fffffffdff8)
    at sdl/i_main.cpp:320


(gdb) bt
#0  M_VerifyPNG (file=0x13d53d0)
    at m_png.cpp:383
#1  0x00000000005a4daa in G_DoSaveGame (okForQuicksave=false, filename=...,
    description=0x7fffffffcc60 "Autosave Sep  3 17:48")
    at g_game.cpp:2075
#2  0x00000000005a46e7 in G_DoAutoSave ()
    at g_game.cpp:1933
#3  0x00000000005a2609 in G_Ticker ()
    at g_game.cpp:1018
#4  0x0000000000583d5b in TryRunTics ()
    at d_net.cpp:1827
#5  0x000000000057b75f in D_DoomLoop ()
    at d_main.cpp:941
#6  0x000000000057e503 in D_DoomMain ()
    at d_main.cpp:2244
#7  0x0000000000544aa4 in main (argc=7, argv=0x7fffffffdff8)
    at sdl/i_main.cpp:320

I get the feeling that M_VerifyPNG is called (by g_game.cpp:2064) while the file is still being written to and not finished until g_game.cpp

Code: Select all

        M_NotifyNewSave (filename.GetChars(), description, okForQuicksave);

        M_FinishPNG (stdfile);
        fclose (stdfile);

Yes, that's exactly what I suspected.

So there are two issues:
1. File being read before finished,
2. FileReader::Read allowing to do a read with len<0. Since fread() actually takes size_t and not long, it interprets len=-123 as an insanely huge number, which leads to the valgrind-observed heap corruption. You might say that the file must have an end at some point, yes -- what is required to trigger the bug is that the file is extended by more than the buffer size between updates to filer->Length. (Which seems to be the case here.)

[Gez]

It seems the r2685 fixes were not enough, since the same bug is still being reported for GZDoom: http://forum.drdteam.org/viewtopic.php?f=24&t=5236

[Hirogen2]

For me the issue is fixed, thanks. (Perhaps the gzdoom version used in that other thread did not yet have the patch.)