Namco 246/256: IDEATAPIDevice::atapi_send_data_block() data write timeout

[aperezbios]

Reported by @Alex-Kw , an early adopter/beta tester:

[10ms] Platform: ZuluIDE RP2040
[10ms] FW Version: 2023.07.26-dev Jul 26 2023 17:08:40
[11ms] DIP switch settings: cablesel 0, drive_id 0 debug log 0
[11ms] Flash chip size: 2048 kB
[12ms] Flash unique ID: 0x2C0F73E3085062E6
[102ms] FPGA initialization succeeded
[109ms] SD card detected, FAT32 volume size: 29542 MB
[110ms] SD MID: 0x27, OID: 0x50 0x48
[110ms] SD Name: SD32G
[110ms] SD Date: 4/2021
[111ms] SD Serial: 0x000001A4
[113ms] Could not determine image type by filename, defaulting to: CD-ROM
[114ms] Loading image SENGOKBASARAX.iso
[191ms] Device 0 configuration:
[192ms] -- Max PIO mode: 3 (phy max 3)
[192ms] -- Max UDMA mode: 0 (phy max 0)
[192ms] -- Max blocksize: 4096 (phy max 4096)
[195ms] Initialization complete!
[2000ms] FPGA license request code: 0xE6 0x62 0x50 0x08 0xE3 0x73 0x0F 0x2C 0xFF 0xFF 0xEF 0xFF 0xEE 0x39 0xDF 0x89 0xA3 
[2001ms] FPGA license accepted with status 0x80
[27149ms] -- Command handler failed for IDE_CMD_NOP
[29910ms] -- Command handler failed for IDE_CMD_NOP
[38115ms] -- Command handler failed for IDE_CMD_NOP
[43654ms] -- Command handler failed for IDE_CMD_NOP
[45664ms] -- Command handler failed for IDE_CMD_NOP
[55694ms] IDEATAPIDevice::atapi_send_data_block() data write timeout
[60195ms] --------------
[60195ms] WATCHDOG TIMEOUT, attempting bus reset
[60196ms] GPIO states: out 0x0CFE0001 oe 0x0607007F in 0x3FFA02C1
[60197ms] STACK 0x2000AF80:    0x00000081 0x0F000E00 0x00000100 0x2000AFE7
[60197ms] STACK 0x2000AF90:    0x502000DC 0x1002A5D3 0x1002A5D8 0x01000000
[60198ms] STACK 0x2000AFA0:    0x00000000 0x1002A5DD 0x00000000 0x00000001
[60199ms] STACK 0x2000AFB0:    0x2000AFE7 0x000000FF 0x2000AFEF 0x000000FF
[60200ms] STACK 0x2000AFC0:    0x00000000 0x00000000 0x2000AFE7 0x0000D98E
[60200ms] STACK 0x2000AFD0:    0x20000A00 0x1002AFF5 0x00000000 0x1002AEC5
[60201ms] STACK 0x2000AFE0:    0x00000000 0x8196834F 0x00000000 0x20000A00
[60202ms] STACK 0x2000AFF0:    0x00000000 0x10021A23 0x00000001 0x000009D8
[60203ms] STACK 0x2000B000:    0x00000010 0x10023D29 0x00000800 0x00000004
[60203ms] STACK 0x2000B010:    0x20000A2C 0x00000000 0x00000002 0x00000004
[60204ms] STACK 0x2000B020:    0x14248000 0x00000000 0x00028490 0x00000000
[60205ms] STACK 0x2000B030:    0x00000000 0x00000000 0x00000001 0x20F48000
[60206ms] STACK 0x2000B040:    0x00000078 0x00000000 0x00000000 0x00000000
[60207ms] STACK 0x2000B050:    0x00000000 0x00000000 0x00000000 0x00000000
[60207ms] STACK 0x2000B060:    0x00000000 0x00000000 0x00000000 0x00000000
[60208ms] STACK 0x2000B070:    0x00000000 0x00000000 0x00000000 0x00000000
[60209ms] -- Command handler failed for IDE_CMD_PACKET
[70754ms] IDEATAPIDevice::atapi_send_data_block() data write timeout
[75209ms] --------------
[75209ms] WATCHDOG TIMEOUT, attempting bus reset
[75210ms] GPIO states: out 0x0CFE0003 oe 0x0607007F in 0x3FFA02FB
[75210ms] STACK 0x2000AEE0:    0x00000000 0x00000001 0x20021C4B 0x00000001
[75211ms] STACK 0x2000AEF0:    0x502000DC 0x10033CF3 0x10032FE8 0x21000000
[75212ms] STACK 0x2000AF00:    0x2001D0E0 0x10033CF3 0x2001D0E0 0x10031B79
[75213ms] STACK 0x2000AF10:    0x2000BBDC 0x00000000 0x00011462 0x1002D89D
[75213ms] STACK 0x2000AF20:    0x2000BBDC 0x1002D87F 0x2000BBDC 0x1002DECB
[75214ms] STACK 0x2000AF30:    0x2001DBFB 0x2000BBDC 0x00011462 0x100292BF
[75215ms] STACK 0x2000AF40:    0x00000000 0x0F000E00 0x2001DBFC 0x00000001
[75216ms] STACK 0x2000AF50:    0x2001DBFB 0x00000001 0x00011462 0x10029A81
[75216ms] STACK 0x2000AF60:    0x00000003 0x50200000 0x00000001 0x00000002
[75217ms] STACK 0x2000AF70:    0x0000E080 0x20418803 0x00000003 0x50200000
[75218ms] STACK 0x2000AF80:    0x00000000 0x00000000 0x00010000 0x1002A291
[75219ms] STACK 0x2000AF90:    0x00000000 0x0F000E00 0x00000100 0x1002A5DD
[75219ms] STACK 0x2000AFA0:    0x00000000 0x1002A5DD 0x00000000 0x00000001
[75220ms] STACK 0x2000AFB0:    0x2000AFE7 0x000000FF 0x2000AFEF 0x000000FF
[75221ms] STACK 0x2000AFC0:    0x00000000 0x00000000 0x2000AFE7 0x00011462
[75222ms] STACK 0x2000AFD0:    0x20000A00 0x1002AFF5 0x00000000 0x1002AEC5
[75223ms] -- Command handler failed for IDE_CMD_PACKET

[aperezbios]

@PetteriAimonen any thoughts on what might be going on here?

[Alex-Kw]

Closed duplicate issue #43, however that issue does contain one more log using a different boot dongle for the system.

INFO: namco 2x6 boots from a security dongle and then accesses IDE for game data. As such, different security dongles (games) may behave differently.

Setup info: Namco 256 with 246+ Jumper set.

[Alex-Kw]

Here's a Debug log with the motherboard in 256 mode. The non-debug log is much shorter, but with debug enabled, it seems to also have an issue with IDE_CMD_NOP eventually; I could speculate it is a different manifestation of the same issue.

[10ms] Platform: ZuluIDE RP2040 [10ms] FW Version: 2023.07.26-dev Jul 26 2023 17:08:40 [11ms] DIP switch settings: cablesel 1, drive_id 0 debug log 1 [11ms] Flash chip size: 2048 kB [12ms] Flash unique ID: 0x2C0F73E3085062E6 [13ms] DBG Loading FPGA bitstream [102ms] FPGA initialization succeeded [109ms] SD card detected, FAT32 volume size: 29542 MB [110ms] SD MID: 0x27, OID: 0x50 0x48 [110ms] SD Name: SD32G [110ms] SD Date: 4/2021 [111ms] SD Serial: 0x000001A4 [115ms] Could not determine image type by filename, defaulting to: CD-ROM [116ms] Loading image te51-dvd0.iso [554ms] DBG Image file te51-dvd0.iso is contiguous, sectors 10897236 to 19119955 [570ms] Device 0 configuration: [571ms] -- Max PIO mode: 3 (phy max 3) [571ms] -- Max UDMA mode: 0 (phy max 0) [572ms] -- Max blocksize: 4096 (phy max 4096) [574ms] DBG -- Operating as primary drive, secondary drive not detected [575ms] Initialization complete! [577ms] DBG IDE_EVENT_HWRST [1080ms] DBG -- Operating as primary drive, secondary drive not detected [1578ms] DBG -- IDE regs: STATUS:0x00 CMD:0xFF DEV:0x00 DEVCTRL:0xFF ERROR:0x01 FEATURE:0xAA LBAL:0x01 LBAM:0x14 LBAH:0xEB [2000ms] FPGA license request code: 0xE6 0x62 0x50 0x08 0xE3 0x73 0x0F 0x2C 0xFF 0xFF 0xEF 0xFF 0xEE 0x39 0xDF 0x89 0xA3 [2001ms] FPGA license accepted with status 0x80 [17384ms] DBG -- Operating as primary drive, secondary drive not detected [18198ms] DBG IDE Command for DEV1: 0x00 IDE_CMD_NOP (device 0x10, dev_ctrl 0x02, feature 0x00, sector_count 0x34, lba 0xEB 0x14 0x12) [18200ms] DBG -- Ignoring command for device not present [18883ms] DBG -- IDE regs: STATUS:0x80 CMD:0x00 DEV:0x10 DEVCTRL:0x02 ERROR:0x01 FEATURE:0x00 LBAL:0x12 LBAM:0x14 LBAH:0xEB [33898ms] Detected IDE STATUS register stuck at busy state 0x80 for 16 seconds, resetting to zero [34899ms] DBG -- IDE regs: STATUS:0x00 CMD:0x00 DEV:0x10 DEVCTRL:0x02 ERROR:0x01 FEATURE:0x00 LBAL:0x12 LBAM:0x14 LBAH:0xEB

[PetteriAimonen]

I think IDE_CMD_NOP may actually be the culprit - I don't think there is a proper handler for it.

I wonder if the host is actually issuing NOP command or if it is somehow mistransferred, but in any case there is some weird remaining busy state after it. I couldn't find an utility to send raw ATA commands on Linux, but it appears to be possible via HDIO_DRIVE_CMD ioctl.

[aperezbios]

@PetteriAimonen I think we're going to have to implement support for IDE_CMD_NOP, as I've run in to several instances where it's being issued.

[PetteriAimonen]

Hmm, turns out the IDE_CMD_NOP is expected to always fail, which is what the default handler does anyway. The actual bug has to be something else..

[Alex-Kw]

Hmm, turns out the IDE_CMD_NOP is expected to always fail, which is what the default handler does anyway. The actual bug has to be something else..

Thanks for the reply and work.

These ISOs are from DVDs if that wasn't mentioned. I noticed this issue:

https://github.com/rabbitholecomputing/ZuluIDE-firmware/issues/7

Let me know if you think that's relevant, or if there are any other things I can try with the debug dip set.

[PetteriAimonen]

@Alex-Kw DVD ISOs probably still have issues, but the difference would matter only when it gets to actually reading the disc.

You could try the latest build from https://github.com/rabbitholecomputing/ZuluIDE-firmware/releases/tag/latest and post the debug log from it. It has some small changes to how unexpected situations are handled.

[Alex-Kw]

@PetteriAimonen Thank you, I've updated the firmware and here's the first result with just the debug DIP switch set. I wonder if it's looking for a second drive and no primary? I believe the CD/DVD Drive I pulled was on cable select, so if it helps, I can obtain logs with the ZuluIDE device configured the other ways (Cable Select or PRI/SEC).

[10ms] Platform: ZuluIDE RP2040 [10ms] FW Version: 2023.08.23-dev Aug 24 2023 04:40:07 [11ms] DIP switch settings: cablesel 0, drive_id 0 debug log 1 [11ms] Flash chip size: 2048 kB [12ms] Flash unique ID: 0x2C0F73E3085062E6 [13ms] DBG Loading FPGA bitstream [102ms] FPGA initialization succeeded [109ms] SD card detected, FAT32 volume size: 29542 MB [110ms] SD MID: 0x27, OID: 0x50 0x48 [110ms] SD Name: SD32G [110ms] SD Date: 4/2021 [111ms] SD Serial: 0x000001A4 [116ms] Could not determine image type by filename, defaulting to: CD-ROM [117ms] Loading image te51-dvd0.iso [558ms] DBG Image file te51-dvd0.iso is contiguous, sectors 10897236 to 19119955 [580ms] Device 0 configuration: [580ms] -- Max PIO mode: 3 (phy max 3) [581ms] -- Max UDMA mode: 0 (phy max 0) [581ms] -- Max blocksize: 4096 (phy max 4096) [584ms] DBG -- Operating as primary drive, secondary drive not detected [585ms] Initialization complete! [587ms] DBG IDE_EVENT_HWRST [1092ms] DBG -- Operating as primary drive, secondary drive not detected [1589ms] DBG -- IDE regs: STATUS:0x00 CMD:0xFF DEV:0x00 DEVCTRL:0xFF ERROR:0x01 FEATURE:0xAA LBAL:0x01 LBAM:0x14 LBAH:0xEB [2000ms] FPGA license request code: 0xE6 0x62 0x50 0x08 0xE3 0x73 0x0F 0x2C 0xFF 0xFD 0xEF 0xFF 0xEE 0x39 0xDF 0x89 0xA3 [2001ms] FPGA license accepted with status 0x80 [17410ms] DBG -- Operating as primary drive, secondary drive not detected [18223ms] DBG IDE Command for DEV1: 0x00 IDE_CMD_NOP (device 0x10, dev_ctrl 0x02, feature 0x00, sector_count 0x34, lba 0xEB 0x14 0x12) [18224ms] DBG -- Command was for a device that is not present - reporting failure [18908ms] DBG -- IDE regs: STATUS:0x41 CMD:0x00 DEV:0x10 DEVCTRL:0x02 ERROR:0x04 FEATURE:0x00 LBAL:0x12 LBAM:0x14 LBAH:0xEB

[aperezbios]

@PetteriAimonen any thoughts on what might be going on here?

[PetteriAimonen]

I think something has to be going significantly wrong with the register writes, resulting in garbage values.

Possibly some kind of timing issue, but that's very hard to debug without having a logic analyzer trace.

[Alex-Kw]

@PetteriAimonen I have a Saleae Logic 8 here. If that would be sufficient, let me know what signals to monitor and I could probably give it a try.

[PetteriAimonen]

@Alex-Kw It's certainly worth a try.

Here are the most useful 8 signals to probe:

• D4, pin 9
• D0, pin 17
• DIOW, pin 23
• DIOR, pin 25
• DA1, pin 33
• DA0, pin 35
• DA2, pin 36
• CS0, pin 37

Trigger on falling edge of DIOW. Ideally samplerate would be at least 10 MHz, and capture for at least 3 seconds.

I've marked the location of pins on the bottom side of ZuluIDE PCB in the image below, but you can probe wherever it is easiest - either on the ZuluIDE connector, or on another connector on a 3-connector IDE cable.

[Alex-Kw]

OK, Here it is. This is a full capture from trigger until the system locks up / stops trying to access. You should be able to use Saleae Logic 2 software for free to open the capture (presuming you don't have it already).

I truly hope it helps. I fashioned a quick cable to connect my Saleae Logic 8 to a 3 connector IDE cable (great idea, thank you), so if further testing is required with this pinout I am good to go. TE5-DVD0.sal.zip

[aperezbios]

@Alex-Kw excellent, thank you for this trace. I hope it sheds some light on WTF is going on :)

[PetteriAimonen]

@Alex-Kw Thanks, I'll try to dig into older versions of the ATAPI specification to see if they clarify anything. Do you happen to know whether the Namco hardware is usually picky about which CD drives it supports, or does it generally work with any drive? If you have a compatible drive available, doing the same logic analyzer capture with it would provide useful information.

---

Here are some initial notes, I'm not yet sure how each of them will affect things:

1. DIOR and DIOW simultaneously active

Host has both read and write signals in active state for 1 second after boot. This is not a valid state, so ZuluIDE could ignore it. Currently it will be interpreted as either read or write randomly, based on which signal activates first. Results in garbage data written to IDE registers, but I think it will not matter as it is replaced later.

2. Other traffic on bus

The host uses old-school way of directly connecting the IDE bus to system (ISA?) bus. There is a lot of other traffic on the bus. ZuluIDE should be ignoring this, but testing on that has been a bit sparse because the systems I currently have use a separate IDE controller chip.

3. Weird write sequence

The write sequence looks like this:

For some reason there are two pulses on DIOW instead of one. The first one possibly violates ATA specification Address valid to DIOW minimum time. I think the double write may be related to behavior of IOCS16 signal, which ATA devices use to indicate to host that destination register has 16 bits. It should work on ZuluIDE but again I don't have a system that requires it.

4. Command sequence

First command occurs at 18 seconds after boot. Register transfer sequence decoded:

1. Write SECTOR_COUNT xxx1xxx0
2. Read SECTOR_COUNT
3. Write LBA_LOW xxx1xxx0
4. Read LBA_LOW
5. Write FEATURE xxx0xxx0
6. Write DEVICE xxx0xxx0 (select device 0)
7. Write COMMAND xxx0xxx0
8. Write COMMAND xxx0xxx0
9. Read STATUS

Then after 1 µs pause

11. Write DEVICE xxx1xxx0 (select device 1)
12. Write COMMAND xxx0xxx0
13. Write COMMAND xxx0xxx0
14. Read STATUS

And after that it appears to decide there is no drive to talk to.

After the first COMMAND write ZuluIDE will be in BUSY state. My interpretation of the ATAPI6 specification is that the result of further writes is indeterminate at this point. But the host is clearly expecting some immediate effect on the STATUS register.

[Alex-Kw]

Thanks for the immediate thoughts @PetteriAimonen, I'll be happy to repeat the test with a working optical drive.

Regarding how picky the system is, for the most part, most drives work. There are a couple of games, namely Tekken 4 and Bloody Roar 3, that are themselves known to be very picky with ATAPI command set and thus drive selection. I am purposely avoiding them for now, Tekken 5 (in use here) is usually quite agreeable drive-wise. I'll upload the other trace ASAP.

[Alex-Kw]

@PetteriAimonen Here is the same capture setup / same boot dongle, with an optical drive instead of the ZuluIDE+disc image. Hopefully it provides some insight, I let it run until it was loading game data for ~20-30 seconds.

TE5-DVD0-OPTICAL.sal.zip

[PetteriAimonen]

Thanks.

Weirdnesses 1-3 appear exactly the same, so I think they are working ok with ZuluIDE also.

There is a clear difference in the command sequence. Instead of only reading STATUS once, the host dutifully polls for 100 ms until the device is ready:

WR SECTOR_COUNT xxx1xxx0
RD SECTOR_COUNT
WR LBA_LOW xxx1xxx0
RD LBA_LOW
WR DEVCTRL?
WR FEATURE xxx0xxx0
WR DEVICE xxx0xxx0
WR CMD xxx0xxx0
WR CMD xxx0xxx0
RD STATUS xxx0xxx0
RD STATUS xxx0xxx0
RD STATUS xxx0xxx0
.. polls for 100 ms
RD STATUS xxx1xxx1

WR DEVICE xxx1xxx0

This is how it should work, so it seems the first STATUS reply by ZuluIDE has something that the host doesn't like.

It's difficult to capture the entire status register contents with a 8-channel analyzer, but I'll try to reproduce the sequence here in FPGA simulator and compare the value against specifications.

[PetteriAimonen]

@Alex-Kw I have a test build here. It tries to speed up the response to STATUS read by a bit, and sets bit 4 so that I can see in trace when the response is ready.

New trace and new debug log from this build would be useful.

https://github.com/rabbitholecomputing/ZuluIDE-firmware/actions/runs/6034876110

[Alex-Kw]

@PetteriAimonen Sure, here you are. Thanks for your help so far.

Edit; this might be 1st boot where the firmware updated. If this isn't what you expect in the trace I'll rerun it.

zululog.txt

Aug31-TE5.sal.zip

[PetteriAimonen]

The upgrade looks ok, trace of D4 changed as expected. Based on trace, the timing meets ATA standards with plenty of time to spare, but for some reason the host still does not appear to like the STATUS response. But the host seems to violate timing in a few places, so it might expect tighter than standard behavior from the drive.

I will attempt some further timing improvements in the FPGA code, but that will have to wait until next week.

In the meanwhile if you are eager to test, traces of both ZuluIDE and the physical CD-ROM drive with D7 / pin 3 probed instead of D4 could confirm that the status BSY state is actually as I expect. If the logic analyzer is capable of higher samplerate, that would be useful also.

[Alex-Kw]

Sounds good. I can attempt to marginally increase the sample rate; I believe I'm at 20MHz and may be able to get 25MHz. I'll try. Moving the pin over from D4 to D7 shouldn't be an issue either.

[Alex-Kw]

Move D4, Pin 9 > To D7 , pin 3

Attached are the samples taken at 25MHz

D7.zip

[PetteriAimonen]

Thanks, that seems to confirm that it is a response time issue. Based on the trace:

• Working optical drive responds to STATUS register read in about 20 ns
• ZuluIDE responds in 80 ns
• ATA specification requires response within 240 ns

In the newest trace it appears to get just a tiny bit further with ZuluIDE before failing, so it's probably close to the edge now.

[Alex-Kw]

Any update on this? The natives are getting restless and some are considering upwards of $300 on a working IDE ODE for the Namco 245/256

[PetteriAimonen]

@Alex-Kw Unfortunately no.. it proved a quite complex issue and I haven't been able to work on it.

[Alex-Kw]

@Alex-Kw Unfortunately no.. it proved a quite complex issue and I haven't been able to work on it.

That is unfortunate... anything that can be done to help? Yet again people are seeking a working IDE ODE for the Namco 246 / 256 and are pointing to a $335 product with hope; https://www.arcade-projects.com/threads/ide-simulator-using-it-in-a-namco-246-256.28716/#post-412677

[aperezbios]

@Alex-Kw can you please try this again with https://github.com/rabbitholecomputing/ZuluIDE-firmware/releases/tag/v2024.05.14 and report back with a debug log file on it? Please try with debug mode both enabled and disabled

[Alex-Kw]

@Alex-Kw can you please try this again with https://github.com/rabbitholecomputing/ZuluIDE-firmware/releases/tag/v2024.05.14 and report back with a debug log file on it? Please try with debug mode both enabled and disabled

I should be able to try this again soon, my Namco hardware and IDE accessories were mistakenly taken with a cabinet purchase but are set to be returned to me soon. I'll report back as soon as I'm able to revisit this and retry! Thank you :)

[lorizzuoso]

Are there any updates on this?