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

Michael Jumper (JIRA) Mon, 20 Mar 2017 22:58:33 -0700

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


Michael Jumper updated GUACAMOLE-239:
-------------------------------------
    Description: 
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.


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

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.



> 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
>         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)

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

Reply via email to