ESP not responding to OPTIONS during registration process (AUD-5034)

[davidedigesualdo]

Environment

• Audio development kit: ESP32-LyraT
• Audio kit version: v4.3
• Module or chip used: ESP32-WROVER-E
• IDF version: both v4.4.4-278-g3c8bc2213c and v5.0.1
• ADF version: v2.6-23-gef058dac
• Build system: idf.py
• Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2021r2-patch5) 8.4.0
• Operating system: Linux
• Using an IDE?: No
• Power supply: USB

Problem Description

I tried to build and run the example code under "examples/protocols/voip". Codec and streams initializations are ok.
When the SIP client tries to register to the SIP PBX (Asterisk), the PBX replies with "Auth requested". Then the SIP client sends authenticated registration message, and the SIP PBX replies with an OPTIONS message. The client doesn't reply, but restarts the loop of registration.

Expected Behavior

Into the "Allow" string the SIP client sends "OPTIONS", so it should implement "OPTIONS" methods.
The expecteed behaviour is the SIP client replies with "200 OK" to the options message, so the PBX sends "200 OK" to the REGISTER message and the registration process is complete.

Actual Behavior

The SIP client doesn't reply to the PBX OPTIONS message and restarts the registration process again and again.

Debug Logs

ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_RESET),boot:0x1f (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:7296
load:0x40078000,len:16484
ho 0 tail 12 room 4
load:0x40080400,len:4260
entry 0x40080668
I (29) boot: ESP-IDF v5.0.1-dirty 2nd stage bootloader
I (29) boot: compile time 15:18:03
I (29) boot: chip revision: v3.1
I (33) qio_mode: Enabling default flash chip QIO
I (38) boot.esp32: SPI Speed      : 80MHz
I (43) boot.esp32: SPI Mode       : QIO
I (47) boot.esp32: SPI Flash Size : 4MB
I (52) boot: Enabling RNG early entropy source...
I (57) boot: Partition Table:
I (61) boot: ## Label            Usage          Type ST Offset   Length
I (68) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (75) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (83) boot:  2 factory          factory app      00 00 00010000 00200000
I (90) boot:  3 flash_tone       Unknown data     01 ff 00210000 0007d000
I (98) boot: End of partition table
I (102) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=34038h (213048) map
I (169) esp_image: segment 1: paddr=00044060 vaddr=3ffb0000 size=03360h ( 13152) load
I (173) esp_image: segment 2: paddr=000473c8 vaddr=40080000 size=08c50h ( 35920) load
I (187) esp_image: segment 3: paddr=00050020 vaddr=400d0020 size=ee8a4h (977060) map
I (455) esp_image: segment 4: paddr=0013e8cc vaddr=40088c50 size=0d334h ( 54068) load
I (484) boot: Loaded app from partition at offset 0x10000
I (484) boot: Disabling RNG early entropy source...
I (496) psram: This chip is ESP32-D0WD
I (496) spiram: Found 64MBit SPI RAM device
I (497) spiram: SPI RAM mode: flash 80m sram 80m
I (499) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (506) cpu_start: Pro cpu up.
I (510) cpu_start: Starting app cpu, entry point is 0x40081530
I (0) cpu_start: App cpu up.
I (1012) spiram: SPI SRAM memory test OK
I (1021) cpu_start: Pro cpu start user code
I (1021) cpu_start: cpu freq: 240000000
I (1021) cpu_start: Application information:
I (1024) cpu_start: Project name:     voip_app
I (1029) cpu_start: App version:      1
I (1033) cpu_start: Compile time:     Nov  7 2023 19:22:51
I (1039) cpu_start: ELF file SHA256:  090bd37a...
I (1045) cpu_start: ESP-IDF:          v4.4.4-278-g3c8bc2213c
I (1051) cpu_start: Min chip rev:     v0.0
I (1056) cpu_start: Max chip rev:     v3.99
I (1061) cpu_start: Chip rev:         v3.1
I (1066) heap_init: Initializing. RAM available for dynamic allocation:
I (1073) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (1079) heap_init: At 3FFB50B8 len 0002AF48 (171 KiB): DRAM
I (1085) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1092) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1098) heap_init: At 40095F84 len 0000A07C (40 KiB): IRAM
I (1105) spiram: Adding pool of 4084K of external SPI memory to heap allocator
I (1113) spi_flash: detected chip: gd
I (1117) spi_flash: flash io: qio
W (1121) spi_flash: Detected size(8192k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (1135) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1150) spiram: Reserving pool of 18K of internal memory for DMA/internal allocations
I (1158) VoIP_EXAMPLE: Func:app_main, Line:151, MEM Total:4449511 Bytes, Inter:327535 Bytes, Dram:287255 Bytes

I (1198) VoIP_EXAMPLE: [1.0] Initialize peripherals management
I (1198) VoIP_EXAMPLE: [1.1] Initialize and start peripherals
I (1200) gpio: GPIO[36]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3
I (1209) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3
I (1219) AUDIO_THREAD: The esp_periph task allocate stack on internal memory
I (1226) VoIP_EXAMPLE: [1.2] Create and start input key service
W (1244) PERIPH_TOUCH: _touch_init
I (1244) AUDIO_THREAD: The input_key_service task allocate stack on external memory
I (1250) VoIP_EXAMPLE: [ 2 ] Initialize av stream
I (1256) I2S: DMA Malloc info, datalen=blocksize=128, dma_buf_count=8
I (1262) I2S: DMA Malloc info, datalen=blocksize=128, dma_buf_count=8
I (1269) I2S: I2S0, MCLK output by GPIO0
I (1275) gpio: GPIO[19]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3
E (1283) gpio: gpio_install_isr_service(449): GPIO isr service already installed
I (1304) gpio: GPIO[21]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1304) ES8388_DRIVER: init,out:02, in:00
I (1312) AUDIO_HAL: Codec mode is 3, Ctrl:1
I (1317) VoIP_EXAMPLE: [ 3 ] Initialize tone player
I (1318) AUDIO_THREAD: The media_task task allocate stack on external memory
I (1327) ESP_AUDIO_TASK: media_ctrl_task running...,0x3f804d18

----------------------------- ESP Audio Platform -----------------------------
|                                                                            |
|                       ESP_AUDIO-v1.7.3-7e1b14a-d08db1d                     |
|                     Compile date: Jul 31 2023-03:44:40                     |
------------------------------------------------------------------------------
I (1367) ESP_AUDIO_CTRL: Func:media_ctrl_create, Line:355, MEM Total:4423807 Bytes, Inter:309415 Bytes, Dram:269135 Bytes

I (1381) MP3_DECODER: MP3 init
E (1383) I2S: register I2S object to platform failed
I (1389) I2S: I2S0, MCLK output by GPIO0
I (1393) VoIP_EXAMPLE: [ 4 ] Create Wi-Fi service instance
E (1399) DISPATCHER: exe first list: 0x0
I (1404) DISPATCHER: dispatcher_event_task is running...
I (1410) AUDIO_THREAD: The esp_dispatcher task allocate stack on internal memory
I (1425) AUDIO_THREAD: The wifi_serv task allocate stack on external memory
I (1429) wifi:wifi driver task: 3ffc6808, prio:23, stack:6656, core=0
I (1432) system_api: Base MAC address is not set
I (1437) system_api: read default base MAC address from EFUSE
I (1457) wifi:wifi firmware version: bd1de02
I (1457) wifi:wifi certification version: v7.0
I (1457) wifi:config NVS flash: enabled
I (1457) wifi:config nano formating: disabled
I (1462) wifi:Init data frame dynamic rx buffer num: 128
I (1467) wifi:Init management frame dynamic rx buffer num: 128
I (1472) wifi:Init management short buffer num: 32
I (1477) wifi:Init static tx buffer num: 9
I (1481) wifi:Init tx cache buffer num: 32
I (1484) wifi:Init static rx buffer size: 1600
I (1489) wifi:Init static rx buffer num: 9
I (1492) wifi:Init dynamic rx buffer num: 128
I (1497) wifi_init: rx ba win: 16
I (1500) wifi_init: tcpip mbox: 64
I (1504) wifi_init: udp mbox: 64
I (1508) wifi_init: tcp mbox: 64
I (1512) wifi_init: tcp tx win: 65535
I (1517) wifi_init: tcp rx win: 65535
I (1521) wifi_init: tcp mss: 1440
I (1525) wifi_init: WiFi/LWIP prefer SPIRAM
I (1530) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1621) wifi:mode : sta (24:dc:c3:00:93:14)
I (1621) wifi:enable tsf
I (1631) WIFI_SERV: Connect to wifi ssid: startbit-ap, pwd:
I (2636) AUDIO_SYS: | Task              | Run Time    | Per | Prio | HWM       | State   | CoreId   | Stack
I (2636) AUDIO_SYS: | main              | 1568        | 0%  | 1    | 1508      | Running | 0        | Intr
I (2645) AUDIO_SYS: | IDLE              | 1005036     |49%  | 0    | 924       | Ready   | 1        | Intr
I (2656) AUDIO_SYS: | IDLE              | 652497      |32%  | 0    | 920       | Ready   | 0        | Intr
I (2666) AUDIO_SYS: | esp_periph        | 3927        | 0%  | 5    | 2136      | Blocked | 0        | Intr
I (2676) AUDIO_SYS: | Tmr Svc           | 333527      |16%  | 1    | 1232      | Blocked | 0        | Intr
I (2688) AUDIO_SYS: | tiT               | 586         | 0%  | 18   | 2788      | Blocked | 7fffffff | Intr
I (2697) AUDIO_SYS: | esp_dispatcher    | 3225        | 0%  | 10   | 1584      | Blocked | 0        | Intr
I (2707) AUDIO_SYS: | input_key_servi   | 0           | 0%  | 5    | 3448      | Blocked | 1        | Extr
I (2718) AUDIO_SYS: | media_task        | 0           | 0%  | 6    | 2080      | Blocked | 0        | Extr
I (2728) AUDIO_SYS: | sys_evt           | 0           | 0%  | 20   | 2596      | Blocked | 0        | Intr
I (2738) AUDIO_SYS: | wifi              | 9727        | 0%  | 23   | 4620      | Blocked | 0        | Intr
I (2749) AUDIO_SYS: | esp_timer         | 1318        | 0%  | 22   | 3304      | Suspended | 0        | Intr
I (2759) AUDIO_SYS: | ipc1              | 2543        | 0%  | 24   | 456       | Blocked | 1        | Intr
I (2770) AUDIO_SYS: | wifi_serv         | 780         | 0%  | 6    | 1328      | Blocked | 0        | Extr
I (2780) AUDIO_SYS: | ipc0              | 0           | 0%  | 1    | 436       | Blocked | 0        | Intr

I (2790) VoIP_EXAMPLE: Func:app_main, Line:211, MEM Total:4307263 Bytes, Inter:255759 Bytes, Dram:215479 Bytes

I (2846) wifi:new:<11,2>, old:<1,0>, ap:<255,255>, sta:<11,2>, prof:1
I (3401) wifi:state: init -> auth (b0)
I (3404) wifi:state: auth -> assoc (0)
I (3408) wifi:state: assoc -> run (10)
I (3416) wifi:connected with startbit-ap, aid = 3, channel 11, 40D, bssid = c0:c9:e3:30:90:a6
I (3417) wifi:security: WPA2-PSK, phy: bgn, rssi: -40
I (3419) wifi:pm start, type: 1

W (3424) WIFI_SERV: WiFi Event cb, Unhandle event_base:WIFI_EVENT, event_id:4
I (3426) wifi:<ba-add>idx:0 (ifx:0, c0:c9:e3:30:90:a6), tid:0, ssn:0, winSize:64
I (3501) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (4425) esp_netif_handlers: sta ip: 192.168.10.100, mask: 255.255.255.0, gw: 192.168.10.1
I (4426) WIFI_SERV: Got ip:192.168.10.100
W (4428) WIFI_SERV: STATE type:2, pdata:0x0, len:0
I (4449) VoIP_EXAMPLE: PERIPH_WIFI_CONNECTED [106]
I (4449) VoIP_EXAMPLE: [ 5 ] Create SIP Service
I (4449) ESP_RTC_CORE: esp_rtc ver: 1.1.0 compile date: Aug 31 2023-09:43:55
I (4457) SIP: Conecting...
I (4460) ESP_RTC_CORE: esp_rtc_init done
W (4487) SIP: CHANGE STATE FROM 0, TO 1, :func: sip_connect:1835
I (4488) SIP: [1970-01-01/00:00:01]=======WRITE 0615 bytes>>
I (4489) SIP:

REGISTER sip:SIPSERVER:5070 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.100:13573;branch=z9hG4bK--2083870965;rport
From: <sip:104245410@SIPSERVER:5070>;tag=1280788979
To: <sip:104245410@SIPSERVER:5070>
Contact: <sip:[email protected]:13573;transport=UDP>
Max-Forwards: 70
Call-ID: 775C60BE9745661485E3F6CC495AF7EB56CC5C7D32C4
CSeq: 1 REGISTER
Expires: 3600
User-Agent: HMSIT
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 (4546) SIP: [1970-01-01/00:00:01]=======================>>
I (4584) SIP: [1970-01-01/00:00:01]<<=====READ 0550 bytes==
I (4585) SIP:

SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.10.100:13573;branch=z9hG4bK--2083870965;received=87.20.180.2;rport=13573
From: <sip:104245410@SIPSERVER:5070>;tag=1280788979
To: <sip:104245410@SIPSERVER:5070>;tag=as12317be6
Call-ID: 775C60BE9745661485E3F6CC495AF7EB56CC5C7D32C4
CSeq: 1 REGISTER
Server: OpenVoip PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="ov3", nonce="405db18e"
Content-Length: 0


I (4631) SIP: [1970-01-01/00:00:01]<<======================
I (4639) SIP: Required authentication
I (4644) SIP: [1970-01-01/00:00:01]=======WRITE 0782 bytes>>
I (4648) SIP:

REGISTER sip:SIPSERVER:5070 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.100:13573;branch=z9hG4bK-1885748060;rport
From: <sip:104245410@SIPSERVER:5070>;tag=-383183236
To: <sip:104245410@SIPSERVER:5070>
Contact: <sip:[email protected]:13573;transport=UDP>
Max-Forwards: 70
Call-ID: 775C60BE9745661485E3F6CC495AF7EB56CC5C7D32C4
CSeq: 2 REGISTER
Expires: 3600
User-Agent: HMSIT
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="104245410", realm="ov3", nonce="405db18e", uri="sip:SIPSERVER:5070", response="b0ccd0163044a053f8ecde6c61533375", algorithm=MD5


I (4720) SIP: [1970-01-01/00:00:01]=======================>>
I (4756) SIP: [1970-01-01/00:00:01]<<=====READ 0589 bytes==
I (4757) SIP:

OPTIONS sip:[email protected]:13573;transport=UDP SIP/2.0
Via: SIP/2.0/UDP SIPSERVER:5060;branch=z9hG4bK70ada0ed;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk@SIPSERVER>;tag=as01fd19c1
To: <sip:[email protected]:13573;transport=UDP>
Contact: <sip:asterisk@SIPSERVER:5060>
Call-ID: 2628799d441a0e9d0ed931863cad185e@SIPSERVER:5060
CSeq: 102 OPTIONS
User-Agent: OpenVoip PBX
Date: Tue, 21 Nov 2023 06:25:35 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


I (4807) SIP: [1970-01-01/00:00:01]<<======================
E (4815) SIP: Error register device
W (4818) SIP: CHANGE STATE FROM 1, TO 0, :func: sip_register:1850
W (5825) SIP: CHANGE STATE FROM 0, TO 0, :func: sip_reconnect:383

Suggestions

It would be great if you can add the possibility to customize the allowed methods in the SIP client configuration, so that a developer can enable/disable the supported methods.

[ahhfzhang]

Hi @davidedigesualdo ,

Our SIP client usually replies with "200 OK" to the 'OPTIONS' message, but not during registration process.

Maybe you could turn off the 'OPTIONS' message on the PBX ？ In addition, we also support configuring the 'OPTIONS' message on client side here.

The other thing is why the 'OPTIONS' message is sent before the registration is replied. Maybe you can try to use TCP/TLS to registration to the server.

br.

[davidedigesualdo]

Hi @ahhfzhang,
thank you for your kind reply.

Unfortunately the PBX is a public service which is not directly managed by me. I've already notified the PBX customer service, but they cannot switch off the OPTIONS during the registration process.

Moreover, the RFC 3261 (SIP: Session Initiation Protocol) doesn't prevent the UAS to send an OPTIONS message to the UA during the registration process, so the correct behaviour should be the UA to answer to the OPTIONS message.

I've tried to use TCP connection, and the behaviour is the same.

[davidedigesualdo]

Hi,
is there any update about this issue?

[kamcio2603]

+1, the same problem with public voip provider, it works great on fritzbox voip device, but not with public providers :(