From dev-return-38766-archive-asf-public=cust-asf.ponee.io@subversion.apache.org Mon Dec 17 10:44:47 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id 89171180652 for ; Mon, 17 Dec 2018 10:44:46 +0100 (CET) Received: (qmail 23329 invoked by uid 500); 17 Dec 2018 09:44:45 -0000 Mailing-List: contact dev-help@subversion.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Delivered-To: mailing list dev@subversion.apache.org Received: (qmail 23318 invoked by uid 99); 17 Dec 2018 09:44:44 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 17 Dec 2018 09:44:44 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id 8E37D1805CB for ; Mon, 17 Dec 2018 09:44:44 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: 1.002 X-Spam-Level: * X-Spam-Status: No, score=1.002 tagged_above=-999 required=6.31 tests=[KAM_LAZY_DOMAIN_SECURITY=1, KAM_SHORT=0.001, RCVD_IN_DNSWL_NONE=-0.0001, UNPARSEABLE_RELAY=0.001] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id PEJthzpRla8j for ; Mon, 17 Dec 2018 09:44:42 +0000 (UTC) Received: from mx0.elegosoft.com (mx0.elegosoft.com [78.47.87.163]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id 984805F3F2 for ; Mon, 17 Dec 2018 09:44:41 +0000 (UTC) Received: from localhost (localhost [127.0.0.1]) by mx0.elegosoft.com (Postfix) with ESMTP id 2C365DE216 for ; Mon, 17 Dec 2018 12:14:35 +0100 (CET) Received: from mx0.elegosoft.com ([127.0.0.1]) by localhost (mx0.elegosoft.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id pCXAa9lQMCTI for ; Mon, 17 Dec 2018 12:14:29 +0100 (CET) Received: from ted.stsp.name (ted.stsp.name [217.197.84.34]) by mx0.elegosoft.com (Postfix) with ESMTPSA id E13DB16C99E for ; Mon, 17 Dec 2018 12:14:28 +0100 (CET) Received: from localhost (ted.stsp.name [local]) by ted.stsp.name (OpenSMTPD) with ESMTPA id e4996faa for ; Mon, 17 Dec 2018 10:44:27 +0100 (CET) Date: Mon, 17 Dec 2018 10:44:27 +0100 From: Stefan Sperling To: dev@subversion.apache.org Subject: [PATCH] fix use-after-free in mod_dav_svn's log_warning() Message-ID: <20181217094427.GN22366@ted.stsp.name> Mail-Followup-To: dev@subversion.apache.org MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline User-Agent: Mutt/1.10.1 (2018-07-13) I have hit a use-after-free in mod_dav_svn while running SVN's regression tests on OpenBSD with httpd 2.4. This problem was apparently known to the author; see the comment which is removed in the diff below. In short, the request structure used as logging context can already be freed before log_warning() runs. The repository structure is allocated in the request's pool, which means the repository is closed when the request pool gets freed. I am not sure which, if any, ordering guarantess exist in this situation. But the patch below switches the logging context to the connection instead of the request and I have been unable to reproduce the issue since. Is there a better solution? Does my proposed solution lose too much logging context? Below is a crash trace; On OpenBSD, freed memory gets overwritten with 0xdf. $ egdb /home/stsp/svn/prefix/httpd/bin/httpd httpd.c> < GNU gdb (GDB) 7.12.1 Copyright (C) 2017 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later 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-unknown-openbsd6.4". Type "show configuration" for configuration details. For bug reporting instructions, please see: . Find the GDB manual and other documentation resources online at: . For help, type "help". Type "apropos word" to search for commands related to "word"... Reading symbols from /home/stsp/svn/prefix/httpd/bin/httpd...done. [New process 351753] Core was generated by `httpd'. Program terminated with signal SIGBUS, Bus error. #0 0x000008baba525290 in ap_get_request_module_loglevel (r=0x8bcbc3b0400, module_index=-1) at /home/stsp/svn/src/httpd-2.4.37/server/util_debug.c:200 200 return l->level; (gdb) p l $1 = (const struct ap_logconf *) 0xdfdfdfdfdfdfdfdf (gdb) up #1 0x000008baba50f45c in log_error_core ( file=0x8bd831429d6 "subversion/mod_dav_svn/repos.c", line=1246, module_index=-1, level=3, status=20014, s=0xdfdfdfdfdfdfdfdf, c=0xdfdfdfdfdfdfdfdf, r=0x8bcbc3b0400, pool=0x0, fmt=0x8bd83149264 "%s%s", args=0x7f7ffffceb20) at /home/stsp/svn/src/httpd-2.4.37/server/log.c:1169 1169 int configured_level = r ? ap_get_request_module_loglevel(r, module_index) : (gdb) up #2 0x000008baba50fe9b in ap_log_rerror_ ( file=0x8bd831429d6 "subversion/mod_dav_svn/repos.c", line=1246, module_index=-1, level=3, status=20014, r=0x8bcbc3b0400, fmt=0x8bd83149264 "%s%s") at /home/stsp/svn/src/httpd-2.4.37/server/log.c:1368 1368 log_error_core(file, line, module_index, level, status, r->server, NULL, r, (gdb) p *r $4 = {pool = 0xdfdfdfdfdfdfdfdf, connection = 0xdfdfdfdfdfdfdfdf, server = 0xdfdfdfdfdfdfdfdf, next = 0xdfdfdfdfdfdfdfdf, prev = 0xdfdfdfdfdfdfdfdf, main = 0xdfdfdfdfdfdfdfdf, the_request = 0xdfdfdfdfdfdfdfdf , assbackwards = -538976289, proxyreq = -538976289, header_only = -538976289, proto_num = -538976289, protocol = 0xdfdfdfdfdfdfdfdf , hostname = 0xdfdfdfdfdfdfdfdf , request_time = -2314885530818453537, status_line = 0xdfdfdfdfdfdfdfdf , status = -538976289, method_number = -538976289, method = 0xdfdfdfdfdfdfdfdf , allowed = -2314885530818453537, allowed_xmethods = 0xdfdfdfdfdfdfdfdf, allowed_methods = 0xdfdfdfdfdfdfdfdf, sent_bodyct = -2314885530818453537, bytes_sent = -2314885530818453537, mtime = -2314885530818453537, range = 0xdfdfdfdfdfdfdfdf , clength = -2314885530818453537, chunked = -538976289, read_body = -538976289, read_chunked = -538976289, expecting_100 = 3755991007, kept_body = 0xdfdfdfdfdfdfdfdf, body_table = 0xdfdfdfdfdfdfdfdf, remaining = -2314885530818453537, read_length = -2314885530818453537, headers_in = 0xdfdfdfdfdfdfdfdf, headers_out = 0xdfdfdfdfdfdfdfdf, err_headers_out = 0xdfdfdfdfdfdfdfdf, subprocess_env = 0xdfdfdfdfdfdfdfdf, notes = 0xdfdfdfdfdfdfdfdf, content_type = 0xdfdfdfdfdfdfdfdf , handler = 0xdfdfdfdfdfdfdfdf , content_encoding = 0xdfdfdfdfdfdfdfdf , content_languages = 0xdfdfdfdfdfdfdfdf, vlist_validator = 0xdfdfdfdfdfdfdfdf , user = 0xdfdfdfdfdfdfdfdf , ap_auth_type = 0xdfdfdfdfdfdfdfdf , unparsed_uri = 0xdfdfdfdfdfdfdfdf , uri = 0xdfdfdfdfdfdfdfdf , filename = 0xdfdfdfdfdfdfdfdf , canonical_filename = 0xdfdfdfdfdfdfdfdf , path_info = 0xdfdfdfdfdfdfdfdf , args = 0xdfdfdfdfdfdfdfdf , used_path_info = -538976289, eos_sent = -538976289, per_dir_config = 0xdfdfdfdfdfdfdfdf, request_config = 0xdfdfdfdfdfdfdfdf, log = 0xdfdfdfdfdfdfdfdf, log_id = 0xdfdfdfdfdfdfdfdf , htaccess = 0xdfdfdfdfdfdfdfdf, output_filters = 0xdfdfdfdfdfdfdfdf, input_filters = 0xdfdfdfdfdfdfdfdf, proto_output_filters = 0xdfdfdfdfdfdfdfdf, proto_input_filters = 0xdfdfdfdfdfdfdfdf, no_cache = -538976289, no_local_copy = -538976289, invoke_mtx = 0xdfdfdfdfdfdfdfdf, parsed_uri = { scheme = 0xdfdfdfdfdfdfdfdf , hostinfo = 0xdfdfdfdfdfdfdfdf , user = 0xdfdfdfdfdfdfdfdf , password = 0xdfdfdfdfdfdfdfdf , hostname = 0xdfdfdfdfdfdfdfdf , port_str = 0xdfdfdfdfdfdfdfdf , path = 0xdfdfdfdfdfdfdfdf , query = 0xdfdfdfdfdfdfdfdf , fragment = 0xdfdfdfdfdfdfdfdf , hostent = 0xdfdfdfdfdfdfdfdf, port = 57311, is_initialized = 1, dns_looked_up = 1, dns_resolved = 1}, finfo = {pool = 0xdfdfdfdfdfdfdfdf, valid = -538976289, protection = -538976289, filetype = 3755991007, user = 3755991007, group = 3755991007, inode = 16131858542891098079, device = -538976289, nlink = -538976289, size = -2314885530818453537, csize = -2314885530818453537, atime = -2314885530818453537, mtime = -2314885530818453537, ctime = -2314885530818453537, fname = 0xdfdfdfdfdfdfdfdf , name = 0xdfdfdfdfdfdfdfdf , filehand = 0xdfdfdfdfdfdfdfdf}, useragent_addr = 0xdfdfdfdfdfdfdfdf, useragent_ip = 0xdfdfdfdfdfdfdfdf , trailers_in = 0xdfdfdfdfdfdfdfdf, trailers_out = 0xdfdfdfdfdfdfdfdf, useragent_host = 0xdfdfdfdfdfdfdfdf , double_reverse = -538976289} (gdb) bt #0 0x000008baba525290 in ap_get_request_module_loglevel (r=0x8bcbc3b0400, module_index=-1) at /home/stsp/svn/src/httpd-2.4.37/server/util_debug.c:200 #1 0x000008baba50f45c in log_error_core ( file=0x8bd831429d6 "subversion/mod_dav_svn/repos.c", line=1246, module_index=-1, level=3, status=20014, s=0xdfdfdfdfdfdfdfdf, c=0xdfdfdfdfdfdfdfdf, r=0x8bcbc3b0400, pool=0x0, fmt=0x8bd83149264 "%s%s", args=0x7f7ffffceb20) at /home/stsp/svn/src/httpd-2.4.37/server/log.c:1169 #2 0x000008baba50fe9b in ap_log_rerror_ ( file=0x8bd831429d6 "subversion/mod_dav_svn/repos.c", line=1246, module_index=-1, level=3, status=20014, r=0x8bcbc3b0400, fmt=0x8bd83149264 "%s%s") at /home/stsp/svn/src/httpd-2.4.37/server/log.c:1368 #3 0x000008bd831785a6 in log_warning (baton=0x8bcbc3b0400, err=0x8bcc9317100) at subversion/mod_dav_svn/repos.c:1246 #4 0x000008bd83367cab in cleanup_fs_apr (data=0x8bd75fc3e00) at subversion/libsvn_fs_base/fs.c:297 #5 0x000008bd1c71183f in run_cleanups (cref=0x8bdb2d12d20) at /home/stsp/svn/src/apr-1.5.2/memory/unix/apr_pools.c:2352 #6 0x000008bd1c70fd24 in pool_clear_debug (pool=0x8bdb2d12d00, file_line=0x8baba4a8c30 "/home/stsp/svn/src/httpd-2.4.37/server/mpm/prefork/prefork.c:507") at /home/stsp/svn/src/apr-1.5.2/memory/unix/apr_pools.c:1553 #7 0x000008bd1c70fc37 in apr_pool_clear_debug (pool=0x8bdb2d12d00, file_line=0x8baba4a8c30 "/home/stsp/svn/src/httpd-2.4.37/server/mpm/prefork/prefork.c:507") at /home/stsp/svn/src/apr-1.5.2/memory/unix/apr_pools.c:1613 #8 0x000008baba575f08 in child_main (child_num_arg=9, child_bucket=0) at /home/stsp/svn/src/httpd-2.4.37/server/mpm/prefork/prefork.c:507 #9 0x000008baba575151 in make_child (s=0x8bd737d6a00, slot=9, bucket=0) at /home/stsp/svn/src/httpd-2.4.37/server/mpm/prefork/prefork.c:716 #10 0x000008baba575744 in perform_idle_server_maintenance (p=0x8bceead7500) at /home/stsp/svn/src/httpd-2.4.37/server/mpm/prefork/prefork.c:824 #11 0x000008baba5745af in prefork_run (_pconf=0x8bceead7500, plog=0x8bcdeb90400, s=0x8bd737d6a00) at /home/stsp/svn/src/httpd-2.4.37/server/mpm/prefork/prefork.c:1019 #12 0x000008baba522abf in ap_run_mpm (pconf=0x8bceead7500, plog=0x8bcdeb90400, s=0x8bd737d6a00) at /home/stsp/svn/src/httpd-2.4.37/server/mpm_common.c:94 #13 0x000008baba5032e0 in main (argc=5, argv=0x7f7ffffcf458) at /home/stsp/svn/src/httpd-2.4.37/server/main.c:819 (gdb) quit [[[ * subversion/mod_dav_svn/repos.c (log_warning): Use a connection context instead of a request context. The request may already have been freed when this function executes. (get_resource): Pass connection context to log_warning(). ]]] Index: subversion/mod_dav_svn/repos.c =================================================================== --- subversion/mod_dav_svn/repos.c (revision 1849066) +++ subversion/mod_dav_svn/repos.c (working copy) @@ -1228,22 +1228,14 @@ create_private_resource(const dav_resource *base, static void log_warning(void *baton, svn_error_t *err) { - request_rec *r = baton; + conn_rec *c = baton; const char *continuation = ""; - /* ### hmm. the FS is cleaned up at request cleanup time. "r" might - ### not really be valid. we should probably put the FS into a - ### subpool to ensure it gets cleaned before the request. - - ### is there a good way to create and use a subpool for all - ### of our functions ... ?? - */ - /* Not showing file/line so no point in tracing */ err = svn_error_purge_tracing(err); while (err) { - ap_log_rerror(APLOG_MARK, APLOG_ERR, APR_EGENERAL, r, "%s%s", + ap_log_cerror(APLOG_MARK, APLOG_ERR, APR_EGENERAL, c, "%s%s", continuation, err->message); continuation = "-"; err = err->child; @@ -2485,8 +2477,11 @@ get_resource(request_rec *r, /* cache the filesystem object */ repos->fs = svn_repos_fs(repos->repos); - /* capture warnings during cleanup of the FS */ - svn_fs_set_warning_func(repos->fs, log_warning, r); + /* Capture warnings during cleanup of the FS. + * The FS is cleaned up at request cleanup time, at which point "r" might + * no longer be valid, leading to a use after free. So we log warnings + * with a connection context instead of a request context. */ + svn_fs_set_warning_func(repos->fs, log_warning, r->connection); /* if an authenticated username is present, attach it to the FS */ if (r->user)