Browse code

- friendlier error messages on send or connect errors (the connection destination is printed)

Andrei Pelinescu-Onciul authored on 21/05/2008 21:42:52
Showing 1 changed files
... ...
@@ -506,7 +506,8 @@ again:
506 506
 			else goto error_timeout;
507 507
 		}
508 508
 		if (errno!=EINPROGRESS && errno!=EALREADY){
509
-			LOG(L_ERR, "ERROR: tcp_blocking_connect: (%d) %s\n",
509
+			LOG(L_ERR, "ERROR: tcp_blocking_connect %s: (%d) %s\n",
510
+					su2a((union sockaddr_union*)servaddr, addrlen),
510 511
 					errno, strerror(errno));
511 512
 			goto error;
512 513
 		}
... ...
@@ -536,15 +537,19 @@ again:
536 536
 #endif
537 537
 		if (n<0){
538 538
 			if (errno==EINTR) continue;
539
-			LOG(L_ERR, "ERROR: tcp_blocking_connect: poll/select failed:"
540
-					" (%d) %s\n", errno, strerror(errno));
539
+			LOG(L_ERR, "ERROR: tcp_blocking_connect %s: poll/select failed:"
540
+					" (%d) %s\n",
541
+					su2a((union sockaddr_union*)servaddr, addrlen),
542
+					errno, strerror(errno));
541 543
 			goto error;
542 544
 		}else if (n==0) /* timeout */ continue;
543 545
 #if defined(HAVE_SELECT) && defined(BLOCKING_USE_SELECT)
544 546
 		if (FD_ISSET(fd, &sel_set))
545 547
 #else
546 548
 		if (pf.revents&(POLLERR|POLLHUP|POLLNVAL)){ 
547
-			LOG(L_ERR, "ERROR: tcp_blocking_connect: poll error: flags %x\n",
549
+			LOG(L_ERR, "ERROR: tcp_blocking_connect %s: poll error: "
550
+					"flags %x\n",
551
+					su2a((union sockaddr_union*)servaddr, addrlen),
548 552
 					pf.revents);
549 553
 			poll_err=1;
550 554
 		}
... ...
@@ -554,7 +559,9 @@ again:
554 554
 			getsockopt(fd, SOL_SOCKET, SO_ERROR, &err, &err_len);
555 555
 			if ((err==0) && (poll_err==0)) goto end;
556 556
 			if (err!=EINPROGRESS && err!=EALREADY){
557
-				LOG(L_ERR, "ERROR: tcp_blocking_connect: SO_ERROR (%d) %s\n",
557
+				LOG(L_ERR, "ERROR: tcp_blocking_connect %s: SO_ERROR (%d) "
558
+						"%s\n",
559
+						su2a((union sockaddr_union*)servaddr, addrlen),
558 560
 						err, strerror(err));
559 561
 				goto error;
560 562
 			}
... ...
@@ -562,8 +569,9 @@ again:
562 562
 	}
563 563
 error_timeout:
564 564
 	/* timeout */
565
-	LOG(L_ERR, "ERROR: tcp_blocking_connect: timeout %d s elapsed from %d s\n",
566
-			elapsed, tcp_connect_timeout);
565
+	LOG(L_ERR, "ERROR: tcp_blocking_connect %s: timeout %d s elapsed "
566
+				"from %d s\n", su2a((union sockaddr_union*)servaddr, addrlen),
567
+				elapsed, tcp_connect_timeout);
567 568
 error:
568 569
 	return -1;
569 570
 end:
... ...
@@ -956,18 +964,20 @@ inline static int tcp_do_connect(	union sockaddr_union* server,
956 956
 
957 957
 	s=socket(AF2PF(server->s.sa_family), SOCK_STREAM, 0);
958 958
 	if (unlikely(s==-1)){
959
-		LOG(L_ERR, "ERROR: tcp_do_connect: socket: (%d) %s\n",
960
-				errno, strerror(errno));
959
+		LOG(L_ERR, "ERROR: tcp_do_connect %s: socket: (%d) %s\n",
960
+				su2a(server, sizeof(*server)), errno, strerror(errno));
961 961
 		goto error;
962 962
 	}
963 963
 	if (init_sock_opt(s)<0){
964
-		LOG(L_ERR, "ERROR: tcp_do_connect: init_sock_opt failed\n");
964
+		LOG(L_ERR, "ERROR: tcp_do_connect %s: init_sock_opt failed\n",
965
+					su2a(server, sizeof(*server)));
965 966
 		goto error;
966 967
 	}
967 968
 	
968 969
 	if (unlikely(from && bind(s, &from->s, sockaddru_len(*from)) != 0)){
969 970
 		LOG(L_WARN, "WARNING: tcp_do_connect: binding to source address"
970
-					" failed: %s [%d]\n", strerror(errno), errno);
971
+					" %s failed: %s [%d]\n", su2a(from, sizeof(*from)),
972
+					strerror(errno), errno);
971 973
 	}
972 974
 	*state=S_CONN_OK;
973 975
 #ifdef TCP_BUF_WRITE
... ...
@@ -979,16 +989,17 @@ again:
979 979
 			if (likely(errno==EINPROGRESS))
980 980
 				*state=S_CONN_CONNECT;
981 981
 			else if (errno!=EALREADY){
982
-				LOG(L_ERR, "ERROR: tcp_do_connect: connect: (%d) %s\n",
983
-						errno, strerror(errno));
982
+				LOG(L_ERR, "ERROR: tcp_do_connect: connect %s: (%d) %s\n",
983
+							su2a(server, sizeof(*server)),
984
+							errno, strerror(errno));
984 985
 				goto error;
985 986
 			}
986 987
 		}
987 988
 	}else{
988 989
 #endif /* TCP_BUF_WRITE */
989 990
 		if (tcp_blocking_connect(s, &server->s, sockaddru_len(*server))<0){
990
-			LOG(L_ERR, "ERROR: tcp_do_connect: tcp_blocking_connect"
991
-						" failed\n");
991
+			LOG(L_ERR, "ERROR: tcp_do_connect: tcp_blocking_connect %s"
992
+						" failed\n", su2a(server, sizeof(*server)));
992 993
 			goto error;
993 994
 		}
994 995
 #ifdef TCP_BUF_WRITE
... ...
@@ -1018,8 +1029,9 @@ find_socket:
1018 1018
 		*res_si=find_si(&ip, 0, PROTO_TCP);
1019 1019
 	
1020 1020
 	if (unlikely(*res_si==0)){
1021
-		LOG(L_WARN, "WARNING: tcp_do_connect: could not find corresponding"
1022
-				" listening socket, using default...\n");
1021
+		LOG(L_WARN, "WARNING: tcp_do_connect %s: could not find corresponding"
1022
+				" listening socket for %s, using default...\n",
1023
+					su2a(server, sizeof(*server)), ip_addr2a(&ip));
1023 1024
 		if (server->s.sa_family==AF_INET) *res_si=sendipv4_tcp;
1024 1025
 #ifdef USE_IPV6
1025 1026
 		else *res_si=sendipv6_tcp;
... ...
@@ -1054,14 +1066,14 @@ struct tcp_connection* tcpconn_connect( union sockaddr_union* server,
1054 1054
 	}
1055 1055
 	s=tcp_do_connect(server, from, type, &my_name, &si, &state);
1056 1056
 	if (s==-1){
1057
-		LOG(L_ERR, "ERROR: tcp_do_connect: failed (%d) %s\n",
1058
-				errno, strerror(errno));
1057
+		LOG(L_ERR, "ERROR: tcp_do_connect %s: failed (%d) %s\n",
1058
+				su2a(server, sizeof(*server)), errno, strerror(errno));
1059 1059
 		goto error;
1060 1060
 	}
1061 1061
 	con=tcpconn_new(s, server, &my_name, si, type, state);
1062 1062
 	if (con==0){
1063
-		LOG(L_ERR, "ERROR: tcp_connect: tcpconn_new failed, closing the "
1064
-				 " socket\n");
1063
+		LOG(L_ERR, "ERROR: tcp_connect %s: tcpconn_new failed, closing the "
1064
+				 " socket\n", su2a(server, sizeof(*server)));
1065 1065
 		goto error;
1066 1066
 	}
1067 1067
 	return con;
... ...
@@ -1086,8 +1098,9 @@ int tcpconn_finish_connect( struct tcp_connection* c,
1086 1086
 	
1087 1087
 	s=tcp_do_connect(&c->rcv.src_su, from, c->type, &local_addr, &si, &state);
1088 1088
 	if (unlikely(s==-1)){
1089
-		LOG(L_ERR, "ERROR: tcpconn_finish_connect: tcp_do_connect for %p"
1090
-						" failed\n", c);
1089
+		LOG(L_ERR, "ERROR: tcpconn_finish_connect %s: tcp_do_connect for %p"
1090
+					" failed\n", su2a(&c->rcv.src_su, sizeof(c->rcv.src_su)),
1091
+					c);
1091 1092
 		return -1;
1092 1093
 	}
1093 1094
 	c->rcv.bind_address=si;
... ...
@@ -1608,16 +1621,18 @@ no_id:
1608 1608
 			if (likely(tcp_options.tcp_connect_wait && 
1609 1609
 						tcp_options.tcp_buf_write )){
1610 1610
 				if (unlikely(*tcp_connections_no >= tcp_max_connections)){
1611
-					LOG(L_ERR, "ERROR: tcp_send: maximum number of connections"
1612
-								" exceeded (%d/%d)\n",
1611
+					LOG(L_ERR, "ERROR: tcp_send %s: maximum number of"
1612
+								" connections exceeded (%d/%d)\n",
1613
+								su2a(&dst->to, sizeof(&dst->to)),
1613 1614
 								*tcp_connections_no, tcp_max_connections);
1614 1615
 					return -1;
1615 1616
 				}
1616 1617
 				c=tcpconn_new(-1, &dst->to, from, 0, dst->proto,
1617 1618
 								S_CONN_PENDING);
1618 1619
 				if (unlikely(c==0)){
1619
-					LOG(L_ERR, "ERROR: tcp_send: could not create new"
1620
-							" connection\n");
1620
+					LOG(L_ERR, "ERROR: tcp_send %s: could not create new"
1621
+							" connection\n",
1622
+							su2a(&dst->to, sizeof(&dst->to)));
1621 1623
 					return -1;
1622 1624
 				}
1623 1625
 				c->flags|=F_CONN_PENDING|F_CONN_FD_CLOSED;
... ...
@@ -1625,8 +1640,10 @@ no_id:
1625 1625
 											 table */
1626 1626
 				/* add it to id hash and aliases */
1627 1627
 				if (unlikely(tcpconn_add(c)==0)){
1628
-					LOG(L_ERR, "ERROR: tcp_send: could not add "
1629
-									"connection %p\n", c);
1628
+					LOG(L_ERR, "ERROR: tcp_send %s: could not add "
1629
+								"connection %p\n",
1630
+								su2a(&dst->to, sizeof(&dst->to)),
1631
+									c);
1630 1632
 					_tcpconn_free(c);
1631 1633
 					n=-1;
1632 1634
 					goto end_no_conn;
... ...
@@ -1634,8 +1651,9 @@ no_id:
1634 1634
 				/* do connect and if src ip or port changed, update the 
1635 1635
 				 * aliases */
1636 1636
 				if (unlikely((fd=tcpconn_finish_connect(c, from))<0)){
1637
-					LOG(L_ERR, "ERROR: tcp_send: tcpconn_finish_connect(%p)"
1638
-							" failed\n", c);
1637
+					LOG(L_ERR, "ERROR: tcp_send %s: tcpconn_finish_connect(%p)"
1638
+							" failed\n", su2a(&dst->to, sizeof(&dst->to)),
1639
+								c);
1639 1640
 					goto conn_wait_error;
1640 1641
 				}
1641 1642
 				/* ? TODO: it might be faster just to queue the write directly
... ...
@@ -1658,8 +1676,9 @@ no_id:
1658 1658
 							if (unlikely(_wbufq_insert(c, buf+n, len-n)<0)){
1659 1659
 								lock_release(&c->write_lock);
1660 1660
 								n=-1;
1661
-								LOG(L_ERR, "ERROR: tcp_send: EAGAIN and"
1661
+								LOG(L_ERR, "ERROR: tcp_send %s: EAGAIN and"
1662 1662
 										" write queue full or failed for %p\n",
1663
+										su2a(&dst->to, sizeof(&dst->to)),
1663 1664
 										c);
1664 1665
 								goto conn_wait_error;
1665 1666
 							}
... ...
@@ -1669,8 +1688,10 @@ no_id:
1669 1669
 						response[1]=CONN_NEW_PENDING_WRITE;
1670 1670
 						if (unlikely(send_fd(unix_tcp_sock, response, 
1671 1671
 												sizeof(response), fd) <= 0)){
1672
-							LOG(L_ERR, "BUG: tcp_send: CONN_NEW_PENDING_WRITE"
1673
-										" for %p failed:" " %s (%d)\n",
1672
+							LOG(L_ERR, "BUG: tcp_send %s: "
1673
+										"CONN_NEW_PENDING_WRITE  for %p"
1674
+										" failed:" " %s (%d)\n",
1675
+										su2a(&dst->to, sizeof(&dst->to)),
1674 1676
 										c, strerror(errno), errno);
1675 1677
 							goto conn_wait_error;
1676 1678
 						}
... ...
@@ -1678,8 +1699,9 @@ no_id:
1678 1678
 						goto end;
1679 1679
 					}
1680 1680
 					/* error: destroy it directly */
1681
-					LOG(L_ERR, "ERROR: tcp_send: connect & send "
1681
+					LOG(L_ERR, "ERROR: tcp_send %s: connect & send "
1682 1682
 										" for %p failed:" " %s (%d)\n",
1683
+										su2a(&dst->to, sizeof(&dst->to)),
1683 1684
 										c, strerror(errno), errno);
1684 1685
 					goto conn_wait_error;
1685 1686
 				}
... ...
@@ -1689,8 +1711,9 @@ no_id:
1689 1689
 				response[1]=CONN_NEW_COMPLETE;
1690 1690
 				if (unlikely(send_fd(unix_tcp_sock, response, 
1691 1691
 										sizeof(response), fd) <= 0)){
1692
-					LOG(L_ERR, "BUG: tcp_send: CONN_NEW_COMPLETE  for %p"
1692
+					LOG(L_ERR, "BUG: tcp_send %s: CONN_NEW_COMPLETE  for %p"
1693 1693
 								" failed:" " %s (%d)\n",
1694
+								su2a(&dst->to, sizeof(&dst->to)),
1694 1695
 								c, strerror(errno), errno);
1695 1696
 					goto conn_wait_error;
1696 1697
 				}
... ...
@@ -1698,7 +1721,8 @@ no_id:
1698 1698
 			}
1699 1699
 #endif /* TCP_CONNECT_WAIT  && TCP_BUF_WRITE */
1700 1700
 			if (unlikely((c=tcpconn_connect(&dst->to, from, dst->proto))==0)){
1701
-				LOG(L_ERR, "ERROR: tcp_send: connect failed\n");
1701
+				LOG(L_ERR, "ERROR: tcp_send %s: connect failed\n",
1702
+								su2a(&dst->to, sizeof(&dst->to)));
1702 1703
 				return -1;
1703 1704
 			}
1704 1705
 			atomic_set(&c->refcnt, 2); /* ref. from here and it will also
... ...
@@ -1713,7 +1737,8 @@ no_id:
1713 1713
 			response[1]=CONN_NEW;
1714 1714
 			n=send_fd(unix_tcp_sock, response, sizeof(response), c->s);
1715 1715
 			if (unlikely(n<=0)){
1716
-				LOG(L_ERR, "BUG: tcp_send: failed send_fd: %s (%d)\n",
1716
+				LOG(L_ERR, "BUG: tcp_send %s: failed send_fd: %s (%d)\n",
1717
+						su2a(&dst->to, sizeof(&dst->to)),
1717 1718
 						strerror(errno), errno);
1718 1719
 				/* we can safely delete it, it's not referenced by anybody */
1719 1720
 				_tcpconn_free(c);
... ...
@@ -1869,8 +1894,10 @@ send_it:
1869 1869
 			lock_release(&c->write_lock);
1870 1870
 		}
1871 1871
 #endif /* TCP_BUF_WRITE */
1872
-		LOG(L_ERR, "ERROR: tcp_send: failed to send on %p: %s (%d)\n",
1873
-					c, strerror(errno), errno);
1872
+		LOG(L_ERR, "ERROR: tcp_send: failed to send on %p (%s:%d->%s): %s (%d)"
1873
+					"\n", c, ip_addr2a(&c->rcv.dst_ip), c->rcv.dst_port,
1874
+					su2a(&c->rcv.src_su, sizeof(&c->rcv.src_su)),
1875
+					strerror(errno), errno);
1874 1876
 #ifdef TCP_BUF_WRITE
1875 1877
 error:
1876 1878
 #endif /* TCP_BUF_WRITE */
... ...
@@ -1890,8 +1917,9 @@ error:
1890 1890
 		 * if it succeeds */
1891 1891
 #ifdef TCP_FD_CACHE
1892 1892
 		if (unlikely(fd_cache_e)){
1893
-			LOG(L_ERR, "ERROR: tcp_send: error on cached fd, removing from the"
1894
-					"cache (%d, %p, %d)\n", 
1893
+			LOG(L_ERR, "ERROR: tcp_send %s: error on cached fd, removing from"
1894
+					" the cache (%d, %p, %d)\n", 
1895
+					su2a(&c->rcv.src_su, sizeof(&c->rcv.src_su)),
1895 1896
 					fd, fd_cache_e->con, fd_cache_e->id);
1896 1897
 			tcp_fd_cache_rm(fd_cache_e);
1897 1898
 			close(fd);
... ...
@@ -1973,6 +2001,7 @@ int tcp_init(struct socket_info* sock_info)
1973 1973
 		LOG(L_ERR, "ERROR: tcp_init: could no init sockaddr_union\n");
1974 1974
 		goto error;
1975 1975
 	}
1976
+	DBG("tcp_init: added %s\n", su2a(addr, sizeof(*addr)));
1976 1977
 	sock_info->socket=socket(AF2PF(addr->s.sa_family), SOCK_STREAM, 0);
1977 1978
 	if (sock_info->socket==-1){
1978 1979
 		LOG(L_ERR, "ERROR: tcp_init: socket: %s\n", strerror(errno));
... ...
@@ -3063,8 +3092,8 @@ static inline int handle_new_connect(struct socket_info* si)
3063 3063
 		/* prepare it for passing to a child */
3064 3064
 		tcpconn->flags|=F_CONN_READER;
3065 3065
 		tcpconn_add(tcpconn);
3066
-		DBG("handle_new_connect: new connection: %p %d flags: %04x\n",
3067
-			tcpconn, tcpconn->s, tcpconn->flags);
3066
+		DBG("handle_new_connect: new connection from %s: %p %d flags: %04x\n",
3067
+			su2a(&su, sizeof(su)), tcpconn, tcpconn->s, tcpconn->flags);
3068 3068
 		if(unlikely(send2child(tcpconn)<0)){
3069 3069
 			LOG(L_ERR,"ERROR: handle_new_connect: no children "
3070 3070
 					"available\n");