dmsg - Formalize most of the debugging output, cleanup, fix uninit bug
authorMatthew Dillon <dillon@apollo.backplane.com>
Tue, 10 Mar 2015 00:09:20 +0000 (17:09 -0700)
committerMatthew Dillon <dillon@apollo.backplane.com>
Tue, 10 Mar 2015 00:09:20 +0000 (17:09 -0700)
* Macroize and formalize most of the debugging output.

* Add LNK_PING support.

* Fix a bug in kdmsg_iocom_uninit().  The RX thread can stall reading
  from the pipe and never wakeup to see the KILLRX flag if no traffic
  comes in.

  To deal with this kdmsg_iocom_uninit() sends a LNK_PING over the link,
  then gives the threads 10 seconds to shutdown nicely.  If they do not
  the pipe descriptor is not-so-nicely shutdown().

lib/libdmsg/crypto.c
lib/libdmsg/dmsg.h
lib/libdmsg/msg.c
lib/libdmsg/msg_lnk.c
lib/libdmsg/service.c
lib/libdmsg/subs.c
sbin/hammer2/cmd_debug.c
sbin/hammer2/cmd_service.c
sys/dev/disk/xdisk/xdisk.c
sys/kern/kern_dmsg.c

index e96ef18..da28e4f 100644 (file)
@@ -100,20 +100,19 @@ dmsg_crypto_gcm_init(dmsg_ioq_t *ioq, char *key, int klen,
 
        if (klen < DMSG_CRYPTO_GCM_KEY_SIZE ||
            ivlen < DMSG_CRYPTO_GCM_IV_FIXED_SIZE) {
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "Not enough key or iv material\n");
+               dm_printf(1, "%s\n", "Not enough key or iv material");
                return -1;
        }
 
-       printf("%s key: ", enc ? "Encryption" : "Decryption");
+       dm_printf(6, "%s key: ", enc ? "Encryption" : "Decryption");
        for (i = 0; i < DMSG_CRYPTO_GCM_KEY_SIZE; ++i)
-               printf("%02x", (unsigned char)key[i]);
-       printf("\n");
+               dmx_printf(6, "%02x", (unsigned char)key[i]);
+       dmx_printf(6, "%s\n", "");
 
-       printf("%s iv:  ", enc ? "Encryption" : "Decryption");
+       dm_printf(6, "%s iv:  ", enc ? "Encryption" : "Decryption");
        for (i = 0; i < DMSG_CRYPTO_GCM_IV_FIXED_SIZE; ++i)
-               printf("%02x", (unsigned char)iv_fixed[i]);
-       printf(" (fixed part only)\n");
+               dmx_printf(6, "%02x", (unsigned char)iv_fixed[i]);
+       dmx_printf(6, "%s\n", " (fixed part only)");
 
        EVP_CIPHER_CTX_init(&ioq->ctx);
 
@@ -165,8 +164,7 @@ dmsg_crypto_gcm_init(dmsg_ioq_t *ioq, char *key, int klen,
        return 0;
 
 fail:
-       if (DMsgDebugOpt)
-               fprintf(stderr, "Error during _gcm_init\n");
+       dm_printf(1, "%s\n", "Error during _gcm_init");
        return -1;
 }
 
@@ -239,8 +237,7 @@ dmsg_crypto_gcm_encrypt_chunk(dmsg_ioq_t *ioq, char *ct, char *pt,
 fail:
        ioq->error = DMSG_IOQ_ERROR_ALGO;
 fail_out:
-       if (DMsgDebugOpt)
-               fprintf(stderr, "error during encrypt_chunk\n");
+       dm_printf(1, "%s\n", "error during encrypt_chunk");
        return -1;
 }
 
@@ -290,8 +287,9 @@ dmsg_crypto_gcm_decrypt_chunk(dmsg_ioq_t *ioq, char *ct, char *pt,
 fail:
        ioq->error = DMSG_IOQ_ERROR_MACFAIL;
 fail_out:
-       if (DMsgDebugOpt)
-               fprintf(stderr, "error during decrypt_chunk (likely authentication error)\n");
+       dm_printf(1, "%s\n",
+                 "error during decrypt_chunk "
+                 "(likely authentication error)");
        return -1;
 }
 
@@ -368,25 +366,23 @@ dmsg_crypto_negotiate(dmsg_iocom_t *iocom)
        if (getpeername(iocom->sock_fd, &sa.sa, &salen) < 0) {
                iocom->ioq_rx.error = DMSG_IOQ_ERROR_NOPEER;
                atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "accept: getpeername() failed\n");
+               dm_printf(1, "%s\n", "accept: getpeername() failed");
                goto done;
        }
        if (getnameinfo(&sa.sa, salen, peername, sizeof(peername),
                        NULL, 0, NI_NUMERICHOST) < 0) {
                iocom->ioq_rx.error = DMSG_IOQ_ERROR_NOPEER;
                atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "accept: cannot decode sockaddr\n");
+               dm_printf(1, "%s\n", "accept: cannot decode sockaddr");
                goto done;
        }
        if (DMsgDebugOpt) {
                if (realhostname_sa(realname, sizeof(realname),
                                    &sa.sa, salen) == HOSTNAME_FOUND) {
-                       fprintf(stderr, "accept from %s (%s)\n",
-                               peername, realname);
+                       dm_printf(1, "accept from %s (%s)\n",
+                                 peername, realname);
                } else {
-                       fprintf(stderr, "accept from %s\n", peername);
+                       dm_printf(1, "accept from %s\n", peername);
                }
        }
 
@@ -404,12 +400,10 @@ dmsg_crypto_negotiate(dmsg_iocom_t *iocom)
                if (stat(path, &st) < 0) {
                        iocom->ioq_rx.error = DMSG_IOQ_ERROR_NORKEY;
                        atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-                       if (DMsgDebugOpt)
-                               fprintf(stderr, "auth failure: unknown host\n");
+                       dm_printf(1, "%s\n", "auth failure: unknown host");
                        goto done;
                }
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "auth succeeded, unencrypted link\n");
+               dm_printf(1, "%s\n", "auth succeeded, unencrypted link");
                goto done;
        }
        if (fp) {
@@ -418,9 +412,7 @@ dmsg_crypto_negotiate(dmsg_iocom_t *iocom)
                if (keys[0] == NULL) {
                        iocom->ioq_rx.error = DMSG_IOQ_ERROR_KEYFMT;
                        atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-                       if (DMsgDebugOpt)
-                               fprintf(stderr,
-                                       "auth failure: bad key format\n");
+                       dm_printf(1, "%s\n", "auth failure: bad key format");
                        goto done;
                }
        }
@@ -440,8 +432,7 @@ dmsg_crypto_negotiate(dmsg_iocom_t *iocom)
        if (keys[1] == NULL) {
                iocom->ioq_rx.error = DMSG_IOQ_ERROR_KEYFMT;
                atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "auth failure: bad host key format\n");
+               dm_printf(1, "%s\n", "auth failure: bad host key format");
                goto done;
        }
 
@@ -450,8 +441,7 @@ dmsg_crypto_negotiate(dmsg_iocom_t *iocom)
        if ((fp = fopen(path, "r")) == NULL) {
                iocom->ioq_rx.error = DMSG_IOQ_ERROR_NOLKEY;
                atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "auth failure: bad host key format\n");
+               dm_printf(1, "%s\n", "auth failure: bad host key format");
                goto done;
        }
        keys[2] = PEM_read_RSAPrivateKey(fp, NULL, NULL, NULL);
@@ -459,8 +449,7 @@ dmsg_crypto_negotiate(dmsg_iocom_t *iocom)
        if (keys[2] == NULL) {
                iocom->ioq_rx.error = DMSG_IOQ_ERROR_KEYFMT;
                atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "auth failure: bad host key format\n");
+               dm_printf(1, "%s\n", "auth failure: bad host key format");
                goto done;
        }
        free(path);
@@ -476,9 +465,8 @@ dmsg_crypto_negotiate(dmsg_iocom_t *iocom)
                    sizeof(handtx) % blksize != 0) {
                        iocom->ioq_rx.error = DMSG_IOQ_ERROR_KEYFMT;
                        atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-                       if (DMsgDebugOpt)
-                               fprintf(stderr, "auth failure: "
-                                               "key size mismatch\n");
+                       dm_printf(1, "%s\n",
+                                 "auth failure: key size mismatch");
                        goto done;
                }
        } else {
@@ -503,8 +491,7 @@ urandfail:
                        close(fd);
                iocom->ioq_rx.error = DMSG_IOQ_ERROR_BADURANDOM;
                atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "auth failure: bad rng\n");
+               dm_printf(1, "%s\n", "auth failure: bad rng");
                goto done;
        }
        if (bcmp(&handrx, &handtx, sizeof(handtx)) == 0)
@@ -566,14 +553,14 @@ urandfail:
                        }
                }
                if (write(iocom->sock_fd, buf2, blksize) != (ssize_t)blksize) {
-                       fprintf(stderr, "WRITE ERROR\n");
+                       dmio_printf(iocom, 1, "%s\n", "WRITE ERROR");
                }
        }
        if (iocom->ioq_rx.error) {
                atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "auth failure: key exchange failure "
-                                       "during encryption\n");
+               dmio_printf(iocom, 1, "%s\n",
+                           "auth failure: key exchange failure "
+                           "during encryption");
                goto done;
        }
 
@@ -601,9 +588,9 @@ urandfail:
        }
        if (iocom->ioq_rx.error) {
                atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "auth failure: key exchange failure "
-                                       "during decryption\n");
+               dmio_printf(iocom, 1, "%s\n",
+                           "auth failure: key exchange failure "
+                           "during decryption");
                goto done;
        }
 
@@ -615,8 +602,8 @@ urandfail:
 keyxchgfail:
                iocom->ioq_rx.error = DMSG_IOQ_ERROR_KEYXCHGFAIL;
                atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-               if (DMsgDebugOpt)
-                       fprintf(stderr, "auth failure: key exchange failure\n");
+               dmio_printf(iocom, 1, "%s\n",
+                           "auth failure: key exchange failure");
                goto done;
        }
 
@@ -656,8 +643,7 @@ keyxchgfail:
 
        atomic_set_int(&iocom->flags, DMSG_IOCOMF_CRYPTED);
 
-       if (DMsgDebugOpt)
-               fprintf(stderr, "auth success: %s\n", handrx.quickmsg);
+       dmio_printf(iocom, 1, "auth success: %s\n", handrx.quickmsg);
 done:
        if (path)
                free(path);
@@ -700,15 +686,20 @@ dmsg_crypto_decrypt(dmsg_iocom_t *iocom __unused, dmsg_ioq_t *ioq)
                    DMSG_CRYPTO_CHUNK_SIZE,
                    &used);
 #ifdef CRYPTO_DEBUG
-               printf("dec: p_len: %d, used: %d, fifo_cdn: %ju, fifo_cdx: %ju\n",
-                      p_len, used, ioq->fifo_cdn, ioq->fifo_cdx);
+               dmio_printf(iocom, 5,
+                           "dec: p_len: %d, used: %d, "
+                           "fifo_cdn: %ju, fifo_cdx: %ju\n",
+                            p_len, used,
+                            ioq->fifo_cdn, ioq->fifo_cdx);
 #endif
                p_len -= used;
                ioq->fifo_cdn += used;
                ioq->fifo_cdx += DMSG_CRYPTO_CHUNK_SIZE;
 #ifdef CRYPTO_DEBUG
-               printf("dec: p_len: %d, used: %d, fifo_cdn: %ju, fifo_cdx: %ju\n",
-                      p_len, used, ioq->fifo_cdn, ioq->fifo_cdx);
+               dmio_printf(iocom, 5,
+                           "dec: p_len: %d, used: %d, "
+                           "fifo_cdn: %ju, fifo_cdx: %ju\n",
+                           p_len, used, ioq->fifo_cdn, ioq->fifo_cdx);
 #endif
        }
 }
@@ -743,8 +734,10 @@ dmsg_crypto_encrypt(dmsg_iocom_t *iocom __unused, dmsg_ioq_t *ioq,
                            (char *)iov[i].iov_base + used,
                            DMSG_CRYPTO_CHUNK_SIZE, &ct_used);
 #ifdef CRYPTO_DEBUG
-                       printf("nactp: %ju, p_len: %d, ct_used: %d, used: %d, nmax: %ju\n",
-                              *nactp, p_len, ct_used, used, nmax);
+                       dmio_printf(iocom, 5,
+                                   "nactp: %ju, p_len: %d, "
+                                   "ct_used: %d, used: %d, nmax: %ju\n",
+                                   *nactp, p_len, ct_used, used, nmax);
 #endif
 
                        *nactp += (size_t)DMSG_CRYPTO_CHUNK_SIZE;       /* plaintext count */
@@ -761,8 +754,10 @@ dmsg_crypto_encrypt(dmsg_iocom_t *iocom __unused, dmsg_ioq_t *ioq,
                        ioq->fifo_end += (size_t)ct_used;
                        nmax -= (size_t)ct_used;
 #ifdef CRYPTO_DEBUG
-                       printf("nactp: %ju, p_len: %d, ct_used: %d, used: %d, nmax: %ju\n",
-                              *nactp, p_len, ct_used, used, nmax);
+                       dmio_printf(iocom, 5,
+                                   "nactp: %ju, p_len: %d, "
+                                   "ct_used: %d, used: %d, nmax: %ju\n",
+                                   *nactp, p_len, ct_used, used, nmax);
 #endif
                }
        }
index c1b4316..38c4528 100644 (file)
 
 #define DMSG_LISTEN_PORT       987
 
+#define dm_printf(level, ctl, ...)             \
+       if (DMsgDebugOpt >= (level))            \
+               fprintf(stderr, "libdmsg: " ctl, __VA_ARGS__)
+#define dmx_printf(level, ctl, ...)            \
+       if (DMsgDebugOpt >= (level))            \
+               fprintf(stderr, ctl, __VA_ARGS__)
+#define dmio_printf(iocom, level, ctl, ...)    \
+       if (DMsgDebugOpt >= (level))            \
+               fprintf(stderr, "libdmsg: " ctl, __VA_ARGS__)
+
+
 /***************************************************************************
  *                             CRYPTO HANDSHAKE                           *
  ***************************************************************************
index c46d392..b15dfc9 100644 (file)
@@ -435,9 +435,8 @@ dmsg_iocom_core(dmsg_iocom_t *iocom)
                 * context of the current thread.  However, modifications
                 * still require atomic ops.
                 */
-#if 0
-               fprintf(stderr, "iocom %p %08x\n", iocom, iocom->flags);
-#endif
+               dmio_printf(iocom, 5, "iocom %p %08x\n",
+                           iocom, iocom->flags);
                if ((iocom->flags & (DMSG_IOCOMF_RWORK |
                                     DMSG_IOCOMF_WWORK |
                                     DMSG_IOCOMF_PWORK |
@@ -546,10 +545,8 @@ dmsg_iocom_core(dmsg_iocom_t *iocom)
                if (iocom->flags & DMSG_IOCOMF_RWORK) {
                        while ((iocom->flags & DMSG_IOCOMF_EOF) == 0 &&
                               (msg = dmsg_ioq_read(iocom)) != NULL) {
-                               if (DMsgDebugOpt) {
-                                       fprintf(stderr, "receive %s\n",
-                                               dmsg_msg_str(msg));
-                               }
+                               dmio_printf(iocom, 4, "receive %s\n",
+                                           dmsg_msg_str(msg));
                                iocom->rcvmsg_callback(msg);
                                pthread_mutex_lock(&iocom->mtx);
                                dmsg_state_cleanuprx(iocom, msg);
@@ -636,7 +633,9 @@ again:
 
                if (msg->state == &iocom->state0) {
                        atomic_set_int(&iocom->flags, DMSG_IOCOMF_EOF);
-                       fprintf(stderr, "EOF ON SOCKET %d\n", iocom->sock_fd);
+                       dmio_printf(iocom, 1,
+                                   "EOF ON SOCKET %d\n",
+                                   iocom->sock_fd);
                }
                return (msg);
        }
@@ -721,10 +720,12 @@ again:
                head = (void *)(ioq->buf + ioq->fifo_beg);
                if (head->magic != DMSG_HDR_MAGIC &&
                    head->magic != DMSG_HDR_MAGIC_REV) {
-                       fprintf(stderr, "%s: head->magic is bad %02x\n",
-                               iocom->label, head->magic);
+                       dmio_printf(iocom, 1,
+                                   "%s: head->magic is bad %02x\n",
+                                   iocom->label, head->magic);
                        if (iocom->flags & DMSG_IOCOMF_CRYPTED)
-                               fprintf(stderr, "(on encrypted link)\n");
+                               dmio_printf(iocom, 1, "%s\n",
+                                           "(on encrypted link)");
                        ioq->error = DMSG_IOQ_ERROR_SYNC;
                        break;
                }
@@ -839,9 +840,9 @@ again:
                head->hdr_crc = 0;
                if (dmsg_icrc32(head, ioq->hbytes) != xcrc32) {
                        ioq->error = DMSG_IOQ_ERROR_XCRC;
-                       fprintf(stderr, "BAD-XCRC(%08x,%08x) %s\n",
-                               xcrc32, dmsg_icrc32(head, ioq->hbytes),
-                               dmsg_msg_str(msg));
+                       dmio_printf(iocom, 1, "BAD-XCRC(%08x,%08x) %s\n",
+                                   xcrc32, dmsg_icrc32(head, ioq->hbytes),
+                                   dmsg_msg_str(msg));
                        assert(0);
                        break;
                }
@@ -984,14 +985,14 @@ again:
                xcrc32 = dmsg_icrc32(msg->aux_data, ioq->abytes);
                if (xcrc32 != msg->any.head.aux_crc) {
                        ioq->error = DMSG_IOQ_ERROR_ACRC;
-                       fprintf(stderr,
-                               "iocom: ACRC error %08x vs %08x "
-                               "msgid %016jx msgcmd %08x auxsize %d\n",
-                               xcrc32,
-                               msg->any.head.aux_crc,
-                               (intmax_t)msg->any.head.msgid,
-                               msg->any.head.cmd,
-                               msg->any.head.aux_bytes);
+                       dmio_printf(iocom, 1,
+                                   "iocom: ACRC error %08x vs %08x "
+                                   "msgid %016jx msgcmd %08x auxsize %d\n",
+                                   xcrc32,
+                                   msg->any.head.aux_crc,
+                                   (intmax_t)msg->any.head.msgid,
+                                   msg->any.head.cmd,
+                                   msg->any.head.aux_bytes);
                        break;
                }
                break;
@@ -1041,7 +1042,7 @@ skip:
                 * message, which should cause master processing loops to
                 * terminate.
                 */
-               fprintf(stderr, "IOQ ERROR %d\n", ioq->error);
+               dmio_printf(iocom, 1, "IOQ ERROR %d\n", ioq->error);
                assert(ioq->msg == msg);
                if (msg) {
                        dmsg_msg_free(msg);
@@ -1129,12 +1130,10 @@ skip:
                 *
                 * State processing only occurs for messages destined for us.
                 */
-               if (DMsgDebugOpt >= 5) {
-                       fprintf(stderr,
-                               "rxmsg cmd=%08x circ=%016jx\n",
-                               msg->any.head.cmd,
-                               (intmax_t)msg->any.head.circuit);
-               }
+               dmio_printf(iocom, 5,
+                           "rxmsg cmd=%08x circ=%016jx\n",
+                           msg->any.head.cmd,
+                           (intmax_t)msg->any.head.circuit);
 
                error = dmsg_state_msgrx(msg, 0);
 
@@ -1434,12 +1433,10 @@ dmsg_iocom_flush2(dmsg_iocom_t *iocom)
                nact -= abytes - ioq->abytes;
                /* ioq->abytes = abytes; optimized out */
 
-#if 0
-               fprintf(stderr,
-                       "txmsg cmd=%08x circ=%016jx\n",
-                       msg->any.head.cmd,
-                       (intmax_t)msg->any.head.circuit);
-#endif
+               dmio_printf(iocom, 5,
+                           "txmsg cmd=%08x circ=%016jx\n",
+                           msg->any.head.cmd,
+                           (intmax_t)msg->any.head.circuit);
 
 #ifdef DMSG_BLOCK_DEBUG
                uint32_t tcmd;
@@ -1460,17 +1457,19 @@ dmsg_iocom_flush2(dmsg_iocom_t *iocom)
                switch (tcmd) {
                case DMSG_BLK_READ | DMSGF_CREATE | DMSGF_DELETE:
                case DMSG_BLK_WRITE | DMSGF_CREATE | DMSGF_DELETE:
-                       fprintf(stderr, "write BIO %-3d %016jx %d@%016jx\n",
-                               biocount, msg->any.head.msgid,
-                               msg->any.blk_read.bytes,
-                               msg->any.blk_read.offset);
+                       dmio_printf(iocom, 4,
+                                   "write BIO %-3d %016jx %d@%016jx\n",
+                                   biocount, msg->any.head.msgid,
+                                   msg->any.blk_read.bytes,
+                                   msg->any.blk_read.offset);
                        break;
                case DMSG_BLK_READ | DMSGF_CREATE | DMSGF_DELETE | DMSGF_REPLY:
                case DMSG_BLK_WRITE | DMSGF_CREATE | DMSGF_DELETE | DMSGF_REPLY:
-                       fprintf(stderr, "wretr BIO %-3d %016jx %d@%016jx\n",
-                               biocount, msg->any.head.msgid,
-                               msg->any.blk_read.bytes,
-                               msg->any.blk_read.offset);
+                       dmio_printf(iocom, 4,
+                                   "wretr BIO %-3d %016jx %d@%016jx\n",
+                                   biocount, msg->any.head.msgid,
+                                   msg->any.blk_read.bytes,
+                                   msg->any.blk_read.offset);
                        break;
                default:
                        break;
@@ -1559,14 +1558,12 @@ dmsg_msg_write(dmsg_msg_t *msg)
        pthread_mutex_lock(&iocom->mtx);
        state = msg->state;
 
-       if (DMsgDebugOpt) {
-               fprintf(stderr,
-                       "msgtx: cmd=%08x msgid=%016jx "
-                       "state %p(%08x) error=%d\n",
-                       msg->any.head.cmd, msg->any.head.msgid,
-                       state, (state ? state->icmd : 0),
-                       msg->any.head.error);
-       }
+       dmio_printf(iocom, 5,
+                   "msgtx: cmd=%08x msgid=%016jx "
+                   "state %p(%08x) error=%d\n",
+                   msg->any.head.cmd, msg->any.head.msgid,
+                   state, (state ? state->icmd : 0),
+                   msg->any.head.error);
 
 
 #if 0
@@ -1577,7 +1574,7 @@ dmsg_msg_write(dmsg_msg_t *msg)
         */
        if ((state->parent->txcmd & DMSGF_DELETE) ||
            (state->parent->rxcmd & DMSGF_DELETE)) {
-               fprintf(stderr, "dmsg_msg_write: EARLY TERMINATION\n");
+               dmio_printf(iocom, 4, "dmsg_msg_write: EARLY TERMINATION\n");
                dmsg_simulate_failure(state, DMSG_ERR_LOSTLINK);
                dmsg_state_cleanuptx(iocom, msg);
                dmsg_msg_free(msg);
@@ -1618,9 +1615,10 @@ dmsg_msg_write(dmsg_msg_t *msg)
         * Discard messages sent to transactions which are already dead.
         */
        if (state && (state->txcmd & DMSGF_DELETE)) {
-               printf("dmsg_msg_write: drop msg %08x to dead "
-                      "circuit state=%p\n",
-                      msg->any.head.cmd, state);
+               dmio_printf(iocom, 4,
+                           "dmsg_msg_write: drop msg %08x to dead "
+                           "circuit state=%p\n",
+                           msg->any.head.cmd, state);
                dmsg_msg_free(msg);
                return;
        }
@@ -1644,11 +1642,12 @@ dmsg_msg_write(dmsg_msg_t *msg)
                 * Illegal message, kill state and related sub-state.
                 * Cannot transmit if state is already dying.
                 */
-               printf("dmsg_msg_write: Write to dying circuit "
-                       "ptxcmd=%08x prxcmd=%08x flags=%08x\n",
-                       state->parent->rxcmd,
-                       state->parent->txcmd,
-                       state->parent->flags);
+               dmio_printf(iocom, 4,
+                           "dmsg_msg_write: Write to dying circuit "
+                           "ptxcmd=%08x prxcmd=%08x flags=%08x\n",
+                           state->parent->rxcmd,
+                           state->parent->txcmd,
+                           state->parent->flags);
                dmsg_state_hold(state);
                dmsg_state_cleanuptx(iocom, msg);
                if ((state->flags & DMSG_STATE_ABORTING) == 0) {
@@ -1661,8 +1660,9 @@ dmsg_msg_write(dmsg_msg_t *msg)
                 * Queue the message, clean up transmit state prior to queueing
                 * to avoid SMP races.
                 */
-               if (DMsgDebugOpt)
-               printf("dmsg_msg_write: commit msg state=%p to txkmsgq\n", state);
+               dmio_printf(iocom, 5,
+                           "dmsg_msg_write: commit msg state=%p to txkmsgq\n",
+                           state);
                dmsg_state_cleanuptx(iocom, msg);
                TAILQ_INSERT_TAIL(&iocom->txmsgq, msg, qentry);
                dummy = 0;
@@ -1752,9 +1752,11 @@ dmsg_state_abort(dmsg_state_t *state)
        state->flags |= DMSG_STATE_ABORTING;
        dmsg_state_dying(state);
        if (state->flags & DMSG_STATE_NEW) {
-               printf("dmsg_state_abort(0): state %p rxcmd %08x txcmd %08x "
-                      "flags %08x - in NEW state\n",
-                      state, state->rxcmd, state->txcmd, state->flags);
+               dmio_printf(iocom, 4,
+                           "dmsg_state_abort(0): state %p rxcmd %08x "
+                           "txcmd %08x flags %08x - in NEW state\n",
+                           state, state->rxcmd,
+                           state->txcmd, state->flags);
                return;
        }
 
@@ -1766,7 +1768,9 @@ dmsg_state_abort(dmsg_state_t *state)
         * until the children are all gone.
         */
        if ((state->rxcmd & DMSGF_DELETE) == 0) {
-               fprintf(stderr, "SIMULATE ERROR\n");
+               dmio_printf(iocom, 5,
+                           "dmsg_state_abort() on state %p\n",
+                           state);
                msg = dmsg_msg_alloc_locked(state, 0, DMSG_LNK_ERROR,
                                            NULL, NULL);
                if ((state->rxcmd & DMSGF_CREATE) == 0)
@@ -2084,13 +2088,13 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
        pthread_mutex_lock(&iocom->mtx);
 
        if (DMsgDebugOpt) {
-               fprintf(stderr,
-                       "msgrx: cmd=%08x msgid=%016jx "
-                       "circuit=%016jx error=%d\n",
-                       msg->any.head.cmd,
-                       msg->any.head.msgid,
-                       msg->any.head.circuit,
-                       msg->any.head.error);
+               dmio_printf(iocom, 5,
+                           "msgrx: cmd=%08x msgid=%016jx "
+                           "circuit=%016jx error=%d\n",
+                           msg->any.head.cmd,
+                           msg->any.head.msgid,
+                           msg->any.head.circuit,
+                           msg->any.head.error);
        }
 
        /*
@@ -2127,9 +2131,9 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
                 * direction.
                 */
                if (pstate == NULL) {
-                       fprintf(stderr,
-                               "missing parent in stacked trans %s\n",
-                               dmsg_msg_str(msg));
+                       dmio_printf(iocom, 4,
+                                   "missing parent in stacked trans %s\n",
+                                   dmsg_msg_str(msg));
                        pthread_mutex_unlock(&iocom->mtx);
                        error = DMSG_IOQ_ERROR_EALREADY;
 
@@ -2165,15 +2169,14 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
        }
 
        if (DMsgDebugOpt) {
-               fprintf(stderr,
-                       "msgrx:\tstate %p(%08x)",
-                       state, (state ? state->icmd : 0));
+               dmio_printf(iocom, 5, "msgrx:\tstate %p(%08x)",
+                           state, (state ? state->icmd : 0));
                if (pstate != &iocom->state0) {
-                       fprintf(stderr,
-                               " pstate %p(%08x)",
-                               pstate, pstate->icmd);
+                       dmio_printf(iocom, 5,
+                                   " pstate %p(%08x)",
+                                   pstate, pstate->icmd);
                }
-               fprintf(stderr, "\n");
+               dmio_printf(iocom, 5, "%s\n", "");
        }
 
        if (mstate) {
@@ -2213,9 +2216,9 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
                 * iocom-based instead of state-based).
                 */
                if (state != pstate) {
-                       fprintf(stderr,
-                               "duplicate transaction %s\n",
-                               dmsg_msg_str(msg));
+                       dmio_printf(iocom, 2,
+                                   "duplicate transaction %s\n",
+                                   dmsg_msg_str(msg));
                        error = DMSG_IOQ_ERROR_TRANS;
                        assert(0);
                        break;
@@ -2273,8 +2276,9 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
                        if (msg->any.head.cmd & DMSGF_ABORT) {
                                error = DMSG_IOQ_ERROR_EALREADY;
                        } else {
-                               fprintf(stderr, "missing-state %s\n",
-                                       dmsg_msg_str(msg));
+                               dmio_printf(iocom, 2,
+                                           "missing-state %s\n",
+                                           dmsg_msg_str(msg));
                                error = DMSG_IOQ_ERROR_TRANS;
                                assert(0);
                        }
@@ -2289,8 +2293,9 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
                        if (msg->any.head.cmd & DMSGF_ABORT) {
                                error = DMSG_IOQ_ERROR_EALREADY;
                        } else {
-                               fprintf(stderr, "reused-state %s\n",
-                                       dmsg_msg_str(msg));
+                               dmio_printf(iocom, 2,
+                                           "reused-state %s\n",
+                                           dmsg_msg_str(msg));
                                error = DMSG_IOQ_ERROR_TRANS;
                                assert(0);
                        }
@@ -2319,8 +2324,8 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
                 * persistent state message should already exist.
                 */
                if (state == pstate) {
-                       fprintf(stderr, "no-state(r) %s\n",
-                               dmsg_msg_str(msg));
+                       dmio_printf(iocom, 2, "no-state(r) %s\n",
+                                   dmsg_msg_str(msg));
                        error = DMSG_IOQ_ERROR_TRANS;
                        assert(0);
                        break;
@@ -2338,8 +2343,9 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
                        if (msg->any.head.cmd & DMSGF_ABORT) {
                                error = DMSG_IOQ_ERROR_EALREADY;
                        } else {
-                               fprintf(stderr, "no-state(r,d) %s\n",
-                                       dmsg_msg_str(msg));
+                               dmio_printf(iocom, 2,
+                                           "no-state(r,d) %s\n",
+                                           dmsg_msg_str(msg));
                                error = DMSG_IOQ_ERROR_TRANS;
                                assert(0);
                        }
@@ -2355,8 +2361,9 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
                        if (msg->any.head.cmd & DMSGF_ABORT) {
                                error = DMSG_IOQ_ERROR_EALREADY;
                        } else {
-                               fprintf(stderr, "reused-state(r,d) %s\n",
-                                       dmsg_msg_str(msg));
+                               dmio_printf(iocom, 2,
+                                           "reused-state(r,d) %s\n",
+                                           dmsg_msg_str(msg));
                                error = DMSG_IOQ_ERROR_TRANS;
                                assert(0);
                        }
@@ -2406,17 +2413,19 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
        switch (msg->tcmd) {
        case DMSG_BLK_READ | DMSGF_CREATE | DMSGF_DELETE:
        case DMSG_BLK_WRITE | DMSGF_CREATE | DMSGF_DELETE:
-               fprintf(stderr, "read  BIO %-3d %016jx %d@%016jx\n",
-                       biocount, msg->any.head.msgid,
-                       msg->any.blk_read.bytes,
-                       msg->any.blk_read.offset);
+               dmio_printf(iocom, 4,
+                           "read  BIO %-3d %016jx %d@%016jx\n",
+                           biocount, msg->any.head.msgid,
+                           msg->any.blk_read.bytes,
+                           msg->any.blk_read.offset);
                break;
        case DMSG_BLK_READ | DMSGF_CREATE | DMSGF_DELETE | DMSGF_REPLY:
        case DMSG_BLK_WRITE | DMSGF_CREATE | DMSGF_DELETE | DMSGF_REPLY:
-               fprintf(stderr, "rread BIO %-3d %016jx %d@%016jx\n",
-                       biocount, msg->any.head.msgid,
-                       msg->any.blk_read.bytes,
-                       msg->any.blk_read.offset);
+               dmio_printf(iocom, 4,
+                           "rread BIO %-3d %016jx %d@%016jx\n",
+                           biocount, msg->any.head.msgid,
+                           msg->any.blk_read.bytes,
+                           msg->any.blk_read.offset);
                break;
        default:
                break;
@@ -2463,7 +2472,7 @@ dmsg_state_msgrx(dmsg_msg_t *msg, int mstate)
        pthread_mutex_unlock(&iocom->mtx);
 
        if (DMsgDebugOpt && error)
-               fprintf(stderr, "msgrx: error %d\n", error);
+               dmio_printf(iocom, 1, "msgrx: error %d\n", error);
 
        return (error);
 }
@@ -2483,25 +2492,29 @@ dmsg_state_relay(dmsg_msg_t *lmsg)
 #ifdef DMSG_BLOCK_DEBUG
        switch (lmsg->tcmd) {
        case DMSG_BLK_OPEN | DMSGF_CREATE:
-               fprintf(stderr, "relay BIO_OPEN (CREATE)\n");
+               dmio_printf(iocom, 4, "%s\n",
+                           "relay BIO_OPEN (CREATE)");
                break;
        case DMSG_BLK_OPEN | DMSGF_DELETE:
-               fprintf(stderr, "relay BIO_OPEN (DELETE)\n");
+               dmio_printf(iocom, 4, "%s\n",
+                           "relay BIO_OPEN (DELETE)");
                break;
        case DMSG_BLK_READ | DMSGF_CREATE | DMSGF_DELETE:
        case DMSG_BLK_WRITE | DMSGF_CREATE | DMSGF_DELETE:
                atomic_add_int(&biocount, 1);
-               fprintf(stderr, "relay BIO %-3d %016jx %d@%016jx\n",
-                       biocount, lmsg->any.head.msgid,
-                       lmsg->any.blk_read.bytes,
-                       lmsg->any.blk_read.offset);
+               dmio_printf(iocom, 4,
+                           "relay BIO %-3d %016jx %d@%016jx\n",
+                           biocount, lmsg->any.head.msgid,
+                           lmsg->any.blk_read.bytes,
+                           lmsg->any.blk_read.offset);
                break;
        case DMSG_BLK_READ | DMSGF_CREATE | DMSGF_DELETE | DMSGF_REPLY:
        case DMSG_BLK_WRITE | DMSGF_CREATE | DMSGF_DELETE | DMSGF_REPLY:
-               fprintf(stderr, "retrn BIO %-3d %016jx %d@%016jx\n",
-                       biocount, lmsg->any.head.msgid,
-                       lmsg->any.blk_read.bytes,
-                       lmsg->any.blk_read.offset);
+               dmio_printf(iocom, 4,
+                           "retrn BIO %-3d %016jx %d@%016jx\n",
+                           biocount, lmsg->any.head.msgid,
+                           lmsg->any.blk_read.bytes,
+                           lmsg->any.blk_read.offset);
                atomic_add_int(&biocount, -1);
                break;
        default:
@@ -2540,9 +2553,9 @@ dmsg_state_relay(dmsg_msg_t *lmsg)
 
 #if 0
                if (lstate->flags & DMSG_STATE_ABORTING) {
-                       fprintf(stderr,
-                               "relay: relay lost link l=%p r=%p\n",
-                               lstate, rstate);
+                       dmio_printf(iocom, 4,
+                                   "relay: relay lost link l=%p r=%p\n",
+                                   lstate, rstate);
                        dmsg_simulate_failure(rstate, 0, DMSG_ERR_LOSTLINK);
                }
 #endif
@@ -2562,9 +2575,6 @@ dmsg_state_relay(dmsg_msg_t *lmsg)
        rmsg->aux_data = lmsg->aux_data;
        lmsg->aux_data = NULL;
 
-       /*
-       fprintf(stderr, "RELAY %08x\n", rmsg->any.head.cmd);
-       */
        dmsg_msg_write(rmsg);
 }
 
@@ -2676,9 +2686,10 @@ dmsg_state_cleanuptx(dmsg_iocom_t *iocom, dmsg_msg_t *msg)
         */
        if ((state->flags & (DMSG_STATE_ABORTING | DMSG_STATE_DYING)) &&
            (state->rxcmd & DMSGF_DELETE) == 0) {
-               printf("kdmsg_state_cleanuptx: state=%p "
-                       "executing deferred abort\n",
-                       state);
+               dmio_printf(iocom, 4,
+                           "cleanuptx: state=%p "
+                           "executing deferred abort\n",
+                           state);
                state->flags &= ~DMSG_STATE_ABORTING;
                dmsg_simulate_failure(state, 1, DMSG_ERR_LOSTLINK);
        }
@@ -2710,9 +2721,7 @@ static void
 dmsg_state_free(dmsg_state_t *state)
 {
        atomic_add_int(&dmsg_state_count, -1);
-       if (DMsgDebugOpt) {
-               fprintf(stderr, "terminate state %p\n", state);
-       }
+       dmio_printf(state->iocom, 5, "terminate state %p\n", state);
        assert((state->flags & (DMSG_STATE_ROOT |
                                DMSG_STATE_SUBINSERTED |
                                DMSG_STATE_RBINSERTED)) == 0);
index 52ebf81..7b09f44 100644 (file)
@@ -332,6 +332,7 @@ static struct dmsg_media_queue mediaq = TAILQ_HEAD_INITIALIZER(mediaq);
 
 static void dmsg_lnk_span(dmsg_msg_t *msg);
 static void dmsg_lnk_conn(dmsg_msg_t *msg);
+static void dmsg_lnk_ping(dmsg_msg_t *msg);
 static void dmsg_lnk_relay(dmsg_msg_t *msg);
 static void dmsg_relay_scan(h2span_conn_t *conn, h2span_node_t *node);
 static void dmsg_relay_delete(h2span_relay_t *relay);
@@ -364,6 +365,9 @@ dmsg_msg_lnk(dmsg_msg_t *msg)
        case DMSG_LNK_SPAN:
                dmsg_lnk_span(msg);
                break;
+       case DMSG_LNK_PING:
+               dmsg_lnk_ping(msg);
+               break;
        default:
                iocom->usrmsg_callback(msg, 1);
                /* state invalid after reply */
@@ -390,7 +394,7 @@ dmsg_lnk_conn(dmsg_msg_t *msg)
 
        pthread_mutex_lock(&cluster_mtx);
 
-       fprintf(stderr,
+       dmio_printf(iocom, 3,
                "dmsg_lnk_conn: msg %p cmd %08x state %p "
                "txcmd %08x rxcmd %08x\n",
                msg, msg->any.head.cmd, state,
@@ -404,7 +408,7 @@ dmsg_lnk_conn(dmsg_msg_t *msg)
                 * acknowledge the request, leaving the transaction open.
                 * We then relay priority-selected SPANs.
                 */
-               fprintf(stderr, "LNK_CONN(%08x): %s/%s/%s\n",
+               dmio_printf(iocom, 3, "LNK_CONN(%08x): %s/%s/%s\n",
                        (uint32_t)msg->any.head.msgid,
                        dmsg_uuid_to_str(&msg->any.lnk_conn.pfs_clid,
                                            &alloc),
@@ -455,7 +459,7 @@ dmsg_lnk_conn(dmsg_msg_t *msg)
                 * On transaction terminate we clean out our h2span_conn
                 * and acknowledge the request, closing the transaction.
                 */
-               fprintf(stderr, "LNK_CONN: Terminated\n");
+               dmio_printf(iocom, 3, "%s\n", "LNK_CONN: Terminated");
                conn = state->any.conn;
                assert(conn);
 
@@ -467,7 +471,7 @@ dmsg_lnk_conn(dmsg_msg_t *msg)
                media = state->media;
                --media->refs;
                if (media->refs == 0) {
-                       fprintf(stderr, "Media shutdown\n");
+                       dmio_printf(iocom, 3, "%s\n", "Media shutdown");
                        TAILQ_REMOVE(&mediaq, media, entry);
                        pthread_mutex_unlock(&cluster_mtx);
                        iocom->usrmsg_callback(msg, 0);
@@ -537,7 +541,8 @@ dmsg_lnk_span(dmsg_msg_t *msg)
         * we can ignore that too.
         */
        if (msg->any.head.cmd & DMSGF_REPLY) {
-               printf("Ignore reply to LNK_SPAN\n");
+               dmio_printf(iocom, 2, "%s\n",
+                           "Ignore reply to LNK_SPAN");
                return;
        }
 
@@ -622,14 +627,14 @@ dmsg_lnk_span(dmsg_msg_t *msg)
 
                RB_INSERT(h2span_link_tree, &node->tree, slink);
 
-               fprintf(stderr,
-                       "LNK_SPAN(thr %p): %p %s cl=%s fs=%s dist=%d\n",
-                       iocom,
-                       slink,
-                       dmsg_uuid_to_str(&msg->any.lnk_span.pfs_clid, &alloc),
-                       msg->any.lnk_span.cl_label,
-                       msg->any.lnk_span.fs_label,
-                       msg->any.lnk_span.dist);
+               dmio_printf(iocom, 3,
+                           "LNK_SPAN(thr %p): %p %s cl=%s fs=%s dist=%d\n",
+                           iocom, slink,
+                           dmsg_uuid_to_str(&msg->any.lnk_span.pfs_clid,
+                                            &alloc),
+                           msg->any.lnk_span.cl_label,
+                           msg->any.lnk_span.fs_label,
+                           msg->any.lnk_span.dist);
                free(alloc);
 #if 0
                dmsg_relay_scan(NULL, node);
@@ -653,12 +658,12 @@ dmsg_lnk_span(dmsg_msg_t *msg)
                node = slink->node;
                cls = node->cls;
 
-               fprintf(stderr, "LNK_DELE(thr %p): %p %s cl=%s fs=%s\n",
-                       iocom,
-                       slink,
-                       dmsg_uuid_to_str(&cls->pfs_clid, &alloc),
-                       cls->cl_label,
-                       node->fs_label);
+               dmio_printf(iocom, 3,
+                           "LNK_DELE(thr %p): %p %s cl=%s fs=%s\n",
+                           iocom, slink,
+                           dmsg_uuid_to_str(&cls->pfs_clid, &alloc),
+                           cls->cl_label,
+                           node->fs_label);
                free(alloc);
 
                /*
@@ -712,6 +717,26 @@ dmsg_lnk_span(dmsg_msg_t *msg)
        pthread_mutex_unlock(&cluster_mtx);
 }
 
+/*
+ * Respond to a PING with a PING|REPLY, forward replies to the usermsg
+ * callback.
+ */
+static
+void
+dmsg_lnk_ping(dmsg_msg_t *msg)
+{
+       dmsg_msg_t *rep;
+
+       if (msg->any.head.cmd & DMSGF_REPLY) {
+               msg->state->iocom->usrmsg_callback(msg, 1);
+       } else {
+               rep = dmsg_msg_alloc(msg->state, 0,
+                                    DMSG_LNK_PING | DMSGF_REPLY,
+                                    NULL, NULL);
+               dmsg_msg_write(rep);
+       }
+}
+
 /*
  * Update relay transactions for SPANs.
  *
@@ -826,8 +851,7 @@ dmsg_relay_scan_specific(h2span_node_t *node, h2span_conn_t *conn)
        if (relay)
                assert(relay->source_rt->any.link->node == node);
 
-       if (DMsgDebugOpt > 8)
-               fprintf(stderr, "relay scan for connection %p\n", conn);
+       dm_printf(9, "relay scan for connection %p\n", conn);
 
        /*
         * Iterate the node's links (received SPANs) in distance order,
@@ -978,7 +1002,7 @@ dmsg_relay_scan_specific(h2span_node_t *node, h2span_conn_t *conn)
         */
        while (relay && relay->source_rt->any.link->node == node) {
                next_relay = RB_NEXT(h2span_relay_tree, &conn->tree, relay);
-               fprintf(stderr, "RELAY DELETE FROM EXTRAS\n");
+               dm_printf(9, "%s\n", "RELAY DELETE FROM EXTRAS");
                dmsg_relay_delete(relay);
                relay = next_relay;
        }
@@ -1013,7 +1037,7 @@ dmsg_findspan(const char *label)
 done:
        pthread_mutex_unlock(&cluster_mtx);
 
-       fprintf(stderr, "findspan: %p\n", state);
+       dm_printf(8, "findspan: %p\n", state);
 
        return state;
 }
@@ -1083,7 +1107,7 @@ dmsg_lnk_relay(dmsg_msg_t *msg)
 
        if (msg->any.head.cmd & DMSGF_DELETE) {
                pthread_mutex_lock(&cluster_mtx);
-               fprintf(stderr, "RELAY DELETE FROM LNK_RELAY MSG\n");
+               dm_printf(8, "%s\n", "RELAY DELETE FROM LNK_RELAY MSG");
                if ((relay = state->any.relay) != NULL) {
                        dmsg_relay_delete(relay);
                } else {
@@ -1100,16 +1124,16 @@ static
 void
 dmsg_relay_delete(h2span_relay_t *relay)
 {
-       fprintf(stderr,
-               "RELAY DELETE %p RELAY %p ON CLS=%p NODE=%p "
-               "DIST=%d FD %d STATE %p\n",
-               relay->source_rt->any.link,
-               relay,
-               relay->source_rt->any.link->node->cls,
-               relay->source_rt->any.link->node,
-               relay->source_rt->any.link->lnk_span.dist,
-               relay->conn->state->iocom->sock_fd,
-               relay->target_rt);
+       dm_printf(8,
+                 "RELAY DELETE %p RELAY %p ON CLS=%p NODE=%p "
+                 "DIST=%d FD %d STATE %p\n",
+                 relay->source_rt->any.link,
+                 relay,
+                 relay->source_rt->any.link->node->cls,
+                 relay->source_rt->any.link->node,
+                 relay->source_rt->any.link->lnk_span.dist,
+                 relay->conn->state->iocom->sock_fd,
+                 relay->target_rt);
 
        RB_REMOVE(h2span_relay_tree, &relay->conn->tree, relay);
        TAILQ_REMOVE(&relay->source_rt->any.link->relayq, relay, entry);
index e1e4ec6..b9c3b04 100644 (file)
@@ -71,9 +71,9 @@ dmsg_master_service(void *data)
        dmsg_iocom_core(&iocom);
        dmsg_iocom_done(&iocom);
 
-       fprintf(stderr,
-               "iocom on fd %d terminated error rx=%d, tx=%d\n",
-               info->fd, iocom.ioq_rx.error, iocom.ioq_tx.error);
+       dmio_printf(iocom, 1,
+                   "iocom on fd %d terminated error rx=%d, tx=%d\n",
+                   info->fd, iocom.ioq_rx.error, iocom.ioq_tx.error);
        close(info->fd);
        info->fd = -1;  /* safety */
        if (info->exit_callback)
index 2e6b509..e9d120f 100644 (file)
@@ -96,8 +96,8 @@ dmsg_connect(const char *hostname)
         * Acquire socket and set options
         */
        if ((fd = socket(AF_INET, SOCK_STREAM, 0)) < 0) {
-               fprintf(stderr, "cmd_debug: socket(): %s\n",
-                       strerror(errno));
+               dm_printf(1, "cmd_debug: socket(): %s\n",
+                         strerror(errno));
                return -1;
        }
        opt = 1;
@@ -115,8 +115,7 @@ dmsg_connect(const char *hostname)
                hen = gethostbyname2(hostname, AF_INET);
                if (hen == NULL) {
                        if (inet_pton(AF_INET, hostname, &lsin.sin_addr) != 1) {
-                               fprintf(stderr,
-                                       "Cannot resolve %s\n", hostname);
+                               dm_printf(3, "Cannot resolve %s\n", hostname);
                                return -1;
                        }
                } else {
@@ -126,8 +125,8 @@ dmsg_connect(const char *hostname)
        if (connect(fd, (struct sockaddr *)&lsin, sizeof(lsin)) < 0) {
                close(fd);
                if (DMsgDebugOpt > 2) {
-                       fprintf(stderr, "debug: Connect failed: %s\n",
-                               strerror(errno));
+                       dm_printf(3, "debug: Connect failed: %s\n",
+                                 strerror(errno));
                }
                return -1;
        }
index 67b4e72..4ef3379 100644 (file)
@@ -236,6 +236,7 @@ shell_ttymsg(dmsg_iocom_t *iocom)
  * Debug session back-end (on remote side)
  */
 static void shell_span(dmsg_msg_t *msg, char *cmdbuf);
+static void shell_ping(dmsg_msg_t *msg, char *cmdbuf);
 
 void
 hammer2_shell_parse(dmsg_msg_t *msg, int unmanaged)
@@ -246,9 +247,14 @@ hammer2_shell_parse(dmsg_msg_t *msg, int unmanaged)
        uint32_t cmd;
 
        /*
-        * Filter on debug shell commands only
+        * Filter on debug shell commands and ping responses only
         */
        cmd = msg->any.head.cmd;
+       if ((cmd & DMSGF_CMDSWMASK) == (DMSG_LNK_PING | DMSGF_REPLY)) {
+               dmsg_printf(iocom, "ping reply\n");
+               return;
+       }
+
        if ((cmd & DMSGF_PROTOS) != DMSG_PROTO_DBG) {
                if (unmanaged)
                        dmsg_msg_reply(msg, DMSG_ERR_NOSUPP);
@@ -268,6 +274,8 @@ hammer2_shell_parse(dmsg_msg_t *msg, int unmanaged)
 
        if (cmdp == NULL || *cmdp == 0) {
                ;
+       } else if (strcmp(cmdp, "ping") == 0) {
+               shell_ping(msg, cmdbuf);
        } else if (strcmp(cmdp, "span") == 0) {
                shell_span(msg, cmdbuf);
        } else if (strcmp(cmdp, "tree") == 0) {
@@ -283,6 +291,17 @@ hammer2_shell_parse(dmsg_msg_t *msg, int unmanaged)
        dmsg_printf(iocom, "debug> ");
 }
 
+static void
+shell_ping(dmsg_msg_t *msg, char *cmdbuf __unused)
+{
+       dmsg_iocom_t *iocom = msg->state->iocom;
+       dmsg_msg_t *m2;
+
+       dmsg_printf(iocom, "sending ping\n");
+       m2 = dmsg_msg_alloc(msg->state, 0, DMSG_LNK_PING, NULL, NULL);
+       dmsg_msg_write(m2);
+}
+
 static void
 shell_span(dmsg_msg_t *msg, char *cmdbuf)
 {
index 4c1d2f5..bdaf3c1 100644 (file)
@@ -703,8 +703,11 @@ autoconn_connect_thread(void *data)
        while (ac->stopme == 0) {
                fd = dmsg_connect(ac->host);
                if (fd < 0) {
-                       fprintf(stderr, "autoconn: Connect failure: %s\n",
-                               ac->host);
+                       if (DMsgDebugOpt > 2) {
+                               fprintf(stderr,
+                                       "autoconn: Connect failure: %s\n",
+                                       ac->host);
+                       }
                        sleep(5);
                        continue;
                }
index 23877cc..a73a62c 100644 (file)
@@ -78,6 +78,9 @@ SYSCTL_INT(_debug, OID_AUTO, xa_active, CTLFLAG_RW, &xa_active, 0,
 static uint64_t xa_last;
 SYSCTL_ULONG(_debug, OID_AUTO, xa_last, CTLFLAG_RW, &xa_last, 0,
           "Offset of last xdisk IO");
+static int xa_debug = 1;
+SYSCTL_INT(_debug, OID_AUTO, xa_debug, CTLFLAG_RW, &xa_debug, 0,
+          "xdisk debugging");
 
 /*
  * Track a BIO tag
@@ -112,6 +115,7 @@ struct xa_softc {
        uint64_t        keyid;
        int             serializing;
        int             last_error;
+       int             terminating;
        char            cl_label[64];   /* from LNK_SPAN cl_label (host/dev) */
        char            fs_label[64];   /* from LNK_SPAN fs_label (serno str) */
        xa_tag_t        *open_tag;
@@ -153,6 +157,9 @@ static int xa_sync_completion(kdmsg_state_t *state, kdmsg_msg_t *msg);
 static int xa_bio_completion(kdmsg_state_t *state, kdmsg_msg_t *msg);
 static void xa_restart_deferred(xa_softc_t *sc);
 
+#define xa_printf(level, ctl, ...)     \
+       if (xa_debug >= (level)) kprintf("xdisk: " ctl, __VA_ARGS__)
+
 MALLOC_DEFINE(M_XDISK, "Networked disk client", "Network Disks");
 
 /*
@@ -210,6 +217,8 @@ xdisk_modevent(module_t mod, int type, void *data)
                break;
        case MOD_UNLOAD:
        case MOD_SHUTDOWN:
+               if (!RB_EMPTY(&xa_device_tree))
+                       return (EBUSY);
                if (xdisk_opencount || TAILQ_FIRST(&xaiocomq))
                        return (EBUSY);
                if (xdisk_dev) {
@@ -289,7 +298,7 @@ xdisk_attach(struct xdisk_attach_ioctl *xaioc)
        fp = holdfp(curproc->p_fd, xaioc->fd, -1);
        if (fp == NULL)
                return EINVAL;
-       kprintf("xdisk_attach fp=%p\n", fp);
+       xa_printf(1, "xdisk_attach fp=%p\n", fp);
 
        /*
         * See if the serial number is already present.  If we are
@@ -352,7 +361,7 @@ xaio_exit(kdmsg_iocom_t *iocom)
        xa_iocom_t *xaio = iocom->handle;
 
        lockmgr(&xdisk_lk, LK_EXCLUSIVE);
-       kprintf("xdisk_detach [xaio_exit()]\n");
+       xa_printf(1, "%s", "xdisk_detach [xaio_exit()]\n");
        TAILQ_REMOVE(&xaiocomq, xaio, entry);
        lockmgr(&xdisk_lk, LK_RELEASE);
 
@@ -376,7 +385,8 @@ xaio_rcvdmsg(kdmsg_msg_t *msg)
        xa_softc_t      *sc;
 
        if (state) {
-               kprintf("xdisk - rcvmsg state=%p rx=%08x tx=%08x msgcmd=%08x\n",
+               xa_printf(4,
+                       "xdisk - rcvmsg state=%p rx=%08x tx=%08x msgcmd=%08x\n",
                        state, state->rxcmd, state->txcmd,
                        msg->any.head.cmd);
        }
@@ -405,8 +415,8 @@ xaio_rcvdmsg(kdmsg_msg_t *msg)
                      sizeof(xaio->dummysc.fs_label));
                xaio->dummysc.fs_label[sizeof(xaio->dummysc.fs_label) - 1] = 0;
 
-               kprintf("xdisk: LINK_SPAN state %p create for %s\n",
-                       msg->state, msg->any.lnk_span.fs_label);
+               xa_printf(3, "LINK_SPAN state %p create for %s\n",
+                         msg->state, msg->any.lnk_span.fs_label);
 
                sc = RB_FIND(xa_softc_tree, &xa_device_tree, &xaio->dummysc);
                if (sc == NULL) {
@@ -492,14 +502,12 @@ xaio_rcvdmsg(kdmsg_msg_t *msg)
                         *          it is synchronous and issues more disk
                         *          I/Os, we will deadlock.
                         */
-                       kprintf("xdisk: A1\n");
                        disk_setdiskinfo(&sc->disk, &sc->info);
                        xa_restart_deferred(sc);        /* eats serializing */
                        lockmgr(&sc->lk, LK_RELEASE);
                } else {
                        lockmgr(&sc->lk, LK_EXCLUSIVE);
                        ++sc->spancnt;
-                       kprintf("xdisk: A2 (%d) ser=%d otag=%p\n", sc->spancnt, sc->serializing, sc->open_tag);
                        TAILQ_INSERT_TAIL(&sc->spanq, msg->state, user_entry);
                        msg->state->any.xa_sc = sc;
                        if (sc->serializing == 0 && sc->open_tag == NULL) {
@@ -508,13 +516,14 @@ xaio_rcvdmsg(kdmsg_msg_t *msg)
                        }
                        lockmgr(&sc->lk, LK_RELEASE);
                        if (sc->dev && sc->dev->si_disk) {
-                               kprintf("reprobe\n");
+                               xa_printf(1, "reprobe disk: %s\n",
+                                         sc->fs_label);
                                disk_msg_send(DISK_DISK_REPROBE,
                                              sc->dev->si_disk,
                                              NULL);
                        }
                }
-               kprintf("xdisk: sc %p spancnt %d\n", sc, sc->spancnt);
+               xa_printf(2, "sc %p spancnt %d\n", sc, sc->spancnt);
                kdmsg_msg_result(msg, 0);
                break;
        case DMSG_LNK_SPAN | DMSGF_DELETE:
@@ -524,14 +533,14 @@ xaio_rcvdmsg(kdmsg_msg_t *msg)
                 * Return a final result, closing our end of the transaction.
                 */
                sc = msg->state->any.xa_sc;
-               kprintf("xdisk: LINK_SPAN state %p delete for %s (sc=%p)\n",
-                       msg->state, (sc ? sc->fs_label : "(null)"), sc);
+               xa_printf(3, "LINK_SPAN state %p delete for %s (sc=%p)\n",
+                         msg->state, (sc ? sc->fs_label : "(null)"), sc);
                lockmgr(&sc->lk, LK_EXCLUSIVE);
                msg->state->any.xa_sc = NULL;
                TAILQ_REMOVE(&sc->spanq, msg->state, user_entry);
                --sc->spancnt;
 
-               kprintf("xdisk: sc %p spancnt %d\n", sc, sc->spancnt);
+               xa_printf(2, "sc %p spancnt %d\n", sc, sc->spancnt);
 
                /*
                 * Spans can come and go as the graph stabilizes, so if
@@ -559,16 +568,16 @@ xaio_rcvdmsg(kdmsg_msg_t *msg)
                 * Ignore unimplemented streaming replies on our LNK_SPAN
                 * transaction.
                 */
-               kprintf("xdisk: LINK_SPAN state %p delete+reply\n",
-                       msg->state);
+               xa_printf(3, "LINK_SPAN state %p delete+reply\n",
+                         msg->state);
                break;
        case DMSG_LNK_SPAN | DMSGF_REPLY:
                /*
                 * Ignore unimplemented streaming replies on our LNK_SPAN
                 * transaction.
                 */
-               kprintf("xdisk: LINK_SPAN state %p reply\n",
-                       msg->state);
+               xa_printf(3, "LINK_SPAN state %p reply\n",
+                         msg->state);
                break;
        case DMSG_DBG_SHELL:
                /*
@@ -591,8 +600,7 @@ xaio_rcvdmsg(kdmsg_msg_t *msg)
                 */
                if (msg->aux_data) {
                        msg->aux_data[msg->aux_size - 1] = 0;
-                       kprintf("xdisk: DEBUGMSG: %s\n",
-                               msg->aux_data);
+                       xa_printf(0, "DEBUGMSG: %s\n", msg->aux_data);
                }
                break;
        default:
@@ -630,13 +638,14 @@ xa_terminate_check(struct xa_softc *sc)
        /*
         * Determine if we can destroy the softc.
         */
-       kprintf("xdisk: terminate check xa%d (%d,%d,%d) sc=%p ",
+       xa_printf(1, "Terminate check xa%d (%d,%d,%d) sc=%p ",
                sc->unit,
                sc->opencnt, sc->serializing, sc->spancnt,
                sc);
 
-       if (sc->opencnt || sc->serializing || sc->spancnt) {
-               kprintf("(leave intact)\n");
+       if (sc->opencnt || sc->serializing || sc->spancnt ||
+           TAILQ_FIRST(&sc->bioq) || TAILQ_FIRST(&sc->tag_pendq)) {
+               xa_printf(1, "%s", "(leave intact)\n");
                return;
        }
 
@@ -645,6 +654,7 @@ xa_terminate_check(struct xa_softc *sc)
         * will create a new softc and disk.
         */
        RB_REMOVE(xa_softc_tree, &xa_device_tree, sc);
+       sc->terminating = 1;
 
        /*
         * Device has to go first to prevent device ops races.
@@ -656,7 +666,7 @@ xa_terminate_check(struct xa_softc *sc)
                sc->dev = NULL;
        }
 
-       kprintf("(remove from tree)\n");
+       xa_printf(1, "%s", "(remove from tree)\n");
        sc->serializing = 1;
        KKASSERT(sc->opencnt == 0);
        KKASSERT(TAILQ_EMPTY(&sc->tag_pendq));
@@ -699,6 +709,10 @@ again:
                tsleep(sc, 0, "xarace", hz / 10);
                goto again;
        }
+       if (sc->terminating) {
+               lockmgr(&xdisk_lk, LK_RELEASE);
+               return ENXIO;   /* raced destruction */
+       }
        sc->serializing = 1;
 
        /*
@@ -750,10 +764,16 @@ xa_close(struct dev_close_args *ap)
        xa_softc_t *sc;
        xa_tag_t *tag;
 
+       lockmgr(&xdisk_lk, LK_EXCLUSIVE);
        sc = dev->si_drv1;
-       if (sc == NULL)
+       if (sc == NULL) {
+               lockmgr(&sc->lk, LK_RELEASE);
                return ENXIO;   /* raced destruction */
-       lockmgr(&xdisk_lk, LK_EXCLUSIVE);
+       }
+       if (sc->terminating) {
+               lockmgr(&sc->lk, LK_RELEASE);
+               return ENXIO;   /* raced destruction */
+       }
        lockmgr(&sc->lk, LK_EXCLUSIVE);
 
        /*
@@ -1050,8 +1070,8 @@ xa_sync_completion(kdmsg_state_t *state, kdmsg_msg_t *msg)
         * of the transaction and we are waiting for the other side to
         * close.
         */
-       kprintf("xa_sync_completion: tag %p msg %08x state %p\n",
-               tag, msg->any.head.cmd, msg->state);
+       xa_printf(1, "xa_sync_completion: tag %p msg %08x state %p\n",
+                 tag, msg->any.head.cmd, msg->state);
 
        if (tag == NULL) {
                if (msg->any.head.cmd & DMSGF_CREATE)
@@ -1082,8 +1102,8 @@ xa_sync_completion(kdmsg_state_t *state, kdmsg_msg_t *msg)
                        break;
                }
                sc->last_error = tag->status.head.error;
-               kprintf("xdisk: blk_open completion status %d\n",
-                       sc->last_error);
+               xa_printf(1, "blk_open completion status %d\n",
+                         sc->last_error);
                if (sc->last_error == 0) {
                        while ((bio = TAILQ_FIRST(&sc->bioq)) != NULL) {
                                tag = xa_setup_cmd(sc, NULL);
@@ -1232,15 +1252,15 @@ handle_done:
 handle_repend:
        tag->bio = NULL;
        if (bio->bio_buf->b_flags & B_FAILONDIS) {
-               kprintf("xa_strategy: disconnected, fail bp %p\n",
-                       bio->bio_buf);
+               xa_printf(1, "xa_strategy: lost link, fail probe bp %p\n",
+                         bio->bio_buf);
                bio->bio_buf->b_error = ENXIO;
                bio->bio_buf->b_flags |= B_ERROR;
                biodone(bio);
                bio = NULL;
-               kprintf("BIO CIRC FAILURE, FAIL BIO %p\n", bio);
        } else {
-               kprintf("BIO CIRC FAILURE, REPEND BIO %p\n", bio);
+               xa_printf(1, "xa_strategy: lost link, requeue bp %p\n",
+                         bio->bio_buf);
        }
        xa_done(tag, 0);
        if ((state->txcmd & DMSGF_DELETE) == 0)
@@ -1310,9 +1330,10 @@ xa_restart_deferred(xa_softc_t *sc)
                                              DMSGF_CREATE,
                                              xa_sync_completion, tag);
                        msg->any.blk_open.modes = DMSG_BLKOPEN_RD;
-                       kprintf("xdisk: BLK_OPEN tag %p state %p "
-                               "span-state %p\n",
-                               tag, msg->state, span);
+                       xa_printf(1,
+                                 "BLK_OPEN tag %p state %p "
+                                 "span-state %p\n",
+                                 tag, msg->state, span);
                        xa_start(tag, msg, 0);
                }
                if (error) {
index c407629..e22004f 100644 (file)
@@ -46,6 +46,7 @@
 #include <sys/mount.h>
 #include <sys/socket.h>
 #include <sys/vnode.h>
+#include <sys/sysctl.h>
 #include <sys/file.h>
 #include <sys/proc.h>
 #include <sys/priv.h>
 
 RB_GENERATE(kdmsg_state_tree, kdmsg_state, rbnode, kdmsg_state_cmp);
 
+SYSCTL_NODE(, OID_AUTO, kdmsg, CTLFLAG_RW, 0, "kdmsg");
+static int kdmsg_debug = 1;
+SYSCTL_INT(_kdmsg, OID_AUTO, debug, CTLFLAG_RW, &kdmsg_debug, 0,
+          "Set debug level for kernel dmsg layer");
+
+#define kd_printf(level, ctl, ...)             \
+        if (kdmsg_debug >= (level)) kprintf("kdmsg: " ctl, __VA_ARGS__)
+
+#define kdio_printf(iocom, level, ctl, ...)      \
+        if (kdmsg_debug >= (level)) kprintf("kdmsg: " ctl, __VA_ARGS__)
+
 static int kdmsg_msg_receive_handling(kdmsg_msg_t *msg);
 static int kdmsg_state_msgrx(kdmsg_msg_t *msg);
 static int kdmsg_state_msgtx(kdmsg_msg_t *msg);
+static void kdmsg_msg_write_locked(kdmsg_iocom_t *iocom, kdmsg_msg_t *msg);
 static void kdmsg_state_cleanuprx(kdmsg_msg_t *msg);
 static void kdmsg_state_cleanuptx(kdmsg_msg_t *msg);
 static void kdmsg_subq_delete(kdmsg_state_t *state);
@@ -249,16 +262,33 @@ void
 kdmsg_iocom_uninit(kdmsg_iocom_t *iocom)
 {
        kdmsg_state_t *state;
+       kdmsg_msg_t *msg;
+       int retries;
 
        /*
-        * Ask the cluster controller to go away
+        * Ask the cluster controller to go away by setting
+        * KILLRX.  Send a PING to get a response to unstick reading
+        * from the pipe.
+        *
+        * After 10 seconds shitcan the pipe and do an unclean shutdown.
         */
        lockmgr(&iocom->msglk, LK_EXCLUSIVE);
+
        atomic_set_int(&iocom->msg_ctl, KDMSG_CLUSTERCTL_KILLRX);
+       msg = kdmsg_msg_alloc(&iocom->state0, DMSG_LNK_PING, NULL, NULL);
+       kdmsg_msg_write_locked(iocom, msg);
 
+       retries = 10;
        while (iocom->msgrd_td || iocom->msgwr_td) {
                wakeup(&iocom->msg_ctl);
                lksleep(iocom, &iocom->msglk, 0, "clstrkl", hz);
+               if (--retries == 0 && iocom->msg_fp) {
+                       kdio_printf(iocom, 0, "%s\n",
+                                   "iocom_uninit: "
+                                   "shitcanning unresponsive pipe");
+                       fp_shutdown(iocom->msg_fp, SHUT_RDWR);
+                       /* retries allowed to go negative, keep looping */
+               }
        }
 
        /*
@@ -309,13 +339,13 @@ kdmsg_iocom_thread_rd(void *arg)
                if (error)
                        break;
                if (hdr.magic != DMSG_HDR_MAGIC) {
-                       kprintf("kdmsg: bad magic: %04x\n", hdr.magic);
+                       kdio_printf(iocom, 1, "bad magic: %04x\n", hdr.magic);
                        error = EINVAL;
                        break;
                }
                hbytes = (hdr.cmd & DMSGF_SIZE) * DMSG_ALIGN;
                if (hbytes < sizeof(hdr) || hbytes > DMSG_HDR_MAX) {
-                       kprintf("kdmsg: bad header size %zd\n", hbytes);
+                       kdio_printf(iocom, 1, "bad header size %zd\n", hbytes);
                        error = EINVAL;
                        break;
                }
@@ -331,15 +361,17 @@ kdmsg_iocom_thread_rd(void *arg)
                                        hbytes - sizeof(hdr),
                                        NULL, 1, UIO_SYSSPACE);
                        if (error) {
-                               kprintf("kdmsg: short msg received\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "short msg received");
                                error = EINVAL;
                                break;
                        }
                }
                msg->aux_size = hdr.aux_bytes;
                if (msg->aux_size > DMSG_AUX_MAX) {
-                       kprintf("kdmsg: illegal msg payload size %zd\n",
-                               msg->aux_size);
+                       kdio_printf(iocom, 1,
+                                   "illegal msg payload size %zd\n",
+                                   msg->aux_size);
                        error = EINVAL;
                        break;
                }
@@ -350,7 +382,8 @@ kdmsg_iocom_thread_rd(void *arg)
                        error = fp_read(iocom->msg_fp, msg->aux_data,
                                        abytes, NULL, 1, UIO_SYSSPACE);
                        if (error) {
-                               kprintf("kdmsg: short msg payload received\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "short msg payload received");
                                break;
                        }
                }
@@ -359,7 +392,7 @@ kdmsg_iocom_thread_rd(void *arg)
                msg = NULL;
        }
 
-       kprintf("kdmsg: read thread terminating error=%d\n", error);
+       kdio_printf(iocom, 1, "read thread terminating error=%d\n", error);
 
        lockmgr(&iocom->msglk, LK_EXCLUSIVE);
        if (msg)
@@ -469,7 +502,7 @@ kdmsg_iocom_thread_wr(void *arg)
                }
        }
 
-       kprintf("kdmsg: write thread terminating error=%d\n", error);
+       kdio_printf(iocom, 1, "write thread terminating error=%d\n", error);
 
        /*
         * Shutdown the socket and set KILLTX for consistency in case the
@@ -511,28 +544,34 @@ kdmsg_iocom_thread_wr(void *arg)
                 * Simulate failure for all sub-states of state0.
                 */
                kdmsg_drain_msgq(iocom);
-               kprintf("simulate failure for all substates of state0\n");
+               kdio_printf(iocom, 2, "%s\n",
+                           "simulate failure for all substates of state0");
                kdmsg_simulate_failure(&iocom->state0, 0, DMSG_ERR_LOSTLINK);
 
                lksleep(iocom, &iocom->msglk, 0, "clstrtk", hz / 2);
 
                if ((int)(ticks - save_ticks) > hz*2 && didwarn == 0) {
                        didwarn = 1;
-                       kprintf("kdmsg: warning, write thread on %p still "
-                               "terminating\n", iocom);
+                       kdio_printf(iocom, 0,
+                                   "Warning, write thread on %p "
+                                   "still terminating\n",
+                                   iocom);
                }
                if ((int)(ticks - save_ticks) > hz*15 && didwarn == 1) {
                        didwarn = 2;
-                       kprintf("kdmsg: warning, write thread on %p still "
-                               "terminating\n", iocom);
+                       kdio_printf(iocom, 0,
+                                   "Warning, write thread on %p "
+                                   "still terminating\n",
+                                   iocom);
                }
                if ((int)(ticks - save_ticks) > hz*60) {
-                       kprintf("kdmsg: msgq %p rd_tree %p wr_tree %p\n",
-                               TAILQ_FIRST(&iocom->msgq),
-                               RB_ROOT(&iocom->staterd_tree),
-                               RB_ROOT(&iocom->statewr_tree));
-                       panic("kdmsg: write thread on %p could not terminate\n",
-                             iocom);
+                       kdio_printf(iocom, 0,
+                                   "Can't terminate: msgq %p "
+                                   "rd_tree %p wr_tree %p\n",
+                                   TAILQ_FIRST(&iocom->msgq),
+                                   RB_ROOT(&iocom->staterd_tree),
+                                   RB_ROOT(&iocom->statewr_tree));
+                       lksleep(iocom, &iocom->msglk, 0, "clstrtk", hz * 10);
                }
        }
 
@@ -613,15 +652,20 @@ kdmsg_msg_receive_handling(kdmsg_msg_t *msg)
         */
        error = kdmsg_state_msgrx(msg);
        if (msg->state->flags & KDMSG_STATE_ABORTING) {
-               kprintf("kdmsg_state_abort(b): state %p rxcmd=%08x txcmd=%08x msgrx error %d\n",
-                       msg->state, msg->state->rxcmd, msg->state->txcmd, error);
+               kdio_printf(iocom, 5,
+                           "kdmsg_state_abort(b): state %p rxcmd=%08x "
+                           "txcmd=%08x msgrx error %d\n",
+                           msg->state, msg->state->rxcmd,
+                           msg->state->txcmd, error);
        }
        if (error) {
                /*
                 * Raw protocol or connection error
                 */
                if (msg->state->flags & KDMSG_STATE_ABORTING)
-                       kprintf("X1 state %p error %d\n", msg->state, error);
+                       kdio_printf(iocom, 5,
+                                   "X1 state %p error %d\n",
+                                   msg->state, error);
                kdmsg_msg_free(msg);
                if (error == EALREADY)
                        error = 0;
@@ -631,17 +675,21 @@ kdmsg_msg_receive_handling(kdmsg_msg_t *msg)
                 * handling function installed for it.
                 */
                if (msg->state->flags & KDMSG_STATE_ABORTING)
-                       kprintf("X2 state %p func %p\n", msg->state, msg->state->func);
+                       kdio_printf(iocom, 5,
+                                   "X2 state %p func %p\n",
+                                   msg->state, msg->state->func);
                error = msg->state->func(msg->state, msg);
                kdmsg_state_cleanuprx(msg);
        } else if (iocom->flags & KDMSG_IOCOMF_AUTOANY) {
                if (msg->state->flags & KDMSG_STATE_ABORTING)
-                       kprintf("X3 state %p\n", msg->state);
+                       kdio_printf(iocom, 5,
+                                   "X3 state %p\n", msg->state);
                error = kdmsg_autorxmsg(msg);
                kdmsg_state_cleanuprx(msg);
        } else {
                if (msg->state->flags & KDMSG_STATE_ABORTING)
-                       kprintf("X4 state %p\n", msg->state);
+                       kdio_printf(iocom, 5,
+                                   "X4 state %p\n", msg->state);
                error = iocom->rcvmsg(msg);
                kdmsg_state_cleanuprx(msg);
        }
@@ -785,7 +833,8 @@ again:
                 * New persistant command received.
                 */
                if (state != &iocom->state0) {
-                       kprintf("kdmsg_state_msgrx: duplicate transaction\n");
+                       kdio_printf(iocom, 1, "%s\n",
+                                   "duplicate transaction");
                        error = EINVAL;
                        break;
                }
@@ -808,8 +857,9 @@ again:
                                                 &sdummy);
                        }
                        if (pstate == NULL) {
-                               kprintf("kdmsg_state_msgrx: "
-                                       "missing parent in stacked trans\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "missing parent in "
+                                           "stacked trans");
                                error = EINVAL;
                                break;
                        }
@@ -853,12 +903,13 @@ again:
                 */
                if (state == &iocom->state0) {
                        if (msg->any.head.cmd & DMSGF_ABORT) {
-                               kprintf("kdmsg_state_msgrx: "
-                                       "state already A\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "msgrx: "
+                                           "state already A");
                                error = EALREADY;
                        } else {
-                               kprintf("kdmsg_state_msgrx: "
-                                       "no state for DELETE\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "msgrx: no state for DELETE");
                                error = EINVAL;
                        }
                        break;
@@ -870,12 +921,12 @@ again:
                 */
                if ((state->rxcmd & DMSGF_CREATE) == 0) {
                        if (msg->any.head.cmd & DMSGF_ABORT) {
-                               kprintf("kdmsg_state_msgrx: "
-                                       "state already B\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "msgrx: state already B");
                                error = EALREADY;
                        } else {
-                               kprintf("kdmsg_state_msgrx: "
-                                       "state reused for DELETE\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "msgrx: state reused for DELETE");
                                error = EINVAL;
                        }
                        break;
@@ -903,10 +954,11 @@ again:
                 * persistent state message should already exist.
                 */
                if (state == &iocom->state0) {
-                       kprintf("kdmsg_state_msgrx: no state match for "
-                               "REPLY cmd=%08x msgid=%016jx\n",
-                               msg->any.head.cmd,
-                               (intmax_t)msg->any.head.msgid);
+                       kdio_printf(iocom, 1,
+                                   "msgrx: no state match for "
+                                   "REPLY cmd=%08x msgid=%016jx\n",
+                                   msg->any.head.cmd,
+                                   (intmax_t)msg->any.head.msgid);
                        error = EINVAL;
                        break;
                }
@@ -922,8 +974,9 @@ again:
                        if (msg->any.head.cmd & DMSGF_ABORT) {
                                error = EALREADY;
                        } else {
-                               kprintf("kdmsg_state_msgrx: no state match "
-                                       "for REPLY|DELETE\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "msgrx: no state match "
+                                           "for REPLY|DELETE");
                                error = EINVAL;
                        }
                        break;
@@ -938,8 +991,9 @@ again:
                        if (msg->any.head.cmd & DMSGF_ABORT) {
                                error = EALREADY;
                        } else {
-                               kprintf("kdmsg_state_msgrx: state reused "
-                                       "for REPLY|DELETE\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "msgrx: state reused "
+                                           "for REPLY|DELETE");
                                error = EINVAL;
                        }
                        break;
@@ -994,8 +1048,9 @@ done:
         * updated.
         */
        if ((state = msg->state) == NULL || error != 0) {
-               kprintf("kdmsg_state_msgrx: state=%p error %d\n", state, error);
-               ;
+               kdio_printf(iocom, 1,
+                           "msgrx: state=%p error %d\n",
+                           state, error);
        } else if (msg->any.head.cmd & DMSGF_DELETE) {
                KKASSERT((state->rxcmd & DMSGF_DELETE) == 0);
                state->rxcmd |= DMSGF_DELETE;
@@ -1030,6 +1085,7 @@ static int
 kdmsg_autorxmsg(kdmsg_msg_t *msg)
 {
        kdmsg_iocom_t *iocom = msg->state->iocom;
+       kdmsg_msg_t *rep;
        int error = 0;
        uint32_t cmd;
 
@@ -1050,6 +1106,17 @@ kdmsg_autorxmsg(kdmsg_msg_t *msg)
        }
 
        switch(cmd) {
+       case DMSG_LNK_PING:
+               /*
+                * Received ping, send reply
+                */
+               rep = kdmsg_msg_alloc(msg->state, DMSG_LNK_PING | DMSGF_REPLY,
+                                     NULL, NULL);
+               kdmsg_msg_write(rep);
+               break;
+       case DMSG_LNK_PING | DMSGF_REPLY:
+               /* ignore replies */
+               break;
        case DMSG_LNK_CONN | DMSGF_CREATE:
        case DMSG_LNK_CONN | DMSGF_CREATE | DMSGF_DELETE:
                /*
@@ -1158,11 +1225,12 @@ kdmsg_state_cleanuprx(kdmsg_msg_t *msg)
                 */
                if ((msg->any.head.cmd & DMSGF_DELETE) &&
                    TAILQ_FIRST(&msg->state->subq)) {
-                       kprintf("simulate failure for substates of state %p "
-                               "cmd %08x/%08x\n",
-                               msg->state,
-                               msg->state->rxcmd,
-                               msg->state->txcmd);
+                       kdio_printf(iocom, 2,
+                                   "simulate failure for substates of "
+                                   "state %p cmd %08x/%08x\n",
+                                   msg->state,
+                                   msg->state->rxcmd,
+                                   msg->state->txcmd);
                        kdmsg_simulate_failure(msg->state,
                                               0, DMSG_ERR_LOSTLINK);
                }
@@ -1278,8 +1346,11 @@ kdmsg_state_abort(kdmsg_state_t *state)
        state->flags |= KDMSG_STATE_ABORTING;
        kdmsg_state_dying(state);
        if (state->flags & KDMSG_STATE_NEW) {
-               kprintf("kdmsg_state_abort(0): state %p rxcmd %08x txcmd %08x flags %08x - in NEW state\n",
-                       state, state->rxcmd, state->txcmd, state->flags);
+               kdio_printf(iocom, 5,
+                           "kdmsg_state_abort(0): state %p rxcmd %08x "
+                           "txcmd %08x flags %08x - in NEW state\n",
+                           state, state->rxcmd,
+                           state->txcmd, state->flags);
                return;
        }
 
@@ -1293,8 +1364,9 @@ kdmsg_state_abort(kdmsg_state_t *state)
         *       (vs a message generated by the other side using its state),
         *       so we must invert DMSGF_REVTRANS and DMSGF_REVCIRC.
         */
-       kprintf("kdmsg_state_abort(1): state %p rxcmd %08x txcmd %08x\n",
-               state, state->rxcmd, state->txcmd);
+       kdio_printf(iocom, 5, 
+                   "kdmsg_state_abort(1): state %p rxcmd %08x txcmd %08x\n",
+                   state, state->rxcmd, state->txcmd);
        if ((state->rxcmd & DMSGF_DELETE) == 0) {
                msg = kdmsg_msg_alloc(state, DMSG_LNK_ERROR, NULL, NULL);
                if ((state->rxcmd & DMSGF_CREATE) == 0)
@@ -1303,16 +1375,18 @@ kdmsg_state_abort(kdmsg_state_t *state)
                                     (state->rxcmd & DMSGF_REPLY);
                msg->any.head.cmd ^= (DMSGF_REVTRANS | DMSGF_REVCIRC);
                msg->any.head.error = DMSG_ERR_LOSTLINK;
-               kprintf("kdmsg_state_abort(a): state %p msgcmd %08x\n",
-                       state, msg->any.head.cmd);
+               kdio_printf(iocom, 5,
+                           "kdmsg_state_abort(a): state %p msgcmd %08x\n",
+                           state, msg->any.head.cmd);
                /* circuit not initialized */
                lockmgr(&state->iocom->msglk, LK_RELEASE);
                kdmsg_msg_receive_handling(msg);
                lockmgr(&state->iocom->msglk, LK_EXCLUSIVE);
                msg = NULL;
        }
-       kprintf("kdmsg_state_abort(2): state %p rxcmd %08x txcmd %08x\n",
-               state, state->rxcmd, state->txcmd);
+       kdio_printf(iocom, 5,
+                   "kdmsg_state_abort(2): state %p rxcmd %08x txcmd %08x\n",
+                   state, state->rxcmd, state->txcmd);
 }
 
 /*
@@ -1419,7 +1493,8 @@ kdmsg_state_msgtx(kdmsg_msg_t *msg)
                        if (msg->any.head.cmd & DMSGF_ABORT) {
                                error = EALREADY;
                        } else {
-                               kprintf("kdmsg_state_msgtx: no state match "
+                               kdio_printf(iocom, 1,
+                                       "msgtx: no state match "
                                        "for DELETE cmd=%08x msgid=%016jx\n",
                                        msg->any.head.cmd,
                                        (intmax_t)msg->any.head.msgid);
@@ -1437,8 +1512,9 @@ kdmsg_state_msgtx(kdmsg_msg_t *msg)
                        if (msg->any.head.cmd & DMSGF_ABORT) {
                                error = EALREADY;
                        } else {
-                               kprintf("kdmsg_state_msgtx: state reused "
-                                       "for DELETE\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "msgtx: state reused "
+                                           "for DELETE");
                                error = EINVAL;
                        }
                        break;
@@ -1465,8 +1541,9 @@ kdmsg_state_msgtx(kdmsg_msg_t *msg)
                 * persistent state message should already exist.
                 */
                if (state == &state->iocom->state0) {
-                       kprintf("kdmsg_state_msgtx: no state match "
-                               "for REPLY | CREATE\n");
+                       kdio_printf(iocom, 1, "%s\n",
+                                   "msgtx: no state match "
+                                   "for REPLY | CREATE");
                        error = EINVAL;
                        break;
                }
@@ -1488,8 +1565,9 @@ kdmsg_state_msgtx(kdmsg_msg_t *msg)
                        if (msg->any.head.cmd & DMSGF_ABORT) {
                                error = EALREADY;
                        } else {
-                               kprintf("kdmsg_state_msgtx: no state match "
-                                       "for REPLY | DELETE\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "msgtx: no state match "
+                                           "for REPLY | DELETE");
                                error = EINVAL;
                        }
                        break;
@@ -1503,8 +1581,9 @@ kdmsg_state_msgtx(kdmsg_msg_t *msg)
                        if (msg->any.head.cmd & DMSGF_ABORT) {
                                error = EALREADY;
                        } else {
-                               kprintf("kdmsg_state_msgtx: state reused "
-                                       "for REPLY | DELETE\n");
+                               kdio_printf(iocom, 1, "%s\n",
+                                           "msgtx: state reused "
+                                           "for REPLY | DELETE");
                                error = EINVAL;
                        }
                        break;
@@ -1561,7 +1640,7 @@ kdmsg_state_cleanuptx(kdmsg_msg_t *msg)
         * iocom->msglk so we can do this before completing our task.
         */
        if (state->flags & KDMSG_STATE_SIGNAL) {
-               kprintf("kdmsg: state %p interlock!\n", state);
+               kdio_printf(iocom, 1, "state %p interlock!\n", state);
                wakeup(state);
        }
        state->flags &= ~(KDMSG_STATE_INTERLOCK | KDMSG_STATE_SIGNAL);
@@ -1617,9 +1696,10 @@ kdmsg_state_cleanuptx(kdmsg_msg_t *msg)
         */
        if ((state->flags & (KDMSG_STATE_ABORTING | KDMSG_STATE_DYING)) &&
            (state->rxcmd & DMSGF_DELETE) == 0) {
-               kprintf("kdmsg_state_cleanuptx: state=%p "
-                       "executing deferred abort\n",
-                       state);
+               kdio_printf(iocom, 5,
+                           "kdmsg_state_cleanuptx: state=%p "
+                           "executing deferred abort\n",
+                           state);
                state->flags &= ~KDMSG_STATE_ABORTING;
                kdmsg_state_abort(state);
        }
@@ -1632,7 +1712,7 @@ _kdmsg_state_hold(kdmsg_state_t *state KDMSG_DEBUG_ARGS)
 {
        atomic_add_int(&state->refs, 1);
 #if KDMSG_DEBUG
-       kprintf("state %p +%d\t%s:%d\n", state, state->refs, file, line);
+       kd_printf(4, "state %p +%d\t%s:%d\n", state, state->refs, file, line);
 #endif
 }
 
@@ -1642,7 +1722,7 @@ _kdmsg_state_drop(kdmsg_state_t *state KDMSG_DEBUG_ARGS)
 {
        KKASSERT(state->refs > 0);
 #if KDMSG_DEBUG
-       kprintf("state %p -%d\t%s:%d\n", state, state->refs, file, line);
+       kd_printf(4, "state %p -%d\t%s:%d\n", state, state->refs, file, line);
 #endif
        if (atomic_fetchadd_int(&state->refs, -1) == 1)
                kdmsg_state_free(state);
@@ -1817,9 +1897,16 @@ void
 kdmsg_msg_write(kdmsg_msg_t *msg)
 {
        kdmsg_iocom_t *iocom = msg->state->iocom;
-       kdmsg_state_t *state;
 
        lockmgr(&iocom->msglk, LK_EXCLUSIVE);
+       kdmsg_msg_write_locked(iocom, msg);
+       lockmgr(&iocom->msglk, LK_RELEASE);
+}
+
+static void
+kdmsg_msg_write_locked(kdmsg_iocom_t *iocom, kdmsg_msg_t *msg)
+{
+       kdmsg_state_t *state;
 
        if (msg->state) {
                /*
@@ -1886,18 +1973,18 @@ kdmsg_msg_write(kdmsg_msg_t *msg)
                    (state->parent->txcmd & DMSGF_DELETE) ||
                    (state->parent->flags & KDMSG_STATE_DYING)) {
 #endif
-                       kprintf("kdmsg_msg_write: Write to dying circuit "
-                               "state=%p "
-                               "ptxcmd=%08x prxcmd=%08x flags=%08x\n",
-                               state,
-                               state->parent->rxcmd,
-                               state->parent->txcmd,
-                               state->parent->flags);
+                       kdio_printf(iocom, 4,
+                                   "kdmsg_msg_write: Write to dying circuit "
+                                   "state=%p "
+                                   "ptxcmd=%08x prxcmd=%08x flags=%08x\n",
+                                   state,
+                                   state->parent->rxcmd,
+                                   state->parent->txcmd,
+                                   state->parent->flags);
                        kdmsg_state_hold(state);
                        kdmsg_state_msgtx(msg);
                        kdmsg_state_cleanuptx(msg);
                        kdmsg_state_drop(state);
-                       lockmgr(&iocom->msglk, LK_RELEASE);
                        return;
                }
        }
@@ -1927,8 +2014,6 @@ kdmsg_msg_write(kdmsg_msg_t *msg)
                                 KDMSG_CLUSTERCTL_SLEEPING);
                wakeup(&iocom->msg_ctl);
        }
-
-       lockmgr(&iocom->msglk, LK_RELEASE);
 }
 
 /*