Improve logging

This commit is contained in:
JonShard
2026-08-11 10:34:47 +02:00
parent 3ae1e089aa
commit 4bfb72d749
21 changed files with 79 additions and 74 deletions
+4 -4
View File
@@ -31,7 +31,7 @@ func _on_body_entered(body: Node3D) -> void:
return
SweetLogger.debug("enabled: {0}", [enabled])
if not enabled:
SweetLogger.debug("disabled in _on_body_entered body", [])
SweetLogger.debug("disabled in _on_body_entered body")
return
if not body.is_in_group(target_group):
return
@@ -50,10 +50,10 @@ func _on_body_entered(body: Node3D) -> void:
var meal_count := contained_items.filter(func(f): return f.type == FoodItem.Type.MEAL).size()
var side_count := contained_items.filter(func(f): return f.type == FoodItem.Type.SIDE).size()
if food_item.type == FoodItem.Type.MEAL and meal_count < meal_positions.size():
SweetLogger.debug("adding meal", [])
SweetLogger.debug("adding meal")
_add_item(body)
if food_item.type == FoodItem.Type.SIDE and side_count < side_positions.size():
SweetLogger.debug("adding side", [])
SweetLogger.debug("adding side")
_add_item(body)
@@ -93,7 +93,7 @@ func _add_item(item: Node3D) -> void:
NetworkManager.despawn_item(item)
# In case the container is on a table that needs to register this addition,
# ask all table in scene to absorb any new items.
SweetLogger.debug("group call absorb_items()", [])
SweetLogger.debug("group call absorb_items()")
get_tree().call_group("table", "absorb_items")
+1 -1
View File
@@ -522,7 +522,7 @@ func _on_player_absent(peer_id: int) -> void:
# --- Command-line driven test bootstrap -----------------------------------
func _handle_cmdline() -> void:
SweetLogger.info("Networkmanager _handle_cmdline()", [])
SweetLogger.info("Networkmanager _handle_cmdline()")
var args := OS.get_cmdline_args()
if args.has("--server"):
log_line("cmdline: --server")
+2 -2
View File
@@ -52,12 +52,12 @@ func _on_body_entered(body: Node3D) -> void:
if not NetworkManager.owns_world():
return
if _combining or body == _pickable:
SweetLogger.debug("other is our own pickable", [])
SweetLogger.debug("other is our own pickable")
return
var other := Helper.find_food_item(body)
if not other:
SweetLogger.debug("other is not a foodItem", [])
SweetLogger.debug("other is not a foodItem")
return
var result: PackedScene = RecipeManager.get_combination_result(_food_item.id, other.id)
+2 -2
View File
@@ -9,10 +9,10 @@ func _ready() -> void:
if not kitchen_scene:
push_error("StationSpawner missing kitchen_scene")
SweetLogger.debug("initializing", [])
SweetLogger.debug("initializing")
if NetworkManager.owns_world():
SweetLogger.debug("initializing on server", [])
SweetLogger.debug("initializing on server")
# Later we will do procedural generation here.
# For now we just load a scene.
NetworkManager.call_deferred("spawn_item", kitchen_scene.resource_path, transform)
+4 -4
View File
@@ -30,14 +30,14 @@ func _reset_values() -> void:
func start_next_day() -> void:
SweetLogger.info("starting next day", [])
SweetLogger.info("starting next day")
_reset_values()
GameManager.set_customers_per_day(GameManager.customers_per_day + GameManager.customers_count_increase_per_day)
GameManager.set_day_number(GameManager.day_number + 1)
func finish_current_day() -> void:
SweetLogger.info("finishing current day", [])
SweetLogger.info("finishing current day")
_reset_values()
@@ -50,9 +50,9 @@ func _process(delta: float) -> void:
#print("DayController: customers_at_this_time: ", customers_at_this_time)
if customers_spawned < customers_at_this_time:
customers_spawned += 1
SweetLogger.debug("spawning customer", [])
SweetLogger.debug("spawning customer")
Signals.request_customer_spawn.emit()
# If day complete
if GameManager.customers_per_day == customers_served and customers_spawned == GameManager.customers_per_day:
SweetLogger.info("day complete", [])
SweetLogger.info("day complete")
finish_current_day()
+6 -6
View File
@@ -119,9 +119,9 @@ func get_next(size, walls):
for wall in walls:
SweetLogger.debug("get_next wall: {0}", [wall])
if wall["der"][1] == 0:
SweetLogger.debug("get_next horizontal wall", [])
SweetLogger.debug("get_next horizontal wall")
if size[0]<wall["len"]-6:
SweetLogger.debug("TileMapLayer get_next length 6 less can go anywhere", [])
SweetLogger.debug("TileMapLayer get_next length 6 less can go anywhere")
if wall["der"][0] == 1:offset[1] = wall["pos"][1]
else: offset[1] = wall["pos"][1]-size[1]
@@ -130,16 +130,16 @@ func get_next(size, walls):
if size[0]+offset[0]>wall["pos"][0]+wall["len"]-3:offset[0] = wall["len"]-(3+size[0])
elif size[0]<=wall["len"]-3:
SweetLogger.debug("TileMapLayer get_next 3 less needs to be on a corner", [])
SweetLogger.debug("TileMapLayer get_next 3 less needs to be on a corner")
if wall["der"][0] == 1:offset[1] = wall["pos"][1]
else: offset[1] = wall["pos"][1]-size[1]
if randi_range(0, 1):offset[0]=wall["pos"][0]+wall["len"]-size[0]
else:offset[0] = wall["pos"][0]
else:
SweetLogger.debug("get_next vertical wall", [])
SweetLogger.debug("get_next vertical wall")
if size[1]<wall["len"]-6:
SweetLogger.debug("TileMapLayer get_next length 6 less can go anywhere", [])
SweetLogger.debug("TileMapLayer get_next length 6 less can go anywhere")
if wall["der"][1] == 1:offset[0] = wall["pos"][0]
else: offset[0] = wall["pos"][0]-size[0]
@@ -148,7 +148,7 @@ func get_next(size, walls):
if size[1]+offset[1]>wall["len"]-3:offset[1] = wall["len"]-(3+size[1])
elif size[1]<=wall["len"]-3:
SweetLogger.debug("TileMapLayer get_next 3 less needs to be on a corner", [])
SweetLogger.debug("TileMapLayer get_next 3 less needs to be on a corner")
if wall["der"][1] == 1:offset[0] = wall["pos"][0]
else: offset[0] = wall["pos"][0]-size[0]
SweetLogger.debug("get_next offset: {0}", [offset])
+3 -3
View File
@@ -91,7 +91,7 @@ func _on_gesture_area_body_entered(body: Node3D) -> void:
SweetLogger.debug("gesture area entered: {0}", [body])
if body.is_in_group("chopping_tool"):
if process_result == "":
SweetLogger.debug("knife entered but nothing to chop", [])
SweetLogger.debug("knife entered but nothing to chop")
return
var speed := 0.0
@@ -111,7 +111,7 @@ func _on_object_picked_up(_item: Variant) -> void:
SweetLogger.debug("object picked up: {0}", [_item])
var food_item = Helper.find_food_item(_item)
if not food_item:
SweetLogger.debug("held object is not a FoodItem", [])
SweetLogger.debug("held object is not a FoodItem")
return
var result = RecipeManager.get_chopping_result(food_item.id)
@@ -125,7 +125,7 @@ func _on_object_picked_up(_item: Variant) -> void:
func _on_object_dropped(_item: Variant) -> void:
SweetLogger.debug("object drop", [])
SweetLogger.debug("object drop")
work_progress = 0
process_result = ""
process_result_work = 0
+1 -1
View File
@@ -11,7 +11,7 @@ func _makeDirty(item) -> void:
return
var plate: PlateController = item.get_node_or_null("PlateController") as PlateController
if not plate:
SweetLogger.debug("held object is not a Plate", [])
SweetLogger.debug("held object is not a Plate")
return
if not plate.is_dirty:
plate.is_dirty = true
+2 -2
View File
@@ -72,7 +72,7 @@ func _on_object_picked_up(_item) -> void:
# Find the CookableItem in held object
var _food_item = _item.get_node_or_null("FoodItem") as FoodItem
if not _food_item:
SweetLogger.debug("held object is not a FoodItem", [])
SweetLogger.debug("held object is not a FoodItem")
return
var result = RecipeManager.get_cooking_result(_food_item.id)
if not result:
@@ -86,7 +86,7 @@ func _on_object_picked_up(_item) -> void:
func _on_object_dropped(_item) -> void:
SweetLogger.debug("object drop", [])
SweetLogger.debug("object drop")
time_cooked = 0
cooking_result = ""
cooking_result_time = 0
+1 -1
View File
@@ -21,6 +21,6 @@ func _process(_delta: float) -> void:
#return
#
if not snap_zone.picked_up_object:
SweetLogger.debug("missing item, spawning new item", [])
SweetLogger.debug("missing item, spawning new item")
var new_item = NetworkManager.spawn_item(item_scene.resource_path, snap_zone.global_transform)
snap_zone.pick_up_object(new_item)
+2 -2
View File
@@ -67,7 +67,7 @@ func _on_object_picked_up(_item) -> void:
func _on_object_dropped(_item) -> void:
SweetLogger.debug("object drop", [])
SweetLogger.debug("object drop")
_reset_sink()
@@ -81,7 +81,7 @@ func complete_washing():
return
plate.is_dirty = false
_reset_sink()
SweetLogger.debug("washing complete!", [])
SweetLogger.debug("washing complete!")
func _process(delta: float) -> void:
+7 -7
View File
@@ -133,7 +133,7 @@ func _handle_drop(_by: Node) -> void:
else:
station.global_transform = original_station_transform
move_handle.global_transform = original_station_transform.translated(Vector3(0, original_handle_y_pos, 0))
SweetLogger.debug("handle drop (local reject), restoring original position", [])
SweetLogger.debug("handle drop (local reject), restoring original position")
func _process(_delta: float) -> void:
if not is_moving:
@@ -193,7 +193,7 @@ func server_handle_drop(new_transform: Transform3D, client_thinks_valid: bool):
server_update_move_ghost_transform.rpc(original_trans)
server_update_handle_transform.rpc(original_trans.translated(Vector3(0, original_handle_y_pos, 0)))
server_update_visibility.rpc(false, true)
SweetLogger.debug("server_handle_drop: transform rejected (invalid)", [])
SweetLogger.debug("server_handle_drop: transform rejected (invalid)")
return
server_update_station_transform.rpc(new_transform)
@@ -201,32 +201,32 @@ func server_handle_drop(new_transform: Transform3D, client_thinks_valid: bool):
server_update_handle_transform.rpc(new_transform.translated(Vector3(0, original_handle_y_pos, 0)))
server_update_visibility.rpc(false, true)
SweetLogger.debug("server_handle_drop: transform applied", [])
SweetLogger.debug("server_handle_drop: transform applied")
@rpc("any_peer", "call_local", "reliable") # Server updates clients
func server_update_station_transform(new_transform: Transform3D) -> void:
SweetLogger.debug("server_update_station_transform", [])
SweetLogger.debug("server_update_station_transform")
station.global_transform = new_transform
original_station_transform = new_transform
@rpc("any_peer", "call_local", "reliable") # Server updates clients
func server_update_handle_transform(new_transform: Transform3D) -> void:
SweetLogger.debug("server_update_handle_transform", [])
SweetLogger.debug("server_update_handle_transform")
move_handle.global_transform = new_transform
@rpc("any_peer", "call_local", "reliable")
func server_update_visibility(ghost_visible: bool, station_visible: bool) -> void:
SweetLogger.debug("server_update_visibility", [])
SweetLogger.debug("server_update_visibility")
move_ghost.visible = ghost_visible
station.visible = station_visible
@rpc("any_peer", "call_local", "unreliable")
func server_update_move_ghost_transform(new_transform: Transform3D, new_color: Color = Color.YELLOW) -> void:
SweetLogger.debug("server_update_move_ghost_transform", [])
SweetLogger.debug("server_update_move_ghost_transform")
move_ghost.global_transform = new_transform
_set_ghost_color(new_color)
+11 -11
View File
@@ -47,7 +47,7 @@ var _players_count: int = 0
func place_order() -> void:
SweetLogger.debug("place_order()", [])
SweetLogger.debug("place_order()")
var new_orders: Array[String] = _unsatisfied_orders.duplicate()
# for _i in range(0, randi_range(1, 2)):
# new_orders.append(GameManager.get_random_meal())
@@ -59,7 +59,7 @@ func place_order() -> void:
func absorb_items():
SweetLogger.debug("absorb_items()", [])
SweetLogger.debug("absorb_items()")
for snap_zone_node in snap_zones:
var held_object = snap_zone_node.picked_up_object
if not held_object:
@@ -69,7 +69,7 @@ func absorb_items():
func satisfyAllOrders() -> void:
SweetLogger.debug("satisfyAllOrders()", [])
SweetLogger.debug("satisfyAllOrders()")
_unsatisfied_orders.clear()
_original_orders.clear()
clearAllFood()
@@ -77,7 +77,7 @@ func satisfyAllOrders() -> void:
func clearAllFood() -> void:
SweetLogger.debug("clearAllFood()", [])
SweetLogger.debug("clearAllFood()")
for zone in snap_zones:
var held_object = zone.picked_up_object
if not held_object:
@@ -98,7 +98,7 @@ func clearAllFood() -> void:
# Group called from Queue when trying to assign customers to tables
func try_consume_customer() -> bool:
if _state == TableState.EMPTY:
SweetLogger.debug("try_consume_customer, consumed a customer", [])
SweetLogger.debug("try_consume_customer, consumed a customer")
_state_end(TableState.EMPTY)
return true
return false
@@ -183,15 +183,15 @@ func _place_order_if_player():
func _get_plate_controller_from_item(_item: Node) -> PlateController:
if not _item:
SweetLogger.debug("_item is null", [])
SweetLogger.debug("_item is null")
return null
for child in _item.get_children():
if child is PlateController:
SweetLogger.debug("found child", [])
SweetLogger.debug("found child")
return child
SweetLogger.debug("no match", [])
SweetLogger.debug("no match")
return null
@@ -211,7 +211,7 @@ func _absorb_item_if_correct(_item: Node) -> void:
# Absorm items from the plate we want
for food_item: FoodItem in plate_controller.container.contained_items: # TOOD: handle registering the meal again when a side is added to the plate
if food_item.id in _unsatisfied_orders and not food_item.is_absorbed:
SweetLogger.debug("_absorb_item_if_correct held a plate with FoodItem that is in unsatisfied orders, removing it", [])
SweetLogger.debug("_absorb_item_if_correct held a plate with FoodItem that is in unsatisfied orders, removing it")
(plate_controller.get_parent() as XRToolsPickable).get_picked_up_by().enabled = false # Lock meal that is deliverd
_unsatisfied_orders.erase(food_item.id)
food_item.is_absorbed = true
@@ -221,13 +221,13 @@ func _absorb_item_if_correct(_item: Node) -> void:
# Side pickable item, no container
var food_item: FoodItem = Helper.find_food_item(_item)
if food_item and food_item.type == FoodItem.Type.SIDE:
SweetLogger.debug("_absorb_item_if_correct held a side that is in unsatisfied orders, removing it", [])
SweetLogger.debug("_absorb_item_if_correct held a side that is in unsatisfied orders, removing it")
# Do not lock snap zone here. Problem if table want many meals, but to many sides have filled up slots, so can't place plates.
_unsatisfied_orders.erase(food_item.id)
_update_state_from_orders()
return
SweetLogger.debug("absorb_item_if_correct() held object is not a Plate or Side", [])
SweetLogger.debug("absorb_item_if_correct() held object is not a Plate or Side")
func _update_state_from_orders():
+2 -2
View File
@@ -32,7 +32,7 @@ func _process(_delta: float) -> void:
func toggle_shop():
if GameManager.game_state == GameManager.GameState.BUILDING:
SweetLogger.debug("toggle shop", [])
SweetLogger.debug("toggle shop")
enabled = !enabled
SweetLogger.debug("_process: money={0} label text={1}", [GameManager.money, money_label.text])
@@ -54,7 +54,7 @@ func _set_poke_enabled_for_controller(controller_node: XRController3D, value: bo
var poke_node = Helper.find_first_child_of_type(controller_node, XRToolsPoke)
if poke_node:
SweetLogger.debug("_set_poke_enabled_for_controller: {0} poke enabled: {1}", [poke_node.get_path(), value])
SweetLogger.debug("_set_poke_enabled_for_controller: {0} poke enabled: {1}", [poke_node.name, value])
poke_node.enabled = value
poke_node.visible = value
else:
+11 -7
View File
@@ -94,12 +94,16 @@ const TIMESTAMP_BG_COLOR = "#1e3a5f"
# WIDTHS
#===================================================================================#
## Column widths for alignment (in characters)
const PEER_ID_COLUMN_WIDTH = 10
const LOG_TYPE_COLUMN_WIDTH = 8
const PEER_ID_COLUMN_WIDTH = 6
const LOG_TYPE_COLUMN_WIDTH = 6
## Default mm:ss:ms; with SHOW_TIMESTAMP_HOURS, hh:mm:ss:ms
const TIMESTAMP_COLUMN_WIDTH_MMSSMS = 9
const TIMESTAMP_COLUMN_WIDTH_HHMMSSMS = 12
const SCRIPT_FUNCTION_COLUMN_WIDTH = 40
const SCRIPT_FUNCTION_COLUMN_WIDTH = 45
const TRUNCATE_PEER_NAME = 6
const TRUNCATE_SCRIPT_NAME = 18
const TRUNCATE_FUNCTION_NAME = 30
#===================================================================================#
# CONFIGURATION
@@ -111,7 +115,7 @@ var _peer_color_cache: Dictionary = {}
@export var SHOW_SCRIPT_NAME = true
@export var SHOW_FUNCTION_NAME = true
## When false (default), timestamp is local mm:ss:ms. When true, local hh:mm:ss:ms (wider column).
@export var SHOW_TIMESTAMP_HOURS = false
@export var SHOW_TIMESTAMP_HOURS = true
#===================================================================================#
# GETTERS
@@ -219,7 +223,7 @@ func _print_rich_log(peer_id_str: String, log_type: String, message: String, scr
var log_type_label = log_type.to_upper()
# Pad peer ID column for alignment
var peer_padded = _pad_text(peer_label, PEER_ID_COLUMN_WIDTH)
var peer_padded = _truncate_text(_pad_text(peer_label, PEER_ID_COLUMN_WIDTH), TRUNCATE_PEER_NAME)
# Format peer ID with its background color
var peer_formatted = _format_rich_text(peer_padded, peer_color.bg_color, peer_color.text_color)
@@ -238,11 +242,11 @@ func _print_rich_log(peer_id_str: String, log_type: String, message: String, scr
var script_function_parts: Array[String] = []
if SHOW_SCRIPT_NAME and script_name != "":
var script_truncated = _truncate_text(script_name, 18)
var script_truncated = _truncate_text(script_name, TRUNCATE_SCRIPT_NAME)
script_function_parts.append(script_truncated)
if SHOW_FUNCTION_NAME and function_name != "":
var function_truncated = _truncate_text(function_name, 20)
var function_truncated = _truncate_text(function_name, TRUNCATE_FUNCTION_NAME)
script_function_parts.append(function_truncated)
if not script_function_parts.is_empty():
+3 -3
View File
@@ -238,7 +238,7 @@ func get_random_meal() -> String:
func get_random_side() -> String:
SweetLogger.debug("get_random_side()", [])
SweetLogger.debug("get_random_side()")
if sides_in_play.size() == 0:
push_error("GameManager: get_random_side() called but sides_in_play is empty")
return ""
@@ -248,11 +248,11 @@ func get_random_side() -> String:
func _restart():
SweetLogger.info("restart Game", [])
SweetLogger.info("restart Game")
game_state = GameState.RUNNING
func game_over():
SweetLogger.info("Game Over", [])
SweetLogger.info("Game Over")
game_state = GameState.GAME_OVER
Signals.game_over.emit()
+7 -7
View File
@@ -111,22 +111,22 @@ static func get_item_scene(item_id: StringName) -> PackedScene:
static func print_all_recipes() -> void:
load_recipes()
if not _loaded:
SweetLogger.warning("could not load recipes.yaml; no recipes printed.", [])
SweetLogger.warning("could not load recipes.yaml; no recipes printed.")
return
if _combining_map.is_empty():
SweetLogger.warning("no combining recipes found", [])
SweetLogger.warning("no combining recipes found")
return
SweetLogger.info("#### RecipeManager: Loaded recipes ####", [])
SweetLogger.info("#### RecipeManager: Loaded recipes ####")
_print_combining_recipes()
SweetLogger.info("", [])
SweetLogger.info("")
_print_cooking_recipes()
SweetLogger.info("", [])
SweetLogger.info("")
_print_chopping_recipes()
SweetLogger.info("", [])
SweetLogger.info("")
_print_rolling_recipes()
SweetLogger.info("", [])
SweetLogger.info("")
_print_augmenting_recipes()
static func _print_combining_recipes() -> void:
+4 -3
View File
@@ -10,10 +10,11 @@ func _position_window() -> void:
var is_server: bool = OS.get_cmdline_args().has("--server")
var screen_rect: Rect2i = DisplayServer.screen_get_usable_rect(DisplayServer.window_get_current_screen())
@warning_ignore("integer_division")
var window_width: int = screen_rect.size.x / 2
var window_height: int = int(screen_rect.size.y * (2.0 / 3.0))
DisplayServer.window_set_size(Vector2i(window_width - 10, window_height))
var x_pos: int = screen_rect.position.x + window_width if is_server else screen_rect.position.x
DisplayServer.window_set_position(Vector2i(x_pos, screen_rect.position.y))
if is_server:
var x_pos: int = screen_rect.position.x + window_width
DisplayServer.window_set_position(Vector2i(x_pos, screen_rect.position.y))
+3 -3
View File
@@ -28,14 +28,14 @@ func satisfy_table_orders() -> void:
func set_buidling_mode():
SweetLogger.info("Setting building mode", [])
SweetLogger.info("Setting building mode")
GameManager.set_game_state(GameManager.GameState.BUILDING)
func set_running_mode():
SweetLogger.info("Setting running mode", [])
SweetLogger.info("Setting running mode")
GameManager.set_game_state(GameManager.GameState.RUNNING)
func set_game_over():
SweetLogger.info("Setting game over", [])
SweetLogger.info("Setting game over")
GameManager.set_game_state(GameManager.GameState.GAME_OVER)
+1 -1
View File
@@ -25,7 +25,7 @@ static func find_first_child_of_type(node: Node, type: Variant) -> Node:
# Returns true if decendant is a decendant node of root, false otherwise. Returns false if either node is null.
static func is_node_decendant_of(decendant: Node, root: Node) -> bool:
if not decendant or not root:
SweetLogger.debug("is_node_decendant_of: decendant or root is null", [])
SweetLogger.debug("is_node_decendant_of: decendant or root is null")
return false
var current: Node = decendant
while current:
+2 -2
View File
@@ -42,7 +42,7 @@ func _run() -> void:
_clear_previous_results(logs_dir)
print_rich("[b]Running the multiplayer test suite...[/b]")
SweetLogger.info("the editor will be unresponsive until it finishes (~2 minutes)", [])
SweetLogger.info("the editor will be unresponsive until it finishes (~2 minutes)")
var server_pid := _launch(exe, project_dir, ["--server"], SERVER_SCENE)
if server_pid <= 0:
@@ -108,7 +108,7 @@ func _print_report(logs_dir: String) -> void:
push_error("No report at %s — the run did not finish. Check logs/mptest_server.log" % path)
return
var text := FileAccess.get_file_as_string(path)
SweetLogger.info("", [])
SweetLogger.info("")
# Colour the summary so a failure is obvious in the Output panel.
for line in text.split("\n"):
if line.begins_with("FAIL") or line.contains("RESULT: FAILED"):