/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/bin/python /Users/geoffberl/git/NetFoundry/ziti-sdk-py/sample/ziti-http-server/ziti-http-server.py /Users/geoffberl/python.flask.json python.flask
Server started http://127.0.0.1:18080
The following shows in the run log, which appears to be four successful responses. However, the python script throws an exception and not response is ever received.
geoff.flask - - [12/Apr/2023 13:17:35] "GET / HTTP/1.1" 200 -
geoff.flask - - [12/Apr/2023 13:17:35] "GET / HTTP/1.1" 200 -
geoff.flask - - [12/Apr/2023 13:17:35] "GET / HTTP/1.1" 200 -
geoff.flask - - [12/Apr/2023 13:17:35] "GET / HTTP/1.1" 200 -
$ python ziti-urllib3.py python.flask.ziti
(99158)[ 0.000] INFO ziti-sdk:utils.c:176 ziti_log_set_level() set log level: root=6/TRACE
(99158)[ 0.000] DEBUG ziti-sdk:zitilib.c:1055 looper() loop is starting
(99158)[ 0.001] DEBUG ziti-sdk:zitilib.c:303 load_ziti_ctx() loading identity from /Users/geoffberl/geoff.flask.json
(99158)[ 0.001] INFO ziti-sdk:utils.c:176 ziti_log_set_level() set log level: root=6/TRACE
(99158)[ 0.001] DEBUG ziti-sdk:config.c:73 load_config() trying to load config from file
(99158)[ 0.001] INFO ziti-sdk:ziti.c:427 ziti_init_async() ztx[0] Ziti C SDK version 0.31.5-147 @ccbc692(HEAD) starting at (2023-04-12T17:17:35.594)
(99158)[ 0.001] INFO ziti-sdk:ziti.c:429 ziti_init_async() ztx[0] using tlsuv[<unknown>], tls[mbed TLS 3.2.1]
(99158)[ 0.001] INFO ziti-sdk:ziti.c:430 ziti_init_async() ztx[0] Loading ziti context with controller[https://MacBook-Pro:1280]
(99158)[ 0.001] INFO ziti-sdk:ziti_ctrl.c:409 ziti_ctrl_init() ctrl[MacBook-Pro] ziti controller client initialized
(99158)[ 0.001] DEBUG ziti-sdk:ziti.c:452 ziti_init_async() ztx[0] using metrics interval: 0
(99158)[ 0.001] VERBOSE ziti-sdk:ziti_ctrl.c:134 start_request() ctrl[MacBook-Pro] starting GET[/version]
(99158)[ 0.001] DEBUG ziti-sdk:ziti.c:257 ziti_set_unauthenticated() ztx[0] setting api_session_state[0] to 0
(99158)[ 0.001] DEBUG ziti-sdk:ziti_ctrl.c:245 ziti_ctrl_clear_api_session() ctrl[MacBook-Pro] clearing api session token for ziti_controller
(99158)[ 0.001] DEBUG ziti-sdk:ziti.c:919 ziti_re_auth() ztx[0] re-auth executing, transitioning to unauthenticated
(99158)[ 0.001] DEBUG ziti-sdk:ziti.c:257 ziti_set_unauthenticated() ztx[0] setting api_session_state[0] to 0
(99158)[ 0.001] DEBUG ziti-sdk:ziti_ctrl.c:245 ziti_ctrl_clear_api_session() ctrl[MacBook-Pro] clearing api session token for ziti_controller
(99158)[ 0.001] DEBUG ziti-sdk:ziti.c:288 is_api_session_expired() ztx[0] is_api_session_expired[TRUE] - api_session is null
(99158)[ 0.001] INFO ziti-sdk:ziti.c:867 ziti_re_auth_with_cb() ztx[0] starting to re-auth with ctlr[https://MacBook-Pro:1280] api_session_status[0] api_session_expired[TRUE]
(99158)[ 0.001] DEBUG ziti-sdk:ziti.c:250 ziti_set_auth_started() ztx[0] setting api_session_state[0] to 1
(99158)[ 0.001] DEBUG ziti-sdk:ziti.c:323 ziti_stop_api_session_refresh() ztx[0] ziti_stop_api_session_refresh: stopping api session refresh
(99158)[ 0.001] VERBOSE ziti-sdk:ziti_ctrl.c:134 start_request() ctrl[MacBook-Pro] starting POST[/authenticate?method=cert]
(99158)[ 0.059] VERBOSE ziti-sdk:ziti_ctrl.c:169 ctrl_resp_cb() ctrl[MacBook-Pro] received headers GET[/version]
(99158)[ 0.059] DEBUG ziti-sdk:ziti_ctrl.c:326 ctrl_body_cb() ctrl[MacBook-Pro] completed GET[/version] in 0.057 s
(99158)[ 0.059] INFO ziti-sdk:ziti.c:1526 version_cb() ztx[0] connected to controller https://MacBook-Pro:1280 version v0.27.7(bd531e470c62 2023-03-30T13:45:29Z)
(99158)[ 0.195] VERBOSE ziti-sdk:ziti_ctrl.c:169 ctrl_resp_cb() ctrl[MacBook-Pro] received headers POST[/authenticate?method=cert]
(99158)[ 0.195] DEBUG ziti-sdk:ziti_ctrl.c:326 ctrl_body_cb() ctrl[MacBook-Pro] completed POST[/authenticate?method=cert] in 0.193 s
(99158)[ 0.195] DEBUG ziti-sdk:ziti_ctrl.c:258 ctrl_login_cb() ctrl[MacBook-Pro] authenticated successfully session[clgdyfjh98eyvif9kon4dvcju]
(99158)[ 0.195] DEBUG ziti-sdk:ziti.c:1442 api_session_cb() ztx[0] logged in successfully => api_session[clgdyfjh98eyvif9kon4dvcju]
(99158)[ 0.195] TRACE ziti-sdk:ziti.c:1381 ziti_set_api_session() ztx[0] API supports cached_last_activity_at
(99158)[ 0.195] DEBUG ziti-sdk:ziti.c:1392 ziti_set_api_session() ztx[0] ziti api session expires in 1800 seconds
(99158)[ 0.195] INFO ziti-sdk:ziti.c:1416 ziti_set_api_session() ztx[0] api session set, setting api_session_timer to 1740s
(99158)[ 0.195] DEBUG ziti-sdk:ziti.c:328 ziti_schedule_api_session_refresh() ztx[0] ziti_schedule_api_session_refresh: scheduling api session refresh: 1740000ms
(99158)[ 0.195] DEBUG ziti-sdk:ziti.c:282 ziti_set_fully_authenticated() ztx[0] setting api_session_state[1] to 3
(99158)[ 0.195] VERBOSE ziti-sdk:ziti_ctrl.c:134 start_request() ctrl[MacBook-Pro] starting GET[/current-identity]
(99158)[ 0.195] VERBOSE ziti-sdk:ziti.c:1338 session_post_auth_query_cb() ztx[0] post auth query callback starting with status[OK]
(99158)[ 0.195] VERBOSE ziti-sdk:ziti.c:1340 session_post_auth_query_cb() ztx[0] transitioning to fully authenticated
(99158)[ 0.195] DEBUG ziti-sdk:ziti.c:282 ziti_set_fully_authenticated() ztx[0] setting api_session_state[3] to 3
(99158)[ 0.195] VERBOSE ziti-sdk:ziti_ctrl.c:134 start_request() ctrl[MacBook-Pro] starting GET[/current-identity]
(99158)[ 0.195] VERBOSE ziti-sdk:ziti.c:1239 ziti_services_refresh() ztx[0] forcing service refresh
(99158)[ 0.195] DEBUG ziti-sdk:ziti_ctrl.c:777 ctrl_paging_req() ctrl[MacBook-Pro] starting paging request GET[/current-identity/edge-routers]
(99158)[ 0.195] VERBOSE ziti-sdk:ziti_ctrl.c:782 ctrl_paging_req() ctrl[MacBook-Pro] requesting /current-identity/edge-routers?limit=25&offset=0
(99158)[ 0.195] VERBOSE ziti-sdk:ziti_ctrl.c:134 start_request() ctrl[MacBook-Pro] starting GET[/current-identity/edge-routers?limit=25&offset=0]
(99158)[ 0.196] VERBOSE ziti-sdk:ziti_ctrl.c:134 start_request() ctrl[MacBook-Pro] starting GET[/current-api-session/service-updates]
(99158)[ 0.201] VERBOSE ziti-sdk:ziti_ctrl.c:169 ctrl_resp_cb() ctrl[MacBook-Pro] received headers GET[/current-identity]
(99158)[ 0.201] DEBUG ziti-sdk:ziti_ctrl.c:326 ctrl_body_cb() ctrl[MacBook-Pro] completed GET[/current-identity] in 0.005 s
(99158)[ 0.203] VERBOSE ziti-sdk:ziti_ctrl.c:169 ctrl_resp_cb() ctrl[MacBook-Pro] received headers GET[/current-identity]
(99158)[ 0.203] DEBUG ziti-sdk:ziti_ctrl.c:326 ctrl_body_cb() ctrl[MacBook-Pro] completed GET[/current-identity] in 0.007 s
(99158)[ 0.208] VERBOSE ziti-sdk:ziti_ctrl.c:169 ctrl_resp_cb() ctrl[MacBook-Pro] received headers GET[/current-identity/edge-routers?limit=25&offset=0]
(99158)[ 0.208] DEBUG ziti-sdk:ziti_ctrl.c:326 ctrl_body_cb() ctrl[MacBook-Pro] completed GET[/current-identity/edge-routers?limit=25&offset=0] in 0.011 s
(99158)[ 0.208] DEBUG ziti-sdk:ziti_ctrl.c:342 ctrl_body_cb() ctrl[MacBook-Pro] received 1/1 for paging request GET[/current-identity/edge-routers]
(99158)[ 0.208] DEBUG ziti-sdk:ziti_ctrl.c:354 ctrl_body_cb() ctrl[MacBook-Pro] completed paging request GET[/current-identity/edge-routers] in 0.011 s
(99158)[ 0.208] TRACE ziti-sdk:ziti.c:1286 edge_routers_cb() ztx[0] connecting to MacBook-Pro-edge-router(tls://127.0.0.1:3022)
(99158)[ 0.208] INFO ziti-sdk:channel.c:235 new_ziti_channel() ch[0] (MacBook-Pro-edge-router@tls://127.0.0.1:3022) new channel for ztx[0] identity[geoff.flask]
(99158)[ 0.208] INFO ziti-sdk:channel.c:734 reconnect_channel() ch[0] reconnecting NOW
(99158)[ 0.208] DEBUG ziti-sdk:channel.c:705 reconnect_cb() ch[0] connecting to 127.0.0.1:3022
(99158)[ 0.217] VERBOSE ziti-sdk:ziti_ctrl.c:169 ctrl_resp_cb() ctrl[MacBook-Pro] received headers GET[/current-api-session/service-updates]
(99158)[ 0.217] DEBUG ziti-sdk:ziti_ctrl.c:326 ctrl_body_cb() ctrl[MacBook-Pro] completed GET[/current-api-session/service-updates] in 0.020 s
(99158)[ 0.217] VERBOSE ziti-sdk:ziti.c:1199 check_service_update() ztx[0] ztx last_update = 2023-03-31T18:37:58.344Z
(99158)[ 0.217] DEBUG ziti-sdk:ziti_ctrl.c:777 ctrl_paging_req() ctrl[MacBook-Pro] starting paging request GET[/services]
(99158)[ 0.217] VERBOSE ziti-sdk:ziti_ctrl.c:782 ctrl_paging_req() ctrl[MacBook-Pro] requesting /services?limit=25&offset=0
(99158)[ 0.217] VERBOSE ziti-sdk:ziti_ctrl.c:134 start_request() ctrl[MacBook-Pro] starting GET[/services?limit=25&offset=0]
(99158)[ 0.225] VERBOSE ziti-sdk:ziti_ctrl.c:169 ctrl_resp_cb() ctrl[MacBook-Pro] received headers GET[/services?limit=25&offset=0]
(99158)[ 0.225] DEBUG ziti-sdk:ziti_ctrl.c:326 ctrl_body_cb() ctrl[MacBook-Pro] completed GET[/services?limit=25&offset=0] in 0.008 s
(99158)[ 0.225] DEBUG ziti-sdk:ziti_ctrl.c:342 ctrl_body_cb() ctrl[MacBook-Pro] received 1/1 for paging request GET[/services]
(99158)[ 0.225] DEBUG ziti-sdk:ziti_ctrl.c:354 ctrl_body_cb() ctrl[MacBook-Pro] completed paging request GET[/services] in 0.008 s
(99158)[ 0.225] VERBOSE ziti-sdk:ziti.c:1241 ziti_services_refresh() ztx[0] scheduling service refresh 60 seconds from now
(99158)[ 0.225] VERBOSE ziti-sdk:ziti.c:1069 update_services() ztx[0] processing service updates
(99158)[ 0.225] DEBUG ziti-sdk:ziti.c:1146 update_services() ztx[0] sending service event 1 added, 0 removed, 0 changed
(99158)[ 0.225] DEBUG ziti-sdk:zitilib.c:1230 Ziti_resolve() host[python.flask.ziti] port[80]
(99158)[ 0.229] DEBUG ziti-sdk:zitilib.c:1195 resolve_cb() resolving python.flask.ziti
(99158)[ 0.229] DEBUG ziti-sdk:zitilib.c:599 find_service() looking up 0:python.flask.ziti:80
(99158)[ 0.229] DEBUG ziti-sdk:zitilib.c:1201 resolve_cb() python.flask.ziti:80 => python.flask
(99158)[ 0.229] DEBUG ziti-sdk:zitilib.c:1214 resolve_cb() assigned python.flask.ziti => 1004064
(99158)[ 0.229] VERBOSE ziti-sdk:zitilib.c:508 check_socket() checking client fd[13]
(99158)[ 0.229] DEBUG ziti-sdk:zitilib.c:634 do_ziti_connect() connecting fd[13] to 100.64.0.1:80
(99158)[ 0.229] DEBUG ziti-sdk:zitilib.c:599 find_service() looking up 1:python.flask.ziti:80
(99158)[ 0.229] DEBUG ziti-sdk:zitilib.c:689 do_ziti_connect() connecting fd[13] to service[python.flask]
(99158)[ 0.229] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.0/Initial] transitioning Initial => Connecting
(99158)[ 0.229] VERBOSE ziti-sdk:posture.c:198 ziti_send_posture_data() ztx[0] starting to send posture data
(99158)[ 0.229] INFO ziti-sdk:posture.c:204 ziti_send_posture_data() ztx[0] first run or potential controller restart detected
(99158)[ 0.229] DEBUG ziti-sdk:posture.c:211 ziti_send_posture_data() ztx[0] posture checks must_send set to TRUE, new_session_id[TRUE], must_send_every_time[TRUE], new_controller_instance[TRUE]
(99158)[ 0.229] VERBOSE ziti-sdk:posture.c:236 ziti_send_posture_data() ztx[0] checking posture queries on 1 service(s)
(99158)[ 0.229] VERBOSE ziti-sdk:posture.c:535 ziti_pr_send_bulk() ztx[0] no change in posture data, not sending
(99158)[ 0.229] DEBUG ziti-sdk:connect.c:522 process_connect() conn[0.0/Connecting] requesting 'Dial' session for service[python.flask]
(99158)[ 0.229] VERBOSE ziti-sdk:ziti_ctrl.c:134 start_request() ctrl[MacBook-Pro] starting POST[/sessions]
(99158)[ 0.275] DEBUG ziti-sdk:channel.c:848 on_channel_connect_internal() ch[0] connected
(99158)[ 0.275] TRACE ziti-sdk:channel.c:403 ziti_channel_send_for_reply() ch[0] => ct[0000] seq[0] len[31]
(99158)[ 0.275] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=95
(99158)[ 0.275] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=132]
(99158)[ 0.275] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[0002] seq[-1] len[0] hdrs[112]
(99158)[ 0.275] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[-1] body+hrds=0+112, in_offset=0, want=112, got=112
(99158)[ 0.275] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[-1] ct[0002]
(99158)[ 0.275] INFO ziti-sdk:channel.c:632 hello_reply_cb() ch[0] connected. EdgeRouter version: v0.27.7|bd531e470c62|2023-03-30T13:45:29Z|darwin|amd64
(99158)[ 0.282] VERBOSE ziti-sdk:ziti_ctrl.c:169 ctrl_resp_cb() ctrl[MacBook-Pro] received headers POST[/sessions]
(99158)[ 0.282] DEBUG ziti-sdk:ziti_ctrl.c:326 ctrl_body_cb() ctrl[MacBook-Pro] completed POST[/sessions] in 0.052 s
(99158)[ 0.282] DEBUG ziti-sdk:connect.c:484 connect_get_net_session_cb() conn[0.0/Connecting] got session[clgdyfjko8eyxif9k8rsvqp4j] for service[python.flask]
(99158)[ 0.282] VERBOSE ziti-sdk:posture.c:198 ziti_send_posture_data() ztx[0] starting to send posture data
(99158)[ 0.282] DEBUG ziti-sdk:posture.c:211 ziti_send_posture_data() ztx[0] posture checks must_send set to TRUE, new_session_id[FALSE], must_send_every_time[TRUE], new_controller_instance[FALSE]
(99158)[ 0.282] VERBOSE ziti-sdk:posture.c:236 ziti_send_posture_data() ztx[0] checking posture queries on 1 service(s)
(99158)[ 0.282] VERBOSE ziti-sdk:posture.c:535 ziti_pr_send_bulk() ztx[0] no change in posture data, not sending
(99158)[ 0.282] DEBUG ziti-sdk:connect.c:532 process_connect() conn[0.0/Connecting] starting Dial connection for service[python.flask] with session[clgdyfjko8eyxif9k8rsvqp4j]
(99158)[ 0.282] DEBUG ziti-sdk:connect.c:415 ziti_connect() conn[0.0/Connecting] selected ch[MacBook-Pro-edge-router@tls://127.0.0.1:3022] for best latency(0 ms)
(99158)[ 0.282] DEBUG ziti-sdk:connect.c:302 on_channel_connected() conn[0.0/Connecting] selected ch[MacBook-Pro-edge-router@tls://127.0.0.1:3022] status[0]
(99158)[ 0.282] TRACE ziti-sdk:connect.c:1038 ziti_channel_start_connection() conn[0.0/Connecting] ch[0] => Edge Connect request token[ba925d66-58e1-459f-b5a7-f274fd9b8363]
(99158)[ 0.282] DEBUG ziti-sdk:channel.c:215 ziti_channel_add_receiver() ch[0] added receiver[0]
(99158)[ 0.282] TRACE ziti-sdk:channel.c:403 ziti_channel_send_for_reply() ch[0] => ct[ED6F] seq[1] len[36]
(99158)[ 0.282] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=218
(99158)[ 0.286] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=108]
(99158)[ 0.286] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED70] seq[1] len[0] hdrs[88]
(99158)[ 0.286] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[1] body+hrds=0+88, in_offset=0, want=88, got=88
(99158)[ 0.286] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[1] ct[ED70]
(99158)[ 0.286] TRACE ziti-sdk:connect.c:974 connect_reply_cb() conn[0.0/Connecting] connected
(99158)[ 0.286] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.0/Connecting] transitioning Connecting => Connected
(99158)[ 0.286] VERBOSE ziti-sdk:zitilib.c:477 connect_socket() connecting client socket[13]
(99158)[ 0.286] VERBOSE ziti-sdk:zitilib.c:499 connect_socket() connected client socket[13] <-> ziti_fd[17]
(99158)[ 0.286] DEBUG ziti-sdk:zitilib.c:587 on_ziti_connect() bridge connected to ziti fd[13]->ziti_fd[17]->conn[0]->service[python.flask]
(99158)[ 0.286] DEBUG ziti-sdk:conn_bridge.c:95 ziti_conn_bridge() br[0.0] connected
(99158)[ 0.286] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.0/Connected] starting flusher
(99158)[ 0.286] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=68
(99158)[ 0.286] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.0/Connected] status 0
(99158)[ 0.286] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.0/Connected] 0 bytes available
(99158)[ 0.286] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.0/Connected] flushed 0 messages
(99158)[ 0.286] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.0/Connected] stopping flusher
(99158)[ 0.286] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=68]
(99158)[ 0.286] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[2] len[24] hdrs[24]
(99158)[ 0.286] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[2] body+hrds=24+24, in_offset=0, want=48, got=48
(99158)[ 0.286] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[2] ct[ED72]
(99158)[ 0.286] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.0/Connected] starting flusher
(99158)[ 0.286] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.0/Connected] <= ct[ED72] edge_seq[1] body[24]
(99158)[ 0.286] VERBOSE ziti-sdk:connect.c:867 conn_inbound_data_msg() conn[0.0/Connected] processing crypto header(24 bytes)
(99158)[ 0.286] VERBOSE ziti-sdk:connect.c:870 conn_inbound_data_msg() conn[0.0/Connected] processed crypto header
(99158)[ 0.286] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.0/Connected] 0 bytes available
(99158)[ 0.286] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.0/Connected] flushed 0 messages
(99158)[ 0.286] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.0/Connected] stopping flusher
(99158)[ 0.286] TRACE ziti-sdk:conn_bridge.c:309 bridge_alloc() br[0.0] alloc live
(99158)[ 0.286] TRACE ziti-sdk:connect.c:1307 ziti_write() conn[0.0/Connected] write 106 bytes
(99158)[ 0.286] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.0/Connected] starting flusher
(99158)[ 0.286] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.0/Connected] 0 bytes available
(99158)[ 0.286] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.0/Connected] flushed 1 messages
(99158)[ 0.286] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.0/Connected] stopping flusher
(99158)[ 0.286] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=167
(99158)[ 0.286] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.0/Connected] status 0
(99158)[ 0.287] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=273]
(99158)[ 0.287] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[3] len[173] hdrs[24]
(99158)[ 0.287] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[3] body+hrds=173+24, in_offset=0, want=197, got=197
(99158)[ 0.287] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[3] ct[ED72]
(99158)[ 0.287] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.0/Connected] starting flusher
(99158)[ 0.287] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[4] len[0] hdrs[36]
(99158)[ 0.287] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[4] body+hrds=0+36, in_offset=0, want=36, got=36
(99158)[ 0.287] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[4] ct[ED72]
(99158)[ 0.287] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.0/Connected] starting flusher
(99158)[ 0.287] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.0/Connected] <= ct[ED72] edge_seq[2] body[173]
(99158)[ 0.287] VERBOSE ziti-sdk:connect.c:877 conn_inbound_data_msg() conn[0.0/Connected] decrypting 173 bytes
(99158)[ 0.287] VERBOSE ziti-sdk:connect.c:881 conn_inbound_data_msg() conn[0.0/Connected] decrypted 156 bytes
(99158)[ 0.287] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.0/Connected] <= ct[ED72] edge_seq[3] body[0]
(99158)[ 0.287] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.0/Connected] 156 bytes available
(99158)[ 0.287] TRACE ziti-sdk:conn_bridge.c:264 on_ziti_data() br[0.0] received 156 bytes from ziti
(99158)[ 0.287] TRACE ziti-sdk:connect.c:825 flush_to_client() conn[0.0/Connected] client consumed 156 out of 156 bytes
(99158)[ 0.287] VERBOSE ziti-sdk:conn_bridge.c:284 on_ziti_data() br[0.0] received EOF from ziti
(99158)[ 0.287] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.0/Connected] flushed 0 messages
(99158)[ 0.287] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.0/Connected] stopping flusher
(99158)[ 0.287] DEBUG ziti-sdk:zitilib.c:543 Ziti_close() closing ziti socket[13]
(99158)[ 0.288] DEBUG ziti-sdk:zitilib.c:530 close_work() closing client fd[13]
(99158)[ 0.288] WARN ziti-sdk:conn_bridge.c:245 on_shutdown() br[0.0] shutdown failed: -57(socket is not connected)
(99158)[ 0.288] DEBUG ziti-sdk:conn_bridge.c:225 close_bridge() br[0.0] closing
(99158)[ 0.288] DEBUG ziti-sdk:zitilib.c:565 on_bridge_close() closed conn for socket(13)
(99158)[ 0.288] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=44
(99158)[ 0.288] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.0/Connected] status 0
(99158)[ 0.288] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.0/Connected] transitioning Connected => Closed
(99158)[ 0.288] DEBUG ziti-sdk:channel.c:222 ziti_channel_rem_receiver() ch[0] removed receiver[0]
(99158)[ 0.288] DEBUG ziti-sdk:connect.c:169 close_conn_internal() conn[0.0/Closed] removing
(99158)[ 0.288] TRACE ziti-sdk:connect.c:144 free_ziti_listen_opts() refuse to free NULL listen_opts
(99158)[ 0.288] TRACE ziti-sdk:connect.c:212 close_conn_internal() conn[0.0/Closed] is being free()'d
(99158)[ 0.288] DEBUG ziti-sdk:ziti.c:1591 grim_reaper() ztx[0] reaped 1 closed (out of 1 total) connections
(99158)[ 0.288] DEBUG ziti-sdk:zitilib.c:1230 Ziti_resolve() host[python.flask.ziti] port[80]
(99158)[ 0.288] DEBUG ziti-sdk:zitilib.c:1195 resolve_cb() resolving python.flask.ziti
(99158)[ 0.288] DEBUG ziti-sdk:zitilib.c:599 find_service() looking up 0:python.flask.ziti:80
(99158)[ 0.288] DEBUG ziti-sdk:zitilib.c:1201 resolve_cb() python.flask.ziti:80 => python.flask
(99158)[ 0.288] VERBOSE ziti-sdk:zitilib.c:508 check_socket() checking client fd[13]
(99158)[ 0.289] DEBUG ziti-sdk:zitilib.c:634 do_ziti_connect() connecting fd[13] to 100.64.0.1:80
(99158)[ 0.289] DEBUG ziti-sdk:zitilib.c:599 find_service() looking up 1:python.flask.ziti:80
(99158)[ 0.289] DEBUG ziti-sdk:zitilib.c:689 do_ziti_connect() connecting fd[13] to service[python.flask]
(99158)[ 0.289] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.1/Initial] transitioning Initial => Connecting
(99158)[ 0.289] VERBOSE ziti-sdk:posture.c:198 ziti_send_posture_data() ztx[0] starting to send posture data
(99158)[ 0.289] DEBUG ziti-sdk:posture.c:211 ziti_send_posture_data() ztx[0] posture checks must_send set to TRUE, new_session_id[FALSE], must_send_every_time[TRUE], new_controller_instance[FALSE]
(99158)[ 0.289] VERBOSE ziti-sdk:posture.c:236 ziti_send_posture_data() ztx[0] checking posture queries on 1 service(s)
(99158)[ 0.289] VERBOSE ziti-sdk:posture.c:535 ziti_pr_send_bulk() ztx[0] no change in posture data, not sending
(99158)[ 0.289] DEBUG ziti-sdk:connect.c:532 process_connect() conn[0.1/Connecting] starting Dial connection for service[python.flask] with session[clgdyfjko8eyxif9k8rsvqp4j]
(99158)[ 0.289] DEBUG ziti-sdk:connect.c:415 ziti_connect() conn[0.1/Connecting] selected ch[MacBook-Pro-edge-router@tls://127.0.0.1:3022] for best latency(0 ms)
(99158)[ 0.289] DEBUG ziti-sdk:connect.c:302 on_channel_connected() conn[0.1/Connecting] selected ch[MacBook-Pro-edge-router@tls://127.0.0.1:3022] status[0]
(99158)[ 0.289] TRACE ziti-sdk:connect.c:1038 ziti_channel_start_connection() conn[0.1/Connecting] ch[0] => Edge Connect request token[ba925d66-58e1-459f-b5a7-f274fd9b8363]
(99158)[ 0.289] DEBUG ziti-sdk:channel.c:215 ziti_channel_add_receiver() ch[0] added receiver[1]
(99158)[ 0.289] TRACE ziti-sdk:channel.c:403 ziti_channel_send_for_reply() ch[0] => ct[ED6F] seq[2] len[36]
(99158)[ 0.289] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=218
(99158)[ 0.291] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=108]
(99158)[ 0.291] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED70] seq[5] len[0] hdrs[88]
(99158)[ 0.291] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[5] body+hrds=0+88, in_offset=0, want=88, got=88
(99158)[ 0.291] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[5] ct[ED70]
(99158)[ 0.291] TRACE ziti-sdk:connect.c:974 connect_reply_cb() conn[0.1/Connecting] connected
(99158)[ 0.291] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.1/Connecting] transitioning Connecting => Connected
(99158)[ 0.291] VERBOSE ziti-sdk:zitilib.c:477 connect_socket() connecting client socket[13]
(99158)[ 0.291] VERBOSE ziti-sdk:zitilib.c:499 connect_socket() connected client socket[13] <-> ziti_fd[17]
(99158)[ 0.291] DEBUG ziti-sdk:zitilib.c:587 on_ziti_connect() bridge connected to ziti fd[13]->ziti_fd[17]->conn[1]->service[python.flask]
(99158)[ 0.291] DEBUG ziti-sdk:conn_bridge.c:95 ziti_conn_bridge() br[0.1] connected
(99158)[ 0.291] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.1/Connected] starting flusher
(99158)[ 0.291] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=68
(99158)[ 0.291] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.1/Connected] status 0
(99158)[ 0.291] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.1/Connected] 0 bytes available
(99158)[ 0.291] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.1/Connected] flushed 0 messages
(99158)[ 0.291] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.1/Connected] stopping flusher
(99158)[ 0.291] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=68]
(99158)[ 0.291] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[6] len[24] hdrs[24]
(99158)[ 0.291] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[6] body+hrds=24+24, in_offset=0, want=48, got=48
(99158)[ 0.291] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[6] ct[ED72]
(99158)[ 0.291] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.1/Connected] starting flusher
(99158)[ 0.291] TRACE ziti-sdk:conn_bridge.c:309 bridge_alloc() br[0.1] alloc live
(99158)[ 0.291] TRACE ziti-sdk:connect.c:1307 ziti_write() conn[0.1/Connected] write 106 bytes
(99158)[ 0.291] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.1/Connected] starting flusher
(99158)[ 0.291] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.1/Connected] <= ct[ED72] edge_seq[1] body[24]
(99158)[ 0.291] VERBOSE ziti-sdk:connect.c:867 conn_inbound_data_msg() conn[0.1/Connected] processing crypto header(24 bytes)
(99158)[ 0.291] VERBOSE ziti-sdk:connect.c:870 conn_inbound_data_msg() conn[0.1/Connected] processed crypto header
(99158)[ 0.291] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.1/Connected] 0 bytes available
(99158)[ 0.291] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.1/Connected] flushed 1 messages
(99158)[ 0.291] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.1/Connected] stopping flusher
(99158)[ 0.291] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=167
(99158)[ 0.291] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.1/Connected] status 0
(99158)[ 0.292] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=273]
(99158)[ 0.292] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[7] len[173] hdrs[24]
(99158)[ 0.292] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[7] body+hrds=173+24, in_offset=0, want=197, got=197
(99158)[ 0.292] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[7] ct[ED72]
(99158)[ 0.292] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.1/Connected] starting flusher
(99158)[ 0.292] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[8] len[0] hdrs[36]
(99158)[ 0.292] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[8] body+hrds=0+36, in_offset=0, want=36, got=36
(99158)[ 0.292] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[8] ct[ED72]
(99158)[ 0.292] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.1/Connected] starting flusher
(99158)[ 0.292] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.1/Connected] <= ct[ED72] edge_seq[2] body[173]
(99158)[ 0.292] VERBOSE ziti-sdk:connect.c:877 conn_inbound_data_msg() conn[0.1/Connected] decrypting 173 bytes
(99158)[ 0.292] VERBOSE ziti-sdk:connect.c:881 conn_inbound_data_msg() conn[0.1/Connected] decrypted 156 bytes
(99158)[ 0.292] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.1/Connected] <= ct[ED72] edge_seq[3] body[0]
(99158)[ 0.292] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.1/Connected] 156 bytes available
(99158)[ 0.292] TRACE ziti-sdk:conn_bridge.c:264 on_ziti_data() br[0.1] received 156 bytes from ziti
(99158)[ 0.292] TRACE ziti-sdk:connect.c:825 flush_to_client() conn[0.1/Connected] client consumed 156 out of 156 bytes
(99158)[ 0.292] VERBOSE ziti-sdk:conn_bridge.c:284 on_ziti_data() br[0.1] received EOF from ziti
(99158)[ 0.292] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.1/Connected] flushed 0 messages
(99158)[ 0.292] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.1/Connected] stopping flusher
(99158)[ 0.292] DEBUG ziti-sdk:zitilib.c:543 Ziti_close() closing ziti socket[13]
(99158)[ 0.292] DEBUG ziti-sdk:zitilib.c:530 close_work() closing client fd[13]
(99158)[ 0.292] WARN ziti-sdk:conn_bridge.c:245 on_shutdown() br[0.1] shutdown failed: -57(socket is not connected)
(99158)[ 0.292] DEBUG ziti-sdk:conn_bridge.c:225 close_bridge() br[0.1] closing
(99158)[ 0.292] DEBUG ziti-sdk:zitilib.c:565 on_bridge_close() closed conn for socket(13)
(99158)[ 0.292] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=44
(99158)[ 0.292] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.1/Connected] status 0
(99158)[ 0.292] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.1/Connected] transitioning Connected => Closed
(99158)[ 0.292] DEBUG ziti-sdk:channel.c:222 ziti_channel_rem_receiver() ch[0] removed receiver[1]
(99158)[ 0.292] DEBUG ziti-sdk:connect.c:169 close_conn_internal() conn[0.1/Closed] removing
(99158)[ 0.292] TRACE ziti-sdk:connect.c:144 free_ziti_listen_opts() refuse to free NULL listen_opts
(99158)[ 0.292] TRACE ziti-sdk:connect.c:212 close_conn_internal() conn[0.1/Closed] is being free()'d
(99158)[ 0.292] DEBUG ziti-sdk:ziti.c:1591 grim_reaper() ztx[0] reaped 1 closed (out of 1 total) connections
(99158)[ 0.292] DEBUG ziti-sdk:zitilib.c:1230 Ziti_resolve() host[python.flask.ziti] port[80]
(99158)[ 0.292] DEBUG ziti-sdk:zitilib.c:1195 resolve_cb() resolving python.flask.ziti
(99158)[ 0.292] DEBUG ziti-sdk:zitilib.c:599 find_service() looking up 0:python.flask.ziti:80
(99158)[ 0.292] DEBUG ziti-sdk:zitilib.c:1201 resolve_cb() python.flask.ziti:80 => python.flask
(99158)[ 0.293] VERBOSE ziti-sdk:zitilib.c:508 check_socket() checking client fd[13]
(99158)[ 0.293] DEBUG ziti-sdk:zitilib.c:634 do_ziti_connect() connecting fd[13] to 100.64.0.1:80
(99158)[ 0.293] DEBUG ziti-sdk:zitilib.c:599 find_service() looking up 1:python.flask.ziti:80
(99158)[ 0.293] DEBUG ziti-sdk:zitilib.c:689 do_ziti_connect() connecting fd[13] to service[python.flask]
(99158)[ 0.293] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.2/Initial] transitioning Initial => Connecting
(99158)[ 0.293] VERBOSE ziti-sdk:posture.c:198 ziti_send_posture_data() ztx[0] starting to send posture data
(99158)[ 0.293] DEBUG ziti-sdk:posture.c:211 ziti_send_posture_data() ztx[0] posture checks must_send set to TRUE, new_session_id[FALSE], must_send_every_time[TRUE], new_controller_instance[FALSE]
(99158)[ 0.293] VERBOSE ziti-sdk:posture.c:236 ziti_send_posture_data() ztx[0] checking posture queries on 1 service(s)
(99158)[ 0.293] VERBOSE ziti-sdk:posture.c:535 ziti_pr_send_bulk() ztx[0] no change in posture data, not sending
(99158)[ 0.293] DEBUG ziti-sdk:connect.c:532 process_connect() conn[0.2/Connecting] starting Dial connection for service[python.flask] with session[clgdyfjko8eyxif9k8rsvqp4j]
(99158)[ 0.293] DEBUG ziti-sdk:connect.c:415 ziti_connect() conn[0.2/Connecting] selected ch[MacBook-Pro-edge-router@tls://127.0.0.1:3022] for best latency(0 ms)
(99158)[ 0.293] DEBUG ziti-sdk:connect.c:302 on_channel_connected() conn[0.2/Connecting] selected ch[MacBook-Pro-edge-router@tls://127.0.0.1:3022] status[0]
(99158)[ 0.293] TRACE ziti-sdk:connect.c:1038 ziti_channel_start_connection() conn[0.2/Connecting] ch[0] => Edge Connect request token[ba925d66-58e1-459f-b5a7-f274fd9b8363]
(99158)[ 0.293] DEBUG ziti-sdk:channel.c:215 ziti_channel_add_receiver() ch[0] added receiver[2]
(99158)[ 0.293] TRACE ziti-sdk:channel.c:403 ziti_channel_send_for_reply() ch[0] => ct[ED6F] seq[3] len[36]
(99158)[ 0.293] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=218
(99158)[ 0.297] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=108]
(99158)[ 0.297] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED70] seq[9] len[0] hdrs[88]
(99158)[ 0.297] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[9] body+hrds=0+88, in_offset=0, want=88, got=88
(99158)[ 0.297] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[9] ct[ED70]
(99158)[ 0.297] TRACE ziti-sdk:connect.c:974 connect_reply_cb() conn[0.2/Connecting] connected
(99158)[ 0.297] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.2/Connecting] transitioning Connecting => Connected
(99158)[ 0.297] VERBOSE ziti-sdk:zitilib.c:477 connect_socket() connecting client socket[13]
(99158)[ 0.297] VERBOSE ziti-sdk:zitilib.c:499 connect_socket() connected client socket[13] <-> ziti_fd[17]
(99158)[ 0.297] DEBUG ziti-sdk:zitilib.c:587 on_ziti_connect() bridge connected to ziti fd[13]->ziti_fd[17]->conn[2]->service[python.flask]
(99158)[ 0.297] DEBUG ziti-sdk:conn_bridge.c:95 ziti_conn_bridge() br[0.2] connected
(99158)[ 0.297] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.2/Connected] starting flusher
(99158)[ 0.297] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=68
(99158)[ 0.297] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.2/Connected] status 0
(99158)[ 0.298] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.2/Connected] 0 bytes available
(99158)[ 0.298] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.2/Connected] flushed 0 messages
(99158)[ 0.298] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.2/Connected] stopping flusher
(99158)[ 0.298] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=68]
(99158)[ 0.298] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[10] len[24] hdrs[24]
(99158)[ 0.298] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[10] body+hrds=24+24, in_offset=0, want=48, got=48
(99158)[ 0.298] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[10] ct[ED72]
(99158)[ 0.298] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.2/Connected] starting flusher
(99158)[ 0.298] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.2/Connected] <= ct[ED72] edge_seq[1] body[24]
(99158)[ 0.298] VERBOSE ziti-sdk:connect.c:867 conn_inbound_data_msg() conn[0.2/Connected] processing crypto header(24 bytes)
(99158)[ 0.298] VERBOSE ziti-sdk:connect.c:870 conn_inbound_data_msg() conn[0.2/Connected] processed crypto header
(99158)[ 0.298] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.2/Connected] 0 bytes available
(99158)[ 0.298] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.2/Connected] flushed 0 messages
(99158)[ 0.298] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.2/Connected] stopping flusher
(99158)[ 0.298] TRACE ziti-sdk:conn_bridge.c:309 bridge_alloc() br[0.2] alloc live
(99158)[ 0.298] TRACE ziti-sdk:connect.c:1307 ziti_write() conn[0.2/Connected] write 106 bytes
(99158)[ 0.298] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.2/Connected] starting flusher
(99158)[ 0.298] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.2/Connected] 0 bytes available
(99158)[ 0.298] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.2/Connected] flushed 1 messages
(99158)[ 0.298] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.2/Connected] stopping flusher
(99158)[ 0.298] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=167
(99158)[ 0.298] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.2/Connected] status 0
(99158)[ 0.299] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=273]
(99158)[ 0.299] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[11] len[173] hdrs[24]
(99158)[ 0.299] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[11] body+hrds=173+24, in_offset=0, want=197, got=197
(99158)[ 0.299] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[11] ct[ED72]
(99158)[ 0.299] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.2/Connected] starting flusher
(99158)[ 0.299] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[12] len[0] hdrs[36]
(99158)[ 0.299] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[12] body+hrds=0+36, in_offset=0, want=36, got=36
(99158)[ 0.299] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[12] ct[ED72]
(99158)[ 0.299] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.2/Connected] starting flusher
(99158)[ 0.299] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.2/Connected] <= ct[ED72] edge_seq[2] body[173]
(99158)[ 0.299] VERBOSE ziti-sdk:connect.c:877 conn_inbound_data_msg() conn[0.2/Connected] decrypting 173 bytes
(99158)[ 0.299] VERBOSE ziti-sdk:connect.c:881 conn_inbound_data_msg() conn[0.2/Connected] decrypted 156 bytes
(99158)[ 0.299] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.2/Connected] <= ct[ED72] edge_seq[3] body[0]
(99158)[ 0.299] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.2/Connected] 156 bytes available
(99158)[ 0.299] TRACE ziti-sdk:conn_bridge.c:264 on_ziti_data() br[0.2] received 156 bytes from ziti
(99158)[ 0.299] TRACE ziti-sdk:connect.c:825 flush_to_client() conn[0.2/Connected] client consumed 156 out of 156 bytes
(99158)[ 0.299] VERBOSE ziti-sdk:conn_bridge.c:284 on_ziti_data() br[0.2] received EOF from ziti
(99158)[ 0.299] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.2/Connected] flushed 0 messages
(99158)[ 0.299] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.2/Connected] stopping flusher
(99158)[ 0.299] DEBUG ziti-sdk:zitilib.c:543 Ziti_close() closing ziti socket[13]
(99158)[ 0.299] DEBUG ziti-sdk:zitilib.c:530 close_work() closing client fd[13]
(99158)[ 0.299] WARN ziti-sdk:conn_bridge.c:245 on_shutdown() br[0.2] shutdown failed: -57(socket is not connected)
(99158)[ 0.299] DEBUG ziti-sdk:conn_bridge.c:225 close_bridge() br[0.2] closing
(99158)[ 0.299] DEBUG ziti-sdk:zitilib.c:565 on_bridge_close() closed conn for socket(13)
(99158)[ 0.299] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=44
(99158)[ 0.299] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.2/Connected] status 0
(99158)[ 0.299] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.2/Connected] transitioning Connected => Closed
(99158)[ 0.299] DEBUG ziti-sdk:channel.c:222 ziti_channel_rem_receiver() ch[0] removed receiver[2]
(99158)[ 0.299] DEBUG ziti-sdk:connect.c:169 close_conn_internal() conn[0.2/Closed] removing
(99158)[ 0.299] TRACE ziti-sdk:connect.c:144 free_ziti_listen_opts() refuse to free NULL listen_opts
(99158)[ 0.299] TRACE ziti-sdk:connect.c:212 close_conn_internal() conn[0.2/Closed] is being free()'d
(99158)[ 0.299] DEBUG ziti-sdk:ziti.c:1591 grim_reaper() ztx[0] reaped 1 closed (out of 1 total) connections
(99158)[ 0.299] DEBUG ziti-sdk:zitilib.c:1230 Ziti_resolve() host[python.flask.ziti] port[80]
(99158)[ 0.300] DEBUG ziti-sdk:zitilib.c:1195 resolve_cb() resolving python.flask.ziti
(99158)[ 0.300] DEBUG ziti-sdk:zitilib.c:599 find_service() looking up 0:python.flask.ziti:80
(99158)[ 0.300] DEBUG ziti-sdk:zitilib.c:1201 resolve_cb() python.flask.ziti:80 => python.flask
(99158)[ 0.300] VERBOSE ziti-sdk:zitilib.c:508 check_socket() checking client fd[13]
(99158)[ 0.300] DEBUG ziti-sdk:zitilib.c:634 do_ziti_connect() connecting fd[13] to 100.64.0.1:80
(99158)[ 0.300] DEBUG ziti-sdk:zitilib.c:599 find_service() looking up 1:python.flask.ziti:80
(99158)[ 0.300] DEBUG ziti-sdk:zitilib.c:689 do_ziti_connect() connecting fd[13] to service[python.flask]
(99158)[ 0.300] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.3/Initial] transitioning Initial => Connecting
(99158)[ 0.300] VERBOSE ziti-sdk:posture.c:198 ziti_send_posture_data() ztx[0] starting to send posture data
(99158)[ 0.300] DEBUG ziti-sdk:posture.c:211 ziti_send_posture_data() ztx[0] posture checks must_send set to TRUE, new_session_id[FALSE], must_send_every_time[TRUE], new_controller_instance[FALSE]
(99158)[ 0.300] VERBOSE ziti-sdk:posture.c:236 ziti_send_posture_data() ztx[0] checking posture queries on 1 service(s)
(99158)[ 0.300] VERBOSE ziti-sdk:posture.c:535 ziti_pr_send_bulk() ztx[0] no change in posture data, not sending
(99158)[ 0.300] DEBUG ziti-sdk:connect.c:532 process_connect() conn[0.3/Connecting] starting Dial connection for service[python.flask] with session[clgdyfjko8eyxif9k8rsvqp4j]
(99158)[ 0.300] DEBUG ziti-sdk:connect.c:415 ziti_connect() conn[0.3/Connecting] selected ch[MacBook-Pro-edge-router@tls://127.0.0.1:3022] for best latency(0 ms)
(99158)[ 0.300] DEBUG ziti-sdk:connect.c:302 on_channel_connected() conn[0.3/Connecting] selected ch[MacBook-Pro-edge-router@tls://127.0.0.1:3022] status[0]
(99158)[ 0.300] TRACE ziti-sdk:connect.c:1038 ziti_channel_start_connection() conn[0.3/Connecting] ch[0] => Edge Connect request token[ba925d66-58e1-459f-b5a7-f274fd9b8363]
(99158)[ 0.300] DEBUG ziti-sdk:channel.c:215 ziti_channel_add_receiver() ch[0] added receiver[3]
(99158)[ 0.300] TRACE ziti-sdk:channel.c:403 ziti_channel_send_for_reply() ch[0] => ct[ED6F] seq[4] len[36]
(99158)[ 0.300] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=218
(99158)[ 0.302] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=108]
(99158)[ 0.302] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED70] seq[13] len[0] hdrs[88]
(99158)[ 0.302] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[13] body+hrds=0+88, in_offset=0, want=88, got=88
(99158)[ 0.302] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[13] ct[ED70]
(99158)[ 0.302] TRACE ziti-sdk:connect.c:974 connect_reply_cb() conn[0.3/Connecting] connected
(99158)[ 0.302] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.3/Connecting] transitioning Connecting => Connected
(99158)[ 0.302] VERBOSE ziti-sdk:zitilib.c:477 connect_socket() connecting client socket[13]
(99158)[ 0.302] VERBOSE ziti-sdk:zitilib.c:499 connect_socket() connected client socket[13] <-> ziti_fd[17]
(99158)[ 0.302] DEBUG ziti-sdk:zitilib.c:587 on_ziti_connect() bridge connected to ziti fd[13]->ziti_fd[17]->conn[3]->service[python.flask]
(99158)[ 0.302] DEBUG ziti-sdk:conn_bridge.c:95 ziti_conn_bridge() br[0.3] connected
(99158)[ 0.302] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.3/Connected] starting flusher
(99158)[ 0.302] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=68
(99158)[ 0.302] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.3/Connected] status 0
(99158)[ 0.302] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.3/Connected] 0 bytes available
(99158)[ 0.302] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.3/Connected] flushed 0 messages
(99158)[ 0.302] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.3/Connected] stopping flusher
(99158)[ 0.302] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=68]
(99158)[ 0.302] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[14] len[24] hdrs[24]
(99158)[ 0.302] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[14] body+hrds=24+24, in_offset=0, want=48, got=48
(99158)[ 0.302] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[14] ct[ED72]
(99158)[ 0.302] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.3/Connected] starting flusher
(99158)[ 0.303] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.3/Connected] <= ct[ED72] edge_seq[1] body[24]
(99158)[ 0.303] VERBOSE ziti-sdk:connect.c:867 conn_inbound_data_msg() conn[0.3/Connected] processing crypto header(24 bytes)
(99158)[ 0.303] VERBOSE ziti-sdk:connect.c:870 conn_inbound_data_msg() conn[0.3/Connected] processed crypto header
(99158)[ 0.303] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.3/Connected] 0 bytes available
(99158)[ 0.303] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.3/Connected] flushed 0 messages
(99158)[ 0.303] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.3/Connected] stopping flusher
(99158)[ 0.303] TRACE ziti-sdk:conn_bridge.c:309 bridge_alloc() br[0.3] alloc live
(99158)[ 0.303] TRACE ziti-sdk:connect.c:1307 ziti_write() conn[0.3/Connected] write 106 bytes
(99158)[ 0.303] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.3/Connected] starting flusher
(99158)[ 0.303] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.3/Connected] 0 bytes available
(99158)[ 0.303] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.3/Connected] flushed 1 messages
(99158)[ 0.303] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.3/Connected] stopping flusher
(99158)[ 0.303] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=167
(99158)[ 0.303] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.3/Connected] status 0
(99158)[ 0.303] TRACE ziti-sdk:channel.c:836 on_channel_data() ch[0] on_data [len=273]
(99158)[ 0.303] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[15] len[173] hdrs[24]
(99158)[ 0.303] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[15] body+hrds=173+24, in_offset=0, want=197, got=197
(99158)[ 0.303] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[15] ct[ED72]
(99158)[ 0.303] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.3/Connected] starting flusher
(99158)[ 0.303] TRACE ziti-sdk:channel.c:523 process_inbound() ch[0] <= ct[ED72] seq[16] len[0] hdrs[36]
(99158)[ 0.303] TRACE ziti-sdk:channel.c:533 process_inbound() ch[0] completing msg seq[16] body+hrds=0+36, in_offset=0, want=36, got=36
(99158)[ 0.303] TRACE ziti-sdk:channel.c:544 process_inbound() ch[0] message is complete seq[16] ct[ED72]
(99158)[ 0.303] TRACE ziti-sdk:connect.c:776 flush_connection() conn[0.3/Connected] starting flusher
(99158)[ 0.303] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.3/Connected] <= ct[ED72] edge_seq[2] body[173]
(99158)[ 0.303] VERBOSE ziti-sdk:connect.c:877 conn_inbound_data_msg() conn[0.3/Connected] decrypting 173 bytes
(99158)[ 0.303] VERBOSE ziti-sdk:connect.c:881 conn_inbound_data_msg() conn[0.3/Connected] decrypted 156 bytes
(99158)[ 0.303] TRACE ziti-sdk:connect.c:1449 process_edge_message() conn[0.3/Connected] <= ct[ED72] edge_seq[3] body[0]
(99158)[ 0.303] VERBOSE ziti-sdk:connect.c:819 flush_to_client() conn[0.3/Connected] 156 bytes available
(99158)[ 0.303] TRACE ziti-sdk:conn_bridge.c:264 on_ziti_data() br[0.3] received 156 bytes from ziti
(99158)[ 0.303] TRACE ziti-sdk:connect.c:825 flush_to_client() conn[0.3/Connected] client consumed 156 out of 156 bytes
(99158)[ 0.303] VERBOSE ziti-sdk:conn_bridge.c:284 on_ziti_data() br[0.3] received EOF from ziti
(99158)[ 0.303] TRACE ziti-sdk:connect.c:806 flush_to_service() conn[0.3/Connected] flushed 0 messages
(99158)[ 0.303] TRACE ziti-sdk:connect.c:769 on_flush() conn[0.3/Connected] stopping flusher
(99158)[ 0.303] DEBUG ziti-sdk:zitilib.c:543 Ziti_close() closing ziti socket[13]
(99158)[ 0.304] DEBUG ziti-sdk:zitilib.c:530 close_work() closing client fd[13]
(99158)[ 0.304] WARN ziti-sdk:conn_bridge.c:245 on_shutdown() br[0.3] shutdown failed: -57(socket is not connected)
(99158)[ 0.304] DEBUG ziti-sdk:conn_bridge.c:225 close_bridge() br[0.3] closing
(99158)[ 0.304] DEBUG ziti-sdk:zitilib.c:565 on_bridge_close() closed conn for socket(13)
(99158)[ 0.304] TRACE ziti-sdk:channel.c:333 on_channel_send() ch[0] write delay = 0.000d q=1 qs=44
(99158)[ 0.304] TRACE ziti-sdk:connect.c:227 on_write_completed() conn[0.3/Connected] status 0
(99158)[ 0.304] VERBOSE ziti-sdk:connect.c:101 conn_set_state() conn[0.3/Connected] transitioning Connected => Closed
(99158)[ 0.304] DEBUG ziti-sdk:channel.c:222 ziti_channel_rem_receiver() ch[0] removed receiver[3]
(99158)[ 0.304] DEBUG ziti-sdk:connect.c:169 close_conn_internal() conn[0.3/Closed] removing
(99158)[ 0.304] TRACE ziti-sdk:connect.c:144 free_ziti_listen_opts() refuse to free NULL listen_opts
(99158)[ 0.304] TRACE ziti-sdk:connect.c:212 close_conn_internal() conn[0.3/Closed] is being free()'d
(99158)[ 0.304] DEBUG ziti-sdk:ziti.c:1591 grim_reaper() ztx[0] reaped 1 closed (out of 1 total) connections
Traceback (most recent call last):
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/response.py", line 444, in _error_catcher
yield
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/response.py", line 567, in read
data = self._fp_read(amt) if not fp_closed else b""
^^^^^^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/response.py", line 533, in _fp_read
return self._fp.read(amt) if amt is not None else self._fp.read()
^^^^^^^^^^^^^^^
File "/opt/homebrew/Cellar/[email protected]/3.11.2_1/Frameworks/Python.framework/Versions/3.11/lib/python3.11/http/client.py", line 478, in read
s = self.fp.read()
^^^^^^^^^^^^^^
File "/opt/homebrew/Cellar/[email protected]/3.11.2_1/Frameworks/Python.framework/Versions/3.11/lib/python3.11/socket.py", line 706, in readinto
return self._sock.recv_into(b)
^^^^^^^^^^^^^^^^^^^^^^^
OSError: [Errno 9] Bad file descriptor
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 723, in urlopen
response = self.ResponseCls.from_httplib(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/response.py", line 653, in from_httplib
resp = ResponseCls(
^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/response.py", line 266, in __init__
self._body = self.read(decode_content=decode_content)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/response.py", line 566, in read
with self._error_catcher():
File "/opt/homebrew/Cellar/[email protected]/3.11.2_1/Frameworks/Python.framework/Versions/3.11/lib/python3.11/contextlib.py", line 155, in __exit__
self.gen.throw(typ, value, traceback)
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/response.py", line 461, in _error_catcher
raise ProtocolError("Connection broken: %r" % e, e)
urllib3.exceptions.ProtocolError: ("Connection broken: OSError(9, 'Bad file descriptor')", OSError(9, 'Bad file descriptor'))
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/sample/ziti-urllib3/ziti-urllib3.py", line 22, in <module>
r = http.request('GET', sys.argv[1])
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/request.py", line 74, in request
return self.request_encode_url(
^^^^^^^^^^^^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/request.py", line 96, in request_encode_url
return self.urlopen(method, url, **extra_kw)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/poolmanager.py", line 376, in urlopen
response = conn.urlopen(method, u.request_uri, **kw)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 815, in urlopen
return self.urlopen(
^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 815, in urlopen
return self.urlopen(
^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 815, in urlopen
return self.urlopen(
^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/connectionpool.py", line 787, in urlopen
retries = retries.increment(
^^^^^^^^^^^^^^^^^^
File "/Users/geoffberl/git/NetFoundry/ziti-sdk-py/venv/lib/python3.11/site-packages/urllib3/util/retry.py", line 592, in increment
raise MaxRetryError(_pool, url, error or ResponseError(cause))
urllib3.exceptions.MaxRetryError: HTTPConnectionPool(host='python.flask.ziti', port=80): Max retries exceeded with url: / (Caused by ProtocolError("Connection broken: OSError(9, 'Bad file descriptor')", OSError(9, 'Bad file descriptor')))
[386273.924] ERROR fabric/router/handler_xgress.(*receiveHandler).HandleXgressReceive [{c/yEbF9kaJp|@/rzO0}<Terminator>]: {origin=[Terminator] uuid=[invalid-uuid-size-of-0-bytes] circuitId=[yEbF9kaJp] seq=[3] error=[cannot forward payload, no destination for circuit=yEbF9kaJp src=rzO0 dst=rwPK]} unable to forward payload