Tasmota: Add an option for Millisecond timestamping **in Console log**

[Bascht74]

Have you looked for this feature in other issues and in the docs?
Yes

Is your feature request related to a problem? Please describe.
_A clear and concise description of what the problem is._
I'd like to look at some timing issues I'm observing. For this I have turned on weblog 4 to look at more information. I would like to see how long each component takes to execute code, or what delays they cause.
Currently there is only the output in seconds in the console, via Time 4 you can activate an output of milliseconds (implemented with #8537), but this does not change the display in the console.

Describe the solution you'd like
_A clear and concise description of what you want to happen._

Could time 4 also influence the output in the console so that the milliseconds are also included there:

e.g. like this:

18:38:07 CMD: time 4
18:38:07.484 MQT: stat/tasmota_FB1089/RESULT = {"Time": "2020-12-16T18:38:07.484"} 

Or another possibility (e.g. weblog 5 = weblog 4 + Milliseconds) to include the millisecond information in the console output.

Describe alternatives you've considered
_A clear and concise description of any alternative solutions or features you've considered._
I didn't find any alternative for that.

Additional context
_Add any other context or screenshots about the feature request here._

(Please, remember to close the issue when the problem has been addressed)

[ascillato]

Hi,

Tasmota is not a real time software, so the result of your request won't be accurate. Tasmota has several tasks in background that are controlled by the Espressif SDK like the wifi radio. Also Tasmota has a dynamic sleep function that reduces the power consumption while it is not being used. Besides this, each cycle of the main scheduler is 50msec, reducing more the accuracy of that time difference measurement.

So, sorry but the result of msec used will randomly depends on wifi, sensors polling, etc.

Besides, this request is more oriented to debugging? In that case, you don't need a runtime command, just modify the code for your tests. An user don't need this.

I'd like to look at some timing issues I'm observing.

Please, can you explain a bit further this?

[stefanbode]

If we use the current time just before printing that might be a small effort. For sure it is not cristal accurate, but for sure better than the 1 second resolution. A also had the use-case in my shutter to get it a bit more specific than just on the second level. I would vote for it.

[stefanbode]

Additionally, I would vote for the TIME command and not an additional loglevel. It could make a lot of sense also for a lower loglevel to get the timestamp of the print

[arendst]

Learn to use syslog and you'll have any timestamp you like.

Additional timestamps in console takeup too much log buffer space.which we do not have. Do not suggest it's just a uint32 as it needs processing too.

Won't implement.

[davidelang]

note that syslog traditionally uses second resolution timestamps (RFC3164),
there is a new timestamp RFC (5424) that includes a high resolution timestamp.
I'm not sure which format tasmota uses, but if it's the original format, the
sub-second data is lost.

David Lang

On Wed, 16 Dec 2020, Theo Arends wrote:

Learn to use syslog and you'll have any timestamp you like.

[sfromis]

What I do when I'd like to see subsecond timing is to subscribe to the MQTT messages (possibly including MqttLog) using a tool able to timestamp the output. It seems that the current version of mosquitto_sub has gained an option for output formatting including timestamp. Of course, this is not the Tasmota timestamp, but from the client subscribing, but my experience is that with a reasonably running network, this does not cause issues. In any case, the non-realtime nature of Tasmota will likely induce more deviations in timing, meaning that in both cases doing millisecond calculations is just "too many digits" to pore over.

[Bascht74]

Thanks for all the answers,

here are some comments:
I'd like to look at some timing issues I'm observing.
Please, can you explain a bit further this?

@ascillato I would like to reproduce a problem that I have often observed when stopping (shutterstop) roller shutters. In this case, the shutter stops and then moves backwards a little. The whole thing only occurs sporadically and with weblog 4 there is a lot of output within a second, so you can't see exactly what happens when (only the sequence, but not the exact time course).

just modify the code for your tests. An user don't need this.
@ascillato If a user is technically "gifted", I think that can help with troubleshooting. However, I would not be able or would not dare (so far) to compile and flash Tasmota myself - that would be something completely different...

Tasmota is not a real time software, so the result of your request won't be accurate.
[...] Learn to use syslog and you'll have any timestamp you like.
@arendst Even a tenth of a second would be better than just a second. It does not need to be completely accurate. Thanks for that advice with syslog. I will look into it. But I would only see the time at which the syslog server received the data, right? (might not be a problem with good wifi)

Won't implement.
@arendst If it is not technically possible or too difficult to output the tenths of a second or millisecond in the log, then that is OK with me. No problem, fine for me.

subscribe to the MQTT messages (possibly including MqttLog)
@sfromis I tried mqttlog 4, but the device (a shelly 2.5) reboots after setting it every 10 seconds... (using: V9.1.0.2 Core 2.7.4.9 SDK 2.2.2-dev(38a443e), because of a fix with shutter stop delay. Can you confirm this?
back to mqttlog 0 -> all OK again. mqttlog 0 - 2 seems OK, but 3 or 4 is producing reboots.

mqttlog 3 console log:

01:11:43 CMD: mqttlog 3
01:11:43 RSL: stat/tasmota_FB1089/RESULT = {"MqttLog":3}
00:00:00 CFG: aus Flash geladen am F5, zählen 447
00:00:00 QPC: Count 1
00:00:00 I2C: ADE7953 gefunden bei 0x38
00:00:00 Projekt tasmota ShellySwitch25-Rollo.EG.Wohnzimmer.Terrasse Version 9.1.0.2(tasmota)-2_7_4_9(2020.12.14 19:13:34)
00:00:04 WIF: verbinden mit AP1 Qar5tz09e589mn05a0 Channel 11 BSSId E0:63:DA:53:3C:3E in Modus 11n als Rollo.EG.Wohnzimmer.Terrasse...
00:00:06 QPC: Reset
00:00:11 WIF: Verbindung fehlgeschlagen, da der AP nicht antwortet (timeout)
00:00:15 WIF: verbunden
00:00:16 HTP: Web-Server aktiv bei Rollo.EG.Wohnzimmer.Terrasse mit IP-Adresse 192.168.175.42
01:12:00 MQT: tele/tasmota_FB1089/INFO3 = {"RestartReason":"Software/System restart"}
01:12:00 MQT: stat/tasmota_FB1089/RESULT = {"POWER1":"OFF"}
01:12:00 MQT: stat/tasmota_FB1089/POWER1 = OFF
01:12:00 MQT: stat/tasmota_FB1089/RESULT = {"POWER2":"OFF"}
01:12:00 MQT: stat/tasmota_FB1089/POWER2 = OFF

It seems that the current version of mosquitto_sub has gained an option for output formatting including timestamp
I tried with mqttlog 2, but mqtt Explorer doesn't show the milliseconds right. Published a feature request here: https://github.com/thomasnordquist/MQTT-Explorer/issues/479
The mosquitto log doesn't show milliseconds neither:
1608162904: New client connected from 192.168.175.42 as DVES_FB1089 (p2, c1, k30, u'mqtt').
So I have to try mosquitto_sub and I installed it.
@sfromis Do you have a quick example for me to get a millisecond output?

@All: Thanks for helping me out here, and thanks again for maintaining Tasmota. I really like it the more I get my nose into it!

Sebastian

[ascillato2]

I would like to reproduce a problem that I have often observed when stopping (shutterstop) roller shutters. In this case, the shutter stops and then moves backwards a little.

That is explained at https://github.com/arendst/Tasmota/issues/9906#issuecomment-746255456

Closing as https://github.com/arendst/Tasmota/issues/10152#issuecomment-747066713

[Bascht74]

@ascillato2 I will read it.
But in that issue @stefanbode says: The Firmware is aware of the overrun but will not go backward.
But mine are going backward from time to time. I will look deeper into that this afternoon. I think I'll figure out why this is happening.

@sfromis I would still appreciate a quick help for the mosquitto_sub command.

[Bascht74]

@arendst I set up the syslog server on my synology nas. There are two formats: BSD and IETF. I don't find any information in the documentation witch format I should choose. If I activate syslog 4 the device keeps restarting like mqttlog > 2 (see above). Is this a know bug of the actual dev version or know for shelly2.5 devices? If not, I could open an issue, if that is OK.
Sebastian

[arendst]

Open a new issue with answers to all questions asked

[sfromis]

About the failure to get milliseconds from MQTT, my suggestion was not about all those other things you looked at, but specifically about the command mosquitto_sub, where you can read the man page and find output format, including Unix timestamp with nanoseconds. Note that this is for newest Mosquitto, not older versions.

[arendst]

OMG:

00:00:00.676 CFG: Loaded from flash at FB, Count 447
00:00:00.744 CFG: Saved to flash at FB, Count 448, Bytes 4096
00:00:00.797 QPC: Reset
00:00:00.802 SRC: Restart
00:00:00.803 Project tasmota Wemos5 Version 9.2.0.1(theo)-2_7_4_9(2020-12-17T14:10:54)
00:00:00.065 WIF: Attempting connection...
00:00:00.402 WIF: Connecting to AP2 indebuurt_IoT Channel 11 BSSId 18:E8:29:CA:17:C1 in mode 11n as wemos5...
00:00:01.844 WIF: Connected
00:00:02.103 HTP: Web server active on wemos5 with IP address 192.168.2.172
14:12:16.035 RTC: UTC 2020-12-17T13:12:16, DST 2020-03-29T02:00:00, STD 2020-10-25T03:00:00
14:12:17.094 MQT: Attempting connection...
14:12:17.110 MQT: Connected
14:12:17.115 MQT: tele/wemos5/LWT = Online (retained)
14:12:17.118 MQT: cmnd/wemos5/POWER = 
14:12:17.122 MQT: Subscribe to cmnd/wemos5/#
14:12:17.123 MQT: Subscribe to cmnd/tasmotas/#
14:12:17.125 MQT: Subscribe to cmnd/DVES_17E067_fb/#
14:12:17.128 MQT: tele/wemos5/INFO1 = {"Module":"Generic","Version":"9.2.0.1(theo)","FallbackTopic":"cmnd/DVES_17E067_fb/","GroupTopic":"cmnd/tasmotas/"}
14:12:17.143 MQT: tele/wemos5/INFO2 = {"WebServerMode":"Admin","Hostname":"wemos5","IPAddress":"192.168.2.172"}
14:12:17.152 MQT: tele/wemos5/INFO3 = {"RestartReason":"Software/System restart"}
14:12:17.160 MQT: stat/wemos5/POWER = {"POWER":"OFF"}
14:12:17.165 MQT: stat/wemos5/POWER = OFF
14:12:21.430 MQT: tele/wemos5/STATE = {"Time":"2020-12-17T14:12:21","Uptime":"0T00:00:09","UptimeSec":9,"Heap":29,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"OFF","Wifi":{"AP":2,"SSId":"indebuurt_IoT","BSSId":"18:E8:29:CA:17:C1","Channel":11,"RSSI":100,"Signal":-31,"LinkCount":1,"Downtime":"0T00:00:03"}}
14:12:21.455 MQT: tele/wemos5/SENSOR = {"Time":"2020-12-17T14:12:21","Switch1":"OFF"}
14:12:22.413 APP: Boot Count 199
14:12:22.638 CFG: Saved to flash at FA, Count 449, Bytes 4096
14:13:19.477 HTP: Main Menu
14:13:21.571 HTP: Console

[s-hadinger]

Nice. We can now optimize to the millisecond

[Bascht74]

@arendst Thanks!

about:
Open a new issue with answers to all questions asked
Will do...