[Ovmsdev] Console logging / CAN tracing

[Michael Balzer]

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