Weird i2c erors on ESP32-DEVKIT_V1 doit

[marian-craciunescu]

I have a PCF-8523 .Initally all goes well but after a time i get this. error.

[E][esp32-hal-i2c.c:1115] i2cProcQueue(): TimeoutRecovery: expected=0ms, actual=2ms [E][esp32-hal-i2c.c:609] i2cDumpI2c(): i2c=0x3ffc1894 [E][esp32-hal-i2c.c:610] i2cDumpI2c(): dev=0x60013000 date=0x16042000 [E][esp32-hal-i2c.c:612] i2cDumpI2c(): lock=0x3ffdf6a0 [E][esp32-hal-i2c.c:614] i2cDumpI2c(): num=0 [E][esp32-hal-i2c.c:615] i2cDumpI2c(): mode=1 [E][esp32-hal-i2c.c:616] i2cDumpI2c(): stage=3 [E][esp32-hal-i2c.c:617] i2cDumpI2c(): error=1 [E][esp32-hal-i2c.c:618] i2cDumpI2c(): event=0x3ffdf724 bits=10 [E][esp32-hal-i2c.c:619] i2cDumpI2c(): intr_handle=0x3ffdf754 [E][esp32-hal-i2c.c:620] i2cDumpI2c(): dq=0x3ffe12cc [E][esp32-hal-i2c.c:621] i2cDumpI2c(): queueCount=1 [E][esp32-hal-i2c.c:622] i2cDumpI2c(): queuePos=0 [E][esp32-hal-i2c.c:623] i2cDumpI2c(): byteCnt=2 [E][esp32-hal-i2c.c:582] i2cDumpDqData(): [0] d0 W STOP buf@=0x3ffc61da, len=1, pos=1, eventH=0x0 bits=0 [E][esp32-hal-i2c.c:598] i2cDumpDqData(): 0x0000: . 03 [E][esp32-hal-i2c.c:944] i2cDumpInts(): row count INTR TX RX [E][esp32-hal-i2c.c:947] i2cDumpInts(): [01] 0x0001 0x0002 0x0002 0x0000 0x000346a6 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000346a6 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [03] 0x0002 0x0040 0x0000 0x0000 0x000346a6 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000346a6 [E][esp32-hal-i2c.c:1115] i2cProcQueue(): TimeoutRecovery: expected=0ms, actual=2ms [E][esp32-hal-i2c.c:609] i2cDumpI2c(): i2c=0x3ffc1894 [E][esp32-hal-i2c.c:610] i2cDumpI2c(): dev=0x60013000 date=0x16042000 [E][esp32-hal-i2c.c:612] i2cDumpI2c(): lock=0x3ffdf6a0 [E][esp32-hal-i2c.c:614] i2cDumpI2c(): num=0 [E][esp32-hal-i2c.c:615] i2cDumpI2c(): mode=1 [E][esp32-hal-i2c.c:616] i2cDumpI2c(): stage=3 [E][esp32-hal-i2c.c:617] i2cDumpI2c(): error=1 [E][esp32-hal-i2c.c:618] i2cDumpI2c(): event=0x3ffdf724 bits=10 [E][esp32-hal-i2c.c:619] i2cDumpI2c(): intr_handle=0x3ffdf754 [E][esp32-hal-i2c.c:620] i2cDumpI2c(): dq=0x3ffe12cc [E][esp32-hal-i2c.c:621] i2cDumpI2c(): queueCount=1 [E][esp32-hal-i2c.c:622] i2cDumpI2c(): queuePos=0 [E][esp32-hal-i2c.c:623] i2cDumpI2c(): byteCnt=8 [E][esp32-hal-i2c.c:582] i2cDumpDqData(): [0] d1 R STOP buf@=0x3ffc6154, len=7, pos=7, eventH=0x0 bits=0 [E][esp32-hal-i2c.c:598] i2cDumpDqData(): 0x0000: ....... 13 13 15 09 00 02 18 [E][esp32-hal-i2c.c:944] i2cDumpInts(): row count INTR TX RX [E][esp32-hal-i2c.c:947] i2cDumpInts(): [01] 0x0001 0x0002 0x0001 0x0000 0x00034b71 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00034b71 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [03] 0x0008 0x0040 0x0000 0x0000 0x00034b72 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0007 0x00034b72 [E][esp32-hal-i2c.c:1115] i2cProcQueue(): TimeoutRecovery: expected=0ms, actual=2ms [E][esp32-hal-i2c.c:609] i2cDumpI2c(): i2c=0x3ffc1894 [E][esp32-hal-i2c.c:610] i2cDumpI2c(): dev=0x60013000 date=0x16042000 [E][esp32-hal-i2c.c:612] i2cDumpI2c(): lock=0x3ffdf6a0 [E][esp32-hal-i2c.c:614] i2cDumpI2c(): num=0 [E][esp32-hal-i2c.c:615] i2cDumpI2c(): mode=1 [E][esp32-hal-i2c.c:616] i2cDumpI2c(): stage=3 [E][esp32-hal-i2c.c:617] i2cDumpI2c(): error=1 [E][esp32-hal-i2c.c:618] i2cDumpI2c(): event=0x3ffdf724 bits=10 [E][esp32-hal-i2c.c:619] i2cDumpI2c(): intr_handle=0x3ffdf754 [E][esp32-hal-i2c.c:620] i2cDumpI2c(): dq=0x3ffe12cc [E][esp32-hal-i2c.c:621] i2cDumpI2c(): queueCount=1 [E][esp32-hal-i2c.c:622] i2cDumpI2c(): queuePos=0 [E][esp32-hal-i2c.c:623] i2cDumpI2c(): byteCnt=8 [E][esp32-hal-i2c.c:582] i2cDumpDqData(): [0] d1 R STOP buf@=0x3ffc6154, len=7, pos=7, eventH=0x0 bits=0 [E][esp32-hal-i2c.c:598] i2cDumpDqData(): 0x0000: ....... 15 13 15 09 00 02 18 [E][esp32-hal-i2c.c:944] i2cDumpInts(): row count INTR TX RX [E][esp32-hal-i2c.c:947] i2cDumpInts(): [01] 0x0001 0x0002 0x0001 0x0000 0x000352a3 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000352a3 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [03] 0x0008 0x0040 0x0000 0x0000 0x000352a4 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0007 0x000352a4 [E][esp32-hal-i2c.c:1115] i2cProcQueue(): TimeoutRecovery: expected=0ms, actual=2ms [E][esp32-hal-i2c.c:609] i2cDumpI2c(): i2c=0x3ffc1894 [E][esp32-hal-i2c.c:610] i2cDumpI2c(): dev=0x60013000 date=0x16042000 [E][esp32-hal-i2c.c:612] i2cDumpI2c(): lock=0x3ffdf6a0 [E][esp32-hal-i2c.c:614] i2cDumpI2c(): num=0 [E][esp32-hal-i2c.c:615] i2cDumpI2c(): mode=1 [E][esp32-hal-i2c.c:616] i2cDumpI2c(): stage=3 [E][esp32-hal-i2c.c:617] i2cDumpI2c(): error=1 [E][esp32-hal-i2c.c:618] i2cDumpI2c(): event=0x3ffdf724 bits=10 [E][esp32-hal-i2c.c:619] i2cDumpI2c(): intr_handle=0x3ffdf754 [E][esp32-hal-i2c.c:620] i2cDumpI2c(): dq=0x3ffe12cc [E][esp32-hal-i2c.c:621] i2cDumpI2c(): queueCount=1 [E][esp32-hal-i2c.c:622] i2cDumpI2c(): queuePos=0 [E][esp32-hal-i2c.c:623] i2cDumpI2c(): byteCnt=2 [E][esp32-hal-i2c.c:582] i2cDumpDqData(): [0] d0 W STOP buf@=0x3ffc61da, len=1, pos=1, eventH=0x0 bits=0 [E][esp32-hal-i2c.c:598] i2cDumpDqData(): 0x0000: . 03 [E][esp32-hal-i2c.c:944] i2cDumpInts(): row count INTR TX RX [E][esp32-hal-i2c.c:947] i2cDumpInts(): [01] 0x0001 0x0002 0x0002 0x0000 0x00035b70 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00035b70 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [03] 0x0002 0x0040 0x0000 0x0000 0x00035b70 [E][esp32-hal-i2c.c:947] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00035b70

[stickbreaker]

@marian-craciunescu my debugging output is to too verbose, in file cores\esp32\esp32-hal-i2c.c change the log level from ERROR to DEBUG at line:1111 from:

if(eBits&EVENT_DONE){ // no gross timeout
#if ARDUHAL_LOG_LEVEL >= ARDUHAL_LOG_LEVEL_ERROR
  uint32_t expected =(totalBytes*10*1000)/i2cGetFrequencyNoMux(i2c);
  if((tAfter-tBefore)>(expected+1)) { //used some of the timeout Period
    // expected can be zero due to small packets
    log_e("TimeoutRecovery: expected=%ums, actual=%ums",expected,(tAfter-tBefore));
    i2cDumpI2c(i2c);
    i2cDumpInts(i2c->num);
    }
#endif

to:

if(eBits&EVENT_DONE){ // no gross timeout
#if ARDUHAL_LOG_LEVEL >= ARDUHAL_LOG_LEVEL_DEBUG
  uint32_t expected =(totalBytes*10*1000)/i2cGetFrequencyNoMux(i2c);
  if((tAfter-tBefore)>(expected+1)) { //used some of the timeout Period
    // expected can be zero due to small packets
    log_e("TimeoutRecovery: expected=%ums, actual=%ums",expected,(tAfter-tBefore));
    i2cDumpI2c(i2c);
    i2cDumpInts(i2c->num);
    }
#endif

I set it to ERROR to see if my code correctly handled devices that stretched SCL. I do not have an devices that stretch it, so I could not test it myself. I was hoping for some feedback thanks.

Sorry for the inconvenience.

Chuck.

[tferrin]

I ended up having to change the logging level for the other i2c debugging output too, otherwise a timeout error can start a cascade of other errors. If I keep the error messages down to just a word or two I occasionally may see a message (like once a day), but things always recover.

[stickbreaker]

@tferrin I never expected this fork to exist this long. I always thought that it would either prove useless or be incorporated into the main branch.

@me-no-dev Stated Nov 2017 that he was working on incorporating it. He said, and and I agreed that the coding style was out of spec for the main branch. He never described the incompatibilities. I don't like the sparseness of comments, braces placement, indention rules. I was trained to always describe what you were trying to code before you coded it. If you could not describe it, there was no chance of correctly coding it.

With this group project, I believe that the lack of comments will doom the project to oblivion. The lack of accurate technical details for the hardware is weighting very heavy on me. I am getting really tired of having to 'discover' how the hardware works. If you read the official Espressif documentation. This repo is pure MAGIC. They have removed all reference to Interrupt driven i2c FIFO operations.

I just assumed based on his prior work, that he would take the best parts, or Ideas and re-code it to match spec. The overload of debug and lack of parameter checking, error recovery was my decision to ease my development.

I'm in a quandary, I don't know wither to polish the rough spots off this mess or leave it as is. I am working on Slave mode I2C, my test code has many differences from this repo. Slave mode has some integration issues with Master mode, I am still encountering deadlocks and race conditions with my theoretical models. Actually creating the deadlocks and races is being a challenge. I know(believe) that I need a design that is perfect from my view. If I can envision problems, they will occur, and unforeseen issues will also occur.

Will you create a PR that contains your modification? It is likely that I can create conditional compile statements that would serve both our goals, (maximum verbosity for debug purposes and minimal messaging for standard usage(.

Chuck.

[tferrin]

Chuck, I sympathize with your position. I think @me-no-dev must have been busy with other things for the past month or more and that little has gotten done on this. I can certainly create a pull request with my changes (they are pretty trivial), but I think a lot of changes are needed to the code (mostly style stuff) before it will be incorporated into the main repository. It's clear to me that you know the I2C protocol well and that your code works much better than the original, so I hope that it will eventually be adopted. With regard to the official Espressif documentation being "sparse," this has been mentioned by many people in numerous internet threads. I've had to look at existing code and guess at what's going on in the hardware or proprietary Espressif libraries way more often than I'm used to with other projects. This approach is very tedious, time consuming, and requires a lot of guess work. If it wasn't for the community here with the collective ideas of many I may have given up with the ESP32 by now. Thanks for all of your work on the I2C interface and I will do what I can to advance it.

--tom