HCPERP513I for DASD 0A82 CCW X'92'

When IPL-ing a 2nd level z/OS (&SYSVER.=Z25B ) under z/VM (7.2 as well as 7.3), after a few minutes z/VM produces these two groups of messages, with about 30 seconds in between:

 11:32:32 HCPERP513I  DASD  0A82 AN OPERATION WAS TERMINATED BECAUSE A FILE
 11:32:32 HCPERP513I  PROTECT ERROR OCCURRED
 11:32:32 HCPERP6300I SENSE DATA FORMAT = 00       MSG CODE = 00
 11:32:32 HCPERP6301I CHANNEL COMMAND WORD COMMAND CODE = 92
 11:32:32 HCPERP6302I SEEK ADDRESS =   000014180003
 11:32:32 HCPERP6303I SENSE = 00040000 00FFFF00 00000000 00000000 00000000
 11:32:32 HCPERP6303I 00000000 00000080 00141803
 11:32:32 HCPERP6304I IRB = 00C24017 2FEEE5A0 0E400008 00800000
 11:32:32 HCPERP6305I USERID = TEL1
 11:32:32 HCPERP2216I CHANNEL PATH ID = 0A
 11:32:58 HCPERP513I  DASD  0A82 AN OPERATION WAS TERMINATED BECAUSE A FILE
 11:32:58 HCPERP513I  PROTECT ERROR OCCURRED
 11:32:58 HCPERP6300I SENSE DATA FORMAT = 00       MSG CODE = 00
 11:32:58 HCPERP6301I CHANNEL COMMAND WORD COMMAND CODE = 92
 11:32:58 HCPERP6302I SEEK ADDRESS =   0000007F0007
 11:32:58 HCPERP6303I SENSE = 00040000 00FFFF00 00000000 00000000 00000000
 11:32:58 HCPERP6303I 00000000 00000080 00007F07
 11:32:58 HCPERP6304I IRB = 00C24017 0FD585B0 0E400008 00800000
 11:32:58 HCPERP6305I USERID = TEL1
 11:32:58 HCPERP2216I CHANNEL PATH ID = 0A

This started happening after closing Issues #572 and #575 in July 2023, which involved corrections in ckddasd.c. Prior to that, these messages never appeared. However, other than these messages now appearing, no related anomalies are seen.

DASD 0A82 is VOL=SER=B5SYS1

Cheers,

Peter

Peter (@Peter-J-Jansen),

Apologies for taking so long to find the time to look into this issue of yours!

I agree that the fact that your reported File Protect errors were not occurring before GitHub Issues #572 and #575 were closed whereas now they are occurring is definitely suspicious and smacks of (points to) an unintended bug having been introduced by one of them, so I would like to begin looking into the cause.

First question: You said the messages begin to appear "after a few minutes". Can you be more specific? Is it 5 minutes after IPLing your z/OS second-level guest? 10 minutes? I would like to try and reproduce the problem for myself by IPLing z/OS 2.5A or 2.5C (those are the only ones I have) under z/VM 7.3, and I would like to know how long I have to wait before the messages begin appearing.

Also, I presume your z/OS guest is sitting mostly idle during this time? Or are you actively using it, and if so, can you remember what you were doing on z/OS when these messages began appearing?

Finally, how do you have your z/OS dasds defined to z/VM? (i.e. in the VM directory) Are they dedicated dasds? Or are they full pack minidisks? In my experience z/VM behaves quite differently when a guest's dasds are defined as minidisks as opposed to being dedicated, so if I am going to try and reproduce your problem, I need to know!

And since we're on the subject, have YOU tried defining your guest's dasds as e.g. dedicated instead of presumably minidisks yet? Does the problem still occur when you do that? Or does the problem go away? This is also important to know since one way points to a problem(?) with z/VM whereas the other way points to a problem with Hercules.

IN SUMMARY:

How many minutes is "after a few minutes"?
Were you doing anything in z/OS or was it sitting idle? What were you doing?
How are z/OS's dasds defined? As minidisks? Or as DEDICATED (i.e. attached) dasds?
(OPTIONAL) I would appreciate it if you could try defining your z/OS dasds differently so we can see whether the "problem" still occurs or not. This is optional as I will probably perform this test myself. But if you can do it quicker, it would be appreciated!

Thanks!

And sorry again for taking so long getting around to looking into this matter. I've been very busy and a lot has been going on in my life! I'm sure you understand.

Dear Fish,

Thanks for your follow-up! I hadn't forgotten about this issue, but in the meantime this problem got a lot worse, in that even IPL-ing just z/VM (both 7.2 or 7.3), similar such messages were being produced, that is even without IPL-ing z/OS 2nd level under it. This was around the time some more changes to ckddasd.c were happening.

Perhaps, I then thought, some CKD CCW problems in the past, somehow could have corrupted my DASD's, both z/OS and z/VM. After unsuccessfully trying out older DASD backups, I then made a decision a number of weeks ago, that I wanted to re-rig my systems from scratch. And to be sure, I wanted to do it using zPDT, so that the chances for corrupted DASD's would be minimal. I hope.

And just today, I finished that task. I have freshly set up DASD for some z/VM and z/OS systems, so far untouched by Hercules. I've just backed these up, so the next days I'll produce CCKD64 compressed ones, with shadowing, the root ones read-only. Only that way can I trust my Hercules tests.

By now, thanks to the efforts, including yours, to finalize some outstanding ckddasd.c work, I would not be surprised that this problem of mine has gone away. I'll let you know as soon as I've been able to run my Hercules tests.

Nevertheless, to answers your questions :

About 3 minutes
z/OS was just IPL-ing
All DASD were ATTached
I will try LINKing them and let you know, but that will take some time

Cheers,

Peter

Just to be clear, the reported problem was occurring when you were IPLing z/OS under z/VM under Hercules, yes? (i.e. NOT z/OS under z/VM under z/VM under Hercules, correct?)

FYI: I just tried my z/OS 2.c under z/VM 7.3 under Hercules, and it appears to work just fine. I let it sit there for a good 30 minutes, and received no unusual messages on the VM console.

One thing I noticed, in my personal notes for z/VM 7.3, I have:

04/14/2023: Successfully applied 2301 service from Jürgen!

I presume you have applied it to your z/VM 7.3 too?

I will try z/VM 7.2 next.

Peter (@Peter-J-Jansen),

I also forgot to ask you, when this problem occurs, do any messages also appear on the Hercules console?

It appears VM is reporting that "File Protect" errors are occurring (on dasd 0A82):

 11:32:32 HCPERP513I  DASD  0A82 AN OPERATION WAS TERMINATED BECAUSE A FILE
 11:32:32 HCPERP513I  PROTECT ERROR OCCURRED
 11:32:32 HCPERP6300I SENSE DATA FORMAT = 00       MSG CODE = 00
 11:32:32 HCPERP6301I CHANNEL COMMAND WORD COMMAND CODE = 92
 11:32:32 HCPERP6302I SEEK ADDRESS =   000014180003
 11:32:32 HCPERP6303I SENSE = 00040000 00FFFF00 00000000 00000000 00000000
 11:32:32 HCPERP6303I 00000000 00000080 00141803
 11:32:32 HCPERP6304I IRB = 00C24017 2FEEE5A0 0E400008 00800000
 11:32:32 HCPERP6305I USERID = TEL1
 11:32:32 HCPERP2216I CHANNEL PATH ID = 0A
 11:32:58 HCPERP513I  DASD  0A82 AN OPERATION WAS TERMINATED BECAUSE A FILE
 11:32:58 HCPERP513I  PROTECT ERROR OCCURRED
 11:32:58 HCPERP6300I SENSE DATA FORMAT = 00       MSG CODE = 00
 11:32:58 HCPERP6301I CHANNEL COMMAND WORD COMMAND CODE = 92
 11:32:58 HCPERP6302I SEEK ADDRESS =   0000007F0007
 11:32:58 HCPERP6303I SENSE = 00040000 00FFFF00 00000000 00000000 00000000
 11:32:58 HCPERP6303I 00000000 00000080 00007F07
 11:32:58 HCPERP6304I IRB = 00C24017 0FD585B0 0E400008 00800000
 11:32:58 HCPERP6305I USERID = TEL1
 11:32:58 HCPERP2216I CHANNEL PATH ID = 0A

If these I/O errors are being thrown by Hercules (due to a Hercules bug), then there should be some associated error messages appearing on the Hercules console as well! Otherwise (if there are no messages on the Hercules console), then the errors are being detected and thrown by VM itself.

Are there any error messages appearing on the Hercules console? If so, may I see your Hercules log file please?

I am unable to reproduce this issue! :(

Am I mistaken regarding the "level" at which they are occurring? Are you maybe running z/OS under a second-level z/VM? (i.e. Hercules --> z/VM --> z/VM --> z/OS?)

I've been testing z/OS under z/VM under Hercules (i.e. Hercules --> z/VM --> z/OS), and I am not seeing any problem.

Did you maybe forget to apply that VM service I mentioned in my earlier comment?

Fish,

Answering your latest questions: (1) I only experienced these messages on the VM OPERATOR console, so it was indeed VM discovering the errors. (2) It was purely z/OS being IPL'd 2nd level, i.e. Hercules --> z/VM --> z/OS. z/VM had the same service applied you had, 2301 for z/VM 7.3 (and actually 2201 for z/VM 7.2).

I'm still working on setting up my tests. But your question re. a 3rd level z/OS is quite interesting, and I will try that as well. Has anyone ever tried z/OS 3rd level? (i.e. Hercules --> z/VM --> z/VM --> z/OS)

Somehow, I suspect that as soon as I've readied my test setups under Hercules (I'm still under zPDT right now), I'll most probably discover that I too can't reproduce my problem, so perhaps it's easier to just wait a little until I'm in a position to do my testing under Hercules.

Thanks for all your kind help Fish!

Cheers,

Peter

Has anyone ever tried z/OS 3rd level? (i.e. Hercules --> z/VM --> z/VM --> z/OS)

I might have, but I can't remember for certain. I remember that I managed to get my existing z/VM system to IPL 2nd-level under itself (see issue #572: "z/VM 7.2 IPL'ing as guest of itself CCW Command Rejects Aaron says quick fix") which was an interesting hard fought effort, but I cannot remember whether or not I tried IPLing z/OS beneath that 2nd-level z/VM or not. I think maybe I did, but I honestly cannot remember.

I still have my shadow files for that effort however, so I'm sure I could give it a try. (As I recall though, I never bothered to try and get networking working, but everything else seemed to work okay, so I should think that wouldn't be a showstopper).

I'd rather not have to expend the effort to give it a try however, if it's not required. And since according to your response, it doesn't appear to be necessary, So I will only try it if you honestly feel it's worth the effort. Is it? Let me know! It's your call! (I might try it anyway just for fun if I find the time!)

I'm hoping you might simply be not be doing something correctly, like forgetting to specify your z/VM's dasds with the Hercules cu=3990-6 option for example? You've made that mistake before! ;-)

I've now been able to re-do my tests with a z/VM and z/OS re-built / configured from scratch under zPDT, thus excluding possible DASD corruptions by Hercules. When IPL-ing both (with z/OS 2nd level obviously) under Hercules (version 4.7.0.11078-SDL-DEV-g79a14889), I still experience this issue.

Next I'll try to collect a Hercules DASD trace in the log, as Aaron suggested already quite some time ago.

Thanks Fish, for your very latest remark concerning the cu=3990-6 option. I had not forgotten that on my DASD-owning Hercules system. But ... I had not included it on the DASD-sharing Hercules systems! In January 2023 that was not a problem, but by now it really is. The problems with this missing cu=3990-6 option on the DASD-sharing Hercules' lead me to the incorrect belief that there was something wrong with the shared.c code, and caused me lots of wasted time. Silly me.

Cheers,

Peter

under Hercules (version 4.7.0.11078-SDL-DEV-g79a14889), I still experience this issue.

Bummer. :(

Next I'll try to collect a Hercules DASD trace in the log, as Aaron suggested already quite some time ago.

Yes, I think that would be our next logical step.

It's odd that I'm not experiencing this problem. I don't understand that. Perhaps your z/VM (or z/VM guest) is configured differently than mine? Or maybe your z/OS itself is configured different than mine? Do you think it might be worthwhile to compare each other's?

But yes, let's look at the CCW trace first. That would be more helpful I think.

OK, I've got a CCW trace of the problem, the interpretation of which is way beyond my understanding of DASD I/O. VM shows these lines on the OPERATOR console :

 10:35:59 HCPERP513I  DASD  0A82 AN OPERATION WAS TERMINATED BECAUSE A FILE
 10:35:59 HCPERP513I  PROTECT ERROR OCCURRED
 10:35:59 HCPERP6300I SENSE DATA FORMAT = 00       MSG CODE = 00
 10:35:59 HCPERP6301I CHANNEL COMMAND WORD COMMAND CODE = 92
 10:35:59 HCPERP6302I SEEK ADDRESS =   000014180003
 10:35:59 HCPERP6303I SENSE = 00040000 00FFFF00 00000000 00000000 00000000
 10:35:59 HCPERP6303I 00000000 00000080 00141803
 10:35:59 HCPERP6304I IRB = 00C24017 7FE615A0 0E400008 00800000
 10:35:59 HCPERP6305I USERID = TEL1
 10:35:59 HCPERP2216I CHANNEL PATH ID = 0A

The Hercules CCW tracing produces these log records, starting with 2 successful X'92' CCW's prior to the 3rd one causing the problem:

10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61010=>14180003 02001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE61298=>00000002 ADAD7000 00000002 ADAD6000 ....[[......[[-.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAD7000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 3 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61018=>14180003 03001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612A0=>00000002 ADAD6000 00000002 ADAD5000 ....[[-.....[[&.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAD6000, len 1000=>00000000 02000002 00000200 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 255 kl 255 dl 65535 of 0
10:35:59 HHC00433I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: MT advance to cyl(5144) head(4)
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61020=>00000000 00000000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0E40, count 0008
10:35:59 HHC01313I 0:0A82 CHAN: sense 00040000 00FFFF00 00000000 00000000 00000000 00000000 00000080 00141803
10:35:59 HHC01314I 0:0A82 CHAN: sense FP 
10:35:59 HHC00806I Processor CP04: I/O interrupt code 00010012 parm 00EC46A8 id 00000000
10:35:59 HHC01317I 0:0A82 CHAN: scsw 00C24017, stat 0E40, count 0008, ccw 7FE615A0
10:35:59 HHC01318I 0:0A82 CHAN: test I/O: cc=0
10:35:59 HHC01334I 0:0A82 CHAN: ORB: IntP:00EC46A8 Key:0 LPM:80 Flags:0C200 ....FP....H. ........ CCW:7FE610B8
10:35:59 HHC01315I 0:0A82 CHAN: ccw 63400010 7FE61088=>40C00000 00000000 14180003 14180003  {..............
10:35:59 HHC01315I 0:0A82 CHAN: ccw 63400010 7FE61088=>40C00000 00000000 14180003 14180003  {..............
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00431I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: seeking to cyl 5144 head 3
10:35:59 HHC01315I 0:0A82 CHAN: ccw 47400010 7FE610A8=>4C000001 14180003 14180003 1F000000 <...............
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation index
10:35:59 HHC00435I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 0 kl 0 dl 8 of 0
10:35:59 HHC00436I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read key 0 bytes
10:35:59 HHC00437I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 8 bytes
10:35:59 HHC00434I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 1 kl 0 dl 4096 of 0
10:35:59 HHC00436I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read key 0 bytes
10:35:59 HHC00437I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC00434I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 2 kl 0 dl 4096 of 0
10:35:59 HHC00436I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read key 0 bytes
10:35:59 HHC00437I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC00434I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 3 kl 0 dl 4096 of 0
10:35:59 HHC00436I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read key 0 bytes
10:35:59 HHC00437I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC00434I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9c634f4700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl

I've kept the complete Hercules log, so please let me know if I should send more of it.

As stated earlier, apart from the VM logging, no other ill effects are noted. This is not to say that SDL-hyperion Hercules 4.7 is totally bug free, as I've experienced other problems, including crashes. These seem unrelated to this issue, and do not always occur.

But perhaps with the above info could lead to solving this issue? Under zPDT, these VM message never appear.

Cheers,

Peter

The Hercules CCW tracing produces these log records, starting with 2 successful X'92' CCW's prior to the 3rd one causing the problem:

Thanks. I'll take a look at them.

This is not to say that SDL-hyperion Hercules 4.7 is totally bug free, as I've experienced other problems, including crashes.

These occasional "crashes" wouldn't happen to be the FRE016 abends described in GitHub Issue #590, would they? Just curious! It could be a clue.

I've kept the complete Hercules log, so please let me know if I should send more of it.

The snippet your provided only shows one occurrence of the error, and unfortunately does not include the Define Extent and Locate Record CCWS that preceded it. I need those. So unfortunately, I'm going to need to see the complete log. Thanks.

OK Fish, no problem. Here is the complete log file:

Hercules_log_435_M1.txt

The excerpt I sent earlier is around record 25700, and can be located by searching for 7FE615A0 (from the VM messages I listed earlier).

Thanks for taking the effort trying to find the root cause!

Cheers,

Peter

OK Fish, no problem. Here is the complete log file:

Thanks. I'll take a look at it.

(question regarding completely unrelated "problem")

I happened to notice the following warning messages in your log related to a recent usleep fix:

02:11:10 HHC00092W Warning in function USLEEP() at ctcadpt.c(3635): rc=0, EINTR retrys count=108
02:11:10 HHC00007I Previous message from function 'herc_usleep' at hscutl.c(653)

It looks like there are a lot of them occurring. (about 50 of them) They don't happen often, but they are happening often enough to be a concern. (Issuing unnecessary warnings only tends to scare our users into believing something is wrong, when in reality it's just a completely normal (but unusual) occurrence.)

Our reporting threshold is currently set to 16:

https://github.com/SDL-Hercules-390/hyperion/blob/ec4102bb67f957a0fd303aa72ac48bec8426f492/hscutl.h#L160

I'm thinking maybe we should increase that to something like 256?

I agree, 16 is way too low, 256 will be better.

Cheers,

Peter

I agree, 16 is way too low, 256 will be better.

Fixed by commit aeb600b8f179bf74acf9e383f1055308260ed920.

FYI:

Regarding your bug: I've found what is happening, but I haven't quite found where or how/why it's happening yet, But nailing it down and getting it fixed should not take me more than a few more days, hopefully.

The gist of it is, a "Read Any" (or "Write Any") Extended Operation should return back to the beginning of the same track, not advance to the next track, but for some odd reason, it sometimes is failing to do that!

Yes, you read that right: it only sometimes doesn't doesn't do that. Other times, it does. That's what I haven't figured out yet. What the conditions are that causes it to sometimes fail, but other times to work correctly.

Take a look at your Hercules log you provided me:

Notice how the I/Os for cyl 5144 head 1 and cyl 5144 head 2 (lines 25492 - 25603 and 25605 - 25716) end normally, successfully reading the counts and data for the entire track (twelve 4096-byte records).

But then the I/O for cyl 5144 head 3 fails, because there are only 3 records on that particular track, not 12.

For some undiscovered reason, ckddasd.c is advancing to the next track, instead of returning back to beginning of the current track like it should be!

It obviously(?) has something to do with reaching end-of-track after the 3rd record instead of after the 12th like the two preceding I/Os, but I haven't found that yet.

But I think I'm very close to nailing it!

But I'm tired right now, and should probably take a quick nap first before attacking it further. Hang loose though! I'm confident I'll have it nailed very soon now! :)

DETAILS:

cyl 5144 head 1:

10:35:59 HHC01334I 0:0A82 CHAN: ORB: IntP:00EC46A8 Key:0 LPM:80 Flags:0C200 ....FP....H. ........ CCW:7FE61560
10:35:59 HHC01315I 0:0A82 CHAN: ccw E7400041 7FE61510=>01800000 00000000 00000000 40C00000 00000000 14180001 14180000 00000000 00000000 00000000 00000000 3F00000D 14180001 00000000 00FF0000 000A0001 ............ {..................................................
10:35:59 HHC00431I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: seeking to cyl 5144 head 1
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation index
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 0 kl 0 dl 8 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw E7400041 7FE61510=>01800000 00000000 00000000 40C00000 00000000 14180001 14180000 00000000 00000000 00000000 00000000 3F00000D 14180001 00000000 00FF0000 000A0001 ............ {..................................................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation count
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 1 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61008=>14180001 01001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE61290=>00000002 ADAF0000 00000002 ADAEF000 ....[.......[.0.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAF0000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 2 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61010=>14180001 02001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE61298=>00000002 ADAEF000 00000002 ADAEE000 ....[.0.....[.\.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAEF000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 3 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61018=>14180001 03001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612A0=>00000002 ADAEE000 00000002 ADAED000 ....[.\.....[.}.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAEE000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 4 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61020=>14180001 04001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612A8=>00000002 ADAED000 00000002 ADAEC000 ....[.}.....[.{.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAED000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 5 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61028=>14180001 05001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612B0=>00000002 ADAEC000 00000002 ADAEB000 ....[.{.....[...
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAEC000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 6 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61030=>14180001 06001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612B8=>00000002 ADAEB000 00000002 ADAEA000 ....[.......[...
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAEB000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 7 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61038=>14180001 07001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612C0=>00000002 ADAEA000 00000002 ADAE9000 ....[.......[...
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAEA000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 8 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61040=>14180001 08001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612C8=>00000002 ADAE9000 00000002 ADAE8000 ....[.......[...
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAE9000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 9 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61048=>14180001 09001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612D0=>00000002 ADAE8000 00000002 ADAE7000 ....[.......[...
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAE8000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 10 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61050=>14180001 0A001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612D8=>00000002 ADAE7000 00000002 ADAE6000 ....[.......[.-.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAE7000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 11 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61058=>14180001 0B001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612E0=>00000002 ADAE6000 00000002 ADAE5000 ....[.-.....[.&.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAE6000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 12 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61060=>14180001 0C001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612E8=>00000002 ADAE5000 00000000 00000000 ....[.&.........
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAE5000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 255 kl 255 dl 65535 of 0
10:35:59 HHC00431I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: seeking to cyl 5144 head 1
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 0 kl 0 dl 8 of 0
10:35:59 HHC00435I Thread 00007f9e1206d700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 1 record 1 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92000008 7FE61068=>14180001 01001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00806I Processor CP00: I/O interrupt code 00010012 parm 00EC46A8 id 00000000
10:35:59 HHC01317I 0:0A82 CHAN: scsw 00C04007, stat 0C00, count 0000, ccw 7FE61630
10:35:59 HHC01318I 0:0A82 CHAN: test I/O: cc=0

cyl 5144 head 2:

10:35:59 HHC01334I 0:0A82 CHAN: ORB: IntP:00EC46A8 Key:0 LPM:80 Flags:0C200 ....FP....H. ........ CCW:7FE61560
10:35:59 HHC01315I 0:0A82 CHAN: ccw E7400041 7FE61510=>01800000 00000000 00000000 40C00000 00000000 14180002 14180000 00000000 00000000 00000000 00000000 3F00000D 14180002 00000000 00FF0000 000A0001 ............ {..................................................
10:35:59 HHC00431I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: seeking to cyl 5144 head 2
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation index
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 0 kl 0 dl 8 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw E7400041 7FE61510=>01800000 00000000 00000000 40C00000 00000000 14180002 14180000 00000000 00000000 00000000 00000000 3F00000D 14180002 00000000 00FF0000 000A0001 ............ {..................................................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation count
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 1 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61008=>14180002 01001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE61290=>00000002 ADAE4000 00000002 ADAE3000 ....[. .....[...
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAE4000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 2 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61010=>14180002 02001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE61298=>00000002 ADAE3000 00000002 ADAE2000 ....[.......[...
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAE3000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 3 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61018=>14180002 03001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612A0=>00000002 ADAE2000 00000002 ADAE1000 ....[.......[...
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAE2000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 4 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61020=>14180002 04001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612A8=>00000002 ADAE1000 00000002 ADAE0000 ....[.......[...
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAE1000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 5 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61028=>14180002 05001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612B0=>00000002 ADAE0000 00000002 ADADF000 ....[.......[[0.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAE0000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 6 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61030=>14180002 06001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612B8=>00000002 ADADF000 00000002 ADADE000 ....[[0.....[[\.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADADF000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 7 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61038=>14180002 07001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612C0=>00000002 ADADE000 00000002 ADADD000 ....[[\.....[[}.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADADE000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 8 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61040=>14180002 08001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612C8=>00000002 ADADD000 00000002 ADADC000 ....[[}.....[[{.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADADD000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 9 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61048=>14180002 09001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612D0=>00000002 ADADC000 00000002 ADADB000 ....[[{.....[[..
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADADC000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 10 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61050=>14180002 0A001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612D8=>00000002 ADADB000 00000002 ADADA000 ....[[......[[..
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADADB000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 11 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61058=>14180002 0B001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612E0=>00000002 ADADA000 00000002 ADAD9000 ....[[......[[..
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADADA000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 12 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61060=>14180002 0C001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612E8=>00000002 ADAD9000 00000000 00000000 ....[[..........
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAD9000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 255 kl 255 dl 65535 of 0
10:35:59 HHC00431I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: seeking to cyl 5144 head 2
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 0 kl 0 dl 8 of 0
10:35:59 HHC00435I Thread 00007f9e11c69700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 2 record 1 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92000008 7FE61068=>14180002 01001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00806I Processor CP01: I/O interrupt code 00010012 parm 00EC46A8 id 00000000
10:35:59 HHC01317I 0:0A82 CHAN: scsw 00C04007, stat 0C00, count 0000, ccw 7FE61630
10:35:59 HHC01318I 0:0A82 CHAN: test I/O: cc=0

Notice how both of the above I/Os are reading the full 12 records that are on the track, and how, when the end of the track is reached (after the 12th record), it seeks back to the beginning of the current track again, exactly how it is supposed to.

Now, contrast those I/Os with the below I/O for cyl 5144 head 3 where, upon reaching end-of-track after the 3rd record, it erroneously advances to the next track! (WTF?!)

cyl 5144 head 3:

10:35:59 HHC01334I 0:0A82 CHAN: ORB: IntP:00EC46A8 Key:0 LPM:80 Flags:0C200 ....FP....H. ........ CCW:7FE61560
10:35:59 HHC01315I 0:0A82 CHAN: ccw E7400041 7FE61510=>01800000 00000000 00000000 40C00000 00000000 14180003 14180000 00000000 00000000 00000000 00000000 3F00000D 14180003 00000000 00FF0000 000A0001 ............ {..................................................
10:35:59 HHC00431I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: seeking to cyl 5144 head 3
10:35:59 HHC00434I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation index
10:35:59 HHC00435I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 0 kl 0 dl 8 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw E7400041 7FE61510=>01800000 00000000 00000000 40C00000 00000000 14180003 14180000 00000000 00000000 00000000 00000000 3F00000D 14180003 00000000 00FF0000 000A0001 ............ {..................................................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation count
10:35:59 HHC00435I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 1 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61008=>14180003 01001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE61290=>00000002 ADAD8000 00000002 ADAD7000 ....[[......[[..
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAD8000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 2 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61010=>14180003 02001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE61298=>00000002 ADAD7000 00000002 ADAD6000 ....[[......[[-.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAD7000, len 1000=>00000000 00000000 00000000 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 3 kl 0 dl 4096 of 0
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61018=>14180003 03001000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00437I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read data 4096 bytes
10:35:59 HHC01315I 0:0A82 CHAN: ccw 86441000 7FE612A0=>00000002 ADAD6000 00000002 ADAD5000 ....[[-.....[[&.
10:35:59 HHC01303I 0:0A82 CHAN: idaw 00000002ADAD6000, len 1000=>00000000 02000002 00000200 00000000 ................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000
10:35:59 HHC00434I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: read count orientation data
10:35:59 HHC00435I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: cyl 5144 head 3 record 255 kl 255 dl 65535 of 0
10:35:59 HHC00433I Thread 00007f9d64dcd700 0:0A82 CKD file /home/hercules/zPDT/ZOS25B/DASD64/B5SYS1.CCKD: MT advance to cyl(5144) head(4)
10:35:59 HHC01315I 0:0A82 CHAN: ccw 92400008 7FE61020=>00000000 00000000                   ........
10:35:59 HHC01312I 0:0A82 CHAN: stat 0E40, count 0008
10:35:59 HHC01313I 0:0A82 CHAN: sense 00040000 00FFFF00 00000000 00000000 00000000 00000000 00000080 00141803
10:35:59 HHC01314I 0:0A82 CHAN: sense FP 
10:35:59 HHC00806I Processor CP04: I/O interrupt code 00010012 parm 00EC46A8 id 00000000
10:35:59 HHC01317I 0:0A82 CHAN: scsw 00C24017, stat 0E40, count 0008, ccw 7FE615A0
10:35:59 HHC01318I 0:0A82 CHAN: test I/O: cc=0

Why the frick it's advancing to the next track instead of returning back to the start of the same track, I don't know! (yet!)

But I'm very close to discovering the cause!

Okay, I've got some good news and I've got some bad news:

The Good News is: I've found the bugs (Yep, there was more than one!) and have a fix for them! Yea!! :-)
The Bad News is: There's still an unresolved "WTF?!" issue which I'm unfortunately unable to explain. :-(

The fix for the primary erroneous FILE PROTECT problem was rather trivial.

The unresolved WTF issue however, concerns me (bothers me) because it's so damn nonsensical, puzzling, baffling, unexplainable. It really doesn't make any sense.

When I began my efforts to manually recreate the problem using the CCW trace that Peter kindly provided, I had trouble doing so because my test -- which is an "exact" copy of problematic CCW chain from Peter's trace -- was always failing with a Command Reject (CMDREJ) on the E7 Prefix CCW because the Define Extent's "End of Extent" field was invalid!

But yet, for some unknown reason, it wasn't being rejected for Peter! (WTF?!)

Take a look at the HHC01315I 0:0A82 CHAN: ccw E7400041 ... lines in each of the trace log snippets I showed in my previous comment above. They're all exactly identical:

10:35:59 HHC01315I 0:0A82 CHAN: ccw E7400041 7FE61510=>01800000 00000000 00000000 40C00000 00000000 14180001 14180000 00000000 00000000 00000000 00000000 3F00000D 14180001 00000000 00FF0000 000A0001 ............ {..................................................
10:35:59 HHC01312I 0:0A82 CHAN: stat 0C00, count 0000

In each and every case, the E7 ccw was processed without error, even though the End of Extent in all of them was invalid! They all specify an End of Extent value that comes before the Beginning of Extent value!

(The 14180001 14180000 values are the Begin/End of Extent fields in the Define Extent data, and the 14180001 value near the end is the Seek Address in the Locate Record Extended data. Notice how the Begin of Extent specifies e.g. cyl 5144 head 1, whereas the End of Extent value is cyl 5144 head 0! The 'HH' (Head) value in the End of Extent field is always zero! And according to the manual, that's invalid because it's a physical address that comes before the Begin of Extent address!)

So why wasn't Peter's Hercules kicking out the E7's with CMDREJ like mine was?! That's the mystery I haven't solved yet, and it's bothering the shit out of me! Peter's Hercules is apparently behaving quite different than mine, and I'm unable to explain why. :-(

Now I should quickly point out that Hercules's rejection of the E7 Prefix due to an apparent invalid End of Extent field in the Prefix CCW's Define Extent data, is actually a bug in this particular case. Due to the E7 Prefix's Field Validity flag indicating that the Define Extent data should be considered valid, and no field checking should be performed. So Hercules should have accepted whatever values were specified in the Define Extent data as-is, without bothering to validate them or throw a CMDREJ as a result. But due to a bug, were weren't accepting them as-is and were validating them instead, causing the CMDREJ -- for ME!

This was because we weren't handing the Field Validity flag properly, causing us to always verify that the Begin/End of Extent fields were valid. This has of course been fixed (or will be as soon as commit my changes), but it still doesn't explain why Peter's E7 Prefix wasn't being being rejected due to this bug like my Hercules was! My Hercules was properly throwing a CMDREJ (due to the bug), so why wasn't Peter's? His Hercules presumably had (has!) the same bug in it! So why did all of Peter's E7 Prefix CCWs succeed, when, due to the bug, they should all have failed like they did for me?! THAT is what is bothering the crap out of me. :-(

But I guess it's all water over the dam now that I've properly fixed things (as soon as I commit my changes) so that such apparent invalid End of Extent values are no longer rejected. The reason they're no longer rejected is because we're now properly honoring the Field Validity flag that was saying the Define Extent data should be treated as valid and accepted as-is, and thus there's no need to validate it.

And we now also correctly don't bother verifying whether the Locate Record Extended's Seek Address is within the Define Extent's Begin/End of Extent boundaries for Read Any or Write Any either. This is because for Read Any and Write Any, the specified Begin of Extent CCHH is never left. That is to say, we never leave the specified track. We never advance to the next track. Because the Locate Record Extended's Extended Operation is Read Any or Write Any, we now correctly return back to the beginning of the same track when end-of-track is reached instead of erroneously advancing to the next track. Thus because we never leave the track specified by the Begin of Extent value, there's no need to specify any End of Extent value. It's meaningless.

Before that fix, we were erroneously advancing to the next track, and THAT was what was causing the erroneous "FILE PROTECT" error that Peter was experiencing.

SUMMARY:

The primary cause of the erroneous FILE PROTECT has been identified and fixed.
The erroneous CMDREJ (for ME!) of the E7 Prefix CCW due to the seemingly "bogus" Define Extent data's End of Extent value has also been fixed.
We now properly honor both of the E7 Prefix's Field Validity and Auxiliary Byte fields' flags to prevent erroneous rejection of values that the user has told us are valid and don't need to be checked.

UNRESOLVED:

Why the FRICK does Peter's unfixed (known to still contain the bug!) Hercules not erroneously rejecting his E7 Prefix CCWs?! Does anyone have a theory regarding that? Because I'm completely baffled by that! :-(

In the mean time, I'll be committing my changes. It might take me a short while however, as I want to do them in separate pieces so you can see what's going on, so I need to be careful about that and go slow, lest I mess something up.

I'm also going to need some help from someone with something else related to this issue too, but I'll explain that in a subsequent comment.

All in all this was a VERY interesting bug!!

Fixed by commits 1b495c75138fbb8b49c4ac72ba12bb50da7c6824, 37001b7f70db15e04c6501ce222930381655b091, 6cba4f921846d8932af2fccde42adfff2d076c35, and most importantly, fffc1f57d9ccd067735df1d1fba5e2feb49f6bb2.

Closing.

But remember, I still need your (someone's!) help with something else related to this issue! I've posted the details in the comment below. Thanks.

Hi guys!

I was able to manually reproduce/recreate this issue by adding a new set of test to our existing E7Prefix test. But at the moment it's hard coded for one of my z/OS 2.5 dasds.

I used dasdls to find a dataset on my C5SYS1 volume with the same attributes that was causing Peter's problem: a track filled with 12 (twelve) 4096 (4K) blocks, followed by a track with less than a full track of the same thing.

Using it, I was able to reproduce Peter's bug and develop a fix.

I would now like to make it a permanent Hercules QA test (i.e. make check runtest test), but I obviously do not want to add the entire fricking 3390-9 volume to our repository just so we can verify my fix! Besides that, it's an IBM ADCD volume so legally we can't anyway. That would be piracy, and I don't think IBM would take too kindly of our doing that.

We already have several dummy empty test volumes that our E7Prefix test uses to run its tests against: "3330.cckd64", "3380.cckd64" and "3390.cckd64".

What I would like to do is to somehow create a single track somewhere on our "3390.cckd64" test volume with 12 (twelve) 4096 (4K) records on it, and another track (ideally immediately following it, but that's not a requirement) with anywhere from 1-11 4K blocks on it _(i.e. with some number of blocks less than 12. Say, only 3 blocks for example)_.

How do I do that? Is there some IEBCOPY I could run on z/OS, or some z/VM utility or script that could do it for me?

I'd really rather not have to write my own channel program to do something as simple as that! I'd prefer using some sort of existing tool to quickly and easily do it without me having to write anything.

Can anyone help me out? Any ideas regarding the fastest/easiest way to accomplish this?

Thanks!

Hi Fish!

Congratulations with this super effort of yours fixing this problem!! I'm absolutely impressed with it. There would have been absolutely no chance for me to find and correct this issue in any reasonable or even unreasonable amount of time.

I've re-run my IPL's, starting from the same zPDT vanilla DASD's after SF- xxxx NOMERGE the shadows as before, and I can confirm that the problem has completely gone away!

Thanks a lot for this Fish!

Cheers, Peter

Congratulations with this super effort of yours fixing this problem!!

You're very welcome, Peter!

... and I can confirm that the problem has completely gone away!

That's good to know. Thanks!

Do you (or anyone else) have any suggestions/ideas regarding my followup question?

I was first going to try it out before replying to that follow-up question, but what I had in mind was just creating a regular z/OS dataset of two tracks, RECFM=FM,LRECL=64,BLKSIZE=4096, with the ISPF editor and write say 64x20=1280 records in it, good for exactly 20 blocks of 4096 bytes. Wouldn't that do it ?

Cheers,

Peter

Rob Prins's post to H390-MVS with JCL for IEBDG is the right answer.

Rob Prins's post to H390-MVS with JCL for IEBDG is the right answer.

Indeed it was!

It worked perfectly and I was able to create my needed test data on the required tracks on my test volume exactly as required.

@Peter-J-Jansen

Peter: Could you do me a favor and re-test your original situation again please? I've just made a new commit containing additional changes related to your original problem and I want to make sure I didn't somehow break something.

I updated the existing E7Prefix runtest test with two new tests to verify the channel programs that were originally causing your FILE PROTECT problem now run successfully, so I'm fairly confident my changes shouldn't break anything (and I've IPLed z/OS 2.5 both natively and under z/VM 7.3 a zillion times too), but just to be doubly sure I'd appreciate you giving your own test a try as well, as extra confirmation.

Thanks.

SDL-Hercules-390 / hyperion