[Ovmsdev] Need some help on CAN errors
Chris van der Meijden
chris at arachnon.de
Fri Sep 18 21:06:07 HKT 2020
Thanx for your help.
I tried CONFIG_OVMS_HW_CAN_TX_QUEUE_SIZE=60 without success and
callback crashes in can.cpp:723:
718 {719 bool loop;720
// Loop until all interrupts are handled721 do {722
bool receivedFrame;723 loop =
msg.body.bus->AsynchronousInterruptHandler(&msg.body.frame,
&receivedFrame);724 if (receivedFrame)725
me->IncomingFrame(&msg.body.frame);726 }
while (loop);727 break;
Will continue trying ...
Regards
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/32137a9f/attachment-0002.htm>
More information about the OvmsDev
mailing list