From f0876825f1e19ee8300f8342513544d746d8082d Mon Sep 17 00:00:00 2001 From: John Alanbrook Date: Thu, 14 Mar 2024 09:33:15 -0500 Subject: [PATCH] Significantly improved logging --- scripts/base.js | 4 +- scripts/camera2d.jso | 4 +- scripts/components.js | 2 +- scripts/debug.js | 2 +- scripts/editor.js | 10 ++-- scripts/engine.js | 9 ++- scripts/entity.js | 2 +- scripts/input.js | 2 +- scripts/std.js | 44 ++++++--------- source/engine/debug/log.c | 116 +++++++++++++------------------------- source/engine/debug/log.h | 19 +++---- source/engine/jsffi.c | 21 +------ source/engine/render.c | 30 +++++----- source/engine/texture.c | 2 +- source/engine/yugine.c | 23 +++----- 15 files changed, 107 insertions(+), 183 deletions(-) diff --git a/scripts/base.js b/scripts/base.js index 2c1e8de..e201401 100644 --- a/scripts/base.js +++ b/scripts/base.js @@ -11,7 +11,7 @@ /* Object.getPrototypeOf = undefined; Object.setPrototypeOf = undefined; -Reflect = undefined; +Reflect = undefined Symbol = undefined; URIError = undefined; Proxy = undefined; @@ -558,7 +558,7 @@ Object.hide = function(obj,...props) for (var prop of props) { var p = Object.getOwnPropertyDescriptor(obj,prop); if (!p) { - console.info(`No property of name ${prop}.`); + console.error(`No property of name ${prop}.`); continue; } p.enumerable = false; diff --git a/scripts/camera2d.jso b/scripts/camera2d.jso index 3f9466f..d8ac3b1 100644 --- a/scripts/camera2d.jso +++ b/scripts/camera2d.jso @@ -6,12 +6,12 @@ this.realzoom = function() { return cmd(135); }; this.right = function() { - return this.pos.x + (Game.width/2); + return this.pos.x + (Window.rendersize.x/2); } this.left = function() { - return this.pos.x - (Game.width/2); + return this.pos.x - (Window.rendersize.x/2); } this.mixin({ diff --git a/scripts/components.js b/scripts/components.js index 86e9287..ccb6de4 100644 --- a/scripts/components.js +++ b/scripts/components.js @@ -24,7 +24,7 @@ var component = { nc.gameobject = go; Object.mixin(nc, this._enghook(go.body)); assign_impl(nc,this.impl); - Object.hide(nc, ['gameobject', 'id']); + Object.hide(nc, 'gameobject', 'id'); nc.post(); return nc; }, diff --git a/scripts/debug.js b/scripts/debug.js index d3850c1..dc5196e 100644 --- a/scripts/debug.js +++ b/scripts/debug.js @@ -130,7 +130,7 @@ Object.assign(performance, { var avgt = performance.best_t(elapsed/times); var totalt = performance.best_t(elapsed); - console.say(`performance [${q}]: ${avgt.time.toFixed(3)} ${avgt.unit} average [${totalt.time.toFixed(3)} ${totalt.unit} for ${times} loops]`); + say(`performance [${q}]: ${avgt.time.toFixed(3)} ${avgt.unit} average [${totalt.time.toFixed(3)} ${totalt.unit} for ${times} loops]`); }, get fps() { return sys_cmd(8); }, diff --git a/scripts/editor.js b/scripts/editor.js index 4682045..6644635 100644 --- a/scripts/editor.js +++ b/scripts/editor.js @@ -1554,7 +1554,7 @@ var replpanel = Object.copy(inputpanel, { guibody() { this.win.selectable = true; - var log = cmd(84); + //var log = cmd(84); log = log.slice(-5000); return [ Mum.text({str:log, anchor:[0,0], offset:[0,-300].sub(this.scrolloffset), selectable: true}), @@ -1575,12 +1575,12 @@ var replpanel = Object.copy(inputpanel, { ecode += `var ${key} = editor.edit_level.objects['${key}'];`; ecode += this.value; - console.say(this.value); + say(this.value); this.value = ""; this.caret = 0; var ret = function() {return eval(ecode);}.call(repl_obj); if (typeof ret === 'object') ret = json.encode(ret,null,1); - console.say(ret); + say(ret); }, resetscroll() { @@ -1616,7 +1616,7 @@ replpanel.inputs.tab = function() { if (eval(`typeof ${keyobj.tofirst('.')}`) === 'object' && eval(`typeof ${keyobj.replace('.', '?.')}`) === 'object') obj = eval(keyobj); else if (this.value.includes('.')){ - console.say(`${this.value} is not an object.`); + say(`${this.value} is not an object.`); return; } @@ -1657,7 +1657,7 @@ replpanel.inputs.tab = function() { }); if (keys.length > 1) - console.repl(keys.join(', ')); + say(keys.join(', ')); }; replpanel.inputs['C-p'] = function() { diff --git a/scripts/engine.js b/scripts/engine.js index 6205342..9c5afb4 100644 --- a/scripts/engine.js +++ b/scripts/engine.js @@ -3,10 +3,9 @@ globalThis.global = globalThis; function use(file) { - if (use.files[file]) return use.files[file]; if (globalThis.console) - console.warn(`running ${file}`); + console.info(`running ${file}`); var c = io.slurp(file); @@ -20,7 +19,7 @@ use.files = {}; function include(file,that) { if (!that) return; - if (globalThis.console) console.warn(`running ${file}`); + if (globalThis.console) console.info(`running ${file}`); var c = io.slurp(file); eval_env(c, that, file); } @@ -29,7 +28,7 @@ function eval_env(script, env, file) { env ??= {}; file ??= "SCRIPT"; - if (globalThis.console) console.warn(`eval ${file}`); + if (globalThis.console) console.info(`eval ${file}`); script = `(function() { ${script}; }).call(this);\n`; return cmd(123,script,env,file); } @@ -91,7 +90,7 @@ global.mixin("scripts/render.js"); global.Game = { engine_start(fn) { - console.warn("engine starting."); + console.info("Starting rendering and sound ..."); cmd(257, fn); }, diff --git a/scripts/entity.js b/scripts/entity.js index a226be5..096ee63 100644 --- a/scripts/entity.js +++ b/scripts/entity.js @@ -742,7 +742,7 @@ ur { /* Apply an ur u to an entity e */ /* u is given as */ function apply_ur(u, e) { - console.log(`applying ur ${u}`); + console.info(`Applying ur named ${u}.`); if (typeof u !== 'string') { console.warn("Must give u as a string."); return; diff --git a/scripts/input.js b/scripts/input.js index 01fb988..9264ec2 100644 --- a/scripts/input.js +++ b/scripts/input.js @@ -336,7 +336,7 @@ var Player = { print_pawns() { for (var pawn of this.pawns.reversed()) - console.say(pawn.toString()); + say(pawn.toString()); }, create() { diff --git a/scripts/std.js b/scripts/std.js index 04f9d8b..155ed64 100644 --- a/scripts/std.js +++ b/scripts/std.js @@ -121,8 +121,6 @@ Resources.replstrs = function(path) } var console = { - set level(x) { cmd(92,x); }, - get level() { return cmd(93); }, print(msg, lvl) { var lg; if (typeof msg === 'object') { @@ -142,10 +140,12 @@ var console = { yughlog(lvl, lg, file, line); }, + spam(msg) { this.print(msg,0); }, + /* this always prints to stdout */ debug(msg) { this.print(msg,1); }, @@ -159,41 +159,29 @@ var console = { }, error(msg) { - this.print(msg, 4); - this.stack(1); + this.print(msg + "\n" + console.stackstr(3), 4); }, - - write(msg) { - if (typeof msg === 'object') - msg = JSON.stringify(msg,null,2); - cmd(91,msg); + panic(msg) { + this.print(msg + "\n" + console.stackstr(1), 5); }, - say(msg) { console.write(msg + '\n'); }, - repl(msg) { cmd(142, msg + '\n'); }, + log(msg) { + if (typeof msg === 'object') msg = JSON.stringify(msg,null,1); + cmd(91, msg + '\n'); + }, + stackstr(skip=0) { + var err = new Error(); + var stack = err.stack.split('\n'); + return stack.slice(skip,stack.length-10).join('\n'); + }, stack(skip = 0) { - var err = new Error(); - var stack = err.stack; - var n = stack.next('\n',0)+1; - for (var i = 0; i < skip; i++) - n = stack.next('\n', n)+1; - console.write(err.name); - console.write(err.message); - console.write(err.stack); - }, - - clear() { - cmd(146); + console.log(stackstr(skip+1)); }, }; -console.log = console.info; - -var say = function(msg) { - console.say(msg); -} +var say = console.log; say.doc = "Print to std out with an appended newline."; console.doc = { diff --git a/source/engine/debug/log.c b/source/engine/debug/log.c index 308e70d..f6996a1 100644 --- a/source/engine/debug/log.c +++ b/source/engine/debug/log.c @@ -8,108 +8,70 @@ #include #include #include "yugine.h" +#include "resources.h" #include "script.h" -int logLevel = 0; - -char *logstr[] = { "spam", "debug", "info", "warn", "error"}; +char *logstr[] = { "spam", "debug", "info", "warn", "error", "panic"}; char *catstr[] = {"engine", "script", "render"}; -FILE *logfile = NULL; - -#define ERROR_BUFFER 1024 -#define CONSOLE_BUF 1024*1024 /* 5MB */ - -char *consolelog = NULL; - -static FILE *sout; +static FILE *logout; /* where logs are written to */ +static FILE *writeout; /* where console is written to */ void log_init() { - consolelog = malloc(CONSOLE_BUF+1); - consolelog[0] = '\0'; - sout = fdopen(dup(1),"w"); - sout = stdout; +#ifndef NDEBUG + logout = fopen(".prosperon/log.txt", "w"); + writeout = fopen(".prosperon/transcript.txt", "w"); +#endif } -const char *logfmt = "%s:%d: %s, %s: %s\n"; +void log_shutdown() +{ + fclose(logout); + fclose(writeout); +} + +const char *logfmt = "%s:%d: [%s] %s, %s: "; void mYughLog(int category, int priority, int line, const char *file, const char *message, ...) { #ifndef NDEBUG - if (priority >= logLevel) { - time_t now = time(0); - struct tm *tinfo = localtime(&now); + time_t now = time(NULL); + struct tm *tinfo = localtime(&now); + char timebuf[80]; + strftime(timebuf, sizeof(timebuf), "%Y-%m-%d %H:%M:%S", tinfo); - double ticks = (double)clock()/CLOCKS_PER_SEC; + fprintf(logout, logfmt, file, line, timebuf, logstr[priority], catstr[category]); - va_list args, arg2; - va_start(args, message); - va_copy(arg2, args); - int len = vsnprintf(NULL, 0, message, args)+1; - char *msg = malloc(len); + va_list args; + va_start(args, message); + vfprintf(logout, message, args); + va_end(args); + fprintf(logout, "\n"); + + if (priority == LOG_DEBUG) { + printf(logfmt, file, line, timebuf, logstr[priority], catstr[category]); + va_list args; + va_start(args,message); + vprintf(message, args); va_end(args); - vsnprintf(msg, len, message, arg2); - va_end(arg2); - - len = snprintf(NULL, 0, logfmt, file,line,logstr[priority], catstr[category], msg)+1; - char *buffer = malloc(len); - snprintf(buffer, len, logfmt, file, line, logstr[priority], catstr[category], msg); - - fprintf(stderr, "%s", buffer); -// if (priority >= LOG_ERROR) -// js_stacktrace(); - fflush(stderr); - - free(msg); - free(buffer); + printf("\n"); + fflush(stdout); } - #endif } +/* print to stdout and console */ void log_print(const char *str) { - fprintf(sout, "%s", str); - fflush(sout); - #ifndef NDEBUG - strncat(consolelog, str, CONSOLE_BUF); - - if (logfile) { - fprintf(logfile, "%s", str); - fflush(logfile); - } + fprintf(writeout, str); #endif -} - -void log_clear() -{ - consolelog[0] = 0; -} - -void console_print(const char *str) -{ -#ifndef NDEBUG - strncat(consolelog, str, CONSOLE_BUF); -#endif -} - -void log_setfile(char *file) { - freopen(file, "w", stderr); - freopen(file, "w", stdout); -} - -void log_cat(FILE *f) { - char out[1024]; - - while (fgets(out, sizeof(out), f)) { - out[strcspn(out, "\n")] = '\0'; - YughInfo(out); - } + printf(str); + fflush(stdout); } void sg_logging(const char *tag, uint32_t lvl, uint32_t id, const char *msg, uint32_t line, const char *file, void *data) { - lvl = 3-lvl; - mYughLog(2, lvl, line, file, "tag: %s, id: %d, msg: %s", tag, id, msg); + lvl = LOG_PANIC-lvl; + mYughLog(LOG_RENDER, lvl, line, file, "tag: %s, id: %d, msg: %s", tag, id, msg); } diff --git a/source/engine/debug/log.h b/source/engine/debug/log.h index bb07dff..88d0eb7 100644 --- a/source/engine/debug/log.h +++ b/source/engine/debug/log.h @@ -9,22 +9,22 @@ #define LOG_INFO 2 #define LOG_WARN 3 #define LOG_ERROR 4 +#define LOG_PANIC 5 #define LOG_ENGINE 0 #define LOG_SCRIPT 1 #define LOG_RENDER 2 -extern char *consolelog; -extern int logLevel; - void log_init(); +void log_shutdown(); #ifndef NDEBUG #define YughLog(cat, pri, msg, ...) mYughLog(cat, pri, __LINE__, __FILE__, msg, ##__VA_ARGS__) -#define YughInfo(msg, ...) mYughLog(0, 0, __LINE__, __FILE__, msg, ##__VA_ARGS__); -#define YughWarn(msg, ...) mYughLog(0, 1, __LINE__, __FILE__, msg, ##__VA_ARGS__); -#define YughError(msg, ...) mYughLog(0, 2, __LINE__, __FILE__, msg, ##__VA_ARGS__); -#define YughCritical(msg, ...) mYughLog(0, 3, __LINE__, __FILE__, msg, ##__VA_ARGS__); +#define YughSpam(msg, ...) mYughLog(0, LOG_SPAM, __LINE__, __FILE__, msg, ##__VA_ARGS__); +#define YughInfo(msg, ...) mYughLog(0, LOG_INFO, __LINE__, __FILE__, msg, ##__VA_ARGS__); +#define YughWarn(msg, ...) mYughLog(0, LOG_WARN, __LINE__, __FILE__, msg, ##__VA_ARGS__); +#define YughError(msg, ...) mYughLog(0, LOG_ERROR, __LINE__, __FILE__, msg, ##__VA_ARGS__); +#define YughCritical(msg, ...) mYughLog(0, LOG_PANIC, __LINE__, __FILE__, msg, ##__VA_ARGS__); #else #define YughLog(cat, pri, msg, ...) #define YughInfo(msg, ...) @@ -33,13 +33,10 @@ void log_init(); #define YughCritical(msg, ...) #endif +/* These log to the correct areas */ void mYughLog(int category, int priority, int line, const char *file, const char *message, ...); void sg_logging(const char *tag, uint32_t lvl, uint32_t id, const char *msg, uint32_t line, const char *file, void *data); -void log_setfile(char *file); -void log_cat(FILE *f); void log_print(const char *str); -void log_clear(); -void console_print(const char *str); #endif diff --git a/source/engine/jsffi.c b/source/engine/jsffi.c index 050c1b5..c2e1879 100644 --- a/source/engine/jsffi.c +++ b/source/engine/jsffi.c @@ -825,10 +825,6 @@ JSValue duk_cmd(JSContext *js, JSValueConst this, int argc, JSValueConst *argv) draw_edge(v1, js_arrlen(argv[1]), js2color(argv[2]), js2number(argv[3]), 0, js2color(argv[2]), 10); break; - case 84: - ret = consolelog ? JS_NewString(js, consolelog) : JS_NewString(js,""); - break; - case 85: ret = vec22js(HMM_ProjV2(js2vec2(argv[1]), js2vec2(argv[2]))); break; @@ -854,18 +850,11 @@ JSValue duk_cmd(JSContext *js, JSValueConst this, int argc, JSValueConst *argv) log_print(str); break; - case 92: - logLevel = js2int(argv[1]); - break; - - case 93: - ret = int2js(logLevel); - break; - case 97: str = js2str(argv[1]); cursor_img(str); break; + case 103: ret = vec22js(js2gameobject(argv[1])->scale.XY); break; @@ -972,11 +961,7 @@ JSValue duk_cmd(JSContext *js, JSValueConst this, int argc, JSValueConst *argv) case 142: str = JS_ToCString(js, argv[1]); - console_print(str); - break; - - case 146: - log_clear(); + log_print(str); break; case 149: @@ -1275,7 +1260,7 @@ JSValue duk_yughlog(JSContext *js, JSValueConst this, int argc, JSValueConst *ar const char *f = JS_ToCString(js, argv[2]); int line = js2int(argv[3]); - mYughLog(1, cmd, line, f, s); + mYughLog(LOG_SCRIPT, cmd, line, f, s); JS_FreeCString(js, s); JS_FreeCString(js, f); diff --git a/source/engine/render.c b/source/engine/render.c index f54ed13..5289698 100644 --- a/source/engine/render.c +++ b/source/engine/render.c @@ -177,47 +177,47 @@ static struct { } sg_shadow; -void trace_make_image(const sg_image_desc *d, sg_image result, void *data) +void trace_make_image(const sg_image_desc *d, sg_image id, void *data) { - YughInfo("Making image %s", d->label); + YughSpam("Made image %s.", d->label); } void trace_init_image(sg_image id, const sg_image_desc *d, void *data) { - YughInfo("Init image %s", d->label); + YughSpam("Init image %s", d->label); } -void trace_make_shader(const sg_shader_desc *d, sg_shader result, void *data) +void trace_make_shader(const sg_shader_desc *d, sg_shader id, void *data) { - YughInfo("Making shader %s", d->label); - if (sg_query_shader_state(result) == SG_RESOURCESTATE_FAILED) + YughSpam("Making shader %s", d->label); + if (sg_query_shader_state(id) == SG_RESOURCESTATE_FAILED) YughError("FAILED MAKING A SHADER: %s\n%s\n%s", d->label); } void trace_fail_shader(sg_shader id, void *data) { - YughError("SHADER DID NOT COMPILE"); + YughError("Shader %u did not compile.", id); } -void trace_destroy_shader(sg_shader shd, void *data) +void trace_destroy_shader(sg_shader id, void *data) { - YughInfo("DESTROYED SHADER"); + YughSpam("Destroyed shader %u.", id); } void trace_fail_image(sg_image id, void *data) { sg_image_desc desc = sg_query_image_desc(id); - YughError("Failed to make image %s", desc.label); + YughError("Failed to make image %u %s", id, desc.label); } -void trace_make_pipeline(const sg_pipeline_desc *d, sg_pipeline result, void *data) +void trace_make_pipeline(const sg_pipeline_desc *d, sg_pipeline id, void *data) { - YughInfo("Making pipeline %s, id %d", d->label, result); + YughSpam("Making pipeline %u [%s].", id, d->label); } void trace_apply_pipeline(sg_pipeline pip, void *data) { - YughInfo("Applying pipeline %d", pip); + YughSpam("Applying pipeline %u %s.", pip, sg_query_pipeline_desc(pip).label); } void trace_fail_pipeline(sg_pipeline pip, void *data) @@ -227,12 +227,12 @@ void trace_fail_pipeline(sg_pipeline pip, void *data) void trace_make_attachments(const sg_attachment_desc *d, sg_attachments result, void *data) { - YughInfo("Making attachments %s", "IMPLEMENT"); + YughSpam("Making attachments %s", "IMPLEMENT"); } void trace_begin_pass(sg_pass pass, const sg_pass_action *action, void *data) { - YughInfo("Begin pass %s", pass.label); + YughSpam("Begin pass %s", pass.label); } static sg_trace_hooks hooks = { diff --git a/source/engine/texture.c b/source/engine/texture.c index cc9baac..fd73d3f 100644 --- a/source/engine/texture.c +++ b/source/engine/texture.c @@ -207,7 +207,7 @@ void texture_free(texture *tex) char *tex_get_path(struct texture *tex) { for (int i = 0; i < shlen(texhash); i++) { if (tex == texhash[i].value) { - YughInfo("Found key %s", texhash[i].key); + YughSpam("Found key %s", texhash[i].key); return texhash[i].key; } } diff --git a/source/engine/yugine.c b/source/engine/yugine.c index 30fdde9..3819ebe 100644 --- a/source/engine/yugine.c +++ b/source/engine/yugine.c @@ -84,12 +84,6 @@ static int sim_play = SIM_PLAY; static int argc; static char **args; -void seghandle() -{ - js_stacktrace(); - exit(1); -} - static JSValue c_init_fn; void c_init() { @@ -153,11 +147,17 @@ void c_frame() void cleanup() { - sfetch_shutdown(); out_memusage(".prosperon/jsmem.txt"); script_stop(); } +void seghandle() +{ + js_stacktrace(); + cleanup(); + exit(1); +} + void c_clean() { cleanup(); gif_rec_end("out.gif"); @@ -293,14 +293,7 @@ int main(int argc, char **argv) { setlocale(LC_ALL, "en_US.utf8"); #ifndef NDEBUG log_init(); - int logout = 0; - if (logout) { - time_t now = time(NULL); - char fname[100]; - snprintf(fname, 100, "yugine-%ld.log", now); - log_setfile(fname); - } - + signal(SIGSEGV, seghandle); signal(SIGABRT, seghandle); signal(SIGFPE, seghandle);