Using a git checkout from a week or so ago. Trying to fully understand
the TS api to make my own wrapper protocol for reverse proxying, and
working through the protocol plugin as an example.
The issue I'm noticing is the protocol plugin is only sending back (to
the client) the first 4096 bytes of a file sent by the server. Actually
more correctly it seems like it is only writing the first 4096 bytes of
the file to cache, which is then subsequently read and sent to client.
I am guessing this is caused because the last parameter to TSVConnWrite
(the length) when writing to the cache for the first time is 4096. Which
is determined from the call to TSIOBufferReaderAvail just before it. The
buffer's size is only 4kb which is why it returns this value, yes?
So anyways I was under the impression that you made additional calls to
TSVIOReenable (q_cache_write_vio/q_server_read_vio) to refill the
buffers and complete the last vio action for that vc. Was I wrong? Or is
this functionality missing from the demo plugin?
I have included as an attachment the debug info from traffic.out while
running the plugin. You can see it seems to read all ~12kb of the file
from server and writes it to the cache. But on reading the cache it only
finds it is 4kb large. I have not modified the code besides some of the
reported debug statements in the attachment.
Any help would be appreciated.
[Jul 25 17:07:48.675] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 0)
[Jul 25 17:07:48.675] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd460)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 100)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fdb00)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) enter
state_interface_with_client
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) enter
state_read_request_from_client
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) Key material:
file name is 1892698240, ../../../proxy/logcat.cc*****
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 1103)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd730)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) enter
state_handle_cache_lookup
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) cache miss or
error!!!
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 1108)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd670)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) enter
state_handle_cache_prepare_for_write
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) enter
state_build_and_send_request
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) initiating host
lookup
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 500)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fddc0)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) enter
state_dns_lookup
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 200)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fcb30)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) enter
state_connect_to_server
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 103)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd390)
[Jul 25 17:07:48.676] Server {46980163213824} DIAG: (protocol) enter
state_send_request_to_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 100)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd110)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_interface_with_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_read_response_from_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) bytes avail from
server: 4096
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) bytes read is
4096, total response length is 4096
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 103)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd110)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_interface_with_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_write_to_cache
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) nbytes 4096,
ndone 4096
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol)
cache_response_length: 4096, block_bytes_read: 0
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) reenable
server_read_vio
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 100)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd110)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_interface_with_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_read_response_from_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) bytes avail from
server: 4096
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) bytes read is
4096, total response length is 8192
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 103)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd110)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_interface_with_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_write_to_cache
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) nbytes 4096,
ndone 4096
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol)
cache_response_length: 8192, block_bytes_read: 4096
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) reenable
server_read_vio
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 100)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd110)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_interface_with_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_read_response_from_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) bytes avail from
server: 2318
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) bytes read is
2318, total response length is 10510
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 104)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd110)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_interface_with_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) get server eos
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) close server_vc
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol)
cache_response_length is 8192, server response length is 10510
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 103)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd110)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_interface_with_server
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_write_to_cache
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) nbytes 4096,
ndone 4096
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol)
cache_response_length: 12288, block_bytes_read: 2318
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) close cache_vc,
cache_response_length is 12288, server_response_length is 10510
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 1102)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fd730)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_handle_cache_lookup
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) cache hit!!!
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) size of cached
object: 4096
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 102)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fdef0)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_handle_cache_read_response
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) entering
buffer_cache_data
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) loading 4096
bytes to buffer reader
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) done reading
from cache, closing cache_vc
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
send_response_to_client
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) response_len is
4096
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) main_handler
(contp 70CF1770 event 103)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) current_handler
(0x2aba757fdb00)
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_interface_with_client
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter
state_send_response_to_client
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) close client_vc,
write_complete: nbytes 4096, ndone 4096
[Jul 25 17:07:48.678] Server {46980163213824} DIAG: (protocol) enter state_done
