chore(doc): Re-structure, separate dev journals

This commit is contained in:
icex2
2023-04-03 17:54:53 +02:00
parent c62f1d8065
commit 6d67a5a81c
4 changed files with 0 additions and 0 deletions
@@ -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.
@@ -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.
@@ -0,0 +1,88 @@
# Notes outlining some aspects of the DirectX calls which were required to know to implement a up-/downscaling feature
As the title says, this outlines some aspects I needed to figure out in order to implement a up-/downscaling feature
within the d3d9 hook module that works on all currently available IIDX versions (9 to 26).
To analyze the rendering loops, I have used a tool called apitrace which traces the calls of many graphic APIs:
https://github.com/apitrace/apitrace
Defintely recommended to quickly figure out what is going on regarding rendering. It also allows you to let you render
parts of a scene after the application exited because it records all API calls and data passed to them.
Anyway, considering the various iterations in (GPU) hardware the game had to undergo combined with weird quirks and
"fixes" Bemanitools is undoing, I wouldn't have guessed that their rendering engine was nearly the same until IIDX 20.
That's when they introduced SD/HD mode.
In this case, that's great news because I had to craft a solution that allows up-/downscaling the final frame to
different resolutions (see the iidxhook-util/d3d9 module for more details about the feature).
But first, we need a breakdown of the render loop's most relevant parts for this:
## IIDX pre 20
Using apitrace, we can see the following outline of a frame (not counting the first one that does a lot of setup in
the beginning):
```
BeginScene
Clear
...
// Here are the main draw calls for the scene rendering to the back buffer
EndScene
Present
```
No render target switching, simply render everything to the back buffer...plain and simple.
Note: The viewport size is determined by the size returned by GetClientRect, wtf.
Welp, no official Konmai seal of approval without that. ¯\_(ツ)_/¯
## IIDX 20+
Using apitrace, we can see the following outline of a frame (not counting the first one that does a lot of setup in
the beginning):
```
BeginScene
// tex1 is a render target texture with size 1280x720 (also in SD mode)
// The game will render to this intermediate target and not directly to the fram ebuffer
SetRenderTarget(0, tex1)
...
Clear
BeginScene -> ErrInvalidCall return code
Clear
...
// Here are the main draw calls for the scene rendering to tex1
...
// Sets the render target to the original frame buffer. The size of the framebuffer is set to the output mode
// resolution, e.g. 1280x720 for HD mode and 640x480 for SD mode
SetRenderTarget(0, frame_buffer)
...
Clear
EndScene
...
// Render, texture and sampler state updates as well as a draw call that draws tex1 to a quad which fills the
// screen space.
...
EndScene -> ErrInvalidCall return code
Present
```
This is quite a different flow to implement HD and SD mode but the solution to solve that particular problem is straight
forward and easy to understand. This means that the game will always render in HD mode and only downscale the final
frame to SD resolution for 640x480 output.
Also, why the fuck do they call BeginScene and EndScene twice? Looks like they wanted to do this in two separate scenes
for some reason. Checking the return values would have revealed to them that something's not right...lucky them that
this code works nevertheless.
Another Konmai seal of approval, a job well done. ¯\_(ツ)_/¯
## iidxhook's up-/downscaling solution
The initial solution simply hooked into BeginScene and EndScene and let the game render to an intermediate render
target texture. The texture was scaled according to the actual target frame buffer size before getting presented. This
solution worked fine for pre IIDX 20 games but created a black screen on IIDX 20+.
In order to avoid two different scaling flows, the final solution that works for both does the following:
* Create a render target texture with native resolution and let the game render to it
* Set the render target to that intermediate render target texture on BeginScene
* Before Present
* Scale the intermediate render target texture to the back buffer
* Set the back buffer as the render target
* Present frame
Just an outline which follows the actual implementation that you can find in the iidxhook-util/d3d9.
@@ -0,0 +1,192 @@
# ACIO BIO2 IIDX package dump
Package dump excerpt of the init sequence of a original Konami IIDX BIO2 with sub IO connected.
This was used to identify a missing piece of information that needs to be communicated to the BIO2
for IIDX to initialize the sub IO correctly.
The dump was cut off after two polls as the sequence just keeps on repeating from that point on.
## Findings for problem to solve
With the previous implemention of the BIO2 driver, which was created off references of SDVX KFCA,
a BIO2 used with IIDX and the sub IO (to upgrade older C02, IO2 cabinets) connected didn't
initialize properly. This resulted in no inputs/outputs other than 14 keys working.
The problem identified was a different byte, exact meaning not known, that is sent in
[exchange 4](#exchange-4-ac-io-cmd-clear). Instead of `0x3B` from the SDVX KFCA based
implementation, it needs to be set to `0x2D`.
## Exchange 1: AC_IO_CMD_ASSIGN_ADDRS
### Write
```text
AA 00 00 01 00 01 00 02
AA: SOF
00: addr
0001: AC_IO_CMD_ASSIGN_ADDRS
00: seq_no
01: nbytes
data: 00
02: checksum
```
### Read
```
AA AA 00 00 01 00 01 01 03
AA: SOF
AA: SOF
00: addr
0001: addr
00: seq_no
01: nbytes
01: data
03: checksum
```
## Exchange 2: AC_IO_CMD_GET_VERSION
### Write
```
AA 01 00 02 00 00 03
AA: SOF
01: addr, node 1
0002: AC_IO_CMD_GET_VERSION
00: seq_no
00: nbytes
03: checksum
```
### Read
```
AA AA 81 00 02 00 2C 0D 06 00 00 ...
AA: SOF
AA: SOF
81: Response flag + node 1
0002: AC_IO_CMD_GET_VERSION
00: seq_no
2C: nbytes
0D 06 00 00 ...: data
XX: checksum
```
## Exchange 3: AC_IO_CMD_START_UP
### Write
```
AA 01 00 03 00 00 04
AA: SOF
01: addr
0003: AC_IO_CMD_START_UP
00: seq_no
00: nbytes
04: checksum
```
### Read
```
AA AA 81 00 03 00 01 00 85
AA: SOF
AA: SOF
81: Response flag + node 1
0003: AC_IO_CMD_START_UP
00: seq_no
01: nbytes
00: data
85: checksum
```
## Exchange 4: AC_IO_CMD_CLEAR
### Write
```
AA 01 01 00 00 01 2D 30
AA: SOF
01: addr
0100: AC_IO_CMD_CLEAR
00: seq_no
01: nbytes
2D: data
30: checksum
```
### Read
```
AA AA 81 01 00 00 01 00 83
AA: SOF
AA: SOF
81: Response flag + node 1
0100: AC_IO_CMD_CLEAR
00: seq_no
01: nbytes
00: data
83: checksum
```
## Exchange 5: BIO2_BI2A_CMD_WATCHDOG
### Write
```
AA 01 01 20 00 02 00 00 24
AA: SOF
01: addr
0120: BIO2_BI2A_CMD_WATCHDOG
00: seq_no
02: nbytes
00 00: data
24: checksum
```
### Read
```
AA AA 81 01 20 00 01 00 A3
AA: SOF
AA: SOF
81: Response flag + node 1
0120: BIO2_BI2A_CMD_WATCHDOG
00: seq_no
01: nbytes
00: data
A3: checksum
```
## Exchange 6: BIO2_BI2A_CMD_POLL
### Write
```
AA 01 01 52 00 30 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 84
AA: SOF
01: addr
0152: BIO2_BI2A_CMD_POLL
00: seq_no
30: nbtes
...: data
84: checksum
```
### Read
```
AA AA 81 01 52 00 2E 00 00 B0 00 F0 00 F0 F0 00 00 00 00 00 02 00 5F 11 FF 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 F3
AA: SOF
AA: SOF
81: Response flag + node 1
0152: BIO2_BI2A_CMD_POLL
00: seq_no
2E: nbytes
...: data
F3: checksum
```
## Exchange 7: BIO2_BI2A_CMD_POLL
### Write
```
AA 01 01 52 00 30 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 84
```
### Read
```
AA AA 81 01 52 00 2E 00 00 B0 00 F0 00 F0 F0 00 00 00 00 00 02 00 64 11 FF 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 F8
```