Merge lp:~jakobunt/ltsp/ldm-log-v2 into lp:~ltsp-upstream/ltsp/ldm-trunk

[Jakob Unterwurzacher]

Bye bye "No response from server" - add ssh error logging

ldm now reads the full output from ssh to show a proper error message
to the user (and also write it to the log).

v2 of the "Bye bye No response from server" patch splits up the change into eight small chunks.
It also tries to be as little intrusive as possible.

Each patch has been individually tested (compile, successful login, incorrect password).

Thanks,
Jakob

[Vagrant Cascadian (vagrantc)]

Thanks for the reworked patches!

Having tested this patchset, it does work to resolve the incorrect loging or password issue with feedback. It does seem to introduce a little noise on a successful login that flashes by too fast to read...

Overall, I think this is better than what we've had before.

[Jakob Unterwurzacher (jakobunt)]

Thanks for the quick feedback & merge!

Regarding the flashing text issue:

If you add LDM_LOGLEVEL=7 to lts.conf (watch out, this also logs passwords!), every change of the displayed text is logged like this:

Sep 22 05:08:10: [gtkgreet] DEBUG: Got command: msg <b>Verifying password. Please wait.</b>

I don't see changes after that one, but maybe your ssh output is different - the log should tell us what is going on.

=== modified file 'src/plugins/ssh/ssh.c'
--- src/plugins/ssh/ssh.c	2014-07-31 19:30:25 +0000
+++ src/plugins/ssh/ssh.c	2014-09-22 22:10:52 +0000
@@ -17,6 +17,7 @@
 #include <sys/stat.h>
 #include <utmp.h>
 #include <crypt.h>
+#include <errno.h>
 
 #include "../../ldm.h"
 #include "../../ldmutils.h"
@@ -321,8 +322,9 @@
         FD_SET(fd, &set);
         st = select(FD_SETSIZE, &set, NULL, NULL, &timeout);
 
-        if (child_exited) {
-            break;                               /* someone died on us */
+        if (st == -1 && errno == EINTR)
+        {
+            continue;                            /* interrupted by signal -> retry */
         }
 
         if (st < 0) {                            /* bad thing */
@@ -348,6 +350,10 @@
             total += size;
         }
 
+        if (child_exited) {
+            break;                               /* someone died on us */
+        }
+
         for (i = 0; i < expects->len; i++) {
             if (strstr(p, g_ptr_array_index(expects, i))) {
                 loopend = TRUE;
@@ -358,22 +364,24 @@
         if (loopend) {
             break;
         }
-
-        if (timeout.tv_sec == 0) {
-            break;
-        }
     }
 
     log_entry("ldm", 7, "expect saw: %s", p);
 
-    if (size < 0 || st < 0 || child_exited) {
+    if (size < 0 || st < 0) {
         return ERROR;                            /* error occured */
     }
     if (loopcount == 0) {
         return TIMED_OUT;                        /* timed out */
-    } else {
-        return i;                                /* which expect did we see? */
-    }
+    }
+    /* Sleep a bit to make sure we notice if ssh died in the meantime */
+    usleep(100000);
+    if (child_exited)
+    {
+        return ERROR;
+    }
+
+    return i;                                    /* which expect did we see? */
 }
 
 void
@@ -399,11 +407,14 @@
            end of the line */
         if (seen == 0) {
             return;
-        } else if (seen == 1) {
-            int i;
-            g_strdelimit(lastseen, "\r\n\t", ' ');
-            g_strchomp(lastseen);
-            i = strlen(lastseen);
+        }
+
+        int i;
+        g_strdelimit(lastseen, "\r\n\t", ' ');
+        g_strchomp(lastseen);
+        i = strlen(lastseen);
+
+        if (seen == 1) {
             /* If it's not the first time through, or the :'s not at the
              * end of a line (password expiry or error), set the message */
             if ((!first_time) || (lastseen[i - 1] != ':')) {
@@ -417,7 +428,13 @@
             }
             first_time = 0;
         } else if (seen < 0) {
-            set_message(_("No response from server, restarting..."));
+            if (i > 0) {
+                log_entry("ssh", 3, "ssh returned: %s", lastseen);
+                set_message(lastseen);
+            }
+            else {
+                set_message(_("No response from server, restarting..."));
+            }
             sleep(5);
             close_greeter();
             die("ssh", "no response, restarting");
@@ -454,12 +471,17 @@
     command = g_strjoin(" ", "ssh", "-Y", "-t", "-M",
                         "-S", sshinfo->ctl_socket,
                         "-o", "NumberOfPasswordPrompts=1",
+                         /* ConnectTimeout should be less than the timeout ssh_chat
+                          * passes to expect, so we get the error message from ssh
+                          * before expect gives up
+                          */
+                        "-o", "ConnectTimeout=10",
                         "-l", sshinfo->username,
                         port ? port : "",
                         sshinfo->sshoptions ? sshinfo->sshoptions : "",
                         sshinfo->server,
                         "echo " SENTINEL "; exec /bin/sh -", NULL);
-    log_entry("ssh", 7, "ssh_session: %s", command);
+    log_entry("ssh", 6, "ssh_session: %s", command);
 
     sshinfo->sshpid = ldm_spawn(command, NULL, NULL, ssh_tty_init);
 
@@ -487,7 +509,7 @@
         command =
             g_strjoin(" ", "ssh", "-S", sshinfo->ctl_socket, "-O", "exit",
                       sshinfo->server, NULL);
-        log_entry("ssh", 7, "closing ssh session: %s"), command;
+        log_entry("ssh", 6, "closing ssh session: %s"), command;
         pid = ldm_spawn(command, NULL, NULL, NULL);
         ldm_wait(pid);
         close(sshinfo->sshfd);