Manual ACKs are not being sent about stan.rb HOT 8 OPEN

@tuwukee , aside note: I am not sure you need to start new thread for each new incoming message. Each subscription is a separate thread already and hence you do client.ack(msg) after the message has been processed, there is no value in extra thread, because the message that is currently processing, will not be ack'ed until client.ack(msg) (until the whole processing will not exit).

from stan.rb.

@blelump thanks for the head ups.
As far as I understand each subscription is being run in its own thread but couldn't it receive multiple events which just get buffered awaiting for processing while I can simply execute handlers in parallel assuming that I have a lot of IO operations?

from stan.rb.

Another side note: when you say: But sometimes, when I restart the server, I see it starts to process events that I know were already processed before., yes, it is always a possibility. Do you know for sure that the server has processed and persisted the ACK for that message that you think should not have redelivered? NATS Streaming is at-least-once delivery, which means that there is a possibility that an application receives a message that it already received.

Granted, when the server processes an ACK it is less likely for that to happen but not impossible. For instance what also could happen is a server sending a message to an application. If that application does not ACK the message for the AckWait period, the server will resend it, and will do so until it receives an ACK for that message. Those resent messages may accumulate in the client's internal queue. Once the message is acknowledged, those already queued messages will still be delivered to the user callback. That is unless the client libraries (and I don't think any of the NATS Streaming clients do that so far) keep track of messages being acknowledged so that they can suppress those in the scenario I just described.

from stan.rb.

@kozlovic thanks for your reply.

Do you know for sure that the server has processed and persisted the ACK for that message that you think should not have redelivered?

Yes, I know for sure that the server has processed those events before, I can see them in the logs.
Default ACK wait period is 30 seconds, in my case event processing takes 1-3 seconds. Sometimes on server restart it receives events which it already processed and presumably ACKed hours ago.

from stan.rb.

Could you show excerpt of logs that show that? If that's the case, don't think this is a problem with the client (unless, like I said, there would have been an accumulation of resent messages in the client library).

from stan.rb.

Sure, here's the logs sample:

On start (already receives outdated events)

events_1  | timestamp='2018-10-08 20:04:24 +0300' level=INFO message='NATS connected'
events_1  | timestamp='2018-10-08 20:04:25 +0300' level=INFO message='[00e8c149-8d79-4e7a-9887-8c27970fac90] Received a message on queue subscription (seq: 879210): {"id":"302b9a7e-a00d-489e-bbfe-2be4ea11fd58","name":"us-west-2-test.event","subject":"us-west-2-test.event","data":{...},"urns":null,"timestamp":"2018-10-08T17:02:46.417738788Z","version":"v1","source":"storage-event-lambda"}. Process by Event::Subscriber::S3File'
events_1  | timestamp='2018-10-08 20:04:25 +0300' level=INFO message='Deleted S3 File, ignoring: ObjectRemoved:DeleteMarkerCreated'
events_1  | timestamp='2018-10-08 20:04:26 +0300' level=INFO message='[00e8c149-8d79-4e7a-9887-8c27970fac90] Received a message on queue subscription (seq: 92): {"id":"e6629f73-08eb-4f04-8d14-49e9275ca8c5","parentId":null,"name":"internal.s3-file.delete","subject":"internal.s3-file.delete","data":{...},"timestamp":"2018-10-08T16:39:19Z","urns":[],"version":"1"}. Process by Event::Subscriber::S3FileDelete'
events_1  | timestamp='2018-10-08 20:04:26 +0300' level=ERROR message='Message data has null, blank, or mismatching source. Ignoring.'

On restart (receives the same events, sequence, event ID and timestamp of the events are the same)

events_1  | timestamp='2018-10-08 20:05:42 +0300' level=INFO message='NATS connected'
events_1  | timestamp='2018-10-08 20:05:42 +0300' level=INFO message='[da13aab0-2a38-4dfa-aaf5-882d4e6702b1] Received a message on queue subscription (seq: 879210): {"id":"302b9a7e-a00d-489e-bbfe-2be4ea11fd58","name":"us-west-2-test.event","subject":"us-west-2-test.event","data":{...},"urns":null,"timestamp":"2018-10-08T17:02:46.417738788Z","version":"v1","source":"storage-event-lambda"}. Process by Event::Subscriber::S3File'
events_1  | timestamp='2018-10-08 20:05:42 +0300' level=INFO message='Deleted S3 File, ignoring: ObjectRemoved:DeleteMarkerCreated'
events_1  | timestamp='2018-10-08 20:05:43 +0300' level=INFO message='[da13aab0-2a38-4dfa-aaf5-882d4e6702b1] Received a message on queue subscription (seq: 92): {"id":"e6629f73-08eb-4f04-8d14-49e9275ca8c5","parentId":null,"name":"internal.s3-file.delete","subject":"internal.s3-file.delete","data":{ ... },"timestamp":"2018-10-08T16:39:19Z","urns":[],"version":"1"}. Process by Event::Subscriber::S3FileDelete'
events_1  | timestamp='2018-10-08 20:05:43 +0300' level=ERROR message='Message data has null, blank, or mismatching source. Ignoring.'

from stan.rb.

That's not NATS Streaming server log.. what I would want to see is a trace in the server log that shows that the ACK for a given message was received and then after a restart, the same message sequence is redelivered. (that requires server to be started with -SDV to be able to see those traces. If this is production and have a high throughput, this is not recommended since tracing is verbose and can slow down the server).

from stan.rb.

Cannot start production with -SDV option. I was trying to reproduce with a local NATS instance, but on local it seems to be working fine (as always).
Btw, regarding the restart - just to be clear, I was talking about the client-app restarts.
Is there a way in the gem to check the state of the client's internal queue?

from stan.rb.