Обсуждение: 2 forks for md5?
I am puzzled about this. The strace output below is from CVS tip and
shows the postmaster and children during a single (local) connection
when the auth method is md5. What we see is 2 calls to clone() (that's
Linux for fork(), more or less). When the auth method is set to trust or
ident, there is only one clone(), which is what I expected.
Have I missed something, or is there a bug here? Do I need to get the
debugger out?
cheers
andrew (who hates debuggers)
4839 select(5, [3 4], NULL, NULL, {12, 827000}) = 0 (Timeout)
4839 rt_sigprocmask(SIG_SETMASK, ~[ILL TRAP ABRT BUS FPE SEGV CONT SYS RTMIN RT_1], NULL, 8) = 0
4839 time(NULL) = 1127347396
4839 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
4839 select(5, [3 4], NULL, NULL, {60, 0}) = 1 (in [4], left {54, 411000})
4839 rt_sigprocmask(SIG_SETMASK, ~[ILL TRAP ABRT BUS FPE SEGV CONT SYS RTMIN RT_1], NULL, 8) = 0
4839 accept(4, {sa_family=AF_FILE, path=@}, [2]) = 6
4839 getsockname(6, {sa_family=AF_FILE, path="/tmp/.s.PGSQL.5656"}, [21]) = 0
4839 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7efc708) = 6496
4839 close(6 <unfinished ...>
6496 close(3 <unfinished ...>
4839 <... close resumed> ) = 0
6496 <... close resumed> ) = 0
4839 time( <unfinished ...>
6496 close(4 <unfinished ...>
4839 <... time resumed> NULL) = 1127347402
6496 <... close resumed> ) = 0
4839 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...>
6496 gettimeofday( <unfinished ...>
4839 <... rt_sigprocmask resumed> NULL, 8) = 0
6496 <... gettimeofday resumed> {1127347402, 573584}, NULL) = 0
4839 select(5, [3 4], NULL, NULL, {60, 0} <unfinished ...>
6496 rt_sigaction(SIGTERM, {0x81b1de0, [], SA_RESTART}, {0x818ddc0, [], SA_RESTART}, 8) = 0
6496 rt_sigaction(SIGQUIT, {0x81b1de0, [], SA_RESTART}, {0x818ddc0, [], SA_RESTART}, 8) = 0
6496 rt_sigaction(SIGALRM, {0x81b1de0, [], 0}, {SIG_IGN}, 8) = 0
6496 rt_sigprocmask(SIG_SETMASK, ~[QUIT ILL TRAP ABRT BUS FPE SEGV ALRM TERM CONT SYS RTMIN RT_1], NULL, 8) = 0
6496 socket(PF_FILE, SOCK_DGRAM, 0) = 3
6496 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
6496 connect(3, {sa_family=AF_FILE, path="/dev/log"}, 16) = 0
6496 time([1127347402]) = 1127347402
6496 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6496 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6496 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6496 send(3, "<134>Sep 21 20:03:22 postgres[64"..., 115, MSG_NOSIGNAL) = 115
6496 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0
6496 recv(6, "\0\0\0(\0\3\0\0user\0andrew\0database\0tem"..., 8192, 0) = 40
6496 send(6, "R\0\0\0\f\0\0\0\5\371\\\0206", 13, 0) = 13
6496 recv(6, "", 8192, 0) = 0
6496 exit_group(0) = ?
4839 <... select resumed> ) = ? ERESTARTNOHAND (To be restarted)
4839 --- SIGCHLD (Child exited) @ 0 (0) ---
4839 rt_sigprocmask(SIG_SETMASK, ~[ILL TRAP ABRT BUS FPE SEGV CONT SYS RTMIN RT_1], NULL, 8) = 0
4839 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 6496
4839 send(5, "\2\0\0\0\20\0\0\0\0\0\0\0`\31\0\0", 16, 0) = 16
4839 waitpid(-1, 0xbfb06d2c, WNOHANG) = 0
4839 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
4839 sigreturn() = ? (mask now [])
4839 rt_sigprocmask(SIG_SETMASK, ~[ILL TRAP ABRT BUS FPE SEGV CONT SYS RTMIN RT_1], NULL, 8) = 0
4839 time(NULL) = 1127347402
4839 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
4839 select(5, [3 4], NULL, NULL, {60, 0}) = 1 (in [4], left {53, 697000})
4839 rt_sigprocmask(SIG_SETMASK, ~[ILL TRAP ABRT BUS FPE SEGV CONT SYS RTMIN RT_1], NULL, 8) = 0
4839 accept(4, {sa_family=AF_FILE, path=@}, [2]) = 6
4839 getsockname(6, {sa_family=AF_FILE, path="/tmp/.s.PGSQL.5656"}, [21]) = 0
4839 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7efc708) = 6498
4839 close(6 <unfinished ...>
6498 close(3 <unfinished ...>
4839 <... close resumed> ) = 0
6498 <... close resumed> ) = 0
4839 time( <unfinished ...>
6498 close(4 <unfinished ...>
4839 <... time resumed> NULL) = 1127347408
6498 <... close resumed> ) = 0
4839 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...>
6498 gettimeofday( <unfinished ...>
4839 <... rt_sigprocmask resumed> NULL, 8) = 0
6498 <... gettimeofday resumed> {1127347408, 879470}, NULL) = 0
4839 select(5, [3 4], NULL, NULL, {60, 0} <unfinished ...>
6498 rt_sigaction(SIGTERM, {0x81b1de0, [], SA_RESTART}, {0x818ddc0, [], SA_RESTART}, 8) = 0
6498 rt_sigaction(SIGQUIT, {0x81b1de0, [], SA_RESTART}, {0x818ddc0, [], SA_RESTART}, 8) = 0
6498 rt_sigaction(SIGALRM, {0x81b1de0, [], 0}, {SIG_IGN}, 8) = 0
6498 rt_sigprocmask(SIG_SETMASK, ~[QUIT ILL TRAP ABRT BUS FPE SEGV ALRM TERM CONT SYS RTMIN RT_1], NULL, 8) = 0
6498 socket(PF_FILE, SOCK_DGRAM, 0) = 3
6498 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
6498 connect(3, {sa_family=AF_FILE, path="/dev/log"}, 16) = 0
6498 time([1127347408]) = 1127347408
6498 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6498 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6498 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6498 send(3, "<134>Sep 21 20:03:28 postgres[64"..., 115, MSG_NOSIGNAL) = 115
6498 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0
6498 recv(6, "\0\0\0(\0\3\0\0user\0andrew\0database\0tem"..., 8192, 0) = 40
6498 send(6, "R\0\0\0\f\0\0\0\5YNNz", 13, 0) = 13
6498 recv(6, "p\0\0\0(md5bd5dda08808b6b81dcb7498c"..., 8192, 0) = 41
6498 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
6498 rt_sigprocmask(SIG_SETMASK, ~[ILL TRAP ABRT BUS FPE SEGV CONT SYS RTMIN RT_1], NULL, 8) = 0
6498 time([1127347408]) = 1127347408
6498 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6498 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6498 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6498 send(3, "<134>Sep 21 20:03:28 postgres[64"..., 126, MSG_NOSIGNAL) = 126
6498 rt_sigaction(SIGHUP, {0x81b1ed8, [], SA_RESTART}, {0x818a71c, [], SA_RESTART}, 8) = 0
6498 rt_sigaction(SIGINT, {0x81b1df0, [], SA_RESTART}, {0x818ddc0, [], SA_RESTART}, 8) = 0
6498 rt_sigaction(SIGTERM, {0x81b1d68, [], SA_RESTART}, {0x81b1de0, [], SA_RESTART}, 8) = 0
6498 rt_sigaction(SIGQUIT, {0x81b1ce0, [], SA_RESTART}, {0x81b1de0, [], SA_RESTART}, 8) = 0
6498 rt_sigaction(SIGALRM, {0x81ac1e4, [], 0}, {0x81b1de0, [], 0}, 8) = 0
6498 rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_IGN}, 8) = 0
6498 rt_sigaction(SIGUSR1, {0x81a60ec, [], SA_RESTART}, {0x818ad60, [], SA_RESTART}, 8) = 0
6498 rt_sigaction(SIGUSR2, {0x80fab8c, [], SA_RESTART}, {0x818ae80, [], SA_RESTART}, 8) = 0
6498 rt_sigaction(SIGFPE, {0x81b1e78, [], SA_RESTART}, {SIG_DFL}, 8) = 0
6498 rt_sigaction(SIGCHLD, {SIG_DFL}, {0x818d800, [], SA_RESTART|SA_NOCLDSTOP}, 8) = 0
6498 rt_sigprocmask(SIG_SETMASK, ~[QUIT ILL TRAP ABRT BUS FPE SEGV CONT SYS RTMIN RT_1], NULL, 8) = 0
6498 open("global/pg_database", O_RDONLY|O_LARGEFILE) = 4
6498 fstat64(4, {st_mode=S_IFREG|0600, st_size=88, ...}) = 0
6498 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f09000
6498 read(4, "\"postgres\" 10791 1663 499 499\n\"t"..., 4096) = 88
6498 close(4) = 0
6498 munmap(0xb7f09000, 4096) = 0
6498 access("base/1", F_OK) = 0
6498 open("base/1/PG_VERSION", O_RDONLY|O_LARGEFILE) = 4
6498 fstat64(4, {st_mode=S_IFREG|0600, st_size=4, ...}) = 0
6498 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f09000
6498 read(4, "8.1\n", 4096) = 4
6498 close(4) = 0
6498 munmap(0xb7f09000, 4096) = 0
6498 semctl(1966103, 3, IPC_64|SETVAL, 0xbfb06d98) = 0
6498 brk(0x9857000) = 0x9857000
6498 open("base/1/pg_internal.init", O_RDONLY|O_LARGEFILE) = 4
6498 fstat64(4, {st_mode=S_IFREG|0600, st_size=58212, ...}) = 0
6498 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f09000
6498 read(4, "b2W\0|\0\0\0\177\6\0\0\1\0\0\0(\n\0\0\0\0\0\0\377\377\377"..., 4096) = 4096
6498 read(4, "\20\0\0\0\377\377\377\377\1\0\4\0\0\0\0\0\n\0\0\0\377\377"..., 4096) = 4096
6498 read(4, "3\n\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0r\0"..., 4096) = 4096
6498 read(4, "\377\377\377\377\1pi\1\0\0\1\0\0\0\0\0h\0\0\0009\n\0\0"..., 4096) = 4096
6498 read(4, "\0\0\0\0h\0\0\0;\n\0\0stavalues2\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
6498 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5\0\n\0\3\t \377\0\0\0"..., 4096) = 4096
6498 read(4, "\32\0\0\0\1\0\0\0\0\0\0\0\305\7\0\0|\0\0\0btree\0\0\0\0"..., 4096) = 4096
6498 read(4, "N\1\0\0O\1\0\0P\1\0\0Q\1\0\0R\1\0\0L\1\0\0\314\3\0\0\364"..., 4096) = 4096
6498 read(4, "N\1\0\0O\1\0\0P\1\0\0Q\1\0\0R\1\0\0L\1\0\0\314\3\0\0\364"..., 4096) = 4096
6498 read(4, "\377\377\377\377\377\377\377\377\1pi\0\0\0\1\0\0\0\0\0"..., 4096) = 4096
6498 brk(0x987b000) = 0x987b000
6498 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
6498 read(4, "\0\0\0\0\32\0\0\0\377\377\377\377\4\0\3\0\0\0\0\0\377\377"..., 4096) = 4096
6498 read(4, "al\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
6498 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
6498 read(4, "\0\0\0\0h\0\0\0\356\4\0\0datallowconn\0\0\0\0\0\0\0\0"..., 4096) = 868
6498 read(4, "", 4096) = 0
6498 close(4) = 0
6498 munmap(0xb7f09000, 4096) = 0
6498 mmap2(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb72e1000
6498 gettimeofday({1127347408, 884651}, NULL) = 0
6498 send(5, "\1\0\0\0\234\0\0\0\1\0\0\0b\31\0\0\1\0\0\0\n\0\0\0\1\0"..., 156, 0) = 156
6498 rt_sigprocmask(SIG_BLOCK, NULL, ~[QUIT ILL TRAP ABRT BUS FPE KILL SEGV CONT STOP SYS RTMIN RT_1], 8) = 0
6498 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
6498 send(6, "R\0\0\0\10\0\0\0\0S\0\0\0\36client_encoding\0SQ"..., 284, 0) = 284
6498 recv(6, "X\0\0\0\4", 8192, 0) = 5
6498 gettimeofday({1127347417, 532222}, NULL) = 0
6498 time([1127347417]) = 1127347417
6498 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6498 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6498 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1267, ...}) = 0
6498 send(3, "<134>Sep 21 20:03:37 postgres[64"..., 162, MSG_NOSIGNAL) = 162
6498 exit_group(0) = ?
4839 <... select resumed> ) = ? ERESTARTNOHAND (To be restarted)
4839 --- SIGCHLD (Child exited) @ 0 (0) ---
4839 rt_sigprocmask(SIG_SETMASK, ~[ILL TRAP ABRT BUS FPE SEGV CONT SYS RTMIN RT_1], NULL, 8) = 0
4839 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG) = 6498
4839 send(5, "\2\0\0\0\20\0\0\0\0\0\0\0b\31\0\0", 16, 0) = 16
4839 waitpid(-1, 0xbfb06d2c, WNOHANG) = 0
4839 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
4839 sigreturn() = ? (mask now [])
4839 rt_sigprocmask(SIG_SETMASK, ~[ILL TRAP ABRT BUS FPE SEGV CONT SYS RTMIN RT_1], NULL, 8) = 0
4839 time(NULL) = 1127347417
4839 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
4839 select(5, [3 4], NULL, NULL, {60, 0} <unfinished ...>
Andrew Dunstan wrote: > > I am puzzled about this. The strace output below is from CVS tip and > shows the postmaster and children during a single (local) connection > when the auth method is md5. What we see is 2 calls to clone() (that's > Linux for fork(), more or less). When the auth method is set to trust > or ident, there is only one clone(), which is what I expected. > > Have I missed something, or is there a bug here? Do I need to get the > debugger out? > > Confusion fixed (thanks, Tom). psql (via libpq) tries twice, if not given a password to begin with (via .pgpass or psql's -W). Ugly but at least not incomprehensible. cheers andrew
Andrew Dunstan <andrew@dunslane.net> writes:
> I am puzzled about this. The strace output below is from CVS tip and
> shows the postmaster and children during a single (local) connection
> when the auth method is md5.
libpq is designed to abandon the connection and retry in certain
circumstances ... are you triggering one of those code paths?
regards, tom lane
Andrew Dunstan <andrew@dunslane.net> writes:
> Confusion fixed (thanks, Tom). psql (via libpq) tries twice, if not
> given a password to begin with (via .pgpass or psql's -W).
> Ugly but at least not incomprehensible.
This seems reasonable behavior when prompting for a password from the
user, since that's going to take a lot of time anyway. I'm not sure
whether libpq should try to excavate a password from ~/.pgpass in
advance of being told by the server that one is needed.
An ideal solution might be to read ~/.pgpass during the bit of code that
handles a password challenge from the server, rather than in the "outer
loop". Not having looked at the libpq code recently, I have no idea how
painful that would be to do.
Comments?
regards, tom lane
Tom Lane wrote: >Andrew Dunstan <andrew@dunslane.net> writes: > > >>Confusion fixed (thanks, Tom). psql (via libpq) tries twice, if not >>given a password to begin with (via .pgpass or psql's -W). >>Ugly but at least not incomprehensible. >> >> > >This seems reasonable behavior when prompting for a password from the >user, since that's going to take a lot of time anyway. I'm not sure >whether libpq should try to excavate a password from ~/.pgpass in >advance of being told by the server that one is needed. > >An ideal solution might be to read ~/.pgpass during the bit of code that >handles a password challenge from the server, rather than in the "outer >loop". Not having looked at the libpq code recently, I have no idea how >painful that would be to do. > > Actually, it looks to me like the cause is some code in psql/startup.c which keeps trying to make a connection while it gets PQnoPasswordSupplied. libpq seemed to work just fine, picking up pgpass before a connection was attempted. My only real concern is that when you turn on log_connections the traces are confusing - from the user's perspective there is only one connection, and there are two mentioned in the log, one of which doesn't have a correspondingly logged disconnect. Maybe worth a mention in the docs? cheers andrew
Andrew Dunstan wrote: > >This seems reasonable behavior when prompting for a password from the > >user, since that's going to take a lot of time anyway. I'm not sure > >whether libpq should try to excavate a password from ~/.pgpass in > >advance of being told by the server that one is needed. > > > >An ideal solution might be to read ~/.pgpass during the bit of code that > >handles a password challenge from the server, rather than in the "outer > >loop". Not having looked at the libpq code recently, I have no idea how > >painful that would be to do. > > > > > > Actually, it looks to me like the cause is some code in psql/startup.c > which keeps trying to make a connection while it gets > PQnoPasswordSupplied. libpq seemed to work just fine, picking up pgpass > before a connection was attempted. > > My only real concern is that when you turn on log_connections the traces > are confusing - from the user's perspective there is only one > connection, and there are two mentioned in the log, one of which doesn't > have a correspondingly logged disconnect. Maybe worth a mention in the docs? I turned on passwords and did see duplicate connections: LOG: connection received: host=[local]LOG: connection received: host=[local]LOG: connection authorized: user=postgresdatabase=testLOG: disconnection: session time: 0:00:00.61 user=postgres database=test host=[local] Basically psql first tries with no password, then when it fails asking for a password, it prompts for one and connects. You will notice only one "authorized:" message. I think that is the real "connection" line, rather than the "recevied" lines. Not sure how we can improve this. We could print an "authorization failed" message. Would that help, or just be overkill? -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001+ If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania19073
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> I turned on passwords and did see duplicate connections:
> LOG: connection received: host=[local]
> LOG: connection received: host=[local]
> LOG: connection authorized: user=postgres database=test
> LOG: disconnection: session time: 0:00:00.61 user=postgres database=test host=[local]
> Basically psql first tries with no password, then when it fails asking
> for a password, it prompts for one and connects. You will notice only
> one "authorized:" message. I think that is the real "connection" line,
> rather than the "recevied" lines. Not sure how we can improve this. We
> could print an "authorization failed" message. Would that help, or just
> be overkill?
I think that would get people more worried rather than less so ---
psql's customary behavior would make it look like you were being
regularly attacked by password guessers :-(. We do already log the
error message in the cases where a password is actually supplied
and is wrong, so an additional message doesn't seem very helpful.
One answer is to downgrade the "connection received" to a DEBUGn
message, so that it's only seen by those who presumably have something
of a clue. I don't really care for this, but you could certainly argue
that the other messages are sufficient for normal purposes.
regards, tom lane
Tom Lane said: > Bruce Momjian <pgman@candle.pha.pa.us> writes: >> I turned on passwords and did see duplicate connections: > >> LOG: connection received: host=[local] >> LOG: connection received: host=[local] >> LOG: connection authorized: user=postgres database=test >> LOG: disconnection: session time: 0:00:00.61 user=postgres >> database=test host=[local] > > > One answer is to downgrade the "connection received" to a DEBUGn > message, so that it's only seen by those who presumably have something > of a clue. I don't really care for this, but you could certainly argue > that the other messages are sufficient for normal purposes. Why not INFO? cheers andrew
Tom Lane wrote: > Bruce Momjian <pgman@candle.pha.pa.us> writes: > > I turned on passwords and did see duplicate connections: > > > LOG: connection received: host=[local] > > LOG: connection received: host=[local] > > LOG: connection authorized: user=postgres database=test > > LOG: disconnection: session time: 0:00:00.61 user=postgres database=test host=[local] > > > Basically psql first tries with no password, then when it fails asking > > for a password, it prompts for one and connects. You will notice only > > one "authorized:" message. I think that is the real "connection" line, > > rather than the "recevied" lines. Not sure how we can improve this. We > > could print an "authorization failed" message. Would that help, or just > > be overkill? > > I think that would get people more worried rather than less so --- > psql's customary behavior would make it look like you were being > regularly attacked by password guessers :-(. We do already log the > error message in the cases where a password is actually supplied > and is wrong, so an additional message doesn't seem very helpful. > > One answer is to downgrade the "connection received" to a DEBUGn > message, so that it's only seen by those who presumably have something > of a clue. I don't really care for this, but you could certainly argue > that the other messages are sufficient for normal purposes. I personally think the current behavior is fine. -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001+ If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania19073
Andrew Dunstan wrote: > Tom Lane said: > > Bruce Momjian <pgman@candle.pha.pa.us> writes: > >> I turned on passwords and did see duplicate connections: > > > >> LOG: connection received: host=[local] > >> LOG: connection received: host=[local] > >> LOG: connection authorized: user=postgres database=test > >> LOG: disconnection: session time: 0:00:00.61 user=postgres > >> database=test host=[local] > > > > > > > One answer is to downgrade the "connection received" to a DEBUGn > > message, so that it's only seen by those who presumably have something > > of a clue. I don't really care for this, but you could certainly argue > > that the other messages are sufficient for normal purposes. > > > Why not INFO? Yea, we could do that, but does it make sense to downgrade the connection message, especially since the "connection authorized" message doesn't contain the hostname. We would have to add the host name to the "connection authorized" message and at that point there is little need for the "connection received" message. -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001+ If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania19073
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> Yea, we could do that, but does it make sense to downgrade the
> connection message, especially since the "connection authorized" message
> doesn't contain the hostname. We would have to add the host name to the
> "connection authorized" message and at that point there is little need
> for the "connection received" message.
The connection-authorized message could be made to carry all the info
for the normal successful-connection case, but for connection failures
(not only bad password, but any other startup failure) it isn't going
to help. So on reflection I think we'd better keep the
connection-received message --- else we'd have to add the equivalent
info to all the failure-case messages.
I'm coming to agree with Andrew that a documentation patch might be the
best answer. But where to put it ... under the description of the
log_connections GUC var?
regards, tom lane
Tom Lane wrote: > Bruce Momjian <pgman@candle.pha.pa.us> writes: > > Yea, we could do that, but does it make sense to downgrade the > > connection message, especially since the "connection authorized" message > > doesn't contain the hostname. We would have to add the host name to the > > "connection authorized" message and at that point there is little need > > for the "connection received" message. > > The connection-authorized message could be made to carry all the info > for the normal successful-connection case, but for connection failures > (not only bad password, but any other startup failure) it isn't going > to help. So on reflection I think we'd better keep the > connection-received message --- else we'd have to add the equivalent > info to all the failure-case messages. > > I'm coming to agree with Andrew that a documentation patch might be the > best answer. But where to put it ... under the description of the > log_connections GUC var? I am thinking we should wait for someone else to notice the double log entries before mentioning it in the docs. -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 359-1001+ If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania19073
Bruce Momjian wrote: >Tom Lane wrote: > > >> >>I'm coming to agree with Andrew that a documentation patch might be the >>best answer. But where to put it ... under the description of the >>log_connections GUC var? >> >> > >I am thinking we should wait for someone else to notice the double log >entries before mentioning it in the docs. > > If I had a more Machiavellian bent I would make sure that happened ;-) How about this note under log_connections?: "Some clients (notably psql) sometimes try to connect without a password before trying with a password. This behaviour will generate two log lines if log_connections is turned on, even though to the user it appears that only one connection has occurred." cheers andrew
Andrew Dunstan wrote:
>
>
> Bruce Momjian wrote:
>
> >Tom Lane wrote:
> >
> >
> >>
> >>I'm coming to agree with Andrew that a documentation patch might be the
> >>best answer. But where to put it ... under the description of the
> >>log_connections GUC var?
> >>
> >>
> >
> >I am thinking we should wait for someone else to notice the double log
> >entries before mentioning it in the docs.
> >
> >
>
> If I had a more Machiavellian bent I would make sure that happened ;-)
>
> How about this note under log_connections?:
>
> "Some clients (notably psql) sometimes try to connect without a password
> before trying with a password. This behaviour will generate two log
> lines if log_connections is turned on, even though to the user it
> appears that only one connection has occurred."
OK, you wore me down. :-)
New text:
This outputs a line to the server log detailing each successful connection. This is off by default,
althoughit is probably very useful. Some client programs, like <application>psql</>, attempt to connect
twicewhile determining if a password is required, so duplicate <literal>connection received</> messasges are not
asign of problem. This option can only be set at server start or in the
<filename>postgresql.conf</filename>configuration file.
-- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610)
359-1001+ If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square,
Pennsylvania19073