{"action":"created","issue":{"url":"https://api.github.com/repos/Icinga/icinga2/issues/6549","repository_url":"https://api.github.com/repos/Icinga/icinga2","labels_url":"https://api.github.com/repos/Icinga/icinga2/issues/6549/labels{/name}","comments_url":"https://api.github.com/repos/Icinga/icinga2/issues/6549/comments","events_url":"https://api.github.com/repos/Icinga/icinga2/issues/6549/events","html_url":"https://github.com/Icinga/icinga2/issues/6549","id":351210649,"node_id":"MDU6SXNzdWUzNTEyMTA2NDk=","number":6549,"title":"very large plugin output causes services to look overdue & time out database connection","user":{"login":"dbu1986","id":41574323,"node_id":"MDQ6VXNlcjQxNTc0MzIz","avatar_url":"https://avatars2.githubusercontent.com/u/41574323?v=4","gravatar_id":"","url":"https://api.github.com/users/dbu1986","html_url":"https://github.com/dbu1986","followers_url":"https://api.github.com/users/dbu1986/followers","following_url":"https://api.github.com/users/dbu1986/following{/other_user}","gists_url":"https://api.github.com/users/dbu1986/gists{/gist_id}","starred_url":"https://api.github.com/users/dbu1986/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/dbu1986/subscriptions","organizations_url":"https://api.github.com/users/dbu1986/orgs","repos_url":"https://api.github.com/users/dbu1986/repos","events_url":"https://api.github.com/users/dbu1986/events{/privacy}","received_events_url":"https://api.github.com/users/dbu1986/received_events","type":"User","site_admin":false},"labels":[{"id":520053862,"node_id":"MDU6TGFiZWw1MjAwNTM4NjI=","url":"https://api.github.com/repos/Icinga/icinga2/labels/DB%20IDO","name":"DB IDO","color":"F7FE2E","default":false},{"id":54043337,"node_id":"MDU6TGFiZWw1NDA0MzMzNw==","url":"https://api.github.com/repos/Icinga/icinga2/labels/bug","name":"bug","color":"fc2929","default":true}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":3,"created_at":"2018-08-16T13:40:59Z","updated_at":"2018-08-27T14:30:04Z","closed_at":null,"author_association":"NONE","body":"<!--- Provide a general summary of the issue in the Title above -->\r\n\r\n<!-- If you are reporting a problem or a bug, please ensure to read https://github.com/Icinga/icinga2/blob/master/doc/15-troubleshooting.md first. -->\r\n\r\n<!-- Formatting tips:\r\n\r\nGitHub supports Markdown: https://guides.github.com/features/mastering-markdown/\r\nMulti-line code blocks either with three back ticks, or four space indent.\r\n\r\n```\r\nobject Host \"myhost\" {\r\n  ...\r\n}\r\n```\r\n-->\r\n\r\n## Expected Behavior\r\n<!--- If you're describing a bug, tell us what should happen -->\r\nThe Output of a check plugin should not affect Icinga2's database connection health, which results in all services to look overdue in Icingaweb2. Icinga2 should take care of submitting database-compatible sql queries regarding the max length of table columns.\r\n\r\n<!--- If you're suggesting a change/improvement, tell us how it should work -->\r\n\r\n## Current Behavior\r\n<!--- If describing a bug, tell us what happens instead of the expected behavior -->\r\nAs soon as Icinga2 is beginning to handle a very large plugin output in one service, the list of overdue check results in Icingaweb2 gets longer, until all active services seem to be overdue in Icingaweb2. The debuglog shows database exceptions e.g. as follows:\r\n```\r\n[2018-08-16 10:41:46 +0200] critical/IdoMysqlConnection: Error \"Query was empty\" when executing query \"\"\r\n```\r\n```\r\n[2018-08-16 10:41:46 +0200] critical/IdoMysqlConnection: Exception during database operation: Verify that your database is operational!\r\n```\r\n```\r\n[2018-08-16 10:41:46 +0200] debug/IdoMysqlConnection: Exception during database operation: Error: std::exception\r\n```\r\n```\r\n[2018-08-16 10:41:46 +0200] critical/IdoMysqlConnection: Error \"MySQL server has gone away\" when executing query \"DELETE FROM icinga_comments WHERE instance_id = 1 AND session_token <> 1534408869\"\r\n```\r\nIt looks like the executed UPDATE query into icinga_servicestatus (with the very long output) causes Icinga2 to time out and close it's database connection.\r\n\r\n<!--- If suggesting a change/improvement, explain the difference from current behavior -->\r\n\r\n## Possible Solution\r\n<!--- Not obligatory, but suggest a fix/reason for the bug, -->\r\nIcinga2 makes sure that the plugin output will fit into the column 'long_output' in table icinga_servicestatus (column type = TEXT => 65535 Chars), e.g. by cutting off the plugin output string while building the sql query. Same might be relevant to column 'perfdata' as well.\r\n<!--- or ideas how to implement:  the addition or change -->\r\n\r\n\r\n## Steps to Reproduce (for bugs)\r\n<!--- Provide a link to a live example, or an unambiguous set of steps to -->\r\n<!--- reproduce this bug. Include configuration, logs, etc. to reproduce, if relevant -->\r\n1. Create a service using a CheckCommand with very long plugin output (e.g. 945635 characters )\r\n2. Let Icinga2 check the service and handle it's plugin output\r\n3. Watch the increasing time of 'last check' on all services in Icingaweb2. You can also watch the increasing list of late check results at Icingaweb2 --> Dashboard -->Overdue.\r\n4. Consulting your debuglog should also make you aware of database exceptions (see above).\r\n\r\n## Context\r\n<!--- How has this issue affected you? What are you trying to accomplish? -->\r\nI am deploying services executing a new check plugin (custom made perl script). Due to different reasons the plugin returns 945635 characters of output, including lots of host-based errors. \r\nI know, it might not be Icinga2's job to take care of buggy outputs of custom plugins, but it seems to allow pretty extensive impacts, which should IMHO get limited.\r\n\r\nAs Icinga2 begins to execute checks, I notice that all services are getting high last check times. The list of overdue check results is increasing until all ~8800 services are affected. Hitting the service's \"Check now\" link does not change this behaviour.\r\nThe debuglog shows exceptions regarding the database connection (see above). I think that's the reason why Icingaweb2 cannot retreive the latest check results from the database. The checks are definitely executed freshly and in time, as traced via debuglog.\r\n\r\nI assume that the large sql query is responsible for the situation, so limiting the input values to the maximum column size of the destination table might be an appropriate way to avoid it.\r\n\r\n<!--- Providing context helps us come up with a solution that is most useful in the real world -->\r\n\r\n## Your Environment\r\n<!--- Include as many relevant details about the environment you experienced the problem in -->\r\n* Version used (`icinga2 --version`):\r\n```\r\nicinga2 - The Icinga 2 network monitoring daemon (version: r2.9.1-1)\r\n\r\nCopyright (c) 2012-2018 Icinga Development Team (https://www.icinga.com/)\r\nLicense GPLv2+: GNU GPL version 2 or later <http://gnu.org/licenses/gpl2.html>\r\nThis is free software: you are free to change and redistribute it.\r\nThere is NO WARRANTY, to the extent permitted by law.\r\n\r\nApplication information:\r\n  Installation root: /usr\r\n  Sysconf directory: /etc\r\n  Run directory: /run\r\n  Local state directory: /var\r\n  Package data directory: /usr/share/icinga2\r\n  State path: /var/lib/icinga2/icinga2.state\r\n  Modified attributes path: /var/lib/icinga2/modified-attributes.conf\r\n  Objects path: /var/cache/icinga2/icinga2.debug\r\n  Vars path: /var/cache/icinga2/icinga2.vars\r\n  PID path: /run/icinga2/icinga2.pid\r\n\r\nSystem information:\r\n  Platform: Red Hat Enterprise Linux Server\r\n  Platform version: 7.5 (Maipo)\r\n  Kernel: Linux\r\n  Kernel version: 3.10.0-862.9.1.el7.x86_64\r\n  Architecture: x86_64\r\n\r\nBuild information:\r\n  Compiler: GNU 4.8.5\r\n  Build host: unknown\r\n\r\n```\r\n* Enabled features (`icinga2 feature list`): \r\n```\r\nEnabled features: api checker command debuglog graphite ido-mysql mainlog notification\r\n```\r\n* Icinga Web 2 version and modules (System - About):  2.6.1\r\n* Config validation (`icinga2 daemon -C`):\r\n```\r\n[2018-08-16 14:38:08 +0200] information/cli: Icinga application loader (version: r2.9.1-1)\r\n[2018-08-16 14:38:08 +0200] information/cli: Loading configuration file(s).\r\n[2018-08-16 14:38:08 +0200] information/ConfigItem: Committing config item(s).\r\n[2018-08-16 14:38:09 +0200] information/ApiListener: My API identity: fravm007010.os-fra.local\r\n[2018-08-16 14:38:18 +0200] information/WorkQueue: #4 (DaemonUtility::LoadConfigFiles) items: 0, rate: 3.25/s (195/min 195/5min 195/15min);\r\n[2018-08-16 14:38:19 +0200] information/WorkQueue: #5 (IdoMysqlConnection, ido-mysql) items: 0, rate:  0/s (0/min 0/5min 0/15min);\r\n[2018-08-16 14:38:19 +0200] information/WorkQueue: #6 (ApiListener, RelayQueue) items: 0, rate:  0/s (0/min 0/5min 0/15min);\r\n[2018-08-16 14:38:19 +0200] information/WorkQueue: #7 (ApiListener, SyncQueue) items: 0, rate:  0/s (0/min 0/5min 0/15min);\r\n[2018-08-16 14:38:19 +0200] information/WorkQueue: #8 (GraphiteWriter, graphite) items: 0, rate:  0/s (0/min 0/5min 0/15min);\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 8809 Services.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 37 ServiceGroups.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 70 HostGroups.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 1 EventCommand.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 2 FileLoggers.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 1 NotificationComponent.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 9 NotificationCommands.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 9421 Notifications.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 1 IcingaApplication.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 612 Hosts.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 1 ApiListener.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 407 Downtimes.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 1 GraphiteWriter.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 140 Comments.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 1 CheckerComponent.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 499 Zones.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 1 ExternalCommandListener.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 501 Endpoints.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 7 ApiUsers.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 1 UserGroup.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 1 IdoMysqlConnection.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 298 CheckCommands.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 19 TimePeriods.\r\n[2018-08-16 14:38:25 +0200] information/ConfigItem: Instantiated 1 User.\r\n[2018-08-16 14:38:26 +0200] information/ScriptGlobal: Dumping variables to file '/var/cache/icinga2/icinga2.vars'\r\n[2018-08-16 14:38:26 +0200] information/cli: Finished validating the configuration file(s).\r\n```"},"comment":{"url":"https://api.github.com/repos/Icinga/icinga2/issues/comments/416246006","html_url":"https://github.com/Icinga/icinga2/issues/6549#issuecomment-416246006","issue_url":"https://api.github.com/repos/Icinga/icinga2/issues/6549","id":416246006,"node_id":"MDEyOklzc3VlQ29tbWVudDQxNjI0NjAwNg==","user":{"login":"dbu1986","id":41574323,"node_id":"MDQ6VXNlcjQxNTc0MzIz","avatar_url":"https://avatars2.githubusercontent.com/u/41574323?v=4","gravatar_id":"","url":"https://api.github.com/users/dbu1986","html_url":"https://github.com/dbu1986","followers_url":"https://api.github.com/users/dbu1986/followers","following_url":"https://api.github.com/users/dbu1986/following{/other_user}","gists_url":"https://api.github.com/users/dbu1986/gists{/gist_id}","starred_url":"https://api.github.com/users/dbu1986/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/dbu1986/subscriptions","organizations_url":"https://api.github.com/users/dbu1986/orgs","repos_url":"https://api.github.com/users/dbu1986/repos","events_url":"https://api.github.com/users/dbu1986/events{/privacy}","received_events_url":"https://api.github.com/users/dbu1986/received_events","type":"User","site_admin":false},"created_at":"2018-08-27T14:30:04Z","updated_at":"2018-08-27T14:30:04Z","author_association":"NONE","body":"Thanks for linking this valuable video!\r\nSure, already did so. My point is to harden Icinga2 against such an impact. It took a while for me to identify the dependency between a crappy plugin output and seemingly system-wide overdue checks in Icingaweb2."}}
{"actor":{"display_login":"dbu1986"}}