[GUACAMOLE-239] Disconnects due to 'backwards' running time

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 0.9.13-incubating
• Assignee: Mike Jumper
• Reporter: Roman Stoffel
• Created: 10/Mar/17 01:27
• Updated: 24/Mar/17 04:08
• Resolved: 24/Mar/17 04:08

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.