debugjolly/work

Change-Id: Ic21d1617ec4d8251ae87ad9abaacde67f3738748

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) {