diff options
author | Andreas Eversberg <jolly@eversberg.eu> | 2024-02-23 14:15:13 +0100 |
---|---|---|
committer | Andreas Eversberg <jolly@eversberg.eu> | 2024-02-23 14:15:13 +0100 |
commit | 74597c416fabd44a81efa829f26755ca445d79c9 (patch) | |
tree | 7f6d794c6c66804bc3184473564b6c93e7eb69ae | |
parent | 2bafb952fb132889c179c89fdc961058af93d398 (diff) |
debugjolly/work
Change-Id: Ic21d1617ec4d8251ae87ad9abaacde67f3738748
-rw-r--r-- | src/core/osmo_io.c | 12 | ||||
-rw-r--r-- | src/core/osmo_io_poll.c | 23 | ||||
-rw-r--r-- | src/core/osmo_io_uring.c | 34 | ||||
-rw-r--r-- | src/core/socket.c | 11 |
4 files changed, 71 insertions, 9 deletions
diff --git a/src/core/osmo_io.c b/src/core/osmo_io.c index 34d4b00c..d7d6e674 100644 --- a/src/core/osmo_io.c +++ b/src/core/osmo_io.c @@ -307,14 +307,17 @@ void iofd_handle_segmented_read(struct osmo_io_fd *iofd, struct msgb *msg, int r struct msgb *pending = NULL; if (rc <= 0) { + LOGPIO(iofd, LOGL_ERROR, "error read, so forward rc=%d\n", rc); iofd->io_ops.read_cb(iofd, rc, msg); return; } do { res = iofd_handle_segmentation(iofd, msg, &pending); - if (res != IOFD_SEG_ACT_DEFER || rc < 0) + if (res != IOFD_SEG_ACT_DEFER || rc < 0) { + LOGPIO(iofd, LOGL_ERROR, "JOLLY now doing segmented read\n"); iofd->io_ops.read_cb(iofd, rc, msg); + } if (res == IOFD_SEG_ACT_HANDLE_MORE) msg = pending; } while (res == IOFD_SEG_ACT_HANDLE_MORE); @@ -334,13 +337,16 @@ void iofd_handle_recv(struct osmo_io_fd *iofd, struct msgb *msg, int rc, struct talloc_steal(iofd->msgb_alloc.ctx, msg); switch (iofd->mode) { case OSMO_IO_FD_MODE_READ_WRITE: + LOGPIO(iofd, LOGL_ERROR, "fd mode\n"); iofd_handle_segmented_read(iofd, msg, rc); break; case OSMO_IO_FD_MODE_RECVFROM_SENDTO: + LOGPIO(iofd, LOGL_ERROR, "fd mode to/from\n"); iofd->io_ops.recvfrom_cb(iofd, rc, msg, &hdr->osa); break; #ifdef HAVE_LIBSCTP case OSMO_IO_FD_MODE_SCTP_RECVMSG_SEND: + LOGPIO(iofd, LOGL_ERROR, "fd mode sctp\n"); msgb_sctp_msg_flags(msg) = 0; if (hdr->hdr.msg_flags & MSG_NOTIFICATION) { msgb_sctp_msg_flags(msg) = OSMO_STREAM_SCTP_MSG_FLAGS_NOTIFICATION; @@ -358,6 +364,7 @@ void iofd_handle_recv(struct osmo_io_fd *iofd, struct msgb *msg, int rc, struct if (rc > 0 && !cmsg) LOGPIO(iofd, LOGL_ERROR, "sctp_recvmsg without SNDRCV cmsg?!?\n"); } + LOGPIO(iofd, LOGL_ERROR, "JOLLY now doing normal read rc=%d\n", rc); iofd->io_ops.read_cb(iofd, rc, msg); break; #endif @@ -598,6 +605,7 @@ struct osmo_io_fd *osmo_iofd_setup(const void *ctx, int fd, const char *name, en } iofd = talloc_zero(ctx, struct osmo_io_fd); +printf("alloc=%p\n", iofd); if (!iofd) return NULL; @@ -621,6 +629,7 @@ struct osmo_io_fd *osmo_iofd_setup(const void *ctx, int fd, const char *name, en iofd->tx_queue.max_length = 32; INIT_LLIST_HEAD(&iofd->tx_queue.msg_queue); + LOGPIO(iofd, LOGL_INFO, "iofd bekommt nun fd=%d\n", iofd->fd); return iofd; } @@ -701,6 +710,7 @@ void osmo_iofd_free(struct osmo_io_fd *iofd) if (!iofd) return; +printf("free=%p\n", iofd); osmo_iofd_close(iofd); if (!IOFD_FLAG_ISSET(iofd, IOFD_FLAG_IN_CALLBACK)) { diff --git a/src/core/osmo_io_poll.c b/src/core/osmo_io_poll.c index aea0bbc3..84528cf8 100644 --- a/src/core/osmo_io_poll.c +++ b/src/core/osmo_io_poll.c @@ -47,7 +47,9 @@ static void iofd_poll_ofd_cb_recvmsg_sendmsg(struct osmo_fd *ofd, unsigned int w struct msgb *msg; int rc, flags = 0; + LOGPIO(iofd, LOGL_INFO, "POLL: got event\n"); if (what & OSMO_FD_READ) { + LOGPIO(iofd, LOGL_INFO, "POLL: got read event\n"); struct iofd_msghdr hdr; msg = iofd_msgb_pending_or_alloc(iofd); if (!msg) { @@ -78,10 +80,13 @@ static void iofd_poll_ofd_cb_recvmsg_sendmsg(struct osmo_fd *ofd, unsigned int w iofd_handle_recv(iofd, msg, (rc < 0 && errno > 0) ? -errno : rc, &hdr); } - if (IOFD_FLAG_ISSET(iofd, IOFD_FLAG_CLOSED)) + if (IOFD_FLAG_ISSET(iofd, IOFD_FLAG_CLOSED)) { + LOGPIO(iofd, LOGL_INFO, "POLL: got event, but close flag is set\n"); return; + } if (what & OSMO_FD_WRITE) { + LOGPIO(iofd, LOGL_INFO, "POLL: got write event\n"); struct iofd_msghdr *msghdr = iofd_txqueue_dequeue(iofd); if (msghdr) { rc = sendmsg(ofd->fd, &msghdr->hdr, msghdr->flags); @@ -125,8 +130,11 @@ static int iofd_poll_register(struct osmo_io_fd *iofd) struct osmo_fd *ofd = &iofd->u.poll.ofd; int rc; - if (IOFD_FLAG_ISSET(iofd, IOFD_FLAG_FD_REGISTERED)) + if (IOFD_FLAG_ISSET(iofd, IOFD_FLAG_FD_REGISTERED)) { + LOGPIO(iofd, LOGL_INFO, "POLL already registered, ignore this one.\n"); return 0; + } + LOGPIO(iofd, LOGL_INFO, "POLL: register our fd=%d, iofd=%p\n", iofd->fd, iofd); osmo_fd_setup(ofd, iofd->fd, 0, &iofd_poll_ofd_cb_dispatch, iofd, 0); rc = osmo_fd_register(ofd); if (!rc) @@ -138,8 +146,11 @@ static int iofd_poll_unregister(struct osmo_io_fd *iofd) { struct osmo_fd *ofd = &iofd->u.poll.ofd; - if (!IOFD_FLAG_ISSET(iofd, IOFD_FLAG_FD_REGISTERED)) + if (!IOFD_FLAG_ISSET(iofd, IOFD_FLAG_FD_REGISTERED)) { + LOGPIO(iofd, LOGL_INFO, "POLL already unregistered, ignore this one.\n"); return 0; + } + LOGPIO(iofd, LOGL_INFO, "POLL: unregister\n"); osmo_fd_unregister(ofd); IOFD_FLAG_UNSET(iofd, IOFD_FLAG_FD_REGISTERED); @@ -148,6 +159,7 @@ static int iofd_poll_unregister(struct osmo_io_fd *iofd) static int iofd_poll_close(struct osmo_io_fd *iofd) { + LOGPIO(iofd, LOGL_INFO, "POLL: close\n"); iofd_poll_unregister(iofd); osmo_fd_close(&iofd->u.poll.ofd); @@ -156,21 +168,25 @@ static int iofd_poll_close(struct osmo_io_fd *iofd) static void iofd_poll_read_enable(struct osmo_io_fd *iofd) { + LOGPIO(iofd, LOGL_INFO, "POLL: read enable\n"); osmo_fd_read_enable(&iofd->u.poll.ofd); } static void iofd_poll_read_disable(struct osmo_io_fd *iofd) { + LOGPIO(iofd, LOGL_INFO, "POLL: read disable\n"); osmo_fd_read_disable(&iofd->u.poll.ofd); } static void iofd_poll_write_enable(struct osmo_io_fd *iofd) { + LOGPIO(iofd, LOGL_INFO, "POLL: write enable\n"); osmo_fd_write_enable(&iofd->u.poll.ofd); } static void iofd_poll_write_disable(struct osmo_io_fd *iofd) { + LOGPIO(iofd, LOGL_INFO, "POLL: write disable\n"); osmo_fd_write_disable(&iofd->u.poll.ofd); } @@ -178,6 +194,7 @@ static void iofd_poll_notify_connected(struct osmo_io_fd *iofd) { int rc; + LOGPIO(iofd, LOGL_INFO, "POLL: request connect notification\n"); rc = iofd_poll_register(iofd); if (rc < 0) return; diff --git a/src/core/osmo_io_uring.c b/src/core/osmo_io_uring.c index a481cad1..ccc1ba97 100644 --- a/src/core/osmo_io_uring.c +++ b/src/core/osmo_io_uring.c @@ -121,6 +121,7 @@ static void iofd_uring_submit_recv(struct osmo_io_fd *iofd, enum iofd_msg_action LOGPIO(iofd, LOGL_ERROR, "Could not allocate msghdr for reading\n"); OSMO_ASSERT(0); } + LOGP(DLIO, LOGL_DEBUG, "neuer msghdr=%p als rx\n", msghdr); msghdr->iov[0].iov_base = msg->tail; msghdr->iov[0].iov_len = msgb_tailroom(msg); @@ -174,6 +175,8 @@ static void iofd_uring_handle_recv(struct iofd_msghdr *msghdr, int rc) struct osmo_io_fd *iofd = msghdr->iofd; struct msgb *msg = msghdr->msg; + LOGP(DLIO, LOGL_DEBUG, "%s: handle recv, rc=%d\n", iofd->name, rc); + if (rc > 0) msgb_put(msg, rc); @@ -186,6 +189,7 @@ static void iofd_uring_handle_recv(struct iofd_msghdr *msghdr, int rc) iofd->u.uring.read_msghdr = NULL; + LOGP(DLIO, LOGL_DEBUG, "free msghdr=%p\n", msghdr); iofd_msghdr_free(msghdr); } @@ -195,6 +199,7 @@ static int iofd_uring_submit_tx(struct osmo_io_fd *iofd); static void iofd_uring_handle_tx(struct iofd_msghdr *msghdr, int rc) { struct osmo_io_fd *iofd = msghdr->iofd; + LOGP(DLIO, LOGL_DEBUG, "%s: tx_completion(rc=%d, msg=%s)\n", iofd->name, rc, msghdr->msg ? msgb_hexdump(msghdr->msg) : "NULL"); /* Detach msghdr from iofd. It might get freed here or it will be freed at iofd_handle_send_completion(). * If there is pending data to send, iofd_uring_submit_tx() will attach it again. @@ -204,11 +209,11 @@ static void iofd_uring_handle_tx(struct iofd_msghdr *msghdr, int rc) iofd->u.uring.write_msghdr = NULL; if (OSMO_UNLIKELY(IOFD_FLAG_ISSET(iofd, IOFD_FLAG_CLOSED))) { + LOGP(DLIO, LOGL_DEBUG, "free msghdr=%p\n", msghdr); msgb_free(msghdr->msg); iofd_msghdr_free(msghdr); - } else { + } else iofd_handle_send_completion(iofd, rc, msghdr); - } /* submit the next to-be-transmitted message for this file descriptor */ if (iofd->u.uring.write_enabled && !IOFD_FLAG_ISSET(iofd, IOFD_FLAG_CLOSED)) @@ -219,6 +224,7 @@ static void iofd_uring_handle_tx(struct iofd_msghdr *msghdr, int rc) static void iofd_uring_handle_completion(struct iofd_msghdr *msghdr, int res) { struct osmo_io_fd *iofd = msghdr->iofd; + LOGP(DLIO, LOGL_DEBUG, "%s: %s(res=%d, action=%u)\n", iofd->name, __func__, res, msghdr->action); IOFD_FLAG_SET(iofd, IOFD_FLAG_IN_CALLBACK); @@ -226,6 +232,7 @@ static void iofd_uring_handle_completion(struct iofd_msghdr *msghdr, int res) case IOFD_ACT_READ: case IOFD_ACT_RECVFROM: case IOFD_ACT_SCTP_RECVMSG: + LOGP(DLIO, LOGL_DEBUG, "%s: %s : read action: got res=%d\n", iofd->name, __func__, res); iofd_uring_handle_recv(msghdr, res); break; case IOFD_ACT_WRITE: @@ -250,25 +257,33 @@ static void iofd_uring_cqe(struct io_uring *ring) struct io_uring_cqe *cqe; struct iofd_msghdr *msghdr; +LOGP(DLIO, LOGL_DEBUG, "bum 1\n"); while (io_uring_peek_cqe(ring, &cqe) == 0) { msghdr = io_uring_cqe_get_data(cqe); +LOGP(DLIO, LOGL_DEBUG, "bum 2 cqe returns msghdr=%p\n", msghdr); if (!msghdr) { LOGP(DLIO, LOGL_DEBUG, "Cancellation returned\n"); io_uring_cqe_seen(ring, cqe); +LOGP(DLIO, LOGL_DEBUG, "bum 3\n"); continue; } if (!msghdr->iofd) { + LOGP(DLIO, LOGL_DEBUG, "jolly free cancelled msghdr\n"); io_uring_cqe_seen(ring, cqe); + LOGP(DLIO, LOGL_DEBUG, "free msghdr=%p\n", msghdr); iofd_msghdr_free(msghdr); continue; } rc = cqe->res; /* Hand the entry back to the kernel before */ +LOGP(DLIO, LOGL_DEBUG, "bum 4 msghdr=%p\n", msghdr); io_uring_cqe_seen(ring, cqe); +LOGP(DLIO, LOGL_DEBUG, "bum 5\n"); iofd_uring_handle_completion(msghdr, rc); +LOGP(DLIO, LOGL_DEBUG, "bum 6\n"); } } @@ -357,6 +372,7 @@ static int iofd_uring_unregister(struct osmo_io_fd *iofd) static void iofd_uring_write_enable(struct osmo_io_fd *iofd) { iofd->u.uring.write_enabled = true; + LOGPIO(iofd, LOGL_DEBUG, "jolly: something enables write\n"); if (iofd->u.uring.write_msghdr) return; @@ -368,6 +384,7 @@ static void iofd_uring_write_enable(struct osmo_io_fd *iofd) if (osmo_iofd_txqueue_len(iofd) > 0) iofd_uring_submit_tx(iofd); else if (iofd->mode == OSMO_IO_FD_MODE_READ_WRITE) { + LOGP(DLIO, LOGL_DEBUG, "%s: dummy write request for detecting connection\n", iofd->name); /* Empty write request to check when the socket is connected */ struct iofd_msghdr *msghdr; struct io_uring_sqe *sqe; @@ -407,6 +424,7 @@ static void iofd_uring_write_disable(struct osmo_io_fd *iofd) static void iofd_uring_read_enable(struct osmo_io_fd *iofd) { iofd->u.uring.read_enabled = true; + LOGPIO(iofd, LOGL_DEBUG, "jolly: something enables read\n"); if (iofd->u.uring.read_msghdr) return; @@ -439,7 +457,9 @@ static int iofd_uring_close(struct osmo_io_fd *iofd) { iofd_uring_read_disable(iofd); iofd_uring_write_disable(iofd); + LOGPIO(iofd, LOGL_DEBUG, "jolly: close called\n"); iofd_uring_unregister(iofd); + return close(iofd->fd); } @@ -457,6 +477,8 @@ static int iofd_uring_connected_cb(struct osmo_fd *ofd, unsigned int what) osmo_fd_unregister(ofd); IOFD_FLAG_UNSET(iofd, IOFD_FLAG_NOTIFY_CONNECTED); + LOGPIO(iofd, LOGL_DEBUG, "jolly: (connect event)\n"); + /* Notify the application about this via a zero-length write completion call-back. */ IOFD_FLAG_SET(iofd, IOFD_FLAG_IN_CALLBACK); iofd->io_ops.write_cb(iofd, 0, NULL); @@ -475,10 +497,13 @@ static int iofd_uring_connected_cb(struct osmo_fd *ofd, unsigned int what) static void iofd_uring_notify_connected(struct osmo_io_fd *iofd) { + LOGP(DLIO, LOGL_DEBUG, "%s: %s (%d)\n", iofd->name, __func__, osmo_fd_is_registered(&iofd->u.uring.connect_ofd)); + if (iofd->mode == OSMO_IO_FD_MODE_SCTP_RECVMSG_SEND) { /* Don't call this function after enabling read or write. */ OSMO_ASSERT(!iofd->u.uring.write_enabled && !iofd->u.uring.read_enabled); + LOGP(DLIO, LOGL_DEBUG, "do the fd thing\n"); /* Use a temporary osmo_fd which we can use to notify us once the connection is established * or failed (indicated by FD becoming writable). * This is needed as (at least for SCTP sockets) one cannot submit a zero-length writev/sendmsg @@ -489,8 +514,11 @@ static void iofd_uring_notify_connected(struct osmo_io_fd *iofd) osmo_fd_register(&iofd->u.uring.connect_ofd); IOFD_FLAG_SET(iofd, IOFD_FLAG_NOTIFY_CONNECTED); } - } else + } else { + LOGP(DLIO, LOGL_DEBUG, "do the uring\n"); iofd_uring_write_enable(iofd); + } + } const struct iofd_backend_ops iofd_uring_ops = { diff --git a/src/core/socket.c b/src/core/socket.c index d36a5f42..a311c8a2 100644 --- a/src/core/socket.c +++ b/src/core/socket.c @@ -870,13 +870,17 @@ int osmo_sock_init2_multiaddr2(uint16_t family, uint16_t type, uint8_t proto, struct sockaddr_in6 addrs_buf[OSMO_SOCK_MAX_ADDRS]; char strbuf[512]; +// printf("%s(family=%u, type=%u, proto=%u, flags=0x%x)\n", __func__, family, type, proto, flags); + /* TODO: So far this function is only aimed for SCTP, but could be reused in the future for other protocols with multi-addr support */ if (proto != IPPROTO_SCTP) return -ENOTSUP; - if (pars && pars->sctp.version != 0) + if (pars && pars->sctp.version != 0) { + LOGP(DLGLOBAL, LOGL_ERROR, "illegal sctp_version\n"); return -EINVAL; + } if ((flags & (OSMO_SOCK_F_BIND | OSMO_SOCK_F_CONNECT)) == 0) { LOGP(DLGLOBAL, LOGL_ERROR, "invalid: you have to specify either " @@ -887,8 +891,11 @@ int osmo_sock_init2_multiaddr2(uint16_t family, uint16_t type, uint8_t proto, if (((flags & OSMO_SOCK_F_BIND) && !local_hosts_cnt) || ((flags & OSMO_SOCK_F_CONNECT) && !remote_hosts_cnt) || local_hosts_cnt > OSMO_SOCK_MAX_ADDRS || - remote_hosts_cnt > OSMO_SOCK_MAX_ADDRS) + remote_hosts_cnt > OSMO_SOCK_MAX_ADDRS) { + LOGP(DLGLOBAL, LOGL_ERROR, "illegal local_hosts_cnt=%zu / remote_hosts_cnt=%zu\n", + local_hosts_cnt, remote_hosts_cnt); return -EINVAL; + } /* figure out local side of socket */ if (flags & OSMO_SOCK_F_BIND) { |