Service sounds are played poorly in the voip project (AUD-5369)

[Olejan]

Environment

• Audio development kit: [ESP32-LyraT-Mini_v1.2]
• Audio kit version (for ESP32-LyraT-Mini): [v1]
• [Required] Module or chip used: [ESP32-WROVER-E]
• [Required] IDF version: [v4.4.4-278-g3c8bc2213c]
• [Required] ADF version: [v2.6-108-g1f275b50]
• Build system: [idf.py]
• [Required] Running log: All logs from power-on to problem recurrence
• Compiler version: [xtensa-esp32-elf-gcc (crosstool-NG esp-2021r2-patch5) 8.4.0]
• Operating system: [Windows]
• (Windows only) Environment type: [ESP Command Prompt (cmd)]
• Using an IDE?: [No]
• Power supply: [USB]

Problem Description

I'm using the voip project. A very good project, but there is an incomprehensible point - service audio signals (Alarm.mp3, WiFi_Success.mp3, ...), when played by the device, have very poor quality. It seems that the task of playing an audio file is very often interrupted by other tasks, and the sound in a speaker is very intermittent, almost indistinguishable. At the same time, I can normally call from a device to a SIP phone, or from a phone to a device, and the sound in the speaker will be very good. I suspect I need to configure the amount of memory allocated for the task of playing service signals, but I don’t know where this can be done.

Please tell me how to make the service signals sound good?

Video

Debug Logs

d:\voip>idf.py monitor
Executing action: monitor
Serial port COM49
Connecting....
Detecting chip type... Unsupported detection protocol, switching and trying again...
Connecting....
Detecting chip type... ESP32
Running idf_monitor in directory D:\voip
Executing "C:\Users\User\.espressif\python_env\idf4.4_py3.11_env\Scripts\python.exe C:\Users\User\esp\esp-adf\esp-idf\tools/idf_monitor.py -p COM49 -b 115200 --toolchain-prefix xtensa-esp32-elf- --target esp32 --revision 0 D:\voip\build\voip_app.elf -m 'C:\Users\User\.espressif\python_env\idf4.4_py3.11_env\Scripts\python.exe' 'C:\Users\User\esp\esp-adf\esp-idf\tools\idf.py'"...
--- WARNING: GDB cannot open serial ports accessed as COMx
--- Using \\.\COM49 instead...
--- idf_monitor on \\.\COM49 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ets Jul 29 2019 12:21:46

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:1
load:0x3fff0030,len:6976
load:0x40078000,len:15780
ho 0 tail 12 room 4
load:0x40080400,len:4516
0x40080400: _init at ??:?

entry 0x400806b8
I (29) boot: ESP-IDF v4.4.4-278-g3c8bc2213c-dirty 2nd stage bootloader
I (29) boot: compile time 16:51:05
I (30) boot: chip revision: v3.1
I (34) qio_mode: Enabling default flash chip QIO
I (39) boot.esp32: SPI Speed      : 80MHz
I (44) boot.esp32: SPI Mode       : QIO
I (49) boot.esp32: SPI Flash Size : 4MB
I (53) boot: Enabling RNG early entropy source...
I (59) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (77) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (84) boot:  2 factory          factory app      00 00 00010000 00200000
I (92) boot:  3 flash_tone       Unknown data     01 ff 00210000 0007d000
I (99) boot: End of partition table
I (103) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=35770h (218992) map
I (172) esp_image: segment 1: paddr=00045798 vaddr=3ffb0000 size=03390h ( 13200) load
I (177) esp_image: segment 2: paddr=00048b30 vaddr=40080000 size=074e8h ( 29928) load
I (188) esp_image: segment 3: paddr=00050020 vaddr=400d0020 size=ef008h (978952) map
I (458) esp_image: segment 4: paddr=0013f030 vaddr=400874e8 size=0f06ch ( 61548) load
I (489) boot: Loaded app from partition at offset 0x10000
I (489) boot: Disabling RNG early entropy source...
I (500) psram: This chip is ESP32-D0WD
I (501) spiram: Found 64MBit SPI RAM device
I (501) spiram: SPI RAM mode: flash 80m sram 80m
I (504) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (511) cpu_start: Pro cpu up.
I (515) cpu_start: Starting app cpu, entry point is 0x4008151c
0x4008151c: call_start_cpu1 at C:/Users/User/esp/esp-adf/esp-idf/components/esp_system/port/cpu_start.c:148

I (0) cpu_start: App cpu up.
I (1017) spiram: SPI SRAM memory test OK
I (1025) cpu_start: Pro cpu start user code
I (1025) cpu_start: cpu freq: 240000000
I (1025) cpu_start: Application information:
I (1028) cpu_start: Project name:     voip_app
I (1034) cpu_start: App version:      1
I (1038) cpu_start: Compile time:     Apr 23 2024 16:50:48
I (1044) cpu_start: ELF file SHA256:  71fde48e46c124df...
I (1050) cpu_start: ESP-IDF:          v4.4.4-278-g3c8bc2213c-dirty
I (1057) cpu_start: Min chip rev:     v0.0
I (1062) cpu_start: Max chip rev:     v3.99
I (1067) cpu_start: Chip rev:         v3.1
I (1072) heap_init: Initializing. RAM available for dynamic allocation:
I (1079) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (1085) heap_init: At 3FFB50D8 len 0002AF28 (171 KiB): DRAM
I (1091) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1098) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1104) heap_init: At 40096554 len 00009AAC (38 KiB): IRAM
I (1111) spiram: Adding pool of 4084K of external SPI memory to heap allocator
I (1119) spi_flash: detected chip: gd
I (1123) spi_flash: flash io: qio
W (1127) spi_flash: Detected size(8192k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1141) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1156) spiram: Reserving pool of 18K of internal memory for DMA/internal allocations
I (1164) VoIP_EXAMPLE: Func:app_main, Line:152, MEM Total:4448455 Bytes, Inter:324991 Bytes, Dram:286199 Bytes

I (1207) VoIP_EXAMPLE: [1.0] Initialize peripherals management
I (1207) VoIP_EXAMPLE: [1.1] Initialize and start peripherals
I (1210) AUDIO_THREAD: The button_task task allocate stack on internal memory
I (1216) AUDIO_THREAD: The esp_periph task allocate stack on internal memory
I (1224) VoIP_EXAMPLE: [1.2] Create and start input key service
I (1231) AUDIO_THREAD: The input_key_service task allocate stack on external memory
I (1239) VoIP_EXAMPLE: [ 2 ] Initialize av stream
I (1245) I2S: DMA Malloc info, datalen=blocksize=128, dma_buf_count=8
I (1252) I2S: DMA Malloc info, datalen=blocksize=128, dma_buf_count=8
I (1259) I2S: I2S0, MCLK output by GPIO0
I (1269) DRV8311: ES8311 in Slave mode
I (1282) gpio: GPIO[21]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
W (1327) I2C_BUS: I2C bus has been already created, [port:0]
I (1331) I2S: DMA Malloc info, datalen=blocksize=256, dma_buf_count=8
I (1331) I2S: DMA Malloc info, datalen=blocksize=256, dma_buf_count=8
I (1336) I2S: I2S1, MCLK output by GPIO0
I (1341) AUDIO_HAL: Codec mode is 3, Ctrl:1
I (1353) VoIP_EXAMPLE: [ 3 ] Initialize tone player
I (1354) AUDIO_THREAD: The media_task task allocate stack on external memory
I (1359) ESP_AUDIO_TASK: media_ctrl_task running...,0x3f804c34

----------------------------- ESP Audio Platform -----------------------------
|                                                                            |
|                 ESP_AUDIO-v1.7.3-40-g00ffda8-dbab925-9815982               |
|                     Compile date: Apr 12 2024-02:32:01                     |
------------------------------------------------------------------------------
I (1400) ESP_AUDIO_CTRL: Func:media_ctrl_create, Line:355, MEM Total:4419803 Bytes, Inter:299135 Bytes, Dram:260343 Bytes

I (1413) MP3_DECODER: MP3 init
E (1416) I2S: register I2S object to platform failed
I (1422) I2S: I2S0, MCLK output by GPIO0
I (1426) VoIP_EXAMPLE: [ 4 ] Create Wi-Fi service instance
E (1433) DISPATCHER: exe first list: 0x0
I (1437) DISPATCHER: dispatcher_event_task is running...
I (1443) AUDIO_THREAD: The esp_dispatcher task allocate stack on internal memory
I (1455) AUDIO_THREAD: The wifi_serv task allocate stack on external memory
I (1462) wifi:wifi driver task: 3ffc7890, prio:23, stack:6656, core=0
I (1465) system_api: Base MAC address is not set
I (1470) system_api: read default base MAC address from EFUSE
I (1492) wifi:wifi firmware version: bd1de02
I (1493) wifi:wifi certification version: v7.0
I (1493) wifi:config NVS flash: enabled
I (1493) wifi:config nano formating: disabled
I (1497) wifi:Init data frame dynamic rx buffer num: 128
I (1502) wifi:Init management frame dynamic rx buffer num: 128
I (1508) wifi:Init management short buffer num: 32
I (1513) wifi:Init static tx buffer num: 9
I (1517) wifi:Init tx cache buffer num: 32
I (1520) wifi:Init static rx buffer size: 1600
I (1524) wifi:Init static rx buffer num: 9
I (1528) wifi:Init dynamic rx buffer num: 128
I (1533) wifi_init: rx ba win: 16
I (1536) wifi_init: tcpip mbox: 64
I (1540) wifi_init: udp mbox: 64
I (1544) wifi_init: tcp mbox: 64
I (1548) wifi_init: tcp tx win: 65535
I (1552) wifi_init: tcp rx win: 65535
I (1557) wifi_init: tcp mss: 1440
I (1561) wifi_init: WiFi/LWIP prefer SPIRAM
I (1566) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1656) wifi:mode : sta (a0:a3:b3:8b:47:f8)
I (1657) wifi:enable tsf
I (1666) WIFI_SERV: Connect to wifi ssid: WiFi, pwd: pwd
I (2663) AUDIO_SYS: | Task              | Run Time    | Per | Prio | HWM       | State   | CoreId   | Stack
I (2663) AUDIO_SYS: | main              | 1856        | 0%  | 1    | 1504      | Running | 0        | Intr
I (2673) AUDIO_SYS: | IDLE              | 1183139     |49%  | 0    | 912       | Ready   | 1        | Intr
I (2683) AUDIO_SYS: | IDLE              | 955970      |39%  | 0    | 972       | Ready   | 0        | Intr
I (2694) AUDIO_SYS: | esp_periph        | 3436        | 0%  | 5    | 2184      | Blocked | 0        | Intr
I (2704) AUDIO_SYS: | button_task       | 26191       | 1%  | 10   | 1664      | Blocked | 0        | Intr
I (2714) AUDIO_SYS: | tiT               | 911         | 0%  | 18   | 2932      | Blocked | 7fffffff | Intr
I (2725) AUDIO_SYS: | esp_dispatcher    | 41749       | 1%  | 10   | 2312      | Blocked | 0        | Intr
I (2735) AUDIO_SYS: | Tmr Svc           | 0           | 0%  | 1    | 1460      | Blocked | 0        | Intr
I (2745) AUDIO_SYS: | ipc0              | 0           | 0%  | 1    | 948       | Blocked | 0        | Intr
I (2756) AUDIO_SYS: | input_key_servi   | 0           | 0%  | 5    | 3448      | Blocked | 1        | Extr
I (2766) AUDIO_SYS: | media_task        | 0           | 0%  | 6    | 2084      | Blocked | 0        | Extr
I (2776) AUDIO_SYS: | ipc1              | 18509       | 0%  | 24   | 968       | Blocked | 1        | Intr
I (2787) AUDIO_SYS: | sys_evt           | 382         | 0%  | 20   | 2940      | Blocked | 0        | Intr
I (2797) AUDIO_SYS: | wifi              | 169438      | 7%  | 23   | 6020      | Blocked | 0        | Intr
I (2807) AUDIO_SYS: | wifi_serv         | 1045        | 0%  | 6    | 2156      | Blocked | 0        | Extr
I (2818) AUDIO_SYS: | esp_timer         | 823         | 0%  | 22   | 3556      | Suspended | 0        | Intr

I (2828) VoIP_EXAMPLE: Func:app_main, Line:212, MEM Total:4303251 Bytes, Inter:245479 Bytes, Dram:206687 Bytes

I (2879) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (3669) wifi:state: init -> auth (b0)
I (3673) wifi:state: auth -> assoc (0)
I (3686) wifi:state: assoc -> run (10)
I (3714) wifi:connected with WiFi, aid = 7, channel 11, BW20, bssid = 18:e8:29:fb:d6:9f
I (3715) wifi:security: WPA2-PSK, phy: bgn, rssi: -58
I (3716) wifi:pm start, type: 1

W (3721) WIFI_SERV: WiFi Event cb, Unhandle event_base:WIFI_EVENT, event_id:4
I (3735) wifi:<ba-add>idx:0 (ifx:0, 18:e8:29:fb:d6:9f), tid:0, ssn:0, winSize:64
I (3785) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (4721) esp_netif_handlers: sta ip: 172.**.**.72, mask: 255.255.255.0, gw: 172.**.**.1
I (4722) WIFI_SERV: Got ip:172.**.**.72
W (4724) WIFI_SERV: STATE type:2, pdata:0x0, len:0
I (4782) VoIP_EXAMPLE: PERIPH_WIFI_CONNECTED [107]
I (4782) VoIP_EXAMPLE: [ 5 ] Create SIP Service
I (4783) ESP_RTC_CORE: esp_rtc ver: 1.1.0 compile date: Feb  5 2024-12:23:15
I (4791) SIP: Conecting...
W (4794) SIP: CHANGE STATE FROM 0, TO 1, :func: sip_connect:1835
I (4800) SIP: [1970-01-01/00:00:01]=======WRITE 0592 bytes>>
I (4806) SIP:

REGISTER sip:172.**.**.35:5060 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.72:16591;branch=z9hG4bK--1155181663;rport
From: <sip:1004@172.**.**.35:5060>;tag=-915015573
To: <sip:1004@172.**.**.35:5060>
Contact: <sip:1004@172.**.**.72:16591;transport=UDP>
Max-Forwards: 70
Call-ID: DCC7310983EA2F4E87EB5A3BA0AAA0F3A2522E01F08A
CSeq: 1 REGISTER
Expires: 3600
User-Agent: ESP32 SIP/2.0
Content-Length: 0
Allow: INVITE, ACK, CANCEL, BYE, UPDATE, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri
Allow-Events: presence, kpml

I (4862) SIP: [1970-01-01/00:00:01]=======================>>
I (4793) ESP_RTC_CORE: esp_rtc_init done
I (4890) SIP: [1970-01-01/00:00:01]<<=====READ 0511 bytes==
I (4891) SIP:

SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 172.**.**.72:16591;rport=16591;received=172.**.**.72;branch=z9hG4bK--1155181663
Call-ID: DCC7310983EA2F4E87EB5A3BA0AAA0F3A2522E01F08A
From: <sip:1004@172.**.**.35>;tag=-915015573
To: <sip:1004@172.**.**.35>;tag=z9hG4bK--1155181663
CSeq: 1 REGISTER
WWW-Authenticate: Digest realm="grandstream",nonce="1713882630/3ef2fed1c45ddb3e730138744eda2372",opaque="25a80eac3b5c511e",algorithm=md5,qop="auth"
Server: Grandstream UCM6202V1.4A 1.0.17.16
Content-Length:  0

I (4934) SIP: [1970-01-01/00:00:01]<<======================
I (4941) SIP: Required authentication
I (4946) SIP: [1970-01-01/00:00:01]=======WRITE 0872 bytes>>
I (4951) SIP:

REGISTER sip:172.**.**.35:5060 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.72:16591;branch=z9hG4bK--1906668690;rport
From: <sip:1004@172.**.**.35:5060>;tag=-1390059461
To: <sip:1004@172.**.**.35:5060>
Contact: <sip:1004@172.**.**.72:16591;transport=UDP>
Max-Forwards: 70
Call-ID: DCC7310983EA2F4E87EB5A3BA0AAA0F3A2522E01F08A
CSeq: 2 REGISTER
Expires: 3600
User-Agent: ESP32 SIP/2.0
Content-Length: 0
Allow: INVITE, ACK, CANCEL, BYE, UPDATE, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri
Allow-Events: presence, kpml
Authorization: Digest username="1004", realm="grandstream", nonce="1713882630/3ef2fed1c45ddb3e730138744eda2372", uri="sip:172.**.**.35:5060", response="bbc8ea8510f8c669cd6259ee00c3c4de", algorithm=md5, qop=auth, nc=00000001, cnonce="36c38a7e9412e007", opaque="25a80eac3b5c511e"

I (5031) SIP: [1970-01-01/00:00:02]=======================>>
I (5070) SIP: [1970-01-01/00:00:02]<<=====READ 0458 bytes==
I (5070) SIP:

SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.**.**.72:16591;rport=16591;received=172.**.**.72;branch=z9hG4bK--1906668690
Call-ID: DCC7310983EA2F4E87EB5A3BA0AAA0F3A2522E01F08A
From: <sip:1004@172.**.**.35>;tag=-1390059461
To: <sip:1004@172.**.**.35>;tag=z9hG4bK--1906668690
CSeq: 2 REGISTER
Date: Tue, 23 Apr 2024 14:30:30 GMT
Contact: <sip:1004@172.**.**.72:16591>;expires=3599
Expires: 3600
Server: Grandstream UCM6202V1.4A 1.0.17.16
Content-Length:  0

I (5109) SIP: [1970-01-01/00:00:02]<<======================
I (5116) SIP: Expires = 3600
I (5119) SIP_SERVICE: ESP_RTC_EVENT_REGISTERED
I (5124) ESP_AUDIO_CTRL: Enter play procedure, src:0
I (5130) ESP_AUDIO_CTRL: Play procedure, URL is ok, src:0
I (5136) ESP_AUDIO_CTRL: Request_CMD_Queue CMD:0, Available:5, que:0x3ffc1f60
I (5144) ESP_AUDIO_CTRL: Func:_ctrl_play, Line:776, MEM Total:4278315 Bytes, Inter:244207 Bytes, Dram:205415 Bytes

I (5156) ESP_AUDIO_TASK: It's a decoder
I (5159) ESP_AUDIO_TASK: 1.CUR IN:[IN_flash],CODEC:[DEC_mp3],RESAMPLE:[8000],OUT:[OUT_iis],rate:0,ch:0,pos:0
I (5170) ESP_AUDIO_TASK: 2.Handles,IN:0x3f805ef4,CODEC:0x3f80608c,FILTER:0x3f81aa28,OUT:0x3f806240
I (5180) ESP_AUDIO_TASK: 2.2 Update all pipeline
I (5185) ESP_AUDIO_TASK: 2.3 Linked new pipeline
I (5191) AUDIO_PIPELINE: link el->rb, el:0x3f805ef4, tag:IN_flash, rb:0x3f81b4bc
I (5199) AUDIO_PIPELINE: link el->rb, el:0x3f80608c, tag:DEC_mp3, rb:0x3f81dd04
I (5208) AUDIO_PIPELINE: link el->rb, el:0x3f81aa28, tag:Audio_forge, rb:0x3f81fd4c
I (5215) ESP_AUDIO_TASK: 3. Previous starting...
I (5220) AUDIO_THREAD: The IN_flash task allocate stack on internal memory
I (5228) AUDIO_THREAD: The DEC_mp3 task allocate stack on external memory
I (5228) TONE_PARTITION: tone partition format 1, total 7
I (5235) MP3_DECODER: MP3 opened
I (5236) ESP_AUDIO_TASK: Blocking play until received AEL_MSG_CMD_REPORT_MUSIC_INFO
I (5245) TONE_STREAM: Tone offset:0001A92C, Tone length:21212, pos:5

I (5260) ESP_AUDIO_TASK: Recv Element[IN_flash-0x3f805ef4] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (5262) CODEC_ELEMENT_HELPER: The element isx3f80608c. The reserve data 2 is 0x0.
I (5283) ESP_AUDIO_TASK: Recv Element[DEC_mp3-0x3f80608c] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (5292) ESP_AUDIO_TASK: Received muisc info then on play
I (5297) ESP_AUDIO_TASK: On event play, status:UNKNOWN, 0
I (5304) AUDIO_THREAD: The Audio_forge task allocate stack on external memory
I (5312) AUDIO_FORGE: audio_forge opened
I (5312) AUDIO_THREAD: The OUT_iis task allocate stack on external memory
I (5324) I2S_STREAM: AUDIO_STREAM_WRITER
I (5328) ESP_AUDIO_TASK: Recv Element[OUT_iis-0x3f806240] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (5341) ESP_AUDIO_TASK: Recv Element[Audio_forge-0x3f81aa28] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (5341) AUDIO_FORGE: audio_forge reopen
I (5351) ESP_AUDIO_TASK: ESP_AUDIO status is AEL_STATUS_STATE_RUNNING, 0, src:0, is_stopping:0
I (5365) ESP_AUDIO_TASK: Func:media_ctrl_task, Line:1033, MEM Total:4169519 Bytes, Inter:237511 Bytes, Dram:198719 Bytes

I (5376) ESP_AUDIO_CTRL: Exit play procedure, ret:0
W (5382) SIP: CHANGE STATE FROM 1, TO 2, :func: sip_register:1863
I (5389) SIP: [1970-01-01/00:00:02]<<=====READ 0763 bytes==
I (5395) SIP:

NOTIFY sip:1004@172.**.**.72:16591 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPj78dd1bcd-bffc-4f38-8020-64f4ac3d29b9
From: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35>;tag=fba01752-8fa3-47c0-8e81-3e79593db3a1
To: <sip:1004@172.**.**.72>
Contact: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35:5060>
Call-ID: 293e023f-e513-4c90-beb2-38fc10c7c0de
CSeq: 15758 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: conference, presence, dialog, message-summary, line-seize, call-info, call-completion, refer
Max-Forwards: 70
User-Agent: Grandstream UCM6202V1.4A 1.0.17.16
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

I (5465) SIP: [1970-01-01/00:00:02]<<======================
W (5740) TONE_STREAM: No more data,ret:0 ,info.byte_pos:21212
I (5741) ESP_AUDIO_TASK: Recv Element[IN_flash-0x3f805ef4] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (6209) SIP: [1970-01-01/00:00:02]<<=====READ 0763 bytes==
I (6210) SIP:

NOTIFY sip:1004@172.**.**.72:16591 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPj78dd1bcd-bffc-4f38-8020-64f4ac3d29b9
From: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35>;tag=fba01752-8fa3-47c0-8e81-3e79593db3a1
To: <sip:1004@172.**.**.72>
Contact: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35:5060>
Call-ID: 293e023f-e513-4c90-beb2-38fc10c7c0de
CSeq: 15758 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: conference, presence, dialog, message-summary, line-seize, call-info, call-completion, refer
Max-Forwards: 70
User-Agent: Grandstream UCM6202V1.4A 1.0.17.16
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

I (6275) SIP: [1970-01-01/00:00:02]<<======================
I (7213) SIP: [1970-01-01/00:00:03]<<=====READ 0763 bytes==
I (7213) SIP:

NOTIFY sip:1004@172.**.**.72:16591 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPj78dd1bcd-bffc-4f38-8020-64f4ac3d29b9
From: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35>;tag=fba01752-8fa3-47c0-8e81-3e79593db3a1
To: <sip:1004@172.**.**.72>
Contact: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35:5060>
Call-ID: 293e023f-e513-4c90-beb2-38fc10c7c0de
CSeq: 15758 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: conference, presence, dialog, message-summary, line-seize, call-info, call-completion, refer
Max-Forwards: 70
User-Agent: Grandstream UCM6202V1.4A 1.0.17.16
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

I (7279) SIP: [1970-01-01/00:00:03]<<======================
I (7849) VoIP_EXAMPLE: [ * ] Volume set to 85 %
I (8129) VoIP_EXAMPLE: [ * ] Volume set to 95 %
I (8409) VoIP_EXAMPLE: [ * ] Volume set to 100 %
I (9215) SIP: [1970-01-01/00:00:04]<<=====READ 0763 bytes==
I (9216) SIP:

NOTIFY sip:1004@172.**.**.72:16591 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPj78dd1bcd-bffc-4f38-8020-64f4ac3d29b9
From: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35>;tag=fba01752-8fa3-47c0-8e81-3e79593db3a1
To: <sip:1004@172.**.**.72>
Contact: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35:5060>
Call-ID: 293e023f-e513-4c90-beb2-38fc10c7c0de
CSeq: 15758 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: conference, presence, dialog, message-summary, line-seize, call-info, call-completion, refer
Max-Forwards: 70
User-Agent: Grandstream UCM6202V1.4A 1.0.17.16
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

I (9282) SIP: [1970-01-01/00:00:04]<<======================
I (11809) MP3_DECODER: Closed
I (11810) ESP_AUDIO_TASK: Received last pos: 21212 bytes
I (11810) ESP_AUDIO_TASK: Recv Element[DEC_mp3-0x3f80608c] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (12591) SIP: [1970-01-01/00:00:05]<<=====READ 0763 bytes==
I (12592) SIP:

NOTIFY sip:1004@172.**.**.72:16591 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPj78dd1bcd-bffc-4f38-8020-64f4ac3d29b9
From: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35>;tag=fba01752-8fa3-47c0-8e81-3e79593db3a1
To: <sip:1004@172.**.**.72>
Contact: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35:5060>
Call-ID: 293e023f-e513-4c90-beb2-38fc10c7c0de
CSeq: 15758 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: conference, presence, dialog, message-summary, line-seize, call-info, call-completion, refer
Max-Forwards: 70
User-Agent: Grandstream UCM6202V1.4A 1.0.17.16
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

I (12657) SIP: [1970-01-01/00:00:05]<<======================
I (12935) AUDIO_FORGE: audio forge closed
I (12936) ESP_AUDIO_TASK: Recv Element[Audio_forge-0x3f81aa28] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (14022) ESP_AUDIO_TASK: Received last time: 8064 ms
I (14023) ESP_AUDIO_TASK: Recv Element[OUT_iis-0x3f806240] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (14029) ESP_AUDIO_TASK: ESP_AUDIO status is AEL_STATUS_STATE_FINISHED, 0, src:0, is_stopping:0
I (14038) ESP_AUDIO_TASK: Func:media_ctrl_task, Line:1033, MEM Total:4220827 Bytes, Inter:238079 Bytes, Dram:199287 Bytes

W (14050) ESP_AUDIO_TASK: Destroy the old pipeline, FINISHED
W (14057) ESP_AUDIO_TASK: The old pipeline destroyed, FINISHED
I (16681) SIP: [1970-01-01/00:00:07]<<=====READ 0763 bytes==
I (16682) SIP:

NOTIFY sip:1004@172.**.**.72:16591 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPj78dd1bcd-bffc-4f38-8020-64f4ac3d29b9
From: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35>;tag=fba01752-8fa3-47c0-8e81-3e79593db3a1
To: <sip:1004@172.**.**.72>
Contact: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35:5060>
Call-ID: 293e023f-e513-4c90-beb2-38fc10c7c0de
CSeq: 15758 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: conference, presence, dialog, message-summary, line-seize, call-info, call-completion, refer
Max-Forwards: 70
User-Agent: Grandstream UCM6202V1.4A 1.0.17.16
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

I (16748) SIP: [1970-01-01/00:00:07]<<======================
I (18830) SIP: [1970-01-01/00:00:08]<<=====READ 1072 bytes==
I (18831) SIP:

INVITE sip:1004@172.**.**.72:16591 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPjd50ea539-63e5-4b83-823a-2d31d7a6bdad
From: "user pc" <sip:1002@172.**.**.35>;tag=152ff603-ed9e-42fd-a6ae-47af248c056a
To: <sip:1004@172.**.**.72>
Contact: "user pc" <sip:1002@172.**.**.35:5060>
Call-ID: 65568be2-eecd-44a2-a955-f5b8517e5c3f
CSeq: 20645 INVITE
Allow: OPTIONS, INFO, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER, MESSAGE, REGISTER
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800
Min-SE: 90
Max-Forwards: 70
User-Agent: Grandstream UCM6202V1.4A 1.0.17.16
Content-Type: application/sdp
Content-Length:   386

v=0
o=- 1292413717 1292413717 IN IP4 172.**.**.35
s=Asterisk
c=IN IP4 172.**.**.35
t=0 0
m=audio 13012 RTP/AVP 8 0 3 9 18 2 97 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:9 G722/8000
a=rtpmap:18 G729/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:97 iLBC/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:30
a=sendrecv

I (18925) SIP: [1970-01-01/00:00:08]<<======================
I (18933) SIP: Remote ARTP port=13012
I (18936) SIP: Remote RTP addr=172.**.**.35
I (18941) SIP: call from 1002
I (18945) SIP: [1970-01-01/00:00:08]=======WRITE 0461 bytes>>
I (18951) SIP:

SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPjd50ea539-63e5-4b83-823a-2d31d7a6bdad
Contact: <sip:1004@172.**.**.72:16591;transport=UDP>
From: "user pc" <sip:1002@172.**.**.35>;tag=152ff603-ed9e-42fd-a6ae-47af248c056a
To: <sip:1004@172.**.**.72>;tag=-175245078
Call-ID: 65568be2-eecd-44a2-a955-f5b8517e5c3f
CSeq: 20645 INVITE
Server: ESP32 SIP/2.0
Allow: ACK, INVITE, BYE, UPDATE, CANCEL, OPTIONS, INFO
Content-Length: 0

I (18995) SIP: [1970-01-01/00:00:08]=======================>>
I (19004) SIP: [1970-01-01/00:00:08]=======WRITE 0461 bytes>>
I (19008) SIP:

SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPjd50ea539-63e5-4b83-823a-2d31d7a6bdad
Contact: <sip:1004@172.**.**.72:16591;transport=UDP>
Contact: <sip:1004@172.**.**.72:16591;transport=UDP>
From: "user pc" <sip:1002@172.**.**.35>;tag=152ff603-ed9e-42fd-a6ae-47af248c056a
To: <sip:1004@172.**.**.72>;tag=888621502
Call-ID: 65568be2-eecd-44a2-a955-f5b8517e5c3f
CSeq: 20645 INVITE
Server: ESP32 SIP/2.0
Allow: ACK, INVITE, BYE, UPDATE, CANCEL, OPTIONS, INFO
Content-Length: 0

I (19052) SIP: [1970-01-01/00:00:09]=======================>>
W (19059) SIP: CHANGE STATE FROM 2, TO 16, :func: _sip_uas_process_req_invite:1003
I (19069) AUDIO_SYS: | Task              | Run Time    | Per | Prio | HWM       | State   | CoreId   | Stack
I (19077) AUDIO_SYS: | main              | 2053        | 0%  | 1    | 1504      | Running | 0        | Intr
I (19087) AUDIO_SYS: | IDLE              | 1227044     |49%  | 0    | 912       | Ready   | 1        | Intr
I (19098) AUDIO_SYS: | IDLE              | 942950      |38%  | 0    | 924       | Ready   | 0        | Intr
I (19108) AUDIO_SYS: | sip_task          | 231336      | 9%  | 20   | 8036      | Blocked | 0        | Extr
I (19118) AUDIO_SYS: | button_task       | 25693       | 1%  | 10   | 1568      | Blocked | 0        | Intr
I (19129) AUDIO_SYS: | tiT               | 1193        | 0%  | 18   | 2164      | Blocked | 7fffffff | Intr
I (19139) AUDIO_SYS: | esp_periph        | 3445        | 0%  | 5    | 2184      | Blocked | 0        | Intr
I (19150) AUDIO_SYS: | ipc1              | 0           | 0%  | 24   | 904       | Blocked | 1        | Intr
I (19160) AUDIO_SYS: | esp_dispatcher    | 0           | 0%  | 10   | 1592      | Blocked | 0        | Intr
I (19171) AUDIO_SYS: | wifi_serv         | 0           | 0%  | 6    | 748       | Blocked | 0        | Extr
I (19181) AUDIO_SYS: | ipc0              | 0           | 0%  | 24   | 948       | Blocked | 0        | Intr
I (19191) AUDIO_SYS: | input_key_servi   | 0           | 0%  | 5    | 2232      | Blocked | 1        | Extr
I (19202) AUDIO_SYS: | media_task        | 0           | 0%  | 6    | 1812      | Blocked | 0        | Extr
I (19212) AUDIO_SYS: | wifi              | 20940       | 0%  | 23   | 4036      | Blocked | 0        | Intr
I (19223) AUDIO_SYS: | esp_timer         | 1703        | 0%  | 22   | 3300      | Suspended | 0        | Intr
I (19233) AUDIO_SYS: | Tmr Svc           | 0           | 0%  | 1    | 1460      | Blocked | 0        | Intr
I (19244) AUDIO_SYS: | sys_evt           | 0           | 0%  | 20   | 1644      | Blocked | 0        | Intr

I (19254) VoIP_EXAMPLE: Func:app_main, Line:212, MEM Total:4249623 Bytes, Inter:242595 Bytes, Dram:203803 Bytes

I (20066) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (20066) ESP_AUDIO_CTRL: Enter play procedure, src:0
I (20066) ESP_AUDIO_CTRL: Play procedure, URL is ok, src:0
I (20072) ESP_AUDIO_CTRL: Request_CMD_Queue CMD:0, Available:5, que:0x3ffc1f60
I (20080) ESP_AUDIO_CTRL: Func:_ctrl_play, Line:776, MEM Total:4249607 Bytes, Inter:242595 Bytes, Dram:203803 Bytes

I (20092) ESP_AUDIO_TASK: It's a decoder
I (20096) ESP_AUDIO_TASK: 1.CUR IN:[IN_flash],CODEC:[DEC_mp3],RESAMPLE:[8000],OUT:[OUT_iis],rate:0,ch:0,pos:0
I (20107) ESP_AUDIO_TASK: 2.Handles,IN:0x3f805ef4,CODEC:0x3f80608c,FILTER:0x3f81aa28,OUT:0x3f806240
I (20117) AUDIO_PIPELINE: audio_pipeline_unlinked
W (20122) AUDIO_PIPELINE: There are no listener registered
I (20128) ESP_AUDIO_TASK: 2.2 Update all pipeline
I (20133) ESP_AUDIO_TASK: 2.3 Linked new pipeline
I (20139) AUDIO_PIPELINE: link el->rb, el:0x3f805ef4, tag:IN_flash, rb:0x3f81adc8
I (20147) AUDIO_PIPELINE: link el->rb, el:0x3f80608c, tag:DEC_mp3, rb:0x3f81b240
I (20155) AUDIO_PIPELINE: link el->rb, el:0x3f81aa28, tag:Audio_forge, rb:0x3f81b284
I (20164) ESP_AUDIO_TASK: 3. Previous starting...
I (20169) AUDIO_THREAD: The IN_flash task allocate stack on internal memory
I (20177) AUDIO_THREAD: The DEC_mp3 task allocate stack on external memory
I (20177) TONE_PARTITION: tone partition format 1, total 7
I (20184) MP3_DECODER: MP3pened
I (20184) ESP_AUDIO_TASK: Blocking play until received AEL_MSG_CMD_REPORT_MUSIC_INFO
I (20194) TONE_STREAM: Tone offset:000002C8, Tone length:26930, pos:0

I (20210) ESP_AUDIO_TASK: Recv Element[IN_flash-0x3f805ef4] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (20211) CODEC_ELEMENT_HELPER: The element is 0x3f80608c. The reserve data 2 is 0x0.
I (20232) ESP_AUDIO_TASK: Recv Element[DEC_mp3-0x3f80608c] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (20241) ESP_AUDIO_TASK: Received muisc info then on play
I (20247) ESP_AUDIO_TASK: On event play, status:UNKNOWN, 0
I (20253) AUDIO_THREAD: The Audio_forge task allocate stack on external memory
I (20262AUDIO_FORGE: audio_forge opened
I (20262) AUDIO_THREAD: The OUT_iis task allocate stack on external memory
I (20274) I2S_STREAM: AUDIO_STREAM_WRITER
I (20274) ESP_AUDIO_CTRL: Exit play procedure, ret:0
I (20284) ESP_AUDIO_TASK: Recv Element[OUT_iis-0x3f806240] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (20290) AUDIO_FORGE: audio_forge reopen
I (20295) ESP_AUDIO_TASK: Recv Element[Audio_forge-0x3f81aa28] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (20311) ESP_AUDIO_TASK: ESP_AUDIO status is AEL_STATUS_STATE_RUNNING, 0, src:0, is_stopping:0
I (20320) ESP_AUDIO_TASK: Func:media_ctrl_task, Line:1033, MEM Total:4170211 Bytes, Inter:237511 Bytes, Dram:198719 Bytes

I (20665) SIP: [1970-01-01/00:00:09]<<=====READ 0763 bytes==
I (20666) SIP:

NOTIFY sip:1004@172.**.**.72:16591 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPj78dd1bcd-bffc-4f38-8020-64f4ac3d29b9
From: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35>;tag=fba01752-8fa3-47c0-8e81-3e79593db3a1
To: <sip:1004@172.**.**.72>
Contact: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35:5060>
Call-ID: 293e023f-e513-4c90-beb2-38fc10c7c0de
CSeq: 15758 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: conference, presence, dialog, message-summary, line-seize, call-info, call-completion, refer
Max-Forwards: 70
User-Agent: Grandstream UCM6202V1.4A 1.0.17.16
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

I (20732) SIP: [1970-01-01/00:00:09]<<======================
I (20740) SIP: [1970-01-01/00:00:09]=======WRITE 0487 bytes>>
I (20744) SIP:

SIP/2.0 486 Busy Here
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPj78dd1bcd-bffc-4f38-8020-64f4ac3d29b9
Contact: <sip:1004@172.**.**.72:16591;transport=UDP>
From: <sip:e84bb5ef-9662-4cbb-893c-73d3051ccf04@172.**.**.35>;tag=fba01752-8fa3-47c0-8e81-3e79593db3a1
To: <sip:1004@172.**.**.72>;tag=2043817601
Call-ID: 293e023f-e513-4c90-beb2-38fc10c7c0de
CSeq: 15758 NOTIFY
Server: ESP32 SIP/2.0
Allow: ACK, INVITE, BYE, UPDATE, CANCEL, OPTIONS, INFO
Content-Length: 0

I (20790) SIP: [1970-01-01/00:00:09]=======================>>
I (21100) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (21100) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (21100) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
W (22035) TONE_STREAM: No more data,ret:0 ,info.byte_pos:26930
I (22035) ESP_AUDIO_TASK: Recv Element[IN_flash-0x3f805ef4] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (22108) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (22108) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (22108) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (23118) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (23118) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (23118) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (24127) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (24127) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (24127) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (25135) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (25135) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (25135) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (25185) MP3_DECODER: Closed
I (25186) ESP_AUDIO_TASK: Received last pos: 26930 bytes
I (25186) ESP_AUDIO_TASK: Recv Element[DEC_mp3-0x3f80608c] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (26143) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (26143) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (26143) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (26303) AUDIO_FORGE: audio forge closed
I (26304) ESP_AUDIO_TASK: Recv Element[Audio_forge-0x3f81aa28] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (27151) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (27151) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (27151) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (27366) ESP_AUDIO_TASK: Received last time: 6464 ms
I (27367) ESP_AUDIO_TASK: Recv Element[OUT_iis-0x3f806240] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (27373) ESP_AUDIO_TASK: ESP_AUDIO status is AEL_STATUS_STATE_FINISHED, 0, src:0, is_stopping:0
I (27382) ESP_AUDIO_TASK: Func:media_ctrl_task, Line:1033, MEM Total:4220459 Bytes, Inter:238079 Bytes, Dram:199287 Bytes

W (27394) ESP_AUDIO_TASK: Destroy the old pipeline, FINISHED
W (27401) ESP_AUDIO_TASK: The old pipeline destroyed, FINISHED
I (28159) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (28159) ESP_AUDIO_CTRL: Enter play procedure, src:0
I (28159) ESP_AUDIO_CTRL: Play procedure, URL is ok, src:0
I (28165) ESP_AUDIO_CTRL: Request_CMD_Queue CMD:0, Available:5, que:0x3ffc1f60
I (28173) ESP_AUDIO_CTRL: Func:_ctrl_play, Line:776, MEM Total:4249591 Bytes, Inter:242595 Bytes, Dram:203803 Bytes

I (28185) ESP_AUDIO_TASK: It's a decoder
I (28189) ESP_AUDIO_TASK: 1.CUR IN:[IN_flash],CODEC:[DEC_mp3],RESAMPLE:[8000],OUT:[OUT_iis],rate:0,ch:0,pos:0
I (28200) ESP_AUDIO_TASK: 2.Handles,IN:0x3f805ef4,CODEC:0x3f80608c,FILTER:0x3f81aa28,OUT:0x3f806240
I (28210) AUDIO_PIPELINE: audio_pipeline_unlinked
W (28215) AUDIO_PIPELINE: There are no listener registered
I (28221) ESP_AUDIO_TASK: 2.2 Update all pipeline
I (28226) ESP_AUDIO_TASK: 2.3 Linked new pipeline
I (28232) AUDIO_PIPELINE: link el->rb, el:0x3f805ef4, tag:IN_flash, rb:0x3f81adc8
I (28240) AUDIO_PIPELINE: link el->rb, el:0x3f80608c, tag:DEC_mp3, rb:0x3f81b240
I (28248) AUDIO_PIPELINE: link el->rb, el:0x3f81aa28, tag:Audio_forge, rb:0x3f81b284
I (28256) ESP_AUDIO_TASK: 3. Previous starting...
I (28262) AUDIO_THREAD: The IN_flash task allocate stack on internal memory
I (28269) AUDIO_THREAD: The DEC_mp3 task allocate stack on external memory
I (28270) TONE_PARTITION: tone partition format 1, total 7
I (28277) MP3_DECODER: MP3 opened
I (28277) ESP_AUDIO_TASK: Blocking play until received AEL_MSG_CMD_REPORT_MUSIC_INFO
I (28287) TONE_STREAM: Tone offset:000002C8, Tone length:26930, pos:0

I (28303) ESP_AUDIO_TASK: Recv Element[IN_flash-0x3f805ef4] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (304) CODEC_ELEMENT_HELPER: The element is 0x3f80608c. The reserve data 2 is 0x0.
I (28325) ESP_AUDIO_TASK: Recv Element[DEC_mp3-0x3f80608c] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (28334) ESP_AUDIO_TASK: Received muisc info then on play
I (28340) ESP_AUDIO_TASK: On event play, status:UNKNOWN, 0
I (28346) AUDIO_THREAD: The Audio_forge task allocate stack on external memory
I (28354) AUDIO_FORGE: audio_forge opened
I (28354) AUDIO_THREAD: The OUT_iis task allocate stack on external memory
I (28367) I2S_STREAM: AUDIO_STREAM_WRITER
I (28367) ESP_AUDIO_CTRL: Exit play procedure, ret:0
I (28377) ESP_AUDIO_TASK: Recv Element[OUT_iis-0x3f806240] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (28383) AUDIO_FORGE: audio_forge reopen
I (28388) ESP_AUDIO_TASK: Recv Element[Audio_forge-0x3f81aa28] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (28404) ESP_AUDIO_TASK: ESP_AUDIO status is AEL_STATUS_STATE_RUNNING, 0, src:0, is_stopping:0
I (28413) ESP_AUDIO_TASK: Func:media_ctrl_task, Line:1033, MEM Total:4170211 Bytes, Inter:237511 Bytes, Dram:198719 Bytes

I (29177) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (29177) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (29177) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
W (30122) TONE_STREAM: No more data,ret:0 ,info.byte_pos:26930
I (30123) ESP_AUDIO_TASK: Recv Element[IN_flash-0x3f805ef4] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (30185) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (30185) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (30185) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (31193) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (31193) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (31193) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (32201) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (32201) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (32201) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (33209) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (33209) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (33209) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (33273) MP3_DECODER: Closed
I (33274) ESP_AUDIO_TASK: Received last pos: 26930 bytes
I (33274) ESP_AUDIO_TASK: Recv Element[DEC_mp3-0x3f80608c] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (34217) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (34217) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (34217) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (34399) AUDIO_FORGE: audio forge closed
I (34400) ESP_AUDIO_TASK: Recv Element[Audio_forge-0x3f81aa28] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (35225) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (35225) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (35225) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (35270) AUDIO_SYS: | Task              | Run Time    | Per | Prio | HWM       | State   | CoreId   | Stack
I (35270) AUDIO_SYS: | main              | 2662        | 0%  | 1    | 1504      | Running | 0        | Intr
I (35280) AUDIO_SYS: | IDLE              | 997030      |49%  | 0    | 912       | Ready   | 1        | Intr
I (35291) AUDIO_SYS: | IDLE              | 939752      |46%  | 0    | 924       | Ready   | 0        | Intr
I (35301) AUDIO_SYS: | button_task       | 24959       | 1%  | 10   | 1568      | Blocked | 0        | Intr
I (35312) AUDIO_SYS: | sip_task          | 11294       | 0%  | 20   | 8036      | Blocked | 0        | Extr
I (35322) AUDIO_SYS: | tiT               | 396         | 0%  | 18   | 2164      | Blocked | 7fffffff | Intr
I (35332) AUDIO_SYS: | esp_periph        | 3469        | 0%  | 5    | 2184      | Blocked | 0        | Intr
I (35343) AUDIO_SYS: | wifi_serv         | 0           | 0%  | 6    | 748       | Blocked | 0        | Extr
I (35353) AUDIO_SYS: | input_key_servi   | 0           | 0%  | 5    | 2232      | Blocked | 1        | Extr
I (35364) AUDIO_SYS: | Tmr Svc           | 0           | 0%  | 1    | 1460      | Blocked | 0        | Intr
I (35374) AUDIO_SYS: | sys_evt           | 0           | 0%  | 20   | 1644      | Blocked | 0        | Intr
I (35384) AUDIO_SYS: | ipc0              | 0           | 0%  | 24   | 948       | Blocked | 0        | Intr
I (35395) AUDIO_SYS: | IN_flash          | 0           | 0%  | 4    | 984       | Blocked | 1        | Intr
I (35405) AUDIO_SYS: | DEC_mp3           | 0           | 0%  | 20   | 2744      | Blocked | 1        | Extr
I (35416) AUDIO_SYS: | media_task        | 4870        | 0%  | 6    | 1812      | Blocked | 0        | Extr
I (35426) AUDIO_SYS: | Audio_forge       | 917         | 0%  | 5    | 2088      | Blocked | 1        | Extr
I (35437) AUDIO_SYS: | esp_timer         | 1196        | 0%  | 22   | 3300      | Suspended | 0        | Intr
I (35447) AUDIO_SYS: | wifi              | 14003       | 0%  | 23   | 4036      | Blocked | 0        | Intr
I (35458) AUDIO_SYS: | OUT_iis           | 4928        | 0%  | 23   | 1592      | Blocked | 1        | Extr
I (35462) ESP_AUDIO_TASK: Received last time: 6464 ms
I (35474) ESP_AUDIO_TASK: Recv Element[OUT_iis-0x3f806240] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (35485) ESP_AUDIO_TASK: ESP_AUDIO status is AEL_STATUS_STATE_FINISHED, 0, src:0, is_stopping:0
I (35494) ESP_AUDIO_TASK: Func:media_ctrl_task, Line:1033, MEM Total:4218131 Bytes, Inter:238079 Bytes, Dram:199287 Bytes

W (35506) ESP_AUDIO_TASK: Destroy the old pipeline, FINISHED
I (35513) AUDIO_SYS: | ipc1              | 0           | 0%  | 24   | 904       | Blocked | 1        | Intr
W (35514) ESP_AUDIO_TASK: The old pipeline destroyed, FINISHED
I (35530) AUDIO_SYS: | esp_dispatcher    | 0           | 0%  | 10   | 1592      | Blocked | 0        | Intr

I (35540) VoIP_EXAMPLE: Func:app_main, Line:212, MEM Total:4249591 Bytes, Inter:242595 Bytes, Dram:203803 Bytes

I (35634) SIP: Sending keep-alive to server
I (36235) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (36235) ESP_AUDIO_CTRL: Enter play procedure, src:0
I (36235) ESP_AUDIO_CTRL: Play procedure, URL is ok, src:0
I (36241) ESP_AUDIO_CTRL: Request_CMD_Queue CMD:0, Available:5, que:0x3ffc1f60
I (36249) ESP_AUDIO_CTRL: Func:_ctrl_play, Line:776, MEM Total:4249591 Bytes, Inter:242595 Bytes, Dram:203803 Bytes

I (36261) ESP_AUDIO_TASK: It's a decoder
I (36265) ESP_AUDIO_TASK: 1.CUR IN:[IN_flash],CODEC:[DEC_mp3],RESAMPLE:[8000],OUT:[OUT_iis],rate:0,ch:0,pos:0
I (36276) ESP_AUDIO_TASK: 2.Handles,IN:0x3f805ef4,CODEC:0x3f80608c,FILTER:0x3f81aa28,OUT:0x3f806240
I (36286) AUDIO_PIPELINE: audio_pipeline_unlinked
W (36291) AUDIO_PIPELINE: There are no listener registered
I (36297) ESP_AUDIO_TASK: 2.2 Update all pipeline
I (36302) ESP_AUDIO_TASK: 2.3 Linked new pipeline
I (36308) AUDIO_PIPELINE: link el->rb, el:0x3f805ef4, tag:IN_flash, rb:0x3f81adb4
I (36316) AUDIO_PIPELINE: link el->rb, el:0x3f80608c, tag:DEC_mp3, rb:0x3f81a904
I (36324) AUDIO_PIPELINE: link el->rb, el:0x3f81aa28, tag:Audio_forge, rb:0x3f81a934
I (36332) ESP_AUDIO_TASK: 3. Previous starting...
I (36338) AUDIO_THREAD: The IN_flash task allocate stack on internal memory
I (36345) AUDIO_THREAD: The DEC_mp3 task allocate stack on external memory
I (36346) TONE_PARTITION: tone partition format 1, total 7
I (36353) MP3_DCOER: MP3 opened
I (36353) ESP_AUDIO_TASK: Blocking play until received AEL_MSG_CMD_REPORT_MUSIC_INFO
I (36363) TONE_STREAM: Tone offset:000002C8, Tone length:26930, pos:0

I (36378) ESP_AUDIO_TASK: Recv Element[IN_flash-0x3f805ef4] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
 (36380) CODEC_ELEMENT_HELPER: The element is 0x3f80608c. The reserve data 2 is 0x0.
I (36401) ESP_AUDIO_TASK: Recv Element[DEC_mp3-0x3f80608c] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (36410) ESP_AUDIO_TASK: Received muisc info then on play
I (36416) ESP_AUDIO_TASK: On event play, status:UNKNOWN, 0
I (36422) AUDIO_THREAD: The Audio_forge task allocate stack on external memory
I (36430) ADIO_FORGE: audio_forge opened
I (36431) AUDIO_THREAD: The OUT_iis task allocate stack on external memory
I (36442) I2S_STREAM: AUDIO_STREAM_WRITER
I (36443) ESP_AUDIO_CTRL: Exit play procedure, ret:0
I (36453) ESP_AUDIO_TASK: Recv Element[OUT_iis-0x3f806240] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (36459) AUDIO_FORGE: audio_forge reopen
I (36464) ESP_AUDIO_TASK: Recv Element[Audio_forge-0x3f81aa28] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_RUNNING
I (36480) ESP_AUDIO_TASK: ESP_AUDIO status is AEL_STATUS_STATE_RUNNING, 0, src:0, is_stopping:0
I (36489) ESP_AUDIO_TASK: Func:media_ctrl_task, Line:1033, MEM Total:4170207 Bytes, Inter:237511 Bytes, Dram:198719 Bytes

I (37253) SIP_SERVICE: ESP_RTC_EVENT_INCOMING...
I (37253) ESP_AUDIO_CTRL: Enter play procedure, src:0
W (37253) ESP_AUDIO_CTRL: Pipeline is already running. Please stop it first.
I (37865) SIP: [1970-01-01/00:00:18]<<=====READ 0427 bytes==
I (37865) SIP:

CANCEL sip:1004@172.**.**.72:16591 SIP/2.0
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPjd50ea539-63e5-4b83-823a-2d31d7a6bdad
From: "user pc" <sip:1002@172.**.**.35>;tag=152ff603-ed9e-42fd-a6ae-47af248c056a
To: <sip:1004@172.**.**.72>
Call-ID: 65568be2-eecd-44a2-a955-f5b8517e5c3f
CSeq: 20645 CANCEL
Reason: Q.850;cause=0
Max-Forwards: 70
User-Agent: Grandstream UCM6202V1.4A 1.0.17.16
Content-Length:  0

I (37901) SIP: [1970-01-01/00:00:18]<<======================
W (37909) SIP: CHANGE STATE FROM 16, TO 2, :func: sip_uas_process_req:1035
I (37915) SIP_SERVICE: ESP_RTC_EVENT_HANGUP
I (37920) SIP: [1970-01-01/00:00:18]=======WRITE 0457 bytes>>
I (37927) SIP:

SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.**.**.35:5060;rport;branch=z9hG4bKPjd50ea539-63e5-4b83-823a-2d31d7a6bdad
Contact: <sip:1004@172.**.**.72:16591;transport=UDP>
From: "user pc" <sip:1002@172.**.**.35>;tag=152ff603-ed9e-42fd-a6ae-47af248c056a
To: <sip:1004@172.**.**.72>;tag=-138885805
Call-ID: 65568be2-eecd-44a2-a955-f5b8517e5c3f
CSeq: 20645 CANCEL
Server: ESP32 SIP/2.0
Allow: ACK, INVITE, BYE, UPDATE, CANCEL, OPTIONS, INFO
Content-Length: 0

I (37970) SIP: [1970-01-01/00:00:18]=======================>>
W (38203) TONE_STREAM: No more data,ret:0 ,info.byte_pos:26930
I (38203) ESP_AUDIO_TASK: Recv Element[IN_flash-0x3f805ef4] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (41345) MP3_DECODER: Closed
I (41346) ESP_AUDIO_TASK: Received last pos: 26930 bytes
I (41346) ESP_AUDIO_TASK: Recv Element[DEC_mp3-0x3f80608c] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (42471) AUDIO_FORGE: audio forge closed
I (42472) ESP_AUDIO_TASK: Recv Element[Audio_forge-0x3f81aa28] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (43534) ESP_AUDIO_TASK: Received last time: 6464 ms
I (43535) ESP_AUDIO_TASK: Recv Element[OUT_iis-0x3f806240] MSG,type:20000,cmd:8,len:4,status:AEL_STATUS_STATE_FINISHED
I (43541) ESP_AUDIO_TASK: ESP_AUDIO status is AEL_STATUS_STATE_FINISHED, 0, src:0, is_stopping:0
I (43550) ESP_AUDIO_TASK: Func:media_ctrl_task, Line:1033, MEM Total:4220079 Bytes, Inter:238079 Bytes, Dram:199287 Bytes

W (43562) ESP_AUDIO_TASK: Destroy the old pipeline, FINISHED
W (43569) ESP_AUDIO_TASK: The old pipeline destroyed, FINISHED
I (51555) AUDIO_SYS: | Task              | Run Time    | Per | Prio | HWM       | State   | CoreId   | Stack
I (51555) AUDIO_SYS: | main              | 2087        | 0%  | 1    | 1504      | Running | 0        | Intr
I (51565) AUDIO_SYS: | IDLE              | 1001893     |49%  | 0    | 912       | Ready   | 1        | Intr
I (51576) AUDIO_SYS: | IDLE              | 953866      |47%  | 0    | 924       | Ready   | 0        | Intr
I (51586) AUDIO_SYS: | esp_periph        | 3424        | 0%  | 5    | 2184      | Blocked | 0        | Intr
I (51596) AUDIO_SYS: | sip_task          | 3096        | 0%  | 20   | 8036      | Blocked | 0        | Extr
I (51607) AUDIO_SYS: | tiT               | 363         | 0%  | 18   | 2164      | Blocked | 7fffffff | Intr
I (51617) AUDIO_SYS: | button_task       | 25274       | 1%  | 10   | 1568      | Blocked | 0        | Intr
I (51628) AUDIO_SYS: | Tmr Svc           | 0           | 0%  | 1    | 1460      | Blocked | 0        | Intr
I (51638) AUDIO_SYS: | sys_evt           | 0           | 0%  | 20   | 1644      | Blocked | 0        | Intr
I (51649) AUDIO_SYS: | ipc1              | 0           | 0%  | 24   | 904       | Blocked | 1        | Intr
I (51659) AUDIO_SYS: | esp_dispatcher    | 0           | 0%  | 10   | 1592      | Blocked | 0        | Intr
I (51669) AUDIO_SYS: | ipc0              | 0           | 0%  | 24   | 948       | Blocked | 0        | Intr
I (51680) AUDIO_SYS: | media_task        | 0           | 0%  | 6    | 1796      | Blocked | 0        | Extr
I (51690) AUDIO_SYS: | esp_timer         | 1127        | 0%  | 22   | 3300      | Suspended | 0        | Intr
I (51701) AUDIO_SYS: | wifi              | 12870       | 0%  | 23   | 4036      | Blocked | 0        | Intr
I (51711) AUDIO_SYS: | wifi_serv         | 0           | 0%  | 6    | 748       | Blocked | 0        | Extr
I (51722) AUDIO_SYS: | input_key_servi   | 0           | 0%  | 5    | 2232      | Blocked | 1        | Extr

I (51732) VoIP_EXAMPLE: Func:app_main, Line:212, MEM Total:4249335 Bytes, Inter:242595 Bytes, Dram:203803 Bytes

Other Items If Possible

• [ ] sdkconfig file (Attach the sdkconfig file from your project folder)
• [ ] elf file in the build folder (Note this may contain all the code details and symbols of your project.)
• [ ] coredump (This provides stacks of tasks.)

[redhyyy]

兄弟你那个乐鑫自建的SIP服务器能注册得上嘛，我从前天开始就登不上了，能分享下授权信息嘛我qq：1768815743

[ktoto2011]

I'm also having the same issue, the previous issue where the firmware won't play a tone on an incoming call has been found here. However, the sound played by this workaround is completely distorted.https://github.com/espressif/esp-adf/issues/1169

[ktoto2011]

https://github.com/espressif/esp-adf/assets/44020882/554170b0-2ac4-4f57-9710-f66306c27f63

This is the same hardware running pipeline_flash_tone firmware for the beep effect

[ktoto2011]

https://github.com/espressif/esp-adf/assets/44020882/a6b76ea3-2ffc-49d8-ae13-0b7f62c5c6bb

This is the same hardware running void firmware with a beep effect, and the sound is very distorted。The firmware driver was adjusted from this discussion https://github.com/espressif/esp-adf/issues/1169