From d07ade8014628930057f5398fc26b06a527bb4d0 Mon Sep 17 00:00:00 2001 From: "Luke T. Shumaker" Date: Tue, 12 Nov 2024 16:29:37 -0700 Subject: w5500: Add DEBUG logging --- libhw/w5500.c | 132 +++++++++++++++++++++++++++++++++++++++++++++++----------- 1 file changed, 107 insertions(+), 25 deletions(-) (limited to 'libhw/w5500.c') 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 /* for PRIu{n} */ + /* TODO: Write a to avoid w5500.c being * pico-sdk-specific. */ #include /* pico-sdk:hardware_gpio */ @@ -77,7 +79,7 @@ #include /* for sleep_*() */ #define LOG_NAME W5500 -#include /* for errorf() */ +#include /* for errorf(), debugf(), const_byte_str() */ #define IMPLEMENTATION_FOR_LIBHW_W5500_H YES #include @@ -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); -- cgit v1.2.3-2-g168b