Sink volume not restored correctly after unmuting

Compiled from master (0b81314b).

Running

pactl set-sink-mute @DEFAULT_SINK@ 1
pactl set-sink-mute @DEFAULT_SINK@ 0

causes the restored volume to be less than it was originally. Setting the volume to the same level (e.g. pressing the slider-head of the GNOME volume slider) restores the expected volume.

There is no (relevant) difference between the output of pw-dump before and after running the previous commands.

git-bisect points to 5bf21444 as the first bad commit.

pipewire log

// setting the volume to approximately the same value as the current volume
[D][000162289.006583][pulse-server.c:5427 handle_packet()] pulse-server 0x616000001880: Received packet command 36 tag 23
[I][000162289.006649][pulse-server.c:3143 do_set_volume()] pulse-server 0x616000001880: [GNOME Shell Volume Control] SET_SINK_VOLUME tag:23 index:46 name:(null)
[I][000162289.006849][volume.c:49 volume_compare()] 0: val 0.150683<>0.154856
[D][000162289.006938][manager.c:86 core_sync()] sync start 1073741985
[D][000162289.006960][pulse-server.c:345 operation_new()] pulse-server 0x613000000ac0: operation tag:23
[D][000162289.006996][pulse-server.c:5427 handle_packet()] pulse-server 0x616000001880: Received packet command 36 tag 24
[I][000162289.007018][pulse-server.c:3143 do_set_volume()] pulse-server 0x616000001880: [GNOME Shell Volume Control] SET_SINK_VOLUME tag:24 index:46 name:(null)
[I][000162289.007084][volume.c:49 volume_compare()] 0: val 0.150683<>0.154856
[D][000162289.007123][manager.c:86 core_sync()] sync start 1073741987
[D][000162289.007141][pulse-server.c:345 operation_new()] pulse-server 0x613000000ac0: operation tag:24
[D][000162289.007293][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 1
[D][000162289.007340][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[I][000162289.007506][acp.c:1806 acp_device_set_volume()] Set hardware volume: 35193
[D][000162289.007549][acp.c:1808 acp_device_set_volume()]   0: 35193
[D][000162289.007567][acp.c:1808 acp_device_set_volume()]   1: 35193
[D][000162289.007715][acp.c:1078 set_volume()] Requested volume: 35193
[D][000162289.007746][acp.c:1079 set_volume()] Got hardware volume: 35263
[D][000162289.007768][acp.c:1080 set_volume()] Calculated software volume: 65406 (accurate-enough=yes)
[I][000162289.007793][alsa-acp-device.c:803 on_volume_changed()] device analog-stereo volume changed
flags:00000000 n_items:34
  object.path = "alsa:pcm:0"
  device.api = "alsa:pcm"
  media.class = "Audio/Device"
  api.alsa.path = "hw:0"
  device.enum.api = "udev"
  device.api = "alsa"
  media.class = "Audio/Device"
  api.alsa.path = "hw:0"
  api.alsa.card = "0"
  api.alsa.card.name = "HDA Intel PCH"
  api.alsa.card.longname = "HDA Intel PCH at 0xae810000 irq 166"
  device.plugged.usec = "3812329"
  device.bus-path = "pci-0000:00:1f.3"
  device.sysfs.path = "/sys/devices/pci0000:00/0000:00:1f.3/sound/card0"
  device.bus = "pci"
  device.subsystem = "sound"
  device.vendor.id = "0x8086"
  device.vendor.name = "Intel Corporation"
  device.product.id = "0xa348"
  device.product.name = "Cannon Lake PCH cAVS"
  device.form-factor = "internal"
  device.name = "alsa_card.pci-0000_00_1f.3"
  device.description = "Built-in Audio"
  device.nick = "HDA Intel PCH"
  device.icon-name = "audio-card-pci"
  api.alsa.use-acp = "true"
  api.acp.auto-profile = "false"
  api.acp.auto-port = "false"
  api.dbus.ReserveDevice1 = "Audio0"
  alsa.card = "0"
  alsa.card_name = "HDA Intel PCH"
  alsa.long_card_name = "HDA Intel PCH at 0xae810000 irq 166"
  alsa.driver_name = "snd_hda_intel"
  device.string = "0"
[D][000162289.008665][impl-device.c:732 device_info()] device 0x61b000002a80: flags:00000000 change_mask:00000004
[D][000162289.008711][impl-device.c:747 device_info()] device 0x61b000002a80: param 0 id:8 (Spa:Enum:ParamId:EnumProfile) 00000002:00000002
[D][000162289.008738][impl-device.c:747 device_info()] device 0x61b000002a80: param 1 id:9 (Spa:Enum:ParamId:Profile) 00000007:00000007
[D][000162289.008761][impl-device.c:747 device_info()] device 0x61b000002a80: param 2 id:12 (Spa:Enum:ParamId:EnumRoute) 00000003:00000003
[D][000162289.008782][impl-device.c:747 device_info()] device 0x61b000002a80: param 3 id:13 (Spa:Enum:ParamId:Route) 00000007:00000006
[D][000162289.008801][impl-device.c:755 device_info()] device 0x61b000002a80: update param 13
[D][000162289.008877][impl-device.c:706 emit_params()] device 0x61b000002a80: emit 1 params
[D][000162289.008904][impl-device.c:458 result_device_done()] device 0x61b000002a80: async result 0 1073742007 (1073742006/1073742007)
[D][000162289.008954][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 0
[D][000162289.008977][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162289.009045][impl-node.c:496 node_set_param()] node 0x61d000021280: resource 0x615000013400 set param id:2 (Spa:Enum:ParamId:Props) 00000000
[D][000162289.009072][audioadapter.c:418 impl_node_set_param()] audioadapter 0x7f7d1332e828: set param 2
[D][000162289.009101][channelmix.c:255 remap_volumes()] 0 0: 3 <-> 3
[D][000162289.009118][channelmix.c:255 remap_volumes()] 1 1: 4 <-> 4
[D][000162289.009137][channelmix-ops.c:456 impl_channelmix_set_volume()] volume:1.000000 mute:0 n_volumes:2
[D][000162289.009160][channelmix-ops.c:461 impl_channelmix_set_volume()] 0: 1.000000 * 1.000000 = 1.000000
[D][000162289.009179][channelmix-ops.c:461 impl_channelmix_set_volume()] 1: 1.000000 * 1.000000 = 1.000000
[D][000162289.009198][channelmix-ops.c:487 impl_channelmix_set_volume()] 0 0: 1.000000
[D][000162289.009215][channelmix-ops.c:487 impl_channelmix_set_volume()] 0 1: 0.000000
[D][000162289.009231][channelmix-ops.c:487 impl_channelmix_set_volume()] 1 0: 0.000000
[D][000162289.009247][channelmix-ops.c:487 impl_channelmix_set_volume()] 1 1: 1.000000
[D][000162289.009265][channelmix-ops.c:502 impl_channelmix_set_volume()] flags:0000000a
[D][000162289.009287][impl-node.c:1318 node_info()] node 0x61d000021280: flags:00000019 change_mask:00000004 max_in:64 max_out:0
[D][000162289.009310][impl-node.c:1341 node_info()] node 0x61d000021280: param 0 id:3 (Spa:Enum:ParamId:EnumFormat) 00000002:00000002
[D][000162289.009330][impl-node.c:1341 node_info()] node 0x61d000021280: param 1 id:1 (Spa:Enum:ParamId:PropInfo) 00000003:00000003
[D][000162289.009349][impl-node.c:1341 node_info()] node 0x61d000021280: param 2 id:2 (Spa:Enum:ParamId:Props) 00000006:00000007
[D][000162289.009368][impl-node.c:1349 node_info()] node 0x61d000021280: update param 2
[D][000162289.009384][impl-node.c:1341 node_info()] node 0x61d000021280: param 3 id:4 (Spa:Enum:ParamId:Format) 00000006:00000006
[D][000162289.009402][impl-node.c:1341 node_info()] node 0x61d000021280: param 4 id:10 (Spa:Enum:ParamId:EnumPortConfig) 00000002:00000002
[D][000162289.009422][impl-node.c:1341 node_info()] node 0x61d000021280: param 5 id:11 (Spa:Enum:ParamId:PortConfig) 00000006:00000006
[D][000162289.009488][impl-node.c:280 emit_params()] node 0x61d000021280: emit 1 params
[D][000162289.009585][module-protocol-native.c:1109 do_resume()] flush
[D][000162289.009607][media-session.c:493 device_event_info()] media-session 0x7ffef740e950: device 41 info
[D][000162289.009644][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 1
[D][000162289.009664][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162289.009649][manager.c:299 device_event_info()] object 0x613000003a00: id:41 change-mask:00000002
[D][000162289.009689][media-session.c:519 device_event_info()] media-session 0x7ffef740e950: device 41 enum params 13 seq:1073742401
[D][000162289.009720][proxy.c:320 pw_proxy_sync()] proxy 0x60c000019180: 42 seq:1 sync 1073742402
[D][000162289.009742][media-session.c:1168 sm_object_sync_update()] sync 0x617000001278 proxy 0x60c000019180 1073742402
[D][000162289.009751][manager.c:419 node_event_info()] object 0x613000003f40: id:46 change-mask:00000010
[D][000162289.009775][media-session.c:601 node_event_info()] media-session 0x7ffef740e950: node 46 info
[D][000162289.009799][manager.c:86 core_sync()] sync start 1073741986
[D][000162289.009812][media-session.c:628 node_event_info()] media-session 0x7ffef740e950: node 46 enum params 2 seq:1073742404
[D][000162289.009842][proxy.c:320 pw_proxy_sync()] proxy 0x616000006c80: 38 seq:1 sync 1073742405
[D][000162289.009857][media-session.c:1168 sm_object_sync_update()] sync 0x616000006cf8 proxy 0x616000006c80 1073742405
[D][000162289.009871][manager.c:299 device_event_info()] object 0x613000007200: id:41 change-mask:00000002
[D][000162289.009919][manager.c:419 node_event_info()] object 0x613000007740: id:46 change-mask:00000010
[D][000162289.009948][manager.c:86 core_sync()] sync start 1073741990
[I][000162289.009946][acp.c:1806 acp_device_set_volume()] Set hardware volume: 35193
[D][000162289.009942][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162289.009993][acp.c:1808 acp_device_set_volume()]   0: 35193
[D][000162289.010006][manager.c:299 device_event_info()] object 0x613000014cc0: id:41 change-mask:00000002
[D][000162289.010026][acp.c:1808 acp_device_set_volume()]   1: 35193
[D][000162289.010041][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 1
[D][000162289.010064][manager.c:419 node_event_info()] object 0x613000015200: id:46 change-mask:00000010
[D][000162289.010070][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162289.010109][manager.c:86 core_sync()] sync start 1073742012
[D][000162289.010132][acp.c:1078 set_volume()] Requested volume: 35193
[D][000162289.010135][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162289.010167][acp.c:1079 set_volume()] Got hardware volume: 35263
[D][000162289.010180][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000002180: busy 1
[D][000162289.010192][acp.c:1080 set_volume()] Calculated software volume: 65406 (accurate-enough=yes)
[D][000162289.010210][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162289.010302][impl-device.c:458 result_device_done()] device 0x61b000002a80: async result 0 1073742009 (1073742008/1073742009)
[D][000162289.010328][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 0
[D][000162289.010345][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162289.010372][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742009 (1073742010/1073742011)
[D][000162289.010392][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742009 (1073742012/1073742013)
[D][000162289.010427][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162289.010458][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000007280: busy 1
[D][000162289.010475][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162289.010521][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742010 (1073742010/1073742011)
[D][000162289.010540][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162289.010571][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162289.010625][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742010 (1073742012/1073742013)
[D][000162289.010645][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742010 (1073742014/1073742015)
[D][000162289.010666][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742010 (1073742010/1073742011)
[D][000162289.010684][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162289.010706][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162289.010725][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742010 (1073742012/1073742013)
[D][000162289.010743][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742010 (1073742014/1073742015)
[D][000162289.010763][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742011 (1073742010/1073742011)
[D][000162289.010796][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 0
[D][000162289.010812][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162289.010837][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742011 (1073742012/1073742013)
[D][000162289.010856][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742011 (1073742014/1073742015)
[D][000162289.010877][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742012 (1073742012/1073742013)
[D][000162289.010895][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162289.010919][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162289.010939][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742012 (1073742014/1073742015)
[D][000162289.010960][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742012 (1073742012/1073742013)
[D][000162289.010978][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162289.010999][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162289.011017][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742012 (1073742014/1073742015)
[D][000162289.011037][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742013 (1073742012/1073742013)
[D][000162289.011059][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000002180: busy 0
[D][000162289.011076][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162289.011098][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742013 (1073742014/1073742015)
[D][000162289.011168][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:1
[D][000162289.011195][impl-device.c:345 pw_impl_device_for_each_param()] device 0x61b000002a80: 1073741988 param 45
[D][000162289.011213][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162289.011236][impl-device.c:345 pw_impl_device_for_each_param()] device 0x61b000002a80: 1073741988 param 46
[D][000162289.011252][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162289.011278][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000021280 enum params seq:1073741989 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162289.011303][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:0
[D][000162289.011329][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073741989 id:2
[D][000162289.011393][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000021280 reply param 1073741989
[D][000162289.011426][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073741989 id:2
[D][000162289.011477][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000021280 reply param 1073741989
[D][000162289.011504][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073741989 id:2
[D][000162289.011583][module-protocol-native.c:1109 do_resume()] flush
[D][000162289.011618][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742014 (1073742014/1073742015)
[D][000162289.011638][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162289.011665][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162289.011736][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742014 (1073742014/1073742015)
[D][000162289.011735][manager.c:86 core_sync()] sync start 1073741991
[D][000162289.011757][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162289.011777][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162289.011797][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742015 (1073742014/1073742015)
[D][000162289.011824][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000007280: busy 0
[D][000162289.011841][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162289.011886][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000013400 enum params seq:1073742404 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162289.011910][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162289.011933][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742404 param 21
[D][000162289.012240][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000013400 reply param 1073742404
[D][000162289.012300][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742404 param 22
[D][000162289.012319][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000013400 reply param 1073742404
[D][000162289.012361][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x61500001ed00 enum params seq:1073741985 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162289.012383][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162289.012404][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073741985 param 21
[D][000162289.012421][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x61500001ed00 reply param 1073741985
[D][000162289.012444][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073741985 param 22
[D][000162289.012461][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x61500001ed00 reply param 1073741985
[D][000162289.012514][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000023800 enum params seq:1073742011 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162289.012536][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162289.012556][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742011 param 21
[D][000162289.012574][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000023800 reply param 1073742011
[D][000162289.012597][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742011 param 22
[D][000162289.012614][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000023800 reply param 1073742011
[D][000162289.012675][module-protocol-native.c:1109 do_resume()] flush
[D][000162289.012716][manager.c:670 on_core_done()] sync end 1073741991/1073741991
[D][000162289.012762][pulse-server.c:574 manager_sync()] pulse-server 0x613000000ac0: manager sync
[I][000162289.012789][pulse-server.c:359 operation_complete()] pulse-server 0x613000000ac0: [GNOME Shell Volume Control] tag:23 complete
[D][000162289.012794][media-session.c:536 device_event_param()] media-session 0x7ffef740e950: device 0x617000001278 param 13 index:0 seq:1073742401
[D][000162289.012817][pulse-server.c:295 reply_new()] pulse-server 0x613000000ac0: REPLY tag:23
[D][000162289.012855][media-session.c:536 device_event_param()] media-session 0x7ffef740e950: device 0x617000001278 param 13 index:8 seq:1073742401
[I][000162289.012861][pulse-server.c:359 operation_complete()] pulse-server 0x613000000ac0: [GNOME Shell Volume Control] tag:24 complete
[D][000162289.012886][pulse-server.c:295 reply_new()] pulse-server 0x613000000ac0: REPLY tag:24
[D][000162289.012895][media-session.c:1115 done_proxy()] done 0x617000001278 proxy 0x60c000019180 avail:0000070c update:00000300 1073742402/1073742402
[D][000162289.012930][pulse-server.c:399 send_subscribe_event()] pulse-server 0x613000000ac0: SUBSCRIBE event:00000010 id:46
[D][000162289.012929][alsa-monitor.c:823 device_update()] device 0x6120000022c0 appeared 1 0
[D][000162289.012964][default-profile.c:366 object_update()] default-profile 0x60d0000001e0: device 0x60d000004cc0 00000300/0000070c
[D][000162289.012963][pulse-server.c:399 send_subscribe_event()] pulse-server 0x613000000ac0: SUBSCRIBE event:00000011 id:65582
[I][000162289.013004][default-profile.c:270 handle_active_profile()] device 'alsa_card.pci-0000_00_1f.3': active profile 'output:analog-stereo+input:analog-stereo'
[I][000162289.013074][default-profile.c:305 handle_profile_switch()] device 'alsa_card.pci-0000_00_1f.3': found best profile 'output:analog-stereo+input:analog-stereo' changed:0
[I][000162289.013095][default-profile.c:344 handle_profile_switch()] device 'alsa_card.pci-0000_00_1f.3': no profile switch needed
[D][000162289.013113][default-routes.c:805 object_update()] default-routes 0x60d0000002b0: device 0x60e0000013a0 00000300/0000070c
[I][000162289.013162][default-routes.c:727 handle_route()] device 41: port 'analog-input-internal-mic'
[I][000162289.013183][default-routes.c:727 handle_route()] device 41: port 'analog-output-speaker'
[D][000162289.013180][manager.c:86 core_sync()] sync start 1073741987
[I][000162289.013298][default-routes.c:502 save_route()] device 41: route properties changed default.route.alsa_card.pci-0000_00_1f.3:output:analog-output-speaker { "mute": false, "volumes": [ 0.154856, 0.154856 ], "channels": [ "FL", "FR" ] }
[D][000162289.013326][manager.c:86 core_sync()] sync start 1073742013
[D][000162289.013346][system.c:174 impl_timerfd_create()] system 0x60c0000001e8: new fd:33
[D][000162289.013448][manager.c:670 on_core_done()] sync end 1073741987/1073741987
[D][000162289.013469][pulse-server.c:574 manager_sync()] pulse-server 0x613000000900: manager sync
[I][000162289.013460][default-routes.c:546 save_profile()] device 41: profile output:analog-stereo+input:analog-stereo unchanged ([ "analog-output-speaker" ])


// mute
[D][000162292.389145][pulse-server.c:5427 handle_packet()] pulse-server 0x616000001880: Received packet command 39 tag 25
[I][000162292.389217][pulse-server.c:3209 do_set_mute()] pulse-server 0x616000001880: [GNOME Volume Control Media Keys] SET_SINK_MUTE tag:25 index:46 name:(null) mute:1
[D][000162292.389521][manager.c:86 core_sync()] sync start 1073741989
[D][000162292.389566][pulse-server.c:345 operation_new()] pulse-server 0x613000000900: operation tag:25
[D][000162292.389666][pulse-server.c:1020 send_command_request()] pulse-server 0x617000001900: REQUEST channel:0 16384
[D][000162292.389780][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 1
[D][000162292.389839][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[I][000162292.390010][acp.c:1853 acp_device_set_mute()] Set hardware mute: 1
[I][000162292.390469][alsa-acp-device.c:841 on_mute_changed()] device analog-stereo mute changed
flags:00000000 n_items:34
  object.path = "alsa:pcm:0"
  device.api = "alsa:pcm"
  media.class = "Audio/Device"
  api.alsa.path = "hw:0"
  device.enum.api = "udev"
  device.api = "alsa"
  media.class = "Audio/Device"
  api.alsa.path = "hw:0"
  api.alsa.card = "0"
  api.alsa.card.name = "HDA Intel PCH"
  api.alsa.card.longname = "HDA Intel PCH at 0xae810000 irq 166"
  device.plugged.usec = "3812329"
[D][000162292.390897][pulse-server.c:5468 handle_memblock()] pulse-server 0x616000001880: Received memblock channel:0 offset:0 flags:00000000 size:16384
  device.bus-path = "pci-0000:00:1f.3"
  device.sysfs.path = "/sys/devices/pci0000:00/0000:00:1f.3/sound/card0"
[D][000162292.390951][pulse-server.c:5479 handle_memblock()] new block 0x6060000086c0 0x62d00006e400/16384 filled:60416 index:2624512 flags:00 offset:0
  device.bus = "pci"
  device.subsystem = "sound"
  device.vendor.id = "0x8086"
  device.vendor.name = "Intel Corporation"
  device.product.id = "0xa348"
  device.product.name = "Cannon Lake PCH cAVS"
  device.form-factor = "internal"
  device.name = "alsa_card.pci-0000_00_1f.3"
  device.description = "Built-in Audio"
  device.nick = "HDA Intel PCH"
  device.icon-name = "audio-card-pci"
  api.alsa.use-acp = "true"
  api.acp.auto-profile = "false"
  api.acp.auto-port = "false"
  api.dbus.ReserveDevice1 = "Audio0"
  alsa.card = "0"
  alsa.card_name = "HDA Intel PCH"
  alsa.long_card_name = "HDA Intel PCH at 0xae810000 irq 166"
  alsa.driver_name = "snd_hda_intel"
  device.string = "0"
[D][000162292.391637][impl-device.c:732 device_info()] device 0x61b000002a80: flags:00000000 change_mask:00000004
[D][000162292.391676][impl-device.c:747 device_info()] device 0x61b000002a80: param 0 id:8 (Spa:Enum:ParamId:EnumProfile) 00000002:00000002
[D][000162292.391701][impl-device.c:747 device_info()] device 0x61b000002a80: param 1 id:9 (Spa:Enum:ParamId:Profile) 00000007:00000007
[D][000162292.391723][impl-device.c:747 device_info()] device 0x61b000002a80: param 2 id:12 (Spa:Enum:ParamId:EnumRoute) 00000003:00000003
[D][000162292.391743][impl-device.c:747 device_info()] device 0x61b000002a80: param 3 id:13 (Spa:Enum:ParamId:Route) 00000006:00000007
[D][000162292.391761][impl-device.c:755 device_info()] device 0x61b000002a80: update param 13
[D][000162292.391841][impl-device.c:706 emit_params()] device 0x61b000002a80: emit 1 params
[D][000162292.391867][impl-device.c:458 result_device_done()] device 0x61b000002a80: async result 0 1073742017 (1073742016/1073742017)
[D][000162292.391888][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 0
[D][000162292.391903][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162292.391959][impl-node.c:496 node_set_param()] node 0x61d000021280: resource 0x615000013400 set param id:2 (Spa:Enum:ParamId:Props) 00000000
[D][000162292.391984][audioadapter.c:418 impl_node_set_param()] audioadapter 0x7f7d1332e828: set param 2
[D][000162292.392011][channelmix.c:255 remap_volumes()] 0 0: 3 <-> 3
[D][000162292.392029][channelmix.c:255 remap_volumes()] 1 1: 4 <-> 4
[D][000162292.392048][channelmix-ops.c:456 impl_channelmix_set_volume()] volume:1.000000 mute:1 n_volumes:2
[D][000162292.392073][channelmix-ops.c:461 impl_channelmix_set_volume()] 0: 0.154856 * 0.000000 = 0.000000
[D][000162292.392094][channelmix-ops.c:461 impl_channelmix_set_volume()] 1: 0.154856 * 0.000000 = 0.000000
[D][000162292.392114][channelmix-ops.c:487 impl_channelmix_set_volume()] 0 0: 0.000000
[D][000162292.392129][channelmix-ops.c:487 impl_channelmix_set_volume()] 0 1: 0.000000
[D][000162292.392146][channelmix-ops.c:487 impl_channelmix_set_volume()] 1 0: 0.000000
[D][000162292.392162][channelmix-ops.c:487 impl_channelmix_set_volume()] 1 1: 0.000000
[D][000162292.392180][channelmix-ops.c:502 impl_channelmix_set_volume()] flags:00000005
[D][000162292.392202][impl-node.c:1318 node_info()] node 0x61d000021280: flags:00000019 change_mask:00000004 max_in:64 max_out:0
[D][000162292.392225][impl-node.c:1341 node_info()] node 0x61d000021280: param 0 id:3 (Spa:Enum:ParamId:EnumFormat) 00000002:00000002
[D][000162292.392246][impl-node.c:1341 node_info()] node 0x61d000021280: param 1 id:1 (Spa:Enum:ParamId:PropInfo) 00000003:00000003
[D][000162292.392265][impl-node.c:1341 node_info()] node 0x61d000021280: param 2 id:2 (Spa:Enum:ParamId:Props) 00000007:00000006
[D][000162292.392309][impl-node.c:1349 node_info()] node 0x61d000021280: update param 2
[D][000162292.392329][impl-node.c:1341 node_info()] node 0x61d000021280: param 3 id:4 (Spa:Enum:ParamId:Format) 00000006:00000006
[D][000162292.392347][impl-node.c:1341 node_info()] node 0x61d000021280: param 4 id:10 (Spa:Enum:ParamId:EnumPortConfig) 00000002:00000002
[D][000162292.392366][impl-node.c:1341 node_info()] node 0x61d000021280: param 5 id:11 (Spa:Enum:ParamId:PortConfig) 00000006:00000006
[D][000162292.392432][impl-node.c:280 emit_params()] node 0x61d000021280: emit 1 params
[D][000162292.392563][module-protocol-native.c:1109 do_resume()] flush
[D][000162292.392554][media-session.c:493 device_event_info()] media-session 0x7ffef740e950: device 41 info
[D][000162292.392698][media-session.c:519 device_event_info()] media-session 0x7ffef740e950: device 41 enum params 13 seq:1073742408
[D][000162292.392743][manager.c:299 device_event_info()] object 0x613000003a00: id:41 change-mask:00000002
[D][000162292.392760][proxy.c:320 pw_proxy_sync()] proxy 0x60c000019180: 42 seq:1 sync 1073742409
[D][000162292.392795][media-session.c:1168 sm_object_sync_update()] sync 0x617000001278 proxy 0x60c000019180 1073742409
[D][000162292.392842][manager.c:419 node_event_info()] object 0x613000003f40: id:46 change-mask:00000010
[D][000162292.392851][media-session.c:601 node_event_info()] media-session 0x7ffef740e950: node 46 info
[D][000162292.392909][manager.c:86 core_sync()] sync start 1073741992
[D][000162292.392918][media-session.c:628 node_event_info()] media-session 0x7ffef740e950: node 46 enum params 2 seq:1073742411
[D][000162292.392955][proxy.c:320 pw_proxy_sync()] proxy 0x616000006c80: 38 seq:1 sync 1073742412
[D][000162292.392989][media-session.c:1168 sm_object_sync_update()] sync 0x616000006cf8 proxy 0x616000006c80 1073742412
[D][000162292.393013][manager.c:299 device_event_info()] object 0x613000007200: id:41 change-mask:00000002
[D][000162292.393083][manager.c:419 node_event_info()] object 0x613000007740: id:46 change-mask:00000010
[D][000162292.393135][manager.c:86 core_sync()] sync start 1073741994
[D][000162292.393194][manager.c:299 device_event_info()] object 0x613000014cc0: id:41 change-mask:00000002
[D][000162292.393235][manager.c:419 node_event_info()] object 0x613000015200: id:46 change-mask:00000010
[D][000162292.393264][manager.c:86 core_sync()] sync start 1073742016
[D][000162292.393344][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162292.393397][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 1
[D][000162292.393417][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162292.393458][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162292.393485][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000002180: busy 1
[D][000162292.393502][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162292.393537][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162292.393561][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 1
[D][000162292.393577][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162292.393608][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162292.393632][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000007280: busy 1
[D][000162292.393648][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162292.394057][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742018 (1073742018/1073742019)
[D][000162292.394082][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.394113][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.394146][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742018 (1073742020/1073742021)
[D][000162292.394165][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742018 (1073742022/1073742023)
[D][000162292.394182][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742018 (1073742024/1073742025)
[D][000162292.394203][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742018 (1073742018/1073742019)
[D][000162292.394220][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.394243][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.394261][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742018 (1073742020/1073742021)
[D][000162292.394279][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742018 (1073742022/1073742023)
[D][000162292.394296][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742018 (1073742024/1073742025)
[D][000162292.394315][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742019 (1073742018/1073742019)
[D][000162292.394348][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 0
[D][000162292.394365][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162292.394390][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742019 (1073742020/1073742021)
[D][000162292.394408][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742019 (1073742022/1073742023)
[D][000162292.394425][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742019 (1073742024/1073742025)
[D][000162292.394445][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742020 (1073742020/1073742021)
[D][000162292.394462][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.394487][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.394528][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742020 (1073742022/1073742023)
[D][000162292.394546][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742020 (1073742024/1073742025)
[D][000162292.394567][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742020 (1073742020/1073742021)
[D][000162292.394584][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.394605][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.394623][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742020 (1073742022/1073742023)
[D][000162292.394641][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742020 (1073742024/1073742025)
[D][000162292.394660][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742021 (1073742020/1073742021)
[D][000162292.394692][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000002180: busy 0
[D][000162292.394718][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162292.394753][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742021 (1073742022/1073742023)
[D][000162292.394775][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742021 (1073742024/1073742025)
[D][000162292.394806][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742022 (1073742022/1073742023)
[D][000162292.394829][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.394864][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.394894][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742022 (1073742024/1073742025)
[D][000162292.394929][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742022 (1073742022/1073742023)
[D][000162292.394955][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.394988][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.395016][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742022 (1073742024/1073742025)
[D][000162292.395048][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742023 (1073742022/1073742023)
[D][000162292.395086][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 0
[D][000162292.395113][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162292.395153][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742023 (1073742024/1073742025)
[D][000162292.395187][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742024 (1073742024/1073742025)
[D][000162292.395214][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.395254][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.395310][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742024 (1073742024/1073742025)
[D][000162292.395339][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.395371][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.395405][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742025 (1073742024/1073742025)
[D][000162292.395442][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000007280: busy 0
[D][000162292.395469][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162292.395573][module-protocol-native.c:1109 do_resume()] flush
[D][000162292.395664][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000013400 enum params seq:1073742411 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162292.395706][manager.c:86 core_sync()] sync start 1073741993
[D][000162292.395709][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:0
[D][000162292.395757][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073742411 id:2
[D][000162292.395853][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000013400 reply param 1073742411
[D][000162292.395912][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073742411 id:2
[D][000162292.395995][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000013400 reply param 1073742411
[D][000162292.396045][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073742411 id:2
[D][000162292.396128][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x61500001ed00 enum params seq:1073741991 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162292.396168][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162292.396207][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073741991 param 21
[D][000162292.396235][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x61500001ed00 reply param 1073741991
[D][000162292.396283][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073741991 param 22
[D][000162292.396313][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x61500001ed00 reply param 1073741991
[D][000162292.396393][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000021280 enum params seq:1073741993 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162292.396432][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162292.396467][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073741993 param 21
[D][000162292.396495][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000021280 reply param 1073741993
[D][000162292.396533][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073741993 param 22
[D][000162292.396562][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000021280 reply param 1073741993
[D][000162292.396620][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000023800 enum params seq:1073742015 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162292.396657][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162292.396691][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742015 param 21
[D][000162292.396718][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000023800 reply param 1073742015
[D][000162292.396756][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742015 param 22
[D][000162292.396783][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000023800 reply param 1073742015
[D][000162292.396923][media-session.c:536 device_event_param()] media-session 0x7ffef740e950: device 0x617000001278 param 13 index:0 seq:1073742408
[D][000162292.397013][media-session.c:536 device_event_param()] media-session 0x7ffef740e950: device 0x617000001278 param 13 index:8 seq:1073742408
[D][000162292.397040][manager.c:86 core_sync()] sync start 1073741995
[D][000162292.397064][media-session.c:1115 done_proxy()] done 0x617000001278 proxy 0x60c000019180 avail:0000070c update:00000300 1073742409/1073742409
[D][000162292.397104][alsa-monitor.c:823 device_update()] device 0x6120000022c0 appeared 1 0
[D][000162292.397138][default-profile.c:366 object_update()] default-profile 0x60d0000001e0: device 0x60d000004cc0 00000300/0000070c
[I][000162292.397197][default-profile.c:270 handle_active_profile()] device 'alsa_card.pci-0000_00_1f.3': active profile 'output:analog-stereo+input:analog-stereo'
[D][000162292.397235][manager.c:86 core_sync()] sync start 1073742017
[I][000162292.397323][default-profile.c:305 handle_profile_switch()] device 'alsa_card.pci-0000_00_1f.3': found best profile 'output:analog-stereo+input:analog-stereo' changed:0
[I][000162292.397364][default-profile.c:344 handle_profile_switch()] device 'alsa_card.pci-0000_00_1f.3': no profile switch needed
[D][000162292.397374][manager.c:670 on_core_done()] sync end 1073741993/1073741993
[D][000162292.397392][default-routes.c:805 object_update()] default-routes 0x60d0000002b0: device 0x60e0000013a0 00000300/0000070c
[D][000162292.397407][pulse-server.c:574 manager_sync()] pulse-server 0x613000000900: manager sync
[I][000162292.397436][pulse-server.c:359 operation_complete()] pulse-server 0x613000000900: [GNOME Volume Control Media Keys] tag:25 complete
[D][000162292.397473][pulse-server.c:295 reply_new()] pulse-server 0x613000000900: REPLY tag:25
[I][000162292.397475][default-routes.c:727 handle_route()] device 41: port 'analog-input-internal-mic'
[I][000162292.397519][default-routes.c:727 handle_route()] device 41: port 'analog-output-speaker'
[D][000162292.397552][pulse-server.c:399 send_subscribe_event()] pulse-server 0x613000000900: SUBSCRIBE event:00000010 id:46
[D][000162292.397599][pulse-server.c:399 send_subscribe_event()] pulse-server 0x613000000900: SUBSCRIBE event:00000011 id:65582
[I][000162292.397683][default-routes.c:502 save_route()] device 41: route properties changed default.route.alsa_card.pci-0000_00_1f.3:output:analog-output-speaker { "mute": true, "volumes": [ 0.154856, 0.154856 ], "channels": [ "FL", "FR" ] }
[D][000162292.397746][system.c:174 impl_timerfd_create()] system 0x60c0000001e8: new fd:33
[D][000162292.397795][manager.c:670 on_core_done()] sync end 1073742017/1073742017
[D][000162292.397830][pulse-server.c:574 manager_sync()] pulse-server 0x613000011d80: manager sync
[I][000162292.397860][default-routes.c:546 save_profile()] device 41: profile output:analog-stereo+input:analog-stereo unchanged ([ "analog-output-speaker" ])


// unmute
[D][000162292.939186][pulse-server.c:5427 handle_packet()] pulse-server 0x616000001880: Received packet command 39 tag 28
[I][000162292.939239][pulse-server.c:3209 do_set_mute()] pulse-server 0x616000001880: [GNOME Volume Control Media Keys] SET_SINK_MUTE tag:28 index:46 name:(null) mute:0
[D][000162292.939402][manager.c:86 core_sync()] sync start 1073741995
[D][000162292.939427][pulse-server.c:345 operation_new()] pulse-server 0x613000000900: operation tag:28
[D][000162292.939574][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 1
[D][000162292.939618][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[I][000162292.939774][acp.c:1853 acp_device_set_mute()] Set hardware mute: 0
[I][000162292.940197][alsa-acp-device.c:841 on_mute_changed()] device analog-stereo mute changed
flags:00000000 n_items:34
  object.path = "alsa:pcm:0"
  device.api = "alsa:pcm"
  media.class = "Audio/Device"
  api.alsa.path = "hw:0"
  device.enum.api = "udev"
  device.api = "alsa"
  media.class = "Audio/Device"
  api.alsa.path = "hw:0"
  api.alsa.card = "0"
  api.alsa.card.name = "HDA Intel PCH"
  api.alsa.card.longname = "HDA Intel PCH at 0xae810000 irq 166"
  device.plugged.usec = "3812329"
  device.bus-path = "pci-0000:00:1f.3"
  device.sysfs.path = "/sys/devices/pci0000:00/0000:00:1f.3/sound/card0"
  device.bus = "pci"
  device.subsystem = "sound"
  device.vendor.id = "0x8086"
  device.vendor.name = "Intel Corporation"
  device.product.id = "0xa348"
  device.product.name = "Cannon Lake PCH cAVS"
  device.form-factor = "internal"
  device.name = "alsa_card.pci-0000_00_1f.3"
  device.description = "Built-in Audio"
  device.nick = "HDA Intel PCH"
  device.icon-name = "audio-card-pci"
  api.alsa.use-acp = "true"
  api.acp.auto-profile = "false"
  api.acp.auto-port = "false"
  api.dbus.ReserveDevice1 = "Audio0"
  alsa.card = "0"
  alsa.card_name = "HDA Intel PCH"
  alsa.long_card_name = "HDA Intel PCH at 0xae810000 irq 166"
  alsa.driver_name = "snd_hda_intel"
  device.string = "0"
[D][000162292.941355][impl-device.c:732 device_info()] device 0x61b000002a80: flags:00000000 change_mask:00000004
[D][000162292.941398][impl-device.c:747 device_info()] device 0x61b000002a80: param 0 id:8 (Spa:Enum:ParamId:EnumProfile) 00000002:00000002
[D][000162292.941424][impl-device.c:747 device_info()] device 0x61b000002a80: param 1 id:9 (Spa:Enum:ParamId:Profile) 00000007:00000007
[D][000162292.941446][impl-device.c:747 device_info()] device 0x61b000002a80: param 2 id:12 (Spa:Enum:ParamId:EnumRoute) 00000003:00000003
[D][000162292.941466][impl-device.c:747 device_info()] device 0x61b000002a80: param 3 id:13 (Spa:Enum:ParamId:Route) 00000007:00000006
[D][000162292.941485][impl-device.c:755 device_info()] device 0x61b000002a80: update param 13
[D][000162292.941562][impl-device.c:706 emit_params()] device 0x61b000002a80: emit 1 params
[D][000162292.941590][impl-device.c:458 result_device_done()] device 0x61b000002a80: async result 0 1073742027 (1073742026/1073742027)
[D][000162292.941613][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 0
[D][000162292.941632][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162292.941689][impl-node.c:496 node_set_param()] node 0x61d000021280: resource 0x615000013400 set param id:2 (Spa:Enum:ParamId:Props) 00000000
[D][000162292.941715][audioadapter.c:418 impl_node_set_param()] audioadapter 0x7f7d1332e828: set param 2
[D][000162292.941743][channelmix.c:255 remap_volumes()] 0 0: 3 <-> 3
[D][000162292.941762][channelmix.c:255 remap_volumes()] 1 1: 4 <-> 4
[D][000162292.941781][channelmix-ops.c:456 impl_channelmix_set_volume()] volume:1.000000 mute:0 n_volumes:2
[D][000162292.941806][channelmix-ops.c:461 impl_channelmix_set_volume()] 0: 0.154856 * 1.000000 = 0.154856
[D][000162292.941828][channelmix-ops.c:461 impl_channelmix_set_volume()] 1: 0.154856 * 1.000000 = 0.154856
[D][000162292.941848][channelmix-ops.c:487 impl_channelmix_set_volume()] 0 0: 0.154856
[D][000162292.941865][channelmix-ops.c:487 impl_channelmix_set_volume()] 0 1: 0.000000
[D][000162292.941882][channelmix-ops.c:487 impl_channelmix_set_volume()] 1 0: 0.000000
[D][000162292.941899][channelmix-ops.c:487 impl_channelmix_set_volume()] 1 1: 0.154856
[D][000162292.941916][channelmix-ops.c:502 impl_channelmix_set_volume()] flags:00000000
[D][000162292.941939][impl-node.c:1318 node_info()] node 0x61d000021280: flags:00000019 change_mask:00000004 max_in:64 max_out:0
[D][000162292.941963][impl-node.c:1341 node_info()] node 0x61d000021280: param 0 id:3 (Spa:Enum:ParamId:EnumFormat) 00000002:00000002
[D][000162292.941984][impl-node.c:1341 node_info()] node 0x61d000021280: param 1 id:1 (Spa:Enum:ParamId:PropInfo) 00000003:00000003
[D][000162292.942002][impl-node.c:1341 node_info()] node 0x61d000021280: param 2 id:2 (Spa:Enum:ParamId:Props) 00000006:00000007
[D][000162292.942021][impl-node.c:1349 node_info()] node 0x61d000021280: update param 2
[D][000162292.942038][impl-node.c:1341 node_info()] node 0x61d000021280: param 3 id:4 (Spa:Enum:ParamId:Format) 00000006:00000006
[D][000162292.942057][impl-node.c:1341 node_info()] node 0x61d000021280: param 4 id:10 (Spa:Enum:ParamId:EnumPortConfig) 00000002:00000002
[D][000162292.942076][impl-node.c:1341 node_info()] node 0x61d000021280: param 5 id:11 (Spa:Enum:ParamId:PortConfig) 00000006:00000006
[D][000162292.942140][impl-node.c:280 emit_params()] node 0x61d000021280: emit 1 params
[D][000162292.942246][module-protocol-native.c:1109 do_resume()] flush
[D][000162292.942270][media-session.c:493 device_event_info()] media-session 0x7ffef740e950: device 41 info
[D][000162292.942311][manager.c:299 device_event_info()] object 0x613000003a00: id:41 change-mask:00000002
[D][000162292.942398][media-session.c:519 device_event_info()] media-session 0x7ffef740e950: device 41 enum params 13 seq:1073742415
[D][000162292.942409][manager.c:419 node_event_info()] object 0x613000003f40: id:46 change-mask:00000010
[D][000162292.942446][proxy.c:320 pw_proxy_sync()] proxy 0x60c000019180: 42 seq:1 sync 1073742416
[D][000162292.942468][manager.c:86 core_sync()] sync start 1073741998
[D][000162292.942480][media-session.c:1168 sm_object_sync_update()] sync 0x617000001278 proxy 0x60c000019180 1073742416
[D][000162292.942533][media-session.c:601 node_event_info()] media-session 0x7ffef740e950: node 46 info
[D][000162292.942554][manager.c:299 device_event_info()] object 0x613000007200: id:41 change-mask:00000002
[D][000162292.942563][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162292.942597][manager.c:419 node_event_info()] object 0x613000007740: id:46 change-mask:00000010
[D][000162292.942591][media-session.c:628 node_event_info()] media-session 0x7ffef740e950: node 46 enum params 2 seq:1073742418
[D][000162292.942611][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 1
[D][000162292.942628][manager.c:86 core_sync()] sync start 1073741998
[D][000162292.942633][proxy.c:320 pw_proxy_sync()] proxy 0x616000006c80: 38 seq:1 sync 1073742419
[D][000162292.942643][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162292.942665][media-session.c:1168 sm_object_sync_update()] sync 0x616000006cf8 proxy 0x616000006c80 1073742419
[D][000162292.942703][manager.c:299 device_event_info()] object 0x613000014cc0: id:41 change-mask:00000002
[D][000162292.942727][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162292.942762][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 1
[D][000162292.942779][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162292.942788][manager.c:419 node_event_info()] object 0x613000015200: id:46 change-mask:00000010
[D][000162292.942834][manager.c:86 core_sync()] sync start 1073742020
[D][000162292.942841][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162292.942887][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000002180: busy 1
[D][000162292.942914][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162292.942989][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162292.943036][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000007280: busy 1
[D][000162292.943057][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162292.943397][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742028 (1073742028/1073742029)
[D][000162292.943443][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.943485][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.943516][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742028 (1073742030/1073742031)
[D][000162292.943537][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742028 (1073742032/1073742033)
[D][000162292.943556][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742028 (1073742034/1073742035)
[D][000162292.943578][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742028 (1073742028/1073742029)
[D][000162292.943597][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.943620][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.943639][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742028 (1073742030/1073742031)
[D][000162292.943657][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742028 (1073742032/1073742033)
[D][000162292.943674][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742028 (1073742034/1073742035)
[D][000162292.943695][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742029 (1073742028/1073742029)
[D][000162292.943728][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 0
[D][000162292.943746][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162292.943774][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742029 (1073742030/1073742031)
[D][000162292.943793][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742029 (1073742032/1073742033)
[D][000162292.943810][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742029 (1073742034/1073742035)
[D][000162292.943830][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742030 (1073742030/1073742031)
[D][000162292.943848][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.943874][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.943914][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742030 (1073742032/1073742033)
[D][000162292.943933][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742030 (1073742034/1073742035)
[D][000162292.943954][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742030 (1073742030/1073742031)
[D][000162292.943971][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.943993][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.944012][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742030 (1073742032/1073742033)
[D][000162292.944181][pulse-server.c:1020 send_command_request()] pulse-server 0x617000001900: REQUEST channel:0 16384
[D][000162292.944281][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742030 (1073742034/1073742035)
[D][000162292.944324][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742031 (1073742030/1073742031)
[D][000162292.944367][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 0
[D][000162292.944393][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162292.944428][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742031 (1073742032/1073742033)
[D][000162292.944457][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742031 (1073742034/1073742035)
[D][000162292.944483][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742032 (1073742032/1073742033)
[D][000162292.944498][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.944523][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.944546][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742032 (1073742034/1073742035)
[D][000162292.944567][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742032 (1073742032/1073742033)
[D][000162292.944585][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.944605][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.944627][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742032 (1073742034/1073742035)
[D][000162292.944649][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742033 (1073742032/1073742033)
[D][000162292.944679][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000002180: busy 0
[D][000162292.944707][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162292.944741][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742033 (1073742034/1073742035)
[D][000162292.944766][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742034 (1073742034/1073742035)
[D][000162292.944793][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.944829][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.944876][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742034 (1073742034/1073742035)
[D][000162292.944898][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162292.944928][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162292.944955][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742035 (1073742034/1073742035)
[D][000162292.944983][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000007280: busy 0
[D][000162292.945002][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162292.945105][module-protocol-native.c:1109 do_resume()] flush
[D][000162292.945140][pulse-server.c:5468 handle_memblock()] pulse-server 0x616000001880: Received memblock channel:0 offset:0 flags:00000000 size:16384
[D][000162292.945172][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000013400 enum params seq:1073742418 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162292.945179][pulse-server.c:5479 handle_memblock()] new block 0x6060000086c0 0x62d00006e400/16384 filled:60416 index:2837504 flags:00 offset:0
[D][000162292.945209][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:0
[D][000162292.945248][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073742418 id:2
[D][000162292.945318][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000013400 reply param 1073742418
[D][000162292.945393][manager.c:86 core_sync()] sync start 1073741999
[D][000162292.945404][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073742418 id:2
[D][000162292.945515][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000013400 reply param 1073742418
[D][000162292.945561][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073742418 id:2
[D][000162292.945662][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x61500001ed00 enum params seq:1073741997 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162292.945702][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162292.945745][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073741997 param 21
[D][000162292.945775][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x61500001ed00 reply param 1073741997
[D][000162292.945824][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073741997 param 22
[D][000162292.945858][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x61500001ed00 reply param 1073741997
[D][000162292.945927][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000021280 enum params seq:1073741997 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162292.945952][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162292.945974][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073741997 param 21
[D][000162292.945990][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000021280 reply param 1073741997
[D][000162292.946013][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073741997 param 22
[D][000162292.946030][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000021280 reply param 1073741997
[D][000162292.946062][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000023800 enum params seq:1073742019 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162292.946083][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162292.946103][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742019 param 21
[D][000162292.946119][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000023800 reply param 1073742019
[D][000162292.946142][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742019 param 22
[D][000162292.946158][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000023800 reply param 1073742019
[D][000162292.946280][media-session.c:536 device_event_param()] media-session 0x7ffef740e950: device 0x617000001278 param 13 index:0 seq:1073742415
[D][000162292.946342][media-session.c:536 device_event_param()] media-session 0x7ffef740e950: device 0x617000001278 param 13 index:8 seq:1073742415
[D][000162292.946338][manager.c:86 core_sync()] sync start 1073741999
[D][000162292.946376][media-session.c:1115 done_proxy()] done 0x617000001278 proxy 0x60c000019180 avail:0000070c update:00000300 1073742416/1073742416
[D][000162292.946403][alsa-monitor.c:823 device_update()] device 0x6120000022c0 appeared 1 0
[D][000162292.946424][default-profile.c:366 object_update()] default-profile 0x60d0000001e0: device 0x60d000004cc0 00000300/0000070c
[I][000162292.946464][default-profile.c:270 handle_active_profile()] device 'alsa_card.pci-0000_00_1f.3': active profile 'output:analog-stereo+input:analog-stereo'
[I][000162292.946533][default-profile.c:305 handle_profile_switch()] device 'alsa_card.pci-0000_00_1f.3': found best profile 'output:analog-stereo+input:analog-stereo' changed:0
[I][000162292.946554][default-profile.c:344 handle_profile_switch()] device 'alsa_card.pci-0000_00_1f.3': no profile switch needed
[D][000162292.946572][default-routes.c:805 object_update()] default-routes 0x60d0000002b0: device 0x60e0000013a0 00000300/0000070c
[D][000162292.946570][manager.c:86 core_sync()] sync start 1073742021
[I][000162292.946621][default-routes.c:727 handle_route()] device 41: port 'analog-input-internal-mic'
[I][000162292.946647][default-routes.c:727 handle_route()] device 41: port 'analog-output-speaker'
[D][000162292.946698][manager.c:670 on_core_done()] sync end 1073741999/1073741999
[D][000162292.946731][pulse-server.c:574 manager_sync()] pulse-server 0x613000000900: manager sync
[I][000162292.946759][pulse-server.c:359 operation_complete()] pulse-server 0x613000000900: [GNOME Volume Control Media Keys] tag:28 complete
[D][000162292.946792][pulse-server.c:295 reply_new()] pulse-server 0x613000000900: REPLY tag:28
[I][000162292.946833][default-routes.c:502 save_route()] device 41: route properties changed default.route.alsa_card.pci-0000_00_1f.3:output:analog-output-speaker { "mute": false, "volumes": [ 0.154856, 0.154856 ], "channels": [ "FL", "FR" ] }
[D][000162292.946865][pulse-server.c:399 send_subscribe_event()] pulse-server 0x613000000900: SUBSCRIBE event:00000010 id:46
[D][000162292.946908][pulse-server.c:399 send_subscribe_event()] pulse-server 0x613000000900: SUBSCRIBE event:00000011 id:65582
[I][000162292.946952][default-routes.c:546 save_profile()] device 41: profile output:analog-stereo+input:analog-stereo unchanged ([ "analog-output-speaker" ])


// setting the volume to approximately the same value as the current volume
[D][000162297.934541][pulse-server.c:5427 handle_packet()] pulse-server 0x616000001880: Received packet command 36 tag 31
[I][000162297.934593][pulse-server.c:3143 do_set_volume()] pulse-server 0x616000001880: [GNOME Shell Volume Control] SET_SINK_VOLUME tag:31 index:46 name:(null)
[I][000162297.934703][volume.c:49 volume_compare()] 0: val 0.154856<>0.154777
[D][000162297.934780][manager.c:86 core_sync()] sync start 1073742001
[D][000162297.934800][pulse-server.c:345 operation_new()] pulse-server 0x613000000ac0: operation tag:31
[D][000162297.934833][pulse-server.c:5427 handle_packet()] pulse-server 0x616000001880: Received packet command 36 tag 32
[I][000162297.934853][pulse-server.c:3143 do_set_volume()] pulse-server 0x616000001880: [GNOME Shell Volume Control] SET_SINK_VOLUME tag:32 index:46 name:(null)
[I][000162297.934935][volume.c:49 volume_compare()] 0: val 0.154856<>0.154777
[D][000162297.934993][manager.c:86 core_sync()] sync start 1073742003
[D][000162297.935018][pulse-server.c:345 operation_new()] pulse-server 0x613000000ac0: operation tag:32
[D][000162297.935214][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 1
[D][000162297.935264][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[I][000162297.935436][acp.c:1806 acp_device_set_volume()] Set hardware volume: 35187
[D][000162297.935493][acp.c:1808 acp_device_set_volume()]   0: 35187
[D][000162297.935517][acp.c:1808 acp_device_set_volume()]   1: 35187
[D][000162297.935619][acp.c:1078 set_volume()] Requested volume: 35187
[D][000162297.935650][acp.c:1079 set_volume()] Got hardware volume: 35263
[D][000162297.935697][acp.c:1080 set_volume()] Calculated software volume: 65395 (accurate-enough=yes)
[I][000162297.935730][alsa-acp-device.c:803 on_volume_changed()] device analog-stereo volume changed
flags:00000000 n_items:34
  object.path = "alsa:pcm:0"
  device.api = "alsa:pcm"
  media.class = "Audio/Device"
  api.alsa.path = "hw:0"
  device.enum.api = "udev"
  device.api = "alsa"
  media.class = "Audio/Device"
  api.alsa.path = "hw:0"
  api.alsa.card = "0"
  api.alsa.card.name = "HDA Intel PCH"
  api.alsa.card.longname = "HDA Intel PCH at 0xae810000 irq 166"
  device.plugged.usec = "3812329"
  device.bus-path = "pci-0000:00:1f.3"
  device.sysfs.path = "/sys/devices/pci0000:00/0000:00:1f.3/sound/card0"
  device.bus = "pci"
  device.subsystem = "sound"
  device.vendor.id = "0x8086"
  device.vendor.name = "Intel Corporation"
  device.product.id = "0xa348"
  device.product.name = "Cannon Lake PCH cAVS"[D][000162297.936214][pulse-server.c:1020 send_command_request()] pulse-server 0x617000001900: REQUEST channel:0 16384

  device.form-factor = "internal"
  device.name = "alsa_card.pci-0000_00_1f.3"
  device.description = "Built-in Audio"
  device.nick = "HDA Intel PCH"
  device.icon-name = "audio-card-pci"
  api.alsa.use-acp = "true"
  api.acp.auto-profile = "false"
  api.acp.auto-port = "false"
  api.dbus.ReserveDevice1 = "Audio0"
  alsa.card = "0"
  alsa.card_name = "HDA Intel PCH"
  alsa.long_card_name = "HDA Intel PCH at 0xae810000 irq 166"
  alsa.driver_name = "snd_hda_intel"
  device.string = "0"
[D][000162297.936778][impl-device.c:732 device_info()] device 0x61b000002a80: flags:00000000 change_mask:00000004
[D][000162297.936823][impl-device.c:747 device_info()] device 0x61b000002a80: param 0 id:8 (Spa:Enum:ParamId:EnumProfile) 00000002:00000002
[D][000162297.936849][impl-device.c:747 device_info()] device 0x61b000002a80: param 1 id:9 (Spa:Enum:ParamId:Profile) 00000007:00000007
[D][000162297.936869][impl-device.c:747 device_info()] device 0x61b000002a80: param 2 id:12 (Spa:Enum:ParamId:EnumRoute) 00000003:00000003
[D][000162297.936889][impl-device.c:747 device_info()] device 0x61b000002a80: param 3 id:13 (Spa:Enum:ParamId:Route) 00000006:00000007
[D][000162297.936907][impl-device.c:755 device_info()] device 0x61b000002a80: update param 13
[D][000162297.936990][impl-device.c:706 emit_params()] device 0x61b000002a80: emit 1 params
[D][000162297.937032][impl-device.c:458 result_device_done()] device 0x61b000002a80: async result 0 1073742037 (1073742036/1073742037)
[D][000162297.937067][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 0
[D][000162297.937096][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162297.937177][impl-node.c:496 node_set_param()] node 0x61d000021280: resource 0x615000013400 set param id:2 (Spa:Enum:ParamId:Props) 00000000
[D][000162297.937206][audioadapter.c:418 impl_node_set_param()] audioadapter 0x7f7d1332e828: set param 2
[D][000162297.937264][channelmix.c:255 remap_volumes()] 0 0: 3 <-> 3
[D][000162297.937285][channelmix.c:255 remap_volumes()] 1 1: 4 <-> 4
[D][000162297.937281][pulse-server.c:5468 handle_memblock()] pulse-server 0x616000001880: Received memblock channel:0 offset:0 flags:00000000 size:16384
[D][000162297.937313][channelmix-ops.c:456 impl_channelmix_set_volume()] volume:1.000000 mute:0 n_volumes:2
[D][000162297.937330][pulse-server.c:5479 handle_memblock()] new block 0x606000008720 0x62a000000200/16384 filled:60416 index:4754432 flags:00 offset:0
[D][000162297.937349][channelmix-ops.c:461 impl_channelmix_set_volume()] 0: 1.000000 * 1.000000 = 1.000000
[D][000162297.937384][channelmix-ops.c:461 impl_channelmix_set_volume()] 1: 1.000000 * 1.000000 = 1.000000
[D][000162297.937406][channelmix-ops.c:487 impl_channelmix_set_volume()] 0 0: 1.000000
[D][000162297.937423][channelmix-ops.c:487 impl_channelmix_set_volume()] 0 1: 0.000000
[D][000162297.937439][channelmix-ops.c:487 impl_channelmix_set_volume()] 1 0: 0.000000
[D][000162297.937455][channelmix-ops.c:487 impl_channelmix_set_volume()] 1 1: 1.000000
[D][000162297.937475][channelmix-ops.c:502 impl_channelmix_set_volume()] flags:0000000a
[D][000162297.937508][impl-node.c:1318 node_info()] node 0x61d000021280: flags:00000019 change_mask:00000004 max_in:64 max_out:0
[D][000162297.937545][impl-node.c:1341 node_info()] node 0x61d000021280: param 0 id:3 (Spa:Enum:ParamId:EnumFormat) 00000002:00000002
[D][000162297.937574][impl-node.c:1341 node_info()] node 0x61d000021280: param 1 id:1 (Spa:Enum:ParamId:PropInfo) 00000003:00000003
[D][000162297.937606][impl-node.c:1341 node_info()] node 0x61d000021280: param 2 id:2 (Spa:Enum:ParamId:Props) 00000007:00000006
[D][000162297.937636][impl-node.c:1349 node_info()] node 0x61d000021280: update param 2
[D][000162297.937665][impl-node.c:1341 node_info()] node 0x61d000021280: param 3 id:4 (Spa:Enum:ParamId:Format) 00000006:00000006
[D][000162297.937690][impl-node.c:1341 node_info()] node 0x61d000021280: param 4 id:10 (Spa:Enum:ParamId:EnumPortConfig) 00000002:00000002
[D][000162297.937709][impl-node.c:1341 node_info()] node 0x61d000021280: param 5 id:11 (Spa:Enum:ParamId:PortConfig) 00000006:00000006
[D][000162297.937775][impl-node.c:280 emit_params()] node 0x61d000021280: emit 1 params
[D][000162297.937871][module-protocol-native.c:1109 do_resume()] flush
[D][000162297.937899][media-session.c:493 device_event_info()] media-session 0x7ffef740e950: device 41 info
[D][000162297.937932][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 1
[D][000162297.937962][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162297.937951][manager.c:299 device_event_info()] object 0x613000003a00: id:41 change-mask:00000002
[D][000162297.938004][media-session.c:519 device_event_info()] media-session 0x7ffef740e950: device 41 enum params 13 seq:1073742422
[D][000162297.938046][manager.c:419 node_event_info()] object 0x613000003f40: id:46 change-mask:00000010
[D][000162297.938053][proxy.c:320 pw_proxy_sync()] proxy 0x60c000019180: 42 seq:1 sync 1073742423
[D][000162297.938088][manager.c:86 core_sync()] sync start 1073742002
[D][000162297.938090][media-session.c:1168 sm_object_sync_update()] sync 0x617000001278 proxy 0x60c000019180 1073742423
[D][000162297.938147][media-session.c:601 node_event_info()] media-session 0x7ffef740e950: node 46 info
[D][000162297.938158][manager.c:299 device_event_info()] object 0x613000007200: id:41 change-mask:00000002
[D][000162297.938189][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162297.938210][manager.c:419 node_event_info()] object 0x613000007740: id:46 change-mask:00000010
[D][000162297.938205][media-session.c:628 node_event_info()] media-session 0x7ffef740e950: node 46 enum params 2 seq:1073742425
[D][000162297.938241][manager.c:86 core_sync()] sync start 1073742006
[D][000162297.938245][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 1
[D][000162297.938248][proxy.c:320 pw_proxy_sync()] proxy 0x616000006c80: 38 seq:1 sync 1073742426
[D][000162297.938262][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162297.938280][media-session.c:1168 sm_object_sync_update()] sync 0x616000006cf8 proxy 0x616000006c80 1073742426
[D][000162297.938295][manager.c:299 device_event_info()] object 0x613000014cc0: id:41 change-mask:00000002
[D][000162297.938335][manager.c:419 node_event_info()] object 0x613000015200: id:46 change-mask:00000010
[D][000162297.938386][manager.c:86 core_sync()] sync start 1073742024
[I][000162297.938403][acp.c:1806 acp_device_set_volume()] Set hardware volume: 35187
[D][000162297.938437][acp.c:1808 acp_device_set_volume()]   0: 35187
[D][000162297.938447][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162297.938464][acp.c:1808 acp_device_set_volume()]   1: 35187
[D][000162297.938516][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000002180: busy 1
[D][000162297.938539][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162297.938589][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:0
[D][000162297.938588][acp.c:1078 set_volume()] Requested volume: 35187
[D][000162297.938618][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000007280: busy 1
[D][000162297.938626][acp.c:1079 set_volume()] Got hardware volume: 35263
[D][000162297.938636][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 1
[D][000162297.938653][acp.c:1080 set_volume()] Calculated software volume: 65395 (accurate-enough=yes)
[D][000162297.939142][impl-device.c:458 result_device_done()] device 0x61b000002a80: async result 0 1073742039 (1073742038/1073742039)
[D][000162297.939189][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006f80: busy 0
[D][000162297.939210][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162297.939255][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742039 (1073742040/1073742041)
[D][000162297.939287][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742039 (1073742042/1073742043)
[D][000162297.939319][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742039 (1073742044/1073742045)
[D][000162297.939356][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742040 (1073742040/1073742041)
[D][000162297.939385][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162297.939630][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162297.939662][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742040 (1073742042/1073742043)
[D][000162297.939677][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742040 (1073742044/1073742045)
[D][000162297.939697][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742040 (1073742040/1073742041)
[D][000162297.939715][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162297.939743][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162297.939761][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742040 (1073742042/1073742043)
[D][000162297.939777][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742040 (1073742044/1073742045)
[D][000162297.939797][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742041 (1073742040/1073742041)
[D][000162297.939827][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000006c80: busy 0
[D][000162297.939844][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162297.939868][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742041 (1073742042/1073742043)
[D][000162297.939886][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742041 (1073742044/1073742045)
[D][000162297.939905][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742042 (1073742042/1073742043)
[D][000162297.939923][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162297.939948][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162297.939990][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742042 (1073742044/1073742045)
[D][000162297.940012][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742042 (1073742042/1073742043)
[D][000162297.940029][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162297.940051][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162297.940070][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742042 (1073742044/1073742045)
[D][000162297.940089][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742043 (1073742042/1073742043)
[D][000162297.940111][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000002180: busy 0
[D][000162297.940128][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162297.940151][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742043 (1073742044/1073742045)
[D][000162297.940171][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742044 (1073742044/1073742045)
[D][000162297.940188][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162297.940213][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162297.940234][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742044 (1073742044/1073742045)
[D][000162297.940252][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162297.940273][impl-device.c:280 result_device_params()] device 0x61b000002a80: add param 13
[D][000162297.940293][impl-device.c:384 result_device_params_async()] device 0x61b000002a80: async result 0 1073742045 (1073742044/1073742045)
[D][000162297.940316][impl-client.c:718 pw_impl_client_set_busy()] client 0x616000007280: busy 0
[D][000162297.940333][module-protocol-native.c:275 client_busy_changed()] protocol-native 0x610000000940: busy changed 0
[D][000162297.940412][impl-device.c:319 pw_impl_device_for_each_param()] device 0x61b000002a80: params id:13 (Spa:Enum:ParamId:Route) index:0 max:4294967295 cached:1
[D][000162297.940438][impl-device.c:345 pw_impl_device_for_each_param()] device 0x61b000002a80: 1073742004 param 45
[D][000162297.940452][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162297.940470][impl-device.c:345 pw_impl_device_for_each_param()] device 0x61b000002a80: 1073742004 param 46
[D][000162297.940485][impl-device.c:272 result_device_params()] device 0x61b000002a80: type 1
[D][000162297.940510][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000021280 enum params seq:1073742005 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162297.940533][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:0
[D][000162297.940556][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073742005 id:2
[D][000162297.940614][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000021280 reply param 1073742005
[D][000162297.940645][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073742005 id:2
[D][000162297.940693][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000021280 reply param 1073742005
[D][000162297.940717][audioadapter.c:120 impl_node_enum_params()] audioadapter 0x7f7d1332e828: 1073742005 id:2
[D][000162297.940787][module-protocol-native.c:1109 do_resume()] flush
[D][000162297.940820][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000013400 enum params seq:1073742425 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162297.940841][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162297.940862][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742425 param 21
[D][000162297.940878][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000013400 reply param 1073742425
[D][000162297.940899][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742425 param 22
[D][000162297.940914][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000013400 reply param 1073742425
[D][000162297.940923][manager.c:86 core_sync()] sync start 1073742007
[D][000162297.940945][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x61500001ed00 enum params seq:1073742001 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162297.940965][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162297.940983][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742001 param 21
[D][000162297.940998][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x61500001ed00 reply param 1073742001
[D][000162297.941018][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742001 param 22
[D][000162297.941033][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x61500001ed00 reply param 1073742001
[D][000162297.941078][impl-node.c:433 node_enum_params()] node 0x61d000021280: resource 0x615000023800 enum params seq:1073742023 id:2 (Spa:Enum:ParamId:Props) index:0 num:4294967295
[D][000162297.941097][impl-node.c:1883 pw_impl_node_for_each_param()] node 0x61d000021280: params id:2 (Spa:Enum:ParamId:Props) index:0 max:4294967295 cached:1
[D][000162297.941115][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742023 param 21
[D][000162297.941129][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000023800 reply param 1073742023
[D][000162297.941149][impl-node.c:1909 pw_impl_node_for_each_param()] node 0x61d000021280: 1073742023 param 22
[D][000162297.941164][impl-node.c:420 reply_param()] node 0x61d000021280: resource 0x615000023800 reply param 1073742023
[D][000162297.941268][media-session.c:536 device_event_param()] media-session 0x7ffef740e950: device 0x617000001278 param 13 index:0 seq:1073742422
[D][000162297.941339][media-session.c:536 device_event_param()] media-session 0x7ffef740e950: device 0x617000001278 param 13 index:8 seq:1073742422
[D][000162297.941363][manager.c:86 core_sync()] sync start 1073742003
[D][000162297.941369][media-session.c:1115 done_proxy()] done 0x617000001278 proxy 0x60c000019180 avail:0000070c update:00000300 1073742423/1073742423
[D][000162297.941424][alsa-monitor.c:823 device_update()] device 0x6120000022c0 appeared 1 0
[D][000162297.941445][default-profile.c:366 object_update()] default-profile 0x60d0000001e0: device 0x60d000004cc0 00000300/0000070c
[I][000162297.941480][default-profile.c:270 handle_active_profile()] device 'alsa_card.pci-0000_00_1f.3': active profile 'output:analog-stereo+input:analog-stereo'
[D][000162297.941522][manager.c:86 core_sync()] sync start 1073742025
[I][000162297.941550][default-profile.c:305 handle_profile_switch()] device 'alsa_card.pci-0000_00_1f.3': found best profile 'output:analog-stereo+input:analog-stereo' changed:0
[I][000162297.941571][default-profile.c:344 handle_profile_switch()] device 'alsa_card.pci-0000_00_1f.3': no profile switch needed
[D][000162297.941585][manager.c:670 on_core_done()] sync end 1073742007/1073742007
[D][000162297.941589][default-routes.c:805 object_update()] default-routes 0x60d0000002b0: device 0x60e0000013a0 00000300/0000070c
[D][000162297.941607][pulse-server.c:574 manager_sync()] pulse-server 0x613000000ac0: manager sync
[I][000162297.941628][pulse-server.c:359 operation_complete()] pulse-server 0x613000000ac0: [GNOME Shell Volume Control] tag:31 complete
[I][000162297.941641][default-routes.c:727 handle_route()] device 41: port 'analog-input-internal-mic'
[D][000162297.941651][pulse-server.c:295 reply_new()] pulse-server 0x613000000ac0: REPLY tag:31
[I][000162297.941662][default-routes.c:727 handle_route()] device 41: port 'analog-output-speaker'
[I][000162297.941678][pulse-server.c:359 operation_complete()] pulse-server 0x613000000ac0: [GNOME Shell Volume Control] tag:32 complete
[D][000162297.941697][pulse-server.c:295 reply_new()] pulse-server 0x613000000ac0: REPLY tag:32
[D][000162297.941737][pulse-server.c:399 send_subscribe_event()] pulse-server 0x613000000ac0: SUBSCRIBE event:00000010 id:46
[I][000162297.941751][default-routes.c:502 save_route()] device 41: route properties changed default.route.alsa_card.pci-0000_00_1f.3:output:analog-output-speaker { "mute": false, "volumes": [ 0.154777, 0.154777 ], "channels": [ "FL", "FR" ] }
[D][000162297.941764][pulse-server.c:399 send_subscribe_event()] pulse-server 0x613000000ac0: SUBSCRIBE event:00000011 id:65582
[D][000162297.941793][system.c:174 impl_timerfd_create()] system 0x60c0000001e8: new fd:33
[D][000162297.941881][manager.c:670 on_core_done()] sync end 1073742003/1073742003
[D][000162297.941901][pulse-server.c:574 manager_sync()] pulse-server 0x613000000900: manager sync
[I][000162297.941899][default-routes.c:546 save_profile()] device 41: profile output:analog-stereo+input:analog-stereo unchanged ([ "analog-output-speaker" ])

I have only tried the built-in ALSA device, I have not checked if it's reproducible for e.g. BlueZ sinks.

Interestingly, if the volume is at about 100% in both the source (I mean the app playing the audio), and on the GNOME shell slider ("system volume"), then this issue seems to go away, so I think it might be that a scalar is applied to the volume again when it is restored, even though the saved volume already has that scalar applied (or something similar).

Another thing I noticed is that when muting/unmuting channelmix.c:set_volume() chooses this->props.channel, however, when setting the volume on the slider, this->props.soft is selected.

I can provide more information if needed.