adjustments for debugging

uniba-swt · Nov 27, 2024 · 8702c37 · 8702c37
1 parent cd788cb
commit 8702c37
Show file tree

Hide file tree

Showing 3 changed files with 71 additions and 9 deletions.
diff --git a/src/state/bidib_state_setter.c b/src/state/bidib_state_setter.c
@@ -435,6 +435,8 @@ void bidib_state_lc_stat(t_bidib_node_address node_address, t_bidib_peripheral_p
 			bidib_state_get_peripheral_mapping_ref_by_port(node_address, port);
 	if (peripheral_mapping != NULL &&
 	    (peripheral_state = bidib_state_get_peripheral_state_ref(peripheral_mapping->id->str)) != NULL) {
+		///TODO: Does this cause a memory leak? maybe not, as it points to memory allocated for
+		// the aspect mapping probably. Is it assigned/malloc'd elsewhere?
 		peripheral_state->data.state_id = NULL;
 		t_bidib_aspect *aspect_mapping;
 		for (size_t i = 0; i < peripheral_mapping->aspects->len; i++) {
@@ -449,9 +451,10 @@ void bidib_state_lc_stat(t_bidib_node_address node_address, t_bidib_peripheral_p
 			                "Aspect 0x%02x of peripheral %s is not mapped in config files",
 			                portstat, peripheral_mapping->id->str);
 		} else {
-			syslog_libbidib(LOG_INFO,
-			                "Feedback for action id %d: Peripheral: %s has aspect: %s (0x%02x)",
-			                action_id, peripheral_mapping->id->str, aspect_mapping->id->str, portstat);
+			// Temporarily disabled for debugging (less logs to read)
+			//syslog_libbidib(LOG_INFO,
+			//                "Feedback for action id %d: Peripheral: %s has aspect: %s (0x%02x)",
+			//                action_id, peripheral_mapping->id->str, aspect_mapping->id->str, portstat);
 		}
 		peripheral_state->data.state_value = portstat;
 	} else {

diff --git a/src/transmission/bidib_transmission_receive.c b/src/transmission/bidib_transmission_receive.c
@@ -418,8 +418,8 @@ void bidib_handle_received_message(uint8_t *message, uint8_t type,
 			break;
 		case MSG_LC_STAT:
 			// update state
-			bidib_log_received_message(addr_stack, seqnum, type, LOG_DEBUG,
-			                           message, action_id);
+			//bidib_log_received_message(addr_stack, seqnum, type, LOG_DEBUG,
+			//                           message, action_id);
 			peripheral_port.port0 = message[data_index];
 			peripheral_port.port1 = message[data_index + 1];
 			bidib_state_lc_stat(node_address, peripheral_port, message[data_index + 2], action_id);
@@ -451,7 +451,8 @@ void bidib_handle_received_message(uint8_t *message, uint8_t type,
 			break;
 		case MSG_BM_FREE:
 			// update state
-			bidib_log_received_message(addr_stack, seqnum, type, LOG_INFO,
+			///TODO: keep at debug level or move back to info?
+			bidib_log_received_message(addr_stack, seqnum, type, LOG_DEBUG,
 			                           message, action_id);
 			bidib_state_bm_occ(node_address, message[data_index], false);
 			pthread_rwlock_rdlock(&bidib_state_boards_rwlock);
@@ -730,6 +731,9 @@ static void bidib_split_packet(const uint8_t *const buffer, size_t buffer_size)
 		if (msg_read_in_us + node_update_us + handle_receive_us > slow_processing_threshold_us) {
 			// In case the processing steps above take above the specified threshold, 
 			// i.e., longer than expected, log the time taken for each of the three steps.
+			syslog_libbidib(LOG_WARNING, 
+			                "bidib_split_packet took longer than threshold %llu us for message of type %s", 
+			                slow_processing_threshold_us, bidib_message_string_mapping[type]);
 			syslog_libbidib(LOG_WARNING, "bidib_split_packet msg-read-in:    %llu us\n", msg_read_in_us);
 			syslog_libbidib(LOG_WARNING, "bidib_split_packet node-update:    %llu us\n", node_update_us);
 			syslog_libbidib(LOG_WARNING, "bidib_split_packet handle-receive: %llu us\n", handle_receive_us);
@@ -781,7 +785,9 @@ static void bidib_receive_packet(void) {
 		return;
 	}
 
-	syslog_libbidib(LOG_DEBUG, "%s", "Received packet");
+	struct timespec tv;
+	clock_gettime(CLOCK_MONOTONIC, &tv);
+	syslog_libbidib(LOG_DEBUG, "Received packet, at time %ld.%.5ld", tv.tv_sec, tv.tv_nsec);
 
 	if (crc == 0x00) {
 		// Split packet in messages and add them to queue, exclude crc sum

diff --git a/test/physical/test_common.c b/test/physical/test_common.c
@@ -181,20 +181,73 @@ bool testsuite_trainReady(const char *train, const char *segment) {
 	}
 }
 
-void testsuite_driveTo(const char *segment, int speed, const char *train) {
+void testsuite_driveTo_old(const char *segment, int speed, const char *train) {
 	syslog(LOG_WARNING, "libbidib test: Drive %s to %s at speed %d", train, segment, speed);
 	bidib_set_train_speed(train, speed, "master");
 	bidib_flush();
+	long counter = 0;
 	while (1) {
 		t_bidib_train_position_query trainPosition = bidib_get_train_position(train);
 		for (size_t i = 0; i < trainPosition.length; i++) {
 			if (!strcmp(segment, trainPosition.segments[i])) {
+				struct timespec tv;
+				clock_gettime(CLOCK_MONOTONIC, &tv);
 				bidib_free_train_position_query(trainPosition);
-				syslog(LOG_WARNING, "libbidib test: Drive %s to %s at speed %d - REACHED TARGET", train, segment, speed);
+				syslog(LOG_WARNING, 
+				       "libbidib test: Drive %s to %s at speed %d - REACHED TARGET - detected at time %ld.%.5ld", 
+				       train, segment, speed, tv.tv_sec, tv.tv_nsec);
 				return;
 			}
 		}
 		bidib_free_train_position_query(trainPosition);
+
+		if (counter++ % 4 == 0) {
+			struct timespec tv;
+			clock_gettime(CLOCK_MONOTONIC, &tv);
+			syslog(LOG_WARNING, 
+			       "libbidib test: Drive %s to %s at speed %d - waiting for train to arrive, time %ld.%.5ld", 
+			       train, segment, speed, tv.tv_sec, tv.tv_nsec);
+		}
+
+		usleep(TRAIN_WAITING_TIME_US);
+	}
+}
+
+void testsuite_driveTo(const char *segment, int speed, const char *train) {
+	// This driveTo impl works by querying the segment state repeatedly, not the train position.
+	// -> bidib_get_segment_state does not need to lock the trainstate rwlock, thus hopefully
+	//    reducing lock contention.
+	syslog(LOG_WARNING, "libbidib test: Drive %s to %s at speed %d", train, segment, speed);
+	bidib_set_train_speed(train, speed, "master");
+	bidib_flush();
+	t_bidib_dcc_address_query tr_dcc_addr = bidib_get_train_dcc_addr(train);
+	t_bidib_dcc_address dcc_address;
+	long counter = 0;
+	while (1) {
+		t_bidib_segment_state_query seg_query = bidib_get_segment_state(segment);
+		for (size_t j = 0; j < seg_query.data.dcc_address_cnt; j++) {
+			dcc_address = seg_query.data.dcc_addresses[j];
+			if (tr_dcc_addr.dcc_address.addrh == dcc_address.addrh 
+			    &&  tr_dcc_addr.dcc_address.addrl == dcc_address.addrl) {
+				struct timespec tv;
+				clock_gettime(CLOCK_MONOTONIC, &tv);
+				bidib_free_segment_state_query(seg_query);
+				syslog(LOG_WARNING, 
+				       "libbidib test: Drive %s to %s at speed %d - REACHED TARGET - detected at time %ld.%.5ld", 
+				       train, segment, speed, tv.tv_sec, tv.tv_nsec);
+				return;
+			}
+		}
+		bidib_free_segment_state_query(seg_query);
+
+		if (counter++ % 4 == 0) {
+			struct timespec tv;
+			clock_gettime(CLOCK_MONOTONIC, &tv);
+			syslog(LOG_WARNING, 
+			       "libbidib test: Drive %s to %s at speed %d - waiting for train to arrive, time %ld.%.5ld", 
+			       train, segment, speed, tv.tv_sec, tv.tv_nsec);
+		}
+
 		usleep(TRAIN_WAITING_TIME_US);
 	}
 }