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.
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 | |
...
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.
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.