unable to recover API session

[qrkourier]

I'm running a Python edge SDK app continuously, which uses the C SDK, and it became de-authorized a few hours ago and seems to be stuck, unable to recover. I was able to curl /edge/client/v1/version while the edge SDK was reporting "CONTROLLER_UNAVAILABLE" so that message appears to be inaccurate:

2023-11-13T13:48:47.920Z     WARN ziti-sdk:ziti_ctrl.c:487 verify_api_session() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] no API session
2023-11-13T13:48:47.920Z     WARN ziti-sdk:bind.c:212 session_cb() server[0.0] failed to get session for service[classifier-service]: -14/UNAUTHORIZED
2023-11-13T13:48:52.655Z     INFO ziti-sdk:ziti.c:913 ziti_re_auth_with_cb() ztx[0] starting to re-auth with ctlr[https://db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io:443] api_session_status[0] api_session_expired[TRUE]
2023-11-13T13:48:57.759Z    ERROR ziti-sdk:ziti_ctrl.c:162 ctrl_resp_cb() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] request failed: -103(software caused connection abort)
2023-11-13T13:48:57.759Z     WARN ziti-sdk:ziti.c:1597 api_session_cb() ztx[0] failed to get api session from ctrl[https://db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io:443] api_session_state[1] CONTROLLER_UNAVAILABLE[-16] software caused connection abort

To recover, I bounced the Python application. It started normally.

This is the beginning of the interruption event time frame from the application log, ~5 hours earlier.

2023-11-13T09:07:29.789Z     INFO ziti-sdk:ziti.c:1560 ziti_set_api_session() ztx[0] api session set, setting api_session_timer to 1740s
2023-11-13T09:36:18.455Z    ERROR ziti-sdk:channel.c:831 on_channel_data() ch[0] unhandled error on_data [-110/connection timed out]
2023-11-13T09:36:18.455Z     WARN ziti-sdk:bind.c:335 on_message() binding failed: -21/connection to edge router terminated
2023-11-13T09:36:18.455Z     INFO ziti-sdk:channel.c:733 reconnect_channel() ch[0] reconnecting in 7687ms (attempt = 1)
2023-11-13T09:36:18.455Z    ERROR ziti-sdk:channel.c:831 on_channel_data() ch[1] unhandled error on_data [-110/connection timed out]
2023-11-13T09:36:18.455Z     WARN ziti-sdk:bind.c:335 on_message() binding failed: -21/connection to edge router terminated
2023-11-13T09:36:18.455Z     INFO ziti-sdk:channel.c:733 reconnect_channel() ch[1] reconnecting in 9511ms (attempt = 1)
2023-11-13T09:36:46.176Z    ERROR ziti-sdk:channel.c:675 ch_connect_timeout() ch[0] connect timeout
2023-11-13T09:36:46.176Z     INFO ziti-sdk:channel.c:733 reconnect_channel() ch[0] reconnecting in 5108ms (attempt = 2)
2023-11-13T09:36:46.176Z    ERROR ziti-sdk:channel.c:861 on_channel_connect_internal() ch[0] failed to connect to ER[OCI us-ashburn-1 Edge Router 1] [-125/operation canceled]
2023-11-13T09:36:46.176Z     INFO ziti-sdk:channel.c:733 reconnect_channel() ch[0] reconnecting in 1317ms (attempt = 3)
2023-11-13T09:36:47.977Z    ERROR ziti-sdk:channel.c:675 ch_connect_timeout() ch[1] connect timeout
2023-11-13T09:36:47.977Z     INFO ziti-sdk:channel.c:733 reconnect_channel() ch[1] reconnecting in 1561ms (attempt = 2)
2023-11-13T09:36:47.977Z    ERROR ziti-sdk:channel.c:861 on_channel_connect_internal() ch[1] failed to connect to ER[AWS Public Router] [-125/operation canceled]
2023-11-13T09:36:47.977Z     INFO ziti-sdk:channel.c:733 reconnect_channel() ch[1] reconnecting in 12586ms (attempt = 3)
2023-11-13T09:37:07.524Z    ERROR ziti-sdk:channel.c:675 ch_connect_timeout() ch[0] connect timeout
2023-11-13T09:37:07.524Z     INFO ziti-sdk:channel.c:733 reconnect_channel() ch[0] reconnecting in 51658ms (attempt = 4)
2023-11-13T09:37:07.524Z    ERROR ziti-sdk:channel.c:861 on_channel_connect_internal() ch[0] failed to connect to ER[OCI us-ashburn-1 Edge Router 1] [-125/operation canceled]
2023-11-13T09:37:07.524Z     INFO ziti-sdk:channel.c:733 reconnect_channel() ch[0] reconnecting in 100486ms (attempt = 5)
2023-11-13T09:37:14.711Z    ERROR ziti-sdk:ziti_ctrl.c:162 ctrl_resp_cb() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] request failed: -3001(temporary failure)
2023-11-13T09:37:14.711Z     WARN ziti-sdk:bind.c:212 session_cb() server[0.0] failed to get session for service[classifier-service]: -16/CONTROLLER_UNAVAILABLE
2023-11-13T09:37:14.711Z    ERROR ziti-sdk:ziti_ctrl.c:162 ctrl_resp_cb() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] request failed: -3001(temporary failure)
2023-11-13T09:37:14.711Z     WARN ziti-sdk:ziti.c:1597 api_session_cb() ztx[0] failed to get api session from ctrl[https://db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io:443] api_session_state[3] CONTROLLER_UNAVAILABLE[-16] temporary failure
2023-11-13T09:37:14.711Z    ERROR ziti-sdk:ziti_ctrl.c:162 ctrl_resp_cb() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] request failed: -3001(temporary failure)
2023-11-13T09:37:14.711Z    ERROR ziti-sdk:ziti.c:1307 edge_routers_cb() ztx[0] failed to get current edge routers: CONTROLLER_UNAVAILABLE/temporary failure
2023-11-13T09:37:14.711Z    ERROR ziti-sdk:ziti_ctrl.c:162 ctrl_resp_cb() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] request failed: -3001(temporary failure)
2023-11-13T09:37:14.711Z     WARN ziti-sdk:ziti_ctrl.c:487 verify_api_session() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] no API session
2023-11-13T09:37:14.711Z    ERROR ziti-sdk:ziti.c:1099 update_services() ztx[0] failed to get service updates err[UNAUTHORIZED/no api session token set for ziti_controller] from ctrl[https://db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io:443]
2023-11-13T09:37:14.711Z     WARN ziti-sdk:ziti.c:1101 update_services() ztx[0] api session is no longer valid. Trying to re-auth
2023-11-13T09:37:14.711Z     INFO ziti-sdk:ziti.c:913 ziti_re_auth_with_cb() ztx[0] starting to re-auth with ctlr[https://db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io:443] api_session_status[0] api_session_expired[TRUE]
2023-11-13T09:37:14.711Z    ERROR ziti-sdk:ziti_ctrl.c:162 ctrl_resp_cb() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] request failed: -3001(temporary failure)
2023-11-13T09:37:14.711Z     WARN ziti-sdk:ziti.c:1597 api_session_cb() ztx[0] failed to get api session from ctrl[https://db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io:443] api_session_state[1] CONTROLLER_UNAVAILABLE[-16] temporary failure
2023-11-13T09:37:14.953Z     WARN ziti-sdk:ziti_ctrl.c:487 verify_api_session() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] no API session
2023-11-13T09:37:14.953Z     WARN ziti-sdk:bind.c:212 session_cb() server[0.0] failed to get session for service[classifier-service]: -14/UNAUTHORIZED
2023-11-13T09:37:19.735Z     INFO ziti-sdk:ziti.c:913 ziti_re_auth_with_cb() ztx[0] starting to re-auth with ctlr[https://db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io:443] api_session_status[0] api_session_expired[TRUE]
2023-11-13T09:37:20.575Z    ERROR ziti-sdk:channel.c:675 ch_connect_timeout() ch[1] connect timeout
2023-11-13T09:37:20.575Z     INFO ziti-sdk:channel.c:733 reconnect_channel() ch[1] reconnecting in 56131ms (attempt = 4)
2023-11-13T09:37:20.575Z    ERROR ziti-sdk:channel.c:861 on_channel_connect_internal() ch[1] failed to connect to ER[AWS Public Router] [-125/operation canceled]
2023-11-13T09:37:20.575Z     INFO ziti-sdk:channel.c:733 reconnect_channel() ch[1] reconnecting in 141854ms (attempt = 5)
2023-11-13T09:37:20.907Z     WARN ziti-sdk:ziti_ctrl.c:487 verify_api_session() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] no API session
2023-11-13T09:37:20.907Z     WARN ziti-sdk:bind.c:212 session_cb() server[0.0] failed to get session for service[classifier-service]: -14/UNAUTHORIZED
2023-11-13T09:37:34.796Z    ERROR ziti-sdk:ziti_ctrl.c:162 ctrl_resp_cb() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] request failed: -110(connection timed out)
2023-11-13T09:37:34.796Z     WARN ziti-sdk:ziti.c:1597 api_session_cb() ztx[0] failed to get api session from ctrl[https://db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io:443] api_session_state[1] CONTROLLER_UNAVAILABLE[-16] connection timed out
2023-11-13T09:37:35.136Z     WARN ziti-sdk:ziti_ctrl.c:487 verify_api_session() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] no API session
2023-11-13T09:37:35.136Z     WARN ziti-sdk:bind.c:212 session_cb() server[0.0] failed to get session for service[classifier-service]: -14/UNAUTHORIZED
2023-11-13T09:37:39.819Z     INFO ziti-sdk:ziti.c:913 ziti_re_auth_with_cb() ztx[0] starting to re-auth with ctlr[https://db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io:443] api_session_status[0] api_session_expired[TRUE]
2023-11-13T09:37:46.749Z     WARN ziti-sdk:ziti_ctrl.c:487 verify_api_session() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] no API session
2023-11-13T09:37:46.749Z     WARN ziti-sdk:bind.c:212 session_cb() server[0.0] failed to get session for service[classifier-service]: -14/UNAUTHORIZED
2023-11-13T09:37:54.859Z    ERROR ziti-sdk:ziti_ctrl.c:162 ctrl_resp_cb() ctrl[db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io] request failed: -110(connection timed out)
2023-11-13T09:37:54.859Z     WARN ziti-sdk:ziti.c:1597 api_session_cb() ztx[0] failed to get api session from ctrl[https://db2f5d29-d062-47e1-82dc-a12738f0768e.production.netfoundry.io:443] api_session_state[1] CONTROLLER_UNAVAILABLE[-16] connection timed out

Environmental details:

• The Python app is running in a Docker container, and I did not test that the container's network was able to reach the controller before I restarted it
• The source code of the Python app is here
• The Dockerfile is here

[qrkourier]

Here's the full application log from the continuous running time frame during which the interruption of availability occurred.

classifier-times.log