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 ...>

Search Discussions

  • Andrew Dunstan at Sep 22, 2005 at 3:10 am

    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
  • Tom Lane at Sep 22, 2005 at 3:30 am

    Andrew Dunstan 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
  • Andrew Dunstan at Sep 22, 2005 at 8:02 pm

    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
  • Bruce Momjian at Sep 22, 2005 at 10:36 pm

    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=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?

    --
    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, Pennsylvania 19073
  • Tom Lane at Sep 22, 2005 at 10:43 pm

    Bruce Momjian 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
  • Andrew Dunstan at Sep 22, 2005 at 10:56 pm

    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
  • Bruce Momjian at Sep 22, 2005 at 11:20 pm

    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, Pennsylvania 19073
  • Tom Lane at Sep 23, 2005 at 12:00 am

    Bruce Momjian 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
  • Bruce Momjian at Sep 23, 2005 at 5:37 pm

    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, Pennsylvania 19073
  • Andrew Dunstan at Sep 24, 2005 at 7:14 pm

    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
  • Bruce Momjian at Sep 24, 2005 at 11:07 pm

    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, although it is probably very
    useful. Some client programs, like <application>psql</>,
    attempt to connect twice while determining if a password is required,
    so duplicate <literal>connection received</> messasges are not a sign
    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, Pennsylvania 19073
  • Bruce Momjian at Sep 22, 2005 at 11:18 pm

    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, Pennsylvania 19073
  • Tom Lane at Sep 22, 2005 at 3:18 am

    Andrew Dunstan 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

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouppgsql-hackers @
categoriespostgresql
postedSep 22, '05 at 1:10a
activeSep 24, '05 at 11:07p
posts14
users3
websitepostgresql.org...
irc#postgresql

People

Translate

site design / logo © 2022 Grokbase