GNOME Bugzilla – Bug 785503
Images are corrupt after import - data loss
Last modified: 2017-08-20 21:05:23 UTC
I shot RAW+JPEG. When I import images from the memory card, I'm facing 2 Problems. 1) some of the imported JPEGs are corrupted 2) some of the RAW files are not imported - sometimes with an reported error, sometimes without an error. I saved the log: Jul 27 21:08:39 pc shotwell.desktop[12156]: Failed to play the file: couldn't get state. Jul 27 21:08:55 pc shotwell.desktop[12156]: Failed to query file for duration Jul 27 21:09:11 pc shotwell.desktop[12156]: Failed to query file for duration Jul 27 21:09:23 pc shotwell.desktop[12156]: Failed to play the file: couldn't get state. Jul 27 21:09:23 pc shotwell.desktop[12156]: Failed to play the file: couldn't get state. Jul 27 21:09:30 pc shotwell.desktop[12156]: Failed to query file for duration Jul 27 21:09:35 pc shotwell.desktop[12156]: Failed to play the file: couldn't get state. Jul 27 21:09:39 pc shotwell[12156]: 0x7f1dc1933c00: failed to release event: Bad file descriptor Jul 27 21:09:39 pc shotwell[12156]: 0x7f1dc1933c00: failed to release event: Bad file descriptor Jul 27 21:10:46 pc shotwell.desktop[12156]: /home/xx/Pictures/2017/2017-07-27/dsc_5720.nef: Unexpected end of file Generally: * I feel that shotwell is very unstable on Fedora 26 * Importing photos seems to be very slow - and unstable My environment: * Fedora 26 * shotwell-0.26.2-1.fc26
I give you slow, there are several weird things happening when importing RAW. The messages look like they are coming from the video thumbnailer - do you also have videos? Are you importing to any special file system (like NTFS, vboxfs, ...) Also, that's the journal/syslog. Can you please attach ~/.cache/shotwell/shotwell.log and the result report after import?
Created attachment 356528 [details] Journal log, when shotwell reports an import error
Created attachment 356529 [details] Shotwell log, when shotwell reports an import error
Created attachment 356530 [details] Import Log, when shotwell reports an import error
Created attachment 356531 [details] journal log, when shotwell reports that the import was successfully
Created attachment 356532 [details] Shotwell log, when shotwell reports that the import was successfully
I've imported the same set of photos 2 times into shotwell and got 2 different results - each with data corruption. Test files * 25 NEF+JPEG pairs My first run: Shotwell reports an import error. See the following attachements * attachment 356528 [details] * attachment 356529 [details] * attachment 356530 [details] The imported NEF files seemed to be valid. Some JPEGS were corrupted. My second run: Shotwell reports that the files was successfully imported. * attachment 356531 [details] * attachment 356532 [details] The imported NEF files seemed to be valid. Some JPEGS were corrupted. > The messages look like they are coming from the video thumbnailer - do you also have videos? No, there was no video to import > Are you importing to any special file system (like NTFS, vboxfs, ...) ext4 on a LVM
Importing the NEF+JPEG files by drag and drop does work fine. First, no data corruption Second, it seems to be faster than importing from camera menu item Third, it does rename NEF and JPEGS to lower case. Importing from the camera menu does only rename the NEF files to lower case. Not the JPEGS.
(In reply to Stefan from comment #8) > Importing the NEF+JPEG files by drag and drop does work fine. > > First, no data corruption > Second, it seems to be faster than importing from camera menu item That's weird. But then again, it might be because of the weird things Shotwell does when importing RAW+JPEG from Camera. I'm still worried because of the thumbnailer output. > Third, it does rename NEF and JPEGS to lower case. Importing from the camera > menu does only rename the NEF files to lower case. Not the JPEGS. Yeah, that's https://bugzilla.gnome.org/show_bug.cgi?id=777626 Are you automatically watching your library for new files? Might be worth a shot to turn that off to speed up importing - and stops corruption, there might be a race there.
> Are you automatically watching your library for new files? Might be worth a > shot to turn that off to speed up importing - and stops corruption, there > might be a race there. No, the option to watch the library directory for new files is off.
version 0.27.0 (compiled from source) - same errors
Can you try running with strace -f -o shotwell.trace shotwell and provide the trace?
Created attachment 356809 [details] debug log corresponding to the strace
I've created a strace for shotwell 0.27.0 (compiled from source). Please see attachment 356809 [details] for the debug log for this run. export SHOTWELL_LOG=1 strace -f -o shotwell.trace ./shotwell The gzip of the trace is too big for bugzilla, so you can download it from: * https://fromsmash.com/8990677d-77c2-11e7-830d-0a39043893bc
FYI, commenting out the following lines in BatchImport.vala makes the import process usable - for me. Line 1705 Line 1742 to 1751 This disables the notification, that prepared files are ready. This way, downloading from the camera and importing is sequential. Of course, I got no feedback of the import process until all files are downloaded from the camera. But * no data corruption of JPEGs * no import errors
(In reply to Stefan from comment #15) > FYI, commenting out the following lines in BatchImport.vala makes the import > process usable - for me. > > Line 1705 > Line 1742 to 1751 THat's for which version? Can you perhaps post links to current git master on https://git.gnome.org/browse/shotwell/tree/src/BatchImport.vala - 1705 is a } there. > > This disables the notification, that prepared files are ready. This way, > downloading from the camera and importing is sequential. Of course, I got no > feedback of the import process until all files are downloaded from the > camera. Notifications are an easy troublespot in Shotwell, so not that surprising.
(In reply to Jens Georg from comment #16) > (In reply to Stefan from comment #15) > > FYI, commenting out the following lines in BatchImport.vala makes the import > > process usable - for me. > > > > Line 1705 > > Line 1742 to 1751 > > THat's for which version? Can you perhaps post links to current git master > on https://git.gnome.org/browse/shotwell/tree/src/BatchImport.vala - 1705 is > a } there. > Ah sorry. shotwell-0.27.0 of course.
With that commented out, do you still see L 6095 2017-08-02 20:32:43 [CRT] import_queue_page_on_fatal_error: assertion 'message != NULL' failed in the shotwell log?
Created attachment 356891 [details] Debug log, when importing files sequential No, this message is not in the log.
it seems, that this error was introduced with version 0.26.0. Version 0.24.6 works correctly
Interesting. Could you do a git bisect?
Accidentally lowered severity
I have finished the git bisect session. Reverting the "bad commit" in the 0.26 branch makes the import usable. The result: eceb40c3578c9c795ad20612a0702024686eafba is the first bad commit commit eceb40c3578c9c795ad20612a0702024686eafba Author: Jens Georg <mail@jensge.org> Date: Thu Mar 9 21:24:28 2017 +0100 Use gp_file_new_from_fd for getting files Previously, we would use a memory file and load the whole file into memory and write it to disk afterwards. That was probably ok for (small) photos, but totally killed memory usage with videos. Signed-off-by: Jens Georg <mail@jensge.org> https://bugzilla.gnome.org/show_bug.cgi?id=732663 :040000 040000 0a154028830b99b8d747afee763630b782456a64 8d159e43aed39bde251a893f09090853c099ef7c M src :040000 040000 c97b9bb8268f6052334e5840e34587d57c61ff2e 3f693573e6dad698e4fbb551def9ef26529c1eb5 M vapi
Shit. Thank you.
Is it possible, that the Posix.close() call in GPhoto.vala method save_image() should not be called? The short story: without Posix.close() the import works on the 0.26 branch The long story: First, I replaced the Posix.close with the following debug code: try { if(FileUtils.close_checked(fd)){ debug("close_checked on fd %d after create_from_fd true", fd); }else { debug("close_checked on fd %d after create_from_fd false", fd); } } catch (Error e) { debug("close_checked on fd %d after create_from_fd exception %s", fd, e.message); } The debug message was in some cases an exception * close_checked on fd 20 after create_from_fd exception Bad file descriptor Second, I removed closing the FD and added more debug statements to see, if the FD value will increase. * debug("Save image %s with fd %d",dest_file.get_path(), fd); During an import of 50 files, the FD value was 20 or 21. Does GPhoto already close the file? Please note, that previous log files points to problems with Bad file descriptors.
(In reply to Stefan from comment #25) > Is it possible, that the Posix.close() call in GPhoto.vala method > save_image() should not be called? Yes, it shouldn't. gphoto2 doesn't document that it takes ownership of the fd with gp_file_new_from_fd and closes it in gp_file_free :( https://github.com/gphoto/libgphoto2/blob/master/libgphoto2/gphoto2-file.c#L151 Thank you very much for looking into that, much appreciated!
Created attachment 357351 [details] [review] Do not close FileDescriptor passed to CameraFile CameraFile takes ownership of the file descriptor and closes it, so we end up closing random file descriptors
Attachment 357351 [details] pushed as 208bc88 - Do not close FileDescriptor passed to CameraFile
Version 0.26.3 is available on Fedora 26 - it works - thanks.