esp-adf icon indicating copy to clipboard operation
esp-adf copied to clipboard

Dueros demo error: AUDIO_EVT: There is no space in external queue (AUD-3818)

Open lanistor opened this issue 2 years ago • 2 comments

I ran Dueros' Demo, and there was no response to the voice interaction step. When I manually clicked the Rec button, it would report warn: W (661493) AUDIO_EVT: There is no space in external queue.

Development board: ESP32-Lyrat-Mini V1.2 ADF version: release/v2.4 IDF version: release/v4.4 Build on: MacOS 12

lanistor avatar May 12 '22 16:05 lanistor

Full log:

--- idf_monitor on /dev/cu.SLAB_USBtoUART 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
I (10) boot: ESP-IDF v4.4.1-91-g36823b45cc-dirty 2nd stage bootloader
I (10) boot: compile time 01:00:42
I (11) boot: chip revision: 3
I (14) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (21) qio_mode: Enabling default flash chip QIO
I (26) boot.esp32: SPI Speed      : 80MHz
I (31) boot.esp32: SPI Mode       : QIO
I (35) boot.esp32: SPI Flash Size : 4MB
I (40) boot: Enabling RNG early entropy source...
I (45) boot: Partition Table:
I (49) boot: ## Label            Usage          Type ST Offset   Length
I (56) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (64) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (71) boot:  2 factory          factory app      00 00 00010000 00310000
I (79) boot: End of partition table
I (83) boot_comm: chip revision: 3, min. application chip revision: 0
I (90) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=6b7f8h (440312) map
I (220) esp_image: segment 1: paddr=0007b820 vaddr=3ffb0000 size=041f0h ( 16880) load
I (225) esp_image: segment 2: paddr=0007fa18 vaddr=40080000 size=00600h (  1536) load
I (226) esp_image: segment 3: paddr=00080020 vaddr=400d0020 size=14c9f8h (1362424) map
I (610) esp_image: segment 4: paddr=001cca20 vaddr=40080600 size=16cb4h ( 93364) load
I (640) esp_image: segment 5: paddr=001e36dc vaddr=50000000 size=00010h (    16) load
I (652) boot: Loaded app from partition at offset 0x10000
I (652) boot: Disabling RNG early entropy source...
I (663) psram: This chip is ESP32-D0WD
I (664) spiram: Found 64MBit SPI RAM device
I (664) spiram: SPI RAM mode: flash 80m sram 80m
I (669) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (676) cpu_start: Pro cpu up.
I (680) cpu_start: Starting app cpu, entry point is 0x4008163c
0x4008163c: call_start_cpu1 at /Users/Shared/SDK/esp/esp-idf/components/esp_system/port/cpu_start.c:160

I (0) cpu_start: App cpu up.
I (1161) spiram: SPI SRAM memory test OK
I (1170) cpu_start: Pro cpu start user code
I (1170) cpu_start: cpu freq: 240000000
I (1170) cpu_start: Application information:
I (1173) cpu_start: Project name:     esp_dueros
I (1178) cpu_start: App version:      v2.3-277-g4f84517-dirty
I (1184) cpu_start: Compile time:     May 13 2022 01:01:29
I (1191) cpu_start: ELF file SHA256:  470c97f7785df1c6...
I (1197) cpu_start: ESP-IDF:          v4.4.1-91-g36823b45cc-dirty
I (1204) heap_init: Initializing. RAM available for dynamic allocation:
I (1211) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (1217) heap_init: At 3FFB7458 len 00028BA8 (162 KiB): DRAM
I (1223) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1230) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1236) heap_init: At 400972B4 len 00008D4C (35 KiB): IRAM
I (1243) spiram: Adding pool of 4084K of external SPI memory to heap allocator
I (1251) spi_flash: detected chip: gd
I (1255) spi_flash: flash io: qio
W (1259) spi_flash: Detected size(8192k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1273) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1288) spiram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1327) DUEROS: ADF version is v2.3-277-g4f84517-dirty
I (1333) DRV8311: ES8311 in Slave mode
I (1344) gpio: GPIO[21]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
W (1389) I2C_BUS: i2c_bus_create:57: I2C bus has been already created, [port:0]
I (1392) gpio: GPIO[13]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1402) SDCARD: Using 1-line SD mode, 4-line SD mode,  base path=/sdcard
I (1474) SDCARD: CID name ASTC!

E (1895) DISPATCHER: exe first list: 0x0
I (1896) DISPATCHER: dispatcher_event_task is running...
I (1899) AUDIO_THREAD: The wifi_serv task allocate stack on external memory
I (1905) wifi:wifi driver task: 3ffce72c, prio:23, stack:6656, core=0
I (1909) system_api: Base MAC address is not set
I (1914) system_api: read default base MAC address from EFUSE
I (1934) wifi:wifi firmware version: 63017e0
I (1934) wifi:wifi certification version: v7.0
I (1934) wifi:config NVS flash: enabled
I (1935) wifi:config nano formating: disabled
I (1939) wifi:Init data frame dynamic rx buffer num: 32
I (1944) wifi:Init management frame dynamic rx buffer num: 32
I (1949) wifi:Init management short buffer num: 32
I (1954) wifi:Init static tx buffer num: 16
I (1958) wifi:Init tx cache buffer num: 32
I (1962) wifi:Init static rx buffer size: 1600
I (1966) wifi:Init static rx buffer num: 16
I (1970) wifi:Init dynamic rx buffer num: 32
I (1975) wifi_init: rx ba win: 16
I (1978) wifi_init: tcpip mbox: 32
I (1982) wifi_init: udp mbox: 6
I (1985) wifi_init: tcp mbox: 6
I (1989) wifi_init: tcp tx win: 5744
I (1993) wifi_init: tcp rx win: 5744
I (1998) wifi_init: tcp mss: 1440
I (2002) wifi_init: WiFi/LWIP prefer SPIRAM
I (2007) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (2099) wifi:mode : sta (34:94:54:4c:1c:5c)
I (2099) wifi:enable tsf
I (1613,tid:3ffdebb8) lightduer_session.c(  44):random = 75933
W (2907) AUDIO_BOARD: The board has already been initialized!
I (2907) AUDIO_THREAD: The media_task task allocate stack on external memory
I (2911) WIFI_SERV: Connect to wifi ssid: Lanistor, pwd: 6688##**
I (2918) ESP_AUDIO_TASK: media_ctrl_task running...,0x3f81a6ec

----------------------------- ESP Audio Platform -----------------------------
|                                                                            |
|                 ESP_AUDIO-v1.7.0-63-g2b9ee8e-bec4a56-4d51bc8               |
|                     Compile date: Feb 23 2022-02:43:28                     |
------------------------------------------------------------------------------
I (2958) ESP_AUDIO_CTRL: Func:media_ctrl_create, Line:350, MEM Total:4209135 Bytes, Inter:185739 Bytes, Dram:151719 Bytes

I (2970) AUDIO_HAL: Codec mode is 3, Ctrl:1
I (2982) MP3_DECODER: MP3 init
I (2984) I2S: APLL expected frequency is 24576000 Hz, real frequency is 24575996 Hz
I (2987) I2S: DMA Malloc info, datalen=blocksize=1200, dma_buf_count=3
I (2994) I2S: DMA Malloc info, datalen=blocksize=1200, dma_buf_count=3
I (3002) I2S: I2S0, MCLK output by GPIO0
I (3006) LYRAT_MINI_V1_1: I2S0, MCLK output by GPIO0
I (3012) AUDIO_WRAPPER: Func:duer_audio_setup_player, Line:184, MEM Total:4199851 Bytes, Inter:170239 Bytes, Dram:136219 Bytes

I (3024) AUDIO_WRAPPER: esp_audio instance is:0x3f81a6ec
I (3031) I2S: DMA Malloc info, datalen=blocksize=1200, dma_buf_count=3
I (3037) I2S: DMA Malloc info, datalen=blocksize=1200, dma_buf_count=3
I (3045) I2S: I2S1, MCLK output by GPIO0
I (3049) LYRAT_MINI_V1_1: I2S1, MCLK output by GPIO0
I (3055) AUDIO_PIPELINE: link el->rb, el:0x3f81ca98, tag:i2s, rb:0x3f81cd24
I (3063) AUDIO_ELEMENT: [i2s-0x3f81ca98] Element task created
I (3069) AUDIO_ELEMENT: [raw-0x3f81cbc8] Element task created
I (3075) AUDIO_PIPELINE: Func:audio_pipeline_run, Line:359, MEM Total:4186927 Bytes, Inter:157079 Bytes, Dram:123059 Bytes

I (3087) AUDIO_ELEMENT: [i2s] AEL_MSG_CMD_RESUME,state:1
I (3093) AUDIO_PIPELINE: Pipeline started
I (3098) AUDIO_WRAPPER: Recorder has been created
Deprecated Quantized wakeNet5: wakeNet5_v1_hilexin_5_0.95_0.90, mode:0 (Dec 10 2021 20:15:15)
3
Initial ONE-MIC auido front-end for speech recognition, mode:1, (Dec 10 2021 20:29:24)
W (3124) RECORDER_SR: Multinet is not enabled in SDKCONFIG
I (3128) AUDIO_THREAD: The feed_task task allocate stack on external memory
I (3136) AUDIO_THREAD: The fetch_task task allocate stack on external memory
I (3144) AUDIO_THREAD: The recorder_task task allocate stack on external memory
I (3152) AUDIO_THREAD: The voice_read_task task allocate stack on external memory
I (4013) wifi:new:<10,0>, old:<1,0>, ap:<255,255>, sta:<10,0>, prof:1
I (4772) wifi:state: init -> auth (b0)
I (4815) wifi:state: auth -> assoc (0)
I (4855) wifi:state: assoc -> run (10)
I (5008) wifi:connected with Lanistor, aid = 7, channel 10, BW20, bssid = 50:64:2b:0a:fc:e1
I (5009) wifi:security: WPA2-PSK, phy: bgn, rssi: -65
I (5011) wifi:pm start, type: 1

W (5017) WIFI_SERV: WiFi Event cb, Unhandle event_base:WIFI_EVENT, event_id:4
W (5072) wifi:<ba-add>idx:0 (ifx:0, 50:64:2b:0a:fc:e1), tid:0, ssn:2, winSize:64
I (5096) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (6329) esp_netif_handlers: sta ip: 192.168.31.141, mask: 255.255.255.0, gw: 192.168.31.1
I (6330) WIFI_SERV: Got ip:192.168.31.141
W (6333) WIFI_SERV: STATE type:2, pdata:0x0, len:0
I (6352) DUEROS: PERIPH_WIFI_CONNECTED [145]
E (6352) DUEROS: Recv Que DUER_CMD_LOGIN
I (6353) DUEROS: duer_start, len:1469
{"configures":"{}","bindToken":"xxx","coapPort":443,"token":"xxx","serverAddr":"device.iot.baidu.com","lwm2mPort":443,"uuid":"2208000000000a","rsaCaCrt":"-----BEGIN CERTIFICATE-----\nxxxxxx\n-----END CERTIFICATE-----\n","macId":"","version":15584}��?T
W (6483) DUEROS: duer_callback: type:0, source:0x3f80a434 data:2, data_len:0
I (5201,tid:3ffdebb8) lightduer_engine.c( 242):duer_engine_start, g_handler:3F81A5D4, length:1469, profile:3F83AC24
I (5219,tid:3ffdebb8) lightduer_ca_conf.c(  38):    duer_conf_get_string: uuid = 2208000000000a
I (5226,tid:3ffdebb8) lightduer_ca_conf.c(  38):    duer_conf_get_string: serverAddr = device.iot.baidu.com
I (5272,tid:3ffdebb8) baidu_ca_socket_adp.c( 139):DNS lookup succeeded. IP=110.242.69.142
I (5293,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
W (5294,tid:3ffdebb8) lightduer_events.c(  81):[lightduer_ca] <== event end = 40128B58, timespent = 94
I (6080,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
W (6080,tid:3ffdebb8) lightduer_events.c(  81):[lightduer_ca] <== event end = 40128D18, timespent = 740
I (6088,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WULD_BLOCK)
I (6096,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
I (6106,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
I (6124,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
I (6124,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
I (6132,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
I (6139,tid:3ffdebb8) lightduer_engine.c( 242):duer_engine_start, g_handler:3F81A5D4, length:0, profile:00000000
I (6151,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
I (6162,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
I (6167,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
I (6176,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
I (6184,tid:3ffdebb8) lightduer_connagent.c( 208):will start latter(DUER_ERR_TRANS_WOULD_BLOCK)
I (6894,tid:3ffdebb8) lightduer_voice.c( 915):Mutex initializing
I (6894,tid:3ffdebb8) lightduer_connagent.c( 189):connect started!
I (6895,tid:3ffdebb8) lightduer_ds_log_cache.c(  85):no cache report
E (8183) DUEROS: event: 0
I (8187) DUEROS: duer_dcs_init
I (6911,tid:3ffdebb8) lightduer_dcs_router.c( 306):namespace: ai.dueros.private.protocol
I (6916,tid:ffdebb8) lightduer_dcs_router.c( 306):namespace: ai.dueros.device_interface.screen_extended_card
I (6925,tid:3ffdebb8) lightduer_dcs_router.c( 306):namespace: ai.dueros.device_interface.screen
I (6934,tid:3ffdebb8) lightduer_dcs_router.c( 306):namespace: ai.dueros.device_interface.system
I (6942,tid:3ffdebb8) lightduer_dcs_router.c( 306):namespace: ai.dueros.device_interface.voice_input
I (6951,tid:3ffdebb8) lightduer_dcs_router.c( 306):namespace: ai.dueros.device_interface.voice_output
I (6961,tid:3ffdebb8) lightduer_dcs_router.c( 306):namespace: ai.dueros.device_interface.speaker_controller
I (6970,tid:3ffdebb8) lightduer_dcs_router.c( 306):namespace: ai.dueros.device_interface.audio_player
I (8261) AUDIO_WRAPPER: duer_dcs_get_speaker_state
E (8269) DUEROS: event: DUER_EVENT_STARTED
W (6988,tid:3ffdebb8) lightduer_events.c(  81):[lightduer_ca] <== event end = 40128D18, timespent = 99
I (6997,tid:3ffdebb8) lightduer_connagent.c( 222):add resource successfully!!
I (7005,tid:3ffdebb8) lightduer_connagent.c( 222):add resource successfully!!
I (8269) DUEROS: Dueros DUER_CMD_CONNECTED, duer_state:20m
W (7011,tid:3ffdebb8) lightduer_engine.c( 697):data cache has not sent, pending..., dcache_len:2, qcache_len:3
W (8300) DUEROS: duer_callback: type:0, source:0x3f80a434 data:3, data_len:0
W (7030,tid:3ffdebb8) lightduer_system_info.c( 306):Undefined memory type, 0
E (7042,tid:3ffdebb8) lightduer_system_info.c( 389):Sys Info: Get disk info failed
W (7059,tid:3ffdebb8) lightduer_engine.c( 697):data cache has not sent, pending..., dcache_len:2, qcache_len:4
W (7070,tid:3ffdebb8) lightduer_engine.c( 697):data cache has not sent, pending..., dcache_len:2, qcache_len:3
W (7080,tid:3ffdebb8) lightduer_engine.c( 697):data cache has not sent, pending..., dcache_len:2, qcache_len:2
W (7089,tid:3ffdebb8) lightduer_engine.c( 697):data cache has not sent, pending..., dcache_len:2, qcache_len:1
I (7894,tid:3ffdebb8) lightduer_dcs_router.c( 460):Directive name: ThrowException
E (7894,tid:3ffdebb8) lightduer_dcs_system.c( 314):error code: INVALID_REQUEST_EXCEPTION
E (7898,tid:3ffdebb8) lightduer_dcs_system.c( 315):error: didp product not exsists
I (7910,tid:3ffdebb8) lightduer_dcs_router.c( 460):Directive name: ThrowException
E (7914,tid:3ffdebb8) lightduer_dcs_system.c( 314):error code: INVALID_REQUEST_EXCEPTION
E (7921,tid:3ffdebb8) lightduer_dcs_system.c( 315):error: didp product not exsists
I (7935,tid:3ffdebb8) lightduer_dcs_router.c( 460):Directive name: DialogueFinished
W (7938,tid:3ffdebb8) lightduer_engine.c( 697):data cache has not sent, pending..., dcache_len:1, qcache_len:2
I (7955,tid:3ffdebb8) lightduer_dcs_router.c( 460):Directive name: DialogueFinished
W (7961,tid:3ffdebb8) lightduer_engine.c( 697):data cache has not sent, pending..., dcache_len:2, qcache_len:2
W (7975,tid:3ffdebb8) lightduer_engine.c( 697):data cache has not sent, pending..., dcache_len:2, qcache_len:1
W (33676) AUDIO_EVT: There is no space in external queue
W (36667) AUDIO_EVT: There is no space in external queue
W (38071) AUDIO_EVT: There is no space in external queue
W (43347) AUDIO_EVT: There is no space in external queue
I (43468) DUEROS: AUDIO_USER_KEY_VOL_UP [69]
W (43468) AUDIO_EVT: There is no space in external queue
W (47016) AUDIO_EVT: There is no space in external queue
W (48699) AUDIO_EVT: There is no space in external queue

lanistor avatar May 12 '22 17:05 lanistor

Hi @lanistor

W (48699) AUDIO_EVT: There is no space in external queue

esp_err_t audio_event_iface_sendout(audio_event_iface_handle_t evt, audio_event_iface_msg_t *msg)
{
    if (evt->external_queue) {
        if (xQueueSend(evt->external_queue, (void *)msg, 0) != pdPASS) {
            ESP_LOGW(TAG, "There is no space in external queue");
            return ESP_FAIL;
        }
    }
    return ESP_OK;
}

https://github.com/espressif/esp-adf/blob/master/components/audio_pipeline/audio_event_iface.c#L273

This means that your event receiving queue is full, you can see here AUDIO_EVENT_IFACE_DEFAULT_CFG. Even if you set it bigger, it will be stuffed again. The most important thing is to clear the event receiving queue.

HengYongChao avatar May 16 '22 03:05 HengYongChao

Happened to me when setup of the listener was missing. I had to add

audio_event_iface_set_listener(esp_periph_set_get_event_iface(set), evt);

ayavilevich avatar Dec 30 '22 08:12 ayavilevich

This topic has become inactive so I'm going to close the issue. Please reopen this if you have any questions or need any further assistance.

jason-mao avatar Sep 05 '23 08:09 jason-mao