search

OpenSIPS / opensips

OpenSIPS is a GPL implementation of a multi-functionality SIP Server that targets to deliver a high-level technical solution (performance, security and quality) to be used in professional SIP server platforms.
https://opensips.org
Other
1.28k stars 580 forks source link

[BUG] opensips-cli takes mi commands take a long time to return answer #3241

Closed babakyakhchali closed 12 months ago

babakyakhchali commented 12 months ago

OpenSIPS version you are running

version: opensips 3.4.2 (x86_64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, HP_MALLOC, DBG_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll, sigio_rt, select.
git revision: 8a6e78dde
main.c compiled on  with gcc 8

Describe the bug

running mi commands like "opensips-cli -x mi ps" will take for ever sometimes!

To Reproduce

  1. Start OpenSIPS
  2. Issued "opensips-cli -x mi reg_list"

Expected behavior

on opensips 3.2 this will return immediately Relevant System Logs

this is level 4 debug messages:

Nov  8 17:09:22 Yakhchali-SBC Chakavak_SBC[2346]: DBG:core:cachedb_fetch: from script [redis] - with grp [local]
Nov  8 17:09:22 Yakhchali-SBC Chakavak_SBC[2346]: DBG:cachedb_redis:redis_get: no such key - blacklist_from:<null>
Nov  8 17:09:22 Yakhchali-SBC Chakavak_SBC[2346]: DBG:core:pv_get_xto_attr: no username
Nov  8 17:09:22 Yakhchali-SBC Chakavak_SBC[2346]: DBG:core:cachedb_fetch: from script [redis] - with grp [local]
Nov  8 17:09:22 Yakhchali-SBC Chakavak_SBC[2346]: DBG:cachedb_redis:redis_get: no such key - blacklist_from:<null>@172.25.19.191
Nov  8 17:09:22 Yakhchali-SBC Chakavak_SBC[2346]: DBG:core:MD5StringArray: MD5 calculated: d767ca88f7e19ed72084a44047f56379
Nov  8 17:09:22 Yakhchali-SBC Chakavak_SBC[2346]: DBG:core:parse_headers: flags=ffffffffffffffff
Nov  8 17:09:22 Yakhchali-SBC Chakavak_SBC[2346]: DBG:core:destroy_avp_list: destroying list 0x7f22711a5ec8
Nov  8 17:09:22 Yakhchali-SBC Chakavak_SBC[2346]: DBG:core:receive_msg: cleaning up
Nov  8 17:09:22 Yakhchali-SBC Chakavak_SBC[2292]: DBG:core:udp_read_req: probing packet received len = 2
Nov  8 17:09:28 Yakhchali-SBC Chakavak_SBC[2270]: DBG:nathelper:nh_timer: resolving next hop: '172.25.18.59'
Nov  8 17:09:32 Yakhchali-SBC Chakavak_SBC[2292]: DBG:core:udp_read_req: probing packet received len = 2
Nov  8 17:09:34 Yakhchali-SBC Chakavak_SBC[2271]: DBG:nathelper:nh_timer: resolving next hop: '172.25.18.59'
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: START *** cls=(nil), connection=0x564c7b3d85d0, url=/opensips_mi, method=POST, versio=HTTP/1.1, upload_data[0]=(nil), *con_cls=(nil)
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: running MHD_create_post_processor
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: pr=[0x7f23b21ea528] pp=[(nil)] p_list=[0x7f23b21ea580]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: START *** cls=(nil), connection=0x564c7b3d85d0, url=/opensips_mi, method=POST, versio=HTTP/1.1, upload_data[66]=0x564c7b4165d5, *con_cls=0x7f23b21ea528
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: NOT a regular POST :o)
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:getConnectionHeader: key=[Accept-Encoding] value=[identity]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:getConnectionHeader: Content-Length=66
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:getConnectionHeader: key=[Host] value=[127.0.0.1:8080]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:getConnectionHeader: key=[User-Agent] value=[Python-urllib/3.7]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:getConnectionHeader: Content-Type=application/json
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: got ContentType [3] with len [66]: {"jsonrpc": "2.0", "id": "17917", "method": "which", "params": []}
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: START *** cls=(nil), connection=0x564c7b3d85d0, url=/opensips_mi, method=POST, versio=HTTP/1.1, upload_data[0]=(nil), *con_cls=0x7f23b21ea528
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: normalised_url=[]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:mi_http:mi_json_answer_to_connection: START *** cls=(nil), connection=0x564c7b3d85d0, url=, method=POST, version=HTTP/1.1, upload_data[66]=0x7f23b21ea609, *con_cls=0x7f23b21ea580
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:mi_http:mi_http_run_mi_cmd: got command=which
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:mi_http:mi_http_run_mi_cmd: got mi response = [0x564c7b3d8250]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:mi_http:mi_json_answer_to_connection: building on page
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: MHD_create_response_from_data [0x7f2266852010:1667]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: START *** cls=(nil), connection=0x564c7b3d8250, url=/opensips_mi, method=POST, versio=HTTP/1.1, upload_data[0]=(nil), *con_cls=(nil)
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: running MHD_create_post_processor
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: pr=[0x7f23b21ea528] pp=[(nil)] p_list=[0x7f23b21ea580]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: START *** cls=(nil), connection=0x564c7b3d8250, url=/opensips_mi, method=POST, versio=HTTP/1.1, upload_data[63]=0x564c7b4165d5, *con_cls=0x7f23b21ea528
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: NOT a regular POST :o)
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:getConnectionHeader: key=[Accept-Encoding] value=[identity]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:getConnectionHeader: Content-Length=63
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:getConnectionHeader: key=[Host] value=[127.0.0.1:8080]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:getConnectionHeader: key=[User-Agent] value=[Python-urllib/3.7]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:getConnectionHeader: Content-Type=application/json
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: got ContentType [3] with len [63]: {"jsonrpc": "2.0", "id": "20360", "method": "ps", "params": {}}
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: START *** cls=(nil), connection=0x564c7b3d8250, url=/opensips_mi, method=POST, versio=HTTP/1.1, upload_data[0]=(nil), *con_cls=0x7f23b21ea528
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: normalised_url=[]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:mi_http:mi_json_answer_to_connection: START *** cls=(nil), connection=0x564c7b3d8250, url=, method=POST, version=HTTP/1.1, upload_data[63]=0x7f23b21ea609, *con_cls=0x7f23b21ea580
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:mi_http:mi_http_run_mi_cmd: got command=ps
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:mi_http:mi_http_run_mi_cmd: got mi response = [0x564c7b3d8200]
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:mi_http:mi_json_answer_to_connection: building on page
Nov  8 17:09:36 Yakhchali-SBC Chakavak_SBC[2266]: DBG:httpd:answer_to_connection: MHD_create_response_from_data [0x7f2266852010:3831]

OS/environment information

Additional context this bug raised after updating from 3.2 to 3.4. Inspecting logs shows that it first tries to run a "which" mi command that takes a long time to return!

liviuchircu commented 12 months ago

Hello! This looks to be a known issue with the libmicrohttpd library and package (the OpenSIPS httpd module directly depends on this library). Throughout versions 0.9.53 - 0.9.71, the library contains a bug causing the delays you are noticing.

More info about the issue and mitigation here. Closing this issue for now, please re-open if the solution doesn't work for you!

Cheers!