Connection fail to gRPC from example python chat bot

[HeinHtet Aung]

I deploy tinode server to aws EKS and socket connection is already working . but for grpc , can't connect ,  This is error log from python chat bot

2024-10-01 06:15:43.570 out: {"hi": {"id": "137", "userAgent": "Tino-chatbot/1.2.2 (Windows/10); gRPC-python/0.22.3", "ver": "0.22.3", "lang": "EN"}}
2024-10-01 06:15:43.610 Disconnected: <_MultiThreadedRendezvous of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: INTERNAL: ipv4:2024-10-01 06:15:43.570 out: {"hi": {"id": "137", "userAgent": "Tino-chatbot/1.2.2 (Windows/10); gRPC-python/0.22.3", "ver": "0.22.3", "lang": "EN"}}
2024-10-01 06:15:43.610 Disconnected: <_MultiThreadedRendezvous of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses; last error: INTERNAL: ipv4:18.142.193.125:16060: Trying to connect an http1.x server (HTTP status 400)"
        debug_error_string = "UNKNOWN:Error received from peer  {created_time:"2024-10-01T06:15:43.5939744+00:00", grpc_status:14, grpc_message:"failed to connect to all addresses; last error: INTERNAL: ipv4:18.142.193.125:16060: Tr
ying to connect an http1.x server (HTTP status 400)"}"
:16060: Trying to connect an http1.x server (HTTP status 400)"
        debug_error_string = "UNKNOWN:Error received from peer  {created_time:"2024-10-01T06:15:43.5939744+00:00", grpc_status:14, grpc_message:"failed to connect to all addresses; last error: INTERNAL: ipv4:18.142.193.125:16060: Tr
ying to connect an http1.x server (HTTP status 400)"}"

[Gene]

This problem is likely cause by your network configuration. Is port 16060 proxied? Is there mismatch between http/https on the client and the server? What do you see in the server log?

[HeinHtet Aung]

Do I need to update some config to see log ? just now I see only a few server log 

2024/10/01 04:25:26 Database adapter: 'mongodb'; version: 113
2024/10/01 04:25:26 Database exists, version is correct.
2024/10/01 04:25:26 Sample data ignored.
2024/10/01 04:25:26 All done.

[Gene]

On Tuesday, October 1, 2024 at 12:11:51 PM UTC+3 HeinHtet Aung wrote:

Do I need to update some config to see log ? just now I see only a few server log 

2024/10/01 04:25:26 Database adapter: 'mongodb'; version: 113
2024/10/01 04:25:26 Database exists, version is correct.
2024/10/01 04:25:26 Sample data ignored.
2024/10/01 04:25:26 All done.

This is the init-db log. Please take a look at the tinode server log. This FAQ maybe of help:

https://github.com/tinode/chat/blob/master/docs/faq.md#q-where-can-i-find-server-logs-when-running-in-docker

[HeinHtet Aung]

Thanks for your help, now I can connect from postman but in python code still didn't work . When I check the log I SSL issue. 

This is my setting in chatbot .

    

    parser.add_argument('--host', default='my-domain.io', help='address of Tinode server gRPC endpoint')
    parser.add_argument('--ssl', default ='true', action='store_true', help='use SSL to connect to the server')
    parser.add_argument('--ssl-host', default='my-domain.io', help='SSL host name to use instead of default (useful for connecting to localhost)')

    parser.add_argument('--listen', default='0.0.0.0:40051', help='address to listen on for incoming Plugin API calls')
    parser.add_argument('--login-basic', help='login using basic authentication username:password')
    parser.add_argument('--login-token', help='login using token authentication')
    parser.add_argument('--login-cookie', default='.tn-cookie', help='read credentials from the provided cookie file')
    parser.add_argument('--quotes', default='quotes.txt', help='file with messages for the chatbot to use, one message per line')

I connect from postman with the same domain and it is working fine.

[HeinHtet Aung]

this is error log from python chat bot 

E0000 00:00:1727839251.148603   11284 ssl_transport_security.cc:1654] Handshake failed with fatal error SSL_ERROR_ZERO_RETURN: error:00000000:invalid library (0):OPENSSL_internal:invalid library (0)
2024-10-02 03:20:51.173 Disconnected: <_MultiThreadedRendezvous of RPC that terminated with:
status = StatusCode.UNAVAILABLE
details = "failed to connect to all addresses; last error: UNKNOWN: ipv4:xxx.xxx.xxx:443: Ssl handshake failed (TSI_PROTOCOL_FAILURE): SSL_ERROR_ZERO_RETURN: error:00000000:invalid library (0):OPENSSL_internal:invalid library (0)"
debug_error_string = "UNKNOWN:Error received from peer  {grpc_message:"failed to connect to all addresses; last error: UNKNOWN: ipv4:xxx.xxx.xxx:443: Ssl handshake failed (TSI_PROTOCOL_FAILURE): SSL_ERROR_ZERO_RETURN: error:00000000:invalid library (0):OPENSSL_internal:invalid library (0)", grpc_status:14, created_time:"2024-10-02T03:20:51.1573276+00:00"}"
>

[Gene]

It looks like the error "Ssl handshake failed (TSI_PROTOCOL_FAILURE): SSL_ERROR_ZERO_RETURN: error:00000000:invalid library (0):OPENSSL_internal:invalid library (0)" is caused by some outdated SSL library in the client code. Try updating your gRPC libraries.

[HeinHtet Aung]

I think my gRPC libraries is already updated version ,  and I am running with python 3.10

C:\TestWorkspace\TinodeChatBot>pip install --upgrade -r requirements.txt
Requirement already satisfied: grpcio in c:\python311\lib\site-packages (from -r requirements.txt (line 1)) (1.66.2)
Requirement already satisfied: tinode-grpc in c:\python311\lib\site-packages (from -r requirements.txt (line 2)) (0.22.3)
Requirement already satisfied: protobuf>=3.6.1 in c:\python311\lib\site-packages (from tinode-grpc->-r requirements.txt (line 2)) (5.28.2)

[Gene]

Nonetheless, the error "OPENSSL_internal:invalid library" is likely related to something being outdated. For example: https://github.com/grpc/grpc-java/issues/10510

It might be that client uses a TLS version not supported by the server or vice versa.

[HeinHtet Aung]

Thanks, Gene, now it is working, the issue is happening on my AWS load balancer side, I am using an outdated security policy in the listener.

[HeinHtet Aung]

After 1 minute if I don't task to chatbot, there is an event (disconnect event form tinode server), from chatbot side tries to reconnect to tinode server , this is log from chatbot:

2024-10-06 06:35:38.116 Disconnected: <_MultiThreadedRendezvous of RPC that terminated with:
status = StatusCode.INTERNAL
details = "Received RST_STREAM with error code 1"
debug_error_string = "UNKNOWN:Error received from peer ipv4: xxx.xxx.xxx.xxx:3000 {created_time:"2024-10-06T06:35:38.0992463+00:00", grpc_status:13, grpc_message:"Received RST_STREAM with error code 1"}"
>
2024-10-06 06:35:41.122 Connecting to secure server at xxx.xx..io:3000
2024-10-06 06:35:41.1232024-10-06 06:35:41.123  out: {"hi": {"id": "107", "userAgent": "Tino-chatbot/1.2.2 (Windows/10); gRPC-python/0.22.3", "ver": "0.22.3", "lang": "EN"}}
out: {"login": {"id": "108", "scheme": "basic", "secret": "VXNlckE6dXNlcmExMjM="}}
2024-10-06 06:35:41.162 2024-10-06 06:35:41.162 in: {"ctrl": {"id": "107", "code": 201, "text": "created", "params": {"maxTagCount": "MTY=", "clusterSize": "MQ==", "build": "Im1vbmdvZGI6djAuMjIuMTMi", "servingAt": "Imh0dHA6Ly86NjA2MC8i", "maxSubscriberCount": "MTI4", "maxMessageSize": "MjYyMTQ0", "maxTagLength": "OTY=", "maxFileUploadSize": "ODM4ODYwOA==", "minTagLength": "Mg==", "reqCred": "bnVsbA==", "ver": "IjAuMjIi"}}}
2024-10-06 06:35:41.162 Server: "mongodb:v0.22.13" "0.22"

But when I checked the tinode server log , server side only received "hi" message 

I2024/10/06 06:37:49 grpc: session started CcB_VbPShrY 172.32.22.109:23126 2
I2024/10/06 06:37:49 grpc in: hi:{id:"111"  user_agent:"Tino-chatbot/1.2.2 (Windows/10); gRPC-python/0.22.3"  ver:"0.22.3"  lang:"EN"} CcB_VbPShrY

why the server side only received only hi message

[Gene]

I understand that you are connecting chatbot to the server through a load balancer. I would suggest to look there first.