To: vim_dev@googlegroups.com Subject: Patch 7.4.1617 Fcc: outbox From: Bram Moolenaar Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ------------ Patch 7.4.1617 Problem: When a JSON message is split it isn't decoded. Solution: Wait a short time for the rest of the message to arrive. Files: src/channel.c, src/json.c, src/structs.h, src/testdir/test_channel.vim, src/testdir/test_channel.py *** ../vim-7.4.1616/src/channel.c 2016-03-20 14:30:56.166394212 +0100 --- src/channel.c 2016-03-20 16:35:38.313536068 +0100 *************** *** 1362,1368 **** * Returns OK or FAIL. */ static int ! channel_save(channel_T *channel, int part, char_u *buf, int len) { readq_T *node; readq_T *head = &channel->ch_part[part].ch_head; --- 1362,1368 ---- * Returns OK or FAIL. */ static int ! channel_save(channel_T *channel, int part, char_u *buf, int len, char *lead) { readq_T *node; readq_T *head = &channel->ch_part[part].ch_head; *************** *** 1403,1411 **** head->rq_prev->rq_next = node; head->rq_prev = node; ! if (log_fd != NULL) { ! ch_log_lead("RECV ", channel); fprintf(log_fd, "'"); if (fwrite(buf, len, 1, log_fd) != 1) return FAIL; --- 1403,1411 ---- head->rq_prev->rq_next = node; head->rq_prev = node; ! if (log_fd != NULL && lead != NULL) { ! ch_log_lead(lead, channel); fprintf(log_fd, "'"); if (fwrite(buf, len, 1, log_fd) != 1) return FAIL; *************** *** 1415,1421 **** } /* ! * Use the read buffer of "channel"/"part" and parse a JSON messages that is * complete. The messages are added to the queue. * Return TRUE if there is more to read. */ --- 1415,1421 ---- } /* ! * Use the read buffer of "channel"/"part" and parse a JSON message that is * complete. The messages are added to the queue. * Return TRUE if there is more to read. */ *************** *** 1425,1431 **** js_read_T reader; typval_T listtv; jsonq_T *item; ! jsonq_T *head = &channel->ch_part[part].ch_json_head; int ret; if (channel_peek(channel, part) == NULL) --- 1425,1433 ---- js_read_T reader; typval_T listtv; jsonq_T *item; ! chanpart_T *chanpart = &channel->ch_part[part]; ! jsonq_T *head = &chanpart->ch_json_head; ! int status; int ret; if (channel_peek(channel, part) == NULL) *************** *** 1438,1452 **** reader.js_fill = NULL; /* reader.js_fill = channel_fill; */ reader.js_cookie = channel; ! ret = json_decode(&reader, &listtv, ! channel->ch_part[part].ch_mode == MODE_JS ? JSON_JS : 0); ! if (ret == OK) { /* Only accept the response when it is a list with at least two * items. */ if (listtv.v_type != VAR_LIST || listtv.vval.v_list->lv_len < 2) { ! /* TODO: give error */ clear_tv(&listtv); } else --- 1440,1462 ---- reader.js_fill = NULL; /* reader.js_fill = channel_fill; */ reader.js_cookie = channel; ! ! /* When a message is incomplete we wait for a short while for more to ! * arrive. After the delay drop the input, otherwise a truncated string ! * or list will make us hang. */ ! status = json_decode(&reader, &listtv, ! chanpart->ch_mode == MODE_JS ? JSON_JS : 0); ! if (status == OK) { /* Only accept the response when it is a list with at least two * items. */ if (listtv.v_type != VAR_LIST || listtv.vval.v_list->lv_len < 2) { ! if (listtv.v_type != VAR_LIST) ! ch_error(channel, "Did not receive a list, discarding"); ! else ! ch_errorn(channel, "Expected list with two items, got %d", ! listtv.vval.v_list->lv_len); clear_tv(&listtv); } else *************** *** 1477,1498 **** } } ! /* Put the unread part back into the channel. ! * TODO: insert in front */ ! if (reader.js_buf[reader.js_used] != NUL) ! { ! if (ret == FAIL) ! { ! ch_error(channel, "Decoding failed - discarding input"); ! ret = FALSE; } else { ! channel_save(channel, part, reader.js_buf + reader.js_used, ! (int)(reader.js_end - reader.js_buf) - reader.js_used); ! ret = TRUE; } } else ret = FALSE; --- 1487,1557 ---- } } ! if (status == OK) ! chanpart->ch_waiting = FALSE; ! else if (status == MAYBE) ! { ! if (!chanpart->ch_waiting) ! { ! /* First time encountering incomplete message, set a deadline of ! * 100 msec. */ ! ch_log(channel, "Incomplete message - wait for more"); ! reader.js_used = 0; ! chanpart->ch_waiting = TRUE; ! #ifdef WIN32 ! chanpart->ch_deadline = GetTickCount() + 100L; ! #else ! gettimeofday(&chanpart->ch_deadline, NULL); ! chanpart->ch_deadline.tv_usec += 100 * 1000; ! if (chanpart->ch_deadline.tv_usec > 1000 * 1000) ! { ! chanpart->ch_deadline.tv_usec -= 1000 * 1000; ! ++chanpart->ch_deadline.tv_sec; ! } ! #endif } else { ! int timeout; ! #ifdef WIN32 ! timeout = GetTickCount() > chanpart->ch_deadline; ! #else ! { ! struct timeval now_tv; ! ! gettimeofday(&now_tv, NULL); ! timeout = now_tv.tv_sec > chanpart->ch_deadline.tv_sec ! || (now_tv.tv_sec == chanpart->ch_deadline.tv_sec ! && now_tv.tv_usec > chanpart->ch_deadline.tv_usec); ! } ! #endif ! if (timeout) ! { ! status = FAIL; ! chanpart->ch_waiting = FALSE; ! } ! else ! { ! reader.js_used = 0; ! ch_log(channel, "still waiting on incomplete message"); ! } } } + + if (status == FAIL) + { + ch_error(channel, "Decoding failed - discarding input"); + ret = FALSE; + chanpart->ch_waiting = FALSE; + } + else if (reader.js_buf[reader.js_used] != NUL) + { + /* Put the unread part back into the channel. + * TODO: insert in front */ + channel_save(channel, part, reader.js_buf + reader.js_used, + (int)(reader.js_end - reader.js_buf) - reader.js_used, NULL); + ret = status == MAYBE ? FALSE: TRUE; + } else ret = FALSE; *************** *** 1559,1564 **** --- 1618,1625 ---- || tv->vval.v_number != channel->ch_part[part].ch_block_id))) { *rettv = item->jq_value; + if (tv->v_type == VAR_NUMBER) + ch_logn(channel, "Getting JSON message %d", tv->vval.v_number); remove_json_node(head, item); return OK; } *************** *** 2289,2295 **** break; /* error or nothing more to read */ /* Store the read message in the queue. */ ! channel_save(channel, part, buf, len); readlen += len; if (len < MAXMSGSIZE) break; /* did read everything that's available */ --- 2350,2356 ---- break; /* error or nothing more to read */ /* Store the read message in the queue. */ ! channel_save(channel, part, buf, len, "RECV "); readlen += len; if (len < MAXMSGSIZE) break; /* did read everything that's available */ *************** *** 2316,2322 **** if (channel->ch_part[part].ch_mode == MODE_RAW || channel->ch_part[part].ch_mode == MODE_NL) channel_save(channel, part, (char_u *)DETACH_MSG_RAW, ! (int)STRLEN(DETACH_MSG_RAW)); /* TODO: When reading from stdout is not possible, should we try to * keep stdin and stderr open? Probably not, assume the other side --- 2377,2383 ---- if (channel->ch_part[part].ch_mode == MODE_RAW || channel->ch_part[part].ch_mode == MODE_NL) channel_save(channel, part, (char_u *)DETACH_MSG_RAW, ! (int)STRLEN(DETACH_MSG_RAW), "PUT "); /* TODO: When reading from stdout is not possible, should we try to * keep stdin and stderr open? Probably not, assume the other side *************** *** 2361,2369 **** continue; /* Wait for up to the channel timeout. */ ! if (fd == INVALID_FD ! || channel_wait(channel, fd, timeout) == FAIL) return NULL; channel_read(channel, part, "channel_read_block"); } --- 2422,2434 ---- continue; /* Wait for up to the channel timeout. */ ! if (fd == INVALID_FD) return NULL; + if (channel_wait(channel, fd, timeout) == FAIL) + { + ch_log(channel, "Timed out"); + return NULL; + } channel_read(channel, part, "channel_read_block"); } *************** *** 2403,2418 **** channel_read_json_block( channel_T *channel, int part, ! int timeout, int id, typval_T **rettv) { int more; sock_T fd; ch_log(channel, "Reading JSON"); if (id != -1) ! channel->ch_part[part].ch_block_id = id; for (;;) { more = channel_parse_json(channel, part); --- 2468,2485 ---- channel_read_json_block( channel_T *channel, int part, ! int timeout_arg, int id, typval_T **rettv) { int more; sock_T fd; + int timeout; + chanpart_T *chanpart = &channel->ch_part[part]; ch_log(channel, "Reading JSON"); if (id != -1) ! chanpart->ch_block_id = id; for (;;) { more = channel_parse_json(channel, part); *************** *** 2420,2426 **** /* search for messsage "id" */ if (channel_get_json(channel, part, id, rettv) == OK) { ! channel->ch_part[part].ch_block_id = 0; return OK; } --- 2487,2493 ---- /* search for messsage "id" */ if (channel_get_json(channel, part, id, rettv) == OK) { ! chanpart->ch_block_id = 0; return OK; } *************** *** 2431,2444 **** if (channel_parse_messages()) continue; ! /* Wait for up to the timeout. */ ! fd = channel->ch_part[part].ch_fd; if (fd == INVALID_FD || channel_wait(channel, fd, timeout) == FAIL) ! break; ! channel_read(channel, part, "channel_read_json_block"); } } ! channel->ch_part[part].ch_block_id = 0; return FAIL; } --- 2498,2547 ---- if (channel_parse_messages()) continue; ! /* Wait for up to the timeout. If there was an incomplete message ! * use the deadline for that. */ ! timeout = timeout_arg; ! if (chanpart->ch_waiting) ! { ! #ifdef WIN32 ! timeout = chanpart->ch_deadline - GetTickCount() + 1; ! #else ! { ! struct timeval now_tv; ! ! gettimeofday(&now_tv, NULL); ! timeout = (chanpart->ch_deadline.tv_sec ! - now_tv.tv_sec) * 1000 ! + (chanpart->ch_deadline.tv_usec ! - now_tv.tv_usec) / 1000 ! + 1; ! } ! #endif ! if (timeout < 0) ! { ! /* Something went wrong, channel_parse_json() didn't ! * discard message. Cancel waiting. */ ! chanpart->ch_waiting = FALSE; ! timeout = timeout_arg; ! } ! else if (timeout > timeout_arg) ! timeout = timeout_arg; ! } ! fd = chanpart->ch_fd; if (fd == INVALID_FD || channel_wait(channel, fd, timeout) == FAIL) ! { ! if (timeout == timeout_arg) ! { ! if (fd != INVALID_FD) ! ch_log(channel, "Timed out"); ! break; ! } ! } ! else ! channel_read(channel, part, "channel_read_json_block"); } } ! chanpart->ch_block_id = 0; return FAIL; } *** ../vim-7.4.1616/src/json.c 2016-03-14 23:04:49.698923062 +0100 --- src/json.c 2016-03-20 15:00:41.492051749 +0100 *************** *** 877,884 **** /* * Decode the JSON from "reader" and store the result in "res". * "options" can be JSON_JS or zero; ! * Return FAIL if the message has a decoding error or the message is ! * truncated. Consumes the message anyway. */ int json_decode(js_read_T *reader, typval_T *res, int options) --- 877,885 ---- /* * Decode the JSON from "reader" and store the result in "res". * "options" can be JSON_JS or zero; ! * Return FAIL for a decoding error. ! * Return MAYBE for an incomplete message. ! * Consumes the message anyway. */ int json_decode(js_read_T *reader, typval_T *res, int options) *************** *** 891,897 **** ret = json_decode_item(reader, res, options); json_skip_white(reader); ! return ret == OK ? OK : FAIL; } /* --- 892,898 ---- ret = json_decode_item(reader, res, options); json_skip_white(reader); ! return ret; } /* *** ../vim-7.4.1616/src/structs.h 2016-03-19 22:11:47.436674835 +0100 --- src/structs.h 2016-03-20 15:28:25.947049408 +0100 *************** *** 1357,1362 **** --- 1357,1370 ---- jsonq_T ch_json_head; /* header for circular json read queue */ int ch_block_id; /* ID that channel_read_json_block() is waiting for */ + /* When ch_waiting is TRUE use ch_deadline to wait for incomplete message + * to be complete. */ + int ch_waiting; + #ifdef WIN32 + DWORD ch_deadline; + #else + struct timeval ch_deadline; + #endif cbq_T ch_cb_head; /* dummy node for per-request callbacks */ char_u *ch_callback; /* call when a msg is not handled */ *** ../vim-7.4.1616/src/testdir/test_channel.vim 2016-03-20 14:30:56.166394212 +0100 --- src/testdir/test_channel.vim 2016-03-20 16:40:25.030569128 +0100 *************** *** 127,133 **** call assert_equal('got it', ch_evalexpr(handle, 'hello!')) " Malformed command should be ignored. ! call assert_equal('ok', ch_evalexpr(handle, 'malformed')) " Request that triggers sending two ex commands. These will usually be " handled before getting the response, but it's not guaranteed, thus wait a --- 127,140 ---- call assert_equal('got it', ch_evalexpr(handle, 'hello!')) " Malformed command should be ignored. ! call assert_equal('ok', ch_evalexpr(handle, 'malformed1')) ! call assert_equal('ok', ch_evalexpr(handle, 'malformed2')) ! call assert_equal('ok', ch_evalexpr(handle, 'malformed3')) ! ! " split command should work ! call assert_equal('ok', ch_evalexpr(handle, 'split')) ! call s:waitFor('exists("g:split")') ! call assert_equal(123, g:split) " Request that triggers sending two ex commands. These will usually be " handled before getting the response, but it's not guaranteed, thus wait a *** ../vim-7.4.1616/src/testdir/test_channel.py 2016-03-20 14:30:56.166394212 +0100 --- src/testdir/test_channel.py 2016-03-20 16:23:44.052927109 +0100 *************** *** 104,114 **** print("sending: {}".format(cmd)) self.request.sendall(cmd.encode('utf-8')) response = "ok" ! elif decoded[1] == 'malformed': cmd = '["ex",":"]wrong!["ex","smi"]' print("sending: {}".format(cmd)) self.request.sendall(cmd.encode('utf-8')) response = "ok" elif decoded[1] == 'an expr': # Send an expr request. cmd = '["expr","setline(\\"$\\", [\\"one\\",\\"two\\",\\"three\\"])"]' --- 104,139 ---- print("sending: {}".format(cmd)) self.request.sendall(cmd.encode('utf-8')) response = "ok" ! elif decoded[1] == 'malformed1': cmd = '["ex",":"]wrong!["ex","smi"]' print("sending: {}".format(cmd)) self.request.sendall(cmd.encode('utf-8')) response = "ok" + elif decoded[1] == 'malformed2': + cmd = '"unterminated string' + print("sending: {}".format(cmd)) + self.request.sendall(cmd.encode('utf-8')) + response = "ok" + # Need to wait for Vim to give up, otherwise the double + # quote in the "ok" response terminates the string. + time.sleep(0.2) + elif decoded[1] == 'malformed3': + cmd = '["ex","missing ]"' + print("sending: {}".format(cmd)) + self.request.sendall(cmd.encode('utf-8')) + response = "ok" + # Need to wait for Vim to give up, otherwise the ] + # in the "ok" response terminates the list. + time.sleep(0.2) + elif decoded[1] == 'split': + cmd = '["ex","let ' + print("sending: {}".format(cmd)) + self.request.sendall(cmd.encode('utf-8')) + time.sleep(0.01) + cmd = 'g:split = 123"]' + print("sending: {}".format(cmd)) + self.request.sendall(cmd.encode('utf-8')) + response = "ok" elif decoded[1] == 'an expr': # Send an expr request. cmd = '["expr","setline(\\"$\\", [\\"one\\",\\"two\\",\\"three\\"])"]' *** ../vim-7.4.1616/src/version.c 2016-03-20 14:30:56.170394171 +0100 --- src/version.c 2016-03-20 16:37:30.232377936 +0100 *************** *** 750,751 **** --- 750,753 ---- { /* Add new patch number below this line */ + /**/ + 1617, /**/ -- Warning label on a superhero Halloween costume: "Caution: Cape does not enable user to fly." /// Bram Moolenaar -- Bram@Moolenaar.net -- http://www.Moolenaar.net \\\ /// sponsor Vim, vote for features -- http://www.Vim.org/sponsor/ \\\ \\\ an exciting new programming language -- http://www.Zimbu.org /// \\\ help me help AIDS victims -- http://ICCF-Holland.org ///