Обсуждение: write_pipe_chunks patch messes up early error message output

[ ok, let's try this again --- apparently there's something in my mail
software that dislikes embedded nulls ]

I was experimenting with what happened if I made the pg_log directory
unwritable, and found out that this comes out on stderr:

<NUL><NUL><NUL>_<NUL><NUL>J3tFATAL:  could not create log file "pg_log/postgresql-2007-07-15_210716.log": Permission
denied

The problem is that elog.c thinks that the GUC variable Redirect_stderr
tells it whether to use the pipe chunk protocol on stderr, but in fact
that should *not* happen until we have successfully launched the syslogger
and repointed stderr to the pipe.

I suspect that error messages coming out of the syslogger itself (and
directed to the original stderr destination) will be similarly broken.

So that patch still needs work.  I think we probably need a flag
variable separate from the GUC variable to tell when to send using
the chunk protocol.
        regards, tom lane

Tom Lane wrote:
> I suspect that error messages coming out of the syslogger itself (and
> directed to the original stderr destination) will be similarly broken.
>   

I thought we had that case handled, but I could be wrong.
> So that patch still needs work. 

Yes, darnit.

>  I think we probably need a flag
> variable separate from the GUC variable to tell when to send using
> the chunk protocol.
>
>   

Sounds reasonable. I will try to get to it this week.

cheers

andrew

Tom Lane wrote:
>  I think we probably need a flag
> variable separate from the GUC variable to tell when to send using
> the chunk protocol.
>
>     
>   

Is there any reason we can't just use a check on whether SysLoggerPID is 
not 0? It should only be set if the syslogger has in fact started.

cheers

andrew

Andrew Dunstan <andrew@dunslane.net> writes:
> Is there any reason we can't just use a check on whether SysLoggerPID is 
> not 0?

(a) that really shouldn't be exported out of postmaster.c, and (b) it is
not readily available to child backends is it?
        regards, tom lane

Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
>   
>> Is there any reason we can't just use a check on whether SysLoggerPID is 
>> not 0?
>>     
>
> (a) that really shouldn't be exported out of postmaster.c, and (b) it is
> not readily available to child backends is it?
>
>     
>   

It's already used in elog.c in Win32 code:
       if ((!Redirect_stderr || am_syslogger ||            (!IsUnderPostmaster && SysLoggerPID==0)) && 
pgwin32_is_service())           write_eventlog(edata->elevel, buf.data);

Child backends might have an out of date version if we restart the 
Syslogger, but would that matter in this case? For current purposes all 
we need is to know that the syslogger has in fact started, ISTM.

If that makes you puke we can do something more elegant, but I suspect 
it will amount to the same thing.

cheers

andrew

Andrew Dunstan <andrew@dunslane.net> writes:
> Tom Lane wrote:
>> (a) that really shouldn't be exported out of postmaster.c, and (b) it is
>> not readily available to child backends is it?

> It's already used in elog.c in Win32 code:

>         if ((!Redirect_stderr || am_syslogger ||
>              (!IsUnderPostmaster && SysLoggerPID==0)) && 
> pgwin32_is_service())
>             write_eventlog(edata->elevel, buf.data);

> Child backends might have an out of date version if we restart the 
> Syslogger, but would that matter in this case?

This code is already too ugly to live :-(.

But aside from esthetics, there is a functional reason to have a
separate flag variable.  Consider the transient state where the
syslogger has failed and we are trying to start a new one.  If the
postmaster wishes to elog anything (like, say, the log entry about
the syslogger having failed) in this interval, then it *should*
use the chunk protocol, because we expect that the data will
eventually be eaten by the new syslogger.

I think offhand that the correct semantics of the flag are "we have
redirected our original stderr into a pipe for syslogger", and in
fact that we should transition the output format exactly at the
instant where we do that; the starting of the child process happens
at a slightly different time, and restarting of the child (if needed)
is yet a different issue.

Another thing that tracking such a flag would help us clean up is
the syslogger's own elogging behavior.  IIRC the "original" syslogger
is launched with its stderr pointing to the original stderr, and so
it's useful for any messages generated by syslogger itself to be copied
onto that stderr.  After a relaunch, though, this is no longer possible
and it'd probably be best if syslogger doesn't even try writing to its
stderr.
        regards, tom lane

> > Is there any reason we can't just use a check on whether
> SysLoggerPID
> > is not 0?
>
> (a) that really shouldn't be exported out of postmaster.c,
> and (b) it is not readily available to child backends is it?

Should there be child backends when the logger did not start ?
I'd think startup would be aborted if that happed ?

Andreas

Tom Lane wrote:
>
> I think offhand that the correct semantics of the flag are "we have
> redirected our original stderr into a pipe for syslogger", and in
> fact that we should transition the output format exactly at the
> instant where we do that; the starting of the child process happens
> at a slightly different time, and restarting of the child (if needed)
> is yet a different issue.
>
>
>   

We could expose syslogger's redirection_done flag, which I think has the 
semantics you want. AFAICS it is never unset once set. (I should note 
that the distance between the point where this is set and where 
SysLoggerPID is set on return from SysLogger_Start is negligible, and no 
logging statements are called there, but I take your point about 
continuing to use chunking during a syslogger restart when SysLoggerPID 
might be 0.)

cheers

andrew

Andrew Dunstan <andrew@dunslane.net> writes:
> Tom Lane wrote:
>> I think offhand that the correct semantics of the flag are "we have
>> redirected our original stderr into a pipe for syslogger",

> We could expose syslogger's redirection_done flag, which I think has the 
> semantics you want.

Yeah, that would work.  You'd have to get rid of the current ad-hoc
method by which it is propagated to the syslogger child process
(EXEC_BACKEND case), because now it will have to be propagated to all
children; so postmaster.c should handle it in BackendParameters.
        regards, tom lane

Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
>   
>> Tom Lane wrote:
>>     
>>> I think offhand that the correct semantics of the flag are "we have
>>> redirected our original stderr into a pipe for syslogger",
>>>       
>
>   
>> We could expose syslogger's redirection_done flag, which I think has the 
>> semantics you want.
>>     
>
> Yeah, that would work.  You'd have to get rid of the current ad-hoc
> method by which it is propagated to the syslogger child process
> (EXEC_BACKEND case), because now it will have to be propagated to all
> children; so postmaster.c should handle it in BackendParameters.
>
>     
>   


The problem with this as it stands is that the syslogger itself is 
forked before the redirection is done. I guess we need to make sure the 
syslogger itself never calls write_pipe_chunks() - which makes sense 
anyway - should probably call write_syslogger_file() directly, I think.

cheers

andrew

Andrew Dunstan <andrew@dunslane.net> writes:
> Tom Lane wrote:
>> Yeah, that would work.  You'd have to get rid of the current ad-hoc
>> method by which it is propagated to the syslogger child process
>> (EXEC_BACKEND case), because now it will have to be propagated to all
>> children; so postmaster.c should handle it in BackendParameters.

> The problem with this as it stands is that the syslogger itself is 
> forked before the redirection is done.

Which is entirely correct.  Re-read what I said about first launch vs
relaunch of the syslogger.  Its stderr will be connected differently in
the two cases, and should be handled differently --- we want the first
launch to try to report problems on its own stderr, but there's no point
after a relaunch.  That's why we pass down redirection_done to it.
        regards, tom lane

Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
>   
>> Tom Lane wrote:
>>     
>>> Yeah, that would work.  You'd have to get rid of the current ad-hoc
>>> method by which it is propagated to the syslogger child process
>>> (EXEC_BACKEND case), because now it will have to be propagated to all
>>> children; so postmaster.c should handle it in BackendParameters.
>>>       
>
>   
>> The problem with this as it stands is that the syslogger itself is 
>> forked before the redirection is done.
>>     
>
> Which is entirely correct.  Re-read what I said about first launch vs
> relaunch of the syslogger.  Its stderr will be connected differently in
> the two cases, and should be handled differently --- we want the first
> launch to try to report problems on its own stderr, but there's no point
> after a relaunch.  That's why we pass down redirection_done to it.
>
>
>   

What I was trying to nut out was how to handle logging from the first 
launched syslogger after redirection is done.

Or, looking at it another way, why would we ever want the syslogger to 
use the chunking protocol at all?

cheers

andrew

Andrew Dunstan <andrew@dunslane.net> writes:
> Or, looking at it another way, why would we ever want the syslogger to 
> use the chunking protocol at all?

Ah, I misunderstood you.  Yeah, I think you are right: if we are
special-casing the syslogger process anyway, then it need only have
these two behaviors:

not redirection_done: write to own stderr (not chunked) and directly to
file

redirection_done: write directly to file

One thing to watch out for is infinite recursion if the write-to-file
gets an error.  I don't remember if we have a defense against that
in there now, but we probably should.
        regards, tom lane

Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
>
>> Or, looking at it another way, why would we ever want the syslogger to
>> use the chunking protocol at all?
>>
>
> Ah, I misunderstood you.  Yeah, I think you are right: if we are
> special-casing the syslogger process anyway, then it need only have
> these two behaviors:
>
> not redirection_done: write to own stderr (not chunked) and directly to
> file
>
> redirection_done: write directly to file
>
> One thing to watch out for is infinite recursion if the write-to-file
> gets an error.  I don't remember if we have a defense against that
> in there now, but we probably should.
>
>
>

I think we do. write_syslogger_file says:

    /* can't use ereport here because of possible recursion */

Anyway, I think the attached patch will do what we need.

cheers

andrew
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/postmaster.c,v
retrieving revision 1.532
diff -c -r1.532 postmaster.c
*** src/backend/postmaster/postmaster.c    11 Jul 2007 08:27:33 -0000    1.532
--- src/backend/postmaster/postmaster.c    19 Jul 2007 15:53:39 -0000
***************
*** 203,210 ****
              BgWriterPID = 0,
              AutoVacPID = 0,
              PgArchPID = 0,
!             PgStatPID = 0;
! pid_t            SysLoggerPID = 0; /* Needs to be accessed from elog.c */

  /* Startup/shutdown state */
  #define            NoShutdown        0
--- 203,210 ----
              BgWriterPID = 0,
              AutoVacPID = 0,
              PgArchPID = 0,
!             PgStatPID = 0,
!             SysLoggerPID = 0;

  /* Startup/shutdown state */
  #define            NoShutdown        0
***************
*** 218,223 ****
--- 218,225 ----
  bool        ClientAuthInProgress = false;        /* T during new-client
                                                   * authentication */

+ bool redirection_done = false;
+
  /* received START_AUTOVAC_LAUNCHER signal */
  static bool start_autovac_launcher = false;

***************
*** 332,337 ****
--- 334,340 ----
      InheritableSocket pgStatSock;
      pid_t        PostmasterPid;
      TimestampTz PgStartTime;
+     bool        redirection_done;
  #ifdef WIN32
      HANDLE        PostmasterHandle;
      HANDLE        initial_signal_pipe;
***************
*** 3953,3958 ****
--- 3956,3963 ----
      param->PostmasterPid = PostmasterPid;
      param->PgStartTime = PgStartTime;

+     param->redirection_done = redirection_done;
+
  #ifdef WIN32
      param->PostmasterHandle = PostmasterHandle;
      write_duplicated_handle(¶m->initial_signal_pipe,
***************
*** 4156,4161 ****
--- 4161,4168 ----
      PostmasterPid = param->PostmasterPid;
      PgStartTime = param->PgStartTime;

+     redirection_done = param->redirection_done;
+
  #ifdef WIN32
      PostmasterHandle = param->PostmasterHandle;
      pgwin32_initial_signal_pipe = param->initial_signal_pipe;
Index: src/backend/postmaster/syslogger.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/syslogger.c,v
retrieving revision 1.32
diff -c -r1.32 syslogger.c
*** src/backend/postmaster/syslogger.c    14 Jun 2007 01:48:51 -0000    1.32
--- src/backend/postmaster/syslogger.c    19 Jul 2007 15:53:39 -0000
***************
*** 79,89 ****
   */
  bool        am_syslogger = false;

  /*
   * Private state
   */
  static pg_time_t next_rotation_time;
- static bool redirection_done = false;
  static bool pipe_eof_seen = false;
  static FILE *syslogFile = NULL;
  static char *last_file_name = NULL;
--- 79,90 ----
   */
  bool        am_syslogger = false;

+ extern bool redirection_done;
+
  /*
   * Private state
   */
  static pg_time_t next_rotation_time;
  static bool pipe_eof_seen = false;
  static FILE *syslogFile = NULL;
  static char *last_file_name = NULL;
***************
*** 582,595 ****
          snprintf(numbuf[bufc++], 32, "%d", fileno(syslogFile));
      else
          strcpy(numbuf[bufc++], "-1");
-     snprintf(numbuf[bufc++], 32, "%d", (int) redirection_done);
  #else                            /* WIN32 */
      if (syslogFile != NULL)
          snprintf(numbuf[bufc++], 32, "%ld",
                   _get_osfhandle(_fileno(syslogFile)));
      else
          strcpy(numbuf[bufc++], "0");
-     snprintf(numbuf[bufc++], 32, "%d", (int) redirection_done);
  #endif   /* WIN32 */

      /* Add to the arg list */
--- 583,594 ----
***************
*** 623,629 ****
          syslogFile = fdopen(fd, "a");
          setvbuf(syslogFile, NULL, LBF_MODE, 0);
      }
-     redirection_done = (bool) atoi(*argv++);
  #else                            /* WIN32 */
      fd = atoi(*argv++);
      if (fd != 0)
--- 622,627 ----
***************
*** 635,641 ****
              setvbuf(syslogFile, NULL, LBF_MODE, 0);
          }
      }
-     redirection_done = (bool) atoi(*argv++);
  #endif   /* WIN32 */
  }
  #endif   /* EXEC_BACKEND */
--- 633,638 ----
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/error/elog.c,v
retrieving revision 1.187
diff -c -r1.187 elog.c
*** src/backend/utils/error/elog.c    14 Jun 2007 01:48:51 -0000    1.187
--- src/backend/utils/error/elog.c    19 Jul 2007 15:53:41 -0000
***************
*** 76,82 ****

  sigjmp_buf *PG_exception_stack = NULL;

! extern pid_t SysLoggerPID;

  /* GUC parameters */
  PGErrorVerbosity Log_error_verbosity = PGERROR_VERBOSE;
--- 76,82 ----

  sigjmp_buf *PG_exception_stack = NULL;

! extern bool redirection_done;

  /* GUC parameters */
  PGErrorVerbosity Log_error_verbosity = PGERROR_VERBOSE;
***************
*** 1780,1790 ****
           * that's really a pipe to the syslogger process. Unless we're in the
           * postmaster, and the syslogger process isn't started yet.
           */
!         if ((!Redirect_stderr || am_syslogger || (!IsUnderPostmaster && SysLoggerPID==0)) && pgwin32_is_service())
              write_eventlog(edata->elevel, buf.data);
          else
  #endif
!             if (Redirect_stderr)
                  write_pipe_chunks(fileno(stderr), buf.data, buf.len);
              else
                  write(fileno(stderr), buf.data, buf.len);
--- 1780,1795 ----
           * that's really a pipe to the syslogger process. Unless we're in the
           * postmaster, and the syslogger process isn't started yet.
           */
!         if (pgwin32_is_service &&
!             (!Redirect_stderr || !redirection_done || am_syslogger))
              write_eventlog(edata->elevel, buf.data);
          else
  #endif
!             /* only use the chunking protocol if we know the syslogger should
!              * be catching stderr output, and we are not ourselves the
!              * syslogger. Otherwise, go directly to stderr.
!              */
!             if (Redirect_stderr && redirection_done && !am_syslogger)
                  write_pipe_chunks(fileno(stderr), buf.data, buf.len);
              else
                  write(fileno(stderr), buf.data, buf.len);

Andrew Dunstan <andrew@dunslane.net> writes:
> Anyway, I think the attached patch will do what we need.

I think you could leave Redirect_stderr out of the elog.c tests
entirely, since redirection_done can never become set without it.

Also, you introduced a bug: pgwin32_is_service is a function no?
Needs invocation parens.

Otherwise looks reasonable.
        regards, tom lane

Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
>   
>> Anyway, I think the attached patch will do what we need.
>>     
>
> I think you could leave Redirect_stderr out of the elog.c tests
> entirely, since redirection_done can never become set without it.
>
> Also, you introduced a bug: pgwin32_is_service is a function no?
> Needs invocation parens.
>
> Otherwise looks reasonable.
>
>             
>   

Thanks. Applied with those fixes, back as far as 8.0.

cheers

andrew