shadowsocks-qt5 icon indicating copy to clipboard operation
shadowsocks-qt5 copied to clipboard
verified publisher icon shadowsocks

Error reporting "TCP connection timeout" while ss-qt5 seem to work normally

Open tengent opened this issue 7 years ago • 4 comments

My enviroment is Fedora 27 , ss-qt5 3.0.0 , libQtShadowsocks 2.0.2.

ss-qt5 seem to works , but sometime i have to refresh the firefox serveral times to load the page.

there is one error reporting keeps spamming both in journald and console.

if i use menu "Connection” -> "Test Latency" , the status finally will be "connected" while a prompt "Connection Timeout " while be imformed by Gnome console

i check the systemd-journald, ss-qt5 is keeping write log " TCP connection timeout" like below Jun 06 10:18:10 localhost.localdomain shadowsocks-qt5.desktop[23356]: TCP connection timeout. Jun 06 10:18:11 localhost.localdomain shadowsocks-qt5.desktop[23356]: TCP connection timeout. Jun 06 10:18:11 localhost.localdomain shadowsocks-qt5.desktop[23356]: TCP connection timeout. Jun 06 10:18:12 localhost.localdomain shadowsocks-qt5.desktop[23356]: TCP connection timeout. Jun 06 10:18:12 localhost.localdomain shadowsocks-qt5.desktop[23356]: TCP connection timeout. Jun 06 10:18:13 localhost.localdomain shadowsocks-qt5.desktop[23356]: TCP connection timeout. Jun 06 10:18:13 localhost.localdomain shadowsocks-qt5.desktop[23356]: TCP connection timeout. Jun 06 10:18:14 localhost.localdomain shadowsocks-qt5.desktop[23356]: TCP connection timeout. 2times per second

i use strace to find out it try to pollin 9 sockets with 995 millisecond timeout poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=12, events=POLLIN}, {fd=14, events=POLLIN}, {fd=17, events=POLLIN}, {fd=19, events=POLLIN}, {fd=24, events=POLLIN}, {fd=25, events=POLLIN}, {fd=26, events=POLLIN}], 9, 995) = 0 (Timeout) write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24 write(2, "TCP connection timeout.\n", 24) = 24

i check all these 9 filedescriptor they are all ESTABLISHED and without reconnection [tyang@localhost fd]$ netstat -tnp|grep 23356 (Not all processes could be identified, non-owned process info will not be shown, you would have to be root to see it all.) tcp 0 0 172.20.51.60:57970 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:48832 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:48448 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:47960 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:47446 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:49172 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:58030 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:49908 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:48864 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:50688 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:47580 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:59552 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:49906 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:49688 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:34912 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:48860 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:34964 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:56456 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:48856 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:49684 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:47518 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:48836 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:48848 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:58194 97.64.124.189:443 ESTABLISHED 23356/ss-qt5 tcp 0 0 172.20.51.60:47578 97.64.124.189:443 ESTABLISHED 23356/ss-qt5

So my guess is that ss-qt5 try to pollin in 9 sockects in 995 millisecond(approximately 1s) when poll(2) return timeout because timeout 995 is reached

if so， the prompt info may be confusable and could be set a level to debug lvl?

if not , any idea about to fix this?

Thx

tengent avatar Jun 06 '18 02:06 tengent

It seems very confusing and I don't remember I've set up any polling like that in the program.

librehat avatar Jun 26 '18 21:06 librehat

what can i do to provide more exact info?

tengent avatar Jul 03 '18 01:07 tengent

I don't think the logs were from this application. Could it be from Qt? Are you using the official Qt rpms or your own compiled version?

librehat avatar Jul 05 '18 22:07 librehat

my qt rpms are shipped by fedora

As you can see below:

[tyang@localhost systemd]$ ldd /usr/bin/ss-qt5 |grep -i qt
	libQt5Widgets.so.5 => /lib64/libQt5Widgets.so.5 (0x00007f600a35e000)
	libQt5Network.so.5 => /lib64/libQt5Network.so.5 (0x00007f6009fd6000)
	libQtShadowsocks.so.2 => /lib64/libQtShadowsocks.so.2 (0x00007f6009d9a000)
	libQt5DBus.so.5 => /lib64/libQt5DBus.so.5 (0x00007f60096c9000)
	libQt5Gui.so.5 => /lib64/libQt5Gui.so.5 (0x00007f6009009000)
	libQt5Core.so.5 => /lib64/libQt5Core.so.5 (0x00007f6008965000)

qt libs are from 3 pkgs

[tyang@localhost systemd]$ for i in `ldd /usr/bin/ss-qt5 |grep -i qt|awk '{print $3}'`; do rpm -qf $i; done|sort|uniq
libQtShadowsocks-2.0.2-1.fc27.x86_64
qt5-qtbase-5.9.6-1.fc27.x86_64
qt5-qtbase-gui-5.9.6-1.fc27.x86_64

And they all come from Fedora Official Repo

[tyang@localhost systemd]$ rpm -qi qt5-qtbase-5.9.6-1.fc27.x86_64
Name        : qt5-qtbase
Version     : 5.9.6
Release     : 1.fc27
Architecture: x86_64
Install Date: Wed 27 Jun 2018 06:19:46 PM CST
Group       : Unspecified
Size        : 9814408
License     : LGPLv2 with exceptions or GPLv3 with exceptions
Signature   : RSA/SHA256, Sat 16 Jun 2018 05:27:55 AM CST, Key ID f55e7430f5282ee4
Source RPM  : qt5-qtbase-5.9.6-1.fc27.src.rpm
Build Date  : Tue 12 Jun 2018 05:00:51 AM CST
Build Host  : buildhw-08.phx2.fedoraproject.org
Relocations : (not relocatable)
Packager    : Fedora Project
Vendor      : Fedora Project
URL         : http://qt-project.org/
Bug URL     : https://bugz.fedoraproject.org/qt5-qtbase
Summary     : Qt5 - QtBase components
Description :
Qt is a software toolkit for developing applications.

This package contains base tools, like string, xml, and network
handling.

tengent avatar Jul 18 '18 04:07 tengent