HHC90013E messages regarding locking issue in channel.c

[PeterCoghlan]

I'm getting a bunch of these messages on the hercules console (probably wrapped):

HHC90013E 'release_lock(&dev->lock)' failed: rc=1: not owned;tid=0000000000c57300, loc=HERCULES_CODE:[V4-2016-10-25]CHANNEL.C;1:4099

This is on Hyperion downloaded on 25 October 2016. The issue exists at least as far back as May 2015 and probably forward to the present day.

The messages occur when a ckd dasd which has been attached to at least some VM/370 variants after ipl time is accessed.

Here's one way to produce the messages:

Get the VM/370 5-Pack VMDIST.zip system from here: http://www.smrcc.org.uk/members/g4ugm/VM370.htm

(One of the Sixpack variants may work too - I haven't tested).

Edit the configuration file vmr60.conf and correct the locations of dasd 141, 241, 34f and 440 only. (I changed the files to read-write and didn't use the shadow files but it might work as well with shadow files - I didn't check). Make sure dasd 540 is not accessible or commented out.

Start up hercules and connect a 3270 emulator to port 3270. IPL 141.

After VM comes up, on the Hercules console enter: attach 540 3350 location-of-fifth-pack

On the 3270 session:

DISCON LOGON MAINT CPCMS VARY ONLINE 540 ATTACH 540 SYSTEM VM50-5 LINK * 235 235 DDR INPUT 235 3350 PRINT 0 YES

Check the hercules console for messages.

[dasdman]

Try turning off SYNCIO, which is no longer really necessary.

Mark

On 01/25/2017 12:10 PM, PeterCoghlan wrote:

I'm getting a bunch of these messages on the hercules console (probably wrapped):

HHC90013E 'release_lock(&dev->lock)' failed: rc=1: not owned;tid=0000000000c57300, loc=HERCULES_CODE:[V4-2016-10-25]CHANNEL.C;1:4099

This is on Hyperion downloaded on 25 October 2016. The issue exists at least as far back as May 2015 and probably forward to the present day.

The messages occur when a ckd dasd which has been attached to at least some VM/370 variants after ipl time is accessed.

Here's one way to produce the messages:

Get the VM/370 5-Pack VMDIST.zip system from here: http://www.smrcc.org.uk/members/g4ugm/VM370.htm

(One of the Sixpack variants may work too - I haven't tested).

Edit the configuration file vmr60.conf and correct the locations of dasd 141, 241, 34f and 440 only. (I changed the files to read-write and didn't use the shadow files but it might work as well with shadow files - I didn't check). Make sure dasd 540 is not accessible or commented out.

Start up hercules and connect a 3270 emulator to port 3270. IPL 141.

After VM comes up, on the Hercules console enter: attach 540 3350 location-of-fifth-pack

On the 3270 session:

DISCON LOGON MAINT CPCMS VARY ONLINE 540 ATTACH 540 SYSTEM VM50-5 LINK * 235 235 DDR INPUT 235 3350 PRINT 0 YES

Check the hercules console for messages.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/hercules-390/hyperion/issues/190, or mute the thread https://github.com/notifications/unsubscribe-auth/ABUttsW_93rrbKEVR-xe8vurfNmp3vtkks5rV6wngaJpZM4Lt8NZ.

[wably]

Just FYI, I was able to recreate this using VM Sixpack 1.2 and using a 3380 volume as the offline device that was made active per Peter's procedure above. I received the same messages on the Hercules console that Peter described. This was using the latest Fish-Git master of Hyperion.

[PeterCoghlan]

Assuming defining OPTION_NOSYNCIO somewhere and rebuilding is the correct way to turn off SYNCIO, I can confirm that the messages do not appear after this is done. I have not done extensive testing to ensure other issues do not arise under the new conditions.

Reading through the code, it seems apparent that the function where the message is issued is never called under the new conditions.

[PeterCoghlan]

I decided to do some investigating for myself.

According to the CHANGES file, SYNCIO has been disabled in various circumstances going back to 2001. It seems to be frowned on and while I haven't seen it written anywhere in so many words, it appears that perhaps it is being "phased out"?

However, according to the html documentation (and this corresponds with reality as far as I can see) there are "syncio" and "nosyncio" options available for c(c)kd dasd devices in the Hercules configuration and in attach commands and if not specified, the default is "syncio".

There is also a "syncio" console command. Amongst other things, this apparently lists the devices for which SYNCIO has been enabled either by default or explicitly.

Beginning sometime between April 2012 and May 2013, dev->syncio gets set to zero in device_reset() which gets called at IPL time. This means that devices that were enabled for SYNCIO either explicitly or by default are unexpectedly disabled for SYNCIO when an operating system is IPLed. This can be seen by issuing the "syncio" console command before and after IPL.

If a device is attached after IPL time, the "syncio" option is assumed by default. device_reset() does not get called and SYNCIO remains enabled for the device. It then appears that in at least some cases of accessing the device, dev->lock is not obtained before an attempt is made to release dev->lock and the messages noted above are displayed on the Hercules console. It is not clear to me whether dev->lock should have been obtained or should not have been released nor whether the error could result in data loss or not in some particular circumstances.

SYNCIO seems to exist in some strange twilight zone at the moment. The documentation is says it is there and it is on by default but it is clearly broken and it appears to get silently turned off at IPL time.

Could I suggest that either SYNCIO is fixed to operate as described in the documentation or SYNCIO is fully disabled by default and the documentation is updated to note this?

[Fish-Git]

For what it's worth, SYNCIO is currently in the process of being completely removed from my (fork of) Hyperion. I hope to commit the change (as well as Bob Polanter's latest VM Assist changes) sometime later today and build a new set of pre-built Windows binaries (it's been a while).

Those of you using Linux however will have to build it yourself.

[PeterCoghlan]

Many thanks Fish. I have tried your fork now and I can confirm that the issue I reported does not occur with it.

I suspect the issue still occurs with the hercules-390/hyperion fork but I haven't tested recently so I can't be positive on that.