[Ovmsdev] Console logging / CAN tracing

Geir Øyvind Vælidalo geir at validalo.net
Mon Jan 1 20:20:16 HKT 2018


This is so nice! Thanks, Stephen!

Geir

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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.teslaclub.hk/pipermail/ovmsdev/attachments/20180101/afa55002/attachment-0001.html>


More information about the OvmsDev mailing list