NTP examples only works for first response

srolf commented 7 years ago

I'm pretty happy to see this project and really like the idea (an ESP-01 with WifiESP creates a lot of trouble because of the serial communication).

For the WifiSpiESP lib I changed a little bit the setup and made some test runs with by using an Arduino M0 combined with a NodeMCU and D1 mini. For both, the ConnectWithWPA example works nicely, beside sporadic freezes after ~5-10 minutes.

But if I adapt the Wiifi NTP examples, always only once a repsonse with packet size 48 is received and properly converted into UTC time. All following responses report a size of 0.

I another test, I created a small MQTT client with the PubSub lib. The connection to the broker is established, a subscribe for 3 messages is confirmed, but never an update is received. After a while, the M0 frezzes completely.

JiriBilek commented 7 years ago

Hi, I am glad you like the library. Regarding the issues, have you tried looking at serial output of the ESP device? At least you can find out if the problem is on Arduino side or ESP side. I will test NTP and MQTT as soon as possible but I don't have Arduino M0, I can perform testing on Atmel processors only.

srolf commented 7 years ago

Thank you for the response.

I'm going to have a look at the debug output, somewhere a FTDI adapter should be lying around. Or would the output become available as Serial.print()? In addition, I will try to extend the setup by a Leonardo. In case of interrest, I can also include a Due.

srolf commented 7 years ago

The serial output of the D1 mini can be directly captured by its USB port, so here is the log =)

Arduino NTP client output:

Attempting to connect to WPA SSID: <SSID>
You're connected to the network
0
48
packet received
Seconds since Jan 1 1900 = 3705196911
Unix time = 1496208111
The UTC time is 5:21:51
0
0
0
0

D1 mini WiFiSPIESP log:

WiFiSPIESP_UseCase_NTP.txt

At the end of the log where a block of LmacRxBlk:1 started, it seems like the connected to the Arduino stopped completely. Just a reset of the Arduino was not sufficient to get it working. Only after removing power from D1 mini, it was detected again.

srolf commented 7 years ago

Is it intendet what the ESP is activated with sta and softAP?

srolf commented 7 years ago

On the Leonardo the situation looks pretty the same, only once the response is properly evaluated:

Attempting to connect to WPA SSID: <SSID>
You're connected to the network
48
packet received
Seconds since Jan 1 1900 = 3705200569
Unix time = 1496211769
The UTC time is 6:22:49
0
0
0
0
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
0
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 0
Returning: 0
Returning: 0
0
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 0
Returning: 0
Returning: 0
0
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
0
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
Returning: 2
Status: Preparing data
0

There is a small difference, after LmacRxBlk:1 it does not stop and you can see continous blocks of Avail[0] = 0 and LmacRxBlk:1.

JiriBilek commented 7 years ago

@srolf , thanks for testing. I will test it on my Uno tomorrow.

srolf commented 7 years ago

@JiriBilek , you are welcome.

If some more tests would be helpful, feel free to let me know about your needs.

There are some more Arduino variants available for me: Uno, Leonardo, Mega, Due, M0, M0 Pro and 101. Also a Micro and Mini would be available, but I'm not sure if the current output would be high enough to empower a D1 mini. Addtionally a NodeMCU is lying around, so also this is something I can check. My prefered setup is a M0 and Due because there is no need to include a level shifter.

leonardo_d1mini_levelshifter

Adaptingn the ESP to any of the Arduinos is not a huge problem for me, because I'm using a proto shield. In the picture a Leonardo, level shifter and a D1 mini is used.

srolf commented 6 years ago

Is here an update available?

It would be just so great to get also MQTT working. Even I would like to give it a try on Arduino Due and M0.

JiriBilek commented 6 years ago

Hi, it seems to me that the library needs calling Udp.begin before sending of each packet and Udp.stop afterwards. I will further explore the problem, take this as a quick&dirty fix. Sorry that I'm responding after a long time.

My code for Arduino (tested on Pro Mini 5V)

/*
 WiFiSPI example: UdpNTPClient

 Get the time from a Network Time Protocol (NTP) time server.
 Demonstrates use of UDP to send and receive data packets
 For more on NTP time servers and the messages needed to communicate with them,
 see http://en.wikipedia.org/wiki/Network_Time_Protocol

*/

#include "WiFiSpi.h"
#include "WiFiSpiUdp.h"

char ssid[] = "***";          // your network SSID (name)
char pass[] = "***";      // your network password
int status = WL_IDLE_STATUS;     // the Wifi radio's status

char timeServer[] = "time.nist.gov";  // NTP server
unsigned int localPort = 2390;        // local port to listen for UDP packets

const int NTP_PACKET_SIZE = 48;  // NTP timestamp is in the first 48 bytes of the message
const int UDP_TIMEOUT = 2000;    // timeout in miliseconds to wait for an UDP packet to arrive

byte packetBuffer[NTP_PACKET_SIZE]; // buffer to hold incoming and outgoing packets

// A UDP instance to let us send and receive packets over UDP
WiFiSpiUdp Udp;

void setup()
{
  // initialize serial for debugging
  Serial.begin(115200);
  // initialize ESP module
  WiFiSpi.init();

  // check for the presence of the shield
  if (WiFiSpi.status() == WL_NO_SHIELD) {
    Serial.println("WiFi shield not present");
    // don't continue
    while (true);
  }

  // attempt to connect to WiFi network
  while (status != WL_CONNECTED) {
    Serial.print("Attempting to connect to WPA SSID: ");
    Serial.println(ssid);
    // Connect to WPA/WPA2 network
    status = WiFiSpi.begin(ssid, pass);
  }

  // you're connected now, so print out the data
  Serial.println("You're connected to the network");

//  Udp.begin(localPort);
}

void loop()
{
  Udp.begin(localPort);

  sendNTPpacket(timeServer); // send an NTP packet to a time server

  // wait for a reply for UDP_TIMEOUT miliseconds
  unsigned long startMs = millis();
  while (!Udp.available() && (millis() - startMs) < UDP_TIMEOUT) {}

  Serial.println(Udp.parsePacket());
  if (Udp.parsePacket()) {
    Serial.println("packet received");
    // We've received a packet, read the data from it into the buffer
    Udp.read(packetBuffer, NTP_PACKET_SIZE);

    // the timestamp starts at byte 40 of the received packet and is four bytes,
    // or two words, long. First, esxtract the two words:

    unsigned long highWord = word(packetBuffer[40], packetBuffer[41]);
    unsigned long lowWord = word(packetBuffer[42], packetBuffer[43]);
    // combine the four bytes (two words) into a long integer
    // this is NTP time (seconds since Jan 1 1900):
    unsigned long secsSince1900 = highWord << 16 | lowWord;
    Serial.print("Seconds since Jan 1 1900 = ");
    Serial.println(secsSince1900);

    // now convert NTP time into everyday time:
    Serial.print("Unix time = ");
    // Unix time starts on Jan 1 1970. In seconds, that's 2208988800:
    const unsigned long seventyYears = 2208988800UL;
    // subtract seventy years:
    unsigned long epoch = secsSince1900 - seventyYears;
    // print Unix time:
    Serial.println(epoch);

    // print the hour, minute and second:
    Serial.print("The UTC time is ");       // UTC is the time at Greenwich Meridian (GMT)
    Serial.print((epoch  % 86400L) / 3600); // print the hour (86400 equals secs per day)
    Serial.print(':');
    if (((epoch % 3600) / 60) < 10) {
      // In the first 10 minutes of each hour, we'll want a leading '0'
      Serial.print('0');
    }
    Serial.print((epoch  % 3600) / 60); // print the minute (3600 equals secs per minute)
    Serial.print(':');
    if ((epoch % 60) < 10) {
      // In the first 10 seconds of each minute, we'll want a leading '0'
      Serial.print('0');
    }
    Serial.println(epoch % 60); // print the second
  }

  Udp.stop();

  // wait ten seconds before asking for the time again
  delay(10000);
}

// send an NTP request to the time server at the given address
void sendNTPpacket(char *ntpSrv)
{
  // set all bytes in the buffer to 0
  memset(packetBuffer, 0, NTP_PACKET_SIZE);
  // Initialize values needed to form NTP request
  // (see URL above for details on the packets)

  packetBuffer[0] = 0b11100011;   // LI, Version, Mode
  packetBuffer[1] = 0;     // Stratum, or type of clock
  packetBuffer[2] = 6;     // Polling Interval
  packetBuffer[3] = 0xEC;  // Peer Clock Precision
  // 8 bytes of zero for Root Delay & Root Dispersion
  packetBuffer[12]  = 49;
  packetBuffer[13]  = 0x4E;
  packetBuffer[14]  = 49;
  packetBuffer[15]  = 52;

  // all NTP fields have been given values, now
  // you can send a packet requesting a timestamp:
  Udp.beginPacket(ntpSrv, 123); //NTP requests are to port 123

  Udp.write(packetBuffer, NTP_PACKET_SIZE);

  Udp.endPacket();
}

JiriBilek commented 6 years ago

I found the bug. Please wait until I fix it.

JiriBilek commented 6 years ago

Fixed in version 0.1.1 of the protocol. Please recompile and reload also the ESP part.

srolf commented 6 years ago

Hi @JiriBilek , I have missed your update, sorry for the pretty late repsonse.

The good news is that I got NTP working with 0.1.1 on the Leonardo! Thank you very much :-)

But there are some observations/findings.

There seems to be something special about Udp.parsePacket():

If I use it in my example 1st by Serial.println(Udp.parsePacket()), packet size is correcly shown
But on 2nd use in if (Udp.parsePacket()), the code doesn't pass and skips the evaluation
In the ESP log, I can see that for the 1st call ParsePacket[0] = 48 is evaluated, but the 2nd ends up with ParsePacket[0] = 0. Does this happen maybe because of the 1st call the packet buffer/length deleted/set to 0? Shouldn't this only happen in case of Udp.read()?
If I disable Serial.println(Udp.parsePacket()), the time evalutation is continously updating in the expected manner.

Why in your Arduino NTP example in loop() a call of Udp.begin() ... Udp.stop() is used, and not once Udp.begin() only in setup()? In my code I'm suing only Udp.begin() in setup() and it's working fine.

Maybe I should cross check the behaviour also on the M0, please let me know.

JiriBilek commented 6 years ago

@srolf, every single call to Udp.parsePacket() clears the buffer. I copied the behaviour from the 8266 libraries. The Udp.stop(), I think, is unnecessary now. I used it as a temporary (and bad) fix. I'll check it.

srolf commented 6 years ago

You are correct about the behaviour of Udp.parsePacket(): Even the Ethernet nor the ESP8266 example is doing it twice. This was a missunderstanding of the API on my side. Thank you so much for the clarification.

I will try to move on with a MQTT example and check also the M0. I'm already anxious to the result :-)

srolf commented 6 years ago

NTP on M0 works.

With the MQTT part I've got some bigger problems.

If I re-use an example which only publish a message each second, everything works fine.

But with an other one which is using 3 subscribes, I'm struggeling heavily. To reduce the complexity for testing, all subs were disabled and just the plain mqtt.loop() remained in order to keep the connection to the broker.

setup() {
  ...
  reconnectBroker();
}

void loop() {
  if (millis() - previousMillis > 100) {
    if (!mqtt.connected()) {
      reconnectBroker();
    }
    else {
      mqtt.loop();
      Serial.println("mqtt.loop()");
    }
  }
  previousMillis = millis();
}

Now the code seems to hang completely after the first call ofmqtt.loop().

The Arduino output looks just like this:

Attempting MQTT connection...
MQTT broker connected.
mqtt.loop()

The same mechanism on a native ESP8266 works without trouble, even if the frequency of the connection check is increased from 1/100ms to 1/10ms by millis() - previousMillis > 10,

if I change the content of loop() to your variant and activate the 3 subs, everythings starts working. But after receiving ~10-40 messages, the Arduino hangs again. Inbetween sporadically also a message seems not to have been received.

void loop() {
  mqtt.loop();
}

But isn't this causing an unexpected higher amount of traffic? And should a reconnect to the broker looks like? Strange... any ideas?

The log of the ESP looks like this:

 Fatal exception 3(LoadStoreErrorCause):
                                                                      epc1=0x40205956, epc2=0x00000000, epc3=0x00000000, excvaddr=0x40231e64, depc=0x00000000

Exception (3):
epc1=0x40205956 epc2=0x00000000 epc3=0x00000000 excvaddr=0x40231e64 depc=0x00000000

ctx: cont
sp: 3ffef700 end: 3ffef950 offset: 01a0

>>>stack>>>
3ffef8a0:  00000000 00000000 00000000 3ffee924
3ffef8b0:  3ffe8584 00000000 3ffef890 3ffee924
3ffef8c0:  3fffdad0 00000000 3ffee8f8 40204ff5
3ffef8d0:  40231e64 0000002b 00000000 40202612
3ffef8e0:  69020000 6902a8c0 3ffee8f8 40205125
3ffef8f0:  3fffdad0 00000000 3ffee6fc 40202361
3ffef900:  402010f8 feefeffe 3ffef8e0 40202141
3ffef910:  00000000 00000000 00000000 00000000
3ffef920:  00000000 00000000 00000000 00000000
3ffef930:  3fffdad0 00000000 3ffee91c 402054fc
3ffef940:  feefeffe feefeffe 3ffee930 40100718
<<<stack<<<

 ets Jan  8 2013,rst cause:2, boot mode:(3,6)

load 0x4010f000, len 1384, room 16
tail 8
chksum 0x2d
csum 0x2d
v60000130
~ld
   ▒

    SPI SLAVE ver. 0.1.1

JiriBilek commented 6 years ago

Hi @srolf If you are still interested in the library, please load new ESP library and test it. There was a serious bug there that crashed the ESP everytime the corrupted message came. J.

srolf commented 6 years ago

Hi @JiriBilek yes, I'm still interested. Frankly spoken: heavily! Test will start on Leonardo and then I'll go ahead with M0 and Due. Thank you very much.

srolf commented 6 years ago

I started with the M0 (because the shield was just configured to it):

sketch with MQTT subribe works
sketch with MQTT publish works

From time to time the connecting to the broker gets lost and is estabilshed afain (so not really a problem).

I will apply more tests with little advanced messages for pub/sub.

Sporadically the following output is seen on ESP8266: Invalid message header - message rejected. I guess that this is exactly in line with your fix.

JiriBilek commented 6 years ago

The rejected messages are priority issue for me now. I still don't know why they are appearing :( . Are you still testing on Leonardo?

srolf commented 6 years ago

I just changed over to the Leonardo. MQTT publish works but let me monitor for a while the ESP8266 output.

srolf commented 6 years ago

The same report Invalid message header - message rejected. can be observed also on the Leonardo. Additonally it seems like that a sub client stops after ~100 received messages. I will check this once more.

JiriBilek commented 6 years ago

We are observing the same problem in #5

srolf commented 6 years ago

I will follow it up there.

JiriBilek commented 5 years ago

Refer to https://github.com/JiriBilek/WiFiSpi/issues/9#issuecomment-434794476

JiriBilek commented 5 years ago

I believe it is fixed.

JiriBilek / WiFiSpi

NTP examples only works for first response #1