Strange pipeline timestamp behaviour

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:
image

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

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
1 Like