unit: Cannot serve css/js static files big size

Thinking this is a windows issue, I’m on windows using WSL with docker but the files are actually in the windows system. Let me try in a mac.

Someone on Reddit appears to have had a the same issue. While they don’t mention they’re running Unit, the error message is identical so I suspect they are: https://www.reddit.com/r/docker/comments/tjomqm/file_has_changed_while_sending_response_to_a/

@tonychuuy

Thanks for your help in debugging this issue. This fix will appear in the next release of Unit, 1.32

OK, so I was able to reproduce this locally by exporting a directory into a QEMU/KVM virtual machine running Fedora using the 9P protocol via

$ qemu-kvm ... -virtfs local,mount_tag=unit_share,path=/srv/unit-share,security_model=passthrough,readonly=on

In the guest I mounted it thus

# mount -t 9p -o trans=virtio,version=9p2000.L,msize=65512,ro unit_share /mnt/9p

Note I set the msize to 65512

After pointing Unit to this directory and executing (in the guest)

$ curl -v localhost:8080/tfile -o /dev/null

Where tfile is a file of 149922 bytes in length, I got the expected failure

* Empty reply from server
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
* Closing connection
curl: (52) Empty reply from server

And looking at the strace output

[pid  1851] recvfrom(22, "GET /tfile HTTP/1.1\r\nHost: local"..., 2048, 0, NULL, NULL) = 82
[pid  1851] openat(AT_FDCWD, "/mnt/9p/tfile", O_RDONLY|O_NONBLOCK) = 23
[pid  1851] newfstatat(23, "", {st_mode=S_IFREG|0644, st_size=149922, ...}, AT_EMPTY_PATH) = 0

We got the request from the client, opened the requested file and stat’d it…

[pid  1851] mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcfd428000
[pid  1851] 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
[pid  1851] write(2, "2024/01/17 15:30:50 [error] 1849"..., 109) = 109

We asked to read 131072 bytes but only got 61440

[pid  1851] munmap(0x7fbcfd428000, 135168) = 0
[pid  1851] close(23)                   = 0
[pid  1851] shutdown(22, SHUT_RDWR)     = 0

At which point the check in unit that if we read less then we asked for kicks in and aborts the transfer…

Now trying it with the above patch which removes that check

$ curl -v localhost:8080/tfile -o /dev/null
...
< HTTP/1.1 200 OK
< Last-Modified: Tue, 16 Jan 2024 14:25:19 GMT
< ETag: "65a691cf-249a2"
< Server: Unit/1.32.0
< Date: Wed, 17 Jan 2024 15:32:35 GMT
< Content-Length: 149922
< 
{ [33109 bytes data]
100  146k  100  146k    0     0  8469k      0 --:--:-- --:--:-- --:--:-- 8612k

All good, lets check the strace output

[pid  1967] recvfrom(22, "GET /tfile HTTP/1.1\r\nHost: local"..., 2048, 0, NULL, NULL) = 82
[pid  1967] openat(AT_FDCWD, "/mnt/9p/tfile", O_RDONLY|O_NONBLOCK) = 23
[pid  1967] newfstatat(23, "", {st_mode=S_IFREG|0644, st_size=149922, ...}, AT_EMPTY_PATH) = 0

Again, we got the request from the client, opened the requested file and stat’d it (oh and just to be clear, we stat(2) the file to get its size).

[pid  1967] mmap(NULL, 135168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f367817b000
[pid  1967] 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
[pid  1967] 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
[pid  1967] 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

So, now we do two reads totalling 80290 bytes and send that back to the client along with some headers.

[pid  1967] 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
[pid  1967] 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
[pid  1967] close(23)                   = 0
[pid  1967] 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

We do another two reads (giving a total of 149922 bytes read) and send that to the client and that’s us done.

This was certainly a fun one to debug 😉

I’ll turn the patch into a PR…

@ac000 @tonychuuy it works for me having the files inside the Linux filesystem outside the mounted windows shares. So taking 9P out will solve it. Testing more

I will give it a try on my WSL2 Ubuntu system. So you are saying the files are on C / D drive not in the WSL Linux file system? How do you start the docker compose service? From the WSL2 cli or from docker desktop?

cli inside WSL ubuntu

From your

curl -v localhost/vendor/telescope/1m -o /dev/null

[pid  3749] pread64(39, "\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) = 65512

Interesting that it again only read 65512 bytes, same as when you tried the css file.

Your initial 1MiB file test worked I assume because it was being served out of tmpfs which is effectively RAM.

OK, so you’re using WSL 2, I think I’ve read that it uses the 9p filesystem protocol, which is a network protocol, which could perhaps explain why you’re seeing short reads…

Need to try and devise some way of testing that theory…

Using the top option from docker and applying strace outside docker works for the test:

root@d7156127adc3:/var/www/html# curl -v localhost:8080/1m -o /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying 127.0.0.1:8080...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /1m HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.74.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Last-Modified: Tue, 16 Jan 2024 10:31:07 GMT
< ETag: "65a65aeb-100000"
< Server: Unit/1.31.1
< Date: Tue, 16 Jan 2024 11:00:02 GMT
< Content-Length: 1048576
<
{ [65363 bytes data]
100 1024k  100 1024k    0     0  62.5M      0 --:--:-- --:--:-- --:--:-- 62.5M
* Connection #0 to host localhost left intact

[pid 84809] <... epoll_wait resumed>[{events=EPOLLIN, data={u32=3221230560, u64=140169478935520}}], 32, -1) = 1
[pid 84809] accept4(11, {sa_family=AF_INET, sin_port=htons(59566), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 32
[pid 84809] accept4(11, 0x7f7bc0001c08, [16], SOCK_NONBLOCK) = -1 EAGAIN (Resource temporarily unavailable)
[pid 84809] epoll_ctl(14, EPOLL_CTL_ADD, 32, {events=EPOLLIN|EPOLLRDHUP|EPOLLET, data={u32=3221235936, u64=140169478940896}}) = 0
[pid 84809] epoll_wait(14, [{events=EPOLLIN, data={u32=3221235936, u64=140169478940896}}], 32, 180000) = 1
[pid 84809] recvfrom(32, "GET /1m HTTP/1.1\r\nHost: localhos"..., 2048, 0, NULL, NULL) = 80
[pid 84809] openat(AT_FDCWD, "/tmp/unit-share/1m", O_RDONLY|O_NONBLOCK) = 33
[pid 84809] fstat(33, {st_mode=S_IFREG|0777, st_size=1048576, ...}) = 0
[pid 84809] mprotect(0x7f7bc0021000, 28672, PROT_READ|PROT_WRITE) = 0
[pid 84809] mprotect(0x7f7bc0028000, 135168, PROT_READ|PROT_WRITE) = 0
[pid 84809] pread64(33, "\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) = 131072
[pid 84809] pread64(33, "\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, 131072) = 131072
[pid 84809] writev(32, [{iov_base="HTTP/1.1 200 OK\r\nLast-Modified: "..., iov_len=173}, {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=131072}, {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=131072}], 3) = 262317
[pid 84809] pread64(33, "\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, 262144) = 131072
[pid 84809] pread64(33, "\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, 393216) = 131072
[pid 84809] writev(32, [{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=131072}, {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=131072}], 2) = 262144
[pid 84809] pread64(33, "\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, 524288) = 131072
[pid 84809] pread64(33, "\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, 655360) = 131072
[pid 84809] writev(32, [{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=131072}, {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=131072}], 2) = 262144
[pid 84809] pread64(33, "\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, 786432) = 131072
[pid 84809] pread64(33, "\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, 917504) = 131072
[pid 84809] close(33)                   = 0
[pid 84809] writev(32, [{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=131072}, {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=131072}], 2) = 262144
[pid 84809] setsockopt(32, SOL_TCP, TCP_NODELAY, [1], 4) = 0
[pid 84809] epoll_wait(14, [{events=EPOLLIN|EPOLLRDHUP, data={u32=3221235936, u64=140169478940896}}], 32, 179980) = 1
[pid 84809] recvfrom(32, "", 2048, 0, NULL, NULL) = 0
[pid 84809] epoll_ctl(14, EPOLL_CTL_DEL, 32, 0x5641a3208ca4) = 0
[pid 84809] epoll_wait(14, [], 32, 0)   = 0
[pid 84809] close(32)                   = 0
[pid 84809] epoll_wait(14,