search

tg-rs / carapax

A Telegram Bot API framework
MIT License
115 stars 12 forks source link

Error: "from" field is missing #37

Closed andywwright closed 4 years ago

andywwright commented 5 years ago

Hey guys!

Sometimes, like once per a few days, I would receive this error

[2019-07-17T07:52:47Z ERROR tgbot::handler::poll] An error has occurred while getting updates: Error("\"from\" field is missing", line: 3, column: 293)

I haven't experienced it myself, but they say the bot went unresponsive for a few minutes because of that.

Would you kindly point me in the right direction as to how to determine the reason for this error?

rossnomann commented 5 years ago

Hi! What is version of tgbot are you using?

rossnomann commented 5 years ago

Anyway, you need to figure out, what kind of update brokes a bot. Looks like there is an issue in message deserializer https://github.com/tg-rs/tg-rs/blob/master/tgbot/src/types/message/mod.rs#L153...L163

rossnomann commented 5 years ago

There might be a problem with forwarded messages also. Fixed in 11086d9a6e64307b63eaab8a2efbf25b8e8c9e06

andywwright commented 5 years ago

oh, sorry, I forgot to mention, it's tgbot 0.4.2

thanks for the prompt reply, I'll try to log the message that causes the error.

andywwright commented 5 years ago

btw, I think it would be great to log messages that cause errors by default, that way we would have an answer to my question already

andywwright commented 5 years ago

It isn't the error itself that bothers me, but the way tgbot tries to handle it. I have no time now to read the source code, but judging from logs it tries to receive this update exactly 30 times, which takes about 3 minutes in my case and it is completely unresponsive during that time

[2019-07-12T12:18:35Z ERROR tgbot::handler::poll] [2019-07-12T12:18:40Z ERROR tgbot::handler::poll] [2019-07-12T12:18:45Z ERROR tgbot::handler::poll] [2019-07-12T12:18:50Z ERROR tgbot::handler::poll] [2019-07-12T12:18:55Z ERROR tgbot::handler::poll] [2019-07-12T12:19:00Z ERROR tgbot::handler::poll] [2019-07-12T12:19:05Z ERROR tgbot::handler::poll] [2019-07-12T12:19:10Z ERROR tgbot::handler::poll] [2019-07-12T12:19:15Z ERROR tgbot::handler::poll] [2019-07-12T12:19:21Z ERROR tgbot::handler::poll] [2019-07-12T12:19:26Z ERROR tgbot::handler::poll] [2019-07-12T12:19:31Z ERROR tgbot::handler::poll] [2019-07-12T12:19:36Z ERROR tgbot::handler::poll] [2019-07-12T12:19:41Z ERROR tgbot::handler::poll] [2019-07-12T12:19:46Z ERROR tgbot::handler::poll] [2019-07-12T12:19:51Z ERROR tgbot::handler::poll] [2019-07-12T12:19:56Z ERROR tgbot::handler::poll] [2019-07-12T12:20:01Z ERROR tgbot::handler::poll] [2019-07-12T12:20:06Z ERROR tgbot::handler::poll] [2019-07-12T12:20:11Z ERROR tgbot::handler::poll] [2019-07-12T12:20:16Z ERROR tgbot::handler::poll] [2019-07-12T12:20:21Z ERROR tgbot::handler::poll] [2019-07-12T12:20:26Z ERROR tgbot::handler::poll] [2019-07-12T12:20:31Z ERROR tgbot::handler::poll] [2019-07-12T12:20:36Z ERROR tgbot::handler::poll] [2019-07-12T12:20:41Z ERROR tgbot::handler::poll] [2019-07-12T12:20:46Z ERROR tgbot::handler::poll] [2019-07-12T12:20:51Z ERROR tgbot::handler::poll] [2019-07-12T12:20:56Z ERROR tgbot::handler::poll] [2019-07-12T12:21:01Z ERROR tgbot::handler::poll] [2019-07-17T07:52:47Z ERROR tgbot::handler::poll] [2019-07-17T07:52:52Z ERROR tgbot::handler::poll] [2019-07-17T07:52:57Z ERROR tgbot::handler::poll] [2019-07-17T07:53:02Z ERROR tgbot::handler::poll] [2019-07-17T07:53:07Z ERROR tgbot::handler::poll] [2019-07-17T07:53:12Z ERROR tgbot::handler::poll] [2019-07-17T07:53:17Z ERROR tgbot::handler::poll] [2019-07-17T07:53:22Z ERROR tgbot::handler::poll] [2019-07-17T07:53:27Z ERROR tgbot::handler::poll] [2019-07-17T07:53:32Z ERROR tgbot::handler::poll] [2019-07-17T07:53:37Z ERROR tgbot::handler::poll] [2019-07-17T07:53:42Z ERROR tgbot::handler::poll] [2019-07-17T07:53:47Z ERROR tgbot::handler::poll] [2019-07-17T07:53:52Z ERROR tgbot::handler::poll] [2019-07-17T07:53:57Z ERROR tgbot::handler::poll] [2019-07-17T07:54:02Z ERROR tgbot::handler::poll] [2019-07-17T07:54:07Z ERROR tgbot::handler::poll] [2019-07-17T07:54:13Z ERROR tgbot::handler::poll] [2019-07-17T07:54:18Z ERROR tgbot::handler::poll] [2019-07-17T07:54:23Z ERROR tgbot::handler::poll] [2019-07-17T07:54:28Z ERROR tgbot::handler::poll] [2019-07-17T07:54:33Z ERROR tgbot::handler::poll] [2019-07-17T07:54:38Z ERROR tgbot::handler::poll] [2019-07-17T07:54:43Z ERROR tgbot::handler::poll] [2019-07-17T07:54:48Z ERROR tgbot::handler::poll] [2019-07-17T07:54:53Z ERROR tgbot::handler::poll] [2019-07-17T07:54:58Z ERROR tgbot::handler::poll] [2019-07-17T07:55:03Z ERROR tgbot::handler::poll] [2019-07-17T07:55:08Z ERROR tgbot::handler::poll] [2019-07-17T07:55:13Z ERROR tgbot::handler::poll]

if that is intended behavior, you might want to reconsider it for let's say just three attempts, rather than thirty

if it is not and thirty attempts come from the telegram side than I think something should be done to avoid such 3-minute blackouts in the future anyway

rossnomann commented 5 years ago

It's a long polling. Bot won't work without it (until you switch to webhook). When an error has occurred while getting updates, it is just ignored and written to log. If a server respond with an error, then bot will (asynchronously) wait for while (timeout got from server response or 5 seconds)

Could you please change log level to debug and restart a bot? RUST_LOG=debug

As for the "from field" error, I have some thoughts and will try to give an answer in the near future.

rossnomann commented 5 years ago

Hmm, no. I have no idea why update couldn't be parsed. Let's see a full debug logs.

andywwright commented 5 years ago

If a server respond with an error, then bot will (asynchronously) wait for while (timeout got from server response or 5 seconds)

hmm.. pauses between the errors in my log are exactly 5 sec, so it probably means that the server was replying with some kind of error, that tgbot did not understand and wait for another 5 sec.

anyway, I've updated to the last version already, so hopefully, it would not happen again. can not afford the debug level because it is too talkative and I use my log for visual monitoring.

if it happens again, I would have to fork your repo and make "logging all in case of error" thing. then I will share the bastard if I catch any.

thanks for always replying very fast. cheers :)

andywwright commented 5 years ago

no, with 0.4.3 is the same

[2019-07-23T08:49:41Z ERROR tgbot::handler::poll] An error has occurred while getting updates: Error("\"from\" field is missing", line: 3, column: 293)

happening once or twice per week with no apparent reason

rossnomann commented 5 years ago

I can add info about update to error message later. Then you need to install tgbot from master. I'll let you know when to update. Or you can do it yourself =)

andywwright commented 5 years ago

I can add info about update to error message later

that would be most kind of you and I think it needs to be done anyway, for the further errors. We're moving our home, so I'm on the wheels, can't contribute at the moment, unfortunately.

rossnomann commented 5 years ago

@andywswan You can update tgbot:

tgbot = { git = 'https://github.com/tg-rs/tg-rs', rev = 'e2dc4c87ee6831bd45f09ee3672bb15cb254274d' }
rossnomann commented 5 years ago

I've just released 0.4.4 with Bot API 4.4 support and improved error message in long polling.

andywwright commented 5 years ago

haven't had a possibility to update to 4.4 yet, but so far the error looks like that:

tb_1 | [2019-07-31T21:24:04Z ERROR tgbot::handler::poll] An error has occurred while getting updates: Can not parse response: "from" field is missing at line 3 column 312 (data={"ok":true,"result":[{"update_id":560506329, tb_1 | [2019-07-31T21:24:09Z ERROR tgbot::handler::poll] An error has occurred while getting updates: Can not parse response: "from" field is missing at line 3 column 312 (data={"ok":true,"result":[{"update_id":560506329, tb_1 | [2019-07-31T21:24:14Z ERROR tgbot::handler::poll] An error has occurred while getting updates: Can not parse response: "from" field is missing at line 3 column 312 (data={"ok":true,"result":[{"update_id":560506329,

rossnomann commented 5 years ago

Could you provide a full line of error message?

andywwright commented 5 years ago

this IS the full line

rossnomann commented 5 years ago

If this is the full line, JSON is invalid and could not be parsed at all.

rossnomann commented 5 years ago

Can you dump all bot logs to a file and upload it to pastebin?

andywwright commented 5 years ago

sorry, I've just restarted the docker container because of the update to 4.4. let's see what the new version would report. also, I'll try to find what could cut logs string length along the way (docker, terminal, etc.)

andywwright commented 5 years ago

still getting the same errors once in a while. dug into a docker log file to check if I could find the full error message there. found that the message is the same as I've shared above, just in json:

{"log":"[2019-08-16T09:15:22Z ERROR tgbot::handler::poll] An error has occurred while getting updates: Can not parse response: \"from\" field is missing at line 3 column 293 (data={\"ok\":true,\"result\":[{\"update_id\":560512174,\n","stream":"stderr","time":"2019-08-16T09:15:22.735840277Z"}

i.e. no information after "update_id", looks cut or incomplete.

so I've cloned your repo and have added these two strings 

    let txt = (1..=500).map(|x| x.to_string()).collect::<String>();
    error!("Log lenght test: {}", txt);

into fn make_request(args...) in poll.rs just to check if I'd see the full-length log in my production docker setup. and sure enough I've got this:

tb_1 | [2019-08-19T09:26:02Z ERROR tgbot::handler::poll] Log length test: 123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500

conclusions: logs have never been cut in the first place, the error details are incomplete or indeed the telegram server sometimes sends a broken update.

now I'm stuck and have no idea as to how to proceed with this issue.

rossnomann commented 5 years ago

Looks like it's a problem in docker: https://github.com/moby/moby/issues/22920#issuecomment-221247713

rossnomann commented 5 years ago

Also sorry for delay, I'm on vacation and don't have enough time

rossnomann commented 4 years ago

@andywswan are there any updates on this?

andywwright commented 4 years ago

first of all - you were right, there is no way to send "\n" through docker's JSON log driver, that's why we have never seen a full error message here. I've tried to replace('\n', "\r") in err, but by some coincidence or the God's will the error itself has disappeared and I have had no chance to see it in full.