# Add milliseconds to timestamp on console logging

**URL:** <https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921>\
**Category:** General\
**Created:** [14 November 2019 03:16 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921 "2019-11-14T03:16:35Z")\
**Posts on this page:** 17\
**Page:** 1

<div class="post-metadata">

**Author:** ![T0T4R4](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/t0t4r4/32/10850_2.png) [@T0T4R4](https://discourse.nodered.org/u/T0T4R4)\
**Post date:** [14 November 2019 03:16 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/1 "2019-11-14T03:16:35Z")

</div>

The timestamp provided as part of the Debug node console logging does not include milliseconds, and is not following the ISO format, is there a way to change this ?

---

<div class="post-metadata">

**Author:** ![Colin](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/colin/32/17040_2.png) [@Colin](https://discourse.nodered.org/u/Colin)\
**Post date:** [14 November 2019 08:10 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/2 "2019-11-14T08:10:46Z")

</div>

Can you clarify which timestamp you mean please. Possibly a screenshot would be useful.

---

<div class="post-metadata">

**Author:** ![cymplecy](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/cymplecy/32/2773_2.png) [@cymplecy](https://discourse.nodered.org/u/cymplecy)\
**Post date:** [14 November 2019 08:12 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/3 "2019-11-14T08:12:53Z")

</div>

I think they mean this one  
 ![image](https://us1.discourse-cdn.com/flex026/uploads/nodered/original/2X/1/1d8264a1a2c9f1b7e5b48cab9bcbeeeb3117ab32.png)

---

<div class="post-metadata">

**Author:** ![Colin](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/colin/32/17040_2.png) [@Colin](https://discourse.nodered.org/u/Colin)\
**Post date:** [14 November 2019 08:27 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/4 "2019-11-14T08:27:16Z")

</div>

@T0T4R4 if you do mean the one at the top of the debug message, why do you need that to more precision? Generally it will not be that accurate anyway as it is the time the debug node gets round to displaying it. Depending on the power of your processor that might well be good fractions of a second late. I am not certain but I suspect that is generated in the browser in which case if you look at it on two browsers at the same time they would not even show the same value if shown to milliseconds. I may be wrong on this one though.

---

<div class="post-metadata">

**Author:** ![dceejay](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/dceejay/32/38_2.png) [@dceejay](https://discourse.nodered.org/u/dceejay)\
**Post date:** [14 November 2019 09:01 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/5 "2019-11-14T09:01:36Z")

</div>

As Colin points out - it is added at the browser end when it processes the message so may not be particularly accurate. I guess we could look to make it clickable to cycle through various formats (currently it is in toLocaleString).

---

<div class="post-metadata">

**Author:** ![T0T4R4](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/t0t4r4/32/10850_2.png) [@T0T4R4](https://discourse.nodered.org/u/T0T4R4)\
**Post date:** [14 November 2019 09:45 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/6 "2019-11-14T09:45:05Z")

</div>

Thanks guys. Yes I indeed meant the one showing both on the debugger window and the node-red console. Is there a better logging strategy that you would recommend ?

---

<div class="post-metadata">

**Author:** ![TotallyInformation](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/totallyinformation/32/31_2.png) [@TotallyInformation](https://discourse.nodered.org/u/TotallyInformation)\
**Post date:** [14 November 2019 10:39 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/7 "2019-11-14T10:39:33Z")

</div>

I think you may need to explain your actual need.

Personally, if I were looking for detailed timing data, I wouldn't use the general log. Instead, I would use a separate log file.

But it really all depends on what you actually want to achieve.

---

<div class="post-metadata">

**Author:** ![T0T4R4](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/t0t4r4/32/10850_2.png) [@T0T4R4](https://discourse.nodered.org/u/T0T4R4)\
**Post date:** [14 November 2019 10:40 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/8 "2019-11-14T10:40:29Z")

</div>

That is exactly my need. Maybe the node-red-contrib-advance-logger plugin could do that...

---

<div class="post-metadata">

**Author:** ![TotallyInformation](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/totallyinformation/32/31_2.png) [@TotallyInformation](https://discourse.nodered.org/u/TotallyInformation)\
**Post date:** [14 November 2019 10:48 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/9 "2019-11-14T10:48:20Z")

</div>

Is this on your own custom node or is it for your flow in general?

Honestly, trying to time flows down to the millisecond is a waste of time since there are far too many variables. It might sometimes be worth it in your own custom node but it would certainly be the last step.

Don't forget that node.js is not a real-time system.

---

<div class="post-metadata">

**Author:** ![T0T4R4](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/t0t4r4/32/10850_2.png) [@T0T4R4](https://discourse.nodered.org/u/T0T4R4)\
**Post date:** [14 November 2019 10:49 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/10 "2019-11-14T10:49:46Z")

</div>

I have never written any custom node 😃  
I'm not really meaning real time, but the issue with the current displays is that I have no garantee that logged messages are displayed in the order they are generated.

---

<div class="post-metadata">

**Author:** ![TotallyInformation](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/totallyinformation/32/31_2.png) [@TotallyInformation](https://discourse.nodered.org/u/TotallyInformation)\
**Post date:** [14 November 2019 10:57 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/11 "2019-11-14T10:57:32Z")

</div>

> [@T0T4R4](#):
>
> I have no garantee that logged messages are displayed in the order they are generated.

Actually, you _do_ have a guarantee, especially if you are using Node-RED v1+. It is just that it is more complex than you might like.

You need to understand a little about how JavaScript works in regard to asynchronous programming.

The log messages _are_ output in order, its just that some nodes will do actions async so that the output order might not be what you initially expect. Depending on the action, that order might not be entirely predictable either though that is less common (an async action might take a variable amount of time to complete).

Have a read of Nick's blog post about the changes for NR v1 in regard to execution order.

Possibly a more useful question is what you might be doing that is time dependent and how the flow might be better organised. Feel free to create a new thread on that subject 😃

---

<div class="post-metadata">

**Author:** ![T0T4R4](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/t0t4r4/32/10850_2.png) [@T0T4R4](https://discourse.nodered.org/u/T0T4R4)\
**Post date:** [14 November 2019 11:01 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/12 "2019-11-14T11:01:08Z")

</div>

Heaps thanks I got it. I just indeed as well updated node from v0.20 to v1.0.1 without passing by the changelog 😃 yeah i know that's bad...

Would you be able to point me at that blog post ?

---

<div class="post-metadata">

**Author:** ![dceejay](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/dceejay/32/38_2.png) [@dceejay](https://discourse.nodered.org/u/dceejay)\
**Post date:** [14 November 2019 11:11 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/13 "2019-11-14T11:11:11Z")

</div>

> **[Making flows asynchronous by default](https://nodered.org/blog/2019/08/16/going-async)**
>
> Changes are coming in Node-RED 1.0 to how messages are routed in a flow. Find out what it means to go asynchronous.

---

<div class="post-metadata">

**Author:** ![zenofmud](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/zenofmud/32/316_2.png) [@zenofmud](https://discourse.nodered.org/u/zenofmud)\
**Post date:** [14 November 2019 11:11 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/14 "2019-11-14T11:11:16Z")

</div>

> [@T0T4R4](#):
>
> Would you be able to point me at that blog post ?

Ummm go to the top of the page and click the `blog` menu item...

---

<div class="post-metadata">

**Author:** ![dceejay](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/dceejay/32/38_2.png) [@dceejay](https://discourse.nodered.org/u/dceejay)\
**Post date:** [14 November 2019 12:54 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/15 "2019-11-14T12:54:50Z")

</div>

> [@T0T4R4](#):
>
> I have no guarantee that logged messages are displayed in the order they are generated.

Well you do in that the timestamps are added at the point they are written to the sidebar log in the browser - so later arriving messages will always be after earlier ones. And on the browser side they are pulled off the websocket queue in the order they were pushed on at the server side... - so yes it does depend what order they were pushed on - if they come from the same node then they will always be in order - if they come from all over your flow, then the order they appear is the order they were output to the queue.

---

<div class="post-metadata">

**Author:** ![T0T4R4](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/t0t4r4/32/10850_2.png) [@T0T4R4](https://discourse.nodered.org/u/T0T4R4)\
**Post date:** [17 November 2019 02:11 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/16 "2019-11-17T02:11:32Z")

</div>

Thanks heaps guys, it's all clear now.

So can we say that in v1.0 NR schedules the messages a bit like a preemptive scheduler ? (and pre-1.0 is was non-preemptive)

---

<div class="post-metadata">

**Author:** ![TotallyInformation](https://sea2.discourse-cdn.com/flex026/user_avatar/discourse.nodered.org/totallyinformation/32/31_2.png) [@TotallyInformation](https://discourse.nodered.org/u/TotallyInformation)\
**Post date:** [17 November 2019 15:40 UTC](https://discourse.nodered.org/t/add-milliseconds-to-timestamp-on-console-logging/17921/17 "2019-11-17T15:40:40Z")

</div>

Urm, no, I don't think so.

It isn't about scheduling, it is about JavaScript's intrinsic loop and its method of asynchronous code handling.

JS is not entirely linear, while it is generally single-threaded, it is able to defer actions to subsequent loop executions so that it doesn't have to wait for slow events to complete.

With something as complex as Node-RED, it can be difficult to know whether a node will process anything as async but you can generally assume that anything that might be slow - such as file actions - will be executed as asynchronous tasks.