From: Justin Wind <justin.wind@gmail.com>
Date: Fri, 25 May 2012 00:32:13 +0000 (-0700)
Subject: consolidated log message callbacks
X-Git-Url: https://git.squeep.com/?a=commitdiff_plain;h=8265806f12a2ae59501cdcf2300b42d4d1c3a120;p=dcpu16

consolidated log message callbacks

replaced warn_cb_ and trace_cb_ with more generic msg_cb_
---

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;
 }
diff --git a/dcpu16.h b/dcpu16.h
index 94e70a3..1f46d45 100644
--- a/dcpu16.h
+++ b/dcpu16.h
@@ -27,10 +27,26 @@ enum dcpu16_register_indexes {
     DCPU16_REG__NUM
 };
 
+/* we call this sort of function for emitting a readable message */
+typedef void (dcpu16_msg_cb_t)(unsigned int, char *, ...);
+
+/* we may emit any of these types of messages */
+enum dcpu16_msg_type {
+    MSG_ERROR = 0,
+    MSG_INFO,
+    MSG_DEBUG
+};
+
+/* update the default message handler */
+dcpu16_msg_cb_t *dcpu16_msg_set_default(dcpu16_msg_cb_t *);
+
+/*
+extern dcpu16_msg_cb_t *dcpu16_msg;
+*/
+
 /* a self-contained dcpu16 core */
 struct dcpu16 {
-    void (*warn_cb_)(char *fmt, ...);
-    void (*trace_cb_)(char *fmt, ...);
+    dcpu16_msg_cb_t *msg_cb_;           /* callback to invoke for messages */
 
     struct dcpu16_acct_cb *cb_table_;   /* list of callbacks to invoke for certain events */
     size_t cb_table_entries_;           /* callback list maintenance */
@@ -109,6 +125,9 @@ struct dcpu16_hw_module {
     struct dcpu16_hw_ctl_cmd *ctl_cmd;
 };
 
+/* update a message handler */
+dcpu16_msg_cb_t *dcpu16_msg_set(struct dcpu16 *, dcpu16_msg_cb_t *);
+
 /* instantiate a new core */
 struct dcpu16 *dcpu16_new(void);
 
@@ -146,8 +165,4 @@ int dcpu16_interrupt(struct dcpu16 *, DCPU16_WORD);
 /* consume a cycle */
 void dcpu16_cycle_inc(struct dcpu16 *, unsigned int);
 
-/* register callbacks to handle warning and debug messages, default is writing to stderr, may be set to null */
-void dcpu16_warn_cb_set(void (*)(char *, ...));
-void dcpu16_trace_cb_set(void (*)(char *, ...));
-
 #endif /* DCPU16_H_3XXIQQG2 */
diff --git a/hw_clock.c b/hw_clock.c
index a6c87b1..ebd58fd 100644
--- a/hw_clock.c
+++ b/hw_clock.c
@@ -39,7 +39,7 @@ void clock_cycle_(struct dcpu16 *vm, struct dcpu16_hw *hw) {
 
         if (clock->interrupt_message) {
             if (dcpu16_interrupt(vm, clock->interrupt_message))
-                vm->warn_cb_("%s: could not send interrupt", hw->mod->name_);
+                vm->msg_cb_(MSG_ERROR, "%s: could not send interrupt", hw->mod->name_);
         }
     }
 }
@@ -71,7 +71,7 @@ int clock_data_init_(struct dcpu16_hw *hw, void *data) {
 
     hw->data = calloc(1, sizeof(struct clock_));
     if (hw->data == NULL) {
-        hw->vm->warn_cb_("%s():%s", "calloc", strerror(errno));
+        hw->vm->msg_cb_(MSG_ERROR, "%s():%s", "calloc", strerror(errno));
         return -1;
     }
     return 0;
diff --git a/hw_keyboard.c b/hw_keyboard.c
index aaf2f2c..f69b8f4 100644
--- a/hw_keyboard.c
+++ b/hw_keyboard.c
@@ -70,7 +70,9 @@ void keyboard_rfbevent_(rfbBool down, rfbKeySym key, rfbClientPtr cl) {
     struct dcpu16_hw *hw = (struct dcpu16_hw *)cl->screen->screenData;
     struct keyboard_ *keyboard = (struct keyboard_ *)hw->data;
 
-    hw->vm->trace_cb_("%s>> down:%u rfb_key:0x%04x", down, key);
+#ifdef DEBUG
+    hw->vm->msg_cb_(MSG_DEBUG, "%s>> down:%u rfb_key:0x%04x", down, key);
+#endif /* DEBUG */
 
     if (keysym_rfbtodcpu(key, &dcpu_key)) {
         /* unhandled key event */
@@ -80,7 +82,7 @@ void keyboard_rfbevent_(rfbBool down, rfbKeySym key, rfbClientPtr cl) {
     keyboard->keys_pressed[dcpu_key] = (down ? 1 : 0);
     if (down) {
         if ((keyboard->buf_tail + 1) % keyboard->buf_sz == keyboard->buf_head) {
-            hw->vm->warn_cb_("keyboard buffer overflow");
+            hw->vm->msg_cb_(MSG_INFO, "keyboard buffer overflow");
             return;
         }
         keyboard->buf[keyboard->buf_tail] = dcpu_key;
@@ -150,13 +152,13 @@ int keyboard_data_init_(struct dcpu16_hw *hw, void *data) {
 
     hw->data = calloc(1, sizeof(struct keyboard_));
     if (hw->data == NULL) {
-        hw->vm->warn_cb_("%s():%s", "calloc", strerror(errno));
+        hw->vm->msg_cb_(MSG_ERROR, "%s():%s", "calloc", strerror(errno));
         return -1;
     }
 
     ((struct keyboard_ *)(hw->data))->buf = malloc(buf_sz * sizeof *((struct keyboard_ *)(hw->data))->buf);
     if (((struct keyboard_ *)(hw->data))->buf == NULL) {
-        hw->vm->warn_cb_("%s():%s", "malloc", strerror(errno));
+        hw->vm->msg_cb_(MSG_ERROR, "%s():%s", "malloc", strerror(errno));
         free(hw->data);
         hw->data = NULL;
         return -1;
@@ -199,11 +201,13 @@ int keyboard_data_ctl_(struct dcpu16_hw *hw, const char *cmd, void *data_in, voi
         }
 
         if (buf_sz_in) {
-            hw->vm->trace_cb_("%s>> resizing buffer from %zu to %zu", __func__, keyboard->buf_sz, *buf_sz_in);
+#ifdef DEBUG
+            hw->vm->msg_cb_(MSG_DEBUG, "%s>> resizing buffer from %zu to %zu", __func__, keyboard->buf_sz, *buf_sz_in);
+#endif /* DEBUG */
 
             tmp_ptr = realloc(keyboard->buf, *buf_sz_in);
             if (tmp_ptr == NULL) {
-                hw->vm->warn_cb_("%s():%s", "realloc", strerror(errno));
+                hw->vm->msg_cb_(MSG_DEBUG, "%s():%s", "realloc", strerror(errno));
                 return -1;
             }
             keyboard->buf = tmp_ptr;
diff --git a/hw_lem1802.c b/hw_lem1802.c
index 0b95d11..1ae7b57 100644
--- a/hw_lem1802.c
+++ b/hw_lem1802.c
@@ -38,7 +38,7 @@
 #define VOIDFP(__x__) (__x__)
 #endif
 
-#define LEM1802_POWER_ON_CYCLES 100000 /* this should vary by, let us say, 10% */
+#define LEM1802_POWER_ON_CYCLES 100000 /* 'about one second' */
 
 #define PIX_X 160       /* pixels in display */
 #define PIX_Y 128       /* pixels in display */
@@ -72,7 +72,7 @@ struct pixel_ {
     unsigned char r;
     unsigned char g;
     unsigned char b;
-    unsigned char a;
+    unsigned char a; /* unused */
 };
 
 struct lem1802_ {
@@ -111,6 +111,7 @@ long long power_on_cycles_(void) {
 
 #if WANT_DELAY_START
     gettimeofday(&tv, NULL);
+    /* consider the 'about' in 'about one second' to be +/- 10% */
     r += LEM1802_POWER_ON_CYCLES - (LEM1802_POWER_ON_CYCLES / 10);
     r += tv.tv_usec % (LEM1802_POWER_ON_CYCLES / 5);
 #endif
@@ -139,7 +140,7 @@ static
 void pixbuf_border_paint_(struct pixel_ *pixbuf, struct pixel_ *border) {
     size_t x, y, i;
 
-    TRACE("%s>> painted border", __func__);
+    TRACE("%s>> painting border", __func__);
 
     /* top */
     for (y = 0; y < PIX_BORDER; y++) {
@@ -353,6 +354,8 @@ int pixbuf_render_vnc_(void *data, struct pixel_ *pixbuf, size_t x, size_t y) {
 
     (void)pixbuf;
 
+    TRACE("%s>> s:%p", __func__, s);
+
     /* derp */
     if (s)
         rfbMarkRectAsModified(s, 0, 0, x, y);
@@ -385,7 +388,7 @@ void lem1802_reset_(struct dcpu16 *vm, struct dcpu16_hw *hw) {
     display->cycle_state_ = 0;
 
 #if DEBUG
-    vm->trace_cb_("%s>>", __func__);
+    vm->msg_cb_(MSG_DEBUG, "%s>>", __func__);
 #endif /* DEBUG */
 }
 
@@ -536,13 +539,13 @@ int lem1802_data_init_(struct dcpu16_hw *hw, void *data) {
 
     hw->data = calloc(1, sizeof(struct lem1802_));
     if (hw->data == NULL) {
-        hw->vm->warn_cb_("%s():%s", "calloc", strerror(errno));
+        hw->vm->msg_cb_(MSG_ERROR, "%s():%s", "calloc", strerror(errno));
         return -1;
     }
 
     ((struct lem1802_ *)(hw->data))->pixbuf = calloc(PIX_X * PIX_Y, sizeof *((struct lem1802_ *)(hw->data))->pixbuf);
     if (((struct lem1802_ *)(hw->data))->pixbuf == NULL) {
-        hw->vm->warn_cb_("%s():%s", "calloc", strerror(errno));
+        hw->vm->msg_cb_(MSG_ERROR, "%s():%s", "calloc", strerror(errno));
         free(hw->data);
         hw->data = NULL;
         return -1;
@@ -672,7 +675,7 @@ int lem1802_data_ctl_(struct dcpu16_hw *hw, const char *cmd, void *data_in, void
             }
         }
 
-        hw->vm->warn_cb_("unknown renderer '%s'", renderer);
+        hw->vm->msg_cb_(MSG_ERROR, "unknown renderer '%s'", renderer);
 
         return -ENOENT;
     }
diff --git a/hw_spc2000.c b/hw_spc2000.c
index 1e20f59..f34b276 100644
--- a/hw_spc2000.c
+++ b/hw_spc2000.c
@@ -16,7 +16,7 @@ int spc2000_data_init_(struct dcpu16_hw *hw, void *data) {
 
     hw->data = calloc(1, sizeof(struct spc2000_));
     if (hw->data == NULL) {
-        hw->vm->warn_cb_("%s():%s", "calloc", strerror(errno));
+        hw->vm->msg_cb_(MSG_ERROR, "%s():%s", "calloc", strerror(errno));
         return -1;
     }
     return 0;
@@ -66,7 +66,7 @@ void spc2000_hwi_(struct dcpu16 *vm, struct dcpu16_hw *hw) {
             ||  vm->reg[DCPU16_REG_C] != 0)
                 break;
             /* trigger */
-            vm->warn_cb_("spc2000 triggered\n");
+            vm->msg_cb_(MSG_INFO, "spc2000 triggered\n");
             break;
 
         case 1: /* SET_UNIT_TO_SKIP */
diff --git a/vm-dcpu16.c b/vm-dcpu16.c
index f7f4c15..cc06b11 100644
--- a/vm-dcpu16.c
+++ b/vm-dcpu16.c
@@ -1,5 +1,6 @@
 #include <stdlib.h>
 #include <stdio.h>
+#include <stdarg.h>
 #include <unistd.h>
 #include <string.h>
 #include <strings.h>
@@ -54,6 +55,11 @@ void sigint_handler_(int sig) {
 }
 
 #define VERBOSE_PRINTF(...) do { if (opt_.verbose) printf(__VA_ARGS__); } while (0)
+#ifdef DEBUG
+#define DEBUG_PRINTF(...) do { if (opt_.verbose > 4) fprintf(stderr, __VA_ARGS__); } while (0)
+#else /* DEBUG */
+#define DEBUG_PRINTF(...) do { } while (0)
+#endif /* DEBUG */
 
 static
 void usage_(char *prog, unsigned int full) {
@@ -205,9 +211,13 @@ struct rfb_instance_ {
     struct dcpu16_hw *attached_keyboard;
 };
 
-/* locate or allocate the next display with an un-occupied framebuffer */
+enum rfbscreen_next_what_ {
+    NEXT_DISPLAY,
+    NEXT_KEYBOARD,
+};
+/* locate next rfb not paired to requested type */
 static
-struct rfb_instance_ *rfbScreen_next_available_display_(struct dynamic_array *rfbScreens, int argc, char *argv[]) {
+struct rfb_instance_ *rfbScreen_next_available_(enum rfbscreen_next_what_ what, struct dynamic_array *rfbScreens, int argc, char *argv[]) {
     size_t i;
     struct rfb_instance_ new_instance, *s;
     struct packed_args_ {
@@ -215,55 +225,38 @@ struct rfb_instance_ *rfbScreen_next_available_display_(struct dynamic_array *rf
         char **argv;
     } parg = { argc, argv };
 
-    fprintf(stderr, "DEBUG: rfbScreens->entries:%zu\n", rfbScreens->entries);
-
     for (i = 0; i < rfbScreens->entries; i++) {
+        struct dcpu16_hw *attached;
+
         s = (struct rfb_instance_ *)DYNARRAY_ITEM(*rfbScreens, i);
-        if (s->attached_display == NULL)
+        switch (what) {
+            case NEXT_DISPLAY:  attached = s->attached_display; break;
+            case NEXT_KEYBOARD: attached = s->attached_keyboard; break;
+        }
+        if (attached == NULL)
             return s;
     }
 
+    /* no available rfb, create new */
     if (dcpu16_hw_module_lem1802.ctl(NULL, "new_rfbScreen", &parg, &new_instance.screen)) {
-        fprintf(stderr, "failed to allocate new rfbScreen");
+        fprintf(stderr, "failed to allocate new rfbScreen\n");
         return NULL;
     }
 
-    new_instance.screen->port += rfbScreens->entries;
-    new_instance.screen->ipv6port += rfbScreens->entries;
-
     new_instance.attached_display = NULL;
     new_instance.attached_keyboard = NULL;
-    s = dynarray_add(rfbScreens, &new_instance);
-    return s;
-}
 
-/* locate or allocate the next display with an un-occupied keyboard */
-static
-struct rfb_instance_ *rfbScreen_next_available_keyboard_(struct dynamic_array *rfbScreens, int argc, char *argv[]) {
-    size_t i;
-    struct rfb_instance_ new_instance, *s;
-    struct packed_args_ {
-        int argc;
-        char **argv;
-    } parg = { argc, argv };
-
-    for (i = 0; i < rfbScreens->entries; i++) {
-        s = (struct rfb_instance_ *)DYNARRAY_ITEM(*rfbScreens, i);
-        if (s->attached_keyboard == NULL)
-            return s;
-    }
+    new_instance.screen->port += rfbScreens->entries;
+    new_instance.screen->ipv6port += rfbScreens->entries;
 
-    if (dcpu16_hw_module_lem1802.ctl(NULL, "new_rfbScreen", &parg, &new_instance.screen)) {
-        fprintf(stderr, "failed to allocate new rfbScreen");
-        return NULL;
-    }
+    DEBUG_PRINTF("%s>> port:%u\n", __func__, new_instance.screen->port);
 
-    new_instance.attached_display = NULL;
-    new_instance.attached_keyboard = NULL;
     s = dynarray_add(rfbScreens, &new_instance);
+
     return s;
 }
 
+
 /* begin serving a screen */
 void rfbScreen_start(rfbScreenInfoPtr s) {
     rfbInitServer(s);
@@ -557,27 +550,25 @@ COMMAND_IMPL(run) {
                     ts_cycle_waste = ts_cycle_rem;
         } else {
             /* negative, we've already blown our time */
-#if 0
-            fprintf(stderr, "cycle time overrun %ld.%09lds\n", ts_cycle_waste.tv_sec, ts_cycle_waste.tv_nsec);
-#endif
+            DEBUG_PRINTF("cycle time overrun %ld.%09lds\n", ts_cycle_waste.tv_sec, ts_cycle_waste.tv_nsec);
         }
 
-#if 0
+#ifdef DEBUG
         /* how did we do */
         gettimespecofday(&ts_cycle_end);
         timespec_subtract(&ts_cycle_rem, &ts_cycle_end_target, &ts_cycle_end);
-        fprintf(stderr, "projected end: %ld.%09ld  actual end: %ld.%09ld  diff: %ld.%09ld\n",
+        DEBUG_PRINTF("projected end: %ld.%09ld  actual end: %ld.%09ld  diff: %ld.%09ld\n",
                 ts_cycle_end_target.tv_sec, ts_cycle_end_target.tv_nsec,
                 ts_cycle_end.tv_sec, ts_cycle_end.tv_nsec,
                 ts_cycle_rem.tv_sec, ts_cycle_rem.tv_nsec);
-#endif
+#endif /* DEBUG */
 
     }
 
     run_cycle_end = vm->cycle_;
     gettimespecofday(&ts_run_end);
     timespec_subtract(&ts_run_diff, &ts_run_end, &ts_run_start);
-    fprintf(stderr, "ran %lld cycles in %ld.%09lds\n",
+    VERBOSE_PRINTF("ran %lld cycles in %ld.%09lds\n",
             run_cycle_end - run_cycle_start,
             ts_run_diff.tv_sec, ts_run_diff.tv_nsec);
 
@@ -633,7 +624,7 @@ COMMAND_IMPL(display) {
         char *argv[] = { "vm-dcpu16", NULL };
         struct rfb_instance_ *s;
 
-        s = rfbScreen_next_available_display_(&rfbScreens_, argc, argv);
+        s = rfbScreen_next_available_(NEXT_DISPLAY, &rfbScreens_, argc, argv);
         if (s == NULL) {
             fprintf(stderr, "failed to initialize vnc\n");
             dcpu16_hw_del(&hw);
@@ -648,6 +639,8 @@ COMMAND_IMPL(display) {
         s->attached_display = hw;
         rfbScreen_start(s->screen);
         renderer_data = s->screen;
+
+        DEBUG_PRINTF("attached display to rfb (frameBuffer:%p)\n", s->screen->frameBuffer);
     }
 #endif /* HAVE_LIBVNCSERVER */
 
@@ -706,7 +699,7 @@ COMMAND_IMPL(keyboard) {
     int argc = 1;
     char *argv[] = { "vm-dcpu16", NULL };
 
-    s = rfbScreen_next_available_keyboard_(&rfbScreens_, argc, argv);
+    s = rfbScreen_next_available_(NEXT_KEYBOARD, &rfbScreens_, argc, argv);
     if (s == NULL) {
         fprintf(stderr, "failed to initialize vnc\n");
         dcpu16_hw_del(&hw);
@@ -784,6 +777,28 @@ COMMAND_HELP(help) {
     fprintf(f, "Displays a list of available commands, or detailed help on a specific command.\n");
 }
 
+static
+void msg_verbose_filter_(unsigned int level, char *fmt, ...) {
+    static const char * const levels[] = { "error", "info", "debug" };
+    FILE *f = (level <= MSG_ERROR) ? stderr : stdout;
+    va_list ap;
+
+    if (level + 2 > opt_.verbose)
+        return;
+
+    if (level < sizeof levels / sizeof *levels)
+        fprintf(f, "[%s %s] ", "dcpu16", levels[level]);
+    else
+        fprintf(f, "[%s %u] ", "dcpu16", level);
+
+    va_start(ap, fmt);
+    vfprintf(f, fmt, ap);
+    va_end(ap);
+
+    fprintf(f, "\n");
+
+    fflush(f);
+}
 
 int main(int argc, char **argv) {
     const char prompt_fmt[] = "PC:%04x> ";
@@ -809,15 +824,11 @@ int main(int argc, char **argv) {
                 exit(EX_USAGE);
         }
     }
-    if (opt_.verbose < 1) {
-        dcpu16_warn_cb_set(NULL);
-        dcpu16_trace_cb_set(NULL);
-    } else if (opt_.verbose < 2) {
-        dcpu16_trace_cb_set(NULL);
-    }
     argc -= optind;
     argv += optind;
 
+    dcpu16_msg_set_default(msg_verbose_filter_);
+
     if ((vm = dcpu16_new()) == NULL) {
         fprintf(stderr, "could not allocate new dcpu16 instance\n");
         exit(EX_UNAVAILABLE);