Multiple Start entries in log when "virtual" node updated

[loseymark]

Using radio.setAddress() with one Moteino USB to manage several "virtual" nodes, I get a Start entry in the log for each individual node that this Moteino manages. The sketch only contacts the gateway for the virtual node experiencing an event. Is this someting I am doing wrong or just expected behavior?

Code Select Expand

[08-22-16_13:25:40.147] [LOG]      [12] DB-Updates:1
[08-22-16_13:25:41.164] [LOG]   >: [30] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:41.174] [LOG]      [30] DB-Updates:1
[08-22-16_13:25:41.249] [LOG]   >: [30] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:41.252] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:41.333] [LOG]   >: [31] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:41.343] [LOG]      [31] DB-Updates:1
[08-22-16_13:25:41.418] [LOG]   >: [32] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:41.428] [LOG]      [32] DB-Updates:1
[08-22-16_13:25:41.503] [LOG]   >: [32] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:41.506] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:41.598] [LOG]   >: [101] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:41.607] [LOG]      [101] DB-Updates:1
[08-22-16_13:25:41.676] [LOG]   >: [102] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:41.687] [LOG]      [102] DB-Updates:1
[08-22-16_13:25:41.766] [LOG]   >: [102] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:41.768] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:41.854] [LOG]   >: [103] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:41.863] [LOG]      [103] DB-Updates:1
[08-22-16_13:25:41.942] [LOG]   >: [104] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:41.951] [LOG]      [104] DB-Updates:1
[08-22-16_13:25:42.019] [LOG]   >: [104] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.022] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:42.108] [LOG]   >: [105] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.115] [LOG]      [105] DB-Updates:1
[08-22-16_13:25:42.197] [LOG]   >: [106] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.205] [LOG]      [106] DB-Updates:1
[08-22-16_13:25:42.286] [LOG]   >: [106] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.288] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:42.364] [LOG]   >: [107] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.371] [LOG]      [107] DB-Updates:1
[08-22-16_13:25:42.452] [LOG]   >: [108] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.460] [LOG]      [108] DB-Updates:1
[08-22-16_13:25:42.540] [LOG]   >: [108] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.543] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:42.628] [LOG]   >: [109] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.637] [LOG]      [109] DB-Updates:1
[08-22-16_13:25:42.708] [LOG]   >: [110] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.716] [LOG]      [110] DB-Updates:1
[08-22-16_13:25:42.796] [LOG]   >: [110] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.799] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:42.884] [LOG]   >: [111] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.892] [LOG]      [111] DB-Updates:1
[08-22-16_13:25:42.972] [LOG]   >: [112] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:42.980] [LOG]      [112] DB-Updates:1
[08-22-16_13:25:43.051] [LOG]   >: [112] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.054] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:43.140] [LOG]   >: [113] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.148] [LOG]      [113] DB-Updates:1
[08-22-16_13:25:43.228] [LOG]   >: [114] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.236] [LOG]      [114] DB-Updates:1
[08-22-16_13:25:43.316] [LOG]   >: [114] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.319] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:43.394] [LOG]   >: [115] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.402] [LOG]      [115] DB-Updates:1
[08-22-16_13:25:43.482] [LOG]   >: [116] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.490] [LOG]      [116] DB-Updates:1
[08-22-16_13:25:43.580] [LOG]   >: [116] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.583] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:43.668] [LOG]   >: [117] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.679] [LOG]      [117] DB-Updates:1
[08-22-16_13:25:43.757] [LOG]   >: [118] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.769] [LOG]      [118] DB-Updates:1
[08-22-16_13:25:43.836] [LOG]   >: [118] START   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.841] [LOG]      DUPLICATE, skipping...
[08-22-16_13:25:43.917] [LOG]   DEVICECOMMAND outlet16 on 192.168.1.1
[08-22-16_13:25:43.935] [LOG]   >: [118] BAT:4.86v RFO:1   [RSSI:-32][ACK-sent]
[08-22-16_13:25:43.948] [LOG]      [118] DB-Updates:1
[08-22-16_13:26:20.490] [LOG]   >: [11] BAT:4.32v F:7827 H:57 P:0.00   [RSSI:-74][ACK-sent]
[08-22-16_13:26:20.496] [LOG]   post: /home/pi/gateway/data/db/0011_F.bin[1471890380,78.27]
[08-22-16_13:26:20.499] [LOG]   post: /home/pi/gateway/data/db/0011_H.bin[1471890380,57]
[08-22-16_13:26:20.510] [LOG]      [11] DB-Updates:1

sketch is attached

[Felix]

Well this certainly explains it:

Code Select Expand

  radio.setAddress(30);                    // Left Door
  radio.sendWithRetry(GATEWAYID, "START", 6);   
  radio.setAddress(31);                         // Right Door
  radio.sendWithRetry(GATEWAYID, "START", 6);
  radio.setAddress(32);                         // SimpliSafe
  radio.sendWithRetry(GATEWAYID, "START", 6);

  // RF Outlets (18 of them)
  for (int i = 101; i<119; i++) {
    radio.setAddress(i);
    radio.sendWithRetry(GATEWAYID, "START", 6);       <------ 18 START messages just here + 3 more above
  }

[loseymark]

OK. I thought I needed to do a start for each, but that that setup would only run once and not in a loop. I see the Start message for each every time any address is used. When does setup get invoked.

My Arduino ignorance is showing.

[Felix]

What that code did was send a succession of START messages from the same node which changed its address between the calls. So the log reflects exactly this effect.

[loseymark]

Ah, then what I need to do is save a current node variable and in setup only do start on that one.

I thought setup was only initiated once on Moteino startup.

[Felix]

I thought setup was only initiated once on Moteino startup.

It is.

[loseymark]

Why then would I get all the start messages every time a serial command is sent to the Moteino from the RPI?

[Felix]

If it's the same code above, is it possible the board is restarted somehow? Maybe an insufficient power supply causes reception to reset the board or something like that?

[loseymark]

Along those lines, I use Pyro for remote procedure calls between the gateway RPI and the RPI with the RFOutlet transmitter and email parser running on it. Pyro is threaded so I have to open and release the serial communications with each event. I'll bet the serial request is what is triggering the start event.

To be sure it isn't power, I'll try putting the MoteinoUSB on a powered USB hub.

[loseymark]

I found out this is because the Raspberry PI sends a reset to the moteino when serial is started on the PI.

When I commented out the radio send of START in Setup though, I could not get serial communication to work.

[Felix]

I found out this is because the Raspberry PI sends a reset to the moteino when serial is started on the PI.

That should only happen once though right? So should not be a problem.

When I commented out the radio send of START in Setup though, I could not get serial communication to work.

Strange, that should have no side effects. It just wont send a START message that's it. Even so the START should end up in the unmatched message db.