Upgrade from 2.2.2 to 2.2.5 caused loss of event track calls

[platedbay]

Hi there,

We recently upgraded our rails application to use the most up to date version of the gem, 2.2.5, from 2.2.2. After some investigation on my end due to reports of events not being tracked properly, I discovered that reverting back to 2.2.2 has resolved the issues we were seeing. I wasn't able to determine specifically why this was occurring, just that controlling everything else and going back down to 2.2.2 meant our existing events were properly tracked.

Ruby version: 2.5.0
Rails version: 5.2.0

We noticed some pretty significant changes between these patch versions, so we were curious if there were any known issues or new ways things should be approached to properly identify users and track events? We haven't had to do much maintenance in that specific area, so we're a bit perplexed as to what could have happened.

Happy to provide any and more information to get to the bottom of this.

[f2prateek]

Hmm.. interesting - so far we haven't heard of this. 2.2.3.pre and 2.2.4.pre was in a pre-release state for 2 months and nobody had reported any issues.

Most of the changes were around bug fixes/improving existing retry behaviour, so if anything you should have expected to see better deliverability.
We also added end to end tests as part of these changes - so I wonder if this is an issue that only exhibits itself under heavy load.

Could you provide any other details - such as logs possibly? You can email us at friends@segment.com and cc prateek@segment.com

[coolnalu]

also seeing this.

[f2prateek]

Hey @rohitpaulk can you take a look using the version Ruby and rails @platedbay mentioned?

[f2prateek]

@platedbay @coolnalu can you make sure to set on_error handler as per https://segment.com/docs/sources/server/ruby/ and share some logs? We have an end to end test that verifies events are being received by Segment - https://github.com/segmentio/analytics-ruby/blob/master/spec/segment/analytics/e2e_spec.rb; so I'm wondering if this something to how you've setup your apps.

[UlyssesInvictus]

@f2prateek Nothing is being logged, so it appears as the failure is silent, without triggering any errors. I'm looking into it further.

[UlyssesInvictus]

Also, I can confirm, wrt

We also added end to end tests as part of these changes - so I wonder if this is an issue that only exhibits itself under heavy load.

That I can reproduce the error locally, on a tiny server, so it doesn't seem to be load based.

[f2prateek]

@UlyssesInvictus got it - if you are able to share a reproducible example, please do - or email us at friends@segment.com and cc prateek@segment.com if you want the code to be private!

[UlyssesInvictus]

Cool, @f2prateek ; unfortunately, I don't think we're actually doing anything very complicated in the Segment initializers themselves, so I suspect the actual issue is some conflict with other batching gems (or whatever it may be), so I'll have to get back to you later after I manage to spin up a new project and repro with a simpler gemset.

However, for now, here's the basic analytics code:

module Analytics
  Client = Segment::Analytics.new(
    write_key: SEGMENT_KEY,
    stub: Rails.env.test?,
    on_error: proc do |status, msg|
      Rails.logger.error "Segment call failed with status #{status}: #{msg}"
    end
  )
end

and then it's as simple as calling Analytics::Client.track(...) 🤷‍♂️ .

In fact, I've tried the following in console:

client = Segment::Analytics.new(write_key: SEGMENT_KEY)
client.track(user_id: "dummy user id", event: "SEGMENT TEST")
client.flush

and can confirm that the only way to get the event to log was to toggle between 2.2.5 and 2.2.2.

Later tomorrow, I'll see what code from our internal initializers/configs I can give you to help debug.

[rohitpaulk]

Tried a couple of things:

• Pushed an empty commit to ensure the e2e tests are working.
• Ran a test script similar to the above this inside a fresh Rails 2.5.0 app.
• Ran a quick load test by sending out 10k events from my machine and back via ngrok to a dummy server.

All of these seemed to work fine 😕

Out of ideas at the moment, but if this isn’t related to load like @UlyssesInvictus mentions - a Gemfile.lock + ruby version could got a long way in helping debug this better :)

[f2prateek]

Thanks @rohitpaulk! I also did a sanity check with the empty commit, as well as pushed a commit that doesn't call flush and only relies on the max_queue_size flag (https://github.com/segmentio/analytics-ruby/compare/prateek/test), which also passed the end to end test https://travis-ci.org/segmentio/analytics-ruby/builds/378872966. This also verifies that this doesn't come out of a bug due to any potential changes in the way we process events after it hits api.segment.io.

It does seem likely that this may be specific to the way some apps are setup (possibly a dependency conflict as @UlyssesInvictus suggested), as I am seeing customers successfully sending events with 2.2.5 of the library.

[platedbay]

Thanks for looking into all of this folks. I just emailed the emails above with our Gemfile.lock. Hopefully it helps.

Also, I do want to clarify that we were still seeing events being fired, just not ALL of them, which made it even more confusing.

[rohitpaulk]

I just emailed the emails above with our Gemfile.lock. Hopefully it helps.

Thanks :) I tried running this with the gems in the provided Gemfile.lock, but wasn't able to trigger the bug.

Also, I do want to clarify that we were still seeing events being fired, just not ALL of them, which made it even more confusing.

@platedbay: Are there any patterns to this? Do you see the same events being dropped every time?

[rohitpaulk]

I've opened a PR to improve our logs so that we can understand these failures better. The current logs we have aren't exhaustive enough. I'll post an update here once that is merged.

[rohitpaulk]

The logging PR has now been merged. All logs from the library will be prefixed with [analytics-ruby], so they should be easy to search for.

@platedbay, @UlyssesInvictus, @coolnalu: If possible, could you try running the latest master for a while and capture logs? We're particularly interested in logs like 'Retrying request', or 'message has exceeded size limit'.

gem "analytics-ruby", :git => "https://github.com/segmentio/analytics-ruby.git", :branch => "master"

Also, please make sure that the Rails logger is configured to emit debug messages. ref

Rails.logger.level = 0

Here's a screenshot of how the logs look on a fresh rails app: