refactor: Conditional log message evaluation (#335)

Closes #316

addons/netfox.extras/plugin.cfg

@@ -3,5 +3,5 @@
 name="netfox.extras"
 description="Game-specific utilities for Netfox"
 author="Tamas Galffy"
-version="1.13.0"
+version="1.13.1"
 script="netfox-extras.gd"

addons/netfox.extras/state-machine/rewindable-state-machine.gd

@@ -53,7 +53,7 @@ func transition(new_state_name: StringName) -> void:
 		return
 
 	if not _available_states.has(new_state_name):
-		_logger.warning("Attempted to transition from state '%s' into unknown state '%s'" % [state, new_state_name])
+		_logger.warning("Attempted to transition from state '%s' into unknown state '%s'", [state, new_state_name])
 		return
 
 	var new_state: RewindableState = _available_states[new_state_name]
@@ -112,7 +112,7 @@ func _set_state(new_state: StringName) -> void:
 		return
 
 	if not _available_states.has(new_state):
-		_logger.warning("Attempted to jump to unknown state: %s" % [new_state])
+		_logger.warning("Attempted to jump to unknown state: %s", [new_state])
 		return
 
 	_state_object = _available_states[new_state]

addons/netfox.extras/weapon/network-weapon.gd

@@ -36,7 +36,7 @@ func fire() -> Node:
 	else:
 		_accept_projectile.rpc(id, NetworkTime.tick, data)
 
-	_logger.debug("Calling after fire hook for %s" % [projectile.name])
+	_logger.debug("Calling after fire hook for %s", [projectile.name])
 	_after_fire(projectile)
 
 	return projectile
@@ -128,7 +128,7 @@ func _before_tick_loop():
 		if is_instance_valid(projectile):
 			_reconcile(projectile, local_data, response_data)
 		else:
-			_logger.warning("Projectile %s vanished by the time of reconciliation!" % [projectile_id])
+			_logger.warning("Projectile %s vanished by the time of reconciliation!", [projectile_id])
 
 	_reconcile_buffer.clear()
 
@@ -149,7 +149,7 @@ func _request_projectile(id: String, tick: int, request_data: Dictionary):
 	# Reject if sender can't use this input
 	if not _can_peer_use(sender) or not _can_fire():
 		_decline_projectile.rpc_id(sender, id)
-		_logger.error("Projectile %s rejected! Peer %s can't use this weapon now" % [id, sender])
+		_logger.error("Projectile %s rejected! Peer %s can't use this weapon now", [id, sender])
 		return
 
 	# Validate incoming data
@@ -159,7 +159,7 @@ func _request_projectile(id: String, tick: int, request_data: Dictionary):
 	if not _is_reconcilable(projectile, request_data, local_data):
 		projectile.queue_free()
 		_decline_projectile.rpc_id(sender, id)
-		_logger.error("Projectile %s rejected! Can't reconcile states: [%s, %s]" % [id, request_data, local_data])
+		_logger.error("Projectile %s rejected! Can't reconcile states: [%s, %s]", [id, request_data, local_data])
 		return
 
 	_save_projectile(projectile, id, local_data)
@@ -168,7 +168,7 @@ func _request_projectile(id: String, tick: int, request_data: Dictionary):
 
 @rpc("authority", "reliable", "call_local")
 func _accept_projectile(id: String, tick: int, response_data: Dictionary):
-	_logger.info("[%s] Accepting projectile %s from %s" % [multiplayer.get_unique_id(), id, multiplayer.get_remote_sender_id()])
+	_logger.info("Accepting projectile %s from %s", [id, multiplayer.get_remote_sender_id()])
 	if multiplayer.get_unique_id() == multiplayer.get_remote_sender_id():
 		# Projectile is local, nothing to do
 		return

addons/netfox.extras/window-tiler.gd

@@ -20,11 +20,11 @@ func _ready() -> void:
 	if not ProjectSettings.get_setting("netfox/extras/auto_tile_windows", false):
 		return
 
-	_logger.debug("Tiling with sid: %s, uid: %s" % [_sid, _uid])
+	_logger.debug("Tiling with sid: %s, uid: %s", [_sid, _uid])
 
 	var err = _make_lock(_sid, _uid)
 	if err != Error.OK:
-		_logger.warning("Failed to create lock for tiling, reason: %s" % [error_string(err)])
+		_logger.warning("Failed to create lock for tiling, reason: %s", [error_string(err)])
 		return
 
 	# Search for locks, stop once no new locks are found
@@ -42,7 +42,7 @@ func _ready() -> void:
 	var tile_count = locks.size()
 	var idx = locks.find(_uid)
 
-	_logger.debug("Tiling as idx %d / %d - %s in %s" % [idx, tile_count, _uid, locks])
+	_logger.debug("Tiling as idx %d / %d - %s in %s", [idx, tile_count, _uid, locks])
 	_tile_window(idx, tile_count)
 
 func _make_lock(sid: String, uid: String) -> Error:
@@ -73,7 +73,7 @@ func _cleanup():
 	if dir:
 		for f in dir.get_files():
 			if f.begins_with(_prefix) and _get_sid(f) != _sid:
-					_logger.trace("Cleaned up lock: %s" % [f])
+					_logger.trace("Cleaned up lock: %s", [f])
 					dir.remove(OS.get_cache_dir() + "/" + f)
 
 func _get_sid(filename: String) -> String:

addons/netfox.internals/logger.gd

@@ -70,36 +70,41 @@ func _check_log_level(level: int) -> bool:
 
 	return true
 
-func _format_text(text: String, level: int) -> String:
+func _format_text(text: String, values: Array, level: int) -> String:
 	level = clampi(level, LOG_MIN, LOG_MAX)
 	var peer_id := NetworkEvents.multiplayer.get_unique_id()
 	var tick := NetworkTime.tick
 
-	return "[%s][@%s][#%s][%s::%s] %s" % [level_prefixes[level], tick, peer_id, module, name, text]
+	var prefix := "[%s][@%s][#%s][%s::%s] " % [level_prefixes[level], tick, peer_id, module, name]
+
+	if values.is_empty():
+		return prefix + text
+	else:
+		return prefix + (text % values)
 
-func _log_text(text: String, level: int):
+func _log_text(text: String, values: Array, level: int):
 	if _check_log_level(level):
-		print(_format_text(text, level))
+		print(_format_text(text, values, level))
 
-func trace(text: String):
-	_log_text(text, LOG_TRACE)
+func trace(text: String, values: Array = []):
+	_log_text(text, values, LOG_TRACE)
 
-func debug(text: String):
-	_log_text(text, LOG_DEBUG)
+func debug(text: String, values: Array = []):
+	_log_text(text, values, LOG_DEBUG)
 
-func info(text: String):
-	_log_text(text, LOG_INFO)
+func info(text: String, values: Array = []):
+	_log_text(text, values, LOG_INFO)
 
-func warning(text: String):
+func warning(text: String, values: Array = []):
 	if _check_log_level(LOG_WARN):
-		var formatted_text = _format_text(text, LOG_WARN)
+		var formatted_text = _format_text(text, values, LOG_WARN)
 		push_warning(formatted_text)
 		# Print so it shows up in the Output panel too
 		print(formatted_text)
 
-func error(text: String):
+func error(text: String, values: Array = []):
 	if _check_log_level(LOG_ERROR):
-		var formatted_text = _format_text(text, LOG_ERROR)
+		var formatted_text = _format_text(text, values, LOG_ERROR)
 		push_error(formatted_text)
 		# Print so it shows up in the Output panel too
 		print(formatted_text)

addons/netfox.internals/plugin.cfg

@@ -3,5 +3,5 @@
 name="netfox.internals"
 description="Shared internals for netfox addons"
 author="Tamas Galffy"
-version="1.13.0"
+version="1.13.1"
 script="plugin.gd"

addons/netfox.noray/noray.gd

@@ -68,10 +68,10 @@ func connect_to_host(address: String, port: int = 8890) -> Error:
 	if is_connected_to_host():
 		disconnect_from_host()
 
-	_logger.info("Trying to connect to noray at %s:%s" % [address, port])
+	_logger.info("Trying to connect to noray at %s:%s", [address, port])
 
 	address = IP.resolve_hostname(address, IP.TYPE_IPV4)
-	_logger.debug("Resolved noray host to %s" % address)
+	_logger.debug("Resolved noray host to %s", [address])
 
 	var err = _peer.connect_to_host(address, port)
 	if err != Error.OK:
@@ -86,11 +86,11 @@ func connect_to_host(address: String, port: int = 8890) -> Error:
 
 	if _peer.get_status() == _peer.STATUS_CONNECTED:
 		_address = address
-		_logger.info("Connected to noray at %s:%s" % [address, port])
+		_logger.info("Connected to noray at %s:%s", [address, port])
 		on_connect_to_host.emit()
 		return OK
 	else:
-		_logger.error("Connection failed to noray at %s:%s, connection status %s" % [address, port, _peer.get_status()])
+		_logger.error("Connection failed to noray at %s:%s, connection status %s", [address, port, _peer.get_status()])
 		disconnect_from_host()
 		return ERR_CONNECTION_ERROR
 
@@ -123,7 +123,7 @@ func register_remote(registrar_port: int = 8809, timeout: float = 8, interval: f
 	udp.bind(0)
 	udp.set_dest_address(_address, registrar_port)
 
-	_logger.debug("Bound UDP to port %s" % [udp.get_local_port()])
+	_logger.debug("Bound UDP to port %s", [udp.get_local_port()])
 
 	var packet = pid.to_utf8_buffer()
 
@@ -134,7 +134,7 @@ func register_remote(registrar_port: int = 8809, timeout: float = 8, interval: f
 			var recv = udp.get_packet().get_string_from_utf8()
 			if recv == "OK":
 				_local_port = udp.get_local_port()
-				_logger.info("Registered local port %s to remote" % [_local_port])
+				_logger.info("Registered local port %s to remote", [_local_port])
 				result = OK
 				timeout = 0 # Break outer loop
 				break
@@ -184,21 +184,21 @@ func _handle_commands(command: String, data: String):
 	if command == "set-oid":
 		_oid = data
 		on_oid.emit(oid)
-		_logger.debug("Saved OID: %s" % oid)
+		_logger.debug("Saved OID: %s", [oid])
 	elif command == "set-pid":
 		_pid = data
 		on_pid.emit(pid)
-		_logger.debug("Saved PID: %s" % pid)
+		_logger.debug("Saved PID: %s", [pid])
 	elif command == "connect":
 		var parts = data.split(":")
 		var host = parts[0]
 		var port = parts[1].to_int()
-		_logger.debug("Received connect command to %s:%s" % [host, port])
+		_logger.debug("Received connect command to %s:%s", [host, port])
 		on_connect_nat.emit(host, port)
 	elif command == "connect-relay":
 		var host = _address
 		var port = data.to_int()
-		_logger.debug("Received connect relay command to %s:%s" % [host, port])
+		_logger.debug("Received connect relay command to %s:%s", [host, port])
 		on_connect_relay.emit(host, port)
 	else:
-		_logger.trace("Received command %s %s" % [command, data])
+		_logger.trace("Received command %s %s", [command, data])

addons/netfox.noray/plugin.cfg

@@ -3,5 +3,5 @@
 name="netfox.noray"
 description="Bulletproof your connectivity with noray integration for netfox"
 author="Tamas Galffy"
-version="1.13.0"
+version="1.13.1"
 script="netfox-noray.gd"

addons/netfox/network-time-synchronizer.gd

@@ -152,7 +152,7 @@ func get_time() -> float:
 	return _clock.get_time()
 
 func _loop():
-	_logger.info("Time sync loop started! Initial timestamp: %ss" % [_clock.get_time()])
+	_logger.info("Time sync loop started! Initial timestamp: %ss", [_clock.get_time()])
 	on_initial_sync.emit()
 
 	while _active:
@@ -175,7 +175,7 @@ func _discipline_clock():
 			return a.get_rtt() < b.get_rtt()
 	)
 
-	_logger.trace("Using sorted samples: \n%s" % [
+	_logger.trace("Using sorted samples: \n%s", [
 		"\n".join(sorted_samples.map(func(it: NetworkClockSample): return "\t" + it.to_string() + " (%.4fs)" % [get_time() - it.ping_sent]))
 	])
 
@@ -207,13 +207,13 @@ func _discipline_clock():
 
 		_offset = 0.
 
-		_logger.warning("Offset %ss is above panic threshold %ss! Resetting clock" % [offset, panic_threshold])
+		_logger.warning("Offset %ss is above panic threshold %ss! Resetting clock", [offset, panic_threshold])
 		on_panic.emit(offset)
 	else:
 		# Nudge clock towards estimated time
 		var nudge := offset / adjust_steps
 		_clock.adjust(nudge)
-		_logger.trace("Adjusted clock by %.2fms, offset: %.2fms, new time: %.4fss" % [nudge * 1000., offset * 1000., _clock.get_time()])
+		_logger.trace("Adjusted clock by %.2fms, offset: %.2fms, new time: %.4fss", [nudge * 1000., offset * 1000., _clock.get_time()])
 
 		_offset = offset - nudge
 
@@ -237,7 +237,7 @@ func _send_pong(idx: int, ping_received: float, pong_sent: float):
 	sample.pong_sent = pong_sent
 	sample.pong_received = pong_received
 
-	_logger.trace("Received sample: %s" % [sample])
+	_logger.trace("Received sample: %s", [sample])
 
 	# Once a sample is done, remove from in-flight samples and move to sample buffer
 	_awaiting_samples.erase(idx)
@@ -248,11 +248,11 @@ func _send_pong(idx: int, ping_received: float, pong_sent: float):
 
 @rpc("any_peer", "call_remote", "reliable")
 func _request_timestamp():
-	_logger.debug("Requested initial timestamp @ %.4fs raw time" % [_clock.get_raw_time()])
+	_logger.debug("Requested initial timestamp @ %.4fs raw time", [_clock.get_raw_time()])
 	_set_timestamp.rpc_id(multiplayer.get_remote_sender_id(), _clock.get_time())
 
 @rpc("any_peer", "call_remote", "reliable")
 func _set_timestamp(timestamp: float):
-	_logger.debug("Received initial timestamp @ %.4fs raw time" % [_clock.get_raw_time()])
+	_logger.debug("Received initial timestamp @ %.4fs raw time", [_clock.get_raw_time()])
 	_clock.set_time(timestamp)
 	_loop()

addons/netfox/network-time.gd

@@ -459,7 +459,7 @@ func _loop():
 			# Game stalled for a while, probably paused, don't run extra ticks
 			# to catch up
 			_was_paused = true
-			_logger.debug("Game stalled for %.4fs, assuming it was a pause" % [clock_step_raw])
+			_logger.debug("Game stalled for %.4fs, assuming it was a pause", [clock_step_raw])
 
 	# Handle pause
 	if _was_paused:
@@ -505,9 +505,9 @@ func _is_active() -> bool:
 func _submit_sync_success():
 	var peer_id = multiplayer.get_remote_sender_id()
 
-	_logger.trace("Received time sync success from #%s, synced peers: %s" % [peer_id, _synced_peers.keys()])
+	_logger.trace("Received time sync success from #%s, synced peers: %s", [peer_id, _synced_peers.keys()])
 
 	if not _synced_peers.has(peer_id):
 		_synced_peers[peer_id] = true
 		after_client_sync.emit(peer_id)
-		_logger.debug("Peer #%s is now on time!" % [peer_id])
+		_logger.debug("Peer #%s is now on time!", [peer_id])

addons/netfox/plugin.cfg

@@ -3,5 +3,5 @@
 name="netfox"
 description="Shared internals for netfox addons"
 author="Tamas Galffy"
-version="1.13.0"
+version="1.13.1"
 script="netfox.gd"

addons/netfox/properties/property-cache.gd

@@ -13,7 +13,7 @@ func get_entry(path: String) -> PropertyEntry:
 	if not _cache.has(path):
 		var parsed = PropertyEntry.parse(root, path)
 		if not parsed.is_valid():
-			_logger.warning("Invalid property path: %s" % path)
+			_logger.warning("Invalid property path: %s", [path])
 		_cache[path] = parsed
 	return _cache[path]
 

addons/netfox/rollback/network-rollback.gd

@@ -158,7 +158,7 @@ func _rollback():
 	# Limit number of rollback ticks
 	if to - from > history_limit:
 		_logger.warning(
-			"Trying to run rollback for ticks %d to %d, past the history limit of %d" %
+			"Trying to run rollback for ticks %d to %d, past the history limit of %d",
 			[from, to, history_limit]
 		)
 		from = NetworkTime.tick - history_limit