Mercurial > vim

changeset 8114:4aea0b0aa714 v7.4.1351

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
commit https://github.com/vim/vim/commit/81661fb86801e6d6e5194b43dfd27d73fcc016ec Author: Bram Moolenaar <Bram@vim.org> Date: Thu Feb 18 22:23:34 2016 +0100 patch 7.4.1351 Problem: When the port isn't opened yet when ch_open() is called it may fail instead of waiting for the specified time. Solution: Loop when select() succeeds but when connect() failed. Also use channel logging for jobs. Add ch_log().
author Christian Brabandt <cb@256bit.org>
date Thu, 18 Feb 2016 22:30:08 +0100
parents fd690d084aaf
children bfb8f0183718
files src/channel.c src/eval.c src/netbeans.c src/proto/channel.pro src/testdir/test_channel.py src/testdir/test_channel.vim src/version.c
diffstat 7 files changed, 316 insertions(+), 178 deletions(-) [+]
line wrap: on
line diff
--- a/src/channel.c
+++ b/src/channel.c
@@ -90,6 +90,9 @@ fd_close(sock_T fd)
 
 /* Log file opened with ch_logfile(). */
 static FILE *log_fd = NULL;
+#ifdef FEAT_RELTIME
+static proftime_T log_start;
+#endif
 
     void
 ch_logfile(FILE *file)
@@ -98,7 +101,18 @@ ch_logfile(FILE *file)
 	fclose(log_fd);
     log_fd = file;
     if (log_fd != NULL)
+    {
 	fprintf(log_fd, "==== start log session ====\n");
+#ifdef FEAT_RELTIME
+	profile_start(&log_start);
+#endif
+    }
+}
+
+    int
+ch_log_active()
+{
+    return log_fd != NULL;
 }
 
     static void
@@ -106,6 +120,13 @@ ch_log_lead(char *what, channel_T *ch)
 {
     if (log_fd != NULL)
     {
+#ifdef FEAT_RELTIME
+	proftime_T log_now;
+
+	profile_start(&log_now);
+	profile_sub(&log_now, &log_start);
+	fprintf(log_fd, "%s ", profile_msg(&log_now));
+#endif
 	if (ch != NULL)
 	    fprintf(log_fd, "%son %d: ", what, ch->ch_id);
 	else
@@ -113,13 +134,14 @@ ch_log_lead(char *what, channel_T *ch)
     }
 }
 
-    static void
+    void
 ch_log(channel_T *ch, char *msg)
 {
     if (log_fd != NULL)
     {
 	ch_log_lead("", ch);
 	fputs(msg, log_fd);
+	fputc('\n', log_fd);
 	fflush(log_fd);
     }
 }
@@ -131,17 +153,19 @@ ch_logn(channel_T *ch, char *msg, int nr
     {
 	ch_log_lead("", ch);
 	fprintf(log_fd, msg, nr);
+	fputc('\n', log_fd);
 	fflush(log_fd);
     }
 }
 
-    static void
+    void
 ch_logs(channel_T *ch, char *msg, char *name)
 {
     if (log_fd != NULL)
     {
 	ch_log_lead("", ch);
 	fprintf(log_fd, msg, name);
+	fputc('\n', log_fd);
 	fflush(log_fd);
     }
 }
@@ -153,6 +177,7 @@ ch_logsn(channel_T *ch, char *msg, char 
     {
 	ch_log_lead("", ch);
 	fprintf(log_fd, msg, name, nr);
+	fputc('\n', log_fd);
 	fflush(log_fd);
     }
 }
@@ -164,6 +189,7 @@ ch_error(channel_T *ch, char *msg)
     {
 	ch_log_lead("ERR ", ch);
 	fputs(msg, log_fd);
+	fputc('\n', log_fd);
 	fflush(log_fd);
     }
 }
@@ -175,6 +201,7 @@ ch_errorn(channel_T *ch, char *msg, int 
     {
 	ch_log_lead("ERR ", ch);
 	fprintf(log_fd, msg, nr);
+	fputc('\n', log_fd);
 	fflush(log_fd);
     }
 }
@@ -186,6 +213,7 @@ ch_errors(channel_T *ch, char *msg, char
     {
 	ch_log_lead("ERR ", ch);
 	fprintf(log_fd, msg, arg);
+	fputc('\n', log_fd);
 	fflush(log_fd);
     }
 }
@@ -253,7 +281,7 @@ add_channel(void)
 	return NULL;
 
     channel->ch_id = next_ch_id++;
-    ch_log(channel, "Created channel\n");
+    ch_log(channel, "Created channel");
 
 #ifdef CHANNEL_PIPES
     for (which = CHAN_SOCK; which <= CHAN_IN; ++which)
@@ -470,14 +498,17 @@ static char *e_cannot_connect = N_("E902
     channel_T *
 channel_open(char *hostname, int port_in, int waittime, void (*close_cb)(void))
 {
-    int			sd;
+    int			sd = -1;
     struct sockaddr_in	server;
-    struct hostent *	host;
+    struct hostent	*host;
 #ifdef WIN32
     u_short		port = port_in;
     u_long		val = 1;
 #else
     int			port = port_in;
+    struct timeval	start_tv;
+    int			so_error;
+    socklen_t		so_error_len = sizeof(so_error);
 #endif
     channel_T		*channel;
     int			ret;
@@ -489,16 +520,7 @@ channel_open(char *hostname, int port_in
     channel = add_channel();
     if (channel == NULL)
     {
-	ch_error(NULL, "Cannot allocate channel.\n");
-	EMSG(_("E897: All channels are in use"));
-	return NULL;
-    }
-
-    if ((sd = socket(AF_INET, SOCK_STREAM, 0)) == -1)
-    {
-	ch_error(channel, "in socket() in channel_open().\n");
-	PERROR("E898: socket() in channel_open()");
-	channel_free(channel);
+	ch_error(NULL, "Cannot allocate channel.");
 	return NULL;
     }
 
@@ -509,115 +531,185 @@ channel_open(char *hostname, int port_in
     server.sin_port = htons(port);
     if ((host = gethostbyname(hostname)) == NULL)
     {
-	ch_error(channel, "in gethostbyname() in channel_open()\n");
+	ch_error(channel, "in gethostbyname() in channel_open()");
 	PERROR("E901: gethostbyname() in channel_open()");
-	sock_close(sd);
 	channel_free(channel);
 	return NULL;
     }
     memcpy((char *)&server.sin_addr, host->h_addr, host->h_length);
 
-    if (waittime >= 0)
+#if defined(__APPLE__) && __APPLE__ == 1
+    /* On Mac a zero timeout almost never works.  At least wait one
+     * millisecond. */
+    if (waittime == 0)
+	waittime = 1;
+#endif
+
+    /*
+     * For Unix we need to call connect() again after connect() failed.
+     * On Win32 one time is sufficient.
+     */
+    while (TRUE)
     {
-	/* Make connect non-blocking. */
-	if (
-#ifdef _WIN32
-	    ioctlsocket(sd, FIONBIO, &val) < 0
-#else
-	    fcntl(sd, F_SETFL, O_NONBLOCK) < 0
-#endif
-	   )
-	{
-	    SOCK_ERRNO;
-	    ch_errorn(channel, "channel_open: Connect failed with errno %d\n",
-								       errno);
+	if (sd >= 0)
 	    sock_close(sd);
-	    channel_free(channel);
-	    return NULL;
-	}
-    }
-
-    /* Try connecting to the server. */
-    ch_logsn(channel, "Connecting to %s port %d\n", hostname, port);
-    ret = connect(sd, (struct sockaddr *)&server, sizeof(server));
-    SOCK_ERRNO;
-    if (ret < 0)
-    {
-	if (errno != EWOULDBLOCK
-#ifdef EINPROGRESS
-		    && errno != EINPROGRESS
-#endif
-		)
+	sd = socket(AF_INET, SOCK_STREAM, 0);
+	if (sd == -1)
 	{
-	    ch_errorn(channel, "channel_open: Connect failed with errno %d\n",
-								       errno);
-	    PERROR(_(e_cannot_connect));
-	    sock_close(sd);
+	    ch_error(channel, "in socket() in channel_open().");
+	    PERROR("E898: socket() in channel_open()");
 	    channel_free(channel);
 	    return NULL;
 	}
-    }
+
+	if (waittime >= 0)
+	{
+	    /* Make connect() non-blocking. */
+	    if (
+#ifdef _WIN32
+		ioctlsocket(sd, FIONBIO, &val) < 0
+#else
+		fcntl(sd, F_SETFL, O_NONBLOCK) < 0
+#endif
+	       )
+	    {
+		SOCK_ERRNO;
+		ch_errorn(channel,
+			 "channel_open: Connect failed with errno %d", errno);
+		sock_close(sd);
+		channel_free(channel);
+		return NULL;
+	    }
+	}
+
+	/* Try connecting to the server. */
+	ch_logsn(channel, "Connecting to %s port %d", hostname, port);
+	ret = connect(sd, (struct sockaddr *)&server, sizeof(server));
 
-    if (waittime >= 0 && ret < 0)
-    {
-	struct timeval	tv;
-	fd_set		wfds;
+	SOCK_ERRNO;
+	if (ret < 0)
+	{
+	    if (errno != EWOULDBLOCK
+		    && errno != ECONNREFUSED
+
+#ifdef EINPROGRESS
+		    && errno != EINPROGRESS
+#endif
+		    )
+	    {
+		ch_errorn(channel,
+			"channel_open: Connect failed with errno %d", errno);
+		PERROR(_(e_cannot_connect));
+		sock_close(sd);
+		channel_free(channel);
+		return NULL;
+	    }
+	}
+
+	/* If we don't block and connect() failed then try using select() to
+	 * wait for the connection to be made. */
+	if (waittime >= 0 && ret < 0)
+	{
+	    struct timeval	tv;
+	    fd_set		wfds;
 #if defined(__APPLE__) && __APPLE__ == 1
 # define PASS_RFDS
-	fd_set          rfds;
+	    fd_set          rfds;
 
-	FD_ZERO(&rfds);
-	FD_SET(sd, &rfds);
-	/* On Mac a zero timeout almost never works.  At least wait one
-	 * millisecond. */
-	if (waittime == 0)
-	    waittime = 1;
+	    FD_ZERO(&rfds);
+	    FD_SET(sd, &rfds);
 #endif
-	FD_ZERO(&wfds);
-	FD_SET(sd, &wfds);
-	tv.tv_sec = waittime / 1000;
-	tv.tv_usec = (waittime % 1000) * 1000;
+	    FD_ZERO(&wfds);
+	    FD_SET(sd, &wfds);
 
-	ch_logn(channel, "Waiting for connection (timeout %d msec)...\n",
-								    waittime);
-	ret = select((int)sd + 1,
+	    tv.tv_sec = waittime / 1000;
+	    tv.tv_usec = (waittime % 1000) * 1000;
+#ifndef WIN32
+	    gettimeofday(&start_tv, NULL);
+#endif
+	    ch_logn(channel,
+		    "Waiting for connection (waittime %d msec)...", waittime);
+	    ret = select((int)sd + 1,
 #ifdef PASS_RFDS
-		&rfds,
+		    &rfds,
 #else
-		NULL,
+		    NULL,
 #endif
-		&wfds, NULL, &tv);
+		    &wfds, NULL, &tv);
 
-	if (ret < 0)
-	{
-	    SOCK_ERRNO;
-	    ch_errorn(channel, "channel_open: Connect failed with errno %d\n",
-								       errno);
-	    PERROR(_(e_cannot_connect));
-	    sock_close(sd);
-	    channel_free(channel);
-	    return NULL;
-	}
+	    if (ret < 0)
+	    {
+		SOCK_ERRNO;
+		ch_errorn(channel,
+			"channel_open: Connect failed with errno %d", errno);
+		PERROR(_(e_cannot_connect));
+		sock_close(sd);
+		channel_free(channel);
+		return NULL;
+	    }
 #ifdef PASS_RFDS
-	if (ret == 0 && FD_ISSET(sd, &rfds) && FD_ISSET(sd, &wfds))
-	{
-	    /* For OS X, this implies error. See tcp(4). */
-	    ch_error(channel, "channel_open: Connect failed\n");
-	    EMSG(_(e_cannot_connect));
-	    sock_close(sd);
-	    channel_free(channel);
-	    return NULL;
-	}
+	    if (ret == 0 && FD_ISSET(sd, &rfds) && FD_ISSET(sd, &wfds))
+	    {
+		/* For OS X, this implies error. See tcp(4). */
+		ch_error(channel, "channel_open: Connect failed");
+		EMSG(_(e_cannot_connect));
+		sock_close(sd);
+		channel_free(channel);
+		return NULL;
+	    }
+#endif
+#ifdef WIN32
+	    /* On Win32 select() is expected to work and wait for up to the
+	     * waittime for the socket to be open. */
+	    if (!FD_ISSET(sd, &wfds) || ret == 0)
+#else
+	    /* See socket(7) for the behavior on Linux-like systems:
+	     * After putting the socket in non-blocking mode, connect() will
+	     * return EINPROGRESS, select() will not wait (as if writing is
+	     * possible), need to use getsockopt() to check if the socket is
+	     * actually open. */
+	    getsockopt(sd, SOL_SOCKET, SO_ERROR, &so_error, &so_error_len);
+	    if (!FD_ISSET(sd, &wfds) || ret == 0 || so_error != 0)
 #endif
-	if (!FD_ISSET(sd, &wfds))
-	{
-	    /* don't give an error, we just timed out. */
-	    ch_error(channel, "Connection timed out\n");
-	    sock_close(sd);
-	    channel_free(channel);
-	    return NULL;
+	    {
+#ifndef WIN32
+		struct  timeval end_tv;
+		long    elapsed_msec;
+
+		gettimeofday(&end_tv, NULL);
+		elapsed_msec = (end_tv.tv_sec - start_tv.tv_sec) * 1000
+				 + (end_tv.tv_usec - start_tv.tv_usec) / 1000;
+		if (waittime > 1 && elapsed_msec < waittime)
+		{
+		    /* The port isn't ready but we also didn't get an error.
+		     * This happens when the server didn't open the socket
+		     * yet.  Wait a bit and try again. */
+		    mch_delay(waittime < 50 ? (long)waittime : 50L, TRUE);
+		    ui_breakcheck();
+		    if (!got_int)
+		    {
+			/* reduce the waittime by the elapsed time and the 50
+			 * msec delay (or a bit more) */
+			waittime -= elapsed_msec;
+			if (waittime > 50)
+			    waittime -= 50;
+			else
+			    waittime = 1;
+			continue;
+		    }
+		    /* we were interrupted, behave as if timed out */
+		}
+#endif
+		/* We timed out. */
+		ch_error(channel, "Connection timed out");
+		sock_close(sd);
+		channel_free(channel);
+		return NULL;
+	    }
+
+	    ch_log(channel, "Connection made");
+	    break;
 	}
-	ch_log(channel, "Connection made\n");
     }
 
     if (waittime >= 0)
@@ -630,55 +722,6 @@ channel_open(char *hostname, int port_in
 #endif
     }
 
-    /* Only retry for netbeans.  TODO: can we use a waittime instead? */
-    if (errno == ECONNREFUSED && close_cb != NULL)
-    {
-	sock_close(sd);
-	if ((sd = socket(AF_INET, SOCK_STREAM, 0)) == -1)
-	{
-	    SOCK_ERRNO;
-	    ch_log(channel, "socket() retry in channel_open()\n");
-	    PERROR("E900: socket() retry in channel_open()");
-	    channel_free(channel);
-	    return NULL;
-	}
-	if (connect(sd, (struct sockaddr *)&server, sizeof(server)))
-	{
-	    int retries = 36;
-	    int success = FALSE;
-
-	    SOCK_ERRNO;
-	    while (retries-- && ((errno == ECONNREFUSED)
-						     || (errno == EINTR)))
-	    {
-		ch_log(channel, "retrying...\n");
-		mch_delay(3000L, TRUE);
-		ui_breakcheck();
-		if (got_int)
-		{
-		    errno = EINTR;
-		    break;
-		}
-		if (connect(sd, (struct sockaddr *)&server,
-						     sizeof(server)) == 0)
-		{
-		    success = TRUE;
-		    break;
-		}
-		SOCK_ERRNO;
-	    }
-	    if (!success)
-	    {
-		/* Get here when the server can't be found. */
-		ch_error(channel, "Cannot connect to port after retry\n");
-		PERROR(_("E899: Cannot connect to port after retry"));
-		sock_close(sd);
-		channel_free(channel);
-		return NULL;
-	    }
-	}
-    }
-
     channel->CH_SOCK = (sock_T)sd;
     channel->ch_close_cb = close_cb;
 
@@ -1155,7 +1198,7 @@ may_invoke_callback(channel_T *channel)
 	if (typetv->v_type != VAR_NUMBER)
 	{
 	    ch_error(channel,
-		      "Dropping message with invalid sequence number type\n");
+		      "Dropping message with invalid sequence number type");
 	    free_tv(listtv);
 	    return FALSE;
 	}
@@ -1223,7 +1266,7 @@ may_invoke_callback(channel_T *channel)
 	{
 	    if (item->cq_seq_nr == seq_nr)
 	    {
-		ch_log(channel, "Invoking one-time callback\n");
+		ch_log(channel, "Invoking one-time callback");
 		/* Remove the item from the list first, if the callback
 		 * invokes ch_close() the list will be cleared. */
 		remove_cb_node(head, item);
@@ -1236,16 +1279,16 @@ may_invoke_callback(channel_T *channel)
 	    item = item->cq_next;
 	}
 	if (!done)
-	    ch_log(channel, "Dropping message without callback\n");
+	    ch_log(channel, "Dropping message without callback");
     }
     else if (channel->ch_callback != NULL)
     {
 	/* invoke the channel callback */
-	ch_log(channel, "Invoking channel callback\n");
+	ch_log(channel, "Invoking channel callback");
 	invoke_callback(channel, channel->ch_callback, argv);
     }
     else
-	ch_log(channel, "Dropping message\n");
+	ch_log(channel, "Dropping message");
 
     if (listtv != NULL)
 	free_tv(listtv);
@@ -1304,7 +1347,7 @@ channel_status(channel_T *channel)
     void
 channel_close(channel_T *channel)
 {
-    ch_log(channel, "Closing channel\n");
+    ch_log(channel, "Closing channel");
 
 #ifdef FEAT_GUI
     channel_gui_unregister(channel);
@@ -1471,7 +1514,7 @@ channel_wait(channel_T *channel, sock_T 
     int			ret;
 
     if (timeout > 0)
-	ch_logn(channel, "Waiting for up to %d msec\n", timeout);
+	ch_logn(channel, "Waiting for up to %d msec", timeout);
 
 
 # ifdef WIN32
@@ -1511,7 +1554,7 @@ channel_wait(channel_T *channel, sock_T 
 # endif
 	if (ret <= 0)
 	{
-	    ch_log(channel, "Nothing to read\n");
+	    ch_log(channel, "Nothing to read");
 	    return FAIL;
 	}
 	break;
@@ -1521,12 +1564,12 @@ channel_wait(channel_T *channel, sock_T 
     struct pollfd	fds;
 
     if (timeout > 0)
-	ch_logn(channel, "Waiting for %d msec\n", timeout);
+	ch_logn(channel, "Waiting for %d msec", timeout);
     fds.fd = fd;
     fds.events = POLLIN;
     if (poll(&fds, 1, timeout) <= 0)
     {
-	ch_log(channel, "Nothing to read\n");
+	ch_log(channel, "Nothing to read");
 	return FAIL;
     }
 # endif
@@ -1558,7 +1601,7 @@ get_read_fd(channel_T *channel)
     if (channel->CH_OUT != CHAN_FD_INVALID)
 	return channel->CH_OUT;
 #endif
-    ch_error(channel, "channel_read() called while socket is closed\n");
+    ch_error(channel, "channel_read() called while socket is closed");
     return CHAN_FD_INVALID;
 }
 
@@ -1637,7 +1680,7 @@ channel_read(channel_T *channel, int whi
 	 *		    -> gui event loop or select loop
 	 *			-> channel_read()
 	 */
-	ch_errors(channel, "%s(): Cannot read\n", func);
+	ch_errors(channel, "%s(): Cannot read", func);
 	channel_save(channel, (char_u *)DETACH_MSG, (int)STRLEN(DETACH_MSG));
 
 	/* TODO: When reading from stdout is not possible, should we try to
@@ -1649,7 +1692,7 @@ channel_read(channel_T *channel, int whi
 
 	if (len < 0)
 	{
-	    ch_error(channel, "channel_read(): cannot read from channel\n");
+	    ch_error(channel, "channel_read(): cannot read from channel");
 	    PERROR(_("E896: read from channel"));
 	}
     }
@@ -1677,7 +1720,7 @@ channel_read_block(channel_T *channel)
     sock_T	fd = get_read_fd(channel);
     char_u	*nl;
 
-    ch_logsn(channel, "Blocking %s read, timeout: %d msec\n",
+    ch_logsn(channel, "Blocking %s read, timeout: %d msec",
 			mode == MODE_RAW ? "RAW" : "NL", channel->ch_timeout);
 
     while (TRUE)
@@ -1718,7 +1761,7 @@ channel_read_block(channel_T *channel)
 	}
     }
     if (log_fd != NULL)
-	ch_logn(channel, "Returning %d bytes\n", (int)STRLEN(msg));
+	ch_logn(channel, "Returning %d bytes", (int)STRLEN(msg));
     return msg;
 }
 
@@ -1733,7 +1776,7 @@ channel_read_json_block(channel_T *chann
     int		more;
     sock_T	fd;
 
-    ch_log(channel, "Reading JSON\n");
+    ch_log(channel, "Reading JSON");
     channel->ch_block_id = id;
     for (;;)
     {
@@ -1821,7 +1864,7 @@ channel_send(channel_T *channel, char_u 
     {
 	if (!channel->ch_error && fun != NULL)
 	{
-	    ch_errors(channel, "%s(): write while not connected\n", fun);
+	    ch_errors(channel, "%s(): write while not connected", fun);
 	    EMSG2("E630: %s(): write while not connected", fun);
 	}
 	channel->ch_error = TRUE;
@@ -1845,7 +1888,7 @@ channel_send(channel_T *channel, char_u 
     {
 	if (!channel->ch_error && fun != NULL)
 	{
-	    ch_errors(channel, "%s(): write failed\n", fun);
+	    ch_errors(channel, "%s(): write failed", fun);
 	    EMSG2("E631: %s(): write failed", fun);
 	}
 	channel->ch_error = TRUE;
--- a/src/eval.c
+++ b/src/eval.c
@@ -504,6 +504,7 @@ static void f_ceil(typval_T *argvars, ty
 #endif
 #ifdef FEAT_CHANNEL
 static void f_ch_close(typval_T *argvars, typval_T *rettv);
+static void f_ch_log(typval_T *argvars, typval_T *rettv);
 static void f_ch_logfile(typval_T *argvars, typval_T *rettv);
 static void f_ch_open(typval_T *argvars, typval_T *rettv);
 static void f_ch_readraw(typval_T *argvars, typval_T *rettv);
@@ -8124,6 +8125,7 @@ static struct fst
 #endif
 #ifdef FEAT_CHANNEL
     {"ch_close",	1, 1, f_ch_close},
+    {"ch_log",		1, 2, f_ch_log},
     {"ch_logfile",	1, 2, f_ch_logfile},
     {"ch_open",		1, 2, f_ch_open},
     {"ch_readraw",	1, 2, f_ch_readraw},
@@ -9950,6 +9952,21 @@ f_ch_close(typval_T *argvars, typval_T *
 }
 
 /*
+ * "ch_log()" function
+ */
+    static void
+f_ch_log(typval_T *argvars, typval_T *rettv UNUSED)
+{
+    char_u	*msg = get_tv_string(&argvars[0]);
+    channel_T	*channel = NULL;
+
+    if (argvars[1].v_type != VAR_UNKNOWN)
+	channel = get_channel_arg(&argvars[1]);
+
+    ch_log(channel, (char *)msg);
+}
+
+/*
  * "ch_logfile()" function
  */
     static void
@@ -14603,9 +14620,30 @@ f_job_start(typval_T *argvars UNUSED, ty
 	cmd = ga.ga_data;
 #endif
     }
+
 #ifdef USE_ARGV
+# ifdef FEAT_CHANNEL
+    if (ch_log_active())
+    {
+	garray_T    ga;
+	int	    i;
+
+	ga_init2(&ga, (int)sizeof(char), 200);
+	for (i = 0; i < argc; ++i)
+	{
+	    if (i > 0)
+		ga_concat(&ga, (char_u *)"  ");
+	    ga_concat(&ga, (char_u *)argv[i]);
+	}
+	ch_logs(NULL, "Starting job: %s", ga.ga_data);
+	ga_clear(&ga);
+    }
+# endif
     mch_start_job(argv, job, &options);
 #else
+# ifdef FEAT_CHANNEL
+    ch_logs(NULL, "Starting job: %s", cmd);
+# endif
     mch_start_job((char *)cmd, job, &options);
 #endif
 
--- a/src/netbeans.c
+++ b/src/netbeans.c
@@ -213,7 +213,7 @@ netbeans_connect(char *params, int doabo
     if (hostname != NULL && address != NULL && password != NULL)
     {
 	port = atoi(address);
-	nb_channel = channel_open(hostname, port, 0, nb_channel_closed);
+	nb_channel = channel_open(hostname, port, 3000, nb_channel_closed);
 	if (nb_channel != NULL)
 	{
 	    /* success */
--- a/src/proto/channel.pro
+++ b/src/proto/channel.pro
@@ -1,5 +1,8 @@
 /* channel.c */
 void ch_logfile(FILE *file);
+int ch_log_active(void);
+void ch_log(channel_T *ch, char *msg);
+void ch_logs(channel_T *ch, char *msg, char *name);
 channel_T *add_channel(void);
 void channel_free(channel_T *channel);
 void channel_gui_register(channel_T *channel);
--- a/src/testdir/test_channel.py
+++ b/src/testdir/test_channel.py
@@ -9,6 +9,7 @@ from __future__ import print_function
 import json
 import socket
 import sys
+import time
 import threading
 
 try:
@@ -158,9 +159,25 @@ class ThreadedTCPRequestHandler(socketse
 class ThreadedTCPServer(socketserver.ThreadingMixIn, socketserver.TCPServer):
     pass
 
+def writePortInFile(port):
+    # Write the port number in Xportnr, so that the test knows it.
+    f = open("Xportnr", "w")
+    f.write("{}".format(port))
+    f.close()
+
 if __name__ == "__main__":
     HOST, PORT = "localhost", 0
 
+    # Wait half a second before opening the port to test waittime in ch_open().
+    # We do want to get the port number, get that first.  We cannot open the
+    # socket, guess a port is free.
+    if len(sys.argv) >= 2 and sys.argv[1] == 'delay':
+        PORT = 13684
+        writePortInFile(PORT)
+
+        print("Wait for it...")
+        time.sleep(0.5)
+
     server = ThreadedTCPServer((HOST, PORT), ThreadedTCPRequestHandler)
     ip, port = server.server_address
 
@@ -169,10 +186,7 @@ if __name__ == "__main__":
     server_thread = threading.Thread(target=server.serve_forever)
     server_thread.start()
 
-    # Write the port number in Xportnr, so that the test knows it.
-    f = open("Xportnr", "w")
-    f.write("{}".format(port))
-    f.close()
+    writePortInFile(port)
 
     print("Listening on port {}".format(port))
 
--- a/src/testdir/test_channel.vim
+++ b/src/testdir/test_channel.vim
@@ -31,17 +31,24 @@ endif
 let s:chopt = {}
 
 " Run "testfunc" after sarting the server and stop the server afterwards.
-func s:run_server(testfunc)
+func s:run_server(testfunc, ...)
   " The Python program writes the port number in Xportnr.
   call delete("Xportnr")
 
+  if a:0 == 1
+    let arg = ' ' . a:1
+  else
+    let arg = ''
+  endif
+  let cmd = s:python . " test_channel.py" . arg
+
   try
     if has('job')
-      let s:job = job_start(s:python . " test_channel.py")
+      let s:job = job_start(cmd)
     elseif has('win32')
-      exe 'silent !start cmd /c start "test_channel" ' . s:python . ' test_channel.py'
+      exe 'silent !start cmd /c start "test_channel" ' . cmd
     else
-      exe 'silent !' . s:python . ' test_channel.py&'
+      exe 'silent !' . cmd . '&'
     endif
 
     " Wait for up to 2 seconds for the port number to be there.
@@ -175,6 +182,7 @@ func s:communicate(port)
 endfunc
 
 func Test_communicate()
+  call ch_log('Test_communicate()')
   call s:run_server('s:communicate')
 endfunc
 
@@ -203,6 +211,7 @@ func s:two_channels(port)
 endfunc
 
 func Test_two_channels()
+  call ch_log('Test_two_channels()')
   call s:run_server('s:two_channels')
 endfunc
 
@@ -220,6 +229,7 @@ func s:server_crash(port)
 endfunc
 
 func Test_server_crash()
+  call ch_log('Test_server_crash()')
   call s:run_server('s:server_crash')
 endfunc
 
@@ -248,6 +258,7 @@ func s:channel_handler(port)
 endfunc
 
 func Test_channel_handler()
+  call ch_log('Test_channel_handler()')
   let s:chopt.callback = 's:Handler'
   call s:run_server('s:channel_handler')
   let s:chopt.callback = function('s:Handler')
@@ -261,9 +272,10 @@ func Test_connect_waittime()
     " TODO: Make this work again for MS-Windows.
     return
   endif
+  call ch_log('Test_connect_waittime()')
   let start = reltime()
   let handle = ch_open('localhost:9876', s:chopt)
-  if ch_status(handle) == "fail"
+  if ch_status(handle) != "fail"
     " Oops, port does exists.
     call ch_close(handle)
   else
@@ -272,7 +284,7 @@ func Test_connect_waittime()
   endif
 
   let start = reltime()
-  let handle = ch_open('localhost:9867', {'waittime': 2000})
+  let handle = ch_open('localhost:9867', {'waittime': 500})
   if ch_status(handle) != "fail"
     " Oops, port does exists.
     call ch_close(handle)
@@ -280,7 +292,7 @@ func Test_connect_waittime()
     " Failed connection doesn't wait the full time on Unix.
     " TODO: why is MS-Windows different?
     let elapsed = reltime(start)
-    call assert_true(reltimefloat(elapsed) < (has('unix') ? 1.0 : 3.0))
+    call assert_true(reltimefloat(elapsed) < 1.0)
   endif
 endfunc
 
@@ -288,6 +300,7 @@ func Test_raw_pipe()
   if !has('job')
     return
   endif
+  call ch_log('Test_raw_pipe()')
   let job = job_start(s:python . " test_channel_pipe.py", {'mode': 'raw'})
   call assert_equal("run", job_status(job))
   try
@@ -311,6 +324,7 @@ func Test_nl_pipe()
   if !has('job')
     return
   endif
+  call ch_log('Test_nl_pipe()')
   let job = job_start(s:python . " test_channel_pipe.py")
   call assert_equal("run", job_status(job))
   try
@@ -346,6 +360,7 @@ func s:unlet_handle(port)
 endfunc
 
 func Test_unlet_handle()
+  call ch_log('Test_unlet_handle()')
   call s:run_server('s:unlet_handle')
 endfunc
 
@@ -366,13 +381,36 @@ func s:close_handle(port)
 endfunc
 
 func Test_close_handle()
+  call ch_log('Test_close_handle()')
   call s:run_server('s:close_handle')
 endfunc
 
 """"""""""
 
 func Test_open_fail()
+  call ch_log('Test_open_fail()')
   silent! let ch = ch_open("noserver")
   echo ch
   let d = ch
 endfunc
+
+""""""""""
+
+func s:open_delay(port)
+  " Wait up to a second for the port to open.
+  let s:chopt.waittime = 1000
+  let channel = ch_open('localhost:' . a:port, s:chopt)
+  unlet s:chopt.waittime
+  if ch_status(channel) == "fail"
+    call assert_false(1, "Can't open channel")
+    return
+  endif
+  call assert_equal('got it', ch_sendexpr(channel, 'hello!'))
+  call ch_close(channel)
+endfunc
+
+func Test_open_delay()
+  call ch_log('Test_open_delay()')
+  " The server will wait half a second before creating the port.
+  call s:run_server('s:open_delay', 'delay')
+endfunc
--- a/src/version.c
+++ b/src/version.c
@@ -748,6 +748,8 @@ static char *(features[]) =
 static int included_patches[] =
 {   /* Add new patch number below this line */
 /**/
+    1351,
+/**/
     1350,
 /**/
     1349,