TSCH: logging, and code style fixes

This commit is contained in:
Simon Duquennoy 2017-06-26 16:39:52 +02:00
parent eadc38ac1f
commit 207d166ce6
5 changed files with 52 additions and 14 deletions

View File

@ -106,7 +106,7 @@ tsch_log_process_pending(void)
log->rx.is_unicast == 0 ? "bc" : "uc", log->rx.is_data, log->rx.sec_level);
log_lladdr_compact(&log->rx.src);
printf("->");
log_lladdr_compact(&linkaddr_node_addr);
log_lladdr_compact(log->rx.is_unicast ? &linkaddr_node_addr : NULL);
printf(", len %u, seq %u",
log->rx.datalen, log->rx.seqno);
if(log->rx.drift_used) {

View File

@ -358,13 +358,13 @@ tsch_packet_parse_eb(const uint8_t *buf, int buf_size,
if(frame->fcf.frame_version < FRAME802154_IEEE802154E_2012
|| frame->fcf.frame_type != FRAME802154_BEACONFRAME) {
LOG_ERR("! parse_eb: frame is not a valid TSCH beacon. Frame version %u, type %u, FCF %02x %02x\n",
LOG_INFO("! parse_eb: frame is not a valid TSCH beacon. Frame version %u, type %u, FCF %02x %02x\n",
frame->fcf.frame_version, frame->fcf.frame_type, buf[0], buf[1]);
LOG_ERR("! parse_eb: frame was from 0x%x/", frame->src_pid);
LOG_ERR_LLADDR((const linkaddr_t *)&frame->src_addr);
LOG_ERR_(" to 0x%x/", frame->dest_pid);
LOG_ERR_LLADDR((const linkaddr_t *)&frame->dest_addr);
LOG_ERR_("\n");
LOG_INFO("! parse_eb: frame was from 0x%x/", frame->src_pid);
LOG_INFO_LLADDR((const linkaddr_t *)&frame->src_addr);
LOG_INFO_(" to 0x%x/", frame->dest_pid);
LOG_INFO_LLADDR((const linkaddr_t *)&frame->dest_addr);
LOG_INFO_("\n");
return 0;
}

View File

@ -88,6 +88,10 @@ extern uint8_t tsch_hopping_sequence[TSCH_HOPPING_SEQUENCE_MAX_LEN];
extern struct tsch_asn_divisor_t tsch_hopping_sequence_length;
/* TSCH timeslot timing (in rtimer ticks) */
extern rtimer_clock_t tsch_timing[tsch_ts_elements_count];
/* Statistics on the current session */
unsigned long tx_count;
unsigned long rx_count;
unsigned long sync_count;
/* TSCH processes */
PROCESS_NAME(tsch_process);

View File

@ -557,6 +557,7 @@ PT_THREAD(tsch_tx_slot(struct pt *pt, struct rtimer *t))
TSCH_DEBUG_TX_EVENT();
/* send packet already in radio tx buffer */
mac_tx_status = NETSTACK_RADIO.transmit(packet_len);
tx_count++;
/* Save tx timestamp */
tx_start_time = current_slot_start + tsch_timing[tsch_ts_tx_offset];
/* calculate TX duration based on sent packet len */
@ -838,6 +839,7 @@ PT_THREAD(tsch_rx_slot(struct pt *pt, struct rtimer *t))
if(linkaddr_cmp(&destination_address, &linkaddr_node_addr)
|| linkaddr_cmp(&destination_address, &linkaddr_null)) {
int do_nack = 0;
rx_count++;
estimated_drift = RTIMER_CLOCK_DIFF(expected_rx_time, rx_start_time);
#if TSCH_TIMESYNC_REMOVE_JITTER
@ -895,6 +897,7 @@ PT_THREAD(tsch_rx_slot(struct pt *pt, struct rtimer *t))
/* Save estimated drift */
drift_correction = -estimated_drift;
is_drift_correction_used = 1;
sync_count++;
tsch_timesync_update(n, since_last_timesync, -estimated_drift);
tsch_schedule_keepalive();
}
@ -1082,7 +1085,7 @@ tsch_slot_operation_start(void)
/* Update current slot start */
prev_slot_start = current_slot_start;
current_slot_start += time_to_next_active_slot;
} while(!tsch_schedule_slot_operation(&slot_operation_timer, prev_slot_start, time_to_next_active_slot, "association"));
} while(!tsch_schedule_slot_operation(&slot_operation_timer, prev_slot_start, time_to_next_active_slot, "assoc"));
}
/*---------------------------------------------------------------------------*/
/* Start actual slot operation */

View File

@ -132,6 +132,8 @@ int tsch_is_initialized = 0;
int tsch_is_coordinator = 0;
/* Are we associated to a TSCH network? */
int tsch_is_associated = 0;
/* Total number of associations since boot */
int tsch_association_count = 0;
/* Is the PAN running link-layer security? */
int tsch_is_pan_secured = LLSEC802154_ENABLED;
/* The current Absolute Slot Number (ASN) */
@ -149,6 +151,11 @@ static clock_time_t tsch_current_ka_timeout;
/* timer for sending keepalive messages */
static struct ctimer keepalive_timer;
/* Statistics on the current session */
unsigned long tx_count;
unsigned long rx_count;
unsigned long sync_count;
/* TSCH processes and protothreads */
PT_THREAD(tsch_scan(struct pt *pt));
PROCESS(tsch_process, "main process");
@ -247,12 +254,30 @@ keepalive_packet_sent(void *ptr, int status, int transmissions)
LOG_INFO("KA sent to ");
LOG_INFO_LLADDR(packetbuf_addr(PACKETBUF_ADDR_RECEIVER));
LOG_INFO_(", st %d-%d\n", status, transmissions);
/* We got no ack, try to recover by switching to the last neighbor we received an EB from */
if(status != MAC_TX_OK) {
if(linkaddr_cmp(&last_eb_nbr_addr, &linkaddr_null)) {
LOG_WARN("not able to re-synchronize, received no EB from other neighbors\n");
} else {
LOG_WARN("re-synchronizing on ");
LOG_WARN_LLADDR(&last_eb_nbr_addr);
LOG_WARN_("\n");
/* We simply pick the last neighbor we receiver sync information from */
tsch_queue_update_time_source(&last_eb_nbr_addr);
tsch_join_priority = last_eb_nbr_jp + 1;
/* Try to get in sync ASAP */
tsch_schedule_keepalive_immediately();
return;
}
}
tsch_schedule_keepalive();
}
/*---------------------------------------------------------------------------*/
/* Prepare and send a keepalive message */
static void
keepalive_send()
keepalive_send(void *ptr)
{
if(tsch_is_associated) {
struct tsch_neighbor *n = tsch_queue_get_time_source();
@ -268,7 +293,7 @@ keepalive_send()
/*---------------------------------------------------------------------------*/
/* Set ctimer to send a keepalive message after expiration of TSCH_KEEPALIVE_TIMEOUT */
void
tsch_schedule_keepalive()
tsch_schedule_keepalive(void)
{
/* Pick a delay in the range [tsch_current_ka_timeout*0.9, tsch_current_ka_timeout[ */
if(!tsch_is_coordinator && tsch_is_associated && tsch_current_ka_timeout > 0) {
@ -410,7 +435,7 @@ tsch_rx_process_pending()
/*---------------------------------------------------------------------------*/
/* Pass sent packets to upper layer */
static void
tsch_tx_process_pending()
tsch_tx_process_pending(void)
{
int16_t dequeued_index;
/* Loop on accessing (without removing) a pending input packet */
@ -461,7 +486,8 @@ tsch_disassociate(void)
if(tsch_is_associated == 1) {
tsch_is_associated = 0;
process_post(&tsch_process, PROCESS_EVENT_POLL, NULL);
LOG_WARN("leaving the network\n");
LOG_WARN("leaving the network, stats: tx %lu, rx %lu, sync %lu\n",
tx_count, rx_count, sync_count);
}
}
/*---------------------------------------------------------------------------*/
@ -605,6 +631,9 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
/* Update global flags */
tsch_is_associated = 1;
tsch_is_pan_secured = frame.fcf.security_enabled;
tx_count = 0;
rx_count = 0;
sync_count = 0;
/* Start sending keep-alives now that tsch_is_associated is set */
tsch_schedule_keepalive();
@ -613,7 +642,9 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
TSCH_CALLBACK_JOINING_NETWORK();
#endif
LOG_INFO("association done, sec %u, PAN ID %x, asn-%x.%lx, jp %u, timeslot id %u, hopping id %u, slotframe len %u with %u links, from ",
tsch_association_count++;
LOG_INFO("association done (%u), sec %u, PAN ID %x, asn-%x.%lx, jp %u, timeslot id %u, hopping id %u, slotframe len %u with %u links, from ",
tsch_association_count,
tsch_is_pan_secured,
frame.src_pid,
tsch_current_asn.ms1b, tsch_current_asn.ls4b, tsch_join_priority,
@ -692,7 +723,7 @@ PT_THREAD(tsch_scan(struct pt *pt))
NETSTACK_RADIO.get_object(RADIO_PARAM_LAST_PACKET_TIMESTAMP, &t0, sizeof(rtimer_clock_t));
/* Parse EB and attempt to associate */
LOG_INFO("association: received packet (%u bytes) on channel %u\n", input_eb.len, current_channel);
LOG_INFO("scan: received packet (%u bytes) on channel %u\n", input_eb.len, current_channel);
tsch_associate(&input_eb, t0);
}