Skip to content

Commit 218c19d

Browse files
gabrielgazollalblgabrielgazollalbl
committed
fix zmq start stop messages
1 parent ca59307 commit 218c19d

5 files changed

Lines changed: 593 additions & 20 deletions

File tree

‎report04-23-2025.md‎

Lines changed: 245 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,245 @@
1+
# Bug Fix Report — April 23, 2026
2+
3+
**Project:** splash_timepix
4+
**Reported by:** tpx
5+
**Session date:** 2026-04-23
6+
**Files modified:** `src/splash_timepix/simulator_cli.py`, `src/splash_timepix/app.py`, `src/splash_timepix/ui/main.py`
7+
8+
---
9+
10+
## Summary
11+
12+
Five bugs were identified and fixed in this session. Three were reported in GitHub issue #11
13+
(simulator CLI stop/start lifecycle), one was a Python scoping error introduced during the
14+
fix, and one was a design-level issue affecting real-acquisition mode (no-count runs).
15+
16+
---
17+
18+
## Bug 1 — `stop` command did not send a ZMQ stop message
19+
20+
**Issue #11 / item 1**
21+
**File:** `src/splash_timepix/simulator_cli.py`
22+
23+
### Description
24+
25+
When using the interactive simulator CLI and typing `stop`, no ZMQ stop message was published
26+
to downstream subscribers (e.g. ArroyoXPS). The stop message only appeared when typing `quit`,
27+
which terminates the entire CLI session.
28+
29+
### Root cause
30+
31+
`stop_auto_sending()` stopped the sending thread by setting `self.running = False` and joined
32+
the thread, but it never closed the TCP socket. The server (`app.py`) only emits a ZMQ stop
33+
message when it detects a TCP client disconnect. Because the socket stayed open, the server
34+
never saw a disconnect and never sent the stop.
35+
36+
Additionally, if the stream finished naturally (the timer expired before the user typed `stop`),
37+
`self.running` was already `False` and the method returned early via `if not self.running: return`,
38+
meaning `disconnect()` was never reached in any code path.
39+
40+
### Fix
41+
42+
`stop_auto_sending()` now always calls `self.disconnect()` regardless of whether the stream was
43+
manually stopped or ended naturally. The early-return guard was replaced with a conditional
44+
block that still prints the appropriate message but falls through to `disconnect()`.
45+
46+
`start_auto_sending()` was also updated to call `self.connect()` automatically if the socket is
47+
`None` (i.e. after a previous stop disconnected it), so the user can issue `start` again without
48+
manually reconnecting.
49+
50+
---
51+
52+
## Bug 2 — Flush counter and scan UUID not reset between runs
53+
54+
**Issue #11 / item 2**
55+
**File:** `src/splash_timepix/simulator_cli.py` (same fix as Bug 1)
56+
57+
### Description
58+
59+
After issuing `stop` followed by a second `start`, the flush numbers shown in the server log
60+
and in ArroyoXPS continued from where the previous run left off (e.g. `flush #11`, `#12`, …)
61+
instead of restarting from `flush #1`. The scan UUID (`scan_name`) was also the same as the
62+
previous run, meaning the two acquisitions could not be distinguished.
63+
64+
### Root cause
65+
66+
The server (`app.py`) resets all acquisition state — including `flush_count`, `cycle_count`,
67+
`scan_name` (UUID), and all accumulators — only when it detects a **new TCP client connection**
68+
(the `was_client_connected` False→True transition). Because `stop` never disconnected the TCP
69+
socket (Bug 1), the server never saw a new connection on the second `start`, so no reset occurred.
70+
71+
### Fix
72+
73+
Same fix as Bug 1: `stop_auto_sending()` disconnects the socket. On the next `start`,
74+
`start_auto_sending()` reconnects. The server detects a new client, generates a fresh UUID
75+
via `str(uuid.uuid4())`, resets all counters, and clears the accumulator arrays before the
76+
new run begins.
77+
78+
---
79+
80+
## Bug 3 — `start N` produced one fewer event message than expected
81+
82+
**Issue #11 / item 3**
83+
**File:** `src/splash_timepix/app.py`
84+
85+
### Description
86+
87+
When running `start 10` with `tdc 10` and `flush-interval 1.0` (so `flush_every_n_cycles = 10`),
88+
users observed 9 ZMQ event messages instead of the expected 10. The final cycle's accumulated
89+
data was never published.
90+
91+
### Root cause
92+
93+
The flush is triggered at the **start of the next TDC cycle** that crosses the flush boundary,
94+
not at the end of the current one. With `flush_every_n_cycles = N`, the condition is:
95+
96+
```python
97+
if cycle_count > 0 and cycle_count % flush_every_n_cycles == 0:
98+
# flush
99+
```
100+
101+
This check runs **before** incrementing `cycle_count`. As a result, with 100 TDC pulses
102+
(10 Hz × 10 s) and N = 10, flushes fire at TDC #11, 21, 31 … 91 — producing 9 flushes.
103+
The data accumulated during cycles 91–100 was never flushed because no 101st TDC arrived
104+
to trigger it.
105+
106+
### Fix
107+
108+
A `do_final_flush()` helper function was added to `app.py`. It merges any remaining data in
109+
`local_accumulator` into `xyt_array`, publishes it as one final ZMQ event message, and
110+
increments `flush_count`. This function is called at all three stop sites (client disconnect
111+
with `--exit-on-disconnect`, ordinary client disconnect, and server shutdown `finally` block)
112+
immediately before the stop message is queued. With the same example above, users now receive
113+
10 event messages followed by the stop message.
114+
115+
---
116+
117+
## Bug 4 — `UnboundLocalError` crash in `do_final_flush`
118+
119+
**File:** `src/splash_timepix/app.py`
120+
121+
### Description
122+
123+
After deploying Bug 3's fix, the server crashed with:
124+
125+
```
126+
UnboundLocalError: cannot access local variable 'xyt_array'
127+
where it is not associated with a value
128+
```
129+
130+
This caused the streaming server to exit unexpectedly on the first client disconnect, making
131+
the second `start` fail with "Connection refused".
132+
133+
### Root cause
134+
135+
Python treats any name that appears on the left-hand side of `+=` as a **local variable** in
136+
that function's scope, even for NumPy arrays where `+=` calls `__iadd__` in-place. Inside
137+
`do_final_flush`, the line `xyt_array += local_accumulator` caused Python to treat `xyt_array`
138+
as a local that had never been assigned, raising `UnboundLocalError` before the operation ran.
139+
140+
### Fix
141+
142+
Added `xyt_array` to the `nonlocal` declaration in `do_final_flush`:
143+
144+
```python
145+
nonlocal flush_count, xyt_array
146+
```
147+
148+
This is the standard Python fix for in-place operators (`+=`, `-=`, etc.) on variables from
149+
an enclosing scope inside a nested function.
150+
151+
---
152+
153+
## Bug 5 — ZMQ start message not sent in real-acquisition mode with zero counts
154+
155+
**File:** `src/splash_timepix/app.py`
156+
157+
### Description
158+
159+
In real detector mode (Start button in the UI), when no particle hits were arriving (dark
160+
measurement, beam off, low flux), no ZMQ start message was published when the user clicked
161+
Start. Instead, both the start message and the stop message arrived simultaneously when the
162+
user clicked Stop, making it impossible for downstream subscribers (e.g. ArroyoXPS) to set up
163+
for an incoming acquisition.
164+
165+
### Root cause
166+
167+
The start message was sent inside `data_callback`, which is only invoked by the socket server
168+
when a batch of packets has been parsed. With zero counts, no packets arrive, the callback is
169+
never called, and `start_message_sent` stays `False`. When Stop is clicked, Serval sends a
170+
shutter-close control packet as part of measurement teardown. This triggers `data_callback`
171+
for the first time, causing the start message to fire — but at the same moment that the stop
172+
sequence is already in progress.
173+
174+
### Fix
175+
176+
The start message is now also sent in the **main loop** the moment the TCP client (`live-cli`
177+
or the simulator) connects, within the `server.client_connected` False→True transition block.
178+
This ensures the start message reaches subscribers before any data arrives, even when the
179+
detector is running at zero counts.
180+
181+
The `data_callback` path is kept as a fallback (guarded by `start_message_sent`) for cases
182+
where data arrives before the main loop's 1-second sleep cycle wakes to detect the connection.
183+
Only one start message is ever sent per run.
184+
185+
**Trade-off acknowledged:** `acquisition_start_time` (used for `acquisition_duration_s` in the
186+
stop message) is now measured from client-connect time rather than first-data time. For zero-count
187+
runs this is more meaningful. For high-count runs the difference is a few seconds. A future
188+
refinement could track `first_data_time` separately and use it for duration when data was present.
189+
190+
---
191+
192+
## Additional UI Fix — Race condition in simulator/replay stop
193+
194+
**File:** `src/splash_timepix/ui/main.py`
195+
196+
### Description
197+
198+
When Stop was clicked in simulator or replay mode, the UI killed both the simulator process
199+
and the streaming server immediately and in sequence. The final flush and ZMQ stop message
200+
(which take ~1–2 seconds to complete after the simulator disconnects) were never published
201+
because the streaming server was terminated before it could complete the sequence.
202+
203+
### Root cause
204+
205+
The stop sequence was:
206+
207+
```python
208+
stop_process("simulator") # kill simulator, OS closes TCP socket
209+
stop_process("streaming") # kill streaming server immediately ← race
210+
_acquiring = False
211+
```
212+
213+
The streaming server needed ~1.5 s after TCP disconnect to: detect the disconnect, run
214+
`do_final_flush()`, queue the ZMQ stop message, wait for the ZMQ worker to publish it (0.5 s
215+
sleep), and exit. Killing it immediately after the simulator gave it no time to do any of this.
216+
217+
### Fix
218+
219+
For simulator and replay modes, `_on_stop_requested` now kills **only** the data source
220+
(simulator or live-cli). The streaming server was already launched with `--exit-on-disconnect`
221+
by the UI, so it exits on its own after detecting the TCP disconnect, completing the full
222+
flush + ZMQ stop sequence first.
223+
224+
Acquisition completion (`_acquiring = False`, UI unlock, data save) is now driven by the
225+
`streaming` process exit event in `_on_process_stopped`, not by the simulator/live-cli exit.
226+
This guarantees that by the time the UI re-enables the Start button, the final ZMQ messages
227+
have already been published.
228+
229+
A 6-second safety timer (`_force_stop_streaming_if_still_running`) was added as a safety net:
230+
if the streaming server has not exited within 6 seconds of the data source being killed
231+
(e.g. due to a server hang or crash), it is force-killed and the UI is unblocked.
232+
233+
---
234+
235+
## Files changed
236+
237+
| File | Changes |
238+
|------|---------|
239+
| `src/splash_timepix/simulator_cli.py` | `stop_auto_sending()` always disconnects; `start_auto_sending()` auto-reconnects if socket is `None` |
240+
| `src/splash_timepix/app.py` | Added `do_final_flush()` helper called at all 3 stop sites; added `nonlocal xyt_array` to fix `UnboundLocalError`; start message now also sent on TCP client connect in main loop |
241+
| `src/splash_timepix/ui/main.py` | Simulator/replay stop no longer kills streaming server immediately; completion driven by streaming process exit; 6-second safety net added |
242+
243+
---
244+
245+
*Report generated: 2026-04-23*

‎src/splash_timepix/app.py‎

Lines changed: 78 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -486,6 +486,44 @@ def handle_tdc(tdc_ts):
486486
mask = pixel_indices > last_boundary
487487
bin_pixels(mask)
488488

489+
def do_final_flush() -> None:
490+
"""Flush any data remaining in the accumulator before sending a stop message.
491+
492+
The normal flush is triggered by an incoming TDC pulse closing the previous
493+
cycle. When a stream ends the last N partial cycles never see a closing TDC,
494+
so this helper is called at each stop site to publish that residual data as
495+
one last event message before the stop control message goes out.
496+
"""
497+
nonlocal flush_count, xyt_array
498+
499+
with xyt_lock:
500+
xyt_array += local_accumulator
501+
has_data = bool(np.any(xyt_array))
502+
if has_data:
503+
array_copy = xyt_array.copy()
504+
xyt_array.fill(0)
505+
506+
local_accumulator.fill(0)
507+
508+
if not has_data:
509+
return
510+
511+
flush_count += 1
512+
partial_cycles = cycle_count % flush_every_n_cycles if flush_every_n_cycles > 0 else cycle_count
513+
flush_metadata = {
514+
"scan_name": scan_name,
515+
"cycles_in_flush": partial_cycles,
516+
"total_cycles": cycle_count,
517+
"flush_number": flush_count,
518+
"pixels_discarded_before_trigger": int(pixels_before_trigger),
519+
"pixels_discarded_outside_window": int(pixels_outside_window),
520+
}
521+
try:
522+
xyt_queue.put_nowait((array_copy, flush_metadata))
523+
logger.info(f"Final flush #{flush_count}: {partial_cycles} partial cycles flushed before stop")
524+
except queue.Full:
525+
logger.warning("Processing queue full, dropping final flush")
526+
489527
# Set the callback
490528
server.set_data_callback(data_callback)
491529

@@ -536,6 +574,7 @@ def handle_tdc(tdc_ts):
536574
logger.info("Client disconnected, initiating shutdown...")
537575
# Send stop message before shutdown
538576
if message_queue is not None and start_message_sent and not stop_message_sent_on_disconnect:
577+
do_final_flush()
539578
acquisition_duration = (time.time() - acquisition_start_time) if acquisition_start_time else 0.0
540579
stop_msg = TimePixStop(
541580
scan_name=scan_name,
@@ -580,13 +619,46 @@ def handle_tdc(tdc_ts):
580619
local_accumulator.fill(0)
581620
logger.info(f"New client connected - resetting acquisition state. New scan: {scan_name}")
582621
print(f"New client connected - resetting acquisition state. New scan: {scan_name}")
622+
623+
# Send start message immediately on client connect so that ZMQ
624+
# subscribers receive it before any data — even when count rates
625+
# are zero and data_callback may never fire before STOP.
626+
# data_callback also tries to send the start message (guarded by
627+
# start_message_sent) as an immediate fallback for the first
628+
# data batch if the main loop is mid-sleep when data arrives.
629+
if message_queue is not None:
630+
acquisition_start_time = current_time
631+
start_msg = TimePixStart(
632+
scan_name=scan_name,
633+
tdc_frequency_hz=tdc_frequency,
634+
t_delta_ns=t_delta_ns,
635+
t_cycle_ns=t_cycle / 1e3,
636+
n_bins=n_bins,
637+
detector_size_x=detector_size_x,
638+
detector_size_y=detector_size_y,
639+
flush_interval_s=flush_interval,
640+
cycles_per_flush=max(1, int(flush_interval * tdc_frequency)),
641+
tdc_channel=tdc_ch,
642+
tdc_edge=tdc_edge,
643+
collapse_y=collapse_y,
644+
zmq_port=zmq_port,
645+
tcp_port=port,
646+
)
647+
try:
648+
message_queue.put_nowait(start_msg.model_dump())
649+
start_message_sent = True
650+
logger.info(f"Queued start message on connect for scan: {scan_name}")
651+
print(f"Queued start message on connect for scan: {scan_name}")
652+
except queue.Full:
653+
logger.warning("Message queue full, dropping start message on connect")
583654
elif not server.client_connected and was_client_connected:
584655
# Client just disconnected - send stop message
585656
heartbeat.set_state(ServerState.READY)
586657
was_client_connected = False
587658

588659
# Send stop message when client disconnects (even without --exit-on-disconnect)
589660
if message_queue is not None and start_message_sent and not stop_message_sent_on_disconnect:
661+
do_final_flush()
590662
acquisition_duration = (time.time() - acquisition_start_time) if acquisition_start_time else 0.0
591663
stop_msg = TimePixStop(
592664
scan_name=scan_name,
@@ -727,8 +799,12 @@ def handle_tdc(tdc_ts):
727799
print("\nShutting down server...")
728800

729801
finally:
730-
# Send stop message (only if we haven't already sent it on client disconnect)
731-
if message_queue is not None and not stop_message_sent_on_disconnect:
802+
# Send stop message only if a start was sent and stop hasn't been sent yet.
803+
# Guarding on start_message_sent prevents an orphan stop from being published
804+
# with the server's initial UUID when the client connection was never detected
805+
# (e.g. connect+disconnect happened within one main-loop sleep cycle).
806+
if message_queue is not None and start_message_sent and not stop_message_sent_on_disconnect:
807+
do_final_flush()
732808
acquisition_duration = (time.time() - acquisition_start_time) if acquisition_start_time else 0.0
733809
stop_msg = TimePixStop(
734810
scan_name=scan_name,

‎src/splash_timepix/simulator_cli.py‎

Lines changed: 17 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -98,6 +98,12 @@ def start_auto_sending(self, duration: float) -> None:
9898
print("Auto-sending is already running")
9999
return
100100

101+
# Reconnect if a previous stop disconnected the socket
102+
if self.socket is None:
103+
print("Reconnecting to server for new acquisition...")
104+
if not self.connect():
105+
return
106+
101107
self.running = True
102108
self.send_thread = threading.Thread(target=self._auto_send_worker, args=(duration,), daemon=True)
103109
self.send_thread.start()
@@ -108,14 +114,17 @@ def start_auto_sending(self, duration: float) -> None:
108114

109115
def stop_auto_sending(self) -> None:
110116
"""Stop automatic message sending."""
111-
if not self.running:
112-
print("Auto-sending is not running")
113-
return
114-
115-
self.running = False
116-
if self.send_thread and self.send_thread.is_alive():
117-
self.send_thread.join(timeout=5)
118-
print("Stopped auto-sending messages")
117+
if self.running:
118+
self.running = False
119+
if self.send_thread and self.send_thread.is_alive():
120+
self.send_thread.join(timeout=5)
121+
print("Stopped auto-sending messages")
122+
# Disconnect regardless of whether the stream was manually stopped or
123+
# ended naturally (timer expired). This is what signals end-of-acquisition
124+
# to the server so it publishes a ZMQ stop message. Safe to call even
125+
# when already disconnected. A reconnect happens automatically the next
126+
# time start_auto_sending() is called.
127+
self.disconnect()
119128

120129
def run_blocking(self, duration: float) -> None:
121130
"""

0 commit comments

Comments
 (0)