Testing with NTP UDP code, fails #80

trlafleur · 2016-07-19T17:30:59Z

In testing with the UdpNTPClient, I have noticed that after some time (often less that 5 to 10min)
The WiFi101 stack stops sending the NTP request packets, but return no error to the program. This has been verified using Wireshark and the test program below.

Using IDE 1.6.9, SAMD 1.6.6, on a Adafruit feather M0 WINC1500

My modified test program and output.

Sending an NTP request
packet received
Seconds since Jan 1 1900 = 3677937580
Unix time = 1468948780
The UTC time is 17:19:40

Sending an NTP request
packet received
Seconds since Jan 1 1900 = 3677937591
Unix time = 1468948791
The UTC time is 17:19:51

Sending an NTP request

Sending an NTP request
packet received
Seconds since Jan 1 1900 = 3677937613
Unix time = 1468948813
The UTC time is 17:20:13

Sending an NTP request

Sending an NTP request

Sending an NTP request

Sending an NTP request

Sending an NTP request

Sending an NTP request

Sending an NTP request

Sending an NTP request


/*

 Udp NTP Client

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

 created 4 Sep 2010
 by Michael Margolis
 modified 9 Apr 2012
 by Tom Igoe

 This code is in the public domain.

 */

#include <SPI.h>
#include <WiFi101.h>
#include <WiFiUdp.h>

int status = WL_IDLE_STATUS;

char ssid[] = "xxxxx";              //  your network SSID (name)
char pass[] = "xxxxx";        // your network password
int keyIndex = 0;                     // your network key Index number (needed only for WEP)

unsigned long t1 = millis();

// My IP address for the WINC1500:
  IPAddress MYip(192, 94, 167, 14);   
// the DNS server address for the WINC1500:
  IPAddress MYdns1(4,2,2,2);  
// the GateWay address for the WINC1500:
  IPAddress MYgw(192, 94, 167, 4);   
// the Sub Net Mask for the Winc1500:
  IPAddress MYsnm(255,255,255,0); 
// DNS name of NTP server to use  
const char NTPserver [] = "1.north-america.pool.ntp.org";        //"1.north-america.pool.ntp.org"  us.pool.ntp.org


unsigned int localPort = 2390;        // local port to listen for UDP packets

IPAddress timeServer(129, 6, 15, 28); // time.nist.gov NTP server

const int NTP_PACKET_SIZE = 48; // NTP time stamp is in the first 48 bytes of the message

byte packetBuffer[ NTP_PACKET_SIZE] = {0}; //buffer to hold incoming and outgoing packets

//WiFiClass::setPins(int8_t cs, int8_t irq, int8_t rst, int8_t en)

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

void setup()
{
  // Open serial communications and wait for port to open:
  Serial.begin(115200);
  while (!Serial) {
    ; // wait for serial port to connect. Needed for native USB port only
  }

WiFi.setPins (8,7,4,2);   // using a Feather with a WINC1500

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


// set manual IP address, comment this out for DHCP
  WiFi.config(MYip, MYdns1, MYgw, MYsnm); 


  // attempt to connect to Wifi network:
  while ( status != WL_CONNECTED) {
    Serial.print("Attempting to connect to SSID: ");
    Serial.println(ssid);
    // Connect to WPA/WPA2 network. Change this line if using open or WEP network:
    status = WiFi.begin(ssid, pass);

    // wait 10 seconds for connection:
    //delay(10000);
  }

  Serial.println("Connected to wifi");
  printWifiStatus();

  Serial.println("\nStarting connection to server...");
  Udp.begin(localPort);
}

void loop()
{

  // check if its time to make an NTP request
  if ( (millis() - t1) > 10000)
  {

    t1 = millis();
    // see if we are still connected
    if ( (WiFi.status() ==  WL_CONNECTED) )
      sendNTPpacket(timeServer);              // send an NTP packet to a time server
      else Serial.println("Not Connected");
  }  

  // wait to see if a reply is available
  //delay(1000);
  if ( Udp.parsePacket() ) 
  {
      RXpacket();
  }

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

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

    //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
}

// send an NTP request to the time server at the given address
unsigned long sendNTPpacket(IPAddress& address)
{
  Serial.println("\nSending an NTP request");
  // 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)
  //Serial.println("2");
  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;

  //Serial.println("3");

  // all NTP fields have been given values, now
  // you can send a packet requesting a timestamp:
  if (!Udp.beginPacket(address, 123)) //; //NTP requests are to port 123)
      Serial.println("beginPacket error");

      //delay (1000);
  if (!Udp.write(packetBuffer, NTP_PACKET_SIZE) ) //;
    Serial.println("write error");
    //delay (1000);
  if (!Udp.endPacket()) //;
    Serial.println("endPacket error");
    //delay (1000);
}


void printWifiStatus() {
  // print the SSID of the network you're attached to:
  Serial.print("SSID: ");
  Serial.println(WiFi.SSID());

  // print your WiFi shield's IP address:
  IPAddress ip = WiFi.localIP();
  Serial.print("IP Address: ");
  Serial.println(ip);

  // print the received signal strength:
  long rssi = WiFi.RSSI();
  Serial.print("signal strength (RSSI):");
  Serial.print(rssi);
  Serial.println(" dBm");
}

The text was updated successfully, but these errors were encountered:

driverblock · 2016-08-12T15:46:44Z

Seeing the same issue on a Arduino WIFI101 and Arduino Zero. Slightly different sketch. Sketch assumes an Adafruit 4-digit 7-segment I2C display, but it's not necessary if you comment the serial output back in (different issue: serial writes block the sketch when my MBP goes to sleep).
If you connect the display, you'll see the blinking colon stop for 15 seconds every 15 seconds when the problem occurs.

It may take 90 minutes or so for the problem to occur. I have also observed one instance in which it spontaneously recovered overnight. That is, failing for maybe 12 hours, then mysteriously recovering.

The sketch uses us.pool.ntp.org, but I have also used it with my own local NTP server, and the problem still occurs. Can't think of anything to try to narrow it down. Seems like a firmware issue.

// Clock example using a seven segment display & NTP clock synchronization
//
// Designed specifically to work with the Adafruit LED 7-Segment backpacks
// and the Feather M0 WIFI and Arduino Zero with WIFI1500 shield.
//
// Adafruit invests time and resources providing this open source code,
// please support Adafruit and open-source hardware by purchasing
// products from Adafruit!
//
// Based on clock_sevenseg_DS1307 written by Tony DiCola for Adafruit Industries.
//
// Modified for NTP and WINC1500 by Rick Lesniak for Adafruit Industries
//
// Released under a MIT license: https://opensource.org/licenses/MIT

#include <Wire.h>
#include "Adafruit_LEDBackpack.h"
#include "Adafruit_GFX.h"

#include "TimeLib.h"

#include <SPI.h>
#include <Adafruit_WINC1500.h>
#include <Adafruit_WINC1500Udp.h>

// Set to false to display time in 12 hour format, or true to use 24 hour:
#define TIME_24_HOUR      true
#define NTP_SYNC_INTERVAL 900  /*M0 clock apparently drifts a bit.  re-sync every day */

// I2C address of the display.  Stick with the default address of 0x70
// unless you've changed the address jumpers on the back of the display.
#define DISPLAY_ADDRESS   0x72


// Create display object.  This is a global variable that
// can be accessed from both the setup and loop function below.
Adafruit_7segment clockDisplay = Adafruit_7segment();

int hours = 0;
int minutes = 0;
int seconds = 0;
int tzOffset = -4;     // Time zone offset: -4 is Eastern Daylight Time.  change to -5 for Eastern Standard Time

// Remember if the colon was drawn on the display so it can be blinked
// on and off every second.
bool blinkColon = false;

// Define the WINC1500 board connections below.
// If you're following the Adafruit WINC1500 board
// guide you don't need to modify these:
#define WINC_CS   8
#define WINC_IRQ  7
#define WINC_RST  4
#define WINC_EN   2     // or, tie EN to VCC and comment this out

// The SPI pins of the WINC1500 (SCK, MOSI, MISO) should be
// connected to the hardware SPI port of the Arduino.
// On an Uno or compatible these are SCK = #13, MISO = #12, MOSI = #11.
// On an Arduino Zero use the 6-pin ICSP header, see:
//   https://www.arduino.cc/en/Reference/SPI

// For WiFI Feather, setup the WINC1500 connection with the pins above 
//  and the default hardware SPI.
//Adafruit_WINC1500 WiFi(WINC_CS, WINC_IRQ, WINC_RST);

// For WiFi1500 shield, use hardware SPI (SCK/MOSI/MISO) and defaults, 
//    SS -> #10, INT -> #7, RST -> #5, EN -> 3-5V
Adafruit_WINC1500 WiFi;

int status = WL_IDLE_STATUS;
char ssid[] = "xxxx";  //  your network SSID (name)
char pass[] = "xxxx";       // your network password
int keyIndex = 0;            // your network key Index number (needed only for WEP)

unsigned int localPort = 2390;      // local port to listen for UDP packets

/* Don't hardwire the IP address or we won't get the benefits of the pool.
    Lookup the IP address for the host name instead */
IPAddress timeServerIP; // NTP server IP address

const char* ntpServerName = "us.pool.ntp.org";  //change to match your own regional pool

const int NTP_PACKET_SIZE = 48; // NTP time stamp is in the first 48 bytes of the message

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

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

//Forward declarations
time_t getNTPTime();
unsigned long sendNTPpacket(IPAddress& address);
void printWifiStatus();

void setup() {
#ifdef WINC_EN
  pinMode(WINC_EN, OUTPUT);
  digitalWrite(WINC_EN, HIGH);
#endif

//  while (!Serial);
  // Setup Serial port to print debug output.
  //Serial.begin(9600);
  //Serial.println("Clock starting!");

  // check for the presence of the shield:
  if (WiFi.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 SSID: ");
    //Serial.println(ssid);
    // Connect to WPA/WPA2 network. Change this line if using open or WEP network:
    status = WiFi.begin(ssid, pass);

    // wait 10 seconds for connection:
    delay(10000);
  }

  //Serial.println("Connected to wifi");
  printWifiStatus();

  //Serial.println("\nStarting connection to server...");
  Udp.begin(localPort);

  // Setup the LED display.
  clockDisplay.begin(DISPLAY_ADDRESS);

  //Set up NTP Time callback
  setSyncInterval(NTP_SYNC_INTERVAL);   //sync to NTP this often
  setSyncProvider(getNTPTime);

  //Serial.println("Waiting for NTP sync");
  //wait for initial time sync to succeed.  getNTPTime will reset the sync interval to 15 seconds if NTP fails
  while (timeSet != timeStatus())
  {
    //Serial.println("Waiting for NTP sync");
    time_t timenow = now();
    delay(1000);
  }
  //Serial.println("NTP time is set");    //sync interval automatically reset to 1 day

//setTime(1468987185);  //set clock to 15 seconds before midnight for debugging purposes.

  //Serial.println("start ticking");
}

void loop() {
  uint32_t loopStart = millis();

  time_t timenow = now();

  hours = hour(timenow);
  minutes = minute(timenow);
  seconds = second(timenow);

  //time zone adustment. NTP time is UTC
  hours = hours + tzOffset;
  if (hours < 0)  //handle wraparound
    hours = hours + 24;
  else
  {
    if (hours > 23)
      hours = hours - 24;
  }

  // Show the time on the display by turning it into a numeric
  // value, like 3:30 turns into 330, by multiplying the hour by
  // 100 and then adding the minutes.
  int displayValue = hours * 100 + minutes;

  // Do 24 hour to 12 hour format conversion when required.
  if (!TIME_24_HOUR) {
    // Handle when hours are past 12 by subtracting 12 hours (1200 value).
    if (hours > 12) {
      displayValue -= 1200;
    }
    // Handle hour 0 (midnight) being shown as 12.
    else if (hours == 0) {
      displayValue += 1200;
    }
  }

  // Now print the time value to the display.
  clockDisplay.print(displayValue, DEC);

  // Add zero padding when in 24 hour mode and it's midnight.
  // In this case the print function above won't have leading 0's
  // which can look confusing.  Go in and explicitly add these zeros.
  if (TIME_24_HOUR && hours == 0) {
    // Pad hour 0.
    clockDisplay.writeDigitNum(1, 0);
   // Also pad when the 10's minute is 0 and should be padded.
   if (minutes < 10) {
     clockDisplay.writeDigitNum(3, 0);
   }
 }

  // Blink the colon by flipping its value every loop iteration
  // (which happens every second).
  blinkColon = !blinkColon;
  clockDisplay.drawColon(blinkColon);

  // Now push out to the display the new values that were set above.
  clockDisplay.writeDisplay();

  // Pause for a second for time to elapse.  This value is in milliseconds
  // so 1000 milliseconds = 1 second.
  uint32_t compensatedDelay = 1000 - (millis() - loopStart);
  delay(compensatedDelay % 1000);  //compensate for the time we spent in loop
}

time_t getNTPTime()
{
  time_t epoch = 0;
  int retries = 0;

  //get a random server from the pool
  WiFi.hostByName(ntpServerName, timeServerIP);
  printIP(timeServerIP); //Serial.println();

  sendNTPpacket(timeServerIP); // send an NTP packet to a time server
  // wait to see if a reply is available
  int replyLen;
  do {
    delay(1000);
    replyLen = Udp.parsePacket();
  } while ((retries++ < 15) && (!replyLen));

  if (!replyLen) {  //run out of retries?
    //Serial.println("no packet yet");
    setSyncInterval(30);   //try again in a few seconds
  }
  else
  {
    //Serial.println("packet received");
    setSyncInterval(NTP_SYNC_INTERVAL);
    // We've received a packet, read the data from it
    Udp.read(packetBuffer, NTP_PACKET_SIZE); // read the packet into the buffer

    //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:
    epoch = secsSince1900 - seventyYears;
    //Serial.println(epoch);
  }
  return epoch;
}

// send an NTP request to the time server at the given address
unsigned long sendNTPpacket(IPAddress & address)
{
  ////Serial.println("1");
  // 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)
  ////Serial.println("2");
  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;

  ////Serial.println("3");

  // all NTP fields have been given values, now
  // you can send a packet requesting a timestamp:
  Udp.beginPacket(address, 123); //NTP requests are to port 123
  ////Serial.println("4");
  Udp.write(packetBuffer, NTP_PACKET_SIZE);
  ////Serial.println("5");
  Udp.endPacket();
  ////Serial.println("6");
}


void printWifiStatus() {
  // print the SSID of the network you're attached to:
  //Serial.print("SSID: ");
  //Serial.println(WiFi.SSID());

  // print your WiFi shield's IP address:
  IPAddress ip = WiFi.localIP();
  //Serial.print("IP Address: ");
  printIP(ip); //Serial.println();

  // print the received signal strength:
  long rssi = WiFi.RSSI();
  //Serial.print("signal strength (RSSI):");
  //Serial.print(rssi);
  //Serial.println(" dBm");
}

void printIP(IPAddress ip)
{
  //Serial.print(ip & 0xFF); //Serial.print(".");
  //Serial.print((ip>>8) & 0xFF); //Serial.print(".");
  //Serial.print((ip>>16) & 0xFF); //Serial.print(".");
  //Serial.print((ip>>24) & 0xFF);
}

sandeepmistry · 2016-08-16T21:30:04Z

@trlafleur can you please try again with removing the following from loop():

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

You already have the if ( (millis() - t1) > 10000) check to send a request every 10 s. I think you intended Udp.parsePacket() to be called every loop cycle.

trlafleur · 2016-08-17T15:36:08Z

I had already fixed the main loop... thanks...

In running my test program with DEBUG Print enable, I get this message when the call's stop working. From this point on, its just stops working.

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1


(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 923 ms
Seconds since Jan 1 1900 = 3680436447
Unix time = 1471447647
The UTC time is 15:27:27

Sending an NTP request

Sending an NTP request

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 146 ms
Seconds since Jan 1 1900 = 3680436452
Unix time = 1471447652
The UTC time is 15:27:32

Sending an NTP request

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

sandeepmistry · 2016-08-17T19:30:22Z

@trlafleur after how long did this occur?

Also, could you please let me know what firmware your board is running? See CheckWifi101FirmwareVersion.ino

Could use please add the following to the switch statement in the socketBufferCb function in src/socket/source/socket_buffer.c:

        case SOCKET_MSG_SENDTO:
        {
            sint16 *sentBytes = (sint16 *)pvMsg;

            printf("SOCKET_MSG_SENDTO: sock = %d, sent bytes = %d\n", sock, *sentBytes);
        }
        break;

and also remove the following from WiFiUDP::begin in src/WiFiUdp.cpp:

setsockopt(_socket, SOL_SOCKET, SO_SET_UDP_SEND_CALLBACK, &u32EnableCallbacks, 0);

I'm looking into some changes to the underlying UDP socket, will push another branch later. However, I haven't been able to reproduce your issue yet, but am seeing the RSSI set to 0 (like #86) when there is a received UDP packet.

sandeepmistry · 2016-08-17T19:36:03Z

One more thing for you to try later is changing the following in the sketch:

  if ( Udp.parsePacket() ) 
  {
      RXpacket();
  }

to:

  while ( Udp.parsePacket() ) 
  {
      RXpacket();
  }

trlafleur · 2016-08-17T22:14:05Z

<3 min

On Wed, Aug 17, 2016 at 12:30 PM, Sandeep Mistry notifications@github.com
wrote:

@trlafleur https://github.com/trlafleur after how long did this occur?

Also, could you please let me know what firmware your board is running?
See CheckWifi101FirmwareVersion.ino
https://github.com/arduino-libraries/WiFi101/blob/master/examples/CheckWifi101FirmwareVersion/CheckWifi101FirmwareVersion.ino

Could use please add the following to the switch statement in the
socketBufferCb function in src/socket/source/socket_buffer.c:
    case SOCKET_MSG_SENDTO:
    {
        sint16 *sentBytes = (sint16 *)pvMsg;

        printf("SOCKET_MSG_SENDTO: sock = %d, sent bytes = %d\n", sock, *sentBytes);
    }
    break;
and also remove the following from WiFiUDP::begin in src/WiFiUdp.cpp:

setsockopt(_socket, SOL_SOCKET, SO_SET_UDP_SEND_CALLBACK, &u32EnableCallbacks, 0);

I'm looking into some changes to the underlying UDP socket, will push
another branch later. However, I haven't been able to reproduce your issue
yet, but am seeing the RSSI set to 0 (like #86
#86) when there is a
received UDP packet.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#80 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AEXCKwmYcmLJJXh6IddJGOG3WaivprTgks5qg2FPgaJpZM4JP-Hn
.

~~ _/) ~~~~ _/) ~~~~ _/) ~~~~ _/) ~~

Tom Lafleur

trlafleur · 2016-08-17T22:43:43Z

firmware:

(APP)(INFO)Firmware ver : 19.4.4

(APP)(INFO)Min driver ver : 19.3.0

(APP)(INFO)Curr driver ver: 19.3.0

IDE 1.6.10

trlafleur · 2016-08-17T23:06:43Z

Same issue with while ()

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 29 ms
Seconds since Jan 1 1900 = 3680463902
Unix time = 1471475102
The UTC time is 23:05:02

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 362 ms
Seconds since Jan 1 1900 = 3680463904
Unix time = 1471475104
The UTC time is 23:05:04

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 27 ms
Seconds since Jan 1 1900 = 3680463906
Unix time = 1471475106
The UTC time is 23:05:06

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 367 ms
Seconds since Jan 1 1900 = 3680463908
Unix time = 1471475108
The UTC time is 23:05:08

Sending an NTP request

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

trlafleur · 2016-08-17T23:19:12Z

Made your two driver changes from above... Still stops working. Ran for about 5mins
(first time I ran this test, I had edited the wrong version of the driver)


Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 34 ms
Seconds since Jan 1 1900 = 3680515069
Unix time = 1471526269
The UTC time is 13:17:49

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 25 ms
Seconds since Jan 1 1900 = 3680515071
Unix time = 1471526271
The UTC time is 13:17:51

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48

Sending an NTP request

Sending an NTP request
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

Sending an NTP request
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

Sending an NTP request
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

Sending an NTP request
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

Sending an NTP request
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

trlafleur · 2016-08-18T13:35:16Z

Something to note:

Just adding a call to WiFi.RSSI() to my RXpacket function, increases packet receive times from ~40ms to over 1000ms... That's a lot of overhead just to get the RSSI!!!!!

   // print the received signal strength:
  long rssi = WiFi.RSSI();


Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 1026 ms
Seconds since Jan 1 1900 = 3680515840
Unix time = 1471527040
The UTC time is 13:30:40

/*

 Udp NTP Client

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

 created 4 Sep 2010
 by Michael Margolis
 modified 9 Apr 2012
 by Tom Igoe

 Modified 20 July 2016
 Tom Lafleur

 This code is in the public domain.

 */

#include <SPI.h>
#include <WiFi101.h>
#include <WiFiUdp.h>

int status = WL_IDLE_STATUS;

char ssid[] = "xxxxxxx";              //  your network SSID (name)
char pass[] = "xxxxxxxxx";        // your network password
int keyIndex = 0;                     // your network key Index number (needed only for WEP)

unsigned long t1  = millis();
unsigned long trx = millis();

// Set fixed IP address as needed
// My IP address for the WINC1500:
  IPAddress MYip(192, 94, 167, 12);   
// the DNS server address for the WINC1500:
  IPAddress MYdns1(4,2,2,2);  
// the GateWay address for the WINC1500:
  IPAddress MYgw(192, 94, 167, 4);   
// the Sub Net Mask for the Winc1500:
  IPAddress MYsnm(255,255,255,0); 
// DNS name of NTP server to use  
//const char NTPserver [] = "1.north-america.pool.ntp.org";         // "1.north-america.pool.ntp.org"  us.pool.ntp.org
//const char NTPserver [] = "ntp.ucsd.edu";                         // 132.239.1.6

unsigned int localPort = 2390;        // local port to listen for UDP packets

IPAddress timeServer(132, 239, 1, 6); // time.nist.gov NTP server  129.6.15.28 / .30, 193.5.216.14

const int NTP_PACKET_SIZE = 48;       // NTP time stamp is in the first 48 bytes of the message

byte packetBuffer[ NTP_PACKET_SIZE ] = {0};     //buffer to hold incoming and outgoing packets

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


/* *************************************************************************
 * 
 * 
 * ************************************************************************ */
void setup()
{
  // Open serial communications and wait for port to open:
  Serial.begin(115200);
  while (!Serial) {
    ; // wait for serial port to connect. Needed for native USB port only
  }

// If using Feather M0 board, un-comment this...
//WiFi.setPins (8,7,4,2);             // using a Feather with a WINC1500

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

// set manual IP address, comment this out for DHCP
  WiFi.config(MYip, MYdns1, MYgw, MYsnm); 

  // attempt to connect to Wifi network:
  while ( status != WL_CONNECTED) {
    Serial.print("Attempting to connect to SSID: ");
    Serial.println(ssid);
    // Connect to WPA/WPA2 network. Change this line if using open or WEP network:
    status = WiFi.begin(ssid, pass);

    // wait 10 seconds for connection:
    delay(10000);
  }

  Serial.println("Connected to wifi");
  printWifiStatus();

  Serial.println("\nStarting connection to UDP server...");
  Udp.begin(localPort);
}


/* *************************************************************************
 * 
 * 
 * ************************************************************************ */
void loop()
{
  // check if its time to make an NTP request
  if ( (millis() - t1) > 2000)
  {  
    t1 = millis();
    // see if we are still connected
    if ( (WiFi.status() ==  WL_CONNECTED) )
          sendNTPpacket(timeServer);                  // send an NTP request packet to a time server
        else Serial.println("Not Connected");
  }  

  // Lets see if a reply is available
    while ( Udp.parsePacket() ) { RXpacket(); }

}  // end of loop


/* ************************************************************************ */
void RXpacket(void)
{

   // printWifiStatus();

    // print the received signal strength:
  long rssi = WiFi.RSSI();
//  Serial.print("signal strength (RSSI):");
//  Serial.print(rssi);
//  Serial.println(" dBm");



    trx = millis() - t1;
    Serial.print("NTP Packet received in: ");
    Serial.print( trx);
    Serial.println(" ms");

    // We've received a packet, read the data from it
    Udp.read(packetBuffer, NTP_PACKET_SIZE);        // read the packet into the buffer

    // 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(':');

    // In the first 10 minutes of each hour, we'll want a leading '0'
    if ( ((epoch % 3600) / 60) < 10 ) { Serial.print('0'); }

    Serial.print((epoch  % 3600) / 60);       // print the minute (3600 equals secs per minute)
    Serial.print(':');

    // In the first 10 seconds of each minute, we'll want a leading '0'
    if ( (epoch % 60) < 10 ) {Serial.print('0');}

    Serial.println(epoch % 60);               // print the second
}


/* ************************************************************************ */
// send an NTP request to the time server at the given address
unsigned long sendNTPpacket(IPAddress& address)
{
  Serial.println("\nSending an NTP request");
  // 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)
  //Serial.println("2");
  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;

  //Serial.println("3");

  // all NTP fields have been given values, now
  // you can send a packet requesting a timestamp:
  if (!Udp.beginPacket(address, 123))                 //NTP requests are to port 123)
  //if (!Udp.beginPacket(NTPserver, 123))             //NTP with DNS requests are to port 123)
        Serial.println("beginPacket error");

  if (!Udp.write(packetBuffer, NTP_PACKET_SIZE) ) 
        Serial.println("write error");

  if (!Udp.endPacket()) 
        Serial.println("endPacket error");
}

/* ************************************************************************ */
void printWifiStatus() {
  // print the SSID of the network you're attached to:
  Serial.print("SSID: ");
  Serial.println(WiFi.SSID());

  // print your WiFi shield's IP address:
  IPAddress ip = WiFi.localIP();
  Serial.print("IP Address: ");
  Serial.println(ip);

  // print the received signal strength:
  long rssi = WiFi.RSSI();
  Serial.print("signal strength (RSSI):");
  Serial.print(rssi);
  Serial.println(" dBm");
}

sandeepmistry · 2016-08-18T14:05:26Z

@trlafleur there's a new branch for you to try out: https://github.com/sandeepmistry/WiFi101/tree/samd-debug-enable_socket-buffer-experiments

I think the RSSI call is timing out because a flag is incorrect set, the branch above should address this.

trlafleur · 2016-08-18T17:35:51Z

Its been running now for 10min... RSSI is working, no delay...

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
signal strength (RSSI):-67 dBm
NTP Packet received in: 39 ms
Seconds since Jan 1 1900 = 3680530484
Unix time = 1471541684
The UTC time is 17:34:44

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
signal strength (RSSI):-68 dBm
NTP Packet received in: 30 ms
Seconds since Jan 1 1900 = 3680530486
Unix time = 1471541686
The UTC time is 17:34:46

sandeepmistry · 2016-08-18T18:16:11Z

@trlafleur cool, let's leave it running, and maybe also try the original version without RSSI?

I can submit a pull request with just sandeepmistry@c2be9f6 for further testing, once we think things are stable.

trlafleur · 2016-08-18T18:37:32Z

I'm at 1 hr now, still working...

On Thu, Aug 18, 2016 at 11:16 AM, Sandeep Mistry notifications@github.com
wrote:

@trlafleur https://github.com/trlafleur cool, let's leave it running,
and maybe also try the original version without RSSI?

I can submit a pull request with just sandeepmistry/WiFi101@c2be9f6
sandeepmistry@c2be9f6
for further testing, once we think things are stable.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#80 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AEXCKytqiOcbZvQ9TCygZ9aGa5blfx3Rks5qhKFsgaJpZM4JP-Hn
.

~~ _/) ~~~~ _/) ~~~~ _/) ~~~~ _/) ~~

Tom Lafleur

trlafleur · 2016-08-18T18:38:33Z

Spoke too soon...

Interesting that sent bytes is -1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1


Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 49 ms
signal strength (RSSI):-67 dBm
Seconds since Jan 1 1900 = 3680534155
Unix time = 1471545355
The UTC time is 18:35:55

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 29 ms
signal strength (RSSI):-68 dBm
Seconds since Jan 1 1900 = 3680534157
Unix time = 1471545357
The UTC time is 18:35:57

Sending an NTP request

Sending an NTP request

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

Sending an NTP request
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

Sending an NTP request
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

driverblock · 2016-08-19T12:42:19Z

I've had it running overnight with 5-minute NTP updates, and it's still going...

trlafleur · 2016-08-19T12:56:29Z

I have three units working, one has been running for two days, other two, anywhere from 2 min to all night, when I restarted the two day unit, it failed in 20 min...

~~ _/) ~~~~ _/) ~~~~ _/) ~~~~ _/) ~~

Tom Lafleur

On Aug 19, 2016, at 5:42 AM, driverblock notifications@github.com wrote:

I've had it running overnight with 5-minute NTP updates, and it's still going...

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

driverblock · 2016-08-19T15:00:16Z

Failing again:

Clock starting!
(APP)(INFO)Chip ID 1503a0

(APP)(DBG)[nm_spi_init][745][nmi spi]: chipid (001003a0)

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(DBG)[wait_for_firmware_start][536]ffff0000 ffff0000 2

(APP)(INFO)Firmware ver   : 19.4.4

(APP)(INFO)Min driver ver : 19.3.0

(APP)(INFO)Curr driver ver: 19.3.0
Attempting to connect to SSID: fios63
Connected to wifi
SSID: fios63
IP Address: 192.168.1.7
signal strength (RSSI):-73 dBm

Starting connection to server...

(APP)(DBG)[socket][589]1 Socket 7 session ID = 1
66.79.136.235

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3680601965
Unix time = 1471613165
Waiting for NTP sync
NTP time is set
start ticking
66.79.136.235

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3680602266
Unix time = 1471613466
66.79.136.235

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3680602567
Unix time = 1471613767
66.79.136.235

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3680602869
Unix time = 1471614069
66.79.136.235

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3680603170
Unix time = 1471614370
66.79.136.235

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3680603472
Unix time = 1471614672
66.79.136.235

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3680603773
Unix time = 1471614973
66.79.136.235

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3680604074
Unix time = 1471615274
66.79.136.235
no packet yet
66.79.136.235

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1
no packet yet
66.79.136.235
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1
no packet yet
66.79.136.235
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1
no packet yet
66.79.136.235
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1
no packet yet
66.79.136.235
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1
no packet yet
66.79.136.235
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1
no packet yet
66.79.136.235

sandeepmistry · 2016-08-19T16:29:18Z

@trlafleur @driverblock I think we're onto something with the sent bytes = -1. I still haven't been able to reproduce locally.

However, if I change the IP address of the NTP server in the sketch to a non-existent host on the network I can easily get the -1. In a few seconds. I'm going to setup a Wireshark capture now.

Would you be able to do this as well? Make sure to setup a capture filter for only the MKR1000's IP address only. I'm wondering if a ICMP message is received the firmware stops sending.

sandeepmistry · 2016-08-19T16:47:28Z

I might be testing a different scenario, but in this case the ARP request for the non-existent host on the network fails and the UDP packet is not sent.

trlafleur · 2016-08-19T17:10:40Z

In another program I'm using the MRK1000, I get these message from time to time...
on rx size


(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 5

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 5

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 5

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 5

(APP)(DBG)[hif_send][414]Failed to alloc rx size

(APP)(DBG)[hif_send][414]Failed to alloc rx size

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 5

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 5

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 5

sandeepmistry · 2016-08-19T17:32:59Z

@trlafleur one step at a time, please open a new issue to track the issue from the last comment if the sketch is different.

It would be great if you can get a Wireshark capture of the -1 case.

sandeepmistry · 2016-08-19T17:59:44Z

Also, please try to ping the board when the sent bytes = -1 condition occurs.

trlafleur · 2016-08-20T01:30:22Z

sketch is the same

Interesting, when I ping it from a Mac... I get DUP messages

tom-imac:~ lafleur$ ping 192.94.167.12
PING 192.94.167.12 (192.94.167.12): 56 data bytes
64 bytes from 192.94.167.12: icmp_seq=0 ttl=64 time=76.967 ms
64 bytes from 192.94.167.12: icmp_seq=0 ttl=64 time=76.984 ms (DUP!)
64 bytes from 192.94.167.12: icmp_seq=1 ttl=64 time=6.326 ms
64 bytes from 192.94.167.12: icmp_seq=1 ttl=64 time=6.339 ms (DUP!)
64 bytes from 192.94.167.12: icmp_seq=2 ttl=64 time=5.285 ms
64 bytes from 192.94.167.12: icmp_seq=2 ttl=64 time=5.291 ms (DUP!)
64 bytes from 192.94.167.12: icmp_seq=3 ttl=64 time=5.721 ms
64 bytes from 192.94.167.12: icmp_seq=3 ttl=64 time=5.734 ms (DUP!)
64 bytes from 192.94.167.12: icmp_seq=4 ttl=64 time=6.866 ms
64 bytes from 192.94.167.12: icmp_seq=4 ttl=64 time=6.871 ms (DUP!)
64 bytes from 192.94.167.12: icmp_seq=5 ttl=64 time=8.469 ms
64 bytes from 192.94.167.12: icmp_seq=5 ttl=64 time=8.483 ms (DUP!)
64 bytes from 192.94.167.12: icmp_seq=6 ttl=64 time=6.054 ms
64 bytes from 192.94.167.12: icmp_seq=6 ttl=64 time=6.067 ms (DUP!)
64 bytes from 192.94.167.12: icmp_seq=7 ttl=64 time=9.683 ms
64 bytes from 192.94.167.12: icmp_seq=7 ttl=64 time=9.706 ms (DUP!)
64 bytes from 192.94.167.12: icmp_seq=8 ttl=64 time=6.068 ms
64 bytes from 192.94.167.12: icmp_seq=8 ttl=64 time=6.105 ms (DUP!)

On Fri, Aug 19, 2016 at 10:33 AM, Sandeep Mistry notifications@github.com
wrote:

@trlafleur https://github.com/trlafleur one step at a time, please open
a new issue to track the issue from the last comment if the sketch is
different.

It would be great if you can get a Wireshark capture of the -1 case.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#80 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AEXCK17VbG0cldOxOLrKA9QL_rpAIqCCks5qhejMgaJpZM4JP-Hn
.

~~ _/) ~~~~ _/) ~~~~ _/) ~~~~ _/) ~~

Tom Lafleur

trlafleur · 2016-08-20T17:30:10Z

Ping do work when the NTP request stop, I get the message below...
But we NO longer see any outbound NTP request as confirm by Wireshark...


SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
NTP Packet received in: 36 ms
signal strength (RSSI):-61 dBm
Seconds since Jan 1 1900 = 3680693797
Unix time = 1471704997
The UTC time is 14:56:37

Sending an NTP request

Sending an NTP request
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1
SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

Sending an NTP request
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1
SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

Sending an NTP request
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1
SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

sandeepmistry · 2016-08-22T18:41:31Z

@trlafleur would you able to share a saved Wireshark capture (upload the .pcap file) to this Github issue. You can add a capture filter like ether host F8:F0:05:F4:D9:8D to only include traffic from the board based on it's MAC address.

The duplicate pings in #80 (comment) seem very suspicious. Could something else on the network be using the same IP address as your board?

I'm going to continue try to reproduce this locally ...

sandeepmistry · 2016-08-23T12:49:07Z

I've been able to reproduce with the original NTP client example with a longer overnight test.

start: The UTC time is 21:20:59
failure: The UTC time is 9:12:33

Will try setting up a test access point to Wireshark/tcpdump next.

trlafleur · 2016-08-23T13:03:57Z

I have been able to run for two days, do a reload, runs for 10 mins. It almost like something is not initialized correctly

~~ _/) ~~~~ _/) ~~~~ _/) ~~~~ _/) ~~

On Aug 23, 2016, at 5:49 AM, Sandeep Mistry notifications@github.com wrote:

I've been able to reproduce with the original NTP client example with a longer overnight test.

start: The UTC time is 21:20:59
failure: The UTC time is 9:12:33
Will try setting up a test access point to Wireshark/tcpdump next.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

driverblock · 2016-09-09T12:50:57Z

Having a very difficut time capturing the sent_bytes = -1 problem. I have seen it occur once recently. That was on a restart, but I didn't have wireshark running at the time. However, I have captured a failure to receive a NTP packet from the server. Trace is here, pcap is attached. You can see in the trace where is says "no packet yet". That indicates that the packet was not received. This is all running on my LAN. I have my windows machine set up as an NTP server. Server is 192.168.1.18. Wifi chip is 192.168.1.166.

IP Address: 192.168.1.166
signal strength (RSSI):-80 dBm

Starting connection to server...

(APP)(DBG)[socket][589]1 Socket 7 session ID = 1
192.168.1.18

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3682413265
Unix time = 1473424465
Waiting for NTP sync
NTP time is set
start ticking
192.168.1.18

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
no packet yet
192.168.1.18
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3682413311
Unix time = 1473424511
192.168.1.18

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3682413328
Unix time = 1473424528
192.168.1.18

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
no packet yet
192.168.1.18
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = 48
(APP)(DBG)[m2m_ip_cb][366]recv callback session ID = 1
packet received
Seconds since Jan 1 1900 = 3682413374
Unix time = 1473424574

NTP_retries.pcapng.zip

driverblock · 2016-09-09T12:57:16Z

Update! I just got the sent_bytes = -1 error.

Connected to wifi
SSID: fios63
IP Address: 192.168.1.166
signal strength (RSSI):-86 dBm

Starting connection to server...

(APP)(DBG)[socket][589]1 Socket 7 session ID = 1
192.168.1.18
no packet yet
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
192.168.1.18

(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1
no packet yet
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
Waiting for NTP sync
192.168.1.18
(APP)(DBG)[m2m_ip_cb][424]send callback session ID = 1

SOCKET_MSG_SENDTO: sock = 7, sent bytes = -1

There's nothing on wireshark except some ARP
NTP_sent_bytes.pcapng.zip

sandeepmistry · 2016-09-09T13:02:22Z

@driverblock great!

This feels like a firmware bug to me. @driverblock could you please open an issue with Atmel Support (http://www.atmel.com/design-support/), you can include a link to this issue. Then please add the case number here as a comment.

sandeepmistry · 2016-09-09T13:08:23Z

@driverblock one more question, did you switch access points between the tests. I see an Apple MAC address in the first .pcap file and a Verizon in the second.

Or are you running the NTP server on a Mac?

driverblock · 2016-09-09T14:04:46Z

I'm running win 10 on an old iMac. Verizon is the router. Not sure why the ARP traces are different

driverblock · 2016-09-09T14:05:46Z

Will do

sandeepmistry · 2016-09-09T15:13:34Z

@driverblock thanks! One more question, was the IP pingable when this happened? Just want to make sure it was still connected to the AP at this time.

driverblock · 2016-09-09T20:27:02Z

Rats. I didn’t see this in time. I’ll t ry to get it to happen again.

driverblock · 2016-09-09T20:46:37Z

Atmel support case # 00045355 https://atmelsupport.force.com/customers/500G0000011kchi

sandeepmistry · 2016-09-09T20:54:09Z

@driverblock thank you! Apologies for not asking you to try the ping test earlier.

driverblock · 2016-09-20T13:42:41Z

Update: Atmel reports that they have reproduced the problem:

We are able to reproduce the issue from our side. I have tried sending periodic NTP requests from WINC1500 for every 4s, and able to get status as -1 which means "SOCK_ERR_INVALID_ADDRESS" in received callback for send_to operation. This occurs in random time after starting the test. We are checking with our internal team and will update earlier.

sandeepmistry · 2016-09-20T14:15:35Z

@driverblock thanks for the update!

sandeepmistry · 2016-10-03T18:14:06Z

Hi @driverblock, any news from Atmel on this. It might be worthwhile to nudge them again.

driverblock · 2016-10-11T13:33:15Z

Just got an update this morning - they're still working on it.

driverblock · 2016-11-10T12:54:29Z

@sandeepmistry - Just heard back from Atmel. They've identified the problem and it will be fixed in firmware release 19.5.2

Hi Rick,

The problem is seen in the cases where the WINC1500 is part of a network where a lot of ARP requests are seen. In our case, it was easily reproducible because the WINC1500 was part of the corporate network where default gateway and AP is different.

The issue has been fixed by our development team and it will be available as part of future release 19.5.2

Thanks,
Rakila

sandeepmistry · 2016-11-10T13:49:05Z

@driverblock great, thanks for the update!

According to @trlafleur's post in #90 (comment), 19.5.2 release date has been pushed out to January now.

sandeepmistry · 2017-03-13T20:28:29Z

@trlafleur @driverblock any news from Atmel/Microchip on this?

There's PR build of the IDE that contains the new v19.5.2 WINC1500 firmware: arduino/Arduino#6069 (comment). Any one up for testing it with the master version of the library to see if this has been fixed?

sandeepmistry · 2017-10-19T18:35:21Z

I'm going to close this for now due to lack of feedback. v19.5.2 of the WINC1500 firmware has been out for some time now, and should include the fix.

trlafleur mentioned this issue Aug 16, 2016

WiFi.status() == WL_CONNECTED although connection lost and WiFi.RSSI() == 0 #86

Closed

sandeepmistry added type: imperfection Perceived defect in any part of project Waiting for Atmel labels Sep 9, 2016

sandeepmistry mentioned this issue Dec 9, 2016

WiFi not recovering from wait for available TCP send buffer #118

Closed

sandeepmistry closed this as completed Oct 19, 2017

Testing with NTP UDP code, fails #80

Testing with NTP UDP code, fails #80

Comments

trlafleur commented Jul 19, 2016 • edited by sandeepmistry Loading

driverblock commented Aug 12, 2016 • edited Loading

sandeepmistry commented Aug 16, 2016

trlafleur commented Aug 17, 2016 • edited Loading

sandeepmistry commented Aug 17, 2016

sandeepmistry commented Aug 17, 2016

trlafleur commented Aug 17, 2016

trlafleur commented Aug 17, 2016

trlafleur commented Aug 17, 2016

trlafleur commented Aug 17, 2016 • edited Loading

trlafleur commented Aug 18, 2016 • edited Loading

sandeepmistry commented Aug 18, 2016

trlafleur commented Aug 18, 2016

sandeepmistry commented Aug 18, 2016

trlafleur commented Aug 18, 2016

trlafleur commented Aug 18, 2016 • edited Loading

driverblock commented Aug 19, 2016

trlafleur commented Aug 19, 2016

driverblock commented Aug 19, 2016

sandeepmistry commented Aug 19, 2016

sandeepmistry commented Aug 19, 2016

trlafleur commented Aug 19, 2016

sandeepmistry commented Aug 19, 2016

sandeepmistry commented Aug 19, 2016

trlafleur commented Aug 20, 2016

trlafleur commented Aug 20, 2016

sandeepmistry commented Aug 22, 2016

sandeepmistry commented Aug 23, 2016

trlafleur commented Aug 23, 2016

driverblock commented Sep 9, 2016

driverblock commented Sep 9, 2016

sandeepmistry commented Sep 9, 2016

sandeepmistry commented Sep 9, 2016

driverblock commented Sep 9, 2016 • edited Loading

driverblock commented Sep 9, 2016 • edited Loading

sandeepmistry commented Sep 9, 2016

driverblock commented Sep 9, 2016 • edited Loading

driverblock commented Sep 9, 2016 • edited Loading

sandeepmistry commented Sep 9, 2016

driverblock commented Sep 20, 2016 • edited Loading

sandeepmistry commented Sep 20, 2016

sandeepmistry commented Oct 3, 2016

driverblock commented Oct 11, 2016

driverblock commented Nov 10, 2016

sandeepmistry commented Nov 10, 2016

sandeepmistry commented Mar 13, 2017

sandeepmistry commented Oct 19, 2017

trlafleur commented Jul 19, 2016 •

edited by sandeepmistry

Loading

driverblock commented Aug 12, 2016 •

edited

Loading

trlafleur commented Aug 17, 2016 •

edited

Loading

trlafleur commented Aug 17, 2016 •

edited

Loading

trlafleur commented Aug 18, 2016 •

edited

Loading

trlafleur commented Aug 18, 2016 •

edited

Loading

driverblock commented Sep 9, 2016 •

edited

Loading

driverblock commented Sep 9, 2016 •

edited

Loading

driverblock commented Sep 9, 2016 •

edited

Loading

driverblock commented Sep 9, 2016 •

edited

Loading

driverblock commented Sep 20, 2016 •

edited

Loading