Bug 1686367 - Useless warnings and errors on the console
Summary: Useless warnings and errors on the console
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: spice-gtk
Version: 29
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Default Assignee for SPICE Bugs
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-03-07 10:48 UTC by Christophe de Dinechin
Modified: 2019-11-27 23:10 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-11-27 23:10:26 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Christophe de Dinechin 2019-03-07 10:48:20 UTC
Description of problem:

When using virt-viewer under normal conditions, a large number of rather annoying warnings are emitted, ranging from information about connections to failed assertions.

Version-Release number of selected component (if applicable):
virt-viewer.x86_64                      7.0-1.fc29                       @fedora
spice-glib.x86_64                        0.35-3.fc29                    @fedora 
spice-gtk3.x86_64                        0.35-3.fc29                    @fedora 
spice-protocol.noarch                    0.12.15-1.fc29                 @updates
spice-server.x86_64                      0.14.1-2.fc29                  @updates
spice-vdagent.x86_64                     0.18.0-2.fc29                  @fedora 

How reproducible: Always


Steps to Reproduce:
1. Run virt-viewer on a guest
2. Look at the console
3. There is no step 3

Actual results:

A spew of messages, e.g.:

(virt-viewer:6229): GSpice-WARNING **: 10:45:34.323: PulseAudio context failed Connection refused

(virt-viewer:6229): GSpice-WARNING **: 10:45:34.323: pa_context_connect() failed: Connection refused
AL lib: (WW) alc_initconfig: Failed to initialize backend "pulse"
AL lib: (EE) ALCplaybackAlsa_open: Could not open playback device 'default': Connection refused
AL lib: (WW) alcSetError: Error generated on device (nil), code 0xa005

(virt-viewer:6229): GLib-GObject-CRITICAL **: 10:45:35.801: g_object_get: assertion 'G_IS_OBJECT (object)' failed

(virt-viewer:6229): GLib-GObject-CRITICAL **: 10:45:35.801: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
AL lib: (EE) ALCplaybackAlsa_open: Could not open playback device 'default': Connection refused
AL lib: (WW) alcSetError: Error generated on device (nil), code 0xa005

(virt-viewer:6229): GLib-GObject-CRITICAL **: 10:45:36.393: g_object_get: assertion 'G_IS_OBJECT (object)' failed

(virt-viewer:6229): GLib-GObject-CRITICAL **: 10:45:36.393: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
AL lib: (EE) ALCplaybackAlsa_open: Could not open playback device 'default': Connection refused
AL lib: (WW) alcSetError: Error generated on device (nil), code 0xa005
AL lib: (EE) ALCcaptureAlsa_open: Could not open capture device 'default': Connection refused
AL lib: (WW) alcSetError: Error generated on device (nil), code 0xa004

(virt-viewer:6229): GLib-GObject-CRITICAL **: 10:45:36.599: g_object_set: assertion 'G_IS_OBJECT (object)' failed

(virt-viewer:6229): GLib-GObject-CRITICAL **: 10:45:36.599: g_object_unref: assertion 'G_IS_OBJECT (object)' failed

(virt-viewer:6229): GLib-GObject-CRITICAL **: 10:45:36.600: g_object_unref: assertion 'G_IS_OBJECT (object)' failed

(virt-viewer:6229): GSpice-WARNING **: 10:45:36.600: gst lacks volume capabilities on src

(virt-viewer:6229): GLib-GObject-CRITICAL **: 10:45:36.600: g_object_unref: assertion 'G_IS_OBJECT (object)' failed

(virt-viewer:6229): GSpice-WARNING **: 10:45:36.600: gst lacks mute capabilities on src: 0

(virt-viewer:6229): GLib-GObject-CRITICAL **: 10:45:36.600: g_object_unref: assertion 'G_IS_OBJECT (object)' failed

(virt-viewer:6229): GSpice-WARNING **: 10:45:36.649: Warning no automount-inhibiting implementation available

(virt-viewer:6229): GSpice-WARNING **: 10:45:41.934: keyboard grab failed 1

(virt-viewer:6229): GSpice-WARNING **: 10:45:41.939: keyboard grab failed 1

(virt-viewer:6229): GSpice-WARNING **: 10:45:47.865: keyboard grab failed 4

(virt-viewer:6229): GSpice-WARNING **: 10:46:02.623: keyboard grab failed 4


Expected results:

No messages, or if any message, messages that are actually informative to the user and show a path of action. For example: "PulseAudio context failed" is a developer-only message.


Additional info:

Suggestions:

1. log these messages somewhere in case a developer wants to see them, but do not send them to the console.

2. add a menu entry in virt-viewer to see the log.

3. Think about a general mechanism for SPICE to report errors to the higher level. Some messages might deserve a UI-level warning, e.g. a little red rectangle at the bottom of the viewer window stating "No audio available - Please click here for information on troubleshooting" that would open an URL explaining possible reasons and solutions. (In my case it's most likely because I was running it over X11).

4. Get rid of the assertions that have been failing forever. Either the code is robust to them, or we should address them. But for an end-user, "assertion 'G_IS_OBJECT (object)' failed" is really annoying if not worrisome.

Comment 1 Christophe Fergeau 2019-03-07 11:27:10 UTC
I'm not seeing any of these messages on my f29 installation, any idea if there is anything special on your system regarding sound, pulseaudio, ...?

Comment 2 Christophe de Dinechin 2019-05-06 16:16:09 UTC
(In reply to Christophe Fergeau from comment #1)
> I'm not seeing any of these messages on my f29 installation, any idea if
> there is anything special on your system regarding sound, pulseaudio, ...?

I do not see anything really special. I see the problem irrespective of the system used (i.e. I see it on Fedora, RHEL and macOS, and on machines that range from standard issue Lenovo laptop to desktops).

For an example of some of the messages, see https://drive.google.com/drive/folders/1QVkMygPSCmfqB_1sxfUUs30kpv-9BlzR around 2:50. It's not very visible since I did my best to hide it in the demos. That was with a Lenovo "standard issue" laptop running Fedora. What could block pulseaudio in that case is that the machine I connected to was remote, I was using `ssh -Y` to connect to it.

When connecting virt-viewer to a local system, I have less warnings, typically "Warning no automount inhibiting implementation available" and that's about it.

Comment 3 Christophe de Dinechin 2019-05-06 16:19:13 UTC
Connecting to a Windows 10 VM over `ssh -Y` with macOS XQuartz client shows:

(virt-viewer:24771): GSpice-WARNING **: 18:12:02.535: PulseAudio context failed Connection refused

(virt-viewer:24771): GSpice-WARNING **: 18:12:02.535: pa_context_connect() failed: Connection refused

but then nothing else.

So I don't think macOS makes things any worse, the message looks very similar.

Comment 4 Christophe de Dinechin 2019-05-06 16:20:03 UTC
Connecting to a Windows 10 VM over `ssh -Y` with macOS XQuartz client shows:

(virt-viewer:24771): GSpice-WARNING **: 18:12:02.535: PulseAudio context failed Connection refused

(virt-viewer:24771): GSpice-WARNING **: 18:12:02.535: pa_context_connect() failed: Connection refused

but then nothing else.

So I don't think macOS makes things any worse, the message looks very similar.

Comment 5 Victor Toso 2019-05-07 05:47:48 UTC
> Suggestions:
> 1. log these messages somewhere in case a developer wants to see them, but do not send them to the console.

Where would you log them? We use glib logging API for portability and since 2.50 they have support to journal
for instance, which I think is nice. I've been waiting a loong time to get to 2.50 as requirement and we are
probably close now, after next release.

> 2. add a menu entry in virt-viewer to see the log.

I would rather store a virt-viewer.log file somewhere but that should be doable already by redirecting the
stdout/stderr

> 3. Think about a general mechanism for SPICE to report errors to the higher level. Some messages might deserve
> a UI-level warning, e.g. a little red rectangle at the bottom of the viewer window stating "No audio available
> - Please click here for information on troubleshooting" that would open an URL explaining possible reasons and
> solutions. (In my case it's most likely because I was running it over X11).

Yes. I have the same thing in mind for some time too. This could also be related to protocol capabilities which is
not really an error from development perspective but an user might get confused why a feature is not working with
one VM and it is with similar one.

> 4. Get rid of the assertions that have been failing forever. Either the code is robust to them, or we should
> address them. But for an end-user, "assertion 'G_IS_OBJECT (object)' failed" is really annoying if not
> worrisome.

Asserts/warnings, helps a lot with the different environments, X11/Wayland, GNOME/KDE/etc, Windows/Linux,
audio with GStreamer/Pulseaudio, etc. Some of those warnings/asserts should have been fixed upstream AFAIR but if
not, just keep bugging us on them :)

Comment 6 Victor Toso 2019-05-07 05:57:00 UTC
(In reply to Christophe de Dinechin from comment #2)
> What could block pulseaudio in that case is that the machine I connected to was
> remote, I was using `ssh -Y` to connect to it.

Yes, the biggest amount of test we have in our code is to user in the local desktop
acessing remote or local VMs. For example, if you run spice client as root or the user privileges
are different than a normal user in local machine, you are more likely to see session related
warnings.

We could improve console related output, improve UI, but functionality would still not work and
it needs to be visible, console is what we use nowadays.

I'd move this bug upstream as I'm not sure this belongs to Fedora.

Comment 7 Christophe de Dinechin 2019-05-07 09:37:44 UTC
(In reply to Victor Toso from comment #5)
> > Suggestions:
> > 1. log these messages somewhere in case a developer wants to see them, but do not send them to the console.
> 
> Where would you log them?

That does not matter much, as long as it's not on the console, where they are annoying and most likely lost (i.e. not available to automatic bug report collection tools).

Logging to the console is desirable if someone requests it. It could be as simple as an effect of -v option.

> We use glib logging API for portability and since 2.50 they have support to journal for instance, which I think is nice. I've been waiting a loong time to get to 2.50 as requirement and we are probably close now, after next release.

journald would be a good option on Linux. Does not work on other platforms though.

g_log_set_handler seems to predate 2.50, so that could be a fallback both for non-Linux and pre-2.50.


> 
> > 2. add a menu entry in virt-viewer to see the log.
> 
> I would rather store a virt-viewer.log file somewhere but that should be
> doable already by redirecting the
> stdout/stderr

If SPICE has been systematic enough in using glib logging. So g_log_set_handler might be better than redirecting stdout / stderr.
This would keep stderr available for user-oriented messages.

Consider for example:

(virt-viewer:6229): GSpice-WARNING **: 10:45:34.323: PulseAudio context failed Connection refused
(virt-viewer:6229): GSpice-WARNING **: 10:45:34.323: pa_context_connect() failed: Connection refused
AL lib: (WW) alc_initconfig: Failed to initialize backend "pulse"
AL lib: (EE) ALCplaybackAlsa_open: Could not open playback device 'default': Connection refused
AL lib: (WW) alcSetError: Error generated on device (nil), code 0xa005

The first two lines are clearly formatted for a log. A regular user does not care much about pid or time stamps.
The last three lines are even worse in terms of being developer-oriented. But they may indicate that indeed, stderr redirection might be necessary.

In any case, if you redirect stderr, it might be useful to preserve the original fd to be able to emit user-oriented messages.

> 
> > 3. Think about a general mechanism for SPICE to report errors to the higher level. Some messages might deserve
> > a UI-level warning, e.g. a little red rectangle at the bottom of the viewer window stating "No audio available
> > - Please click here for information on troubleshooting" that would open an URL explaining possible reasons and
> > solutions. (In my case it's most likely because I was running it over X11).
> 
> Yes. I have the same thing in mind for some time too. This could also be
> related to protocol capabilities which is
> not really an error from development perspective but an user might get
> confused why a feature is not working with
> one VM and it is with similar one.

Agreed. This is why you should give users a feedback that is relevant to them.

For the above it might be something like:

Warning: Sound is disabled because no suitable sound device were found.
         (you can find more information in /var/log/virt-viewer.log)


> 
> > 4. Get rid of the assertions that have been failing forever. Either the code is robust to them, or we should
> > address them. But for an end-user, "assertion 'G_IS_OBJECT (object)' failed" is really annoying if not
> > worrisome.
> 
> Asserts/warnings, helps a lot with the different environments, X11/Wayland,
> GNOME/KDE/etc, Windows/Linux,
> audio with GStreamer/Pulseaudio, etc. Some of those warnings/asserts should
> have been fixed upstream AFAIR but if
> not, just keep bugging us on them :)

Obviously I was not advocating against having assertions, but against having them failing in such a scarily visible way ;-)

Good news that you think they have been fixed. As indicated in a previous comment, this bug was filed following my experience doing demos for RHEL8. At the time, I thought I would have time to look into this myself and fix it. How naive I was ;-)

Comment 8 Christophe de Dinechin 2019-05-07 09:46:37 UTC
(In reply to Victor Toso from comment #6)
> (In reply to Christophe de Dinechin from comment #2)
> > What could block pulseaudio in that case is that the machine I connected to was
> > remote, I was using `ssh -Y` to connect to it.
> 
> Yes, the biggest amount of test we have in our code is to user in the local
> desktop
> acessing remote or local VMs. For example, if you run spice client as root
> or the user privileges
> are different than a normal user in local machine, you are more likely to
> see session related
> warnings.
> 
> We could improve console related output, improve UI, but functionality would
> still not work and
> it needs to be visible, console is what we use nowadays.

I tried to clarify in my previous comment that I don't want things to fail silently, I only suggest to make an effort to reserve the console for user-sanitized messages, and move the scary asserts and hexadecimal gobbledygook for log files or -v / SPICE_DEBUG output.

> 
> I'd move this bug upstream as I'm not sure this belongs to Fedora.

I've not really validated on non-Fedora hosts.

Am I correct that the most active upstream bug list at the moment is https://gitlab.freedesktop.org/spice/spice-gtk/issues? Others like https://bugs.freedesktop.org/buglist.cgi?component=spice-gtk&product=Spice&resolution=--- make a pretty convincing imitation of deadness.

Comment 9 Ben Cotton 2019-10-31 18:59:07 UTC
This message is a reminder that Fedora 29 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora 29 on 2019-11-26.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
Fedora 'version' of '29'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 29 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 10 Ben Cotton 2019-11-27 23:10:26 UTC
Fedora 29 changed to end-of-life (EOL) status on 2019-11-26. Fedora 29 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.


Note You need to log in before you can comment on or make changes to this bug.