[OpenSIPS-Users] 3.2.3 TLS issue
Mark Farmer
farmorg at gmail.com
Thu Nov 11 14:51:02 EST 2021
Weirdly I started seeing this yesterday and I have not found a solution yet.
I am trying to get a core dump which is not working for some reason but
this is the sanitized log from my server:
INFO:tls_wolfssl:_wolfssl_tls_async_connect: new TLS connection to
52.114.75.24:5061 established
NOTICE:tls_wolfssl:verify_callback: depth = 1, verify success
NOTICE:tls_wolfssl:verify_callback: depth = 0, verify success
ERROR:core:io_watch_add: [TCP_main] epoll_ctl ADD failed: Bad file
descriptor [9]
INFO:tls_wolfssl:_wolfssl_tls_async_connect: new TLS connection to
52.114.132.46:5061 established
CRITICAL:core:sig_usr: segfault in process pid: 6055, id: 12
NOTICE:tls_wolfssl:verify_callback: depth = 1, verify success
NOTICE:tls_wolfssl:verify_callback: depth = 0, verify success
INFO:tls_wolfssl:_wolfssl_tls_async_connect: new TLS connection to
52.114.32.169:5061 established
NOTICE:tls_wolfssl:verify_callback: depth = 1, verify success
NOTICE:tls_wolfssl:verify_callback: depth = 0, verify success
INFO:tls_wolfssl:_wolfssl_tls_accept: New TLS connection from
52.114.132.46:7040 accepted
INFO:tls_wolfssl:tls_dump_cert_info: tls_accept: client TLS certificate
subject: /CN=sip.pstnhub.microsoft.com, issuer: /C=US/O=Microsoft
Corporation/CN=Microsoft RSA TLS CA 02
request_route: Received OPTIONS from 52.114.132.46
request_route: - checking 52.114.132.46:7040
request_route: - OPTIONS FROM Microsoft
request_route: sip OPTIONS from Microsoft, logging contact header
request_route: Contact Header = <sip:sip-du-a-us.pstnhub.microsoft.com:5061>
request_route: Logging Message Buffer: OPTIONS
sip:my.domain.com:5061;transport=tls
SIP/2.0#015#012FROM:
<sip:sip-du-a-us.pstnhub.microsoft.com:5061>;tag=9ca48371-0c0f-4526-a573-078118b77b12#015#012TO:
<sip:my.domain.com:5061;transport=tls>#0
15#012CSEQ: 1 OPTIONS#015#012CALL-ID:
28694205-553a-402e-998e-e0aa5c36edea#015#012MAX-FORWARDS: 69#015#012VIA:
SIP/2.0/TLS 52.114.132.46:5061;branch=z9hG4bKce3091ed#015#012CONTACT: <sip:
sip-du-a-us.pstnhub.microsoft.com:5061>#015#012CONTENT-LENGTH:
0#015#012USER-AGENT: Microsoft.PSTNHub.SIPProxy v.2021.11.2.11 i.USEA
.3#015#012ALLOW: INVITE,ACK,OPTIONS,CANCEL,BYE,NOTIFY#015#012#015
request_route: OPTIONS from tls:52.114.132.46:7040 Sending reply 200 OK
INFO:core:handle_sigs: child process 6055 exited by a signal 11
INFO:core:handle_sigs: core was generated
INFO:core:handle_sigs: terminating due to SIGCHLD
INFO:core:sig_usr: signal 15 received
INFO:core:shutdown_opensips: process 2(6045) [MI FIFO] terminated, still
waiting for 13 more
INFO:core:sig_usr: signal 15 received
INFO:core:shutdown_opensips: process 4(6047) [time_keeper] terminated,
still waiting for 12 more
INFO:core:shutdown_opensips: process 3(6046) [HTTPD INADDR_ANY:8080]
terminated, still waiting for 11 more
INFO:core:shutdown_opensips: process 13(6056) [TCP receiver] terminated,
still waiting for 10 more
INFO:core:shutdown_opensips: process 5(6048) [timer] terminated, still
waiting for 9 more
INFO:core:shutdown_opensips: process 10(6053) [TCP receiver] terminated,
still waiting for 8 more
INFO:core:shutdown_opensips: process 7(6050) [SIP receiver
udp:x.x.x.x:5060] terminated, still waiting for 7 more
INFO:core:shutdown_opensips: process 11(6054) [TCP receiver] terminated,
still waiting for 6 more
INFO:core:shutdown_opensips: process 14(6058) [Timer handler] terminated,
still waiting for 5 more
INFO:core:shutdown_opensips: process 6(6049) [SIP receiver
udp:x.x.x.x:5060] terminated, still waiting for 4 more
INFO:core:shutdown_opensips: process 15(6059) [TCP main] terminated, still
waiting for 3 more
INFO:core:shutdown_opensips: process 8(6051) [SIP receiver
udp:x.x.x.x:5060] terminated, still waiting for 2 more
INFO:core:shutdown_opensips: process 1(6044) [SNMP AgentX] terminated,
still waiting for 1 more
INFO:core:shutdown_opensips: process 9(6052) [SIP receiver
udp:x.x.x.x:5060] terminated, still waiting for 0 more
INFO:core:cleanup: cleanup
INFO:snmpstats:mod_destroy: The SNMPStats module got the kill signal
INFO:snmpstats:mod_destroy: Shutting down the AgentX Sub-Agent!
INFO:tls_wolfssl:mod_destroy: destroying tls_wolfssl module
CRITICAL:core:sig_usr: segfault in attendant (starter) process!
Mark.
On Thu, 11 Nov 2021 at 13:59, Gregory Massel <greg at switchtel.co.za> wrote:
> I'm running OpenSIPS 3.2.3 and it keeps bombing out on SSL connections.
>
> With WolfSSL it segfaults:
>
> Nov 11 11:52:04 msteams /usr/sbin/opensips[15322]: NOTICE:tls_wolfssl:verify_callback: depth = 1, verify success
> Nov 11 11:52:04 msteams /usr/sbin/opensips[15322]: NOTICE:tls_wolfssl:verify_callback: depth = 0, verify success
> Nov 11 11:52:04 msteams /usr/sbin/opensips[15322]: INFO:tls_wolfssl:_wolfssl_tls_async_connect: new TLS connection to 52.114.75.24:5061 established
> Nov 11 11:52:04 msteams /usr/sbin/opensips[15322]: NOTICE:tls_wolfssl:verify_callback: depth = 1, verify success
> Nov 11 11:52:04 msteams /usr/sbin/opensips[15322]: NOTICE:tls_wolfssl:verify_callback: depth = 0, verify success
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15322]: INFO:tls_wolfssl:_wolfssl_tls_async_connect: new TLS connection to 52.114.132.46:5061 established
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15328]: CRITICAL:core:sig_usr: segfault in process pid: 15328, id: 25
> Nov 11 11:52:05 msteams kernel: [22403546.537543] opensips[15328]: segfault at 35 ip 00007ff7b4b3f790 sp 00007fff48dd0a30 error 4 in tls_wolfssl.so[7ff7b4a71000+1e3000]
> Nov 11 11:52:05 msteams kernel: [22403546.537549] Code: ff ff e9 5b ff ff ff 0f 1f 00 53 48 8d 3d 08 40 3b 00 e8 53 09 00 00 85 c0 75 4f 48 8b 3d 50 40 3b 00 48 85 ff 74 14 0f 1f 00 <48> 8b 5f 08 e8 87 36 f7 ff 48 85 db 48 89 df 75
> ef 5b 48 8d 3d d7
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15322]: NOTICE:tls_wolfssl:verify_callback: depth = 1, verify success
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15322]: NOTICE:tls_wolfssl:verify_callback: depth = 0, verify success
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15322]: INFO:tls_wolfssl:_wolfssl_tls_accept: New TLS connection from 52.114.75.24:17152 accepted
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15322]: INFO:tls_wolfssl:tls_dump_cert_info: tls_accept: client TLS certificate subject: /CN=sip.pstnhub.microsoft.com, issuer: /C=US/O=Microsoft Corporation/CN=Microsoft RSA TLS CA 01
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15325]: NOTICE:tls_wolfssl:verify_callback: depth = 1, verify success
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15325]: NOTICE:tls_wolfssl:verify_callback: depth = 0, verify success
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15329]: CRITICAL:core:sig_usr: segfault in process pid: 15329, id: 26
> Nov 11 11:52:05 msteams kernel: [22403546.732270] traps: opensips[15329] general protection fault ip:7ff7b4b0953d sp:7fff48dd0760 error:0 in tls_wolfssl.so[7ff7b4a71000+1e3000]
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15326]: NOTICE:tls_wolfssl:verify_callback: depth = 1, verify success
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15326]: NOTICE:tls_wolfssl:verify_callback: depth = 0, verify success
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15325]: INFO:tls_wolfssl:_wolfssl_tls_async_connect: new TLS connection to 54.171.127.194:5061 established
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15330]: CRITICAL:core:sig_usr: segfault in process pid: 15330, id: 27
> Nov 11 11:52:05 msteams kernel: [22403546.801626] traps: opensips[15330] general protection fault ip:7ff7b4b3f790 sp:7fff48dd0a30 error:0 in tls_wolfssl.so[7ff7b4a71000+1e3000]
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15326]: NOTICE:tls_wolfssl:verify_callback: depth = 1, verify success
> Nov 11 11:52:05 msteams /usr/sbin/opensips[15326]: NOTICE:tls_wolfssl:verify_callback: depth = 0, verify success
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15325]: INFO:tls_wolfssl:_wolfssl_tls_async_connect: new TLS connection to 52.114.14.70:5061 established
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15325]: INFO:tls_wolfssl:_wolfssl_tls_async_connect: new TLS connection to 54.172.60.3:5061 established
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:handle_sigs: child process 15328 exited by a signal 11
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:handle_sigs: core was generated
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:handle_sigs: terminating due to SIGCHLD
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15296]: INFO:core:sig_usr: signal 15 received
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15297]: INFO:core:sig_usr: signal 15 received
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 3(15296) [time_keeper] terminated, still waiting for 28 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 4(15297) [timer] terminated, still waiting for 27 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 5(15298) [SIP receiver udp:127.0.0.1:5060] terminated, still waiting for 26 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 6(15299) [SIP receiver udp:127.0.0.1:5060] terminated, still waiting for 25 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 14(15308) [SIP receiver udp:[0:0:0:0:0:0:0:1]:5060] terminated, still waiting for 24 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 30(15333) [TCP main] terminated, still waiting for 23 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 9(15302) [SIP receiver udp:196.216.192.19:5060] terminated, still waiting for 22 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 15(15310) [SIP receiver udp:[0:0:0:0:0:0:0:1]:5060] terminated, still waiting for 21 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 19(15319) [SIP receiver udp:[2001:43F8:BC0:1:0:0:0:1019]:5060] terminated, still waiting for 20 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 29(15332) [Timer handler] terminated, still waiting for 19 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 1(15294) [MI FIFO] terminated, still waiting for 18 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 21(15322) [TCP receiver] terminated, still waiting for 17 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 20(15320) [SIP receiver udp:[2001:43F8:BC0:1:0:0:0:1019]:5060] terminated, still waiting for 16 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 11(15304) [SIP receiver udp:196.216.192.19:5060] terminated, still waiting for 15 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 8(15301) [SIP receiver udp:127.0.0.1:5060] terminated, still waiting for 14 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 2(15295) [HTTPD INADDR_ANY:8888] terminated, still waiting for 13 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 10(15303) [SIP receiver udp:196.216.192.19:5060] terminated, still waiting for 12 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 13(15307) [SIP receiver udp:[0:0:0:0:0:0:0:1]:5060] terminated, still waiting for 11 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 16(15311) [SIP receiver udp:[0:0:0:0:0:0:0:1]:5060] terminated, still waiting for 10 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 22(15323) [TCP receiver] terminated, still waiting for 9 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 12(15305) [SIP receiver udp:196.216.192.19:5060] terminated, still waiting for 8 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 18(15317) [SIP receiver udp:[2001:43F8:BC0:1:0:0:0:1019]:5060] terminated, still waiting for 7 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 17(15315) [SIP receiver udp:[2001:43F8:BC0:1:0:0:0:1019]:5060] terminated, still waiting for 6 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 24(15326) [TCP receiver] terminated, still waiting for 5 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 7(15300) [SIP receiver udp:127.0.0.1:5060] terminated, still waiting for 4 more
> Nov 11 11:52:06 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 23(15325) [TCP receiver] terminated, still waiting for 3 more
> Nov 11 11:52:09 msteams /usr/sbin/opensips[15293]: INFO:core:shutdown_opensips: process 26(15329) [TCP receiver] terminated, still waiting for 2 more
> Nov 11 11:52:11 msteams /usr/sbin/opensips[15293]: INFO:core:cleanup: cleanup
> Nov 11 11:52:12 msteams /usr/sbin/opensips[15293]: INFO:tls_wolfssl:mod_destroy: destroying tls_wolfssl module
> Nov 11 11:52:12 msteams /usr/sbin/opensips[15293]: CRITICAL:core:fm_free: freeing already freed shm pointer (0x7ff7badd7878), first free: (null): (null)(0) - aborting!
> Nov 11 11:52:18 msteams systemd[1]: opensips.service: Main process exited, code=dumped, status=6/ABRT
> Nov 11 11:52:18 msteams systemd[1]: opensips.service: Failed with result 'core-dump'.
> Nov 11 11:52:18 msteams systemd[1]: opensips.service: Service hold-off time over, scheduling restart.
> Nov 11 11:52:18 msteams systemd[1]: opensips.service: Scheduled restart job, restart counter is at 1.
> Nov 11 11:52:18 msteams systemd[1]: Stopped OpenSIPS is a very fast and flexible SIP (RFC3261) server.
>
>
> With OpenSSL it remains running, however, is still extremely unhappy:
>
> Nov 11 15:46:35 msteams /usr/sbin/opensips[5044]: CRITICAL:core:io_watch_add: #012>>> fd_array idx 8 (fd=236) points to bogus map (fd=-1,type=0,flags=20000000,data=(nil))#012#012It seems you have hit a programming bug.#012Please help us make OpenSIPS better by reporting it at https://github.com/OpenSIPS/opensips/issues
> Nov 11 15:46:35 msteams /usr/sbin/opensips[5044]: CRITICAL:core:io_watch_add: #012>>> used fd map fd=227 is not present in fd_array (fd=227,type=19,flags=80000002,data=0x7f4b4e12eb80)#012#012It seems you have hit a programming bug.#012Please help us make OpenSIPS better by reporting it at https://github.com/OpenSIPS/opensips/issues
> Nov 11 15:46:35 msteams /usr/sbin/opensips[5044]: CRITICAL:core:io_watch_add: #012>>> unused fd_map fd=236 has bogus data (fd=-1,flags=20000000,data=(nil))#012#012It seems you have hit a programming bug.#012Please help us make OpenSIPS better by reporting it at https://github.com/OpenSIPS/opensips/issues
> Nov 11 15:46:35 msteams /usr/sbin/opensips[5044]: CRITICAL:core:io_watch_add: [TCP_main] check failed after successful fd add (fd=244,type=19,data=0x7f4b4e1c8240,flags=2) already=0
>
>
> I didn't have these issues with OpenSIPS 3.1, however, am not sure how to
> downgrade as, when I do, it complains that the database table structure is
> not suitable and there does not appear to be a migration script to revert
> to an older version.
>
>
> --
> Regards
> *Gregory Massel*
> *T* +27 87 550 0000
> *F* +27 11 783 4877
> *W* www.switchtel.co.za
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
--
Mark Farmer
farmorg at gmail.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20211111/f7f0d4bf/attachment-0001.html>
More information about the Users
mailing list