Hide Forgot
Created attachment 1683746 [details] Screenshot of problem Description of problem: Network manager started stuck when I tries connecting to VPN (openconnect) after upgrade gnome-shell to 3.37.1-1.fc33 version Demonstration: https://youtu.be/5l_rAfozF6g Last good working gnome-shell version: 3.36.1-2.fc33
Maybe this message from system log helps: May 01 21:49:39 localhost.localdomain tracker-store[5734]: OK May 01 21:49:39 localhost.localdomain systemd[4908]: tracker-store.service: Succeeded. May 01 21:49:46 localhost.localdomain gnome-shell[4998]: Some code called array.toString() on a Uint8Array instance. Previously this would have interpreted the bytes of the array as a string, but that is nonstandard. In the future this will return the bytes as comma-separated digits. For the time being, the old behavior has been preserved, but please fix your code anyway to explicitly call ByteArray.toString(array). (Note that array.toString() may have been called implicitly.) 0 _vpnChildProcessLineOldStyle() ["resource:///org/gnome/shell/ui/components/networkAgent.js":473:16] 1 _readStdoutOldStyle() ["resource:///org/gnome/shell/ui/components/networkAgent.js":496:13] 2 AsyncFunctionNext() ["self-hosted":840:4] May 01 21:49:57 localhost.localdomain realmd[4694]: quitting realmd service after timeout May 01 21:49:57 localhost.localdomain realmd[4694]: stopping service May 01 21:49:57 localhost.localdomain systemd[1]: realmd.service: Succeeded. May 01 21:49:57 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=realmd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Proposed as a Blocker and Freeze Exception for 33-beta by Fedora user mikhail using the blocker tracking app because: Connection to VPN servers via Network Manager it is basic functionality. And breaking it is unacceptable especially when many began to work remotely due to COVID 19.
Are you still having trouble with this? OpenVPN is working fine for me, but I don't have an openconnect VPN to test with...
(In reply to Adam Williamson from comment #3) > Are you still having trouble with this? OpenVPN is working fine for me, but > I don't have an openconnect VPN to test with... I suspect OpenVPN didn't request response code (in my case this is second factor sms) Stuck happens after requesting response code. And doesn't matter is entered code are correct or NetworkManager window will be closed. The result would only one. Connection will not established and NetworkManager window will stuck. https://youtu.be/WHEHzkjkPws Retested on gnome-shell 3.37.1-3
mikhail: can you connect from a console with nmcli as a workaround?
Discussed during the 2020-07-20 blocker review meeting: [0] The decision to delay the classification of this as a blocker bug was made as, while we see this as a bad problem and on its face potentially a blocker, the existing criteria don't really cover it, and we're not sure exactly how broken it is yet. We are punting for more research on how common the bug is, and also a potential proposal of VPN-specific release criteria. [0] https://meetbot.fedoraproject.org/fedora-blocker-review/2020-07-20/f33-blocker-review.2020-07-20-16.18.txt
(In reply to Adam Williamson from comment #5) > mikhail: can you connect from a console with nmcli as a workaround? No differences because `$ nmcli c up Tensor` show graphical interface for entering the password. Demonstration: https://youtu.be/kGzHGmS16es So you could easily reproduce this bug it even without entering the password. Just switch to LEGACY policy `update-crypto-policies --set LEGACY` and use `vpn.tensor.ru:501` as the gateway in openconnect.
Oh, forgot `--ask` $ nmcli c up Tensor --ask POST https://vpn.tensor.ru:501/ Connected to 91.213.144.15:501 SSL negotiation with vpn.tensor.ru Connected to HTTPS on vpn.tensor.ru with ciphersuite (TLS1.2)-(DHE-CUSTOM1024)-(RSA-SHA512)-(AES-256-CBC)-(SHA1) XML POST enabled Please enter your username and password. GROUP: [Corp|Main|Office|Region|TechSupport|TechSupport-Region]:Region POST https://vpn.tensor.ru:501/ XML POST enabled Please enter your username and password. Username:mv.gavrilov Password: POST https://vpn.tensor.ru:501/ Please enter your one-time password You will receive a password via mobile application or via SMS. SMS delivery time is up to 5 minutes. Be patient! Response: POST https://vpn.tensor.ru:501/ Connection successfully activated (D-Bus active path: /org/freedesktop/NetworkManager/ActiveConnection/8) it looks like it works
OK, so in the worst case we at least have some kind of workaround :/ BTW, I'm not convinced the log messages you pasted earlier are the problem here, to me they read like a kinda "WARNING you are doing something bad but for now it will keep behaving the same way" message, which shouldn't be the cause of the problem...can you perhaps post full log messages from 2-3 minutes around the attempt, in case there's something else in there? thanks!
> I'm not convinced the log messages you pasted earlier are the problem here, > to me they read like a kinda "WARNING you are doing something bad but for now it will keep behaving > the same way" message, which shouldn't be the cause of the problem...can you perhaps post full log messages > from 2-3 minutes around the attempt, in case there's something else in there? thanks! Demonstration with `journalctl -f` https://youtu.be/OIis2Dq2DSQ $ journalctl -f -- Logs begin at Thu 2020-04-16 22:37:38 +05. -- Jul 21 23:54:20 localhost.localdomain systemd[1]: libvirtd.service: Unit process 1700 (dnsmasq) remains running after unit stopped. Jul 21 23:54:20 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=libvirtd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 21 23:54:20 localhost.localdomain systemd[1]: libvirtd.service: Unit process 1701 (dnsmasq) remains running after unit stopped. Jul 21 23:54:20 localhost.localdomain systemd[1]: libvirtd.service: Consumed 1.327s CPU time. Jul 21 23:54:32 localhost.localdomain tracker-store[2986]: OK Jul 21 23:54:32 localhost.localdomain systemd[2228]: tracker-store.service: Succeeded. Jul 21 23:54:32 localhost.localdomain systemd[2228]: tracker-store.service: Consumed 2.142s CPU time. Jul 21 23:54:42 localhost.localdomain systemd[2228]: Starting Mark boot as successful... Jul 21 23:54:42 localhost.localdomain systemd[2228]: grub-boot-success.service: Succeeded. Jul 21 23:54:42 localhost.localdomain systemd[2228]: Finished Mark boot as successful. Jul 21 23:56:10 localhost.localdomain NetworkManager[1206]: <info> [1595357770.0344] audit: op="connection-activate" uuid="e561fcb2-6353-41b3-8b46-2adae6ba006d" name="Tensor" pid=2368 uid=1000 result="success" Jul 21 23:56:10 localhost.localdomain NetworkManager[1206]: <info> [1595357770.0429] vpn-connection[0x55f30f7cc140,e561fcb2-6353-41b3-8b46-2adae6ba006d,"Tensor",0]: Started the VPN service, PID 3806 Jul 21 23:56:10 localhost.localdomain NetworkManager[1206]: <info> [1595357770.0614] vpn-connection[0x55f30f7cc140,e561fcb2-6353-41b3-8b46-2adae6ba006d,"Tensor",0]: Saw the service appear; activating connection Jul 21 23:56:10 localhost.localdomain gnome-shell[2368]: libinput error: event13 - Logitech G903 LS: client bug: event processing lagging behind by 15ms, your system is too slow Jul 21 23:56:12 localhost.localdomain gnome-shell[2368]: libinput error: client bug: timer event13 debounce short: scheduled expiry is in the past (-1ms), your system is too slow Jul 21 23:56:15 localhost.localdomain gnome-shell[2368]: Some code called array.toString() on a Uint8Array instance. Previously this would have interpreted the bytes of the array as a string, but that is nonstandard. In the future this will return the bytes as comma-separated digits. For the time being, the old behavior has been preserved, but please fix your code anyway to explicitly call ByteArray.toString(array). (Note that array.toString() may have been called implicitly.) 0 _vpnChildProcessLineOldStyle() ["resource:///org/gnome/shell/ui/components/networkAgent.js":473:16] 1 _readStdoutOldStyle() ["resource:///org/gnome/shell/ui/components/networkAgent.js":496:13] 2 AsyncFunctionNext() ["self-hosted":840:4] Jul 21 23:56:26 localhost.localdomain NetworkManager[1206]: <error> [1595357786.2961] vpn-connection[0x55f30f7cc140,e561fcb2-6353-41b3-8b46-2adae6ba006d,"Tensor",0]: Failed to request VPN secrets #3: No agents were available for this request. Jul 21 23:56:26 localhost.localdomain NetworkManager[1206]: <info> [1595357786.2976] vpn-connection[0x55f30f7cc140,e561fcb2-6353-41b3-8b46-2adae6ba006d,"Tensor",0]: VPN plugin: state changed: stopped (6)
thanks for the video, that's useful indeed. yeah, it really seems like that array.toString() error occurs along with the freeze, and nothing else does. do you get anything else if you run journalctl -f as root?
(In reply to Adam Williamson from comment #11) > do you get anything else if you run journalctl -f as root? https://youtu.be/MBPJDMRs3PM I did not see any differences. # journalctl -f -- Logs begin at Fri 2020-04-17 01:51:47 +05. -- Jul 27 10:22:17 localhost.localdomain systemd[1]: Starting Fingerprint Authentication Daemon... Jul 27 10:22:17 localhost.localdomain systemd[1]: Started Fingerprint Authentication Daemon. Jul 27 10:22:17 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=fprintd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 27 10:22:23 localhost.localdomain audit[3539]: USER_AUTH pid=3539 uid=1000 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:authentication grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=localhost.localdomain addr=? terminal=pts/0 res=success' Jul 27 10:22:23 localhost.localdomain audit[3539]: USER_ACCT pid=3539 uid=1000 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="root" exe="/usr/bin/su" hostname=localhost.localdomain addr=? terminal=pts/0 res=success' Jul 27 10:22:23 localhost.localdomain su[3539]: (to root) mikhail on pts/0 Jul 27 10:22:23 localhost.localdomain audit[3539]: CRED_ACQ pid=3539 uid=1000 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=localhost.localdomain addr=? terminal=pts/0 res=success' Jul 27 10:22:23 localhost.localdomain su[3539]: pam_unix(su-l:session): session opened for user root(uid=0) by (uid=1000) Jul 27 10:22:23 localhost.localdomain audit[3539]: USER_START pid=3539 uid=1000 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:session_open grantors=pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_umask,pam_xauth acct="root" exe="/usr/bin/su" hostname=localhost.localdomain addr=? terminal=pts/0 res=success' Jul 27 10:22:26 localhost.localdomain systemd[2199]: gnome-launched-tracker-extract.desktop-2757.scope: Succeeded. Jul 27 10:22:34 localhost.localdomain systemd[1]: systemd-localed.service: Succeeded. Jul 27 10:22:34 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-localed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 27 10:22:34 localhost.localdomain audit: BPF prog-id=43 op=UNLOAD Jul 27 10:22:34 localhost.localdomain audit: BPF prog-id=42 op=UNLOAD Jul 27 10:22:34 localhost.localdomain audit: BPF prog-id=41 op=UNLOAD Jul 27 10:22:38 localhost.localdomain NetworkManager[1197]: <info> [1595827358.4137] audit: op="connection-activate" uuid="e561fcb2-6353-41b3-8b46-2adae6ba006d" name="Tensor" pid=2355 uid=1000 result="success" Jul 27 10:22:38 localhost.localdomain NetworkManager[1197]: <info> [1595827358.4219] vpn-connection[0x5610a2bac0a0,e561fcb2-6353-41b3-8b46-2adae6ba006d,"Tensor",0]: Started the VPN service, PID 3596 Jul 27 10:22:38 localhost.localdomain NetworkManager[1197]: <info> [1595827358.4383] vpn-connection[0x5610a2bac0a0,e561fcb2-6353-41b3-8b46-2adae6ba006d,"Tensor",0]: Saw the service appear; activating connection Jul 27 10:22:39 localhost.localdomain systemd[2199]: Starting Tracker metadata extractor... Jul 27 10:22:39 localhost.localdomain tracker-extract[3624]: Set scheduler policy to SCHED_IDLE Jul 27 10:22:39 localhost.localdomain tracker-extract[3624]: Setting priority nice level to 19 Jul 27 10:22:39 localhost.localdomain systemd[2199]: Started Tracker metadata extractor. Jul 27 10:22:41 localhost.localdomain gnome-shell[2355]: libinput error: event9 - Logitech G903 LS: client bug: event processing lagging behind by 27ms, your system is too slow Jul 27 10:22:41 localhost.localdomain gnome-shell[2355]: libinput error: client bug: timer event9 debounce: scheduled expiry is in the past (-2ms), your system is too slow Jul 27 10:22:41 localhost.localdomain gnome-shell[2355]: libinput error: client bug: timer event9 debounce short: scheduled expiry is in the past (-15ms), your system is too slow Jul 27 10:22:43 localhost.localdomain gnome-shell[2355]: Some code called array.toString() on a Uint8Array instance. Previously this would have interpreted the bytes of the array as a string, but that is nonstandard. In the future this will return the bytes as comma-separated digits. For the time being, the old behavior has been preserved, but please fix your code anyway to explicitly call ByteArray.toString(array). (Note that array.toString() may have been called implicitly.) 0 _vpnChildProcessLineOldStyle() ["resource:///org/gnome/shell/ui/components/networkAgent.js":473:16] 1 _readStdoutOldStyle() ["resource:///org/gnome/shell/ui/components/networkAgent.js":496:13] 2 AsyncFunctionNext() ["self-hosted":840:4] Jul 27 10:22:47 localhost.localdomain systemd[1]: fprintd.service: Succeeded. Jul 27 10:22:47 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=fprintd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 27 10:22:51 localhost.localdomain systemd[2199]: tracker-extract.service: Succeeded. Jul 27 10:22:51 localhost.localdomain systemd[2199]: tracker-extract.service: Consumed 1.975s CPU time. Jul 27 10:22:53 localhost.localdomain systemd[1]: systemd-hostnamed.service: Succeeded. Jul 27 10:22:53 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 27 10:22:53 localhost.localdomain audit: BPF prog-id=40 op=UNLOAD Jul 27 10:22:53 localhost.localdomain audit: BPF prog-id=39 op=UNLOAD Jul 27 10:23:07 localhost.localdomain systemd[1]: libvirtd.service: Succeeded. Jul 27 10:23:07 localhost.localdomain systemd[1]: libvirtd.service: Unit process 1664 (dnsmasq) remains running after unit stopped. Jul 27 10:23:07 localhost.localdomain systemd[1]: libvirtd.service: Unit process 1665 (dnsmasq) remains running after unit stopped. Jul 27 10:23:07 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=libvirtd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 27 10:23:07 localhost.localdomain systemd[1]: libvirtd.service: Consumed 1.376s CPU time. Jul 27 10:23:08 localhost.localdomain NetworkManager[1197]: <error> [1595827388.2834] vpn-connection[0x5610a2bac0a0,e561fcb2-6353-41b3-8b46-2adae6ba006d,"Tensor",0]: Failed to request VPN secrets #3: No agents were available for this request. Jul 27 10:23:08 localhost.localdomain NetworkManager[1197]: <info> [1595827388.2857] vpn-connection[0x5610a2bac0a0,e561fcb2-6353-41b3-8b46-2adae6ba006d,"Tensor",0]: VPN plugin: state changed: stopped (6) Jul 27 10:23:08 localhost.localdomain NetworkManager[1197]: <info> [1595827388.2880] vpn-connection[0x5610a2bac0a0,e561fcb2-6353-41b3-8b46-2adae6ba006d,"Tensor",0]: VPN service disappeared Jul 27 10:23:12 localhost.localdomain tracker-store[2924]: OK Jul 27 10:23:12 localhost.localdomain systemd[2199]: tracker-store.service: Succeeded.
Discussed during the 2020-08-03 blocker review meeting: [0] The decision to delay the classification of this as a blocker bug was made as we believe this could be a potential blocker violating the "basic functionality" criterion, the lack of testing and reproducability has us skeptical for now. We'll punt for further testing. [0] https://meetbot.fedoraproject.org/fedora-blocker-review/2020-08-03/f33-blocker-review.2020-08-03-16.02.txt
Discussed during the 2020-08-10 blocker review meeting: [0] The decision to delay the classification of this as a blocker bug was made as we still don't have any further info on this yet, so we need to punt again. We will send out a call for testing to try and get more info. [0] https://meetbot.fedoraproject.org/fedora-blocker-review/2020-08-10/f33-blocker-review.2020-08-10-16.17.txt
I was able to reproduce this bug.
Created attachment 1711021 [details] I was able to recreate the bug.
This bug appears to have been reported against 'rawhide' during the Fedora 33 development cycle. Changing version to 33.
Thanks Brad, that's useful! Can you check your journal and see if you see the same array.toString() error?
Aug 10 21:01:01 localhost.localdomain gnome-shell[2073]: Some code called array.toString() on a Uint8Array instance. Previously this would have interpreted the byt> (Note that array.toString() may have been called implicitly.) 0 _vpnChildProcessLineOldStyle() ["resource:///org/gnome/shell/ui/components/networkAgent.js":473:16] 1 _readStdoutOldStyle() ["resource:///org/gnome/shell/ui/components/networkAgent.js":496:13] 2 AsyncFunctionNext() ["self-hosted":840:4]
I was testing again and the String error was not present but I got a different error. See below. Aug 13 20:18:40 localhost.localdomain audit[4501]: USER_END pid=4501 uid=0 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success' Aug 13 20:18:40 localhost.localdomain audit[4501]: CRED_DISP pid=4501 uid=0 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_fprintd acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success' Aug 13 20:18:48 localhost.localdomain NetworkManager[2709]: <info> [1597364328.8932] audit: op="connection-activate" uuid="98a924db-699a-4328-9d62-896482d48e35" name="kensingerrepair.com" pid=3454 uid=1000 result="success" Aug 13 20:18:48 localhost.localdomain NetworkManager[2709]: <info> [1597364328.8990] vpn-connection[0x55dfbd05c550,98a924db-699a-4328-9d62-896482d48e35,"kensingerrepair.com",0]: Started the VPN service, PID 4517 Aug 13 20:18:48 localhost.localdomain NetworkManager[2709]: <info> [1597364328.9151] vpn-connection[0x55dfbd05c550,98a924db-699a-4328-9d62-896482d48e35,"kensingerrepair.com",0]: Saw the service appear; activating connection Aug 13 20:19:56 localhost.localdomain systemd[1]: Starting dnf makecache... Aug 13 20:19:57 localhost.localdomain dnf[4536]: Metadata timer caching disabled when running on a battery. Aug 13 20:19:57 localhost.localdomain systemd[1]: dnf-makecache.service: Succeeded. Aug 13 20:19:57 localhost.localdomain systemd[1]: Finished dnf makecache. Aug 13 20:19:57 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dnf-makecache comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Aug 13 20:19:57 localhost.localdomain audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dnf-makecache comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Aug 13 20:20:49 localhost.localdomain NetworkManager[2709]: <error> [1597364449.0141] vpn-connection[0x55dfbd05c550,98a924db-699a-4328-9d62-896482d48e35,"kensingerrepair.com",0]: Failed to request VPN secrets #3: No agents were available for this request. Aug 13 20:20:49 localhost.localdomain NetworkManager[2709]: <info> [1597364449.0195] vpn-connection[0x55dfbd05c550,98a924db-699a-4328-9d62-896482d48e35,"kensingerrepair.com",0]: VPN plugin: state changed: stopped (6)
A fix for this was just merged upstream. I'm going to try backporting it, hold on for an update shortly.
Looks like fmuellner is way ahead of me. He's backported the fix and sent builds for F33 and F34, but the F33 build failed because the version of mutter it needs to build against isn't in the buildroot yet. I'll try and remember to post here once things are cleared up and you can update and test.
(In reply to Adam Williamson from comment #22) > the F33 build failed because the version of mutter it needs to build against isn't in the buildroot yet. It is now and the F33 build went through.
Yup, so the fix is in gnome-shell-3.37.90-1.fc33 / gnome-shell-3.37.90-1.fc34 (depending whether you go with F33 or Rawhide now we branched). Please test and report if it's fixed. Thanks!
(In reply to Adam Williamson from comment #24) > Yup, so the fix is in gnome-shell-3.37.90-1.fc33 / > gnome-shell-3.37.90-1.fc34 (depending whether you go with F33 or Rawhide now > we branched). Please test and report if it's fixed. Thanks! I confirm the issue was gone after upgrading gnome-shell and mutter to 3.37.90-1.fc33 version.
Awesome! It's gone 'stable' already (Bodhi is still in Rawhide mode on F33) so we can close this. Thanks.