`take_bias_steps` fails and hits UnboundLocalError

[BrianJKoopman]

From a crash last night on satp1 it looks like operations.bias_steps.take_bias_steps sometimes fails in this try block and hits an UnboundLocalError due to the variable init_current_mode not being set when an exception is raised during the try:

sodetlib/sodetlib/operations/bias_steps.py

Lines 1169 to 1209 in c7bc197

	try:
	dc_biases = initial_dc_biases
	init_current_mode = sdl.get_current_mode_array(S)
	if high_current_mode:
	dc_biases = dc_biases / S.high_low_current_ratio
	step_voltage /= S.high_low_current_ratio
	sdl.set_current_mode(S, bgs, 1)
	S.log(f"Waiting {hcm_wait_time} sec after switching to hcm")
	time.sleep(hcm_wait_time)
	bsa = BiasStepAnalysis(S, cfg, bgs, run_kwargs=run_kwargs)
	bsa.sid = sdl.stream_g3_on(
	S, tag=g3_tag, channel_mask=channel_mask, downsample_factor=1,
	filter_disable=True, subtype=stream_subtype, enable_compression=enable_compression
	)
	bsa.start = time.time()
	for bg in bgs:
	if use_waveform:
	play_bias_steps_waveform(
	S, cfg, bg, step_duration, step_voltage,
	num_steps=nsteps
	)
	else:
	play_bias_steps_dc(
	S, cfg, bg, step_duration, step_voltage,
	num_steps=nsteps, dacs=dacs,
	)
	bsa.stop = time.time()
	finally:
	sdl.stream_g3_off(S)
	# Restores current mode to initial values
	sdl.set_current_mode(S, np.where(init_current_mode == 0)[0], 0)
	sdl.set_current_mode(S, np.where(init_current_mode == 1)[0], 1)
	S.set_downsample_factor(initial_ds_factor)
	S.set_filter_disable(initial_filter_disable)

The full traceback:

Traceback (most recent call last):
  File "<string>", line 30, in <module>
  File "/usr/local/lib/python3.10/dist-packages/sorunlib/smurf.py", line 209, in take_bgmap
    check_response(resp)
  File "/usr/local/lib/python3.10/dist-packages/sorunlib/_internal.py", line 35, in check_response
    raise RuntimeError(error)
RuntimeError: Task failed to complete successfully.
OCSReply: OK : Operation "take_bgmap" is currently not running (FAILED).
  take_bgmap[session=541]; status=done with ERROR 61.2 s ago, took 4.6 s
  messages (4 of 4):
    1698922951.696 Status is now "starting".
    1698922951.699 Status is now "running".
    1698922956.276 CRASH: [Failure instance: Traceback: <class 'UnboundLocalError'>: local variable 'init_current_mode' referenced before assignment
/usr/lib/python3.8/threading.py:932:_bootstrap_inner
/usr/lib/python3.8/threading.py:870:run
/usr/local/lib/python3.8/dist-packages/twisted/_threads/_threadworker.py:47:work
/usr/local/lib/python3.8/dist-packages/twisted/_threads/_team.py:182:doWork
--- <exception caught here> ---
/usr/local/lib/python3.8/dist-packages/twisted/python/threadpool.py:244:inContext
/usr/local/lib/python3.8/dist-packages/twisted/python/threadpool.py:260:<lambda>
/usr/local/lib/python3.8/dist-packages/twisted/python/context.py:117:callWithContext
/usr/local/lib/python3.8/dist-packages/twisted/python/context.py:82:callWithContext
/usr/local/lib/python3.8/dist-packages/socs/agents/pysmurf_controller/agent.py:654:take_bgmap
/usr/local/src/pysmurf/python/pysmurf/client/util/pub.py:50:wrapper
/sodetlib/sodetlib/operations/bias_steps.py:1067:take_bgmap
/usr/local/src/pysmurf/python/pysmurf/client/util/pub.py:50:wrapper
/sodetlib/sodetlib/operations/bias_steps.py:1205:take_bias_steps
]
    1698922956.284 Status is now "done".
  other keys in .session: op_code, data

[jlashner]

To give some more context... here are the full logs for the bgmap from the pysmurf-controller:

2023-11-02T11:02:31+0000 take_bgmap:541 Status is now "running".
2023-11-02T11:02:32+0000 [ 2023-11-02 11:02:32 ]  filename explicitly given. Overriding last_tune bool in load_tune.
2023-11-02T11:02:32+0000 [ 2023-11-02 11:02:32 ]  Done loading tuning
2023-11-02T11:02:32+0000 [ 2023-11-02 11:02:32 ]  Loading tune data for all bands=[0, 1, 2, 3, 4, 5, 6, 7].
2023-11-02T11:02:35+0000 [ 2023-11-02 11:02:35 ]  Session-id returned 0! Will try to obtain from file path
2023-11-02T11:02:35+0000 [ 2023-11-02 11:02:35 ]  Could not extract session id from filepath! Setting to 0
2023-11-02T11:02:35+0000 [ 2023-11-02 11:02:35 ]  caput smurf_server_s7:AMCc:SmurfProcessor:FileWriter:Close 1
2023-11-02T11:02:35+0000 [ 2023-11-02 11:02:35 ]  caput smurf_server_s7:AMCc:FpgaTopLevel:AppTop:AppCore:enableStreaming 0
2023-11-02T11:02:35+0000 [ 2023-11-02 11:02:35 ]  Waiting 0.15 seconds after...
2023-11-02T11:02:36+0000 [ 2023-11-02 11:02:36 ]  Done waiting.
2023-11-02T11:02:36+0000 [ 2023-11-02 11:02:36 ]  Waiting for g3 file to close out
2023-11-02T11:02:36+0000 take_bgmap:541 CRASH: [Failure instance: Traceback: <class 'UnboundLocalError'>: local variable 'init_current_mode' referenced before assignment
/usr/lib/python3.8/threading.py:932:_bootstrap_inner
/usr/lib/python3.8/threading.py:870:run
/usr/local/lib/python3.8/dist-packages/twisted/_threads/_threadworker.py:47:work
/usr/local/lib/python3.8/dist-packages/twisted/_threads/_team.py:182:doWork
--- <exception caught here> ---
/usr/local/lib/python3.8/dist-packages/twisted/python/threadpool.py:244:inContext
/usr/local/lib/python3.8/dist-packages/twisted/python/threadpool.py:260:<lambda>
/usr/local/lib/python3.8/dist-packages/twisted/python/context.py:117:callWithContext
/usr/local/lib/python3.8/dist-packages/twisted/python/context.py:82:callWithContext
/usr/local/lib/python3.8/dist-packages/socs/agents/pysmurf_controller/agent.py:654:take_bgmap
/usr/local/src/pysmurf/python/pysmurf/client/util/pub.py:50:wrapper
/sodetlib/sodetlib/operations/bias_steps.py:1067:take_bgmap
/usr/local/src/pysmurf/python/pysmurf/client/util/pub.py:50:wrapper
/sodetlib/sodetlib/operations/bias_steps.py:1205:take_bias_steps
]
2023-11-02T11:02:36+0000 take_bgmap:541 Status is now "done".

In particular, the lines:

2023-11-02T11:02:35+0000 [ 2023-11-02 11:02:35 ]  Session-id returned 0! Will try to obtain from file path
2023-11-02T11:02:35+0000 [ 2023-11-02 11:02:35 ]  Could not extract session id from filepath! Setting to 0

point to something else going wrong.

The only way I think init_current_mode could possibly be unbound, is if the line:

     init_current_mode = sdl.get_current_mode_array(S) 

errored out, which must be due to a epics caget failure. I think this means this is either caused by

• failing fiber connection
• GIL being held by the smurf-streamer (maybe data was being streamed?), so it was not able to poll the epics register in time...