Certain message cannot be sent in chat

Bug
1

For some reason on two different non-Meta forums, this exact message cannot be sent in chat:

???
```
firepup650@firepi:~/projects/python/bitbot $ sudo journalctl -fu h-bitbot
Sep 16 18:21:33 firepi systemd[1]: Starting h-bitbot.service - 9pfs's bitbot...
Sep 16 18:21:33 firepi systemd[1]: Started h-bitbot.service - 9pfs's bitbot.
Sep 16 18:21:34 firepi systemd[1]: h-bitbot.service: Main process exited, code=exited, status=1/FAILURE
Sep 16 18:21:34 firepi systemd[1]: h-bitbot.service: Failed with result 'exit-code'.
Sep 16 18:21:34 firepi systemd[1]: h-bitbot.service: Consumed 1.157s CPU time, no IP traffic.
Sep 16 18:21:39 firepi systemd[1]: h-bitbot.service: Scheduled restart job, restart counter is at 84.
Sep 16 18:21:39 firepi systemd[1]: Stopped h-bitbot.service - 9pfs's bitbot.
Sep 16 18:21:39 firepi systemd[1]: h-bitbot.service: Consumed 1.157s CPU time, no IP traffic.
Sep 16 18:21:39 firepi systemd[1]: Starting h-bitbot.service - 9pfs's bitbot...
Sep 16 18:21:39 firepi systemd[1]: Started h-bitbot.service - 9pfs's bitbot.
Sep 16 18:21:42 firepi systemd[1]: h-bitbot.service: Main process exited, code=exited, status=1/FAILURE
```

Removing either the ??? from the first line, or the last line of that log snippet causes it to send properly.

For some reason, I cannot reproduce this on Meta however.

It causes the error both at https://forum.obl.ong/ and https://amcforum.wiki/, it causes a 500 error, logs from AMC are:

Kinda long log 
Message (28 copies reported)

Failed to handle exception in exception app middleware : ActiveRecord::ValueTooLong : PG::StringDataRightTruncation: ERROR:  value too long for type character varying(1000)


Backtrace

rack-mini-profiler-3.3.1/lib/patches/db/pg.rb:72:in `exec_params'
rack-mini-profiler-3.3.1/lib/patches/db/pg.rb:72:in `exec_params'
activerecord-7.1.4/lib/active_record/connection_adapters/postgresql_adapter.rb:894:in `block (2 levels) in exec_no_cache'
activerecord-7.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:1027:in `block in with_raw_connection'
activesupport-7.1.4/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
activerecord-7.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:999:in `with_raw_connection'
activerecord-7.1.4/lib/active_record/connection_adapters/postgresql_adapter.rb:893:in `block in exec_no_cache'
activesupport-7.1.4/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
activerecord-7.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:1142:in `log'
activerecord-7.1.4/lib/active_record/connection_adapters/postgresql_adapter.rb:892:in `exec_no_cache'
activerecord-7.1.4/lib/active_record/connection_adapters/postgresql_adapter.rb:872:in `execute_and_clear'
activerecord-7.1.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:64:in `internal_exec_query'
activerecord-7.1.4/lib/active_record/connection_adapters/abstract/database_statements.rb:153:in `exec_insert'
activerecord-7.1.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:83:in `exec_insert'
activerecord-7.1.4/lib/active_record/connection_adapters/abstract/database_statements.rb:191:in `insert'
activerecord-7.1.4/lib/active_record/connection_adapters/abstract/query_cache.rb:25:in `insert'
activerecord-7.1.4/lib/active_record/persistence.rb:588:in `_insert_record'
activerecord-7.1.4/lib/active_record/persistence.rb:1252:in `_create_record'
activerecord-7.1.4/lib/active_record/counter_cache.rb:188:in `_create_record'
activerecord-7.1.4/lib/active_record/locking/optimistic.rb:84:in `_create_record'
activerecord-7.1.4/lib/active_record/encryption/encryptable_record.rb:184:in `_create_record'
activerecord-7.1.4/lib/active_record/attribute_methods/dirty.rb:240:in `_create_record'
activerecord-7.1.4/lib/active_record/callbacks.rb:445:in `block in _create_record'
activesupport-7.1.4/lib/active_support/callbacks.rb:110:in `run_callbacks'
activesupport-7.1.4/lib/active_support/callbacks.rb:952:in `_run_create_callbacks'
activerecord-7.1.4/lib/active_record/callbacks.rb:445:in `_create_record'
activerecord-7.1.4/lib/active_record/timestamp.rb:116:in `_create_record'
activerecord-7.1.4/lib/active_record/persistence.rb:1221:in `create_or_update'
activerecord-7.1.4/lib/active_record/callbacks.rb:441:in `block in create_or_update'
activesupport-7.1.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
activerecord-7.1.4/lib/active_record/autosave_association.rb:375:in `around_save_collection_association'
activesupport-7.1.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
activesupport-7.1.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
activesupport-7.1.4/lib/active_support/callbacks.rb:952:in `_run_save_callbacks'
activerecord-7.1.4/lib/active_record/callbacks.rb:441:in `create_or_update'
activerecord-7.1.4/lib/active_record/timestamp.rb:127:in `create_or_update'
activerecord-7.1.4/lib/active_record/persistence.rb:751:in `save!'
activerecord-7.1.4/lib/active_record/validations.rb:55:in `save!'
activerecord-7.1.4/lib/active_record/transactions.rb:313:in `block in save!'
activerecord-7.1.4/lib/active_record/transactions.rb:365:in `block in with_transaction_returning_status'
activerecord-7.1.4/lib/active_record/connection_adapters/abstract/database_statements.rb:342:in `transaction'
activerecord-7.1.4/lib/active_record/transactions.rb:361:in `with_transaction_returning_status'
activerecord-7.1.4/lib/active_record/transactions.rb:313:in `save!'
activerecord-7.1.4/lib/active_record/suppressor.rb:56:in `save!'
/var/www/discourse/plugins/chat/app/services/chat/create_message.rb:159:in `save_message'
/var/www/discourse/app/services/service/base.rb:117:in `instance_exec'
/var/www/discourse/app/services/service/base.rb:117:in `call'
/var/www/discourse/app/services/service/base.rb:207:in `block (2 levels) in call'
/var/www/discourse/app/services/service/base.rb:207:in `each'
/var/www/discourse/app/services/service/base.rb:207:in `block in call'
activerecord-7.1.4/lib/active_record/connection_adapters/abstract/transaction.rb:535:in `block in within_new_transaction'
activesupport-7.1.4/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
activerecord-7.1.4/lib/active_record/connection_adapters/abstract/transaction.rb:532:in `within_new_transaction'
activerecord-7.1.4/lib/active_record/connection_adapters/abstract/database_statements.rb:344:in `transaction'
activerecord-7.1.4/lib/active_record/transactions.rb:212:in `transaction'
/var/www/discourse/app/services/service/base.rb:207:in `call'
/var/www/discourse/app/services/service/base.rb:374:in `block in run!'
/var/www/discourse/app/services/service/base.rb:374:in `each'
/var/www/discourse/app/services/service/base.rb:374:in `run!'
/var/www/discourse/app/services/service/base.rb:367:in `run'
<internal:kernel>:90:in `tap'
/var/www/discourse/app/services/service/base.rb:234:in `call'
/var/www/discourse/lib/service_runner.rb:141:in `block in setup_and_run_service'
/var/www/discourse/lib/service_runner.rb:138:in `instance_eval'
/var/www/discourse/lib/service_runner.rb:138:in `setup_and_run_service'
/var/www/discourse/lib/service_runner.rb:121:in `call'
/var/www/discourse/lib/service_runner.rb:115:in `call'
/var/www/discourse/app/services/service/base.rb:235:in `call'
/var/www/discourse/plugins/chat/app/controllers/chat/api/channel_messages_controller.rb:71:in `create'
actionpack-7.1.4/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
actionpack-7.1.4/lib/abstract_controller/base.rb:224:in `process_action'
actionpack-7.1.4/lib/action_controller/metal/rendering.rb:165:in `process_action'
actionpack-7.1.4/lib/abstract_controller/callbacks.rb:259:in `block in process_action'
activesupport-7.1.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/var/www/discourse/app/controllers/application_controller.rb:424:in `block in with_resolved_locale'
i18n-1.14.5/lib/i18n.rb:351:in `with_locale'
/var/www/discourse/app/controllers/application_controller.rb:424:in `with_resolved_locale'
activesupport-7.1.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
activesupport-7.1.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
actionpack-7.1.4/lib/abstract_controller/callbacks.rb:258:in `process_action'
actionpack-7.1.4/lib/action_controller/metal/rescue.rb:25:in `process_action'
actionpack-7.1.4/lib/action_controller/metal/instrumentation.rb:74:in `block in process_action'
activesupport-7.1.4/lib/active_support/notifications.rb:206:in `block in instrument'
activesupport-7.1.4/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
activesupport-7.1.4/lib/active_support/notifications.rb:206:in `instrument'
actionpack-7.1.4/lib/action_controller/metal/instrumentation.rb:73:in `process_action'
actionpack-7.1.4/lib/action_controller/metal/params_wrapper.rb:261:in `process_action'
activerecord-7.1.4/lib/active_record/railties/controller_runtime.rb:32:in `process_action'
actionpack-7.1.4/lib/abstract_controller/base.rb:160:in `process'
actionview-7.1.4/lib/action_view/rendering.rb:40:in `process'
rack-mini-profiler-3.3.1/lib/mini_profiler/profiling_methods.rb:115:in `block in profile_method'
actionpack-7.1.4/lib/action_controller/metal.rb:227:in `dispatch'
actionpack-7.1.4/lib/action_controller/metal.rb:309:in `dispatch'
actionpack-7.1.4/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
actionpack-7.1.4/lib/action_dispatch/routing/route_set.rb:32:in `serve'
actionpack-7.1.4/lib/action_dispatch/journey/router.rb:51:in `block in serve'
actionpack-7.1.4/lib/action_dispatch/journey/router.rb:131:in `block in find_routes'
actionpack-7.1.4/lib/action_dispatch/journey/router.rb:124:in `each'
actionpack-7.1.4/lib/action_dispatch/journey/router.rb:124:in `find_routes'
actionpack-7.1.4/lib/action_dispatch/journey/router.rb:32:in `serve'
actionpack-7.1.4/lib/action_dispatch/routing/route_set.rb:882:in `call'
railties-7.1.4/lib/rails/engine.rb:536:in `call'
railties-7.1.4/lib/rails/railtie.rb:226:in `public_send'
railties-7.1.4/lib/rails/railtie.rb:226:in `method_missing'
actionpack-7.1.4/lib/action_dispatch/routing/mapper.rb:31:in `block in <class:Constraints>'
actionpack-7.1.4/lib/action_dispatch/routing/mapper.rb:60:in `serve'
actionpack-7.1.4/lib/action_dispatch/journey/router.rb:51:in `block in serve'
actionpack-7.1.4/lib/action_dispatch/journey/router.rb:131:in `block in find_routes'
actionpack-7.1.4/lib/action_dispatch/journey/router.rb:124:in `each'
actionpack-7.1.4/lib/action_dispatch/journey/router.rb:124:in `find_routes'
actionpack-7.1.4/lib/action_dispatch/journey/router.rb:32:in `serve'
actionpack-7.1.4/lib/action_dispatch/routing/route_set.rb:882:in `call'
/var/www/discourse/lib/middleware/omniauth_bypass_middleware.rb:64:in `call'
rack-2.2.9/lib/rack/tempfile_reaper.rb:15:in `call'
rack-2.2.9/lib/rack/conditional_get.rb:40:in `call'
rack-2.2.9/lib/rack/head.rb:12:in `call'
actionpack-7.1.4/lib/action_dispatch/http/permissions_policy.rb:36:in `call'
/var/www/discourse/lib/content_security_policy/middleware.rb:12:in `call'
/var/www/discourse/lib/middleware/anonymous_cache.rb:393:in `call'
/var/www/discourse/lib/middlewar
2 Likes
2

It is trying to insert into the chat table and the column is limited to 1000 chars.

Maybe try this in data explorer:

SELECT 
    column_name, 
    data_type, 
    character_maximum_length
FROM 
    information_schema.columns
WHERE 
    table_name = 'chat_messages'
    AND column_name IN ('cooked', 'message')

Is there a max length defined somehow on your schema?

2 Likes
4

The value too long for type character varying(1000) indicates to me that it’s related to excerpt. This is surprising because technically we limit excerpts at 150 chars, so this case should never happen, at first I thought it was a bug in our excerpt builder but looking at the excerpt code in chat I saw this:

def build_excerpt
  # just show the URL if the whole message is a URL, because we cannot excerpt oneboxes
  return message if UrlHelper.relaxed_parse(message).is_a?(URI)

  # upload-only messages are better represented as the filename
  return uploads.first.original_filename if cooked.blank? && uploads.present?

  # this may return blank for some complex things like quotes, that is acceptable
  PrettyText.excerpt(cooked, EXCERPT_LENGTH, strip_links: true, keep_mentions: true)
end

Quick debugging has shown that we actually never reach PrettyText.excerpt and we stop at the first return. Apparently the ??? is making our code thinks this is a URL:

[1] pry(main)> UrlHelper.relaxed_parse("???\ntest").is_a?(URI)
=> true
3 Likes
8

We have identified the fix, but will take some time to land in main.

1 Like