search

manuelbl / ttn-esp32

The Things Network device library for ESP32 (ESP-IDF) and SX127x based devices
MIT License
308 stars 63 forks source link

xQueueReceive stuck #44

Closed alkosa closed 1 year ago

alkosa commented 3 years ago

Hi,

I have a ESP32 Heltec V2 Lora board. I use this ttn-esp32 firmware pack. I try to send a sensor data to the chirpstack Lorawan system, but I have a problem.

The Joining to the chirpstack system is OK. I send 2 byte data. After that I wait 30 second and I try to send another data, but It is not successfull. It is stopped the firmware. After the debuging of the firmware, I have realized, the freezing is in the ttn.c/ttn_transmit_message function:

while (true)
 {
        ttn_lmic_event_t result;
        xQueueReceive(lmic_event_queue, (void*)&result, portMAX_DELAY);
       ...
}

What is the problem?

Thank you very much for your help

manuelbl commented 3 years ago

This library is built to work with The Things Network, hence the name. It has not been tested with ChirpStack. So I can't really tell why it is stuck.

The code location you have highlighted is where the current task waits until the transmission, which takes place in a separate thread, has completed. One of the reasons the transmission takes longer than expected is that the link budget has been used up and the device must wait until it is allowed to transmit again. This is more likely if the device uses a low data rate. But I am not familiar with the ChirpStack details.

alkosa commented 3 years ago

Hi Manuel.

Thank you for your answer.

I do not know the problem is coming from the chirpstack system. I do not know the problem has a connection between the chirpstack and the The Things Network?

I use:

The first data sending is OK.

Debug outputs:

System Init

[0;32mI (12) boot: ESP-IDF v4.4-dev-2928-gd5f58ab135-dirty 2nd stage bootloader[0m
[0;32mI (12) boot: compile time 16:27:09[0m
[0;32mI (13) boot: chip revision: 1[0m
[0;32mI (16) boot_comm: chip revision: 1, min. bootloader chip revision: 0[0m
[0;32mI (23) boot.esp32: SPI Speed      : 40MHz[0m
[0;32mI (28) boot.esp32: SPI Mode       : DIO[0m
[0;32mI (32) boot.esp32: SPI Flash Size : 2MB[0m
[0;32mI (37) boot: Enabling RNG early entropy source...[0m
[0;32mI (42) boot: Partition Table:[0m
[0;32mI (46) boot: ## Label            Usage          Type ST Offset   Length[0m
[0;32mI (53) boot:  0 nvs              WiFi data        01 02 00009000 00006000[0m
[0;32mI (61) boot:  1 phy_init         RF data          01 01 0000f000 00001000[0m
[0;32mI (68) boot:  2 factory          factory app      00 00 00010000 00100000[0m
[0;32mI (76) boot: End of partition table[0m
[0;32mI (80) boot_comm: chip revision: 1, min. application chip revision: 0[0m
[0;32mI (87) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=0ca60h ( 51808) map[0m
[0;32mI (114) esp_image: segment 1: paddr=0001ca88 vaddr=3ffb0000 size=02920h ( 10528) load[0m
[0;32mI (119) esp_image: segment 2: paddr=0001f3b0 vaddr=40080000 size=00c68h (  3176) load[0m
[0;32mI (121) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=2404ch (147532) map[0m
[0;32mI (182) esp_image: segment 4: paddr=00044074 vaddr=40080c68 size=0dabch ( 55996) load[0m
[0;32mI (205) esp_image: segment 5: paddr=00051b38 vaddr=50000000 size=00010h (    16) load[0m
[0;32mI (213) boot: Loaded app from partition at offset 0x10000[0m
[0;32mI (213) boot: Disabling RNG early entropy source...[0m
[0;32mI (225) cpu_start: Pro cpu up.[0m
[0;32mI (226) cpu_start: Starting app cpu, entry point is 0x400811d4[0m
[0;32mI (220) cpu_start: App cpu up.[0m
[0;32mI (240) cpu_start: Pro cpu start user code[0m
[0;32mI (240) cpu_start: cpu freq: 160000000[0m
[0;32mI (240) cpu_start: Application information:[0m
[0;32mI (244) cpu_start: Project name:     ttn-esp32-heltek-v2[0m
[0;32mI (250) cpu_start: App version:      c62aafc0-dirty[0m
[0;32mI (256) cpu_start: Compile time:     Nov  9 2021 08:44:39[0m
[0;32mI (262) cpu_start: ELF file SHA256:  e015672c165b3727...[0m
[0;32mI (268) cpu_start: ESP-IDF:          v4.4-dev-2928-gd5f58ab135-dirty[0m
[0;32mI (275) heap_init: Initializing. RAM available for dynamic allocation:[0m
[0;32mI (282) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM[0m
[0;32mI (288) heap_init: At 3FFB3718 len 0002C8E8 (178 KiB): DRAM[0m
[0;32mI (295) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM[0m
[0;32mI (301) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[0m
[0;32mI (307) heap_init: At 4008E724 len 000118DC (70 KiB): IRAM[0m
[0;32mI (315) spi_flash: detected chip: winbond[0m
[0;32mI (318) spi_flash: flash io: dio[0m
[0;33mW (322) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.[0m
[0;32mI (336) cpu_start: Starting scheduler on PRO CPU.[0m
[0;32mI (0) cpu_start: Starting scheduler on APP CPU.[0m

Application Init (Adc, GPIO and the starting of the joining to chirpstack)

[0;32mI (429) MAIN: This is esp32 chip with 2 CPU cores, WiFi/BT/BLE, [0m
[0;32mI (429) MAIN: silicon revision 1, [0m
[0;32mI (429) MAIN: 2MB external flash[0m
[0;32mI (439) MAIN: Minimum free heap size: 290032 bytes[0m
[0;32mI (439) MAIN: [APP] Startup..[0m
[0;32mI (449) MAIN: [APP] Free memory: 290484 bytes[0m
[0;32mI (449) MAIN: [APP] IDF version: v4.4-dev-2928-gd5f58ab135-dirty[0m
[0;32mI (459) ADC_SAMPLE: eFuse Two Point: NOT supported[0m
[0;32mI (459) ADC_SAMPLE: eFuse Vref: Supported[0m
[0;32mI (469) ADC_SAMPLE: Characterized using eFuse Vref[0m
[0;32mI (469) gpio: GPIO[16]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 [0m
[0;32mI (479) SSD1306: OLED configured successfully[0m
[0;32mI (649) ttn_prov: DevEUI, AppEUI/JoinEUI and AppKey saved in NVS storage[0m
[0;32mI (649) MYLORA: Joining...[0m
[0;32mI (769) ttn_hal: IO initialized[0m
[0;32mI (769) ttn_hal: SPI initialized[0m
[0;32mI (769) ttn_hal: Timer initialized[0m

For example, I don't know why the LORA joining precedes IO, SPI, Timer Init?

In the code the ttn initialization is before than the LORA connection...

the code (mylora.c):

// Initialize TTN
    ttn_init();

    // Configure the SX127x pins
    ttn_configure_pins(TTN_SPI_HOST, TTN_PIN_NSS, TTN_PIN_RXTX, TTN_PIN_RST, TTN_PIN_DIO0, TTN_PIN_DIO1);

    // The below line can be commented after the first run as the data is saved in NVS
    ttn_provision(devEui, appEui, appKey);

    // Register callback for received messages
    ttn_on_message((ttn_message_cb )messageReceived);

    ttn_set_adr_enabled(true);
    ttn_set_data_rate(TTN_DR_EU868_SF12);
    ttn_set_max_tx_pow(14);

    ESP_LOGI(TAG,"Joining...");
    ssd1306DisplayText("Joining...");
    //ssd1306DisplayText("Sending message8");
    if (ttn_join())
    {
        isLoraJoined = true;
        ESP_LOGI(TAG,"Joined.");
        //ssd1306DisplayText("Joined...");
        printLcdMessageWithLoraInfos("Joined...");
        printAllRFSettings();
        vTaskDelay(1 * pdMS_TO_TICKS(1000));
        xTaskCreate(sendMessages, "send_messages", 1024 * 4, (void* )0, XTASK_LORA_JOIN_TASK_PRIORITY, NULL);
    }
    else
    {
        ESP_LOGI(TAG,"Join failed. Goodbye");
        ssd1306DisplayText("Join failed. Restart");
        myLoraReset();
    }

Joining and the first sending is successful

[0;32mI (799) ttn: event EV_JOINING[0m
[0;32mI (799) ttn: event EV_TXSTART[0m
[0;32mI (7249) ttn: event EV_RXSTART[0m
[0;32mI (9119) ttn: event EV_JOINED[0m
[0;32mI (9119) MYLORA: Joined.[0m
[0;32mI (9249) MYLORA: TX : SF12, BW 125kHz, 868.5 MHz[0m
[0;32mI (9249) MYLORA: RX1: SF12, BW 125kHz, 868.5 MHz[0m
[0;32mI (9249) MYLORA: RX2: not used[0m
[0;32mI (9259) MYLORA: RSSI -4dbm[0m
[0;32mI (10259) MYLORA: Sending message...[0m
[0;32mI (10389) MYLORA: TX : SF12, BW 125kHz, 868.5 MHz[0m
[0;32mI (10389) MYLORA: RX1: SF12, BW 125kHz, 868.5 MHz[0m
[0;32mI (10389) MYLORA: RX2: not used[0m
[0;32mI (10389) MYLORA: RSSI -4dbm[0m
[0;32mI (10389) ttn: event EV_TXSTART[0m
[0;32mI (12539) ttn: event EV_RXSTART[0m
[0;32mI (13899) MYLORA: Message of 0 bytes received on port 0:[0m
[0;32mI (13899) MYLORA: Message sent.[0m  
[0;32mI (13899) ttn: event EV_TXCOMPLETE[0m

After 30seconds I try to resend the data...

[0;32mI (44029) MYLORA: Sending message...[0m
[0;32mI (44159) MYLORA: TX : SF12, BW 125kHz, 868.1 MHz[0m
[0;32mI (44159) MYLORA: RX1: SF12, BW 125kHz, 868.1 MHz[0m
[0;32mI (44159) MYLORA: RX2: not used[0m
[0;32mI (44159) MYLORA: RSSI -3dbm[0m
[0;32mI (60469) MYLORA: Lora Sending Data Timeout.[0m //Stuck after 20 seconds I restart the MCU
[0;32mI (60589) MYLORA: Restarting in 3 seconds...[0m
[0;32mI (61589) MYLORA: Restarting in 2 seconds...[0m
[0;32mI (62589) MYLORA: Restarting in 1 seconds...[0m
[0;32mI (63589) MYLORA: Restarting in 0 seconds...[0m

My easy solution is: I wait 20seconds, if the sending is stuck, I reset the MCU. Ok it is a primitive solution but it is working.

it would be good to know what is the root cause of the problem... I would like to remove this restart solution because for example i do not send data via LORA to the end node

Thank you for you help.:)

manuelbl commented 3 years ago

Sending a message every 30s on SF12 is way over the allowed duty cycle of TTN. Most likely, the transmission is delay on purpose to enforce the duty cycle limits.

Either wait longer between messages, change the data rate or both.

alkosa commented 3 years ago

You are right!!

I have modified the spread factor from SF12 to SF7, it is working better.

[0;32mI (8839) MYLORA: Joined.[0m
[0;32mI (8959) MYLORA: TX : SF7, BW 125kHz, 868.3 MHz[0m
[0;32mI (8959) MYLORA: RX1: SF7, BW 125kHz, 868.3 MHz[0m
[0;32mI (8959) MYLORA: RX2: not used[0m
[0;32mI (8969) MYLORA: RSSI -41dbm[0m

[0;32mI (9969) MYLORA: Sending message...[0m
[0;32mI (10099) MYLORA: TX : SF7, BW 125kHz, 868.3 MHz[0m
[0;32mI (10099) MYLORA: RX1: SF7, BW 125kHz, 868.3 MHz[0m
[0;32mI (10099) MYLORA: RX2: not used[0m
[0;32mI (10099) MYLORA: RSSI -41dbm[0m
[0;32mI (10099) ttn: event EV_TXSTART[0m
[0;32mI (11139) ttn: event EV_RXSTART[0m
[0;32mI (12139) ttn: event EV_RXSTART[0m
[0;32mI (12379) MYLORA: Message sent.[0m
[0;32mI (12379) ttn: event EV_TXCOMPLETE[0m

[0;32mI (42509) MYLORA: Sending message...[0m
[0;32mI (42639) MYLORA: TX : SF7, BW 125kHz, 868.1 MHz[0m
[0;32mI (42639) MYLORA: RX1: SF7, BW 125kHz, 868.1 MHz[0m
[0;32mI (42639) MYLORA: RX2: SF12, BW 125kHz, 869.5 MHz[0m
[0;32mI (42639) MYLORA: RSSI -41dbm[0m
[0;32mI (42649) ttn: event EV_TXSTART[0m
[0;32mI (43679) ttn: event EV_RXSTART[0m
[0;32mI (44679) ttn: event EV_RXSTART[0m
[0;32mI (44919) MYLORA: Message sent.[0m
[0;32mI (44919) ttn: event EV_TXCOMPLETE[0m

[0;32mI (75059) MYLORA: Sending message...[0m
[0;32mI (75189) MYLORA: TX : SF7, BW 125kHz, 868.5 MHz[0m
[0;32mI (75189) MYLORA: RX1: SF7, BW 125kHz, 868.5 MHz[0m
[0;32mI (75189) MYLORA: RX2: SF12, BW 125kHz, 869.5 MHz[0m
[0;32mI (75189) MYLORA: RSSI -41dbm[0m
[0;32mI (75199) ttn: event EV_TXSTART[0m
[0;32mI (76229) ttn: event EV_RXSTART[0m
[0;32mI (77229) ttn: event EV_RXSTART[0m
[0;32mI (77469) MYLORA: Message sent.[0m
[0;32mI (77469) ttn: event EV_TXCOMPLETE[0m

[0;32mI (107609) MYLORA: Sending message...[0m
[0;32mI (107739) MYLORA: TX : SF7, BW 125kHz, 867.7 MHz[0m
[0;32mI (107739) MYLORA: RX1: SF7, BW 125kHz, 867.7 MHz[0m
[0;32mI (107739) MYLORA: RX2: SF12, BW 125kHz, 869.5 MHz[0m
[0;32mI (107739) MYLORA: RSSI -41dbm[0m
[0;32mI (107749) ttn: event EV_TXSTART[0m
[0;32mI (108779) ttn: event EV_RXSTART[0m
[0;32mI (109779) ttn: event EV_RXSTART[0m
[0;32mI (110019) MYLORA: Message sent.[0m
[0;32mI (110019) ttn: event EV_TXCOMPLETE[0m

[0;32mI (140159) MYLORA: Sending message...[0m
[0;32mI (140289) MYLORA: TX : SF7, BW 125kHz, 868.5 MHz[0m
[0;32mI (140289) MYLORA: RX1: SF7, BW 125kHz, 868.5 MHz[0m
[0;32mI (140289) MYLORA: RX2: SF12, BW 125kHz, 869.5 MHz[0m
[0;32mI (140289) MYLORA: RSSI -41dbm[0m
[0;32mI (140299) ttn: event EV_TXSTART[0m
[0;32mI (141329) ttn: event EV_RXSTART[0m
[0;32mI (142329) ttn: event EV_RXSTART[0m
[0;32mI (142569) MYLORA: Message sent.[0m
[0;32mI (142569) ttn: event EV_TXCOMPLETE[0m

Thank you for your help. :)

Br: Sándor.

xssfox commented 4 months ago

If anyone else comes across this behaviour another reason can be that the DIO pins are misconfigured causing the esp32 to not realise that a packet rx has occured