search

ptpb / pb

pb is a formerly-lightweight pastebin and url shortener
Other
549 stars 52 forks source link

curl: (18) transfer closed with 822159 bytes remaining to read #219

Closed buhman closed 6 years ago

buhman commented 6 years ago 
λ zack [~] → curl https://ptpb.pw/HP3Y > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 53 29.5M   53 15.9M    0     0  6281k      0  0:00:04  0:00:02  0:00:02 6279k
curl: (18) transfer closed with 14364700 bytes remaining to read
λ zack [~] → curl https://ptpb.pw/HP3Y > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 79 29.5M   79 23.5M    0     0  7560k      0  0:00:04  0:00:03  0:00:01 7560k
curl: (18) transfer closed with 6365097 bytes remaining to read
λ zack [~] → curl https://ptpb.pw/HP3Y > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 80 29.5M   80 23.7M    0     0  5191k      0  0:00:05  0:00:04  0:00:01 5191k
curl: (18) transfer closed with 6130106 bytes remaining to read
λ zack [~] → curl https://ptpb.pw/HP3Y > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 96 29.5M   96 28.4M    0     0  7713k      0  0:00:03  0:00:03 --:--:-- 7711k
curl: (18) transfer closed with 1204486 bytes remaining to read
λ zack [~] → curl https://ptpb.pw/HP3Y > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 96 29.5M   96 28.5M    0     0  9555k      0  0:00:03  0:00:03 --:--:-- 9555k
curl: (18) transfer closed with 1065720 bytes remaining to read
λ zack [~] → curl https://ptpb.pw/HP3Y > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 96 29.5M   96 28.6M    0     0  11.1M      0  0:00:02  0:00:02 --:--:-- 11.1M
curl: (18) transfer closed with 975512 bytes remaining to read
λ zack [~] → curl https://ptpb.pw/HP3Y > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 97 29.5M   97 28.8M    0     0  8693k      0  0:00:03  0:00:03 --:--:-- 8693k
curl: (18) transfer closed with 822159 bytes remaining to read
λ zack [~] → curl https://ptpb.pw/HP3Y > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 29.5M  100 29.5M    0     0  8959k      0  0:00:03  0:00:03 --:--:-- 8956k
buhman commented 6 years ago 
May 30 06:03:35 ptpb nginx[1558]: 2018/05/30 06:03:35 [error] 2532#2532: *1774386 upstream prematurely closed connection while reading upstream, client: 2601:645:8004:1bc0::a358, server: _, request: "GET /HP3Y.webm HTTP/1.1", upstream: "http://127.0.0.1:6081/HP3Y.webm", host: "ptpb.pw", referrer: "https://ptpb.pw/HP3Y.webm"
buhman commented 6 years ago 
May 30 06:05:19 ptpb uwsgi[3901]: Wed May 30 06:05:19 2018 - uwsgi_response_write_body_do(): Connection reset by peer [core/writer.c line 331] during GET /HP3Y.webm (0.0.0.0)
May 30 06:05:19 ptpb uwsgi[3901]: OSError: write error

lovely

buhman commented 6 years ago 
root@ptpb:~# varnishlog -g request -q "ReqUrl eq '/HP3Y.webm'"
*   << Request  >> 5521326   
-   Begin          req 5521325 rxreq
-   Timestamp      Start: 1527662074.867364 0.000000 0.000000
-   Timestamp      Req: 1527662074.867364 0.000000 0.000000
-   ReqStart       127.0.0.1 56372
-   ReqMethod      GET
-   ReqURL         /HP3Y.webm
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: ptpb.pw
-   ReqHeader      X-Forwarded-Proto: https
-   ReqHeader      Connection: close
-   ReqHeader      User-Agent: curl/7.60.0
-   ReqHeader      Accept: */*
-   ReqHeader      X-Forwarded-For: 127.0.0.1
-   VCL_call       RECV
-   VCL_return     hash
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 5521327 fetch
-   Timestamp      Fetch: 1527662075.097471 0.230107 0.230107
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Content-Type: video/webm
-   RespHeader     Content-Length: 31037417
-   RespHeader     ETag: "paste-3b5cae45f1e6310e9facb0be91afe03f651cfdd8"
-   RespHeader     Cache-Control: public, max-age=43200
-   RespHeader     Date: Wed, 30 May 2018 06:34:35 GMT
-   RespHeader     X-Varnish: 5521326
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   VCL_return     deliver
-   Timestamp      Process: 1527662075.097488 0.230124 0.000017
-   RespHeader     Accept-Ranges: bytes
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1527662075.099180 0.231817 0.001693
-   ReqAcct        125 0 125 292 467513 467805
-   End            
**  << BeReq    >> 5521327   
--  Begin          bereq 5521326 fetch
--  Timestamp      Start: 1527662074.867496 0.000000 0.000000
--  BereqMethod    GET
--  BereqURL       /HP3Y.webm
--  BereqProtocol  HTTP/1.1
--  BereqHeader    Host: ptpb.pw
--  BereqHeader    X-Forwarded-Proto: https
--  BereqHeader    User-Agent: curl/7.60.0
--  BereqHeader    Accept: */*
--  BereqHeader    X-Forwarded-For: 127.0.0.1
--  BereqHeader    Accept-Encoding: gzip
--  BereqHeader    X-Varnish: 5521327
--  VCL_call       BACKEND_FETCH
--  VCL_return     fetch
--  BackendOpen    18 boot.default ::1 10002 ::1 43888
--  Timestamp      Bereq: 1527662074.867704 0.000208 0.000208
--  Timestamp      Beresp: 1527662075.097348 0.229852 0.229644
--  BerespProtocol HTTP/1.1
--  BerespStatus   200
--  BerespReason   OK
--  BerespHeader   Content-Type: video/webm
--  BerespHeader   Content-Length: 31037417
--  BerespHeader   ETag: "paste-3b5cae45f1e6310e9facb0be91afe03f651cfdd8"
--  BerespHeader   Cache-Control: public, max-age=43200
--  BerespHeader   Date: Wed, 30 May 2018 06:34:35 GMT
--  BerespHeader   Accept-Ranges: none
--  TTL            RFC 43200 10 -1 1527662075 1527662075 1527662075 0 43200
--  VCL_call       BACKEND_RESPONSE
--  VCL_return     deliver
--  Storage        malloc s0
--  ObjProtocol    HTTP/1.1
--  ObjStatus      200
--  ObjReason      OK
--  ObjHeader      Content-Type: video/webm
--  ObjHeader      Content-Length: 31037417
--  ObjHeader      ETag: "paste-3b5cae45f1e6310e9facb0be91afe03f651cfdd8"
--  ObjHeader      Cache-Control: public, max-age=43200
--  ObjHeader      Date: Wed, 30 May 2018 06:34:35 GMT
--  Fetch_Body     3 length stream
--  ExpKill        LRU_Cand p=0x7f0ebc9bf600 f=0x0 r=1
--  ExpKill        LRU x=5245884
--  ExpKill        LRU_Cand p=0x7f0ebc9b6fc0 f=0x0 r=1
--  ExpKill        LRU x=4598182
--  ExpKill        LRU_Cand p=0x7f0ebc9b7740 f=0x0 r=1
--  ExpKill        LRU x=5245887
--  ExpKill        LRU_Cand p=0x7f0ebc9b7080 f=0x0 r=1
--  ExpKill        LRU x=4598185
--  ExpKill        LRU_Cand p=0x7f0ed6ba6d80 f=0x0 r=1
--  ExpKill        LRU x=5245890
--  ExpKill        LRU_Cand p=0x7f0ebc9b7680 f=0x0 r=1
--  ExpKill        LRU x=5245893
--  ExpKill        LRU_Cand p=0x7f0ebc9b7140 f=0x0 r=1
--  ExpKill        LRU x=4598188
--  ExpKill        LRU_Cand p=0x7f0ebc9b7200 f=0x0 r=1
--  ExpKill        LRU x=4598191
--  ExpKill        LRU_Cand p=0x7f0e9bbebc00 f=0x0 r=1
--  ExpKill        LRU x=5245896
--  ExpKill        LRU_Cand p=0x7f0ebc9b72c0 f=0x0 r=1
--  ExpKill        LRU x=4598194
--  ExpKill        LRU_Cand p=0x7f0ebc9bf540 f=0x0 r=1
--  ExpKill        LRU x=5245899
--  ExpKill        LRU_Cand p=0x7f0eba668b00 f=0x0 r=1
--  ExpKill        LRU x=5245902
--  ExpKill        LRU_Cand p=0x7f0ebc9b81c0 f=0x0 r=1
--  ExpKill        LRU x=4598197
--  ExpKill        LRU_Cand p=0x7f0ebc9b8280 f=0x0 r=1
--  ExpKill        LRU x=4598200
--  ExpKill        LRU_Cand p=0x7f0ed6ba6cc0 f=0x0 r=1
--  ExpKill        LRU x=5245905
--  ExpKill        LRU_Cand p=0x7f0ebc9b8700 f=0x0 r=1
--  ExpKill        LRU x=4598203
--  ExpKill        LRU_Cand p=0x7f0ee4fd9d40 f=0x0 r=1
--  ExpKill        LRU x=5245908
--  ExpKill        LRU_Cand p=0x7f0ebc9b8a00 f=0x0 r=1
--  ExpKill        LRU x=4598206
--  ExpKill        LRU_Cand p=0x7f0ea0b3d280 f=0x0 r=1
--  ExpKill        LRU x=5245911
--  ExpKill        LRU_Cand p=0x7f0ebc9b8b80 f=0x0 r=1
--  ExpKill        LRU x=4598209
--  ExpKill        LRU_Cand p=0x7f0ebc9bf480 f=0x0 r=1
--  ExpKill        LRU x=5245914
--  ExpKill        LRU_Cand p=0x7f0ebc9b8c40 f=0x0 r=1
--  ExpKill        LRU x=4598212
--  ExpKill        LRU_Cand p=0x7f0ebc9bf3c0 f=0x0 r=1
--  ExpKill        LRU x=5245917
--  ExpKill        LRU_Cand p=0x7f0eba9c0100 f=0x0 r=1
--  ExpKill        LRU x=5150506
--  ExpKill        LRU_Cand p=0x7f0eb4becd00 f=0x0 r=1
--  ExpKill        LRU x=5245920
--  ExpKill        LRU_Cand p=0x7f0eba9c01c0 f=0x0 r=1
--  ExpKill        LRU x=5150509
--  ExpKill        LRU_Cand p=0x7f0eb4becc40 f=0x0 r=1
--  ExpKill        LRU x=5245923
--  ExpKill        LRU_Cand p=0x7f0eba9c0280 f=0x0 r=1
--  ExpKill        LRU x=5150512
--  ExpKill        LRU_Cand p=0x7f0ee4fd9c80 f=0x0 r=1
--  ExpKill        LRU x=5245926
--  ExpKill        LRU_Cand p=0x7f0eba9c0340 f=0x0 r=1
--  ExpKill        LRU x=5150515
--  ExpKill        LRU_Cand p=0x7f0ea0b3d1c0 f=0x0 r=1
--  ExpKill        LRU x=5245929
--  ExpKill        LRU_Cand p=0x7f0ec4f87780 f=0x0 r=1
--  ExpKill        LRU x=4825595
--  ExpKill        LRU_Cand p=0x7f0eb4becb80 f=0x0 r=1
--  ExpKill        LRU x=5245932
--  ExpKill        LRU_Cand p=0x7f0eba9c0400 f=0x0 r=1
--  ExpKill        LRU x=5150518
--  ExpKill        LRU_Cand p=0x7f0ea0b3d100 f=0x0 r=1
--  ExpKill        LRU x=5245935
--  ExpKill        LRU_Cand p=0x7f0eba9c04c0 f=0x0 r=1
--  ExpKill        LRU x=5150521
--  ExpKill        LRU_Cand p=0x7f0eb4becac0 f=0x0 r=1
--  ExpKill        LRU x=5245938
--  ExpKill        LRU_Cand p=0x7f0eba9c0580 f=0x0 r=1
--  ExpKill        LRU x=5150524
--  ExpKill        LRU_Cand p=0x7f0eba668a40 f=0x0 r=1
--  ExpKill        LRU x=5245941
--  ExpKill        LRU_Cand p=0x7f0eba9c0640 f=0x0 r=1
--  ExpKill        LRU x=5150527
--  ExpKill        LRU_Cand p=0x7f0ebc9bf300 f=0x0 r=1
--  ExpKill        LRU x=5245944
--  ExpKill        LRU_Cand p=0x7f0ebc9b8d00 f=0x0 r=1
--  ExpKill        LRU x=4598215
--  ExpKill        LRU_Cand p=0x7f0eba668980 f=0x0 r=1
--  ExpKill        LRU x=5245947
--  ExpKill        LRU_Cand p=0x7f0ebc9b8dc0 f=0x0 r=1
--  ExpKill        LRU x=4598218
--  ExpKill        LRU_Cand p=0x7f0eba6688c0 f=0x0 r=1
--  ExpKill        LRU x=5245950
--  ExpKill        LRU_Cand p=0x7f0ec24860c0 f=0x0 r=1
--  ExpKill        LRU x=4598221
--  ExpKill        LRU_Cand p=0x7f0ebc9b75c0 f=0x0 r=1
--  ExpKill        LRU x=5245953
--  ExpKill        LRU_Cand p=0x7f0ec2486180 f=0x0 r=1
--  ExpKill        LRU x=4598224
--  ExpKill        LRU_Cand p=0x7f0ebc9bf240 f=0x0 r=1
--  ExpKill        LRU x=5245956
--  ExpKill        LRU_Cand p=0x7f0ec2486240 f=0x0 r=1
--  ExpKill        LRU x=4598227
--  ExpKill        LRU_Cand p=0x7f0ebc9b7500 f=0x0 r=1
--  ExpKill        LRU x=5245959
--  ExpKill        LRU_Cand p=0x7f0ec2486300 f=0x0 r=1
--  ExpKill        LRU x=4598230
--  ExpKill        LRU_Cand p=0x7f0eba668800 f=0x0 r=1
--  ExpKill        LRU x=5245962
--  ExpKill        LRU_Cand p=0x7f0ec2486a80 f=0x0 r=1
--  ExpKill        LRU x=4598233
--  ExpKill        LRU_Cand p=0x7f0ea0b3d040 f=0x0 r=1
--  ExpKill        LRU x=5245965
--  ExpKill        LRU_Cand p=0x7f0ec2486b40 f=0x0 r=1
--  ExpKill        LRU x=4598236
--  ExpKill        LRU_Cand p=0x7f0ebc9bf180 f=0x0 r=1
--  ExpKill        LRU x=5245968
--  ExpKill        LRU_Cand p=0x7f0ec2486c00 f=0x0 r=1
--  ExpKill        LRU x=4598239
--  ExpKill        LRU_Cand p=0x7f0ea0b3cf80 f=0x0 r=1
--  ExpKill        LRU x=5245971
--  ExpKill        LRU_Cand p=0x7f0ebc9bf0c0 f=0x0 r=1
--  ExpKill        LRU x=5245974
--  ExpKill        LRU_Cand p=0x7f0ec2486cc0 f=0x0 r=1
--  ExpKill        LRU x=4598242
--  ExpKill        LRU_Cand p=0x7f0ec2486d80 f=0x0 r=1
--  ExpKill        LRU x=4598245
--  ExpKill        LRU_Cand p=0x7f0ea0b3cec0 f=0x0 r=1
--  ExpKill        LRU x=5245977
--  ExpKill        LRU_Cand p=0x7f0ec2486e40 f=0x0 r=1
--  ExpKill        LRU x=4598248
--  ExpKill        LRU_Cand p=0x7f0ed6ba6c00 f=0x0 r=1
--  ExpKill        LRU x=5245980
--  ExpKill        LRU_Cand p=0x7f0ec2486f00 f=0x0 r=1
--  ExpKill        LRU x=4598251
--  ExpKill        LRU_Cand p=0x7f0ebc9b7440 f=0x0 r=1
--  ExpKill        LRU x=5245983
--  ExpKill        LRU_Cand p=0x7f0ec2486fc0 f=0x0 r=1
--  ExpKill        LRU x=4598254
--  ExpKill        LRU_Cand p=0x7f0eb4beca00 f=0x0 r=1
--  ExpKill        LRU x=5245986
--  ExpKill        LRU_Cand p=0x7f0ec2487080 f=0x0 r=1
--  ExpKill        LRU x=4598257
--  ExpKill        LRU_Cand p=0x7f0ec2487140 f=0x0 r=1
--  ExpKill        LRU x=4598260
--  ExpKill        LRU_Cand p=0x7f0ebc9b7380 f=0x0 r=1
--  ExpKill        LRU x=5245989
--  ExpKill        LRU_Cand p=0x7f0eda7a2a80 f=0x0 r=1
--  ExpKill        LRU x=5445237
--  FetchError     Could not get storage
--  BackendClose   18 boot.default
--  BereqAcct      177 0 177 223 467513 467736
--  End
buhman commented 6 years ago

I restarted varnish and the problem vanished:

root@ptpb:~# varnishlog -g request -q "ReqUrl eq '/HP3Y.webm'"
*   << Request  >> 5         
-   Begin          req 4 rxreq
-   Timestamp      Start: 1527662399.626231 0.000000 0.000000
-   Timestamp      Req: 1527662399.626231 0.000000 0.000000
-   ReqStart       127.0.0.1 56584
-   ReqMethod      GET
-   ReqURL         /HP3Y.webm
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Host: ptpb.pw
-   ReqHeader      X-Forwarded-Proto: https
-   ReqHeader      Connection: close
-   ReqHeader      User-Agent: curl/7.60.0
-   ReqHeader      Accept: */*
-   ReqHeader      X-Forwarded-For: 127.0.0.1
-   VCL_call       RECV
-   VCL_return     hash
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 6 fetch
-   Timestamp      Fetch: 1527662399.880366 0.254135 0.254135
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Content-Type: video/webm
-   RespHeader     Content-Length: 31037417
-   RespHeader     ETag: "paste-3b5cae45f1e6310e9facb0be91afe03f651cfdd8"
-   RespHeader     Cache-Control: public, max-age=43200
-   RespHeader     Date: Wed, 30 May 2018 06:39:59 GMT
-   RespHeader     X-Varnish: 5
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   VCL_return     deliver
-   Timestamp      Process: 1527662399.880390 0.254159 0.000024
-   RespHeader     Accept-Ranges: bytes
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1527662399.926859 0.300628 0.046469
-   ReqAcct        125 0 125 286 31037417 31037703
-   End            
**  << BeReq    >> 6         
--  Begin          bereq 5 fetch
--  Timestamp      Start: 1527662399.626338 0.000000 0.000000
--  BereqMethod    GET
--  BereqURL       /HP3Y.webm
--  BereqProtocol  HTTP/1.1
--  BereqHeader    Host: ptpb.pw
--  BereqHeader    X-Forwarded-Proto: https
--  BereqHeader    User-Agent: curl/7.60.0
--  BereqHeader    Accept: */*
--  BereqHeader    X-Forwarded-For: 127.0.0.1
--  BereqHeader    Accept-Encoding: gzip
--  BereqHeader    X-Varnish: 6
--  VCL_call       BACKEND_FETCH
--  VCL_return     fetch
--  BackendOpen    18 boot.default ::1 10002 ::1 44100
--  Timestamp      Bereq: 1527662399.626517 0.000180 0.000180
--  Timestamp      Beresp: 1527662399.880246 0.253908 0.253728
--  BerespProtocol HTTP/1.1
--  BerespStatus   200
--  BerespReason   OK
--  BerespHeader   Content-Type: video/webm
--  BerespHeader   Content-Length: 31037417
--  BerespHeader   ETag: "paste-3b5cae45f1e6310e9facb0be91afe03f651cfdd8"
--  BerespHeader   Cache-Control: public, max-age=43200
--  BerespHeader   Date: Wed, 30 May 2018 06:39:59 GMT
--  BerespHeader   Accept-Ranges: none
--  TTL            RFC 43200 10 -1 1527662400 1527662400 1527662399 0 43200
--  VCL_call       BACKEND_RESPONSE
--  VCL_return     deliver
--  Storage        malloc s0
--  ObjProtocol    HTTP/1.1
--  ObjStatus      200
--  ObjReason      OK
--  ObjHeader      Content-Type: video/webm
--  ObjHeader      Content-Length: 31037417
--  ObjHeader      ETag: "paste-3b5cae45f1e6310e9facb0be91afe03f651cfdd8"
--  ObjHeader      Cache-Control: public, max-age=43200
--  ObjHeader      Date: Wed, 30 May 2018 06:39:59 GMT
--  Fetch_Body     3 length stream
--  BackendReuse   18 boot.default
--  Timestamp      BerespBody: 1527662399.915772 0.289434 0.035526
--  Length         31037417
--  BereqAcct      171 0 171 223 31037417 31037640
--  End
buhman commented 6 years ago

Interpretation:

http://varnish-misc.varnish-cache.narkive.com/tUrH8ayo/question-about-an-lru-error

There were tons of tiny un-expired objects in varnish LRU cache, and not enough room for a large ~30MB object, and the number of object deletions exceeded nuke_limit.

To reduce the probability of this happening again, I:

Handwavingly, this should probably be ok, but if not I'll have to do actual math and observation.

buhman commented 6 years ago

Though not directly related to the actual problem,

Also disabled nginx proxy temporary file creation, as this is redundant due to proxying to varnish (proxy_request_buffering was already off, but openresty still had messages about creating temporary files anyway).