Misp: Pull all job stucks at 15% when adding to the database is not complete

[nyzsirt]

Work environment

| Questions | Answers
|---------------------------|--------------------
| Type of issue | Bug
| OS version (server) | ubuntu 16.04
| OS version (client) | Ubuntu
| PHP version | 7.0
| MISP version / git hash | 2.4.90
| Browser | google chrome

Expected behavior

expect to finish pulling from server input

Actual behavior

finish pulling and complete

Steps to reproduce the behavior

start scheduled task type pull all

Logs

`
/var/www/MISP/app/tmp/logs# tail -f resque-2018-05-10.log

[2018-05-10 16:21:46] main.INFO: got {"queue":"email","id":"cd11e8c00f3a3e1c7d9d9ba0ea6a0dde","class":"EventShell","args":[["alertemail","1","34863","31690",null]]} {"type":"got","args":"[object] (Resque_Job: {\"queue\":\"email\",\"id\":\"cd11e8c00f3a3e1c7d9d9ba0ea6a0dde\",\"class\":\"EventShell\",\"args\":[[\"alertemail\",\"1\",\"34863\",\"31690\",null]]})","worker":"rtir:25904"} []
[2018-05-10 16:21:46] main.INFO: Processing ID:cd11e8c00f3a3e1c7d9d9ba0ea6a0dde in email {"type":"process","worker":"rtir:25904","job_id":"cd11e8c00f3a3e1c7d9d9ba0ea6a0dde"} []
[2018-05-10 16:21:46] main.INFO: done ID:cd11e8c00f3a3e1c7d9d9ba0ea6a0dde {"type":"done","job_id":"cd11e8c00f3a3e1c7d9d9ba0ea6a0dde","time":384,"worker":"rtir:25904"} []
`

[scoggins]

Seeing the same issue here, job stops after getting the same error:

Questions | Answers
-- | --
Type of issue | Bug
OS version (server) | Redhat 7
OS version (client) | MacOS X
PHP version | 7.2.5
MISP version / git hash | 2.4.90
Browser | Safari

[2018-05-12 19:46:44] main.ERROR: {"queue":"default","id":"76fe3ca98ee42e8bb8d9c5143a09535d","class":
"ServerShell","args":[["pull","1","1","full","1228"]]} failed: SQLSTATE[HY000]: General error: 1366 Incorrect integer value: '' for column 'deleted' at row 1 {"type":"fail","log":"SQLSTATE[HY000]: General error: 1366 Incorrect integer value: '' for column 'deleted' at row 1","job_id":"76fe3ca98ee42e8bb8d9c5143a09535d","time":4987,"worker":"misp.xxx.xxx:57047"} []

[scoggins]

I've managed to resolve my issue by disabling STRICT_TRANS_TABLES in sql_mode on mysql.

[Brueggus]

We're currently facing the same issue.

To my mind, disabling STRICT_TRANS_TABLES is a workaround, but no proper solution for the issue.

Disabling strict mode prevents queries "with invalid or missing data" from being aborted and rolled back (https://mariadb.com/kb/en/library/sql-mode/), so apparently there's still an issue in MISP which creates somewhat invalid SQL-Queries to the DB server.

[iglocska]

yeah strict_trans_tables is not a nice solution. Just out of curiosity, are you trying to pull from a very old instance?

[Brueggus]

Nope - it's the other way around:
Local version: 2.4.90
Remote version: 2.4.91

Some events get pulled, but sooner or later the pull job stops with the error message:

app/Console/cake Server pull 3 1 full

Welcome to CakePHP v2.9.9 Console
---------------------------------------------------------------
App : app
Path: /opt/appdir/http/MISP/app/
---------------------------------------------------------------
Error: SQLSTATE[22007]: Invalid datetime format: 1366 Incorrect integer value: '' for column 'deleted' at row 1
#0 /opt/appdir/http/MISP/app/Lib/cakephp/lib/Cake/Model/Datasource/DboSource.php(470): PDOStatement->execute(Array)
#1 /opt/appdir/http/MISP/app/Lib/cakephp/lib/Cake/Model/Datasource/DboSource.php(436): DboSource->_execute('INSERT INTO `mi...', Array)
#2 /opt/appdir/http/MISP/app/Lib/cakephp/lib/Cake/Model/Datasource/DboSource.php(1090): DboSource->execute('INSERT INTO `mi...')
#3 /opt/appdir/http/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(1940): DboSource->create(Object(ObjectReference), Array, Array)
#4 /opt/appdir/http/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(1758): Model->_doSave(Array, Array)
#5 /opt/appdir/http/MISP/app/Model/ObjectReference.php(228): Model->save(Array)
#6 /opt/appdir/http/MISP/app/Model/Event.php(2704): ObjectReference->captureReference(Array, '6141', Array, Object(Log))
#7 /opt/appdir/http/MISP/app/Model/Server.php(1767): Event->_add(Array, true, Array, '2', '1', true, '6007')
#8 /opt/appdir/http/MISP/app/Console/Command/ServerShell.php(40): Server->pull(Array, '1', 'full', Array, '6007')
#9 /opt/appdir/http/MISP/app/Lib/cakephp/lib/Cake/Console/Shell.php(458): ServerShell->pull()
#10 /opt/appdir/http/MISP/app/Lib/cakephp/lib/Cake/Console/ShellDispatcher.php(219): Shell->runCommand('pull', Array)
#11 /opt/appdir/http/MISP/app/Lib/cakephp/lib/Cake/Console/ShellDispatcher.php(66): ShellDispatcher->dispatch()
#12 /opt/appdir/http/MISP/app/Console/cake.php(32): ShellDispatcher::run(Array)
#13 {main}

We're running MariaDB on a separate virtual server, but I wouldn't say the latency's too high (<2ms).

[8ear]

He Guys,
why this issue is closed?

Our workaround was to install the database on the same server as the apache2. But the issue itself isn't closed with one of these two workarounds.

Kind regards

[combobulator]

We are also experiencing this issue and would like to avoid the above workaround.
Our DB is in a separate docker container on the same host as the web server.

/var/www/MISP/app/Console# ./cake Server pull 2 1 update
Welcome to CakePHP v2.10.9 Console
---------------------------------------------------------------
App : app
Path: /var/www/MISP/app/
---------------------------------------------------------------
Error: SQLSTATE[HY000]: General error: 1366 Incorrect integer value: '' for column 'deleted' at row 1
#0 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Datasource/DboSource.php(472): PDOStatement->execute(Array)
#1 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Datasource/DboSource.php(438): DboSource->_execute('INSERT INTO `mi...', Array)
#2 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Datasource/DboSource.php(1092): DboSource->execute('INSERT INTO `mi...')
#3 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(1942): DboSource->create(Object(ObjectReference), Array, Array)
#4 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(1760): Model->_doSave(Array, Array)
#5 /var/www/MISP/app/Model/ObjectReference.php(228): Model->save(Array)
#6 /var/www/MISP/app/Model/Event.php(2817): ObjectReference->captureReference(Array, '89028', Array, Object(Log))
#7 /var/www/MISP/app/Model/Server.php(1835): Event->_edit(Array, Array, '89028', '165116')
#8 /var/www/MISP/app/Console/Command/ServerShell.php(40): Server->pull(Array, '1', 'update', Array, '165116')
#9 /var/www/MISP/app/Lib/cakephp/lib/Cake/Console/Shell.php(459): ServerShell->pull()
#10 /var/www/MISP/app/Lib/cakephp/lib/Cake/Console/ShellDispatcher.php(219): Shell->runCommand('pull', Array)
#11 /var/www/MISP/app/Lib/cakephp/lib/Cake/Console/ShellDispatcher.php(66): ShellDispatcher->dispatch()
#12 /var/www/MISP/app/Console/cake.php(32): ShellDispatcher::run(Array)
#13 {main}

It looks like the numbers in the line starting #7 refer to local & remote Event IDs(?).
Checking those entries in the database shows they both have valid values in the deleted column (integers - 0 or 1).
This issue occurs on a specific sub-set of our Events; trying the pull multiple times brings up a different Event each time but they appear to be from the same source.

Any input would be much appreciated :)

[patricksvgr]

We can confirm the same behavior (on 2e172ee) when pulling from a same version MISP (2.4.93) - it pulls up to a one-digit number of events before it stops, the same error as already posted occurs.

[patricksvgr]

Alright, we did some debugging and it turns out that the table misp.object_references is using the wrong type tinyint(4) instead of tinyint(1) for the deleted field.

Fix would be: ALTER TABLE object_references CHANGE deleted deleted tinyint(1) NOT NULL;

[combobulator]

I just encountered a similar error with the tags table; the org_id column had the tinyint type, whereas the others had int(11)

Error

# ./cake server pull 3 10 full

Welcome to CakePHP v2.10.9 Console
---------------------------------------------------------------
App : app
Path: /var/www/MISP/app/
---------------------------------------------------------------
Notice Error: Undefined index: name in [/var/www/MISP/app/Model/Organisation.php, line 148]

2018-10-12 12:37:45 Notice: Undefined index: name in [/var/www/MISP/app/Model/Organisation.php, line 148]
Notice Error: Undefined index: name in [/var/www/MISP/app/Model/Organisation.php, line 150]

2018-10-12 12:37:45 Notice: Undefined index: name in [/var/www/MISP/app/Model/Organisation.php, line 150]
Error: SQLSTATE[HY000]: General error: 1366 Incorrect integer value: '' for column 'org_id' at row 1
#0 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Datasource/DboSource.php(472): PDOStatement->execute(Array)
#1 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Datasource/DboSource.php(438): DboSource->_execute('INSERT INTO `mi...', Array)
#2 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Datasource/DboSource.php(1092): DboSource->execute('INSERT INTO `mi...')
#3 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(1942): DboSource->create(Object(SharingGroupOrg), Array, Array)
#4 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(1760): Model->_doSave(Array, Array)
#5 /var/www/MISP/app/Model/SharingGroup.php(620): Model->save(Array)
#6 /var/www/MISP/app/Model/Event.php(2769): SharingGroup->captureSG(Array, Array)
#7 /var/www/MISP/app/Model/Event.php(2790): Event->__captureSGForElement(Array, Array)
#8 /var/www/MISP/app/Model/Event.php(2993): Event->__captureObjects(Array, Array)
#9 /var/www/MISP/app/Model/Server.php(1887): Event->_add(Array, true, Array, '2', '10', true, '32')
#10 /var/www/MISP/app/Model/Server.php(1918): Server->__checkIfPulledEventExistsAndAddOrUpdate(Array, '5b98eb3f-eae8-4...', Array, Array, Object(Event), Array, Array, '32')
#11 /var/www/MISP/app/Model/Server.php(2024): Server->__pullEvent('5b423b3f-f732-4...', Array, Array, Object(Event), Array, Array, '32')
#12 /var/www/MISP/app/Console/Command/ServerShell.php(40): Server->pull(Array, '10', 'full', Array, '32')
#13 /var/www/MISP/app/Lib/cakephp/lib/Cake/Console/Shell.php(459): ServerShell->pull()
#14 /var/www/MISP/app/Lib/cakephp/lib/Cake/Console/ShellDispatcher.php(219): Shell->runCommand('pull', Array)
#15 /var/www/MISP/app/Lib/cakephp/lib/Cake/Console/ShellDispatcher.php(66): ShellDispatcher->dispatch()
#16 /var/www/MISP/app/Console/cake.php(32): ShellDispatcher::run(Array)
#17 {main}

Problem column

| TABLE_CATALOG | TABLE_SCHEMA | TABLE_NAME                    | COLUMN_NAME      | ORDINAL_POSITION | COLUMN_DEFAULT | IS_NULLABLE | DATA_TYPE | CHARACTER_MAXIMUM_LENGTH | CHARACTER_OCTET_LENGTH | NUMERIC_PRECISION | NUMERIC_SCALE | DATETIME_PRECISION | CHARACTER_SET_NAME | COLLATION_NAME | COLUMN_TYPE | COLUMN_KEY | EXTRA | PRIVILEGES                      | COLUMN_COMMENT | GENERATION_EXPRESSION |
+---------------+--------------+-------------------------------+------------------+------------------+----------------+-------------+-----------+--------------------------+------------------------+-------------------+---------------+--------------------+--------------------+----------------+-------------+------------+-------+---------------------------------+----------------+-----------------------+
| def           | misp         | tags                          | org_id           |                5 | 0              | NO          | tinyint   |                     NULL |                   NULL |                 3 |             0 |               NULL | NULL               | NULL           | tinyint(1)  | MUL        |       | select,insert,update,references |                |                       |
+---------------+--------------+-------------------------------+------------------+------------------+----------------+-------------+-----------+--------------------------+------------------------+-------------------+---------------+--------------------+--------------------+----------------+-------------+------------+-------+---------------------------------+----------------+-----------------------+

Fix

ALTER TABLE tags CHANGE org_id org_id int(11) NOT NULL DEFAULT '0';

[SteveClement]

bump @iglocska