[Ovmsdev] Need some help on CAN errors
Michael Balzer
dexter at expeedo.de
Fri Sep 18 22:54:53 HKT 2020
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 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
> _______________________________________________
> 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
More information about the OvmsDev
mailing list