Correction: The crashes occur when I use   CAN_frame_t txframe;   txframe = {};   txframe.MsgID = 0x219;   txframe.FIR.B.DLC = 8;   txframe.data = { 0x…, 0x…, … };  txframe.Write(m_can3); to write to the bus. When I use the  comfBus->WriteStandard(0x219, length, data); method I have no crashes. Continuing the quest ... Chris Am Donnerstag, den 17.09.2020, 21:35 +0200 schrieb Michael Balzer:

    That looks like a bug in the MCP2515 driver.

    

    

...

      The TX that come to the bus (3T11) we see 15 times the first messages (that is right), one time the second messages (wrong, should be two) and 6 times the third messages (wrong, should be 5).     

    

    I haven't fully analyzed the code path yet, but my impression so far     is we have a race condition between mcp2515::Write() and     mcp2515::AsynchronousInterruptHandler(). If I'm right, that could     lead to wrong TX log entries and even to lost or out of sequence     frame transmissions in a situation like yours, when many frames get     sent in series without any delay.

    

    The race scheme is:

    

    - The application task (low prio) calls Write() concurrently to the     "TX done" interrupt of the last frame sent being raised.

    - The interrupt is sent to the CAN task (high prio), which calls     AsynchronousInterruptHandler() concurrently now to the Write().

    - Both Write() and AsynchronousInterruptHandler() may now get "TX     buffer is free" from the MCP2515

    - …Write() will then immediately fill the TX buffer with the new     frame

    - …and AsynchronousInterruptHandler() will concurrently fill the TX     buffer with the next frame of the TX queue if any

    

    As the SPI bus has a lock, both writes may succeed, but m_tx_frame     will contain only the last of the two frames, so the next log entry     will be wrong. The m_tx_frame container (originating from PR 259)     has been designed under the assumption of stricly sequential frame     transmissions.

    

    You could have had that very effect on the second time of the second     message vs. the first time of the third message:

    

    1600352233.392765 3CER TX_Queue T11 291 8a aa 00       00 00 46 03 00

    1600352233.394239 3T11 291 8a aa 00 00 00 46       03 00

    1600352233.394816 3CER TX_Queue T11 291 00 aa       00 00 00 46 03 00

    1600352233.395680 3T11 291 8a aa 00 00 00 46       03 00

    1600352233.396153 3CER TX_Queue T11 291 00 aa       00 00 00 46 03 00

    1600352233.404239 3T11 291 00 aa 00 00 00 46       03 00

    1600352233.404538 3CER TX_Queue T11 291 00 00 00 00       00 46 03 00

      1600352233.404753 3CER TX_Queue T11 291 00 00 00 00 00 46       03 00

    … TX "00 aa" done IRQ coming in here,           queue has "00 00" frame ready which gets sent concurrently

            → wrong frame "00 00" is now in m_tx_frame and gets logged           instead of "00 aa":

        1600352233.405126 3T11 291 00 00 00 00 00 46       03 00

      

    

    A second opinion on this would be good, possibly by someone else who     has worked on the MCP2515 code last?

    

    Chris, while we're thinking about this, you could try serialising     the frames by sending them one by one using the TX callback. The TX     queue is meant to handle bulk transmissions, but you may need to     raise the queue size (sdkconfig:     CONFIG_OVMS_HW_CAN_TX_QUEUE_SIZE=20) in that case.

    

    

...

      On the RX side (3R11) we only see 3 times the first messages, none of the second and one of the third.

    

    

    The RX log entries are the frames received from the vehicle.

    

    Regards,

    Michael

    

    

    

    Am 17.09.20 um 17:06 schrieb Chris van       der Meijden:

    

    

...

      Hi all

I'm trying to make the Lock/Unlock function work for the VW e-UP on T26A.

I found the right messages and got it working once, not knowing why.

What I need to do is sending 22 messages in a row. My code for that is:

        // Send 0x291 messages

        for (k=0;k<15;k++)         {            data[0] = 0x8A;            data[1] = 0xAA;            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);

        }

        for (k=0;k<2;k++)         {            data[0] = 0x00;            data[1] = 0xAA;            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);

        }

        for (k=0;k<5;k++)         {            data[0] = 0x00;            data[1] = 0x00;            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);

        }

This is what I get in the logging:

V (96275) canlog-monitor: 1600352233.355713 3T11 291 8a aa 00 00 00 46 03 00 V (96275) canlog-monitor: 1600352233.357066 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96275) canlog-monitor: 1600352233.357673 3T11 291 8a aa 00 00 00 46 03 00 V (96275) canlog-monitor: 1600352233.358156 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (96285) mcp2515: AsynchronousInterruptHandler: error while sending frame. msgId 0x291 V (96285) canlog-monitor: 1600352233.364241 3T11 291 8a aa 00 00 00 46 03 00 E (96285) can: can3: intr=8 rxpkt=0 txpkt=4 errflags=0x85050101 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 V (96285) canlog-monitor: 1600352233.364745 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 W (96285) mcp2515: can3 EFLG: TX_Err_Warn EWARN  V (96285) canlog-monitor: 1600352233.364965 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (96285) can: can3: intr=8 rxpkt=1 txpkt=5 errflags=0x4050104 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 E (96285) canlog-monitor: 1600352233.366305 3CER Error intr=8 rxpkt=0 txpkt=4 errflags=0x85050101 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 V (96285) canlog-monitor: 1600352233.367035 3R11 291 8a aa 00 00 00 46 03 00 V (96285) canlog-monitor: 1600352233.367620 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.367647 3CER TX_Fail T11 291 8a aa 00 00 00 46 03 00 E (96295) canlog-monitor: 1600352233.368350 3CER Error intr=8 rxpkt=1 txpkt=5 errflags=0x4050104 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 V (96295) canlog-monitor: 1600352233.368403 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.369064 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.370243 3R11 470 40 00 00 00 00 00 00 14 V (96295) canlog-monitor: 1600352233.371859 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.374239 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.374827 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.375507 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.375976 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96305) canlog-monitor: 1600352233.384241 3T11 291 8a aa 00 00 00 46 03 00 V (96305) canlog-monitor: 1600352233.384985 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96305) canlog-monitor: 1600352233.385602 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (96305) can: can3: intr=14 rxpkt=2 txpkt=10 errflags=0x27450501 rxerr=0 txerr=100 rxovr=0 txovr=0 txdelay=12 wdgreset=0 errreset=0 V (96305) canlog-monitor: 1600352233.386140 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 W (96305) mcp2515: can3 EFLG: TX_Err_Warn EWARN  E (96305) canlog-monitor: 1600352233.387010 3CER Error intr=14 rxpkt=2 txpkt=10 errflags=0x27450501 rxerr=0 txerr=100 rxovr=0 txovr=0 txdelay=12 wdgreset=0 errreset=0 V (96305) canlog-monitor: 1600352233.387820 3R11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.388508 3R11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.388548 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.388586 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.390509 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.391040 3R11 359 ff 89 ff 00 10 6b 80 00 V (96315) canlog-monitor: 1600352233.392246 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.392765 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.394239 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.394816 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.395680 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.396153 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404239 3T11 291 00 aa 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404538 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404753 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404791 3R11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.405089 3R11 457 00 47 00 V (96325) canlog-monitor: 1600352233.405126 3T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.406203 3T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.407538 3T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.408701 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (96335) canlog-monitor: 1600352233.414259 3T11 291 00 00 00 00 00 46 03 00 E (96335) can: can3: intr=25 rxpkt=7 txpkt=21 errflags=0x27400501 rxerr=0 txerr=90 rxovr=0 txovr=0 txdelay=18 wdgreset=0 errreset=0 E (96335) canlog-monitor: 1600352233.416398 3CER Error intr=25 rxpkt=7 txpkt=21 errflags=0x27400501 rxerr=0 txerr=90 rxovr=0 txovr=0 txdelay=18 wdgreset=0 errreset=0 V (96335) canlog-monitor: 1600352233.416729 3R11 320 01 00 00 01 00 02 00 80 V (96335) canlog-monitor: 1600352233.417216 3R11 575 00 00 00 00 V (96335) canlog-monitor: 1600352233.417255 3T11 291 00 00 00 00 00 46 03 00 V (96335) canlog-monitor: 1600352233.417283 3T11 291 00 00 00 00 00 46 03 00 I (96335) ovms-server-v2: Send MP-0 c22,0

I see some weird stuff here ...

The TX that come to the bus (3T11) we see 15 times the first messages (that is right), one time the second messages (wrong, should be two) and 6 times the third messages (wrong, should be 5).

On the RX side (3R11) we only see 3 times the first messages, none of the second and one of the third.

To unlock the doors we need on 3R11 (???) 15 times first, 5 times second and two times third.

I don't understand enough from the can communication within OVMS to solve this on my own. Could someone help me out here?

Thanx!

Regards

Chris _______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

    

    

       

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

Hey Michael I get this error message on the patch: git apply ../mcp2515.patch ../mcp2515.patch:9: trailing whitespace.   OvmsRecMutexLock lock(&m_mutex); ../mcp2515.patch:17: trailing whitespace.   // if there are frames waiting in the TX queue, add the new one there as well: ../mcp2515.patch:18: trailing whitespace.   if (uxQueueMessagesWaiting(m_txqueue)) ../mcp2515.patch:19: trailing whitespace.     { ../mcp2515.patch:20: trailing whitespace.     return QueueWrite(p_frame, maxqueuewait); error: Anwendung des Patches fehlgeschlagen: vehicle/OVMS.V3/components/mcp2515/src/mcp2515.cpp:308 error: vehicle/OVMS.V3/components/mcp2515/src/mcp2515.cpp: Patch konnte nicht angewendet werden error: Anwendung des Patches fehlgeschlagen: vehicle/OVMS.V3/components/mcp2515/src/mcp2515.h:35 error: vehicle/OVMS.V3/components/mcp2515/src/mcp2515.h: Patch konnte nicht angewendet werden I'm even with the master ... Greetinx Chris Am Freitag, den 18.09.2020, 15:59 +0200 schrieb Michael Balzer:

Chris,

I've got no simple way to test changes to the MCP2515 driver, can you please try the attached patch?

In case you're not familiar with patching:

git apply …/mcp2515.patch

That's simply adding a mutex to Write() & AsynchronousInterruptHandler() plus a minor optimization to directly queue a frame if the queue isn't empty.

Thanks, Michael

Am 18.09.20 um 15:39 schrieb Chris van der Meijden:

...

Correction:

The crashes occur when I use

  CAN_frame_t txframe;   txframe = {};   txframe.MsgID = 0x219;   txframe.FIR.B.DLC = 8;   txframe.data = { 0x…, 0x…, … };   txframe.Write(m_can3);

to write to the bus.

When I use the 

comfBus->WriteStandard(0x219, length, data);

method I have no crashes.

Continuing the quest ...

Chris

Am Donnerstag, den 17.09.2020, 21:35 +0200 schrieb Michael Balzer:

...

That looks like a bug in the MCP2515 driver.

...

The TX that come to the bus (3T11) we see 15 times the first messages (that is right), one time the second messages (wrong, should be two) and 6 times the third messages (wrong, should be 5).   I haven't fully analyzed the code path yet, but my impression so far is we have a race condition between mcp2515::Write() and mcp2515::AsynchronousInterruptHandler(). If I'm right, that could lead to wrong TX log entries and even to lost or out of sequence frame transmissions in a situation like yours, when many frames get sent in series without any delay.

The race scheme is:

- The application task (low prio) calls Write() concurrently to the "TX done" interrupt of the last frame sent being raised. - The interrupt is sent to the CAN task (high prio), which calls AsynchronousInterruptHandler() concurrently now to the Write(). - Both Write() and AsynchronousInterruptHandler() may now get "TX buffer is free" from the MCP2515 - …Write() will then immediately fill the TX buffer with the new frame - …and AsynchronousInterruptHandler() will concurrently fill the TX buffer with the next frame of the TX queue if any

As the SPI bus has a lock, both writes may succeed, but m_tx_frame will contain only the last of the two frames, so the next log entry will be wrong. The m_tx_frame container (originating from PR 259) has been designed under the assumption of stricly sequential frame transmissions.

You could have had that very effect on the second time of the second message vs. the first time of the third message:

1600352233.392765 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 1600352233.394239 3T11 291 8a aa 00 00 00 46 03 00 1600352233.394816 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 1600352233.395680 3T11 291 8a aa 00 00 00 46 03 00 1600352233.396153 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 1600352233.404239 3T11 291 00 aa 00 00 00 46 03 00 1600352233.404538 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 1600352233.404753 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 … TX "00 aa" done IRQ coming in here, queue has "00 00" frame ready which gets sent concurrently   → wrong frame "00 00" is now in m_tx_frame and gets logged instead of "00 aa": 1600352233.405126 3T11 291 00 00 00 00 00 46 03 00

A second opinion on this would be good, possibly by someone else who has worked on the MCP2515 code last?

Chris, while we're thinking about this, you could try serialising the frames by sending them one by one using the TX callback. The TX queue is meant to handle bulk transmissions, but you may need to raise the queue size (sdkconfig: CONFIG_OVMS_HW_CAN_TX_QUEUE_SIZE=20) in that case.

...

On the RX side (3R11) we only see 3 times the first messages, none of the second and one of the third.   The RX log entries are the frames received from the vehicle.

Regards, Michael

Am 17.09.20 um 17:06 schrieb Chris van der Meijden:

...

Hi all

I'm trying to make the Lock/Unlock function work for the VW e- UP on T26A.

I found the right messages and got it working once, not knowing why.

What I need to do is sending 22 messages in a row. My code for that is:

        // Send 0x291 messages

        for (k=0;k<15;k++)         {            data[0] = 0x8A;            data[1] = 0xAA;            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);

        }

        for (k=0;k<2;k++)         {            data[0] = 0x00;            data[1] = 0xAA;            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);

        }

        for (k=0;k<5;k++)         {            data[0] = 0x00;            data[1] = 0x00;            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);

        }

This is what I get in the logging:

V (96275) canlog-monitor: 1600352233.355713 3T11 291 8a aa 00 00 00 46 03 00 V (96275) canlog-monitor: 1600352233.357066 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96275) canlog-monitor: 1600352233.357673 3T11 291 8a aa 00 00 00 46 03 00 V (96275) canlog-monitor: 1600352233.358156 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (96285) mcp2515: AsynchronousInterruptHandler: error while sending frame. msgId 0x291 V (96285) canlog-monitor: 1600352233.364241 3T11 291 8a aa 00 00 00 46 03 00 E (96285) can: can3: intr=8 rxpkt=0 txpkt=4 errflags=0x85050101 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 V (96285) canlog-monitor: 1600352233.364745 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 W (96285) mcp2515: can3 EFLG: TX_Err_Warn EWARN  V (96285) canlog-monitor: 1600352233.364965 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (96285) can: can3: intr=8 rxpkt=1 txpkt=5 errflags=0x4050104 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 E (96285) canlog-monitor: 1600352233.366305 3CER Error intr=8 rxpkt=0 txpkt=4 errflags=0x85050101 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 V (96285) canlog-monitor: 1600352233.367035 3R11 291 8a aa 00 00 00 46 03 00 V (96285) canlog-monitor: 1600352233.367620 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.367647 3CER TX_Fail T11 291 8a aa 00 00 00 46 03 00 E (96295) canlog-monitor: 1600352233.368350 3CER Error intr=8 rxpkt=1 txpkt=5 errflags=0x4050104 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 V (96295) canlog-monitor: 1600352233.368403 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.369064 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.370243 3R11 470 40 00 00 00 00 00 00 14 V (96295) canlog-monitor: 1600352233.371859 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.374239 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.374827 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.375507 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.375976 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96305) canlog-monitor: 1600352233.384241 3T11 291 8a aa 00 00 00 46 03 00 V (96305) canlog-monitor: 1600352233.384985 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96305) canlog-monitor: 1600352233.385602 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (96305) can: can3: intr=14 rxpkt=2 txpkt=10 errflags=0x27450501 rxerr=0 txerr=100 rxovr=0 txovr=0 txdelay=12 wdgreset=0 errreset=0 V (96305) canlog-monitor: 1600352233.386140 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 W (96305) mcp2515: can3 EFLG: TX_Err_Warn EWARN  E (96305) canlog-monitor: 1600352233.387010 3CER Error intr=14 rxpkt=2 txpkt=10 errflags=0x27450501 rxerr=0 txerr=100 rxovr=0 txovr=0 txdelay=12 wdgreset=0 errreset=0 V (96305) canlog-monitor: 1600352233.387820 3R11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.388508 3R11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.388548 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.388586 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.390509 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.391040 3R11 359 ff 89 ff 00 10 6b 80 00 V (96315) canlog-monitor: 1600352233.392246 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.392765 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.394239 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.394816 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.395680 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.396153 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404239 3T11 291 00 aa 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404538 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404753 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404791 3R11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.405089 3R11 457 00 47 00 V (96325) canlog-monitor: 1600352233.405126 3T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.406203 3T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.407538 3T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.408701 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (96335) canlog-monitor: 1600352233.414259 3T11 291 00 00 00 00 00 46 03 00 E (96335) can: can3: intr=25 rxpkt=7 txpkt=21 errflags=0x27400501 rxerr=0 txerr=90 rxovr=0 txovr=0 txdelay=18 wdgreset=0 errreset=0 E (96335) canlog-monitor: 1600352233.416398 3CER Error intr=25 rxpkt=7 txpkt=21 errflags=0x27400501 rxerr=0 txerr=90 rxovr=0 txovr=0 txdelay=18 wdgreset=0 errreset=0 V (96335) canlog-monitor: 1600352233.416729 3R11 320 01 00 00 01 00 02 00 80 V (96335) canlog-monitor: 1600352233.417216 3R11 575 00 00 00 00 V (96335) canlog-monitor: 1600352233.417255 3T11 291 00 00 00 00 00 46 03 00 V (96335) canlog-monitor: 1600352233.417283 3T11 291 00 00 00 00 00 46 03 00 I (96335) ovms-server-v2: Send MP-0 c22,0

I see some weird stuff here ...

The TX that come to the bus (3T11) we see 15 times the first messages (that is right), one time the second messages (wrong, should be two) and 6 times the third messages (wrong, should be 5).

On the RX side (3R11) we only see 3 times the first messages, none of the second and one of the third.

To unlock the doors we need on 3R11 (???) 15 times first, 5 times second and two times third.

I don't understand enough from the can communication within OVMS to solve this on my own. Could someone help me out here?

Thanx!

Regards

Chris _______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev  

---

OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev  

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev  

---

OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

That did the trick :-) It compiled. Now I just have to wait till the car is back from shoppig ... As soon as I have results, I'll be back. Chris Am Freitag, den 18.09.2020, 16:54 +0200 schrieb Michael Balzer:

Chris,

see git help apply, you can try

git apply --whitespace=fix or git apply --whitespace=nowarn

Regards, Michael

Am 18.09.20 um 16:45 schrieb Chris van der Meijden:

...

Hey Michael

I get this error message on the patch:

git apply ../mcp2515.patch

../mcp2515.patch:9: trailing whitespace.   OvmsRecMutexLock lock(&m_mutex); ../mcp2515.patch:17: trailing whitespace.   // if there are frames waiting in the TX queue, add the new one there as well: ../mcp2515.patch:18: trailing whitespace.   if (uxQueueMessagesWaiting(m_txqueue)) ../mcp2515.patch:19: trailing whitespace.     { ../mcp2515.patch:20: trailing whitespace.     return QueueWrite(p_frame, maxqueuewait); error: Anwendung des Patches fehlgeschlagen: vehicle/OVMS.V3/components/mcp2515/src/mcp2515.cpp:308 error: vehicle/OVMS.V3/components/mcp2515/src/mcp2515.cpp: Patch konnte nicht angewendet werden error: Anwendung des Patches fehlgeschlagen: vehicle/OVMS.V3/components/mcp2515/src/mcp2515.h:35 error: vehicle/OVMS.V3/components/mcp2515/src/mcp2515.h: Patch konnte nicht angewendet werden

I'm even with the master ...

Greetinx

Chris

Am Freitag, den 18.09.2020, 15:59 +0200 schrieb Michael Balzer:

...

Chris,

I've got no simple way to test changes to the MCP2515 driver, can you please try the attached patch?

In case you're not familiar with patching:

git apply …/mcp2515.patch

That's simply adding a mutex to Write() & AsynchronousInterruptHandler() plus a minor optimization to directly queue a frame if the queue isn't empty.

Thanks, Michael

Am 18.09.20 um 15:39 schrieb Chris van der Meijden:

...

Correction:

The crashes occur when I use

  CAN_frame_t txframe;   txframe = {};   txframe.MsgID = 0x219;   txframe.FIR.B.DLC = 8;   txframe.data = { 0x…, 0x…, … };   txframe.Write(m_can3);

to write to the bus.

When I use the 

comfBus->WriteStandard(0x219, length, data);

method I have no crashes.

Continuing the quest ...

Chris

Am Donnerstag, den 17.09.2020, 21:35 +0200 schrieb Michael Balzer:

...

That looks like a bug in the MCP2515 driver.

...

The TX that come to the bus (3T11) we see 15 times the first messages (that is right), one time the second messages (wrong, should be two) and 6 times the third messages (wrong, should be 5).

  I haven't fully analyzed the code path yet, but my impression so far is we have a race condition between mcp2515::Write() and mcp2515::AsynchronousInterruptHandler(). If I'm right, that could lead to wrong TX log entries and even to lost or out of sequence frame transmissions in a situation like yours, when many frames get sent in series without any delay.

The race scheme is:

- The application task (low prio) calls Write() concurrently to the "TX done" interrupt of the last frame sent being raised. - The interrupt is sent to the CAN task (high prio), which calls AsynchronousInterruptHandler() concurrently now to the Write(). - Both Write() and AsynchronousInterruptHandler() may now get "TX buffer is free" from the MCP2515 - …Write() will then immediately fill the TX buffer with the new frame - …and AsynchronousInterruptHandler() will concurrently fill the TX buffer with the next frame of the TX queue if any

As the SPI bus has a lock, both writes may succeed, but m_tx_frame will contain only the last of the two frames, so the next log entry will be wrong. The m_tx_frame container (originating from PR 259) has been designed under the assumption of stricly sequential frame transmissions.

You could have had that very effect on the second time of the second message vs. the first time of the third message:

1600352233.392765 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 1600352233.394239 3T11 291 8a aa 00 00 00 46 03 00 1600352233.394816 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 1600352233.395680 3T11 291 8a aa 00 00 00 46 03 00 1600352233.396153 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 1600352233.404239 3T11 291 00 aa 00 00 00 46 03 00 1600352233.404538 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 1600352233.404753 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 … TX "00 aa" done IRQ coming in here, queue has "00 00" frame ready which gets sent concurrently   → wrong frame "00 00" is now in m_tx_frame and gets logged instead of "00 aa": 1600352233.405126 3T11 291 00 00 00 00 00 46 03 00

A second opinion on this would be good, possibly by someone else who has worked on the MCP2515 code last?

Chris, while we're thinking about this, you could try serialising the frames by sending them one by one using the TX callback. The TX queue is meant to handle bulk transmissions, but you may need to raise the queue size (sdkconfig: CONFIG_OVMS_HW_CAN_TX_QUEUE_SIZE=20) in that case.

...

On the RX side (3R11) we only see 3 times the first messages, none of the second and one of the third.

  The RX log entries are the frames received from the vehicle.

Regards, Michael

Am 17.09.20 um 17:06 schrieb Chris van der Meijden:

...

Hi all

I'm trying to make the Lock/Unlock function work for the VW e- UP on T26A.

I found the right messages and got it working once, not knowing why.

What I need to do is sending 22 messages in a row. My code for that is:

        // Send 0x291 messages

        for (k=0;k<15;k++)         {            data[0] = 0x8A;            data[1] = 0xAA;            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);

        }

        for (k=0;k<2;k++)         {            data[0] = 0x00;            data[1] = 0xAA;            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);

        }

        for (k=0;k<5;k++)         {            data[0] = 0x00;            data[1] = 0x00;            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);

        }

This is what I get in the logging:

V (96275) canlog-monitor: 1600352233.355713 3T11 291 8a aa 00 00 00 46 03 00 V (96275) canlog-monitor: 1600352233.357066 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96275) canlog-monitor: 1600352233.357673 3T11 291 8a aa 00 00 00 46 03 00 V (96275) canlog-monitor: 1600352233.358156 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (96285) mcp2515: AsynchronousInterruptHandler: error while sending frame. msgId 0x291 V (96285) canlog-monitor: 1600352233.364241 3T11 291 8a aa 00 00 00 46 03 00 E (96285) can: can3: intr=8 rxpkt=0 txpkt=4 errflags=0x85050101 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 V (96285) canlog-monitor: 1600352233.364745 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 W (96285) mcp2515: can3 EFLG: TX_Err_Warn EWARN  V (96285) canlog-monitor: 1600352233.364965 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (96285) can: can3: intr=8 rxpkt=1 txpkt=5 errflags=0x4050104 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 E (96285) canlog-monitor: 1600352233.366305 3CER Error intr=8 rxpkt=0 txpkt=4 errflags=0x85050101 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 V (96285) canlog-monitor: 1600352233.367035 3R11 291 8a aa 00 00 00 46 03 00 V (96285) canlog-monitor: 1600352233.367620 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.367647 3CER TX_Fail T11 291 8a aa 00 00 00 46 03 00 E (96295) canlog-monitor: 1600352233.368350 3CER Error intr=8 rxpkt=1 txpkt=5 errflags=0x4050104 rxerr=0 txerr=107 rxovr=0 txovr=0 txdelay=6 wdgreset=0 errreset=0 V (96295) canlog-monitor: 1600352233.368403 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.369064 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.370243 3R11 470 40 00 00 00 00 00 00 14 V (96295) canlog-monitor: 1600352233.371859 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.374239 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.374827 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.375507 3T11 291 8a aa 00 00 00 46 03 00 V (96295) canlog-monitor: 1600352233.375976 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96305) canlog-monitor: 1600352233.384241 3T11 291 8a aa 00 00 00 46 03 00 V (96305) canlog-monitor: 1600352233.384985 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96305) canlog-monitor: 1600352233.385602 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (96305) can: can3: intr=14 rxpkt=2 txpkt=10 errflags=0x27450501 rxerr=0 txerr=100 rxovr=0 txovr=0 txdelay=12 wdgreset=0 errreset=0 V (96305) canlog-monitor: 1600352233.386140 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 W (96305) mcp2515: can3 EFLG: TX_Err_Warn EWARN  E (96305) canlog-monitor: 1600352233.387010 3CER Error intr=14 rxpkt=2 txpkt=10 errflags=0x27450501 rxerr=0 txerr=100 rxovr=0 txovr=0 txdelay=12 wdgreset=0 errreset=0 V (96305) canlog-monitor: 1600352233.387820 3R11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.388508 3R11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.388548 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.388586 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.390509 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.391040 3R11 359 ff 89 ff 00 10 6b 80 00 V (96315) canlog-monitor: 1600352233.392246 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.392765 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.394239 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.394816 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.395680 3T11 291 8a aa 00 00 00 46 03 00 V (96315) canlog-monitor: 1600352233.396153 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404239 3T11 291 00 aa 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404538 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404753 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.404791 3R11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.405089 3R11 457 00 47 00 V (96325) canlog-monitor: 1600352233.405126 3T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.406203 3T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.407538 3T11 291 00 00 00 00 00 46 03 00 V (96325) canlog-monitor: 1600352233.408701 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (96335) canlog-monitor: 1600352233.414259 3T11 291 00 00 00 00 00 46 03 00 E (96335) can: can3: intr=25 rxpkt=7 txpkt=21 errflags=0x27400501 rxerr=0 txerr=90 rxovr=0 txovr=0 txdelay=18 wdgreset=0 errreset=0 E (96335) canlog-monitor: 1600352233.416398 3CER Error intr=25 rxpkt=7 txpkt=21 errflags=0x27400501 rxerr=0 txerr=90 rxovr=0 txovr=0 txdelay=18 wdgreset=0 errreset=0 V (96335) canlog-monitor: 1600352233.416729 3R11 320 01 00 00 01 00 02 00 80 V (96335) canlog-monitor: 1600352233.417216 3R11 575 00 00 00 00 V (96335) canlog-monitor: 1600352233.417255 3T11 291 00 00 00 00 00 46 03 00 V (96335) canlog-monitor: 1600352233.417283 3T11 291 00 00 00 00 00 46 03 00 I (96335) ovms-server-v2: Send MP-0 c22,0

I see some weird stuff here ...

The TX that come to the bus (3T11) we see 15 times the first messages (that is right), one time the second messages (wrong, should be two) and 6 times the third messages (wrong, should be 5).

On the RX side (3R11) we only see 3 times the first messages, none of the second and one of the third.

To unlock the doors we need on 3R11 (???) 15 times first, 5 times second and two times third.

I don't understand enough from the can communication within OVMS to solve this on my own. Could someone help me out here?

Thanx!

Regards

Chris _______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

  _______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

 

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

  _______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

Sharkcow, see changes.txt: - Wifi client: support static IP configuration, manually set or automatically applied by SSID   New commands:     wifi ip static [<ip> <subnet> <gateway>]     wifi ip dhcp   New configs:     wifi.ssid "<ssid>.ovms.staticip" "<ip>,<subnet>,<gateway>" Regards, Michael Am 18.09.20 um 17:59 schrieb sharkcow:

Hi all,

is it (easily) possible to configure/compile OVMS with a static WiFi client IP? I searched the sources for "FreeRTOS_IPInit" and looked through the config file, but didn't find anything. (Yes, ideally I should configure my router accordingly, but my current one is too cheap for that :()

Thanks!

sharkcow _______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

I did a first test with mixed results. I don't see the Asynchronous Errors anymore, but I see TX_FAIL messages and neither unlocking nor climate control works with the patch. I will continue on monday with some deeper checks and I hope I can produce some log output then. Regards Chris

Chris, I've now set up a test environment for CAN2 & 3 and have begun investigating the issue. I'll come back to you when I've fixed it. Regards, Michael Am 18.09.20 um 19:51 schrieb Michael Balzer:

Chris,

the fix isn't meant to eliminate bus errors, it just should solve the log errors.

I.e. you should now see exactly those frames in the TX log, that you transmit.

TX_Fail log entries can result from actual bus errors as well as from TX queue overflows.

TX queue overflows are counted separately, see can can3 status. If you have TX overflows, you need to raise the queue size.

Regards, Michael

Am 18.09.20 um 19:38 schrieb Chris van der Meijden:

...

I did a first test with mixed results.

I don't see the Asynchronous Errors anymore, but I see TX_FAIL messages and neither unlocking nor climate control works with the patch.

I will continue on monday with some deeper checks and I hope I can produce some log output then.

Regards

Chris

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

Chris & everyone, I've pushed my fix for the out of sequence transmissions and faulty transmission logs on bulk transmissions. My tests showed the esp32can driver had the same issue. The fix uses a mutex to avoid concurrent frame writes from the application and CAN task context. In addition I fixed a bug in the mcp2515 driver that caused endless log spam in case of bus errors -- the same error condition would get logged over and over again. Chris, I've also raised the default CAN TX queue size to 30 to allow your 22 frames to be queued with a standard build as well. But I hope that's just a first hack and won't be necessary once you figured out how the protocol works. Regards, Michael Am 19.09.20 um 13:13 schrieb Chris van der Meijden:

Perfect! Thanx.

I'm back on track on monday.

Regards

Chris

Am Samstag, den 19.09.2020, 13:12 +0200 schrieb Michael Balzer:

...

Chris,

I've now set up a test environment for CAN2 & 3 and have begun investigating the issue.

I'll come back to you when I've fixed it.

Regards, Michael

Am 18.09.20 um 19:51 schrieb Michael Balzer:

...

Chris,

the fix isn't meant to eliminate bus errors, it just should solve the log errors.

I.e. you should now see exactly those frames in the TX log, that you transmit.

TX_Fail log entries can result from actual bus errors as well as from TX queue overflows.

TX queue overflows are counted separately, see can can3 status. If you have TX overflows, you need to raise the queue size.

Regards, Michael

Am 18.09.20 um 19:38 schrieb Chris van der Meijden:

...

I did a first test with mixed results.

I don't see the Asynchronous Errors anymore, but I see TX_FAIL messages and neither unlocking nor climate control works with the patch.

I will continue on monday with some deeper checks and I hope I can produce some log output then.

Regards

Chris

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26 _______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com <mailto:OvmsDev@lists.openvehicles.com> http://lists.openvehicles.com/mailman/listinfo/ovmsdev

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

FYI: the errors in your log were no real errors, they were just RX buffer 0 to buffer 1 rollover events, i.e. RX0 was full, so the message was stored in RX1. A real overflow (loss of frame) would have been counted in "rxovr". An RX0 overflow indicates the MCP SPI communication isn't fast enough to retrieve & process all frames immediately. We had this discussion before: it seems the buffer rollover is pretty common on the MCP buses. Maybe we really shouldn't consider it an error condition? Users also get irritated by these: https://www.openvehicles.com/node/2558 Regards, Michael Am 21.09.20 um 12:30 schrieb Chris van der Meijden:

I'm back on track.

With the fix and some changes on my code I now get all 22 messages through in the right order. The doors won't unlock though, but that is an other problem.

This is my new code:

        unsigned char data[8];         uint8_t length;         length = 8;

        unsigned char data2[2];         uint8_t length2;         length2 = 2;

        canbus *comfBus;         comfBus = m_can3;

        // This is a very dirty workaround to get the wakup of the ring working.         // We send 0x69E some values without knowing what they do.

        data2[0] = 0x14;         data2[1] = 0x42;         if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x69E, length2, data2);

        vTaskDelay(10 / portTICK_PERIOD_MS);

        // Send 0x291 messages

        for (k=0;k<15;k++)         {            data[0] = 0x8A;            if (dopen) {               data[1] = 0xAA;            } else {               data[1] = 0x55;            }            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);         }

        for (k=0;k<2;k++)         {            data[0] = 0x00;            if (dopen) {               data[1] = 0xAA;            } else {               data[1] = 0x55;            }            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);         }

        for (k=0;k<5;k++)         {            data[0] = 0x00;            data[1] = 0x00;            data[2] = 0x00;            data[3] = 0x00;            data[4] = 0x00;            data[5] = 0x46;            data[6] = 0x03;            data[7] = 0x00;            if (vwup_enable_write && !dev_mode)             comfBus->WriteStandard(0x291, length, data);         }

And this is the log:

I (130214) v-vweup-t26: Unlock Doors V (130214) canlog-monitor: 1600683470.161382 3T11 69E 14 42 V (130214) canlog-monitor: 1600683470.163658 3R11 400 00 02 01 04 00 04 00 00 V (130224) canlog-monitor: 1600683470.170670 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130234) canlog-monitor: 1600683470.180434 3T11 291 8a aa 00 00 00 46 03 00 V (130234) canlog-monitor: 1600683470.181037 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (130234) can: can3: intr=4 rxpkt=1 txpkt=2 errflags=0x23400401 rxerr=0 txerr=0 rxovr=0 txovr=0 txdelay=14 wdgreset=0 errreset=0 V (130234) canlog-monitor: 1600683470.181088 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130234) canlog-monitor: 1600683470.181136 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130234) canlog-monitor: 1600683470.181183 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.181231 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.181278 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.181325 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.181373 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.181420 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.181468 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.181515 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.181562 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.181610 3CER TX_Queue T11 291 8a aa 00 00 00 46 03 00 E (130244) canlog-monitor: 1600683470.183376 3CER Error intr=4 rxpkt=1 txpkt=2 errflags=0x23400401 rxerr=0 txerr=0 rxovr=0 txovr=0 txdelay=14 wdgreset=0 errreset=0 V (130244) canlog-monitor: 1600683470.183706 3R11 6E7 44 42 03 00 11 00 04 01 V (130244) canlog-monitor: 1600683470.184082 3R11 381 02 00 00 00 00 00 V (130244) canlog-monitor: 1600683470.184510 3R11 369 3d 00 00 d0 ff 00 00 00 V (130244) canlog-monitor: 1600683470.184608 3T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.185274 3R11 531 00 20 20 00 V (130244) canlog-monitor: 1600683470.186426 3T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.188290 3T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.190066 3T11 291 8a aa 00 00 00 46 03 00 V (130244) canlog-monitor: 1600683470.191871 3T11 291 8a aa 00 00 00 46 03 00 V (130254) canlog-monitor: 1600683470.193276 3R11 397 00 00 00 00 00 00 00 00 V (130254) canlog-monitor: 1600683470.194507 3T11 291 8a aa 00 00 00 46 03 00 V (130254) canlog-monitor: 1600683470.195477 3R11 4B9 02 00 00 00 00 00 V (130254) canlog-monitor: 1600683470.196682 3T11 291 8a aa 00 00 00 46 03 00 V (130254) canlog-monitor: 1600683470.197727 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 V (130254) canlog-monitor: 1600683470.200428 3T11 291 8a aa 00 00 00 46 03 00 V (130254) canlog-monitor: 1600683470.200971 3CER TX_Queue T11 291 00 aa 00 00 00 46 03 00 V (130254) canlog-monitor: 1600683470.201671 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (130264) canlog-monitor: 1600683470.210425 3T11 291 8a aa 00 00 00 46 03 00 E (130264) can: can3: intr=16 rxpkt=7 txpkt=11 errflags=0x23400401 rxerr=0 txerr=0 rxovr=0 txovr=0 txdelay=21 wdgreset=0 errreset=0 I (130264) ovms-server-v2: Send MP-0 c22,0 V (130264) canlog-monitor: 1600683470.210989 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (130264) canlog-monitor: 1600683470.211040 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (130264) canlog-monitor: 1600683470.211088 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 V (130264) canlog-monitor: 1600683470.211135 3CER TX_Queue T11 291 00 00 00 00 00 46 03 00 E (130274) canlog-monitor: 1600683470.212453 3CER Error intr=16 rxpkt=7 txpkt=11 errflags=0x23400401 rxerr=0 txerr=0 rxovr=0 txovr=0 txdelay=21 wdgreset=0 errreset=0 V (130274) canlog-monitor: 1600683470.212768 3R11 4BD 02 00 00 00 00 00 V (130274) canlog-monitor: 1600683470.213129 3R11 658 10 28 00 05 00 a4 1a 00 V (130274) canlog-monitor: 1600683470.213215 3T11 291 8a aa 00 00 00 46 03 00 V (130274) canlog-monitor: 1600683470.213927 3R11 3B5 02 00 00 00 00 00 V (130274) canlog-monitor: 1600683470.215092 3T11 291 8a aa 00 00 00 46 03 00 V (130274) canlog-monitor: 1600683470.216295 3R11 527 07 01 00 10 71 88 8f 08 V (130274) canlog-monitor: 1600683470.217474 3T11 291 8a aa 00 00 00 46 03 00 V (130274) canlog-monitor: 1600683470.218655 3R11 400 00 01 01 04 00 04 00 00 V (130274) canlog-monitor: 1600683470.219894 3T11 291 8a aa 00 00 00 46 03 00 V (130274) canlog-monitor: 1600683470.221120 3R11 58C 80 00 80 00 00 00 00 05 V (130274) canlog-monitor: 1600683470.222263 3T11 291 8a aa 00 00 00 46 03 00 V (130274) canlog-monitor: 1600683470.223433 3R11 470 40 00 00 00 00 00 00 13 V (130274) canlog-monitor: 1600683470.224666 3T11 291 00 aa 00 00 00 46 03 00 V (130284) canlog-monitor: 1600683470.226223 3T11 291 00 aa 00 00 00 46 03 00 V (130284) canlog-monitor: 1600683470.227809 3T11 291 00 00 00 00 00 46 03 00 V (130284) canlog-monitor: 1600683470.229369 3T11 291 00 00 00 00 00 46 03 00 V (130284) canlog-monitor: 1600683470.231051 3T11 291 00 00 00 00 00 46 03 00 V (130284) canlog-monitor: 1600683470.232657 3T11 291 00 00 00 00 00 46 03 00 V (130284) canlog-monitor: 1600683470.233705 3R11 2C1 00 00 00 00 02 00 V (130284) canlog-monitor: 1600683470.234903 3T11 291 00 00 00 00 00 46 03 00

I will now dig on why the doors won't unlock ...

Thanx!

Chris

Am Sonntag, den 20.09.2020, 13:57 +0200 schrieb Michael Balzer:

...

Chris & everyone,

I've pushed my fix for the out of sequence transmissions and faulty transmission logs on bulk transmissions. My tests showed the esp32can driver had the same issue.

The fix uses a mutex to avoid concurrent frame writes from the application and CAN task context.

In addition I fixed a bug in the mcp2515 driver that caused endless log spam in case of bus errors -- the same error condition would get logged over and over again.

Chris, I've also raised the default CAN TX queue size to 30 to allow your 22 frames to be queued with a standard build as well. But I hope that's just a first hack and won't be necessary once you figured out how the protocol works.

Regards, Michael

Am 19.09.20 um 13:13 schrieb Chris van der Meijden:

...

Perfect! Thanx.

I'm back on track on monday.

Regards

Chris

Am Samstag, den 19.09.2020, 13:12 +0200 schrieb Michael Balzer:

...

Chris,

I've now set up a test environment for CAN2 & 3 and have begun investigating the issue.

I'll come back to you when I've fixed it.

Regards, Michael

Am 18.09.20 um 19:51 schrieb Michael Balzer:

...

Chris,

the fix isn't meant to eliminate bus errors, it just should solve the log errors.

I.e. you should now see exactly those frames in the TX log, that you transmit.

TX_Fail log entries can result from actual bus errors as well as from TX queue overflows.

TX queue overflows are counted separately, see can can3 status. If you have TX overflows, you need to raise the queue size.

Regards, Michael

Am 18.09.20 um 19:38 schrieb Chris van der Meijden:

...

I did a first test with mixed results.

I don't see the Asynchronous Errors anymore, but I see TX_FAIL messages and neither unlocking nor climate control works with the patch.

I will continue on monday with some deeper checks and I hope I can produce some log output then.

Regards

Chris

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev  

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev  

---

OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev  

_______________________________________________ OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev   --  Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26

---

OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

---

OvmsDev mailing list OvmsDev@lists.openvehicles.com http://lists.openvehicles.com/mailman/listinfo/ovmsdev

-- Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal Fon 02333 / 833 5735 * Handy 0176 / 206 989 26