Frequent "Lost connection to MySQL server during query" (Got an error reading communication packets) errors

oliver · January 28, 2022, 10:02am

Infos:

Used Zammad version: 5.0.3 on MySQL 5.7.37
Used Zammad installation type: Docker Swarm, image built from source
Operating system: Docker image built from ruby:2.7.4-slim
Browser + version: FF 96.0.2 (64-Bit)

Expected behavior:

Being able to leave app open in the browser in idle without getting errors when returning to it.

Actual behavior:

Getting Error 500 after 10-20 minutes in idle.

Steps to reproduce the behavior:

I finally upgraded from 3.3.0 to 5.0.3, but now I’m stuck with this problem:

Zammad works fine for about 10-20 minutes, then it seems to lose its connection to mysql, resulting in Error 500 in the GUI until doing a full refresh in the browser.

I’m running in a custom built docker image, which is very similar to zammad-docker-compose/containers/zammad, just using MySQL instead of Postgres. Instead of libpq-dev/libpq5 I install libmariadb-dev at build time and ruby-mysql2 at run time.

MySQL runs with these params:

  mysql:
    image: 'mysql:5.7.37'
    command: --character-set-client-handshake=FALSE --character-set-server=utf8mb4 --collation-server=utf8mb4_unicode_ci --max_allowed_packet=256M --innodb_fast_shutdown=0 --skip-character-set-client-handshake

I can log into Zammad, everything works fine. After a while, I get this in the mysql logs:

[Note] Aborted connection xxxx to db: 'zammad_prod' user: 'zammad' host: 'x.x.x.x' (Got an error reading communication packets)

Zammad still looking nice on the browser tab, but when I click something, like opening a ticket, I get

I, [2022-01-27T16:49:36.101374 #13-181240] INFO -- : Started POST "/api/v1/taskbar" for x.x.x.x at 2022-01-27 16:49:36 +0000
I, [2022-01-27T16:49:36.103534 #13-181340] INFO -- : Started GET "/api/v1/tickets/2642?all=true&_=1643297293802" for x.x.x.x at 2022-01-27 16:49:36 +0000
F, [2022-01-27T16:49:36.112024 #13-181340] FATAL -- :
[da32f6ef-4a58-4188-8766-14b6d4f06381] ActiveRecord::StatementInvalid (Mysql2::Error::ConnectionError: Lost connection to MySQL server during query):
[da32f6ef-4a58-4188-8766-14b6d4f06381]
[da32f6ef-4a58-4188-8766-14b6d4f06381] config/initializers/db_preferences.rb:14:in `block in <main>'
x.x.x.x - - [27/Jan/2022:16:49:36 +0000] "GET /api/v1/tickets/2642?all=true&_=1643297293802 HTTP/1.1" 500 46 "https://my.domain.com/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:96.0) Gecko/20100101 Firefox/96.0"

Zammad now displays various Error 500 messages. Once I fully refresh in the browser, all is fine again for 10-20 minutes, until the same as above happens again.

I worked through MySQL :: MySQL 5.7 Reference Manual :: B.3.2.7 MySQL server has gone away, tried increasing max_allowed_packet to 516M, which only leads to the same issue, just some minutes later.

I know there are not too many Zammad users on mysql, but has someone else possibly seen this behaviour? Anybody running Zammad 5.0.3 on MySQL 5.7.37 at all?

I found out that Zammad uses ruby gem mysql2 0.5.3 and I understand GitHub - brianmario/mysql2: A modern, simple and very fast Mysql library for Ruby - binding to libmysql in a way that mysql2 does not really support ruby 2.7 at this time. Could this be related?

Any help appreciated!

Thx,
-Oliver

germeshausen · January 28, 2022, 9:56pm

Sounds like a problem with your MySQL configuration for the connection pool. Have a look at the number of concurrent allowed connections and the number of persistent connections.
https://docs.zammad.org/en/latest/appendix/configure-database-server.html

Depending on different options the MySQL service may consume a lot resources.
If you allow persistent connections the response will be faster as the connection is established, but when all connections are used, no new connections could be established. There a some settings which can help in this case.
Additional you might have a look at tuning primer which may help you to identify bottlenecks and the resources you may consume with the settings.

oliver · February 18, 2022, 10:35am

So I was able to isolate this issue, and suggest a possible fix here:

github.com/zammad/zammad

Frequent “Lost connection to MySQL server during query” errors resulting in client-side Error 500

opened 10:33AM - 18 Feb 22 UTC

olivergrahl

### Infos: * Used Zammad version: 5.0.3 * Installation method (source, package, ..): Docker Swarm * Operating system: * Database + version: MySQL 5.7.37 * Elasticsearch version: n/a * Browser + version: FF 97.0 (64-Bit) ### Expected behavior: Being able to leave app open in the browser in idle without getting errors when returning to it. ### Actual behavior: Getting Error 500 after 10-30 minutes in idle. ### Steps to reproduce the behavior: Note that - just to reproduce this issue - I run `zammad/zammad` with a custom entrypoint and command in order to replace `postgres` with `mysql`. Yes, it would have been way easier to track this down and reproduce having a `mysql` variant of `zammad/zammad`. ```bash docker swarm init cat <<EOF | docker stack deploy --compose-file - zammad version: '3.4' networks: test: services: mysql: image: 'mysql:5.7.37' command: --character-set-server=utf8 --max_allowed_packet=256M deploy: restart_policy: condition: any environment: - 'MYSQL_RANDOM_ROOT_PASSWORD=true' - 'MYSQL_USER=zammad' - 'MYSQL_PASSWORD=secret' - 'MYSQL_DATABASE=zammad' networks: - test zammad: image: 'zammad/zammad:5.1.0-335' command: "-c \"set -x; apt-get update && apt-get install -y --no-install-recommends ruby-mysql2 && cd /opt/zammad && sed -i 's#mysql#postgres#' /usr/local/bundle/config && bundle install && sed -i -e 's#.*adapter:.*# adapter: mysql2#' -e 's#.*password:.*# password: secret#' -e 's#.*host:.*# host: mysql#' /opt/zammad/config/database.yml && sed -i 's#.*postgres.*##i' /docker-entrypoint.sh && sed -i 's#.*done##' /docker-entrypoint.sh && sed -i 's#.*elasticsearch.*##i' /docker-entrypoint.sh && service redis-server start && bundle exec rake db:migrate && bundle exec rake db:seed && /docker-entrypoint.sh zammad\"" deploy: restart_policy: condition: any entrypoint: /bin/bash networks: - test ports: - target: 80 published: 8088 EOF ``` * Open http://localhost:8088 in the browser and walk through initial setup steps (Create, Next, Next, Skip) * Get to overview containing the "Welcome to Zammad" ticket. Click ticket to verify it "works". Close ticket view. * Wait 10-30 minutes. * Click "Welcome to Zammad" ticket again. * Zammad now displays various Error 500 messages. * After full refresh in the browser, all is fine again for 10-30 minutes, until the same as above happens again. `docker service logs zammad_zammad` now contains: ``` I, [2022-02-18T09:41:45.560205 #896-178580] INFO -- : Started POST "/api/v1/recent_view" for 10.255.0.2 at 2022-02-18 09:41:45 +0000 F, [2022-02-18T09:41:45.568291 #896-178100] FATAL -- : [50fbce82-c4f8-40c7-89a1-3b81b02454fe] ActiveRecord::StatementInvalid (Mysql2::Error::ConnectionError: Lost connection to MySQL server during query): [50fbce82-c4f8-40c7-89a1-3b81b02454fe] [50fbce82-c4f8-40c7-89a1-3b81b02454fe] config/initializers/db_preferences.rb:15:in `block in <main>' ``` After further investigation, it appears that this line is causing the problem: https://github.com/zammad/zammad/blob/24c3bdfd8748874cb5f16c4e618cf78cded47743/config/initializers/db_preferences.rb#L13 Changing `:before` to `:after` seems to fix it. To verify, include `sed -i 's#:before#:after#' /opt/zammad/config/initializers/db_preferences.rb` as below: ```bash docker stack rm zammad cat <<EOF | docker stack deploy --compose-file - zammad version: '3.4' networks: test: services: mysql: image: 'mysql:5.7.37' command: --character-set-server=utf8 --max_allowed_packet=256M deploy: restart_policy: condition: any environment: - 'MYSQL_RANDOM_ROOT_PASSWORD=true' - 'MYSQL_USER=zammad' - 'MYSQL_PASSWORD=secret' - 'MYSQL_DATABASE=zammad' networks: - test zammad: image: 'zammad/zammad:5.1.0-335' command: "-c \"set -x; apt-get update && apt-get install -y --no-install-recommends ruby-mysql2 && cd /opt/zammad && sed -i 's#mysql#postgres#' /usr/local/bundle/config && bundle install && sed -i 's#:before#:after#' /opt/zammad/config/initializers/db_preferences.rb && sed -i -e 's#.*adapter:.*# adapter: mysql2#' -e 's#.*password:.*# password: secret#' -e 's#.*host:.*# host: mysql#' /opt/zammad/config/database.yml && sed -i 's#.*postgres.*##i' /docker-entrypoint.sh && sed -i 's#.*done##' /docker-entrypoint.sh && sed -i 's#.*elasticsearch.*##i' /docker-entrypoint.sh && service redis-server start && bundle exec rake db:migrate && bundle exec rake db:seed && /docker-entrypoint.sh zammad\"" deploy: restart_policy: condition: any entrypoint: /bin/bash networks: - test ports: - target: 80 published: 8088 EOF ``` I have to admit that I don't really understand what's going on here, maybe some kind of race condition. Executing a statement in `Mysql2Adapter.set_callback :before` is possibly not a good idea. Let me add that I was able to reproduce the issue on two different machines. I have not been able to reproduce it using just `docker run ...` instead of Docker Swarm as above. Maybe some differences in Docker's networking are playing a role here. I don't understand enough of all this to explain, though. Another possible workaround could be to remove the `Mysql2Adapter.set_callback` code from the db initializer alltogether, and use `ActiveRecord::Base.transaction(isolation: :read_committed) do` in https://github.com/zammad/zammad/blob/24c3bdfd8748874cb5f16c4e618cf78cded47743/app/models/transaction.rb#L14 I have not tried it, though, and I cannot verify if this or my workaround above (using `:after` instead of `:before`) still works in the way it should in terms of the reason for the statement being added in [82b61e4](https://github.com/zammad/zammad/commit/82b61e4811fc94650e7ef00e9afc318ac1e642de). Yes I'm sure this is a bug and no feature request or a general question.

system · June 18, 2022, 10:35am

This topic was automatically closed 120 days after the last reply. New replies are no longer allowed.