search

getappmap / appmap-ruby

AppMap client agent for Ruby
https://appland.org
Other
100 stars 13 forks source link

With AppMap gem enabled some tests will fail and others will fail as a group #301

Closed petecheslock closed 1 year ago

petecheslock commented 1 year ago

Steps to reproduce the problem

  1. Clone the latest 4.x release tag for Mastodon (v4.0.2 is the latest i've tried) from forked version
  2. Setup the environment with an updated docker compose
  3. Source environment variables to setup dev environment source .env-rspec
  4. Set custom webpacker.yml to support running rspec locally.
  5. Run webpack RAILS_ENV=test ./bin/webpack
  6. Run tests RAILS_ENV=test bundle exec rspec

Expected behaviour

Tests that fail togeather fail individually and tests that pass together pass individually

Actual behaviour

Tests that failed when running as a group will pass when running individually

Detailed description

While working on some Mastodon tutorial content for onboarding new engineers I ran across a problem where running all the rspec tests will have a series of about 54 tests fail - it does not seem like the same group of tests each time although I'm going to do a few more tests to confirm.

For example - when running RAILS_ENV=test bundle exec rspec I'll get the following error:

 621) ActivityPub::RepliesController GET #index with signature behaves like allowed access when status is public behaves like cacheable response returns public Cache-Control header
       Failure/Error: object.active_mentions.to_a.sort_by(&:id) + object.tags + object.emojis

       TypeError:
         no implicit conversion of nil into String
       Shared Example Group: "cacheable response" called from ./spec/controllers/activitypub/replies_controller_spec.rb:96
       Shared Example Group: "allowed access" called from ./spec/controllers/activitypub/replies_controller_spec.rb:193
       # ./app/serializers/activitypub/note_serializer.rb:116:in `+'
       # ./app/serializers/activitypub/note_serializer.rb:116:in `virtual_tags'
       # ./app/lib/activitypub/serializer.rb:36:in `serializable_hash'
       # ./app/lib/activitypub/serializer.rb:36:in `serializable_hash'
       # ./app/lib/activitypub/adapter.rb:19:in `serializable_hash'
       # ./app/controllers/activitypub/replies_controller.rb:17:in `index'
       # ./spec/controllers/activitypub/replies_controller_spec.rb:183:in `block (3 levels) in <top (required)>'
       # ./spec/controllers/activitypub/replies_controller_spec.rb:23:in `block (3 levels) in <top (required)>'

       rspec './spec/controllers/activitypub/replies_controller_spec.rb[1:1:2:1:3:3:3]' # ActivityPub::RepliesController GET #index with signature behaves like allowed access when status is public behaves like cacheable response returns public Cache-Control header

But when I run this test by itself it will pass.

$ RAILS_ENV=test bundle exec rspec ./spec/controllers/activitypub/replies_controller_spec.rb                                                                                     INT ✘  3.0.4   13:29:51  

Randomized with seed 23157
warning: tag 'v0.1.2' is externally known as '0.1.2'                                                                                                                                                                                         |  ETA: ??:??:?? 
 40/40 |=============================================================================================================== 100 ================================================================================================================>| Time: 00:00:19 

Finished in 20 seconds (files took 3.48 seconds to load)
40 examples, 0 failures

Randomized with seed 23157

When looking at all the failed tests after a full run will show 79 failures

$ cat tmp/rspec/examples.txt  | grep failed | sed 's/\[.*//g' | uniq | wc -l    
79

When iterating thru the list and re-running individually many will succeed. 

$ for i in `cat tmp/rspec/examples.txt  | grep failed | sed 's/\[.*//g' | uniq`;do RAILS_ENV=test bundle exec rspec $i;done

<tests run>

cat tmp/rspec/examples.txt  | grep failed | sed 's/\[.*//g' | uniq | wc -l
28

A list of the tests that are failed after running together: test-failed-with-appmap.txt

kgilpin commented 1 year ago

@petecheslock can you report which test runs right before the tests start failing? Because can infer it’s something in that test that’s causing the failures. Especially if it’s always the same one.

petecheslock commented 1 year ago

Playing around with this - here is one example of a simple "test fails when appmap enabled - passes when disabled"

The test at this ref: https://github.com/land-of-apps/mastodon/blob/95b1facd7/spec/controllers/accounts_controller_spec.rb

RAILS_ENV=test APPMAP=false bundle exec rspec './spec/controllers/accounts_controller_spec.rb[1:1:2:5:4]' --seed 12345
Run options: include {:ids=>{"./spec/controllers/accounts_controller_spec.rb"=>["1:1:2:5:4"]}}                                              

Randomized with seed 12345
 1/1 |======================================================= 100 ========================================================>| Time: 00:00:02 

Finished in 2.05 seconds (files took 2.02 seconds to load)
1 example, 0 failures

Randomized with seed 12345
    ~/r/mastodon    appmap-v4 !6 ?1  RAILS_ENV=test APPMAP=true bundle exec rspec './spec/controllers/accounts_controller_spec.rb[1:1:2:5:4]' --seed 12345
Run options: include {:ids=>{"./spec/controllers/accounts_controller_spec.rb"=>["1:1:2:5:4"]}}                                              

Randomized with seed 12345

  1) AccountsController GET #show as JSON when signed in renders account
     Failure/Error: object.suspended? ? [] : (object.emojis + object.tags)

     TypeError:
       no implicit conversion of nil into String
     # ./app/serializers/activitypub/actor_serializer.rb:142:in `+'
     # ./app/serializers/activitypub/actor_serializer.rb:142:in `virtual_tags'
     # ./app/lib/activitypub/serializer.rb:36:in `serializable_hash'
     # ./app/lib/activitypub/adapter.rb:19:in `serializable_hash'
     # ./app/controllers/concerns/cache_concern.rb:22:in `render_with_cache'
     # ./app/controllers/accounts_controller.rb:32:in `block (2 levels) in show'
     # ./app/controllers/accounts_controller.rb:17:in `show'
     # ./spec/controllers/accounts_controller_spec.rb:204:in `block (5 levels) in <top (required)>'

 1/1 |======================================================= 100 ========================================================>| Time: 00:00:02 

Finished in 2.67 seconds (files took 2.58 seconds to load)
1 example, 1 failure

Failed examples:

rspec './spec/controllers/accounts_controller_spec.rb[1:1:2:5:4]' # AccountsController GET #show as JSON when signed in renders account

Randomized with seed 12345

Currently using a default appmap.yml. 

---
name: mastodon
language: ruby
appmap_dir: tmp/appmap
packages:
- path: app
- path: lib
kgilpin commented 1 year ago

Hi Pete, I am working on this. This is the same bug as before.

On Tue, Dec 13, 2022 at 1:19 PM Pete Cheslock @.***> wrote:

Playing around with this - here is one example of a simple "test fails when appmap enabled - passes when disabled"

The test at this ref: https://github.com/land-of-apps/mastodon/blob/95b1facd7/spec/controllers/accounts_controller_spec.rb

RAILS_ENV=test APPMAP=false bundle exec rspec './spec/controllers/accounts_controller_spec.rb[1:1:2:5:4]' --seed 12345

Run options: include {:ids=>{"./spec/controllers/accounts_controller_spec.rb"=>["1:1:2:5:4"]}}

Randomized with seed 12345

1/1 |======================================================= 100 ========================================================>| Time: 00:00:02

Finished in 2.05 seconds (files took 2.02 seconds to load)

1 example, 0 failures

Randomized with seed 12345

   ~/r/mastodon    appmap-v4 !6 ?1  RAILS_ENV=test APPMAP=true bundle exec rspec './spec/controllers/accounts_controller_spec.rb[1:1:2:5:4]' --seed 12345

Run options: include {:ids=>{"./spec/controllers/accounts_controller_spec.rb"=>["1:1:2:5:4"]}}

Randomized with seed 12345

1) AccountsController GET #show as JSON when signed in renders account

 Failure/Error: object.suspended? ? [] : (object.emojis + object.tags)

 TypeError:

   no implicit conversion of nil into String

 # ./app/serializers/activitypub/actor_serializer.rb:142:in `+'

 # ./app/serializers/activitypub/actor_serializer.rb:142:in `virtual_tags'

 # ./app/lib/activitypub/serializer.rb:36:in `serializable_hash'

 # ./app/lib/activitypub/adapter.rb:19:in `serializable_hash'

 # ./app/controllers/concerns/cache_concern.rb:22:in `render_with_cache'

 # ./app/controllers/accounts_controller.rb:32:in `block (2 levels) in show'

 # ./app/controllers/accounts_controller.rb:17:in `show'

 # ./spec/controllers/accounts_controller_spec.rb:204:in `block (5 levels) in <top (required)>'

1/1 |======================================================= 100 ========================================================>| Time: 00:00:02

Finished in 2.67 seconds (files took 2.58 seconds to load)

1 example, 1 failure

Failed examples:

rspec './spec/controllers/accounts_controller_spec.rb[1:1:2:5:4]' # AccountsController GET #show as JSON when signed in renders account

Randomized with seed 12345

Currently using a default appmap.yml.

name: mastodon

language: ruby

appmap_dir: tmp/appmap

packages:

  • path: app

  • path: lib

— Reply to this email directly, view it on GitHub https://github.com/getappmap/appmap-ruby/issues/301#issuecomment-1349419679, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAAVC66ILKJZFZHIHQ5CR3DWNC4ZRANCNFSM6AAAAAASXKBHQA . You are receiving this because you commented.Message ID: @.***>

petecheslock commented 1 year ago

Updated run with the hook telemetry enabled from https://github.com/getappmap/appmap-ruby/pull/303

APPMAP_PROFILE_HOOK=true APPMAP_LOG_HOOK=true DISABLE_SPRING=true RAILS_ENV=test APPMAP=true bundle exec rspec ./spec/lib/activitypub/dereferencer_spec.rb --seed 12345

Randomized with seed 12345
warning: tag 'v0.1.2' is externally known as '0.1.2'                                                                                                       |  ETA: ??:??:?? 

  1) ActivityPub::Dereferencer#object with a URI returns object
     Failure/Error: while (chunk = readpartial)

     HTTP::StateError:
       body has already been consumed
     # ./app/lib/request.rb:171:in `body_with_limit'
     # ./app/lib/activitypub/dereferencer.rb:53:in `block in perform_request'
     # ./app/lib/request.rb:72:in `perform'
     # ./app/lib/activitypub/dereferencer.rb:51:in `perform_request'
     # ./app/lib/activitypub/dereferencer.rb:35:in `fetch_with_signature!'
     # ./app/lib/activitypub/dereferencer.rb:26:in `fetch_object!'
     # ./app/lib/activitypub/dereferencer.rb:13:in `object'
     # ./spec/lib/activitypub/dereferencer_spec.rb:10:in `block (3 levels) in <top (required)>'
     # ./spec/lib/activitypub/dereferencer_spec.rb:20:in `block (4 levels) in <top (required)>'

  2) ActivityPub::Dereferencer#object with a URI with signature account makes signed request
     Failure/Error: while (chunk = readpartial)

     HTTP::StateError:
       body has already been consumed
     # ./app/lib/request.rb:171:in `body_with_limit'
     # ./app/lib/activitypub/dereferencer.rb:53:in `block in perform_request'
     # ./app/lib/request.rb:72:in `perform'
     # ./app/lib/activitypub/dereferencer.rb:51:in `perform_request'
     # ./app/lib/activitypub/dereferencer.rb:35:in `fetch_with_signature!'
     # ./app/lib/activitypub/dereferencer.rb:26:in `fetch_object!'
     # ./app/lib/activitypub/dereferencer.rb:13:in `object'
     # ./spec/lib/activitypub/dereferencer_spec.rb:10:in `block (3 levels) in <top (required)>'
     # ./spec/lib/activitypub/dereferencer_spec.rb:27:in `block (5 levels) in <top (required)>'

  3) ActivityPub::Dereferencer#object with a bearcap returns object
     Failure/Error: while (chunk = readpartial)

     HTTP::StateError:
       body has already been consumed
     # ./app/lib/request.rb:171:in `body_with_limit'
     # ./app/lib/activitypub/dereferencer.rb:53:in `block in perform_request'
     # ./app/lib/request.rb:72:in `perform'
     # ./app/lib/activitypub/dereferencer.rb:51:in `perform_request'
     # ./app/lib/activitypub/dereferencer.rb:31:in `fetch_with_token!'
     # ./app/lib/activitypub/dereferencer.rb:24:in `fetch_object!'
     # ./app/lib/activitypub/dereferencer.rb:13:in `object'
     # ./spec/lib/activitypub/dereferencer_spec.rb:10:in `block (3 levels) in <top (required)>'
     # ./spec/lib/activitypub/dereferencer_spec.rb:51:in `block (4 levels) in <top (required)>'

  4) ActivityPub::Dereferencer#object with a bearcap makes request with Authorization header
     Failure/Error: while (chunk = readpartial)

     HTTP::StateError:
       body has already been consumed
     # ./app/lib/request.rb:171:in `body_with_limit'
     # ./app/lib/activitypub/dereferencer.rb:53:in `block in perform_request'
     # ./app/lib/request.rb:72:in `perform'
     # ./app/lib/activitypub/dereferencer.rb:51:in `perform_request'
     # ./app/lib/activitypub/dereferencer.rb:31:in `fetch_with_token!'
     # ./app/lib/activitypub/dereferencer.rb:24:in `fetch_object!'
     # ./app/lib/activitypub/dereferencer.rb:13:in `object'
     # ./spec/lib/activitypub/dereferencer_spec.rb:10:in `block (3 levels) in <top (required)>'
     # ./spec/lib/activitypub/dereferencer_spec.rb:46:in `block (4 levels) in <top (required)>'

  5) ActivityPub::Dereferencer#object with a bearcap with signature account makes signed request
     Failure/Error: while (chunk = readpartial)

     HTTP::StateError:
       body has already been consumed
     # ./app/lib/request.rb:171:in `body_with_limit'
     # ./app/lib/activitypub/dereferencer.rb:53:in `block in perform_request'
     # ./app/lib/request.rb:72:in `perform'
     # ./app/lib/activitypub/dereferencer.rb:51:in `perform_request'
     # ./app/lib/activitypub/dereferencer.rb:31:in `fetch_with_token!'
     # ./app/lib/activitypub/dereferencer.rb:24:in `fetch_object!'
     # ./app/lib/activitypub/dereferencer.rb:13:in `object'
     # ./spec/lib/activitypub/dereferencer_spec.rb:10:in `block (3 levels) in <top (required)>'
     # ./spec/lib/activitypub/dereferencer_spec.rb:58:in `block (5 levels) in <top (required)>'

 7/7 |======================================================================= 100 ========================================================================>| Time: 00:00:02 

Finished in 2.49 seconds (files took 2.92 seconds to load)
7 examples, 5 failures

Failed examples:

rspec ./spec/lib/activitypub/dereferencer_spec.rb:16 # ActivityPub::Dereferencer#object with a URI returns object
rspec ./spec/lib/activitypub/dereferencer_spec.rb:23 # ActivityPub::Dereferencer#object with a URI with signature account makes signed request
rspec './spec/lib/activitypub/dereferencer_spec.rb[1:1:2:2]' # ActivityPub::Dereferencer#object with a bearcap returns object
rspec './spec/lib/activitypub/dereferencer_spec.rb[1:1:2:1]' # ActivityPub::Dereferencer#object with a bearcap makes request with Authorization header
rspec ./spec/lib/activitypub/dereferencer_spec.rb:54 # ActivityPub::Dereferencer#object with a bearcap with signature account makes signed request

Randomized with seed 12345
AppMap: Package actionpack-6.1.7 took 0.03172 seconds to hook
AppMap: Package sidekiq-6.5.7 took 0.031117000000000002 seconds to hook
AppMap: Package activejob-6.1.7 took 0.011054999999999999 seconds to hook
AppMap: Package devise-4.8.1 took 0.156465 seconds to hook
AppMap: Package jwt-2.4.1 took 0.0013380000000000006 seconds to hook
AppMap: Package lib/redis took 0.002698 seconds to hook
AppMap: Package lib/paperclip took 0.0022559999999999998 seconds to hook
AppMap: Package lib/mastodon took 0.0015249999999999997 seconds to hook
AppMap: Package lib/devise took 0.005416000000000001 seconds to hook
AppMap: Package lib/chewy took 0.0012360000000000001 seconds to hook
AppMap: Package lib/active_record took 0.0017289999999999999 seconds to hook
AppMap: Package railties-6.1.7 took 0.008343 seconds to hook
AppMap: Package actionview-6.1.7 took 0.014808999999999998 seconds to hook
AppMap: Package lib/json_ld took 0.002222 seconds to hook
AppMap: Package app/models took 0.25038 seconds to hook
AppMap: Package app/validators took 0.001318 seconds to hook
AppMap: Package app/lib took 0.014020000000000003 seconds to hook
AppMap: Package app/helpers took 0.014317000000000002 seconds to hook
AppMap: Package app/controllers took 0.0028409999999999998 seconds to hook
AppMap: Package app/presenters took 0.001026 seconds to hook
AppMap: Package app/serializers took 0.012216 seconds to hook

appmap_hook.log

petecheslock commented 1 year ago

Dropping an update here - using this version of appmap-ruby

git_source(:github) { |repo| "https://github.com/#{repo}.git" }
gem 'appmap',
  github: 'applandinc/appmap-ruby',
  branch: 'feat/enhanced-hook-logging',
  group: %i[test development]
DISABLE_SPRING=true RAILS_ENV=test bundle exec rspec ./spec/services/activitypub/fetch_remote_key_service_spec.rb 

Randomized with seed 22668
warning: tag 'v0.1.2' is externally known as '0.1.2'                                                                                         |  ETA: ??:??:?? 

  1) ActivityPub::FetchRemoteKeyService#call when the key and owner do not match returns the nil
     Failure/Error: while (chunk = readpartial)

     HTTP::StateError:
       body has already been consumed
     # ./app/lib/request.rb:171:in `body_with_limit'
     # ./app/helpers/jsonld_helper.rb:179:in `block in fetch_resource_without_id_validation'
     # ./app/lib/request.rb:72:in `perform'
     # ./app/helpers/jsonld_helper.rb:176:in `fetch_resource_without_id_validation'
     # ./app/helpers/jsonld_helper.rb:162:in `fetch_resource'
     # ./app/services/activitypub/fetch_remote_key_service.rb:21:in `call'
     # ./spec/services/activitypub/fetch_remote_key_service_spec.rb:46:in `block (3 levels) in <top (required)>'
     # ./spec/services/activitypub/fetch_remote_key_service_spec.rb:79:in `block (4 levels) in <top (required)>'

With appmap disabled

APPMAP=false DISABLE_SPRING=true RAILS_ENV=test bundle exec rspec ./spec/services/activitypub/fetch_remote_key_service_spec.rb

Randomized with seed 25647
 3/3 |================================================================ 100 =================================================================>| Time: 00:00:00 

Finished in 0.44548 seconds (files took 2.85 seconds to load)
3 examples, 0 failures

Randomized with seed 25647

I have the following in my appmap.yml which SHOULD? exclude the method that fails. 

---
name: mastodon
language: ruby
appmap_dir: tmp/appmap
packages:
- path: app
- path: lib
exclude:
- Request::ClientLimit#body_with_limit

appmap_hook.log

kgilpin commented 1 year ago

Making that config change is working for me.

On Thu, Dec 15, 2022 at 10:25 AM Pete Cheslock @.***> wrote:

Dropping an update here - using this version of appmap-ruby

git_source(:github) { |repo| "https://github.com/#{repo}.git" } gem 'appmap', github: 'applandinc/appmap-ruby', branch: 'feat/enhanced-hook-logging', group: %i[test development]

DISABLE_SPRING=true RAILS_ENV=test bundle exec rspec ./spec/services/activitypub/fetch_remote_key_service_spec.rb

Randomized with seed 22668 warning: tag 'v0.1.2' is externally known as '0.1.2' | ETA: ??:??:??

1) ActivityPub::FetchRemoteKeyService#call when the key and owner do not match returns the nil Failure/Error: while (chunk = readpartial)

 HTTP::StateError:
   body has already been consumed
 # ./app/lib/request.rb:171:in `body_with_limit'
 # ./app/helpers/jsonld_helper.rb:179:in `block in fetch_resource_without_id_validation'
 # ./app/lib/request.rb:72:in `perform'
 # ./app/helpers/jsonld_helper.rb:176:in `fetch_resource_without_id_validation'
 # ./app/helpers/jsonld_helper.rb:162:in `fetch_resource'
 # ./app/services/activitypub/fetch_remote_key_service.rb:21:in `call'
 # ./spec/services/activitypub/fetch_remote_key_service_spec.rb:46:in `block (3 levels) in <top (required)>'
 # ./spec/services/activitypub/fetch_remote_key_service_spec.rb:79:in `block (4 levels) in <top (required)>'

With appmap disabled

APPMAP=false DISABLE_SPRING=true RAILS_ENV=test bundle exec rspec ./spec/services/activitypub/fetch_remote_key_service_spec.rb

Randomized with seed 25647 3/3 |================================================================ 100 =================================================================>| Time: 00:00:00

Finished in 0.44548 seconds (files took 2.85 seconds to load) 3 examples, 0 failures

Randomized with seed 25647

I have the following in my appmap.yml which SHOULD? exclude the method that fails.

name: mastodon language: ruby appmap_dir: tmp/appmap packages:

  • path: app
  • path: lib exclude:
  • Request::ClientLimit#body_with_limit

appmap_hook.log https://github.com/getappmap/appmap-ruby/files/10238216/appmap_hook.log

— Reply to this email directly, view it on GitHub https://github.com/getappmap/appmap-ruby/issues/301#issuecomment-1353263914, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAAVC67ZTLGDWZMG2HKSU7LWNM2AFANCNFSM6AAAAAASXKBHQA . You are receiving this because you commented.Message ID: @.***>

petecheslock commented 1 year ago

Hmm - coming back to this issue - Still running into an error - here is one example - and tried to drop and reload the test DB beforehand as i was getting some errors related to DB records already existing. 

RAILS_ENV=test ./bin/rails db:drop db:create db:schema:load db:seed    

$ APPMAP_PROFILE_HOOK=true APPMAP_LOG_HOOK=true DISABLE_SPRING=true RAILS_ENV=test APPMAP=false bundle exec rspec ./spec/services/resolve_account_service_spec.rb

<snip>
Finished in 2.83 seconds (files took 1.83 seconds to load)
20 examples, 0 failures

Randomized with seed 41844

But then with appmap enabled:

$ RAILS_ENV=test ./bin/rails db:drop db:create db:schema:load db:seed         
$ APPMAP_PROFILE_HOOK=true APPMAP_LOG_HOOK=true DISABLE_SPRING=true RAILS_ENV=test APPMAP=true bundle exec rspec ./spec/services/resolve_account_service_spec.rb
<snip>
 8) ResolveAccountService with a legitimate webfinger redirection returns new remote account
     Failure/Error: while (chunk = readpartial)

     HTTP::StateError:
       body has already been consumed
     # ./app/lib/request.rb:171:in `body_with_limit'
     # ./app/helpers/jsonld_helper.rb:179:in `block in fetch_resource_without_id_validation'
     # ./app/lib/request.rb:72:in `perform'
     # ./app/helpers/jsonld_helper.rb:176:in `fetch_resource_without_id_validation'
     # ./app/helpers/jsonld_helper.rb:169:in `fetch_resource'
     # ./app/services/activitypub/fetch_remote_actor_service.rb:19:in `call'
     # ./app/services/activitypub/fetch_remote_account_service.rb:6:in `call'
     # ./app/services/resolve_account_service.rb:114:in `block in fetch_account!'
     # ./app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
     # ./app/models/concerns/lockable.rb:10:in `block in with_lock'
     # ./app/lib/redis_configuration.rb:10:in `with'
     # ./app/models/concerns/redisable.rb:9:in `with_redis'
     # ./app/models/concerns/lockable.rb:9:in `with_lock'
     # ./app/services/resolve_account_service.rb:113:in `fetch_account!'
     # ./app/services/resolve_account_service.rb:55:in `call'
     # ./spec/services/resolve_account_service_spec.rb:109:in `block (3 levels) in <top (required)>'

 20/20 |================================================================================ 100 =================================================================================>| Time: 00:00:02 

Finished in 2.61 seconds (files took 2.66 seconds to load)
20 examples, 8 failures

Failed examples:

rspec ./spec/services/resolve_account_service_spec.rb:3 # ResolveAccountService processes one remote account at a time using locks
rspec ./spec/services/resolve_account_service_spec.rb:191 # ResolveAccountService with an already-known acct: URI changing ActivityPub id returns new remote account
rspec ./spec/services/resolve_account_service_spec.rb:145 # ResolveAccountService with an ActivityPub account returns new remote account
rspec ./spec/services/resolve_account_service_spec.rb:154 # ResolveAccountService with an ActivityPub account with multiple types returns new remote account
rspec ./spec/services/resolve_account_service_spec.rb:117 # ResolveAccountService with a misconfigured redirection returns new remote account
rspec './spec/services/resolve_account_service_spec.rb[1:9:2]' # ResolveAccountService with an already-known actor changing acct: URI merges accounts
rspec './spec/services/resolve_account_service_spec.rb[1:9:1]' # ResolveAccountService with an already-known actor changing acct: URI returns new remote account
rspec ./spec/services/resolve_account_service_spec.rb:102 # ResolveAccountService with a legitimate webfinger redirection returns new remote account

Randomized with seed 56750
AppMap: Package actionpack-6.1.7 took 0.036256 seconds to hook
AppMap: Package sidekiq-6.5.8 took 0.02994 seconds to hook
AppMap: Package activejob-6.1.7 took 0.012323999999999995 seconds to hook
AppMap: Package devise-4.8.1 took 0.15274100000000002 seconds to hook
AppMap: Package jwt-2.5.0 took 0.0023429999999999996 seconds to hook
AppMap: Package lib/paperclip took 0.0021019999999999997 seconds to hook
AppMap: Package lib/mastodon took 0.001341 seconds to hook
AppMap: Package lib/devise took 0.00532 seconds to hook
AppMap: Package lib/chewy took 0.001307 seconds to hook
AppMap: Package lib/active_record took 0.001686 seconds to hook
AppMap: Package railties-6.1.7 took 0.008036 seconds to hook
AppMap: Package actionview-6.1.7 took 0.013760000000000001 seconds to hook
AppMap: Package lib/json_ld took 0.002197 seconds to hook
AppMap: Package app/models took 0.377423 seconds to hook
AppMap: Package app/validators took 0.002474 seconds to hook
AppMap: Package app/lib took 0.014785 seconds to hook
AppMap: Package app/helpers took 0.016700999999999997 seconds to hook
AppMap: Package app/controllers took 0.003131 seconds to hook
AppMap: Package app/workers took 0.001422 seconds to hook

Here is a branch with the config i'm using.

Any ideas?

kgilpin commented 1 year ago

I don't see anything excluded in that branch:

https://github.com/land-of-apps/mastodon/blob/appmap-ruby-issue-301/appmap.yml

I was expecting to see something like:

exclude:

On Wed, Dec 21, 2022 at 2:02 PM Pete Cheslock @.***> wrote:

Hmm - coming back to this issue - Still running into an error - here is one example - and tried to drop and reload the test DB beforehand as i was getting some errors related to DB records already existing.

RAILS_ENV=test ./bin/rails db:create db:schema:load db:seed

$ APPMAP_PROFILE_HOOK=true APPMAP_LOG_HOOK=true DISABLE_SPRING=true RAILS_ENV=test APPMAP=false bundle exec rspec ./spec/services/resolve_account_service_spec.rb

Finished in 2.83 seconds (files took 1.83 seconds to load) 20 examples, 0 failures Randomized with seed 41844 But then with appmap enabled: $ RAILS_ENV=test ./bin/rails db:drop db:create db:schema:load db:seed $ APPMAP_PROFILE_HOOK=true APPMAP_LOG_HOOK=true DISABLE_SPRING=true RAILS_ENV=test APPMAP=true bundle exec rspec ./spec/services/resolve_account_service_spec.rb 8) ResolveAccountService with a legitimate webfinger redirection returns new remote account Failure/Error: while (chunk = readpartial) HTTP::StateError: body has already been consumed # ./app/lib/request.rb:171:in `body_with_limit' # ./app/helpers/jsonld_helper.rb:179:in `block in fetch_resource_without_id_validation' # ./app/lib/request.rb:72:in `perform' # ./app/helpers/jsonld_helper.rb:176:in `fetch_resource_without_id_validation' # ./app/helpers/jsonld_helper.rb:169:in `fetch_resource' # ./app/services/activitypub/fetch_remote_actor_service.rb:19:in `call' # ./app/services/activitypub/fetch_remote_account_service.rb:6:in `call' # ./app/services/resolve_account_service.rb:114:in `block in fetch_account!' # ./app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock' # ./app/models/concerns/lockable.rb:10:in `block in with_lock' # ./app/lib/redis_configuration.rb:10:in `with' # ./app/models/concerns/redisable.rb:9:in `with_redis' # ./app/models/concerns/lockable.rb:9:in `with_lock' # ./app/services/resolve_account_service.rb:113:in `fetch_account!' # ./app/services/resolve_account_service.rb:55:in `call' # ./spec/services/resolve_account_service_spec.rb:109:in `block (3 levels) in ' 20/20 |================================================================================ 100 =================================================================================>| Time: 00:00:02 Finished in 2.61 seconds (files took 2.66 seconds to load) 20 examples, 8 failures Failed examples: rspec ./spec/services/resolve_account_service_spec.rb:3 # ResolveAccountService processes one remote account at a time using locks rspec ./spec/services/resolve_account_service_spec.rb:191 # ResolveAccountService with an already-known acct: URI changing ActivityPub id returns new remote account rspec ./spec/services/resolve_account_service_spec.rb:145 # ResolveAccountService with an ActivityPub account returns new remote account rspec ./spec/services/resolve_account_service_spec.rb:154 # ResolveAccountService with an ActivityPub account with multiple types returns new remote account rspec ./spec/services/resolve_account_service_spec.rb:117 # ResolveAccountService with a misconfigured redirection returns new remote account rspec './spec/services/resolve_account_service_spec.rb[1:9:2]' # ResolveAccountService with an already-known actor changing acct: URI merges accounts rspec './spec/services/resolve_account_service_spec.rb[1:9:1]' # ResolveAccountService with an already-known actor changing acct: URI returns new remote account rspec ./spec/services/resolve_account_service_spec.rb:102 # ResolveAccountService with a legitimate webfinger redirection returns new remote account Randomized with seed 56750 AppMap: Package actionpack-6.1.7 took 0.036256 seconds to hook AppMap: Package sidekiq-6.5.8 took 0.02994 seconds to hook AppMap: Package activejob-6.1.7 took 0.012323999999999995 seconds to hook AppMap: Package devise-4.8.1 took 0.15274100000000002 seconds to hook AppMap: Package jwt-2.5.0 took 0.0023429999999999996 seconds to hook AppMap: Package lib/paperclip took 0.0021019999999999997 seconds to hook AppMap: Package lib/mastodon took 0.001341 seconds to hook AppMap: Package lib/devise took 0.00532 seconds to hook AppMap: Package lib/chewy took 0.001307 seconds to hook AppMap: Package lib/active_record took 0.001686 seconds to hook AppMap: Package railties-6.1.7 took 0.008036 seconds to hook AppMap: Package actionview-6.1.7 took 0.013760000000000001 seconds to hook AppMap: Package lib/json_ld took 0.002197 seconds to hook AppMap: Package app/models took 0.377423 seconds to hook AppMap: Package app/validators took 0.002474 seconds to hook AppMap: Package app/lib took 0.014785 seconds to hook AppMap: Package app/helpers took 0.016700999999999997 seconds to hook AppMap: Package app/controllers took 0.003131 seconds to hook AppMap: Package app/workers took 0.001422 seconds to hook [Here is a branch with the config i'm using.](https://github.com/land-of-apps/mastodon/tree/appmap-ruby-issue-301) Any ideas? — Reply to this email directly, view it on GitHub , or unsubscribe . You are receiving this because you commented.Message ID: ***@***.***>
petecheslock commented 1 year ago

Ok - i've updated the appmap.yml on that branch and reran the command but ended up with the same results as before. Is the format of that exclude section correct?

I ran with DEBUG=true to see if anything useful was logged - here's what was outputted to the console. 

Randomized with seed 24024
#<Thread:0x0000000138c2fd10 /Users/petecheslock/repos/mastodon/spec/services/resolve_account_service_spec.rb:216 run> terminated with exception (report_on_exception is true): |  ETA: ??:??:?? 
/Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/gems/http-5.1.1/lib/http/response/body.rb:67:in `stream!': body has already been consumed (HTTP::StateError)
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/gems/http-5.1.1/lib/http/response/body.rb:29:in `readpartial'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/3.0.0/forwardable.rb:238:in `readpartial'
        from /Users/petecheslock/repos/mastodon/app/lib/request.rb:171:in `body_with_limit'
        from /Users/petecheslock/repos/mastodon/app/helpers/jsonld_helper.rb:179:in `block in fetch_resource_without_id_validation'
        from /Users/petecheslock/repos/mastodon/app/lib/request.rb:72:in `perform'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `bind_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `do_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:49:in `trace_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:16:in `call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:63:in `block in hook_method_def'
        from /Users/petecheslock/repos/mastodon/app/helpers/jsonld_helper.rb:176:in `fetch_resource_without_id_validation'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `bind_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `do_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:49:in `trace_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:16:in `call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:63:in `block in hook_method_def'
        from /Users/petecheslock/repos/mastodon/app/helpers/jsonld_helper.rb:169:in `fetch_resource'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `bind_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `do_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:49:in `trace_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:16:in `call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:63:in `block in hook_method_def'
        from /Users/petecheslock/repos/mastodon/app/services/activitypub/fetch_remote_actor_service.rb:19:in `call'
        from /Users/petecheslock/repos/mastodon/app/services/activitypub/fetch_remote_account_service.rb:6:in `call'
        from /Users/petecheslock/repos/mastodon/app/services/resolve_account_service.rb:114:in `block in fetch_account!'
        from /Users/petecheslock/repos/mastodon/app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/gems/mario-redis-lock-1.2.1/lib/redis_lock.rb:44:in `acquire'
        from /Users/petecheslock/repos/mastodon/app/models/concerns/lockable.rb:10:in `block in with_lock'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:65:in `block (2 levels) in with'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `handle_interrupt'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:64:in `block in with'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `handle_interrupt'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/gems/connection_pool-2.3.0/lib/connection_pool.rb:61:in `with'
        from /Users/petecheslock/repos/mastodon/app/lib/redis_configuration.rb:10:in `with'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `bind_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `do_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:49:in `trace_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:16:in `call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:63:in `block in hook_method_def'
        from /Users/petecheslock/repos/mastodon/app/models/concerns/redisable.rb:9:in `with_redis'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `bind_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `do_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:49:in `trace_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:16:in `call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:63:in `block in hook_method_def'
        from /Users/petecheslock/repos/mastodon/app/models/concerns/lockable.rb:9:in `with_lock'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `bind_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:40:in `do_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:49:in `trace_call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:16:in `call'
        from /Users/petecheslock/.asdf/installs/ruby/3.0.4/lib/ruby/gems/3.0.0/bundler/gems/appmap-ruby-4af5645a43f6/lib/appmap/hook/method/ruby3.rb:63:in `block in hook_method_def'
        from /Users/petecheslock/repos/mastodon/app/services/resolve_account_service.rb:113:in `fetch_account!'
        from /Users/petecheslock/repos/mastodon/app/services/resolve_account_service.rb:55:in `call'
        from /Users/petecheslock/repos/mastodon/spec/services/resolve_account_service_spec.rb:220:in `block (4 levels) in <top (required)>'
petecheslock commented 1 year ago

Coming back to this for other testing - updating to 0.98.0 fixes this problem with the following in the appmap.yml

---
name: mastodon
language: ruby
appmap_dir: tmp/appmap
packages:
- path: app
- path: lib
exclude:
- Request::ClientLimit#body_with_limit
- Request::ClientLimit#truncated_body