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

Remote bug watches

Bug watches keep track of this bug in other bug trackers.