events.action: opened
events.author: marjon-halter
events.masked_author: username_0
events.text: Enabled the TCP Echo project.
  Setup my laptop to be on the same subnet as the ESP32-WROVER board.
  Installed xinetd to get an echo server running.
  
  Configured the TCP Echo project to:
  1. Connect to AP
  2. Send echo messages.
  3. Disconnect from AP
  4. Sleep for a fixed time.
  5. Wake up.
  6. Repeat.
  
  **System information**
  - Hardware: Espressif Demo board for ESP32-WROVER
  - IDE used:Eclipse
  - Operating System [Linux]
  - Version of Amazon FreeRTOS (run ``git describe --tags`` to find it): v1.4.6-61-gf0c0efc7
  - Project [TCP Echo] with addition of code to disconnect from AP, sleep and reconnect to AP on wakeup.
  
  **Expected behavior**
  Expect the TCP stack to handle the error returned by wifi driver and recover.
  
  **Screenshots or console output**
  ```cpp
  --- idf_monitor on /dev/ttyUSB0 115200 ---
  --- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
  ets Jun  8 2016 00:22:57
  
  rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
  flash read err, 1000
  ets_main.c 371 
  ets Jun  8 2016 00:22:57
  
  rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
  configsip: 0, SPIWP:0xee
  clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
  mode:DIO, clock div:2
  load:0x3fff0018,len:4
  load:0x3fff001c,len:6312
  load:0x40078000,len:11264
  ho 0 tail 12 room 4
  load:0x40080000,len:6008
  0x40080000: _iram_start at /home/marjon/workspace/amazon-freertos/lib/FreeRTOS/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685
  
  entry 0x4008032c
  0x4008032c: _KernelExceptionVector at ??:?
  
  I (31) boot: ESP-IDF v3.1.1-18-g607d2ce34 2nd stage bootloader
  I (31) boot: compile time 14:23:45
  I (31) boot: Enabling RNG early entropy source...
  I (37) boot: SPI Speed      : 40MHz
  I (41) boot: SPI Mode       : DIO
  I (45) boot: SPI Flash Size : 16MB
  I (49) boot: Partition Table:
  I (52) boot: ## Label            Usage          Type ST Offset   Length
  I (60) boot:  0 nvs              WiFi data        01 02 00010000 00006000
  I (67) boot:  1 otadata          OTA data         01 00 00016000 00002000
  I (75) boot:  2 phy_init         RF data          01 01 00018000 00001000
  I (82) boot:  3 ota_0            OTA app          00 10 00020000 00177000
  I (90) boot:  4 ota_1            OTA app          00 11 001a0000 00177000
  I (97) boot:  5 storage          WiFi data        01 02 00317000 00010000
  I (105) boot: End of partition table
  E (109) boot: ota data partition invalid and no factory, will try all partitions
  I (117) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x14160 ( 82272) map
  I (155) esp_image: segment 1: paddr=0x00034188 vaddr=0x3ffc0000 size=0x02bf8 ( 11256) load
  I (159) esp_image: segment 2: paddr=0x00036d88 vaddr=0x3ffc2bf8 size=0x00000 (     0) load
  I (161) esp_image: segment 3: paddr=0x00036d90 vaddr=0x40080000 size=0x00400 (  1024) load
  0x40080000: _iram_start at /home/marjon/workspace/amazon-freertos/lib/FreeRTOS/portable/ThirdParty/GCC/Xtensa_ESP32/xtensa_vectors.S:1685
  
  I (171) esp_image: segment 4: paddr=0x00037198 vaddr=0x40080400 size=0x08e78 ( 36472) load
  I (194) esp_image: segment 5: paddr=0x00040018 vaddr=0x400d0018 size=0x75a28 (481832) map
  0x400d0018: _stext at ??:?
  
  I (363) esp_image: segment 6: paddr=0x000b5a48 vaddr=0x40089278 size=0x06eb4 ( 28340) load
  0x40089278: coex_arbit_clean_overtime_until at ??:?
  
  I (376) esp_image: segment 7: paddr=0x000bc904 vaddr=0x400c0000 size=0x00000 (     0) load
  I (376) esp_image: segment 8: paddr=0x000bc90c vaddr=0x50000000 size=0x00000 (     0) load
  I (392) boot: Loaded app from partition at offset 0x20000
  I (392) boot: ota rollback check done
  I (393) boot: Disabling RNG early entropy source...
  I (398) cpu_start: Pro cpu up.
  I (402) cpu_start: Single core mode
  I (407) heap_init: Initializing. RAM available for dynamic allocation:
  I (413) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
  I (419) heap_init: At 3FFD2248 len 0000DDB8 (55 KiB): DRAM
  I (425) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
  I (432) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
  I (438) heap_init: At 4009012C len 0000FED4 (63 KiB): IRAM
  I (444) cpu_start: Pro cpu start user code
  I (127) cpu_start: Starting scheduler on PRO CPU.
  I (208) wifi: wifi driver task: 3ffda368, prio:23, stack:3584, core=0
  I (208) wifi: wifi firmware version: 8f35e40
  I (208) wifi: config NVS flash: enabled
  I (208) wifi: config nano formating: disabled
  I (208) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
  I (218) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
  I (238) wifi: Init dynamic tx buffer num: 32
  I (238) wifi: Init data frame dynamic rx buffer num: 5
  I (238) wifi: Init management frame dynamic rx buffer num: 5
  I (248) wifi: Init static rx buffer size: 1600
  I (248) wifi: Init static rx buffer num: 5
  I (258) wifi: Init dynamic rx buffer num: 5
  0 9 [main] WiFi module initialized. Connecting to AP <accesspoint>...
  W (268) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
  I (438) phy: phy_version: 4000, b6198fa, Sep  3 2018, 15:11:06, 0, 2
  I (478) wifi: mode : sta (30:ae:a4:cf:0c:64)
  I (478) WIFI: SYSTEM_EVENT_STA_START
  I (848) wifi: n:3 0, o:1 0, ap:255 255, sta:3 0, prof:1
  I (1828) wifi: state: init -> auth (b0)
  I (1838) wifi: state: auth -> assoc (0)
  I (1848) wifi: state: assoc -> run (10)
  I (1858) wifi: connected with <accesspoint>, channel 3
  I (1858) wifi: pm start, type: 1
  
  I (1858) WIFI: SYSTEM_EVENT_STA_CONNECTED
  1 420 [IP-task] vDHCPProcess: offer a0201dfip
  I (4388) event: sta ip: 10.2.1.223, mask: 255.255.252.0, gw: 10.2.1.1
  I (4388) WIFI: SYSTEM_EVENT_STA_GOT_IP
  2 422 [IP-task] vDHCPProcess: offer a0201dfip
  3 423 [main] WiFi Connected to AP. Creating tasks which use network...
  4 423 [main] ERROR: Failed to provision certificate -1 
  5 424 [main] Write certificate...
  6 424 [main] ERROR: Failed to provision certificate 7 
  7 425 [main] ERROR: Failed to provision private key 7 
  I (4418) wifi: state: run -> init (0)
  I (4418) wifi: pm stop, total sleep time: 2101247 us / 2560729 us
  
  I (4428) wifi: n:3 0, o:3 0, ap:255 255, sta:3 0, prof:1
  I (4438) WIFI: SYSTEM_EVENT_STA_DISCONNECTED: 8
  8 425 [Echo0] WiFi module initialized. Connecting to AP <accesspoint>...
  I (4558) wifi: n:3 0, o:3 0, ap:255 255, sta:3 0, prof:1
  I (5538) wifi: state: init -> auth (b0)
  I (5548) wifi: state: auth -> assoc (0)
  I (5558) wifi: state: assoc -> run (10)
  I (5578) wifi: connected with <accesspoint>, channel 3
  I (5578) wifi: pm start, type: 1
  
  I (5578) WIFI: SYSTEM_EVENT_STA_CONNECTED
  9 733 [IP-task] vDHCPProcess: offer a0201dfip
  I (7518) event: sta ip: 10.2.1.223, mask: 255.255.252.0, gw: 10.2.1.1
  I (7518) WIFI: SYSTEM_EVENT_STA_GOT_IP
  10 735 [IP-task] vDHCPProcess: offer a0201dfip
  11 735 [Echo0] WiFi Connected to AP. Creating tasks which use network...
  12 735 [Echo0] Connecting to echo server
  13 936 [Echo0] Echo demo failed to connect to echo server 10.2.2.248.
  I (9678) wifi: state: run -> init (0)
  I (9678) wifi: pm stop, total sleep time: 2865884 us / 4092174 us
  
  I (9678) wifi: n:3 0, o:3 0, ap:255 255, sta:3 0, prof:1
  I (9678) WIFI: SYSTEM_EVENT_STA_DISCONNECTED: 8
  14 951 [Echo0] Connecting to echo server
  15 1451 [Echo0] Echo demo failed to connect to echo server 10.2.2.248.
  16 1466 [Echo0] Connecting to echo server
  E (15678) NetInterface: Failed to tx buffer 0x3ffdd522, len 42, err -16
  17 1751 [Echo0] Echo demo failed to connect to echo server 10.2.2.248.
  18 1766 [Echo0] Connecting to echo server
  E (18678) NetInterface: Failed to tx buffer 0x3ffdd522, len 42, err -16
  19 2051 [Echo0] Echo demo failed to connect to echo server 10.2.2.248.
  20 2066 [Echo0] Connecting to echo server
  E (21678) NetInterface: Failed to tx buffer 0x3ffdd522, len 42, err -16
  21 2351 [Echo0] Echo demo failed to connect to echo server 10.2.2.248.
  ```
  
  **To reproduce**
  Steps to reproduce the behavior:
  See description on top of this ticket.
  
  **Additional context**
  Add any other context about the problem here.
  
  Thank you!
events.title: NetInterface: Failed to tx buffer ..., err -16
events.type: issue
events.action: created
events.author: aggarg
events.masked_author: username_1
events.text: Looking at the logs, it seems that it is failing to provision the certificate and key.
  
  ```
  4 423 [main] ERROR: Failed to provision certificate -1 
  5 424 [main] Write certificate...
  6 424 [main] ERROR: Failed to provision certificate 7 
  7 425 [main] ERROR: Failed to provision private key 7 
  ```
  
  Would you please double check that you have set ```keyCLIENT_CERTIFICATE_PEM``` and ```keyCLIENT_PRIVATE_KEY_PEM``` in ```aws_clientcredential_keys.h```? The correct formatting should look something like this:
  
  ```
  #define keyCLIENT_CERTIFICATE_PEM \
  "-----BEGIN CERTIFICATE-----\n" \
  "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\n" \
  "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb\n" \
  "cccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccc\n" \
  "dddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddd\n" \
  "eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee\n" \
  "ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff\n" \
  "gggggggggggggggggggggggggggggggggggggggggggggggggggggggggggggggg\n" \
  "hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh\n" \
  "iiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiii\n" \
  "jjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjj\n" \
  "kkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkk\n" \
  "llllllllllllllllllllllllllllllllllllllllllllllllllllllllllllllll\n" \
  "mmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmm\n" \
  "nnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnn\n" \
  "oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo\n" \
  "pppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp\n" \
  "qqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqq\n" \
  "rrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr\n" \
  "-----END CERTIFICATE-----\n"
  ```
  
  ```
  #define keyCLIENT_PRIVATE_KEY_PEM \
  "-----BEGIN RSA PRIVATE KEY-----\n" \
  "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa\n" \
  "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb\n" \
  "cccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccccc\n" \
  "dddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddddd\n" \
  "eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee\n" \
  "ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff\n" \
  "gggggggggggggggggggggggggggggggggggggggggggggggggggggggggggggggg\n" \
  "hhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhhh\n" \
  "iiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiiii\n" \
  "jjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjjj\n" \
  "kkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkk\n" \
  "llllllllllllllllllllllllllllllllllllllllllllllllllllllllllllllll\n" \
  "mmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmmm\n" \
  "nnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnn\n" \
  "oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo\n" \
  "pppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppppp\n" \
  "qqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqq\n" \
  "rrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr\n" \
  "ssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssssss\n" \
  "tttttttttttttttttttttttttttttttttttttttttttttttttttttttttttttttt\n" \
  "uuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuuu\n" \
  "vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv\n" \
  "wwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwwww\n" \
  "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx\n" \
  "yyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy\n" \
  "-----END RSA PRIVATE KEY-----\n"
  ```
  
  Thanks.
events.type: comment
events.action: created
events.author: marjon-halter
events.masked_author: username_0
events.text: Fair comment, but I was just testing connecting to the access point and doing a TCP echo to a local echo server (my laptop). I doubt it will need the AWS client keys for that task?
events.type: comment
events.action: created
events.author: aggarg
events.masked_author: username_1
events.text: Yes you are right. I am setting it up to see what might be going wrong.
  
  The other thing that you might try meanwhile is to check that the laptop's firewall is not blocking the incoming connection as you are failing to connect:
  
  ```
  12 735 [Echo0] Connecting to echo server
  13 936 [Echo0] Echo demo failed to connect to echo server 10.2.2.248.
  ```
  
  Would you mind sharing your changes to the TCP Echo demo so that I can replicate the same scenario.
  
  Thank you for your patience.
events.type: comment
events.action: created
events.author: marjon-halter
events.masked_author: username_0
events.text: Is there a private place I can share the file changes?
events.type: comment
events.action: created
events.author: marjon-halter
events.masked_author: username_0
events.text: https://github.com/username_0/amazon-freertos --> tcp_echo_demo. It would not repeat it so quickly now, but it still happens eventually. The bug is intermittent. The wifi driver has to NOT yet transition from assoc->run, but the IP stack is already sending data out to the wifi driver.
  i.e.
  `I (5538) wifi: state: init -> auth (b0)`
  `I (5548) wifi: state: auth -> assoc (0)`
  `I (5558) wifi: state: assoc -> run (10)`
  `I (5578) wifi: connected with <accesspoint>, channel 3`
  `I (5578) wifi: pm start, type: 1`
events.type: comment
events.action: closed
events.author: qiutongs
events.masked_author: username_2
events.type: issue