Job fails when turbo_rails sends an empty string in the argument list

Question

Job fails when turbo_rails sends an empty string in the argument list

Closed this issue 3 months ago · 12 comments

I have a turbo_rails model booking.rb which has

broadcasts_refreshes_to :jump

This enqueues a job with the following raw data:

  {
  "id": 26,
  "queue_name": "default",
  "class_name": "Turbo::Streams::BroadcastStreamJob",
  "arguments": {
    "job_class": "Turbo::Streams::BroadcastStreamJob",
    "job_id": "ec0afdd3-0c15-42e0-a174-91c0e8c2c852",
    "provider_job_id": null,
    "queue_name": "default",
    "priority": null,
    "arguments": [
      "",
      {
        "content": "<turbo-stream action=\"refresh\"></turbo-stream>",
        "_aj_ruby2_keywords": [
          "content"
        ]
      }
    ],
    "executions": 0,
    "exception_executions": {
    },
    "locale": "en",
    "timezone": "UTC",
    "enqueued_at": "2024-04-10T11:12:48.383565000Z",
    "scheduled_at": "2024-04-10T11:12:48.383452000Z"
  },
  "priority": 0,
  "active_job_id": "ec0afdd3-0c15-42e0-a174-91c0e8c2c852",
  "scheduled_at": "2024-04-10T12:12:48.383+01:00",
  "finished_at": null,
  "concurrency_key": null,
  "created_at": "2024-04-10T12:12:48.383+01:00",
  "updated_at": "2024-04-10T12:12:48.383+01:00"
}

The job then fails with:

Message	ERROR: zero-length delimited identifier at or near """" LINE 1: NOTIFY "", '"\u003cturbo-stream action=\"refresh\"\u003e\u00... ^
/Users/rob/.rvm/gems/ruby-3.3.0/gems/actioncable-enhanced-postgresql-adapter-1.0.1/lib/action_cable/subscription_adapter/enhanced_postgresql.rb:56:in `exec'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/actioncable-enhanced-postgresql-adapter-1.0.1/lib/action_cable/subscription_adapter/enhanced_postgresql.rb:56:in `block in broadcast'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/actioncable-7.1.3.2/lib/action_cable/subscription_adapter/postgresql.rb:54:in `block in with_broadcast_connection'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/activerecord-7.1.3.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:227:in `with_connection'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/actioncable-7.1.3.2/lib/action_cable/subscription_adapter/postgresql.rb:51:in `with_broadcast_connection'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/actioncable-enhanced-postgresql-adapter-1.0.1/lib/action_cable/subscription_adapter/enhanced_postgresql.rb:74:in `with_broadcast_connection'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/actioncable-enhanced-postgresql-adapter-1.0.1/lib/action_cable/subscription_adapter/enhanced_postgresql.rb:39:in `broadcast'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/actioncable-7.1.3.2/lib/action_cable/server/broadcasting.rb:50:in `block in broadcast'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/activesupport-7.1.3.2/lib/active_support/notifications.rb:206:in `block in instrument'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/activesupport-7.1.3.2/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/activesupport-7.1.3.2/lib/active_support/notifications.rb:206:in `instrument'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/actioncable-7.1.3.2/lib/action_cable/server/broadcasting.rb:48:in `broadcast'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/actioncable-7.1.3.2/lib/action_cable/server/broadcasting.rb:27:in `broadcast'
/Users/rob/.rvm/gems/ruby-3.3.0/gems/turbo-rails-2.0.5/app/channels/turbo/streams/broadcasts.rb:91:in `broadcast_stream_to'

I assume this is related to the empty string

    "arguments": [
here=>      "",
      {

fwiw: The same job runs ok on sidekiq

--

Rails 7.1.3
Solid Queue: 0.3.0

Answer 1 · 2024-04-11T12:45:01.000Z

Hey @ConfusedVorlon, I'll look into this one. It's very strange, as Solid Queue doesn't do anything special with job arguments. It relies on Active Job's serialize method to store them and on Active Job's execute method to deserialize and run it 🤔 The job arguments are completely opaque to Solid Queue.

In any case, I'll investigate and might ask more questions.

Answer 2 · 2024-04-11T12:56:15.000Z

@ConfusedVorlon, when you run this with Sidekiq, could you log and share what the parameters look like?

Answer 3 · 2024-04-11T14:26:42.000Z

Many thanks for looking at this :)

Job: Turbo::Streams::BroadcastStreamJob
Arguments: "", {"content"=>"<turbo-stream action=\"refresh\"></turbo-stream>"}

so, it does have that empty argument.

Answer 4 · 2024-04-11T14:37:05.000Z

Looking at this though - it seems wrong that there is no identifier for the refresh.
It wasn't so obvious with the other content in the solid queue case.
Digging in now to see what/if I'm doing wrong...

Answer 5 · 2024-04-11T14:37:56.000Z

Thank you! I suspect that's the deserialized version of the arguments, though 🤔 Because Active Job needs to distinguish between Ruby kwargs (_aj_ruby2_keywords) and symbol keys (_aj_symbol_keys), and there you just have:

{"content"=>"<turbo-stream action=\"refresh\"></turbo-stream>"}

My suspicion is that Sidekiq is doing something to the empty string before executing the job so that it doesn't fail. The thing is that having an empty string there seems wrong, because that'd be the channel you're broadcasting to 😕 I'm not sure how this can work with Sidekiq. When you're using Sidekiq, do you see the messages being broadcasted at all?

Answer 6 · 2024-04-11T14:50:24.000Z

not sure what sidekiq is doing. I'm just reading args from the sidekiq web interface.
happy to dig elsewhere if you can point me in the right direction.

I figured out what the trigger is though - jump is an optional association, and in this case it is nil.

So - I'm guessing roughly: turbo_rails is calling booking.jump, finding nil and generating an identifier from that which is an empty string.

I think I can work around this with an after_update_commit that checks before broadcasting.

It feels like this is probably something where turbo_rails could just help me out and not broadcast to a nil association.

I have no idea what the correct behaviour ought to be for solid_queue...

Answer 7 · 2024-04-11T15:06:10.000Z

little more info - I was confusing this broadcast with a different one.

So - I thought it was doing a job that was being done elsewhere. Obviously in fact it is a non-job.

Nonetheless, sidekiq does seem to be behaving as if it is performing the job for whatever that's worth...

web               | [ActiveJob] Enqueued Turbo::Streams::BroadcastStreamJob (Job ID: a54de5b5-2eb2-46b4-92fc-92cf60c19aee) to Sidekiq(default) with arguments: "", {:content=>"<turbo-stream action=\"refresh\"></turbo-stream>"}
worker            | 2024-04-11T15:02:28.868Z pid=73365 tid=27it class=Turbo::Streams::BroadcastStreamJob jid=467375c301c89d35ed714e79 INFO: start
worker            | 2024-04-11T15:02:28.909Z pid=73365 tid=27it class=Turbo::Streams::BroadcastStreamJob jid=467375c301c89d35ed714e79 INFO: Performing Turbo::Streams::BroadcastStreamJob (Job ID: a54de5b5-2eb2-46b4-92fc-92cf60c19aee) from Sidekiq(default) enqueued at 2024-04-11T15:02:28.867699000Z with arguments: "", {:content=>"<turbo-stream action=\"refresh\"></turbo-stream>"}
worker            | 2024-04-11T15:02:28.909Z pid=73365 tid=27it class=Turbo::Streams::BroadcastStreamJob jid=467375c301c89d35ed714e79 INFO: Performed Turbo::Streams::BroadcastStreamJob (Job ID: a54de5b5-2eb2-46b4-92fc-92cf60c19aee) from Sidekiq(default) in 0.96ms
worker            | 2024-04-11T15:02:28.910Z pid=73365 tid=27it class=Turbo::Streams::BroadcastStreamJob jid=467375c301c89d35ed714e79 elapsed=0.041 INFO: done

Answer 8 · 2024-04-11T15:20:29.000Z

Aha! That's very useful.

not sure what sidekiq is doing. I'm just reading args from the sidekiq web interface.

Ahh got it! Yes, that'd be the deserialized arguments. It's ok, don't worry about that.

It feels like this is probably something where turbo_rails could just help me out and not broadcast to a nil association.

Yes, I agree! Maybe it's better to reopen the issue you opened in the turbo-rails repo and add this info 🤔

I have no idea what the correct behaviour ought to be for solid_queue...

I think the right behaviour is the one you're getting, since for Solid Queue the job and its arguments are a sort of a black box, and doesn't have any influence on why the job might be failing here (an empty string passed to the PostgreSQL cable adapter). However, that's also true for Sidekiq, and this:

Nonetheless, sidekiq does seem to be behaving as if it is performing the job for whatever that's worth...

worker            | 2024-04-11T15:02:28.909Z pid=73365 tid=27it class=Turbo::Streams::BroadcastStreamJob jid=467375c301c89d35ed714e79 INFO: Performing Turbo::Streams::BroadcastStreamJob (Job ID: a54de5b5-2eb2-46b4-92fc-92cf60c19aee) from Sidekiq(default) enqueued at 2024-04-11T15:02:28.867699000Z with arguments: "", {:content=>"<turbo-stream action=\"refresh\"></turbo-stream>"}
worker            | 2024-04-11T15:02:28.909Z pid=73365 tid=27it class=Turbo::Streams::BroadcastStreamJob jid=467375c301c89d35ed714e79 INFO: Performed Turbo::Streams::BroadcastStreamJob (Job ID: a54de5b5-2eb2-46b4-92fc-92cf60c19aee) from Sidekiq(default) in 0.96ms

is certainly strange! Is it possible the error isn't being surfaced here, and the job is somehow ending at Sidekiq's Dead set? My Sidekiq experience is very limited, as I only used it in production about 7 years ago, but I know there are multiple ways you can handle errors in Sidekiq. Is it possible the failure is being silenced somehow?

Answer 9 · 2024-04-11T15:52:11.000Z

Thank you so much for your help here. It's really appreciated.

I'll definitely open a turbo_rails issue. Not exactly sure where is best to catch this or I'd send a PR.

As far as I can tell, Sidekiq really does think that it is processing the job. It isn't incrementing the failed count - it would retry by default and keep the job around. It certainly does that with other broadcast jobs - but I haven't dug deeply enough to be 100% sure.

My suspicion is that it just carries on regardless. The empty argument seems to be a postgres specific complaint, and sidekiq isn't going anywhere near that, so I assume it just doesn't care.

I do have a slight spidey-sense, where I do wonder if solid_queue should behave differently.

Digging a bit deeper, the job is enqueued here:

https://github.com/hotwired/turbo-rails/blob/6a60eb4f72d2e834f91279b0a6f95be411ae6174/app/channels/turbo/streams/broadcasts.rb#L71

  def broadcast_refresh_later_to(*streamables, request_id: Turbo.current_request_id, **opts)
    refresh_debouncer_for(*streamables, request_id: request_id).debounce do
      Turbo::Streams::BroadcastStreamJob.perform_later stream_name_from(streamables), content: turbo_stream_refresh_tag(request_id: request_id, **opts)
    end
  end

streamables is [nil], so stream_name_from(streamables) is ""

In principle - there is nothing wrong with an empty string as an argument.

Should solid queue reject this ?

It seems like some postgres wierdness might be creeping in where it shouldn't....

Answer 10 · 2024-04-11T16:56:34.000Z

I should have done about three steps ago!

So - following through all the way to the actual job.

class Turbo::Streams::BroadcastStreamJob < ActiveJob::Base
  discard_on ActiveJob::DeserializationError

  def perform(stream, content:)
    binding.b
    Turbo::StreamsChannel.broadcast_stream_to(stream, content: content)
  end
end

sidekiq does indeed call this with stream == ""

Answer 11 · 2024-04-12T08:54:31.000Z

I figured I'd simplify things and just create my own job.
It works fine with empty string arguments.
So - presumably the postgres error is unrelated to solid queue.

@rosa Thank you for your help with this rabbit hole!

Answer 12 · 2024-04-12T11:04:00.000Z

Aha! Thanks a lot for digging into this! I agree with your findings, the error seems unrelated to Solid Queue 👍🏻
I hope you don't run into more problems! A change in turbo-rails to improve this scenario would certainly be welcome, I'm sure. Thanks again!