search

ioBroker / ioBroker.history

manages state history
MIT License
30 stars 23 forks source link

sendto(getHistory) not returning the oldest value #331

Open klein0r opened 6 months ago

klein0r commented 6 months ago

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:

klein0r commented 6 months ago

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 commented 6 months ago

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}`);
    }
});