[jira] [Resolved] (GUACAMOLE-239) Disconnects due to 'backwards' running time

["Michael Jumper (JIRA)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/GUACAMOLE-239?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Michael Jumper resolved GUACAMOLE-239.
--------------------------------------
       Resolution: Fixed
    Fix Version/s: 0.9.13-incubating

> Disconnects due to 'backwards' running time
> -------------------------------------------
>
>                 Key: GUACAMOLE-239
>                 URL: https://issues.apache.org/jira/browse/GUACAMOLE-239
>             Project: Guacamole
>          Issue Type: Bug
>            Reporter: Roman Stoffel
>            Assignee: Michael Jumper
>             Fix For: 0.9.13-incubating
>
>         Attachments: backwards-running-time.PNG
>
>
> h3. 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
> h3. 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:
> !backwards-running-time.PNG|width=100%!
> This caused the condition in __guac_handle_sync to fail:
>  
> {code:none}
> 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:none}
> #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:none}
> 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)