Deadlock on MySQL-database when 4-5 simultaneous logins to ProFTPd with updatecount query causing authentication timeout

[maltris]

What I Did

Set up ProFTPd with mod_sql and an update-query to the database after FTP PASS. Run 4-5 parallel client logins on the same user against ProFTPd that PASS within the same second (0-1ms from each other). Get this in the sql log:

2023-05-02 07:04:46,817 mod_sql/4.5[501930]: unrecoverable backend error
2023-05-02 07:04:46,817 mod_sql/4.5[501930]: error: '1213'
2023-05-02 07:04:46,817 mod_sql/4.5[501930]: message: 'Deadlock found when trying to get lock; try restarting transaction'

And a timed out authentication.

What I Expected/Wanted

Get the count of logins and the date of the last login into the database table and run 4-5 simultaneous logins with the same user (in the same second, a few milliseconds from each other) against the ProFTPd.

Example as referenced here:

SQLLog PASS updatecount
SQLNamedQuery updatecount UPDATE "count=count+1, accessed=now() WHERE userid='%u'" ftpuser

ProFTPD Version and Configuration

proftpd -V

Compile-time Settings:
  Version: 1.3.8 (stable)
  Platform: LINUX [Linux 5.4.0-96-generic x86_64]
  OS/Release:
    NAME="Alpine Linux"
    ID=alpine
    VERSION_ID=3.16.5
    PRETTY_NAME="Alpine Linux v3.16"
  Built: Tue Apr 25 2023 13:56:18 UTC
  Built With:
    configure  '--enable-ctrls' '--enable-openssl' '--enable-quotatab' '--with-modules=mod_tls:mod_quotatab:mod_sql:mod_sql_passwd:mod_quotatab_sql:mod_quotatab_file:mod_ctrls_admin:mod_auth_otp:mod_sql_sqlite:mod_sql_mysql:mod_ban:mod_readme:mod_sftp:mod_sftp_sql:mod_proxy_protocol:mod_ident:mod_ifsession' '--enable-nls'

  CFLAGS: -g2 -O2 -Wall -fno-omit-frame-pointer -fno-strict-aliasing
  LDFLAGS: -Wl,-L$(top_srcdir)/lib,-L$(top_builddir)/lib  -rdynamic  -L/usr/lib/
  LIBS:  -lssl -lcrypto -lm -lmysqlclient -lz  -lsqlite3  -lssl  -lcrypto 

  Files:
    Configuration File:
      /usr/local/etc/proftpd.conf
    Pid File:
      /usr/local/var/proftpd.pid
    Scoreboard File:
      /usr/local/var/proftpd.scoreboard

  Info:
    + Max supported UID: 4294967295
    + Max supported GID: 4294967295

  Features:
    - Autoshadow support
    + Controls support
    - curses support
    - Developer support
    - DSO support
    + IPv6 support
    + Largefile support
    - Lastlog support
    - Memcache support
    - ncurses support
    + NLS support
    + OpenSSL support (OpenSSL 1.1.1t  7 Feb 2023)
    - PCRE support
    - PCRE2 support
    - POSIX ACL support
    - Redis support
    + Sendfile support
    + Shadow file support
    - Sodium support
    + Trace support
    + xattr support

  Tunable Options:
    PR_TUNABLE_BUFFER_SIZE = 1024
    PR_TUNABLE_DEFAULT_RCVBUFSZ = 8192
    PR_TUNABLE_DEFAULT_SNDBUFSZ = 8192
    PR_TUNABLE_ENV_MAX = 2048
    PR_TUNABLE_GLOBBING_MAX_MATCHES = 100000
    PR_TUNABLE_GLOBBING_MAX_RECURSION = 8
    PR_TUNABLE_HASH_TABLE_SIZE = 40
    PR_TUNABLE_LOGIN_MAX = 256
    PR_TUNABLE_NEW_POOL_SIZE = 512
    PR_TUNABLE_PATH_MAX = 4096
    PR_TUNABLE_SCOREBOARD_BUFFER_SIZE = 80
    PR_TUNABLE_SCOREBOARD_SCRUB_TIMER = 30
    PR_TUNABLE_SELECT_TIMEOUT = 30
    PR_TUNABLE_TIMEOUTIDENT = 10
    PR_TUNABLE_TIMEOUTIDLE = 600
    PR_TUNABLE_TIMEOUTLINGER = 10
    PR_TUNABLE_TIMEOUTLOGIN = 300
    PR_TUNABLE_TIMEOUTNOXFER = 300
    PR_TUNABLE_TIMEOUTSTALLED = 3600
    PR_TUNABLE_XFER_SCOREBOARD_UPDATES = 10

[Castaglia]

Interesting! From reading MySQL docs, I think this is occurring because of the "searched SQL UPDATE", i.e.:

SQLNamedQuery updatecount UPDATE "count=count+1, accessed=now() WHERE userid='%u'" ftpuser

In this UPDATE statement, the existing value of the count column is first read ("searched"), and then updated, by this:

count=count+1

Such "searched UPDATE" statements can cause implicit locking, to ensure an atomic transaction of that read-then-write sequence.

I'm not sure how important that count value is; if you don't need/use it, removing that increment should resolve the issue.

Alternatively, from reading https://dev.mysql.com/doc/refman/8.0/en/update.html, you might try this (but I've not tested this yet):

# Use a FREEFORM statement to customize our UPDATE statement
SQLNamedQuery updatecount FREEFORM "UPDATE LOW_PRIORITY ftpuser SET count=count+1, accessed=now() WHERE userid='%u'"

Per the above docs, the LOW_PRIORITY may avoid the deadlock, at the expense of some additional latency:

With the LOW_PRIORITY modifier, execution of the UPDATE is delayed until no other clients are reading from the table. This affects only storage engines that use only table-level locking (such as MyISAM, MEMORY, and MERGE).

[Castaglia]

In addition to the above, I should also have mod_sql_mysql look for these deadlock errors (mysql_errno() return value of ER_LOCK_DEADLOCK, it appears), and retry the UPDATE (and INSERT?) statement a couple of times, as it is a race condition.

I wonder if Postgres and SQLite have similar considerations; I'll have to research this topic for them as well.

[Castaglia]

For my reference, mod_sql_postgres uses the PQresultStatus() function, which doesn't have any documented deadlock-looking errors. And mod_sql_sqlite already handles "database busy" errors with retries.

This current behavior -- lacking retrying on deadlock/busy errors -- looks to be specific just to mod_sql_mysql.

[Castaglia]

Could you try out #1668, see if it helps remedy this issue for you?

[Castaglia]

@maltris Would it be possible to see the rest of your ProFTPD configuration, to aid me in reproducing this behavior locally? Thanks!

[maltris]

Helloo,

it was so silent around that topic because I just excluded the update statements in a production environment. But I want to help fixing the problem, so as soon as possible I will try the change you mentioned and report back as soon as I am able.