gistfile1.txt

========== ac1: receive system message about ephemeral timer modification ==========
4.29 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1043: interrupt: smtp
4.29 [events-ac2] DC_EVENT_MSGS_CHANGED data1=10 data2=12
4.29 [events-ac2] calling hook name=ac_outgoing_message kwargs={'message': <Message outgoing sys=True 'Message de' id=12 sender=1/tmpy.ncknz@testrun.org chat=10/ac1>}
4.29 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:225: smtp fake idle - interrupted
4.29 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
4.29 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:217: executing smtp job
4.29 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:886: Smtp-job #2, action SendMsgToSmtp started...
4.29 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:955: Smtp begin immediate try 0 of job #2, action SendMsgToSmtp
10.30 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:722: fetch_new_messages: ignoring uid 1, last seen was 1
10.30 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 0 mails read from "INBOX".
10.39 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:67: Idle entering wait-on-remote state
10.39 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:89: Idle wait was interrupted
4.48 [events-ac2] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=2407 was smtp-sent to tmpy.g39gh@testrun.org
4.48 [events-ac2] DC_EVENT_MSG_DELIVERED data1=10 data2=12
4.48 [events-ac2] calling hook name=ac_message_delivered kwargs={'message': <Message outgoing sys=True 'Message de' id=12 sender=1/tmpy.ncknz@testrun.org chat=10/ac1>}
4.48 [events-ac2] DC_EVENT_DELETED_BLOB_FILE data1=0 data2=/tmp/pytest-of-hpk/pytest-73/test_ephemeral_timer0/livedb2-blobs/Mr.rrv9h7k770x.a0q-qka7jtr@testrun.
4.48 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:979: Inbox finished immediate try 0 of job #2, action SendMsgToSmtp
4.48 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:936: Smtp removes job #2, action SendMsgToSmtp as it succeeded
4.48 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
4.48 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:223: smtp fake idle - started
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Imap-thread
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:886: Inbox-job #2, action MarkseenMsgOnImap started...
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:955: Inbox begin immediate try 0 of job #2, action MarkseenMsgOnImap
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1040: Marking message INBOX/1 as seen...
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:197: saving job for Smtp-thread: Job { job_id: 0, action: SendMdn, foreign_id: 10, desired_timestamp: 1594844735, added_timestamp: 1594844735, tries: 0, param: Params { inner: {MsgId: "11"} }, pending_error: None }
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1043: interrupt: smtp
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:979: Inbox finished immediate try 0 of job #2, action MarkseenMsgOnImap
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:936: Inbox removes job #2, action MarkseenMsgOnImap as it succeeded
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Imap-thread
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:225: smtp fake idle - interrupted
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:217: executing smtp job
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:886: Smtp-job #3, action SendMdn started...
10.49 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:955: Smtp begin immediate try 0 of job #3, action SendMdn
10.61 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:722: fetch_new_messages: ignoring uid 1, last seen was 1
10.61 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 0 mails read from "INBOX".
10.66 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:67: Idle entering wait-on-remote state
10.73 [events-ac1] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=951 was smtp-sent to tmpy.ncknz@testrun.org
10.73 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:979: Inbox finished immediate try 0 of job #3, action SendMdn
10.73 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:936: Smtp removes job #3, action SendMdn as it succeeded
10.73 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
10.73 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:223: smtp fake idle - started
5.51 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:79: Idle has NewData
5.61 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Imap-thread
5.82 [events-ac2] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:47: Receiving message INBOX/2, seen=false...
5.82 [events-ac2] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:1346: not creating ad-hoc group: too few contacts
5.82 [events-ac2] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:830: Message has 1 parts and is assigned to chat #Chat#10.
5.82 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:197: saving job for Imap-thread: Job { job_id: 0, action: MarkseenMsgOnImap, foreign_id: 13, desired_timestamp: 1594844736, added_timestamp: 1594844736, tries: 0, param: Params { inner: {} }, pending_error: None }
5.82 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1034: interrupt: imap
5.82 [events-ac2] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:253: received message 2 has Message-Id: Mr.e7QHFqj3Rm7.90bVXHjWfN9@testrun.org
5.82 [events-ac2] DC_EVENT_MSG_READ data1=10 data2=11
5.82 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 1 mails read from "INBOX".
5.93 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:722: fetch_new_messages: ignoring uid 2, last seen was 2
5.93 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 0 mails read from "INBOX".
6.02 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:67: Idle entering wait-on-remote state
6.02 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:89: Idle wait was interrupted
6.12 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Imap-thread
6.12 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:886: Inbox-job #3, action MarkseenMsgOnImap started...
6.12 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:955: Inbox begin immediate try 0 of job #3, action MarkseenMsgOnImap
6.12 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1040: Marking message INBOX/2 as seen...
6.12 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:979: Inbox finished immediate try 0 of job #3, action MarkseenMsgOnImap
6.12 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:936: Inbox removes job #3, action MarkseenMsgOnImap as it succeeded
6.12 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Imap-thread
6.20 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:722: fetch_new_messages: ignoring uid 2, last seen was 2
6.20 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 0 mails read from "INBOX".
6.29 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:67: Idle entering wait-on-remote state
FAILEDARCH=64 BCC_SELF=0 
BLOBDIR=/tmp/pytest-of-hpk/pytest-73/test_ephemeral_timer0/livedb1-blobs 
CONFIGURED_MVBOX_FOLDER=<unset> CONFIGURED_SENTBOX_FOLDER=<unset> 
DATABASE_DIR=/tmp/pytest-of-hpk/pytest-73/test_ephemeral_timer0/livedb1 
DATABASE_VERSION=65 DELTACHAT_CORE_VERSION=v1.40.0 DISPLAY_NAME=ac1 
E2EE_ENABLED=0 
ENTERED_ACCOUNT_SETTINGS=tmpy.g39gh@testrun.org imap:unset:***:unset:0:cert_strict smtp:unset:0:unset:0:cert_strict 0 
FINGERPRINT=2E6FA2CB23B532D728634B5864B08F61A9ED9443 FOLDERS_CONFIGURED=3 
INBOX_WATCH=1 IS_CONFIGURED=1 JOURNAL_MODE=wal LEVEL=awesome MDNS_ENABLED=1 
MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 MVBOX_WATCH=0 
NUMBER_OF_CHAT_MESSAGES=2 NUMBER_OF_CHATS=1 NUMBER_OF_CONTACTS=1 
PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=1 SELFAVATAR=<unset> SENTBOX_WATCH=0 
SQLITE_VERSION=3.31.1 UPTIME=0h 0m 41s 
USED_ACCOUNT_SETTINGS=tmpy.g39gh@testrun.org imap:tmpy.g39gh@testrun.org:***:testrun.org:993:cert_strict smtp:tmpy.g39gh@testrun.org:***:testrun.org:587:cert_strict AUTH_NORMAL 0x4IMAP_SSL 0x200SMTP_STARTTLS 0x10000 
--------- INBOX 2 messages ---------
Message 1 /tmp/pytest-of-hpk/pytest-73/test_ephemeral_timer0/IMAP/ac1/INBOX/1
Message 1 (b'\\Seen',) Message-Id: <Mr.WnYirYGneEG.pXMlfkmSrdW@testrun.org>
Message 2 /tmp/pytest-of-hpk/pytest-73/test_ephemeral_timer0/IMAP/ac1/INBOX/2
Message 2 () Message-Id: <Mr.rRv9h7k770X.a0q-QkA7JTr@testrun.org>

ARCH=64 BCC_SELF=0 
BLOBDIR=/tmp/pytest-of-hpk/pytest-73/test_ephemeral_timer0/livedb2-blobs 
CONFIGURED_MVBOX_FOLDER=<unset> CONFIGURED_SENTBOX_FOLDER=<unset> 
DATABASE_DIR=/tmp/pytest-of-hpk/pytest-73/test_ephemeral_timer0/livedb2 
DATABASE_VERSION=65 DELTACHAT_CORE_VERSION=v1.40.0 DISPLAY_NAME=ac2 
E2EE_ENABLED=0 
ENTERED_ACCOUNT_SETTINGS=tmpy.ncknz@testrun.org imap:unset:***:unset:0:cert_strict smtp:unset:0:unset:0:cert_strict 0 
FINGERPRINT=CCCB5AA9F6E1141C943165F1DB18B18CBCF70487 FOLDERS_CONFIGURED=3 
INBOX_WATCH=1 IS_CONFIGURED=1 JOURNAL_MODE=wal LEVEL=awesome MDNS_ENABLED=1 
MESSAGES_IN_CONTACT_REQUESTS=0 MVBOX_MOVE=0 MVBOX_WATCH=0 
NUMBER_OF_CHAT_MESSAGES=4 NUMBER_OF_CHATS=1 NUMBER_OF_CONTACTS=1 
PRIVATE_KEY_COUNT=1 PUBLIC_KEY_COUNT=1 SELFAVATAR=<unset> SENTBOX_WATCH=0 
SQLITE_VERSION=3.31.1 UPTIME=0h 0m 35s 
USED_ACCOUNT_SETTINGS=tmpy.ncknz@testrun.org imap:tmpy.ncknz@testrun.org:***:testrun.org:993:cert_strict smtp:tmpy.ncknz@testrun.org:***:testrun.org:587:cert_strict AUTH_NORMAL 0x4IMAP_SSL 0x200SMTP_STARTTLS 0x10000 
--------- INBOX 2 messages ---------
Message 1 /tmp/pytest-of-hpk/pytest-73/test_ephemeral_timer0/IMAP/ac2/INBOX/1
Message 1 () Message-Id: <Mr.YU7vsTvi-Gn.zDdr6jrL5u2@testrun.org>
Message 2 /tmp/pytest-of-hpk/pytest-73/test_ephemeral_timer0/IMAP/ac2/INBOX/2
Message 2 (b'\\Seen',) Message-Id: <Mr.e7QHFqj3Rm7.90bVXHjWfN9@testrun.org>


35.24 [MAIN-ac2] stop_ongoing
35.24 [MAIN-ac2] dc_stop_io (stop core IO scheduler)
35.24 [events-ac2] DC_EVENT_INFO data1=0 data2=src/context.rs:246: No ongoing process to stop.
35.24 [events-ac2] DC_EVENT_INFO data1=0 data2=src/context.rs:163: stopping IO
35.24 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:97: shutting down inbox loop
35.24 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:234: shutting down smtp loop
35.24 [MAIN-ac2] remove dc_context references
35.24 [MAIN-ac2] wait for event thread to finish
40.24 [MAIN-ac2] WARN: event thread did not terminate
40.48 [MAIN-ac2] shutdown finished
46.41 [MAIN-ac1] stop_ongoing
46.41 [MAIN-ac1] dc_stop_io (stop core IO scheduler)
46.41 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:246: No ongoing process to stop.
46.41 [events-ac1] DC_EVENT_INFO data1=0 data2=src/context.rs:163: stopping IO
46.41 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:97: shutting down inbox loop
46.41 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:234: shutting down smtp loop
46.42 [MAIN-ac1] remove dc_context references
46.42 [MAIN-ac1] wait for event thread to finish
51.42 [MAIN-ac1] WARN: event thread did not terminate
51.50 [MAIN-ac1] shutdown finished


============================================= FAILURES =============================================
______________________________ TestOnlineAccount.test_ephemeral_timer ______________________________

self = <test_account.TestOnlineAccount object at 0x7f410af30510>
acfactory = <deltachat.testplugin.acfactory.<locals>.AccountMaker object at 0x7f410af30790>
lp = <deltachat.testplugin.lp.<locals>.Printer object at 0x7f410b732450>

    def test_ephemeral_timer(self, acfactory, lp):
        ac1, ac2 = acfactory.get_two_online_accounts()
        ac1.set_config("e2ee_enabled", "0")
        ac2.set_config("e2ee_enabled", "0")
    
        lp.sec("ac1: create chat with ac2")
        chat1 = ac1.create_chat(ac2)
        chat2 = ac2.create_chat(ac1)
    
        lp.sec("ac1: set ephemeral timer to 60")
        chat1.set_ephemeral_timer(60)
    
        lp.sec("ac1: check that ephemeral timer is set for chat")
        assert chat1.get_ephemeral_timer() == 60
        chat1_summary = chat1.get_summary()
        assert chat1_summary["ephemeral_timer"] == {'Enabled': {'duration': 60}}
    
        lp.sec("ac2: receive system message about ephemeral timer modification")
        ac2._evtracker.get_matching("DC_EVENT_CHAT_EPHEMERAL_TIMER_MODIFIED")
        system_message1 = ac2._evtracker.wait_next_incoming_message()
        assert chat2.get_ephemeral_timer() == 60
        assert system_message1.is_system_message()
    
        # Disabled until markers are implemented
        # assert "Ephemeral timer: 60\n" in system_message1.get_message_info()
    
        lp.sec("ac2: send message to ac1")
        sent_message = chat2.send_text("message")
        assert sent_message.ephemeral_timer == 60
        assert "Ephemeral timer: 60\n" in sent_message.get_message_info()
    
        # Timer is started immediately for sent messages
        assert sent_message.ephemeral_timestamp is not None
        assert "Expires: " in sent_message.get_message_info()
    
        lp.sec("ac1: waiting for message from ac2")
        text_message = ac1._evtracker.wait_next_incoming_message()
        assert text_message.text == "message"
        assert text_message.ephemeral_timer == 60
        assert "Ephemeral timer: 60\n" in text_message.get_message_info()
    
        # Timer should not start until message is displayed
        assert text_message.ephemeral_timestamp is None
        assert "Expires: " not in text_message.get_message_info()
        text_message.mark_seen()
        text_message = ac1.get_message_by_id(text_message.id)
        assert text_message.ephemeral_timestamp is not None
        assert "Expires: " in text_message.get_message_info()
    
        lp.sec("ac2: set ephemeral timer to 0")
        chat2.set_ephemeral_timer(0)
    
        lp.sec("ac1: receive system message about ephemeral timer modification")
>       ac1._evtracker.get_matching("DC_EVENT_CHAT_EPHEMERAL_TIMER_MODIFIED")

tests/test_account.py:1629: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
src/deltachat/events.py:85: in get_matching
    for ev in self.iter_events(timeout=timeout, check_error=check_error):
src/deltachat/events.py:81: in iter_events
    yield self.get(timeout=timeout, check_error=check_error)
src/deltachat/events.py:74: in get
    ev = self._event_queue.get(timeout=timeout)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <queue.Queue object at 0x7f410b7b0550>, block = True, timeout = 30

    def get(self, block=True, timeout=None):
        '''Remove and return an item from the queue.
    
        If optional args 'block' is true and 'timeout' is None (the default),
        block if necessary until an item is available. If 'timeout' is
        a non-negative number, it blocks at most 'timeout' seconds and raises
        the Empty exception if no item was available within that time.
        Otherwise ('block' is false), return an item if one is immediately
        available, else raise the Empty exception ('timeout' is ignored
        in that case).
        '''
        with self.not_empty:
            if not block:
                if not self._qsize():
                    raise Empty
            elif timeout is None:
                while not self._qsize():
                    self.not_empty.wait()
            elif timeout < 0:
                raise ValueError("'timeout' must be a non-negative number")
            else:
                endtime = time() + timeout
                while not self._qsize():
                    remaining = endtime - time()
                    if remaining <= 0.0:
>                       raise Empty
E                       _queue.Empty

/usr/lib/python3.7/queue.py:178: Empty
===================================== short test summary info ======================================
FAILED tests/test_account.py::TestOnlineAccount::test_ephemeral_timer - _queue.Empty
================================ 1 failed, 86 deselected in 53.00s =================================