Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Less flaky bot tests #63

Merged
merged 4 commits into from
Nov 30, 2022
Merged

Less flaky bot tests #63

merged 4 commits into from
Nov 30, 2022

Conversation

missytake
Copy link
Contributor

The setup of the admin group seems to be improved a lot already by this, though I don't fully understand why. But I haven't seen it in a while that the setup phase hangs.

For the actual tests, this doesn't seem to help much. But there is a bit better logging now, which helps understanding what is wrong. I think it's that the bot thread isn't so responsive, and somehow doesn't process incoming messages very well. But no idea why that would be the case.

@missytake
Copy link
Contributor Author

missytake commented Nov 28, 2022 •
edited
Loading

Only tests/test_bot.py::TestAdminGroup::test_check_privileges seems to be failing now, it seems that no ac_incoming_message event is emitted, even though the message arrives in the bot's mailbox:

27.51 [events-bot] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:73: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(5)) }
27.52 [events] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:73: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(5)) }
27.51 [events-bot] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:73: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(5)) }
27.52 [events] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:73: INBOX: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(5)) }
27.53 [events-bot] DC_EVENT_INFO data1=0 data2=src/job.rs:350: loading job
27.54 [events] DC_EVENT_INFO data1=0 data2=src/job.rs:350: loading job
27.53 [events-bot] DC_EVENT_INFO data1=0 data2=src/job.rs:350: loading job
27.54 [events] DC_EVENT_INFO data1=0 data2=src/job.rs:350: loading job
27.55 [events-bot] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
27.57 [events] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
27.55 [events-bot] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
27.57 [events] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
27.57 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:99: Receiving message, seen=false...
27.59 [events] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:99: Receiving message, seen=false...
27.57 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:99: Receiving message, seen=false...
27.59 [events] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:99: Receiving message, seen=false...
27.58 [events-bot] DC_EVENT_INFO data1=0 data2=src/decrypt.rs:46: Detected Autocrypt-mime message
27.59 [events] DC_EVENT_INFO data1=0 data2=src/decrypt.rs:46: Detected Autocrypt-mime message
27.58 [events-bot] DC_EVENT_INFO data1=0 data2=src/decrypt.rs:46: Detected Autocrypt-mime message
27.59 [events] DC_EVENT_INFO data1=0 data2=src/decrypt.rs:46: Detected Autocrypt-mime message
27.58 [events-bot] DC_EVENT_WARNING data1=0 data2=src/mimeparser.rs:739: Ignoring nested protected headers
27.60 [events] DC_EVENT_WARNING data1=0 data2=src/mimeparser.rs:739: Ignoring nested protected headers
27.58 [events-bot] DC_EVENT_WARNING data1=0 data2=src/mimeparser.rs:739: Ignoring nested protected headers
27.60 [events] DC_EVENT_WARNING data1=0 data2=src/mimeparser.rs:739: Ignoring nested protected headers
27.58 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:121: received message has Message-Id: Mr.QjK5ngPwP6j.Slpnl-AZdBl@x.testrun.org
27.60 [events] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:121: received message has Message-Id: Mr.QjK5ngPwP6j.Slpnl-AZdBl@x.testrun.org
27.58 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:121: received message has Message-Id: Mr.QjK5ngPwP6j.Slpnl-AZdBl@x.testrun.org
27.60 [events] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:121: received message has Message-Id: Mr.QjK5ngPwP6j.Slpnl-AZdBl@x.testrun.org
27.58 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:1991: not creating ad-hoc group: too few contacts
27.60 [events] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:1991: not creating ad-hoc group: too few contacts
27.58 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:1991: not creating ad-hoc group: too few contacts
27.60 [events] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:1991: not creating ad-hoc group: too few contacts
27.58 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:1217: Message has 1 parts and is assigned to chat #Chat#11.
27.60 [events] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:1217: Message has 1 parts and is assigned to chat #Chat#11.
27.58 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:1217: Message has 1 parts and is assigned to chat #Chat#11.
27.60 [events] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:1217: Message has 1 parts and is assigned to chat #Chat#11.
27.59 [events-bot] DC_EVENT_INFO data1=0 data2=src/contact.rs:1518: Recently seen loop waiting for 0h 9m 35s or interupt
27.60 [events] DC_EVENT_INFO data1=0 data2=src/contact.rs:1518: Recently seen loop waiting for 0h 9m 35s or interupt
27.59 [events-bot] DC_EVENT_INFO data1=0 data2=src/contact.rs:1518: Recently seen loop waiting for 0h 9m 35s or interupt
27.60 [events] DC_EVENT_INFO data1=0 data2=src/contact.rs:1518: Recently seen loop waiting for 0h 9m 35s or interupt
27.59 [events-bot] DC_EVENT_MSGS_CHANGED data1=11 data2=16
27.60 [events] DC_EVENT_MSGS_CHANGED data1=11 data2=16
27.59 [events-bot] DC_EVENT_MSGS_CHANGED data1=11 data2=16
27.60 [events] DC_EVENT_MSGS_CHANGED data1=11 data2=16
27.59 [events-bot] DC_EVENT_INFO data1=0 data2=src/imap.rs:905: 1 mails read from "INBOX".
27.60 [events] DC_EVENT_INFO data1=0 data2=src/imap.rs:905: 1 mails read from "INBOX".
27.59 [events-bot] DC_EVENT_INFO data1=0 data2=src/imap.rs:905: 1 mails read from "INBOX".
27.60 [events] DC_EVENT_INFO data1=0 data2=src/imap.rs:905: 1 mails read from "INBOX".
27.59 [events-bot] DC_EVENT_INCOMING_MSG_BUNCH data1=0 data2=0
27.60 [events] DC_EVENT_INCOMING_MSG_BUNCH data1=0 data2=0
27.59 [events-bot] DC_EVENT_INCOMING_MSG_BUNCH data1=0 data2=0
27.61 [events] DC_EVENT_INCOMING_MSG_BUNCH data1=0 data2=0
27.61 [events-bot] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
27.63 [events] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
27.61 [events-bot] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
27.63 [events] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
27.61 [events-bot] DC_EVENT_INFO data1=0 data2=src/imap.rs:1717: ignoring unsolicited response Recent(5)
27.63 [events] DC_EVENT_INFO data1=0 data2=src/imap.rs:1717: ignoring unsolicited response Recent(5)
27.61 [events-bot] DC_EVENT_INFO data1=0 data2=src/imap.rs:1717: ignoring unsolicited response Recent(5)
27.63 [events] DC_EVENT_INFO data1=0 data2=src/imap.rs:1717: ignoring unsolicited response Recent(5)
27.63 [events-bot] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:58: INBOX: Idle entering wait-on-remote state
27.65 [events] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:58: INBOX: Idle entering wait-on-remote state
27.63 [events-bot] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:58: INBOX: Idle entering wait-on-remote state
27.65 [events] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:58: INBOX: Idle entering wait-on-remote state

It seems that message.is_in_fresh() returns False, and the message doesn't pass this if statement: https://github.com/deltachat/deltachat-core-rust/blob/master/python/src/deltachat/events.py#L300

@missytake missytake mentioned this pull request Nov 30, 2022
Merged
@missytake
Copy link
Contributor Author

Hm, it seems that check_privileges is also failing 1 of 10 times on master - so let's merge this for now and try to fix that failing test later.

@missytake missytake merged commit 892c613 into master Nov 30, 2022
@missytake missytake deleted the less-flaky-bot-tests branch November 30, 2022 16:44
@Hocuri
Copy link

Hocuri commented Dec 5, 2022 •
edited
Loading

So, I started investigating this as promised on IRC.

I must say, these logs are hard to read, with each line being repeated four times:

2022-12-05T19:11:47.9592712Z 8.84 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:121: received message has Message-Id: Mr.JGOXtVooqd5.pnTH5LI3ERI@x.testrun.org
2022-12-05T19:11:47.9593396Z 8.84 [events] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:121: received message has Message-Id: Mr.JGOXtVooqd5.pnTH5LI3ERI@x.testrun.org
2022-12-05T19:11:47.9594067Z 8.84 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:121: received message has Message-Id: Mr.JGOXtVooqd5.pnTH5LI3ERI@x.testrun.org
2022-12-05T19:11:47.9594738Z 8.84 [events] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:121: received message has Message-Id: Mr.JGOXtVooqd5.pnTH5LI3ERI@x.testrun.org

Anyway, from the logs at the CI of #64, it looks like the bot just doesn't answer, because after the lines

2022-12-05T19:11:47.9850320Z 22.82 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:121: received message has Message-Id: Mr.zwaYMGKf95D.y_awvdtVheb@x.testrun.org
2022-12-05T19:11:47.9853262Z 22.82 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:1991: not creating ad-hoc group: too few contacts
2022-12-05T19:11:47.9855874Z 22.82 [events-bot] DC_EVENT_INFO data1=0 data2=src/receive_imf.rs:1217: Message has 1 parts and is assigned to chat #Chat#11.
2022-12-05T19:11:47.9858491Z 22.83 [events-bot] DC_EVENT_INFO data1=0 data2=src/contact.rs:1518: Recently seen loop waiting for 0h 9m 43s or interupt
2022-12-05T19:11:47.9860722Z 22.83 [events-bot] DC_EVENT_MSGS_CHANGED data1=11 data2=16
2022-12-05T19:11:47.9862434Z 22.83 [events-bot] DC_EVENT_INFO data1=0 data2=src/imap.rs:905: 1 mails read from "INBOX".

there are no further log entries about messages being sent or received, and Mr.zwaYMGKf95D.y_awvdtVheb@x.testrun.org is the message that said /list-tokens:

2022-12-05T19:11:47.9875720Z ======== Last message was not 'Sorry, I...' but: ========
2022-12-05T19:11:47.9876078Z /list-tokens
2022-12-05T19:11:47.9876505Z Sent: 2022.12.05 19:09:52 by Me (pytest-admin-201@x.testrun.org)
2022-12-05T19:11:47.9876872Z State: Delivered, Encrypted
2022-12-05T19:11:47.9877102Z 
2022-12-05T19:11:47.9877379Z Message-ID: Mr.zwaYMGKf95D.y_awvdtVheb@x.testrun.org
2022-12-05T19:11:47.9877630Z </INBOX/;UID=6>
2022-12-05T19:11:47.9877761Z 
2022-12-05T19:11:47.9877909Z No Hop Info

It seems that message.is_in_fresh() returns False, and the message doesn't pass this if statement: https://github.com/deltachat/deltachat-core-rust/blob/master/python/src/deltachat/events.py#L300

Why do you think so?

@missytake missytake mentioned this pull request Dec 13, 2022
Merged
@missytake
Copy link
Contributor Author

Ah, it seems that a contact request doesn't create an ac_incoming_message event anymore? Because this is happening outside of an established group of course. Which event would cover that?

@Hocuri
Copy link

Hocuri commented Dec 14, 2022

If an incoming message doesn't trigger an incoming_message event, then it triggers msgs_changed.

@missytake
Copy link
Contributor Author

So I opened my debugger and looked at it:

Screenshot_2022-12-14_17-27-33

So it seems the message triggers an DC_EVENT_MSGS_CHANGED event, but no ac_incoming_message. I can't easily hook into that I think, that's a bummer and a python bindings problem, I guess.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@missytake @Hocuri