[Ovmsdev] Console logging / CAN tracing

Mon Jan 1 20:12:49 HKT 2018

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