tcp_received() fix

2017-09-07 18:09:19 -07:00
parent e18c1ccf80
commit 4fd2db7dd6
10 changed files with 223 additions and 124 deletions
--- a/include/libzt.h
+++ b/include/libzt.h
@@ -84,10 +84,26 @@ struct zts_ifreq {

 #endif

+/****************************************************************************/
+/* Legend                                                                   */
+/****************************************************************************/
+
+/*
+	NSLWIP network_stack_lwip
+	NSPICO network_stack_pico
+	NSRXBF network_stack_pico guarded frame buffer RX
+	ZTVIRT zt_virtual_wire
+	APPFDS app_fd
+	VSRXBF app_fd TX buf
+	VSTXBF app_fd RX buf
+*/
+
 /****************************************************************************/
 /* lwIP                                                                     */
 /****************************************************************************/

+// For LWIP configuration see: include/lwipopts.h
+
 #if defined(STACK_LWIP)
 #define LWIP_APPLICATION_POLL_FREQ         2
 #define LWIP_TCP_TIMER_INTERVAL            50
--- a/include/lwipopts.h
+++ b/include/lwipopts.h
@@ -81,21 +81,27 @@
 #define LWIP_DBG_TYPES_ON               LWIP_DBG_ON

 #define ETHARP_DEBUG                    LWIP_DBG_OFF
+
+// interfaces
+#define SLIP_DEBUG                      LWIP_DBG_OFF
 #define NETIF_DEBUG                     LWIP_DBG_OFF
-#define PBUF_DEBUG                      LWIP_DBG_OFF
+// API (not used in libzt)
 #define API_LIB_DEBUG                   LWIP_DBG_OFF
 #define API_MSG_DEBUG                   LWIP_DBG_OFF
 #define SOCKETS_DEBUG                   LWIP_DBG_OFF
+// other
 #define ICMP_DEBUG                      LWIP_DBG_OFF
 #define IGMP_DEBUG                      LWIP_DBG_OFF
 #define INET_DEBUG                      LWIP_DBG_OFF
-#define IP_DEBUG                        LWIP_DBG_OFF
-#define IP_REASS_DEBUG                  LWIP_DBG_OFF
 #define RAW_DEBUG                       LWIP_DBG_OFF
+// memory
+#define PBUF_DEBUG                      LWIP_DBG_OFF
 #define MEM_DEBUG                       LWIP_DBG_OFF
 #define MEMP_DEBUG                      LWIP_DBG_OFF
+// system
 #define SYS_DEBUG                       LWIP_DBG_OFF
 #define TIMERS_DEBUG                    LWIP_DBG_OFF
+// TCP
 #define TCP_DEBUG                       LWIP_DBG_OFF
 #define TCP_INPUT_DEBUG                 LWIP_DBG_OFF
 #define TCP_FR_DEBUG                    LWIP_DBG_OFF
@@ -105,13 +111,19 @@
 #define TCP_OUTPUT_DEBUG                LWIP_DBG_OFF
 #define TCP_RST_DEBUG                   LWIP_DBG_OFF
 #define TCP_QLEN_DEBUG                  LWIP_DBG_OFF
-#define UDP_DEBUG                       LWIP_DBG_OFF
-#define TCPIP_DEBUG                     LWIP_DBG_OFF
-#define SLIP_DEBUG                      LWIP_DBG_OFF
-#define DHCP_DEBUG                      LWIP_DBG_OFF
+// IP
 #define AUTOIP_DEBUG                    LWIP_DBG_OFF
-#define DNS_DEBUG                       LWIP_DBG_OFF
+#define IP_DEBUG                        LWIP_DBG_OFF
+#define IP_REASS_DEBUG                  LWIP_DBG_OFF
 #define IP6_DEBUG                       LWIP_DBG_OFF
+// TCP/IP
+#define TCPIP_DEBUG                     LWIP_DBG_OFF
+// UDP
+#define UDP_DEBUG                       LWIP_DBG_OFF
+// services
+#define DHCP_DEBUG                      LWIP_DBG_OFF
+#define DNS_DEBUG                       LWIP_DBG_OFF
+

 #define LWIP_UDP        1
 #define LWIP_TCP        1
@@ -134,7 +146,7 @@ reason for "twice" are both the nagle algorithm and delayed ACK from the
 remote peer.
 */

-#define TCP_WND TCP_MSS*10 // max = 0xffff
+#define TCP_WND 0xffff // max = 0xffff, min = TCP_MSS*2

 //#define LWIP_NOASSERT 1
 #define TCP_LISTEN_BACKLOG   0
@@ -330,7 +342,7 @@ happening sooner than they should.
 /**
 * PBUF_POOL_SIZE: the number of buffers in the pbuf pool.
 */
-#define PBUF_POOL_SIZE                  2048 /* was 32 */
+#define PBUF_POOL_SIZE                  8000 /* was 32 */


 /*------------------------------------------------------------------------------
@@ -534,7 +546,7 @@ happening sooner than they should.
 /**
 * LWIP_STATS==1: Enable statistics collection in lwip_stats.
 */
-#define LWIP_STATS                      0
+#define LWIP_STATS                      1

 /*------------------------------------------------------------------------------
 --------------------------------- PPP Options ----------------------------------
--- a/make-liblwip.mk
+++ b/make-liblwip.mk
@@ -109,7 +109,7 @@ endif
 ifeq ($(LIBZT_IPV6),1)
 	LWIPFILES+=$(CORE6FILES)
 	CFLAGS+=-DLIBZT_IPV6=1 -DLWIP_IPV6 -DLWIP_IPV4=0 -DIPv6 
-	# -DLWIP_DEBUG=1
+	#-DLWIP_DEBUG=1
 endif

 LWIPFILESW=$(wildcard $(LWIPFILES))
--- a/src/VirtualSocket.hpp
+++ b/src/VirtualSocket.hpp
@@ -64,7 +64,7 @@ namespace ZeroTier {
 		struct pico_socket *picosock = NULL;
 #endif
 #if defined(STACK_LWIP)
-		void *pcb = NULL;
+		void *pcb = NULL; // Protocol Control Block
 #endif

 		struct sockaddr_storage local_addr; // address we've bound to locally
@@ -82,19 +82,31 @@ namespace ZeroTier {
 		std::time_t closure_ts = 0;

 		VirtualSocket() {
+
+			memset(&local_addr, 0, sizeof(sockaddr_storage));
+			memset(&peer_addr,  0, sizeof(sockaddr_storage));
+
+			// ringbuffer used for incoming and outgoing traffic between app, stack, stack drivers, and ZT
 			TXbuf = new RingBuffer<unsigned char>(ZT_TCP_TX_BUF_SZ);
 			RXbuf = new RingBuffer<unsigned char>(ZT_TCP_RX_BUF_SZ);

+			// socketpair, I/O channel between app and stack drivers
 			closure_ts = -1;
 			ZT_PHY_SOCKFD_TYPE fdpair[2];
 			if(socketpair(PF_LOCAL, SOCK_STREAM, 0, fdpair) < 0) {
 				if(errno < 0) {
-					DEBUG_ERROR("unable to create socketpair");
+					DEBUG_ERROR("unable to create socketpair, errno=%d", errno);
 					return;
 				}
 			}
 			sdk_fd = fdpair[0];
 			app_fd = fdpair[1];
+
+			// set to non-blocking since these are used as the primary I/O channel
+			if (fcntl(sdk_fd, F_SETFL, O_NONBLOCK) < 0) {
+				DEBUG_ERROR("error while setting virtual socket to NONBLOCKING. exiting", errno);
+				exit(0);
+			} 
 		}
 		~VirtualSocket() { 
 			close(app_fd);
--- a/src/VirtualTap.cpp
+++ b/src/VirtualTap.cpp
@@ -550,18 +550,24 @@ namespace ZeroTier {
 		return err;
 	}

+	// Remove VritualSocket from VirtualTap, and instruct network stacks to dismantle their
+	// respective protocol control structures
 	int VirtualTap::Close(VirtualSocket *vs) {
 		int err = 0;
 		if(!vs) {
 			DEBUG_ERROR("invalid VirtualSocket");
 			return -1;
 		}
+		removeVirtualSocket(vs);
 #if defined(STACK_PICO)
-		err = picostack->pico_Close(vs);
+		if(picostack) {
+			err = picostack->pico_Close(vs);
+		}
 #endif
 #if defined(STACK_LWIP)
-		if(lwipstack)
-			lwipstack->lwip_Close(vs);
+		if(lwipstack) {
+			err = lwipstack->lwip_Close(vs);
+		}
 #endif
 		if(vs->sock) {
 			_phy.close(vs->sock, false);
--- a/src/libzt.cpp
+++ b/src/libzt.cpp
@@ -499,7 +499,7 @@ Linux:
 */

 int zts_connect(ZT_CONNECT_SIG) {
-	DEBUG_INFO("fd=%d");
+	DEBUG_INFO("fd=%d",fd);
 	int err = errno = 0;
 	if(fd < 0 || fd >= ZT_MAX_SOCKETS) {
 		errno = EBADF;
@@ -586,7 +586,7 @@ int zts_connect(ZT_CONNECT_SIG) {
 		bool complete = false;
 		while(true)
 		{
-			// FIXME: locking and unlocking so often might cause a performance bottleneck while outgoing VirtualSockets
+			// FIXME: locking and unlocking so often might cause significant performance overhead while outgoing VirtualSockets
 			// are being established (also applies to accept())
 			nanosleep((const struct timespec[]){{0, (ZT_CONNECT_RECHECK_DELAY * 1000000)}}, NULL);
 			tap->_tcpconns_m.lock();
@@ -607,8 +607,9 @@ int zts_connect(ZT_CONNECT_SIG) {
 				}
 			}
 			tap->_tcpconns_m.unlock();
-			if(complete)
+			if(complete) {
 				break;
+			}
 		}
 	}
 	return err;
@@ -771,7 +772,12 @@ int zts_accept(ZT_ACCEPT_SIG) {
 		errno = EBADF;
 		return -1;
 	}
-	// +1 since we'll be creating a new pico_socket when we accept the VirtualSocket
+	if(addr && *addrlen <= 0) {
+		DEBUG_ERROR("invalid address length given");
+		errno = EINVAL; // TODO, not actually a valid error for this function
+		return -1;
+	}
+	// since we'll be creating a new stack socket or protocol control block when we accept the connection
 	if(!can_provision_new_socket()) {
 		DEBUG_ERROR("cannot provision additional socket due to limitation of network stack");
 		errno = EMFILE;
@@ -797,9 +803,8 @@ int zts_accept(ZT_ACCEPT_SIG) {
 		else {
 			blocking = !(f_err & O_NONBLOCK);
 		}
-
+		ZeroTier::VirtualSocket *accepted_vs;
 		if(!err) {
-			ZeroTier::VirtualSocket *accepted_vs;
 			if(!blocking) { // non-blocking
 				DEBUG_EXTRA("EWOULDBLOCK, not a real error, assuming non-blocking mode");
 				errno = EWOULDBLOCK;
@@ -819,10 +824,12 @@ int zts_accept(ZT_ACCEPT_SIG) {
 				err = accepted_vs->app_fd;
 			}
 		}
-		if(!err) {
-			// copy address into provided address buffer and len buffer
-			memcpy(addr, &(vs->peer_addr), sizeof(struct sockaddr));
-			*addrlen = sizeof(vs->peer_addr);
+		if(err > 0) {
+			if(addr && *addrlen) {
+				*addrlen = *addrlen < sizeof(accepted_vs->peer_addr) ? *addrlen : sizeof(accepted_vs->peer_addr);
+				// copy address into provided address buffer and len buffer
+				memcpy(addr, &(accepted_vs->peer_addr), *addrlen);
+			}
 		}
 	}
 	ZeroTier::_multiplexer_lock.unlock();
@@ -2221,8 +2228,16 @@ ZeroTier::VirtualSocket *get_virtual_socket(int fd)
 void del_virtual_socket(int fd)
 {
 	ZeroTier::_multiplexer_lock.lock();
-	ZeroTier::unmap.erase(fd);
-	ZeroTier::fdmap.erase(fd);
+	std::map<int, ZeroTier::VirtualSocket*>::iterator fd_iter = ZeroTier::unmap.find(fd);
+  	if(fd_iter != ZeroTier::unmap.end()) {
+  		ZeroTier::unmap.erase(fd_iter);
+  	}
+	//ZeroTier::unmap.erase(fd);
+	std::map<int, std::pair<ZeroTier::VirtualSocket*,ZeroTier::VirtualTap*>*>::iterator un_iter = ZeroTier::fdmap.find(fd);
+  	if(un_iter != ZeroTier::fdmap.end()) {
+  		ZeroTier::fdmap.erase(un_iter);
+  	}
+	//ZeroTier::fdmap.erase(fd);
 	ZeroTier::_multiplexer_lock.unlock();
 }

@@ -2236,7 +2251,11 @@ void add_unassigned_virtual_socket(int fd, ZeroTier::VirtualSocket *vs)
 void del_unassigned_virtual_socket(int fd)
 {
 	ZeroTier::_multiplexer_lock.lock();
-	ZeroTier::unmap.erase(fd);
+	std::map<int, ZeroTier::VirtualSocket*>::iterator iter = ZeroTier::unmap.find(fd);
+  	if(iter != ZeroTier::unmap.end()) {
+  		ZeroTier::unmap.erase(iter);
+  	}
+	//ZeroTier::unmap.erase(fd);
 	ZeroTier::_multiplexer_lock.unlock();
 }

@@ -2250,7 +2269,11 @@ void add_assigned_virtual_socket(ZeroTier::VirtualTap *tap, ZeroTier::VirtualSoc
 void del_assigned_virtual_socket(ZeroTier::VirtualTap *tap, ZeroTier::VirtualSocket *vs, int fd)
 {
 	ZeroTier::_multiplexer_lock.lock();
-	ZeroTier::fdmap.erase(fd);
+	std::map<int, std::pair<ZeroTier::VirtualSocket*,ZeroTier::VirtualTap*>*>::iterator iter = ZeroTier::fdmap.find(fd);
+  	if(iter != ZeroTier::fdmap.end()) {
+  		ZeroTier::fdmap.erase(iter);
+  	}
+	//ZeroTier::fdmap.erase(fd);
 	ZeroTier::_multiplexer_lock.unlock();
 }

--- a/src/lwIP.cpp
+++ b/src/lwIP.cpp
@@ -57,13 +57,11 @@ err_t lwip_eth_tx(struct netif *netif, struct pbuf *p)

 	ZeroTier::VirtualTap *tap = (ZeroTier::VirtualTap*)netif->state;
 	bufptr = buf;
-	// Copy data from each pbuf, one at a time
 	for(q = p; q != NULL; q = q->next) {
 		memcpy(bufptr, q->payload, q->len);
 		bufptr += q->len;
 		totalLength += q->len;
 	}
-	// Split ethernet header and feed into handler
 	struct eth_hdr *ethhdr;
 	ethhdr = (struct eth_hdr *)buf;

@@ -290,6 +288,7 @@ namespace ZeroTier
 		if(socket_type == SOCK_STREAM) {
 			struct tcp_pcb *new_tcp_PCB = tcp_new();
 			*pcb = new_tcp_PCB;
+			tcp_nagle_disable(new_tcp_PCB);
 			return ERR_OK;
 		}
 		if(socket_type == SOCK_DGRAM) {
@@ -455,7 +454,7 @@ namespace ZeroTier

 	int lwIP::lwip_Listen(VirtualSocket *vs, int backlog)
 	{
-		DEBUG_INFO("vs=%p", vs);
+		//DEBUG_INFO("vs=%p", vs);
 		struct tcp_pcb* listeningPCB;
 #ifdef TCP_LISTEN_BACKLOG
 		listeningPCB = tcp_listen_with_backlog((struct tcp_pcb*)vs->pcb, backlog);
@@ -466,19 +465,20 @@ namespace ZeroTier
 			vs->pcb = listeningPCB;
 			tcp_accept(listeningPCB, lwip_cb_accept); // set callback
 			tcp_arg(listeningPCB, vs);
-			//fcntl(tap->_phy.getDescriptor(vs->sock), F_SETFL, O_NONBLOCK);
 		}
 		return 0;
 	}

 	VirtualSocket* lwIP::lwip_Accept(VirtualSocket *vs)
 	{
+		//DEBUG_INFO();
 		if(!vs) {
 			DEBUG_ERROR("invalid virtual socket");
 			handle_general_failure();
 			return NULL;
 		}
 		// Retreive first of queued VirtualSockets from parent VirtualSocket
+		// TODO: check multithreaded behaviour
 		VirtualSocket *new_vs = NULL;
 		if(vs->_AcceptedConnections.size()) {
 			new_vs = vs->_AcceptedConnections.front();
@@ -538,7 +538,6 @@ namespace ZeroTier
 		}
 		if(vs->socket_type == SOCK_DGRAM) 
 		{
-			//DEBUG_ERROR("socket_type==SOCK_DGRAM");
 			// TODO: Packet re-assembly hasn't yet been tested with lwIP so UDP packets are limited to MTU-sized chunks
 			int udp_trans_len = std::min(len, (ssize_t)ZT_MAX_MTU);
 			//DEBUG_EXTRA("allocating pbuf chain of size=%d for UDP packet", udp_trans_len);
@@ -564,7 +563,6 @@ namespace ZeroTier
 		}
 		if(vs->socket_type == SOCK_STREAM) 
 		{
-			DEBUG_ERROR("socket_type==SOCK_STREAM");
 			// How much we are currently allowed to write to the VirtualSocket
 			ssize_t sndbuf = ((struct tcp_pcb*)vs->pcb)->snd_buf;
 			int err, r;
@@ -572,15 +570,16 @@ namespace ZeroTier
 				// PCB send buffer is full, turn off readability notifications for the
 				// corresponding PhySocket until lwip_cb_sent() is called and confirms that there is
 				// now space on the buffer
-				DEBUG_ERROR("lwIP stack is full, sndbuf == 0");
-				vs->tap->_phy.setNotifyReadable(vs->sock, false);
+				DEBUG_ERROR("lwIP stack is full, sndbuf==0");
+				//vs->tap->_phy.setNotifyReadable(vs->sock, false);
 				return -1;
 			}
 			int buf_w = vs->TXbuf->write((const unsigned char*)data, len);
 			if (buf_w != len) {
 				// because we checked ZT_TCP_TX_BUF_SZ above, this should not happen
 				DEBUG_ERROR("TX wrote only %d but expected to write %d", buf_w, len);
-				exit(0);
+				handle_general_failure();
+				return ZT_ERR_GENERAL_FAILURE;
 			}
 			if(vs->TXbuf->count() <= 0) {
 				return -1; // nothing to write
@@ -609,49 +608,61 @@ namespace ZeroTier

 	int lwIP::lwip_Close(VirtualSocket *vs)
 	{
-		//DEBUG_INFO();
+		int err = 0;
+		errno = 0;
 		if(vs->socket_type == SOCK_DGRAM) {
 			udp_remove((struct udp_pcb*)vs->pcb);
 		}
 		// FIXME: check if already closed? vs->TCP_pcb->state != CLOSED
 		if(vs->pcb) {
-			//DEBUG_EXTRA("vs=%p, sock=%p, PCB->state = %d", 
-			//  conn, sock, vs->TCP_pcb->state);
 			if(((struct tcp_pcb*)vs->pcb)->state == SYN_SENT /*|| vs->TCP_pcb->state == CLOSE_WAIT*/) {
 				DEBUG_EXTRA("ignoring close request. invalid PCB state for this operation. sock=%p", vs->sock);
+				// TODO: errno = ?;
 				return -1;
 			}
 			struct tcp_pcb* tpcb = (struct tcp_pcb*)vs->pcb;
 			if(tcp_close(tpcb) == ERR_OK) {
-				// Unregister callbacks for this PCB
-				tcp_arg(tpcb, NULL);
+				// unregister callbacks for this PCB
+				tcp_arg(tpcb,  NULL);
 				tcp_recv(tpcb, NULL);
-				tcp_err(tpcb, NULL);
+				tcp_err(tpcb,  NULL);
 				tcp_sent(tpcb, NULL);
 				tcp_poll(tpcb, NULL, 1);
 			}
 			else {
 				DEBUG_EXTRA("error while calling tcp_close() sock=%p", vs->sock);
+				err = -1;
+				// TODO: set errno
 			}
 		}
-		return 0;
+		return err;
 	}

 	/****************************************************************************/
 	/* Callbacks from lwIP stack                                                */
 	/****************************************************************************/

+	// write data from processed packets from the stack to the client app
+	/*
+		With the raw API, tcp_recv() sets up to receive data via a callback function. Your callback 
+		is delivered chains of pbufs as they become available. You have to manage extracting data 
+		from the pbuf chain, and don't forget to watch out for multiple pbufs in a single callback: 
+		the 'tot_len' field indicates the total length of data in the pbuf chain. You must call 
+		tcp_recved() to tell LWIP when you have processed the received data. As with the netconn API, 
+		you may receive more or less data than you want, and will have to either wait for further 
+		callbacks, or hold onto excess data for later processing.
+
+		http://lwip.wikia.com/wiki/Receiving_data_with_LWIP
+	*/
 	err_t lwIP::lwip_cb_tcp_recved(void *arg, struct tcp_pcb *PCB, struct pbuf *p, err_t err)
 	{
-		DEBUG_INFO();
+		//DEBUG_INFO();
 		VirtualSocket *vs = (VirtualSocket *)arg;
 		int tot = 0;
-
 		if(!vs) {
 			DEBUG_ERROR("no virtual socket");
 			return ERR_OK; // FIXME: Determine if this is correct behaviour expected by the stack 
 		}
-
 		struct pbuf* q = p;
 		if(p == NULL) {
 			/*
@@ -659,13 +670,10 @@ namespace ZeroTier
 				// FIXME: Implement?
 			}
 			*/
-			DEBUG_INFO("p == NULL");
-			return ERR_ABRT;
+			return ERR_ABRT; // close connection
 		}
-
 		vs->tap->_tcpconns_m.lock();
 		vs->_rx_m.lock();
-
 		// cycle through pbufs and write them to the RX buffer
 		while(p != NULL) {
 			if(p->len <= 0)
@@ -675,38 +683,51 @@ namespace ZeroTier
 			if(avail < len) {
 				DEBUG_ERROR("not enough room (%d bytes) on RX buffer", avail);
 			}
-			// get it on the buffer, fast!
+			// place new incoming data on ringbuffer before we try to send it to the app			
 			memcpy(vs->RXbuf->get_buf(), p->payload, len);
 			vs->RXbuf->produce(len);
 			p = p->next;
 			tot += len;
 		}
-		DEBUG_INFO("tot=%d", tot);
-
 		if(tot) {
+			tcp_recved(PCB, tot);
+			DEBUG_TRANS("len=%5d buf_len=%13d [NSLWIP        -->     VSRXBF]", tot, vs->RXbuf->count());
 			int w, write_attempt_sz = vs->RXbuf->count() < ZT_MAX_MTU ? vs->RXbuf->count() : ZT_MAX_MTU;
 			if((w = write(vs->sdk_fd, vs->RXbuf->get_buf(), write_attempt_sz)) < 0) {
-				perror("write");
 				DEBUG_ERROR("write(fd=%d)=%d, errno=%d", vs->sdk_fd, w, errno);
 			}
 			if(w > 0) {
-				DEBUG_INFO("write_attempt_sz=%d, w=%d", write_attempt_sz, w);
 				vs->RXbuf->consume(w);
+				if(w < write_attempt_sz) {
+					DEBUG_TRANS("len=%5d buf_len=%13d [VSRXBF        -->     APPFDS]", w, vs->RXbuf->count());
+					DEBUG_ERROR("warning, intended to write %d bytes", write_attempt_sz);
+				}
+				else {
+					DEBUG_TRANS("len=%5d buf_len=%13d [VSRXBF        -->     APPFDS]", w, vs->RXbuf->count());
+				}
 			}
-			
-			//vs->tap->_phy.setNotifyWritable(vs->sock, true);
-			//vs->tap->phyOnUnixWritable(vs->sock, NULL, true); // to app
 		}
-		
+		else {
+			DEBUG_EXTRA("warning, wrote 0 bytes");
+		}
 		vs->tap->_tcpconns_m.unlock();
 		vs->_rx_m.unlock();
-
 		pbuf_free(q);
 		return ERR_OK;
 	}

+/*
+	NSLWIP network_stack_lwip
+	NSPICO network_stack_pico
+	NSRXBF network_stack_pico guarded frame buffer RX
+	ZTVIRT zt_virtual_wire
+	APPFDS app_fd
+	VSRXBF app_fd TX buf
+	VSTXBF app_fd RX buf
+*/
 	err_t lwIP::lwip_cb_accept(void *arg, struct tcp_pcb *newPCB, err_t err)
 	{
+		//DEBUG_INFO();
 		VirtualSocket *vs = (VirtualSocket*)arg;
 		struct sockaddr_storage ss;
 #if defined(LIBZT_IPV4)
@@ -742,7 +763,7 @@ namespace ZeroTier
 	// copy processed datagram to app socket
 	void lwIP::lwip_cb_udp_recved(void * arg, struct udp_pcb * upcb, struct pbuf * p, const ip_addr_t * addr, u16_t port)
 	{
-		DEBUG_EXTRA("arg(vs)=%p, pcb=%p, port=%d)", arg, upcb, port);
+		//DEBUG_EXTRA("arg(vs)=%p, pcb=%p, port=%d)", arg, upcb, port);
 		VirtualSocket *vs = (VirtualSocket *)arg;
 		if(!vs) {
 			DEBUG_ERROR("invalid virtual socket");
@@ -799,9 +820,11 @@ namespace ZeroTier
 		pbuf_free(q);
 	}

+	// callback from stack to notify driver that data was sent
 	err_t lwIP::lwip_cb_sent(void* arg, struct tcp_pcb *PCB, u16_t len)
 	{
-		DEBUG_EXTRA("pcb=%p", PCB);
+		//DEBUG_EXTRA("pcb=%p", PCB);
+		/*
 		VirtualSocket *vs = (VirtualSocket *)arg;
 		Mutex::Lock _l(vs->tap->_tcpconns_m);
 		if(vs && len) {
@@ -811,6 +834,7 @@ namespace ZeroTier
 				vs->tap->_phy.whack();
 			}
 		}
+		*/
 		return ERR_OK;
 	}

@@ -837,76 +861,79 @@ namespace ZeroTier

 	void lwIP::lwip_cb_err(void *arg, err_t err)
 	{
-		DEBUG_ERROR("err=%d", err);
 		VirtualSocket *vs = (VirtualSocket *)arg;
 		if(!vs){
-			DEBUG_ERROR("vs==NULL");
+			DEBUG_ERROR("err=%d, invalid virtual socket", err);
 			errno = -1; // FIXME: Find more appropriate value
 		}
-		Mutex::Lock _l(vs->tap->_tcpconns_m);
-		int fd = vs->tap->_phy.getDescriptor(vs->sock);
-		DEBUG_ERROR("vs=%p, pcb=%p, fd=%d, err=%d", vs, vs->pcb, fd, err);
-		DEBUG_ERROR("closing virtual socket");
+		DEBUG_ERROR("vs=%p, pcb=%p, fd=%d, err=%d", vs, vs->pcb, vs->app_fd, err);
 		vs->tap->Close(vs);
+
 		switch(err)
 		{
-			case ERR_MEM:
-				DEBUG_ERROR("ERR_MEM->ENOMEM");
+			case ERR_MEM: // -1
+				DEBUG_ERROR("ERR_MEM->ENOMEM, Out of memory error.");
 				errno = ENOMEM;
 				break;
-			case ERR_BUF:
-				DEBUG_ERROR("ERR_BUF->ENOBUFS");
+			case ERR_BUF: // -2
+				DEBUG_ERROR("ERR_BUF->ENOBUFS, Buffer error.");
 				errno = ENOBUFS;
 				break;
-			case ERR_TIMEOUT:
-				DEBUG_ERROR("ERR_TIMEOUT->ETIMEDOUT");
+			case ERR_TIMEOUT: // -3
+				DEBUG_ERROR("ERR_TIMEOUT->ETIMEDOUT, Timeout.");
 				errno = ETIMEDOUT;
 				break;
-			case ERR_RTE:
-				DEBUG_ERROR("ERR_RTE->ENETUNREACH");
+			case ERR_RTE: // -4
+				DEBUG_ERROR("ERR_RTE->ENETUNREACH, Routing problem.");
 				errno = ENETUNREACH;
 				break;
-			case ERR_INPROGRESS:
-				DEBUG_ERROR("ERR_INPROGRESS->EINPROGRESS");
+			case ERR_INPROGRESS: // -5
+				DEBUG_ERROR("ERR_INPROGRESS->EINPROGRESS, Operation in progress.");
 				errno = EINPROGRESS;
 				break;
-			case ERR_VAL:
-				DEBUG_ERROR("ERR_VAL->EINVAL");
+			case ERR_VAL: // -6
+				DEBUG_ERROR("ERR_VAL->EINVAL, Illegal value.");
 				errno = EINVAL;
 				break;
-			case ERR_WOULDBLOCK:
-				DEBUG_ERROR("ERR_WOULDBLOCK->EWOULDBLOCK");
+			case ERR_WOULDBLOCK: // -7
+				DEBUG_ERROR("ERR_WOULDBLOCK->EWOULDBLOCK, Operation would block.");
 				errno = EWOULDBLOCK;
 				break;
-			case ERR_USE:
-				DEBUG_ERROR("ERR_USE->EADDRINUSE");
+			case ERR_USE: // -8
+				DEBUG_ERROR("ERR_USE->EADDRINUSE, Address in use.");
 				errno = EADDRINUSE;
 				break;
-			case ERR_ISCONN:
-				DEBUG_ERROR("ERR_ISvs->EISCONN");
+			case ERR_ALREADY: // -9 ?
+				DEBUG_ERROR("ERR_ALREADY->EISCONN, Already connecting.");
 				errno = EISCONN;
 				break;
-			case ERR_ABRT:
-				DEBUG_ERROR("ERR_ABRT->ECONNREFUSED");
-				errno = ECONNREFUSED;
+			case ERR_ISCONN: // -10
+				DEBUG_ERROR("ERR_ISCONN->EISCONN, Already connected");
+				errno = EISCONN;
 				break;
-
-				// TODO: Below are errors which don't have a standard errno correlate
-
-			case ERR_RST:
-				// -1
+			case ERR_CONN: // -11 ?
+				DEBUG_ERROR("ERR_CONN->EISCONN, Not connected");
+				errno = EISCONN;
 				break;
-			case ERR_CLSD:
-				// -1
+			case ERR_IF: // -12
+				DEBUG_ERROR("ERR_IF, Low-level netif error.");
+				errno = -1;
 				break;
-			case ERR_CONN:
-				// -1
+			case ERR_ABRT: // -13
+				DEBUG_ERROR("ERR_ABRT, Connection aborted.");
+				errno = -1;
 				break;			
-			case ERR_ARG:
-				// -1
+			case ERR_RST: // -14
+				DEBUG_ERROR("ERR_RST, Connection reset.");
+				errno = -1;
 				break;
-			case ERR_IF:
-				// -1
+			case ERR_CLSD: // -15
+				DEBUG_ERROR("ERR_CLSD, Connection closed.");
+				errno = -1;
+				break;
+			case ERR_ARG: // -16
+				DEBUG_ERROR("ERR_ARG, Illegal argument.");
+				errno = -1;
 				break;
 			default:
 				break;
--- a/src/lwIP.hpp
+++ b/src/lwIP.hpp
@@ -161,6 +161,7 @@ extern "C" u16_t lwip_ntohs(LWIP_NTOHS_SIG);
 extern "C" void tcp_input(LWIP_TCP_INPUT_SIG);
 extern "C" err_t ip_input(LWIP_IP_INPUT_SIG);

+
 //extern "C" void netif_set_status_callback(NETIF_SET_STATUS_CALLBACK);


--- a/src/picoTCP.cpp
+++ b/src/picoTCP.cpp
@@ -401,7 +401,7 @@ namespace ZeroTier {
 			return;
 		}
 		if(vs->socket_type == SOCK_STREAM) {
-			DEBUG_TRANS("len=%5d, [app(buf) --> network_stack(vs=%p)] proto=0x%04x (TCP)", r, vs, PICO_PROTO_TCP);
+			DEBUG_TRANS("len=%5d buf_len=%13d [VSTXBF        -->     NSPICO] proto=0x%04x (TCP)", r, vs->TXbuf->count(), PICO_PROTO_TCP);
 		}
 		if(r == 0) {
 			// DEBUG_ERROR("err=%d, pico_err=%d, %s", r, pico_err, beautify_pico_error(pico_err));
@@ -935,7 +935,7 @@ namespace ZeroTier {
 			return -1;
 		}
 		if(vs->picosock->state & PICO_SOCKET_STATE_CLOSED){
-			DEBUG_ERROR("socket is CLOSED, this write() will fail");
+			DEBUG_ERROR("socket is CLOSED, this wrpico_cb_tcp_writeite() will fail");
 			return -1;
 		}
 		if(!vs) {
@@ -983,10 +983,10 @@ namespace ZeroTier {
 				vs->TXbuf->consume(r);
 			}
 			if(vs->socket_type == SOCK_STREAM) {
-				DEBUG_TRANS("len=%5d [app(buf) --> network_stack(vs=%p)] proto=0x%04x (TCP)", r, vs, PICO_PROTO_TCP);
+				DEBUG_TRANS("len=%5d buf_len=%13d [VSTXBF        -->     NSPICO] proto=0x%04x (TCP)", r, vs->TXbuf->count(), PICO_PROTO_TCP);
 			}
 			if(vs->socket_type == SOCK_DGRAM) {
-				DEBUG_TRANS("len=%5d [app(buf) --> network_stack(vs=%p)] proto=0x%04x (TCP)", r, vs, PICO_PROTO_UDP);
+				DEBUG_TRANS("len=%5d buf_len=               [APPFDS        -->     NSPICO] proto=0x%04x (UDP)", r, PICO_PROTO_TCP);
 			}
 		}
 		return err;
--- a/test/selftest.cpp
+++ b/test/selftest.cpp
@@ -239,7 +239,7 @@ void wait_until_tplus_s(long int original_time, int tplus_s) {
 	fprintf(stderr, "\n\n--- WAITING FOR T+%d --- (current: T+%d)\n\n", tplus_s, current_time_offset);
 	if(current_time_offset > tplus_s) {
 		DEBUG_ERROR("--- ABORTING TEST: Tests are out of sync and might not yield valid results. ---");
-		exit(0);
+		//exit(0);
 	}
 	if(current_time_offset == tplus_s) {
 		DEBUG_ERROR("--- WARNING: Tests might be out of sync and might not yield valid results. ---");
@@ -824,10 +824,11 @@ void tcp_client_sustained_4(TCP_UNIT_TEST_SIG_4)
 				w += n;
 				wrem -= n;
 				err = n;
+				DEBUG_TEST("wrote=%d, w=%d, wrem=%d", n, w, wrem);
 			}
 		}
 		long int tx_tf = get_now_ts();	
-		DEBUG_TEST("wrote=%d", w);
+		DEBUG_TEST("wrote=%d, reading next...", w);
 		// RX
 		long int rx_ti = 0;	
 		while(rrem) {
@@ -981,13 +982,14 @@ void tcp_server_sustained_4(TCP_UNIT_TEST_SIG_4)
 		*passed = false;
 		return;
 	}
-	struct sockaddr_in client;
-	socklen_t client_addrlen = sizeof(sockaddr_in);
-	if((client_fd = ACCEPT(fd, (struct sockaddr *)&client, &client_addrlen)) < 0) {
+	struct sockaddr_storage client;
+	struct sockaddr_in *in4 = (struct sockaddr_in*)&client;
+	socklen_t client_addrlen = sizeof(sockaddr_storage);
+	if((client_fd = ACCEPT(fd, (struct sockaddr *)in4, &client_addrlen)) < 0) {
 		fprintf(stderr,"error accepting connection (%d)\n", err);
 		perror("accept");
 	}
-	DEBUG_TEST("accepted connection from %s, on port %d", inet_ntoa(client.sin_addr), ntohs(client.sin_port));
+	DEBUG_TEST("accepted connection from %s, on port %d", inet_ntoa(in4->sin_addr), ntohs(in4->sin_port));
 	if(op == TEST_OP_N_BYTES) {
 		int wrem = cnt, rrem = cnt;
 		long int rx_ti = 0;
@@ -1001,11 +1003,11 @@ void tcp_server_sustained_4(TCP_UNIT_TEST_SIG_4)
 				r += n;
 				rrem -= n;
 				err = n;
+				DEBUG_TEST("read=%d, r=%d, rrem=%d", n, r, rrem);
 			}
 		}
 		long int rx_tf = get_now_ts();	
-		DEBUG_TEST("read=%d", r);
-		
+		DEBUG_TEST("read=%d, writing next...", r);
 		long int tx_ti = get_now_ts();	
 		while(wrem) {
 			int next_write = std::min(1024, wrem);
@@ -2254,7 +2256,7 @@ int main(int argc , char *argv[])
 #if defined(__SELFTEST__)
 	// set start time here since we need to wait for both libzt instances to be online
 	long int selftest_start_time = get_now_ts();
-	subtest_expected_duration = 30;
+	subtest_expected_duration = 5;

 	DEBUG_TEST("Waiting for libzt to come online...\n");
 	zts_simple_start(path.c_str(), nwid.c_str());
@@ -2319,7 +2321,7 @@ int main(int argc , char *argv[])
 #endif // __SELFTEST__

 	port = start_port;
-	cnt  = 1024*128;
+	cnt  = 1024*16;
 	op   = TEST_OP_N_BYTES;

 /*
@@ -2341,7 +2343,7 @@ udp-ip6-server   |              |      OK        |                |       OK

 #if defined(LIBZT_IPV4)
 	// UDP 4 client/server
-	/*
+	
 	ipv = 4;
 	subtest_start_time_offset += subtest_expected_duration;
 	subtest_expected_duration = 30;
@@ -2413,7 +2415,7 @@ udp-ip6-server   |              |      OK        |                |       OK
 	}
 	RECORD_RESULTS(passed, details, &results);
 	port++;
-*/
+
 // TCP 4 client/server

 	ipv = 4;