diff --git a/core/net/ip/tcpip.c b/core/net/ip/tcpip.c index bfa83f082..6d7eac8ec 100644 --- a/core/net/ip/tcpip.c +++ b/core/net/ip/tcpip.c @@ -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) { diff --git a/core/net/ipv6/uip-ds6-nbr.c b/core/net/ipv6/uip-ds6-nbr.c index ae4987d38..9e0cee179 100644 --- a/core/net/ipv6/uip-ds6-nbr.c +++ b/core/net/ipv6/uip-ds6-nbr.c @@ -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 diff --git a/core/net/ipv6/uip-ds6.c b/core/net/ipv6/uip-ds6.c index 3f79155fc..6e7be7b66 100644 --- a/core/net/ipv6/uip-ds6.c +++ b/core/net/ipv6/uip-ds6.c @@ -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 */ diff --git a/core/net/ipv6/uip-icmp6.c b/core/net/ipv6/uip-icmp6.c index 8dfbe9087..9e28abc92 100644 --- a/core/net/ipv6/uip-icmp6.c +++ b/core/net/ipv6/uip-icmp6.c @@ -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]) diff --git a/core/net/ipv6/websocket-http-client.c b/core/net/ipv6/websocket-http-client.c index dd1c0431b..b712a42f2 100644 --- a/core/net/ipv6/websocket-http-client.c +++ b/core/net/ipv6/websocket-http-client.c @@ -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 { diff --git a/core/net/ipv6/websocket.c b/core/net/ipv6/websocket.c index 4abc537b5..9f1fe7a9d 100644 --- a/core/net/ipv6/websocket.c +++ b/core/net/ipv6/websocket.c @@ -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"); diff --git a/core/net/linkaddr.h b/core/net/linkaddr.h index 839af4cbe..da9000253 100644 --- a/core/net/linkaddr.h +++ b/core/net/linkaddr.h @@ -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; diff --git a/core/net/mac/csma/csma-output.c b/core/net/mac/csma/csma-output.c index e99b01033..a9dded386 100644 --- a/core/net/mac/csma/csma-output.c +++ b/core/net/mac/csma/csma-output.c @@ -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); diff --git a/core/net/mac/csma/csma.c b/core/net/mac/csma/csma.c index 5d5329131..56b71e8b0 100644 --- a/core/net/mac/csma/csma.c +++ b/core/net/mac/csma/csma.c @@ -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(); } diff --git a/core/net/mac/framer/frame802154e-ie.c b/core/net/mac/framer/frame802154e-ie.c index f050d3b05..20eb98d8b 100644 --- a/core/net/mac/framer/frame802154e-ie.c +++ b/core/net/mac/framer/frame802154e-ie.c @@ -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 */ diff --git a/core/net/mac/framer/framer-802154.c b/core/net/mac/framer/framer-802154.c index ecb04811b..e674a71ef 100644 --- a/core/net/mac/framer/framer-802154.c +++ b/core/net/mac/framer/framer-802154.c @@ -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 diff --git a/core/net/mac/mac.c b/core/net/mac/mac.c index 6aec9d023..3a6ffff97 100644 --- a/core/net/mac/mac.c +++ b/core/net/mac/mac.c @@ -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); } diff --git a/core/net/mac/tsch/tsch-log.c b/core/net/mac/tsch/tsch-log.c index 9f631988b..47f57630d 100644 --- a/core/net/mac/tsch/tsch-log.c +++ b/core/net/mac/tsch/tsch-log.c @@ -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); } diff --git a/core/net/mac/tsch/tsch-log.h b/core/net/mac/tsch/tsch-log.h index caf26e515..d86a4c137 100644 --- a/core/net/mac/tsch/tsch-log.h +++ b/core/net/mac/tsch/tsch-log.h @@ -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; }; }; diff --git a/core/net/mac/tsch/tsch-packet.c b/core/net/mac/tsch/tsch-packet.c index 3d4ac2ee7..923f03457 100644 --- a/core/net/mac/tsch/tsch-packet.c +++ b/core/net/mac/tsch/tsch-packet.c @@ -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 /*---------------------------------------------------------------------------*/ diff --git a/core/net/mac/tsch/tsch-queue.c b/core/net/mac/tsch/tsch-queue.c index d1a19a648..c9a68ed9e 100644 --- a/core/net/mac/tsch/tsch-queue.c +++ b/core/net/mac/tsch/tsch-queue.c @@ -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; diff --git a/core/net/mac/tsch/tsch-queue.h b/core/net/mac/tsch/tsch-queue.h index 00cffec16..f73cb0d10 100644 --- a/core/net/mac/tsch/tsch-queue.h +++ b/core/net/mac/tsch/tsch-queue.h @@ -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 diff --git a/core/net/mac/tsch/tsch-schedule.c b/core/net/mac/tsch/tsch-schedule.c index b16c8b7a7..378a34ff8 100644 --- a/core/net/mac/tsch/tsch-schedule.c +++ b/core/net/mac/tsch/tsch-schedule.c @@ -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); diff --git a/core/net/mac/tsch/tsch-slot-operation.c b/core/net/mac/tsch/tsch-slot-operation.c index 6f1749bd2..57250757f 100644 --- a/core/net/mac/tsch/tsch-slot-operation.c +++ b/core/net/mac/tsch/tsch-slot-operation.c @@ -59,8 +59,7 @@ #include "sys/cooja_mt.h" #endif /* CONTIKI_TARGET_COOJA || CONTIKI_TARGET_COOJA_IP64 */ -#include - +#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; ); } diff --git a/core/net/mac/tsch/tsch.c b/core/net/mac/tsch/tsch.c index 7a90c3347..b4365bf8e 100644 --- a/core/net/mac/tsch/tsch.c +++ b/core/net/mac/tsch/tsch.c @@ -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(); } } diff --git a/core/net/net-debug.c b/core/net/net-debug.c index 8d6fb19d7..deec18cb2 100644 --- a/core/net/net-debug.c +++ b/core/net/net-debug.c @@ -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]); } diff --git a/core/net/rpl-lite/rpl-dag.c b/core/net/rpl-lite/rpl-dag.c index eff99b76f..d03efa9a0 100644 --- a/core/net/rpl-lite/rpl-dag.c +++ b/core/net/rpl-lite/rpl-dag.c @@ -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 */ diff --git a/core/net/rpl-lite/rpl-ext-header.c b/core/net/rpl-lite/rpl-ext-header.c index e29fa738f..d16de80b3 100644 --- a/core/net/rpl-lite/rpl-ext-header.c +++ b/core/net/rpl-lite/rpl-ext-header.c @@ -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); diff --git a/core/net/rpl-lite/rpl-icmp6.c b/core/net/rpl-lite/rpl-icmp6.c index 505fc67f1..ec5c0f5c2 100644 --- a/core/net/rpl-lite/rpl-icmp6.c +++ b/core/net/rpl-lite/rpl-icmp6.c @@ -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"); diff --git a/core/net/rpl-lite/rpl-mrhof.c b/core/net/rpl-lite/rpl-mrhof.c index a40748a81..f9c70913e 100644 --- a/core/net/rpl-lite/rpl-mrhof.c +++ b/core/net/rpl-lite/rpl-mrhof.c @@ -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 diff --git a/core/net/rpl-lite/rpl-neighbor.c b/core/net/rpl-lite/rpl-neighbor.c index 8a558d6a5..7bb9a56f6 100644 --- a/core/net/rpl-lite/rpl-neighbor.c +++ b/core/net/rpl-lite/rpl-neighbor.c @@ -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"); } } /*---------------------------------------------------------------------------*/ diff --git a/core/net/rpl-lite/rpl-of0.c b/core/net/rpl-lite/rpl-of0.c index cdb421088..72c01217c 100644 --- a/core/net/rpl-lite/rpl-of0.c +++ b/core/net/rpl-lite/rpl-of0.c @@ -89,7 +89,7 @@ static void reset(void) { - LOG_INFO("Reset OF0\n"); + LOG_INFO("reset OF0\n"); } /*---------------------------------------------------------------------------*/ static uint16_t diff --git a/core/net/rpl-lite/rpl-timers.c b/core/net/rpl-lite/rpl-timers.c index 5bd335cc5..0cfda4abe 100644 --- a/core/net/rpl-lite/rpl-timers.c +++ b/core/net/rpl-lite/rpl-timers.c @@ -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 */ } /*---------------------------------------------------------------------------*/ diff --git a/core/net/rpl-lite/rpl.c b/core/net/rpl-lite/rpl.c index bf59fc47b..77a8e3941 100644 --- a/core/net/rpl-lite/rpl.c +++ b/core/net/rpl-lite/rpl.c @@ -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(); } } diff --git a/core/sys/log-conf.h b/core/sys/log-conf.h index 35ae27f7b..c2c917564 100644 --- a/core/sys/log-conf.h +++ b/core/sys/log-conf.h @@ -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 diff --git a/core/sys/log.h b/core/sys/log.h index 312993cef..fc4522fe7 100644 --- a/core/sys/log.h +++ b/core/sys/log.h @@ -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__) diff --git a/examples/ipv6/rpl-simple/node.c b/examples/ipv6/rpl-simple/node.c index aaca07eaa..35ed922c8 100644 --- a/examples/ipv6/rpl-simple/node.c +++ b/examples/ipv6/rpl-simple/node.c @@ -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"); } } /*---------------------------------------------------------------------------*/