This seems to be happening consistently each time we try to lock DRMI, it happened again at around 2:55 UTC

Hang and I did a test where we commented out a switch that happens to the SRCL1 filter:

        for dof in ['MICH', 'PRCL', 'SRCL']:
            ezca.get_LIGOFilter('LSC-%s1'%dof).switch('INPUT','OUTPUT', 'ON', wait=False)
            ezca.get_LIGOFilter('LSC-%s2'%dof).switch('INPUT','OUTPUT', 'ON', wait=False)
            if ezca.read('GRD-SUS_ETMX_STATE', as_string=True) == 'MISALIGNED' or lscparams.gate_valve_flag == True:
                log('setting gains for DRMI without arms')
                ezca.get_LIGOFilter('LSC-%s1'%dof).ramp_gain(lscparams.gain['DRMI_%s'%dof]['NO_ARMS'], ramp_time=2, wait=False)
            else:
                log('setting gains for DRMI with arms')
                ezca.get_LIGOFilter('LSC-%s1'%dof).ramp_gain(lscparams.gain['DRMI_%s'%dof]['ACQUIRE'], ramp_time=2, wait=False)
        #ezca.get_LIGOFilter('LSC-SRCL1').switch('OFFSET','OFF') # ensure modehop offset is off before trying to acquire

with the last line here commented out, the input was on at the end of the state.  I don't understand why switching the offset off should also turn off the input, this seems like a bug which could be bad. 

Here is the guardian log at this time:

2018-08-16_03:15:29.555316Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-MICH1_SW1 => 4
2018-08-16_03:15:29.555808Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-MICH1 => ON: INPUT, OUTPUT
2018-08-16_03:15:29.650288Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-MICH2 => ON: INPUT, OUTPUT
2018-08-16_03:15:29.651080Z ISC_DRMI [ACQUIRE_DRMI_1F.main] setting gains for DRMI with arms
2018-08-16_03:15:29.653531Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-MICH1_TRAMP => 2
2018-08-16_03:15:29.657395Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-MICH1_GAIN => 2.8
2018-08-16_03:15:29.660579Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-PRCL1_SW1 => 4
2018-08-16_03:15:29.661017Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-PRCL1 => ON: INPUT, OUTPUT
2018-08-16_03:15:29.661774Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-PRCL2 => ON: INPUT, OUTPUT
2018-08-16_03:15:29.663042Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-PRCL1_TRAMP => 2
2018-08-16_03:15:29.664269Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-PRCL1_GAIN => 16
2018-08-16_03:15:29.665760Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-SRCL1_SW1 => 4
2018-08-16_03:15:29.666674Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-SRCL1 => ON: INPUT, OUTPUT
2018-08-16_03:15:29.668874Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-SRCL2 => ON: INPUT, OUTPUT
2018-08-16_03:15:29.669472Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-SRCL1_TRAMP => 2
2018-08-16_03:15:29.677308Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-SRCL1_GAIN => -30
2018-08-16_03:15:57.549237Z ISC_DRMI [ACQUIRE_DRMI_1F.run] flashed, waiting to proceed
2018-08-16_03:15:57.553965Z ISC_DRMI [ACQUIRE_DRMI_1F.run] timer['lockpause'] = 0.5
2018-08-16_03:15:58.049619Z ISC_DRMI [ACQUIRE_DRMI_1F.run] timer['lockpause'] done
2018-08-16_03:16:26.037704Z ISC_DRMI [ACQUIRE_DRMI_1F.run] flashed, waiting to proceed
2018-08-16_03:16:26.038565Z ISC_DRMI [ACQUIRE_DRMI_1F.run] timer['lockpause'] = 0.5
2018-08-16_03:16:26.540255Z ISC_DRMI [ACQUIRE_DRMI_1F.run] timer['lockpause'] done
2018-08-16_03:16:52.536669Z ISC_DRMI [ACQUIRE_DRMI_1F.run] flashed, waiting to proceed
2018-08-16_03:16:52.542715Z ISC_DRMI [ACQUIRE_DRMI_1F.run] timer['lockpause'] = 0.5
2018-08-16_03:16:53.043944Z ISC_DRMI [ACQUIRE_DRMI_1F.run] timer['lockpause'] done
2018-08-16_03:17:32.666054Z ISC_DRMI [ACQUIRE_DRMI_1F.run] flashed, waiting to proceed
2018-08-16_03:17:32.672112Z ISC_DRMI [ACQUIRE_DRMI_1F.run] timer['lockpause'] = 0.5
2018-08-16_03:17:33.173887Z ISC_DRMI [ACQUIRE_DRMI_1F.run] timer['lockpause'] done
 

So the problem is that switching off th OFFSET is also switching off the INPUT?  Can you try using "cdsutils switch" from the command line and see what that does?  It should also be able to tell you what buttons are engaged/disengaged, or you can use "cdsutils sfm" to decode the raw SW1/2 EPICS records.

Are these channels hooked up to any triggers?

When I open a guardian shell for ISC_DRMI everything works correctly.  Same with cdsutils switch, everything is working correctly.  
The switching statements H1:LSC-SRCL1_SW1 => "Number" are only sent if the button needs to be pressed, and the "Number is not 0, unlike these two lines from Sheila's original alog:

2018-08-16_02:26:16.494002Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-SRCL1_SW1 => 0
2018-08-16_02:26:16.744942Z ISC_DRMI [ACQUIRE_DRMI_1F.main] ezca: H1:LSC-SRCL1 => OFF: OFFSET

Seems that our online guardian is not functioning the same as the interactive shell.


craig.cahillane@zotws14:~ 0$ guardian -i ISC_DRMI
--------------------
aLIGO Guardian Shell
--------------------
ezca prefix: H1:
system: ISC_DRMI (/opt/rtcds/userapps/release/isc/h1/guardian/ISC_DRMI.py)

In [1]: ezca.get_LIGOFilter('LSC-SRCL1').switch('OFFSET','OFF')
H1:LSC-SRCL1 => OFF: OFFSET

In [2]: ezca.get_LIGOFilter('LSC-SRCL1').switch('OFFSET','OFF')
H1:LSC-SRCL1 => OFF: OFFSET

In [3]: ezca.get_LIGOFilter('LSC-SRCL1').switch('OFFSET','OFF')
H1:LSC-SRCL1_SW1 => 8
H1:LSC-SRCL1 => OFF: OFFSET

In [4]: ezca.get_LIGOFilter('LSC-SRCL1').switch('OFFSET','OFF')
H1:LSC-SRCL1_SW1 => 8
H1:LSC-SRCL1 => OFF: OFFSET

In [5]: ezca.get_LIGOFilter('LSC-SRCL1').switch('OFFSET','OFF')
H1:LSC-SRCL1 => OFF: OFFSET

In [6]: ezca.get_LIGOFilter('LSC-SRCL1').switch('OFFSET','OFF')
H1:LSC-SRCL1_SW1 => 8
H1:LSC-SRCL1 => OFF: OFFSET

In [7]: ezca.get_LIGOFilter('LSC-SRCL1').switch('OFFSET','OFF')
H1:LSC-SRCL1 => OFF: OFFSET

In [8]: ezca.get_LIGOFilter('LSC-SRCL1').switch('INPUT','OFF')
H1:LSC-SRCL1_SW1 => 4
H1:LSC-SRCL1 => OFF: INPUT

In [9]: ezca.get_LIGOFilter('LSC-SRCL1').switch('INPUT','ON')
H1:LSC-SRCL1_SW1 => 4
H1:LSC-SRCL1 => ON: INPUT

Jamie,

SRCL1 has FM1 triggered, none of the rest of them are triggered. 

Above In[3] and In[4] are examples where Craig had set the SRCL1 bank up in the same way it will be when this command is run by the guardian. 

As far as I can tell from looking at H1:LSC-SRCL1_SWSTAT channel via NDS remotely, it looks like the INPUT is never set to on, even though the log would have you believe that it was.

Are you really sure there's no internal triggering happening on this filter module?

If there's triggering happening on this filter module I would be much more suspicious of that than guardian just spontaneous not doing something.  The triggering and guardian could easily be fighting each other.  Please check that you know exactly what the triggering is doing in this circumstance.

This does seem to be something to do with the triggering, only FM1 is triggered.

• We can't reproduce what is happening from a guardian shell, even if we run the commands while POP18 is flashing so that FM1 is triggering on and off.
• Georgia and Craig set the trigger matrix element to 0 and let the guardian run through the state, and the input was turned on in that case.
• In the example I originally posted, the timing of the guardian log seems to be off from the timing recorded in the frames by 60 seconds. ie, the guardian log says that the state changed from PREP_DRMI to ACQUIRE_DRMI at 02:26:16 UTC, which is 1218421594. However, the trend of ISC_DRMI_STATE_N shows it changing from 20 (PREP_DRMI) to 30 (ACQUIRE_DRMI) at 1218421538
• Jamie called and suggested we make a different guardian state that is disconnected from the graph to try some of these similar things from.  We could use the LSC_XARM filter for some testing. 
• As long as we comment out the line that turns off the offset the input gets turned on.  This is strange because in the example above the input never gets turned on.