Proxy not reusing sessions for first batch of recover requests

[zhukaihan]

Hello!

We deployed an instance of pushpin on our kubernetes cluster with hint and poll for pushing data down SSE streams. We observed that, after a hint, it's going to send a recover request for each client connected. We know that pushpin aggregates/reuse requests on proxy level using sharing-key. However, it's only happening in kubernetes deployment, not with local docker container. It could also happen on local with docker's kubernetes enabled (not 100% sure about this).

After digging deeper, we see that the difference is in inspect not available log from proxy. We also see the ordering of logs is different. The proxy determines inspect not available before a zrpc sends and receives sharing-key.

The first "batch" of proxy request is going to have inspect not available for each request after a hint. Subsequent "batches" reuses proxy sessions as expected.

This happens on 1.38.0. We reverted to use 1.34.0 (that has zurl) and no longer sees this behavior (didn't test out 1.35.0, 1.36.0, or 1.37.0).

The log below has 4 clients connected to pushpin with param max_open_sessions=2. It is showing the first "batch" of recovery requests for 2 clients.
We see the proxy determines inspect not available and creating proxysession before it receives sharing-key from zrpc server, which seems to be the wrong order.

        [DEBUG] 2024-03-08 19:10:23.175 [proxy] zhttp/zws server: IN { "passthrough": { "trusted": true, "prefer-internal": true, "auto-share": true, "route": "*,*,*,*" }, "seq": 0, "id": "7d76447b-9e0c-4a29-a387-ac00ebcda1ab", "credits": 200000, "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ] ], "ext": { "multi": true }, "from": "pushpin-handler_10", "stream": true }
        [DEBUG] 2024-03-08 19:10:23.175 [proxy] IN id=7d76447b-9e0c-4a29-a387-ac00ebcda1ab, GET http://localhost:7999/recover/1_289220_996_
        [DEBUG] 2024-03-08 19:10:23.175 [proxy] requestsession: 0xaaab066e51c0 localhost has 1 routes
        
        [DEBUG] 2024-03-08 19:10:23.176 [proxy] zhttp/zws server: IN { "passthrough": { "trusted": true, "prefer-internal": true, "auto-share": true, "route": "*,*,*,*" }, "seq": 0, "id": "2b8ef8e7-5526-42c1-b8a5-afffec407262", "credits": 200000, "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ] ], "ext": { "multi": true }, "from": "pushpin-handler_10", "stream": true }
        [DEBUG] 2024-03-08 19:10:23.176 [proxy] IN id=2b8ef8e7-5526-42c1-b8a5-afffec407262, GET http://localhost:7999/recover/1_289220_996_
        [DEBUG] 2024-03-08 19:10:23.179 [proxy] requestsession: 0xaaab066db8a0 localhost has 1 routes
        
        [DEBUG] 2024-03-08 19:10:23.180 [proxy] zhttp/zws server: IN { "passthrough": { "trusted": true, "prefer-internal": true, "auto-share": true, "route": "*,*,*,*" }, "seq": 0, "id": "e7ab7436-c2a9-4425-8d38-ad3205f1a0e5", "credits": 200000, "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ] ], "ext": { "multi": true }, "from": "pushpin-handler_10", "stream": true }
        [DEBUG] 2024-03-08 19:10:23.180 [proxy] zhttp/zws server: IN { "passthrough": { "trusted": true, "prefer-internal": true, "auto-share": true, "route": "*,*,*,*" }, "seq": 0, "id": "6463261a-d8dc-47f2-9dd7-3b8d7df49314", "credits": 200000, "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ] ], "ext": { "multi": true }, "from": "pushpin-handler_10", "stream": true }
        
        [DEBUG] 2024-03-08 19:10:23.180 [proxy] zhttp server: OUT pushpin-handler_10 { "id": "7d76447b-9e0c-4a29-a387-ac00ebcda1ab", "seq": 0, "type": "keep-alive", "ext": { "multi": true }, "from": "pushpin-proxy_9" }
->        [DEBUG] 2024-03-08 19:10:23.180 [proxy] inspect not available
        
        [DEBUG] 2024-03-08 19:10:23.180 [proxy] zhttp server: OUT pushpin-handler_10 { "id": "2b8ef8e7-5526-42c1-b8a5-afffec407262", "seq": 0, "type": "keep-alive", "ext": { "multi": true }, "from": "pushpin-proxy_9" }
        [DEBUG] 2024-03-08 19:10:23.180 [proxy] inspect not available
        
->        [DEBUG] 2024-03-08 19:10:23.181 [proxy] zrpc client: OUT { "id": "d88406b1-7c74-44f5-9945-a7b8dc03a0af", "args": { "body": "", "auto-share": true, "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ] ] }, "method": "inspect" }
->        [DEBUG] 2024-03-08 19:10:23.181 [proxy] creating proxysession for id=7d76447b-9e0c-4a29-a387-ac00ebcda1ab
        [DEBUG] 2024-03-08 19:10:23.181 [proxy] proxysession: 0xaaab066e1b40 forwarding to 172.111.111.111:8080
        
        [DEBUG] 2024-03-08 19:10:23.181 [proxy] zrpc client: OUT { "id": "243bf7bc-97f0-47e7-8f50-5b71cc3da587", "args": { "body": "", "auto-share": true, "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ] ] }, "method": "inspect" }
        [DEBUG] 2024-03-08 19:10:23.181 [proxy] creating proxysession for id=2b8ef8e7-5526-42c1-b8a5-afffec407262
        [DEBUG] 2024-03-08 19:10:23.181 [proxy] proxysession: 0xaaab066fce90 forwarding to 172.111.111.111:8080
        
        [DEBUG] 2024-03-08 19:10:23.182 [proxy] zhttp client: OUT { "id": "c405cd07-12b6-4bc8-b77b-f5e3b3af8c4a", "seq": 0, "credits": 200000, "connect-port": 8080, "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ], [ "Grip-Sig", "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJleHAiOjE3MDk5Mjg2MjMsImlzcyI6InB1c2hwaW4ifQ.Ir7O5wfWuTWC4dl7_clnfqkyEnlns1gN1bkeRkjpK0k" ], [ "Grip-Feature", "status, session, link:next, filter:skip-self, filter:skip-users, filter:require-sub, filter:build-id, filter:var-subst" ], [ "Host", "localhost:7999" ] ], "ignore-policies": true, "ext": { "multi": true }, "from": "pushpin-proxy_9", "stream": true, "connect-host": "172.111.111.111" }
        [DEBUG] 2024-03-08 19:10:23.182 [proxy] zhttp client: OUT { "id": "30250e68-167d-4d1f-814d-2d22011b6e75", "seq": 0, "credits": 200000, "connect-port": 8080, "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ], [ "Grip-Sig", "eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJleHAiOjE3MDk5Mjg2MjMsImlzcyI6InB1c2hwaW4ifQ.Ir7O5wfWuTWC4dl7_clnfqkyEnlns1gN1bkeRkjpK0k" ], [ "Grip-Feature", "status, session, link:next, filter:skip-self, filter:skip-users, filter:require-sub, filter:build-id, filter:var-subst" ], [ "Host", "localhost:7999" ] ], "ignore-policies": true, "ext": { "multi": true }, "from": "pushpin-proxy_9", "stream": true, "connect-host": "172.111.111.111" }
        
        [DEBUG] 2024-03-08 19:10:23.187 [handler] zhttp/zws client: IN pushpin-handler_10 { "type": "keep-alive", "seq": 0, "from": "pushpin-proxy_9", "id": "7d76447b-9e0c-4a29-a387-ac00ebcda1ab", "ext": { "multi": true } }
        
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::client] client-worker 1: stream conn starting 0 1/25000
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::executor] spawning future with size 12720
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::client] client-worker 1: task started: connection-0
        
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::connection] client-conn 1-0-30250e68-167d-4d1f-814d-2d22011b6e75: request: GET http://localhost:7999/recover/1_289220_996_
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::connection] client-conn 1-0-30250e68-167d-4d1f-814d-2d22011b6e75: resolving: [172.111.111.111]
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::connection] client-conn 1-0-30250e68-167d-4d1f-814d-2d22011b6e75: connecting to one of [172.111.111.111:8080]
        
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::client] client-worker 0: stream conn starting 0 1/25000
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::executor] spawning future with size 12720
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::client] client-worker 0: task started: connection-0
        
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::connection] client-conn 0-0-c405cd07-12b6-4bc8-b77b-f5e3b3af8c4a: request: GET http://localhost:7999/recover/1_289220_996_
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::connection] client-conn 0-0-c405cd07-12b6-4bc8-b77b-f5e3b3af8c4a: resolving: [172.111.111.111]
        
       [DEBUG] 2024-03-08 19:10:23.187 [handler] zhttp client: OUT pushpin-proxy_9 { "type": "keep-alive", "seq": 1, "from": "pushpin-handler_10", "id": "7d76447b-9e0c-4a29-a387-ac00ebcda1ab" }
        
        [DEBUG] 2024-03-08 19:10:23.187 [condure] [pushpin::connection] client-conn 0-0-c405cd07-12b6-4bc8-b77b-f5e3b3af8c4a: connecting to one of [172.111.111.111:8080]
        [DEBUG] 2024-03-08 19:10:23.187 [handler] zhttp/zws client: IN pushpin-handler_10 { "type": "keep-alive", "seq": 0, "from": "pushpin-proxy_9", "id": "2b8ef8e7-5526-42c1-b8a5-afffec407262", "ext": { "multi": true } }
        
        [DEBUG] 2024-03-08 19:10:23.187 [handler] zhttp client: OUT pushpin-proxy_9 { "type": "keep-alive", "seq": 1, "from": "pushpin-handler_10", "id": "2b8ef8e7-5526-42c1-b8a5-afffec407262" }
        
->        [DEBUG] 2024-03-08 19:10:23.188 [handler] zrpc server: IN { "args": { "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ] ], "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "body": "", "auto-share": true }, "id": "d88406b1-7c74-44f5-9945-a7b8dc03a0af", "method": "inspect" }
->        [DEBUG] 2024-03-08 19:10:23.188 [handler] zrpc server: OUT { "success": true, "id": "d88406b1-7c74-44f5-9945-a7b8dc03a0af", "value": { "no-proxy": false, "sharing-key": "auto|http://localhost:7999/recover/1_289220_996_|1_289220_996_; last-id=1_289220_996_" } }
        [DEBUG] 2024-03-08 19:10:23.188 [handler] zrpc server: IN { "args": { "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ] ], "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "body": "", "auto-share": true }, "id": "243bf7bc-97f0-47e7-8f50-5b71cc3da587", "method": "inspect" }
        [DEBUG] 2024-03-08 19:10:23.188 [handler] zrpc server: OUT { "success": true, "id": "243bf7bc-97f0-47e7-8f50-5b71cc3da587", "value": { "no-proxy": false, "sharing-key": "auto|http://localhost:7999/recover/1_289220_996_|1_289220_996_; last-id=1_289220_996_" } }
        [DEBUG] 2024-03-08 19:10:23.188 [proxy] zhttp/zws server: IN stream { "seq": 1, "id": "7d76447b-9e0c-4a29-a387-ac00ebcda1ab", "type": "keep-alive", "from": "pushpin-handler_10" }
        [DEBUG] 2024-03-08 19:10:23.188 [proxy] zhttp/zws server: IN stream { "seq": 1, "id": "2b8ef8e7-5526-42c1-b8a5-afffec407262", "type": "keep-alive", "from": "pushpin-handler_10" }
        [DEBUG] 2024-03-08 19:10:23.188 [proxy] zhttp/zws client: IN pushpin-proxy_9 { "id": "30250e68-167d-4d1f-814d-2d22011b6e75", "seq": 0, "type": "keep-alive", "ext": { "multi": true }, "from": "condure" }
        [DEBUG] 2024-03-08 19:10:23.188 [proxy] zhttp client: OUT condure { "id": "30250e68-167d-4d1f-814d-2d22011b6e75", "seq": 1, "type": "keep-alive", "from": "pushpin-proxy_9" }
        [DEBUG] 2024-03-08 19:10:23.188 [proxy] zhttp/zws client: IN pushpin-proxy_9 { "id": "c405cd07-12b6-4bc8-b77b-f5e3b3af8c4a", "seq": 0, "type": "keep-alive", "ext": { "multi": true }, "from": "condure" }
        [DEBUG] 2024-03-08 19:10:23.188 [proxy] zhttp client: OUT condure { "id": "c405cd07-12b6-4bc8-b77b-f5e3b3af8c4a", "seq": 1, "type": "keep-alive", "from": "pushpin-proxy_9" }
        [DEBUG] 2024-03-08 19:10:23.188 [condure] [pushpin::client] client-worker 1: queued zmq message for 1 conns
        [DEBUG] 2024-03-08 19:10:23.188 [condure] [pushpin::connection] client-conn 1-0-30250e68-167d-4d1f-814d-2d22011b6e75: handle packet: keep-alive
        [DEBUG] 2024-03-08 19:10:23.188 [condure] [pushpin::client] client-worker 0: queued zmq message for 1 conns
        [DEBUG] 2024-03-08 19:10:23.188 [condure] [pushpin::connection] client-conn 0-0-c405cd07-12b6-4bc8-b77b-f5e3b3af8c4a: handle packet: keep-alive
        
->        [DEBUG] 2024-03-08 19:10:23.188 [proxy] zrpc client: IN { "id": "d88406b1-7c74-44f5-9945-a7b8dc03a0af", "value": { "no-proxy": false, "sharing-key": "auto|http://localhost:7999/recover/1_289220_996_|1_289220_996_; last-id=1_289220_996_" }, "success": true }
        [DEBUG] 2024-03-08 19:10:23.188 [proxy] zrpc client: IN { "id": "243bf7bc-97f0-47e7-8f50-5b71cc3da587", "value": { "no-proxy": false, "sharing-key": "auto|http://localhost:7999/recover/1_289220_996_|1_289220_996_; last-id=1_289220_996_" }, "success": true }
        
        [DEBUG] 2024-03-08 19:10:23.222 [condure] [pushpin::connection] client-conn 0-0-c405cd07-12b6-4bc8-b77b-f5e3b3af8c4a: connected to 172.111.111.111:8080
        [DEBUG] 2024-03-08 19:10:23.228 [condure] [pushpin::connection] client-conn 1-0-30250e68-167d-4d1f-814d-2d22011b6e75: connected to 172.111.111.111:8080
        [DEBUG] 2024-03-08 19:10:23.288 [condure] [pushpin::connection] client-conn 1-0-30250e68-167d-4d1f-814d-2d22011b6e75: response: 200 OK
        [DEBUG] 2024-03-08 19:10:23.288 [condure] [pushpin::connection] client-conn 1-0-30250e68-167d-4d1f-814d-2d22011b6e75: finished

The log below shows the right ordering. First fetch inspect data, then do proxy with the sharing-key available.

->        [DEBUG] 2024-03-08 19:10:23.289 [proxy] zrpc client: OUT { "id": "b23402dc-e957-4a10-8079-e5e11f3473e2", "args": { "body": "", "auto-share": true, "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ] ] }, "method": "inspect" }
        [DEBUG] 2024-03-08 19:10:23.290 [proxy] zhttp/zws server: IN stream { "seq": 1, "id": "e7ab7436-c2a9-4425-8d38-ad3205f1a0e5", "type": "keep-alive", "from": "pushpin-handler_10" }
        [DEBUG] 2024-03-08 19:10:23.289 [handler] zhttp/zws client: IN pushpin-handler_10 { "code": 200, "seq": 1, "from": "pushpin-proxy_9", "id": "2b8ef8e7-5526-42c1-b8a5-afffec407262", "headers": [ [ "Date", "Fri, 08 Mar 2024 19:10:23 GMT" ], [ "Content-Length", "1044" ], [ "Grip-Hold", "stream" ], [ "Grip-Channel", "1_289220_996_; prev-id=1_289220_996_" ], [ "Grip-Keep-Alive", "data:  \\n\\n; format=cstring; timeout=15" ], [ "Grip-Link", "</recover/1_289220_996_>; rel=next; timeout=2147483" ], [ "Vary", "Origin" ], [ "X-Content-Type-Options", "nosniff" ] ], "reason": "OK" } 1044 "data: [{\"key\":\"peter-test-5\",\"metadata\":{\"deployed\":true,\"evaluationMode\":\"remote\",\"flagType\":\"release\",\"flagVersion\":37},\"segments\":[{\"metadata\":{\"segmentName\":\"default\"},\"variant\":\"off\"}],\"variants\":{\"off\":{\"key\":\"off\",\"metadata\":{\"default\":true}},\"on\":{\"key\":\"on\",\"payload\":{\"haha\":\"aa\"},\"value\":\"on\"}}},{\"key\":\"peter-test-local-1\",\"metadata\":{\"deployed\":true,\"evaluationMode\":\"local\",\"flagType\":\"release\",\"flagVersion\":150},\"segments\":[{\"conditions\":[[{\"op\":\"is\",\"selector\":[\"context\",\"user\",\"use...r\":[\"context\",\"user\",\"device_id\"],\"values\":[\"asdf\"]}]],\"metadata\":{\"segmentName\":\"individual-inclusions\"},\"variant\":\"on\"},{\"bucket\":{\"allocations\":[{\"distributions\":[{\"range\":[0,42949673],\"variant\":\"on\"}],\"range\":[0,92]}],\"salt\":\"iQ7VVBCW\",\"selector\":[\"context\",\"user\",\"device_id\"]},\"metadata\":{\"segmentName\":\"All Other Users\"},\"variant\":\"off\"}],\"variants\":{\"off\":{\"key\":\"off\",\"metadata\":{\"default\":true}},\"on\":{\"key\":\"on\",\"payload\":{\"a\":\"ffeffefffeeaaeeeff0cc0ee0ee111ee1ff10\"},\"value\":\"on\"}}}]\n\n"
        [INFO] 2024-03-08 19:10:23.289 [handler] GET http://localhost:7999/recover/1_289220_996_ route=*,*,*,* code=200 1044 #1_289220_996_=1_289220_996_
        [DEBUG] 2024-03-08 19:10:23.289 [handler] zhttp/zws client: IN pushpin-handler_10 { "type": "keep-alive", "seq": 0, "from": "pushpin-proxy_9", "id": "e7ab7436-c2a9-4425-8d38-ad3205f1a0e5", "ext": { "multi": true } }
        [DEBUG] 2024-03-08 19:10:23.289 [handler] zhttp client: OUT pushpin-proxy_9 { "type": "keep-alive", "seq": 1, "from": "pushpin-handler_10", "id": "e7ab7436-c2a9-4425-8d38-ad3205f1a0e5" }
->        [DEBUG] 2024-03-08 19:10:23.290 [handler] zrpc server: IN { "args": { "headers": [ [ "Grip-Last", "1_289220_996_; last-id=1_289220_996_" ] ], "method": "GET", "uri": "http://localhost:7999/recover/1_289220_996_", "body": "", "auto-share": true }, "id": "b23402dc-e957-4a10-8079-e5e11f3473e2", "method": "inspect" }
->        [DEBUG] 2024-03-08 19:10:23.290 [handler] zrpc server: OUT { "success": true, "id": "b23402dc-e957-4a10-8079-e5e11f3473e2", "value": { "no-proxy": false, "sharing-key": "auto|http://localhost:7999/recover/1_289220_996_|1_289220_996_; last-id=1_289220_996_" } }
        
->        [DEBUG] 2024-03-08 19:10:23.290 [proxy] zrpc client: IN { "id": "b23402dc-e957-4a10-8079-e5e11f3473e2", "value": { "no-proxy": false, "sharing-key": "auto|http://localhost:7999/recover/1_289220_996_|1_289220_996_; last-id=1_289220_996_" }, "success": true }
->        [DEBUG] 2024-03-08 19:10:23.290 [proxy] need to proxy with sharing key: auto|http://localhost:7999/recover/1_289220_996_|1_289220_996_; last-id=1_289220_996_
        [DEBUG] 2024-03-08 19:10:23.290 [proxy] creating proxysession for id=e7ab7436-c2a9-4425-8d38-ad3205f1a0e5
        [DEBUG] 2024-03-08 19:10:23.290 [proxy] proxysession: 0xaaab066daad0 forwarding to 172.111.111.111:8080

Thanks!

[jkarneges]

Hi Peter,

Are you seeing the "inspect not available" message for incoming client requests too, or only for next link fetches?

[zhukaihan]

Hi Justin,
Yes, only for next link fetches. And only after hint. The initial large response on new connections with Grip-Link works fine and reuses proxy sessions as well.
Also just tested with 1.37.0 and that seems to work as well.

[jkarneges]

I was able to reproduce this. It seems the issue has to do with external routing (when the scheme/domain of the next link is different than that of the original request) rather than pushpin version, although it is possible older versions may have slightly different behavior. Maybe the links differ in your environments.

In any case, this does look like a bug, and will be fixed in the next version very soon.