[OpenSIPS-Devel] crash after async rest request
Liviu Chircu
liviu at opensips.org
Tue Nov 22 11:46:41 CET 2016
Hi, Alec!
Unfortunately, the backtrace and logs are not very helpful, as they only
indicate a crash somewhere in libcurl.
Following from this, I tried to replicate the issue on a 2.2 (commit
d250e1c), but with little success, even at a high CPS rate. I did manage
to spot an issue with the non-async call, where libcurl clearly spawns a
thread to do each blocking transfer. This is not okay, as rest_client
instructs libcurl to use a series of faster, OpenSIPS-specific non
thread safe allocation functions. The good news is that we can revert
this with an easy patch.
So, as a next step, we have two directions:
- investigate your crash further / try to replicate. For this, I would
need some specific startup parameters. (OS, curl library
package/version, OpenSIPS startup command line, rest_client module
configuration)
- I notice you are running off the 2.2 release packages. If it's
possible for you to compile / install OpenSIPS 2.2 from sources on your
box, you can change dir to the root OpenSIPS dir, and apply the patch
below in order to fix the "thread safety" bug. Maybe the original
problem goes away with this as well:
git apply <(base64 -d <<EOF
ZGlmZiAtLWdpdCBhL21vZHVsZXMvcmVzdF9jbGllbnQvcmVzdF9jbGllbnQuYyBiL21vZHVsZXMv
cmVzdF9jbGllbnQvcmVzdF9jbGllbnQuYwppbmRleCA5Y2E3N2VmLi5lZmRiOTliIDEwMDY0NAot
LS0gYS9tb2R1bGVzL3Jlc3RfY2xpZW50L3Jlc3RfY2xpZW50LmMKKysrIGIvbW9kdWxlcy9yZXN0
X2NsaWVudC9yZXN0X2NsaWVudC5jCkBAIC0xNTQsNyArMTU0LDcgQEAgc3RydWN0IG1vZHVsZV9l
eHBvcnRzIGV4cG9ydHMgPSB7CiAJbW9kX2Rlc3Ryb3ksCiAJY2hpbGRfaW5pdCwvKiBwZXItY2hp
bGQgaW5pdCBmdW5jdGlvbiAqLwogfTsKLQorI2lmIDAKIHN0YXRpYyB2b2lkICpvc2lwc19tYWxs
b2Moc2l6ZV90IHNpemUpCiB7CiAJdm9pZCAqcCA9IHBrZ19tYWxsb2Moc2l6ZSk7CkBAIC0xOTcs
NiArMTk3LDcgQEAgc3RhdGljIHZvaWQgb3NpcHNfZnJlZSh2b2lkICpwdHIpCiAJaWYgKHB0cikK
IAkJcGtnX2ZyZWUocHRyKTsKIH0KKyNlbmRpZgogCiBzdGF0aWMgaW50IG1vZF9pbml0KHZvaWQp
CiB7CkBAIC0yMTAsMTIgKzIxMSwxNCBAQCBzdGF0aWMgaW50IG1vZF9pbml0KHZvaWQpCiAJCWNv
bm5lY3RfcG9sbF9pbnRlcnZhbCA9IDIwOwogCX0KIAorI2lmIDAKIAljdXJsX2dsb2JhbF9pbml0
X21lbShDVVJMX0dMT0JBTF9BTEwsCiAJCQkJCQkgb3NpcHNfbWFsbG9jLAogCQkJCQkJIG9zaXBz
X2ZyZWUsCiAJCQkJCQkgb3NpcHNfcmVhbGxvYywKIAkJCQkJCSBvc2lwc19zdHJkdXAsCiAJCQkJ
CQkgb3NpcHNfY2FsbG9jKTsKKyNlbmRpZgogCiAJbXVsdGlfaGFuZGxlID0gY3VybF9tdWx0aV9p
bml0KCk7CiAK
EOF
)
Liviu Chircu
OpenSIPS Developer
http://www.opensips-solutions.com
On 22.11.2016 03:35, Alec J Fett wrote:
> (resending with truncated log since my last message was oversized for
> the list)
>
> Hi Devs,
>
> I have an existing config with a working rest_post() query without issue.
> By simply wrapping with async() and specifying a resume route,
> OpenSIPS is crashing every time the request is made via https.
>
> Interestingly, this seems to happen only when making https request
> with async()... that is a) http works with async() and b) both http
> and https work without async().
>
> Logs and stack trace below.
>
>
> Thanks,
>
> Alec
>
>
> version: opensips 2.2.2 (x86_64/linux)
> flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC,
> F_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_lt, epoll_et, sigio_rt, select.
> git revision: d250e1c
> main.c compiled on with gcc 4.8
>
>
>
> [New LWP 8915]
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library "/usr/grte/v4/lib64/libthread_db.so.1".
> Core was generated by `opensips -w /tmp'.
> Program terminated with signal SIGSEGV, Segmentation fault.
> #0 0x00007fdf4f8fd5b3 in ?? () from
> /usr/lib/x86_64-linux-gnu/libcurl-gnutls.so.4
> (gdb) bt full
> #0 0x00007fdf4f8fd5b3 in ?? () from
> /usr/lib/x86_64-linux-gnu/libcurl-gnutls.so.4
> No symbol table info available.
> #1 0x00007fdf4f8d38df in ?? () from
> /usr/lib/x86_64-linux-gnu/libcurl-gnutls.so.4
> No symbol table info available.
> #2 0x00007fdf4f8d4dff in ?? () from
> /usr/lib/x86_64-linux-gnu/libcurl-gnutls.so.4
> No symbol table info available.
> #3 0x00007fdf4f8e66db in ?? () from
> /usr/lib/x86_64-linux-gnu/libcurl-gnutls.so.4
> No symbol table info available.
> #4 0x00007fdf4f8f6047 in ?? () from
> /usr/lib/x86_64-linux-gnu/libcurl-gnutls.so.4
> No symbol table info available.
> #5 0x00007fdf4f8f6671 in curl_multi_perform () from
> /usr/lib/x86_64-linux-gnu/libcurl-gnutls.so.4
> No symbol table info available.
> #6 0x00007fdf4fb2d01d in resume_async_http_req () from
> /usr/lib/x86_64-linux-gnu/opensips/modules/rest_client.so
> No symbol table info available.
> #7 0x00007fdf511efc49 in t_resume_async () from
> /usr/lib/x86_64-linux-gnu/opensips/modules/tm.so
> No symbol table info available.
> #8 0x0000000000519f7a in ?? ()
> No symbol table info available.
> #9 0x000000000051bf47 in tcp_worker_proc ()
> No symbol table info available.
> #10 0x0000000000514c88 in tcp_start_processes ()
> No symbol table info available.
> #11 0x00000000004197da in main ()
> No symbol table info available.
> (gdb)
>
>
> 2016-11-19T02:35:25.626123+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8915]:
> DBG:tm:io_watch_add: [TCP_worker] io_watch_add op (27 on 6) (0x7e4020,
> 27, 16, 0x7fdf51b77df0,1), fd_no=3/1024
> 2016-11-19T02:35:25.626135+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8915]:
> DBG:core:destroy_avp_list: destroying list (nil)
> 2016-11-19T02:35:25.626139+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8915]:
> DBG:core:receive_msg: cleaning up
> 2016-11-19T02:35:25.626160+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8915]:
> DBG:core:tcp_read_req: tcp_read_req end
> 2016-11-19T02:35:25.627576+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8915]:
> DBG:tm:t_resume_async: resuming on fd 27, transaction 0x7fdf51b72d60
> 2016-11-19T02:35:25.628876+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8915]:
> DBG:rest_client:resume_async_http_req: running handles: 1
> 2016-11-19T02:35:25.672898+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8915]:
> DBG:tm:t_resume_async: resuming on fd 27, transaction 0x7fdf51b72d60
> 2016-11-19T02:35:25.828337+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8924]:
> DBG:core:io_wait_loop_epoll: [TCP_main] EPOLLHUP on IN ->connection
> closed by the remote peer!
> 2016-11-19T02:35:25.828363+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8924]:
> CRITICAL:core:receive_fd: EOF on 25
> 2016-11-19T02:35:25.828367+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8924]:
> DBG:core:handle_worker: dead child 12, pid 8915 (shutting down?)
> 2016-11-19T02:35:25.828372+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8924]:
> DBG:core:io_watch_del: [TCP_main] io_watch_del op on index 12 25
> (0x7e4020, 25, 12, 0x0,0x1) fd_no=29 called
> 2016-11-19T02:35:25.828468+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8924]:
> DBG:core:io_wait_loop_epoll: [TCP_main] EPOLLHUP on IN ->connection
> closed by the remote peer!
> 2016-11-19T02:35:25.828485+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8924]:
> DBG:core:handle_tcp_worker: dead tcp worker 0 (pid 8915, no 0)
> (shutting down?)
> 2016-11-19T02:35:25.828490+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8924]:
> DBG:core:io_watch_del: [TCP_main] io_watch_del op on index 20 23
> (0x7e4020, 23, 20, 0x0,0x1) fd_no=28 called
> 2016-11-19T02:35:26.140655+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8903]:
> DBG:core:handle_sigs: status = 139
> 2016-11-19T02:35:26.140759+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8903]:
> INFO:core:handle_sigs: child process 8915 exited by a signal 11
> 2016-11-19T02:35:26.140805+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8903]:
> INFO:core:handle_sigs: core was generated
> 2016-11-19T02:35:26.140850+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8903]:
> INFO:core:handle_sigs: terminating due to SIGCHLD
> 2016-11-19T02:35:26.141012+00:00 cc-foosipas1.foo.voip.example.com
> <http://cc-foosipas1.foo.voip.example.com> opensips[8924]:
> INFO:core:sig_usr: signal 15 received
>
>
>
>
>
> _______________________________________________
> Devel mailing list
> Devel at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/devel
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/devel/attachments/20161122/7bd91315/attachment-0001.htm>
More information about the Devel
mailing list