giomba/nes-proj
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Use logging module for MAC layers

Browse Source
This commit is contained in:
Simon Duquennoy 2017-06-20 18:06:30 +02:00
parent 9f0177570d
commit 661f4c5023
16 changed files with 155 additions and 196 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

51
core/net/mac/csma/csma-output.c
View File

@ -50,22 +50,15 @@
#include "lib/list.h"
#include "lib/memb.h"
#include <string.h>
#include <stdio.h>
#if CONTIKI_TARGET_COOJA || CONTIKI_TARGET_COOJA_IP64
#include "lib/simEnvChange.h"
#include "sys/cooja_mt.h"
#endif /* CONTIKI_TARGET_COOJA || CONTIKI_TARGET_COOJA_IP64 */
#define DEBUG 0
#if DEBUG
#include <stdio.h>
#define PRINTF(...) printf(__VA_ARGS__)
#else /* DEBUG */
#define PRINTF(...)
#endif /* DEBUG */
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE_STR "CSMA"
#define LOG_LEVEL MAC_LOG_LEVEL
/* Constants of the IEEE 802.15.4 standard */
@ -179,7 +172,7 @@ send_one_packet(mac_callback_t sent, void *ptr)
if(NETSTACK_FRAMER.create() < 0) {
/* Failed to allocate space for headers */
PRINTF("csma: send failed, too large header\n");
LOG_ERR("csma: send failed, too large header\n");
ret = MAC_TX_ERR_FATAL;
} else {
#if CSMA_802154_AUTOACK
@ -251,7 +244,7 @@ send_one_packet(mac_callback_t sent, void *ptr)
}
}
} else {
PRINTF("csma tx noack\n");
LOG_WARN("csma tx noack\n");
}
}
break;
@ -297,7 +290,7 @@ transmit_from_queue(void *ptr)
if(n) {
struct packet_queue *q = list_head(n->packet_queue);
if(q != NULL) {
PRINTF("csma: preparing number %d %p, queue len %d\n", n->transmissions, q,
LOG_INFO("csma: preparing number %d %p, queue len %d\n", n->transmissions, q,
list_length(n->packet_queue));
/* Send first packet in the neighbor queue */
queuebuf_to_packetbuf(q->buf);
@ -321,7 +314,7 @@ schedule_transmission(struct neighbor_queue *n)
delay = random_rand() % delay;
}
PRINTF("csma: scheduling transmission in %u ticks, NB=%u, BE=%u\n",
LOG_INFO("csma: scheduling transmission in %u ticks, NB=%u, BE=%u\n",
(unsigned)delay, n->collisions, backoff_exponent);
ctimer_set(&n->transmit_timer, delay, transmit_from_queue, n);
}
@ -336,7 +329,7 @@ free_packet(struct neighbor_queue *n, struct packet_queue *p, int status)
queuebuf_free(p->buf);
memb_free(&metadata_memb, p->ptr);
memb_free(&packet_memb, p);
PRINTF("csma: free_queued_packet, queue length %d, free packets %d\n",
LOG_INFO("csma: free_queued_packet, queue length %d, free packets %d\n",
list_length(n->packet_queue), memb_numfree(&packet_memb));
if(list_head(n->packet_queue) != NULL) {
/* There is a next packet. We reset current tx information */
@ -368,15 +361,15 @@ tx_done(int status, struct packet_queue *q, struct neighbor_queue *n)
switch(status) {
case MAC_TX_OK:
PRINTF("csma: rexmit ok %d\n", n->transmissions);
LOG_INFO("csma: tx ok %d\n", n->transmissions);
break;
case MAC_TX_COLLISION:
case MAC_TX_NOACK:
PRINTF("csma: drop with status %d after %d transmissions, %d collisions\n",
LOG_WARN("csma: drop with status %d after %d transmissions, %d collisions\n",
status, n->transmissions, n->collisions);
break;
default:
PRINTF("csma: rexmit failed %d: %d\n", n->transmissions, status);
LOG_ERR("csma: tx failed %d: %d\n", n->transmissions, status);
break;
}
@ -412,7 +405,7 @@ collision(struct packet_queue *q, struct neighbor_queue *n,
if(n->transmissions >= metadata->max_transmissions) {
tx_done(MAC_TX_COLLISION, q, n);
} else {
PRINTF("csma: rexmit collision %d\n", n->transmissions);
LOG_INFO("csma: tx collision %d\n", n->transmissions);
rexmit(q, n);
}
}
@ -430,7 +423,7 @@ noack(struct packet_queue *q, struct neighbor_queue *n, int num_transmissions)
if(n->transmissions >= metadata->max_transmissions) {
tx_done(MAC_TX_NOACK, q, n);
} else {
PRINTF("csma: rexmit noack %d\n", n->transmissions);
LOG_INFO("csma: tx noack %d\n", n->transmissions);
rexmit(q, n);
}
}
@ -464,11 +457,11 @@ packet_sent(void *ptr, int status, int num_transmissions)
}
if(q == NULL) {
PRINTF("csma: seqno %d not found\n",
LOG_WARN("csma: seqno %d not found\n",
packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO));
return;
} else if(q->ptr == NULL) {
PRINTF("csma: no metadata\n");
LOG_WARN("csma: no metadata\n");
return;
}
@ -546,7 +539,7 @@ csma_output_packet(mac_callback_t sent, void *ptr)
metadata->cptr = ptr;
list_add(n->packet_queue, q);
PRINTF("csma: send_packet, queue length %d, free packets %d\n",
LOG_INFO("csma: send_packet, queue length %d, free packets %d\n",
list_length(n->packet_queue), memb_numfree(&packet_memb));
/* If q is the first packet in the neighbor's queue, send asap */
if(list_head(n->packet_queue) == q) {
@ -555,10 +548,10 @@ csma_output_packet(mac_callback_t sent, void *ptr)
return;
}
memb_free(&metadata_memb, q->ptr);
PRINTF("csma: could not allocate queuebuf, dropping packet\n");
LOG_WARN("csma: could not allocate queuebuf, dropping packet\n");
}
memb_free(&packet_memb, q);
PRINTF("csma: could not allocate queuebuf, dropping packet\n");
LOG_WARN("csma: could not allocate queuebuf, dropping packet\n");
}
/* The packet allocation failed. Remove and free neighbor entry if empty. */
if(list_length(n->packet_queue) == 0) {
@ -566,11 +559,11 @@ csma_output_packet(mac_callback_t sent, void *ptr)
memb_free(&neighbor_memb, n);
}
} else {
PRINTF("csma: Neighbor queue full\n");
LOG_WARN("csma: Neighbor queue full\n");
}
PRINTF("csma: could not allocate packet, dropping packet\n");
LOG_WARN("csma: could not allocate packet, dropping packet\n");
} else {
PRINTF("csma: could not allocate neighbor, dropping packet\n");
LOG_WARN("csma: could not allocate neighbor, dropping packet\n");
}
mac_call_sent_callback(sent, ptr, MAC_TX_ERR, 1);
}

22
core/net/mac/csma/csma.c
View File

@ -44,16 +44,10 @@
#include "net/packetbuf.h"
#include "net/netstack.h"
#include <string.h>
#include <stdio.h>
#define DEBUG 0
#if DEBUG
#include <stdio.h>
#define PRINTF(...) printf(__VA_ARGS__)
#else /* DEBUG */
#define PRINTF(...)
#endif /* DEBUG */
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE_STR "CSMA"
#define LOG_LEVEL MAC_LOG_LEVEL
/*---------------------------------------------------------------------------*/
static void
@ -76,15 +70,15 @@ input_packet(void)
#if CSMA_802154_AUTOACK
if(packetbuf_datalen() == CSMA_ACK_LEN) {
/* Ignore ack packets */
PRINTF("csma: ignored ack\n");
LOG_INFO("csma: ignored ack\n");
} else
#endif /* CSMA_802154_AUTOACK */
if(NETSTACK_FRAMER.parse() < 0) {
PRINTF("csma: failed to parse %u\n", packetbuf_datalen());
LOG_ERR("csma: failed to parse %u\n", packetbuf_datalen());
} else if(!linkaddr_cmp(packetbuf_addr(PACKETBUF_ADDR_RECEIVER),
&linkaddr_node_addr) &&
!packetbuf_holds_broadcast()) {
PRINTF("csma: not for us\n");
LOG_WARN("csma: not for us\n");
} else {
int duplicate = 0;
@ -93,7 +87,7 @@ input_packet(void)
duplicate = mac_sequence_is_duplicate();
if(duplicate) {
/* Drop the packet. */
PRINTF("csma: drop duplicate link layer packet %u\n",
LOG_WARN("csma: drop duplicate link layer packet %u\n",
packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO));
} else {
mac_sequence_register_seqno();

23
core/net/mac/mac.c
View File

@ -32,32 +32,29 @@
#include "net/mac/mac.h"
#define DEBUG 0
#if DEBUG
#include <stdio.h>
#define PRINTF(...) printf(__VA_ARGS__)
#else /* DEBUG */
#define PRINTF(...)
#endif /* DEBUG */
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE_STR "MAC"
#define LOG_LEVEL MAC_LOG_LEVEL
/*---------------------------------------------------------------------------*/
void
mac_call_sent_callback(mac_callback_t sent, void *ptr, int status, int num_tx)
{
PRINTF("mac_callback_t %p ptr %p status %d num_tx %d\n",
LOG_INFO("mac_callback_t %p ptr %p status %d num_tx %d\n",
(void *)sent, ptr, status, num_tx);
switch(status) {
case MAC_TX_COLLISION:
PRINTF("mac: collision after %d tx\n", num_tx);
break;
LOG_INFO("collision after %d tx\n", num_tx);
break;
case MAC_TX_NOACK:
PRINTF("mac: noack after %d tx\n", num_tx);
LOG_INFO("noack after %d tx\n", num_tx);
break;
case MAC_TX_OK:
PRINTF("mac: sent after %d tx\n", num_tx);
LOG_INFO("sent after %d tx\n", num_tx);
break;
default:
PRINTF("mac: error %d after %d tx\n", status, num_tx);
LOG_INFO("error %d after %d tx\n", status, num_tx);
}
if(sent) {

11
core/net/mac/tsch/tsch-log.c
View File

@ -51,14 +51,7 @@
#include "net/mac/tsch/tsch-slot-operation.h"
#include "lib/ringbufindex.h"
#if TSCH_LOG_LEVEL >= 1
#define DEBUG DEBUG_PRINT
#else /* TSCH_LOG_LEVEL */
#define DEBUG DEBUG_NONE
#endif /* TSCH_LOG_LEVEL */
#include "net/net-debug.h"
#if TSCH_LOG_LEVEL >= 2 /* Skip this file for log levels 0 or 1 */
#if TSCH_LOG_PER_SLOT
PROCESS_NAME(tsch_pending_events_process);
@ -156,4 +149,4 @@ tsch_log_init(void)
ringbufindex_init(&log_ringbuf, TSCH_LOG_QUEUE_LEN);
}
#endif /* TSCH_LOG_LEVEL */
#endif /* TSCH_LOG_PER_SLOT */

16
core/net/mac/tsch/tsch-log.h
View File

@ -59,19 +59,19 @@
* 0: no log
* 1: basic PRINTF enabled
* 2: basic PRINTF enabled and tsch-log module enabled */
#ifdef TSCH_LOG_CONF_LEVEL
#define TSCH_LOG_LEVEL TSCH_LOG_CONF_LEVEL
#else /* TSCH_LOG_CONF_LEVEL */
#define TSCH_LOG_LEVEL 2
#endif /* TSCH_LOG_CONF_LEVEL */
#ifdef TSCH_LOG_CONF_PER_SLOT
#define TSCH_LOG_PER_SLOT TSCH_LOG_CONF_PER_SLOT
#else /* TSCH_LOG_CONF_PER_SLOT */
#define TSCH_LOG_PER_SLOT 0
#endif /* TSCH_LOG_CONF_PER_SLOT */
#if TSCH_LOG_LEVEL < 2 /* For log level 0 or 1, the logging functions do nothing */
#if (TSCH_LOG_PER_SLOT == 0)
#define tsch_log_init()
#define tsch_log_process_pending()
#define TSCH_LOG_ADD(log_type, init_code)
#else /* TSCH_LOG_LEVEL */
#else /* (TSCH_LOG_PER_SLOT == 0) */
/************ Types ***********/
@ -133,6 +133,6 @@ void tsch_log_process_pending(void);
} \
} while(0);
#endif /* TSCH_LOG_LEVEL */
#endif /* (TSCH_LOG_PER_SLOT == 0) */
#endif /* __TSCH_LOG_H__ */

29
core/net/mac/tsch/tsch-packet.c
View File

@ -45,21 +45,16 @@
#include "net/mac/tsch/tsch-private.h"
#include "net/mac/tsch/tsch-schedule.h"
#include "net/mac/tsch/tsch-security.h"
#include "net/mac/tsch/tsch-log.h"
#include "net/mac/framer/frame802154.h"
#include "net/mac/framer/framer-802154.h"
#include "net/netstack.h"
#include "lib/ccm-star.h"
#include "lib/aes-128.h"
#include <stdio.h>
#include <string.h>
#if TSCH_LOG_LEVEL >= 1
#define DEBUG DEBUG_PRINT
#else /* TSCH_LOG_LEVEL */
#define DEBUG DEBUG_NONE
#endif /* TSCH_LOG_LEVEL */
#include "net/net-debug.h"
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE_STR "TSCH Packet"
#define LOG_LEVEL MAC_LOG_LEVEL
/*---------------------------------------------------------------------------*/
/* Construct enhanced ACK packet and return ACK length */
@ -357,19 +352,19 @@ tsch_packet_parse_eb(const uint8_t *buf, int buf_size,
/* Parse 802.15.4-2006 frame, i.e. all fields before Information Elements */
if((ret = frame802154_parse((uint8_t *)buf, buf_size, frame)) == 0) {
PRINTF("TSCH:! parse_eb: failed to parse frame\n");
LOG_ERR("! parse_eb: failed to parse frame\n");
return 0;
}
if(frame->fcf.frame_version < FRAME802154_IEEE802154E_2012
|| frame->fcf.frame_type != FRAME802154_BEACONFRAME) {
PRINTF("TSCH:! parse_eb: frame is not a valid TSCH beacon. Frame version %u, type %u, FCF %02x %02x\n",
LOG_ERR("! 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]);
PRINTF("TSCH:! parse_eb: frame was from 0x%x/", frame->src_pid);
PRINTLLADDR((const uip_lladdr_t *)&frame->src_addr);
PRINTF(" to 0x%x/", frame->dest_pid);
PRINTLLADDR((const uip_lladdr_t *)&frame->dest_addr);
PRINTF("\n");
LOG_ERR("! parse_eb: frame was from 0x%x/", frame->src_pid);
LOG_ERR_LLADDR((const uip_lladdr_t *)&frame->src_addr);
LOG_ERR(" to 0x%x/", frame->dest_pid);
LOG_ERR_LLADDR((const uip_lladdr_t *)&frame->dest_addr);
LOG_ERR("\n");
return 0;
}
@ -396,7 +391,7 @@ tsch_packet_parse_eb(const uint8_t *buf, int buf_size,
/* Parse information elements. We need to substract the MIC length, as the exact payload len is needed while parsing */
if((ret = frame802154e_parse_information_elements(buf + curr_len, buf_size - curr_len - mic_len, ies)) == -1) {
PRINTF("TSCH:! parse_eb: failed to parse IEs\n");
LOG_ERR("! parse_eb: failed to parse IEs\n");
return 0;
}
curr_len += ret;

23
core/net/mac/tsch/tsch-queue.c
View File

@ -52,15 +52,12 @@
#include "net/mac/tsch/tsch-queue.h"
#include "net/mac/tsch/tsch-schedule.h"
#include "net/mac/tsch/tsch-slot-operation.h"
#include "net/mac/tsch/tsch-log.h"
#include <string.h>
#if TSCH_LOG_LEVEL >= 1
#define DEBUG DEBUG_PRINT
#else /* TSCH_LOG_LEVEL */
#define DEBUG DEBUG_NONE
#endif /* TSCH_LOG_LEVEL */
#include "net/net-debug.h"
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE_STR "TSCH Queue"
#define LOG_LEVEL MAC_LOG_LEVEL
/* Check if TSCH_QUEUE_NUM_PER_NEIGHBOR is power of two */
#if (TSCH_QUEUE_NUM_PER_NEIGHBOR & (TSCH_QUEUE_NUM_PER_NEIGHBOR - 1)) != 0
@ -155,7 +152,7 @@ tsch_queue_update_time_source(const linkaddr_t *new_addr)
}
if(new_time_src != old_time_src) {
PRINTF("TSCH: update time source: %u -> %u\n",
LOG_INFO("update time source: %u -> %u\n",
TSCH_LOG_ID_FROM_LINKADDR(old_time_src ? &old_time_src->addr : NULL),
TSCH_LOG_ID_FROM_LINKADDR(new_time_src ? &new_time_src->addr : NULL));
@ -195,13 +192,13 @@ tsch_queue_flush_nbr_queue(struct tsch_neighbor *n)
if(p != NULL) {
/* Set return status for packet_sent callback */
p->ret = MAC_TX_ERR;
PRINTF("TSCH-queue:! flushing packet\n");
LOG_WARN("! flushing packet\n");
/* Call packet_sent callback */
mac_call_sent_callback(p->sent, p->ptr, p->ret, p->transmissions);
/* Free packet queuebuf */
tsch_queue_free_packet(p);
}
PRINTF("TSCH-queue: packet is deleted packet=%p\n", p);
LOG_INFO("packet deleted %p\n", p);
}
}
/*---------------------------------------------------------------------------*/
@ -253,7 +250,7 @@ tsch_queue_add_packet(const linkaddr_t *addr, mac_callback_t sent, void *ptr)
/* Add to ringbuf (actual add committed through atomic operation) */
n->tx_array[put_index] = p;
ringbufindex_put(&n->tx_ringbuf);
PRINTF("TSCH-queue: packet is added put_index=%u, packet=%p\n",
LOG_INFO("packet is added put_index %u, packet %p\n",
put_index, p);
return p;
} else {
@ -263,7 +260,7 @@ tsch_queue_add_packet(const linkaddr_t *addr, mac_callback_t sent, void *ptr)
}
}
}
PRINTF("TSCH-queue:! add packet failed: %u %p %d %p %p\n", tsch_is_locked(), n, put_index, p, p ? p->qb : NULL);
LOG_ERR("! add packet failed: %u %p %d %p %p\n", tsch_is_locked(), n, put_index, p, p ? p->qb : NULL);
return 0;
}
/*---------------------------------------------------------------------------*/
@ -290,7 +287,7 @@ tsch_queue_remove_packet_from_queue(struct tsch_neighbor *n)
/* Get and remove packet from ringbuf (remove committed through an atomic operation */
int16_t get_index = ringbufindex_get(&n->tx_ringbuf);
if(get_index != -1) {
PRINTF("TSCH-queue: packet is removed, get_index=%u\n", get_index);
LOG_INFO("packet is removed, get_index %u\n", get_index);
return n->tx_array[get_index];
} else {
return NULL;

10
core/net/mac/tsch/tsch-rpl.c
View File

@ -46,12 +46,10 @@
#include "net/mac/tsch/tsch-log.h"
#include "tsch-rpl.h"
#if TSCH_LOG_LEVEL >= 1
#define DEBUG DEBUG_PRINT
#else /* TSCH_LOG_LEVEL */
#define DEBUG DEBUG_NONE
#endif /* TSCH_LOG_LEVEL */
#include "net/net-debug.h"
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE_STR "TSCH RPL"
#define LOG_LEVEL MAC_LOG_LEVEL
/*---------------------------------------------------------------------------*/
/* To use, set #define TSCH_CALLBACK_JOINING_NETWORK tsch_rpl_callback_joining_network */

24
core/net/mac/tsch/tsch-schedule.c
View File

@ -55,12 +55,10 @@
#include "sys/rtimer.h"
#include <string.h>
#if TSCH_LOG_LEVEL >= 1
#define DEBUG DEBUG_PRINT
#else /* TSCH_LOG_LEVEL */
#define DEBUG DEBUG_NONE
#endif /* TSCH_LOG_LEVEL */
#include "net/net-debug.h"
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE_STR "TSCH Schedule"
#define LOG_LEVEL MAC_LOG_LEVEL
/* Pre-allocated space for links */
MEMB(link_memb, struct tsch_link, TSCH_SCHEDULE_MAX_LINKS);
@ -92,7 +90,7 @@ tsch_schedule_add_slotframe(uint16_t handle, uint16_t size)
/* Add the slotframe to the global list */
list_add(slotframe_list, sf);
}
PRINTF("TSCH-schedule: add_slotframe %u %u\n",
LOG_INFO("add_slotframe %u %u\n",
handle, size);
tsch_release_lock();
return sf;
@ -126,7 +124,7 @@ tsch_schedule_remove_slotframe(struct tsch_slotframe *slotframe)
/* Now that the slotframe has no links, remove it. */
if(tsch_get_lock()) {
PRINTF("TSCH-schedule: remove slotframe %u %u\n", slotframe->handle, slotframe->size.val);
LOG_INFO("remove slotframe %u %u\n", slotframe->handle, slotframe->size.val);
memb_free(&slotframe_memb, slotframe);
list_remove(slotframe_list, slotframe);
tsch_release_lock();
@ -186,11 +184,11 @@ tsch_schedule_add_link(struct tsch_slotframe *slotframe,
* to keep neighbor state in sync with link options etc.) */
tsch_schedule_remove_link_by_timeslot(slotframe, timeslot);
if(!tsch_get_lock()) {
PRINTF("TSCH-schedule:! add_link memb_alloc couldn't take lock\n");
LOG_ERR("! add_link memb_alloc couldn't take lock\n");
} else {
l = memb_alloc(&link_memb);
if(l == NULL) {
PRINTF("TSCH-schedule:! add_link memb_alloc failed\n");
LOG_ERR("! add_link memb_alloc failed\n");
tsch_release_lock();
} else {
static int current_link_handle = 0;
@ -210,7 +208,7 @@ tsch_schedule_add_link(struct tsch_slotframe *slotframe,
}
linkaddr_copy(&l->addr, address);
PRINTF("TSCH-schedule: add_link %u %u %u %u %u %u\n",
LOG_INFO("add_link %u %u %u %u %u %u\n",
slotframe->handle, link_options, link_type, timeslot, channel_offset, TSCH_LOG_ID_FROM_LINKADDR(address));
/* Release the lock before we update the neighbor (will take the lock) */
@ -251,7 +249,7 @@ tsch_schedule_remove_link(struct tsch_slotframe *slotframe, struct tsch_link *l)
if(l == current_link) {
current_link = NULL;
}
PRINTF("TSCH-schedule: remove_link %u %u %u %u %u\n",
LOG_INFO("remove_link %u %u %u %u %u\n",
slotframe->handle, l->link_options, l->timeslot, l->channel_offset,
TSCH_LOG_ID_FROM_LINKADDR(&l->addr));
@ -274,7 +272,7 @@ tsch_schedule_remove_link(struct tsch_slotframe *slotframe, struct tsch_link *l)
return 1;
} else {
PRINTF("TSCH-schedule:! remove_link memb_alloc couldn't take lock\n");
LOG_ERR("! remove_link memb_alloc couldn't take lock\n");
}
}
return 0;

7
core/net/mac/tsch/tsch-security.c
View File

@ -53,13 +53,6 @@
#include <stdio.h>
#include <string.h>
#if TSCH_LOG_LEVEL >= 1
#define DEBUG DEBUG_PRINT
#else /* TSCH_LOG_LEVEL */
#define DEBUG DEBUG_NONE
#endif /* TSCH_LOG_LEVEL */
#include "net/net-debug.h"
/* The two keys K1 and K2 from 6TiSCH minimal configuration
* K1: well-known, used for EBs
* K2: secret, used for data and ACK

104
core/net/mac/tsch/tsch.c
View File

@ -61,12 +61,10 @@
#error TSCH: FRAME802154_VERSION must be at least FRAME802154_IEEE802154E_2012
#endif
#if TSCH_LOG_LEVEL >= 1
#define DEBUG DEBUG_PRINT
#else /* TSCH_LOG_LEVEL */
#define DEBUG DEBUG_NONE
#endif /* TSCH_LOG_LEVEL */
#include "net/net-debug.h"
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE_STR "TSCH"
#define LOG_LEVEL MAC_LOG_LEVEL
/* Use to collect link statistics even on Keep-Alive, even though they were
* not sent from an upper layer and don't have a valid packet_sent callback */
@ -147,9 +145,9 @@ static struct ctimer keepalive_timer;
/* TSCH processes and protothreads */
PT_THREAD(tsch_scan(struct pt *pt));
PROCESS(tsch_process, "TSCH: main process");
PROCESS(tsch_send_eb_process, "TSCH: send EB process");
PROCESS(tsch_pending_events_process, "TSCH: pending events process");
PROCESS(tsch_process, "main process");
PROCESS(tsch_send_eb_process, "send EB process");
PROCESS(tsch_pending_events_process, "pending events process");
/* Other function prototypes */
static void packet_input(void);
@ -228,7 +226,7 @@ keepalive_packet_sent(void *ptr, int status, int transmissions)
#ifdef TSCH_LINK_NEIGHBOR_CALLBACK
TSCH_LINK_NEIGHBOR_CALLBACK(packetbuf_addr(PACKETBUF_ADDR_RECEIVER), status, transmissions);
#endif
PRINTF("TSCH: KA sent to %u, st %d-%d\n",
LOG_INFO("KA sent to %u, st %d-%d\n",
TSCH_LOG_ID_FROM_LINKADDR(packetbuf_addr(PACKETBUF_ADDR_RECEIVER)), status, transmissions);
tsch_schedule_keepalive();
}
@ -243,7 +241,7 @@ keepalive_send()
packetbuf_clear();
packetbuf_set_addr(PACKETBUF_ADDR_RECEIVER, &n->addr);
NETSTACK_MAC.send(keepalive_packet_sent, NULL);
PRINTF("TSCH: sending KA to %u\n",
LOG_INFO("sending KA to %u\n",
TSCH_LOG_ID_FROM_LINKADDR(&n->addr));
}
}
@ -263,7 +261,7 @@ tsch_schedule_keepalive()
static void
eb_input(struct input_packet *current_input)
{
/* PRINTF("TSCH: EB received\n"); */
/* LOG_INFO("EB received\n"); */
frame802154_t frame;
/* Verify incoming EB (does its ASN match our Rx time?),
* and update our join priority. */
@ -313,20 +311,20 @@ eb_input(struct input_packet *current_input)
int32_t asn_diff = TSCH_ASN_DIFF(current_input->rx_asn, eb_ies.ie_asn);
if(asn_diff != 0) {
/* We disagree with our time source's ASN -- leave the network */
PRINTF("TSCH:! ASN drifted by %ld, leaving the network\n", asn_diff);
LOG_WARN("! ASN drifted by %ld, leaving the network\n", asn_diff);
tsch_disassociate();
}
if(eb_ies.ie_join_priority >= TSCH_MAX_JOIN_PRIORITY) {
/* Join priority unacceptable. Leave network. */
PRINTF("TSCH:! EB JP too high %u, leaving the network\n",
LOG_WARN("! EB JP too high %u, leaving the network\n",
eb_ies.ie_join_priority);
tsch_disassociate();
} else {
#if TSCH_AUTOSELECT_TIME_SOURCE
/* Update join priority */
if(tsch_join_priority != eb_ies.ie_join_priority + 1) {
PRINTF("TSCH: update JP from EB %u -> %u\n",
LOG_INFO("update JP from EB %u -> %u\n",
tsch_join_priority, eb_ies.ie_join_priority + 1);
tsch_join_priority = eb_ies.ie_join_priority + 1;
}
@ -409,7 +407,7 @@ tsch_start_coordinator(void)
tsch_is_associated = 1;
tsch_join_priority = 0;
PRINTF("TSCH: starting as coordinator, PAN ID %x, asn-%x.%lx\n",
LOG_INFO("starting as coordinator, PAN ID %x, asn-%x.%lx\n",
frame802154_get_pan_id(), tsch_current_asn.ms1b, tsch_current_asn.ls4b);
/* Start slot operation */
@ -423,7 +421,7 @@ tsch_disassociate(void)
if(tsch_is_associated == 1) {
tsch_is_associated = 0;
process_post(&tsch_process, PROCESS_EVENT_POLL, NULL);
PRINTF("TSCH: leaving the network\n");
LOG_WARN("leaving the network\n");
}
}
/*---------------------------------------------------------------------------*/
@ -438,7 +436,7 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
if(input_eb == NULL || tsch_packet_parse_eb(input_eb->payload, input_eb->len,
&frame, &ies, &hdrlen, 0) == 0) {
PRINTF("TSCH:! failed to parse EB (len %u)\n", input_eb->len);
LOG_ERR("! failed to parse EB (len %u)\n", input_eb->len);
return 0;
}
@ -447,7 +445,7 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
#if TSCH_JOIN_SECURED_ONLY
if(frame.fcf.security_enabled == 0) {
PRINTF("TSCH:! parse_eb: EB is not secured\n");
LOG_ERR("! parse_eb: EB is not secured\n");
return 0;
}
#endif /* TSCH_JOIN_SECURED_ONLY */
@ -456,14 +454,14 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
if(!tsch_security_parse_frame(input_eb->payload, hdrlen,
input_eb->len - hdrlen - tsch_security_mic_len(&frame),
&frame, (linkaddr_t*)&frame.src_addr, &tsch_current_asn)) {
PRINTF("TSCH:! parse_eb: failed to authenticate\n");
LOG_ERR("! parse_eb: failed to authenticate\n");
return 0;
}
#endif /* LLSEC802154_ENABLED */
#if !LLSEC802154_ENABLED
if(frame.fcf.security_enabled == 1) {
PRINTF("TSCH:! parse_eb: we do not support security, but EB is secured\n");
LOG_ERR("! parse_eb: we do not support security, but EB is secured\n");
return 0;
}
#endif /* !LLSEC802154_ENABLED */
@ -471,14 +469,14 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
#if TSCH_JOIN_MY_PANID_ONLY
/* Check if the EB comes from the PAN ID we expect */
if(frame.src_pid != IEEE802154_PANID) {
PRINTF("TSCH:! parse_eb: PAN ID %x != %x\n", frame.src_pid, IEEE802154_PANID);
LOG_ERR("! parse_eb: PAN ID %x != %x\n", frame.src_pid, IEEE802154_PANID);
return 0;
}
#endif /* TSCH_JOIN_MY_PANID_ONLY */
/* There was no join priority (or 0xff) in the EB, do not join */
if(ies.ie_join_priority == 0xff) {
PRINTF("TSCH:! parse_eb: no join priority\n");
LOG_ERR("! parse_eb: no join priority\n");
return 0;
}
@ -500,7 +498,7 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
memcpy(tsch_hopping_sequence, ies.ie_hopping_sequence_list, ies.ie_hopping_sequence_len);
TSCH_ASN_DIVISOR_INIT(tsch_hopping_sequence_length, ies.ie_hopping_sequence_len);
} else {
PRINTF("TSCH:! parse_eb: hopping sequence too long (%u)\n", ies.ie_hopping_sequence_len);
LOG_ERR("! parse_eb: hopping sequence too long (%u)\n", ies.ie_hopping_sequence_len);
return 0;
}
}
@ -511,7 +509,7 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
int32_t asn_threshold = TSCH_CHECK_TIME_AT_ASSOCIATION * 60ul * TSCH_CLOCK_TO_SLOTS(CLOCK_SECOND, tsch_timing_timeslot_length);
int32_t asn_diff = (int32_t)tsch_current_asn.ls4b - expected_asn;
if(asn_diff > asn_threshold) {
PRINTF("TSCH:! EB ASN rejected %lx %lx %ld\n",
LOG_ERR("! EB ASN rejected %lx %lx %ld\n",
tsch_current_asn.ls4b, expected_asn, asn_diff);
return 0;
}
@ -521,10 +519,10 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
/* Create schedule */
if(ies.ie_tsch_slotframe_and_link.num_slotframes == 0) {
#if TSCH_SCHEDULE_WITH_6TISCH_MINIMAL
PRINTF("TSCH: parse_eb: no schedule, setting up minimal schedule\n");
LOG_INFO("parse_eb: no schedule, setting up minimal schedule\n");
tsch_schedule_create_minimal();
#else
PRINTF("TSCH: parse_eb: no schedule\n");
LOG_INFO("parse_eb: no schedule\n");
#endif
} else {
/* First, empty current schedule */
@ -543,7 +541,7 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
ies.ie_tsch_slotframe_and_link.links[i].timeslot, ies.ie_tsch_slotframe_and_link.links[i].channel_offset);
}
} else {
PRINTF("TSCH:! parse_eb: too many links in schedule (%u)\n", num_links);
LOG_ERR("! parse_eb: too many links in schedule (%u)\n", num_links);
return 0;
}
}
@ -575,7 +573,7 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
TSCH_CALLBACK_JOINING_NETWORK();
#endif
PRINTF("TSCH: 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 ",
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_is_pan_secured,
frame.src_pid,
tsch_current_asn.ms1b, tsch_current_asn.ls4b, tsch_join_priority,
@ -583,13 +581,13 @@ tsch_associate(const struct input_packet *input_eb, rtimer_clock_t timestamp)
ies.ie_channel_hopping_sequence_id,
ies.ie_tsch_slotframe_and_link.slotframe_size,
ies.ie_tsch_slotframe_and_link.num_links);
PRINTLLADDR((const uip_lladdr_t *)&frame.src_addr);
PRINTF("\n");
LOG_INFO_LLADDR((const linkaddr_t *)&frame.src_addr);
LOG_INFO("\n");
return 1;
}
}
PRINTF("TSCH:! did not associate.\n");
LOG_ERR("! did not associate.\n");
return 0;
}
@ -631,7 +629,7 @@ PT_THREAD(tsch_scan(struct pt *pt))
if(current_channel != scan_channel) {
NETSTACK_RADIO.set_value(RADIO_PARAM_CHANNEL, scan_channel);
current_channel = scan_channel;
PRINTF("TSCH: scanning on channel %u\n", scan_channel);
LOG_INFO("scanning on channel %u\n", scan_channel);
}
current_channel_since = now_time;
}
@ -654,7 +652,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 */
PRINTF("TSCH: association: received packet (%u bytes) on channel %u\n", input_eb.len, current_channel);
LOG_INFO("association: received packet (%u bytes) on channel %u\n", input_eb.len, current_channel);
tsch_associate(&input_eb, t0);
}
@ -754,9 +752,9 @@ PROCESS_THREAD(tsch_send_eb_process, ev, data)
packetbuf_set_datalen(eb_len);
/* Enqueue EB packet */
if(!(p = tsch_queue_add_packet(&tsch_eb_address, NULL, NULL))) {
PRINTF("TSCH:! could not enqueue EB packet\n");
LOG_ERR("! could not enqueue EB packet\n");
} else {
PRINTF("TSCH: enqueue EB packet %u %u\n", eb_len, hdr_len);
LOG_INFO("enqueue EB packet %u %u\n", eb_len, hdr_len);
p->tsch_sync_ie_offset = tsch_sync_ie_offset;
p->header_len = hdr_len;
}
@ -804,7 +802,7 @@ tsch_init(void)
/* Radio Rx mode */
if(NETSTACK_RADIO.get_value(RADIO_PARAM_RX_MODE, &radio_rx_mode) != RADIO_RESULT_OK) {
printf("TSCH:! radio does not support getting RADIO_PARAM_RX_MODE. Abort init.\n");
LOG_ERR("! radio does not support getting RADIO_PARAM_RX_MODE. Abort init.\n");
return;
}
/* Disable radio in frame filtering */
@ -814,34 +812,34 @@ tsch_init(void)
/* Set radio in poll mode */
radio_rx_mode |= RADIO_RX_MODE_POLL_MODE;
if(NETSTACK_RADIO.set_value(RADIO_PARAM_RX_MODE, radio_rx_mode) != RADIO_RESULT_OK) {
printf("TSCH:! radio does not support setting required RADIO_PARAM_RX_MODE. Abort init.\n");
LOG_ERR("! radio does not support setting required RADIO_PARAM_RX_MODE. Abort init.\n");
return;
}
/* Radio Tx mode */
if(NETSTACK_RADIO.get_value(RADIO_PARAM_TX_MODE, &radio_tx_mode) != RADIO_RESULT_OK) {
printf("TSCH:! radio does not support getting RADIO_PARAM_TX_MODE. Abort init.\n");
LOG_ERR("! radio does not support getting RADIO_PARAM_TX_MODE. Abort init.\n");
return;
}
/* Unset CCA */
radio_tx_mode &= ~RADIO_TX_MODE_SEND_ON_CCA;
if(NETSTACK_RADIO.set_value(RADIO_PARAM_TX_MODE, radio_tx_mode) != RADIO_RESULT_OK) {
printf("TSCH:! radio does not support setting required RADIO_PARAM_TX_MODE. Abort init.\n");
LOG_ERR("! radio does not support setting required RADIO_PARAM_TX_MODE. Abort init.\n");
return;
}
/* Test setting channel */
if(NETSTACK_RADIO.set_value(RADIO_PARAM_CHANNEL, TSCH_DEFAULT_HOPPING_SEQUENCE[0]) != RADIO_RESULT_OK) {
printf("TSCH:! radio does not support setting channel. Abort init.\n");
LOG_ERR("! radio does not support setting channel. Abort init.\n");
return;
}
/* Test getting timestamp */
if(NETSTACK_RADIO.get_object(RADIO_PARAM_LAST_PACKET_TIMESTAMP, &t, sizeof(rtimer_clock_t)) != RADIO_RESULT_OK) {
printf("TSCH:! radio does not support getting last packet timestamp. Abort init.\n");
LOG_ERR("! radio does not support getting last packet timestamp. Abort init.\n");
return;
}
/* Check max hopping sequence length vs default sequence length */
if(TSCH_HOPPING_SEQUENCE_MAX_LEN < sizeof(TSCH_DEFAULT_HOPPING_SEQUENCE)) {
printf("TSCH:! TSCH_HOPPING_SEQUENCE_MAX_LEN < sizeof(TSCH_DEFAULT_HOPPING_SEQUENCE). Abort init.\n");
LOG_ERR("! TSCH_HOPPING_SEQUENCE_MAX_LEN < sizeof(TSCH_DEFAULT_HOPPING_SEQUENCE). Abort init.\n");
}
/* Init TSCH sub-modules */
@ -872,9 +870,9 @@ send_packet(mac_callback_t sent, void *ptr)
if(!tsch_is_associated) {
if(!tsch_is_initialized) {
PRINTF("TSCH:! not initialized (see earlier logs), drop outgoing packet\n");
LOG_WARN("! not initialized (see earlier logs), drop outgoing packet\n");
} else {
PRINTF("TSCH:! not associated, drop outgoing packet\n");
LOG_WARN("! not associated, drop outgoing packet\n");
}
ret = MAC_TX_ERR;
mac_call_sent_callback(sent, ptr, ret, 1);
@ -920,27 +918,27 @@ send_packet(mac_callback_t sent, void *ptr)
#endif
if((hdr_len = NETSTACK_FRAMER.create()) < 0) {
PRINTF("TSCH:! can't send packet due to framer error\n");
LOG_ERR("! can't send packet due to framer error\n");
ret = MAC_TX_ERR;
} else {
struct tsch_packet *p;
/* Enqueue packet */
p = tsch_queue_add_packet(addr, sent, ptr);
if(p == NULL) {
PRINTF("TSCH:! can't send packet to %u with seqno %u, queue %u %u\n",
LOG_ERR("! can't send packet to %u with seqno %u, queue %u %u\n",
TSCH_LOG_ID_FROM_LINKADDR(addr), tsch_packet_seqno,
packet_count_before,
tsch_queue_packet_count(addr));
ret = MAC_TX_ERR;
} else {
p->header_len = hdr_len;
PRINTF("TSCH: send packet to %u with seqno %u, queue %u %u, len %u %u\n",
LOG_INFO("send packet to %u with seqno %u, queue %u %u, len %u %u\n",
TSCH_LOG_ID_FROM_LINKADDR(addr), tsch_packet_seqno,
packet_count_before,
tsch_queue_packet_count(addr),
p->header_len,
queuebuf_datalen(p->qb));
(void)packet_count_before; /* Discard "variable set but unused" warning in case of TSCH_LOG_LEVEL of 0 */
(void)packet_count_before; /* Discard "variable set but unused"warning in case of TSCH_LOG_LEVEL of 0 */
}
}
if(ret != MAC_TX_DEFERRED) {
@ -956,7 +954,7 @@ packet_input(void)
frame_parsed = NETSTACK_FRAMER.parse();
if(frame_parsed < 0) {
PRINTF("TSCH:! failed to parse %u\n", packetbuf_datalen());
LOG_ERR("! failed to parse %u\n", packetbuf_datalen());
} else {
int duplicate = 0;
@ -966,7 +964,7 @@ packet_input(void)
duplicate = mac_sequence_is_duplicate();
if(duplicate) {
/* Drop the packet. */
PRINTF("TSCH:! drop dup ll from %u seqno %u\n",
LOG_WARN("! drop dup ll from %u seqno %u\n",
TSCH_LOG_ID_FROM_LINKADDR(packetbuf_addr(PACKETBUF_ADDR_SENDER)),
packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO));
} else {
@ -975,7 +973,7 @@ packet_input(void)
}
if(!duplicate) {
PRINTF("TSCH: received from %u with seqno %u\n",
LOG_INFO("received from %u with seqno %u\n",
TSCH_LOG_ID_FROM_LINKADDR(packetbuf_addr(PACKETBUF_ADDR_SENDER)),
packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO));
NETSTACK_NETWORK.input();
@ -994,7 +992,7 @@ turn_on(void)
process_start(&tsch_send_eb_process, NULL);
/* try to associate to a network or start one if setup as coordinator */
process_start(&tsch_process, NULL);
PRINTF("TSCH: starting as %s\n", tsch_is_coordinator ? "coordinator" : "node");
LOG_INFO("starting as %s\n", tsch_is_coordinator ? "coordinator": "node");
return 1;
}
return 0;

10
core/sys/log-conf.h
View File

@ -48,6 +48,10 @@
/* A list of currently supported modules */
#ifndef IPV6_LOG_LEVEL
#define IPV6_LOG_LEVEL LOG_LEVEL_NONE
#endif /* IPV6_LOG_LEVEL */
#ifndef SICSLOWPAN_LOG_LEVEL
#define SICSLOWPAN_LOG_LEVEL LOG_LEVEL_NONE
#endif /* SICSLOWPAN_LOG_LEVEL */
@ -56,9 +60,9 @@
#define TCPIP_LOG_LEVEL LOG_LEVEL_NONE
#endif /* TCPIP_LOG_LEVEL */
#ifndef IPV6_LOG_LEVEL
#define IPV6_LOG_LEVEL LOG_LEVEL_NONE
#endif /* IPV6_LOG_LEVEL */
#ifndef MAC_LOG_LEVEL
#define MAC_LOG_LEVEL LOG_LEVEL_WARN
#endif /* MAC_LOG_LEVELL */
#endif /* __LOG_CONF_H__ */

7
examples/ipv6/rpl-tsch/project-conf.h
View File

@ -92,10 +92,9 @@
/******************* Configure TSCH ********************/
/*******************************************************/
/* TSCH logging. 0: disabled. 1: basic log. 2: with delayed
* log messages from interrupt */
#undef TSCH_LOG_CONF_LEVEL
#define TSCH_LOG_CONF_LEVEL 2
/* TSCH per-slot logging */
#undef TSCH_LOG_CONF_PER_SLOT
#define TSCH_LOG_CONF_PER_SLOT 1
/* IEEE802.15.4 PANID */
#undef IEEE802154_CONF_PANID

7
examples/platform-specific/jn516x/rpl/common-conf.h
View File

@ -68,10 +68,9 @@
#define TSCH_CALLBACK_JOINING_NETWORK tsch_rpl_callback_joining_network
#define TSCH_CALLBACK_LEAVING_NETWORK tsch_rpl_callback_leaving_network
/* TSCH logging. 0: disabled. 1: basic log. 2: with delayed
* log messages from interrupt */
#undef TSCH_LOG_CONF_LEVEL
#define TSCH_LOG_CONF_LEVEL 2
/* TSCH per-slot logging */
#undef TSCH_LOG_CONF_PER_SLOT
#define TSCH_LOG_CONF_PER_SLOT 1
/* Do not start TSCH at init, wait for NETSTACK_MAC.on() */
#undef TSCH_CONF_AUTOSTART

2
examples/platform-specific/jn516x/tsch/common-conf.h
View File

@ -38,7 +38,7 @@
#define WITH_TSCH 1
#define WITH_TSCH_SECURITY 0
#define TSCH_LOG_CONF_LEVEL 2
#define TSCH_LOG_CONF_PER_SLOT 1
#define WITH_COAP_RESOURCES 0
#undef ENABLE_COOJA_DEBUG

5
regression-tests/13-ieee802154/code-flush-nbr-queue/project-conf.h
View File

@ -38,8 +38,9 @@
#undef QUEUEBUF_CONF_NUM
#define QUEUEBUF_CONF_NUM 1
#undef TSCH_LOG_CONF_LEVEL
#define TSCH_LOG_CONF_LEVEL 2
/* TSCH per-slot logging */
#undef TSCH_LOG_CONF_PER_SLOT
#define TSCH_LOG_CONF_PER_SLOT 1
#undef TSCH_CONF_AUTOSTART
#define TSCH_CONF_AUTOSTART 1