SPIFlashLogger class - Uses a provided SPI flash class or the imp003+'s built-in SPI flash class to turn part of the SPI flash into a rotating log (first in, first out) of serialised objects.

README.md

SPI Flash Logger class

Introduction

The SPI Flash Logger class manages all or a portion of a SPI flash (either via imp003+'s built-in SPI flash driver or any functionally compatible driver) and turns it into an logger. It will log any serialisable object (table, array, string, blob, integer, float, boolean and null) and when it reaches the end of the available space it will override the oldest data first.

NOR-flash technology

The SPI flash uses NOR technology. This means that all bits are 1 at their initial value (or after erasing) and can be changed to 0 with a write command. Once a bit has been changed to 0 it will remain there until it is erased. Further writes have no effect, similarly writing a 1 never has any effect. Reads and writes are unlimited and reliable but erase actions are limited to somewhere between 100,000 and 1,000,000 erases on any one sector. For this reason, it is best to try to distribute erases over the storage space as much as possible to avoid hot-spots.

Format

The physical memory is usually divided into blocks (64kb) and sectors (4kb) and the class adds a concept of chunks (256 bytes). This class ignores blocks and works with sector and chunks but all erases are performed one sector at a time. At the start of every sector use the first chunk to store meta data about the sector, specifically a four-byte sector id and a two bytes chunk map. In memory the class tracks the exact position of the next write but if the device reboots (and loses this location) the sector meta data is use to rebuild this value to the closest chunk.

Efficiency

• 256 bytes of every sector are expended on meta data.
• Serialisation of the object has some overhead dependant on the object structure. The serialised object contains length and CRC meta data.
• There is a four byte marker before every object to help locate the start of each object in the data stream.
• After a reboot the sector meta data allows the class to locate the next write position at the next chunk which wastes some of the previous chunk.
• Write and read operations need to operate a sector at a time because of the meta data at the start of each sector.

Class Methods

constructor([start [, end [, flash]])

• start = the byte location of the start of the file system. Defaults to 0. Must be on a sector boundary.
• end = the byte location of the end of the file system + 1. Defaults to the size of the storage. Must be on a sector boundary.
• flash = a initialised SPIFlash object. If not provided the internal hardware.spiflash object will be used.

dimensions()

• returns the size, in bytes, of the storage

write(object)

• object = any serialisable object not larger than the storage space (less the overhead)
• returns nothing

readSync(callback)

• callback = function which will be called once for every object found on the flash. It will be called from the oldest to the newest.
• returns nothing

erase()

• returns nothing

index.nut

//==============================================================================
// return;
imp.setpowersave(true);
logger <- SPIFlashLogger(0, 5*4096);

if (false) {
    server.log("========[ Erasing ]=========")
    logger.erase();
    server.log("========[ Done ]=========\n\n")
}

if (true) {
    server.log("========[ Writing ]=========")
    for (local i = 0; i < 1; i++) {
        server.log("Start of " + i + "\n")
        logger.write("Start of " + i);
        server.log("Writing blob\n")
        logger.write(blob(2500));
        server.log("Writing end of " + i + "\n")
        logger.write("End of " + i);
        server.log("\n")
    }
    server.log("========[ Done ]=========\n\n")
}

if (true) {
    server.log("========[ Reading ]=========")
    logger.readSync(function (object) {
        switch (typeof object) {
            case "string":
                server.log(format("Read: %s[%d] %s", typeof object, object.len(), object));
                break;
            case "table":
            case "array":
            case "blob":
                server.log(format("Read: %s[%d]", typeof object, object.len()));
                break;
            default:
                server.log(format("Read: %s", typeof object));
        }
    });
    server.log("========[ Done ]=========\n\n")

    server.log("========[ Erasing ]=========")
    logger.erase();
    server.log("========[ Done ]=========\n\n")
}

serializer.device.nut

// =============================================================================
class Serializer {

    // Serialize a variable of any type into a blob
    function serialize (obj, prefix = null) {
        // Take a guess at the initial size
        local b = blob(2000);
        local header_len = 3;
        local prefix_len = (prefix == null) ? 0 : prefix.len();
        // Write the prefix plus dummy data for len and crc late
        if (prefix_len > 0) {
            foreach (ch in prefix) b.writen(ch, 'b');
        }
        b.writen(0, 'b');
        b.writen(0, 'b');
        b.writen(0, 'b');
        // Serialise the object
        _serialize(b, obj);
        // Shrink it down to size
        b.resize(b.tell());
        // Go back and add the len and CRC
        local body_len = b.len() - header_len - prefix_len;
        b.seek(prefix_len);
        b.writen(body_len, 'w');
        b.writen(LRC8(b, header_len + prefix_len), 'b');
        // Hop back home
        b.seek(0);
        return b;
    }

    function _serialize (b, obj) {

        switch (typeof obj) {
            case "integer":
                return _write(b, 'i', format("%d", obj));
            case "float":
                local f = format("%0.7f", obj).slice(0,9);
                while (f[f.len()-1] == '0') f = f.slice(0, -1);
                return _write(b, 'f', f);
            case "null":
            case "function": // Silently setting this to null
                return _write(b, 'n');
            case "bool":
                return _write(b, 'b', obj ? "\x01" : "\x00");
            case "blob":
                return _write(b, 'B', obj);
            case "string":
                return _write(b, 's', obj);
            case "table":
            case "array":
                local t = (typeof obj == "table") ? 't' : 'a';
                _write(b, t, obj.len());
                foreach ( k,v in obj ) {
                    _serialize(b, k);
                    _serialize(b, v);
                }
                return;
            default:
                throw ("Can't serialize " + typeof obj);
                // Utils.log("Can't serialize " + typeof obj);
        }
    }


    function _write(b, type, payload = null) {

        // Calculate the lengths
        local prefix_length = true;
        local payloadlen = 0;
        switch (type) {
            case 'n':
            case 'b':
                prefix_length = false;
                break;
            case 'a':
            case 't':
                payloadlen = payload;
                break;
            default:
                payloadlen = payload.len();
        }
        
        // Update the blob
        b.writen(type, 'b');
        if (prefix_length) {
            b.writen(payloadlen >> 8 & 0xFF, 'b');
            b.writen(payloadlen & 0xFF, 'b');
        }
        if (typeof payload == "string" || typeof payload == "blob") {
            foreach (ch in payload) {
                b.writen(ch, 'b');
            }
        }
    }


    // Deserialize a string into a variable
    function deserialize (s, prefix = null) {
        // Read and check the prefix and header
        local prefix_len = (prefix == null) ? 0 : prefix.len();
        local header_len = 3;
        s.seek(0);
        local pfx = prefix_len > 0 ? s.readblob(prefix_len) : null;
        local len = s.readn('w');
        local crc = s.readn('b');
        if (s.len() != len+prefix_len+header_len) throw "Expected " + len + " bytes";
        // Check the prefix
        if (prefix != null && pfx.tostring() != prefix.tostring()) throw "Prefix mismatch";
        // Check the CRC
        local _crc = LRC8(s, prefix_len+header_len);
        if (crc != _crc) throw format("CRC err: 0x%02x != 0x%02x", crc, _crc);
        // Deserialise the rest
        return _deserialize(s, prefix_len+header_len).val;
    }

    function _deserialize (s, p = 0) {
        for (local i = p; i < s.len(); i++) {
            local t = s[i];
            // Utils.log("Next type: 0x%02x", t)
            
            switch (t) {
                case 'n': // Null
                    return { val = null, len = 1 };
                case 'i': // Integer
                    local len = s[i+1] << 8 | s[i+2];
                    s.seek(i+3);
                    local val = s.readblob(len).tostring().tointeger();
                    return { val = val, len = 3+len };
                case 'f': // Float
                    local len = s[i+1] << 8 | s[i+2];
                    s.seek(i+3);
                    local val = s.readblob(len).tostring().tofloat();
                    return { val = val, len = 3+len };
                case 'b': // Bool
                    local val = s[i+1];
                    // Utils.log("** Bool with value: %s", (val == 1) ? "true" : "false")
                    return { val = (val == 1), len = 2 };
                case 'B': // Blob
                    local len = s[i+1] << 8 | s[i+2];
                    local val = blob(len);
                    for (local j = 0; j < len; j++) {
                        val[j] = s[i+3+j];
                    }
                    return { val = val, len = 3+len };
                case 's': // String
                    local len = s[i+1] << 8 | s[i+2];
                    local val = "";
                    s.seek(i+3);
                    if (len > 0) {
                        val = s.readblob(len).tostring();
                    }
                    // Utils.log("** String with length %d (0x%02x 0x%02x) and value: %s", len, s[i+1], s[i+2], val)
                    return { val = val, len = 3+len };
                case 't': // Table
                case 'a': // Array
                    local len = 0;
                    local nodes = s[i+1] << 8 | s[i+2];
                    i += 3;
                    local tab = null;

                    if (t == 'a') {
                        // Utils.log("** Array with " + nodes + " nodes");
                        tab = [];
                    }
                    if (t == 't') {
                        // Utils.log("** Table with " + nodes + " nodes");
                        tab = {};
                    }

                    for (local node = 0; node < nodes; node++) {

                        local k = _deserialize(s, i);
                        i += k.len;
                        len += k.len;

                        local v = _deserialize(s, i);
                        i += v.len;
                        len += v.len;
                        
                        // Utils.log("** Node %d: Key = '%s' (%d), Value = '" + v.val + "' [%s] (%d)", node, k.val, k.len, typeof v.val, v.len)
                        
                        if (typeof tab == "array")  tab.push(v.val);
                        else                        tab[k.val] <- v.val;
                    }
                    return { val = tab, len = len+3 };
                default:
                    throw format("Unknown type: 0x%02x at %d", t, i);
            }
        }
    }


    function LRC8 (data, offset = 0) {
        local LRC = 0x00;
        for (local i = offset; i < data.len(); i++) {
            LRC = (LRC + data[i]) & 0xFF;
        }
        return ((LRC ^ 0xFF) + 1) & 0xFF;
    }

}

spiflashlogger.device.nut

/*
 * To Do: Add callbacks to allow the _at_pos to be read and write from nv. 
 *        It should be read at init() and written at write()
 */

//==============================================================================
class SPIFlashLogger {
    
    _flash = null;
    _size = null;
    _start = null;
    _end = null;
    _len = null;
    _sectors = 0;
    _max_data = 0;
    _at_sec = 0;
    _at_pos = 0;
    _map = null;
    _enables = 0;
    _next_sec_id = 1;
    
    _version = [1, 0, 0];
    
    static SECTOR_SIZE = 4096;
    static SECTOR_META_SIZE = 6;
    static SECTOR_BODY_SIZE = 4090;
    static CHUNK_SIZE = 256;
    
    static OBJECT_MARKER = "\x00\xAA\xCC\x55";
    static OBJECT_MARKER_SIZE = 4;
    static OBJECT_HDR_SIZE = 7; // OBJECT_MARKER (4 bytes) + size (2 bytes) + crc (1 byte)
    static OBJECT_MIN_SIZE = 6; // OBJECT_MARKER (4 bytes) + size (2 bytes)

    static SECTOR_DIRTY = 0x00;
    static SECTOR_CLEAN = 0xFF;
    
    //--------------------------------------------------------------------------
    constructor(start = null, end = null, flash = null) {
        
        if (!("Serializer" in getroottable())) throw "Serializer class must be defined";
        
        _flash = flash ? flash : hardware.spiflash;

        _enable();
        _size = _flash.size();
        _disable();
        
        if (start == null) _start = 0;
        else if (start < _size) _start = start;
        else throw "Invalid start value";
        if (_start % SECTOR_SIZE != 0) throw "start must be at a sector boundary";
        
        if (end == null) _end = _size;
        else if (end > _start) _end = end;
        else throw "Invalid end value";
        if (_end % SECTOR_SIZE != 0) throw "end must be at a sector boundary";
        
        _len = _end - _start;
        _sectors = _len / SECTOR_SIZE;
        _max_data = _sectors * SECTOR_BODY_SIZE;
        _map = blob(_sectors); // Can compress this by eight by using bits instead of bytes
        
        // Initialise the values by reading the metadata
        _init();
    }
    
    //--------------------------------------------------------------------------
    function dimensions() {
        return { "size": _size, "len": _len, "start": _start, "end": _end, "sectors": _sectors, "sector_size": SECTOR_SIZE }
    }
    
    //--------------------------------------------------------------------------
    function write(object) {
        
        // Serialise the object
        local object = Serializer.serialize(object, OBJECT_MARKER);
        local obj_len = object.len();
        assert(obj_len < _max_data);

        _enable();
        
        // Write one sector at a time with the metadata attached
        local obj_pos = 0, obj_remaining = obj_len;
        do {
            
            // How far are we from the end of the sector
            if (_at_pos < SECTOR_META_SIZE) _at_pos = SECTOR_META_SIZE;
            local sec_remaining = SECTOR_SIZE - _at_pos;
            if (obj_remaining < sec_remaining) sec_remaining = obj_remaining;
            
            // We are too close to the end of the sector, skip to the next sector
            if (sec_remaining < OBJECT_MIN_SIZE) {
                _at_sec = (_at_sec + 1) % _sectors;
                _at_pos = SECTOR_META_SIZE;
            }
            
            // Now write the data
            _write(object, _at_sec, _at_pos, obj_pos, sec_remaining);
            _map[_at_sec] = SECTOR_DIRTY;
            
            // Update the positions
            obj_pos += sec_remaining;
            obj_remaining -= sec_remaining;
            _at_pos += sec_remaining;
            if (_at_pos >= SECTOR_SIZE) {
                _at_sec = (_at_sec + 1) % _sectors;
                _at_pos = SECTOR_META_SIZE;
            }
            
        } while (obj_remaining > 0);
        
        _disable();
    }
    
    //--------------------------------------------------------------------------
    function readSync(callback) {
        
        local serialised_object = blob();

        _enable();
        for (local i = 0; i < _sectors; i++) {
            local sector = (_at_sec+i+1) % _sectors;
            if (_map[sector] == SECTOR_DIRTY) {

                // Read the whole body in. We could read in just the dirty chunks but for now this is easier
                local start = _start + (sector * SECTOR_SIZE);
                local data = _flash.read(start + SECTOR_META_SIZE, SECTOR_BODY_SIZE);
                local data_str = data.tostring();

                local find_pos = 0;
                while (find_pos < data.len()) {
                    if (serialised_object.len() == 0) {
                        
                        // We are at the start of a new object, so search for a header in the data
                        // server.log(format("Searching for header from sec %d pos %d", sector, find_pos));
                        local header_loc = data_str.find(OBJECT_MARKER, find_pos);
                        if (header_loc != null) {

                            
                            // Get the length of the object and make a blob to receive it
                            data.seek(header_loc + OBJECT_MARKER_SIZE);
                            local len = data.readn('w');
                            serialised_object = blob(OBJECT_HDR_SIZE + len);
                            
                            // server.log(format("Found a header at sec %d pos %d len %d", sector, header_loc, len));
                            
                            // Now reenter the loop to receive the data into the new blob
                            data.seek(header_loc);
                            find_pos = header_loc;
                            continue;

                        } else {
                            
                            // No object header found, so skip to the next sector
                            break;
                            
                        }
                        
                    } else {
                        
                        // Work out how much is required and available
                        local rem_in_data = data.len()  - data.tell();
                        local rem_in_object = serialised_object.len() - serialised_object.tell();
                        
                        // Copy only as much as is required and available
                        local rem_to_copy = (rem_in_data <= rem_in_object) ? rem_in_data : rem_in_object;
                        // server.log(format("rem_in_data = %d, rem_in_object = %d => rem_to_copy = %d", rem_in_data, rem_in_object, rem_to_copy))
                        serialised_object.writeblob(data.readblob(rem_to_copy));

                        // If we have finished filling the serialised object then deserialise it
                        local rem_in_object = serialised_object.len() - serialised_object.tell();
                        if (rem_in_object == 0) {
                            try {
                                local object = Serializer.deserialize(serialised_object, OBJECT_MARKER);
                                callback(object);
                                find_pos += rem_to_copy;
                                // server.log("After deserialise, search from: " + find_pos);
                            } catch (e) {
                                server.error(e);
                                find_pos ++;
                            }
                            serialised_object.resize(0);
                        } else {
                            find_pos += rem_to_copy;
                        }
                        
                        // If we have run out of data in this sector, move onto the next sector
                        local rem_in_data = data.len()  - data.tell();
                        if (rem_in_data == 0) {
                            break;
                        }
                    }

                }
            }
        }
        _disable();

    }
    
    //--------------------------------------------------------------------------
    function erase() {
        for (local sector = 0; sector < _sectors; sector++) {
            if (_map[sector] == SECTOR_DIRTY) {
                erase(sector);
            }
        }
    }
    
    //--------------------------------------------------------------------------
    function _enable() {
        if (_enables++ == 0) {
            _flash.enable();
        }
    }    
    
    //--------------------------------------------------------------------------
    function _disable() {
        if (--_enables == 0)  {
            _flash.disable();
        }
    }    
    
    //--------------------------------------------------------------------------
    function _write(object, sector, pos, object_pos = 0, len = null) {
        
        if (len == null) len = object.len();

        // Prepare the new metadata
        local meta = blob(6);

        // Erase the sector(s) if it is dirty but not if we are appending
        local appending = (pos > SECTOR_META_SIZE);
        if (_map[sector] == SECTOR_DIRTY && !appending) {
            // Prepare the next sector
            erase(sector, sector+1, true);
            // Write a new sector id
            meta.writen(_next_sec_id++, 'i');
        } else {
            // Make sure we have a valid sector id
            if (_metadata(sector).id > 0) {
                meta.writen(0xFFFFFFFF, 'i');
            } else {
                meta.writen(_next_sec_id++, 'i');
            }
        }
        
        // Write the new usage map, changing only the bit in this write
        local chunk_map = 0xFFFF;
        local bit_start = math.floor(1.0 * pos / CHUNK_SIZE).tointeger();
        local bit_finish = math.ceil(1.0 * (pos+len) / CHUNK_SIZE).tointeger();
        for (local bit = bit_start; bit < bit_finish; bit++) {
            local mod = 1 << bit;
            chunk_map = chunk_map ^ mod;
        }
        meta.writen(chunk_map, 'w');
        
        // Write the metadata and the data
        local start = _start + (sector * SECTOR_SIZE);
        // server.log(format("Writing to sec %d pos %d to %d and metadata 0x%04x", sector, pos, pos+len, chunk_map));
        _enable();
        _flash.write(start, meta);
        _flash.write(start + pos, object, 0, object_pos, object_pos+len);
        _disable();
        
        return len;
    }
    
    //--------------------------------------------------------------------------
    function _metadata(sector) {
        // NOTE: Should we skip clean sectors automatically?
        // server.log("Reading meta from sector: " + sector);
        local start = _start + (sector * SECTOR_SIZE);
        local meta = _flash.read(start, SECTOR_META_SIZE);
        // Parse the meta data 
        meta.seek(0);
        return { "id": meta.readn('i'), "map": meta.readn('w') };
        
    }
    
    //--------------------------------------------------------------------------
    function _init() {
        
        local best_id = 0, best_sec = 0, best_map = 0xFFFFF;
        
        // Read all the metadata
        _enable();
        for (local sector = 0; sector < _sectors; sector++) {
            // Hunt for the highest id and its map
            local meta = _metadata(sector);
            if (meta.id > 0) {
                if (meta.id > best_id) {
                    best_sec = sector;
                    best_id = meta.id;
                    best_map = meta.map;
                }
                // server.log(format("Sector %d [id: %d] => 0x%04x", sector, meta.id, meta.map));
            } else {
                // This sector has no id, we are going to assume it is clean
                _map[sector] = SECTOR_CLEAN;
            }
        }
        _disable();
        
        // We should have the answers we are seeking now
        _at_pos = 0;
        _at_sec = best_sec;
        _next_sec_id = best_id+1;
        for (local bit = 1; bit <= 16; bit++) {
            local mod = 1 << bit;
            _at_pos += (~best_map & mod) ? CHUNK_SIZE : 0;
        }
        // server.log(format("Initial sector %d [next_id: %d], pos %d", _at_sec, _next_sec_id, _at_pos));
        
    }
    
    //--------------------------------------------------------------------------
    function _erase(start_sector = null, end_sector = null, preparing = false) {
        
        if (start_sector == null) {
            start_sector = 0;
            end_sector = _sectors;
        }
        if (end_sector == null) {
            end_sector = start_sector + 1;
        } 
        if (start_sector < 0 || end_sector > _sectors) throw "Invalid format request";

        /*
        if (start_sector +1 == end_sector) {
            server.log(format("Erasing flash sectors %d", start_sector));
        } else {
            server.log(format("Erasing flash from sectors %d to %d", start_sector, end_sector));
        }
        */
        
        _enable();
        for (local sector = start_sector; sector < end_sector; sector++) {
            // Erase the requested sector
            _flash.erasesector(_start + (sector * SECTOR_SIZE));
            
            // Mark the sector as clean
            _map[sector] = SECTOR_CLEAN;
            
            // Move the pointer on to the next sector
            if (!preparing && sector == _at_sec) {
                _at_sec = (_at_sec + 1) % _sectors;
                _at_pos = SECTOR_META_SIZE;
            }
        }
        _disable();
        
    }
}

utils.log

//==============================================================================
class Utils {
    
    function logBin(data, start = null, end = null) {
        
        if (start == null) start = 0;
        if (end == null) end = data.len();
        
        local dbg = "";
        for (local j = start; j < end; j++) {
            dbg += format("%02x ", data[j]);
        }
        server.log(dbg)
    }
    
}