[jira] [Created] (GUACAMOLE-239) Disconnects due to 'backwards' running time. Fix in PR

["Roman Stoffel (JIRA)" <ji...@apache.org>]

Roman Stoffel created GUACAMOLE-239:
---------------------------------------

             Summary: Disconnects due to 'backwards' running time. Fix in PR
                 Key: GUACAMOLE-239
                 URL: https://issues.apache.org/jira/browse/GUACAMOLE-239
             Project: Guacamole
          Issue Type: Bug
            Reporter: Roman Stoffel


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.

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. See screen shot wire shark

This caused the condition in __guac_handle_sync to fail:
 
{code}
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;
{code}

So, instrumented the timestamp.c, guac_timestamp_current:

{code}
#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
{code}

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

{code}
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
{code}



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.




--
This message was sent by Atlassian JIRA
(v6.3.15#6346)