Compile error from scout when instrumenting code that uses numbered parameters in blocks

[DanielJoyce]

Ruby 2.7
scout_apm (2.6.7)

Deploying to our dev env k8s instance on GCP, the pods are crashing, investigating I found the following in the logs:

2020-05-05 14:14:51.302 PDT
/usr/local/bundle/gems/scout_apm-2.6.7/lib/scout_apm/auto_instrument/instruction_sequence.rb:11:in `compile': /app/app/controllers/live_data_controller.rb:32: syntax error, unexpected '{', expecting `then' or ';' or '\\n' (SyntaxError)
Error
2020-05-05 14:14:51.302 PDT
...ert'"]){singular_values.all?} { ::ScoutApm::AutoInstrument("...
Error
2020-05-05 14:14:51.302 PDT
... ^
Error
2020-05-05 14:14:51.302 PDT
/app/app/controllers/live_data_controller.rb:32: syntax error, unexpected '}', expecting `end'
Error
2020-05-05 14:14:51.302 PDT
...in `upsert'"]){_1.point.raw?} }
Error
2020-05-05 14:14:51.302 PDT
... ^
Error
2020-05-05 14:14:51.302 PDT
/app/app/controllers/live_data_controller.rb:67: syntax error, unexpected `end', expecting end-of-input

Apparently this code is tripping it up:

    unless singular_values.all? { _1.point.raw? }
      point_ids = singular_values.reject { _1.point.raw? }.map(&:id).to_sentence
      message = "The following points are not raw: #{ point_ids }. You can only upsert " \
        "live values for raw points."

      return render json: { message: message }, status: :unprocessable_entity
    end

If scount is trying to inject this code { ::ScoutApm::AutoInstrument("... after the .all? { _1.point.raw? } all block, I think it needs a newline

Something like

   unless singular_values.all? { _1.point.raw? }
      { ::ScoutApm::AutoInstrument("...")}
      point_ids = singular_values.reject { _1.point.raw? }.map(&:id).to_sentence
      message = "The following points are not raw: #{ point_ids }. You can only upsert " \
        "live values for raw points."

      return render json: { message: message }, status: :unprocessable_entity
    end

[dlanderson]

Thanks for the report @DanielJoyce - we'll investigate. To confirm, you explicitly enabled AutoInstruments via config setting, correct?

[DanielJoyce]

Well when we view tracing info on the website, it shows the percent of time spent in auto-instrumented code. We use the default settings.

# This configuration file is used for Scout APM.
common: &defaults
  monitor: true

# TODO: The name needs to be split between development and production.
production:
  <<: *defaults

development:
  <<: *defaults
  monitor: false

test:
  <<: *defaults
  monitor: false

So its whatever the default settings do.

[DanielJoyce]

It looks like auto_instrument defaults to false, so I don't know what it is doing then...

From the docs:

auto_instruments	Instrument custom code with AutoInstruments.	false

[dlanderson]

Can you check to see if it's being enabled in your environment variables? It would be SCOUT_AUTO_INSTRUMENTS=true

[DanielJoyce]

It looks like we turn it on programmatically.

ScoutApm::Context.add({ station: data_query_context.queried_points.first.station.id })

By adding this line to various code paths

[dlanderson]

Hrm, this wouldn't turn on the AutoInstruments feature. This is just attaching pieces of data to the detailed traces we collect.

It looks like we turn it on programmatically.

ScoutApm::Context.add({ station: data_query_context.queried_points.first.station.id })

I'm not having any luck reproducing the compile error on Ruby 2.7 with the same code. Would it be possible to share the entire method code where this unless block is used? You can send to [email protected] instead of here if you prefer.

[DanielJoyce]

Okay, yes, it looks like we do have it turned on via the env var.

[DanielJoyce]

I just added SCOUT_AUTO_INSTRUMENTS=true before running our tests, and seeing errors in the exact same spot

SyntaxError:
        /home/danieljoyce/git/tesla/projects/tesla-site/app/controllers/live_data_controller.rb:33: syntax error, unexpected '{', expecting `then' or ';' or '\n'
        ...ert'"]){singular_values.all?} { ::ScoutApm::AutoInstrument("...
        ...                              ^
        /home/danieljoyce/git/tesla/projects/tesla-site/app/controllers/live_data_controller.rb:33: syntax error, unexpected '}', expecting `end'
        ...in `upsert'"]){_1.point.raw?} }
        ...                              ^
        /home/danieljoyce/git/tesla/projects/tesla-site/app/controllers/live_data_controller.rb:68: syntax error, unexpected `end', expecting end-of-input
      # ./app/controllers/live_data_controller.rb:33: syntax error, unexpected '{', expecting `then' or ';' or '\n'
      # ...ert'"]){singular_values.all?} { ::ScoutApm::AutoInstrument("...
      # ...                              ^
      # ./app/controllers/live_data_controller.rb:33: syntax error, unexpected '}', expecting `end'
      # ...in `upsert'"]){_1.point.raw?} }
      # ...                              ^
      # ./app/controllers/live_data_controller.rb:68: syntax error, unexpected `end', expecting end-of-input
      # ./spec/requests/live_data_spec.rb:35:in `block (4 levels) in <main>'

Bit clearer than the GCP logs. I will see what needs to be done on our end to get more info

[DanielJoyce]

Producing minimal test case...

[DanielJoyce]

So it appears what is going is scout is trying to insert a call here

unless singular_values.all? { _1.point.raw? }

producing

ert'"]){singular_values.all?} { ::ScoutApm::AutoInstrument("...

The argument to all? is getting displaced.

[DanielJoyce]

Hmm, the use of _1 in the block call to all? seems to be what is tripping it up.

[DanielJoyce]

This works

    unless singular_values.all? { |singular_value| singular_value.point.raw? }
      point_ids = singular_values.reject { _1.point.raw? }.map(&:id).to_sentence
      message = "The following points are not raw: #{ point_ids }. You can only upsert " \
        "live values for raw points."

      return render json: { message: message }, status: :unprocessable_entity
    end

This doesn't

    unless singular_values.all? { _1.point.raw? }
      point_ids = singular_values.reject { _1.point.raw? }.map(&:id).to_sentence
      message = "The following points are not raw: #{ point_ids }. You can only upsert " \
        "live values for raw points."

      return render json: { message: message }, status: :unprocessable_entity
    end

producing:

SyntaxError:
        /home/danieljoyce/git/tesla/projects/tesla-site/app/controllers/live_data_controller.rb:34: syntax error, unexpected '{', expecting `then' or ';' or '\n'
        ...ert'"]){singular_values.all?} { ::ScoutApm::AutoInstrument("...
        ...                              ^
        /home/danieljoyce/git/tesla/projects/tesla-site/app/controllers/live_data_controller.rb:34: syntax error, unexpected '}', expecting `end'
        ...in `upsert'"]){_1.point.raw?} }
        ...                              ^
        /home/danieljoyce/git/tesla/projects/tesla-site/app/controllers/live_data_controller.rb:69: syntax error, unexpected `end', expecting end-of-input
      # ./app/controllers/live_data_controller.rb:34: syntax error, unexpected '{', expecting `then' or ';' or '\n'
      # ...ert'"]){singular_values.all?} { ::ScoutApm::AutoInstrument("...
      # ...                              ^
      # ./app/controllers/live_data_controller.rb:34: syntax error, unexpected '}', expecting `end'
      # ...in `upsert'"]){_1.point.raw?} }
      # ...                              ^
      # ./app/controllers/live_data_controller.rb:69: syntax error, unexpected `end', expecting end-of-input
      # ./spec/requests/live_data_spec.rb:148:in `block (4 levels) in <main>'

Ruby 2.7 supports new syntax for block arguments, letting you access them by argument number instead of having to name them. It appears auto-instrument doesn't support this new syntax.

It appears auto instrumentation trips up on blocks in 2.7 using numbered parameters.

https://prathamesh.tech/2019/12/25/all-you-need-to-know-about-ruby-2-7/#numbered-parameters

[dlanderson]

Can you let me know what version of parser and ast is in your Gemfile.lock?

I can't reproduce with parser =2.5.0.3 and ast = 2.4.0 as seen in this gist. These are the gems we rely on to parse the ruby AST correctly and identify the type of AST nodes where we can insert our instrumentation . If these don't understand the new Ruby 2.7 syntax that might be the issue.

[DanielJoyce]

parser 2.7.1.2, and ast 2.4.0

[DanielJoyce]

https://rubygems.org/gems/ast/versions/2.4.0

VERSIONS:
2.4.0 - January 25, 2018 (15 KB)
2.3.0 - June 07, 2016 (14.5 KB)
2.2.0 - December 19, 2015 (14.5 KB)
2.1.0 - August 03, 2015 (14.5 KB)
2.0.0 - April 21, 2014 (14 KB)

ast 2.4.0 came out in 2018, so I don't think it understands ruby 2.7.0

https://github.com/whitequark/ast

ooof, no commits in 2 years.

[dlanderson]

I ran through versions of parser and it looks like a bug was introduced in 2.7.0.0. Can you pin your parser version to 2.6.4.1? In Gemfile:

gem 'parser', '= 2.6.4.1'

[DanielJoyce]

I saw the gist, was the code then actually compiled after that?

Because, then ruby says:

SyntaxError:
        /home/danieljoyce/git/tesla/projects/tesla-site/app/controllers/live_data_controller.rb:34: syntax error, unexpected '{', expecting `then' or ';' or '\n'
        ...ert'"]){singular_values.all?} { ::ScoutApm::AutoInstrument("...
        ...                              ^
        /home/danieljoyce/git/tesla/projects/tesla-site/app/controllers/live_data_controller.rb:34: syntax error, unexpected '}', expecting `end'
        ...in `upsert'"]){_1.point.raw?} }
        ...                              ^
        /home/danieljoyce/git/tesla/projects/tesla-site/app/controllers/live_data_controller.rb:69: syntax error, unexpected `end', expecting end-of-input

[DanielJoyce]

Will try that.

[DanielJoyce]

We have a dependency on sorbet-rails which locks parser to >= 2.7 :P

[DanielJoyce]

Yeah, the code in errors I am getting is different than the generated code in your gist

My errors show a piece like:

...ert'"]){singular_values.all?} { ::ScoutApm::AutoInstrument("...

A block is added after the all? in a weird manner.

Your gist shows

strument/all.rb:3:in check_points'"]){singular_values.all? { _1.point.raw? }}`

Maybe I downgrade sorbet...

[DanielJoyce]

We forced an upgrade in sorbet to remove ruby 2.7 warnings which caused a cascading upgrade of a bunch of other packages which then, appears to break scout.

In dependency hell now. But everything seems to break if we upgrade other packages for better ruby 2.7.0 compatibility. And they force a upgrade of parser to >= 2.7

Working on it.

[DanielJoyce]

I'm having no luck "going back in time", scout worked for us in the past, some point in the last few days, an upgrade occured to some package, and has broken scout's instrumentation. Still trying to narrow it down.

[dlanderson]

@DanielJoyce I'd recommend just leaving AutoInstruments turned off until we can reconcile the behavior of parser >= 2.7.0.0. Just unset SCOUT_AUTO_INSTRUMENTS env var and restart your app servers.

AutoInstruments is just one small part of what we capture in detailed traces. You'll still have tons of functionality without it - https://docs.scoutapm.com/#autoinstruments

[DanielJoyce]

Yeah, so we are on parser 2.7.1.2 with no easy way to go back to 2.6

Here are some cases we cooked up

    # works
    pp singular_values.all? { |_1| _1.point.raw? }
    # works
    pp "derp" if singular_values.all? { |_1| _1.point.nil? }
    # breaks
    pp "derp" if singular_values.all? { _1.point.raw? }
    # breaks
    pp "derp" if singular_values.all? { _1.point.type == "raw" }
    # breaks
    pp "derp" if singular_values.all? { _1.point.nil? }

The isssue seems to be a numbered block parameter using a predicate method nested in a all? which is then used as part of a boolean check. The issue likely does exist in parser then.

[DanielJoyce]

irb(main):004:1' Parser::CurrentRuby.parse('unless [nil,nil,1].all? { _1.nil? }
irb(main):005:1'   pp "derp"
irb(main):006:0>     end')
=> s(:if,
  s(:numblock,
    s(:send,
      s(:array,
        s(:nil),
        s(:nil),
        s(:int, 1)), :all?), 1,
    s(:send,
      s(:lvar, :_1), :nil?)), nil,
  s(:send, nil, :pp,
    s(:str, "derp")))
irb(main):007:1' Parser::CurrentRuby.parse('unless [nil,nil,1].all? { |_1| _1.nil? }
irb(main):008:1'   pp "derp"
irb(main):009:0>     end')
=> s(:if,
  s(:block,
    s(:send,
      s(:array,
        s(:nil),
        s(:nil),
        s(:int, 1)), :all?),
    s(:args,
      s(:arg, :_1)),
    s(:send,
      s(:lvar, :_1), :nil?)), nil,
  s(:send, nil, :pp,
    s(:str, "derp")))

This looks sensible, maybe?

[Masa331]

This same thing now also breaks in my app on ruby 3.0.1, parser 3.0.1.1 and ast 2.4.2. Also this singular_values.all? { |_1| _1.point.nil? } no longer works in Ruby > 3 bc it starts to throw SyntaxError itself

[wilg]

I'm having this issue too: looks like #401 was actually a dupe of this.