[Ovmsdev] Need some help on CAN errors
Michael Balzer
dexter at expeedo.de
Fri Sep 18 03:35:03 HKT 2020
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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20200917/44137943/attachment-0001.html>
More information about the OvmsDev
mailing list