Project

General

Profile

Bug #10131

import from camera: darktable freeze when closing the import dialog

Added by Damien Firmenich over 4 years ago. Updated over 4 years ago.

Status:
New
Priority:
Low
Assignee:
-
Category:
General
Target version:
-
Start date:
10/03/2014
Due date:
% Done:

0%

Affected Version:
1.4.2
System:
other GNU/Linux
bitness:
64-bit
hardware architecture:
amd64/x86

Description

Steps to reproduce:

- connect a device, in my case a Nexus 5 (MTP mode)
- open dialog to import from the camera
- try to close the window using cancel button, or shortcut
- darktable freezes and need to be killed

I know that darktable isn't built to handle an Android smartphone, but it is still useful to import photos from it.

History

#1 Updated by Fernando R over 4 years ago

I can also reproduce this.

There seems to be a problem when trying to obtain the thumbnails using MTP:

#0  0x00007ffff416c10c in __lll_lock_wait () from /usr/lib/libpthread.so.0
#1  0x00007ffff4166885 in pthread_mutex_lock () from /usr/lib/libpthread.so.0
#2  0x00007ffff7a5c4d4 in dt_pthread_mutex_lock_with_caller (mutex=mutex@entry=0x6a78a0,
    file=file@entry=0x7ffff7b32190 "/home/zacarias/src/darktable/src/common/camera_control.c", line=line@entry=613,
    function=function@entry=0x7ffff7b332f0 <__FUNCTION__.59891> "dt_camctl_detect_cameras") at /home/zacarias/src/darktable/src/common/dtpthread.h:97
#3  0x00007ffff7a5dcd0 in dt_camctl_detect_cameras (c=0x6a78a0) at /home/zacarias/src/darktable/src/common/camera_control.c:613
#4  0x00007fffad407f06 in _camctl_camera_disconnected_callback (camera=<optimized out>, data=0xb6a2f0)
    at /home/zacarias/src/darktable/src/libs/import.c:273
#5  0x00007ffff7a5e0e0 in _dispatch_camera_disconnected (c=c@entry=0x6a78a0, camera=0xe22830)
    at /home/zacarias/src/darktable/src/common/camera_control.c:1487
---Type <return> to continue, or q <return> to quit---
#6  0x00007ffff7a5f848 in _error_func_dispatch25 (context=<optimized out>, text=0x7fffd801dbb0 "PTP General Error", data=0x6a78a0)
    at /home/zacarias/src/darktable/src/common/camera_control.c:170
#7  0x00007ffff5ce842d in gp_context_error () from /usr/lib/libgphoto2.so.6
#8  0x00007fffa98aba32 in ?? () from /usr/lib/libgphoto2/2.5.4/ptp2.so
#9  0x00007fffa98b70ff in ?? () from /usr/lib/libgphoto2/2.5.4/ptp2.so
#10 0x00007ffff5ced2c3 in ?? () from /usr/lib/libgphoto2.so.6
#11 0x00007ffff5cef087 in gp_filesystem_get_file () from /usr/lib/libgphoto2.so.6
#12 0x00007ffff5ce6969 in gp_camera_file_get () from /usr/lib/libgphoto2.so.6
#13 0x00007ffff7a5e956 in _camctl_recursive_get_previews (c=c@entry=0x6a78a0, flags=flags@entry=CAMCTL_IMAGE_PREVIEW_DATA,
    path=path@entry=0x7fffe4b61880 "/store_00010001/DCIM/.thumbnails") at /home/zacarias/src/darktable/src/common/camera_control.c:876
#14 0x00007ffff7a5ecb3 in _camctl_recursive_get_previews (c=c@entry=0x6a78a0, flags=flags@entry=CAMCTL_IMAGE_PREVIEW_DATA,
    path=path@entry=0x7fffe4b62a30 "/store_00010001/DCIM") at /home/zacarias/src/darktable/src/common/camera_control.c:948
#15 0x00007ffff7a5ecb3 in _camctl_recursive_get_previews (c=c@entry=0x6a78a0, flags=flags@entry=CAMCTL_IMAGE_PREVIEW_DATA,
    path=path@entry=0x7fffe4b63be0 "/store_00010001") at /home/zacarias/src/darktable/src/common/camera_control.c:948
#16 0x00007ffff7a5ecb3 in _camctl_recursive_get_previews (c=c@entry=0x6a78a0, flags=flags@entry=CAMCTL_IMAGE_PREVIEW_DATA,
    path=path@entry=0x7ffff7af8ada "/") at /home/zacarias/src/darktable/src/common/camera_control.c:948
#17 0x00007ffff7a5ef88 in dt_camctl_get_previews (c=0x6a78a0, flags=CAMCTL_IMAGE_PREVIEW_DATA, cam=<optimized out>)
    at /home/zacarias/src/darktable/src/common/camera_control.c:969
#18 0x00007ffff7a5fe4c in dt_camera_get_previews_job_run (job=<optimized out>) at /home/zacarias/src/darktable/src/control/jobs/camera_jobs.c:296
#19 0x00007ffff79a4549 in dt_control_run_job (control=control@entry=0x6a8ed0) at /home/zacarias/src/darktable/src/control/jobs.c:276
#20 0x00007ffff79a4658 in dt_control_work (ptr=<optimized out>) at /home/zacarias/src/darktable/src/control/jobs.c:474
#21 0x00007ffff4164314 in start_thread () from /usr/lib/libpthread.so.0
#22 0x00007ffff0f8c3ed in clone () from /usr/lib/libc.so.6

Just to confirm that what happens to you is the same as this, can you confirm that, in your case, you never get to see a "thumbnail/preview" of the pictures but only their filename?

#2 Updated by Fernando R over 4 years ago

Oh! And these are the messages printed when executed with "-d all"

[add_job] 0 | get camera previews job | queue: 1 | priority: 0
[run_job+] 02 121893534.021316 get camera previews job | queue: 1 | priority: 4
[camera_control] registering listener 0x182be80
[camera_control] camera control locked for camera 0x17f8db0
[camera_control] gphoto2 status: Downloading '.thumbdata4--1967290299' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] gphoto2 status: Downloading '.thumbdata4--1967290299' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] gphoto2 status: Downloading '.thumbdata4-1763508120' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] gphoto2 status: Downloading '.thumbdata4-1763508120' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] gphoto2 status: Downloading '.thumbdata4-1763508120' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] failed to retrieve preview of file .thumbdata4-1763508120
[camera_control] gphoto2 status: Downloading '.thumbindex4--1967290299' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] gphoto2 status: Downloading '.thumbindex4--1967290299' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] gphoto2 status: Downloading '.thumbindex4--1967290299' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] failed to retrieve preview of file .thumbindex4--1967290299
[camera_control] gphoto2 status: Downloading '.thumbindex4-1763508120' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] gphoto2 status: Downloading '.thumbindex4-1763508120' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] gphoto2 status: Downloading '.thumbindex4-1763508120' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] failed to retrieve preview of file .thumbindex4-1763508120
[camera_control] gphoto2 status: Downloading '1409080654845.jpg' from folder '/store_00010001/DCIM/.thumbnails'...
[camera_control] gphoto2 error: PTP General Error

So... from the backtrace and these messages, this is what is happening:

  1. From "_camctl_recursive_get_previews()" function "gp_camera_file_get()" is called several times
     to retrieve each image thumbnail.

  2. The first three times (when trying to access files named ".thumb*"), "gp_camera_file_get()" 
     fails and returns immediately. 

  3. However, the fourth time (when trying to acess a file named "140*.jpg", which seems to be the
     first "real" image), "gp_camera_file_get()" produces a "PTP General Error" and calls
     back into "_error_func_dispatch25()".

  4. Then "_error_func_dispatch25()" calls "_dispatch_camera_disconnected()", which calls 
     "_camctl_camera_disconnected_callback()" --> "dt_camctl_detect_cameras()" 

  5. So... as a result of receiving a PTP error we try to disconnect and rescan for camera devices.
     However, before the actual scanning, the camera control lock is needed. This is where the
     thread sleeps forever because someone else already has the lock and won't release it.

So... there are two problems here:
  1. One where gphoto cannot handle MTP pictures properly
  2. Another one where darktable locks when this happens

#3 Updated by Fernando R over 4 years ago

Regarding issue 2 (ie. "why does darktable lock?"), this is what we know:
  1. Thread X is locked trying to adquire mutex "camctl->lock"
  2. Someone else already has that mutex locked

But who? Well, according to "gdb" its the same X thread. We can verify this by printing the "mutex" structure and having a look at the "__data.__owner" field.

I have modified the "dt_pthread_mutex_t" structure to add a new field ("last_lock_bt") which saves the backtrace of the latest path to achieve the lock. This is what it returned:

(gdb) print *mutex
$2 = {mutex = {__data = {__lock = 2, __count = 0, __owner = 10557, __nusers = 1, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0,
        __next = 0x0}}, __size = "\002\000\000\000\000\000\000\000=)\000\000\001", '\000' <repeats 26 times>, __align = 2},
  name = "/home/zacarias/src/darktable/src/common/camera_control.c:538 (dt_camctl_new)", '\000' <repeats 179 times>,
  time_locked = 121898027.24459501, time_sum_wait = 4.0084123611450195e-06, time_sum_locked = 0.81888701021671295, top_locked_name = {
    "/home/zacarias/src/darktable/src/common/camera_control.c:706 (dt_camctl_detect_cameras)", '\000' <repeats 168 times>,
    '\000' <repeats 255 times>, '\000' <repeats 255 times>}, top_locked_sum = {0.81888701021671295, 0, 0}, top_wait_name = {
    "/home/zacarias/src/darktable/src/common/camera_control.c:613 (dt_camctl_detect_cameras)", '\000' <repeats 168 times>,
    "/home/zacarias/src/darktable/src/common/camera_control.c:497 (_camctl_lock)", '\000' <repeats 180 times>, '\000' <repeats 255 times>},
  top_wait_sum = {1.9967555999755859e-06, 2.0116567611694336e-06, 0}, last_lock_bt = {0x7ffff7a5b9d6 <dt_pthread_mutex_lock_with_caller+420>,
    0x7ffff7a5e1ec <_camctl_lock+36>, 0x7ffff7a5e34e <dt_camctl_get_previews+19>, 0x7ffff7a5f223 <dt_camera_get_previews_job_run+55>,
    0x7ffff79a398d <dt_control_run_job+226>, 0x7ffff79a3a9c <dt_control_work+67>, 0x7ffff4163314 <start_thread+196>, 0x7ffff0f8b3ed <clone+109>,
    0x0, 0x7ffff7382228 <g_signal_emit_valist+4072>}}

Now, the "important" field is this one:

last_lock_bt = {0x7ffff7a5b9d6 <dt_pthread_mutex_lock_with_caller+420>,
                0x7ffff7a5e1ec <_camctl_lock+36>,
                0x7ffff7a5e34e <dt_camctl_get_previews+19>,
                0x7ffff7a5f223 <dt_camera_get_previews_job_run+55>,
                0x7ffff79a398d <dt_control_run_job+226>,
                0x7ffff79a3a9c <dt_control_work+67>,
                0x7ffff4163314 <start_thread+196>,
                0x7ffff0f8b3ed <clone+109>,
                0x0,
                0x7ffff7382228 <g_signal_emit_valist+4072>}

Now we now what happened. This is the timeline of events:

  Thread X
    start_thread()
      dt_control_work()
        dt_control_run_job()
          dt_camera_get_previews_job_run()
            dt_camctl_get_previews()
              _camctl_lock()
                dt_pthread_mutex_lock_with_caller()  <------------- FIRST LOCK
              _camctl_recursive_get_previews()
                gp_camera_file_get()
                  ...
                    _error_func_dispatch25()
                      _dispatch_camera_disconnected()
                        dt_camctl_detect_cameras()
                          dt_pthread_mutex_lock_with_caller() <--- SECOND LOCK

According to all this... which place would be a good one to unlock the mutex? Maybe the " _dispatch_camera_disconnected()" function? Someone who know more about the code organization should answer this :)

#4 Updated by Fernando R over 4 years ago

One more thing: I changed the mutex type from NORMAL to RECURSIVE (after all, at least in this particular situation, a RECURSIVE mutex does not seem like a bad choice) and now it "kind of" works:
  1. The "PTP General error" is shown all the time, but thumbnails do load and are shown in the list.
  2. The process of showing all pictures takes a lot of time and you have to wait for it to finish as both the "Cancel" and "Import" buttons do not work until that happens.
  3. At the end, you can select the pictures you want and import them.
In order to make the mutex recursive I changed the implementation of "dt_pthread_mutex_init_with_caller()":
  - #if defined(__OpenBSD__)  -->  #if 1
  - PTHREAD_MUTEX_NORMAL  -->  PTHREAD_MUTEX_RECURSIVE

However I don't know why the "__OpenBSD__" macro was placed there in the first place, so this should be
reviewed with care.
At this point I see three tasks need to be done:
  1. Check if it makes sense to make that mutex recursive (see note above)
  2. Investigate why the gphote library is producing those errors
  3. Allow for the "Cancel" button to be pressed even when the thumbnails importing process is running

Also available in: Atom PDF