API Error for specific UTF-8 chars in subject

[saschaarthur]

Hello,

Postal runs into trouble having a specific UTF-8 spacing character in the subject line.

Sending an E-Mail with a Subject Line including this spacing char:
https://www.fileformat.info/info/unicode/char/e0100/index.htm
fails with
{"{\"status\":\"internal-server-error\"}":500}

Any idea how to solve it?
The character seems to be accepted when placed in the E-Mail body.

[willpower232]

Are you able to find the error in the logs? We'll need to know where it went wrong.

[saschaarthur]

postal      | 13:59:52 web.1              | => [web.1:27] [2021-04-26T13:59:52.925] INFO -- : Started POST "/api/v1/send/message" for 10.9.0.2 at 2021-04-26 13:59:52 +0000
postal      | 13:59:52 web.1              | => [web.1:27] [2021-04-26T13:59:52.939] INFO -- : Mysql2::Error
postal      | 13:59:52 web.1              | => [web.1:27] [2021-04-26T13:59:52.940] INFO -- : Incorrect string value: '\xF3\xA0\x84\x80\xF3\xA0...' for column `postal-server-1`.`messages`.`subject` at row 1
postal      | 13:59:52 web.1              | => [web.1:27] [2021-04-26T13:59:52.940] INFO -- : /opt/postal/vendor/bundle/ruby/2.6.0/gems/mysql2-0.5.3/lib/mysql2/client.rb:131:in `_query'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/mysql2-0.5.3/lib/mysql2/client.rb:131:in `block in query'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/mysql2-0.5.3/lib/mysql2/client.rb:130:in `handle_interrupt'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/mysql2-0.5.3/lib/mysql2/client.rb:130:in `query'
postal      | 13:59:52 web.1              | => /opt/postal/lib/postal/message_db/database.rb:319:in `query_on_connection'
postal      | 13:59:52 web.1              | => /opt/postal/lib/postal/message_db/database.rb:224:in `block in insert'
postal      | 13:59:52 web.1              | => /opt/postal/lib/postal/message_db/mysql.rb:20:in `client'
postal      | 13:59:52 web.1              | => /opt/postal/lib/postal/message_db/database.rb:342:in `with_mysql'
postal      | 13:59:52 web.1              | => /opt/postal/lib/postal/message_db/database.rb:223:in `insert'
postal      | 13:59:52 web.1              | => /opt/postal/lib/postal/message_db/message.rb:565:in `_create'
postal      | 13:59:52 web.1              | => /opt/postal/lib/postal/message_db/message.rb:206:in `save'
postal      | 13:59:52 web.1              | => /opt/postal/app/models/outgoing_message_prototype.rb:199:in `create_message'
postal      | 13:59:52 web.1              | => /opt/postal/app/models/outgoing_message_prototype.rb:81:in `block in create_messages'
postal      | 13:59:52 web.1              | => /opt/postal/app/models/outgoing_message_prototype.rb:79:in `each'
postal      | 13:59:52 web.1              | => /opt/postal/app/models/outgoing_message_prototype.rb:79:in `each_with_object'
postal      | 13:59:52 web.1              | => /opt/postal/app/models/outgoing_message_prototype.rb:79:in `create_messages'
postal      | 13:59:52 web.1              | => /opt/postal/api/controllers/send_api_controller.rb:59:in `block (4 levels) in load_directory'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/moonrope-2.0.1/lib/moonrope/action.rb:170:in `instance_exec'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/moonrope-2.0.1/lib/moonrope/action.rb:170:in `block (2 levels) in execute'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/moonrope-2.0.1/lib/moonrope/action.rb:169:in `each'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/moonrope-2.0.1/lib/moonrope/action.rb:169:in `block in execute'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/moonrope-2.0.1/lib/moonrope/action.rb:112:in `convert_errors_to_action_result'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/moonrope-2.0.1/lib/moonrope/action.rb:156:in `execute'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/moonrope-2.0.1/lib/moonrope/request.rb:113:in `execute'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/moonrope-2.0.1/lib/moonrope/rack_middleware.rb:88:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/moonrope-2.0.1/lib/moonrope/doc_server.rb:118:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.5/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.5/lib/action_dispatch/middleware/cookies.rb:670:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.5/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.5/lib/active_support/callbacks.rb:98:in `run_callbacks'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.5/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.5/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.5/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/railties-5.2.5/lib/rails/rack/logger.rb:38:in `call_app'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/railties-5.2.5/lib/rails/rack/logger.rb:28:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.5/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.5/lib/action_dispatch/middleware/request_id.rb:27:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/activesupport-5.2.5/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.5/lib/action_dispatch/middleware/executor.rb:14:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.5/lib/action_dispatch/middleware/static.rb:127:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/secure_headers-6.3.0/lib/secure_headers/middleware.rb:11:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/sentry-raven-2.7.4/lib/raven/integrations/rack.rb:51:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/railties-5.2.5/lib/rails/engine.rb:524:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/puma-4.3.5/lib/puma/commonlogger.rb:40:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/puma-4.3.5/lib/puma/configuration.rb:228:in `call'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/puma-4.3.5/lib/puma/server.rb:713:in `handle_request'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/puma-4.3.5/lib/puma/server.rb:472:in `process_client'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/puma-4.3.5/lib/puma/server.rb:328:in `block in run'
postal      | 13:59:52 web.1              | => /opt/postal/vendor/bundle/ruby/2.6.0/gems/puma-4.3.5/lib/puma/thread_pool.rb:134:in `block in spawn_thread'
postal      | 13:59:52 web.1              | => 10.9.0.2 - - [26/Apr/2021:13:59:52 +0000] "POST /api/v1/send/message HTTP/1.1" 500 - 0.0177

[willpower232]

How old is your Postal installation? In theory this was resolved with 752558f

[saschaarthur]

Running on the latest master.

Also migrated everything as described here: #1164

UTF-8 is generally working, only very specific characters as this one is not working

[saschaarthur]

looking at your link at 752558f exactly matches to the issue i have.

The reason prob is that the subject column is not migrated to utf8mb4, thats why it works in body and not in the subject line.

Also a user already complained here 752558f#commitcomment-45466226 that hes not able to use utf-8 emojis?

[willpower232]

Interesting, emoji works for me and HeidiSQL thinks I've got the encoding everywhere

[saschaarthur]

/opt/postal/lib/postal/message_db/migrations# ls -alh
total 88K
drwxr-xr-x 2 postal postal 4.0K Apr 26 08:08 .
drwxr-xr-x 3 postal postal 4.0K Apr 26 08:08 ..
-rw-r--r-- 1 postal postal  389 Apr 26 08:08 01_create_migrations.rb
-rw-r--r-- 1 postal postal 3.4K Apr 26 08:08 02_create_messages.rb
-rw-r--r-- 1 postal postal 1.1K Apr 26 08:08 03_create_deliveries.rb
-rw-r--r-- 1 postal postal  620 Apr 26 08:08 04_create_live_stats.rb
-rw-r--r-- 1 postal postal  630 Apr 26 08:08 05_create_raw_message_sizes.rb
-rw-r--r-- 1 postal postal 1.1K Apr 26 08:08 06_create_clicks.rb
-rw-r--r-- 1 postal postal  914 Apr 26 08:08 07_create_loads.rb
-rw-r--r-- 1 postal postal 1010 Apr 26 08:08 08_create_stats.rb
-rw-r--r-- 1 postal postal  900 Apr 26 08:08 09_create_links.rb
-rw-r--r-- 1 postal postal  832 Apr 26 08:08 10_create_spam_checks.rb
-rw-r--r-- 1 postal postal  287 Apr 26 08:08 11_add_time_to_deliveries.rb
-rw-r--r-- 1 postal postal  287 Apr 26 08:08 12_add_hold_expiry.rb
-rw-r--r-- 1 postal postal  306 Apr 26 08:08 13_add_index_to_message_status.rb
-rw-r--r-- 1 postal postal  923 Apr 26 08:08 14_create_suppressions.rb
-rw-r--r-- 1 postal postal 1.2K Apr 26 08:08 15_create_webhook_requests.rb
-rw-r--r-- 1 postal postal  559 Apr 26 08:08 16_add_url_and_hook_to_webhooks.rb
-rw-r--r-- 1 postal postal  556 Apr 26 08:08 17_add_replaced_link_count_to_messages.rb
-rw-r--r-- 1 postal postal  331 Apr 26 08:08 18_add_endpoints_to_messages.rb
-rw-r--r-- 1 postal postal 2.4K Apr 26 08:08 19_convert_database_to_utf8mb4.rb
-rw-r--r-- 1 postal postal  270 Apr 26 08:08 20_increase_links_url_size.rb

rake db:migrate:status
(in /opt/postal)

database: postal

 Status   Migration ID    Migration Name
--------------------------------------------------
   up     20161003195209  Create authie sessionsauthie
   up     20161003195210  Add indexes to authie sessionsauthie
   up     20161003195211  Add parent id to authie sessionsauthie
   up     20161003195212  Add two factor auth fields to authieauthie
   up     20170418200606  Initial schema
   up     20170421195414  Add token hashes to authie sessionsauthie
   up     20170421195415  Add index to token hashes on authie sessionsauthie
   up     20170428153353  Remove type from IP pools
   up     20180216114344  Add host to authie sessionsauthie
   up     20200717083943  Add UUID to credentials

./postal upgrade
Compiling Assets
Migrating database
-------------------------------------------------------------------
1: ...
-------------------------------------------------------------------
Nothing to do.

SELECT TABLE_SCHEMA
     , TABLE_NAME
     , COLUMN_NAME
     , COLLATION_NAME
FROM INFORMATION_SCHEMA.COLUMNS
WHERE TABLE_NAME = 'messages';

any idea hows that possible?

[willpower232]

if you create a new server in Postal, does that get utf8mb4?

[saschaarthur]

yeah thats weird!

If i create a new 2nd server.. both switching to utf8mb4_unicode_ci.
But if i delete the 2nd test-server again .. the first server is falling back to utf8_general_ci ?!

[willpower232]

creating a second server shouldn't affect the first one which implies your database client might be going wrong somehow when telling you the collations?

[saschaarthur]

before:

after:

after deleted:

Verified it again and youre right, my mistake sorry..

Anyways the initial table stays at utf8_general_ci , and idea why migrations (as you can see above) are marked as done but the table is still at utf8_general_ci ? Having 4 different instances of postal with exactly this problem.

Current workarround:
Deleting migration 19 & 20 from migrations table and letting them rerun with postal upgrade fixes the cause. After the migrations the database and tables is having utf8mb4.

The only question im having is.. how is it possible that those migrations got on all my 4 instances marked as successfully runned, even if it seems they failed / were never running?

[willpower232]

No worries, happens to us all.

I'll give a fresh install a go when I can to see what happens, it is odd that all your instances have the same error.

[willpower232]

Actually I had a recent copy which seems to be fine, how long ago did you make the Postal instances?

[saschaarthur]

maybe a year or two ago?

[willpower232]

So it might be that the upgrade process missed yours out somehow. If you're comfortable in a database editor, you could make the fixes yourself, I'm not familiar enough with ruby to know the correct way of resolving it.