mastodon
mastodon copied to clipboard
mastodon
Sidekiq dead queue full of failed jobs, causing random accounts and instances to be unreachable/not visible.
Steps to reproduce the problem
- As a user of my instance
- Attempt to search for or follow new users or new servers
- Receive http 500 error from search UI on my instance
Expected behaviour
I should be able to find and follow users on new servers and accounts
Actual behaviour
Http 500 errors when searching for newer users
Detailed description
Currently my sidekiq dead queue is entirely full of 9999 dead ActivityPub::ProcessingWorker jobs with errors similar to the following:
ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
Specifications
SOFTWARE Mastodon 4.0.2 Ruby 3.0.4p208 PostgreSQL 14.6 Redis 7.0.5
Looking at the arguments to these errors via the sidekiq ui, I can see that it's trying to process or find an external/new status from users that for whatever reason I am unable to find/view from my instance.
I've grabbed more detailed logs from my instance during my lunch break, it appears maybe there's more to this, I see multiple sidekiq jobs are failing with the exact same error: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json\:
Logs:
2022-12-19T18:46:08Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/73a45741375e8187657db5a9edcf4d2d20221219-520-iat7zb.png to /tmp/810b9de62e3465582a0d2096bc7dfafa20221219-520-uqt2eu.png
2022-12-19T18:46:08Z app[sidekiq] dc1 [info]Command :: file -b --mime '/tmp/810b9de62e3465582a0d2096bc7dfafa20221219-520-uqt2eu.png'
2022-12-19T18:46:08Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/73a45741375e8187657db5a9edcf4d2d20221219-520-iat7zb.png to /tmp/2a12df139244f2c4a80ef7de02d9dd6720221219-520-ypwoiy.png
2022-12-19T18:46:08Z app[sidekiq] dc1 [info]2022-12-19T18:46:08.809Z pid=520 tid=adbw class=PushUpdateWorker jid=bcfcc59d08cb5b325190f9c5 elapsed=0.334 INFO: done
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]2022-12-19T18:46:09.445Z pid=520 tid=a2no class=ThreadResolveWorker jid=92961206d8c18ada142d5021 INFO: Adding dead ThreadResolveWorker job 92961206d8c18ada142d5021
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]2022-12-19T18:46:09.447Z pid=520 tid=a2no class=ThreadResolveWorker jid=92961206d8c18ada142d5021 elapsed=4.236 INFO: fail
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]2022-12-19T18:46:09.447Z pid=520 tid=a2no WARN: {"context":"Job raised exception","job":{"retry":3,"queue":"pull","args":[109541797225078917,"https://tech.lgbt/users/robotfactory/statuses/109541785218457247"],"class":"ThreadResolveWorker","jid":"92961206d8c18ada142d5021","created_at":1671475177.8793168,"enqueued_at":1671475565.2105694,"error_message":"PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json\nLINE 1: ...ed_at\" = '2022-12-19 18:40:49.085952', \"fields\" = '[{\"name\":...\n ^\nDETAIL: Token \"https\" is invalid.\nCONTEXT: JSON data, line 1: ...{\"name\":\"Website\",\"value\":\"\\\\u003ca href=\\\\\"https...\n","error_class":"ActiveRecord::StatementInvalid","failed_at":1671475182.2562983,"retry_count":2,"retried_at":1671475252.3950691}}
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]2022-12-19T18:46:09.447Z pid=520 tid=a2no WARN: ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]LINE 1: ...ed_at" = '2022-12-19 18:46:06.141057', "fields" = '[{"name":...
2022-12-19T18:46:09Z app[sidekiq] dc1 [info] ^
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]CONTEXT: JSON data, line 1: ...{"name":"Website","value":"\\u003ca href=\\"https...
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]2022-12-19T18:46:09.447Z pid=520 tid=a2no WARN: /opt/mastodon/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `exec_params'
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]/opt/mastodon/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `block (2 levels) in exec_no_cache'
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]/opt/mastodon/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.7/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]2022-12-19T18:46:09.859Z pid=520 tid=acf8 class=LinkCrawlWorker jid=bb89c91f0ce2cab59ed973d2 INFO: start
2022-12-19T18:46:09Z app[sidekiq] dc1 [info]2022-12-19T18:46:09.965Z pid=520 tid=acf8 class=LinkCrawlWorker jid=bb89c91f0ce2cab59ed973d2 elapsed=0.106 INFO: done
2022-12-19T18:46:10Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] [paperclip] Trying to link /tmp/57ec60e4cb9e8af6029e760343d6385720221219-529-pap18o.png to /tmp/4f4f4d850b8b737aaf2116bed0dfca8820221219-529-19iadb.png
2022-12-19T18:46:10Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] Command :: file -b --mime '/tmp/4f4f4d850b8b737aaf2116bed0dfca8820221219-529-19iadb.png'
2022-12-19T18:46:10Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] [paperclip] Trying to link /tmp/57ec60e4cb9e8af6029e760343d6385720221219-529-pap18o.png to /tmp/f0d5a507fcd055fbd1159ed43a24798b20221219-529-4m9sb3.png
2022-12-19T18:46:11Z app[rails] dc1 [info][203e7d93-0bd2-40b3-a890-bc058a320dbf] method=POST path=/inbox format=json controller=ActivityPub::InboxesController action=create status=202 duration=232.37 view=0.00 db=162.16 key=https://relay.tirefireind.us/actor#main-key
2022-12-19T18:46:11Z app[sidekiq] dc1 [info]2022-12-19T18:46:11.893Z pid=520 tid=acf8 class=ActivityPub::ProcessingWorker jid=a780d011e1837d28adf399ff INFO: start
2022-12-19T18:46:11Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] [paperclip] Trying to link /tmp/73a45741375e8187657db5a9edcf4d2d20221219-529-tl57n0.png to /tmp/69c32dbb5b310fe5d83df281a3fb123320221219-529-1itm08.png
2022-12-19T18:46:11Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] Command :: file -b --mime '/tmp/69c32dbb5b310fe5d83df281a3fb123320221219-529-1itm08.png'
2022-12-19T18:46:11Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] [paperclip] Trying to link /tmp/73a45741375e8187657db5a9edcf4d2d20221219-529-tl57n0.png to /tmp/ab899bba38c9f27a6d963f8d81e535a620221219-529-rzumh3.png
2022-12-19T18:46:12Z app[sidekiq] dc1 [info]Rejected Announce activity https://relay.tirefireind.us/activities/5efe6de1-f2b5-4ec5-92c4-45b85a58e982 from https://relay.tirefireind.us/actor
2022-12-19T18:46:12Z app[sidekiq] dc1 [info]2022-12-19T18:46:12.155Z pid=520 tid=acf8 class=ActivityPub::ProcessingWorker jid=a780d011e1837d28adf399ff elapsed=0.262 INFO: done
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] method=GET path=/api/v2/search format=html controller=Api::V2::SearchController action=index status=500 error='ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-19T18:46:12Z app[rails] dc1 [info]LINE 1: ...ed_at" = '2022-12-19 18:46:09.505476', "fields" = '[{"name":...
2022-12-19T18:46:12Z app[rails] dc1 [info] ^
2022-12-19T18:46:12Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-19T18:46:12Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: ...{"name":"Website","value":"\\u003ca href=\\"https...
2022-12-19T18:46:12Z app[rails] dc1 [info]' duration=6935.10 view=0.00 db=542.99
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d]
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-19T18:46:12Z app[rails] dc1 [info]LINE 1: ...ed_at" = '2022-12-19 18:46:09.505476', "fields" = '[{"name":...
2022-12-19T18:46:12Z app[rails] dc1 [info] ^
2022-12-19T18:46:12Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-19T18:46:12Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: ...{"name":"Website","value":"\\u003ca href=\\"https...
2022-12-19T18:46:12Z app[rails] dc1 [info]):
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d]
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/models/account.rb:343:in `save_with_optional_media!'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/services/activitypub/process_account_service.rb:75:in `update_account'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/services/activitypub/process_account_service.rb:29:in `block in call'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/models/concerns/lockable.rb:10:in `block in with_lock'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/lib/redis_configuration.rb:10:in `with'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/models/concerns/redisable.rb:9:in `with_redis'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/models/concerns/lockable.rb:9:in `with_lock'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/services/activitypub/process_account_service.rb:21:in `call'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/services/activitypub/fetch_remote_actor_service.rb:38:in `call'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/services/resolve_url_service.rb:26:in `process_url'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/services/resolve_url_service.rb:16:in `call'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/services/search_service.rb:83:in `url_resource'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/services/search_service.rb:16:in `block in call'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/services/search_service.rb:12:in `call'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/controllers/api/v2/search_controller.rb:33:in `search_results'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/controllers/api/v2/search_controller.rb:12:in `index'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] app/controllers/concerns/localized.rb:11:in `set_locale'
2022-12-19T18:46:12Z app[rails] dc1 [info][75fe739c-4ea9-455d-b271-ca10ba98c35d] lib/mastodon/rack_middleware.rb:9:in `call'
2022-12-19T18:46:13Z app[rails] dc1 [info][5ea61dc2-77ec-47c1-ac19-7a8c6d38d957] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=202 duration=118.67 view=0.00 db=53.77 key=https://mastodon.vlaanderen/users/99#main-key
2022-12-19T18:46:13Z app[sidekiq] dc1 [info]2022-12-19T18:46:13.776Z pid=520 tid=acf8 class=ActivityPub::ProcessingWorker jid=79dcab624a505430fb3260f6 INFO: start
2022-12-19T18:46:14Z app[rails] dc1 [info][22f8a49f-5b50-4129-aefa-237793d394ce] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=202 duration=230.47 view=0.00 db=161.56 key=https://mastodon.social/users/krystman#main-key
2022-12-19T18:46:14Z app[sidekiq] dc1 [info]2022-12-19T18:46:14.452Z pid=520 tid=afg4 class=ActivityPub::ProcessingWorker jid=5dbceea43a673d246e3db40d INFO: start
2022-12-19T18:46:15Z app[sidekiq] dc1 [info]2022-12-19T18:46:15.419Z pid=520 tid=agps class=DistributionWorker jid=ef86f92ab39e1892acf6af9b INFO: start
2022-12-19T18:46:15Z app[sidekiq] dc1 [info]2022-12-19T18:46:15.421Z pid=520 tid=afg4 class=ActivityPub::ProcessingWorker jid=5dbceea43a673d246e3db40d elapsed=0.969 INFO: done
2022-12-19T18:46:15Z app[rails] dc1 [info][4109a112-b3e4-4017-8f71-00c7c5d3a690] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=202 duration=233.65 view=0.00 db=161.14 key=https://universeodon.com/users/popsci#main-key
2022-12-19T18:46:15Z app[sidekiq] dc1 [info]2022-12-19T18:46:15.794Z pid=520 tid=adbw class=ActivityPub::ProcessingWorker jid=c9d48e3d1dd67d6a0382bceb INFO: start
2022-12-19T18:46:16Z app[sidekiq] dc1 [info]2022-12-19T18:46:16.184Z pid=520 tid=afg4 class=FeedInsertWorker jid=9d815e8aef06a4ba5d632cd1 INFO: start
2022-12-19T18:46:16Z app[sidekiq] dc1 [info]2022-12-19T18:46:16.242Z pid=520 tid=agps class=DistributionWorker jid=ef86f92ab39e1892acf6af9b elapsed=0.823 INFO: done
2022-12-19T18:46:16Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/2d86ea0770a3402e969679fb6ad3614820221219-520-k5afrn.png to /tmp/720508c3aaa460169ed69e52400ca0dc20221219-520-daf8ha.png
2022-12-19T18:46:16Z app[sidekiq] dc1 [info]Command :: file -b --mime '/tmp/720508c3aaa460169ed69e52400ca0dc20221219-520-daf8ha.png'
2022-12-19T18:46:16Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/2d86ea0770a3402e969679fb6ad3614820221219-520-k5afrn.png to /tmp/be21e0f439af8450d34c9ba031fef18620221219-520-a2vz34.png
2022-12-19T18:46:16Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/2a38a37b48307b4f1164fefdda9107d420221219-520-8mb830.png to /tmp/3a2b98dd53b43bec03db620f1c45bce220221219-520-7kmhd9.png
2022-12-19T18:46:16Z app[sidekiq] dc1 [info]Command :: file -b --mime '/tmp/3a2b98dd53b43bec03db620f1c45bce220221219-520-7kmhd9.png'
2022-12-19T18:46:16Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/2a38a37b48307b4f1164fefdda9107d420221219-520-8mb830.png to /tmp/efee6774776b2218b55627ecc40dd1fb20221219-520-oc34f0.png
2022-12-19T18:46:16Z app[sidekiq] dc1 [info]2022-12-19T18:46:16.735Z pid=520 tid=aab8 class=PushUpdateWorker jid=4ced696e3281cac351843efc INFO: start
2022-12-19T18:46:16Z app[sidekiq] dc1 [info]2022-12-19T18:46:16.791Z pid=520 tid=afg4 class=FeedInsertWorker jid=9d815e8aef06a4ba5d632cd1 elapsed=0.607 INFO: done
2022-12-19T18:46:16Z app[sidekiq] dc1 [info]2022-12-19T18:46:16.835Z pid=520 tid=agps class=DistributionWorker jid=8bafb4d6cba0d29216a3db34 INFO: start
2022-12-19T18:46:16Z app[sidekiq] dc1 [info]2022-12-19T18:46:16.837Z pid=520 tid=adbw class=ActivityPub::ProcessingWorker jid=c9d48e3d1dd67d6a0382bceb elapsed=1.042 INFO: done
2022-12-19T18:46:17Z app[sidekiq] dc1 [info]2022-12-19T18:46:17.066Z pid=520 tid=aab8 class=PushUpdateWorker jid=4ced696e3281cac351843efc elapsed=0.331 INFO: done
2022-12-19T18:46:17Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] [paperclip] Trying to link /tmp/57ec60e4cb9e8af6029e760343d6385720221219-529-fs49qz.png to /tmp/c3786dc7d057775cd8b1eb2fc298bce320221219-529-e4rdkq.png
2022-12-19T18:46:17Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] Command :: file -b --mime '/tmp/c3786dc7d057775cd8b1eb2fc298bce320221219-529-e4rdkq.png'
2022-12-19T18:46:17Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] [paperclip] Trying to link /tmp/57ec60e4cb9e8af6029e760343d6385720221219-529-fs49qz.png to /tmp/90cfbcb352f2f24a4bcb46dde8e0559d20221219-529-jclcto.png
2022-12-19T18:46:17Z app[sidekiq] dc1 [info]2022-12-19T18:46:17.520Z pid=520 tid=afg4 class=FeedInsertWorker jid=966b3dcb58cf9e879eb1efde INFO: start
2022-12-19T18:46:17Z app[sidekiq] dc1 [info]2022-12-19T18:46:17.583Z pid=520 tid=agps class=DistributionWorker jid=8bafb4d6cba0d29216a3db34 elapsed=0.748 INFO: done
2022-12-19T18:46:18Z app[rails] dc1 [info][5d0a9900-7ca1-419a-8ae8-08e669e899cd] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=202 duration=229.98 view=0.00 db=161.09 key=https://jorts.horse/users/ancient_catbus#main-key
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]2022-12-19T18:46:18.009Z pid=520 tid=adbw class=ActivityPub::ProcessingWorker jid=bde7ddab7a1f37a204afd313 INFO: start
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]2022-12-19T18:46:18.082Z pid=520 tid=aab8 class=PushUpdateWorker jid=8cc71ac0689ae29ac0cb9ab1 INFO: start
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]2022-12-19T18:46:18.138Z pid=520 tid=afg4 class=FeedInsertWorker jid=966b3dcb58cf9e879eb1efde elapsed=0.618 INFO: done
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]2022-12-19T18:46:18.415Z pid=520 tid=aab8 class=PushUpdateWorker jid=8cc71ac0689ae29ac0cb9ab1 elapsed=0.333 INFO: done
2022-12-19T18:46:18Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] [paperclip] Trying to link /tmp/73a45741375e8187657db5a9edcf4d2d20221219-529-8q8xfv.png to /tmp/c6c60b5c1c8e73351903a08a3437920c20221219-529-lscces.png
2022-12-19T18:46:18Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] Command :: file -b --mime '/tmp/c6c60b5c1c8e73351903a08a3437920c20221219-529-lscces.png'
2022-12-19T18:46:18Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] [paperclip] Trying to link /tmp/73a45741375e8187657db5a9edcf4d2d20221219-529-8q8xfv.png to /tmp/6b24754caa1d6354400e2c7d1d04749720221219-529-zcte16.png
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]2022-12-19T18:46:18.534Z pid=520 tid=acf8 class=ActivityPub::ProcessingWorker jid=79dcab624a505430fb3260f6 elapsed=4.757 INFO: fail
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]2022-12-19T18:46:18.534Z pid=520 tid=acf8 WARN: {"context":"Job raised exception","job":{"retry":8,"queue":"ingress","backtrace":true,"args":[109362998590215000,"{\"@context\":\"https://www.w3.org/ns/activitystreams\",\"id\":\"https://mastodon.social/users/emaytch/statuses/109541787821061283/activity\",\"type\":\"Announce\",\"actor\":\"https://mastodon.social/users/emaytch\",\"published\":\"2022-12-19T18:37:13Z\",\"to\":[\"https://mastodon.social/users/emaytch/followers\"],\"cc\":[\"https://mastodon.social/users/asociologist\",\"https://www.w3.org/ns/activitystreams#Public\"],\"object\":\"https://mastodon.social/users/asociologist/statuses/109541584214200675\"}",null,"Account"],"class":"ActivityPub::ProcessingWorker","jid":"79dcab624a505430fb3260f6","created_at":1671475034.6921299,"enqueued_at":1671475573.7759166,"error_message":"PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json\nLINE 10: ...rs/asociologist/collections/featured', \"fields\" = '[{\"name\":...\n ^\nDETAIL: Token \"http\" is invalid.\nCONTEXT: JSON data, line 1: [{\"name\":\"Website\",\"value\":\"\\\\u003ca href=\\\\\"http...\n","error_class":"ActiveRecord::StatementInvalid","failed_at":1671475039.325798,"retry_count":4,"error_backtrace":"eJzN0N1KQzEMwPFXOexGBW3mlG3sVUS6Ng2z2JPUpOegb7/uQxC888q78g+E\nX/qyAKkNxmBNkjDMxEkU4sSpEOgUv+DJLd0SDjQaBGx5JiUUTQ9r9+g2UHK8\nZn/pgMJMvQj7kEJtpAZVrB2U7KN8N6dxt96sdpmHPX0S+ho0jHazuP8PolgE\n34fb1VBopmJ3Q49nJYvHgG/0N6dNtYq239DrABLVvoYYMxlk7qoT5CR73v6A\n9VclHXPz/TScVImbLxJS/7/XI1ndqT4=\n","retried_at":1671475256.007769}}
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]2022-12-19T18:46:18.534Z pid=520 tid=acf8 WARN: ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]LINE 10: ...rs/asociologist/collections/featured', "fields" = '[{"name":...
2022-12-19T18:46:18Z app[sidekiq] dc1 [info] ^
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]DETAIL: Token "http" is invalid.
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Website","value":"\\u003ca href=\\"http...
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]2022-12-19T18:46:18.534Z pid=520 tid=acf8 WARN: /opt/mastodon/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `exec_params'
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]/opt/mastodon/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `block (2 levels) in exec_no_cache'
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]/opt/mastodon/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.7/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
2022-12-19T18:46:18Z app[sidekiq] dc1 [info]2022-12-19T18:46:18.731Z pid=520 tid=agps class=ActivityPub::ProcessingWorker jid=be1117f3dc0369e1163af361 INFO: start
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] method=GET path=/api/v2/search format=html controller=Api::V2::SearchController action=index status=500 error='ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-19T18:46:19Z app[rails] dc1 [info]LINE 1: ...ed_at" = '2022-12-19 18:46:15.862611', "fields" = '[{"name":...
2022-12-19T18:46:19Z app[rails] dc1 [info] ^
2022-12-19T18:46:19Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-19T18:46:19Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: ...{"name":"Website","value":"\\u003ca href=\\"https...
2022-12-19T18:46:19Z app[rails] dc1 [info]' duration=4115.33 view=0.00 db=543.23
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9]
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-19T18:46:19Z app[rails] dc1 [info]LINE 1: ...ed_at" = '2022-12-19 18:46:15.862611', "fields" = '[{"name":...
2022-12-19T18:46:19Z app[rails] dc1 [info] ^
2022-12-19T18:46:19Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-19T18:46:19Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: ...{"name":"Website","value":"\\u003ca href=\\"https...
2022-12-19T18:46:19Z app[rails] dc1 [info]):
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9]
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/models/account.rb:343:in `save_with_optional_media!'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/services/activitypub/process_account_service.rb:75:in `update_account'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/services/activitypub/process_account_service.rb:29:in `block in call'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/models/concerns/lockable.rb:10:in `block in with_lock'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/lib/redis_configuration.rb:10:in `with'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/models/concerns/redisable.rb:9:in `with_redis'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/models/concerns/lockable.rb:9:in `with_lock'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/services/activitypub/process_account_service.rb:21:in `call'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/services/activitypub/fetch_remote_actor_service.rb:38:in `call'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/services/resolve_url_service.rb:26:in `process_url'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/services/resolve_url_service.rb:16:in `call'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/services/search_service.rb:83:in `url_resource'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/services/search_service.rb:16:in `block in call'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/services/search_service.rb:12:in `call'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/controllers/api/v2/search_controller.rb:33:in `search_results'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/controllers/api/v2/search_controller.rb:12:in `index'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] app/controllers/concerns/localized.rb:11:in `set_locale'
2022-12-19T18:46:19Z app[rails] dc1 [info][7b2a127c-6f39-432b-8b3a-6bb8a0e11cd9] lib/mastodon/rack_middleware.rb:9:in `call'
2022-12-19T18:46:19Z app[sidekiq] dc1 [info]2022-12-19T18:46:19.374Z pid=520 tid=afg4 class=ActivityPub::SynchronizeFeaturedCollectionWorker jid=d2203001a0dd98fd02a534bb INFO: start
2022-12-19T18:46:19Z app[sidekiq] dc1 [info]2022-12-19T18:46:19.381Z pid=520 tid=aab8 class=ActivityPub::SynchronizeFeaturedTagsCollectionWorker jid=7eed594ec14ffe3cb0b032b3 INFO: start
2022-12-19T18:46:19Z app[sidekiq] dc1 [info]2022-12-19T18:46:19.751Z pid=520 tid=afg4 class=ActivityPub::SynchronizeFeaturedCollectionWorker jid=d2203001a0dd98fd02a534bb elapsed=0.377 INFO: done
2022-12-19T18:46:19Z app[sidekiq] dc1 [info]2022-12-19T18:46:19.752Z pid=520 tid=aab8 class=ActivityPub::SynchronizeFeaturedTagsCollectionWorker jid=7eed594ec14ffe3cb0b032b3 elapsed=0.371 INFO: done
2022-12-19T18:46:20Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/fc18311ff95a2cb9a28781883977d8f920221219-520-cikxhg.png to /tmp/4c1159771d8b18a67290578b9107dbde20221219-520-q3psyo.png
2022-12-19T18:46:20Z app[sidekiq] dc1 [info]Command :: file -b --mime '/tmp/4c1159771d8b18a67290578b9107dbde20221219-520-q3psyo.png'
2022-12-19T18:46:20Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/fc18311ff95a2cb9a28781883977d8f920221219-520-cikxhg.png to /tmp/d26f793a7c522e2bebb1fee4c579462f20221219-520-x29i38.png
2022-12-19T18:46:20Z app[sidekiq] dc1 [info]Command :: identify -format %m '/tmp/d26f793a7c522e2bebb1fee4c579462f20221219-520-x29i38.png[0]'
2022-12-19T18:46:20Z app[sidekiq] dc1 [info]Command :: convert '/tmp/d26f793a7c522e2bebb1fee4c579462f20221219-520-x29i38.png[0]' -auto-orient -resize "434x531>" -quality 90 +profile "!icc,*" +set modify-date +set create-date '/tmp/1cd8252c069474b0d95a2bc99ec0871f20221219-520-bynvm6'
2022-12-19T18:46:20Z app[sidekiq] dc1 [info]Command :: convert '/tmp/1cd8252c069474b0d95a2bc99ec0871f20221219-520-bynvm6' -depth 8 RGB:-
2022-12-19T18:46:20Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/1cd8252c069474b0d95a2bc99ec0871f20221219-520-bynvm6 to /tmp/a1fe78a06e6dea09cff0350a6e42fe0b20221219-520-rzkvui
2022-12-19T18:46:20Z app[sidekiq] dc1 [info][paperclip] saving cache/media_attachments/files/109/541/823/601/303/744/original/22feda6f15682e86.png
2022-12-19T18:46:21Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/5d0143897f2c9413144b853b79170e0620221219-520-d38zw3.jpg to /tmp/e61ea412154a3080a3c56315e619547020221219-520-muym81.jpg
2022-12-19T18:46:21Z app[sidekiq] dc1 [info]Command :: file -b --mime '/tmp/e61ea412154a3080a3c56315e619547020221219-520-muym81.jpg'
2022-12-19T18:46:21Z app[sidekiq] dc1 [info][paperclip] Trying to link /tmp/5d0143897f2c9413144b853b79170e0620221219-520-d38zw3.jpg to /tmp/537b71dc70711a327d58019203f86ee720221219-520-yyuypv.jpg
2022-12-19T18:46:21Z app[sidekiq] dc1 [info][paperclip] saving cache/media_attachments/files/109/541/823/601/303/744/small/22feda6f15682e86.png
2022-12-19T18:46:22Z app[rails] dc1 [info][088956ad-23e9-4bd2-b007-145a13796977] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=202 duration=230.56 view=0.00 db=161.37 key=https://haunted.computer/users/netspooky#main-key
2022-12-19T18:46:22Z app[sidekiq] dc1 [info]2022-12-19T18:46:22.249Z pid=520 tid=ajfc class=ActivityPub::ProcessingWorker jid=410c75405a48d3906b739e99 INFO: start
2022-12-19T18:46:22Z app[rails] dc1 [info][571097c4-d00a-4a33-b953-159793497585] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=202 duration=225.38 view=0.00 db=160.84 key=https://hachyderm.io/users/ian#main-key
2022-12-19T18:46:22Z app[sidekiq] dc1 [info]2022-12-19T18:46:22.313Z pid=520 tid=afg4 class=ActivityPub::ProcessingWorker jid=752b1a279aa378d9e70170d7 INFO: start
2022-12-19T18:46:22Z app[rails] dc1 [info][2d3f9645-e4dc-48ed-9454-11e4268279ca] method=GET path=/health format=html controller=HealthController action=show status=200 duration=1.12 view=0.74 db=0.00
^C%
~~Seems similar to https://github.com/mastodon/mastodon/discussions/22356~~
It's not similar to #22356. Not sure what's going on though, will need more investigation.
Hey @ClearlyClaire thanks for clarifying.
Anything I can do to provide more info? I'm able and willing to help dig.
One of the main things I notice is the errors are always saying they see the 'http' or 'https' part of the html href string found in folk's profile metadata fields as an invalid JSON token.
I will post more logs in here in a few hours.
Additionally, I am reminded this could very well be an artifact caused by some previous state issues with my instance's database, I would be hard pressed to see how they relate, but I suppose this additional context could be useful (if it doesn't wind up being a red-herring): https://github.com/mastodon/mastodon/issues/20820
The message is very weird, it seems that the SQL query has malformed JSON… but we do not do anything fancy to serialize this. I fail to see what could be causing this.
Here's the second batch of logs I had promised, these include a few repeated traces:
Logs:
2022-12-23T04:18:02Z app[rails] dc1 [info][602c2fc8-7bb9-480b-9d64-e0daba22d0de] lib/mastodon/rack_middleware.rb:9:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=500 error='ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:02Z app[rails] dc1 [info]LINE 10: ...s/iamvlaaaaaaad/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:02Z app[rails] dc1 [info] ^
2022-12-23T04:18:02Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:02Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Twitter","value":"\\u003ca href=\\"https...
2022-12-23T04:18:02Z app[rails] dc1 [info]' duration=3377.65 view=0.00 db=397.52 key=https://hachyderm.io/users/iamvlaaaaaaad#main-key
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae]
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:02Z app[rails] dc1 [info]LINE 10: ...s/iamvlaaaaaaad/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:02Z app[rails] dc1 [info] ^
2022-12-23T04:18:02Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:02Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Twitter","value":"\\u003ca href=\\"https...
2022-12-23T04:18:02Z app[rails] dc1 [info]):
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae]
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/models/account.rb:343:in `save_with_optional_media!'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/services/activitypub/process_account_service.rb:75:in `update_account'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/services/activitypub/process_account_service.rb:29:in `block in call'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/models/concerns/lockable.rb:10:in `block in with_lock'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/lib/redis_configuration.rb:10:in `with'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/models/concerns/redisable.rb:9:in `with_redis'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/models/concerns/lockable.rb:9:in `with_lock'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/services/activitypub/process_account_service.rb:21:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/services/activitypub/fetch_remote_actor_service.rb:38:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/services/activitypub/fetch_remote_key_service.rb:49:in `find_actor'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/services/activitypub/fetch_remote_key_service.rb:30:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/controllers/concerns/signature_verification.rb:249:in `block in actor_from_key_id'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/controllers/concerns/signature_verification.rb:263:in `stoplight_wrap_request'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/controllers/concerns/signature_verification.rb:249:in `actor_from_key_id'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/controllers/concerns/signature_verification.rb:89:in `signed_request_actor'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] app/controllers/concerns/signature_verification.rb:53:in `require_actor_signature!'
2022-12-23T04:18:02Z app[rails] dc1 [info][3e424296-8c6a-4eb0-8822-ec24615440ae] lib/mastodon/rack_middleware.rb:9:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=500 error='ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:02Z app[rails] dc1 [info]LINE 10: .../users/jadeonly/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:02Z app[rails] dc1 [info] ^
2022-12-23T04:18:02Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:02Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Website","value":"\\u003ca href=\\"https...
2022-12-23T04:18:02Z app[rails] dc1 [info]' duration=3559.77 view=0.00 db=396.19 key=https://hachyderm.io/users/jadeonly#main-key
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155]
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:02Z app[rails] dc1 [info]LINE 10: .../users/jadeonly/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:02Z app[rails] dc1 [info] ^
2022-12-23T04:18:02Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:02Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Website","value":"\\u003ca href=\\"https...
2022-12-23T04:18:02Z app[rails] dc1 [info]):
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155]
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/models/account.rb:343:in `save_with_optional_media!'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/services/activitypub/process_account_service.rb:75:in `update_account'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/services/activitypub/process_account_service.rb:29:in `block in call'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/models/concerns/lockable.rb:10:in `block in with_lock'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/lib/redis_configuration.rb:10:in `with'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/models/concerns/redisable.rb:9:in `with_redis'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/models/concerns/lockable.rb:9:in `with_lock'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/services/activitypub/process_account_service.rb:21:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/services/activitypub/fetch_remote_actor_service.rb:38:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/services/activitypub/fetch_remote_key_service.rb:49:in `find_actor'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/services/activitypub/fetch_remote_key_service.rb:30:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/controllers/concerns/signature_verification.rb:249:in `block in actor_from_key_id'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/controllers/concerns/signature_verification.rb:263:in `stoplight_wrap_request'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/controllers/concerns/signature_verification.rb:249:in `actor_from_key_id'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/controllers/concerns/signature_verification.rb:89:in `signed_request_actor'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] app/controllers/concerns/signature_verification.rb:53:in `require_actor_signature!'
2022-12-23T04:18:02Z app[rails] dc1 [info][a9aedeaa-58d9-4473-89a7-0c4ebf3d5155] lib/mastodon/rack_middleware.rb:9:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=500 error='ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:02Z app[rails] dc1 [info]LINE 10: ...users/codeyarns/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:02Z app[rails] dc1 [info] ^
2022-12-23T04:18:02Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:02Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Homepage","value":"\\u003ca href=\\"https...
2022-12-23T04:18:02Z app[rails] dc1 [info]' duration=3548.31 view=0.00 db=399.20 key=https://hachyderm.io/users/codeyarns#main-key
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a]
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:02Z app[rails] dc1 [info]LINE 10: ...users/codeyarns/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:02Z app[rails] dc1 [info] ^
2022-12-23T04:18:02Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:02Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Homepage","value":"\\u003ca href=\\"https...
2022-12-23T04:18:02Z app[rails] dc1 [info]):
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a]
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/models/account.rb:343:in `save_with_optional_media!'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/services/activitypub/process_account_service.rb:75:in `update_account'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/services/activitypub/process_account_service.rb:29:in `block in call'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/models/concerns/lockable.rb:10:in `block in with_lock'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/lib/redis_configuration.rb:10:in `with'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/models/concerns/redisable.rb:9:in `with_redis'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/models/concerns/lockable.rb:9:in `with_lock'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/services/activitypub/process_account_service.rb:21:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/services/activitypub/fetch_remote_actor_service.rb:38:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/services/activitypub/fetch_remote_key_service.rb:49:in `find_actor'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/services/activitypub/fetch_remote_key_service.rb:30:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/controllers/concerns/signature_verification.rb:249:in `block in actor_from_key_id'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/controllers/concerns/signature_verification.rb:263:in `stoplight_wrap_request'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/controllers/concerns/signature_verification.rb:249:in `actor_from_key_id'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/controllers/concerns/signature_verification.rb:89:in `signed_request_actor'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] app/controllers/concerns/signature_verification.rb:53:in `require_actor_signature!'
2022-12-23T04:18:02Z app[rails] dc1 [info][38a1787a-7527-444b-82ea-18ded998ec2a] lib/mastodon/rack_middleware.rb:9:in `call'
2022-12-23T04:18:02Z app[rails] dc1 [info][4963e491-499d-4e6a-bca0-3fce077c0e55] method=GET path=/api/v1/instance format=*/* controller=Api::V1::InstancesController action=show status=200 duration=545.23 view=83.52 db=457.94
2022-12-23T04:18:02Z app[sidekiq] dc1 [info]2022-12-23T04:18:02.929Z pid=520 tid=dzso class=LinkCrawlWorker jid=af80a40feebe5edb3f4da9b8 INFO: start
2022-12-23T04:18:03Z app[rails] dc1 [info][af763570-8cd5-4e2f-b7bf-ec8c36724ff2] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=202 duration=208.50 view=0.00 db=148.16 key=https://ravenation.club/users/AlgoCompSynth#main-key
2022-12-23T04:18:03Z app[sidekiq] dc1 [info]2022-12-23T04:18:03.151Z pid=520 tid=dvn8 class=ActivityPub::ProcessingWorker jid=b9e1bd0de575965b85840b88 INFO: start
2022-12-23T04:18:03Z app[rails] dc1 [info][52b2002e-2c5e-41a9-b438-9b616579e1a6] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=202 duration=210.33 view=0.00 db=148.06 key=https://mas.to/users/BlackAzizAnansi#main-key
2022-12-23T04:18:03Z app[sidekiq] dc1 [info]2022-12-23T04:18:03.302Z pid=520 tid=e2as class=ActivityPub::ProcessingWorker jid=f4d21281c99528e56b18e245 INFO: start
2022-12-23T04:18:03Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] [paperclip] Trying to link /tmp/2f43bc7baa116cce1fe3454ad1cc4d6720221223-529-rpzxtx.jpg to /tmp/06340760d417a3fda1ea4afaff72b4ae20221223-529-re0sf3.jpg
2022-12-23T04:18:03Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] Command :: file -b --mime '/tmp/06340760d417a3fda1ea4afaff72b4ae20221223-529-re0sf3.jpg'
2022-12-23T04:18:03Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] [paperclip] Trying to link /tmp/2f43bc7baa116cce1fe3454ad1cc4d6720221223-529-rpzxtx.jpg to /tmp/6427591d4f0b220695a24dd8665d11e120221223-529-8uily3.jpg
2022-12-23T04:18:03Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] [paperclip] Trying to link /tmp/a3a581bf82921dfe198c139b6ecc772b20221223-529-tmiamr.jpg to /tmp/7c2ff37f14373e584d525e4c87a73e9020221223-529-faxmhs.jpg
2022-12-23T04:18:03Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] Command :: file -b --mime '/tmp/7c2ff37f14373e584d525e4c87a73e9020221223-529-faxmhs.jpg'
2022-12-23T04:18:03Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] Command :: identify -format %m '/tmp/a3a581bf82921dfe198c139b6ecc772b20221223-529-tmiamr.jpg[0]'
2022-12-23T04:18:03Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] Command :: convert '/tmp/a3a581bf82921dfe198c139b6ecc772b20221223-529-tmiamr.jpg[0]' -auto-orient -resize "1061x707>" +profile "!icc,*" +set modify-date +set create-date '/tmp/44efa7a95d98580cf96b0198897d5bd920221223-529-g789uw'
2022-12-23T04:18:03Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] [paperclip] Trying to link /tmp/44efa7a95d98580cf96b0198897d5bd920221223-529-g789uw to /tmp/3bf599b282830d40be2b2f00889983dc20221223-529-ubantv
2022-12-23T04:18:04Z app[sidekiq] dc1 [info]2022-12-23T04:18:04.185Z pid=520 tid=e3e0 class=DistributionWorker jid=e287f3a26f6f2c61a1cc7d05 INFO: start
2022-12-23T04:18:04Z app[sidekiq] dc1 [info]2022-12-23T04:18:04.189Z pid=520 tid=dvn8 class=ActivityPub::ProcessingWorker jid=b9e1bd0de575965b85840b88 elapsed=1.038 INFO: done
2022-12-23T04:18:04Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] [paperclip] Trying to link /tmp/6d79a14a0ebaeaf7c00a8b0fc118b0b120221223-529-x4flxa.png to /tmp/33748ebdfbd94e72133e59509fe7712f20221223-529-rdrcx2.png
2022-12-23T04:18:04Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] Command :: file -b --mime '/tmp/33748ebdfbd94e72133e59509fe7712f20221223-529-rdrcx2.png'
2022-12-23T04:18:04Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] [paperclip] Trying to link /tmp/6d79a14a0ebaeaf7c00a8b0fc118b0b120221223-529-x4flxa.png to /tmp/a28ef4aa89a4d393e3baabd956a54fcb20221223-529-drze3y.png
2022-12-23T04:18:04Z app[sidekiq] dc1 [info]2022-12-23T04:18:04.575Z pid=520 tid=dzso class=LinkCrawlWorker jid=af80a40feebe5edb3f4da9b8 elapsed=1.646 INFO: done
2022-12-23T04:18:04Z app[sidekiq] dc1 [info]2022-12-23T04:18:04.607Z pid=520 tid=dvn8 class=DistributionWorker jid=13dabeea5f168e3b4216c5d1 INFO: start
2022-12-23T04:18:04Z app[sidekiq] dc1 [info]2022-12-23T04:18:04.661Z pid=520 tid=e2as class=ActivityPub::ProcessingWorker jid=f4d21281c99528e56b18e245 elapsed=1.358 INFO: done
2022-12-23T04:18:04Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] [paperclip] Trying to link /tmp/89cb105f5b443da2b5c8b5a3f0b8576c20221223-529-83nfnl.jpeg to /tmp/546a82f7a1ac4f4cab979581497f0a1620221223-529-fy4nx4.jpeg
2022-12-23T04:18:04Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] Command :: file -b --mime '/tmp/546a82f7a1ac4f4cab979581497f0a1620221223-529-fy4nx4.jpeg'
2022-12-23T04:18:04Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] [paperclip] Trying to link /tmp/89cb105f5b443da2b5c8b5a3f0b8576c20221223-529-83nfnl.jpeg to /tmp/d9d17520d97540ec7361a0066abe919420221223-529-bhmxld.jpeg
2022-12-23T04:18:05Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] [paperclip] Trying to link /tmp/0c2ba650159abfea509930a898eea06320221223-529-l1lp8o.jpeg to /tmp/4acf7e74e0e936a0b6abd96c4081fff820221223-529-2ovswk.jpeg
2022-12-23T04:18:05Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] Command :: file -b --mime '/tmp/4acf7e74e0e936a0b6abd96c4081fff820221223-529-2ovswk.jpeg'
2022-12-23T04:18:05Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] [paperclip] Trying to link /tmp/0c2ba650159abfea509930a898eea06320221223-529-l1lp8o.jpeg to /tmp/d76c254b0f3853c4251daf959722010820221223-529-hcd9xz.jpeg
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=500 error='ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:05Z app[rails] dc1 [info]LINE 10: ...sers/gnarlygeek/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:05Z app[rails] dc1 [info] ^
2022-12-23T04:18:05Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:05Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Twittodon","value":"\\u003ca href=\\"https...
2022-12-23T04:18:05Z app[rails] dc1 [info]' duration=3341.69 view=0.00 db=396.58 key=https://hachyderm.io/users/gnarlygeek#main-key
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c]
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:05Z app[rails] dc1 [info]LINE 10: ...sers/gnarlygeek/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:05Z app[rails] dc1 [info] ^
2022-12-23T04:18:05Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:05Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Twittodon","value":"\\u003ca href=\\"https...
2022-12-23T04:18:05Z app[rails] dc1 [info]):
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c]
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/models/account.rb:343:in `save_with_optional_media!'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/services/activitypub/process_account_service.rb:75:in `update_account'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/services/activitypub/process_account_service.rb:29:in `block in call'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/models/concerns/lockable.rb:10:in `block in with_lock'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/lib/redis_configuration.rb:10:in `with'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/models/concerns/redisable.rb:9:in `with_redis'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/models/concerns/lockable.rb:9:in `with_lock'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/services/activitypub/process_account_service.rb:21:in `call'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/services/activitypub/fetch_remote_actor_service.rb:38:in `call'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/services/activitypub/fetch_remote_key_service.rb:49:in `find_actor'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/services/activitypub/fetch_remote_key_service.rb:30:in `call'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/controllers/concerns/signature_verification.rb:249:in `block in actor_from_key_id'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/controllers/concerns/signature_verification.rb:263:in `stoplight_wrap_request'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/controllers/concerns/signature_verification.rb:249:in `actor_from_key_id'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/controllers/concerns/signature_verification.rb:89:in `signed_request_actor'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] app/controllers/concerns/signature_verification.rb:53:in `require_actor_signature!'
2022-12-23T04:18:05Z app[rails] dc1 [info][9702c2bc-e4c9-4f14-8c2c-04efd84aa21c] lib/mastodon/rack_middleware.rb:9:in `call'
2022-12-23T04:18:05Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] [paperclip] Trying to link /tmp/422d5c2ce1f12c92f0673c4ccfda749f20221223-529-qpgtce.jpeg to /tmp/95dd204f19b1e2c78370214c06b99e8d20221223-529-ku3coi.jpeg
2022-12-23T04:18:05Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] Command :: file -b --mime '/tmp/95dd204f19b1e2c78370214c06b99e8d20221223-529-ku3coi.jpeg'
2022-12-23T04:18:05Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] [paperclip] Trying to link /tmp/422d5c2ce1f12c92f0673c4ccfda749f20221223-529-qpgtce.jpeg to /tmp/6cc279985ad50fe6de4e53dab3046f3620221223-529-b32h5.jpeg
2022-12-23T04:18:05Z app[sidekiq] dc1 [info]2022-12-23T04:18:05.297Z pid=520 tid=dscw class=FeedInsertWorker jid=b866247f168bb46bfbe977d8 INFO: start
2022-12-23T04:18:05Z app[sidekiq] dc1 [info]2022-12-23T04:18:05.350Z pid=520 tid=e3e0 class=DistributionWorker jid=e287f3a26f6f2c61a1cc7d05 elapsed=1.165 INFO: done
2022-12-23T04:18:05Z app[sidekiq] dc1 [info]2022-12-23T04:18:05.351Z pid=520 tid=dvn8 class=DistributionWorker jid=13dabeea5f168e3b4216c5d1 elapsed=0.744 INFO: done
2022-12-23T04:18:05Z app[rails] dc1 [info][61de6a58-76f9-47af-8cea-a8be9014ce43] method=GET path=/health format=html controller=HealthController action=show status=200 duration=0.77 view=0.27 db=0.00
2022-12-23T04:18:06Z app[sidekiq] dc1 [info]2022-12-23T04:18:06.024Z pid=520 tid=dscw class=FeedInsertWorker jid=b866247f168bb46bfbe977d8 elapsed=0.728 INFO: done
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=500 error='ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:06Z app[rails] dc1 [info]LINE 10: .../users/markphip/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:06Z app[rails] dc1 [info] ^
2022-12-23T04:18:06Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:06Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"GitHub","value":"\\u003ca href=\\"https...
2022-12-23T04:18:06Z app[rails] dc1 [info]' duration=3419.54 view=0.00 db=401.18 key=https://hachyderm.io/users/markphip#main-key
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8]
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:06Z app[rails] dc1 [info]LINE 10: .../users/markphip/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:06Z app[rails] dc1 [info] ^
2022-12-23T04:18:06Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:06Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"GitHub","value":"\\u003ca href=\\"https...
2022-12-23T04:18:06Z app[rails] dc1 [info]):
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8]
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/models/account.rb:343:in `save_with_optional_media!'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/services/activitypub/process_account_service.rb:75:in `update_account'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/services/activitypub/process_account_service.rb:29:in `block in call'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/models/concerns/lockable.rb:10:in `block in with_lock'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/lib/redis_configuration.rb:10:in `with'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/models/concerns/redisable.rb:9:in `with_redis'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/models/concerns/lockable.rb:9:in `with_lock'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/services/activitypub/process_account_service.rb:21:in `call'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/services/activitypub/fetch_remote_actor_service.rb:38:in `call'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/services/activitypub/fetch_remote_key_service.rb:49:in `find_actor'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/services/activitypub/fetch_remote_key_service.rb:30:in `call'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/controllers/concerns/signature_verification.rb:249:in `block in actor_from_key_id'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/controllers/concerns/signature_verification.rb:263:in `stoplight_wrap_request'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/controllers/concerns/signature_verification.rb:249:in `actor_from_key_id'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/controllers/concerns/signature_verification.rb:89:in `signed_request_actor'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] app/controllers/concerns/signature_verification.rb:53:in `require_actor_signature!'
2022-12-23T04:18:06Z app[rails] dc1 [info][2098d010-61c0-48f6-afca-46ac3481aae8] lib/mastodon/rack_middleware.rb:9:in `call'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=500 error='ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:07Z app[rails] dc1 [info]LINE 10: ...l/users/rgordon/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:07Z app[rails] dc1 [info] ^
2022-12-23T04:18:07Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:07Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Website","value":"\\u003ca href=\\"https...
2022-12-23T04:18:07Z app[rails] dc1 [info]' duration=4494.30 view=0.00 db=397.50 key=https://mastodon.social/users/rgordon#main-key
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d]
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:07Z app[rails] dc1 [info]LINE 10: ...l/users/rgordon/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:07Z app[rails] dc1 [info] ^
2022-12-23T04:18:07Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:07Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: [{"name":"Website","value":"\\u003ca href=\\"https...
2022-12-23T04:18:07Z app[rails] dc1 [info]):
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d]
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/models/account.rb:343:in `save_with_optional_media!'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/services/activitypub/process_account_service.rb:75:in `update_account'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/services/activitypub/process_account_service.rb:29:in `block in call'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/models/concerns/lockable.rb:10:in `block in with_lock'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/lib/redis_configuration.rb:10:in `with'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/models/concerns/redisable.rb:9:in `with_redis'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/models/concerns/lockable.rb:9:in `with_lock'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/services/activitypub/process_account_service.rb:21:in `call'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/services/activitypub/fetch_remote_actor_service.rb:38:in `call'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/services/activitypub/fetch_remote_key_service.rb:49:in `find_actor'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/services/activitypub/fetch_remote_key_service.rb:30:in `call'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/controllers/concerns/signature_verification.rb:249:in `block in actor_from_key_id'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/controllers/concerns/signature_verification.rb:263:in `stoplight_wrap_request'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/controllers/concerns/signature_verification.rb:249:in `actor_from_key_id'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/controllers/concerns/signature_verification.rb:89:in `signed_request_actor'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] app/controllers/concerns/signature_verification.rb:53:in `require_actor_signature!'
2022-12-23T04:18:07Z app[rails] dc1 [info][0f4c9cf2-ce3a-4313-a9ea-3854f67f988d] lib/mastodon/rack_middleware.rb:9:in `call'
2022-12-23T04:18:13Z app[rails] dc1 [info][fe72d2eb-29d5-4219-b3f6-34860d2c8c15] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=202 duration=215.00 view=0.00 db=148.82 key=https://journa.host/users/juddlegum#main-key
2022-12-23T04:18:13Z app[sidekiq] dc1 [info]2022-12-23T04:18:13.116Z pid=520 tid=e3e0 class=ActivityPub::ProcessingWorker jid=ee5293d8aaef3ef9581987c7 INFO: start
2022-12-23T04:18:14Z app[rails] dc1 [info][65af563e-1a70-40b9-af8a-ae9faf60b235] method=GET path=/api/v1/timelines/public format=html controller=Api::V1::Timelines::PublicController action=show status=200 duration=1257.11 view=57.97 db=1094.16
2022-12-23T04:18:16Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] [paperclip] Trying to link /tmp/012c07808aec4b985dbefb91dd6a207a20221223-529-yhj299.jpg to /tmp/d69a24ede348b2365fdfd797b1e52d2620221223-529-vprwy1.jpg
2022-12-23T04:18:16Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] Command :: file -b --mime '/tmp/d69a24ede348b2365fdfd797b1e52d2620221223-529-vprwy1.jpg'
2022-12-23T04:18:16Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] [paperclip] Trying to link /tmp/012c07808aec4b985dbefb91dd6a207a20221223-529-yhj299.jpg to /tmp/4c3b37984bed7366e859c0bd4d4da01520221223-529-2gkijj.jpg
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] method=POST path=/inbox format=html controller=ActivityPub::InboxesController action=create status=500 error='ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:18Z app[rails] dc1 [info]LINE 10: ...ial/users/sigue/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:18Z app[rails] dc1 [info] ^
2022-12-23T04:18:18Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:18Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: ...name":"My GitHub","value":"\\u003ca href=\\"https...
2022-12-23T04:18:18Z app[rails] dc1 [info]' duration=4112.95 view=0.00 db=400.23 key=https://mastodon.social/users/sigue#main-key
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761]
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:18:18Z app[rails] dc1 [info]LINE 10: ...ial/users/sigue/collections/featured', "fields" = '[{"name":...
2022-12-23T04:18:18Z app[rails] dc1 [info] ^
2022-12-23T04:18:18Z app[rails] dc1 [info]DETAIL: Token "https" is invalid.
2022-12-23T04:18:18Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: ...name":"My GitHub","value":"\\u003ca href=\\"https...
2022-12-23T04:18:18Z app[rails] dc1 [info]):
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761]
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/models/account.rb:343:in `save_with_optional_media!'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/services/activitypub/process_account_service.rb:75:in `update_account'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/services/activitypub/process_account_service.rb:29:in `block in call'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/models/concerns/lockable.rb:12:in `block (2 levels) in with_lock'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/models/concerns/lockable.rb:10:in `block in with_lock'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/lib/redis_configuration.rb:10:in `with'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/models/concerns/redisable.rb:9:in `with_redis'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/models/concerns/lockable.rb:9:in `with_lock'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/services/activitypub/process_account_service.rb:21:in `call'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/services/activitypub/fetch_remote_actor_service.rb:38:in `call'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/services/activitypub/fetch_remote_key_service.rb:49:in `find_actor'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/services/activitypub/fetch_remote_key_service.rb:30:in `call'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/controllers/concerns/signature_verification.rb:249:in `block in actor_from_key_id'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/controllers/concerns/signature_verification.rb:263:in `stoplight_wrap_request'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/controllers/concerns/signature_verification.rb:249:in `actor_from_key_id'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/controllers/concerns/signature_verification.rb:89:in `signed_request_actor'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] app/controllers/concerns/signature_verification.rb:53:in `require_actor_signature!'
2022-12-23T04:18:18Z app[rails] dc1 [info][34992120-35f9-4e45-b52b-82b5909d9761] lib/mastodon/rack_middleware.rb:9:in `call'
As it appears, this happens when certain accounts with http or https in them are encountered by my server.
While fiddling around on my own server trying to see if there's some weird behaviour, I did notice that you cannot put the doublequote character " anywhere in your bio metadata, it will cause a 500 error, so I do suspect something is parsing this content incorrectly/weirdly.
Here are much more concise logs for me specifically trying to update my bio metadata to a value that contains a doublequote ("):
Logs:
2022-12-23T04:32:27Z app[sidekiq] dc1 [info]2022-12-23T04:32:27.087Z pid=520 tid=gisw class=ActivityPub::ProcessingWorker jid=89fbe5ece951ac1e542d510a INFO: start
2022-12-23T04:32:27Z app[rails] dc1 [info][ebcd5ea2-7c67-4912-967d-00588bd434ad] method=PUT path=/settings/profile format=html controller=Settings::ProfilesController action=update status=500 error='ActiveRecord::StatementInvalid: PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:32:27Z app[rails] dc1 [info]LINE 1: ...ed_at" = '2022-12-23 04:32:27.067657', "fields" = '[{"name":...
2022-12-23T04:32:27Z app[rails] dc1 [info] ^
2022-12-23T04:32:27Z app[rails] dc1 [info]DETAIL: Expected "," or "}", but found ""},{"".
2022-12-23T04:32:27Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: ...klambda.dev"},{"name":"tech","value":"bro\\""},{"...
2022-12-23T04:32:27Z app[rails] dc1 [info]' duration=410.62 view=0.00 db=346.31
2022-12-23T04:32:27Z app[rails] dc1 [info][ebcd5ea2-7c67-4912-967d-00588bd434ad]
2022-12-23T04:32:27Z app[rails] dc1 [info][ebcd5ea2-7c67-4912-967d-00588bd434ad] ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR: invalid input syntax for type json
2022-12-23T04:32:27Z app[rails] dc1 [info]LINE 1: ...ed_at" = '2022-12-23 04:32:27.067657', "fields" = '[{"name":...
2022-12-23T04:32:27Z app[rails] dc1 [info] ^
2022-12-23T04:32:27Z app[rails] dc1 [info]DETAIL: Expected "," or "}", but found ""},{"".
2022-12-23T04:32:27Z app[rails] dc1 [info]CONTEXT: JSON data, line 1: ...klambda.dev"},{"name":"tech","value":"bro\\""},{"...
2022-12-23T04:32:27Z app[rails] dc1 [info]):
2022-12-23T04:32:27Z app[rails] dc1 [info][ebcd5ea2-7c67-4912-967d-00588bd434ad]
2022-12-23T04:32:27Z app[rails] dc1 [info][ebcd5ea2-7c67-4912-967d-00588bd434ad] app/services/update_account_service.rb:8:in `call'
2022-12-23T04:32:27Z app[rails] dc1 [info][ebcd5ea2-7c67-4912-967d-00588bd434ad] app/controllers/settings/profiles_controller.rb:11:in `update'
2022-12-23T04:32:27Z app[rails] dc1 [info][ebcd5ea2-7c67-4912-967d-00588bd434ad] app/controllers/concerns/localized.rb:11:in `set_locale'
2022-12-23T04:32:27Z app[rails] dc1 [info][ebcd5ea2-7c67-4912-967d-00588bd434ad] lib/mastodon/rack_middleware.rb:9:in `call'
It seems to be the same type of error as all those errors seen from remote accounts.
Yeah, the " should be properly escaped by Rails, we really don't do anything fancy with that. How did you install Ruby? Are you perhaps using an unusual locale? What's your database's locale?
Unsure how to check db locale, but I can check in a bit. My DB is hosted via a Postgres as a Service provider (neon.tech)
As far as ruby install goes, I'm on fly.io hosting the latest mastodon docker image, no further modifications beyond env vars (I do not see anything relating to locale in my fly.toml (the source of env vars)).
I've ran show in the database on all the values mentioned here:
| LC_COLLATE | String sort order |
|---|---|
| LC_CTYPE | Character classification (What is a letter? Its upper-case equivalent?) |
| LC_MESSAGES | Language of messages |
| LC_MONETARY | Formatting of currency amounts |
| LC_NUMERIC | Formatting of numbers |
| LC_TIME | Formatting of dates and times |
It appears they all show C as the output (except for LC_MESSAGES which shows no value) so I believe that says I have no locale set, or the "standard" local chosen?
I'm afraid I have no idea what is occurring and I don't have many leads…
What happens if you run the following in a Rails console (RAILS_ENV=production bundle exec rails c):
ActiveRecord::Base.verbose_query_logs = true
Account.find(-99).update!(fields: [{name: 'test', value: '<a href="#">test</a>'}])
Hey @ClearlyClaire , sorry for the long delay. Thanks for your continued help, and happy new year.
root@c3981f2b:/mastodon# RAILS_ENV=production bundle exec rails c
Chewy console strategy is `urgent`
Loading production environment (Rails 6.1.7)
irb(main):001:0> ActiveRecord::Base.verbose_query_logs = true
=> true
irb(main):002:0> Account.find(-99).update!(fields: [{name: 'test', value: '<a href="#">test</a>'}])
=> true
irb(main):003:0>
I'm not certain how to interpret either of these results.
WHOA, I think this may have fixed the issue? I was just able to find an account, that prior to running these two commands I was unable to search for via my server (it would error out as with these 5xx errors documented above).
I'm going to monitor my logs and see if the 5xx errors have stopped and check if sidekiq jobs stopped failing.
Can you explain your hunch and what those commands performed?
Sorry, the rails console should have been started with RAILS_LOG_LEVEL=debug, that is, RAILS_LOG_LEVEL=debug RAILS_ENV=production bundle exec rails c.
The purpose was not to fix anything (I can't see how it could have), but to run a simple query similar to the ones that seem to cause issues for you, while printing out the exact SQL query generated by Rails in those cases.
Well this is incredibly bizarre timing, but it appears my issue has either subsided or resolved itself. No changes on my end beyond upping the amount of RAM available to sidekiq, so I'm wondering if my Postgres host was doing some changes. 🤔
I can provide those queries just for more documentation purposes after work today.
I think this issue can be tentatively closed, I will bump it if it reappears.
Closed, since this was almost certainly a bug in the upstream Postgres provider
