Bug 1830343 - Network manager started stuck when I tries connecting to VPN (openconnect) after upgrade gnome-shell to 3.37.1-1.fc33 version
Summary: Network manager started stuck when I tries connecting to VPN (openconnect) a...
Keywords:
Status: NEW
Alias: None
Product: Fedora
Classification: Fedora
Component: gnome-shell
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Florian Müllner
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: BetaBlocker, F33BetaBlocker BetaFreezeException, F33BetaFreezeException
TreeView+ depends on / blocked
 
Reported: 2020-05-01 17:03 UTC by Mikhail
Modified: 2020-08-03 17:05 UTC (History)
9 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Type: Bug


Attachments (Terms of Use)
Screenshot of problem (14.77 MB, image/png)
2020-05-01 17:03 UTC, Mikhail
no flags Details


Links
System ID Priority Status Summary Last Updated
GNOME Gitlab GNOME/gnome-shell - issues 2728 None None None 2020-05-01 17:17:16 UTC

Description Mikhail 2020-05-01 17:03:29 UTC
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

Comment 1 Mikhail 2020-05-01 17:07:39 UTC
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'

Comment 2 Fedora Blocker Bugs Application 2020-05-01 17:11:38 UTC
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.

Comment 3 Adam Williamson 2020-05-23 00:19:41 UTC
Are you still having trouble with this? OpenVPN is working fine for me, but I don't have an openconnect VPN to test with...

Comment 4 Mikhail 2020-05-25 19:00:37 UTC
(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

Comment 5 Adam Williamson 2020-07-20 16:37:03 UTC
mikhail: can you connect from a console with nmcli as a workaround?

Comment 6 Geoffrey Marr 2020-07-20 18:58:38 UTC
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

Comment 7 Mikhail 2020-07-20 21:10:56 UTC
(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.

Comment 8 Mikhail 2020-07-20 21:17:46 UTC
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

Comment 9 Adam Williamson 2020-07-20 23:19:03 UTC
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!

Comment 10 Mikhail 2020-07-21 19:23:40 UTC
> 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)

Comment 11 Adam Williamson 2020-07-22 17:25:38 UTC
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?

Comment 12 Mikhail 2020-07-27 06:09:32 UTC
(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.

Comment 13 Geoffrey Marr 2020-08-03 17:05:24 UTC
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


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