dt_print() maintenance and fixes

1. In database code the macros TRY_EXEC, TRY_STEP and TRY_PREPARE use dt_print() internally, the
   message strings all got the leading [init] and ending newlines stripped off, instead the macros
   take care of this.
   The leading [init] has been replaced by "TRY_EXEC" or the appropriate according to the macro for
   improved log quality. Also just one line per error with message and sql error string.

   Also at various places the log information for one problem appeared on several lines, fixed those.

2. dt_control_job_print() - now as static _control_job_print() - has been refactored and
   gets additional parameters to print "everything" instead of following a dt_print() without a newline.
   So - prettyfied logs pluse denser code.

3. Removed some overseen newlines or dots at the end of dt_print()

4. Spotted an unused inline function and commented it

Author: jenshannoschwalm

src/bauhaus/bauhaus.c

@@ -1239,7 +1239,7 @@ void dt_bauhaus_update_from_field(dt_iop_module_t *module,
       default:
         dt_print
           (DT_DEBUG_ALWAYS,
-           "[dt_bauhaus_update_from_field] invalid bauhaus widget type encountered\n");
+           "[dt_bauhaus_update_from_field] invalid bauhaus widget type encountered");
     }
 
     // if gui->reset then notebook tab highlights were not yet changed

src/common/bilateralcl.c

@@ -147,7 +147,7 @@ dt_bilateral_cl_t *dt_bilateral_init_cl(const int devid,
   }
 
 #if 0
-  fprintf(stderr, "[bilateral] created grid [%d %d %d]"
+  dt_print(DT_DEBUG_ALWAYS, "[bilateral] created grid [%d %d %d]"
           " with sigma (%f %f) (%f %f)\n", b->size_x, b->size_y, b->size_z,
           b->sigma_s, sigma_s, b->sigma_r, sigma_r);
 #endif

src/common/camera_control.c

@@ -1885,7 +1885,7 @@ int dt_camctl_camera_property_exists(const dt_camctl_t *c,
   {
     dt_print(DT_DEBUG_CAMCTL,
              "[camera_control] failed to check if property exists"
-             " in camera configuration, camera == NULL\n");
+             " in camera configuration, camera == NULL");
     return 0;
   }
 
@@ -1895,7 +1895,7 @@ int dt_camctl_camera_property_exists(const dt_camctl_t *c,
   {
     dt_print(DT_DEBUG_CAMCTL,
              "[camera_control] failed to check if property exists"
-             " in camera configuration, camera configuration == NULL\n");
+             " in camera configuration, camera configuration == NULL");
     return 0;
   }
 
@@ -1963,7 +1963,7 @@ const char *dt_camctl_camera_property_get_first_choice(const dt_camctl_t *c,
   {
     dt_print(DT_DEBUG_CAMCTL,
              "[camera_control] failed to get first choice of property from camera,"
-             " camera==NULL\n");
+             " camera==NULL");
     return NULL;
   }
   dt_camera_t *camera = (dt_camera_t *)cam;
@@ -1997,7 +1997,7 @@ const char *dt_camctl_camera_property_get_next_choice(const dt_camctl_t *c,
   {
     dt_print(DT_DEBUG_CAMCTL,
              "[camera_control] Failed to get next choice of property from camera,"
-             " camera==NULL\n");
+             " camera==NULL");
     return NULL;
   }
   dt_camera_t *camera = (dt_camera_t *)cam;

src/common/colorspaces.c

@@ -2057,7 +2057,7 @@ void dt_colorspaces_set_display_profile
     else
       _update_display_profile(buffer, buffer_size, name, sizeof(name));
     dt_print(DT_DEBUG_CONTROL, "[color profile] we got a new screen profile `%s'"
-             " from the %s (size: %d)\n",
+             " from the %s (size: %d)",
              *name ? name : "(unknown)", profile_source, buffer_size);
   }
   else
@@ -2210,7 +2210,7 @@ dt_colorspaces_color_profile_type_t dt_colorspaces_cicp_to_type
 
   if(filename != NULL)
     dt_print(DT_DEBUG_IMAGEIO, "[colorin] unsupported CICP color profile"
-             " for `%s': %d/%d/%d\n", filename,
+             " for `%s': %d/%d/%d", filename,
              cicp->color_primaries,
              cicp->transfer_characteristics,
              cicp->matrix_coefficients);

src/common/database.c

@@ -87,7 +87,7 @@ const dt_pwstorage_t *dt_pwstorage_new()
         _backend = PW_STORAGE_BACKEND_LIBSECRET;
     #endif
 
-    dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] autodetected storage backend.");
+    dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] autodetected storage backend");
   }
   else if(strcmp(_backend_str, "none") == 0)
     _backend = PW_STORAGE_BACKEND_NONE;
@@ -109,28 +109,28 @@ const dt_pwstorage_t *dt_pwstorage_new()
 #endif
   else if(strcmp(_backend_str, "gnome keyring") == 0)
   {
-    dt_print(DT_DEBUG_ALWAYS, "[pwstorage_new] GNOME Keyring backend is no longer supported.");
+    dt_print(DT_DEBUG_ALWAYS, "[pwstorage_new] GNOME Keyring backend is no longer supported");
     dt_control_log(_("GNOME Keyring backend is no longer supported. configure a different one"));
     _backend = PW_STORAGE_BACKEND_NONE;
   }
 
   switch(_backend)
   {
     default:
-      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] unknown storage backend. Using none.");
+      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] unknown storage backend. Using none");
     case PW_STORAGE_BACKEND_NONE:
       pwstorage->pw_storage_backend = PW_STORAGE_BACKEND_NONE;
       pwstorage->backend_context = NULL;
       dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] no storage backend. not storing username/password. "
-                                   "please change in preferences, security tab.\n");
+                                   "please change in preferences, security tab");
       break;
     case PW_STORAGE_BACKEND_LIBSECRET:
 #ifdef HAVE_LIBSECRET
-      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] using libsecret backend for username/password storage.");
+      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] using libsecret backend for username/password storage");
       pwstorage->backend_context = (void *)dt_pwstorage_libsecret_new();
       if(pwstorage->backend_context == NULL)
       {
-        dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] error starting libsecret. using no storage backend.");
+        dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] error starting libsecret. using no storage backend");
         pwstorage->backend_context = NULL;
         pwstorage->pw_storage_backend = PW_STORAGE_BACKEND_NONE;
       }
@@ -141,17 +141,17 @@ const dt_pwstorage_t *dt_pwstorage_new()
       break;
 #else
       dt_print(DT_DEBUG_PWSTORAGE,
-               "[pwstorage_new] libsecret backend not available. using no storage backend.");
+               "[pwstorage_new] libsecret backend not available. using no storage backend");
       pwstorage->backend_context = NULL;
       pwstorage->pw_storage_backend = PW_STORAGE_BACKEND_NONE;
 #endif
     case PW_STORAGE_BACKEND_KWALLET:
 #ifdef HAVE_KWALLET
-      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] using kwallet backend for username/password storage.");
+      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] using kwallet backend for username/password storage");
       pwstorage->backend_context = (void *)dt_pwstorage_kwallet_new();
       if(pwstorage->backend_context == NULL)
       {
-        dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] error starting kwallet. using no storage backend.");
+        dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] error starting kwallet. using no storage backend");
         pwstorage->backend_context = NULL;
         pwstorage->pw_storage_backend = PW_STORAGE_BACKEND_NONE;
       }
@@ -163,30 +163,30 @@ const dt_pwstorage_t *dt_pwstorage_new()
       break;
 #else
       dt_print(DT_DEBUG_PWSTORAGE,
-               "[pwstorage_new] kwallet backend not available. using no storage backend.");
+               "[pwstorage_new] kwallet backend not available. using no storage backend");
       pwstorage->backend_context = NULL;
       pwstorage->pw_storage_backend = PW_STORAGE_BACKEND_NONE;
 #endif
     case PW_STORAGE_BACKEND_APPLE_KEYCHAIN:
 #ifdef HAVE_APPLE_KEYCHAIN
-      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] using apple keychain backend for username/password storage.");
+      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] using apple keychain backend for username/password storage");
       pwstorage->backend_context = (void *)dt_pwstorage_apple_keychain_new();
       pwstorage->pw_storage_backend = PW_STORAGE_BACKEND_APPLE_KEYCHAIN;
 #else
       dt_print(DT_DEBUG_PWSTORAGE,
-               "[pwstorage_new] apple keychain backend not available. using no storage backend.");
+               "[pwstorage_new] apple keychain backend not available. using no storage backend");
       pwstorage->backend_context = NULL;
       pwstorage->pw_storage_backend = PW_STORAGE_BACKEND_NONE;
 #endif
       break;
     case PW_STORAGE_BACKEND_WINDOWS_CREDENTIALS:
 #ifdef HAVE_WINDOWS_CREDENTIALS
-      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] using windows credentials backend for username/password storage.");
+      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_new] using windows credentials backend for username/password storage");
       pwstorage->backend_context = (void *)dt_pwstorage_windows_credentials_new();
       pwstorage->pw_storage_backend = PW_STORAGE_BACKEND_WINDOWS_CREDENTIALS;
 #else
       dt_print(DT_DEBUG_PWSTORAGE,
-               "[pwstorage_new] windows credentials backend not available. using no storage backend.");
+               "[pwstorage_new] windows credentials backend not available. using no storage backend");
       pwstorage->backend_context = NULL;
       pwstorage->pw_storage_backend = PW_STORAGE_BACKEND_NONE;
 #endif
@@ -253,7 +253,7 @@ gboolean dt_pwstorage_set(const gchar *slot, GHashTable *table)
   switch(darktable.pwstorage->pw_storage_backend)
   {
     case PW_STORAGE_BACKEND_NONE:
-      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_set] no backend. not storing anything.");
+      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_set] no backend. not storing anything");
       break;
     case PW_STORAGE_BACKEND_LIBSECRET:
 #if HAVE_LIBSECRET
@@ -289,7 +289,7 @@ GHashTable *dt_pwstorage_get(const gchar *slot)
   switch(darktable.pwstorage->pw_storage_backend)
   {
     case PW_STORAGE_BACKEND_NONE:
-      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_get] no backend. not reading anything.");
+      dt_print(DT_DEBUG_PWSTORAGE, "[pwstorage_get] no backend. not reading anything");
       break;
     case PW_STORAGE_BACKEND_LIBSECRET:
 #if HAVE_LIBSECRET

src/common/pwstorage/pwstorage.c

@@ -186,11 +186,12 @@ void dt_control_job_set_state_callback(_dt_job_t *job, dt_job_state_change_callb
   job->state_changed_cb = cb;
 }
 
-
-static void dt_control_job_print(_dt_job_t *job)
+// We don't want to log dt_get_wtime() as we already show the stamp
+static void _control_job_print(_dt_job_t *job, const char *info, const char *err, int32_t res)
 {
   if(!job) return;
-  dt_print(DT_DEBUG_CONTROL, "%s | queue: %d | priority: %d", job->description, job->queue, job->priority);
+  dt_print(DT_DEBUG_CONTROL, "[%s]\t%02d %s %s | queue: %d | priority: %d",
+    info, res, err, job->description, job->queue, job->priority);
 }
 
 void dt_control_job_cancel(_dt_job_t *job)
@@ -213,7 +214,7 @@ void dt_control_job_wait(_dt_job_t *job)
     g_usleep(100000); // wait 0.1 seconds
     state = dt_control_job_get_state(job);
   }
-     
+
   /* if job execution is not finished let's wait for it */
   if(state == DT_JOB_STATE_RUNNING || state == DT_JOB_STATE_CANCELLED)
   {
@@ -246,19 +247,15 @@ static gboolean _control_run_job_res(dt_control_t *control, int32_t res)
   dt_pthread_mutex_lock(&job->wait_mutex);
   if(dt_control_job_get_state(job) == DT_JOB_STATE_QUEUED)
   {
-    dt_print(DT_DEBUG_CONTROL, "[run_job+] %02d %f ", res, dt_get_wtime());
-    dt_control_job_print(job);
-    dt_print(DT_DEBUG_CONTROL, "\n");
+    _control_job_print(job, "run_job+", "", res);
 
     _control_job_set_state(job, DT_JOB_STATE_RUNNING);
 
     /* execute job */
     job->result = job->execute(job);
 
     _control_job_set_state(job, DT_JOB_STATE_FINISHED);
-    dt_print(DT_DEBUG_CONTROL, "[run_job-] %02d %f ", res, dt_get_wtime());
-    dt_control_job_print(job);
-    dt_print(DT_DEBUG_CONTROL, "\n");
+    _control_job_print(job, "run_job-", "", res);
   }
   dt_pthread_mutex_unlock(&job->wait_mutex);
   dt_control_job_dispose(job);
@@ -330,22 +327,15 @@ static _dt_job_t *_control_schedule_job(dt_control_t *control)
 
 static void _control_job_execute(_dt_job_t *job)
 {
-  dt_print(DT_DEBUG_CONTROL, "[run_job+] %02d %f ", DT_CTL_WORKER_RESERVED + dt_control_get_threadid(),
-           dt_get_wtime());
-  dt_control_job_print(job);
-  dt_print_nts(DT_DEBUG_CONTROL, "\n");
+  _control_job_print(job, "run_job+", "", DT_CTL_WORKER_RESERVED + dt_control_get_threadid());
 
   _control_job_set_state(job, DT_JOB_STATE_RUNNING);
 
   /* execute job */
   job->result = job->execute(job);
 
   _control_job_set_state(job, DT_JOB_STATE_FINISHED);
-
-  dt_print(DT_DEBUG_CONTROL, "[run_job-] %02d %f ", DT_CTL_WORKER_RESERVED + dt_control_get_threadid(),
-           dt_get_wtime());
-  dt_control_job_print(job);
-  dt_print_nts(DT_DEBUG_CONTROL, "\n");
+  _control_job_print(job, "run_job-", "", DT_CTL_WORKER_RESERVED + dt_control_get_threadid());
 }
 
 static gboolean _control_run_job(dt_control_t *control)
@@ -394,8 +384,7 @@ gboolean dt_control_add_job_res(dt_control_t *control,
   }
 
   dt_print(DT_DEBUG_CONTROL, "[add_job_res] %d | ", res);
-  dt_control_job_print(job);
-  dt_print_nts(DT_DEBUG_CONTROL, "\n");
+  _control_job_print(job, "add_job_res", "", res);
 
   _control_job_set_state(job, DT_JOB_STATE_QUEUED);
   control->job_res[res] = job;
@@ -441,9 +430,7 @@ gboolean dt_control_add_job(dt_control_t *control,
   GList **queue = &control->queues[queue_id];
   size_t length = control->queue_length[queue_id];
 
-  dt_print(DT_DEBUG_CONTROL, "[add_job] %zu | ", length);
-  dt_control_job_print(job);
-  dt_print_nts(DT_DEBUG_CONTROL, "\n");
+  _control_job_print(job, "add_job", "", (int32_t)length);
 
   if(queue_id == DT_JOB_QUEUE_SYSTEM_FG)
   {
@@ -456,9 +443,7 @@ gboolean dt_control_add_job(dt_control_t *control,
       _dt_job_t *other_job = (_dt_job_t *)control->job[k];
       if(_control_job_equal(job, other_job))
       {
-        dt_print(DT_DEBUG_CONTROL, "[add_job] found job already in scheduled: ");
-        dt_control_job_print(other_job);
-        dt_print_nts(DT_DEBUG_CONTROL, "\n");
+        _control_job_print(other_job, "add_job", "found job already in scheduled:", -1);
 
         dt_pthread_mutex_unlock(&control->queue_mutex);
 
@@ -475,9 +460,7 @@ gboolean dt_control_add_job(dt_control_t *control,
       _dt_job_t *other_job = (_dt_job_t *)iter->data;
       if(_control_job_equal(job, other_job))
       {
-        dt_print(DT_DEBUG_CONTROL, "[add_job] found job already in queue: ");
-        dt_control_job_print(other_job);
-        dt_print_nts(DT_DEBUG_CONTROL, "\n");
+        _control_job_print(other_job, "add_job", "found job already in queue", -1);
 
         *queue = g_list_delete_link(*queue, iter);
         length--;

src/control/jobs.c

@@ -1921,7 +1921,7 @@ void dt_dev_read_history_ext(dt_develop_t *dev,
 
     dt_print(DT_DEBUG_PARAMS,
              "[dt_dev_read_history_ext] temporary history initialised with"
-             " default params and presets\n");
+             " default params and presets");
 
     // Now merge memory.history into main.history
 

src/develop/develop.c

@@ -1978,7 +1978,7 @@ gboolean _iop_validate_params(dt_introspection_field_t *field,
         {
           if(report)
             dt_print(DT_DEBUG_ALWAYS, "[iop_validate_params] `%s' failed"
-                   " for type \"%s\", for array element \"%d\"\n",
+                   " for type \"%s\", for array element \"%d\"",
                      name, field->header.type_name, i);
           all_ok = FALSE;
           break;

src/develop/imageop.c

@@ -968,14 +968,14 @@ static inline gboolean _dt_masks_intbuf_growto(dt_masks_intbuf_t *a,
   {
     // not much we can do here except emit an error message
     dt_print(DT_DEBUG_ALWAYS,
-             "critical: out of memory for intbuf '%s' with size request %zu!\n",
+             "critical: out of memory for intbuf '%s' with size request %zu!",
              a->tag, newsize);
     return FALSE;
   }
   if (a->buffer)
   {
     memcpy(newbuf, a->buffer, a->size * sizeof(int));
-    dt_print(DT_DEBUG_MASKS, "[masks intbuf '%s'] grows to size %lu (is %p, was %p)\n",
+    dt_print(DT_DEBUG_MASKS, "[masks intbuf '%s'] grows to size %lu (is %p, was %p)",
              a->tag,
              (unsigned long)a->size, newbuf, a->buffer);
     dt_free_align(a->buffer);
@@ -997,7 +997,7 @@ dt_masks_intbuf_t *dt_masks_intbuf_init(const size_t size, const char *tag)
     g_strlcpy(a->tag, tag, sizeof(a->tag)); //only for debugging purposes
     a->pos = 0;
     if(_dt_masks_intbuf_growto(a, size))
-      dt_print(DT_DEBUG_MASKS, "[masks intbuf '%s'] with initial size %lu (is %p)\n",
+      dt_print(DT_DEBUG_MASKS, "[masks intbuf '%s'] with initial size %lu (is %p)",
                a->tag,
                (unsigned long)a->size, a->buffer);
     if(a->buffer == NULL)
@@ -1035,13 +1035,14 @@ static inline
 void dt_masks_intbuf_free(dt_masks_intbuf_t *a)
 {
   if(a == NULL) return;
-  dt_print(DT_DEBUG_MASKS, "[masks intbuf '%s'] freed (was %p)\n", a->tag,
+  dt_print(DT_DEBUG_MASKS, "[masks intbuf '%s'] freed (was %p)", a->tag,
           a->buffer);
   dt_free_align(a->buffer);
   free(a);
 }
 
 // Dump buffer to file for debugging.
+/*
 static inline
 void dt_masks_intnbuf_debug_print(dt_masks_intbuf_t *a)
 {
@@ -1056,6 +1057,7 @@ void dt_masks_intnbuf_debug_print(dt_masks_intbuf_t *a)
   }
   fclose(f);
 }
+*/
 
 /* End of dynamic buffer code
  ******************************************************/