enhance logging, correct loop logic

mini-beieli-node.ino

@@ -134,8 +134,8 @@ bool fUsbPower;
 bool g_fPrintedSleeping = false;
 
 //  the job that's used to synchronize us with the LMIC code
-static osjob_t sensorJob;
 static osjob_t iterationJob;
+static osjob_t sendJob;
 
 void setup(void)
 {
@@ -155,6 +155,9 @@ void setup(void)
 
 void setup_platform(void)
 {
+  if (config_data.debug_level > 0) {
+    gCatena.SafePrintf("%010d - setup_platform\n", millis());
+  }
 
   /* add our application-specific commands */
   gCatena.addCommands(
@@ -164,11 +167,12 @@ void setup_platform(void)
 
   // read config_data from fram...
   if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("Reading Calibration Config from FRAM...\n");
+    gCatena.SafePrintf("%010d - Reading Calibration Config from FRAM...\n", millis());
   }
   gCatena.getFram()->getField(cFramStorage::kBme680Cal, (uint8_t *)&config_data, sizeof(config_data));
 
   if (config_data.debug_level > 0) {
+    gCatena.SafePrintf("%010d - setup_platform, this is the configuration\n", millis());
     gCatena.SafePrintf("cal_w1_0: %d\n", config_data.cal_w1_0);
     gCatena.SafePrintf("cal_w2_0: %d\n", config_data.cal_w2_0);
     gCatena.SafePrintf("cal_w1_factor: %d.%03d\n", (int)config_data.cal_w1_factor, (int)(config_data.cal_w1_factor * 1000) % 1000);
@@ -265,6 +269,10 @@ void setup_platform(void)
 
 void setup_bme280(void)
 {
+  if (config_data.debug_level > 0) {
+    gCatena.SafePrintf("%010d - setup_bme280\n", millis());
+  }
+
   if (gBME280.begin(BME280_ADDRESS, Adafruit_BME280::OPERATING_MODE::Sleep)) {
     fBme = true;
   }
@@ -276,13 +284,13 @@ void setup_bme280(void)
 
 bool setup_scales(void)
 {
+  if (config_data.debug_level > 0) {
+    gCatena.SafePrintf("%010d - setup_scales\n", millis());
+  }
+
   bool res;
   res = true;
 
-  if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("Setup Scales...\n");
-  }
-
   // Enable Power
   digitalWrite(D10, HIGH);
 
@@ -295,12 +303,12 @@ bool setup_scales(void)
   LoadCell.begin(A1, A0);
 
   if (!(LoadCell.wait_ready_timeout(2000))) {
-    gCatena.SafePrintf("Scale not ready after Init.\n");
+    gCatena.SafePrintf("%010d - Scale not ready after Init.\n");
     res = false;
   }
 
   if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("Setup Scale is complete\n");
+    gCatena.SafePrintf("%010d - setup_scale done\n", millis());
   }
 
   return res;
@@ -308,11 +316,15 @@ bool setup_scales(void)
 
 void setup_flash(void)
 {
+  if (config_data.debug_level > 0) {
+    gCatena.SafePrintf("%010d - setup_flash\n", millis());
+  }
+
   if (gFlash.begin(&gSPI2, Catena::PIN_SPI2_FLASH_SS)) {
     fFlash = true;
     gFlash.powerDown();
     if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("FLASH found, but power down\n");
+      gCatena.SafePrintf("%010d - FLASH found, but power down\n", millis());
     }
   }
   else {
@@ -320,24 +332,27 @@ void setup_flash(void)
     gFlash.end();
     gSPI2.end();
     if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("No FLASH found: check hardware\n");
+      gCatena.SafePrintf("%010d - No FLASH found: check hardware\n", millis());
     }
   }
 }
 
 void setup_uplink(void)
 {
+  if (config_data.debug_level > 0) {
+    gCatena.SafePrintf("%010d - setup_uplink\n", millis());
+  }
 
   // Do an unjoin, so every reboot will trigger a join
   if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("Do an unjoin...\n");
+    gCatena.SafePrintf("%010d - do an unjoin...\n", millis());
   }
   LMIC_unjoin();
 
   /* trigger a join by sending the first packet */
   if (!(gCatena.GetOperatingFlags() & static_cast<uint32_t>(gCatena.OPERATING_FLAGS::fManufacturingTest))) {
     if (!gLoRaWAN.IsProvisioned())
-      gCatena.SafePrintf("LoRaWAN not provisioned yet. Use the commands to set it up.\n");
+      gCatena.SafePrintf("%010d - LoRaWAN not provisioned yet. Use the commands to set it up.\n");
     else {
       gLed.Set(LedPattern::Joining);
 
@@ -469,7 +484,7 @@ uint8_t GetVBatValue(int millivolts)
 void DoDeepSleep()
 {
   if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("Now going to deep sleep: %d\n", millis());
+    gCatena.SafePrintf("%010d - now going to deep sleep\n", millis());
   }
 
   // Prepare Deep Sleep
@@ -491,7 +506,7 @@ void DoDeepSleep()
   if (fFlash)
     gSPI2.begin();
   if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("Done with deep sleep: %d\n", millis());
+    gCatena.SafePrintf("%010d - done with deep sleep\n", millis());
   }
 }
 
@@ -500,34 +515,39 @@ void ReadSensors(SENSOR_data &sensor_data) {
   int32_t weight_current32;
 
   // vBat
-  res.vbat = (uint8_t)(gCatena.ReadVbat() * 1000.0f);
+  gCatena.poll();
+  int vbat_mv = (int)(gCatena.ReadVbat() * 1000.0f);
+  res.vbat = GetVBatValue(vbat_mv);
   if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("vBat:    %d mV\n", res.vbat);
+    gCatena.SafePrintf("vBat:    %d mV\n", vbat_mv);
   }
 
   // Read Scales
   if (setup_scales()) {
     if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("HX711 LoadCell is ready.\n");
+      gCatena.SafePrintf("%010d - HX711 LoadCell is ready.\n", millis());
     }
     LoadCell.set_gain(128);
+    gCatena.poll();
     res.weight1 = (int32_t)LoadCell.read_average(5);
     if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("Load_cell 1 weight1_current: %ld\n", res.weight1);
+      gCatena.SafePrintf("%010d - Load_cell 1 weight1_current: %ld\n", millis(), res.weight1);
     }
+    gCatena.poll();
     LoadCell.set_gain(32);
     res.weight2 = (int32_t)LoadCell.read_average(5);
     if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("Load_cell 2 weight2_current: %ld\n", res.weight2);
+      gCatena.SafePrintf("%010d - Load_cell 2 weight2_current: %ld\n", millis(), res.weight2);
     }
   }
   else {
     if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("HX711 LoadCell not ready.\n");
+      gCatena.SafePrintf("%010d - HX711 LoadCell not ready.\n", millis());
     }
   }
 
   // Disable Power
+  gCatena.poll();
   digitalWrite(D10, LOW);
 
   // Gewicht berechnen
@@ -540,16 +560,19 @@ void ReadSensors(SENSOR_data &sensor_data) {
   res.weight = (uint16_t)weight_current32;
 
   if (fBme) {
+    gCatena.poll();
     /* warm up the BME280 by discarding a measurement */
     (void)gBME280.readTemperature();
 
+    gCatena.poll();
     Adafruit_BME280::Measurements m = gBME280.readTemperaturePressureHumidity();
     // temperature is 2 bytes from -0x80.00 to +0x7F.FF degrees C
     // pressure is 2 bytes, hPa * 10.
     // humidity is one byte, where 0 == 0/256 and 0xFF == 255/256.
     if (config_data.debug_level > 0) {
       gCatena.SafePrintf(
-        "BME280:  T: %d P: %d RH: %d\n",
+        "%010d - BME280:  T: %d P: %d RH: %d\n",
+        millis(),
         (int)m.Temperature,
         (int)m.Pressure,
         (int)m.Humidity);
@@ -558,7 +581,7 @@ void ReadSensors(SENSOR_data &sensor_data) {
     res.humidity = (uint8_t)m.Humidity;
     res.pressure = (uint8_t)((m.Pressure / 100) - PRESSURE_OFFSET);
     if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("pressure_current: %d\n", res.pressure);
+      gCatena.SafePrintf("%010d - pressure_current: %d\n", millis(), res.pressure);
     }
   }
 
@@ -576,7 +599,7 @@ void StartNewIteration() {
   // vBus
   float vBus = gCatena.ReadVbus();
   if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("vBus:    %d mV\n", (int)(vBus * 1000.0f));
+    gCatena.SafePrintf("%010d - vBus:    %d mV\n", millis(), (int)(vBus * 1000.0f));
   }
   fUsbPower = (vBus > 4.3) ? true : false;
 
@@ -623,22 +646,18 @@ void StartNewIteration() {
   if ( (iteration == 1) || (my_position >= MAX_VALUES_TO_SEND) || ((last_sensor_reading.weight - current_sensor_reading.weight) > SEND_DIFF_THRESHOLD_5GRAMS) || ((millis() - timer_pos0) > 3600000)) {
     lora_data.offset_last_reading = (uint8_t)((millis() - timer_pos0) / 1000 / 60);
     if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("startSendingUplink(), my_position: %d\n",my_position);
+      gCatena.SafePrintf("%010d - startSendingUplink(), my_position: %d, iteration: %d\n", millis(), my_position, iteration);
     }
     startSendingUplink(iteration == 1);
     gLed.Set(LedPattern::TwoShort);
 
-    // we allow 10 seconds for RX1 and RX2 to complete...
+    // If we have any critical jobs to complete in the next 8 seconds, do not sleep but process them
-    uint32_t deepSleepDelay = 10;
+    long loopCount = 0;
-    for (auto n = deepSleepDelay; n > 0; --n)
+    while (os_queryTimeCriticalJobs(ms2osticks(8000)) != 0)
     {
-      uint32_t tNow = millis();
+      loopCount++;
-
+      gCatena.poll();
-      while (uint32_t(millis() - tNow) < 1000)
+      yield();
-      {
-        gCatena.poll();
-        yield();
-      }
     }
   }
 
@@ -648,7 +667,7 @@ void StartNewIteration() {
   }
 
   if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("now going to sleep for %d seconds...\n",CATCFG_T_INTERVAL);
+    gCatena.SafePrintf("%010d - now going to sleep for %d seconds...\n", millis(), CATCFG_T_INTERVAL);
     if (fUsbPower) {
       gCatena.SafePrintf("USB Power is on\n");
     } else {
@@ -659,9 +678,13 @@ void StartNewIteration() {
   gLed.Set(LedPattern::Sleeping);
   if (!fUsbPower) {
     DoDeepSleep();
-    startNewIterationCb(&iterationJob);
+    os_setTimedCallback(
-  } else {
+      &iterationJob,
-    gCatena.SafePrintf("os_setTimedCallback for startNewIterationCb in %d...\n",CATCFG_T_INTERVAL);
+      os_getTime() + sec2osticks(2),
+      startNewIterationCb);
+  }
+  else {
+    gCatena.SafePrintf("%010d - light sleep; os_setTimedCallback for startNewIterationCb in %d...\n", millis(), CATCFG_T_INTERVAL);
     os_setTimedCallback(
       &iterationJob,
       os_getTime() + sec2osticks(CATCFG_T_INTERVAL),
@@ -688,12 +711,12 @@ void startSendingUplink(bool firstTime)
 
   if (firstTime) {
     if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("SendBuffer firstTime\n");
+      gCatena.SafePrintf("%010d - SendBuffer firstTime\n", millis());
     }
     gLoRaWAN.SendBuffer((uint8_t*)&lora_data_first, sizeof(LORA_data_first), sendBufferDoneCb, NULL, fConfirmed, kUplinkPort);
   } else {
     if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("SendBuffer not firstTime\n");
+      gCatena.SafePrintf("%010d - SendBuffer not firstTime\n", millis());
     }
     gLoRaWAN.SendBuffer((uint8_t*)&lora_data, sizeof(LORA_data), sendBufferDoneCb, NULL, fConfirmed, kUplinkPort);
   }
@@ -720,12 +743,12 @@ static void sendBufferDoneCb(
       gLoRaWAN.Shutdown();
     }
     else if (config_data.debug_level > 0) {
-      gCatena.SafePrintf("send buffer failed\n");
+      gCatena.SafePrintf("%010d - send buffer failed\n", millis());
     }
   }
 
   os_setTimedCallback(
-    &sensorJob,
+    &sendJob,
     os_getTime() + sec2osticks(CATCFG_T_SETTLE),
     pFn
   );
@@ -747,7 +770,7 @@ static void settleDoneCb(
   osjob_t* pSendJob)
 {
   if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("settleDoneCb\n");
+    gCatena.SafePrintf("%010d - settleDoneCb\n", millis());
   }
 
   if (config_data.debug_level > 2) {
@@ -766,20 +789,26 @@ static void sleepDoneCb(osjob_t* pJob)
 {
   gLed.Set(LedPattern::WarmingUp);
 
+  if (config_data.debug_level > 0) {
+    gCatena.SafePrintf("%010d - sleepDoneCb\n", millis());
+  }
+
   os_setTimedCallback(
-    &sensorJob,
+    pJob,
     os_getTime() + sec2osticks(CATCFG_T_WARMUP),
     warmupDoneCb);
 }
 
 static void warmupDoneCb(osjob_t* pJob)
 {
-  gCatena.SafePrintf("warmupDoneCb\n");
+  if (config_data.debug_level > 0) {
+    gCatena.SafePrintf("%010d - warmupDoneCb\n", millis());
+  }
 }
 
 static void startNewIterationCb(osjob_t* pJob)
 {
-  gCatena.SafePrintf("startNewIterationCb\n");
+  gCatena.SafePrintf("%010d - startNewIterationCb\n", millis());
   StartNewIteration();
 }
 
@@ -790,7 +819,7 @@ static void receiveMessage(void *pContext, uint8_t port, const uint8_t *pMessage
   SENSOR_data temp_sensor_data;
 
   if (config_data.debug_level > 0) {
-    gCatena.SafePrintf("receiveMessage was called!!!\n");
+    gCatena.SafePrintf("%010d - receiveMessage was called!!!\n", millis());
   }
 
   if (config_data.debug_level > 2) {

mini_beieli_node.h

@@ -15,7 +15,7 @@ enum {
   // add measurement and broadcast time, but we attempt
   // to compensate for the gross effects below.
   CATCFG_T_CYCLE = 6 * 60, // every 6 minutes
-  //CATCFG_T_CYCLE = 60, // for Testing
+  //CATCFG_T_CYCLE = 30, // for Testing
   CATCFG_T_CYCLE_TEST = 30, // every 10 seconds
   CATCFG_T_CYCLE_INITIAL = 30,    // every 30 seconds initially
   CATCFG_INTERVAL_COUNT_INITIAL = 30,     // repeat for 15 minutes
@@ -55,7 +55,7 @@ enum {
   |
   \****************************************************************************/
 
-static const int32_t fwVersion = 20191115;
+static const int32_t fwVersion = 20191120;
 static const byte MAX_VALUES_TO_SEND = 8;
 //static const byte MAX_VALUES_TO_SEND = 1;  // Testing
 static const uint8_t LORA_DATA_VERSION = 1;