openssh unix dev - Jun 2001 - [Lutz.Jaenicke@aet.TU-Cottbus.DE: 2.9p1: HP-UX 10.20 utmp/wtmp handling broken?]

Hi!

I am resending the following message about problems with utmp handling.
* In the meantime I had some request in private mail from people asking
  whether I have new information.
* The problem is still persistant in 2.9p2.
* My own new investigations show, that the problem only appears with
  protocol 2, not with protocol 1, I therefore only started to note it
  when protocol 2 became the default as of OpenSSH 2.9.
- To reproduce: build a connection with protocol 1/2 and then kill the client
  with -TERM. For protocol 1, the entry in utmp on the server will be
  removed, for protocol 2 it will not be removed.
>From sshd -d I see, that session_pty_cleanup() is not being called.
As far as I understood the code in session.c:session_pty_req()
        /*
         * Add a cleanup function to clear the utmp entry and record logout
         * time in case we call fatal() (e.g., the connection gets closed).
         */
        fatal_add_cleanup(session_pty_cleanup, (void *)s);
should make sure, that the utmp entry is cleared, but it obviously
doesn't work as I expected from that statement.

Best regards,
	Lutz

----- Forwarded message from Lutz Jaenicke <Lutz.Jaenicke at
aet.TU-Cottbus.DE> -----

Delivered-To: openssh-unix-dev-list-93873 at shitei.mindrot.org
Date: Thu, 10 May 2001 10:11:38 +0200
From: Lutz Jaenicke <Lutz.Jaenicke at aet.TU-Cottbus.DE>
To: openssh-unix-dev at mindrot.org
Subject: 2.9p1: HP-UX 10.20 utmp/wtmp handling broken?
Mail-Followup-To: openssh-unix-dev at mindrot.org
User-Agent: Mutt/1.2.5i
Organization: BTU Cottbus, Allgemeine Elektrotechnik
Precedence: bulk

Hi!

I have updated to OpenSSH 2.9p1 on HP-UX 10.20.
Since this update, I seem to have problems with utmp/wtmp handling,
in that entries are not removed as expected.
ws01 36: w
 10:06am  up 76 days, 12:52,  12 users,  load average: 0.17, 0.25, 0.20
User     tty           login@  idle   JCPU   PCPU  what
...
root     pts/8         5:28pm159:41                -
...
ws01 37: ps -ef | grep pts/8
(nothing)
ws01 39: lsof /dev/pts/8
(nothing)
>From my observations this seems to happen, when slogin is not finished with
"exit", but the ssh-client is killed (e.g. because it was in a
terminal window
and I log off the window manager).

Can anybody verify this behaviour? (Fixes?) I don't remember having seen
this with 2.5.2p2...

Best regards,
	Lutz
-- 
Lutz Jaenicke                             Lutz.Jaenicke at aet.TU-Cottbus.DE
BTU Cottbus               http://www.aet.TU-Cottbus.DE/personen/jaenicke/
Lehrstuhl Allgemeine Elektrotechnik                  Tel. +49 355 69-4129
Universitaetsplatz 3-4, D-03044 Cottbus              Fax. +49 355 69-4153

----- End forwarded message -----

-- 
Lutz Jaenicke                             Lutz.Jaenicke at aet.TU-Cottbus.DE
BTU Cottbus               http://www.aet.TU-Cottbus.DE/personen/jaenicke/
Lehrstuhl Allgemeine Elektrotechnik                  Tel. +49 355 69-4129
Universitaetsplatz 3-4, D-03044 Cottbus              Fax. +49 355 69-4153

At this point I can only verify that it's true for OpenBSD, but it is not
true for Linux.  I have a sneeking feeling that if I were to try it under
Solaris it would mimic Linux (I'll try it when I get to work).  My only
reason for this belief is I think PAM may actually handle utmp/wtmp clean
ups if the application does not.

- Ben

On Wed, 20 Jun 2001, Lutz Jaenicke wrote:
> Hi!
>
> I am resending the following message about problems with utmp handling.
> * In the meantime I had some request in private mail from people asking
>   whether I have new information.
> * The problem is still persistant in 2.9p2.
> * My own new investigations show, that the problem only appears with
>   protocol 2, not with protocol 1, I therefore only started to note it
>   when protocol 2 became the default as of OpenSSH 2.9.
> - To reproduce: build a connection with protocol 1/2 and then kill the
client
>   with -TERM. For protocol 1, the entry in utmp on the server will be
>   removed, for protocol 2 it will not be removed.
>
> >From sshd -d I see, that session_pty_cleanup() is not being called.
> As far as I understood the code in session.c:session_pty_req()
>         /*
>          * Add a cleanup function to clear the utmp entry and record logout
>          * time in case we call fatal() (e.g., the connection gets closed).
>          */
>         fatal_add_cleanup(session_pty_cleanup, (void *)s);
> should make sure, that the utmp entry is cleared, but it obviously
> doesn't work as I expected from that statement.
>
> Best regards,
> 	Lutz
>
> ----- Forwarded message from Lutz Jaenicke <Lutz.Jaenicke at
aet.TU-Cottbus.DE> -----
>
> Delivered-To: openssh-unix-dev-list-93873 at shitei.mindrot.org
> Date: Thu, 10 May 2001 10:11:38 +0200
> From: Lutz Jaenicke <Lutz.Jaenicke at aet.TU-Cottbus.DE>
> To: openssh-unix-dev at mindrot.org
> Subject: 2.9p1: HP-UX 10.20 utmp/wtmp handling broken?
> Mail-Followup-To: openssh-unix-dev at mindrot.org
> User-Agent: Mutt/1.2.5i
> Organization: BTU Cottbus, Allgemeine Elektrotechnik
> Precedence: bulk
>
> Hi!
>
> I have updated to OpenSSH 2.9p1 on HP-UX 10.20.
> Since this update, I seem to have problems with utmp/wtmp handling,
> in that entries are not removed as expected.
> ws01 36: w
>  10:06am  up 76 days, 12:52,  12 users,  load average: 0.17, 0.25, 0.20
> User     tty           login@  idle   JCPU   PCPU  what
> ...
> root     pts/8         5:28pm159:41                -
> ...
> ws01 37: ps -ef | grep pts/8
> (nothing)
> ws01 39: lsof /dev/pts/8
> (nothing)
>
> >From my observations this seems to happen, when slogin is not finished
with
> "exit", but the ssh-client is killed (e.g. because it was in a
terminal window
> and I log off the window manager).
>
> Can anybody verify this behaviour? (Fixes?) I don't remember having
seen
> this with 2.5.2p2...
>
> Best regards,
> 	Lutz
> --
> Lutz Jaenicke                             Lutz.Jaenicke at
aet.TU-Cottbus.DE
> BTU Cottbus               http://www.aet.TU-Cottbus.DE/personen/jaenicke/
> Lehrstuhl Allgemeine Elektrotechnik                  Tel. +49 355 69-4129
> Universitaetsplatz 3-4, D-03044 Cottbus              Fax. +49 355 69-4153
>
> ----- End forwarded message -----
>
> --
> Lutz Jaenicke                             Lutz.Jaenicke at
aet.TU-Cottbus.DE
> BTU Cottbus               http://www.aet.TU-Cottbus.DE/personen/jaenicke/
> Lehrstuhl Allgemeine Elektrotechnik                  Tel. +49 355 69-4129
> Universitaetsplatz 3-4, D-03044 Cottbus              Fax. +49 355 69-4153
>

On Wed, Jun 20, 2001 at 10:20:51AM +0200, Lutz Jaenicke
wrote:
> I am resending the following message about problems with utmp handling.
thanks. your original message was somehow dropped due to
problems with the signal-to-noise ratio.

you can try this patch (against -current).

the patch does a little bit more, but all you
need is this:
+       channel_free_all();
+
        signal(SIGCHLD, SIG_DFL);
        while ((pid = waitpid(-1, &status, WNOHANG)) > 0)
                session_close_by_pid(pid, status);
-       channel_stop_listening();

in serverloop.c and an implementation for channel_free_all().

(some interfaces in channel.c have been changed since 2.9).

Index: channels.c
==================================================================RCS file:
/home/markus/cvs/ssh/channels.c,v
retrieving revision 1.125
diff -u -r1.125 channels.c
--- channels.c	2001/06/07 20:23:04	1.125
+++ channels.c	2001/06/20 13:25:23
@@ -223,11 +223,7 @@
 		channels = xmalloc(channels_alloc * sizeof(Channel *));
 		for (i = 0; i < channels_alloc; i++)
 			channels[i] = NULL;
-		/*
-		 * Kludge: arrange a call to channel_stop_listening if we
-		 * terminate with fatal().
-		 */
-		fatal_add_cleanup((void (*) (void *)) channel_stop_listening, NULL);
+		fatal_add_cleanup((void (*) (void *)) channel_free_all, NULL);
 	}
 	/* Try to find a free slot where to put the new channel. */
 	for (found = -1, i = 0; i < channels_alloc; i++)
@@ -334,38 +330,15 @@
 	xfree(c);
 }
 
-
-/*
- * Stops listening for channels, and removes any unix domain sockets that we
- * might have.
- */
-
 void
-channel_stop_listening()
+channel_free_all(void)
 {
 	int i;
-	Channel *c;
 
-	for (i = 0; i < channels_alloc; i++) {
-		c = channels[i];
-		if (c != NULL) {
-			switch (c->type) {
-			case SSH_CHANNEL_AUTH_SOCKET:
-				close(c->sock);
-				/* auth_sock_cleanup_proc deletes the socket */
-				channel_free(c);
-				break;
-			case SSH_CHANNEL_PORT_LISTENER:
-			case SSH_CHANNEL_RPORT_LISTENER:
-			case SSH_CHANNEL_X11_LISTENER:
-				close(c->sock);
-				channel_free(c);
-				break;
-			default:
-				break;
-			}
-		}
-	}
+	debug("closing all channels");
+	for (i = 0; i < channels_alloc; i++)
+		if (channels[i] != NULL)
+			channel_free(channels[i]);
 }
 
 /*
Index: channels.h
==================================================================RCS file:
/home/markus/cvs/ssh/channels.h,v
retrieving revision 1.38
diff -u -r1.38 channels.h
--- channels.h	2001/06/16 08:50:39	1.38
+++ channels.h	2001/06/20 13:25:24
@@ -150,6 +150,7 @@
 channel_set_fds(int id, int rfd, int wfd, int efd,
     int extusage, int nonblock);
 void    channel_free(Channel *c);
+void    channel_free_all(void);
 
 void	channel_send_open(int id);
 void	channel_request(int id, char *service, int wantconfirm);
@@ -182,8 +183,8 @@
 void    channel_output_poll(void);
 
 int     channel_not_very_much_buffered_data(void);
-void    channel_stop_listening(void);
 void    channel_close_all(void);
+void    channel_free_all(void);
 int     channel_still_open(void);
 char   *channel_open_message(void);
 int	channel_find_open(void);
Index: clientloop.c
==================================================================RCS file:
/home/markus/cvs/ssh/clientloop.c,v
retrieving revision 1.75
diff -u -r1.75 clientloop.c
--- clientloop.c	2001/06/04 23:07:20	1.75
+++ clientloop.c	2001/06/20 13:28:17
@@ -546,7 +546,7 @@
 				leave_raw_mode();
 
 				/* Stop listening for new connections. */
-				channel_stop_listening();
+				channel_close_all();	/* proto1 only XXXX */
 
 				printf("%c& [backgrounded]\n", escape_char);
 
@@ -926,8 +926,7 @@
 	if (have_pty)
 		signal(SIGWINCH, SIG_DFL);
 
-	/* Stop listening for connections. */
-	channel_stop_listening();
+	channel_free_all();
 
 	if (have_pty)
 		leave_raw_mode();
Index: packet.c
==================================================================RCS file:
/home/markus/cvs/ssh/packet.c,v
retrieving revision 1.66
diff -u -r1.66 packet.c
--- packet.c	2001/06/12 16:11:26	1.66
+++ packet.c	2001/06/20 13:25:24
@@ -1085,7 +1085,7 @@
 	packet_write_wait();
 
 	/* Stop listening for connections. */
-	channel_stop_listening();
+	channel_close_all();
 
 	/* Close the connection. */
 	packet_close();
Index: serverloop.c
==================================================================RCS file:
/home/markus/cvs/ssh/serverloop.c,v
retrieving revision 1.68
diff -u -r1.68 serverloop.c
--- serverloop.c	2001/06/04 23:07:20	1.68
+++ serverloop.c	2001/06/20 13:25:24
@@ -608,8 +608,7 @@
 		close(fdin);
 	fdin = -1;
 
-	/* Stop listening for channels; this removes unix domain sockets. */
-	channel_stop_listening();
+	channel_free_all();
 
 	/* We no longer want our SIGCHLD handler to be called. */
 	signal(SIGCHLD, SIG_DFL);
@@ -700,10 +699,11 @@
 	if (writeset)
 		xfree(writeset);
 
+	channel_free_all();
+
 	signal(SIGCHLD, SIG_DFL);
 	while ((pid = waitpid(-1, &status, WNOHANG)) > 0)
 		session_close_by_pid(pid, status);
-	channel_stop_listening();
 }
 
 void

On Wed, Jun 20, 2001 at 03:49:26PM +0200, Markus Friedl
wrote:
> you can try this patch (against -current).
> 
> the patch does a little bit more, but all you
> need is this:
> +       channel_free_all();
> +
>         signal(SIGCHLD, SIG_DFL);
>         while ((pid = waitpid(-1, &status, WNOHANG)) > 0)
>                 session_close_by_pid(pid, status);
> -       channel_stop_listening();
> 
> in serverloop.c and an implementation for channel_free_all().
It does not work.

The effect is still the same.
A sshd -d yields:
Connection closed by remote host.
debug1: closing all channels
debug1: channel_free: channel 0: server-session, nchannels 1
debug1: channel_free: channel 0: dettaching channel user
debug1: session_by_channel: session 0 channel 0
debug1: session_close_by_channel: channel 0 kill 18299
Closing connection to 141.43.132.151

Following the code in session.c, session_close_by_channel with
s->pid != 0 will "notify child, delay session cleanup".
However, session_close() is never called (it would be seen due to
 debug("session_close: session %d pid %d", s->self, s->pid))
and therefore it seems that session_pty_cleanup(s) (finally calling
the record_logout() function) is never called.

Best regards,
	Lutz
-- 
Lutz Jaenicke                             Lutz.Jaenicke at aet.TU-Cottbus.DE
BTU Cottbus               http://www.aet.TU-Cottbus.DE/personen/jaenicke/
Lehrstuhl Allgemeine Elektrotechnik                  Tel. +49 355 69-4129
Universitaetsplatz 3-4, D-03044 Cottbus              Fax. +49 355 69-4153

On Wed, Jun 20, 2001 at 06:08:45PM +0200, Lutz Jaenicke
wrote:
> On Wed, Jun 20, 2001 at 03:49:26PM +0200, Markus Friedl wrote:
> > you can try this patch (against -current).
> > 
> > the patch does a little bit more, but all you
> > need is this:
> > +       channel_free_all();
> > +
> >         signal(SIGCHLD, SIG_DFL);
> >         while ((pid = waitpid(-1, &status, WNOHANG)) > 0)
> >                 session_close_by_pid(pid, status);
> > -       channel_stop_listening();
> > 
> > in serverloop.c and an implementation for channel_free_all().
> 
> It does not work.
> 
> The effect is still the same.
> A sshd -d yields:
> Connection closed by remote host.
> debug1: closing all channels
> debug1: channel_free: channel 0: server-session, nchannels 1
> debug1: channel_free: channel 0: dettaching channel user
> debug1: session_by_channel: session 0 channel 0
> debug1: session_close_by_channel: channel 0 kill 18299
> Closing connection to 141.43.132.151
> 
> Following the code in session.c, session_close_by_channel with
> s->pid != 0 will "notify child, delay session cleanup".
> However, session_close() is never called (it would be seen due to
>  debug("session_close: session %d pid %d", s->self,
s->pid))
> and therefore it seems that session_pty_cleanup(s) (finally calling
> the record_logout() function) is never called.
i see, there are more changes in current.

could you please try current?

On Thu, Jun 21, 2001 at 05:43:26AM +0200, Markus Friedl
wrote:
> On Wed, Jun 20, 2001 at 06:08:45PM +0200, Lutz Jaenicke wrote:
> > Following the code in session.c, session_close_by_channel with
> > s->pid != 0 will "notify child, delay session cleanup".
> > However, session_close() is never called (it would be seen due to
> >  debug("session_close: session %d pid %d", s->self,
s->pid))
> > and therefore it seems that session_pty_cleanup(s) (finally calling
> > the record_logout() function) is never called.
> 
> i see, there are more changes in current.
> 
> could you please try current?
Ok, the CVS mirror has now been updated including the patch :-)
It does not work, though :-(
The "famous last words" are:
debug1: fd 7 setting O_NONBLOCK
debug2: fd 3 is O_NONBLOCK
debug2: callback done
Connection closed by remote host.
debug1: channel_free: channel 0: server-session, nchannels 1
debug3: channel_free: status: The following connections are open:
  #0 server-session (t4 r0 i1/0 o16/0 fd 7/3)

debug1: channel_free: channel 0: dettaching channel user
debug1: session_by_channel: session 0 channel 0
debug1: session_close_by_channel: channel 0 kill 28025
debug3: channel_close_fds: channel 0: r 7 w 3 e -1
Closing connection to 127.0.0.1

When the connection is closed, the child (in this case 27921) will be
killed from session_close_by_channel() with either TERM or HUP.
However, session_close(), which is responsible for recording the logout,
is not called.

Best regards,
	Lutz
-- 
Lutz Jaenicke                             Lutz.Jaenicke at aet.TU-Cottbus.DE
BTU Cottbus               http://www.aet.TU-Cottbus.DE/personen/jaenicke/
Lehrstuhl Allgemeine Elektrotechnik                  Tel. +49 355 69-4129
Universitaetsplatz 3-4, D-03044 Cottbus              Fax. +49 355 69-4153

On Thu, Jun 21, 2001 at 03:12:15PM +0200, Lutz Jaenicke
wrote:
> Ok, the CVS mirror has now been updated including the patch :-)
> It does not work, though :-(
> The "famous last words" are:
> debug1: fd 7 setting O_NONBLOCK
> debug2: fd 3 is O_NONBLOCK
> debug2: callback done
> Connection closed by remote host.
> debug1: channel_free: channel 0: server-session, nchannels 1
> debug3: channel_free: status: The following connections are open:
>   #0 server-session (t4 r0 i1/0 o16/0 fd 7/3)
> 
> debug1: channel_free: channel 0: dettaching channel user
> debug1: session_by_channel: session 0 channel 0
> debug1: session_close_by_channel: channel 0 kill 28025
> debug3: channel_close_fds: channel 0: r 7 w 3 e -1
> Closing connection to 127.0.0.1
> 
> When the connection is closed, the child (in this case 27921) will be
                                                         ^^^^^
(This was an old PID from another example, sorry. Read this: 28025)
> killed from session_close_by_channel() with either TERM or HUP.
> However, session_close(), which is responsible for recording the logout,
> is not called.
> 
> Best regards,
> 	Lutz
> -- 
> Lutz Jaenicke                             Lutz.Jaenicke at
aet.TU-Cottbus.DE
> BTU Cottbus               http://www.aet.TU-Cottbus.DE/personen/jaenicke/
> Lehrstuhl Allgemeine Elektrotechnik                  Tel. +49 355 69-4129
> Universitaetsplatz 3-4, D-03044 Cottbus              Fax. +49 355 69-4153
-- 
Lutz Jaenicke                             Lutz.Jaenicke at aet.TU-Cottbus.DE
BTU Cottbus               http://www.aet.TU-Cottbus.DE/personen/jaenicke/
Lehrstuhl Allgemeine Elektrotechnik                  Tel. +49 355 69-4129
Universitaetsplatz 3-4, D-03044 Cottbus              Fax. +49 355 69-4153

i get this on openbsd-current:

Connection closed by remote host.
debug1: channel_free: channel 0: server-session, nchannels 1
debug3: channel_free: status: The following connections are open:
  #0 server-session (t4 r0 i1/0 o16/0 fd 4/3)

debug1: channel_free: channel 0: dettaching channel user
debug1: session_by_channel: session 0 channel 0
debug1: session_close_by_channel: channel 0 kill 5870
debug1: Received SIGCHLD.
debug3: channel_close_fds: channel 0: r 4 w 3 e -1
debug1: session_by_pid: pid 5870
debug1: session_close: session 0 pid 5870
debug1: session_pty_cleanup: session 0 release /dev/ttyqc
Closing connection to 127.0.0.1

-m

Hello!
> That leaves the question about a "cleaner" solution to this
effect.
> After first sending the bug report, I received private mails indicating,
> that this effect has also been seen on Linux, so it is not a pure
HP-problem.
Thats right; the problem appears on Linux as well. I have tried even the
new snapshots in which the problem should be fixed - without success.
Now I tried the "Lutz-bugfix" and it works on Linux, too.

Greetings, Jan


-- 
Jan Suchanek, 
Universitaet Ulm, URG, Fakultaet fuer Informatik,
89069 Ulm, Germany
Raum: O27/243

Tel.: +49/(0)731-5024205, Fax: +49/(0)731-5024202