Asterisk
  1. Asterisk
  2. ASTERISK-19603

Asterisk AMI truncates long responses over medium latency connections

    Details

    • Type: Bug Bug
    • Status: Closed
    • Severity: Major Major
    • Resolution: Workaround Available
    • Affects Version/s: 1.8.7.2
    • Target Release Version/s: None
    • Component/s: Core/ManagerInterface
    • Security Level: None
    • Labels:
      None
    • Environment:
      CentOS release 5.5 (Final) - 2.6.18-194.el5 #1 SMP Fri Apr 2 14:58:14 EDT 2010 x86_64 x86_64 x86_64 GNU/Linux
    • Frequency of Occurrence:
      Constant

      Description

      Asterisk Manager is truncating long responses when it is connected to over a WAN (with reasonable latency ~50ms). This issue is not occurring when connected locally (127.0.0.1) or from a machine on the same switch/subnet.

      The particular command being issued is "Action: Command\r\nCommand: database show", which produces about 5000 lines of text when functioning correctly. It ends with "-END COMMAND-".

      When it is being truncated, the command returns a significantly shorter response, though it still ends with "-END COMMAND-".

      A packet capture on the server side reveals that, at a certain point, the Manager has sent out around 10 packets without receiving an ACK, and then sends out a FIN. The ACKs from the client arrive shortly after, followed by a few retransmissions, and a FIN from the client. In a low-latency connection, the ACKs from the client keep up with the Manager and the entire database is shown before "-END COMMAND-" and FIN are sent from the server.

      The problem appears to lie somewhere around astman_append() below, with a buffer of sorts being fully consumed and returning when the client isn't able to read quickly enough:

      static int action_command(struct mansession *s, const struct message *m)
      {
              const char *cmd = astman_get_header(m, "Command");
              const char *id = astman_get_header(m, "ActionID");
              char *buf, *final_buf;
              char template[] = "/tmp/ast-ami-XXXXXX";        /* template for temporary file */
              int fd;
              off_t l;
      
              if (ast_strlen_zero(cmd)) {
                      astman_send_error(s, m, "No command provided");
                      return 0;
              }
      
              if (check_blacklist(cmd)) {
                      astman_send_error(s, m, "Command blacklisted");
                      return 0;
              }
      
              fd = mkstemp(template);
      
              astman_append(s, "Response: Follows\r\nPrivilege: Command\r\n");
              if (!ast_strlen_zero(id)) {
                      astman_append(s, "ActionID: %s\r\n", id);
              }
              /* FIXME: Wedge a ActionID response in here, waiting for later changes */
              ast_cli_command(fd, cmd);       /* XXX need to change this to use a FILE * */
              l = lseek(fd, 0, SEEK_END);     /* how many chars available */
      
              /* This has a potential to overflow the stack.  Hence, use the heap. */
              buf = ast_calloc(1, l + 1);
              final_buf = ast_calloc(1, l + 1);
              if (buf) {
                      lseek(fd, 0, SEEK_SET);
                      if (read(fd, buf, l) < 0) {
                              ast_log(LOG_WARNING, "read() failed: %s\n", strerror(errno));
                      }
                      buf[l] = '\0';
                      if (final_buf) {
                              term_strip(final_buf, buf, l);
                              final_buf[l] = '\0';
                      }
                      astman_append(s, "%s", S_OR(final_buf, buf));
                      ast_free(buf);
              }
              close(fd);
              unlink(template);
              astman_append(s, "--END COMMAND--\r\n\r\n");
              if (final_buf) {
                      ast_free(final_buf);
              }
              return 0;
      }
      

      To test my theory, I created a TCP proxy on the server which connects to the Asterisk Manager, allows tcp connections to itself, and buffers Manager responses to an array instead of directly sending them to the client. This works. Removing the buffering component and making the proxy wait for each line to send to the client before reading the next line from the Manager causes the truncated behavior.

      I could only find one ticket that seemed to relate to this issue, though it's from '04. Perhaps it will provide some insight to the person able to solve this issue:

      [patch] Allow Manager API Command to return big amount of output data +++
      ASTERISK-1948

        Issue Links

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

          Activity

          Hide
          David Woolley added a comment -

          From http://svn.digium.com/svn/asterisk/tags/1.8.7.2/main/manager.c:

          			} else if (!strcasecmp(var->name, "writetimeout")) {
          				int value = atoi(var->value);
          				if (value < 100) {
          					ast_log(LOG_WARNING, "Invalid writetimeout value '%s' at line %d\n", var->value, var->lineno);
          				} else {
          					user->writetimeout = value;
          				}
          

          The error you quote relates to the general section, but this is a per user option. Also, if it were deprecated, it would still be accepted, but possibly with a warning.

          Show
          David Woolley added a comment - From http://svn.digium.com/svn/asterisk/tags/1.8.7.2/main/manager.c: } else if (!strcasecmp(var->name, "writetimeout")) { int value = atoi(var->value); if (value < 100) { ast_log(LOG_WARNING, "Invalid writetimeout value '%s' at line %d\n", var->value, var->lineno); } else { user->writetimeout = value; } The error you quote relates to the general section, but this is a per user option. Also, if it were deprecated, it would still be accepted, but possibly with a warning.
          Hide
          WRP added a comment -

          Thank you, David. I'll try it in the user section and see if it resolves this issue.

          Show
          WRP added a comment - Thank you, David. I'll try it in the user section and see if it resolves this issue.
          Hide
          mbrevda added a comment -

          a. this issue isn't just over medium latency connections, we have seen it on the same (local) host (with large datasets)
          b. uping the value of writetimeout in manager.conf seems to resolve the issue

          Show
          mbrevda added a comment - a. this issue isn't just over medium latency connections, we have seen it on the same (local) host (with large datasets) b. uping the value of writetimeout in manager.conf seems to resolve the issue
          Hide
          WRP added a comment -

          @mbrevda You seem to be spot on. IMO writetimeout shouldn't be needed when data is actively being sent, but setting writetimeout to something higher does resolve the issue.

          Show
          WRP added a comment - @mbrevda You seem to be spot on. IMO writetimeout shouldn't be needed when data is actively being sent, but setting writetimeout to something higher does resolve the issue.
          Hide
          Malcolm Davenport added a comment -

          I believe WRP is correct. If data's being sent, one shouldn't have to manually set a parameter to ensure that it actually all gets sent.

          But, I'm going to close this, for now, as "workaround available." If someone wants to move forward on a better solution, I'm certain that would be helpful.

          Show
          Malcolm Davenport added a comment - I believe WRP is correct. If data's being sent, one shouldn't have to manually set a parameter to ensure that it actually all gets sent. But, I'm going to close this, for now, as "workaround available." If someone wants to move forward on a better solution, I'm certain that would be helpful.

            People

            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: