Cannot Open File for Writing

Bug #1928210 reported by snaums
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
SoundConverter
Fix Committed
Critical
Unassigned

Bug Description

I'm converting about 2000 flac-files to mp3. After about 400-500 files, sometimes more, soundconverter crashes with "Cannot open file for Writing" in its logs (see below), also a dialog window pops up and displays the same message. The application hangs and output some gstreamer-errors before crashing out. I am deleting the original files, the problem also occurs after about the same number of files without deleting the source files.

I guess there is a close-call missing and you run into ENFILE or EMFILE, but I am not sure.

I am using Soundconverter 4.0 on Arch Linux.

I've changed the filenames.
```
ERROR: gst-resource-error-quark: Die Ressource konnte nicht zum Schreiben geöffnet werden. (6): 5 filename.flac
converted '1 filename.flac' to '1 filename.mp3'
deleting: '1 filename.flac'
ERROR: gst-resource-error-quark: Die Ressource konnte nicht zum Schreiben geöffnet werden. (6): 6 filename.flac

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.737: gst_poll_get_read_gpollfd: assertion 'set != NULL' failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.738: gst_bus_create_watch: assertion 'bus->priv->poll != NULL' failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.738: Creating bus watch failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.738: Could not add signal watch to bus bus10410

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.739: gst_poll_get_read_gpollfd: assertion 'set != NULL' failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.739: gst_bus_create_watch: assertion 'bus->priv->poll != NULL' failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.739: Creating bus watch failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.739: Could not add signal watch to bus bus10413

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.740: gst_poll_get_read_gpollfd: assertion 'set != NULL' failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.740: gst_bus_create_watch: assertion 'bus->priv->poll != NULL' failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.740: Creating bus watch failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.740: Could not add signal watch to bus bus10416

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.741: gst_poll_get_read_gpollfd: assertion 'set != NULL' failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.742: gst_bus_create_watch: assertion 'bus->priv->poll != NULL' failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.742: Creating bus watch failed

(soundconverter:225141): GStreamer-CRITICAL **: 12:13:33.742: Could not add signal watch to bus bus10419

(soundconverter:225141): GLib-ERROR **: 12:13:33.742: Creating pipes for GWakeup: Zu viele offene Dateien
^C^C^Cfish: Job 1, 'soundconverter' terminated by signal SIGTRAP (Verfolgungs- oder Haltepunkt erreicht)
```

with `--debug`, again I removed the file names.

```
ERROR: ui.py, line 120, gst-resource-error-quark: Die Ressource konnte nicht zum Schreiben geöffnet werden. (6): .flac
DEBUG: converter.py, line 367, .mp3
INFO: converter.py, line 407, converted '.flac' to '.mp3'
INFO: converter.py, line 442, deleting: 'file:///.flac'
DEBUG: converter.py, line 321, launching: 'giosrc location="file:///.flac" name=src ! decodebin name=decoder ! audiorate ! audioconvert ! audioresample ! lamemp3enc encoding-engine-quality=2 target=quality cbr=false quality=0 ! xingmux ! id3mux ! giosink location="file:///.flac_623214_SC_"'
ERROR: ui.py, line 120, gst-resource-error-quark: Die Ressource konnte nicht zum Schreiben geöffnet werden. (6): file.flac
DEBUG: converter.py, line 321, launching: 'giosrc location="file:///.flac" name=src ! decodebin name=decoder ! audiorate ! audioconvert ! audioresample ! lamemp3enc encoding-engine-quality=2 target=quality cbr=false quality=0 ! xingmux ! id3mux ! giosink location="file:///.flac_983381_SC_"'
DEBUG: converter.py, line 321, launching: 'giosrc location="file:///.flac" name=src ! decodebin name=decoder ! audiorate ! audioconvert ! audioresample ! lamemp3enc encoding-engine-quality=2 target=quality cbr=false quality=0 ! xingmux ! id3mux ! giosink location="file:///.flac_362721_SC_"'

//..

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.161: gst_poll_get_read_gpollfd: assertion 'set != NULL' failed

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.161: gst_bus_create_watch: assertion 'bus->priv->poll != NULL' failed

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.161: Creating bus watch failed

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.161: Could not add signal watch to bus bus5614
DEBUG: converter.py, line 321, launching: 'giosrc location="file:///...flac" name=src ! decodebin name=decoder ! audiorate ! audioconvert ! audioresample ! lamemp3enc encoding-engine-quality=2 target=quality cbr=false quality=0 ! xingmux ! id3mux ! giosink location="file:///...flac_556567_SC_"'

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.163: gst_poll_get_read_gpollfd: assertion 'set != NULL' failed

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.163: gst_bus_create_watch: assertion 'bus->priv->poll != NULL' failed

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.163: Creating bus watch failed

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.163: Could not add signal watch to bus bus5617
DEBUG: converter.py, line 321, launching: 'giosrc location="file:///file%20%28Deluxe%20Mix%29.flac" name=src ! decodebin name=decoder ! audiorate ! audioconvert ! audioresample ! lamemp3enc encoding-engine-quality=2 target=quality cbr=false quality=0 ! xingmux ! id3mux ! giosink location="file:///file__Deluxe_Mix_.flac_712597_SC_"'

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.165: gst_poll_get_read_gpollfd: assertion 'set != NULL' failed

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.165: gst_bus_create_watch: assertion 'bus->priv->poll != NULL' failed

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.165: Creating bus watch failed

(soundconverter:230564): GStreamer-CRITICAL **: 12:58:54.165: Could not add signal watch to bus bus5620

(soundconverter:230564): GLib-ERROR **: 12:58:54.165: Creating pipes for GWakeup: Zu viele offene Dateien
fish: Job 1, 'soundconverter --debug' terminated by signal SIGTRAP (Verfolgungs- oder Haltepunkt erreicht)
```

Revision history for this message
sezanzeb (sezanzeb) wrote :

I'm not observing fds that are not being closed in /proc. As soundconverter finishes off its running tasks the number of open fds there is being reduced on my system. Is that the case for you as well?

I also think closing and opening files would be gstreamers job, since soundconverter is really just creating pipelines for gstreamer to execute.

The error might originate from here: https://github.com/kassoulet/soundconverter/blob/py3k/soundconverter/gstreamer/converter.py#L545 which stops the whole pipeline. Maybe soundconverter should continue converting and ignore that error?

Revision history for this message
GautierPortet (kassoulet) wrote :

Someone reported the same issue by email. For now I did not managed to reproduce it.

Changed in soundconverter:
status: New → Confirmed
importance: Undecided → Critical
Revision history for this message
GautierPortet (kassoulet) wrote :

OK so we really have an open file leakage here.
This after ~500 successful conversions:

[...]
converted '/data/Music/Local/Scene/bitjam/bitjam_127/17-H0ffmann-Jay Step.mp3' to '/data/tmp/Music/Local/Scene/bitjam/bitjam_127/17-H0ffmann-Jay Step.m4a'
converted '/data/Music/Local/Scene/bitjam/bitjam_127/18-2irritated - hear me-Hear Me.mp3' to '/data/tmp/Music/Local/Scene/bitjam/bitjam_127/18-2irritated - hear me-Hear Me.m4a'
ERROR: gst-resource-error-quark: Could not open resource for writing. (6): /data/Music/Local/Scene/bitjam/bitjam_128.mp3
converted '/data/Music/Local/Scene/bitjam/bitjam_127/19-Vincenzo-Ancient Dreams.mp3' to '/data/tmp/Music/Local/Scene/bitjam/bitjam_127/19-Vincenzo-Ancient Dreams.m4a'
ERROR: gst-resource-error-quark: Could not open resource for writing. (6): /data/Music/Local/Scene/bitjam/bitjam_129.mp3
ERROR: gst-resource-error-quark: Could not open resource for reading. (5): /data/Music/Local/Scene/bitjam/bitjam_127/21-tEiS-Jingle (Outro).mp3
converted '/data/Music/Local/Scene/bitjam/bitjam_127/20-KEiTO (Unreleased)-Keep Praying.mp3' to '/data/tmp/Music/Local/Scene/bitjam/bitjam_127/20-KEiTO (Unreleased)-Keep Praying.m4a'
ERROR: gst-resource-error-quark: Could not open resource for writing. (6): /data/Music/Local/Scene/bitjam/bitjam_130.mp3
^C
(soundconverter:107694): GLib-ERROR **: 22:55:00.752: Creating pipes for GWakeup: Too many open files
^C^C./run: line 1: 107694 Trace/breakpoint trap (core dumped) soundconverter "$@"

But as sezanzeb noticed: we do not actually open read/write the files...

Revision history for this message
sezanzeb (sezanzeb) wrote :

Correction: I think soundconverter is actually supposed to continue converting. _on_error calls the callback which continues the taskqueue. So ignoring errors is not an solution, I guess it freezes up because it is unable to create another gstreamer pipeline due to the file limit.

Revision history for this message
sezanzeb (sezanzeb) wrote :

It would be interesting to know if this bug appeared with a new gstreamer version. I'll try converting lots of files as well and will post my gstreamer version later.

What is your version?

Revision history for this message
sezanzeb (sezanzeb) wrote :

Running a conversion multiple times increases the number of fds in /proc.

Most of them are sockets, like

lrwx------ 1 mango mango 64 14. Mai 23:11 142 -> 'socket:[53142]'
lrwx------ 1 mango mango 64 14. Mai 23:11 145 -> 'socket:[72208]'
lrwx------ 1 mango mango 64 14. Mai 23:11 146 -> 'socket:[72209]'
lrwx------ 1 mango mango 64 14. Mai 23:11 149 -> 'socket:[53143]'
lrwx------ 1 mango mango 64 14. Mai 23:11 150 -> 'socket:[53144]'

by 34 for 17 files, so 2 socket fds for each pipeline.

Is something missing in _cleanup maybe?

Revision history for this message
sezanzeb (sezanzeb) wrote :

found the bug, going to make a PR later

Revision history for this message
sezanzeb (sezanzeb) wrote :

https://github.com/kassoulet/soundconverter/pull/52

> "I'm not observing fds that are not being closed in /proc"

genius false observation. The number of fds is decreasing after conversions, but there are some leftover each time.

I guess maybe we should notify the debian maintainer of soundconverter to pull the fix or whatever they have to do?

Changed in soundconverter:
milestone: none → 4.0.1
status: Confirmed → Fix Committed
Revision history for this message
GautierPortet (kassoulet) wrote :

I will release a new version asap.

Revision history for this message
snaums (snaums) wrote :

Thank you all for your work!

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers