Feedback-loop logging to mysql's sys_log

Discussion in 'General' started by TenTwentyFour, Oct 29, 2017.

  1. TenTwentyFour

    TenTwentyFour New Member

    We've encountered the following issue on an ispconfig slave server during occasional (and randomly distributed) cron-triggered runs of server.sh:
    Code:
    /bin/sh: fork: Cannot allocate memory
    More recently, we've also seen
    Code:
    /bin/sh: xrealloc: .././subst.c:687: cannot allocate 67116672 bytes (536903680 bytes allocated)
    We've determined that this is a symptom of the slave server trying to log to it's mysql sys_log table, then trying to log the failure to do so to the same table, etc, creating a feedback loop and eventually running out of memory while attempting to do so:

    Code:
    29.10.2017-15:12 - WARNING - Unable to connect to local server.
    29.10.2017-15:12 - DEBUG - Remove Lock: /usr/local/ispconfig/server/temp/.ispconfig_cron_lock
    29.10.2017-15:12 - WARNING - Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), 'Unable to connect to local server.') -> 0 ()
    29.10.2017-15:12 - WARNING - Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 0, UNIX_TIMESTAMP(), 'Remove Lock: /usr/local/ispconfig/server/temp/.ispconfig_cron_lock') -> 0 ()
    29.10.2017-15:12 - WARNING - Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), 'Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), \'U
    nable to connect to local server.\') -> 0 ()') -> 0 ()
    […]
    29.10.2017-15:12 - WARNING - Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), 'Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), \'Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), \\\'Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), \\\\\\\'Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), \\\\\\\\\\\\\\\'Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\'Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\'Falsche Anfrage / Wrong QuerySQL-Query = INSERT INTO sys_log (server_id,datalog_id,loglevel,tstamp,message) VALUES (5, 0, 1, UNIX_TIMESTAMP(), \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\'Unable to connect to local server.\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\') -> 0 ()\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\') -> 0 ()\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\') -> 0 ()\\\\\\\\\\\\\\\') -> 0 ()\\\\\\\') -> 0 ()\\\') -> 0 ()\') -> 0 ()') -> 0 ()
    […]\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\[…]') -> 0 ()\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\
    \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\') -> 0 ()\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\
    \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\') -> 0 ()\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\') -> 0 ()\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\
    \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\') -> 0 ()\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\') -> 0 ()\\\\\\\\\\\\\\\') -> 0 ()\\\\\\\') -> 0 ()\\\') -> 0 ()\') -> 0 ()') -> 0 ()
    The initial error here seems to be "Unable to connect to local server", meaning the local MySQL server, but we've tried debugging this, manually running server.sh, even adding var_dumps throughout the code-base. But every manual run just works out correctly, connecting to the local server just fine.

    So it would seem that under some conditions, the application is unable to connect to the local mysql server. Indeed, when looking at the sys_log table, it's empty:

    Code:
    mysql> select message from sys_log;
    Empty set (0.00 sec)
    
    It would seem that the MySQL daemon was somehow unreachable during a brief period of time, every few days and that, if a cron run occurs in just that moment, this phenomenon is the result. We guessed e.g. logrotate, but aren't able to find anything in the system logs that would support this hypothesis.

    The system's DEBUG level is already set to DEBUG. Any ideas that could help us pinpoint the issue here?
     
  2. TenTwentyFour

    TenTwentyFour New Member

    I just briefly wanted to bump this thread and see if I'm actually alone in experiencing this behavior?
     

Share This Page