Uploaded image for project: 'Guacamole'
  1. Guacamole
  2. GUACAMOLE-239

Disconnects due to 'backwards' running time

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 0.9.13-incubating
    • Component/s: None
    • Labels:
      None

      Description

      Short version:

      We had Azure guacd running on an Azure Linux, Ubuntu 16.04 instance.
      This causes disconnects, since the protocol implementation does not expect backward running time.
      Changing the timestamp.c to use CLOCK_MONOTONIC fixes this issue.

      Pull request: https://github.com/apache/incubator-guacamole-server/pull/74

      Details investigation:

      We observed frequent disconnects on our Azure running guacd instance.

      When monitoring the traffic between the web-socket-server and guacd, we discovered backward running time:

      This caused the condition in __guac_handle_sync to fail:

      int __guac_handle_sync(guac_user* user, int argc, char** argv) {
      
          int frame_duration;
      
          guac_timestamp current = guac_timestamp_current();
          guac_timestamp timestamp = __guac_parse_int(argv[0]);
      
          /* Error if timestamp is in future */
          if (timestamp > user->client->last_sent_timestamp)
              return -1;
      

      So, instrumented the timestamp.c, guac_timestamp_current:

      #ifdef HAVE_CLOCK_GETTIME
      
          struct timespec current;
      
          /* Get current time */
          clock_gettime(CLOCK_REALTIME, &current);
      
          /* Calculate milliseconds */
          guac_timestamp ts = (guac_timestamp) current.tv_sec * 1000 + current.tv_nsec / 1000000;
          printf("TS clock_gettime %lld\n", (long long)ts);
          return ts;
      #else
      
          struct timeval current;
      
          /* Get current time */
          gettimeofday(&current, NULL);
      
          /* Calculate milliseconds */
          guac_timestamp ts = (guac_timestamp) current.tv_sec * 1000 + current.tv_usec / 1000;
          printf("TS gettimeofday %lld\n", (long long)ts);
          return ts;
      #endif
      

      This, indeed yielded 'backwards' running time, with connection failure on it:

      TS clock_gettime 1489106020137
      TS clock_gettime 1489106020137 <-- Send out
      TS clock_gettime 1489106020077
      TS clock_gettime 1489106020077
      TS clock_gettime 1489106020077
      TS clock_gettime 1489106020088  <-- Send out, now expect's this time. Causing failure when client answers with 1489106020137 
      
      
      
      TS clock_gettime 14guacd[7]: DEBUG:     Sending ts 1489106020042
      guacd[7]: DEBUG:        Expect 1489106020010 <= 1489106020042
      guacd[7]: DEBUG:        Sync time is ok.
      guacd[7]: DEBUG:        Sending ts 1489106020074
      guacd[7]: DEBUG:        Expect 1489106020042 <= 1489106020074
      guacd[7]: DEBUG:        Sync time is ok.
      guacd[7]: DEBUG:        Sending ts 1489106020104
      guacd[7]: DEBUG:        Expect 1489106020074 <= 1489106020104
      guacd[7]: DEBUG:        Sync time is ok.
      guacd[7]: DEBUG:        Sending ts 1489106020137
      guacd[7]: DEBUG:        Expect 1489106020104 <= 1489106020137
      guacd[7]: DEBUG:        Sync time is ok.
      guacd[7]: DEBUG:        Sending ts 1489106020088
      guacd[7]: DEBUG:        Expect 1489106020137 <= 1489106020088
      guacd[7]: DEBUG:        Sync time is out of order.
      guacd[7]: WARNING:      Connection aborted
      guacd[7]: DEBUG:        Failing instruction handler in client was "sync"
      guacd[7]: DEBUG:        Sending ts 1489106020125
      guacd[7]: DEBUG:        Output thread terminated.
      guacd[7]: INFO: Client disconnected
      89106020042
      TS clock_gettime 1489106020043
      TS clock_gettime 1489106020063
      TS clock_gettime 1489106020063
      TS clock_gettime 1489106020063
      TS clock_gettime 1489106020074
      TS clock_gettime 1489106020074
      TS clock_gettime 1489106020093
      TS clock_gettime 1489106020094
      TS clock_gettime 1489106020094
      TS clock_gettime 1489106020104
      TS clock_gettime 1489106020105
      TS clock_gettime 1489106020126
      TS clock_gettime 1489106020126
      TS clock_gettime 1489106020126
      TS clock_gettime 1489106020137
      TS clock_gettime 1489106020137
      TS clock_gettime 1489106020077
      TS clock_gettime 1489106020077
      TS clock_gettime 1489106020077
      TS clock_gettime 1489106020088
      TS clock_gettime 1489106020088
      TS clock_gettime 1489106020114
      TS clock_gettime 1489106020115
      TS clock_gettime 1489106020115
      TS clock_gettime 1489106020125
      TS clock_gettime 1489106020126
      TS clock_gettime 1489106020529
      

      Using clock_gettime(CLOCK_MONOTONIC,..) instead of clock_gettime(CLOCK_REALTIME,..) fixed this issue.

      From the man pages, the CLOCK_MONOTONIC is precisely to ensure that time never runs backwards.

        Activity

        There are no comments yet on this issue.

          People

          • Assignee:
            mike.jumper Michael Jumper
            Reporter:
            Gamlor Roman Stoffel
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development