Questions on Post Login Action cache usage and reliability

djfy · May 14, 2024, 8:50pm

Definition of Terminology

Before I ask my questions, please let me define a few terms, based on the Auth0 docs, to hopefully provide more clarity throughout this post:

Action – a single block of executable code defined within a Post-Login flow. An Action is provided an Event object and API object as described in the Login Flow Auth0 documentation (Login Flow)
Flow – a defined composition of Actions. In the context of this post, this term refers only to the Post-Login flow. Thus, whenever any user logs in, the Flow is executed, i.e., each Action within the Flow is executed in order.
Flow Invocation – a unique execution of all defined Actions in the Flow whenever a user logs in. So, if two different users log in at the same time, then two distinct Flow Invocations will run.
Cache – this refers to the Cache object provided by the API object in the Action as defined in the within this documentation page Actions Triggers: post-login - API Object and the limitations of which are described in the documentation here Actions Limitations.
Cache Operation – refers to the following behavior performed by an Action: Attempt to acquire a value from the Cache using a key; if the value at the key does not exist then set the value, else proceed with the value retrieved from the Cache without setting the value. Assume this behavior respects all cache data limitations currently defined in the Auth0 documentation, assume any cached value is still within its time-to-live (TTL), and assume the same key is used.
Cache Hit – refers to when the Cache Operation successfully results in a value on the first get attempt. No set operation is performed.
Cache Miss – refers to when the Cache Operation fails to result in a value on the first get attempt and must perform the set operation.
Consistency – refers to how reliably and predictably the Cache performs the Cache Operation behavior within and across Flow Invocations. In other words, how reliable and predictable Cache Hits and Cache Misses are within and across Flow Invocations.

Questions:

What is the intended caching behavior of the Cache supposed to be within a single Flow Invocation? For example, if a Flow defines Action#1 and Action#2 where both attempt the same Cache Operation, then which Actions should result in a Cache Hit and which should result in a Cache Miss?
A follow up to question #1 - What Consistency can be expected of this intended behavior for Development, Staging, and Production Auth0 tenants?
What is the intended caching behavior of the Cache supposed to be across multiple, distinct Flow Invocations? For example, a Flow defines Action#1 and Action#2 where both attempt the same Cache Operation. Then, User#1 logs in (FlowInvocation#1), then logs out, and finally logs in again (FlowInvocation#2). Which Actions in each Flow Invocation should result in a Cache Hit and which should result in a Cache Miss?
A follow up to question #3 - What Consistency can be expected of this intended behavior for Development, Staging, and Production Auth0 tenants?

Motivation for these questions

I was experimenting with the Cache behavior using the two Actions (defined in Appendix A.1 below) in a Development tenant Post-Login Flow. My experimentation used real login attempts, did not utilize the Flow testing tool, and did use the Real-time Webtask Logs extension to observe console.log statements made by the Actions.

Again, please see the Appendices (A.1, B.1, B.2, and B.3) for code and log snippets.

My personal findings for questions #1 and #2

Action#1 always resulted in a Cache Miss and Action#2 always resulted in a Cache Hit. Action#2 produced the value from the Action#1 set operation.
This observed behavior appears to be Consistent.

My personal findings for questions #3 and #4

The results are unexpected if you assume typical Cache behavior:

For a single cycle, I observed the following results. A “cycle” meant going through all Flow Invocations described in Question #3’s example text a single time and then waiting 15 minutes for the default time-to-live timeout:
- FlowInvocation#1-Action#1 resulted in a Cache Miss.
- FlowInvocation#1-Action#2 resulted in a Cache Hit and produced the value from the FlowInvocation#1-Action#1 set operation.
- FlowInvocation#2-Action#1 resulted in a Cache Miss.
- FlowInvocation#2-Action#2 resulted in a Cache Hit and produced the value from the FlowInvocation#2-Action#1 set operation.
- This observed behavior appears to be Consistent, albeit unexpected if assuming traditional caching behavior (i.e., FlowInvocation#2-Action#1 should result in a Cache Hit)
For many cycles, I observed the following results. “Many cycles” meant going through all Flow Invocations described in Question #3’s example text repeatedly. For example, manually logging in and out of a single user account many times for 3-7 minutes (i.e., manually logging in/out more than 100 times within that timespan):
- On the first cycle:
  - Same as the aforementioned single cycle results.
- On subsequent cycles:
  - For some initial number of cycles (let’s call this the “cold phase”):
    - Action#1 of either Flow Invocation resulted in a Cache Miss most of the time, but possibly a Cache Hit sometimes. Then, the respective Action#2 resulted in a Cache Hit and always produced the value seen in the respective Action#1.
  - Then, at some arbitrary number of cycles after the initial set (let’s call this the “warmed-up phase”):
    - Action#1 of either Flow Invocation resulted in a Cache Hit most of the time, but with the occasional Cache Miss. The Cache Hits appear to produce different values for the same key. Specifically, the values from some previous Flow Invocation’s Cache Operation.
    - The respective Action#2 resulted in a Cache Hit and always produced the value from the respective Action#1.
- This behavior, while very unexpected and hard to comprehend, appears to be Consistent.

Conclusions based on observations

Cache Operations are Consistent within a single Flow Invocation for the same cache key. In other words, the first Action in a Flow to perform a Cache Operation will set the value for all other Actions in the flow that perform the same Cache Operation, regardless of whether the first Action resulted in a Cache Miss or Cache Hit.
Cache Operations are not reasonably Consistent across different Flow Invocations for the same cache key. Based on observations, it appears there is a “warm up” time for the Cache using the same key across Flow Invocations. During the initial “cold phase”, Cache Operations will result in a Cache Miss. After the Cache is warmed up (i.e., after many Flow Invocations have set the value for the same key), then Cache Operations will very likely produce a Cache Hit. However, these Cache Hits are not Consistent and will likely produce different values for the same key. The value of these Cache Hits may be from any previous Flow Invocation’s Cache Operation.

Implications of Conclusions

The following list of hyperlinks refer to documentation where Community Engineers state or strongly imply that a major use case of the Cache is caching Machine-To-Machine (M2M) access tokens across Flow Invocations. This is such a major use case because Auth0 has strict monthly limits on the granted number of M2M access tokens.

Thus, an implication from the aforementioned Conclusions is the inconsistent Cache behavior across Flow Invocations significantly invalidates or hinders this use case. Specifically, many M2M access token requests must occur and must be cached before Flow Invocations are able to, probably, resolve a previously cached token. And, even then, if cache values are pulled from different behind-the-scenes cache sources, then recomposing an access token from 3 cached values (as described in Caching M2M access token in Actions - #4 by rueben.tiow) could possibly break.

Concluding Question

Is this seemingly inconsistent behavior of the Post-Login Cache across Flow Invocations a bug/defect?

Appendix A.1

// First Action in Post-Login Flow
exports.onExecutePostLogin = async (event, api) => {
    const testKey = 'testCacheKey';
    const testValue = 'testCacheValue' + `${getRandomIntInclusive(0,100)}`;
    const testCacheValue = api.cache.get(testKey);

    if (!testCacheValue)
    {
        console.log(`cache miss in first action, logging stringified cache value to verify: ${JSON.stringify(testCacheValue)}`);
        var cacheSetResult = api.cache.set(testKey, testValue);
        console.log(`cachetSet result in first action: ${JSON.stringify(cacheSetResult)}`)
    }
    else
    {
        console.log(`found cache item in first action: ${JSON.stringify(testCacheValue)}`)
    }
};

function getRandomIntInclusive(min, max) {
  const minCeiled = Math.ceil(min);
  const maxFloored = Math.floor(max);
  return Math.floor(Math.random() * (maxFloored - minCeiled + 1) + minCeiled); // The maximum is inclusive and the minimum is inclusive
}

// Second Action in Post-Login Flow
exports.onExecutePostLogin = async (event, api) => {
    const testKey = 'testCacheKey';
    const testValue = 'testCacheValue' + `${getRandomIntInclusive(0,100)}`;
    const testCacheValue = api.cache.get(testKey);

    if (!testCacheValue)
    {
        console.log(`cache miss in second action, logging stringified cache value to verify: ${JSON.stringify(testCacheValue)}`);
        var cacheSetResult = api.cache.set(testKey, testValue);
        console.log(`cachetSet result in second action: ${JSON.stringify(cacheSetResult)}`)
    }
    else
    {
        console.log(`found cache item in second action: ${JSON.stringify(testCacheValue)}`)
    }
};

function getRandomIntInclusive(min, max) {
  const minCeiled = Math.ceil(min);
  const maxFloored = Math.floor(max);
  return Math.floor(Math.random() * (maxFloored - minCeiled + 1) + minCeiled); // The maximum is inclusive and the minimum is inclusive
}

Appendix B.1 Log Snippet from “cold phase” Cache

2:54:51 PM:
 Connected
2:58:53 PM:
 sandbox runtime ready
2:58:53 PM:
 finished webtask request
2:58:54 PM:
 sandbox runtime ready
2:58:54 PM:
 cache miss in first action, logging stringified cache value to verify: undefined cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue10","expires_at":1715717634151}}
2:58:54 PM:
 finished webtask request
2:58:54 PM:
 found cache item in second action: {"value":"testCacheValue10","expires_at":1715717634151}
2:58:54 PM:
 finished webtask request
2:58:59 PM:
 sandbox runtime ready
2:58:59 PM:
 finished webtask request
2:58:59 PM:
 cache miss in first action, logging stringified cache value to verify: undefined
2:58:59 PM:
 cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue1","expires_at":1715717639975}}
2:58:59 PM:
 finished webtask request
2:59:00 PM:
 found cache item in second action: {"value":"testCacheValue1","expires_at":1715717639975}
2:59:00 PM:
 finished webtask request
2:59:01 PM:
 finished webtask request
2:59:01 PM:
 cache miss in first action, logging stringified cache value to verify: undefined
2:59:01 PM:
 cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue26","expires_at":1715717641273}}
2:59:01 PM:
 finished webtask request
2:59:01 PM:
 found cache item in second action: {"value":"testCacheValue26","expires_at":1715717641273}
2:59:01 PM:
 finished webtask request
2:59:02 PM:
 finished webtask request
2:59:02 PM:
 cache miss in first action, logging stringified cache value to verify: undefined cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue73","expires_at":1715717642371}}
2:59:02 PM:
 finished webtask request
2:59:02 PM:
 found cache item in second action: {"value":"testCacheValue73","expires_at":1715717642371}
2:59:02 PM:
 finished webtask request
2:59:03 PM:
 finished webtask request
2:59:03 PM:
 cache miss in first action, logging stringified cache value to verify: undefined
2:59:03 PM:
 cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue15","expires_at":1715717643621}}
2:59:03 PM:
 finished webtask request
2:59:03 PM:
 found cache item in second action: {"value":"testCacheValue15","expires_at":1715717643621}
2:59:03 PM:
 finished webtask request
2:59:09 PM:
 finished webtask request
2:59:09 PM:
 cache miss in first action, logging stringified cache value to verify: undefined
2:59:09 PM:
 cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue67","expires_at":1715717649403}}
2:59:09 PM:
 finished webtask request
2:59:09 PM:
 found cache item in second action: {"value":"testCacheValue67","expires_at":1715717649403}
2:59:09 PM:
 finished webtask request
2:59:11 PM:
 finished webtask request
2:59:11 PM:
 cache miss in first action, logging stringified cache value to verify: undefined
2:59:11 PM:
 cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue71","expires_at":1715717651098}}
2:59:11 PM:
 finished webtask request
2:59:11 PM:
 found cache item in second action: {"value":"testCacheValue71","expires_at":1715717651098}
2:59:11 PM:
 finished webtask request
2:59:15 PM:
 finished webtask request
2:59:15 PM:
 cache miss in first action, logging stringified cache value to verify: undefined
2:59:15 PM:
 cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue30","expires_at":1715717655079}}
2:59:15 PM:
 finished webtask request
2:59:15 PM:
 found cache item in second action: {"value":"testCacheValue30","expires_at":1715717655079}
2:59:15 PM:
 finished webtask request

Appendix B.2 Log Snippet from “semi-warm” Cache

Note the mixture of Cache Misses and Cache Hits described in first action statements.

2:59:57 PM:
 finished webtask request
2:59:57 PM:
 cache miss in first action, logging stringified cache value to verify: undefined
2:59:57 PM:
 cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue29","expires_at":1715717697644}}
2:59:57 PM:
 finished webtask request
2:59:57 PM:
 found cache item in second action: {"value":"testCacheValue29","expires_at":1715717697644}
2:59:57 PM:
 finished webtask request
2:59:58 PM:
 finished webtask request
2:59:58 PM:
 cache miss in first action, logging stringified cache value to verify: undefined cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue68","expires_at":1715717698807}}
2:59:58 PM:
 finished webtask request
2:59:58 PM:
 found cache item in second action: {"value":"testCacheValue68","expires_at":1715717698807}
2:59:58 PM:
 finished webtask request
3:00:00 PM:
 finished webtask request
3:00:00 PM:
 cache miss in first action, logging stringified cache value to verify: undefined cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue24","expires_at":1715717700237}}
3:00:00 PM:
 finished webtask request
3:00:00 PM:
 found cache item in second action: {"value":"testCacheValue24","expires_at":1715717700237}
3:00:00 PM:
 finished webtask request
3:00:01 PM:
 finished webtask request
3:00:01 PM:
 cache miss in first action, logging stringified cache value to verify: undefined
3:00:01 PM:
 cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue42","expires_at":1715717701334}}
3:00:01 PM:
 finished webtask request
3:00:01 PM:
 found cache item in second action: {"value":"testCacheValue42","expires_at":1715717701334}
3:00:01 PM:
 finished webtask request
3:00:02 PM:
 finished webtask request
3:00:02 PM:
 cache miss in first action, logging stringified cache value to verify: undefined cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue15","expires_at":1715717702333}}
3:00:02 PM:
 finished webtask request
3:00:02 PM:
 found cache item in second action: {"value":"testCacheValue15","expires_at":1715717702333}
3:00:02 PM:
 finished webtask request
3:00:03 PM:
 finished webtask request
3:00:03 PM:
 found cache item in first action: {"value":"testCacheValue1","expires_at":1715717639975}
3:00:03 PM:
 finished webtask request
3:00:03 PM:
 found cache item in second action: {"value":"testCacheValue1","expires_at":1715717639975}
3:00:03 PM:
 finished webtask request
3:00:03 PM:
 finished webtask request
3:00:03 PM:
 cache miss in first action, logging stringified cache value to verify: undefined
3:00:03 PM:
 cachetSet result in first action: {"type":"success","record":{"value":"testCacheValue85","expires_at":1715717703953}}
3:00:03 PM:
 finished webtask request
3:00:03 PM:
 found cache item in second action: {"value":"testCacheValue85","expires_at":1715717703953}
3:00:03 PM:
 finished webtask request
3:00:04 PM:
 finished webtask request
3:00:04 PM:
 found cache item in first action: {"value":"testCacheValue71","expires_at":1715717651098}
3:00:04 PM:
 finished webtask request
3:00:04 PM:
 found cache item in second action: {"value":"testCacheValue71","expires_at":1715717651098}
3:00:04 PM:
 finished webtask request
3:00:06 PM:
 finished webtask request
3:00:06 PM:
 found cache item in first action: {"value":"testCacheValue8","expires_at":1715717683183}
3:00:06 PM:
 finished webtask request
3:00:06 PM:
 found cache item in second action: {"value":"testCacheValue8","expires_at":1715717683183}
3:00:06 PM:
 finished webtask request

Appendix B.3 Log Snippet from fully “warmed up” Cache

Note there is, generally, no Cache Misses in first action log statements, but the resolved values are generally inconsistent.

3:02:50 PM:
 finished webtask request
3:02:50 PM:
 found cache item in first action: {"value":"testCacheValue65","expires_at":1715717797835}
3:02:50 PM:
 finished webtask request
3:02:50 PM:
 found cache item in second action: {"value":"testCacheValue65","expires_at":1715717797835}
3:02:50 PM:
 finished webtask request
3:02:51 PM:
 finished webtask request
3:02:51 PM:
 found cache item in first action: {"value":"testCacheValue10","expires_at":1715717634151}
3:02:51 PM:
 finished webtask request
3:02:51 PM:
 found cache item in second action: {"value":"testCacheValue10","expires_at":1715717634151}
3:02:51 PM:
 finished webtask request
3:02:52 PM:
 finished webtask request
3:02:52 PM:
 finished webtask request
3:02:52 PM:
 found cache item in first action: {"value":"testCacheValue15","expires_at":1715717643621}
3:02:52 PM:
 found cache item in second action: {"value":"testCacheValue15","expires_at":1715717643621}
3:02:52 PM:
 finished webtask request
3:02:52 PM:
 finished webtask request
3:02:52 PM:
 found cache item in first action: {"value":"testCacheValue8","expires_at":1715717683183}
3:02:52 PM:
 finished webtask request
3:02:52 PM:
 found cache item in second action: {"value":"testCacheValue8","expires_at":1715717683183}
3:02:52 PM:
 finished webtask request
3:02:54 PM:
 finished webtask request
3:02:54 PM:
 found cache item in first action: {"value":"testCacheValue10","expires_at":1715717835958}
3:02:54 PM:
 finished webtask request
3:02:54 PM:
 found cache item in second action: {"value":"testCacheValue10","expires_at":1715717835958}
3:02:54 PM:
 finished webtask request
3:02:57 PM:
 finished webtask request
3:02:57 PM:
 found cache item in first action: {"value":"testCacheValue60","expires_at":1715717813483}
3:02:57 PM:
 finished webtask request
3:02:57 PM:
 found cache item in second action: {"value":"testCacheValue60","expires_at":1715717813483}
3:02:57 PM:
 finished webtask request
3:02:58 PM:
 finished webtask request
3:02:58 PM:
 found cache item in first action: {"value":"testCacheValue95","expires_at":1715717684372}
3:02:58 PM:
 finished webtask request
3:02:58 PM:
 found cache item in second action: {"value":"testCacheValue95","expires_at":1715717684372}
3:02:58 PM:
 finished webtask request
3:02:59 PM:
 finished webtask request
3:02:59 PM:
 found cache item in first action: {"value":"testCacheValue50","expires_at":1715717797010}
3:02:59 PM:
 finished webtask request
3:02:59 PM:
 found cache item in second action: {"value":"testCacheValue50","expires_at":1715717797010}
3:02:59 PM:
 finished webtask request
3:03:00 PM:
 finished webtask request
3:03:00 PM:
 found cache item in first action: {"value":"testCacheValue68","expires_at":1715717698807}
3:03:00 PM:
 finished webtask request
3:03:00 PM:
 found cache item in second action: {"value":"testCacheValue68","expires_at":1715717698807}
3:03:00 PM:
 finished webtask request
3:03:01 PM:
 finished webtask request
3:03:01 PM:
 found cache item in first action: {"value":"testCacheValue58","expires_at":1715717821936}
3:03:01 PM:
 finished webtask request
3:03:01 PM:
 found cache item in second action: {"value":"testCacheValue58","expires_at":1715717821936}
3:03:01 PM:
 finished webtask request

djfy · May 15, 2024, 8:09pm

Bump, hoping to get some official clarification on the Cache behavior

djfy · May 20, 2024, 2:53pm

Bump, still hoping to get some official clarification on intended Cache behavior.