Merge branch 'egil/extend-ttsl_drv-logging'

* egil/extend-ttsl_drv-logging:
  erts: Increase ttsl_drv logging capabilities

1 files changed, 100 insertions, 48 deletions

diff --git a/erts/emulator/drivers/unix/ttsl_drv.c b/erts/emulator/drivers/unix/ttsl_drv.c
index 25cad37e25..abfc52d3bc 100644
--- a/erts/emulator/drivers/unix/ttsl_drv.c
+++ b/erts/emulator/drivers/unix/ttsl_drv.c
@@ -199,7 +199,7 @@ static void my_debug_printf(char *fmt, ...)
     erts_vsnprintf(buffer,1024,fmt,args);
     va_end(args);
     erts_fprintf(debuglog,"%s\n",buffer);
-    //erts_printf("Debuglog = %s\n",buffer);
+    /*erts_printf("Debuglog = %s\n",buffer);*/
 }
 
 #else
@@ -261,15 +261,17 @@ static int ttysl_init(void)
 	    if (debuglog != NULL)
 		setbuf(debuglog,NULL);
 	}
-	DEBUGLOG(("Debuglog = %s(0x%ld)\n",dl,(long) debuglog));
+	DEBUGLOG(("ttysl_init: Debuglog = %s(0x%ld)\n",dl,(long) debuglog));
     }
 #endif
+    DEBUGLOG(("ttysl_init: ttysl_port = %d\n", ttysl_port));
     return 0;
 }
 
 static ErlDrvData ttysl_start(ErlDrvPort port, char* buf)
 {
 #ifndef HAVE_TERMCAP
+    DEBUGLOG(("ttysl_start: failure - no TERMCAP configured!\n"));
     return ERL_DRV_ERROR_GENERAL;
 #else
     char *s, *t, *l;
@@ -277,36 +279,46 @@ static ErlDrvData ttysl_start(ErlDrvPort port, char* buf)
     int flag;
     extern int using_oldshell; /* set this to let the rest of erts know */
 
+    DEBUGLOG(("ttysl_start: driver input \"%s\", ttysl_port = %d (-1 expected)", buf, ttysl_port));
     utf8buf_size = 0;
-    if (ttysl_port != (ErlDrvPort)-1)
-      return ERL_DRV_ERROR_GENERAL;
+    if (ttysl_port != (ErlDrvPort)-1) {
+        DEBUGLOG(("ttysl_start: failure with ttysl_port = %d, not initialized properly?\n", ttysl_port));
+        return ERL_DRV_ERROR_GENERAL;
+    }
 
-    if (!isatty(0) || !isatty(1))
+    DEBUGLOG(("ttysl_start: isatty(0) = %d (1 expected), isatty(1) = %d (1 expected)", isatty(0), isatty(1)));
+    if (!isatty(0) || !isatty(1)) {
+        DEBUGLOG(("ttysl_start: failure in isatty, isatty(0) = %d, isatty(1) = %d", isatty(0), isatty(1)));
 	return ERL_DRV_ERROR_GENERAL;
+    }
 
     /* Set the terminal modes to default leave as is. */
     canon = echo = sig = 0;
 
     /* Parse the input parameters. */
     for (s = strchr(buf, ' '); s; s = t) {
-	s++;
-	/* Find end of this argument (start of next) and insert NUL. */
-	if ((t = strchr(s, ' '))) {
-	    *t = '\0';
-	}
-	if ((flag = ((*s == '+') ? 1 : ((*s == '-') ? -1 : 0)))) {
-	    if (s[1] == 'c') canon = flag;
-	    if (s[1] == 'e') echo = flag;
-	    if (s[1] == 's') sig = flag;
-	}
-	else if ((ttysl_fd = open(s, O_RDWR, 0)) < 0)
-	      return ERL_DRV_ERROR_GENERAL;
+        s++;
+        /* Find end of this argument (start of next) and insert NUL. */
+        if ((t = strchr(s, ' '))) {
+            *t = '\0';
+        }
+        if ((flag = ((*s == '+') ? 1 : ((*s == '-') ? -1 : 0)))) {
+            if (s[1] == 'c') canon = flag;
+            if (s[1] == 'e') echo = flag;
+            if (s[1] == 's') sig = flag;
+        }
+        else if ((ttysl_fd = open(s, O_RDWR, 0)) < 0) {
+            DEBUGLOG(("ttysl_start: failed to open ttysl_fd, open(%s, O_RDWR, 0)) = %d\n", s, ttysl_fd));
+            return ERL_DRV_ERROR_GENERAL;
+        }
     }
+
     if (ttysl_fd < 0)
       ttysl_fd = 0;
 
     if (tty_init(ttysl_fd, canon, echo, sig) < 0 ||
-	tty_set(ttysl_fd) < 0) {
+        tty_set(ttysl_fd) < 0) {
+        DEBUGLOG(("ttysl_start: failed init tty or set tty\n"));
 	ttysl_port = (ErlDrvPort)-1;
 	tty_reset(ttysl_fd);
 	return ERL_DRV_ERROR_GENERAL;
@@ -314,6 +326,7 @@ static ErlDrvData ttysl_start(ErlDrvPort port, char* buf)
 
     /* Set up smart line and termcap stuff. */
     if (!start_lbuf() || !start_termcap()) {
+        DEBUGLOG(("ttysl_start: failed to start_lbuf or start_termcap\n"));
 	stop_lbuf();		/* Must free this */
 	tty_reset(ttysl_fd);
 	return ERL_DRV_ERROR_GENERAL;
@@ -335,10 +348,10 @@ static ErlDrvData ttysl_start(ErlDrvPort port, char* buf)
     l = setlocale(LC_CTYPE, "");  /* Set international environment */
     if (l != NULL) {
 	utf8_mode = (strcmp(nl_langinfo(CODESET), "UTF-8") == 0);
-	DEBUGLOG(("setlocale: %s\n",l));
+	DEBUGLOG(("ttysl_start: setlocale: %s",l));
     }
 #endif
-    DEBUGLOG(("utf8_mode is %s\n",(utf8_mode) ? "on" : "off"));
+    DEBUGLOG(("ttysl_start: utf8_mode is %s",(utf8_mode) ? "on" : "off"));
     sys_signal(SIGCONT, cont);
     sys_signal(SIGWINCH, winch);
 
@@ -348,6 +361,7 @@ static ErlDrvData ttysl_start(ErlDrvPort port, char* buf)
     /* we need to know this when we enter the break handler */
     using_oldshell = 0;
 
+    DEBUGLOG(("ttysl_start: successful start\n"));
     return (ErlDrvData)ttysl_port;	/* Nothing important to return */
 #endif /* HAVE_TERMCAP */
 }
@@ -418,6 +432,7 @@ static ErlDrvSSizeT ttysl_control(ErlDrvData drv_data,
 
 static void ttysl_stop(ErlDrvData ttysl_data)
 {
+    DEBUGLOG(("ttysl_stop: ttysl_port = %d\n",ttysl_port));
     if (ttysl_port != (ErlDrvPort)-1) {
 	stop_lbuf();
 	stop_termcap();
@@ -617,12 +632,13 @@ static int check_buf_size(byte *s, int n)
     int ch;
     int size = 10;
 
+    DEBUGLOG(("check_buf_size: n = %d",n));
     while(pos < n) {
 	/* Indata is always UTF-8 */
 	if ((ch = pick_utf8(s,n,&pos)) < 0) {
 	    /* XXX temporary allow invalid chars */
 	    ch = (int) s[pos];
-	    DEBUGLOG(("Invalid UTF8:%d",ch));
+	    DEBUGLOG(("check_buf_size: Invalid UTF8:%d",ch));
 	    ++pos;
 	} 
 	if (utf8_mode) { /* That is, terminal is UTF8 compliant */
@@ -630,7 +646,7 @@ static int check_buf_size(byte *s, int n)
 #ifdef HAVE_WCWIDTH
 		int width;
 #endif
-		DEBUGLOG(("Printable(UTF-8:%d):%d",pos,ch));
+		DEBUGLOG(("check_buf_size: Printable(UTF-8:%d):%d",pos,ch));
 		size++;
 #ifdef HAVE_WCWIDTH
 		if ((width = wcwidth(ch)) > 1) {
@@ -640,21 +656,21 @@ static int check_buf_size(byte *s, int n)
 	    } else if (ch == '\t') {
 		size += 8;
 	    } else {
-		DEBUGLOG(("Magic(UTF-8:%d):%d",pos,ch));
+		DEBUGLOG(("check_buf_size: Magic(UTF-8:%d):%d",pos,ch));
 		size += 2;
 	    }
 	} else {
 	    if (ch <= 255 && isprint(ch)) {
-		DEBUGLOG(("Printable:%d",ch));
+		DEBUGLOG(("check_buf_size: Printable:%d",ch));
 		size++;
 	    } else if (ch == '\t') 
 		size += 8;
 	    else if (ch >= 128) {
-		DEBUGLOG(("Non printable:%d",ch));
+		DEBUGLOG(("check_buf_size: Non printable:%d",ch));
 		size += (octal_or_hex_positions(ch) + 1);
 	    }
 	    else {
-		DEBUGLOG(("Magic:%d",ch));
+		DEBUGLOG(("check_buf_size: Magic:%d",ch));
 		size += 2;
 	    }
 	}
@@ -664,10 +680,12 @@ static int check_buf_size(byte *s, int n)
 
 	lbuf_size = size + lpos + BUFSIZ;
 	if ((lbuf = driver_realloc(lbuf, lbuf_size * sizeof(Uint32))) == NULL) {
+            DEBUGLOG(("check_buf_size: alloc failure of %d bytes", lbuf_size * sizeof(Uint32)));
 	    driver_failure(ttysl_port, -1);
 	    return(0);
 	}
     }
+    DEBUGLOG(("check_buf_size: success\n"));
     return(1);
 }
 
@@ -685,6 +703,8 @@ static void ttysl_from_erlang(ErlDrvData ttysl_data, char* buf, ErlDrvSizeT coun
     if (lpos > MAXSIZE) 
 	put_chars((byte*)"\n", 1);
 
+    DEBUGLOG(("ttysl_from_erlang: OP = %d", buf[0]));
+
     switch (buf[0]) {
     case OP_PUTC_SYNC:
         /* Using sync means that we have to send an ok to the
@@ -695,7 +715,7 @@ static void ttysl_from_erlang(ErlDrvData ttysl_data, char* buf, ErlDrvSizeT coun
            the port_command. */
         /* fall through */
     case OP_PUTC:
-	DEBUGLOG(("OP: Putc(%lu)",(unsigned long) count-1));
+	DEBUGLOG(("ttysl_from_erlang: OP: Putc(%lu)",(unsigned long) count-1));
 	if (check_buf_size((byte*)buf+1, count-1) == 0)
 	    return; 
 	put_chars((byte*)buf+1, count-1);
@@ -738,6 +758,7 @@ static void ttysl_from_erlang(ErlDrvData ttysl_data, char* buf, ErlDrvSizeT coun
                                   ERL_DRV_USE|ERL_DRV_WRITE,1);
                     break;
                 } else {
+                    DEBUGLOG(("ttysl_from_erlang: driver failure in writev(%d,..) = %d (errno = %d)\n", ttysl_fd, written, errno));
 		    driver_failure_posix(ttysl_port, errno);
 		    return;
                 }
@@ -774,6 +795,9 @@ static void ttysl_to_tty(ErlDrvData ttysl_data, ErlDrvEvent fd) {
         ErlDrvSizeT sz;
 
         iov = driver_peekq(ttysl_port,&qlen);
+        
+        DEBUGLOG(("ttysl_to_tty: qlen = %d", qlen));
+
         if (iov)
             written = writev(ttysl_fd, iov, qlen > MAXIOV ? MAXIOV : qlen);
         else
@@ -782,6 +806,7 @@ static void ttysl_to_tty(ErlDrvData ttysl_data, ErlDrvEvent fd) {
             if (errno == EINTR) {
 	        continue;
 	    } else if (errno != ERRNO_BLOCK){
+                DEBUGLOG(("ttysl_to_tty: driver failure in writev(%d,..) = %d (errno = %d)\n", ttysl_fd, written, errno));
 	        driver_failure_posix(ttysl_port, errno);
             }
             break;
@@ -804,6 +829,7 @@ static void ttysl_to_tty(ErlDrvData ttysl_data, ErlDrvEvent fd) {
                     /* flush has been called, which means we should terminate
                        when queue is empty. This will not send any exit
                        message */
+                    DEBUGLOG(("ttysl_to_tty: ttysl_terminate normal\n"));
                     driver_failure_atom(ttysl_port, "normal");
                 break;
             }
@@ -814,6 +840,7 @@ static void ttysl_to_tty(ErlDrvData ttysl_data, ErlDrvEvent fd) {
 }
 
 static void ttysl_flush_tty(ErlDrvData ttysl_data) {
+    DEBUGLOG(("ttysl_flush_tty: .."));
     ttysl_terminate = 1;
     return;
 }
@@ -834,6 +861,8 @@ static void ttysl_from_tty(ErlDrvData ttysl_data, ErlDrvEvent fd)
 	p += utf8buf_size;
 	utf8buf_size = 0;
     }
+
+    DEBUGLOG(("ttysl_from_tty: remainder = %d", left));
     
     if ((i = read((int)(SWord)fd, (char *) p, left)) >= 0) {
 	if (p != b) {
@@ -847,7 +876,7 @@ static void ttysl_from_tty(ErlDrvData ttysl_data, ErlDrvEvent fd)
 		utf8buf_size = i -pos;
 		memcpy(utf8buf,b+pos,utf8buf_size);
 	    } else if (ch == -1) {
-		DEBUGLOG(("Giving up on UTF8 mode, invalid character"));
+		DEBUGLOG(("ttysl_from_tty: Giving up on UTF8 mode, invalid character"));
 		utf8_mode = 0;
 		goto latin_terminal;
 	    }
@@ -864,6 +893,7 @@ static void ttysl_from_tty(ErlDrvData ttysl_data, ErlDrvEvent fd)
 	    }
 	}
     } else {
+        DEBUGLOG(("ttysl_from_tty: driver failure in read(%d,..) = %d\n", (int)(SWord)fd, i)); 
 	driver_failure(ttysl_port, -1);
     }
 }
@@ -1155,7 +1185,7 @@ static int write_buf(Uint32 *s, int n)
 	    byte *octbuff;
 	    byte octtmp[256];
 	    int octbytes;
-	    DEBUGLOG(("Escaped: %d", ch));
+	    DEBUGLOG(("write_buf: Escaped: %d", ch));
 	    octbytes = octal_or_hex_positions(ch);
 	    if (octbytes > 256) {
 		octbuff = driver_alloc(octbytes);
@@ -1164,11 +1194,11 @@ static int write_buf(Uint32 *s, int n)
 	    }
 	    octbytes = 0;
 	    octal_or_hex_format(ch, octbuff, &octbytes);
-	     DEBUGLOG(("octbytes: %d", octbytes));
+            DEBUGLOG(("write_buf: octbytes: %d", octbytes));
 	    outc('\\');
 	    for (i = 0; i < octbytes; ++i) {
 		outc(lastput = octbuff[i]);
-		DEBUGLOG(("outc: %d", (int) lastput));
+		DEBUGLOG(("write_buf: outc: %d", (int) lastput));
 	    }
 	    n -= octbytes+1;
 	    s += octbytes+1;
@@ -1180,7 +1210,7 @@ static int write_buf(Uint32 *s, int n)
 	    --n; s++;
 #endif
 	} else {
-	    DEBUGLOG(("Very unexpected character %d",(int) *s));
+	    DEBUGLOG(("write_buf: Very unexpected character %d",(int) *s));
 	    ++n;
 	    --s;
 	}
@@ -1242,6 +1272,9 @@ static int start_termcap(void)
     size_t envsz = 1024;
     char *env = NULL;
     char *c;
+    int tres;
+
+    DEBUGLOG(("start_termcap: .."));
 
     capbuf = driver_alloc(1024);
     if (!capbuf)
@@ -1249,9 +1282,10 @@ static int start_termcap(void)
     eres = erl_drv_getenv("TERM", capbuf, &envsz);
     if (eres == 0)
 	env = capbuf;
-    else if (eres < 0)
+    else if (eres < 0) {
+        DEBUGLOG(("start_termcap: failure in erl_drv_getenv(\"TERM\", ..) = %d\n", eres));
 	goto false;
-    else /* if (eres > 1) */ {
+    } else /* if (eres > 1) */ {
       char *envbuf = driver_alloc(envsz);
       if (!envbuf)
 	  goto false;
@@ -1261,7 +1295,8 @@ static int start_termcap(void)
 	  if (eres == 0)
 	      break;
 	  newenvbuf = driver_realloc(envbuf, envsz);
-	  if (eres < 0 || !newenvbuf) {
+          if (eres < 0 || !newenvbuf) {
+              DEBUGLOG(("start_termcap: failure in erl_drv_getenv(\"TERM\", ..) = %d or realloc buf == %p\n", eres, newenvbuf));
 	      env = newenvbuf ? newenvbuf : envbuf;
 	      goto false;
 	  }
@@ -1269,8 +1304,10 @@ static int start_termcap(void)
       }
       env = envbuf;
     }
-    if (tgetent((char*)lbuf, env) <= 0)
-      goto false;
+    if ((tres = tgetent((char*)lbuf, env)) <= 0) {
+        DEBUGLOG(("start_termcap: failure in tgetent(..) = %d\n", tres));
+        goto false;
+    }
     if (env != capbuf) {
 	env = NULL;
 	driver_free(env);
@@ -1286,8 +1323,11 @@ static int start_termcap(void)
     if (!(left = tgetflag("bs") ? "\b" : tgetstr("bc", &c)))
       left = "\b";		/* Can't happen - but does on Solaris 2 */
     right = tgetstr("nd", &c);
-    if (up && down && left && right)
-      return TRUE;
+    if (up && down && left && right) {
+        DEBUGLOG(("start_termcap: successful start\n"));
+        return TRUE;
+    }
+    DEBUGLOG(("start_termcap: failed start\n"));
  false:
     if (env && env != capbuf)
 	driver_free(env);
@@ -1364,10 +1404,13 @@ static void update_cols(void)
 
 static struct termios tty_smode, tty_rmode;
 
-static int tty_init(int fd, int canon, int echo, int sig)
-{
-    if (tcgetattr(fd, &tty_rmode) < 0)
-      return -1;
+static int tty_init(int fd, int canon, int echo, int sig) {
+    int tres;
+    DEBUGLOG(("tty_init: fd = %d, canon = %d, echo = %d, sig = %d", fd, canon, echo, sig));
+    if ((tres = tcgetattr(fd, &tty_rmode)) < 0) {
+        DEBUGLOG(("tty_init: failure in tcgetattr(%d,..) = %d\n", fd, tres));
+        return -1;
+    }
     tty_smode = tty_rmode;
 
     /* Default characteristics for all usage including termcap output. */
@@ -1420,6 +1463,7 @@ static int tty_init(int fd, int canon, int echo, int sig)
 #endif	
 	tty_smode.c_lflag &= ~(ISIG|IEXTEN);
     }
+    DEBUGLOG(("tty_init: successful init\n"));
     return 0;
 }
 
@@ -1430,20 +1474,25 @@ static int tty_init(int fd, int canon, int echo, int sig)
 
 static int tty_set(int fd)
 {
-    DEBUGF(("Setting tty...\n"));
+    int tres;
+    DEBUGF(("tty_set: Setting tty...\n"));
 
-    if (tcsetattr(fd, TCSANOW, &tty_smode) < 0)
+    if ((tres = tcsetattr(fd, TCSANOW, &tty_smode)) < 0) {
+        DEBUGLOG(("tty_set: failure in tcgetattr(%d,..) = %d\n", fd, tres));
 	return(-1);
+    }
     return(0);
 }
 
 static int tty_reset(int fd)         /* of terminal device */
 {
-    DEBUGF(("Resetting tty...\n"));
+    int tres;
+    DEBUGF(("tty_reset: Resetting tty...\n"));
 
-    if (tcsetattr(fd, TCSANOW, &tty_rmode) < 0)
+    if ((tres = tcsetattr(fd, TCSANOW, &tty_rmode)) < 0) {
+        DEBUGLOG(("tty_reset: failure in tcsetattr(%d,..) = %d\n", fd, tres));
 	return(-1);
-    
+    }
     return(0);
 }
 
@@ -1458,6 +1507,7 @@ static int tty_reset(int fd)         /* of terminal device */
 static RETSIGTYPE suspend(int sig)
 {
     if (tty_reset(ttysl_fd) < 0) {
+        DEBUGLOG(("signal: failure in suspend(%d), can't reset tty %d\n", sig, ttysl_fd));
 	fprintf(stderr,"Can't reset tty \n");
 	exit(1);
     }
@@ -1469,6 +1519,7 @@ static RETSIGTYPE suspend(int sig)
     sys_signal(sig, suspend);	/* Reset signal handler */ 
 
     if (tty_set(ttysl_fd) < 0) {
+        DEBUGLOG(("signal: failure in suspend(%d), can't set tty %d\n", sig, ttysl_fd));
 	fprintf(stderr,"Can't set tty raw \n");
 	exit(1);
     }
@@ -1479,6 +1530,7 @@ static RETSIGTYPE suspend(int sig)
 static RETSIGTYPE cont(int sig)
 {
     if (tty_set(ttysl_fd) < 0) {
+        DEBUGLOG(("signal: failure in cont(%d), can't set tty raw %d\n", sig, ttysl_fd));
 	fprintf(stderr,"Can't set tty raw\n");
 	exit(1);
     }