Revision 9:2f607bafc29e, committed 2016-01-16

Comitter:

WiredHome

Date:

Sat Jan 16 20:47:33 2016 +0000

Parent:

8:802277794640

Commit message:

NTPClient was computing the offset from the server to the client incorrectly (when it was promoting 32 to 64bit values. The result was time-jumps (e.g. from 2016 to 2084) and then back. This was most noticeable with the WiFly interface (extra delays)

Changed in this revision

--- a/NTPClient.cpp	Thu Nov 26 18:20:56 2015 +0000
+++ b/NTPClient.cpp	Sat Jan 16 20:47:33 2016 +0000
@@ -16,27 +16,47 @@
  * DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
  * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
  */
+#include "mbed.h" //time() and set_time()
 
-//Debug is disabled by default
-#if 0
-//Enable debug
-#define __DEBUG__
+//#define DEBUG "NTPc"
+
+#if (defined(DEBUG))
 #include <cstdio>
-#define DBG(x, ...) std::printf("[NTPClient : DBG]"x"\r\n", ##__VA_ARGS__);
-#define WARN(x, ...) std::printf("[NTPClient : WARN]"x"\r\n", ##__VA_ARGS__);
-#define ERR(x, ...) std::printf("[NTPClient : ERR]"x"\r\n", ##__VA_ARGS__);
+#define INFO(x, ...) std::printf("[INF %s %4d] "x"\r\n", DEBUG, __LINE__, ##__VA_ARGS__);
+#define WARN(x, ...) std::printf("[WRN %s %4d] "x"\r\n", DEBUG, __LINE__, ##__VA_ARGS__);
+#define ERR(x, ...)  std::printf("[ERR %s %4d] "x"\r\n", DEBUG, __LINE__, ##__VA_ARGS__);
+static void HexDump(const char * title, const uint8_t * p, int count)
+{
+    int i;
+    char buf[100] = "0000: ";
+
+    if (*title)
+        INFO("%s", title);
+    for (i=0; i<count; ) {
+        sprintf(buf + strlen(buf), "%02X ", *(p+i));
+        if ((++i & 0x0F) == 0x00) {
+            INFO("%s", buf);
+            if (i < count)
+                sprintf(buf, "%04X: ", i);
+            else
+                buf[0] = '\0';
+        }
+    }
+    if (strlen(buf))
+        INFO("%s", buf);
+}
 #else
 //Disable debug
-#define DBG(x, ...)
+#define INFO(x, ...)
 #define WARN(x, ...)
 #define ERR(x, ...)
+#define HexDump(a,b,c)
 #endif
 
 #include "NTPClient.h"
 
 #include "UDPSocket.h"
 
-#include "mbed.h" //time() and set_time()
 
 #define NTP_PORT 123
 #define NTP_CLIENT_PORT 0 //Random port
@@ -49,14 +69,14 @@
 
 NTPResult NTPClient::setTime(const char* host, uint16_t port, uint32_t timeout)
 {
-#ifdef __DEBUG__
+#ifdef DEBUG
     time_t ctTime;
     ctTime = time(NULL);
-    DBG("Time is set to (UTC): %s", ctime(&ctTime));
+    INFO("Time is currently (UTC): %s", ctime(&ctTime));
 #endif
 
     //Create & bind socket
-    DBG("Binding socket");
+    INFO("Binding socket");
     m_sock.bind(0); //Bind to a random port
 
     m_sock.set_blocking(false, timeout); //Set not blocking
@@ -64,7 +84,7 @@
     struct NTPPacket pkt;
 
     //Now ping the server and wait for response
-    DBG("Ping");
+    INFO("Ping");
     //Prepare NTP Packet:
     pkt.li = 0; //Leap Indicator : No warning
     pkt.vn = 4; //Version Number : 4
@@ -81,15 +101,19 @@
     pkt.origTm_s = 0;
     pkt.rxTm_s = 0;
     pkt.txTm_s = htonl( NTP_TIMESTAMP_DELTA + time(NULL) ); //WARN: We are in LE format, network byte order is BE
-
+    INFO("pkt.txTm_s = %u", ntohl(pkt.txTm_s) );
     pkt.refTm_f = pkt.origTm_f = pkt.rxTm_f = pkt.txTm_f = 0;
 
+    HexDump("NTP Post", (uint8_t *)&pkt, sizeof(NTPPacket));
+    
     Endpoint outEndpoint;
-
+    INFO("outEndpoint instantiated");
+    
     if( outEndpoint.set_address(host, port) < 0) {
         m_sock.close();
         return NTP_DNS;
     }
+    INFO("outEndpoint: %s:%d", outEndpoint.get_address(), outEndpoint.get_port());
 
     //Set timeout, non-blocking and wait using select
     int ret = m_sock.sendTo( outEndpoint, (char*)&pkt, sizeof(NTPPacket) );
@@ -101,20 +125,25 @@
 
     //Read response
     Endpoint inEndpoint;
-
+    INFO(" inEndpoint instantiated: %s.", inEndpoint.get_address());
+    
     // Set the inEndpoint address property
     inEndpoint.set_address(outEndpoint.get_address(), 0);
 
-    DBG("Pong");
+    INFO(" inEndpoint: %s", inEndpoint.get_address());
+
+    INFO("Pong");
+    int loopLimit = 20;  // semi-randomly selected so it doesn't hang forever here...
     do {
-        ret = m_sock.receiveFrom( inEndpoint, (char*)&pkt, sizeof(NTPPacket) ); //FIXME need a DNS Resolver to actually compare the incoming address with the DNS name
+        ret = m_sock.receiveFrom( inEndpoint, (char*)&pkt, sizeof(NTPPacket) );
         if(ret < 0) {
             ERR("Could not receive packet");
             m_sock.close();
             return NTP_CONN;
         }
-        DBG(".");
-    } while( strcmp(outEndpoint.get_address(), inEndpoint.get_address()) != 0 );
+        INFO(".");
+        loopLimit--;
+    } while( strcmp(outEndpoint.get_address(), inEndpoint.get_address()) != 0 && loopLimit > 0);
 
     if(ret < (int)sizeof(NTPPacket)) { //TODO: Accept chunks
         ERR("Receive packet size does not match");
@@ -128,6 +157,8 @@
         return NTP_PRTCL;
     }
 
+    HexDump("NTP Info", (uint8_t *)&pkt, sizeof(NTPPacket));
+
     //Correct Endianness
     pkt.refTm_s = ntohl( pkt.refTm_s );
     pkt.refTm_f = ntohl( pkt.refTm_f );
@@ -140,15 +171,31 @@
 
     //Compute offset, see RFC 4330 p.13
     uint32_t destTm_s = (NTP_TIMESTAMP_DELTA + time(NULL));
-    int64_t offset = ( (int64_t)( pkt.rxTm_s - pkt.origTm_s ) + (int64_t) ( pkt.txTm_s - destTm_s ) ) / 2; //Avoid overflow
-    DBG("Sent @%ul", pkt.txTm_s);
-    DBG("Offset: %lld", offset);
+    INFO("destTm_s = %u", destTm_s);
+    INFO("pkt.txTm_s = %u", pkt.txTm_s );
+    
+    // Modification by David Smart
+    // The setTime function was computing the offset incorrectly as the value was promoted to 64-bit.
+    // The side effect was that a negative offset ended up as a very large positive (e.g. jump from 
+    // 2016 to 2084). This change revises that computation.
+    int64_t offset = ( ((int64_t)pkt.rxTm_s - pkt.origTm_s ) + ((int64_t) pkt.txTm_s - destTm_s ) ) / 2; //Avoid overflow
+    
+    // delay is not needed, this was for diagnostic purposes only.
+    //int64_t delay = ((int64_t) destTm_s - pkt.origTm_s) - ((int64_t) pkt.txTm_s - pkt.rxTm_s);
+    INFO("txTm_s   @%u", pkt.txTm_s);
+    INFO("origTm_s @%u", pkt.origTm_s);
+    INFO("rxTm_s   @%u", pkt.rxTm_s);
+    INFO("destTm_s @%u", destTm_s);
+    INFO("Offset: %lld", offset);
+    //INFO("Delay:  %lld", delay);
+    
+    INFO(" time:    %u", time(NULL));
     //Set time accordingly
     set_time( time(NULL) + offset );
 
 #ifdef __DEBUG__
     ctTime = time(NULL);
-    DBG("Time is now (UTC): %s", ctime(&ctTime));
+    INFO("Time is now (UTC): %s", ctime(&ctTime));
 #endif
 
     m_sock.close();

--- a/NTPClient.h	Thu Nov 26 18:20:56 2015 +0000
+++ b/NTPClient.h	Sat Jan 16 20:47:33 2016 +0000
@@ -15,6 +15,7 @@
  * NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM,
  * DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
  * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
+ *
  */
 
 /** \file