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

contact::tests::test_was_seen_recently is flaky #5440

Closed
link2xt opened this issue Apr 7, 2024 · 4 comments
Closed

contact::tests::test_was_seen_recently is flaky #5440

link2xt opened this issue Apr 7, 2024 · 4 comments

Comments

@link2xt
Copy link
Collaborator

link2xt commented Apr 7, 2024

Log of failure from CI:

2024-04-07T09:40:29.4270628Z failures:
2024-04-07T09:40:29.4270829Z 
2024-04-07T09:40:29.4271643Z ---- contact::tests::test_was_seen_recently stdout ----
2024-04-07T09:40:29.4272740Z thread 'contact::tests::test_was_seen_recently' panicked at src/contact.rs:2823:9:
2024-04-07T09:40:29.4273614Z assertion failed: contact.was_seen_recently()
2024-04-07T09:40:29.4274498Z stack backtrace:
2024-04-07T09:40:29.4274908Z    0: rust_begin_unwind
2024-04-07T09:40:29.4275740Z              at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/std/src/panicking.rs:647:5
2024-04-07T09:40:29.4276660Z    1: core::panicking::panic_fmt
2024-04-07T09:40:29.4277522Z              at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/panicking.rs:72:14
2024-04-07T09:40:29.4278429Z    2: core::panicking::panic
2024-04-07T09:40:29.4279272Z              at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/panicking.rs:144:5
2024-04-07T09:40:29.4280383Z    3: deltachat::contact::tests::test_was_seen_recently::{{closure}}
2024-04-07T09:40:29.4281137Z              at ./src/contact.rs:2823:9
2024-04-07T09:40:29.4281874Z    4: <core::pin::Pin<P> as core::future::future::Future>::poll
2024-04-07T09:40:29.4282993Z              at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/future/future.rs:124:9
2024-04-07T09:40:29.4284149Z    5: tokio::runtime::park::CachedParkThread::block_on::{{closure}}
2024-04-07T09:40:29.4285625Z              at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/park.rs:281:63
2024-04-07T09:40:29.4286765Z    6: tokio::runtime::coop::with_budget
2024-04-07T09:40:29.4288019Z              at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/coop.rs:107:5
2024-04-07T09:40:29.4289217Z    7: tokio::runtime::coop::budget
2024-04-07T09:40:29.4290702Z              at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/coop.rs:73:5
2024-04-07T09:40:29.4291973Z    8: tokio::runtime::park::CachedParkThread::block_on
2024-04-07T09:40:29.4293383Z              at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/park.rs:281:31
2024-04-07T09:40:29.4294967Z    9: tokio::runtime::context::blocking::BlockingRegionGuard::block_on
2024-04-07T09:40:29.4296864Z              at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context/blocking.rs:66:9
2024-04-07T09:40:29.4298604Z   10: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::{{closure}}
2024-04-07T09:40:29.4300366Z              at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/multi_thread/mod.rs:87:13
2024-04-07T09:40:29.4302058Z   11: tokio::runtime::context::runtime::enter_runtime
2024-04-07T09:40:29.4303667Z              at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/context/runtime.rs:65:16
2024-04-07T09:40:29.4305044Z   12: tokio::runtime::scheduler::multi_thread::MultiThread::block_on
2024-04-07T09:40:29.4306797Z              at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/scheduler/multi_thread/mod.rs:86:9
2024-04-07T09:40:29.4308266Z   13: tokio::runtime::runtime::Runtime::block_on
2024-04-07T09:40:29.4309651Z              at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.37.0/src/runtime/runtime.rs:351:45
2024-04-07T09:40:29.4310962Z   14: deltachat::contact::tests::test_was_seen_recently
2024-04-07T09:40:29.4311828Z              at ./src/contact.rs:2828:9
2024-04-07T09:40:29.4312618Z   15: deltachat::contact::tests::test_was_seen_recently::{{closure}}
2024-04-07T09:40:29.4313522Z              at ./src/contact.rs:2808:42
2024-04-07T09:40:29.4314338Z   16: core::ops::function::FnOnce::call_once
2024-04-07T09:40:29.4315461Z              at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/ops/function.rs:250:5
2024-04-07T09:40:29.4316675Z   17: core::ops::function::FnOnce::call_once
2024-04-07T09:40:29.4317762Z              at /rustc/7cf61ebde7b22796c69757901dd346d0fe70bd97/library/core/src/ops/function.rs:250:5
2024-04-07T09:40:29.4319128Z note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
2024-04-07T09:40:29.4320101Z 
2024-04-07T09:40:29.4320420Z ========== Chats of bob: ==========
2024-04-07T09:40:29.4321213Z Single#Chat#10: alice@example.org [alice@example.org] 
2024-04-07T09:40:29.4322191Z --------------------------------------------------------------------------------
2024-04-07T09:40:29.4323052Z Msg#10:  (Contact#Contact#10): moin [FRESH]
2024-04-07T09:40:29.4323941Z --------------------------------------------------------------------------------
2024-04-07T09:40:29.4324551Z 
2024-04-07T09:40:29.4324558Z 
2024-04-07T09:40:29.4324777Z ========== Chats of alice: ==========
2024-04-07T09:40:29.4325668Z Single#Chat#10: bob@example.net [bob@example.net] 
2024-04-07T09:40:29.4326660Z --------------------------------------------------------------------------------
2024-04-07T09:40:29.4327567Z Msg#10: Me (Contact#Contact#Self): moin  √
2024-04-07T09:40:29.4328583Z --------------------------------------------------------------------------------
2024-04-07T09:40:29.4329110Z 
2024-04-07T09:40:29.4329748Z alice INFO: src/sql/migrations.rs:924: Created new database; [migration] v68-v110
2024-04-07T09:40:29.4331008Z alice INFO: src/sql.rs:293: Opened database "/tmp/.tmpi9m7dh/db.sqlite".
2024-04-07T09:40:29.4332489Z bob INFO: src/sql/migrations.rs:924: Created new database; [migration] v68-v110
2024-04-07T09:40:29.4333655Z bob INFO: src/sql.rs:293: Opened database "/tmp/.tmpA4qpTs/db.sqlite".
2024-04-07T09:40:29.4334880Z alice INFO: src/contact.rs:794: Added contact id=10 addr=bob@example.net.
2024-04-07T09:40:29.4336382Z alice WARN: �[33msrc/test_utils.rs:589: Contact bob@example.net created by TestContext�[0m
2024-04-07T09:40:29.4337727Z alice �[32mReceived MSGS_CHANGED(chat_id=Chat#Special0, msg_id=Msg#0)�[0m
2024-04-07T09:40:29.4339131Z alice INFO: src/e2ee.rs:77: Peerstate for "bob@example.net" missing, cannot encrypt.
2024-04-07T09:40:29.4340390Z alice �[32mReceived MSGS_CHANGED(chat_id=Chat#10, msg_id=Msg#10)�[0m
2024-04-07T09:40:29.4341655Z bob INFO: src/contact.rs:794: Added contact id=10 addr=alice@example.org.
2024-04-07T09:40:29.4343389Z bob WARN: �[33msrc/test_utils.rs:589: Contact alice@example.org created by TestContext�[0m
2024-04-07T09:40:29.4344780Z bob �[32mReceived MSGS_CHANGED(chat_id=Chat#Special0, msg_id=Msg#0)�[0m
2024-04-07T09:40:29.4346334Z bob INFO: src/receive_imf.rs:220: Receiving message "Mr.WavB9s-6FRc.BZ3CLmvYVOx@localhost", seen=false...
2024-04-07T09:40:29.4347905Z bob INFO: src/receive_imf.rs:1561: Message has 1 parts and is assigned to chat #Chat#10.
2024-04-07T09:40:29.4349239Z bob �[32mReceived CONTACTS_CHANGED(contact=Some(ContactId(10)))�[0m
2024-04-07T09:40:29.4350589Z bob Received Event { id: 2045145201, typ: IncomingMsg { chat_id: ChatId(10), msg_id: MsgId(10) } }
2024-04-07T09:40:29.4351604Z 
2024-04-07T09:40:29.4351610Z 
2024-04-07T09:40:29.4351804Z failures:
2024-04-07T09:40:29.4352400Z     contact::tests::test_was_seen_recently
2024-04-07T09:40:29.4352870Z 
2024-04-07T09:40:29.4353661Z test result: FAILED. 767 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out; finished in 33.54s
2024-04-07T09:40:29.4354519Z 
2024-04-07T09:40:29.4477763Z error: test failed, to rerun pass `-p deltachat --lib`
@link2xt
Copy link
Collaborator Author

link2xt commented Apr 7, 2024 •
edited
Loading

This is before #5436 is merged

@iequidoo iequidoo self-assigned this Apr 7, 2024
@iequidoo
Copy link
Collaborator

iequidoo commented Apr 8, 2024

#5436 is only about ContactsChanged/"recently seen" events, so it doesn't help and that's expected: https://github.com/deltachat/deltachat-core-rust/actions/runs/8592517467/job/23542635400

@Hocuri
Copy link
Collaborator

Hocuri commented Apr 8, 2024

I can reliably reproduce this on my computer with while cargo test test_was_seen_recently; do echo; done (@iequidoo if this helps - in case it doesn't happen on your computer, I can git bisect it)

iequidoo added a commit that referenced this issue Apr 9, 2024
@iequidoo
test: Protect from time jumps in the tests (#5440)
84392ea 
For now only in `test_was_seen_recently()`, looks like it's the only one failing because of system
time jumps caused by `SystemTime::shift()` called from other tests in parallel. Add
`SystemTimeTools::lock()` for this so that tests calling `SystemTime::shift()` wait for critical
sections in parallel running tests to be done.
@iequidoo iequidoo mentioned this issue Apr 9, 2024
Closed
iequidoo added a commit that referenced this issue Apr 10, 2024
@iequidoo
test: Protect from time jumps in the tests (#5440)
8b36603 
For now only in `test_was_seen_recently()`, looks like it's the only one failing because of system
time jumps caused by `SystemTime::shift()` called from other tests in parallel. Add
`SystemTimeTools::lock()` for this so that tests calling `SystemTime::shift()` wait for critical
sections in parallel running tests to be done.
iequidoo added a commit that referenced this issue Apr 10, 2024
@iequidoo
test: Protect from time jumps in the tests (#5440)
c66cd93 
For now only in `test_was_seen_recently()`, looks like it's the only one failing because of system
time jumps caused by `SystemTime::shift()` called from other tests in parallel. Add
`SystemTimeTools::lock()` for this so that tests calling `SystemTime::shift()` wait for critical
sections in parallel running tests to be done.
@link2xt
Copy link
Collaborator Author

link2xt commented Apr 10, 2024 •
edited
Loading

In CI this is fixed (worked around) by #5457
nextest runs each test in a separate process, so tests don't interfere with each other and don't shift time.

@iequidoo iequidoo removed their assignment Apr 11, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Hocuri @link2xt @iequidoo