[net2-wg] mirage progress

Fri Jun 16 06:27:00 PDT 2006

Hi,

I just added a tag, net2-beta2-test7, with changes to the UARTLogger
and additional debug statements, as well as the addition of a sequence
number to the application messages.

>From tests I've been running in mirage, I see the following.

I see no loops forming, I printed the trees and they look fine. I have
a topology with 6~7 levels (depth). See the tree below.

The added log messages allow us to see the progress of a routing
message, as I log the forwarding, receiving, sending, and send done
errors.

This is a successful message from node 142 to 0.
(look at field 9: 20 is sent, 21 is receive, 22 is forward. AM (field
8) EE is app data msg)
142 34723 00 FF FF 09 22 16 20 00 00 8E 00 95 00 00 0C
149 34732 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 07
149 34733 00 FF FF 09 22 16 22 00 00 95 00 74 00 00 09
130 34742 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 07
116 34743 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 08
116 34744 00 FF FF 09 22 16 22 00 00 74 00 82 00 00 0A
130 34754 00 FF FF 09 22 16 22 00 00 82 00 67 00 00 09
103 34762 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 06
103 34763 00 FF FF 09 22 16 22 00 00 67 00 44 00 00 08
68 34774 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 08
68 34775 00 FF FF 09 22 16 22 00 00 44 00 25 00 00 0A
37 34785 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 07
37 34786 00 FF FF 09 22 16 22 00 00 25 00 00 00 00 09
0 34794 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 07
0 34795 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 01 00 00 00 05 00 00 0C

Great! All this in 62ms.
The second one is also ok.

Then the third one fails, and it never works again.
The culprit is node 116, and a closer look reveals the following:

Notice 21 22 (good), 21 22, 21 25.
25 is SENDDONE_WAITACK, signaled in sendDone(),
  else if (ackPending && !call PacketAcknowledgements.wasAcked(msg)) {

After this, this packet is never again acked, and the queue fills up.
Any ideas?

116 34743 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 08
116 34744 00 FF FF 09 22 16 22 00 00 74 00 82 00 00 0A
116 44324 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 0B
116 44336 00 FF FF 09 22 16 22 00 00 74 00 82 00 00 0D
116 44743 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 0E
116 44745 00 FF FF 09 22 16 25 00 00 74 00 82 00 00 10
116 44990 00 FF FF 09 22 16 25 00 00 74 00 82 00 00 13
116 45213 00 FF FF 09 22 16 25 00 00 74 00 82 00 00 15
116 45387 00 FF FF 09 22 16 25 00 00 74 00 82 00 00 17
116 45585 00 FF FF 09 22 16 25 00 00 74 00 82 00 00 19
116 45732 00 FF FF 09 22 16 25 00 00 74 00 82 00 00 1B
116 45744 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 1C
116 45920 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 1D
116 45968 00 FF FF 09 22 16 25 00 00 74 00 82 00 00 1F
116 46131 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 20
116 46227 00 FF FF 09 22 16 25 00 00 74 00 82 00 00 22
116 46402 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 23
116 46448 00 FF FF 09 22 16 25 00 00 74 00 82 00 00 25
116 46573 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 26
116 46573 00 FF FF 09 22 16 10 00 00 00 00 00 00 00 27
116 46574 00 FF FF 09 22 16 11 00 00 00 00 00 00 00 28
116 46588 00 FF FF 09 22 16 25 00 00 74 00 82 00 00 2A
116 46746 00 FF FF 09 22 16 21 00 00 00 00 00 00 00 2C
116 46746 00 FF FF 09 22 16 10 00 00 00 00 00 00 00 2D
116 46758 00 FF FF 09 22 16 11 00 00 00 00 00 00 00 2E

Just for illustration, here's the tree. Notice the path
142-149-116-130-106-68-37-0:

   +--0
      +--6
         +--13
      +--10
      +--20
      +--37
         +--36
         +--68
            +--62
            +--70
               +--74
            +--78
               +--71
            +--103
               +--95
               +--96
               +--100
                  +--124
               +--102
               +--104
               +--120
               +--123
                  +--111
                     +--143
                     +--146
                  +--115
                     +--141
               +--130
                  +--116
                     +--119
                     +--145
                        +--148
                     +--149
                        +--132
                        +--142
            +--107
               +--105
               +--125
                  +--112
                     +--117
      +--40
         +--61

Rodrigo

On 6/15/06, Philip Levis <pal at cs.stanford.edu> wrote:
> On Jun 15, 2006, at 6:18 PM, Rodrigo Fonseca wrote:
>
> > Hi,
> >
> > the title should not mean progress is a mirage...
> > Anyway, I ran a test on mirage on a 47 node topology. The tree forms
> > great, is similar to what is formed by mint, and keeps being correctly
> > updated. It seems to be fairly stable as well.
> >
> > There is some problem with forwarding, though.
> > So far I can only describe the symptoms.
> >
> > Setup: 47 node micaz testbed, CC2420 power setting to 5.
> > Tree is formed with depth of 7, I verified the tree and it makes
> > sense.
> >
> > Transmission: node at hop 6 transmits a packet every 1024ms. Only 1
> > node is transmitting.
> >
> > Result:
> > 0 61184 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 01 00 00 00 05 00 00 0C
> > 0 68440 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 02 00 73 00 62 00 00 07
> > 0 68764 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 02 00 73 00 62 BE EF 07
> > 0 68919 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 02 00 73 00 62 BE EF 07
> > 0 69614 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 03 00 74 00 48 BE EF 06
> > 0 70609 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 04 00 74 00 48 BE EF 06
> > 0 71599 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 05 00 74 00 48 BE EF 06
> > 0 72873 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 06 00 74 00 48 BE EF 06
> > 0 73249 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 06 00 74 00 48 BE EF 06
> > 0 73249 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 06 00 74 00 48 BE EF 06
> > 0 73517 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 06 00 74 00 48 BE EF 06
> > 0 155984 00 FF FF 0F 22 EE 00 00 8E EE 00 8E 00 59 00 73 00 38 BE
> > EF 06
> >
> > This is what 0 gets. Nothing after that.
> > format: <node> <t (ms)> <hex dump of packet>
> > These packets are from node 142 (8E), collection id EE. Field 16 is
> > the node sequence number, incremented every time a send is successful
> > to the CollectionTree at the origin.
> >
> > Observations:
> > 1. The first packet is crazy: there is nothing right, except the
> > sequence number.
> > 2. The second packet has no sensor value, the tree metrics are right.
> > 3. The strange thing is that the third packet has the same sequence
> > number (02), but the BEEF value is different!
> > 4. We get 3 copies of packet 2, 4 copies of packet 6, and then skip to
> > packet 59!
> >
> > Due to lack of instrumentation, the only problem reported by a node
> > directly on the path was by node 124, NET_C_FE_MSG_POOL_EMPTY.
>
> There is currently no duplicate suppression; false negatives on ACKs
> could very much cause multiple copies of a packet to appear in the
> network.
>
> Phil
>
>