CORE: on Windows file handle of closed console still in use later, can even corrupt files used by Xemu then

[smf-]

Sometimes I am getting messages like this overwriting the .d81 that I specified on the command line

FILE: file c64-test-image01.d81 opened as c64-test-image01.d81 with base mode-set as fd=8
D81: fd 8 has been attached with 0 offset, read_only = 0, autoclose = 1
SDCARD: configuring F011 FDC with have_disk=1, can_write=1
SDCARD: D81: mounting OK
HYPERVISOR: first return after RESET.
MEM: no forced ROM re-apply policy was requested
ROM: version check succeeded, detected version: 911008
ROM: version check suggests DMA revision 1
DMA: setting chip revision to #1 based on the ROM auto-detection

I think this is related to the console closing (I run without -syscon on Windows).

I have been running with

#define DEBUG(...)
#define DEBUGPRINT(...)

and that seemed to make the problem go away

I recently tried instead to put this code in sysconsole_close() after FreeConsole()

freopen("nul", "w", stdout);
freopen("nul", "w", stderr);
freopen("nul", "r", stdin);

and it hasn't happened yet, but it always was rather random.

This issue has been happening with binaries I downloaded as well as with master & next builds, which I cross compile using Ubuntu on WSL.

[lgblgblgb]

I'm not sure I understand what is overwritten here, and how that is related to logging. Xemu is designed to ALWAYS have logging (some level, ie DEBUGPRINT(), the DEBUG() is another story, it can be controlled to go into a file, and disabled in release builds because of performance reasons - at least in newer branches, maybe not yet in master, that is very old). Sure, if there is no console/terminal open, those messages does not go anywhere too much. So it's the desired behaviour. Though no idea what do you mean about overwriting a D81. How is your D81 is corrupted and why is it related to logging? Btw -syscon just sets if console is kept open after the initial state, but the initialization messages are before closing console (if it's not requested to say, with -syscon). The intent of this, that in case of an Xemu initialization error, the user can look at the console about the problems. If the emulation "kicks in" without problem, the console is closed, unless -syscon is given, instructing not to close the console. But still, what does it to do with D81 corruption? Judging by the log fragment above, I see nothing abnormal.

[smf-]

"those messages does not go anywhere too much. So it's the desired behaviour"

They randomly overwrite the start of the .d81, I'm sure that is not desired behavior.

I am assuming it's because in the sysconsole_open() you do this.

fp = _fdopen( hConHandle, "r" );
*stdin = *fp;

fp = _fdopen( hConHandle, "w" );
*stderr = *fp;

But there is nothing after FreeConsole() is called to stop it writing to the stale handle, it seems that the handles get reused sometimes.

"Judging by the log fragment above, I see nothing abnormal."

I copied them out from offset 0 of the .d81 that it had just corrupted. Not from a log file or console. I do not think that is desirable behavior.

It took a while to figure out why my .d81 were being corrupted. I originally thought it was the log file, but it seems to be anything going to stdout after the .d81 has been opened can end up in the .d81.

[lgblgblgb]

Ah OK. I thought you have problems with the log saying it opens D81 or something and why Xemu has logging at all (that is my "it's the desired behaviour" goes), or the log means it overwrites (like with truncate instead of r/w open or such). I see your point now. My not so nice English knowledge also makes it harder to catch things right, especially at the first try.

That seems to be an interesting finding. Honestly I haven't ever used Windows, so no idea now at the first sight at least;) I learnt some Windows programming just for Xemu (really, believe or not), otherwise I don't have even Windows to try (I seldom use "wine" for testing), so I am not even a Windows user. That whole mess of windows console is the fruit of weeks of google'ing from my side how windows console works at all, since I had not the faintest idea.

Very interesting, and kinda strange that nobody has spotted it yet, even if we know that - I guess - most users use Xemu/MEGA65 with Windows (unlike me, hehe...). But anyway, now that I understand your point, it seems to be a legit (and kinda dangerous) problem, indeed.

So, thanks (also for the clarification) I keep this open, until I have time to look on this oddity :-O

[smf-]

I don't know how many people are using it on windows, but as it usually only overwrites the first couple block(s) then it's possible it's happening for other people but they haven't noticed because their disks aren't full enough (as you know, CBM DOS starts allocating from the middle of the disk out).

The software I am running uses every block of the .d81 & track 0 is read first, so it fails spectacularly very quickly if it's been overwritten.

[lgblgblgb]

Well, it's kinda irrelevant how and exactly what part is overwritten, the problem that it shouldn't be touched by logging indeed, of course :) But you may have a point here that probably because of the track zero usage by your program helped to discover the problem. I guess now I pay the price for trying to be "extra smart" and using "windows black magic of file handles + console" without deeply understanding how it really works :(

[hernandp]

@smf it is easy to reproduce? I make native Windows builds, and also use WSL for work.

[lgblgblgb]

Btw the way, now I was just google'ing a bit again ;) [well, well, my windows knowledge again ...] and I found that the suggested method is like this (for example, surely ideally stderr and even stdin must be taken care, just to avoid any other possibility of problem even including reading from stdin and having moved file position which can also cause problem, even if it's not literally on-write-corruption):

freopen("NUL:", "w", stdout);

Note the colon after NUL (though I am not sure if that colon is really needed). The problem however that if the problem is relative hard to trigger, then it's not so easy to test, if this is the solution. I try to find my abandoned win10 VM ;) and test this, I wouldn't trust here in wine this time, which usually my way to test Xemu for Windows ...

Also, I'll put this before FreeConsole() just to avoid any possible race condition that for a brief time still can be a problem not having console behind the std file descriptors.

Also, I would call this problem "HIGH PRIORITY" as unwanted corruption (especially this way!) is very much a problem.

[smf-]

@smf it is easy to reproduce? I make native Windows builds, and also use WSL for work.

I can't for sure say how easy it was to reproduce, when I first ran xmega65, I managed to run half quite a few times without it happening and then it kept happening often. I assume the console is closed from another thread and there is a race condition, or something else random is going on with the handles.

You will probably have to load the .d81 in a hex editor to tell if it's happened. I notice it quickly as the first program on the disk contains block 0 and so I get a file not found (or sometimes it locks up) when doing shift+end to load it.

I reverted my changes and pulled the latest code from the "next" branch and the first run corrupted the .d81, I restored the .d81 and it worked once before corrupting it again.

I've been able to run many times now after moving the code after the FreeConsole()

if (!FreeConsole()) {
    if (!waitmsg)
        ERROR_WINDOW("Cannot release windows console!");
} else {
    sysconsole_is_open = 0;
    DEBUGPRINT("WINDOWS: console is closed" NL);
}
// redirect std file handled to "NUL" to avoid strange issues after closing the console, like corrupting
// other files (for unknown reasons) by further I/O after FreeConsole() ...
file_handle_redirect(NULL_DEVICE, "stderr", "w", stderr);
file_handle_redirect(NULL_DEVICE, "stdout", "w", stdout);
file_handle_redirect(NULL_DEVICE, "stdin", "r", stdin);

I'm running using a batch file that contains: set XEMU_DEBUG_FILE=d:\xemu.log @..\xemu\build\bin\xmega65.win64 -8 %1 -go64 -besure

and I pass the .d81 in as a parameter to the script.

I would prefer to use -autoload (rather than shift+end) but it appears to not work with -go64

[lgblgblgb]

@smf- I'm not fully understand why you want (or why it would help) to put those after FreeConsole(), it's againt any sense (ok windows in general is a ... a... well "strange thing", and against common sense, that's true ....). I put those before FreeConsole() by will (and even checking if worked, and refuse closing console if did not, just to avoid any possibility of the problem even during a strange situation). I think it must be before, so there is zero time throughout the code when there is closed console but still "redirected" std file handles. Btw if you put that after, even the DEBUGPRINT("WINDOWS: console is closed" NL); after FreeConsole() call before the frepopen's can cause problems for example (yes, that line can be removed, however the intent that optionally can log into a file too so it still have some sense). Windows is a strange thing. Maybe I need to put twice, before and after FreeConsole() just to be sure, really odd ...

[lgblgblgb]

@smf- Oh and btw, you may want to use the -prg switch more to "inject" program directly into the memory. It's even auto detect (by the first two bytes of the PRG problem, ie loading address) C64/C65 mode and does the job as its own, you don't need to specify anything like -go64. That function of -prg is also available from the context UI menu. The "legacy" -autoload and -go64 is problematic since tries to inject key presses but that's very sensitive of timing and the actual used ROM. Though for sure, the functionality is not the same, -prg is meant to be for PRG files only, -autoload is a bit different can deal with loading files from "the disk" (attached disk image or MEGA65 SD-card internally mounted one) and optionally supports though the mode that can convert a PRG on-the-fly into a 'virtual D81'. Also -go64 worked with -autoload but always breaks with if the slightest change on timing, it is kinda a bad design in this context, unfortunately. Sure, if you need a whole disk image anyway, -prg is problematic, unless if you have the very ugly trick, to have the prg to load as its own too, and specified with -prg and also attaching the disk image with -8, yes, indeed kinda redundant and workaround-kind of solution, I admit.

[smf-]

@smf- I'm not fully understand why you want (or why it would help) to put those after FreeConsole(),

I don't care personally where they are, but putting the lines before the FreeConsole() just don't stop the corruption (which suggests to me that it's not actually working, so repeating it again just in case seems rather pointless).

The way sysconsole_open() works is different to other examples I have seen, I might look at changing it to use:

freopen ("CONOUT$", "w", stdout);
freopen ("CONOUT$", "w", stderr);

I need a whole disk image, I might look at -autoload. although it will likely only save me a few seconds here and there & so it's not on top of my list

[gardners]

@lgblgblgb may I make a horrible, horrible suggestion for a work around? Open a dummy file straight after opening the D81, so that the D81 can't be the recipient of the junk.

[lgblgblgb]

Suggestion of @smf- to move the freopen stuff after FreeConsole ... (also the commit above is meant not to init sensor API on windows with newer SDLs which triggers some windows problems with mostly older windows versions it seems, totally unrelated stuff but anyway)

[smf-]

I've been running with this for a while (diff based off latest next), it looks cleaner and it hasn't caused me any issues so far.

 xemu/emutools.c | 21 +++------------------
 1 file changed, 3 insertions(+), 18 deletions(-)

diff --git a/xemu/emutools.c b/xemu/emutools.c
index c82b13c..48a161f 100644
--- a/xemu/emutools.c
+++ b/xemu/emutools.c
@@ -1117,10 +1117,7 @@ int _sdl_emu_secured_modal_box_ ( const char *items_in, const char *msg )
 void sysconsole_open ( void )
 {
 #ifdef XEMU_ARCH_WIN
-   int hConHandle;
-   HANDLE lStdHandle;
    CONSOLE_SCREEN_BUFFER_INFO coninfo;
-   FILE *fp;
    if (sysconsole_is_open)
        return;
    sysconsole_is_open = 0;
@@ -1150,23 +1147,11 @@ void sysconsole_open ( void )
    //coninfo.dwSize.X = 100;
    SetConsoleScreenBufferSize(GetStdHandle(STD_OUTPUT_HANDLE), coninfo.dwSize);
    // redirect unbuffered STDOUT to the console
-   lStdHandle = GetStdHandle(STD_OUTPUT_HANDLE);
-   hConHandle = _open_osfhandle((INT_PTR)lStdHandle, _O_TEXT);
-   fp = _fdopen( hConHandle, "w" );
-   *stdout = *fp;
-   setvbuf( stdout, NULL, _IONBF, 0 );
+   freopen("CONOUT$", "w", stdout);
    // redirect unbuffered STDIN to the console
-   lStdHandle = GetStdHandle(STD_INPUT_HANDLE);
-   hConHandle = _open_osfhandle((INT_PTR)lStdHandle, _O_TEXT);
-   fp = _fdopen( hConHandle, "r" );
-   *stdin = *fp;
-   setvbuf( stdin, NULL, _IONBF, 0 );
+   freopen("CONIN$", "r", stdin);
    // redirect unbuffered STDERR to the console
-   lStdHandle = GetStdHandle(STD_ERROR_HANDLE);
-   hConHandle = _open_osfhandle((INT_PTR)lStdHandle, _O_TEXT);
-   fp = _fdopen( hConHandle, "w" );
-   *stderr = *fp;
-   setvbuf( stderr, NULL, _IONBF, 0 );
+   freopen("CONOUT$", "w", stderr);
    // make cout, wcout, cin, wcin, wcerr, cerr, wclog and clog point to console as well
    // sync_with_stdio();
    // Set Con Attributes

You still need to freopen() the handles to NUL in sysconsole_close() or FreeConsole() will leave the window open. With the above code it doesn't matter which way round you do it though.

I'm not sure if it's worth file_handle_redirect() failures preventing the call to FreeConsole() and you can use it for warning about the initial freopen()'s failing, I didn't because it meant moving the method and the diff would get even bigger.

[lgblgblgb]

I'm tempted to close this, there was some changes here and there meanwhile, not sure if this problem still shows up, as it was not the case for me, at least ............ I close it now, but pls re-open if it's still a problem!