Unstable Connection

[merlink01]

All 20 Minutes the application tries to reconnect:

DEBUG 12:23:02.484 - Network state change event received :: 1 :: true
INFO 12:23:02.485 - Network connection lost

Testing Windows Version. 0.8.0

[merlink01]

Excuse me, all 20 seconds ;-)

[hitman401]

@merlink01, please try launcher 0.8.1. If you face the same problem, then please do re-open this issue.

You will have to register a new account since this connects to the test-8 network.

Thanks

[merlink01]

OK, testet again...

It got better but still not usable:

DEBUG 12:43:15.317775800 [routing::core core.rs:1103] Client(36e264..) Received LostPeer - PeerId(d80f..)
DEBUG 12:43:15.317775800 [routing::core core.rs:2337] Client(36e264..) Lost bootstrap connection to dd105a.. (PeerId(d80f..)).
TRACE 12:43:15.317775800 [safe_core::core::client::message_queue message_queue.rs:172] EventReceiverThread received: Event::Terminate
DEBUG 14:43:15.318 - Network state change event received :: 1 :: true
INFO 12:43:15.317775800 [safe_core::core::client::message_queue message_queue.rs:193] Received a Terminate event. Informing 2 observers.
INFO 12:43:15.317775800 [safe_core::ffi mod.rs:254] Informing Disconnected to 1 FFI network event observers.
INFO 14:43:15.318 - Network connection lost

[merlink01]

Sorry, can't reopen:

you can re-open your own issues *if you closed them yourself

[merlink01]

this log brings the client Launcher to a hang for ~ 3 Minutes until it brings connection lost and reconnect

DEBUG 14:54:46.828 - Invoking CLIENT STATS API:: PUTs COUNT::client-stats
TRACE 12:54:46.827532700 [safe_core::ffi mod.rs:447] FFI retrieve client issued POSTs.
DEBUG 14:54:46.829 - Sending message to FFI - 975aa6d8-7f66-4b27-aa45-1a52c45f483c - client-stats - puts
TRACE 12:54:46.829532800 [safe_core::ffi mod.rs:435] FFI retrieve client issued PUTs.
DEBUG 14:54:46.835 - FFI response code 0 for id - aee3b8f3-f774-4b66-af9b-581ab0e97b61
VERBOSE 14:54:46.836 - Invoking response callback :: callback id - aee3b8f3-f774-4b66-af9b-581ab0e97b61
DEBUG 14:54:46.838 - FFI response code 0 for id - ebb6c237-29b7-4541-b645-6bfeff5e7ce0
VERBOSE 14:54:46.838 - Invoking response callback :: callback id - ebb6c237-29b7-4541-b645-6bfeff5e7ce0
DEBUG 14:54:46.840 - FFI response code 0 for id - d414f333-6105-4743-8452-dac19ff2c903
VERBOSE 14:54:46.842 - Invoking response callback :: callback id - d414f333-6105-4743-8452-dac19ff2c903
DEBUG 14:54:46.846 - FFI response code 0 for id - 975aa6d8-7f66-4b27-aa45-1a52c45f483c
VERBOSE 14:54:46.847 - Invoking response callback :: callback id - 975aa6d8-7f66-4b27-aa45-1a52c45f483c
DEBUG 14:54:47.60 - Waiting for directory key for creating an session
DEBUG 14:54:47.61 - Invoking Auth::getAppDirectoryKey API
DEBUG 14:54:47.61 - Sending message to FFI - b7af252b-cb3c-48d3-acc0-65006e0caf78 - auth - app-dir-key
TRACE 12:54:47.061546100 [safe_core::ffi mod.rs:284] FFI Get app dir key to locate app's exclusive dir on the SAFE Network.
TRACE 12:54:47.061546100 [safe_core::ffi mod.rs:289] FFI app dir key is being fetched for app with name: SAFE Demo App.
TRACE 12:54:47.061546100 [safe_core::ffi::launcher_config_handler launcher_config_handler.rs:150] Get Launcher's config directory.
TRACE 12:54:47.061546100 [safe_core::nfs::helper::directory_helper directory_helper.rs:226] Getting a configuration directory (from withing configuration root dir) with name: LauncherReservedDirectory
.
TRACE 12:54:47.061546100 [safe_core::nfs::helper::directory_helper directory_helper.rs:165] Getting an unversioned directory listing.
DEBUG 12:54:47.061546100 [safe_core::nfs::helper::directory_helper directory_helper.rs:393] Getting structured data from the network ...
TRACE 12:54:47.061546100 [safe_core::core::client mod.rs:358] GET for Structured(345a2e.., 15101)
DEBUG 14:54:47.76 - FFI/mod/auth.js - Getting App Root Dir Key
DEBUG 12:55:00.232299400 [routing::core core.rs:1103] Client(36e264..) Received LostPeer - PeerId(d473..)
DEBUG 12:55:00.232299400 [routing::core core.rs:2337] Client(36e264..) Lost bootstrap connection to 19cfef.. (PeerId(d473..)).
TRACE 12:55:00.232299400 [safe_core::core::client::message_queue message_queue.rs:172] EventReceiverThread received: Event::Terminate
INFO 12:55:00.232299400 [safe_core::core::client::message_queue message_queue.rs:193] Received a Terminate event. Informing 2 observers.
DEBUG 14:55:00.232 - Network state change event received :: 1 :: true
INFO 12:55:00.232299400 [safe_core::ffi mod.rs:254] Informing Disconnected to 1 FFI network event observers.
INFO 14:55:00.233 - Network connection lost
ERROR 12:55:07.063690200 [routing::core core.rs:2200] Client(36e264..) - Unable to find connection to proxy node in proxy map
DEBUG 12:55:07.063690200 [routing::core core.rs:1909] Client(36e264..) Failed to send message: ProxyConnectionNotFound
DEBUG 14:55:10.239 - Restarting FFI client worker handles
DEBUG 14:55:10.239 - Sending message to FFI - 7ca7f9c2-b392-46a3-a307-ce4955d241ad - reset -
DEBUG 14:55:10.240 - Invoking Auth::login API
TRACE 12:55:10.239871800 [safe_core::ffi mod.rs:341] FFI Dropping client.
DEBUG 12:55:10.239871800 [safe_core::ffi mod.rs:125] FfiHandle is now being dropped.
DEBUG 14:55:10.240 - Sending message to FFI - c91b16ca-9590-4da8-a935-8ffebda54c94 - auth - login
TRACE 12:55:10.239871800 [safe_core::ffi mod.rs:250] FFI exiting the network event notifier thread.
TRACE 12:55:10.240871900 [safe_core::ffi mod.rs:217] FFI login a registered client.
TRACE 12:55:10.240871900 [safe_core::core::client mod.rs:78] Creating unregistered client.
TRACE 12:55:11.756958600 [safe_core::core::client mod.rs:87] Waiting to get connected to the Network...
DEBUG 12:55:13.134037400 [routing::core core.rs:562] Disconnected(491341..) Received BootstrapConnect from PeerId(fb7f..).
DEBUG 12:55:13.134037400 [routing::core core.rs:1122] Disconnected(491341..) - Sending ClientIdentify to PeerId(fb7f..).
DEBUG 12:55:13.227042700 [routing::core core.rs:1335] Client(491341..) - State changed to client, quorum size: 5.
TRACE 12:55:13.228042700 [safe_core::core::client::message_queue message_queue.rs:172] EventReceiverThread received: Event::Connected
TRACE 12:55:13.228042700 [safe_core::core::client mod.rs:95] Connected to the Network.
TRACE 12:55:13.271045200 [safe_core::core::client mod.rs:358] GET for Structured(59550b.., 0)
TRACE 12:55:16.070205300 [safe_core::core::client::message_queue message_queue.rs:172] EventReceiverThread received: Event::Response { response: GetSuccess(StructuredData { type_tag: 0, name: 59550b..
, data: 8273e6..29c609, previous_owner_keys: [], version: 2, current_owner_keys: ["baccd0..ef0c20"], previous_owner_signatures: ["705af3..57d202"] }, MessageId(986814..)), src: NaeManager(name: 59550b
..), dst: Client { client_name: 491341.., proxy_node_name: 636301.., peer_id: PeerId(b94f..) } }
TRACE 12:55:17.617293800 [safe_core::core::client mod.rs:219] Waiting to get connected to the Network...
ERROR 12:55:17.993315300 [routing::core core.rs:2200] Client(36e264..) - Unable to find connection to proxy node in proxy map
DEBUG 12:55:17.993315300 [routing::core core.rs:1909] Client(36e264..) Failed to send message: ProxyConnectionNotFound
DEBUG 12:55:18.999372800 [routing::core core.rs:562] Disconnected(36e264..) Received BootstrapConnect from PeerId(c5fc..).
DEBUG 12:55:18.999372800 [routing::core core.rs:1122] Disconnected(36e264..) - Sending ClientIdentify to PeerId(c5fc..).
DEBUG 12:55:19.096378400 [routing::core core.rs:1335] Client(36e264..) - State changed to client, quorum size: 5.
TRACE 12:55:19.096378400 [safe_core::core::client::message_queue message_queue.rs:172] EventReceiverThread received: Event::Connected
TRACE 12:55:19.096378400 [safe_core::core::client mod.rs:227] Connected to the Network.
TRACE 12:55:19.156381800 [safe_core::ffi mod.rs:234] FFI register a network event observer.
TRACE 12:55:19.156381800 [safe_core::ffi mod.rs:318] FFI Get safe-drive key to locate SAFEDrive on the SAFE Network.
DEBUG 14:55:19.157 - FFI/mod/auth.js - Registering observer
TRACE 12:55:19.156381800 [safe_core::ffi::helper helper.rs:47] Obtain directory key for SAFEDrive - This can be cached for efficiency. So if this is seen many times, check for missed optimisation oppo
rtunity.
TRACE 12:55:19.156381800 [safe_core::nfs::helper::directory_helper directory_helper.rs:192] Getting the user root directory listing.
TRACE 12:55:19.156381800 [safe_core::nfs::helper::directory_helper directory_helper.rs:165] Getting an unversioned directory listing.
DEBUG 14:55:19.158 - FFI/mod/auth.js - get SafeDrive Dir Key
DEBUG 12:55:19.156381800 [safe_core::nfs::helper::directory_helper directory_helper.rs:393] Getting structured data from the network ...
TRACE 12:55:19.156381800 [safe_core::core::client mod.rs:358] GET for Structured(96ced6.., 15101)
TRACE 12:55:19.905424700 [safe_core::core::client::message_queue message_queue.rs:172] EventReceiverThread received: Event::Response { response: GetSuccess(StructuredData { type_tag: 15101, name: 96ce
d6.., data: 000000..9d2d9f, previous_owner_keys: [], version: 4, current_owner_keys: ["baccd0..ef0c20"], previous_owner_signatures: ["367324..5da00b"] }, MessageId(873f51..)), src: NaeManager(name: 96
ced6..), dst: Client { client_name: 36e264.., proxy_node_name: 73e53e.., peer_id: PeerId(3c1b..) } }
TRACE 12:55:19.905424700 [safe_core::core::structured_data_operations::unversioned unversioned.rs:144] Getting unversioned StructuredData
DEBUG 14:55:19.907 - FFI response code 0 for id - c91b16ca-9590-4da8-a935-8ffebda54c94
TRACE 12:55:19.905424700 [safe_core::ffi mod.rs:415] FFI Dropping vector.
VERBOSE 14:55:19.907 - Invoking response callback :: callback id - c91b16ca-9590-4da8-a935-8ffebda54c94
DEBUG 14:55:19.908 - Invoking CLIENT STATS API:: Account Info ::client-stats
DEBUG 14:55:19.909 - Sending message to FFI - a19ca470-88e4-44df-983b-4832743ffe69 - client-stats - acc-info
DEBUG 14:55:19.914 - Network state change event received :: 0 :: true
INFO 14:55:19.915 - Connected with network
TRACE 12:55:19.914425200 [safe_core::ffi mod.rs:556] FFI get account information.
TRACE 12:55:19.915425200 [safe_core::core::client mod.rs:543] Account info GET issued.
DEBUG 14:55:19.916 - Dropping unregistered client
DEBUG 14:55:19.916 - Invoking Auth::dropUnregisteredClient API
DEBUG 14:55:19.917 - Sending message to FFI - 1744b53f-d714-42e0-a4ea-5cf728fb2a53 - auth - drop-unregistered-client
DEBUG 14:55:19.918 - Invoking CLIENT STATS API:: Account Info ::client-stats
DEBUG 14:55:19.918 - Sending message to FFI - ae4cbe1d-9419-4cd2-b1fa-31dd766f26ac - client-stats - acc-info
TRACE 12:55:19.918425400 [safe_core::ffi mod.rs:556] FFI get account information.
TRACE 12:55:19.919425500 [safe_core::core::client mod.rs:543] Account info GET issued.
DEBUG 14:55:19.923 - FFI response code 0 for id - 1744b53f-d714-42e0-a4ea-5cf728fb2a53
VERBOSE 14:55:19.924 - Invoking response callback :: callback id - 1744b53f-d714-42e0-a4ea-5cf728fb2a53
TRACE 12:55:20.402453100 [safe_core::core::client::message_queue message_queue.rs:172] EventReceiverThread received: Event::Response { response: GetAccountInfoSuccess { MessageId(4631da..), .. }, src:
ClientManager(name: 36e264..), dst: Client { client_name: 36e264.., proxy_node_name: 73e53e.., peer_id: PeerId(3c1b..) } }
DEBUG 14:55:20.403 - FFI response code 0 for id - a19ca470-88e4-44df-983b-4832743ffe69
VERBOSE 14:55:20.404 - Invoking response callback :: callback id - a19ca470-88e4-44df-983b-4832743ffe69
TRACE 12:55:20.411453600 [safe_core::core::client::message_queue message_queue.rs:172] EventReceiverThread received: Event::Response { response: GetAccountInfoSuccess { MessageId(fc85ac..), .. }, src:
ClientManager(name: 36e264..), dst: Client { client_name: 36e264.., proxy_node_name: 73e53e.., peer_id: PeerId(3c1b..) } }
DEBUG 14:55:20.413 - FFI response code 0 for id - ae4cbe1d-9419-4cd2-b1fa-31dd766f26ac
VERBOSE 14:55:20.414 - Invoking response callback :: callback id - ae4cbe1d-9419-4cd2-b1fa-31dd766f26ac
DEBUG 12:55:38.070463600 [safe_core::core::client::response_getter response_getter.rs:177] Response has timed out - firing wait canceller.
INFO 12:55:38.070463600 [safe_core::ffi mod.rs:395]
FFI cross-boundary error propagation:

---

ERRNO: -34 FfiError::DnsError -> DnsError::NfsError -> NfsError::CoreError -> Request has timed out - CoreError::RequestTimeout

DEBUG 14:55:38.71 - FFI response code -34 for id - 76bdbcfb-a55e-4ab9-9ffd-0d65f3179505
VERBOSE 14:55:38.72 - Invoking error response callback :: callback id - 76bdbcfb-a55e-4ab9-9ffd-0d65f3179505
WARN 14:55:38.75 - Err 400 - Msg :: [object Object]
DEBUG 14:56:19.919 - Invoking CLIENT STATS API:: GETs COUNT::client-stats
DEBUG 14:56:35.644 - Sending message to FFI - 00eba06a-25c9-4f92-af9b-7af7d209a9ee - client-stats - gets
DEBUG 14:56:35.648 - Invoking CLIENT STATS API:: DELETEs COUNT::client-stats
TRACE 12:56:35.648756900 [safe_core::ffi mod.rs:423] FFI retrieve client issued GETs.
DEBUG 14:56:35.649 - Sending message to FFI - dffc5ea3-a785-48c8-8220-3a113d5ec641 - client-stats - deletes
DEBUG 14:56:35.649 - Invoking CLIENT STATS API:: POSTs COUNT::client-stats
TRACE 12:56:35.649757000 [safe_core::ffi mod.rs:459] FFI retrieve client issued DELETEs.
DEBUG 14:56:35.650 - Sending message to FFI - 2ee15e49-229e-47a3-9ced-3be7605ca94e - client-stats - posts
DEBUG 14:56:35.651 - Invoking CLIENT STATS API:: PUTs COUNT::client-stats
TRACE 12:56:35.651757100 [safe_core::ffi mod.rs:447] FFI retrieve client issued POSTs.
DEBUG 14:56:35.651 - Sending message to FFI - 2ed63b8b-aea6-47d7-9fc4-3db46e30116d - client-stats - puts
TRACE 12:56:35.652757200 [safe_core::ffi mod.rs:435] FFI retrieve client issued PUTs.
DEBUG 14:56:35.669 - FFI response code 0 for id - 00eba06a-25c9-4f92-af9b-7af7d209a9ee
VERBOSE 14:56:35.671 - Invoking response callback :: callback id - 00eba06a-25c9-4f92-af9b-7af7d209a9ee
DEBUG 14:56:35.673 - FFI response code 0 for id - dffc5ea3-a785-48c8-8220-3a113d5ec641
VERBOSE 14:56:35.674 - Invoking response callback :: callback id - dffc5ea3-a785-48c8-8220-3a113d5ec641
DEBUG 14:56:35.676 - FFI response code 0 for id - 2ee15e49-229e-47a3-9ced-3be7605ca94e
VERBOSE 14:56:35.677 - Invoking response callback :: callback id - 2ee15e49-229e-47a3-9ced-3be7605ca94e
DEBUG 14:56:35.678 - FFI response code 0 for id - 2ed63b8b-aea6-47d7-9fc4-3db46e30116d
VERBOSE 14:56:35.679 - Invoking response callback :: callback id - 2ed63b8b-aea6-47d7-9fc4-3db46e30116d
DEBUG 12:56:47.069410200 [safe_core::core::client::response_getter response_getter.rs:177] Response has timed out - firing wait canceller.
INFO 12:56:47.069410200 [safe_core::ffi mod.rs:295]
FFI cross-boundary error propagation:

---

ERRNO: -34 FfiError::NfsError -> NfsError::CoreError -> Request has timed out - CoreError::RequestTimeout

ERROR 14:56:47.72 - FFI/mod/auth.js - Getting App Root Dir Key failed with code -34
DEBUG 14:56:47.74 - FFI response code -34 for id - b7af252b-cb3c-48d3-acc0-65006e0caf78
VERBOSE 14:56:47.74 - Invoking error response callback :: callback id - b7af252b-cb3c-48d3-acc0-65006e0caf78
ERROR 14:56:47.76 - Creating session :: {"errorCode":-34,"errorMsg":"Failed with error code -34"}
WARN 14:56:47.78 - Err 500 - Msg :: [object Object]
DEBUG 12:57:19.774076600 [routing::core core.rs:1103] Client(36e264..) Received LostPeer - PeerId(c5fc..)
DEBUG 12:57:19.774076600 [routing::core core.rs:2337] Client(36e264..) Lost bootstrap connection to 73e53e.. (PeerId(c5fc..)).
TRACE 12:57:19.774076600 [safe_core::core::client::message_queue message_queue.rs:172] EventReceiverThread received: Event::Terminate
INFO 12:57:19.774076600 [safe_core::core::client::message_queue message_queue.rs:193] Received a Terminate event. Informing 2 observers.
DEBUG 14:57:19.774 - Network state change event received :: 1 :: true
INFO 12:57:19.774076600 [safe_core::ffi mod.rs:254] Informing Disconnected to 1 FFI network event observers.
INFO 14:57:19.774 - Network connection lost

[Viv-Rajkumar]

Sorry, can't reopen:

Np, I've opened it now.

As for the issue itself. It seems like a weird one and the last two posts could almost be two seperate issues.

INFO 14:43:15.318 - Network connection lost

That should have nothing to do with launcher itself. It's a different module and its basically just reporting it lost connection to a bootstrap node in the network. Now ofcourse if the internet connection on the computer is fine and it still does not connect back to the network when hitting "Retry" or restarting launcher, it'd be a weird case thats not reproduced.

The second post looks like the original request has timed out. Unfortunately with this being in TEST-8, its hard to be accurate here since many other factors can influence that such as the groups having high churn or just generally not fast enough to respond before the local client considered it a timeout. Why the Launcher hung while this was going on is still not clear though.

Thanks for the bug report @merlink01 hopefully @krishnaIndia or someone from the team has more info to try and debug this issue.

[merlink01]

THX, if you need some more information call me.