Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

LZH depacking fails on NFS drive #193

Closed
mikrosk opened this issue May 18, 2019 · 7 comments

Comments

Projects
None yet
4 participants
@mikrosk
Copy link
Collaborator

commented May 18, 2019

I tried to reproduce this scenario: http://atari-forum.com/viewtopic.php?f=103&t=30390&start=75#p319956 (the lzh depacking issue) and indeed I was able to. However looking into the log, I fail to see how is this a communication / uneven address allocation issue, there is clearly something wrong with the translation:

01481545 00000002 (2019-05-18 20:23:42.951679)  handleAcsiCommand: 3f a0 43 45 03 42 00 08 00 00 00 00 00 00 isIcd
01481547 00000002 (2019-05-18 20:23:42.953295)  handleAcsiCommand - CE specific command - module: 03
01481548 00000001 (2019-05-18 20:23:42.954888)  TranslatedDisk function - GEMDOS_Fseek (42)
01481550 00000002 (2019-05-18 20:23:42.956588)  TranslatedDisk::onFseek - atariHandle: 0, offset: 524288, seekMode: 0
01481557 00000007 (2019-05-18 20:23:42.963355)  TranslatedDisk::onFseek - ok, current position is 524288, and we got 6230466 bytes to end of file
01481563 00000006 (2019-05-18 20:23:42.969500)

01481564 00000001 (2019-05-18 20:23:42.971089)  handleAcsiCommand: 20 43 45 03 4e 00
01481566 00000002 (2019-05-18 20:23:42.972655)  handleAcsiCommand - CE specific command - module: 03
01481568 00000002 (2019-05-18 20:23:42.974321)  TranslatedDisk function - GEMDOS_Fsfirst (4e)
01481570 00000002 (2019-05-18 20:23:42.976719)  TranslatedDisk::onFsfirst(001531b8) - atari search string: CHIPS_X\CHIPS_X.HYP, find attribs: 0xff
01481572 00000002 (2019-05-18 20:23:42.978334)  find attribs: 0xff -> FA_READONLY FA_HIDDEN FA_SYSTEM FA_VOLUME FA_DIR FA_ARCHIVE 
01481573 00000001 (2019-05-18 20:23:42.980047)  TranslatedDisk::createFullAtariPath - without drive letter, relative path : CHIPS_X/CHIPS_X.HYP => /LHARC/TWO/CHIPS_X/CHIPS_X.HYP
01481575 00000002 (2019-05-18 20:23:42.981834)  DirTranslator::shortToLongPath - shortToLongFileName() failed for short name: CHIPS_X path=/mnt/shared/LHARC/TWO
01481577 00000002 (2019-05-18 20:23:42.983531)  DirTranslator::getShortenerForPath - shortener for /mnt/shared/LHARC/TWO/CHIPS_X NOT found, creating
01481582 00000005 (2019-05-18 20:23:42.988730)  DirTranslator::shortToLongPath - shortToLongFileName() failed for short name: CHIPS_X.HYP path=/mnt/shared/LHARC/TWO/CHIPS_X
01481584 00000002 (2019-05-18 20:23:42.990538)  TranslatedDisk::createFullHostPath - dirTranslator.shortToLongPath -- root: /mnt/shared, inFullAtariPath: /LHARC/TWO/CHIPS_X/CHIPS_X.HYP -> partialLongHostPath: LHARC/TWO/CHIPS_X/CHIPS_X.HYP
01481586 00000002 (2019-05-18 20:23:42.992227)  TranslatedDisk::onFsfirst - atari search string: CHIPS_X\CHIPS_X.HYP, host search string: /mnt/shared/LHARC/TWO/CHIPS_X/CHIPS_X.HYP
01481587 00000001 (2019-05-18 20:23:42.993899)  TranslatedDisk::isRootDir - hostPath: /mnt/shared/LHARC/TWO/CHIPS_X -- no, it's NOT a root dir
01481590 00000003 (2019-05-18 20:23:42.996992)  TranslatedDisk::onFsfirst - host search string: /mnt/shared/LHARC/TWO/CHIPS_X/CHIPS_X.HYP 0 entries found
01481623 00000033 (2019-05-18 20:23:43.029786)

01481625 00000002 (2019-05-18 20:23:43.031387)  handleAcsiCommand: 20 43 45 03 43 00
01481626 00000001 (2019-05-18 20:23:43.032978)  handleAcsiCommand - CE specific command - module: 03
01481628 00000002 (2019-05-18 20:23:43.034558)  TranslatedDisk function - GEMDOS_Fattrib (43)
01481630 00000002 (2019-05-18 20:23:43.037004)  TranslatedDisk::createFullAtariPath - without drive letter, relative path : CHIPS_X/CHIPS_X.HYP => /LHARC/TWO/CHIPS_X/CHIPS_X.HYP
01481632 00000002 (2019-05-18 20:23:43.038837)  DirTranslator::shortToLongPath - shortToLongFileName() failed for short name: CHIPS_X path=/mnt/shared/LHARC/TWO
01481634 00000002 (2019-05-18 20:23:43.040505)  DirTranslator::shortToLongPath - shortToLongFileName() failed for short name: CHIPS_X.HYP path=/mnt/shared/LHARC/TWO/CHIPS_X
01481635 00000001 (2019-05-18 20:23:43.042173)  TranslatedDisk::createFullHostPath - dirTranslator.shortToLongPath -- root: /mnt/shared, inFullAtariPath: /LHARC/TWO/CHIPS_X/CHIPS_X.HYP -> partialLongHostPath: LHARC/TWO/CHIPS_X/CHIPS_X.HYP
01481639 00000004 (2019-05-18 20:23:43.045271)
     LOG_ERROR occurred
     Time since beginning of ACSI command handling: 15
     Time between this and previous ACSI command  : 60
01481639 00000004 (2019-05-18 20:23:43.045271)  TranslatedDisk::onFattrib() -- stat(/mnt/shared/LHARC/TWO/CHIPS_X/CHIPS_X.HYP) failed

Repro steps:

  • copy lharceng.ttp to NFS drive
  • copy some big (in my case 6 MB) lzh next to it
  • drag&drop the lzh file on lharceng.ttp

It fails in about 10% of depacking (after exactly 512 KB has been read from the archive).

@mikrosk mikrosk added the bug label May 18, 2019

@ggnkua

This comment has been minimized.

Copy link
Collaborator

commented May 18, 2019

Do we know if this happens on Falcon only?

@miniupnp

This comment has been minimized.

Copy link
Collaborator

commented May 18, 2019

also does it happen on a Translated USB flash drive, or is it specific to NFS ? or SMB ?

@mikrosk

This comment has been minimized.

Copy link
Collaborator Author

commented May 18, 2019

Same for a translated usb flash drive.

@d-hedberg

This comment has been minimized.

Copy link

commented May 19, 2019

Here's my test program I sent to Jookie about a year ago with regards to the even/odd file buffer bug. It reads the data file (included in the archive) into a buffer at an odd address and into a buffer at an even address. It checks that the data before and after the file buffers are not touched, and that the first 3 bytes read and the last 2 bytes read are correct. If everything is read correctly, I think the resulting print out on the screen would be the 2 words BEGIN and END. If it failed it would be something else. Don't remember. The source code is included as well. It's simple, but it was enough for me to verify that the bug actually existed and enough to reproduce it.

I now have a TT as well, but I haven't hooked up the CosmosEx to it yet as I ordered a CosmosEx 3.0 for the TT, so I'll rather wait. I would be interested to know if you can reproduce the bug on the TT as well.

CXTEST2.ZIP

@mikrosk

This comment has been minimized.

Copy link
Collaborator Author

commented May 19, 2019

@d-hedberg I can reproduce it, too. Logs are much cleaner now:

00703205 00000002 (2019-05-19 10:22:22.504483)  handleAcsiCommand: 20 43 45 03 3d 00
00703206 00000001 (2019-05-19 10:22:22.506162)  handleAcsiCommand - CE specific command - module: 03
00703208 00000002 (2019-05-19 10:22:22.507758)  TranslatedDisk function - GEMDOS_Fopen (3d)
00703211 00000003 (2019-05-19 10:22:22.510410)  TranslatedDisk::createFullAtariPath - without drive letter, relative path : CXTEST2.DAT => /A/CXTEST2.DAT
00703212 00000001 (2019-05-19 10:22:22.512141)  TranslatedDisk::createFullHostPath - dirTranslator.shortToLongPath -- root: /mnt/shared, inFullAtariPath: /A/CXTEST2.DAT -> partialLongHostPath: A/CXTEST2.DAT
00703214 00000002 (2019-05-19 10:22:22.513879)  TranslatedDisk::isDriveIndexReadOnly -- drive index: 13 -> not READ ONLY 
00703217 00000003 (2019-05-19 10:22:22.516757)  TranslatedDisk::onFopen - /mnt/shared/A/CXTEST2.DAT - success, index is 0
00703221 00000004 (2019-05-19 10:22:22.520727)

00703223 00000002 (2019-05-19 10:22:22.522406)  handleAcsiCommand: 20 43 45 03 65 00
00703224 00000001 (2019-05-19 10:22:22.523983)  handleAcsiCommand - CE specific command - module: 03
00703226 00000002 (2019-05-19 10:22:22.525623)  TranslatedDisk function - GD_CUSTOM_getBytesToEOF (65)
00703229 00000003 (2019-05-19 10:22:22.528459)  TranslatedDisk::getByteCountToEndOfFile - for atari handle 0 - there are 168048 bytes until the end of file
00703234 00000005 (2019-05-19 10:22:22.533823)

00703236 00000002 (2019-05-19 10:22:22.535370)  handleAcsiCommand: 3f a0 43 45 03 3f 00 01 fc 00 00 00 00 00 isIcd
00703237 00000001 (2019-05-19 10:22:22.536950)  handleAcsiCommand - CE specific command - module: 03
00703239 00000002 (2019-05-19 10:22:22.538586)  TranslatedDisk function - GEMDOS_Fread (3f)
00703240 00000001 (2019-05-19 10:22:22.540282)  TranslatedDisk::onFread - atariHandle: 0, byteCount: 130048, seekOffset: 0
00703243 00000003 (2019-05-19 10:22:22.543000)  TranslatedDisk::onFread - all 130048 bytes transfered
00703336 00000093 (2019-05-19 10:22:22.635307)

00703337 00000001 (2019-05-19 10:22:22.636907)  handleAcsiCommand: 3f a0 43 45 03 3f 00 00 94 00 00 00 00 00 isIcd
00703339 00000002 (2019-05-19 10:22:22.638511)  handleAcsiCommand - CE specific command - module: 03
00703340 00000001 (2019-05-19 10:22:22.640233)  TranslatedDisk function - GEMDOS_Fread (3f)
00703342 00000002 (2019-05-19 10:22:22.641906)  TranslatedDisk::onFread - atariHandle: 0, byteCount: 37888, seekOffset: 0
00703344 00000002 (2019-05-19 10:22:22.643754)  TranslatedDisk::onFread - all 37888 bytes transfered
00703374 00000030 (2019-05-19 10:22:22.674286)

00703376 00000002 (2019-05-19 10:22:22.675653)  handleAcsiCommand: 3f a0 43 45 03 3f 00 00 02 00 00 00 00 00 isIcd
00703378 00000002 (2019-05-19 10:22:22.677515)  handleAcsiCommand - CE specific command - module: 03
00703379 00000001 (2019-05-19 10:22:22.679100)  TranslatedDisk function - GEMDOS_Fread (3f)
00703381 00000002 (2019-05-19 10:22:22.680850)  TranslatedDisk::onFread - atariHandle: 0, byteCount: 512, seekOffset: 0
00703383 00000002 (2019-05-19 10:22:22.682607)  TranslatedDisk::onFread - only 112 bytes out of 512 bytes transfered
00703387 00000004 (2019-05-19 10:22:22.686603)

00703388 00000001 (2019-05-19 10:22:22.688134)  handleAcsiCommand: 20 43 45 03 63 00
00703390 00000002 (2019-05-19 10:22:22.689866)  handleAcsiCommand - CE specific command - module: 03
00703392 00000002 (2019-05-19 10:22:22.691477)  TranslatedDisk function - GD_CUSTOM_getRWdataCnt (63)
00703396 00000004 (2019-05-19 10:22:22.695416)

00703397 00000001 (2019-05-19 10:22:22.697169)  handleAcsiCommand: 20 43 45 03 3e 00
00703399 00000002 (2019-05-19 10:22:22.698808)  handleAcsiCommand - CE specific command - module: 03
00703399 00000000 (2019-05-19 10:22:22.699098)  TranslatedDisk function - GEMDOS_Fclose (3e)
00703400 00000001 (2019-05-19 10:22:22.699491)  TranslatedDisk::onFclose - closing handle 0 (index 0)
00703403 00000003 (2019-05-19 10:22:22.702701)

00703404 00000001 (2019-05-19 10:22:22.704225)  handleAcsiCommand: 20 43 45 03 3d 00
00703405 00000001 (2019-05-19 10:22:22.704512)  handleAcsiCommand - CE specific command - module: 03
00703405 00000000 (2019-05-19 10:22:22.704701)  TranslatedDisk function - GEMDOS_Fopen (3d)
00703406 00000001 (2019-05-19 10:22:22.705945)  TranslatedDisk::createFullAtariPath - without drive letter, relative path : CXTEST2.DAT => /A/CXTEST2.DAT
00703406 00000000 (2019-05-19 10:22:22.706268)  TranslatedDisk::createFullHostPath - dirTranslator.shortToLongPath -- root: /mnt/shared, inFullAtariPath: /A/CXTEST2.DAT -> partialLongHostPath: A/CXTEST2.DAT
00703407 00000001 (2019-05-19 10:22:22.706482)  TranslatedDisk::isDriveIndexReadOnly -- drive index: 13 -> not READ ONLY 
00703411 00000004 (2019-05-19 10:22:22.710489)  TranslatedDisk::onFopen - /mnt/shared/A/CXTEST2.DAT - success, index is 0
00703414 00000003 (2019-05-19 10:22:22.714173)

00703416 00000002 (2019-05-19 10:22:22.715787)  handleAcsiCommand: 20 43 45 03 65 00
00703417 00000001 (2019-05-19 10:22:22.717151)  handleAcsiCommand - CE specific command - module: 03
00703419 00000002 (2019-05-19 10:22:22.718691)  TranslatedDisk function - GD_CUSTOM_getBytesToEOF (65)
00703422 00000003 (2019-05-19 10:22:22.721490)  TranslatedDisk::getByteCountToEndOfFile - for atari handle 0 - there are 168048 bytes until the end of file
00703427 00000005 (2019-05-19 10:22:22.726613)

00703428 00000001 (2019-05-19 10:22:22.727946)  handleAcsiCommand: 3f a0 43 45 03 3f 00 00 02 00 00 00 00 00 isIcd
00703430 00000002 (2019-05-19 10:22:22.729705)  handleAcsiCommand - CE specific command - module: 03
00703431 00000001 (2019-05-19 10:22:22.731087)  TranslatedDisk function - GEMDOS_Fread (3f)
00703433 00000002 (2019-05-19 10:22:22.732669)  TranslatedDisk::onFread - atariHandle: 0, byteCount: 512, seekOffset: 0
00703433 00000000 (2019-05-19 10:22:22.732969)  TranslatedDisk::onFread - all 512 bytes transfered
00703437 00000004 (2019-05-19 10:22:22.737203)

00703439 00000002 (2019-05-19 10:22:22.738731)  handleAcsiCommand: 3f a0 43 45 03 3f 00 01 fc 00 ff 00 00 00 isIcd
00703440 00000001 (2019-05-19 10:22:22.740234)  handleAcsiCommand - CE specific command - module: 03
00703441 00000001 (2019-05-19 10:22:22.740511)  TranslatedDisk function - GEMDOS_Fread (3f)
00703441 00000000 (2019-05-19 10:22:22.740699)  TranslatedDisk::onFread - atariHandle: 0, byteCount: 130048, seekOffset: -1
00703442 00000001 (2019-05-19 10:22:22.741804)  TranslatedDisk::onFread - all 130048 bytes transfered
00703543 00000101 (2019-05-19 10:22:22.842466)

00703544 00000001 (2019-05-19 10:22:22.843845)  handleAcsiCommand: 3f a0 43 45 03 3f 00 00 92 00 ff 00 00 00 isIcd
00703546 00000002 (2019-05-19 10:22:22.845446)  handleAcsiCommand - CE specific command - module: 03
00703547 00000001 (2019-05-19 10:22:22.846815)  TranslatedDisk function - GEMDOS_Fread (3f)
00703549 00000002 (2019-05-19 10:22:22.848373)  TranslatedDisk::onFread - atariHandle: 0, byteCount: 37376, seekOffset: -1
00703550 00000001 (2019-05-19 10:22:22.850215)  TranslatedDisk::onFread - all 37376 bytes transfered
00703578 00000028 (2019-05-19 10:22:22.878185)  FW: Hans,  2017-04-13, LED is: 255, XI: 0x22
00703581 00000003 (2019-05-19 10:22:22.880808)

00703583 00000002 (2019-05-19 10:22:22.882478)  handleAcsiCommand: 3f a0 43 45 03 3f 00 00 02 00 00 00 00 00 isIcd
00703584 00000001 (2019-05-19 10:22:22.883868)  handleAcsiCommand - CE specific command - module: 03
00703586 00000002 (2019-05-19 10:22:22.885430)  TranslatedDisk function - GEMDOS_Fread (3f)
00703587 00000001 (2019-05-19 10:22:22.886762)  TranslatedDisk::onFread - atariHandle: 0, byteCount: 512, seekOffset: 0
00703589 00000002 (2019-05-19 10:22:22.888350)  TranslatedDisk::onFread - only 114 bytes out of 512 bytes transfered
00703593 00000004 (2019-05-19 10:22:22.893021)

00703595 00000002 (2019-05-19 10:22:22.894616)  handleAcsiCommand: 20 43 45 03 63 00
00703596 00000001 (2019-05-19 10:22:22.895983)  handleAcsiCommand - CE specific command - module: 03
00703598 00000002 (2019-05-19 10:22:22.897573)  TranslatedDisk function - GD_CUSTOM_getRWdataCnt (63)
00703602 00000004 (2019-05-19 10:22:22.901314)

00703603 00000001 (2019-05-19 10:22:22.902855)  handleAcsiCommand: 20 43 45 03 3e 00
00703603 00000000 (2019-05-19 10:22:22.903135)  handleAcsiCommand - CE specific command - module: 03
00703604 00000001 (2019-05-19 10:22:22.903324)  TranslatedDisk function - GEMDOS_Fclose (3e)
00703604 00000000 (2019-05-19 10:22:22.903577)  TranslatedDisk::onFclose - closing handle 0 (index 0)

I'll try to take a look sometime today although no promises -- if there is a bug in the atari driver, I will find it but if it goes deeper into that Pexec() / fake disk image emulation, I'm at lost.

@mikrosk mikrosk closed this in af0f8f1 May 19, 2019

@mikrosk

This comment has been minimized.

Copy link
Collaborator Author

commented May 19, 2019

Good news, everyone! It was easier than I thought. I'm attaching a fixed ce_dd.prg as it is a critical update.

ce_dd.prg.zip

@d-hedberg

This comment has been minimized.

Copy link

commented May 19, 2019

Well done! Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.