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

sendto(getHistory) not returning the oldest value #331

Open
klein0r opened this issue May 14, 2024 · 2 comments
Open

sendto(getHistory) not returning the oldest value #331

klein0r opened this issue May 14, 2024 · 2 comments

Comments

@klein0r
Copy link
Contributor

klein0r commented May 14, 2024

Describe the bug
A clear and concise description of what the bug is.

To Reproduce

Check the following script. It writes a number given of records into the database and tries to find the oldest timestamp afterwards (with value 0).

It's working if less that 961 records have been generated (in this case). Otherwise it returns the value "23".

const objId = '0_userdata.0.test_history';
const startTs = new Date(2024, 0, 1, 0, 0, 0); // 1704063600000

const stepSize = 60 * 60 * 1000; // 1 hour
const generateRows = 960; // CHANGE THIS to 961 (or higher)

function getTestData() {
    const testData = [];
    let ts = startTs.getTime();

    for (let i = 0; i < generateRows; i++) {
        ts = startTs.getTime() + (stepSize * i);
        testData.push({ ts, val: i, ack: true, from: 'system.adapter.javascript.0' });
    }

    console.log(`Generated test data: ${testData.length} items, from ${formatDate(startTs.getTime(), 'DD.MM.YYYY hh:mm:ss.sss')} to ${formatDate(ts, 'DD.MM.YYYY hh:mm:ss.sss')}`);

    return { testData, endTs: ts };
}

createState(objId, { type: 'number', read: true, write: true }, async () => {
    await sendToAsync('history.0', 'enableHistory', {
        id: objId,
        options: {
            enabled: true,
            aliasId: '',
            debounceTime: 0,
            blockTime: 0,
            changesOnly: true,
            changesRelogInterval: 0,
            changesMinDelta: 0,
            ignoreBelowNumber: '',
            disableSkippedValueLogging: false,
            retention: 31536000,
            customRetentionDuration: 365,
            maxLength: 960,
            enableDebugLogs: true,
            debounce: 0,
        }
    });
    const enabledDps = await sendToAsync('history.0', 'getEnabledDPs', {});

    console.log(`Activated logging for ${Object.keys(enabledDps).join(', ')}`);

    if (Object.keys(enabledDps).includes(objId)) {
        // Delete previous data
        const deleteAllResult = await sendToAsync('history.0', 'deleteAll', [{ id: objId }]);
        console.log(`Deleted all saved values: ${deleteAllResult?.success}`);

        // Save new test data
        const { testData, endTs } = getTestData();
        const storeStateResult = await sendToAsync('history.0', 'storeState', {
            id: objId,
            state: testData,
        });
        console.log(`Stored new values: ${storeStateResult?.success}`);

        const getHistoryResult = await sendToAsync('history.0', 'getHistory', {
            id: objId,
            options: {
                start: startTs.getTime(),
                end: endTs,
                aggregate: 'none',
                limit: 1000,
                returnNewestEntries: false,
                ignoreNull: true,
                addId: true,
                from: true,
                ack: true,
                q: true,
            }
        });
        console.log(`History result: ${JSON.stringify(getHistoryResult?.result[0])}`);

        const getOldestResult = await sendToAsync('history.0', 'getHistory', {
            id: objId,
            options: {
                start: 1,
                end: endTs,
                aggregate: 'none',
                limit: 1,
                returnNewestEntries: false,
                ignoreNull: true,
            }
        });
        console.log(`Oldest record result: ${JSON.stringify(getOldestResult?.result[0])}`);
    } else {
        console.error(`Logging not activated for ${objId}`);
    }
});

Versions:

  • Adapter version: 3.0.1
  • JS-Controller version: 5.0.19
  • Node version: 20.12.2
  • Operating system: Debian 12
@klein0r
Copy link
Contributor Author

klein0r commented May 14, 2024

const generateRows = 960;:

2024-05-14 20:03:16.244  - debug: history.0 (7218) 0_userdata.0.test_history17157097962440.2592514243858921 getHistory message: {"id":"0_userdata.0.test_history","options":{"start":1,"end":1707516000000,"aggregate":"none","limit":1,"returnNewestEntries":false,"ignoreNull":true}}
2024-05-14 20:03:16.244  - debug: history.0 (7218) 0_userdata.0.test_history17157097962440.2592514243858921 getHistory options final: {"id":"0_userdata.0.test_history","path":"/home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/","start":1,"end":1707516000000,"step":null,"count":1,"from":false,"ack":false,"q":false,"ignoreNull":true,"aggregate":"none","limit":1,"addId":false,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.test_history17157097962440.2592514243858921","round":null,"debugLog":true}
2024-05-14 20:03:16.244  - debug: history.0 (7218) getOneCachedData: got 960 datapoints for 0_userdata.0.test_history
2024-05-14 20:03:16.244  - debug: history.0 (7218) 0_userdata.0.test_history17157097962440.2592514243858921 after getCachedData: length = 960, isFull=false
2024-05-14 20:03:16.244  - debug: history.0 (7218) getOneFileData: 19700101 -> 20240209 for 0_userdata.0.test_history
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240101 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240101/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240102 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240102/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240103 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240103/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240104 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240104/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240105 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240105/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240106 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240106/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240107 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240107/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240108 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240108/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240109 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240109/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240110 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240110/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240111 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240111/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240112 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240112/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240113 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240113/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.244  - debug: history.0 (7218) handleFileData: 20240114 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240114/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240115 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240115/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240116 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240116/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240117 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240117/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240118 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240118/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240119 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240119/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240120 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240120/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240121 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240121/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240122 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240122/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240123 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240123/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240124 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240124/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240125 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240125/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240126 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240126/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240127 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240127/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240128 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240128/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240129 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240129/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240130 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240130/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240131 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240131/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240201 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240201/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240202 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240202/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240203 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240203/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240204 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240204/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240205 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240205/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240206 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240206/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240207 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240207/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240208 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240208/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) handleFileData: 20240209 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240209/history.0_userdata.0.test_history.json
2024-05-14 20:03:16.245  - debug: history.0 (7218) 0_userdata.0.test_history17157097962440.2592514243858921 after getFileData: cacheData.length = 960, fileData.length = 0
2024-05-14 20:03:16.245  - debug: history.0 (7218) 0_userdata.0.test_history17157097962440.2592514243858921 pre-cut data to 1 oldest values
2024-05-14 20:03:16.245  - debug: history.0 (7218) 0_userdata.0.test_history17157097962440.2592514243858921 Beautify: 1 results
2024-05-14 20:03:16.245  - debug: history.0 (7218) 0_userdata.0.test_history17157097962440.2592514243858921 after beautify: options.result.length = 1
2024-05-14 20:03:16.245  - debug: history.0 (7218) 0_userdata.0.test_history17157097962440.2592514243858921 Send: 1 values in: 1ms

Selects 19700101 -> 20240209 for 0_userdata.0.test_history


const generateRows = 961;:

2024-05-14 20:00:36.446  - debug: history.0 (7218) 0_userdata.0.test_history17157096364460.6053462561680132 getHistory message: {"id":"0_userdata.0.test_history","options":{"start":1,"end":1707519600000,"aggregate":"none","limit":1,"returnNewestEntries":false,"ignoreNull":true}}
2024-05-14 20:00:36.446  - debug: history.0 (7218) 0_userdata.0.test_history17157096364460.6053462561680132 getHistory options final: {"id":"0_userdata.0.test_history","path":"/home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/","start":1,"end":1707519600000,"step":null,"count":1,"from":false,"ack":false,"q":false,"ignoreNull":true,"aggregate":"none","limit":1,"addId":false,"returnNewestEntries":false,"percentile":null,"quantile":null,"integralUnit":null,"integralInterpolation":null,"removeBorderValues":false,"logId":"0_userdata.0.test_history17157096364460.6053462561680132","round":null,"debugLog":true}
2024-05-14 20:00:36.446  - debug: history.0 (7218) getOneCachedData: got 1 datapoints for 0_userdata.0.test_history
2024-05-14 20:00:36.446  - debug: history.0 (7218) 0_userdata.0.test_history17157096364460.6053462561680132 after getCachedData: length = 1, isFull=false
2024-05-14 20:00:36.447  - debug: history.0 (7218) getOneFileData: 19700101 -> 20240210 for 0_userdata.0.test_history
2024-05-14 20:00:36.447  - debug: history.0 (7218) handleFileData: 20240101 -> /home/mkleine/ioBroker.history/.dev-server/default/iobroker-data/history/20240101/history.0_userdata.0.test_history.json
2024-05-14 20:00:36.447  - debug: history.0 (7218) 0_userdata.0.test_history17157096364460.6053462561680132 after getFileData: cacheData.length = 1, fileData.length = 1
2024-05-14 20:00:36.447  - debug: history.0 (7218) 0_userdata.0.test_history17157096364460.6053462561680132 pre-cut data to 1 oldest values
2024-05-14 20:00:36.447  - debug: history.0 (7218) 0_userdata.0.test_history17157096364460.6053462561680132 Beautify: 1 results
2024-05-14 20:00:36.447  - debug: history.0 (7218) 0_userdata.0.test_history17157096364460.6053462561680132 after beautify: options.result.length = 1
2024-05-14 20:00:36.447  - debug: history.0 (7218) 0_userdata.0.test_history17157096364460.6053462561680132 Send: 1 values in: 1ms

Selects 19700101 -> 20240210 for 0_userdata.0.test_history

@klein0r
Copy link
Contributor Author

klein0r commented May 16, 2024

Another test. Looks like the last record of the first day in selected range is returned (instead the first one). But just if the number of stored values is larger than Maximum state count in RAM / maxLength (960). What does that mean? And why does it work when selecting more values?

Oldest record result for 0_userdata.0.test_history2: {"ts":1714597933000,"val":3} -> 01.05.2024 23:12:13.000 (should be 01.05.2024 11:12:13.000)
const objId = '0_userdata.0.test_history2';
const startTs = new Date(2024, 4, 1, 11, 12, 13);

const stepSize = 60 * 60 * 4 * 1000; // 4 hours
const generateRows = 961; // CHANGE THIS to 961 (or higher)

async function createTestData(count) {
    let testData = [];
    let ts = startTs.getTime();
    let storedValueCnt = 0;

    for (let i = 0; i < count; i++) {
        ts = startTs.getTime() + (stepSize * i);
        testData.push({ ts, val: i, ack: true, from: 'system.adapter.javascript.0' });

        if (testData.length % 100 === 0) {
            await sendToAsync('history.0', 'storeState', {
                id: objId,
                state: testData,
            });

            storedValueCnt += testData.length;
            testData = [];
        }
    }

    if (testData.length > 0) {
        await sendToAsync('history.0', 'storeState', {
            id: objId,
            state: testData,
        });

        storedValueCnt += testData.length;
    }

    console.warn(`Generated test data: ${storedValueCnt} items, from ${formatDate(startTs.getTime(), 'DD.MM.YYYY hh:mm:ss.sss')} to ${formatDate(ts, 'DD.MM.YYYY hh:mm:ss.sss')}`);

    return ts;
}

async function testSelectData(endTs) {
    // THIS IS WORKING
    const testLimit = 1000;
    const getHistoryResult = await sendToAsync('history.0', 'getHistory', {
        id: objId,
        options: {
            start: startTs.getTime(),
            end: endTs,
            aggregate: 'none',
            limit: testLimit,
            returnNewestEntries: false,
            ignoreNull: true,
            addId: true,
            from: true,
            ack: true,
            q: true,
        }
    });
    const firstRecord = getHistoryResult?.result[0];
    if (firstRecord.ts !== startTs.getTime()) {
        console.warn(`Oldest record result for ${objId}: ${JSON.stringify(firstRecord)} -> ${formatDate(firstRecord.ts, 'DD.MM.YYYY hh:mm:ss.sss')} (should be ${formatDate(startTs.getTime(), 'DD.MM.YYYY hh:mm:ss.sss')})`);
    }

    // THIS IS NOT WORKING (limit too low?)
    const getOldestResult = await sendToAsync('history.0', 'getHistory', {
        id: objId,
        options: {
            start: 1,
            end: endTs,
            aggregate: 'none',
            limit: 1,
            returnNewestEntries: false,
            ignoreNull: true,
        }
    });
    const singleRecord = getOldestResult?.result[0];
    if (singleRecord.ts !== startTs.getTime()) {
        console.warn(`Oldest record result for ${objId}: ${JSON.stringify(singleRecord)} -> ${formatDate(singleRecord.ts, 'DD.MM.YYYY hh:mm:ss.sss')} (should be ${formatDate(startTs.getTime(), 'DD.MM.YYYY hh:mm:ss.sss')})`);
    }
}

createState(objId, { type: 'number', read: true, write: true }, async () => {
    await sendToAsync('history.0', 'enableHistory', {
        id: objId,
        options: {
            enabled: true,
            aliasId: '',
            debounceTime: 0,
            blockTime: 0,
            changesOnly: true,
            changesRelogInterval: 0,
            changesMinDelta: 0,
            ignoreBelowNumber: '',
            disableSkippedValueLogging: false,
            retention: 31536000,
            customRetentionDuration: 365,
            maxLength: 960,
            enableDebugLogs: true,
            debounce: 0,
        }
    });
    const enabledDps = await sendToAsync('history.0', 'getEnabledDPs', {});

    console.log(`Logging is active for ${Object.keys(enabledDps).join(', ')}`);

    if (Object.keys(enabledDps).includes(objId)) {
        // Delete previous data
        const deleteAllResult = await sendToAsync('history.0', 'deleteAll', [{ id: objId }]);
        console.log(`Deleted all saved values of ${objId}: ${deleteAllResult?.success}`);

        // Save new test data
        const endTs = await createTestData(generateRows);

        // loop for development
        setInterval(async () => {
            testSelectData(endTs);
        }, 2000);
    } else {
        console.error(`Logging not activated for ${objId}`);
    }
});

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

1 participant