myvtm/Framework/spshell/log.cpp

#include "precompile.h"
#include "SpBase.h"

#include "log.h"
#include "app.h"

#include "sp_log.h"
#include "sp_svc.h"
#include "sp_iom.h"
#include "sp_cfg.h"
#include "sp_env.h"

#include "fileutil.h"
#include "strutil.h"
#include "dbgutil.h"
#include <winpr/file.h>

#ifdef _WIN32
#include "SpShellConsole.h"
#endif //_WIN32

#define MAX_LOGFILE_SIZE	(1<<20)

typedef struct log_t {
	SYSTEMTIME tm_start;
	FILE *fp;
	int file_seq;// non-zero when file is already exist
	int last_error;
	sp_log_daemon_t *log_daemon;
}log_t;

static const char *str_types[] = {
	"Nil",
	"Evt",
	"Wrn",
	"Err",
	"Dbg",
};

static const char *str_severity[] = {
	"Nil",
	"low",
	"mid",
	"hgh",
};

static BOOL __log_need_change(log_t *log, LPSYSTEMTIME now)
{
	TOOLKIT_ASSERT(now);

	/* if error occurs, may be Hard Disk broken or space is run out. so no need to change file */
	if (log->last_error)
		return FALSE; 

	/* fp currently is null, when system start */
	if (!log->fp)
		return TRUE;

	/* a new day come */
	if (log->tm_start.wYear != now->wYear || 
		log->tm_start.wMonth != now->wMonth ||
		log->tm_start.wDay != now->wDay)
		return TRUE;

	/* file size has exceed MAX_LOGFILE_SIZE */
	if (ftell(log->fp) > MAX_LOGFILE_SIZE) {
		return TRUE;
	}

	/* 10 minutes pass */
	{
		int diff = (now->wHour - log->tm_start.wHour) * 3600;
		diff += (now->wMinute - log->tm_start.wMinute) * 60;
		diff += (now->wSecond - log->tm_start.wSecond);
		if (diff >= 600) {
			return TRUE;
		}
	}

	return FALSE;
}

static const char *get_temp_path(char *buf, LPSYSTEMTIME now, int seq)
{
	sp_env_t *env = sp_get_env();
	sp_cfg_t *cfg = env->cfg;
	sp_cfg_root_ini_t *root_cfg = cfg->root_ini;
	const char *dir = root_cfg->ref_syslog_path;

	if (dir != NULL && strlen(dir) > 0) {
        if (seq) {
            sprintf(buf, "%s" SPLIT_SLASH_STR "%08X_%02d-%02d-%02d_%02d-%02d-%02d(%03d)", dir,
                    cfg->install_ini->current_startup_time,
                    now->wYear, now->wMonth, now->wDay,
                    now->wHour, now->wMinute, now->wSecond, seq % 1000);
        } else {
            sprintf(buf, "%s" SPLIT_SLASH_STR "%08X_%02d-%02d-%02d_%02d-%02d-%02d", dir,
                    cfg->install_ini->current_startup_time,
                    now->wYear, now->wMonth, now->wDay,
                    now->wHour, now->wMinute, now->wSecond);
        }
	}

	return buf;
}

static const char *new_tmp_path(char *buf, LPSYSTEMTIME now, int *file_seq)
{
	int seq = 0;
	int i;
	const int max_tries = 1000;

	for (i = 0; i < max_tries; ++i) {
		get_temp_path(buf, now, seq);
		strcat(buf, ".xml");
		if (ExistsFileA(buf)) {
			seq++;
		} else {
			break;
		}
	}

	if (i == max_tries) {
		return NULL;
	}

	//buf[strlen(buf) - 4] = 0;

	*file_seq = seq;

	return buf;
}

static BOOL rename_file1(LPSYSTEMTIME tm_start, int file_seq)
{
	char x[MAX_PATH];
	char y[MAX_PATH];

	get_temp_path(x, tm_start, file_seq);
	strcpy(y, x);
	strcat(y, ".xml");

	return MoveFileExA(x, y, MOVEFILE_REPLACE_EXISTING);
}

static void __log_change_file(log_t *log, LPSYSTEMTIME now)
{
	char tmp[MAX_PATH];

	if (log->fp) {
		fflush(log->fp);
		fclose(log->fp);
		log->fp = NULL;
	}

	if (!new_tmp_path(tmp, now, &log->file_seq)) {
		log->last_error = -1;
		DbgWithLink(LOG_LEVEL_WARN, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)("cannot create log tmp file");
		return;
	}

	log->fp = fopen(tmp, "wb");
	if (!log->fp) {
		log->last_error = -1;
		DbgWithLink(LOG_LEVEL_WARN, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)("cannot fopen log tmp file %s", tmp);
		return;
	} else {
		memcpy(&log->tm_start, now, sizeof(SYSTEMTIME));
	}
}

static void __log_write_record(log_t *log, 
	u__int64_t log_id,
	LPSYSTEMTIME tm,
	int log_type, 
	u__int64_t prev_rsn,
	u__int64_t curr_rsn,
	int original_rsn_type, 
	int rsn_depth,
	int log_severity,
	int log_sys_error, 
	int log_usr_error,
	const char *module,
	const char *entity,
	const char *msg)
{
	int n;
	
	n = fprintf(log->fp, 
		//"<Log SN=\"0x%llX\" Time=\"%02d:%02d:%02d\" LogType=\"%d\" CRS=\"0x%llX\" LRS=\"0x%llX\" ORS=\"0x%X\" RunCount=\"%d\" SeverityLevel=\"%d\" SysCode=\"0x%X\" UserCode=\"0x%X\" SpName=\"%s\" Entity=\"%s\">%s</Log>\r\n",
		"<Log SN=\"0x%llX\" Time=\"%02d:%02d:%02d\" LogType=\"%d\" SeverityLevel=\"%d\" SysCode=\"0x%X\" UserCode=\"0x%X\" SpName=\"%s\" Entity=\"%s\">%s</Log>\r\n",
		log_id, 
		tm->wHour, tm->wMinute, tm->wSecond, 
		log_type, 
		/*curr_rsn, 
		prev_rsn,
		original_rsn_type, 
		rsn_depth, */
		log_severity,
		log_sys_error,
		log_usr_error,
		module, 
		entity, 
		msg);
	if (n < 0) {
		log->last_error = -1;
		fclose(log->fp);
		log->fp = NULL;
			
		DbgWithLink(LOG_LEVEL_WARN, LOG_TYPE_SYSTEM).setAPI(__FUNCTION__)("write log record failed!");
	}
}


static void on_log(void *inst, 
	int nsub,
	u__int64_t *sub,
	int client_id, 
	int log_epid,
	int client_instance_id,
	u__int64_t log_id,
	u__int64_t prev_rsn,
	u__int64_t curr_rsn,
	int original_rsn_type, 
	int rsn_depth, 
	unsigned int log_time,
	int log_type, 
	int log_severity, 
	int log_sys_error, 
	int log_usr_error,
	int param_cnt, 
	int *params,
	const char *msg, 
	void *user_data,
	const char* bussId, const char* traceId, const char* spanId, const char* parentSpanId)
{
	
	sp_env_t *env = sp_get_env();
	sp_cfg_t *cfg = env->cfg;
	sp_cfg_shell_entity_t *ent = sp_cfg_get_entity_by_idx(cfg, client_id);
	sp_cfg_shell_module_t *mod = ent ? ent->mod : sp_cfg_get_module_by_idx(cfg, log_epid);
	log_t *log = (log_t*)user_data;
	app_t *app = get_app_instance();

	if (cfg == NULL || ent == NULL || mod == NULL || log == NULL || app == NULL)
		return;

#ifdef RVC_OS_WIN
    // 在调试控制台显示已订阅实体日志
	if (app->pConsole != NULL && app->pConsole->HasSubLogCnn()) {
		app->pConsole->OutputLog(client_id, ent->name, msg);
	}
#endif //RVC_OS_WIN

	if(app->bsc_gui != NULL) {

        CSimpleStringA msgContent(true);
        int notifyType = 0;
		const bool needTosendNormal = (ent->debug_level > 0);

		if (log_type == 1 && needTosendNormal) { // Log_Event
			notifyType = GUI_DISPLAY_ELEM_LOG_EVENT;
			msgContent = CSimpleStringA::Format("[%s] I:{%s}(uc:0x%X)", ent->name, msg, log_usr_error);
		}
		else if (log_type == 2 && (needTosendNormal || log_severity == 3 /*Severity_High*/)) { //Log_Warning
			notifyType = GUI_DISPLAY_ELEM_LOG_WARN;
            msgContent = CSimpleString::Format("[%s] W:{%s}(sc:0x%X, uc:0x%X)", ent->name, msg, log_sys_error, log_usr_error);
		}
		else if (log_type == 3) {// Log_Error
			notifyType = GUI_DISPLAY_ELEM_LOG_ERROR;
			msgContent = CSimpleString::Format("[%s] E:{%s}(sc:0x%X, uc:0x%X)", ent->name, msg, log_sys_error, log_usr_error);
		}
        else if ((log_type == 4 || log_type == 0) && needTosendNormal) {// Log_Debug
			notifyType = GUI_DISPLAY_ELEM_LOG_DEBUG;
			msgContent = CSimpleString::Format("[%s] D:{%s}", ent->name, msg);
		}
		else if (log_type == 5) {// Log_Fatal
			notifyType = GUI_DISPLAY_ELEM_LOG_FATAL;
			msgContent = CSimpleString::Format("[%s] F:{%s}(sc:0x%X, uc:0x%X)", ent->name, msg, log_sys_error, log_usr_error);
		}
		else if (log_type == 6) {//Log_Notify
            notifyType = GUI_DISPLAY_ELEM_NOTIFY_INFO;
            if (log_severity == 2) {//Notify_Warn
                notifyType = GUI_DISPLAY_ELEM_NOTIFY_WARN;
            } else if (log_severity == 3) {
                notifyType = GUI_DISPLAY_ELEM_NOTIFY_ERROR;
            }
#if defined(_MSC_VER)
			msgContent = CSimpleString::Format("[%s] N:{%s}(sc:0x%X, uc:0x%X)", ent->name, msg, log_sys_error, log_usr_error);
#else
			CSimpleStringA strMsg = CSimpleStringA::Format("%s V%d.%d.%d", ent->name, ent->version.major, ent->version.minor, ent->version.revision);
			strMsg += ":][:"; /** arrange with QtGUIConsole to split entity name and msg content [Gifur@202133]*/
			msgContent = CSimpleString::Format("%s%s", strMsg.GetData(), msg);
#endif //_MSC_VER
		}

		if (notifyType != 0) {
#if defined(_MSC_VER)
			sp_gui_show_running_info(app->bsc_gui, msgContent, notifyType);
#else
			app->bsc_gui->show_running_info(app->bsc_gui->gui_inst, msgContent, notifyType);
#endif //_MSC_VER
		}
	}

	/** 不打印SystemLog [Gifur@2022516]*/

	//SYSTEMTIME st;
	//y2k_to_localtime(log_time, &st);

	//if (__log_need_change(log, &st)) {
	//	__log_change_file(log, &st);
	//}

	//if (!log->last_error && log->fp) {
	//	LARGE_INTEGER t;
	//	char *escape = str_xml_escape(msg);
	//	t.QuadPart = log_id;
	//	__log_write_record(log, 
	//		log_id, &st, log_type, 
	//		prev_rsn, curr_rsn, original_rsn_type, rsn_depth, 
	//		log_severity, log_sys_error, log_usr_error, 
	//		mod->name, ent ? ent->name : "$Anonymous$", escape);
	//	FREE(escape);
	//}
}

// user send flush command
static void on_flush(void *inst, 
					 int client_id, 
					 LPSYSTEMTIME lst, 
					 void *user_data)
{
	log_t *log = (log_t*)user_data;
	if (log->fp) {
		fflush(log->fp);
		/*fclose(log->fp);
		log->fp = NULL;*/
	}
}

static void on_timeout_interval(void *inst, LPSYSTEMTIME lst, void *user_data)
{
	/** 不打印SystemLog [Gifur@2022516]*/

	//log_t *log = (log_t*)user_data;
	//if (log->fp) {
	//	if (__log_need_change(log, lst)) {
	//		fclose(log->fp);
	//		log->fp = NULL;
	//	} else {
	//		fflush(log->fp);
	//	}
	//}
}

int log_create(sp_svc_t *svc, log_t **p_log)
{
	log_t *log = ZALLOC_T(log_t);
	sp_env_t *env = sp_get_env();
	sp_cfg_t *cfg = env->cfg;
	sp_cfg_root_ini_t *root_cfg = cfg->root_ini;
	//const char *dir = root_cfg->ref_syslog_path;
	int rc;

	rc = sp_log_daemon_create(&on_log, &on_flush, &on_timeout_interval, log, svc, &log->log_daemon);
	if (rc == 0) {
		*p_log = log;
	} else {
		free(log);
	}
	return rc;
}

int log_destroy(log_t *log)
{
	int rc;

	rc = sp_log_daemon_destroy(log->log_daemon);
	if (rc == 0) {
		if (log->fp) {
			fflush(log->fp);
			fclose(log->fp);
			log->fp = NULL;
		}
		free(log);
	}

	return 0;
}