Interestingly, where I usually see a range of continued messages from a process continually in the debug log, they appear to stop for this PID at 3:47am, and that process seems blocked on a tcp/tls send:
Oct 8 03:47:39 hvprxy osips[2639896]: DBG:core:get_dummy_sip_msg: reusing the static sip msg 0x7f6fc6d859a0 Oct 8 03:47:39 hvprxy osips[2639896]: DBG:core:release_dummy_sip_msg: cleaning the static sip msg 0x7f6fc6d859a0 Oct 8 03:47:39 hvprxy osips[2639896]: DBG:core:destroy_avp_list: destroying list (nil) Oct 8 03:47:39 hvprxy osips[2639896]: DBG:usrloc:update_ucontact: exists callback for type= UL_CONTACT_UPDATE Oct 8 03:47:39 hvprxy osips[2639896]: DBG:usrloc:run_ul_callbacks: contact=0x7f6ec95a3540, callback type 2/15, id 0 entered Oct 8 03:47:39 hvprxy osips[2639896]: DBG:mid_registrar:mid_reg_ct_event: Contact callback (2): contact='sip:[snip]:50375;transport=tls' Oct 8 03:47:39 hvprxy osips[2639896]: DBG:mid_registrar:build_contact: building contact ... Oct 8 03:47:39 hvprxy osips[2639896]: DBG:mid_registrar:build_contact: created Contact HF: Contact: <sip:[snip]:50375;transport=tls>;expires=59#015#012 Oct 8 03:47:39 hvprxy osips[2639896]: DBG:mid_registrar:mid_reg_resp_in: got ptr back: 0x7f6ed4c4b9c0 Oct 8 03:47:39 hvprxy osips[2639896]: DBG:mid_registrar:mid_reg_resp_in: RESPONSE FORWARDED TO caller! Oct 8 03:47:39 hvprxy osips[2639896]: DBG:tm:t_should_relay_response: T_code=0, new_code=200 Oct 8 03:47:39 hvprxy osips[2639896]: DBG:tm:relay_reply: T_state=4, branch=0, save=0, relay=0, cancel_BM=0 Oct 8 03:47:39 hvprxy osips[2639896]: DBG:core:parse_headers: flags=2000 Oct 8 03:47:39 hvprxy osips[2639896]: DBG:core:parse_headers: flags=ffffffffffffffff Oct 8 03:47:39 hvprxy osips[2639896]: DBG:core:build_res_buf_from_sip_res: old size: 585, new size: 483 Oct 8 03:47:39 hvprxy osips[2639896]: DBG:core:build_res_buf_from_sip_res: copied size: orig:583, new: 483, rest: 2 msg=[snip] Oct 8 03:47:39 hvprxy osips[2639896]: DBG:tm:insert_timer_unsafe: [2]: 0x7f6ed4bd82b0 (12697) Oct 8 03:47:39 hvprxy osips[2639896]: DBG:core:tcp_conn_get: con found in state 0 Oct 8 03:47:39 hvprxy osips[2639896]: DBG:core:tcp_conn_get: tcp connection found (0x7f6ec95e6988), acquiring fd Oct 8 03:47:39 hvprxy osips[2639896]: DBG:core:tcp_conn_get: c= 0x7f6ec95e6988, n=16, Usock=643 [no more output for this pid in log] root@hvprxy:~# gdb opensips 2639896 GNU gdb (Ubuntu 9.2-0ubuntu1~20.04) 9.2 Copyright (C) 2020 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-linux-gnu". Type "show configuration" for configuration details. For bug reporting instructions, please see: <http://www.gnu.org/software/gdb/bugs/>. Find the GDB manual and other documentation resources online at: <http://www.gnu.org/software/gdb/documentation/>. [snip] (gdb) bt full #0 0x00007f6fe6d49057 in __libc_recvmsg (fd=fd@entry=643, msg=msg@entry=0x7ffed767fd20, flags=flags@entry=256) at ../sysdeps/unix/sysv/linux/recvmsg.c:28 resultvar = 18446744073709551104 __arg3 = <optimized out> _a2 = <optimized out> sc_ret = <optimized out> __arg1 = <optimized out> _a3 = <optimized out> sc_cancel_oldtype = <optimized out> resultvar = <optimized out> resultvar = <optimized out> __arg2 = <optimized out> _a1 = <optimized out> #1 0x000055b7abde3fac in receive_fd (unix_socket=unix_socket@entry=643, data=data@entry=0x7ffed767fe20, data_len=data_len@entry=8, fd=fd@entry=0x7ffed767fe1c, flags=flags@entry=256) at net/tcp_passfd.c:213 msg = {msg_name = 0x0, msg_namelen = 0, msg_iov = 0x7ffed767fd60, msg_iovlen = 1, msg_control = 0x7ffed767fd70, msg_controllen = 24, msg_flags = 0} iov = {{iov_base = 0x7ffed767fe20, iov_len = 8}} new_fd = <optimized out> ret = <optimized out> n = <optimized out> cmsg = <optimized out> control_un = {cm = {cmsg_len = 519691042825, cmsg_level = 5, cmsg_type = 280, __cmsg_data = 0x7ffed767fd80 "\001"}, control = "\t\000\000\000y\000\000\000\005\000\000\000\030\001\000\000\001\000\000\000\267U\000"} __FUNCTION__ = "receive_fd" #2 0x000055b7abdd9fa3 in tcp_conn_get (id=<optimized out>, ip=ip@entry=0x7ffed767ff00, port=port@entry=50375, proto=proto@entry=PROTO_TLS, proto_extra_id=proto_extra_id@entry=0x0, conn=conn@entry=0x7ffed767fef0, conn_fd=0x7ffed767feec, send_sock=0x7f6fc6b4a420) at net/net_tcp.c:529 c = 0x7f6ec95e6988 tmp = <optimized out> a = <optimized out> hash = <optimized out> response = {140113801537928, 1} part = <optimized out> n = <optimized out> fd = 0 __FUNCTION__ = "tcp_conn_get" #3 0x00007f6ec3b98159 in proto_tls_send (send_sock=0x7f6fc6b4a420, buf=0x7f6fc6d85428 "SIP/2.0 200 OK\r\nv: [snip]r"..., len=483, to=0x7f6ed4bd8350, id=<optimized out>) at proto_tls.c:490 c = 0x55b7abed0230 <__compound_literal.0> dom = 0x0 ip = {af = 2, len = 4, u = {addrl = {9385250162, 0}, addr32 = {795315570, 2, 0, 0}, addr16 = {36210, 12135, 2, 0, 0, 0, 0, 0}, addr = "r\215g/\002\000\000\000\000\000\000\000\000\000\000"}} port = <optimized out> fd = 21943 n = <optimized out> rlen = <optimized out> __FUNCTION__ = "proto_tls_send" #4 0x00007f6ec5ccd3af in msg_send (msg=0x0, len=<optimized out>, buf=0x7f6fc6d85428 "SIP/2.0 200 OK\r\nv: SIP/2.0/TLS 192.168.86.60:50375;rport=50375;[snip]"..., id=<optimized out>, to=0x7f6ed4bd8350, proto=3, send_sock=0x7f6fc6b4a420) at ../../forward.h:123 out_buff = { s = 0x7f6fc6d85428 "SIP/2.0 200 OK\r\nv: SIP/2.0/TLS 192.168.86.60:50375;rport=50375;received=[snip]"..., len = 483} port = <optimized out> ip = <optimized out> out_buff = <optimized out> port = <optimized out> ip = <optimized out> __FUNCTION__ = "msg_send" __ip = <optimized out> #5 send_pr_buffer (rb=rb@entry=0x7f6ed4bd8330, buf=buf@entry=0x7f6fc6d85428, len=<optimized out>, ctx=ctx@entry=0x0) at t_funcs.c:68 --Type <RET> for more, q to quit, c to continue without paging-- __FUNCTION__ = "send_pr_buffer" #6 0x00007f6ec5cc3eef in relay_reply (t=0x7f6ed4bd8230, p_msg=<optimized out>, branch=<optimized out>, msg_status=<optimized out>, cancel_bitmap=0x7ffed7680144) at t_reply.c:1364 relay = 0 save_clone = 0 buf = 0x7f6fc6d85428 "SIP/2.0 200 OK\r\nv: SIP/2.0/TLS 192.168.86.60:50375;rport=50375;received=[snip]"... res_len = 483 relayed_code = 200 relayed_msg = 0x7f6fc6d83c00 bm = {to_tag_val = {s = 0x55b7abfd9808 <global_avps> "", len = -976256698}} totag_retr = 0 reply_status = RPS_COMPLETED uas_rb = 0x7f6ed4bd8330 cb_s = {s = 0x7f6fc6d83c00 "\f", len = -681049792} text = {s = 0x55b7abec1e50 <log_level> "ȬB\311n\177", len = 0} __FUNCTION__ = "relay_reply" [snip] -- Andrew Yager, CEO (BCompSc, JNCIS-SP, MACS (Snr) CP) business nbn™ advisor (advisor 01783150) Real World Technology Solutions - IT People you can trust Voice | Data | IT Procurement | Managed IT rwts.com.au | 1300 798 718 Real World is a DellEMC Gold Partner This document should be read only by those persons to whom it is addressed and its content is not intended for use by any other persons. If you have received this message in error, please notify us immediately. Please also destroy and delete the message from your computer. Any unauthorised form of reproduction of this message is strictly prohibited. We are not liable for the proper and complete transmission of the information contained in this communication, nor for any delay in its receipt. Please consider the environment before printing this e-mail. On Fri, 8 Oct 2021 at 09:34, Andrew Yager <and...@rwts.com.au> wrote: > > Hi, > > Procs had restarted; but repeated the exercise and it's pid 48 this time. > > (gdb) bt full > #0 0x00007f6fe6d48297 in __libc_write (fd=fd@entry=203, > buf=buf@entry=0x7ffed7680050, nbytes=nbytes@entry=24) at > ../sysdeps/unix/sysv/linux/write.c:26 > resultvar = 18446744073709551104 > __arg3 = <optimized out> > _a2 = <optimized out> > sc_ret = <optimized out> > __arg1 = <optimized out> > _a3 = <optimized out> > sc_cancel_oldtype = <optimized out> > resultvar = <optimized out> > resultvar = <optimized out> > __arg2 = <optimized out> > _a1 = <optimized out> > #1 0x000055b7abca8d33 in __ipc_send_job (payload2=0x0, > payload1=0x55b7abc6e760 <rpc_get_pkg_stats>, type=0, fd=203) at > ipc.c:171 > job = {snd_proc = 1, handler_type = 0, payload1 = > 0x55b7abc6e760 <rpc_get_pkg_stats>, payload2 = 0x0} > n = <optimized out> > job = <optimized out> > n = <optimized out> > __FUNCTION__ = "__ipc_send_job" > #2 ipc_send_rpc (dst_proc=dst_proc@entry=48, > rpc=rpc@entry=0x55b7abc6e760 <rpc_get_pkg_stats>, > param=param@entry=0x0) at ipc.c:194 > [snip] > --- > > (gdb) p pt[48] > $1 = {pid = 2639896, type = TYPE_UDP, pg_filter = 0x7f6fc6b4a930, desc > = "SIP receiver udp:1.1.1.1:5060", '\000' <repeats 92 times>, flags = > 228, ipc_pipe = {202, > 203}, ipc_pipe_holder = {202, 203}, ipc_sync_pipe = {204, 205}, > ipc_sync_pipe_holder = {204, 205}, tcp_socks_holder = {642, 643}, > unix_sock = 642, log_level = 4, > default_log_level = 4, load_rt = 0x7f6ec9493f10, load_1m = > 0x7f6ec9493fd0, load_10m = 0x7f6ec9494090, pkg_total = 0x7f6ec94d2048, > pkg_used = 0x7f6ec94d20f8, > pkg_rused = 0x7f6ec94d3b80, pkg_mused = 0x7f6ec94d3c38, pkg_free = > 0x7f6ec94d2e00, pkg_frags = 0x7f6ec94d8050, load = {ST_window = {0 > <repeats 415 times>, 509, > 1000 <repeats 37 times>, 996, 1000 <repeats 109 times>, 996, > 1000 <repeats 12 times>, 997, 1000, 1000, 1000, 1000, 1000, 1000, > 1000, 1000, 997, > 1000 <repeats 32 times>, 996, 1000 <repeats 13 times>, 997, 1000 > <repeats 60 times>, 997, 1000, 1000, 1000, 1000, 1000, 997, 1000 > <repeats 13 times>, 967, 0, 0, 0, > 0, 0, 255, 151, 0, 0, 0, 0, 0, 0, 0, 0, 527, 1000, 906, 0 > <repeats 268 times>}, LT_window = {0 <repeats 459 times>, 301288, 0 > <repeats 140 times>}, > last_time = 1633625259739989, is_busy = 1 '\001'}} > > Andrew > > -- > Andrew Yager, CEO (BCompSc, JNCIS-SP, MACS (Snr) CP) > business nbn™ advisor (advisor 01783150) > Real World Technology Solutions - IT People you can trust > Voice | Data | IT Procurement | Managed IT > rwts.com.au | 1300 798 718 > > > Real World is a DellEMC Gold Partner > > This document should be read only by those persons to whom it is > addressed and its content is not intended for use by any other > persons. If you have received this message in error, please notify us > immediately. Please also destroy and delete the message from your > computer. Any unauthorised form of reproduction of this message is > strictly prohibited. We are not liable for the proper and complete > transmission of the information contained in this communication, nor > for any delay in its receipt. Please consider the environment before > printing this e-mail. > > > On Fri, 8 Oct 2021 at 01:15, Bogdan-Andrei Iancu <bog...@opensips.org> wrote: > > > > OK, getting closer :). Let's see who is the proc ID 46. > > > > In GDB, just do > > > > > p pt[46] > > > > Regards, > > > > Bogdan-Andrei Iancu > > > > OpenSIPS Founder and Developer > > https://www.opensips-solutions.com > > OpenSIPS eBootcamp 2021 > > https://opensips.org/training/OpenSIPS_eBootcamp_2021/ > > > > On 10/7/21 3:37 PM, Andrew Yager wrote: > > > > Hi Bogdan-Andrei, > > > > OK; my non expert opinion is that these two lines in ipc.c may be a pointer > > to a "symptom" of the problem… > > > > // FIXME - we should check if the destination process really listens > > // for read, otherwise we may end up filling in the pipe and block > > > > but, I really want to know why it's blocking on the IPC comms before that. > > > > Here's the BT. > > > > (gdb) bt full > > #0 0x00007f1e4ce9b297 in __libc_write (fd=fd@entry=195, > > buf=buf@entry=0x7fffc86261b0, nbytes=nbytes@entry=24) at > > ../sysdeps/unix/sysv/linux/write.c:26 > > resultvar = 18446744073709551104 > > __arg3 = <optimized out> > > _a2 = <optimized out> > > sc_ret = <optimized out> > > __arg1 = <optimized out> > > _a3 = <optimized out> > > sc_cancel_oldtype = <optimized out> > > resultvar = <optimized out> > > resultvar = <optimized out> > > __arg2 = <optimized out> > > _a1 = <optimized out> > > #1 0x000055ddea5cad33 in __ipc_send_job (payload2=0x0, > > payload1=0x55ddea590760 <rpc_get_pkg_stats>, type=0, fd=195) at ipc.c:171 > > job = {snd_proc = 1, handler_type = 0, payload1 = 0x55ddea590760 > > <rpc_get_pkg_stats>, payload2 = 0x0} > > n = <optimized out> > > job = <optimized out> > > n = <optimized out> > > __FUNCTION__ = "__ipc_send_job" > > #2 ipc_send_rpc (dst_proc=dst_proc@entry=46, rpc=rpc@entry=0x55ddea590760 > > <rpc_get_pkg_stats>, param=param@entry=0x0) at ipc.c:194 > > > > _______________________________________________ Users mailing list Users@lists.opensips.org http://lists.opensips.org/cgi-bin/mailman/listinfo/users