ExtMod queued message ID duplicates

[evgeniy]

Hello, I'm using extmodule to proceed call.route and other messages. Extmodule works less then 1 second, monitored with statsd
Yate version is 5.3.0, flags: -Dd -DZ -C -Da -Dm -Du -N nodename -p pidfile

Under high load yate crashes.

In logs I see a lot of FAILs:

Code: [Select]

2016-06-29_10:24:29.313098 <FAIL> Thread 'Engine Worker' could not lock mutex 'CallEndpoint' owned by 'Call Router' waited by 14 others for 10000000 usec!
2016-06-29_10:25:23.458147 <FAIL> Thread 'Engine Worker' could not lock mutex 'CallEndpoint' owned by 'Call Router' waited by 18 others for 10000000 usec!
2016-06-29_10:26:42.810675 <FAIL> Thread 'Engine Worker' could not lock mutex 'CallEndpoint' owned by 'Call Router' waited by 12 others for 10000000 usec!
2016-06-29_10:27:23.544752 <FAIL> Thread 'Call Router' could not lock mutex 'CallEndpoint' owned by 'Call Router' waited by 11 others for 10000000 usec!
2016-06-29_10:27:52.171657 <FAIL> Thread 'Originate Thread' could not lock mutex 'CallEndpoint' owned by 'Call Router' waited by 10 others for 10000000 usec!
2016-06-29_10:33:10.954569 <FAIL> Thread 'Engine Worker' could not lock mutex 'CallEndpoint' owned by 'Call Router' waited by 16 others for 10000000 usec!
and finally I get crash:

Code: [Select]

2016-06-29_10:27:23.544752 <FAIL> Thread 'Call Router' could not lock mutex 'CallEndpoint' owned by 'Call Router' waited by 11 others for 10000000 usec!
Yate (30111) is starting Wed Jun 29 10:27:24 2016

Strange that I have similar logs with same message ID "0x7f29f56fcea0"

Code: [Select]

2016-06-29_10:27:20.950752 <ALL> ExtMod queued message 0x7f29f56fcea0 'call.route' [0x1dfb6e0]
2016-06-29_10:27:21.196528 <ExtModReceiver:INFO> Matched message 0x7f29f56fcea0 [0x1dfb6e0]
2016-06-29_10:27:21.196584 <ALL> ExtMod message 0x7f29f56fcea0 'call.route' returning true [0x1dfb6e0]
2016-06-29_10:27:21.204145 <ALL> ExtMod queued message 0x7f29f56fcea0 'call.route' [0x1dfb6e0]
2016-06-29_10:27:21.443368 <ExtModReceiver:INFO> Matched message 0x7f29f56fcea0 [0x1dfb6e0]
2016-06-29_10:27:21.443413 <ALL> ExtMod message 0x7f29f56fcea0 'call.route' returning true [0x1dfb6e0]
2016-06-29_10:27:21.447789 <ALL> ExtMod queued message 0x7f29f56fcea0 'call.route' [0x1dfb6e0]
2016-06-29_10:27:21.693842 <ExtModReceiver:INFO> Matched message 0x7f29f56fcea0 [0x1dfb6e0]
2016-06-29_10:27:21.693888 <ALL> ExtMod message 0x7f29f56fcea0 'call.route' returning true [0x1dfb6e0]
2016-06-29_10:27:21.701095 <ALL> ExtMod queued message 0x7f29f56fcea0 'call.route' [0x1dfb6e0]
2016-06-29_10:27:21.943996 <ExtModReceiver:INFO> Matched message 0x7f29f56fcea0 [0x1dfb6e0]
2016-06-29_10:27:21.944086 <ALL> ExtMod message 0x7f29f56fcea0 'call.route' returning true [0x1dfb6e0]
2016-06-29_10:27:21.948178 <ALL> ExtMod queued message 0x7f29f56fcea0 'call.route' [0x1dfb6e0]
2016-06-29_10:27:22.194203 <ExtModReceiver:INFO> Matched message 0x7f29f56fcea0 [0x1dfb6e0]
2016-06-29_10:27:22.194264 <ALL> ExtMod message 0x7f29f56fcea0 'call.route' returning true [0x1dfb6e0]
2016-06-29_10:27:22.200481 <ALL> ExtMod queued message 0x7f29f56fcea0 'call.route' [0x1dfb6e0]
2016-06-29_10:27:22.446118 <ExtModReceiver:INFO> Matched message 0x7f29f56fcea0 [0x1dfb6e0]
2016-06-29_10:27:22.446164 <ALL> ExtMod message 0x7f29f56fcea0 'call.route' returning true [0x1dfb6e0]
2016-06-29_10:27:22.450448 <ALL> ExtMod queued message 0x7f29f56fcea0 'call.route' [0x1dfb6e0]
2016-06-29_10:27:22.696289 <ExtModReceiver:INFO> Matched message 0x7f29f56fcea0 [0x1dfb6e0]
2016-06-29_10:27:22.696345 <ALL> ExtMod message 0x7f29f56fcea0 'call.route' returning true [0x1dfb6e0]
2016-06-29_10:27:22.701495 <ALL> ExtMod queued message 0x7f29f56fcea0 'call.route' [0x1dfb6e0]
2016-06-29_10:27:22.947780 <ExtModReceiver:INFO> Matched message 0x7f29f56fcea0 [0x1dfb6e0]
2016-06-29_10:27:22.947844 <ALL> ExtMod message 0x7f29f56fcea0 'call.route' returning true [0x1dfb6e0]
2016-06-29_10:27:22.951745 <ALL> ExtMod queued message 0x7f29f56fcea0 'call.route' [0x1dfb6e0]
2016-06-29_10:27:23.197780 <ExtModReceiver:INFO> Matched message 0x7f29f56fcea0 [0x1dfb6e0]
2016-06-29_10:27:23.197839 <ALL> ExtMod message 0x7f29f56fcea0 'call.route' returning true [0x1dfb6e0]
2016-06-29_10:27:23.202972 <ALL> ExtMod queued message 0x7f29f56fcea0 'call.route' [0x1dfb6e0]
2016-06-29_10:27:23.444193 <ExtModReceiver:INFO> Matched message 0x7f29f56fcea0 [0x1dfb6e0]
2016-06-29_10:27:23.444245 <ALL> ExtMod message 0x7f29f56fcea0 'call.route' returning true [0x1dfb6e0]

[marian]

It is not the same message id.
The debug message displays the object's address in memory.
An object may be re-allocated at the same address.

Some issue: your script is holding the call.route message for about 230ms.
Your system won't be able to process more than 4 call atempts per second.
You may move your routing to a javascript routing script (call routing is done asynchronously).

Under heavy load, if internal messages are taking a lot of time to be processed internal dispatcher threads will become busy and the supervisor will restart yate.
You may start yate with -C -Dam
-Da will abort if a debug FAIL is displayed.
This will leave a core when yate is aborted and may give some hint on what happens.

[evgeniy]

Thank you for help.
My script processes routings in parallel, up to 4 routings simultaneously, and answer when any of routings finished.
I will try to increase, maybe this help.

Javascript routing script fully asynchronous and it can route well on heavy load without lock mutex problem?

[marian]

Yes, a javascript routing script is run in call router's thread.