Skip to content

Aurora MySQL Writer Instance Crashes Intermittently After Write Forwarding Is Enabled

0

Engine Version: 8.0.mysql_aurora.3.05.2

DB cluster role: Regional clustor

Local read replica write forwarding: Enabled

aurora_replica_read_consistency: Session

Issue: The system initially works properly after enabling, but begins crashing and rebooting automatically after several hours of operation. This occurs despite normal readings for both max_connections and ForwardingWriterOpenSessions metrics. The cluster configuration was minimal at the time of the crash, consisting of just two replicas—one read and one write.

Error in the write replica at the time of crash:

2025-01-20T19:13:53.726681Z 320772 [ERROR] [MY-013183] [InnoDB] Assertion failure: fwd_cmd.cc:3170:thd->variables.aurora_cmd_forwarding_mode_options != CMD_FWD_MODE_LONG_POLL thread 70369950036960 (ut0dbg.cc:58)
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
2025-01-20T19:13:53Z UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
BuildID[sha1]=82a011aba84a660d4bf03c9af2fb1fe3233b0bc1
Thread pointer: 0x4000ffa7e000
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 4000492c8aa7 thread_stack 0x40000
/rdsdbbin/oscar/bin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x30) [0x2647ff0]
/rdsdbbin/oscar/bin/mysqld(print_fatal_signal(int)+0x31c) [0x124d4dc]
/rdsdbbin/oscar/bin/mysqld(my_server_abort()+0x98) [0x124da98]
/rdsdbbin/oscar/bin/mysqld(my_abort()+0x14) [0x263ee14]
/rdsdbbin/oscar/bin/mysqld(ut_dbg_assertion_failed(char const*, char const*, unsigned long)+0x2a4) [0x2a0a224]
/rdsdbbin/oscar/bin/mysqld(send_command_result_to_replica(THD*, std::shared_ptr<Oscar::FWD::FwdCommandResponse>, bool)+0x2b8) [0x119c0b8]
/rdsdbbin/oscar/bin/mysqld(send_response_to_replica(THD*)+0x94) [0x119c174]
/rdsdbbin/oscar/bin/mysqld(THD_task::finish_process_connection()+0x1a8) [0x123a4a8]
/rdsdbbin/oscar/bin/mysqld(THD_task::process_task(Thread_pool*)+0x98) [0x123c958]
/rdsdbbin/oscar/bin/mysqld(THD_task::async_commit_done(THD_task*)+0x90) [0x123b8f0]
/rdsdbbin/oscar/bin/mysqld() [0x3022ca8]
/rdsdbbin/oscar/bin/mysqld() [0x3059b30]
/rdsdbbin/oscar/bin/mysqld() [0x30526e0]
/rdsdbbin/oscar/bin/mysqld() [0x3261714]
/rdsdbbin/oscar/bin/mysqld() [0x326797c]
/rdsdbbin/oscar/bin/mysqld() [0x3267e50]
/rdsdbbin/oscar/bin/mysqld() [0x32634f0]
/rdsdbbin/oscar/bin/mysqld() [0x331d318]
/rdsdbbin/oscar/bin/mysqld() [0x331d6ac]
/rdsdbbin/oscar/bin/mysqld() [0x11bee90]
/rdsdbbin/oscar/bin/mysqld() [0x11bf11c]
/usr/local/csd/lib/libboost_thread.so.1.77.0(+0xa7ec) [0x40002e50e7ec]
/lib64/libpthread.so.0(+0x722c) [0x40002f74322c]
/lib64/libc.so.6(+0xd4a1c) [0x40002fb36a1c]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): Connection ID (thread ID): 320772
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

Write replica general log entries for thread ID 320772 at the time of the crash:

2025-01-20T19:12:21.820866Z	320772 Query	INSERT INTO `User` (`Id`)
VALUES (120578)
2025-01-20T19:12:21.850334Z	320772 Query	INSERT INTO `UserApplication` (`AppId`, `UserId`)
VALUES (8085445, 120578)
2025-01-20T19:12:22.110309Z	320772 Query	UPDATE `Organization` SET `AddressId` = 434788, `CityId` = 10716, `CountryId` = 293, `Latitude` = '50.9471393', `Longitude` = '6.9410172', `StateId` = 50, `SubtypeId` = NULL, `TypeId` = 2
WHERE `Id` = 385488
2025-01-20T19:12:22.380036Z	320772 Query	UPDATE `Organization` SET `AddressId` = 434788, `CityId` = 10716, `CountryId` = 293, `Latitude` = '50.9471393', `Longitude` = '6.9410172', `StateId` = 50, `SubtypeId` = NULL, `TypeId` = 2
WHERE `Id` = 385488
2025-01-20T19:13:26.451772Z	320772 Query	UPDATE `Organization` SET `AddressId` = 434788, `CityId` = 10716, `CountryId` = 293, `Latitude` = '50.9471393', `Longitude` = '6.9410172', `StateId` = 50, `SubtypeId` = NULL, `TypeId` = 2
WHERE `Id` = 385488
2025-01-20T19:13:38.293755Z	320772 Query	INSERT INTO `User` (`Id`)
VALUES (120579)
2025-01-20T19:13:38.303302Z	320772 Query	INSERT INTO `UserApplication` (`AppId`, `UserId`)
VALUES (876909984, 120579)
2025-01-20T19:13:53.718963Z	320772 Query	UPDATE `Organization` SET `AddressId` = 434788, `CityId` = 10716, `CountryId` = 293, `Latitude` = '50.9471393', `Longitude` = '6.9410172', `StateId` = 50, `SubtypeId` = NULL, `TypeId` = 2
WHERE `Id` = 385488

Read replica general log entries for the same connection ID, showing queries forwarded from this instance:

2025-01-20T19:13:39.826178Z	1246388 Query	SELECT `m0`.`Id`, `m0`.`AttributeId`, `m0`.`Discriminator`, `m0`.`IsMainFilter`, `m0`.`LabelGroupId`, `m0`.`ModuleId`, `m0`.`FilterTypeId`, `m`.`Id`
FROM `Module` AS `m`
INNER JOIN `ModuleFilter` AS `m0` ON `m`.`Id` = `m0`.`ModuleId`
WHERE `m`.`AppId` = 876909984
ORDER BY `m`.`Id`
2025-01-20T19:13:39.827772Z	1246388 Query	SELECT `m0`.`ModuleId`, `m0`.`TypeId`, `m`.`Id`
FROM `Module` AS `m`
INNER JOIN `ModuleType` AS `m0` ON `m`.`Id` = `m0`.`ModuleId`
WHERE `m`.`AppId` = 876909984
ORDER BY `m`.`Id`
2025-01-20T19:13:53.721407Z	1246388 Query	SET NAMES utf8mb4
2025-01-20T19:13:53.722038Z	1246388 Query	SELECT `o`.`Id`, `o`.`AddressId`, `o`.`CityId`, `o`.`CountryId`, `o`.`Domain`, `o`.`Email`, `o`.`EmailDomain`, `o`.`House`, `o`.`Latitude`, `o`.`Logo`, `o`.`Longitude`, `o`.`Name`, `o`.`StateId`, `o`.`Street`, `o`.`SubtypeId`, `o`.`TypeId`, `o`.`Url`, `o`.`UrlName`, `o`.`Version`, `o`.`ZipCode`
FROM `Organization` AS `o`
WHERE `o`.`Id` = 385488
ORDER BY `o`.`Id`
LIMIT 1
2025-01-20T19:13:53.722950Z	1246388 Query	SELECT `o0`.`OrganizationId`, `o0`.`CategoryId`, `t`.`Id`
FROM (
    SELECT `o`.`Id`
    FROM `Organization` AS `o`
    WHERE `o`.`Id` = 385488
    LIMIT 1
) AS `t`
INNER JOIN `OrganizationCategory` AS `o0` ON `t`.`Id` = `o0`.`OrganizationId`
ORDER BY `t`.`Id`
2025-01-20T19:13:53.752880Z	1246388 Query	SET NAMES utf8mb4
2025-01-20T19:13:53.753539Z	1246388 Query	SET AUTOCOMMIT = 1;
2025-01-20T19:13:53.753619Z	1246388 Query	UPDATE `Organization` SET `Version` = 638729972323766000
WHERE `Id` = 385488;

The error message regarding variables.aurora_cmd_forwarding_mode_options != CMD_FWD_MODE_LONG_POLL is not documented in any available resources. The queries in the general log appear normal, and identical queries execute successfully in other instances without causing crashes.

asked 2 years ago295 views

1 Answer
1

The issue you're experiencing with your Aurora MySQL Writer Instance crashing intermittently after enabling write forwarding is concerning and appears to be related to an internal assertion failure in the write forwarding mechanism.

The error message "Assertion failure: fwd_cmd.cc:3170:thd->variables.aurora_cmd_forwarding_mode_options != CMD_FWD_MODE_LONG_POLL" suggests there's an unexpected state in the write forwarding process. This could be due to a bug in the Aurora MySQL engine, particularly in how it handles certain write forwarding scenarios.

Given that the crash occurs after several hours of operation and the queries in the general log appear normal, it's possible that there's a race condition or an edge case that's triggered under specific circumstances.

To address this issue, consider the following steps:

  1. Update to the latest minor version of Aurora MySQL 3.05 if available, as it may contain fixes for such issues.

  2. Review and possibly adjust the write forwarding related parameters:

    • Check if increasing the aurora_fwd_writer_idle_timeout helps (e.g., set it to a higher value like 300 seconds).
    • Ensure aurora_fwd_writer_max_connections_pct is set appropriately for your workload.
  3. Monitor the ForwardingWriterOpenSessions metric closely to see if there are any spikes or anomalies before the crash occurs.

  4. Consider temporarily disabling write forwarding to see if the crashes stop, which would confirm that the issue is related to this feature.

  5. Examine your application's connection handling and transaction patterns. Ensure that connections are being properly closed and not left idle for extended periods.

  6. If the issue persists, it would be advisable to open a support case with AWS, providing them with the error logs, general logs, and details about your cluster configuration. They may be able to provide more specific guidance or identify if this is a known issue with your particular version of Aurora MySQL.

  7. In the meantime, if this is affecting your production environment, consider implementing a workaround such as using read replicas without write forwarding or directing writes to the primary instance directly.

Remember that write forwarding, while useful, can introduce additional complexity in transaction handling and consistency. Ensure that your application is designed to handle potential issues that may arise from using this feature.

Sources
Forwarded connection on Writer terminated; try restarting transaction | AWS re:Post
Read consistency for write forwarding - Amazon Aurora
Using local write forwarding in an Amazon Aurora MySQL DB cluster - Amazon Aurora

answered 2 years ago

EXPERT

reviewed 2 years ago

  • Thanks! Updating Aurora version fixed it 👍🏻

  • Okk, same error is back even after version update, only thing changed is line number. Now error is thrown from fwd_cmd.cc:3288

You are not logged in. Log in to post an answer.

A good answer clearly answers the question and provides constructive feedback and encourages professional growth in the question asker.