On Wed, 14 May 2014, Mark Cave-Ayland wrote:
On 14/05/14 12:10, BALATON Zoltan wrote:
The logs I've posted are with DEBUG_IDE_ATAPI, DEBUG_DBDMA and
DEBUG_MACIO already enabled...
Well sure, but not the ones in your last email - I had to go back several
mails back into the thread to pull them out. Bear in mind the high volume of
these lists means that a lot of people who could help won't have the time to
do this.
All the logs I posted in this thread were with these debug options
enabled. Maybe the beginning was missing as I only included the logs from
the failing dma reply because before that I was tracing to see that the
TOC was read and about to be returned so I did not include those logs
again. (They were in the previous mail though.) I'm including them again
below this time.
Which part is it that's still confusing you? Putting breakpoints on
pmac_ide_transfer() and pmac_ide_atapi_transfer_cb() will show you the
iterations on each DMA request (be sure to compare against a "known good"
example to understand how it should work first). If you can give more detail
as to which bits are confusing, I will try my best to explain them.
Looking at the backtrace:
#0 ide_atapi_cmd_error (s=0x5555563cb238, sense_key=5, asc=33)
at hw/ide/atapi.c:141
#1 0x00005555556cecf5 in ide_atapi_io_error (s=0x5555563cb238, ret=-5)
at hw/ide/atapi.c:160
#2 0x00005555556d9d01 in pmac_ide_atapi_transfer_cb (opaque=0x5555563ccc68,
ret=-5) at hw/ide/macio.c:64
#3 0x00005555556780d2 in dma_complete (dbs=0x5555563ab840, ret=-5)
at dma-helpers.c:121
#4 0x00005555556781db in dma_bdrv_cb (opaque=0x5555563ab840, ret=-5)
at dma-helpers.c:149
#5 0x0000555555614dd1 in bdrv_co_em_bh (opaque=0x5555563b5000) at block.c:4602
#6 0x00005555555f8170 in aio_bh_poll (ctx=0x55555637fc00) at async.c:81
#7 0x00005555555f7dc9 in aio_poll (ctx=0x55555637fc00, blocking=false)
at aio-posix.c:188
#8 0x00005555555f8587 in aio_ctx_dispatch (source=0x55555637fc00, callback=
0x0, user_data=0x0) at async.c:205
#9 0x00007ffff78ca6d5 in g_main_context_dispatch ()
from /lib64/libglib-2.0.so.0
#10 0x00005555557a0f42 in glib_pollfds_poll () at main-loop.c:190
#11 0x00005555557a1042 in os_host_main_loop_wait (timeout=0) at main-loop.c:235
#12 0x00005555557a1115 in main_loop_wait (nonblocking=1) at main-loop.c:484
#13 0x0000555555844190 in main_loop () at vl.c:2075
#14 0x000055555584bc23 in main (argc=30, argv=0x7fffffffdc88, envp=
0x7fffffffdd80) at vl.c:4556
shows that pmac_ide_atapi_transfer_cb is called with ret=-5 which is why
it fails, so putting a breakpoint there is too late. What I don't
understand is where this -5 value comes from. I don't have a known good
example because Darwin reads the TOC differently (probably before enabling
DMA, I did not trace it more than the logs I've included earlier though)
and MorphOS always fails.
Here are the logs of all requests MorphOS does up to the failing ReadTOC
again:
ATAPI limit=0x8000 packet: 00 00 00 00 00 00 00 00 00 00 00 00
ATAPI limit=0x8000 packet: 12 00 00 00 24 00 00 00 00 00 00 00
reply: tx_size=36 elem_tx_size=0 index=0
byte_count_limit=32768
status=0x58
reply: tx_size=0 elem_tx_size=0 index=36
status=0x50
ATAPI limit=0x8000 packet: 1b 00 00 00 01 00 00 00 00 00 00 00
ATAPI limit=0x8000 packet: 00 00 00 00 00 00 00 00 00 00 00 00
ATAPI limit=0x8000 packet: 25 00 00 00 00 00 00 00 00 00 00 00
reply: tx_size=8 elem_tx_size=0 index=0
byte_count_limit=32768
status=0x58
reply: tx_size=0 elem_tx_size=0 index=8
status=0x50
ATAPI limit=0x8000 packet: 5a 00 05 00 00 00 00 00 30 00 00 00
atapi_cmd_error: sense=0x5 asc=0x24
ATAPI limit=0x8000 packet: 5a 00 04 00 00 00 00 00 28 00 00 00
atapi_cmd_error: sense=0x5 asc=0x24
ATAPI limit=0x8000 packet: 5a 00 03 00 00 00 00 00 28 00 00 00
atapi_cmd_error: sense=0x5 asc=0x24
ATAPI limit=0x8000 packet: 5a 00 3f 00 00 00 00 01 02 00 00 00
atapi_cmd_error: sense=0x5 asc=0x24
ATAPI limit=0x8000 packet: 51 00 00 00 00 00 00 00 22 00 00 00
reply: tx_size=34 elem_tx_size=0 index=0
byte_count_limit=32768
status=0x58
reply: tx_size=0 elem_tx_size=0 index=34
status=0x50
DBDMA: writel 0x0000000000000d0c <= 0x00e4e960
DBDMA: channel 0x1a reg 0x3
DBDMA: dbdma_cmdptr_load 0x00e4e960
ATAPI limit=0x8000 packet: 43 00 00 00 00 00 00 03 24 00 00 00
DBDMA: DBDMA_run_bh
DBDMA: writel 0x0000000000000d00 <= 0x80008000
DBDMA: channel 0x1a reg 0x0
DBDMA: status 0x00008400
DBDMA: readl 0x0000000000000d00 => 0x80008000
DBDMA: channel 0x1a reg 0x0
DBDMA: DBDMA_run_bh
DBDMA: channel_run
dbdma_cmd 0x7f8f93662ee0
req_count 0x0324
command 0x3000
phy_addr 0x00e4f30c
cmd_dep 0x00000000
res_count 0x0000
xfer_status 0x0000
DBDMA: start_input
DBDMA: addr 0xe4f30c key 0x0
pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=0, len=324
io_buffer_size = 0
io->len = 0x324
sector_num=-1 size=20, cmd_cmd=0
atapi_cmd_error: sense=0x5 asc=0x21
done DMA
DBDMA: dbdma_end
DBDMA: conditional_wait
DBDMA: dbdma_cmdptr_save 0x00e4e960
DBDMA: xfer_status 0x00008400 res_count 0x0000
DBDMA: conditional_interrupt
DBDMA: conditional_branch
DBDMA: dbdma_cmdptr_load 0x00e4e970
DBDMA: channel_run
dbdma_cmd 0x7f8f93662ee0
req_count 0x0000
command 0x7000
phy_addr 0x00000000
cmd_dep 0x00000000
res_count 0x0000
xfer_status 0x0000
DBDMA: readl 0x0000000000000d04 => 0x00008000
DBDMA: channel 0x1a reg 0x1
DBDMA: writel 0x0000000000000d00 <= 0x98000000
DBDMA: channel 0x1a reg 0x0
DBDMA: status 0x00000000
ATAPI limit=0x8000 packet: 00 00 00 00 00 00 00 00 00 00 00 00
ATAPI limit=0x8000 packet: 00 00 00 00 00 00 00 00 00 00 00 00
and here are the corresponding debug logs from MorphOS that shows what is
it trying to do:
Dev_Inquiry@idemacio2.device-0: DiskPort 0x200a9310
Dev_Inquiry@idemacio2.device-0: ATAPI
Dev_InquirySCSI@idemacio2.device-0:
Dev_InquirySCSI@idemacio2.device-0: Send TestDrive
Dev_InquirySCSI@idemacio2.device-0: 1st TestDrive Status 0
Dev_InquirySCSI@idemacio2.device-0: Send Inquiry
Dev_InquirySCSI@idemacio2.device-0: No IOError
Dev_InquirySCSI@idemacio2.device-0: Unit is there physically
Dev_InquirySCSI@idemacio2.device-0: DriveGeometry
Dev_SetUnitBlockSize@idemacio2.device-0: SectorSize 2048
Dev_SetUnitBlockSize@idemacio2.device-0: SectorSize 2048 SectorShift 11
SectorShiftHighMask 0xffe00000
Dev_InquirySCSI@idemacio2.device-0: Set Removable
Dev_InquirySCSI@idemacio2.device-0: Send StartUnit
Dev_InquirySCSI@idemacio2.device-0: StartMotor IOError 0 SCSIError 0x0
Dev_InquirySCSI@idemacio2.device-0: Sense [0] 0x00000000000000000000000000000000
Dev_InquirySCSI@idemacio2.device-0: TestUnitReady IOError 0 SCSIError 0x0
Dev_InquirySCSI@idemacio2.device-0: Sense[0] 0x00000000000000000000000000000000
Dev_InquirySCSI@idemacio2.device-0: StartUnit done
Dev_InquirySCSI@idemacio2.device-0: TstDrive IOError 0 SCSIError 0x0
Dev_Capacity@idemacio2.device-0:
Dev_Capacity@idemacio2.device-0: DeviceType 5 needs Capacity
Dev_Capacity16@idemacio2.device-0:
Dev_Capacity16@idemacio2.device-0: Send Capacity16
Dev_Capacity16@idemacio2.device-0: IOError -4 SCSIError 0x0
Dev_Capacity10@idemacio2.device-0:
Dev_Capacity10@idemacio2.device-0: Send Capacity
Dev_Capacity10@idemacio2.device-0: Status ok
Dev_Capacity10@idemacio2.device-0: SectorCount 112839 (0x1b8c7)
Dev_Capacity10@idemacio2.device-0: SectorSize 2048
Dev_Capacity10@idemacio2.device-0: ignore for CDROM..too dangerous with Atapi
returning random crap
Dev_Capacity10@idemacio2.device-0: TotalSectors 112839
Dev_Capacity10@idemacio2.device-0: SectorSize 2048
Dev_Capacity@idemacio2.device-0: Capacity10 ok
Dev_Capacity@idemacio2.device-0: Send ModeSense(Flex Disk Page)
Dev_ModeSense@idemacio2.device-0: Page 5 Length 32 Flags 0x0 PageOffset
0x200cae98
Dev_ModeSense@idemacio2.device-0: Use ModeSense10
Dev_ModeSense@idemacio2.device-0: Final Length 48 Offset 16
Dev_Capacity@idemacio2.device-0: ModeSense error 45
Dev_Capacity@idemacio2.device-0: Send ModeSense(Rigid Disk Geometry Page)
Dev_ModeSense@idemacio2.device-0: Page 4 Length 24 Flags 0x0 PageOffset
0x200cae98
Dev_ModeSense@idemacio2.device-0: Use ModeSense10
Dev_ModeSense@idemacio2.device-0: Final Length 40 Offset 16
Dev_Capacity@idemacio2.device-0: ModeSense error 45
Dev_Capacity@idemacio2.device-0: Send ModeSense(Format Page)
Dev_ModeSense@idemacio2.device-0: Page 3 Length 24 Flags 0x0 PageOffset
0x200cae98
Dev_ModeSense@idemacio2.device-0: Use ModeSense10
Dev_ModeSense@idemacio2.device-0: Final Length 40 Offset 16
Dev_Capacity@idemacio2.device-0: ModeSense error 45
Dev_Capacity@idemacio2.device-0: No ModeHeader yet
Dev_Capacity@idemacio2.device-0: Send ModeSense(Parameter Header)
Dev_ModeSense@idemacio2.device-0: Page 63 Length 242 Flags 0x0 PageOffset
0x200cae98
Dev_ModeSense@idemacio2.device-0: Use ModeSense10
Dev_ModeSense@idemacio2.device-0: Final Length 258 Offset 16
Dev_Capacity@idemacio2.device-0: ModeSense error 45
Dev_InquirySCSI@idemacio2.device-0: Mark Unit is ready
Dev_InquirySCSI@idemacio2.device-0: scan/mount partitions
LibMountMountTagList@idemacio2.device-0: DeviceType 5 MountMode 0
LibMountMountTagList@idemacio2.device-0: mountable devicetype
LibMountMountTagList@idemacio2.device-0: Mount CD
Mount_MountCD@idemacio2.device-0: DiskPort 0x2004bf60
Mount_MountCD@idemacio2.device-0: Device 0x200a7f64 <idemacio2.device> Unit
0x20078654 UnitNum 0
Mount_MountCD@idemacio2.device-0: Check for bootable disc...
Mount_GetDiscInfo@idemacio2.device-0:
Mount_GetDiscInfo@idemacio2.device-0: MyDiscInfoData 0x200abe84
Mount_GetDiscInfo@idemacio2.device-0: GetDiscInfo io_Error(0)
Mount_GetDiscInfo@idemacio2.device-0: Flags 0xe FirstTrack 1
Mount_GetDiscInfo@idemacio2.device-0: Sessions 1
Mount_GetDiscInfo@idemacio2.device-0: FirstTrackLastSession 1
Mount_GetDiscInfo@idemacio2.device-0: Flags1 0x20 DiscType 0
Mount_GetDiscInfo@idemacio2.device-0: DiscID <> DiscBarCode <>
Mount_GetDiscInfo@idemacio2.device-0: ok
Mount_MountCD@idemacio2.device-0: MyDiscInfoData 0x200abe84 Length 32
Mount_GetTOC@idemacio2.device-0: Locate ISO descriptor
Mount_GetTOC@idemacio2.device-0: READ_TOC io_Error(45)
Mount_GetTOC@idemacio2.device-0: failed
Mount_MountCD@idemacio2.device-0: no toc data
Regards,
BALATON Zoltan
