Shadowsocks-libev: ss-libev version 2.6.2 (1.19) did not start on boot

[seicowing]

Please answer these questions before submitting your issue. Thanks!

What version of shadowsocks-libev are you using?

2.6.2

What operating system are you using?

Debian8

What did you do?

reboot

What did you expect to see?

ss-server starts automatically during startup

What did you see instead?

ss-server did not start during startup

shadowsocks-libev.service - Shadowsocks-libev Default Server Service
Loaded: loaded (/lib/systemd/system/shadowsocks-libev.service; enabled)
Active: active (running) since Thu 2017-01-19 21:17:54 CST; 16s ago
Docs: man:shadowsocks-libev(8)
Main PID: 584 (ss-server)
CGroup: /system.slice/shadowsocks-libev.service
└─584 /usr/bin/ss-server -a root -c /etc/shadowsocks-libev/config.json -u -A --plugin obfs-server --plugin-opts obfs=http
ss-server[485]: 2017-01-19 13:11:20 INFO: onetime authentication enabled
ss-server[485]: 2017-01-19 13:11:20 INFO: plugin "obfs-server" enabled
ss-server[485]: 2017-01-19 13:11:20 INFO: UDP relay enabled
ss-server[485]: 2017-01-19 13:11:20 INFO: initializing ciphers... rc4-md5

or

hadowsocks-libev.service - Shadowsocks-libev Default Server Service
Loaded: loaded (/lib/systemd/system/shadowsocks-libev.service; enabled)
Active: active (running) since Thu 2017-01-19 14:18:42 CST; 6min ago
Docs: man:shadowsocks-libev(8)
Main PID: 580 (ss-server)
CGroup: /system.slice/shadowsocks-libev.service
├─ 580 /usr/bin/ss-server -a root -c /etc/shadowsocks-libev/config.json -u
└─1042 obfs-server

Jan 19 14:18:42 f986bb8d-42b0 ss-server[580]: 2017-01-19 14:18:42 INFO: onetime authentication enabled
Jan 19 14:18:42 f986bb8d-42b0 ss-server[580]: 2017-01-19 14:18:42 INFO: plugin "obfs-server" enabled
Jan 19 14:18:42 f986bb8d-42b0 ss-server[580]: 2017-01-19 14:18:42 INFO: UDP relay enabled
Jan 19 14:18:42 f986bb8d-42b0 ss-server[580]: 2017-01-19 14:18:42 INFO: initializing ciphers... chacha20
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: tcp port reuse enabled
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: tcp server listening at 127.0.0.1:53526
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: udp port reuse enabled
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: udp server listening at 0.0.0.0:3389
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: running from root user
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 [simple-obfs] INFO: obfuscating enabled
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 [simple-obfs] INFO: tcp port reuse enabled
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 [simple-obfs] INFO: listening at 0.0.0.0:3389
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 [simple-obfs] INFO: running from root user
ss-server and obfs-server do not start at the same time.

What is your config in detail (with all sensitive info masked)?

ss-server with obfs

[seicowing]

actually, if with obfs or not with obfs,ss-server did not start after rebooting on time.
sometimes ss-server would start at least 3 or 4 minutes after rebooting ,maybe longer.

[madeye]

What is your config in detail (with all sensitive info masked)?

[seicowing]

{
"server":"0.0.0.0",
"server_port":443,
"local_port":1080,
"password":"xxxxxx",
"timeout":60,
"method":"chacha20",
"auth":true,
"plugin":"obfs-server",
"plugin_opts":"obfs=http"
}

[madeye]

1. According to your log, ss-server started successfully.
2. If you're not using a domain name as server, the delay should not come from shadowsocks. Double check your systemd configs or report it to the distribution maintainer.

[seicowing]

I knew that ss-server started successfully, but it seemed that these processes delayed.
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: tcp port reuse enabled
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: tcp server listening at 127.0.0.1:53526
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: udp port reuse enabled
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: udp server listening at 0.0.0.0:3389
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: running from root user
I did not change any detail on systemd configs and there was no this issue before version 2.6.2 which was updated yesterday. It's so confusing.

[seicowing]

[Unit]
Description=Shadowsocks-libev Default Server Service
Documentation=man:shadowsocks-libev(8)
After=network.target

[Service]
Type=simple
EnvironmentFile=/etc/default/shadowsocks-libev
User=root
LimitNOFILE=32768
ExecStart=/usr/bin/ss-server -a $USER -c $CONFFILE $DAEMON_ARGS

[Install]

Is there anything wrong with this systemd config?

[madeye]

After=network.target

It means shadowsocks will only start after a connection is established. You may remove this line and try again.

[seicowing]

I have tried,but it did not work.
I noticed this :
CGroup: /system.slice/shadowsocks-libev.service
├─ 580 /usr/bin/ss-server -a root -c /etc/shadowsocks-libev/config.json -u
└─1042 obfs-server

Jan 19 14:18:42 f986bb8d-42b0 ss-server[580]: 2017-01-19 14:18:42 INFO: initializing ciphers... chacha20
Jan 19 14:22:09 localhost ss-server[580]: 2017-01-19 14:22:09 INFO: tcp port reuse enabled

Is it possible that this issue caused by obfs-server plugin? After all this systemed config for ss-server is the same with older version's and the issue did not happen before.

[seicowing]

the normal startup sequence is :

Main PID: 1059 (ss-server)
CGroup: /system.slice/shadowsocks-libev.service
├─1059 /usr/bin/ss-server -a root -c /etc/shadowsocks-libev/config...
└─1060 obfs-server

but after rebooting startup sequence is:
CGroup: /system.slice/shadowsocks-libev.service
├─ 580 /usr/bin/ss-server -a root -c /etc/shadowsocks-libev/config.json -u
└─1042 obfs-server

[madeye]

I don't think so. As you said,

actually, if with obfs or not with obfs,ss-server did not start after rebooting on time.
sometimes ss-server would start at least 3 or 4 minutes after rebooting ,maybe longer.

W/o obfs-server, shadowsocks works as before. And actually, obfs-server is forked from the parent process, which won't block the main thread.

[madeye]

You may try http://supervisord.org/ instead.

[seicowing]

Yes, obfs-server did not block the main thead and ss-server did start successfully .but obfs-server had a startup delay then caused the ss-server won't work after rebooting.

[seicowing]

Could you try to install ss-server on a debian 8 server and rebooting, see if this issue appears.

[lesswest]

@Jieee006
ln -s /usr/local/bin/obfs-server /usr/bin
试一下

[seicowing]

@lesswest It does not work. did you have this issue? and did you resolve it?

[lesswest]

@Jieee006 我做了这一步之后，就解决了。
https://github.com/shadowsocks/shadowsocks-libev/issues/1082

[seicowing]

@lesswest Debian8? I will try it again.

[lesswest]

@Jieee006 ubuntu 14.04 、ubuntu 16.04

[seicowing]

@lesswest Did you have this issue before,such as 2.6.1 or 2.6.0 ? you installed version 2.6.2 which updated these two days?

[lesswest]

@Jieee006 2.6.2，之前没有。

[seicowing]

@lesswest @madeye It still does not work for debian. But It should be caused by obfs-server.

[seicowing]

I have installed obfs-server in usr/bin/ directly ,but it does not work either.

[madeye]

OK, it turns out to be blocked by randombytes_buf. @wongsyrone Any suggestion?

EDIT: Seems not, still debugging.

EDIT2: It's blocked by sodium_init. So it's still an issue of initializing random data generator. It happens usually on new VPS. @wongsyrone again.

IMO, for this issue, the best solution is using your shadowsocks much harder, e.g., play video stream all the day through your shadowsocks. 😄

[wongsyrone]

Try latest libsodium release. In general, libsodium uses /dev/urandom on *nix, it is initialised when kernel finishes its startup.

BTW, I never have this kind of issue no matter running on VPS or router.

[wongsyrone]

One possible cause is Shadowsocks starts too early. Or some deadlock issues? I have no idea.

[seicowing]

@madeye it is possible.I created a new server for tests.I will do what you suggested.

[seicowing]

@wongsyrone I have installed libsodium 1.0.11 ,so I have no idea either.Just try madeye's suggestion later.

[wongsyrone]

I am using systemd for auto startup, you should let shadowsocks start after network.target. There may have bugs on plugin starting code.

[seicowing]

Yes, the default systemd config is that shadowsocks starts after network.target. I have had many tests on my servers,has the same issue. may have bugs indeed.
[Unit]
Description=Shadowsocks-libev Default Server Service
Documentation=man:shadowsocks-libev(8)
After=network.target

[Service]
Type=simple
EnvironmentFile=/etc/default/shadowsocks-libev
User=root
LimitNOFILE=32768
ExecStart=/usr/bin/ss-server -a $USER -c $CONFFILE $DAEMON_ARGS

[madeye]

It's blocked by libsodium, which has nothing to do with shadowsocks-libev.

An interesting workaround is adding this line to your /etc/rc.local

wget -O /dev/null http://cachefly.cachefly.net/100mb.test

[wongsyrone]

It may block at https://github.com/jedisct1/libsodium/blob/db97a3550207486261d6b44d0e9771be36800d65/src/libsodium/sodium/utils.c#L378

[wongsyrone]

sodium_init() doesn't perform any memory allocations. However, on Unix systems, it may open /dev/urandom and keep the descriptor open, so that the device remains accessible after a chroot() call. Multiple calls to sodium_init() do not cause additional descriptors to be opened.

sodium_init() returns 0 on success, -1 on failure, and 1 if the library had already been initialized.

[seicowing]

It's blocked by libsodium ,then any another suggestion? Are we able to fix this issue ?

[madeye]

Try the workaround in https://github.com/shadowsocks/shadowsocks-libev/issues/1103#issuecomment-274293406

[seicowing]

@madeye Thanks. I have tried it already.The workaround can make it start earlier due to downloading something first. Interesting ! But essentially this issue still exists.

[madeye]

It takes 10s to generate enough random numbers with wget in my local test. I think a 10s delay is not a real problem considering the security provided by the current libsodium approach.

If you believe it's really an issue for you, maybe open an issue to libsodium project instead.

[madeye]

Here is the feedback from libsodium team on a similar issue reported to them months ago:

https://github.com/jedisct1/libsodium-php/issues/94#issuecomment-236379030

[seicowing]

OK.Thanks I saw the feedback.It is not a libsodium bug?The best workaround here now is that add a line to /etc/rc.local
wget -O /dev/null http://cachefly.cachefly.net/100mb.test ?

[wongsyrone]

OK. entropy changed https://lkml.org/lkml/2016/7/25/43

[wongsyrone]

Libsodium documentation describes all questions in detail.

Before returning, the function _ensures_ that the system's random number generator has been properly seeded.

On some Linux systems, this _may take some time_, especially when called right after a reboot of the system. That issue has been reported on Digital Ocean virtual machines as well as on Scaleway ARM instances.

This can be confirmed with the following command:

cat /proc/sys/kernel/random/entropy_avail
If the command returns 0 or a very low number (< 160), and you are not running an obsolete kernel, this is very likely to be the case.

In a virtualized environment, make sure that the virtio-rng interface is available. If this is a cloud service and the hypervisor settings are out of your reach, consider switching to a difference service.

On a bare-metal host such as Scaleway instances, a possible workaround is to install the rng-tools package:

apt-get install rng-tools
And check the value of /proc/sys/kernel/random/entropy_avail again. If the value didn't go any higher, install haveged:

apt-get install haveged
Haveged should only be used as a very last resort. It hasn't received any updates for 10+ years, and shouldn't be trusted as a single entropy source, especially on virtualized environments.

Jitterentropy is a better alternative, but most Linux distributions don't offer it as an installable package yet.

https://github.com/jedisct1/libsodium-doc/blob/master/usage/README.md