search

jeelabs / esp-link

esp8266 wifi-serial bridge, outbound TCP, and arduino/AVR/LPC/NXP programmer
Other
2.82k stars 720 forks source link

Console output mixed with SLIP packet when UART Debug Log is enabled #424

Open damiano94 opened 5 years ago

damiano94 commented 5 years ago

Like title says, most of Serial.print content is not received by esp-link and also most of mqtt publish calls are ignored. In Debug log I only get one slip crc error but in my arduino code there are more mqtt publish statements that are not seen by esp link. I have ESP-12E board and Arduino Pro Mini. Arduino is supplied from SMPS and ESP too but from LDO. There is also Logic level shifter board.

Snippet of Debug Log:

Click to expand

en=3, qos=0, retain=0
137589> MQTT: Publish, topic: "sensors/kociolco/cwutemp", length: 31
137595> SLIP: start or end len=15 inpkt=0
137602> MQTT: Send type=PUBLISH id=0000 len=31
142559> SLIP: start or end len=71 inpkt=1
142560> SLIP: bad CRC, crc=0240 rcv=0a0d len=71
142560> \0B\00\05\00\00\00\00\00\1C\00sensors/kociolco/outdoortemp\03\00-29\00\02\00\03\00\00\00\01\00\00\00Millis: 4441457\0D\0A
142570> SLIP: start or end len=10 inpkt=1
142574> cmdParsePacket: cmd=7 argc=0 value=0
142578> cmdExec: Dispatching cmd=GET_TIME
142581> cmdResponse: cmd=2 val=1544908168 argc=0
142631> SLIP: start or end len=0 inpkt=1
142631> SLIP: start or end len=60 inpkt=1
142631> cmdParsePacket: cmd=11 argc=5 value=0
142633> cmdExec: Dispatching cmd=MQTT_PUB
142637> MQTT: MQTTCMD_Publish topic=sensors/kociolco/cotemp, data_len=3, qos=0, retain=0
142645> MQTT: Publish, topic: "sensors/kociolco/cotemp", length: 30
142651> MQTT: Send type=PUBLISH id=0000 len=30
142655> SLIP: start or end len=14 inpkt=0
142659> SLIP: start or end len=60 inpkt=1
142663> cmdParsePacket: cmd=11 argc=5 value=0
142667> cmdExec: Dispatching cmd=MQTT_PUB
142670> MQTT: MQTTCMD_Publish topic=sensors/kociolco/cwutemp, data_len=3, qos=0, retain=0
142678> MQTT: Publish, topic: "sensors/kociolco/cwutemp", length: 31
142684> SLIP: start or end len=15 inpkt=0
142691> MQTT: Send type=PUBLISH id=0000 len=31

en=3, qos=0, retain=0
152855> MQTT: Publish, topic: "sensors/kociolco/cwutemp", length: 31
152862> SLIP: start or end len=15 inpkt=0
152869> MQTT: Send type=PUBLISH id=0000 len=31
157825> SLIP: start or end len=71 inpkt=1
157825> SLIP: bad CRC, crc=83da rcv=0a0d len=71
157825> \0B\00\05\00\00\00\00\00\1C\00sensors/kociolco/outdoortemp\03\00-29\00\02\00\03\00\00\00\01\00\00\00Millis: 4456754\0D\0A
157835> SLIP: start or end len=10 inpkt=1
157839> cmdParsePacket: cmd=7 argc=0 value=0
157843> cmdExec: Dispatching cmd=GET_TIME
157847> cmdResponse: cmd=2 val=1544908184 argc=0
157896> SLIP: start or end len=0 inpkt=1
157896> SLIP: start or end len=60 inpkt=1
157896> cmdParsePacket: cmd=11 argc=5 value=0
157899> cmdExec: Dispatching cmd=MQTT_PUB
157902> MQTT: MQTTCMD_Publish topic=sensors/kociolco/cotemp, data_len=3, qos=0, retain=0
157910> MQTT: Publish, topic: "sensors/kociolco/cotemp", length: 30
157916> MQTT: Send type=PUBLISH id=0000 len=30
157921> SLIP: start or end len=14 inpkt=0
157924> SLIP: start or end len=60 inpkt=1
157928> cmdParsePacket: cmd=11 argc=5 value=0
157932> cmdExec: Dispatching cmd=MQTT_PUB
157936> MQTT: MQTTCMD_Publish topic=sensors/kociolco/cwutemp, data_len=3, qos=0, retain=0
157944> MQTT: Publish, topic: "sensors/kociolco/cwutemp", length: 31
157950> SLIP: start or end len=15 inpkt=0
157956> MQTT: Send type=PUBLISH id=0000 len=31

After bad CRC line you can see mqtt topic and payload and after that "Millis: 4456754\0D\0A" <- That should go to µC Console page.

µC Console:
Click to expand

CO Temp: 430
CWU Temp: 337
CO Temp: 430
CWU Temp: 337
CO Temp: 430
CWU Temp: 337
CO Temp: 430
CWU Temp: 337
CO Temp: 430
CWU Temp: 337
CO Temp: 430
CWU Temp: 337
CO Temp: 430
CWU Temp: 337
CO Temp: 430
CWU Temp: 337
CO Temp: 427
CWU Temp: 337
CO Temp: 430
CWU Temp: 337


Arduino sketch:
Click to expand

#include <OneWire.h> 
#include <DallasTemperature.h>
#include <ELClient.h>
#include <ELClientMqtt.h>
#include <ELClientCmd.h>
#include <ApplicationMonitor.h>
#include <avr/eeprom.h>
#include <xitoa.h>

//#include <avr/eeprom.h>

#define PUMP_PIN 3
#define PUMP_PIN2 4
#define PUMP_PIN3 5
#define AIRDOOR_PIN 6
#define TEMP_PIN A1
#define POT_PIN A0

Watchdog::CApplicationMonitor ApplicationMonitor;

uint8_t EEMEM airDoorTempEE = 50;

bool espOk = false;
int setTemp = 410;
int hist = 20;
volatile uint8_t airDoorTemp = 50;
uint8_t airDoorTempHist = 1;
unsigned long timeReqTemp;
int pump2Delay = 0, floorPumpDelay = 0;
int pumpOn = 0;
//int lastTemp, lastCwuTemp, lastBadCount = 0;
int lastBadCount = 0;

OneWire oneWire(TEMP_PIN);
DallasTemperature sensors(&oneWire);

DeviceAddress piec = { 0x28, 0xFF, 0x13, 0x0E, 0xA3, 0x16, 0x03, 0xD9 }; 
DeviceAddress cwu = { 0x28, 0xFF, 0x2A, 0x26, 0xA3, 0x16, 0x03, 0xC2 };
DeviceAddress outdoor = { 0x28, 0xFF, 0xF6, 0x27, 0xA3, 0x16, 0x03, 0x32 };

//ELClient esp(&Serial, &Serial);
ELClient esp(&Serial);
ELClientCmd cmd(&esp);
ELClientMqtt mqtt(&esp);

// Callback when MQTT is connected
void mqttConnected(void* response) {
  Serial.println("MQTT connected!");
  mqtt.subscribe("devices/kociolco/airdoortempset");
}

// Callback when an MQTT message arrives for one of our subscriptions
void mqttData(void* response) {
  ELClientResponse *res = (ELClientResponse *)response;

  Serial.print("Received: topic=");
  String topic = res->popString();
  Serial.println(topic);

  Serial.print("data=");
  String data = res->popString();
  Serial.println(data);
  if(topic.equals("devices/kociolco/airdoortempset"))
  {
    char buf[5];
    uint8_t old = airDoorTemp;
    airDoorTemp = data.toInt();
    if(airDoorTemp < 20 || airDoorTemp > 70) airDoorTemp = 50;
    Serial.println("Setting new Air Door Temp");
    if(airDoorTemp != old) eeprom_write_byte(&airDoorTempEE, airDoorTemp);
  }
}

// Callback made form esp-link to notify that it has just come out of a reset. This means we
// need to initialize it!
void resetCb(void) {
  Serial.println("EL-Client (re-)starting!");
  ApplicationMonitor.IAmAlive();
  espOk = esp.Sync();      // sync up with esp-link, blocks for up to 2 seconds
  if(espOk) {
    Serial.println("EL-Client synced!");
    mqtt.setup();
    Serial.println("EL-MQTT ready!!!");
  }
  else {
    Serial.println("EL-Client sync failed!");
  }
}

// the setup function runs once when you press reset or power the board
void setup() {
  //eeprom_write_byte((uint8_t *)500, 0xff);
  //eeprom_write_byte(&airDoorTempEE, 50);
  //while(true);
  Serial.begin(115200);
  Serial.println("Arduino starting...");
  pinMode(LED_BUILTIN, OUTPUT);
  digitalWrite(LED_BUILTIN, LOW);
  pinMode(PUMP_PIN, OUTPUT);
  digitalWrite(PUMP_PIN, LOW);
  pinMode(PUMP_PIN2, OUTPUT);
  digitalWrite(PUMP_PIN2, LOW);
  pinMode(PUMP_PIN3, OUTPUT);
  digitalWrite(PUMP_PIN3, LOW);
  pinMode(AIRDOOR_PIN, OUTPUT);
  digitalWrite(AIRDOOR_PIN, LOW);
  analogReference(EXTERNAL);
  pinMode(POT_PIN, INPUT);

  airDoorTemp = eeprom_read_byte(&airDoorTempEE);
  if(airDoorTemp < 20 || airDoorTemp > 70) airDoorTemp = 50;

  ApplicationMonitor.Dump(Serial);
  ApplicationMonitor.EnableWatchdog(Watchdog::CApplicationMonitor::Timeout_4s);
  sensors.begin();
  sensors.setResolution(piec, 10);
  sensors.setResolution(cwu, 10);
  sensors.setWaitForConversion(false);
  sensors.requestTemperatures();
  timeReqTemp = millis();
  //delay(900);
  //lastTemp = (int)(sensors.getTempC(piec)*10);
  //lastCwuTemp = (int)(sensors.getTempC(cwu)*10);
  mqtt.connectedCb.attach(mqttConnected);
  mqtt.dataCb.attach(mqttData);
  esp.resetCb = resetCb;
  resetCb();
}

// the loop function runs over and over again forever
void loop() {
  ApplicationMonitor.IAmAlive();
  //ApplicationMonitor.SetData();  
  if(espOk) esp.Process();
  if(((millis() - timeReqTemp) > 5000) /*&& sensors.isConversionComplete()*/)
  {
    Serial.print("Millis: "); Serial.println(millis());
    uint32_t t = cmd.GetTime();
    //Serial.print("Time: "); Serial.println(t);
    ApplicationMonitor.SetData(t);
    int currentTemp = (int)(sensors.getTempC(piec)*10);
    //bool lastConvBad = (abs(lastTemp - currentTemp) > 10) && (lastBadCount < 3);
    if(/*!lastConvBad && */(currentTemp > (DEVICE_DISCONNECTED_C * 10)))
    {
      lastBadCount = 0;
      int cwuTemp = (int)(sensors.getTempC(cwu)*10);
      //if(abs(lastCwuTemp - cwuTemp) > 10)
        //cwuTemp = lastCwuTemp;
      //int setTemp = (analogRead(POT_PIN) + analogRead(POT_PIN)) / 2;
      int outdoorTemp = (int)(sensors.getTempC(outdoor)*10);
      /*Serial.print("CO Temp: ");
      Serial.println(currentTemp);
      Serial.print("CWU Temp: ");
      Serial.println(cwuTemp);
      Serial.print("Outdoor Temp: ");
      Serial.println(outdoorTemp);*/
      char buf[12];
      itoa(currentTemp/* / 10*/, buf, 10);
      if(espOk) mqtt.publish("sensors/kociolco/cotemp", buf);
      Serial.print("CO Temp: ");
      Serial.println(buf);
      itoa(cwuTemp/* / 10*/, buf, 10);
      if(espOk) mqtt.publish("sensors/kociolco/cwutemp", buf);
      Serial.print("CWU Temp: ");
      Serial.println(buf);
      itoa(outdoorTemp/* / 10*/, buf, 10);
      if(espOk) mqtt.publish("sensors/kociolco/outdoortemp", buf);
      Serial.print("Outdoor Temp: ");
      Serial.println(buf);
      itoa(airDoorTemp/* / 10*/, buf, 10);
      if(espOk) mqtt.publish("devices/kociolco/airdoortemp", buf);
      Serial.print("Air Door Temp: ");
      Serial.println(buf);
      Serial.print("devices/kociolco/copump ");
      Serial.println(pumpOn);
      if(pumpOn == 0) {
        if(espOk) mqtt.publish("devices/kociolco/copump", "0");        
        if(pump2Delay <= 0)
          digitalWrite(PUMP_PIN2, LOW);
        else
          pump2Delay -= 5;
        if(floorPumpDelay <= 0)
          digitalWrite(PUMP_PIN3, LOW);
        else
          floorPumpDelay -= 5;       
      }        
      else {
        if(espOk) mqtt.publish("devices/kociolco/copump", "1");
      }        
      /*Serial.print("Time: ");
      Serial.println(millis());
      Serial.print("Set Temp: ");
      Serial.println(setTemp);
      Serial.print("CO Temp: ");
      Serial.println(currentTemp);
      Serial.print("CWU Temp: ");
      Serial.println(cwuTemp);
      Serial.print("Pump status: ");
      Serial.println(pumpOn);*/
      if((currentTemp > setTemp /*&& currentTemp >= cwuTemp*/) || currentTemp > 850)
      {
        digitalWrite(PUMP_PIN, HIGH);
        digitalWrite(PUMP_PIN2, HIGH);
        digitalWrite(PUMP_PIN3, HIGH);
        digitalWrite(LED_BUILTIN, HIGH);
        pump2Delay = 120;
        floorPumpDelay = 300;
        pumpOn = 1;
      }
      else if(currentTemp < 850 && ((currentTemp + hist) < setTemp/* || (currentTemp + hist) < cwuTemp*/))
      {
        digitalWrite(PUMP_PIN, LOW);
        //digitalWrite(PUMP_PIN2, LOW);
        //digitalWrite(PUMP_PIN3, LOW);
        digitalWrite(LED_BUILTIN, LOW);
        pumpOn = 0;
      }
      //lastTemp = currentTemp;
      //lastCwuTemp = cwuTemp;
      if(currentTemp <= ((airDoorTemp - airDoorTempHist) * 10))
      {
        digitalWrite(AIRDOOR_PIN, HIGH);
      }
      else if(currentTemp > (airDoorTemp * 10))
      {
        digitalWrite(AIRDOOR_PIN, LOW);
      }
    }
    else //nie znamy temperatury więc trzeba wyłączyć pompy, tutaj po 60 iteracjach pętli czyli po ok 5 min
    {
      digitalWrite(AIRDOOR_PIN, LOW);
      if(lastBadCount >= 60)
      {
        digitalWrite(PUMP_PIN, LOW);
        digitalWrite(PUMP_PIN2, LOW);
        digitalWrite(PUMP_PIN3, LOW);
        pumpOn = 0;
      }
      else
        lastBadCount++;
    }
    /*if(lastConvBad)
    {
      lastBadCount++;
      Serial.println("LastConvBad");
    }
    if(lastBadCount > 1)
    {
      lastBadCount = 0;
      //lastTemp = currentTemp;
      //lastCwuTemp = cwuTemp;
      Serial.println("LastBadCount Reset!");
    }*/
    //Serial.print("Time: ");
    //Serial.println(millis());
    sensors.requestTemperatures();
    timeReqTemp = millis();
    if(!espOk) resetCb();
  }  
}

You see more Serial.print and mqtt.publish calls but most of them are missed by esp-link.

This only happens when uart0 or uart1 option on esp link's debug page is enabled. When I switch to auto or off everything works as it should. I need debug output because sometimes esplink is stopping working and it just blinks randomly LED and resets attached arduino over and over again. On my access point's (router with OpenWRT) log I see that esp tries to connect and it succeds but I cannot access web page.

tve commented 5 years ago

I'm sorry to say that this is somewhat expected. The uart output only has the 128-byte hardware buffer and then blocks the caller. You can try to change the baud rate to the max (921k baud?) and/or comment-out some of the more verbose messages. WRT resets, does it do that when you turn off the debug log also?

damiano94 commented 5 years ago

Ok, I'll try to increase baud. It's on µC Console page?

WRT resets, does it do that when you turn off the debug log also?

So when WRT resets esp-link it also resets attached mcu? Normally I have debug log turned off. It started happening week ago, it works 1-3 days and then it stops working. I can't really say for sure if its esp-link fault or OpenWRT but i didn't see anything suspicious in router's log. By the way, how to detect that esp-link is not responding (disconnected or not working) ? Maybe I put additional wire to reset esp-link from arduino.

Edit

I increased baud to max which is 460800 but I get framing error. I tried 250000, it works but same things are happening. I commented all Serial.print calls and esp link only sees one more mqtt publish. Debug Log:

Click to expand

106714> SLIP: start or end len=0 inpkt=1
106717> SLIP: start or end len=64 inpkt=1
106721> cmdParsePacket: cmd=11 argc=5 value=0
106725> cmdExec: Dispatching cmd=MQTT_PUB
106729> MQTT: MQTTCMD_Publish topic=sensors/kociolco/outdoortemp, data_len=3, qos=0, retain=0
106737> MQTT: Publish, topic: "sensors/kociolco/outdoortemp", length: 35
106744> SLIP: start or end len=0 inpkt=1
106780> MQTT: Send type=PUBLISH id=0000 len=31
106782> MQTT: Send type=PUBLISH id=0000 len=35
108439> HTTP GET /menu: 200, 10ms, h=13640
108441> HTTP GET /log/dbg: 200, 5ms, h=14400

0\1C\00devices/
111664> SLIP: start or end len=10 inpkt=1
111668> cmdParsePacket: cmd=7 argc=0 value=0
111672> cmdExec: Dispatching cmd=GET_TIME
111676> cmdResponse: cmd=2 val=1544913292 argc=0
111721> SLIP: start or end len=0 inpkt=1
111721> SLIP: start or end len=60 inpkt=1
111721> cmdParsePacket: cmd=11 argc=5 value=0
111724> cmdExec: Dispatching cmd=MQTT_PUB

But why there is empty line and number with > is missing at the beginning? And why outputing debug log on uart1 is affecting uart0? They have shared buffer? I changed baud back to 115200 and with no Serial.print calls same happens as on 250000 baud. On 250000 it doesn't matter if debug log is enabled or not. I tried 57600 and I got crc error, so 115200 is the best choice. With disabled debug log it is not continuous Debug Log:

Click to expand

tching cmd=MQTT_PUB
691918> MQTT: MQTTCMD_Publish topic=sensors/kociolco/cwutemp, data_len=3, qos=0, retain=0
691919> MQTT: Publish, topic: "sensors/kociolco/cwutemp", length: 31
691919> MQTT: Send type=PUBLISH id=0000 len=31
691919> SLIP: start or end len=15 inpkt=0
691926> SLIP: start or end len=64 inpkt=1
691927> cmdParsePacket: cmd=11 argc=5 value=0
691927> cmdExec: Dispatching cmd=MQTT_PUB
691927> MQTT: MQTTCMD_Publish topic=sensors/kociolco/outdoortemp, data_len=3, qos=0, retain=0
691927> MQTT: Publish, topic: "sensors/kociolco/outdoortemp", length: 35
691927> MQTT: Send type=PUBLISH id=0000 len=35
691928> SLIP: start or end len=19 inpkt=0
691928> SLIP: start or end len=64 inpkt=1
691928> cmdParsePacket: cmd=11 argc=5 value=0
691928> cmdExec: Dispatching cmd=MQTT_PUB
691929> MQTT: MQTTCMD_Publish topic=devices/kociolco/airdoortemp, data_len=2, qos=0, retain=0
691929> MQTT: Publish, topic: "devices/kociolco/airdoortemp", length: 34
691930> MQTT: Send type=PUBLISH id=0000 len=34
691936> SLIP: start or end len=30 inpkt=0
691937> SLIP: start or end len=60 inpkt=1
691937> cmdParsePacket: cmd=11 argc=5 value=0
691938> cmdExec: Dispatching cmd=MQTT_PUB
691938> MQTT: MQTTCMD_Publish topic=devices/kociolco/copump, data_len=1, qos=0, retain=0
691938> MQTT: Publish, topic: "devices/kociolco/copump", length: 28
691938> MQTT: Send type=PUBLISH id=0000 len=28
692301> HTTP GET /log/text: 200, 10ms, h=15248
692720> HTTP GET /log/text: 200, 4ms, h=15240
693241> HTTP GET /log/text: 200, 4ms, h=15240
693862> HTTP GET /log/text: 200, 5ms, h=15240
694263> HTTP GET /log/text: 200, 5ms, h=15240
694550> HTTP GET /log/text: 200, 4ms, h=15240
694833> HTTP GET /log/text: 200, 5ms, h=15240
694942> HTTP GET /log/text: 200, 5ms, h=15240
695322> HTTP GET /log/text: 200, 6ms, h=15240
695635> HTTP GET /log/text: 200, 6ms, h=15240
695974> HTTP GET /log/text: 200, 9ms, h=15240
696277> HTTP GET /log/text: 200, 5ms, h=15240
696469> HTTP GET /log/text: 200, 4ms, h=15240

tching cmd=MQTT_PUB
696982> MQTT: MQTTCMD_Publish topic=sensors/kociolco/cwutemp, data_len=3, qos=0, retain=0
696982> MQTT: Publish, topic: "sensors/kociolco/cwutemp", length: 31
696982> MQTT: Send type=PUBLISH id=0000 len=31
696982> SLIP: start or end len=15 inpkt=0
696990> SLIP: start or end len=64 inpkt=1
696990> cmdParsePacket: cmd=11 argc=5 value=0
696990> cmdExec: Dispatching cmd=MQTT_PUB
696990> MQTT: MQTTCMD_Publish topic=sensors/kociolco/outdoortemp, data_len=3, qos=0, retain=0
696990> MQTT: Publish, topic: "sensors/kociolco/outdoortemp", length: 35
696991> MQTT: Send type=PUBLISH id=0000 len=35
696991> SLIP: start or end len=19 inpkt=0
696991> SLIP: start or end len=64 inpkt=1
696991> cmdParsePacket: cmd=11 argc=5 value=0
696992> cmdExec: Dispatching cmd=MQTT_PUB
696992> MQTT: MQTTCMD_Publish topic=devices/kociolco/airdoortemp, data_len=2, qos=0, retain=0
696992> MQTT: Publish, topic: "devices/kociolco/airdoortemp", length: 34
696993> MQTT: Send type=PUBLISH id=0000 len=34
696999> SLIP: start or end len=33 inpkt=0
697001> SLIP: start or end len=60 inpkt=1
697001> cmdParsePacket: cmd=11 argc=5 value=0
697001> cmdExec: Dispatching cmd=MQTT_PUB
697001> MQTT: MQTTCMD_Publish topic=devices/kociolco/copump, data_len=1, qos=0, retain=0
697001> MQTT: Publish, topic: "devices/kociolco/copump", length: 28
697002> MQTT: Send type=PUBLISH id=0000 len=28
697135> HTTP GET /log/text: 200, 10ms, h=15248
697489> HTTP GET /log/text: 200, 4ms, h=15240
697743> HTTP GET /log/text: 200, 4ms, h=15240
697921> HTTP GET /log/text: 200, 7ms, h=15240
698202> HTTP GET /log/text: 200, 5ms, h=15240
698483> HTTP GET /log/text: 200, 4ms, h=15240
698764> HTTP GET /log/text: 200, 4ms, h=15240
699064> HTTP GET /log/text: 200, 7ms, h=15240
699269> HTTP GET /log/text: 200, 5ms, h=15240
699447> HTTP GET /log/text: 200, 5ms, h=15240
699720> HTTP GET /log/text: 200, 5ms, h=15240
700013> HTTP GET /log/text: 200, 6ms, h=15240
700322> HTTP GET /log/text: 200, 7ms, h=15240
700560> HTTP GET /log/text: 200, 4ms, h=15240
700769> HTTP GET /log/text: 200, 4ms, h=15240