Handlilng Epics Connection Issues (method + some oddities of TSAT's sytem)

[samdayweiss]

A few things in this:

1.) What are recommended ways to troubleshoot/re-initiate epics connections without re-hammering?

2.) I tried "soft" rehammering to isolate the epics connection issue and not reboot the entire slot, and this did not work. Only when I hard re-set was the epics connection able to restore.

3.) On our S04 smurf server, the command jackhammer hammer --no-reboot actually did a hard (not soft) rehammer, even though it prompted the "are you sure you want to soft-reset slots etc. etc.). Maybe @jlashner can take a look at this for us?

[jlashner]

Hi Sam, can you describe a bit more about the connection issues you're seeing? In particular if you could paste / elaborate on the following it would be very helpful:

• the client-side error message, i.e. what is actually being thrown in the jupyter / pysmurf-controller? Does it happen at a single spot in particular or is it random?
• any streamer-side error messages. Are the epics errors accompanied by some sort of hardware transaction error in the smurf-streawmer?

A few things to note and try:

• If epics failures correspond to hardware transaction errors in the streamer back-end, the issue is typically fiber. If not, you probably don't need a hammer.
• One thing we've found (https://github.com/simonsobs/daq-discussions/discussions/59) is that if the client container (pysmurf-controllers or smurf-jupyter) have been running for an very extended period of time, there is something that is causing the Swap memory usage to grow, which may be interfering with the epics client. I've found that running docker stop <container> && docker rm <container> and then bringing them back up fixes the issue. This does not reset the hardware or the streamer backend, so is a lot quicker to do and recover from compared to a hammer. We don't fully understand why this is happening, so I'd be interested in hearing if it helps alleviate the issue for you.

[tpsatt]

We're seeing similar issues on LAT. Intermittently, we find that the ability to connect to a pysmurf control object drops out, and we're not able to recover it without hammering. The error we get upon trying to establish a connection is:

---------------------------------------------------------------------------
ChannelAccessGetFailure                   Traceback (most recent call last)
Cell In[2], line 6
      4 cfg = DetConfig()
      5 cfg.load_config_files(slot=slot)
----> 6 S = cfg.get_smurf_control(make_logfile=True)

File /sodetlib/sodetlib/det_config.py:651, in DetConfig.get_smurf_control(self, offline, epics_root, smurfpub_id, make_logfile, setup, dump_configs, config_dir, apply_dev_configs, load_device_tune, **pysmurf_kwargs)
    649     S = pysmurf.client.SmurfControl(offline=True)
    650 else:
--> 651     S = pysmurf.client.SmurfControl(
    652         epics_root=epics_root, cfg_file=self.pysmurf_file, setup=setup,
    653         make_logfile=make_logfile, data_path_id=smurfpub_id,
    654         **pysmurf_kwargs)
    655 self.S = S
    656 # Lets just stash this in pysmurf...

File /usr/local/src/pysmurf/python/pysmurf/client/base/smurf_control.py:154, in SmurfControl.__init__(self, epics_root, cfg_file, data_dir, name, make_logfile, setup, offline, smurf_cmd_mode, no_dir, shelf_manager, validate_config, data_path_id, **kwargs)
    151 super().__init__(offline=offline, **kwargs)
    153 if cfg_file is not None or data_dir is not None:
--> 154     self.initialize(data_dir=data_dir,
    155         name=name, make_logfile=make_logfile, setup=setup,
    156         smurf_cmd_mode=smurf_cmd_mode, no_dir=no_dir,
    157         data_path_id=data_path_id, **kwargs)

File /usr/local/src/pysmurf/python/pysmurf/client/base/smurf_control.py:281, in SmurfControl.initialize(self, data_dir, name, make_logfile, setup, smurf_cmd_mode, no_dir, publish, payload_size, data_path_id, **kwargs)
    279 # Crate/carrier configuration details that won't change.
    280 self.crate_id = self.get_crate_id()
--> 281 self.slot_number = self.get_slot_number()
    283 # Channel assignment files
    284 self.channel_assignment_files = {}

File /usr/local/src/pysmurf/python/pysmurf/client/command/smurf_command.py:5032, in SmurfCommandMixin.get_slot_number(self, **kwargs)
   5023 def get_slot_number(self, **kwargs):
   5024     """
   5025     Gets the slot number of the crate that the carrier is installed into.
   5026 
   (...)
   5030         The slot number of the crate that the carrier is installed into.
   5031     """
-> 5032     return self._caget(
   5033         self.amc_carrier_bsi + self._slot_number_reg,
   5034         **kwargs)

File /usr/local/src/pysmurf/python/pysmurf/client/command/smurf_command.py:220, in SmurfCommandMixin._caget(self, pvname, write_log, execute, count, log_level, enable_poll, disable_poll, new_epics_root, yml, retry_on_fail, use_monitor, max_retry, timeout, **kwargs)
    218         self.log(f'Retry attempt {n_retry+1} of {max_retry}')
    219         #ret = epics.caget(pvname, count=count, use_monitor=use_monitor, **kwargs)
--> 220         ret = self._pv_cache[pvname].get(count=count,
    221                                          use_monitor=use_monitor,
    222                                          timeout=timeout,
    223                                          **kwargs)
    224         n_retry += 1
    226 # After retries, raise error

File /usr/local/lib/python3.8/dist-packages/epics/pv.py:484, in PV.get(self, count, as_string, as_numpy, timeout, with_ctrlvars, use_monitor)
    462 def get(self, count=None, as_string=False, as_numpy=True,
    463         timeout=None, with_ctrlvars=False, use_monitor=True):
    464     """returns current value of PV.  Use the options:
    465     count       explicitly limit count for array data
    466     as_string   flag(True/False) to get a string representation
   (...)
    482     this method will raise the exception ChannelAccessGetFailure.
    483     """
--> 484     data = self.get_with_metadata(count=count, as_string=as_string,
    485                                   as_numpy=as_numpy, timeout=timeout,
    486                                   with_ctrlvars=with_ctrlvars,
    487                                   use_monitor=use_monitor)
    488     return (data['value']
    489             if data is not None
    490             else None)

File /usr/local/lib/python3.8/dist-packages/epics/pv.py:47, in _ensure_context.<locals>.wrapped(self, *args, **kwargs)
     45     raise RuntimeError('Expected CA context is unset')
     46 elif expected_context == initial_context:
---> 47     return func(self, *args, **kwargs)
     49 # If not using the expected context, switch to it here:
     50 if initial_context is not None:

File /usr/local/lib/python3.8/dist-packages/epics/pv.py:563, in PV.get_with_metadata(self, count, as_string, as_numpy, timeout, with_ctrlvars, form, use_monitor, as_namespace)
    558     count = self._args['count']
    560 # ca.get_with_metadata will handle multiple requests for the same
    561 # PV internally, so there is no need to change between
    562 # `get_with_metadata` and `get_complete_with_metadata` here.
--> 563 md = ca.get_with_metadata(
    564     self.chid, ftype=ftype, count=count, timeout=timeout,
    565     as_numpy=as_numpy)
    566 if md is None:
    567     # Get failed. Indicate with a `None` as the return value
    568     return

File /usr/local/lib/python3.8/dist-packages/epics/ca.py:641, in withMaybeConnectedCHID.<locals>.wrapper(*args, **kwds)
    639         timeout = kwds.get('timeout', DEFAULT_CONNECTION_TIMEOUT)
    640         connect_channel(chid, timeout=timeout)
--> 641 return fcn(*args, **kwds)

File /usr/local/lib/python3.8/dist-packages/epics/ca.py:1396, in get_with_metadata(chid, ftype, count, wait, timeout, as_string, as_numpy)
   1393         PySEVCHK('get', ret)
   1395 if wait:
-> 1396     return get_complete_with_metadata(chid, count=count, ftype=ftype,
   1397                                       timeout=timeout, as_string=as_string,
   1398                                       as_numpy=as_numpy)

File /usr/local/lib/python3.8/dist-packages/epics/ca.py:641, in withMaybeConnectedCHID.<locals>.wrapper(*args, **kwds)
    639         timeout = kwds.get('timeout', DEFAULT_CONNECTION_TIMEOUT)
    640         connect_channel(chid, timeout=timeout)
--> 641 return fcn(*args, **kwds)

File /usr/local/lib/python3.8/dist-packages/epics/ca.py:1537, in get_complete_with_metadata(chid, ftype, count, timeout, as_string, as_numpy)
   1535 if isinstance(full_value, Exception):
   1536     get_failure_reason = full_value
-> 1537     raise get_failure_reason
   1539 # NOTE: unpacking happens for each requester; this could potentially be put
   1540 # in the get callback itself. (different downside there...)
   1541 extended_data, _ = full_value

ChannelAccessGetFailure: Get failed; status code: 152

When we hammer, the connection resumes, so we don't think it's likely to be a fiber issue. This still persists upon restarting the smurf-jupyter docker.

[jlashner]

Thanks for posting this. Just want to add logs from the smurf-streamer from when this was happening (in /data/logs/17047/1704737051/smurf-streamer-s5.log on smurf-so6-lat):

      1 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AppTop.AppCore.RtmCryoDet.SpiCryo.read:'Memory Error for AMCc.FpgaTopLevel.AppTop.AppCore.RtmCryoDet.SpiCryo.read at               address 0x82100004 Timeout waiting for register transaction message response'
      2 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AppTop.AppCore.RtmCryoDet.SpiCryo.read:Error reading value from variable 'AMCc.FpgaTopLevel.AppTop.AppCore.RtmCryoDet.             SpiCryo.read'
      3 1704736715.17366:pyrogue.epicsV3.Value: Error getting values from epics: smurf_server_s5:AMCc:FpgaTopLevel:AppTop:AppCore:RtmCryoDet:SpiCryo:read
      4                                                                                                     
      5 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId:'Memory Error for AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId at address           0x7000080 Timeout waiting for register transaction message response'
      6 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId:Error reading value from variable 'AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.            CrateId'
      7 1704736720.159629:pyrogue.epicsV3.Value: Error getting values from epics: smurf_server_s5:AMCc:FpgaTopLevel:AmcCarrierCore:AmcCarrierBsi:CrateId
      8                                                                                                     
      9 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId:'Memory Error for AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId at address           0x7000080 Timeout waiting for register transaction message response'
     10 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId:Error reading value from variable 'AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.            CrateId'
     11 1704736725.269076:pyrogue.epicsV3.Value: Error getting values from epics: smurf_server_s5:AMCc:FpgaTopLevel:AmcCarrierCore:AmcCarrierBsi:CrateId
     12                                                                                                     
     13 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AppTop.AppCore.RtmCryoDet.SpiCryo.read:'Memory Error for AMCc.FpgaTopLevel.AppTop.AppCore.RtmCryoDet.SpiCryo.read at               address 0x82100004 Timeout waiting for register transaction message response'
     14 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AppTop.AppCore.RtmCryoDet.SpiCryo.read:Error reading value from variable 'AMCc.FpgaTopLevel.AppTop.AppCore.RtmCryoDet.             SpiCryo.read'
     15 1704737003.258483:pyrogue.epicsV3.Value: Error getting values from epics: smurf_server_s5:AMCc:FpgaTopLevel:AppTop:AppCore:RtmCryoDet:SpiCryo:read
     16                                                                                                     
     17 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId:'Memory Error for AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId at address           0x7000080 Timeout waiting for register transaction message response'
     18 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId:Error reading value from variable 'AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.            CrateId'
     19 1704737008.401363:pyrogue.epicsV3.Value: Error getting values from epics: smurf_server_s5:AMCc:FpgaTopLevel:AmcCarrierCore:AmcCarrierBsi:CrateId
     20                                                                                                     
     21 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId:'Memory Error for AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId at address           0x7000080 Timeout waiting for register transaction message response'
     22 ERROR:pyrogue.Variable.RemoteVariable.AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.CrateId:Error reading value from variable 'AMCc.FpgaTopLevel.AmcCarrierCore.AmcCarrierBsi.            CrateId'
     23 1704737013.505024:pyrogue.epicsV3.Value: Error getting values from epics: smurf_server_s5:AMCc:FpgaTopLevel:AmcCarrierCore:AmcCarrierBsi:CrateId