Subtracting time differences - inconsistency in strptime results?

[sdevadas]

I have a set of events which are of the type:
Type=httpPreReply Guid=b6d4d009-4643-4ff2-8fad-e20868ce3a17 Datetime=07/08/201118:59:59.565

(this is in the message field of windows event log).

Datetime is some application timing field.

I extract related pairs of Datetime fields using transaction (i.e. Guid) and convert them using strptime and then calculate their difference.

1. The datetime fields are extracted correctly
2. For some reason strptime works for the first few hundred results and then start behaving inconsistently i.e. only one of the Datetime fields are converted, or sometimes both are not.
3. Due to this I am unable to get differences of pairs of time correctly.

Would anyone know why Datetime strings convert inconsistently somewhere in the middle of the result set (they are all generated from the same source). Any hints on debugging would also be appreciated.

My query is:

earliest="07/08/2011:19:00:00" latest="07/08/2011:20:00:00" host="PRWBHZ*" Type="Information" SourceName="Horizon" (Message="Type=httpPostSend*" OR Message="Type=httpPreReply*") | rex field=Message "Type=(?<TheType>.*) Guid=(?<TheGuid>.*) Datetime=(?<TheDatetime>.*).*" | transaction TheGuid | eval TheDatetimeCount=mvcount(TheDatetime) | search TheDatetimeCount=2 | eval firstdtimestr=mvindex(TheDatetime, 0) | eval secondtimestr=mvindex(TheDatetime, 1)  | eval firsttime=strptime(firsttimestr, "%m/%d/%Y%H:%M:%S.%z") | eval secondtime=strptime(secondtimestr, "%m/%d/%Y%H:%M:%S.%z") | eval TotalTime=firsttime - secondtime | table firsttimestr, secondtimestr, firsttime, secondtime, TotalTime

The results come back as correctly for the first few hundred results:
| firsttimestr | secondtimestr | firsttime | secondtime |TotalTime

2 | 07/08/201118:27:06.453 | 07/08/201118:27:06.500 | 1310132046.000000 | 1310131626.000000 | 420.000000

3 | 07/08/201118:07:51.353 | 07/08/201118:07:51.400 | 1310134491.000000 | 1310134071.000000 | 420.000000

4 | 07/08/201118:00:39.157 | 07/08/201118:00:39.204 | 1310141019.000000 | 1310140599.000000 | 420.000000
...

In this case, after the 601, the results of strptime conversion start becoming inconsistent. They are missing for 1 or both the fields. Hence I cannot calculate the TotalTime from this row onwards.

601 | 07/08/201118:33:36.867 | 07/08/201118:33:36.883 | | |

602 | 07/08/201118:33:33.883 | 07/08/201118:33:33.898 | | |

603 | 07/08/201118:33:20.273 | 07/08/201118:33:20.289 | | |

604 | 07/08/201118:33:20.232 | 07/08/201118:33:20.263 | 1310140880.000000 | |

605 | 07/08/201118:33:14.398 | 07/08/201118:33:14.414 | | 1310134754.000000 |

606 | 07/08/201118:32:54.154 | 07/08/201118:32:54.169 | 1310143134.000000 | |

607 | 07/08/201118:32:39.382 | 07/08/201118:32:39.397 | | |

608 | 07/08/201118:32:27.178 | 07/08/201118:32:27.225 | | 1310141247.000000 |

609 | 07/08/201118:32:23.991 | 07/08/201118:32:24.006 | | 1310149584.000000 |

610 | 07/08/201118:32:23.950 | 07/08/201118:32:23.966 | 1310114543.000000 | |

611 | 07/08/201118:32:22.288 | 07/08/201118:32:22.303 | | 1310138962.000000 |

612 | 07/08/201118:32:17.372 | 07/08/201118:32:17.388 | | |

613 | 07/08/201118:32:12.278 | 07/08/201118:32:12.294 | | |

614 | 07/08/201118:32:05.647 | 07/08/201118:32:05.662 | 1310125505.000000 | |
...

[sdevadas · Accepted solution]

My strptime formatting was incorrect.

I used:
strptime(firsttimestr, "%m/%d/%Y%H:%M:%S.%z")

From doc I saw %z should be %q
i.e.
strptime(firsttimestr, "%m/%d/%Y%H:%M:%S.%q")

Things work well when I made the changes.