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

ESP32 'Espduino' modules - very low TX WiFi power issues #89

Open roadsnail opened 3 years ago

roadsnail commented 3 years ago

While carrying out some testing, I noticed that on occasions my ESP32 CS took a while to connect to my test WiFi with retries observed on the serial output.

Checking the status of my CS (as seen by the AP), I noticed the WiFi signal received by the AP was very low. Approx -85dBm, sometimes worse! Putting the CS into STA and AP mode made no difference, with the TX still low for AP and receive signal at my test AP. I independently checked the signal level with WiFi Analyser on my phone.

Thinking I may have a faulty module, I ordered up a new ESPduino (ESP32 on arduino form factor module just to be clear) and the results are exactly the same having flashed yesterday's master branch of CS.

Interestingly, but confusingly, a different module (NodeMCU ESP-32) does not seem to have an issue with TX WiFi power! The signal received from this module at my test AP is in the right ballpark given distance (around -50dBm): a huge difference of around 35dBm when compared to the ESPDuino modules (both of them).

In order to make sure the suspect modules are actually capable of higher transmit power and I haven't somehow broken them, I decided to do a full erase in Espressif's download tool and then flash micropython for ESP32 with the same tool. After flashing, micropython connects to my test AP without issue and at a sensible TX power level. (Around -50dBm) for both 'suspect' modules, thus proving the modules are indeed capable of operating at a higher TX WiFi power level and are not broken.

I noticed that on starting WiFi in STA mode on both modules, that micropython displays a message... 'phy_init: failed to load RF calibration data (0x1102), falling back to full calibration' but I would guess that is to be expected given that I did a full flash erase prior to flashing python, thus erasing any WiFi calibration data (stored in PHY NVS?). Note that this message is not displayed on subsequent STA connections which is normal given that WiFi calibration only need to be carried out once.

Following on from proving that both modules are capable of a full WiFi TX signal, I next flashed the master build of CS (on both modules) and observe that once again TX levels are very poor.

I am thinking that maybe Wifi calibration data is not being initialised fully by CS given the fact I do a full flash erase before flashing CS?

I am probably wrong given that no one else has reported any issues with CS on these ESP32 modules, and that I do not see an issue with the NodeMCU part? Why the NodeMCU module does not exhibit the power issue, I do not have any ideas given that all three of my modules are based on the same ESP-WROOM-32 modules. But I have now run out of ideas on how to get my two modules to work reliably with CS.

One last piece of information - all testing has been carried out with just plain ESP modules, ie no motor driver shield connected, ruling out any hardware interactions with the shield.

Any pointers as to where to go next would be much appreciated.

atanisoft commented 3 years ago

micropython uses IDF v3.x last I checked and that may explain some of the differences but not all.

Can you capture the console using CONFIG_WIFI_DEBUG_OUTPUT=y in sdkconfig?

Also can you try commenting out these two lines:

I'd suggest erase_flash before testing with these two lines commented.

roadsnail commented 3 years ago

Yes, the micropython uses IDF v3.something. The reason I flashed it was to check that the two boards are still capable of higher tx power.

Anyhow commented out the lines indicated and rebuilt, flash-erased and flashed... here is the capture... The tx power level is still down at -80

ESP32 Command Station v1.5.0 (v1.5.0-beta1-11-g1cc1b01-dirty) starting up...
Compiled on Oct 22 2020 16:34:13 using IDF v4.2-beta1-86-gdddcc2ede
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 (783) sdmmc_sd: sdmmc_init_sd_if_cond: send_if_cond (1) returned 0x108
E (784) vfs_fat_sdmmc: sdmmc_card_init failed (0x108).
ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x108 (ESP_ERR_INVALID_RESPONSE) at 0x40087b63
0x40087b63: _esp_error_check_failed_without_abort at C:/Users/chris/Desktop/esp-idf-2/components/esp_common/src/esp_err.c:40

file: "../components/Configuration/FileSystemManager.cpp" line 149
func: FileSystemManager::FileSystemManager()
expression: esp_vfs_fat_sdspi_mount(VFS_MOUNT, &sd_host, &device_cfg, &sd_cfg, &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:09 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] Initializing WiFi stack
I (1435) wifi:wifi driver task: 3ffd1680, prio:23, stack:6656, core=0
I (1437) wifi:wifi firmware version: d3be909
I (1437) wifi:wifi certification version: v7.0
I (1441) wifi:config NVS flash: disabled
I (1444) wifi:config nano formating: disabled
I (1449) wifi:Init data frame dynamic rx buffer num: 32
I (1453) wifi:Init management frame dynamic rx buffer num: 32
I (1459) wifi:Init management short buffer num: 32
I (1463) wifi:Init dynamic tx buffer num: 32
I (1467) wifi:Init static rx buffer size: 1600
I (1472) wifi:Init static rx buffer num: 16
I (1475) wifi:Init dynamic rx buffer num: 32
[WiFi] Configuring Station (SSID: msshnot_2)
D (1484) wifi:clear blacklist
[WiFi] Starting WiFi stack
V (1582) wifi:ht20 freq=2412, chan=1
D (1584) wifi:filter: set rx policy=0
I (1584) wifi:mode : sta (3c:71:bf:4d:7d:2c)
D (1585) wifi:filter: set rx policy=1
D (1586) wifi:connect status 0 -> 0
[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] Station started, attempting to connect to SSID: msshnot_2.
D (1610) wifi:Start wifi connect
D (1613) wifi:connect status 0 -> 0
D (1616) wifi:connect chan=0
V (1618) wifi:nvs=0, ssid=msshnot_2, channel=255
V (1623) wifi:ssid=msshnot_2 match nvs 0, channel=255
D (1627) wifi:first chan=1
D (1630) wifi:connect status 0 -> 1
D (1633) wifi:filter: set rx policy=3
D (1636) wifi:clear scan ap list
D (1639) wifi:start scan: type=0x50f, priority=2, cb=0x40175568, arg=0x0, ss_state=0x1, time=57533, index=0
0x40175568: cnx_start_handoff_cb at ??:?

V (1649) wifi:inter_channel_timeout: arg=0x0, ss_state=0x1
D (1654) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
V (1660) wifi:change: chan<1,0>, dur<0,120>
V (1664) wifi:enter start op, arg=0x3ffb7f00
V (1668) wifi:scan operation: state=0x3, chan<1,0>, arg=0x3ffb7f00, status=0
V (1674) wifi:scan specific ssid=msshnot_2
V (1679) wifi:start max timer
Allocating new alias B89 for node 05020103f000
D (1801) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (1802) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
V (1802) wifi:change: chan<2,0>, dur<0,120>
V (1805) wifi:ht20 freq=2417, chan=2
V (1809) wifi:enter start op, arg=0x3ffb7f00
V (1812) wifi:scan operation: state=0x3, chan<2,0>, arg=0x3ffb7f00, status=0
V (1819) wifi:scan specific ssid=msshnot_2
V (1823) wifi:start max timer
D (1946) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (1946) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
V (1946) wifi:change: chan<3,0>, dur<0,120>
V (1950) wifi:ht20 freq=2422, chan=3
V (1953) wifi:enter start op, arg=0x3ffb7f00
V (1957) wifi:scan operation: state=0x3, chan<3,0>, arg=0x3ffb7f00, status=0
V (1964) wifi:scan specific ssid=msshnot_2
V (1968) wifi:start max timer
D (2090) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (2091) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
V (2091) wifi:change: chan<4,0>, dur<0,120>
V (2094) wifi:ht20 freq=2427, chan=4
V (2098) wifi:enter start op, arg=0x3ffb7f00
V (2101) wifi:scan operation: state=0x3, chan<4,0>, arg=0x3ffb7f00, status=0
V (2108) wifi:scan specific ssid=msshnot_2
V (2112) wifi:start max timer
D (2235) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (2235) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
V (2235) wifi:change: chan<5,0>, dur<0,120>
V (2238) wifi:ht20 freq=2432, chan=5
V (2242) wifi:enter start op, arg=0x3ffb7f00
V (2245) wifi:scan operation: state=0x3, chan<5,0>, arg=0x3ffb7f00, status=0
V (2252) wifi:scan specific ssid=msshnot_2
V (2256) wifi:start max timer
D (2379) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (2379) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120>
V (2379) wifi:change: chan<6,0>, dur<0,120>
V (2382) wifi:ht20 freq=2437, chan=6
V (2386) wifi:enter start op, arg=0x3ffb7f00
V (2390) wifi:scan operation: state=0x3, chan<6,0>, arg=0x3ffb7f00, status=0
V (2396) wifi:scan specific ssid=msshnot_2
V (2400) wifi:start max timer
D (2409) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2411) wifi:profile match: ss_state=0x7
V (2411) wifi:scan histroy table is not full yet, add
V (2416) wifi:add ssid=msshnot_2, chan=6 to scan history
D (2421) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2426) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (2433) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (2440) wifi:profile match: ss_state=0x7
V (2443) wifi:update scan history ssid=msshnot_2, channel=6
D (2520) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2520) wifi:profile match: ss_state=0x7
V (2520) wifi:update scan history ssid=msshnot_2, channel=6
D (2523) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2528) wifi:find first mathched ssid, scan done
V (2532) wifi:back home chan=<1,0>, current chan=<6,0>
V (2537) wifi:ht20 freq=2412, chan=1
D (2541) wifi:filter: set rx policy=4
D (2544) wifi:first chan=1
V (2546) wifi:scan_done: arg=0x0, status=0, cur_time=964032, scan_id=128, scan state=0
V (2554) wifi:call scan_done cb, arg=0x0
D (2557) wifi:handoff_cb: status=0
V (2560) wifi:best bss has set.
D (2563) wifi:ap found, mac=a2:2a:a8:84:f0:14
V (2567) wifi:bssid=a2:2a:a8:84:f0:14, LR=0
D (2571) wifi:new_bss=0x3ffb69b0, cur_bss=0x0, new_chan=<6,0>, cur_chan=1
D (2578) wifi:filter: set rx policy=5
I (2581) wifi:new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1
V (2587) wifi:ht20 freq=2437, chan=6
D (2591) wifi:connect_op: status=0, auth=5, cipher=3
D (2595) wifi:auth mode is not none
D (3131) wifi:connect_bss: auth=1, reconnect=0
I (3131) wifi:state: init -> auth (b0)
D (3132) wifi:start 1s AUTH timer
D (3132) wifi:clear scan ap list
D (3135) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (3139) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (3143) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (3148) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (3153) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (3157) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (3168) wifi:recv auth: seq=2, status=0
I (3168) wifi:state: auth -> assoc (0)
D (3169) wifi:restart connect 1s timer for assoc
D (3179) wifi:recv assoc: type=0x10
D (3179) wifi:filter: set rx policy=6
I (3180) wifi:state: assoc -> run (10)
D (3184) wifi:start 10s connect timer for 4 way handshake
V (3189) wifi:wpa_psk start
V (3192) wifi:wpa_psk handle succeed
V (3206) wifi:wpa_psk start
V (3207) wifi:wpa_psk handle succeed
I (3219) wifi:connected with msshnot_2, aid = 11, channel 6, BW20, bssid = a2:2a:a8:84:f0:14
I (3219) wifi:security: WPA2-PSK, phy: bgn, rssi: -42
D (3221) wifi:remove all except a2:2a:a8:84:f0:14 from rc list
D (3226) wifi:clear blacklist
D (3229) wifi:filter: set rx policy=7
I (3232) wifi:pm start, type: 1

D (3236) wifi:Send sta connected event
D (3239) wifi:connect status 1 -> 5
D (3242) wifi:obss scan is disabled
D (3245) wifi:start obss scan: obss scan is stopped
I (3250) wifi:AP's beacon interval = 102400 us, DTIM period = 3
[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"
I (3758) wifi:Set ps type: 0

[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.
atanisoft commented 3 years ago

@roadsnail can you connect to the web interface and on the config page for wifi click on the "Connect to network" button which should perform a WiFi scan. I'm wondering if the RSSI that is reported from that is different than what your AP is showing.

roadsnail commented 3 years ago

The scan reports the RSSI being -42 being the signal strength of my AP as seen by the ESP32 The signal strength I mentioned above, (ie -80 ish) is being reported by my AP... ie it's the signal strength of my ESP32 tx

The issue I am still seeing is that the esp32 (espduino) type boards are transmitting on very low power.

By the way, I would suspect that my previous logged issue (laggy loco commands from JMRI) is probably due to the very low tx level of my CS.

Thanks for your help so far. I think I will uncomment the two lines commented out earlier, rebuild and continue experimenting here.

atanisoft commented 3 years ago

By the way, I would suspect that my previous logged issue (laggy loco commands from JMRI) is probably due to the very low tx level of my CS.

That's possible, it is also possible there is a bug somewhere in the code that is causing a delay.

Thanks for your help so far. I think I will uncomment the two lines commented out earlier, rebuild and continue experimenting here.

No problem, I'll continue experimentation as well on my side.

TrainzLuvr commented 3 years ago

@roadsnail for the sake of argument, connect to the /config URL of your CS, and look up the _txpower value?

Maybe the value is set low ... and I recall mapping of those values to real dBms was weird, to say the least.

roadsnail commented 3 years ago

@TrainzLuvr, thanks for the input. I can confirm that tx power in /config reports 20dBm (max value).

Strangely enough, if I then change the TX power level to 2 and SAVE. Once the CS has rebooted, my AP reports an even lower power level from the CS. So low, that I'm amazed the AP can even communicate with the ESP32!

I am now suspecting some sort of ESP32 WiFi TX power calibration problem given that flashing micropython on the same hardware resets the maximum tx power level.

TrainzLuvr commented 3 years ago

@roadsnail err...those values are not in dBms, that was my point.

Espressif chose some weird way of mapping values to actual dBm so that the maximum output power of 20dBm would be a value of 78, check this commit https://github.com/atanisoft/ESP32CommandStation/commit/89f0f177ea2f4401f052f3b836bb62771f6b6bbd

atanisoft commented 3 years ago

I'm not seeing any specific API in IDF v4.0+ that would explain this degraded RSSI as observed on the AP side, or any reason why the micropython library is able to see better numbers.

roadsnail commented 3 years ago

@TrainzLuvr , yes, thanks again for your input. I got your original point. The 20dBm I referred to was the value displayed in the CS configuration WiFi tx power where I see 20dBm, with a drop-down menu allowing between 2 and 20 tx power to be selected. I get that 2-20 represents min-maximum power values for the wifi tx and not true dBm. Maybe the use of dBm should be dropped in the GUI? Just a thought...

I presume the 2-20 scale relates to the following (see table below) taken from Espressif source, but whatever, my CS web gui reports that tx power is set to max (20). Whereas my AP (ubiquiti AP AC lite) reports receiving a signal strength (from ESP32) down around -80dBm (that's proper dBm).

typedef enum { WIFI_POWER_19_5dBm = 78,// 19.5dBm WIFI_POWER_19dBm = 76,// 19dBm WIFI_POWER_18_5dBm = 74,// 18.5dBm WIFI_POWER_17dBm = 68,// 17dBm WIFI_POWER_15dBm = 60,// 15dBm WIFI_POWER_13dBm = 52,// 13dBm WIFI_POWER_11dBm = 44,// 11dBm WIFI_POWER_8_5dBm = 34,// 8.5dBm WIFI_POWER_7dBm = 28,// 7dBm WIFI_POWER_5dBm = 20,// 5dBm WIFI_POWER_2dBm = 8,// 2dBm WIFI_POWER_MINUS_1dBm = -4// -1dBm

@atanisoft , once again I appreciate your delving into the 4.0 API docs. I am also trying to get my head around espressif's docs relating to Wifi setup. I am also aware that no one else appears to be having issues with the espduino type boards, so maybe 'park' this issue and see if anyone else reports a similar problem.

One last thing. Am I using a correct ESP-IDF? From the log, my last build shows ... Compiled on Oct 22 2020 16:34:13 using IDF v4.2-beta1-86-gdddcc2ede

Thanks again for your input.

buelowp commented 3 years ago

I think I can give this a shot. I've got the Wemos Espduino variant. If you think that is close enough? Also, which IDF branch should I build against?

atanisoft commented 3 years ago

@buelowp IDF v4.0.1 or v4.2 branch should be safe for testing.

roadsnail commented 3 years ago

@buelowp That would be great if you could give your module a go. This site -- https://www.cnx-software.com/2017/09/04/espduino-32-wemos-d1-r32-esp32-boards-support-some-arduino-uno-shields/ shows pictures of the board type I am using. One of my boards looks exactly like the Wemos versions shown. The other looks identical apart from 'ESPDUINO-32 HW-729' silkscreened where the other shows Wemos...

I have built against V4.2 . My build environment is W10.

atanisoft commented 3 years ago

@roadsnail I've got a few of the second one (the one branded as HW-729). Functionally they all appear to be identical with exception of the USB port (B vs Micro-B). This is also the same one that I recommend for users as it is one of the easiest to interface with the motor shields etc.

The only downside I know of with it is the PCB antenna on the esp-wroom-32 module is sitting directly on the PCB. It would be better suited if it was elevated slightly or shifted off the PCB so it is not receiving any interference from a copper pour, though in the ones I have it appears they have a copper pour keep-out area under the antenna.

buelowp commented 3 years ago

Let me know if you want any other details, but here's the capture I just got. My AP is reporting -69 dBm for this connection.

et.RÕ¹ 8 &Š²‚‚:2&§Ój

r.—‚ÂE (PêUI=¹_REª•bœœÑé0x1&BšA%_FA*Õe1…SH_šêQ¥
coË¥Í¥p: â SÐR¥‚••5
clkEÉÙé0x0°)}‘ÉÙ:0ø‚,dEÉÙé0x00iÍÁߖÙé0x00¬‹}‘Év:0ø‚bºÁ_drö'ÂÁ0
m‹•éÄRŠ±œ­div'ŠHˆë+‘é0x3fæ‚š‚âleî'ÓHˆë+‘é0x3f–‚š¢,låK¢ÊÂÂ
ì+‘é0x40°‚‚‚âle’’¢
ì+‘é0x40°‚¢‚‚âleKšºŠ’j
e‹Éå0x40Â06ŽSHø

ESP32 Command Station v1.5.0 (v1.5.0-beta1-14-ga373938) starting up...
Compiled on Oct 23 2020 07:20:45 using IDF v4.2-beta1-227-gf0e87c933
Running from: ota_0
ESP32 Command Station uses the OpenMRN library
Copyright (c) 2019-2020, OpenMRN
All rights reserved.
[NVS] Initializing NVS
[TimeZone] UTC-5
[ADC] Configure 12-bit ADC resolution
E (802) sdmmc_sd: sdmmc_init_sd_if_cond: send_if_cond (1) returned 0x108
E (803) vfs_fat_sdmmc: sdmmc_card_init failed (0x108).
ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x108 (ESP_ERR_INVALID_RESPONSE) at 0x40087b77
file: "/home/peter/Projects/ESP32CommandStation/components/Configuration/FileSystemManager.cpp" line 149
func: FileSystemManager::FileSystemManager()
expression: esp_vfs_fat_sdspi_mount(VFS_MOUNT, &sd_host, &device_cfg, &sd_cfg, &sd_)
[FS] SD Card not present or mounting failed, using SPIFFS
[FS] SPIFFS usage: 18.38/757.66 KiB
[FS] SPIFFS will be used for persistent storage.
[FS] Dumping content of filesystem: /cfg
[FS] /cfg/ESP32CS/trains.json (433 bytes) mtime: Thu Aug 20 00:09:41 2020
[FS] /cfg/LCC/config (485 bytes) mtime: Thu Jan  1 04:59:59 1970
[FS] /cfg/LCC/cdi.xml (8184 bytes) mtime: Fri Oct 23 18:13:35 2020
[FS] /cfg/LCC/train.xml (5406 bytes) mtime: Fri Oct 23 18:13:35 2020
[FS] /cfg/LCC/tmptrain.xml (2593 bytes) mtime: Fri Oct 23 18:13:35 2020
[LCC] Initializing Stack (node-id: 5020103f000)
[WiFi] Starting WiFiManager
[SNTP] Polling pool.ntp.org for time updates
[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] Registering 3 - Trolley (idle: Off, limited: Off)
[TrainDB] Registering 4 - Amtrack (idle: Off, limited: Off)
[TrainDB] Found 2 persistent roster entries.

ESP32 Command Station Startup complete!

[WiFi] Starting WiFi Manager task
[WiFi] Initializing WiFi stack
I (1529) wifi:wifi driver task: 3ffd1950, prio:23, stack:6656, core=0
I (1532) wifi:wifi firmware version: f8b2044
I (1534) wifi:wifi certification version: v7.0
I (1539) wifi:config NVS flash: disabled
I (1542) wifi:config nano formating: disabled
I (1547) wifi:Init data frame dynamic rx buffer num: 32
I (1551) wifi:Init management frame dynamic rx buffer num: 32
I (1557) wifi:Init management short buffer num: 32
I (1561) wifi:Init dynamic tx buffer num: 32
I (1565) wifi:Init static rx buffer size: 1600
I (1570) wifi:Init static rx buffer num: 16
I (1573) wifi:Init dynamic rx buffer num: 32
[WiFi] Configuring Station (SSID: buelows)
D (1581) wifi:clear blacklist
[WiFi] Starting WiFi stack
V (1666) wifi:ht20 freq=2412, chan=1
D (1668) wifi:filter: set rx policy=0
I (1668) wifi:mode : sta (30:ae:a4:40:d0:a4)
D (1669) wifi:filter: set rx policy=1
D (1670) wifi:connect status 0 -> 0
[WiFi] [1/36] Waiting for SSID connection.
[WiFi] Setting ESP32 hostname to "esp32cs_5020103f000".
[WiFi] MAC Address: 30:ae:a4:40:d0:a4
[DHCP] Starting DHCP Client.
[WiFi] Station started, attempting to connect to SSID: buelows.
D (1694) wifi:Start wifi connect
D (1696) wifi:connect status 0 -> 0
D (1700) wifi:connect chan=0
V (1702) wifi:nvs=0, ssid=buelows, channel=255
V (1706) wifi:ssid=buelows match nvs 0, channel=255
D (1711) wifi:first chan=1
D (1713) wifi:connect status 0 -> 1
D (1717) wifi:filter: set rx policy=3
D (1720) wifi:clear scan ap list
D (1723) wifi:start scan: type=0x50f, priority=2, cb=0x40175e60, arg=0x0, ss_state=0x1, time=57009, index=0
V (1732) wifi:inter_channel_timeout: arg=0x0, ss_state=0x1
D (1738) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
V (1743) wifi:change: chan<1,0>, dur<0,120>
V (1747) wifi:enter start op, arg=0x3ffb7dd0
V (1751) wifi:scan operation: state=0x3, chan<1,0>, arg=0x3ffb7dd0, status=0
V (1758) wifi:scan specific ssid=buelows
V (1762) wifi:start max timer
Allocating new alias B89 for node 05020103f000
D (1885) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (1885) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
V (1886) wifi:change: chan<2,0>, dur<0,120>
V (1889) wifi:ht20 freq=2417, chan=2
V (1892) wifi:enter start op, arg=0x3ffb7dd0
V (1896) wifi:scan operation: state=0x3, chan<2,0>, arg=0x3ffb7dd0, status=0
V (1903) wifi:scan specific ssid=buelows
V (1907) wifi:start max timer
D (1911) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (1915) wifi:profile match: ss_state=0x7
V (1917) wifi:scan histroy table is not full yet, add
V (1922) wifi:add ssid=buelows, chan=2 to scan history
D (1928) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (1932) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (1939) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (1945) wifi:profile match: ss_state=0x7
V (1949) wifi:update scan history ssid=buelows, channel=2
D (1954) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (1959) wifi:profile match: ss_state=0x7
V (1963) wifi:update scan history ssid=buelows, channel=2
D (1968) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (1973) wifi:profile match: ss_state=0x7
V (1976) wifi:update scan history ssid=buelows, channel=2
D (1982) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (1986) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (1994) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (2000) wifi:profile match: ss_state=0x7
V (2004) wifi:update scan history ssid=buelows, channel=2
D (2009) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2014) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (2021) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (2027) wifi:profile match: ss_state=0x7
V (2031) wifi:update scan history ssid=buelows, channel=2
D (2036) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2041) wifi:profile match: ss_state=0x7
V (2045) wifi:update scan history ssid=buelows, channel=2
D (2050) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2054) wifi:profile match: ss_state=0x7
V (2058) wifi:update scan history ssid=buelows, channel=2
D (2063) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2068) wifi:profile match: ss_state=0x7
V (2072) wifi:update scan history ssid=buelows, channel=2
D (2077) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2082) wifi:find first mathched ssid, scan done
V (2086) wifi:back home chan=<1,0>, current chan=<2,0>
V (2091) wifi:ht20 freq=2412, chan=1
D (2095) wifi:filter: set rx policy=4
D (2098) wifi:first chan=1
V (2100) wifi:scan_done: arg=0x0, status=0, cur_time=434091, scan_id=128, scan state=0
V (2108) wifi:call scan_done cb, arg=0x0
D (2111) wifi:handoff_cb: status=0
V (2115) wifi:best bss has set.
D (2117) wifi:ap found, mac=24:4b:fe:33:9f:11
V (2121) wifi:bssid=24:4b:fe:33:9f:11, LR=0
D (2125) wifi:new_bss=0x3ffb6880, cur_bss=0x0, new_chan=<2,0>, cur_chan=1
D (2132) wifi:filter: set rx policy=5
I (2135) wifi:new:<2,0>, old:<1,0>, ap:<255,255>, sta:<2,0>, prof:1
V (2141) wifi:ht20 freq=2417, chan=2
D (2145) wifi:connect_op: status=0, auth=5, cipher=3 
D (2149) wifi:auth mode is not none
D (2688) wifi:connect_bss: auth=1, reconnect=0
I (2688) wifi:state: init -> auth (b0)
D (2689) wifi:start 1s AUTH timer
D (2689) wifi:clear scan ap list
D (2691) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2696) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2700) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2705) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2709) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2716) wifi:recv auth: seq=2, status=0
I (2718) wifi:state: auth -> assoc (0)
D (2722) wifi:restart connect 1s timer for assoc
D (2729) wifi:recv assoc: type=0x10
D (2730) wifi:filter: set rx policy=6
I (2732) wifi:state: assoc -> run (10)
D (2736) wifi:start 10s connect timer for 4 way handshake
V (2741) wifi:wpa_psk start
V (2744) wifi:wpa_psk handle succeed
V (2754) wifi:wpa_psk start
V (2755) wifi:wpa_psk handle succeed
I (2757) wifi:connected with buelows, aid = 6, channel 2, BW20, bssid = 24:4b:fe:33:9f:11
I (2760) wifi:security: WPA2-PSK, phy: bgn, rssi: -56
D (2765) wifi:remove all except 24:4b:fe:33:9f:11 from rc list
D (2771) wifi:clear blacklist
D (2773) wifi:filter: set rx policy=7
I (2777) wifi:pm start, type: 1

D (2780) wifi:Send sta connected event
D (2783) wifi:connect status 1 -> 5
D (2786) wifi:obss scan is disabled
D (2790) wifi:start obss scan: obss scan is stopped
[WiFi] Connected to SSID: buelows
[IPv4] [2/36] Waiting for IP address assignment.
V (2813) wifi:sta recv dup seq=0 tid=6, discard
V (2815) wifi:sta recv dup seq=0 tid=6, discard
[WiFi] IP address is 172.24.1.56, starting hub (if enabled) and uplink
[mDNS] Initializing mDNS system
[mDNS] Setting mDNS hostname to "esp32cs_5020103f000"
I (2826) wifi:Set ps type: 0

[httpd] Starting HTTP listener on port 80
I (2832) wifi:AP's beacon interval = 102400 us, DTIM period = 1
[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.
[SNTP] Received time update, new localtime: Fri Oct 23 18:14:38 2020

Incoming connection from 172.24.1.11, fd 50.
[TaskMon] uptime: 00:00:45 freeHeap: 173424, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB
Incoming connection from 172.24.1.11, fd 50.
Incoming connection from 172.24.1.11, fd 50.
Incoming connection from 172.24.1.11, fd 51.
Incoming connection from 172.24.1.11, fd 52.
Incoming connection from 172.24.1.11, fd 53.
Incoming connection from 172.24.1.11, fd 54.
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x4015104a  PS      : 0x00060d30  A0      : 0x80153c2f  A1      : 0x3ffcda60  
A2      : 0x000000e0  A3      : 0x0000059b  A4      : 0x3ffccc9c  A5      : 0x00000000  
A6      : 0x3ffcccf0  A7      : 0x00000000  A8      : 0x80145d45  A9      : 0x3ffcda40  
A10     : 0x00000000  A11     : 0x3ffcdaac  A12     : 0x000005a7  A13     : 0x00000000  
A14     : 0x3ffddb40  A15     : 0x3ffb6154  SAR     : 0x00000019  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x000000e0  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0xffffffff  

Backtrace:0x40151047:0x3ffcda60 0x40153c2c:0x3ffcda80 0x40142b71:0x3ffcdaa0

ELF file SHA256: 9ba30c97af2a0962

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:0x3fff0030,len:4
load:0x3fff0034,len:4988
load:0x40078000,len:13224
load:0x40080400,len:3712
entry 0x40080644

ESP32 Command Station v1.5.0 (v1.5.0-beta1-14-ga373938) starting up...
Compiled on Oct 23 2020 07:20:45 using IDF v4.2-beta1-227-gf0e87c933
Running from: ota_0
ESP32 Command Station uses the OpenMRN library
Copyright (c) 2019-2020, OpenMRN
All rights reserved.
[NVS] Initializing NVS
[TimeZone] UTC-5
[ADC] Configure 12-bit ADC resolution
E (803) sdmmc_sd: sdmmc_init_sd_if_cond: send_if_cond (1) returned 0x108
E (804) vfs_fat_sdmmc: sdmmc_card_init failed (0x108).
ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x108 (ESP_ERR_INVALID_RESPONSE) at 0x40087b77
file: "/home/peter/Projects/ESP32CommandStation/components/Configuration/FileSystemManager.cpp" line 149
func: FileSystemManager::FileSystemManager()
expression: esp_vfs_fat_sdspi_mount(VFS_MOUNT, &sd_host, &device_cfg, &sd_cfg, &sd_)
[FS] SD Card not present or mounting failed, using SPIFFS
[FS] SPIFFS usage: 18.38/757.66 KiB
[FS] SPIFFS will be used for persistent storage.
[FS] Dumping content of filesystem: /cfg
[FS] /cfg/ESP32CS/trains.json (433 bytes) mtime: Thu Aug 20 00:09:41 2020
[FS] /cfg/LCC/config (485 bytes) mtime: Thu Jan  1 04:59:59 1970
[FS] /cfg/LCC/cdi.xml (8184 bytes) mtime: Fri Oct 23 18:13:35 2020
[FS] /cfg/LCC/train.xml (5406 bytes) mtime: Fri Oct 23 18:13:35 2020
[FS] /cfg/LCC/tmptrain.xml (2593 bytes) mtime: Fri Oct 23 18:13:35 2020
[LCC] Initializing Stack (node-id: 5020103f000)
[WiFi] Starting WiFiManager
[SNTP] Polling pool.ntp.org for time updates
[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] Registering 3 - Trolley (idle: Off, limited: Off)
[TrainDB] Registering 4 - Amtrack (idle: Off, limited: Off)
[TrainDB] Found 2 persistent roster entries.

ESP32 Command Station Startup complete!

[WiFi] Starting WiFi Manager task
[WiFi] Initializing WiFi stack
I (1530) wifi:wifi driver task: 3ffd1938, prio:23, stack:6656, core=0
I (1533) wifi:wifi firmware version: f8b2044
I (1535) wifi:wifi certification version: v7.0
I (1539) wifi:config NVS flash: disabled
I (1543) wifi:config nano formating: disabled
I (1547) wifi:Init data frame dynamic rx buffer num: 32
I (1552) wifi:Init management frame dynamic rx buffer num: 32
I (1558) wifi:Init management short buffer num: 32
I (1562) wifi:Init dynamic tx buffer num: 32
I (1566) wifi:Init static rx buffer size: 1600
I (1571) wifi:Init static rx buffer num: 16
I (1574) wifi:Init dynamic rx buffer num: 32
[WiFi] Configuring Station (SSID: buelows)
D (1582) wifi:clear blacklist
[WiFi] Starting WiFi stack
V (1667) wifi:ht20 freq=2412, chan=1
D (1668) wifi:filter: set rx policy=0
I (1669) wifi:mode : sta (30:ae:a4:40:d0:a4)
D (1669) wifi:filter: set rx policy=1
D (1670) wifi:connect status 0 -> 0
[WiFi] [1/36] Waiting for SSID connection.
[WiFi] Setting ESP32 hostname to "esp32cs_5020103f000".
[WiFi] MAC Address: 30:ae:a4:40:d0:a4
[DHCP] Starting DHCP Client.
[WiFi] Station started, attempting to connect to SSID: buelows.
D (1694) wifi:Start wifi connect
D (1697) wifi:connect status 0 -> 0
D (1700) wifi:connect chan=0
V (1703) wifi:nvs=0, ssid=buelows, channel=255
V (1707) wifi:ssid=buelows match nvs 0, channel=255
D (1711) wifi:first chan=1
D (1714) wifi:connect status 0 -> 1
D (1717) wifi:filter: set rx policy=3
D (1720) wifi:clear scan ap list
D (1723) wifi:start scan: type=0x50f, priority=2, cb=0x40175e60, arg=0x0, ss_state=0x1, time=57006, index=0
V (1733) wifi:inter_channel_timeout: arg=0x0, ss_state=0x1
D (1738) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
V (1743) wifi:change: chan<1,0>, dur<0,120>
V (1747) wifi:enter start op, arg=0x3ffb7dd0
V (1751) wifi:scan operation: state=0x3, chan<1,0>, arg=0x3ffb7dd0, status=0
V (1758) wifi:scan specific ssid=buelows
V (1762) wifi:start max timer
Allocating new alias B89 for node 05020103f000
D (1885) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (1885) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
V (1886) wifi:change: chan<2,0>, dur<0,120>
V (1889) wifi:ht20 freq=2417, chan=2
V (1893) wifi:enter start op, arg=0x3ffb7dd0
V (1896) wifi:scan operation: state=0x3, chan<2,0>, arg=0x3ffb7dd0, status=0
V (1903) wifi:scan specific ssid=buelows
V (1907) wifi:start max timer
D (1916) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (1917) wifi:profile match: ss_state=0x7
V (1918) wifi:scan histroy table is not full yet, add
V (1922) wifi:add ssid=buelows, chan=2 to scan history
D (1927) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (1932) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (1939) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (1946) wifi:profile match: ss_state=0x7
V (1949) wifi:update scan history ssid=buelows, channel=2
D (1955) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (1959) wifi:profile match: ss_state=0x7
V (1963) wifi:update scan history ssid=buelows, channel=2
D (1968) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (1973) wifi:profile match: ss_state=0x7
V (1976) wifi:update scan history ssid=buelows, channel=2
D (1982) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (1986) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (1994) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (2000) wifi:profile match: ss_state=0x7
V (2004) wifi:update scan history ssid=buelows, channel=2
D (2009) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2014) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (2021) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (2027) wifi:profile match: ss_state=0x7
V (2031) wifi:update scan history ssid=buelows, channel=2
D (2036) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2041) wifi:profile match: ss_state=0x7
V (2045) wifi:update scan history ssid=buelows, channel=2
D (2050) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2055) wifi:profile match: ss_state=0x7
V (2058) wifi:update scan history ssid=buelows, channel=2
D (2064) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2068) wifi:profile match: ss_state=0x7
V (2072) wifi:update scan history ssid=buelows, channel=2
D (2077) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2082) wifi:find first mathched ssid, scan done
V (2086) wifi:back home chan=<1,0>, current chan=<2,0>
V (2091) wifi:ht20 freq=2412, chan=1
D (2095) wifi:filter: set rx policy=4
D (2098) wifi:first chan=1
V (2100) wifi:scan_done: arg=0x0, status=0, cur_time=434087, scan_id=128, scan state=0
V (2108) wifi:call scan_done cb, arg=0x0
D (2112) wifi:handoff_cb: status=0
V (2115) wifi:best bss has set.
D (2118) wifi:ap found, mac=24:4b:fe:33:9f:11
V (2122) wifi:bssid=24:4b:fe:33:9f:11, LR=0
D (2126) wifi:new_bss=0x3ffb6880, cur_bss=0x0, new_chan=<2,0>, cur_chan=1
D (2132) wifi:filter: set rx policy=5
I (2136) wifi:new:<2,0>, old:<1,0>, ap:<255,255>, sta:<2,0>, prof:1
V (2141) wifi:ht20 freq=2417, chan=2
D (2145) wifi:connect_op: status=0, auth=5, cipher=3 
D (2149) wifi:auth mode is not none
D (2688) wifi:connect_bss: auth=1, reconnect=0
I (2688) wifi:state: init -> auth (b0)
D (2689) wifi:start 1s AUTH timer
D (2689) wifi:clear scan ap list
D (2692) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2696) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2700) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2705) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2710) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (2716) wifi:recv auth: seq=2, status=0
I (2718) wifi:state: auth -> assoc (0)
D (2722) wifi:restart connect 1s timer for assoc
D (2729) wifi:recv assoc: type=0x10
D (2730) wifi:filter: set rx policy=6
I (2732) wifi:state: assoc -> run (10)
D (2736) wifi:start 10s connect timer for 4 way handshake
D (2741) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

V (2746) wifi:wpa_psk start
V (2749) wifi:wpa_psk handle succeed
V (2760) wifi:wpa_psk start
V (2761) wifi:wpa_psk handle succeed
I (2763) wifi:connected with buelows, aid = 6, channel 2, BW20, bssid = 24:4b:fe:33:9f:11
I (2765) wifi:security: WPA2-PSK, phy: bgn, rssi: -59
D (2770) wifi:remove all except 24:4b:fe:33:9f:11 from rc list
D (2775) wifi:clear blacklist
D (2778) wifi:filter: set rx policy=7
I (2781) wifi:pm start, type: 1

D (2785) wifi:Send sta connected event
D (2788) wifi:connect status 1 -> 5
D (2791) wifi:obss scan is disabled
D (2794) wifi:start obss scan: obss scan is stopped
[WiFi] Connected to SSID: buelows
[IPv4] [2/36] Waiting for IP address assignment.
[WiFi] IP address is 172.24.1.56, starting hub (if enabled) and uplink
[mDNS] Initializing mDNS system
[mDNS] Setting mDNS hostname to "esp32cs_5020103f000"
I (2822) wifi:Set ps type: 0

[httpd] Starting HTTP listener on port 80
[JMRI] Starting JMRI listener
Listening on port 80, fd 48
Listening on port 2560, fd 49
I (2838) wifi:AP's beacon interval = 102400 us, DTIM period = 1
[mDNS] Advertising _http._tcp:80.
[mDNS] Advertising _esp32cs._tcp:2560.
Incoming connection from 172.24.1.11, fd 50.
Incoming connection from 172.24.1.11, fd 51.
[SNTP] Received time update, new localtime: Fri Oct 23 18:15:34 2020

Incoming connection from 172.24.1.11, fd 50.
Incoming connection from 172.24.1.11, fd 51.
[TaskMon] uptime: 00:00:45 freeHeap: 174400, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB
[TaskMon] uptime: 00:01:30 freeHeap: 174400, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB
[TaskMon] uptime: 00:02:15 freeHeap: 174400, largest free block: 113792, tasks: 16, mainBufferPool: 0.67kB
roadsnail commented 3 years ago

@atanisoft . Yes I agree regarding the Wroom-32 module antenna sitting on the PCB. I too wondered if there was a lovely ground plane running under the antenna. I even broke up some of the PCB, but the little I removed is just plain board. Also, I have a different module, the NodeMCU variant I mentioned earlier, where the Wroom module antenna also sits over the PCB. This is the variant which delivers full power with the same build flashed! This is driving me nuts!

@buelowp . Thanks for supplying your log. I'll take a look at it and see if I can spot any glaring differences. You mention that your AP sees a signal level of -69dBm. Is that the sort of level you would expect given the distance of your CS from the AP?

buelowp commented 3 years ago

Yes, it's oscillating between -70 and -66 dBm right now, and I've got a good connection. We have mesh here, so I can tell which node it's attached to, and I can compare that signal strength to other devices on the same node. It's sitting next to my old iPad I use for work, and the iPad is reporting -72 dBm, so it seems to be correct.

roadsnail commented 3 years ago

@buelowp . Okay thanks. As mentioned above, I see around -80dBm at my access point. (I only have the one). In comparison, I have an ESP8266 based sensor sitting about 2 feet away from me, and the signal level is reported at -56dBm.

EDIT. Also my AP monitoring SW reports multiple excessive retries while communicating with my CS. So bottom line, I can communicate with the ESPDuino, but the connection is not at all robust given the distance from AP (about 10feet). As I mentioned above, if I flash micropython onto the module I see a robust signal from the same device, so I know my boards are capable of a decent signal.

I know I must be overlooking something really basic here, but for the life of me, I can't see what! I am happy to be educated though if someone can point me in the right direction.

atanisoft commented 3 years ago

In testing https://github.com/atanisoft/ESP32CommandStation/pull/90 I noticed the following output (from an esp32 that went through factory reset process):

[WiFi] Configuring SoftAP (SSID: esp32cs_5020103f000)
[WiFi] Configuring Station (SSID: TheHomeNet)
[WiFi] Starting WiFi stack
[WiFi] Setting ESP32 hostname to "esp32cs_5020103f000".
[WiFi] MAC Address: 30:ae:a4:c1:54:a8
[DHCP] Starting DHCP Client.
[WiFi] Adjusting maximum WiFi TX power 78 -> 46.
[WiFi] Station started, attempting to connect to SSID: TheHomeNet.

So something is not 100% correct somewhere as the maximum TX power should be 78 by default.

EDIT: note that /config shows it correctly as 78. I'm thinking that the loading of config is not being done atomically and will be looking at adjusting the code for that before going further.

roadsnail commented 3 years ago

In testing #90 I noticed the following output (from an esp32 that went through factory reset process):

Just to be clear - Are you referring to flash erase, then reflashing espressiff 'AT' binaries?

atanisoft commented 3 years ago

Just to be clear - Are you referring to flash erase, then reflashing espressiff 'AT' binaries?

erase flash followed by a reflash of CS binary. I have not use the AT binary on any esp32 (only esp8266).

EDIT: also a power cycle (pull usb out and plugin again)

roadsnail commented 3 years ago

Okay, thanks. That's interesting.

I'm currently re-building my build environment just in case there is an issue there. Have just managed to screw things up, so one step forwards two steps back. Ho hum!