here’s a case where the round trip processing of a curl request takes around 50 seconds. I’ve noticed that call being made from the browser,
after navigating to http://odoo.ngx.ziti/web. That request gets intercepted by my local Ziti Desktop Edge Mac.
here’s the command sequence I’ve issued on the client
date +'%Y-%m-%d %H:%M:%S' && curl -i 'http://odoo.ngx.ziti/longpolling/poll' \
-H 'Accept: application/json, text/javascript, */*; q=0.01' \
-H 'Referer: http://odoo.ngx.ziti/web' \
-H 'X-Requested-With: XMLHttpRequest' \
-H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.93 Safari/537.36' \
-H 'Content-Type: application/json' \
--data-raw '{"jsonrpc":"2.0","method":"call","params":{"channels":["bundle_changed"],"last":0,"options":{"bus_inactivity":14326}},"id":775537654}' \
--compressed && date +'%Y-%m-%d %H:%M:%S'
output:
2021-05-17 15:14:18
HTTP/1.0 200 OK
Content-Type: application/json
Content-Length: 49
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: POST
Set-Cookie: session_id=799ebcf42593b3c62856d6198bec96e872f3f3fd; Expires=Sun, 15-Aug-2021 19:15:09 GMT; Max-Age=7776000; HttpOnly; Path=/
Server: Werkzeug/0.16.1 Python/3.8.6
Date: Mon, 17 May 2021 19:15:09 GMT
{"jsonrpc": "2.0", "id": 775537654, "result": []}
2021-05-17 15:15:09
note: so the command execution on the client started at 2021-05-17 15:14:18 (that’s EDT) and ended at 2021-05-17 15:15:09
startup of nginx:
date +'%Y-%m-%d %H:%M:%S' && ZITI_LOG=99 /usr/local/nginx/sbin/nginx
2021-05-17 15:14:07
[ 0.004] INFO ../library/ziti.c:230 ziti_init_async() ztx[0] Ziti C SDK version 0.23.2.10 @301a845(main) starting at (2021-05-17T19:14:07.638)
[ 0.004] INFO ../library/ziti.c:231 ziti_init_async() ztx[0] Loading from config[/Users/oluetkeh/Developer/ngx_ziti_downstream/work/ngx_downstream.json] controller[https://18.210.117.20:443]
[ 0.004] DEBUG ../library/ziti.c:251 ziti_init_async() ztx[0] using metrics interval: 6
[ 0.005] VERBOSE _deps/uv-mbed-src/src/http.c:349 client not connected, starting connect sequence
from the timestamps one can see that the curl request is issued about 11s after the start of nginx.
The ziti trace log below shows incoming data from the curl request at relative time: 11.334.
What’s fascinating is that ziti ‘claims’ the response from the upstream server was received at relative time 11.370, yet right before that are nginx log
lines with timestamps 2021/05/17 15:14:44, which is 37s after the start. The following log message at TRACE level then contains the response time from the upstream
server (Date: Mon, 17 May 2021 19:15:09 GMT); that date is equivalent to relative time of ~52s.
I read this as: the processing of the incoming request to ziti took >50s and it even ‘stopped ziti timekeeping’. Can you pls have a look.
log sippets:
access log on upstream server:
2021-05-17 18:17:51,965 1259 INFO odoo werkzeug: 192.168.123.243 - - [17/May/2021 18:17:51] "POST /longpolling/poll HTTP/1.1" 200 - 4 0.003 50.111
nginx error.log with ziti trace logging:
2021/05/17 15:14:07 [debug] 70345#672784: bind() 0.0.0.0:18080 #24
...
[ 0.070] TRACE _deps/uv-mbed-src/src/http_req.c:67 processing
HTTP/1.1 200 OK
Content-Type: application/json
Server: ziti-controller/v0.19.6
Date: Mon, 17 May 2021 19:14:07 GMT
Content-Length: 179
{"data":{"apiVersions":{"edge":{"v1":{"path":"/edge/v1"}}},"buildDate":"2021-03-11 14:24:38","revision":"50673e084ae5","runtimeVersion":"go1.15.8","version":"v0.19.6"},"meta":{}}
[ 0.070] VERBOSE _deps/uv-mbed-src/src/http_req.c:196 status = 200 OK
[ 0.070] VERBOSE _deps/uv-mbed-src/src/http_req.c:206 message complete
[ 0.070] INFO ../library/ziti.c:909 version_cb() ztx[0] connected to controller https://18.210.117.20:443 version v0.19.6(50673e084ae5 2021-03-11 14:24:38)
[ 0.070] VERBOSE _deps/uv-mbed-src/src/http_req.c:69 processed 321 out of 321
[ 0.070] VERBOSE _deps/uv-mbed-src/src/http.c:359 client connected, processing request[/authenticate?method=cert] state[0]
[ 0.070] VERBOSE _deps/uv-mbed-src/src/http.c:361 sending request[/authenticate?method=cert] headers
[ 0.070] TRACE _deps/uv-mbed-src/src/http.c:365 writing request >>> POST /edge/v1/authenticate?method=cert HTTP/1.1
Content-Length: 329
Content-Type: application/json
Connection: keep-alive
Host: 18.210.117.20
Accept: application/json
[ 0.070] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 > v[0], ct[256], len[5]
[ 0.070] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 > v[772], ct[257], len[1]
[ 0.070] VERBOSE _deps/uv-mbed-src/src/http.c:372 sending request[/authenticate?method=cert] body
[ 0.070] VERBOSE _deps/uv-mbed-src/src/http.c:272 sending body chunk 329 bytes
[ 0.070] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 > v[0], ct[256], len[5]
[ 0.070] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 > v[772], ct[257], len[1]
[ 0.071] VERBOSE _deps/uv-mbed-src/src/http.c:243 request write completed: 0
[ 0.071] VERBOSE _deps/uv-mbed-src/src/http.c:248 request body write completed: 0
[ 0.145] TRACE _deps/uv-mbed-src/src/tls_link.c:112 TLS(0x7f909f01a4f8)[2]: 1166
[ 0.145] TRACE _deps/uv-mbed-src/src/tls_link.c:167 TLS(0x7f909f01a4f8) processing 1166 bytes
[ 0.145] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[0], ct[256], len[5]
[ 0.145] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[772], ct[257], len[1]
[ 0.145] TRACE _deps/uv-mbed-src/src/tls_link.c:180 TLS(0x7f909f01a4f8) produced 1144 application byte (rc=0)
[ 0.145] TRACE _deps/uv-mbed-src/src/http_req.c:67 processing
HTTP/1.1 200 OK
Content-Type: application/json
Expiration-Seconds: 1800
Expires-At: 2021-05-17 19:44:07.77279255 +0000 UTC
Server: ziti-controller/v0.19.6
Set-Cookie: zt-session=53f7e11a-8810-49f2-9fbd-4f61648b4e40; Expires=Mon, 17 May 2021 19:44:07 GMT
Zt-Session: 53f7e11a-8810-49f2-9fbd-4f61648b4e40
Date: Mon, 17 May 2021 19:14:07 GMT
Content-Length: 774
{"data":{"_links":{"current-identity":{"href":"./current-identity"},"self":{"href":"./current-api-session"}},"createdAt":"2021-05-17T19:14:07.772Z","id":"ckoszkcns6oif3w72ggg0sx52","tags":{},"updatedAt":"2021-05-17T19:14:07.772Z","authQueries":[],"configTypes":["all"],"identity":{"_links":{"edge-router-policies":{"href":"./identities/Ui4qnD6qd/edge-routers"},"posture-data":{"href":"./identities/Ui4qnD6qd/posture-data"},"self":{"href":"./identities/Ui4qnD6qd"},"service-policies":{"href":"./identities/Ui4qnD6qd/service-policies"}},"entity":"identities","id":"Ui4qnD6qd","name":"ngx_downstream"},"identityId":"Ui4qnD6qd","ipAddress":"96.2
[ 0.145] VERBOSE _deps/uv-mbed-src/src/http_req.c:196 status = 200 OK
[ 0.145] VERBOSE _deps/uv-mbed-src/src/http_req.c:206 message complete
...
[ 0.278] DEBUG /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:263 ngx_ziti_downstream_listen_cb() Ngx ziti downstream module waiting for client data! 0(OK)
[ 11.334] TRACE _deps/uv-mbed-src/src/tls_link.c:112 TLS(0x7f909d60bfe0)[2]: 330
[ 11.334] TRACE _deps/uv-mbed-src/src/tls_link.c:167 TLS(0x7f909d60bfe0) processing 330 bytes
[ 11.334] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[0], ct[256], len[5]
[ 11.334] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[772], ct[257], len[1]
[ 11.334] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[0], ct[256], len[5]
[ 11.334] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[772], ct[257], len[1]
[ 11.334] TRACE _deps/uv-mbed-src/src/tls_link.c:180 TLS(0x7f909d60bfe0) produced 286 application byte (rc=0)
[ 11.334] TRACE ../library/channel.c:807 on_channel_data() ch[0] on_data [len=286]
[ 11.334] TRACE ../library/channel.c:527 process_inbound() ch[0] <= ct[ED73] seq[2] len[36] hdrs[230]
[ 11.334] TRACE ../library/channel.c:535 process_inbound() ch[0] completing msg seq[2] body+hrds=36+230, in_offset=0, want=266, got=266
[ 11.334] TRACE ../library/channel.c:546 process_inbound() ch[0] message is complete seq[2] ct[ED73]
[ 11.334] TRACE ../library/connect.c:1275 process_edge_message() conn[0.0] <= ct[ED73] edge_seq[0] body[36]
[ 11.334] VERBOSE ../library/connect.c:91 conn_set_state() conn[0.1] transitioning Initial => Accepting
[ 11.334] DEBUG /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:276 ngx_ziti_downstream_on_client() incoming connection from 'Luetkehoelter.Olaf.marketing'
[ 11.334] DEBUG /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:282 ngx_ziti_downstream_on_client() got app data: 122 bytes
[ 11.334] TRACE /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:283 ngx_ziti_downstream_on_client() got app data:
'{"dst_protocol":"tcp","dst_ip":"100.64.2.3","dst_port":"80","src_protocol":"tcp","src_ip":"100.64.0.1","src_port":"57752"}'
[ 11.334] DEBUG ../library/channel.c:195 ziti_channel_add_receiver() ch[0] added receiver[1]
[ 11.334] TRACE ../library/connect.c:1137 ziti_accept() conn[0.1] ch[0] => Edge Accept parent_conn_id[0]
[ 11.334] TRACE ../library/channel.c:364 ziti_channel_send_for_reply() ch[0] => ct[0000] seq[60788] len[2]
[ 11.334] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 > v[0], ct[256], len[5]
[ 11.334] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 > v[772], ct[257], len[1]
[ 11.335] TRACE ../library/channel.c:765 on_write() on_write(0x7f909eb047a0,0)
[ 11.346] TRACE _deps/uv-mbed-src/src/tls_link.c:112 TLS(0x7f909d60bfe0)[2]: 100
[ 11.346] TRACE _deps/uv-mbed-src/src/tls_link.c:167 TLS(0x7f909d60bfe0) processing 100 bytes
[ 11.346] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[0], ct[256], len[5]
[ 11.346] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[772], ct[257], len[1]
[ 11.346] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[0], ct[256], len[5]
[ 11.346] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[772], ct[257], len[1]
[ 11.346] TRACE _deps/uv-mbed-src/src/tls_link.c:180 TLS(0x7f909d60bfe0) produced 56 application byte (rc=0)
[ 11.346] TRACE ../library/channel.c:807 on_channel_data() ch[0] on_data [len=56]
[ 11.346] TRACE ../library/channel.c:527 process_inbound() ch[0] <= ct[ED70] seq[3] len[0] hdrs[36]
[ 11.346] TRACE ../library/channel.c:535 process_inbound() ch[0] completing msg seq[3] body+hrds=0+36, in_offset=0, want=36, got=36
[ 11.346] TRACE ../library/channel.c:546 process_inbound() ch[0] message is complete seq[3] ct[ED70]
[ 11.346] TRACE ../library/connect.c:897 connect_reply_cb() conn[0.1] accepted
[ 11.346] TRACE ../library/channel.c:317 ziti_channel_send() ch[0] => ct[ED72] seq[3] len[24]
[ 11.346] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 > v[0], ct[256], len[5]
[ 11.346] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 > v[772], ct[257], len[1]
[ 11.346] VERBOSE ../library/connect.c:91 conn_set_state() conn[0.1] transitioning Accepting => Connected
[ 11.346] DEBUG /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:292 ngx_ziti_downstream_on_client_connect() --- ngx_ziti_downstream_on_client_connect
[ 11.347] TRACE ../library/connect.c:204 on_write_completed() conn[0.1] status 0
[ 11.359] TRACE _deps/uv-mbed-src/src/tls_link.c:112 TLS(0x7f909d60bfe0)[2]: 112
[ 11.359] TRACE _deps/uv-mbed-src/src/tls_link.c:167 TLS(0x7f909d60bfe0) processing 112 bytes
[ 11.359] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[0], ct[256], len[5]
[ 11.359] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[772], ct[257], len[1]
[ 11.359] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[0], ct[256], len[5]
[ 11.359] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[772], ct[257], len[1]
[ 11.359] TRACE _deps/uv-mbed-src/src/tls_link.c:180 TLS(0x7f909d60bfe0) produced 68 application byte (rc=0)
[ 11.359] TRACE ../library/channel.c:807 on_channel_data() ch[0] on_data [len=68]
[ 11.359] TRACE ../library/channel.c:527 process_inbound() ch[0] <= ct[ED72] seq[4] len[24] hdrs[24]
[ 11.359] TRACE ../library/channel.c:535 process_inbound() ch[0] completing msg seq[4] body+hrds=24+24, in_offset=0, want=48, got=48
[ 11.359] TRACE ../library/channel.c:546 process_inbound() ch[0] message is complete seq[4] ct[ED72]
[ 11.359] TRACE ../library/connect.c:1275 process_edge_message() conn[0.1] <= ct[ED72] edge_seq[1] body[24]
[ 11.359] VERBOSE ../library/connect.c:771 conn_inbound_data_msg() conn[0.1] processing crypto header(24 bytes)
[ 11.359] VERBOSE ../library/connect.c:774 conn_inbound_data_msg() conn[0.1] processed crypto header
[ 11.359] TRACE ../library/connect.c:736 flush_to_client() conn[0.1] flushing 0 bytes to client
[ 11.370] TRACE _deps/uv-mbed-src/src/tls_link.c:112 TLS(0x7f909d60bfe0)[2]: 638
[ 11.370] TRACE _deps/uv-mbed-src/src/tls_link.c:167 TLS(0x7f909d60bfe0) processing 638 bytes
[ 11.370] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[0], ct[256], len[5]
[ 11.370] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[772], ct[257], len[1]
[ 11.370] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[0], ct[256], len[5]
[ 11.370] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 < v[772], ct[257], len[1]
[ 11.370] TRACE _deps/uv-mbed-src/src/tls_link.c:180 TLS(0x7f909d60bfe0) produced 594 application byte (rc=0)
[ 11.370] TRACE ../library/channel.c:807 on_channel_data() ch[0] on_data [len=594]
[ 11.370] TRACE ../library/channel.c:527 process_inbound() ch[0] <= ct[ED72] seq[5] len[550] hdrs[24]
[ 11.370] TRACE ../library/channel.c:535 process_inbound() ch[0] completing msg seq[5] body+hrds=550+24, in_offset=0, want=574, got=574
[ 11.370] TRACE ../library/channel.c:546 process_inbound() ch[0] message is complete seq[5] ct[ED72]
[ 11.370] TRACE ../library/connect.c:1275 process_edge_message() conn[0.1] <= ct[ED72] edge_seq[2] body[550]
[ 11.370] VERBOSE ../library/connect.c:781 conn_inbound_data_msg() conn[0.1] decrypting 550 bytes
[ 11.370] VERBOSE ../library/connect.c:785 conn_inbound_data_msg() conn[0.1] decrypted 533 bytes
[ 11.370] TRACE ../library/connect.c:736 flush_to_client() conn[0.1] flushing 533 bytes to client
[ 11.370] DEBUG /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:303 ngx_ziti_downstream_on_client_data() client sent 533 bytes
[ 11.370] TRACE /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:304 ngx_ziti_downstream_on_client_data() client sent these 533 bytes:
POST /longpolling/poll HTTP/1.1
Host: odoo.ngx.ziti
Accept-Encoding: deflate, gzip
Accept: application/json, text/javascript, */*; q=0.01
Referer: http://odoo.ngx.ziti/web
X-Requested-With: XMLHttpRequest
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.93 Safari/537.36
Content-Type: application/json
Content-Length: 133
{"jsonrpc":"2.0","method":"call","params":{"channels":["bundle_changed"],"last":0,"options":{"bus_inactivity":14326}},"id":775537654}
2021/05/17 15:14:43 [notice] 70345#672784: signal 28 (SIGWINCH) received from 6055
2021/05/17 15:14:43 [debug] 70345#672784: kevent events: -1
2021/05/17 15:14:43 [info] 70345#672784: kevent() failed (4: Interrupted system call)
2021/05/17 15:14:43 [debug] 70345#672784: timer delta: 36001
2021/05/17 15:14:43 [debug] 70345#672784: worker cycle
2021/05/17 15:14:43 [debug] 70345#672784: kevent timer: -1, changes: 0
2021/05/17 15:14:44 [notice] 70345#672784: signal 28 (SIGWINCH) received from 6055
2021/05/17 15:14:44 [debug] 70345#672784: kevent events: -1
2021/05/17 15:14:44 [info] 70345#672784: kevent() failed (4: Interrupted system call)
2021/05/17 15:14:44 [debug] 70345#672784: timer delta: 369
2021/05/17 15:14:44 [debug] 70345#672784: worker cycle
2021/05/17 15:14:44 [debug] 70345#672784: kevent timer: -1, changes: 0
2021/05/17 15:14:44 [notice] 70345#672784: signal 28 (SIGWINCH) received from 6055
2021/05/17 15:14:44 [debug] 70345#672784: kevent events: -1
2021/05/17 15:14:44 [info] 70345#672784: kevent() failed (4: Interrupted system call)
2021/05/17 15:14:44 [debug] 70345#672784: timer delta: 298
2021/05/17 15:14:44 [debug] 70345#672784: worker cycle
2021/05/17 15:14:44 [debug] 70345#672784: kevent timer: -1, changes: 0
[ 11.370] DEBUG /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:311 ngx_ziti_downstream_on_client_data() response from upstream server is 402 bytes long.
[ 11.370] TRACE /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:312 ngx_ziti_downstream_on_client_data() response from upstream server 402 bytes:
HTTP/1.0 200 OK
Content-Type: application/json
Content-Length: 49
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: POST
Set-Cookie: session_id=799ebcf42593b3c62856d6198bec96e872f3f3fd; Expires=Sun, 15-Aug-2021 19:15:09 GMT; Max-Age=7776000; HttpOnly; Path=/
Server: Werkzeug/0.16.1 Python/3.8.6
Date: Mon, 17 May 2021 19:15:09 GMT
{"jsonrpc": "2.0", "id": 775537654, "result": []}
[ 11.370] TRACE /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:323 ngx_ziti_downstream_on_client_data() ziti_chunk to write 402 bytes:
HTTP/1.0 200 OK
Content-Type: application/json
Content-Length: 49
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: POST
Set-Cookie: session_id=799ebcf42593b3c62856d6198bec96e872f3f3fd; Expires=Sun, 15-Aug-2021 19:15:09 GMT; Max-Age=7776000; HttpOnly; Path=/
Server: Werkzeug/0.16.1 Python/3.8.6
Date: Mon, 17 May 2021 19:15:09 GMT
{"jsonrpc": "2.0", "id": 775537654, "result": []}
[ 11.370] TRACE ../library/channel.c:317 ziti_channel_send() ch[0] => ct[ED72] seq[4] len[419]
[ 11.370] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 > v[0], ct[256], len[5]
[ 11.370] TRACE _deps/uv-mbed-src/src/engine_openssl.c:224 > v[772], ct[257], len[1]
[ 11.370] DEBUG /Users/oluetkeh/Developer/ngx_ziti_downstream/src/ngx_ziti_downstream_module.c:326 ngx_ziti_downstream_on_client_data() ziti_write return code after writing 402 of 402 bytes: 0
[ 61.470] VERBOSE ../library/posture.c:178 ziti_send_posture_data() starting to send posture data
[ 61.470] DEBUG ../library/posture.c:182 ziti_send_posture_data() posture checks either never sent or session changed, must_send = true
[ 61.470] DEBUG ../library/posture.c:468 ziti_pr_send_bulk() no change in posture data, not sending
[ 61.470] ERROR ../library/channel.c:670 connect_timeout() ch[1] connect timeout
...