Move debug log dump from ynh_exit_properly to the core after failed app operation

This commit is contained in:
Alexandre Aubin 2019-11-04 20:20:12 +01:00 committed by Alexandre Aubin
parent 6ff99f7cba
commit 71878f6bbe
3 changed files with 36 additions and 39 deletions

View file

@ -28,43 +28,6 @@ ynh_exit_properly () {
# Small tempo to avoid the next message being mixed up with other DEBUG messages # Small tempo to avoid the next message being mixed up with other DEBUG messages
sleep 0.5 sleep 0.5
ynh_print_err --message="!!\n $app's script has encountered an error. Its execution was cancelled.\n!!"
# If the script is executed from the CLI, dump the end of the log that precedes the crash.
if [ "$YNH_INTERFACE" == "cli" ]
then
# Unset xtrace to not spoil the log
set +x
local ynh_log="/var/log/yunohost/yunohost-cli.log"
# Wait for the log to be fill with the data until the crash.
local timeout=0
while ! tail --lines=20 "$ynh_log" | grep --quiet "+ ynh_exit_properly"
do
((timeout++))
if [ $timeout -eq 500 ]; then
break
fi
done
echo -e "\e[34m\e[1mPlease find here an extract of the log before the crash:\e[0m" >&2
# Tail the last 30 lines of log of YunoHost
# But remove all lines after "ynh_exit_properly"
# Remove the timestamp at the beginning of the line
# Remove "yunohost.hook..."
# Add DEBUG and color it at the beginning of each log line.
echo -e "$(tail --lines=30 "$ynh_log" \
| sed '1,/+ ynh_exit_properly/!d' \
| sed 's/^[[:digit:]: ,-]*//g' \
| sed 's/ *yunohost.hook.*\]/ -/g' \
| sed 's/^WARNING /&/g' \
| sed 's/^DEBUG /& /g' \
| sed 's/^INFO /& /g' \
| sed 's/^/\\e[34m\\e[1m[DEBUG]\\e[0m: /g')" >&2
set -x
fi
if type -t ynh_clean_setup > /dev/null; then # Check if the function exist in the app script. if type -t ynh_clean_setup > /dev/null; then # Check if the function exist in the app script.
ynh_clean_setup # Call the function to do specific cleaning for the app. ynh_clean_setup # Call the function to do specific cleaning for the app.
fi fi

View file

@ -738,6 +738,8 @@ def app_upgrade(app=[], url=None, file=None):
error = m18n.n('app_upgrade_script_failed') error = m18n.n('app_upgrade_script_failed')
logger.exception(m18n.n("app_upgrade_failed", app=app_instance_name, error=error)) logger.exception(m18n.n("app_upgrade_failed", app=app_instance_name, error=error))
failure_message_with_debug_instructions = operation_logger.error(error) failure_message_with_debug_instructions = operation_logger.error(error)
if msettings.get('interface') != 'api':
dump_app_log_extract_for_debugging(operation_logger)
# Script got manually interrupted ... N.B. : KeyboardInterrupt does not inherit from Exception # Script got manually interrupted ... N.B. : KeyboardInterrupt does not inherit from Exception
except (KeyboardInterrupt, EOFError): except (KeyboardInterrupt, EOFError):
upgrade_retcode = -1 upgrade_retcode = -1
@ -1002,6 +1004,8 @@ def app_install(operation_logger, app, label=None, args=None, no_remove_on_failu
error = m18n.n('app_install_script_failed') error = m18n.n('app_install_script_failed')
logger.exception(m18n.n("app_install_failed", app=app_id, error=error)) logger.exception(m18n.n("app_install_failed", app=app_id, error=error))
failure_message_with_debug_instructions = operation_logger.error(error) failure_message_with_debug_instructions = operation_logger.error(error)
if msettings.get('interface') != 'api':
dump_app_log_extract_for_debugging(operation_logger)
# Script got manually interrupted ... N.B. : KeyboardInterrupt does not inherit from Exception # Script got manually interrupted ... N.B. : KeyboardInterrupt does not inherit from Exception
except (KeyboardInterrupt, EOFError): except (KeyboardInterrupt, EOFError):
error = m18n.n('operation_interrupted') error = m18n.n('operation_interrupted')
@ -1118,6 +1122,33 @@ def app_install(operation_logger, app, label=None, args=None, no_remove_on_failu
hook_callback('post_app_install', args=args_list, env=env_dict) hook_callback('post_app_install', args=args_list, env=env_dict)
def dump_app_log_extract_for_debugging(operation_logger):
with open(operation_logger.log_path, "r") as f:
lines = f.readlines()
lines_to_display = []
for line in lines:
if not ": " in line.strip():
continue
# A line typically looks like
# 2019-10-19 16:10:27,611: DEBUG - + mysql -u piwigo --password=********** -B piwigo
# And we just want the part starting by "DEBUG - "
line = line.strip().split(": ", 1)[1]
lines_to_display.append(line)
if line.endswith("+ ynh_exit_properly"):
break
elif len(lines_to_display) > 20:
lines_to_display.pop(0)
logger.warning("Here's an extract of the logs before the crash. It might help debugging the error:")
for line in lines_to_display:
logger.info(line)
def _migrate_legacy_permissions(app): def _migrate_legacy_permissions(app):
from yunohost.permission import user_permission_list, user_permission_update from yunohost.permission import user_permission_list, user_permission_update

View file

@ -36,14 +36,14 @@ from datetime import datetime
from glob import glob from glob import glob
from collections import OrderedDict from collections import OrderedDict
from moulinette import msignals, m18n from moulinette import msignals, m18n, msettings
from yunohost.utils.error import YunohostError from yunohost.utils.error import YunohostError
from moulinette.utils import filesystem from moulinette.utils import filesystem
from moulinette.utils.log import getActionLogger from moulinette.utils.log import getActionLogger
from moulinette.utils.filesystem import read_file, mkdir, write_to_yaml, read_yaml from moulinette.utils.filesystem import read_file, mkdir, write_to_yaml, read_yaml
from yunohost.app import ( from yunohost.app import (
app_info, _is_installed, _parse_app_instance_name, _patch_php5 app_info, _is_installed, _parse_app_instance_name, _patch_php5, dump_app_log_extract_for_debugging
) )
from yunohost.hook import ( from yunohost.hook import (
hook_list, hook_info, hook_callback, hook_exec, CUSTOM_HOOK_FOLDER hook_list, hook_info, hook_callback, hook_exec, CUSTOM_HOOK_FOLDER
@ -1399,6 +1399,9 @@ class RestoreManager():
logger.exception(msg) logger.exception(msg)
operation_logger.error(msg) operation_logger.error(msg)
if msettings.get('interface') != 'api':
dump_app_log_extract_for_debugging(operation_logger)
self.targets.set_result("apps", app_instance_name, "Error") self.targets.set_result("apps", app_instance_name, "Error")
remove_script = os.path.join(app_scripts_in_archive, 'remove') remove_script = os.path.join(app_scripts_in_archive, 'remove')