Strange pipeline timestamp behaviour

[gaetan-craft (Gaëtan)]

I have messages with a tiestamp field written in an app and the flowed through different mechanisms to graylog. I want to add graylog ingestion time to have a rough measurement of log latency. I tried to achieve this using pipelines. I have no issue adding ingestion time but issues computing the latency.
My first try was with this pipeline rule:

rule "add ingestion timestamp"
when 
    true
then
    let ingestion_time = now();
    set_field("log_latency",ingestion_time.millis-to_date($message.timestamp).millis);
end

latency was always 0 which does not look right

2. Describe your environment:

• OS Information:
  Linux Ubuntu
• Package Version:
  4.2.9+f0d8298, codename Noir

3. What steps have you already taken to try and solve the problem?

I tried to add intermediate field to understand why the latency was always 0
Code changed to

rule "add ingestion timestamp"
when 
    true
then
    let ingestion_time = now();
    let timestamp_time = parse_date(to_string($message.timestamp), "yyyy-MM-dd'T'HH:mm:ss.SSSZ");
    set_field("timestamp_text", to_string($message.timestamp,"default_text"));
    set_field("timestamp2b", $message.timestamp);
    set_field("timestamp2", timestamp_time);
    set_field("ingestion_time",ingestion_time);
    set_field("ingestion_time_millis", ingestion_time.millis);
    set_field("timestamp_millis",to_date($message.timestamp).millis); 
end

And to my utmost suprise a message goging through this pipelines looked like this:

4. How can the community help?
Is there any magic trick involving $message.timestamp ?
Should I do this another way ?

[tmacgbay]

You can use the debug function to sus out what is happening in the rule:

rule "add ingestion timestamp"
when 
    true
then
    let ingestion_time = now();
    let the_diff = ingestion_time.millis - to_date($message.timestamp).millis;
    
     // use $ tail -f /var/log/graylog-server/server.log to watch for the results of the below debug messages
     //
     debug(concat("============ current time in ms: ", to_string(ingestion_time.millis)));
     debug(concat("============ timestamp in ms: ",    to_string(to_date($message.timestamp).millis)));
     debug(concat("============ difference: ",        to_string(the_diff)));

    set_field("log_latency",the_diff);

end

[ihe]

Hi, you might use the field gl2_receive_timestamp instead of ingestion_time = now();. I used it for similar purposes some time ago, but I’m not sure if it still exists.

[localhost (MFL)]

@ihe : I don’t see gl2_receive_timestamp filled, actually.

I think the diff calculation won’t really fit whats happening. If you calculate the diff between the actual pipeline processing step and the timestamp of the original message, that also includes the transport time the message needed to reach the graylog server.

We add a field input_time at the beginning of our processing pipeline rules, so at a later point in time it is possible to calculate the runtime in the pipelines:

rule "add pipeline_processingtime"
when 
    has_field("input_time")
then
    let ingestion_time = to_date($message.input_time).millis;
    let current_time = to_date(now()).millis;
    let millis_diff = to_long(to_long(current_time) - to_long(ingestion_time));

    set_field("pipeline_processingtime", millis_diff);
end