Gnome-shell-extension-gsconnect: Underlying SSH stopped.

[Msouza91]

This might look like a duplicate of #518 but hear me out, cause the problem did not solve itself when I started adb.

I've installed the extension and the app, most functions run fine, mount however is among the failing pile. It does mount, but when I try to open the folder I've set up to the share I get the underlying SSH process exited and it unmounts.

A clear and concise description of what the bug is.

Steps To Reproduce:

1. Mount the device from the top pannel or personal keyboard shortcut
2. Double click on the folder to access the files
3. See error

Expected behavior

See the contents of the phone folder

Log from GsConnect

GSConnect Version: 30
GSConnect Install: user
GJS: 15803
XDG_SESSION_TYPE: wayland
GDMSESSION: gnome
--------------------------------------------------------------------------------
-- Logs begin at Wed 2019-12-18 09:30:10 -03, end at Sun 2020-01-05 18:34:16 -03. --
jan 05 18:33:15 systemd[154564]: Starting Tracker metadata database store and lookup manager...
jan 05 18:33:15 systemd[154564]: Started Tracker metadata database store and lookup manager.
jan 05 18:33:16 systemd[154564]: Starting Tracker metadata extractor...
jan 05 18:33:16 systemd[154564]: Started Tracker metadata extractor.
jan 05 18:33:26 systemd[154564]: tracker-extract.service: Succeeded.
jan 05 18:33:35 tracker-miner-f[154993]: g_str_has_suffix: assertion 'str != NULL' failed
jan 05 18:33:45 systemd[154564]: Started Application launched by gnome-shell.
jan 05 18:33:45 systemd[154564]: gnome-launched-org.gnome.Shell.Extensions.GSConnect.Preferences.desktop-170431.scope: Succeeded.
jan 05 18:33:45 systemd[1]: Starting Hostname Service...
jan 05 18:33:46 systemd[1]: Started Hostname Service.
jan 05 18:33:46 audit[1]: SERVICE_START 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'
jan 05 18:33:46 tracker-store[170383]: OK
jan 05 18:33:46 systemd[154564]: tracker-store.service: Succeeded.
jan 05 18:34:03 org.gnome.Shell.Extensions.GSConnect[155143]: [/service/protocol/core.js:send:329]: moto z3 play: {
                                                                "id": 1578260043065,
                                                                "type": "kdeconnect.sftp.request",
                                                                "body": {
                                                                  "startBrowsing": true
                                                                }
                                                              }
jan 05 18:34:03 org.gnome.Shell.Extensions.GSConnect[155143]: [/service/protocol/core.js:receive/<:283]: moto z3 play: {
                                                                "id": 1578260042715,
                                                                "type": "kdeconnect.sftp",
                                                                "body": {
                                                                  "ip": "192.168.xx.xx",
                                                                  "port": 1740,
                                                                  "user": "kdeconnect",
                                                                  "password": "<redacted>",
                                                                  "path": "/",
                                                                  "multiPaths": [
                                                                    "/downloads"
                                                                  ],
                                                                  "pathNames": [
                                                                    "downloads"
                                                                  ]
                                                                }
                                                              }
jan 05 18:34:10 tracker-miner-f[154993]: g_str_has_suffix: assertion 'str != NULL' failed
jan 05 18:34:10 org.gnome.Shell.Extensions.GSConnect[155143]: [/service/plugins/sftp.js:_unmount/</<:235]: Backend currently unmounting
                                                              _unmount/</<@/home/marco/.local/share/gnome-shell/extensions/[email protected]/service/plugins/sftp.js:235:21
                                                              @/home/marco/.local/share/gnome-shell/extensions/[email protected]/service/daemon.js:1142:2
jan 05 18:34:16 systemd[1]: systemd-hostnamed.service: Succeeded.
jan 05 18:34:16 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'

Logcat

--------- beginning of main
01-05 18:45:51.743 30578 30586 W System  : A resource failed to call close. 
01-05 18:46:39.729 30578 30642 I KDE/LanLink: Using port 1739
01-05 18:47:29.871 30578 30642 E KDE/sendPacket: Exception
01-05 18:47:29.871 30578 30642 E KDE/sendPacket: java.net.SocketTimeoutException: Poll timed out
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at libcore.io.IoBridge.poll(IoBridge.java:664)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at java.net.PlainSocketImpl.socketAccept(PlainSocketImpl.java:191)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:451)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at java.net.ServerSocket.implAccept(ServerSocket.java:547)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at java.net.ServerSocket.accept(ServerSocket.java:515)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at org.kde.kdeconnect.Backends.LanBackend.LanLink.sendPacket(LanLink.java:185)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at org.kde.kdeconnect.Device.sendPacketBlocking(Device.java:700)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at org.kde.kdeconnect.DevicePacketQueue$SendingThread.run(DevicePacketQueue.java:112)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at java.lang.Thread.run(Thread.java:764)
01-05 18:47:29.872 30578 30642 E KDE/sendPacket: No device link (of 1 available) could send the package. Packet kdeconnect.notification to ultra.pmf lost!
01-05 18:47:29.873 30578 30642 I KDE/LanLink: Using port 1739

System Details (please complete the following information):

• GSConnect version: 30
  
  
  
  • Installed from: GNOME Extensions Website
  
  
• GNOME/Shell version: 3.34.2
• Distro/Release: Fedora 31

GSConnect environment (if applicable):

• Paired Device(s): Moto Z3 Play, Android Pie November 1st security patch
• KDE Connect app version: 1.13.5

Additional Notes:
GsConnect and KDE app could only find each other after I made an exception to not pass app data through the VPN connection.

[andyholmes]

Hmm, can you try debugging GVfs to see if there are any relevant errors there? And you're sure ports 1739-1764 are also open for connection?

[Msouza91]

I'm not that savvy with firewall rules to be 100% sure the ports are open, but I am able to see the preconfigured folder from the phone inside nautilus, it's just when I try to double click on it that it fails.

I should mention that I've only gotten to this point after installing sshfs, it wouldn't even try to mount before.
Here's the log you asked for:
gvfsd.log

[Msouza91]

I've done some research apparently the ports are closed, do you have a pre made command for creating a zone with the range associated with these connections? Doesn't seem like a good idea leaving the ports open in the default zone. Oh, I'm using firewalld
Edit: Well, I went to check my default settings with firewall-cmd --list-ports and the range mentioned is inside the range that was already permitted (1025-65535), so it is not a matter of locked ports if I'm not mistaken horribly, that wouldn't be a shocker haha!

[andyholmes]

Are these ports also bypassing your VPN? It seems like the problem is happening in ssh which might require deeper debugging if this isn't an issue with your network.

[Msouza91]

I had the bypass on the phone and the PC was not connected to the VPN, I've tested disabling the VPN completely on the phone as well, but the issue persists. I can help debugging it as much as I am capable of, just point me to the right direction!

[Msouza91]

Are you too busy right now? What should I look into in the meantime?

[ferdnyc]

@Msouza91

Firewalld's configuration is somewhat confusing on certain points, ports being one of them, and the documentation is no help at all. I see the same ports: 1025-65535/udp 1025-65535/tcp in the configuration for the default "FedoraWorkstation" zone (which I don't use) on my system, too.

With a range like that, I can only think that the ports config represents an _outgoing_ port range — there's no point in running a firewall at all if it's going to allow _incoming_ connections to basically every user-accessible port. Restricting outbound connections to only non-privileged ports also makes a good deal of sense. So, that's presumably what that does.

But GSConnect needs incoming ports open so that it's reachable by other devices. Typically that's done in firewalld by creating a new service definition which accepts incoming connections on the ports for that service. Then the service is assigned to one or more zones, primarily the default zone(s) for any interface(s) you want GSConnect to listen on.

(I believe it _does_ have to be the default zone, at least for that interface, because again: incoming connection. The ports need to be open by default. Firewalld does have the ability to further restrict exposure on the network by assigning source IP ranges and other parameters to service definitions, if necessary. I've never used those features myself, but they could potentially offer additional security.)

For my setup I used the firewall-config GUI, since firewalld's firewall-cmd language is nebulous and verbose enough that it's one of the few times I actually feel the GUI is easier. I have no idea how you'd define this using firewall-cmd commands, I just know there'd be a lot of typing.

Fortunately, though, the config is output as fairly readable XML in /etc/firewalld/ so that's another way to exchange configs.

My /etc/firewalld/services/kdeconnect.xml contains:

<?xml version="1.0" encoding="utf-8"?>
<service>
  <port port="1716" protocol="tcp"/>
  <port port="1716" protocol="udp"/>
  <port port="1739-1764" protocol="tcp"/>
  <port port="1739-1764" protocol="udp"/>
</service>

The default zone for my ethernet connection is home.

(That's shown in the firewall-config interface, or the zone currently in use for the physical device can be looked up with firewall-cmd --get-active-zones. The interface's zone is actually assigned by Network-Manager when it brings up a connection on that interface, so the configuration parameter connection.zone in Network-Manager's nmcli c show NAME output is the canonical source for the zone assigned to a managed network connection.)

My /etc/firewalld/zones/home.xml therefore contains:

<?xml version="1.0" encoding="utf-8"?>
<zone>
  <short>Home</short>
  <description>For use in home areas. You mostly trust the other computers on networks to not harm your computer. Only selected incoming connections are accepted.</description>
[...]
  <service name="kdeconnect"/>
[...]
</zone>

(I'm NATted behind a gateway router with its own firewall, so the ports are only open to my local subnet. I _do_ trust the other computers on that network — they're all me.)

Looking at your gvfsd debug output, gvfsd-sftp _is_ making the initial connection to the service running on your phone, hence the icon showing up in Nautilus. It's just that the connection is quickly dropped again, seemingly from the remote end, whenever any further attempts are made to access that service.

That could be an issue of the phone failing to make a connection back to your PC, and dropping any open connections for what it considers to be an unreachable peer. In which case, opening the firewall ports would hopefully fix that.

Or it could be that particularly aggressive power-saving features aren't allowing the SSH service to stay running unless KDE Connect is the active foreground app. We've seen some of that. If that's the case, then it may help to check whatever settings your phone offers for battery-saving or application-monitoring features. Adding KDE Connect to whatever whitelist/blacklist will prevent the phone from aggressively restricting its background operations can often improve the reliability of KDE Connect's network services.

[andyholmes]

@Msouza91 sorry, I've been very busy lately and haven't had much time to get back to you.

As @ferdnyc says, this likely is still a network problem, but you can do some things to dig a little deeper and find out why.

For the record, we haven't used sshfs for sometime (actualy GVfs spawns a raw ssh process and uses that). But if installing it changed something, that's a good sign that sshfs might have been bundled with an exception for the firewall (like the XML Frank posted above).

Since sshfs will work, you can make a manual connection using that. This is roughyl what KDE Connect does:

$ sshfs [email protected]:/ ~/some_mount_point \
        -o port=0000 \
        -s -f -F /dev/null \
        -o IdentityFile=~/.config/gsconnect/private.pem \
        -o StrictHostKeyChecking=no \
        -o UserKnownHostsFile=/dev/null \
        -o uid=1000 \
        -o gid=1000
        -o password_stdin

The IP address (0.0.0.0), port (0000) and password you'll have to get from the response packet:

{
  "id" : 1578974518481,
  "type" : "kdeconnect.sftp",
  "body" : {
    "ip" : "192.168.0.68",
    "port" : 1752,
    "user" : "kdeconnect",
    "password" : "Stcu1IVGrXIHVNM78cLlHHBKnzxU",
    "path" : "/",
    "multiPaths" : [
      "/Primary"
    ],
    "pathNames" : [
      "Primary"
    ]
  }
}

Once the sshfs process starts you'll have to paste the password into the terminal and hit enter. To get the response packet you'll probably have to enable debug mode manually:

dconf write /org/gnome/shell/extensions/gsconnect/debug true

You should then try to mount the device in GSConnect. Whether that fails or not doesn't matter, as long as you get the response packet.

[Msouza91]

Well, I tried the GUI tool Frank recommended, really fool proof, but still
I couldn't connect, I managed to mount the share with sshfs but even using
the dconf command you asked me to run the response packet didn't show up,
so I got the IP and port from Nautilus while hovering the mouse over the
placeholder name of the share while mounted automatically by GsConnect. And
when I tried to click on the mounted share in nautilus it dismounted itself
aswell.

`sshfs [email protected]:/ ~/kde_test \
-o port=1739 \
-s -f -F /dev/null \
-o IdentityFile=~/.config/gsconnect/private.pem \
-o StrictHostKeyChecking=no \
-o UserKnownHostsFile=/dev/null \
-o uid=1000 \
-o gid=1000 \
-o password_stdin

Warning: Permanently added '[192.168.0.100]:1739' (RSA) to the list of
known hosts.

remote host has disconnected`

On Tue, 14 Jan 2020 at 01:15, Andy Holmes [e-mail] wrote:

@Msouza91 https://github.com/Msouza91 sorry, I've been very busy lately
and haven't had much time to get back to you.

As @ferdnyc https://github.com/ferdnyc says, this likely is still a
network problem, but you can do some things to dig a little deeper and find
out why.

For the record, we haven't used sshfs for sometime (actualy GVfs spawns a
raw ssh process and uses that). But if installing it changed something,
that's a good sign that sshfs might have been bundled with an exception
for the firewall (like the XML Frank posted above).

Since sshfs will work, you can make a manual connection using that. This
is roughyl what KDE Connect does:

$ sshfs [email protected]:/ ~/some_mount_point \
-o port=0000 \
-s -f -F /dev/null \
-o IdentityFile=~/.config/gsconnect/private.pem \
-o StrictHostKeyChecking=no \
-o UserKnownHostsFile=/dev/null \
-o uid=1000 \
-o gid=1000
-o password_stdin

The IP address (0.0.0.0), port (0000) and password you'll have to get
from the response packet:

{
"id" : 1578974518481,
"type" : "kdeconnect.sftp",
"body" : {
"ip" : "192.168.0.68",
"port" : 1752,
"user" : "kdeconnect",
"password" : "Stcu1IVGrXIHVNM78cLlHHBKnzxU",
"path" : "/",
"multiPaths" : [
"/Primary"
],
"pathNames" : [
"Primary"
]
}
}

Once the sshfs process starts you'll have to paste the password into the
terminal and hit enter. To get the response packet you'll probably have to
enable debug mode manually:

dconf write /org/gnome/shell/extensions/gsconnect/debug true

You should then try to mount the device in GSConnect. Whether that fails
or not doesn't matter, as long as you get the response packet.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/andyholmes/gnome-shell-extension-gsconnect/issues/746?email_source=notifications&email_token=AEU6H7DLGN27E7CHHEC2U7TQ5U35JA5CNFSM4KC5N75KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEI3GWJI#issuecomment-573991717,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AEU6H7HYYCTMAZWBEETBND3Q5U35JANCNFSM4KC5N75A
.

--

Marcos Souza

Prefeitura Municipal de Fortaleza

Fundação de Ciência, Tecnologia e Inovação - CITINOVA

Tel: [phone]
[e-mail].[email protected]

Whatsapp - (85)99225-8181 [e-mail]

[andyholmes]

It seems like the problem is happening in kdeconnect-android, so the next step would be to debug the Android app. With adb installed and your phone connected by USB this is done with:

$ adb logcat --pid=$(adb shell pidof -s org.kde.kdeconnect_tp)

Then you can just let GSConnect try to automount again. The above command will only show messages for the app though, so if there are no errors there you may have to drop the --pid part to catch errors in Android as a whole.

[Msouza91]

I've attached my logcat in the opening of the issue.

Logcat

--------- beginning of main
01-05 18:45:51.743 30578 30586 W System  : A resource failed to call close. 
01-05 18:46:39.729 30578 30642 I KDE/LanLink: Using port 1739
01-05 18:47:29.871 30578 30642 E KDE/sendPacket: Exception
01-05 18:47:29.871 30578 30642 E KDE/sendPacket: java.net.SocketTimeoutException: Poll timed out
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at libcore.io.IoBridge.poll(IoBridge.java:664)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at java.net.PlainSocketImpl.socketAccept(PlainSocketImpl.java:191)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:451)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at java.net.ServerSocket.implAccept(ServerSocket.java:547)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at java.net.ServerSocket.accept(ServerSocket.java:515)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at org.kde.kdeconnect.Backends.LanBackend.LanLink.sendPacket(LanLink.java:185)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at org.kde.kdeconnect.Device.sendPacketBlocking(Device.java:700)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at org.kde.kdeconnect.DevicePacketQueue$SendingThread.run(DevicePacketQueue.java:112)
01-05 18:47:29.871 30578 30642 E KDE/sendPacket:        at java.lang.Thread.run(Thread.java:764)
01-05 18:47:29.872 30578 30642 E KDE/sendPacket: No device link (of 1 available) could send the package. Packet kdeconnect.notification to ultra.pmf lost!
01-05 18:47:29.873 30578 30642 I KDE/LanLink: Using port 1739

[andyholmes]

Hmm, I'm not 100% sure, but I believe the above error may be from the device becoming disconnected during the icon transfer for a notification.

If that was the only error in the log, you may have to remove the --pid ... part to see the SFTP server error.

[Msouza91]

I've sent the output from adb logcat > logcat.txt to the contact email you specified in your github profile since I'm not sure if there is any sensitive information, probably there isn't but not opted for not trying my luck haha. I've mentioned the hash code of the issue ( _pound sign_ 746) so it is not so much of a hassle to find it.

[andyholmes]

Hmm, there doesn't seem to be any logging being done by kdeconnect or Apache MINA at all. My best guess is that whatever is causing the Sftp server to close the connection is not something it considers a fatal error.

The source for the server is quite simple, so I'm not sure there's anything more I can do to help here unfortunately. My best advice would be to eliminate all possible network complications like VPNs, firewalls, etc to try and narrow down what is causing this, since it doesn't seem to be a programming error in either GSConnect or kdeconnect-android.

[andyholmes]

Possibly related: https://bugs.kde.org/show_bug.cgi?id=417787

[andyholmes]

Has this changed with the release of kdeconnect-android 1.14?

[Msouza91]

Unfortunately, I've changed my setup... Thanks to COVID-19 I finally took the time to install Arch and run i3, and even before, having to keep switching from 4g to Wi-Fi at work so I could use it proved to be quite the hassle, maybe this troubleshooting we did can help someone else.

[andyholmes]

Okay, no problem :)

[DotIN13]

I was experiencing the same issue and tried the troubleshooting procedure provided in this issue.

I am using a Xiaomi Mix3 with latest MIUI12.0.1.0 stable on Android 10. My kdeconnect version is 1.14.2 and my gsconnect version is 36.

My kde-android adb logcat was exactly the same as issuecomment-576242305. And my full adb logcat indicated that SharePlugin did not have permission to create files in Downloads directory. So I thought it was the sandbox mechanism of Android 10 and I manually customized destination directory from default emulated/0/Downloads to tree: Downloads. But still I get failed receiving file error. This time the full adb logcat was different and as follows:

08-20 11:11:55.293  4786 24974 E Shareplugin: Error receiving file
08-20 11:11:55.293  4786 24974 E Shareplugin: java.lang.SecurityException: Document 24 is not a descendant of downloads
08-20 11:11:55.293  4786 24974 E Shareplugin:   at android.os.Parcel.createException(Parcel.java:2074)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at android.os.Parcel.readException(Parcel.java:2042)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at android.database.DatabaseUtils.readExceptionFromParcel(DatabaseUtils.java:188)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at android.database.DatabaseUtils.readExceptionWithFileNotFoundExceptionFromParcel(DatabaseUtils.java:151)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at android.content.ContentProviderProxy.openAssetFile(ContentProviderNative.java:631)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at android.content.ContentResolver.openAssetFileDescriptor(ContentResolver.java:1536)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at android.content.ContentResolver.openOutputStream(ContentResolver.java:1242)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at android.content.ContentResolver.openOutputStream(ContentResolver.java:1218)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at org.kde.kdeconnect.Plugins.SharePlugin.CompositeReceiveFileJob.run(CompositeReceiveFileJob.java:155)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:462)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at java.util.concurrent.FutureTask.run(FutureTask.java:266)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
08-20 11:11:55.293  4786 24974 E Shareplugin:   at java.lang.Thread.run(Thread.java:919)

And the aforementioned error repeated for Document 25, Document 26 and Document 27.

not decendants of downloads reminded me that MIUI12 might be restricting file creation in downloads folder, so I created a KDEConnect folder in device root and customized destination directory to it. Now I am able to normally send files to my phone.

So thank you guys for providing debugging details and hope this could help other KDE/GSConnect or Xiaomi users.