glpi-project / glpi

GLPI is a Free Asset and IT Management Software package, Data center management, ITIL Service Desk, licenses tracking and software auditing.
https://glpi-project.org
GNU General Public License v3.0
4.08k stars 1.27k forks source link

Repeated glpi_logs related delete queries slow down server #16614

Closed laszlokertesz closed 3 months ago

laszlokertesz commented 6 months ago

Code of Conduct

Is there an existing issue for this?

Version

10.0.12

Bug description

After reboot of the server and start of apache and mariadb (this happened both with 10.0.9 and 10.0.12) the database becomes flooded with queries like

DELETE `glpi_logs` FROM `glpi_logs` WHERE `itemtype` = 'Agent' AND `items_id` = '186'

I counted 350 at a certain point. This is a big issue since our logs table is really big (around 800 000 000 records) and these queries bog the machine down until the service basically becomes unresponsive. These are related to incoming inventories (if i disable it, after a while the server becomes serviceable), i presume every agent that reports in gets a query like this. But these take very long time, sometimes they get killed because of timeouts and result in rollbacks.

I don't know why these are triggered, the agents that appear on the list are both new and old. Can someone give some pointers where can i disable this, i can do some background cleanup if needed but tying these queries to inventory requests that result in the web server being overwhelmed is not really working out.

Relevant log output

No response

Page URL

No response

Steps To reproduce

I just restarted the server (had some 70 days uptime) and this behavior started.

Your GLPI setup information

Information about system installation and configuration
GLPI 10.0.9 ( => /var/www/html/glpi)
Installation mode: TARBALL
Current language:en_GB

Server
 
Operating system: Linux inventory.3pillarglobal.com 6.1.0-12-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.52-1 (2023-09-07) x86_64
PHP 8.2.7 apache2handler (Core, FFI, PDO, Phar, Reflection, SPL, SimpleXML, Zend OPcache, apache2handler, apcu, bz2, calendar,
    ctype, curl, date, dom, exif, fileinfo, filter, ftp, gd, gettext, hash, iconv, imap, intl, json, ldap, libxml, mbstring, mysqli,
    mysqlnd, openssl, pcre, pdo_mysql, posix, random, readline, session, shmop, sockets, sodium, ssh2, standard, sysvmsg, sysvsem,
    sysvshm, tokenizer, xml, xmlreader, xmlrpc, xmlwriter, xsl, zip, zlib)
Setup: max_execution_time="30" memory_limit="256M" post_max_size="8M" safe_mode="" session.save_handler="files"
    upload_max_filesize="2M" 
Software: Apache ()
    Mozilla/5.0 (X11; Linux x86_64; rv:122.0) Gecko/20100101 Firefox/122.0
Server Software: Debian 12
    Server Version: 10.11.3-MariaDB-1
    Server SQL Mode: STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
    Parameters: root@localhost/glpi
    Host info: Localhost via UNIX socket

PHP version (8.2.7) is supported.
Sessions configuration is OK.
Allocated memory is sufficient.
mysqli extension is installed.
Following extensions are installed: dom, fileinfo, filter, libxml, json, simplexml, xmlreader, xmlwriter.
curl extension is installed.
gd extension is installed.
intl extension is installed.
zlib extension is installed.
The constant SODIUM_CRYPTO_AEAD_XCHACHA20POLY1305_IETF_NPUBBYTES is present.
Database engine version (10.11.3) is supported.
No files from previous GLPI version detected.
The log file has been created successfully.
Write access to /var/www/html/glpi/files/_cache has been validated.
Write access to /var/www/html/glpi/config has been validated.
Write access to /var/www/html/glpi/files/_cron has been validated.
Write access to /var/www/html/glpi/files has been validated.
Write access to /var/www/html/glpi/files/_dumps has been validated.
Write access to /var/www/html/glpi/files/_graphs has been validated.
Write access to /var/www/html/glpi/files/_lock has been validated.
Write access to /var/www/html/glpi/files/_pictures has been validated.
Write access to /var/www/html/glpi/files/_plugins has been validated.
Write access to /var/www/html/glpi/files/_rss has been validated.
Write access to /var/www/html/glpi/files/_sessions has been validated.
Write access to /var/www/html/glpi/files/_tmp has been validated.
Write access to /var/www/html/glpi/files/_uploads has been validated.

Web server root directory configuration seems safe.
PHP directive "session.cookie_secure" should be set to "on" when GLPI can be accessed on HTTPS protocol.
PHP directive "session.cookie_httponly" should be set to "on" to prevent client-side script to access cookie values.
OS and PHP are relying on 64 bits integers.
exif extension is installed.
ldap extension is installed.
openssl extension is installed.
Following extensions are installed: bz2, Phar, zip.
Zend OPcache extension is installed.
Following extensions are installed: ctype, iconv, mbstring, sodium.
Write access to /var/www/html/glpi/marketplace has been validated.
Timezones seems loaded in database.

GLPI constants
 
GLPI_ROOT: "/var/www/html/glpi"
GLPI_CONFIG_DIR: "/var/www/html/glpi/config"
GLPI_VAR_DIR: "/var/www/html/glpi/files"
GLPI_MARKETPLACE_DIR: "/var/www/html/glpi/marketplace"
GLPI_USE_CSRF_CHECK: "1"
GLPI_CSRF_EXPIRES: "7200"
GLPI_CSRF_MAX_TOKENS: "100"
GLPI_USE_IDOR_CHECK: "1"
GLPI_IDOR_EXPIRES: "7200"
GLPI_ALLOW_IFRAME_IN_RICH_TEXT: false
GLPI_SERVERSIDE_URL_ALLOWLIST: ["/^(https?|feed):\\/\\/[^@:]+(\\/.*)?$/"]
GLPI_TELEMETRY_URI: "https://telemetry.glpi-project.org"
GLPI_INSTALL_MODE: "TARBALL"
GLPI_NETWORK_MAIL: "glpi@teclib.com"
GLPI_NETWORK_SERVICES: "https://services.glpi-network.com"
GLPI_MARKETPLACE_ALLOW_OVERRIDE: true
GLPI_MARKETPLACE_MANUAL_DOWNLOADS: true
GLPI_USER_AGENT_EXTRA_COMMENTS: ""
GLPI_DISABLE_ONLY_FULL_GROUP_BY_SQL_MODE: "1"
GLPI_AJAX_DASHBOARD: "1"
GLPI_CALDAV_IMPORT_STATE: 0
GLPI_DEMO_MODE: "0"
GLPI_CENTRAL_WARNINGS: "1"
GLPI_DOC_DIR: "/var/www/html/glpi/files"
GLPI_CACHE_DIR: "/var/www/html/glpi/files/_cache"
GLPI_CRON_DIR: "/var/www/html/glpi/files/_cron"
GLPI_DUMP_DIR: "/var/www/html/glpi/files/_dumps"
GLPI_GRAPH_DIR: "/var/www/html/glpi/files/_graphs"
GLPI_LOCAL_I18N_DIR: "/var/www/html/glpi/files/_locales"
GLPI_LOCK_DIR: "/var/www/html/glpi/files/_lock"
GLPI_LOG_DIR: "/var/www/html/glpi/files/_log"
GLPI_PICTURE_DIR: "/var/www/html/glpi/files/_pictures"
GLPI_PLUGIN_DOC_DIR: "/var/www/html/glpi/files/_plugins"
GLPI_RSS_DIR: "/var/www/html/glpi/files/_rss"
GLPI_SESSION_DIR: "/var/www/html/glpi/files/_sessions"
GLPI_TMP_DIR: "/var/www/html/glpi/files/_tmp"
GLPI_UPLOAD_DIR: "/var/www/html/glpi/files/_uploads"
GLPI_INVENTORY_DIR: "/var/www/html/glpi/files/_inventories"
GLPI_NETWORK_REGISTRATION_API_URL: "https://services.glpi-network.com/api/registration/"
GLPI_MARKETPLACE_PLUGINS_API_URI: "https://services.glpi-network.com/api/marketplace/"
GLPI_I18N_DIR: "/var/www/html/glpi/locales"
GLPI_VERSION: "10.0.9"
GLPI_SCHEMA_VERSION: "10.0.9@77fc44668eaae89b61d95fe606d20d93d66110cd"
GLPI_MARKETPLACE_PRERELEASES: false
GLPI_MIN_PHP: "7.4.0"
GLPI_MAX_PHP: "8.3.0"
GLPI_YEAR: "2023"

Libraries
 
htmlawed/htmlawed version 1.2.14 in (/var/www/html/glpi/vendor/htmlawed/htmlawed)
phpmailer/phpmailer version 6.8.0 in (/var/www/html/glpi/vendor/phpmailer/phpmailer/src)
simplepie/simplepie version 1.5.8 in (/var/www/html/glpi/vendor/simplepie/simplepie/library)
tecnickcom/tcpdf version 6.6.2 in (/var/www/html/glpi/vendor/tecnickcom/tcpdf)
michelf/php-markdown in (/var/www/html/glpi/vendor/michelf/php-markdown/Michelf)
true/punycode in (/var/www/html/glpi/vendor/true/punycode/src)
iamcal/lib_autolink in (/var/www/html/glpi/vendor/iamcal/lib_autolink)
sabre/dav in (/var/www/html/glpi/vendor/sabre/dav/lib/DAV)
sabre/http in (/var/www/html/glpi/vendor/sabre/http/lib)
sabre/uri in (/var/www/html/glpi/vendor/sabre/uri/lib)
sabre/vobject in (/var/www/html/glpi/vendor/sabre/vobject/lib)
laminas/laminas-i18n in (/var/www/html/glpi/vendor/laminas/laminas-i18n/src)
laminas/laminas-servicemanager in (/var/www/html/glpi/vendor/laminas/laminas-servicemanager/src)
monolog/monolog in (/var/www/html/glpi/vendor/monolog/monolog/src/Monolog)
sebastian/diff in (/var/www/html/glpi/vendor/sebastian/diff/src)
donatj/phpuseragentparser in (/var/www/html/glpi/vendor/donatj/phpuseragentparser/src/UserAgent)
elvanto/litemoji in (/var/www/html/glpi/vendor/elvanto/litemoji/src)
symfony/console in (/var/www/html/glpi/vendor/symfony/console)
scssphp/scssphp in (/var/www/html/glpi/vendor/scssphp/scssphp/src)
laminas/laminas-mail in (/var/www/html/glpi/vendor/laminas/laminas-mail/src/Protocol)
laminas/laminas-mime in (/var/www/html/glpi/vendor/laminas/laminas-mime/src)
rlanvin/php-rrule in (/var/www/html/glpi/vendor/rlanvin/php-rrule/src)
blueimp/jquery-file-upload in (/var/www/html/glpi/vendor/blueimp/jquery-file-upload/server/php)
ramsey/uuid in (/var/www/html/glpi/vendor/ramsey/uuid/src)
psr/log in (/var/www/html/glpi/vendor/psr/log/Psr/Log)
psr/simple-cache in (/var/www/html/glpi/vendor/psr/simple-cache/src)
psr/cache in (/var/www/html/glpi/vendor/psr/cache/src)
league/csv in (/var/www/html/glpi/vendor/league/csv/src)
mexitek/phpcolors in (/var/www/html/glpi/vendor/mexitek/phpcolors/src/Mexitek/PHPColors)
guzzlehttp/guzzle in (/var/www/html/glpi/vendor/guzzlehttp/guzzle/src)
guzzlehttp/psr7 in (/var/www/html/glpi/vendor/guzzlehttp/psr7/src)
glpi-project/inventory_format in (/var/www/html/glpi/vendor/glpi-project/inventory_format/lib/php)
wapmorgan/unified-archive in (/var/www/html/glpi/vendor/wapmorgan/unified-archive/src)
paragonie/sodium_compat in (/var/www/html/glpi/vendor/paragonie/sodium_compat/src)
symfony/cache in (/var/www/html/glpi/vendor/symfony/cache)
html2text/html2text in (/var/www/html/glpi/vendor/html2text/html2text/src)
symfony/css-selector in (/var/www/html/glpi/vendor/symfony/css-selector)
symfony/dom-crawler in (/var/www/html/glpi/vendor/symfony/dom-crawler)
twig/twig in (/var/www/html/glpi/vendor/twig/twig/src)
twig/string-extra in (/var/www/html/glpi/vendor/twig/string-extra)
symfony/polyfill-ctype not found
symfony/polyfill-iconv not found
symfony/polyfill-mbstring not found
symfony/polyfill-php80 not found
symfony/polyfill-php81 not found
symfony/polyfill-php82 in (/var/www/html/glpi/vendor/symfony/polyfill-php82)
league/oauth2-client in (/var/www/html/glpi/vendor/league/oauth2-client/src/Provider)
league/oauth2-google in (/var/www/html/glpi/vendor/league/oauth2-google/src/Provider)
thenetworg/oauth2-azure in (/var/www/html/glpi/vendor/thenetworg/oauth2-azure/src/Provider)
phpCas version 1.6.0 in (/usr/share/php/CAS/source)

LDAP directories
 
Server: 'ldaps://1.1.1.1', Port: '636', BaseDN: 'DC=domain,DC=corp', Connection filter:
        '(&(objectClass=user)(objectCategory=person)(!(userAccountControl:1.2.840.113556.1.4.803:=2)))', RootDN: 'CN=Glpi
        Auth,OU=AD,OU=ServiceAccounts,OU=AllUsers,DC=domain,DC=corp', Use TLS: none
Server: 'localhost', Port: '1636', BaseDN: 'DC=domain,DC=com', Connection filter: none, RootDN: 'OptimalGre', Use TLS:
        none

SQL replicas
 
Not active

Notifications
 
Way of sending emails: PHP

Plugins list
 
    glpiinventory        Name: GLPI Inventory                 Version: 1.2.3      State: Enabled                                 
        Install Method: Manual
    phpsaml              Name: PHP SAML                       Version: 1.2.1      State: Enabled                                 
        Install Method: Manual

Anything else?

We have around 3000 endpoints reporting. The behavior started after upgrading to 10.0.12, but even after a rollback to a backup with 10.0.9 and reboot it did the same so this is not tied to version 10.0.12, but to something else, some cleanup routine i guess but i haven't found it's source.

laszlokertesz commented 6 months ago

I found the log entries. It does seem to point to the glpi inventory plugin?

/var/www/html/glpi/files/_log/sql-errors.log:  SQL: DELETE `glpi_logs` FROM `glpi_logs` WHERE `itemtype` = 'Agent' AND `items_id` = '1051'
/var/www/html/glpi/files/_log/sql-errors.log-  Error: Lock wait timeout exceeded; try restarting transaction
/var/www/html/glpi/files/_log/sql-errors.log-  Backtrace :
/var/www/html/glpi/files/_log/sql-errors.log-  src/DBmysql.php:1579                               
/var/www/html/glpi/files/_log/sql-errors.log-  src/CommonDBTM.php:841                             DBmysql->delete()
/var/www/html/glpi/files/_log/sql-errors.log-  src/CommonDBTM.php:787                             CommonDBTM->cleanHistory()
/var/www/html/glpi/files/_log/sql-errors.log-  src/CommonDBTM.php:2068                            CommonDBTM->deleteFromDB()
/var/www/html/glpi/files/_log/sql-errors.log-  src/CommonDBTM.php:4627                            CommonDBTM->delete()
/var/www/html/glpi/files/_log/sql-errors.log-  src/Inventory/Asset/MainAsset.php:786              CommonDBTM->deleteByCriteria()
/var/www/html/glpi/files/_log/sql-errors.log-  src/RuleImportAsset.php:969                        Glpi\Inventory\Asset\MainAsset->rulepassed()
/var/www/html/glpi/files/_log/sql-errors.log-  src/Rule.php:1525                                  RuleImportAsset->executeActions()
/var/www/html/glpi/files/_log/sql-errors.log-  src/RuleCollection.php:1640                        Rule->process()
/var/www/html/glpi/files/_log/sql-errors.log-  src/Inventory/Asset/MainAsset.php:573              RuleCollection->processAllRules()
/var/www/html/glpi/files/_log/sql-errors.log-  src/Inventory/Inventory.php:709                    Glpi\Inventory\Asset\MainAsset->handle()
/var/www/html/glpi/files/_log/sql-errors.log-  src/Inventory/Inventory.php:340                    Glpi\Inventory\Inventory->handleItem()
/var/www/html/glpi/files/_log/sql-errors.log-  src/Inventory/Request.php:360                      Glpi\Inventory\Inventory->doInventory()
/var/www/html/glpi/files/_log/sql-errors.log-  src/Inventory/Request.php:90                       Glpi\Inventory\Request->inventory()
/var/www/html/glpi/files/_log/sql-errors.log-  src/Agent/Communication/AbstractRequest.php:359    Glpi\Inventory\Request->handleAction()
/var/www/html/glpi/files/_log/sql-errors.log-  src/Agent/Communication/AbstractRequest.php:271    Glpi\Agent\Communication\AbstractRequest->handleJSONRequest()
/var/www/html/glpi/files/_log/sql-errors.log-  front/inventory.php:92                             Glpi\Agent\Communication\AbstractRequest->handleRequest()
/var/www/html/glpi/files/_log/sql-errors.log-  plugins/glpiinventory/front/communication.php:72   include_once()
/var/www/html/glpi/files/_log/sql-errors.log-  plugins/glpiinventory/index.php:45                 include_once()
/var/www/html/glpi/files/_log/sql-errors.log-  {"user":"inventory@inventory.3pillarglobal.com","mem_usage":"87.900\", 6.13Mio)"} 
laszlokertesz commented 6 months ago

I traced it to src/Inventory/Asset/MainAsset.php, part of Glpi proper.

Line 834

        //check for any old agent to remove
         $agent = new \Agent();
         $agent->deleteByCriteria([
             'itemtype' => $this->item->getType(),
             'items_id' => $items_id,
             'NOT' => [
                 'id' => $this->agent->fields['id']
             ]
         ]);

If i comment these lines out, everything returns to normal. Is this section really necessary?

stonebuzz commented 6 months ago

This code deletes the agent from the asset currently being inventoried if it has changed (for example, you switch from Fusion to GLPI-agent).

This will lead to a cascade of database cleanup, particularly in the glpi_logs table, where all entries relating to this itemtype and item_id must be deleted.

What does the following SQL query return?

SELECT count(*) FROM `glpi_logs` WHERE `itemtype` = 'Agent' AND `items_id` = '1051'

Best regards

laszlokertesz commented 6 months ago

This code deletes the agent from the asset currently being inventoried if it has changed (for example, you switch from Fusion to GLPI-agent).

This will lead to a cascade of database cleanup, particularly in the glpi_logs table, where all entries relating to this itemtype and item_id must be deleted.

What does the following SQL query return?

SELECT count(*) FROM `glpi_logs` WHERE `itemtype` = 'Agent' AND `items_id` = '1051'

Best regards

About 50 000 000 lines. Obviously this is our issue here. Actualy the issue is that this is trigered for hundreds of agents in a few minutes. I let them run in the weekend but none finished even after 12 hours and the server was mostly unresponsive for Web UI management, the logs were full of timed ot transactions.

And we switched to glpi agent a while ago. But only after we rebooted the server this was triggered for some reason.

cconard96 commented 6 months ago

Are all your tables migrated to using InnoDB instead of MyISAM? There are a lot of performance benefits including smarter locking. With MyISAM, the entire table is locked (made read-only) during a DELETE operation.

laszlokertesz commented 6 months ago

Are all your tables migrated to using InnoDB instead of MyISAM? There are a lot of performance benefits including smarter locking. With MyISAM, the entire table is locked (made read-only) during a DELETE operation.

I think so. The logs table definitely is.

stonebuzz commented 6 months ago

@laszlokertesz

Can you view the agent's history with the ID 1051

image

Do you see anything unusual (an untimely change of linked item, something else)?

github-actions[bot] commented 4 months ago

There has been no activity on this issue for some time and therefore it is considered stale and will be closed automatically in 10 days.

If this issue is related to a bug, please try to reproduce on latest release. If the problem persist, feel free to add a comment to revive this issue. If it is related to a new feature, please open a topic to discuss with community about this enhancement on suggestion website.

You may also consider taking a subscription to get professionnal support or contact GLPI editor team directly.