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

Logging: added feature for compact address logging (last 16 bits). Cleanup more logs in MAC layers, IPv6 and RPL

This commit is contained in:
Simon Duquennoy 2017-06-23 21:12:36 +02:00
parent a78b4e32e9
commit 821590c4b5
32 changed files with 264 additions and 191 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

9
core/net/ip/tcpip.c
View File

@ -507,14 +507,16 @@ get_nexthop(uip_ipaddr_t *addr)
uip_ipaddr_t *nexthop;
uip_ds6_route_t *route;
LOG_INFO("output: looking for next hop for host ");
LOG_INFO("output: processing packet from ");
LOG_INFO_6ADDR(&UIP_IP_BUF->srcipaddr);
LOG_INFO_(" to ");
LOG_INFO_6ADDR(&UIP_IP_BUF->destipaddr);
LOG_INFO_("\n");
if(NEXTHOP_NON_STORING(addr)) {
LOG_INFO("output: selected next hop from SRH: ");
LOG_INFO_6ADDR(addr);
LOG_INFO("\n");
LOG_INFO_("\n");
return addr;
}
@ -728,6 +730,9 @@ send_packet:
linkaddr = NULL;
}
LOG_INFO("output: sending to ");
LOG_INFO_LLADDR((linkaddr_t *)linkaddr);
LOG_INFO_("\n");
tcpip_output(linkaddr);
if(nbr) {

2
core/net/ipv6/uip-ds6-nbr.c
View File

@ -54,7 +54,7 @@
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE "IPv6 Neighbor"
#define LOG_MODULE "IPv6 Nbr"
#define LOG_LEVEL IPV6_LOG_LEVEL
#ifdef UIP_CONF_DS6_NEIGHBOR_STATE_CHANGED

2
core/net/ipv6/uip-ds6.c
View File

@ -53,7 +53,7 @@
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE "IPv6 Data Structures"
#define LOG_MODULE "IPv6 DS"
#define LOG_LEVEL IPV6_LOG_LEVEL
struct etimer uip_ds6_timer_periodic; /**< Timer for maintenance of data structures */

2
core/net/ipv6/uip-icmp6.c
View File

@ -49,7 +49,7 @@
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE "IPv6 ICMPv6"
#define LOG_MODULE "ICMPv6"
#define LOG_LEVEL IPV6_LOG_LEVEL
#define UIP_IP_BUF ((struct uip_ip_hdr *)&uip_buf[UIP_LLH_LEN])

2
core/net/ipv6/websocket-http-client.c
View File

@ -40,7 +40,7 @@
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE "IPv6 Websocket"
#define LOG_MODULE "Websocket"
#define LOG_LEVEL IPV6_LOG_LEVEL
enum {

2
core/net/ipv6/websocket.c
View File

@ -39,7 +39,7 @@
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE "IPv6 Websocket"
#define LOG_MODULE "Websocket"
#define LOG_LEVEL IPV6_LOG_LEVEL
PROCESS(websocket_process, "Websockets process");

2
core/net/linkaddr.h
View File

@ -65,6 +65,8 @@ typedef union {
unsigned char u8[LINKADDR_SIZE];
#if LINKADDR_SIZE == 2
uint16_t u16;
#else
uint16_t u16[LINKADDR_SIZE/2];
#endif /* LINKADDR_SIZE == 2 */
} linkaddr_t;

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

@ -160,7 +160,7 @@ backoff_period(void)
}
/*---------------------------------------------------------------------------*/
static int
send_one_packet(mac_callback_t sent, void *ptr)
send_one_packet(void *ptr)
{
int ret;
int last_sent_ok = 0;
@ -172,7 +172,7 @@ send_one_packet(mac_callback_t sent, void *ptr)
if(NETSTACK_FRAMER.create() < 0) {
/* Failed to allocate space for headers */
LOG_ERR("send failed, too large header\n");
LOG_ERR("failed to create packet\n");
ret = MAC_TX_ERR_FATAL;
} else {
#if CSMA_802154_AUTOACK
@ -239,8 +239,6 @@ send_one_packet(mac_callback_t sent, void *ptr)
ret = MAC_TX_COLLISION;
}
}
} else {
LOG_WARN("tx noack\n");
}
}
break;
@ -275,7 +273,8 @@ send_one_packet(mac_callback_t sent, void *ptr)
if(ret == MAC_TX_OK) {
last_sent_ok = 1;
}
mac_call_sent_callback(sent, ptr, ret, 1);
packet_sent(ptr, ret, 1);
return last_sent_ok;
}
/*---------------------------------------------------------------------------*/
@ -286,11 +285,14 @@ transmit_from_queue(void *ptr)
if(n) {
struct packet_queue *q = list_head(n->packet_queue);
if(q != NULL) {
LOG_INFO("preparing number %d %p, queue len %d\n", n->transmissions, q,
list_length(n->packet_queue));
LOG_INFO("preparing packet for ");
LOG_INFO_LLADDR(&n->addr);
LOG_INFO_(", seqno %u, tx %u, queue %d\n",
queuebuf_attr(q->buf, PACKETBUF_ATTR_MAC_SEQNO),
n->transmissions, list_length(n->packet_queue));
/* Send first packet in the neighbor queue */
queuebuf_to_packetbuf(q->buf);
send_one_packet(packet_sent, n);
send_one_packet(n);
}
}
}
@ -310,7 +312,7 @@ schedule_transmission(struct neighbor_queue *n)
delay = random_rand() % delay;
}
LOG_INFO("scheduling transmission in %u ticks, NB=%u, BE=%u\n",
LOG_DBG("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);
}
@ -325,7 +327,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);
LOG_INFO("free_queued_packet, queue length %d, free packets %d\n",
LOG_DBG("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 */
@ -355,19 +357,11 @@ tx_done(int status, struct packet_queue *q, struct neighbor_queue *n)
cptr = metadata->cptr;
ntx = n->transmissions;
switch(status) {
case MAC_TX_OK:
LOG_INFO("tx ok %d\n", n->transmissions);
break;
case MAC_TX_COLLISION:
case MAC_TX_NOACK:
LOG_WARN("drop with status %d after %d transmissions, %d collisions\n",
status, n->transmissions, n->collisions);
break;
default:
LOG_ERR("tx failed %d: %d\n", n->transmissions, status);
break;
}
LOG_INFO("packet sent to ");
LOG_INFO_LLADDR(&n->addr);
LOG_INFO_(", seqno %u, status %u, tx %u, coll %u\n",
packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO),
status, n->transmissions, n->collisions);
free_packet(n, q, status);
mac_call_sent_callback(sent, cptr, status, ntx);
@ -401,7 +395,6 @@ collision(struct packet_queue *q, struct neighbor_queue *n,
if(n->transmissions >= metadata->max_transmissions) {
tx_done(MAC_TX_COLLISION, q, n);
} else {
LOG_INFO("tx collision %d\n", n->transmissions);
rexmit(q, n);
}
}
@ -419,7 +412,6 @@ 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 {
LOG_INFO("tx noack %d\n", n->transmissions);
rexmit(q, n);
}
}
@ -453,14 +445,20 @@ packet_sent(void *ptr, int status, int num_transmissions)
}
if(q == NULL) {
LOG_WARN("seqno %d not found\n",
LOG_WARN("packet sent: seqno %u not found\n",
packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO));
return;
} else if(q->ptr == NULL) {
LOG_WARN("no metadata\n");
LOG_WARN("packet sent: no metadata\n");
return;
}
LOG_INFO("tx to ");
LOG_INFO_LLADDR(&n->addr);
LOG_INFO_(", seqno %u, status %u, tx %u, coll %u\n",
packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO),
status, n->transmissions, n->collisions);
switch(status) {
case MAC_TX_OK:
tx_ok(q, n, num_transmissions);
@ -535,8 +533,11 @@ csma_output_packet(mac_callback_t sent, void *ptr)
metadata->cptr = ptr;
list_add(n->packet_queue, q);
LOG_INFO("send_packet, queue length %d, free packets %d\n",
list_length(n->packet_queue), memb_numfree(&packet_memb));
LOG_INFO("sending to ");
LOG_INFO_LLADDR(addr);
LOG_INFO_(", seqno %u, queue length %d, free packets %d\n",
packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO),
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) {
schedule_transmission(n);

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

@ -70,7 +70,7 @@ input_packet(void)
#if CSMA_802154_AUTOACK
if(packetbuf_datalen() == CSMA_ACK_LEN) {
/* Ignore ack packets */
LOG_INFO("ignored ack\n");
LOG_DBG("ignored ack\n");
} else
#endif /* CSMA_802154_AUTOACK */
if(NETSTACK_FRAMER.parse() < 0) {
@ -87,8 +87,9 @@ input_packet(void)
duplicate = mac_sequence_is_duplicate();
if(duplicate) {
/* Drop the packet. */
LOG_WARN("drop duplicate link layer packet %u\n",
packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO));
LOG_WARN("drop duplicate link layer packet from ");
LOG_WARN_LLADDR(packetbuf_addr(PACKETBUF_ADDR_SENDER));
LOG_WARN_(", seqno %u\n", packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO));
} else {
mac_sequence_register_seqno();
}

2
core/net/mac/framer/frame802154e-ie.c
View File

@ -42,7 +42,7 @@
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE "Frame 802.15.4e"
#define LOG_MODULE "Frame 15.4"
#define LOG_LEVEL FRAMER_LOG_LEVEL
/* c.f. IEEE 802.15.4e Table 4b */

2
core/net/mac/framer/framer-802154.c
View File

@ -45,7 +45,7 @@
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE "Frame 802.15.4e"
#define LOG_MODULE "Frame 15.4"
#define LOG_LEVEL FRAMER_LOG_LEVEL
/** \brief The sequence number (0x00 - 0xff) added to the transmitted

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

@ -41,22 +41,6 @@
void
mac_call_sent_callback(mac_callback_t sent, void *ptr, int status, int num_tx)
{
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:
LOG_INFO("collision after %d tx\n", num_tx);
break;
case MAC_TX_NOACK:
LOG_INFO("noack after %d tx\n", num_tx);
break;
case MAC_TX_OK:
LOG_INFO("sent after %d tx\n", num_tx);
break;
default:
LOG_INFO("error %d after %d tx\n", status, num_tx);
}
if(sent) {
sent(ptr, status, num_tx);
}

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

@ -50,6 +50,7 @@
#include "net/mac/tsch/tsch-schedule.h"
#include "net/mac/tsch/tsch-slot-operation.h"
#include "lib/ringbufindex.h"
#include "sys/log.h"
#if TSCH_LOG_PER_SLOT
@ -88,21 +89,26 @@ tsch_log_process_pending(void)
}
switch(log->type) {
case tsch_log_tx:
printf("%s-%u-%u %u tx %d, st %d-%d",
log->tx.dest == 0 ? "bc" : "uc", log->tx.is_data, log->tx.sec_level,
log->tx.datalen,
log->tx.dest,
log->tx.mac_tx_status, log->tx.num_tx);
printf("%s-%u-%u tx ",
linkaddr_cmp(&log->tx.dest, &linkaddr_null) ? "bc" : "uc", log->tx.is_data, log->tx.sec_level);
log_lladdr_compact(&linkaddr_node_addr);
printf("->");
log_lladdr_compact(&log->tx.dest);
printf(", len %u, seq %u, st %d %d",
log->tx.datalen, log->tx.seqno, log->tx.mac_tx_status, log->tx.num_tx);
if(log->tx.drift_used) {
printf(", dr %d", log->tx.drift);
}
printf("\n");
break;
case tsch_log_rx:
printf("%s-%u-%u %u rx %d",
log->rx.is_unicast == 0 ? "bc" : "uc", log->rx.is_data, log->rx.sec_level,
log->rx.datalen,
log->rx.src);
printf("%s-%u-%u rx ",
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);
printf(", len %u, seq %u",
log->rx.datalen, log->rx.seqno);
if(log->rx.drift_used) {
printf(", dr %d", log->rx.drift);
}

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

@ -56,13 +56,6 @@
#define TSCH_LOG_QUEUE_LEN 8
#endif /* TSCH_LOG_CONF_QUEUE_LEN */
/* Returns an integer ID from a link-layer address */
#ifdef TSCH_LOG_CONF_ID_FROM_LINKADDR
#define TSCH_LOG_ID_FROM_LINKADDR(addr) TSCH_LOG_CONF_ID_FROM_LINKADDR(addr)
#else /* TSCH_LOG_ID_FROM_LINKADDR */
#define TSCH_LOG_ID_FROM_LINKADDR(addr) ((addr) ? (addr)->u8[LINKADDR_SIZE - 1] : 0)
#endif /* TSCH_LOG_ID_FROM_LINKADDR */
#if (TSCH_LOG_PER_SLOT == 0)
#define tsch_log_init()
@ -85,16 +78,17 @@ struct tsch_log_t {
char message[48];
struct {
int mac_tx_status;
int dest;
linkaddr_t dest;
int drift;
uint8_t num_tx;
uint8_t datalen;
uint8_t is_data;
uint8_t sec_level;
uint8_t drift_used;
uint8_t seqno;
} tx;
struct {
int src;
linkaddr_t src;
int drift;
int estimated_drift;
uint8_t datalen;
@ -102,6 +96,7 @@ struct tsch_log_t {
uint8_t is_data;
uint8_t sec_level;
uint8_t drift_used;
uint8_t seqno;
} rx;
};
};

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

@ -53,7 +53,7 @@
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE "TSCH Packet"
#define LOG_MODULE "TSCH Pkt"
#define LOG_LEVEL MAC_LOG_LEVEL
/*---------------------------------------------------------------------------*/

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

@ -153,9 +153,11 @@ tsch_queue_update_time_source(const linkaddr_t *new_addr)
}
if(new_time_src != old_time_src) {
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));
LOG_INFO("update time source: ");
LOG_INFO_LLADDR(old_time_src ? &old_time_src->addr : NULL);
LOG_INFO_(" -> ");
LOG_INFO_LLADDR(new_time_src ? &new_time_src->addr : NULL);
LOG_INFO_("\n");
/* Update time source */
if(new_time_src != NULL) {
@ -199,7 +201,6 @@ tsch_queue_flush_nbr_queue(struct tsch_neighbor *n)
/* Free packet queuebuf */
tsch_queue_free_packet(p);
}
LOG_INFO("packet deleted %p\n", p);
}
}
/*---------------------------------------------------------------------------*/
@ -251,7 +252,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);
LOG_INFO("packet is added put_index %u, packet %p\n",
LOG_DBG("packet is added put_index %u, packet %p\n",
put_index, p);
return p;
} else {
@ -265,6 +266,13 @@ tsch_queue_add_packet(const linkaddr_t *addr, mac_callback_t sent, void *ptr)
return 0;
}
/*---------------------------------------------------------------------------*/
/* Returns the number of packets currently in any TSCH queue */
int
tsch_queue_global_packet_count(void)
{
return QUEUEBUF_NUM - memb_numfree(&packet_memb);
}
/*---------------------------------------------------------------------------*/
/* Returns the number of packets currently in the queue */
int
tsch_queue_packet_count(const linkaddr_t *addr)
@ -288,7 +296,6 @@ 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) {
LOG_INFO("packet is removed, get_index %u\n", get_index);
return n->tx_array[get_index];
} else {
return NULL;

2
core/net/mac/tsch/tsch-queue.h
View File

@ -160,6 +160,8 @@ struct tsch_neighbor *tsch_queue_get_time_source(void);
int tsch_queue_update_time_source(const linkaddr_t *new_addr);
/* Add packet to neighbor queue. Use same lockfree implementation as ringbuf.c (put is atomic) */
struct tsch_packet *tsch_queue_add_packet(const linkaddr_t *addr, mac_callback_t sent, void *ptr);
/* Returns the number of packets currently in any TSCH queue */
int tsch_queue_global_packet_count(void);
/* Returns the number of packets currently a given neighbor queue */
int tsch_queue_packet_count(const linkaddr_t *addr);
/* Remove first packet from a neighbor queue. The packet is stored in a separate

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

@ -57,7 +57,7 @@
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE "TSCH Schedule"
#define LOG_MODULE "TSCH Sched"
#define LOG_LEVEL MAC_LOG_LEVEL
/* Pre-allocated space for links */
@ -208,9 +208,10 @@ tsch_schedule_add_link(struct tsch_slotframe *slotframe,
}
linkaddr_copy(&l->addr, address);
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));
LOG_INFO("add_link %u %u %u %u %u ",
slotframe->handle, link_options, link_type, timeslot, channel_offset);
LOG_INFO_LLADDR(address);
LOG_INFO_("\n");
/* Release the lock before we update the neighbor (will take the lock) */
tsch_release_lock();
@ -249,9 +250,10 @@ tsch_schedule_remove_link(struct tsch_slotframe *slotframe, struct tsch_link *l)
if(l == current_link) {
current_link = NULL;
}
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));
LOG_INFO("remove_link %u %u %u %u ",
slotframe->handle, l->link_options, l->timeslot, l->channel_offset);
LOG_INFO_LLADDR(&l->addr);
LOG_INFO_("\n");
list_remove(slotframe->links_list, l);
memb_free(&link_memb, l);

23
core/net/mac/tsch/tsch-slot-operation.c
View File

@ -59,8 +59,7 @@
#include "sys/cooja_mt.h"
#endif /* CONTIKI_TARGET_COOJA || CONTIKI_TARGET_COOJA_IP64 */
#include <stdio.h>
#include "sys/log.h"
/* TSCH debug macros, i.e. to set LEDs or GPIOs on various TSCH
* timeslot events */
#ifndef TSCH_DEBUG_INIT
@ -690,17 +689,18 @@ PT_THREAD(tsch_tx_slot(struct pt *pt, struct rtimer *t))
/* Log every tx attempt */
TSCH_LOG_ADD(tsch_log_tx,
log->tx.mac_tx_status = mac_tx_status;
log->tx.num_tx = current_packet->transmissions;
log->tx.datalen = queuebuf_datalen(current_packet->qb);
log->tx.drift = drift_correction;
log->tx.drift_used = is_drift_correction_used;
log->tx.is_data = ((((uint8_t *)(queuebuf_dataptr(current_packet->qb)))[0]) & 7) == FRAME802154_DATAFRAME;
log->tx.num_tx = current_packet->transmissions;
log->tx.datalen = queuebuf_datalen(current_packet->qb);
log->tx.drift = drift_correction;
log->tx.drift_used = is_drift_correction_used;
log->tx.is_data = ((((uint8_t *)(queuebuf_dataptr(current_packet->qb)))[0]) & 7) == FRAME802154_DATAFRAME;
#if LLSEC802154_ENABLED
log->tx.sec_level = queuebuf_attr(current_packet->qb, PACKETBUF_ATTR_SECURITY_LEVEL);
log->tx.sec_level = queuebuf_attr(current_packet->qb, PACKETBUF_ATTR_SECURITY_LEVEL);
#else /* LLSEC802154_ENABLED */
log->tx.sec_level = 0;
log->tx.sec_level = 0;
#endif /* LLSEC802154_ENABLED */
log->tx.dest = TSCH_LOG_ID_FROM_LINKADDR(queuebuf_addr(current_packet->qb, PACKETBUF_ADDR_RECEIVER));
linkaddr_copy(&log->tx.dest, queuebuf_addr(current_packet->qb, PACKETBUF_ADDR_RECEIVER));
log->tx.seqno = queuebuf_attr(current_packet->qb, PACKETBUF_ATTR_MAC_SEQNO);
);
/* Poll process for later processing of packet sent events and logs */
@ -894,7 +894,7 @@ PT_THREAD(tsch_rx_slot(struct pt *pt, struct rtimer *t))
/* Log every reception */
TSCH_LOG_ADD(tsch_log_rx,
log->rx.src = TSCH_LOG_ID_FROM_LINKADDR((linkaddr_t*)&frame.src_addr);
linkaddr_copy(&log->rx.src, (linkaddr_t *)&frame.src_addr);
log->rx.is_unicast = frame.fcf.ack_required;
log->rx.datalen = current_input->len;
log->rx.drift = drift_correction;
@ -902,6 +902,7 @@ PT_THREAD(tsch_rx_slot(struct pt *pt, struct rtimer *t))
log->rx.is_data = frame.fcf.frame_type == FRAME802154_DATAFRAME;
log->rx.sec_level = frame.aux_hdr.security_control.security_level;
log->rx.estimated_drift = estimated_drift;
log->rx.seqno = frame.seq;
);
}

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

@ -226,8 +226,9 @@ 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
LOG_INFO("KA sent to %u, st %d-%d\n",
TSCH_LOG_ID_FROM_LINKADDR(packetbuf_addr(PACKETBUF_ADDR_RECEIVER)), status, transmissions);
LOG_INFO("KA sent to ");
LOG_INFO_LLADDR(packetbuf_addr(PACKETBUF_ADDR_RECEIVER));
LOG_INFO_(", st %d-%d\n", status, transmissions);
tsch_schedule_keepalive();
}
/*---------------------------------------------------------------------------*/
@ -241,8 +242,9 @@ keepalive_send()
packetbuf_clear();
packetbuf_set_addr(PACKETBUF_ADDR_RECEIVER, &n->addr);
NETSTACK_MAC.send(keepalive_packet_sent, NULL);
LOG_INFO("sending KA to %u\n",
TSCH_LOG_ID_FROM_LINKADDR(&n->addr));
LOG_INFO("sending KA to ");
LOG_INFO_LLADDR(&n->addr);
LOG_INFO_("\n");
}
}
/*---------------------------------------------------------------------------*/
@ -381,6 +383,9 @@ tsch_tx_process_pending()
struct tsch_packet *p = dequeued_array[dequeued_index];
/* Put packet into packetbuf for packet_sent callback */
queuebuf_to_packetbuf(p->qb);
LOG_INFO("packet sent to ");
LOG_INFO_LLADDR(packetbuf_addr(PACKETBUF_ADDR_RECEIVER));
LOG_INFO_(", status %d, tx %d\n", p->ret, p->transmissions);
/* Call packet_sent callback */
mac_call_sent_callback(p->sent, p->ptr, p->ret, p->transmissions);
/* Free packet queuebuf */
@ -864,7 +869,6 @@ static void
send_packet(mac_callback_t sent, void *ptr)
{
int ret = MAC_TX_DEFERRED;
int packet_count_before;
int hdr_len = 0;
const linkaddr_t *addr = packetbuf_addr(PACKETBUF_ADDR_RECEIVER);
@ -906,8 +910,6 @@ send_packet(mac_callback_t sent, void *ptr)
}
#endif /* LLSEC802154_ENABLED */
packet_count_before = tsch_queue_packet_count(addr);
#if !NETSTACK_CONF_BRIDGE_MODE
/*
* In the Contiki stack, the source address of a frame is set at the RDC
@ -925,20 +927,19 @@ send_packet(mac_callback_t sent, void *ptr)
/* Enqueue packet */
p = tsch_queue_add_packet(addr, sent, ptr);
if(p == NULL) {
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));
LOG_ERR("! can't send packet to ");
LOG_ERR_LLADDR(addr);
LOG_ERR_(" with seqno %u, queue %u %u\n",
tsch_packet_seqno, tsch_queue_packet_count(addr), tsch_queue_global_packet_count());
ret = MAC_TX_ERR;
} else {
p->header_len = hdr_len;
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_PER_SLOT */
LOG_INFO("send packet to ");
LOG_INFO_LLADDR(addr);
LOG_INFO_(" with seqno %u, queue %u %u, len %u %u\n",
tsch_packet_seqno,
tsch_queue_packet_count(addr), tsch_queue_global_packet_count(),
p->header_len, queuebuf_datalen(p->qb));
}
}
if(ret != MAC_TX_DEFERRED) {
@ -964,18 +965,18 @@ packet_input(void)
duplicate = mac_sequence_is_duplicate();
if(duplicate) {
/* Drop the packet. */
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));
LOG_WARN("! drop dup ll from ");
LOG_WARN_LLADDR(packetbuf_addr(PACKETBUF_ADDR_SENDER));
LOG_WARN_(" seqno %u\n", packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO));
} else {
mac_sequence_register_seqno();
}
}
if(!duplicate) {
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));
LOG_INFO("received from ");
LOG_INFO_LLADDR(packetbuf_addr(PACKETBUF_ADDR_SENDER));
LOG_INFO_(" with seqno %u\n", packetbuf_attr(PACKETBUF_ATTR_MAC_SEQNO));
NETSTACK_NETWORK.input();
}
}

4
core/net/net-debug.c
View File

@ -50,8 +50,8 @@ net_debug_lladdr_print(const uip_lladdr_t *addr)
} else {
unsigned int i;
for(i = 0; i < LINKADDR_SIZE; i++) {
if(i > 0) {
PRINTA(":");
if(i > 0 && i % 2 == 0) {
PRINTA(".");
}
PRINTA("%02x", addr->addr[i]);
}

39
core/net/rpl-lite/rpl-dag.c
View File

@ -56,33 +56,18 @@
extern rpl_of_t rpl_of0, rpl_mrhof;
static rpl_of_t * const objective_functions[] = RPL_SUPPORTED_OFS;
static int init_dag_from_dio(rpl_dio_t *dio);
static void leave_dag(void);
/*---------------------------------------------------------------------------*/
/* Allocate instance table. */
rpl_instance_t curr_instance;
/*---------------------------------------------------------------------------*/
void
rpl_dag_periodic(unsigned seconds)
{
if(curr_instance.used) {
if(curr_instance.dag.lifetime != RPL_LIFETIME(RPL_INFINITE_LIFETIME)) {
curr_instance.dag.lifetime =
curr_instance.dag.lifetime > seconds ? curr_instance.dag.lifetime - seconds : 0;
if(curr_instance.dag.lifetime == 0) {
leave_dag();
}
}
}
}
/*---------------------------------------------------------------------------*/
static void
leave_dag(void)
leave_dag(const char *str)
{
LOG_INFO("leaving DAG \n");
LOG_INFO("leaving DAG ");
LOG_INFO_6ADDR(&curr_instance.dag.dag_id);
LOG_INFO_(", instance %u\n", curr_instance.instance_id);
LOG_INFO_(", instance %u (%s)\n", curr_instance.instance_id, str);
/* Issue a no-path DAO */
RPL_LOLLIPOP_INCREMENT(curr_instance.dag.dao_curr_seqno);
@ -102,6 +87,20 @@ leave_dag(void)
curr_instance.used = 0;
}
/*---------------------------------------------------------------------------*/
void
rpl_dag_periodic(unsigned seconds)
{
if(curr_instance.used) {
if(curr_instance.dag.lifetime != RPL_LIFETIME(RPL_INFINITE_LIFETIME)) {
curr_instance.dag.lifetime =
curr_instance.dag.lifetime > seconds ? curr_instance.dag.lifetime - seconds : 0;
if(curr_instance.dag.lifetime == 0) {
leave_dag("expired");
}
}
}
}
/*---------------------------------------------------------------------------*/
int
rpl_is_addr_in_our_dag(const uip_ipaddr_t *addr)
{
@ -493,7 +492,7 @@ rpl_process_dao_ack(uint8_t sequence, uint8_t status)
if(status >= RPL_DAO_ACK_UNABLE_TO_ACCEPT) {
/* We got a NACK, leave the DAG */
leave_dag();
leave_dag("DAO-NACK");
}
}
}
@ -545,7 +544,7 @@ rpl_dag_init_root(uint8_t instance_id, uip_ipaddr_t *dag_id,
version = curr_instance.dag.version;
RPL_LOLLIPOP_INCREMENT(version);
}
leave_dag();
leave_dag("init root");
}
/* Init DAG and instance */

19
core/net/rpl-lite/rpl-ext-header.c
View File

@ -115,7 +115,7 @@ rpl_ext_header_srh_get_next_hop(uip_ipaddr_t *ipaddr)
return 1;
}
LOG_ERR("packet needs multi-hop downward routing but SRH not found\n");
LOG_DBG("no SRH found\n");
uip_ext_len = last_uip_ext_len;
return 0;
}
@ -249,8 +249,8 @@ insert_srh_header(void)
dest_node = rpl_ns_get_node(&UIP_IP_BUF->destipaddr);
if(dest_node == NULL) {
/* The destination is not found, skip SRH insertion */
return 1;
LOG_ERR("SRH node not found\n");
return 0;
}
root_node = rpl_ns_get_node(&curr_instance.dag.dag_id);
@ -271,10 +271,9 @@ insert_srh_header(void)
cmpri = 15;
cmpre = 15;
if(node == root_node) {
LOG_INFO("SRH no need to insert SRH\n");
return 1;
}
/* Note that in case of a direct child (node == root_node), we insert
SRH anyway, as RFC 6553 mandates that routed datagrams must include
SRH or the RPL option (or both) */
while(node != NULL && node != root_node) {
@ -395,7 +394,11 @@ rpl_ext_header_hbh_update(int uip_ext_opt_offset)
sender_closer = sender_rank < curr_instance.dag.rank;
loop_detected = (down && !sender_closer) || (!down && sender_closer);
LOG_INFO("packet going %s, sender closer %d (%d < %d), rank error %u, loop detected %u\n",
LOG_INFO("ext hdr: packet from ");
LOG_INFO_6ADDR(&UIP_IP_BUF->srcipaddr);
LOG_INFO_(" to ");
LOG_INFO_6ADDR(&UIP_IP_BUF->destipaddr);
LOG_INFO_(" going %s, sender closer %d (%d < %d), rank error %u, loop detected %u\n",
down == 1 ? "down" : "up", sender_closer, sender_rank,
curr_instance.dag.rank, rank_error_signaled, loop_detected);

4
core/net/rpl-lite/rpl-icmp6.c
View File

@ -532,7 +532,7 @@ dao_input(void)
/* Destination Advertisement Object */
LOG_INFO("received a %sDAO from ", dao.lifetime == 0 ? "No-path " : "");
LOG_INFO_6ADDR(&UIP_IP_BUF->srcipaddr);
LOG_INFO_(", lifetime %u, prefix ", dao.lifetime);
LOG_INFO_(", seqno %u, lifetime %u, prefix ", dao.sequence, dao.lifetime);
LOG_INFO_6ADDR(&dao.prefix);
LOG_INFO_(", prefix length %u, parent ", dao.prefixlen);
LOG_INFO_6ADDR(&dao.parent_addr);
@ -606,7 +606,7 @@ rpl_icmp6_dao_output(uint8_t lifetime)
LOG_INFO_6ADDR(prefix);
LOG_INFO_(" to ");
LOG_INFO_6ADDR(&curr_instance.dag.dag_id);
LOG_INFO_(" , parent ");
LOG_INFO_(", parent ");
LOG_INFO_6ADDR(parent_ipaddr);
LOG_INFO_("\n");

2
core/net/rpl-lite/rpl-mrhof.c
View File

@ -94,7 +94,7 @@ to the threshold of 96 in the non-squared case) */
static void
reset(void)
{
LOG_INFO("Reset MRHOF\n");
LOG_INFO("reset MRHOF\n");
}
/*---------------------------------------------------------------------------*/
static uint16_t

12
core/net/rpl-lite/rpl-neighbor.c
View File

@ -83,17 +83,21 @@ rpl_neighbor_print_list(const char *str)
rpl_nbr_t *nbr = nbr_table_head(rpl_neighbors);
clock_time_t clock_now = clock_time();
printf("nbr: MOP %u OCP %u rank %u dioint %u, DS6 nbr count %u (%s)\n",
LOG_INFO("nbr: own state, addr ");
LOG_INFO_6ADDR(rpl_get_global_address());
LOG_INFO_(" MOP %u OCP %u rank %u dioint %u, DS6 nbr count %u (%s)\n",
curr_instance.mop, curr_instance.of->ocp, curr_rank,
curr_dio_interval, uip_ds6_nbr_num(), str);
while(nbr != NULL) {
const struct link_stats *stats = rpl_neighbor_get_link_stats(nbr);
printf("nbr: %3u %5u, %5u => %5u -- %2u %c%c%c (last tx %u min ago)\n",
rpl_neighbor_get_ipaddr(nbr)->u8[15],
LOG_INFO("nbr: ");
LOG_INFO_6ADDR(rpl_neighbor_get_ipaddr(nbr));
LOG_INFO_(" %5u, %5u => %5u -- %2u %c%c%c%c (last tx %u min ago)\n",
nbr->rank,
rpl_neighbor_get_link_metric(nbr),
rpl_neighbor_rank_via_nbr(nbr),
stats != NULL ? stats->freshness : 0,
(nbr->rank == ROOT_RANK) ? 'r' : ' ',
(acceptable_rank(rpl_neighbor_rank_via_nbr(nbr)) && curr_instance.of->nbr_is_acceptable_parent(nbr)) ? 'a' : ' ',
link_stats_is_fresh(stats) ? 'f' : ' ',
nbr == curr_instance.dag.preferred_parent ? 'p' : ' ',
@ -101,7 +105,7 @@ rpl_neighbor_print_list(const char *str)
);
nbr = nbr_table_next(rpl_neighbors, nbr);
}
printf("nbr: end of list\n");
LOG_INFO("nbr: end of list\n");
}
}
/*---------------------------------------------------------------------------*/

2
core/net/rpl-lite/rpl-of0.c
View File

@ -89,7 +89,7 @@
static void
reset(void)
{
LOG_INFO("Reset OF0\n");
LOG_INFO("reset OF0\n");
}
/*---------------------------------------------------------------------------*/
static uint16_t

7
core/net/rpl-lite/rpl-timers.c
View File

@ -412,8 +412,9 @@ handle_probing_timer(void *ptr)
if(target_ipaddr != NULL) {
const struct link_stats *stats = rpl_neighbor_get_link_stats(probing_target);
(void)stats;
LOG_INFO("probing %u %s last tx %u min ago\n",
rpl_neighbor_get_lladdr(probing_target)->u8[7],
LOG_INFO("probing ");
LOG_INFO_6ADDR(rpl_neighbor_get_ipaddr(probing_target));
LOG_INFO_(" %s last tx %u min ago\n",
curr_instance.dag.urgent_probing_target != NULL ? "(urgent)" : "",
probing_target != NULL ?
(unsigned)((clock_time() - stats->last_tx_time) / (60 * CLOCK_SECOND)) : 0
@ -463,7 +464,7 @@ handle_periodic_timer(void *ptr)
ctimer_reset(&periodic_timer);
#if LOG_INFO_ENABLED
rpl_neighbor_print_list("Periodic");
rpl_neighbor_print_list("Periodic");
#endif /* LOG_INFO_ENABLED */
}
/*---------------------------------------------------------------------------*/

3
core/net/rpl-lite/rpl.c
View File

@ -93,6 +93,9 @@ rpl_link_neighbor_callback(const linkaddr_t *addr, int status, int numtx)
if(nbr != NULL) {
/* Link stats were updated, and we need to update our internal state.
Updating from here is unsafe; postpone */
LOG_INFO("packet sent to ");
LOG_INFO_LLADDR(addr);
LOG_INFO_(", status %u, tx %u\n", status, numtx);
rpl_timers_schedule_state_update();
}
}

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

@ -49,15 +49,15 @@
/* A list of currently supported modules */
#ifndef RPL_LOG_LEVEL
#define RPL_LOG_LEVEL LOG_LEVEL_INFO /* Only for rpl-lite */
#define RPL_LOG_LEVEL LOG_LEVEL_NONE /* Only for rpl-lite */
#endif /* RPL_LOG_LEVEL */
#ifndef TCPIP_LOG_LEVEL
#define TCPIP_LOG_LEVEL LOG_LEVEL_WARN
#define TCPIP_LOG_LEVEL LOG_LEVEL_NONE
#endif /* TCPIP_LOG_LEVEL */
#ifndef IPV6_LOG_LEVEL
#define IPV6_LOG_LEVEL LOG_LEVEL_WARN
#define IPV6_LOG_LEVEL LOG_LEVEL_NONE
#endif /* IPV6_LOG_LEVEL */
#ifndef SICSLOWPAN_LOG_LEVEL

70
core/sys/log.h
View File

@ -89,14 +89,46 @@ void uip_debug_ipaddr_print(const uip_ipaddr_t *addr);
#define LOG_WITH_ANNOTATE 0
#endif /* LOG_CONF_WITH_ANNOTATE */
/* Log only the last 16 bytes of linklayer and IPv6 addresses */
#ifdef LOG_CONF_WITH_COMPACT_ADDR
#define LOG_WITH_COMPACT_ADDR LOG_CONF_WITH_COMPACT_ADDR
#else /* LOG_CONF_WITH_COMPACT_ADDR */
#define LOG_WITH_COMPACT_ADDR 0
#endif /* LOG_CONF_WITH_COMPACT_ADDR */
/* Compact address representation and logging */
static inline void
log_lladdr_compact(const linkaddr_t *lladdr)
{
if(lladdr == NULL) {
LOG_OUTPUT("LL-NULL");
} else {
LOG_OUTPUT("LL-%04x", UIP_HTONS(lladdr->u16[LINKADDR_SIZE/2-1]));
}
}
static inline void
log_6addr_compact(const uip_ipaddr_t *ipaddr)
{
if(ipaddr == NULL) {
LOG_OUTPUT("6A-NULL");
} else if(uip_is_addr_mcast(ipaddr)) {
LOG_OUTPUT("6M-%04x", UIP_HTONS(ipaddr->u16[sizeof(uip_ipaddr_t)/2-1]));
} else if(uip_is_addr_linklocal(ipaddr)) {
LOG_OUTPUT("6L-%04x", UIP_HTONS(ipaddr->u16[sizeof(uip_ipaddr_t)/2-1]));
} else {
LOG_OUTPUT("6G-%04x", UIP_HTONS(ipaddr->u16[sizeof(uip_ipaddr_t)/2-1]));
}
}
/* Main log function */
#define LOG(newline, level, ...) do { \
#define LOG(newline, level, levelstr, ...) do { \
if(level <= LOG_LEVEL) { \
if(newline) { \
LOG_OUTPUT("[%-4s: %-10s] ", levelstr, LOG_MODULE); \
if(LOG_WITH_LOC) { \
LOG_OUTPUT("%s:%d: ", __FILE__, __LINE__); \
LOG_OUTPUT("[%s: %d] ", __FILE__, __LINE__); \
} \
LOG_OUTPUT("%s: ", LOG_MODULE); \
} \
LOG_OUTPUT(__VA_ARGS__); \
} \
@ -112,27 +144,35 @@ void uip_debug_ipaddr_print(const uip_ipaddr_t *addr);
/* Link-layer address */
#define LOG_LLADDR(level, lladdr) do { \
if(level <= LOG_LEVEL) { \
net_debug_lladdr_print(lladdr); \
if(LOG_WITH_COMPACT_ADDR) { \
log_lladdr_compact(lladdr); \
} else { \
net_debug_lladdr_print(lladdr); \
} \
} \
} while (0)
/* IPv6 address */
#define LOG_6ADDR(level, lladdr) do { \
#define LOG_6ADDR(level, ipaddr) do { \
if(level <= LOG_LEVEL) { \
uip_debug_ipaddr_print(lladdr); \
if(LOG_WITH_COMPACT_ADDR) { \
log_6addr_compact(ipaddr); \
} else { \
uip_debug_ipaddr_print(ipaddr); \
} \
} \
} while (0)
} while (0)
/* More compact versions of LOG macros */
#define LOG_ERR(...) LOG(1, LOG_LEVEL_ERR, __VA_ARGS__)
#define LOG_WARN(...) LOG(1, LOG_LEVEL_WARN, __VA_ARGS__)
#define LOG_INFO(...) LOG(1, LOG_LEVEL_INFO, __VA_ARGS__)
#define LOG_DBG(...) LOG(1, LOG_LEVEL_DBG, __VA_ARGS__)
#define LOG_ERR(...) LOG(1, LOG_LEVEL_ERR, "ERR", __VA_ARGS__)
#define LOG_WARN(...) LOG(1, LOG_LEVEL_WARN, "WARN", __VA_ARGS__)
#define LOG_INFO(...) LOG(1, LOG_LEVEL_INFO, "INFO", __VA_ARGS__)
#define LOG_DBG(...) LOG(1, LOG_LEVEL_DBG, "DBG", __VA_ARGS__)
#define LOG_ERR_(...) LOG(0, LOG_LEVEL_ERR, __VA_ARGS__)
#define LOG_WARN_(...) LOG(0, LOG_LEVEL_WARN, __VA_ARGS__)
#define LOG_INFO_(...) LOG(0, LOG_LEVEL_INFO, __VA_ARGS__)
#define LOG_DBG_(...) LOG(0, LOG_LEVEL_DBG, __VA_ARGS__)
#define LOG_ERR_(...) LOG(0, LOG_LEVEL_ERR, "ERR", __VA_ARGS__)
#define LOG_WARN_(...) LOG(0, LOG_LEVEL_WARN, "WARN", __VA_ARGS__)
#define LOG_INFO_(...) LOG(0, LOG_LEVEL_INFO, "INFO", __VA_ARGS__)
#define LOG_DBG_(...) LOG(0, LOG_LEVEL_DBG, "DBG", __VA_ARGS__)
#define LOG_ERR_LLADDR(...) LOG_LLADDR(LOG_LEVEL_ERR, __VA_ARGS__)
#define LOG_WARN_LLADDR(...) LOG_LLADDR(LOG_LEVEL_WARN, __VA_ARGS__)

32
examples/ipv6/rpl-simple/node.c
View File

@ -44,6 +44,11 @@
#include "dev/serial-line.h"
#include "net/ipv6/uip-ds6-route.h"
/* Log configuration */
#include "sys/log.h"
#define LOG_MODULE "App"
#define LOG_LEVEL LOG_LEVEL_INFO
#define UDP_PORT 8765
#define START_INTERVAL (15 * CLOCK_SECOND)
@ -69,26 +74,37 @@ receiver(struct simple_udp_connection *c,
const uint8_t *data,
uint16_t datalen)
{
int seq_id;
unsigned seq_id;
memcpy(&seq_id, data, sizeof(int));
if(uip_ip6addr_cmp(&destination_ipaddr, &node_ipaddr)) {
printf("App: received %u from %u\n", seq_id, sender_addr->u8[15]);
printf("App: sending reply to %u\n", sender_addr->u8[15]);
LOG_INFO("received request %u from ", seq_id);
LOG_INFO_6ADDR(sender_addr);
LOG_INFO_("\n");
LOG_INFO("sending reply %u to ", seq_id);
LOG_INFO_6ADDR(sender_addr);
LOG_INFO_("\n");
simple_udp_sendto(&udp_conn, &seq_id, sizeof(seq_id), sender_addr);
} else {
printf("App: received reply %u from %u\n", seq_id, sender_addr->u8[15]);
static unsigned reply_count = 0;
reply_count++;
LOG_INFO("received reply %u (%u/%u) from ", seq_id, reply_count, seq_id);
LOG_INFO_6ADDR(sender_addr);
LOG_INFO_("\n");
}
}
/*---------------------------------------------------------------------------*/
static void
send_packet(void *ptr)
{
if(rpl_get_default_instance() != NULL) {
static int seq_id = 0;
printf("App: sending request %u to %u\n", ++seq_id, destination_ipaddr.u8[15]);
if(rpl_is_reachable()) {
static unsigned seq_id = 0;
LOG_INFO("sending request %u to ", ++seq_id);
LOG_INFO_6ADDR(&destination_ipaddr);
LOG_INFO_("\n");
simple_udp_sendto(&udp_conn, &seq_id, sizeof(seq_id), &destination_ipaddr);
} else {
printf("App: not joined\n");
LOG_INFO("not connected yet\n");
}
}
/*---------------------------------------------------------------------------*/