Skip to content

Commit cdd919a

Browse files
authored
Merge pull request #130 from kneasle/friendly-logging
Make Wheatley's logging friendlier
2 parents 8e495f2 + 056d6de commit cdd919a

File tree

5 files changed

+38
-39
lines changed

5 files changed

+38
-39
lines changed

CHANGE_LOG.md

Lines changed: 8 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,14 +1,19 @@
11
# 0.6.0 (W.I.P.)
2-
- Add support for loading CompLib urls (_including 'share' links to private comps_) with `--comp-url` (actually added in `0.5.0`).
2+
- Add support for loading CompLib urls (_including 'share' links to private comps_) with
3+
`--comp-url` (actually added in `0.5.0`).
34
- Add proper support for backstroke starts (with 3 rows of rounds for `--up-down-in`).
4-
- Allow support of the new tower sizes - `5`, `14` and `16`.
5+
- Add `--start-index` to specify how many rows into a lead of a method Wheatley should start.
56
- Add `-v`/`--verbose` and `-q`/`--quiet` to change how much stuff Wheatley prints.
67
- Print summary string of what Wheatley is going to ring before every touch.
78
- Tell users when Wheatley is waiting for `Look To`.
8-
- Add `--start-index` to specify how many rows into a lead of a method Wheatley should start.
9+
- Make the error messages friendlier.
10+
- Moved some overly verbose `INFO` messages into `DEBUG`.
11+
- Capped all numbers to 3 decimal places.
12+
- Made debug 'wait' logging slightly less verbose.
913

1014
## Technical changes
1115

16+
- Allow support of the new tower sizes - `5`, `14` and `16`.
1217
- Allow Wheatley to ring with any (positive) number of cover bells.
1318
- Change place notation parsing to comply with CompLib and the XML specification.
1419
- Add full static typing, and fix some `None`-related bugs.

wheatley/main.py

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -202,8 +202,6 @@ def server_main(override_args: Optional[List[str]], stop_on_join_tower: bool) ->
202202
with tower:
203203
tower.wait_loaded()
204204

205-
print("=== LOADED ===")
206-
207205
if args.look_to_time is not None:
208206
bot.look_to_has_been_called(args.look_to_time)
209207

@@ -425,8 +423,6 @@ def console_main(override_args: Optional[List[str]], stop_on_join_tower: bool) -
425423
with tower:
426424
tower.wait_loaded()
427425

428-
print("=== LOADED ===")
429-
430426
if not stop_on_join_tower:
431427
bot.main_loop()
432428

wheatley/rhythm/regression.py

Lines changed: 12 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -99,9 +99,14 @@ def __init__(self, inertia: float, peal_speed: float=178, handstroke_gap: float=
9999
self._max_bells_in_dataset = max_bells_in_dataset
100100

101101
self.stage = 0
102+
# Two values that determine the linear relationship between ringing and real time - these are set by
103+
# the regression algorithm and used to decide when Wheatley's bells should be rung
102104
self._start_time = 0.0
103105
self._blow_interval = 0.0
104106

107+
# The actual time that the current touch started (this is unaffected by the regression algorithm)
108+
self._real_start_time = 0.0
109+
105110
self._number_of_user_controlled_bells = 0
106111
# Maps a bell and a stroke to the row number and place which that bell is next expected to ring at
107112
# that stroke
@@ -118,7 +123,7 @@ def _add_data_point(self, row_number: int, place: int, real_time: float, weight:
118123
self.data_set.append((blow_time, real_time, weight))
119124

120125
for (b, r, w) in self.data_set:
121-
self.logger.debug(f" {b}\t{r}\t{w}")
126+
self.logger.debug(f"Datapoint: {b:4.1f} {r - self._real_start_time:8.3f}s {w:.3f}")
122127

123128
# Only calculate the regression line if there are at least two datapoints, otherwise
124129
# just store the datapoint
@@ -135,7 +140,7 @@ def _add_data_point(self, row_number: int, place: int, real_time: float, weight:
135140
self._blow_interval = lerp(new_blow_interval, self._blow_interval,
136141
regression_preferred_inertia)
137142

138-
self.logger.debug(f"Bell interval: {self._blow_interval}")
143+
self.logger.debug(f"Bell interval: {self._blow_interval:.3f}")
139144

140145
# Filter out datapoints with extremely low weights
141146
self.data_set = list(filter(lambda d: d[2] > WEIGHT_REJECTION_THRESHOLD, self.data_set))
@@ -184,8 +189,7 @@ def expect_bell(self, expected_bell: Bell, row_number: int, place: int, expected
184189
_should_ have been in the ringing, and so can use that knowledge to inform the speed of the
185190
ringing.
186191
"""
187-
self.logger.debug(f"Expected bell {expected_bell} at index {row_number}:{place} at stroke"
188-
+ f"{expected_stroke}")
192+
self.logger.debug(f"Expected bell {expected_bell} at index {row_number}:{place} at {expected_stroke}")
189193
self._expected_bells[(expected_bell, expected_stroke)] = (row_number, place)
190194

191195
def change_setting(self, key: str, value: Any) -> None:
@@ -220,7 +224,7 @@ def on_bell_ring(self, bell: Bell, stroke: Stroke, real_time: float) -> None:
220224
expected_blow_time = self.index_to_blow_time(row_number, place)
221225
diff = self.real_time_to_blow_time(real_time) - expected_blow_time
222226

223-
self.logger.info(f"{bell} off by {diff} places")
227+
self.logger.debug(f"{bell} off by {diff:.3f} places")
224228

225229
# If this was the first bell, then overwrite the start_time to update
226230
# the regression line
@@ -260,6 +264,9 @@ def initialise_line(self, stage: int, user_controls_treble: bool, start_time: fl
260264
seconds_per_whole_pull = peal_speed_seconds / 2520 # 2520 = 5040 / 2
261265
self._blow_interval = seconds_per_whole_pull / (self.stage * 2 + 1)
262266

267+
# Set real start time to make debug output more succinct
268+
self._real_start_time = start_time
269+
263270
if not user_controls_treble:
264271
# If the bot is ringing the first bell, then add it as a datapoint anyway, so that after
265272
# the 2nd bell is rung, a regression line can be made

wheatley/rhythm/wait_for_user.py

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -54,16 +54,18 @@ def wait_for_bell_time(self, current_time: float, bell: Bell, row_number: int, p
5454
user_controlled, stroke)
5555
if user_controlled:
5656
delay_for_user = 0.0
57+
self.logger.debug(f"Waiting for {bell}...")
5758
while bell in self._expected_bells[stroke]:
5859
self.sleep(self.sleep_time)
5960
delay_for_user += self.sleep_time
60-
self.logger.debug(f"Waiting for {bell}")
6161
if self._should_return_to_mainloop:
62+
self.logger.debug("Returning to mainloop")
6263
break
64+
self.logger.debug(f"Finished waiting for {bell}")
6365

6466
if delay_for_user:
6567
self.delay += delay_for_user
66-
self.logger.info(f"Delayed for {delay_for_user}")
68+
self.logger.debug(f"Delayed for {delay_for_user:.3f}s")
6769

6870
# Reset the flag to say that we've returned to the mainloop
6971
self._should_return_to_mainloop = False

wheatley/tower.py

Lines changed: 14 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -76,11 +76,7 @@ def ring_bell(self, bell: Bell, expected_stroke: Stroke) -> bool:
7676

7777
bell_num: int = bell.number
7878
is_handstroke: bool = stroke.is_hand()
79-
self._emit(
80-
"c_bell_rung",
81-
{"bell": bell_num, "stroke": is_handstroke, "tower_id": self.tower_id},
82-
""
83-
)
79+
self._emit("c_bell_rung", {"bell": bell_num, "stroke": is_handstroke, "tower_id": self.tower_id})
8480

8581
return True
8682
except Exception as e:
@@ -113,27 +109,23 @@ def get_stroke(self, bell: Bell) -> Optional[Stroke]:
113109

114110
def make_call(self, call: str) -> None:
115111
""" Broadcasts a given call to the other users of the tower. """
116-
self._emit("c_call", {"call": call, "tower_id": self.tower_id}, f"Call '{call}'")
112+
self.logger.info(f"(EMIT): Calling '{call}'")
113+
self._emit("c_call", {"call": call, "tower_id": self.tower_id})
117114

118115
def set_at_hand(self) -> None:
119116
""" Sets all the bells at hand. """
120-
self._emit("c_set_bells", {"tower_id": self.tower_id}, "Set at hand")
117+
self.logger.info("(EMIT): Setting bells at handstroke")
118+
self._emit("c_set_bells", {"tower_id": self.tower_id})
121119

122120
def set_number_of_bells(self, number: int) -> None:
123121
""" Set the number of bells in the tower. """
124-
self._emit(
125-
"c_size_change",
126-
{"new_size": number, "tower_id": self.tower_id},
127-
f"Set number of bells '{number}'"
128-
)
122+
self.logger.info(f"(EMIT): Setting size to {number}")
123+
self._emit("c_size_change", {"new_size": number, "tower_id": self.tower_id})
129124

130125
def set_is_ringing(self, value: bool) -> None:
131126
""" Broadcast to all the users that Wheatley has started or stopped ringing. """
132-
self._emit(
133-
"c_wheatley_is_ringing",
134-
{"is_ringing": value, "tower_id": self.tower_id},
135-
f"Setting is ringing to {value}"
136-
)
127+
self.logger.info(f"(EMIT): Telling RR clients to set is_ringing to {value}")
128+
self._emit("c_wheatley_is_ringing", {"is_ringing": value, "tower_id": self.tower_id})
137129

138130
def wait_loaded(self) -> None:
139131
""" Pause the thread until the socket-io connection is open and stable. """
@@ -155,7 +147,7 @@ def _create_client(self) -> None:
155147
""" Generates the socket-io client and attaches callbacks. """
156148
self._socket_io_client = socketio.Client()
157149
self._socket_io_client.connect(self._url)
158-
self.logger.info(f"Connected to {self._url}")
150+
self.logger.debug(f"Connected to {self._url}")
159151

160152
self._socket_io_client.on("s_bell_rung", self._on_bell_rung)
161153
self._socket_io_client.on("s_global_state", self._on_global_bell_state)
@@ -241,15 +233,16 @@ def _on_user_list(self, user_list: JSON) -> None:
241233

242234
def _join_tower(self) -> None:
243235
""" Joins the tower as an anonymous user. """
236+
self.logger.info(f"(EMIT): Joining tower {self.tower_id}")
244237
self._emit(
245238
"c_join",
246239
{"anonymous_user": True, "tower_id": self.tower_id},
247-
f"Joining tower {self.tower_id}"
248240
)
249241

250242
def _request_global_state(self) -> None:
251243
""" Send a request to the server to get the current state of the tower. """
252-
self._emit('c_request_global_state', {"tower_id": self.tower_id}, "Request state")
244+
self.logger.debug("(EMIT): Requesting global state.")
245+
self._emit('c_request_global_state', {"tower_id": self.tower_id})
253246

254247
def _on_bell_rung(self, data: JSON) -> None:
255248
""" Callback called when the client receives a signal that a bell has been rung. """
@@ -328,16 +321,13 @@ def _on_call(self, data: Dict[str, str]) -> None:
328321
if not found_callback:
329322
self.logger.warning(f"No callback found for '{call}'")
330323

331-
def _emit(self, event: str, data: Any, message: str) -> None:
324+
def _emit(self, event: str, data: Any) -> None:
332325
""" Emit a socket-io signal. """
333326
if self._socket_io_client is None or not self._socket_io_client.connected:
334327
raise SocketIOClientError("Not Connected")
335328

336329
self._socket_io_client.emit(event, data)
337330

338-
if message:
339-
self.logger.info(f"EMIT: {message}")
340-
341331
@staticmethod
342332
def _bells_set_at_hand(number: int) -> List[Stroke]:
343333
""" Returns the representation of `number` bells, all set at handstroke. """
@@ -346,4 +336,3 @@ def _bells_set_at_hand(number: int) -> List[Stroke]:
346336

347337
class SocketIOClientError(Exception):
348338
"""Errors related to SocketIO Client"""
349-
pass

0 commit comments

Comments
 (0)