chore: fix debuglog usage

runtime/Makefile

@@ -13,7 +13,7 @@ USE_MEM = USE_MEM_VM
 CFLAGS = ${OPTFLAGS} -D${USE_MEM} -I${INC} -pthread
 CFLAGS += -D${ARCH}
 CFILES += ${RTDIR}/arch/${ARCH}/*.c
-#CFLAGS += -DDEBUG 
+CFLAGS += -DDEBUG 
 CFLAGS += -D_GNU_SOURCE
 #CFLAGS += -DLOG_TO_FILE
 #CFLAGS += -DUSE_HTTP_UVIO #-DUSE_HTTP_SYNC

runtime/include/arch/x86_64/context.h

@@ -1,6 +1,7 @@
 #pragma once
 
 #include "arch/common.h"
+#include "types.h"
 
 #define ARCH_SIG_JMP_OFF 8
 
@@ -55,6 +56,11 @@ arch_context_switch(struct arch_context *current, struct arch_context *next)
 	/* Assumption: Software Interrupts are disabled by caller */
 	assert(software_interrupt_is_disabled);
 
+	if (next->variant == ARCH_CONTEXT_QUICK && (next->regs[UREG_RIP] == 0 || next->regs[UREG_RSP] == 0)) {
+		debuglog("Next Context was Quick Variant, but data was invalid.");
+		assert(0);
+	}
+
 	/* if both current and next are NULL, there is no state change */
 	assert(current != NULL || next != NULL);
 

runtime/include/sandbox_request.h

@@ -43,6 +43,6 @@ sandbox_request_allocate(struct module *module, char *arguments, int socket_desc
 	sandbox_request->absolute_deadline         = request_arrival_timestamp
 	                                     + module->relative_deadline_us * runtime_processor_speed_MHz;
 
-	debuglog("[%p: %s]\n", sandbox_request, sandbox_request->module->name);
+	debuglog("%s:%d @ %p\n", sandbox_request->module->name, sandbox_request->module->port, sandbox_request);
 	return sandbox_request;
 }

runtime/include/types.h

@@ -89,11 +89,12 @@ typedef void (*mod_libc_fn_t)(int32_t, int32_t);
  */
 #ifdef DEBUG
 #ifdef LOG_TO_FILE
-#define debuglog(fmt, ...)                                                                                  \
-	dprintf(runtime_log_file_descriptor, "(%d,%lu) %s: " fmt, sched_getcpu(), pthread_self(), __func__, \
-	        ##__VA_ARGS__)
+#define debuglog(fmt, ...)                                                                                      \
+	dprintf(runtime_log_file_descriptor, "CPU: %02d, Thread: %x> %s: " fmt, sched_getcpu(), pthread_self(), \
+	        __func__, ##__VA_ARGS__)
 #else /* !LOG_TO_FILE */
-#define debuglog(fmt, ...) printf("(%d,%lu) %s: " fmt, sched_getcpu(), pthread_self(), __func__, ##__VA_ARGS__)
+#define debuglog(fmt, ...) \
+	printf("CPU: %02d, Thread: 0x%lx> %s: " fmt, sched_getcpu(), pthread_self(), __func__, ##__VA_ARGS__)
 #endif /* LOG_TO_FILE */
 #else  /* !DEBUG */
 #define debuglog(fmt, ...)

runtime/src/arch_context.c

@@ -11,6 +11,7 @@
  */
 void __attribute__((noinline)) __attribute__((noreturn)) arch_context_mcontext_restore(void)
 {
+	debuglog("Sending SIGUSR1");
 	pthread_kill(pthread_self(), SIGUSR1);
 	assert(false);
 }

runtime/src/local_runqueue_list.c

@@ -84,7 +84,8 @@ void
 local_runqueue_list_append(struct sandbox *sandbox_to_append)
 {
 	assert(ps_list_singleton_d(sandbox_to_append));
-	debuglog("(%d,%lu) %s: run %p, %s\n", sched_getcpu(), pthread_self(), __func__, s, s->module->name);
+	debuglog("(%d,%lu) %s: run %p, %s\n", sched_getcpu(), pthread_self(), __func__, sandbox_to_append,
+	         sandbox_to_append->module->name);
 	ps_list_head_append_d(&local_runqueue_list, sandbox_to_append);
 }
 

runtime/src/local_runqueue_minheap.c

@@ -142,16 +142,15 @@ local_runqueue_minheap_preempt(ucontext_t *user_context)
 	/* If we're able to get a sandbox request with a tighter deadline, preempt the current context and run it */
 	struct sandbox_request *sandbox_request;
 	if (global_deadline < local_deadline) {
-		debuglog("Thread %lu | Sandbox %lu | Had deadline of %lu. Trying to preempt for request with %lu\n",
-		         pthread_self(), current_sandbox->allocation_timestamp, local_deadline, global_deadline);
+		debuglog("Sandbox %lu has deadline of %lu. Trying to preempt for request with %lu\n",
+		         current_sandbox->request_arrival_timestamp, local_deadline, global_deadline);
 
 		int return_code = global_request_scheduler_remove(&sandbox_request);
 
 		/* If we were unable to get a sandbox_request, exit */
 		if (return_code != 0) goto done;
 
-		debuglog("Thread %lu Preempted %lu for %lu\n", pthread_self(), local_deadline,
-		         sandbox_request->absolute_deadline);
+		debuglog("Preempted %lu for %lu\n", local_deadline, sandbox_request->absolute_deadline);
 
 		/* Allocate the request */
 		struct sandbox *next_sandbox = sandbox_allocate(sandbox_request);

runtime/src/sandbox.c

@@ -66,7 +66,7 @@ sandbox_parse_http_request(struct sandbox *sandbox, size_t length)
 
 /**
  * Receive and Parse the Request for the current sandbox
- * @return 1 on success, 0 if no context, < 0 on failure.
+ * @return 1 on success, < 0 on failure.
  */
 static inline int
 sandbox_receive_and_parse_client_request(struct sandbox *sandbox)
@@ -78,9 +78,8 @@ sandbox_receive_and_parse_client_request(struct sandbox *sandbox)
 	int r = 0;
 	r = recv(sandbox->client_socket_descriptor, (sandbox->request_response_data), sandbox->module->max_request_size,
 	         0);
-	if (r <= 0) {
-		if (r < 0) perror("Error reading request data from client socket");
-		if (r == 0) perror("Client unexpectedly returned zero bytes");
+	if (r < 0) {
+		perror("Error reading request data from client socket");
 		return r;
 	}
 	while (r > 0) {

runtime/src/software_interrupt.c

@@ -81,7 +81,6 @@ software_interrupt_handle_signals(int signal_type, siginfo_t *signal_info, void
 			assert(signal_info->si_code == SI_TKILL);
 		}
 
-		debuglog("alrm:%d\n", software_interrupt_SIGALRM_count);
 		software_interrupt_SIGALRM_count++;
 
 		/* NOOP if software interrupts not enabled */

runtime/src/worker_thread.c

@@ -60,8 +60,8 @@ worker_thread_switch_to_sandbox(struct sandbox *next_sandbox)
 		/* Switching from "Base Context" */
 		current_sandbox_set(next_sandbox);
 
-		debuglog("Thread %lu | Switching from Base Context to Sandbox %lu\n", pthread_self(),
-		         next_sandbox->allocation_timestamp);
+		debuglog("Base Context > Sandbox %lu (%d variant)\n", next_sandbox->request_arrival_timestamp,
+		         next_context->variant);
 
 		arch_context_switch(NULL, next_context);
 
@@ -76,8 +76,8 @@ worker_thread_switch_to_sandbox(struct sandbox *next_sandbox)
 
 		current_sandbox_set(next_sandbox);
 
-		debuglog("Thread %lu | Switching from Sandbox %lu to Sandbox %lu\n", pthread_self(),
-		         current_sandbox->allocation_timestamp, next_sandbox->allocation_timestamp);
+		debuglog("Sandbox %lu > Sandbox %lu\n", current_sandbox->request_arrival_timestamp,
+		         next_sandbox->request_arrival_timestamp);
 
 		/* Switch to the associated context. */
 		arch_context_switch(current_context, next_context);
@@ -93,7 +93,7 @@ worker_thread_switch_to_sandbox(struct sandbox *next_sandbox)
 static inline void
 worker_thread_switch_to_base_context()
 {
-	software_interrupt_disable();
+	assert(!software_interrupt_is_enabled());
 	assert(worker_thread_is_switching_context == false);
 	worker_thread_is_switching_context = true;
 
@@ -105,8 +105,7 @@ worker_thread_switch_to_base_context()
 
 	current_sandbox_set(NULL);
 
-	debuglog("Thread %lu | Switching from Sandbox %lu to Base Context\n", pthread_self(),
-	         current_sandbox->allocation_timestamp);
+	debuglog("Sandbox %lu > Base Context\n", current_sandbox->request_arrival_timestamp);
 
 	arch_context_switch(&current_sandbox->ctxt, &worker_thread_base_context);
 
@@ -155,8 +154,8 @@ worker_thread_block_current_sandbox(void)
 
 	/* Switch to the next sandbox */
 	struct sandbox *next_sandbox = local_runqueue_get_next();
-	debuglog("[%p: %next_sandbox, %p: %next_sandbox]\n", current_sandbox, current_sandbox->module->name,
-	         next_sandbox, next_sandbox ? next_sandbox->module->name : "");
+	debuglog("[%p: %p, %p: %p]\n", current_sandbox, current_sandbox->module->name, next_sandbox,
+	         next_sandbox ? next_sandbox->module->name : "");
 
 	/* If able to get one, switch to it. Otherwise, return to base context */
 	if (next_sandbox == NULL) {
@@ -273,6 +272,7 @@ __attribute__((noreturn)) void
 worker_thread_on_sandbox_exit(struct sandbox *exiting_sandbox)
 {
 	assert(exiting_sandbox);
+	debuglog("Exiting %lu\n", exiting_sandbox->request_arrival_timestamp);
 
 	/* Because the stack is still in use, only unmap linear memory and defer free resources until "main
 	function execution" */