StartTime, EndTime, BootTime property value

[heestree]

Hi,

Thanks for new etl file parse feature. I am trying to get start, end, and boot time of etl file and somehow I can't get the right datetime. My codes are as follows:

let events_read = process_from_file(dump_file.file_path);

fn process_from_file(input_file: PathBuf) -> usize {
    let (trace, handle) = FileTrace::new(input_file, empty_callback).start().unwrap();
    FileTrace::process_from_handle(handle).unwrap();
}

fn empty_callback(record: &EventRecord, schema_locator: &SchemaLocator) {
  match schema_locator.event_schema(record) {
        Err(_err) => {}
        Ok(schema) => {
            if schema.provider_name() == "MSNT_SystemTrace" {
                if schema.task_name() == "EventTrace" {
                    if schema.opcode_name() == "Header" {
                        let parser = Parser::create(record, &schema);
                        let start_time: Option<i64> = parser.try_parse("StartTime").ok();
                        let end_time: Option<i64> = parser.try_parse("EndTime").ok();
                        let boot_time: Option<i64> = parser.try_parse("BootTime").ok();
                        let cpu_speed: Option<u32> = parser.try_parse("CPUSpeed").ok();
                        let resolution: Option<u32> = parser.try_parse("TimerResolution").ok();
                        if resolution.is_some() {
                            dbg!(start_time.unwrap());
                            dbg!(end_time.unwrap());
                            dbg!(boot_time.unwrap());
                            dbg!(cpu_speed.unwrap());
                            dbg!(resolution.unwrap());
                            let start_time = Utc.timestamp_nanos(start_time.unwrap() as i64);
                            println!("start_time: {}", start_time);
                            let end_time = Utc.timestamp_nanos(end_time.unwrap() as i64);
                            println!("end_time: {}", end_time);
                            let boot_time = Utc.timestamp_nanos(boot_time.unwrap() as i64);
                            println!("boot_time: {}", boot_time);
                        } 
                    }
                }
            } 
        }
    }
}

Output is as follows:

[src\cmds_fr_console_hidden\get_timer_resolution.rs:163] start_time.unwrap() = 3170652886736593920
[src\cmds_fr_console_hidden\get_timer_resolution.rs:164] end_time.unwrap() = 133223811153179641
[src\cmds_fr_console_hidden\get_timer_resolution.rs:165] boot_time.unwrap() = 8791154017049772033
[src\cmds_fr_console_hidden\get_timer_resolution.rs:166] cpu_speed.unwrap() = 3302
[src\cmds_fr_console_hidden\get_timer_resolution.rs:167] resolution.unwrap() = 156250
start_time: 2070-06-22 08:54:46.736593920 UTC
end_time: 1974-03-22 22:36:51.153179641 UTC
boot_time: 2248-07-31 11:13:37.049772033 UTC

What is the right way to get datetime from i64 for start, end, and boo time? Or parser.try_parse return wrong value?
CPUSpeed and TimeResolution (u32) are correct.

etl file is attached below: please remove .txt and unzip test.zip file. original file name is test.etl.
test.zip.txt

[daladim]

I am not sure what is wrong here.
I have a few suggestions though.

• Windows usually encodes dates as FILETIME, which are hundreds of nanoseconds since January 1, 1601. Utc.timestamp_nanos probably interprets the numbers you give it as nanoseconds since January 1, 1970 instead. You should check the documentation of your provider (if any...).
• In case the previous idea does not solve your problem, what happens when you open your .etl file with Windows tools? (e.g. perfview.exe, or Windows Event Viewer (which is able to open them IIRC)) What timestamp do they show?

[heestree]

Thanks @daladim

I converted windows time to unix time and I got correct EndTime.
I followed this link

end_time_nsec.separate_with_underscores() = "133_223_811_153_179_641"
end_time_msec.separate_with_underscores() = "1_677_907_515_317"
end_time_naive_datetime = 2023-03-04T05:25:15.317

Interesting thing is StartTime and BootTime are still wrong as shown below.

QQ:

1. Why is try_parse for StartTime returns big number 3_170_652_886_736_593_920 when EndTime returns correct one 133_223_811_153_179_641? Only difference that I see is the property_buffer in find_property.
2. Where in the code gets property buffer from etl file?

Thanks for your help and guidance.

BTW, wpa shows:

3 | Start Time (UTC) | 2023/03/04 05:25:11.2996373
4 | End Time (UTC) | 2023/03/04 05:25:15.3179641
5 | Start Time (Local) | 2023/03/03 21:25:11.2996373
6 | End Time (Local) | 2023/03/03 21:25:15.3179641

Following is my result

------------- start time -------------
[src\cmds_fr_console_hidden\get_sys_config.rs:173] start_time_nsec.separate_with_underscores() = "3_170_652_886_736_593_920"
3170652886736593920 -> 305420815073659
[src\cmds_fr_console_hidden\get_sys_config.rs:176] start_time_msec.separate_with_underscores() = "305_420_815_073_659"
[src\etw\ferris_etw\frrs_utils.rs:45] naive_datetime = +11648-05-26T03:17:53.659
[src\etw\ferris_etw\frrs_utils.rs:48] datetime_again = +11648-05-26T03:17:53.659Z
[src\etw\ferris_etw\frrs_utils.rs:55] datetime_new_format.to_string() = "+11648-05-26 03:17:53"
[src\cmds_fr_console_hidden\get_sys_config.rs:178] start_time = +11648-05-26T03:17:53.659Z
------------- end time -------------
[src\cmds_fr_console_hidden\get_sys_config.rs:183] end_time_nsec.separate_with_underscores() = "133_223_811_153_179_641"
133223811153179641 -> 1677907515317
[src\cmds_fr_console_hidden\get_sys_config.rs:186] end_time_msec.separate_with_underscores() = "1_677_907_515_317"
[src\etw\ferris_etw\frrs_utils.rs:45] naive_datetime = 2023-03-04T05:25:15.317
[src\etw\ferris_etw\frrs_utils.rs:48] datetime_again = 2023-03-04T05:25:15.317Z
[src\etw\ferris_etw\frrs_utils.rs:55] datetime_new_format.to_string() = "2023-03-04 05:25:15"
[src\cmds_fr_console_hidden\get_sys_config.rs:188] end_time = 2023-03-04T05:25:15.317Z
------------- boot time -------------
[src\cmds_fr_console_hidden\get_sys_config.rs:193] boot_time_nsec.separate_with_underscores() = "8_791_154_017_049_772_033"
8791154017049772033 -> 867470928104977
[src\cmds_fr_console_hidden\get_sys_config.rs:196] boot_time_msec.separate_with_underscores() = "867_470_928_104_977"
[src\etw\ferris_etw\frrs_utils.rs:45] naive_datetime = +29459-01-22T18:41:44.977
[src\etw\ferris_etw\frrs_utils.rs:48] datetime_again = +29459-01-22T18:41:44.977Z
[src\etw\ferris_etw\frrs_utils.rs:55] datetime_new_format.to_string() = "+29459-01-22 18:41:44"
[src\cmds_fr_console_hidden\get_sys_config.rs:198] boot_time = +29459-01-22T18:41:44.977Z

Followings are the functions that I created/used.

// start time
println!("------------- start time -------------");
let start_time_nsec = start_time.unwrap();
dbg!(start_time_nsec.separate_with_underscores());
let start_time_msec = convert_windowstime_to_unixtime(start_time_nsec, true);
dbg!(start_time_msec.separate_with_underscores());
let start_time = convert_u64_to_datetime(start_time_msec, true);
dbg!(start_time);

// end time
println!("------------- end time -------------");
let end_time_nsec = end_time.unwrap();
dbg!(end_time_nsec.separate_with_underscores());
let end_time_msec = convert_windowstime_to_unixtime(end_time_nsec, true);
dbg!(end_time_msec.separate_with_underscores());
let end_time = convert_u64_to_datetime(end_time_msec, true);
dbg!(end_time);

// boot time
println!("------------- boot time -------------");
let boot_time_nsec = boot_time.unwrap();
dbg!(boot_time_nsec.separate_with_underscores());
let boot_time_msec = convert_windowstime_to_unixtime(boot_time_nsec, true);
dbg!(boot_time_msec.separate_with_underscores());
let boot_time = convert_u64_to_datetime(boot_time_msec, true);
dbg!(boot_time);

// ---------------------------------------------
pub fn convert_windowstime_to_unixtime(wintime: u64, msec: bool) -> u64 {
    // https://stackoverflow.com/questions/6161776/convert-windows-filetime-to-second-in-unix-linux

    if msec {
        const WINDOWS_TICKS_PER_SECOND: u64 = 10_000;
        const EPOCH_DIFFERENCE: u64 = 11_644_473_600_000;
        //convert from 100ns intervals to milli-second
        let mut converted_time = wintime / WINDOWS_TICKS_PER_SECOND;
        //subtract number of milli-seconds between epochs
        converted_time = converted_time - EPOCH_DIFFERENCE;
        println!("{} -> {}", wintime, converted_time);

        converted_time
    } else {
        const WINDOWS_TICKS_PER_SECOND: u64 = 10_000_000;
        const EPOCH_DIFFERENCE: u64 = 11_644_473_600;
        //convert from 100ns intervals to seconds;
        let mut converted_time = wintime / WINDOWS_TICKS_PER_SECOND;
        //subtract number of seconds between epochs
        converted_time = converted_time - EPOCH_DIFFERENCE;
        println!("{} -> {}", wintime, converted_time);

        converted_time
    }
}

// ---------------------------------------------
pub fn convert_str_to_datetime(str: &str, msec: bool) -> DateTime<Utc> {
    let timestamp = str.parse::<u64>().unwrap();
    dbg!(timestamp);

    convert_u64_to_datetime(timestamp, msec)
}

// ---------------------------------------------
pub fn convert_u64_to_datetime(timestamp: u64, msec: bool) -> DateTime<Utc> {
    let naive_datetime = if msec {
        chrono::NaiveDateTime::from_timestamp_millis(timestamp as i64).unwrap()
    } else {
        chrono::NaiveDateTime::from_timestamp_opt(timestamp as i64, 0).unwrap()
    };
    dbg!(naive_datetime);

    let datetime_again: chrono::DateTime<Utc> = chrono::DateTime::from_utc(naive_datetime, Utc);
    dbg!(datetime_again);

    let datetime_new_format = if msec {
        datetime_again.format("%Y-%m-%d %H:%M:%S") // TODO: FIXME: add msec
    } else {
        datetime_again.format("%Y-%m-%d %H:%M:%S")
    };
    dbg!(datetime_new_format.to_string());

    datetime_again
}

[daladim]

1. I am not sure. Your usage of ferrisetw looks correct, so the problem may be elsewhere.

You could try to (find and) check the documentation. Maybe BootTime is a duration, and not a date?
You may want to look at how crateslike sysinfo implement fetching BootTime, if I remember correctly they grab the same value as yours.

I don't know why StartDate > EndDate though.

[daladim]

2. I'm not sure I understand your question, sorry :-/
   Which property do you mean? Parsing is done the same way for live traces and ETL traces. ETW records are passed by windows into our trace_callback_thunk function. You may want to look how they are handled from there.

[daladim]

Maybe ferrisetw could be reading the buffer at the wrong indices for StartTime? That would be a bug.
Maybe tools such as MessageAnalyzer could show you the raw i64 value that we're expected to read, and see whether we're getting the right one here.

[heestree]

Thanks @daladim
Boot time is a date time: BootTime="3/3/2023 8:46:14 PM" (from PerfView)
Following is what I found so far. I think the culprit is TimeZoneInformation. It has wrong buffer size (1 byte) which should be 176 byte. So, all the properties behind TimeZoneInformation will get wrong value (due to wrong buffer offset), and ones before TimeZoneInformation will have correct value. For instance, EndTime is before TimeZoneInformation, so it gets correcct value. But BootTime and StartTime are after TimeZoneInformation, so, they got wrong values.
So if we can get right buffer (with right size) for TimeZoneInformation, we'll be ok.
You should be able to reproduce this with any ETL file.

Dump from ferrisetw:

[ferrisetw\src\parser.rs:248] prop_slice = PropertySlice {
    property: Property {
        name: "TimeZoneInformation",
        flags: (empty),
        length: 1,
        in_type: InTypeUInt8,
        out_type: OutTypeNull,
    },
    buffer: [
        224,
    ],
}

Dump from etw-profile
Property { name: "TimeZoneInformation", flags: (empty), length: 1, desc: Primitive(PrimitiveDesc { in_type: InTypeUInt8, out_type: OutTypeNull }), map_info: None, count: 176 } [224, 1, 0, 0, 64, 0, 116, 0, 122, 0, 114, 0, 101, 0, 115, 0, 46, 0, 100, 0, 108, 0, 108, 0, 44, 0, 45, 0, 50, 0, 49, 0, 50, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 11, 0, 0, 0, 1, 0, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 64, 0, 116, 0, 122, 0, 114, 0, 101, 0, 115, 0, 46, 0, 100, 0, 108, 0, 108, 0, 44, 0, 45, 0, 50, 0, 49, 0, 49, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 3, 0, 0, 0, 2, 0, 2, 0, 0, 0, 0, 0, 0, 0, 196, 255, 255, 255, 0, 0, 0, 0]

[daladim]

Hmm, that's interesting, thanks for the investigation!
That definitely sounds like a bug in ferrisetw then, I'll have a look...as soon as I have a little time (but if you know how to fix it, feel free to make a merge request, of course!)

[daladim]

Well that is strange.
Windows (through TdhGetEventInformation) gives us the following EVENT_PROPERTY_INFO regarding TimeZoneInformation:

000000: 00 00 00 00  50 04 00 00   .... P...
000008: 04 00 2d 01  00 00 00 00   ..-. ....
000010: b0 00 01 00  00 00 00 00   .... ....  // size is 01!

Its flags are 0, so it does not look we're missing anything special here. Reading at the documentation and the code of Property::new(), we haven't forgotten to handle some special case, and its length is correctly defined as 1 (the byte in bold)... 🤔

@n4r1b , do you have any idea here?

[daladim]

I guess I should have a look at how etw-profile finds out this is 176 bytes long...

[heestree]

just fyi, etw-reader has property.count field, which ferrisetw doesn't have.
In find_property_size() etw-reader has extra layer of if-statement which checks count and if count != 1 it returns
Ok(tdh::property_size(self.event.record(), &property.name).unwrap() as usize) as property size.
In ferrisetw, it returns return Ok(size);
we may need to understand what property.count is and how it got set in etw-reader.