Fix reapTime logic in NetworkDB #1944

fcrisciani · 2017-09-19T20:51:05Z

Added remainingReapTime field in the table event.
Wihtout it a node that did not have a state for the element
was marking the element for deletion setting the max reapTime.
This was creating the possibility to keep the entry being resync
between nodes forever avoding the purpose of the reap time
itself.
On broadcast of the table event the node owner was rewritten
with the local node name, this was not correct because the owner
should continue to remain the original one of the message

Signed-off-by: Flavio Crisciani flavio.crisciani@docker.com

codecov-io · 2017-09-20T17:33:22Z

Codecov Report

Merging #1944 into master will decrease coverage by 0.06%.
The diff coverage is 48.42%.

@@            Coverage Diff             @@
##           master    #1944      +/-   ##
==========================================
- Coverage      38%   37.94%   -0.07%     
==========================================
  Files         137      137              
  Lines       27149    27308     +159     
==========================================
+ Hits        10317    10361      +44     
- Misses      15562    15674     +112     
- Partials     1270     1273       +3

Impacted Files	Coverage Δ
networkdb/broadcast.go	`83.63% <100%> (+0.3%)`	⬆️
networkdb/cluster.go	`45.69% <4.76%> (-0.44%)`	⬇️
networkdb/networkdb.pb.go	`37.31% <48.67%> (-1.54%)`	⬇️
networkdb/delegate.go	`70.17% <55.55%> (-0.67%)`	⬇️
networkdb/networkdb.go	`60% <89.18%> (+2.98%)`	⬆️
endpoint_cnt.go	`86.08% <0%> (+2.6%)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update c34e58a...fbba555. Read the comment docs.

vieux · 2017-09-20T23:11:21Z

networkdb/cluster.go

+				return false
+			}
+
+			params := strings.Split(path[1:], "/")


are we 100% sure the path will have 4 / in it ?

why 4? it is actually 3 like: fmt.Sprintf("/%s/%s/%s", nid, tname, key)
Also the insertion and deletion is now contained in single functions: createOrUpdateEntry and deleteEntry

sorry I meant 3

Yes. this is the current expectation in the code and as @fcrisciani mentioned it is all organized now under the same functions and this assumption is valid.

vieux · 2017-09-20T23:13:16Z

networkdb/cluster.go

+
+			okTable, okNetwork := nDB.deleteEntry(nid, tname, key)
+			if !okTable {
+				logrus.Errorf("Could not delete entry in table %s with network id %s and key %s as it does not exist", tname, nid, key)


I'm having some trouble reading the message, could we replace it by the table here and the network a couple of lines down ?

I actually left the original messages, I just had to change the bool on top.
Anyway here it refers to the entry itself not the table.
Maybe a better rephrase can be: Table delete failed, entry with key:%s does not exists in the table:%s network:%s
WDYT?

@fcrisciani yeah, sound good

k changing it

vieux · 2017-09-20T23:19:20Z

networkdb/delegate.go

+	// This case can happen if the cluster is running different versions of the engine where the old version does not have the
+	// field. If that is not the case, this can be a BUG
+	if e.deleting && e.reapTime == 0 {
+		logrus.Warnf("handleTableEvent object %+v has a 0 reapTime, is the cluster running the same docker engine version?", tEvent)
 		e.reapTime = reapInterval


is this change of behavior expected here ?
shouldn't we log when e.reapTime == 0 but still do e.reapTime = reapInterval if it is not ?

nope, this is actually the point of this patch, the reapTime should be the one passed in the proto (line 237).
If that is 0 and the entry is marked for deletion we are in front of a bug (nodes does not set the value properly) or we are dealing with an old client that does not set it because does not have the new proto.

The old behavior was such that no matter when you get the notification the clock was being set to the max value of 30 min

Except in that very unfortunate circumstance that the ResidualReapTime populated by the peer has infact gone down to exactly 0 seconds at the time of populating the message (https://github.com/docker/libnetwork/pull/1944/files#diff-ced1ed36c3141cb15bdf5acafed78d67R583). If that happens in such a rare situation, we will reset this back to 30 seconds and the event will get cleaned up in 30 seconds (or in the more rarest of occasions we get another genuine 0 seconds ResidualReapTime).

@fcrisciani is that correct ?

BTW. yes. This is the actual point of this patch and I think it is a good idea to get this done.

@mavenugo your point is correct only for the case of the truncation of the number. I will add an extra check that the number truncated is still strictly greater than 0.
The improvement here is that the lock is taken only 1 time and not following the same pattern of saving the keys to delete and then do another semaphore race to delete them. So right now the only case in this patch that turns out to be 0 is when the residual time in seconds is 0.xxxx that truncated will be 0.

vieux · 2017-09-20T23:56:37Z

LGTM (with the log format update)

mavenugo · 2017-09-21T08:01:46Z

networkdb/delegate.go

 			msg:   buf,
 			id:    tEvent.NetworkID,
 			tname: tEvent.TableName,
 			key:   tEvent.Key,
-			node:  nDB.config.NodeName,
+			node:  tEvent.NodeName,


Being a rebroadcast event and based on the current logic of depending on the residual reaptimer, what is the purpose of this change ?

if I understood correctly flavio's explanation, it's not strictly related to this PR. it's an issue he saw while he was looking at the code.

Without this change, when the event was rebroadcasted, the node original node emitting the event was replaced with the one rebroadcasting it. So you could receive event saying it originated from one node, but actually came from another one.

The node is simply rebroadcasting the message of another node, at the top of the function there is the check that skips messages where the owner matches with the current node.
Without this change the ownership of the entry is messed up and can cause issues on deletion

ok. this is a bit subtle and I think a good testing coverage will help mitigate the risk.

mavenugo · 2017-09-21T08:19:30Z

networkdb/networkdb.go

+				defer nDB.RUnlock()
+				return len(nDB.networkNodes[nid])
+			},
+			RetransmitMult: 4,


Nit: Pls reorganize this code so that not-so-important changes doesn't popup. The only real change in this blob is the addition of entriesNumber and the rest of if is purely code reorganization. It is very distracting to see such changes in a PR with other sensitive changes.

mavenugo · 2017-09-21T08:44:25Z

networkdb/networkdb.go

@@ -141,6 +141,9 @@ type network struct {

 	// Number of gossip messages sent related to this network during the last stats collection period
 	qMessagesSent int
+
+	// Number of entries on the network
+	entriesNumber int


I guess this is used only for debugging purposes... It would be good to write a comment reflecting the purpose and we should not be tempted to use this as a reference counter for any logic in the future.

will add extra comments

mavenugo · 2017-09-21T09:00:21Z

@fcrisciani overall the changes LGTM. Only a few minor questions/comments.

- Added remainingReapTime field in the table event. Wihtout it a node that did not have a state for the element was marking the element for deletion setting the max reapTime. This was creating the possibility to keep the entry being resync between nodes forever avoding the purpose of the reap time itself. - On broadcast of the table event the node owner was rewritten with the local node name, this was not correct because the owner should continue to remain the original one of the message Signed-off-by: Flavio Crisciani <flavio.crisciani@docker.com>

- Changed the loop per network. Previous implementation was taking a ReadLock to update the reapTime but now with the residualReapTime also the bulkSync is using the same ReadLock creating possible issues in concurrent read and update of the value. The new logic fetches the list of networks and proceed to the cleanup network by network locking the database and releasing it after each network. This should ensure a fair locking avoiding to keep the database blocked for too much time. Note: The ticker does not guarantee that the reap logic runs precisely every reapTimePeriod, actually documentation says that if the routine is too long will skip ticks. In case of slowdown of the process itself it is possible that the lifetime of the deleted entries increases, it still should not be a huge problem because now the residual reaptime is propagated among all the nodes a slower node will let the deleted entry being repropagate multiple times but the state will still remain consistent. Signed-off-by: Flavio Crisciani <flavio.crisciani@docker.com>

fcrisciani · 2017-09-21T16:40:53Z

@mavenugo @vieux addressed all the comments, can you guys have a new pass on it?
I will start in the mean time another round of test on it

mavenugo

Thanks for addressing the comments. LGTM

vieux

LGTM

Make sure that the network is garbage collected after the entries. Entries to be deleted requires that the network is present. Signed-off-by: Flavio Crisciani <flavio.crisciani@docker.com>

vieux · 2017-09-22T18:20:33Z

New commit LGTM

Fix for networkDB garbage collection (PR: moby/libnetwork#1944) Added extra logs to monitor the netowrkDB status and number of entries per network Signed-off-by: Flavio Crisciani <flavio.crisciani@docker.com>

Fix for networkDB garbage collection (PR: moby/libnetwork#1944) Added extra logs to monitor the netowrkDB status and number of entries per network Signed-off-by: Flavio Crisciani <flavio.crisciani@docker.com> Upstream-commit: 0404342 Component: engine

Fix for networkDB garbage collection (PR: moby/libnetwork#1944) Added extra logs to monitor the netowrkDB status and number of entries per network Signed-off-by: Flavio Crisciani <flavio.crisciani@docker.com>

fcrisciani force-pushed the netdb-fix-reap branch 3 times, most recently from f3a3aca to d2c57f4 Compare September 20, 2017 17:16

fcrisciani force-pushed the netdb-fix-reap branch 3 times, most recently from b388729 to 78f80e7 Compare September 20, 2017 21:23

vieux reviewed Sep 20, 2017

View reviewed changes

fcrisciani force-pushed the netdb-fix-reap branch from 78f80e7 to 3350cb8 Compare September 21, 2017 04:34

mavenugo reviewed Sep 21, 2017

View reviewed changes

Flavio Crisciani added 2 commits September 21, 2017 09:37

fcrisciani force-pushed the netdb-fix-reap branch from 3350cb8 to 3feb3aa Compare September 21, 2017 16:38

mavenugo approved these changes Sep 21, 2017

View reviewed changes

fcrisciani mentioned this pull request Sep 21, 2017

Netdb code cleanup #1949

Closed

vieux approved these changes Sep 21, 2017

View reviewed changes

Avoid alignment of reapNetwork and tableEntries

fbba555

Make sure that the network is garbage collected after the entries. Entries to be deleted requires that the network is present. Signed-off-by: Flavio Crisciani <flavio.crisciani@docker.com>

fcrisciani force-pushed the netdb-fix-reap branch from 3537443 to fbba555 Compare September 22, 2017 17:57

mavenugo approved these changes Sep 22, 2017

View reviewed changes

mavenugo merged commit 0f08d31 into moby:master Sep 22, 2017

fcrisciani deleted the netdb-fix-reap branch September 22, 2017 20:57

fcrisciani mentioned this pull request Sep 22, 2017

[17.06 backport] NetworkDB fixes backport #1953

Merged

fcrisciani mentioned this pull request Sep 22, 2017

[17.03 backport] NetworkDB fixes backport #1954

Merged

fcrisciani mentioned this pull request Sep 24, 2017

Vendoring libnetwork moby/moby#34961

Merged

thaJeztah mentioned this pull request Nov 20, 2017

[17.09] Fix reapTime logic in NetworkDB + handle cleanup DNS for attachable container #2017

Merged

This was referenced Mar 8, 2018

Swarm Nodes Become Unavailable When Swarm is Under Heavy Load moby/moby#32841

Closed

Docker Swarm Mode service discovery is totally unstable moby/moby#33589

Closed

thaJeztah mentioned this pull request Jul 31, 2018

Do docker daemon version of swarm nodes have to be exactly the same? moby/moby#37566

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix reapTime logic in NetworkDB #1944

Fix reapTime logic in NetworkDB #1944

fcrisciani commented Sep 19, 2017

codecov-io commented Sep 20, 2017 •

edited

Loading

vieux Sep 20, 2017

fcrisciani Sep 20, 2017

vieux Sep 20, 2017

mavenugo Sep 21, 2017

vieux Sep 20, 2017

fcrisciani Sep 20, 2017

vieux Sep 20, 2017

fcrisciani Sep 20, 2017

vieux Sep 20, 2017

fcrisciani Sep 20, 2017

mavenugo Sep 21, 2017

mavenugo Sep 21, 2017

fcrisciani Sep 21, 2017

vieux commented Sep 20, 2017

mavenugo Sep 21, 2017

vieux Sep 21, 2017

fcrisciani Sep 21, 2017

mavenugo Sep 21, 2017

mavenugo Sep 21, 2017 •

edited

Loading

mavenugo Sep 21, 2017

fcrisciani Sep 21, 2017

mavenugo commented Sep 21, 2017

fcrisciani commented Sep 21, 2017 •

edited

Loading

mavenugo left a comment

vieux left a comment

vieux commented Sep 22, 2017

Fix reapTime logic in NetworkDB #1944

Fix reapTime logic in NetworkDB #1944

Conversation

fcrisciani commented Sep 19, 2017

codecov-io commented Sep 20, 2017 • edited Loading

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vieux commented Sep 20, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mavenugo Sep 21, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mavenugo commented Sep 21, 2017

fcrisciani commented Sep 21, 2017 • edited Loading

mavenugo left a comment

Choose a reason for hiding this comment

vieux left a comment

Choose a reason for hiding this comment

vieux commented Sep 22, 2017

codecov-io commented Sep 20, 2017 •

edited

Loading

mavenugo Sep 21, 2017 •

edited

Loading

fcrisciani commented Sep 21, 2017 •

edited

Loading