Wierd Time[0] value in OnExecution

[alex.nt]

Greetings,

I have the following output in my log:

Timestamp is taken from Time[0]

2011-12-09 19:16:20: barsInProgressIndex#0
2011-12-09 19:16:20: barsInProgressIndex#0
2011-12-09 19:16:20: barsInProgressIndex#1
2011-12-09 19:16:20: barsInProgressIndex#1
2011-12-09 19:18:24: barsInProgressIndex#1 ...
2011-12-09 19:18:24: barsInProgressIndex#1 ...
2011-12-09 19:19:19: barsInProgressIndex#1
2011-12-09 19:19:19: barsInProgressIndex#1
2011-12-09 19:21:39: barsInProgressIndex#1
2011-12-09 19:21:39: barsInProgressIndex#1
2011-12-09 19:24:23: barsInProgressIndex#1
2011-12-09 19:24:23: barsInProgressIndex#1
2011-12-09 19:26:10: barsInProgressIndex#1
2011-12-09 19:26:10: barsInProgressIndex#1 # after this EnterShort(1, ...) gets called
2011-12-09 19:26:10: barsInProgressIndex#1, signal confirmed, entering Sell
2011-12-09 19:16:20: Order 19:26:10 filled # comes from OnExecution

The question is: how come the timestamp on the last message is different from the timestamp of the bar that had issued the entry order?

Note, that there are 2 data series based on volume on the chart, both represent the same instrument but with different volume values. The order is issued sometimes via EnterShort(0, ..., sometimes via EnterShort(1,

Since at 19:26:10 we had issued the order as EnterShort(1, then why 19:16:20 bar (barsInProgressIndex#0 bar) is mentioned upon a fill?

[NinjaTrader_RyanM1]

Hi alex.nt,

Please make sure you are using the latest version of NT, release 8. There was this fix that may be related.
Fixed 4576 Charts Executions of non-primary series of multi-series strategies could be on wrong bar index of series.

If you are unsure about any output from your strategy after upgrading, please post a simplified code snippet that generates the output.

[alex.nt]

I have just installed the latest version and the problem persists...

The code is very simple:
1. print message before sending a market order
2. Print message in OnExecution like:
protected override void OnExecution(IExecution execution)
{
if (execution != null && execution.Order != null && execution.Order.OrderState == OrderState.Filled)
{
Log("Order " + execution.Name + " filled"); // <----- weird time
}
}

I think this may be related to the fact that I use 2 charts (onBarUpdate gets called for one and for another so may be onExecution still thinks in terms of slow chart, which can be behind)...

[NinjaTrader_RyanM1]

I don't see where time is used anywhere in your example code. Are you talking about the timestamp that's included when generating a log statement?

[alex.nt]

Yes, the timestamp is prepended to the message in Log function.

[NinjaTrader_Brett]

The log time appended is the local system time.

The log time you are comparring it to the right on that last line does not look like you are accessing the correct time value.

You are doing Log("Order " + execution.Name + " filled");

You should be using:

Log("Order " + execution.Time + " filled");

Finally, please be carefull with logging. We prefer using the output window and the Print command for this logging as if there are too many lines in the log this will cause performance issues in NinjaTrader.

-Brett

[alex.nt]

Hi Brett,
Ok, here is the log function:
public void Log(string s)
{
string pre = string.Format("{0:yyyy-MM-dd HH:mm:ss}", Time[0]) + ": ";
Print(pre + s);
}

[NinjaTrader_Brett]

Hello,

Looks like you are overriding the log output.

This would be unsupported and would not recommend doing this, this may be a contributing factor for why your time is not correct. Would recommend using the standard log method.

-Brett