Postgres background worker processes get stuck trying to write to stderr

[immerrr]

Hi!

I'm running a postgres-flex 16.4 instance and every once in a while it stops responding to some queries (but only some of them).

flyio/postgres-flex:16.4@sha256:f107dbfaa732063b31ee94aa728c4f5648a672259fd62bfaa245f9b7a53b5479

The queries are listed as active, and lock monitoring (as per postgres wiki) shows nobody is waiting on anything. There is no load on the server, and the queries are light (one i've got right now is SHOW EXTENSIONS). The queries cannot be cancelled by pg_cancel/-terminate_backend. The only way to get rid of them is to restart the server.

I've logged on to the container and was able to confirm that the background processes are indeed there and are indeed stuck doing nothing. pdb shows they are stuck trying to emit an error message:

# gdb -p 23173

# gdb -p 23173
<snip>
(gdb) backtrace
#0  0x00007f1af43b8574 in __GI___libc_write (fd=2, buf=0x55a80b88bfa0, nbytes=158) at ../sysdeps/unix/sysv/linux/write.c:26
#1  0x000055a7f4e76e65 in EmitErrorReport ()
#2  0x000055a7f4d0da0c in PostgresMain ()
#3  0x000055a7f4eea8ca in ?? ()
#4  0x000055a7f4c71c79 in PostmasterMain ()
#5  0x000055a7f493ede9 in main ()

strace shows that the process is trying to write a log message to stderr

# strace -p 23173

# strace -p 23173
strace: Process 23173 attached
write(2, "2025-01-31 16:13:37.315 UTC [231"..., 158

That worker's stderr is connected to a PTS

# ls -l /proc/23173/fd/{0,1,2}

# ls -l /proc/23173/fd/{0,1,2}
lrwx------ 1 postgres postgres 64 Jan 31 16:14 /proc/23173/fd/0 -> /dev/pts/0
lrwx------ 1 postgres postgres 64 Jan 31 16:14 /proc/23173/fd/1 -> /dev/pts/0
lrwx------ 1 postgres postgres 64 Jan 31 16:14 /proc/23173/fd/2 -> /dev/pts/0

I double checked that I cannot write to that pts from my terminal either, # echo 123 > /dev/pts/0 gets stuck, too. So my current hypothesis as to why the process is stuck is that /dev/pts/0's internal buffer is full and the process that is supposed to read from it on the other side doesn't do its job for some reason.

pstree shows that postgres is started by start command, and some further digging in this repo got me to the place where I think the pipe is created for postgres:

https://github.com/fly-apps/postgres-flex/blob/master/internal/supervisor/output.go#L54

But i'm not sure on where to look for what else is happening to the other side of the pipe, as Go is not my native tongue. Please, advise.

Thanks!

[immerrr]

I ran dlv and I think it confirmed my hypothesis. There are 6 coroutines that are running p.cmd.Run (and I confirmed that gr 39 is executing gosu postgres ...):

/go/pkg/mod/golang.org/x/sync@v0.1.0/errgroup/errgroup.go:72 in golang.org/x/sync/errgroup.(*Group).Go.func1
          Goroutine 39 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 648)
          Goroutine 40 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 670) [select 14358646945]
          Goroutine 41 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 675) [select 14358646945]
          Goroutine 42 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 654) [timer goroutine (idle) 1222138421]
          Goroutine 43 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 684) [timer goroutine (idle) 1222138421]
        Total: 6

But for some reason, only 5 coroutines running PipeOutput:

/go/src/github.com/fly-apps/fly-postgres/internal/supervisor/output.go:56 in github.com/fly-apps/postgres-flex/internal/supervisor.(*multiOutput).PipeOutput.func2
          Goroutine 125 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 669)
          Goroutine 26 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 687)
          Goroutine 29 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 671)
          Goroutine 30 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 672)
          Goroutine 126 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 677) [timer goroutine (idle) 347447510891741]
        Total: 5

And here again, I went through all of them to check the processes that they are running:

(dlv) grs -w startloc Go.func1 -exec up 8 p p.name
  Goroutine 39 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 648)
"postgres"
  Goroutine 40 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 670) [select 14358646945]
"proxy"
  Goroutine 41 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 675) [select 14358646945]
"repmgrd"
  Goroutine 42 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 654) [timer goroutine (idle) 1222138421]
"monitor"
  Goroutine 43 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 684) [timer goroutine (idle) 1222138421]
"admin"
  Goroutine 44 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 679) [timer goroutine (idle) 1222138421]
"exporter"
[6 goroutines]

(dlv) grs -w startloc PipeOutput.func2 -exec up 10 p proc.name
* Goroutine 26 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 687)
"monitor"
  Goroutine 29 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 671)
"exporter"
  Goroutine 30 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 672)
"admin"
  Goroutine 125 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 669)
"proxy"
  Goroutine 126 - User: .usr/local/go/src/runtime/internal/syscall/syscall_linux.go:38 syscall.RawSyscall6 (0x403df3) (thread 677) [timer goroutine (idle) 347447510891741]
"repmgrd"
[5 goroutines]

[davissp14]

Interesting, are you able to reproduce this on the latest release?

[immerrr]

I have updated to the latest version, and will keep an eye on it.

docker-hub-mirror.fly.io/flyio/postgres-flex:16.6@sha256:16a034c9e62320ee66488776b705f1e026d63439b89551d8adac0d9f8682c2a6

The thing is, I wasn't able to trigger it deliberately. It happened on its own a few times over the last couple of weeks.

[immerrr]

@davissp14 i was just able to reproduce the problem with the latest release.

tl;dr. python -c "print('SELECT ' + ','.join(['unknown()'] * 10000))" | psql $DATABASE_URL will block the log file handle for postgres and all its subprocesses

The problem is in the process output processing code which uses bufio.Scanner

		scanner := bufio.NewScanner(pipe.pty)

		for scanner.Scan() {
			m.WriteLine(proc, scanner.Bytes())
		}

scanner.Scan function is known to return false

when there are no more tokens, either by reaching the end of the input or an error

So one thing to improve here would be to check scanner.Err method before exiting to see if there is something that should be reported to the user. It would help reduce the investigation time in this case, but may not be needed in the end (see below).

So it got me thinking, what would be an example of an error, where the scanner would break, but the pipe would remain open. As I said previously, I'm not a golang dev, so went back to the docs and lo and behold:

Scanning stops unrecoverably at EOF, the first I/O error, or a token too large to fit in the Scanner.Buffer

The Scanner.Buffer link lead me to MaxScanTokenSize which says that the default buffer size is 64k. I just needed to get Postgres to print a line that is longer than that. It is easy as Postgres is by default configured to log any query errors, so...

echo 'SELECT unknown()' | psql $DATABASE_URL

produces the following error log

2025-02-03 14:47:10.215
postgres | 2025-02-03 13:47:10.213 UTC [24869] HINT:  No function matches the given name and argument types. You might need to add explicit type casts.
2025-02-03 14:47:10.215	
postgres | 2025-02-03 13:47:10.213 UTC [24869] ERROR:  function unknown() does not exist at character 8

And

python -c "print('SELECT ' + ','.join(['unknown()'] * 10000))" | psql $DATABASE_URL

breaks the Scanner and as soon as the pipe's internal buffer gets full any postgres subprocess that tries to log something will be locked indefinitely.

Like I said above, checking scanner.Err() would probably return something like bufio.Scanner: token too long and would hint at the simpler solution, which is to specify a bigger buffer for the scanner and tweak the code to create new scanners to continue reading from pipe.pty until EOF. It would still lose the longer log lines, but at least it wouldn't block the output of the child process.

To solve the issue completely, the documentation for bufio.Scanner goes on to recommend the following:

Programs that need more control over error handling or large tokens, or must run sequential scans on a reader, should use bufio.Reader instead.

If I had to guess, they probably mean to use reader.ReadLine method and checking its isPrefix return value.

[davissp14]

This should address the issue. Mind giving it a try?

#273

[immerrr]

Looks solid, left some early feedback in the PR...

Brb, going to figure out how to deploy custom postgres images...

[immerrr]

I tested an image with the following changes and can confirm it fixes the broken log piping issue:

modified   internal/supervisor/output.go
@@ -7,6 +7,7 @@ import (
 	"log"
 	"os"
 	"sync"
+	"io"
 
 	"github.com/pkg/term/termios"
 )
@@ -54,10 +55,19 @@ func (m *multiOutput) PipeOutput(proc *process) {
 	pipe := m.openPipe(proc)
 
 	go func(proc *process, pipe *ptyPipe) {
-		scanner := bufio.NewScanner(pipe.pty)
-
-		for scanner.Scan() {
-			m.WriteLine(proc, scanner.Bytes())
+		reader := bufio.NewReader(pipe.pty);
+
+		for {
+			v, err := reader.ReadBytes('\n')
+			if len(v) > 0 {
+				m.WriteLine(proc, v)
+			}
+			if err != nil {
+				if err != io.EOF {
+					log.Printf("failed to read process %s output: %s", proc.name, err)
+				}
+				break
+			}
 		}
 	}(proc, pipe)
 }
@@ -84,7 +94,9 @@ func (m *multiOutput) WriteLine(proc *process, p []byte) {
 	buf.WriteString("\033[0m | ")
 
 	buf.Write(p)
-	buf.WriteByte('\n')
+	if p[len(p)-1] != '\n' {
+		buf.WriteByte('\n')
+	}
 
 	m.mutex.Lock()
 	defer m.mutex.Unlock()

[immerrr]

I used 1MB for reader buffer, but that shouldn't be necessary (I was going to use reader.ReadLine method, but borrowed reader.ReadBytes from your PR) Removed the extra changes from the diff, they should be closer to your PR now.

[davissp14]

Awesome! I really appreciate you digging into this!

[davissp14]

Cutting a release for this today. Will be addressed in v0.0.65.