Misp: PyMISP.add_hashes() Error: [PDOException] SQLSTATE[40001]: Serialization failure: 1213 Deadlock

[github-germ]

2.4.90
mariaDB 5.5.56

has this been seen before? any idea on how to resolve is appreciated.

this occurs in error.log when calling PyMISP.add_hashes()

2018-05-21 03:06:50 Error: [PDOException] SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction
Request URL: /attributes/add/11404
Stack Trace:
#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('UPDATE `misp`.`...', Array)
#2 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Datasource/Database/Mysql.php(424): DboSource->execute('UPDATE `misp`.`...')
#3 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(1926): Mysql->update(Object(Event), '`id` = 11404, `...', Array)
#4 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(1760): Model->_doSave(Array, Array)
#5 /var/www/MISP/app/Model/Attribute.php(570): Model->save(Array, Array)
#6 /var/www/MISP/app/Model/Attribute.php(610): Attribute->__alterAttributeCount('11404')
#7 /var/www/MISP/app/Lib/cakephp/lib/Cake/Event/CakeEventManager.php(241): Attribute->afterSave(true, Array)
#8 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(1970): CakeEventManager->dispatch(Object(CakeEvent))
#9 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(1754): Model->_doSave(Array, Array)
#10 /var/www/MISP/app/Lib/cakephp/lib/Cake/Model/Model.php(2352): Model->save(Array, Array)
#11 /var/www/MISP/app/Controller/AttributesController.php(276): Model->saveMany(Array)
#12 [internal function]: AttributesController->add('11404')
#13 /var/www/MISP/app/Lib/cakephp/lib/Cake/Controller/Controller.php(491): ReflectionMethod->invokeArgs(Object(AttributesController), Array)
#14 /var/www/MISP/app/Lib/cakephp/lib/Cake/Routing/Dispatcher.php(193): Controller->invokeAction(Object(CakeRequest))
#15 /var/www/MISP/app/Lib/cakephp/lib/Cake/Routing/Dispatcher.php(167): Dispatcher->_invoke(Object(AttributesController), Object(CakeRequest))
#16 /var/www/MISP/app/webroot/index.php(92): Dispatcher->dispatch(Object(CakeRequest), Object(CakeResponse))
#17 {main}

[adulau]

Could you share your script?

[github-germ]

A, thx for the reply. My script is a multi-threaded ingestion of many events each with many attributes to add. Single threaded it can take many hours, hence threading. I do have thread locks, but have tried to protect less code for performance gain.

Interestingly, the threaded process worked quite well until this weekend when I fixed a bug where my PyMISP.add_hashes() were returning internal error. Once they started succeeding, the deadlock starting appearing; I imagine due to more contention(?).

Could the db deadlock on the MISP server-side be rooted in a need to lock a wider code region in my PyMISP client side? I was about to try this now, but am concerned about the performance. If there are any tips on being thread-safe with PyMISP, that could be a big help. Thank you.

[adulau]

Thank you. It will be difficult to debug but two questions:

• How is your MariaDB configured? Do you have innodb_file_per_table as true or false?
• Not sure how many attributes that you are adding. If this is only for correlation, I suppose you considered the use of feed caching instead of importing attributes.

[github-germ]

innodb_file_per_table is OFF, the default for the MariaDB 5.5 version we have.

[github-germ]

A, we don't have lots of mysql experience of MyISAM v. InnoDB, but suspect that the InnoDB row locking will be a better choice here. Do you have any guidance for us to switch?

[garanews]

I have the same issue with MariaDB.
Same script against misp with mysql works.
With MariaDB, tried to tune something with @Rafiot but no success.
I was using pymisp and python multiprocessing module.

[iglocska]

Pushed a new branch with a potential fix for it. Could you switch to the deadlockfix branch and see if the issue gets resolved? It means we'll have slightly slower attribute adds, but if it solves a nasty issue like this it's probably worth it...

[github-germ]

Hi Andras, Great + Thanks!! I don't control the base MISP version on this host. Let me talk with them. To make the test simpler, is this the only file that changed?

• app/Controller/AttributesController.php
• https://github.com/MISP/MISP/commit/6ad4a167189b0f056a0ebaf3e2e416898c3b367b#diff-4e170dc14483ed36d7c9658c82f61516

Am I understanding that the .91 version uses an atomic add/commit for the entire array, i.e. a longer lock, while the revised version disables atomic and add/commits each element individually, i.e. no lock (and a little slower)?

And if that interpretation is correct, why do you think the .91 version could allow a race toward deadlock, e.g. from two "competing" threads attempting an add?

[iglocska]

Correct indeed! We still have some leeway of tuning it further afterwards, we were wide open for deadlocks as the framework actually generated a single transaction for all attributes/correlations to be added in one shot, which can be a fair bit of inserts in one shot. Something that we could look into in the future is to only use atomic => false if a certain threshold is reached for payload size (for example, use a transaction if more than 10 attributes are about to be inserted)

[github-germ]

Yowza!

So, I would think we should first test this change while we are still on mariaDB/MyISAM to see if it recurs. And then if it resolves, we should also move to a newer mariaDB (we have an old 5.5) which will default to InnoDB to include row locks (vs. table).

Make sense?

Also, because I will be asked. If this works, could this become a .92 release soon? This organization prefers to avoid frequent updates to core code.

Thanks again for this support!!

[iglocska]

Moving to the newer version makes sense anyway of course ;) Yeah, I'll include the changes in .92 if it really resolves the issue for sure. Sadly even with row level locking we might run into similar issues - but it will probably be a lot less frequent.

Just make sure you test it and give feedback to see if it's the silver bullet to the multi-threading issues.

[github-germ]

OK... we upgraded to Maria 10.2.8/InnoDB and installed AttributesController.php and so far have not see the SQL deadlock reported earlier. However, I do see lock wait timeouts:

2018-05-22 20:28:45 Error: [PDOException] SQLSTATE[HY000]: General error: \
1205 Lock wait timeout exceeded; try restarting transaction

By associating my client log with error.log it appears those timeouts are triggered by PyMISP.add_hashes(), e.g.

add_hashes(event_id=11424, category="Payload delivery", \
filename="UNAVAILABLE", md5="847cdcc42f3bd99a9fde5ba8c459dfd0", \
sha1="8621a08394d54d8ee48d8a7733192c7a22fa7350", \
sha256="7e843c7385259d5d75fd35fc9a18dd248296c59626b124db8428bba534d56cae") \
returned {'name': 'An Internal Error Has Occurred.', \
'message': 'An Internal Error Has Occurred.', 'url': '/attributes/add/11424'}

1. Can you shed some light on the impact of that timeout, e.g. my code keeps running; so, is it just that hash that is not added or more than that?
2. Is there something in my.cnf we can tune? I go from the default 50 to 100 for the lock timeout while I wait for your next reply and report back... e.g.

MariaDB [misp]> show variables like 'innodb_lock_wait_timeout';
+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| innodb_lock_wait_timeout | 50    |
+--------------------------+-------+

1. Is there more defensive code you can add to the server-side improving thread safety?

Seemingly unrelated, but we'd like to understand root cause, see https://github.com/MISP/MISP/issues/1402#issuecomment-391046070

THANKS.

[github-germ]

Sorry to report that I am again seeing deadlocks. And as expected, once we hit that general state with threads continuing to hit the db, we start to see many of these...

2018-05-22 21:25:24 Error: [PDOException] SQLSTATE[40001]: \
Serialization failure: 1213 Deadlock found when trying to get lock; \
try restarting transaction

I'll wait for your reply on next steps. Thanks!!

[iglocska]

is that on the 2.4 branch or the deadlockfix branch?

[github-germ]

As i wrote yesterday in order to simplify I only changed AttributesController.php on top of 2.4.90. If that's not correct, let me know. Thx...

[Rafiot]

This is a bad idea, as it breaks the update mechanism of MISP (in the future, when you run git pull, it will fail).

[github-germ]

I saved the original file and it's back in place now. Was that the only file? If so, we need more work on this issue. If I need to install differently to test, let me know. Thank you.

[Rafiot]

It is probably fine for this particular change. But next time you find a bug and we fix it, you won't be able to do a git pull (unless you revert your changes). And if you continue to patch the files manually, you will need to keep track of all the changes manually.

For example:

1. you find a bug
2. @iglocska fixes it in one file
3. turns out the file @iglocska patched had an other change that depends on other changes in multiple files
4. you have super weird issues that don't make any sense to us and we won't be able to help you

[github-germ]

Raphaël, I understand and can deal with this. No worries. I do appreciate your advice however.

Andras, Hoping to hear back as this issue has blocked our project progress. THANKS as always for the great support!!

[Rafiot]

All good then, I'm closing the issue :)

[github-germ]

This issue isn’t closed. It’s still a problem. Please reopen.

The patch didn’t resolve the occurrences of DB deadlocks as I reported yesterday: https://github.com/MISP/MISP/issues/3264#issuecomment-391146535

Andras, what next? Thx.

[Rafiot]

Well then, please answer @iglocska's question regarding which branch you're on. If you're not on a branch and still patch code manually, please provide a diff with the said branches so we can have an idea of the status your code.

[iglocska]

What @Rafiot said, an output from git status along with the commit ID you're on would help a lot to ensure that you really are on the same code-base that we're on.

I saved the original file and it's back in place now. Was that the only file?

This is super worrying as two files were changed by the patch.

[github-germ]

Ok. In https://github.com/MISP/MISP/issues/3264#issuecomment-390978405 I wrote that I would try the single file and you replied in what I thought confirmed that. My bad.

Will retest. Thank you.

[iglocska]

Ah ok, I misunderstood that, but you can check the changes of individual commits by clicking the last tab on the commit view.

With that said, please don't use manual modifications - that will only lead to issues. We cannot support non standard MISP installations / forks for obvious reasons.

[github-germ]

Understood. I need to convince the folks who control this host to be flexible to allow pulls, etc. vs. "freezing" the codebase. That model does not jive with this type of project.

Appreciate you not beating me up too bad (-: ... I'll let you know how this looks when I get to test it (again).

[iglocska]

For sure, freezing is always counter-productive, but the best advice I can give is to also have a test instance where you have a bit more flexibility!

[github-germ]

Andras, Good news. Looking good. Ran ingestion without any deadlocks. I was running the deadlockfix branch commit 6ad4a167189b0f056a0ebaf3e2e416898c3b367b. It does appear to be slower, but better than having errors 👍

I assume this will go into .92 -- any idea when that release might come out?

Thx again for your help and your patience!!

[github-germ]

Hi Andras, let me know plans to merge deadlockfix when you get a chance. See https://github.com/MISP/MISP/issues/3264#issuecomment-392135188 THANKS AGAIN!!

[iglocska]

I'm away for a week long training atm, but will look into merging it after (or during if one of the evenings I get too much time on my hands ;))

[github-germ]

Thanks!

[github-germ]

Any chance getting this closed and merged in this week? Thanks a lot!

[Rafiot]

Probably, yes.

[github-germ]

Hi Raphael,

We enter deployment next week of our first MISP instance. We are currently running 2.4.91 with the deadlockfix branch:

git show-ref --heads
 4d89a769605a734b84735d110e14a669be498d31 refs/heads/2.4
 6ad4a167189b0f056a0ebaf3e2e416898c3b367b refs/heads/deadlockfix

My OPS team is conservative when it comes to installed releases. Is this what you suggest we use, or might there be a merge into a new .92 release soon?

Thanks!

[Rafiot]

We have a blocking issue right now, so it will probably need a few more days.

[iglocska]

The previous deadlock fix made it into 2.4.92, just checkout 2.4 and pull the latest version.

[github-germ]

Super. Thank you!!

[iglocska]

No worries, make sure you enable the fix. I've made it optional (as for non multi-thread heavy environments it's counter-productive). You can find the setting under administration -> server settings -> MISP tab -> deadlock fix