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

Croner & PM2: try to "date set" make the callback be called 2 times #101

Closed
oom- opened this issue May 29, 2022 · 6 comments
Closed

Croner & PM2: try to "date set" make the callback be called 2 times #101

oom- opened this issue May 29, 2022 · 6 comments

Comments

@oom-
Copy link

oom- commented May 29, 2022

Hello,
I'm using pm2 to keep my services up and running and centralize logs.

I'm running actually a really simple piece of code in a docker container (basically theses commands appears in my Dockerfile):

FROM node:16.15-bullseye-slim
COPY main.js /opt/src/publisher/main.js
COPY package-lock.json /opt/src/publisher/package-lock.json
COPY package.json /opt/src/publisher/package.json
WORKDIR /opt/src/publisher
RUN npm ci --only=prod && npm install -g pm2
CMD pm2 start /opt/src/publisher/main.js --time  -o /var/log/publisher/publisher.log -e /var/log/publisher/publisher.log ; pm2 logs

Here is my NodeJS code:

const dayjs = require('dayjs');
const Cron = require("croner");

//Simple match wildcard function like: "aa" will match "a*" or "*a" or "**" but not "bb" or "b*"
function matchWildcard(str1, str2) {
    if (typeof str1 != "string" || typeof str2 != "string")
        return false;
    if (str1.length != str2.length)
        return false;
    for (let i = 0; i < str1.length; i++) {
        if (str1.at(i) != "*" && str2.at(i) != "*" && str1.at(i) != str2.at(i)) {
            console.debug(`${str1} matchs ${str2} ?: FALSE`);
            return false;
        }
    }
    console.debug(`${str1} matchs ${str2} ?: TRUE`);
    return true;
}

//My cron task running every minute
const job = Cron("0 */1 * ? * *", async () => {
    let now = dayjs();
    let dayKey = now.format("HH:mm.DD-MM");
    matchWildcard("12:00.27-**", dayKey);
});

So I met this really strange error where if I run a bash in my docker and try to change the date (unsuccessfully), the croner job is going to start to execute the callback at 32:00 min and 32:59min (like one ate 00sec and one at 59 sec) or starting to has 1sec late.

# date -s "23:55:00"
date: cannot set date: Operation not permitted
Mon May 30 23:55:00 +14 2022

image

I know this is a really specific case but I was wondering if it could hide something more deep.

@Hexagon
Copy link
Owner

Hexagon commented May 29, 2022

Interesting!

Could you pass and print new Date().toISOString() to matchWildcard, to get the exact internal time of each execution.

Something like

const dayjs = require('dayjs');
const Cron = require("croner");

//Simple match wildcard function like: "aa" will match "a*" or "*a" or "**" but not "bb" or "b*"
function matchWildcard(str1, str2, /*+*/ nowIso) {
    console.debug(nowIso); // +
    if (typeof str1 != "string" || typeof str2 != "string")
        return false;
    if (str1.length != str2.length)
        return false;
    for (let i = 0; i < str1.length; i++) {
        if (str1.at(i) != "*" && str2.at(i) != "*" && str1.at(i) != str2.at(i)) {
            console.debug(`${str1} matchs ${str2} ?: FALSE`);
            return false;
        }
    }
    console.debug(`${str1} matchs ${str2} ?: TRUE`);
    return true;
}

//My cron task running every minute
const job = Cron("0 */1 * ? * *", async () => {
    let now = dayjs(),
          nowIso = new Date().toISOString(); // +
    let dayKey = now.format("HH:mm.DD-MM");
    matchWildcard("12:00.27-**", dayKey, /* + */ nowIso);
});

Also, did you just change the date once, and after that croner started maing multiple double runs? Which version of Node?

@oom-
Copy link
Author

oom- commented May 30, 2022

Ok so I updated the code with a little extra line and info:

const dayjs = require('dayjs');
const Cron = require("croner");

let counter = 0;

//Simple match wildcard function like: "aa" will match "a*" or "*a" or "**" but not "bb" or "b*"
function matchWildcard(str1, str2, /*+*/ nowIso) {
    console.debug("[NOWISO]:", nowIso); // +
    if (typeof str1 != "string" || typeof str2 != "string")
        return false;
    if (str1.length != str2.length)
        return false;
    for (let i = 0; i < str1.length; i++) {
        if (str1.at(i) != "*" && str2.at(i) != "*" && str1.at(i) != str2.at(i)) {
            console.debug(`${str1} matchs ${str2} ?: FALSE`);
            return false;
        }
    }
    console.debug(`${str1} matchs ${str2} ?: TRUE`);
    return true;
}

//My cron task running every minute
const job = Cron("0 */1 * ? * *", async () => {
    console.log(`---------------------------NEW CALL: ${counter++}--------------------------`)
    let now = dayjs(),
    nowIso = new Date().toISOString(); 
    let dayKey = now.format("HH:mm.DD-MM");
    matchWildcard("12:00.27-**", dayKey,  nowIso);
});

Seems that now even without trying to type date set I get 2 calls :

0|main  | 2022-05-30T09:09:00: ---------------------------NEW CALL: 0--------------------------
0|main  | 2022-05-30T09:09:00: [NOWISO]: 2022-05-30T09:09:00.006Z
0|main  | 2022-05-30T09:09:00: 12:00.27-** matchs 09:09.30-05 ?: FALSE
0|main  | 2022-05-30T09:09:59: ---------------------------NEW CALL: 1--------------------------
0|main  | 2022-05-30T09:09:59: [NOWISO]: 2022-05-30T09:09:59.995Z
0|main  | 2022-05-30T09:09:59: 12:00.27-** matchs 09:09.30-05 ?: FALSE
0|main  | 2022-05-30T09:10:00: ---------------------------NEW CALL: 2--------------------------
0|main  | 2022-05-30T09:10:00: [NOWISO]: 2022-05-30T09:10:00.002Z
0|main  | 2022-05-30T09:10:00: 12:00.27-** matchs 09:10.30-05 ?: FALSE
0|main  | 2022-05-30T09:10:59: ---------------------------NEW CALL: 3--------------------------
0|main  | 2022-05-30T09:10:59: [NOWISO]: 2022-05-30T09:10:59.996Z
0|main  | 2022-05-30T09:10:59: 12:00.27-** matchs 09:10.30-05 ?: FALSE
0|main  | 2022-05-30T09:11:00: ---------------------------NEW CALL: 4--------------------------
0|main  | 2022-05-30T09:11:00: [NOWISO]: 2022-05-30T09:11:00.001Z
0|main  | 2022-05-30T09:11:00: 12:00.27-** matchs 09:11.30-05 ?: FALSE

As you can see the CALL 15 and CALL 16 are following each other at 1 sec.
Docker_Desktop_IlUTUFidv4

I do not have the issue if pm2 stop all and restart it with node main.js directly. :/
Edit: version of node is node:16.15-bullseye-slim

@Hexagon
Copy link
Owner

Hexagon commented May 30, 2022

It seems like the clock in docker runs too fast, which makes the trigger run to early. Then, as the target time is not yet reached, it makes a new schedule for one second later, and runs again.

Do you have the same problem running with node/pm2 on host machine? I can not replicate the behavior in any of the setups (host, pm2+host, pm2+docker). So it seems to be related to a specific version of something.

However, I've published a new version (4.3.12) which supports time travel. Give it a try :)

@Hexagon
Copy link
Owner

Hexagon commented Jun 13, 2022

Reopen if the problem persist

@Hexagon
Copy link
Owner

Hexagon commented Jun 16, 2022

Fix caused more problems than it solved, so we're back to square one on this one

Hexagon added a commit that referenced this issue Jun 18, 2022
@Hexagon
Copy link
Owner

Hexagon commented Jun 18, 2022

@oom- Should be resolved in 4.3.14, please verify

@Hexagon Hexagon closed this as completed Jun 18, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants