search

Lonami / grammers

(tele)gramme.rs - use Telegram's API from Rust
https://t.me/gramme_rs
Apache License 2.0
554 stars 113 forks source link

Sending fails after some time #237

Closed linuseing closed 3 weeks ago

linuseing commented 5 months ago

Hey,

I have two instances running, one "user" client and one bot client. The user client seems to work just fine, but the bot kinda stops sending messages after some time. Sending doesn't fail but the call just never returns. Since I have no Idea what happens here, did anyone encounter this issue before?

Thanks in advance and thanks for the otherwise great library!

Jonarod commented 4 months ago

After some headaches trying to pinpoint some bug in my app, I came to the same conclusion. Sending or editing messages through grammers_client::client::client::Client.edit_message() for example, works for "some time" and then all of a sudden the call never returns, not even an Error, it just hangs here forever.

I unfortunately cannot reproduce exactly when it decides to just stop returning, sometimes my app can live fine for 1 hour then get stuck, and last week it lasted 2 days before freezing... but at some point, grammers_client::client::client::Client.send_message() or grammers_client::client::client::Client.edit_message() is called and never returns.

Lonami commented 4 months ago

Do logs show a disconnection after the call?

Jonarod commented 4 months ago

Wouldn't Result return an Error if we try to Client.send_message() with a disconnected client?

Unfortunately I just activated TRACE logs for grammers specifically only yesterday, so I will post TRACE logs here when I see my app freeze again if that can help.

Lonami commented 4 months ago

grammers resets some of it state on disconnect so it's possible the oneshot channel is being dropped, meaning a response will never be set, appearing "stuck".

Sadly the logs may not be too great, but it's still worth trying.

Could also be a deadlock.

Jonarod commented 4 months ago

Ok so here are the logs after freeze:

[2024-06-22T13:20:03Z DEBUG my_app::forwarders::telegram_forwarder] Sending new message to Telegram
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] enqueueing request messages.sendMessage to be serialized
[2024-06-22T13:20:03Z TRACE grammers_mtsender] reading bytes and sending up to 0 bytes via network
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] enqueueing keepalive ping 1719062403520411533
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] enqueueing request ping_delay_disconnect to be serialized
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383316802750267400)
[2024-06-22T13:20:03Z TRACE grammers_mtsender] reading bytes and sending up to 164 bytes via network
[2024-06-22T13:20:03Z TRACE grammers_mtsender] reading bytes and sending up to 164 bytes via network
[2024-06-22T13:20:03Z INFO  grammers_mtsender] connecting...
[2024-06-22T13:20:03Z INFO  grammers_mtsender] retrying the call
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383316803141903584)
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] serialized request dff8042c (messages.sendMessage) with MsgId(7383316803141981144)
[2024-06-22T13:20:03Z TRACE grammers_mtsender] reading bytes and sending up to 308 bytes via network
[2024-06-22T13:20:03Z TRACE grammers_mtsender] written 308 bytes to the network (308/308)
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] sent request with MsgId(7383316803141903584)
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] sent request with MsgId(7383316803141981144)
[2024-06-22T13:20:03Z TRACE grammers_mtsender] reading bytes and sending up to 0 bytes via network
[2024-06-22T13:20:03Z INFO  grammers_mtsender] connecting...
[2024-06-22T13:20:03Z INFO  grammers_mtsender] retrying the call
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383316803932687940)
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] serialized request dff8042c (messages.sendMessage) with MsgId(7383316803932774544)
[2024-06-22T13:20:03Z TRACE grammers_mtsender] reading bytes and sending up to 308 bytes via network
[2024-06-22T13:20:03Z TRACE grammers_mtsender] written 308 bytes to the network (308/308)
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] sent request with MsgId(7383316803932687940)
[2024-06-22T13:20:03Z DEBUG grammers_mtsender] sent request with MsgId(7383316803932774544)
[2024-06-22T13:20:03Z TRACE grammers_mtsender] reading bytes and sending up to 0 bytes via network
[2024-06-22T13:20:03Z INFO  grammers_mtsender] connecting...
[2024-06-22T13:20:04Z INFO  grammers_mtsender] retrying the call
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383316805024245760)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] serialized request dff8042c (messages.sendMessage) with MsgId(7383316805024294384)
[2024-06-22T13:20:04Z TRACE grammers_mtsender] reading bytes and sending up to 308 bytes via network
[2024-06-22T13:20:04Z TRACE grammers_mtsender] written 308 bytes to the network (308/308)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] sent request with MsgId(7383316805024245760)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] sent request with MsgId(7383316805024294384)
[2024-06-22T13:20:04Z TRACE grammers_mtsender] reading bytes and sending up to 0 bytes via network
[2024-06-22T13:20:04Z INFO  grammers_mtsender] connecting...
[2024-06-22T13:20:04Z INFO  grammers_mtsender] retrying the call
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383316805813459076)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] serialized request dff8042c (messages.sendMessage) with MsgId(7383316805813538364)
[2024-06-22T13:20:04Z TRACE grammers_mtsender] reading bytes and sending up to 308 bytes via network
[2024-06-22T13:20:04Z TRACE grammers_mtsender] written 308 bytes to the network (308/308)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] sent request with MsgId(7383316805813459076)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] sent request with MsgId(7383316805813538364)
[2024-06-22T13:20:04Z TRACE grammers_mtsender] reading bytes and sending up to 0 bytes via network
[2024-06-22T13:20:04Z INFO  grammers_mtsender] connecting...
[2024-06-22T13:20:04Z INFO  grammers_mtsender] retrying the call
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383316806599093672)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] serialized request dff8042c (messages.sendMessage) with MsgId(7383316806599175852)
[2024-06-22T13:20:04Z TRACE grammers_mtsender] reading bytes and sending up to 308 bytes via network
[2024-06-22T13:20:04Z TRACE grammers_mtsender] written 308 bytes to the network (308/308)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] sent request with MsgId(7383316806599093672)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] sent request with MsgId(7383316806599175852)
[2024-06-22T13:20:04Z TRACE grammers_mtsender] reading bytes and sending up to 0 bytes via network
[2024-06-22T13:20:04Z INFO  grammers_mtsender] connecting...
[2024-06-22T13:20:04Z INFO  grammers_mtsender] retrying the call
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383316807368718048)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] serialized request dff8042c (messages.sendMessage) with MsgId(7383316807368791348)
[2024-06-22T13:20:04Z TRACE grammers_mtsender] reading bytes and sending up to 308 bytes via network
[2024-06-22T13:20:04Z TRACE grammers_mtsender] written 308 bytes to the network (308/308)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] sent request with MsgId(7383316807368718048)
[2024-06-22T13:20:04Z DEBUG grammers_mtsender] sent request with MsgId(7383316807368791348)
[2024-06-22T13:20:04Z TRACE grammers_mtsender] reading bytes and sending up to 0 bytes via network

Then it goes into some kind of loop repeating the same every second or so, while growing its serialized request f3427b8c (ping_delay_disconnect) with MsgId(xxxxx) list like this:

[2024-06-22T14:16:57Z INFO  grammers_mtsender] connecting...
[2024-06-22T14:16:57Z INFO  grammers_mtsender] retrying the call
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466792803976)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request dff8042c (messages.sendMessage) with MsgId(7383331466792880412)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466792923832)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466792964168)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466792999480)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793042440)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793082124)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793124760)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793164572)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793204768)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793242400)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793283644)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793320504)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793357688)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793399556)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793433896)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793473800)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793516648)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793560016)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793784560)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793846596)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793879760)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793909048)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793937084)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466793968424)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794000968)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794039788)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794078116)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794118568)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794155836)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794192108)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794284120)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794326668)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794363468)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794791456)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794853000)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794883456)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794912876)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794941124)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794969628)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466794997792)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795026064)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795102080)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795143540)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795193260)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795227704)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795267236)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795302176)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795338664)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795374032)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795520416)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795572240)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795609068)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795640496)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795668308)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795695320)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795722680)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466795749580)
[2024-06-22T14:16:57Z TRACE grammers_mtsender] reading bytes and sending up to 2100 bytes via network
[2024-06-22T14:16:57Z TRACE grammers_mtsender] written 2100 bytes to the network (2100/2100)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466792803976)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466792880412)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466792923832)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466792964168)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466792999480)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793042440)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793082124)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793124760)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793164572)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793204768)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793242400)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793283644)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793320504)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793357688)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793399556)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793433896)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793473800)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793516648)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793560016)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793784560)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793846596)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793879760)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793909048)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793937084)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466793968424)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794000968)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794039788)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794078116)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794118568)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794155836)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794192108)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794284120)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794326668)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794363468)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794791456)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794853000)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794883456)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794912876)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794941124)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794969628)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466794997792)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795026064)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795102080)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795143540)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795193260)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795227704)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795267236)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795302176)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795338664)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795374032)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795520416)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795572240)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795609068)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795640496)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795668308)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795695320)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795722680)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331466795749580)
[2024-06-22T14:16:57Z TRACE grammers_mtsender] reading bytes and sending up to 0 bytes via network
[2024-06-22T14:16:57Z INFO  grammers_mtsender] connecting...

This last [2024-06-22T14:16:57Z INFO grammers_mtsender] connecting... is the last ever log I received for my entire app like 2 hours ago, and it just stuck here. Nothing else happened, suggesting me some sort of deadlock happening under the hood maybe.

I really don't get why it indefinitely tries to send the message instead of just trying 2 or 3 times and return an error.

Lonami commented 4 months ago

I don't know what your code is doing, and the logs lack millisecond precision, but that second part definitely has a suspicious amount of ping_delay_disconnects in such a short while. The library should only perform these once every minute to make sure the connection is alive.

It also seems like none of the messages.sendMessage receuved a response, but I do see a lot of "connecting" in-between.

So I guess it is something with the network going down.

I really don't get why it indefinitely tries to send the message instead of just trying 2 or 3 times and return an error.

It should:

https://github.com/Lonami/grammers/blob/663f59871a1b8a2063bf051abf7642d5f3b5d58b/lib/grammers-mtsender/src/lib.rs#L316-L327

And this error should also be propagated upwards correctly; it's not just swallowed. So, hard to say why the problem occurs, but definitely seems network-related.

MaxVerevkin commented 4 months ago

It should:

I was experiencing a very similar issue, and I "solved" it by removing the retrying logic (https://github.com/MaxVerevkin/grammers/commit/602747fe8d05611cc1b8c76c58d2f511bb4a8aa3), never have happened to me again (I do not understand what the root cause of the issue is).

Lonami commented 4 months ago

cc @MrAliSalehi per your PR on #196; do you have any insight?

Jonarod commented 4 months ago

Yeah maybe a bumpy network who knows really. However my app basically listens to a remote websocket with one tokio::task using tokio_tungstenite and another tokio::task is responsible to receive some messages and relay some of them to Telegram using grammers. The websocket listener's task sends/receives ping/pong to/from the websocket server every 30 seconds, which means it can reach the internet back and forth during hours and hours. I have logs of these ping/pong WHILE the other task (where grammers sits) is just lost in its loop "trying to connect". Would be quite surprised if tungstenite can ping and receive pong to/from the outside but grammers couldn't just on every instances it tried to reconnect... Doubt it. Here is another extract from my logs that shows: sending ping to websocket, receiving confirmation pong from websocket, meanwhile grammers still tries to reconnect on the other task.

[2024-06-22T14:16:57Z INFO  grammers_mtsender] connecting...
[2024-06-22T14:16:57Z TRACE my_app::utils::websocket] 
    [SENDING]:
    ping

[2024-06-22T14:16:57Z TRACE tokio_tungstenite] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/lib.rs:243 WebSocketStream.with_context
[2024-06-22T14:16:57Z TRACE tungstenite::protocol] Sending frame: Frame { header: FrameHeader { is_final: true, rsv1: false, rsv2: false, rsv3: false, opcode: Data(Text), mask: Some([38, 157, 243, 112]) }, payload: [112, 105, 110, 103] }
[2024-06-22T14:16:57Z TRACE tungstenite::protocol::frame] writing frame 
    <FRAME>
    final: true
    reserved: false false false
    opcode: TEXT
    length: 10
    payload length: 4
    payload: 0x70696e67

[2024-06-22T14:16:57Z TRACE tokio_tungstenite] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/lib.rs:243 WebSocketStream.with_context
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:167 Write.write
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:126 AllowStd.with_context
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:169 Write.with_context write -> poll_write
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:178 Write.flush
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:126 AllowStd.with_context
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:180 Write.with_context flush -> poll_flush
[2024-06-22T14:16:57Z TRACE my_app::utils::websocket] Waiting to receive from socket_writer_channel_rx...
[2024-06-22T14:16:57Z INFO  grammers_mtsender] retrying the call
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465230743580)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request dff8042c (messages.sendMessage) with MsgId(7383331465230805752)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465230906876)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465230943640)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465230978356)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231011052)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231044624)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231077864)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231111180)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231144488)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231176300)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231209460)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231242560)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231277760)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231310724)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231344716)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231377404)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231412292)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231446496)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231481116)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231519128)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231552484)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231589444)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231623064)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231657364)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231689336)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231723140)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231756940)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231901592)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231948792)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465231983140)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232017096)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232049984)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232080260)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232114684)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232176008)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232212532)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232245564)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232278816)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232311904)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232345276)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232377140)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232411536)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232443328)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232476660)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232507964)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232540220)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232571096)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232604716)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232636296)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232671164)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232706380)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232737352)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232770296)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232802220)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232836752)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232870128)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331465232904240)
[2024-06-22T14:16:57Z TRACE grammers_mtsender] reading bytes and sending up to 2100 bytes via network
[2024-06-22T14:16:57Z TRACE grammers_mtsender] written 2100 bytes to the network (2100/2100)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465230743580)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465230805752)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465230906876)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465230943640)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465230978356)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231011052)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231044624)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231077864)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231111180)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231144488)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231176300)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231209460)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231242560)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231277760)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231310724)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231344716)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231377404)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231412292)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231446496)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231481116)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231519128)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231552484)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231589444)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231623064)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231657364)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231689336)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231723140)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231756940)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231901592)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231948792)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465231983140)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232017096)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232049984)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232080260)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232114684)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232176008)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232212532)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232245564)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232278816)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232311904)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232345276)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232377140)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232411536)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232443328)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232476660)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232507964)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232540220)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232571096)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232604716)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232636296)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232671164)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232706380)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232737352)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232770296)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232802220)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232836752)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232870128)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] sent request with MsgId(7383331465232904240)
[2024-06-22T14:16:57Z TRACE grammers_mtsender] reading bytes and sending up to 0 bytes via network
[2024-06-22T14:16:57Z INFO  grammers_mtsender] connecting...
[2024-06-22T14:16:57Z TRACE tokio_tungstenite] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/lib.rs:288 Stream.poll_next
[2024-06-22T14:16:57Z TRACE tokio_tungstenite] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/lib.rs:243 WebSocketStream.with_context
[2024-06-22T14:16:57Z TRACE tokio_tungstenite] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/lib.rs:298 Stream.with_context poll_next -> read()
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:149 Read.read
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:126 AllowStd.with_context
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:152 Read.with_context read -> poll_read
[2024-06-22T14:16:57Z TRACE tungstenite::protocol::frame::frame] Parsed headers [129, 4]
[2024-06-22T14:16:57Z TRACE tungstenite::protocol::frame::frame] First: 10000001
[2024-06-22T14:16:57Z TRACE tungstenite::protocol::frame::frame] Second: 100
[2024-06-22T14:16:57Z TRACE tungstenite::protocol::frame::frame] Opcode: Data(Text)
[2024-06-22T14:16:57Z TRACE tungstenite::protocol::frame::frame] Masked: false
[2024-06-22T14:16:57Z TRACE tungstenite::protocol::frame] received frame 
    <FRAME>
    final: true
    reserved: false false false
    opcode: TEXT
    length: 6
    payload length: 4
    payload: 0x706f6e67

[2024-06-22T14:16:57Z TRACE tungstenite::protocol] Received message pong
[2024-06-22T14:16:57Z TRACE my_app::utils::websocket] 
    [RECEIVED]:
    pong
[2024-06-22T14:16:57Z TRACE tokio_tungstenite] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/lib.rs:288 Stream.poll_next
[2024-06-22T14:16:57Z TRACE tokio_tungstenite] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/lib.rs:243 WebSocketStream.with_context
[2024-06-22T14:16:57Z TRACE tokio_tungstenite] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/lib.rs:298 Stream.with_context poll_next -> read()
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:149 Read.read
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:126 AllowStd.with_context
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] /Users/user/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-tungstenite-0.23.1/src/compat.rs:152 Read.with_context read -> poll_read
[2024-06-22T14:16:57Z TRACE tokio_tungstenite::compat] WouldBlock
[2024-06-22T14:16:57Z TRACE my_app::utils::websocket] Received health signal!
[2024-06-22T14:16:57Z TRACE my_app::utils::websocket] Waiting 30s before checking health again...
[2024-06-22T14:16:57Z INFO  grammers_mtsender] retrying the call
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466017768224)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request dff8042c (messages.sendMessage) with MsgId(7383331466017830144)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466017870040)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466017902924)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466017936668)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466017968524)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018000816)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018032132)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018064364)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018096772)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018128872)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018161300)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018192536)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018263524)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018303632)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018333960)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018364992)
[2024-06-22T14:16:57Z DEBUG grammers_mtsender] serialized request f3427b8c (ping_delay_disconnect) with MsgId(7383331466018396924)

Also, I guess this log that repeats 274 times should hint that network is okay too, no?

[2024-06-22T14:16:57Z TRACE grammers_mtsender] reading bytes and sending up to 2100 bytes via network
[2024-06-22T14:16:57Z TRACE grammers_mtsender] written 2100 bytes to the network (2100/2100)

I'd argue that somehow the retry process is kinda forking itself multiple times like if it was spawning a new thread to retry, never incrementing the attempts on the same state, hence never triggering the 5 max attempts.

What is worrying is that I expect to get passed the Client.send_message().await? and I should see its resolution as an Ok()/Err() in the log, but this never occurs. Since I use 2 separate tasks, I can see that grammers's task turns crazy by itself and nothing else is interfering with it. Also what triggers the sending of a message is just an rx channel in a loop, and I can see each iteration of this loop in the logs, then all of a sudden, the rx.recv().await correctly receives a new message to be sent, and I never see the end of the loop: the code literally blocks after Client.send_message().await? point blank. The websocket server ends up closing the connection (which is normal behaviour) and the websocket listener task finishes gracefully, but my app never quits because it's waiting for grammers's task to finish... which never happens as it is stuck in its "trying to connect" loop.

Regarding the attempts, I see in the code you shared that there should be 5 attempts before erroring, but I never see that count. I guess it would be nice to have another trace!() to track the count on each attempts, as it feels like somehow the attempts is either in a race condition never updating itself.

Lonami commented 4 months ago

Thanks for the detailed analysis; I still hope to continue looking into this a bit more, but the above commit might help.

Lonami commented 4 months ago

I've also gotten rid of some unnecessarily nested retry logic (a95a4e73b07a82bb457728e4775707974d2a74f5, which wasn't doing anything), the fact it would always retry at least once even if you didn't want it to (995302553cacacac35b091c1a6fcab1df186a81d), and if all attempts to reconnect fail, the error should correctly propagate all the way up now (c860631280772ee85cceac388b2f8f7f67586600).

Jonarod commented 4 months ago

Ok so I deployed the change with the revision c860631. Now I can see actual Result<T> being returned, which is a lot more normal now. Thanks.

However, I am still unable to send messages after some time. Except now it returns with proper error directly. Here is the error when trying to Client.send_message().await, exactly where it would be trapped in infinite loop before. 

request error: read error, IO failed: read 0 bytes

After this, I am not able to send messages anymore, it always prints the same error. Like I said before, on the other hand network is stable with proper ping/pong being delivered.

Question: is grammers well suited for long lived processes or is it better to just use it to, connect, send a few messages, and disconnect? I feel like it disconnects after some time and suddenly gets unresponsive, so should I manually reconnect or check connection periodically?

Again thank you for your time.

Jonarod commented 4 months ago

Or I was thinking, is it possible that Telegram's MT Proto API itself implements some kind of timeout to cut long lived inactive connections? If that is the case, is the reconnect logic implemented in grammers in a transparent manner or should we handle that ourselves? And wouldn't it be better to use something like tdlib instead of the mtproto api maybe?

Just some food for thoughts :)

Lonami commented 4 months ago

Question: is grammers well suited for long lived processes

Well, currently it isn't, as you can see. But, I would like for it to be, yes. The library should be able to reconnect and continue as if nothing happened (unless Telegram has an outage lasting for multiple hours, in which case I think it's fine for the library to bail, and a supervisor to take care of the situation).

is the reconnect logic implemented in grammers in a transparent manner or should we handle that ourselves?

I didn't implement it. It was added by #196. My vision for this is, there is a trait which can be implemented, which specifies how many reconnection attempts should occur and when each attempt should be made. But I personally haven't tested the reconnect feature, or even tried it really (as I don't have a use for grammers myself at the moment).

So please, by all means I encourage you to dig into the code and see if you can find what is wrong. Reproducing faulty network conditions isn't easy for me. I'm happy to help, perhaps in the gramme_rs Telegram chat for more direct communication.

wouldn't it be better to use something like tdlib instead of the mtproto api maybe?

I have never use tdlib, and prefer to keep it that way. It's an additional abstraction layer I'm not willing to learn at the moment, and I also want to know exactly what goes on underneath. Hence why grammers is built from scratch.

MrAliSalehi commented 4 months ago

is the reconnect logic implemented in grammers in a transparent manner

I had the reconnection logic in a few projects and they were all working fine, BUT, with the recent issues mentioned by users, there must a bug or a special case that we didn't handle. so basically it works, but not always, I guess your best "temporary" solution would be to drop and reconnect the client manually

Jonarod commented 3 months ago

I see. Thanks for your insights.

Just a note, after 5 days running and re-reunning my project, I have reached to the conclusion that grammers stops sending messages after 60 minutes of inactivity somehow. My app is always able to send messages during the 1st hour of an app reload (when the remote websocket asks to disconnect, my app gracefully stops and reloads itself, thus recreating the grammers connection from scratch). Past 60 minutes, it is never able to send messages and returns an error: request error: read error, IO failed: read 0 bytes until next reload.

Now I am trying to find the best way to force disconnect then reconnect the grammers client (as suggested by @MrAliSalehi), so I found: grammers_client::client::client::Client.run_until_disconnected(self) and/or grammers_client::client::client::InitParams with grammers_mtsender::FixedReconnect

Could any of these help in this situation? Does grammers_mtsender::FixedReconnect still works after the re-works in the c860631 commit ?

Or is there a better way to gracefully drop the connection without arbitrarily dropping messages being sent and without sign-out? (I understand that signing-out means revoking the saved session which I don't want to since my app is a long-running process and cannot afford to go through the signin and verification process periodically).

Lonami commented 3 months ago

Dropping the client should be enough for a graceful disconnection. There's an internal Arc, so all clones must be dropped.