I2C-EEProm write failed because it requires a little delay

[soramame21]

tests-api-i2c got failed.

Log analysis

1. EEProm WR passed when string length is 2 and 10 bytes, but failed when the length is 100 bytes at Case 9.
2. It means that a string, which contains 99 chars and a ending NULL, was written to I2C slave, right after reading 100 bytes data from the same address, but the read string is different from the one written. even read string size is different from written string's.
3. and the failure happened mostly when string size is bigger then page size (32 bytes).

A. The log with more printf, the failed point is marked by <<

[1500793846.72][CONN][RXD] >>> Running case #5: 'I2C - EEProm WR 2 Bytes'... [1500793846.77][CONN][INF] found KV pair in stream: {{testcase_start;I2C - EEProm WR 2 Bytes}}, queued... [1500793846.78][CONN][RXD] [1500793846.78][CONN][RXD] [1500793846.80][CONN][RXD] Address = 5 [1500793846.81][CONN][RXD] Len = 2 [1500793846.84][CONN][RXD] Num Bytes Written = 2 [1500793846.87][CONN][RXD] Num Bytes Read = 2 [1500793846.90][CONN][RXD] Written String = D [1500793846.92][CONN][RXD] Read String = D [1500793846.92][CONN][RXD] [1500793846.98][CONN][INF] found KV pair in stream: {{__testcase_finish;I2C - EEProm WR 2 Bytes;1;0}}, queued... [1500793847.03][CONN][RXD] >>> 'I2C - EEProm WR 2 Bytes': 1 passed, 0 failed [1500793847.03][CONN][RXD] [1500793847.09][CONN][RXD] >>> Running case #6: 'I2C - EEProm 2nd WR 2 Bytes'... [1500793847.14][CONN][INF] found KV pair in stream: {{testcase_start;I2C - EEProm 2nd WR 2 Bytes}}, queued... [1500793847.15][CONN][RXD] [1500793847.16][CONN][RXD] [1500793847.17][CONN][RXD] Address = 5 [1500793847.18][CONN][RXD] Len = 2 [1500793847.21][CONN][RXD] Num Bytes Written = 2 [1500793847.24][CONN][RXD] Num Bytes Read = 2 [1500793847.27][CONN][RXD] Written String = P [1500793847.29][CONN][RXD] Read String = P [1500793847.30][CONN][RXD] [1500793847.35][CONN][INF] found KV pair in stream: {{testcase_finish;I2C - EEProm 2nd WR 2 Bytes;1;0}}, queued... [1500793847.41][CONN][RXD] >>> 'I2C - EEProm 2nd WR 2 Bytes': 1 passed, 0 failed [1500793847.41][CONN][RXD] [1500793847.47][CONN][RXD] >>> Running case #7: 'I2C - EEProm WR 10 Bytes'... [1500793847.52][CONN][INF] found KV pair in stream: {{__testcase_start;I2C - EEProm WR 10 Bytes}}, queued... [1500793847.53][CONN][RXD] [1500793847.54][CONN][RXD] [1500793847.55][CONN][RXD] Address = 100 [1500793847.57][CONN][RXD] Len = 10 [1500793847.60][CONN][RXD] Num Bytes Written = 10 [1500793847.62][CONN][RXD] Num Bytes Read = 10 [1500793847.66][CONN][RXD] Written String = ABNYCLCBR [1500793847.69][CONN][RXD] Read String = ABNYCLCBR [1500793847.70][CONN][RXD] [1500793847.75][CONN][INF] found KV pair in stream: {{testcase_finish;I2C - EEProm WR 10 Bytes;1;0}}, queued... [1500793847.80][CONN][RXD] >>> 'I2C - EEProm WR 10 Bytes': 1 passed, 0 failed [1500793847.81][CONN][RXD] [1500793847.87][CONN][RXD] >>> Running case #8: 'I2C - EEProm 2nd WR 10 Bytes'... [1500793847.93][CONN][INF] found KV pair in stream: {{testcase_start;I2C - EEProm 2nd WR 10 Bytes}}, queued... [1500793847.94][CONN][RXD] [1500793847.94][CONN][RXD] [1500793847.96][CONN][RXD] Address = 100 [1500793847.97][CONN][RXD] Len = 10 [1500793848.00][CONN][RXD] Num Bytes Written = 10 [1500793848.03][CONN][RXD] Num Bytes Read = 10 [1500793848.06][CONN][RXD] Written String = EEHBSCLIV [1500793848.10][CONN][RXD] Read String = EEHBSCLIV [1500793848.10][CONN][RXD] [1500793848.16][CONN][INF] found KV pair in stream: {{__testcase_finish;I2C - EEProm 2nd WR 10 Bytes;1;0}}, queued... [1500793848.22][CONN][RXD] >>> 'I2C - EEProm 2nd WR 10 Bytes': 1 passed, 0 failed [1500793848.22][CONN][RXD] [1500793848.28][CONN][RXD] >>> Running case #9: 'I2C - EEProm WR 100 Bytes'... [1500793848.33][CONN][INF] found KV pair in stream: {{testcase_start;I2C - EEProm WR 100 Bytes}}, queued... [1500793848.39][CONN][RXD] :75::FAIL: String Written != String Read << failed 1st point! hit TEST_ASSERT_MESSAGE, write string != read string, length: 100 bytes [1500793848.43][CONN][RXD] :76::FAIL: String Written != String Read [1500793848.65][CONN][RXD] :77::FAIL: Expected 'YRGCTGXMUZXVMVDVZVCZXGSBXUTRUKGRKQGXPIDXMXDSYMYKAMVCEHGRBWKQVFRTLWAGVRTJVQWBKZJOVPBMHNKFDEZXFWSVUVQ' Was 'YRGCTGXMUZXVMVDVZVCZXGSB@'. String read does not match the string written [1500793848.65][CONN][RXD] [1500793848.66][CONN][RXD] [1500793848.67][CONN][RXD] Address = 1000 [1500793848.70][CONN][RXD] Len = 100 [1500793848.73][CONN][RXD] Num Bytes Written = 100 [1500793848.76][CONN][RXD] Num Bytes Read = 100 [1500793848.88][CONN][RXD] Written String = YRGCTGXMUZXVMVDVZVCZXGSBXUTRUKGRKQGXPIDXMXDSYMYKAMVCEHGRBWKQVFRTLWAGVRTJVQWBKZJOVPBMHNKFDEZXFWSVUVQ [1500793848.92][CONN][RXD] Read String = YRGCTGXMUZXVMVDVZVCZXGSB@ [1500793848.93][CONN][RXD] [1500793849.00][CONN][INF] found KV pair in stream: {{testcase_finish;I2C - EEProm WR 100 Bytes;0;3}}, queued... [1500793849.08][CONN][RXD] >>> 'I2C - EEProm WR 100 Bytes': 0 passed, 3 failed with reason 'Test Cases Failed' [1500793849.08][CONN][RXD] [1500793849.15][CONN][RXD] >>> Running case #10: 'I2C - EEProm 2nd WR 100 Bytes'... [1500793849.20][CONN][INF] found KV pair in stream: {{__testcase_start;I2C - EEProm 2nd WR 100 Bytes}}, queued... [1500793849.22][CONN][RXD] [1500793849.23][CONN][RXD] ** [1500793849.25][CONN][RXD] Address = 1000 [1500793849.27][CONN][RXD] Len = 100 [1500793849.30][CONN][RXD] Num Bytes Written = 100 [1500793849.32][CONN][RXD] Num Bytes Read = 100 [1500793849.45][CONN][RXD] Written String = << failed 2nd point! but was not be caught by hitting any TEST_ASSERT_MESSAGE, write string != read string, length: 100 bytes YXTOJMFQQVBGBORSMNLISXWWPSELZKGCPEPDSRDBZZQNYWTBLKZHWAHAOZFOGWVRWAYOONNNAXJBTWDPIDQPQCXIARDIFSQOZPW [1500793849.58][CONN][RXD] Read String = YXTOJMFQQVBGBORSMNLISXWWPSELZKGCPEPDSRDBZZQNYWTBLKZHWAHAQZNLURZPZOEBVRETQEXUDSNTKVJUVXKQARDIFSQOZPW [1500793849.59][CONN][RXD] ** [1500793849.65][CONN][INF] found KV pair in stream: {{testcase_finish;I2C - EEProm 2nd WR 100 Bytes;1;0}}, queued... [1500793849.70][CONN][RXD] >>> 'I2C - EEProm 2nd WR 100 Bytes': 1 passed, 0 failed [1500793849.70][CONN][RXD] [1500793849.77][CONN][RXD] >>> Test cases: 9 passed, 1 failed with reason 'Test Cases Failed' [1500793849.79][CONN][RXD] >>> TESTS FAILED! [1500793849.82][CONN][INF] found KV pair in stream: {{testcase_summary;9;1}}, queued... [1500793849.85][CONN][INF] found KV pair in stream: {{max_heap_usage;0}}, queued... [1500793849.85][HTST][ERR] orphan event in main phase: {{max_heap_usage;0}}, timestamp=1500793849.845000 [1500793849.87][CONN][INF] found KV pair in stream: {{reserved_heap;0}}, queued... [1500793849.87][HTST][ERR] orphan event in main phase: {{reserved_heap;0}}, timestamp=1500793849.867000 [1500793849.89][CONN][INF] found KV pair in stream: {{end;failure}}, queued... [1500793849.89][HTST][INF] __notify_complete(False) [1500793849.90][HTST][INF] exit_event_queue received [1500793849.90][HTST][INF] test suite run finished after 4.82 sec... [1500793849.90][CONN][INF] found KV pair in stream: {{exit;0}}, queued... [1500793849.90][CONN][INF] received special even 'host_test_finished' value='True', finishing [1500793849.91][HTST][INF] CONN exited with code: 0 [1500793849.91][HTST][INF] Some events in queue [1500793849.92][HTST][INF] stopped consuming events [1500793849.92][HTST][INF] host test result() call skipped, received: False [1500793849.92][HTST][WRN] missing __exit event from DUT [1500793849.92][HTST][INF] calling blocking teardown() [1500793849.92][HTST][INF] teardown() finished [1500793849.92][HTST][INF] {{result;failure}} mbedgt: checking for GCOV data... mbedgt: mbed-host-test-runner: stopped and returned 'FAIL' mbedgt: test on hardware with target id: 701100000000000000000000000000000000000097969904 mbedgt: test suite 'tests-api-i2c' ................................................................... FAIL in 62.52 sec test case: 'I2C - EEProm 2nd WR 10 Bytes' .................................................. OK in 0.23 sec test case: 'I2C - EEProm 2nd WR 100 Bytes' .................................................. OK in 0.45 sec test case: 'I2C - EEProm 2nd WR 2 Bytes' .................................................... OK in 0.21 sec test case: 'I2C - EEProm 2nd WR Single Byte' ................................................ OK in 0.06 sec test case: 'I2C - EEProm WR 10 Bytes' ...................................................... OK in 0.23 sec test case: 'I2C - EEProm WR 100 Bytes' ...................................................... FAIL in 0.67 sec test case: 'I2C - EEProm WR 2 Bytes' ........................................................ OK in 0.21 sec test case: 'I2C - EEProm WR Single Byte' .................................................... OK in 0.06 sec test case: 'I2C - Instantiation of I2C Object' .............................................. OK in 0.07 sec test case: 'I2C - LM75B Temperature Read' ................................................... OK in 0.07 sec mbedgt: test case summary: 9 passes, 1 failure

Test and Fix

4. I2CEeprom driver writes data with page alignment. please refer following I2CEeprom::write() source code.
5. After testing with different sizes, I identified that
   • The failure can be reproduced when the string is written in multiple pages.
   • Once the string can be written in a single page, then no error will occur.
   • String written in 1st page can be read correctly always.
6. The WR address is 1000, if the string size is 24 byte (=23 chars with a ending NULL), then the string doesn't cross the page ended at 1024. then it can be read correctly. if the string size is 25 byte, then 24 chars will locate at 1st page ended at 1024 and 1 byte (the ending NULL) will be located at 2nd page ended at 1056. then the read and comparison test will fail.
7. Added line A in I2CEeprom::write. a 2ms delay is added before writing in a new page. the fix is quite platform dependent. on xxxM066, wait_ms(2); can pass the test, but when changed to wait_ms(1); then the test got failed. I'm not sure the 2ms wait is good enough for other platforms.
8. I assume, other platforms can also have this issue. how were they solved?
9. I2CEeprom driver is not ARM source file, should I make a pull request? or just remark it as a known issue?

B. ci-test-shield\I2CEeprom\I2CEeprom.cpp, with fixed code

size_t I2CEeprom::write(size_t address, const char *buffer, size_t size) {
    // Check the address and size fit onto the chip.
    if (!checkSpace(address, size))
        return 0;

    const char *page = buffer;
    size_t left = size;

    // Whle we have some more data to write.
    while (left != 0) {
        // Calculate the number of bytes we can write in the current page.
        // If the address is not page aligned then write enough to page 
        // align it.
        size_t toWrite;
        if ((address % m_pageSize) != 0) {
            toWrite = (((address / m_pageSize) + 1) * m_pageSize) - address;
            if (toWrite > size) {
                toWrite = size;
            }
        } else {
            if (left <= m_pageSize) {
                toWrite = left;
            } else {
                toWrite = m_pageSize;
            }
        }

        //printf("Writing [%.*s] at %d size %d\n\r", toWrite, page, address, toWrite);
        wait_ms(2);      //line A,  added a little deplay, before writing in a new page.
        // Start the page write with the addres ine one write call.
        char values[] = { (address >> 8), (address & 0xFF) };

        m_i2c.start();
        if (m_i2c.write(m_i2cAddress) == 0) {
            return size - left;
        }
        if (m_i2c.write(values[0]) == 0) {
            return size - left;
        }
        if (m_i2c.write(values[1]) == 0) {
            return size - left;
        }

        // Write the bytes out one at a time to avoid having to copy them to
        // another buffer.        
        for (int count = 0; count != toWrite; ++count) {
            if (m_i2c.write(*page) == 0) {
            // Write failed to return bytes written so far.
                return size - left;
            }
            ++page;
        }

        // Stop the transaction now we've completed the page
        // write.
        m_i2c.stop();

        waitForWrite();

        // Update the counters with the amount we've just written
        left -= toWrite;
        address += toWrite;
    }

    return size;
}

[BlackstoneEngineering]

@soramame21 , please specify what platform you are seeing this failure on. Also please check that you are using the latest tests, please provide a git log --oneline -n1 so we can confirm your version

[soramame21]

@BlackstoneEngineering This is a pre-release platform working with 5v not 3.3v. the ci-test-shield is modified specially. I'm using the latest version of ci-test-shield.

dfce4e2 (HEAD -> master, origin/master, origin/HEAD) Add repository structure to readme

Since the working environment is different from others, I think we may not need to make further investigation on it. I'd like to close this issue. What is your comment or suggestion?

[soramame21]

@BlackstoneEngineering I close it now. if it's necessary to go deeper, we can reopen it.