[BUG] ASYNC rest_client requests timeout

[john08burke]

OpenSIPS version you are running

version: opensips 3.1.1 (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: unknown
main.c compiled on 16:01:37 Apr 21 2021 with gcc 8

Describe the bug
In our test environment, we simulate HTTP API integrations with a localized container serving mock data. This results in an almost instantaneous response. If the mock API doesn't inject some delay in the response, OpenSIPS fails to see the response and eventually the request will time out.

Noteworthy logs:

Apr 22 18:34:10 [111] DBG:rest_client:w_async_rest_get: async rest get http://0.0.0.0:8889/fake_endpoint 0x7fca9ff68030 (nil) 0x7fca9ff68220
Apr 22 18:34:10 [111] DBG:rest_client:start_async_http_req: perform code: 0, handles: 0
Apr 22 18:34:10 [111] DBG:rest_client:start_async_http_req: libcurl TCP connect: we should wait up to -1ms (timeout=3000ms, poll=20ms)!
Apr 22 18:34:10 [111] DBG:rest_client:start_async_http_req: curl_multi_timeout() returned -1, pausing 20ms...
Apr 22 18:34:10 [111] DBG:rest_client:start_async_http_req: busy waiting 20ms ...
...
...
Apr 22 18:34:13 [111] ERROR:rest_client:start_async_http_req: connect timeout on http://0.0.0.0:8889/fake_endpoint (3s)

The issue appears to be with the way OpenSIPS is using libcurl's multi interface, specifically the curl_multi_timeout function. The code currently checks curl_multi_timeout for a -1 return and goes to busy loop instead of checking for completed transfer or available fd.

opensips/modules/rest_client/rest_methods.c

Lines 739 to 743 in 1178395

	if (retry_time == -1) {
	LM_DBG("curl_multi_timeout() returned -1, pausing %ldms...\n",
	busy_wait);
	goto busy_wait;
	}

However, libcurl's docs state the following about curl_multi_timeout:

Note: if libcurl returns a -1 timeout here, it just means that libcurl currently has no stored timeout value. You must not wait too long (more than a few seconds perhaps) before you call curl_multi_perform() again.

I also noticed that the timeout from curl_multi_timeout is never utilized, but rather busy waiting is always done via connect_poll_interval param. There is a micro optimization to be done here, as in theory curl_multi_timeout could return value smaller than connect_poll_interval or even signal immediate processing should be done via 0.

To Reproduce

1. Start OpenSIPS with this minimal script
2. Start up some fast responding web server.
3. Send call.
4. Notice OpenSIPS times out request.

OS/environment information

• Operating System: Debian 10
• OpenSIPS installation: git 3.1 latest

[liviuchircu]

hey, @john08burke! I tried to reproduce this locally using an Apache on localhost, but I can't get it to respond faster than 5 ms, so I couldn't reproduce your specific bug. However, your suggested fix seems logical and my tests are still passing after applying it.

What's most interesting, though, is that my async GET using libcurl 7.68 actually gets stuck in a different sequence of events:

Apr 26 12:14:04 [37043] DBG:rest_client:w_async_rest_get: async rest get http://localhost 0x7fef29d16350 (nil) (nil)
Apr 26 12:14:04 [37043] DBG:rest_client:get_multi: multi pool size is now 1
Apr 26 12:14:04 [37043] DBG:rest_client:start_async_http_req: perform code: 0, handles: 1
Apr 26 12:14:04 [37043] DBG:rest_client:start_async_http_req: libcurl TCP connect: we should wait up to 1ms (timeout=20000ms, poll=20ms)!
Apr 26 12:14:04 [37043] DBG:rest_client:start_async_http_req: ongoing transfer on fd 246
Apr 26 12:14:04 [37043] DBG:rest_client:start_async_http_req: >>> add fd 246 to ongoing transfers
...
Apr 26 12:14:04 [37043] DBG:tm:t_handle_async: placing async job into reactor with timeout 0
Apr 26 12:14:04 [37043] DBG:tm:io_watch_add: [UDP_worker] io_watch_add op (246 on 177) (0x56152cc42560, 246, 16, 0x7fef26157d70,1), fd_no=4/8192
Apr 26 12:14:04 [37043] DBG:core:destroy_avp_list: destroying list (nil)
Apr 26 12:14:04 [37043] DBG:core:receive_msg: cleaning up
...
Apr 26 12:14:04 [37043] DBG:tm:t_resume_async: resuming on fd 246, transaction 0x7fef261540d8 
Apr 26 12:14:04 [37043] DBG:rest_client:_resume_async_http_req: resume async processing...
Apr 26 12:14:04 [37043] DBG:rest_client:_resume_async_http_req: perform result: 0, running: 1
Apr 26 12:14:04 [37043] DBG:rest_client:_resume_async_http_req: transfer in progress...

There seems to be an extraneous || !enable_expect_100 exit condition within the while loop, preventing curl_multi_perform() to be called multiple times after a CURLM_OK return code, which should actually be the correct usage flow. Removing the condition unblocks my own fast async transfers, so I'll get that issue fixed in a separate commit.

Cheers!