Bug 100064 - HDMI output source not remembered
Summary: HDMI output source not remembered
Status: RESOLVED MOVED
Alias: None
Product: PulseAudio
Classification: Unclassified
Component: misc (show other bugs)
Version: unspecified
Hardware: Other All
: medium normal
Assignee: pulseaudio-bugs
QA Contact: pulseaudio-bugs
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-03-05 09:21 UTC by Martin Ejdestig
Modified: 2018-07-30 10:32 UTC (History)
1 user (show)

See Also:
i915 platform:
i915 features:


Attachments
pulseverbose.log (339.72 KB, text/plain)
2017-03-05 14:46 UTC, Martin Ejdestig
Details
pulseverbose.log.1 (95.80 KB, text/plain)
2017-03-05 14:47 UTC, Martin Ejdestig
Details
pulseverbose.log.2 (354.34 KB, text/plain)
2017-03-05 14:47 UTC, Martin Ejdestig
Details
pulseverbose.log.3 (96.55 KB, text/plain)
2017-03-05 14:47 UTC, Martin Ejdestig
Details
0001-switch-on-port-available-avoid-switching-away-from-p.patch (2.59 KB, patch)
2017-03-05 17:33 UTC, Tanu Kaskinen
Details | Splinter Review
pulseverbose-patch1.log (316.70 KB, text/plain)
2017-03-06 16:37 UTC, Martin Ejdestig
Details
Debug patch and logs (53.08 KB, application/x-xz)
2017-03-06 17:56 UTC, Martin Ejdestig
Details
0001-more-logging.patch (3.16 KB, patch)
2017-03-07 17:22 UTC, Tanu Kaskinen
Details | Splinter Review
Log with 0001-more-logging.patch applied (348.28 KB, text/x-log)
2017-03-08 18:45 UTC, Martin Ejdestig
Details
Log with 0001-more-logging.patch applied for second pulseaudio process (100.91 KB, text/plain)
2017-03-09 17:27 UTC, Martin Ejdestig
Details

Description Martin Ejdestig 2017-03-05 09:21:02 UTC
I am running PulseAudio 10.0 with GNOME on an up to date Arch installation. I have three monitors connected; 1 displayport, 1 HDMI and 1 DVI.

I have a GTX 970 so I mostly use the proprietary Nvidia drivers.

User A on the system uses the displayport and DVI monitors and has selected "Line Out - Built-in Audio" in the sound settings of GNOME control center.

User B on the system only uses the HDMI monitor and wants sound coming out of the monitor so "HDMI / DisplayPort 3 - GM204..." is selected in the sound settings of GNOME control center.

I normally use User A, but when I login as user B I always have to open GNOME's control center and reselect "HDMI / Displayport 3" because it has been reset to "Line Out - Built-in Audio".

It does not seem to matter if I logout user A before I login as user B.
Comment 1 Tanu Kaskinen 2017-03-05 12:59:21 UTC
Does the output device get reset also if you just restart pulseaudio while logged in as B?
Comment 2 Martin Ejdestig 2017-03-05 13:51:19 UTC
Nope. Killing the "pulseaudio" process while logged in as B and letting it respawn does not seem to reset the output device to "Line Out".
Comment 3 Tanu Kaskinen 2017-03-05 14:10:31 UTC
Ok. Let's try to figure out what happens during the logout-login cycle. Add these lines to ~/.config/pulse/daemon.conf (for the B user):

log-target = newfile:/tmp/pulseverbose.log
log-level = debug
log-time = yes

That will make pulseaudio generate log files in /tmp. There will be one file per started pulseaudio instance.

First restart pulseaudio so that the new configuration takes effect. Then set the output device to hdmi if it's not set so already. Then log out. Before logging back in, wait for a bit, because I think the user instance of systemd for user B won't be immediately terminated, and it will be reused if you log in too quickly. When logging back in, check that the output device has changed to line out. There should now be two logs in /tmp. Attach them to this bug, and I'll try to figure out what happens.
Comment 4 Martin Ejdestig 2017-03-05 14:46:52 UTC
Created attachment 130071 [details]
pulseverbose.log
Comment 5 Martin Ejdestig 2017-03-05 14:47:19 UTC
Created attachment 130072 [details]
pulseverbose.log.1
Comment 6 Martin Ejdestig 2017-03-05 14:47:36 UTC
Created attachment 130073 [details]
pulseverbose.log.2
Comment 7 Martin Ejdestig 2017-03-05 14:47:52 UTC
Created attachment 130074 [details]
pulseverbose.log.3
Comment 8 Martin Ejdestig 2017-03-05 14:48:09 UTC
As user A (my main desktop user) I su:ed to user B and created the config file. Verified that no user B process was running as user A, VT switched to GDM and logged in as user B.

When logged in as user B, I went to GNOME's control center to verify that output was set to "Line Out", set it to "HDMI" again and logged out.

I then VT switched from GDM to user A and verified that log files had been written (pulseverbose.log and pulseverbose.log.1) and that no user B process was still running.

I then VT swithed to GDM again and logged in as user B and noticed same behaviour as previous login. Logged out and VT switched from GDM to user A. Now pulseverbose.log.2 and pulseverbose.log.3 had also been created.
Comment 9 Martin Ejdestig 2017-03-05 15:54:18 UTC
Do not know if this is related to my problems, but why are log.1 and log.3 created? .log and .log.2 seems to be the "real" logs. Something tries to spawn an extra pulseaudio instance when user B logs in?
Comment 10 Tanu Kaskinen 2017-03-05 16:23:13 UTC
That's weird indeed.

The second instance removes the pid file:

W: [pulseaudio] pid.c: Stale PID file, overwriting.

If the pid file was created by the first instance, the second instance should have at this point noticed that a daemon was already running. Now the second instance determined that there's no other daemon running. This can happen if kill(pid, 0) fails. When passing 0 as the signal, no signal will be sent by kill(), but permission checks are done, so maybe pulseaudio doesn't have the permission to send any signals.

Immediately after starting, the second instance receives SIGTERM. What's sending that signal? It looks like a controlled start-stop sequence, so I would guess that systemd is doing this. I don't have any idea why, though. Does the systemd journal have any strange stuff in it about starting pulseaudio?

I don't know if this is related to the routing problem. It seems possible that the second instance messes something up, but I haven't yet studied the logs in detail.
Comment 11 Tanu Kaskinen 2017-03-05 16:47:35 UTC
At one point something makes HDMI 2 change state from unavailable to available, and module-switch-on-available will then switch the HDMI card to the HDMI 2 profile. You want to keep using HDMI 3, however. When you switched to HDMI 3 earlier, pulseaudio saved your preference, but it seems that the preference is not being consulted when considering what to do when HDMI 2 becomes available.

This should be pretty easy to fix: just don't switch to HDMI 2 if you've previously selected HDMI 3 and it's still available.
Comment 12 Martin Ejdestig 2017-03-05 16:48:08 UTC
If I run journalctl --user I see this for first login of user B:

mar 05 15:31:41 gromit pulseaudio[31127]: ICE default IO error handler doing an exit(), pid = 31127, errno = 32
mar 05 15:31:41 gromit systemd[31045]: pulseaudio.service: Main process exited, code=exited, status=1/FAILURE
mar 05 15:31:41 gromit systemd[31045]: pulseaudio.service: Unit entered failed state.
mar 05 15:31:41 gromit systemd[31045]: pulseaudio.service: Failed with result 'exit-code'
...
mar 05 15:31:41 gromit systemd[31045]: pulseaudio.service: Service hold-off time over, scheduling restart.
mar 05 15:31:41 gromit systemd[31045]: Stopped Sound Service.
mar 05 15:31:41 gromit systemd[31045]: Starting Sound Service...

I see the same thing for the second time when B logs in.
Comment 13 Martin Ejdestig 2017-03-05 16:51:14 UTC
(In reply to Tanu Kaskinen from comment #11)
> This should be pretty easy to fix: just don't switch to HDMI 2 if you've
> previously selected HDMI 3 and it's still available.

Hum, but "Line Out" is selected, not HDMI 2.
Comment 14 Tanu Kaskinen 2017-03-05 16:56:57 UTC
Yes, but when switching the card profile, the HDMI 3 sink becomes unavailable. The HDMI 3 sink was previously selected as the default sink by you, but now there's no sink that's explicitly selected as the default. In this situation the analog output sink becomes the default. Switching the HDMI card profile to HDMI 2 doesn't imply setting the HDMI 2 sink as the default. Complicated, I know...
Comment 15 Martin Ejdestig 2017-03-05 16:59:43 UTC
OK. :)

(Also, probably not relevant any longer then since you seem to understand the problem, but the time stamps in the journalctl --user output above is close to when the user logs out (as far as I can tell by looking at the system wide journal).)
Comment 16 Tanu Kaskinen 2017-03-05 17:33:30 UTC
Created attachment 130075 [details] [review]
0001-switch-on-port-available-avoid-switching-away-from-p.patch

Here's an untested patch. Are you able to try it out? It's hard for me to test it, because I don't have similar hardware.
Comment 17 Martin Ejdestig 2017-03-05 18:11:40 UTC
Thank you!

I have applied it on a local branch but will have to build and test tomorrow (I am being forcibly removed from the computer ;) .

I looked quickly on the home page and in the repo for instruction on how to test but did not find any. Maybe I overlooked it. What is the easiest way for me to make sure the custom build is started when I log in with user B after I have built the branch?
Comment 19 Martin Ejdestig 2017-03-06 16:36:34 UTC
The patch does not seem to work. Will attach new log soon.

> I hope this is helpful:

I was mainly looking for how to not have to do "make install" as root (once bitten...).

Configured with:

CFLAGS="-g -O0" ./configure --prefix=$HOME/Desktop/Temp/usr --sysconfdir=$HOME/Desktop/Temp/etc --localstatedir=$HOME/Desktop/Temp/var --with-udev-rules-dir=$HOME/Desktop/Temp/lib/udev/rules.d --with-systemduserunitdir=$HOME/Desktop/Temp/usr/lib/systemd/user --enable-force-preopen

installed and overrode the pulseaudio.service ExecStart line by running "systemctl --user edit pulseaudio":

I can see that the binary executed in user B's session is the one in $HOME/Desktop/Temp/usr . I assume modules in $HOME/Desktop/Temp/usr are preferred to the system installed ones. :)
Comment 20 Martin Ejdestig 2017-03-06 16:37:42 UTC
Created attachment 130091 [details]
pulseverbose-patch1.log
Comment 21 Tanu Kaskinen 2017-03-06 17:05:05 UTC
(In reply to Martin Ejdestig from comment #19)
> The patch does not seem to work. Will attach new log soon.

The new log looks fine, the HDMI card profile doesn't any more get changed from HDMI 3 to HDMI 2. Do you still observe the same behaviour as before?
Comment 22 Martin Ejdestig 2017-03-06 17:11:55 UTC
Yupp, same behavior. I was just about to retest after adding some pa_log_debug() statements to the patch. Maybe that is not useful if you think the log looks fine?
Comment 23 Martin Ejdestig 2017-03-06 17:46:57 UTC
I tested a bit with pa_log_debug():s sprinkled everywhere and it seems like port is NULL in is_preferred_port_active_and_available() so it returns false.

Once out of my 5 test runs it did work however. port was not NULL and switch_to_port() was not called.
Comment 24 Martin Ejdestig 2017-03-06 17:56:14 UTC
Created attachment 130092 [details]
Debug patch and logs

Patch that adds pa_log_debug() and logs. pulseverbose.log.2 is log for when it worked.
Comment 25 Tanu Kaskinen 2017-03-07 17:22:15 UTC
Created attachment 130114 [details] [review]
0001-more-logging.patch

When preferred_output_port is set, it should be remembered. The logs don't show it becoming unset at any point, which makes me think that when pulseaudio starts, the variable doesn't get restored (except when it randomly does get restored?). I made a patch that will hopefully shed more light on what happens during the startup. Please apply it and send logs again (since this seems to be a bit random, it's probably good to try several times again).
Comment 26 Martin Ejdestig 2017-03-08 18:45:37 UTC
Created attachment 130130 [details]
Log with 0001-more-logging.patch applied

Attached log with 0001-more-logging.patch applied.

Was not able get a log of when it works after trying ~10 times.
Comment 27 Martin Ejdestig 2017-03-08 19:01:36 UTC
> Was not able get a log of when it works after trying ~10 times.

I have only ever seen it working once though (the one time mentioned above) so would probably have to try _a lot_ more to see it again.

Looking at the latest log though...:

"foobar - alsa_card.pci-0000_01_00.1: Storing preferred_output_port = (null) in the database."

Old config is overwritten at start for some reason?
Comment 28 Tanu Kaskinen 2017-03-08 19:28:18 UTC
Is that message from an "extra" pulseaudio instance? When you sent the package with 8 logs, every other of them were from those extra pulseaudio instances that shut down immediately after starting up.

The rest of this comment was written before your last comment:

It looks like the preferred_output_port is saved in the database, but then it magically is unset again when the database is later loaded.

I suspect that the "extra" pulseaudio instance overwrites the database. Things might happen like this:

Instance 1 (the "real" instance) starts.

You change the output to HDMI 3, and preferred_output_port is written to the database, but the database is not written on disk yet (there's a 10 second delay).

You initiate logout.

Instance 2 (the "extra" instance) starts (you mentioned that it seems to start around the time you log out). The database file that instance 2 reads doesn't yet contain the update.

Instance 1 exits and writes the database on disk. The update is now on the disk.

Instance 2 exits and writes the database on disk. The update is now lost, because instance 2 was not aware of the update.

If instance 2 always starts when you log out, you could try waiting for at least 10 seconds before logging out after changing the output to HDMI 3. The theory is that the extra instance will then read the up-to-date database, and not overwrite it with old data.

Also, you mentioned that you saw this in the journal:

ICE default IO error handler doing an exit(), pid = 31127, errno = 32

According to the internet[1], you can get rid of that error by deleting ~/.ICEauthority. Perhaps that will stop the extra pulseaudio instance from starting? (I find that unlikely, though.)

[1] https://stackoverflow.com/questions/20621070/ice-default-io-error-handler-doing-an-exit-pid-11281-errno-4#22038069
Comment 29 Tanu Kaskinen 2017-03-08 19:40:01 UTC
(In reply to Tanu Kaskinen from comment #28)
> Is that message from an "extra" pulseaudio instance? When you sent the
> package with 8 logs, every other of them were from those extra pulseaudio
> instances that shut down immediately after starting up.

Sorry, I misunderstood what you meant. The message you mentioned is from the log that you attached. Good catch - I didn't notice myself this strange thing. If the configuration overwritten during startup, then that would indeed explain the behaviour.
Comment 30 Tanu Kaskinen 2017-03-08 19:46:44 UTC
Hmm, no, it doesn't explain the problem. Please ignore the previous comment (comment #29). That message is printed after the card is already created. The database is read at an earlier stage, and at that time the read value was null.
Comment 31 Martin Ejdestig 2017-03-09 17:14:47 UTC
(In reply to Tanu Kaskinen from comment #28)
> I suspect that the "extra" pulseaudio instance overwrites the database.
> Things might happen like this:
> 
> Instance 1 (the "real" instance) starts.
> 
> You change the output to HDMI 3, and preferred_output_port is written to the
> database, but the database is not written on disk yet (there's a 10 second
> delay).
> 
> You initiate logout.
> 
> Instance 2 (the "extra" instance) starts (you mentioned that it seems to
> start around the time you log out). The database file that instance 2 reads
> doesn't yet contain the update.
> 
> Instance 1 exits and writes the database on disk. The update is now on the
> disk.
> 
> Instance 2 exits and writes the database on disk. The update is now lost,
> because instance 2 was not aware of the update.

I do not think this is the case. I think systemd spawns the extra instance as a result of the first instance terminating. In the journal output in comment 12 you can see "Main process exited" first and then "Starting Sound Service...". 

So it does not look like two pulseaudio instances are running at the same time. The timestamps for when this happens is during logout though. The timestamps in the user journal that looks like in comment 12 matches "Stopped User Manager" timestamps in the system wide journal. 

> If instance 2 always starts when you log out, you could try waiting for at
> least 10 seconds before logging out after changing the output to HDMI 3. The
> theory is that the extra instance will then read the up-to-date database,
> and not overwrite it with old data.

Looking at the latest log I can see:

(  21.405|   0.000) D: [pulseaudio] module-card-restore.c: foobar - alsa_card.pci-0000_01_00.1: Storing preferred_output_port = hdmi-output-2 in the database.

and:

(  36.710|   3.415) D: [pulseaudio] module-x11-xsmp.c: Got die message from XSMP.

~14s between db write and logout? I tried a couple of times more just now and waited >> 10s but same result.

> Also, you mentioned that you saw this in the journal:
> 
> ICE default IO error handler doing an exit(), pid = 31127, errno = 32
> 
> According to the internet[1], you can get rid of that error by deleting
> ~/.ICEauthority. Perhaps that will stop the extra pulseaudio instance from
> starting? (I find that unlikely, though.)

Yeah, did not help.

But I think systemd correctly restarts pulseaudio after the first instance exits since it exits with a non zero exit code (see comment 12) and "Restart" is set to "on-failure" in the service file. I have no idea why though.
Comment 32 Martin Ejdestig 2017-03-09 17:24:50 UTC
Btw, why are there two stores? One with null and one with hdmi-output-2.

(  21.405|   0.000) I: [pulseaudio] module-card-restore.c: Storing profile hdmi-stereo-extra2 for port hdmi-output-2 on card alsa_card.pci-0000_01_00.1.
(  21.405|   0.000) D: [pulseaudio] module-card-restore.c: foobar - alsa_card.pci-0000_01_00.1: Storing preferred_output_port = (null) in the database.
(  21.405|   0.000) D: [pulseaudio] card.c: alsa_card.pci-0000_01_00.1: preferred_output_port: (unset) -> hdmi-output-2
(  21.405|   0.000) D: [pulseaudio] module-card-restore.c: foobar - alsa_card.pci-0000_01_00.1: Storing preferred_output_port = hdmi-output-2 in the database.
Comment 33 Martin Ejdestig 2017-03-09 17:27:00 UTC
Created attachment 130148 [details]
Log with 0001-more-logging.patch applied for second pulseaudio process

In the log for the second process it looks like it reads correctly and then stores "null" directly after at startup. Or?

(   0.513|   0.000) D: [pulseaudio] module-card-restore.c: foobar - alsa_card.pci-0000_01_00.1: e->preferred_output_port = hdmi-output-2
(   0.513|   0.000) D: [pulseaudio] module-card-restore.c: foobar - port not found
(   0.513|   0.000) D: [pulseaudio] card.c: alsa_card.pci-0000_01_00.1: preferred_output_port = (unset) (pa_card_new)
(   0.513|   0.000) D: [pulseaudio] module-alsa-card.c: Found 1 jacks.
(   0.513|   0.000) I: [pulseaudio] alsa-util.c: Unable to attach to mixer hw:1: No such file or directory
(   0.513|   0.000) E: [pulseaudio] module-alsa-card.c: Failed to open mixer for jack detection
(   0.513|   0.000) D: [pulseaudio] module-card-restore.c: Tried to restore profile output:hdmi-stereo-extra2 for card alsa_card.pci-0000_01_00.1, but the card doesn't have such profile.
(   0.513|   0.000) I: [pulseaudio] card.c: Created 0 "alsa_card.pci-0000_01_00.1"
(   0.513|   0.000) I: [pulseaudio] module-card-restore.c: Storing port latency offsets for card alsa_card.pci-0000_01_00.1.
(   0.513|   0.000) D: [pulseaudio] module-card-restore.c: foobar - alsa_card.pci-0000_01_00.1: Storing preferred_output_port = (null) in the database.
Comment 34 Tanu Kaskinen 2017-03-09 22:13:18 UTC
Ok, now we're getting a bit forward. These messages give a clue:

(   0.513|   0.000) D: [pulseaudio] module-card-restore.c: foobar - alsa_card.pci-0000_01_00.1: e->preferred_output_port = hdmi-output-2
(   0.513|   0.000) D: [pulseaudio] module-card-restore.c: foobar - port not found

So a port named hdmi-output-2 was not found when trying to restore the preferred output port. There were problems when probing the card. The first profile (HDMI 1) worked:

(   0.039|   0.000) D: [pulseaudio] alsa-mixer.c: Looking at profile output:hdmi-stereo
(   0.039|   0.000) D: [pulseaudio] alsa-mixer.c: Checking for playback on Digital Stereo (HDMI) (hdmi-stereo)
(   0.039|   0.000) D: [pulseaudio] alsa-util.c: Trying hdmi:1 with SND_PCM_NO_AUTO_FORMAT ...
(   0.040|   0.000) D: [pulseaudio] alsa-util.c: Managed to open hdmi:1
(   0.040|   0.000) D: [pulseaudio] alsa-util.c: Maximum hw buffer size is 23777 ms
(   0.139|   0.099) D: [pulseaudio] alsa-util.c: Set buffer size first (to 4408 samples), period size second (to 1102 samples).
(   0.139|   0.000) D: [pulseaudio] alsa-mixer.c: Profile output:hdmi-stereo supported.

The rest of the hdmi profiles fail, however. Here's the output for HDMI 3:

(   0.510|   0.000) D: [pulseaudio] alsa-mixer.c: Looking at profile output:hdmi-stereo-extra2
(   0.510|   0.000) D: [pulseaudio] alsa-mixer.c: Checking for playback on Digital Stereo (HDMI 3) (hdmi-stereo-extra2)
(   0.510|   0.000) D: [pulseaudio] alsa-util.c: Trying hdmi:1,2 with SND_PCM_NO_AUTO_FORMAT ...
(   0.510|   0.000) I: [pulseaudio] (alsa-lib)confmisc.c: cannot find card '1'
(   0.510|   0.000) I: [pulseaudio] (alsa-lib)conf.c: function snd_func_card_driver returned error: No such file or directory
(   0.510|   0.000) I: [pulseaudio] (alsa-lib)confmisc.c: error evaluating strings
(   0.510|   0.000) I: [pulseaudio] (alsa-lib)conf.c: function snd_func_concat returned error: No such file or directory
(   0.510|   0.000) I: [pulseaudio] (alsa-lib)confmisc.c: error evaluating name
(   0.510|   0.000) I: [pulseaudio] (alsa-lib)conf.c: function snd_func_refer returned error: No such file or directory
(   0.510|   0.000) I: [pulseaudio] (alsa-lib)conf.c: Evaluate error: No such file or directory
(   0.510|   0.000) I: [pulseaudio] (alsa-lib)pcm.c: Unknown PCM hdmi:1,2
(   0.510|   0.000) I: [pulseaudio] alsa-util.c: Error opening PCM device hdmi:1,2: No such file or directory
(   0.510|   0.000) D: [pulseaudio] alsa-mixer.c: Caching failure to open output:hdmi-stereo-extra2

I'm not sure if this a driver bug, or normal behaviour when logging out.

(In reply to Martin Ejdestig from comment #31)
> But I think systemd correctly restarts pulseaudio after the first instance
> exits since it exits with a non zero exit code (see comment 12) and
> "Restart" is set to "on-failure" in the service file. I have no idea why
> though.

Good observation. Now that I look at the log of the first instance again, the shutdown sequence is clearly not complete, so it's not a clean shutdown, which explains the non-zero return value. Is pulseaudio crashing? Or does it get a kill signal? The journal seems to claim that the process returns exit code 1, which is not true in case of a crash or kill (AFAIK there's no exit code at all in those cases). PulseAudio shouldn't call exit(1) by itself. I suspect some of the X libraries does that.
Comment 35 Tanu Kaskinen 2017-03-09 23:52:05 UTC
(In reply to Tanu Kaskinen from comment #34)
> PulseAudio shouldn't call exit(1) by itself. I suspect some of the X libraries
> does that.

I forgot that the journal actually tells that quite clearly:

mar 05 15:31:41 gromit pulseaudio[31127]: ICE default IO error handler doing an exit(), pid = 31127, errno = 32

The exit seems to be happening in pa__done() of src/modules/x11/module-x11-xsmp.c. Does removing the IceRemoveConnectionWatch() call fix things?
Comment 36 Martin Ejdestig 2017-03-14 16:06:19 UTC
(In reply to Tanu Kaskinen from comment #35)
> The exit seems to be happening in pa__done() of
> src/modules/x11/module-x11-xsmp.c. Does removing the
> IceRemoveConnectionWatch() call fix things?

Commenting out IceRemoveConnectionWatch() does not help. It seems to exit before that.

Backtrace from attaching to pulseaudio and logging out:

#0  0x00007f9f7d0f4f1d in write () from /usr/lib/libpthread.so.0
#1  0x00007f9f7e1f4928 in ?? () from /usr/lib/libICE.so.6
#2  0x00007f9f7e1f8fe8 in _IceWrite () from /usr/lib/libICE.so.6
#3  0x00007f9f7e1f90c4 in IceFlush () from /usr/lib/libICE.so.6
#4  0x00007f9f7dfe6540 in SmcCloseConnection () from /usr/lib/libSM.so.6
#5  0x00007f9f85634ded in module_x11_xsmp_LTX_pa__done (m=0x202ee20) at modules/x11/module-x11-xsmp.c:232
#6  0x00007f9f7fdc8968 in pa_module_free (m=0x202ee20) at pulsecore/module.c:250
#7  0x00007f9f7fdc8b1b in pa_module_unload (m=0x202ee20, force=true) at pulsecore/module.c:285
#8  0x00007f9f7fdc909e in defer_cb (api=0x1fbbba8, e=0x203bed0, userdata=0x1fbd720) at pulsecore/module.c:350
#9  0x00007f9f7f754fc9 in dispatch_defer (m=0x1fbbb50) at pulse/mainloop.c:680
#10 0x00007f9f7f755b9f in pa_mainloop_dispatch (m=0x1fbbb50) at pulse/mainloop.c:889
#11 0x00007f9f7f755d67 in pa_mainloop_iterate (m=0x1fbbb50, block=1, retval=0x7fff1d887b54) at pulse/mainloop.c:929
#12 0x00007f9f7f755dc7 in pa_mainloop_run (m=0x1fbbb50, retval=0x7fff1d887b54) at pulse/mainloop.c:944
#13 0x000000000042902e in main (argc=2, argv=0x7fff1d887d28) at daemon/main.c:1142
Comment 37 Martin Ejdestig 2017-03-14 16:10:36 UTC
When testing this I also noticed another thing. I managed to get output switched back to "Line Out" for user B by just VT-switching. I did not capture logs for that though. But... maybe... best to just try to handle one thing at a time (i.e. get logging out/in working first and worry about VT-switching later :) .
Comment 38 Martin Ejdestig 2017-03-14 16:13:52 UTC
Oh, sorry. Forgot to mention that it is due to SIGPIPE:

Thread 1 "pulseaudio" received signal SIGPIPE, Broken pipe.
0x00007f9f7d0f4f1d in write () from /usr/lib/libpthread.so.0
(gdb) bt
#0  0x00007f9f7d0f4f1d in write () from /usr/lib/libpthread.so.0
< rest of backtrace, see comment 36 >
Comment 39 Martin Ejdestig 2017-03-14 16:27:14 UTC
Commenting out both SmcCloseConnection() and IceRemoveConnectionWatch() just makes pulseaudio exit at a later point. Keep in mind that I have no idea what I am doing here. :) (I know _nothing_ about X session handling and ICE etc.)

Have set breakpoints on exit() and _exit():

Thread 1 "pulseaudio" hit Breakpoint 2, 0x00007f452299a700 in exit () from /usr/lib/libc.so.6
(gdb) bt
#0  0x00007f452299a700 in exit () from /usr/lib/libc.so.6
#1  0x00007f45245360fa in ?? () from /usr/lib/libICE.so.6
#2  0x00007f452453bee4 in _IceRead () from /usr/lib/libICE.so.6
#3  0x00007f452454015f in IceProcessMessages () from /usr/lib/libICE.so.6
#4  0x00007f452b977656 in ice_io_cb (a=0xbc6ba8, e=0xc81130, fd=42, flags=(PA_IO_EVENT_INPUT | PA_IO_EVENT_HANGUP), userdata=0xc4c110) at modules/x11/module-x11-xsmp.c:90
#5  0x00007f4525a97e8a in dispatch_pollfds (m=0xbc6b50) at pulse/mainloop.c:655
#6  0x00007f4525a98bea in pa_mainloop_dispatch (m=0xbc6b50) at pulse/mainloop.c:898
#7  0x00007f4525a98d67 in pa_mainloop_iterate (m=0xbc6b50, block=1, retval=0x7ffcb1834c14) at pulse/mainloop.c:929
#8  0x00007f4525a98dc7 in pa_mainloop_run (m=0xbc6b50, retval=0x7ffcb1834c14) at pulse/mainloop.c:944
#9  0x000000000042902e in main (argc=2, argv=0x7ffcb1834de8) at daemon/main.c:1142
(gdb) c
Continuing.

Thread 4 "alsa-sink-HDMI " received signal SIGCONT, Continued.
[Switching to Thread 0x7f451bbbc700 (LWP 11414)]
0x00007f4522a4676b in ppoll () from /usr/lib/libc.so.6
(gdb) c
Continuing.
[Switching to Thread 0x7f4534d068c0 (LWP 11247)]

Thread 1 "pulseaudio" hit Breakpoint 2, 0x00007f452299a700 in exit () from /usr/lib/libc.so.6
(gdb) c
Continuing.

Thread 1 "pulseaudio" hit Breakpoint 1, 0x00007f4522a1e830 in _exit () from /usr/lib/libc.so.6
(gdb) c
Continuing.
[Thread 0x7f451b3bb700 (LWP 11249) exited]
[Thread 0x7f4534d068c0 (LWP 11247) exited]
[Inferior 1 (process 11247) exited with code 01]
(gdb)
Comment 40 Tanu Kaskinen 2017-04-23 15:51:03 UTC
I see it's been more than a month without a reply. I'm sorry, I forgot about this bug...

ice_io_cb() could have a codition that if flags contains PA_IO_EVENT_HANGUP like it does in this situation, then don't call IceProcessMessages().

But since the original reason for adding the hacks in the module code was to see if the profile switching starts to work properly, I think it's better to just not load module-x11-xsmp at all. If your system uses systemd or consolekit, the xsmp module isn't useful anyway, because module-systemd-logind or module-console-kit already do the job of module-x11-xsmp (which is to keep pulseaudio running for the duration of the login session). The module is loaded by /usr/bin/start-pulseaudio-x11 during the X session startup, so you'll need to modify start-pulseaudio-x11 so that it doesn't load module-x11-xsmp.

I wonder if we could remove module-x11-xsmp from start-pulseaudio-x11 upstream. It's not necessary for most Linux systems, but maybe other operating systems benefit from it? It's not clear to me how to fix the module so that we could be sure that the X11 libraries don't call exit() while also making sure that the session management and ICE connections get cleaned up properly.
Comment 41 Tanu Kaskinen 2017-04-23 17:06:01 UTC
Now I remember why I didn't earlier suggest removing module-x11-xsmp: it doesn't only keep pulseaudio running, it's also required for telling the other X11 modules to unload themselves when X11 shuts down.

I suggest you to comment out also module-x11-publish and module-x11-cork-request from /usr/bin/start-pulseaudio-x11 (after which the script will do basically nothing, but that's fine).
Comment 42 Martin Ejdestig 2017-05-13 18:03:21 UTC
Indeed, commenting out module-x11-publish and module-x11-xsmp (module-x11-cork-request was already commented out... on Arch) makes everything behave as expected (HDMI source is remembered).

Do not like that I have to edit a script in /usr/bin though. :(
Comment 43 GitLab Migration User 2018-07-30 10:32:31 UTC
-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/494.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.