search

alexbelgium / hassio-addons

My homeassistant addons
MIT License
1.53k stars 216 forks source link

🐛 [Transmission Openvpn] Transmission client is killed upon VPN restart (because of inactivity) #435

Closed almico closed 2 years ago

almico commented 2 years ago

Which addon?

Describe the bug

When the VPN tries to restart, everything is taken down.

To Reproduce

Wait for the VPN to restart.

Full addon log

I'm pasting the relevant part of the log. I can post the beginning, if needed.

[22/Aug/2022:14:09:08 +0200] 200 192.168.16.2, 172.30.32.1(172.30.32.2) POST /rpc HTTP/1.1 (Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/104.0.0.0 Safari/537.36)
Mon Aug 22 14:16:26 2022 [xyz.somevpn.com] Inactivity timeout (--ping-restart), restarting
Mon Aug 22 14:16:26 2022 SIGTERM received, sending exit notification to peer
Mon Aug 22 14:16:27 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.3.2 255.255.255.0 init
resolv.conf was restored
Sending kill signal to transmission-daemon
Waiting 5s for transmission-daemon to die
Sending kill signal (SIGKILL) to transmission-daemon
Mon Aug 22 14:16:30 2022 /sbin/ip route del [redacted]/32
Mon Aug 22 14:16:30 2022 /sbin/ip route del 0.0.0.0/1
Mon Aug 22 14:16:30 2022 /sbin/ip route del 128.0.0.0/1
Mon Aug 22 14:16:30 2022 Closing TUN/TAP interface
Mon Aug 22 14:16:30 2022 /sbin/ip addr del dev tun0 10.8.3.2/24
Mon Aug 22 14:16:30 2022 SIGTERM[soft,exit-with-notification] received, process exiting
2022/08/22 14:22:48 [error] 720#720: *3726 connect() failed (111: Connection refused) while connecting to upstream, client: 172.30.32.2, server: db21ed7f-transmission-openvpn, request: "GET /web/tr-web-control/script/easyui/locale/easyui-lang-en.js?_=1661170966625 HTTP/1.1", upstream: "http://127.0.0.1:9091/transmission/web/tr-web-control/script/easyui/locale/easyui-lang-en.js?_=1661170966625", host: "192.168.16.103:8123", referrer: "http://192.168.16.103:8123/api/hassio_ingress/fA4Z8Xm1mGT71HBH5mm9EYeMk4T-A9z2ElJhC7rpKYI/web/"
[22/Aug/2022:14:22:48 +0200] 502 192.168.16.2, 172.30.32.1(172.30.32.2) GET /web/tr-web-control/script/easyui/locale/easyui-lang-en.js?_=1661170966625 HTTP/1.1 (Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/104.0.0.0 Safari/537.36)
2022/08/22 14:22:48 [error] 720#720: *3726 connect() failed (111: Connection refused) while connecting to upstream, client: 172.30.32.2, server: db21ed7f-transmission-openvpn, request: "GET /web/tr-web-control/script/easyui/locale/easyui-lang-en.js?_=1661170966626 HTTP/1.1", upstream: "http://127.0.0.1:9091/transmission/web/tr-web-control/script/easyui/locale/easyui-lang-en.js?_=1661170966626", host: "192.168.16.103:8123", referrer: "http://192.168.16.103:8123/api/hassio_ingress/fA4Z8Xm1mGT71HBH5mm9EYeMk4T-A9z2ElJhC7rpKYI/web/"
[22/Aug/2022:14:22:48 +0200] 502 192.168.16.2, 172.30.32.1(172.30.32.2) GET /web/tr-web-control/script/easyui/locale/easyui-lang-en.js?_=1661170966626 HTTP/1.1 (Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/104.0.0.0 Safari/537.36)

Full addon config

DEBUG: false
DNS_server: 8.8.4.4,1.1.1.1
LOCAL_NETWORK: 192.168.0.0/16
OPENVPN_PASSWORD: [redacted]
OPENVPN_USERNAME: [redacted]
PGID: "1000"
PUID: "1000"
TRANSMISSION_DOWNLOAD_DIR: /mnt/shared/transmission/downloads
TRANSMISSION_HOME: /config/addons_config/transmission
TRANSMISSION_INCOMPLETE_DIR: /mnt/shared/transmission/incomplete
TRANSMISSION_WATCH_DIR: /mnt/shared/transmission/watch_dir
TRANSMISSION_WEB_UI: transmission-web-control
OPENVPN_CUSTOM_PROVIDER: true
OPENVPN_CUSTOM_PROVIDER_OVPN_LOCATION: [redacted]
TRANSMISSION_V3_UPDATE: true
cifspassword: [redacted]
cifsusername: [redacted]
networkdisks: //192.168.16.18/shared

System

alexbelgium commented 2 years ago

Hi, is this a new behavior ? As this seems an upstream behavior. Or it is due to the "latest" image and I'll revert to the "4.0" one. Thanks

almico commented 2 years ago

I can't answer with absolute certainty. I moved from a Raspberry PI 4B to a VM inside an Intel i5. All I know is I faced it today for the first time 😃

alexbelgium commented 2 years ago

Do you have a custom config file for which you could remove the ’--ping-restart‘ directive that is mentioned at the top of your excerpt?

almico commented 2 years ago

Do you want me to try deleting it? As far as I remember, it's set by the VPN provider in its config.

almico commented 2 years ago

The same issue happened with "4.0-v17". This is from the logs:

Mon Aug 29 07:47:12 2022 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Mon Aug 29 07:47:12 2022 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Mon Aug 29 07:47:12 2022 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 4096 bit RSA
Mon Aug 29 07:55:16 2022 Connection reset command was pushed by server ('[N]')
Mon Aug 29 07:55:16 2022 SIGTERM received, sending exit notification to peer
Mon Aug 29 07:55:17 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.3.2 255.255.255.0 init
resolv.conf was restored
Sending kill signal to transmission-daemon
Waiting 5s for transmission-daemon to die
Successfuly closed transmission-daemon
Mon Aug 29 07:55:21 2022 /sbin/ip route del [redacted]/32
Mon Aug 29 07:55:21 2022 /sbin/ip route del 0.0.0.0/1
Mon Aug 29 07:55:21 2022 /sbin/ip route del 128.0.0.0/1
Mon Aug 29 07:55:21 2022 Closing TUN/TAP interface
Mon Aug 29 07:55:21 2022 /sbin/ip addr del dev tun0 10.8.3.2/24
Mon Aug 29 07:55:21 2022 SIGTERM[soft,exit-with-notification] received, process exiting
2022/08/29 08:48:12 [error] 742#742: *36987 connect() failed (111: Connection refused) while connecting to upstream, client: 172.30.32.2, server: db21ed7f-transmission-openvpn, request: "GET /web/ HTTP/1.1", upstream: "http://127.0.0.1:9091/transmission/web/", host: "192.168.16.18:8123", referrer: "http://192.168.16.18:8123/db21ed7f_transmission_openvpn"

I'm going to upgrade to "4.0-v18" and see what happens.

almico commented 2 years ago

This issue is still there, using 4.0-v19

alexbelgium commented 2 years ago

Thanks ; however I honestly have no idea of what could help. I could revert the image back to 4.0 instead of latest if you'd prefer

almico commented 2 years ago

If I got it correctly, in /etc/cont-init.d/99-run.sh you execute /./etc/openvpn/start.sh & echo "". That script, in turn, executes exec openvpn ${TRANSMISSION_CONTROL_OPTS} ${OPENVPN_OPTS} --config "${CHOSEN_OPENVPN_CONFIG}" that, I think, triggers tunnelUp.sh. So far, everything is ok. The problem should be that openvpn is shut down either because of some inactivity timeout, or because of an explicit (remote?) reset request. That triggers the execution of tunnelDown.sh, and that's the end of the story 😄 All that should be needed is a restart of openvpn (a new exec openvpn...?). Maybe from within tunnelDown.sh?

alexbelgium commented 2 years ago

Hi, this looks like https://github.com/haugene/docker-transmission-openvpn/issues/2063

The recommandation is to have an automation to restart the container... https://haugene.github.io/docker-transmission-openvpn/faq/#set_the_ping-exit_option_for_openvpn_and_restart-flag_in_docker

Can't you activate the HA option of "guard dog" that restarts the container in case of issues?

alexbelgium commented 2 years ago

Thanks for the analysis, I've replaced the tunnel own script by an automatic addon restart. This is comparable to openvpn restart but avoids deal g with potential network issues. Could you please test? Thanks!

Actually I could try just to restart just the openvpn but globally it's the same, except that restarting the addon should avoid ip leakage

almico commented 2 years ago

Upgrading now 😃

github-actions[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

almico commented 2 years ago

@alexbelgium There must be a bug in the "resurrect" script 😄 

Mon Sep 19 18:17:39 2022 [antanex.com] Inactivity timeout (--ping-restart), restarting
Mon Sep 19 18:17:39 2022 SIGTERM received, sending exit notification to peer
Mon Sep 19 18:17:40 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.1.3 255.255.255.0 init
parse error: Expected string key before ':' at line 1, column 4
[16:17:40] ERROR: Unknown HTTP error occured
Mon Sep 19 18:17:40 2022 WARNING: Failed running command (--up/--down): external program exited with error status: 1
Mon Sep 19 18:17:40 2022 Exiting due to fatal error

The only option, for me, is manually restart the addon.

alexbelgium commented 2 years ago

Hi, I've pushed a new version, could you please test it? Thanks

almico commented 2 years ago

Thank you. I upgraded last night. Will post findings 😃

github-actions[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

almico commented 2 years ago

Hi @alexbelgium 😃 Unfortunately, the issue is still there:

Wed Oct 12 02:08:41 2022 [somevpn.org] Inactivity timeout (--ping-restart), restarting
Wed Oct 12 02:08:41 2022 SIGTERM received, sending exit notification to peer
Wed Oct 12 02:08:42 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.0.4 255.255.255.0 init
parse error: Expected string key before ':' at line 1, column 4
[00:08:42] ERROR: Unknown HTTP error occured
Wed Oct 12 02:08:42 2022 WARNING: Failed running command (--up/--down): external program exited with error status: 1
Wed Oct 12 02:08:42 2022 Exiting due to fatal error

The only option is a manual restart.

alexbelgium commented 2 years ago

You could try to check the content of the /etc/openvpn/tunnelDown.sh file using portainer. If I find some time I'll reinstall the addon to test

almico commented 2 years ago

I already looked at that file, but it makes no sense to me. If I execute it manually, it succeeds, but this is true while everything is working fine. My best guess is that script is executed in a different system state, and, most likely, it is some other script that is, called by it, failing. In other words, I fear the "parse error" is not coming directly from /etc/openvpn/tunnelDown.sh, but from, say bashio::addon.restart.

alexbelgium commented 2 years ago

Hi, please try this version I've added api access to see if it changes anything

almico commented 2 years ago

Will report as soon as anything relevant happens 😃

almico commented 2 years ago 
Thu Oct 13 16:46:18 2022 [somevpn.org] Inactivity timeout (--ping-restart), restarting
Thu Oct 13 16:46:18 2022 SIGTERM received, sending exit notification to peer
Thu Oct 13 16:46:19 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.2.2 255.255.255.0 init
parse error: Expected string key before ':' at line 1, column 4
[14:46:19] ERROR: Unknown HTTP error occured
Thu Oct 13 16:46:19 2022 WARNING: Failed running command (--up/--down): external program exited with error status: 1
Thu Oct 13 16:46:19 2022 Exiting due to fatal error

Same as before. I really cannot understand in what file is expected to be that ":" at line 1, column 4 😭

alexbelgium commented 2 years ago

I wonder if this is because the bashio command requires root, and the script is launched from a user... I think it means it can't read the options.json file, which requires root access, or that the /data is chmod -R 755

almico commented 2 years ago

Some result, different error message, this time:

Sun Oct 16 02:43:32 2022 [somevpn.org] Inactivity timeout (--ping-restart), restarting
Sun Oct 16 02:43:32 2022 SIGTERM received, sending exit notification to peer
Sun Oct 16 02:43:33 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.2.4 255.255.255.0 init
Sun Oct 16 02:43:33 2022 WARNING: Failed running command (--up/--down): could not execute external program
Sun Oct 16 02:43:33 2022 Exiting due to fatal error
almico commented 2 years ago

Transmission Openvpn Current version: 4.0-v28

Mon Oct 17 10:22:17 2022 [somevpn.org] Inactivity timeout (--ping-restart), restarting
Mon Oct 17 10:22:17 2022 SIGTERM received, sending exit notification to peer
Mon Oct 17 10:22:18 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.1.4 255.255.255.0 init
[08:22:18] FATAL: Tunnel down, addon restarting in 15 seconds
parse error: Expected string key before ':' at line 1, column 4
[08:22:33] ERROR: Unknown HTTP error occured
resolv.conf was restored
Sending kill signal to transmission-daemon
Waiting 5s for transmission-daemon to die
Successfuly closed transmission-daemon
Mon Oct 17 10:22:35 2022 /sbin/ip route del 7.25.11.62/32
Mon Oct 17 10:22:36 2022 /sbin/ip route del 0.0.0.0/1
Mon Oct 17 10:22:36 2022 /sbin/ip route del 128.0.0.0/1
Mon Oct 17 10:22:36 2022 Closing TUN/TAP interface
Mon Oct 17 10:22:36 2022 /sbin/ip addr del dev tun0 10.8.1.4/24
Mon Oct 17 10:22:36 2022 SIGTERM[soft,exit-with-notification] received, process exiting

This time, the addon died differently, but died 😄

almico commented 2 years ago

Transmission Openvpn Current version: 4.0-v25

Tue Oct 18 14:38:24 2022 [somevpn.org] Inactivity timeout (--ping-restart), restarting
Tue Oct 18 14:38:24 2022 SIGTERM received, sending exit notification to peer
Tue Oct 18 14:38:25 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.3.6 255.255.255.0 init
[12:38:25] FATAL: Tunnel down, addon restarting in 15 seconds
/./usr/bin/restart_addon: line 9: __BASHIO_LIB_DIR: readonly variable
resolv.conf was restored
Sending kill signal to transmission-daemon
Waiting 5s for transmission-daemon to die
Successfuly closed transmission-daemon
Tue Oct 18 14:38:44 2022 /sbin/ip route del 7.25.1.61/32
Tue Oct 18 14:38:44 2022 /sbin/ip route del 0.0.0.0/1
Tue Oct 18 14:38:44 2022 /sbin/ip route del 128.0.0.0/1
Tue Oct 18 14:38:44 2022 Closing TUN/TAP interface
Tue Oct 18 14:38:44 2022 /sbin/ip addr del dev tun0 10.8.3.6/24
Tue Oct 18 14:38:44 2022 SIGTERM[soft,exit-with-notification] received, process exiting

What I see in the UI is: image

I think the UI is there, but the underlying Transmission is gone 😄

almico commented 2 years ago

I see there is a new version of the add-on. Installing now 😄

alexbelgium commented 2 years ago

Hi, indeed it seems the container env doesn't get pulled in and I try to force it manually through trials and errors given I can't find a way to replicate it using portainer

alexbelgium commented 2 years ago

No more errors but not working anyway ;)

almico commented 2 years ago

Transmission Openvpn Current version: 4.0-v27

Wed Oct 19 09:05:59 2022 Connection reset command was pushed by server ('[N]')
Wed Oct 19 09:05:59 2022 SIGTERM received, sending exit notification to peer
Wed Oct 19 09:06:00 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.3.3 255.255.255.0 init
[07:06:00] FATAL: Tunnel down, addon restarting in 15 seconds
resolv.conf was restored
Sending kill signal to transmission-daemon
Waiting 5s for transmission-daemon to die
Successfuly closed transmission-daemon
Wed Oct 19 09:06:19 2022 /sbin/ip route del 4.23.15.6/32
Wed Oct 19 09:06:19 2022 /sbin/ip route del 0.0.0.0/1
Wed Oct 19 09:06:19 2022 /sbin/ip route del 128.0.0.0/1
Wed Oct 19 09:06:19 2022 Closing TUN/TAP interface
Wed Oct 19 09:06:19 2022 /sbin/ip addr del dev tun0 10.8.3.3/24
Wed Oct 19 09:06:19 2022 SIGTERM[soft,exit-with-notification] received, process exiting

Basically, it looks like transmission-daemon is taken down, but never started again.

alexbelgium commented 2 years ago

It also looks as if the curl command for the supervisor restart of the addon doesn't work ;-)

Another solution could be to link the finish script with the start one but the it would be an endless loop

almico commented 2 years ago

It also looks as if the curl command for the supervisor restart of the addon doesn't work ;-)

Do you have the command, and the error? Can I find them somewhere?

alexbelgium commented 2 years ago

Hi, the bashio::addon.restart function is described in this library : https://github.com/hassio-addons/bashio/blob/main/lib/addons.sh

If we follow the different logic, it seems to arrive to this command : curl --silent --show-error \ --write-out '\n%{http_code}' --request "${method}" \ -H "${auth_header}" \ -H "Content-Type: application/json" \ -d "${data}" \ "${__BASHIO_SUPERVISOR_API}${resource}" where $method = POST ; $resource=/addons/transmission_openvpn/restart ; $auth_header, $__BASHIO_SUPERVISOR_API are described in the container env

almico commented 2 years ago

It also looks as if the curl command for the supervisor restart of the addon doesn't work ;-)

To be honest, this is something I saw in previous reports. Now, I can no longer see any trace of that in my report.

almico commented 2 years ago

As far as I can see, the failure pattern is always the same now:

Wed Oct 19 09:05:59 2022 Connection reset command was pushed by server ('[N]')
Wed Oct 19 09:05:59 2022 SIGTERM received, sending exit notification to peer
Wed Oct 19 09:06:00 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.3.3 255.255.255.0 init
[07:06:00] FATAL: Tunnel down, addon restarting in 15 seconds
resolv.conf was restored
Sending kill signal to transmission-daemon
Waiting 5s for transmission-daemon to die
Successfuly closed transmission-daemon
Wed Oct 19 09:06:19 2022 /sbin/ip route del 4.23.15.6/32
Wed Oct 19 09:06:19 2022 /sbin/ip route del 0.0.0.0/1
Wed Oct 19 09:06:19 2022 /sbin/ip route del 128.0.0.0/1
Wed Oct 19 09:06:19 2022 Closing TUN/TAP interface
Wed Oct 19 09:06:19 2022 /sbin/ip addr del dev tun0 10.8.3.3/24
Wed Oct 19 09:06:19 2022 SIGTERM[soft,exit-with-notification] received, process exiting

In the log above, I do not see any message about "Restarting Transmission daemon". I would expect something like that, since there is a "Sending kill signal to transmission-daemon".

almico commented 2 years ago

New error message in logs, this time!

Tue Oct 25 18:54:27 2022 [somevpn.org] Inactivity timeout (--ping-restart), restarting
Tue Oct 25 18:54:27 2022 SIGTERM received, sending exit notification to peer
Tue Oct 25 18:54:29 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.0.3 255.255.255.0 init
/etc/openvpn/tunnelDown.sh: /./usr/bin/restart_addon: /usr/bin/with-contenv: bad interpreter: No such file or directory
resolv.conf was restored
Sending kill signal to transmission-daemon
Waiting 5s for transmission-daemon to die
Successfuly closed transmission-daemon
Tue Oct 25 18:54:33 2022 /sbin/ip route del 6.23.1.12/32
Tue Oct 25 18:54:33 2022 /sbin/ip route del 0.0.0.0/1
Tue Oct 25 18:54:33 2022 /sbin/ip route del 128.0.0.0/1
Tue Oct 25 18:54:33 2022 Closing TUN/TAP interface
Tue Oct 25 18:54:33 2022 /sbin/ip addr del dev tun0 10.8.0.3/24
Tue Oct 25 18:54:33 2022 SIGTERM[soft,exit-with-notification] received, process exiting
almico commented 2 years ago

Hi again @alexbelgium 😃 So, it all boils down to this

/./usr/bin/restart_addon: /usr/bin/with-contenv: bad interpreter: No such file or directory

where the key point is that /usr/bin/with-contenv does not exist anywhere in the system.

alexbelgium commented 2 years ago

Thanks, I'll put back the previous one, but it still won't solve why the bashio command to restart the add-on doesn't work...

alexbelgium commented 2 years ago

Commit to restore the shebang : https://github.com/alexbelgium/hassio-addons/commit/72bd04aa30b2e3a431412c777a333e68b1a20b8a

almico commented 2 years ago

We're back to the old version of the issue 😭 

Thu Nov  3 09:00:35 2022 [somevpn.org] Inactivity timeout (--ping-restart), restarting
Thu Nov  3 09:00:35 2022 SIGTERM received, sending exit notification to peer
Thu Nov  3 09:00:36 2022 /etc/openvpn/tunnelDown.sh tun0 1500 1585 10.8.3.2 255.255.255.0 init
[08:00:36] FATAL: Tunnel down, addon restarting in 15 seconds
resolv.conf was restored
Sending kill signal to transmission-daemon
Waiting 5s for transmission-daemon to die
Successfuly closed transmission-daemon
Thu Nov  3 09:00:55 2022 /sbin/ip route del 9.23.11.2/32
Thu Nov  3 09:00:55 2022 /sbin/ip route del 0.0.0.0/1
Thu Nov  3 09:00:55 2022 /sbin/ip route del 128.0.0.0/1
Thu Nov  3 09:00:55 2022 Closing TUN/TAP interface
Thu Nov  3 09:00:55 2022 /sbin/ip addr del dev tun0 10.8.3.2/24
Thu Nov  3 09:00:55 2022 SIGTERM[soft,exit-with-notification] received, process exiting
alexbelgium commented 2 years ago

Ah, ah, I see you are persistent with this issue. I'm really sorry that I don't know how to solve this. Perhaps I could add a local ping with cron but I fear the impact on the addon resources

alexbelgium commented 2 years ago

Hi, if you activate the new auto_restart bool, it should check every hour if the vpn is up. If not, it should automatically restart the addon. Could you please try? Thanks

almico commented 2 years ago

It doesn't work:

Updating variables
Using PUID 1000 and PGID 1000
[13:01:37] INFO: Custom openvpn provider selected
Copying ovpn file to proper location
Exporting variable for custom provider : somevpn.org
[13:01:37] INFO: Auto restarting addon if openvpn down for more than 1h
chmod: cannot access '/etc/cron.hourly/cronupdate': No such file or directory
/etc/cont-init.d/99-run.sh: exiting 1
alexbelgium commented 2 years ago

I had already pushed a new version, sorry

alexbelgium commented 2 years ago

New version pushed to have the cron show in addon log

alexbelgium commented 2 years ago

Doesn't work, same error

alexbelgium commented 1 year ago

I think it now works. I've pushed a new version

almico commented 1 year ago

Installing 4.0-v40 now 😃

almico commented 1 year ago

Ah ah ah 😆 Then, I will install 4.0-v41!

alexbelgium commented 1 year ago

Both have the same code but 41 has an additional message to say after rebooting that it was rebooted