[Home]

Summary:ASTERISK-30278: tcptls: Abort occurs if SSL error is logged if MALLOC_DEBUG is enabled
Reporter:N A (InterLinked)Labels:
Date Opened:2022-10-26 21:10:47Date Closed:2022-10-31 09:32:32
Priority:MinorRegression?
Status:Closed/CompleteComponents:Core/General Core/HTTP
Versions:18.15.0 20.0.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Debian 10Attachments:
Description:Somehow this didn't happen with 20.0.0-rc2 but does with 20.0.0:

Workaround is to comment out tls stuff in http.conf. This allows Asterisk to load, but anything TLS related is broken.

This should be handled more elegantly and should not prevent Asterisk from loading.

{noformat}
[2022-10-27 02:08:01]  Bound HTTP server 'http server' to address 0.0.0.0:8088
[2022-10-27 02:08:01] ERROR[13478]: tcptls.c:478 __ssl_setup: TLS/SSL error loading cert file. </etc/letsencrypt/live/REDACTED/fullchain.pem>
[2022-10-27 02:08:01] ERROR[13478]: tcptls.c:126 write_openssl_error_to_log: 139767752312704:error:0200100D:system library:fopen:Permission denied:../crypto/bio/bss_file.c:288:fopen('/etc/letsencrypt/live/REDACTED/fullchain.pem','r')
139767752312704:error:20074002:BIO routines:file_ctrl:system lib:../crypto/bio/bss_file.c:290:
139767752312704:error:140DC002:SSL routines:use_certificate_chain_file:system lib:../ssl/ssl_rsa.c:596:

WARNING: Freeing unregistered memory 0x555f8eb934e0 by tcptls.c write_openssl_error_to_log() line 129
Aborted
{noformat}

Backtrace:
{noformat}
Thread 1 (Thread 0x7f6e3a769780 (LWP 13346)):
#0  0x00007f6e3c7da8eb in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
       set = {__val = {134238211, 0, 536870944, 0 <repeats 11 times>, 140722913561296, 94339226947474}}
       pid = <optimized out>
       tid = <optimized out>
#1  0x00007f6e3c7c5535 in __GI_abort () at abort.c:79
       save_stage = 1
       act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {0 <repeats 13 times>, 384, 874643456, 140722913561680}}, sa_flags = 1015628820, sa_restorer = 0x34220000}
       sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x000055cd102a3847 in ast_do_crash () at utils.c:2770
#3  0x000055cd100f7c69 in my_do_crash () at astmm.c:230
#4  0x000055cd100f8698 in __ast_free (ptr=0x55cd10f24460, file=0x55cd1037c6a9 "tcptls.c", lineno=129, func=0x55cd1037cea0 <__PRETTY_FUNCTION__.35492> "write_openssl_error_to_log") at astmm.c:488
       reg = 0x0
#5  0x000055cd10285ad4 in write_openssl_error_to_log () at tcptls.c:129
       fp = 0x55cd10f292d0
       buffer = 0x55cd10f24460 "140111403980672:error:0200100D:system library:fopen:Permission denied:../crypto/bio/bss_file.c:288:fopen('/etc/letsencrypt/live/voip.REDACTED.org/fullchain.pem','r')n140111403980672:error:20074002:BI"...
       length = 366
       __FUNCTION__ = "write_openssl_error_to_log"
       __PRETTY_FUNCTION__ = "write_openssl_error_to_log"
#6  0x000055cd10286aab in __ssl_setup (cfg=0x55cd1042d5e0 <http_tls_cfg>, client=0) at tcptls.c:479
       tmpprivate = 0x55cd118b0580 "/etc/letsencrypt/live/voip.REDACTED.org/privkey.pem"
       disable_ssl = 1
       ssl_opts = 37748736
       __FUNCTION__ = "__ssl_setup"
       __PRETTY_FUNCTION__ = "__ssl_setup"
#7  0x000055cd10287013 in ast_ssl_setup (cfg=0x55cd1042d5e0 <http_tls_cfg>) at tcptls.c:572
#8  0x000055cd102f055b in __ast_http_load (reload=0) at http.c:2535
       cfg = 0x55cd1123eff0
       v = 0x0
       enabled = -1
       new_static_uri_enabled = -1
       new_status_uri_enabled = 0
       newprefix = '000' <repeats 79 times>
       server_name = "000sterisk/20.0.0000000310064020000000000000200227v:n177000000000254A020001000000000300ώ021315U000000P000000000000000000000370ώ021315U000000320NF233374177000000000000"4000000000000200NF233374177000000206314017020315U000000en000000000000000000370067071020315U000000000000000000000000000000b030071020315U000"
       redirect = 0x0
       config_flags = {flags = 0}
       bindport = 8088
       http_tls_was_enabled = 0
       bindaddr = 0x7ffc9b464da0 "0.0.0.0"
       __PRETTY_FUNCTION__ = "__ast_http_load"
       __FUNCTION__ = "__ast_http_load"
#9  0x000055cd102f0bad in load_module () at http.c:2666
       __PRETTY_FUNCTION__ = "load_module"
#10 0x000055cd101bf9de in start_resource (mod=0x55cd10e00610) at loader.c:1718
       tmp = "244232065020315U000000@001340020315U000000000PF233374177000000261267033020315U000000tary Ser000000000000000000000000@001340020315U000000020006340020315U000000000000000000000000000000;270033020315U000000002", '000' <repeats 15 times>, "@001340020315U000000020006340020315U000000360310070020315U", '000' <repeats 26 times>, "pPF233374177000000361272033020315U000000001000000000001", '000' <repeats 11 times>, "220006340020315U000000020006340020315U000000PQF233374177000000000000"...
       res = AST_MODULE_LOAD_SUCCESS
       __PRETTY_FUNCTION__ = "start_resource"
       __FUNCTION__ = "start_resource"
#11 0x000055cd101c042d in start_resource_attempt (mod=0x55cd10e00610, count=0x7ffc9b46526c) at loader.c:1894
       lres = AST_MODULE_LOAD_DECLINE
       __FUNCTION__ = "start_resource_attempt"
#12 0x000055cd101c0e18 in start_resource_list (resources=0x7ffc9b465270, mod_count=0x7ffc9b46526c) at loader.c:1991
       mod = 0x55cd10e00610
       lres = AST_MODULE_LOAD_SUCCESS
       missingdeps = {elems = 0x55cd11bced60, max = 2, current = 0}
       res = 0
       printmissing = 0x0
       __PRETTY_FUNCTION__ = "start_resource_list"
       __FUNCTION__ = "start_resource_list"
#13 0x000055cd101c1c37 in load_resource_list (load_order=0x7ffc9b465420, mod_count=0x7ffc9b46541c) at loader.c:2173
       module_priorities = {elems = 0x55cd10edc7a0, max = 500, current = 363}
       order = 0x0
       attempt = 5
       count = 32
       res = -1
       didwork = 0
       lasttry = 1
       __PRETTY_FUNCTION__ = "load_resource_list"
       __FUNCTION__ = "load_resource_list"
#14 0x000055cd101c2672 in load_modules () at loader.c:2396
       order = 0x0
       load_count = 396
       load_order = {first = 0x0, last = 0x0}
       res = 0
       modulecount = 0
       i = 21965
       cur = 0x0
       warning_msg = 0x7ffc9b465480
       deprecated_in = "020TF233374177000000022375)020315U000000000000000000000000000000060c?020315U000", <incomplete sequence 320>
       removed_in = "t004000000001000000000z312)020315U000000H016000000000000000000340206A020315U000000("
       replacement = " 235003021315U000000060c?020315U000000021.3020315U000000340d3020315U000000000000000000020004000000a 3020315U000000343215020020315U000000006E034020315U000000354363016020315U000000222364016020315U000000200305027020315U000000st017020315U000000vi017020315U000000233p|<n177000000232233f020315U000000000000000000000000000", <incomplete sequence 340>
       start_time = {tv_sec = 1666836403, tv_usec = 120419}
       end_time = {tv_sec = 140722913563776, tv_usec = 94339239780048}
       usElapsed = 94339228460256
       __FUNCTION__ = "load_modules"
       __PRETTY_FUNCTION__ = "load_modules"
#15 0x000055cd100f7486 in asterisk_daemon (isroot=0, runuser=0x55cd10e031a0 "asterisk", rungroup=0x55cd10e030f0 "asterisk") at asterisk.c:4261
       f = 0x55cd10e02e30
       sigs = {__val = {134238211, 0 <repeats 15 times>}}
       num = -1892950143
       buf = 0x7ffc9b467890 "p272062020315U"
       pbx_uuid = "1c97f475-d389-4d7e-9c78-81857c466fbf"
       __FUNCTION__ = "asterisk_daemon"
#16 0x000055cd100f6976 in main (argc=2, argv=0x7ffc9b467978) at asterisk.c:4028
       c = -1
       x = 2
       isroot = 0
       rundir_exists = 1
       runuser = 0x55cd10e031a0 "asterisk"
       rungroup = 0x55cd10e030f0 "asterisk"
       xarg = 0x0
       l = {rlim_cur = 1024, rlim_max = 1048576}
       getopt_settings = 0x55cd103367d8 "BC:cde:FfG:ghIiL:M:mnpqRrs:TtU:VvWXx:"
       __PRETTY_FUNCTION__ = "main"
       __FUNCTION__ = "main"
{noformat}
Comments:By: Asterisk Team (asteriskteam) 2022-10-26 21:10:51.215-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.

Please note that by submitting data, code, or documentation to Sangoma through JIRA, you accept the Terms of Use present at [https://www.asterisk.org/terms-of-use/|https://www.asterisk.org/terms-of-use/].
By: Joshua C. Colp (jcolp) 2022-10-27 03:48:54.032-0500

20.0.0-rc2 and 20.0.0 are the same code. There are no code changes between the two. You are building with MALLOC_DEBUG. If you weren't doing so before then it may not have crashed then.
By: Joshua C. Colp (jcolp) 2022-10-27 03:50:46.087-0500

In fact, I think that's exactly what happened and the issue has been there for ages. It just only happens if MALLOC_DEBUG is enabled and an SSL error is written to the log. That mechanism it appears has OpenSSL providing an allocated buffer, while we try to use our own free to free it. Since it's not in astmm, that code is written to abort since it's a mistake in the code.
By: Friendly Automation (friendly-automation) 2022-10-31 09:32:33.426-0500

Change 19509 merged by Friendly Automation:
tcptls: Prevent crash when freeing OpenSSL errors.

[https://gerrit.asterisk.org/c/asterisk/+/19509|https://gerrit.asterisk.org/c/asterisk/+/19509]
By: Friendly Automation (friendly-automation) 2022-10-31 09:41:54.125-0500

Change 19510 merged by Friendly Automation:
tcptls: Prevent crash when freeing OpenSSL errors.

[https://gerrit.asterisk.org/c/asterisk/+/19510|https://gerrit.asterisk.org/c/asterisk/+/19510]
By: Friendly Automation (friendly-automation) 2022-10-31 12:49:30.737-0500

Change 19461 merged by Friendly Automation:
tcptls: Prevent crash when freeing OpenSSL errors.

[https://gerrit.asterisk.org/c/asterisk/+/19461|https://gerrit.asterisk.org/c/asterisk/+/19461]
By: Friendly Automation (friendly-automation) 2022-11-01 06:31:42.317-0500

Change 19511 merged by Joshua Colp:
tcptls: Prevent crash when freeing OpenSSL errors.

[https://gerrit.asterisk.org/c/asterisk/+/19511|https://gerrit.asterisk.org/c/asterisk/+/19511]