refactor: Add a bit more logging; change WARNING to ERROR.

ERROR is caught in tests, so we'll use it more for things that ought not
to happen.

other/bootstrap_daemon/docker/tox-bootstrapd.sha256

@@ -1 +1 @@
-2b9ba3bcb87cc1f9f60c340a50795ca1f41733a44840a29c3a6bc2a542bf6b8c  /usr/local/bin/tox-bootstrapd
+c0dc82c8f4418f900e662076a2002363838f60eb55950a04d6cda0698b06e687  /usr/local/bin/tox-bootstrapd

toxcore/Messenger.c

@@ -504,22 +504,22 @@ int m_send_message_generic(Messenger *m, int32_t friendnumber, uint8_t type, con
                            uint32_t *message_id)
 {
     if (type > MESSAGE_ACTION) {
-        LOGGER_WARNING(m->log, "Message type %d is invalid", type);
+        LOGGER_WARNING(m->log, "message type %d is invalid", type);
         return -5;
     }
 
     if (!friend_is_valid(m, friendnumber)) {
-        LOGGER_WARNING(m->log, "Friend number %d is invalid", friendnumber);
+        LOGGER_WARNING(m->log, "friend number %d is invalid", friendnumber);
         return -1;
     }
 
     if (length >= MAX_CRYPTO_DATA_SIZE) {
-        LOGGER_WARNING(m->log, "Message length %u is too large", length);
+        LOGGER_WARNING(m->log, "message length %u is too large", length);
         return -2;
     }
 
     if (m->friendlist[friendnumber].status != FRIEND_ONLINE) {
-        LOGGER_WARNING(m->log, "Friend %d is not online", friendnumber);
+        LOGGER_WARNING(m->log, "friend %d is not online", friendnumber);
         return -3;
     }
 
@@ -534,7 +534,7 @@ int m_send_message_generic(Messenger *m, int32_t friendnumber, uint8_t type, con
                                            m->friendlist[friendnumber].friendcon_id), packet, length + 1, 0);
 
     if (packet_num == -1) {
-        LOGGER_WARNING(m->log, "Failed to write crypto packet for message of length %d to friend %d",
+        LOGGER_WARNING(m->log, "failed to write crypto packet for message of length %d to friend %d",
                        length, friendnumber);
         return -4;
     }
@@ -1528,7 +1528,7 @@ static bool do_all_filetransfers(Messenger *m, int32_t friendnumber, void *userd
 
         if (max_speed_reached(m->net_crypto, friend_connection_crypt_connection_id(
                                   m->fr_c, friendcon->friendcon_id))) {
-            LOGGER_DEBUG(m->log, "Maximum connection speed reached");
+            LOGGER_DEBUG(m->log, "maximum connection speed reached");
             // connection doesn't support any more data
             return false;
         }
@@ -3203,7 +3203,7 @@ Messenger *new_messenger(Mono_Time *mono_time, Messenger_Options *options, unsig
 
     if (!options->udp_disabled && options->proxy_info.proxy_type != TCP_PROXY_NONE) {
         // We don't currently support UDP over proxy.
-        LOGGER_WARNING(m->log, "UDP enabled and proxy set: disabling UDP");
+        LOGGER_INFO(m->log, "UDP enabled and proxy set: disabling UDP");
         options->udp_disabled = true;
     }
 

toxcore/TCP_common.c

@@ -232,7 +232,7 @@ static uint16_t read_TCP_length(const Logger *logger, Socket sock, const IP_Port
         net_unpack_u16(length_buf, &length);
 
         if (length > MAX_PACKET_SIZE) {
-            LOGGER_WARNING(logger, "TCP packet too large: %d > %d", length, MAX_PACKET_SIZE);
+            LOGGER_ERROR(logger, "TCP packet too large: %d > %d", length, MAX_PACKET_SIZE);
             return -1;
         }
 
@@ -273,7 +273,7 @@ int read_packet_TCP_secure_connection(const Logger *logger, Socket sock, uint16_
     const int len_packet = read_TCP_packet(logger, sock, data_encrypted, *next_packet_length, ip_port);
 
     if (len_packet != *next_packet_length) {
-        LOGGER_WARNING(logger, "invalid packet length: %d, expected %d", len_packet, *next_packet_length);
+        LOGGER_ERROR(logger, "invalid packet length: %d, expected %d", len_packet, *next_packet_length);
         return 0;
     }
 
@@ -282,7 +282,7 @@ int read_packet_TCP_secure_connection(const Logger *logger, Socket sock, uint16_
     const int len = decrypt_data_symmetric(shared_key, recv_nonce, data_encrypted, len_packet, data);
 
     if (len + CRYPTO_MAC_SIZE != len_packet) {
-        LOGGER_WARNING(logger, "decrypted length %d does not match expected length %d", len + CRYPTO_MAC_SIZE, len_packet);
+        LOGGER_ERROR(logger, "decrypted length %d does not match expected length %d", len + CRYPTO_MAC_SIZE, len_packet);
         return -1;
     }
 

toxcore/TCP_server.c

@@ -301,12 +301,12 @@ static int handle_TCP_handshake(const Logger *logger, TCP_Secure_Connection *con
                                 const uint8_t *self_secret_key)
 {
     if (length != TCP_CLIENT_HANDSHAKE_SIZE) {
-        LOGGER_WARNING(logger, "invalid handshake length: %d != %d", length, TCP_CLIENT_HANDSHAKE_SIZE);
+        LOGGER_ERROR(logger, "invalid handshake length: %d != %d", length, TCP_CLIENT_HANDSHAKE_SIZE);
         return -1;
     }
 
     if (con->status != TCP_STATUS_CONNECTED) {
-        LOGGER_WARNING(logger, "TCP connection %u not connected", (unsigned int)con->identifier);
+        LOGGER_ERROR(logger, "TCP connection %u not connected", (unsigned int)con->identifier);
         return -1;
     }
 
@@ -317,7 +317,7 @@ static int handle_TCP_handshake(const Logger *logger, TCP_Secure_Connection *con
                                      data + CRYPTO_PUBLIC_KEY_SIZE + CRYPTO_NONCE_SIZE, TCP_HANDSHAKE_PLAIN_SIZE + CRYPTO_MAC_SIZE, plain);
 
     if (len != TCP_HANDSHAKE_PLAIN_SIZE) {
-        LOGGER_WARNING(logger, "invalid TCP handshake decrypted length: %d != %d", len, TCP_HANDSHAKE_PLAIN_SIZE);
+        LOGGER_ERROR(logger, "invalid TCP handshake decrypted length: %d != %d", len, TCP_HANDSHAKE_PLAIN_SIZE);
         crypto_memzero(shared_key, sizeof(shared_key));
         return -1;
     }
@@ -820,7 +820,10 @@ static Socket new_listening_TCP_socket(const Logger *logger, Family family, uint
     ok = ok && bind_to_port(sock, family, port) && (net_listen(sock, TCP_MAX_BACKLOG) == 0);
 
     if (!ok) {
-        LOGGER_ERROR(logger, "could not bind to TCP port %d (family = %d)", port, family.value);
+        char *const error = net_new_strerror(net_error());
+        LOGGER_ERROR(logger, "could not bind to TCP port %d (family = %d): %s",
+                     port, family.value, error ? error : "(null)");
+        net_kill_strerror(error);
         kill_sock(sock);
         return net_invalid_socket;
     }
@@ -956,7 +959,7 @@ static int do_incoming(TCP_Server *tcp_server, uint32_t i)
     TCP_Secure_Connection *conn_new = &tcp_server->unconfirmed_connection_queue[index_new];
 
     if (conn_new->status != TCP_STATUS_NO_STATUS) {
-        LOGGER_WARNING(tcp_server->logger, "incoming connection %d would overwrite existing", i);
+        LOGGER_ERROR(tcp_server->logger, "incoming connection %d would overwrite existing", i);
         kill_TCP_secure_connection(conn_new);
     }
 

toxcore/net_crypto.c

@@ -817,17 +817,19 @@ static int get_data_pointer(const Packets_Array *array, Packet_Data **data, uint
  * return packet number on success.
  */
 non_null()
-static int64_t add_data_end_of_buffer(Packets_Array *array, const Packet_Data *data)
+static int64_t add_data_end_of_buffer(const Logger *logger, Packets_Array *array, const Packet_Data *data)
 {
     const uint32_t num_spots = num_packets_array(array);
 
     if (num_spots >= CRYPTO_PACKET_BUFFER_SIZE) {
+        LOGGER_WARNING(logger, "crypto packet buffer size exceeded; rejecting packet of length %d", data->length);
         return -1;
     }
 
     Packet_Data *new_d = (Packet_Data *)calloc(1, sizeof(Packet_Data));
 
     if (new_d == nullptr) {
+        LOGGER_ERROR(logger, "packet data allocation failed");
         return -1;
     }
 
@@ -1080,14 +1082,14 @@ static int send_data_packet(Net_Crypto *c, int crypt_connection_id, const uint8_
     const uint16_t max_length = MAX_CRYPTO_PACKET_SIZE - (1 + sizeof(uint16_t) + CRYPTO_MAC_SIZE);
 
     if (length == 0 || length > max_length) {
-        LOGGER_WARNING(c->log, "zero-length or too large data packet: %d (max: %d)", length, max_length);
+        LOGGER_ERROR(c->log, "zero-length or too large data packet: %d (max: %d)", length, max_length);
         return -1;
     }
 
     Crypto_Connection *conn = get_crypto_connection(c, crypt_connection_id);
 
     if (conn == nullptr) {
-        LOGGER_WARNING(c->log, "connection id %d not found", crypt_connection_id);
+        LOGGER_ERROR(c->log, "connection id %d not found", crypt_connection_id);
         return -1;
     }
 
@@ -1099,7 +1101,7 @@ static int send_data_packet(Net_Crypto *c, int crypt_connection_id, const uint8_
     const int len = encrypt_data_symmetric(conn->shared_key, conn->sent_nonce, data, length, packet + 1 + sizeof(uint16_t));
 
     if (len + 1 + sizeof(uint16_t) != packet_size) {
-        LOGGER_WARNING(c->log, "encryption failed: %d", len);
+        LOGGER_ERROR(c->log, "encryption failed: %d", len);
         pthread_mutex_unlock(conn->mutex);
         return -1;
     }
@@ -1120,7 +1122,7 @@ static int send_data_packet_helper(Net_Crypto *c, int crypt_connection_id, uint3
                                    const uint8_t *data, uint16_t length)
 {
     if (length == 0 || length > MAX_CRYPTO_DATA_SIZE) {
-        LOGGER_WARNING(c->log, "zero-length or too large data packet: %d (max: %d)", length, MAX_CRYPTO_PACKET_SIZE);
+        LOGGER_ERROR(c->log, "zero-length or too large data packet: %d (max: %d)", length, MAX_CRYPTO_PACKET_SIZE);
         return -1;
     }
 
@@ -1175,6 +1177,8 @@ static int64_t send_lossless_packet(Net_Crypto *c, int crypt_connection_id, cons
                                     uint8_t congestion_control)
 {
     if (length == 0 || length > MAX_CRYPTO_DATA_SIZE) {
+        LOGGER_ERROR(c->log, "rejecting too large (or empty) packet of size %d on crypt connection %d", length,
+                     crypt_connection_id);
         return -1;
     }
 
@@ -1189,6 +1193,7 @@ static int64_t send_lossless_packet(Net_Crypto *c, int crypt_connection_id, cons
     reset_max_speed_reached(c, crypt_connection_id);
 
     if (conn->maximum_speed_reached && congestion_control) {
+        LOGGER_INFO(c->log, "congestion control: maximum speed reached on crypt connection %d", crypt_connection_id);
         return -1;
     }
 
@@ -1197,7 +1202,7 @@ static int64_t send_lossless_packet(Net_Crypto *c, int crypt_connection_id, cons
     dt.length = length;
     memcpy(dt.data, data, length);
     pthread_mutex_lock(conn->mutex);
-    const int64_t packet_num = add_data_end_of_buffer(&conn->send_array, &dt);
+    const int64_t packet_num = add_data_end_of_buffer(c->log, &conn->send_array, &dt);
     pthread_mutex_unlock(conn->mutex);
 
     if (packet_num == -1) {
@@ -2848,28 +2853,35 @@ int64_t write_cryptpacket(Net_Crypto *c, int crypt_connection_id, const uint8_t
                           uint8_t congestion_control)
 {
     if (length == 0) {
+        // We need at least a packet id.
+        LOGGER_ERROR(c->log, "rejecting empty packet for crypto connection %d", crypt_connection_id);
         return -1;
     }
 
     if (data[0] < PACKET_ID_RANGE_LOSSLESS_START || data[0] > PACKET_ID_RANGE_LOSSLESS_END) {
+        LOGGER_ERROR(c->log, "rejecting lossless packet with out-of-range id %d", data[0]);
         return -1;
     }
 
     Crypto_Connection *conn = get_crypto_connection(c, crypt_connection_id);
 
     if (conn == nullptr) {
+        LOGGER_WARNING(c->log, "invalid crypt connection id %d", crypt_connection_id);
         return -1;
     }
 
     if (conn->status != CRYPTO_CONN_ESTABLISHED) {
+        LOGGER_WARNING(c->log, "attempted to send packet to non-established connection %d", crypt_connection_id);
         return -1;
     }
 
     if (congestion_control && conn->packets_left == 0) {
+        LOGGER_ERROR(c->log, "congestion control: rejecting packet of length %d on crypt connection %d", length,
+                     crypt_connection_id);
         return -1;
     }
 
-    int64_t ret = send_lossless_packet(c, crypt_connection_id, data, length, congestion_control);
+    const int64_t ret = send_lossless_packet(c, crypt_connection_id, data, length, congestion_control);
 
     if (ret == -1) {
         return -1;

toxcore/network.c

@@ -670,7 +670,7 @@ static int receivepacket(const Logger *log, Socket sock, IP_Port *ip_port, uint8
 
         if (!should_ignore_recv_error(error)) {
             char *strerror = net_new_strerror(error);
-            LOGGER_ERROR(log, "Unexpected error reading from socket: %u, %s", error, strerror);
+            LOGGER_ERROR(log, "unexpected error reading from socket: %u, %s", error, strerror);
             net_kill_strerror(strerror);
         }
 
@@ -867,7 +867,7 @@ Networking_Core *new_networking_ex(const Logger *log, const IP *ip, uint16_t por
     if (!sock_valid(temp->sock)) {
         int neterror = net_error();
         char *strerror = net_new_strerror(neterror);
-        LOGGER_ERROR(log, "Failed to get a socket?! %d, %s", neterror, strerror);
+        LOGGER_ERROR(log, "failed to get a socket?! %d, %s", neterror, strerror);
         net_kill_strerror(strerror);
         free(temp);
 
@@ -884,11 +884,11 @@ Networking_Core *new_networking_ex(const Logger *log, const IP *ip, uint16_t por
     int n = 1024 * 1024 * 2;
 
     if (setsockopt(temp->sock.socket, SOL_SOCKET, SO_RCVBUF, (const char *)&n, sizeof(n)) != 0) {
-        LOGGER_WARNING(log, "Failed to set socket option %d", SO_RCVBUF);
+        LOGGER_ERROR(log, "failed to set socket option %d", SO_RCVBUF);
     }
 
     if (setsockopt(temp->sock.socket, SOL_SOCKET, SO_SNDBUF, (const char *)&n, sizeof(n)) != 0) {
-        LOGGER_WARNING(log, "Failed to set socket option %d", SO_SNDBUF);
+        LOGGER_ERROR(log, "failed to set socket option %d", SO_SNDBUF);
     }
 
 #endif
@@ -898,7 +898,7 @@ Networking_Core *new_networking_ex(const Logger *log, const IP *ip, uint16_t por
     int broadcast = 1;
 
     if (setsockopt(temp->sock.socket, SOL_SOCKET, SO_BROADCAST, (const char *)&broadcast, sizeof(broadcast)) != 0) {
-        LOGGER_WARNING(log, "Failed to set socket option %d", SO_BROADCAST);
+        LOGGER_ERROR(log, "failed to set socket option %d", SO_BROADCAST);
     }
 
 #endif
@@ -1047,7 +1047,7 @@ Networking_Core *new_networking_ex(const Logger *log, const IP *ip, uint16_t por
     char ip_str[IP_NTOA_LEN];
     int neterror = net_error();
     char *strerror = net_new_strerror(neterror);
-    LOGGER_ERROR(log, "Failed to bind socket: %d, %s IP: %s port_from: %u port_to: %u", neterror, strerror,
+    LOGGER_ERROR(log, "failed to bind socket: %d, %s IP: %s port_from: %u port_to: %u", neterror, strerror,
                  ip_ntoa(ip, ip_str, sizeof(ip_str)), port_from, port_to);
     net_kill_strerror(strerror);
     kill_networking(temp);