records with asyn:READBACK are not always setting STAT and SEVR correctly when UDF=0

This issue is in response to this EPICS tech-talk thread: https://epics.anl.gov/tech-talk/2021/msg01094.php

I have created a new debug_udf branch in asyn to test this, using a modified version of testAsynPortDriver.cpp and its IOC.

I have reproduced the problem.

I added a new bo record called Clutch. This is the definition of that record. Note that it does not set PINI=1, does not set VAL, and sets the asyn:READBACK info tag to 1.

record(bo, "$(P)$(R)Clutch")
{
    field(DTYP, "asynInt32")
    field(OUT,  "@asyn($(PORT),$(ADDR),$(TIMEOUT))CLUTCH")
    field(ZNAM, "Off")
    field(ONAM, "On")
    info(asyn:READBACK, "1")
}

The driver was modified to add an asynInt32 parameter, P_Clutch, corresponding to this record. Its value is not set in the constructor. The following code was added to the poller thread.

+    epicsThreadSleep(2.0);
     lock();
+    setIntegerParam(P_Clutch, 1);
+    callParamCallbacks();
+    unlock();
+    epicsThreadSleep(2.0);
+    lock();
+    setIntegerParam(P_Clutch, 0);
+    callParamCallbacks();

Because the value of the Clutch parameter is not set at all until 2 seconds after the thread is created the initial readback in init_record will return asynUndefined, and UDF should be 1, and STAT=UDF, SEVR=INVALID.

The above code sleeps for 2 seconds and then sets the value of clutch to 1 and calls the callbacks. Because asyn:READBACK=1 this should do the following:

Set the record VAL field to 1
Set the record UDF field to 0
Process the record. Processing the record should set STAT and SEVR to NO_ALARM.

The code then sleeps for another 2 seconds and sets the value back to 0, and again does the callbacks. At this point the record VAL should be 0 and STAT and SEVR should still be NO_ALARM.

iocBoot/ioctestAsynPortDriver/st.cmd was modified as follows:

index cdd5baf..499ce2a 100644
--- a/iocBoot/ioctestAsynPortDriver/st.cmd
+++ b/iocBoot/ioctestAsynPortDriver/st.cmd
@@ -5,9 +5,20 @@ testAsynPortDriver_registerRecordDeviceDriver(pdbbase)
 #asynSetTraceMask("", 0, 17)

 testAsynPortDriverConfigure("testAPD", 1000)
+date

 dbLoadRecords("../../db/testAsynPortDriver.db","P=testAPD:,R=scope1:,PORT=testAPD,ADDR=0,TIMEOUT=1,NPOINTS=1000")
 dbLoadRecords("../../db/asynRecord.db","P=testAPD:,R=asyn1,PORT=testAPD,ADDR=0,OMAX=80,IMAX=80")
 #asynSetTraceMask("testAPD",0,0xff)
 asynSetTraceIOMask("testAPD",0,0x2)
 iocInit()
+
+date
+dbpr testAPD:scope1:Clutch 2
+epicsThreadSleep(3)
+date
+dbpr testAPD:scope1:Clutch 2
+epicsThreadSleep(3)
+date
+dbpr testAPD:scope1:Clutch 2
+

It prints the time right after the driver is created. This is the output, so the driver was created at 09:31:02.84.

testAsynPortDriverConfigure("testAPD", 1000)
date
2021/05/28 09:31:02.849064

It prints the time and then runs dbpr on the Clutch record immediately after iocInit. At this point we expect VAL=0 (record default), UDF=1, STAT=UDF, SEVR=INVALID, TIME=undefined because the record has never processed. This is indeed exactly what we actually see:

iocRun: All initialization complete
date
2021/05/28 09:31:03.353862
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 0             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: INVALID       SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: UDF
TIME: <undefined>   TPRO: 0             TSE : 0             TSEL: CONSTANT
UDF : 1             UDFS: INVALID       VAL : 0             ZNAM: Off
ZSV : NO_ALARM

It then sleeps for 3 seconds, which is long enough for the first setting of the Clutch parameter in the polling thread. At this point we expect VAL=1, UDF=0, STAT=SEVR=NO_ALARM, TIME=about 2 seconds after driver was created. Here is what we actually see.

UDF=0 (as expected)
VAL=1 (as expected)
TIME= 09:31:04.84 (exactly 2 seconds after the driver and the poller thread was created, as expected)
STAT=UDF (this is NOT expected)

SEVR=INVALID ( this is NOT expected)

epicsThreadSleep(3)
date
2021/05/28 09:31:06.354234
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 1             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: INVALID       SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: UDF
TIME: 2021-05-28 09:31:04.849222534     TPRO: 0             TSE : 0
TSEL: CONSTANT      UDF : 0             UDFS: INVALID       VAL : 1
ZNAM: Off           ZSV : NO_ALARM

It then sleeps for anther 3 seconds, which is long enough for the second setting of the Clutch parameter in the polling thread, which is back to 0. At this point we expect VAL=0, UDF=0, STAT=SEVR=NO_ALARM, TIME=about 2 seconds after the previous time the record was processed=09:31:06.84. That is indeed exactly what we actually see.

epicsThreadSleep(3)
date
2021/05/28 09:31:09.354519
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 0             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: NO_ALARM      SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: NO_ALARM
TIME: 2021-05-28 09:31:06.849333901     TPRO: 0             TSE : 0
TSEL: CONSTANT      UDF : 0             UDFS: INVALID       VAL : 0
ZNAM: Off           ZSV : NO_ALARM

So the problem is that the first time the record processes due to a callback UDF=0 but STAT and SEVR do not get set to NO_ALARM. Why not?

I changed the record to set TPRO=1. This is the complete output after iocInit.

iocRun: All initialization complete
date
2021/05/28 14:28:04.856334
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 0             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: INVALID       SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: UDF
TIME: <undefined>   TPRO: 1             TSE : 0             TSEL: CONSTANT
UDF : 1             UDFS: INVALID       VAL : 0             ZNAM: Off
ZSV : NO_ALARM
epicsThreadSleep(3)
cbLow: dbProcess of 'testAPD:scope1:Clutch'
date
2021/05/28 14:28:07.856849
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 1             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: INVALID       SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: UDF
TIME: 2021-05-28 14:28:06.351359043     TPRO: 1             TSE : 0
TSEL: CONSTANT      UDF : 0             UDFS: INVALID       VAL : 1
ZNAM: Off           ZSV : NO_ALARM
epicsThreadSleep(3)
cbLow: dbProcess of 'testAPD:scope1:Clutch'
date
2021/05/28 14:28:10.857157
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 0             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: NO_ALARM      SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: NO_ALARM
TIME: 2021-05-28 14:28:08.351439259     TPRO: 1             TSE : 0
TSEL: CONSTANT      UDF : 0             UDFS: INVALID       VAL : 0
ZNAM: Off           ZSV : NO_ALARM

So both times I expect the record to process I see the message

cbLow: dbProcess of 'testAPD:scope1:Clutch'

I just ran camonitor when the IOC started.

corvette:~/devel/areaDetector>camonitor -tcs testAPD:scope1:Clutch.VAL testAPD:scope1:Clutch.UDF testAPD:scope1:Clutch.STAT testAPD:scope1:Clutch.SEVR
testAPD:scope1:Clutch.VAL      *** Not connected (PV not found)
testAPD:scope1:Clutch.UDF      *** Not connected (PV not found)
testAPD:scope1:Clutch.STAT     *** Not connected (PV not found)
testAPD:scope1:Clutch.SEVR     *** Not connected (PV not found)
testAPD:scope1:Clutch.VAL      <undefined>(2021-05-28 14:38:03.723596) Off UDF INVALID
testAPD:scope1:Clutch.UDF      <undefined>(2021-05-28 14:38:03.723638) 1 UDF INVALID
testAPD:scope1:Clutch.STAT     <undefined>(2021-05-28 14:38:03.723656) UDF UDF INVALID
testAPD:scope1:Clutch.SEVR     <undefined>(2021-05-28 14:38:03.723671) INVALID UDF INVALID
testAPD:scope1:Clutch.VAL      2021-05-28 14:38:04.626883(2021-05-28 14:38:04.626969) On UDF INVALID
testAPD:scope1:Clutch.SEVR     2021-05-28 14:38:06.627000(2021-05-28 14:38:06.627097) NO_ALARM
testAPD:scope1:Clutch.STAT     2021-05-28 14:38:06.627000(2021-05-28 14:38:06.627139) NO_ALARM
testAPD:scope1:Clutch.VAL      2021-05-28 14:38:06.627000(2021-05-28 14:38:06.627150) Off

So we first see monitors on VAL, UDF, STAT, and SEVR at iocInit with undefined server timestamps. VAL is in the Off (0) state. This is what we expect.

Then 2 seconds after the driver was created we get a monitor on VAL for the On (1) state. This is correct. However, it did not send monitors on STAT and SEVR because they did not change, while they should have.

Then 2 seconds after the first time the record processes, it processes again. This time VAL is Off again, and STAT and SEVR have changed to NO_ALARM.

This seems to prove conclusively that the record did process the first time, and sent out a monitor on VAL. But it did not change STAT and SEVR as expected.

I just ran the testAsynPortDriver test using debug_udf branch and base 3.15.5. It behaves the same as base 7.0.5, so the problem is not due to a recent change to base.

I modified devAsynInt32.c::processBo to print some debugging as follows:

diff --git a/asyn/devEpics/devAsynInt32.c b/asyn/devEpics/devAsynInt32.c
index 4dfc50c..8d1ab1e 100644
--- a/asyn/devEpics/devAsynInt32.c
+++ b/asyn/devEpics/devAsynInt32.c
@@ -1213,37 +1213,40 @@ static long processBo(boRecord *pr)
     devPvt *pPvt = (devPvt *)pr->dpvt;
     int status;

     epicsMutexLock(pPvt->devPvtLock);
     if(pPvt->newOutputCallbackValue && getCallbackValue(pPvt)) {
         /* We got a callback from the driver */
         if (pPvt->result.status == asynSuccess) {
             pr->rval = pPvt->result.value;
             pr->val = (pr->rval) ? 1 : 0;
             pr->udf = 0;
+            asynPrint(pPvt->pasynUser, ASYN_TRACE_WARNING, "processBo record=%s, udf=0\n", pr->name);
         }
     } else if(pr->pact == 0) {
         pPvt->result.value = pr->rval;
         if(pPvt->canBlock) {
             pr->pact = 1;
             pPvt->asyncProcessingActive = 1;
         }
         epicsMutexUnlock(pPvt->devPvtLock);
         status = pasynManager->queueRequest(pPvt->pasynUser, 0, 0);
         if((status==asynSuccess) && pPvt->canBlock) return 0;
         if(pPvt->canBlock) pr->pact = 0;
         epicsMutexLock(pPvt->devPvtLock);
         reportQueueRequestStatus(pPvt, status);
     }
     pasynEpicsUtils->asynStatusToEpicsAlarm(pPvt->result.status,
                                             WRITE_ALARM, &pPvt->result.alarmStatus,
                                             INVALID_ALARM, &pPvt->result.alarmSeverity);
+    asynPrint(pPvt->pasynUser, ASYN_TRACE_WARNING, "processBo record=%s, calling recGblSetSevr status=%d, severity=%d\n",
+              pr->name, pPvt->result.alarmStatus, pPvt->result.alarmSeverity);
     (void)recGblSetSevr(pr, pPvt->result.alarmStatus, pPvt->result.alarmSeverity);
     if (pPvt->numDeferredOutputCallbacks > 0) {
         callbackRequest(&pPvt->outputCallback);
         pPvt->numDeferredOutputCallbacks--;
     }
     pPvt->newOutputCallbackValue = 0;
     pPvt->asyncProcessingActive = 0;
     epicsMutexUnlock(pPvt->devPvtLock);
     if(pPvt->result.status == asynSuccess) {
         return 0;

So it prints the a message when it sets udf=0 and it prints a message just before it calls recGblSetSevr with the values it is setting for status and severity.

This is now the complete output after iocInit:


iocRun: All initialization complete
date
2021/05/29 10:03:51.073336
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 0             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: INVALID       SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: UDF
TIME: <undefined>   TPRO: 1             TSE : 0             TSEL: CONSTANT
UDF : 1             UDFS: INVALID       VAL : 0             ZNAM: Off
ZSV : NO_ALARM
epicsThreadSleep(3)
cbLow: dbProcess of 'testAPD:scope1:Clutch'
2021/05/29 10:03:52.566 processBo record=testAPD:scope1:Clutch, udf=0
2021/05/29 10:03:52.566 processBo record=testAPD:scope1:Clutch, calling recGblSetSevr status=0, severity=0
date
2021/05/29 10:03:54.073656
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 1             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: INVALID       SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: UDF
TIME: 2021-05-29 10:03:52.565900993     TPRO: 1             TSE : 0
TSEL: CONSTANT      UDF : 0             UDFS: INVALID       VAL : 1
ZNAM: Off           ZSV : NO_ALARM
epicsThreadSleep(3)
cbLow: dbProcess of 'testAPD:scope1:Clutch'
2021/05/29 10:03:54.566 processBo record=testAPD:scope1:Clutch, udf=0
2021/05/29 10:03:54.566 processBo record=testAPD:scope1:Clutch, calling recGblSetSevr status=0, severity=0
date
2021/05/29 10:03:57.073942
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 0             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: NO_ALARM      SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: NO_ALARM
TIME: 2021-05-29 10:03:54.565963934     TPRO: 1             TSE : 0
TSEL: CONSTANT      UDF : 0             UDFS: INVALID       VAL : 0
ZNAM: Off           ZSV : NO_ALARM

Note that the first time the record processes it has indeed set udf=0 and called recGblSetSevr with status=0, severity=0. Yet for some reason the record STAT and SEVR fields are UDF and INVALID.

I am having a hard time seeing that I am doing something wrong in asyn.

This problem is happening because the record's author decided that the only way to clear a UDF alarm would be for a value to be put into the record, either from an external put from a CA or DB link (in which case code in the dbAccess.c dbPut() routine clears UDF at that time and the record would get processed) or by reading a value through the DOL link during record processing triggered by some other means. In both cases UDF will have been cleared before the call to checkAlarms() in the boRecord::process() routine, which is where the UDF field is checked.

Unfortunately for Asyn, (and this applies to all output record types) the checkAlarms() routine gets called before the device support's write_bo() routine, so clearing UDF in processBo() is too late for this process cycle, the UDF_ALARM has already been registered. This also means that if the bo record is configured with non-zero alarms in ZSV or OSV the initial read wouldn't trigger the appropriate STATE_ALARM either, since they get set in that routine as well.

My impression (I wasn't involved at the time) is that the EPICS record API really wasn't designed with asynchronous device support in mind, it was bolted on afterwards, and this is one of the results.

For a fix I suggest looking at having the outputCallbackCallback() routine clear pr->udf before it calls dbProcess(pr) – it knows that there will be a value available so that seems the appropriate thing to do, and it already has the record locked. I suspect there are multiple copies of that routine, one in each devAsynTYPE.c file.

Thanks @anjohnson. I was beginning to think this was the correct solution as well.

I have implemented the above suggestion from @anjohnson on the debug_udf branch, and it fixes the problem in the modified version of testAsynPortDriver on that branch.

This is the complete output when the IOC boot. Note that the first time the record processes it now has STAT=SEVR=NO_ALARM.

iocRun: All initialization complete
date
2021/05/31 18:52:30.617941
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 0             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: INVALID       SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: UDF
TIME: <undefined>   TPRO: 1             TSE : 0             TSEL: CONSTANT
UDF : 1             UDFS: INVALID       VAL : 0             ZNAM: Off
ZSV : NO_ALARM
epicsThreadSleep(3)
cbLow: dbProcess of 'testAPD:scope1:Clutch'
2021/05/31 18:52:32.113 processBo record=testAPD:scope1:Clutch, calling recGblSetSevr status=0, severity=0
date
2021/05/31 18:52:33.618458
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 1             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: NO_ALARM      SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: NO_ALARM
TIME: 2021-05-31 18:52:32.113240966     TPRO: 1             TSE : 0
TSEL: CONSTANT      UDF : 0             UDFS: INVALID       VAL : 1
ZNAM: Off           ZSV : NO_ALARM
epicsThreadSleep(3)
cbLow: dbProcess of 'testAPD:scope1:Clutch'
2021/05/31 18:52:34.113 processBo record=testAPD:scope1:Clutch, calling recGblSetSevr status=0, severity=0
date
2021/05/31 18:52:36.618791
dbpr testAPD:scope1:Clutch 2
ACKS: NO_ALARM      ACKT: YES           ASG :               BKPT: 00
COSV: NO_ALARM      DESC:               DISA: 0             DISP: 0
DISS: NO_ALARM      DISV: 1             DOL : CONSTANT      DTYP: asynInt32
EVNT:               FLNK: CONSTANT      HIGH: 0
IVOA: Continue normally                 IVOV: 0             LCNT: 0
MASK: 0             NAME: testAPD:scope1:Clutch             NSEV: NO_ALARM
NSTA: NO_ALARM      OMSL: supervisory   ONAM: On            OSV : NO_ALARM
OUT : INST_IO @asyn(testAPD,0,1)CLUTCH  PACT: 0             PHAS: 0
PINI: NO            PRIO: LOW           PUTF: 0             RBV : 0
RPRO: 0             RVAL: 0             SCAN: Passive       SDIS: CONSTANT
SDLY: -1            SEVR: NO_ALARM      SIML: CONSTANT      SIMM: NO
SIMS: NO_ALARM      SIOL: CONSTANT      SSCN: <nil>         STAT: NO_ALARM
TIME: 2021-05-31 18:52:34.113340066     TPRO: 1             TSE : 0
TSEL: CONSTANT      UDF : 0             UDFS: INVALID       VAL : 0
ZNAM: Off           ZSV : NO_ALARM
epics>

@tboegi can you please test this branch and see if it works for you?

@MarkRivers : I tested the branch this morning. The record alarm state/severity changed as desired. My first test was missing the monitor event: camonitor and pvmonitor did not pick up the change. After re-cloning and update to the latest origin/7.0 branch in EPICS base the monitors worked as expected. Thanks so much to everyone for the fix.

From a more Git-user perspective: Should the commit message be reformated in a more Git-stylish way? One short header line, an empty line and a longer commit message, probably summarizing the most important parts of the nice discussion now spread out here and tech talk. That would allow people that run git log to gather more insight into the roles of device support, record processing and alarm handling. Just a general thought.

Mark's change handles the UDF issue, but doesn't resolve the case where the ZSV or OSV fields should be causing the record to go into an alarm state after the initial readback. That behavior is specific to the individual record type though, and would have to be implemented in the processBo() routine after setting pr->val:

recGblSetSevr(prec, STATE_ALARM, pr->val ? pr->osv : pr->zsv);

Hmm, the bo record's init_record() routine isn't raising a ZSV/OSV alarm in the synchronous case either – that looks like a bug in Base, which explains why the Asyn code isn't doing it. I suggest don't try fixing that in Asyn until we agree it should be done in Base.

Mark's fix also resolves a problem with the initial read-back of any output record using Asyn that has IVOA set to Don't drive outputs (and UDFS has the default INVALID alarm severity) since UDF being set will then prevent the device support from being called at all by the process() routine.

@MarkRivers I'd appreciate your thoughts on my STATE_ALARM issue in the Base record types. I've started a conversation about this and similar record API issues in the epics-base project, please respond there if you can.

Mark's fix also resolves a problem with the initial read-back of any output record using Asyn that has IVOA set to Don't drive outputs (and UDFS has the default INVALID alarm severity) since UDF being set will then prevent the device support from being called at all by the process() routine.

I'm not sure I understand that comment. My fix should only affect the behavior when the driver does a callback to device support, which causes the record to process. I don't think I changed the behavior for the initial readback?

Note that I have merged these changes in devEpics from the debug_udf branch to the master branch. I did not merge the changes to the testAsynPortDriver application.

Sorry, I probably worded that badly, I wasn't talking about the readback in DSET init_record().

Before this fix you were clearing UDF in your processBo() routine. If IVOA is Don't drive outputs and UDF is TRUE the DSET write_bo() routine will not be called by the record, because UDF generates an INVALID alarm and IVOA says not to write to the hardware in that state, thus your callback probably wouldn't actually do what you're expecting it to. I haven't actually tried it so I might be wrong, but by clearing UDF in the callback before you call dbProcess() the INVALID alarm doesn't happen.

Something similar will also happen if SIMM is Yes, but I think that's a user problem if they set SIMM on an output record that also has an info(asyn:READBACK, "1") tag.

Thanks @MarkRivers I just tested that ZSV=1 (in IOC:m2-OpenClutch) works for the bo record, both with initial readback and late connect. m1 has ZSV=0 and goes from UDF into no alarm. m2 has ZSV=1 and goes from UDF into minor alarm. All as it should be

IOC:m1-OpenClutch Closed UDF INVALID IOC:m2-OpenClutch Closed UDF INVALID IOC:m1-OpenClutch 2021-06-03 22:33:05.994300 Closed
IOC:m2-OpenClutch 2021-06-03 22:33:05.999080 Closed STATE MINOR

I think this issue can be closed.

epics-modules / asyn

records with asyn:READBACK are not always setting STAT and SEVR correctly when UDF=0 #136