issues ClusterNodeInfo (not) picking an existing entry on startup

[Julian Reschke <ju...@gmx.de>]

Hi there,

when the DocumentNodeStore starts up, it attempts to find an entry that 
matches the current instance (which is defined by something based on 
network interface address and the current working directory).

However, an additional check is done when the cluster lease end time 
hasn't been reached, in which case the entry is skipped (assuming it 
belongs to a different instance), and the scan continues. When no other 
entry is found, a new one is created.

So why would we *ever* consider instances with matching instance 
information to be different? As far as I can tell the answer is: for 
unit testing.

But...

With the current assignment very weird things can happen, and I believe 
I see exactly this happening in a customer problem I'm investigating. 
The sequence is:

1) First system startup, cluster node id 1 is assigned

2) System crashes or was crashed

3) System restarts within the lease time (120s?), a new cluster node id 
is assigned

4) System shuts down, and gets restarted after a longer interval: 
cluster id 1 is used again, and system starts MissingLastRevRecovery, 
despite the previous shutdown having been clean

So what we see is that the system starts up with varying cluster node 
ids, and recovery processes may run with no correlation to what happened 
before.

Proposal:

a) Make ClusterNodeInfo.createInstance() much more verbose, so that the 
default system log contains sufficient information to understand why a 
certain cluster node id was picked.

b) Drop the logic that skips entries with non-expired leases, so that we 
get a one-to-one relation between instance ids and cluster node ids. For 
the unit tests that currently rely on this logic, switch to APIs where 
the test setup picks the cluster node id.

Feedback appreciated,

Julian

Re: issues ClusterNodeInfo (not) picking an existing entry on startup

[Julian Reschke <ju...@greenbytes.de>]

On 2015-09-21 10:41, Marcel Reutegger wrote:
> Hi,
>
> On 17/09/15 18:48, "Julian Reschke" wrote:
>> With the current assignment very weird things can happen, and I believe
>> I see exactly this happening in a customer problem I'm investigating.
>> The sequence is:
>>
>> 1) First system startup, cluster node id 1 is assigned
>>
>> 2) System crashes or was crashed
>>
>> 3) System restarts within the lease time (120s?), a new cluster node id
>> is assigned
>>
>> 4) System shuts down, and gets restarted after a longer interval:
>> cluster id 1 is used again, and system starts MissingLastRevRecovery,
>> despite the previous shutdown having been clean
>
> this shouldn't happen, at least when deployed with the
> DocumentNodeStoreService. the service registers a scheduled task,
> which checks for expired leases on a regular basis. this means
> if you have at least one instance running, the lastRev recovery
> for cluster id 1 will happen while the cluster node is running.
>
>> So what we see is that the system starts up with varying cluster node
>> ids, and recovery processes may run with no correlation to what happened
>> before.
>
> this can happen if the scheduled lastRev task didn't kick in while
> the system was up and running. this means it was running for less
> than a minute (= the lease timeout).
>
>> Proposal:
>>
>> a) Make ClusterNodeInfo.createInstance() much more verbose, so that the
>> default system log contains sufficient information to understand why a
>> certain cluster node id was picked.
>
> +1 makes sense.
>
>> b) Drop the logic that skips entries with non-expired leases, so that we
>> get a one-to-one relation between instance ids and cluster node ids. For
>> the unit tests that currently rely on this logic, switch to APIs where
>> the test setup picks the cluster node id.
>
> I agree. As noted by Thomas in one of the issues, I also think it
> would make sense to wait for the lease end and then continue with
> the startup using the matching cluster id of the just expired lease.
>
> Regards
>   Marcel

Thanks for the feedback, Marcel.

In the meantime I opened 
<https://issues.apache.org/jira/browse/OAK-3424> to track this.

Best regards, Julian


-- 
<green/>bytes GmbH, Hafenweg 16, D-48155 Münster, Germany
Amtsgericht Münster: HRB5782

Re: issues ClusterNodeInfo (not) picking an existing entry on startup

[Julian Reschke <ju...@gmx.de>]

On 2015-09-21 10:41, Marcel Reutegger wrote:
> Hi,
>
> On 17/09/15 18:48, "Julian Reschke" wrote:
>> With the current assignment very weird things can happen, and I believe
>> I see exactly this happening in a customer problem I'm investigating.
>> The sequence is:
>>
>> 1) First system startup, cluster node id 1 is assigned
>>
>> 2) System crashes or was crashed
>>
>> 3) System restarts within the lease time (120s?), a new cluster node id
>> is assigned
>>
>> 4) System shuts down, and gets restarted after a longer interval:
>> cluster id 1 is used again, and system starts MissingLastRevRecovery,
>> despite the previous shutdown having been clean
>
> this shouldn't happen, at least when deployed with the
> DocumentNodeStoreService. the service registers a scheduled task,
> which checks for expired leases on a regular basis. this means
> if you have at least one instance running, the lastRev recovery
> for cluster id 1 will happen while the cluster node is running.

According to the logs I'm looking at this did not happen. One potential 
reason would be that the cluster node info was marked as being 
recovered, thus no recovery was tried (this would happen if the system 
was killed while recovery was running, right?).

On the other hand, the system *did* run the recovery later on for that 
node, when it picked it.

Seems it would be best if we added sufficient logging here that when 
this happens again we'll have more data.

Best regards, Julian

Re: issues ClusterNodeInfo (not) picking an existing entry on startup

[Marcel Reutegger <mr...@adobe.com>]

Hi,

On 17/09/15 18:48, "Julian Reschke" wrote:
>With the current assignment very weird things can happen, and I believe
>I see exactly this happening in a customer problem I'm investigating.
>The sequence is:
>
>1) First system startup, cluster node id 1 is assigned
>
>2) System crashes or was crashed
>
>3) System restarts within the lease time (120s?), a new cluster node id
>is assigned
>
>4) System shuts down, and gets restarted after a longer interval:
>cluster id 1 is used again, and system starts MissingLastRevRecovery,
>despite the previous shutdown having been clean

this shouldn't happen, at least when deployed with the
DocumentNodeStoreService. the service registers a scheduled task,
which checks for expired leases on a regular basis. this means
if you have at least one instance running, the lastRev recovery
for cluster id 1 will happen while the cluster node is running.

>So what we see is that the system starts up with varying cluster node
>ids, and recovery processes may run with no correlation to what happened
>before.

this can happen if the scheduled lastRev task didn't kick in while
the system was up and running. this means it was running for less
than a minute (= the lease timeout).

>Proposal:
>
>a) Make ClusterNodeInfo.createInstance() much more verbose, so that the
>default system log contains sufficient information to understand why a
>certain cluster node id was picked.

+1 makes sense.

>b) Drop the logic that skips entries with non-expired leases, so that we
>get a one-to-one relation between instance ids and cluster node ids. For
>the unit tests that currently rely on this logic, switch to APIs where
>the test setup picks the cluster node id.

I agree. As noted by Thomas in one of the issues, I also think it
would make sense to wait for the lease end and then continue with
the startup using the matching cluster id of the just expired lease.

Regards
 Marcel