Forum OpenACS Q&A: Re: How to correctly configure the reverse proxy.

Collapse
6: Re: How to correctly configure the reverse proxy. (response to 1)
Posted by Tony Kirkham on 03/19/21 05:13 AM

Another few weeks have gone by and I am back to working this.

After turning up the logging with : ns_logctl severity Debug(connchan) 1 I can now see the following when I attempt to upload a larger file:

... ; #
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: Inside validation call back pmd::val_call
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend sent 1325 bytes <Success>
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan open http://server-name/package/api/program/12345/logo?user_id=555 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0

... ; # it starts out okay with 10 of these lines that appear to show good sends

[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: partial write operation, sent 14120 instead of 16000 bytes
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: would block, no timeout configured, origLength 16000 still to send 1880 already sent 14120
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: would block, no timeout configured, origLength 16000 still to send 16000 already sent 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0

... ; # then something appears to break with the "partial write operation" and we have 23 of the "would block, no timeout configured" lines

[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: would block, no timeout configured, origLength 16000 still to send 16000 already sent 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: would block, no timeout configured, origLength 16000 still to send 16000 already sent 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: would block, no timeout configured, origLength 16000 still to send 16000 already sent 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0

... ; # followed by 10 lines that seem to succeed

[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: partial write operation, sent 728 instead of 16000 bytes
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: would block, no timeout configured, origLength 16000 still to send 15272 already sent 728
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: would block, no timeout configured, origLength 16000 still to send 16000 already sent 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0

... ; # followed by 8 failing lines which account for the 51 sends that I see with the reduced logging which I posted earlier in this thread.

[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: would block, no timeout configured, origLength 16000 still to send 16000 already sent 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: upstream: send max 16000 bytes from string to conn90 (length 808989)
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): DriverSend conn90: would block, no timeout configured, origLength 8989 still to send 8989 already sent 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan write conn90 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ConnChanDetachObjCmd sock 7
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan detach conn91 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Notice: PROXY: backendChan conn90 frontendChan conn91 method POST version 1.0 http://server-name/package/api/program/12345/logo?user_id=555
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan callback conn91 returns 0
[18/Mar/2021:12:39:06][1.7f799d60a700][-conn:server_name:3:3424-] Debug(connchan): ns_connchan callback conn90 returns 0
[18/Mar/2021:12:39:16][1.7f7957fff700][-socks-] Debug(connchan): NsTclConnChanProc why 64
[18/Mar/2021:12:39:16][1.7f7957fff700][-socks-] Debug(connchan): ns_connchan exists conn91 returns 0
[18/Mar/2021:12:39:16][1.7f7957fff700][-socks-] Debug(connchan): ns_connchan exists conn90 returns 0
[18/Mar/2021:12:39:16][1.7f7957fff700][-socks-] Notice: PROXY: spool from conn91 (exists 1) to conn90 (exists 1): condition t
... ; #

So now I can see that there are periods where there are what appears to be successful transfers and periods where there is a partial write and then the following sends fail with "would block, no timeout configured". I am working on increasing the Node logging, but have not gotten there.

The error I can see on the NaviServer side indicates that there is something interferring with the send at times, but that it clears after a little bit and that there is a way to configure for a longer timeout for this case. As I have indicated in an earlier post in this thread, I have tried to set the only timeouts I know of without any success.

What timeout configuration is this warning referring to?

We are planning to get to NaviServer/4.99.20 sometime soon, but if possible we need to get this working with what we have.

Thank you for any assistance you can give. I really appreciate it.

-Tony