Added some storage+debugging to track what happens before we disconnect. Maybe I'll learn something.

git-svn-id: https://www.unprompted.com/svn/projects/tildefriends/trunk@4146 ed5197a5-7fde-0310-b194-c3ffbd925b24

core/core.js

@@ -843,6 +843,10 @@ loadSettings().then(function() {
 			var data = trace();
 			response.writeHead(200, {"Content-Type": "application/json; charset=utf-8", "Content-Length": data.length.toString()});
 			return response.end(data);
+		} else if (match = /^\/disconnections$/.exec(request.uri)) {
+			var data = utf8Encode(JSON.stringify(disconnectionsDebug(), null, 2));
+			response.writeHead(200, {"Content-Type": "application/json; charset=utf-8", "Content-Length": data.byteLength.toString()});
+			return response.end(data);
 		} else if (match = /^\/debug$/.exec(request.uri)) {
 			var data = JSON.stringify(getDebug(), null, 2);
 			response.writeHead(200, {"Content-Type": "application/json; charset=utf-8", "Content-Length": data.length.toString()});

src/ssb.c

@@ -71,12 +71,31 @@ typedef enum {
 enum {
 	k_connections_changed_callbacks_max = 8,
 	k_tf_ssb_rpc_message_body_length_max = 1 * 1024 * 1024,
+	k_debug_close_message_count = 32,
+	k_debug_close_connection_count = 8,
 };
 
 typedef struct _tf_ssb_broadcast_t tf_ssb_broadcast_t;
 typedef struct _tf_ssb_connection_t tf_ssb_connection_t;
 typedef struct _tf_ssb_request_t tf_ssb_request_t;
 
+typedef struct _tf_ssb_debug_message_t
+{
+	bool outgoing;
+	int flags;
+	int32_t request_number;
+	size_t size;
+	uint8_t data[];
+} tf_ssb_debug_message_t;
+
+typedef struct _tf_ssb_debug_close_t
+{
+	char id[k_id_base64_len];
+	char tunnel[k_id_base64_len];
+	char reason[128];
+	tf_ssb_debug_message_t* messages[k_debug_close_message_count];
+} tf_ssb_debug_close_t;
+
 typedef struct _tf_ssb_request_t
 {
 	int32_t request_number;
@@ -196,6 +215,8 @@ typedef struct _tf_ssb_t
 
 	tf_ssb_broadcasts_changed_callback_node_t* broadcasts_changed;
 	int broadcasts_changed_count;
+
+	tf_ssb_debug_close_t debug_close[k_debug_close_connection_count];
 } tf_ssb_t;
 
 typedef struct _tf_ssb_connection_message_request_t
@@ -276,6 +297,8 @@ typedef struct _tf_ssb_connection_t
 
 	tf_ssb_connection_scheduled_t* scheduled;
 	int scheduled_count;
+
+	tf_ssb_debug_message_t* debug_messages[k_debug_close_message_count];
 } tf_ssb_connection_t;
 
 static JSClassID _connection_class_id;
@@ -290,6 +313,53 @@ static void _tf_ssb_nonce_inc(uint8_t* nonce);
 static void _tf_ssb_write(tf_ssb_connection_t* connection, void* data, size_t size);
 static void _tf_ssb_connection_finalizer(JSRuntime* runtime, JSValue value);
 
+static void _tf_ssb_add_debug_close(tf_ssb_t* ssb, tf_ssb_connection_t* connection, const char* reason)
+{
+	for (int i = 0; i < k_debug_close_message_count; i++)
+	{
+		tf_free(ssb->debug_close[k_debug_close_connection_count - 1].messages[i]);
+	}
+	for (int i = k_debug_close_connection_count - 1; i > 0; i--)
+	{
+		ssb->debug_close[i] = ssb->debug_close[i - 1];
+	}
+	
+	tf_ssb_id_bin_to_str(ssb->debug_close[0].id, sizeof(ssb->debug_close[0].id), connection->serverpub);
+	if (connection->tunnel_connection)
+	{
+		tf_ssb_id_bin_to_str(ssb->debug_close[0].tunnel, sizeof(ssb->debug_close[0].tunnel), connection->tunnel_connection->serverpub);
+	}
+	else
+	{
+		memset(ssb->debug_close[0].tunnel, 0, sizeof(ssb->debug_close[0].tunnel));
+	}
+	memcpy(ssb->debug_close[0].messages, connection->debug_messages, sizeof(connection->debug_messages));
+	memset(connection->debug_messages, 0, sizeof(connection->debug_messages));
+	snprintf(ssb->debug_close[0].reason, sizeof(ssb->debug_close[0].reason), "%s", reason);
+}
+
+static void _tf_ssb_connection_add_debug_message(tf_ssb_connection_t* connection, bool outgoing, int flags, int32_t request_number, const uint8_t* data, size_t size)
+{
+	if (connection->debug_messages[k_debug_close_message_count - 1])
+	{
+		tf_free(connection->debug_messages[k_debug_close_message_count - 1]);
+	}
+	for (int i = k_debug_close_message_count - 1; i > 0; i--)
+	{
+		connection->debug_messages[i] = connection->debug_messages[i - 1];
+	}
+	tf_ssb_debug_message_t* message = tf_malloc(sizeof(tf_ssb_debug_message_t) + size);
+	*message = (tf_ssb_debug_message_t)
+	{
+		.outgoing = outgoing,
+		.flags = flags,
+		.request_number = request_number,
+		.size = size,
+	};
+	memcpy(message + 1, data, size);
+	connection->debug_messages[0] = message;
+}
+
 static void _tf_ssb_connection_send_close(tf_ssb_connection_t* connection)
 {
 	uint8_t message_enc[34];
@@ -316,6 +386,7 @@ static void _tf_ssb_connection_close(tf_ssb_connection_t* connection, const char
 		connection->state == k_tf_ssb_state_server_verified)
 	{
 		printf("Connection %s %p is closing: %s.\n", connection->name, connection, reason);
+		_tf_ssb_add_debug_close(connection->ssb, connection, reason);
 		connection->state = k_tf_ssb_state_closing;
 		_tf_ssb_connection_send_close(connection);
 	}
@@ -627,6 +698,7 @@ void tf_ssb_connection_rpc_send(tf_ssb_connection_t* connection, uint8_t flags,
 	{
 		printf(MAGENTA "%s RPC SEND" RESET " flags=%x RN=%d: [%zd B] %.*s\n", connection->name, flags, request_number, size, (flags & k_ssb_rpc_mask_type) == k_ssb_rpc_flag_binary ? 0 : (int)size, message);
 	}
+	_tf_ssb_connection_add_debug_message(connection, true, flags, request_number, message, size);
 	_tf_ssb_connection_box_stream_send(connection, combined, 1 + 2 * sizeof(uint32_t) + size);
 	tf_free(combined);
 	connection->ssb->rpc_out++;
@@ -1376,6 +1448,7 @@ static bool _tf_ssb_name_equals(JSContext* context, JSValue object, const char**
 static void _tf_ssb_connection_rpc_recv(tf_ssb_connection_t* connection, uint8_t flags, int32_t request_number, const uint8_t* message, size_t size)
 {
 	connection->ssb->rpc_in++;
+	_tf_ssb_connection_add_debug_message(connection, false, flags, request_number, message, size);
 	if (size == 0)
 	{
 		_tf_ssb_connection_close(connection, "rpc recv zero");
@@ -1740,6 +1813,12 @@ void _tf_ssb_connection_destroy(tf_ssb_connection_t* connection, const char* rea
 		connection->message_requests = NULL;
 		connection->message_requests_count = 0;
 
+		for (int i = 0; i < k_debug_close_message_count; i++)
+		{
+			tf_free(connection->debug_messages[i]);
+			connection->debug_messages[i] = NULL;
+		}
+
 		tf_free(connection);
 	}
 }
@@ -2206,6 +2285,13 @@ void tf_ssb_destroy(tf_ssb_t* ssb)
 		ssb->broadcasts_count--;
 		tf_free(broadcast);
 	}
+	for (int i = 0; i < k_debug_close_connection_count; i++)
+	{
+		for (int j = 0; j < k_debug_close_message_count; j++)
+		{
+			tf_free(ssb->debug_close[i].messages[j]);
+		}
+	}
 	tf_free(ssb);
 }
 
@@ -3267,3 +3353,39 @@ void tf_ssb_connection_set_ebt_send_clock(tf_ssb_connection_t* connection, JSVal
 	JS_FreeValue(context, connection->ebt_send_clock);
 	connection->ebt_send_clock = JS_DupValue(context, send_clock);
 }
+
+JSValue tf_ssb_get_disconnection_debug(tf_ssb_t* ssb, JSContext* context)
+{
+	JSValue result = JS_NewObject(context);
+	JSValue disconnections = JS_NewArray(context);
+	for (int i = 0; i < k_debug_close_connection_count; i++)
+	{
+		JSValue disconnection = JS_NewObject(context);
+		if (*ssb->debug_close[i].id)
+		{
+			JS_SetPropertyStr(context, disconnection, "id", JS_NewString(context, ssb->debug_close[i].id));
+			if (*ssb->debug_close[i].tunnel)
+			{
+				JS_SetPropertyStr(context, disconnection, "tunnel", JS_NewString(context, ssb->debug_close[i].tunnel));
+			}
+			JS_SetPropertyStr(context, disconnection, "reason", JS_NewString(context, ssb->debug_close[i].reason));
+			JSValue messages = JS_NewArray(context);
+			for (int j = 0; j < k_debug_close_message_count; j++)
+			{
+				if (ssb->debug_close[i].messages[j])
+				{
+					JSValue message = JS_NewObject(context);
+					JS_SetPropertyStr(context, message, "direction", JS_NewString(context, ssb->debug_close[i].messages[j]->outgoing ? "out" : "in"));
+					JS_SetPropertyStr(context, message, "flags", JS_NewInt32(context, ssb->debug_close[i].messages[j]->flags));
+					JS_SetPropertyStr(context, message, "request_number", JS_NewInt32(context, ssb->debug_close[i].messages[j]->request_number));
+					JS_SetPropertyStr(context, message, "payload", JS_NewStringLen(context, (const char*)ssb->debug_close[i].messages[j]->data, ssb->debug_close[i].messages[j]->size));
+					JS_SetPropertyUint32(context, messages, j, message);
+				}
+			}
+			JS_SetPropertyStr(context, disconnection, "messages", messages);
+		}
+		JS_SetPropertyUint32(context, disconnections, i, disconnection);
+	}
+	JS_SetPropertyStr(context, result, "disconnections", disconnections);
+	return result;
+}

src/ssb.h

@@ -182,3 +182,5 @@ JSClassID tf_ssb_get_connection_class_id();
 void tf_ssb_get_stats(tf_ssb_t* ssb, tf_ssb_stats_t* out_stats);
 
 tf_ssb_blob_wants_t* tf_ssb_connection_get_blob_wants_state(tf_ssb_connection_t* connection);
+
+JSValue tf_ssb_get_disconnection_debug(tf_ssb_t* ssb, JSContext* context);

src/task.c

@@ -826,6 +826,12 @@ static JSValue _tf_task_getDebug(JSContext* context, JSValueConst this_val, int
 	return result;
 }
 
+static JSValue _tf_task_disconnectionsDebug(JSContext* context, JSValueConst this_val, int argc, JSValueConst* argv)
+{
+	tf_task_t* task = JS_GetContextOpaque(context);
+	return tf_ssb_get_disconnection_debug(task->_ssb, context);
+}
+
 static JSValue _tf_task_getFile(JSContext* context, JSValueConst this_val, int argc, JSValueConst* argv)
 {
 	tf_task_t* task = JS_GetContextOpaque(context);
@@ -1572,6 +1578,7 @@ void tf_task_activate(tf_task_t* task)
 		JS_SetPropertyStr(context, global, "trace", JS_NewCFunction(context, _tf_task_trace, "trace", 1));
 		JS_SetPropertyStr(context, global, "getStats", JS_NewCFunction(context, _tf_task_getStats, "getStats", 0));
 		JS_SetPropertyStr(context, global, "getDebug", JS_NewCFunction(context, _tf_task_getDebug, "getDebug", 0));
+		JS_SetPropertyStr(context, global, "disconnectionsDebug", JS_NewCFunction(context, _tf_task_disconnectionsDebug, "disconnectionsDebug", 0));
 	}
 	else
 	{