<html><head><meta http-equiv="Content-Type" content="text/html; charset=us-ascii"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; line-break: after-white-space;" class="">This is so nice! Thanks, Stephen!<div class=""><br class=""></div><div class="">Geir<br class=""><div><br class=""><blockquote type="cite" class=""><div class="">1. jan. 2018 kl. 13:12 skrev Michael Balzer <<a href="mailto:dexter@expeedo.de" class="">dexter@expeedo.de</a>>:</div><br class="Apple-interchange-newline"><div class=""><div class="">Stephen,<br class=""><br class="">your new log handling works nicely:<br class=""><br class="">OVMS > co can1 scan 1-10<br class="">Scan #1-10...<br class="">Done.<br class="">V (189794) can: tx can1 id 601 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (189844) can: tx can1 id 601 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (189854) can: tx can1 id 601 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (189904) can: tx can1 id 601 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (189914) can: tx can1 id 601 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (189964) can: tx can1 id 601 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (189964) can: tx can1 id 602 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190014) can: tx can1 id 602 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190024) can: tx can1 id 602 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190074) can: tx can1 id 602 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190084) can: tx can1 id 602 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190134) can: tx can1 id 602 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190134) can: tx can1 id 603 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190184) can: tx can1 id 603 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190194) can: tx can1 id 603 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190244) can: tx can1 id 603 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190254) can: tx can1 id 603 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190304) can: tx can1 id 603 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190304) can: tx can1 id 604 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190354) can: tx can1 id 604 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190364) can: tx can1 id 604 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190414) can: tx can1 id 604 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190424) can: tx can1 id 604 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190474) can: tx can1 id 604 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190474) can: tx can1 id 605 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190524) can: tx can1 id 605 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190534) can: tx can1 id 605 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190584) can: tx can1 id 605 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">V (190594) can: tx can1 id 605 len 8: 40 00 10 00 00 00 00 00 | @.......<br class="">V (190644) can: tx can1 id 605 len 8: 80 00 10 00 00 00 04 05 | ........<br class="">[30 log messages lost]<br class="">OVMS ><br class=""><br class=""><br class="">Regards,<br class="">Michael<br class=""><br class=""><br class="">Am 31.12.2017 um 18:11 schrieb Stephen Casner:<br class=""><blockquote type="cite" class="">Michael,<br class=""><br class="">The queue size is currently 30, which should handle the 15<br class="">notifications from Twizy. We can make that number larger as<br class="">appropriate.<br class=""><br class=""> -- Steve<br class=""><br class="">On Sun, 31 Dec 2017, Michael Balzer wrote:<br class=""><br class=""><blockquote type="cite" class="">Stephen,<br class=""><br class="">I agree overall, just one note:<br class=""><br class="">If we set the wait time to zero, log messages will also get lost if<br class="">too many are sent to be processed for just a short period of<br class="">time. I.e. not the situation of a CAN trace, where there's no other<br class="">way than discarding messages, but some single background operation<br class="">that simply produces a chunk of messages too fast for the async<br class="">console. As an example, if the Twizy detects a battery status<br class="">change, it will trigger 15 notifications at once. So with wait time<br class="">zero, some of the log output always will be lost.<br class=""><br class="">But on the other hand, delaying the logging process is always bad,<br class="">and we just don't have the RAM to buffer more messages, so I'd also<br class="">be fine with that policy change.<br class=""><br class="">Regards,<br class="">Michael<br class=""><br class=""><br class="">Am 31.12.2017 um 09:52 schrieb Stephen Casner:<br class=""><blockquote type="cite" class="">Michael,<br class=""><br class="">No, I would prefer to remove this "busy" mechanism that you added<br class="">because it does not serve any useful purpose. During the time that<br class="">"busy" would be false the probability of the queue becoming full is<br class="">very low because the amount of processing in the command parser<br class="">itself is small, so it makes no difference whether the wait<br class="">time is 0 or 1000. Therefore we might as well set the wait time to<br class="">zero always.<br class=""><br class="">Choosing to set the wait time to zero (during a command or not) means<br class="">that we choose to discard log messages rather than delaying the<br class="">processes that are generating them. It is fine with me if we want to<br class="">make that policy change. Then I think we should have a counter for<br class="">lost log messages and print a warning message about that loss when<br class="">control returns to the command parser. I did that as part of the new<br class="">support for commands that take input from the console; while in that<br class="">mode, log messages are moved to a separate queue, and when that queue<br class="">fills the oldest messages are discarded.<br class=""><br class=""> -- Steve<br class=""><br class="">On Sat, 30 Dec 2017, Michael Balzer wrote:<br class=""><br class=""><blockquote type="cite" class="">Stephen,<br class=""><br class="">can you take a look at my mitigation of the queue blocking issue?<br class=""><br class=""><a href="https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/b08e70497158bd2473e02c8912271627c4bb71b6" class="">https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/commit/b08e70497158bd2473e02c8912271627c4bb71b6</a><br class=""><br class="">If a console currently executes a command, I lower the log queueing wait time to 0. Other consoles continue normal log processing, so I can for example issue<br class="">commands on the telnet console and watch their log output on the async.<br class=""><br class="">Regards,<br class="">Michael<br class=""><br class=""><br class="">Am 29.12.2017 um 23:04 schrieb Stephen Casner:<br class=""><blockquote type="cite" class="">Michael,<br class=""><br class="">The right fix is to change the CAN tracing to gather its output into a<br class="">buffer so complete lines get logged.<br class=""><br class="">The ESP_LOG macros get redirected through our logging system as well,<br class="">but (currently) only to the async console rather than all consoles.<br class="">Is logging of CAN traces to telnet/SSH sessions desired? How about<br class="">other logging?<br class=""><br class="">There may also be some ways to improve handling of full-queue<br class="">conditions to degrade more gracefully.<br class=""><br class=""> -- Steve<br class=""><br class="">On Fri, 29 Dec 2017, Michael Balzer wrote:<br class=""><br class=""><blockquote type="cite" class="">I've found a strange issue with console logging and/or especially<br class="">CAN tracing:<br class=""><br class="">If CAN tracing is enabled and a and that sends CAN frames and runs<br class="">longer than about a second (?) (i.e. "co can1 scan"), the trace<br class="">output first becomes garbled, the command will need much longer than<br class="">usual to finish, and after returning to the prompt, the hex and<br class="">single char output of the trace is split into separate outputs,<br class="">coming one per second (running for a while), intermixing with the<br class="">shell prompt. Also trace output gets garbled especially on a<br class="">parallel telnet session.<br class=""><br class="">I suspect that's due to the UART queue becoming full, and the<br class="">console logger doing xQueueSendToBack() with 1000 ms timeouts.<br class=""><br class="">Every hex dump byte is logged by a separate call to<br class="">MyCommandApp.Log(). If the queue is full, every single call gets<br class="">delayed for a second ...adding up to block the console for as many<br class="">seconds as there are calls...? (unverified theory)<br class=""><br class=""><blockquote type="cite" class="">As proposed, I will change the script code to use BufferedShell and<br class="">also change how console_logger() is done so I can remove the<br class="">problematic OvmsConsole::Log() function. Then puts() will work again,<br class="">too.<br class=""> -- Steve<br class=""></blockquote>Is this related? I.e. should the CAN trace output be done using<br class="">ESP_LOG instead of MyCommandApp.Log()?<br class=""><br class="">If so I can take care of that...<br class=""><br class="">Regards,<br class="">Michael<br class=""><br class="">--<br class="">Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal<br class="">Fon 02333 / 833 5735 * Handy 0176 / 206 989 26<br class=""></blockquote>_______________________________________________<br class="">OvmsDev mailing list<br class="">OvmsDev@lists.teslaclub.hk<br class="">http://lists.teslaclub.hk/mailman/listinfo/ovmsdev<br class=""></blockquote>--<br class="">Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal<br class="">Fon 02333 / 833 5735 * Handy 0176 / 206 989 26<br class=""><br class=""><br class="">_______________________________________________<br class="">OvmsDev mailing list<br class="">OvmsDev@lists.teslaclub.hk<br class="">http://lists.teslaclub.hk/mailman/listinfo/ovmsdev<br class=""><br class=""><br class=""></blockquote>_______________________________________________<br class="">OvmsDev mailing list<br class=""><a href="mailto:OvmsDev@lists.teslaclub.hk" class="">OvmsDev@lists.teslaclub.hk</a><br class="">http://lists.teslaclub.hk/mailman/listinfo/ovmsdev<br class=""></blockquote>--<br class="">Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal<br class="">Fon 02333 / 833 5735 * Handy 0176 / 206 989 26<br class=""><br class=""><br class="">_______________________________________________<br class="">OvmsDev mailing list<br class=""><a href="mailto:OvmsDev@lists.teslaclub.hk" class="">OvmsDev@lists.teslaclub.hk</a><br class="">http://lists.teslaclub.hk/mailman/listinfo/ovmsdev<br class=""><br class=""><br class=""></blockquote>_______________________________________________<br class="">OvmsDev mailing list<br class=""><a href="mailto:OvmsDev@lists.teslaclub.hk" class="">OvmsDev@lists.teslaclub.hk</a><br class="">http://lists.teslaclub.hk/mailman/listinfo/ovmsdev<br class=""></blockquote><br class="">-- <br class="">Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal<br class="">Fon 02333 / 833 5735 * Handy 0176 / 206 989 26<br class=""><br class="">_______________________________________________<br class="">OvmsDev mailing list<br class=""><a href="mailto:OvmsDev@lists.teslaclub.hk" class="">OvmsDev@lists.teslaclub.hk</a><br class="">http://lists.teslaclub.hk/mailman/listinfo/ovmsdev<br class=""></div></div></blockquote></div><br class=""></div></body></html>