Device Logs shows wrong dates (and in locale format - potentially part of the issue)

[Steve-Mcl]

Current Behavior

Log entries that arrive from an agent while the Device Log is open, have dates close to epoch. Suspect inconsistent datetime strings used across different applications and regions.

DEMO

crazy-timestamps.mp4

NOTE:

The issue may not be in FF, it may be in the agent - in how the date is transmitted from the agent to the broker, or how the incoming broker sub inteprets the transmitted date value. A good argument for date strings in ISO format across the board.

Expected Behavior

Logs arriving "over the air" should show correct date

Also, to avoid ambiguity (like when a device is in another TZ/Region to the forge platform to the users browser), I would prefer to see all log dates in ISO8601 format

Steps To Reproduce

1. Log into staging or local FF
2. navigate to a device & restart (or start) the device
3. navigate to the "Device Logs"
   a. check datetime stamps in the device logs
   a. should be dd/mm/yyyy HH:MM:SS (Which may be a clue to the underlying issue)
4. Click "Developer Mode" and enable
5. Check the timestamp in the device logs for the latest entries
6. Disable Developer Mode & refresh the pages
   a. Are timestamps now 2023 once more?

Environment

• FlowForge version: 1.8
• Node.js version: 16
• Platform/OS: windows/linux
• Browser: Chrome

Have you provided an initial effort estimate for this issue?

I have provided an initial effort estimate

[knolleary]

The device agent is logging using a different timestamp format to the logs from Node-RED. Here's console output from the device agent (main branch as of right now):

[NR] 30/06/2023 09:05:15 [info] Starting flows
[NR] 30/06/2023 09:05:15 [info] Started flows
[NR] 30/06/2023 09:05:15 [info] Project Link nodes connected
[AGENT] 30 Jun 2023, 09:06:20 info: Disabling remote editor access

The timestamps should be consistently formatted regardless of whether its node-red or the agent logging. I suspect that is part of the root cause for how the dates then appear incorrect when reparsed in the platform.

[knolleary]

Looking at the log events being sent back to the platform, there is an order of magnitude issue here.

Node-RED log statement: {"ts":"16881138776440000","level":"info","msg":"Started flows"}
Device Agent log statement: {"level":"info","msg":"Disabling remote editor access","ts":1688113901212}

Note the ts for the NR log is 1000x the agent log value.

[knolleary]

Figured out the root cause.

The device agent is being consistent with how nr-launcher sends logs to the platform. It takes the timestamp of the log event 1688113901212 and appends a 4-digit counter. This allows for multiple log messages in the same ms, whilst keeping the ability to paginate through the log entries.

What the device agent isn't doing is handling the agent's own log messages quite right so they lack the properly formatted property when sent up to the platform.