SAFE Network Dev Update - April 25, 2019

Development Updates
22

I just tried the following successfully, perhaps you are mixing mock with non-mock?

$ export SAFE_AUTH_PASSWORD="aaaaaa"
$ export SAFE_AUTH_SECRET="bbbbb"
$ echo "{ \"secret\":\"$SAFE_AUTH_SECRET\", \"password\":\"$SAFE_AUTH_PASSWORD\" }" > myconfig.json
$ cat myconfig.json 
{ "secret":"bbbbb", "password":"aaaaaa" }
$ cargo run --features mock-network -- -c myconfig.json -i nnnnnnn -y
    Finished dev [unoptimized + debuginfo] target(s) in 0.45s
     Running `target/debug/safe_auth -c myconfig.json -i nnnnnnn -y`
Account was created successfully!
$ cargo run --features mock-network -- -c myconfig.json -y
    Finished dev [unoptimized + debuginfo] target(s) in 0.42s
     Running `target/debug/safe_auth -c myconfig.json -y`
Logged in the SAFE Network successfully!
2 Likes
23

I only use non-mock on community network.

In your example, could you try unsetting the environment variables before relaunching the program? I guess that they are used in priority (otherwise you would get a warning that storing your secret/password in plaintext in a config file is not secure).

5 Likes
24

Ah yes, I can reproduce it now, thanks a lot @tfa , Iā€™ll take a look at it tomorrow and fix it! (FYI: Reading the credentials from a config file doesn't work if SAFE_AUTH_* env vars are unset Ā· Issue #39 Ā· maidsafe-archive/safe-authenticator-cli Ā· GitHub)

8 Likes
25

Hey @tfa, Iā€™m still waiting for other folks to review it before being able to merge it, but if you wanna give it a try this is the fix: fix(config): getting rid of the string quotes when reading account credentials from a config file by bochaco Ā· Pull Request #40 Ā· maidsafe-archive/safe-authenticator-cli Ā· GitHub

8 Likes
26

fyi: I also did get that error and after applying your fix, it didnā€™t occur anymore.
And I did get the following extra output:
Warning! Storing your secret/password in plaintext in a config file is not secure.

2 Likes
27

who else is feeling bullish on all these meetups? Like with such a small market if you can reach out to 10 new people each to have a really good look at the potential benefits of this project oh man we will see some action like we have not in a while on the markets.

1 Like
28

100% I would be all over this if there was something available in my area. This community is second to none, but we could be doing so much more.

1 Like
29

Yes, I have used your fork and it works. Thanks a lot @bochaco.

I have used it to add a new tab in the web app for the community network. It is named ā€œContactsā€ and it shows if nodes in the contact list are operational and the duration of the connection of an account.

For each node, a safe_auth.crust.config file is created with only this node and a CLI session is launched. A 30s delay is defined between each loop over the set of nodes and a 5s delay is defined between each node within the loop.

The connection itself lasts about 24s. Thatā€™s a bit high, maybe the community network is not performant enough. But the narrow band for the values is very strange. It could be interesting to check if this happens for other networks too (Mock, Alpha 2 or local ones), there could be something fishy with the CLI.

Note that the number of cumulative connected clients in the vaultsā€™ logs, which was stagnant, will progress much more rapidly from now on because of these automatic connections.

7 Likes
30

This morning connect time is much better: around 4.5s for each contact node.

Edit:
Maybe internet traffic is globally reduced during a public holiday.

When I look at my logs, the rupture is very brutal: Yesterday connect time was around 24s for more than 2 hours and suddenly the value changed to around 4.4s and didnā€™t varied since this event.

Here is the transition time:

2019-04-30T23:22:21.601907217Z [{ "ip": "95.216.189.149:5483", "time": "24.376" }, { "ip": "116.203.25.212:5483", "time": "24.259" }, { "ip": "95.216.206.201:5483", "time": "24.378" }, { "ip": "116.203.56.138:5483", "time": "24.298" }]
2019-04-30T23:24:09.117438150Z [{ "ip": "95.216.189.149:5483", "time": "24.395" }, { "ip": "116.203.25.212:5483", "time": "24.303" }, { "ip": "95.216.206.201:5483", "time": "4.401" }, { "ip": "116.203.56.138:5483", "time": "4.360" }]
2019-04-30T23:25:16.605919531Z [{ "ip": "95.216.189.149:5483", "time": "4.398" }, { "ip": "116.203.25.212:5483", "time": "4.266" }, { "ip": "95.216.206.201:5483", "time": "4.441" }, { "ip": "116.203.56.138:5483", "time": "4.330" }]

There is something fishy somewhere. It could be the CLI, the safe network, the Hetzner cloud, the docker stack, ā€¦

5 Likes
31

Even stranger: since the transition mentioned above there has been only 2 connections that lasted 24s, all other connections lasted 4s.

This means that all connections last either 4s or 24s, there are not intermediate values. I am sure of that because following command gives no result:

docker logs a23f44b96166 | egrep -v '"time": "(24|4)\.'

(the log lines have the format shown in my previous post)

The timings given by the CLI should be investigated. There may be something in the network that limits in an abnormal way the throughput for account connections.

1 Like
32

Just in case Iā€™m missunderstanding, @tfa are you talking about the safe_auth CLI or some other CLI you have? beceause if itā€™s the safe_auth CLI I donā€™t think it has anything to do with those metrics as it only gives you the credentials for the app to the connect to the network but it doesnā€™t participate in the connection.

33

I am talking about the safe_auth CLI. Here is my script:

# To get the real part of time function
TIMEFORMAT=%R
# Decompose IP list in 2 to not generate separator on last IP
FIRST_IPS="95.216.189.149:5483 116.203.25.212:5483 95.216.206.201:5483"
LAST_IP="116.203.56.138:5483"
while true
do
    REQ="["
    for IP in $FIRST_IPS $LAST_IP
    do
        echo "{
        \"hard_coded_contacts\": [ \"$IP\" ],
        \"whitelisted_node_ips\": null,
        \"whitelisted_client_ips\": null,
        \"tcp_acceptor_port\": null,
        \"service_discovery_port\": null,
        \"bootstrap_cache_name\": null,
        \"force_acceptor_port_in_ext_ep\": false,
        \"network_name\": \"tfa\",
        \"dev\": null
        }" > safe_auth.crust.config
        TIME_RES=$({ time ./safe_auth --config /run/secrets/SAFE_AUTH_CONFIG; } 2>&1)
        if [ $? -ne 0 ];
        then
            TIME_RES="Error"
        else
            # Suppress the warning about secret/password in plaintext in a config file not secure
            TIME_RES=$(echo $TIME_RES | sed -r -e "s/.* ([0-9\.]+)$/\1/")
        fi
        SEPA=", "
        if [ $IP == $LAST_IP ]; then SEPA=""; fi
        REQ="$REQ{ \"ip\": \"$IP\", \"time\": \"$TIME_RES\" }$SEPA"
        sleep 5
    done
    REQ="$REQ]"
    echo "$REQ"
    sleep 30
done

Note: The complex interpretation of TIME_RES is to get rid of the warning about secret/password in plaintext. IMO this message should be suppressed. Itā€™s a pain to manage and developers are aware of this. Personally, I store config file in a docker secret.

Yes, it does. Otherwise, how would it give the PUT balance or the apps authorizations.

34

Ah ok, I didnā€™t understand what you were doing, so you are meassuring the timings on the commands that the safe_auth CLI iself does, ok, cool.

Yes, I agree, we should have an option/flag to remove it, Iā€™ll raise this as an issue so we can add something like --silent

2 Likes
35

The strange behavior mentioned a long time ago is still occurring in the community network. During months connection time was 4s but for 2 days it has been 24s again.

Transition was exactly at 2019-07-18 18:55. Most nodes are managed by Hetzner but not all, and I canā€™t believe that a problem on Hetzner network would create a constant supplementary delay.

I think there is an issue in the code, maybe some unfortunate timers in crust or an external library like mio. 24s to connect is too long and constant connection times are not normal. Did @maidsafe observed similar figures in their tests?

Here is an excerpt of my check-contact container logs that shows the transition:

2019-07-18T18:48:20.613915530Z [{ "ip": "95.216.189.149:5483", "time": "4.625" }, { "ip": "116.203.25.212:5483", "time": "4.452" }, { "ip": "95.216.206.201:5483", "time": "4.659" }, { "ip": "116.203.56.138:5483", "time": "4.459" }]
2019-07-18T18:49:28.872645072Z [{ "ip": "95.216.189.149:5483", "time": "4.626" }, { "ip": "116.203.25.212:5483", "time": "4.454" }, { "ip": "95.216.206.201:5483", "time": "4.621" }, { "ip": "116.203.56.138:5483", "time": "4.458" }]
2019-07-18T18:50:37.121512814Z [{ "ip": "95.216.189.149:5483", "time": "4.651" }, { "ip": "116.203.25.212:5483", "time": "4.455" }, { "ip": "95.216.206.201:5483", "time": "4.628" }, { "ip": "116.203.56.138:5483", "time": "4.421" }]
2019-07-18T18:51:45.351568838Z [{ "ip": "95.216.189.149:5483", "time": "4.636" }, { "ip": "116.203.25.212:5483", "time": "4.420" }, { "ip": "95.216.206.201:5483", "time": "4.632" }, { "ip": "116.203.56.138:5483", "time": "4.461" }]
2019-07-18T18:52:53.670204775Z [{ "ip": "95.216.189.149:5483", "time": "4.660" }, { "ip": "116.203.25.212:5483", "time": "4.480" }, { "ip": "95.216.206.201:5483", "time": "4.630" }, { "ip": "116.203.56.138:5483", "time": "4.456" }]
2019-07-18T18:55:21.284341444Z [{ "ip": "95.216.189.149:5483", "time": "24.444" }, { "ip": "116.203.25.212:5483", "time": "24.322" }, { "ip": "95.216.206.201:5483", "time": "24.434" }, { "ip": "116.203.56.138:5483", "time": "24.326" }]
2019-07-18T18:57:48.937508400Z [{ "ip": "95.216.189.149:5483", "time": "24.447" }, { "ip": "116.203.25.212:5483", "time": "24.345" }, { "ip": "95.216.206.201:5483", "time": "24.437" }, { "ip": "116.203.56.138:5483", "time": "24.325" }]
2019-07-18T19:00:16.609759521Z [{ "ip": "95.216.189.149:5483", "time": "24.465" }, { "ip": "116.203.25.212:5483", "time": "24.325" }, { "ip": "95.216.206.201:5483", "time": "24.436" }, { "ip": "116.203.56.138:5483", "time": "24.347" }]
2019-07-18T19:02:44.232357225Z [{ "ip": "95.216.189.149:5483", "time": "24.446" }, { "ip": "116.203.25.212:5483", "time": "24.328" }, { "ip": "95.216.206.201:5483", "time": "24.430" }, { "ip": "116.203.56.138:5483", "time": "24.325" }]
2019-07-18T19:05:11.976432805Z [{ "ip": "95.216.189.149:5483", "time": "24.490" }, { "ip": "116.203.25.212:5483", "time": "24.355" }, { "ip": "95.216.206.201:5483", "time": "24.460" }, { "ip": "116.203.56.138:5483", "time": "24.326" }]
9 Likes
37

When all data are traced (RUST_LOG=trace ./safe_auth), we get 2 suspicious timers in mio.

First, a 9 secondes one:

[2019-07-21T09:13:57Z TRACE mio::timer] inserted timeout; slot=188; token=Token(1)
[2019-07-21T09:14:06Z TRACE mio::timer] wakeup thread: sleep_until_tick=100; now_tick=100

And then a 11 secondes one:

[2019-07-21T09:14:06Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=100; sleep_until_tick=210; duration=11000
[2019-07-21T09:14:17Z TRACE mio::timer] wakeup thread: sleep_until_tick=210; now_tick=210

I will wait until connections get back to 4s (if they ever do) to see how these figures are changed (I think that even 4s was not normal).

For reference here is the log of connexion with with safe_auth (May 5th version). It is partially truncated due to a discourse limit.

[2019-07-21T09:13:54Z DEBUG safe_auth] Starting Authenticator...
[2019-07-21T09:13:54Z INFO  safe_auth::cli_helpers] Using secret from provided ENV var: SAFE_AUTH_SECRET
[2019-07-21T09:13:54Z INFO  safe_auth::cli_helpers] Using password from provided ENV var: SAFE_AUTH_PASSWORD
[2019-07-21T09:13:54Z DEBUG safe_auth::cli] Additional search path set for crust config file: resources/
[2019-07-21T09:13:54Z DEBUG safe_auth] Attempting to log in...
[2019-07-21T09:13:54Z TRACE mio::poll] registering with poller
[2019-07-21T09:13:54Z TRACE mio::poll] registering with poller
[2019-07-21T09:13:54Z TRACE tokio_threadpool::builder] build; num-workers=2
[2019-07-21T09:13:54Z TRACE mio::poll] registering with poller
[2019-07-21T09:13:54Z TRACE safe_authenticator::client] Attempting to log into an acc.
[2019-07-21T09:13:54Z DEBUG tokio_reactor::background] starting background reactor
[2019-07-21T09:13:54Z TRACE safe_authenticator::client] Creating throw-away routing getter for account packet.
[2019-07-21T09:13:54Z TRACE crust::main::service] Network name: Some("tfa")
[2019-07-21T09:13:56Z TRACE mio::poll] registering with poller
[2019-07-21T09:13:56Z TRACE mio::poll] registering with poller
[2019-07-21T09:13:56Z TRACE mio::timer] wakeup thread: sleep_until_tick=18446744073709551615; now_tick=0
[2019-07-21T09:13:56Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=0; blocking sleep
[2019-07-21T09:13:56Z TRACE crust::main::service] Event loop started
[2019-07-21T09:13:56Z TRACE crust::main::config_refresher] Entered state ConfigRefresher
[2019-07-21T09:13:56Z TRACE mio::timer] setting timeout; delay=30.001267936s; tick=300; current-tick=0
[2019-07-21T09:13:56Z TRACE mio::timer] advancing the wakeup time; target=300; curr=18446744073709551615
[2019-07-21T09:13:56Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:13:56Z TRACE mio::timer] inserted timeout; slot=44; token=Token(0)
[2019-07-21T09:13:56Z TRACE mio::timer] wakeup thread: sleep_until_tick=300; now_tick=0
[2019-07-21T09:13:56Z TRACE safe_core::client] Waiting to get connected to the Network...
[2019-07-21T09:13:56Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=0; sleep_until_tick=300; duration=30000
[2019-07-21T09:13:56Z TRACE mio::poll] registering with poller
[2019-07-21T09:13:56Z TRACE mio::timer] setting timeout; delay=10.002688066s; tick=100; current-tick=0
[2019-07-21T09:13:56Z TRACE mio::timer] advancing the wakeup time; target=100; curr=300
[2019-07-21T09:13:56Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:13:56Z TRACE mio::timer] inserted timeout; slot=100; token=Token(1)
[2019-07-21T09:13:56Z TRACE mio::timer] setting timeout; delay=1.002879145s; tick=10; current-tick=0
[2019-07-21T09:13:56Z TRACE mio::timer] advancing the wakeup time; target=10; curr=100
[2019-07-21T09:13:56Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:13:56Z TRACE mio::timer] inserted timeout; slot=10; token=Token(2)
[2019-07-21T09:13:56Z TRACE mio::timer] wakeup thread: sleep_until_tick=10; now_tick=0
[2019-07-21T09:13:56Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=0; sleep_until_tick=10; duration=1000
[2019-07-21T09:13:57Z TRACE mio::timer] wakeup thread: sleep_until_tick=10; now_tick=10
[2019-07-21T09:13:57Z TRACE mio::timer] setting readiness from wakeup thread
[2019-07-21T09:13:57Z TRACE mio::timer] wakeup thread: sleep_until_tick=18446744073709551615; now_tick=10
[2019-07-21T09:13:57Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=10; blocking sleep
[2019-07-21T09:13:57Z TRACE mio::timer] tick_to; target_tick=10; current_tick=0
[2019-07-21T09:13:57Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:13:57Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
...
[2019-07-21T09:13:57Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:13:57Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:13:57Z TRACE mio::timer] ticking; curr=Token(2)
[2019-07-21T09:13:57Z TRACE mio::timer] triggering; token=Token(2)
[2019-07-21T09:13:57Z TRACE mio::timer] unlinking timeout; slot=10; token=Token(2)
[2019-07-21T09:13:57Z TRACE mio::poll] registering with poller
[2019-07-21T09:13:57Z TRACE mio::timer] tick_to; target_tick=10; current_tick=10
[2019-07-21T09:13:57Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:13:57Z TRACE mio::timer] unsetting readiness
[2019-07-21T09:13:57Z TRACE mio::timer] advancing the wakeup time; target=100; curr=18446744073709551615
[2019-07-21T09:13:57Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:13:57Z TRACE mio::timer] wakeup thread: sleep_until_tick=100; now_tick=10
[2019-07-21T09:13:57Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=10; sleep_until_tick=100; duration=9000
[2019-07-21T09:13:57Z TRACE mio::poll] registering with poller
[2019-07-21T09:13:57Z TRACE mio::timer] unlinking timeout; slot=100; token=Token(1)
[2019-07-21T09:13:57Z TRACE crust::main::active_connection] Entered state ActiveConnection: PublicId(name: d21814..) -> PublicId(name: 26b962..)
[2019-07-21T09:13:57Z TRACE mio::timer] setting timeout; delay=121.006958808s; tick=1210; current-tick=11
[2019-07-21T09:13:57Z TRACE mio::timer] inserted timeout; slot=186; token=Token(1)
[2019-07-21T09:13:57Z TRACE mio::timer] setting timeout; delay=21.006979213s; tick=210; current-tick=11
[2019-07-21T09:13:57Z TRACE mio::timer] inserted timeout; slot=210; token=Token(2)
[2019-07-21T09:13:57Z TRACE crust::main::active_connection] Connection Map inserted: PublicId(name: 26b962..) -> Some(ConnectionId { active_connection: Some(Token(6)), currently_handshaking: 0 })
[2019-07-21T09:13:57Z DEBUG routing::states::bootstrapping] Bootstrapping(d21814..) Received BootstrapConnect from 26b962...
[2019-07-21T09:13:57Z DEBUG routing::states::bootstrapping] Bootstrapping(d21814..) Sending BootstrapRequest to 26b962...
[2019-07-21T09:13:57Z TRACE mio::poll] registering with poller
[2019-07-21T09:13:57Z TRACE mio::timer] unlinking timeout; slot=210; token=Token(2)
[2019-07-21T09:13:57Z TRACE mio::timer] setting timeout; delay=21.007660159s; tick=210; current-tick=11
[2019-07-21T09:13:57Z TRACE mio::timer] inserted timeout; slot=210; token=Token(2)
[2019-07-21T09:13:57Z TRACE mio::timer] unlinking timeout; slot=186; token=Token(1)
[2019-07-21T09:13:57Z TRACE mio::timer] setting timeout; delay=121.009010198s; tick=1210; current-tick=11
[2019-07-21T09:13:57Z TRACE mio::timer] inserted timeout; slot=186; token=Token(1)
[2019-07-21T09:13:57Z DEBUG routing::states::client] Client(d21814..) State changed to client.
[2019-07-21T09:13:57Z TRACE safe_core::client] Connected to the Network.
[2019-07-21T09:13:57Z TRACE mio::poll] registering with poller
[2019-07-21T09:13:57Z TRACE mio::timer] unlinking timeout; slot=210; token=Token(2)
[2019-07-21T09:13:57Z TRACE mio::timer] setting timeout; delay=21.010635075s; tick=210; current-tick=11
[2019-07-21T09:13:57Z TRACE mio::timer] inserted timeout; slot=210; token=Token(2)
[2019-07-21T09:13:57Z TRACE mio::timer] unlinking timeout; slot=186; token=Token(1)
[2019-07-21T09:13:57Z TRACE mio::timer] setting timeout; delay=121.157047637s; tick=1212; current-tick=11
[2019-07-21T09:13:57Z TRACE mio::timer] inserted timeout; slot=188; token=Token(1)
[2019-07-21T09:14:06Z TRACE mio::timer] wakeup thread: sleep_until_tick=100; now_tick=100
[2019-07-21T09:14:06Z TRACE mio::timer] setting readiness from wakeup thread
[2019-07-21T09:14:06Z TRACE mio::timer] wakeup thread: sleep_until_tick=18446744073709551615; now_tick=100
[2019-07-21T09:14:06Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=100; blocking sleep
[2019-07-21T09:14:06Z TRACE mio::timer] tick_to; target_tick=100; current_tick=11
[2019-07-21T09:14:06Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
...
[2019-07-21T09:14:06Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:14:06Z TRACE mio::timer] unsetting readiness
[2019-07-21T09:14:06Z TRACE mio::timer] advancing the wakeup time; target=210; curr=18446744073709551615
[2019-07-21T09:14:06Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:14:06Z TRACE mio::timer] wakeup thread: sleep_until_tick=210; now_tick=100
[2019-07-21T09:14:06Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=100; sleep_until_tick=210; duration=11000
[2019-07-21T09:14:17Z TRACE mio::timer] wakeup thread: sleep_until_tick=210; now_tick=210
[2019-07-21T09:14:17Z TRACE mio::timer] setting readiness from wakeup thread
[2019-07-21T09:14:17Z TRACE mio::timer] wakeup thread: sleep_until_tick=18446744073709551615; now_tick=210
[2019-07-21T09:14:17Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=210; blocking sleep
[2019-07-21T09:14:17Z TRACE mio::timer] tick_to; target_tick=210; current_tick=101
[2019-07-21T09:14:17Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
...
[2019-07-21T09:14:17Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:14:17Z TRACE mio::timer] ticking; curr=Token(2)
[2019-07-21T09:14:17Z TRACE mio::timer] triggering; token=Token(2)
[2019-07-21T09:14:17Z TRACE mio::timer] unlinking timeout; slot=210; token=Token(2)
[2019-07-21T09:14:17Z TRACE mio::timer] setting timeout; delay=41.005243887s; tick=410; current-tick=210
[2019-07-21T09:14:17Z TRACE mio::timer] advancing the wakeup time; target=410; curr=18446744073709551615
[2019-07-21T09:14:17Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:14:17Z TRACE mio::timer] wakeup thread: sleep_until_tick=410; now_tick=210
[2019-07-21T09:14:17Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=210; sleep_until_tick=410; duration=20000
[2019-07-21T09:14:17Z TRACE mio::timer] inserted timeout; slot=154; token=Token(2)
[2019-07-21T09:14:17Z TRACE mio::poll] registering with poller
[2019-07-21T09:14:17Z TRACE mio::timer] tick_to; target_tick=210; current_tick=210
[2019-07-21T09:14:17Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:14:17Z TRACE mio::timer] unsetting readiness
[2019-07-21T09:14:17Z TRACE mio::timer] advancing the wakeup time; target=300; curr=410
[2019-07-21T09:14:17Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:14:17Z TRACE mio::timer] wakeup thread: sleep_until_tick=300; now_tick=210
[2019-07-21T09:14:17Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=210; sleep_until_tick=300; duration=9000
[2019-07-21T09:14:17Z TRACE mio::timer] unlinking timeout; slot=188; token=Token(1)
[2019-07-21T09:14:17Z TRACE mio::timer] setting timeout; delay=141.102209376s; tick=1411; current-tick=211
[2019-07-21T09:14:17Z TRACE mio::timer] inserted timeout; slot=131; token=Token(1)
[2019-07-21T09:14:17Z TRACE routing::states::client] Client(d21814..) Got UserMessagePart fc07fa.., 1/1 from NaeManager(name: f62cfb..) to Client { client_name: d21814.., proxy_node_name: 26b962.. }.
[2019-07-21T09:14:17Z DEBUG routing::state_machine] State::Client(d21814..) Terminating state machine
[2019-07-21T09:14:17Z TRACE crust::common::core] Graceful event loop exit.
[2019-07-21T09:14:17Z TRACE safe_authenticator::client] Creating an actual routing...
[2019-07-21T09:14:17Z TRACE crust::main::service] Network name: Some("tfa")
[2019-07-21T09:14:18Z TRACE mio::poll] registering with poller
[2019-07-21T09:14:18Z TRACE mio::poll] registering with poller
[2019-07-21T09:14:18Z TRACE crust::main::service] Event loop started
[2019-07-21T09:14:18Z TRACE crust::main::config_refresher] Entered state ConfigRefresher
[2019-07-21T09:14:18Z TRACE mio::timer] wakeup thread: sleep_until_tick=18446744073709551615; now_tick=0
[2019-07-21T09:14:18Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=0; blocking sleep
[2019-07-21T09:14:18Z TRACE mio::timer] setting timeout; delay=30.000331237s; tick=300; current-tick=0
[2019-07-21T09:14:18Z TRACE mio::timer] advancing the wakeup time; target=300; curr=18446744073709551615
[2019-07-21T09:14:18Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:14:18Z TRACE mio::timer] inserted timeout; slot=44; token=Token(0)
[2019-07-21T09:14:18Z TRACE safe_core::client] Waiting to get connected to the Network...
[2019-07-21T09:14:18Z TRACE mio::poll] registering with poller
[2019-07-21T09:14:18Z TRACE mio::timer] setting timeout; delay=10.001183621s; tick=100; current-tick=0
[2019-07-21T09:14:18Z TRACE mio::timer] advancing the wakeup time; target=100; curr=300
[2019-07-21T09:14:18Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:14:18Z TRACE mio::timer] inserted timeout; slot=100; token=Token(1)
[2019-07-21T09:14:18Z TRACE mio::timer] setting timeout; delay=1.001290984s; tick=10; current-tick=0
[2019-07-21T09:14:18Z TRACE mio::timer] advancing the wakeup time; target=10; curr=100
[2019-07-21T09:14:18Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:14:18Z TRACE mio::timer] inserted timeout; slot=10; token=Token(2)
[2019-07-21T09:14:18Z TRACE mio::timer] wakeup thread: sleep_until_tick=300; now_tick=0
[2019-07-21T09:14:18Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=0; sleep_until_tick=300; duration=30000
[2019-07-21T09:14:18Z TRACE mio::timer] wakeup thread: sleep_until_tick=10; now_tick=0
[2019-07-21T09:14:18Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=0; sleep_until_tick=10; duration=1000
[2019-07-21T09:14:19Z TRACE mio::timer] wakeup thread: sleep_until_tick=10; now_tick=10
[2019-07-21T09:14:19Z TRACE mio::timer] setting readiness from wakeup thread
[2019-07-21T09:14:19Z TRACE mio::timer] wakeup thread: sleep_until_tick=18446744073709551615; now_tick=10
[2019-07-21T09:14:19Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=10; blocking sleep
[2019-07-21T09:14:19Z TRACE mio::timer] tick_to; target_tick=10; current_tick=0
[2019-07-21T09:14:19Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:14:19Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
...
[2019-07-21T09:14:19Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:14:19Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:14:19Z TRACE mio::timer] ticking; curr=Token(2)
[2019-07-21T09:14:19Z TRACE mio::timer] triggering; token=Token(2)
[2019-07-21T09:14:19Z TRACE mio::timer] unlinking timeout; slot=10; token=Token(2)
[2019-07-21T09:14:19Z TRACE mio::poll] registering with poller
[2019-07-21T09:14:19Z TRACE mio::timer] tick_to; target_tick=10; current_tick=10
[2019-07-21T09:14:19Z TRACE mio::timer] ticking; curr=Token(18446744073709551615)
[2019-07-21T09:14:19Z TRACE mio::timer] unsetting readiness
[2019-07-21T09:14:19Z TRACE mio::timer] advancing the wakeup time; target=100; curr=18446744073709551615
[2019-07-21T09:14:19Z TRACE mio::timer] unparking wakeup thread
[2019-07-21T09:14:19Z TRACE mio::timer] wakeup thread: sleep_until_tick=100; now_tick=10
[2019-07-21T09:14:19Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=10; sleep_until_tick=100; duration=9000
[2019-07-21T09:14:19Z TRACE mio::poll] registering with poller
[2019-07-21T09:14:19Z TRACE mio::timer] unlinking timeout; slot=100; token=Token(1)
[2019-07-21T09:14:19Z TRACE crust::main::active_connection] Entered state ActiveConnection: PublicId(name: 516553..) -> PublicId(name: 26b962..)
[2019-07-21T09:14:19Z TRACE mio::timer] setting timeout; delay=121.004269091s; tick=1210; current-tick=11
[2019-07-21T09:14:19Z TRACE mio::timer] inserted timeout; slot=186; token=Token(1)
[2019-07-21T09:14:19Z TRACE mio::timer] setting timeout; delay=21.004280048s; tick=210; current-tick=11
[2019-07-21T09:14:19Z TRACE mio::timer] inserted timeout; slot=210; token=Token(2)
[2019-07-21T09:14:19Z TRACE crust::main::active_connection] Connection Map inserted: PublicId(name: 26b962..) -> Some(ConnectionId { active_connection: Some(Token(6)), currently_handshaking: 0 })
[2019-07-21T09:14:19Z DEBUG routing::states::bootstrapping] Bootstrapping(516553..) Received BootstrapConnect from 26b962...
[2019-07-21T09:14:19Z DEBUG routing::states::bootstrapping] Bootstrapping(516553..) Sending BootstrapRequest to 26b962...
[2019-07-21T09:14:19Z TRACE mio::poll] registering with poller
[2019-07-21T09:14:19Z TRACE mio::timer] unlinking timeout; slot=210; token=Token(2)
[2019-07-21T09:14:19Z TRACE mio::timer] setting timeout; delay=21.004818252s; tick=210; current-tick=11
[2019-07-21T09:14:19Z TRACE mio::timer] inserted timeout; slot=210; token=Token(2)
[2019-07-21T09:14:19Z TRACE mio::timer] unlinking timeout; slot=186; token=Token(1)
[2019-07-21T09:14:19Z TRACE mio::timer] setting timeout; delay=121.005678707s; tick=1210; current-tick=11
[2019-07-21T09:14:19Z TRACE mio::timer] inserted timeout; slot=186; token=Token(1)
[2019-07-21T09:14:19Z DEBUG routing::states::client] Client(516553..) State changed to client.
[2019-07-21T09:14:19Z TRACE safe_core::client] Connected to the Network.
[2019-07-21T09:14:19Z DEBUG safe_auth] Returning logged-in Authenticator instance
[2019-07-21T09:14:19Z DEBUG safe_authenticator] Authenticator is now being dropped.
[2019-07-21T09:14:19Z DEBUG tokio_core::reactor] consuming notification queue
[2019-07-21T09:14:19Z DEBUG tokio_core::reactor] loop poll - 93.932Āµs
[2019-07-21T09:14:19Z DEBUG tokio_core::reactor] loop time - Instant { tv_sec: 7392727, tv_nsec: 754956081 }
[2019-07-21T09:14:19Z DEBUG tokio_core::reactor] loop process, 13.808Āµs
[2019-07-21T09:14:19Z DEBUG safe_core::event_loop] Exiting Core Event Loop
[2019-07-21T09:14:19Z TRACE tokio_threadpool::pool] shutdown; state=pool::State { lifecycle: Running, num_futures: 0 }
[2019-07-21T09:14:19Z TRACE tokio_threadpool::pool]   -> transitioned to shutdown
[2019-07-21T09:14:19Z TRACE tokio_threadpool::pool]   -> shutting down workers
[2019-07-21T09:14:19Z DEBUG routing::state_machine] State::Client(516553..) Terminating state machine
[2019-07-21T09:14:19Z TRACE crust::common::core] Graceful event loop exit.
3 Likes
38

Now, connect time is back at 4s, exact transition here:

2019-07-22T01:12:03.237456445Z [{ "ip": "95.216.189.149:5483", "time": "24.475" }, { "ip": "116.203.25.212:5483", "time": "24.323" }, { "ip": "95.216.206.201:5483", "time": "24.473" }, { "ip": "116.203.56.138:5483", "time": "24.348" }]
2019-07-22T01:14:30.882814725Z [{ "ip": "95.216.189.149:5483", "time": "24.448" }, { "ip": "116.203.25.212:5483", "time": "24.325" }, { "ip": "95.216.206.201:5483", "time": "24.470" }, { "ip": "116.203.56.138:5483", "time": "24.316" }]
2019-07-22T01:17:18.580969434Z [{ "ip": "95.216.189.149:5483", "time": "24.473" }, { "ip": "116.203.25.212:5483", "time": "24.290" }, { "ip": "95.216.206.201:5483", "time": "24.473" }, { "ip": "116.203.56.138:5483", "time": "44.350" }]
2019-07-22T01:18:26.246691688Z [{ "ip": "95.216.189.149:5483", "time": "4.497" }, { "ip": "116.203.25.212:5483", "time": "4.300" }, { "ip": "95.216.206.201:5483", "time": "4.484" }, { "ip": "116.203.56.138:5483", "time": "4.295" }]
2019-07-22T01:19:33.929333543Z [{ "ip": "95.216.189.149:5483", "time": "4.502" }, { "ip": "116.203.25.212:5483", "time": "4.325" }, { "ip": "95.216.206.201:5483", "time": "4.467" }, { "ip": "116.203.56.138:5483", "time": "4.289" }]
2019-07-22T01:20:41.560097330Z [{ "ip": "95.216.189.149:5483", "time": "4.508" }, { "ip": "116.203.25.212:5483", "time": "4.292" }, { "ip": "95.216.206.201:5483", "time": "4.466" }, { "ip": "116.203.56.138:5483", "time": "4.274" }]

Note that there is a peak at 44s just before going to 4s.

First timer mentioned above has disappeared, and second one has become 1s:

[2019-07-22T19:48:40Z TRACE mio::timer] sleeping; tick_ms=100; now_tick=0; sleep_until_tick=10; duration=1000
[2019-07-22T19:48:41Z TRACE mio::timer] wakeup thread: sleep_until_tick=10; now_tick=10

Observations since May 22nd:

  • connect time above 28s happened only 10 times and each time the value was 44s
  • connect time between 20s and 28s and different from 24s happened 9 times
  • connect time = 24s happened approximatively 8_000 times
  • connect time between 10s and 20s happened 9 times
  • connect time between 5s and 10s happened 223 times
  • connect time = 4s happened approximatively 300_000 times
  • connect time has never been < 4s

This concentration on 4s, 24s and 44s is very strange and should merit some investigations by @maidsafe.

10 Likes