Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[SPARK-33440][CORE] Use current timestamp with warning log in HadoopFSDelegationTokenProvider when the issue date for token is not set up properly #30366

Closed
wants to merge 6 commits into from

Conversation

HeartSaVioR
Copy link
Contributor

@HeartSaVioR HeartSaVioR commented Nov 13, 2020

What changes were proposed in this pull request?

This PR proposes to use current timestamp with warning log when the issue date for token is not set up properly. The next section will explain the rationalization with details.

Why are the changes needed?

Unfortunately not every implementations respect the issue date in AbstractDelegationTokenIdentifier, which Spark relies on while calculating. The default value of issue date is 0L, which is far from actual issue date, breaking logic on calculating next renewal date under some circumstance, leading to 0 interval (immediate) on rescheduling token renewal.

In HadoopFSDelegationTokenProvider, Spark calculates token renewal interval as below:

val renewIntervals = creds.getAllTokens.asScala.filter {
_.decodeIdentifier().isInstanceOf[AbstractDelegationTokenIdentifier]
}.flatMap { token =>
Try {
val newExpiration = token.renew(hadoopConf)
val identifier = token.decodeIdentifier().asInstanceOf[AbstractDelegationTokenIdentifier]
val interval = newExpiration - identifier.getIssueDate
logInfo(s"Renewal interval is $interval for token ${token.getKind.toString}")
interval
}.toOption
}
if (renewIntervals.isEmpty) None else Some(renewIntervals.min)

The interval is calculated as token.renew() - identifier.getIssueDate, which is providing correct interval assuming both token.renew() and identifier.getIssueDate produce correct value, but it's going to be weird when identifier.getIssueDate provides 0L (default value), like below:

20/10/13 06:34:19 INFO security.HadoopFSDelegationTokenProvider: Renewal interval is 1603175657000 for token S3ADelegationToken/IDBroker
20/10/13 06:34:19 INFO security.HadoopFSDelegationTokenProvider: Renewal interval is 86400048 for token HDFS_DELEGATION_TOKEN

Hopefully we pick the minimum value as safety guard (so in this case, 86400048 is being picked up), but the safety guard leads unintentional bad impact on this case.

// Get the time of next renewal.
val nextRenewalDate = tokenRenewalInterval.flatMap { interval =>
val nextRenewalDates = fetchCreds.getAllTokens.asScala
.filter(_.decodeIdentifier().isInstanceOf[AbstractDelegationTokenIdentifier])
.map { token =>
val identifier = token
.decodeIdentifier()
.asInstanceOf[AbstractDelegationTokenIdentifier]
identifier.getIssueDate + interval
}
if (nextRenewalDates.isEmpty) None else Some(nextRenewalDates.min)
}
nextRenewalDate

Spark leverages the interval being calculated in above, "minimum" value of intervals, and blindly adds the value to token's issue date to calculates the next renewal date for the token, and picks "minimum" value again. In problematic case, the value would be 86400048 (86400048 + 0) which is quite smaller than current timestamp.

// Calculate the time when new credentials should be created, based on the configured
// ratio.
val now = System.currentTimeMillis
val ratio = sparkConf.get(CREDENTIALS_RENEWAL_INTERVAL_RATIO)
val delay = (ratio * (nextRenewal - now)).toLong
scheduleRenewal(delay)
creds

The next renewal date is subtracted with current timestamp again to get the interval, and multiplexed by configured ratio to produce the final schedule interval. In problematic case, this value goes to negative.

val _delay = math.max(0, delay)
logInfo(s"Scheduling renewal in ${UIUtils.formatDuration(delay)}.")
val renewalTask = new Runnable() {
override def run(): Unit = {
updateTokensTask()
}
}
renewalExecutor.schedule(renewalTask, _delay, TimeUnit.MILLISECONDS)

There's a safety guard to not allow negative value, but that's simply 0 meaning schedule immediately. This triggers next calculation of next renewal date to calculate the schedule interval, lead to the same behavior, hence updating delegation token immediately and continuously.

As we fetch token just before the calculation happens, the actual issue date is likely slightly before, hence it's not that dangerous to use current timestamp as issue date for the token the issue date has not been set up properly. Still, it's better not to leave the token implementation as it is, so we log warn message to let end users consult with token implementer.

Does this PR introduce any user-facing change?

Yes. End users won't encounter the tight loop of schedule of token renewal after the PR. In end users' perspective of reflection, there's nothing end users need to change.

How was this patch tested?

Manually tested with problematic environment.

@github-actions github-actions bot added the CORE label Nov 13, 2020
@HeartSaVioR
Copy link
Contributor Author

I sought into the test code to add the test, but I haven't found any on calculation.

I'll need to mock HadoopFSDelegationTokenProvider in any way (mocking, subclassing) which also requires changing some methods from private to at least private[deploy]. I'll need to also deal with Credentials and create some Tokens & AbstractDelegationTokenIdentifiers for test purpose. Given the actual change is 50 lines, the requirements of the testing sounds like a bit huge, but I'll try out if we think it's still necessary to construct the test.

@HeartSaVioR
Copy link
Contributor Author

cc. @vanzin @squito @tgravescs @jerryshao Appreciate the reviewing. Thanks in advance!

@HeartSaVioR
Copy link
Contributor Author

Oh also cc. @gaborgsomogyi as he worked on this part before.

@HeartSaVioR
Copy link
Contributor Author

HeartSaVioR commented Nov 13, 2020

Another possible improvement (though I'm not 100% sure about the risk) would be considering issue date as current timestamp when the value is 0L (default). This might calculate the interval/next renewal date be smaller than the actual (hence the risk), but as we fetch the token before doing the calculation (please correct me if I'm missing here), the alternative won't be too skewed.

This improvement is also helpful to address another possible issue where the problematic token identifier is solely used. Spark will correctly calculates the next renewal date for the first time (min interval is actually expired date so it's going to be correct after adding 0L), but Spark also caches the interval which is "unchanged", and adding 0L to the cached interval won't change the next renewal date, hence eventually it will be earlier than current timestamp, triggering the same problem.

Please review the additional possible improvement as well. I'll incorporate it once reviewers double-check about the idea and say it's OK to go.

@HeartSaVioR
Copy link
Contributor Author

Btw, I guess, the token renewal interval is at least hours in practice. If I'm right here, it doesn't sound a crazy idea to always call the token.renew() to get the "correct" next renewal dates and pick the minimum value. This would eliminate almost all the safeguards and simplifies the logic greatly, having trade-off Spark should make calls per each token update.

Does this make sense?

@SparkQA
Copy link

SparkQA commented Nov 13, 2020

Kubernetes integration test starting
URL: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder-K8s/35642/

@SparkQA
Copy link

SparkQA commented Nov 13, 2020

Kubernetes integration test status failure
URL: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder-K8s/35642/

@SparkQA
Copy link

SparkQA commented Nov 13, 2020

Test build #131036 has finished for PR 30366 at commit 38a6c5a.

  • This patch passes all tests.
  • This patch merges cleanly.
  • This patch adds no public classes.

@tgravescs
Copy link
Contributor

@HeartSaVioR thanks for the detailed description and analysis, that is very helpful.
I thought the way we did it was just got the earliest renewal so we didn't have to track all them individually because the common case is renewal only happens in hours time frame - like once every 24 hours but its obviously configurable. At that point you just check all of them. I'll have to look at the code in more detail to make sure I remember correctly and I think things have changed with code refactoring that I didn't review.
In general it seems bad for any token to have renewal that is under a certain threshold, definitely shouldn't be immediate all the time. I'll look some more this afternoon.

Copy link
Member

@dongjoon-hyun dongjoon-hyun left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, @HeartSaVioR . BTW, it would be great if we can have a test case with mocking.

val nextRenewalDateForToken = issueDate + interval
logDebug(s"Next renewal date is $nextRenewalDateForToken for token ${kind.toString}")
nextRenewalDateForToken
}.filterNot(_ < currentTime)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we hit the situation where _ < currentTime for all tokens? Do we need to distinguish this case from the case tokenRenewalIntervals is empty?

@@ -230,6 +230,8 @@ private[spark] class HadoopDelegationTokenManager(
val now = System.currentTimeMillis
val ratio = sparkConf.get(CREDENTIALS_RENEWAL_INTERVAL_RATIO)
val delay = (ratio * (nextRenewal - now)).toLong
logInfo(s"Calculated delay on renewal is $delay, based on next renewal $nextRenewal " +
s"and the ratio $ratio")
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Although the log message has timestamp, it would be good to have now information together in addition to nextRenewal in this log line because it will be subtracted and can be minus.

@HeartSaVioR
Copy link
Contributor Author

HeartSaVioR commented Nov 14, 2020

@tgravescs

Thanks for the comment.

I thought the way we did it was just got the earliest renewal so we didn't have to track all them individually because the common case is renewal only happens in hours time frame - like once every 24 hours but its obviously configurable.

Yes that's configurable but agree that it only happens in hours time frame. The problematic token also produced expired time as 7 days later, so even longer than the Hadoop delegation token. The problem is simply just because Spark has a belief that token identifier should have valid issue date, whereas it's not "guaranteed" for every implementations. Once the precondition is broken, the calculation is completely going on unexpected way. There's safeguard but the safeguard also makes thing bad.

That's why I had to change the approach. Before reaching this approach, I just fixed the issue via simply discarding the invalid next renewal date like less than now, but that really feels me just adding a workaround. (This workaround also can't handle the new case I left in above comment.) And given we're here, I'd like to collect some ideas to make this "concrete" with tolerating known case of broken assumption.

@HeartSaVioR
Copy link
Contributor Author

@dongjoon-hyun
Thanks for the review. Given @tgravescs is revisiting the logic (and considering the above comments as well), I expect the code change would occur afterwards. I'd defer addressing review comments until we are in agreement with the direction and the PR reflects the consensus.

In the meanwhile I'll try to look into how to add the test.

@HeartSaVioR HeartSaVioR changed the title [SPARK-33440][CORE] Separate the calculation for the next renewal date for each delegation token [WIP][SPARK-33440][CORE] Separate the calculation for the next renewal date for each delegation token Nov 14, 2020
@HeartSaVioR HeartSaVioR marked this pull request as draft November 14, 2020 02:35
@HeartSaVioR
Copy link
Contributor Author

I just changed the PR to draft, as I would make sure we consider about the better change (than the current approach of the PR) accounting my comments above.

Reviewers, please consider the code change to only the reference, and go through below comments and share your opinion. Thanks in advance!

#30366 (comment)
#30366 (comment)

@HeartSaVioR
Copy link
Contributor Author

I see another problematic case where there're two token identifiers (say, token A and B) which token B's identifier provides issue date as 0L (same as the case provided in PR description) but the token B requires shorter token renewal period than token A. In this case, we can't simply ignore the renewal period calculation for token B.

And I'm also in doubt with caching the renewal interval. Suppose the same case, but token A has intermittent issue and ends up throwing exception when token.renew() is called for token A. This is "swallowed" without any log message and the renewal interval for the token A is never reconsidered.
(Probably we need to retry the call after some period, but the period should be also taken carefully in case of the token which token.renew() always throws exception. A bit complicated to also account for now?)

@gaborgsomogyi
Copy link
Contributor

AFAIU the problem is that the valid issue date is not filled. I think this is a bug because the whole concept is based on token provider voting. All providers give back the time when it requires renewal and the security manager takes a lowest one. This means couple of providers obtain tokens a little bit earlier but I think this shouldn't be change.

Just a question: Without valid issue date how should the security manager know when exactly the token need to be renewed?

@HeartSaVioR
Copy link
Contributor Author

Looks like Spark requires two preconditions to make scheduling renewal work correctly:

  1. token.renew() should give valid expiration date, or should throw exception if it's not supported.
  2. token identifier should give valid issue date.

This is from the case where only 1) is fulfilled. In this case, we can still schedule based on the "absolute" renewal date from token.renew(), but no longer be able to deal with "interval" which is relative to "issue date".

@gaborgsomogyi
Copy link
Contributor

gaborgsomogyi commented Nov 16, 2020

I've had a deeper look and the title was a little bit misleading to me. I thought we intend to change the framework itself bit is seems like has effect only on HadoopFS provider. This makes the situation less invasive because the whole logic stays the same but some provider internals what we need to change. Though I think it would be include HadoopFSDelegationTokenProvider in the title.

I think not filling such fields is a bug in the client itself but I feel the pain from user perspective.
Without super deep consideration and since we're speaking about at least hours or days not yet sure why we're not just using now as issue date (with a super big warning printout)?
I need to dig a little bit deeper to have good internals knowledge (I've mainly reviewed and developed the framework itself).

@HeartSaVioR
Copy link
Contributor Author

Ah yes you're right. I should have clarified the boundary of change - HadoopFS provider is only affected. Let me add the information in PR title.

Regarding considering now as issue date, I agree that is probably one of easiest approaches and not hurting much, if there's a guarantee that fetchDelegationToken always update all tokens. I'm not expert here, so don't know about the case the precondition can be broken. That's why I'm hesitate to make a change based on that.

Btw, we're also opening the possibility to fix this in Hadoop side, as the problematic identifier was from KNOX and it inherited the abstract class in hadoop-aws. Once we fix it we could just keep the precondition that issue date should be valid. I'll try to deal with Hadoop side first, and revisit afterwards.

@HeartSaVioR
Copy link
Contributor Author

HeartSaVioR commented Nov 17, 2020

FYI, fixing S3 identifier's invalid issue date is tracked via https://issues.apache.org/jira/browse/HADOOP-17379

The question remains, would we still want to make the code be resilient to the bad token identifier, as there're existing Hadoop versions which contain the bug?

If the answer is yes, we could weigh the options we enumerated. IMHO, consider the issue date as now is the simplest one (I think we can even skip adding unit test for this option), just not 100% sure it's safe to assume.

If the answer is no, we can close this PR and mark the issue as "Won't track here" or likewise.

@gaborgsomogyi
Copy link
Contributor

Good to hear the bug will be fixed on Hadoop side.

The question remains, would we still want to make the code be resilient to the bad token identifier, as there're existing Hadoop versions which contain the bug?

My personal opinion is yes and no. I don't think we should solve all problem what token providers generate especially because the change can be either risky (using now) or complex which could bring in new issues (tracking individually).
What I would do is writing out an error message what causes the issue not to spend huge amount of time to find it out next time.

@tgravescs
Copy link
Contributor

sorry for my delay, I got busy with other things. Yeah fixing the Hadoop side is great. Its been a long time since I looked at tokens so tried to look at the Hadoop code to refresh my memory.

I would say it doesn't hurt for us to protect if the issue date is 0 by using now and then logging a warning that we are doing so. That is what I thought the Hadoop secret managers did with it on renewal.

I'm assuming the issueDate never changed from 0? meaning it started 0 and even after renewal it stayed 0, right? Do you know what class was renewing?

@gaborgsomogyi
Copy link
Contributor

I would say it doesn't hurt for us to protect if the issue date is 0 by using now and then logging a warning that we are doing so. That is what I thought the Hadoop secret managers did with it on renewal.

Could you point some Hadoop code to understand your point?

@tgravescs
Copy link
Contributor

@gaborgsomogyi
Copy link
Contributor

Do we re-obtain these tokens or renew already existing as well? Now goes on when we renew.

@dongjoon-hyun dongjoon-hyun dismissed their stale review November 19, 2020 16:02

I received author's feedback.

@dongjoon-hyun
Copy link
Member

According to the author's opinion, I dismissed my review comments. We can add a test case later if we need.

@dongjoon-hyun
Copy link
Member

Could you review this, @mridulm and @tgravescs ?

@HeartSaVioR
Copy link
Contributor Author

HeartSaVioR commented Nov 19, 2020

LGTM. Note we've got one more change due on hadoop-common to use UTC as the issue date.

This raises another question: what to do if the issue date > now? That is it thinks it was issued a few hours into the future? What happens then?

AFAIK we don't have any guard around that. If the result of token.renew() is later than issue date, we still get correct value of renew interval, but calculating next renewal date would be problematic as we get it via issue date + renew interval.

We finally calculate the schedule interval for the next renewal via next renewal date - now. If the renewal date goes to be less than now, we adjust the negative value as 0, and continuous scheduling without delay happens like I described in the PR description. If the renewal date goes to be higher than actual expire date, well, we know the result already.

@SparkQA
Copy link

SparkQA commented Nov 20, 2020

Test build #131375 has finished for PR 30366 at commit bc472fd.

  • This patch fails to build.
  • This patch merges cleanly.
  • This patch adds no public classes.

@SparkQA
Copy link

SparkQA commented Nov 20, 2020

Kubernetes integration test starting
URL: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder-K8s/35978/

@SparkQA
Copy link

SparkQA commented Nov 20, 2020

Kubernetes integration test starting
URL: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder-K8s/35979/

@SparkQA
Copy link

SparkQA commented Nov 20, 2020

Kubernetes integration test status success
URL: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder-K8s/35978/

@SparkQA
Copy link

SparkQA commented Nov 20, 2020

Kubernetes integration test status failure
URL: https://amplab.cs.berkeley.edu/jenkins/job/SparkPullRequestBuilder-K8s/35979/

@SparkQA
Copy link

SparkQA commented Nov 20, 2020

Test build #131376 has finished for PR 30366 at commit abbbc48.

  • This patch passes all tests.
  • This patch merges cleanly.
  • This patch adds no public classes.

@HeartSaVioR
Copy link
Contributor Author

cc. @tgravescs @mridulm Friendly reminder.

Copy link
Contributor

@gaborgsomogyi gaborgsomogyi left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM from my side too. Adding test would be hell complicated (if possible).

@steveloughran
Copy link
Contributor

I think you should also log when the issueDate is > the time on the local machine. As discussed, fixing up is hard, but at least printing out "clock mismatch" is a useful thing to see in the logs when you hit problems

@HeartSaVioR
Copy link
Contributor Author

OK I think that's a good addition. Updated.

@tgravescs I'm sorry, but could you take a quick look again? Thanks in advance.

@steveloughran
Copy link
Contributor

thanks; hopefully we won't ever see this in the logs, but at least when it causes renewal problems then there'll be something in the logs to point the blame at clock settings in whatever issued the token

@SparkQA
Copy link

SparkQA commented Nov 26, 2020

Test build #131836 has finished for PR 30366 at commit 90216ff.

  • This patch passes all tests.
  • This patch merges cleanly.
  • This patch adds no public classes.

@HeartSaVioR HeartSaVioR changed the title [SPARK-33440][CORE] Use current timestamp with warning log when the issue date for token is not set up properly [SPARK-33440][CORE] Use current timestamp with warning log in HadoopFSDelegationTokenProvider when the issue date for token is not set up properly Nov 28, 2020
@HeartSaVioR
Copy link
Contributor Author

@tgravescs Friendly reminder.

@SparkQA
Copy link

SparkQA commented Nov 30, 2020

Test build #131945 has finished for PR 30366 at commit b749574.

  • This patch passes all tests.
  • This patch merges cleanly.
  • This patch adds no public classes.

Copy link
Contributor

@tgravescs tgravescs left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

adding the log message looks fine

HeartSaVioR added a commit that referenced this pull request Nov 30, 2020
…SDelegationTokenProvider when the issue date for token is not set up properly

### What changes were proposed in this pull request?

This PR proposes to use current timestamp with warning log when the issue date for token is not set up properly. The next section will explain the rationalization with details.

### Why are the changes needed?

Unfortunately not every implementations respect the `issue date` in `AbstractDelegationTokenIdentifier`, which Spark relies on while calculating. The default value of issue date is 0L, which is far from actual issue date, breaking logic on calculating next renewal date under some circumstance, leading to 0 interval (immediate) on rescheduling token renewal.

In HadoopFSDelegationTokenProvider, Spark calculates token renewal interval as below:

https://github.com/apache/spark/blob/2c64b731ae6a976b0d75a95901db849b4a0e2393/core/src/main/scala/org/apache/spark/deploy/security/HadoopFSDelegationTokenProvider.scala#L123-L134

The interval is calculated as `token.renew() - identifier.getIssueDate`, which is providing correct interval assuming both `token.renew()` and `identifier.getIssueDate` produce correct value, but it's going to be weird when `identifier.getIssueDate` provides 0L (default value), like below:

```
20/10/13 06:34:19 INFO security.HadoopFSDelegationTokenProvider: Renewal interval is 1603175657000 for token S3ADelegationToken/IDBroker
20/10/13 06:34:19 INFO security.HadoopFSDelegationTokenProvider: Renewal interval is 86400048 for token HDFS_DELEGATION_TOKEN
```

Hopefully we pick the minimum value as safety guard (so in this case, `86400048` is being picked up), but the safety guard leads unintentional bad impact on this case.

https://github.com/apache/spark/blob/2c64b731ae6a976b0d75a95901db849b4a0e2393/core/src/main/scala/org/apache/spark/deploy/security/HadoopFSDelegationTokenProvider.scala#L58-L71

Spark leverages the interval being calculated in above, "minimum" value of intervals, and blindly adds the value to token's issue date to calculates the next renewal date for the token, and picks "minimum" value again. In problematic case, the value would be `86400048` (86400048 + 0) which is quite smaller than current timestamp.

https://github.com/apache/spark/blob/2c64b731ae6a976b0d75a95901db849b4a0e2393/core/src/main/scala/org/apache/spark/deploy/security/HadoopDelegationTokenManager.scala#L228-L234

The next renewal date is subtracted with current timestamp again to get the interval, and multiplexed by configured ratio to produce the final schedule interval. In problematic case, this value goes to negative.

https://github.com/apache/spark/blob/2c64b731ae6a976b0d75a95901db849b4a0e2393/core/src/main/scala/org/apache/spark/deploy/security/HadoopDelegationTokenManager.scala#L180-L188

There's a safety guard to not allow negative value, but that's simply 0 meaning schedule immediately. This triggers next calculation of next renewal date to calculate the schedule interval, lead to the same behavior, hence updating delegation token immediately and continuously.

As we fetch token just before the calculation happens, the actual issue date is likely slightly before, hence it's not that dangerous to use current timestamp as issue date for the token the issue date has not been set up properly. Still, it's better not to leave the token implementation as it is, so we log warn message to let end users consult with token implementer.

### Does this PR introduce _any_ user-facing change?

Yes. End users won't encounter the tight loop of schedule of token renewal after the PR. In end users' perspective of reflection, there's nothing end users need to change.

### How was this patch tested?

Manually tested with problematic environment.

Closes #30366 from HeartSaVioR/SPARK-33440.

Authored-by: Jungtaek Lim (HeartSaVioR) <kabhwan.opensource@gmail.com>
Signed-off-by: Jungtaek Lim (HeartSaVioR) <kabhwan.opensource@gmail.com>
(cherry picked from commit f5d2165)
Signed-off-by: Jungtaek Lim (HeartSaVioR) <kabhwan.opensource@gmail.com>
@HeartSaVioR
Copy link
Contributor Author

Thanks all for reviewing! Merged into master and branch-3.0.

@HeartSaVioR HeartSaVioR deleted the SPARK-33440 branch November 30, 2020 21:58
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants