session-destroy is not sent

[zolia]

Node provider / consumer versions: Mysterium Node 0.21.0-1snapshot-20200220T0755-7e017106 (latest master)

Provider: OSX
Consumer: debian 10

After successful connection consumer fails to send session-destroy.
Actual session-destroy message is being sent way too late. It should be sent before even attempting to disconnect openvpn session.

2020-02-20T12:50:57.038 DBG consumer/statistics/tracker.go:78        > bytes received 2.2 MB, sent 374.5 kB
2020-02-20T12:50:57.038 DBG consumer/bandwidth/tracker.go:95         > Download speed: 41.1 kbps
2020-02-20T12:50:57.039 DBG consumer/bandwidth/tracker.go:96         > Upload speed: 17.4 kbps
2020-02-20T12:50:57.826 INF core/connection/manager.go:426           > Connection state: Connected → Disconnecting
2020-02-20T12:50:57.864 DBG firewall/iptables/iptables.go:34         > "sudo /sbin/iptables -D OUTPUT -s 88.198.207.96 -j MYST_CONSUMER_KILL_SWITCH" output:

2020-02-20T12:50:57.865 INF logconfig/openvpnlog.go:54               > [openvpn-mgmt] Shutdown
2020-02-20T12:50:57.865 INF logconfig/openvpnlog.go:54               > [openvpn-mgmt] Shutdown finished
2020-02-20T12:50:57.865 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:57 2020 event_wait : Interrupted system call (code=4)
2020-02-20T12:50:57.865 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:57 2020 SIGTERM received, sending exit notification to peer
2020-02-20T12:50:57.902 WRN logconfig/openvpnlog.go:45               > Failed to remove tun device: [sudo ip tuntap delete dev tun0 mode tun] Returned exit error: exit status 1 Cmd output: ioctl(TUNSETIFF): Device or resource busy

2020-02-20T12:50:57.928 DBG firewall/iptables/iptables.go:34         > "sudo /sbin/iptables -D MYST_CONSUMER_KILL_SWITCH -d 88.119.191.24 -j ACCEPT" output:

2020-02-20T12:50:57.928 DBG session/pingpong/invoice_payer.go:294    > Stopping...
2020-02-20T12:50:57.928 DBG consumer/statistics/reporter.go:132      > Session statistics reporter stopping
2020-02-20T12:50:57.932 DBG consumer/session/session_storage.go:88   > Session 7db7fca8-568e-4aaa-ad48-586a1fe6396e updated
2020-02-20T12:50:57.932 INF core/connection/manager.go:426           > Connection state: Disconnecting → NotConnected
2020-02-20T12:50:57.932 INF cmd/di.go:843                            > Reconnecting HTTP clients due to VPN connection state change
2020-02-20T12:50:57.932 DBG core/location/oracle_resolver.go:41      > Detecting with oracle resolver
2020-02-20T12:50:57.933 INF communication/nats/connector.go:85       > Attempting to reconnect to broker (2 connections)
2020-02-20T12:50:57.933 INF communication/nats/connector.go:91       > Re-establishing broker connection fb099fbe-8a25-4375-92ea-f57201116987
2020-02-20T12:50:57.934 INF communication/nats/connector.go:91       > Re-establishing broker connection 75a54a0b-b820-403a-9912-1ed3b8de31ff
2020-02-20T12:50:58.946 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:58 2020 /etc/mysterium-node/nonpriv-ip route del 88.119.191.24/32
2020-02-20T12:50:58.962 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:58 2020 /etc/mysterium-node/nonpriv-ip route del 0.0.0.0/1
2020-02-20T12:50:58.976 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stderr: RTNETLINK answers: No such process
2020-02-20T12:50:58.977 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:58 2020 ERROR: Linux route delete command failed: external program exited with error status: 2
2020-02-20T12:50:58.978 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:58 2020 /etc/mysterium-node/nonpriv-ip route del 128.0.0.0/1
2020-02-20T12:50:58.991 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stderr: RTNETLINK answers: No such process
2020-02-20T12:50:58.992 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:58 2020 ERROR: Linux route delete command failed: external program exited with error status: 2
2020-02-20T12:50:58.993 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:58 2020 Closing TUN/TAP interface
2020-02-20T12:50:58.993 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:58 2020 /etc/mysterium-node/nonpriv-ip addr del dev tun0 10.8.0.3/24
2020-02-20T12:50:59.006 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stderr: RTNETLINK answers: Cannot assign requested address
2020-02-20T12:50:59.008 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:59 2020 Linux ip addr del failed: external program exited with error status: 2
2020-02-20T12:50:59.009 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:59 2020 /etc/mysterium-node/update-resolv-conf tun0 1500 1552 10.8.0.3 255.255.255.0 init
2020-02-20T12:50:59.068 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:59 2020 SIGTERM[soft,exit-with-notification] received, process exiting
2020-02-20T12:50:59.069 DBG logconfig/openvpnlog.go:63               > [openvpn-proc] Stdout: Thu Feb 20 12:50:59 2020 MANAGEMENT: >STATE:1582199459,EXITING,exit-with-notification,,,,,
2020-02-20T12:50:59.069 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line received: >STATE:1582199459,EXITING,exit-with-notification,,,,,
2020-02-20T12:50:59.069 WRN logconfig/openvpnlog.go:45               > [openvpn-mgmt] Connection failed to read: EOF
2020-02-20T12:50:59.069 DBG logconfig/openvpnlog.go:63               > [openvpn-mgmt] Line delivering: >STATE:1582199459,EXITING,exit-with-notification,,,,,
2020-02-20T12:50:59.069 INF logconfig/openvpnlog.go:54               > [openvpn-mgmt] Event consumer is done
2020-02-20T12:50:59.070 WRN logconfig/openvpnlog.go:45               > [openvpn-mgmt] Middleware stop error: connection is gone
2020-02-20T12:50:59.070 WRN logconfig/openvpnlog.go:45               > [openvpn-mgmt] Middleware stop error: write tcp 127.0.0.1:40907->127.0.0.1:33380: write: broken pipe
2020-02-20T12:50:59.070 DBG core/connection/manager.go:532           > onStateChanged called
2020-02-20T12:50:59.071 INF logconfig/openvpnlog.go:54               > [openvpn-proc] Stderr: stream ended
2020-02-20T12:50:59.072 INF logconfig/openvpnlog.go:54               > [openvpn-proc] Stdout: stream ended
2020-02-20T12:50:59.072 INF core/connection/manager.go:472           > Connection exited
2020-02-20T12:51:00.934 INF communication/nats/connector.go:93       > Re-establishing broker connection fb099fbe-8a25-4375-92ea-f57201116987 DONE (check result=nats: timeout)
2020-02-20T12:51:00.935 INF communication/nats/connector.go:93       > Re-establishing broker connection 75a54a0b-b820-403a-9912-1ed3b8de31ff DONE (check result=nats: timeout)
2020-02-20T12:51:00.935 INF communication/nats/connector.go:97       > All broker connections re-established
2020-02-20T12:51:00.935 DBG core/connection/manager.go:507           > State updater stopCalled
2020-02-20T12:51:03.037 DBG core/location/cache.go:95                > Location update succeeded: {88.198.207.96 24940 Hetzner Online GmbH EU DE Unknown hosting}
2020-02-20T12:51:03.059 INF market/mysterium/mysterium_api.go:306    > Session stats sent: 7db7fca8-568e-4aaa-ad48-586a1fe6396e
2020-02-20T12:51:03.059 DBG consumer/statistics/reporter.go:102      > Final stats sent
2020-02-20T12:51:03.936 WRN communication/nats/sender.go:81          > Connection failed error="nats: timeout"
2020-02-20T12:51:03.937 DBG communication/nats/sender.go:84          > Request "3e3b89ea-4640-4cfe-a160-3b72c9d1a776.session-destroy" sending: {"payload":{"session_id":"7db7fca8-568e-4aaa-ad48-586a1fe6396e"},"signature":"TFAT8D0ksIKREO1MrR3sBsVGxFaCpbTdXMXI3Fxr65lvt4hGAtI2v9MvoVU+PMuuvvfTLPXR198d0iWlZoWb9wA="}



2020-02-20T12:51:13.937 INF session/destroy_producer.go:50           > Session destroy request failed error="failed to send request '3e3b89ea-4640-4cfe-a160-3b72c9d1a776.session-destroy': nats: timeout"
2020-02-20T12:51:13.938 WRN core/connection/manager.go:291           > Cleanup error error="failed to send request '3e3b89ea-4640-4cfe-a160-3b72c9d1a776.session-destroy': nats: timeout"
2020-02-20T12:51:13.938 INF communication/nats/connector.go:71       > Removing broker connection from the registry: fb099fbe-8a25-4375-92ea-f57201116987
2020-02-20T12:51:13.942 WRN communication/nats/connection_wrap.go:86 > NATS: disconnected
2020-02-20T12:51:13.942 WRN communication/nats/connection_wrap.go:85 > NATS: connection closed
2020-02-20T12:51:13.979 DBG firewall/iptables/iptables.go:34         > "sudo /sbin/iptables -D MYST_CONSUMER_KILL_SWITCH -d testnet-broker.mysterium.network -j ACCEPT" output:


2020-02-20T12:51:24.779 WRN communication/nats/connection_wrap.go:86 > NATS: disconnected
2020-02-20T12:51:24.812 WRN communication/nats/connection_wrap.go:87 > NATS: reconnected