Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
3 tasks
Olejan opened this issue Apr 23, 2024 · 4 comments
Open
3 tasks

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

Olejan opened this issue Apr 23, 2024 · 4 comments

Comments

@Olejan
Copy link

Olejan commented Apr 23, 2024

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.)
@github-actions github-actions bot changed the title Service sounds are played poorly in the voip project Service sounds are played poorly in the voip project (AUD-5369) Apr 23, 2024
@redhyyy
Copy link

redhyyy commented Apr 24, 2024

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

@ktoto2011
Copy link

ktoto2011 commented Apr 30, 2024 •
edited
Loading

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.#1169

@ktoto2011
Copy link

pipeline_flash_tone.mp4

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

@ktoto2011
Copy link

ktoto2011 commented Apr 30, 2024 •
edited
Loading

void.mp4

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 #1169

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Olejan @ktoto2011 @redhyyy