Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1j2pK1-0007hl-WB for pgsql-bugs@arkaria.postgresql.org; Sat, 15 Feb 2020 04:44:54 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1j2pK0-0006tn-CL for pgsql-bugs@arkaria.postgresql.org; Sat, 15 Feb 2020 04:44:52 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1j2pJz-0006tf-Pm for pgsql-bugs@lists.postgresql.org; Sat, 15 Feb 2020 04:44:52 +0000 Received: from mail-lf1-x142.google.com ([2a00:1450:4864:20::142]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1j2pJw-0004cX-Sh for pgsql-bugs@lists.postgresql.org; Sat, 15 Feb 2020 04:44:50 +0000 Received: by mail-lf1-x142.google.com with SMTP id l18so8205612lfc.1 for ; Fri, 14 Feb 2020 20:44:48 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=subject:to:cc:references:from:message-id:date:user-agent :mime-version:in-reply-to:content-language; bh=iZNr66WH8ghe/MXPKYSQ+VmMt62Qbw/Ns2CvC/rlh7I=; b=TschGHPBscUbRLLSfJVCYA9QN5uiAKNs2zbEsV8Exjf51Fm6I6bJb0kQfl6H8UqZtu eadAR6HpCvgxNnednrN7M8BX/GLs4CDxZzG5uItu68QowSG0ES2+tHUGnrLh1f3Mi3YH 4vo43Ck8TRcQ/Wi2Bg629Kv5CBGtD/FgWdbGuUNk1yyfQH/wIxpqhwFBbKvp9ZS0TNl/ 3/7vtOllMBMWMeHQFbTkQsb6vi6tghqbPMkfQz9M4nsGuZ1tsO0K2gX8epaiGKV+tTnF NRPTKxjUH02Qdo1HWrHSM7/HxLalkB2Zfu3TAvqWVqCfpkdIN2jvv16UqApof2RojRtf XwLA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:subject:to:cc:references:from:message-id:date :user-agent:mime-version:in-reply-to:content-language; bh=iZNr66WH8ghe/MXPKYSQ+VmMt62Qbw/Ns2CvC/rlh7I=; b=VrvGbCMAJ5hrwhUlFsUy7Ace2dt++7h+isa2c53iuJltB8YypkRxtZXoujn8013D5O keOeOjmbL8mARTl1owC28xBNV+3Q4cutr/oAxW6li2ipf4vn3hYlsZhhVrzcS/Tbnblq +E6ZDXzqtwDaw/sH5Vl0xR2updeo0f+z3WFoxsbs+Gwc/7Oh6hqCTsTLDxCmvOua1tD2 e8lhdu2o5B6UUllTKN77+YgJ1vdmHGjkpBqp2A3/nMq1QNnMbp+N4ANwiQsBtC6xsZUO rPZ5U9qFLxxW+4eJlwxZkr+U/I41iI0XuWkmJP9DCivHwa6BKKa0p4c3kIh8IDoKuRdL iI8A== X-Gm-Message-State: APjAAAVQtoKoSdaODRvhgDvGB4ezWZqTndLBgogBrDIrO0fhA5ZeFQce jHfKBH3olFZSwn/U4gLAVJxljRJpHD0= X-Google-Smtp-Source: APXvYqyzw+JE65Ca0zSQ1ZQ10PAaC/suoG54CJBnURbROeNFEFuQPc9I0YzLHjEN2AwKvbuG2U8bSQ== X-Received: by 2002:ac2:522f:: with SMTP id i15mr3210495lfl.138.1581741886521; Fri, 14 Feb 2020 20:44:46 -0800 (PST) Received: from [1.0.0.7] ([178.155.4.213]) by smtp.gmail.com with ESMTPSA id k12sm3688345lfc.33.2020.02.14.20.44.45 (version=TLS1_3 cipher=TLS_AES_128_GCM_SHA256 bits=128/128); Fri, 14 Feb 2020 20:44:45 -0800 (PST) Subject: Re: BUG #16259: Cannot Use "pg_ctl start -l logfile" on Clean Install on Windows Server 2012/2016 To: Tom Lane , Heath Lord Cc: "Jonathan S. Katz" , pgsql-bugs@lists.postgresql.org References: <16259-c5ebed32a262a8b1@postgresql.org> <22619.1581702327@sss.pgh.pa.us> <98b2f7d0-9010-358a-36c9-a5b09020dd08@postgresql.org> <3568.1581710233@sss.pgh.pa.us> <7959.1581716776@sss.pgh.pa.us> From: Alexander Lakhin Message-ID: <3f72f608-88ab-bd43-b7de-685c26e69421@gmail.com> Date: Sat, 15 Feb 2020 07:44:44 +0300 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101 Thunderbird/68.4.1 MIME-Version: 1.0 In-Reply-To: <7959.1581716776@sss.pgh.pa.us> Content-Type: multipart/mixed; boundary="------------F3F241EEAD5D9E876F17BE30" Content-Language: en-US List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk This is a multi-part message in MIME format. --------------F3F241EEAD5D9E876F17BE30 Content-Type: multipart/alternative; boundary="------------5DBE62F0431765C88863B0E7" --------------5DBE62F0431765C88863B0E7 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit Hello Tom, 15.02.2020 00:46, Tom Lane wrote: > Heath Lord writes: >> Another interesting thing that we have found is that this issue >> only manifests >> itself if you are trying to launch the pg_ctl command as a privileged >> user. If you >> try to run this command as a user who is not an Administrator, then we do not >> see this issue. This is another reason why Dory does not exhibit this behavior. >> With this finding, it has to be something with how pg_ctl is restricting the >> user when running the postgres.exe command from the CMD.exe process, >> so we are not trying to launch postgres as a privileged user. > OOOHHH ... I think the light just went on, then. The reason we have > an issue is that we drop admin privileges (via CreateRestrictedProcess) > when we launch CMD.EXE, just below this. So we are still admin when > the new code touches the log file, and that's why it's getting created > with different privileges from files that the postmaster (or CMD.EXE) > would create. I can easily reproduce this by opening "x64 Native Tools Command Prompt for VS 2019" with "Run as Administrator". When executing `vcregress taptest src/bin/pg_basebackup` in this command prompt, I get: t/010_pg_basebackup.pl ... 1/106 Bailout called.  Further testing stopped:  pg_ctl start failed FAILED--Further testing stopped: pg_ctl start failed > The idea I'd had for a fix is that we don't need to actually create the > file if it's not there yet. All we need is to delay if it's there and > can't be opened. So rather than open for writing, I think we could open > for reading, along the lines of > > FILE *fd = fopen(log_file, "r"); > > if (fd != NULL) /* we may just ignore any error */ > fclose(fd); > > The looping logic in pgwin32_open doesn't really care which kind > of access we're asking for. With the proposed change and the delay_after_unlink_pid.patch [1] applied I get the same fail on `vcregress taptest src/bin/pg_basebackup` as before 0da33c76: waiting for server to shut down.... done server stopped waiting for server to start....The process cannot access the file because it is being used by another process.  stopped waiting pg_ctl: could not start server So just the read permission is not sufficient for that check. > BTW, we could make this at least slightly cheaper by using > open() not fopen(). > > Alexander, this was your patch to start with ... any thoughts? Yes, it was my omission. Please look at the improved patch. It works for me in both command prompts and still gives a meaningful message on error.   In fact running taptests (pg_basebackup, pg_ctl) in an elevated prompt fails anyway, but later and with other errors, e.g.: t/001_start_stop.pl .. ok t/002_status.pl ...... ok t/003_promote.pl ..... 5/12 Bailout called.  Further testing stopped:  pg_ctl start failed FAILED--Further testing stopped: pg_ctl start failed ... pg_ctl: could not start server Examine the log output. # pg_ctl start failed; logfile: 2020-02-15 07:16:05.588 MSK [1784] PANIC:  could not open file "global/pg_control": Permission denied Bail out!  pg_ctl start failed But I think it's not related to this bug. [1] https://www.postgresql.org/message-id/e5179494-715e-f8a3-266b-0cf52adac8f4%40gmail.com Best regards, Alexander --------------5DBE62F0431765C88863B0E7 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 8bit
Hello Tom,
15.02.2020 00:46, Tom Lane wrote:
Heath Lord <heath.lord@crunchydata.com> writes:

   Another interesting thing that we have found is that this issue
only manifests
itself if you are trying to launch the pg_ctl command as a privileged
user.  If you
try to run this command as a user who is not an Administrator, then we do not
see this issue.  This is another reason why Dory does not exhibit this behavior.
  With this finding, it has to be something with how pg_ctl is restricting the
user when running the postgres.exe command from the CMD.exe process,
so we are not trying to launch postgres as a privileged user.

OOOHHH ... I think the light just went on, then.  The reason we have
an issue is that we drop admin privileges (via CreateRestrictedProcess)
when we launch CMD.EXE, just below this.  So we are still admin when
the new code touches the log file, and that's why it's getting created
with different privileges from files that the postmaster (or CMD.EXE)
would create.
I can easily reproduce this by opening "x64 Native Tools Command Prompt for VS 2019" with "Run as Administrator". When executing `vcregress taptest src/bin/pg_basebackup` in this command prompt, I get:
t/010_pg_basebackup.pl ... 1/106 Bailout called.  Further testing stopped:  pg_ctl start failed
FAILED--Further testing stopped: pg_ctl start failed
The idea I'd had for a fix is that we don't need to actually create the
file if it's not there yet.  All we need is to delay if it's there and
can't be opened.  So rather than open for writing, I think we could open
for reading, along the lines of

        FILE       *fd = fopen(log_file, "r");

        if (fd != NULL)     /* we may just ignore any error */
            fclose(fd);

The looping logic in pgwin32_open doesn't really care which kind
of access we're asking for.
With the proposed change and the delay_after_unlink_pid.patch [1] applied I get the same fail on `vcregress taptest src/bin/pg_basebackup` as before 0da33c76:
waiting for server to shut down.... done
server stopped
waiting for server to start....The process cannot access the file because it is being used by another process.
 stopped waiting
pg_ctl: could not start server

So just the read permission is not sufficient for that check. 
BTW, we could make this at least slightly cheaper by using
open() not fopen().

Alexander, this was your patch to start with ... any thoughts?
Yes, it was my omission. Please look at the improved patch.
It works for me in both command prompts and still gives a meaningful message on error.
 
In fact running taptests (pg_basebackup, pg_ctl) in an elevated prompt fails anyway, but later and with other errors, e.g.:

t/001_start_stop.pl .. ok
t/002_status.pl ...... ok
t/003_promote.pl ..... 5/12 Bailout called.  Further testing stopped:  pg_ctl start failed
FAILED--Further testing stopped: pg_ctl start failed
...
pg_ctl: could not start server
Examine the log output.
# pg_ctl start failed; logfile:
2020-02-15 07:16:05.588 MSK [1784] PANIC:  could not open file "global/pg_control": Permission denied
Bail out!  pg_ctl start failed

But I think it's not related to this bug.

[1] https://www.postgresql.org/message-id/e5179494-715e-f8a3-266b-0cf52adac8f4%40gmail.com

Best regards,
Alexander
--------------5DBE62F0431765C88863B0E7-- --------------F3F241EEAD5D9E876F17BE30 Content-Type: text/x-patch; charset=UTF-8; name="pg_ctl-16259.patch" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="pg_ctl-16259.patch" diff --git a/src/bin/pg_ctl/pg_ctl.c b/src/bin/pg_ctl/pg_ctl.c index bcb1ddb1351..29ac12173a8 100644 --- a/src/bin/pg_ctl/pg_ctl.c +++ b/src/bin/pg_ctl/pg_ctl.c @@ -529,15 +529,18 @@ start_postmaster(void) * previous postmaster will still have the file open for a short time * after removing postmaster.pid.) */ - FILE *fd = fopen(log_file, "a"); + int fd = open(log_file, O_RDWR, 0); - if (fd == NULL) + if (fd == -1) { - write_stderr(_("%s: could not create log file \"%s\": %s\n"), - progname, log_file, strerror(errno)); - exit(1); + if (errno != ENOENT) { + write_stderr(_("%s: could not open log file \"%s\": %s\n"), + progname, log_file, strerror(errno)); + exit(1); + } + } else { + close(fd); } - fclose(fd); snprintf(cmd, MAXPGPATH, "CMD /C \"\"%s\" %s%s < \"%s\" >> \"%s\" 2>&1\"", exec_path, pgdata_opt, post_opts, DEVNULL, log_file); --------------F3F241EEAD5D9E876F17BE30--