Re: [HACKERS] 2 forks for md5?
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 ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [HACKERS] 2 forks for md5?
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 applicationpsql/, attempt to connect twice while determining if a password is required, so duplicate literalconnection received/ messasges are not a sign of problem. This option can only be set at server start or in the filenamepostgresql.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 ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [HACKERS] 2 forks for md5?
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 ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [HACKERS] 2 forks for md5?
Tom Lane wrote: Andrew Dunstan [EMAIL PROTECTED] 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 ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [HACKERS] 2 forks for md5?
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 ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [HACKERS] 2 forks for md5?
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 ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [HACKERS] 2 forks for md5?
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 ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [HACKERS] 2 forks for md5?
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 ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [HACKERS] 2 forks for md5?
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 ---(end of broadcast)--- TIP 9: In versions below 8.0, the planner will ignore your desire to choose an index scan if your joining column's datatypes do not match
Re: [HACKERS] 2 forks for md5?
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 ---(end of broadcast)--- TIP 6: explain analyze is your friend
[HACKERS] 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, [EMAIL PROTECTED], [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, 134Sep 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, [EMAIL PROTECTED], [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
Re: [HACKERS] 2 forks for md5?
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 ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [HACKERS] 2 forks for md5?
Andrew Dunstan [EMAIL PROTECTED] 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 ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [HACKERS] 2 forks for md5?
Andrew Dunstan [EMAIL PROTECTED] 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 ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
