Mercurial > vim
diff src/channel.c @ 8114:4aea0b0aa714 v7.4.1351
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 | 882ba5080c5c |
children | 39532ee7dd43 |
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;