search

moleculerjs / moleculer

:rocket: Progressive microservices framework for Node.js
https://moleculer.services/
MIT License
6.15k stars 583 forks source link

Cache stampede #489

Closed tiaod closed 5 years ago

tiaod commented 5 years ago

Consider the flowing service:

module.exports = {
    name: "greeter",
    actions: {
        welcome: {
            params: {
                name: "string"
            },
            cache: {
                ttl: 5
            },
            handler(ctx) {
                console.log('run welcome')
                return new Promise(function(resolve, reject) {
                    setTimeout(()=>resolve(`Welcome1, ${ctx.params.name}`), 3000)
                });
            }
        }
    }
};

Expected Behavior

If cache expired, concurrent request will only call the welcome handler for only one time.

[2019-03-11T10:19:30.566Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:30.566Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
run welcome
[2019-03-11T10:19:30.701Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:30.702Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
[2019-03-11T10:19:30.830Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:30.831Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
[2019-03-11T10:19:30.957Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:30.958Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
[2019-03-11T10:19:31.086Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:31.087Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
[2019-03-11T10:19:31.220Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:31.221Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
[2019-03-11T10:19:31.352Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:31.352Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
[2019-03-11T10:19:31.468Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.004 s]
[2019-03-11T10:19:31.468Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:31.486Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:31.487Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
[2019-03-11T10:19:31.489Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+2.340 ms]
[2019-03-11T10:19:31.489Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:31.547Z] INFO  desktop-6avpisg-1828/API: => GET /favicon.ico
[2019-03-11T10:19:31.620Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:31.621Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
[2019-03-11T10:19:31.623Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.059 ms]
[2019-03-11T10:19:31.623Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:31.664Z] INFO  desktop-6avpisg-1828/API: => GET /favicon.ico
[2019-03-11T10:19:31.981Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.004 s]
[2019-03-11T10:19:31.981Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:32.282Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.004 s]
[2019-03-11T10:19:32.282Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:32.475Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.004 s]
[2019-03-11T10:19:32.475Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:32.632Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.004 s]
[2019-03-11T10:19:32.632Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:32.919Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.003 s]

Current Behavior

It call the handler multiple times:

[2019-03-11T10:19:30.566Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:30.566Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
run welcome
[2019-03-11T10:19:30.701Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:30.702Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
run welcome
[2019-03-11T10:19:30.830Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:30.831Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
run welcome
[2019-03-11T10:19:30.957Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:30.958Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
run welcome
[2019-03-11T10:19:31.086Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:31.087Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
run welcome
[2019-03-11T10:19:31.220Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:31.221Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
run welcome
[2019-03-11T10:19:31.352Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:31.352Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
run welcome
[2019-03-11T10:19:31.468Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.004 s]
[2019-03-11T10:19:31.468Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:31.486Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:31.487Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
[2019-03-11T10:19:31.489Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+2.340 ms]
[2019-03-11T10:19:31.489Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:31.547Z] INFO  desktop-6avpisg-1828/API: => GET /favicon.ico
[2019-03-11T10:19:31.620Z] INFO  desktop-6avpisg-1828/API: => GET /api/greeter/welcome?name=John1
[2019-03-11T10:19:31.621Z] INFO  desktop-6avpisg-1828/API:    Call 'greeter.welcome' action
[2019-03-11T10:19:31.623Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.059 ms]
[2019-03-11T10:19:31.623Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:31.664Z] INFO  desktop-6avpisg-1828/API: => GET /favicon.ico
[2019-03-11T10:19:31.981Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.004 s]
[2019-03-11T10:19:31.981Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:32.282Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.004 s]
[2019-03-11T10:19:32.282Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:32.475Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.004 s]
[2019-03-11T10:19:32.475Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:32.632Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.004 s]
[2019-03-11T10:19:32.632Z] INFO  desktop-6avpisg-1828/API:
[2019-03-11T10:19:32.919Z] INFO  desktop-6avpisg-1828/API: <= 200 GET /greeter/welcome?name=John1 [+3.003 s]

I think maybe it better to acquire a redis lock before calling the handler? 🤔

tiaod commented 5 years ago

I'm trying to write a PR, which will solve this issue.

tiaod commented 5 years ago

Fixed via #490

icebob commented 5 years ago

There are some breaking change in redlock 4. https://github.com/mike-marcacci/node-redlock/blob/master/CHANGELOG.md Can it cause a problem in Moleculer cacher?

tiaod commented 5 years ago

@icebob I didn't catch the error of unlock. What is the expected behavior of unlock error? 🤔

icebob commented 5 years ago

I have no idea...