search

atanisoft / ESP32CommandStation

An ESP32 based DCC Command Station with integrated OpenLCB (LCC) --- NOTE: this project is not under active development.
https://atanisoft.github.io/ESP32CommandStation/
GNU General Public License v3.0
90 stars 34 forks source link

Prioritized DCC Packet support #85

Closed atanisoft closed 3 years ago

atanisoft commented 3 years ago

This shifts the DCC signal generator to use a prioritized queue for packet generation. If a locomotive has an update it will be scheduled ahead of any background refresh packets. Similarly when an e-stop request has been received it will take highest priority and will be continually broadcast until cleared (click button on web interface again, clear via UWT-100 throttle or similar).

roadsnail commented 3 years ago

Tried this and I see a problem with my ESP32 not connecting to my AP and serial monitor does not show successful startup. Reverted to an older build which connected fine to AP and startup is fine (see following serial log for working build)/startup

ESP32 Command Station v1.5.0 (v1.5.0-beta1-2-gb28a0f2) starting up... Compiled on Oct 12 2020 17:26:29 using IDF v4.0.1-dirty Running from: ota_0 ESP32 Command Station uses the OpenMRN library Copyright (c) 2019-2020, OpenMRN All rights reserved. [NVS] Initializing NVS [TimeZone] UTC0 [ADC] Configure 12-bit ADC resolution E (785) sdmmc_sd: sdmmc_init_sd_if_cond: send_if_cond (1) returned 0x108 ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x108 (ESP_ERR_INVALID_RESPONSE) at 0x40090847 file: "../components/Configuration/FileSystemManager.cpp" line 132 func: FileSystemManager::FileSystemManager() expression: esp_vfs_fat_sdmmc_mount(VFS_MOUNT, &sd_host, &sd_slot, &sdcfg, &sd) [FS] SD Card not present or mounting failed, using SPIFFS [FS] SPIFFS usage: 17.65/757.66 KiB [FS] SPIFFS will be used for persistent storage. [FS] Dumping content of filesystem: /cfg [FS] /cfg/LCC/cdi.xml (8184 bytes) mtime: Thu Jan 1 00:00:00 1970 [FS] /cfg/LCC/train.xml (5406 bytes) mtime: Thu Jan 1 00:00:01 1970 [FS] /cfg/LCC/tmptrain.xml (2593 bytes) mtime: Thu Jan 1 00:00:02 1970 [FS] /cfg/LCC/config (485 bytes) mtime: Wed Dec 31 23:59:59 1969 [LCC] Initializing Stack (node-id: 5020103f000) [WiFi] Starting WiFiManager [Turnout] Initializing DCC Turnout database [FS] /cfg/ESP32CS/turnouts.json does not exist, returning blank json object [Turnout] Loaded 0 DCC turnout(s) [Config] Enabling GPIO Outputs [Output] Initializing outputs [FS] /cfg/ESP32CS/outputs.json does not exist, returning blank json object [Output] Loaded 0 outputs [Config] Enabling GPIO Inputs [Sensors] Initializing sensors [FS] /cfg/ESP32CS/sensors.json does not exist, returning blank json object [Sensors] Loaded 0 sensors [Track] Registering /dev/track VFS interface [OPS] Configuring H-Bridge (L298 2000 mA max) using ADC 1:0 [OPS] Short limit 3686/4096 (1799.80 mA), events (on: 0, off: 0) [OPS] Shutdown limit 4080/4096 (1992.19 mA), events (on: 0, off: 0) [PROG] Configuring H-Bridge (L298 2000 mA max) using ADC 1:3 [PROG] Short limit 512/4096 (250.00 mA), events (on: 0, off: 0) [PROG] Shutdown limit 1024/4096 (500.00 mA), events (on: 0, off: 0) [PROG] Prog ACK: 122/4096 ( 59.57 mA) [Track] Registering LCC EventConsumer for Track Power (On:10000000000fffe, Off:10000000000ffff) [OPS] DCC config: zero:96uS, one:58uS, preamble-bits:11, wave:high,low [eStop] Registering emergency stop handler (On: 10000000000fffd, Off:10000000000fffc) [OPS] signal pin: 19, RMT(ch:0,mem:69[2],clk-div:80,clk-src:APB) [Track] Connecting track interface (track:OPS, fd:0) [OPS] Starting signal generator [Track] Connecting track interface (track:PROG, fd:3) [PROG] DCC config: zero:96uS, one:58uS, preamble-bits:22, wave:high,low [PROG] signal pin: 18, RMT(ch:3,mem:80[2],clk-div:80,clk-src:APB) [CDI] Checking /cfg/LCC/cdi.xml... [PROG] Starting signal generator [CDI] File /cfg/LCC/cdi.xml appears up-to-date (len 8184 vs 8184) [CDI] Registering CDI with stack... [LCC] Config file opened using fd:6 [CDI] Checking /cfg/LCC/train.xml... [CDI] File /cfg/LCC/train.xml appears up-to-date (len 5406 vs 5406) [CDI] Checking /cfg/LCC/tmptrain.xml... [CDI] File /cfg/LCC/tmptrain.xml appears up-to-date (len 2593 vs 2593) [TrainDB] Initializing... [TrainDB] Found 0 persistent roster entries.

ESP32 Command Station Startup complete!

[WiFi] Starting WiFi Manager task [WiFi] Starting TCP/IP stack [WiFi] Initializing WiFi stack [WiFi] Configuring Station (SSID: msshnot_2) [WiFi] Starting WiFi stack [WiFi] [1/36] Waiting for SSID connection. [WiFi] Setting ESP32 hostname to "esp32cs_5020103f000". [WiFi] MAC Address: 3c:71:bf:4d:7d:2c [DHCP] Starting DHCP Client. [WiFi] Setting TX power to: 78 [WiFi] Station started, attempting to connect to SSID: msshnot_2. Allocating new alias B89 for node 05020103f000 [WiFi] Connected to SSID: msshnot_2 [IPv4] [2/36] Waiting for IP address assignment. [WiFi] IP address is 192.168.20.11, starting hub (if enabled) and uplink [mDNS] Initializing mDNS system [mDNS] Setting mDNS hostname to "esp32cs_5020103f000" [httpd] Starting HTTP listener on port 80 [JMRI] Starting JMRI listener Listening on port 80, fd 48 Listening on port 2560, fd 49 [mDNS] Advertising _http._tcp:80. [mDNS] Advertising _esp32cs._tcp:2560. [TaskMon] uptime: 00:00:57 freeHeap: 180008, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB [TaskMon] uptime: 00:01:42 freeHeap: 180156, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB

Next I rebuilt #85, and loaded onto test system. This does not appear to startup and go on to complete WiFi Manager task... see following serial log

ESP32 Command Station v1.5.0 (v1.5.0-beta1-5-gfa13ad9) starting up... Compiled on Oct 12 2020 17:51:26 using IDF v4.0.1-dirty Running from: ota_0 ESP32 Command Station uses the OpenMRN library Copyright (c) 2019-2020, OpenMRN All rights reserved. [NVS] Initializing NVS [TimeZone] UTC0 [ADC] Configure 12-bit ADC resolution E (785) sdmmc_sd: sdmmc_init_sd_if_cond: send_if_cond (1) returned 0x108 ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x108 (ESP_ERR_INVALID_RESPONSE) at 0x40090847 file: "../components/Configuration/FileSystemManager.cpp" line 132 func: FileSystemManager::FileSystemManager() expression: esp_vfs_fat_sdmmc_mount(VFS_MOUNT, &sd_host, &sd_slot, &sdcfg, &sd) [FS] SD Card not present or mounting failed, using SPIFFS [FS] SPIFFS usage: 18.14/757.66 KiB [FS] SPIFFS will be used for persistent storage. [FS] Dumping content of filesystem: /cfg [FS] /cfg/LCC/cdi.xml (8184 bytes) mtime: Thu Jan 1 00:00:00 1970 [FS] /cfg/LCC/train.xml (5406 bytes) mtime: Thu Jan 1 00:00:01 1970 [FS] /cfg/LCC/tmptrain.xml (2593 bytes) mtime: Thu Jan 1 00:00:02 1970 [FS] /cfg/LCC/config (485 bytes) mtime: Wed Dec 31 23:59:59 1969 [FS] /cfg/ESP32CS/trains.json (213 bytes) mtime: Thu Jan 1 00:07:34 1970 [LCC] Initializing Stack (node-id: 5020103f000) [WiFi] Starting WiFiManager [Turnout] Initializing DCC Turnout database [FS] /cfg/ESP32CS/turnouts.json does not exist, returning blank json object [Turnout] Loaded 0 DCC turnout(s) [Config] Enabling GPIO Outputs [Output] Initializing outputs [FS] /cfg/ESP32CS/outputs.json does not exist, returning blank json object [Output] Loaded 0 outputs [Config] Enabling GPIO Inputs [Sensors] Initializing sensors [FS] /cfg/ESP32CS/sensors.json does not exist, returning blank json object [Sensors] Loaded 0 sensors [Track] Registering /dev/track VFS interface [OPS] Configuring H-Bridge (L298 2000 mA max) using ADC 1:0 [OPS] Short limit 3686/4096 (1799.80 mA), events (on: 0, off: 0) [OPS] Shutdown limit 4080/4096 (1992.19 mA), events (on: 0, off: 0) [PROG] Configuring H-Bridge (L298 2000 mA max) using ADC 1:3 [PROG] Short limit 512/4096 (250.00 mA), events (on: 0, off: 0) [PROG] Shutdown limit 1024/4096 (500.00 mA), events (on: 0, off: 0) [PROG] Prog ACK: 122/4096 ( 59.57 mA) [OPS] DCC config: zero:96uS, one:58uS, preamble-bits:11, wave:high,low [OPS] signal pin: 19, RMT(ch:0,mem:69[2],clk-div:80,clk-src:APB) [OPS] Starting signal generator [PROG] DCC config: zero:96uS, one:58uS, preamble-bits:22, wave:high,low [PROG] signal pin: 18, RMT(ch:3,mem:80[2],clk-div:80,clk-src:APB) [PROG] Starting signal generator

roadsnail commented 3 years ago

@atanisoft. Have built 6221911 (pulled latest changes to my local build directory, then ran idf.py build) and loaded onto my test system. My Serial log shows that WiFi is now initialised (which it didn't with my last test), however, I then see a Core 0 panic (see serial log below) and ESP32 goes into a loop, initialising, then panicing.

Tried erasing flash (idf.py erase_flash), probably unnecessary, and reloading, but results are the same.

ets Jun 8 2016 00:22:57

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:0x3fff0018,len:4 load:0x3fff001c,len:4540 load:0x40078000,len:12132 load:0x40080400,len:3524 entry 0x40080640

ESP32 Command Station v1.5.0 (v1.5.0-beta1-7-g6221911) starting up... Compiled on Oct 13 2020 11:50:45 using IDF v4.0.1-dirty Running from: ota_0 ESP32 Command Station uses the OpenMRN library Copyright (c) 2019-2020, OpenMRN All rights reserved. [NVS] Initializing NVS [TimeZone] UTC0 [ADC] Configure 12-bit ADC resolution E (782) sdmmc_sd: sdmmc_init_sd_if_cond: send_if_cond (1) returned 0x108 ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x108 (ESP_ERR_INVALID_RESPONSE) at 0x40090847 file: "../components/Configuration/FileSystemManager.cpp" line 132 func: FileSystemManager::FileSystemManager() expression: esp_vfs_fat_sdmmc_mount(VFS_MOUNT, &sd_host, &sd_slot, &sdcfg, &sd) [FS] SD Card not present or mounting failed, using SPIFFS [FS] SPIFFS usage: 0.00/757.66 KiB [FS] SPIFFS will be used for persistent storage. [FS] Dumping content of filesystem: /cfg [LCC] Corrupt/missing configuration file detected, /cfg/LCC/config is not the expected size: 4294967295 vs 485 bytes. [LCC] Initializing Stack (node-id: 5020103f000) [WiFi] Starting WiFiManager [Turnout] Initializing DCC Turnout database [FS] /cfg/ESP32CS/turnouts.json does not exist, returning blank json object [Turnout] Loaded 0 DCC turnout(s) [Config] Enabling GPIO Outputs [Output] Initializing outputs [FS] /cfg/ESP32CS/outputs.json does not exist, returning blank json object [Output] Loaded 0 outputs [Config] Enabling GPIO Inputs [Sensors] Initializing sensors [FS] /cfg/ESP32CS/sensors.json does not exist, returning blank json object [Sensors] Loaded 0 sensors [Track] Registering /dev/track VFS interface [OPS] Configuring H-Bridge (L298 2000 mA max) using ADC 1:0 [OPS] Short limit 3686/4096 (1799.80 mA), events (on: 0, off: 0) [OPS] Shutdown limit 4080/4096 (1992.19 mA), events (on: 0, off: 0) [PROG] Configuring H-Bridge (L298 2000 mA max) using ADC 1:3 [PROG] Short limit 512/4096 (250.00 mA), events (on: 0, off: 0) [PROG] Shutdown limit 1024/4096 (500.00 mA), events (on: 0, off: 0) [PROG] Prog ACK: 122/4096 ( 59.57 mA) [OPS] DCC config: zero:96uS, one:58uS, preamble-bits:11, wave:high,low [OPS] signal pin: 19, RMT(ch:0,mem:69[2],clk-div:80,clk-src:APB) [OPS] Starting signal generator [PROG] DCC config: zero:96uS, one:58uS, preamble-bits:22, wave:high,low [PROG] signal pin: 18, RMT(ch:3,mem:80[2],clk-div:80,clk-src:APB) [PROG] Starting signal generator [Track] Registering LCC EventConsumer for Track Power (On:10000000000fffe, Off:10000000000ffff) [eStop] Registering emergency stop handler (On: 10000000000fffd, Off:10000000000fffc) [Track] Connecting track interface (track:OPS, fd:0) [Track] Connecting track interface (track:PROG, fd:3) [CDI] Checking /cfg/LCC/cdi.xml... [CDI] File /cfg/LCC/cdi.xml does not exist [CDI] Updating /cfg/LCC/cdi.xml (len 8184) [CDI] Registering CDI with stack... Creating config file /cfg/LCC/config [LCC] MonitoredHBridge(PROG) factory_reset(6) invoked, defaulting configuration [LCC] MonitoredHBridge(OPS) factory_reset(6) invoked, defaulting configuration [LCC] ESP32 Command Station factory_reset(6) triggered. [LCC] Config file opened using fd:6 [CDI] Checking /cfg/LCC/train.xml... [CDI] File /cfg/LCC/train.xml does not exist [CDI] Updating /cfg/LCC/train.xml (len 5406) [CDI] Checking /cfg/LCC/tmptrain.xml... [CDI] File /cfg/LCC/tmptrain.xml does not exist [CDI] Updating /cfg/LCC/tmptrain.xml (len 2593) [TrainDB] Initializing... [TrainDB] Found 0 persistent roster entries.

ESP32 Command Station Startup complete!

[WiFi] Starting WiFi Manager task [WiFi] Starting TCP/IP stack [WiFi] Initializing WiFi stack [WiFi] Configuring Station (SSID: msshnot_2) [WiFi] Starting WiFi stack [WiFi] [1/36] Waiting for SSID connection. [WiFi] Setting ESP32 hostname to "esp32cs_5020103f000". [WiFi] MAC Address: 3c:71:bf:4d:7d:2c [DHCP] Starting DHCP Client. [WiFi] Setting TX power to: 78 [WiFi] Station started, attempting to connect to SSID: msshnot_2. Allocating new alias B89 for node 05020103f000 [WiFi] Connected to SSID: msshnot_2 [IPv4] [2/36] Waiting for IP address assignment. [WiFi] IP address is 192.168.20.11, starting hub (if enabled) and uplink [mDNS] Initializing mDNS system [mDNS] Setting mDNS hostname to "esp32cs_5020103f000" [httpd] Starting HTTP listener on port 80 [JMRI] Starting JMRI listener Listening on port 80, fd 48 Listening on port 2560, fd 49 [mDNS] Advertising _http._tcp:80. [mDNS] Advertising _esp32cs._tcp:2560. Incoming connection from 192.168.211.95, fd 50. [JMRI 192.168.211.95/50] Connected [DCC++ loco 48] Set function 1 to 0 [DCC++ loco 48] Set function 2 to 0 [DCC++ loco 48] Set function 3 to 0 [DCC++ loco 48] Set function 4 to 0 Allocating new alias 066 for node 060100000030 Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled. Core 0 register dump: PC : 0x400fa831 PS : 0x00060030 A0 : 0x8011b698 A1 : 0x3ffbf510
A2 : 0x3ffcb284 A3 : 0x3ffcb314 A4 : 0x00000000 A5 : 0x00000000
A6 : 0x00000000 A7 : 0x00000000 A8 : 0x00000000 A9 : 0x0114cbcc
A10 : 0xbaad5678 A11 : 0x00000000 A12 : 0x3ffcb214 A13 : 0x3ffcb2e4
A14 : 0xbaad5678 A15 : 0x3ffcb2e4 SAR : 0x00000010 EXCCAUSE: 0x0000001c
EXCVADDR: 0xbaad5678 LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0xffffffff

ELF file SHA256: 76c49db6c7f89de4

Backtrace: 0x400fa82e:0x3ffbf510 0x4011b695:0x3ffbf560 0x4011b4a1:0x3ffbf590 0x400d9ae5:0x3ffbf5c0 0x400d36d8:0x3ffbfcd0

atanisoft commented 3 years ago

@roadsnail can you capture the console via idf.py monitor so it will decode the backtrace? I'll try and reproduce it in the meantime.

EDIT: I've observed some crashes in the new code but not yet narrowed down the cause.

roadsnail commented 3 years ago

@atanisoft I'll try run monitor later but other commitments may get in the way.

roadsnail commented 3 years ago

Managed to grab a quick monitor...

I noticed that the CS didn't want to re-connect to my AP. My AP reported that the CS was connected, but it wasn't! So forced a reconnect on AP, then reset CS and captured the following. In summary, CS connects to AP okay. Then I fired up JMRI and it connects to CS.

Then I switched power onto the track. Next turned loco lights off/on and Panic happens. CS reboots and struggles to reconnect to AP.

Anyhow, monitor follows:-

ESP32 Command Station v1.5.0 (v1.5.0-beta1-7-g6221911) starting up... Compiled on Oct 13 2020 11:50:45 using IDF v4.0.1-dirty Running from: ota_0 ESP32 Command Station uses the OpenMRN library Copyright (c) 2019-2020, OpenMRN All rights reserved. [NVS] Initializing NVS [TimeZone] UTC0 [ADC] Configure 12-bit ADC resolution E (785) sdmmc_sd: sdmmc_init_sd_if_cond: send_if_cond (1) returned 0x108 ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x108 (ESP_ERR_INVALID_RESPONSE) at 0x40090847 0x40090847: _esp_error_check_failed_without_abort at C:/Users/chris/Desktop/esp-idf/components/esp32/panic.c:721

file: "../components/Configuration/FileSystemManager.cpp" line 132 func: FileSystemManager::FileSystemManager() expression: esp_vfs_fat_sdmmc_mount(VFS_MOUNT, &sd_host, &sd_slot, &sdcfg, &sd) [FS] SD Card not present or mounting failed, using SPIFFS [FS] SPIFFS usage: 17.65/757.66 KiB [FS] SPIFFS will be used for persistent storage. [FS] Dumping content of filesystem: /cfg [FS] /cfg/LCC/cdi.xml (8184 bytes) mtime: Thu Jan 1 00:00:08 1970 [FS] /cfg/LCC/train.xml (5406 bytes) mtime: Thu Jan 1 00:00:09 1970 [FS] /cfg/LCC/tmptrain.xml (2593 bytes) mtime: Thu Jan 1 00:00:10 1970 [FS] /cfg/LCC/config (485 bytes) mtime: Wed Dec 31 23:59:59 1969 [LCC] Initializing Stack (node-id: 5020103f000) [WiFi] Starting WiFiManager [Turnout] Initializing DCC Turnout database [FS] /cfg/ESP32CS/turnouts.json does not exist, returning blank json object [Turnout] Loaded 0 DCC turnout(s) [Config] Enabling GPIO Outputs [Output] Initializing outputs [FS] /cfg/ESP32CS/outputs.json does not exist, returning blank json object [Output] Loaded 0 outputs [Config] Enabling GPIO Inputs [Sensors] Initializing sensors [FS] /cfg/ESP32CS/sensors.json does not exist, returning blank json object [Sensors] Loaded 0 sensors [Track] Registering /dev/track VFS interface [OPS] Configuring H-Bridge (L298 2000 mA max) using ADC 1:0 [OPS] Short limit 3686/4096 (1799.80 mA), events (on: 0, off: 0) [OPS] Shutdown limit 4080/4096 (1992.19 mA), events (on: 0, off: 0) [PROG] Configuring H-Bridge (L298 2000 mA max) using ADC 1:3 [PROG] Short limit 512/4096 (250.00 mA), events (on: 0, off: 0) [PROG] Shutdown limit 1024/4096 (500.00 mA), events (on: 0, off: 0) [PROG] Prog ACK: 122/4096 ( 59.57 mA) [OPS] DCC config: zero:96uS, one:58uS, preamble-bits:11, wave:high,low [OPS] signal pin: 19, RMT(ch:0,mem:69[2],clk-div:80,clk-src:APB) [OPS] Starting signal generator [PROG] DCC config: zero:96uS, one:58uS, preamble-bits:22, wave:high,low [PROG] signal pin: 18, RMT(ch:3,mem:80[2],clk-div:80,clk-src:APB) [PROG] Starting signal generator [Track] Registering LCC EventConsumer for Track Power (On:10000000000fffe, Off:10000000000ffff) [eStop] Registering emergency stop handler (On: 10000000000fffd, Off:10000000000fffc) [Track] Connecting track interface (track:OPS, fd:0) [Track] Connecting track interface (track:PROG, fd:3) [CDI] Checking /cfg/LCC/cdi.xml... [CDI] File /cfg/LCC/cdi.xml appears up-to-date (len 8184 vs 8184) [CDI] Registering CDI with stack... [LCC] Config file opened using fd:6 [CDI] Checking /cfg/LCC/train.xml... [CDI] File /cfg/LCC/train.xml appears up-to-date (len 5406 vs 5406) [CDI] Checking /cfg/LCC/tmptrain.xml... [CDI] File /cfg/LCC/tmptrain.xml appears up-to-date (len 2593 vs 2593) [TrainDB] Initializing... [TrainDB] Found 0 persistent roster entries.

ESP32 Command Station Startup complete!

[WiFi] Starting WiFi Manager task [WiFi] Starting TCP/IP stack [WiFi] Initializing WiFi stack [WiFi] Configuring Station (SSID: msshnot_2) [WiFi] Starting WiFi stack [WiFi] [1/36] Waiting for SSID connection. [WiFi] Setting ESP32 hostname to "esp32cs_5020103f000". [WiFi] MAC Address: 3c:71:bf:4d:7d:2c [DHCP] Starting DHCP Client. [WiFi] Setting TX power to: 78 [WiFi] Station started, attempting to connect to SSID: msshnot_2. Allocating new alias B89 for node 05020103f000 [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:2). [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] Connected to SSID: msshnot_2 [IPv4] [2/36] Waiting for IP address assignment. [WiFi] IP address is 192.168.20.11, starting hub (if enabled) and uplink [mDNS] Initializing mDNS system [mDNS] Setting mDNS hostname to "esp32cs_5020103f000" [httpd] Starting HTTP listener on port 80 [JMRI] Starting JMRI listener Listening on port 80, fd 48 Listening on port 2560, fd 49 [mDNS] Advertising _http._tcp:80. [mDNS] Advertising _esp32cs._tcp:2560. Incoming connection from 192.168.211.95, fd 50. [JMRI 192.168.211.95/50] Connected No command handler for [#] [Track] Enabling track output: OPS [OPS] 0.00 mA / 2000 mA [TaskMon] uptime: 00:00:47 freeHeap: 176184, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB [Track] Disabling track output: OPS (if enabled) [Track] Disabling track output: PROG (if enabled) [TaskMon] uptime: 00:01:32 freeHeap: 177784, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB [TaskMon] uptime: 00:02:18 freeHeap: 176192, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB [Track] Enabling track output: OPS [OPS] 0.00 mA / 2000 mA [Track] Disabling track output: OPS (if enabled) [Track] Disabling track output: PROG (if enabled) [TaskMon] uptime: 00:03:03 freeHeap: 177784, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB [DCC++ loco 48] Set function 1 to 0 [DCC++ loco 48] Set function 2 to 0 [DCC++ loco 48] Set function 3 to 0 [DCC++ loco 48] Set function 4 to 0 Allocating new alias 066 for node 060100000030 Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled. Core 0 register dump: PC : 0x400fa831 PS : 0x00060930 A0 : 0x8011b698 A1 : 0x3ffbf510 0x400fa831: os_mutex_lock at c:\users\chris\documents\arduino\esp32commandstation\build/../components/OpenMRNLite/src/os/os.h:551 (inlined by) esp32cs::RMTTrackDevice::RMTTrackDevice(char const, rmt_channel_t, unsigned char, unsigned int, gpio_num_t, RailcomDriver) at c:\users\chris\documents\arduino\esp32commandstation\build/../components/DCCSignalGenerator/RMTTrackDevice.cpp:245

A2 : 0x3ffcb3cc A3 : 0x3ffcb45c A4 : 0x00000000 A5 : 0x00000000 A6 : 0x00000000 A7 : 0x00000000 A8 : 0x00000000 A9 : 0x0b3c8b4e A10 : 0xbaad5678 A11 : 0x00000000 A12 : 0x3ffcb35c A13 : 0x3ffcb42c A14 : 0xbaad5678 A15 : 0x3ffcb42c SAR : 0x00000010 EXCCAUSE: 0x0000001c EXCVADDR: 0xbaad5678 LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0xffffffff

ELF file SHA256: 76c49db6c7f89de4

Backtrace: 0x400fa82e:0x3ffbf510 0x4011b695:0x3ffbf560 0x4011b4a1:0x3ffbf590 0x400d9ae5:0x3ffbf5c0 0x400d36d8:0x3ffbfcd0 0x400fa82e: os_mutex_lock at c:\users\chris\documents\arduino\esp32commandstation\build/../components/OpenMRNLite/src/os/os.h:551 (inlined by) esp32cs::RMTTrackDevice::RMTTrackDevice(char const, rmt_channel_t, unsigned char, unsigned int, gpio_num_t, RailcomDriver) at c:\users\chris\documents\arduino\esp32commandstation\build/../components/DCCSignalGenerator/RMTTrackDevice.cpp:245

0x4011b695: Timer::~Timer() at c:\users\chris\documents\arduino\esp32commandstation\build/../components/OpenMRNLite/src/executor/Timer.cpp:39

0x4011b4a1: StateFlowWithQueue::notify() at c:\users\chris\documents\arduino\esp32commandstation\build/../components/OpenMRNLite/src/executor/StateFlow.cpp:111

0x400d9ae5: app_main at c:\users\chris\documents\arduino\esp32commandstation\build/../main/ESP32CommandStation.cpp:370 (discriminator 1)

0x400d36d8: esp_crosscore_int_init at C:/Users/chris/Desktop/esp-idf/components/esp32/crosscore_int.c:83

Rebooting... ets Jun 8 2016 00:22:57

rst:0xc (SW_CPU_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:0x3fff0018,len:4 load:0x3fff001c,len:4540 load:0x40078000,len:12132 load:0x40080400,len:3524 entry 0x40080640

ESP32 Command Station v1.5.0 (v1.5.0-beta1-7-g6221911) starting up... Compiled on Oct 13 2020 11:50:45 using IDF v4.0.1-dirty Running from: ota_0 ESP32 Command Station uses the OpenMRN library Copyright (c) 2019-2020, OpenMRN All rights reserved. [NVS] Initializing NVS [TimeZone] UTC0 [ADC] Configure 12-bit ADC resolution E (786) sdmmc_sd: sdmmc_init_sd_if_cond: send_if_cond (1) returned 0x108 ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x108 (ESP_ERR_INVALID_RESPONSE) at 0x40090847 0x40090847: _esp_error_check_failed_without_abort at C:/Users/chris/Desktop/esp-idf/components/esp32/panic.c:721

file: "../components/Configuration/FileSystemManager.cpp" line 132 func: FileSystemManager::FileSystemManager() expression: esp_vfs_fat_sdmmc_mount(VFS_MOUNT, &sd_host, &sd_slot, &sdcfg, &sd) [FS] SD Card not present or mounting failed, using SPIFFS [FS] SPIFFS usage: 17.65/757.66 KiB [FS] SPIFFS will be used for persistent storage. [FS] Dumping content of filesystem: /cfg [FS] /cfg/LCC/cdi.xml (8184 bytes) mtime: Thu Jan 1 00:00:08 1970 [FS] /cfg/LCC/train.xml (5406 bytes) mtime: Thu Jan 1 00:00:09 1970 [FS] /cfg/LCC/tmptrain.xml (2593 bytes) mtime: Thu Jan 1 00:00:10 1970 [FS] /cfg/LCC/config (485 bytes) mtime: Wed Dec 31 23:59:59 1969 [LCC] Initializing Stack (node-id: 5020103f000) [WiFi] Starting WiFiManager [Turnout] Initializing DCC Turnout database [FS] /cfg/ESP32CS/turnouts.json does not exist, returning blank json object [Turnout] Loaded 0 DCC turnout(s) [Config] Enabling GPIO Outputs [Output] Initializing outputs [FS] /cfg/ESP32CS/outputs.json does not exist, returning blank json object [Output] Loaded 0 outputs [Config] Enabling GPIO Inputs [Sensors] Initializing sensors [FS] /cfg/ESP32CS/sensors.json does not exist, returning blank json object [Sensors] Loaded 0 sensors [Track] Registering /dev/track VFS interface [OPS] Configuring H-Bridge (L298 2000 mA max) using ADC 1:0 [OPS] Short limit 3686/4096 (1799.80 mA), events (on: 0, off: 0) [OPS] Shutdown limit 4080/4096 (1992.19 mA), events (on: 0, off: 0) [PROG] Configuring H-Bridge (L298 2000 mA max) using ADC 1:3 [PROG] Short limit 512/4096 (250.00 mA), events (on: 0, off: 0) [PROG] Shutdown limit 1024/4096 (500.00 mA), events (on: 0, off: 0) [PROG] Prog ACK: 122/4096 ( 59.57 mA) [OPS] DCC config: zero:96uS, one:58uS, preamble-bits:11, wave:high,low [OPS] signal pin: 19, RMT(ch:0,mem:69[2],clk-div:80,clk-src:APB) [OPS] Starting signal generator [PROG] DCC config: zero:96uS, one:58uS, preamble-bits:22, wave:high,low [PROG] signal pin: 18, RMT(ch:3,mem:80[2],clk-div:80,clk-src:APB) [PROG] Starting signal generator [Track] Registering LCC EventConsumer for Track Power (On:10000000000fffe, Off:10000000000ffff) [eStop] Registering emergency stop handler (On: 10000000000fffd, Off:10000000000fffc) [Track] Connecting track interface (track:OPS, fd:0) [Track] Connecting track interface (track:PROG, fd:3) [CDI] Checking /cfg/LCC/cdi.xml... [CDI] File /cfg/LCC/cdi.xml appears up-to-date (len 8184 vs 8184) [CDI] Registering CDI with stack... [LCC] Config file opened using fd:6 [CDI] Checking /cfg/LCC/train.xml... [CDI] File /cfg/LCC/train.xml appears up-to-date (len 5406 vs 5406) [CDI] Checking /cfg/LCC/tmptrain.xml... [CDI] File /cfg/LCC/tmptrain.xml appears up-to-date (len 2593 vs 2593) [TrainDB] Initializing... [TrainDB] Found 0 persistent roster entries.

ESP32 Command Station Startup complete!

[WiFi] Starting WiFi Manager task [WiFi] Starting TCP/IP stack [WiFi] Initializing WiFi stack [WiFi] Configuring Station (SSID: msshnot_2) [WiFi] Starting WiFi stack [WiFi] [1/36] Waiting for SSID connection. [WiFi] Setting ESP32 hostname to "esp32cs_5020103f000". [WiFi] MAC Address: 3c:71:bf:4d:7d:2c [DHCP] Starting DHCP Client. [WiFi] Setting TX power to: 78 [WiFi] Station started, attempting to connect to SSID: msshnot_2. Allocating new alias B89 for node 05020103f000 [WiFi] Connected to SSID: msshnot_2 [IPv4] [2/36] Waiting for IP address assignment. [WiFi] Lost connection to SSID: msshnot_2 (reason:6) [WiFi] Attempting to reconnect to SSID: msshnot_2. [WiFi] [3/36] Waiting for SSID connection. [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:15). [WiFi] [4/36] Waiting for SSID connection. [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] [5/36] Waiting for SSID connection. [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:2). [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:205). [WiFi] [6/36] Waiting for SSID connection. [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] [7/36] Waiting for SSID connection. [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] [8/36] Waiting for SSID connection. [WiFi] Connection failed, reconnecting to SSID: msshnot_2 (reason:201). [WiFi] Connected to SSID: msshnot_2 [WiFi] IP address is 192.168.20.11, starting hub (if enabled) and uplink [mDNS] Initializing mDNS system [mDNS] Setting mDNS hostname to "esp32cs_5020103f000" [httpd] Starting HTTP listener on port 80 [JMRI] Starting JMRI listener Listening on port 80, fd 48 Listening on port 2560, fd 49 [mDNS] Advertising _http._tcp:80. [mDNS] Advertising _esp32cs._tcp:2560. [TaskMon] uptime: 00:00:45 freeHeap: 179648, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB

atanisoft commented 3 years ago

Guru Meditation Error: Core 0 panic'ed (LoadProhibited). Exception was unhandled. Core 0 register dump: PC : 0x400fa831 PS : 0x00060930 A0 : 0x8011b698 A1 : 0x3ffbf510 A2 : 0x3ffcb3cc A3 : 0x3ffcb45c A4 : 0x00000000 A5 : 0x00000000 A6 : 0x00000000 A7 : 0x00000000 A8 : 0x00000000 A9 : 0x0b3c8b4e A10 : 0xbaad5678 A11 : 0x00000000 A12 : 0x3ffcb35c A13 : 0x3ffcb42c A14 : 0xbaad5678 A15 : 0x3ffcb42c SAR : 0x00000010 EXCCAUSE: 0x0000001c EXCVADDR: 0xbaad5678 LBEG : 0x4000c2e0 LEND : 0x4000c2f6 LCOUNT : 0xffffffff

ELF file SHA256: 76c49db6c7f89de4

Backtrace: 0x400fa82e:0x3ffbf510 0x4011b695:0x3ffbf560 0x4011b4a1:0x3ffbf590 0x400d9ae5:0x3ffbf5c0 0x400d36d8:0x3ffbfcd0 0x400fa82e: os_mutex_lock at c:\users\chris\documents\arduino\esp32commandstation\build/../components/OpenMRNLite/src/os/os.h:551 (inlined by) esp32cs::RMTTrackDevice::RMTTrackDevice(char const, rmt_channel_t, unsigned char, unsigned int, gpio_num_t, RailcomDriver) at c:\users\chris\documents\arduino\esp32commandstation\build/../components/DCCSignalGenerator/RMTTrackDevice.cpp:245 0x4011b695: Timer::~Timer() at c:\users\chris\documents\arduino\esp32commandstation\build/../components/OpenMRNLite/src/executor/Timer.cpp:39 0x4011b4a1: StateFlowWithQueue::notify() at c:\users\chris\documents\arduino\esp32commandstation\build/../components/OpenMRNLite/src/executor/StateFlow.cpp:111 0x400d9ae5: app_main at c:\users\chris\documents\arduino\esp32commandstation\build/../main/ESP32CommandStation.cpp:370 (discriminator 1) 0x400d36d8: esp_crosscore_int_init at C:/Users/chris/Desktop/esp-idf/components/esp32/crosscore_int.c:83

Thanks for capturing this, it is odd though as the line that is being referenced doesn't match up to a call to os_mutex_lock. I'll do some more digging on this as it looks like there is some sort of corruption occurring somewhere.

Here is the crash that I'm seeing and working on resolving:

Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x400fa5bf  PS      : 0x00060b30  A0      : 0x8011bc44  A1      : 0x3ffbf380 
A2      : 0x3ffcbdb8  A3      : 0xbaad5678  A4      : 0x00000000  A5      : 0x00000000  
A6      : 0xffc8a0d0  A7      : 0x00000000  A8      : 0x00000000  A9      : 0x3ffbf350  
A10     : 0xbaad5678  A11     : 0x00000002  A12     : 0x3ffcbd64  A13     : 0x3ffcbe18  
A14     : 0xbaad5678  A15     : 0x3ffcbe18  SAR     : 0x00000010  EXCCAUSE: 0x0000001c  
EXCVADDR: 0xbaad5678  LBEG    : 0x40082745  LEND    : 0x4008274d  LCOUNT  : 0x00000026  

Backtrace:0x400fa5bc:0x3ffbf380 0x4011bc41:0x3ffbf3d0 0x4011ba4d:0x3ffbf400 0x400dcb7e:0x3ffbf430 0x4008ae18:0x3ffbfd10
0x400fa5bc: esp32cs::PrioritizedUpdateLoop::entry() at ESP32CommandStation/build/../components/DCCSignalGenerator/PrioritizedUpdateLoop.cpp:171
0x4011bc41: StateFlowBase::run() at ESP32CommandStation/build/../components/OpenMRNLite/src/executor/StateFlow.cpp:63 (discriminator 4)
0x4011ba4d: ExecutorBase::entry() at build/../components/OpenMRNLite/src/executor/Executor.cpp:324
0x400dcb7e: app_main at ESP32CommandStation/build/../components/OpenMRNLite/src/os/OS.hxx:99
 (inlined by) ?? at ESP32CommandStation/build/../components/OpenMRNLite/src/executor/Executor.hxx:345
 (inlined by) ?? at ESP32CommandStation/build/../components/OpenMRNLite/src/openlcb/SimpleStack.hxx:168
 (inlined by) app_main at ESP32CommandStation/build/../main/ESP32CommandStation.cpp:416
0x4008ae18: main_task at esp-idf-master/components/freertos/xtensa/port.c:535

This is an odd one as it appears to be timing related where the train has been allocated (but not fully?) and the update loop is trying to generate a packet for it. I haven't narrowed it down yet but will be working on it and see if I can reproduce the failure you see.

roadsnail commented 3 years ago

UPDATE.

Have tried 64d56fa and not seeing panics. However the connection to my AP is a problem. I'm seeing multiple retries connecting in the first place, then keeping a connection. My AP is reporting a very low signal strength which is odd. It may be an issue with my esp32 espduino board, so I'm checking some things at this end as and when time is available.

When I have a connection I am able to command loco, but wifi connection is very flaky and sometimes commands are laggy, but that may be down to wifi issues. More testing needed here.

ALSO - Currently building a softap build so that I can connect directly to the ESP32 from my laptop and JMRI. Will update when I know more...

FURTHER UPDATE:

My sofap build also suffers with very poor wifi connection with ESP32 almost next to laptop! So maybe I have issues with my espduino module? I may have to order up a spare to continue with testing. On the plus side, I am not seeing any panics with this build.

atanisoft commented 3 years ago

@roadsnail it sounds like some progress is being made. I've not seen the WiFi connection issues with any boards in a while. The only thing I can think of is after you did the erase_flash it somehow is defaulting to a lower TX power setting than the default. You can confirm this in the startup output by looking for [WiFi] Adjusting maximum WiFi TX power or [WiFi] Setting TX power to. If you do not see 78 or there is an error at the time these are printed I can try and give a fix for that.

roadsnail commented 3 years ago

Was wondering that... I see [WiFi] Setting TX power to: 78 in serial o/p at startup, so guess TX power is being set okay.

Checking signal strengths using Wifi Analyzer app on my phone I see about -75dBm on channels 6+10 for softap esp32cs with phone next to esp32. In comparison my nearest access point hovers between -45 to -50dBm

Will investigate more tomorrow if I can make time.

TrainzLuvr commented 3 years ago

Actually, I have also been having WiFi problems for a while now.

WiFi would stay on only when idle, most of the time. It would drop upon commands being issued, and commands woul also be laggy during times WiFi worked.

This goes back even before we added the TXpower option, so the issue has been around.

atanisoft commented 3 years ago

@TrainzLuvr thanks for confirming. It's possible that there is a bug in there somewhere but it is not clear yet where. The only thing I do know is the wifi task (idf side) is bound to one core and there is no option of having it float but there is on the TCP/IP side

TrainzLuvr commented 3 years ago

Could we have some extra logging added for this specific purpose, although the coredumps didn't work before, I'm not sure what would be the best way?

atanisoft commented 3 years ago

There is a flag to enable extra wifi logging in the sdkconfig. Though it would require a serial port to receive it. I'm not certain we can avoid that entirely

atanisoft commented 3 years ago

@TrainzLuvr @roadsnail Can you both test this update once more? I've identified an issue in the RMT code which is causing general performance issues of the rest of the CS (mostly in the TWAI driver though).

TrainzLuvr commented 3 years ago

Just to confirm, we are testing the "dcc" branch?

atanisoft commented 3 years ago

Just to confirm, we are testing the "dcc" branch?

Yup, once this has been confirmed I'll merge it down to master and do some further testing with the other two PRs that are pending.

TrainzLuvr commented 3 years ago 
../components/DCCSignalGenerator/RMTTrackDevice.cpp:404:27: error: macro "portYIELD_FROM_ISR" passed 1 arguments, but takes just 0
   portYIELD_FROM_ISR(woken);
                           ^
../components/DCCSignalGenerator/RMTTrackDevice.cpp: In constructor 'esp32cs::RMTTrackDevice::RMTTrackDevice(const char*, rmt_channel_t, uint8_t, size_t, gpio_num_t, RailcomDriver*)':
../components/DCCSignalGenerator/RMTTrackDevice.cpp:219:5: error: 'xQueueCreateStatic' was not declared in this scope
     xQueueCreateStatic(packet_queue_len, sizeof(dcc::Packet)
     ^~~~~~~~~~~~~~~~~~
../components/DCCSignalGenerator/RMTTrackDevice.cpp:219:5: note: suggested alternative: 'xQueueCreateSet'
     xQueueCreateStatic(packet_queue_len, sizeof(dcc::Packet)
     ^~~~~~~~~~~~~~~~~~
     xQueueCreateSet
../components/DCCSignalGenerator/RMTTrackDevice.cpp: In member function 'void esp32cs::RMTTrackDevice::rmt_transmit_complete()':
../components/DCCSignalGenerator/RMTTrackDevice.cpp:404:3: error: 'portYIELD_FROM_ISR' was not declared in this scope
   portYIELD_FROM_ISR(woken);
   ^~~~~~~~~~~~~~~~~~
[894/907] Building CXX object esp-idf/main/CMakeFiles/__idf_main.dir/WebServer.cpp.obj
ninja: build stopped: subcommand failed.
ninja failed with exit code 1
atanisoft commented 3 years ago

../components/DCCSignalGenerator/RMTTrackDevice.cpp:404:27: error: macro "portYIELD_FROM_ISR" passed 1 arguments, but takes just 0 portYIELD_FROM_ISR(woken);

are you on IDF v4.2 or master?

../components/DCCSignalGenerator/RMTTrackDevice.cpp:219:5: error: 'xQueueCreateStatic' was not declared in this scope xQueueCreateStatic(packet_queue_len, sizeof(dcc::Packet)

There is an update to sdkconfig.defaults, make sure the new entry is present in your sdkconfig (you can do an inplace update/rebuild).

TrainzLuvr commented 3 years ago

On IDF v4.2 here.

I re-ran idf.py menuconfig and re-saved my config, but error still comes up.

Which entry am I looking for in sdkconfig.defaults?

atanisoft commented 3 years ago

Which entry am I looking for in sdkconfig.defaults?

CONFIG_FREERTOS_SUPPORT_STATIC_ALLOCATION=y

I checked the issue with portYIELD_FROM_ISR and the arg version is IDF v4.3+ so adjusted that in the latest commit.

TrainzLuvr commented 3 years ago

I pulled the updated dcc branch. Also updated my IDF 4.2 branch.

sdkconfig.defaults has that new entry but I'm still getting this error:

............/components/DCCSignalGenerator/RMTTrackDevice.cpp
../components/DCCSignalGenerator/RMTTrackDevice.cpp: In constructor 'esp32cs::RMTTrackDevice::RMTTrackDevice(const char*, rmt_channel_t, uint8_t, size_t, gpio_num_t, RailcomDriver*)':
../components/DCCSignalGenerator/RMTTrackDevice.cpp:219:5: error: 'xQueueCreateStatic' was not declared in this scope
     xQueueCreateStatic(packet_queue_len, sizeof(dcc::Packet)
     ^~~~~~~~~~~~~~~~~~
../components/DCCSignalGenerator/RMTTrackDevice.cpp:219:5: note: suggested alternative: 'xQueueCreateSet'
     xQueueCreateStatic(packet_queue_len, sizeof(dcc::Packet)
     ^~~~~~~~~~~~~~~~~~
     xQueueCreateSet
ninja: build stopped: subcommand failed.
ninja failed with exit code 1
atanisoft commented 3 years ago

add it to your sdkconfig

TrainzLuvr commented 3 years ago

Oh! For whatever reason I thought that sdkconfig.defaults is being parsed after running idf.py menuconfig

Compiled successfully now. Thanks.

atanisoft commented 3 years ago

sdkconfig.defaults will be picked up only when sdkconfig does not exist unfortunately. It is not the most ideal setup but I don't have many options on fixing that yet.

TrainzLuvr commented 3 years ago

Hmm...I'm seeing this in monitor:

[TaskMon] uptime: 00:02:15 freeHeap: 111108, largest free block: 40028, tasks: 17, mainBufferPool: 0.72kB                      
[TWAI] RX:0 (pending:0,overrun:0,discard:0) TX:17 (pending:17,suc:0,fail:0) bus (arb-err:0,err:7738,state:Running)             
[WiFi] Lost connection to SSID: ******* (reason:200)                                                                         
[WiFi] Attempting to reconnect to SSID: *******.                                                                             
[WebSocket fd:51] read-error (113: Software caused connection abort), disconnecting (recv)                                     
[mDNS] Removing advertisement of _open☺cb-can._tcp.                                                                            
[WS 192.168.*.*/51] Disconnected                                                                                            
[Hub] Shutting down TCP/IP listener                                                                                            
Shutdown listening socket 12021.                                                                                               
[Uplink] Disconnecting from uplink.                                                                                            
[TWAI] RX:0 (pending:0,overrun:0,discard:0) TX:17 (pending:17,suc:0,fail:0) bus (arb-err:0,err:7738,state:Running)             
[WiFi] Connection failed, reconnecting to SSID: ******* (reason:2).                                                          
[WiFi] Connection failed, reconnecting to SSID: ******* (reason:205).                                                        
[WiFi] Connection failed, reconnecting to SSID: ******* (reason:2).                                                          
[WiFi] Connection failed, reconnecting to SSID: ******* (reason:205).                                                        
[WiFi] Connection failed, reconnecting to SSID: ******* (reason:4).                                                          
[TWAI] RX:0 (pending:0,overrun:0,discard:0) TX:17 (pending:17,suc:0,fail:0) bus (arb-err:0,err:7738,state:Running)             
[WiFi] Connection failed, reconnecting to SSID: ******* (reason:205).                                                        
[WiFi] Connection failed, reconnecting to SSID: ******* (reason:2).                                                          
[WiFi] Connection failed, reconnecting to SSID: ******* (reason:205).                                                        
[WiFi] Connected to SSID: *******                                                                                            
[WiFi] IP address is 192.168.*.*, starting hub (if enabled) and uplink                                                      
[WiFi] Setting TX power to: 44                                                                                                 
[Hub] Starting TCP/IP listener on port 12021                                                                                   
Listening on port 12021, fd 48                                                                                                 
[mDNS] Advertising _open☺cb-can._tcp:12021.                                                                                    
[OPS]   0.00 mA / 3000 mA

It goes back online, stays on for a bit then the cycle above repeats (drop, reconnecting).

Then I connect my UWT-100 on dry (no loco on track, no track connected, not even CS, just bare ESP32 out of the socket).

I play with the throttle, even though it reports no loco found, etc, eventually it lets me change speed and function keys and then crash:

abort() was called at PC 0x400d5cdb on core 0
0x400d5cdb: __cxa_end_catch at C:/espressif/esp-idf/components/cxx/cxx_exception_stubs.cpp:13

Backtrace:0x40088c7e:0x3ffe9920 0x40089291:0x3ffe9940 0x4008fd91:0x3ffe9960 0x400d5cdb:0x3ffe99e0 0x40195319:0x3ffe9a00 0x4010ef4d:0x3ffe9a20 0x4010efa8:0x3ffe9a60 0x401a79bf:0x3ffe9a80 0x40128d4d:0x3ffe9aa0 0x40128ded:0x3ffe9af0 0x4012563b:0x3ffe9b10

0x40088c7e: panic_abort at C:/espressif/esp-idf/components/esp_system/panic.c:341
0x40089291: esp_system_abort at C:/espressif/esp-idf/components/esp_system/system_api.c:106
0x4008fd91: abort at C:/espressif/esp-idf/components/newlib/abort.c:46
0x400d5cdb: __cxa_end_catch at C:/espressif/esp-idf/components/cxx/cxx_exception_stubs.cpp:13
0x40195319: operator new(unsigned int) at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/gcc/libstdc++-v3/libsupc++/new_op.cc:54
0x4010ef4d: http::Httpd::new_connection(int) at r:\code\esp32commandstation\build/../components/HttpServer/src/HttpServer.cpp:205
0x4010efa8: http::incoming_http_connection(int) at r:\code\esp32commandstation\build/../components/HttpServer/src/HttpServer.cpp:63
0x401a79bf: std::_Function_handler<void (int), void (*)(int)>::_M_invoke(std::_Any_data const&, int&&) at c:\espressif\tools\xtensa-esp32-elf\esp-2020r2-8.2.0\xtensa-esp32-elf\xtensa-esp32-elf\include\c++\8.2.0\bits/std_function.h:297
0x40128d4d: SocketListener::AcceptThreadBody() at c:\espressif\tools\xtensa-esp32-elf\esp-2020r2-8.2.0\xtensa-esp32-elf\xtensa-esp32-elf\include\c++\8.2.0\bits/std_function.h:687
 (inlined by) SocketListener::AcceptThreadBody() at r:\code\esp32commandstation\build/../components/OpenMRNLite/src/utils/socket_listener.cpp:175
0x40128ded: accept_thread_start(void*) at r:\code\esp32commandstation\build/../components/OpenMRNLite/src/utils/socket_listener.cpp:63
0x4012563b: os_thread_start at r:\code\esp32commandstation\build/../components/OpenMRNLite/src/os/os.c:391
atanisoft commented 3 years ago

[TWAI] RX:0 (pending:0,overrun:0,discard:0) TX:17 (pending:17,suc:0,fail:0) bus (arb-err:0,err:7738,state:Running)
[WiFi] Connection failed, reconnecting to SSID: (reason:2).
[WiFi] Connection failed, reconnecting to SSID: (reason:205).
[WiFi] Connection failed, reconnecting to SSID: (reason:2).
[WiFi] Connection failed, reconnecting to SSID: (reason:205).
[WiFi] Connection failed, reconnecting to SSID: *** (reason:4).

Breakdown of the reason codes can be found here. But in general it looks like it is somehow dropping packets talking to the AP (router).

abort() was called at PC 0x400d5cdb on core 0 0x400d5cdb: __cxa_end_catch at C:/espressif/esp-idf/components/cxx/cxx_exception_stubs.cpp:13

Backtrace:0x40088c7e:0x3ffe9920 0x40089291:0x3ffe9940 0x4008fd91:0x3ffe9960 0x400d5cdb:0x3ffe99e0 0x40195319:0x3ffe9a00 0x4010ef4d:0x3ffe9a20 0x4010efa8:0x3ffe9a60 0x401a79bf:0x3ffe9a80 0x40128d4d:0x3ffe9aa0 0x40128ded:0x3ffe9af0 0x4012563b:0x3ffe9b10

0x40088c7e: panic_abort at C:/espressif/esp-idf/components/esp_system/panic.c:341 0x40089291: esp_system_abort at C:/espressif/esp-idf/components/esp_system/system_api.c:106 0x4008fd91: abort at C:/espressif/esp-idf/components/newlib/abort.c:46 0x400d5cdb: __cxa_end_catch at C:/espressif/esp-idf/components/cxx/cxx_exception_stubs.cpp:13 0x40195319: operator new(unsigned int) at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/gcc/libstdc++-v3/libsupc++/new_op.cc:54

This looks like it is related to https://github.com/atanisoft/ESP32CommandStation/issues/78 and it is manifesting in the http code. You should be able to overlay https://github.com/atanisoft/ESP32CommandStation/pull/84 without issues on the dcc branch and it may help some but it won't fix it 100% likely.

TrainzLuvr commented 3 years ago

Have you noticed this though?

[TWAI] RX:0 (pending:0,overrun:0,discard:0) TX:17 (pending:17,suc:0,fail:0) bus (arb-err:0,err:7738,state:Running)

Why so many bus errors (the number keeps increasing)?

atanisoft commented 3 years ago

Why so many bus errors (the number keeps increasing)?

If you don't have a CAN transceiver connected this would make sense.

TrainzLuvr commented 3 years ago

Right, I'm running dry at the moment, so I can have monitor on.

I've merged PR #84 into the dcc branch, so now waiting to see if it crashes or not...

roadsnail commented 3 years ago

Hi all. Have had other commitments the last two day, but I think I have caught up committing a7b1987 on the dcc branch. I am also now using ESP-IDF release/v4.2 so I think I have the same build environment as TrainzLuvr. I also went down the same build error route, but have a successful build now also with a manual addition to sdkconfig as mentioned above.

I really need to test properly tomorrow, but I am still seeing Wifi issues.

  1. Very low signal levels seen at my AP
  2. Disconnections from my AP seemingly after some CS idle time, requiring reset of CS.

JMRI then connects okay, but I'm still seeing laggy 'Lights on/off' toggling command from JMRI throttle to loco.

Then just as I started typing this. My test loco shot off the end of my test track without any intervention! No harm done!

Will continue tomorrow, looking at monitor traffic as it is too late now.

Cheers all.

atanisoft commented 3 years ago

Then just as I started typing this. My test loco shot off the end of my test track without any intervention! No harm done!

This sounds like the CS crashed and restarted.

I really need to test properly tomorrow, but I am still seeing Wifi issues.

  1. Very low signal levels seen at my AP
  2. Disconnections from my AP seemingly after some CS idle time, requiring reset of CS.

I think that may need to be routed to the IDF team as they seem to have broken it somehow and/or the setting of the wifi TX power is operating in the exact opposite of how it is documented.

You can turn on CONFIG_WIFI_DEBUG_OUTPUT in your sdkconfig and it should print out a lot of details from the underlying WiFi code to the console.

roadsnail commented 3 years ago

I have just received a different esp32 module and on first testing, the wifi issue I was seeing on my epduino is not an issue on the new one. Have just go to interface the newer module to my motor shield somehow as it has a different form factor.

atanisoft commented 3 years ago

@TrainzLuvr In my desk setup I've reproduced the following output during startup and the cause is interesting...

[WiFi] Connection failed, reconnecting to SSID: (reason:2).
[WiFi] Connection failed, reconnecting to SSID: (reason:205).
[WiFi] Connection failed, reconnecting to SSID: (reason:2).
[WiFi] Connection failed, reconnecting to SSID: (reason:205). [WiFi] Connection failed, reconnecting to SSID: *** (reason:4).

In trying to narrow down the cause I disconnected the CAN transceiver from the 5V supply (5V pin on the ESP32 which is directly fed by the USB-VBUS line). Once I disconnected that the CS started up and connected to the network without issues and I could reconnect it after WiFi startup completed without issues. So, the conclusion at this point is that the WiFi issues are unrelated to the TX power setting but instead related to insufficient power supply on the 5V bus which feeds the 3v3 LDO (typically 750mA or 1A, some are only 500mA though which is the bare minimum in the esp32 datasheet). It is interesting that I haven't seen this error until this week in any of my testing over the last three years with various esp32 modules/devices (and have not yet seen this on the esp32s2 but that also uses less current overall).

@roadsnail Your Espduino is likely fine as long as you power it via the barrel connector. On the ones I have on hand they all have an MP1280 step-down converter which provides 5V 2A (max) and there is an LDO on the board to drop to 3v3 for the esp32.

TrainzLuvr commented 3 years ago

Does this mean 1A on the 5V bus is not enough to drive all the hardware, because isn't the 5V coming from the LM2675 and not ESP32?

atanisoft commented 3 years ago

Does this mean 1A on the 5V bus is not enough to drive all the hardware, because isn't the 5V coming from the LM2675 and not ESP32?

When powered via USB the LM2675 is not used as the 5V supply. The 5V current limit will be whatever the USB supply can provide (usually at least 500mA) but the USB cable can influence this as well.

TrainzLuvr commented 3 years ago

Then I'll need to find a way to monitor the CS when fully powered up and not just a stand-alone ESP32...

atanisoft commented 3 years ago

Then I'll need to find a way to monitor the CS when fully powered up and not just a stand-alone ESP32...

Right, I'm in the same position as I usually use an esp32 on breadboard for testing the various updates in isolation with console output capture for debugging. On the CS PCB we can redirect console output to the UART1 connector (pins 16,17) and use a standalone FTDI cable connecting only: GND, RX, TX. I'm also looking at a few other options to capture console output via the web but that can (and should) be tracked via a different issue/PR.

roadsnail commented 3 years ago

I am going to order up a replacement esp32 arduino style module. I have tried to get more power out of my existing module, but its output appears to be crippled (my AP reports signal strength of -88dBm!!). It's possible that the JMRI command lags I witnessed may have been caused by the suspect module, so I will watch your testing with interest while awaiting a replacement.