gistfile1.txt

========== ac2: receive system message about ephemeral timer modification ==========
3.77 [events-ac1] calling hook name=ac_outgoing_message kwargs={'message': <Message outgoing sys=True 'Message de' id=10 sender=1/tmpy.vv722@testrun.org chat=10/ac2>}
3.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:225: smtp fake idle - interrupted
3.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
3.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:217: executing smtp job
3.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:886: Smtp-job #1, action SendMsgToSmtp started...
3.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:955: Smtp begin immediate try 0 of job #1, action SendMsgToSmtp
3.88 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 0 mails read from "INBOX".
3.96 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:75: Idle entering wait-on-remote state
4.02 [events-ac1] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as tmpy.vv722@testrun.org ok
4.11 [events-ac2] DC_EVENT_IMAP_CONNECTED data1=0 data2=IMAP-LOGIN as tmpy.gtp9g@testrun.org, capabilities:  THREAD=REFS URL-PARTIAL SNIPPET=FUZZY CONDSTORE LITERAL+ UIDPLUS THREAD=REFERENCES CONTEXT=SEARCH Imap4rev1 NAMESPACE LOGIN-REFERRALS LIST-EXTENDED ESEARCH SPECIAL-USE IDLE SORT I18NLEVEL=1 SORT=DISPLAY THREAD=ORDEREDSUBJECT LIST-STATUS SASL-IR BINARY CATENATE CHILDREN ENABLE UNSELECT SEARCHRES MOVE NOTIFY ESORT ID MULTIAPPEND QRESYNC WITHIN
4.40 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 0 mails read from "INBOX".
4.49 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:75: Idle entering wait-on-remote state
5.28 [events-ac1] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=1152 was smtp-sent to tmpy.gtp9g@testrun.org
5.28 [events-ac1] DC_EVENT_MSG_DELIVERED data1=10 data2=10
5.28 [events-ac1] calling hook name=ac_message_delivered kwargs={'message': <Message outgoing sys=True 'Message de' id=10 sender=1/tmpy.vv722@testrun.org chat=10/ac2>}
5.29 [events-ac1] DC_EVENT_DELETED_BLOB_FILE data1=0 data2=/tmp/pytest-of-hpk/pytest-99/test_ephemeral_timer0/livedb1-blobs/Mr.nyjfonsbgjs.ub51jaxsljj@testrun.
5.29 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:979: Finished immediate try 0 of job #1, action SendMsgToSmtp
5.29 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:936: Smtp removes job #1, action SendMsgToSmtp as it succeeded
5.29 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
5.29 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:223: smtp fake idle - started
5.80 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:87: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }
5.89 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Imap-thread
6.06 [events-ac2] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:47: Receiving message INBOX/1, seen=false...
6.06 [events-ac2] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:1346: not creating ad-hoc group: too few contacts
6.06 [events-ac2] DC_EVENT_CHAT_EPHEMERAL_TIMER_MODIFIED data1=10 data2=60
6.06 [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.
6.06 [events-ac2] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:253: received message 1 has Message-Id: Mr.NYjFONsBGjs.uB51jaxsLJJ@testrun.org
6.06 [events-ac2] DC_EVENT_INCOMING_MSG data1=10 data2=10
6.06 [events-ac2] calling hook name=ac_incoming_message kwargs={'message': <Message incoming sys=True 'Message de' id=10 sender=10/tmpy.vv722@testrun.org chat=10/ac1>}

========== ac2: send message to ac1 ==========
6.06 [events-ac2] DC_EVENT_INFO data1=0 data2=src/chat.rs:858: [autocrypt] peerstate for tmpy.vv722@testrun.org is NOPREFERENCE
6.07 [events-ac2] DC_EVENT_NEW_BLOB_FILE data1=0 data2=$BLOBDIR/Mr.vsvmpg4einj.7rtgqpw4vnw@testrun.
6.07 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:197: saving job for Smtp-thread: Job { job_id: 0, action: SendMsgToSmtp, foreign_id: 11, desired_timestamp: 1594857792, added_timestamp: 1594857792, tries: 0, param: Params { inner: {Recipients: "tmpy.vv722@testrun.org", File: "$BLOBDIR/Mr.vsvmpg4einj.7rtgqpw4vnw@testrun."} }, pending_error: None }
6.07 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1043: interrupt: smtp
6.07 [events-ac2] DC_EVENT_MSGS_CHANGED data1=10 data2=11
6.07 [events-ac2] calling hook name=ac_outgoing_message kwargs={'message': <Message outgoing sys=False 'message' id=11 sender=1/tmpy.gtp9g@testrun.org chat=10/ac1>}
6.07 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:225: smtp fake idle - interrupted
6.07 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
6.07 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:217: executing smtp job
6.07 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:886: Smtp-job #1, action SendMsgToSmtp started...
6.07 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:955: Smtp begin immediate try 0 of job #1, action SendMsgToSmtp
6.07 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 1 mails read from "INBOX".

========== ac1: waiting for message from ac2 ==========
6.16 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:722: fetch_new_messages: ignoring uid 1, last seen was 1
6.16 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 0 mails read from "INBOX".
6.25 [events-ac2] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:75: Idle entering wait-on-remote state
6.33 [events-ac2] DC_EVENT_SMTP_CONNECTED data1=0 data2=SMTP-LOGIN as tmpy.gtp9g@testrun.org ok
6.55 [events-ac2] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=2258 was smtp-sent to tmpy.vv722@testrun.org
6.55 [events-ac2] DC_EVENT_MSG_DELIVERED data1=10 data2=11
6.56 [events-ac2] calling hook name=ac_message_delivered kwargs={'message': <Message outgoing sys=False 'message' id=11 sender=1/tmpy.gtp9g@testrun.org chat=10/ac1>}
6.56 [events-ac2] DC_EVENT_DELETED_BLOB_FILE data1=0 data2=/tmp/pytest-of-hpk/pytest-99/test_ephemeral_timer0/livedb2-blobs/Mr.vsvmpg4einj.7rtgqpw4vnw@testrun.
6.56 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:979: Finished immediate try 0 of job #1, action SendMsgToSmtp
6.56 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:936: Smtp removes job #1, action SendMsgToSmtp as it succeeded
6.56 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
6.56 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:223: smtp fake idle - started
7.23 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:87: Idle has NewData ResponseData { raw: 4096, response: MailboxData(Exists(1)) }
7.32 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Imap-thread
7.50 [events-ac1] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:47: Receiving message INBOX/1, seen=false...
7.50 [events-ac1] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:1346: not creating ad-hoc group: too few contacts
7.50 [events-ac1] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:830: Message has 1 parts and is assigned to chat #Chat#10.
7.50 [events-ac1] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:253: received message 1 has Message-Id: Mr.vSvMPG4eINJ.7rtgqpW4vNw@testrun.org
7.50 [events-ac1] DC_EVENT_INCOMING_MSG data1=10 data2=11
7.50 [events-ac1] calling hook name=ac_incoming_message kwargs={'message': <Message incoming sys=False 'message' id=11 sender=10/tmpy.gtp9g@testrun.org chat=10/ac2>}
7.51 [events-ac1] DC_EVENT_INFO data1=0 data2=src/message.rs:1147: Seen message Msg#11.
7.51 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:197: saving job for Imap-thread: Job { job_id: 0, action: MarkseenMsgOnImap, foreign_id: 11, desired_timestamp: 1594857793, added_timestamp: 1594857793, tries: 0, param: Params { inner: {} }, pending_error: None }
7.51 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1034: interrupt: imap
7.51 [events-ac1] DC_EVENT_MSGS_CHANGED data1=0 data2=0

========== ac2: set ephemeral timer to 0 ==========
7.51 [events-ac2] DC_EVENT_CHAT_EPHEMERAL_TIMER_MODIFIED data1=10 data2=0
7.51 [events-ac2] DC_EVENT_INFO data1=0 data2=src/chat.rs:858: [autocrypt] peerstate for tmpy.vv722@testrun.org is NOPREFERENCE
7.51 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 1 mails read from "INBOX".
7.51 [events-ac2] DC_EVENT_NEW_BLOB_FILE data1=0 data2=$BLOBDIR/Mr.gf1t97nrgb9.3rx_afx4abt@testrun.
7.51 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:197: saving job for Smtp-thread: Job { job_id: 0, action: SendMsgToSmtp, foreign_id: 12, desired_timestamp: 1594857793, added_timestamp: 1594857793, tries: 0, param: Params { inner: {Recipients: "tmpy.vv722@testrun.org", File: "$BLOBDIR/Mr.gf1t97nrgb9.3rx_afx4abt@testrun."} }, pending_error: None }

7.52 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1043: interrupt: smtp
========== ac1: receive system message about ephemeral timer modification ==========
7.52 [events-ac2] DC_EVENT_MSGS_CHANGED data1=10 data2=12
7.52 [events-ac2] calling hook name=ac_outgoing_message kwargs={'message': <Message outgoing sys=True 'Message de' id=12 sender=1/tmpy.gtp9g@testrun.org chat=10/ac1>}
7.52 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:225: smtp fake idle - interrupted
7.52 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
7.52 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:217: executing smtp job
7.52 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:886: Smtp-job #2, action SendMsgToSmtp started...
7.52 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:955: Smtp begin immediate try 0 of job #2, action SendMsgToSmtp
7.60 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:722: fetch_new_messages: ignoring uid 1, last seen was 1
7.60 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 0 mails read from "INBOX".
7.69 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:75: Idle entering wait-on-remote state
7.69 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/idle.rs:97: Idle wait was interrupted
7.70 [events-ac2] DC_EVENT_SMTP_MESSAGE_SENT data1=0 data2=Message len=2407 was smtp-sent to tmpy.vv722@testrun.org
7.70 [events-ac2] DC_EVENT_MSG_DELIVERED data1=10 data2=12
7.70 [events-ac2] calling hook name=ac_message_delivered kwargs={'message': <Message outgoing sys=True 'Message de' id=12 sender=1/tmpy.gtp9g@testrun.org chat=10/ac1>}
7.70 [events-ac2] DC_EVENT_DELETED_BLOB_FILE data1=0 data2=/tmp/pytest-of-hpk/pytest-99/test_ephemeral_timer0/livedb2-blobs/Mr.gf1t97nrgb9.3rx_afx4abt@testrun.
7.70 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:979: Finished immediate try 0 of job #2, action SendMsgToSmtp
7.70 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:936: Smtp removes job #2, action SendMsgToSmtp as it succeeded
7.70 [events-ac2] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
7.70 [events-ac2] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:223: smtp fake idle - started
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Imap-thread
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:886: Inbox-job #2, action MarkseenMsgOnImap started...
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:955: Inbox begin immediate try 0 of job #2, action MarkseenMsgOnImap
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:1040: Marking message INBOX/1 as seen...
7.77 [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: 1594857793, added_timestamp: 1594857793, tries: 0, param: Params { inner: {MsgId: "11"} }, pending_error: None }
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1043: interrupt: smtp
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:979: Finished immediate try 0 of job #2, action MarkseenMsgOnImap
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:936: Inbox removes job #2, action MarkseenMsgOnImap as it succeeded
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Imap-thread
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:225: smtp fake idle - interrupted
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Smtp-thread
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/scheduler.rs:217: executing smtp job
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:886: Smtp-job #3, action SendMdn started...
7.77 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:955: Smtp begin immediate try 0 of job #3, action SendMdn
7.85 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:722: fetch_new_messages: ignoring uid 1, last seen was 1
7.85 [events-ac1] DC_EVENT_INFO data1=0 data2=src/imap/mod.rs:672: 0 mails read from "INBOX".
7.85 [events-ac1] DC_EVENT_WARNING data1=0 data2=src/imap/idle.rs:57: skip idle, got unsolicited response Exists(2)
7.85 [events-ac1] DC_EVENT_INFO data1=0 data2=src/job.rs:1063: loading job for Imap-thread
8.05 [events-ac1] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:47: Receiving message INBOX/2, seen=false...
8.05 [events-ac1] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:1346: not creating ad-hoc group: too few contacts
8.05 [events-ac1] DC_EVENT_CHAT_EPHEMERAL_TIMER_MODIFIED data1=10 data2=0
8.05 [events-ac1] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:830: Message has 1 parts and is assigned to chat #Chat#10.
8.05 [events-ac1] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:253: received message 2 has Message-Id: Mr.gf1T97NrgB9.3rX_AfX4aBT@testrun.org
8.05 [events-ac1] DC_EVENT_INCOMING_MSG data1=10 data2=12
PASSED