Urgent: Migration stuck v3.8.1, missing acks from node

migration

#1

I have 8 node cluster on 3.8.1 version. I have restarted one node because client connection was ~15k on this machine (on other machine ~3-5k) and migration started as expected but it got stuck on all machines after certain %.

I increased migration thread to 5.

asinfo -v "set-config:context=service;migrate-threads=5"

and it started again but got stuck again and i increased it to 10 then 15. Migration got completed on 1 node but got stuck to ~98-99% on all other nodes. When i checked logs(/var/log/aerospike/aerospike.log), it says -

WARNING (migrate): (migrate.c:930) missing acks from node bb9a4083a7ac40c

on some machines.

when i checked on node bb9a4083a7ac40c (same machine that i restarted) it has repeated warning in logs:

Jun 20 2017 14:19:47 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb904d0657ac40c
Jun 20 2017 14:19:49 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb904d0657ac40c
Jun 20 2017 14:19:49 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb97cd1657ac40c
Jun 20 2017 14:19:49 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb9f0d0657ac40c
Jun 20 2017 14:19:49 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb9f0d0657ac40c
Jun 20 2017 14:19:50 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb99c083a7ac40c
Jun 20 2017 14:19:52 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb9f0d0657ac40c
Jun 20 2017 14:19:53 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb904d0657ac40c
Jun 20 2017 14:19:54 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb904d0657ac40c
Jun 20 2017 14:19:54 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb97cd1657ac40c
Jun 20 2017 14:19:54 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb9f0d0657ac40c
Jun 20 2017 14:19:55 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb9f0d0657ac40c
Jun 20 2017 14:19:55 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb99c083a7ac40c
Jun 20 2017 14:19:57 GMT: WARNING (migrate): (migrate.c:930) missing acks from node bb9f0d0657ac40c

My asmonitor info output:

 asmonitor -e info

Enter help for commands

Creating History file,  [Errno 2] No such file or directory
Cannot read config file /home/platform/.asmonitor/asmonitor.conf
Created initial config file /home/platform/.asmonitor/asmonitor.conf
8 hosts in cluster: 10.100.156.40:3000,10.56.101.152:3000,10.56.101.153:3000,10.56.101.158:3000,10.56.101.184:3000,10.57.115.42:3000,10.57.115.79:3000,10.57.115.91:3000
===NODES===
2017-06-20 14:03:23.781525
Sorting by IP, in Ascending order:
ip:port               Build   Cluster      Cluster   Free   Free   Migrates              Node         Principal    Replicated    Sys
                          .      Size   Visibility   Disk    Mem          .                ID                ID       Objects   Free
                          .         .            .    pct    pct          .                 .                 .             .    Mem
10.100.156.40:3000    3.8.1         8         true     93     28      (1,0)   BB97CC4FA902500   BB9F0D0657AC40C   255,568,473     21
10.56.101.152:3000    3.8.1         8         true     93     30      (1,1)   BB97CD1657AC40C   BB9F0D0657AC40C   250,739,669     21
10.56.101.153:3000    3.8.1         8         true     93     30      (1,1)   BB99C083A7AC40C   BB9F0D0657AC40C   249,529,073     21
10.56.101.158:3000    3.8.1         8         true     93     31      (0,3)   BB9F0D0657AC40C   BB9F0D0657AC40C   246,399,098     23
10.56.101.184:3000    3.8.1         8         true     93     31      (0,0)   BB9E047FB902500   BB9F0D0657AC40C   247,875,947     23
10.57.115.42:3000     3.8.1         8         true     93     33     (7,10)   BB9A4083A7AC40C   BB9F0D0657AC40C   242,836,781     25
10.57.115.79:3000     3.8.1         8         true     93     29      (0,0)   BB9E0D0657AC40C   BB9F0D0657AC40C   252,761,992     20
10.57.115.91:3000     3.8.1         8         true     93     28      (1,2)   BB904D0657AC40C   BB9F0D0657AC40C   255,422,182     20
Number of nodes displayed: 8


 ===NAMESPACE===
Total (unique) objects in cluster for test : 0
Total (unique) objects in cluster for bidder : 1,000,971,169
Note: Total (unique) objects is an under estimate if migrations are in progress.


ip/namespace            Avail   Evicted        Master     Repl     Stop      Used   Used      Used   Used    hwm   hwm
                          Pct   Objects       Objects   Factor   Writes      Disk   Disk       Mem    Mem   Disk   Mem
                            .         .             .        .        .         .      %         .      %      .     .
10.56.101.184/bidder       91         0   124,286,992        2    false   62.88 G      7   41.37 G     83     50    60
10.56.101.152/bidder       91         0   131,351,331        2    false   63.60 G      7   41.87 G     84     50    60
10.57.115.91/bidder        91         0   129,163,656        2    false   64.79 G      7   42.66 G     86     50    60
10.56.101.158/bidder       91         0   123,056,943        2    false   62.51 G      7   41.14 G     83     50    60
10.57.115.79/bidder        91         0   124,544,372        2    false   64.12 G      7   42.17 G     85     50    60
10.56.101.153/bidder       91         0   120,054,404        2    false   63.30 G      7   41.59 G     84     50    60
10.100.156.40/bidder       91         0   132,088,662        2    false   64.83 G      7   42.64 G     86     50    60
10.57.115.42/bidder        93         0   116,424,809        2    false   61.60 G      7   39.61 G     80     50    60
10.56.101.184/test        n/a         0             0        2    false       n/a    n/a    0.00 B      0     50    60
10.56.101.152/test        n/a         0             0        2    false       n/a    n/a    0.00 B      0     50    60
10.57.115.91/test         n/a         0             0        2    false       n/a    n/a    0.00 B      0     50    60
10.56.101.158/test        n/a         0             0        2    false       n/a    n/a    0.00 B      0     50    60
10.57.115.79/test         n/a         0             0        2    false       n/a    n/a    0.00 B      0     50    60
10.56.101.153/test        n/a         0             0        2    false       n/a    n/a    0.00 B      0     50    60
10.57.115.42/test         n/a         0             0        2    false       n/a    n/a    0.00 B      0     50    60
10.100.156.40/test        n/a         0             0        2    false       n/a    n/a    0.00 B      0     50    60
Number of rows displayed: 16

what’s going wrong ?


#2

This means that a particular migration thread has begun to throttle because it has 16 MB of un-acked records. The warning doesn’t print until the thread has remained in this state for at least 5 seconds, and will continue to print in 5 second intervals until the outstanding acks drop below the 16 MB threshold.

In other words, you have pushed migration higher than your network or machine/disks can sustain. I suggest decreasing migrate-threads down to 1 (this will not take effect immediately, threads will terminate as migrations complete). You should also increasing migrate-sleep to ~200 μs. You may revert the migrate-sleep to the default value once the system stabilizes again.

By default, migrate-sleep is 1 μs, which is aggressive but works well with one thread. With multiple threads this default can quickly become too aggressive. If you plan to tune up threads, begin by increasing the migrate-sleep to avoid overwhelming network etc. In later releases we introduced log tickers and stats to show the rate migrations are receiving and sending data which can be useful to see if you have tuned up the rate or not.


#3

i have decreased migrate-thread to 1 and increased migrate-sleep to 200

asinfo -v "set-config:context=namespace;id=bidder;migrate-sleep=200"

 asinfo -v "set-config:context=service;migrate-threads=1"

How long will it take to affect (approx) (I have > 1B keys in cluster) ?

will it be safe to add more nodes at this moment or should i wait for this migration to complete? I am running out of space so have to add new machines ASAP. Please suggest.


#4

You can add more machines now without issue, but make sure you wait at least 10 seconds between adding each node or until the cluster size is agreed on all the nodes.


#5

Actually, adding a node would be great because it will cancel the ongoing migrations and your migrate threads will quickly reduce to the configured value.


#6

Thanks it worked :sweat_smile: I added 2 more node and migration completed on all nodes.

I also changed migrate-sleep on all nodes

asinfo -v "set-config:context=namespace;id=bidder;migrate-sleep=1"

#7

It got stuck again on migration :frowning: . It seems that one node (BB9A4083A7AC40C) restarted during night but don’t know the reason. I caught few suspicious lines in log and posting it below:

asadm -e info

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~Network Information~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
              Node               Node                   Ip   Build   Enterprise   Cluster            Cluster     Cluster         Principal   Client       Uptime
                 .                 Id                    .       .            .      Size                Key   Integrity                 .    Conns            .
10.100.15.18:3000    BB95CD5FA902500    10.100.15.18:3000    3.8.1   False             10   1F7BC27D9A3EA972   True        BB9F0D0657AC40C     4287   52:58:57
10.100.15.96:3000    BB9E88A637AC40C    10.100.15.96:3000    3.8.1   False             10   1F7BC27D9A3EA972   True        BB9F0D0657AC40C     4208   52:30:11
10.100.156.40:3000   BB97CC4FA902500    10.100.156.40:3000   3.8.1   False             10   1F7BC27D9A3EA972   True        BB9F0D0657AC40C     4142   2090:33:50
10.56.101.152:3000   BB97CD1657AC40C    10.56.101.152:3000   3.8.1   False             10   1F7BC27D9A3EA972   True        BB9F0D0657AC40C     4099   2038:42:25
10.56.101.153:3000   BB99C083A7AC40C    10.56.101.153:3000   3.8.1   False             10   1F7BC27D9A3EA972   True        BB9F0D0657AC40C     4220   2038:11:58
10.56.101.158:3000   *BB9F0D0657AC40C   10.56.101.158:3000   3.8.1   False             10   1F7BC27D9A3EA972   True        BB9F0D0657AC40C     4099   2087:49:29
10.56.101.184:3000   BB9E047FB902500    10.56.101.184:3000   3.8.1   False             10   1F7BC27D9A3EA972   True        BB9F0D0657AC40C     4175   2037:41:37
10.57.115.42:3000    BB9A4083A7AC40C    10.57.115.42:3000    3.8.1   False             10   1F7BC27D9A3EA972   True        BB9F0D0657AC40C     6183   70:35:55
10.57.115.79:3000    BB9E0D0657AC40C    10.57.115.79:3000    3.8.1   False             10   1F7BC27D9A3EA972   True        BB9F0D0657AC40C     4108   2039:45:59
10.57.115.91:3000    BB904D0657AC40C    10.57.115.91:3000    3.8.1   False             10   1F7BC27D9A3EA972   True        BB9F0D0657AC40C     4151   2085:24:18
Number of rows: 10

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~Namespace Information~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Namespace                 Node   Avail%   Evictions      Master     Replica     Repl     Stop     Pending         Disk    Disk     HWM          Mem     Mem    HWM      Stop
        .                    .        .           .     Objects     Objects   Factor   Writes    Migrates         Used   Used%   Disk%         Used   Used%   Mem%   Writes%
        .                    .        .           .           .           .        .        .   (tx%,rx%)            .       .       .            .       .      .         .
bidder      10.100.15.18:3000    92               0   110.569 M   112.270 M   2        false    (45,100)     59.440 GB   6       50       38.159 GB   77      60     90
bidder      10.100.15.96:3000    93               0   114.565 M    98.603 M   2        false    (48,100)     56.713 GB   6       50       36.409 GB   73      60     90
bidder      10.56.101.184:3000   91               0   118.758 M   103.662 M   2        false    (50,100)     58.686 GB   6       50       38.604 GB   78      60     90
bidder      10.56.101.152:3000   91               0   122.076 M    95.552 M   2        false    (41,100)     58.412 GB   6       50       38.475 GB   77      60     90
bidder      10.57.115.91:3000    91               0   124.452 M   107.362 M   2        false    (62,100)     61.200 GB   7       50       40.281 GB   81      60     90
bidder      10.56.101.158:3000   91               0   114.767 M   103.964 M   2        false    (54,100)     57.972 GB   6       50       38.164 GB   77      60     90
bidder      10.57.115.79:3000    91               0   117.346 M   106.236 M   2        false    (55,100)     59.125 GB   6       50       38.890 GB   78      60     90
bidder      10.56.101.153:3000   91               0   112.623 M   108.844 M   2        false    (48,98)      58.947 GB   6       50       38.733 GB   78      60     90
bidder      10.57.115.42:3000    92               0   111.221 M   283.523 K   2        false    (99,50)      57.735 GB   6       50       37.066 GB   75      60     90
bidder      10.100.156.40:3000   91               0   120.929 M   104.353 M   2        false    (47,100)     61.207 GB   7       50       40.241 GB   81      60     90
bidder                                            0     1.167 G   941.130 M                     (75,75)     589.436 GB                   385.023 GB
test        10.100.15.18:3000    N/E              0     0.000       0.000     2        false    (0,0)              N/E   N/E     50        0.000 B    0       60     90
test        10.100.15.96:3000    N/E              0     0.000       0.000     2        false    (0,0)              N/E   N/E     50        0.000 B    0       60     90
test        10.56.101.184:3000   N/E              0     0.000       0.000     2        false    (0,0)              N/E   N/E     50        0.000 B    0       60     90
test        10.56.101.152:3000   N/E              0     0.000       0.000     2        false    (0,0)              N/E   N/E     50        0.000 B    0       60     90
test        10.57.115.91:3000    N/E              0     0.000       0.000     2        false    (0,0)              N/E   N/E     50        0.000 B    0       60     90
test        10.56.101.158:3000   N/E              0     0.000       0.000     2        false    (0,0)              N/E   N/E     50        0.000 B    0       60     90
test        10.57.115.79:3000    N/E              0     0.000       0.000     2        false    (0,0)              N/E   N/E     50        0.000 B    0       60     90
test        10.56.101.153:3000   N/E              0     0.000       0.000     2        false    (0,0)              N/E   N/E     50        0.000 B    0       60     90
test        10.57.115.42:3000    N/E              0     0.000       0.000     2        false    (0,0)              N/E   N/E     50        0.000 B    0       60     90
test        10.100.156.40:3000   N/E              0     0.000       0.000     2        false    (0,0)              N/E   N/E     50        0.000 B    0       60     90
test                                              0     0.000       0.000                       (0,0)         0.000 B                      0.000 B
Number of rows: 22

Node BB9F0D0657AC40C logs:

Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2352) hb considers expiring: now 7996910434 last 7996908887
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2371) hb expires but fabric says DEAD: node bb9a4083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2550) removing node on heartbeat failure: bb9a4083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (fabric): (fabric.c:1762) fabric: node bb9a4083a7ac40c departed
Jun 22 2017 23:14:20 GMT: INFO (fabric): (fabric.c:1678) fabric disconnecting node: bb9a4083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1964) as_paxos_spark establishing transaction [33]@bb9f0d0657ac40c ClSz = 10 ; # change = 1 : DEL bb9a4083a7ac40c;
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:2932) {33} principal acking it's prepare bb9f0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1623) removing failed node bb9a4083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:356) DISALLOW MIGRATIONS
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb9e88a637ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb9e0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb9e047fb902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb99c083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb97cd1657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb97cc4fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb95cd5fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1509) SUCCESSION [33]@bb9f0d0657ac40c: bb9f0d0657ac40c bb9e88a637ac40c bb9e0d0657ac40c bb9e047fb902500 bb99c083a7ac40c bb97cd1657ac40c bb97cc4fa902500 bb95cd5fa902500 bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb99c083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb97cd1657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb9e047fb902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb97cc4fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb9e0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb9e88a637ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb95cd5fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3228) All partition data has been received by principal
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb9e88a637ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb9e0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb9e047fb902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb99c083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb97cd1657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb97cc4fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb95cd5fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2447) CLUSTER SIZE = 9
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2485) Global state is well formed
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2230) setting replication factors: cluster size 9, paxos single replica limit 1
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2245) {test} replication factor is 2
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2245) {bidder} replication factor is 2
Jun 22 2017 23:14:20 GMT: INFO (config): (cluster_config.c:421) rack aware is disabled
Jun 22 2017 23:14:20 GMT: INFO (partition): (cluster_config.c:380) rack aware is disabled
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:3222) {test} re-balanced, expected migrations - (86 tx, 109 rx)
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:3222) {bidder} re-balanced, expected migrations - (86 tx, 109 rx)
Jun 22 2017 23:14:20 GMT: INFO (paxos): (partition.c:3239) global partition state: total 8192 lost 0 unique 8192 duplicate 0
Jun 22 2017 23:14:20 GMT: INFO (paxos): (partition.c:3241) partition state after fixing lost partitions (master): total 8192 lost 0 unique 8192 duplicate 0
Jun 22 2017 23:14:20 GMT: INFO (paxos): (partition.c:3243) 1588 new partition version tree paths generated
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:348) ALLOW MIGRATIONS

Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:1070) initiated connection to mesh seed host at 10.57.115.42:3002 (10.57.115.42:3002) via socket 393 from 10.56.101.158:56612
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2556) new heartbeat received: bb9a4083a7ac40c principal node is bb9f0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (fabric): (fabric.c:1756) fabric: node bb9a4083a7ac40c arrived
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1964) as_paxos_spark establishing transaction [34]@bb9f0d0657ac40c ClSz = 9 ; # change = 1 : ADD bb9a4083a7ac40c;
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:2932) {34} principal acking it's prepare bb9f0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1616) inserting node bb9a4083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:356) DISALLOW MIGRATIONS
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb9e88a637ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb9e0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb9e047fb902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb9a4083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb99c083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb97cd1657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb97cc4fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb95cd5fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1500) sending sync message to bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:1509) SUCCESSION [34]@bb9f0d0657ac40c: bb9f0d0657ac40c bb9e88a637ac40c bb9e0d0657ac40c bb9e047fb902500 bb9a4083a7ac40c bb99c083a7ac40c bb97cd1657ac40c bb97cc4fa902500 bb95cd5fa902500 bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb9e0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb97cd1657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb9e047fb902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb99c083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb97cc4fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb9e88a637ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb95cd5fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3199) Received paxos partition sync request from bb9a4083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3228) All partition data has been received by principal
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb9e88a637ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb9e0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb9e047fb902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb9a4083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb99c083a7ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb97cd1657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb97cc4fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb95cd5fa902500
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3231) Sending paxos partition sync message to bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2447) CLUSTER SIZE = 10
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2485) Global state is well formed
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2230) setting replication factors: cluster size 10, paxos single replica limit 1
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2245) {test} replication factor is 2
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2245) {bidder} replication factor is 2
Jun 22 2017 23:14:20 GMT: INFO (config): (cluster_config.c:421) rack aware is disabled
Jun 22 2017 23:14:20 GMT: INFO (partition): (cluster_config.c:380) rack aware is disabled
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:3222) {test} re-balanced, expected migrations - (86 tx, 86 rx)
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:3222) {bidder} re-balanced, expected migrations - (86 tx, 86 rx)
Jun 22 2017 23:14:21 GMT: INFO (paxos): (partition.c:3239) global partition state: total 8192 lost 0 unique 6604 duplicate 1588
Jun 22 2017 23:14:21 GMT: INFO (paxos): (partition.c:3241) partition state after fixing lost partitions (master): total 8192 lost 0 unique 6604 duplicate 1588
Jun 22 2017 23:14:21 GMT: INFO (paxos): (partition.c:3243) 0 new partition version tree paths generated
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:348) ALLOW MIGRATIONS

Node BB9A4083A7AC40C (this node seems restarted) :

Jun 22 2017 23:14:18 GMT: INFO (hb): (hb.c:2352) hb considers expiring: now 7918874972 last 7918873450
Jun 22 2017 23:14:18 GMT: INFO (hb): (hb.c:2371) hb expires but fabric says DEAD: node bb9f0d0657ac40c
Jun 22 2017 23:14:18 GMT: INFO (hb): (hb.c:2550) removing node on heartbeat failure: bb9f0d0657ac40c
Jun 22 2017 23:14:18 GMT: INFO (fabric): (fabric.c:1762) fabric: node bb9f0d0657ac40c departed
Jun 22 2017 23:14:18 GMT: INFO (fabric): (fabric.c:1678) fabric disconnecting node: bb9f0d0657ac40c
Jun 22 2017 23:14:18 GMT: INFO (fabric): (fabric.c:1288) can't write to notification file descriptor: will probably have to take down process
Jun 22 2017 23:14:18 GMT: INFO (fabric): (fabric.c:1288) can't write to notification file descriptor: will probably have to take down process
Jun 22 2017 23:14:18 GMT: INFO (paxos): (paxos.c:2175) departed node bb9f0d0657ac40c is no longer principal pro tempore
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4812)  system memory: free 17107860kb ( 25 percent free )
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4818)  ClusterSize 10 ::: objects 221429046 ::: sub_objects 0
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4827)  rec refs 221598435 ::: rec locks 0 ::: trees 0 ::: wr reqs 0 ::: mig tx 0 ::: mig rx 41
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4832)  replica errs :: null 0 non-null 0 ::: sync copy errs :: master 0
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7118, 582128, 575010) : hb (14, 2139, 2125) : fab (133, 508, 375)
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4844)    heartbeat_received: self 0 : foreign 22867939
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4845)    heartbeat_stats: bt 0 bf 20397534 nt 0 ni 0 nn 0 nnir 0 nal 0 sf1 0 sf2 0 sf3 0 sf4 0 sf5 0 sf6 1 mrf 0 eh 180 efd 30 efa 150 um 8536 mcf 0 rc 2125
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4857)    tree_counts: nsup 1 scan 0 dup 0 wprocess 0 migrx 41 migtx 0 ssdr 0 ssdw 0 rw 0
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4874) {test} disk bytes used 0 : avail pct 100
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4876) {test} memory bytes used 0 (index 0 : sindex 0 : data 0) : used pct 0.00
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4924) {test} migrations - complete
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4874) {bidder} disk bytes used 60041106048 : avail pct 92
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4876) {bidder} memory bytes used 38546442099 (index 14171458944 : sindex 97843 : data 24374885312) : used pct 71.80
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4924) {bidder} migrations - complete
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4931)    partitions: actual 780 sync 808 desync 0 zombie 0 absent 6604
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:137) histogram dump: reads (0 total) msec
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:137) histogram dump: writes_master (829642 total) msec
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (00: 0000806699) (01: 0000007724) (02: 0000002372) (03: 0000002318)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (04: 0000003673) (05: 0000001484) (06: 0000000287) (07: 0000000183)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (08: 0000000148) (09: 0000000141) (10: 0000000545) (11: 0000003647)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:163)  (12: 0000000345) (13: 0000000032) (14: 0000000044)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:137) histogram dump: proxy (723 total) msec
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (00: 0000000170) (01: 0000000085) (02: 0000000070) (03: 0000000076)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (04: 0000000052) (05: 0000000059) (06: 0000000047) (07: 0000000044)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:163)  (08: 0000000057) (09: 0000000035) (10: 0000000028)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:137) histogram dump: udf (79910506 total) msec
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (00: 0079720787) (01: 0000121231) (02: 0000042560) (03: 0000017079)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (04: 0000004808) (05: 0000002060) (06: 0000001409) (07: 0000000354)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (08: 0000000028) (09: 0000000023) (10: 0000000058) (11: 0000000063)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:163)  (12: 0000000041) (13: 0000000004) (14: 0000000001)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:137) histogram dump: query (795945 total) msec
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (00: 0000012866) (01: 0000384558) (02: 0000376542) (03: 0000015417)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (04: 0000003215) (05: 0000000816) (06: 0000001260) (07: 0000000598)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (08: 0000000195) (09: 0000000099) (10: 0000000123) (11: 0000000138)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:163)  (12: 0000000066) (13: 0000000038) (14: 0000000014)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:137) histogram dump: query_rec_count (783195 total) count
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (01: 0000001603) (02: 0000000092) (03: 0000000535) (04: 0000000897)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:154)  (05: 0000000232) (06: 0000002333) (07: 0000008402) (08: 0000768791)
Jun 22 2017 23:14:19 GMT: INFO (info): (hist.c:163)  (09: 0000000310)
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2352) hb considers expiring: now 7918876927 last 7918875414
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2380) hb expires but fabric says ALIVE: lasttime 161 node bb95cd5fa902500
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:1683) as_hb_tcp_recv() fd 5012 returning error try 3 len 339 read_so_far 184
Jun 22 2017 23:14:20 GMT: WARNING (hb): (hb.c:2227) about to goto CloseSocket....
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:1070) initiated connection to mesh seed host at 10.56.101.158:3002 (10.56.101.158:3002) via socket 5671 from 10.57.115.42:57674
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2352) hb considers expiring: now 7918877077 last 7918875414
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2380) hb expires but fabric says ALIVE: lasttime 321 node bb95cd5fa902500
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2352) hb considers expiring: now 7918877228 last 7918875414
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:405) Sync message received from a principal bb9f0d0657ac40c that is back from the dead?
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2380) hb expires but fabric says ALIVE: lasttime 442 node bb95cd5fa902500
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:356) DISALLOW MIGRATIONS
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2352) hb considers expiring: now 7918877228 last 7918875628
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2380) hb expires but fabric says ALIVE: lasttime 442 node bb9e88a637ac40c
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2556) new heartbeat received: bb9f0d0657ac40c principal node is bb9f0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (fabric): (fabric.c:1756) fabric: node bb9f0d0657ac40c arrived
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3168) SUCCESSION [34]@bb9f0d0657ac40c*: bb9f0d0657ac40c bb9e88a637ac40c bb9e0d0657ac40c bb9e047fb902500 bb9a4083a7ac40c bb99c083a7ac40c bb97cd1657ac40c bb97cc4fa902500 bb95cd5fa902500 bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3179) node bb9f0d0657ac40c is now principal pro tempore
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:2305) Sent partition sync request to node bb9f0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:1683) as_hb_tcp_recv() fd 7458 returning error try 3 len 339 read_so_far 184
Jun 22 2017 23:14:20 GMT: WARNING (hb): (hb.c:2227) about to goto CloseSocket....
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:1683) as_hb_tcp_recv() fd 993 returning error try 3 len 339 read_so_far 184
Jun 22 2017 23:14:20 GMT: WARNING (hb): (hb.c:2227) about to goto CloseSocket....
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:1683) as_hb_tcp_recv() fd 186 returning error try 3 len 339 read_so_far 184
Jun 22 2017 23:14:20 GMT: WARNING (hb): (hb.c:2227) about to goto CloseSocket....
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2352) hb considers expiring: now 7918877380 last 7918875628
Jun 22 2017 23:14:20 GMT: INFO (hb): (hb.c:2380) hb expires but fabric says ALIVE: lasttime 602 node bb9e88a637ac40c
Jun 22 2017 23:14:21 GMT: INFO (hb): (hb.c:1070) initiated connection to mesh non-seed host at 10.100.15.18:3002 (10.100.15.18:3002) via socket 186 from 10.57.115.42:58952
Jun 22 2017 23:14:21 GMT: INFO (fabric): (fabric.c:1318) can't write to notification file descriptor: will probably have to take down process
Jun 22 2017 23:14:21 GMT: INFO (hb): (hb.c:1683) as_hb_tcp_recv() fd 7598 returning error try 3 len 339 read_so_far 184
Jun 22 2017 23:14:21 GMT: WARNING (hb): (hb.c:2227) about to goto CloseSocket....
Jun 22 2017 23:14:21 GMT: INFO (hb): (hb.c:1070) initiated connection to mesh non-seed host at 10.100.15.96:3002 (10.100.15.96:3002) via socket 5740 from 10.57.115.42:42176
Jun 22 2017 23:14:21 GMT: INFO (paxos): (paxos.c:3263) received partition sync message from bb9f0d0657ac40c
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:2447) CLUSTER SIZE = 10
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:2485) Global state is well formed
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:2230) setting replication factors: cluster size 10, paxos single replica limit 1
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:2245) {test} replication factor is 2
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:2245) {bidder} replication factor is 2
Jun 22 2017 23:14:21 GMT: INFO (config): (cluster_config.c:421) rack aware is disabled
Jun 22 2017 23:14:21 GMT: INFO (partition): (cluster_config.c:380) rack aware is disabled
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:3222) {test} re-balanced, expected migrations - (794 tx, 794 rx)
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:3222) {bidder} re-balanced, expected migrations - (794 tx, 794 rx)
Jun 22 2017 23:14:21 GMT: INFO (paxos): (partition.c:3239) global partition state: total 8192 lost 0 unique 6604 duplicate 1588
Jun 22 2017 23:14:21 GMT: INFO (paxos): (partition.c:3241) partition state after fixing lost partitions (master): total 8192 lost 0 unique 6604 duplicate 1588
Jun 22 2017 23:14:21 GMT: INFO (paxos): (partition.c:3243) 0 new partition version tree paths generated
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:348) ALLOW MIGRATIONS
Jun 22 2017 23:14:23 GMT: INFO (fabric): (fabric.c:1318) can't write to notification file descriptor: will probably have to take down process
Jun 22 2017 23:14:23 GMT: INFO (hb): (hb.c:1070) initiated connection to mesh seed host at 10.56.101.152:3002 (10.56.101.152:3002) via socket 5756 from 10.57.115.42:49250
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4812)  system memory: free 17138988kb ( 26 percent free )
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4818)  ClusterSize 10 ::: objects 221429068 ::: sub_objects 0
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4827)  rec refs 221490160 ::: rec locks 0 ::: trees 0 ::: wr reqs 8 ::: mig tx 1137 ::: mig rx 460
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4832)  replica errs :: null 0 non-null 0 ::: sync copy errs :: master 0
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 8 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7269, 582289, 575020) : hb (18, 2148, 2130) : fab (142, 524, 382)
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4844)    heartbeat_received: self 0 : foreign 22868988
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4845)    heartbeat_stats: bt 0 bf 20398259 nt 0 ni 0 nn 0 nnir 0 nal 0 sf1 0 sf2 0 sf3 0 sf4 0 sf5 0 sf6 1 mrf 0 eh 185 efd 30 efa 155 um 8536 mcf 0 rc 2130
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4857)    tree_counts: nsup 1 scan 0 dup 0 wprocess 0 migrx 460 migtx 1137 ssdr 0 ssdw 0 rw 8
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4874) {test} disk bytes used 0 : avail pct 100
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4876) {test} memory bytes used 0 (index 0 : sindex 0 : data 0) : used pct 0.00
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4922) {test} migrations - remaining (733 tx, 384 rx), active (1 tx, 10 rx), 29.66% complete
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4874) {bidder} disk bytes used 60041114752 : avail pct 92
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4876) {bidder} memory bytes used 38546446467 (index 14171460352 : sindex 97843 : data 24374888272) : used pct 71.80
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4922) {bidder} migrations - remaining (794 tx, 794 rx), active (1 tx, 10 rx), 0.00% complete

continue …


#8

Node BB9E047FB902500 :

Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:2919) {32} sending prepare_ack to bb9f0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:356) DISALLOW MIGRATIONS
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3168) SUCCESSION [33]@bb9f0d0657ac40c*: bb9f0d0657ac40c bb9e88a637ac40c bb9e0d0657ac40c bb9e047fb902500 bb99c083a7ac40c bb97cd1657ac40c bb97cc4fa902500 bb95cd5fa902500 bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3179) node bb9f0d0657ac40c is now principal pro tempore
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:2305) Sent partition sync request to node bb9f0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3263) received partition sync message from bb9f0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2447) CLUSTER SIZE = 9
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2485) Global state is well formed
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2230) setting replication factors: cluster size 9, paxos single replica limit 1
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2245) {test} replication factor is 2
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:2245) {bidder} replication factor is 2
Jun 22 2017 23:14:20 GMT: INFO (config): (cluster_config.c:421) rack aware is disabled
Jun 22 2017 23:14:20 GMT: INFO (partition): (cluster_config.c:380) rack aware is disabled
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:3222) {test} re-balanced, expected migrations - (72 tx, 92 rx)
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:3222) {bidder} re-balanced, expected migrations - (72 tx, 92 rx)
Jun 22 2017 23:14:20 GMT: INFO (paxos): (partition.c:3239) global partition state: total 8192 lost 0 unique 8192 duplicate 0
Jun 22 2017 23:14:20 GMT: INFO (paxos): (partition.c:3241) partition state after fixing lost partitions (master): total 8192 lost 0 unique 8192 duplicate 0
Jun 22 2017 23:14:20 GMT: INFO (paxos): (partition.c:3243) 1588 new partition version tree paths generated
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:348) ALLOW MIGRATIONS
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:2919) {33} sending prepare_ack to bb9f0d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (partition): (partition.c:356) DISALLOW MIGRATIONS
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3168) SUCCESSION [34]@bb9f0d0657ac40c*: bb9f0d0657ac40c bb9e88a637ac40c bb9e0d0657ac40c bb9e047fb902500 bb9a4083a7ac40c bb99c083a7ac40c bb97cd1657ac40c bb97cc4fa902500 bb95cd5fa902500 bb904d0657ac40c
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:3179) node bb9f0d0657ac40c is now principal pro tempore
Jun 22 2017 23:14:20 GMT: INFO (paxos): (paxos.c:2305) Sent partition sync request to node bb9f0d0657ac40c
Jun 22 2017 23:14:21 GMT: INFO (paxos): (paxos.c:3263) received partition sync message from bb9f0d0657ac40c
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:2447) CLUSTER SIZE = 10
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:2485) Global state is well formed
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:2230) setting replication factors: cluster size 10, paxos single replica limit 1
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:2245) {test} replication factor is 2
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:2245) {bidder} replication factor is 2
Jun 22 2017 23:14:21 GMT: INFO (config): (cluster_config.c:421) rack aware is disabled
Jun 22 2017 23:14:21 GMT: INFO (partition): (cluster_config.c:380) rack aware is disabled
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:3222) {test} re-balanced, expected migrations - (72 tx, 72 rx)
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:3222) {bidder} re-balanced, expected migrations - (72 tx, 72 rx)
Jun 22 2017 23:14:21 GMT: INFO (paxos): (partition.c:3239) global partition state: total 8192 lost 0 unique 6604 duplicate 1588
Jun 22 2017 23:14:21 GMT: INFO (paxos): (partition.c:3241) partition state after fixing lost partitions (master): total 8192 lost 0 unique 6604 duplicate 1588
Jun 22 2017 23:14:21 GMT: INFO (paxos): (partition.c:3243) 0 new partition version tree paths generated
Jun 22 2017 23:14:21 GMT: INFO (partition): (partition.c:348) ALLOW MIGRATIONS
Jun 22 2017 23:14:21 GMT: WARNING (fabric): (fabric.c:2323) No fabric transmit structure in global hash for fabric transaction-id 38
Jun 22 2017 23:14:21 GMT: INFO (info): (thr_info.c:4812)  system memory: free 15330404kb ( 23 percent free )
Jun 22 2017 23:14:21 GMT: INFO (info): (thr_info.c:4818)  ClusterSize 10 ::: objects 224981662 ::: sub_objects 0

what could be the reason? Is it possible to return incorrect data during this period ? I have seen some inconsistency (key present but returned not present) during this period. Can it be because of this?


#9

Looks like the clustering algorithms were in a bad state. 3.7.0.1 introduced a new paxos recovery policy which later became default, but not sure when. Make sure your cluster is using this policy as it eliminates a lot of these problems.

Yes, in this case the cluster will behave as if there were a network partition, inconsistent operations are expected.

3.13 introduced a new clustering system which addresses additional issues that were not possible to address with a recovery policy.


#10

I am using 3.8.1 version. How can i apply that policy? do you have any document on this?


#11

I think @kporter is referring to paxos-recovery-policy=auto-reset-master. It’s helped stabilize my clusters greatly :smiley:


#12

According to this document http://www.aerospike.com/docs/reference/configuration#paxos-recovery-policy It seems that auto-reset-master is already default as i am using 3.8.1 version.


#13

You can validate this is your policy by running asinfo -v ‘get-config:context=service’ -l | grep -i paxos-rec


#14

Yes, it is auto-reset-master.

$ asinfo -v 'get-config:context=service' -l | grep -i paxos-rec
paxos-recovery-policy=auto-reset-master

#15

The old clustering algorithm still had flaws even with this policy; however, they were very difficult to exercise (the remaining issues were addressed in paxos-protocol v5 in 3.13.0 release. With this policy running I would begin to more strongly suspect a network problem.


#16

@kporter i have posted one more question couple of days ago but didn’t get any response yet.

Do you think that it is also related to this? If not, can you guide me in right direction?


#17

Seems to also correlate with network problems. Could you share the log lines containing the work “proto” about 5 min prior and a few minutes into one of these events?

grep "proto" /var/log/aerospike/aerospike.log

#18

@kporter this timeout issue is very frequent (multiple times a day). this was present even before migration issue and still present today.

Seems to also correlate with network problems

Are you referring to Aerospike clustering algorithm or somethiing related to my cluster network?


#19

Yes, all the above. These log warnings aren’t part of normal operations based on information provided so far I would lean more towards the actual network itself.

BTW, would be interesting to see the “proto” log lines I mentioned.


#20

grep "proto" /var/log/aerospike/aerospike.log-20170623

on Node BB9A4083A7AC40C:

Output:

Jun 22 2017 23:12:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (6985, 581275, 574290) : hb (16, 2135, 2119) : fab (140, 508, 368)
Jun 22 2017 23:12:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (6984, 581277, 574293) : hb (16, 2135, 2119) : fab (140, 508, 368)
Jun 22 2017 23:13:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7057, 581665, 574608) : hb (15, 2138, 2123) : fab (140, 508, 368)
Jun 22 2017 23:13:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 2 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7070, 581686, 574616) : hb (16, 2139, 2123) : fab (140, 508, 368)
Jun 22 2017 23:13:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7069, 581690, 574621) : hb (16, 2139, 2123) : fab (140, 508, 368)
Jun 22 2017 23:13:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7064, 581697, 574633) : hb (16, 2139, 2123) : fab (140, 508, 368)
Jun 22 2017 23:13:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 9 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7293, 581974, 574681) : hb (16, 2139, 2123) : fab (140, 508, 368)
Jun 22 2017 23:13:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7311, 581994, 574683) : hb (16, 2139, 2123) : fab (140, 508, 368)
Jun 22 2017 23:14:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (6998, 581998, 575000) : hb (16, 2139, 2123) : fab (140, 508, 368)
Jun 22 2017 23:14:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7118, 582128, 575010) : hb (14, 2139, 2125) : fab (133, 508, 375)
Jun 22 2017 23:14:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 8 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7269, 582289, 575020) : hb (18, 2148, 2130) : fab (142, 524, 382)
Jun 22 2017 23:14:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 16 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7269, 582316, 575047) : hb (18, 2148, 2130) : fab (142, 524, 382)
Jun 22 2017 23:14:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 201 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7570, 582736, 575166) : hb (18, 2148, 2130) : fab (142, 524, 382)
Jun 22 2017 23:14:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 149 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7530, 583334, 575804) : hb (18, 2148, 2130) : fab (142, 524, 382)
Jun 22 2017 23:15:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 181 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7538, 583865, 576327) : hb (18, 2148, 2130) : fab (142, 524, 382)
Jun 22 2017 23:15:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 186 prox 0 wait 1 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7540, 584527, 576987) : hb (18, 2149, 2131) : fab (142, 524, 382)
Jun 22 2017 23:15:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 143 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7531, 585094, 577563) : hb (18, 2149, 2131) : fab (142, 524, 382)
Jun 22 2017 23:15:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 169 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7471, 585568, 578097) : hb (18, 2150, 2132) : fab (142, 524, 382)
Jun 22 2017 23:15:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 213 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7544, 586334, 578790) : hb (18, 2150, 2132) : fab (142, 524, 382)
Jun 22 2017 23:15:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 135 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7517, 587007, 579490) : hb (18, 2150, 2132) : fab (142, 524, 382)
Jun 22 2017 23:16:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 234 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7522, 587635, 580113) : hb (18, 2150, 2132) : fab (142, 524, 382)
Jun 22 2017 23:16:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 155 prox 0 wait 4 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7410, 588373, 580963) : hb (18, 2150, 2132) : fab (142, 524, 382)
Jun 22 2017 23:16:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 94 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7337, 588887, 581550) : hb (18, 2150, 2132) : fab (142, 524, 382)
Jun 22 2017 23:16:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 29 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7275, 589102, 581827) : hb (18, 2150, 2132) : fab (142, 524, 382)
Jun 22 2017 23:16:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 7 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7362, 589307, 581945) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:16:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 12 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7363, 589350, 581987) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:17:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 25 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7362, 589395, 582033) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:17:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 4 prox 0 wait 2 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7335, 589410, 582075) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:17:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 5 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7334, 589450, 582116) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:17:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 11 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7344, 589493, 582149) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:17:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7325, 589527, 582202) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:17:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 13 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7348, 589568, 582220) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:18:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 5 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7325, 589607, 582282) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:18:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 11 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7338, 589650, 582312) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:18:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 4 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7320, 589681, 582361) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:18:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7319, 589689, 582370) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:18:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 8 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7334, 589728, 582394) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:18:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 18 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7344, 589753, 582409) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:19:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7323, 589763, 582440) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:19:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 16 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7337, 589798, 582461) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:19:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7321, 589817, 582496) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:19:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 14 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7337, 589849, 582512) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:19:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7323, 589864, 582541) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:19:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 13 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7341, 589899, 582558) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:20:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 6 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7372, 590005, 582633) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:20:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7517, 590182, 582665) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:20:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 15 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7532, 590230, 582698) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:20:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7520, 590244, 582724) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:20:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 11 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7529, 590290, 582761) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:20:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7519, 590296, 582777) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:21:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7518, 590321, 582803) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:21:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 13 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7512, 590345, 582833) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:21:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 17 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7522, 590379, 582857) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:21:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 19 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7526, 590409, 582883) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:21:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 4 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7516, 590418, 582902) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:21:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 11 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7523, 590458, 582935) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:22:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7508, 590487, 582979) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:22:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7507, 590501, 582994) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:22:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 7 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7529, 590570, 583041) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:22:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 16 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7536, 590590, 583054) : hb (17, 2150, 2133) : fab (142, 524, 382)
Jun 22 2017 23:22:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7540, 590612, 583072) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:22:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7527, 590623, 583096) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:23:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7546, 590669, 583123) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:23:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 8 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7560, 590699, 583139) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:23:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 20 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7549, 590717, 583168) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:23:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7538, 590720, 583182) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:23:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7554, 590754, 583200) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:23:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 17 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7584, 590792, 583208) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:24:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7572, 590805, 583233) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:24:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 3 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7572, 590838, 583266) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:24:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 11 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7611, 590885, 583274) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:24:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 5 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7619, 590931, 583312) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:24:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 4 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7640, 590982, 583342) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:24:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 18 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7654, 591001, 583347) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:25:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7650, 591008, 583358) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:25:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 6 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7691, 591080, 583389) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:25:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7691, 591085, 583394) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:25:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7693, 591093, 583400) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:25:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7660, 591103, 583443) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:25:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7667, 591111, 583444) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:26:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7640, 591120, 583480) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:26:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7657, 591142, 583485) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:26:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7654, 591149, 583495) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:26:39 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7661, 591158, 583497) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:26:49 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7678, 591184, 583506) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:26:59 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7680, 591198, 583518) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:27:09 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7678, 591210, 583532) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:27:19 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7679, 591221, 583542) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:27:29 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7679, 591222, 583543) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:27:40 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7678, 591224, 583546) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:27:50 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7678, 591232, 583554) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:28:00 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7678, 591232, 583554) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:28:10 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7678, 591238, 583560) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:28:20 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7676, 591243, 583567) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:28:30 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7676, 591247, 583571) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:28:40 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7677, 591249, 583572) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:28:50 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7676, 591255, 583579) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:29:00 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7677, 591258, 583581) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:29:10 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7673, 591266, 583593) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:29:20 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7673, 591274, 583601) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:29:30 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7673, 591275, 583602) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:29:40 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7674, 591281, 583607) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:29:50 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7677, 591311, 583634) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:30:00 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7682, 591317, 583635) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:30:10 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 6 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7715, 591354, 583639) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:30:20 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 6 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7715, 591360, 583645) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:30:30 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7716, 591369, 583653) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:30:40 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 3 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7714, 591370, 583656) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:30:50 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 3 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7715, 591380, 583665) : hb (17, 2152, 2135) : fab (142, 524, 382)
Jun 22 2017 23:31:00 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (7715, 591381, 583666) : hb (17, 2152, 2135) : fab (142, 524, 382)

On BB9E047FB902500 node:

Jun 22 2017 23:13:21 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4440, 10622224, 10617784) : hb (16, 1979, 1963) : fab (141, 225, 84)
Jun 22 2017 23:13:31 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4441, 10622231, 10617790) : hb (16, 1979, 1963) : fab (141, 225, 84)
Jun 22 2017 23:13:41 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4434, 10622234, 10617800) : hb (16, 1979, 1963) : fab (141, 225, 84)
Jun 22 2017 23:13:51 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4564, 10622402, 10617838) : hb (16, 1979, 1963) : fab (141, 225, 84)
Jun 22 2017 23:14:01 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4564, 10622407, 10617843) : hb (16, 1979, 1963) : fab (141, 225, 84)
Jun 22 2017 23:14:11 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4399, 10622421, 10618022) : hb (16, 1979, 1963) : fab (141, 225, 84)
Jun 22 2017 23:14:21 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4400, 10622424, 10618024) : hb (15, 1979, 1964) : fab (141, 225, 84)
Jun 22 2017 23:14:31 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4400, 10622430, 10618030) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:14:41 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4400, 10622434, 10618034) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:14:51 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 5 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4498, 10622548, 10618050) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:15:01 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4507, 10622562, 10618055) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:15:11 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 17 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4523, 10622581, 10618058) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:15:21 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 6 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4534, 10622604, 10618070) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:15:31 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4534, 10622609, 10618075) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:15:41 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4524, 10622619, 10618095) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:15:51 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 15 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4534, 10622645, 10618111) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:16:01 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 7 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4509, 10622653, 10618144) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:16:11 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 10 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4530, 10622674, 10618144) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:16:21 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 11 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4517, 10622677, 10618160) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:16:31 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 2 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4508, 10622692, 10618184) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:16:41 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4508, 10622695, 10618187) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:16:51 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4465, 10622699, 10618234) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:17:01 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4431, 10622715, 10618284) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:17:11 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4411, 10622731, 10618320) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:17:21 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 1 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4400, 10622738, 10618338) : hb (16, 1980, 1964) : fab (142, 226, 84)
Jun 22 2017 23:17:31 GMT: INFO (info): (thr_info.c:4842)    trans_in_progress: wr 0 prox 0 wait 0 ::: q 0 ::: iq 0 ::: dq 0 : fds - proto (4401, 10622743, 10618342) : hb (16, 1980, 1964) : fab (142, 226, 84)