[BUG] ASYNC rest_client requests timeout triggers only after it receives data

[vbomfim]

Hi guys,

OpenSIPS version you are running

version: opensips 3.2.3 (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.
main.c compiled on  with gcc 9

Describe the bug
The async rest_post is not triggering before receiving data.
The log shows "connected, but transfer timed out (5s)", but only after it receives the response that last longer than the expected timeout.
May be related to #2483 #2483

To Reproduce

   async(rest_post($var(connectURL), $json_compact(req), "application/json" , $var(resp), $var(ct), $var(rcode)), resume);

Config:

OPENSIPS_VERSION = 3.2
OPENSIPS_BUILD = nightly or releases
modparam("rest_client", "curl_timeout", 5)
modparam("rest_client", "connection_timeout", 5)
modparam("rest_client", "connect_poll_interval", 20)

Expected behavior
Trigger the resume context on timeout.

Relevant System Logs

Dec 10 23:38:08 [17] DBG:rest_client:w_async_rest_post: async rest post 'http://192.168.2.44:9099/v1/' 0x7f4f12f996b8 0x7f4f12f99898 0x7f4f12f999e0
Dec 10 23:38:08 [17] DBG:rest_client:get_multi: multi pool size is now 1
Dec 10 23:38:08 [17] DBG:rest_client:start_async_http_req: perform code: 0, handles: 1
Dec 10 23:38:08 [17] DBG:rest_client:start_async_http_req: libcurl TCP connect: we should wait up to 199ms (**timeout=5000ms, poll=20ms**)!
Dec 10 23:38:08 [17] DBG:rest_client:start_async_http_req: busy waiting 20ms ...
Dec 10 23:38:08 [17] DBG:rest_client:start_async_http_req: perform code: 0, handles: 1
Dec 10 23:38:08 [17] DBG:rest_client:start_async_http_req: ongoing transfer on fd 4`
Dec 10 23:38:08 [17] DBG:rest_client:start_async_http_req: >>> add fd 4 to ongoing transfers
Dec 10 23:38:08 [17] DBG:tm:t_handle_async: placing async job into reactor with timeout 0
Dec 10 23:38:08 [17] DBG:tm:io_watch_add: [UDP_worker] io_watch_add op (4 on 96) (0x55c78652c120, 4, 16, 0x7f4f11375548,1), fd_no=4/41943
Dec 10 23:38:08 [17] DBG:core:destroy_avp_list: destroying list (nil)
**Dec 10 23:38:08** [17] DBG:core:receive_msg: cleaning up
    15s later, but the timeout is 5s.
**Dec 10 23:38:23** [17] DBG:tm:t_resume_async: resuming on fd 4, transaction 0x7f4f1137d298 
Dec 10 23:38:23 [17] DBG:rest_client:_resume_async_http_req: resume async processing...
Dec 10 23:38:23 [17] DBG:rest_client:_resume_async_http_req: perform result: 0, running: 0
Dec 10 23:38:23 [17] DBG:rest_client:del_transfer: del fd 4
Dec 10 23:38:23 [17] ERROR:rest_client:_resume_async_http_req: **connected, but transfer timed out (5s)**
Dec 10 23:38:23 [17] DBG:rest_client:_resume_async_http_req: HTTP response code: 0
Dec 10 23:38:23 [17] DBG:tm:io_watch_del: [UDP_worker] io_watch_del op on index -1 4 (0x55c78652c120, 4, -1, 0x10,0x1) fd_no=5 called
Dec 10 23:38:23 [17] async rest_post() with -3, user=4384981095
Dec 10 23:38:23 [17] DBG:core:comp_scriptvar: int 26: -3 / 0
Dec 10 23:38:23 [17] async rest_post() failed with -3, user=4384981095
Dec 10 23:38:23 [17] DBG:core:MD5StringArray: MD5 calculated: 3beb091d49b6a2e245ae9c8c3efb98c5
Dec 10 23:38:23 [17] DBG:core:parse_headers: flags=ffffffffffffffff
Dec 10 23:38:23 [17] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Dec 10 23:38:23 [17] DBG:tm:set_timer: relative timeout is 500000
Dec 10 23:38:23 [17] DBG:tm:insert_timer_unsafe: [4]: 0x7f4f1137d3e0 (40200000)
Dec 10 23:38:23 [17] DBG:tm:insert_timer_unsafe: [0]: 0x7f4f1137d410 (44)
Dec 10 23:38:23 [17] DBG:tm:_reply_light: reply sent out. buf=0x7f4f131e0360: SIP/2.0 5..., shmem=0x7f4f113755c0: SIP/2.0 5
Dec 10 23:38:23 [17] DBG:tm:_reply_light: finished
Dec 10 23:38:23 [17] DBG:tm:do_t_cleanup: transaction 0x7f4f1137d298 already updated! Skipping update!
Dec 10 23:38:23 [17] DBG:tm:t_unref: UNREF_UNSAFE: [0x7f4f1137d298] after is 0

OS/environment information

• Operating System:
  $ cat /proc/version
  Linux version 5.11.0-1021-azure (buildd@lgw01-amd64-016) (gcc (Ubuntu 9.3.0-17ubuntu120.04) 9.3.0, GNU ld (GNU Binutils for Ubuntu) 2.34) new rpm modules #2220.04.1-Ubuntu SMP Fri Oct 29 01:11:25 UTC 2021

• OpenSIPS installation:
  OPENSIPS_BUILD=releases
  OPENSIPS_VERSION=3.2
  OPENSIPS_EXTRA_MODULES="opensips-json-module opensips-restclient-module opensips-uuid-module"

Additional context
#2483 #2483

[github-actions]

Any updates here? No progress has been made in the last 15 days, marking as stale. Will close this issue if no further updates are made in the next 30 days.

[liviuchircu]

Hi, @vbomfim! The inability to "trigger" the libcurl async context until only when some signaling (HTTP 200 OK, 500 Server Error, etc.) is received on the socket is a known issue and a solution was implemented per #1838 in all OpenSIPS 3.2+ releases. The fix was to add the ability to set a timeout for the async() statement itself! For example:

async(rest_get(...), resume_route, 5);

This should force-trigger your resume_route after at most 5 seconds, regardless whether the libcurl file descriptor stuck in the epoll loop receives signaling in due time or not.

[vbomfim]

Hi @liviuchircu , Thank you very much for your help. It did work.
Wondering if I could give back updating the doc https://www.opensips.org/Documentation/Script-Async-3-3.
Thank you