Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

sntp problem with 3.0 #9879

Closed
1 task done
wcwuttke opened this issue Jun 17, 2024 · 45 comments
Closed
1 task done

sntp problem with 3.0 #9879

wcwuttke opened this issue Jun 17, 2024 · 45 comments
Labels
Type: Example Issue is related to specific example.

Comments

@wcwuttke
Copy link

Board

DEVKIT V1, ESP32 Dev Module

Device Description

Clone ESP32 DEVKIT V1, Freenove ESP32-WROOM

Hardware Configuration

no

Version

v3.0.1

IDE Name

Arduino IDE

Operating System

Windows 11 and MACOS 14.5

Flash frequency

80 MHz

PSRAM enabled

no

Upload speed

921600

Description

Never gets time adjustment from BTP almost every time. Only once in a while successfully gets the time adjustment. Worked fine in version 2.0.17.

Sketch

ESP32 SimpleTime example.

Debug Message

no error message

Other Steps to Reproduce

Work fine in version 2.0.17 but not in 3.0 or above

I have checked existing issues, online documentation and the Troubleshooting Guide

  • I confirm I have checked existing issues, online documentation and Troubleshooting guide.
@wcwuttke wcwuttke added the Status: Awaiting triage Issue is waiting for triage label Jun 17, 2024
@wcwuttke
Copy link
Author

Should be NTP - not BTP.

@SuGlider
Copy link
Collaborator

Issue confirmed. This is a a problem with esp_sntp_servermode_dhcp(1); // (optional) call.

@SuGlider SuGlider mentioned this issue Jun 17, 2024
Closed
@SuGlider
Copy link
Collaborator

@wcwuttke - Please check PR #9884 that comments out esp_sntp_servermode_dhcp(1); // (optional) code line in the example.

@SuGlider SuGlider self-assigned this Jun 17, 2024
@SuGlider SuGlider added Type: Bug 🐛 All bugs Type: Example Issue is related to specific example. and removed Status: Awaiting triage Issue is waiting for triage labels Jun 17, 2024
@SuGlider SuGlider added this to the 3.0.2 milestone Jun 17, 2024
@wcwuttke
Copy link
Author

I commented out esp_sntp_servermode_dhcp(1); and it appeared to fix the problem. I rebooted the board three times successfully. However, the fourth and fifth time, got "No time available (yet)". Rebooted again and got the time. Rebooted again and got "No time available (yet)". Rebooted again and got the time. It looks like the problem is still there intermittently.

@SuGlider
Copy link
Collaborator

SuGlider commented Jun 18, 2024 •
edited
Loading

This is interesting... I was getting 100% success while I had debug output as Verbose.
But when I tried it with no debug output I also see the issue youo are reporting about the problem being still there.

It may also be related to another fix from the https://github.com/espressif/arduino-esp32/pull/9862/files
It seems that it must wait for the WiFi interface to really get started.

Indeed removing esp_sntp_servermode_dhcp(1); is not the fix.

I have applied the fix from #9862 here and it seems to improve the success rate to 8 out of 10.

Could you apply the change to libraries/WiFi/src/STA.cpp into the begin() function?

bool STAClass::begin(bool tryConnect) {
  if (!WiFi.enableSTA(true)) {
    log_e("STA enable failed!");
    return false;
  }
  if (!waitStatusBits(ESP_NETIF_STARTED_BIT, 1000)) {
    log_e("Failed to start STA!");
    return false;
  }
  if (tryConnect) {
    return connect();
  }
  return true;
}

@SuGlider
Copy link
Collaborator

@me-no-dev - Could you please also take a look into it?

@SuGlider
Copy link
Collaborator

SuGlider commented Jun 18, 2024 •
edited
Loading

@wcwuttke - I think I got the solution: I changed the NTP server to const char *ntpServer1 = "time.google.com";
It has worked 100% of 20 resets of the board.

@SuGlider SuGlider removed the Type: Bug 🐛 All bugs label Jun 18, 2024
@wcwuttke
Copy link
Author

wcwuttke commented Jun 18, 2024 via email

@me-no-dev
Copy link
Member

The change in STA.cpp is irrelevant. esp_sntp_servermode_dhcp(1); should be the line after WiFi.begin() as explained in it's comment, but will also not cause NTP to fail, it will just not take it from DHCP if it offers NTP server.

With that said, I am trying to replicate the issue and I can not. I got No time available (yet) once and a couple of seconds later, it got the time just fine. Restarted tenths of times.

@wcwuttke
Copy link
Author

me-no-dev,
I don't know what your configuration is, but the only way I can get this sketch to work reliably is with version 2.0.17. With 3.0.1, it will work once in a while, but mostly fails.

@me-no-dev
Copy link
Member

I don't know what your configuration is

The example as-is. Nothing else. My SSID and PASS

@me-no-dev
Copy link
Member

Did you wait after you got the message to eventually get the NTP or not?

@SuGlider SuGlider removed this from the 3.0.2 milestone Jun 18, 2024
@wcwuttke
Copy link
Author

wcwuttke commented Jun 18, 2024 via email

@me-no-dev
Copy link
Member

@wcwuttke I see, but I can not reproduce here. I made more than 30 restarts with the sketch as-is and could not get it to fail once. I suspect something in your environment is to blame

@wcwuttke
Copy link
Author

wcwuttke commented Jun 19, 2024 via email

@me-no-dev
Copy link
Member

ESP32-WROVER-E (ESP32 v3) on a Mac M1MAX (should not matter) and my router is Mikrotik without any special settings for NTP. Sketch is SimpleTime with adjusted SSID, PASS and time offset for my zone. From all reboots I got No time available (yet) only once for just one time, after which time was updated before next 5 seconds expires.

Any chance you can try in a different network environment? I have no idea why 2.x worked but 3.x fails for you...

@wcwuttke
Copy link
Author

wcwuttke commented Jun 19, 2024 via email

@me-no-dev
Copy link
Member

can you turn core debug to level Verbose and paste the output before setup on those ESPs? I'll try to use the same

@wcwuttke
Copy link
Author

wcwuttke commented Jun 19, 2024 via email •
edited by me-no-dev
Loading

@me-no-dev
Copy link
Member

yes. will test tomorrow

@wcwuttke
Copy link
Author

wcwuttke commented Jun 19, 2024 via email •
edited by me-no-dev
Loading

@me-no-dev
Copy link
Member

can you please not reply via email? formatting the data you paste is impossible this way and it's very hard to read

@wcwuttke
Copy link
Author

I agree. However, to me it looks OK on Github. I had a lot of trouble trying to cut & paste from the Arduino IDE, and I have never used the debug features before. (I have always used "Serial.print" for debugging.) Let me try compiling on the Win 11 machine to see what is happening with it. Maybe if I knew exactly what you are looking for I could try to get it.

@me-no-dev
Copy link
Member

Email replies do not support Markdown

@me-no-dev
Copy link
Member

After you paste it here and not through email. we can fix the format (though that is something you should do yourself). Email replies are ok if you are just commenting, but pasting logs and code is not good

@me-no-dev
Copy link
Member

Something very strange has happened. When I compile with 3.0.1, the app repeatedly crashes. I go back to 2.0.17, all is well. Go back to 3.0.1 continuous crashing.

That sounds like the issue is in your environment. Or are you using another sketch and not the SimpleTime?

@wcwuttke
Copy link
Author

I am using SimpleTime. I just tested on the Win11 machine with the same results. Keeps on crashing - both 3.0.0 and 3.0.1. I revert to 2.0.17 and all is well. Now it is 3 different machines with 3 different OS's.

@me-no-dev
Copy link
Member

I do have rev1 wrovers here so will test tomorrow

@wcwuttke
Copy link
Author

Just for fun, I tested using Arduino 1.8.19 on the Win11 machine. Same result. OK with 2.0.17, keeps crashing with 3.0.1.

@wcwuttke
Copy link
Author

As long as we are testing with two different chips, we will never have the same testing environment. I will order a WROVER board today to see what happens on this end.

@wcwuttke
Copy link
Author

Things are getting stranger. I compiled a few other example projects and came back to SimpleTime. Amazingly enough it compiled and ran OK - but, sometimes got the time, sometimes it didn't. I captured the verbose debug output of 3 reboots - both getting time and not getting time - to a file which is attached.
Debug.txt

@me-no-dev
Copy link
Member

and my output with the same module as yours (many restarts an no fail):

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
flash read err, 1000
ets_main.c 371 
ets Jun  8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:1448
load:0x40078000,len:14844
ho 0 tail 12 room 4
load:0x40080400,len:4
load:0x40080404,len:3356
entry 0x4008059c
[     1][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_RX (2) successfully set to 0x400d9648
[    12][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_TX (3) successfully set to 0x400d9618
[    26][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_CTS (4) successfully set to 0x400d95e8
[    39][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_RTS (5) successfully set to 0x400d95b8
[    53][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_RX (2) successfully set to 0x400d9648
[    66][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_TX (3) successfully set to 0x400d9618
[    79][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_CTS (4) successfully set to 0x400d95e8
[    93][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_RTS (5) successfully set to 0x400d95b8
[   106][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_RX (2) successfully set to 0x400d9648
[   120][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_TX (3) successfully set to 0x400d9618
[   133][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_CTS (4) successfully set to 0x400d95e8
[   147][V][esp32-hal-periman.c:235] perimanSetBusDeinit(): Deinit function for type UART_RTS (5) successfully set to 0x400d95b8
[   162][D][esp32-hal-cpu.c:264] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz
[   224][V][esp32-hal-periman.c:160] perimanSetPinBus(): Pin 3 successfully set to type UART_RX (2) with bus 0x3ffbdb80
[   235][V][esp32-hal-periman.c:160] perimanSetPinBus(): Pin 1 successfully set to type UART_TX (3) with bus 0x3ffbdb80
=========== Before Setup Start ===========
Chip Info:
------------------------------------------
  Model             : ESP32
  Package           : D0WD-Q6
  Revision          : 100
  Cores             : 2
  Frequency         : 240 MHz
  Embedded Flash    : No
  Embedded PSRAM    : No
  2.4GHz WiFi       : Yes
  Classic BT        : Yes
  BT Low Energy     : Yes
  IEEE 802.15.4     : No
------------------------------------------
INTERNAL Memory Info:
------------------------------------------
  Total Size        :   336152 B ( 328.3 KB)
  Free Bytes        :   304948 B ( 297.8 KB)
  Allocated Bytes   :    23948 B (  23.4 KB)
  Minimum Free Bytes:   298816 B ( 291.8 KB)
  Largest Free Block:   110580 B ( 108.0 KB)
------------------------------------------
Flash Info:
------------------------------------------
  Chip Size         :  4194304 B (4 MB)
  Block Size        :    65536 B (  64.0 KB)
  Sector Size       :     4096 B (   4.0 KB)
  Page Size         :      256 B (   0.2 KB)
  Bus Speed         : 80 MHz
  Bus Mode          : QIO
------------------------------------------
Partitions Info:
------------------------------------------
                nvs : addr: 0x00009000, size:    20.0 KB, type: DATA, subtype: NVS
            otadata : addr: 0x0000E000, size:     8.0 KB, type: DATA, subtype: OTA
               app0 : addr: 0x00010000, size:  1280.0 KB, type:  APP, subtype: OTA_0
               app1 : addr: 0x00150000, size:  1280.0 KB, type:  APP, subtype: OTA_1
             spiffs : addr: 0x00290000, size:  1408.0 KB, type: DATA, subtype: SPIFFS
           coredump : addr: 0x003F0000, size:    64.0 KB, type: DATA, subtype: COREDUMP
------------------------------------------
Software Info:
------------------------------------------
  Compile Date/Time : Jun 10 2024 10:52:03
  Compile Host OS   : macosx
  ESP-IDF Version   : v5.1.4-51-g442a798083-dirty
  Arduino Version   : 3.0.1
------------------------------------------
Board Info:
------------------------------------------
  Arduino Board     : ESP32_DEV
  Arduino Variant   : esp32
  Arduino FQBN      : esp32:esp32:esp32:UploadSpeed=921600,CPUFreq=240,FlashFreq=80,FlashMode=qio,FlashSize=4M,PartitionScheme=default,DebugLevel=verbose,PSRAM=disabled,LoopCore=1,EventsCore=1,EraseFlash=none,JTAGAdapter=default,ZigbeeMode=default
============ Before Setup End ============
[   737][V][esp32-hal-uart.c:408] uartBegin(): UART0 baud(115200) Mode(800001c) rxPin(3) txPin(1)
[   746][V][esp32-hal-uart.c:497] uartBegin(): UART0 not installed. Starting installation
[   756][V][esp32-hal-uart.c:544] uartBegin(): UART0 initialization done.
Connecting to nbis-test [   794][V][NetworkEvents.cpp:119] checkForEvent(): Network Event: 9 - WIFI_READY
[   875][V][STA.cpp:184] _onStaEvent(): STA Started
[   880][V][NetworkEvents.cpp:119] checkForEvent(): Network Event: 11 - STA_START
[   887][V][STA.cpp:110] _onStaArduinoEvent(): Arduino STA Event: 11 - STA_START
[   982][V][STA.cpp:204] _onStaEvent(): STA Connected: SSID: nbis-test, BSSID: 74:4d:28:c6:7a:fc, Channel: 8, Auth: WPA_WPA2_PSK
[   994][V][NetworkEvents.cpp:119] checkForEvent(): Network Event: 13 - STA_CONNECTED
[   998][V][NetworkInterface.cpp:66] _onIpEvent(): sta Got New IP: 192.168.254.99 MASK: 255.255.255.0 GW: 192.168.254.1
[  1012][V][STA.cpp:110] _onStaArduinoEvent(): Arduino STA Event: 13 - STA_CONNECTED
[  1019][V][NetworkEvents.cpp:119] checkForEvent(): Network Event: 16 - STA_GOT_IP
[  1027][V][STA.cpp:110] _onStaArduinoEvent(): Arduino STA Event: 16 - STA_GOT_IP
[  1034][V][STA.cpp:169] _onStaArduinoEvent(): STA IP: 192.168.254.99, MASK: 255.255.255.0, GW: 192.168.254.1
. CONNECTED
=========== After Setup Start ============
INTERNAL Memory Info:
------------------------------------------
  Total Size        :   336152 B ( 328.3 KB)
  Free Bytes        :   256700 B ( 250.7 KB)
  Allocated Bytes   :    69396 B (  67.8 KB)
  Minimum Free Bytes:   253256 B ( 247.3 KB)
  Largest Free Block:   110580 B ( 108.0 KB)
------------------------------------------
GPIO Info:
------------------------------------------
  GPIO : BUS_TYPE[bus/unit][chan]
  --------------------------------------  
     1 : UART_TX[0]
     3 : UART_RX[0]
============ After Setup End =============
Got time adjustment from NTP!
Thursday, June 20 2024 14:02:50
Thursday, June 20 2024 14:02:52
Thursday, June 20 2024 14:02:57

@wcwuttke
Copy link
Author

wcwuttke commented Jun 20, 2024 •
edited
Loading

I set up a Win10 machine as an NTP server. In the SimpleTime sketch I used the Win10 IP address in ConfigTime(). This configuration works like a charm (3.0.1). So....to me it looks like a DNS problem of some sort. I have an XFinity router which from time to time has had DNS problems. Let me reboot that and let's see what happens. Progress is being made.

@wcwuttke
Copy link
Author

wcwuttke commented Jun 20, 2024 •
edited
Loading

Well, rebooting the router didn't help.

update: Used IP address for time.google.com (216.239.35.4) instead of hostname and it works well.
Also for IP address of pool.ntp.org. It looks that at least I've found a workaround.

update: Tried the WROVER. Has the same problem. Gets time only once in a while.

@TD-er
Copy link
Contributor

TD-er commented Jun 24, 2024 •
edited
Loading

Can you check to see if you already have a DNS server set when trying to start making a NTP request?
Quote often the DNS is not immediately set on the first DHCP request and it may also be reset when WiFi is disabled.

Another option is to also check to see if your router supports replying to NTP requests. If so, then you could also try to make a NTP call to your gateway IP.
This isn't a universal 'fix', but it may give results faster if powered-on-time matters.

Edit:
Another idea...
Could it be you try to resolve a DNS record for fetching the time which is using DNSSEC?

@wcwuttke
Copy link
Author

My immediate problem with my current project is solved by using the NTP server IP address instead of the hostname. I wrote a small sketch that uses gethostbyname() and it gets the IP address every time. I will not be doing any more testing of this problem - I am working on finishing my project.

@me-no-dev
Copy link
Member

It's interesting that this solved your issue. Do you by any chance have IPv6 enabled?

@wcwuttke
Copy link
Author

The Xfinity router has IPv6 enabled. There is no way to disable it.

@me-no-dev
Copy link
Member

You could try and call WiFi.enableIPv6() before WiFi.begin() and see if that improves anything? Is the IPv6 Link-Local only, or do you also have a global address?

@wcwuttke
Copy link
Author

It looks like you found the answer! Enabling IPv6 makes everything work as advertised. The router has both local and global IPv6 addresses.

@TD-er
Copy link
Contributor

TD-er commented Jun 25, 2024

Hmm this makes me wonder why it was not working.
Maybe the DNS resolve did only return an AAAA record? But then, why?

@me-no-dev
Copy link
Member

Awesome! Could we consider this resolved?

@TD-er could be router specific thing or something that has changed in NTP/LwIP. Unfortunately I can not reproduce it here. Everything works as expected, regardless if I enable v6 in the router or not.

@me-no-dev
Copy link
Member

Maybe it returns V4 mapped into V6 address and NTP does not handle it?

@wcwuttke
Copy link
Author

As far as I am concerned, you can close the ticket. You might put a note somewhere about this issue, though. It had me tearing my hair out for awhile. Thanks...

@me-no-dev
Copy link
Member

we will keep an eye for similar issues

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Type: Example Issue is related to specific example.
Projects
Arduino ESP32 Core Project Roadmap
Status: Done
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix(SimpleTime): fixes example for SimpleTime.ino espressif/arduino-esp32
4 participants
@TD-er @me-no-dev @wcwuttke @SuGlider