add some logging, and a more precise teardown for online python tests

python/src/deltachat/account.py

@@ -23,13 +23,14 @@ class Account(object):
     by the underlying deltachat c-library.  All public Account methods are
     meant to be memory-safe and return memory-safe objects.
     """
-    def __init__(self, db_path, logid=None):
+    def __init__(self, db_path, logid=None, eventlogging=True):
         """ initialize account object.
 
         :param db_path: a path to the account database. The database
                         will be created if it doesn't exist.
         :param logid: an optional logging prefix that should be used with
                       the default internal logging.
+        :param eventlogging: if False no eventlogging and no context callback will be configured
         """
         self._dc_context = ffi.gc(
             lib.dc_context_new(lib.py_dc_callback, ffi.NULL, ffi.NULL),
@@ -39,14 +40,15 @@ class Account(object):
             db_path = db_path.encode("utf8")
         if not lib.dc_open(self._dc_context, db_path, ffi.NULL):
             raise ValueError("Could not dc_open: {}".format(db_path))
-        self._evlogger = EventLogger(self._dc_context, logid)
+        if eventlogging:
-        deltachat.set_context_callback(self._dc_context, self._process_event)
+            self._evlogger = EventLogger(self._dc_context, logid)
+            deltachat.set_context_callback(self._dc_context, self._process_event)
         self._threads = IOThreads(self._dc_context)
         self._configkeys = self.get_config("sys.config_keys").split()
         self._imex_completed = threading.Event()
 
     def __del__(self):
-        lib.dc_close(self._dc_context)
+        self.shutdown()
 
     def _check_config_key(self, name):
         if name not in self._configkeys:
@@ -336,12 +338,21 @@ class Account(object):
         lib.dc_stop_ongoing_process(self._dc_context)
         self._threads.stop(wait=wait)
 
+    def shutdown(self, wait=True):
+        """ stop threads and close and remove underlying dc_context and callbacks. """
+        if hasattr(self, "_dc_context"):
+            lib.dc_close(self._dc_context)
+            self.stop_threads(wait=wait)
+            deltachat.clear_context_callback(self._dc_context)
+            del self._dc_context
+
     def _process_event(self, ctx, evt_name, data1, data2):
         assert ctx == self._dc_context
-        self._evlogger(evt_name, data1, data2)
+        if hasattr(self, "_evlogger"):
-        method = getattr(self, "on_" + evt_name.lower(), None)
+            self._evlogger(evt_name, data1, data2)
-        if method is not None:
+            method = getattr(self, "on_" + evt_name.lower(), None)
-            method(data1, data2)
+            if method is not None:
+                method(data1, data2)
         return 0
 
     def on_dc_event_imex_progress(self, data1, data2):

python/tests/conftest.py

@@ -16,12 +16,22 @@ def pytest_addoption(parser):
     )
 
 
+@pytest.hookimpl(trylast=True)
+def pytest_runtest_call(item):
+    # perform early finalization because we otherwise get cloberred
+    # output from concurrent threads printing between execution
+    # of the test function and the teardown phase of that test function
+    if "acfactory" in item.funcargs:
+        acfactory = item.funcargs["acfactory"]
+        acfactory.finalize()
+
+
 def pytest_report_header(config, startdir):
     t = tempfile.mktemp()
     try:
-        ac = Account(t)
+        ac = Account(t, eventlogging=False)
         info = ac.get_info()
-        del ac
+        ac.shutdown()
     finally:
         os.remove(t)
     return "Deltachat core={} sqlite={}".format(
@@ -52,7 +62,6 @@ def acfactory(pytestconfig, tmpdir, request):
             self.live_count = 0
             self.offline_count = 0
             self._finalizers = []
-            request.addfinalizer(self.finalize)
             self.init_time = time.time()
 
         def finalize(self):
@@ -78,6 +87,7 @@ def acfactory(pytestconfig, tmpdir, request):
             ac = Account(tmpdb.strpath, logid="ac{}".format(self.offline_count))
             ac._evlogger.init_time = self.init_time
             ac._evlogger.set_timeout(2)
+            self._finalizers.append(ac.shutdown)
             return ac
 
         def get_configured_offline_account(self):
@@ -103,7 +113,7 @@ def acfactory(pytestconfig, tmpdir, request):
             ac._evlogger.set_timeout(30)
             ac.configure(**configdict)
             ac.start_threads()
-            self._finalizers.append(lambda: ac.stop_threads(wait=False))
+            self._finalizers.append(ac.shutdown)
             return ac
 
         def clone_online_account(self, account):
@@ -114,7 +124,7 @@ def acfactory(pytestconfig, tmpdir, request):
             ac._evlogger.set_timeout(30)
             ac.configure(addr=account.get_config("addr"), mail_pw=account.get_config("mail_pw"))
             ac.start_threads()
-            self._finalizers.append(lambda: ac.stop_threads(wait=False))
+            self._finalizers.append(ac.shutdown)
             return ac
 
     return AccountMaker()

python/tests/test_lowlevel.py

@@ -1,6 +1,6 @@
 from __future__ import print_function
 import pytest
-from deltachat import capi, Account, const, set_context_callback
+from deltachat import capi, Account, const, set_context_callback, clear_context_callback
 from deltachat.capi import ffi
 from deltachat.account import EventLogger
 
@@ -10,6 +10,13 @@ def test_empty_context():
     capi.lib.dc_close(ctx)
 
 
+def test_callback_None2int():
+    ctx = capi.lib.dc_context_new(capi.lib.py_dc_callback, ffi.NULL, ffi.NULL)
+    set_context_callback(ctx, lambda *args: None)
+    capi.lib.dc_close(ctx)
+    clear_context_callback(ctx)
+
+
 def test_dc_close_events():
     ctx = capi.lib.dc_context_new(capi.lib.py_dc_callback, ffi.NULL, ffi.NULL)
     evlog = EventLogger(ctx)

python/tox.ini

@@ -52,6 +52,7 @@ commands =
 python_files = tests/test_*.py 
 norecursedirs = .tox 
 xfail_strict=true
+timeout = 60
 
 [flake8]
 max-line-length = 120

src/context.rs

@@ -306,7 +306,6 @@ pub unsafe fn dc_close(context: &Context) {
     info!(context, 0, "disconnecting SMTP");
     context.smtp.clone().lock().unwrap().disconnect();
 
-    info!(context, 0, "closing SQL");
     context.sql.close(context);
     let mut dbfile = context.dbfile.write().unwrap();
     free(*dbfile as *mut libc::c_void);

src/dc_job.rs

@@ -49,10 +49,10 @@ pub struct dc_job_t {
 }
 
 pub unsafe fn dc_perform_imap_jobs(context: &Context) {
-    dc_log_info(
+    info!(
         context,
-        0i32,
+        0,
-        b"INBOX-jobs started...\x00" as *const u8 as *const libc::c_char,
+        "INBOX-jobs started...",
     );
 
     let probe_imap_network = *context.probe_imap_network.clone().read().unwrap();
@@ -60,13 +60,14 @@ pub unsafe fn dc_perform_imap_jobs(context: &Context) {
     *context.perform_inbox_jobs_needed.write().unwrap() = 0;
 
     dc_job_perform(context, 100, probe_imap_network);
-    dc_log_info(
+    info!(
         context,
-        0i32,
+        0,
-        b"INBOX-jobs ended.\x00" as *const u8 as *const libc::c_char,
+        "INBOX-jobs ended.",
     );
 }
 unsafe fn dc_job_perform(context: &Context, thread: libc::c_int, probe_network: libc::c_int) {
+    // info!(context, 0, "dc_job_perform {} {}", thread, probe_network);
     let mut select_stmt: *mut sqlite3_stmt;
     let mut job = dc_job_t {
         job_id: 0,
@@ -133,6 +134,7 @@ unsafe fn dc_job_perform(context: &Context, thread: libc::c_int, probe_network:
         let mut tries: libc::c_int = 0i32;
         while tries <= 1i32 {
             job.try_again = 0i32;
+            // info!(context, 0, "dc_job_perform action {}", job.action);
             match job.action {
                 5901 => {
                     dc_job_do_DC_JOB_SEND(context, &mut job);

src/imap.rs

@@ -477,6 +477,7 @@ impl Imap {
                 }
             }
         }
+        info!(context, 0, "IMAP unsetup_handle2.");
         let stream = self.session.lock().unwrap().1.take();
         if stream.is_some() {
             match stream.unwrap().shutdown(net::Shutdown::Both) {
@@ -487,6 +488,7 @@ impl Imap {
             }
         }
 
+        info!(context, 0, "IMAP unsetup_handle3.");
         let mut cfg = self.config.write().unwrap();
         cfg.selected_folder = None;
         cfg.selected_mailbox = None;