Significantly improved logging

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;

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({

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;
   },

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); },

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()
 {

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);
   },
 

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;

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() {

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.print(msg + "\n" + console.stackstr(3), 4);
-    this.stack(1);
   },
-
-  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'); },
+  log(msg) {
-  repl(msg) { cmd(142, msg + '\n'); },    
+    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();
+    console.log(stackstr(skip+1));
-    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 = console.info;
+var say = console.log;
-
-var say = function(msg) {
-  console.say(msg);
-}
 say.doc = "Print to std out with an appended newline.";
 
 console.doc = {

source/engine/debug/log.c

@@ -8,108 +8,70 @@
 #include <unistd.h>
 #include <stdio.h>
 #include "yugine.h"
+#include "resources.h"
 
 #include "script.h"
 
-int logLevel = 0;
+char *logstr[] = { "spam", "debug", "info", "warn", "error", "panic"};
-
-char *logstr[] = { "spam", "debug", "info", "warn", "error"};
 char *catstr[] = {"engine", "script", "render"};
 
-FILE *logfile = NULL;
+static FILE *logout; /* where logs are written to */
-
+static FILE *writeout; /* where console is written to */
-#define ERROR_BUFFER 1024
-#define CONSOLE_BUF 1024*1024 /* 5MB */
-
-char *consolelog = NULL;
-
-static FILE *sout;
 
 void log_init()
 {
-  consolelog = malloc(CONSOLE_BUF+1);
+#ifndef NDEBUG
-  consolelog[0] = '\0';
+  logout = fopen(".prosperon/log.txt", "w");
-  sout = fdopen(dup(1),"w");
+  writeout = fopen(".prosperon/transcript.txt", "w");
-  sout = stdout;
+#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(NULL);
-    time_t now = time(0);
+  struct tm *tinfo = localtime(&now);
-    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_list args;
-    va_start(args, message);
+  va_start(args, message);
-    va_copy(arg2, args);
+  vfprintf(logout, message, args);
-    int len = vsnprintf(NULL, 0, message, args)+1;
+  va_end(args);
-    char *msg = malloc(len);
+  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);
+    printf("\n");
-    va_end(arg2);
+    fflush(stdout);
-    
-    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);
   }
-
 #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);
+  fprintf(writeout, str);
-
-  if (logfile) {
-    fprintf(logfile, "%s", str);
-    fflush(logfile);
-  }
 #endif
-}
+  printf(str);
-
+  fflush(stdout);
-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);
-    }
 }
 
 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;
+  lvl = LOG_PANIC-lvl;
-  mYughLog(2, lvl, line, file, "tag: %s, id: %d, msg: %s", tag, id, msg);
+  mYughLog(LOG_RENDER, lvl, line, file, "tag: %s, id: %d, msg: %s", tag, id, msg);
 }

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 YughSpam(msg,  ...) mYughLog(0, LOG_SPAM, __LINE__, __FILE__, msg, ##__VA_ARGS__);
-#define YughWarn(msg, ...) mYughLog(0, 1, __LINE__, __FILE__, msg, ##__VA_ARGS__);
+#define YughInfo(msg, ...) mYughLog(0, LOG_INFO, __LINE__, __FILE__, msg, ##__VA_ARGS__);
-#define YughError(msg, ...) mYughLog(0, 2, __LINE__, __FILE__, msg, ##__VA_ARGS__);
+#define YughWarn(msg, ...) mYughLog(0, LOG_WARN, __LINE__, __FILE__, msg, ##__VA_ARGS__);
-#define YughCritical(msg, ...) mYughLog(0, 3, __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

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);
+      log_print(str);
-      break;
-
-    case 146:
-      log_clear();
       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);

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);
+  YughSpam("Making shader %s", d->label);
-  if (sg_query_shader_state(result) == SG_RESOURCESTATE_FAILED)
+  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 = {

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;
     }
   }

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);