SC-F001/logtool/rtc_drift_run.txt

[1] Opening COM3 at 115200 baud and resetting board...
    EN pulsed. Waiting for boot output...
ets Jul 29 2019 12:21:46



rst:0x1 (POWERON_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:2

load:0x3fff0030,len:7176

load:0x40078000,len:16092

ho 0 tail 12 room 4

load:0x40080400,len:4

load:0x40080404,len:3912

entry 0x40080640

I (31) boot: ESP-IDF v5.3.1-dirty 2nd stage bootloader

I (31) boot: compile time Mar  4 2026 13:08:05

I (31) boot: Multicore bootloader

I (36) boot: chip revision: v3.1

I (40) boot.esp32: SPI Speed      : 40MHz

I (44) boot.esp32: SPI Mode       : DIO

I (49) boot.esp32: SPI Flash Size : 8MB

I (53) boot: Enabling RNG early entropy source...

I (59) boot: Partition Table:

I (62) boot: ## Label            Usage          Type ST Offset   Length

I (70) boot:  0 nvs              WiFi data        01 02 00009000 00004000

I (77) boot:  1 otadata          OTA data         01 00 0000d000 00002000

I (84) boot:  2 phy_init         RF data          01 01 0000f000 00001000

I (92) boot:  3 ota_0            OTA app          00 10 00010000 00180000

I (99) boot:  4 ota_1            OTA app          00 11 00190000 00180000

I (107) boot:  5 storage          Unknown data     01 40 00310000 00020000

I (114) boot: End of partition table

I (119) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=409d0h (264656) map

I (218) esp_image: segment 1: paddr=000509f8 vaddr=3ff80063 size=00008h (     8) load

I (218) esp_image: segment 2: paddr=00050a08 vaddr=3ffbdb60 size=0648ch ( 25740) load

I (233) esp_image: segment 3: paddr=00056e9c vaddr=40080000 size=0917ch ( 37244) load

I (248) esp_image: segment 4: paddr=00060020 vaddr=400d0020 size=ffbf0h (1047536) map

I (607) esp_image: segment 5: paddr=0015fc18 vaddr=4008917c size=11f50h ( 73552) load

I (636) esp_image: segment 6: paddr=00171b70 vaddr=400c0000 size=00064h (   100) load

I (637) esp_image: segment 7: paddr=00171bdc vaddr=50000000 size=0004ch (    76) load

I (656) boot: Loaded app from partition at offset 0x10000

I (656) boot: Disabling RNG early entropy source...

I (668) cpu_start: Multicore app

W (830) clk: 32 kHz XTAL not found, switching to internal 150 kHz oscillator

I (838) cpu_start: Pro cpu start user code

I (838) cpu_start: cpu freq: 160000000 Hz

I (839) app_init: Application information:

I (843) app_init: Project name:     SC-F001

I (848) app_init: App version:      e2451fc-dirty

I (853) app_init: Compile time:     Mar  5 2026 16:20:24

I (859) app_init: ELF file SHA256:  3aee52b89...

I (865) app_init: ESP-IDF:          v5.3.1-dirty

I (870) efuse_init: Min chip rev:     v0.0

I (875) efuse_init: Max chip rev:     v3.99 

I (880) efuse_init: Chip rev:         v3.1

I (885) heap_init: Initializing. RAM available for dynamic allocation:

I (892) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM

I (898) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM

I (904) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM

I (910) heap_init: At 3FFCDD48 len 000122B8 (72 KiB): DRAM

I (916) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM

I (922) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM

I (929) heap_init: At 4009B0CC len 00004F34 (19 KiB): IRAM

I (937) spi_flash: detected chip: generic

I (940) spi_flash: flash io: dio

W (944) i2c: This driver is an old driver, please migrate your application code to adapt `driver/i2c_master.h`

I (955) coexist: coex firmware version: 4482466

I (960) main_task: Started on CPU0

I (970) main_task: Calling app_main()

W (970) RTC: Slow clock source is 0 — expected XTAL32K (1). Check sdkconfig.

I (970) RTC: Wakeup: normal boot

I (980) MAIN: Firmware: V_e2451fc-dirty (2026-03-05 22:20:22)

I (980) MAIN: Version: e2451fc-dirty

I (990) MAIN: Branch: main

I (990) MAIN: Built: 2026-03-05 22:20:22

I (990) STORAGE: Initializing storage system...

I (1000) STORAGE: Storage partition found: size=131072 bytes

I (1010) STORAGE: Log init: scanning 28 sectors with bisection

I (1030) STORAGE: Log system initialized (bisection). Head: 131072, Tail: 16384

I (1030) STORAGE: Log writer task started

I (1030) STORAGE: Log wr



========================================

  UART JSON Interface Ready

========================================

Type 'HELP' for available commands

Type 'GET' to see system status



> I (1050) UART: UART interface started

I (1050) gpio: GPIO[25]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 

I (1060) RF: RF receiver task started on core 0

I (1070) BTDM_INIT: BT controller compile version [b022216]

I (1070) BTDM_INIT: Bluetooth MAC: 94:54:c5:38:c4:3a

I (1080) phy_init: phy_version 4830,54550f7,Jun 20 2024,14:22:08

E (1090) phy_init: esp_phy_load_cal_data_from_nvs: NVS has not been initialized. Call nvs_flash_init before starting WiFi/BT.

W (1100) phy_init: failed to load RF calibration data (0x1101), falling back to full calibration

W (1170) phy_init: saving new calibration data because of checksum failure, mode(2)

E (1410) BT_OSI: config_new: NVS not initialized. Call nvs_flash_init before initializing bluetooth.

W (1410) BT_BTC: btc_config_init unable to load config file; starting unconfigured.



E (1410) BT_OSI: config_save: NVS not initialized. Call nvs_flash_init before initializing bluetooth.

E (1420) BT_OSI: config_save, err_code: 0x2



E (1480) BT_APPL: bta_gattc_co_cache_addr_init, Line = 436, nvs flash open fail, err_code = 1101

E (1500) BT_OSI: config_save: NVS not initialized. Call nvs_flash_init before initializing bluetooth.

E (1500) BT_OSI: config_save, err_code: 0x2



E (1510) BT_OSI: config_save: NVS not initialized. Call nvs_flash_init before initializing bluetooth.

E (1520) BT_OSI: config_save, err_code: 0x2



E (1520) BT_OSI: config_save: NVS not initialized. Call nvs_flash_init before initializing bluetooth.

E (1530) BT_OSI: config_save, err_code: 0x2



E (1540) BT_OSI: config_save: NVS not initialized. Call nvs_flash_init before initializing bluetooth.

E (1550) BT_OSI: config_save, err_code: 0x2



I (1560) BT_HID: Scanning for HID devices (3s)...

I (1560) BT_HID: BLE HID host initialised

I (1560) gpio: GPIO[14]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 

I (1570) WEBSERVER: Initializing webserver...

I (1570) gpio: GPIO[27]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 

I (1590) WEBSERVER: AP LAUNCHING

I (1610) WEBSERVER: AP LAUNCHING...

I (1610) WEBSERVER: HI THERE

I (1630) wifi:wifi driver task: 3ffe2808, prio:23, stack:6656, core=0

I (1640) wifi:wifi firmware version: ccaebfa

I (1640) wifi:wifi certification version: v7.0

I (1640) wifi:config NVS flash: enabled

I (1640) wifi:config nano formating: disabled

I (1640) wifi:Init data frame dynamic rx buffer num: 32

I (1650) wifi:Init static rx mgmt buffer num: 5

I (1650) wifi:Init management short buffer num: 32

I (1650) wifi:Init dynamic tx buffer num: 32

I (1660) wifi:Init static rx buffer size: 1600

I (1660) wifi:Init static rx buffer num: 10

I (1670) wifi:Init dynamic rx buffer num: 32

I (1680) wifi_init: rx ba win: 6

I (1680) wifi_init: accept mbox: 6

I (1680) wifi_init: tcpip mbox: 32

I (1680) wifi_init: udp mbox: 6

I (1690) wifi_init: tcp mbox: 6

I (1690) wifi_init: tcp tx win: 5760

I (1690) wifi_init: tcp rx win: 5760

I (1700) wifi_init: tcp mss: 1440

I (1710) wifi:mode : softAP (94:54:c5:38:c4:39)

I (1720) wifi:Total power save buffer number: 16

I (1720) wifi:Init max length of beacon: 752/752

I (1720) wifi:Init max length of beacon: 752/752

I (1730) esp_netif_lwip: DHCP server started on interface WIFI_AP_DEF with IP: 192.168.4.1

I (1730) DNS_SERVER: DNS server started on port 53

I (1740) mdns_mem: mDNS task will be created from internal RAM

I (1740) WEBSERVER: SoftAP ready. SSID: sc.local, Channel: 6, Password: password

I (1760) WEBSERVER: Access at: http://sc.local or http://sc.local.local or http://192.168.4.1

I (1760) WEBSERVER: AP LAUNCHED

I (1760) WEBSERVER: STARTING HTTP

I (1770) WEBSERVER: HTTP server started successfully

I (1770) WEBSERVER: Registered URI handler: /

I (1780) WEBSERVER: Registered URI handler: /get

I (1780) WEBSERVER: Registered URI handler: /post

I (1790) WEBSERVER: Registered URI handler: /log

I (1790) WEBSERVER: Registered URI handler: /ota

I (1800) WEBSERVER: Registered URI handler: /*

I (1800) WEBSERVER: Webserver initialization complete

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

I (2110) wifi:new:<6,1>, old:<6,1>, ap:<6,1>, sta:<255,255>, prof:6, snd_ch_cfg:0x0

I (2110) wifi:station: 84:5c:f3:b4:49:ed join, AID=1, bgn, 40U

E rmt: hw buffer too small, received symbols truncated

I (2170) WEBSERVER: Station connected, AID=1

I (2210) esp_netif_lwip: DHCP server assigned IP to a client, IP is: 192.168.4.2

I (2670) wifi:<ba-add>idx:2 (ifx:1, 84:5c:f3:b4:49:ed), tid:0, ssn:23, winSize:64

E rmt: hw buffer too small, received symbols truncated






> 





> W (3320) httpd_txrx: httpd_resp_send_err: 404 Not Found - Nothing matches the given URI

W (3420) httpd_txrx: httpd_resp_send_err: 404 Not Found - Nothing matches the given URI

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

I (4570) BT_HID: Found 0 HID device(s)

I (4570) BT_HID: No HID devices found, retrying in 2000ms...

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated






> 





> E rmt: hw buffer too small, received symbols truncated

I (6570) BT_HID: Scanning for HID devices (3s)...

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated






> 





> I (9580) BT_HID: Found 0 HID device(s)

I (9580) BT_HID: No HID devices found, retrying in 2000ms...

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

W (11560) httpd_txrx: httpd_resp_send_err: 404 Not Found - Nothing matches the given URI

I (11580) BT_HID: Scanning for HID devices (3s)...

W (11600) httpd_txrx: httpd_resp_send_err: 404 Not Found - Nothing matches the given URI

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated






> 





> E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

I (14600) BT_HID: Found 0 HID device(s)

I (14600) BT_HID: No HID devices found, retrying in 2000ms...

E rmt: hw buffer too small, received symbols truncated






> 





> E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

I (16600) BT_HID: Scanning for HID devices (3s)...

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated






> 





> 
    Boot complete.

Multi-cycle mode: 30 cycles × 120s = ~60 min

[INIT] Syncing device RTC to host time (1773161170)...
POST: {"time": 1773161170}




I (19210) COMMS: Setting time to 1773161170

I (19210) ALARM: SET FOR 1773161828 (in 658 s)

I (19210) STORAGE: Wrote; Tail/Head are now 16384/131093

{

	"status":	"ok",

	"params_updated":	0,

	"params_failed":	0,

	"cmd_executed":	false

}



> 





>        Accepted.

[INIT] Baseline RTCDEBUG:
RTCDEBUG




=== RTC DEBUG ===

  reset_reason:      POWER_ON (1)

  wakeup_cause:      UNDEFINED (normal boot/reset) (0)

  slow_clk_src:      NOT XTAL32K — check crystal! (0)



  rtc_set:           true

  current_time:      1773161170  (2026-03-10 16:46:10 UTC)

  rtc_backup_s:      1773161170  (2026-03-10 16:46:10 UTC)

  rtc_sleep_entry_s: 0  (N/A UTC)

  next_alarm_s:      1773161828  (2026-03-10 16:57:08 UTC)



  uptime:            18s

  clock_offset:      1773161152s  (current - uptime; stable = good)

  sleep_add:         0s  (added to entry_s on this boot, 0 if no sleep)
=================





> 





> I (19610) BT_HID: Found 0 HID device(s)

I (19610) BT_HID: No HID devices found, retrying in 2000ms...

W (19850) httpd_txrx: httpd_resp_send_err: 404 Not Found - Nothing matches the given URI

W (19900) httpd_txrx: httpd_resp_send_err: 404 Not Found - Nothing matches the given URI

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

I (21610) BT_HID: Scanning for HID devices (3s)...

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

Traceback (most recent call last):
  File "C:\data\stockcropper-sw\SC-F001\logtool\rtc_test.py", line 510, in <module>
    main()
    ~~~~^^
  File "C:\data\stockcropper-sw\SC-F001\logtool\rtc_test.py", line 504, in main
    ok = run_multi_cycle(ser, args.port, args.cycles, args.boot_timeout)
  File "C:\data\stockcropper-sw\SC-F001\logtool\rtc_test.py", line 288, in run_multi_cycle
    baseline_raw     = send_cmd(ser, "RTCDEBUG", timeout=5.0)
  File "C:\data\stockcropper-sw\SC-F001\logtool\rtc_test.py", line 98, in send_cmd
    return _read_until_prompt(ser, timeout, nudge=False)
  File "C:\data\stockcropper-sw\SC-F001\logtool\rtc_test.py", line 84, in _read_until_prompt
    raise TimeoutError(
        f"Device prompt not seen within {timeout}s.\nOutput so far:\n{buf}"
    )
TimeoutError: Device prompt not seen within 5.0s.
Output so far:
RTCDEBUG




=== RTC DEBUG ===

  reset_reason:      POWER_ON (1)

  wakeup_cause:      UNDEFINED (normal boot/reset) (0)

  slow_clk_src:      NOT XTAL32K <20> check crystal! (0)



  rtc_set:           true

  current_time:      1773161170  (2026-03-10 16:46:10 UTC)

  rtc_backup_s:      1773161170  (2026-03-10 16:46:10 UTC)

  rtc_sleep_entry_s: 0  (N/A UTC)

  next_alarm_s:      1773161828  (2026-03-10 16:57:08 UTC)



  uptime:            18s

  clock_offset:      1773161152s  (current - uptime; stable = good)

  sleep_add:         0s  (added to entry_s on this boot, 0 if no sleep)
=================





> 





> I (19610) BT_HID: Found 0 HID device(s)

I (19610) BT_HID: No HID devices found, retrying in 2000ms...

W (19850) httpd_txrx: httpd_resp_send_err: 404 Not Found - Nothing matches the given URI

W (19900) httpd_txrx: httpd_resp_send_err: 404 Not Found - Nothing matches the given URI

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

I (21610) BT_HID: Scanning for HID devices (3s)...

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated

E rmt: hw buffer too small, received symbols truncated