Logger outputs logfile and savegame on crash (#439)

addons/escoria-core/game/core-scripts/esc_room.gd

@@ -105,8 +105,6 @@ func _ready():
 	if global_id.empty():
 		global_id = name
 	
-	
-	
 	# Manage player location at room start
 	if player != null \
 			and escoria.object_manager.get_start_location() != null:

addons/escoria-core/game/core-scripts/log/esc_logger.gd

@@ -2,11 +2,23 @@
 extends Object
 class_name ESCLogger
 
+# Log file format
+const  LOG_FILE_FORMAT: String = "log_%s_%s.log"
+
 
 # The path of the ESC file that was reported last (used for removing
 # duplicate warnings
 var warning_path: String
 
+# Log file handler
+var log_file: File
+
+# Crash save filename
+var crash_savegame_filename
+
+# Did we crash already?
+onready var crashed = false
+
 
 # Valid log levels
 enum { LOG_ERROR, LOG_WARNING, LOG_INFO, LOG_DEBUG, LOG_TRACE }
@@ -22,6 +34,24 @@ var _level_map: Dictionary = {
 }
 
 
+# Logger constructor
+func _init():
+	# Open logfile in write mode
+	log_file = File.new()
+	var log_file_path = ProjectSettings.get_setting(
+		"escoria/debug/log_file_path"
+	)
+	var date = OS.get_datetime()
+	log_file_path = log_file_path.plus_file(LOG_FILE_FORMAT % [
+			str(date["year"]) + str(date["month"]) + str(date["day"]),
+			str(date["hour"]) + str(date["minute"]) + str(date["second"])
+		])
+	log_file.open(
+		log_file_path, 
+		File.WRITE
+	)
+
+
 # Log a trace message
 #
 # #### Parameters
@@ -29,9 +59,10 @@ var _level_map: Dictionary = {
 # * string: Text to log
 # * args: Additional information
 func trace(string: String, args = []):
-	if _get_log_level() >= LOG_TRACE:
+	if _get_log_level() >= LOG_TRACE and !crashed:
 		var argsstr = str(args) if !args.empty() else ""
-		printerr("(T)\t" + string + " \t" + argsstr)
+		_log("(T)\t" + string + " \t" + argsstr)
+
 
 # Log a debug message
 #
@@ -40,9 +71,9 @@ func trace(string: String, args = []):
 # * string: Text to log
 # * args: Additional information
 func debug(string: String, args = []):
-	if _get_log_level() >= LOG_DEBUG:
+	if _get_log_level() >= LOG_DEBUG and !crashed:
 		var argsstr = str(args) if !args.empty() else ""
-		printerr("(D)\t" + string + " \t" + argsstr)
+		_log("(D)\t" + string + " \t" + argsstr)
 
 
 # Log an info message
@@ -52,7 +83,7 @@ func debug(string: String, args = []):
 # * string: Text to log
 # * args: Additional information
 func info(string: String, args = []):
-	if _get_log_level() >= LOG_INFO:
+	if _get_log_level() >= LOG_INFO and !crashed:
 		var argsstr = []
 		if !args.empty():
 			for arg in args:
@@ -61,7 +92,7 @@ func info(string: String, args = []):
 						argsstr.append(p.global_id)
 				else:
 					argsstr.append(str(arg))
-		print("(I)\t" + string + " \t" + str(argsstr))
+		_log("(I)\t" + string + " \t" + str(argsstr))
 
 
 # Log a warning message
@@ -71,11 +102,17 @@ func info(string: String, args = []):
 # * string: Text to log
 # * args: Additional information
 func warning(string: String, args = []):
-	if _get_log_level() >= LOG_WARNING:
+	if _get_log_level() >= LOG_WARNING and !crashed:
 		var argsstr = str(args) if !args.empty() else ""
-		printerr("(W)\t" + string + " \t" + argsstr)
+		_log("(W)\t" + string + " \t" + argsstr, true)
 		if ProjectSettings.get_setting("escoria/debug/terminate_on_warnings"):
-			print_stack()
+			_perform_stack_trace_log()			
+			_log("%s\n- %s" % [ 
+				ProjectSettings.get_setting("escoria/debug/crash_message"), 
+				log_file.get_path_absolute() 
+			])
+			crashed = true
+			escoria.quit()
 			assert(false)
 
 
@@ -85,12 +122,25 @@ func warning(string: String, args = []):
 # 
 # * string: Text to log
 # * args: Additional information
-func error(string: String, args = []):
-	if _get_log_level() >= LOG_ERROR:
+func error(string: String, args = [], do_savegame: bool = true):
+	if _get_log_level() >= LOG_ERROR and !crashed:
 		var argsstr = str(args) if !args.empty() else ""
-		printerr("(E)\t" + string + " \t" + argsstr)
+		_log("(E)\t" + string + " \t" + argsstr, true)
 		if ProjectSettings.get_setting("escoria/debug/terminate_on_errors"):
-			print_stack()
+			_perform_stack_trace_log()
+			if do_savegame:
+				_perform_save_game_log()
+				
+			_log("%s\n- %s\n- %s" % [ 
+				ProjectSettings.get_setting("escoria/debug/crash_message"), 
+				log_file.get_path_absolute().get_base_dir().plus_file(
+					escoria.save_manager.crash_savegame_filename.get_file()
+				),
+				log_file.get_path_absolute() 
+			])
+			
+			crashed = true
+			escoria.quit()
 			assert(false)
 
 
@@ -135,7 +185,76 @@ func report_errors(p_path: String, errors: Array) -> void:
 	error(text)
 
 
+# Write message:
+# - in logfile
+# - in stdout, or stderr if err is true.
+#
+# #### Parameters
+# 
+# * message: Message to log
+# * err: if true, write in stderr
+func _log(message:String, err: bool = false):
+	if err:
+		printerr(message)
+	else:
+		print(message)
+	_write_logfile(message)
+
+
 # Returns the currently set log level
 # **Returns** Log level as set in the configuration
 func _get_log_level() -> int:
 	return _level_map[ProjectSettings.get_setting("escoria/debug/log_level")]
+
+
+# Creates a savegame file and save it in output log location
+func _perform_save_game_log():
+	_log("Performing emergency savegame.")
+	var error = escoria.save_manager.save_game_crash()
+	if error == OK:
+		_log(
+			"Emergency savegame created successfully in folder: %s" %
+				ProjectSettings.get_setting(
+					"escoria/debug/log_file_path"
+				)
+		)
+	else:
+		_log("Emergency savegame creation failed!", false)
+
+
+# Logs and writes the stack trace into stdout and log file.
+func _perform_stack_trace_log():
+	_log("Stack trace:")
+	print_stack()
+	_write_stack_logfile()
+
+
+# Write a message in the output logfile
+#
+# #### Parameters
+# 
+# * message: Message to write
+func _write_logfile(message: String) -> void:
+	if log_file.is_open():
+		log_file.store_string(message + "\n")
+
+
+# Write the stacktrace in the output logfile
+func _write_stack_logfile():
+	var frame_number = 0
+	for stack in get_stack().slice(2, get_stack().size()):
+		_write_logfile(
+			"Frame %s - %s:%s in function '%s'" % [
+				str(frame_number),
+				stack["source"],
+				stack["line"],
+				stack["function"],
+			]
+		)
+		frame_number += 1
+
+
+# Close the log file cleanly
+func close_logs():
+	_log("Closing logs peacefully.")
+	log_file.close()

addons/escoria-core/game/core-scripts/save_data/esc_save_manager.gd

@@ -7,9 +7,15 @@ var save_enabled: bool = true
 # Variable containing the saves folder obtained from Project Settings
 var save_folder: String
 
+# Filename of the latest crash savegame file
+var crash_savegame_filename: String
+
 # Template for savegames filenames
 const SAVE_NAME_TEMPLATE: String = "save_%03d.tres"
 
+# Template for crash savegames filenames
+const CRASH_SAVE_NAME_TEMPLATE: String = "crash_autosave_%s_%s.tres"
+
 # Variable containing the settings folder obtained from Project Settings
 var settings_folder: String
 
@@ -74,7 +80,61 @@ func save_game(id: int, p_savename: String):
 			["Save requested while saving is not possible. Save canceled."])
 		return
 	
-	var save_game := ESCSaveGame.new()
+	var save_game := _do_save_game(p_savename)
+
+	var directory: Directory = Directory.new()
+	if not directory.dir_exists(save_folder):
+		directory.make_dir_recursive(save_folder)
+
+	var save_path = save_folder.plus_file(SAVE_NAME_TEMPLATE % id)
+	var error: int = ResourceSaver.save(save_path, save_game)
+	if error != OK:
+		escoria.logger.report_errors(
+			"esc_save_data_resources.gd",
+			["There was an issue writing the save %s to %s" % [id, save_path]]
+		)
+
+
+# Performs an emergency savegame in case of crash.
+func save_game_crash():
+	var datetime = OS.get_datetime()
+	var datetime_string = "%02d/%02d/%02d %02d:%02d" % [
+		datetime["day"],
+		datetime["month"],
+		datetime["year"],
+		datetime["hour"],
+		datetime["minute"],
+	]
+	
+	var save_game := _do_save_game("Crash %s" % datetime_string)
+	
+	var save_file_path: String = ProjectSettings.get_setting(
+		"escoria/debug/log_file_path"
+	)
+	crash_savegame_filename = save_file_path.plus_file(
+		CRASH_SAVE_NAME_TEMPLATE % [
+			str(datetime["year"]) + str(datetime["month"]) 
+					+ str(datetime["day"]),
+			str(datetime["hour"]) + str(datetime["minute"]) 
+					+ str(datetime["second"])
+		]
+	)
+	
+	var error: int = ResourceSaver.save(crash_savegame_filename, save_game)
+	if error != OK:
+		escoria.logger.report_errors(
+			"esc_save_data_resources.gd",
+			["There was an issue writing the crash save to %s" 
+				% crash_savegame_filename])
+	return error
+
+
+# Actual savegame function. 
+#
+# ## Parameters
+# - p_savename: name of the savegame
+func _do_save_game(p_savename: String) -> ESCSaveGame:
+	var save_game = ESCSaveGame.new()
 	save_game.escoria_version = escoria.ESCORIA_VERSION
 	save_game.game_version = ProjectSettings.get_setting(
 		"escoria/main/game_version"
@@ -94,17 +154,8 @@ func save_game(id: int, p_savename: String):
 	escoria.globals_manager.save_game(save_game)
 	escoria.object_manager.save_game(save_game)
 	escoria.main.save_game(save_game)
+	return save_game
 
-	var directory: Directory = Directory.new()
-	if not directory.dir_exists(save_folder):
-		directory.make_dir_recursive(save_folder)
-
-	var save_path = save_folder.plus_file(SAVE_NAME_TEMPLATE % id)
-	var error: int = ResourceSaver.save(save_path, save_game)
-	if error != OK:
-		escoria.logger.report_errors(
-			"esc_save_data_resources.gd",
-			["There was an issue writing the save %s to %s" % [id, save_path]])
 
 # Load a savegame file from its id.
 #

addons/escoria-core/game/escoria.gd

@@ -134,6 +134,16 @@ func _ready():
 	)
 
 
+func _notification(what):
+	match what:
+		MainLoop.NOTIFICATION_WM_QUIT_REQUEST:
+			escoria.logger.close_logs()
+			get_tree().quit()
+		MainLoop.NOTIFICATION_WM_GO_BACK_REQUEST:
+			escoria.logger.close_logs()
+			get_tree().quit()
+
+
 # Called by Escoria's main_scene as very very first event EVER.
 # Usually you'll want to show some logos animations before spawning the main
 # menu in the escoria/main/game_start_script 's :init event
@@ -339,3 +349,8 @@ func run_event_from_script(script: ESCScript, event_name: String):
 			[]
 		)
 		return
+
+
+# Function called to quit the game.
+func quit():
+	get_tree().notification(MainLoop.NOTIFICATION_WM_QUIT_REQUEST)

addons/escoria-core/plugin.gd

@@ -211,6 +211,30 @@ func set_escoria_debug_settings():
 		}
 		ProjectSettings.add_property_info(property_info)
 	
+	# Define output log file path
+	if not ProjectSettings.has_setting("escoria/debug/log_file_path"):
+		ProjectSettings.set_setting("escoria/debug/log_file_path", "user://")
+		var property_info = {
+			"name": "escoria/debug/log_file_path",
+			"type": TYPE_STRING,
+			"hint": PROPERTY_HINT_DIR
+		}
+		ProjectSettings.add_property_info(property_info)
+	
+	# Define crash message
+	if not ProjectSettings.has_setting("escoria/debug/crash_message"):
+		ProjectSettings.set_setting(
+			"escoria/debug/crash_message", 
+			"We're sorry, but the game crashed. Please send us the " +
+			"following files:\n"
+		)
+		var property_info = {
+			"name": "escoria/debug/crash_message",
+			"type": TYPE_STRING,
+			"hint": PROPERTY_HINT_MULTILINE_TEXT
+		}
+		ProjectSettings.add_property_info(property_info)
+	
 	# Room selector preference
 	if not ProjectSettings.has_setting("escoria/debug/enable_room_selector"):
 		ProjectSettings.set_setting("escoria/debug/enable_room_selector", false)

addons/escoria-core/ui_library/menus/main_menu/main_menu.gd

@@ -22,7 +22,7 @@ func _on_options_pressed():
 
 # Quit the game
 func _on_quit_pressed():
-	get_tree().quit()
+	escoria.quit()
 
 
 # Hide the options panel again

addons/escoria-core/ui_library/menus/pause_menu/pause_menu.gd

@@ -28,7 +28,7 @@ func _on_load_game_pressed():
 
 # Quit the game
 func _on_quit_pressed():
-	get_tree().quit()
+	escoria.quit()
 
 
 # Hide the save slots again