[Ovmsdev] Need some help on CAN errors

Chris van der Meijden chris at arachnon.de
Fri Sep 18 21:39:04 HKT 2020


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 at lists.openvehicles.com
> > http://lists.openvehicles.com/mailman/listinfo/ovmsdev
> > 
> >     
> 
>     
> 
>     
>   
> 
> _______________________________________________
> OvmsDev mailing list
> OvmsDev at lists.openvehicles.com
> http://lists.openvehicles.com/mailman/listinfo/ovmsdev
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20200918/b8664bd5/attachment-0002.htm>


More information about the OvmsDev mailing list