GUACAMOLE-608: Fix connection write thread may encounter dead loop

[changkun]

guacd involves a __write_all function to write instruction as much as possible. However, system call write is possible return 0 and also set errno, which is not verified in the function.

A possible case is write keeps return 0 (nothing writes to buffer). Therefore the daemon process encounters a dead loop. Furthermore, it leads CPU rate up to 99%.

The above phenomenon is observed from server:

$ top
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
15176 root      20   0 1988580  25720   3168 S  99.9  0.3  12176:50 guacd
25414 root      20   0 1726048  23324   3040 S  99.9  0.3  17227:15 guacd
...

$ sudo lsof -i | grep 15176 # no network connection
$ top -H -p 25414
  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
25418 root      20   0 1726048  23324   3040 R 99.9  0.3  17230:06 guacd
25414 root      20   0 1726048  23324   3040 S  0.0  0.3   0:00.00 guacd
25420 root      20   0 1726048  23324   3040 S  0.0  0.3   0:06.16 guacd

This patch perhaps needs more discussion on when and why this is happening, as well as whether should we record the failure to log, for instance:

int written = write(fd, buffer, length);
if (written < 0)
    return -1;
if (written == 0 && errno > 0) {
    guacd_log(GUAC_LOG_ERROR, "Unable to write buffer to file descriptor: %s", strerror(errno));
    return -1;
}

[necouchman]

I'm good with it. @mike-jumper any concerns with this change? Based on the documentation of the write call as referenced by @changkun, this seems to be the correct way to go...

[mike-jumper]

The contents of errno are not defined for a successful call to write(). I don't believe the standard allows us to rely on checking solely errno to determine whether write() failed.

[changkun]

As far as I know from a higher level language, Go wraps write call and return error if errno is not zero.

[mike-jumper]

Unless the standards behind errno or write() define what errno will be after a successful call to write(), it is non-portable to make assumptions about that behavior.

[changkun]

How about if (written < 0 || (written == 0 && errno > 0))?
This condition completely satisfies the man page description.

[mike-jumper]

Yep. That looks good to me.

[mike-jumper]

@changkun, can you point to any documentation specifically covering the circumstances under which write() may return 0 for a blocking socket?

I'm hesitant to simply handle all 0 returns as equivalent to errors, as the normal behavior for such a case is to retry the write(), however I'd also expect the socket to block until things can be written for cases where 0 would be returned.

[necouchman]

@mike-jumper There was a link in this pull request to the documentation, which says this:

If count is zero and fd refers to a regular file, then write() may return a failure status if one of the errors below is detected. If no errors are detected, 0 will be returned without causing any other effect. If count is zero and fd refers to a file other than a regular file, the results are not specified.

https://linux.die.net/man/2/write

This does say that this should only be the case where fd is a regular file, so, presumably, this should not happen when this is a socket??

[mike-jumper]

Yeah, that's were I'm not sure. The 0 return seems clearly defined for writing to files and for non-blocking sockets, but it's unclear to me whether there are non-error conditions for a blocking socket which would result in a write() not blocking, returning 0, and (presumably) possibly succeeding later if retried.

If it is true that a 0 return should really not happen for a blocking socket, or if 0 is only really handled as end-of-stream for a blocking socket, then handling 0 as if it were an error makes sense.

For non-blocking sockets, a 0 return is not necessarily fatal, and likely indicates that the send attempt should be retried (send buffer is full, etc.). If that is the case here, then the proper solution would be to poll() or select() on the file descriptor to wait for the socket to be ready for writing, not to avoid the loop entirely, but as the socket is a blocking socket here I'd expect the write() call to simply block.

[changkun]

@mike-jumper So far, I investigated the phenomenon described in the PR description, the __write_all is a possible reason that leads a 99% CPU usage rate (dead loop) that satisfy the three condition:

1. three threads alive;
2. no network connection;
3. not reproducible, happens in a low probability.

Do you have any other guess for it?

[mike-jumper]

It definitely should be fixed, but whether the fix is to interpret 0 as an error condition (these changes) or to interpret 0 as a need to retry (select() / poll() to avoid a tight loop, but still loop) is currently unclear.

So far, I investigated the phenomenon described in the PR description, the __write_all is a possible reason that leads a 99% CPU usage rate (dead loop) that satisfy the three condition:

1. three threads alive;
2. no network connection;
3. not reproducible, happens in a low probability.

Does this mean you are encountering this in practice?

[changkun]

@mike-jumper Yes, very few connection processes satisfy the three conditions are observed in practice.

[mike-jumper]

What I mean is, if you are encountering this in practice, then that might be an opportunity to add some temporary additional logging and see what conditions surround a write() which returns 0.

[necouchman]

So @mike-jumper you good with this PR, now, or did you still want @changkun to chase down specific situations where this is occurring before we push forward with a merge?

[mike-jumper]

The latter. We need more information before I am comfortable with these changes as they stand. The circumstances that write() may return 0 need to be understood before we start handling that with anything other than a retry (the existing behavior).

If write() can only return 0 for a blocking socket under error conditions or when the socket is being closed, then these changes are safe.

If write() may return 0 for a blocking socket under normal conditions (high network activity and full buffers, for example), then these changes will harm connection stability, and we need to look toward ways to make the retry loop not CPU bound (poll() / select()) rather than aborting as if an error occurred.

It comes down to more than just determining specific situations where this occurs in practice. That may help find a starting point, but we will ultimately need standards documentation to support either solution.

[mike-jumper]

As mentioned above, we need to know that write() returning 0 for a blocking socket is an error condition before we can safely handle it as a fatal error.

[mike-jumper]

For example, what if write() is interrupted by a signal? Will it then potentially return 0, having written nothing prior to being interrupted, with errno set to EINTR? Such a write() would presumably succeed if retried, depending on the nature of the signal.

[changkun]

Yeah, @mike-jumper, I completely understand your concerns, to be honest, I am also not confident regarding the change.
For system calls, only return value and errno influence the calling result, after reading the source of glibc, it seems only the case which leads returning zero is trying to write a zero length buffer. However, it is guaranteed by guac_parser_shift and guac_socket_read to write a non zero buffer.

Speaking of the virgin idea of the PR, it intends to solve the issue of high CPU usage rate.

let's take a look at those high CPU rate processes.

$ top
top - 17:32:27 up 35 days,  7:48,  0 users,  load average: 4.43, 4.02, 4.07
Tasks:  20 total,   1 running,  19 sleeping,   0 stopped,   0 zombie
%Cpu(s): 39.8 us,  1.4 sy,  0.0 ni, 57.0 id,  1.6 wa,  0.0 hi,  0.1 si,  0.1 st
KiB Mem:   8175596 total,  7683964 used,   491632 free,   385312 buffers
KiB Swap:        0 total,        0 used,        0 free.  4100680 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
26329 root      20   0 2250720  24896   3040 S  98.2  0.3  14352:42 guacd
57599 root      20   0 2249092  25236   3164 S  98.2  0.3 224:35.78 guacd
50821 root      20   0 2250724  27004   3168 S  91.7  0.3   2992:43 guacd
    1 root      20   0   21752    856    576 S   0.0  0.0   0:00.02 init.sh
   12 root      20   0 5712804  21156    712 S   0.0  0.3  50:55.79 guacd
   13 root      20   0   46440   1160    768 S   0.0  0.0   0:00.00 su
   14 jetty     20   0 4002728 321704   2024 S   0.0  3.9  28:59.74 java
58607 root      20   0 5707804  31532   3012 S   0.0  0.4   0:01.36 guacd
58648 root      20   0 5697740  35216   4152 S   0.0  0.4   0:01.46 guacd
58852 root      20   0 5748784  31620   3012 S   0.0  0.4   0:00.73 guacd
58876 root      20   0 5747880  36248   4156 S   0.0  0.4   0:00.60 guacd

$ top -H -p 50821
top - 17:31:06 up 35 days,  7:47,  0 users,  load average: 3.75, 3.87, 4.02
Threads:   3 total,   1 running,   2 sleeping,   0 stopped,   0 zombie
%Cpu(s): 85.8 us,  0.7 sy,  0.0 ni, 13.0 id,  0.0 wa,  0.0 hi,  0.2 si,  0.2 st
KiB Mem:   8175596 total,  7947360 used,   228236 free,   400124 buffers
KiB Swap:        0 total,        0 used,        0 free.  4268008 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
50825 root      20   0 2250724  27004   3168 R 98.9  0.3   2991:25 guacd
50821 root      20   0 2250724  27004   3168 S  0.0  0.3   0:00.01 guacd
50827 root      20   0 2250724  27004   3168 S  0.0  0.3   0:00.87 guacd

$ top -H -p 26329
top - 17:31:53 up 35 days,  7:47,  0 users,  load average: 3.95, 3.90, 4.03
Threads:   3 total,   1 running,   2 sleeping,   0 stopped,   0 zombie
%Cpu(s): 92.3 us,  0.9 sy,  0.0 ni,  6.6 id,  0.0 wa,  0.0 hi,  0.1 si,  0.2 st
KiB Mem:   8175596 total,  8049068 used,   126528 free,   396788 buffers
KiB Swap:        0 total,        0 used,        0 free.  4276156 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
26333 root      20   0 2250720  24896   3040 R 96.2  0.3  14352:05 guacd
26329 root      20   0 2250720  24896   3040 S  0.0  0.3   0:00.00 guacd
26335 root      20   0 2250720  24896   3040 S  0.0  0.3   0:04.45 guacd

thread creation: guacd_connection_thread (26329) --> guac_user_thread (26331) --> guacd_connection_io_thread (26333) --> guacd_connection_write_thread (26335)

guac_user_thread seems already exited (if PID assumption is correct), and the only thing that guacd_connection_io_thread doing is read from fd and write to the socket.

Surprisingly for a connectionless thread can still reading a non zero buffer from fd.

[changkun]

Therefore my hypothesis is guacd_connection_io_thread breaks its read loop and waiting for guacd_connection_write_thread, then write is the only reason that caused an endless loop. For write, -1 and positive are correctly handled by __write_all, then the only cause of endless loop might be an unhandled case of returning zero.

Dead loop backtrace:

warning: process 32054 is a cloned process
Reading symbols from /usr/local/sbin/guacd...done.
Reading symbols from /lib64/ld-linux-x86-64.so.2...Reading symbols from /usr/lib/debug//lib/x86_64-linux-gnu/ld-2.19.so...done.
done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
0x00007febc05ee316 in ?? ()
(gdb) backtrace
#0  0x00007febc05ee316 in ?? ()
#1  0x00007febc05ee350 in ?? ()
#2  0x00007febc05ee3e0 in ?? ()
#3  0x00007feb20264890 in ?? ()
#4  0x00007feb2014bac0 in ?? ()
#5  0x00007feaf776db20 in ?? ()
#6  0x00007feb201a5de0 in ?? ()
#7  0x0000000000000043 in ?? ()
#8  0x00000000b51af9fe in ?? ()
#9  0x00007febcd898010 in ?? ()
#10 0x00007febc05ebe88 in ?? ()
#11 0x00007febbc00d582 in ?? ()
#12 0x00007feaf77adb1e in ?? ()
#13 0x3d6665726820613c in ?? ()
#14 0x5f6c7275207b7b22 in ?? ()
#15 0x626f6a2728726f66 in ?? ()
#16 0x29276e696d64612e in ?? ()
#17 0x616c6320227d7d20 in ?? ()
#18 0x7473696c223d7373 in ?? ()
#19 0x692d70756f72672d in ?? ()
#20 0xceb0d63e226d6574 in ?? ()
#21 0xe7abbfe7bdbfefbb in ?? ()
#22 0xabbfe7abbfe7abbf in ?? ()
#23 0xbfe7abbfe7abbfe7 in ?? ()
#24 0xe7abbfe7abbfe7ab in ?? ()
#25 0xabbfe7abbfe7abbf in ?? ()
#26 0xbfe7abbfe7abbfe7 in ?? ()
#27 0xe7abbfe7abbfe7ab in ?? ()
#28 0xabbfe7abbfe7abbf in ?? ()
#29 0xbfe7abbfe7abbfe7 in ?? ()
#30 0xe7abbfe7abbfe7ab in ?? ()
#31 0xabbfe7abbfe7abbf in ?? ()
#32 0xbfe7abbfe7abbfe7 in ?? ()
#33 0xe7abbfe7abbfe7ab in ?? ()
#34 0xabbfe7abbfe7abbf in ?? ()
#35 0xbfe7abbfe7abbfe7 in ?? ()
#36 0xe7abbfe7abbfe7ab in ?? ()
#37 0xabbfe7abbfe7abbf in ?? ()
#38 0xbfe7abbfe7abbfe7 in ?? ()
#39 0xe7abbfe7abbfe7ab in ?? ()
#40 0xabbfe7abbfe7abbf in ?? ()
#41 0xbfe7abbfe7abbfe7 in ?? ()
#42 0xe7abbfe7abbfe7ab in ?? ()
#43 0xabbfe7abbfe7abbf in ?? ()
#44 0xbfe7abbfe7abbfe7 in ?? ()
#45 0xe7abbfe7abbfe7ab in ?? ()
#46 0xabbfe7abbfe7abbf in ?? ()
#47 0xbfe7abbfe7abbfe7 in ?? ()
#48 0xe7abbfe7abbfe7ab in ?? ()
#49 0xabbfe7abbfe7abbf in ?? ()
#50 0xbfe7abbfe7abbfe7 in ?? ()
#51 0xe7abbfe7abbfe7ab in ?? ()
#52 0xabbfe7abbfe7abbf in ?? ()
#53 0xbfe7abbfe7abbfe7 in ?? ()
#54 0xe7abbfe7abbfe7ab in ?? ()
#55 0xabbfe7abbfe7abbf in ?? ()

[changkun]

close due to #181

[mike-jumper]

...
#0  0x00007febc05ee316 in ?? ()
#1  0x00007febc05ee350 in ?? ()
#2  0x00007febc05ee3e0 in ?? ()
#3  0x00007feb20264890 in ?? ()
#4  0x00007feb2014bac0 in ?? ()
#5  0x00007feaf776db20 in ?? ()
#6  0x00007feb201a5de0 in ?? ()
#7  0x0000000000000043 in ?? ()
#8  0x00000000b51af9fe in ?? ()
#9  0x00007febcd898010 in ?? ()
...

A backtrace is only going to be useful with corresponding symbols. These addresses are going to be specific to your build of whatever-is-in-memory-at-that-location.

close due to #181

@changkun, #181 is an entirely different change covering a different loop. Can you clarify why you believe these changes are no longer needed in light of #181?

[changkun]

Hi @mike-jumper, those backtraces with corresponding symbols are presented in #181 . I generally believe #181 fixes the infinite loop problem.

In speaking of this PR changes, there was a "wrong" deployment (master branch with this PR changes, instead of using 0.9.14 releasing) a week ago and there was an automatically disconnection observed in our practices and CPU spinning remains.

Despite the deployment was not controlled by one condition, the remaining CPU spinning seems still proves this PR doesn't help.

Back to the write call, I reread the doc provided in above. It seems we all misread the documentation before.

On error, -1 is returned, and errno is set appropriately.

This explains no matter how write call wraps syscall, -1 is returned if there was an error.

If count is zero and fd refers to a file other than a regular file, the results are not specified.

and apparently count is non-zero (guaranteed in guac_socket_read)in our case:

/* Transfer data from file descriptor to socket */
while ((length = guac_socket_read(params->socket, buffer, sizeof(buffer))) > 0) {
    if (__write_all(params->fd, buffer, length) < 0)
        break;
}

see

guacamole-server/src/guacd/connection.c

Line 121 in 332e187

while ((length = guac_socket_read(params->socket, buffer, sizeof(buffer))) > 0) {

[changkun]

FYI: the write call is called correctly in guacd. However check errno in this PR is still a right way.

I quote an answer from Dietrich on StackOverflow below, and

TLDR: errno is not set if write return non-negative, but it can be negative if it was not reset by the caller.

With write, there are only two cases to consider:

• If it fails, the result is -1 and errno is set.
• If it succeeds, the result is 0 or larger and errno is not set.
  There are no other cases to consider, unless you are interested in historical Unix implementations (see: Is a return value of 0 from write(2) in C an error?).

The reason that write may return 0 is because the input buffer may be empty.

Q: However, the man page of C write call roughly describes errno may also be set but unspecified if we write zero length buffer without explaining any detail.

A: All this means is that it's possible for a 0-length write to fail. If it fails, it returns -1 and sets errno. If it succeeds, it returns 0 and does not set errno. This is the same behavior for any other write, it's just mentioned in the man page because people may find it surprising that a 0-length write could fail.

Q: What is the status of errno if write call returning 0 for a file, a non-blocking socket, or a blocking socket?

In this case, errno is not set, because write did not fail. This will only happen if the input buffer is zero bytes.

Q: When and how write call returning 0 and errno is not 0?

A: This does not happen. Either errno is set and the return is -1, or errno is not set and the return is 0 or larger.

Q: What is the status of errno if write call returning positive? Will it be negative?

A: The errno value will not be set. It will have the same value as it did before the write call.

Q: Is there any other syscall may encounter the same situation?

In general, system calls will either return an error or they will succeed. They won't do some mixture of both. Look at the Return Value section of other man pages and you will see that they are mostly the same as write.