by Hirogen2 » Fri Sep 03, 2010 9:54 am
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.)
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]
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)
[/code]
Judging from the backtrace of both the first and second invocation of M_VerifyPNG
[code]
(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
[/code]
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:2075:
[code]
M_NotifyNewSave (filename.GetChars(), description, okForQuicksave);
M_FinishPNG (stdfile);
fclose (stdfile);
[/code]
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.)