HTTP: Remove short read check in nxt_http_static_buf_completion() #1067
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
|
Hi @ac000,
Agree.
Could you check if it's a specific error code in the use case? Try with something like this. I mean if the patch is to fix some error code, we can enhance it and keep the logic |
|
It's not an error, that would be signalled by a return of pread(2) has been asked to read X amount of bytes, it returned > -1 < X amount of bytes. Let me quote from the man page
Note the middle paragraph. As can be seen, with this did we read less bytes than asked for but it's not an error check in place, we terminate the transfer if that check is true. If we remove that check we will pread(2) as many times as necessary (possibly reading less bytes than asked for each time) until all the file is read and sent. Assuming a read on a regular file will return all the bytes asked for, is often true but there are circumstances where it is not, this, where the files being served are coming from a network filesystem is one of them. |
hongzhidao
approved these changes
Jan 18, 2024
ac000
force-pushed
the
short-reads
branch
2 times, most recently
from
b7ca3fa
to
93c8d6d
Compare
|
Highlighted in the code snippet where the problem lies. Added Zhidao's Reviewed-by tag. |
|
Fixed alignment in commit message |
|
Wrap the (n == -1) check in a nxt_slow_path() |
|
Check for NXT_ERROR from nxt_file_read() rather than its numeric value. |
andrey-zelenkov
approved these changes
Jan 19, 2024
On GH, @tonychuuy reported an issue when using Units 'share' action they would get the following error in the unit log 2024/01/15 17:53:41 [error] 49#52 *103 file "/var/www/html/public/vendor/telescope/app.css" has changed while sending response to a client This would happen when trying to serve files over a certain size and the requested file would not be sent. This is due to a somewhat bogus check in nxt_http_static_buf_completion() I say bogus because it's not clear what the check is trying to accomplish and the error message is not entirely accurate either. The check in question goes like n = pread(file->fd, buf, size, offset); return n; ... if (n != size) { if (n >= 0) { /* log file changed error and finish */ /* >> Problem is here << */ } /* log general error and finish */ } If the number of bytes read is not what we asked for and is > -1 (i.e not an error) then it says the file has changed, but really it only checks if the file has _shrunk_ (we can't get back _more_ bytes than we asked for) since it was stat'd. This is what happens recvfrom(22, "GET /tfile HTTP/1.1\r\nHost: local"..., 2048, 0, NULL, NULL) = 82 openat(AT_FDCWD, "/mnt/9p/tfile", O_RDONLY|O_NONBLOCK) = 23 newfstatat(23, "", {st_mode=S_IFREG|0644, st_size=149922, ...}, AT_EMPTY_PATH) = 0 We get a request from a client, open the requested file and stat(2) it to get the file size. We would then go into a pread/writev loop reading the file data and sending it to the client until it's all been sent. However what was happening in this case was this (showing a dummy file of 149922 bytes) pread64(23, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 131072, 0) = 61440 write(2, "2024/01/17 15:30:50 [error] 1849"..., 109) = 109 We wanted to read 131072 bytes but only read 61440 bytes, the above check triggered and the file transfer was aborted and the above error message logged. Normally for a regular file you will only get less bytes than asked for if the read call is interrupted by a signal or you're near the end of file. There is however at least another situation where this may happen, if the file in question is being served from a network filesystem. It turns out that was indeed the case here, the files where being served over the 9P filesystem protocol. Unit was running in a docker container in an Ubuntu VM under Windows/WSL2 and the files where being passed through to the VM from Windows over 9P. Whatever the intention of this check, it is clearly causing issues in real world scenarios. If it was really desired to check if the had changed since it was opened/stat'd then it would require a different methodology and be a patch for another day. But as it stands this current check does more harm than good, so lets just remove it. With it removed we now get for the above test file recvfrom(22, "GET /tfile HTTP/1.1\r\nHost: local"..., 2048, 0, NULL, NULL) = 82 openat(AT_FDCWD, "/mnt/9p/tfile", O_RDONLY|O_NONBLOCK) = 23 newfstatat(23, "", {st_mode=S_IFREG|0644, st_size=149922, ...}, AT_EMPTY_PATH) = 0 mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f367817b000 pread64(23, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 131072, 0) = 61440 pread64(23, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 18850, 61440) = 18850 writev(22, [{iov_base="HTTP/1.1 200 OK\r\nLast-Modified: "..., iov_len=171}, {iov_base="\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=61440}, {iov_base="\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=18850}], 3) = 80461 pread64(23, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 69632, 80290) = 61440 pread64(23, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 141730) = 8192 close(23) = 0 writev(22, [{iov_base="\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=61440}, {iov_base="\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=8192}], 2) = 69632 So we can see we do two pread(2)s's and a writev(2), then another two pread(2)s and another writev(2) and all the file data has been read and sent to the client. Reported-by: tonychuuy <https://github.com/tonychuuy> Link: <https://en.wikipedia.org/wiki/9P_(protocol)> Fixes: 08a8d15 ("Basic support for serving static files.") Closes: nginx#1064 Reviewed-by: Zhidao Hong <z.hong@f5.com> Reviewed-by: Andrei Zeliankou <zelenkov@nginx.com> Signed-off-by: Andrew Clayton <a.clayton@nginx.com>
|
Add Andrei's Reviewed-by |
|
I remember having seen this error while developing the gzip feature (not in the final version, though). I don't remember what was the trigger, but it was probably something I did wrong while trying things. That part of the code was the one I felt less comfortable with (it is, as you say, very weird), so when you review those patches, check twice that part of the code. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
On GH, @tonychuuy reported an issue when using Units 'share' action they would get the following error in the unit log
2024/01/15 17:53:41 [error] 49#52 *103 file "/var/www/html/public/vendor/telescope/app.css" has changed while sending response to a client
This would happen when trying to serve files over a certain size and the requested file would not be sent.
This is due to a somewhat bogus check in
nxt_http_static_buf_completion()
I say bogus because it's not clear what the check is trying to accomplish and the error message is not entirely accurate either.
The check in question goes like
If the number of bytes read is not what we asked for and is > -1 (i.e not an error) then it says the file has changed, but really it only checks if the file has shrunk (we can't get back more bytes than we asked for) since it was stat'd.
This is what happens
recvfrom(22, "GET /tfile HTTP/1.1\r\nHost: local"..., 2048, 0, NULL, NULL) = 82
openat(AT_FDCWD, "/mnt/9p/tfile", O_RDONLY|O_NONBLOCK) = 23
newfstatat(23, "", {st_mode=S_IFREG|0644, st_size=149922, ...}, AT_EMPTY_PATH) = 0
We get a request from a client, open the requested file and stat(2) it to get the file size.
We would then go into a pread/writev loop reading the file data and sending it to the client until it's all been sent.
However what was happening in this case was this (showing a dummy file of 149922 bytes)
pread64(23, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 131072, 0) = 61440
write(2, "2024/01/17 15:30:50 [error] 1849"..., 109) = 109
We wanted to read 131072 bytes but only read 61440 bytes, the above check triggered and the file transfer was aborted and the above error message logged.
Normally for a regular file you will only get less bytes than asked for if the read call is interrupted by a signal or you're near the end of file.
There is however at least another situation where this may happen, if the file in question is being served from a network filesystem.
It turns out that was indeed the case here, the files where being served over the 9P filesystem protocol. Unit was running in a docker container in an Ubuntu VM under Windows/WSL2 and the files where being passed through to the VM from Windows over 9P.
Whatever the intention of this check, it is clearly causing issues in real world scenarios.
If it was really desired to check if the had changed since it was opened/stat'd then it would require a different methodology and be a patch for another day. But as it stands this current check does more harm than good, so lets just remove it.
With it removed we now get for the above test file
recvfrom(22, "GET /tfile HTTP/1.1\r\nHost: local"..., 2048, 0, NULL, NULL) = 82
openat(AT_FDCWD, "/mnt/9p/tfile", O_RDONLY|O_NONBLOCK) = 23
newfstatat(23, "", {st_mode=S_IFREG|0644, st_size=149922, ...}, AT_EMPTY_PATH) = 0
mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f367817b000
pread64(23, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 131072, 0) = 61440
pread64(23, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 18850, 61440) = 18850
writev(22, [{iov_base="HTTP/1.1 200 OK\r\nLast-Modified: "..., iov_len=171}, {iov_base="\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=61440}, {iov_base="\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=18850}], 3) = 80461
pread64(23, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 69632, 80290) = 61440
pread64(23, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192, 141730) = 8192
close(23) = 0
writev(22, [{iov_base="\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=61440}, {iov_base="\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=8192}], 2) = 69632
So we can see we do two pread(2)s's and a writev(2), then another two pread(2)s and another writev(2) and all the file data has been read and sent to the client.