myvtm/spshell/log.cpp

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

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

#include "fileutil.h"
#include "strutil.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)
{
	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 (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;
		sp_dbg_warn("cannot create log tmp file");
		return;
	}

	log->fp = fopen(tmp, "wb");
	if (!log->fp) {
		log->last_error = -1;
		sp_dbg_warn("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;
			
		sp_dbg_warn("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)
{
	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();

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

	// 在启动画面显示日志
	if (log_type == 1) // Log_Event
		sp_gui_show_running_info(app->bsc_gui, CSimpleString::Format("[%s] I:{%s}(uc:0x%X)", ent->name, msg,  log_usr_error), 0);
	else if (log_type == 2)	// Log_Warning
		sp_gui_show_running_info(app->bsc_gui, CSimpleString::Format("[%s] W:{%s}(sc:0x%X, uc:0x%X)", ent->name, msg, log_sys_error, log_usr_error), 0);
	else if (log_type == 3)	// Log_Error
		sp_gui_show_running_info(app->bsc_gui, CSimpleString::Format("[%s] E:{%s}(sc:0x%X, uc:0x%X)", ent->name, msg, log_sys_error, log_usr_error), 0);
	else if (log_type == 4 || log_type == 0)	// Log_Debug
		sp_gui_show_running_info(app->bsc_gui, CSimpleString::Format("[%s] D:{%s}", ent->name, msg), 0);

#endif //_WIN32

	// 输出到文件
	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)
{
	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;
}