<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body>
Chris,<br>
<br>
I've got no simple way to test changes to the MCP2515 driver, can
you please try the attached patch?<br>
<br>
In case you're not familiar with patching:<br>
<br>
<tt>git apply …/mcp2515.patch</tt><br>
<br>
That's simply adding a mutex to Write() &
AsynchronousInterruptHandler() plus a minor optimization to directly
queue a frame if the queue isn't empty.<br>
<br>
Thanks,<br>
Michael<br>
<br>
<br>
<div class="moz-cite-prefix">Am 18.09.20 um 15:39 schrieb Chris van
der Meijden:<br>
</div>
<blockquote type="cite"
cite="mid:1600436344.17636.4.camel@arachnon.de">
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
<div>Correction:</div>
<div><br>
</div>
<div>The crashes occur when I use</div>
<div><br>
</div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;">
CAN_frame_t txframe;</tt><tt style="color: rgb(0, 0, 0);
white-space: normal;"><br>
</tt><tt style="color: rgb(0, 0, 0); white-space: normal;">
txframe = {};</tt><tt style="color: rgb(0, 0, 0); white-space:
normal;"><br>
</tt><tt style="color: rgb(0, 0, 0); white-space: normal;">
txframe.MsgID = 0x219;</tt><tt style="color: rgb(0, 0, 0);
white-space: normal;"><br>
</tt><tt style="color: rgb(0, 0, 0); white-space: normal;">
txframe.FIR.B.DLC = 8;</tt><tt style="color: rgb(0, 0, 0);
white-space: normal;"><br>
</tt><tt style="color: rgb(0, 0, 0); white-space: normal;">
txframe.data = { 0x…, 0x…, … };</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;">
txframe.Write(m_can3);</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;"><br>
</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;">to
write to the bus.</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;"><br>
</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;">When I
use the </tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;"><br>
</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;">comfBus->WriteStandard(0x219,
length, data);</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;"><br>
</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;">method
I have no crashes.</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;"><br>
</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;">Continuing
the quest ...</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;"><br>
</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;">Chris</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;"><br>
</tt></div>
<div><tt style="color: rgb(0, 0, 0); white-space: normal;"><br>
</tt></div>
<div>Am Donnerstag, den 17.09.2020, 21:35 +0200 schrieb Michael
Balzer:</div>
<blockquote type="cite"> That looks like a bug in the MCP2515
driver.<br>
<br>
<blockquote type="cite">
<pre class="moz-quote-pre" wrap="">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).</pre>
</blockquote>
<br>
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.<br>
<br>
The race scheme is:<br>
<br>
- The application task (low prio) calls Write() concurrently to
the "TX done" interrupt of the last frame sent being raised.<br>
- The interrupt is sent to the CAN task (high prio), which calls
AsynchronousInterruptHandler() concurrently now to the Write().<br>
- Both Write() and AsynchronousInterruptHandler() may now get
"TX buffer is free" from the MCP2515<br>
- …Write() will then immediately fill the TX buffer with the new
frame<br>
- …and AsynchronousInterruptHandler() will concurrently fill the
TX buffer with the next frame of the TX queue if any<br>
<br>
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.<br>
<br>
You could have had that very effect on the second time of the
second message vs. the first time of the third message:<br>
<br>
<tt>1600352233.392765 3CER TX_Queue T11 291 <b>8a</b><b> aa</b>
00 00 00 46 03 00</tt><tt><br>
</tt><tt>1600352233.394239 3T11 291 <b>8a</b><b> aa</b> 00 00
00 46 03 00</tt><tt><br>
</tt><tt>1600352233.394816 3CER TX_Queue T11 291 <b>00</b><b>
aa</b> 00 00 00 46 03 00</tt><tt><br>
</tt><tt>1600352233.395680 3T11 291 <b>8a</b><b> aa</b> 00 00
00 46 03 00</tt><tt><br>
</tt><tt>1600352233.396153 3CER TX_Queue T11 291 <b>00</b><b>
aa</b> 00 00 00 46 03 00</tt><tt><br>
</tt><tt>1600352233.404239 3T11 291 <b>00</b><b> aa</b> 00 00
00 46 03 00<br>
</tt><tt>1600352233.404538 3CER TX_Queue T11 291 <b>00 00</b>
00 00 00 46 03 00<br>
1600352233.404753 3CER TX_Queue T11 291 <b>00 00</b> 00 00 00
46 03 00<br>
</tt><tt><tt><tt>… </tt><tt>TX "00 aa" done IRQ coming in here,
queue has "00 00" frame ready which gets sent concurrently<br>
→ wrong frame "00 00" is now in m_tx_frame and gets
logged instead of "00 aa":<br>
</tt></tt>1600352233.405126 3T11 291 <b>00 00</b> 00 00 00
46 03 00<br>
<br>
</tt><br>
A second opinion on this would be good, possibly by someone else
who has worked on the MCP2515 code last?<br>
<br>
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.<br>
<br>
<blockquote type="cite">
<pre class="moz-quote-pre" wrap="">On the RX side (3R11) we only see 3 times the first messages, none of
the second and one of the third.
</pre>
</blockquote>
<br>
The RX log entries are the frames received from the vehicle.<br>
<br>
Regards,<br>
Michael<br>
<br>
<br>
<br>
<div class="moz-cite-prefix">Am 17.09.20 um 17:06 schrieb Chris
van der Meijden:<br>
</div>
<blockquote type="cite"
cite="mid:1600355177.27369.1.camel@arachnon.de">
<pre class="moz-quote-pre" wrap="">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
<a class="moz-txt-link-abbreviated" href="mailto:OvmsDev@lists.openvehicles.com" moz-do-not-send="true">OvmsDev@lists.openvehicles.com</a>
<a class="moz-txt-link-freetext" href="http://lists.openvehicles.com/mailman/listinfo/ovmsdev" moz-do-not-send="true">http://lists.openvehicles.com/mailman/listinfo/ovmsdev</a>
</pre>
</blockquote>
<br>
<pre>_______________________________________________
OvmsDev mailing list
<a href="mailto:OvmsDev@lists.openvehicles.com" moz-do-not-send="true">OvmsDev@lists.openvehicles.com</a>
<a href="http://lists.openvehicles.com/mailman/listinfo/ovmsdev" moz-do-not-send="true">http://lists.openvehicles.com/mailman/listinfo/ovmsdev</a>
</pre>
</blockquote>
<br>
<fieldset class="mimeAttachmentHeader"></fieldset>
<pre class="moz-quote-pre" wrap="">_______________________________________________
OvmsDev mailing list
<a class="moz-txt-link-abbreviated" href="mailto:OvmsDev@lists.openvehicles.com">OvmsDev@lists.openvehicles.com</a>
<a class="moz-txt-link-freetext" href="http://lists.openvehicles.com/mailman/listinfo/ovmsdev">http://lists.openvehicles.com/mailman/listinfo/ovmsdev</a>
</pre>
</blockquote>
<br>
<pre class="moz-signature" cols="72">--
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26</pre>
</body>
</html>