w5500: Add DEBUG logging

1 files changed, 107 insertions, 25 deletions

diff --git a/libhw/w5500.c b/libhw/w5500.c
index c1607f1..e675ae9 100644
--- a/libhw/w5500.c
+++ b/libhw/w5500.c
@@ -67,6 +67,8 @@
  * SPDX-License-Identifier: MIT
  */
 
+#include <inttypes.h> /* for PRIu{n} */
+
 /* TODO: Write a <libhw/generic/gpio.h> to avoid w5500.c being
  * pico-sdk-specific.  */
 #include <hardware/gpio.h> /* pico-sdk:hardware_gpio */
@@ -77,7 +79,7 @@
 #include <libhw/generic/alarmclock.h> /* for sleep_*() */
 
 #define LOG_NAME W5500
-#include <libmisc/log.h> /* for errorf() */
+#include <libmisc/log.h> /* for errorf(), debugf(), const_byte_str() */
 
 #define IMPLEMENTATION_FOR_LIBHW_W5500_H YES
 #include <libhw/w5500.h>
@@ -88,26 +90,43 @@
 
 #include "config.h"
 
-/* These are the default values of the Linux kernel's
- * net.ipv4.ip_local_port_range, so I figure they're probably good
- * values to use.  */
 #ifndef CONFIG_W5500_LOCAL_PORT_MIN
 	#error config.h must define CONFIG_W5500_LOCAL_PORT_MIN
 #endif
-
 #ifndef CONFIG_W5500_LOCAL_PORT_MAX
 	#error config.h must define CONFIG_W5500_LOCAL_PORT_MAX
 #endif
-
 #ifndef CONFIG_W5500_NUM
 	#error config.h must define CONFIG_W5500_NUM
 #endif
+#ifndef CONFIG_W5500_DEBUG
+	#error config.h must define CONFIG_W5500_DEBUG
+#endif
 
 /* C language *****************************************************************/
 
 #define UNUSED(name)
 #define ARRAY_LEN(ary) (sizeof(ary)/sizeof((ary)[0]))
 
+static const char *w5500_state_str(uint8_t state) {
+	switch (state) {
+	case STATE_CLOSED:          return "STATE_CLOSED";
+	case STATE_TCP_INIT:        return "STATE_TCP_INIT";
+	case STATE_TCP_LISTEN:      return "STATE_TCP_LISTEN";
+	case STATE_TCP_SYNSENT:     return "STATE_TCP_SYNSENT";
+	case STATE_TCP_SYNRECV:     return "STATE_TCP_SYNRECV";
+	case STATE_TCP_ESTABLISHED: return "STATE_TCP_ESTABLISHED";
+	case STATE_TCP_FIN_WAIT:    return "STATE_TCP_FIN_WAIT";
+	case STATE_TCP_CLOSING:     return "STATE_TCP_CLOSING";
+	case STATE_TCP_TIME_WAIT:   return "STATE_TCP_TIME_WAIT";
+	case STATE_TCP_CLOSE_WAIT:  return "STATE_TCP_CLOSE_WAIT";
+	case STATE_TCP_LAST_ACK:    return "STATE_TCP_LAST_ACK";
+	case STATE_UDP:             return "STATE_UDP";
+	case STATE_MACRAW:          return "STATE_MACRAW";
+	default:                    return const_byte_str(state);
+	}
+}
+
 /* vtables ********************************************************************/
 
 /* iface */
@@ -207,7 +226,10 @@ static COROUTINE w5500_irq_cr(void *_chip) {
 
 	for (;;) {
 		while (!gpio_get(chip->pin_intr)) {
-			if (w5500ll_read_common_reg(chip->spidev, chip_interrupt))
+			debugf("w5500_irq_cr(): gpio low");
+
+			uint8_t chipintr = w5500ll_read_common_reg(chip->spidev, chip_interrupt);
+			if (chipintr)
 				w5500ll_write_common_reg(chip->spidev, chip_interrupt, 0xFF);
 
 			uint8_t sockmask = w5500ll_read_common_reg(chip->spidev, sock_interrupt);
@@ -226,12 +248,18 @@ static COROUTINE w5500_irq_cr(void *_chip) {
 						send_bits   = sockintr & (SOCKINTR_SEND_OK|SOCKINTR_SEND_TIMEOUT),
 						recv_bits   = sockintr & (SOCKINTR_RECV_DAT|SOCKINTR_RECV_FIN);
 
-					if (listen_bits)
+					if (listen_bits) {
+						debugf("w5500_irq_cr(): signal sock[%"PRIu8"]->listen_sema", socknum);
 						cr_sema_signal(&socket->listen_sema);
-					if (recv_bits)
+					}
+					if (recv_bits) {
+						debugf("w5500_irq_cr(): signal sock[%"PRIu8"]->read_sema", socknum);
 						cr_sema_signal(&socket->read_sema);
-					if (send_bits)
+					}
+					if (send_bits) {
+						debugf("w5500_irq_cr(): signal sock[%"PRIu8"]->write_ch", socknum);
 						_w5500_sockintr_ch_send(&socket->write_ch, send_bits);
+					}
 					break;
 				}
 
@@ -239,6 +267,7 @@ static COROUTINE w5500_irq_cr(void *_chip) {
 			}
 		}
 		cr_sema_wait(&chip->intr);
+		debugf("w5500_irq_cr(): sema signalled");
 	}
 
 	cr_end();
@@ -296,6 +325,7 @@ static inline void w5500_socket_close(struct _w5500_socket *socket) {
 static struct w5500 *w5500_chips[CONFIG_W5500_NUM] = {0};
 
 static void w5500_intrhandler(uint gpio, uint32_t UNUSED(event_mask)) {
+	debugf("w5500_intrhandler(): interrupt on pin %u", gpio);
 	for (size_t i = 0; i < ARRAY_LEN(w5500_chips); i++)
 		if (w5500_chips[i] && w5500_chips[i]->pin_intr == gpio)
 			cr_sema_signal_from_intrhandler(&w5500_chips[i]->intr);
@@ -328,8 +358,8 @@ void _w5500_init(struct w5500 *chip,
 			.socknum = i,
 			/* mutable */
 			.next_free = (i + 1 < 8) ? &chip->sockets[i+1] : NULL,
-			/* the rest of the mutable members get
-			 * initialized to the zero values */
+			/* The rest of the mutable members get
+			 * initialized to the zero values.  */
 		};
 	}
 
@@ -361,7 +391,7 @@ void _w5500_init(struct w5500 *chip,
 
 /* chip methods ***************************************************************/
 
-static inline void w5500_post_reset(struct w5500 *chip) {
+static void w5500_post_reset(struct w5500 *chip) {
 	/* The W5500 does not have a built-in MAC address, we must
 	 * provide one.  */
 	w5500ll_write_common_reg(chip->spidev, eth_addr, chip->hwaddr);
@@ -426,7 +456,7 @@ static struct net_eth_addr w5500_if_hwaddr(implements_net_iface *_chip) {
 	return chip->hwaddr;
 }
 
-static void w5500_if_up(implements_net_iface *_chip, struct net_iface_config cfg) {
+static void _w5500_if_up(implements_net_iface *_chip, struct net_iface_config cfg) {
 	struct w5500 *chip = VCALL_SELF(struct w5500, implements_net_iface, _chip);
 	assert(chip);
 
@@ -435,8 +465,17 @@ static void w5500_if_up(implements_net_iface *_chip, struct net_iface_config cfg
 	w5500ll_write_common_reg(chip->spidev, ip_addr, cfg.addr);
 }
 
+static void w5500_if_up(implements_net_iface *_chip, struct net_iface_config cfg) {
+	debugf("if_up()");
+	debugf(":: addr         = "PRI_net_ip4_addr, ARG_net_ip4_addr(cfg.addr));
+	debugf(":: gateway_addr = "PRI_net_ip4_addr, ARG_net_ip4_addr(cfg.gateway_addr));
+	debugf(":: subnet_mask  = "PRI_net_ip4_addr, ARG_net_ip4_addr(cfg.subnet_mask));
+	_w5500_if_up(_chip, cfg);
+}
+
 static void w5500_if_down(implements_net_iface *_chip) {
-	w5500_if_up(_chip, (struct net_iface_config){0});
+	debugf("if_down()");
+	_w5500_if_up(_chip, (struct net_iface_config){0});
 }
 
 static implements_net_stream_listener *w5500_if_tcp_listen(implements_net_iface *_chip, uint16_t local_port) {
@@ -444,8 +483,11 @@ static implements_net_stream_listener *w5500_if_tcp_listen(implements_net_iface
 	assert(chip);
 
 	struct _w5500_socket *sock = w5500_alloc_socket(chip);
-	if (!sock)
+	if (!sock) {
+		debugf("tcp_listen() => no sock");
 		return NULL;
+	}
+	debugf("tcp_listen() => sock[%"PRIu8"]", sock->socknum);
 
 	if (!local_port)
 		local_port = w5500_alloc_local_port(chip);
@@ -468,9 +510,12 @@ static implements_net_stream_conn *w5500_if_tcp_dial(implements_net_iface *_chip
 	assert(port);
 
 	struct _w5500_socket *socket = w5500_alloc_socket(chip);
-	if (!socket)
+	if (!socket) {
+		debugf("tcp_dial() => no sock");
 		return NULL;
+	}
 	uint8_t socknum = socket->socknum;
+	debugf("tcp_dial() => sock[%"PRIu8"]", socknum);
 
 	uint16_t local_port = w5500_alloc_local_port(chip);
 
@@ -495,6 +540,7 @@ static implements_net_stream_conn *w5500_if_tcp_dial(implements_net_iface *_chip
 	w5500_socket_cmd(socket, CMD_CONNECT);
 	for (;;) {
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
+		debugf("tcp_dial(): state=%s", w5500_state_str(state));
 		switch (state) {
 		case STATE_TCP_SYNSENT:
 			cr_yield();
@@ -507,14 +553,17 @@ static implements_net_stream_conn *w5500_if_tcp_dial(implements_net_iface *_chip
 	}
 }
 
-implements_net_packet_conn *w5500_if_udp_conn(implements_net_iface *_chip, uint16_t local_port) {
+static implements_net_packet_conn *w5500_if_udp_conn(implements_net_iface *_chip, uint16_t local_port) {
 	struct w5500 *chip = VCALL_SELF(struct w5500, implements_net_iface, _chip);
 	assert(chip);
 
 	struct _w5500_socket *socket = w5500_alloc_socket(chip);
-	if (!socket)
+	if (!socket) {
+		debugf("udp_conn() => no sock");
 		return NULL;
+	}
 	uint8_t socknum = socket->socknum;
+	debugf("udp_conn() => sock[%"PRIu8"]", socknum);
 
 	if (!local_port)
 		local_port = w5500_alloc_local_port(chip);
@@ -541,8 +590,10 @@ static implements_net_stream_conn *w5500_tcplist_accept(implements_net_stream_li
 	ASSERT_SELF(stream_listener, TCP);
 
  restart:
-	if (!socket->list_open)
+	if (!socket->list_open) {
+		debugf("tcp_listener.accept() => already closed");
 		return NULL;
+	}
 
 	/* Mimics socket.c:socket().  */
 	w5500_socket_close(socket);
@@ -556,6 +607,7 @@ static implements_net_stream_conn *w5500_tcplist_accept(implements_net_stream_li
 	w5500_socket_cmd(socket, CMD_LISTEN);
 	for (;;) {
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
+		debugf("tcp_listener.accept() => state=%s", w5500_state_str(state));
 		switch (state) {
 		case STATE_TCP_LISTEN:
 		case STATE_TCP_SYNRECV:
@@ -574,6 +626,7 @@ static implements_net_stream_conn *w5500_tcplist_accept(implements_net_stream_li
 }
 
 static int w5500_tcplist_close(implements_net_stream_listener *_socket) {
+	debugf("tcp_listener.close()");
 	ASSERT_SELF(stream_listener, TCP);
 
 	socket->list_open = false;
@@ -584,6 +637,7 @@ static int w5500_tcplist_close(implements_net_stream_listener *_socket) {
 /* tcp_conn methods ***********************************************************/
 
 static ssize_t w5500_tcp_write(implements_net_stream_conn *_socket, void *buf, size_t count) {
+	debugf("tcp_conn.write(%zu)", count);
 	ASSERT_SELF(stream_conn, TCP);
 	assert(buf);
 	assert(count);
@@ -610,11 +664,15 @@ static ssize_t w5500_tcp_write(implements_net_stream_conn *_socket, void *buf, s
 
 	size_t done = 0;
 	while (done < count) {
-		if (!socket->write_open)
+		if (!socket->write_open) {
+			debugf(" => soft closed");
 			return -NET_ECLOSED;
+		}
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
-		if (state != STATE_TCP_ESTABLISHED && state != STATE_TCP_CLOSE_WAIT)
+		if (state != STATE_TCP_ESTABLISHED && state != STATE_TCP_CLOSE_WAIT) {
+			debugf(" => hard closed");
 			return -NET_ECLOSED;
+		}
 
 		uint16_t freesize = uint16be_unmarshal(w5500ll_read_sock_reg(chip->spidev, socknum, tx_free_size));
 		if (freesize < count-done && freesize < min_free_space) {
@@ -634,9 +692,11 @@ static ssize_t w5500_tcp_write(implements_net_stream_conn *_socket, void *buf, s
 		w5500_socket_cmd(socket, CMD_SEND);
 		switch (_w5500_sockintr_ch_recv(&socket->write_ch)) {
 		case SOCKINTR_SEND_OK:
+			debugf(" => sent %zu", freesize);
 			done += freesize;
 			break;
 		case SOCKINTR_SEND_TIMEOUT:
+			debugf(" => ACK timeout");
 			return -NET_EACK_TIMEOUT;
 		case SOCKINTR_SEND_OK|SOCKINTR_SEND_TIMEOUT:
 			assert_notreached("send both OK and timed out?");
@@ -644,10 +704,12 @@ static ssize_t w5500_tcp_write(implements_net_stream_conn *_socket, void *buf, s
 			assert_notreached("invalid write_ch bits");
 		}
 	}
+	debugf(" => send finished");
 	return done;
 }
 
 static void w5500_tcp_set_read_deadline(implements_net_stream_conn *_socket, uint64_t ns) {
+	debugf("tcp_conn.set_read_deadline(%"PRIu64")", ns);
 	ASSERT_SELF(stream_conn, TCP);
 	socket->read_deadline_ns = ns;
 }
@@ -658,6 +720,7 @@ static void w5500_tcp_alarm_handler(void *_arg) {
 }
 
 static ssize_t w5500_tcp_read(implements_net_stream_conn *_socket, void *buf, size_t count) {
+	debugf("tcp_conn.read()");
 	ASSERT_SELF(stream_conn, TCP);
 	assert(buf);
 	assert(count);
@@ -674,10 +737,12 @@ static ssize_t w5500_tcp_read(implements_net_stream_conn *_socket, void *buf, si
 	for (;;) {
 		if (!socket->read_open) {
 			VCALL(bootclock, del_trigger, &trigger);
+			debugf(" => soft closed");
 			return -NET_ECLOSED;
 		}
 		if (socket->read_deadline_ns && socket->read_deadline_ns <= VCALL(bootclock, get_time_ns)) {
 			VCALL(bootclock, del_trigger, &trigger);
+			debugf(" => recv timeout");
 			return -NET_ERECV_TIMEOUT;
 		}
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
@@ -688,6 +753,7 @@ static ssize_t w5500_tcp_read(implements_net_stream_conn *_socket, void *buf, si
 			break; /* OK */
 		default:
 			VCALL(bootclock, del_trigger, &trigger);
+			debugf(" => hard closed");
 			return -NET_ECLOSED;
 		}
 
@@ -697,12 +763,14 @@ static ssize_t w5500_tcp_read(implements_net_stream_conn *_socket, void *buf, si
 			break;
 		if (state == STATE_TCP_CLOSE_WAIT) {
 			VCALL(bootclock, del_trigger, &trigger);
-			return 0; /* EOF */
+			debugf(" => EOF");
+			return 0;
 		}
 
 		cr_sema_wait(&socket->read_sema);
 	}
 	assert(avail);
+	debugf(" => received %"PRIu16" bytes", avail);
 	uint16_t ptr = uint16be_unmarshal(w5500ll_read_sock_reg(chip->spidev, socknum, rx_read_pointer));
 	/* Read the data.  */
 	if ((size_t)avail > count)
@@ -717,6 +785,7 @@ static ssize_t w5500_tcp_read(implements_net_stream_conn *_socket, void *buf, si
 }
 
 static int w5500_tcp_close(implements_net_stream_conn *_socket, bool rd, bool wr) {
+	debugf("tcp_conn.close(rd=%s, wr=%s)", rd ? "true" : "false", wr ? "true" : "false");
 	ASSERT_SELF(stream_conn, TCP);
 
 	if (rd)
@@ -748,18 +817,23 @@ static int w5500_tcp_close(implements_net_stream_conn *_socket, bool rd, bool wr
 
 static ssize_t w5500_udp_sendto(implements_net_packet_conn *_socket, void *buf, size_t count,
                                 struct net_ip4_addr node, uint16_t port) {
+	debugf("udp_conn.sendto()");
 	ASSERT_SELF(packet_conn, UDP);
 	assert(buf);
 	assert(count);
 
 	uint16_t bufsize = ((uint16_t)w5500ll_read_sock_reg(chip->spidev, socknum, tx_buf_size))*1024;
-	if (count > bufsize)
+	if (count > bufsize) {
+		debugf(" => msg too large");
 		return -NET_EMSGSIZE;
+	}
 
 	for (;;) {
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
-		if (state != STATE_UDP)
+		if (state != STATE_UDP) {
+			debugf(" => closed");
 			return -NET_ECLOSED;
+		}
 
 		uint16_t freesize = uint16be_unmarshal(w5500ll_read_sock_reg(chip->spidev, socknum, tx_free_size));
 		if (freesize >= count)
@@ -782,8 +856,10 @@ static ssize_t w5500_udp_sendto(implements_net_packet_conn *_socket, void *buf,
 
 	switch (_w5500_sockintr_ch_recv(&socket->write_ch)) {
 	case SOCKINTR_SEND_OK:
+		debugf(" => sent");
 		return count;
 	case SOCKINTR_SEND_TIMEOUT:
+		debugf(" => ARP timeout");
 		return -NET_EARP_TIMEOUT;
 	case SOCKINTR_SEND_OK|SOCKINTR_SEND_TIMEOUT:
 		assert_notreached("send both OK and timed out?");
@@ -793,6 +869,7 @@ static ssize_t w5500_udp_sendto(implements_net_packet_conn *_socket, void *buf,
 }
 
 static void w5500_udp_set_read_deadline(implements_net_packet_conn *_socket, uint64_t ns) {
+	debugf("udp_conn.set_read_deadline(%"PRIu64")", ns);
 	ASSERT_SELF(packet_conn, UDP);
 	socket->read_deadline_ns = ns;
 }
@@ -804,6 +881,7 @@ static void w5500_udp_alarm_handler(void *_arg) {
 
 static ssize_t w5500_udp_recvfrom(implements_net_packet_conn *_socket, void *buf, size_t count,
                                   struct net_ip4_addr *ret_node, uint16_t *ret_port) {
+	debugf("udp_conn.recvfrom()");
 	ASSERT_SELF(packet_conn, UDP);
 	assert(buf);
 	assert(count);
@@ -820,11 +898,13 @@ static ssize_t w5500_udp_recvfrom(implements_net_packet_conn *_socket, void *buf
 	for (;;) {
 		if (socket->read_deadline_ns && socket->read_deadline_ns <= VCALL(bootclock, get_time_ns)) {
 			VCALL(bootclock, del_trigger, &trigger);
+			debugf(" => recv timeout");
 			return -NET_ERECV_TIMEOUT;
 		}
 		uint8_t state = w5500ll_read_sock_reg(chip->spidev, socknum, state);
 		if (state != STATE_UDP) {
 			VCALL(bootclock, del_trigger, &trigger);
+			debugf(" => hard closed");
 			return -NET_ECLOSED;
 		}
 
@@ -851,6 +931,7 @@ static ssize_t w5500_udp_recvfrom(implements_net_packet_conn *_socket, void *buf
 	if (ret_port)
 		*ret_port = uint16be_decode(&hdr[4]);
 	uint16_t len = uint16be_decode(&hdr[6]);
+	debugf(" => received %"PRIu16" bytes%s", len, len < avail-8 ? " (plus more messages)" : "");
 	/* Now read the actual data.  */
 	if (count > len)
 		count = len;
@@ -864,6 +945,7 @@ static ssize_t w5500_udp_recvfrom(implements_net_packet_conn *_socket, void *buf
 }
 
 static int w5500_udp_close(implements_net_packet_conn *_socket) {
+	debugf("udp_conn.close()");
 	ASSERT_SELF(packet_conn, UDP);
 
 	w5500_socket_close(socket);