inkscape crashed with SIGSEGV in file_save()

[Christopher Kyle Horton]

Occurred when I closed Inkscape.

ProblemType: Crash
DistroRelease: Ubuntu 12.04
Package: inkscape 0.48.3.1-0ubuntu2
ProcVersionSignature: Ubuntu 3.2.0-20.33-generic 3.2.12
Uname: Linux 3.2.0-20-generic x86_64
ApportVersion: 1.95-0ubuntu1
Architecture: amd64
CrashCounter: 1
Date: Wed Mar 28 15:01:15 2012
ExecutablePath: /usr/bin/inkscape
InstallationMedia: Ubuntu 12.04 LTS "Precise Pangolin" - Alpha amd64 (20111129.1)
ProcCmdline: inkscape /home/username/MyKaryotes/graphics/cell.svg
ProcEnviron:
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SegvReason: reading NULL VMA
Signal: 11
SourcePackage: inkscape
Title: inkscape crashed with SIGSEGV in sp_file_save_dialog()
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups: adm cdrom dip lpadmin plugdev sambashare sudo

[Apport retracing service (apport)]

StacktraceTop:
 file_save (parentWindow=..., doc=0x2817f00, uri=..., key=0x22cb480, checkoverwrite=true, official=true, save_method=Inkscape::Extension::FILE_SAVE_METHOD_SAVE_AS) at file.cpp:638
 sp_file_save_dialog (parentWindow=..., doc=0x2817f00, save_method=Inkscape::Extension::FILE_SAVE_METHOD_SAVE_AS) at file.cpp:861
 sp_action_perform (action=0x281ec40, data=0x0) at helper/action.cpp:181
 closure_invoke_notifiers (notify_type=2, closure=0x3ad05e0) at /build/buildd/glib2.0-2.32.0/./gobject/gclosure.c:273
 _g_closure_invoke_va (closure=0x3ad05e0, return_value=0x0, instance=0x1, args=0x7fff9a55cd10, n_params=32767, param_types=<optimized out>) at /build/buildd/glib2.0-2.32.0/./gobject/gclosure.c:839

[Christopher Kyle Horton (christhehorton)]

Got this crash again when closing Inkscape after saving my file as a .xcf.

[su_v (suv-lp)]

> Got this crash again when closing Inkscape after saving my file as a .xcf.

Testing on OS X 10.7.2:
- Not reproduced with Inkscape 0.48.2: Inkscape quits without crash
- Reproduced with Inkscape 0.48.3.1 and 0.48+devel r11146

[Johan Engelen (johanengelen)]

~suv: can you comment out lines 646 and 647 and see if the crash still happens?
" SP_ACTIVE_DESKTOP->event_log->rememberFileSave();
    SP_ACTIVE_DESKTOP->messageStack()->flash(Inkscape::NORMAL_MESSAGE, _("Document saved."));
"

Thanks.

[Johan Engelen (johanengelen)]

for longer term testing, please try:
if ( SP_ACTIVE_DESKTOP && SP_ACTIVE_DESKTOP->event_log){
    SP_ACTIVE_DESKTOP->event_log->rememberFileSave();
}
if ( SP_ACTIVE_DESKTOP && SP_ACTIVE_DESKTOP->messageStack()) {
    SP_ACTIVE_DESKTOP->messageStack()->flash(Inkscape::NORMAL_MESSAGE, _("Document saved."));
}

[Johan Engelen (johanengelen)]

I've added testing code to trunk, have a go and see if you get any message pointing to this bug when Inkscape crashes.

[jazzynico (jazzynico)]

Reproduced on Ubuntu 11.04, Inkscape trunk revision 11621.
Console message: ** Message: file_save: SP_ACTIVE_DESKTOP == NULL. please report to bug #967416

Full gdb trace attached.

[Johan Engelen (johanengelen)]

It depends on quick timing. When saving the document, control returns to the GUI before the save is complete. If inkscape is closed in that period: crash.

It seems a ton of crashes can happen when the save is still happening while inkscape is closed. The code is not at all ready for multithreading like that.

[Johan Engelen (johanengelen)]

So to fix this, the exit procedure should be able to figure out if some threads are running in the background (the saving thread), and wait for it to start destroying objects.

[Johan Engelen (johanengelen)]

"wait for it to start destroying objects."
wait for it before starting to destroy objects.

[Tavmjong Bah (tavmjong-free)]

This may be a wider problem that just in saving a file. Take a large file (icons.svg) and apply one of the color extensions to one of the icons. There is a high probability of a crash.

[su_v (suv-lp)]

On 2014-06-30 09:53 +0100, Tavmjong Bah wrote:
> This may be a wider problem that just in saving a file. Take a large
> file (icons.svg) and apply one of the color extensions to one of the
> icons. There is a high probability of a crash.

Tracked in:
- Bug 1333445 “various crashes with color extensions”
  <https://bugs.launchpad.net/inkscape/+bug/1333445>

[ScislaC (scislac)]

Someone who can reproduce this: Does it at least emergency save still when it crashes?

[Liam P. White (liampwhite)]

Reproduced with lp:inkscape/experimental r13485.

If you save as XCF and then e.g press Ctrl+Q quickly enough Inkscape will show a message about failed export and then abort. It does not make an emergency save.

#4 0x00000000004c5d26 in Inkscape::DocumentUndo::getUndoSensitive (document=0x25c0ea0) at ../../src/document-undo.cpp:105
#5 0x0000000000761018 in Inkscape::Extension::save (key=0x1d4b3d0, doc=0x25c0ea0, filename=0xb9c27b8 "/home/liam/test/foo.xcf", setextension=false, check_overwrite=true, official=true, save_method=Inkscape::
Extension::FILE_SAVE_METHOD_INKSCAPE_SVG) at ../../src/extension/system.cpp:316
#6 0x00000000004dc7fa in file_save (parentWindow=..., doc=0x25c0ea0, uri=..., key=0x1d4b3d0, checkoverwrite=true, official=true, save_method=Inkscape::Extension::FILE_SAVE_METHOD_INKSCAPE_SVG) at ../../src/file
.cpp:664
#7 0x00000000004dd99d in sp_file_save_dialog (parentWindow=..., doc=0x25c0ea0, save_method=Inkscape::Extension::FILE_SAVE_METHOD_INKSCAPE_SVG) at ../../src/file.cpp:932
#8 0x00000000004dde92 in sp_file_save_document (parentWindow=..., doc=0x25c0ea0) at ../../src/file.cpp:980
#9 0x00000000004de10f in sp_file_save (parentWindow=...) at ../../src/file.cpp:1011

[ScislaC (scislac)]

I was able to reproduce just now as well. Given the lack of emergency save, this is a data loss issue. We could get into nitpicking about "should have saved in svg first", but it's data loss in the end.

[jazzynico (jazzynico)]

Reproduced on Windows XP, Inkscape trunk revision 13528.

But Inkscape opens the '"Do you want to save this file as Inkscape SVG" first, and then crashes if the XCF (or other format) save isn't done.
Scislac, could you please confirm it crashed with no save dialog on your computer?

[Liam P. White (liampwhite)]

@jazzynico

Confirming this behavior

[Bryce Harrington (bryce)]

Do we have a plan for fixing this? Threading bugs can be so tricky...

Would it make sense to have the save routine set a lock when it starts, and then have the exit thread check for existing locks and refuse or delay exiting until they've cleared? Perhaps the lock could be timestamped so that the lock is only honored for, say, 10 seconds (the save routine could re-issue the lock if it expects the save operation to take more time than that.

[Mark Harmer (drivehappy)]

I thought I might take a crack at this since it looked interesting. I apologize for the length, I've added debugging details so hopefully it's clear. I'm new to the codebase and GTK, so I've added a lot so it can be double-checked.

I don't think this is a threading problem. Rather, it looks like a reentrant issue with with running a script. I've attached two full stacktraces that give some more details prior to the actual crash, I reference them below:

The first, stacktrace_remove_desktop.txt, shows the backtrace at the point where the last desktop is destroyed, SP_ACTIVE_DESKTOP is effectively set to NULL.

For brevity I'm posting a snippet:

#0 Inkscape::Application::remove_desktop
#1 sp_desktop_widget_dispose
~snip~
#14 sp_ui_close_all
~snip~
#34 g_main_loop_run
~snip~
#35 Inkscape::Extension::Implementation::Script::execute
#36Inkscape::Extension::Implementation::Script::save
#37 Inkscape::Extension::Output::save
#38 Inkscape::Extension::save
#39 file_save
     at file.cpp:666
#40 sp_file_save_dialog
~snip~
#60 g_main_loop_run
#61 IA__gtk_main
#62 sp_main_gui
#63 __libc_start_main

At this point it starts becoming clear that the Extension::Script::execute has launched another main loop while it waits on the child python script to complete execution, or at least Script::cancelProcessing is called.

I believe the script has not completed, therefore the input handler is run in the "context" of this new main loop, the UI saves and deletes the desktops (including SP_ACTIVE_DESKTOP). At some point the inner g_main_loop_run then returns, and eventually unwinds back to file_save, this then continues and hits the failure at the added debug messages and segfaults when dereferencing in file_save.

I've also added a stacktrace_after_initial_save_xcf.txt where I simply saved to a XCF file, waited a second then grabbed a backtrace to verify that a second g_main_loop was still executing. Again, I'm not familiar enough with GTK, but I suspect this second loop is handling the window events, so it actually appears that the UI thread has returned from the file save and is handling event in the "real" loop, but in fact the stack is still sitting deep within the file_save call.

I think this explains the problems where it happens to only occur when initially saving with certain formats (those that run scripts). I believe it also explains what appeared to be a threading issue since it was not 100% reproducible, actually it's more of a process-race on whether the script can complete before exiting.

I'm not really sure of the fix here, again I'm new to the codebase and I don't know the Extension/Scripts requirements. I'm not entirely sure why there's a need for a Glib::MainLoop in the script - as I would think that any script work would be done in the spawn_async_with_pipes. Or, maybe this intentionally/cleverly hides blocking on the UI thread for script results.

[jazzynico (jazzynico)]

Thanks for your analysis, Mark!

If I understand correctly, checking a "save (or extension) in progress" status before quitting (or destroying the desktop) would fix the issue?

> I'm not entirely sure why there's a need for a Glib::MainLoop in the script

It seems to be used to cancel the running extension.

[Mark Harmer (drivehappy)]

@jazzynico
Thanks, I think that would solve the crash, however some issues come to mind with that solution:
  1. It would introduce some global state, which would be tricky to reason about for anyone not familiar with the specifics. This is particularly complicated since it appears from the code everything is on the same thread.
  2. Other UI actions aside from saving are likely to be affected, any changes in each may silently trigger unsuspecting behavior due to this in the future (this may actually be causing some other bugs after saving as well?)

I didn't mention, but this main_loop can also cause multiple script saves to chain on the call stack: for example, if another save is performed instead of an exit, that save is actually running yet another file_save call (and thus running another g_main_loop_run). At this point there's 3 different entry points on the stack into file_save from the same thread, and although it may technically work, to me it seems brittle.

I think the culprit here is the extra main loop being run in the script, and I think the only clean solution would be to remove it completely. Upon closer investigation I think the only time it's actually stopped (in the context of saving) is if the appropriate file_listeners (stdout, stderr) have read data from the spawned script process. Although there is a Script::cancelProcessing, I think this is only called from an Extension Effect.

Would displaying a dialog window (replacing the _main_loop entirely) here instead work? This should block and the file_listeners and cancellation could then simply close it when completed. I'll see if I can play around with a solution, again my GTK experience is very basic so maybe there's a better approach.

[Johan Engelen (johanengelen)]

I want to remind you all that the majority of Inkscape's code is not at all ready for multithreading. This save code, and all the code and data it needs for saving the document is certainly not thread safe. So the fix is to remove the _main_loop_run stuff, and just do the save right there and then (block on the save, and only continue when it is done).

[Mark Harmer (drivehappy)]

I've attached a proposed patch.

One thing of note is that this actually keeps the Glib::MainLoop, after reading more into it, it appears that a recursive call to running a main loop is supported.

The actual problem is that this was reusing the default MainContext which had all of the original input sources. This patch builds a new MainContext for the new MainLoop, and with each file_listener::init connects the stdout and stderr it to this new context.

This causes the expected blocking UI behavior until the script has completed saving since the new context shouldn't have any other sources. Unfortunately this does cause the UI to appear to be hung until the script completes the save, but given Johan's statement it sounds like it might be a reasonable fix until multithreading can be added.

[Ubuntu Foundations Team Bug Bot (crichton)]

The attachment "bug967416.patch" seems to be a patch. If it isn't, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are a member of the ~ubuntu-reviewers, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issues please contact him.]

[su_v (suv-lp)]

On 2015-01-12 02:38 (+0100), Mark Harmer wrote:
> This causes the expected blocking UI behavior until the script has
> completed saving since the new context shouldn't have any other
> sources. Unfortunately this does cause the UI to appear to be hung
> until the script completes the save, but given Johan's statement it
> sounds like it might be a reasonable fix until multithreading can be
> added.

Somewhat related (UX problem with (script-based) exports which may take very long, without providing the user any kind of feedback about the status):
- Bug #616129 “Progress Dialog for Save As Optimized SVG”
  https://bugs.launchpad.net/inkscape/+bug/616129

[ScislaC (scislac)]

Patch reviewed and tested successfully on Ubuntu Vivid. Fix committed in trunk r14060.

[ScislaC (scislac)]

Will be backporting, please do not adjust milestone.

[su_v (suv-lp)]

On 2015-04-27 18:04 (+0200), ScislaC wrote:
> Will be backporting, please do not adjust milestone.

@ScislaC - is it ok if I backport r14060? AFAICT the diff applies ok (one offset), and I'll run tests later tonight with latest 0.91.x builds.

[su_v (suv-lp)]

Fix from trunk r14060 backported to 0.91.x in rev 13829.