From 8702c37e91949d863a4b622ae88fa64e9aab2c52 Mon Sep 17 00:00:00 2001 From: Bernhard Luedtke Date: Wed, 27 Nov 2024 14:34:10 +0100 Subject: [PATCH] adjustments for debugging --- src/state/bidib_state_setter.c | 9 ++- src/transmission/bidib_transmission_receive.c | 14 +++-- test/physical/test_common.c | 57 ++++++++++++++++++- 3 files changed, 71 insertions(+), 9 deletions(-) diff --git a/src/state/bidib_state_setter.c b/src/state/bidib_state_setter.c index 2baf7fb..015b890 100644 --- 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 index b28163d..f4fb476 100644 --- 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 index 8dfc27e..bfc4a6a 100644 --- 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); } }