Rabbitmq Streams and message timestamp clarification

[Jonathon L]

Hi there,

I'm encountering unexpected behaviour using the Go Streams Client library, versions:

- github.com/rabbitmq/rabbitmq-stream-go-client v1.4.2

- RabbitMQ: 3.13 with management, amqp 1.0, stream, and shovel plugins

Ref docs:

- https://www.rabbitmq.com/docs/streams#consuming

- https://pkg.go.dev/github.com/rabbitmq/rabbitmq-str...@v1.4.2/pkg/stream#OffsetSpecification

One thing I can't confirm from the RMQ docs is what this stream message timestamp corresponds to? Is it the server's UTC system time when the message was entered into the stream? Can it be set by the client via any of the AMQP 1.0's message parameters such as "MessageProperties.CreationTime"?

Next, how should we exactly use the timestamp offset spec when consuming? My test setup uses a system timezone of UTC with all defaults for the stream config. The producer, consumer, and rabbitmq are all running on the same test system. The test steps are as follows:

1. publish 5 messages at time A (starts at offset 0)

2. Wait 5 minutes, publish another 5 messages at time B (i.e. B ~= A + 5min).

3. Consume using stream.OffsetSpecification{}.Timestamp(int64(timestamp)) where 'timestamp' is the Unix timestamp equivalent of B (I'm assuming this is the correct format based on the RMQ ref link posted above, though there are no comments for this API)

For each message, I set the MessageProperties.CreationTime to the current system time (in UTC). I read this and print it out when consuming.

Expectation: It attaches to the stream around offset 5 (ideally, exactly at that corresponding message)

Observed: It attaches to the beginning of the stream (at offset 0)

The stream metadata (from the "Environment" struct) when consuming is as follows:

&{stats:map[committed_chunk_id:5 first_chunk_id:0 last_chunk_id:5] streamName:events}

Is my expectation valid? Any clarification would be greatly appreciated.

Thank you for taking the time to help me out.

[Karl Nilsson]

You may need to add a bit of margin to your offset specification - say 5.5 minutes instead of 5. 

Karl Nilsson

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/34a42d3b-5b95-4403-b279-6d40dc9fd38dn%40googlegroups.com.

[Jonathon L]

Thanks for the quick reply!

As in try a timestamp of B +/- 30sec? This produced the same result.

The message timestamps are as follows (the data is just a string containing the message index, the timestamp is the MessageProperties.CreationTime that I set during publishing printed out in ISO 8601 and Unix formats):

data:      event-0

offset:    0
timestamp: 2024-09-16 18:43:21.591 +0000 UTC, unix: 1726512201
data:      event-1
offset:    1
timestamp: 2024-09-16 18:43:21.591 +0000 UTC, unix: 1726512201
data:      event-2
offset:    2
timestamp: 2024-09-16 18:43:21.591 +0000 UTC, unix: 1726512201
data:      event-3
offset:    3
timestamp: 2024-09-16 18:43:21.591 +0000 UTC, unix: 1726512201
data:      event-4
offset:    4
timestamp: 2024-09-16 18:43:21.591 +0000 UTC, unix: 1726512201
data:      event-5
offset:    5
timestamp: 2024-09-16 18:47:36.48 +0000 UTC, unix: 1726512456
data:      event-6
offset:    6
timestamp: 2024-09-16 18:47:36.48 +0000 UTC, unix: 1726512456
data:      event-7
offset:    7
timestamp: 2024-09-16 18:47:36.481 +0000 UTC, unix: 1726512456
data:      event-8
offset:    8
timestamp: 2024-09-16 18:47:36.481 +0000 UTC, unix: 1726512456
data:      event-9
offset:    9
timestamp: 2024-09-16 18:47:36.481 +0000 UTC, unix: 1726512456

As you can see, the first 5 messages all have the same timestamp (A), and the last five all have the same timestamp that is just over 4 minutes later (B). The value I use as the parameter to the timestamp specification has been 1726512456,  (1726512456 - 30), 1800000000, 2000000000, 0... they all result in attaching to the stream at offset 0.

It is not until I added 3 more zero's (1726512456000) does the result change to the equivalent of OffsetSpecification.Next

Can you confirm that the OffsetSpecification{}.Timestamp() API takes an absolute Unix timestamp?

[Gabriele Santomaggio]

Hi Jonathon,

May I ask to open a discussion here:  https://github.com/rabbitmq/rabbitmq-stream-go-client/discussions?

An example and other details can help to understand the problem. 

I will have a look.

Thank you 

[Artur Wroblewski]

On Mon, Sep 16, 2024 at 12:03:43PM -0700, 'Jonathon L' via rabbitmq-users wrote:
[...]

> Ref docs:
> - https://www.rabbitmq.com/docs/streams#consuming
> - https://pkg.go.dev/github.com/rabbitmq/rabbitmq-str...@v1.4.2/pkg/stream#OffsetSpecification
>
> One thing I can't confirm from the RMQ docs is what this stream message
> timestamp corresponds to? Is it the server's UTC system time when the
> message was entered into the stream? Can it be set by the client via any of
> the AMQP 1.0's message parameters such as "MessageProperties.CreationTime"?

The stream message timestamp is Erlang system time.

Be careful when using it.

For example, try on a laptop - put the machine to sleep for few minutes,
and observe Erlang system time catching up with system time.

On a server, I would start RabbitMQ *after* time is synchronized.

See also

https://github.com/rabbitmq/rabbitmq-server/blob/main/deps/rabbitmq_stream/docs/PROTOCOL.adoc#subscribe
https://www.erlang.org/doc/apps/erts/time_correction.html#Erlang_System_Time
https://github.com/rabbitmq/rabbitmq-server/issues/3769

> Next, how should we exactly use the timestamp offset spec when consuming?

Having a timestamp, I would round it down, then ignore duplicate messages.

If anyone has better ideas, please share.

Best regards,

Artur

--
https://mortgage.diy-labs.eu/

[Karl Nilsson]

The timestamp (the erlang interpretation of the system time in milliseconds) is there to allow readers to attach at an approximate time in the log, nothing else really. It is not guaranteed to be monotonic.

Use the offset for de-duplication during processing. RabbitMQ does not interpret the creation time property so you can set that as you like.

Cheers

Karl

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.

To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/ZulOnzKNKog97ZPp%40greymatter.

--

Karl Nilsson

[Jonathon L]

Thank you all for the replies.

@Gabriele, will do, thank you.

@Karl, are you saying that the timestamp provided by the client library should be in Milliseconds? (I'll confirm over on the rabbitmq-stream-go-client discussion board).

[Jonathon L]

I updated my tests to use a millisecond value for the OffsetSpecification.Timestamp() API and it worked as expected.

Output from publishing ten messages with 1 second delay between each:

MsgId: 0, CreationTime: 2024-09-17 17:33:18.952744024 +0000 UTC, 1726594398952
MsgId: 1, CreationTime: 2024-09-17 17:33:19.952920607 +0000 UTC, 1726594399952
MsgId: 2, CreationTime: 2024-09-17 17:33:20.954221535 +0000 UTC, 1726594400954
MsgId: 3, CreationTime: 2024-09-17 17:33:21.954620248 +0000 UTC, 1726594401954
MsgId: 4, CreationTime: 2024-09-17 17:33:22.955506095 +0000 UTC, 1726594402955
MsgId: 5, CreationTime: 2024-09-17 17:33:23.956158253 +0000 UTC, 1726594403956
MsgId: 6, CreationTime: 2024-09-17 17:33:24.956541401 +0000 UTC, 1726594404956
MsgId: 7, CreationTime: 2024-09-17 17:33:25.957654936 +0000 UTC, 1726594405957
MsgId: 8, CreationTime: 2024-09-17 17:33:26.95877349 +0000 UTC,  1726594406958
MsgId: 9, CreationTime: 2024-09-17 17:33:27.960295693 +0000 UTC, 1726594407960

Then output from my consumer starting at 10 milliseconds before message 4 and reading the rest of the stream (1726594402945):

data:      event-4, offset: 4
timestamp: 2024-09-17 17:33:22.955 +0000 UTC, unix: 1726594402955
data:      event-5, offset: 5
timestamp: 2024-09-17 17:33:23.956 +0000 UTC, unix: 1726594403956
data:      event-6, offset: 6
timestamp: 2024-09-17 17:33:24.956 +0000 UTC, unix: 1726594404956
data:      event-7, offset: 7
timestamp: 2024-09-17 17:33:25.957 +0000 UTC, unix: 1726594405957
data:      event-8, offset: 8
timestamp: 2024-09-17 17:33:26.958 +0000 UTC, unix: 1726594406958
data:      event-9, offset: 9
timestamp: 2024-09-17 17:33:27.96 +0000 UTC,  unix: 1726594407960