search

JuliaWeb / HTTP.jl

HTTP for Julia
https://juliaweb.github.io/HTTP.jl/stable/
Other
626 stars 177 forks source link

stream is closed or unusable #1141

Open gabfeldman opened 5 months ago

gabfeldman commented 5 months ago

Hi, I'm getting "stream is closed or unusable" repeatedly. My application tried to post to two different paths in the same server repeatedly. Usually one succeeds, but the other fails with this error. It's not always the same that succeeds and the same that fails. The server side is an Asp.Net application.

Turning on debug logging I noticed when it succeeds the connection status is 🔗 and when it fails it's 🔁. Does it mean the TCP connection is left open between HTTP POST's? Could this cause problems and is there a way to control it from the API?

Here are some logs. I edited/replaced hostname and paths, but kept them called path1 and path2 consistently with the original paths.

From a successful post:

┌ Debug: 2024-01-19 10:23:12 POST /edited/out/path1 HTTP/1.1 └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:23 ┌ Debug: 2024-01-19 10:23:12 client startwrite └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:24 ┌ Debug: 2024-01-19 10:23:12 👁 Start write:🔗 0s edited_out_hostname.com:80:34998 RawFD(40) └ @ HTTP.Connections /home/edited_out/.julia/packages/HTTP/bDoga/src/Connections.jl:254 ┌ Debug: 2024-01-19 10:23:12 HTTP.Messages.Request: │ """ │ POST /edited/out/path1 HTTP/1.1^M │ content-type: application/json^M │ accept: application/json^M │ Host: edited_out_hostname.com^M │ User-Agent: HTTP.jl/1.10.0^M │ Content-Length: 9088645^M │ Accept-Encoding: gzip^M │ ^M │ {"Values":[[2.4244589384637e-5,9.696970408467966e-8,-8.80839410348564e-5,-0.00026724486302313704,-0.00019090140656547578,-5.404007391480651e-5,-9.304158834005928e-5,5.652147934365198e-5,5.5513718809321515e-5,-3.090757969991526e-5,3.1132365302631656e-5,-0.00013491706069477695,-4.236164933711622e-5,-9.120336879653467e-5,-0.00013415773433824503,5.628862944039552e-6,-2.663748423494667e-8,-2.1396304067147203e-5,-6.247515363647575e-5,-4.452279418853024e-5,-1.2976746228763053e-5,-2.2533535655992695e-5,1.4381148469975124e-5,1.1509563179650563e-5,-3.1207485636840724e-6,8.445877230503955e-6,-3.510569200666959e-5,-8.350194723496513e-6,-1.7545404633175465e-5,-2.6188420401319724e-5,3.3623308698433272e-6,-3.2607846765901856e-8,-1.3153052921477944e-5,-3.746362406626858e-5,-2.6556017071356303e-5,-7.556372534068525e-6,-1.4542846634767061e-5,9.421185241031251e-6,4.886469598905069e-6,-2.311813369337166e-6,3.6869433015437685e-6,-2.2190522877299942e-5,-4.104317798195921e-6,-8.365968531193128e-6,-1.51289909 │ ⋮ │ 9088645-byte body │ """ └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:28 ┌ Debug: 2024-01-19 10:23:12 client startread └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:50 ┌ Debug: 2024-01-19 10:23:12 👁 Start read: 🔗 0s edited_out_hostname.com:80:34998 RawFD(40) └ @ HTTP.Connections /home/edited_out/.julia/packages/HTTP/bDoga/src/Connections.jl:278 ┌ Debug: 2024-01-19 10:23:13 client closewrite └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:45 ┌ Debug: 2024-01-19 10:23:13 🗣 Write done: 🔁 1s edited_out_hostname.com:80:34998 RawFD(40) └ @ HTTP.Connections /home/edited_out/.julia/packages/HTTP/bDoga/src/Connections.jl:266

And from a failed one:

┌ Debug: 2024-01-19 10:23:22 POST /edited/out/path2 HTTP/1.1 └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:23 ┌ Debug: 2024-01-19 10:23:22 client startwrite └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:24 ┌ Debug: 2024-01-19 10:23:22 👁 Start write:🔁 8s edited_out_hostname.com:80:34998 RawFD(40) └ @ HTTP.Connections /home/edited_out/.julia/packages/HTTP/bDoga/src/Connections.jl:254 ┌ Debug: 2024-01-19 10:23:22 💀 Closed: eof 8s edited_out_hostname.com:80:34998 RawFD(40) └ @ HTTP.Connections /home/edited_out/.julia/packages/HTTP/bDoga/src/Connections.jl:289 ┌ Debug: 2024-01-19 10:23:22 HTTP.Messages.Request: │ """ │ POST /edited/out/path2 HTTP/1.1^M │ content-type: application/json^M │ accept: application/json^M │ Host: edited_out_hostname.com^M │ User-Agent: HTTP.jl/1.10.0^M │ Content-Length: 6032518^M │ Accept-Encoding: gzip^M │ ^M │ {"Values":[[2.393793453691377e-5,9.545363554596088e-8,-8.655711259838417e-5,-0.000262692181768706,-0.00018764659291458833,-5.3079466484524726e-5,-9.144217545186659e-5,5.556290256278702e-5,5.454424511261431e-5,-3.0337772895754204e-5,3.0482839607088956e-5,-0.00013255714790542868,-4.1687875118608e-5,-8.973551156481332e-5,-0.0001319920583818794,5.556277814129511e-6,-3.420519228842148e-8,-2.0679162111560757e-5,-6.205574567524804e-5,-4.408353644436498e-5,-1.1837697841165481e-5,-2.198184599398522e-5,1.3183960075450835e-5,1.1300547431143497e-5,-7.5869050467696286e-6,8.203089279827627e-6,-3.157937642435901e-5,-8.862549392087204e-6,-1.9127087303785503e-5,-2.835073174770801e-5,3.318459088438068e-6,-4.305346964101777e-8,-1.2583113265601298e-5,-3.749011489078789e-5,-2.633615024229091e-5,-6.491294474961445e-6,-1.4331460729596983e-5,8.367768068354828e-6,5.232715743761399e-6,-4.112015363191306e-6,2.968108118320425e-6,-2.001507369102215e-5,-5.398033187707887e-6,-1.1154281402770293e-5,-1.626108209837682 │ ⋮ │ 6032518-byte body │ """ └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:28 ┌ Debug: 2024-01-19 10:23:22 client startread └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:50 ┌ Debug: 2024-01-19 10:23:22 👁 Start read: 💀 0s edited_out_hostname.com:80:34998 RawFD(4294967295) └ @ HTTP.Connections /home/edited_out/.julia/packages/HTTP/bDoga/src/Connections.jl:278 ┌ Debug: 2024-01-19 10:23:22 client closeread └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:59 ┌ Debug: 2024-01-19 10:23:22 client closewrite └ @ HTTP.StreamRequest /home/edited_out/.julia/packages/HTTP/bDoga/src/clientlayers/StreamRequest.jl:45 ┌ Debug: 2024-01-19 10:23:22 ✉️ Read done: 💀 0s edited_out_hostname.com:80:34998 RawFD(4294967295) └ @ HTTP.Connections /home/edited_out/.julia/packages/HTTP/bDoga/src/Connections.jl:307 ┌ Debug: 2024-01-19 10:23:22 🗣 Write done: 💀 0s edited_out_hostname.com:80:34998 RawFD(4294967295) └ @ HTTP.Connections /home/edited_out/.julia/packages/HTTP/bDoga/src/Connections.jl:266

omus commented 4 months ago

HTTP.jl uses connection pooling so it attempts to keep TCP connections open for repeat requests. I've also seen similar problems. From my investigation it seems that:

┌ Debug: 2024-01-19 10:23:22 💀 Closed: eof 8s edited_out_hostname.com:80:34998 RawFD(40)
└ @ HTTP.Connections /home/edited_out/.julia/packages/HTTP/bDoga/src/Connections.jl:289

indicates that the server has closed the connection for RawFD(40). From this point on the FD will show RawFD(4294967295).

Later on we attempt to use this connection again to read/write. Messages such as:

┌ Debug: 2024-01-19 10:23:22 ✉️ Read done: 💀 0s edited_out_hostname.com:80:34998 RawFD(4294967295)
└ @ HTTP.Connections /home/edited_out/.julia/packages/HTTP/bDoga/src/Connections.jl:307

Show the connection status as 💀 which means the connection is closed.

If you are waiting a long time between your requests possibly setting an idle_timeout value could help. In my particular case the failed connection occurs ~30 seconds after a successful one.

omus commented 4 months ago

If you can modify you server settings you may see less issues if you can increase the connection keep-alive timeout on the server side. I had a Node.js server which was only keeping persistent connections open for 5 seconds.

omus commented 4 months ago

I believe this is an internal HTTP.jl issue in that the monitor_idle_connection call happens on a separate thread the connection can be closed and another thread will attempt to read/write to that closed connection.