Bemanitools v5.26 release

doc/dev/c02-driver-on-w7-crash.md

@@ -0,0 +1,103 @@
+# Follow-up (14th August 2019)
+After publishing this post-mortem, I got messaged by a user on sows who was able to shed some more light on this issue.
+The user was experiencing the same symptoms on a Win7 setup: blue screen once the firmware was flashed to the C02 IO.
+This user's solutions was to use the USB2 ports on the PC instead of the USB3 ones. This is good to know and kinda
+aligns with the weird things happening in the driver (see below).
+
+# Post-mortem: C02 IO kernel module crash on Windows 7 (29th July 2019) by icex2
+## Background
+The original ezusbsys.sys kernel module, which is required to run the C02 IO, was compiled for Windows XP 32-bit, only.
+There is a newer driver by Cypress, cyusb3.sys, which could be used to IO2 boards on newer Windows platforms, but does
+not work with the C02 IO in combination with Konami's propriatery firmware. Thus, it was not possible to run the C02 IO
+on anything than Windows XP 32-bit. But, with newer IIDX games running on Windows 7 64-bit, the C02 IO wasn't usable
+anymore. Leaving aside, that the newer games actually require a BIO2 board and do not support C02 nor IO2 boards
+anymore.
+
+## The goal
+I still wanted to use my cabinet with a C02 board on newer games which is possible with BT5 adding an emulation layer
+and an interface (iidxio). This IO interface can be used to implement a driver that talks to a real IO again. Thus,
+implementing a ezusb iidxio driver library, we can run newer games with an C02 IO as well.
+
+However, there was no ezusbsys.sys driver that works on newer platforms required to run the newer games. But, Cypress
+was nice and included the source code of the ezusbsys kernel module. With a few tweaks and a very recent version of
+visual studio, it was quite easy to build this driver for newer platforms, including Windows 7, 8 and 10 in both
+32-bit and 64-bit variants.
+
+## The problem
+But, when using this driver on certain combinations of newer hardware (max. 1-2 years old) and Windows 7, the kernel
+module might crash after the Konami C02 firmware got flashed to the ezusb board. The result was a bluescreen and reboot.
+
+However, the hardware was fine and the kernel module worked fine on another piece of hardware, the stock PC that was 
+used with iidx 20 to 24. However, this hardware is not powerful enough to run iidx 25 and newer without stuttering
+issues.
+
+## The analysis/debugging
+Note: The full source code can be found in the bemanitools-supplement package.
+
+Setup:
+* Native hardware with Windows 7 that was crashing
+* Vmware with Windows 10 and Visual Studio 2019 to compile the kernel module. Target platform Windows 7 64-bit
+* Booting Windows 7 in test mode to allow unsigned kernel modules to run and with debug output turned on
+* dbgview on Windows 7 machine to get local kernel dbg output
+
+Because I wanted to stick to Windows 7 in the beginning (refer to the solution section), I started debugging the kernel
+module by enabling the debug message output that was already available in the code. However, since kernel debug message
+printing can be very delayed, the kernel could not print various messages before the kernel crashed.
+
+Thus, I started stripping the kernel module step by step to narrow down the possible spots causing the crash. After a
+few hours, I got the (first) issue tracked down:
+
+After the firmware was flashed, the device had to re-enumerate. When this happens, the function *Ezusb_PnPAddDevice*
+is called to create a new instance of the device. Since this kernel module is acting as a filter driver, it has to
+trap this call, and add a filter device before the real device in the device stack. Thus, each call to the ezusb device
+hits the filter device first and the filter device calls the real device after doing some magic.
+
+*Ezusb_PnPAddDevice* calls *Ezusb_CreateDeviceObject*. Afterwards, it checks the status of the call to 
+*Ezusb_CreateDeviceObject* and if successful, it tries attaching the device to the device stack. However, instead of
+using *IoAttachDeviceToDeviceStackSafe* it uses the unsafe variant *IoAttachDeviceToDeviceStack* which can lead to a
+race condition on newer Windows Systems. Furthermore, all initialization of further variables of the *deviceObject*
+needs to happen BEFORE doing that. Again, this is a race condition.
+
+Next issue: Once the kernel calls *Ezusb_StartDevice* -> *Ezusb_ConfigureDevice* -> *Ezusb_SelectInterfaces*, it tries
+to use *USBD_ParseConfigurationDescriptorEx* to get the interface from the configuration descriptor. However, that
+fails for some unknown reason. I checked the data structure and it is perfectly fine and everything is there. Thus,
+I wrote my own version *Ezusb_GetInterfaceFromConfigurationDescriptor* which does all the magic required to get this
+part fixed:
+```
+PUSB_INTERFACE_DESCRIPTOR Ezusb_GetInterfaceFromConfigurationDescriptor(
+	IN PUSB_CONFIGURATION_DESCRIPTOR ConfigurationDescriptor
+	)
+{
+	if (!ConfigurationDescriptor) {
+		Ezusb_KdPrint(("ERROR Ezusb_GetInterfaceFromConfigurationDescriptor NULL configuration desc"));
+		return NULL;
+	}
+
+	if (ConfigurationDescriptor->wTotalLength < sizeof(USB_CONFIGURATION_DESCRIPTOR) + sizeof(USB_CONFIGURATION_DESCRIPTOR)) {
+		Ezusb_KdPrint(("ERROR Ezusb_GetInterfaceFromConfigurationDescriptor configuration descriptor too small to have space for interface descriptor"));
+		return NULL;
+	}
+
+	// hardcoding this to a single interface because we only care about the ezusb used with IIDX (C02 IO)
+	if (ConfigurationDescriptor->bNumInterfaces < 1) {
+		Ezusb_KdPrint(("ERROR Ezusb_GetInterfaceFromConfigurationDescriptor num interfaces 0"));
+		return NULL;
+	}
+
+	// when retrieving the configuration descriptor from the usb device, the interface is located right next to it
+	return (PUSB_INTERFACE_DESCRIPTOR) (((unsigned char*) ConfigurationDescriptor) + sizeof(USB_CONFIGURATION_DESCRIPTOR));
+}
+```
+
+And next issue is just up ahead: Following the above, we have to call *Ezusb_USBD_CreateConfigurationRequestEx* to
+create a USB configuration request to set the interface we want to use. This is executed with a *Ezusb_CallUSBD* call
+which sends request to the real hardware. However, this request always fails. The call *IoCallDriver* inside 
+*Ezusb_CallUSBD* always returns an NTSTATUS code that is not documented anywhere (can't find the exact status code
+anymore, but once you get it, try to find it in the header file).
+
+At this point, I had to give up. I already wasted too many hours and this is clearly a dead end.
+
+## The solution
+Once I realized that I got stuck with Windows 7 and I didn't want to buy (more) new hardware, I gave Windows 10 a try.
+Surprisingly, this solved all the issues and the kernel module runs fine. The C02 board is flashable without crashing
+and works with newer IIDX games.

doc/dev/device-list.md

@@ -0,0 +1,26 @@
+# H44B
+
+(RGB) LED output board for jubeat cabinets.
+
+# ICCA
+
+Separate boxed unit containing with one card reader slot and pin key pad
+
+- BeatmaniaIIDX DistorteD to Lincle: grey slotted readers hanging below the
+side speakers next to the monitor
+- DDR SN 1/2: slotted readers red/black supernova cover mounted to the side of
+the cabinet next to the monitor (left and right)
+
+# ICCB
+
+Single card reader slot (no separate pin pad) built into the cabinet.
+Pin entry using game controls.
+
+- (First gen) Jubeat cabinets before replaced with wave pass readers
+
+# ICCC
+
+Single card reader wave pass unit without separate pin pad. Pin entry using
+game controls. Still supported by newer versions.
+
+- (Second gen) Jubeat cabinets with wave pass readers

doc/dev/logging-breakdown-avs.md

@@ -0,0 +1,76 @@
+Copy/pasted from chat with tau (2018/02/10):
+
+alright then. so for modern iidx.
+
+we want to do logging inside iidxhook and we also want to pass AVS-style log functions to iidxio which in turn passes them on to geninput in order for those to do logging too
+
+so iidxhook connects to the AVS log API: log_body_misc and friends, which I assume are invoked using a log_misc() macro in Konami's source code that adds some sort of module tag.
+
+anyway yeah this we already know.
+
+libutil has four function ptrs: log_impl_misc and co. These are static variables which are statically initialized to some no-op functions. Except log_impl_fatal, whose implementation just calls libc abort()
+
+at startup you call log_to_external(), supplying four function ptrs to wire these up to. As the name suggests, this causes Bemanitools libutil to talk to something that is compatible with the AVS log sink API.
+
+alternatively you can log_to_writer(), which initializes Bemanitools to use its own, internal logging system, and you give it a log writer function that takes strings and writes them somewhere.
+
+So you have log sinks and you have log writers. The path is [application code] -> [log sink] -> [logging engine] -> [log writer]
+19:29
+
+inside config.exe (or generally outside of modern AVS games) this path looks like [bemanitools application code] -> [log sinks passed across dlls] -> [bemanitools logging engine] -> [bemanitools log writer]
+
+inside modern AVS game the path looks like [bt hook dll / bt iodev dll] -> [avs log_body_whatever log sinks] -> [avs logging engine] -> [launcher.exe log writer]
+
+note that I tried to keep the log writer API consistent with the AVS log writer API but then Konami went and broke it repeatedly so now Bemanitools has its own stable log writer API. Launcher tracks the AVS log writer API, which breaks constantly, so that's not the same thing.
+
+anyway that's the background story. Now for the details about IIDX in particular.
+
+up until about iidx19 we did things the obvious way: iidxhook would log_to_external() to hook into the AVS log sinks and then call those directly and all was well. Then one fine day I was given a IIDX19 data dump and tried running iidxhook and it crashed with a stack overflow. hmm.
+
+the problem boils down to this: iidx19 AVS added those log timestamps. And for for whatever reason the AVS logging engine needs to access some mutexes and condition variables to make this work properly
+
+but AVS of course in grand Konami tradition has its own threading and concurrency primitive API which wraps the Win32 API. tbf this is kind of understandable in some sense, because win32 actually did not have condition variables until Windows Vista! in 2006! seriously, I'm not kidding.
+
+there's all sorts of articles out there describing in fine detail how to use Win32's event objects to implement your own condition variables and the multitudinous pitfalls that this entails
+
+but anyway one fun thing about the AVS concurrency API is that you can't actually use concurrency primitives unless you're calling that API from a thread launched using the AVS threading API
+
+and that's a problem in the case of iidxhook, because iidx is old as balls relatively speaking and its EZUSB driver code has I think two worker threads, which it launches using the MS libc's _beginthreadex() function
+
+this in turn is a wrapper around the win32 CreateThread function, but it also boots up stdio on whatever new thread gets launched and basically is responsible for guaranteeing that the libc will operate correctly on the newly launched thread
+
+so yeah when you do windows programming, never call CreateThread, always call _beginthreadex. otherwise stuff will break. maybe.
+
+point is, IIDX predates modern AVS so it just uses Windows threading directly. So, IIDX worker thread starts up, iidxhook does its thing, writes a log message, calls into AVS logging, which in turn grabs an AVS mutex, the implementation of which says "omg this isn't an AVS thread aaaaaa" and ... attempts to call back into the logging system to log this fact. whereupon a stack overflow condition proceeds in a predictable manner.
+
+so, there are a few ways to deal with this problem. bemanitools 4 dealt with it in a fairly stupid way.
+
+and very elaborate way too
+
+bt4 intercepted IIDX's calls to create Windows threads and then redirected those calls to go via the AVS threading API
+
+so now the worker threads are AVS threads and logging works as expected
+
+which is all well and good but the problem is that these threads are quite timing critical. it probably worked fine, but i didn't want to risk affecting those threads in a weird way and introducing latency and jitter. i wanted to keep the threading pristine and not mess with it just for the sake of diagnostic messages
+
+so bemanitools 5 uses the log server approach
+
+at an appropriate time, it creates its own AVS thread, the logging server. Since it is an AVS thread, it can call the AVS logging API
+
+and then we have log_post_misc() and friends, implemented in log-server.c
+
+we initialize the Bemanitools logging system to log "externally" to those funcs and we also propagate those to iidxio.dll and eamio.dll which in turn pass them to geninput.dll
+
+so what do log_post_misc and friends do
+
+they lock a "mailbox" using the win32 concurrency primitives and write the log severity and a pointer to the string to be logged into the mailbox, then signal the log server thread, again using win32 concurrency primitives
+
+then they do a synchronous wait for an acknowledgement from the logging server: since we're holding a string pointer, we cannot return until that string pointer has been consumed or it may be concurrently invalidated
+
+so the log server wakes up, locks the mailbox, calls AVS log_body_misc() to write the log message, then once that returns it asserts a signal in the mailbox (again, win32 event object because lol what are condition variables) and releases the lock.
+
+the caller gets the signal, wakes up, and returns to whatever Bemanitools code is running on the IIDX IO worker thread that wanted to write a log message.
+
+end of essay.
+
+