[Ovmsdev] Need some help on CAN errors
Chris van der Meijden
chris at arachnon.de
Fri Sep 18 22:45:55 HKT 2020
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 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
> >
> >
> > _______________________________________________
> > 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
More information about the OvmsDev
mailing list