X-Git-Url: http://git.squeep.com/?p=dcpu16;a=blobdiff_plain;f=dcpu16.c;fp=dcpu16.c;h=c63c8002ae3762c2aed40973745ae38047a04344;hp=e8e24d137c8f8a25b8bb62f810a6c9b9dd725ad1;hb=8265806f12a2ae59501cdcf2300b42d4d1c3a120;hpb=49be905f037fbd22b6ae0275efbab2ed95d4d9b7

diff --git a/dcpu16.c b/dcpu16.c
index e8e24d1..c63c800 100644
--- a/dcpu16.c
+++ b/dcpu16.c
@@ -54,62 +54,63 @@ const char * const dcpu16_reg_names[] = {
     NULL
 };
 
-static void printf_null_(char *fmt, ...) { (void)fmt; }
+#define MSG_(__level__, __vm__, ...) do { ((__vm__) ? ((struct dcpu16 *)(__vm__))->msg_cb_ : dcpu16_msg_)((__level__), __VA_ARGS__); } while (0)
+#define MSG_INFO(__vm__,...) MSG_(MSG_INFO, __vm__, __VA_ARGS__)
+#define MSG_ERROR(__vm__,...) MSG_(MSG_ERROR, __vm__, __VA_ARGS__)
+#ifdef DEBUG
+#define MSG_DEBUG(__vm__,...) MSG_(MSG_DEBUG, __vm__, __VA_ARGS__)
+#else /* DEBUG */
+#define MSG_DEBUG(__vm__,...) do {} while (0)
+#endif /* DEBUG */
+#ifdef DEBUG_DECODE
+#define MSG_DEBUG_DECODE (MSG_DEBUG + 2)
+#endif /* DEBUG_DECODE
 
-/* some default warning and debug reporting functions, which can be overridden by clients */
-#define WARN(...) do { if (warn_cb_) warn_cb_(__VA_ARGS__); } while (0)
-static inline void warn_(char *fmt, ...) __attribute__((format(printf, 1, 2)));
+/* messages could be sent nowhere */
+static void msg_null_(unsigned int l, char *fmt, ...) { (void)l, (void)fmt; }
+
+/* messages default to standard streams */
+static void msg_default_(unsigned int, char *, ...) __attribute__((format(printf, 2, 3)));
 static inline
-void warn_(char *fmt, ...) {
+void msg_default_(unsigned int l, char *fmt, ...) {
+    static const char * const msg_tag_[] = { "info", "error", "debug" };
+    FILE *f = (l <= MSG_INFO) ? stderr : stdout;
     va_list ap;
 
-    fprintf(stderr, "[warning] ");
+    if (l < sizeof msg_tag_ / sizeof *msg_tag_)
+        fprintf(f, "[%s] ", msg_tag_[l]);
+    else
+        fprintf(f, "[%u] ", l);
+
     va_start(ap, fmt);
-    vfprintf(stderr, fmt, ap);
+    vfprintf(f, fmt, ap);
     va_end(ap);
-    fprintf(stderr, "\n");
-    fflush(stderr);
-}
-static void (*warn_cb_)(char *fmt, ...) = warn_;
-void dcpu16_warn_cb_set(void (*fn)(char *fmt, ...)) {
-    if (fn)
-        warn_cb_ = fn;
-    else
-        warn_cb_ = printf_null_;
+
+    fprintf(f, "\n");
+
+    fflush(f);
 }
 
-#ifdef DEBUG
-#define TRACE(...) do { if (trace_cb_) trace_cb_(__VA_ARGS__); } while (0)
-static inline void trace_(char *fmt, ...) __attribute__((format(printf, 1, 2)));
-static inline
-void trace_(char *fmt, ...) {
-    va_list ap;
+/*  dcpu16 message callback
+ *  This function pointer is copied into newly instantiated dcpu16 structures,
+ *  and is invoked directly for messages independant of a dcpu16 context.
+ */
+dcpu16_msg_cb_t *dcpu16_msg_ = msg_default_;
 
-    fprintf(stdout, "[debug] ");
-    va_start(ap, fmt);
-    vfprintf(stdout, fmt, ap);
-    va_end(ap);
-    fprintf(stdout, "\n");
-    fflush(stdout);
+/* set a new default message callback */
+/* returns the previous setting */
+dcpu16_msg_cb_t *dcpu16_msg_set_default(dcpu16_msg_cb_t *msg_cb) {
+    dcpu16_msg_cb_t *r = dcpu16_msg_;
+    dcpu16_msg_ = msg_cb ? msg_cb : msg_null_;
+    return r;
 }
-#else /* DEBUG */
-#define TRACE(...) do {} while(0)
-#endif /* DEBUG */
-static void (*trace_cb_)(char *fmt, ...) =
-#ifdef DEBUG
-    trace_
-#else /* DEBUG */
-    NULL
-#endif
-    ;
-void dcpu16_trace_cb_set(void (*fn)(char *fmt, ...)) {
-    if (fn)
-        trace_cb_ = fn;
-    else
-        trace_cb_ = printf_null_;
+/* set a new callback */
+dcpu16_msg_cb_t *dcpu16_msg_set(struct dcpu16 *vm, dcpu16_msg_cb_t *msg_cb) {
+    dcpu16_msg_cb_t *r = vm->msg_cb_;
+    vm->msg_cb_ = msg_cb ? msg_cb : msg_null_;
+    return r;
 }
 
-
 /*  acct_event_
  *  invokes callbacks for specified event
  */
@@ -135,7 +136,7 @@ int interrupt_enqueue_(struct dcpu16 *vm, DCPU16_WORD message) {
 
     if (vm->interrupts_tail_ == vm->interrupts_head_) {
         vm->on_fire_ = 1;
-        WARN("interrupt queue overflow (system is now on fire)");
+        MSG_INFO(vm, "interrupt queue overflow (system is now on fire)");
         return -1;
     }
 
@@ -147,7 +148,7 @@ DCPU16_WORD interrupt_dequeue_(struct dcpu16 *vm) {
     DCPU16_WORD message;
 
     if (vm->interrupts_tail_ == vm->interrupts_head_) {
-        WARN("interrupt underflow");
+        MSG_INFO(vm, "interrupt underflow");
         return 0;
     }
 
@@ -165,14 +166,14 @@ void dcpu16_cycle_inc(struct dcpu16 *vm, unsigned int n) {
     while (n--) {
         /* new cycle */
         vm->cycle_ += 1;
-        TRACE("%s>> starting cycle %llu", vm->cycle_);
+        MSG_DEBUG(vm, "%s>> starting cycle %llu", __func__, vm->cycle_);
 
         /* signal interested cycle hooks */
         acct_event_(vm, DCPU16_ACCT_EV_CYCLE, vm->reg[DCPU16_REG_PC]);
 
         /* signal attached hardware */
         for (i = 0; i < vm->hw_table_entries_; i++) {
-            TRACE("%s>> notifying %s", __func__, vm->hw_table_[i].mod->name_);
+            MSG_DEBUG(vm, "%s>> notifying %s", __func__, vm->hw_table_[i].mod->name_);
             if (vm->hw_table_[i].mod->cycle)
                 vm->hw_table_[i].mod->cycle(vm, &vm->hw_table_[i]);
         }
@@ -206,21 +207,28 @@ void value_decode_(struct dcpu16 *vm, DCPU16_WORD value, unsigned int value_is_a
                 sp = (DCPU16_WORD)(vm->reg[DCPU16_REG_SP] + *sp_adjust);
 
     (void)pc;
-    TRACE("%s>> is_a:%u pc:0x%04x sp:0x%04x value_data:0x%04x\n", 
-          __func__,
-          value_is_a,
-          pc,
-          sp,
-          value_data);
+
+#ifdef DEBUG_DECODE
+    MSG_(MSG_DEBUG_DECODE, vm ,"%s>> is_a:%u pc:0x%04x sp:0x%04x value_data:0x%04x\n", 
+                  __func__,
+                  value_is_a,
+                  pc,
+                  sp,
+                  value_data);
+#endif /* DEBUG_DECODE */
 
     if (value <= 0x07) { /* register */
         *e_what = EWHAT_REG;
         *e_reg = value & 0x07;
         *v = vm->reg + *e_reg;
-        TRACE("%s>>     %s (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     %s (0x%04x)",
               __func__,
               dcpu16_reg_names[value],
               **v);
+#endif /* DEBUG_DECODE */
+
         return;
     }
 
@@ -229,11 +237,15 @@ void value_decode_(struct dcpu16 *vm, DCPU16_WORD value, unsigned int value_is_a
         *e_addr = vm->reg[value & 0x07];
         *v = &(vm->ram[ *e_addr ]);
         acct_event_(vm, DCPU16_ACCT_EV_REG_READ, value & 0x07);
-        TRACE("%s>>     [%s] [0x%04x] (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     [%s] [0x%04x] (0x%04x)",
               __func__,
               dcpu16_reg_names[value & 0x07],
               vm->reg[value & 0x07],
               **v);
+#endif /* DEBUG_DECODE */
+
         return;
     }
 
@@ -245,12 +257,16 @@ void value_decode_(struct dcpu16 *vm, DCPU16_WORD value, unsigned int value_is_a
         *e_addr = value_data + vm->reg[value & 0x07];
         acct_event_(vm, DCPU16_ACCT_EV_REG_READ, value & 0x07);
         *v = vm->ram + *e_addr;
-        TRACE("%s>>     [nextword + %s] [0x%04x + 0x%04x] (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     [nextword + %s] [0x%04x + 0x%04x] (0x%04x)",
               __func__,
               dcpu16_reg_names[value & 0x07],
               value_data,
               vm->reg[value & 0x07],
               **v);
+#endif /* DEBUG_DECODE */
+
         return;
     }
 
@@ -263,12 +279,20 @@ void value_decode_(struct dcpu16 *vm, DCPU16_WORD value, unsigned int value_is_a
             *v = &(vm->ram[sp - 1]);
             *sp_adjust -= 1;
             *e_addr = sp - 1;
-            TRACE("%s>>     PUSH [0x%04x] (0x%04x)", __func__, sp - 1, **v);
+
+#ifdef DEBUG_DECODE
+            MSG_(MSG_DEBUG_DECODE, vm, "%s>>     PUSH [0x%04x] (0x%04x)", __func__, sp - 1, **v);
+#endif /* DEBUG_DECODE */
+
         } else { /* a */
             *v = &(vm->ram[sp]);
             *sp_adjust += 1;
             *e_addr = sp;
-            TRACE("%s>>     POP [0x%04x] (0x%04x)", __func__, sp, **v);
+
+#ifdef DEBUG_DECODE
+            MSG_(MSG_DEBUG_DECODE, vm, "%s>>     POP [0x%04x] (0x%04x)", __func__, sp, **v);
+#endif /* DEBUG_DECODE */
+
         }
         break;
 
@@ -277,10 +301,13 @@ void value_decode_(struct dcpu16 *vm, DCPU16_WORD value, unsigned int value_is_a
         *e_what = EWHAT_RAM;
         *v = &(vm->ram[sp]);
         *e_addr = sp;
-        TRACE("%s>>     PEEK [0x%04x] (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     PEEK [0x%04x] (0x%04x)",
               __func__,
               sp,
               **v);
+#endif /* DEBUG_DECODE */
         break;
 
         case 0x1a: /* PICK n */
@@ -290,41 +317,53 @@ void value_decode_(struct dcpu16 *vm, DCPU16_WORD value, unsigned int value_is_a
         *cycle_adjust += 1;
         *e_addr = sp + value_data;
         *v = vm->ram + *e_addr;
-        TRACE("%s>>     PICK 0x%04x [0x%04x] (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     PICK 0x%04x [0x%04x] (0x%04x)",
               __func__,
               value_data,
               sp + value_data,
               **v);
+#endif /* DEBUG_DECODE */
         break;
 
         case 0x1b: /* SP */
         *e_reg = DCPU16_REG_SP;
         *e_what = EWHAT_REG;
         *v = &(vm->reg[DCPU16_REG_SP]);
-        TRACE("%s>>     %s (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     %s (0x%04x)",
               __func__,
               dcpu16_reg_names[DCPU16_REG_SP],
               **v);
+#endif /* DEBUG_DECODE */
         break;
 
         case 0x1c: /* PC */
         *e_reg = DCPU16_REG_PC;
         *e_what = EWHAT_REG;
         *v = &(vm->reg[DCPU16_REG_PC]);
-        TRACE("%s>>     %s (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     %s (0x%04x)",
               __func__,
               dcpu16_reg_names[DCPU16_REG_PC],
               **v);
+#endif /* DEBUG_DECODE */
         break;
 
         case 0x1d: /* EX */
         *e_reg = DCPU16_REG_EX;
         *e_what = EWHAT_REG;
         *v = &(vm->reg[DCPU16_REG_EX]);
-        TRACE("%s>>     %s (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     %s (0x%04x)",
               __func__,
               dcpu16_reg_names[DCPU16_REG_EX],
               **v);
+#endif /* DEBUG_DECODE */
         break;
 
         case 0x1e: /* [next word] / [[pc++]] */
@@ -334,10 +373,13 @@ void value_decode_(struct dcpu16 *vm, DCPU16_WORD value, unsigned int value_is_a
         *cycle_adjust += 1;
         *e_addr = value_data;
         *v = vm->ram + *e_addr;
-        TRACE("%s>>     [nextword] [0x%04x] (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     [nextword] [0x%04x] (0x%04x)",
               __func__,
               value_data,
               **v);
+#endif /* DEBUG_DECODE */
         break;
 
         case 0x1f: /* next word (literal) / [pc++] */
@@ -347,18 +389,24 @@ void value_decode_(struct dcpu16 *vm, DCPU16_WORD value, unsigned int value_is_a
         *cycle_adjust += 1;
         *work_v = value_data;
         *v = work_v;
-        TRACE("%s>>     nextword (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     nextword (0x%04x)",
               __func__,
               **v);
+#endif /* DEBUG_DECODE */
         break;
 
         default: /* 0x20-0x3f: literal values 0xffff-0x1e */
         *e_what = EWHAT_NONE;
         *work_v = (value & 0x1f) - 1;
         *v = work_v;
-        TRACE("%s>>     literal (0x%04x)",
+
+#ifdef DEBUG_DECODE
+        MSG_(MSG_DEBUG_DECODE, vm, "%s>>     literal (0x%04x)",
               __func__,
               **v);
+#endif /* DEBUG_DECODE */
     }
 }
 
@@ -389,7 +437,7 @@ struct opcode_entry {
                       &vm->reg_work_[1], &a, &ev_a_addr, &ev_a_reg, &ev_a_what,\
                       &pc_adjust, &sp_adjust, &cycle_adjust);\
         vm->reg[DCPU16_REG_SP] += sp_adjust;\
-        dcpu16_cycle_inc(vm, cycle_adjust);\
+        if (cycle_adjust) dcpu16_cycle_inc(vm, cycle_adjust);\
     } while (0)
 #define OP_NBI_ (void)val_b, (void)b, (void)ev_b_addr, (void)val_b_data, (void)ev_b_reg, (void)ev_b_what
 #define OP_BASIC_ value_decode_(vm, val_b, 0, val_b_data,\
@@ -435,7 +483,7 @@ OP_IMPL(nbi__reserved_) {
     /* fire an illegal instruction event for current instruction */
     DCPU16_WORD future_opcode = (vm->ram[vm->reg[DCPU16_REG_PC] - pc_adjust] >> (OPCODE_BASIC_BITS + OPCODE_OPERAND_B_BITS));
 
-    WARN("reserved future opcode 0x%04x invoked", future_opcode);
+    MSG_INFO(vm, "reserved future opcode 0x%04x invoked", future_opcode);
 
     ACCT_ILL(vm->reg[DCPU16_REG_PC] - pc_adjust);
 
@@ -465,7 +513,7 @@ OP_IMPL(nbi__reserved2_) {
     OP_NBI(nbi__reserved2_);
     /* reserved */
 
-    WARN("reserved nbi opcode invoked");
+    MSG_INFO(vm, "reserved nbi opcode invoked");
 
     ACCT_ILL(vm->reg[DCPU16_REG_PC] - pc_adjust);
 
@@ -480,7 +528,7 @@ OP_IMPL(nbi_int) {
     ACCT_REG_R(DCPU16_REG_IA);
     if (vm->reg[DCPU16_REG_IA]) {
         if ( interrupt_enqueue_(vm, *a) ) {
-            WARN("failed to queue interrupt");
+            MSG_INFO(vm, "failed to queue interrupt");
             return;
         }
 
@@ -587,7 +635,7 @@ OP_IMPL(nbi_hwq) {
     ACCT_R(a);
 
     if (*a >= vm->hw_table_entries_) {
-        WARN("hardware query for non-extant device 0x%04x", *a);
+        MSG_INFO(vm, "hardware query for non-extant device 0x%04x", *a);
         vm->reg[DCPU16_REG_A] = 0;
         vm->reg[DCPU16_REG_B] = 0;
         vm->reg[DCPU16_REG_C] = 0;
@@ -616,14 +664,14 @@ OP_IMPL(nbi_hwi) {
     ACCT_R(a);
 
     if (*a > vm->hw_table_entries_) {
-        WARN("interrupt for non-extant device 0x%04x", *a);
+        MSG_INFO(vm, "interrupt for non-extant device 0x%04x", *a);
         return;
     }
 
     if (vm->hw_table_[*a].mod->hwi)
         vm->hw_table_[*a].mod->hwi(vm, &vm->hw_table_[*a]);
     else
-        WARN("hardware 0x%04x has no interrupt handler", *a);
+        MSG_INFO(vm, "hardware 0x%04x has no interrupt handler", *a);
 
     dcpu16_cycle_inc(vm, 4);
 }
@@ -634,7 +682,7 @@ OP_IMPL(nbi_hcf) {
     ACCT_R(a);
 
     vm->on_fire_ = 1;
-    WARN("system on fire");
+    MSG_INFO(vm, "system on fire");
 
     dcpu16_cycle_inc(vm, 9);
 }
@@ -685,7 +733,7 @@ OP_IMPL(_nbi_) {
 
     assert(e->impl != NULL);
 
-    TRACE(">> %s 0x%04x", e->name, val_b);
+    MSG_DEBUG(vm, "%s>> %s 0x%04x", __func__, e->name, val_b);
     e->impl(vm, 0, 0, val_a, val_a_data);
 }
 
@@ -702,7 +750,7 @@ OP_IMPL(set) {
     *b = *a;
 
     ACCT_W(b);
-    
+
     dcpu16_cycle_inc(vm, 1);
 }
 
@@ -910,7 +958,7 @@ OP_IMPL(shr) {
     *b = acc & 0xffff;
     vm->reg[DCPU16_REG_EX] = (*b << 16) >> *a;
 
-    WARN("IMPLEMENT");
+    MSG_ERROR(vm, "IMPLEMENT");
 
     ACCT_REG_W(DCPU16_REG_EX);
     ACCT_W(b);
@@ -929,7 +977,7 @@ OP_IMPL(asr) {
     *b = acc & 0xffff;
     vm->reg[DCPU16_REG_EX] = (*b << 16) >> *a;
 
-    WARN("IMPLEMENT");
+    MSG_ERROR(vm, "IMPLEMENT");
 
     ACCT_REG_W(DCPU16_REG_EX);
     ACCT_W(b);
@@ -1179,7 +1227,7 @@ OP_IMPL(std) {
 OP_IMPL(_reserved_) {
     OP_BASIC(_reserved_);
 
-    WARN("reserved opcode invoked");
+    MSG_INFO(vm, "reserved opcode invoked");
 
     ACCT_ILL(vm->reg[DCPU16_REG_PC] - pc_adjust);
 }
@@ -1219,32 +1267,74 @@ static const struct opcode_entry opcode_basic_entries[] = {
     {0x1f, "STD", op_std },
     {0x00, "", NULL }
 };
+#define OPCODE_BASIC_MAX (((sizeof(opcode_basic_entries)) / (sizeof(struct opcode_entry))) - 1)
 
 static inline
 void dump_operand_value_(DCPU16_WORD value, DCPU16_WORD nextword, unsigned int value_position) {
+    printf(" ");
     if (value <= 0x07) {
-        printf(" %s", dcpu16_reg_names[value]);
+        printf("%s", dcpu16_reg_names[value]);
     } else if (value <= 0x0f) {
-        printf(" [%s]", dcpu16_reg_names[value & 0x07]);
+        printf("[%s]", dcpu16_reg_names[value & 0x07]);
     } else if (value <= 0x17) {
-        printf(" [0x%04x + %s]", nextword, dcpu16_reg_names[value & 0x07]);
+        printf("[0x%04x + %s]", nextword, dcpu16_reg_names[value & 0x07]);
     } else switch (value) {
         case 0x18:
             if (value_position == 0) { /* b */
-                printf(" PUSH");
+                printf("PUSH");
+            } else {
+                printf("POP");
+            }
+            break;
+        case 0x19: printf("PEEK"); break;
+        case 0x1a: printf("PICK 0x%04x", nextword); break;
+        case 0x1b: printf("SP"); break;
+        case 0x1c: printf("PC"); break;
+        case 0x1d: printf("EX"); break;
+        case 0x1e: printf("[0x%04x]", nextword); break;
+        case 0x1f: printf("0x%04x", nextword); break;
+        default:   printf("0x%02x", value - 0x21);
+    }
+}
+
+static inline
+int operand_snprint_(char *buf, size_t buf_sz, DCPU16_WORD value, DCPU16_WORD nextword, unsigned int operand_is_a) {
+    int len;
+
+    len = snprintf(buf, buf_sz, " ");
+    if ((size_t)len >= buf_sz)
+        return -1;
+
+    buf += len, buf_sz -= len;
+
+    if (value <= 0x07) {
+        len = snprintf(buf, buf_sz, "%s", dcpu16_reg_names[value]);
+    } else if (value <= 0x0f) {
+        len = snprintf(buf, buf_sz, "[%s]", dcpu16_reg_names[value & 0x07]);
+    } else if (value <= 0x17) {
+        len = snprintf(buf, buf_sz, "[0x%04x + %s]", nextword, dcpu16_reg_names[value & 0x07]);
+    } else switch (value) {
+        case 0x18:
+            if (operand_is_a == 0) { /* b */
+                len = snprintf(buf, buf_sz, "PUSH");
             } else {
-                printf(" POP");
+                len = snprintf(buf, buf_sz, "POP");
             }
             break;
-        case 0x19: printf(" PEEK"); break;
-        case 0x1a: printf(" PICK 0x%04x", nextword); break;
-        case 0x1b: printf(" SP"); break;
-        case 0x1c: printf(" PC"); break;
-        case 0x1d: printf(" EX"); break;
-        case 0x1e: printf(" [0x%04x]", nextword); break;
-        case 0x1f: printf(" 0x%04x", nextword); break;
-        default:   printf(" 0x%02x", value - 0x21);
+        case 0x19: len = snprintf(buf, buf_sz, "PEEK"); break;
+        case 0x1a: len = snprintf(buf, buf_sz, "PICK 0x%04x", nextword); break;
+        case 0x1b: len = snprintf(buf, buf_sz, "SP"); break;
+        case 0x1c: len = snprintf(buf, buf_sz, "PC"); break;
+        case 0x1d: len = snprintf(buf, buf_sz, "EX"); break;
+        case 0x1e: len = snprintf(buf, buf_sz, "[0x%04x]", nextword); break;
+        case 0x1f: len = snprintf(buf, buf_sz, "0x%04x", nextword); break;
+        default:   len = snprintf(buf, buf_sz, "0x%02x", (short)(value - 0x21));
     }
+
+    if ((size_t)len >= buf_sz)
+        return -1;
+
+    return len;
 }
 
 
@@ -1275,7 +1365,8 @@ void instruction_decode_(DCPU16_WORD *mem, DCPU16_WORD addr,
         *a_data = NULL;
     }
 
-    TRACE("\n%s: [0x%04x]:0x%04x op:0x%02x b:0x%02x (b_data:0x%04x) a:0x%02x (a_data:0x%04x) len:0x%02x\n",
+#ifdef DEBUG_DECODE
+    MSG_(MSG_DEBUG_DECODE, NULL, "\n%s: [0x%04x]:0x%04x op:0x%02x b:0x%02x (b_data:0x%04x) a:0x%02x (a_data:0x%04x) len:0x%02x\n",
             __func__, 
             addr,
             mem[addr],
@@ -1285,6 +1376,7 @@ void instruction_decode_(DCPU16_WORD *mem, DCPU16_WORD addr,
             *a,
             *a_data ? **a_data : 0,
             *instr_len);
+#endif /* DEBUG_DECODE */
 }
 
 /*  dcpu16_mnemonify_buf
@@ -1293,6 +1385,7 @@ void instruction_decode_(DCPU16_WORD *mem, DCPU16_WORD addr,
 DCPU16_WORD dcpu16_mnemonify_buf(DCPU16_WORD *buf) {
     DCPU16_WORD opcode, b, a, instr_len, *b_data, *a_data;
     const struct opcode_entry *e;
+    char operand[16];
 
     instruction_decode_(buf, 0, &opcode, &b, &b_data, &a, &a_data, &instr_len);
 
@@ -1304,12 +1397,13 @@ DCPU16_WORD dcpu16_mnemonify_buf(DCPU16_WORD *buf) {
     printf("%s", e->name);
 
     if (opcode) {
-        dump_operand_value_(b, b_data ? *b_data : 0, 0);
-        printf(",");
+        operand_snprint_(operand, sizeof operand, b, b_data ? *b_data : 0, 0);
+        printf("%s,", operand);
     }
 
     if (opcode || b) {
-        dump_operand_value_(a, a_data ? *a_data : 0, 1);
+        operand_snprint_(operand, sizeof operand, a, a_data ? *a_data : 0, 1);
+        printf("%s", operand);
     }
 
     return instr_len;
@@ -1367,7 +1461,7 @@ DCPU16_WORD dcpu16_disassemble_print(struct dcpu16 *vm, DCPU16_WORD addr) {
 }
 
 int dcpu16_interrupt(struct dcpu16 *vm, DCPU16_WORD message) {
-    TRACE("%s>> message:0x%04x", __func__, message);
+    MSG_DEBUG(vm, "%s>> message:0x%04x", __func__, message);
     return interrupt_enqueue_(vm, message);
 }
 
@@ -1386,19 +1480,16 @@ void dcpu16_step(struct dcpu16 *vm) {
     vm->reg[DCPU16_REG_PC] += instr_len;
 
     /* run the operation */
-    for (e = opcode_basic_entries; e->impl; e++) {
-        if (e->value == opcode) {
-            TRACE("%s>> %s 0x%04x, 0x%04x", __func__, e->name, b, a);
-            e->impl(vm, b, b_data ? *b_data : 0, a, a_data ? *a_data : 0);
-            break;
-        }
-    }
+    e = opcode_basic_entries + opcode;
+    MSG_DEBUG(vm, "%s", e->name ? e->name : "???");
+    e->impl(vm, b, b_data ? *b_data : 0, a, a_data ? *a_data : 0);
+
 
     /* and jump over next instr(s) if needed */
     while (vm->skip_) {
         instruction_decode_(vm->ram, vm->reg[DCPU16_REG_PC], &opcode, &b, &b_data, &a, &a_data, &instr_len);
         vm->reg[DCPU16_REG_PC] += instr_len;
-        TRACE("++ SKIPPED %x words", instr_len);
+        MSG_DEBUG(vm, "%s>> ++ SKIPPED %x words", __func__, instr_len);
         if (opcode >= 0x10 && opcode <= 0x17) {
             /* skipping a branch instruction? skip branch's skippable instruction as well */
             dcpu16_cycle_inc(vm, 1);
@@ -1414,11 +1505,12 @@ void dcpu16_step(struct dcpu16 *vm) {
             DCPU16_WORD message;
             message = interrupt_dequeue_(vm);
 
-            TRACE("%s>> %s interrupt IA:0x%04x message:0x%04x",
-                  __func__,
-                  vm->reg[DCPU16_REG_IA] ? "servicing" : "ignoring",
-                  vm->reg[DCPU16_REG_IA],
-                  message);
+            MSG_DEBUG(vm, "%s>> %s interrupt IA:0x%04x message:0x%04x",
+                      __func__,
+                      vm->reg[DCPU16_REG_IA] ? "servicing" : "ignoring",
+                      vm->reg[DCPU16_REG_IA],
+                      message);
+
             if (vm->reg[DCPU16_REG_IA]) {
                 /* then service the next interrupt */
                 vm->interrupts_deferred_ = 1;
@@ -1436,9 +1528,11 @@ void dcpu16_step(struct dcpu16 *vm) {
 struct dcpu16_hw *dcpu16_hw_new(struct dcpu16 *vm, struct dcpu16_hw_module *mod, void *data) {
     struct dcpu16_hw *hw;
 
+    MSG_DEBUG(vm, "%s>> mod:%p data:%p", __func__, mod, data);
+
     hw = malloc(sizeof *hw);
     if (hw == NULL) {
-        vm->warn_cb_("%s():%s", "malloc", strerror(errno));
+        MSG_ERROR(vm, "%s():%s", "malloc", strerror(errno));
         return NULL;
     }
     hw->vm = vm;
@@ -1446,7 +1540,7 @@ struct dcpu16_hw *dcpu16_hw_new(struct dcpu16 *vm, struct dcpu16_hw_module *mod,
 
     if (mod->data_init) {
         if (mod->data_init(hw, data)) {
-            vm->warn_cb_("failed to init hw module data");
+            MSG_ERROR(vm, "failed to init hw module data");
             free(hw);
             return NULL;
         }
@@ -1461,6 +1555,10 @@ struct dcpu16_hw *dcpu16_hw_new(struct dcpu16 *vm, struct dcpu16_hw_module *mod,
 void dcpu16_hw_del(struct dcpu16_hw **hw) {
     if (hw) {
         if (*hw) {
+            MSG_DEBUG((*hw)->vm, "%s>> hw:%p",
+                                 __func__,
+                                 *hw);
+
             if ((*hw)->mod->data_free) {
                 (*hw)->mod->data_free(*hw);
             }
@@ -1474,15 +1572,24 @@ void dcpu16_hw_del(struct dcpu16_hw **hw) {
  *  invokes per-module controls for hw device
  */
 int dcpu16_hw_ctl(struct dcpu16_hw *hw, const char *cmd, void *data_in, void *data_out) {
-    if (hw) {
-        if (hw->mod) {
-            if (hw->mod->ctl) {
-                if (cmd) {
-                    return hw->mod->ctl(hw, cmd, data_in, data_out);
-                }
+    if (!hw)
+        return -1;
+
+    MSG_DEBUG(hw->vm, "%s>> name:%s cmd:%s in:%p out:%p",
+                      __func__,
+                      hw->mod->name_,
+                      cmd,
+                      data_in,
+                      data_out);
+
+    if (hw->mod) {
+        if (hw->mod->ctl) {
+            if (cmd) {
+                return hw->mod->ctl(hw, cmd, data_in, data_out);
             }
         }
     }
+
     return 0;
 }
 
@@ -1494,15 +1601,15 @@ int dcpu16_hw_attach(struct dcpu16 *vm, struct dcpu16_hw *hw) {
     if (!vm || !hw)
         return -1;
 
-    TRACE("%s>> name:%s ID:0x%04x%04x MFG:0x%04x%04x VER:0x%04x",
-          __func__,
-          hw->mod->name_,
-          hw->mod->id_h, hw->mod->id_l,
-          hw->mod->mfg_l, hw->mod->mfg_h,
-          hw->mod->ver);
+    MSG_DEBUG(vm, "%s>> name:%s ID:0x%04x%04x MFG:0x%04x%04x VER:0x%04x",
+                  __func__,
+                  hw->mod->name_,
+                  hw->mod->id_h, hw->mod->id_l,
+                  hw->mod->mfg_l, hw->mod->mfg_h,
+                  hw->mod->ver);
 
     if (vm->hw_table_entries_ == 0xffff) {
-        WARN("maximum hardware entries reached");
+        MSG_ERROR(vm, "maximum hardware entries reached");
         return -1;
     }
 
@@ -1510,7 +1617,7 @@ int dcpu16_hw_attach(struct dcpu16 *vm, struct dcpu16_hw *hw) {
         size_t new_entries = vm->hw_table_allocated_ + 32;
         void *tmp_ptr = realloc(vm->hw_table_, new_entries * sizeof * (vm->hw_table_));
         if (tmp_ptr == NULL) {
-            fprintf(stderr, "%s():%s", "realloc", strerror(errno));
+            MSG_ERROR(vm, "%s():%s", "realloc", strerror(errno));
             return -1;
         }
         vm->hw_table_ = tmp_ptr;
@@ -1520,7 +1627,7 @@ int dcpu16_hw_attach(struct dcpu16 *vm, struct dcpu16_hw *hw) {
     memcpy(vm->hw_table_ + vm->hw_table_entries_, hw, sizeof *hw);
     vm->hw_table_entries_++;
 
-    TRACE("%s>> added hw entry %zu", __func__, vm->hw_table_entries_);
+    MSG_DEBUG(vm, "%s>> added hw entry %zu", __func__, vm->hw_table_entries_);
 
     return 0;
 }
@@ -1551,7 +1658,7 @@ int dcpu16_acct_add(struct dcpu16 *vm, dcpu16_acct_event mask, dcpu16_ev_cb_t *f
         size_t new_entries = vm->cb_table_allocated_ + 32;
         void *tmp_ptr = realloc(vm->cb_table_, new_entries * sizeof *(vm->cb_table_));
         if (tmp_ptr == NULL) {
-            fprintf(stderr, "%s():%s", "realloc", strerror(errno));
+            MSG_ERROR(vm, "%s():%s", "realloc", strerror(errno));
             return -1;
         }
         vm->cb_table_ = tmp_ptr;
@@ -1561,7 +1668,7 @@ int dcpu16_acct_add(struct dcpu16 *vm, dcpu16_acct_event mask, dcpu16_ev_cb_t *f
     memcpy(vm->cb_table_ + vm->cb_table_entries_, &cb, sizeof cb);
     vm->cb_table_entries_++;
 
-    TRACE("%s>> attached event callback %zu", __func__, vm->cb_table_entries_);
+    MSG_DEBUG(vm, "%s>> attached event callback %zu", __func__, vm->cb_table_entries_);
 
     return 0;
 }
@@ -1575,7 +1682,7 @@ void dcpu16_reset(struct dcpu16 *vm) {
     if (!vm)
         return;
 
-    TRACE("%s>> reset", __func__);
+    MSG_DEBUG(vm, "%s>> reset", __func__);
 
     vm->skip_ = 0;
     vm->interrupts_deferred_ = 0;
@@ -1605,10 +1712,9 @@ struct dcpu16 *dcpu16_new(void) {
 
     vm = calloc(1, sizeof *vm);
     if (vm == NULL)
-        WARN("%s: %s(%zu): %s", __func__, "calloc", strerror(errno));
+        MSG_ERROR(NULL, "%s: %s(%zu): %s", __func__, "calloc", strerror(errno));
 
-    vm->warn_cb_ = warn_cb_;
-    vm->trace_cb_ = trace_cb_;
+    vm->msg_cb_ = dcpu16_msg_;
 
     return vm;
 }