* 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().
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);
return 0;
fail:
- if (DMsgDebugOpt)
- fprintf(stderr, "Error during _gcm_init\n");
+ dm_printf(1, "%s\n", "Error during _gcm_init");
return -1;
}
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;
}
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;
}
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);
}
}
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) {
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;
}
}
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;
}
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);
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);
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 {
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)
}
}
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;
}
}
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;
}
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;
}
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);
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
}
}
(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 */
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
}
}
#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 *
***************************************************************************
* 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 |
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);
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);
}
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;
}
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;
}
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;
* 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);
*
* 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);
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;
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;
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
*/
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);
* 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;
}
* 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) {
* 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;
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;
}
* 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)
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);
}
/*
* 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;
}
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) {
* 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;
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);
}
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);
}
* 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;
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);
}
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);
}
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;
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);
}
#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:
#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
rmsg->aux_data = lmsg->aux_data;
lmsg->aux_data = NULL;
- /*
- fprintf(stderr, "RELAY %08x\n", rmsg->any.head.cmd);
- */
dmsg_msg_write(rmsg);
}
*/
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);
}
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);
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);
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 */
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,
* 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),
* 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);
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);
* 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;
}
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);
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);
/*
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.
*
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,
*/
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;
}
done:
pthread_mutex_unlock(&cluster_mtx);
- fprintf(stderr, "findspan: %p\n", state);
+ dm_printf(8, "findspan: %p\n", state);
return state;
}
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 {
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);
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)
* 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;
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 {
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;
}
* 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)
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);
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) {
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)
{
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;
}
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
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;
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");
/*
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) {
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
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);
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);
}
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) {
* 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) {
}
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:
* 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
* 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:
/*
*/
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:
/*
* 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;
}
* 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.
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));
tsleep(sc, 0, "xarace", hz / 10);
goto again;
}
+ if (sc->terminating) {
+ lockmgr(&xdisk_lk, LK_RELEASE);
+ return ENXIO; /* raced destruction */
+ }
sc->serializing = 1;
/*
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);
/*
* 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)
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);
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)
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) {
#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);
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 */
+ }
}
/*
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;
}
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;
}
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;
}
}
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)
}
}
- 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
* 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);
}
}
*/
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;
* 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);
}
* 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;
}
&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;
}
*/
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;
*/
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;
* 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;
}
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;
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;
* 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;
kdmsg_autorxmsg(kdmsg_msg_t *msg)
{
kdmsg_iocom_t *iocom = msg->state->iocom;
+ kdmsg_msg_t *rep;
int error = 0;
uint32_t cmd;
}
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:
/*
*/
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);
}
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;
}
* (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)
(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);
}
/*
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);
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;
* 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;
}
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;
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;
* 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);
*/
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);
}
{
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
}
{
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);
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) {
/*
(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;
}
}
KDMSG_CLUSTERCTL_SLEEPING);
wakeup(&iocom->msg_ctl);
}
-
- lockmgr(&iocom->msglk, LK_RELEASE);
}
/*
tuxillo's projects / dragonfly.git / commitdiff