{"action":"created","issue":{"url":"https://api.github.com/repos/hercules-390/hyperion/issues/107","repository_url":"https://api.github.com/repos/hercules-390/hyperion","labels_url":"https://api.github.com/repos/hercules-390/hyperion/issues/107/labels{/name}","comments_url":"https://api.github.com/repos/hercules-390/hyperion/issues/107/comments","events_url":"https://api.github.com/repos/hercules-390/hyperion/issues/107/events","html_url":"https://github.com/hercules-390/hyperion/issues/107","id":153101017,"number":107,"title":"SCSI error in function read_tape(): Invalid argument - ","user":{"login":"kensmyth","id":18289881,"avatar_url":"https://avatars.githubusercontent.com/u/18289881?v=3","gravatar_id":"","url":"https://api.github.com/users/kensmyth","html_url":"https://github.com/kensmyth","followers_url":"https://api.github.com/users/kensmyth/followers","following_url":"https://api.github.com/users/kensmyth/following{/other_user}","gists_url":"https://api.github.com/users/kensmyth/gists{/gist_id}","starred_url":"https://api.github.com/users/kensmyth/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kensmyth/subscriptions","organizations_url":"https://api.github.com/users/kensmyth/orgs","repos_url":"https://api.github.com/users/kensmyth/repos","events_url":"https://api.github.com/users/kensmyth/events{/privacy}","received_events_url":"https://api.github.com/users/kensmyth/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/hercules-390/hyperion/labels/In%20progress...","name":"In progress...","color":"FF9933"},{"url":"https://api.github.com/repos/hercules-390/hyperion/labels/Question","name":"Question","color":"00B85C"},{"url":"https://api.github.com/repos/hercules-390/hyperion/labels/Researching...","name":"Researching...","color":"FFCC99"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":17,"created_at":"2016-05-04T19:57:33Z","updated_at":"2016-05-17T06:50:49Z","closed_at":null,"body":"This is related to the fix applied for  SCSI error HHC00205E for each SCSI drive #97 \r\n------------------------------------------------------------------------------------------------------------\r\nBuilt the modified version but hit another problem. The SCSI errors HHC00205E are gone, but now seeing `type scsi: error in function read_tape(): Invalid argument` Please see below:\r\n\r\n(status of tape drives from linux before starting Herc:)\r\n\r\n```\r\nroot@debian8:/home/ken/hyp/hyperion-master# mt -f /dev/nst0 status\r\nSCSI 2 tape drive:\r\nFile number=0, block number=0, partition=0.\r\nTape block size 0 bytes. Density code 0x42 (LTO-2).\r\nSoft error count since last status=0\r\nGeneral status bits on (41010000):\r\nBOT ONLINE IM_REP_EN\r\n\r\nroot@debian8:/home/ken/hyp/hyperion-master# mt -f /dev/nst1 status\r\nSCSI 2 tape drive:\r\nFile number=0, block number=0, partition=0.\r\nTape block size 0 bytes. Density code 0x42 (LTO-2).\r\nSoft error count since last status=0\r\nGeneral status bits on (41010000):\r\nBOT ONLINE IM_REP_EN\r\n\r\nroot@debian8:/home/ken/hyp/hyperion-master# mt -f /dev/nst2 status\r\nSCSI 2 tape drive:\r\nFile number=0, block number=0, partition=0.\r\nTape block size 0 bytes. Density code 0x3 (GCR (6250 bpi)).\r\nSoft error count since last status=0\r\nGeneral status bits on (41810000):\r\nBOT ONLINE D_6250 IM_REP_EN\r\nroot@debian8:/home/ken/hyp/hyperion-master#\r\n```\r\n\r\n(Hercules log):\r\n\r\n```\r\nroot@debian8:/home/ken/hyp/hyperion-master# ./hercules -f config1\r\nHHC01413I Hercules version 4.0\r\nHHC01414I (C) Copyright 1999-2015 by Roger Bowler, Jan Jaeger, and others\r\nHHC01415I Build date: May 3 2016 at 13:44:54\r\nHHC01417I Built with: GCC 4.9.2\r\nHHC01417I Build type: GNU/Linux x86_64 host architecture build\r\nHHC01417I Modes: S/370 ESA/390 z/Arch\r\nHHC01417I Max CPU Engines: 8\r\nHHC01417I Using setresuid() for setting privileges\r\nHHC01417I Using POSIX threads Threading Model\r\nHHC01417I Using Error-Checking Mutex Locking Model\r\nHHC01417I With Syncio support\r\nHHC01417I With Shared Devices support\r\nHHC01417I With Dynamic loading support\r\nHHC01417I Using shared libraries\r\nHHC01417I With External GUI support\r\nHHC01417I With IPV6 support\r\nHHC01417I With HTTP Server support\r\nHHC01417I With sqrtl support\r\nHHC01417I With SIGABEND handler\r\nHHC01417I Without CCKD BZIP2 support\r\nHHC01417I Without HET BZIP2 support\r\nHHC01417I With ZLIB support\r\nHHC01417I With Regular Expressions support\r\nHHC01417I Without Object REXX support\r\nHHC01417I Without Regina REXX support\r\nHHC01417I With Automatic Operator support\r\nHHC01417I Without National Language Support\r\nHHC01417I Machine dependent assists: cmpxchg1 cmpxchg4 cmpxchg8 hatomics=C11\r\nHHC01417I Running on: debian8 (Linux-3.16.0-4-amd64 x86_64) MP=4\r\nHHC01508I HDL: loadable module directory is /usr/local/lib/hercules\r\nHHC00100I Thread id 00007f8d7e808700, prio 15, name Processor CP00 started\r\nHHC00811I Processor CP00: architecture mode z/Arch\r\nHHC00100I Thread id 00007f8d7e707700, prio -20, name Timer started\r\nHHC02204I cpuserial set to 000611\r\nHHC02204I cpumodel set to 3033\r\nHHC17003I MAIN storage is 16M (mainsize); storage is not locked\r\nHHC17003I EXPANDED storage is 0 (xpndsize); storage is not locked\r\nHHC02204I port set to port=8038 noauth\r\nHHC01801E HTTP server: invalid root directory: HTTP/: No such file or directory\r\nHHC02204I root set to HTTP/\r\nHHC01807I HTTP server signaled to start\r\nHHC02204I numcpu set to 1\r\nHHC02204I maxcpu set to 1\r\nHHC02204I tzoffset set to -0500\r\nHHC00811I Processor CP00: architecture mode S/370\r\nHHC02204I archmode set to S/370\r\nHHC00100I Thread id 00007f8d7ea0b700, prio 4, name HTTP server started\r\nHHC01801E HTTP server: invalid root directory: HTTP/: No such file or directory\r\nHHC02204I scsimount set to YES\r\nHHC00101I Thread id 00007f8d7ea0b700, prio 4, name HTTP server ended\r\nHHC01200E 0:000C Card: error in function access(): No such file or directory\r\nHHC01463E 0:000C device initialization failed\r\nHHC00221I 0:0480 Tape file /dev/nst2, type scsi: format type SCSI attached tape drive\r\nHHC00222I 0:0480 Tape file /dev/nst2, type scsi: option --online accepted\r\nHHC00222I 0:0480 Tape file /dev/nst2, type scsi: option -d accepted\r\nHHC00100I Thread id 00007f8d7ea0b700, prio 2147483647, name SCSI-TAPE mount monitor started\r\nHHC00221I 0:0481 Tape file /dev/nst1, type scsi: format type SCSI attached tape drive\r\nHHC00222I 0:0481 Tape file /dev/nst1, type scsi: option --online accepted\r\nHHC00222I 0:0481 Tape file /dev/nst1, type scsi: option -d accepted\r\nHHC00221I 0:0482 Tape file /dev/nst0, type scsi: format type SCSI attached tape drive\r\nHHC00222I 0:0482 Tape file /dev/nst0, type scsi: option --online accepted\r\nHHC00222I 0:0482 Tape file /dev/nst0, type scsi: option -d accepted\r\nHHC00100I Thread id 00007f8d7e90a700, prio 4, name Console connection started\r\nHHC01024I Waiting for console connections on port 3270\r\nHHC00414I 0:0152 CKD file dasd/hasp00.152: cyls 411 heads 19 tracks 7809 trklen 13312\r\n:\r\nHHC00414I 0:0190 CKD file dasd/work03.190: cyls 1114 heads 15 tracks 16710 trklen 56832\r\nHHC00100I Thread id 00007f8d81a69700, prio 0, name Control panel started\r\n:\r\nHHC01603I scsimount\r\nHHC02203I scsimount : 5\r\nHHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2\r\nHHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1\r\nHHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0\r\n```\r\n\r\n```\r\n/15.06.15 LGN001I TSO logon in progress at VTAM terminal CUU0C0\r\n/15.06.17 TSU 41 $HASP100 HERC01 ON TSOINRDR\r\n/15.06.17 TSU 41 $HASP373 HERC01 STARTED\r\n/15.06.17 TSU 41 IEF125I HERC01 - LOGGED ON - TIME=15.06.17\r\n/15.06.50 JOB 80 $HASP100 HERC01TT ON INTRDR\r\n/15.06.50 JOB 80 $HASP373 HERC01TT STARTED - INIT 1 - CLASS A - SYS TK4-\r\n/15.06.50 JOB 80 IEF403I HERC01TT - STARTED - TIME=15.06.50\r\n```\r\n\r\n(job HERC01TT wants to allocate drives 481 & 482)\r\n\r\n```\r\nHHC00205E 0:0480 Tape file /dev/nst2, type scsi: error in function read_tape(): Invalid argument\r\n/15.06.50 JOB 80 IEF503I INCORRECT VOLUME LABEL OR I/O ERROR\r\n/15.06.50 JOB 80 IEF234E D 480\r\n```\r\n\r\n&nbsp;\r\n(drive 480 gets checked and tape dismounted but 480 is not requested by job HERC01TT !?)\r\n\r\n```\r\nHHC01603I scsimount\r\nHHC02203I scsimount : 5\r\nHHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2\r\nHHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1\r\nHHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0\r\nHHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function read_tape(): Invalid argument\r\n```\r\n\r\n```\r\n/15.07.07 JOB 80 IEF503I INCORRECT VOLUME LABEL OR I/O ERROR\r\n/15.07.07 JOB 80 IEF234E D 481\r\nHHC00205E 0:0482 Tape file /dev/nst0, type scsi: error in function read_tape(): Invalid argument\r\n/15.07.15 JOB 80 IEF503I INCORRECT VOLUME LABEL OR I/O ERROR\r\n/15.07.15 JOB 80 IEF234E D 482\r\n/15.07.21 JOB 80 *IEC501A M 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE\r\n```\r\n\r\n(MVS tries to check the tape labels and decides they are not correct (probably b/c scsi read error, then dismounts them))\r\n\r\n```\r\nHHC01603I scsimount\r\nHHC02203I scsimount : 5\r\nHHC02275I SCSI auto-mount: thread IS active for drive 0:0480 = /dev/nst2\r\nHHC02275I SCSI auto-mount: thread IS active for drive 0:0481 = /dev/nst1\r\nHHC02275I SCSI auto-mount: thread IS active for drive 0:0482 = /dev/nst0\r\n```\r\n\r\n(after tapes are reloaded and ready)\r\n\r\n```\r\nHHC92702D Tape /dev/nst2: finish_scsitape_open mt_gstat 0x41810000 BOT ONLINE D_6250 IM_REP_EN\r\nHHC92702D Tape /dev/nst1: finish_scsitape_open mt_gstat 0x41010000 BOT ONLINE IM_REP_EN\r\nHHC00205E 0:0481 Tape file /dev/nst1, type scsi: error in function read_tape(): Invalid argument\r\n/15.08.54 JOB 80 IEC512I LBL ERR 481, ,NL,SL0690,SL,HERC01TT,GENERATE\r\n/15.08.56 JOB 80 *IEC704A L 481,SL0690,SL,6250 BPI,HERC01TT,GENERATE\r\n/15.08.56 JOB 80 *00 IEC704A REPLY 'VOLSER,OWNER INFORMATION','M'OR'U'\r\nHHC92702D Tape /dev/nst0: finish_scsitape_open mt_gstat 0x41010000 BOT ONLINE IM_REP_EN\r\n```\r\n\r\n(nothing else happens)\r\n\r\n```\r\nHHC01603I scsimount\r\nHHC02203I scsimount : 5\r\nHHC02275I SCSI auto-mount: thread is NOT active for drive 0:0480 = /dev/nst2\r\nHHC02275I SCSI auto-mount: thread is NOT active for drive 0:0481 = /dev/nst1\r\nHHC02275I SCSI auto-mount: thread is NOT active for drive 0:0482 = /dev/nst0\r\nHHC01603I stop\r\nHHC00834I Processor CP00: manual state selected\r\n```\r\n\r\n(JCL for the job HERC01TT that was running, this normally runs to completion on older Herc 4.00 after timeouts with SCSI errors HHC00205E )\r\n\r\n```\r\n000001 //HERC01TT JOB 'TAPE TEST',CLASS=A,MSGCLASS=X,NOTIFY=HERC01,\r\n000002 // REGION=6M,TIME=1440\r\n000003 //*\r\n000004 //GENERATE EXEC PGM=IEBDG\r\n000005 //SYSPRINT DD SYSOUT=*\r\n000006 //OUTDS DD DISP=(NEW,PASS),DSN=&&TEMP00,\r\n000007 // VOL=SER=SL0690,UNIT=(481,,DEFER),\r\n000008 // DCB=(RECFM=FB,LRECL=256,BLKSIZE=25600)\r\n000009 //SYSIN DD *\r\n000010 DSD OUTPUT=(OUTDS)\r\n000011 FD NAME=FIELD1,LENGTH=256,FORMAT=RA\r\n000012 CREATE QUANTITY=1234567,NAME=(FIELD1)\r\n000013 END\r\n000014 //*\r\n000015 //TAPECOPY EXEC PGM=IEBGENER\r\n000016 //SYSIN DD DUMMY\r\n000017 //SYSPRINT DD SYSOUT=*\r\n000018 //SYSUT1 DD DISP=(OLD,PASS),DSN=&&TEMP00,\r\n000019 // VOL=SER=SL0690,UNIT=481\r\n000020 //SYSUT2 DD DISP=(NEW,PASS),DSN=&&TEMP01,\r\n000021 // VOL=SER=SL0691,UNIT=482\r\n000022 //*\r\n000023 //COMPARE EXEC PGM=IEBCOMPR\r\n000024 //SYSIN DD DUMMY\r\n000025 //SYSPRINT DD SYSOUT=*\r\n000026 //SYSUT1 DD DISP=(OLD,DELETE),DSN=&&TEMP00,\r\n000027 // VOL=SER=SL0690,UNIT=481\r\n000028 //SYSUT2 DD DISP=(OLD,DELETE),DSN=&&TEMP01,\r\n000029 // VOL=SER=SL0691,UNIT=482\r\n000030 //\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/hercules-390/hyperion/issues/comments/219633881","html_url":"https://github.com/hercules-390/hyperion/issues/107#issuecomment-219633881","issue_url":"https://api.github.com/repos/hercules-390/hyperion/issues/107","id":219633881,"user":{"login":"Fish-Git","id":1486786,"avatar_url":"https://avatars.githubusercontent.com/u/1486786?v=3","gravatar_id":"","url":"https://api.github.com/users/Fish-Git","html_url":"https://github.com/Fish-Git","followers_url":"https://api.github.com/users/Fish-Git/followers","following_url":"https://api.github.com/users/Fish-Git/following{/other_user}","gists_url":"https://api.github.com/users/Fish-Git/gists{/gist_id}","starred_url":"https://api.github.com/users/Fish-Git/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Fish-Git/subscriptions","organizations_url":"https://api.github.com/users/Fish-Git/orgs","repos_url":"https://api.github.com/users/Fish-Git/repos","events_url":"https://api.github.com/users/Fish-Git/events{/privacy}","received_events_url":"https://api.github.com/users/Fish-Git/received_events","type":"User","site_admin":false},"created_at":"2016-05-17T06:50:48Z","updated_at":"2016-05-17T06:50:48Z","body":"> HHC01415I Built on Feb 5 2015 at 16:48:19\r\n\r\nWhich tells me you did not do as I asked.\r\n\r\nI don't want you to perform your test using whatever version you happened to still have that happens to have been  _Built_ on Feb 5 2015. I want you to build a new version, **_today_**, but using Hyperion _source code_ from Feb 5 2015.\r\n\r\nIn other words pull or clone or whatever the Nix command is to extract the Hyperion source code from Feb 5 2015 and then build that. _Today_. I want to see on the Hercules log that Hyperion was built _today_. I want to see:\r\n\r\nHHC01415I Built on **May 16 2016** at ...\r\n\r\nIt would also help to enable CCW tracing on all drives too:\r\n\r\n    t+480\r\n    t+481\r\n    t+482\r\n\r\nBasically what I'm getting at here is that I'm not convinced that your \"Built on Feb 5 2015\" version is actually the Feb 5 2015 version of Hyperion. I suspect it is a much older (pre-Sep 2013) version of Hyperion that just happened to have been _built_ on Feb 5 2015.\r\n\r\nThe reason I suspect that is because, as I explained, it was at that time that `MAX_BLKLEN ` was changed to 2MB, which is what's causing your `invalid argument` error. Thus _every_ version of Hyperion -- _after Sep 2013_ -- should cause the same invalid argument error.\r\n\r\nOnly versions of Hyperion _before_ Sep 2013 should run correctly.\r\n\r\nThus your \"Feb 2015\" version should also be getting `invalid argument`. Since it doesn't however (as you have shown), that is telling me that things are not as they seem. That is telling me that your \"_Built on_ Feb 2015\" version is actually a version that was built using source code from _before_ Sep 2013.\r\n\r\nYes, it was _built on_ Feb 2015, but we don't know with any certainty what actual source code was used. My conjecture is that pre-Sep 2013 source code was used. I mean, I could just as easily use Hyperion source code from 2001 and build it _today_, so that the \"Built on\" date appears with today's date. Thus the \"Built on\" date doesn't tell us much and thus I'm not trusting the \"Built on Feb 2015\" message since I can't be sure what source code was used to build Hyperion on that particular date.\r\n\r\nI am strongly suspecting your \"Built on Feb 2015\" version is actually a much older version. If it was actually a Feb 2015 version of Hyperion built on that same day, then it _should_ be getting the same `invalid argument` error we are seeing today. The fact that it's not is proof to me that things are not as they seem.\r\n\r\nNow since Hyperion doesn't yet include the git commit hash in its version string, we still can't trust the \"Built on\" date to tell us anything definitive, but I'm trusting you Ken. I'm trusting you to be competent enough to be able to do as I ask. I'm trusting you to be able to pull the Hyperion source code _from Feb 2015_ and build and tun your same test using that.\r\n\r\nAs I stated in my previous reply, I strongly suspect it too will encounter the same `invalid argument` error once it gets past the scsimount problem.\r\n\r\nFYI: I'm still looking into how best to fix the current `invalid argument` error, so that problem will be fixed before too long too. Once it is, you should be good to go.\r\n\r\nBut your claim that your job ran fine using the Feb 2015 version of Hyperion is simply not believable. Something else very strange is going on and I very much want to understand what it is. I very much want to solve this mystery. I want to understand what's going on.\r\n\r\nWill you help me?\r\n\r\nPlease?\r\n"}}